quic: more of the implementation, fixing bits

src/quic/data.cc

@@ -1,11 +1,14 @@
+#include <sys/socket.h>
 #if HAVE_OPENSSL && NODE_OPENSSL_HAS_QUIC
 
 #include "data.h"
 #include <env-inl.h>
 #include <memory_tracker-inl.h>
 #include <ngtcp2/ngtcp2.h>
 #include <node_sockaddr-inl.h>
+#include <string_bytes.h>
 #include <v8.h>
+#include "defs.h"
 #include "util.h"
 
 namespace node {
@@ -26,6 +29,25 @@ Path::Path(const SocketAddress& local, const SocketAddress& remote) {
   ngtcp2_addr_init(&this->remote, remote.data(), remote.length());
 }
 
+std::string Path::ToString() const {
+  DebugIndentScope indent;
+  auto prefix = indent.Prefix();
+
+  const sockaddr* local_in = reinterpret_cast<const sockaddr*>(local.addr);
+  auto local_addr = SocketAddress::GetAddress(local_in);
+  auto local_port = SocketAddress::GetPort(local_in);
+
+  const sockaddr* remote_in = reinterpret_cast<const sockaddr*>(remote.addr);
+  auto remote_addr = SocketAddress::GetAddress(remote_in);
+  auto remote_port = SocketAddress::GetPort(remote_in);
+
+  std::string res("{");
+  res += prefix + "local: " + local_addr + ":" + std::to_string(local_port);
+  res += prefix + "remote: " + remote_addr + ":" + std::to_string(remote_port);
+  res += indent.Close();
+  return res;
+}
+
 PathStorage::PathStorage() {
   ngtcp2_path_storage_zero(this);
 }

src/quic/data.h

@@ -1,5 +1,6 @@
 #pragma once
 
+#include <string>
 #if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
 #if HAVE_OPENSSL && NODE_OPENSSL_HAS_QUIC
 
@@ -17,6 +18,7 @@ namespace quic {
 struct Path final : public ngtcp2_path {
   Path(const SocketAddress& local, const SocketAddress& remote);
   inline operator ngtcp2_path*() { return this; }
+  std::string ToString() const;
 };
 
 struct PathStorage final : public ngtcp2_path_storage {

src/quic/endpoint.cc

@@ -1077,7 +1077,7 @@ void Endpoint::Receive(const uv_buf_t& buf,
     // as a server, then we cannot accept the initial packet.
     if (is_closed() || is_closing() || !is_listening()) return;
 
-    Debug(this, "Trying to create new session for initial packet");
+    Debug(this, "Trying to create new session for %s", config.dcid);
     auto session = Session::Create(this, config);
     if (session) {
       receive(session.get(),
@@ -1096,7 +1096,7 @@ void Endpoint::Receive(const uv_buf_t& buf,
                                        const SocketAddress& local_address,
                                        const SocketAddress& remote_address) {
     // Conditionally accept an initial packet to create a new session.
-    Debug(this, "Trying to accept initial packet");
+    Debug(this, "Trying to accept initial packet for %s from %s", dcid, remote_address);
 
     // If we're not listening as a server, do not accept an initial packet.
     if (state_->listening == 0) return;
@@ -1111,7 +1111,7 @@ void Endpoint::Receive(const uv_buf_t& buf,
       // successful, or an error code if it was not. Currently there's only one
       // documented error code (NGTCP2_ERR_INVALID_ARGUMENT) but we'll handle
       // any error here the same -- by ignoring the packet entirely.
-      Debug(this, "Failed to accept initial packet");
+      Debug(this, "Failed to accept initial packet from %s", remote_address);
       return;
     }
 
@@ -1120,7 +1120,8 @@ void Endpoint::Receive(const uv_buf_t& buf,
     // version negotiation packet in response.
     if (ngtcp2_is_supported_version(hd.version) == 0) {
       Debug(this,
-            "Packet was not accepted because the version is not supported");
+            "Packet was not accepted because the version (%d) is not supported",
+            hd.version);
       SendVersionNegotiation(
           PathDescriptor{version, dcid, scid, local_address, remote_address});
       STAT_INCREMENT(Stats, packets_received);
@@ -1142,8 +1143,8 @@ void Endpoint::Receive(const uv_buf_t& buf,
     if (state_->busy || limits_exceeded) {
       Debug(this,
             "Packet was not accepted because the endpoint is busy or the "
-            "remote peer has exceeded their maximum number of concurrent "
-            "connections");
+            "remote address %s has exceeded their maximum number of concurrent "
+            "connections", remote_address);
       // Endpoint is busy or the connection count is exceeded. The connection is
       // refused. For the purpose of stats collection, we'll count both of these
       // the same.
@@ -1190,7 +1191,7 @@ void Endpoint::Receive(const uv_buf_t& buf,
     // a new token. If it does exist, and if it is valid, we grab the original
     // cid and continue.
     if (!is_remote_address_validated) {
-      Debug(this, "Remote address is not validated");
+      Debug(this, "Remote address %s is not validated", remote_address);
       switch (hd.type) {
         case NGTCP2_PKT_INITIAL:
           // First, let's see if we need to do anything here.
@@ -1199,8 +1200,8 @@ void Endpoint::Receive(const uv_buf_t& buf,
             // If there is no token, generate and send one.
             if (hd.tokenlen == 0) {
               Debug(this,
-                    "Initial packet has no token. Sending retry to start "
-                    "validation");
+                    "Initial packet has no token. Sending retry to %s to start "
+                    "validation", remote_address);
               SendRetry(PathDescriptor{
                   version,
                   dcid,
@@ -1219,15 +1220,15 @@ void Endpoint::Receive(const uv_buf_t& buf,
             switch (hd.token[0]) {
               case RetryToken::kTokenMagic: {
                 RetryToken token(hd.token, hd.tokenlen);
-                Debug(this, "Initial packet has retry token %s", token);
+                Debug(this, "Initial packet from %s has retry token %s", remote_address, token);
                 auto ocid = token.Validate(
                     version,
                     remote_address,
                     dcid,
                     options_.token_secret,
                     options_.retry_token_expiration * NGTCP2_SECONDS);
                 if (!ocid.has_value()) {
-                  Debug(this, "Retry token is invalid.");
+                  Debug(this, "Retry token from %s is invalid.", remote_address);
                   // Invalid retry token was detected. Close the connection.
                   SendImmediateConnectionClose(
                       PathDescriptor{
@@ -1243,22 +1244,23 @@ void Endpoint::Receive(const uv_buf_t& buf,
                 // original retry packet sent to the client. We use it for
                 // validation.
                 Debug(this,
-                      "Retry token is valid. Original dcid %s",
-                      ocid.value());
+                      "Retry token from %s is valid. Original dcid %s",
+                      remote_address, ocid.value());
                 config.ocid = ocid.value();
                 config.retry_scid = dcid;
                 config.set_token(token);
                 break;
               }
               case RegularToken::kTokenMagic: {
                 RegularToken token(hd.token, hd.tokenlen);
-                Debug(this, "Initial packet has regular token %s", token);
+                Debug(this, "Initial packet from %s has regular token %s",
+                      remote_address, token);
                 if (!token.Validate(
                         version,
                         remote_address,
                         options_.token_secret,
                         options_.token_expiration * NGTCP2_SECONDS)) {
-                  Debug(this, "Regular token is invalid.");
+                  Debug(this, "Regular token from %s is invalid.", remote_address);
                   // If the regular token is invalid, let's send a retry to be
                   // lenient. There's a small risk that a malicious peer is
                   // trying to make us do some work but the risk is fairly low
@@ -1275,12 +1277,12 @@ void Endpoint::Receive(const uv_buf_t& buf,
                   STAT_INCREMENT(Stats, packets_received);
                   return;
                 }
-                Debug(this, "Regular token is valid.");
+                Debug(this, "Regular token from %s is valid.", remote_address);
                 config.set_token(token);
                 break;
               }
               default: {
-                Debug(this, "Initial packet has unknown token type");
+                Debug(this, "Initial packet from %s has unknown token type", remote_address);
                 // If our prefix bit does not match anything we know about,
                 // let's send a retry to be lenient. There's a small risk that a
                 // malicious peer is trying to make us do some work but the risk
@@ -1301,10 +1303,11 @@ void Endpoint::Receive(const uv_buf_t& buf,
             // path to the remote address is valid (for now). Let's record that
             // so we don't have to do this dance again for this endpoint
             // instance.
-            Debug(this, "Remote address is validated");
+            Debug(this, "Remote address %s is validated", remote_address);
             addrLRU_.Upsert(remote_address)->validated = true;
           } else if (hd.tokenlen > 0) {
-            Debug(this, "Ignoring initial packet with unexpected token");
+            Debug(this, "Ignoring initial packet from %s with unexpected token",
+                  remote_address);
             // If validation is turned off and there is a token, that's weird.
             // The peer should only have a token if we sent it to them and we
             // wouldn't have sent it unless validation was turned on. Let's
@@ -1314,7 +1317,7 @@ void Endpoint::Receive(const uv_buf_t& buf,
           }
           break;
         case NGTCP2_PKT_0RTT:
-          Debug(this, "Sending retry to initial 0RTT packet");
+          Debug(this, "Sending retry to %s due to initial 0RTT packet", remote_address);
           // If it's a 0RTT packet, we're always going to perform path
           // validation no matter what. This is a bit unfortunate since
           // ORTT is supposed to be, you know, 0RTT, but sending a retry

src/quic/session.cc

@@ -184,6 +184,17 @@ Session::SendPendingDataScope::~SendPendingDataScope() {
 // ============================================================================
 
 namespace {
+
+inline const char* getEncryptionLevelName(ngtcp2_encryption_level level) {
+  switch (level) {
+    case NGTCP2_ENCRYPTION_LEVEL_1RTT: return "1rtt";
+    case NGTCP2_ENCRYPTION_LEVEL_0RTT: return "0rtt";
+    case NGTCP2_ENCRYPTION_LEVEL_HANDSHAKE: return "handshake";
+    case NGTCP2_ENCRYPTION_LEVEL_INITIAL: return "initial";
+  }
+  return "<unknown>";
+}
+
 // Qlog is a JSON-based logging format that is being standardized for low-level
 // debug logging of QUIC connections and dataflows. The qlog output is generated
 // optionally by ngtcp2 for us. The on_qlog_write callback is registered with
@@ -497,11 +508,11 @@ Session::Session(Endpoint* endpoint,
       allocator_(BindingData::Get(env())),
       endpoint_(BaseObjectWeakPtr<Endpoint>(endpoint)),
       config_(config),
+      local_address_(config.local_address),
+      remote_address_(config.remote_address),
       connection_(InitConnection()),
       tls_context_(env(), config_.side, this, config_.options.tls_options),
       application_(select_application()),
-      local_address_(config.local_address),
-      remote_address_(config.remote_address),
       timer_(env(),
              [this, self = BaseObjectPtr<Session>(this)] { OnTimeout(); }) {
   MakeWeak();
@@ -765,7 +776,6 @@ bool Session::Receive(Store&& store,
 
     uint64_t now = uv_hrtime();
     ngtcp2_pkt_info pi{};  // Not used but required.
-    Debug(this, "Session is receiving packet");
     int err = ngtcp2_conn_read_pkt(*this, path, &pi, vec.base, vec.len, now);
     switch (err) {
       case 0: {
@@ -818,14 +828,15 @@ bool Session::Receive(Store&& store,
     }
     // Shouldn't happen but just in case.
     last_error_ = QuicError::ForNgtcp2Error(err);
-    Debug(this, "Error while receiving packet: %s", last_error_);
+    Debug(this, "Error while receiving packet: %s (%d)", last_error_, err);
     Close();
     return false;
   };
 
   auto update_stats = OnScopeLeave([&] { UpdateDataStats(); });
   remote_address_ = remote_address;
   Path path(local_address, remote_address_);
+  Debug(this, "Session is receiving packet received along path %s", path);
   STAT_INCREMENT_N(Stats, bytes_received, store.length());
   if (receivePacket(&path, store)) application().SendPendingData();
 
@@ -2023,7 +2034,11 @@ struct Session::Impl {
   static int on_receive_rx_key(ngtcp2_conn* conn,
                                ngtcp2_encryption_level level,
                                void* user_data) {
-    NGTCP2_CALLBACK_SCOPE(session)
+    auto session = Impl::From(conn, user_data);
+    if (UNLIKELY(session->is_destroyed())) return NGTCP2_ERR_CALLBACK_FAILURE;
+
+    Debug(session, "Receiving RX key for level %d for dcid %s",
+          getEncryptionLevelName(level), session->config().dcid);
 
     if (!session->is_server() && (level == NGTCP2_ENCRYPTION_LEVEL_0RTT ||
                                   level == NGTCP2_ENCRYPTION_LEVEL_1RTT)) {
@@ -2076,7 +2091,12 @@ struct Session::Impl {
   static int on_receive_tx_key(ngtcp2_conn* conn,
                                ngtcp2_encryption_level level,
                                void* user_data) {
-    NGTCP2_CALLBACK_SCOPE(session)
+    auto session = Impl::From(conn, user_data);
+    if (UNLIKELY(session->is_destroyed())) return NGTCP2_ERR_CALLBACK_FAILURE;
+
+    Debug(session, "Receiving TX key for level %d for dcid %s",
+          getEncryptionLevelName(level), session->config().dcid);
+
     if (session->is_server() && (level == NGTCP2_ENCRYPTION_LEVEL_0RTT ||
                                  level == NGTCP2_ENCRYPTION_LEVEL_1RTT)) {
       if (!session->application().Start()) return NGTCP2_ERR_CALLBACK_FAILURE;
@@ -2288,6 +2308,7 @@ void Session::RegisterExternalReferences(ExternalReferenceRegistry* registry) {
 Session::QuicConnectionPointer Session::InitConnection() {
   ngtcp2_conn* conn;
   Path path(local_address_, remote_address_);
+  Debug(this, "Initializing session for path %s", path);
   TransportParams::Config tp_config(
       config_.side, config_.ocid, config_.retry_scid);
   TransportParams transport_params(tp_config, config_.options.transport_params);

src/quic/session.h

@@ -415,11 +415,11 @@ class Session final : public AsyncWrap, private SessionTicket::AppData::Source {
   ngtcp2_mem allocator_;
   BaseObjectWeakPtr<Endpoint> endpoint_;
   Config config_;
+  SocketAddress local_address_;
+  SocketAddress remote_address_;
   QuicConnectionPointer connection_;
   TLSContext tls_context_;
   std::unique_ptr<Application> application_;
-  SocketAddress local_address_;
-  SocketAddress remote_address_;
   StreamsMap streams_;
   TimerWrapHandle timer_;
   size_t send_scope_depth_ = 0;