Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GlobalLogHandler::GetLogHandler() singleton is not unique. #1409

Closed
marcalff opened this issue May 19, 2022 · 5 comments · Fixed by #1420
Closed

GlobalLogHandler::GetLogHandler() singleton is not unique. #1409

marcalff opened this issue May 19, 2022 · 5 comments · Fixed by #1420
Labels
bug Something isn't working

Comments

@marcalff
Copy link
Member

Greetings.

The title is correct.

In my application, the code is calling:

(1) GlobalLogHandler::SetLogHandler(), to set a custom handler

(2) OTEL_INTERNAL_LOG_XXX(), to print internal logs.

These calls produce logs in the custom handler, as expected so far.

But then, later:

(3) OTEL_INTERNAL_LOG_XXX() calls from opentelemetry libraries
end up calling the default handler DefaultLogHandler instead of the custom
one, which defeats the purpose of a singleton SetLogHandler().

Analysis:

GlobalLogHandler::GetHandlerAndLevel() is implemented inline in a header
file, not a .cc file.

When building static libraries, this "singleton" ends up in multiple
libraries:

malff@localhost.localdomain:lib64> pwd
/usr/local/lib64
malff@localhost.localdomain:lib64> for L in `ls libopentelemetry_*.a`; do echo $L; nm $L | c++filt | grep GlobalLogHandler::GetHandlerAndLevel; done
libopentelemetry_common.a
libopentelemetry_exporter_ostream_metrics.a
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_ostream_span.a
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_otlp_grpc.a
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_otlp_grpc_log.a
libopentelemetry_exporter_otlp_http.a
libopentelemetry_exporter_otlp_http_client.a
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_http_client_curl.a
libopentelemetry_metrics.a
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_otlp_recordable.a
libopentelemetry_proto.a
libopentelemetry_resources.a
libopentelemetry_trace.a
0000000000000000 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000000000 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000000000 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_version.a

Note, interestingly, how the GlobalLogHandler::GetHandlerAndLevel() code is
not part of libopentelemetry_common.a, but defined (not referenced) in every use instead.

(4)

man nm gives, for my platform and for "u":

       "u" The symbol is a unique global symbol.  This is a GNU extension to the standard set of
           ELF symbol bindings.  For such a symbol the dynamic linker will make sure that in the
           entire process there is just one symbol with this name and type in use.

I am willing to accept that the linker, when linking several libopentelemetry_*.a static libraries into a final binary, will resolve duplicates, making the singleton unique.

However, there is more to it.

Now with dynamic libraries:

malff@localhost.localdomain:lib64> pwd
/usr/local/lib64
malff@localhost.localdomain:lib64> for L in `ls libopentelemetry_*.so`; do echo $L; nm $L | c++filt | grep GlobalLogHandler::GetHandlerAndLevel; done
libopentelemetry_common.so
libopentelemetry_exporter_ostream_metrics.so
000000000023f788 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
000000000002da83 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
000000000023f760 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_ostream_span.so
0000000000308048 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
00000000000c8765 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000308020 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_otlp_grpc_log.so
libopentelemetry_exporter_otlp_grpc.so
00000000017a82e8 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
0000000000c1d273 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
00000000017a82c0 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_otlp_http_client.so
0000000000727688 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
00000000002ccd8f W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
0000000000727660 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_exporter_otlp_http.so
libopentelemetry_http_client_curl.so
libopentelemetry_metrics.so
00000000004646c8 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
00000000001b0a4f W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
00000000004646a0 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_otlp_recordable.so
libopentelemetry_resources.so
libopentelemetry_trace.so
00000000002e4a08 u guard variable for opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
00000000000b06d1 W opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()
00000000002e49e0 u opentelemetry::v1::sdk::common::internal_log::GlobalLogHandler::GetHandlerAndLevel()::handler_and_level
libopentelemetry_version.so

My reading of (4) is that the linker, when producing a -- single -- opentelemetry_xyz.so library, will ensure the symbol there is unique ... for this .so alone.

The linker is never given all the code at once, and can not enforce uniqueness for all the *.so libraries combined.

Looking further, at runtime: how is dlopen() supposed to reconcile uniqueness of a symbol, when defined in multiple *.so shared libraries ?

Note how the symbol is "W" (weak)

       "W"
       "w" The symbol is a weak symbol that has not been specifically tagged as a weak object
           symbol.  When a weak defined symbol is linked with a normal defined symbol, the normal
           defined symbol is used with no error.  When a weak undefined symbol is linked and the
           symbol is not defined, the value of the symbol is determined in a system-specific
           manner without error.  On some systems, uppercase indicates that a default value has
           been specified.

This possibly explains why multiple instances of the same singleton are not reported as duplicate symbols.

I was not able to investigate if/how dlopen() resolves this, and whether there are indeed multiple instances of the singleton in the final loaded binary or not, but this is highly suspicious, and the behavior seen is consistent with duplicates.

Suggestions for a fix:

Abandon the idea of defining singleton in header files, use a *.cc file instead.

For GlobalLogHandler::GetHandlerAndLevel(),
implement this in global_log_handler.cc, and adjust makefiles accordingly.

Now, this raises the interesting questions of every other singleton defined in
header files, in particular:

  • per signal provider singletons
  • global propagator singletons
  • internal spin locks singletons
  • etc

For example:

  • trace::Provider::GetTracerProvider()
  • trace::Provider::GetLock()
    are at risk of not being unique.

Please consider moving every singleton implementation in a *.cc file,
so it gets defined in only one library (.a or .so), not many.

A good home for these singletons can be libopentelemetry_common.so, possibly libopentelemetry_version.so

Regards.

@marcalff marcalff added the bug Something isn't working label May 19, 2022
@owent
Copy link
Member

owent commented May 19, 2022

To my understanding, ELF ABI will let all .so and executable to share the heap, and when linking, the first weak symbol is used when it's in more than one libraries.This mechanism will ensure all libraries use the same function and the global or static variables finally.Unless you compile them as local symbol (maybe by using -fvisibility=hidden) or use dlopen() to load symbol for a specify .so.

This problem is simular to #1105, we can not do it now because we need api module be head-only.
Maybe we can have more discussion about it.

@marcalff
Copy link
Member Author

A possibility is that I am not using the proper build / link flags when building, will investigate more locally.

@lalitb
Copy link
Member

lalitb commented May 31, 2022

@marcalff - Did you try this further. There should be ideally single global singleton used in the case of more than one library.

@marcalff
Copy link
Member Author

marcalff commented Jun 1, 2022

Hi @lalitb, welcome back.

I have spent a lot of time trying to get logs from the opentelemetry-cpp libraries, but never could make it work.

I am aware that some logs are protected by additional flags, as in:

  opentelemetry::exporter::otlp::OtlpHttpExporterOptions options;
  options.console_debug = true;

and even with console_debug set to true I could not get anything in my own log handler with the main branch.

Then, out of desperation, I moved (in a local branch) the handler_and_level singleton to global_log_handler.cc,
and things worked as expected on the first try.

This allowed me to make progress investigating my own application.

From the technical discussion, I agree that there should be only one single global singleton used, even when multiple opentelemetry-*.so shared libraries are involved, but this does not match my observation.

If it helps, the structure of my application is as follows:

  • a binary that contains main()
  • a shared library, my_plugin.so, that contains calls to opentelemetry-cpp (API and SDK)
  • my_plugin.so is opened with dlopen() from main()
  • my_plugin.so is linked with libopentelemetry-*.so

Build environment used:

malff@localhost.localdomain:build-opentelemetry-cpp> pwd
/home/malff/CODE/MY_GITHUB/build-opentelemetry-cpp
malff@localhost.localdomain:build-opentelemetry-cpp> uname -a
Linux localhost.localdomain 5.3.18-150300.59.68-preempt #1 SMP PREEMPT Wed May 4 11:29:09 UTC 2022 (ea30951) x86_64 x86_64 x86_64 GNU/Linux
malff@localhost.localdomain:build-opentelemetry-cpp> ccmake --version
ccmake version 3.17.0

CMake suite maintained and supported by Kitware (kitware.com/cmake).
malff@localhost.localdomain:build-opentelemetry-cpp> /usr/bin/g++-10 --version
g++-10 (SUSE Linux) 10.3.0
Copyright (C) 2020 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. 

opentelemetry-cpp built with -DCMAKE_POSITION_INDEPENDENT_CODE=ON in CMake.

Local patch applied to make things work:

diff --git a/sdk/include/opentelemetry/sdk/common/global_log_handler.h b/sdk/include/opentelemetry/sdk/common/global_log_handler.h
index 612d21e..42dcd67 100644
--- a/sdk/include/opentelemetry/sdk/common/global_log_handler.h
+++ b/sdk/include/opentelemetry/sdk/common/global_log_handler.h
@@ -143,12 +143,7 @@ class GlobalLogHandler
   static void SetLogLevel(LogLevel level) noexcept { GetHandlerAndLevel().second = level; }
 
 private:
-  static std::pair<nostd::shared_ptr<LogHandler>, LogLevel> &GetHandlerAndLevel() noexcept
-  {
-    static std::pair<nostd::shared_ptr<LogHandler>, LogLevel> handler_and_level{
-        nostd::shared_ptr<LogHandler>(new DefaultLogHandler), LogLevel::Warning};
-    return handler_and_level;
-  }
+  static std::pair<nostd::shared_ptr<LogHandler>, LogLevel> &GetHandlerAndLevel() noexcept;
 };
 
 }  // namespace internal_log
diff --git a/sdk/src/common/CMakeLists.txt b/sdk/src/common/CMakeLists.txt
index debffef..d867435 100644
--- a/sdk/src/common/CMakeLists.txt
+++ b/sdk/src/common/CMakeLists.txt
@@ -1,4 +1,4 @@
-set(COMMON_SRCS random.cc core.cc)
+set(COMMON_SRCS random.cc core.cc global_log_handler.cc)
 if(WIN32)
   list(APPEND COMMON_SRCS platform/fork_windows.cc)
 else()
diff --git a/sdk/src/common/global_log_handler.cc b/sdk/src/common/global_log_handler.cc
index e69de29..5c9c17c 100644
--- a/sdk/src/common/global_log_handler.cc
+++ b/sdk/src/common/global_log_handler.cc
@@ -0,0 +1,25 @@
+
+#include <opentelemetry/sdk/common/global_log_handler.h>
+
+namespace nostd = opentelemetry::nostd;
+
+OPENTELEMETRY_BEGIN_NAMESPACE
+namespace sdk {
+
+namespace common {
+
+namespace internal_log {
+
+std::pair<nostd::shared_ptr<LogHandler>, LogLevel>
+&GlobalLogHandler::GetHandlerAndLevel() noexcept
+  {
+    static std::pair<nostd::shared_ptr<LogHandler>, LogLevel> handler_and_level{
+        nostd::shared_ptr<LogHandler>(new DefaultLogHandler), LogLevel::Warning};
+    return handler_and_level;
+  }
+
+} // namespace internal_log
+} // namespace common
+} // namespace sdk
+OPENTELEMETRY_END_NAMESPACE
+

@owent
Copy link
Member

owent commented Jun 1, 2022

Sorry for my mistake, GlobalLogHandler ia part of sdk, not in api. We we can move this implementation into global_log_handler.cc.
This problem may also be solved by add __attribute__((noclone)) and __attribute__((noinline)) to GlobalLogHandler::GetHandlerAndLevel

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants