log long running sqls executed from a stored procedure

Signed-off-by: Aakash Arayambeth <[email protected]>

db/reqlog.c

@@ -1477,7 +1477,6 @@ inline void reqlog_set_sql(struct reqlogger *logger, struct string_ref *sr)
     put_ref(&logger->sql_ref);
     if (sr) {
         logger->sql_ref = get_ref(sr);
-        reqlog_logf(logger, REQL_INFO, "sql=%s", string_ref_cstr(logger->sql_ref));
     }
 }
 
@@ -2189,6 +2188,9 @@ void reqlog_end_request(struct reqlogger *logger, int rc, const char *callfunc,
         long_request_thresh = long_request_ms;
     }
 
+    if (logger->sql_ref)
+        reqlog_logf(logger, REQL_INFO, "sql=%s", string_ref_cstr(logger->sql_ref));
+
     if (logger->durationus >= M2U(long_request_thresh)) {
         if (logger->clnt) {
             log_params(logger);

lua/sp.c

@@ -1241,6 +1241,7 @@ static int create_temp_table(Lua lua, pthread_mutex_t **lk, const char **name)
         *lk = NULL;
         luabb_error(lua, sp, sqlite3ErrStr(rc));
     }
+    reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__);
 out:
     if (sql) strbuf_free(sql);
     return -1;
@@ -2213,7 +2214,7 @@ static int lua_prepare_sql_int(SP sp, const char *sql, sqlite3_stmt **stmt,
     /* Reset logger. This clears table names (see reqlog_add_table) and
        print events (see reqlog_logv_int) in the logger. */
     reqlog_reset_logger(sp->thd->logger);
-
+    reqlog_set_origin(sp->thd->logger, "%s", sp->clnt->origin);
 retry:
     memset(&err, 0, sizeof(struct errstat));
     if (sp->initial) {
@@ -2226,6 +2227,7 @@ static int lua_prepare_sql_int(SP sp, const char *sql, sqlite3_stmt **stmt,
         sp->rc = get_prepared_stmt_try_lock(sp->thd, sp->clnt, rec_ptr, &err, flags & ~PREPARE_RECREATE);
     }
     sp->initial = 0;
+    reqlog_set_sql(sp->thd->logger, create_string_ref(sql));
     if ((sp->rc == SQLITE_PERM) && (maxRetries != 0) &&
             ((maxRetries == -1) || (nRetry++ < maxRetries))) {
         int sleepms = ATOMIC_LOAD32(gbl_lua_prepare_retry_sleep);
@@ -2311,6 +2313,7 @@ static void lua_end_step(struct sqlclntstate *clnt, SP sp,
     }
 }
 
+
 static void lua_end_all_step(struct sqlclntstate *clnt, SP sp)
 {
     if (sp != NULL) {
@@ -2484,6 +2487,7 @@ static int dbtable_insert(Lua lua)
     }
     lua_end_step(sp->clnt, sp, stmt);
     if (rc == SQLITE_DONE) rc = 0;
+    reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__);
 out:if (rc) {
         const char *errstr = NULL;
         sqlite3 *sqldb = getdb(sp);
@@ -2545,6 +2549,7 @@ static int dbtable_copyfrom(Lua lua)
     }
     lua_end_step(sp->clnt, sp, stmt);
 
+    reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__);
     sqlite3_finalize(stmt);
 
     lua_pushinteger(lua, 0); /* Success return code. */
@@ -3087,6 +3092,7 @@ static void drop_temp_tables(SP sp)
             expire = 1;
             logmsg(LOGMSG_FATAL, "sqlite3_step rc:%d sql:%s\n", rc, drop_sql);
         }
+        reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__);
     }
     clnt->skip_peer_chk = 0;
     if (expire) {
@@ -3763,13 +3769,13 @@ static int db_exec(Lua lua)
         sp->rc = lua_check_errors(sp->clnt, sqldb, stmt, &err);
         sp->error = strdup(err);
     }
-
     if (sp->rc) {
         lua_pushnil(lua);
         lua_pushinteger(lua, sp->rc);
     } else {
         lua_pushinteger(lua, 0); /* Success return code */
     }
+    reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__);
     return 2;
 }
 
@@ -6766,6 +6772,7 @@ static void clone_temp_tables(SP sp)
         sqlite3_stmt *stmt;
         lua_prepare_sql_with_temp_ddl(sp, strbuf_buf(sql), &stmt);
         clone_temp_table(stmt, &tmp->tbl);
+        reqlog_end_request(sp->thd->logger, 0, __func__, __LINE__);
         sqlite3_finalize(stmt);
         sp->clnt->skip_peer_chk = 0;
         strbuf_free(sql);
@@ -7320,13 +7327,15 @@ void *exec_trigger(char *spname)
     char sql[128];
     snprintf(sql, sizeof(sql), "exec procedure %s()", spname);
 
+    char origin[128];
+    snprintf(origin, sizeof(origin), "trigger->%s", spname);
     struct sqlclntstate clnt;
     start_internal_sql_clnt(&clnt);
     clnt.dbtran.mode = TRANLEVEL_SOSQL;
     clnt.sql = sql;
+    clnt.origin = origin;
     clnt.dbtran.trans_has_sp = 1;
     clnt.current_user.bypass_auth = 1;
-
     thread_memcreate(128 * 1024);
     struct sqlthdstate thd = {0};
     sqlengine_thd_start(NULL, &thd, THRTYPE_TRIGGER);

tests/longreq_sp_queries.test/Makefile

@@ -0,0 +1,8 @@
+ifeq ($(TESTSROOTDIR),)
+  include ../testcase.mk
+else
+  include $(TESTSROOTDIR)/testcase.mk
+endif
+ifeq ($(TEST_TIMEOUT),)
+	export TEST_TIMEOUT=3m
+endif

tests/longreq_sp_queries.test/dropsptrigger.sql

@@ -0,0 +1,2 @@
+DROP PROCEDURE dormant '1'
+DROP LUA TRIGGER dormant

tests/longreq_sp_queries.test/lrl.options

@@ -0,0 +1,3 @@
+setattr REP_WORKERS 0
+setattr REP_PROCESSORS 0
+decoupled_logputs off

tests/longreq_sp_queries.test/runit

@@ -0,0 +1,55 @@
+#!/usr/bin/env bash
+bash -n "$0" | exit 1
+set -x
+. ${TESTSROOTDIR}/tools/cluster_utils.sh
+. ${TESTSROOTDIR}/tools/runit_common.sh
+
+function setup_longreq
+{
+    for node in $CLUSTER ; do
+        cdb2sql ${CDB2_OPTIONS} --host $node $DBNAME "EXEC PROCEDURE sys.cmd.send('reql longreqfile <stdout>')"
+        cdb2sql ${CDB2_OPTIONS} --host $node $DBNAME "EXEC PROCEDURE sys.cmd.send('reql longrequest 0')"
+        cdb2sql ${CDB2_OPTIONS} --host $node $DBNAME "EXEC PROCEDURE sys.cmd.send('reql longsqlrequest 0')"
+    done
+}
+
+function test_logic
+{
+    $CDB2SQL_EXE $CDB2_OPTIONS $DBNAME default "insert into t values(1)"
+}
+
+function check_logs
+{
+    logfile=
+    found=0
+    sleep 20 # give time for .db file to flush
+    for node in $CLUSTER ; do
+        logfile="$TESTDIR/logs/$DBNAME.$node.db"
+        grep 'trigger->dormant' $logfile 
+        if [[ $? == 0 ]]; then
+            found=1
+            break
+        fi
+    done
+    [[ "$found" -ne "1" ]] && failexit "longrequest log not found"
+}
+
+function create_tables_sp_trigger
+{
+    cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./tables.sql
+    cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./dropsptrigger.sql
+    cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./sp.sql
+    cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./trigger.sql
+}
+
+function run_test
+{
+    create_tables_sp_trigger
+    setup_longreq
+    test_logic
+    check_logs
+}
+
+run_test
+echo "Success"
+exit 0

tests/longreq_sp_queries.test/sp.sql

@@ -0,0 +1,7 @@
+CREATE PROCEDURE dormant version '1'{
+local function main(event)
+    db:sleep(2)
+    db:exec("INSERT INTO triggered select * from generate_series(1,49999)")
+    return 0
+end
+}

tests/longreq_sp_queries.test/tables.sql

@@ -0,0 +1,4 @@
+DROP TABLE IF EXISTS t;
+DROP TABLE IF EXISTS triggered;
+CREATE TABLE t(a int primary key)$$
+CREATE TABLE triggered(b int)$$

tests/longreq_sp_queries.test/trigger.sql

@@ -0,0 +1 @@
+CREATE LUA TRIGGER dormant on (TABLE t for INSERT);