Skip to content

fix: stop dropping other threads' database log lines during queries - #5197

Merged
connortechnology merged 3 commits into
ZoneMinder:masterfrom
nabbi:fix/b3-db-log-lines
Oct 11, 2026
Merged

connortechnology merged 3 commits into
ZoneMinder:masterfrom
nabbi:fix/b3-db-log-lines

Conversation

@nabbi

@nabbi nabbi commented Oct 11, 2026

Copy link
Copy Markdown
Contributor

Automated PR, tested in a zm-holodeck sandbox. An AI agent (Claude Opus 5.5) reproduced the bug on a disposable ZoneMinder built from upstream master 6c0f976c2, wrote this fix and ran the checks below on the same lab. Minimal human review before opening: please review it as you would any contributor's PR.

TL;DR

  • Fixes: lines logged while another thread runs a database query never reach the Logs table, and the database log queue can deadlock threads that log.
  • Change: only the thread running a query is kept out of database logging (a thread_local count instead of setting the process-wide level to NOLOG), and the queue's backlog warning is logged after releasing the queue's mutex; 5 files, +206/-18 (173 of them tests).
  • Risk: every daemon logs through logPrint, and every Logs row goes through zmDbDo. The debug feedback loop the old toggle prevented is covered by a test. Lock order is now db_mutex → log_mutex → queue mutex everywhere.
  • Tested: reproduced before, passes after; the checks covering the diff are green.
Bug: reproduction and cause

Reproduction

Lab: upstream master 6c0f976c2, clean, Debian trixie, MariaDB, simulated cameras.
A Catch2 test (in the PR, [notCI][dblive]): thread A runs zmDbDo("DO SLEEP(2)"); 500 ms in, the main thread checks the logger's database level and logs an Info line, then waits up to 5 s for it in Logs.

/src/tests/zm_db_logging_live.cpp:97: FAILED:
  CHECK( Logger::fetch()->databaseLevel() == Logger::INFO )
with expansion:
  -6 == 0
/src/tests/zm_db_logging_live.cpp:101: FAILED:
  CHECK( WaitForLog(Marker("during"), std::chrono::seconds(5)) )
with expansion:
  false

First seen in a running zmc: its log file had a Warning and an Info line at 17:58:31.9644 and .9668; the Logs table had only the Info line logged 0.05 ms before them.
Deadlock: a thread holds db_mutex for 1 s so rows queue up while 4 threads log: dbQueue deadlock: 0 of 4 logging threads finished.

Cause

  • zmDbDo() sets the logger's database level to NOLOG for the whole mysql_query loop (src/zm_db.cpp:275-277). The level is one value for the process, and logPrint queues a Logs row only if (level <= mDatabaseLevel) (src/zm_logger.cpp:544). Since c56d23a5a (2024-06-20) the window is the full query.
  • The toggle keeps the "Success running sql query INSERT INTO Logs" line from queueing another insert at a debug database level (43e7e612c, c56d23a5a); only the thread running the query needs that.
  • mDatabaseLevel is written from zmDbDo and zmDbQueue::process under different locks and read in logPrint: a data race.
  • zmDbQueue::process logs its backlog warning while holding the queue's mutex (src/zm_db.cpp:390, :401); logPrint holds log_mutex while dbQueue.push() takes the queue's mutex (src/zm_db.cpp:417). Opposite order: deadlock.
Change and checks

Change

  • src/zm_logger.h, src/zm_logger.cpp: Logger::DatabaseLogPause, an RAII guard over a static thread_local count; logPrint skips the database while the calling thread holds one.
  • src/zm_db.cpp: zmDbDo and the backlog warning use the guard instead of saving, lowering and restoring mDatabaseLevel, which is now written only by Logger::initialise(). zmDbQueue::process takes the backlog size under its mutex and warns after unlocking.
  • tests/zm_db_logging_live.cpp: three [notCI][dblive] cases (need a database, like zm_db_contention_live.cpp).

Behaviour changes

Change Who sees it Intended / collateral Tested by
Lines from other threads during a query reach Logs Log view, api/logs, clients reading logs intended dblive test 1
zmDbDo's own lines stay out of Logs, now for the calling thread only same no change dblive test 2
Backlog warning logged after the queue's mutex is released nobody side fix (deadlock) dblive test 3

After

fix/b3 at 522dc4e68 (base 6c0f976c2): All tests passed (291 assertions in 6 test cases); unit-tests 14716 assertions / 249 cases; script-tests PASS=28; smoke PASS=11 XFAIL=1 (known). Not run: clients, contract (no API/web change), multi-server. 1.38: same bug; zm_logger needs small context edits.

🤖 Generated with Claude Code

nabbi and others added 3 commits October 10, 2026 12:49
Live-database tests ([notCI][dblive]) for how the logger and zmDbDo
interact:

- a line logged on one thread while another thread is inside zmDbDo
  reaches the Logs table
- zmDbDo's own debug lines stay out of Logs when the database level is
  debug, so inserting a Logs row cannot log another one without end
- a dbQueue backlog over 40 rows does not deadlock threads that log

The first fails on master: zmDbDo sets the process-wide database log
level to NOLOG for the whole query, so the line is dropped.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
zmDbDo lowered the logger's database level to NOLOG for as long as its
query ran, so that its own lines (and, at a debug database level, the line
about every insert into Logs) could not queue more inserts into Logs. The
level is shared by the whole process, so every line any other thread
logged in that window never reached the Logs table or the web log view,
while the log file and syslog still had it. The save and restore of that
shared level from several threads is also a data race: a thread can
restore a stale NOLOG and leave database logging off.

Replace the toggle with Logger::DatabaseLogPause, a thread_local count
that keeps only the current thread's lines out of the database. zmDbDo
and the queue's backlog warning use it; mDatabaseLevel is no longer
written outside of initialise().

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
zmDbQueue::process logged its "db queue size has grown larger" warning
while holding the queue mutex. logPrint holds the logger's mutex while it
pushes a Logs row, which takes the queue mutex. With more than 40 rows
waiting, a thread logging to the database and the queue thread could each
hold one of the two locks and wait for the other, stopping every thread
that logs.

Take the backlog size under the lock and warn after releasing it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@connortechnology
connortechnology merged commit 378b774 into ZoneMinder:master Oct 11, 2026
10 checks passed
connortechnology pushed a commit that referenced this pull request Oct 11, 2026
…5197)

* test: cover lines logged to the database while a query runs

Live-database tests ([notCI][dblive]) for how the logger and zmDbDo
interact:

- a line logged on one thread while another thread is inside zmDbDo
  reaches the Logs table
- zmDbDo's own debug lines stay out of Logs when the database level is
  debug, so inserting a Logs row cannot log another one without end
- a dbQueue backlog over 40 rows does not deadlock threads that log

The first fails on master: zmDbDo sets the process-wide database log
level to NOLOG for the whole query, so the line is dropped.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix: stop dropping other threads' database log lines during queries

zmDbDo lowered the logger's database level to NOLOG for as long as its
query ran, so that its own lines (and, at a debug database level, the line
about every insert into Logs) could not queue more inserts into Logs. The
level is shared by the whole process, so every line any other thread
logged in that window never reached the Logs table or the web log view,
while the log file and syslog still had it. The save and restore of that
shared level from several threads is also a data race: a thread can
restore a stale NOLOG and leave database logging off.

Replace the toggle with Logger::DatabaseLogPause, a thread_local count
that keeps only the current thread's lines out of the database. zmDbDo
and the queue's backlog warning use it; mDatabaseLevel is no longer
written outside of initialise().

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix: warn about the database queue backlog outside the queue's lock

zmDbQueue::process logged its "db queue size has grown larger" warning
while holding the queue mutex. logPrint holds the logger's mutex while it
pushes a Logs row, which takes the queue mutex. With more than 40 rows
waiting, a thread logging to the database and the queue thread could each
hold one of the two locks and wait for the other, stopping every thread
that logs.

Take the backlog size under the lock and warn after releasing it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
(cherry picked from commit 378b774)

Backport notes: release-1.38 has no smDoLogRotate next to the new member, and
lists the database tests elsewhere in tests/CMakeLists.txt. On 1.38,
Logger::initialise() caps each target's level at Info without ZM_LOG_DEBUG, not
just the overall level, so the live test sets the database level itself before
raising the overall level.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants