55#include < chrono>
66#include < condition_variable>
77#include < cstdint>
8- #include < map>
8+ #include < map> // IWYU pragma: keep
99#include < memory> // IWYU pragma: keep
1010#include < mutex>
1111#include < nlohmann/json.hpp>
2727#include " opentelemetry/sdk/logs/recordable.h"
2828#include " opentelemetry/version.h"
2929
30+ // Half this file only exists under ENABLE_ASYNC_EXPORT, and include-what-you-use asks for these
31+ // in the configurations that build it and asks for them to go in the ones that do not.
3032#ifdef ENABLE_ASYNC_EXPORT
3133# include < cstddef>
3234# include < functional>
35+ # include < set>
36+
3337# include " opentelemetry/common/timestamp.h"
3438#endif
3539
@@ -423,12 +427,7 @@ ElasticsearchLogRecordExporter::ElasticsearchLogRecordExporter(
423427 ,
424428 synchronization_data_ (new SynchronizationData())
425429#endif
426- {
427- #ifdef ENABLE_ASYNC_EXPORT
428- synchronization_data_->finished_session_counter_ .store (0 );
429- synchronization_data_->session_counter_ .store (0 );
430- #endif
431- }
430+ {}
432431
433432std::unique_ptr<sdklogs::Recordable> ElasticsearchLogRecordExporter::MakeRecordable () noexcept
434433{
@@ -438,9 +437,72 @@ std::unique_ptr<sdklogs::Recordable> ElasticsearchLogRecordExporter::MakeRecorda
438437sdk::common::ExportResult ElasticsearchLogRecordExporter::Export (
439438 const nostd::span<std::unique_ptr<sdklogs::Recordable>> &records) noexcept
440439{
440+ #ifdef ENABLE_ASYNC_EXPORT
441+ // Registered before anything that can return, so a flush asked from the moment these records
442+ // arrive waits for them, and every exit below reports through the guard.
443+ const std::size_t span_count = records.size ();
444+ auto synchronization_data = synchronization_data_;
445+
446+ std::uint64_t session_id = 0 ;
447+ {
448+ std::lock_guard<std::mutex> lock (synchronization_data_->force_flush_cv_m );
449+ session_id = synchronization_data_->next_session_id ++;
450+ synchronization_data_->running_sessions .insert (session_id);
451+ }
452+
453+ // Retiring the export is separate from describing what happened to it, because the refusal
454+ // below has to retire without having an outcome to report through the completion.
455+ auto retire = [session_id, synchronization_data]() noexcept {
456+ bool retired = false ;
457+ {
458+ // Published under the mutex ForceFlush() waits on. A waiter that has evaluated its
459+ // predicate but not yet parked would otherwise not see this until the next wakeup.
460+ std::lock_guard<std::mutex> lock (synchronization_data->force_flush_cv_m );
461+ retired = synchronization_data->running_sessions .erase (session_id) == 1 ;
462+ }
463+ synchronization_data->force_flush_cv .notify_all ();
464+ return retired;
465+ };
466+
467+ using Completion = std::function<bool (opentelemetry::sdk::common::ExportResult)>;
468+ Completion complete = [span_count,
469+ retire](opentelemetry::sdk::common::ExportResult result) noexcept {
470+ retire ();
471+
472+ // Logged after the session is retired. The log handler is replaceable, and one that calls
473+ // ForceFlush() would otherwise wait for the very session this call has not let go of yet.
474+ //
475+ // That is the whole of what the ordering buys, and it is worth being exact about the rest.
476+ // It does not make a log handler safe to re-enter the exporter from in general: one that
477+ // flushes from any callback the HTTP client dispatches can still wait on work that only the
478+ // client thread it is standing on can advance. That is
479+ // https://github.com/open-telemetry/opentelemetry-cpp/issues/4435, and it is not fixed here.
480+ if (result != opentelemetry::sdk::common::ExportResult::kSuccess )
481+ {
482+ OTEL_INTERNAL_LOG_ERROR (" [ES Log Exporter] ERROR: Export "
483+ << span_count
484+ << " log record(s) error: " << static_cast <int >(result));
485+ }
486+ else
487+ {
488+ OTEL_INTERNAL_LOG_DEBUG (" [ES Log Exporter] Export " << span_count
489+ << " log record(s) success" );
490+ }
491+ return true ;
492+ };
493+
494+ // Exactly two exits below: the shutdown refusal retires by hand, and the handler takes the
495+ // session over after SendRequest(). A return added between them must do one or the other.
496+ #endif
497+
441498 // Return failure if this exporter has been shutdown
442499 if (isShutdown ())
443500 {
501+ #ifdef ENABLE_ASYNC_EXPORT
502+ // Retired before the log line below, so a handler that flushes does not wait on this
503+ // Export(). The refusal is reported there, not through the completion.
504+ retire ();
505+ #endif
444506 OTEL_INTERNAL_LOG_ERROR (" [ES Log Exporter] Exporting "
445507 << records.size () << " log(s) failed, exporter is shutdown" );
446508 return sdk::common::ExportResult::kFailure ;
@@ -481,29 +543,10 @@ sdk::common::ExportResult ElasticsearchLogRecordExporter::Export(
481543
482544#ifdef ENABLE_ASYNC_EXPORT
483545 // Send the request
484- synchronization_data_->session_counter_ .fetch_add (1 , std::memory_order_release);
485- std::size_t span_count = records.size ();
486- auto synchronization_data = synchronization_data_;
487- auto handler = std::make_shared<AsyncResponseHandler>(
488- session,
489- [span_count, synchronization_data](opentelemetry::sdk::common::ExportResult result) {
490- if (result != opentelemetry::sdk::common::ExportResult::kSuccess )
491- {
492- OTEL_INTERNAL_LOG_ERROR (" [ES Log Exporter] ERROR: Export "
493- << span_count
494- << " log record(s) error: " << static_cast <int >(result));
495- }
496- else
497- {
498- OTEL_INTERNAL_LOG_DEBUG (" [ES Log Exporter] Export " << span_count
499- << " log record(s) success" );
500- }
501-
502- synchronization_data->finished_session_counter_ .fetch_add (1 , std::memory_order_release);
503- synchronization_data->force_flush_cv .notify_all ();
504- return true ;
505- },
506- options_.console_debug_ );
546+ // The handler reports this session from here on, so the completion goes to it rather than
547+ // being copied to it.
548+ auto handler =
549+ std::make_shared<AsyncResponseHandler>(session, std::move (complete), options_.console_debug_ );
507550 session->SendRequest (handler);
508551 return sdk::common::ExportResult::kSuccess ;
509552#else
@@ -548,41 +591,38 @@ bool ElasticsearchLogRecordExporter::ForceFlush(std::chrono::microseconds timeou
548591 OPENTELEMETRY_MAYBE_UNUSED ) noexcept
549592{
550593#ifdef ENABLE_ASYNC_EXPORT
551- std::lock_guard<std::recursive_mutex> lock_guard{synchronization_data_->force_flush_m };
552- std::size_t running_counter =
553- synchronization_data_->session_counter_ .load (std::memory_order_acquire);
554594 // ASAN will report chrono: runtime error: signed integer overflow: A + B cannot be represented
555595 // in type 'long int' here. So we reset timeout to meet signed long int limit here.
596+ // Returns zero for a timeout not worth waiting against, which is also how a caller asks for
597+ // no deadline.
556598 timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout (
557599 timeout, std::chrono::microseconds::zero ());
558600
559- std::chrono::steady_clock::duration timeout_steady =
560- std::chrono::duration_cast<std::chrono::steady_clock::duration>(timeout);
561- if (timeout_steady <= std::chrono::steady_clock::duration ::zero ())
601+ // No deadline still gets one, since a client is not obliged to call back. response_timeout_
602+ // is the value the request itself carries, so an outstanding session owes an event within it.
603+ if (timeout <= std::chrono::microseconds ::zero ())
562604 {
563- timeout_steady = ( std::chrono::steady_clock::duration::max)() ;
605+ timeout = std::chrono::seconds{options_. response_timeout_ } ;
564606 }
565607
566- std::unique_lock<std::mutex> lk_cv (synchronization_data_->force_flush_cv_m );
567- // Wait for all the sessions to finish
568- while (timeout_steady > std::chrono::steady_clock::duration::zero ())
569- {
570- if (synchronization_data_->finished_session_counter_ .load (std::memory_order_acquire) >=
571- running_counter)
572- {
573- break ;
574- }
608+ // Before the lock, so acquiring the mutex spends the caller's budget and not a fresh one.
609+ const std::chrono::steady_clock::time_point deadline =
610+ std::chrono::steady_clock::now () +
611+ std::chrono::duration_cast<std::chrono::steady_clock::duration>(timeout);
575612
576- std::chrono::steady_clock::time_point start_timepoint = std::chrono::steady_clock::now ();
577- if (std::cv_status::no_timeout != synchronization_data_->force_flush_cv .wait_for (
578- lk_cv, std::chrono::seconds{options_.response_timeout_ }))
579- {
580- break ;
581- }
582- timeout_steady -= std::chrono::steady_clock::now () - start_timepoint;
583- }
613+ std::unique_lock<std::mutex> lock (synchronization_data_->force_flush_cv_m );
614+
615+ // The next id, not a count: a session started later takes a larger id and cannot stand in for
616+ // one of these. Ids are issued in order, so the smallest one still running decides.
617+ const std::uint64_t watermark = synchronization_data_->next_session_id ;
618+ ++synchronization_data_->watermarks_taken ;
619+ const auto flushed = [this , watermark]() {
620+ const auto &running = synchronization_data_->running_sessions ;
621+ return running.empty () || *running.begin () >= watermark;
622+ };
584623
585- return timeout_steady > std::chrono::steady_clock::duration::zero ();
624+ // wait_until() returns the predicate, so running out of time cannot report success.
625+ return synchronization_data_->force_flush_cv .wait_until (lock, deadline, flushed);
586626#else
587627 return true ;
588628#endif
0 commit comments