util: Log early messages #16112

maflcko · 2019-05-28T12:36:08Z

Early log messages are dropped on the floor and they'd never make it to the console or debug log. This can be tested by running the test included in this pull request without re-compiling the bitcoind.

Fix that by buffering early messages and flushing them as soon as all logging options have been initialized and logging has been started.

This pull request is identical to "Log early messages with -printtoconsole" (#13088) by ajtowns, with the following changes:

Rebased
Added docstrings for m_buffering and StartLogging
Switch CCriticalSection (aka RecursiveMutex) to just Mutex in the last commit
Added tests

Fixes #16098
Fixes #13157
Closes #13088

promag

Tested ACK fa9bc80, ~~I don't see a problem regarding the new circular dependency.~~

src/init.cpp

maflcko · 2019-05-28T14:38:51Z

I don't see a problem regarding the new circular dependency.

It would lead to issues in debug builds when a potential deadlock was detected, so I've reverted that for now.

DrahtBot · 2019-05-28T15:56:33Z

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#16224 (gui: Bilingual GUI error messages by hebasto)
#16115 (On bitcoind startup, write config args to debug.log by LarryRuane)

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.

hebasto

Concept ACK.

src/init.cpp

src/logging.cpp

src/test/setup_common.cpp

src/init.cpp

StartLogging() is used to mark the start of logging generically, whether using -printtoconsole or -debuglogfile.

This ensures log messages prior to StartLogging() are replayed to the console as well as to the debug log file.

sipa · 2019-05-28T20:08:18Z

Concept ACK

practicalswift · 2019-05-29T07:23:38Z

Is there any reason to buffer the writing to stdout (m_print_to_console)?

ajtowns · 2019-05-31T01:37:55Z

Is there any reason to buffer the writing to stdout (m_print_to_console)?

If you have bitcoind -noconnect=0 but have printtoconsole=0 in bitcoind.conf, then the "confusing double-negative" error will be queued when parsing the command line, but m_print_to_console can't be set to false until later when the config file is actually read.

ajtowns · 2019-05-31T02:07:12Z

I've done #16127 to see what it would take to keep the thread safety annotations without the dependency loop (and hopefully also without the bugs), and what it'd look like to do the same thing elsewhere. Seems better to do that later (or not at all) than to add it to this PR to me...

ajtowns · 2019-05-31T02:52:13Z

utACK faa2a47

kristapsk

ACK faa2a47 (ran added functional test before / after recompiling, didn't do additional testing)

practicalswift · 2019-06-12T07:16:31Z

@MarcoFalke, why buffer also the writing to stdout? Don't we want to print to stdout as soon as possible to be on the safe side? I think it makes sense to keep the "print to console" code path as simple/dumb as possible. Especially given the amount of trouble we've had with getting "just-after-process-launch-logging" working robustly :-)

Is there any reason to buffer the writing to stdout (m_print_to_console)?

maflcko · 2019-06-17T22:01:42Z

@practicalswift See #16112 (comment)

maflcko · 2019-06-17T22:03:25Z

Unless there are objections, this will be merged tomorrow

hebasto · 2019-06-18T10:16:37Z

Unless there are objections, this will be merged tomorrow

Going to test in a few hours.

hebasto · 2019-06-18T14:47:07Z

ACK faa2a47

Tested on Linux Mint 19.1:

the patched test/functional/feature_config_args.py fails on master (22b6c4e)
LogPrintf() fails due to premature call before InitLogging() #16098 is fixed:

$ cat ~/.bitcoin/bitcoin.conf
trash=1

$ src/qt/bitcoin-qt -noonion=0

$ head ~/.bitcoin/debug.log 





2019-06-18T14:40:23Z Warning: parsed potentially confusing double-negative -onion=0
2019-06-18T14:40:23Z Ignoring unknown configuration value trash
2019-06-18T14:40:23Z Bitcoin Core version v0.18.99.0-10ae3a70e (release build)
2019-06-18T14:40:23Z GUI: QObject::connect: invalid null parameter
2019-06-18T14:40:23Z Assuming ancestors of block 0000000000000000000f1c54590ee18d15ec70e68c8cd4cfbadb1b4f11697eee have valid signatures.

Nit: could the test for

bitcoin/src/util/system.cpp

Line 864 in 8ab4f28

LogPrintf("Ignoring unknown configuration value %s\n", option.first);

be added?

faa2a47 logging: Add threadsafety comments (MarcoFalke) 0b282f9 Log early messages with -printtoconsole (Anthony Towns) 4129874 Replace OpenDebugLog() with StartLogging() (Anthony Towns) Pull request description: Early log messages are dropped on the floor and they'd never make it to the console or debug log. This can be tested by running the test included in this pull request without re-compiling the `bitcoind`. Fix that by buffering early messages and flushing them as soon as all logging options have been initialized and logging has been started. This pull request is identical to "Log early messages with -printtoconsole" (#13088) by **ajtowns**, with the following changes: * Rebased * Added docstrings for `m_buffering` and `StartLogging` * Switch `CCriticalSection` (aka `RecursiveMutex`) to just `Mutex` in the last commit * Added tests Fixes #16098 Fixes #13157 Closes #13088 ACKs for commit faa2a4: ajtowns: utACK faa2a47 hebasto: ACK faa2a47 kristapsk: ACK faa2a47 (ran added functional test before / after recompiling, didn't do additional testing) Tree-SHA512: 685e2882642fe2a43ce171d42862582dadb840d03cda8236a994322c389ca2a1f3f431b179b2726c155c61793543bb340c568a5455d97f8b83bc7d307a85d387

faa2a47 logging: Add threadsafety comments (MarcoFalke) 0b282f9 Log early messages with -printtoconsole (Anthony Towns) 4129874 Replace OpenDebugLog() with StartLogging() (Anthony Towns) Pull request description: Early log messages are dropped on the floor and they'd never make it to the console or debug log. This can be tested by running the test included in this pull request without re-compiling the `bitcoind`. Fix that by buffering early messages and flushing them as soon as all logging options have been initialized and logging has been started. This pull request is identical to "Log early messages with -printtoconsole" (bitcoin#13088) by **ajtowns**, with the following changes: * Rebased * Added docstrings for `m_buffering` and `StartLogging` * Switch `CCriticalSection` (aka `RecursiveMutex`) to just `Mutex` in the last commit * Added tests Fixes bitcoin#16098 Fixes bitcoin#13157 Closes bitcoin#13088 ACKs for commit faa2a4: ajtowns: utACK faa2a47 hebasto: ACK faa2a47 kristapsk: ACK faa2a47 (ran added functional test before / after recompiling, didn't do additional testing) Tree-SHA512: 685e2882642fe2a43ce171d42862582dadb840d03cda8236a994322c389ca2a1f3f431b179b2726c155c61793543bb340c568a5455d97f8b83bc7d307a85d387

Summary: ``` Early log messages are dropped on the floor and they'd never make it to the console or debug log. This can be tested by running the test included in this pull request without re-compiling the bitcoind. Fix that by buffering early messages and flushing them as soon as all logging options have been initialized and logging has been started. ``` Backport of core [[bitcoin/bitcoin#16112 | PR16112]]. Test Plan: ninja check check-functional Reviewers: #bitcoin_abc, deadalnix Reviewed By: #bitcoin_abc, deadalnix Subscribers: deadalnix Differential Revision: https://reviews.bitcoinabc.org/D5553

5478d6c logging: thread safety annotations (Anthony Towns) e685ca1 util/system.cpp: add thread safety annotations for dir_locks (Anthony Towns) a788789 test/checkqueue_tests: thread safety annotations (Anthony Towns) 479c584 rpc/blockchain.cpp: thread safety annotations for latestblock (Anthony Towns) 8b5af3d net: fMsgProcWake use LOCK instead of lock_guard (Anthony Towns) de7c5f4 wallet/wallet.h: Remove mutexScanning which was only protecting a single atomic bool (Anthony Towns) c3cf2f5 rpc/blockchain.cpp: Remove g_utxosetscan mutex that is only protecting a single atomic variable (Anthony Towns) Pull request description: In a few cases we need to use `std::mutex` rather than the sync.h primitives. But `std::lock_guard<std::mutex>` doesn't include the clang thread safety annotations unless you also use clang's C library, which means you can't indicate when variables should be guarded by `std::mutex` mutexes. This adds an annotated version of `std::lock_guard<std::mutex>` to threadsafety.h to fix that, and modifies places where `std::mutex` is used to take advantage of the annotations. It's based on top of #16112, and turns the thread safety comments included there into annotations. It also changes the RAII classes in wallet/wallet.h and rpc/blockchain.cpp to just use the atomic<bool> flag for synchronisation rather than having a mutex that doesn't actually guard anything as well. ACKs for top commit: MarcoFalke: ACK 5478d6c 🗾 hebasto: re-ACK 5478d6c, only renamed s/`MutexGuard`/`LockGuard`/, and dropped the commit "test/util_threadnames_tests: add thread safety annotations" since the [previous](#16127 (review)) review. ryanofsky: Code review ACK 5478d6c. Thanks for taking suggestions! Only changes since last review are dropping thread rename test commit d53072ec730d8eec5a5b72f7e65a54b141e62b19 and renaming mutex guard to lock guard Tree-SHA512: 7b00d31f6f2b5a222ec69431eb810a74abf0542db3a65d1bbad54e354c40df2857ec89c00b4a5e466c81ba223267ca95f3f98d5fbc1a1d052a2c3a7d2209790a

5478d6c logging: thread safety annotations (Anthony Towns) e685ca1 util/system.cpp: add thread safety annotations for dir_locks (Anthony Towns) a788789 test/checkqueue_tests: thread safety annotations (Anthony Towns) 479c584 rpc/blockchain.cpp: thread safety annotations for latestblock (Anthony Towns) 8b5af3d net: fMsgProcWake use LOCK instead of lock_guard (Anthony Towns) de7c5f4 wallet/wallet.h: Remove mutexScanning which was only protecting a single atomic bool (Anthony Towns) c3cf2f5 rpc/blockchain.cpp: Remove g_utxosetscan mutex that is only protecting a single atomic variable (Anthony Towns) Pull request description: In a few cases we need to use `std::mutex` rather than the sync.h primitives. But `std::lock_guard<std::mutex>` doesn't include the clang thread safety annotations unless you also use clang's C library, which means you can't indicate when variables should be guarded by `std::mutex` mutexes. This adds an annotated version of `std::lock_guard<std::mutex>` to threadsafety.h to fix that, and modifies places where `std::mutex` is used to take advantage of the annotations. It's based on top of bitcoin#16112, and turns the thread safety comments included there into annotations. It also changes the RAII classes in wallet/wallet.h and rpc/blockchain.cpp to just use the atomic<bool> flag for synchronisation rather than having a mutex that doesn't actually guard anything as well. ACKs for top commit: MarcoFalke: ACK 5478d6c 🗾 hebasto: re-ACK 5478d6c, only renamed s/`MutexGuard`/`LockGuard`/, and dropped the commit "test/util_threadnames_tests: add thread safety annotations" since the [previous](bitcoin#16127 (review)) review. ryanofsky: Code review ACK 5478d6c. Thanks for taking suggestions! Only changes since last review are dropping thread rename test commit d53072ec730d8eec5a5b72f7e65a54b141e62b19 and renaming mutex guard to lock guard Tree-SHA512: 7b00d31f6f2b5a222ec69431eb810a74abf0542db3a65d1bbad54e354c40df2857ec89c00b4a5e466c81ba223267ca95f3f98d5fbc1a1d052a2c3a7d2209790a

merge bitcoin#11640, bitcoin#11599, bitcoin#16112, bitcoin#16127, bitcoin#18635, bitcoin#19249: thread safety and locking improvements

DrahtBot added Tests Utils/log/libs labels May 28, 2019

maflcko removed the Tests label May 28, 2019

maflcko force-pushed the 1905-bufferLog branch 2 times, most recently from fab38de to fa9bc80 Compare May 28, 2019 13:07

promag reviewed May 28, 2019

View reviewed changes

src/init.cpp Outdated Show resolved Hide resolved

maflcko force-pushed the 1905-bufferLog branch 4 times, most recently from fa10f8b to faaba72 Compare May 28, 2019 14:37

maflcko mentioned this pull request May 28, 2019

test: Handle timestamps without microseconds in combine_logs #13157

Closed

hebasto reviewed May 28, 2019

View reviewed changes

src/init.cpp Outdated Show resolved Hide resolved

src/logging.cpp Outdated Show resolved Hide resolved

src/test/setup_common.cpp Outdated Show resolved Hide resolved

src/init.cpp Outdated Show resolved Hide resolved

ajtowns and others added 3 commits May 28, 2019 14:26

Replace OpenDebugLog() with StartLogging()

4129874

StartLogging() is used to mark the start of logging generically, whether using -printtoconsole or -debuglogfile.

Log early messages with -printtoconsole

0b282f9

This ensures log messages prior to StartLogging() are replayed to the console as well as to the debug log file.

logging: Add threadsafety comments

faa2a47

maflcko force-pushed the 1905-bufferLog branch from faaba72 to fa6bb8a Compare May 28, 2019 18:27

maflcko force-pushed the 1905-bufferLog branch from bb96bd0 to faa2a47 Compare May 29, 2019 01:23

ajtowns mentioned this pull request May 29, 2019

Log early messages with -printtoconsole #13088

Closed

ajtowns mentioned this pull request May 31, 2019

More thread safety annotation coverage #16127

Merged

maflcko changed the title ~~log: Log early messages~~ util: Log early messages Jun 11, 2019

kristapsk approved these changes Jun 11, 2019

View reviewed changes

maflcko merged commit faa2a47 into bitcoin:master Jun 18, 2019

maflcko deleted the 1905-bufferLog branch June 18, 2019 18:08

maflcko mentioned this pull request Jun 18, 2019

test: Add test for unknown args #16234

Merged

kwvg mentioned this pull request Jun 5, 2021

merge #11640, #11599, #16112, #16127, #18635, #19249: thread safety and locking improvements dashpay/dash#4190

Merged

kwvg added a commit to kwvg/dash that referenced this pull request Jun 8, 2021

merge bitcoin#16112: Log early messages

8bc1cae

UdjinM6 added a commit to dashpay/dash that referenced this pull request Jun 11, 2021

Merge pull request #4190 from kittywhiskers/tlocks

a8aee57

merge bitcoin#11640, bitcoin#11599, bitcoin#16112, bitcoin#16127, bitcoin#18635, bitcoin#19249: thread safety and locking improvements

bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021

util: Log early messages #16112

util: Log early messages #16112

Uh oh!

Conversation

maflcko commented May 28, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

promag left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

maflcko commented May 28, 2019

Uh oh!

DrahtBot commented May 28, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

hebasto left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

sipa commented May 28, 2019

Uh oh!

practicalswift commented May 29, 2019

Uh oh!

ajtowns commented May 31, 2019

Uh oh!

ajtowns commented May 31, 2019

Uh oh!

ajtowns commented May 31, 2019

Uh oh!

kristapsk left a comment

Choose a reason for hiding this comment

Uh oh!

practicalswift commented Jun 12, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Jun 17, 2019

Uh oh!

maflcko commented Jun 17, 2019

Uh oh!

hebasto commented Jun 18, 2019

Uh oh!

hebasto commented Jun 18, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

8 participants

maflcko commented May 28, 2019 •

edited

Loading

promag left a comment •

edited

Loading

DrahtBot commented May 28, 2019 •

edited

Loading

practicalswift commented Jun 12, 2019 •

edited

Loading