Log Server Handshake Size

Summary: - logging number of bytes the server sent during the handshake for insight.

Reviewed By: mjoras

Differential Revision: D33069800

fbshipit-source-id: e7e8f25183ee30de99e2971bae3c6b93882f6e63

quic/api/QuicTransportFunctions.cpp

@@ -164,19 +164,20 @@ WriteQuicDataResult writeQuicDataToSocketImpl(
   }
   FrameScheduler scheduler = std::move(schedulerBuilder).build();
   packetsWritten = writeConnectionDataToSocket(
-      sock,
-      connection,
-      srcConnId,
-      dstConnId,
-      std::move(builder),
-      PacketNumberSpace::AppData,
-      scheduler,
-      congestionControlWritableBytes,
-      packetLimit,
-      aead,
-      headerCipher,
-      version,
-      writeLoopBeginTime);
+                       sock,
+                       connection,
+                       srcConnId,
+                       dstConnId,
+                       std::move(builder),
+                       PacketNumberSpace::AppData,
+                       scheduler,
+                       congestionControlWritableBytes,
+                       packetLimit,
+                       aead,
+                       headerCipher,
+                       version,
+                       writeLoopBeginTime)
+                       .packetsWritten;
   VLOG_IF(10, packetsWritten || probesWritten)
       << nodeToString(connection.nodeType) << " written data "
       << (exceptCryptoStream ? "without crypto data " : "")
@@ -984,6 +985,7 @@ WriteQuicDataResult writeCryptoAndAckDataToSocket(
   auto builder = LongHeaderBuilder(packetType);
   WriteQuicDataResult result;
   auto& packetsWritten = result.packetsWritten;
+  auto& bytesWritten = result.bytesWritten;
   auto& probesWritten = result.probesWritten;
   auto& cryptoStream =
       *getCryptoStream(*connection.cryptoState, encryptionLevel);
@@ -1011,7 +1013,7 @@ WriteQuicDataResult writeCryptoAndAckDataToSocket(
   // Only get one chance to write probes.
   numProbePackets = 0;
   // Crypto data is written without aead protection.
-  packetsWritten += writeConnectionDataToSocket(
+  auto writeResult = writeConnectionDataToSocket(
       sock,
       connection,
       srcConnId,
@@ -1026,6 +1028,10 @@ WriteQuicDataResult writeCryptoAndAckDataToSocket(
       version,
       Clock::now(),
       token);
+
+  packetsWritten += writeResult.packetsWritten;
+  bytesWritten += writeResult.bytesWritten;
+
   VLOG_IF(10, packetsWritten || probesWritten)
       << nodeToString(connection.nodeType)
       << " written crypto and acks data type=" << packetType
@@ -1108,19 +1114,20 @@ uint64_t writeZeroRttDataToSocket(
                     .simpleFrames())
           .build();
   auto written = writeConnectionDataToSocket(
-      socket,
-      connection,
-      srcConnId,
-      dstConnId,
-      std::move(builder),
-      LongHeader::typeToPacketNumberSpace(type),
-      scheduler,
-      congestionControlWritableBytes,
-      packetLimit,
-      aead,
-      headerCipher,
-      version,
-      Clock::now());
+                     socket,
+                     connection,
+                     srcConnId,
+                     dstConnId,
+                     std::move(builder),
+                     LongHeader::typeToPacketNumberSpace(type),
+                     scheduler,
+                     congestionControlWritableBytes,
+                     packetLimit,
+                     aead,
+                     headerCipher,
+                     version,
+                     Clock::now())
+                     .packetsWritten;
   VLOG_IF(10, written > 0) << nodeToString(connection.nodeType)
                            << " written zero rtt data, packets=" << written
                            << " " << connection;
@@ -1308,7 +1315,7 @@ void encryptPacketHeader(
   }
 }
 
-uint64_t writeConnectionDataToSocket(
+WriteQuicDataResult writeConnectionDataToSocket(
     folly::AsyncUDPSocket& sock,
     QuicConnectionStateBase& connection,
     const ConnectionId& srcConnId,
@@ -1358,6 +1365,9 @@ uint64_t writeConnectionDataToSocket(
           QuicBatchingMode::BATCHING_MODE_NONE
       ? connection.transportSettings.writeConnectionDataPacketsLimit
       : connection.transportSettings.maxBatchSize;
+
+  uint64_t bytesWritten = 0;
+
   while (scheduler.hasData() && ioBufBatch.getPktSent() < packetLimit &&
          ((ioBufBatch.getPktSent() < batchSize) ||
           writeLoopTimeLimit(writeLoopBeginTime, connection))) {
@@ -1389,13 +1399,15 @@ uint64_t writeConnectionDataToSocket(
         headerCipher);
 
     if (!ret.buildSuccess) {
-      return ioBufBatch.getPktSent();
+      return {ioBufBatch.getPktSent(), 0, bytesWritten};
     }
     // If we build a packet, we updateConnection(), even if write might have
     // been failed. Because if it builds, a lot of states need to be updated no
     // matter the write result. We are basically treating this case as if we
     // pretend write was also successful but packet is lost somewhere in the
     // network.
+    bytesWritten += ret.encodedSize;
+
     auto& result = ret.result;
     updateConnection(
         connection,
@@ -1413,7 +1425,7 @@ uint64_t writeConnectionDataToSocket(
         connection.writeDebugState.noWriteReason =
             NoWriteReason::SOCKET_FAILURE;
       }
-      return ioBufBatch.getPktSent();
+      return {ioBufBatch.getPktSent(), 0, bytesWritten};
     }
   }
 
@@ -1425,7 +1437,7 @@ uint64_t writeConnectionDataToSocket(
     CHECK(buf->length() == 0 && buf->headroom() == 0);
     connection.bufAccessor->release(std::move(buf));
   }
-  return ioBufBatch.getPktSent();
+  return {ioBufBatch.getPktSent(), 0, bytesWritten};
 }
 
 uint64_t writeProbingDataToSocket(
@@ -1448,20 +1460,21 @@ uint64_t writeProbingDataToSocket(
       scheduler, connection, "CloningScheduler", aead.getCipherOverhead());
   auto writeLoopBeginTime = Clock::now();
   auto written = writeConnectionDataToSocket(
-      sock,
-      connection,
-      srcConnId,
-      dstConnId,
-      builder,
-      pnSpace,
-      cloningScheduler,
-      unlimitedWritableBytes,
-      probesToSend,
-      aead,
-      headerCipher,
-      version,
-      writeLoopBeginTime,
-      token);
+                     sock,
+                     connection,
+                     srcConnId,
+                     dstConnId,
+                     builder,
+                     pnSpace,
+                     cloningScheduler,
+                     unlimitedWritableBytes,
+                     probesToSend,
+                     aead,
+                     headerCipher,
+                     version,
+                     writeLoopBeginTime,
+                     token)
+                     .packetsWritten;
   if (probesToSend && !written) {
     // Fall back to send a ping:
     connection.pendingEvents.sendPing = true;
@@ -1471,19 +1484,20 @@ uint64_t writeProbingDataToSocket(
                       .pingFrames())
             .build();
     written += writeConnectionDataToSocket(
-        sock,
-        connection,
-        srcConnId,
-        dstConnId,
-        builder,
-        pnSpace,
-        pingScheduler,
-        unlimitedWritableBytes,
-        probesToSend - written,
-        aead,
-        headerCipher,
-        version,
-        writeLoopBeginTime);
+                   sock,
+                   connection,
+                   srcConnId,
+                   dstConnId,
+                   builder,
+                   pnSpace,
+                   pingScheduler,
+                   unlimitedWritableBytes,
+                   probesToSend - written,
+                   aead,
+                   headerCipher,
+                   version,
+                   writeLoopBeginTime)
+                   .packetsWritten;
   }
   VLOG_IF(10, written > 0)
       << nodeToString(connection.nodeType)
@@ -1513,19 +1527,20 @@ uint64_t writeD6DProbeToSocket(
       aead.getCipherOverhead(),
       connection.d6d.currentProbeSize);
   auto written = writeConnectionDataToSocket(
-      sock,
-      connection,
-      srcConnId,
-      dstConnId,
-      builder,
-      pnSpace,
-      d6dProbeScheduler,
-      unlimitedWritableBytes,
-      1,
-      aead,
-      headerCipher,
-      version,
-      Clock::now());
+                     sock,
+                     connection,
+                     srcConnId,
+                     dstConnId,
+                     builder,
+                     pnSpace,
+                     d6dProbeScheduler,
+                     unlimitedWritableBytes,
+                     1,
+                     aead,
+                     headerCipher,
+                     version,
+                     Clock::now())
+                     .packetsWritten;
   VLOG_IF(10, written > 0) << nodeToString(connection.nodeType)
                            << " writing d6d probes using scheduler=D6DScheduler"
                            << connection;

quic/api/QuicTransportFunctions.h

@@ -83,6 +83,7 @@ using WritableBytesFunc =
 struct WriteQuicDataResult {
   uint64_t packetsWritten{};
   uint64_t probesWritten{};
+  uint64_t bytesWritten{};
 };
 
 /**
@@ -270,7 +271,7 @@ void encryptPacketHeader(
  * data allowed by the writableBytesFunc and will only write a maximum
  * number of packetLimit packets at each invocation.
  */
-uint64_t writeConnectionDataToSocket(
+WriteQuicDataResult writeConnectionDataToSocket(
     folly::AsyncUDPSocket& sock,
     QuicConnectionStateBase& connection,
     const ConnectionId& srcConnId,

quic/api/test/QuicTransportFunctionsTest.cpp

@@ -3149,6 +3149,7 @@ TEST_F(QuicTransportFunctionsTest, TestCryptoWritingIsHandshakeInOutstanding) {
 
   EXPECT_EQ(1, res.packetsWritten);
   EXPECT_EQ(0, res.probesWritten);
+  EXPECT_GE(res.bytesWritten, buf->computeChainDataLength());
   ASSERT_EQ(1, conn->outstandings.packets.size());
   EXPECT_TRUE(getFirstOutstandingPacket(*conn, PacketNumberSpace::Initial)
                   ->metadata.isHandshake);
@@ -3173,6 +3174,7 @@ TEST_F(QuicTransportFunctionsTest, NoCryptoProbeWriteIfNoProbeCredit) {
       *conn->initialHeaderCipher,
       getVersion(*conn),
       conn->transportSettings.writeConnectionDataPacketsLimit);
+  EXPECT_GE(res.bytesWritten, buf->computeChainDataLength());
 
   EXPECT_EQ(1, res.packetsWritten);
   EXPECT_EQ(0, res.probesWritten);
@@ -3195,7 +3197,7 @@ TEST_F(QuicTransportFunctionsTest, NoCryptoProbeWriteIfNoProbeCredit) {
       *conn->initialHeaderCipher,
       getVersion(*conn),
       conn->transportSettings.writeConnectionDataPacketsLimit);
-
+  EXPECT_EQ(0, res.bytesWritten);
   EXPECT_EQ(0, res.packetsWritten);
   EXPECT_EQ(0, res.probesWritten);
 }
@@ -3208,7 +3210,7 @@ TEST_F(QuicTransportFunctionsTest, ResetNumProbePackets) {
   auto rawSocket = socket.get();
 
   conn->pendingEvents.numProbePackets[PacketNumberSpace::Initial] = 2;
-  writeCryptoAndAckDataToSocket(
+  auto writeRes1 = writeCryptoAndAckDataToSocket(
       *rawSocket,
       *conn,
       *conn->clientConnectionId,
@@ -3219,11 +3221,12 @@ TEST_F(QuicTransportFunctionsTest, ResetNumProbePackets) {
       getVersion(*conn),
       conn->transportSettings.writeConnectionDataPacketsLimit);
   EXPECT_FALSE(conn->pendingEvents.anyProbePackets());
+  EXPECT_EQ(0, writeRes1.bytesWritten);
 
   conn->handshakeWriteCipher = createNoOpAead();
   conn->handshakeWriteHeaderCipher = createNoOpHeaderCipher();
   conn->pendingEvents.numProbePackets[PacketNumberSpace::Handshake] = 2;
-  writeCryptoAndAckDataToSocket(
+  auto writeRes2 = writeCryptoAndAckDataToSocket(
       *rawSocket,
       *conn,
       *conn->clientConnectionId,
@@ -3234,6 +3237,7 @@ TEST_F(QuicTransportFunctionsTest, ResetNumProbePackets) {
       getVersion(*conn),
       conn->transportSettings.writeConnectionDataPacketsLimit);
   EXPECT_FALSE(conn->pendingEvents.anyProbePackets());
+  EXPECT_EQ(0, writeRes2.bytesWritten);
 
   conn->oneRttWriteCipher = createNoOpAead();
   conn->oneRttWriteHeaderCipher = createNoOpHeaderCipher();

quic/server/QuicServerTransport.cpp

@@ -286,17 +286,20 @@ void QuicServerTransport::writeData() {
          hasAcksToSchedule(conn_->ackStates.initialAckState))) {
       CHECK(conn_->initialWriteCipher);
       CHECK(conn_->initialHeaderCipher);
-      packetLimit -= writeCryptoAndAckDataToSocket(
-                         *socket_,
-                         *conn_,
-                         srcConnId /* src */,
-                         destConnId /* dst */,
-                         LongHeader::Types::Initial,
-                         *conn_->initialWriteCipher,
-                         *conn_->initialHeaderCipher,
-                         version,
-                         packetLimit)
-                         .packetsWritten;
+
+      auto res = writeCryptoAndAckDataToSocket(
+          *socket_,
+          *conn_,
+          srcConnId /* src */,
+          destConnId /* dst */,
+          LongHeader::Types::Initial,
+          *conn_->initialWriteCipher,
+          *conn_->initialHeaderCipher,
+          version,
+          packetLimit);
+
+      packetLimit -= res.packetsWritten;
+      serverConn_->numHandshakeBytesSent += res.bytesWritten;
     }
     if (!packetLimit && !conn_->pendingEvents.anyProbePackets()) {
       return;
@@ -316,17 +319,19 @@ void QuicServerTransport::writeData() {
          hasAcksToSchedule(conn_->ackStates.handshakeAckState))) {
       CHECK(conn_->handshakeWriteCipher);
       CHECK(conn_->handshakeWriteHeaderCipher);
-      packetLimit -= writeCryptoAndAckDataToSocket(
-                         *socket_,
-                         *conn_,
-                         srcConnId /* src */,
-                         destConnId /* dst */,
-                         LongHeader::Types::Handshake,
-                         *conn_->handshakeWriteCipher,
-                         *conn_->handshakeWriteHeaderCipher,
-                         version,
-                         packetLimit)
-                         .packetsWritten;
+      auto res = writeCryptoAndAckDataToSocket(
+          *socket_,
+          *conn_,
+          srcConnId /* src */,
+          destConnId /* dst */,
+          LongHeader::Types::Handshake,
+          *conn_->handshakeWriteCipher,
+          *conn_->handshakeWriteHeaderCipher,
+          version,
+          packetLimit);
+
+      packetLimit -= res.packetsWritten;
+      serverConn_->numHandshakeBytesSent += res.bytesWritten;
     }
     if (!packetLimit && !conn_->pendingEvents.anyProbePackets()) {
       return;

quic/server/state/ServerStateMachine.h

@@ -132,6 +132,9 @@ struct QuicServerConnectionState : public QuicConnectionStateBase {
   // Whether we've sent the new_token frame yet.
   bool sentNewTokenFrame{false};
 
+  // Number of bytes the server has written during the handshake.
+  uint64_t numHandshakeBytesSent{0};
+
 #ifdef CCP_ENABLED
   // Pointer to struct that maintains state needed for interacting with libccp.
   // Once instance of this struct is created for each instance of