Fix verbose RPC message tracing #398
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
We have JsonConverter and IMessagePackFormatter<T> types that have side effects in order to support marshaling of special objects. This makes tracing the full JSON-RPC message hazardous if it means we run these custom serializers multiple times per message, and this is in fact happening lately. The fix is to be sure we only serialize/deserialize a message *once*. This means that the result of the serialization must be retained long enough to trace (if tracing is turned on). It also means we need to retain the text that was *de*serialized long enough to be traced. We also don't want to allocate a string for the entire message unless tracing requires it. The approach varies between formatters, as follows: For the `JsonMessageFormatter` we have a super-convenient `JToken` instance that represents the entire message either after serialization or before deserialization. This type knows how to render a string representation of itself. So for this formatter we simply raise the trace events with the `JToken` as a parameter, which the string formatter will call `ToString` on if a trace listener wants it as a string. For the `MessagePackFormatter` it's a little more complicated. There is no native JSON text representation at all (since msgpack is a binary encoding). But we still want to trace a JSON text representation for logging/diagnostics purposes. MessagePack has a converter that translates msgpack binary to JSON text, but this requires that we have the entire msgpack byte sequence. When deserializing this is easy enough: we have the sequence to deserialize from anyway. But when serializing, we're writing to an `IBufferWriter<T>` which doesn't give us access to access the serialized binary later. So seeing the full msgpack that was serialized in order to convert to JSON and trace it is something the formatter needs help with. The message handlers have access to the full msgpack to be written, so we arrange for the handlers to "call back" into the formatter after the formatter is done serializing in order to say "by the way, here's the full sequence you just wrote out" which the formatter can then use to raise the trace event with an object that will convert it to JSON text if/when the object's ToString() method is called. This call back from the handler into the formatter is through an optional interface that only the `MessagePackFormatter` needs to implement. As part of this 'callback' from handler to formatter, the `LengthHeaderMessageHandler` needed a slightly revision: it didn't have a way to collect the entire serialized sequence written by the formatter because the `PrefixingBufferWriter<T>` doesn't expose a `ReadOnlySequence<T>` for all the written bytes like `Sequence<T>` does. So I had to switch to `Sequence<T>` in this handler. This means that small messages will have their buffer copied (even when not tracing) once before being transmitted where they weren't being copied before. But these are small messages so the impact is likely very small. Large messages were already getting copied anyway, so no difference there. So with this change we now have safe and complete tracing of JSON-RPC messages for all handlers and formatters, and without nasty doubling of side-effects. Fixes microsoft#386
Codecov Report
@@ Coverage Diff @@
## master #398 +/- ##
==========================================
- Coverage 90.33% 90.27% -0.07%
==========================================
Files 47 47
Lines 3581 3608 +27
==========================================
+ Hits 3235 3257 +22
- Misses 346 351 +5
Continue to review full report at Codecov.
|
milopezc
approved these changes
Dec 5, 2019
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
We have JsonConverter and IMessagePackFormatter types that have side effects in order to support marshaling of special objects. This makes tracing the full JSON-RPC message hazardous if it means we run these custom serializers multiple times per message, and this is in fact happening lately.
The fix is to be sure we only serialize/deserialize a message once. This means that the result of the serialization must be retained long enough to trace (if tracing is turned on). It also means we need to retain the text that was deserialized long enough to be traced. We also don't want to allocate a string for the entire message unless tracing requires it.
The approach varies between formatters, as follows:
For the
JsonMessageFormatterwe have a super-convenientJTokeninstance that represents the entire message either after serialization or before deserialization. This type knows how to render a string representation of itself. So for this formatter we simply raise the trace events with theJTokenas a parameter, which the string formatter will callToStringon if a trace listener wants it as a string.For the
MessagePackFormatterit's a little more complicated. There is no native JSON text representation at all (since msgpack is a binary encoding). But we still want to trace a JSON text representation for logging/diagnostics purposes. MessagePack has a converter that translates msgpack binary to JSON text, but this requires that we have the entire msgpack byte sequence. When deserializing this is easy enough: we have the sequence to deserialize from anyway. But when serializing, we're writing to anIBufferWriter<T>which doesn't give us access to access the serialized binary later. So seeing the full msgpack that was serialized in order to convert to JSON and trace it is something the formatter needs help with. The message handlers have access to the full msgpack to be written, so we arrange for the handlers to "call back" into the formatter after the formatter is done serializing in order to say "by the way, here's the full sequence you just wrote out" which the formatter can then use to raise the trace event with an object that will convert it to JSON text if/when the object's ToString() method is called. This call back from the handler into the formatter is through an optional interface that only theMessagePackFormatterneeds to implement.As part of this 'callback' from handler to formatter, the
LengthHeaderMessageHandlerneeded a slightly revision: it didn't have a way to collect the entire serialized sequence written by the formatter because thePrefixingBufferWriter<T>doesn't expose aReadOnlySequence<T>for all the written bytes likeSequence<T>does. So I had to switch toSequence<T>in this handler. This means that small messages will have their buffer copied (even when not tracing) once before being transmitted where they weren't being copied before. But these are small messages so the impact is likely very small. Large messages were already getting copied anyway, so no difference there.So with this change we now have safe and complete tracing of JSON-RPC messages for all handlers and formatters, and without nasty doubling of side-effects.
Fixes #386