Relog configuration args on debug.log rotation #16673

pull LarryRuane wants to merge 1 commits into bitcoin:master from LarryRuane:relog-args-on-rotation changing 6 files +144 −32
  1. LarryRuane commented at 11:07 PM on August 20, 2019: contributor

    This PR was part of #16115 but reviewers requested that this be made into a separate PR. As explained in #16115, it's useful, maybe even crucial, for support, analysis, and debugging purposes for the configuration arguments to be present in the debug.log file, as that may be the only artifact provided to the developer or support team. That PR logs the configuration settings (command-line arguments and bitcoin.conf contents) when bitcoind starts. But sometime later, the debug log file may be "rotated" (a new debug.log file started so it doesn't grow unbounded in size) and this information would be lost unless the previous debug.log is preserved.

    This PR re-logs the configuration information when the log rotates, ensuring that the current debug.log file contains this information. Reviewers had reservations about the previous approach (which you can see in #16115's discussion thread), so this PR implements this functionality in a simpler and (I believe) much better way.

  2. fanquake added the label Utils/log/libs on Aug 20, 2019
  3. DrahtBot commented at 3:01 AM on August 21, 2019: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    <!--174a7506f384e20aa4161008e828411d-->

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #25614 (Severity-based logging, step 2 by jonatack)

    If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

  4. DrahtBot added the label Needs rebase on Aug 21, 2019
  5. LarryRuane force-pushed on Aug 21, 2019
  6. DrahtBot removed the label Needs rebase on Aug 21, 2019
  7. LarryRuane force-pushed on Aug 21, 2019
  8. in test/functional/test_framework/test_node.py:310 in d252dfe814 outdated 
     306 | @@ -307,7 +307,7 @@ def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
 307 |          wait_until(self.is_node_stopped, timeout=timeout)
 308 |  
 309 |      @contextlib.contextmanager
 310 | -    def assert_debug_log(self, expected_msgs, timeout=2):
 311 | +    def assert_debug_log(self, expected_msgs, unexpected_msgs=[], timeout=2):
    practicalswift commented at 9:18 PM on August 25, 2019:

    Do you really want unexpected_msgs to preserve parameter state between calls? :-)

    >>> def foobar(foo, bar=[]):
...     bar.append(foo)
...     print(bar)
...
>>> foobar("hello")
['hello']
>>> foobar("hello")
['hello', 'hello']
>>> foobar("hello")
['hello', 'hello', 'hello']

    I think this is what you want:

    def assert_debug_log(self, expected_msgs, unexpected_msgs, timeout=2):
    if unexpected_msgs is None:
        unexpected_msgs = []

    FWIW I think we should use a linter to guard against this Python gotcha :-)

    LarryRuane commented at 3:48 AM on August 26, 2019:

    Great catch, I had no idea! I fixed this in #16115 (where it was introduced) and force-pushed rebased this PR onto that branch.

    LarryRuane commented at 8:27 PM on August 29, 2019:

    @practicalswift, I don't think this was an actual problem. I added a debug print and unexpected_msgs didn't include previous values. I think it's not broken because this function, assert_debug_log(), doesn't modify the variable (it's not mutable). Here's an extremely simplified version of this function and some sample calls to it:

    def assert_debug_log(unexpected_msgs=[]):
    print(unexpected_msgs)
    for unexpected_msg in unexpected_msgs:
        print('  ', unexpected_msg)

assert_debug_log()
assert_debug_log(["foo"])
assert_debug_log(unexpected_msgs=["foo"])
assert_debug_log("bar") # not actually called this way but just curious
assert_debug_log()

    The output:

    []
['foo']
   foo
['foo']
   foo
bar
   b
   a
   r
[]

    What prompted me to investigate this further is that I wondered if any of our existing python code has this problem. I found just one instance, which is in wallet_importmulti.py:

    def test_importmulti(self, req, success, error_code=None, error_message=None, warnings=[]):

    But adding a debug print to that function showed everything was okay. I believe that's because warnings isn't modified in that function.

  9. LarryRuane cross-referenced this on Aug 26, 2019 from issue On bitcoind startup, write config args to debug.log by LarryRuane
  10. LarryRuane force-pushed on Aug 26, 2019
  11. practicalswift cross-referenced this on Aug 26, 2019 from issue tests: Avoid common Python default parameter gotcha when mutable dict/list:s are used as default parameter values by practicalswift
  12. maflcko referenced this in commit cc40b55da7 on Aug 28, 2019
  13. sidhujag referenced this in commit 20a512ab44 on Aug 28, 2019
  14. DrahtBot added the label Needs rebase on Sep 5, 2019
  15. LarryRuane force-pushed on Sep 5, 2019
  16. DrahtBot removed the label Needs rebase on Sep 5, 2019
  17. DrahtBot added the label Needs rebase on Oct 16, 2019
  18. LarryRuane force-pushed on Oct 25, 2019
  19. DrahtBot removed the label Needs rebase on Oct 25, 2019
  20. LarryRuane force-pushed on Nov 21, 2019
  21. DrahtBot added the label Needs rebase on Dec 13, 2019
  22. LarryRuane force-pushed on Dec 13, 2019
  23. DrahtBot removed the label Needs rebase on Dec 13, 2019
  24. DrahtBot added the label Needs rebase on Dec 19, 2019
  25. LarryRuane force-pushed on Dec 20, 2019
  26. DrahtBot removed the label Needs rebase on Dec 20, 2019
  27. LarryRuane force-pushed on Dec 23, 2019
  28. LarryRuane force-pushed on Jan 19, 2020
  29. LarryRuane commented at 6:51 PM on January 19, 2020: contributor

    Force-pushed after rebasing onto https://github.com/bitcoin/bitcoin/pull/16115

  30. LarryRuane force-pushed on Jan 20, 2020
  31. DrahtBot added the label Needs rebase on Jan 29, 2020
  32. LarryRuane force-pushed on Jan 31, 2020
  33. DrahtBot removed the label Needs rebase on Jan 31, 2020
  34. DrahtBot cross-referenced this on Feb 11, 2020 from issue More thread safety annotation coverage by ajtowns
  35. LarryRuane force-pushed on Feb 18, 2020
  36. LarryRuane commented at 5:32 PM on February 18, 2020: contributor

    Rebased onto latest master

  37. DrahtBot cross-referenced this on Apr 12, 2020 from issue cli: show default values in config args log by brakmic
  38. DrahtBot cross-referenced this on Apr 30, 2020 from issue Wallet passive startup by ryanofsky
  39. DrahtBot added the label Needs rebase on May 28, 2020
  40. LarryRuane force-pushed on May 28, 2020
  41. DrahtBot removed the label Needs rebase on May 28, 2020
  42. LarryRuane force-pushed on Jul 12, 2020
  43. LarryRuane commented at 12:45 AM on July 13, 2020: contributor

    Force-pushed merge conflict fixes. I believe all reviewer comments have been addressed; no more work planned, this PR can be merged if desired.

  44. monstrobishi referenced this in commit dfb35e0a17 on Jul 30, 2020
  45. DrahtBot cross-referenced this on Aug 26, 2020 from issue log: Prefix log messages with function name and source code location if -logsourcelocations is set by practicalswift
  46. ShengguangXiao referenced this in commit f1b90146b1 on Aug 28, 2020
  47. DrahtBot cross-referenced this on Sep 22, 2020 from issue log: Mitigate disk filling attacks by temporarily rate limiting LogPrintf(…) by practicalswift
  48. DrahtBot added the label Needs rebase on Feb 18, 2021
  49. LarryRuane force-pushed on Mar 3, 2021
  50. jonatack commented at 10:48 PM on March 3, 2021: contributor

    Concept ACK. I'm a fan of the original feature that logs the config options to the debug log.

  51. DrahtBot removed the label Needs rebase on Mar 3, 2021
  52. DrahtBot cross-referenced this on Apr 5, 2021 from issue log: Mitigate disk filling attacks by rate limiting LogPrintf by dergoegge
  53. DrahtBot cross-referenced this on Apr 16, 2021 from issue log: Mitigate disk filling attacks by globally rate limiting LogPrintf(…) by dergoegge
  54. DrahtBot cross-referenced this on Apr 20, 2021 from issue MOVEONLY: Move common init code to init/common by ryanofsky
  55. DrahtBot added the label Needs rebase on Apr 23, 2021
  56. LarryRuane force-pushed on Apr 24, 2021
  57. LarryRuane commented at 3:48 AM on April 24, 2021: contributor

    Force-pushed required rebase. I should have mentioned earlier that you can test this manually by starting bitcoind, waiting for it to start up and sync, and then running:

    kill -SIGHUP `pgrep bitcoind`

    Then check debug.log; the version information and configuration settings should appear at the end. (You can do that kill repeatedly, and the information will appear again each time.)

    A more realistic test is is to do actual log rotation: Start bitcoind, wait for it to start up, then

    mv ~/.bitcoin/debug.log ~/.bitcoin/debug.log.old

    (Note that in this state, additional logging will go to debug.log.old; the new debug.log won't exist.)

    Then send the signal. A new debug.log will be created containing the version and configuration information. Further logging will appear there (and not to debug.log.old). The intention is that debug.log.old can be compressed, or archived (or deleted) or whatever. (See man logrotate.)

  58. DrahtBot removed the label Needs rebase on Apr 24, 2021
  59. DrahtBot cross-referenced this on Jun 27, 2021 from issue Rotate debug.log file by LarryRuane
  60. rebroad commented at 4:46 PM on November 21, 2021: contributor

    NACK - does not seem useful or necessary (given the previous logs can be referred to easily).

  61. LarryRuane commented at 5:28 PM on November 21, 2021: contributor

    NACK - does not seem useful or necessary (given the previous logs can be referred to easily).

    Well, if it's not useful or necessary, I don't think it's for this reason, because an external log rotation agent (see logrotate on Unix-like systems, for example) may have deleted the initial part of the debug.log file for the currently-running instance of bitcoind that contains the configuration information (which does get logged at startup).

  62. rebroad commented at 1:13 PM on November 25, 2021: contributor

    NACK - does not seem useful or necessary (given the previous logs can be referred to easily).

    Well, if it's not useful or necessary, I don't think it's for this reason, because an external log rotation agent (see logrotate on Unix-like systems, for example) may have deleted the initial part of the debug.log file for the currently-running instance of bitcoind that contains the configuration information (which does get logged at startup).

    ah, I see.. yes, in that case this might be useful, but I think it's better if it's optional - or you could just use a logrotate script to save this part of the debug.log file elsewhere before it deletes the file.

  63. DrahtBot cross-referenced this on Mar 2, 2022 from issue refactor: Split ArgsManager out of util/system by Empact
  64. DrahtBot cross-referenced this on Mar 3, 2022 from issue logging: Add severity level to logs by klementtan
  65. DrahtBot added the label Needs rebase on May 24, 2022
  66. LarryRuane force-pushed on Aug 2, 2022
  67. LarryRuane commented at 7:04 PM on August 2, 2022: contributor

    Force-pushed rebase, and made a few improvements.

  68. DrahtBot removed the label Needs rebase on Aug 2, 2022
  69. util: relog configuration arguments when debug.log rotates a4e6c45238
  70. LarryRuane force-pushed on Aug 2, 2022
  71. DrahtBot cross-referenced this on Aug 4, 2022 from issue Severity-based logging, step 2 by jonatack
  72. DrahtBot added the label Needs rebase on Sep 1, 2022
  73. DrahtBot commented at 9:18 PM on September 1, 2022: contributor

    <!--cf906140f33d8803c4a75a2196329ecb-->

    🐙 This pull request conflicts with the target branch and needs rebase.

    <sub>Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a "draft".</sub>

  74. achow101 commented at 6:01 PM on October 12, 2022: member

    Closing this as it has not had any activity in a while. If you are interested in continuing work on this, please leave a comment so that it can be reopened.

  75. achow101 closed this on Oct 12, 2022
  76. knst referenced this in commit 4d794e027c on Feb 13, 2023
  77. knst referenced this in commit 45d58d93ed on Feb 13, 2023
  78. knst referenced this in commit 16ad65a17c on Feb 28, 2023
  79. knst referenced this in commit 4507ba2728 on Feb 28, 2023
  80. knst referenced this in commit 3c2ab6c42b on Mar 14, 2023
  81. knst referenced this in commit 1fad1541e8 on Mar 15, 2023
  82. PastaPastaPasta referenced this in commit a84ec5cc19 on Apr 4, 2023
  83. bitcoin locked this on Oct 12, 2023
Contributors
LarryRuaneDrahtBotpracticalswiftjonatackrebroadachow101
Labels
Utils/log/libsNeeds rebase
Linked (view graph)
#16115 On bitcoind startup, write config args to debug.log#16726 tests: Avoid common Python default parameter gotcha when mutable dict/list:s are used as default parameter values
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-05-19 06:54 UTC