Add logging to the QUIC write path.

Review URL: https://chromiumcodereview.appspot.com/17518002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@208098 0039d316-1c4b-4281-b951-d872f2087c98

net/base/net_log_event_type_list.h

@@ -1279,6 +1279,15 @@ EVENT_TYPE(QUIC_SESSION_CLOSE_ON_ERROR)
 //   }
 EVENT_TYPE(QUIC_SESSION_PACKET_RECEIVED)
 
+// Session sent a QUIC packet.
+//   {
+//     "encryption_level": <The EncryptionLevel of the packet>
+//     "packet_sequence_number": <The packet's full 64-bit sequence number,
+//                                as a base-10 string.>,
+//     "size": <The size of the packet in bytes>
+//   }
+EVENT_TYPE(QUIC_SESSION_PACKET_SENT)
+
 // Session received a QUIC packet header for a valid packet.
 //   {
 //     "guid": <The 64-bit GUID for this connection, as a base-10 string>,
@@ -1299,6 +1308,15 @@ EVENT_TYPE(QUIC_SESSION_PACKET_HEADER_RECEIVED)
 //   }
 EVENT_TYPE(QUIC_SESSION_STREAM_FRAME_RECEIVED)
 
+// Session sent a STREAM frame.
+//   {
+//     "stream_id": <The id of the stream which this data is for>,
+//     "fin": <True if this is the final data set by the peer on this stream>,
+//     "offset": <Offset in the byte stream where this data starts>,
+//     "length": <Length of the data in this frame>,
+//   }
+EVENT_TYPE(QUIC_SESSION_STREAM_FRAME_SENT)
+
 // Session received an ACK frame.
 //   {
 //     "sent_info": <Details of packet sent by the peer>
@@ -1317,14 +1335,40 @@ EVENT_TYPE(QUIC_SESSION_STREAM_FRAME_RECEIVED)
 //   }
 EVENT_TYPE(QUIC_SESSION_ACK_FRAME_RECEIVED)
 
+// Session sent an ACK frame.
+//   {
+//     "sent_info": <Details of packet sent by the peer>
+//       {
+//         "least_unacked": <Lowest sequence number of a packet sent by the peer
+//                           for which it has not received an ACK>,
+//       }
+//     "received_info": <Details of packet received by the peer>
+//       {
+//         "largest_observed": <The largest sequence number of a packet received
+//                               by (or inferred by) the peer>,
+//         "missing": <List of sequence numbers of packets lower than
+//                     largest_observed which have not been received by the
+//                     peer>,
+//       }
+//   }
+EVENT_TYPE(QUIC_SESSION_ACK_FRAME_SENT)
+
 // Session recevied a RST_STREAM frame.
 //   {
 //     "offset": <Offset in the byte stream which triggered the reset>,
-//     "error_code": <QuicErrorCode in the frame>,
+//     "quic_rst_stream_error": <QuicRstStreamErrorCode in the frame>,
 //     "details": <Human readable description>,
 //   }
 EVENT_TYPE(QUIC_SESSION_RST_STREAM_FRAME_RECEIVED)
 
+// Session sent a RST_STREAM frame.
+//   {
+//     "offset": <Offset in the byte stream which triggered the reset>,
+//     "quic_rst_stream_error": <QuicRstStreamErrorCode in the frame>,
+//     "details": <Human readable description>,
+//   }
+EVENT_TYPE(QUIC_SESSION_RST_STREAM_FRAME_SENT)
+
 // Session received a CONGESTION_FEEDBACK frame.
 //   {
 //     "type": <The specific type of feedback being provided>,
@@ -1346,13 +1390,41 @@ EVENT_TYPE(QUIC_SESSION_RST_STREAM_FRAME_RECEIVED)
 //   }
 EVENT_TYPE(QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED)
 
+// Session received a CONGESTION_FEEDBACK frame.
+//   {
+//     "type": <The specific type of feedback being provided>,
+//     Other per-feedback type details:
+//
+//     for InterArrival:
+//     "accumulated_number_of_lost_packets": <Total number of lost packets
+//                                            over the life of this session>,
+//     "received_packets": <List of strings of the form:
+//                          <sequence_number>@<receive_time_in_ms>>,
+//
+//     for FixRate:
+//     "bitrate_in_bytes_per_second": <The configured bytes per second>,
+//
+//     for TCP:
+//     "accumulated_number_of_lost_packets": <Total number of lost packets
+//                                            over the life of this session>,
+//     "receive_window": <Number of bytes in the receive window>,
+//   }
+EVENT_TYPE(QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT)
+
 // Session received a CONNECTION_CLOSE frame.
 //   {
-//     "error_code": <QuicErrorCode in the frame>,
+//     "quic_error": <QuicErrorCode in the frame>,
 //     "details": <Human readable description>,
 //   }
 EVENT_TYPE(QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED)
 
+// Session received a CONNECTION_CLOSE frame.
+//   {
+//     "quic_error": <QuicErrorCode in the frame>,
+//     "details": <Human readable description>,
+//   }
+EVENT_TYPE(QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT)
+
 // ------------------------------------------------------------------------
 // QuicHttpStream
 // ------------------------------------------------------------------------

net/quic/quic_connection.cc

@@ -87,7 +87,7 @@ QuicConnection::QuicConnection(QuicGuid guid,
       write_blocked_(false),
       debug_visitor_(NULL),
       packet_creator_(guid_, &framer_, random_generator_, is_server),
-      packet_generator_(this, &packet_creator_),
+      packet_generator_(this, NULL, &packet_creator_),
       idle_network_timeout_(
           QuicTime::Delta::FromSeconds(kDefaultInitialTimeoutSecs)),
       overall_connection_timeout_(QuicTime::Delta::Infinite()),
@@ -1111,7 +1111,7 @@ bool QuicConnection::WritePacket(EncryptionLevel level,
 
   int error;
   QuicTime now = clock_->Now();
-  if (helper_->WritePacketToWire(*encrypted, &error) == -1) {
+  if (WritePacketToWire(sequence_number, level, *encrypted, &error) == -1) {
     if (helper_->IsWriteBlocked(error)) {
       // TODO(satyashekhar): It might be more efficient (fewer system calls), if
       // all connections share this variable i.e this becomes a part of
@@ -1156,6 +1156,20 @@ bool QuicConnection::WritePacket(EncryptionLevel level,
   return true;
 }
 
+int QuicConnection::WritePacketToWire(QuicPacketSequenceNumber sequence_number,
+                                      EncryptionLevel level,
+                                      const QuicEncryptedPacket& packet,
+                                      int* error) {
+  int bytes_written = helper_->WritePacketToWire(packet, error);
+  if (debug_visitor_) {
+    // WritePacketToWire returned -1, then |error| will be populated with
+    // a NetErrorCode, which we want to pass along to the visitor.
+    debug_visitor_->OnPacketSent(sequence_number, level, packet,
+                                 bytes_written == -1 ? *error : bytes_written);
+  }
+  return bytes_written;
+}
+
 bool QuicConnection::OnSerializedPacket(
     const SerializedPacket& serialized_packet) {
   if (serialized_packet.retransmittable_frames != NULL) {

net/quic/quic_connection.h

@@ -82,10 +82,17 @@ class NET_EXPORT_PRIVATE QuicConnectionVisitorInterface {
 // Interface which gets callbacks from the QuicConnection at interesting
 // points.  Implementations must not mutate the state of the connection
 // as a result of these callbacks.
-class NET_EXPORT_PRIVATE QuicConnectionDebugVisitorInterface {
+class NET_EXPORT_PRIVATE QuicConnectionDebugVisitorInterface
+    : public QuicPacketGenerator::DebugDelegateInterface {
  public:
   virtual ~QuicConnectionDebugVisitorInterface() {}
 
+  // Called when a packet has been sent.
+  virtual void OnPacketSent(QuicPacketSequenceNumber sequence_number,
+                            EncryptionLevel level,
+                            const QuicEncryptedPacket& packet,
+                            int rv) = 0;
+
   // Called when a packet has been received, but before it is
   // validated or parsed.
   virtual void OnPacketReceived(const IPEndPoint& self_address,
@@ -306,6 +313,7 @@ class NET_EXPORT_PRIVATE QuicConnection
   }
   void set_debug_visitor(QuicConnectionDebugVisitorInterface* debug_visitor) {
     debug_visitor_ = debug_visitor;
+    packet_generator_.set_debug_delegate(debug_visitor);
   }
   const IPEndPoint& self_address() const { return self_address_; }
   const IPEndPoint& peer_address() const { return peer_address_; }
@@ -429,6 +437,11 @@ class NET_EXPORT_PRIVATE QuicConnection
                    HasRetransmittableData retransmittable,
                    Force force);
 
+  int WritePacketToWire(QuicPacketSequenceNumber sequence_number,
+                        EncryptionLevel level,
+                        const QuicEncryptedPacket& packet,
+                        int* error);
+
   // Make sure an ack we got from our peer is sane.
   bool ValidateAckFrame(const QuicAckFrame& incoming_ack);
 

net/quic/quic_connection_logger.cc

@@ -25,6 +25,23 @@ base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
   return dict;
 }
 
+base::Value* NetLogQuicPacketSentCallback(
+    QuicPacketSequenceNumber sequence_number,
+    EncryptionLevel level,
+    size_t packet_size,
+    int rv,
+    NetLog::LogLevel /* log_level */) {
+  base::DictionaryValue* dict = new base::DictionaryValue();
+  dict->SetInteger("encryption_level", level);
+  dict->SetString("packet_sequence_number",
+                  base::Uint64ToString(sequence_number));
+  dict->SetInteger("size", packet_size);
+  if (rv < 0) {
+    dict->SetInteger("net_error", rv);
+  }
+  return dict;
+}
+
 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
                                             NetLog::LogLevel /* log_level */) {
   base::DictionaryValue* dict = new base::DictionaryValue();
@@ -137,7 +154,56 @@ QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
 QuicConnectionLogger::~QuicConnectionLogger() {
 }
 
-  // QuicConnectionDebugVisitorInterface
+void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
+  switch (frame.type) {
+    case PADDING_FRAME:
+      break;
+    case STREAM_FRAME:
+      net_log_.AddEvent(
+          NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
+          base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
+      break;
+    case ACK_FRAME:
+      net_log_.AddEvent(
+          NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
+          base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
+      break;
+    case CONGESTION_FEEDBACK_FRAME:
+      net_log_.AddEvent(
+          NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
+          base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
+                     frame.congestion_feedback_frame));
+      break;
+    case RST_STREAM_FRAME:
+      net_log_.AddEvent(
+          NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
+          base::Bind(&NetLogQuicRstStreamFrameCallback,
+                     frame.rst_stream_frame));
+      break;
+    case CONNECTION_CLOSE_FRAME:
+      net_log_.AddEvent(
+          NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
+          base::Bind(&NetLogQuicConnectionCloseFrameCallback,
+                     frame.connection_close_frame));
+      break;
+    case GOAWAY_FRAME:
+      break;
+    default:
+      DCHECK(false) << "Illegal frame type: " << frame.type;
+  }
+}
+
+void QuicConnectionLogger::OnPacketSent(
+    QuicPacketSequenceNumber sequence_number,
+    EncryptionLevel level,
+    const QuicEncryptedPacket& packet,
+    int rv) {
+  net_log_.AddEvent(
+      NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
+      base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
+                 packet.length(), rv));
+}
+
 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
                                             const IPEndPoint& peer_address,
                                             const QuicEncryptedPacket& packet) {

net/quic/quic_connection_logger.h

@@ -20,7 +20,15 @@ class NET_EXPORT_PRIVATE QuicConnectionLogger
 
   virtual ~QuicConnectionLogger();
 
+  // QuicPacketGenerator::DebugDelegateInterface
+  virtual void OnFrameAddedToPacket(const QuicFrame& frame) OVERRIDE;
+
   // QuicConnectionDebugVisitorInterface
+  virtual void OnPacketSent(QuicPacketSequenceNumber sequence_number,
+                            EncryptionLevel level,
+                            const QuicEncryptedPacket& packet,
+                            int rv) OVERRIDE;
+
   virtual void OnPacketReceived(const IPEndPoint& self_address,
                                 const IPEndPoint& peer_address,
                                 const QuicEncryptedPacket& packet) OVERRIDE;

net/quic/quic_packet_generator.cc

@@ -13,8 +13,10 @@ using base::StringPiece;
 namespace net {
 
 QuicPacketGenerator::QuicPacketGenerator(DelegateInterface* delegate,
+                                         DebugDelegateInterface* debug_delegate,
                                          QuicPacketCreator* creator)
     : delegate_(delegate),
+      debug_delegate_(debug_delegate),
       packet_creator_(creator),
       should_flush_(true),
       should_send_ack_(false),
@@ -77,7 +79,7 @@ QuicConsumedData QuicPacketGenerator::ConsumeData(QuicStreamId id,
     QuicFrame frame;
     size_t bytes_consumed = packet_creator_->CreateStreamFrame(
         id, data, offset + total_bytes_consumed, fin, &frame);
-    bool success = packet_creator_->AddSavedFrame(frame);
+    bool success = AddFrame(frame);
     DCHECK(success);
 
     total_bytes_consumed += bytes_consumed;
@@ -158,7 +160,7 @@ bool QuicPacketGenerator::HasPendingFrames() const {
 bool QuicPacketGenerator::AddNextPendingFrame() {
   if (should_send_ack_) {
     pending_ack_frame_.reset(delegate_->CreateAckFrame());
-    if (!packet_creator_->AddSavedFrame(QuicFrame(pending_ack_frame_.get()))) {
+    if (!AddFrame(QuicFrame(pending_ack_frame_.get()))) {
       // packet was full
       return false;
     }
@@ -168,8 +170,7 @@ bool QuicPacketGenerator::AddNextPendingFrame() {
 
   if (should_send_feedback_) {
     pending_feedback_frame_.reset(delegate_->CreateFeedbackFrame());
-    if (!packet_creator_->AddSavedFrame(QuicFrame(
-            pending_feedback_frame_.get()))) {
+    if (!AddFrame(QuicFrame(pending_feedback_frame_.get()))) {
       // packet was full
       return false;
     }
@@ -178,7 +179,7 @@ bool QuicPacketGenerator::AddNextPendingFrame() {
   }
 
   DCHECK(!queued_control_frames_.empty());
-  if (!packet_creator_->AddSavedFrame(queued_control_frames_.back())) {
+  if (!AddFrame(queued_control_frames_.back())) {
     // packet was full
     return false;
   }
@@ -186,6 +187,14 @@ bool QuicPacketGenerator::AddNextPendingFrame() {
   return true;
 }
 
+bool QuicPacketGenerator::AddFrame(const QuicFrame& frame) {
+  bool success = packet_creator_->AddSavedFrame(frame);
+  if (success && debug_delegate_) {
+    debug_delegate_->OnFrameAddedToPacket(frame);
+  }
+  return success;
+}
+
 void QuicPacketGenerator::SerializeAndSendPacket() {
   SerializedPacket serialized_packet = packet_creator_->SerializePacket();
   DCHECK(serialized_packet.packet);

net/quic/quic_packet_generator.h

@@ -70,7 +70,19 @@ class NET_EXPORT_PRIVATE QuicPacketGenerator {
     virtual bool OnSerializedPacket(const SerializedPacket& packet) = 0;
   };
 
+  // Interface which gets callbacks from the QuicPacketGenerator at interesting
+  // points.  Implementations must not mutate the state of the generator
+  // as a result of these callbacks.
+  class NET_EXPORT_PRIVATE DebugDelegateInterface {
+   public:
+    virtual ~DebugDelegateInterface() {}
+
+    // Called when a frame has been added to the current packet.
+    virtual void OnFrameAddedToPacket(const QuicFrame& frame) = 0;
+  };
+
   QuicPacketGenerator(DelegateInterface* delegate,
+                      DebugDelegateInterface* debug_delegate,
                       QuicPacketCreator* creator);
 
   virtual ~QuicPacketGenerator();
@@ -89,14 +101,21 @@ class NET_EXPORT_PRIVATE QuicPacketGenerator {
 
   bool HasQueuedFrames() const;
 
+  void set_debug_delegate(DebugDelegateInterface* debug_delegate) {
+    debug_delegate_ = debug_delegate;
+  }
+
  private:
   void SendQueuedFrames();
 
   bool HasPendingFrames() const;
   bool AddNextPendingFrame();
+
+  bool AddFrame(const QuicFrame& frame);
   void SerializeAndSendPacket();
 
   DelegateInterface* delegate_;
+  DebugDelegateInterface* debug_delegate_;
 
   QuicPacketCreator* packet_creator_;
   QuicFrames queued_control_frames_;

net/quic/quic_packet_generator_test.cc

@@ -79,7 +79,7 @@ class QuicPacketGeneratorTest : public ::testing::Test {
   QuicPacketGeneratorTest()
       : framer_(kQuicVersion1, QuicTime::Zero(), false),
         creator_(42, &framer_, &random_, false),
-        generator_(&delegate_, &creator_),
+        generator_(&delegate_, NULL, &creator_),
         packet_(0, NULL, 0, NULL),
         packet2_(0, NULL, 0, NULL),
         packet3_(0, NULL, 0, NULL),