Spans submitted using OTLP endpoint are not appearing correctly

[pdegenhardt]

Describe the bug I have a couple of child System.Diagnostics.Activity instances, which are executed in sequence: an initialize and an execute inside a command handler. In some instances the initialize activity is appearing in the trace AFTER the execute activity.

To Reproduce I am using the following code in to create the parent and child activities.

        using var activity = AthenaDiagnostics.ApplicationSource.StartActivity("Query: {queryType}");
        using (AthenaDiagnostics.ApplicationSource.StartActivity("Initialize handler"))
        {
            await InitializeAsync(cancellationToken);
        }
        using (AthenaDiagnostics.ApplicationSource.StartActivity("Execute handler"))
        {
            var result = await HandleCoreAsync(query, cancellationToken);
            if (activity?.IsAllDataRequested == true)
            {
                activity.SetTag("queryType", _name);
            }
            return result;
        }

If I look at the JSON for each span, I can see the following:

Initialize: @st=2024-06-21T06:46:50.3143249Z, @t=2024-06-21T06:46:50.3194968Z
Execute:    @st=2024-06-21T06:46:50.0886911Z, @t=2024-06-21T06:46:50.3195447Z

Expected behavior The initialize activity should appear BEFORE the execute activity.

Screenshots

I have tried calling SetStartTime and SetEndTime on each of the child activities but this does not rectify the problem.

Environment (please complete the following information):

• OS: Windows
• Browser: Chrome
• Seq Version: 2024.3.11547
• Using Docker? No

Additional context OpenTelemetry.Exporter.OpenTelemetryProtocol 1.9.0

Tracing initialization is as follows:

[nblumhardt]

Thanks for the report @pdegenhardt - that's certainly a strange one! I've copied the structure of your code into a repro project but at least with ten runs, everything looks fine to me.

Is the problem regularly reproducible? Clock jitter would go some way to explaining it as a one-off, but otherwise I think trying to comment out code until you have a minimal reproduction is the most likely route to a successful diagnosis.

Server-side the timestamps are stored as-is, so it seems most likely that the issue is client-side, but nothing can be completely ruled out, unfortunately.

[pdegenhardt]

@nblumhardt Ok thanks! I was suspecting it might be down to the OTLP batch exporter. Will do some more experimenting.

There aren't any Seq settings or configuration knobs that cause the @t property to take on the timestamp that the event is received at the server, rather than the value that is transmitted? (The Seq server is quite some network distance from the server generating the spans)

[liammclennan]

Hi @pdegenhardt

There is a 'Use server timestamps' option on API keys.

[pdegenhardt]

@liammclennan Thanks so much! That was it.