Program using OpenTelemetry.pm doesn't exit

[abh]

Using the OLTP exporter, my test program doesn't exit. It prints "shutdown", but keeps running. What am I missing? I don't see any logging. I can access the OTLP endpoint from other programs.

When I use the console exporter the program works as expected.

use v5.30.0;
use strict;
use Data::Dump qw(pp);
use OpenTelemetry;
use OpenTelemetry::SDK;
use OpenTelemetry::SDK::Exporter::Console;
use OpenTelemetry::SDK::Trace::Span::Processor::Simple;

use OpenTelemetry::Exporter::OTLP;
use OpenTelemetry::SDK::Trace::Span::Processor::Batch;

# Obtain the current default tracer provider
my $provider = OpenTelemetry->tracer_provider;

#pp($provider);

# OpenTelemetry->tracer_provider->add_span_processor(
#     OpenTelemetry::SDK::Trace::Span::Processor::Simple->new(
#         exporter => OpenTelemetry::SDK::Exporter::Console->new,
#     ),
# );

my $exporter = OpenTelemetry::Exporter::OTLP->new(

    #endpoint => 'http://otelcol-ntp.ntppipeline.svc:4318'
);

# Use it with a span processor
my $processor = OpenTelemetry::SDK::Trace::Span::Processor::Batch->new(exporter => $exporter,);

OpenTelemetry->tracer_provider->add_span_processor($processor);

# Create a trace
my $tracer = $provider->tracer(name => 'web', version => '1.0');

# Record spans
$tracer->in_span(
    outer => sub ($span, $context) {

        warn "outer";

        # In outer span

        $tracer->in_span(
            inner => sub ($span, $context) {

                warn "inner";

                # In inner span
            }
        );
    }
);

warn "done";

$exporter->force_flush();

warn "flushed";

$exporter->shutdown(100);

warn "shutdown";

[jjatria]

Thanks for the report!

I've seen similar situations in the tests sometimes. I think this is down to the batch exporter using an IO::Async::Function which hasn't terminated, which is what I'm trying to address at least with https://github.com/jjatria/perl-opentelemetry-sdk/blob/b0477773bd15365a06da30e50030758280fb5608/lib/OpenTelemetry/SDK/Trace/Span/Processor/Batch.pm#L180 but it might be that that's not enough.

Most of my tests have been with applications that don't really exit, so this is a useful test case.

[jjatria]

I think I've figured it out. The TL;DR is that I think 786919bfc810eb75c2f7d5835872c4aea51b77fd fixes the problem. But read on for a more detailed explanation.

---

First, a couple of details.

The 5.30.0 feature bundle does not include the warnings pragma. Adding use warnings to your script warns

Illegal character in prototype for ? : $span, $context at ... line ....

because the 5.30.0 also does not include the signatures experimental feature (which you are using in the subs passed as arguments to in_span). Adding use experimental 'signatures' at least ensures we are not getting stuck on red-herrings.

Another thing I noted was that you are doing use OpenTelemetry::SDK and also adding your own span_processor. This is probably not what you wanted: when you use the SDK it will automatically call import, which will set up the default span processors, etc, based on the configuration in the environment.

Since the your environment has nothing set (I presume), it will default to the otlp exporter, which uses the batch processor. So you'll be setting up two separate batch processors. With the change linked to above, this is not really a problem, but it was probably complicating things.

A slightly modified version of your script might look a little like this:

#!/usr/bin/env perl

use strict;
use warnings;
use experimental 'signatures';

BEGIN {
    $ENV{OTEL_TRACES_ENDPOINT} = 'http://otelcol-ntp.ntppipeline.svc:4318';
    # console just to give a little more output
    $ENV{OTEL_TRACES_EXPORTER} = 'console,otlp';
}

# These might also help give an idea of what is happening behind the scenes
use Log::Any::Adapter 'Stderr';
use Metrics::Any::Adapter 'Stderr';

# Since we 'use' these, they call `import` at compile time, which is
# why the ENV variables are set inside a BEGIN block. They could
# instead be set in your actual environment
use OpenTelemetry;
use OpenTelemetry::SDK;

# Obtain the current default tracer provider
my $provider = OpenTelemetry->tracer_provider;

# Create a tracer
my $tracer = $provider->tracer( name => 'web', version => '1.0' );

# Record spans
$tracer->in_span(
    outer => sub ($span, $context) {
        warn "outer";

        $tracer->in_span(
            inner => sub ($span, $context) {
                warn "inner";
            }   
        );  
    }   
);

warn "done";

$provider->force_flush(5)->get; # shorter timeout because impatience

warn "flushed";

$provider->shutdown->get;

warn "shutdown";

Which with the change mentioned above results in the following output (I've removed the IO::Async metrics for brevity):

outer at ... line ...
inner at ... line ...
{'attributes' => {},'dropped_attributes' => 0,'dropped_events' => 0,'dropped_links' => 0,'end_timestamp' => '1700601406.57685','events' => [],'instrumentation_scope' => {'name' => 'web','version' => '1.0'},'kind' => 1,'links' => [],'name' => 'inner','parent_span_id' => '51aee170e5514e6a','resource' => {'process.command' => 'bar','process.command_args' => [],'process.executable.name' => 'perl','process.executable.path' => '.../bin/perl','process.pid' => 2830730,'process.runtime.name' => 'perl','process.runtime.version' => 'v5.36.0','telemetry.sdk.language' => 'perl','telemetry.sdk.name' => 'opentelemetry','telemetry.sdk.version' => '0.018'},'span_id' => '07c851b844df6533','start_timestamp' => '1700601406.5764','status' => {'code' => 1,'description' => ''},'trace_flags' => 1,'trace_id' => '3720c15834e5f72cf14efc4fceadea5c','trace_state' => ''}
{'attributes' => {},'dropped_attributes' => 0,'dropped_events' => 0,'dropped_links' => 0,'end_timestamp' => '1700601406.5845','events' => [],'instrumentation_scope' => {'name' => 'web','version' => '1.0'},'kind' => 1,'links' => [],'name' => 'outer','parent_span_id' => '0000000000000000','resource' => {'process.command' => 'bar','process.command_args' => [],'process.executable.name' => 'perl','process.executable.path' => '.../bin/perl','process.pid' => 2830730,'process.runtime.name' => 'perl','process.runtime.version' => 'v5.36.0','telemetry.sdk.language' => 'perl','telemetry.sdk.name' => 'opentelemetry','telemetry.sdk.version' => '0.018'},'span_id' => '51aee170e5514e6a','start_timestamp' => '1700601406.57547','status' => {'code' => 1,'description' => ''},'trace_flags' => 1,'trace_id' => '3720c15834e5f72cf14efc4fceadea5c','trace_state' => ''}
done at ... line ...
METRIC DISTRIBUTION otel.otlp_exporter.message.uncompressed_size +522 => 522/1 [avg=522]
METRIC DISTRIBUTION otel.otlp_exporter.message.compressed_size +357 => 357/1 [avg=357]
METRIC GAUGE otel.otlp_exporter.request_duration status:599 => 0.00501956
METRIC COUNTER otel.otlp_exporter.failure reason:socket_error +1 => 1
METRIC GAUGE otel.otlp_exporter.request_duration status:599 => 0.00237993
METRIC COUNTER otel.otlp_exporter.failure reason:socket_error +1 => 2
OpenTelemetry error: Unable to export 2 spans
METRIC COUNTER otel.bsp.export.failure +1 => 1
METRIC COUNTER otel.bsp.dropped_spans reason:export-failure +2 => 2
flushed at ... line ...
shutdown at ... line ...

Note that the socket errors are because http://otelcol-ntp.ntppipeline.svc:4318 is unreachable for me. ;)

If you think this answers your question I think you can close this, but feel free to ask for clarification if anything here was a little hazy. Documenting this beast will take quite a bit of work...

---

Updated snippet to reflect https://github.com/jjatria/perl-opentelemetry/issues/8, after which all shutdown and force_flush methods return Future objects.

[jjatria]

This change is included in OpenTelemetry::SDK 0.018, which should be indexed by CPAN shortly :rocket:

[jjatria]

I think this issue can now be closed, but feel free to re-open it if you think otherwise.