Merge bitcoin/bitcoin#22872: log: improve checkaddrman logging with duration in milliseconds

22b44fc696dc1078c40d17e2d497c74c7b4ae750 p2p: improve checkaddrman logging with duration in milliseconds (Jon Atack)
ec65bed00ee2e403e39b3c5977caf4abd31ccc87 log, timer: add LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE macro (Jon Atack)
325da75a5396f3161a6eade74b349105ed5722ab log, timer: allow not repeating log message on completion (Jon Atack)

Pull request description:

  This patch:
  - updates the `logging/timer.h::Timer` class to allow not repeating the log message on completion
  - adds a `LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE` macro that prints the descriptive message when logging the start but not when logging the completion
  - updates the checkaddrman logging to log the duration, and renames the function like the `-checkaddrman` configuration option in order to prefix every log message with `CheckAddrman` instead of the longer, less pleasant, and different-from-checkaddrman `ForceCheckAddrman` (the Doxygen documentation on the function already makes clear that it is unaffected by `m_consistency_check_ratio`).

  before
  ```
  2021-09-21T18:42:50Z [opencon] Addrman checks started: new 64864, tried 1690, total 66554
  2021-09-21T18:42:50Z [opencon] Addrman checks completed successfully
  ```

  after
  ```
  2021-09-21T18:42:50Z [opencon] CheckAddrman: new 64864, tried 1690, total 66554 started
  2021-09-21T18:42:50Z [opencon] CheckAddrman: completed (76.21ms)
  ```

  To test, build and run bitcoind with `-debug=addrman -checkaddrman=<n>` for a value of `n` in the range of, say, 10 to 40.

ACKs for top commit:
  laanwj:
    Code review ACK 22b44fc696dc1078c40d17e2d497c74c7b4ae750

Tree-SHA512: 658c0dfaaa9d07092e2418f2d05007c58cc35be6593f22b3c592ce793334a885dd92dacc46bdeddc9d37939cf11174660a094c07c0fa117fbb282953aa45a94d

2 files changed, 4 insertions, 4 deletions

diff --git a/test/functional/feature_asmap.py b/test/functional/feature_asmap.py
index debd87962f..02c000eb95 100755
--- a/test/functional/feature_asmap.py
+++ b/test/functional/feature_asmap.py
@@ -89,8 +89,8 @@ class AsmapTest(BitcoinTestFramework):
         self.restart_node(0, ["-asmap", "-checkaddrman=1"])
         with self.node.assert_debug_log(
             expected_msgs=[
-                "Addrman checks started: new 1, tried 1, total 2",
-                "Addrman checks completed successfully",
+                "CheckAddrman: new 1, tried 1, total 2 started",
+                "CheckAddrman: completed",
             ]
         ):
             self.node.getnodeaddresses()  # getnodeaddresses re-runs the addrman checks
diff --git a/test/functional/rpc_net.py b/test/functional/rpc_net.py
index 0857f4e0ca..28712fc89e 100755
--- a/test/functional/rpc_net.py
+++ b/test/functional/rpc_net.py
@@ -260,7 +260,7 @@ class NetTest(BitcoinTestFramework):
 
         self.log.debug("Test that adding a valid address to the tried table succeeds")
         assert_equal(node.addpeeraddress(address="1.2.3.4", tried=True, port=8333), {"success": True})
-        with node.assert_debug_log(expected_msgs=["Addrman checks started: new 0, tried 1, total 1"]):
+        with node.assert_debug_log(expected_msgs=["CheckAddrman: new 0, tried 1, total 1 started"]):
             addrs = node.getnodeaddresses(count=0)  # getnodeaddresses re-runs the addrman checks
             assert_equal(len(addrs), 1)
             assert_equal(addrs[0]["address"], "1.2.3.4")
@@ -273,7 +273,7 @@ class NetTest(BitcoinTestFramework):
 
         self.log.debug("Test that adding a second address, this time to the new table, succeeds")
         assert_equal(node.addpeeraddress(address="2.0.0.0", port=8333), {"success": True})
-        with node.assert_debug_log(expected_msgs=["Addrman checks started: new 1, tried 1, total 2"]):
+        with node.assert_debug_log(expected_msgs=["CheckAddrman: new 1, tried 1, total 2 started"]):
             addrs = node.getnodeaddresses(count=0)  # getnodeaddresses re-runs the addrman checks
             assert_equal(len(addrs), 2)