<a class="header-button" href="https://bugzilla.mozilla.org/home" title="Go to home page"> Bugzilla

Updated

•

2 years ago

Flags: needinfo?(kershaw)

Comment 3

•

2 years ago

^Passing to kershaw to try to reproduce

Assignee

Comment 4

•

2 years ago

Yeah, I can reproduce this.
I'll try to take a look.

Flags: needinfo?(kershaw)

Assignee

Updated

•

2 years ago

Flags: needinfo?(kershaw)

Comment 5

•

2 years ago

I tried to rewrite the server side with my node.js plugin, but I could not reproduce it with nightly. So, it may be something specific to the server (buffer sizes may be different).

Comment 6

•

2 years ago

I played around with the Go example. Does anyone have an idea how to adjust flow control windows? On the C++ side of Firefox, I see that it stops always around 1 MB receiving. Fc may be the cause. The problem must be visible on the rust level.

Comment 7

•

2 years ago

Okay, from debugging at the Rust side, I see that it is blocked when the flow control window is full. However, no frame for indicating a change of max stream data seems to be sent, but I do not know why.

alex

Reporter

Comment 8

•

2 years ago

Does anyone have an idea how to adjust flow control windows?

If you apply this diff to server.go in the github repo linked in the OP you can adjust flow control parameters:

diff --git a/server.go b/server.go
index 688a0d8..00ae7ef 100644
--- a/server.go
+++ b/server.go
@@ -19,7 +19,7 @@ import (
        "time"
 
        "github.com/quic-go/quic-go/http3"
-
+       "github.com/quic-go/quic-go"
        "github.com/quic-go/webtransport-go"
 )
 
@@ -40,6 +40,11 @@ func main() {
                        TLSConfig: tlsConf,
                        Addr:      "localhost:12345",
                        Handler:   wmux,
+                       QUICConfig: &quic.Config{
+                               MaxStreamReceiveWindow: 0,
+                               InitialConnectionReceiveWindow: 0,
+                               // other fields here
+                       },
                },
                CheckOrigin: func(r *http.Request) bool { return true },
        }

There are various settings available.

Comment 9

•

2 years ago

Thanks, but I can only adjust the receive window on the go server side. In this case, the receive window on the Firefox side is important (so the send window on the go side). I have just found out that Firefox sends out an increase in the max stream size (MaxStreamData capsule)), but not an increase in the session size.
If you are familiar with the go code, can you find out if the the go side:
a.) The MaxStreamData is received. (I only see that the sending function is called on the Firefox side with a size big enough to allow resuming transmission).
b.) If a.) is true, if the session max_data parameter prevents the sending of further data on the go side, of if it is just that b.) is not true.

At the moment, I am not sure if I would blame Firefox or the Go code. One thing that is different on Firefox is that it seems that MaxDataStream is only sent when the server already hits a blocking state.

Comment 10

•

2 years ago

Ok, the session maxdata limit is 16 MB on the Firefox side for receiving.
As Firefox sends the MaxStreamData (it is still possible that it does not reach the socket, but I do not think so),
the questions above on the go side must be answered. From what I can see, firefox is behaving correctly.

So, I will stop the investigation here and hope somone may debug the go side.

qlogs: https://github.com/MarcoPolo/webtransport-send-lots-of-data/tree/main/qlog

Comment 11

•

2 years ago

Another thing that I may have seen is that the Firefox side receives more data than is allowed by flow control (but I am not sure if I remember correctly) and that this leads to a close of the connection, as Firefox does not tolerate this violation. But This was not clear.

Marco Munizaga

Comment 12

•

1 year ago

I've taken a cursory look at this and produced two qlogs. One for Firefox and another for Chrome. The send rate looks wonky in the Firefox qlog. It seems like the server isn't getting timely acks. I'm also not seeing any max_data frames. And I only see a single max_stream_data frame. Those seem like a bug.

Maybe a qlog from the firefox side would help? I'm not sure how to generate that. For the Go server, using my fork of the repro https://github.com/MarcoPolo/webtransport-send-lots-of-data and setting the QLOGDIR=<dir> env var prior to starting the server will save the qlog there.

Comment 13

•

1 year ago

However, it would be more interesting to see what the values of the max_data or max_stream_data property are on the server side. During my debugging session, it look at the firefox side, it looked as the server recognized a flow control violation and shutdown. So what does the client think? What are the flow control values for the server? It may be that the server did not send a max_data, as the server is within current limits until the server violates it with a package exceeding the flow control limit before the client tells the server to raise it.

Marco Munizaga

Comment 14

•

1 year ago

It's straightforward to figure that out from the qlog:

❮ rg "(max_(data|stream_data)|(data|stream_data)_blocked)" firefox.sqlog       

3:{"time":0.228791,"name":"transport:parameters_set","data":{"owner":"local","original_destination_connection_id":"10f4e16145742e00","stateless_reset_token":"350fa31f52d6c04c614f3ce83902d94d","initial_source_connection_id":"ecb411b5","disable_active_migration":true,"max_idle_timeout":30000,"max_udp_payload_size":1452,"ack_delay_exponent":3,"max_ack_delay":26,"active_connection_id_limit":4,"initial_max_data":786432,"initial_max_stream_data_bidi_local":524288,"initial_max_stream_data_bidi_remote":524288,"initial_max_stream_data_uni":524288,"initial_max_streams_bidi":100,"initial_max_streams_uni":100,"max_datagram_frame_size":16383}}
11:{"time":1.157583,"name":"transport:parameters_set","data":{"owner":"remote","initial_source_connection_id":"a61172","disable_active_migration":true,"max_idle_timeout":30000,"max_udp_payload_size":4611686018427387903,"ack_delay_exponent":3,"max_ack_delay":20,"active_connection_id_limit":8,"initial_max_data":25165824,"initial_max_stream_data_bidi_local":12582912,"initial_max_stream_data_bidi_remote":1048576,"initial_max_stream_data_uni":1048576,"initial_max_streams_bidi":16,"initial_max_streams_uni":16,"max_datagram_frame_size":1200}}
27224:{"time":84.186208,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"3abedc","packet_number":11513,"key_phase_bit":"1"},"raw":{"length":28},"frames":[{"frame_type":"stream_data_blocked","stream_id":4,"limit":12582912}],"ecn":"Not-ECT"}}
27229:{"time":85.496166,"name":"transport:packet_received","data":{"header":{"packet_type":"1RTT","dcid":"ecb411b5","packet_number":51,"key_phase_bit":"1"},"raw":{"length":38,"payload_length":32},"frames":[{"frame_type":"ack","acked_ranges":[[10175,11513],[5775,10173]]},{"frame_type":"max_stream_data","stream_id":4,"maximum":14050548}],"ecn":"Not-ECT"}}
29511:{"time":91.530833,"name":"transport:packet_sent","data":{"header":{"packet_type":"1RTT","dcid":"3abedc","packet_number":12554,"key_phase_bit":"1"},"raw":{"length":28},"frames":[{"frame_type":"stream_data_blocked","stream_id":4,"limit":14050548}],"ecn":"Not-ECT"}}

That shows the initial max_stream_data from the client (FF) 12582912. Then the server being blocked and sending a stream_data_blocked frame. The client then sending a max_stream_data frame to update to 14050548. Then the server being blocked again and sending another stream_data_blocked frame. At this point the stream stalls and the connection eventually times out.

There seem to be at least a couple of bugs here, but the biggest thing is that the client never sends another max_stream_data frame.

Comment 15

•

1 year ago

If I remember correctly (it was a while ago), I had seen, I think, in the rust code that a flow violation was detected, and then it aborted some in some way. But this must be used cautiously, as a debugger can alter the behavior. So, that may be the info from the new max_stream.
Are you sure, that you never exceed with the server the flow control limit of the client?
(And may also be that the limit is updated inside firefox with a bit of a delay, so what happens, if you delay sending more data a bit.)

You can get a log for the client with
"In about:logging, please select Logging to file and set MOZ_LOG to timestamp,sync,nsHttp:5,WebTransport:5,nsWebTransport:5."
At least, this is what the Mozilla team told me during the discussion on another bug. You may then be able to see more.

Marco Munizaga

Comment 16

•

1 year ago

Are you sure, that you never exceed with the server the flow control limit of the client?

Yes. It's quite obvious from the qlog. You can visualize the packets on https://qvis.quictools.info/.

Here's a screenshot of that:
https://github.com/user-attachments/assets/5123369d-7757-4ebd-85bd-94683a12b259

alex

Reporter

Comment 17

•

1 year ago

Kershaw - did you manage to reproduce this bug yet? Is there anything I can do do help?

Updated

•

1 year ago

Flags: needinfo?(kershaw)

Updated

•

1 year ago

Flags: needinfo?(kershaw)

Assignee

Comment 18

•

1 year ago

Sorry for the delay.

The problem is that the Http3WebTransportStream didn't handle the error code NS_BASE_STREAM_WOULD_BLOCK well.
When receiving NS_BASE_STREAM_WOULD_BLOCK, we should call AsyncWait and then write data when the stream is available to write again.

Severity: -- → S3

Flags: needinfo?(kershaw)

Priority: -- → P2

Whiteboard: [necko-triaged] [necko-priority-queue]

Assignee

Comment 19

•

1 year ago

Attached file Bug 1899812 - Handle would block error for Http3WebTransportStream, r=#necko — Details

Phabricator Automation

Updated

•

1 year ago

Assignee: nobody → kershaw

Status: UNCONFIRMED → ASSIGNED

Ever confirmed: true

Pulsebot

Comment 20

•

1 year ago

Pushed by kjang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ab45b7958482 Handle would block error for Http3WebTransportStream, r=necko-reviewers,jesup

amarc

Comment 21

•

1 year ago

Backed out for causing xpcshell failures @ test_simple_stream.js

TEST-UNEXPECTED-TIMEOUT | dom/webtransport/test/xpcshell/test_simple_stream.js | Test timed out

Flags: needinfo?(kershaw)