Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Immediate timeout on macOS #2315

Open
mdavemartin opened this issue Sep 3, 2024 · 2 comments
Open

Immediate timeout on macOS #2315

mdavemartin opened this issue Sep 3, 2024 · 2 comments
Labels
priority/medium Rank 3

Comments

@mdavemartin
Copy link

Problem:

I've been trying to get the bottom of this issue for a while now. I'd like to integrate the crate into the application I'm building, but I can't get it to work on mac.
No matter what I did, it always ended up being an immediate timeout.
Eventually I settled on trying the echo example code to see if I have something misconfigured or misused, but it yielded the same result.

Steps:

  1. Server is up and listening.
  2. Client tries to connect and is accepted by the server, connection and stream get created.
  3. Depending on timing, one or zero message gets sent successfully, then it seems to stop working. It seems like the server hangs after the first message, but no message required for it to timeout.
  4. Client continues to send packets and times out eventually with IdleTimerExpired error.
  5. Retry connection with client, connection does not get accepted. Now it really seems like the server hung.

Here is the trace from the first connection:

2024-09-03T18:28:28.069687Z DEBUG s2n_quic:server: platform_feature_configured: configuration=Gso { max_segments: 1 }
2024-09-03T18:28:28.069865Z DEBUG s2n_quic:server: platform_feature_configured: configuration=BaseMtu { mtu: 1228 }
2024-09-03T18:28:28.069879Z DEBUG s2n_quic:server: platform_feature_configured: configuration=InitialMtu { mtu: 1228 }
2024-09-03T18:28:28.069888Z DEBUG s2n_quic:server: platform_feature_configured: configuration=MaxMtu { mtu: 1228 }
2024-09-03T18:28:28.069897Z DEBUG s2n_quic:server: platform_feature_configured: configuration=Gro { enabled: false }
2024-09-03T18:28:28.069922Z DEBUG s2n_quic:server: platform_feature_configured: configuration=Ecn { enabled: true }
2024-09-03T18:28:28.071133Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=false rx_ready=false tx_ready=true application_wakeup=false
2024-09-03T18:28:28.071159Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=None processing_duration=29µs
2024-09-03T18:28:29.071777Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:29.071910Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=None processing_duration=146µs
2024-09-03T18:28:32.871901Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=false rx_ready=true tx_ready=false application_wakeup=false
2024-09-03T18:28:32.872007Z DEBUG s2n_quic:server: version_information: server_versions=[1] client_versions=[] chosen_version=Some(1)
2024-09-03T18:28:32.872618Z DEBUG s2n_quic:server:conn{id=0}: key_update: key_type=Initial cipher_suite=TLS_AES_128_GCM_SHA256
2024-09-03T18:28:32.872712Z DEBUG s2n_quic:server:conn{id=0}: connection_started: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true }
2024-09-03T18:28:32.872735Z DEBUG s2n_quic:server:conn{id=0}: mtu_updated: path_id=0 mtu=1200 cause=NewPath
2024-09-03T18:28:32.872783Z DEBUG s2n_quic:server:conn{id=0}: datagram_received: len=1200
2024-09-03T18:28:32.872829Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Initial { number: 0, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Crypto { offset: 0, len: 271 }
2024-09-03T18:28:32.872896Z DEBUG s2n_quic:server:conn{id=0}: tls_client_hello: payload=[[3, 3, 172, 198, 13, 60, 81, 148, 17, 28, 190, 176, 147, 34, 197, 144, 125, 214, 73, 253, 74, 174, 82, 38, 122, 114, 85, 254, 54, 118, 37, 54, 11, 141, 0, 0, 6, 19, 1, 19, 2, 19, 3, 1, 0, 0, 220, 0, 43, 0, 3, 2, 3, 4, 0, 10, 0, 10, 0, 8, 0, 23, 0, 29, 0, 24, 0, 25, 0, 51, 0, 71, 0, 69, 0, 23, 0, 65, 4, 206, 56, 15, 252, 176, 153, 230, 179, 11, 165, 143, 172, 142, 238, 159, 64, 197, 245, 205, 96, 11, 189, 33, 74, 68, 132, 141, 72, 194, 164, 119, 72, 195, 57, 241, 74, 63, 53, 51, 69, 126, 135, 172, 235, 198, 34, 52, 41, 131, 229, 228, 93, 233, 136, 215, 113, 85, 138, 15, 244, 252, 25, 146, 18, 0, 13, 0, 20, 0, 18, 4, 3, 5, 3, 6, 3, 8, 9, 8, 10, 8, 11, 8, 4, 8, 5, 8, 6, 0, 0, 0, 14, 0, 12, 0, 0, 9, 108, 111, 99, 97, 108, 104, 111, 115, 116, 0, 16, 0, 5, 0, 3, 2, 104, 51, 0, 11, 0, 2, 1, 0, 0, 57, 0, 59, 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, 15, 16, 43, 154, 46, 95, 213, 236, 159, 207, 206, 253, 72, 197, 191, 155, 8, 249, 0, 23, 0, 0]]
2024-09-03T18:28:32.873204Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Initial { number: 0, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Padding
2024-09-03T18:28:32.873710Z DEBUG s2n_quic:server:conn{id=0}: key_update: key_type=Handshake cipher_suite=TLS_AES_128_GCM_SHA256
2024-09-03T18:28:32.873852Z DEBUG s2n_quic:server:conn{id=0}: application_protocol_information: chosen_application_protocol=[104, 51]
2024-09-03T18:28:32.873880Z DEBUG s2n_quic:server:conn{id=0}: transport_parameters_received: transport_parameters=TransportParameters { original_destination_connection_id: None, initial_source_connection_id: Some(0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9), retry_source_connection_id: None, stateless_reset_token: None, preferred_address: None, migration_support: true, max_idle_timeout: 30s, ack_delay_exponent: 3, max_ack_delay: 25ms, max_udp_payload_size: 65527, active_connection_id_limit: 3, initial_max_stream_data_bidi_local: 3750000, initial_max_stream_data_bidi_remote: 3750000, initial_max_stream_data_uni: 3750000, initial_max_streams_bidi: 100, initial_max_streams_uni: 100, max_datagram_frame_size: 0, dc_supported_versions: [] }
2024-09-03T18:28:32.873938Z DEBUG s2n_quic:server:conn{id=0}: key_update: key_type=OneRtt { generation: 0 } cipher_suite=TLS_AES_128_GCM_SHA256
2024-09-03T18:28:32.873978Z DEBUG s2n_quic:server:conn{id=0}: server_name_information: chosen_server_name="localhost"
2024-09-03T18:28:32.874184Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=Initial { number: 0, version: 1 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.874202Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=Initial { number: 0, version: 1 } path_id=0 ack_range=0..=0
2024-09-03T18:28:32.874222Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=Initial { number: 0, version: 1 } path_id=0 frame=Crypto { offset: 0, len: 123 }
2024-09-03T18:28:32.874250Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=Initial { number: 0, version: 1 } packet_len=195
2024-09-03T18:28:32.874269Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=Handshake { number: 0, version: 1 } path_id=0 frame=Crypto { offset: 0, len: 722 }
2024-09-03T18:28:32.874285Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=Handshake { number: 0, version: 1 } path_id=0 frame=Padding
2024-09-03T18:28:32.874408Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=Handshake { number: 0, version: 1 } packet_len=1005
2024-09-03T18:28:32.874429Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=1200 gso_offset=0
2024-09-03T18:28:32.874455Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=333ms smoothed_rtt=333ms latest_rtt=333ms rtt_variance=166.5ms max_ack_delay=25ms pto_count=0 congestion_window=12000 bytes_in_flight=1200 congestion_limited=false
2024-09-03T18:28:32.874504Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(998.655ms) processing_duration=2.613ms
2024-09-03T18:28:32.875901Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=false rx_ready=true tx_ready=false application_wakeup=false
2024-09-03T18:28:32.875925Z DEBUG s2n_quic:server: version_information: server_versions=[1] client_versions=[] chosen_version=Some(1)
2024-09-03T18:28:32.875943Z DEBUG s2n_quic:server:conn{id=0}: datagram_received: len=1200
2024-09-03T18:28:32.875965Z DEBUG s2n_quic:server:conn{id=0}: packet_received: packet_header=Initial { number: 1, version: 1 }
2024-09-03T18:28:32.875983Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Initial { number: 1, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.876020Z DEBUG s2n_quic:server:conn{id=0}: ack_range_received: packet_header=Initial { number: 1, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } ack_range=0..=0
2024-09-03T18:28:32.876055Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=0 congestion_window=12000 bytes_in_flight=1005 congestion_limited=false
2024-09-03T18:28:32.876085Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Initial { number: 1, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Padding
2024-09-03T18:28:32.876124Z DEBUG s2n_quic:server:conn{id=0}: packet_received: packet_header=Handshake { number: 0, version: 1 }
2024-09-03T18:28:32.876139Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Handshake { number: 0, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.876183Z DEBUG s2n_quic:server:conn{id=0}: ack_range_received: packet_header=Handshake { number: 0, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } ack_range=0..=0
2024-09-03T18:28:32.876212Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=0 congestion_window=12000 bytes_in_flight=0 congestion_limited=false
2024-09-03T18:28:32.876301Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Handshake { number: 0, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Crypto { offset: 0, len: 36 }
2024-09-03T18:28:32.876345Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=Handshake { number: 0, version: 1 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Padding
2024-09-03T18:28:32.876379Z DEBUG s2n_quic:server:conn{id=0}: key_space_discarded: space=Initial
2024-09-03T18:28:32.876392Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=0 congestion_window=12000 bytes_in_flight=0 congestion_limited=false
2024-09-03T18:28:32.876499Z DEBUG s2n_quic:server:conn{id=0}: handshake_status_updated: status=Complete
2024-09-03T18:28:32.876511Z DEBUG s2n_quic:server:conn{id=0}: handshake_status_updated: status=Confirmed
2024-09-03T18:28:32.876524Z DEBUG s2n_quic:server:conn{id=0}: tls_exporter_ready: session=TlsSession { .. }
2024-09-03T18:28:32.876550Z DEBUG s2n_quic:server:conn{id=0}: key_space_discarded: space=Handshake
2024-09-03T18:28:32.876561Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=0 congestion_window=12000 bytes_in_flight=0 congestion_limited=false
2024-09-03T18:28:32.876634Z DEBUG s2n_quic:server:conn{id=0}: datagram_received: len=53
2024-09-03T18:28:32.876654Z DEBUG s2n_quic:server:conn{id=0}: packet_received: packet_header=OneRtt { number: 0 }
2024-09-03T18:28:32.876668Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=OneRtt { number: 0 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Stream { id: 0, offset: 0, len: 0, is_fin: false }
2024-09-03T18:28:32.876703Z DEBUG s2n_quic:server:conn{id=0}: frame_received: packet_header=OneRtt { number: 0 } path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } frame=Padding
2024-09-03T18:28:32.876781Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 0 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.876947Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 0 } path_id=0 ack_range=0..=0
2024-09-03T18:28:32.876963Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 0 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:32.876980Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 0 } path_id=0 frame=NewConnectionId { sequence_number: 1, retire_prior_to: 1 }
2024-09-03T18:28:32.876993Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 0 } path_id=0 frame=NewConnectionId { sequence_number: 2, retire_prior_to: 1 }
2024-09-03T18:28:32.877006Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 0 } path_id=0 frame=NewConnectionId { sequence_number: 3, retire_prior_to: 1 }
2024-09-03T18:28:32.877031Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 0 } packet_len=152
2024-09-03T18:28:32.877206Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=152 gso_offset=0
2024-09-03T18:28:32.877229Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=0 congestion_window=12000 bytes_in_flight=152 congestion_limited=false
Connection accepted from Ok(127.2024-09-03T18:28:32.877272Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(29.784ms) processing_duration=1.371ms
0.0.1:62252)
Stream opened from Ok(127.0.0.1:62252)
2024-09-03T18:28:32.907524Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:32.907608Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=1 congestion_window=12000 bytes_in_flight=152 congestion_limited=false
2024-09-03T18:28:32.907768Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 2 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.907792Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 2 } path_id=0 ack_range=0..=0
2024-09-03T18:28:32.907809Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 2 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:32.907831Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 2 } path_id=0 frame=Padding
2024-09-03T18:28:32.907866Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 2 } packet_len=53
2024-09-03T18:28:32.907883Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=1 space=OneRtt reason=PtoProbe
2024-09-03T18:28:32.907898Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:32.907930Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 4 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.907947Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 4 } path_id=0 ack_range=0..=0
2024-09-03T18:28:32.907962Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 4 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:32.907979Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 4 } path_id=0 frame=Padding
2024-09-03T18:28:32.908000Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 4 } packet_len=53
2024-09-03T18:28:32.908014Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=3 space=OneRtt reason=PtoProbe
2024-09-03T18:28:32.908027Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:32.908049Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=1 congestion_window=12000 bytes_in_flight=258 congestion_limited=false
2024-09-03T18:28:32.908098Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(58.684ms) processing_duration=581µs
2024-09-03T18:28:32.971300Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:32.971445Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=2 congestion_window=12000 bytes_in_flight=258 congestion_limited=false
2024-09-03T18:28:32.971979Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 6 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.972044Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 6 } path_id=0 ack_range=0..=0
2024-09-03T18:28:32.972075Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 6 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:32.972125Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 6 } path_id=0 frame=Padding
2024-09-03T18:28:32.972209Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 6 } packet_len=53
2024-09-03T18:28:32.972233Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=5 space=OneRtt reason=PtoProbe
2024-09-03T18:28:32.972259Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:32.972362Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 8 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:32.972389Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 8 } path_id=0 ack_range=0..=0
2024-09-03T18:28:32.972412Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 8 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:32.972456Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 8 } path_id=0 frame=Padding
2024-09-03T18:28:32.972501Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 8 } packet_len=53
2024-09-03T18:28:32.972522Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=7 space=OneRtt reason=PtoProbe
2024-09-03T18:28:32.972544Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:32.972579Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=2 congestion_window=12000 bytes_in_flight=364 congestion_limited=false
2024-09-03T18:28:32.972670Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(120.032ms) processing_duration=1.382ms
2024-09-03T18:28:33.094327Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:33.094539Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=3 congestion_window=12000 bytes_in_flight=364 congestion_limited=false
2024-09-03T18:28:33.094816Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 10 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:33.094902Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 10 } path_id=0 ack_range=0..=0
2024-09-03T18:28:33.094979Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 10 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:33.095057Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 10 } path_id=0 frame=Padding
2024-09-03T18:28:33.095165Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 10 } packet_len=53
2024-09-03T18:28:33.095220Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=9 space=OneRtt reason=PtoProbe
2024-09-03T18:28:33.095276Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:33.095384Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 12 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:33.095458Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 12 } path_id=0 ack_range=0..=0
2024-09-03T18:28:33.095515Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 12 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:33.095582Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 12 } path_id=0 frame=Padding
2024-09-03T18:28:33.095666Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 12 } packet_len=53
2024-09-03T18:28:33.095721Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=11 space=OneRtt reason=PtoProbe
2024-09-03T18:28:33.095879Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:33.096182Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=3 congestion_window=12000 bytes_in_flight=470 congestion_limited=false
2024-09-03T18:28:33.096488Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(240.537ms) processing_duration=2.172ms
2024-09-03T18:28:33.338080Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:33.338238Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=4 congestion_window=12000 bytes_in_flight=470 congestion_limited=false
2024-09-03T18:28:33.338453Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 14 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:33.338498Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 14 } path_id=0 ack_range=0..=0
2024-09-03T18:28:33.338527Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 14 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:33.338570Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 14 } path_id=0 frame=Padding
2024-09-03T18:28:33.338651Z DEBUG s2n_quic:server:conn{id=0}: ecn_state_changed: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } state=Unknown
2024-09-03T18:28:33.338692Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 14 } packet_len=53
2024-09-03T18:28:33.338713Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=13 space=OneRtt reason=PtoProbe
2024-09-03T18:28:33.338738Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:33.338797Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 16 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:33.338829Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 16 } path_id=0 ack_range=0..=0
2024-09-03T18:28:33.338855Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 16 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:33.338887Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 16 } path_id=0 frame=Padding
2024-09-03T18:28:33.338947Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 16 } packet_len=53
2024-09-03T18:28:33.338972Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=15 space=OneRtt reason=PtoProbe
2024-09-03T18:28:33.338996Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:33.339039Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=4 congestion_window=12000 bytes_in_flight=576 congestion_limited=false
2024-09-03T18:28:33.339148Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(483.791ms) processing_duration=1.084ms
2024-09-03T18:28:33.823974Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:33.824262Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=5 congestion_window=12000 bytes_in_flight=576 congestion_limited=false
2024-09-03T18:28:33.824673Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 18 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:33.824773Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 18 } path_id=0 ack_range=0..=0
2024-09-03T18:28:33.824876Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 18 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:33.825021Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 18 } path_id=0 frame=Padding
2024-09-03T18:28:33.825166Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 18 } packet_len=53
2024-09-03T18:28:33.825222Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=17 space=OneRtt reason=PtoProbe
2024-09-03T18:28:33.825282Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:33.825413Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 20 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:33.825484Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 20 } path_id=0 ack_range=0..=0
2024-09-03T18:28:33.825542Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 20 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:33.825612Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 20 } path_id=0 frame=Padding
2024-09-03T18:28:33.825702Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 20 } packet_len=53
2024-09-03T18:28:33.825756Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=19 space=OneRtt reason=PtoProbe
2024-09-03T18:28:33.825809Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:33.825899Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=5 congestion_window=12000 bytes_in_flight=682 congestion_limited=false
2024-09-03T18:28:33.826117Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(967.561ms) processing_duration=2.17ms
2024-09-03T18:28:34.795200Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:34.795618Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=6 congestion_window=12000 bytes_in_flight=682 congestion_limited=false
2024-09-03T18:28:34.796019Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 22 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:34.796117Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 22 } path_id=0 ack_range=0..=0
2024-09-03T18:28:34.796183Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 22 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:34.796325Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 22 } path_id=0 frame=Padding
2024-09-03T18:28:34.796597Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 22 } packet_len=53
2024-09-03T18:28:34.796690Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=21 space=OneRtt reason=PtoProbe
2024-09-03T18:28:34.796767Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:34.796924Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 24 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:34.796996Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 24 } path_id=0 ack_range=0..=0
2024-09-03T18:28:34.797120Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 24 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:34.797196Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 24 } path_id=0 frame=Padding
2024-09-03T18:28:34.797291Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 24 } packet_len=53
2024-09-03T18:28:34.797345Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=23 space=OneRtt reason=PtoProbe
2024-09-03T18:28:34.797398Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:34.797490Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=6 congestion_window=12000 bytes_in_flight=788 congestion_limited=false
2024-09-03T18:28:34.797720Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(1.93646s) processing_duration=2.548ms
2024-09-03T18:28:36.735913Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:36.736118Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=7 congestion_window=12000 bytes_in_flight=788 congestion_limited=false
2024-09-03T18:28:36.736420Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 26 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:36.736483Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 26 } path_id=0 ack_range=0..=0
2024-09-03T18:28:36.736537Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 26 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:36.736599Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 26 } path_id=0 frame=Padding
2024-09-03T18:28:36.736678Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 26 } packet_len=53
2024-09-03T18:28:36.736707Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=25 space=OneRtt reason=PtoProbe
2024-09-03T18:28:36.736739Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:36.736812Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 28 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:36.736848Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 28 } path_id=0 ack_range=0..=0
2024-09-03T18:28:36.736877Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 28 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:36.736913Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 28 } path_id=0 frame=Padding
2024-09-03T18:28:36.736961Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 28 } packet_len=53
2024-09-03T18:28:36.736988Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=27 space=OneRtt reason=PtoProbe
2024-09-03T18:28:36.737015Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:36.737062Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=7 congestion_window=12000 bytes_in_flight=894 congestion_limited=false
2024-09-03T18:28:36.737180Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(3.875734s) processing_duration=1.314ms
2024-09-03T18:28:40.614282Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:40.614623Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=8 congestion_window=12000 bytes_in_flight=894 congestion_limited=false
2024-09-03T18:28:40.615052Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 30 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:40.615146Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 30 } path_id=0 ack_range=0..=0
2024-09-03T18:28:40.615211Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 30 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:40.615305Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 30 } path_id=0 frame=Padding
2024-09-03T18:28:40.615451Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 30 } packet_len=53
2024-09-03T18:28:40.615511Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=29 space=OneRtt reason=PtoProbe
2024-09-03T18:28:40.615568Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:40.615698Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 32 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:40.615806Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 32 } path_id=0 ack_range=0..=0
2024-09-03T18:28:40.615872Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 32 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:40.615951Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 32 } path_id=0 frame=Padding
2024-09-03T18:28:40.616078Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 32 } packet_len=53
2024-09-03T18:28:40.616410Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=31 space=OneRtt reason=PtoProbe
2024-09-03T18:28:40.616458Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:40.616699Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=8 congestion_window=12000 bytes_in_flight=1000 congestion_limited=false
2024-09-03T18:28:40.616886Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(7.751218s) processing_duration=2.629ms
2024-09-03T18:28:48.368926Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:28:48.369227Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=9 congestion_window=12000 bytes_in_flight=1000 congestion_limited=false
2024-09-03T18:28:48.369630Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 34 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:48.369742Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 34 } path_id=0 ack_range=0..=0
2024-09-03T18:28:48.369810Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 34 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:48.369906Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 34 } path_id=0 frame=Padding
2024-09-03T18:28:48.370051Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 34 } packet_len=53
2024-09-03T18:28:48.370151Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=33 space=OneRtt reason=PtoProbe
2024-09-03T18:28:48.370234Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:48.370369Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 36 } path_id=0 frame=Ack { ecn_counts: Some(EcnCounts { ect_0_count: 1, ect_1_count: 0, ce_count: 0 }), largest_acknowledged: 0, ack_range_count: 1 }
2024-09-03T18:28:48.370467Z DEBUG s2n_quic:server:conn{id=0}: ack_range_sent: packet_header=OneRtt { number: 36 } path_id=0 ack_range=0..=0
2024-09-03T18:28:48.370526Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 36 } path_id=0 frame=HandshakeDone
2024-09-03T18:28:48.370596Z DEBUG s2n_quic:server:conn{id=0}: frame_sent: packet_header=OneRtt { number: 36 } path_id=0 frame=Padding
2024-09-03T18:28:48.370689Z DEBUG s2n_quic:server:conn{id=0}: packet_sent: packet_header=OneRtt { number: 36 } packet_len=53
2024-09-03T18:28:48.370742Z DEBUG s2n_quic:server:conn{id=0}: packet_skipped: number=35 space=OneRtt reason=PtoProbe
2024-09-03T18:28:48.370796Z DEBUG s2n_quic:server:conn{id=0}: datagram_sent: len=53 gso_offset=0
2024-09-03T18:28:48.370888Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=9 congestion_window=12000 bytes_in_flight=1106 congestion_limited=false
2024-09-03T18:28:48.371248Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=Some(14.506319s) processing_duration=2.35ms
2024-09-03T18:29:02.878959Z DEBUG s2n_quic:server: platform_event_loop_wakeup: timeout_expired=true rx_ready=false tx_ready=false application_wakeup=false
2024-09-03T18:29:02.879267Z DEBUG s2n_quic:server:conn{id=0}: recovery_metrics: path=Path { local_addr: 127.0.0.1:4433, local_cid: 0xcee046a8f0aa106c552ec86681a01b2b, remote_addr: 127.0.0.1:62252, remote_cid: 0x2b9a2e5fd5ec9fcfcefd48c5bf9b08f9, id: 0, is_active: true } min_rtt=1.762ms smoothed_rtt=1.762ms latest_rtt=1.762ms rtt_variance=881µs max_ack_delay=25ms pto_count=9 congestion_window=12000 bytes_in_flight=1106 congestion_limited=false
2024-09-03T18:29:02.879468Z DEBUG s2n_quic:server:conn{id=0}: connection_closed: error=IdleTimerExpired { source: Location { file: "/Users/dave/.cargo/registry/src/index.crates.io-6f17d22bba15001f/s2n-quic-transport-0.45.0/src/connection/connection_impl.rs", line: 1078, col: 24 } }
2024-09-03T18:29:02.879733Z DEBUG s2n_quic:server: platform_event_loop_sleep: timeout=None processing_duration=798µs
2024-09-03T18:29:02.879863Z DEBUG presence_server: Stream task exited.
2024-09-03T18:29:02.880053Z DEBUG presence_server: Connection task exited.

Fired up wireshark to get any clues, my only observation is that continuous handshakes are sent during the timeout window.

macOS version: 13.5.1

Note: I did not encounter any issues on linux with this (example) code.
@lrstewart
Copy link
Contributor

Thanks for the issue! We'll try to get this prioritized for an investigation.

@WesleyRosenblum
Copy link
Contributor

Would you be able to provide the logs from the client as well, and a packet capture (ideally with the key log)?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
priority/medium Rank 3
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mdavemartin @lrstewart @WesleyRosenblum