otlp http exporter timeout doesn't work?

[wxl374]

I add traces with otlp http exporter in my project, but after a little time, all my worker threads are stuck. Stacks shows that a thread waiting for a response got the SimpleSpanProcessor's lock and another threads waiting for the lock. The stacks as follows:

Thread 15 (Thread 0x7f29f4ff9700 (LWP 30)):
#0 0x00007f2a0b681705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00007f2a06eb69ac in std::condition_variable::wait(std::unique_lockstd::mutex&) () from /lib64/libstdc++.so.6
#2 0x00000000006ba5f7 in opentelemetry::v1::exporter::otlp::(anonymous namespace)::ResponseHandler::waitForResponse() ()
#3 0x00000000006bcad8 in opentelemetry::v1::exporter::otlp::OtlpHttpClient::Export(google::protobuf::Message const&) ()
#4 0x00000000006b10e5 in opentelemetry::v1::exporter::otlp::OtlpHttpExporter::Export(opentelemetry::v1::nostd::span<std::unique_ptr<opentelemetry::v1::sdk::trace::Recordable, std::default_deleteopentelemetry::v1::sdk::trace::Recordable >, 18446744073709551615ul> const&) ()
#5 0x00000000004656bb in opentelemetry::v1::sdk::trace::SimpleSpanProcessor::OnEnd(std::unique_ptr<opentelemetry::v1::sdk::trace::Recordable, std::default_deleteopentelemetry::v1::sdk::trace::Recordable >&&) (this=0x1809880, span=) at ../include/opentelemetry/sdk/opentelemetry/sdk/trace/simple_processor.h:51
#6 0x00000000006ad088 in opentelemetry::v1::sdk::trace::MultiSpanProcessor::OnEnd(std::unique_ptr<opentelemetry::v1::sdk::trace::Recordable, std::default_deleteopentelemetry::v1::sdk::trace::Recordable >&&) ()
#7 0x00000000006ab256 in opentelemetry::v1::sdk::trace::Span::End(opentelemetry::v1::trace::EndSpanOptions const&) ()
……

Thread 16 (Thread 0x7f29effff700 (LWP 31)):
#0 0x00007f2a063d248d in nanosleep () from /lib64/libc.so.6
#1 0x00007f2a06403014 in usleep () from /lib64/libc.so.6
#2 0x0000000000465671 in sleep_for<long, std::ratio<1l, 1000l> > (__rtime=...) at /usr/include/c++/4.8.2/thread:281
#3 opentelemetry::v1::common::SpinLockMutex::lock (this=this@entry=0x1809890) at ../include/opentelemetry/api/opentelemetry/common/spin_lock_mutex.h:117
#4 0x00000000004656ae in lock_guard (__m=..., this=) at /usr/include/c++/4.8.2/mutex:414
#5 opentelemetry::v1::sdk::trace::SimpleSpanProcessor::OnEnd(std::unique_ptr<opentelemetry::v1::sdk::trace::Recordable, std::default_deleteopentelemetry::v1::sdk::trace::Recordable >&&) (this=0x1809880, span=) at ../include/opentelemetry/sdk/opentelemetry/sdk/trace/simple_processor.h:50
#6 0x00000000006ad088 in opentelemetry::v1::sdk::trace::MultiSpanProcessor::OnEnd(std::unique_ptr<opentelemetry::v1::sdk::trace::Recordable, std::default_deleteopentelemetry::v1::sdk::trace::Recordable >&&) ()
#7 0x00000000006ab256 in opentelemetry::v1::sdk::trace::Span::End(opentelemetry::v1::trace::EndSpanOptions const&) ()
……

I didn't configure exporter::otlp::OtlpHttpExporterOptions.timeout, so the value got from environment variables by default (

opentelemetry-cpp/exporters/otlp/include/opentelemetry/exporters/otlp/otlp_environment.h

Line 150 in 426365c

inline const std::chrono::system_clock::duration GetOtlpDefaultTimeout()

); also I didn't configure environment variables, the value should be 0.

My question is,

1. does this stuck result from the value of exporter::otlp::OtlpHttpExporterOptions.timeout?
2. I invoke StartSpan and End (span) in different functions(threads), on the contrary, all the examples in opentelemetry-cpp/examples/ are in the same function, am I using it right?

For now I don't know the reason why the request didn't response (I compile the static libraries without -DCMAKE_BUILD_TYPE=Debug, there is no symbol tables found in gdb, I got nothing from stack frames), maybe I will consider to add the compile options.

some details:
compilation options: -Wno-unused-local-typedefs -Wall -g -fPIC -std=c++11 -DSNAPPY -fopenmp -O3 -fno-strict-aliasing -msse3 -mssse3 -DJSON_IS_AMALGAMATION -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -DJSON_IS_AMALGAMATION
gcc verion: 4.8.3
opentelemetry-cpp verion: v1.1.0

[lalitb]

does this stuck result from the value of exporter::otlp::OtlpHttpExporterOptions.timeout?

This is possible. Have seen sometimes timeout not working in our CI pipeline for the nonexistent endpoint. Is the collector endpoint not reachable in this case? Please update here if you find more information.

I invoke StartSpan and End (span) in different functions(threads), on the contrary, all the examples in opentelemetry-cpp/examples/ are in the same function, am I using it right?

Yes, as the shared_ptr to the Span object is returned, it is fine to move it across, and close in a different thread. In the case of multiple threads, the trace::Scope object to manage the Span context can't be used as it is stored in Thread Local Storage(TLS). The examples in the repo use the trace::Scope object and so they are in a single thread.

there is no symbol tables found in gdb,

symbols should be generated if build using -DCMAKE_BUILD_TYPE=Debug

[wxl374]

I replayed this situation:

1. add
   std::this_thread::sleep_for(std::chrono::seconds(1));
   before function body in
   

   opentelemetry-cpp/exporters/otlp/src/otlp_http_client.cc

   Line 111 in 7b9132c

   bool waitForResponse()

2. remove otel-collector

It's because std::condition_variable.wait() will wait forever when notify_all() is called before wait(), but we can't make any assumption about the calling order between notify_all() and wait().

how to fix:

1. add a private bool variable called "stop_waiting" in
   

   opentelemetry-cpp/exporters/otlp/src/otlp_http_client.cc

   Line 67 in 1cf2422

   class ResponseHandler : public http_client::EventHandler

2. use the predicated overload of wait with stop_waiting checking in
   

   opentelemetry-cpp/exporters/otlp/src/otlp_http_client.cc

   Line 111 in 1cf2422

   bool waitForResponse()

3. modify stop_waiting in lock before notify_all is called (in OnResponse() and OnEvent())

references:
https://en.cppreference.com/w/cpp/thread/condition_variable
https://stackoverflow.com/questions/17562908/what-if-notify-is-called-before-wait
https://stackoverflow.com/questions/19142368/what-happens-if-i-call-wait-on-a-notified-condition-variable
https://stackoverflow.com/questions/41594472/how-to-ensure-wait-for-is-called-before-notify-one#comment70394038_41594472

[lalitb]

Thanks, @wxl374 . Would you like to contribute to the fix, or else raise an issue to let someone pick this up? Thanks once again for investigating the issue.