Improve logging to colocate Seq, ID, and Rev as much as possible
JFlath opened this issue · 0 comments
In most places, we log the document ID and rev alongside each other, for example:
2019-01-08T00:00:39.175Z [INF] CRUD: Stored doc "mydoc" / "1-aaaaaaaaaaaaaaaaaaaaaaaaaaaf1a78"
2019-01-08T00:00:39.176Z [INF] Cache: Received #12345678 after 1ms ("my_doc" / "1-aaaaaaaaaaaaaaaaaaaaaaaaaaaf1a78")
As one of the two lines above also shows, we often have the sequence number in the mix too. This makes simple lookups easy - "What sequence number was rev 1-abc
?" "What document/rev was sequence number 123?" can be done with a simple grep.
There are a few cases though where we don't log everything we have available - one particular example is here:
Line 204 in 94538d1
Generally, this is still fine, and you can infer what you need from the surrounding lines. There are a few of reasons it would be nice to add more data here though:
- Searching - it's nice to be able to be able to grep for
my_doc
and pull out as much info as possible about it. In this case, we wouldn't pull out theImport
line, which gives a bit of an incomplete picture. - Error cases - we've seen cases where a process doesn't proceed exactly as we'd expect (for example if the doc is deleted and recreated by the SDK) - in these cases, it's very helpful to be able to pull out as much data at each log line.
- Overlapping logging - Partially handled by the introduction of contexts, but in the cases of overlapping operations, having everything explicit is super helpful.
Obviously, this needs balancing with not making the logs too verbose; it might also be redundant if we spread the use contexts further down, but I wouldn't mind getting something more in there first.
Assigning to myself to see if there are a few quick ones I can flag up/add in first.