diff --git a/quic/api/CMakeLists.txt b/quic/api/CMakeLists.txt index d7af4d6bc..efebf9b0d 100644 --- a/quic/api/CMakeLists.txt +++ b/quic/api/CMakeLists.txt @@ -38,6 +38,7 @@ add_dependencies( mvfst_happyeyeballs mvfst_looper mvfst_loss + mvfst_qlogger mvfst_state_functions mvfst_state_machine mvfst_state_pacing_functions @@ -61,6 +62,7 @@ target_link_libraries( mvfst_happyeyeballs mvfst_looper mvfst_loss + mvfst_qlogger mvfst_state_functions mvfst_state_machine mvfst_state_pacing_functions diff --git a/quic/api/QuicTransportBase.h b/quic/api/QuicTransportBase.h index 58fabaf06..e20cc066a 100644 --- a/quic/api/QuicTransportBase.h +++ b/quic/api/QuicTransportBase.h @@ -435,6 +435,10 @@ class QuicTransportBase : public QuicSocket { conn_->logger = std::move(logger); } + void setQLogger(std::shared_ptr qLogger) { + conn_->qLogger = std::move(qLogger); + } + virtual void cancelAllAppCallbacks( std::pair error) noexcept; diff --git a/quic/api/QuicTransportFunctions.cpp b/quic/api/QuicTransportFunctions.cpp index 17da7d4da..640090d5b 100644 --- a/quic/api/QuicTransportFunctions.cpp +++ b/quic/api/QuicTransportFunctions.cpp @@ -206,6 +206,9 @@ void updateConnection( VLOG(10) << nodeToString(conn.nodeType) << " sent packetNum=" << packetNum << " in space=" << packetNumberSpace << " size=" << encodedSize << " " << conn; + if (conn.qLogger) { + conn.qLogger->add(packet, encodedSize); + } for (const auto& frame : packet.frames) { folly::variant_match( frame, @@ -603,13 +606,13 @@ uint64_t writeQuicDataExceptCryptoStreamToSocket( uint64_t written = 0; if (connection.pendingEvents.numProbePackets) { auto probeScheduler = std::move(FrameScheduler::Builder( - connection, - fizz::EncryptionLevel::AppTraffic, - PacketNumberSpace::AppData, - "ProbeWithoutCrypto") - .streamFrames() - .streamRetransmissions()) - .build(); + connection, + fizz::EncryptionLevel::AppTraffic, + PacketNumberSpace::AppData, + "ProbeWithoutCrypto") + .streamFrames() + .streamRetransmissions()) + .build(); written = writeProbingDataToSocket( socket, connection, @@ -764,6 +767,9 @@ void writeCloseCommon( auto packetBuf = std::move(packet.header); packetBuf->prependChain(std::move(body)); auto packetSize = packetBuf->computeChainDataLength(); + if (connection.qLogger) { + connection.qLogger->add(packet.packet, packetSize); + } QUIC_TRACE( packet_sent, connection, diff --git a/quic/api/test/QuicTransportFunctionsTest.cpp b/quic/api/test/QuicTransportFunctionsTest.cpp index ea9b88eb2..bcbb8ade8 100644 --- a/quic/api/test/QuicTransportFunctionsTest.cpp +++ b/quic/api/test/QuicTransportFunctionsTest.cpp @@ -12,6 +12,8 @@ #include #include #include +#include +#include #include #include @@ -181,7 +183,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnection) { auto mockCongestionController = std::make_unique(); auto rawCongestionController = mockCongestionController.get(); conn->congestionController = std::move(mockCongestionController); - + conn->qLogger = std::make_shared(); // Builds a fake packet to test with. auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); @@ -210,6 +212,25 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnection) { .WillOnce(Return(true)); updateConnection( *conn, folly::none, packet.packet, TimePoint{}, getEncodedSize(packet)); + + // verify handshake packet is stored in QLogger + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + + EXPECT_EQ(qLogger->logs.size(), 1); + auto p1 = std::move(qLogger->logs[0]); + auto event1 = dynamic_cast(p1.get()); + EXPECT_EQ(event1->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event1->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event1->eventType, QLogEventType::PacketSent); + EXPECT_EQ(event1->frames.size(), 2); + // verify contents of writeStreamFrame in QLogger + auto frame = static_cast(event1->frames[0].get()); + EXPECT_EQ(frame->streamId, stream1->id); + EXPECT_EQ(frame->offset, 0); + EXPECT_EQ(frame->len, 5); + EXPECT_EQ(frame->fin, false); + EXPECT_EQ( conn->ackStates.initialAckState.nextPacketNum, currentNextInitialPacketNum); @@ -302,10 +323,18 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnection) { EXPECT_TRUE(eq(*IOBuf::copyBuffer("ats up"), *rt6.data.front())); EXPECT_EQ(rt6.offset, 6); EXPECT_EQ(rt6.eof, 1); + + // another handshake packet was sent + EXPECT_EQ(qLogger->logs.size(), 2); + auto p2 = std::move(qLogger->logs[1]); + auto event2 = dynamic_cast(p2.get()); + EXPECT_EQ(event2->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event2->frames.size(), 3); } TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionPacketSorting) { auto conn = createConn(); + conn->qLogger = std::make_shared(); conn->ackStates.initialAckState.nextPacketNum = 0; conn->ackStates.handshakeAckState.nextPacketNum = 1; conn->ackStates.appDataAckState.nextPacketNum = 2; @@ -331,21 +360,42 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionPacketSorting) { appDataPacket.packet, TimePoint{}, getEncodedSize(appDataPacket)); + // verify qLogger added correct logs + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + + EXPECT_EQ(3, qLogger->logs.size()); + auto l1 = std::move(qLogger->logs[0]); + auto l2 = std::move(qLogger->logs[1]); + auto l3 = std::move(qLogger->logs[2]); + auto event1 = dynamic_cast(l1.get()); + auto event2 = dynamic_cast(l2.get()); + auto event3 = dynamic_cast(l3.get()); + + EXPECT_EQ(event1->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event2->packetType, toString(LongHeader::Types::Initial)); + EXPECT_EQ(event3->packetType, toString(LongHeader::Types::ZeroRtt)); EXPECT_EQ(3, conn->outstandingPackets.size()); auto& firstHeader = conn->outstandingPackets.front().packet.header; - EXPECT_EQ(0, folly::variant_match(firstHeader, [](const auto& h) { - return h.getPacketSequenceNum(); - })); + auto firstPacketNum = folly::variant_match( + firstHeader, [](const auto& h) { return h.getPacketSequenceNum(); }); + EXPECT_EQ(0, firstPacketNum); + EXPECT_EQ(1, event1->packetNum); + EXPECT_EQ( PacketNumberSpace::Initial, folly::variant_match( firstHeader, [](const auto& h) { return h.getPacketNumberSpace(); })); auto& lastHeader = conn->outstandingPackets.back().packet.header; - EXPECT_EQ(2, folly::variant_match(lastHeader, [](const auto& h) { - return h.getPacketSequenceNum(); - })); + + auto lastPacketNum = folly::variant_match( + lastHeader, [](const auto& h) { return h.getPacketSequenceNum(); }); + + EXPECT_EQ(2, lastPacketNum); + EXPECT_EQ(2, event3->packetNum); + EXPECT_EQ( PacketNumberSpace::AppData, folly::variant_match( @@ -354,6 +404,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionPacketSorting) { TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionFinOnly) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); auto stream1 = conn->streamManager->createNextBidirectionalStream().value(); @@ -362,6 +413,25 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionFinOnly) { updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event->frames.size(), 1); + auto frame = static_cast(event->frames[0].get()); + EXPECT_EQ(frame->streamId, stream1->id); + EXPECT_EQ(frame->offset, 0); + EXPECT_EQ(frame->len, 0); + EXPECT_EQ(frame->fin, true); + EXPECT_EQ(stream1->retransmissionBuffer.size(), 1); auto& rt1 = stream1->retransmissionBuffer.front(); @@ -373,6 +443,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionFinOnly) { TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionAllBytesExceptFin) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); auto stream1 = conn->streamManager->createNextUnidirectionalStream().value(); @@ -385,6 +456,24 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionAllBytesExceptFin) { updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event->frames.size(), 1); + auto frame = static_cast(event->frames[0].get()); + EXPECT_EQ(frame->streamId, stream1->id); + EXPECT_EQ(frame->offset, 0); + EXPECT_EQ(frame->len, buf->computeChainDataLength()); + EXPECT_EQ(frame->fin, false); + EXPECT_EQ(stream1->currentWriteOffset, buf->computeChainDataLength()); EXPECT_EQ(stream1->retransmissionBuffer.size(), 1); @@ -398,6 +487,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionAllBytesExceptFin) { TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionEmptyAckWriteResult) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); // None of the largestAckScheduled should be changed. But since // buildEmptyPacket() builds a Handshake packet, we use handshakeAckState to @@ -406,6 +496,17 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionEmptyAckWriteResult) { conn->ackStates.handshakeAckState.largestAckScheduled; updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); + + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + EXPECT_EQ( currentPendingLargestAckScheduled, conn->ackStates.handshakeAckState.largestAckScheduled); @@ -413,6 +514,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionEmptyAckWriteResult) { TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionPureAckCounter) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto stream = conn->streamManager->createNextBidirectionalStream().value(); writeDataToQuicStream(*stream, nullptr, true); EXPECT_EQ(0, conn->outstandingHandshakePacketsCount); @@ -429,6 +531,17 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionPureAckCounter) { *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); EXPECT_EQ(1, conn->outstandingPureAckPacketsCount); + // verify QLogger contains correct packet and frame information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + EXPECT_EQ(event->frames.size(), 1); + auto nonHandshake = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); packetEncodedSize = nonHandshake.header ? nonHandshake.header->computeChainDataLength() : 0; @@ -446,11 +559,26 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionPureAckCounter) { updateConnection( *conn, folly::none, packet2.packet, TimePoint(), getEncodedSize(packet)); EXPECT_EQ(1, conn->outstandingPureAckPacketsCount); + + // verify QLogger contains correct packet information + EXPECT_EQ(2, qLogger->logs.size()); + auto p2 = std::move(qLogger->logs[1]); + auto event2 = dynamic_cast(p2.get()); + EXPECT_EQ(event2->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event2->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event2->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event2->frames.size(), 1); + auto frame = static_cast(event2->frames[0].get()); + EXPECT_EQ(frame->streamId, 1); + EXPECT_EQ(frame->errorCode, GenericApplicationErrorCode::UNKNOWN); + EXPECT_EQ(frame->offset, 0); } TEST_F(QuicTransportFunctionsTest, TestPaddingPureAckPacketIsStillPureAck) { auto conn = createConn(); - + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); auto packetEncodedSize = packet.header ? packet.header->computeChainDataLength() : 0; @@ -463,10 +591,22 @@ TEST_F(QuicTransportFunctionsTest, TestPaddingPureAckPacketIsStillPureAck) { updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); EXPECT_EQ(1, conn->outstandingPureAckPacketsCount); + + // verify QLogger contains correct packet and frames information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + EXPECT_EQ(event->frames.size(), 2); } TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionHandshakeCounter) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto stream = conn->streamManager->createNextBidirectionalStream().value(); writeDataToQuicStream(*stream, nullptr, true); EXPECT_EQ(0, conn->outstandingHandshakePacketsCount); @@ -481,6 +621,22 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionHandshakeCounter) { *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); EXPECT_EQ(1, conn->outstandingHandshakePacketsCount); + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p1 = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p1.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, packetEncodedSize); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event->frames.size(), 1); + auto frame = static_cast(event->frames[0].get()); + EXPECT_EQ(frame->offset, 0); + EXPECT_EQ(frame->len, 0); + auto nonHandshake = buildEmptyPacket(*conn, PacketNumberSpace::AppData); packetEncodedSize = nonHandshake.header ? nonHandshake.header->computeChainDataLength() : 0; @@ -497,11 +653,27 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionHandshakeCounter) { nonHandshake.packet, TimePoint(), getEncodedSize(packet)); + // verify QLogger contains correct packet information + EXPECT_EQ(2, qLogger->logs.size()); + auto p2 = std::move(qLogger->logs[1]); + auto event2 = dynamic_cast(p2.get()); + EXPECT_EQ(event2->packetType, toString(LongHeader::Types::ZeroRtt)); + EXPECT_EQ(event2->packetSize, packetEncodedSize); + EXPECT_EQ(event2->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event2->frames.size(), 1); + auto gotStreamFrame = static_cast(event2->frames[0].get()); + EXPECT_EQ(gotStreamFrame->streamId, stream1->id); + EXPECT_EQ(gotStreamFrame->offset, 0); + EXPECT_EQ(gotStreamFrame->len, 0); + EXPECT_EQ(gotStreamFrame->fin, true); EXPECT_EQ(1, conn->outstandingHandshakePacketsCount); } TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionForOneRttCryptoData) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto stream = conn->streamManager->createNextBidirectionalStream().value(); writeDataToQuicStream(*stream, nullptr, true); EXPECT_EQ(0, conn->outstandingHandshakePacketsCount); @@ -515,6 +687,23 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionForOneRttCryptoData) { packet.packet.frames.push_back(WriteCryptoFrame(0, 0)); updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); + + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, kShortHeaderPacketType); + EXPECT_EQ(event->packetSize, packetEncodedSize); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event->frames.size(), 1); + auto frame = static_cast(event->frames[0].get()); + EXPECT_EQ(frame->offset, 0); + EXPECT_EQ(frame->len, 0); + EXPECT_EQ(0, conn->outstandingHandshakePacketsCount); EXPECT_EQ(1, conn->outstandingPackets.size()); @@ -534,12 +723,30 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionForOneRttCryptoData) { nonHandshake.packet, TimePoint(), getEncodedSize(packet)); + + // verify QLogger contains correct packet information + EXPECT_EQ(2, qLogger->logs.size()); + auto p2 = std::move(qLogger->logs[1]); + auto event2 = dynamic_cast(p2.get()); + EXPECT_EQ(event2->packetType, toString(LongHeader::Types::ZeroRtt)); + EXPECT_EQ(event2->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event2->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(event2->frames.size(), 1); + auto frame2 = static_cast(event2->frames[0].get()); + EXPECT_EQ(frame2->streamId, stream1->id); + EXPECT_EQ(frame2->offset, 0); + EXPECT_EQ(frame2->len, 0); + EXPECT_EQ(frame2->fin, true); + EXPECT_EQ(0, conn->outstandingHandshakePacketsCount); EXPECT_EQ(2, conn->outstandingPackets.size()); } TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithPureAck) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); auto mockCongestionController = std::make_unique(); auto rawController = mockCongestionController.get(); @@ -555,10 +762,24 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithPureAck) { EXPECT_TRUE( getFirstOutstandingPacket(*conn, PacketNumberSpace::Handshake)->pureAck); EXPECT_EQ(0, conn->lossState.totalBytesAcked); + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + // verify QLogger contains correct packet information + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, getEncodedSize(packet)); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + // verify QLogger contains correct frame information + EXPECT_EQ(event->frames.size(), 1); + auto frame = static_cast(event->frames[0].get()); + EXPECT_EQ(frame->ackBlocks.size(), 1); } TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithBytesStats) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); conn->lossState.totalBytesSent = 13579; conn->lossState.totalBytesAcked = 8642; @@ -568,6 +789,17 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithBytesStats) { conn->lossState.totalBytesSentAtLastAck = 10000; conn->lossState.totalBytesAckedAtLastAck = 5000; updateConnection(*conn, folly::none, packet.packet, TimePoint(), 555); + + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto event = dynamic_cast(p.get()); + EXPECT_EQ(event->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(event->packetSize, 555); + EXPECT_EQ(event->eventType, QLogEventType::PacketSent); + EXPECT_EQ( 13579 + 555, getFirstOutstandingPacket(*conn, PacketNumberSpace::Handshake) @@ -594,6 +826,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithBytesStats) { TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithCloneResult) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto mockCongestionController = std::make_unique(); auto rawCongestionController = mockCongestionController.get(); conn->congestionController = std::move(mockCongestionController); @@ -605,7 +838,8 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithCloneResult) { MockClock::mockNow = [=]() { return thisMoment; }; RegularQuicWritePacket writePacket(std::move(shortHeader)); // Add a dummy frame into the packet so we don't treat it as pureAck - MaxDataFrame maxDataFrame(1000 + conn->flowControlState.advertisedMaxOffset); + auto maxDataAmt = 1000 + conn->flowControlState.advertisedMaxOffset; + MaxDataFrame maxDataFrame(maxDataAmt); conn->pendingEvents.connWindowUpdate = true; writePacket.frames.push_back(std::move(maxDataFrame)); PacketEvent event = 1; @@ -615,6 +849,20 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithCloneResult) { EXPECT_CALL(*rawCongestionController, onPacketSent(_)).Times(1); updateConnection( *conn, event, std::move(writePacket), MockClock::now(), 1500); + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto qLogEvent = dynamic_cast(p.get()); + EXPECT_EQ(qLogEvent->packetType, kShortHeaderPacketType); + EXPECT_EQ(qLogEvent->packetSize, 1500); + EXPECT_EQ(qLogEvent->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(qLogEvent->frames.size(), 1); + auto frame = static_cast(qLogEvent->frames[0].get()); + EXPECT_EQ(frame->maximumData, maxDataAmt); EXPECT_EQ( futureMoment, getLastOutstandingPacket(*conn, PacketNumberSpace::AppData)->time); @@ -630,6 +878,7 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionWithCloneResult) { TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionStreamWindowUpdate) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); auto packetNum = folly::variant_match( packet.packet.header, @@ -640,12 +889,30 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionStreamWindowUpdate) { packet.packet.frames.push_back(std::move(streamWindowUpdate)); updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); + + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto qLogEvent = dynamic_cast(p.get()); + EXPECT_EQ(qLogEvent->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(qLogEvent->packetSize, getEncodedSize(packet)); + EXPECT_EQ(qLogEvent->eventType, QLogEventType::PacketSent); + + // verify QLogger contains correct frame information + EXPECT_EQ(qLogEvent->frames.size(), 1); + auto frame = static_cast(qLogEvent->frames[0].get()); + EXPECT_EQ(frame->streamId, stream->id); + EXPECT_EQ(frame->maximumData, 0); + EXPECT_EQ(packetNum, *stream->latestMaxStreamDataPacket); EXPECT_FALSE(conn->latestMaxDataPacket.hasValue()); } TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionConnWindowUpdate) { auto conn = createConn(); + conn->qLogger = std::make_shared(); auto packet = buildEmptyPacket(*conn, PacketNumberSpace::Handshake); auto packetNum = folly::variant_match( packet.packet.header, @@ -656,6 +923,21 @@ TEST_F(QuicTransportFunctionsTest, TestUpdateConnectionConnWindowUpdate) { packet.packet.frames.push_back(std::move(connWindowUpdate)); updateConnection( *conn, folly::none, packet.packet, TimePoint(), getEncodedSize(packet)); + + // verify QLogger contains correct packet information + std::shared_ptr qLogger = + std::dynamic_pointer_cast(conn->qLogger); + EXPECT_EQ(1, qLogger->logs.size()); + auto p = std::move(qLogger->logs[0]); + auto qLogEvent = dynamic_cast(p.get()); + EXPECT_EQ(qLogEvent->packetType, toString(LongHeader::Types::Handshake)); + EXPECT_EQ(qLogEvent->packetSize, getEncodedSize(packet)); + EXPECT_EQ(qLogEvent->eventType, QLogEventType::PacketSent); + // verify QLogger contains correct frame information + EXPECT_EQ(qLogEvent->frames.size(), 1); + auto frame = static_cast(qLogEvent->frames[0].get()); + EXPECT_EQ(frame->maximumData, conn->flowControlState.advertisedMaxOffset); + EXPECT_FALSE(stream->latestMaxStreamDataPacket.hasValue()); EXPECT_EQ(packetNum, *conn->latestMaxDataPacket); } diff --git a/quic/client/CMakeLists.txt b/quic/client/CMakeLists.txt index 635d351e0..e67f552e9 100644 --- a/quic/client/CMakeLists.txt +++ b/quic/client/CMakeLists.txt @@ -27,6 +27,7 @@ add_dependencies( mvfst_flowcontrol mvfst_happyeyeballs mvfst_loss + mvfst_qlogger mvfst_state_ack_handler mvfst_state_pacing_functions mvfst_transport @@ -38,6 +39,7 @@ target_link_libraries( mvfst_flowcontrol mvfst_happyeyeballs mvfst_loss + mvfst_qlogger mvfst_state_ack_handler mvfst_state_pacing_functions mvfst_transport diff --git a/quic/client/QuicClientTransport.cpp b/quic/client/QuicClientTransport.cpp index 8b736266b..5a3c67e1c 100644 --- a/quic/client/QuicClientTransport.cpp +++ b/quic/client/QuicClientTransport.cpp @@ -214,6 +214,9 @@ void QuicClientTransport::processPacketData( protectionLevel == ProtectionType::KeyPhaseOne; auto& regularPacket = *regularOptional; + if (conn_->qLogger) { + conn_->qLogger->add(regularPacket, packetSize); + } if (!isProtectedPacket) { for (auto& quicFrame : regularPacket.frames) { auto isPadding = boost::get(&quicFrame); @@ -227,7 +230,6 @@ void QuicClientTransport::processPacketData( } } } - QUIC_TRACE(packet_recvd, *conn_, toString(pnSpace), packetNum, packetSize); // We got a packet that was not the version negotiation packet, that means diff --git a/quic/logging/CMakeLists.txt b/quic/logging/CMakeLists.txt index c53dc84b5..f62c66dce 100644 --- a/quic/logging/CMakeLists.txt +++ b/quic/logging/CMakeLists.txt @@ -3,6 +3,38 @@ # This source code is licensed under the MIT license found in the # LICENSE file in the root directory of this source tree. +add_library( + mvfst_qlogger STATIC + QLogger.cpp + QLoggerTypes.cpp + FileQLogger.cpp +) + +target_include_directories( + mvfst_qlogger PUBLIC + $ + $ +) + +target_compile_options( + mvfst_qlogger + PRIVATE + ${_QUIC_COMMON_COMPILE_OPTIONS} +) + +add_dependencies( + mvfst_qlogger + mvfst_codec_types + mvfst_state_machine +) + +target_link_libraries( + mvfst_qlogger PUBLIC + Folly::folly + ${LIBFIZZ_LIBRARY} + mvfst_codec_types +) + file( GLOB_RECURSE QUIC_API_HEADERS_TOINSTALL RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} @@ -14,4 +46,10 @@ foreach(header ${QUIC_API_HEADERS_TOINSTALL}) install(FILES ${header} DESTINATION include/quic/logging/${header_dir}) endforeach() +install( + TARGETS mvfst_qlogger + EXPORT mvfst-exports + DESTINATION lib +) + add_subdirectory(test) diff --git a/quic/logging/QLogger.cpp b/quic/logging/QLogger.cpp index 9ec52869c..92981cdf2 100644 --- a/quic/logging/QLogger.cpp +++ b/quic/logging/QLogger.cpp @@ -22,7 +22,7 @@ std::unique_ptr createPacketEvent( regularPacket.header, [](const auto& h) { return h.getPacketSequenceNum(); }); event->packetSize = packetSize; - event->eventType = EventType::PacketReceived; + event->eventType = QLogEventType::PacketReceived; event->packetType = folly::variant_match( regularPacket.header, [](const LongHeader& header) { return toString(header.getHeaderType()); }, @@ -143,7 +143,7 @@ std::unique_ptr createPacketEvent( writePacket.header, [](const auto& h) { return h.getPacketSequenceNum(); }); event->packetSize = packetSize; - event->eventType = EventType::PacketSent; + event->eventType = QLogEventType::PacketSent; event->packetType = folly::variant_match( writePacket.header, [](const LongHeader& header) { return toString(header.getHeaderType()); }, @@ -262,7 +262,7 @@ std::unique_ptr createPacketEvent( auto event = std::make_unique(); event->packetSize = packetSize; event->eventType = - isPacketRecvd ? EventType::PacketReceived : EventType::PacketSent; + isPacketRecvd ? QLogEventType::PacketReceived : QLogEventType::PacketSent; event->packetType = kVersionNegotiationPacketType.str(); event->versionLog = std::make_unique( VersionNegotiationLog(versionPacket.versions)); diff --git a/quic/logging/QLoggerTypes.cpp b/quic/logging/QLoggerTypes.cpp index 16c482f6f..0612c2c58 100644 --- a/quic/logging/QLoggerTypes.cpp +++ b/quic/logging/QLoggerTypes.cpp @@ -248,11 +248,11 @@ folly::dynamic QLogVersionNegotiationEvent::toDynamic() const { return d; } -std::string toString(EventType type) { +std::string toString(QLogEventType type) { switch (type) { - case EventType::PacketSent: + case QLogEventType::PacketSent: return "PACKET_SENT"; - case EventType::PacketReceived: + case QLogEventType::PacketReceived: return "PACKET_RECEIVED"; } LOG(WARNING) << "toString has unhandled QLog event type"; diff --git a/quic/logging/QLoggerTypes.h b/quic/logging/QLoggerTypes.h index 8aa578a0c..d2bedaa21 100644 --- a/quic/logging/QLoggerTypes.h +++ b/quic/logging/QLoggerTypes.h @@ -292,12 +292,12 @@ class VersionNegotiationLog { folly::dynamic toDynamic() const; }; -enum class EventType : uint32_t { +enum class QLogEventType : uint32_t { PacketReceived, PacketSent, }; -std::string toString(EventType type); +std::string toString(QLogEventType type); class QLogEvent { public: @@ -314,7 +314,7 @@ class QLogPacketEvent : public QLogEvent { std::string packetType; PacketNum packetNum{0}; uint64_t packetSize{0}; - EventType eventType; + QLogEventType eventType; folly::dynamic toDynamic() const override; }; @@ -326,11 +326,11 @@ class QLogVersionNegotiationEvent : public QLogEvent { std::unique_ptr versionLog; std::string packetType; uint64_t packetSize{0}; - EventType eventType; + QLogEventType eventType; folly::dynamic toDynamic() const override; }; -std::string toString(EventType type); +std::string toString(QLogEventType type); } // namespace quic diff --git a/quic/logging/test/QLoggerTest.cpp b/quic/logging/test/QLoggerTest.cpp index 412f3da38..e696369a4 100644 --- a/quic/logging/test/QLoggerTest.cpp +++ b/quic/logging/test/QLoggerTest.cpp @@ -41,24 +41,17 @@ TEST_F(QLoggerTest, TestRegularWritePacket) { EXPECT_EQ(gotObject.streamId, streamId); EXPECT_EQ(gotObject.offset, offset); EXPECT_EQ(gotObject.fin, fin); + EXPECT_EQ(gotEvent->eventType, QLogEventType::PacketSent); } TEST_F(QLoggerTest, TestRegularPacket) { - auto expected = folly::IOBuf::copyBuffer("hello"); - auto packet = createStreamPacket( - getTestConnectionId(0), - getTestConnectionId(1), - 1, - streamId, - *expected, - 0 /* cipherOverhead */, - 0 /* largestAcked */, - folly::none /* longHeaderOverride */, - fin, - folly::none /* shortHeaderOverride */, - offset); + auto headerIn = + ShortHeader(ProtectionType::KeyPhaseZero, getTestConnectionId(1), 1); + RegularQuicPacket regularQuicPacket(headerIn); + ReadStreamFrame frame(streamId, offset, fin); + + regularQuicPacket.frames.emplace_back(std::move(frame)); - auto regularQuicPacket = packet.packet; FileQLogger q; q.add(regularQuicPacket, 10); @@ -69,6 +62,7 @@ TEST_F(QLoggerTest, TestRegularPacket) { EXPECT_EQ(gotObject.streamId, streamId); EXPECT_EQ(gotObject.offset, offset); EXPECT_EQ(gotObject.fin, fin); + EXPECT_EQ(gotEvent->eventType, QLogEventType::PacketReceived); } TEST_F(QLoggerTest, TestVersionNegotiationPacket) { @@ -85,6 +79,57 @@ TEST_F(QLoggerTest, TestVersionNegotiationPacket) { } TEST_F(QLoggerTest, RegularPacketFollyDynamic) { + folly::dynamic expected = folly::parseJson( + R"({ + "traces": [ + {"event_fields":[ + "CATEGORY", + "EVENT_TYPE", + "TRIGGER", + "DATA" + ], + "events":[ + [ + "TRANSPORT", + "PACKET_RECEIVED", + "DEFAULT", + { + "packet_type": "1RTT", + "header":{ + "packet_number":1, + "packet_size":10 + }, + "frames":[ + {"frame_type":"STREAM", + "id":10, + "fin":true, + "length":0, + "offset":0 + } + ] + } + ] + ] + } + ] + })"); + + auto headerIn = + ShortHeader(ProtectionType::KeyPhaseZero, getTestConnectionId(1), 1); + RegularQuicPacket regularQuicPacket(headerIn); + ReadStreamFrame frame(streamId, offset, fin); + + regularQuicPacket.frames.emplace_back(std::move(frame)); + + FileQLogger q; + q.add(regularQuicPacket, 10); + + folly::dynamic gotDynamic = q.toDynamic(); + + EXPECT_EQ(expected, gotDynamic); +} + +TEST_F(QLoggerTest, RegularWritePacketFollyDynamic) { folly::dynamic expected = folly::parseJson( R"({ "traces": [ @@ -103,7 +148,8 @@ TEST_F(QLoggerTest, RegularPacketFollyDynamic) { "packet_type": "INITIAL", "header":{ "packet_number":10, - "packet_size":10}, + "packet_size":10 + }, "frames":[ {"frame_type":"STREAM", "id":10, diff --git a/quic/server/CMakeLists.txt b/quic/server/CMakeLists.txt index 533fa40bc..15b95d6be 100644 --- a/quic/server/CMakeLists.txt +++ b/quic/server/CMakeLists.txt @@ -35,6 +35,7 @@ add_dependencies( mvfst_codec mvfst_codec_types mvfst_handshake + mvfst_qlogger mvfst_transport ) @@ -46,6 +47,7 @@ target_link_libraries( mvfst_codec mvfst_codec_types mvfst_handshake + mvfst_qlogger mvfst_transport ) diff --git a/quic/server/state/ServerStateMachine.cpp b/quic/server/state/ServerStateMachine.cpp index bb03cc608..d94137d85 100644 --- a/quic/server/state/ServerStateMachine.cpp +++ b/quic/server/state/ServerStateMachine.cpp @@ -624,6 +624,9 @@ void onServerReadDataFromOpen( conn.serverConnIdParams->clientConnId = *conn.clientConnectionId; conn.readCodec->setServerConnectionId(*conn.serverConnectionId); } + if (conn.qLogger) { + conn.qLogger->add(regularPacket, packetSize); + } QUIC_TRACE(packet_recvd, conn, packetNum, packetSize); // We assume that the higher layer takes care of validating that the version // is supported. @@ -988,7 +991,9 @@ void onServerReadDataFromClosed( auto pnSpace = folly::variant_match( regularOptional->header, [](const auto& h) { return h.getPacketNumberSpace(); }); - + if (conn.qLogger) { + conn.qLogger->add(regularPacket, packetSize); + } QUIC_TRACE(packet_recvd, conn, packetNum, packetSize); bool isProtectedPacket = protectionLevel == ProtectionType::ZeroRtt || diff --git a/quic/state/StateData.h b/quic/state/StateData.h index d417eb2ac..0f57406ff 100644 --- a/quic/state/StateData.h +++ b/quic/state/StateData.h @@ -19,6 +19,7 @@ #include #include #include +#include #include #include #include @@ -573,6 +574,9 @@ struct QuicConnectionStateBase { // Logger for this connection. std::shared_ptr logger; + // QLogger for this connection + std::shared_ptr qLogger; + // Track stats for various server events QuicTransportStatsCallback* infoCallback{nullptr};