couchbase/sync_gateway

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:

base.Infof(base.KeyImport, "Created new rev ID %v", newRev)

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 the Import 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.