Improved stability of the ippusbxd daemon when hammered by many requests

IPP-over-USB printers have only a few channels (USB interfaces, at
least 2) for processing requests in parallel. For printing (needs 2
channels, 1 for the data, 1 for monitoring the printer status) and for
querying capabilities or status (usually only 1 interface) this works
very well. But if one tries to access the printer's web admin
interface, the start page pulls in many images (buttons, logos, ...)
and other resources (CSS style sheets, ...) and the web browser tries
to load them all at once and the printer's limited amount of
interfaces cannot process all these requests which made ippusbxd
locking up or terminate with a fatal error.

To prevent this, the following changes were done:

- Let a thread time out when it waits more than 3 seconds for a free
  USB interface.

- Let a thread time out if it waits for more than 3 seconds for a new
  message from the client.

- Do not treat errors in the USB and TCP functions fatal any more,
  instead, simply close the appropriate thread.

- Use a spinlock also when releasing a USB interface.

Note: The changes only prevent lock-ups and fatal errors of ippusbxd,
to kep running the daemon for subsequent requests, they do not make
the web interface completely working.

6 files changed, 110 insertions, 44 deletions

diff --git a/src/http.c b/src/http.c
index 8ce87cd..1fe8557 100644
--- a/src/http.c
+++ b/src/http.c
@@ -54,7 +54,7 @@ static void packet_check_completion(struct http_packet_t *pkt)
 	// Msg full
 	if (msg->claimed_size && msg->received_size >= msg->claimed_size) {
 		msg->is_completed = 1;
-		NOTE("http: Message completed: Received size > claimed size");
+		NOTE("http: Message completed: Received size >= claimed size");
 
 		// Sanity check
 		if (msg->spare_filled > 0)
diff --git a/src/ippusbxd.c b/src/ippusbxd.c
index 0a39c09..7e8e6f7 100644
--- a/src/ippusbxd.c
+++ b/src/ippusbxd.c
@@ -42,7 +42,7 @@ static void *service_connection(void *arg_void)
 	// classify priority
 	struct usb_conn_t *usb = NULL;
 	int usb_failed = 0;
-	while (!arg->tcp->is_closed) {
+	while (!arg->tcp->is_closed && usb_failed == 0) {
 		struct http_message_t *server_msg = NULL;
 		struct http_message_t *client_msg = NULL;
 
@@ -74,6 +74,7 @@ static void *service_connection(void *arg_void)
 					ERR("Thread #%d: M %p: Failed to acquire usb interface",
 					    arg->thread_num, client_msg);
 					packet_free(pkt);
+					usb_failed = 1;
 					goto cleanup_subconn;
 				}
 				usb_failed = 0;
@@ -89,7 +90,13 @@ static void *service_connection(void *arg_void)
 			// In no-printer mode we simply ignore passing the
 			// client message on to the printer
 			if (arg->usb_sock != NULL) {
-				usb_conn_packet_send(usb, pkt);
+			        if (usb_conn_packet_send(usb, pkt) == 0) {
+				        ERR("Thread #%d: M %p P %p: Interface #%d: Unable to send client package via USB",
+					    arg->thread_num,
+					    client_msg, pkt, usb->interface_index);
+					packet_free(pkt);
+					goto cleanup_subconn;
+				}
 				NOTE("Thread #%d: M %p P %p: Interface #%d: Client pkt done",
 				     arg->thread_num,
 				     client_msg, pkt, usb->interface_index);
@@ -127,7 +134,7 @@ static void *service_connection(void *arg_void)
 				pkt = usb_conn_packet_get(usb, server_msg);
 				if (pkt == NULL) {
 					usb_failed = 1;
-					break;
+					goto cleanup_subconn;
 				}
 			} else {
 				// In no-printer mode we "invent" the answer
@@ -147,7 +154,13 @@ static void *service_connection(void *arg_void)
 			NOTE("Thread #%d: M %p P %p: Pkt from usb (buffer size: %d)\n===\n%s===",
 			     arg->thread_num, server_msg, pkt, pkt->filled_size,
 			     hexdump(pkt->buffer, (int)pkt->filled_size));
-			tcp_packet_send(arg->tcp, pkt);
+			if (tcp_packet_send(arg->tcp, pkt) == 0) {
+				ERR("Thread #%d: M %p P %p: Unable to send client package via TCP",
+				    arg->thread_num,
+				    client_msg, pkt);
+				packet_free(pkt);
+				goto cleanup_subconn;
+			}
 			if (usb != NULL)
 				NOTE("Thread #%d: M %p P %p: Interface #%d: Server pkt done",
 				     arg->thread_num, server_msg, pkt,
diff --git a/src/tcp.c b/src/tcp.c
index e1e4d1d..f5c6107 100644
--- a/src/tcp.c
+++ b/src/tcp.c
@@ -172,6 +172,12 @@ struct http_packet_t *tcp_packet_get(struct tcp_conn_t *tcp,
 		return pkt;
 	}
 
+	struct timeval tv;
+	tv.tv_sec = 3;
+	tv.tv_usec = 0;
+	setsockopt(tcp->sd, SOL_SOCKET, SO_RCVTIMEO,
+		   (char *)&tv, sizeof(struct timeval));
+
 	while (want_size != 0 && !msg->is_completed) {
 		NOTE("TCP: Getting %d bytes", want_size);
 		uint8_t *subbuffer = pkt->buffer + pkt->filled_size;
@@ -180,6 +186,7 @@ struct http_packet_t *tcp_packet_get(struct tcp_conn_t *tcp,
 			int errno_saved = errno;
 			ERR("recv failed with err %d:%s", errno_saved,
 				strerror(errno_saved));
+			tcp->is_closed = 1;
 			goto error;
 		}
 		NOTE("TCP: Got %d bytes", gotten_size);
@@ -207,7 +214,7 @@ error:
 	return NULL;
 }
 
-void tcp_packet_send(struct tcp_conn_t *conn, struct http_packet_t *pkt)
+int tcp_packet_send(struct tcp_conn_t *conn, struct http_packet_t *pkt)
 {
 	size_t remaining = pkt->filled_size;
 	size_t total = 0;
@@ -217,9 +224,10 @@ void tcp_packet_send(struct tcp_conn_t *conn, struct http_packet_t *pkt)
 		if (sent < 0) {
 			if (errno == EPIPE) {
 				conn->is_closed = 1;
-				return;
+				return 1;
 			}
-			ERR_AND_EXIT("Failed to sent data over TCP");
+			ERR("Failed to sent data over TCP");
+			return 0;
 		}
 
 		size_t sent_ulong = (unsigned) sent;
@@ -230,6 +238,7 @@ void tcp_packet_send(struct tcp_conn_t *conn, struct http_packet_t *pkt)
 			remaining -= sent_ulong;
 	}
 	NOTE("TCP: sent %lu bytes", total);
+	return 1;
 }
 
 
diff --git a/src/tcp.h b/src/tcp.h
index 77a4eeb..eda7f24 100644
--- a/src/tcp.h
+++ b/src/tcp.h
@@ -50,4 +50,4 @@ void tcp_conn_close(struct tcp_conn_t *);
 
 struct http_packet_t *tcp_packet_get(struct tcp_conn_t *,
                                      struct http_message_t *);
-void tcp_packet_send(struct tcp_conn_t *, struct http_packet_t *);
+int tcp_packet_send(struct tcp_conn_t *, struct http_packet_t *);
diff --git a/src/usb.c b/src/usb.c
index 9805c90..42efe03 100644
--- a/src/usb.c
+++ b/src/usb.c
@@ -166,9 +166,11 @@ struct usb_sock_t *usb_open()
 			status = libusb_get_config_descriptor(candidate,
 			                                      config_num,
 			                                      &config);
-			if (status < 0)
-				ERR_AND_EXIT("USB: didn't get config desc %s",
-					libusb_error_name(status));
+			if (status < 0) {
+				ERR("USB: didn't get config desc %s",
+				    libusb_error_name(status));
+				goto error;
+			}
 
 			int interface_count = count_ippoverusb_interfaces(config);
 			libusb_free_config_descriptor(config);
@@ -187,7 +189,8 @@ struct usb_sock_t *usb_open()
 			}
 
 			if (!auto_pick) {
-				ERR_AND_EXIT("No ipp-usb interfaces found");
+				ERR("No ipp-usb interfaces found");
+				goto error;
 			}
 		}
 	}
@@ -481,15 +484,21 @@ static int usb_all_conns_staled(struct usb_sock_t *usb)
 struct usb_conn_t *usb_conn_acquire(struct usb_sock_t *usb)
 {
 
+        int i;
 	if (usb->num_avail <= 0) {
 		NOTE("All USB interfaces busy, waiting ...");
-		while (usb->num_avail <= 0)
-			usleep(100000);
+		for (i = 0; i < 30 && usb->num_avail <= 0; i ++)
+		  usleep(100000);
+		if (usb->num_avail <= 0) {
+		        ERR("Timed out waiting for a free USB interface");
+		        return NULL;
+		}
+		usleep(100000);
 	}
 
 	struct usb_conn_t *conn = calloc(1, sizeof(*conn));
 	if (conn == NULL) {
-		ERR("failed to aloc space for usb connection");
+		ERR("Failed to alloc space for usb connection");
 		return NULL;
 	}
 
@@ -498,8 +507,6 @@ struct usb_conn_t *usb_conn_acquire(struct usb_sock_t *usb)
 		conn->parent = usb;
 
 		uint32_t slot = usb->num_taken;
-		usb->num_taken++;
-		usb->num_avail--;
 
 		conn->interface_index = usb->interface_pool[slot];
 		conn->interface = usb->interfaces + conn->interface_index;
@@ -507,9 +514,10 @@ struct usb_conn_t *usb_conn_acquire(struct usb_sock_t *usb)
 
 		// Sanity check: Is the interface still free
 		if (sem_trywait(&uf->lock)) {
-		  ERR_AND_EXIT("Interface #%d (%d) already in use!",
-			       conn->interface_index,
-			       uf->libusb_interface_index);
+		  ERR("Interface #%d (%d) already in use!",
+		      conn->interface_index,
+		      uf->libusb_interface_index);
+		  goto acquire_error;
 		}
 
 		// Make kernel release interface
@@ -531,11 +539,14 @@ struct usb_conn_t *usb_conn_acquire(struct usb_sock_t *usb)
 			// so we're left with a spinlock
 			status = libusb_claim_interface(
 				usb->printer, uf->libusb_interface_index);
+			if (status) NOTE("Failed to claim interface %d, retrying", conn->interface_index);
 			switch (status) {
 			case LIBUSB_ERROR_NOT_FOUND:
-				ERR_AND_EXIT("USB Interface did not exist");
+				ERR("USB Interface did not exist");
+				goto acquire_error;
 			case LIBUSB_ERROR_NO_DEVICE:
-				ERR_AND_EXIT("Printer was removed");
+				ERR("Printer was removed");
+				goto acquire_error;
 			default:
 				break;
 			}
@@ -545,9 +556,20 @@ struct usb_conn_t *usb_conn_acquire(struct usb_sock_t *usb)
 		libusb_set_interface_alt_setting(usb->printer,
 		                                 uf->libusb_interface_index,
 		                                 uf->interface_alt);
+
+		// Take successfully acquired interface from the pool
+		usb->num_taken++;
+		usb->num_avail--;
 	}
 	sem_post(&usb->pool_manage_lock);
 	return conn;
+
+ acquire_error:
+
+	sem_post(&usb->pool_manage_lock);
+	free(conn);
+	return NULL;
+
 }
 
 void usb_conn_release(struct usb_conn_t *conn)
@@ -555,8 +577,15 @@ void usb_conn_release(struct usb_conn_t *conn)
 	struct usb_sock_t *usb = conn->parent;
 	sem_wait(&usb->pool_manage_lock);
 	{
-		libusb_release_interface(usb->printer,
+		int status = 0;
+		do {
+			// Spinlock-like
+			// Libusb does not offer a blocking call
+			// so we're left with a spinlock
+		        status = libusb_release_interface(usb->printer,
 				conn->interface->libusb_interface_index);
+			if (status) NOTE("Failed to release interface %d, retrying", conn->interface_index);
+		} while (status != 0);
 
 		// Return usb interface to pool
 		usb->num_taken--;
@@ -572,7 +601,7 @@ void usb_conn_release(struct usb_conn_t *conn)
 	sem_post(&usb->pool_manage_lock);
 }
 
-void usb_conn_packet_send(struct usb_conn_t *conn, struct http_packet_t *pkt)
+int usb_conn_packet_send(struct usb_conn_t *conn, struct http_packet_t *pkt)
 {
 	int size_sent = 0;
 	const int timeout = 1000; // 1 sec
@@ -587,15 +616,19 @@ void usb_conn_packet_send(struct usb_conn_t *conn, struct http_packet_t *pkt)
 		                                  conn->interface->endpoint_out,
 		                                  pkt->buffer + sent, to_send,
 		                                  &size_sent, timeout);
-		if (status == LIBUSB_ERROR_NO_DEVICE)
-			ERR_AND_EXIT("P %p: Printer has been disconnected",
-				     pkt);
+		if (status == LIBUSB_ERROR_NO_DEVICE) {
+			ERR("P %p: Printer has been disconnected",
+			    pkt);
+			return 0;
+		}
 		if (status == LIBUSB_ERROR_TIMEOUT) {
 			NOTE("P %p: USB: send timed out, retrying", pkt);
 
-			if (num_timeouts++ > PRINTER_CRASH_TIMEOUT_RECEIVE)
-				ERR_AND_EXIT("P %p: Usb send fully timed out",
-					     pkt);
+			if (num_timeouts++ > PRINTER_CRASH_TIMEOUT_RECEIVE) {
+				ERR("P %p: Usb send fully timed out",
+				    pkt);
+				return 0;
+			}
 
 			// Sleep for tenth of a second
 			struct timespec sleep_dur;
@@ -604,18 +637,23 @@ void usb_conn_packet_send(struct usb_conn_t *conn, struct http_packet_t *pkt)
 			nanosleep(&sleep_dur, NULL);
 			if (size_sent == 0)
 				continue;
-		} else if (status < 0)
-			ERR_AND_EXIT("P %p: USB: send failed with status %s",
-				     pkt, libusb_error_name(status));
-		if (size_sent < 0)
-			ERR_AND_EXIT("P %p: Unexpected negative size_sent",
-				     pkt);
+		} else if (status < 0) {
+			ERR("P %p: USB: send failed with status %s",
+			    pkt, libusb_error_name(status));
+			return 0;
+		}
+		if (size_sent < 0) {
+			ERR("P %p: Unexpected negative size_sent",
+			    pkt);
+			return 0;
+		}
 
 		pending -= (size_t) size_sent;
 		sent += (size_t) size_sent;
 		NOTE("P %p: USB: sent %d bytes", pkt, size_sent);
 	}
 	NOTE("P %p: USB: sent %d bytes in total", pkt, sent);
+	return 1;
 }
 
 struct http_packet_t *usb_conn_packet_get(struct usb_conn_t *conn, struct http_message_t *msg)
@@ -646,8 +684,10 @@ struct http_packet_t *usb_conn_packet_get(struct usb_conn_t *conn, struct http_m
 
 		// Expand buffer if needed
 		if (pkt->buffer_capacity < pkt->filled_size + read_size_ulong)
-			if (packet_expand(pkt) < 0)
-				ERR_AND_EXIT("Failed to ensure room for usb pkt");
+			if (packet_expand(pkt) < 0) {
+				ERR("Failed to ensure room for usb pkt");
+				goto cleanup;
+			}
 
 		int gotten_size = 0;
 		int status = libusb_bulk_transfer(
@@ -657,8 +697,10 @@ struct http_packet_t *usb_conn_packet_get(struct usb_conn_t *conn, struct http_m
 		                      read_size,
 		                      &gotten_size, timeout);
 
-		if (status == LIBUSB_ERROR_NO_DEVICE)
-			ERR_AND_EXIT("Printer has been disconnected");
+		if (status == LIBUSB_ERROR_NO_DEVICE) {
+			ERR("Printer has been disconnected");
+			goto cleanup;
+		}
 
 		if (status != 0 && status != LIBUSB_ERROR_TIMEOUT) {
 			ERR("bulk xfer failed with error code %d", status);
@@ -670,8 +712,10 @@ struct http_packet_t *usb_conn_packet_get(struct usb_conn_t *conn, struct http_m
 			    read_size, gotten_size);
 		}
 
-		if (gotten_size < 0)
-			ERR_AND_EXIT("Negative read size unexpected");
+		if (gotten_size < 0) {
+			ERR("Negative read size unexpected");
+			goto cleanup;
+		}
 
 		if (gotten_size > 0) {
 			times_staled = 0;
diff --git a/src/usb.h b/src/usb.h
index 7a261ed..e376a77 100644
--- a/src/usb.h
+++ b/src/usb.h
@@ -66,6 +66,6 @@ void usb_register_callback(struct usb_sock_t *);
 struct usb_conn_t *usb_conn_acquire(struct usb_sock_t *);
 void usb_conn_release(struct usb_conn_t *);
 
-void usb_conn_packet_send(struct usb_conn_t *, struct http_packet_t *);
+int usb_conn_packet_send(struct usb_conn_t *, struct http_packet_t *);
 struct http_packet_t *usb_conn_packet_get(struct usb_conn_t *, struct http_message_t *);