qlog icon indicating copy to clipboard operation
qlog copied to clipboard

the frames_processed fails to capture received and sent frames

Open toidiu opened this issue 3 years ago • 7 comments

The frames_processed event fails to capture the sending and receiving of frames since it only specified a single packet_number field.

According to the transport rfc:

Each endpoint maintains a separate packet number for sending and receiving.

I feel mirroring the packet events would be consistent and result in two events: frames_sent and frames_received which will be easier to match on.

toidiu avatar Apr 22 '21 19:04 toidiu

So the idea is that send/receive semantics for frames are done in the packet_sent and packet_received events. These not only log e.g., the packet header, but also the frames and their contents.

The frames_processed event is an additional one to be used to signify exactly that: when the frames are -processed- (as this does not necessarily happen directly after/before send/receive). This is mostly in the cases where a) the processing code is decoupled heavily from the send/recv code or b) you don't want to log full packets, but are mainly interested in e.g., how stream frames are handled. The packet_number is just to have -a- way of correlating this info to the packet carrying the frames for later cross-reference, but not intended to replace the packet_sent and packet_received events (which log the packet numbers as well of course).

If you would only want to log the frames (e.g., have pure frames_sent and frames_received), you could just use packet_sent and packet_received and omit packet-level information from these instead.

From your issue, I assume this wasn't clear when reading the draft and that we should clarify it. However, I feel like the setup works as you desire/describe, so I don't think there's a design issue. If you disagree, please let us know.

(note: it's likely that the frames_processed event will be replaced with a number of more specific events like acks_processed, see #85)

rmarx avatar Apr 23 '21 07:04 rmarx

Thanks for the explanation. The intention of frame_processed makes sense but there is text that added to my confusion. There might still be a good usecase for frame_sent/recv event and I listed the pros/cons for that.

Note: in some implementations, it can be difficult to log frames directly, even when using packet_sent and packet_received events. For these cases, this event also contains the direct packet_number field, which can be used to more explicitly link this event to the packet_sent/received events.

note and packet_number confusion The quote from the draft specifically calls out sending and receiving and how the packet_number can be used to link the event to the packet event.

If this event is meant for processing of received events, as you described, then it might be good to call that out explicitly and remove the packet_sent part.

difficulty in logging frames in packet event The quote describes our use case pretty well (difficult to log frames directly, even when using packet_sent and packet_received events). So we plan to emit the packet event with sparse info and another event which captures the frame info. Given that I see two options:

  • using packet_sent/recv
    • pros: this will allow us to reuse the event.
    • cons: low granularity of the logs. There is more data in a frame_event vs a packet_event. Customers only wishing to consume packet_events will need to do their own parsing or opt into both events; this can be noisy/cumbersome.
  • adding and using new frame_sent/recv
    • pros: this will allow users to easily consume packet_events vs frame_event.
    • cons: more events and possibly duplication.

toidiu avatar Apr 23 '21 19:04 toidiu

Thank you for the additional information. I now understand the root of your issue (I think) and agree that there's a semantic mismatch (at minimum in the use of the verb "processed" vs parsed/created).

I also understand the arguments for separate frame_* events, but I'm unsure if it's still possible to make such a change. The packet_* events are at the core of qlog and implemented by all stacks that do qlog (that I know of). All the tooling also utilizes this. Splitting this up by default would mean lots of code churn (one of the reasons we added a separate frames_processed in the first place).

Am I correct in understanding you have a concrete need for this split in your own stack (i.e., it's difficult to emit everything in packet_sent/received and you really need separate events?) or this this mainly a theoretical exercise? In the first case, could you provide a few more details on how/why it works that way? Thanks!

rmarx avatar Apr 26 '21 09:04 rmarx

All the tooling also utilizes this. Splitting this up by default would mean lots of code churn (one of the reasons we added a separate frames_processed in the first place).

I wanted to make sure we were on the same page. I was suggesting that we keep the frames field in the packet_* events and introduce frame_* events. This might introduce duplication but also not break existing tooling.

We do have a need for this in our stack. Emitting the packet_* with the frames info would force us to have extra allocation; which we need to avoid in a networking library (QUIC).


If its not possible to add frame_*:

The alternative is that we emit the packet_* with just the packet related info and then later on emit another packet_* with frames related info. However, I do wonder if qlog tools are flexible enough to expect this behavior and match the 'separated' packet events?

This still doesn't address easy filtering of packet vs frame events, so we would likely add a custom field to indicate and filter that easily.


Aside: I am not familiar with the existing tooling and how easy/difficult they would be to update, but I wonder if there is a way to mark fields as deprecated so that new tools opt into the preferred usage (streamline and remove duplication).

I also wonder if breaking tools might be acceptable since this is still in draft. But I am new here so defer the decision to you and others; also thats is a much larger conversation.

toidiu avatar Apr 26 '21 19:04 toidiu

Hi, wanted to make sure someone saw the above comment.

Would be good to know which way the draft design will lean so that we can remain compatible.

toidiu avatar May 03 '21 18:05 toidiu

Hey toidiu,

Thanks for following up. I did see your previous post, and thanks for confirming this is an issue in your stack.

At this point, we are preparing for adoption of the qlog drafts in the IETF QUIC working group, where one of the discussions to be had is indeed the amount and fine-grainedness of events. Your input will be useful then. However, at this time, I cannot guarantee new frame_* events will be added, nor that they won't... It's safe to say they won't be added anytime soon though.

For now, I'd say the best approach is to log two packet_* events then (as those should be easy to merge automatically by tooling).

At this point, there isn't all that much (public/open-source) tooling that I'm aware of. The biggest toolsuite is qvis (https://github.com/quiclog/qvis), which is incidentally also maintained by myself. I can say that currently logging separate packet_* events for the same packet (one with, one without frames) won't auto-merge the two in qvis (and I don't expect any other tooling to do this atm). Conceptually this is something I could add, but all that would do is choose either the first or the last and pretend that's the only event in there, loosing timing info (though maybe that's enough for what you need atm?). If that's a needed workaround for you at this time, let me know at https://github.com/quiclog/qvis/issues and I'll add that.

In general, I don't worry too much about breaking tooling at this point (since we're still in draft), but I'm not at all certain frame_* events will ever be added and re-writing tools to deal with them properly would be too much work at the moment (As a quick hack, I would support them by merging them with packet_* events, just as I would do when not using separate frame_* events).

I hope that answers your questions. If not, feel free to let us know!

rmarx avatar May 03 '21 19:05 rmarx

For now, I'd say the best approach is to log two packet_* events then (as those should be easy to merge automatically by tooling).

Thanks @rmarx for the reply on how to proceed. Your reasoning makes sense in light of upcoming adoption and the unknowns.

Please feel free to close the issue.

toidiu avatar May 04 '21 04:05 toidiu

Sounds like the author found a solution. Closing this ticket but we can reopen if I've gotten the wrong end of the stick.

LPardue avatar Sep 08 '22 01:09 LPardue