search

brave / brave-browser

Brave browser for Android, iOS, Linux, macOS, Windows.
https://brave.com
Mozilla Public License 2.0
17.7k stars 2.31k forks source link

[C130] unexpected messages in logs #41360

Open LaurenWags opened 1 week ago

LaurenWags commented 1 week ago

Description

While testing C130 PR build(s), I noticed the below messages in my logs. I'm not sure if they have any adverse effects yet but they display a few times.

[34424:259:1002/103751.266810:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices). tls_blocking_disallowed 1

Steps to reproduce

  1. Clean profile using one of the PR builds (see https://bravesoftware.slack.com/archives/CU5UXM3EC/p1727798559900959)
  2. Launch (I launched via terminal with /Applications/Brave\ Browser\ Nightly.app/Contents/MacOS/Brave\ Browser\ Nightly --args --enable-logging=stderr
  3. Visit brave://version to confirm you are using a C130 build
  4. Wait a couple of minutes

Actual result

[34424:259:1002/103751.266810:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
[34424:259:1002/103751.545628:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
[34424:259:1002/103751.545686:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
[34424:259:1002/103751.545742:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1

Expected result

no such messages

Reproduces how often

Easily reproduced

Brave version (brave://version info)

PR build for C130:

Brave 1.72.51 Chromium: 130.0.6723.19 (Official Build) nightly (x86_64)
Revision 06fad829365844d6f91d8f6f1fa1e87d1c9e611c
OS macOS Version 14.7 (Build 23H124)

Channel information

Reproducibility

Miscellaneous information

cc @emerick

LaurenWags commented 1 week ago

fyi looks like @GeetaSarvadnya also saw these messages on macOS arm64 with C130 PR build.

LaurenWags commented 1 week ago

Could not reproduce with latest Nightly using same STR

Brave | 1.72.57 Chromium: 129.0.6668.89 (Official Build) nightly (arm64)
-- | --
Revision | c7b1032f95321674b86890954354731254f2fba6
OS | macOS Version 15.1 (Build 24B5055e)
LaurenWags commented 1 week ago

on macOS arm64, here's the crash report: bcc90300-1893-b30c-0000-000000000000

Brave | 1.72.48 Chromium: 130.0.6723.19 (Official Build) nightly (arm64)
-- | --
Revision | 70b441e85b783a65b0088d92c496fa56d6509945
OS | macOS Version 15.1 (Build 24B5055e)
emerick commented 1 week ago

Sounds like it could be a Mac-only startup issue. Upstream has rolled some deeper checks for disallowed instances of blocking behavior and are working through them, so this could turn out to be an upstream issue.

LaurenWags commented 1 week ago

Not seeing the messages with 130.0.6723.19 (Official Build) beta (x86_64) on macOS x64 😞 

Google Chrome | 130.0.6723.19 (Official Build) beta (x86_64)
-- | --
Revision | 79f55b47facdadeb2da1e2540997e27e9023e318-refs/branch-heads/6723@{#426}
OS | macOS Version 14.7 (Build 23H124)

Used similar steps as those in the description:

  1. Launch (I launched via terminal with /Applications/Google\ Chrome\ Beta.app/Contents/MacOS/Google\ Chrome\ Beta --args --enable-logging=stderr)
  2. Visit chrome://version to confirm you are using a C130 build
  3. Wait a couple of minutes --> no messages in terminal about tls blocking
GeetaSarvadnya commented 1 week ago

Reproduced the issue on macOS arm64, I am seeing the same logs on arm64 

259:1003/204229.600463:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
[783:259:1003/204229.753356:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
[783:259:1003/204229.753397:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
[783:259:1003/204229.753419:ERROR:thread_restrictions.cc(54)] Check failed: !tls_blocking_disallowed. Function marked as blocking was called from a scope that disallows blocking! If this task is running inside the ThreadPool, it needs to have MayBlock() in its TaskTraits. Otherwise, consider making this blocking work asynchronous or, as a last resort, you may use ScopedAllowBlocking (see its documentation for best practices).
tls_blocking_disallowed 1
emerick commented 1 week ago

This appears to be an issue with updater::DoPeriodicTasks calling base::PathExists in a non-blocking scope cc @mherrmann 

base::internal::AssertBlockingAllowed[ 00 ] crash_reporter::DumpWithoutCrashing() ( crashpad.cc:267 )
[ 01 ] base::debug::DumpWithoutCrashing(base::Location const&, base::TimeDelta) ( dump_without_crashing.cc:108 )
[ 02 ] logging::(anonymous namespace)::DumpWithoutCrashing(base::debug::CrashKeyString*, std::__Cr::basic_string<char, std::__Cr::char_traits<char>, std::__Cr::allocator<char>> const&, base::Location const&, base::NotFatalUntil) ( check.cc:117 )
[ 03 ] logging::(anonymous namespace)::CheckLogMessage::~CheckLogMessage() ( check.cc:168 )
[ 04 ] logging::(anonymous namespace)::CheckLogMessage::~CheckLogMessage() ( check.cc:166 )
[ 05 ] logging::(anonymous namespace)::CheckLogMessage::~CheckLogMessage() ( check.cc:166 )
[ 06 ] std::__Cr::default_delete<logging::LogMessage>::operator()(logging::LogMessage*) const ( unique_ptr.h:69 )
[ 07 ] std::__Cr::unique_ptr<logging::LogMessage, std::__Cr::default_delete<logging::LogMessage>>::reset(logging::LogMessage*) ( unique_ptr.h:281 )
[ 08 ] logging::CheckError::~CheckError() ( check.cc:335 )
[ 09 ] logging::CheckError::~CheckError() ( check.cc:325 )
[ 10 ] base::internal::AssertBlockingAllowed() ( thread_restrictions.cc:54 )
[ 11 ] base::ScopedBlockingCall::ScopedBlockingCall(base::Location const&, base::BlockingType) ( scoped_blocking_call.cc:46 )
[ 12 ] base::ScopedBlockingCall::ScopedBlockingCall(base::Location const&, base::BlockingType) ( scoped_blocking_call.cc:41 )
[ 13 ] base::PathExists(base::FilePath const&) ( file_util_posix.cc:596 )
[ 14 ] updater::DoPeriodicTasks(base::OnceCallback<void ()>) ( scheduler_mac.cc:70 )
[ 15 ] base::OnceCallback<void ()>::Run() && ( callback.h:156 )
[ 16 ] base::TaskAnnotator::RunTaskImpl(base::PendingTask&) ( task_annotator.cc:203 )
[ 17 ] void base::TaskAnnotator::RunTask<base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl(base::LazyNow*)::$_3>(perfetto::StaticString, base::PendingTask&, base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl(base::LazyNow*)::$_3&&) ( task_annotator.h:90 )
[ 18 ] base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl(base::LazyNow*) ( thread_controller_with_message_pump_impl.cc:470 )
[ 19 ] base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork() ( thread_controller_with_message_pump_impl.cc:332 )
[ 20 ] non-virtual thunk to base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork() ( thread_controller_with_message_pump_impl.cc:0 )
[ 21 ] base::MessagePumpCFRunLoopBase::RunWork() ( message_pump_apple.mm:450 )
[ 22 ] base::MessagePumpCFRunLoopBase::RunWork() ( message_pump_apple.mm:450 )
[ 23 ] base::apple::CallWithEHFrame(void () block_pointer)
[ 24 ] __CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__
[ 25 ] __CFRunLoopDoTimer
[ 26 ] __CFRunLoopDoTimers
[ 27 ] __CFRunLoopRun
[ 28 ] CFRunLoopRunSpecific
[ 29 ] 0x1a9222334
[ 30 ] 0x1a9222334
[ 31 ] 0x1a92220b0
[ 32 ] 0x1a9221e64
[ 33 ] _DPSNextEvent
[ 34 ] __71-[BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:]_block_invoke ( chrome_browser_application_mac.mm:335 )
[ 35 ] __71-[BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:]_block_invoke ( chrome_browser_application_mac.mm:335 )
[ 36 ] base::apple::CallWithEHFrame(void () block_pointer)
[ 37 ] -[NSApplication run]
[ 38 ] base::MessagePumpNSApplication::DoRun(base::MessagePump::Delegate*) ( message_pump_apple.mm:807 )
[ 39 ] base::MessagePumpNSApplication::DoRun(base::MessagePump::Delegate*) ( message_pump_apple.mm:807 )
[ 40 ] base::MessagePumpCFRunLoopBase::Run(base::MessagePump::Delegate*) ( message_pump_apple.mm:161 )
[ 41 ] base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run(bool, base::TimeDelta) ( thread_controller_with_message_pump_impl.cc:640 )
[ 42 ] content::BrowserMainLoop::RunMainMessageLoop() ( browser_main_loop.cc:1102 )
[ 43 ] content::BrowserMainLoop::RunMainMessageLoop() ( browser_main_loop.cc:1102 )
[ 44 ] content::BrowserMainRunnerImpl::Run() ( browser_main_runner_impl.cc:157 )
[ 45 ] content::BrowserMain(content::MainFunctionParams) ( browser_main.cc:34 )
[ 46 ] content::RunContentProcess(content::ContentMainParams, content::ContentMainRunner*) ( content_main.cc:356 )
[ 47 ] content::ContentMain(content::ContentMainParams) ( content_main.cc:369 )
[ 48 ] content::RunContentProcess(content::ContentMainParams, content::ContentMainRunner*) ( content_main.cc:356 )
[ 49 ] content::ContentMain(content::ContentMainParams) ( content_main.cc:369 )
[ 50 ] ChromeMain ( chrome_main.cc:231 )
[ 51 ] main ( chrome_exe_main_mac.cc:218 )
emerick commented 1 week ago

This is why we see these messages only on MacOS and exactly 19 seconds after launch: https://source.chromium.org/chromium/chromium/src/+/main:chrome/browser/updater/scheduler.cc;l=28