fix longreq logs

Signed-off-by: Emelia Lei <wlei29@bloomberg.net>

Author: emelialei88

db/osql_srs.c

@@ -321,6 +321,7 @@ static int srs_tran_replay_int(struct sqlclntstate *clnt, int(dispatch_fn)(struc
         clnt->start_gen = bdb_get_rep_gen(thedb->bdb_env);
         LISTC_FOR_EACH(&osql->history->lst, item, lnk)
         {
+            clnt->done = 0; /* reset done flag */
             restore_stmt(clnt, item);
             if ((rc = dispatch_fn(clnt)) != 0)
                 break;
@@ -373,6 +374,7 @@ static int srs_tran_replay_int(struct sqlclntstate *clnt, int(dispatch_fn)(struc
     }
 
     osql_set_replay(__FILE__, __LINE__, clnt, OSQL_RETRY_NONE);
+    clnt->verify_retries = 0;
 
     return rc;
 }

db/reqlog.c

@@ -1603,7 +1603,7 @@ static void log_header_ll(struct reqlogger *logger, struct output *out,
     struct reqlog_print_callback_args args;
 
     if (out == long_request_out) {
-        dumpf(logger, out, "LONG REQUEST %d msec ", U2M(logger->durationus));
+        dumpf(logger, out, "LONG REQUEST %d msec", U2M(logger->durationus));
     } else {
         dumpf(logger, out, "%s %d msec ", logger->request_type,
               U2M(logger->durationus));
@@ -1614,8 +1614,7 @@ static void log_header_ll(struct reqlogger *logger, struct output *out,
     if (gbl_fingerprint_queries && logger->have_fingerprint) {
         char expanded_fp[2 * FINGERPRINTSZ + 1];
         util_tohex(expanded_fp, logger->fingerprint, FINGERPRINTSZ);
-        dumpf(logger, out, "for fingerprint %.*s", FINGERPRINTSZ * 2,
-                    expanded_fp);
+        dumpf(logger, out, " for fingerprint %.*s", FINGERPRINTSZ * 2, expanded_fp);
     }
 
     struct sqlclntstate *clnt = logger->clnt;
@@ -1630,6 +1629,10 @@ static void log_header_ll(struct reqlogger *logger, struct output *out,
         dumpf(logger, out, " clntapi %s", logger->api_type);
     }
 
+    if (logger->vreplays) {
+        dumpf(logger, out, " verify replays=%d", logger->vreplays);
+    }
+
     if (out == long_request_out && is_running) {
         /* No need to include 'rc' if the request is still running. */
         dumpf(logger, out, " **running**\n");
@@ -1921,6 +1924,16 @@ inline void reqlog_set_rqid(struct reqlogger *logger, void *id, int idlen)
     logger->have_id = 1;
 }
 
+void reqlog_set_rqid_from_clnt(struct reqlogger *logger, struct sqlclntstate *clnt)
+{
+    unsigned long long rqid = clnt->osql.rqid;
+    if (rqid != 0 && rqid != OSQL_RQID_USE_UUID)
+        reqlog_set_rqid(logger, &rqid, sizeof(rqid));
+    else if (!comdb2uuid_is_zero(clnt->osql.uuid))
+        /* have an "id_set" instead? */
+        reqlog_set_rqid(logger, clnt->osql.uuid, sizeof(uuid_t));
+}
+
 static int current_long_request_count = 0;
 static int current_long_request_duration_ms = 0;
 static int current_longest_long_request_ms = 0;
@@ -2019,6 +2032,8 @@ void reqlog_long_running_clnt(struct sqlclntstate *clnt)
 
     logger.rc = 0;
 
+    reqlog_set_rqid_from_clnt(&logger, clnt);
+
     /* Should this long running statement be reported at this instant? */
 
     int duration_beyond_thresh_sec = (duration_ms - gbl_sql_time_threshold) / 1000;
@@ -2062,10 +2077,6 @@ void reqlog_long_running_clnt(struct sqlclntstate *clnt)
         reqlog_set_fingerprint(&logger, (const char *)fp, FINGERPRINTSZ);
     }
 
-    if (logger.vreplays) {
-        reqlog_logf(&logger, REQL_INFO, "verify replays=%d", logger.vreplays);
-    }
-
     flushdump(&logger, NULL);
 
     log_header(&logger, long_request_out, 1);

db/reqlog.h

@@ -89,6 +89,7 @@ uint64_t reqlog_get_queue_time(const struct reqlogger *logger);
 void reqlog_reset_fingerprint(struct reqlogger *logger, size_t n);
 void reqlog_set_fingerprint(struct reqlogger *logger, const char *fp, size_t n);
 void reqlog_set_rqid(struct reqlogger *logger, void *id, int idlen);
+void reqlog_set_rqid_from_clnt(struct reqlogger *logger, struct sqlclntstate *clnt);
 void reqlog_set_event(struct reqlogger *logger, evtype_t evtype);
 evtype_t reqlog_get_event(struct reqlogger *logger);
 void reqlog_add_table(struct reqlogger *logger, const char *table);

db/sqlinterfaces.c

@@ -203,6 +203,8 @@ void handle_sql_intrans_unrecoverable_error(struct sqlclntstate *clnt);
 void comdb2_set_sqlite_vdbe_dtprec(Vdbe *p);
 static int execute_sql_query_offload(struct sqlthdstate *, struct sqlclntstate *);
 static int record_query_cost(struct sql_thread *, struct sqlclntstate *);
+static void free_normalized_sql(struct sqlclntstate *clnt);
+void free_original_normalized_sql(struct sqlclntstate *clnt);
 
 static int sql_debug_logf_int(struct sqlclntstate *clnt, const char *func,
                               int line, const char *fmt, va_list args)
@@ -1247,13 +1249,7 @@ static void sql_statement_done(struct sql_thread *thd, struct reqlogger *logger,
 
     thd->crtshard = 0;
 
-    unsigned long long rqid = clnt->osql.rqid;
-    if (rqid != 0 && rqid != OSQL_RQID_USE_UUID)
-        reqlog_set_rqid(logger, &rqid, sizeof(rqid));
-    else if (!comdb2uuid_is_zero(clnt->osql.uuid)) {
-        /* have an "id_set" instead? */
-        reqlog_set_rqid(logger, clnt->osql.uuid, sizeof(uuid_t));
-    }
+    reqlog_set_rqid_from_clnt(logger, clnt);
 
     LISTC_T(struct sql_hist) lst;
     listc_init(&lst, offsetof(struct sql_hist, lnk));
@@ -1266,15 +1262,15 @@ static void sql_statement_done(struct sql_thread *thd, struct reqlogger *logger,
     h->cost.time = comdb2_time_epochms() - thd->startms;
     h->cost.prepTime = thd->prepms;
     h->when = thd->stime;
-    h->txnid = rqid;
+    h->txnid = clnt->osql.rqid;
 
     time_metric_add(thedb->service_time, h->cost.time);
     clnt->last_cost = (int64_t) h->cost.cost;
 
     /* request logging framework takes care of logging long sql requests */
     reqlog_set_cost(logger, h->cost.cost);
-    if (rqid) {
-        reqlog_logf(logger, REQL_INFO, "rqid=%llx", rqid);
+    if (clnt->osql.rqid) {
+        reqlog_logf(logger, REQL_INFO, "rqid=%llx", clnt->osql.rqid);
     }
     reqlog_set_netwaitus(logger, clnt->netwaitus);
 
@@ -1696,17 +1692,15 @@ static void reqlog_setup_begin_commit_rollback(struct sqlthdstate *thd, struct s
     query_stats_setup(thd, clnt);
 
     if (reqlog_get_event(thd->logger) == EV_SQL) {
-        unsigned char fp[FINGERPRINTSZ];
-        size_t len;
         char stmt[9] = {0}; // begin, commit, or rollback
         int i = 0;
         for (const char *s = clnt->sql; *s != '\0' && *s != ' ' && i < sizeof(stmt) - 1; s++, i++) {
             stmt[i] = (char) tolower(*s);
         }
-        if (gbl_fingerprint_queries) {
-            calc_fingerprint(stmt, &len, fp);
-            reqlog_set_fingerprint(thd->logger, (const char *)fp, FINGERPRINTSZ);
-        }
+
+        /* Reset so we don't print the stale fingerprint */
+        free_normalized_sql(clnt);
+        free_original_normalized_sql(clnt);
     }
     log_queue_time(thd->logger, clnt);
 }
@@ -1838,7 +1832,7 @@ int handle_sql_begin(struct sqlthdstate *thd, struct sqlclntstate *clnt,
 
     if (sideeffects == TRANS_CLNTCOMM_NORMAL) {
         /* for chunks and SPs, don't end the request */
-        reqlog_end_request(thd->logger, -1, __func__, __LINE__);
+        reqlog_end_request(thd->logger, rc, __func__, __LINE__);
     }
 
     return rc;
@@ -2392,7 +2386,7 @@ int handle_sql_commitrollback(struct sqlthdstate *thd,
         clnt->osql.xerr.errval = ERR_BLOCK_FAILED + ERR_VERIFY;
         sql_set_sqlengine_state(clnt, __FILE__, __LINE__,
                                 SQLENG_NORMAL_PROCESS);
-        outrc = CDB2ERR_VERIFY_ERROR;
+        outrc = rc = CDB2ERR_VERIFY_ERROR;
         Pthread_mutex_lock(&clnt->wait_mutex);
         clnt->ready_for_heartbeats = 0;
         Pthread_mutex_unlock(&clnt->wait_mutex);
@@ -2537,12 +2531,13 @@ int handle_sql_commitrollback(struct sqlthdstate *thd,
 
 done:
     reset_clnt_flags(clnt);
+    reqlog_set_rqid_from_clnt(thd->logger, clnt);
     if (clnt->osql.sock_started == 0)
         comdb2uuid_clear(clnt->osql.uuid);
 
     if (sideeffects == TRANS_CLNTCOMM_NORMAL) {
         /* end request only for non-chunk and non-SP transactions */
-        reqlog_end_request(thd->logger, -1, __func__, __LINE__);
+        reqlog_end_request(thd->logger, rc, __func__, __LINE__);
     }
 
     /* if this is a retry, let the upper layer free the structure */

tests/longreq_sanity.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_sanity.test/runit

@@ -0,0 +1,136 @@
+#!/usr/bin/env bash
+bash -n "$0" | exit 1
+
+set -e
+dbnm=$1
+
+mach=$(cdb2sql --tabs ${CDB2_OPTIONS} $dbnm default "SELECT comdb2_host()")
+
+if [ "$mach" = "" ]; then
+   echo "could not retrieve hostname" >&2
+   exit 1
+fi
+
+r="cdb2sql -s ${CDB2_OPTIONS} $dbnm default --host $mach"
+
+if [ -n "$CLUSTER" ] ; then
+    logfile="$TESTDIR/logs/$dbnm.$mach.db"
+else
+    logfile="$TESTDIR/logs/$dbnm.db"
+fi
+
+$r << "EOF" >/dev/null
+@send reql longreqfile <stdout>
+@send reql longsqlrequest 1
+put tunable longreq_log_freq_sec 1
+EOF
+
+$r "create table if not exists tlr (id int, v int)" >/dev/null
+
+$r << "EOF" >/dev/null
+set maxtransize 200000
+insert into tlr select value, value from generate_series(1, 100000)
+EOF
+
+
+# Use a FIFO to control pid1's transaction timing:
+# pid1: begin + update, then wait for pid2 to commit a conflicting update, then commit.
+# This forces a verify retry on pid1's commit.
+fifo=$(mktemp -u)
+outfile=$(mktemp)
+mkfifo $fifo
+
+$r < $fifo > $outfile 2>&1 &
+pid1=$!
+exec 3> $fifo
+
+echo "set maxtransize 200000" >&3
+echo "begin" >&3
+echo "update tlr set v=v+1" >&3
+echo "select 'update_done'" >&3
+while ! grep -q 'update_done' $outfile; do sleep 0.1; done
+
+$r << "EOF"
+set maxtransize 200000
+update tlr set v=v-1
+EOF
+
+echo "commit" >&3
+exec 3>&-
+wait $pid1
+rm -f $fifo $outfile
+
+sleep 2
+
+# ---- Test 1: begin/commit should not have fingerprint ----
+echo "Test 1: begin/commit should not have fingerprint"
+
+if awk '/LONG REQUEST/{hdr=$0} /sql=(begin|commit)/ && hdr ~ /for fingerprint/{found=1} END{exit !found}' $logfile; then
+    echo "FAIL: begin or commit has fingerprint" >&2
+    exit 1
+fi
+
+echo "Test 1 passed"
+
+# ---- Test 2: begin/commit should not have negative rc ----
+echo "Test 2: no negative rc on begin/commit"
+
+if awk '/LONG REQUEST/{hdr=$0} /sql=(begin|commit)/ && hdr ~ /rc -/{found=1} END{exit !found}' $logfile; then
+    echo "FAIL: begin or commit has negative rc" >&2
+    exit 1
+fi
+
+echo "Test 2 passed"
+
+# ---- Test 3: **running** logs appear during verify retry with replay count ----
+echo "Test 3: running logs have verify replays during retry"
+
+if ! grep -q 'verify replays=.*\*\*running\*\*' $logfile; then
+    echo "FAIL: no **running** log with verify replays found" >&2
+    exit 1
+fi
+
+echo "Test 3 passed"
+
+# ---- Test 4: at least one **running** log has rqid ----
+echo "Test 4: at least one running log has rqid"
+
+# rqid may be empty after watchdog kicks off for a long running transaction 
+# but before osql session starts and assigns an uuid.
+# Check that at least one running log has a non-empty rqid.
+if ! grep '\*\*running\*\*' $logfile | grep -q 'rqid [0-9a-f]'; then
+    echo "FAIL: no **running** log has rqid" >&2
+    exit 1
+fi
+
+echo "Test 4 passed"
+
+# ---- Test 5: final commit completion log has rqid ----
+echo "Test 5: commit completion has rqid"
+
+if awk '/LONG REQUEST/{hdr=$0} /sql=commit,/ && hdr ~ /rqid  from/{found=1} END{exit !found}' $logfile; then
+    echo "FAIL: commit completion log has empty rqid" >&2
+    exit 1
+fi
+
+echo "Test 5 passed"
+
+# ---- Test 6: verify replays do not leak across transactions ----
+echo "Test 6: verify replays do not leak to next transaction"
+
+# Run another long transaction after the replay test
+$r << "EOF"
+set maxtransize 200000
+update tlr set v=v+2
+EOF
+
+# Check that the most recent update log does not have verify replays
+if tail -20 $logfile | grep 'sql=UPDATE tlr SET v = v + 2' | grep -q 'verify replays'; then
+    echo "FAIL: verify replays leaked to subsequent transaction" >&2
+    exit 1
+fi
+
+echo "Test 6 passed"
+
+echo "All tests passed."
+exit 0

tests/replay_eventlog.test/fingerprints_freq.exp

@@ -15,7 +15,6 @@
    1000 7b3aa6d46d54b8a092b8c3e74a1fc7d0 insert into t1(  alltype
     100 8b048737cee209884c0eb5b86f9815f7 insert into t1(alltypes_
       1 8be5e8c404c7e6c72b3a5d926cc150fd create table t1  { // th
-      2 8d589afa4dfaeeed85fff5aa78e5ff6a begin
     500 92e6e3090f8f99f9ed0b9015f849d8e3 insert into t1(alltypes_
       8 aa98684e80e6fa9bd1cb3ee39443df7e select count(*) from t1
     500 aefd75efcaf1d7e65205373fc5a09b89 update t1 set alltypes_s
@@ -26,5 +25,3 @@
     110 e4510162feae7bd9a746c798ad56027d insert into t1(alltypes_
      10 f2c85b80eb883ee3c1eb184a8bca4e4d update t1 set alltypes_u
       1 f49bb0b4877aac4df9adb8d4e097e140 select * from t1 order b
-      1 fff66e9b3d962fa319c8068b5c1997cd rollback
-      1 fffca4d67ea0a788813031b8bbc3b329 commit