Server-initiated close with code and reason are received by neqo, but not forwarded to WebTransport
Categories
(Core :: Networking: HTTP, defect, P2)
Tracking
()
| Tracking | Status | |
|---|---|---|
| firefox112 | --- | fixed |
People
(Reporter: jesup, Assigned: edgul)
References
(Blocks 2 open bugs)
Details
(Whiteboard: [necko-triaged])
Attachments
(2 files)
When running close.https.any.js wpt test, the server-initiated close tests timeout in neqo. neqo receives the close with correct code and reasons and logs it:
2023-02-02 18:31:53.141258 UTC - [Parent 3562716: Socket Thread]: V/neqo_http3::* [neqo_http3::features::extended_connect::webtransport_session] [WebTransportSession session=0] Received frame: Some(CloseSession { error: 32, message: "abc" }) fin=true
However, it appears to not actually close the connection and eventually times out in quic and reports a session closed with code 0, "".
2023-02-02 18:32:23.154016 UTC - [Parent 3562716: Socket Thread]: I/neqo_transport::* [neqo_transport::connection] [Client e491d119683eed278e835af3dd93ef20723ace] idle timeout expired
Requires all my patches up for review, plus a few fixes from kershaw
run with :
./mach wpt --enable-webtransport-h3 testing/web-platform/tests/webtransport/close.https.any.js
|
Reporter | |
Comment 1•2 years ago
|
||
Starts at the test in question, ends after the timeout and when it's reported to WebTransportParent
|
||
Updated•2 years ago
|
|
|
Reporter | |
Comment 2•2 years ago
|
||
Ed, Sunil - this is another bug one of you could take
It looks like the Http3Server is not sending any info back to the client for SessionClosed ServerEvent.
https://searchfox.org/mozilla-central/rev/5ccb73c0217d1710b10d6e6e297cf3396d10ec23/netwerk/test/http3server/src/main.rs#487-496
I suspect we just need some kind of session.response here.
I also suspect this is related to or duplicate of Bug 1816143.
Hey Randell,
I'm seeing:
- only the occasional timeout error.
- more commonly
FAIL server initiated closure with code and reason - promise_test: Unhandled rejection with value: object "WebTransportError: WebTransport connection rejected"on close.https.any.html - more commonly
FAIL server initiated closure with code and reason - assert_equals: code expected 32 but got 0on close.https.any.worker.html
Curious:
- Did you noticed this as being intermittent at all?
- Were you testing only with
close.https.any.htmlor the workers or both?
|
||
Comment 5•2 years ago
|
||
(In reply to Ed Guloien [:edgul] from comment #4)
Hey Randell,
I'm seeing:
- only the occasional timeout error.
- more commonly
FAIL server initiated closure with code and reason - promise_test: Unhandled rejection with value: object "WebTransportError: WebTransport connection rejected"on close.https.any.html- more commonly
FAIL server initiated closure with code and reason - assert_equals: code expected 32 but got 0on close.https.any.worker.htmlCurious:
- Did you noticed this as being intermittent at all?
- Were you testing only with
close.https.any.htmlor the workers or both?
I've noticed this error and I am going to submit a patch in bug 1816439 to fix it.
In addition, I can get the close code and reason here with the following code:
diff --git a/netwerk/protocol/http/Http3Session.cpp b/netwerk/protocol/http/Http3Session.cpp
index 5608a8426d1a7..4ad5cc3e52442 100644
--- a/netwerk/protocol/http/Http3Session.cpp
+++ b/netwerk/protocol/http/Http3Session.cpp
@@ -703,8 +703,13 @@ nsresult Http3Session::ProcessEvents() {
// TODO read status and reason properly.
// TODO we do not hanlde the case when a WebTransport session stream
// is closed before headers are send.
- nsCString reason = ""_ns;
- wt->OnSessionClosed(0, reason);
+ SessionCloseReasonExternal& reasonExternal =
+ event.web_transport._0.session_closed.reason;
+ nsCString reason(reinterpret_cast<const char*>(data.Elements()),
+ data.Length());
+ LOG(("reason.tag=%d err=%lld data=%s\n", reasonExternal.tag,
+ reasonExternal.error._0, reason.get()));
+ wt->OnSessionClosed(reasonExternal.error._0, reason);
} break;
case WebTransportEventExternal::Tag::NewStream: {
LOG(
Note that we might want to check the tag value to differentiate the close reason.
Note that we might want to check the tag value to differentiate the close reason.
Do you mean feed the OnSesssionClosed first parameter conditionally?
Ie:
- if error ->
reasonExtrenal.error._0 - if status ->
reasonExtrenal.status._0 - if clean ->
reasonExtrenal.clean._0
If so will the second parameter always be directly from data?
|
|
||
Comment 7•2 years ago
|
||
(In reply to Ed Guloien [:edgul] from comment #6)
Note that we might want to check the tag value to differentiate the close reason.
Do you mean feed the OnSesssionClosed first parameter conditionally?
Ie:
- if error ->
reasonExtrenal.error._0- if status ->
reasonExtrenal.status._0- if clean ->
reasonExtrenal.clean._0
Yes.
If so will the second parameter always be directly from
data?
No, the data only contains value when the tag is Clean.
|
||
Comment 10•2 years ago
|
||
|
||
Comment 11•2 years ago
|
||
Backed out for causing build bustages on Http3Session.cpp
- Backout link
- Push with failures
- Failure Log
- Failure line: /builds/worker/checkouts/gecko/netwerk/protocol/http/Http3Session.cpp:728:73: error: format specifies type 'unsigned long' but the argument has type 'uint64_t' (aka 'unsigned long long') [-Werror,-Wformat]
|
|
||
Comment 13•2 years ago
|
||
|
||
Comment 14•2 years ago
|
||
Backed out for causing bustages on Logging.h
- backout: https://hg.mozilla.org/integration/autoland/rev/2b6ddba7dcdda909db6c8405ed7d7abfa9638e67
- push: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&selectedTaskRun=Tj53CDo-RXutdIDoDigwHQ.0&revision=3a9c67c6d582bd7664d78710dc379d9e1dccddf9
- failure log: https://treeherder.mozilla.org/logviewer?job_id=406585882&repo=autoland&lineNumber=29374
[task 2023-02-22T23:17:45.875Z] 23:17:45 INFO - In file included from /builds/worker/workspace/obj-build/dist/include/mozilla/MozPromise.h:13:0,
[task 2023-02-22T23:17:45.876Z] 23:17:45 INFO - from /builds/worker/workspace/obj-build/ipc/ipdl/_ipdlheaders/mozilla/net/PNecko.h:15,
[task 2023-02-22T23:17:45.876Z] 23:17:45 INFO - from /builds/worker/workspace/obj-build/ipc/ipdl/_ipdlheaders/mozilla/net/PNeckoChild.h:9,
[task 2023-02-22T23:17:45.876Z] 23:17:45 INFO - from /builds/worker/workspace/obj-build/dist/include/mozilla/net/NeckoChild.h:11,
[task 2023-02-22T23:17:45.877Z] 23:17:45 INFO - from /builds/worker/checkouts/gecko/netwerk/protocol/http/HttpLog.h:20,
[task 2023-02-22T23:17:45.877Z] 23:17:45 INFO - from /builds/worker/checkouts/gecko/netwerk/protocol/http/ConnectionHandle.cpp:7,
[task 2023-02-22T23:17:45.877Z] 23:17:45 INFO - from Unified_cpp_protocol_http1.cpp:2:
[task 2023-02-22T23:17:45.878Z] 23:17:45 INFO - /builds/worker/checkouts/gecko/netwerk/protocol/http/Http3Session.cpp: In member function 'nsresult mozilla::net::Http3Session::ProcessEvents()':
[task 2023-02-22T23:17:45.878Z] 23:17:45 ERROR - /builds/worker/workspace/obj-build/dist/include/mozilla/Logging.h:290:61: error: format '%d' expects argument of type 'int', but argument 4 has type 'mozilla::net::SessionCloseReasonExternal::Tag' [-Werror=format=]
[task 2023-02-22T23:17:45.878Z] 23:17:45 INFO - MOZ_LOG_EXPAND_ARGS _args); \
[task 2023-02-22T23:17:45.878Z] 23:17:45 INFO - ^
[task 2023-02-22T23:17:45.879Z] 23:17:45 INFO - /builds/worker/checkouts/gecko/netwerk/protocol/http/HttpLog.h:56:3: note: in expansion of macro 'MOZ_LOG'
[task 2023-02-22T23:17:45.879Z] 23:17:45 INFO - MOZ_LOG(mozilla::net::gHttpLog, mozilla::LogLevel::Verbose, args)
[task 2023-02-22T23:17:45.879Z] 23:17:45 INFO - ^~~~~~~
[task 2023-02-22T23:17:45.880Z] 23:17:45 INFO - /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2StreamTunnel.cpp:12:19: note: in expansion of macro 'LOG5'
[task 2023-02-22T23:17:45.880Z] 23:17:45 INFO - #define LOG(args) LOG5(args)
[task 2023-02-22T23:17:45.880Z] 23:17:45 INFO - ^~~~
[task 2023-02-22T23:17:45.880Z] 23:17:45 INFO - /builds/worker/checkouts/gecko/netwerk/protocol/http/Http3Session.cpp:728:13: note: in expansion of macro 'LOG'
[task 2023-02-22T23:17:45.881Z] 23:17:45 INFO - LOG(("reason.tag=%d err=%u data=%s\n", reasonExternal.tag, status,
[task 2023-02-22T23:17:45.881Z] 23:17:45 INFO - ^
[task 2023-02-22T23:17:45.881Z] 23:17:45 INFO - cc1plus: all warnings being treated as errors
[task 2023-02-22T23:17:45.882Z] 23:17:45 ERROR - gmake[4]: *** [/builds/worker/checkouts/gecko/config/rules.mk:668: Unified_cpp_protocol_http1.o] Error 1
|
|
||
Comment 15•2 years ago
|
||
|
||
Comment 16•2 years ago
|
||
| bugherder | ||
Description
•