Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Include db and handler context in all db-specific logging #3815

Closed
adamcfraser opened this issue Nov 5, 2018 · 3 comments

Comments

@adamcfraser
Copy link
Contributor

commented Nov 5, 2018

Diagnosing issues for Sync Gateway nodes running multiple databases is more difficult for log messages that don't otherwise identify a database. Including the database name in log messages in a standard way would address this.

  • Pass the blip context id or REST handler serial number down to changes processing, for inclusion on changes-related logging
  • Include database identifier for changes and crud logging
@JFlath

This comment has been minimized.

Copy link
Collaborator

commented Nov 6, 2018

Related, but not directly (so feel free to tell me to open my own ticket ;)).

Would it also make sense to surface the handler's serial number in log messages? I know we do something similar for BLIP to tie subsequent messages to their overarching connection/replication, but taking the changes feed for example:

2018-11-06T09:32:13.704Z [INF] HTTP:  #003: GET /db/_changes (as ADMIN)
2018-11-06T09:32:13.704Z [INF] HTTP:  #002: GET /db/_changes (as ADMIN)
2018-11-06T09:32:13.704Z [INF] HTTP:  #001: GET /db/_changes (as ADMIN)
2018-11-06T09:32:13.705Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:0 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42006aae0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...
2018-11-06T09:32:13.705Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:0 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc42011c660 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...
2018-11-06T09:32:13.705Z [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:0 Conflicts:false IncludeDocs:false Wait:false Continuous:false Terminator:0xc4202aa3c0 HeartbeatMs:0 TimeoutMs:300000 ActiveOnly:false}) ...
2018-11-06T09:32:13.705Z [INF] Cache: getCachedChanges("*", 0) --> 1 changes valid from #1
2018-11-06T09:32:13.705Z [INF] Cache: getCachedChanges("*", 0) --> 1 changes valid from #1
2018-11-06T09:32:13.705Z [INF] Cache: getCachedChanges("*", 0) --> 1 changes valid from #1
2018-11-06T09:32:13.705Z [INF] Changes: MultiChangesFeed done
2018-11-06T09:32:13.705Z [INF] Changes: MultiChangesFeed done
2018-11-06T09:32:13.705Z [INF] Changes: MultiChangesFeed done
2018-11-06T09:32:13.705Z [INF] HTTP+: #001:     --> 200 OK  (1.4 ms)
2018-11-06T09:32:13.705Z [INF] HTTP+: #003:     --> 200 OK  (1.4 ms)
2018-11-06T09:32:13.705Z [INF] HTTP+: #002:     --> 200 OK  (1.4 ms)

Here the requests are actually the same (because I'm being lazy), but you have to make some inferences about which of the intervening lines relate to #001, #002, and #003. Even if theoretically all the data is there to unpick it, it would be a nice readability enhancement to drop in the serial/request number.

Edit: I didn't notice at first, but the requests are so close together they actually get logged in reverse 😂. Probably helps illustrate the issue!

I think this should be reasonably easy as most of the cases we care about this have access to the handler...

@adamcfraser

This comment has been minimized.

Copy link
Contributor Author

commented Nov 7, 2018

@JFlath I agree with the general motivation. We've already added additional user context logging to the majority of the changes log lines, so it's already a bit easier to differentiate between these in most cases, but I agree that directly connecting changes/cache level logging with the owning HTTP/blip request would have a lot of value. It probably makes sense to think about in the scope of this ticket, as it suggests a somewhat more verbose method to differentiate between db name, blip context, and HTTP serial numbers.

@adamcfraser adamcfraser added backlog and removed review labels Nov 13, 2018

@adamcfraser adamcfraser assigned bbrks and unassigned adamcfraser Nov 13, 2018

@bbrks

This comment has been minimized.

Copy link
Member

commented Nov 14, 2018

As discussed, we'd like a more generic approach to attaching context to log messages. I'll close the current PR and will use this ticket for tracking the stretch goal of contextual logging for HTTP/blip/db/users for Iridium.

@adamcfraser adamcfraser changed the title Include database identifier in all db-specific logging Include db and handler context in all db-specific logging Dec 13, 2018

@adamcfraser adamcfraser added ready and removed backlog labels Jan 7, 2019

@bbrks bbrks referenced this issue Jan 9, 2019
2 of 2 tasks complete

@bbrks bbrks added review and removed ready labels Jan 11, 2019

@bbrks bbrks closed this in #3896 Jan 14, 2019

bbrks added a commit that referenced this issue Jan 14, 2019

#3815 HTTP/Blip logging context (#3896)
* Add context-aware logging functions

* Use contextual logging for HTTP/Blip requests

* Address PR comments

* Contextualise cache and crud logging

* Use typed context value key

* Remove embedded type accessor

* Re-create user-scoped datbase for each blip handler instead of reloading user

* Add nil check for user now ReloadUser isn't handling it
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.