s2n-quic: IdleTimerExpired when trying to flush and close SendStream

Problem:

Our team switched one of our nascent projects to using s2n-quic from quinn in a recent rewrite. We have integration tests that build a dummy server and client. The client successfully writes to the server via a split BidirectionalStream, the server successfully receives and processes the request and writes back successfully (via a split BidirectionalStream), and the client successfully receives the correct response. But after writing back, the server hangs for 30 seconds before it handles an IdleTimerExpired error that occurs during a write operation. I have not been able to replicate this error.

I get this error whenever I call SendStream::poll_flush. It hangs for 30 seconds, then is polled a second time and immediately returns this error.

I would include code, but I haven’t been able to replicate this in a simpler way. The fact is that I don’t know the replication steps, which is why I am making this issue. I am using s2n-quic version 1.16.0 both in our project and in the replication. I can include the tracing logs if that would be helpful.

Solution:

Sufficient documentation for s2n_quic::connection::Error to address a problem like this one, including distinct examples for why it would occur in a ReceiveStream or a SendStream for specific methods.

Tracing Logs

2023-02-21T21:07:38.030656Z DEBUG rustls::client::hs: No cached session for DnsName(DnsName(DnsName("localhost")))
2023-02-21T21:07:38.030842Z DEBUG rustls::client::hs: Not resuming any session  
2023-02-21T21:07:38.064035Z DEBUG project::server: state=PollingMakeService     
2023-02-21T21:07:38.064090Z DEBUG project::server: state=Accepting              
2023-02-21T21:07:39.034077Z DEBUG rustls::server::hs: decided upon suite TLS13_AES_128_GCM_SHA256
2023-02-21T21:07:39.036285Z DEBUG rustls::server::hs: Chosen ALPN protocol [106, 106]
2023-02-21T21:07:39.044028Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_128_GCM_SHA256
2023-02-21T21:07:39.044126Z DEBUG rustls::client::tls13: Not resuming           
2023-02-21T21:07:39.045759Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([6a6a]), ServerNameAck, TransportParameters([1, 4, 128, 0, 117, 48, 4, 4, 128, 57, 56, 112, 5, 4, 128, 57, 56, 112, 6, 4, 128, 57, 56, 112, 7, 4, 128, 57, 56, 112, 8, 2, 64, 100, 9, 2, 64, 100, 14, 1, 3, 0, 8, 75, 246, 226, 91, 49, 153, 1, 177, 15, 16, 130, 131, 123, 116, 246, 217, 23, 79, 91, 4, 195, 112, 129, 147, 57, 119])]
2023-02-21T21:07:39.045924Z DEBUG rustls::client::hs: ALPN protocol is Some(b"jj")
2023-02-21T21:07:39.048570Z TRACE project::framed_write: flushing framed write  
2023-02-21T21:07:39.048593Z TRACE project::framed_write: writing length=20      
2023-02-21T21:07:39.048636Z TRACE project::framed_write: flushing SendStream    
2023-02-21T21:07:39.049748Z DEBUG project::server: state=Accepting              
2023-02-21T21:07:39.049791Z DEBUG project::server: Accepted new connection remote=127.0.0.1:58364
2023-02-21T21:07:39.049815Z DEBUG project::server: state=CallingMakeService(SharedFuture(...), Connection)
2023-02-21T21:07:39.049848Z DEBUG project::server: state=PollingMakeService     
2023-02-21T21:07:39.049866Z DEBUG project::server: state=Accepting              
2023-02-21T21:07:39.049995Z DEBUG handle_connection: project::server: connection closed, dropping _sender
2023-02-21T21:07:39.050115Z TRACE project::framed_read: read chunk source_mut_length=0 source_mut_capacity=0 source_length=0 next_length=20
2023-02-21T21:07:39.050156Z TRACE project::framed_read: decoded frame source_mut_length=0 source_mut_capacity=0 source_length=19
2023-02-21T21:07:39.050191Z DEBUG project::server: read header method=create_rule
2023-02-21T21:07:39.050196Z TRACE project::framed_write: flushing framed write  
2023-02-21T21:07:39.050217Z TRACE project::framed_write: writing length=0       
2023-02-21T21:07:39.050233Z TRACE project::framed_write: flushing SendStream    
2023-02-21T21:07:39.050226Z TRACE project::framed_read: decoded frame source_mut_length=0 source_mut_capacity=0 source_length=0
2023-02-21T21:07:39.051042Z DEBUG project::server: read request body            
2023-02-21T21:07:39.051078Z TRACE project::framed_write: flushing framed write  
2023-02-21T21:07:39.051095Z TRACE project::framed_write: writing length=1       
2023-02-21T21:07:39.051141Z TRACE project::framed_write: flushing SendStream    
2023-02-21T21:07:39.051638Z TRACE project::framed_write: flushing framed write  
2023-02-21T21:07:39.051662Z TRACE project::framed_write: writing length=0       
2023-02-21T21:07:39.051680Z TRACE project::framed_write: flushing SendStream       
2023-02-21T21:07:39.051733Z TRACE project::framed_read: read chunk source_mut_length=0 source_mut_capacity=0 source_length=0 next_length=1
2023-02-21T21:07:39.051764Z TRACE project::framed_read: decoded frame source_mut_length=0 source_mut_capacity=0 source_length=0
2023-02-21T21:07:39.076570Z TRACE project::framed_write: flushing framed write  
2023-02-21T21:07:39.076612Z TRACE project::framed_write: writing length=0          
2023-02-21T21:07:39.076631Z TRACE project::framed_write: flushing SendStream       
2023-02-21T21:07:39.077160Z DEBUG project::server: Shutdown signal was reading, sending on watch channel
2023-02-21T21:07:39.077183Z DEBUG project::server: state=ShuttingDown           
2023-02-21T21:08:09.077502Z TRACE project::framed_write: flushing framed write  
2023-02-21T21:08:09.077604Z TRACE project::framed_write: writing length=0          
2023-02-21T21:08:09.077656Z TRACE project::framed_write: flushing SendStream       
2023-02-21T21:08:09.077788Z DEBUG project::server: failed to close write error=Write(ConnectionError { error: IdleTimerExpired { source: Location { file: "/home/lando/.cargo/registry/src/github.com-1ecc6299db9ec823/s2n-quic-transport-0.17.0/src/connection/connection_impl.rs", line: 1038, col: 24 } } })
2023-02-21T21:08:09.078040Z DEBUG project::server: request processed, dropping _sender
2023-02-21T21:08:09.078206Z DEBUG project::server: state=ShuttingDown           
2023-02-21T21:08:09.078295Z DEBUG project::server: All connections dropped, shutting down