New issue
Advanced search Search tips

Issue 749066 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Jul 2017
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 3
Type: Bug

Blocking:
issue 368525



Sign in to add a comment

Data race accessing logging.cc::g_min_log_level

Project Member Reported by gab@chromium.org, Jul 26 2017

Issue description

This race is caught by every test that overrides InProcessBrowserTest::SetUp() to do something before if that something does logging (e.g. virtually all).

This race is also real in the product. If any thread (including main thread) calls SetMinLogLevel() at any point, it races with any log statement trying to GetMinLogLevel().

As usual, there is no such thing as benign data race: 
https://software.intel.com/en-us/blogs/2013/01/06/benign-data-races-what-could-possibly-go-wrong

This is a prerequisite to enabling TSAN for browser_tests.

Log:

WARNING: ThreadSanitizer: data race (pid=9471)
  Write of size 4 at 0x0000106c47d0 by main thread:
    #0 logging::SetMinLogLevel(int) base/logging.cc:412:19 (browser_tests+0x4256c1b)
    #1 logging::InitChromeLogging(base::CommandLine const&, logging::OldFileDeletionState) chrome/common/logging_chrome.cc:325:7 (browser_tests+0x5e28b4f)
    #2 InitLogging chrome/app/chrome_main_delegate.cc:487:3 (browser_tests+0x5e0cb00)
    #3 ChromeMainDelegate::PreSandboxStartup() chrome/app/chrome_main_delegate.cc:837 (browser_tests+0x5e0cb00)
    #4 content::ContentMainRunnerImpl::Initialize(content::ContentMainParams const&) content/app/content_main_runner.cc:638:18 (browser_tests+0x41f3a05)
    #5 content::ContentServiceManagerMainDelegate::Initialize(service_manager::MainDelegate::InitializeParams const&) content/app/content_service_manager_main_delegate.cc:37:32 (browser_tests+0x41f15a4)
    #6 service_manager::Main(service_manager::MainParams const&) services/service_manager/embedder/main.cc:426:29 (browser_tests+0x7035226)
    #7 content::ContentMain(content::ContentMainParams const&) content/app/content_main.cc:19:10 (browser_tests+0x41f1fcb)
    #8 content::BrowserTestBase::SetUp() content/public/test/browser_test_base.cc:271:3 (browser_tests+0x4d46146)
    #9 InProcessBrowserTest::SetUp() chrome/test/base/in_process_browser_test.cc:271:20 (browser_tests+0x43939d0)
    #10 HistoryBrowserTest::SetUp() chrome/browser/history/history_browsertest.cc:56:27 (browser_tests+0x8bae07)
    (...)
  Previous read of size 4 at 0x0000106c47d0 by thread T1:
    #0 GetMinLogLevel base/logging.cc:416:10 (browser_tests+0x4256ddc)
    #1 GetVlogVerbosity base/logging.cc:431 (browser_tests+0x4256ddc)
    #2 logging::GetVlogLevelHelper(char const*, unsigned long) base/logging.cc:441 (browser_tests+0x4256ddc)
    #3 GetVlogLevel<35> base/logging.h:261:10 (browser_tests+0x51854a0)
    #4 net::MapSystemError(int) net/base/net_errors_posix.cc:18 (browser_tests+0x51854a0)
    #5 MapAcceptError net/socket/socket_posix.cc:38:14 (browser_tests+0x527cd91)
    #6 net::SocketPosix::DoAccept(std::__1::unique_ptr<net::SocketPosix, std::__1::default_delete<net::SocketPosix> >*) net/socket/socket_posix.cc:422 (browser_tests+0x527cd91)
    #7 net::SocketPosix::Accept(std::__1::unique_ptr<net::SocketPosix, std::__1::default_delete<net::SocketPosix> >*, base::Callback<void (int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) net/socket/socket_posix.cc:166:12 (browser_tests+0x527cb8a)
    #8 net::TCPSocketPosix::Accept(std::__1::unique_ptr<net::TCPSocketPosix, std::__1::default_delete<net::TCPSocketPosix> >*, net::IPEndPoint*, base::Callback<void (int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) net/socket/tcp_socket_posix.cc:231:21 (browser_tests+0x50d6d57)
    #9 net::TCPServerSocket::Accept(std::__1::unique_ptr<net::StreamSocket, std::__1::default_delete<net::StreamSocket> >*, base::Callback<void (int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) net/socket/tcp_server_socket.cc:73:24 (browser_tests+0x50d5af1)
    #10 net::test_server::EmbeddedTestServer::DoAcceptLoop() net/test/embedded_test_server/embedded_test_server.cc:347:26 (browser_tests+0x5355961)
    (...)
  Location is global 'logging::(anonymous namespace)::g_min_log_level' of size 4 at 0x0000106c47d0 (browser_tests+0x0000106c47d0)
  Thread T1 'EmbeddedTestServer IO Thread' (tid=9513, running) created by main thread at:
    #0 pthread_create <null> (browser_tests+0x58d6b3)
    #1 base::(anonymous namespace)::CreateThread(unsigned long, bool, base::PlatformThread::Delegate*, base::PlatformThreadHandle*, base::ThreadPriority) base/threading/platform_thread_posix.cc:110:13 (browser_tests+0x42ee166)
    #2 base::PlatformThread::CreateWithPriority(unsigned long, base::PlatformThread::Delegate*, base::PlatformThreadHandle*, base::ThreadPriority) base/threading/platform_thread_posix.cc:193:10 (browser_tests+0x42ee025)
    #3 base::Thread::StartWithOptions(base::Thread::Options const&) base/threading/thread.cc:112:15 (browser_tests+0x42f9b53)
    #4 net::test_server::EmbeddedTestServer::StartAcceptingConnections() net/test/embedded_test_server/embedded_test_server.cc:172:3 (browser_tests+0x5354b3d)
    #5 net::test_server::EmbeddedTestServer::Start() net/test/embedded_test_server/embedded_test_server.cc:89:3 (browser_tests+0x5354285)
    #6 HistoryBrowserTest::SetUp() chrome/browser/history/history_browsertest.cc:55:5 (browser_tests+0x8badf0)
    (...)
SUMMARY: ThreadSanitizer: data race base/logging.cc:412:19 in logging::SetMinLogLevel(int)
 

Comment 1 by gab@chromium.org, Jul 26 2017

Owner: gab@chromium.org
Status: Started (was: St)
Project Member

Comment 2 by bugdroid1@chromium.org, Jul 26 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/60d3f7a4275923fb934550908dd3a9999061c1c1

commit 60d3f7a4275923fb934550908dd3a9999061c1c1
Author: Gabriel Charette <gab@chromium.org>
Date: Wed Jul 26 23:34:56 2017

Do not explicitly set kLoggingLevel in browser_tests.

The value specified was the same as the default value in logging.cc
but passing the flag explicitly resulted in a write to
logging.cc::g_min_log_level which would race with reads in tests that
kick off async tasks prior to kicking off their browser.

This CL is attempt #2 at this after dropping
https://chromium-review.googlesource.com/c/585853/

Bug:  749066 , 368525
Change-Id: I83a55241300e5e40af15c6ca702551b579dacbfd
Reviewed-on: https://chromium-review.googlesource.com/587418
Reviewed-by: danakj <danakj@chromium.org>
Reviewed-by: Scott Violet <sky@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#489799}
[modify] https://crrev.com/60d3f7a4275923fb934550908dd3a9999061c1c1/chrome/test/base/test_launcher_utils.cc

Comment 3 by gab@chromium.org, Jul 27 2017

Status: Fixed (was: Started)

Sign in to add a comment