Add idle recovery debug telemetry

Summary: Add debug-gated QUIC lifecycle snapshots to distinguish stale-connection recovery from general request slowness. Requests now record connection age, last RX/TX age, signed idle-deadline distance, and timer counts at request start and completion. mvfst reports separate idle and keepalive callbacks plus overdue-deadline observations; ngtcp2 reports its unified transport timer. Recreated requests preserve the prior connection UUID so the request can be joined to the close reason and replacement connection.

Reviewed By: jbeshay

Differential Revision: D125287129

fbshipit-source-id: 921046a7ed2a6273fde59be0125dcbd8904ccaf4

quic/api/QuicTransportBaseLite.cpp

@@ -2723,6 +2723,12 @@ void QuicTransportBaseLite::lossTimeoutExpired() noexcept {
 void QuicTransportBaseLite::idleTimeoutExpired(bool drain) noexcept {
   MVVLOG(4) << __func__ << " " << *this;
   [[maybe_unused]] auto self = sharedGuard();
+  const auto now = Clock::now();
+  if (idleTimeoutDeadline_.has_value() && now >= *idleTimeoutDeadline_) {
+    lastIdleDeadlineOverdue_ =
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            now - *idleTimeoutDeadline_);
+  }
   // idle timeout is expired, just close the connection and drain or
   // send connection close immediately depending on 'drain'
   MVDCHECK_NE(closeState_, CloseState::CLOSED);
@@ -2759,6 +2765,16 @@ void QuicTransportBaseLite::sendPing(
 
 void QuicTransportBaseLite::keepaliveTimeoutExpired() noexcept {
   [[maybe_unused]] auto self = sharedGuard();
+  ++keepaliveTimeoutFiredCount_;
+  const auto now = Clock::now();
+  const bool idleDeadlineExpired =
+      idleTimeoutDeadline_.has_value() && now >= *idleTimeoutDeadline_;
+  if (idleDeadlineExpired) {
+    ++keepaliveExpiredIdleDeadlineCount_;
+    lastIdleDeadlineOverdue_ =
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            now - *idleTimeoutDeadline_);
+  }
   conn_->pendingEvents.sendPing = true;
   updateWriteLooper(true);
 }
@@ -3323,6 +3339,7 @@ void QuicTransportBaseLite::setIdleTimer() {
   }
   cancelTimeout(&idleTimeout_);
   cancelTimeout(&keepaliveTimeout_);
+  idleTimeoutDeadline_.reset();
   auto localIdleTimeout = conn_->transportSettings.idleTimeout;
   // The local idle timeout being zero means it is disabled.
   if (localIdleTimeout == 0ms) {
@@ -3332,6 +3349,7 @@ void QuicTransportBaseLite::setIdleTimer() {
       conn_->peerIdleTimeout > 0ms ? conn_->peerIdleTimeout : localIdleTimeout;
   auto idleTimeout = timeMin(localIdleTimeout, peerIdleTimeout);
 
+  idleTimeoutDeadline_ = Clock::now() + idleTimeout;
   scheduleTimeout(&idleTimeout_, idleTimeout);
   auto idleTimeoutCount = idleTimeout.count();
   if (conn_->transportSettings.enableKeepalive) {

quic/api/QuicTransportBaseLite.h

@@ -382,6 +382,7 @@ class QuicTransportBaseLite : virtual public QuicSocketLite,
         : transport_(transport) {}
 
     void timeoutExpired() noexcept override {
+      ++transport_->idleTimeoutFiredCount_;
       transport_->idleTimeoutExpired(true /* drain */);
     }
 
@@ -950,6 +951,11 @@ class QuicTransportBaseLite : virtual public QuicSocketLite,
   ExcessWriteTimeout excessWriteTimeout_;
   IdleTimeout idleTimeout_;
   KeepaliveTimeout keepaliveTimeout_;
+  Optional<TimePoint> idleTimeoutDeadline_;
+  uint64_t idleTimeoutFiredCount_{0};
+  uint64_t keepaliveTimeoutFiredCount_{0};
+  uint64_t keepaliveExpiredIdleDeadlineCount_{0};
+  Optional<std::chrono::milliseconds> lastIdleDeadlineOverdue_;
   AckTimeout ackTimeout_;
   PathValidationTimeout pathValidationTimeout_;
   DrainTimeout drainTimeout_;

quic/client/QuicClientTransportLite.cpp

@@ -2353,6 +2353,35 @@ std::chrono::milliseconds QuicClientTransportLite::getConnectionIdleDuration()
       now - lastReceivedPacketTime);
 }
 
+ConnectionLifecycleDebugState
+QuicClientTransportLite::getConnectionLifecycleDebugState() const {
+  const auto now = Clock::now();
+  const auto ageSince = [now](TimePoint time) {
+    return time >= now
+        ? std::chrono::milliseconds::zero()
+        : std::chrono::duration_cast<std::chrono::milliseconds>(now - time);
+  };
+  const auto lastTxTime =
+      conn_->lossState.maybeLastPacketSentTime.value_or(conn_->connectionTime);
+
+  ConnectionLifecycleDebugState state{
+      .connectionAge = ageSince(conn_->connectionTime),
+      .lastRxAge = getConnectionIdleDuration(),
+      .lastTxAge = ageSince(lastTxTime),
+      .idleDeadlineDelta = std::nullopt,
+      .lastIdleDeadlineOverdue = lastIdleDeadlineOverdue_,
+      .idleTimeoutFiredCount = idleTimeoutFiredCount_,
+      .keepaliveTimeoutFiredCount = keepaliveTimeoutFiredCount_,
+      .keepaliveExpiredIdleDeadlineCount = keepaliveExpiredIdleDeadlineCount_,
+  };
+  if (idleTimeoutDeadline_.has_value()) {
+    state.idleDeadlineDelta =
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            *idleTimeoutDeadline_ - now);
+  }
+  return state;
+}
+
 int64_t QuicClientTransportLite::getNetworkReadCallbackStartTimeMs() const {
   if (networkReadCallbackStartTime_ == TimePoint{}) {
     return -1;

quic/client/QuicClientTransportLite.h

@@ -27,6 +27,17 @@ namespace quic {
 class ClientHandshakeFactory;
 class QuicTokenCache;
 
+struct ConnectionLifecycleDebugState {
+  std::chrono::milliseconds connectionAge{0};
+  std::chrono::milliseconds lastRxAge{0};
+  std::chrono::milliseconds lastTxAge{0};
+  Optional<std::chrono::milliseconds> idleDeadlineDelta;
+  Optional<std::chrono::milliseconds> lastIdleDeadlineOverdue;
+  uint64_t idleTimeoutFiredCount{0};
+  uint64_t keepaliveTimeoutFiredCount{0};
+  uint64_t keepaliveExpiredIdleDeadlineCount{0};
+};
+
 class QuicClientTransportLite
     : virtual public QuicTransportBaseLite,
       public QuicAsyncUDPSocket::ReadCallback,
@@ -247,6 +258,8 @@ class QuicClientTransportLite
 
   std::chrono::milliseconds getConnectionIdleDuration() const;
 
+  ConnectionLifecycleDebugState getConnectionLifecycleDebugState() const;
+
   int64_t getNetworkReadCallbackStartTimeMs() const;
 
   uint64_t getReceivedUdpDatagramCount() const;

quic/client/test/QuicClientTransportLiteTest.cpp

@@ -50,6 +50,14 @@ class QuicClientTransportLiteMock : public QuicClientTransportLite {
   [[nodiscard]] quic::Expected<void, QuicError> invokeWriteSocketData() {
     return writeSocketData();
   }
+
+  void setIdleTimeoutDeadlineForTest(TimePoint deadline) {
+    idleTimeoutDeadline_ = deadline;
+  }
+
+  void invokeKeepaliveTimeoutExpiredForTest() {
+    keepaliveTimeoutExpired();
+  }
 };
 
 class QuicClientTransportLiteTest : public Test {
@@ -190,6 +198,33 @@ TEST_F(
   EXPECT_LT(idleDuration, std::chrono::milliseconds(3000));
 }
 
+TEST_F(
+    QuicClientTransportLiteTest,
+    ConnectionLifecycleDebugStateTracksIdleDeadlineAndTimer) {
+  const auto now = Clock::now();
+  auto* conn = quicClient_->getConn();
+  conn->connectionTime = now - std::chrono::seconds(20);
+  conn->ackStates.appDataAckState.largestRecvdPacketTime =
+      now - std::chrono::seconds(2);
+  conn->lossState.maybeLastPacketSentTime = now - std::chrono::seconds(3);
+  quicClient_->setIdleTimeoutDeadlineForTest(
+      now - std::chrono::milliseconds(500));
+
+  quicClient_->invokeKeepaliveTimeoutExpiredForTest();
+  const auto state = quicClient_->getConnectionLifecycleDebugState();
+
+  EXPECT_GE(state.connectionAge, std::chrono::milliseconds(19'900));
+  EXPECT_GE(state.lastRxAge, std::chrono::milliseconds(1'900));
+  EXPECT_GE(state.lastTxAge, std::chrono::milliseconds(2'900));
+  ASSERT_TRUE(state.idleDeadlineDelta.has_value());
+  EXPECT_LE(*state.idleDeadlineDelta, std::chrono::milliseconds(-500));
+  ASSERT_TRUE(state.lastIdleDeadlineOverdue.has_value());
+  EXPECT_GE(*state.lastIdleDeadlineOverdue, std::chrono::milliseconds(500));
+  EXPECT_EQ(state.idleTimeoutFiredCount, 0);
+  EXPECT_EQ(state.keepaliveTimeoutFiredCount, 1);
+  EXPECT_EQ(state.keepaliveExpiredIdleDeadlineCount, 1);
+}
+
 TEST_F(
     QuicClientTransportLiteTest,
     SetTransportSettingsPreservesPeerTimestampFrameExponent) {