fix: keep only the database queue thread out of database logging

[connortechnology]

Follow-up to #5197, from its review.

#5197 replaced the process-wide NOLOG toggle with Logger::DatabaseLogPause, held inside every zmDbDo(). That keeps the calling thread out of the database for the whole query, so the thread's own errors about the query never reached Logs: "Can't run query ..." and the lock contention retries were only in the log files. It was the same before #5197, but now that the pause is per thread it doesn't have to be.

The feedback loop the pause exists for only starts where Logs rows are inserted, on the dbQueue thread. So this holds one DatabaseLogPause on the dbQueue thread for its whole life, at the top of zmDbQueue::process(), and none in zmDbDo().

• The queue thread logs nothing to the database: its own "Success running sql query INSERT INTO Logs" lines and the backlog warning, as before.
• Every other thread's query lines reach Logs: errors always, and success lines when the database log level is debug.

Tradeoff to review: the queue also carries Event, Frame and Monitor_Status writes (zm_event.cpp, zm_monitor.cpp), so an error in one of those async writes still stays out of Logs. Pausing only for the Logs inserts would get those too, but it would mean zmDbQueue recognising the logger's SQL. I went with the whole thread.

At a debug database level, ordinary queries' success lines now also land in Logs, one extra row per query. That only applies when someone has set the database level to debug.

Tests

tests/zm_db_logging_live.cpp ([notCI][dblive]):

• "zmDbDo's own debug lines stay out of Logs" becomes "the queue thread's inserts into Logs do not log themselves". There must be no "Success running sql query INSERT INTO Logs" rows and the row count must settle, while DO 1 run on the test's thread logs its success line.
• New: "an error from a query on another thread reaches Logs". It runs a query on a missing table and waits for "Can't run query".

Both fail with #5197 as merged. All 7 [dblive] cases pass on master plus this change against MariaDB (run as www-data, zm.conf credentials), and so does the unit suite: 249 cases, 14718 assertions.

🤖 Generated with Claude Code

[connortechnology]

@nabbi could you review this follow-up to your #5197? It moves the DatabaseLogPause from zmDbDo() to the dbQueue thread, so query errors from other threads reach Logs. The open question is in the description: pause the whole queue thread (this PR) or only the Logs inserts.

[nabbi]

Automated review, tested in a zm-holodeck sandbox. An AI agent (Claude Opus 5.5) built this PR on master 25dba3267, ran it on a simulated 5-camera ZoneMinder, and compared it with master and with one small change on top. Minimal human review before posting.

TL;DR: The direction looks right to us. With this PR, errors and retries from zmc's own synchronous queries (start-up, exit, reconnect) reach Logs again, and at a debug database level nothing about the queue's Logs inserts loops back. One gap remains: the queue thread still keeps all of its lines out of Logs, so errors from queued writes (Monitor_Status every 10 s, Events, Frames, Stats) never reach Logs. Under lock contention in our test, 6 of 9 "Giving up on query" errors were invisible. A small change closes the gap without bringing the loop back: tag each queued row as a Logs insert or not, and pause database logging only around the Logs inserts and the backlog warning (diff below, +21/−14 in src, plus one test). Could you take it into this PR, or as a follow-up?

Suggested change and test evidence

The change. zmDbQueue::push(std::string &&sql, bool log_row = false). The queue stores pair<string,bool>. logPrint pushes with true. process() drops the thread-wide DatabaseLogPause and creates one only around a log_row insert and around the "db queue size has grown" warning. DatabaseLogPause stays thread_local, so no new shared state is added. One new [dblive] test: "an error from a queued write reaches Logs". (Diff below.)

Builds: master 25dba3267; master + this PR; master + this PR + the change ("PR+F"); and the same plus #5203. Each was built from a clean tree in one sandbox and run under the same conditions.

Scenario	master	this PR	PR+F
Debug database level, 5 cameras, 120 s: rows about inserting into Logs; rate	0; 57.2k rows/min, flat	0; 57.2k flat	0; 57.2k flat
zmc start-up INSERT fails (main thread): error rows in Logs	0	2	2
Queued Monitor_Status write fails: error rows in Logs / syslog	0 / 3	0 / 2	2 / 2
Row lock held, innodb_lock_wait_timeout=1: retry + give-up rows in Logs (file log: about 50 + 9; syslog: 9 give-ups)	0 + 0	15 + 3	49 + 9
Database paused 30 s: monitors back / queue drained (default; debug)	6.6 / 6.7 s; 3.3 / 15.9 s	6.5 / 6.6; 3.3 / 15.9	6.5 / 6.6; 3.3 / 15.9
Default-level Logs rows/min, 5 monitors	5	8	4
30 SIGHUP reloads of every zmc	pass	pass	pass

• Backlog warning count: it varies 36x between runs of the same master build (41 to 1498 per 120 s). The queue size stays the same on all three builds: p95 below about 125, never over 200.
• ThreadSanitizer: on this PR and on PR+F, the only reports in zm_db/zm_logger are ones master has too: the unlocked zmDbConnected read in logPrint, and the reload races fix: re-initialise the logger in place on reload instead of deleting it #5203 addresses. None is in zmDbQueue::process.
• AddressSanitizer: 0 reports on either.
• Unit tests: 249 cases pass on both. The [dblive] tests against a live database pass on PR+F (8 cases). On this PR, only the new queued-write case fails.
• Smoke and the scoped checks: pass, including with fix: re-initialise the logger in place on reload instead of deleting it #5203 merged on top (clean merge).
• Not covered by either version: lines logged while the connection is down are still dropped (logPrint checks zmDbConnected), so a queued write that fails because the connection was lost still does not reach Logs.

Diff on top of this PR (`git diff pr-5208..alt/f-logrow -- src tests`)

diff --git a/src/zm_db.cpp b/src/zm_db.cpp
index 1d0999726..de0ec9a27 100644
--- a/src/zm_db.cpp
+++ b/src/zm_db.cpp
@@ -379,12 +379,6 @@ void zmDbQueue::stop() {
 }
 
 void zmDbQueue::process() {
-  // This thread runs the inserts into Logs. A line it logged would queue another
-  // insert, and at a debug database level the "Success running sql query" line
-  // of each insert would do so without end, so nothing it logs goes to the
-  // database. Other threads log there as usual, including the errors and debug
-  // lines of their own queries.
-  Logger::DatabaseLogPause pause_db_logging;
   std::unique_lock<std::mutex> lock(mMutex);
 
   while (!mTerminate and !zm_terminate) {
@@ -393,7 +387,8 @@ void zmDbQueue::process() {
     }
     while (!mQueue.empty()) {
       size_t backlog = mQueue.size();
-      std::string sql = std::move(mQueue.front());
+      std::string sql = std::move(mQueue.front().first);
+      bool log_row = mQueue.front().second;
       mQueue.pop();
       // My idea for leaving the locking around each sql statement is to allow
       // other db writers to get a chance
@@ -401,19 +396,30 @@ void zmDbQueue::process() {
       if (backlog > 40) {
         // Not while holding mMutex: logging takes the logger's mutex, and a
         // thread already holding that one waits on mMutex to push its row.
+        // A row about the backlog would only add to it, so none is written.
+        Logger::DatabaseLogPause pause_db_logging;
         Warning("db queue size has grown larger %zu than 40 entries", backlog);
       }
-      zmDbDo(sql);
+      if (log_row) {
+        // An insert into Logs. A line about it would queue another insert, and at
+        // a debug database level its "Success running sql query" line would do
+        // so without end, so lines about these inserts stay out of the database.
+        // Lines about the other queued writes (events, frames, stats) go there.
+        Logger::DatabaseLogPause pause_db_logging;
+        zmDbDo(sql);
+      } else {
+        zmDbDo(sql);
+      }
       lock.lock();
     }
   }
 }  // end void zmDbQueue::process()
 
-void zmDbQueue::push(std::string &&sql) {
+void zmDbQueue::push(std::string &&sql, bool log_row) {
   {
     std::unique_lock<std::mutex> lock(mMutex);
     if (mTerminate) return;
-    mQueue.push(std::move(sql));
+    mQueue.emplace(std::move(sql), log_row);
   }
   mCondition.notify_all();
 }
diff --git a/src/zm_db.h b/src/zm_db.h
index a9820f40b..b90178cf8 100644
--- a/src/zm_db.h
+++ b/src/zm_db.h
@@ -28,6 +28,7 @@
 #include <queue>
 #include <string>
 #include <thread>
+#include <utility>
 #include <unistd.h>
 
 // How many times a query that lost a lock race is re-run before being
@@ -45,7 +46,8 @@ useconds_t zmDbContentionBackoff(int attempt);
 
 class zmDbQueue {
  private:
-  std::queue<std::string> mQueue;
+  // The flag marks rows the logger queued (inserts into Logs).
+  std::queue<std::pair<std::string, bool>> mQueue;
   std::thread             mThread;
   std::mutex              mMutex;
   std::condition_variable mCondition;
@@ -53,7 +55,7 @@ class zmDbQueue {
  public:
   zmDbQueue();
   ~zmDbQueue();
-  void push(std::string &&sql);
+  void push(std::string &&sql, bool log_row = false);
   void process();
   void stop();
 };
diff --git a/src/zm_logger.cpp b/src/zm_logger.cpp
index 0aa3ffaf4..ccdb16293 100644
--- a/src/zm_logger.cpp
+++ b/src/zm_logger.cpp
@@ -553,7 +553,7 @@ void Logger::logPrint(bool hex, const char *filepath, int line, int level, const
                                  "( %jd.%06" PRIi64 ", '%s', %d, %d, %d, '%s', '%s', '%s', %d )",
                                  static_cast<intmax_t>(now_sec), static_cast<int64>(now_frac.count()), mId.c_str(), staticConfig.SERVER_ID, tid, level, classString,
                                  escapedString.c_str(), file, line);
-      dbQueue.push(std::move(sql_string));
+      dbQueue.push(std::move(sql_string), true);
     }
   }  // end if level <= mDatabaseLevel
 
diff --git a/src/zm_logger.h b/src/zm_logger.h
index f402e893b..f715844f0 100644
--- a/src/zm_logger.h
+++ b/src/zm_logger.h
@@ -153,7 +153,7 @@ class Logger {
   // While one of these is alive, lines logged on the thread that created it
   // are not written to the database. Every other thread keeps logging there.
   //
-  // The database queue's thread holds one for its whole life: at a debug
+  // The database queue holds one around each insert into Logs: at a debug
   // database level, inserting a Logs row logs a line about that insert, which
   // would queue another insert, and so on without end.
   class DatabaseLogPause {
diff --git a/tests/zm_db_logging_live.cpp b/tests/zm_db_logging_live.cpp
index 57eb06f76..5a032ac20 100644
--- a/tests/zm_db_logging_live.cpp
+++ b/tests/zm_db_logging_live.cpp
@@ -133,6 +133,16 @@ TEST_CASE("an error from a query on another thread reaches Logs", "[notCI][dbliv
   CHECK(WaitForLog("Can't run query%" + table + "%", std::chrono::seconds(5)));
 }
 
+TEST_CASE("an error from a queued write reaches Logs", "[notCI][dblive]") {
+  // Events, frames and stats are written through dbQueue too. Only the queue's
+  // inserts into Logs are kept from logging; its other writes report errors.
+  LiveLogger live(Logger::INFO);
+
+  const std::string table = stringtf("zm_test_dblog_queued_missing_%d", getpid());
+  dbQueue.push(stringtf("UPDATE `%s` SET x=1", table.c_str()));
+  CHECK(WaitForLog("Can't run query%" + table + "%", std::chrono::seconds(5)));
+}
+
 TEST_CASE("a backlog in dbQueue does not deadlock threads that log", "[notCI][dblive]") {
   // With more than 40 rows waiting, the queue thread warns about the backlog.
   // It used to do that while holding the queue's mutex, and logPrint takes the

🤖 Generated with Claude Code

[connortechnology]

Thanks @nabbi, taken into this PR as 4bc4c6e: rows the logger queues are flagged, and only those inserts and the backlog warning run with the pause, so errors from the queued Events/Frames/Stats/Monitor_Status writes reach Logs. I also rebased onto current master. Here all 8 [dblive] cases pass (including your queued-write test and the no-loop test at a debug database level), and so does the unit suite (249 cases). Agreed that lines logged while the connection is down are a separate gap.