Bug 830146: Add packet logging for DataChannels, and log SCTP debugs through NSPR r=jesup,mcmanus

media/mtransport/test/sctp_unittest.cpp

@@ -298,10 +298,21 @@ class TransportTest : public ::testing::Test {
     delete p2_;
   }
 
+  static void debug_printf(const char *format, ...) {
+    va_list ap;
+
+    va_start(ap, format);
+    vprintf(format, ap);
+    va_end(ap);
+  }
+
+
   static void SetUpTestCase() {
-    usrsctp_init(0, &TransportTestPeer::conn_output);
     if (sctp_logging) {
+      usrsctp_init(0, &TransportTestPeer::conn_output, debug_printf);
       usrsctp_sysctl_set_sctp_debug_on(0xffffffff);
+    } else {
+      usrsctp_init(0, &TransportTestPeer::conn_output, nullptr);
     }
   }
 

netwerk/sctp/datachannel/DataChannel.cpp

@@ -41,6 +41,15 @@ GetDataChannelLog()
     sLog = PR_NewLogModule("DataChannel");
   return sLog;
 }
+
+PRLogModuleInfo*
+GetSCTPLog()
+{
+  static PRLogModuleInfo* sLog;
+  if (!sLog)
+    sLog = PR_NewLogModule("SCTP");
+  return sLog;
+}
 #endif
 
 static bool sctp_initialized;
@@ -138,6 +147,27 @@ receive_cb(struct socket* sock, union sctp_sockstore addr,
   return connection->ReceiveCallback(sock, data, datalen, rcv, flags);
 }
 
+#ifdef PR_LOGGING
+static void
+debug_printf(const char *format, ...)
+{
+  va_list ap;
+  char buffer[1024];
+
+  if (PR_LOG_TEST(GetSCTPLog(), PR_LOG_ALWAYS)) {
+    va_start(ap, format);
+#ifdef _WIN32
+    if (vsnprintf_s(buffer, sizeof(buffer), _TRUNCATE, format, ap) > 0) {
+#else
+    if (vsnprintf(buffer, sizeof(buffer), format, ap) > 0) {
+#endif
+      PR_LogPrint("%s", buffer);
+    }
+    va_end(ap);
+  }
+}
+#endif
+
 DataChannelConnection::DataChannelConnection(DataConnectionListener *listener) :
    mLock("netwerk::sctp::DataChannel")
 {
@@ -232,18 +262,34 @@ DataChannelConnection::Init(unsigned short aPort, uint16_t aNumStreams, bool aUs
       if (aUsingDtls) {
         LOG(("sctp_init(DTLS)"));
 #ifdef MOZ_PEERCONNECTION
-        usrsctp_init(0, DataChannelConnection::SctpDtlsOutput);
+        usrsctp_init(0,
+                     DataChannelConnection::SctpDtlsOutput,
+#ifdef PR_LOGGING
+                     debug_printf
+#else
+                     nullptr
+#endif
+                    );
 #else
         NS_ASSERTION(!aUsingDtls, "Trying to use SCTP/DTLS without mtransport");
 #endif
       } else {
         LOG(("sctp_init(%d)", aPort));
-        usrsctp_init(aPort, nullptr);
+        usrsctp_init(aPort,
+                     nullptr,
+#ifdef PR_LOGGING
+                     debug_printf
+#else
+                     nullptr
+#endif
+                    );
       }
 
-      // Set logging to datachannel:6 to get SCTP debugs
 #ifdef PR_LOGGING
-      usrsctp_sysctl_set_sctp_debug_on(GetDataChannelLog()->level > 5 ? SCTP_DEBUG_ALL : 0);
+      // Set logging to SCTP:PR_LOG_DEBUG to get SCTP debugs
+      if (PR_LOG_TEST(GetSCTPLog(), PR_LOG_ALWAYS)) {
+        usrsctp_sysctl_set_sctp_debug_on(SCTP_DEBUG_ALL);
+      }
 #endif
       usrsctp_sysctl_set_sctp_blackhole(2);
       sctp_initialized = true;
@@ -483,8 +529,16 @@ void
 DataChannelConnection::SctpDtlsInput(TransportFlow *flow,
                                      const unsigned char *data, size_t len)
 {
-  //LOG(("%p: SCTP/DTLS received %ld bytes", this, len));
+#ifdef PR_LOGGING
+  if (PR_LOG_TEST(GetSCTPLog(), PR_LOG_DEBUG)) {
+    char *buf;
 
+    if ((buf = usrsctp_dumppacket((void *)data, len, SCTP_DUMP_INBOUND)) != NULL) {
+      PR_LogPrint("%s", buf);
+      usrsctp_freedumpbuffer(buf);
+    }
+  }
+#endif
   // Pass the data to SCTP
   usrsctp_conninput(static_cast<void *>(this), data, len, 0);
 }
@@ -507,6 +561,16 @@ DataChannelConnection::SctpDtlsOutput(void *addr, void *buffer, size_t length,
   DataChannelConnection *peer = static_cast<DataChannelConnection *>(addr);
   int res;
 
+#ifdef PR_LOGGING
+  if (PR_LOG_TEST(GetSCTPLog(), PR_LOG_DEBUG)) {
+    char *buf;
+
+    if ((buf = usrsctp_dumppacket(buffer, length, SCTP_DUMP_OUTBOUND)) != NULL) {
+      PR_LogPrint("%s", buf);
+      usrsctp_freedumpbuffer(buf);
+    }
+  }
+#endif
   // We're async proxying even if on the STSThread because this is called
   // with internal SCTP locks held in some cases (such as in usrsctp_connect()).
   // SCTP has an option for Apple, on IP connections only, to release at least

netwerk/sctp/datachannel/DataChannelLog.h

@@ -20,6 +20,7 @@
 
 #ifdef PR_LOGGING
 extern PRLogModuleInfo* GetDataChannelLog();
+extern PRLogModuleInfo* GetSCTPLog();
 #endif
 
 #undef LOG

netwerk/sctp/src/netinet/sctp_os_userspace.h

@@ -520,7 +520,10 @@ struct sx {int dummy;};
 #include <netinet/ip_options.h>
 #endif
 
-#define SCTP_PRINTF(...)   printf(__VA_ARGS__)
+#define SCTP_PRINTF(...)                                  \
+	if (SCTP_BASE_VAR(debug_printf)) {                \
+		SCTP_BASE_VAR(debug_printf)(__VA_ARGS__); \
+	}
 
 #if defined(__FreeBSD__)
 #ifndef in6pcb

netwerk/sctp/src/netinet/sctp_pcb.h

@@ -336,6 +336,7 @@ struct sctp_base_info {
 	userland_thread_t recvthreadudp6;
 #endif
 	int (*conn_output)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df);
+	void (*debug_printf)(const char *format, ...);
 #endif
 };
 

netwerk/sctp/src/netinet/sctp_usrreq.c

@@ -74,7 +74,8 @@ extern struct sctp_ss_functions sctp_ss_functions[];
 void
 #if defined(__Userspace__)
 sctp_init(uint16_t port,
-          int (*conn_output)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df))
+          int (*conn_output)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df),
+          void (*debug_printf)(const char *format, ...))
 #else
 sctp_init(void)
 #endif
@@ -156,6 +157,7 @@ sctp_init(void)
 #endif
 	SCTP_BASE_VAR(timer_thread_should_exit) = 0;
 	SCTP_BASE_VAR(conn_output) = conn_output;
+	SCTP_BASE_VAR(debug_printf) = debug_printf;
 #endif
 	sctp_pcb_init();
 #if defined(__Userspace__)

netwerk/sctp/src/netinet/sctp_var.h

@@ -433,7 +433,9 @@ void sctp_drain __P((void));
 void sctp_drain(void);
 #endif
 #if defined(__Userspace__)
-void sctp_init(uint16_t, int (*)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df));
+void sctp_init(uint16_t,
+               int (*)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df),
+               void (*)(const char *, ...));
 #else
 #if defined(__FreeBSD__) && __FreeBSD_version < 1000000
 void sctp_init __P((void));

netwerk/sctp/src/user_socket.c

@@ -75,9 +75,10 @@ extern int sctpconn_attach(struct socket *so, int proto, uint32_t vrf_id);
 
 void
 usrsctp_init(uint16_t port,
-             int (*conn_output)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df))
+             int (*conn_output)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df),
+             void (*debug_printf)(const char *format, ...))
 {
-	sctp_init(port, conn_output);
+	sctp_init(port, conn_output, debug_printf);
 }
 
 

netwerk/sctp/src/usrsctp.h

@@ -846,7 +846,8 @@ struct sctp_timeouts {
 
 void
 usrsctp_init(uint16_t,
-             int (*)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df));
+             int (*)(void *addr, void *buffer, size_t length, uint8_t tos, uint8_t set_df),
+             void (*)(const char *, ...));
 
 struct socket *
 usrsctp_socket(int domain, int type, int protocol,
@@ -968,7 +969,7 @@ usrsctp_register_address(void *);
 void
 usrsctp_deregister_address(void *);
 
-#define SCTP_DUMP_OUTBOUND 0
+#define SCTP_DUMP_OUTBOUND 1
 #define SCTP_DUMP_INBOUND  0
 
 char *