This adds a frame stat for PATH_NEW_CONNECTION_ID

As part of this a few minor fixes, in recording and logging the
PATH_NEW_CONNECTION_ID frames.

Also a few fixes for logging frames that were mistakenly not logged.

quinn-proto/src/connection/mod.rs

@@ -649,7 +649,7 @@ impl Connection {
             };
 
             if !path_should_send && space_id < SpaceId::Data {
-                trace!(?space_id, ?path_id, "nothing to send");
+                trace!(?space_id, ?path_id, "everything sent in space");
                 space_id = space_id.next();
                 continue;
             }
@@ -1030,11 +1030,13 @@ impl Connection {
             )?;
 
             // We implement MTU probes as ping packets padded up to the probe size
+            trace!("PING");
             builder.frame_space_mut().write(frame::FrameType::PING);
             self.stats.frame_tx.ping += 1;
 
             // If supported by the peer, we want no delays to the probe's ACK
             if self.peer_supports_ack_frequency() {
+                trace!("IMMEDIATE_ACK");
                 builder
                     .frame_space_mut()
                     .write(frame::FrameType::IMMEDIATE_ACK);
@@ -3725,6 +3727,7 @@ impl Connection {
 
         // HANDSHAKE_DONE
         if !is_0rtt && mem::replace(&mut space.pending.handshake_done, false) {
+            trace!("HANDSHAKE_DONE");
             buf.write(frame::FrameType::HANDSHAKE_DONE);
             sent.retransmits.get_or_create().handshake_done = true;
             // This is just a u8 counter and the frame is typically just sent once
@@ -3743,6 +3746,7 @@ impl Connection {
         {
             let frame = frame::ObservedAddr::new(path.remote, self.next_observed_addr_seq_no);
             if buf.remaining_mut() > frame.size() {
+                trace!(seq = %frame.seq_no, ip = %frame.ip, port = frame.port, "OBSERVED_ADDRESS");
                 frame.write(buf);
 
                 self.next_observed_addr_seq_no = self.next_observed_addr_seq_no.saturating_add(1u8);
@@ -3966,6 +3970,7 @@ impl Connection {
                         id = %issued.id,
                         "PATH_NEW_CONNECTION_ID",
                     );
+                    self.stats.frame_tx.path_new_connection_id += 1;
                     Some(issued.path_id)
                 }
                 false => {
@@ -3975,6 +3980,7 @@ impl Connection {
                         "NEW_CONNECTION_ID"
                     );
                     debug_assert_eq!(issued.path_id, PathId(0));
+                    self.stats.frame_tx.new_connection_id += 1;
                     None
                 }
             };
@@ -3987,18 +3993,22 @@ impl Connection {
             }
             .encode(buf);
             sent.retransmits.get_or_create().new_cids.push(issued);
-            self.stats.frame_tx.new_connection_id += 1;
         }
 
         // RETIRE_CONNECTION_ID
         let retire_cid_bound = frame::RetireConnectionId::size_bound(is_multipath_negotiated);
         while !path_exclusive_only && buf.remaining_mut() > retire_cid_bound {
             let (path_id, sequence) = match space.pending.retire_cids.pop() {
-                Some((PathId(0), seq)) if !is_multipath_negotiated => (None, seq),
-                Some((path_id, seq)) => (Some(path_id), seq),
+                Some((PathId(0), seq)) if !is_multipath_negotiated => {
+                    trace!(sequence = seq, "RETIRE_CONNECTION_ID");
+                    (None, seq)
+                }
+                Some((path_id, seq)) => {
+                    trace!(?path_id, sequence = seq, "PATH_RETIRE_CONNECTION_ID");
+                    (Some(path_id), seq)
+                }
                 None => break,
             };
-            trace!(?path_id, sequence, "RETIRE_CONNECTION_ID");
             frame::RetireConnectionId { path_id, sequence }.write(buf);
             sent.retransmits
                 .get_or_create()
@@ -4061,6 +4071,7 @@ impl Connection {
                 break;
             }
 
+            trace!("NEW_TOKEN");
             new_token.encode(buf);
             sent.retransmits
                 .get_or_create()

quinn-proto/src/connection/stats.rs

@@ -47,6 +47,7 @@ pub struct FrameStats {
     pub max_streams_bidi: u64,
     pub max_streams_uni: u64,
     pub new_connection_id: u64,
+    pub path_new_connection_id: u64,
     pub new_token: u64,
     pub path_challenge: u64,
     pub path_response: u64,
@@ -97,7 +98,11 @@ impl FrameStats {
                     self.streams_blocked_uni += 1;
                 }
             }
-            Frame::NewConnectionId(_) => self.new_connection_id += 1,
+            Frame::NewConnectionId(frame) => match frame.path_id {
+                Some(_) => self.path_new_connection_id += 1,
+                None => self.new_connection_id += 1,
+            },
+
             // TODO(@divma): split stats?
             Frame::RetireConnectionId { .. } => self.retire_connection_id += 1,
             Frame::PathChallenge(_) => self.path_challenge += 1,
@@ -136,6 +141,7 @@ impl std::fmt::Debug for FrameStats {
             .field("MAX_STREAMS_BIDI", &self.max_streams_bidi)
             .field("MAX_STREAMS_UNI", &self.max_streams_uni)
             .field("NEW_CONNECTION_ID", &self.new_connection_id)
+            .field("PATH_NEW_CONNECTION_ID", &self.path_new_connection_id)
             .field("NEW_TOKEN", &self.new_token)
             .field("PATH_CHALLENGE", &self.path_challenge)
             .field("PATH_RESPONSE", &self.path_response)

quinn-proto/src/tests/mod.rs

@@ -1537,6 +1537,41 @@ fn keep_alive() {
     }
 }
 
+#[test]
+fn cid_issued() {
+    let _guard = subscribe();
+    let transport_cfg = Arc::new(TransportConfig {
+        max_concurrent_multipath_paths: NonZeroU32::new(3),
+        ..TransportConfig::default()
+    });
+    let server_cfg = Arc::new(ServerConfig {
+        transport: transport_cfg.clone(),
+        ..server_config()
+    });
+    let server = Endpoint::new(Default::default(), Some(server_cfg), true, None);
+    let client = Endpoint::new(Default::default(), None, true, None);
+
+    let mut pair = Pair::new_from_endpoint(client, server);
+    let client_cfg = ClientConfig {
+        transport: transport_cfg,
+        ..client_config()
+    };
+    let (client_ch, _server_ch) = pair.connect_with(client_cfg);
+    pair.drive();
+
+    let client_stats = pair.client_conn_mut(client_ch).stats();
+    dbg!(&client_stats);
+
+    // The client does not send NEW_CONNECTION_ID frames when multipath is enabled.
+    assert_eq!(client_stats.frame_tx.new_connection_id, 0);
+    assert!(client_stats.frame_tx.path_new_connection_id > 0);
+
+    // The server still does send NEW_CONNECTION_ID frames when multipath is enabled, this
+    // is allowed, though it could avoid this.  TODO(flub): fix this sometime.
+    assert!(client_stats.frame_rx.new_connection_id > 0);
+    assert!(client_stats.frame_rx.path_new_connection_id > 0);
+}
+
 #[test]
 fn cid_rotation() {
     let _guard = subscribe();

quinn-proto/src/transport_parameters.rs

@@ -532,7 +532,6 @@ impl TransportParameters {
                     }
 
                     params.initial_max_path_id = Some(value);
-                    tracing::debug!(initial_max_path_id=%value, "multipath enabled");
                 }
                 _ => {
                     macro_rules! parse {