Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-47256

Overly verbose Magma INFO logs result in short log history

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • Critical
    • 7.1.0
    • 7.1.0
    • storage-engine
    • Untriaged
    • 1
    • Unknown
    • Magma May 2022

    Description

      When looking at some recent Magma issues (e.g. MB-46661), the amount of log messages output by Magma / MagmaKVStore is large - such that the duration the logs covers is significantly curtailed.

      For example (but others probably exist):

      • 80 messages about the purger running in a 1 second window (and this repeats many times) - excmple:

        2021-06-01T10:51:50.059506-07:00 INFO [(default) magma_35]Started running purger for kvstore:683
        2021-06-01T10:51:50.059574-07:00 INFO [(default) magma_34]Started running purger for kvstore:466
        2021-06-01T10:51:50.059626-07:00 INFO [(default) magma_34]Completed running purger for kvstore:466
        2021-06-01T10:51:50.059775-07:00 INFO [(default) magma_35]Completed running purger for kvstore:683
        

      • very verbose warmup / startup - for example:

        2021-06-01T06:16:08.331861-07:00 INFO [(default) magma_19]Created kvstore 955 rev 1 init offset 1:0
        2021-06-01T06:16:08.334543-07:00 INFO [(default) magma_19/kvstore-955/rev-000000001]KVStore::Open kvstore-955/rev-000000001 highSeqno:0 replayOffset:1:0
        2021-06-01T06:16:08.334576-07:00 INFO [(default) magma_19]KVStore kvstore-955/rev-000000001 created
        

      • others...

      The general intent is that INFO should only be used for significant, rare events (initial startup, new DCP connection, new vBucket created, vBucket changes state) - and should be as terse as possible for the more common of those events (i.e. vBucket events typically happen 1024x as often as Bucket events; so it's fine to say print 20 log messages total when a Bucket is created, but not ok to print 20 per vBucket.

      I appreciate that during initial bringup it has been useful and desirable to record as much information as possible to debug any issues, but as we prepare for productisation we need to ensure that we have sufficient history in log files coming back from customers - we should be aiming for at least 7 days of logs in a cbcollect when the system is in steady-state.

      As a concrete suggestion - for the 3 log messages printed when a vbucket is created, could they be compressed into a single line, or perhaps removed entirely in the successful case?

      2021-06-01T06:16:08.331861-07:00 INFO [(default) magma_19]Created kvstore 955 rev 1 init offset 1:0
      2021-06-01T06:16:08.334543-07:00 INFO [(default) magma_19/kvstore-955/rev-000000001]KVStore::Open kvstore-955/rev-000000001 highSeqno:0 replayOffset:1:0
      2021-06-01T06:16:08.334576-07:00 INFO [(default) magma_19]KVStore kvstore-955/rev-000000001 created
      

      Please let me know if you need any more info / guidance on what's acceptable etc.

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            ritesh.agarwal Ritesh Agarwal
            drigby Dave Rigby (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty