Apm-agent-dotnet: [BUG] Elastic.Apm "fail:" logs when up/downloading Streams to/from Blob storage.

[gcstarr]

APM Agent version and Azure Blob storage

<PackageReference Include="Azure.Storage.Blobs" Version="12.8.4" />
<PackageReference Include="Elastic.Apm" Version="1.11.0" />
<PackageReference Include="Elastic.Apm.Azure.Storage" Version="1.11.0" />

Environment

Windows 10

.NET Framework/Core name and version:
.NET SDK v5.0.300

Application Target Framework(s):

<TargetFramework>net5.0</TargetFramework>
<LangVersion>9.0</LangVersion>

Describe the bug

I originally thought I had the same issue described in elastic/apm-agent-dotnet#1352 however after downgrading Azure.Storage.Blobs to v12.8.4 the issue continued, namely getting the Failed capturing DiagnosticSource event warning from Elastic.Apm on blob operations when using AzureBlobStorageDiagnosticsSubscriber.

This happens on UploadAsync when the Stream being uploaded is a Stream type that has CanSeek set to false, such as HttpRequestStream. This also happens to me when downloading to a Stream, regardless of CanSeek setting.

Error:

fail: Elastic.Apm[0]
      {AzureBlobStorageDiagnosticListener} Failed capturing DiagnosticSource event
      System.ArgumentNullException: Value cannot be null. (Parameter 'uriString')
         at System.Uri..ctor(String uriString)
         at Elastic.Apm.Azure.Storage.BlobUrl..ctor(String url)
         at Elastic.Apm.Azure.Storage.AzureBlobStorageDiagnosticListener.OnStart(KeyValuePair`2 kv, String action)
         at Elastic.Apm.Azure.Storage.AzureBlobStorageDiagnosticListener.HandleOnNext(KeyValuePair`2 kv)
         at Elastic.Apm.DiagnosticListeners.DiagnosticListenerBase.OnNext(KeyValuePair`2 kv)

The blob successfully uploads. And the span is created, however the above warning displays in the logs, and I assume the span will be missing some information.

To Reproduce

I made a repo that reproduces this here: https://github.com/gcstarr/ElasticApmAzureBlobBug

Relevant portions:

1. .UseElasticApm(new AzureBlobStorageDiagnosticsSubscriber());
2. Use an "un-seekable" Stream type (as HttpRequestStream is) to upload from. I made a simple sub-class of MemoryStream like this:

public class UnSeekableStream : MemoryStream
{
    public UnSeekableStream()
    {
    }
    public UnSeekableStream(byte[] buffer) : base(buffer)
    {
    }

    public override bool CanSeek => false;
}

1. Attempt to upload the stream. My function is:

public async Task StartAsync(CancellationToken cancellationToken)
{
    const string containerName = "data-storage";
    var client = new BlockBlobClient(_connectionString, containerName, "test1/test2/test3/testblob");
    var testBytes = Encoding.UTF8.GetBytes("{\"test\": \"test\"}");

    var transaction = _tracer.StartTransaction("Blob Tests", "Sample");

    var seekableStream = new MemoryStream(testBytes);
    var seekableSpan = transaction.StartSpan("Seekable Test Blob Upload", "Sample");
    await client.UploadAsync(seekableStream, new BlobUploadOptions());
    // No errors logged ^
    seekableSpan.End();

    var unSeekableStream = new UnSeekableStream(testBytes);
    var unSeekableSpan = transaction.StartSpan("Un-seekable Test Blob Upload", "Sample");
    await client.UploadAsync(unSeekableStream, new BlobUploadOptions());
    // Fail error logged ^
    unSeekableSpan.End();

    var seekableDownloadStream = new MemoryStream();
    var seekableDownloadSpan = transaction.StartSpan("Seekable Test Blob Download", "Sample");
    await client.DownloadToAsync(seekableDownloadStream);
    // Fail error logged ^
    seekableDownloadSpan.End();

    var unSeekableDownloadStream = new UnSeekableStream();
    var unSeekableDownloadSpan = transaction.StartSpan("Un-seekable Test Blob Download", "Sample");
    await client.DownloadToAsync(unSeekableDownloadStream);
    // Fail error logged ^
    unSeekableDownloadSpan.End();

    transaction.End();
}

1. Note a fail: logged at each of the 3 places noted above by comment.

Expected behavior

Uploading an CanSeek=false Stream type, such as HttpRequestStream, should work as other streams. Downloading to a stream should not throw warnings.

Actual behavior

Uploading with a CanSeek=false Stream type, or downloading to any Stream type, causes Elastic.Apm to throw warnings.

[russcam]

Thanks for reporting @gcstarr.

We're looking at a general fix for #1352, for the next release, which I think would also address this issue. Thank you for the reproduction; I'll add a test in the fix branch based on your repro, to assert this will also be addressed.

[russcam]

Hi @gcstarr, #1484 has been merged which fixes the error that you're seeing in the logs. I've opened https://github.com/elastic/apm-agent-dotnet/pull/1516 to add an additional test using an unseekable stream, thanks for the example. In this case, multiple spans are created related to uploading, staging and committing the blocks. For some of these spans. the destination url for the blob on Azure storage is not available, which was throwing an exception. Now, the url value will be used if it's available otherwise will be omitted from the captured data. Here's what the output for the test in https://github.com/elastic/apm-agent-dotnet/pull/1516 looks like

Elastic.Apm.Azure.Storage.Tests.AzureBlobStorageDiagnosticListenerTests.Capture_Span_When_Upload_Block_Blob_With_Unseekable_Stream

{AbstractConfigurationReader (MockConfiguration)} The agent was started without a service name. The service name will be automatically discovered.
{AbstractConfigurationReader (MockConfiguration)} The agent was started without a service name. The automatically discovered service name is ReSharperTestRunner
{AbstractConfigurationReader (MockConfiguration)} The agent was started without a service version. The service version will be automatically discovered.
{AbstractConfigurationReader (MockConfiguration)} The agent was started without a service version. The automatically discovered service version is 2.2.1.58
{SystemInfoHelper} No /proc/self/cgroup found - the agent will not report container id
{HttpDiagnosticListener} Current runtime is not detected as Full Framework - returning implementation for Core. RuntimeInformation.FrameworkDescription: .NET 5.0.10
{DiagnosticInitializer} There are no listeners in the current batch (Elastic.Apm.DiagnosticListeners.HttpDiagnosticListenerCoreImpl) that would like to subscribe to `Azure.Storage.Blobs' events source
{DiagnosticInitializer} Subscribed Elastic.Apm.Azure.Storage.AzureBlobStorageDiagnosticListener to `Azure.Storage.Blobs' events source
{AzureBlobStorageDiagnosticListener} Called with key: `BlobContainerClient.Create.Start'
{AzureBlobStorageDiagnosticListener} No current transaction or span - exiting
{DiagnosticInitializer} There are no listeners in the current batch (Elastic.Apm.DiagnosticListeners.HttpDiagnosticListenerCoreImpl) that would like to subscribe to `Azure.Core' events source
{DiagnosticInitializer} Subscribed Elastic.Apm.Azure.Storage.AzureCoreDiagnosticListener to `Azure.Core' events source
{AzureBlobStorageDiagnosticListener} Called with key: `BlobContainerClient.Create.Stop'
{AzureBlobStorageDiagnosticListener} Could not find segment for activity 00-9b6d32639e03de48b05360d61df79f72-a6e004144ea5954e-00 in tracked segments
{AbstractConfigurationReader (MockConfiguration)} No transaction sample rate provided. Defaulting to '1'
{Transaction} New Transaction instance created: Transaction{Id: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, ParentId: null, Name: Upload Azure Block Blob, Type: storage, Outcome: Unknown, IsSampled: True}. IsSampled (True) is based on the given sampler (Sampler{ constant: True }). Start time: 2021-10-12 06:46:20.2651370 UTC (as timestamp: 1634021180265137)
{Tracer} Starting Transaction{Id: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, ParentId: null, Name: Upload Azure Block Blob, Type: storage, Outcome: Unknown, IsSampled: True}
{AzureBlobStorageDiagnosticListener} Called with key: `BlockBlobClient.Upload.Start'
{AbstractConfigurationReader (MockConfiguration)} No transaction max spans provided. Defaulting to '500'
{Span.582a4f1a4d830c84} New Span instance created: Span{Id: 582a4f1a4d830c84, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}. Start time: 2021-10-12 06:46:20.2876630 UTC (as timestamp: 1634021180287663). Parent span: (null)
{Transaction} Starting Span{Id: 582a4f1a4d830c84, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}
{AzureBlobStorageDiagnosticListener} Called with key: `BlockBlobClient.StageBlock.Start'
{AbstractConfigurationReader (MockConfiguration)} No transaction max spans provided. Defaulting to '500'
{Span.06afab923804a805} New Span instance created: Span{Id: 06afab923804a805, TransactionId: f1e341b6d861bf4b, ParentId: 582a4f1a4d830c84, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}. Start time: 2021-10-12 06:46:20.3183490 UTC (as timestamp: 1634021180318349). Parent span: Span{Id: 582a4f1a4d830c84, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}
{Span.582a4f1a4d830c84} Starting Span{Id: 06afab923804a805, TransactionId: f1e341b6d861bf4b, ParentId: 582a4f1a4d830c84, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}
{AzureBlobStorageDiagnosticListener} Called with key: `BlockBlobClient.StageBlock.Stop'
{Span.06afab923804a805} Ended Span{Id: 06afab923804a805, TransactionId: f1e341b6d861bf4b, ParentId: 582a4f1a4d830c84, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload e6ca61c0-8403-468b-851a-81cbb98f2f33/b050a582-dbd6-434a-af66-44f4789c0bb8, Type: storage, Outcome: Success, IsSampled: True}. Start time: 2021-10-12 06:46:20.3183490 UTC (as timestamp: 1634021180318349), End time: 2021-10-12 06:46:20.5033950 UTC (as timestamp: 1634021180503395), Duration: 185.046ms
{AzureBlobStorageDiagnosticListener} Called with key: `BlockBlobClient.CommitBlockList.Start'
{AbstractConfigurationReader (MockConfiguration)} No transaction max spans provided. Defaulting to '500'
{Span.4293b5c84b8832ac} New Span instance created: Span{Id: 4293b5c84b8832ac, TransactionId: f1e341b6d861bf4b, ParentId: 582a4f1a4d830c84, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}. Start time: 2021-10-12 06:46:20.6023920 UTC (as timestamp: 1634021180602392). Parent span: Span{Id: 582a4f1a4d830c84, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}
{Span.582a4f1a4d830c84} Starting Span{Id: 4293b5c84b8832ac, TransactionId: f1e341b6d861bf4b, ParentId: 582a4f1a4d830c84, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Unknown, IsSampled: True}
{AzureBlobStorageDiagnosticListener} Called with key: `BlockBlobClient.CommitBlockList.Stop'
{Span.4293b5c84b8832ac} Ended Span{Id: 4293b5c84b8832ac, TransactionId: f1e341b6d861bf4b, ParentId: 582a4f1a4d830c84, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload e6ca61c0-8403-468b-851a-81cbb98f2f33/b050a582-dbd6-434a-af66-44f4789c0bb8, Type: storage, Outcome: Success, IsSampled: True}. Start time: 2021-10-12 06:46:20.6023920 UTC (as timestamp: 1634021180602392), End time: 2021-10-12 06:46:20.7798570 UTC (as timestamp: 1634021180779857), Duration: 177.465ms
{AzureBlobStorageDiagnosticListener} Called with key: `BlockBlobClient.Upload.Stop'
{Span.582a4f1a4d830c84} Ended Span{Id: 582a4f1a4d830c84, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Upload, Type: storage, Outcome: Success, IsSampled: True}. Start time: 2021-10-12 06:46:20.2876630 UTC (as timestamp: 1634021180287663), End time: 2021-10-12 06:46:20.8044010 UTC (as timestamp: 1634021180804401), Duration: 516.738ms
{Transaction} Ended Transaction{Id: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, ParentId: null, Name: Upload Azure Block Blob, Type: storage, Outcome: Success, IsSampled: True}. Start time: 2021-10-12 06:46:20.2651370 UTC (as timestamp: 1634021180265137), End time: 2021-10-12 06:46:20.8402560 UTC (as timestamp: 1634021180840256), Duration: 575.119ms
{AzureBlobStorageDiagnosticListener} Called with key: `BlobContainerClient.DeleteIfExists.Start'
{AzureBlobStorageDiagnosticListener} `BlobContainerClient.DeleteIfExists.Start' key is not a traced diagnostic event
{AzureBlobStorageDiagnosticListener} Called with key: `BlobContainerClient.Delete.Start'
{AbstractConfigurationReader (MockConfiguration)} No transaction max spans provided. Defaulting to '500'
{Span.a7dff07f4ea1f35e} New Span instance created: Span{Id: a7dff07f4ea1f35e, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Delete, Type: storage, Outcome: Unknown, IsSampled: True}. Start time: 2021-10-12 06:46:20.8690390 UTC (as timestamp: 1634021180869039). Parent span: (null)
{Transaction} Starting Span{Id: a7dff07f4ea1f35e, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Delete, Type: storage, Outcome: Unknown, IsSampled: True}
{AzureBlobStorageDiagnosticListener} Called with key: `BlobContainerClient.Delete.Stop'
{Span.a7dff07f4ea1f35e} Ended Span{Id: a7dff07f4ea1f35e, TransactionId: f1e341b6d861bf4b, ParentId: f1e341b6d861bf4b, TraceId: 29725c0fa11adf448ee2030ffadff08d, Name: AzureBlob Delete e6ca61c0-8403-468b-851a-81cbb98f2f33, Type: storage, Outcome: Success, IsSampled: True}. Start time: 2021-10-12 06:46:20.8690390 UTC (as timestamp: 1634021180869039), End time: 2021-10-12 06:46:21.0349520 UTC (as timestamp: 1634021181034952), Duration: 165.913ms
{AzureBlobStorageDiagnosticListener} Called with key: `BlobContainerClient.DeleteIfExists.Stop'
{AzureBlobStorageDiagnosticListener} Could not find segment for activity 00-29725c0fa11adf448ee2030ffadff08d-d95a6cc132d37a45-01 in tracked segments