Relog configuration args on debug.log rotation #16673

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

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

   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? :-)

   0>>> def foobar(foo, bar=[]):
   1...     bar.append(foo)
   2...     print(bar)
   3...
   4>>> foobar("hello")
   5['hello']
   6>>> foobar("hello")
   7['hello', 'hello']
   8>>> foobar("hello")
   9['hello', 'hello', 'hello']
   

   I think this is what you want:

   0def assert_debug_log(self, expected_msgs, unexpected_msgs, timeout=2):
   1    if unexpected_msgs is None:
   2        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:

   0def assert_debug_log(unexpected_msgs=[]):
   1    print(unexpected_msgs)
   2    for unexpected_msg in unexpected_msgs:
   3        print('  ', unexpected_msg)
   4
   5assert_debug_log()
   6assert_debug_log(["foo"])
   7assert_debug_log(unexpected_msgs=["foo"])
   8assert_debug_log("bar") # not actually called this way but just curious
   9assert_debug_log()
   

   The output:

   0[]
   1['foo']
   2   foo
   3['foo']
   4   foo
   5bar
   6   b
   7   a
   8   r
   9[]
   

   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:

   0def 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 force-pushed on Aug 26, 2019
10. maflcko referenced this in commit cc40b55da7 on Aug 28, 2019
11. sidhujag referenced this in commit 20a512ab44 on Aug 28, 2019
12. DrahtBot added the label Needs rebase on Sep 5, 2019
13. LarryRuane force-pushed on Sep 5, 2019
14. DrahtBot removed the label Needs rebase on Sep 5, 2019
15. DrahtBot added the label Needs rebase on Oct 16, 2019
16. LarryRuane force-pushed on Oct 25, 2019
17. DrahtBot removed the label Needs rebase on Oct 25, 2019
18. LarryRuane force-pushed on Nov 21, 2019
19. DrahtBot added the label Needs rebase on Dec 13, 2019
20. LarryRuane force-pushed on Dec 13, 2019
21. DrahtBot removed the label Needs rebase on Dec 13, 2019
22. DrahtBot added the label Needs rebase on Dec 19, 2019
23. LarryRuane force-pushed on Dec 20, 2019
24. DrahtBot removed the label Needs rebase on Dec 20, 2019
25. LarryRuane force-pushed on Dec 23, 2019
26. LarryRuane force-pushed on Jan 19, 2020
27. 
    LarryRuane commented at 6:51 pm on January 19, 2020: contributor

    Force-pushed after rebasing onto https://github.com/bitcoin/bitcoin/pull/16115
28. LarryRuane force-pushed on Jan 20, 2020
29. DrahtBot added the label Needs rebase on Jan 29, 2020
30. LarryRuane force-pushed on Jan 31, 2020
31. DrahtBot removed the label Needs rebase on Jan 31, 2020
32. LarryRuane force-pushed on Feb 18, 2020
33. 
    LarryRuane commented at 5:32 pm on February 18, 2020: contributor

    Rebased onto latest master
34. DrahtBot added the label Needs rebase on May 28, 2020
35. LarryRuane force-pushed on May 28, 2020
36. DrahtBot removed the label Needs rebase on May 28, 2020
37. LarryRuane force-pushed on Jul 12, 2020
38. 
    LarryRuane commented at 0: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.
39. monstrobishi referenced this in commit dfb35e0a17 on Jul 30, 2020
40. ShengguangXiao referenced this in commit f1b90146b1 on Aug 28, 2020
41. DrahtBot added the label Needs rebase on Feb 18, 2021
42. LarryRuane force-pushed on Mar 3, 2021
43. 
    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.
44. DrahtBot removed the label Needs rebase on Mar 3, 2021
45. DrahtBot added the label Needs rebase on Apr 23, 2021
46. LarryRuane force-pushed on Apr 24, 2021
47. 
    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:

    0kill -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

    0mv ~/.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.)

48. DrahtBot removed the label Needs rebase on Apr 24, 2021
49. 
    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).
50. 
    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).

51. 
    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.

52. DrahtBot added the label Needs rebase on May 24, 2022
53. LarryRuane force-pushed on Aug 2, 2022
54. 
    LarryRuane commented at 7:04 pm on August 2, 2022: contributor

    Force-pushed rebase, and made a few improvements.
55. DrahtBot removed the label Needs rebase on Aug 2, 2022
56. util: relog configuration arguments when debug.log rotates a4e6c45238
57. LarryRuane force-pushed on Aug 2, 2022
58. DrahtBot added the label Needs rebase on Sep 1, 2022
59. 
    DrahtBot commented at 9:18 pm on September 1, 2022: contributor

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

    Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a “draft”.

60. 
    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.
61. achow101 closed this on Oct 12, 2022

    ---

62. knst referenced this in commit 4d794e027c on Feb 13, 2023
63. knst referenced this in commit 45d58d93ed on Feb 13, 2023
64. knst referenced this in commit 16ad65a17c on Feb 28, 2023
65. knst referenced this in commit 4507ba2728 on Feb 28, 2023
66. knst referenced this in commit 3c2ab6c42b on Mar 14, 2023
67. knst referenced this in commit 1fad1541e8 on Mar 15, 2023
68. PastaPastaPasta referenced this in commit a84ec5cc19 on Apr 4, 2023
69. bitcoin locked this on Oct 12, 2023

Contributors
LarryRuane DrahtBot practicalswift jonatack rebroad achow101

Labels
Utils/log/libs Needs rebase