When analyzing functional test logs (produced with combine_logs.py), entries sometimes sort slightly out of order because even though python prints 6 digits for microsecond precision, it fills up the last 3 digits with zeroes. For example, it may look like a message was received by the test framework before it was sent by the node.
Change this to actually use microsecond precision - this should make combined logs a little bit easier to analyze.
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--006a51241073e994b41acfe9ec718e94-->
For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32676.
<!--021abf342d371248e50ceaed478a90ca-->
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | maflcko, janb84, davidgumberg, achow101 |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
<!--5faf32d7da4f0f540f40219e4f7537a3-->
This makes it easier to compare test and bitcoind logs -
combine_logs.py orders by timestamp and will be more precise.
<!--85328a0da195eb286784d51f73fa0af9-->
🚧 At least one of the CI tasks failed.
<sub>Task lint: https://github.com/bitcoin/bitcoin/runs/43407398087</sub>
<sub>LLM reason (✨ experimental): The CI failure is caused by a failed lint check due to a dead code warning in Python code.</sub>
<details><summary>Hints</summary>
Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:
Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.
Leave a comment here, if you need help tracking down a confusing failure.
</details>
nice!
review ACK ed179e0a6528c39b3bca76365f256716f917e19b 🗳
<details><summary>Show signature</summary>
Signature:
untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
trusted comment: review ACK ed179e0a6528c39b3bca76365f256716f917e19b 🗳
6s+yyc9O+I5NzBwm5FAP966If0KN+FGS6ilbXoVTv+E67Pu+935Z1wWiLOXInAvwBdGTLxmUxUTPtEiyvqVCDQ==
</details>
847 | + dt = datetime.fromtimestamp(record.created, timezone.utc) 848 | + return dt.strftime('%Y-%m-%dT%H:%M:%S.%f') 849 | + 850 | + formatter = MicrosecondFormatter( 851 | + fmt='%(asctime)sZ %(name)s (%(levelname)s): %(message)s', 852 | + )
non-blocking question/nit, why is this approach with a derived class of logging.Formatter preferable to modifying the datefmt string?
- formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d000Z %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%dT%H:%M:%S')
+ formatter = logging.Formatter(fmt='%(asctime)sZ %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%dT%H:%M:%S.%f')
I tried that too - it doesn't work, it will print
2025-06-03T19:12:56.%fZ TestFramework (INFO):
See https://stackoverflow.com/questions/75035056/microsecond-do-not-work-in-python-logger-format for some background.
non-blocking question/nit, why is this approach with a derived class of
logging.Formatterpreferable to modifying thedatefmtstring?- formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d000Z %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%dT%H:%M:%S') + formatter = logging.Formatter(fmt='%(asctime)sZ %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%dT%H:%M:%S.%f')
Does it work locally? The docs say:
The %f format directive only applies to strptime(), not to strftime(). However, see also datetime.datetime.strptime() and datetime.datetime.strftime() where the %f format directive applies to microseconds.
Ah, thanks for the context, I hadn't checked since I assumed the format specifiers would not differ between datetime.datetime.strftime() and strftime(), but I can confirm that applying the diff I suggest, the logs look exactly as @mzumsande indicated, and the microseconds are not printed.
837 | @@ -837,9 +838,16 @@ def _start_logging(self): 838 | # User can provide log level as a number or string (eg DEBUG). loglevel was caught as a string, so try to convert it to an int 839 | ll = int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper() 840 | ch.setLevel(ll) 841 | + 842 | # Format logs the same as bitcoind's debug.log with microprecision (so log files can be concatenated and sorted) 843 | - formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d000Z %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%dT%H:%M:%S') 844 | - formatter.converter = time.gmtime 845 | + class MicrosecondFormatter(logging.Formatter): 846 | + def formatTime(self, record, _=None):
by the way, I switched to _=None because datefmt=None runs into a linter error (unused variable 'datefmt' ), and omitting the arg is not allowed (TypeErrors). Not sure if the linter is correct to complain about this.
I can see it fail if python internally passes datefmt as a keyword arg. I can see disabling the linter, because it may be wrong due to this. I can also see just saying assert not datefmt to ensure it is None and ensure the keyword is used. But no strong opinion. I think anything is fine here.
I don't have a strong opinion either, I just wanted to mention this because _=None may look weird to some - if the current approach is fine I'll just leave it at this.
Tested ACK https://github.com/bitcoin/bitcoin/pull/32676/commits/ed179e0a6528c39b3bca76365f256716f917e19b
Added an assert(0) to feature_abortnode.py and on this branch, microsecond times are printed, on master (5471e29d057049d2b5a) they are not.
Didn't try to reproduce the described situation in the PR of out-of-order logs, but it makes sense that the existing behavior would result in nonsensical ordering of logs any time you have sub-ms events, and I can recall having run into this before.
<details>
<summary>
</summary>
diff --git a/test/functional/feature_abortnode.py b/test/functional/feature_abortnode.py
index a5c8aa163a..8abe487b9e 100755
--- a/test/functional/feature_abortnode.py
+++ b/test/functional/feature_abortnode.py
@@ -37,6 +37,7 @@ class AbortNodeTest(BitcoinTestFramework):
# Check that node0 aborted
self.log.info("Waiting for crash")
self.nodes[0].wait_until_stopped(timeout=5, expect_error=True, expected_stderr="Error: A fatal internal error occurred, see debug.log for details: Failed to disconnect block.")
+ assert(0)
self.log.info("Node crashed - now verifying restart fails")
self.nodes[0].assert_start_raises_init_error()
$ git checkout --detach ed179e0
$ ./build/test/functional/feature_abortnode.py
2025-06-03T20:52:18.520787Z TestFramework (INFO): PRNG seed is: 5653719685663637249
2025-06-03T20:52:18.521155Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_q_44vhww
2025-06-03T20:52:18.885450Z TestFramework (INFO): Waiting for crash
2025-06-03T20:52:19.036796Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
File "/bitcoin/test/functional/test_framework/test_framework.py", line 190, in main
self.run_test()
~~~~~~~~~~~~~^^
File "/bitcoin./build/test/functional/feature_abortnode.py", line 40, in run_test
assert(0)
^
AssertionError
2025-06-03T20:52:19.088096Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-06-03T20:52:19.088240Z TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_func_test_q_44vhww
2025-06-03T20:52:19.088274Z TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_func_test_q_44vhww/test_framework.log
2025-06-03T20:52:19.088372Z TestFramework (ERROR):
2025-06-03T20:52:19.088455Z TestFramework (ERROR): Hint: Call /bitcoin/test/functional/combine_logs.py '/tmp/bitcoin_func_test_q_44vhww' to consolidate all logs
2025-06-03T20:52:19.088480Z TestFramework (ERROR):
2025-06-03T20:52:19.088499Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-06-03T20:52:19.088536Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-06-03T20:52:19.088554Z TestFramework (ERROR):
$ git checkout --detach 5471e2
$ ./build/test/functional/feature_abortnode.py
2025-06-03T21:00:11.760000Z TestFramework (INFO): PRNG seed is: 6770717479175070298
2025-06-03T21:00:11.760000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_z_r_1o2o
2025-06-03T21:00:12.124000Z TestFramework (INFO): Waiting for crash
2025-06-03T21:00:12.276000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
File "/bitcoin/test/functional/test_framework/test_framework.py", line 189, in main
self.run_test()
~~~~~~~~~~~~~^^
File "/bitcoin/./build/test/functional/feature_abortnode.py", line 40, in run_test
assert(0)
^
AssertionError
2025-06-03T21:00:12.327000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-06-03T21:00:12.327000Z TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_func_test_z_r_1o2o
2025-06-03T21:00:12.327000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_func_test_z_r_1o2o/test_framework.log
2025-06-03T21:00:12.327000Z TestFramework (ERROR):
2025-06-03T21:00:12.327000Z TestFramework (ERROR): Hint: Call /bitcoin/test/functional/combine_logs.py '/tmp/bitcoin_func_test_z_r_1o2o' to consolidate all logs
2025-06-03T21:00:12.327000Z TestFramework (ERROR):
2025-06-03T21:00:12.327000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-06-03T21:00:12.327000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-06-03T21:00:12.327000Z TestFramework (ERROR):
ACK ed179e0a6528c39b3bca76365f256716f917e19b
The new output is of the same length but of higher precision (replacing the unused 0) 👍 (keeping it the same format should prevent any parse problems of 3rd party scripts)
ACK ed179e0a6528c39b3bca76365f256716f917e19b