Split "verbose" on-every-packet messages to a verbose log

This way, the regular log will only contain connection-time information.

4 files changed, 56 insertions, 30 deletions

diff --git a/agent/agent-priv.h b/agent/agent-priv.h
index c413bc1..7497cb1 100644
--- a/agent/agent-priv.h
+++ b/agent/agent-priv.h
@@ -274,10 +274,14 @@ void nice_debug_init (void);
 
 #ifdef NDEBUG
 static inline gboolean nice_debug_is_enabled (void) { return FALSE; }
+static inline gboolean nice_debug_is_verbose (void) { return FALSE; }
 static inline void nice_debug (const char *fmt, ...) { }
+static inline void nice_debug_verbose (const char *fmt, ...) { }
 #else
 gboolean nice_debug_is_enabled (void);
+gboolean nice_debug_is_verbose (void);
 void nice_debug (const char *fmt, ...) G_GNUC_PRINTF (1, 2);
+void nice_debug_verbose (const char *fmt, ...) G_GNUC_PRINTF (1, 2);
 #endif
 
 #endif /*_NICE_AGENT_PRIV_H */
diff --git a/agent/agent.c b/agent/agent.c
index 84d4093..a2c475f 100644
--- a/agent/agent.c
+++ b/agent/agent.c
@@ -1533,7 +1533,7 @@ pseudo_tcp_socket_recv_messages (PseudoTcpSocket *self,
             (gchar *) buffer->buffer + iter->offset,
             buffer->size - iter->offset);
 
-        nice_debug ("%s: Received %" G_GSSIZE_FORMAT " bytes into "
+        nice_debug_verbose ("%s: Received %" G_GSSIZE_FORMAT " bytes into "
             "buffer %p (offset %" G_GSIZE_FORMAT ", length %" G_GSIZE_FORMAT
             ").", G_STRFUNC, len, buffer->buffer, iter->offset, buffer->size);
 
@@ -1589,7 +1589,7 @@ pseudo_tcp_socket_readable (PseudoTcpSocket *sock, gpointer user_data)
 
   g_object_ref (agent);
 
-  nice_debug ("Agent %p: s%d:%d pseudo Tcp socket readable", agent,
+  nice_debug_verbose ("Agent %p: s%d:%d pseudo Tcp socket readable", agent,
       stream->id, component->id);
 
   component->tcp_readable = TRUE;
@@ -1667,7 +1667,7 @@ pseudo_tcp_socket_readable (PseudoTcpSocket *sock, gpointer user_data)
         component->recv_messages, component->n_recv_messages,
         &component->recv_messages_iter, &child_error);
 
-    nice_debug ("%s: Client buffers case: Received %d valid messages:",
+    nice_debug_verbose ("%s: Client buffers case: Received %d valid messages:",
         G_STRFUNC, n_valid_messages);
     nice_debug_input_message_composition (component->recv_messages,
         component->n_recv_messages);
@@ -1710,7 +1710,7 @@ pseudo_tcp_socket_writable (PseudoTcpSocket *sock, gpointer user_data)
   NiceAgent *agent = component->agent;
   Stream *stream = component->stream;
 
-  nice_debug ("Agent %p: s%d:%d pseudo Tcp socket writable", agent,
+  nice_debug_verbose ("Agent %p: s%d:%d pseudo Tcp socket writable", agent,
       stream->id, component->id);
 
   agent_signal_socket_writable (agent, component);
@@ -1747,7 +1747,7 @@ pseudo_tcp_socket_write_packet (PseudoTcpSocket *psocket,
       gchar tmpbuf[INET6_ADDRSTRLEN];
       nice_address_to_string (addr, tmpbuf);
 
-      nice_debug (
+      nice_debug_verbose (
           "Agent %p : s%d:%d: sending %d bytes on socket %p (FD %d) to [%s]:%d",
           component->agent, component->stream->id, component->id, len,
           sock->fileno, g_socket_get_fd (sock->fileno), tmpbuf,
@@ -1972,7 +1972,7 @@ process_queued_tcp_packets (NiceAgent *agent, Stream *stream,
     return;
   }
 
-  nice_debug ("%s: Sending outstanding packets for agent %p.", G_STRFUNC,
+  nice_debug_verbose ("%s: Sending outstanding packets for agent %p.", G_STRFUNC,
       agent);
 
   while ((vec = g_queue_peek_head (&component->queued_tcp_packets)) != NULL) {
@@ -3515,7 +3515,7 @@ agent_recv_message_unlocked (
     retval = nice_socket_recv_messages (nicesock, message, 1);
   }
 
-  nice_debug ("%s: Received %d valid messages of length %" G_GSIZE_FORMAT
+  nice_debug_verbose ("%s: Received %d valid messages of length %" G_GSIZE_FORMAT
       " from base socket %p.", G_STRFUNC, retval, message->length, nicesock);
 
   if (retval == 0) {
@@ -3534,10 +3534,10 @@ agent_recv_message_unlocked (
     goto done;
   }
 
-  if (nice_debug_is_enabled ()) {
+  if (nice_debug_is_verbose ()) {
     gchar tmpbuf[INET6_ADDRSTRLEN];
     nice_address_to_string (message->from, tmpbuf);
-    nice_debug ("Agent %p : Packet received on local socket %d from [%s]:%u (%" G_GSSIZE_FORMAT " octets).", agent,
+    nice_debug_verbose ("Agent %p : Packet received on local socket %d from [%s]:%u (%" G_GSSIZE_FORMAT " octets).", agent,
         g_socket_get_fd (nicesock->fileno), tmpbuf,
         nice_address_get_port (message->from), message->length);
   }
@@ -3549,7 +3549,7 @@ agent_recv_message_unlocked (
     if (!nice_address_equal (message->from, &turn->server))
       continue;
 
-    nice_debug ("Agent %p : Packet received from TURN server candidate.",
+    nice_debug_verbose ("Agent %p : Packet received from TURN server candidate.",
         agent);
 
     for (i = component->local_candidates; i; i = i->next) {
@@ -3637,7 +3637,7 @@ agent_recv_message_unlocked (
 
       /* Received data on a reliable connection. */
 
-      nice_debug ("%s: notifying pseudo-TCP of packet, length %" G_GSIZE_FORMAT,
+      nice_debug_verbose ("%s: notifying pseudo-TCP of packet, length %" G_GSIZE_FORMAT,
           G_STRFUNC, message->length);
       pseudo_tcp_socket_notify_message (component->tcp, message);
 
@@ -3671,14 +3671,14 @@ nice_debug_input_message_composition (const NiceInputMessage *messages,
 {
   guint i;
 
-  if (!nice_debug_is_enabled ())
+  if (!nice_debug_is_verbose ())
     return;
 
   for (i = 0; i < n_messages; i++) {
     const NiceInputMessage *message = &messages[i];
     guint j;
 
-    nice_debug ("Message %p (from: %p, length: %" G_GSIZE_FORMAT ")", message,
+    nice_debug_verbose ("Message %p (from: %p, length: %" G_GSIZE_FORMAT ")", message,
         message->from, message->length);
 
     for (j = 0;
@@ -3687,7 +3687,7 @@ nice_debug_input_message_composition (const NiceInputMessage *messages,
          j++) {
       GInputVector *buffer = &message->buffers[j];
 
-      nice_debug ("\tBuffer %p (length: %" G_GSIZE_FORMAT ")", buffer->buffer,
+      nice_debug_verbose ("\tBuffer %p (length: %" G_GSIZE_FORMAT ")", buffer->buffer,
           buffer->size);
     }
   }
@@ -3723,7 +3723,7 @@ compact_message (const NiceOutputMessage *message, gsize buffer_length)
 guint8 *
 compact_input_message (const NiceInputMessage *message, gsize *buffer_length)
 {
-  nice_debug ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
+  nice_debug_verbose ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
   nice_debug_input_message_composition (message, 1);
 
   /* This works as long as NiceInputMessage is a subset of eNiceOutputMessage */
@@ -3741,7 +3741,7 @@ memcpy_buffer_to_input_message (NiceInputMessage *message,
 {
   guint i;
 
-  nice_debug ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
+  nice_debug_verbose ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
 
   message->length = 0;
 
@@ -4040,7 +4040,7 @@ nice_agent_recv_messages_blocking_or_nonblocking (NiceAgent *agent,
     goto done;
   }
 
-  nice_debug ("%s: %p: (%s):", G_STRFUNC, agent,
+  nice_debug_verbose ("%s: %p: (%s):", G_STRFUNC, agent,
       blocking ? "blocking" : "non-blocking");
   nice_debug_input_message_composition (messages, n_messages);
 
@@ -4073,7 +4073,7 @@ nice_agent_recv_messages_blocking_or_nonblocking (NiceAgent *agent,
         component->recv_messages, component->n_recv_messages,
         &component->recv_messages_iter);
 
-    nice_debug ("%s: %p: Received %d valid messages from pending I/O buffer.",
+    nice_debug_verbose ("%s: %p: Received %d valid messages from pending I/O buffer.",
         G_STRFUNC, agent,
         nice_input_message_iter_get_n_valid_messages (
             &component->recv_messages_iter));
@@ -4094,7 +4094,7 @@ nice_agent_recv_messages_blocking_or_nonblocking (NiceAgent *agent,
         &component->recv_messages_iter, &child_error);
     adjust_tcp_clock (agent, stream, component);
 
-    nice_debug ("%s: %p: Received %d valid messages from pseudo-TCP read "
+    nice_debug_verbose ("%s: %p: Received %d valid messages from pseudo-TCP read "
         "buffer.", G_STRFUNC, agent,
         nice_input_message_iter_get_n_valid_messages (
             &component->recv_messages_iter));
@@ -4178,7 +4178,7 @@ recv_error:
     n_valid_messages = -1;
   }
 
-  nice_debug ("%s: %p: n_valid_messages: %d, n_messages: %u", G_STRFUNC, agent,
+  nice_debug_verbose ("%s: %p: n_valid_messages: %d, n_messages: %u", G_STRFUNC, agent,
       n_valid_messages, n_messages);
 
 done:
@@ -4334,7 +4334,7 @@ nice_agent_send_messages_nonblocking_internal (
       gchar tmpbuf[INET6_ADDRSTRLEN];
       nice_address_to_string (&component->selected_pair.remote->addr, tmpbuf);
 
-      nice_debug ("Agent %p : s%d:%d: sending %u messages to "
+      nice_debug_verbose ("Agent %p : s%d:%d: sending %u messages to "
           "[%s]:%d", agent, stream_id, component_id, n_messages, tmpbuf,
           nice_address_get_port (&component->selected_pair.remote->addr));
     }
@@ -4484,7 +4484,7 @@ nice_agent_send_messages_nonblocking_internal (
     n_sent = -1;
   }
 
-  nice_debug ("%s: n_sent: %d, n_messages: %u", G_STRFUNC,
+  nice_debug_verbose ("%s: n_sent: %d, n_messages: %u", G_STRFUNC,
       n_sent, n_messages);
 
 done:
@@ -4834,7 +4834,7 @@ component_io_cb (GSocket *gsocket, GIOCondition condition, gpointer user_data)
       retval = agent_recv_message_unlocked (agent, stream, component,
           socket_source->socket, &local_message);
 
-      nice_debug ("%s: %p: received %d valid messages with %" G_GSSIZE_FORMAT
+      nice_debug_verbose ("%s: %p: received %d valid messages with %" G_GSSIZE_FORMAT
           " bytes", G_STRFUNC, agent, retval, local_message.length);
 
       /* Don’t expect any valid messages to escape pseudo_tcp_socket_readable()
@@ -4864,7 +4864,7 @@ component_io_cb (GSocket *gsocket, GIOCondition condition, gpointer user_data)
       retval = agent_recv_message_unlocked (agent, stream, component,
           socket_source->socket, &local_message);
 
-      nice_debug ("%s: %p: received %d valid messages with %" G_GSSIZE_FORMAT
+      nice_debug_verbose ("%s: %p: received %d valid messages with %" G_GSSIZE_FORMAT
            " bytes", G_STRFUNC, agent, retval, local_message.length);
 
       if (retval == RECV_WOULD_BLOCK) {
@@ -4905,7 +4905,7 @@ component_io_cb (GSocket *gsocket, GIOCondition condition, gpointer user_data)
           socket_source->socket,
           &component->recv_messages[component->recv_messages_iter.message]);
 
-      nice_debug ("%s: %p: received %d valid messages", G_STRFUNC, agent,
+      nice_debug_verbose ("%s: %p: received %d valid messages", G_STRFUNC, agent,
           retval);
 
       if (retval == RECV_SUCCESS) {
diff --git a/agent/debug.c b/agent/debug.c
index 6e69f9b..f4ac4b8 100644
--- a/agent/debug.c
+++ b/agent/debug.c
@@ -48,17 +48,20 @@
 #include "agent-priv.h"
 
 static int debug_enabled = 0;
+static int debug_verbose_enabled = 0;
 
 #define NICE_DEBUG_STUN 1
 #define NICE_DEBUG_NICE 2
 #define NICE_DEBUG_PSEUDOTCP 4
 #define NICE_DEBUG_PSEUDOTCP_VERBOSE 8
+#define NICE_DEBUG_NICE_VERBOSE 16
 
 static const GDebugKey keys[] = {
   { (gchar *)"stun",  NICE_DEBUG_STUN },
   { (gchar *)"nice",  NICE_DEBUG_NICE },
   { (gchar *)"pseudotcp",  NICE_DEBUG_PSEUDOTCP },
   { (gchar *)"pseudotcp-verbose",  NICE_DEBUG_PSEUDOTCP_VERBOSE },
+  { (gchar *)"nice-verbose",  NICE_DEBUG_NICE_VERBOSE },
   { NULL, 0},
 };
 
@@ -88,10 +91,16 @@ void nice_debug_init (void)
       flags = g_parse_debug_string (flags_string, keys,  4);
     if (gflags_string && strstr (gflags_string, "libnice-pseudotcp-verbose"))
       flags |= NICE_DEBUG_PSEUDOTCP_VERBOSE;
+    if (gflags_string && strstr (gflags_string, "libnice-nice-verbose")) {
+      flags |= NICE_DEBUG_NICE_VERBOSE;
+    }
 
     stun_set_debug_handler (stun_handler);
     nice_debug_enable (TRUE);
 
+    if (flags & NICE_DEBUG_NICE_VERBOSE)
+      debug_verbose_enabled = TRUE;
+
     /* Set verbose before normal so that if we use 'all', then only
        normal debug is enabled, we'd need to set pseudotcp-verbose without the
        pseudotcp flag in order to actually enable verbose pseudotcp */
@@ -107,6 +116,10 @@ gboolean nice_debug_is_enabled (void)
 {
   return debug_enabled;
 }
+gboolean nice_debug_is_verbose (void)
+{
+  return debug_verbose_enabled;
+}
 #else
 /* Defined in agent-priv.h. */
 #endif
@@ -136,6 +149,15 @@ void nice_debug (const char *fmt, ...)
     va_end (ap);
   }
 }
+void nice_debug_verbose (const char *fmt, ...)
+{
+  va_list ap;
+  if (debug_verbose_enabled) {
+    va_start (ap, fmt);
+    g_logv (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, fmt, ap);
+    va_end (ap);
+  }
+}
 #else
 /* Defined in agent-priv.h. */
 #endif
diff --git a/socket/udp-turn.c b/socket/udp-turn.c
index e640363..2b20142 100644
--- a/socket/udp-turn.c
+++ b/socket/udp-turn.c
@@ -336,7 +336,7 @@ socket_recv_messages (NiceSocket *sock,
   if (sock->priv == NULL)
     return 0;
 
-  nice_debug ("received message on TURN socket");
+  nice_debug_verbose ("received message on TURN socket");
 
   n_messages = nice_socket_recv_messages (priv->base_socket,
       recv_messages, n_recv_messages);
@@ -374,7 +374,7 @@ socket_recv_messages (NiceSocket *sock,
       buffer = message->buffers[0].buffer;
       buffer_length = message->length;
     } else {
-      nice_debug ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
+      nice_debug_verbose ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
 
       buffer = compact_input_message (message, &buffer_length);
       allocated_buffer = TRUE;
@@ -663,7 +663,7 @@ socket_dequeue_all_data (UdpTurnPriv *priv, const NiceAddress *to)
       SendData *data =
           (SendData *) g_queue_pop_head(send_queue);
 
-      nice_debug ("dequeuing data");
+      nice_debug_verbose ("dequeuing data");
       _socket_send_wrapped (priv->base_socket, &priv->server_addr,
           data->data_len, data->data, data->reliable);
 
@@ -835,7 +835,7 @@ socket_send_message (NiceSocket *sock, const NiceAddress *to,
       }
 
       /* enque data */
-      nice_debug ("enqueuing data");
+      nice_debug_verbose ("enqueuing data");
       socket_enqueue_data(priv, to, msg_len, (gchar *)buffer, reliable);
 
       return msg_len;
@@ -1121,7 +1121,7 @@ nice_udp_turn_socket_parse_recv_message (NiceSocket *sock, NiceSocket **from_soc
   }
 
   /* Slow path. */
-  nice_debug ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
+  nice_debug_verbose ("%s: **WARNING: SLOW PATH**", G_STRFUNC);
 
   buf = compact_input_message (message, &buf_len);
   len = nice_udp_turn_socket_parse_recv (sock, from_sock,