Skip to content

Conversation

@jonatack
Copy link
Member

@jonatack jonatack commented Mar 9, 2023

The logging RPC does not work as intended and as documented in its help when 0 or none are passed.

Per the RPC logging help:

$ ./src/bitcoin-cli help logging

In addition, the following are available as category names with special meanings:
  - "all",  "1" : represent all logging categories.
  - "none", "0" : even if other logging categories are specified, ignore all of them.

The behavior and documentation were added in #11191, but over time and extended refactoring, the behavior no longer works in master and versions 22/23/24 (the last supported versions currently) -- passing 0/none has no effect. As there was no test coverage, the regressions went uncaught. In v24, none became unrecognized:

$ ./src/bitcoin-cli logging '["none"]'
error code: -8
error message:
unknown logging category none

During the same time period, passing 1 and all has been operational and documented.

Solution: detect none/0 values and add test coverage in any case, and either:

  • leave the functionality out, raise with an error message if the values are passed, and update the RPC help documentation, or

  • fix the behavior by returning early.

Both solutions involve essentially the same code size and complexity. Given that all/1 has been operational, and that none/0 has been documented and appears per the code of the original PR to have been operational, it seems preferable for consistency to support none/0 in symmetry with all/1 and as ACKed, intended, and documented in #11191.

Done by this pull:

  • add missing RPC logging logic and test coverage
  • update the -debug and -debugexclude config options to use the same code for consistency in behavior between them, and for consistency with the logging RPC that provides the same behavior for both -include and -exclude
  • improve the user-facing documentation and examples; can be tested with ./src/bitcoind -h | grep -A12 "\-debug=<\|debugexclude" && ./src/bitcoin-cli help logging

If it is decided to backport a fix, commit Fix RPC logging behavior when "0" and "none" values are passed could probably suffice.

@DrahtBot
Copy link
Contributor

DrahtBot commented Mar 9, 2023

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

Code Coverage

For detailed information about the code coverage, see the test coverage report.

Reviews

See the guideline for information on the review process.

Type Reviewers
ACK pinheadmz
Ignored review ajtowns

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

  • #28318 (logging: Simplify API for level based logging by ajtowns)

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.

@jonatack jonatack marked this pull request as ready for review March 9, 2023 02:54
@fanquake
Copy link
Member

fanquake commented Mar 9, 2023

or none are passed, including not recognizing none:

Any idea when/how this was broken?

@fanquake
Copy link
Member

fanquake commented Mar 9, 2023

Probably in f1379ae from #25614:

replace the unused BCLog::Level:None string "none" with an empty string
as the case will never be hit

So only broken for 24.x.

@jonatack
Copy link
Member Author

jonatack commented Mar 9, 2023

The behavior was intended to be added in #11191.

I downloaded and tested v23.1 and the behavior wasn't functional: passing 0 or none had no effect.

In v24, f1379ae made none not be recognized, but the logic for the intended behavior remained absent anyway.

I've added this information to the PR description.

@fanquake
Copy link
Member

The behavior was intended to be added in #11191.

It's still not clear if this was broken from the time it was merged, or at some other later point. This also does not work with 22.x, and any earlier versions are EOL.

If it's been broken forever (or at least is in all currently maintained releases), and no ones even noticed, we could take advantage of that, to remove some of the complexity here; do we definitely need multiple different ways of achieving the same logging toggling?

@jonatack jonatack changed the title rpc: fix logging RPC when "none" values are passed, add test coverage, improve docs Fix logging RPC and -debugexclude with 0/none values, add test coverage, improve docs Mar 10, 2023
@jonatack jonatack force-pushed the 2023-03-logging-fixes-and-test-coverage branch from a5f8a7a to 215400a Compare March 10, 2023 18:54
@jonatack jonatack marked this pull request as draft March 10, 2023 19:56
@jonatack jonatack force-pushed the 2023-03-logging-fixes-and-test-coverage branch 2 times, most recently from 980837e to 1509228 Compare March 16, 2023 21:45
@jonatack jonatack force-pushed the 2023-03-logging-fixes-and-test-coverage branch from 1509228 to 76f4e13 Compare March 31, 2023 13:05
@jonatack
Copy link
Member Author

Rebased.

could take advantage of that, to remove some of the complexity here; do we definitely need multiple different ways of achieving the same logging toggling?

Exploring this, it doesn't look like there would be much code simplification gained by dropping none for 0 only, which would no longer be in symmetry with all/1 that have been operational for a long time. A couple lines could be saved by removing the -debugexclude config option, but that option is practical to have, as seen by its use in our own unit/fuzz and functional test frameworks.

It seems the way forward from here is to detect none/0 values, add test coverage and then either:

  • leave the functionality out, raise with an error message if none/0 values are passed, and update the RPC help documentation, or

  • simply fix the original behavior by returning early.

Both involve similar code size/complexity and the second option seems preferable. The updated code here is about the same length as before, modulo missing test coverage and improved documentation.

In the last pushes I've updated the PR description and first commit message with this info and improved the code and tests. This should be ready for further review!

@jonatack jonatack marked this pull request as ready for review March 31, 2023 16:04
Copy link
Contributor

@ajtowns ajtowns left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK 05143b2b94cc1d62f27fc73212aa59f9d471f2b8

jonatack and others added 7 commits August 31, 2023 18:31
Per the RPC logging help:

```
In addition, the following are available as category names with special meanings:
  - "all",  "1" : represent all logging categories.
  - "none", "0" : even if other logging categories are specified, ignore all of them.
```

The behavior and documentation were added in bitcoin#11191, but over time and extended
refactoring, the behavior is not longer working in Bitcoin Core versions
22/23/24 (the last supported versions currently) -- passing `0` or `none` has no
effect.  As there was no test coverage, the regressions went uncaught.  In v24,
`none` became unrecognized.

During the same time period, passing `1` and `all` has been operational and documented.

We therefore need to detect none/0 values and add test coverage in any case, and either:

- leave the functionality out, raise with an error message if none/0 are passed,
  and update the RPC help documentation, or

- fix the behavior by returning early.

Both solutions involve essentially the same code size and complexity.  Given
that all/1 has been operational, and that none/0 has been documented and appears
to have been operational previously, it seems preferable for consistency to
support none/0 in symmetry with all/1, and as ACKed, intended, and documented
since bitcoin#11191.

---

This commit therefore adds:

- the missing logic to make the functionality work

- a missing logging.h include header

- the relevant info in the logging RPC help doc
for consistency between them and for consistency with the logging RPC that uses
the same logic for both -include and -exclude.

Co-authored-by: Anthony Towns <[email protected]>
Co-authored-by: Matthew Zipkin <[email protected]>
Can be tested with:

./src/bitcoind -h | grep -A12 "\-debug=<\|debugexclude"
These cases should never be hit and are not needed; the 0/none logging category
logic is handled only by the callers of IsNoneCategory() at these times:

1) during bitcoind startup init

2) when the `logging` RPC is invoked
and make the logging example in the developer notes zsh-compatible
(for instance, zsh is currently the default shell in macOS).

The RPC logging help can be tested with:

./src/bitcoin-cli help logging
@jonatack jonatack force-pushed the 2023-03-logging-fixes-and-test-coverage branch from 05143b2 to 94b059f Compare September 1, 2023 00:37
@jonatack
Copy link
Member Author

jonatack commented Sep 1, 2023

Updated for @ajtowns' feedback to make IsNoneCategory() a static function in 6f4127b (#27231).

git diff 05143b2 94b059f

diff --git a/src/logging.h b/src/logging.h
index 4dfb7106327..83c285c905d 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -180,7 +180,7 @@ namespace BCLog {
 
         bool WillLogCategory(LogFlags category) const;
         bool WillLogCategoryLevel(LogFlags category, Level level) const;
-        [[nodiscard]] bool IsNoneCategory(const std::string& s) const { return s == "0" || s == "none"; }
+        [[nodiscard]] static bool IsNoneCategory(const std::string& s) { return s == "0" || s == "none"; }

@ajtowns
Copy link
Contributor

ajtowns commented Sep 5, 2023

reACK 94b059f

Copy link
Member

@pinheadmz pinheadmz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

re-ACK 94b059f

confirmed with range diff 93b387fe70 to 94b059f
Changes since last review address AJ's comments, minimal diff
Built and tested again locally

Show Signature
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

ACK 94b059ffe403a948957152b96f24fba4d9ee31f0
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEE5hdzzW4BBA4vG9eM5+KYS2KJyToFAmT4nZIACgkQ5+KYS2KJ
yTpNDQ//Qlf3FswTPrPl8KG9iZAZvzA0CVvIeBRdFZWgtDJ1cGnIllxEsnVfE7R9
J6EXUEdZ+XCvzfVxLaLR9W23dWtRttNjC+cx/i7GexIYlAQfI4FGECuMitXXEYsR
pYujKEQ/6SETiI8TBJC3OqiWhBodDzzfzdevhiKKbX2dKY9c22OqTSP9TI6XJQfw
R8iqZuj4Tps4jUrNYoWQmo8C71KReVnCdDi3jeKKKXeGFfkb/hJNDqRRqtyLvqd2
Ih/N67BbjtHjtJ2U16x2qFN5xyyBer/nXRirM9GKTKrt6ZpDhY6k2k3h5pVOfKGg
JCUyKLh7N1sWplUbHVQQ+1SHSM9deuwHu/Ld9iuRcBydz4EM9J4oxskVE68CZclT
zynxdsAxoWvxuADMsKj94WY2zsJTr/mnJaq+d6prXTYTkdpxCi9BSno5GxJrIfRX
H7gwqAVxsx8npJbsUmkawB8NBI9xeeYiam1jhipFsWLyovPEAw5APao3/kuVNu58
sMz9ui0dUohtfbPsZoUbimSNofSc5anELjAxT3ekQFImCxHaZSf6/LQ+muNG/qRg
aGrK4fNXsRQX39BIv4E0fYTMm8Ud+r6LuRDTs+z1OEOt+VKVcGs4amQ4jMdtZios
nPeS3TZzKwWVYsjQCZ2LQyICDPkAIFxIRHLWtubrh/WYPM+Leik=
=jmH2
-----END PGP SIGNATURE-----

pinheadmz's public key is on keybase

@ajtowns
Copy link
Contributor

ajtowns commented Sep 12, 2023

The behavior was intended to be added in #11191.

It's still not clear if this was broken from the time it was merged, or at some other later point. This also does not work with 22.x, and any earlier versions are EOL.

If it's been broken forever (or at least is in all currently maintained releases), and no ones even noticed, we could take advantage of that, to remove some of the complexity here; do we definitely need multiple different ways of achieving the same logging toggling?

Has this comment being replied to anywhere already?

It does seem like it would be pretty easy to remove this behaviour -- removing "none" would mean that anyone who specified it would get an error on startup, which is a good clue to fix their config. And you get the same "actually, for this run I want to disable debugging stuff" by adding -nodebug at the end (eg, on the cli) or by specifying "-debugexclude=all". For the logging rpc, just replace the argument with [] instead of adding none seems reasonable.

@jonatack
Copy link
Member Author

Has this comment being replied to anywhere already?

Yes, #27231 (comment) and the pull description contains that discussion as well.

@ajtowns
Copy link
Contributor

ajtowns commented Sep 13, 2023

Exploring this, it doesn't look like there would be much code simplification gained by dropping none for 0 only, which would no longer be in symmetry with all/1 that have been operational for a long time.

Why would you keep the 0 option? Just drop the concept entirely: master...ajtowns:bitcoin:202309-debug-no-none That special case was added well prior to -debugexclude (namely #3067 vs #10123)

@jonatack
Copy link
Member Author

I think that question is addressed in the pull description.

@ajtowns
Copy link
Contributor

ajtowns commented Sep 13, 2023

Why would you keep the 0 option? Just drop the concept entirely: master...ajtowns:bitcoin:202309-debug-no-none That special case was added well prior to -debugexclude (namely #3067 vs #10123)

I think that question is addressed in the pull description.

I would have thought it was obvious that I don't see an answer to that question in the pull description, so that's an impressively unconstructive response. In the PR description, you claim:

  • leave the functionality out, raise with an error message if the values are passed, and update the RPC help documentation, or
  • fix the behavior by returning early.

Both solutions involve essentially the same code size and complexity.

But that's trivially not true: removing the code obviously results in a lower code size, and it also reduces the number of special cases that have to be documented and understood by users.

No longer convinced this makes sense.

@jonatack
Copy link
Member Author

jonatack commented Sep 13, 2023

I would have thought it was obvious that I don't see an answer to that question in the pull description, so that's an impressively unconstructive response.

It's reasonable to think one could gloss over the long-ish discussion in the OP (or what I attempted to communicate with it), as I think it replies to the question (at least, as I understood it).

Here's the relevant section:

During the same time period, passing `1` and `all` has been operational and documented. 

Solution: detect `none`/`0` values and add test coverage in any case, and either:
    
- leave the functionality out, raise with an error message if the values are passed, and update the RPC
  help documentation, or

- fix the behavior by returning early.

Both solutions involve essentially the same code size and complexity.  Given that `all`/`1` has been
operational, and that `none`/`0` has been documented and appears per the code of the original PR
to have been operational, it seems preferable for consistency to support `none`/`0` in symmetry with
`all`/`1` and as ACKed, intended, and documented in #11191.

But that's trivially not true: removing the code obviously results in a lower code size

No, not if we check for the values and raise with an error message if the values are passed, with relevant test coverage. This ought to be done given that the functionality has been documented in the RPC help for around 7 years now, and perhaps also as it's not clear at what point it broke.

That is what I meant by "Solution: detect none/0 values and add test coverage in any case", for either way requires code, test coverage, and documentation changes. As I wrote, I prefer the route of fixing what was ACKed, intended, and documented in #11191.

This pull improves a lot of things here. It not only fixes broken functionality while using lesser or equal lines of code (apart from test coverage and added docs), it also adds test coverage that has been missing for a long time and improves the documentation. It would be nice to see this finally move forward, and I appreciate your reviews of it!

@ajtowns
Copy link
Contributor

ajtowns commented Sep 14, 2023

Both solutions involve essentially the same code size and complexity.  Given that `all`/`1` has been
operational, and that `none`/`0` has been documented and appears per the code of the original PR
to have been operational, it seems preferable for consistency to support `none`/`0` in symmetry with
`all`/`1` and as ACKed, intended, and documented in #11191.

But that's trivially not true: removing the code obviously results in a lower code size

No, not if we check for the values and raise with an error message if the values are passed, with relevant test coverage.

We already check for invalid categories and issue an error message for those. Doing the same thing for none/0 doesn't require extra code or extra test coverage.

This ought to be done given that the functionality has been documented in the RPC help for around 7 years now, and perhaps also as it's not clear at what point it broke.

FWIW, it broke in #12954 ("This is purely a refactor with no behavior changes." 🙄) -- previously getCategoryMask evaluated all the strings, returning null if "none" was passed in and erroring out if any were invalid; after that PR EnableOrDisableLogCategories dropped the special handling of "none" and enabled/disabled each category as it went, which means logging ["net", "nosuchcategory"] changed its behaviour from just giving an error, to first enabling net logging, then giving an error.

#11191 was merged 2017-11-30 and #12954 was merged 2018-05-01 so this behaviour only worked for five months if you were running master, and only for the 0.16.x release. 0.16.0 was also the first release that considered logging a public api (#11626).

(I have an alias git-history which runs git log --ignore-cr-at-eol -M -C -L${2},${3}:${1}; so git blame rpc/node.cpp to get the line numbers of the function, then git-history rpc/node.cpp 187 204 makes it easy to trace things through. At least until the refactorings get too intense. AAAA+++ excellent alias, highly recommended)

That is what I meant by "Solution: detect none/0 values and add test coverage in any case", for either way requires code, test coverage, and documentation changes. As I wrote, I prefer the route of fixing what was ACKed, intended, and documented in #11191.

Why? The people who ACKed an old PR aren't gods, and we don't have to take their opinions at the time as gospel. As far as I can see, the other ways we (now) have of getting this behaviour are strictly superior.

The reasons to have that behaviour originally was that "-debug" was originally a bool flag that got upgraded to support multiple distinct categories, and the arg parser at the time wasn't as clever/complicated as it is today. The reason given in 11191 for doing anything was "0","1" are allowed in both array of <include> and <exclude>. "0" is ignored and "1" is treated same as "all". It is confusing, so forbid them. so "forbid them" for none/0 still seems pretty reasonable.

This pull improves a lot of things here. It not only fixes broken functionality while using lesser or equal lines of code (apart from test coverage and added docs), it also adds test coverage that has been missing for a long time and improves the documentation. It would be nice to see this finally move forward, and I appreciate your reviews of it!

These commits have a bunch of extra complexity compared to dropping support for this behaviour:

  • Fix RPC logging behaviour -- bunch of extra code, with a requirement to keep it in sync with code in init, vs dropping the documentation
  • Update -debug help docs -- bunch of extra text to read documenting a special case that most people won't want
  • Functional test coverage for RPC -- the 0/none loop can be omitted entirely (unknown category just means previously listed categories get actioned)

Other commits seem mostly fine with 0/none special casing dropped:

  • Unit tests for LogPrintfCategory -- fine
  • Functional test does not return all/none -- fine
  • Improve RPC logging doc and examples -- fine
  • Functional test coverage for -debug -- replace -debug=0 with -nodebug, drop -debugexclude=none check
  • Remove unused NONE enums -- fine-ish

@jonatack
Copy link
Member Author

jonatack commented Jan 8, 2024

I'm going to open an alternate pull that does what you suggest and see what reviewers (if any) prefer.

@DrahtBot
Copy link
Contributor

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

@fanquake
Copy link
Member

fanquake commented Mar 6, 2024

I'm going to open an alternate pull that does what you suggest and see what reviewers (if any) prefer.

Did this end up getting opened? Moving this PR to draft for now in any case.

@fanquake fanquake marked this pull request as draft March 6, 2024 13:59
@fanquake fanquake closed this Mar 18, 2024
@jonatack jonatack mentioned this pull request Apr 3, 2024
@jonatack
Copy link
Member Author

jonatack commented Apr 8, 2024

Will re-open as a new PR, along with the alternative version, as it is a good and mature patch with many updates made for reviews and nits.

@bitcoin bitcoin locked and limited conversation to collaborators Apr 8, 2025
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

9 participants