/* * Copyright (c) Facebook, Inc. and its affiliates. * * This source code is licensed under the MIT license found in the * LICENSE file in the root directory of this source tree. * */ #include #include #include namespace quic { void FileQLogger::addPacket( const RegularQuicPacket& regularPacket, uint64_t packetSize) { logs.push_back(createPacketEvent(regularPacket, packetSize)); } void FileQLogger::addPacket( const RegularQuicWritePacket& writePacket, uint64_t packetSize) { logs.push_back(createPacketEvent(writePacket, packetSize)); } void FileQLogger::addPacket( const VersionNegotiationPacket& versionPacket, uint64_t packetSize, bool isPacketRecvd) { logs.push_back(createPacketEvent(versionPacket, packetSize, isPacketRecvd)); } void FileQLogger::addConnectionClose( std::string error, std::string reason, bool drainConnection, bool sendCloseImmediately) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( std::move(error), std::move(reason), drainConnection, sendCloseImmediately, refTime)); } void FileQLogger::addTransportSummary( uint64_t totalBytesSent, uint64_t totalBytesRecvd, uint64_t sumCurWriteOffset, uint64_t sumMaxObservedOffset, uint64_t sumCurStreamBufferLen, uint64_t totalBytesRetransmitted, uint64_t totalStreamBytesCloned, uint64_t totalBytesCloned, uint64_t totalCryptoDataWritten, uint64_t totalCryptoDataRecvd) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( totalBytesSent, totalBytesRecvd, sumCurWriteOffset, sumMaxObservedOffset, sumCurStreamBufferLen, totalBytesRetransmitted, totalStreamBytesCloned, totalBytesCloned, totalCryptoDataWritten, totalCryptoDataRecvd, refTime)); } void FileQLogger::addCongestionMetricUpdate( uint64_t bytesInFlight, uint64_t currentCwnd, std::string congestionEvent, std::string state, std::string recoveryState) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( bytesInFlight, currentCwnd, std::move(congestionEvent), std::move(state), std::move(recoveryState), refTime)); } void FileQLogger::addBandwidthEstUpdate( uint64_t bytes, std::chrono::microseconds interval) { logs.push_back(std::make_unique( bytes, interval, std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint))); } void FileQLogger::addAppLimitedUpdate() { logs.push_back(std::make_unique( true, std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint))); } void FileQLogger::addAppUnlimitedUpdate() { logs.push_back(std::make_unique( false, std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint))); } void FileQLogger::addPacingMetricUpdate( uint64_t pacingBurstSizeIn, std::chrono::microseconds pacingIntervalIn) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( pacingBurstSizeIn, pacingIntervalIn, refTime)); } void FileQLogger::addPacingObservation( std::string actual, std::string expect, std::string conclusion) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( std::move(actual), std::move(expect), std::move(conclusion), refTime)); } void FileQLogger::addAppIdleUpdate(std::string idleEvent, bool idle) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( std::move(idleEvent), idle, refTime)); } void FileQLogger::addPacketDrop(size_t packetSize, std::string dropReason) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( packetSize, std::move(dropReason), refTime)); } void FileQLogger::addDatagramReceived(uint64_t dataLen) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back( std::make_unique(dataLen, refTime)); } void FileQLogger::addLossAlarm( PacketNum largestSent, uint64_t alarmCount, uint64_t outstandingPackets, std::string type) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( largestSent, alarmCount, outstandingPackets, std::move(type), refTime)); } void FileQLogger::addPacketsLost( PacketNum largestLostPacketNum, uint64_t lostBytes, uint64_t lostPackets) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( largestLostPacketNum, lostBytes, lostPackets, refTime)); } void FileQLogger::addTransportStateUpdate(std::string update) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( std::move(update), refTime)); } void FileQLogger::addPacketBuffered( PacketNum packetNum, ProtectionType protectionType, uint64_t packetSize) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( packetNum, protectionType, packetSize, refTime)); } void FileQLogger::addPacketAck( PacketNumberSpace packetNumSpace, PacketNum packetNum) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( packetNumSpace, packetNum, refTime)); } void FileQLogger::addMetricUpdate( std::chrono::microseconds latestRtt, std::chrono::microseconds mrtt, std::chrono::microseconds srtt, std::chrono::microseconds ackDelay) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( latestRtt, mrtt, srtt, ackDelay, refTime)); } folly::dynamic FileQLogger::toDynamic() const { folly::dynamic dynamicObj = folly::dynamic::object; dynamicObj[kQLogVersionField] = kQLogVersion; dynamicObj[kQLogTitleField] = kQLogTitle; dynamicObj[kQLogDescriptionField] = kQLogDescription; folly::dynamic summaryObj = folly::dynamic::object; summaryObj[kQLogTraceCountField] = 1; // hardcoded, we only support 1 trace right now // max duration is calculated like this: // if there is <= 1 event, max_duration is 0 // otherwise, it is the (time of the last event - time of the first event) summaryObj["max_duration"] = (logs.size() == 0) ? 0 : (logs.back()->refTime - logs[0]->refTime).count(); summaryObj["max_outgoing_loss_rate"] = ""; summaryObj["total_event_count"] = logs.size(); dynamicObj["summary"] = summaryObj; dynamicObj["traces"] = folly::dynamic::array(); folly::dynamic dynamicTrace = folly::dynamic::object; dynamicTrace["vantage_point"] = folly::dynamic::object("type", vantagePointString(vantagePoint))( "name", vantagePointString(vantagePoint)); dynamicTrace["title"] = kQLogTraceTitle; dynamicTrace["description"] = kQLogTraceDescription; dynamicTrace["configuration"] = folly::dynamic::object("time_offset", 0)("time_units", kQLogTimeUnits); std::string dcidStr = dcid.hasValue() ? dcid.value().hex() : ""; std::string scidStr = scid.hasValue() ? scid.value().hex() : ""; folly::dynamic commonFieldsObj = folly::dynamic::object; commonFieldsObj["reference_time"] = "0"; commonFieldsObj["dcid"] = dcidStr; commonFieldsObj["scid"] = scidStr; commonFieldsObj["protocol_type"] = protocolType; dynamicTrace["common_fields"] = std::move(commonFieldsObj); // convert stored logs into folly::Dynamic event array auto events = folly::dynamic::array(); for (auto& event : logs) { events.push_back(event->toDynamic()); } dynamicTrace["events"] = events; dynamicTrace["event_fields"] = folly::dynamic::array( "relative_time", "CATEGORY", "EVENT_TYPE", "TRIGGER", "DATA"); dynamicObj["traces"].push_back(dynamicTrace); return dynamicObj; } void FileQLogger::addStreamStateUpdate( quic::StreamId id, std::string update, folly::Optional timeSinceStreamCreation) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( id, std::move(update), std::move(timeSinceStreamCreation), vantagePoint, refTime)); } void FileQLogger::addConnectionMigrationUpdate(bool intentionalMigration) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( intentionalMigration, vantagePoint, refTime)); } void FileQLogger::addPathValidationEvent(bool success) { auto refTime = std::chrono::duration_cast( std::chrono::steady_clock::now() - refTimePoint); logs.push_back(std::make_unique( success, vantagePoint, refTime)); } void FileQLogger::outputLogsToFile(const std::string& path, bool prettyJson) { if (!dcid.hasValue()) { LOG(ERROR) << "Error: No dcid found"; return; } std::string outputPath = folly::to(path, "/", (dcid.value()).hex(), ".qlog"); std::ofstream fileObj(outputPath); if (fileObj) { auto qLog = prettyJson ? folly::toPrettyJson(toDynamic()) : folly::toJson(toDynamic()); fileObj << qLog; } else { LOG(ERROR) << "Error: Can't write to provided path: " << path; } fileObj.close(); } } // namespace quic