Reducing logging code and making fixes to web scanning

This patch changes the tcp_packet_get() function so that if an attempted
read from the tcp socket were to time out while the printer is still
transferring data then the connection will remain open.

This should fix any issues with high dpi scanning, as in earlier
versions the socket was being closed prematurely while the printer was
still streaming data over the socket from the scan.

This patch also cuts down on some of the unnecessary logging code.

3 files changed, 84 insertions, 45 deletions

diff --git a/src/ippusbxd.c b/src/ippusbxd.c
index f9ab016..2416575 100644
--- a/src/ippusbxd.c
+++ b/src/ippusbxd.c
@@ -194,14 +194,17 @@ static void read_transfer_callback(struct libusb_transfer *transfer)
 
   switch (transfer->status) {
     case LIBUSB_TRANSFER_COMPLETED:
-      NOTE("Thread #%u: Transfer has completed successfully", thread_num);
       user_data->pkt->filled_size = transfer->actual_length;
 
-      NOTE("Thread #%u: Pkt from %s (buffer size: %zu)\n===\n%s===", thread_num,
-           "usb", user_data->pkt->filled_size,
-           hexdump(user_data->pkt->buffer, (int)user_data->pkt->filled_size));
+      if (transfer->actual_length) {
+        NOTE("Thread #%u: Pkt from %s (buffer size: %zu)\n===\n%s===", thread_num,
+             "usb", user_data->pkt->filled_size,
+             hexdump(user_data->pkt->buffer, (int)user_data->pkt->filled_size));
 
-      tcp_packet_send(user_data->tcp, user_data->pkt);
+        tcp_packet_send(user_data->tcp, user_data->pkt);
+        /* Mark the tcp socket as active. */
+        set_is_active(user_data->tcp, 1);
+      }
 
       break;
     case LIBUSB_TRANSFER_ERROR:
@@ -235,6 +238,9 @@ static void read_transfer_callback(struct libusb_transfer *transfer)
       g_options.terminate = 1;
   }
 
+  /* Free the packet used for the transfer. */
+  packet_free(user_data->pkt);
+
   /* Mark the transfer as completed. */
   pthread_mutex_lock(read_inflight_mutex);
   *user_data->read_inflight = 0;
@@ -242,7 +248,6 @@ static void read_transfer_callback(struct libusb_transfer *transfer)
   pthread_mutex_unlock(read_inflight_mutex);
 
   /* Cleanup the data used for the transfer */
-  packet_free(user_data->pkt);
   free(user_data);
   libusb_free_transfer(transfer);
 }
@@ -262,8 +267,6 @@ static void *service_connection(void *params_void)
       (struct service_thread_param *)params_void;
   uint32_t thread_num = params->thread_num;
 
-  NOTE("Thread #%u: Setting up both ends for communication", thread_num);
-
   /* Detach this thread so that the main thread does not need to join this
      thread after termination for clean-up. */
   pthread_detach(pthread_self());
@@ -293,8 +296,6 @@ static void *service_connection(void *params_void)
   printer_params->thread_num += 1;
 
   /* Attempt to start the printer's end of the communication. */
-  NOTE("Thread #%u: Attempting to register thread %u", thread_num,
-       thread_num + 1);
   if (setup_communication_thread(&service_printer_connection, printer_params))
     goto cleanup;
 
@@ -338,27 +339,36 @@ static void service_socket_connection(struct service_thread_param *params)
 {
   uint32_t thread_num = params->thread_num;
 
-  NOTE("Thread #%u: Starting on socket end", thread_num);
-
   struct http_packet_t *pkt = NULL;
 
   while (is_socket_open(params) && !g_options.terminate) {
-    pkt = tcp_packet_get(params->tcp);
-
+    /* Allocate packet for incoming message. */
+    struct http_packet_t *pkt = packet_new();
     if (pkt == NULL) {
-      if (!is_socket_open(params))
-        NOTE("Thread: #%u: Client closed connection", thread_num);
-      else
-        NOTE("Thread: #%u: There was an error reading from the socket",
-             thread_num);
+      ERR("Failed to allocate packet for incoming tcp message");
       return;
     }
 
-    NOTE("Thread #%u: Pkt from tcp (buffer size: %zu)\n===\n%s===", thread_num,
-         pkt->filled_size, hexdump(pkt->buffer, (int)pkt->filled_size));
+    int status = tcp_packet_get(params->tcp, pkt);
+    if (status) {
+      NOTE("Thread #%u: There was an error reading from the socket",
+           thread_num);
+      return;
+    }
+
+    if (!is_socket_open(params)) {
+      NOTE("Thread #%u: Client closed connection", thread_num);
+      return;
+    }
+
+    if (pkt->filled_size) {
+      NOTE("Thread #%u: Pkt from tcp (buffer size: %zu)\n===\n%s===", thread_num,
+           pkt->filled_size, hexdump(pkt->buffer, (int)pkt->filled_size));
+
+      /* Send pkt to printer. */
+      usb_conn_packet_send(params->usb_conn, pkt);
+    }
 
-    /* Send pkt to printer. */
-    usb_conn_packet_send(params->usb_conn, pkt);
     packet_free(pkt);
   }
 }
@@ -392,8 +402,6 @@ static void *service_printer_connection(void *params_void)
       (struct service_thread_param *)params_void;
   uint32_t thread_num = params->thread_num;
 
-  NOTE("Thread #%u: Starting on printer end", thread_num);
-
   /* Register clean-up handler. */
   pthread_cleanup_push(cleanup_handler, &thread_num);
 
@@ -418,7 +426,6 @@ static void *service_printer_connection(void *params_void)
     if (!is_socket_open(params) || g_options.terminate)
       break;
 
-    NOTE("Thread #%u: No read in flight, starting a new one", thread_num);
     struct http_packet_t *pkt = packet_new();
     if (pkt == NULL) {
       ERR("Thread #%u: Failed to allocate packet", thread_num);
@@ -435,7 +442,7 @@ static void *service_printer_connection(void *params_void)
     }
 
     read_transfer = setup_async_read(
-        params->usb_conn, pkt, read_transfer_callback, (void *)user_data, 2000);
+        params->usb_conn, pkt, read_transfer_callback, (void *)user_data, 5000);
 
     if (read_transfer == NULL) {
       ERR("Thread #%u: Failed to allocate memory for libusb transfer",
diff --git a/src/tcp.c b/src/tcp.c
index 2e08516..46fa78c 100644
--- a/src/tcp.c
+++ b/src/tcp.c
@@ -17,6 +17,7 @@
 #include <stdlib.h>
 #include <string.h>
 #include <ctype.h>
+#include <pthread.h>
 #include <sys/time.h>
 #include <sys/types.h>
 #include <unistd.h>
@@ -221,30 +222,36 @@ uint16_t tcp_port_number_get(struct tcp_sock_t *sock)
   return 0;
 }
 
-struct http_packet_t *tcp_packet_get(struct tcp_conn_t *tcp)
+int tcp_packet_get(struct tcp_conn_t *tcp, struct http_packet_t *pkt)
 {
-  /* Alloc packet ==---------------------------------------------------== */
-  struct http_packet_t *pkt = packet_new();
-  if (pkt == NULL) {
-    ERR("failed to create packet for incoming tcp message");
-    goto error;
-  }
-
   struct timeval tv;
-  tv.tv_sec = 3;
+  tv.tv_sec = 5;
   tv.tv_usec = 0;
   if (setsockopt(tcp->sd, SOL_SOCKET, SO_RCVTIMEO, &tv, sizeof(tv))) {
     ERR("TCP: Setting options for tcp connection socket failed");
-    goto error;
+    return -1;
   }
 
   ssize_t gotten_size = recv(tcp->sd, pkt->buffer, pkt->buffer_capacity, 0);
 
   if (gotten_size < 0) {
     int errno_saved = errno;
+    /* In the event that there was a timeout reading from the socket, but there
+     * has recently been data sent from the printer to the socket, then we do
+     * not return an error and simply allow for another attempt at reading from
+     * the socket. */
+    if ((errno_saved == EAGAIN || errno_saved == EWOULDBLOCK) &&
+        get_is_active(tcp)) {
+      /* Mark the the socket as inactive so that if another timeout occurs
+       * without new data being transferred on the socket then the connection
+       * will close. */
+      set_is_active(tcp, 0);
+      return 0;
+    }
+
     ERR("recv failed with err %d:%s", errno_saved, strerror(errno_saved));
     tcp->is_closed = 1;
-    goto error;
+    return -1;
   }
 
   if (gotten_size == 0) {
@@ -252,12 +259,7 @@ struct http_packet_t *tcp_packet_get(struct tcp_conn_t *tcp)
   }
 
   pkt->filled_size = gotten_size;
-  return pkt;
-
- error:
-  if (pkt != NULL)
-    packet_free(pkt);
-  return NULL;
+  return 0;
 }
 
 int tcp_packet_send(struct tcp_conn_t *conn, struct http_packet_t *pkt)
@@ -297,6 +299,7 @@ struct tcp_conn_t *tcp_conn_select(struct tcp_sock_t *sock,
     ERR("Calloc for connection struct failed");
     goto error;
   }
+
   fd_set rfds;
   int retval = 0;
   int nfds = 0;
@@ -336,6 +339,11 @@ struct tcp_conn_t *tcp_conn_select(struct tcp_sock_t *sock,
     ERR("accept failed");
     goto error;
   }
+
+  /* Attempt to initialize the connection's mutex. */
+  if (pthread_mutex_init(&conn->mutex, NULL))
+    goto error;
+
   return conn;
 
  error:
@@ -353,5 +361,22 @@ void tcp_conn_close(struct tcp_conn_t *conn)
   shutdown(conn->sd, SHUT_RDWR);
 
   close(conn->sd);
+  pthread_mutex_destroy(&conn->mutex);
   free(conn);
 }
+
+int get_is_active(struct tcp_conn_t *tcp)
+{
+  pthread_mutex_lock(&tcp->mutex);
+  int val = tcp->is_active;
+  pthread_mutex_unlock(&tcp->mutex);
+
+  return val;
+}
+
+void set_is_active(struct tcp_conn_t *tcp, int val)
+{
+  pthread_mutex_lock(&tcp->mutex);
+  tcp->is_active = val;
+  pthread_mutex_unlock(&tcp->mutex);
+}
diff --git a/src/tcp.h b/src/tcp.h
index 5ae6b4f..e79edb4 100644
--- a/src/tcp.h
+++ b/src/tcp.h
@@ -15,6 +15,8 @@
 #pragma once
 #include <stdint.h>
 
+#include <pthread.h>
+
 #include <sys/types.h>
 #include <sys/socket.h>
 #include <netinet/in.h>
@@ -37,6 +39,8 @@ struct tcp_sock_t {
 struct tcp_conn_t {
   int sd;
   int is_closed;
+  int is_active;
+  pthread_mutex_t mutex;
 };
 
 struct tcp_sock_t *tcp_open(uint16_t, char* interface);
@@ -48,5 +52,8 @@ struct tcp_conn_t *tcp_conn_select(struct tcp_sock_t *sock,
 				   struct tcp_sock_t *sock6);
 void tcp_conn_close(struct tcp_conn_t *);
 
-struct http_packet_t *tcp_packet_get(struct tcp_conn_t *);
+int tcp_packet_get(struct tcp_conn_t *, struct http_packet_t *);
 int tcp_packet_send(struct tcp_conn_t *, struct http_packet_t *);
+
+int get_is_active(struct tcp_conn_t *tcp);
+void set_is_active(struct tcp_conn_t *tcp, int val);