log long running sqls executed from a stored procedure

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;
@@ -2199,6 +2200,16 @@ static int dbstmt_bind_int(Lua lua, dbstmt_t *dbstmt)
     return stmt_bind(lua, dbstmt->stmt);
 }
 
+static void lua_set_clnt_sql(struct sqlclntstate *clnt, char *sql) {
+    if (!clnt || !sql) return;
+    clnt->sql = sql;
+}
+
+static void lua_set_clnt_origin(struct sqlclntstate *clnt, char *origin) {
+    if (!clnt || !origin) return;
+    clnt->origin = origin;
+}
+
 static int lua_prepare_sql_int(SP sp, const char *sql, sqlite3_stmt **stmt,
                                struct sql_state *rec, int flags)
 {
@@ -2213,7 +2224,10 @@ 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, "trigger->%s",sp->spname); 
+    /* we also need to change the clnt->origin : periodic longreq logger uses it
+     */
+    lua_set_clnt_sql(sp->clnt, (char *)sql);
 retry:
     memset(&err, 0, sizeof(struct errstat));
     if (sp->initial) {
@@ -2311,6 +2325,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 +2499,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 +2561,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 +3104,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 +3781,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 +6784,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);

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);