Bug 1233652: added verbose logging to debug proxy connectivity problems draft
authorNils Ohlmeier [:drno] <drno@ohlmeier.org>
Tue, 02 Feb 2016 16:51:25 -0800
changeset 328776 c98f3771900a06b0b39b65cc3b16b24412276925
parent 328271 5f9ba76eb3b1fd9377bbdb4cc2f98a7e75eabdfb
child 513865 25d14b02847e1f609ca2bc96fbe4d09c75621704
push id10422
push userdrno@ohlmeier.org
push dateThu, 04 Feb 2016 07:00:37 +0000
bugs1233652
milestone47.0a1
Bug 1233652: added verbose logging to debug proxy connectivity problems
media/mtransport/third_party/nICEr/src/net/nr_proxy_tunnel.c
--- a/media/mtransport/third_party/nICEr/src/net/nr_proxy_tunnel.c
+++ b/media/mtransport/third_party/nICEr/src/net/nr_proxy_tunnel.c
@@ -93,27 +93,43 @@ static nr_socket_vtbl nr_socket_proxy_tu
   nr_socket_proxy_tunnel_getfd,
   nr_socket_proxy_tunnel_getaddr,
   nr_socket_proxy_tunnel_connect,
   nr_socket_proxy_tunnel_write,
   nr_socket_proxy_tunnel_read,
   nr_socket_proxy_tunnel_close
 };
 
+static void nr_socket_proxy_tunnel_set_state(nr_socket_proxy_tunnel *sock,
+                                             nr_socket_proxy_tunnel_state _state)
+{
+  if (_state == sock->state)
+    return;
+
+  sock->state = _state;
+  if (sock->state == PROXY_TUNNEL_FAILED) {
+    r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_set_state [%p]: state set to %d", sock,
+          sock->state);
+  } else {
+    r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_set_state [%p]: state set to %d", sock,
+          sock->state);
+  }
+}
+
 static int send_http_connect(nr_socket_proxy_tunnel *sock)
 {
   int r, _status;
   int port;
   int printed;
   char addr[MAX_HTTP_CONNECT_ADDR_SIZE];
   char mesg[MAX_HTTP_CONNECT_ADDR_SIZE + MAX_ALPN_LENGTH + 128];
   size_t offset = 0;
   size_t bytes_sent;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"send_http_connect");
+  r_log(LOG_GENERIC,LOG_DEBUG,"send_http_connect [%p]", sock);
 
   if ((r=nr_transport_addr_get_port(&sock->remote_addr, &port))) {
     ABORT(r);
   }
 
   if ((r=nr_transport_addr_get_addrstring(&sock->remote_addr, addr, sizeof(addr)))) {
     ABORT(r);
   }
@@ -140,21 +156,22 @@ static int send_http_connect(nr_socket_p
   offset += strlen(END_HEADERS);
 
   if ((r=nr_socket_write(sock->inner, mesg, offset, &bytes_sent, 0))) {
     ABORT(r);
   }
 
   if (bytes_sent < offset) {
     /* TODO(bug 1116583): buffering and wait for */
-    r_log(LOG_GENERIC,LOG_DEBUG,"send_http_connect should be buffering %lu", (unsigned long)bytes_sent);
+    r_log(LOG_GENERIC,LOG_DEBUG,"send_http_connect [%p] should be buffering %lu",
+          sock, (unsigned long)bytes_sent);
     ABORT(R_IO_ERROR);
   }
 
-  sock->state = PROXY_TUNNEL_REQUESTED;
+  nr_socket_proxy_tunnel_set_state(sock, PROXY_TUNNEL_REQUESTED);
 
   _status = 0;
 abort:
   return(_status);
 }
 
 static char *find_http_terminator(char *response, size_t len)
 {
@@ -199,74 +216,74 @@ static int parse_http_response(char *beg
 
   return 0;
 }
 
 static int nr_socket_proxy_tunnel_destroy(void **objpp)
 {
   nr_socket_proxy_tunnel *sock;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_destroy");
-
   if (!objpp || !*objpp)
     return 0;
 
   sock = (nr_socket_proxy_tunnel *)*objpp;
   *objpp = 0;
 
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_destroy [%p]", sock);
+
   if (sock->resolver_handle) {
     nr_resolver_cancel(sock->config->resolver, sock->resolver_handle);
   }
 
   nr_proxy_tunnel_config_destroy(&sock->config);
   nr_socket_destroy(&sock->inner);
   RFREE(sock);
 
   return 0;
 }
 
 static int nr_socket_proxy_tunnel_getfd(void *obj, NR_SOCKET *fd)
 {
   nr_socket_proxy_tunnel *sock = (nr_socket_proxy_tunnel *)obj;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_getfd");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_getfd [%p]", sock);
 
   return nr_socket_getfd(sock->inner, fd);
 }
 
 static int nr_socket_proxy_tunnel_getaddr(void *obj, nr_transport_addr *addrp)
 {
   nr_socket_proxy_tunnel *sock = (nr_socket_proxy_tunnel *)obj;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_getaddr");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_getaddr [%p]", sock);
 
   return nr_socket_getaddr(sock->inner, addrp);
 }
 
 static int nr_socket_proxy_tunnel_resolved_cb(void *obj, nr_transport_addr *proxy_addr)
 {
   int r, _status;
   nr_socket_proxy_tunnel *sock = (nr_socket_proxy_tunnel*)obj;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_resolved_cb");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_resolved_cb [%p]", sock);
 
   /* Mark the socket resolver as completed */
   sock->resolver_handle = 0;
 
   if (proxy_addr) {
     r_log(LOG_GENERIC,LOG_DEBUG,"Resolved proxy address %s -> %s",
         sock->config->proxy_host, proxy_addr->as_string);
   }
   else {
     r_log(LOG_GENERIC,LOG_WARNING,"Failed to resolve proxy %s",
         sock->config->proxy_host);
     /* TODO: Mozilla bug 1241758: because of the callback the return value goes
      * nowhere, so we can't mark the candidate as failed, so everything depends
      * on the overall timeouts in this case. */
-    sock->state = PROXY_TUNNEL_FAILED;
+    nr_socket_proxy_tunnel_set_state(sock, PROXY_TUNNEL_FAILED);
     ABORT(R_NOT_FOUND);
   }
 
   if ((r=nr_socket_connect(sock->inner, proxy_addr))) {
     ABORT(r);
   }
 
   _status = 0;
@@ -288,46 +305,46 @@ int nr_socket_proxy_tunnel_connect(void 
   }
 
   assert(config->proxy_host);
 
   /* Check if the proxy_host is already an IP address */
   has_addr = !nr_str_port_to_transport_addr(config->proxy_host,
       config->proxy_port, IPPROTO_TCP, &proxy_addr);
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_connect: %s", config->proxy_host);
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_connect [%p]: %s", sock, config->proxy_host);
 
   if (!has_addr && !config->resolver) {
-    r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_connect name resolver not configured");
+    r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_connect [%p]: name resolver not configured", sock);
     ABORT(R_NOT_FOUND);
   }
 
   if (!has_addr) {
     resource.domain_name=config->proxy_host;
     resource.port=config->proxy_port;
     resource.stun_turn=NR_RESOLVE_PROTOCOL_TURN;
     resource.transport_protocol=IPPROTO_TCP;
 
     if ((r=nr_socket_getaddr(sock->inner, &local_addr))) {
-      r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_connect failed to get local address");
+      r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_connect [%p]: failed to get local address", sock);
       ABORT(r);
     }
 
     switch(local_addr.ip_version) {
       case NR_IPV4:
         resource.address_family=AF_INET;
         break;
       case NR_IPV6:
         resource.address_family=AF_INET6;
         break;
       default:
         ABORT(R_BAD_ARGS);
     }
 
-    r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_connect: nr_resolver_resolve");
+    r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_connect [%p]: nr_resolver_resolve", sock);
     if ((r=nr_resolver_resolve(config->resolver, &resource,
             nr_socket_proxy_tunnel_resolved_cb, (void *)sock, &sock->resolver_handle))) {
       r_log(LOG_GENERIC,LOG_ERR,"Could not invoke DNS resolver");
       ABORT(r);
     }
 
     ABORT(R_WOULDBLOCK);
   }
@@ -342,17 +359,17 @@ abort:
 }
 
 int nr_socket_proxy_tunnel_write(void *obj, const void *msg, size_t len,
                                  size_t *written)
 {
   int r, _status;
   nr_socket_proxy_tunnel *sock = (nr_socket_proxy_tunnel*)obj;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_write");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_write [%p]", sock);
 
   if (sock->state >= PROXY_TUNNEL_CLOSED) {
     return R_FAILED;
   }
 
   if (sock->state == PROXY_TUNNEL_NONE) {
     if ((r=send_http_connect(sock))) {
       ABORT(r);
@@ -377,17 +394,17 @@ int nr_socket_proxy_tunnel_read(void *ob
 {
   int r, _status;
   char *ptr, *http_term;
   size_t bytes_read, available_buffer_len, maxlen_int;
   size_t pending;
   nr_socket_proxy_tunnel *sock = (nr_socket_proxy_tunnel*)obj;
   unsigned int http_status;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_read");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_read [%p]", sock);
 
   *len = 0;
 
   if (sock->state >= PROXY_TUNNEL_CLOSED) {
     return R_FAILED;
   }
 
   if (sock->state == PROXY_TUNNEL_CONNECTED) {
@@ -400,30 +417,32 @@ int nr_socket_proxy_tunnel_read(void *ob
     ABORT(R_INTERNAL);
   }
 
   /* Do not read more than maxlen bytes */
   available_buffer_len = sizeof(sock->buffer) - sock->buffered_bytes;
   maxlen_int = maxlen < available_buffer_len ? maxlen : available_buffer_len;
   if ((r=nr_socket_read(sock->inner, sock->buffer + sock->buffered_bytes,
           maxlen_int, &bytes_read, 0))) {
+    r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_read [%p]: failed to read from socket %d", sock, r);
     ABORT(r);
   }
 
   sock->buffered_bytes += bytes_read;
 
   if (http_term = find_http_terminator(sock->buffer, sock->buffered_bytes)) {
     if ((r = parse_http_response(sock->buffer, http_term, &http_status))) {
+      r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_read [%p]: failed to extract HTTP response code with error %d", sock, r);
       ABORT(r);
     }
 
     /* TODO (bug 1115934): Handle authentication challenges. */
     if (http_status < 200 || http_status >= 300) {
-      r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_read unable to connect %u",
-            http_status);
+      r_log(LOG_GENERIC,LOG_ERR,"nr_socket_proxy_tunnel_read [%p]: connect failed with HTTP response code %u",
+            sock, http_status);
       ABORT(R_FAILED);
     }
 
     sock->state = PROXY_TUNNEL_CONNECTED;
 
     ptr = http_term + strlen(END_HEADERS);
     pending = sock->buffered_bytes - (ptr - sock->buffer);
 
@@ -432,36 +451,39 @@ int nr_socket_proxy_tunnel_read(void *ob
     }
 
     assert(pending <= maxlen);
     *len = pending;
 
     memcpy(buf, ptr, *len);
   }
 
+  r_log(LOG_GENERIC,LOG_WARNING,"nr_proxy_tunnel_read [%p]: failed to find HTTP terminator in response", sock);
   _status=0;
 abort:
   if (_status && _status != R_WOULDBLOCK) {
-      sock->state = PROXY_TUNNEL_FAILED;
+    r_log(LOG_GENERIC,LOG_ERR,"nr_proxy_tunnel_read [%p]: failure %d", sock,
+          _status);
+    nr_socket_proxy_tunnel_set_state(sock, PROXY_TUNNEL_FAILED);
   }
   return(_status);
 }
 
 int nr_socket_proxy_tunnel_close(void *obj)
 {
   nr_socket_proxy_tunnel *sock = (nr_socket_proxy_tunnel*)obj;
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_close");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_close [%p]", sock);
 
   if (sock->resolver_handle) {
     nr_resolver_cancel(sock->config->resolver, sock->resolver_handle);
     sock->resolver_handle = 0;
   }
 
-  sock->state = PROXY_TUNNEL_CLOSED;
+  nr_socket_proxy_tunnel_set_state(sock, PROXY_TUNNEL_CLOSED);
 
   return nr_socket_close(sock->inner);
 }
 
 int nr_proxy_tunnel_config_create(nr_proxy_tunnel_config **configpp)
 {
   int _status;
   nr_proxy_tunnel_config *configp=0;
@@ -609,17 +631,17 @@ int nr_socket_proxy_tunnel_create(nr_pro
 
   if ((r=nr_proxy_tunnel_config_copy(config, &sock->config)))
     ABORT(r);
 
   if ((r=nr_socket_create_int(sock, &nr_socket_proxy_tunnel_vtbl, socketpp))) {
     ABORT(r);
   }
 
-  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_created");
+  r_log(LOG_GENERIC,LOG_DEBUG,"nr_socket_proxy_tunnel_created [%p]", sock);
 
   _status=0;
 abort:
   if (_status) {
     sockv = sock;
     nr_socket_proxy_tunnel_destroy(&sockv);
   }
   return(_status);