`finish` sometimes hangs forever

[joshtriplett]

I put together the following simple test of wtransport, as an experiment:

use clap::Parser;
use tokio::io::AsyncReadExt;

#[derive(Parser)]
#[command(name = "wtransport-test")]
enum WtransportTest {
    Client(Client),
    Server,
}

#[derive(Parser)]
struct Client {
    /// Server certificate hash
    hash: wtransport::tls::Sha256Digest,
}

#[tokio::main]
async fn main() -> eyre::Result<()> {
    match WtransportTest::parse() {
        WtransportTest::Client(args) => client(args).await,
        WtransportTest::Server => server().await,
    }
}

async fn client(args: Client) -> eyre::Result<()> {
    let config = wtransport::ClientConfig::builder()
        .with_bind_default()
        .with_server_certificate_hashes([args.hash])
        .build();
    let connection = wtransport::Endpoint::client(config)?
        .connect("https://localhost:4433/demo-path")
        .await?;
    println!("Established WebTransport connection");
    let mut recv_stream = connection.accept_uni().await?;
    println!("Accepted unidirectional stream");
    let mut s = String::new();
    recv_stream.read_to_string(&mut s).await?;
    println!("Read string: {s}");
    Ok(())
}

async fn server() -> eyre::Result<()> {
    let identity = wtransport::Identity::self_signed(["localhost"])?;
    let hash = identity.certificate_chain().as_slice()[0].hash();
    println!("Created server certificate with hash {hash}");
    let config = wtransport::ServerConfig::builder()
        .with_bind_default(4433)
        .with_identity(identity)
        .build();
    let server = wtransport::Endpoint::server(config)?;
    println!("Established listening server");
    let incoming_session = server.accept().await;
    println!(
        "Got incoming session from {}",
        incoming_session.remote_address()
    );
    let incoming_request = incoming_session.await?;
    println!(
        "Incoming request has authority {}, path {}",
        incoming_request.authority(),
        incoming_request.path()
    );
    let connection = incoming_request.accept().await?;
    println!("Accepted connection");
    let mut send_stream = connection.open_uni().await?.await?;
    println!("Established unidirectional stream");
    send_stream.write_all(b"Hello world!").await?;
    println!("Sent data");
    send_stream.finish().await?;
    println!("Finished");
    Ok(())
}

This uses the following [dependencies] in Cargo.toml:

clap = { version = "4.5.49", features = ["deprecated", "derive"] }
eyre = "0.6.12"
tokio = { version = "1.47.1", features = ["macros", "rt-multi-thread"] }
wtransport = { version = "0.6.1", features = ["aws-lc-rs", "self-signed"], default-features = false }

To test this, run it with server which will print a hash, then run it with client that-hash.

Sometimes, both the server and client will complete as expected. However, sometimes, the server will do this:

Created server certificate with hash 83:4e:3c:d4:4d:a3:5d:19:e8:54:f5:72:ee:7d:a0:25:e7:c3:13:a1:9d:6a:0b:75:54:f9:bc:04:d3:3b:cc:17
Established listening server
Got incoming session from [::1]:50257
Incoming request has authority localhost:4433, path /demo-path
Accepted connection
Established unidirectional stream
Sent data

And then hang, never printing "Finished".

[BiagioFesta]

Thank you for the report.

From the network trace analysis:

Working Case Flow

// Server sends packet 11
// send_stream.write_all(b"Hello world!").await?;
Server ---> Client   
QUIC Short Header DCID=... PKN=11
  STREAM id=7 fin=0 off=3 len=12 dir=Unidirectional origin=Server-initiated
    Stream Data: "Hello world!"
    ...

// Server sends packet 12
// send_stream.finish().await?;
// This is an empty STREAM frame (with FIN bit = 1), indicating the stream has ended.
Server ---> Client   
QUIC Short Header DCID=... PKN=12
  STREAM id=7 fin=1 off=15 len=0 dir=Unidirectional origin=Server-initiated
    Stream Data: ""
    ...

// Client sends
// Contains ACK for server packet 9 (old packets we can ignore)
Client ---> Server
QUIC Short Header DCID=... PKN=11
   ACK
    Largest Acknowledged: 9
     ...

// Client sends
// Contains ACK for server packet 12
// This informs the server that the final frame (FIN) for the stream has been received.
Client ---> Server
QUIC Short Header DCID=... PKN=12
  ACK
    Largest Acknowledged: 12
    ...

NOT Working Case Flow

// Server sends packet 13
// send_stream.write_all(b"Hello world!").await?;
Server ---> Client   
QUIC Short Header DCID=... PKN=13
  STREAM id=7 fin=0 off=3 len=12 dir=Unidirectional origin=Server-initiated
    Stream Data: "Hello world!"
    ...

// Client sends
// Contains ACK for server packet 13 (acknowledging the "Hello world!" message)
Client ---> Server
QUIC Short Header DCID=... PKN=13
  ACK
    Largest Acknowledged: 13
   ...

// Server sends packet 14
// send_stream.finish().await?;
// This is an empty STREAM frame (with FIN bit = 1), indicating the stream has ended.
Server ---> Client
QUIC Short Header DCID=... PKN=14
  STREAM id=7 fin=1 off=15 len=0 dir=Unidirectional origin=Server-initiated
    Stream Data: ""
    ...

// From this point, only server traffic remains.
// The server sends packet 15...
// Immediate ACKs are ack-eliciting, so the server is waiting for an ACK for packet 14, which never arrives.
Server ---> Client
QUIC Short Header DCID=... PKN=15
  IMMEDIATE_ACK
  ...

// The server continues sending immediate ACKs.

---

Based on the network analysis, the issue appears to be the missing ACK for send_stream.finish().await?.

In the non-working case, it seems the client closes the connection/process before receiving the FIN bit that signals the end of the stream (which is reasonable, as it does not wait for it). The server then becomes stuck, waiting for the ACK from a client that has already closed. After a timeout, the server should complete anyway indicating the timed-out of the QUIC connection (which happens on my repro env).

I’m not entirely sure whether this should be classified as a bug, since, if confirmed on your side, it might actually be expected behavior overall.

However, I might look deeper into whether the library is missing something in its destructors (I am assuming the FIN is actually read by the client, considering tokio::read_to_string reads until EOF source, but considering application is closing and QUIC connection driver is executed on a different tokio task, it might not have the time to sends the latest ACK before the process terminated).

That said, the concept of performing "cleanup" during application shutdown is always somewhat tricky and unpredictable in networking contexts.

After adding:

println!("Read string: {s}");
+ tokio::task::yield_now().await;
Ok(())

the issue no longer reproduces on my side.

[BiagioFesta]

I confirm EOF read is working for tokio::read_to_string RecvStream implementation, as removing send_stream.finish() and making the server pending, the client does not read the "Hello World!" string (awaits for EOF)

[joshtriplett]

Rather than just tokio::task::yield_now().await, could there be some defined procedure to more explicitly shut down the connection and make sure the other end gets a chance to see that?

Obviously timeouts are needed to handle the unexpected disconnect case, but I'd like to not need timeouts for the expected disconnect case.

Is the right approach here to call .close() and wait for that before exiting? Or something else?

[BiagioFesta]

Unfortunately I don't think there is a straightforward solution right away.

The underlying QUIC stack quic.connection.close is a sync operation (wtransport's close is merely a wrapper for the code mapping: https://github.com/BiagioFesta/wtransport/blob/master/wtransport/src/connection.rs#L305-L307)

Does not provide this guarantee:

Only the peer last receiving application data can be certain that all data is delivered. The only reliable action it can then take is to close the connection, potentially with a custom error code. The delivery of the final CONNECTION_CLOSE frame is very likely if both endpoints stay online long enough [...] Otherwise, the remote peer will time out the connection, provided that the idle timeout is not disabled.

For the client side, I think we could leverage the following part of the documentation

and Endpoint::wait_idle() can be used

I am reasoning loudly but, in theory, the parent Endpoint might be propagated to the Connection and makes the close() of the connection an async which concatenates wait_idle. This should be only for the client (Endpoint for server is aggregate of ALL connection and would not make sense). But it is something to reason better about it I guess.