[dbarker]

Fixes # (issue)

#4367 runs the configuration example with user extension components that each log to the global logger. This exposed a race condition when two threads read/write to the global log level at the same time.

SUMMARY: ThreadSanitizer: data race (/home/runner/.cache/bazel/e6b8d6759295e14b76bc8cb98b604748/execroot/_main/bazel-out/k8-fastbuild-tsan/bin/examples/configuration/../../_solib_k8/libsdk_Ssrc_Scommon_Slibglobal_Ulog_Uhandler.so+0x6182) (BuildId: 3f249d24e0f37758df7e7d69675545906815d63d) in opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::SetLogLevel(opentelemetry::v1::sdk::common::internal_log::LogLevel)

TSAN detailed log

FAIL: //examples/configuration:example_yaml_extensions (Exit 66) (see /home/runner/.cache/bazel/e6b8d6759295e14b76bc8cb98b604748/execroot/_main/bazel-out/k8-fastbuild-tsan/testlogs/examples/configuration/example_yaml_extensions/test.log)
INFO: From Testing //examples/configuration:example_yaml_extensions:
==================== Test output for //examples/configuration:example_yaml_extensions:
==================
WARNING: ThreadSanitizer: data race (pid=11333)
  Write of size 1 at 0x7ffaf2e70040 by main thread:
    #0 opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::SetLogLevel(opentelemetry::v1::sdk::common::internal_log::LogLevel) <null> (libsdk_Ssrc_Scommon_Slibglobal_Ulog_Uhandler.so+0x6182) (BuildId: 3f249d24e0f37758df7e7d69675545906815d63d)
    #1 opentelemetry::v1::sdk::configuration::ConfiguredSdk::Install() <null> (libsdk_Ssrc_Sconfiguration_Slibconfiguration_Ucore.so+0x306e2d) (BuildId: dbb246d649bc26795ef1a4c96018f8f1ecc8fd2f)
    #2 (anonymous namespace)::InitOtel(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) <null> (example_yaml_extensions+0x62b3d) (BuildId: 55678efe21aaf52d1c2347186c3e4fb7dae4b13a)
    #3 main <null> (example_yaml_extensions+0x62f7e) (BuildId: 55678efe21aaf52d1c2347186c3e4fb7dae4b13a)

  Previous read of size 1 at 0x7ffaf2e70040 by thread T3:
    #0 opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetLogLevel() <null> (libsdk_Ssrc_Scommon_Slibglobal_Ulog_Uhandler.so+0x6119) (BuildId: 3f249d24e0f37758df7e7d69675545906815d63d)
    #1 CustomPushMetricExporter::Export(opentelemetry::v1::sdk::metrics::ResourceMetrics const&) <null> (example_yaml_extensions+0x561f3) (BuildId: 55678efe21aaf52d1c2347186c3e4fb7dae4b13a)
    #2 opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::CollectAndExportOnce()::{lambda(opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}::operator()(opentelemetry::v1::sdk::metrics::ResourceMetrics&) const <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e10bd) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #3 opentelemetry::v1::nostd::function_ref<bool (opentelemetry::v1::sdk::metrics::ResourceMetrics&)>::BindTo<opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::CollectAndExportOnce()::{lambda(opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}>(opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::CollectAndExportOnce()::{lambda(opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}&)::{lambda(void*, opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}::operator()(void*, opentelemetry::v1::sdk::metrics::ResourceMetrics&) const <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e1df5) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #4 opentelemetry::v1::nostd::function_ref<bool (opentelemetry::v1::sdk::metrics::ResourceMetrics&)>::BindTo<opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::CollectAndExportOnce()::{lambda(opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}>(opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::CollectAndExportOnce()::{lambda(opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}&)::{lambda(void*, opentelemetry::v1::sdk::metrics::ResourceMetrics&)#1}::_FUN(void*, opentelemetry::v1::sdk::metrics::ResourceMetrics&) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e1e54) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #5 opentelemetry::v1::nostd::function_ref<bool (opentelemetry::v1::sdk::metrics::ResourceMetrics&)>::operator()(opentelemetry::v1::sdk::metrics::ResourceMetrics&) const <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x49fb1e) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #6 opentelemetry::v1::sdk::metrics::MetricReader::Collect(opentelemetry::v1::nostd::function_ref<bool (opentelemetry::v1::sdk::metrics::ResourceMetrics&)>) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x49ee19) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #7 opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::CollectAndExportOnce() <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e12aa) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #8 opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::DoBackgroundWork() <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e0b38) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #9 void std::__invoke_impl<void, void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*>(std::__invoke_memfun_deref, void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*&&)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*&&) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e5b71) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #10 std::__invoke_result<void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*>::type std::__invoke<void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*>(void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*&&)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*&&) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e5a3e) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #11 void std::thread::_Invoker<std::tuple<void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*> >::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e593a) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #12 std::thread::_Invoker<std::tuple<void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*> >::operator()() <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e58c2) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #13 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::*)(), opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader*> > >::_M_run() <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e5874) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #14 <null> <null> (libstdc++.so.6+0xecdb3) (BuildId: 753c6c8608b61d4e67be8f0c890e03e0aa046b8b)

  Location is global 'opentelemetry::v1::sdk::common::internal_log::(anonymous namespace)::GlobalLogHandlerData::Instance()::instance' of size 24 at 0x7ffaf2e70030 (libsdk_Ssrc_Scommon_Slibglobal_Ulog_Uhandler.so+0xa040)

  Thread T3 (tid=11342, running) created by main thread at:
    #0 pthread_create ../../../../src/libsanitizer/tsan/tsan_interceptors_posix.cpp:1022 (libtsan.so.2+0x5ac1a) (BuildId: 2a13a7710e361d06f7babbea53065ca2be93f738)
    #1 std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) <null> (libstdc++.so.6+0xeceb0) (BuildId: 753c6c8608b61d4e67be8f0c890e03e0aa046b8b)
    #2 opentelemetry::v1::sdk::metrics::PeriodicExportingMetricReader::OnInitialized() <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x3e0a1f) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #3 opentelemetry::v1::sdk::metrics::MetricReader::SetMetricProducer(opentelemetry::v1::sdk::metrics::MetricProducer*) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x49ea65) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #4 opentelemetry::v1::sdk::metrics::MetricCollector::MetricCollector(opentelemetry::v1::sdk::metrics::MeterContext*, std::shared_ptr<opentelemetry::v1::sdk::metrics::MetricReader>, std::unique_ptr<opentelemetry::v1::sdk::metrics::MetricFilter, std::default_delete<opentelemetry::v1::sdk::metrics::MetricFilter> >) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x4abbbf) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #5 opentelemetry::v1::sdk::metrics::MeterContext::AddMetricReader(std::shared_ptr<opentelemetry::v1::sdk::metrics::MetricReader>, std::unique_ptr<opentelemetry::v1::sdk::metrics::MetricFilter, std::default_delete<opentelemetry::v1::sdk::metrics::MetricFilter> >) <null> (libsdk_Ssrc_Smetrics_Slibmetrics.so+0x46cfe0) (BuildId: 0b27efc794dd8ed82327275deb69bdea4c1be791)
    #6 opentelemetry::v1::sdk::configuration::SdkBuilder::CreateMeterProvider(std::unique_ptr<opentelemetry::v1::sdk::configuration::MeterProviderConfiguration, std::default_delete<opentelemetry::v1::sdk::configuration::MeterProviderConfiguration> > const&, opentelemetry::v1::sdk::resource::Resource const&) const <null> (libsdk_Ssrc_Sconfiguration_Slibconfiguration_Ucore.so+0x3b1ad7) (BuildId: dbb246d649bc26795ef1a4c96018f8f1ecc8fd2f)
    #7 opentelemetry::v1::sdk::configuration::SdkBuilder::CreateConfiguredSdk(std::unique_ptr<opentelemetry::v1::sdk::configuration::Configuration, std::default_delete<opentelemetry::v1::sdk::configuration::Configuration> > const&) const <null> (libsdk_Ssrc_Sconfiguration_Slibconfiguration_Ucore.so+0x3b5765) (BuildId: dbb246d649bc26795ef1a4c96018f8f1ecc8fd2f)
    #8 opentelemetry::v1::sdk::configuration::ConfiguredSdk::Create(std::shared_ptr<opentelemetry::v1::sdk::configuration::Registry>, std::unique_ptr<opentelemetry::v1::sdk::configuration::Configuration, std::default_delete<opentelemetry::v1::sdk::configuration::Configuration> > const&) <null> (libsdk_Ssrc_Sconfiguration_Slibconfiguration_Ucore.so+0x30699f) (BuildId: dbb246d649bc26795ef1a4c96018f8f1ecc8fd2f)
    #9 (anonymous namespace)::InitOtel(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) <null> (example_yaml_extensions+0x62ac2) (BuildId: 55678efe21aaf52d1c2347186c3e4fb7dae4b13a)
    #10 main <null> (example_yaml_extensions+0x62f7e) (BuildId: 55678efe21aaf52d1c2347186c3e4fb7dae4b13a)

SUMMARY: ThreadSanitizer: data race (/home/runner/.cache/bazel/e6b8d6759295e14b76bc8cb98b604748/execroot/_main/bazel-out/k8-fastbuild-tsan/bin/examples/configuration/../../_solib_k8/libsdk_Ssrc_Scommon_Slibglobal_Ulog_Uhandler.so+0x6182) (BuildId: 3f249d24e0f37758df7e7d69675545906815d63d) in opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::SetLogLevel(opentelemetry::v1::sdk::common::internal_log::LogLevel)

Changes

Please provide a brief description of the changes here.

For significant contributions please make sure you have completed the following items:

• CHANGELOG.md updated for non-trivial changes
• Unit tests have been added
• Changes in public API reviewed

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 81.78%. Comparing base (5cfda3c) to head (b8f4125).
⚠️ Report is 1 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4368      +/-   ##
==========================================
+ Coverage   81.77%   81.78%   +0.01%     
==========================================
  Files         493      493              
  Lines       19456    19474      +18     
==========================================
+ Hits        15909    15924      +15     
- Misses       3547     3550       +3     

Files with missing lines	Coverage Δ
sdk/src/common/global_log_handler.cc	76.20% <100.00%> (ø)

... and 1 file with indirect coverage changes

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[marcalff]

LGTM

[marcalff]

@dbarker

Thanks for the fix.

This is a bug in the production code, because changing the log level dynamically while an application is running is valid, and expected.

Risk analysis:

Consequences when not fixing this

User applications will see TSAN data races, as reported.

An instrumented application thread may not be responsive to log level changes, only noticing the change "eventually".

• This prevents troubleshooting when increasing the log level,
• This causes spamming when decreasing the log level.

Consequences when fixing this

Possible concern with performance overhead, using an atomic instead of a plain read.

Analysis:

• The atomic is "mostly-read", meaning the value will be written to only on very exceptional conditions.
• Readers will load the atomic once, and keep in the CPU cache as shared (MOSI)
• The cache is very unlikely to be invalidated, so there will be no contention on the log level.
• The cache will only be invalidated on a write, working exactly as expected.

My assessment is that we should fix this, per this PR.