Repository navigation
fix: log per-event traffic and webhook notices at debug - #377
Merged
Merged
Conversation
'Skipping webhook. Not subscribed for this type' fires whenever a session receives an event it did not subscribe to, and 'No webhook set for user' whenever one without a webhook does — both describe supported setups, not problems, and both are emitted once per discarded event. On a 150-session instance they were ~90% of every line left at LOG_LEVEL=warn: the log file rotated every couple of minutes, taking the real warnings with it. LOG_LEVEL=debug brings them back when needed.
'Message Received', 'Message delivered', 'Message was read', 'Chat Presence
received', 'Facebook message received' and the delete/edit detections fire
once per event the server receives, so their volume tracks inbound traffic
rather than anything an operator acts on. On a 150-session instance they
were ~9.7k lines/min on their own.
Actions the API performs on request ('Message sent', 'Message deleted',
'Message pinned', ...) stay at info: those are the audit trail of what the
caller asked for, and there is one per API call.
eliasmeireles
changed the title
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.
Problem
Two kinds of log lines scale with traffic rather than with anything an operator can act on.
1. Webhook notices logged at
Warn, once per discarded event:Skipping webhook. Not subscribed for this type— the session subscribed to a subset of the events, so every other event it receives logs a warning.No webhook set for user— the session has no webhook at all (RabbitMQ-only or polling setups).2. Per-event traffic logged at
Info:Message Received,Message delivered,Message was read,Chat Presence received,Facebook message received, plus the delete/edit detections.Measured on a 150-session instance over one minute:
28,123 lines/min in total. The container log file rotated every couple of minutes, so by the time an incident was investigated the relevant lines were already gone — that cost us real debugging time after a
Client outdatedoutage, where the surviving window was shorter than the time it took to notice the problem.Setting
LOG_LEVEL=warncut it to 1,862 lines/min, and ~90% of what remained was the two webhook notices — they are the only ones in this set that survive a severity filter, which is what makes them worth fixing in code rather than in configuration.With both changes the same instance logs ~6 lines/min at
warn, and the log file now holds hours of history instead of minutes.Change
Debug.LOG_LEVEL=debugbrings them back for anyone who relies on them, and the README documents that.Info—Message sent,Message deleted,Message pinnedand friends. There is one per API call, and they are the audit trail of what the caller asked for.No behaviour change beyond the log level; the branches themselves are untouched.
Testing
go build ./...,go vet ./...andgo test ./...pass.