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

@@ -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;

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
  *

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,23 +185,42 @@ 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;
 		}
 
 		buf.type = V4L2_BUF_TYPE_VIDEO_CAPTURE;
 		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);