Exception when non-json metadata is sent and open telemetry is active

[intens-pavlas]

Describe the bug
If an event has application/octet-stream metadata (we're using protobuf serialization) and open telemetry is active at the same time then an Exception is thrown in TraceSubscriptionEvent when subscribed on the stream. It is not handled and it is propagated to a client code, where it prevents the event from being received.

To Reproduce
I found some similiraties with #310 .

I was able to borrow his minimal example and modify it to reproduce my behavior.

Replicated code

Steps to reproduce the behavior

1. Setup open telemetry & add active listener for "eventstoredb"
2. Write an event with application/octet-stream metadata, which will be invalid JsonDocument
3. Subscribe to the stream and try to receive the event message

Expected behavior
I think the exception should never be thrown in the first place. However catching the exception in EventMetadataExtensions.cs:24

if (!JsonDocument.TryParseValue(ref reader, out var doc))

->

var text = System.Text.Encoding.UTF8.GetString(eventMetadata.Span);
JsonDocument? doc = null;
try {
	if (!JsonDocument.TryParseValue(ref reader, out doc))
		return TracingMetadata.None;
} catch {
	return TracingMetadata.None;
}

or

Checking for content type in EventStoreClient.Subscriptions.cs:231

if (subscriptionMessage is StreamMessage.Event evt)

->

if (subscriptionMessage is StreamMessage.Event evt && 
    evt.ResolvedEvent.Event.ContentType == "application/json")

both worked well for me as a quick fix.

Actual behavior
The exception is thrown before the event is passed to the client code - preventing the event from being received.

Config/Logs/Screenshots

'0x10' is an invalid start of a value. LineNumber: 1 | BytePositionInLine: 0.

This char is sepcial character used in protobuf serialization process:

• ␐ 0x10 Data Link Escape Cause a limited number of contiguously following characters to be interpreted in some different way.
• ␂ 0x02 Start of Text Terminates the header and starts the message text.
• ␃ 0x03 End of Text Ends the message text, starts a footer (up to the next TC)

  at System.Text.Json.ThrowHelper.ThrowJsonReaderException(Utf8JsonReader& json, ExceptionResource resource, Byte nextByte, ReadOnlySpan`1 bytes)
   at System.Text.Json.Utf8JsonReader.ConsumeValue(Byte marker)
   at System.Text.Json.Utf8JsonReader.ReadFirstToken(Byte first)
   at System.Text.Json.Utf8JsonReader.ReadSingleSegment()
   at System.Text.Json.Utf8JsonReader.Read()
   at System.Text.Json.JsonDocument.TryParseValue(Utf8JsonReader& reader, JsonDocument& document, Boolean shouldThrow, Boolean useArrayPools)
   at EventStore.Client.Diagnostics.ActivitySourceExtensions.TraceSubscriptionEvent(ActivitySource source, String subscriptionId, ResolvedEvent resolvedEvent, ChannelInfo channelInfo, EventStoreClientSettings settings, UserCredentials userCredentials)
   at EventStore.Client.EventStoreClient.StreamSubscriptionResult.<>c__DisplayClass13_0.<<-ctor>g__PumpMessages|0>d.MoveNext()
--- End of stack trace from previous location ---
   at EventStore.Client.EventStoreClient.StreamSubscriptionResult.<>c__DisplayClass13_0.<<-ctor>g__PumpMessages|0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.Threading.Channels.AsyncOperation`1.GetResult(Int16 token)
   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+MoveNext()
   at EventStore.Client.EventStoreClient.StreamSubscriptionResult.<get_Messages>g__GetMessages|12_0()+MoveNext()
   at EventStore.Client.EventStoreClient.StreamSubscriptionResult.<get_Messages>g__GetMessages|12_0()+MoveNext()
   at EventStore.Client.EventStoreClient.StreamSubscriptionResult.<get_Messages>g__GetMessages|12_0()+MoveNext()
   at EventStore.Client.EventStoreClient.StreamSubscriptionResult.<get_Messages>g__GetMessages|12_

EventStore details

• EventStore server version: 24.6.0 ("7847c5d39")
• Operating system: Windows 11 / Linux ("Unix 5.15.146.1")
• EventStore client version (if applicable): 23.3.3

Additional context
What is little odd to me is even before this all happens. In EventMetadataExtensions.cs:54 TryInjectTracingMetadata there is an attempt to parse stream into json document and if it fails, it will pass through original stream, which probably allows bad characters to propagate through. Maybe it shouldn't be even initiated when arbitrary application/octet-stream is sent. Or there should be some other way to trace such metadata. This is probably up to you to evaluate further.

[josephcummings]

Hi @intens-pavlas

Thanks for bringing this to our attention, I will look into this and come back to you shortly.

[intens-pavlas]

Thank you! It's been a great experience so far. My first tests against the current master seem to be fine. Do you have any insight when the next release might be published so we can reference the new nugget package?

[josephcummings]

Hey @intens-pavlas

I am preparing the patch to be released today as v23.3.4

[intens-pavlas]

Thanks for the quick turnaround, I'm looking forward to it.

[josephcummings]

Hey @intens-pavlas

v23.3.4 is now up on NuGet, let me know if you have any issues going forwards.

Thanks!

[paddyb]

Hi @josephcummings
Using v23.3.4 of the libraries and subscribing to a category stream with resolveLinkTos = true the trace writer fails to resolve the traceid from the resolved event metadata if I'm understanding it correctly.
TraceSubscriptionEvent() returns early if the OriginalEvent.ContentType != "application/json". Can this be tested differently depending on the configuration of the subscription?
src/EventStore.Client/Common/Diagnostics/ActivitySourceExtensions.cs#L36

[w1am]

Hey @paddyb, We removed the condition that was causing it to return early. We also now extract the trace context from the Event instead of the OriginalEvent to account for category stream events. Please try out 23.3.5 and let us know how it goes.

[paddyb]

Tested it there @w1am and it's working just fine now. Thank you for the quick turnaround