Improved trace logging in httpc to help with debugging bug #3843

https://tvheadend.org/issues/3843#change-20135

src/httpc.c

@@ -127,6 +127,7 @@ http_client_shutdown ( http_client_t *hc, int force, int reconnect )
 {
   struct http_client_ssl *ssl = hc->hc_ssl;
 
+  tvhtrace(LS_HTTPC, "%04X: shutdown", shortid(hc));
   hc->hc_shutdown = 1;
   if (ssl) {
     if (!ssl->shutdown) {
@@ -173,13 +174,15 @@ http_client_poll_dir ( http_client_t *hc, int in, int out )
   tvhpoll_event_t ev;
   if (hc->hc_efd) {
     if (events == 0 && hc->hc_pause) {
+      tvhtrace(LS_HTTPC, "%04X: pausing input", shortid(hc));
       if (hc->hc_pevents_pause == 0)
         hc->hc_pevents_pause = hc->hc_pevents;
       memset(&ev, 0, sizeof(ev));
       ev.fd       = hc->hc_fd;
       ev.data.ptr = hc;
       tvhpoll_rem(hc->hc_efd, &ev, 1);
     } else if (hc->hc_pevents != events) {
+      tvhtrace(LS_HTTPC, "%04X: add poll for input%s", shortid(hc), out ? " and output" : "");
       memset(&ev, 0, sizeof(ev));
       ev.fd       = hc->hc_fd;
       ev.events   = events | TVHPOLL_IN;
@@ -196,6 +199,7 @@ void
 http_client_unpause( http_client_t *hc )
 {
   if (hc->hc_pause) {
+    tvhtrace(LS_HTTPC, "%04X: resuming input", shortid(hc));
     http_client_poll_dir(hc, hc->hc_pevents_pause & TVHPOLL_IN,
                              hc->hc_pevents_pause & TVHPOLL_OUT);
     hc->hc_pause = 0;
@@ -662,10 +666,8 @@ http_client_finish( http_client_t *hc )
   http_client_wcmd_t *wcmd;
   int res;
 
-  if (hc->hc_data && tvhtrace_enabled()) {
-    tvhtrace(LS_HTTPC, "%04X: received %s data", shortid(hc), http_ver2str(hc->hc_version));
-    tvhlog_hexdump(LS_HTTPC, hc->hc_data, hc->hc_csize);
-  }
+  tvhtrace(LS_HTTPC, "%04X: finishing", shortid(hc));
+
   if (hc->hc_in_rtp_data && hc->hc_rtp_data_complete) {
     pthread_mutex_unlock(&hc->hc_mutex);
     res = hc->hc_rtp_data_complete(hc);
@@ -953,30 +955,37 @@ http_client_run0( http_client_t *hc )
   else
     r = recv(hc->hc_fd, buf, hc->hc_io_size, MSG_DONTWAIT);
   if (r == 0) {
-    if (hc->hc_in_data && !hc->hc_keepalive)
+    tvhtrace(LS_HTTPC, "%04X: end of stream", shortid(hc));
+    if (hc->hc_in_data && !hc->hc_keepalive) {
+      tvhtrace(LS_HTTPC, "%04X: no keep-alive, finishing", shortid(hc));
       return http_client_finish(hc);
+    }
     return http_client_flush(hc, -EIO);
   }
   if (r < 0) {
-    if (errno == EIO && hc->hc_in_data && !hc->hc_keepalive)
+    if (errno == EIO && hc->hc_in_data && !hc->hc_keepalive) {
+      tvhtrace(LS_HTTPC, "%04X: error reading: %s", shortid(hc), strerror(errno));
+      tvhtrace(LS_HTTPC, "%04X: no keep-alive, finishing", shortid(hc));
       return http_client_finish(hc);
+    }
     if (ERRNO_AGAIN(errno))
       return HTTP_CON_RECEIVING;
+    tvhtrace(LS_HTTPC, "%04X: error reading: %s", shortid(hc), strerror(errno));
     return http_client_flush(hc, -errno);
   }
-  if (r > 0 && tvhtrace_enabled()) {
-    tvhtrace(LS_HTTPC, "%04X: received %s answer (len = %zd)", shortid(hc), http_ver2str(hc->hc_version), r);
-    tvhlog_hexdump(LS_HTTPC, buf, MIN(64, r));
-  }
 
   if (hc->hc_in_data && !hc->hc_in_rtp_data) {
     res = http_client_data_received(hc, buf, r, 0);
     if (res < 0)
       return http_client_flush(hc, res);
-    if (res > 0)
+    if (res > 0) {
+      tvhtrace(LS_HTTPC, "%04X: data complete, finishing", shortid(hc));
       return http_client_finish(hc);
-    if (hc->hc_data_limit && r + hc->hc_rsize >= hc->hc_data_limit)
+    }
+    if (hc->hc_data_limit && r + hc->hc_rsize >= hc->hc_data_limit) {
+      tvhtrace(LS_HTTPC, "%04X: data overflow", shortid(hc));
       return http_client_flush(hc, -EOVERFLOW);
+    }
     goto retry;
   }