Repository navigation
fix: stop dropping other threads' database log lines during queries - #5197
Merged
Merged
Conversation
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
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
TL;DR
thread_localcount 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).logPrint, and every Logs row goes throughzmDbDo. The debug feedback loop the old toggle prevented is covered by a test. Lock order is nowdb_mutex→log_mutex→ queue mutex everywhere.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 runszmDbDo("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 inLogs.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_mutexfor 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 wholemysql_queryloop (src/zm_db.cpp:275-277). The level is one value for the process, andlogPrintqueues a Logs row onlyif (level <= mDatabaseLevel)(src/zm_logger.cpp:544). Sincec56d23a5a(2024-06-20) the window is the full query.43e7e612c,c56d23a5a); only the thread running the query needs that.mDatabaseLevelis written fromzmDbDoandzmDbQueue::processunder different locks and read inlogPrint: a data race.zmDbQueue::processlogs its backlog warning while holding the queue's mutex (src/zm_db.cpp:390,:401);logPrintholdslog_mutexwhiledbQueue.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 astatic thread_localcount;logPrintskips the database while the calling thread holds one.src/zm_db.cpp:zmDbDoand the backlog warning use the guard instead of saving, lowering and restoringmDatabaseLevel, which is now written only byLogger::initialise().zmDbQueue::processtakes the backlog size under its mutex and warns after unlocking.tests/zm_db_logging_live.cpp: three[notCI][dblive]cases (need a database, likezm_db_contention_live.cpp).Behaviour changes
api/logs, clients reading logszmDbDo's own lines stay out of Logs, now for the calling thread onlyAfter
fix/b3at522dc4e68(base6c0f976c2):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_loggerneeds small context edits.🤖 Generated with Claude Code