Add more initial packet and tls handshake logging

Summary:
Adds more logging for:
- Number of initial packets received
- Number of unique crypto frames received
- Time elapsed to get the last meaningful initial crypto frame.
- named groups, psk status, and ech status from TLS layer.

Reviewed By: mjoras

Differential Revision: D71910754

fbshipit-source-id: ea8524213ba296727079800bb167ec080143c10b

quic/api/QuicTransportBaseLite.cpp

@@ -1373,7 +1373,7 @@ void QuicTransportBaseLite::closeImpl(
 
   uint64_t totalCryptoDataWritten = 0;
   uint64_t totalCryptoDataRecvd = 0;
-
+  auto timeUntilLastInitialCryptoFrameReceived = std::chrono::milliseconds(0);
   if (conn_->cryptoState) {
     totalCryptoDataWritten +=
         conn_->cryptoState->initialStream.currentWriteOffset;
@@ -1386,9 +1386,14 @@ void QuicTransportBaseLite::closeImpl(
     totalCryptoDataRecvd +=
         conn_->cryptoState->handshakeStream.maxOffsetObserved;
     totalCryptoDataRecvd += conn_->cryptoState->oneRttStream.maxOffsetObserved;
+    timeUntilLastInitialCryptoFrameReceived =
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            conn_->cryptoState->lastInitialCryptoFrameReceivedTimePoint -
+            conn_->connectionTime);
   }
 
   if (conn_->qLogger) {
+    auto tlsSummary = conn_->handshakeLayer->getTLSSummary();
     conn_->qLogger->addTransportSummary(
         {conn_->lossState.totalBytesSent,
          conn_->lossState.totalBytesRecvd,
@@ -1410,7 +1415,13 @@ void QuicTransportBaseLite::closeImpl(
          conn_->usedZeroRtt,
          conn_->version.value_or(QuicVersion::MVFST_INVALID),
          conn_->dsrPacketCount,
-         getAppProtocol().value_or("")});
+         conn_->initialPacketsReceived,
+         conn_->uniqueInitialCryptoFramesReceived,
+         timeUntilLastInitialCryptoFrameReceived,
+         tlsSummary.alpn,
+         tlsSummary.namedGroup,
+         tlsSummary.pskType,
+         tlsSummary.echStatus});
   }
 
   // TODO: truncate the error code string to be 1MSS only.

quic/client/handshake/ClientHandshake.h

@@ -121,6 +121,10 @@ class ClientHandshake : public Handshake {
   virtual const std::shared_ptr<const folly::AsyncTransportCertificate>
   getPeerCertificate() const = 0;
 
+  TLSSummary getTLSSummary() const override {
+    LOG(FATAL) << "Not implemented";
+  }
+
   ~ClientHandshake() override = default;
 
  protected:

quic/fizz/client/handshake/FizzClientHandshake.cpp

@@ -241,6 +241,26 @@ FizzClientHandshake::getPeerCertificate() const {
   return state_.serverCert();
 }
 
+Handshake::TLSSummary FizzClientHandshake::getTLSSummary() const {
+  Handshake::TLSSummary summary;
+  if (state_.alpn().hasValue()) {
+    summary.alpn = state_.alpn().value();
+  }
+  if (state_.group().hasValue()) {
+    summary.namedGroup =
+        folly::to<std::string>(fizz::toString(state_.group().value()));
+  }
+  if (state_.pskType().hasValue()) {
+    summary.pskType =
+        folly::to<std::string>(fizz::toString(state_.pskType().value()));
+  }
+  if (state_.echState().hasValue()) {
+    summary.echStatus =
+        fizz::client::toString(state_.echState().value().status);
+  }
+  return summary;
+}
+
 class FizzClientHandshake::ActionMoveVisitor {
  public:
   explicit ActionMoveVisitor(FizzClientHandshake& client) : client_(client) {}

quic/fizz/client/handshake/FizzClientHandshake.h

@@ -59,6 +59,8 @@ class FizzClientHandshake : public ClientHandshake {
   const std::shared_ptr<const folly::AsyncTransportCertificate>
   getPeerCertificate() const override;
 
+  TLSSummary getTLSSummary() const override;
+
  protected:
   Optional<QuicCachedPsk> getPsk(const Optional<std::string>& hostname) const;
 

quic/handshake/HandshakeLayer.h

@@ -53,6 +53,14 @@ class Handshake {
   virtual void handshakeConfirmed() {
     LOG(FATAL) << "Not implemented";
   }
+
+  struct TLSSummary {
+    std::string alpn;
+    std::string namedGroup;
+    std::string pskType;
+    std::string echStatus;
+  };
+  [[nodiscard]] virtual TLSSummary getTLSSummary() const = 0;
 };
 
 constexpr folly::StringPiece kQuicDraft23Salt =

quic/logging/FileQLogger.cpp

@@ -253,7 +253,13 @@ void FileQLogger::addTransportSummary(const TransportSummaryArgs& args) {
       args.usedZeroRtt,
       args.quicVersion,
       args.dsrPacketCount,
-      std::move(args.alpn),
+      args.initialPacketsReceived,
+      args.uniqueInitialCryptoFramesReceived,
+      args.timeUntilLastInitialCryptoFrameReceived,
+      args.alpn,
+      args.namedGroup,
+      args.pskType,
+      args.echStatus,
       refTime));
 }
 

quic/logging/QLogger.h

@@ -62,7 +62,13 @@ class QLogger {
     bool usedZeroRtt{};
     QuicVersion quicVersion{QuicVersion::MVFST_INVALID};
     uint64_t dsrPacketCount{};
+    uint16_t initialPacketsReceived{};
+    uint16_t uniqueInitialCryptoFramesReceived{};
+    std::chrono::milliseconds timeUntilLastInitialCryptoFrameReceived;
     std::string alpn;
+    std::string namedGroup;
+    std::string pskType;
+    std::string echStatus;
   };
   virtual void addTransportSummary(const TransportSummaryArgs& args) = 0;
   virtual void addCongestionMetricUpdate(

quic/logging/QLoggerCommon.cpp

@@ -78,7 +78,13 @@ void QLoggerCommon::addTransportSummary(const TransportSummaryArgs& args) {
       args.usedZeroRtt,
       args.quicVersion,
       args.dsrPacketCount,
+      args.initialPacketsReceived,
+      args.uniqueInitialCryptoFramesReceived,
+      args.timeUntilLastInitialCryptoFrameReceived,
       args.alpn,
+      args.namedGroup,
+      args.pskType,
+      args.echStatus,
       refTime));
 }
 

quic/logging/QLoggerTypes.cpp

@@ -431,7 +431,13 @@ QLogTransportSummaryEvent::QLogTransportSummaryEvent(
     bool usedZeroRttIn,
     QuicVersion quicVersionIn,
     uint64_t dsrPacketCountIn,
+    uint16_t initialPacketsReceivedIn,
+    uint16_t uniqueInitialCryptoFramesReceivedIn,
+    std::chrono::milliseconds timeUntilLastInitialCryptoFrameReceivedIn,
     std::string alpnIn,
+    std::string namedGroupIn,
+    std::string pskTypeIn,
+    std::string echStatusIn,
     std::chrono::microseconds refTimeIn)
     : totalBytesSent{totalBytesSentIn},
       totalBytesRecvd{totalBytesRecvdIn},
@@ -452,7 +458,14 @@ QLogTransportSummaryEvent::QLogTransportSummaryEvent(
       usedZeroRtt{usedZeroRttIn},
       quicVersion{quicVersionIn},
       dsrPacketCount{dsrPacketCountIn},
-      alpn{alpnIn} {
+      initialPacketsReceived{initialPacketsReceivedIn},
+      uniqueInitialCryptoFramesReceived{uniqueInitialCryptoFramesReceivedIn},
+      timeUntilLastInitialCryptoFrameReceived{
+          timeUntilLastInitialCryptoFrameReceivedIn},
+      alpn{std::move(alpnIn)},
+      namedGroup{std::move(namedGroupIn)},
+      pskType{std::move(pskTypeIn)},
+      echStatus{std::move(echStatusIn)} {
   eventType = QLogEventType::TransportSummary;
   refTime = refTimeIn;
 }
@@ -489,7 +502,16 @@ folly::dynamic QLogTransportSummaryEvent::toDynamic() const {
       static_cast<std::underlying_type<decltype(quicVersion)>::type>(
           quicVersion);
   data["dsr_packet_count"] = dsrPacketCount;
+  data["initial_packets_received"] = initialPacketsReceived;
+  data["unique_initial_crypto_frames_received"] =
+      uniqueInitialCryptoFramesReceived;
+  data["time_until_last_initial_crypto_frame_received"] =
+      timeUntilLastInitialCryptoFrameReceived.count();
   data["alpn"] = alpn;
+  data["named_group"] = namedGroup;
+  data["psk_type"] = pskType;
+  data["ech_status"] = echStatus;
+  ;
 
   d.push_back(std::move(data));
   return d;

quic/logging/QLoggerTypes.h

@@ -488,7 +488,13 @@ class QLogTransportSummaryEvent : public QLogEvent {
       bool usedZeroRtt,
       QuicVersion version,
       uint64_t dsrPacketCount,
+      uint16_t initialPacketsReceived,
+      uint16_t uniqueInitialCryptoFramesReceived,
+      std::chrono::milliseconds timeUntilLastInitialCryptoFrameReceived,
       std::string alpn,
+      std::string namedGroup,
+      std::string pskType,
+      std::string echStatus,
       std::chrono::microseconds refTimeIn);
   ~QLogTransportSummaryEvent() override = default;
   uint64_t totalBytesSent;
@@ -509,7 +515,13 @@ class QLogTransportSummaryEvent : public QLogEvent {
   bool usedZeroRtt;
   QuicVersion quicVersion;
   uint64_t dsrPacketCount;
+  uint16_t initialPacketsReceived;
+  uint16_t uniqueInitialCryptoFramesReceived;
+  std::chrono::milliseconds timeUntilLastInitialCryptoFrameReceived;
   std::string alpn;
+  std::string namedGroup;
+  std::string pskType;
+  std::string echStatus;
 
   FOLLY_NODISCARD folly::dynamic toDynamic() const override;
 };

quic/logging/test/QLoggerTest.cpp

@@ -117,7 +117,14 @@ TEST_F(QLoggerTest, TransportSummaryEvent) {
        false,
        QuicVersion::MVFST,
        37,
-       "blah"});
+       /* numQuicInitialPacketReceived = */ 1,
+       /* numUniqueInitialCryptoFrameReceived = */ 1,
+       /* timeUntilLastInitialCryptoFrameReceived = */
+       std::chrono::milliseconds(1),
+       /* alpn = */ "blah",
+       /* namedGroup = */ "group",
+       /* pskType = */ "resumed",
+       /* echStatus = */ "accepted"});
 
   std::unique_ptr<QLogEvent> p = std::move(q.logs[0]);
   auto gotEvent = dynamic_cast<QLogTransportSummaryEvent*>(p.get());
@@ -139,7 +146,13 @@ TEST_F(QLoggerTest, TransportSummaryEvent) {
   EXPECT_EQ(gotEvent->finalPacketLossTimeReorderingThreshDividend, 47);
   EXPECT_EQ(gotEvent->usedZeroRtt, false);
   EXPECT_EQ(gotEvent->dsrPacketCount, 37);
+  EXPECT_EQ(gotEvent->initialPacketsReceived, 1);
+  EXPECT_EQ(gotEvent->uniqueInitialCryptoFramesReceived, 1);
+  EXPECT_EQ(gotEvent->timeUntilLastInitialCryptoFrameReceived.count(), 1);
   EXPECT_EQ(gotEvent->alpn, "blah");
+  EXPECT_EQ(gotEvent->namedGroup, "group");
+  EXPECT_EQ(gotEvent->pskType, "resumed");
+  EXPECT_EQ(gotEvent->echStatus, "accepted");
 }
 
 TEST_F(QLoggerTest, CongestionMetricUpdateEvent) {
@@ -859,7 +872,13 @@ TEST_F(QLoggerTest, TransportSummaryFollyDynamic) {
        "used_zero_rtt": true,
        "quic_version": 4207849474,
        "dsr_packet_count": 37,
-       "alpn": "blah"
+       "initial_packets_received": 1,
+       "unique_initial_crypto_frames_received": 1,
+       "time_until_last_initial_crypto_frame_received": 1,
+       "alpn": "blah",
+       "named_group": "group",
+       "psk_type": "resumed",
+       "ech_status": "accepted"
      }
    ]
  ])");
@@ -884,7 +903,14 @@ TEST_F(QLoggerTest, TransportSummaryFollyDynamic) {
        true,
        QuicVersion::MVFST,
        37,
-       "blah"});
+       /* numQuicInitialPacketReceived = */ 1,
+       /* numUniqueInitialCryptoFrameReceived = */ 1,
+       /* timeUntilLastInitialCryptoFrameReceived = */
+       std::chrono::milliseconds(1),
+       /* alpn = */ "blah",
+       /* namedGroup = */ "group",
+       /* pskType = */ "resumed",
+       /* echStatus = */ "accepted"});
   folly::dynamic gotDynamic = q.toDynamic();
   gotDynamic["traces"][0]["events"][0][0] = "0"; // hardcode reference time
   folly::dynamic gotEvents = gotDynamic["traces"][0]["events"];

quic/server/handshake/ServerHandshake.cpp

@@ -304,6 +304,25 @@ const Optional<Buf>& ServerHandshake::getAppToken() const {
   return state_.appToken();
 }
 
+Handshake::TLSSummary ServerHandshake::getTLSSummary() const {
+  Handshake::TLSSummary summary;
+  if (state_.alpn().hasValue()) {
+    summary.alpn = state_.alpn().value();
+  }
+  if (state_.group().hasValue()) {
+    summary.namedGroup =
+        folly::to<std::string>(fizz::toString(state_.group().value()));
+  }
+  if (state_.pskType().hasValue()) {
+    summary.pskType =
+        folly::to<std::string>(fizz::toString(state_.pskType().value()));
+  }
+  if (state_.echState().hasValue()) {
+    summary.echStatus = fizz::server::toString(state_.echStatus());
+  }
+  return summary;
+}
+
 class ServerHandshake::ActionMoveVisitor : public boost::static_visitor<> {
  public:
   explicit ActionMoveVisitor(ServerHandshake& server) : server_(server) {}

quic/server/handshake/ServerHandshake.h

@@ -247,6 +247,8 @@ class ServerHandshake : public Handshake {
    */
   const Optional<Buf>& getAppToken() const;
 
+  TLSSummary getTLSSummary() const override;
+
  protected:
   Phase phase_{Phase::Handshake};
 

quic/server/state/ServerStateMachine.cpp

@@ -976,6 +976,15 @@ void onServerReadDataFromOpen(
 
     bool isZeroRttPacket = protectionLevel == ProtectionType::ZeroRtt;
 
+    bool isQuicInitialPacket =
+        regularPacket.header.getHeaderForm() == HeaderForm::Long &&
+        regularPacket.header.asLong()->getHeaderType() ==
+            LongHeader::Types::Initial;
+
+    if (isQuicInitialPacket) {
+      ++conn.initialPacketsReceived;
+    }
+
     if (!isProtectedPacket || isZeroRttPacket) {
       // there are some frame restrictions
       auto isFrameInvalidFn = !isProtectedPacket
@@ -1182,10 +1191,19 @@ void onServerReadDataFromOpen(
                    << getCryptoStream(*conn.cryptoState, encryptionLevel)
                           ->currentReadOffset
                    << " " << conn;
+          auto cryptoStream =
+              getCryptoStream(*conn.cryptoState, encryptionLevel);
+          auto readBufferSize = cryptoStream->readBuffer.size();
           appendDataToReadBuffer(
-              *getCryptoStream(*conn.cryptoState, encryptionLevel),
+              *cryptoStream,
               StreamBuffer(
                   std::move(cryptoFrame.data), cryptoFrame.offset, false));
+          if (isQuicInitialPacket &&
+              readBufferSize != cryptoStream->readBuffer.size()) {
+            ++conn.uniqueInitialCryptoFramesReceived;
+            conn.cryptoState->lastInitialCryptoFrameReceivedTimePoint =
+                Clock::now();
+          }
           break;
         }
         case QuicFrame::Type::ReadStreamFrame: {

quic/server/test/QuicServerTransportTest.cpp

@@ -4017,6 +4017,19 @@ TEST_F(QuicUnencryptedServerTransportTest, TestNoAckOnlyCryptoInitial) {
   }
 }
 
+TEST_F(QuicUnencryptedServerTransportTest, TestDuplicateCryptoInitialLogging) {
+  auto transportSettings = server->getTransportSettings();
+  server->setTransportSettings(transportSettings);
+
+  recvClientHello();
+  recvClientHello();
+  recvClientHello();
+
+  EXPECT_GE(serverWrites.size(), 1);
+  EXPECT_EQ(getConn().initialPacketsReceived, 3);
+  EXPECT_EQ(getConn().uniqueInitialCryptoFramesReceived, 1);
+}
+
 TEST_F(
     QuicUnencryptedServerTransportTest,
     TestHandshakeNotWritableBytesLimited) {

quic/state/BUCK

@@ -137,9 +137,6 @@ mvfst_cpp_library(
         "//quic/logging:qlogger",
         "//quic/observer:socket_observer_types",
     ],
-    external_deps = [
-        "glog",
-    ],
 )
 
 mvfst_cpp_library(
@@ -179,8 +176,6 @@ mvfst_cpp_library(
         "QuicStreamFunctions.h",
     ],
     deps = [
-        ":quic_stream_utilities",
-        "//folly/io:iobuf",
         "//quic:exception",
         "//quic/flowcontrol:flow_control",
     ],

quic/state/StateData.h

@@ -251,6 +251,9 @@ struct QuicCryptoState {
 
   // Stream to exchange handshake data encrypted with 1-rtt keys.
   QuicCryptoStream oneRttStream;
+
+  // Time point that the last initial packet with crypto frame received.
+  TimePoint lastInitialCryptoFrameReceivedTimePoint;
 };
 
 struct ConnectionCloseEvent {
@@ -734,6 +737,12 @@ struct QuicConnectionStateBase : public folly::DelayedDestruction {
     } fields;
   };
   TosHeader socketTos;
+
+  // Number of QUIC initial packets received.
+  uint16_t initialPacketsReceived{0};
+
+  // Number of QUIC unique crypto frame received with initial package.
+  uint16_t uniqueInitialCryptoFramesReceived{0};
 };
 
 std::ostream& operator<<(std::ostream& os, const QuicConnectionStateBase& st);