Interop with aioquic decryption issue about pquic

[rmarx]

Hey @mpiraux, small note on that: qlog actually only allows "1RTT". The onertt thing is because enums in most programming languages cannot start with a numerical character and we modeled the qlog schema after TypeScript, which has that same problem. Arguably that kind of implementation detail should not be in the spec and it has given others some confusion as well, so we'll probably remove it down the line, keeping only 1RTT as an entry.

In qvis specifically then, we're more lenient. It doesn't really look for the specific enum values, just matches identical packet_type string values together when trying to correlate two traces. So you can use "onertt" if you're just doing pquic traces, it just breaks when using aioquic's "1rtt" or another's "1RTT". Finally, we do a pass to transform to uppercase "1rtt" into "1RTT", originally to help with draft-00 to draft-01 transition, so aioquic seems interoperable with other qlogs, even though it is indeed also not 100% correct according to spec.

Hope that helps :)

[mpiraux]

I just pushed a big update for Multipath, which basically uses and converts initial paths into uniflows instead of opening new (redundant) uniflows. In our testing this has simplified things quite a bit and fixed some bugs. Yours could very be one of them, as well as the other ones. Could you try the latest commit ? I will update the live endpoint in a few minutes

[mpiraux]

Something broke in the QLOG plugin, I am investigating further.

[The3ternum]

Additional observation: It seems that the undecryptable 1rtt packet that is being sent from the PQUIC server actually has a length that is greater than 1500 bytes (1523 bytes to be exact, excluding the header), thus the packet is rejected by the decryptor on the aioquic client.

[mpiraux]

I am working on a fix for this issue. Meanwhile a small note regarding the "onertt" vs "1rtt" packet type logging: it seems that it's a bug on aioquic's side, the spec allows "onertt" and "1RTT" as values for identifiying these packets, but not "1rtt". https://quiclog.github.io/internet-drafts/draft02/draft-marx-qlog-event-definitions-quic-h3.html#name-packettype

[The3ternum]

Hi, thank you for the fix, it seems that the three packets from the first screenshot (initial 1 and handshake 2 from the aioquic client and 1RTT 1 from the pquic server) still are not decrypted correctly by either endpoint.

• Between an aioquic CLIENT and a pquic SERVER:

  1. This loss of the 1RTT packet no longer causes the pquic server to remain stuck in a PING-ACK-loop.
  2. In addition, the connection seems to finish successfully, transporting all 999999 bytes between the endpoints.
  3. In this configuration the aioquic client is able to establish a second sending uniflow via the path challenge and path response mechanism.
  4. The pquic server is able to respong with MP_ACK-frames, the aioquic client can parse them correctly.
  5. I had a bug where the aioquic client sends a UNIFLOWS-frame before its additional sending uniflow was validated, causing only a single entry to exist in the sending uniflows info section. (And I have been able to fix it, so thank you :) )

• Between an aioquic SERVER and a pquic CLIENT:

  1. I cannot yet confirm if this connection ends succesfully, due to certain things happening.
  2. It seems that, when the aioquic server tries to perform a path validation to establish an additional sending uniflow, the pquic client sends back a PATH_RESPONSE-frame (along with an additional PATH_CHALLENGE-frame and 2 UNIFLOWS-frames). However, the packet that carries these frames never arrives on the aioquic server (there are no errors, the packet isn't even logged as received via a "datagrams_received"-event, which happens before the packet is processed). Therefore the aioquic server can never establish its additional sending uniflow (or respond to the PATH_CHALLENGE-frame from the pquic server). Additionally, the uniflows frames from the pquic client contain 2 entries for the receiving uniflows, which is correct, but also 2 entries for the sending uniflows which i assume is incorrect, since the pquic client's additional sending uniflow has not yet been established. See the screenshot below.
     
  3. It also seems that the pquic client never sends an ack-of-ack trigger (or ack-eliciting frames), therefore the aioquic server never responds with its own ACKs, which (about 70 sent packets later) results in the pquic client logging almost every 1RTT packet as a loss event. See the screenshot below.
     
  4. There are some instances that the pquic client sends another PATH_CHALLENGE-frame along with a UNIFLOWS-frame, on which the aioquic server is able to respond. This also triggers an ACK from the aioquic server, where all the "lost" packets at that point are acknowledged. The pquic client then also logs a lot of in-flight events. See the screenshot below.
     
  5. After the aioquic server has transported all the data and signaled the end with stream 0 FIN-flag enabled, the pquic client keeps logging a lot of 1RTT packet loss events. Then the pquic client starts sending PATH_CHALLENGE frames and PING+PADING-frames for a while (which also restart at packet number 1, I assume these come from the additional sending uniflow on the pquic client). These packets are also not received by the aioquic server (again, not even the reception of the packet is logged as a "datagrams_received"-event, which happens before the packet is processed). Eventually the pquic client sends a CONNECTION_CLOSE-frame, closing the connection. See the screenshot below.
     

I have also included the QLOG-files from both the aioquic server and the pquic client, as well ass the console log from the pquic-client. See Logs.zip

[The3ternum]

One of my questions is what the behaviour of the additional sending uniflows is in the PQUIC endpoint (more specific, the client), as it seems like it is trying to send data over a new path?

I believe that it is also worth mentioning that I have included an address filter for the pquic endpoint. I am not sure if it is correct, but the code should currently only allow "127.0.0.1" to be used. (It seems to work, as the PQUIC endpoint no longer advertises additional addresses.)
If incorrect, what code should I be using instead? And how do i include the IPv6 variant "::1"? See Only_local.zip for the code that i used.

[mpiraux]

However, the packet that carries these frames never arrives on the aioquic server (there are no errors, the packet isn't even logged as received via a "datagrams_received"-event, which happens before the packet is processed).

It would be interesting to capture where this packet is going. I am guessing the address handling code is bad.

Therefore the aioquic server can never establish its additional sending uniflow (or respond to the PATH_CHALLENGE-frame from the pquic server).

Correct, but it could send again the PC.

Additionally, the uniflows frames from the pquic client contain 2 entries for the receiving uniflows, which is correct, but also 2 entries for the sending uniflows which i assume is incorrect, since the pquic client's additional sending uniflow has not yet been established.

IIRC, in our code, sending uniflows are activated as soon as you receive credit for it in the form of a CID for the particular uniflow. It looks like the specs define the active state as path usage over a validated address. I'll file a bug for that.

It also seems that the pquic client never sends an ack-of-ack trigger (or ack-eliciting frames), therefore the aioquic server never responds with its own ACKs

We currently request an ACK to prune ACK ranges if more than 10 blocks are used, but otherwise we rely on the server to issue ACKs from time to time. We could change that to bundle an PING every x ACK. It's unfortunate the server doesn't send one from time to time.

There are some instances that the pquic client sends another PATH_CHALLENGE-frame along with a UNIFLOWS-frame, on which the aioquic server is able to respond.

My guess is that is considers the uniflow as broken at some point because it doesn't receive any ACKs, so it marks it as not verified and opens a new uniflow. I think it's a new one because UNIFLOWS frame are only sent once per uniflow.

After the aioquic server has transported all the data and signaled the end with stream 0 FIN-flag enabled, the pquic client keeps logging a lot of 1RTT packet loss events. Then the pquic client starts sending PATH_CHALLENGE frames and PING+PADING-frames for a while (which also restart at packet number 1, I assume these come from the additional sending uniflow on the pquic client).

The sending uniflow is again considered as broken at some point I guess.

So to conclude from all your interesting findings:

• I'll file a bug regarding sending uniflows, path validation and the active state.
• I suggest that you look at the addresses to which the missing packets are sent to.
• My understanding is that at some point, uniflows are marked as broken, though I can't find the code that would explain that. So I'll dig deeper on that side.

[mpiraux]

It would be interesting to capture where this packet is going. I am guessing the address handling code is bad.

I actually just fixed a bug regarding that particular code, which caused memory corruption. The commit is running through our test suite and I should ship it here in the afternoon.
EDIT: There it is 9b27331

[mpiraux]

And how do i include the IPv6 variant "::1"?

The code is correct for IPv4 localhost, you need to compare the in6_addr_t to one initialised to "::1", using memcmp for instance.

[The3ternum]

It seems that the QLOG-file generated by the PQUIC client does not contain "packet_received" or "packet_sent" events, which prevent QVIS from generating a visualisation (according to the console log seen in the screenshot).

i have used the following parameters to start the client (./picoquicdemo):

-P plugins/multipath/multipath_rr_cond.plugin -P plugins/qlog/qlog.plugin -P plugins/multipath/multipath_qlog.plugin -P plugins/multipath/addresses_filters/filter_only_local.plugin -q qlog_output_client.qlog -G 999999 ::1 4433

There's still something that goes wrong, although i am unable to discern the problem. On the aioquic server I am currently using only sending uniflow 0 until sending uniflow 1 becomes available, then only sending uniflow 1 is used (for testing purposes)

I have included the QLOGs from the aioquic server and the PQUIC client, along with the console log from the pquic client, see
Logs.zip

[mpiraux]

@The3ternum, d2acec6 has a fix for the QLOG bug