SimpleLogRecordProcessor causes deadlock

[RohacekD]

Describe your environment
I am using v1.20.0#0 from vcpkg . When I use OtlpGrpcLogRecordExporter connecting to the Azure collector that is not currently running I got deadlocked on every log.

Steps to reproduce

otlp::OtlpGrpcLogRecordExporterOptions logger_opts;
logger_opts.endpoint = endpoint;
auto exporter		= otlp::OtlpGrpcLogRecordExporterFactory::Create(logger_opts);
auto processor	= std::make_unique<logs_sdk::SimpleLogRecordProcessor>(std::move(exporter));
m_Provider		= std::make_shared<logs_sdk::LoggerProvider>(std::move(processor), std::move(resource));

auto	logger = m_Provider->GetLogger("firstlog", "library_name", OPENTELEMETRY_SDK_VERSION);
logger->EmitLogRecord(severity, msg, ...);

Because OtlpGrpcLogRecordExporter::Export finds out the server is UNAVAILABLE it tries to log this situation:

 grpc::Status status =
        OtlpGrpcClient::DelegateExport(log_service_stub_.get(), std::move(context),
                                       std::move(arena), std::move(*request), response);

if (!status.ok())
{
  OTEL_INTERNAL_LOG_ERROR(
      "[OTLP LOG GRPC Exporter] Export() failed: " << status.error_message());
  return sdk::common::ExportResult::kFailure;
}

This code goes through SimpleLogRecordProcessor::OnEmit again but this time the lock there is locked.

What is the actual behavior?
Deadlock on second entry to the SimpleLogRecordProcessor::OnEmit.

[marcalff]

Thanks for the report.

Could you clarify how OTEL_INTERNAL_LOG_ERROR() leads to SimpleLogRecordProcessor::OnEmit() ?

Do you have a custom internal error handler installed, and what does it do ?

[lalitb]

+1 to @marcalff comment. If you have custom internal error handler configured, ensure that it is not using the OTel logging API to push internal logs through same logging provider, as this would lead to infinite log generation (in case of batch processor), and deadlock (in case of simple processor).
Separate thing, SimpleLogRecordProcessor is not advised to be used in production setup.

[RohacekD]

My custom log handler is not really doing anything fancy:

void GrpcLogHandler::Handle(opentelemetry::sdk::common::internal_log::LogLevel level, const char* file, int line, const char* msg, const opentelemetry::sdk::common::AttributeMap& attributes) noexcept
{
	namespace internal_log = opentelemetry::sdk::common::internal_log;
	namespace trace = opentelemetry::trace;
	auto logger = m_Provider->GetLogger("firstlog", "library_name", OPENTELEMETRY_SDK_VERSION);
	opentelemetry::common::SystemTimestamp now(std::chrono::system_clock::now());
	opentelemetry::logs::Severity		   severity = GetSeverity(level);
	logger->EmitLogRecord(severity, msg,
		opentelemetry::common::MakeAttributes({{opentelemetry::trace::SemanticConventions::kCodeLineno, line}, 
		{opentelemetry::trace::SemanticConventions::kCodeFilepath, file}}), 
		now, trace::Provider::GetTracerProvider()->GetTracer("tracerName", OPENTELEMETRY_SDK_VERSION)->GetCurrentSpan());
}

And set as global log handler via internal_log::GlobalLogHandler::SetLogHandler

[lalitb]

You shouldn't be using OTel instrumentation inside the custom error handler. This will lead to behavior similar to #3039 with batch processor, and dead lock with simple processor. It is a known issue.

[marcalff]

Closing as not a bug.
GlobalLogHandler::SetLogHandler is meant for opentelemetry-cpp internal logs, not for raising logs in opentelemetry using the log signal.