kg retrieval logs merge - #140
Merged
Merged
Conversation
The subservices that do the actual knowledge-graph retrieval report their work -- which KPs they called, what timed out, why an edge came back empty -- in the TRAPI `logs` list of the response they POST to /callback. The merge only ever built a fresh message (or, on the direct-lookup path, returned the callback message whose logs finish_query then shadows with the ones spliced in from the log store), so those entries were dropped and never reached the query's log list. Lift them off each callback in the merge child and hand them back with the child's own records, so the parent folds them into the query logger and save_logs flushes them alongside everything else. Entries below the query's requested log level are dropped, malformed `logs` fields are survivable, and MERGE_MAX_CALLBACK_LOGS (default 1000) caps how many entries a single callback can contribute so a chatty subservice can't flood the query's logs. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012QwdpTHjvsiTS1wfuq395b
The duplication had nothing to do with the callbacks themselves -- two pre-existing bugs in the log plumbing compounded, and folding the KG retrieval logs into that plumbing made them obvious. _build_task_context builds "a logger per task" with logging.getLogger, but the name is keyed on the query, so every task a worker runs for that query lands on the same process-wide logger object -- and each one added another QueryLogHandler to it. save_logs then picked whichever handler came first and, crucially, never emptied it. So the first handler accumulated every record for the query for the life of the process, and each task's flush wrote the whole pile again: the Nth callback's merge re-persisted the previous N-1 callbacks' logs. merge_message feels this hardest, since a query gets one wake task per callback. - QueryLogHandler.drain() empties the queue as it hands the records over, so a later flush of the same handler can't write them a second time. A failed write puts them back (they're nowhere else now). - attach_query_handler() reuses a handler the logger already has instead of stacking another. Applied to the task/worker loggers and to the server routes -- /response built its handler on a fixed logger name, so it grew one per request. - Since flushing is now destructive, a lost write would lose logs rather than duplicate them: store the logs as a Redis list that each flush appends to (atomically, with the TTL refresh in the same round trip) instead of rewriting the whole array read-modify-write. A query has several concurrent log producers -- the callback handler, each worker stage, one merge task per callback -- so those rewrites were racing. A key still holding the old whole-blob format is converted in place. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012QwdpTHjvsiTS1wfuq395b
One query fans out into many retrievals whose logs all land in a single
list, so an untagged "KP timed out" line says nothing about which retrieval
it came from. Prefix every entry taken off a callback with [callback_id] --
the same tag the callback handler and the merge already use -- so a line
joins up with the rest of that retrieval's trail.
The lookup end of that trail was missing at the default log level: the
dispatch was logged at DEBUG (with the id only buried in the callback URL),
and BTE's direct path logged nothing at all. Log it at INFO with the tag in
all four dispatch sites, and name the id on the lookup-failed lines, which
had it available and didn't print it.
A query's logs now read:
[a1b2c3d4] Sending lookup query to http://retrieval/asyncquery
[a1b2c3d4] Got back 12 results.
[a1b2c3d4] Querying KP infores:automat-robokop
[a1b2c3d4] KP infores:text-mining timed out after 30s
[a1b2c3d4] Merged 1 callback(s) in 0.42s
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_012QwdpTHjvsiTS1wfuq395b
Codecov Report❌ Patch coverage is
... and 4 files with indirect coverage changes Continue to review full report in Codecov by Harness.
🚀 New features to boost your workflow:
|
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
2 participants
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.
Include Retriever/Gandalf logs in the final message response