You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by ma...@apache.org on 2018/05/31 05:26:54 UTC

[trafficserver] 02/03: Print dcid and scid in debug log to identify quic connection

This is an automated email from the ASF dual-hosted git repository.

masaori pushed a commit to branch quic-latest
in repository https://gitbox.apache.org/repos/asf/trafficserver.git

commit 976cec2ac7fc7932a0890ab8decdd532a7c1f3b5
Author: Masaori Koshiba <ma...@apache.org>
AuthorDate: Tue May 29 14:05:41 2018 +0900

    Print dcid and scid in debug log to identify quic connection
    
    Only change logs in QUICNetVConnection. Other components will be fixed.
---
 iocore/net/P_QUICNetVConnection.h | 16 ++++++++--
 iocore/net/QUICNetVConnection.cc  | 64 ++++++++++++++++++++++++++++-----------
 iocore/net/quic/Mock.h            |  6 ++++
 iocore/net/quic/QUICConnection.h  |  1 +
 iocore/net/quic/QUICTypes.cc      |  6 ++++
 iocore/net/quic/QUICTypes.h       |  1 +
 6 files changed, 73 insertions(+), 21 deletions(-)

diff --git a/iocore/net/P_QUICNetVConnection.h b/iocore/net/P_QUICNetVConnection.h
index 94f6ccf..3398aa6 100644
--- a/iocore/net/P_QUICNetVConnection.h
+++ b/iocore/net/P_QUICNetVConnection.h
@@ -74,6 +74,9 @@
 
 #define QUIC_OP_HANDSHAKE 0x16
 
+// Size of connection ids for debug log : e.g. aaaaaaaa-bbbbbbbb\0
+static constexpr size_t MAX_CIDS_SIZE = 8 + 1 + 8 + 1;
+
 // class QUICNextProtocolSet;
 // struct QUICCertLookup;
 
@@ -195,6 +198,7 @@ public:
   QUICConnectionId peer_connection_id() const override;
   QUICConnectionId original_connection_id() const override;
   QUICConnectionId connection_id() const override;
+  std::string_view cids() const override;
   const QUICFiveTuple five_tuple() const override;
   uint32_t maximum_quic_packet_size() const override;
   uint32_t minimum_quic_packet_size() override;
@@ -228,11 +232,14 @@ private:
   QUICPacketType _last_received_packet_type = QUICPacketType::UNINITIALIZED;
   std::random_device _rnd;
 
-  QUICConnectionId _peer_quic_connection_id;
-  QUICConnectionId _original_quic_connection_id;
-  QUICConnectionId _quic_connection_id;
+  QUICConnectionId _peer_quic_connection_id;     // dst cid
+  QUICConnectionId _original_quic_connection_id; // dst cid of initial packet from client
+  QUICConnectionId _quic_connection_id;          // src cid
   QUICFiveTuple _five_tuple;
 
+  char _cids_data[MAX_CIDS_SIZE] = {0};
+  std::string_view _cids;
+
   UDPConnection *_udp_con            = nullptr;
   QUICPacketHandler *_packet_handler = nullptr;
   QUICPacketFactory _packet_factory;
@@ -332,6 +339,9 @@ private:
 
   void _handle_idle_timeout();
 
+  void _update_cids();
+  void _update_peer_cid(const QUICConnectionId &new_cid);
+
   QUICPacketUPtr _the_final_packet = QUICPacketFactory::create_null_packet();
   QUICStatelessResetToken _reset_token;
 
diff --git a/iocore/net/QUICNetVConnection.cc b/iocore/net/QUICNetVConnection.cc
index 8126bac..bd216a7 100644
--- a/iocore/net/QUICNetVConnection.cc
+++ b/iocore/net/QUICNetVConnection.cc
@@ -42,13 +42,15 @@
 #define STATE_FROM_VIO(_x) ((NetState *)(((char *)(_x)) - STATE_VIO_OFFSET))
 #define STATE_VIO_OFFSET ((uintptr_t) & ((NetState *)0)->vio)
 
-#define QUICConDebug(fmt, ...) Debug("quic_net", "[%" PRIx64 "] " fmt, this->_peer_quic_connection_id.l64(), ##__VA_ARGS__)
+#define QUICConDebug(fmt, ...) Debug("quic_net", "[%s] " fmt, this->cids().data(), ##__VA_ARGS__)
 
-#define QUICConVDebug(fmt, ...) Debug("v_quic_net", "[%" PRIx64 "] " fmt, this->_peer_quic_connection_id.l64(), ##__VA_ARGS__)
+#define QUICConVDebug(fmt, ...) Debug("v_quic_net", "[%s] " fmt, this->cids().data(), ##__VA_ARGS__)
 
-#define QUICError(fmt, ...)                                                                     \
-  Debug("quic_net", "[%" PRIx64 "] " fmt, this->_peer_quic_connection_id.l64(), ##__VA_ARGS__); \
-  Error("quic_net [%" PRIx64 "] " fmt, this->_peer_quic_connection_id.l64(), ##__VA_ARGS__)
+#define QUICFCDebug(fmt, ...) Debug("quic_flow_ctrl", "[%s] " fmt, this->cids().data(), ##__VA_ARGS__)
+
+#define QUICError(fmt, ...)                                           \
+  Debug("quic_net", "[%s] " fmt, this->cids().data(), ##__VA_ARGS__); \
+  Error("quic_net [%s] " fmt, this->cids().data(), ##__VA_ARGS__)
 
 static constexpr uint32_t IPV4_HEADER_SIZE            = 20;
 static constexpr uint32_t IPV6_HEADER_SIZE            = 40;
@@ -84,8 +86,10 @@ QUICNetVConnection::init(QUICConnectionId peer_cid, QUICConnectionId original_ci
     this->_ctable->insert(this->_original_quic_connection_id, this);
   }
 
-  QUICConDebug("Connection ID %" PRIx64 " has been changed to %" PRIx64, this->_original_quic_connection_id.l64(),
-               this->_quic_connection_id.l64());
+  this->_update_cids();
+
+  // TODO: print full cids
+  QUICConDebug("dcid=%08" PRIx32 " scid=%08" PRIx32, this->_peer_quic_connection_id.h32(), this->_quic_connection_id.h32());
 }
 
 bool
@@ -339,6 +343,12 @@ QUICNetVConnection::connection_id() const
   return this->_quic_connection_id;
 }
 
+std::string_view
+QUICNetVConnection::cids() const
+{
+  return this->_cids;
+}
+
 const QUICFiveTuple
 QUICNetVConnection::five_tuple() const
 {
@@ -457,8 +467,8 @@ QUICNetVConnection::handle_frame(std::shared_ptr<const QUICFrame> frame)
   switch (frame->type()) {
   case QUICFrameType::MAX_DATA:
     this->_remote_flow_controller->forward_limit(std::static_pointer_cast<const QUICMaxDataFrame>(frame)->maximum_data());
-    Debug("quic_flow_ctrl", "Connection [%" PRIx64 "] [REMOTE] %" PRIu64 "/%" PRIu64, this->_peer_quic_connection_id.l64(),
-          this->_remote_flow_controller->current_offset(), this->_remote_flow_controller->current_limit());
+    QUICFCDebug("[REMOTE] %" PRIu64 "/%" PRIu64, this->_remote_flow_controller->current_offset(),
+                this->_remote_flow_controller->current_limit());
     this->_schedule_packet_write_ready();
 
     break;
@@ -1247,8 +1257,8 @@ QUICNetVConnection::_packetize_frames()
     ++frame_count;
     if (frame->type() == QUICFrameType::STREAM) {
       int ret = this->_remote_flow_controller->update(this->_stream_manager->total_offset_sent());
-      Debug("quic_flow_ctrl", "Connection [%" PRIx64 "] [REMOTE] %" PRIu64 "/%" PRIu64, this->_peer_quic_connection_id.l64(),
-            this->_remote_flow_controller->current_offset(), this->_remote_flow_controller->current_limit());
+      QUICFCDebug("[REMOTE] %" PRIu64 "/%" PRIu64, this->_remote_flow_controller->current_offset(),
+                  this->_remote_flow_controller->current_limit());
       ink_assert(ret == 0);
     }
     this->_store_frame(buf, len, retransmittable, current_packet_type, std::move(frame));
@@ -1319,8 +1329,8 @@ QUICNetVConnection::_recv_and_ack(QUICPacketUPtr packet)
   }
 
   int ret = this->_local_flow_controller->update(this->_stream_manager->total_offset_received());
-  Debug("quic_flow_ctrl", "Connection [%" PRIx64 "] [LOCAL] %" PRIu64 "/%" PRIu64, this->_peer_quic_connection_id.l64(),
-        this->_local_flow_controller->current_offset(), this->_local_flow_controller->current_limit());
+  QUICFCDebug("[LOCAL] %" PRIu64 "/%" PRIu64, this->_local_flow_controller->current_offset(),
+              this->_local_flow_controller->current_limit());
   if (ret != 0) {
     return QUICErrorUPtr(new QUICConnectionError(QUICTransErrorCode::FLOW_CONTROL_ERROR));
   }
@@ -1410,10 +1420,10 @@ QUICNetVConnection::_init_flow_control_params(const std::shared_ptr<const QUICTr
 
   this->_local_flow_controller->set_limit(local_initial_max_data);
   this->_remote_flow_controller->set_limit(remote_initial_max_data);
-  Debug("quic_flow_ctrl", "Connection [%" PRIx64 "] [LOCAL] %" PRIu64 "/%" PRIu64, this->_peer_quic_connection_id.l64(),
-        this->_local_flow_controller->current_offset(), this->_local_flow_controller->current_limit());
-  Debug("quic_flow_ctrl", "Connection [%" PRIx64 "] [REMOTE] %" PRIu64 "/%" PRIu64, this->_peer_quic_connection_id.l64(),
-        this->_remote_flow_controller->current_offset(), this->_remote_flow_controller->current_limit());
+  QUICFCDebug("[LOCAL] %" PRIu64 "/%" PRIu64, this->_local_flow_controller->current_offset(),
+              this->_local_flow_controller->current_limit());
+  QUICFCDebug("[REMOTE] %" PRIu64 "/%" PRIu64, this->_remote_flow_controller->current_offset(),
+              this->_remote_flow_controller->current_limit());
 }
 
 void
@@ -1451,7 +1461,7 @@ QUICNetVConnection::_dequeue_recv_packet(QUICPacketCreationResult &result)
       // FIXME src connection id could be zero ? if so, check packet header type.
       if (src_cid != QUICConnectionId::ZERO()) {
         if (this->_peer_quic_connection_id != src_cid) {
-          this->_peer_quic_connection_id = src_cid;
+          this->_update_peer_cid(src_cid);
         }
       }
     }
@@ -1752,3 +1762,21 @@ QUICNetVConnection::_validate_new_path()
   ink_hrtime rto = this->_loss_detector->current_rto_period();
   this->_schedule_path_validation_timeout(3 * rto);
 }
+
+void
+QUICNetVConnection::_update_cids()
+{
+  snprintf(this->_cids_data, sizeof(this->_cids_data), "%08" PRIx32 "-%08" PRIx32 "", this->_peer_quic_connection_id.h32(),
+           this->_quic_connection_id.h32());
+
+  this->_cids = {this->_cids_data, sizeof(this->_cids_data)};
+}
+
+void
+QUICNetVConnection::_update_peer_cid(const QUICConnectionId &new_cid)
+{
+  QUICConDebug("dcid: %08" PRIx32 " -> %08" PRIx32, this->_peer_quic_connection_id.h32(), new_cid.h32());
+
+  this->_peer_quic_connection_id = new_cid;
+  this->_update_cids();
+}
diff --git a/iocore/net/quic/Mock.h b/iocore/net/quic/Mock.h
index b713554..761e96f 100644
--- a/iocore/net/quic/Mock.h
+++ b/iocore/net/quic/Mock.h
@@ -169,6 +169,12 @@ public:
     return QUICFiveTuple();
   }
 
+  std::string_view
+  cids() const override
+  {
+    return std::string_view("00000000-00000000"sv);
+  }
+
   uint32_t
   transmit_packet(QUICPacketUPtr packet) override
   {
diff --git a/iocore/net/quic/QUICConnection.h b/iocore/net/quic/QUICConnection.h
index 1f7cd8f..2b4b5e1 100644
--- a/iocore/net/quic/QUICConnection.h
+++ b/iocore/net/quic/QUICConnection.h
@@ -39,6 +39,7 @@ public:
   virtual QUICConnectionId peer_connection_id() const     = 0;
   virtual QUICConnectionId original_connection_id() const = 0;
   virtual QUICConnectionId connection_id() const          = 0;
+  virtual std::string_view cids() const                   = 0;
   virtual const QUICFiveTuple five_tuple() const          = 0;
 
   /*
diff --git a/iocore/net/quic/QUICTypes.cc b/iocore/net/quic/QUICTypes.cc
index 33a43e2..be89426 100644
--- a/iocore/net/quic/QUICTypes.cc
+++ b/iocore/net/quic/QUICTypes.cc
@@ -285,3 +285,9 @@ QUICConnectionId::l64() const
   }
   return v;
 }
+
+uint32_t
+QUICConnectionId::h32() const
+{
+  return static_cast<uint32_t>(QUICIntUtil::read_nbytes_as_uint(this->_id, 4));
+}
diff --git a/iocore/net/quic/QUICTypes.h b/iocore/net/quic/QUICTypes.h
index abc8ea1..7b26777 100644
--- a/iocore/net/quic/QUICTypes.h
+++ b/iocore/net/quic/QUICTypes.h
@@ -245,6 +245,7 @@ public:
    * This is just for debugging.
    */
   uint64_t l64() const;
+  uint32_t h32() const;
 
   uint8_t length() const;
   bool is_zero() const;

-- 
To stop receiving notification emails like this one, please contact
masaori@apache.org.