From bb264b2b330c606649e53e09045f9a25db7c31ef Mon Sep 17 00:00:00 2001
From: Piotr Esden-Tempski <piotr@esden.net>
Date: Sat, 2 Jan 2021 14:44:09 -0800
Subject: [PATCH] linux-v4l2: Improve error and debug logging

The capture loop errors are now logged as such.
Increased the amount of information logged in debug mode, including
state of all buffers on timeout.
Add device name to all capture loop debug output, especially useful when
debugging issues with multiple v4l2 video streams.
---
 plugins/linux-v4l2/v4l2-helpers.c | 28 ++++++++++++++++++++++
 plugins/linux-v4l2/v4l2-helpers.h | 14 +++++++++++
 plugins/linux-v4l2/v4l2-input.c   | 39 ++++++++++++++++++++++++++-----
 3 files changed, 75 insertions(+), 6 deletions(-)

diff --git a/plugins/linux-v4l2/v4l2-helpers.c b/plugins/linux-v4l2/v4l2-helpers.c
index ff57f0eb9..0ae73397f 100644
--- a/plugins/linux-v4l2/v4l2-helpers.c
+++ b/plugins/linux-v4l2/v4l2-helpers.c
@@ -61,6 +61,34 @@ int_fast32_t v4l2_stop_capture(int_fast32_t dev)
 	return 0;
 }
 
+#ifdef _DEBUG
+int_fast32_t v4l2_query_all_buffers(int_fast32_t dev,
+				    struct v4l2_buffer_data *buf_data)
+{
+	struct v4l2_buffer buf;
+
+	blog(LOG_DEBUG, "attempting to read buffer data for %ld buffers",
+	     buf_data->count);
+
+	for (uint_fast32_t i = 0; i < buf_data->count; i++) {
+		buf.index = i;
+		buf.type = V4L2_BUF_TYPE_VIDEO_CAPTURE;
+		buf.memory = V4L2_MEMORY_MMAP;
+		if (v4l2_ioctl(dev, VIDIOC_QUERYBUF, &buf) < 0) {
+			blog(LOG_DEBUG,
+			     "failed to read buffer data for buffer #%ld", i);
+		} else {
+			blog(LOG_DEBUG,
+			     "query buf #%ld info: ts: %06ld buf id #%d, flags 0x%08X, seq #%d, len %d, used %d",
+			     i, buf.timestamp.tv_usec, buf.index, buf.flags,
+			     buf.sequence, buf.length, buf.bytesused);
+		}
+	}
+
+	return 0;
+}
+#endif
+
 int_fast32_t v4l2_create_mmap(int_fast32_t dev, struct v4l2_buffer_data *buf)
 {
 	struct v4l2_requestbuffers req;
diff --git a/plugins/linux-v4l2/v4l2-helpers.h b/plugins/linux-v4l2/v4l2-helpers.h
index 19c7226b9..69b1c8d08 100644
--- a/plugins/linux-v4l2/v4l2-helpers.h
+++ b/plugins/linux-v4l2/v4l2-helpers.h
@@ -184,6 +184,20 @@ int_fast32_t v4l2_start_capture(int_fast32_t dev, struct v4l2_buffer_data *buf);
  */
 int_fast32_t v4l2_stop_capture(int_fast32_t dev);
 
+#ifdef _DEBUG
+/**
+ * Query the status of all buffers.
+ * Only used for debug purposes.
+ *
+ * @param dev handle for the v4l2 device
+ * @param buf_data buffer data
+ *
+ * @return negative on failure
+ */
+int_fast32_t v4l2_query_all_buffers(int_fast32_t dev,
+				    struct v4l2_buffer_data *buf_data);
+#endif
+
 /**
  * Create memory mapping for buffers
  *
diff --git a/plugins/linux-v4l2/v4l2-input.c b/plugins/linux-v4l2/v4l2-input.c
index 7be6ed00e..c1e31d9b5 100644
--- a/plugins/linux-v4l2/v4l2-input.c
+++ b/plugins/linux-v4l2/v4l2-input.c
@@ -162,13 +162,19 @@ static void *v4l2_thread(void *vptr)
 	struct obs_source_frame out;
 	size_t plane_offsets[MAX_AV_PLANES];
 
+	blog(LOG_DEBUG, "%s: new capture thread", data->device_id);
+
 	if (v4l2_start_capture(data->dev, &data->buffers) < 0)
 		goto exit;
 
+	blog(LOG_DEBUG, "%s: new capture started", data->device_id);
+
 	frames = 0;
 	first_ts = 0;
 	v4l2_prep_obs_frame(data, &out, plane_offsets);
 
+	blog(LOG_DEBUG, "%s: obs frame prepared", data->device_id);
+
 	while (os_event_try(data->event) == EAGAIN) {
 		FD_ZERO(&fds);
 		FD_SET(data->dev, &fds);
@@ -179,10 +185,20 @@ static void *v4l2_thread(void *vptr)
 		if (r < 0) {
 			if (errno == EINTR)
 				continue;
-			blog(LOG_DEBUG, "select failed");
+			blog(LOG_ERROR, "%s: select failed", data->device_id);
 			break;
 		} else if (r == 0) {
-			blog(LOG_DEBUG, "select timeout");
+			blog(LOG_ERROR, "%s: select timed out",
+			     data->device_id);
+
+#ifdef _DEBUG
+			v4l2_query_all_buffers(data->dev, &data->buffers);
+#endif
+
+			if (v4l2_ioctl(data->dev, VIDIOC_LOG_STATUS) < 0) {
+				blog(LOG_ERROR, "%s: failed to log status",
+				     data->device_id);
+			}
 			continue;
 		}
 
@@ -190,12 +206,21 @@ static void *v4l2_thread(void *vptr)
 		buf.memory = V4L2_MEMORY_MMAP;
 
 		if (v4l2_ioctl(data->dev, VIDIOC_DQBUF, &buf) < 0) {
-			if (errno == EAGAIN)
+			if (errno == EAGAIN) {
+				blog(LOG_DEBUG, "%s: ioctl dqbuf eagain",
+				     data->device_id);
 				continue;
-			blog(LOG_DEBUG, "failed to dequeue buffer");
+			}
+			blog(LOG_ERROR, "%s: failed to dequeue buffer",
+			     data->device_id);
 			break;
 		}
 
+		blog(LOG_DEBUG,
+		     "%s: ts: %06ld buf id #%d, flags 0x%08X, seq #%d, len %d, used %d",
+		     data->device_id, buf.timestamp.tv_usec, buf.index,
+		     buf.flags, buf.sequence, buf.length, buf.bytesused);
+
 		out.timestamp = timeval2ns(buf.timestamp);
 		if (!frames)
 			first_ts = out.timestamp;
@@ -207,14 +232,16 @@ static void *v4l2_thread(void *vptr)
 		obs_source_output_video(data->source, &out);
 
 		if (v4l2_ioctl(data->dev, VIDIOC_QBUF, &buf) < 0) {
-			blog(LOG_DEBUG, "failed to enqueue buffer");
+			blog(LOG_ERROR, "%s: failed to enqueue buffer",
+			     data->device_id);
 			break;
 		}
 
 		frames++;
 	}
 
-	blog(LOG_INFO, "Stopped capture after %" PRIu64 " frames", frames);
+	blog(LOG_INFO, "%s: Stopped capture after %" PRIu64 " frames",
+	     data->device_id, frames);
 
 exit:
 	v4l2_stop_capture(data->dev);