log: Add debug log category prefix #21058

1. 
   ghost commented at 8:12 pm on February 1, 2021: none

   I wanted to log (especially incoming) onion connections. Was unsure if category net or tor would do that.

   In the debug log you do not see which debug message is of what category, or if it is of no debug category at all (standard log).

   I would like if debug log categories are logged e.g. with a [<debug log category>] prefix. E.g. for net debug category log line, the line is currently logged like this (I hope I am right that this belongs to netcategory, so this is an example of the uncertainty that results in the current absence of the category logging): 2021-02-01T19:33:08Z SOCKS5 connected zncs3yn6h4l7c3z7.onion

   My wish would be that it would be logged like this:

   2021-02-01T19:33:08Z [net] SOCKS5 connected zncs3yn6h4l7c3z7.onion

   If that would have any drawback like log gets bloated, an option to toggle debug log category prefix logging could be introduced, e.g. debugcategorylogging=<1|0>

2. unknown added the label Feature on Feb 1, 2021
3. 
   ghost commented at 9:08 pm on February 1, 2021: none

   I know log category logging e.g. from Bind DNS server log.
4. 
   x4e commented at 3:16 pm on February 2, 2021: none

   I’m not sure that would be very easy, a log’s category is not a single category but rather a number that can represent many different categories by bitflags. I guess it could be possible to generate a comma seperated list of every category that the log is a part of, but that would probably be slow and complicated.
5. 
   laanwj commented at 7:08 pm on February 2, 2021: member

   Although strictly a bit flag, every message that is logged is only in one category (or always logged) so it should be possible to do this (no opinion on whether we should).
6. 
   ghost commented at 11:44 am on February 7, 2021: none

   I have a patch working, that does this. With the patch the log looks like so (note the UpdateTip log line which is a non-debug message):

    02021-02-07T00:00:09Z [mempool] AcceptToMemoryPool: peer=8: accepted 6507f93244d81d6b005736ac06570fec84197d5bb37214eebe0d7fdc815336d3 (poolsz 11 txn, 18 kB)
    12021-02-07T00:00:09Z [net] sending inv (37 bytes) peer=4
    22021-02-07T00:00:09Z [net] received: inv (37 bytes) peer=5
    32021-02-07T00:00:13Z [net] sending inv (37 bytes) peer=3
    42021-02-07T00:00:26Z [net] received: cmpctblock (394 bytes) peer=4
    52021-02-07T00:00:26Z [cmpctblock] Initialized PartiallyDownloadedBlock for block 000000000000002c855e1b2624e578875d5dfc0f6e213b12ef9e1cd34a9c7ca5 using a cmpctblock of size 394
    62021-02-07T00:00:26Z [net] received: blocktxn (33 bytes) peer=4
    72021-02-07T00:00:26Z [cmpctblock] Successfully reconstructed block 000000000000002c855e1b2624e578875d5dfc0f6e213b12ef9e1cd34a9c7ca5 with 1 txn prefilled, 11 txn from mempool (incl 
    8at least 0 from extra pool) and 0 txn requested
    92021-02-07T00:00:26Z [validation] NewPoWValidBlock: block hash=000000000000002c855e1b2624e578875d5dfc0f6e213b12ef9e1cd34a9c7ca5
   102021-02-07T00:00:26Z [bench]   - Load block from disk: 0.00ms [0.00s]
   112021-02-07T00:00:26Z [bench]     - Sanity checks: 0.03ms [0.00s (0.05ms/blk)]
   122021-02-07T00:00:26Z [bench]     - Fork checks: 0.10ms [0.00s (0.19ms/blk)]
   132021-02-07T00:00:26Z [bench]       - Connect 12 transactions: 1.28ms (0.107ms/tx, 0.051ms/txin) [0.07s (3.20ms/blk)]
   142021-02-07T00:00:26Z [bench]     - Verify 25 txins: 1.41ms (0.056ms/txin) [0.12s (5.52ms/blk)]
   152021-02-07T00:00:26Z [bench]     - Index writing: 0.59ms [0.02s (0.73ms/blk)]
   162021-02-07T00:00:26Z [bench]   - Writing chainstate: 0.15ms [0.00s (0.18ms/blk)]
   172021-02-07T00:00:26Z [estimatefee] Blockpolicy estimates updated by 11 of 11 block txs, since last block 10 of 10 tracked, mempool map size 0, max target 10 from current
   182021-02-07T00:00:26Z UpdateTip: new best=000000000000002c855e1b2624e578875d5dfc0f6e213b12ef9e1cd34a9c7ca5 height=1934160 version=0x20000000 log2_work=73.671475 tx=59354560 date='2021-02-07T00:00:21Z' progress=1.000000 cache=0.2MiB(1067txo)
   192021-02-07T00:00:26Z [bench]   - Connect postprocess: 2.58ms [15.41s (733.75ms/blk)]
   202021-02-07T00:00:26Z [bench] - Connect block: 5.70ms [15.57s (741.52ms/blk)]
   212021-02-07T00:00:26Z [validation] Enqueuing BlockConnected: block hash=000000000000002c855e1b2624e578875d5dfc0f6e213b12ef9e1cd34a9c7ca5 block height=1934160
   

   It looks like some people already had demand for a log category, and wrote the category prefix in the debug message text itself. This would not be needed anymore with this patch, and currently results in a double prefix, e.g.

   02021-02-07T04:50:51Z [tor] tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
   

   I would be willing to create a follow-up PR to remove those then obsolete manually inserted debug log category prefixes from the debug messages.

7. 
   jonatack commented at 7:20 pm on May 31, 2022: member

   This seems to have been closed/completed by #24464 and current follow-ups.
8. MarcoFalke closed this on Jun 1, 2022

   ---

9. DrahtBot locked this on Jun 1, 2023

Contributors
ghost x4e laanwj jonatack

Labels
Feature