QLog changes to support ack receive timestamps

Summary: Add additional ACK_RECEIVE_TIMESTAMP fields in Read and Write AckFrame logs.

Reviewed By: bschlinker

Differential Revision: D37799091

fbshipit-source-id: fb1d6fbe9b3bcb5c0f8f8786a787730eaa699d1c

quic/logging/BaseQLogger.cpp

@@ -155,8 +155,13 @@ std::unique_ptr<QLogPacketEvent> BaseQLogger::createPacketEvent(
       }
       case QuicFrame::Type::ReadAckFrame: {
         const auto& frame = *quicFrame.asReadAckFrame();
-        event->frames.push_back(
+        event->frames.push_back(std::make_unique<ReadAckFrameLog>(
-            std::make_unique<ReadAckFrameLog>(frame.ackBlocks, frame.ackDelay));
+            frame.ackBlocks,
+            frame.ackDelay,
+            frame.frameType,
+            frame.maybeLatestRecvdPacketTime,
+            frame.maybeLatestRecvdPacketNum,
+            frame.recvdPacketsTimestampRanges));
         break;
       }
       case QuicFrame::Type::ReadStreamFrame: {
@@ -276,7 +281,12 @@ std::unique_ptr<QLogPacketEvent> BaseQLogger::createPacketEvent(
       case QuicWriteFrame::Type::WriteAckFrame: {
         const WriteAckFrame& frame = *quicFrame.asWriteAckFrame();
         event->frames.push_back(std::make_unique<WriteAckFrameLog>(
-            frame.ackBlocks, frame.ackDelay));
+            frame.ackBlocks,
+            frame.ackDelay,
+            frame.frameType,
+            frame.maybeLatestRecvdPacketTime,
+            frame.maybeLatestRecvdPacketNum,
+            frame.recvdPacketsTimestampRanges));
         break;
       }
       case QuicWriteFrame::Type::WriteStreamFrame: {

quic/logging/QLoggerTypes.cpp

@@ -212,13 +212,33 @@ folly::dynamic RetireConnectionIdFrameLog::toDynamic() const {
 folly::dynamic ReadAckFrameLog::toDynamic() const {
   folly::dynamic d = folly::dynamic::object();
   folly::dynamic ackRangeDynamic = folly::dynamic::array();
+  folly::dynamic recvdPacketsTimestampRangesDynamic = folly::dynamic::array();
 
   for (const auto& b : ackBlocks) {
     ackRangeDynamic.push_back(
         folly::dynamic::array(b.startPacket, b.endPacket));
   }
   d["acked_ranges"] = ackRangeDynamic;
-  d["frame_type"] = toQlogString(FrameType::ACK);
+  d["frame_type"] = toQlogString(frameType);
+  if (frameType == FrameType::ACK_RECEIVE_TIMESTAMPS) {
+    if (maybeLatestRecvdPacketTime.has_value()) {
+      d["latest_recvd_packet_time"] =
+          maybeLatestRecvdPacketTime.value().count();
+    }
+    if (maybeLatestRecvdPacketNum.has_value()) {
+      d["latest_recvd_packet_num"] = maybeLatestRecvdPacketNum.value();
+    }
+    for (auto it = recvdPacketsTimestampRanges.cbegin();
+         it != recvdPacketsTimestampRanges.cend();
+         ++it) {
+      recvdPacketsTimestampRangesDynamic.push_back(folly::dynamic::array(
+          it->gap,
+          it->timestamp_delta_count,
+          it->deltas.front(),
+          it->deltas.back()));
+    }
+    d["timestamp_ranges"] = recvdPacketsTimestampRangesDynamic;
+  }
   d["ack_delay"] = ackDelay.count();
   return d;
 }
@@ -226,12 +246,32 @@ folly::dynamic ReadAckFrameLog::toDynamic() const {
 folly::dynamic WriteAckFrameLog::toDynamic() const {
   folly::dynamic d = folly::dynamic::object();
   folly::dynamic ackRangeDynamic = folly::dynamic::array();
+  folly::dynamic recvdPacketsTimestampRangesDynamic = folly::dynamic::array();
 
   for (auto it = ackBlocks.cbegin(); it != ackBlocks.cend(); ++it) {
     ackRangeDynamic.push_back(folly::dynamic::array(it->start, it->end));
   }
   d["acked_ranges"] = ackRangeDynamic;
-  d["frame_type"] = toQlogString(FrameType::ACK);
+  d["frame_type"] = toQlogString(frameType);
+  if (frameType == FrameType::ACK_RECEIVE_TIMESTAMPS) {
+    if (maybeLatestRecvdPacketTime.has_value()) {
+      d["latest_recvd_packet_time"] =
+          maybeLatestRecvdPacketTime.value().count();
+    }
+    if (maybeLatestRecvdPacketNum.has_value()) {
+      d["latest_recvd_packet_num"] = maybeLatestRecvdPacketNum.value();
+    }
+    for (auto it = recvdPacketsTimestampRanges.cbegin();
+         it != recvdPacketsTimestampRanges.cend();
+         ++it) {
+      recvdPacketsTimestampRangesDynamic.push_back(folly::dynamic::array(
+          it->gap,
+          it->timestamp_delta_count,
+          it->deltas.front(),
+          it->deltas.back()));
+    }
+    d["timestamp_ranges"] = recvdPacketsTimestampRangesDynamic;
+  }
   d["ack_delay"] = ackDelay.count();
   return d;
 }

quic/logging/QLoggerTypes.h

@@ -194,11 +194,24 @@ class ReadAckFrameLog : public QLogFrame {
  public:
   ReadAckFrame::Vec ackBlocks;
   std::chrono::microseconds ackDelay;
-
+  FrameType frameType;
+  folly::Optional<std::chrono::microseconds> maybeLatestRecvdPacketTime;
+  folly::Optional<PacketNum> maybeLatestRecvdPacketNum;
+  RecvdPacketsTimestampsRangeVec recvdPacketsTimestampRanges;
   ReadAckFrameLog(
       const ReadAckFrame::Vec& ackBlocksIn,
-      std::chrono::microseconds ackDelayIn)
+      std::chrono::microseconds ackDelayIn,
-      : ackBlocks{ackBlocksIn}, ackDelay{ackDelayIn} {}
+      FrameType frameTypeIn = FrameType::ACK,
+      folly::Optional<std::chrono::microseconds> maybeLatestRecvdPacketTimeIn =
+          folly::none,
+      folly::Optional<PacketNum> maybeLatestRecvdPacketNumIn = folly::none,
+      RecvdPacketsTimestampsRangeVec recvdPacketsTimestampRangesIn = {})
+      : ackBlocks{ackBlocksIn},
+        ackDelay{ackDelayIn},
+        frameType{frameTypeIn},
+        maybeLatestRecvdPacketTime{maybeLatestRecvdPacketTimeIn},
+        maybeLatestRecvdPacketNum{maybeLatestRecvdPacketNumIn},
+        recvdPacketsTimestampRanges(recvdPacketsTimestampRangesIn) {}
   ~ReadAckFrameLog() override = default;
   FOLLY_NODISCARD folly::dynamic toDynamic() const override;
 };
@@ -207,11 +220,26 @@ class WriteAckFrameLog : public QLogFrame {
  public:
   WriteAckFrame::AckBlockVec ackBlocks;
   std::chrono::microseconds ackDelay;
+  FrameType frameType;
+  folly::Optional<std::chrono::microseconds> maybeLatestRecvdPacketTime;
+  folly::Optional<PacketNum> maybeLatestRecvdPacketNum;
+  RecvdPacketsTimestampsRangeVec recvdPacketsTimestampRanges;
 
   WriteAckFrameLog(
       const WriteAckFrame::AckBlockVec& ackBlocksIn,
-      std::chrono::microseconds ackDelayIn)
+      std::chrono::microseconds ackDelayIn,
-      : ackBlocks{ackBlocksIn}, ackDelay{ackDelayIn} {}
+      FrameType frameTypeIn = FrameType::ACK,
+      folly::Optional<std::chrono::microseconds> maybeLatestRecvdPacketTimeIn =
+          folly::none,
+      folly::Optional<PacketNum> maybeLatestRecvdPacketNumIn = folly::none,
+      RecvdPacketsTimestampsRangeVec recvdPacketsTimestampRangesIn = {})
+      : ackBlocks{ackBlocksIn},
+        ackDelay{ackDelayIn},
+        frameType{frameTypeIn},
+
+        maybeLatestRecvdPacketTime{maybeLatestRecvdPacketTimeIn},
+        maybeLatestRecvdPacketNum{maybeLatestRecvdPacketNumIn},
+        recvdPacketsTimestampRanges{recvdPacketsTimestampRangesIn} {}
   ~WriteAckFrameLog() override = default;
   FOLLY_NODISCARD folly::dynamic toDynamic() const override;
 };

quic/logging/test/QLoggerTest.cpp

@@ -721,6 +721,82 @@ TEST_F(QLoggerTest, AddingMultipleFrames) {
   EXPECT_EQ(expected, gotEvents);
 }
 
+TEST_F(QLoggerTest, AddingAckReceiveTimestampFrame) {
+  folly::dynamic expected = folly::parseJson(
+      R"([
+           [
+             "0",
+             "transport",
+             "packet_sent",
+             {
+               "frames": [
+                 {
+                   "ack_delay": 111,
+                   "acked_ranges": [
+                     [
+                       300,
+                       400
+                     ],
+                     [
+                       100,
+                       200
+                     ]
+                   ],
+                   "frame_type": "ack_receive_timestamps",
+                   "latest_recvd_packet_num": 400,
+                   "latest_recvd_packet_time": 100000,
+                   "timestamp_ranges": [
+                    [
+                      1,
+                      1,
+                      1,
+                      1
+                    ]
+                  ]
+                 },
+                 {
+                   "fin": true,
+                   "frame_type": "stream",
+                   "stream_id": "10",
+                   "length": 0,
+                   "offset": 0
+                 }
+               ],
+               "header": {
+                 "packet_number": 100,
+                 "packet_size": 10
+               },
+               "packet_type": "initial"
+             }
+           ]
+  ])");
+
+  FileQLogger q(VantagePoint::Client);
+  RegularQuicWritePacket packet =
+      createNewPacket(100, PacketNumberSpace::Initial);
+
+  WriteAckFrame ackFrame;
+  ackFrame.frameType = FrameType::ACK_RECEIVE_TIMESTAMPS;
+  ackFrame.ackDelay = 111us;
+  ackFrame.ackBlocks.emplace_back(300, 400);
+  ackFrame.ackBlocks.emplace_back(100, 200);
+  ackFrame.maybeLatestRecvdPacketNum = 400;
+  ackFrame.maybeLatestRecvdPacketTime = 100ms;
+  RecvdPacketsTimestampsRange recvdPacketsTimestampsRange = {
+      .gap = 1, .timestamp_delta_count = 1, .deltas = {1}};
+  ackFrame.recvdPacketsTimestampRanges = {recvdPacketsTimestampsRange};
+  WriteStreamFrame streamFrame(streamId, offset, len, fin);
+
+  packet.frames.emplace_back(std::move(ackFrame));
+  packet.frames.emplace_back(std::move(streamFrame));
+
+  q.addPacket(packet, 10);
+  folly::dynamic gotDynamic = q.toDynamic();
+  gotDynamic["traces"][0]["events"][0][0] = "0"; // hardcode reference time
+  folly::dynamic gotEvents = gotDynamic["traces"][0]["events"];
+  EXPECT_EQ(expected, gotEvents);
+}
+
 TEST_F(QLoggerTest, ConnectionCloseFollyDynamic) {
   folly::dynamic expected = folly::parseJson(
       R"([[
@@ -1654,4 +1730,150 @@ TEST_F(QLoggerTest, PrettyDatagram) {
   EXPECT_EQ(expected, parsed);
 }
 
+TEST_F(QLoggerTest, ReadAckReceiveTimestampsFrame) {
+  folly::dynamic expected = folly::parseJson(
+      R"({
+   "description": "Converted from file",
+   "qlog_version": "draft-00",
+   "title": "mvfst qlog",
+   "traces": [
+     {
+       "common_fields": {
+         "dcid": "0101",
+         "protocol_type": "QUIC_HTTP3",
+         "reference_time": "0",
+         "scid": ""
+       },
+       "configuration": {
+         "time_offset": 0,
+         "time_units": "us"
+       },
+       "description": "Generated qlog from connection",
+       "event_fields": [
+         "relative_time",
+         "category",
+         "event",
+         "data"
+       ],
+       "events": [
+         [
+           "31",
+           "transport",
+           "packet_received",
+           {
+             "frames": [
+               {
+                 "fin": true,
+                 "frame_type": "stream",
+                 "stream_id": "10",
+                 "length": 0,
+                 "offset": 0
+               },
+               {
+                   "ack_delay": 111,
+                   "acked_ranges": [
+                     [
+                       300,
+                       400
+                     ],
+                     [
+                       100,
+                       200
+                     ]
+                   ],
+                   "frame_type": "ack_receive_timestamps",
+                   "latest_recvd_packet_num": 400,
+                   "latest_recvd_packet_time": 100000,
+                   "timestamp_ranges": [
+                    [
+                      1,
+                      1,
+                      1,
+                      1
+                    ]
+                  ]
+                }
+             ],
+             "header": {
+               "packet_number": 1,
+               "packet_size": 10
+             },
+             "packet_type": "1RTT"
+           }
+         ]
+       ],
+       "title": "mvfst qlog from single connection",
+       "vantage_point": {
+         "name": "server",
+         "type": "server"
+       }
+     }
+   ],
+   "summary": {
+     "max_duration": 0,
+     "total_event_count": 1,
+     "trace_count": 1
+   }
+ })");
+
+  auto headerIn =
+      ShortHeader(ProtectionType::KeyPhaseZero, getTestConnectionId(1), 1);
+  RegularQuicPacket regularQuicPacket(std::move(headerIn));
+
+  ReadAckFrame ackFrame;
+  ackFrame.frameType = FrameType::ACK_RECEIVE_TIMESTAMPS;
+  ackFrame.ackDelay = 111us;
+  ackFrame.ackBlocks.emplace_back(300, 400);
+  ackFrame.ackBlocks.emplace_back(100, 200);
+  ackFrame.maybeLatestRecvdPacketNum = 400;
+  ackFrame.maybeLatestRecvdPacketTime = 100ms;
+  RecvdPacketsTimestampsRange recvdPacketsTimestampsRange = {
+      .gap = 1, .timestamp_delta_count = 1, .deltas = {1}};
+  ackFrame.recvdPacketsTimestampRanges = {recvdPacketsTimestampsRange};
+
+  ReadStreamFrame frame(streamId, offset, fin);
+
+  regularQuicPacket.frames.emplace_back(std::move(frame));
+  regularQuicPacket.frames.emplace_back(std::move(ackFrame));
+  auto dir = folly::fs::temp_directory_path().string();
+
+  auto* q = new FileQLogger(
+      VantagePoint::Server,
+      kHTTP3ProtocolType,
+      dir,
+      true /* prettyJson */,
+      true /* streaming */);
+
+  folly::Random::DefaultGenerator rng;
+  rng.seed(
+      std::chrono::high_resolution_clock::now().time_since_epoch().count());
+
+  q->setDcid(ConnectionId(std::vector<uint8_t>{
+      static_cast<uint8_t>(
+          folly::Random::rand32(0, std::numeric_limits<uint8_t>::max(), rng)),
+      static_cast<uint8_t>(
+          folly::Random::rand32(0, std::numeric_limits<uint8_t>::max(), rng)),
+      static_cast<uint8_t>(
+          folly::Random::rand32(0, std::numeric_limits<uint8_t>::max(), rng)),
+      static_cast<uint8_t>(
+          folly::Random::rand32(0, std::numeric_limits<uint8_t>::max(), rng)),
+  }));
+  q->addPacket(regularQuicPacket, 10);
+  EXPECT_EQ(q->logs.size(), 0);
+
+  std::string outputPath =
+      folly::to<std::string>(dir, "/", (q->dcid.value()).hex(), ".qlog");
+  delete q;
+
+  std::ifstream file(outputPath, std::ifstream::in);
+  std::string str(
+      (std::istreambuf_iterator<char>(file)), std::istreambuf_iterator<char>());
+  folly::dynamic parsed = folly::parseJson(str);
+
+  parsed["traces"][0]["events"][0][0] = "31"; // hardcode reference time
+  parsed["traces"][0]["common_fields"]["dcid"] = "0101";
+
+  EXPECT_EQ(expected, parsed);
+}
+
 } // namespace quic::test