Bug 1290365: added extensive logging for TURN TCP draft
authorNils Ohlmeier [:drno] <drno@ohlmeier.org>
Sat, 30 Jul 2016 00:41:05 -0700
changeset 394669 093a53bdf20e834456a728c283a2565c96f5700d
parent 394256 2ea3d51ba1bb9f5c3b6921c43ea63f70b4fdf5d2
child 526858 25050f055d50f9a675126c7401082104c0736fd2
push id24622
push userdrno@ohlmeier.org
push dateSat, 30 Jul 2016 17:02:06 +0000
bugs1290365
milestone50.0a1
Bug 1290365: added extensive logging for TURN TCP MozReview-Commit-ID: 4LBZe4SoVOL
media/mtransport/third_party/nICEr/src/ice/ice_candidate.c
media/mtransport/third_party/nICEr/src/stun/nr_socket_buffered_stun.c
--- a/media/mtransport/third_party/nICEr/src/ice/ice_candidate.c
+++ b/media/mtransport/third_party/nICEr/src/ice/ice_candidate.c
@@ -792,21 +792,24 @@ static int nr_ice_start_relay_turn(nr_ic
                                    cand->u.relayed.server->password,
                                    &cand->stun_server_addr,
                                    &cand->u.relayed.turn))
       ABORT(r);
 
     if(r=nr_socket_turn_set_ctx(cand->osock, cand->u.relayed.turn))
       ABORT(r);
 
+    r_log(LOG_ICE,LOG_INFO,"ICE(%s)/CAND(%s): delay for nr_ice_start_relay_turn_timer_cb (%d)", cand->ctx->label, cand->label,cand->stream->ctx->stun_delay);
     NR_ASYNC_TIMER_SET(cand->stream->ctx->stun_delay,nr_ice_start_relay_turn_timer_cb,cand,&cand->delay_timer);
     cand->stream->ctx->stun_delay += cand->stream->ctx->Ta;
 
     _status=0;
   abort:
+    if (_status)
+      r_log(LOG_ICE,LOG_ERR,"ICE(%s)/CAND(%s): %s failed with status: %d", cand->ctx->label, cand->label, __FUNCTION__, _status);
     return(_status);
   }
 #endif /* USE_TURN */
 
 static void nr_ice_srvrflx_stun_finished_cb(NR_SOCKET sock, int how, void *cb_arg)
   {
     int _status;
     nr_ice_candidate *cand=cb_arg;
--- a/media/mtransport/third_party/nICEr/src/stun/nr_socket_buffered_stun.c
+++ b/media/mtransport/third_party/nICEr/src/stun/nr_socket_buffered_stun.c
@@ -251,16 +251,17 @@ abort:
 static void nr_socket_buffered_stun_failed(nr_socket_buffered_stun *sock)
   {
     NR_SOCKET fd;
 
     sock->read_state = NR_ICE_SOCKET_READ_FAILED;
 
     /* Cancel waiting on the socket */
     if (sock->inner && !nr_socket_getfd(sock->inner, &fd)) {
+      r_log(LOG_GENERIC, LOG_INFO, "%s canceling RW callbacks", __FUNCTION__);
       NR_ASYNC_CANCEL(fd, NR_ASYNC_WAIT_WRITE);
       NR_ASYNC_CANCEL(fd, NR_ASYNC_WAIT_READ);
     }
   }
 
 static int nr_socket_buffered_stun_recvfrom(void *obj,void * restrict buf,
   size_t maxlen, size_t *len, int flags, nr_transport_addr *from)
 {
@@ -340,16 +341,17 @@ reread:
   if (!nr_transport_addr_is_wildcard(&sock->remote_addr)) {
     if ((r=nr_transport_addr_copy(from, &sock->remote_addr)))
       ABORT(r);
   }
 
   _status=0;
 abort:
   if (_status && (_status != R_WOULDBLOCK)) {
+    r_log(LOG_GENERIC, LOG_ERR, "Read failure in %s: %d", __FUNCTION__, _status);
     nr_socket_buffered_stun_failed(sock);
   }
 
   return(_status);
 }
 
 static int nr_socket_buffered_stun_getfd(void *obj, NR_SOCKET *fd)
 {
@@ -405,18 +407,20 @@ static int nr_socket_buffered_stun_accep
 static void nr_socket_buffered_stun_connected_cb(NR_SOCKET s, int how, void *arg)
 {
   nr_socket_buffered_stun *sock = (nr_socket_buffered_stun *)arg;
 
   assert(!sock->connected);
 
   sock->connected = 1;
   if (sock->pending) {
-    r_log(LOG_GENERIC, LOG_INFO, "Invoking writable_cb on connected (%u)", (uint32_t) sock->pending);
+    r_log(LOG_GENERIC, LOG_INFO, "Socket (%p) invoking writable_cb on connected (%u)", sock, (uint32_t) sock->pending);
     nr_socket_buffered_stun_writable_cb(s, how, arg);
+  } else {
+    r_log(LOG_GENERIC, LOG_INFO, "Socket (%p) connected with no pending data", sock);
   }
 }
 
 static int nr_socket_buffered_stun_connect(void *obj, nr_transport_addr *addr)
 {
   nr_socket_buffered_stun *sock = (nr_socket_buffered_stun *)obj;
   int r, _status;
 
@@ -428,16 +432,17 @@ static int nr_socket_buffered_stun_conne
       NR_SOCKET fd;
 
       if ((r=nr_socket_getfd(sock->inner, &fd)))
         ABORT(r);
 
       NR_ASYNC_WAIT(fd, NR_ASYNC_WAIT_WRITE, nr_socket_buffered_stun_connected_cb, sock);
       ABORT(R_WOULDBLOCK);
     }
+    r_log(LOG_GENERIC, LOG_ERR, "%s socket (%p) connect failed with r: %d", __FUNCTION__, sock, r);
     ABORT(r);
   } else {
     r_log(LOG_GENERIC, LOG_INFO, "Connected without blocking");
     sock->connected = 1;
   }
 
   _status=0;
 abort:
@@ -508,16 +513,18 @@ static int nr_socket_buffered_stun_write
 
     sock->pending += len;
   }
 
   if (sock->pending) {
     if (!already_armed) {
       if ((r=nr_socket_buffered_stun_arm_writable_cb(sock)))
         ABORT(r);
+    } else {
+      r_log(LOG_GENERIC, LOG_INFO, "Assuming socket is still/already armed with connect callback - connected (%d)", sock->connected);
     }
     r_log(LOG_GENERIC, LOG_INFO, "Write buffer not empty for %s  %u - %s armed (@%p),%s connected",
           sock->remote_addr.as_string, (uint32_t)sock->pending,
           already_armed ? "already" : "", &sock->pending,
           sock->connected ? "" : " not");
   }
 
   *written = original_len;