camera-streamer icon indicating copy to clipboard operation
camera-streamer copied to clipboard

Published 20 hours ago • verified publisher icon ayufan

Camera streamer stops sending frames (octoprint multicam setup)

Open damned-me opened this issue 11 months ago • 1 comments

I'm using camera-streamer on octopi to expose two webcams connected to a RPI4. Both webcams work correctly on other devices.

When connecting to the served ports with a GET /stream, I often get a 500 status code, as in the following response.

HTTP/1.1 500 Server Error
Content-Type: text/plain
Content-Length: 13

Server Error
No frames.

The service is up and running. A request to / demonstrates that the server correctly exposes the resource:

HTTP/1.1 200 OK
Content-Type: text/html
Content-Length: 2733
Access-Control-Allow-Origin: *

<!DOCTYPE html>

<html>
...
		<li>
			<a href="stream"><b>/stream</b></a> (MJPEG stream)</b><br>
			<br>
			<ul>
				<li>Get a live stream. Works everywhere, but consumes a ton of bandwidth.</li>
				<li>Uses resolution specified by <i>-camera-stream.height=</i>.</li>
			</ul>
		</li>
...
</body>
</html>

Note that the systemd process reports no errors when trying to connect

pi@octoprint:~ $ sudo systemctl status [email protected]
● [email protected] - camera-streamer endoscope
     Loaded: loaded (/etc/systemd/system/[email protected]; disabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/[email protected]
             └─override.conf
     Active: active (running) since Thu 2024-03-07 18:37:23 CET; 3h 8min ago
TriggeredBy: ● camera-streamer-usb-endoscope.path
    Process: 1114 ExecCondition=/bin/sh -c [ -e $DEVICE ] (code=exited, status=0/SUCCESS)
    Process: 1115 ExecCondition=/bin/sh -c ! ss -ltn src :$PORT | grep -q LISTEN (code=exited, status=0/SUCCESS)
   Main PID: 1118 (camera-streamer)
      Tasks: 19 (limit: 4915)
        CPU: 25.085s
     CGroup: /system.slice/system-camera\x2dstreamer\x2dusb.slice/[email protected]
             └─1118 /usr/bin/camera-streamer --http-port=8081 --camera-type=v4l2 --camera-path=/dev/v4l/by-id/usb-Generic_HD_camera-video-index0 --camera-format=YUYV --camera-width=1280 --camera-height=720 --camera-fps=15 --camera-nbufs=4 --http-listen=0.0.0.0

Mar 07 21:38:57 octoprint sh[1118]: util/http/http.c: HTTP8081/7: Client disconnected 192.168.1.187.
Mar 07 21:44:07 octoprint sh[1118]: util/http/http.c: HTTP8081/8: Client connected 192.168.1.187 (fd=12).
Mar 07 21:44:07 octoprint sh[1118]: util/http/http.c: HTTP8081/8: Request 'GET' '/stream' ''
Mar 07 21:44:09 octoprint sh[1118]: util/http/http.c: HTTP8081/8: Client disconnected 192.168.1.187.
Mar 07 21:45:06 octoprint sh[1118]: util/http/http.c: HTTP8081/9: Client connected 192.168.1.187 (fd=13).
Mar 07 21:45:06 octoprint sh[1118]: util/http/http.c: HTTP8081/9: Request 'GET' '/stream' ''
Mar 07 21:45:08 octoprint sh[1118]: util/http/http.c: HTTP8081/9: Client disconnected 192.168.1.187.
Mar 07 21:46:02 octoprint sh[1118]: util/http/http.c: HTTP8081/0: Client connected 192.168.1.187 (fd=4).
Mar 07 21:46:02 octoprint sh[1118]: util/http/http.c: HTTP8081/0: Request 'GET' '/stream' ''
Mar 07 21:46:04 octoprint sh[1118]: util/httpMar 07 21:20:51 octoprint sh[645]: device/links.c: SNAPSHOT:capture:mplane:buf0: Capture image is outdated. Skipped. Now: 9950728676, vs 9830550890.
Mar 07 21:20:52 octoprint sh[645]: util/http/http.c: HTTP8080/4: Client disconnected 192.168.1.10.
Mar 07 21:22:52 octoprint sh[645]: util/http/http.c: HTTP8080/7: Client connected 192.168.1.10 (fd=11).
Mar 07 21:22:52 octoprint sh[645]: util/http/http.c: HTTP8080/7: Request 'GET' '/snapshot' ''
Mar 07 21:22:52 octoprint sh[645]: util/http/http.c: HTTP8080/7: Client disconnected 192.168.1.10.
Mar 07 21:24:52 octoprint sh[645]: util/http/http.c: HTTP8080/5: Client connected 192.168.1.10 (fd=9).
Mar 07 21:24:52 octoprint sh[645]: util/http/http.c: HTTP8080/5: Request 'GET' '/snapshot' ''
Mar 07 21:24:52 octoprint sh[645]: util/http/http.c: HTTP8080/5: Client disconnected 192.168.1.10.
Mar 07 21:26:52 octoprint sh[645]: util/http/http.c: HTTP8080/6: Client connected 192.168.1.10 (fd=10).
Mar 07 21:26:52 octoprint sh[645]: util/http/http.c: HTTP8080/6: Request 'GET' '/snapshot' ''
Mar 07 21:26:52 octoprint sh[645]: util/http/http.c: HTTP8080/6: Client disconnected 192.168.1.10.
Mar 07 21:28:53 octoprint sh[645]: util/http/http.c: HTTP8080/8: Client connected 192.168.1.10 (fd=12).
Mar 07 21:28:53 octoprint sh[645]: util/http/http.c: HTTP8080/8: Request 'GET' '/snapshot' ''
Mar 07 21:28:53 octoprint sh[645]: util/http/http.c: HTTP8080/8: Client disconnected 192.168.1.10.
Mar 07 21:30:53 octoprint sh[645]: util/http/http.c: HTTP8080/9: Client connected 192.168.1.10 (fd=13).
Mar 07 21:30:53 octoprint sh[645]: util/http/http.c: HTTP8080/9: Request 'GET' '/snapshot' ''/http.c: HTTP8081/0: Client disconnected 192.168.1.187.
lines 1-24/24 (END)

Follows the output of journalctl -u camera-streamer\* that includes the run reported in the aforementioned output, also attaching a more comprehensive version of logs here.

Mar 07 18:37:22 octoprint systemd[1]: [email protected]: Scheduled restart job, restart counter is at 1.
Mar 07 18:37:22 octoprint systemd[1]: Stopped camera-streamer endoscope.
Mar 07 18:37:22 octoprint systemd[1]: Starting camera-streamer endoscope...
Mar 07 18:37:23 octoprint systemd[1]: Started camera-streamer endoscope.
Mar 07 18:37:23 octoprint sh[1118]: util/http/http.c: ?: HTTP listening on 0.0.0.0:8081.
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device.c: CAMERA: Device path=/dev/v4l/by-id/usb-Generic_HD_camera-video-index0 fd=14 opened
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: CAMERA: The 'horizontal_flip=0' was failed to find.
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: CAMERA: The 'vertical_flip=0' was failed to find.
Mar 07 18:37:23 octoprint sh[1118]: device/camera/camera_input.c: CAMERA: Disabling DMA since device uses USB (which is likely not working properly).
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/buffer_list.c: CAMERA:capture: Requested resolution=1280x720 is unavailable. Got 640x480. Accepted
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: CAMERA:capture: Using: 640x480/YUYV, buffers=2, bytesperline=1280, sizeimage=0.6MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: CAMERA:capture: Opened 2 buffers. Memory used: 1.2 MiB
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device.c: SNAPSHOT: Device path=/dev/video31 fd=17 opened
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: SNAPSHOT:output:mplane: Using: 640x480/YUYV, buffers=2, bytesperline=1280, sizeimage=0.6MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: SNAPSHOT:output:mplane: Opened 2 buffers. Memory used: 1.2 MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: SNAPSHOT:capture:mplane: Using: 640x480/JPEG, buffers=2, bytesperline=0, sizeimage=4.0MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: SNAPSHOT:capture:mplane: Opened 2 buffers. Memory used: 8.0 MiB
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device.c: VIDEO: Device path=/dev/video11 fd=22 opened
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: VIDEO:output:mplane: Using: 640x480/YUYV, buffers=2, bytesperline=1280, sizeimage=0.6MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: VIDEO:output:mplane: Opened 2 buffers. Memory used: 1.2 MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: VIDEO:capture:mplane: Using: 640x480/H264, buffers=2, bytesperline=0, sizeimage=0.5MiB
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: VIDEO:capture:mplane: Opened 2 buffers. Memory used: 1.0 MiB
Mar 07 18:37:23 octoprint sh[1118]: device/device.c: CAMERA: Setting frame interval_us=0 for FPS=15
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: CAMERA: The 'AfTrigger=1' was failed to find.
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: SNAPSHOT: Configuring option 'Compression Quality' (009d0903) = 80
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'Repeat Sequence Header' (009909e2) = 1
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'Video Bitrate Mode' (009909ce) = 0
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'Video Bitrate' (009909cf) = 2000000
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'Repeat Sequence Header' (009909e2) = 5000000
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'H264 I-Frame Period' (00990a66) = 30
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'H264 Level' (00990a67) = 11
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'H264 Profile' (00990a6b) = 4
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'H264 Minimum QP Value' (00990a61) = 16
Mar 07 18:37:23 octoprint sh[1118]: device/v4l2/device_options.c: VIDEO: Configuring option 'H264 Maximum QP Value' (00990a62) = 32
Mar 07 18:37:23 octoprint sh[1118]: device/links.c: ?: Link 0: CAMERA:capture[640x480/YUYV/2] => [SNAPSHOT:output:mplane[640x480/YUYV/2], VIDEO:output:mplane[640x480/YUYV/2]]
Mar 07 18:37:23 octoprint sh[1118]: device/links.c: ?: Link 1: SNAPSHOT:capture:mplane[640x480/JPEG/2] => [SNAPSHOT-CAPTURE, STREAM-CAPTURE]
Mar 07 18:37:23 octoprint sh[1118]: device/links.c: ?: Link 2: VIDEO:capture:mplane[640x480/H264/2] => [VIDEO-CAPTURE]
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: CAMERA:capture: Streaming started... Was 0 of 2 enqueud
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: SNAPSHOT:output:mplane: Streaming started... Was 0 of 2 enqueud
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: VIDEO:output:mplane: Streaming started... Was 0 of 2 enqueud
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: SNAPSHOT:capture:mplane: Streaming started... Was 0 of 2 enqueud
Mar 07 18:37:23 octoprint sh[1118]: device/buffer_list.c: VIDEO:capture:mplane: Streaming started... Was 0 of 2 enqueud
Mar 07 18:37:27 octoprint sh[645]: util/http/http.c: HTTP8080/9: Client connected 192.168.1.10 (fd=13).
Mar 07 18:37:29 octoprint sh[645]: util/http/http.c: HTTP8080/9: Request 'GET' '/snapshot' ''
...
Mar 07 21:36:54 octoprint sh[645]: util/http/http.c: HTTP8080/2: Request 'GET' '/snapshot' ''
Mar 07 21:36:54 octoprint sh[645]: util/http/http.c: HTTP8080/2: Client disconnected 192.168.1.10.
Mar 07 21:38:54 octoprint sh[645]: util/http/http.c: HTTP8080/3: Client connected 192.168.1.10 (fd=7).
Mar 07 21:38:54 octoprint sh[645]: util/http/http.c: HTTP8080/3: Request 'GET' '/snapshot' ''
Mar 07 21:38:54 octoprint sh[645]: device/links.c: SNAPSHOT:capture:mplane:buf0: Capture image is outdated. Skipped. Now: 11033195947, vs 10913060413.
Mar 07 21:38:54 octoprint sh[645]: util/http/http.c: HTTP8080/3: Client disconnected 192.168.1.10.
Mar 07 21:38:55 octoprint sh[1118]: util/http/http.c: HTTP8081/7: Client connected 192.168.1.187 (fd=11).
Mar 07 21:38:55 octoprint sh[1118]: util/http/http.c: HTTP8081/7: Request 'GET' '/stream' ''
Mar 07 21:38:55 octoprint sh[1118]: device/links.c: CAMERA:capture: Stale detected. Restarting streaming...
Mar 07 21:38:55 octoprint sh[1118]: device/buffer_list.c: CAMERA:capture: Streaming stopped... Was 0 of 2 enqueud
Mar 07 21:38:55 octoprint sh[1118]: device/buffer_list.c: CAMERA:capture: Streaming started... Was 0 of 2 enqueud
Mar 07 21:38:57 octoprint sh[1118]: util/http/http.c: HTTP8081/7: Client disconnected 192.168.1.187.
Mar 07 21:40:54 octoprint sh[645]: util/http/http.c: HTTP8080/4: Client connected 192.168.1.10 (fd=8).
Mar 07 21:40:54 octoprint sh[645]: util/http/http.c: HTTP8080/4: Request 'GET' '/snapshot' ''
Mar 07 21:40:54 octoprint sh[645]: util/http/http.c: HTTP8080/4: Client disconnected 192.168.1.10.
Mar 07 21:42:54 octoprint sh[645]: util/http/http.c: HTTP8080/7: Client connected 192.168.1.10 (fd=11).
Mar 07 21:42:54 octoprint sh[645]: util/http/http.c: HTTP8080/7: Request 'GET' '/snapshot' ''
Mar 07 21:42:54 octoprint sh[645]: device/links.c: SNAPSHOT:capture:mplane:buf0: Capture image is outdated. Skipped. Now: 11273686025, vs 11153548900.
Mar 07 21:42:54 octoprint sh[645]: util/http/http.c: HTTP8080/7: Client disconnected 192.168.1.10.2

This configuration used to work at alternate intervals, sometimes the cameras would work correctly but suddently stops, without a clear reason or the occurring of a particular event. Currently, restarting the unit or rebooting the system won't fix the issue.

Some fixes I've already tried are:

  • Restarted webcams and camera streamer in multiple ways (systemctl restart camera-streamer, sudo camera-streamer-control restart, etc...)
  • Read realtime log journalctl -fu camera-streamer\* looking for errors or warnings
  • Rebooting the RPI sudo shutdown now -r
  • Switching USB ports (currently using USB 3.0 ports for both devices)
  • Switching net interface (wlan0, eth0). Currently using connection trough Ethernet cable
  • Powering the RPI with different power supplies (from 15W to 65W)

I'm opening this issue after a post on the octoprint forum, more information can be found there. I may be switching to the "old" camera stack proposed by the octoprint mainline but, even if I didn't debug the program directly, I would be happy to provide valuable information for the resolution of the problem.

Thanks

damned-me avatar Mar 13 '24 17:03 damned-me

I wanted to add some information and so I did a quick debug run with gdb (using the following command: /usr/bin/camera-streamer --http-port=8081 --camera-type=v4l2 --camera-path=/dev/video0 --camera-format=YUYV --camera-width=1280 --camera-height=720 --camera-fps=15 --camera-nbufs=4 --http-listen=0.0.0.0) and found this stack trace:

(gdb) b http_500
Breakpoint 1 at 0x37960: file util/http/http_methods.c, line 75.
(gdb) c
Continuing.
util/http/http.c: HTTP8081/0: Client connected 192.168.1.187 (fd=4).
util/http/http.c: HTTP8081/0: Request 'GET' '/stream' ''
[Switching to Thread 0xae639ac0 (LWP 3298)]

Thread 2 "camera-streamer" hit Breakpoint 1, http_500 (stream=0xa7c005f8, data=0x0) at util/http/http_methods.c:75
75      util/http/http_methods.c: No such file or directory.
(gdb) backtrace
#0  http_500 (stream=0xa7c005f8, data=0x0) at util/http/http_methods.c:75
#1  0x0002e380 in http_stream (worker=0x2fb380, stream=0xa7c005f8) at output/http_jpeg.c:96
#2  0x0003718c in http_process (worker=0x2fb380, stream=0xa7c005f8) at util/http/http.c:194
#3  0x0003732c in http_client (worker=0x2fb380) at util/http/http.c:221
#4  0x00037428 in http_worker (worker=0x2fb380) at util/http/http.c:243
#5  0xb6f84310 in start_thread (arg=0xae639ac0) at pthread_create.c:477
#6  0xb4e7b5c8 in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

meaning that the function buffer_lock_write_loop at http_jpeg.c:93 returns 0

I noted, breaking on buffer_lock.c:141, that the function can hit goto error with frames set to zero, which means that if the function fails to get the lock it exit with a return value equal to 0. Thus hitting the if(n == 0) in http_jpeg.c:91.

(gdb) c
Continuing.
util/http/http.c: HTTP8081/1: Client disconnected 192.168.1.10.
util/http/http.c: HTTP8081/0: Client connected 192.168.1.187 (fd=4).
util/http/http.c: HTTP8081/0: Request 'GET' '/stream' ''
[Switching to Thread 0xae639ac0 (LWP 3919)]

Thread 2 "camera-streamer" hit Breakpoint 5, buffer_lock_write_loop (buf_lock=0x2b3350 <stream_lock>, nframes=0, timeout_ms=0,
    fn=0x2e24c <http_stream_buf_part>, data=0xa7c005f8) at device/buffer_lock.c:141
141     in device/buffer_lock.c
(gdb) backtrace
#0  buffer_lock_write_loop (buf_lock=0x2b3350 <stream_lock>, nframes=0, timeout_ms=0, fn=0x2e24c <http_stream_buf_part>, data=0xa7c005f8)
    at device/buffer_lock.c:141
#1  0x0002e364 in http_stream (worker=0x2fb380, stream=0xa7c005f8) at output/http_jpeg.c:93
#2  0x0003718c in http_process (worker=0x2fb380, stream=0xa7c005f8) at util/http/http.c:194
#3  0x0003732c in http_client (worker=0x2fb380) at util/http/http.c:221
#4  0x00037428 in http_worker (worker=0x2fb380) at util/http/http.c:243
#5  0xb6f84310 in start_thread (arg=0xae639ac0) at pthread_create.c:477
#6  0xb4e7b5c8 in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) i locals
buf = 0x0
ret = -1259606884
counter = 0
frames = 0
deadline_ms = 4943263440
frame_stop_ms = 4941263443
(gdb)

I wonder if this could be a concurrency related issue.

damned-me avatar Mar 17 '24 02:03 damned-me