Zoneminder unusable: intermittent zmc issue with monitors (start/terminate/restart loop)

[llama]

I've set up a new installation of Zoneminder 1.32.3 (installed via pkg within FreeBSD 11.2, 3.6GHz modern i3 processor and 32GB RAM) and am having issues getting a stable monitor feed, which means ZM is unusable. I'm using ffmpeg 4.1 and installed ZM's dependencies, MySQL etc following the FreeBSD port's instructions.

For a given monitor, it seems that zmc is started up but gives a lot of warnings (

Code: Select all

Unable to receive frame 0: Resource temporarily unavailable, continuing

). After these warnings, zm_monitor indicates that some frames are being captured but at an unusual FPS (either 50 or 100fps when it should be 25). zmc is eventually restarted because it was detected to *not* have been capturing frames past the WATCH_MAX_DELAY setting (I tried bumping this setting up to 60+ seconds but makes no difference). zmc gets terminated and then restarted and this process of start, fail, restart continues ad infinitum. Frames captured can be seen occasionally in the montage so zmc is at least partially working before it gets terminated and restarted. The full debug log for the zmc process is below.

Code: Select all

01/05/19 12:27:04.985995 zmc_m4[102133].DB1-zm_logger.cpp/251 [LogOpts: level=DB1/DB1, screen=OFF, database=INF, logfile=DB1->/var/log/zm/zm_debug.log.33128, syslog=INF]
01/05/19 12:27:04.986118 zmc_m4[102133].DB1-zm_utils.cpp/281 [Detected a x86\x86-64 processor with AVX2]
01/05/19 12:27:04.986358 zmc_m4[102133].DB1-zm_monitor.cpp/2059 [Got 1 for v4l_captures_per_frame]
01/05/19 12:27:04.986511 zmc_m4[102133].DB1-zm_monitor.cpp/406 [monitor purpose=1]
01/05/19 12:27:04.986521 zmc_m4[102133].DB1-zm_monitor.cpp/416 [mem.size SharedData=600 TriggerData=560 VideoStoreData=4128 total=62213512]
01/05/19 12:27:04.986532 zmc_m4[102133].DB1-zm_storage.cpp/94 [No id passed to Storage constructor.  Using default path /opt/zoneminder/events instead]
01/05/19 12:27:04.986540 zmc_m4[102133].DB1-zm_monitor.cpp/420 [Storage path: /opt/zoneminder/events]
01/05/19 12:27:05.006547 zmc_m4[102133].DB1-zm_monitor.cpp/486 [Monitor Front Porch has function 2]
01/05/19 12:27:05.006583 zmc_m4[102133].DB1-zm_monitor.cpp/487 [Monitor Front Porch LBF = '%N - %d/%m/%y %H:%M:%S', LBX = 0, LBY = 0, LBS = 1]
01/05/19 12:27:05.006598 zmc_m4[102133].DB1-zm_monitor.cpp/488 [Monitor Front Porch IBC = 20, WUC = 0, pEC = 0, PEC = 50, EAF = 1, FRI = 100, RBP = 6, ARBP = 6, FM = 0]
01/05/19 12:27:05.006822 zmc_m4[102133].DB1-zm_zone.cpp/862 [Got 1 zones for monitor Front Porch]
01/05/19 12:27:05.015136 zmc_m4[102133].DB1-zm_monitor.cpp/2322 [Loaded monitor 4(Front Porch), 1 zones]
01/05/19 12:27:05.015174 zmc_m4[102133].INF-zmc.cpp/223 [Starting Capture version 1.32.3]
01/05/19 12:27:05.029052 zmc_m4[102133].INF-zm_ffmpeg_camera.cpp/163 [Priming capture from rtsp://10.0.0.123/unicast]
01/05/19 12:27:05.039919 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/344 [Calling avformat_open_input for rtsp://10.0.0.123/unicast]
01/05/19 12:27:05.105156 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/376 [Opened input]
01/05/19 12:27:05.105191 zmc_m4[102133].INF-zm_ffmpeg_camera.cpp/378 [Stream open rtsp://10.0.0.123/unicast, parsing streams...]
01/05/19 12:27:06.786408 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/503 [Failed to find decoder (h264_mmal)]
01/05/19 12:27:06.786455 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/514 [Video Found decoder h264]
01/05/19 12:27:06.786464 zmc_m4[102133].DB1-zm_ffmpeg.cpp/267 [Dumping stream index i(0) index(0)]
01/05/19 12:27:06.786472 zmc_m4[102133].DB1-zm_ffmpeg.cpp/272 [    Stream #0:0]
01/05/19 12:27:06.786478 zmc_m4[102133].DB1-zm_ffmpeg.cpp/280 [, frames:42, timebase: 1/90000]
01/05/19 12:27:06.786500 zmc_m4[102133].DB1-zm_ffmpeg.cpp/282 [: Video: h264 (High), yuv420p(progressive), 1920x1080]
01/05/19 12:27:06.786512 zmc_m4[102133].DB1-zm_ffmpeg.cpp/227 [25 fps, ]
01/05/19 12:27:06.786524 zmc_m4[102133].DB1-zm_ffmpeg.cpp/229 [90k stream tb numerator , ]
01/05/19 12:27:06.786531 zmc_m4[102133].DB1-zm_ffmpeg.cpp/229 [180k codec time base:]
01/05/19 12:27:06.786538 zmc_m4[102133].DB1-zm_ffmpeg.cpp/337 [
]
01/05/19 12:27:06.786545 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/521 [Calling avcodec_open2]
01/05/19 12:27:06.786629 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/544 [HWACCEL not in use]
01/05/19 12:27:06.786649 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/556 [Audio Found decoder]
01/05/19 12:27:06.786656 zmc_m4[102133].DB1-zm_ffmpeg.cpp/267 [Dumping stream index i(1) index(0)]
01/05/19 12:27:06.786663 zmc_m4[102133].DB1-zm_ffmpeg.cpp/272 [    Stream #0:1]
01/05/19 12:27:06.786670 zmc_m4[102133].DB1-zm_ffmpeg.cpp/280 [, frames:18, timebase: 1/8000]
01/05/19 12:27:06.786682 zmc_m4[102133].DB1-zm_ffmpeg.cpp/282 [: Audio: pcm_alaw, 8000 Hz, 1 channels, s16, 64 kb/s]
01/05/19 12:27:06.786691 zmc_m4[102133].DB1-zm_ffmpeg.cpp/337 [
]
01/05/19 12:27:06.786698 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/563 [Calling avcodec_open2]
01/05/19 12:27:06.786713 zmc_m4[102133].DB1-zm_ffmpeg_camera.cpp/600 [Calling sws_isSupportedInput]
01/05/19 12:27:06.791611 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.825456 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.830325 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.859885 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.883509 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.903845 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.932981 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.960299 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:06.984979 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:07.018688 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:07.034148 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:07.052239 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:07.065444 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:07.078798 zmc_m4[102133].WAR-zm_ffmpeg_camera.cpp/900 [Unable to receive frame 0: Resource temporarily unavailable, continuing]
01/05/19 12:27:07.097715 zmc_m4[102133].INF-zm_monitor.cpp/2477 [Front Porch: images:1 - Capturing at 50.00 fps, capturing bandwidth 65928bytes/sec]
01/05/19 12:27:24.483984 zmc_m4[102133].INF-zm_signal.cpp/40 [Got signal 15 (Terminated), exiting]
01/05/19 12:27:24.544555 zmc_m4[102133].DB1-zm_logger.cpp/255 [Terminating Logger]

The Zoneminder issue is intermittent — yesterday I had 2 of the same cameras functioning fine but saw the same issue occurring when adding a third camera. Now today, I can't get a single camera to stream correctly; I disabled the other cameras when trying to debug this issue.

Cameras are cheap Xiaofang cameras (ZM monitor config screenshots attached), but the cameras stream fine via RTSP on the network — ffmpeg streams/records to a file for hours on end without error; I tested this on the same machine as Zoneminder to ensure there's nothing odd about the network configuration. Likewise VLC plays the streams without issue from another computer. For note, the post-event image count is up at 50 because of the "empty H264" files issue (viewtopic.php?p=107703); without it this high the result is events (when capture was working) would be empty video files.

Cameras are being streamed at 1080p and 25fps but it's worth noting the same issues were seen when dropping the resolution to 720p and 10fps. Other posts suggest RAM issues or availability of tmpfs or shared memory; there's sufficient RAM on the machine and plenty available (eg writing 8GB to /tmp works fine). For note, both ZM_PATH_MAP and ZM_PATH_SWAP are on separate tmpfs mounts.

Let me know if there's any other info I can provide, options I can tweak or tests to run. As mentioned, I'd tried tweaking WATCH_MAX_DELAY and also WATCH_CHECK_INTERVAL without any difference, tried tweaking the camera's internal settings for FPS/resolution, but also Zoneminder's monitor settings for storage, buffers and even Source Type (eg tried as "Remote" but that fails entirely with 400 Bad Request, as expected as it is deprecated/non-recommended to use this).

Thanks!

[llama]

Anyone got any thoughts? With being unable to access cameras, ZM is completely dead in the water for me.

[MrMagoo]

Do your cameras support any other video sources that you could try ?

Have you tried stopping zoneminder completely and grabbing video directly from these sources with ffmpeg to see if they stream correctly independently ?


ffmpeg -i rtsp://admin:PassWord1@10.4.4.200:554/live/main -t 10 /tmp/out.mp4

[llama]

Do your cameras support any other video sources that you could try ?

Thanks for the suggestions. So I just tried firing up a network stream via ffserver (to stream a MP4 file as a HTTP FLV stream) from my desktop computer and a freshly-restarted Zoneminder struggles with that as well, with the capture remaining stable for a few seconds and then has what appears to be the same issue:

Code: Select all

2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:07 zmc_m6 100939 ERR Unable to send packet at frame 0: Resource temporarily unavailable, continuing zm_ffmpeg_camera.cpp 240
2019-02-02 15:17:10 zmc_m6 100939 INF Monitor-6: images:100 - Capturing at 33.33 fps, capturing bandwidth 41693bytes/sec zm_monitor.cpp 2477
2019-02-02 15:17:14 zmc_m6 100939 INF Monitor-6: images:200 - Capturing at 25.00 fps, capturing bandwidth 32851bytes/sec zm_monitor.cpp 2477
2019-02-02 15:17:57 zmc_m6 100939 INF Failed to capture image from monitor 6 Monitor-6 (1/1) zmc.cpp 311
2019-02-02 15:17:57 zmc_m6 100939 INF Return from Capture (-1), signal loss zm_monitor.cpp 2391
2019-02-02 15:17:57 zmc_m6 100939 INF Unable to read packet from stream 0: error -541478725 "End of file".  zm_ffmpeg_camera.cpp 95
2019-02-02 15:17:57 zmc_m6 100939 INF Got signal 15 (Terminated), exiting zm_signal.cpp 40

This gets repeated in a loop, the capture attempts to start, loads for a short while and then fails, before being terminated. Occasionally, the termination and restart looks a little different:

Code: Select all

2019-02-02 15:18:23 zmc_m6 102010 INF Monitor-6: images:100 - Capturing at 33.33 fps, capturing bandwidth 27649bytes/sec 2477
2019-02-02 15:18:27 zmc_m6 102010 INF Monitor-6: images:200 - Capturing at 25.00 fps, capturing bandwidth 19818bytes/sec zm_monitor.cpp 2477
2019-02-02 15:19:00 zmc_m6 102010 INF Got signal 15 (Terminated), exiting zm_signal.cpp 40
2019-02-02 15:19:00 zmc_m6 102010 INF Unable to read packet from stream 0: error -541478725 "End of file".  zm_ffmpeg_camera.cpp 195
2019-02-02 15:19:00 zmc_m6 102010 INF Return from Capture (-1), signal loss zm_monitor.cpp 2391
2019-02-02 15:19:00 zmc_m6 102010 INF Failed to capture image from monitor 6 Monitor-6 (1/1) zmc.cpp 311
2019-02-02 15:20:05 zmc_m6 100939 INF Priming capture from http://10.0.0.10:8090/live.flv zm_ffmpeg_camera.cpp 163
2019-02-02 15:20:05 zmc_m6 100939 INF Starting Capture version 1.32.3 zmc.cpp 223
2019-02-02 15:20:36 zmc_m6 100939 INF Got signal 15 (Terminated), exiting zm_signal.cpp 40
2019-02-02 15:20:36 zmc_m6 100939 WAR Option rtsp_transport not recognized by ffmpeg zm_ffmpeg_camera.cpp 372
2019-02-02 15:20:36 zmc_m6 100939 INF Stream open http://10.0.0.10:8090/live.flv, parsing streams...  zm_ffmpeg_camera.cpp 378
2019-02-02 15:20:36 zmc_m6 100939 ERR Unable to find stream info from http://10.0.0.10:8090/live.flv due to: Operation timed out zm_ffmpeg_camera.cpp 388
2019-02-02 15:20:36 zmc_m6 100939 ERR Failed to prime capture of initial monitor zmc.cpp 253
2019-02-02 15:20:48 zmc_m6 101984 INF Priming capture from http://10.0.0.10:8090/live.flv zm_ffmpeg_camera.cpp 163
2019-02-02 15:20:48 zmc_m6 101984 INF Starting Capture version 1.32.3 zmc.cpp 223

Running ffmpeg on the same machine ZM (via

Code: Select all

ffmpeg -i http://10.0.0.10:8090/live.flv /tmp/dummy.flv

) sees the stream load fine. There's one initial warning/error from ffmpeg of "co located POCs unavailable" but after that, the stream is fine.

Have you tried stopping zoneminder completely and grabbing video directly from these sources with ffmpeg to see if they stream correctly independently ?

ffmpeg -i rtsp://admin:PassWord1@10.4.4.200:554/live/main -t 10 /tmp/out.mp4

Yes, I'd tried doing this with ffmpeg directly to a file on the machine ZM is installed on. No issues or errors with the stream running for hours on end with the command (run as the web user to ensure parity with ZM):

Code: Select all

sudo -u www ffmpeg -i rtsp://10.0.0.123/unicast -c:v copy foo.mp4
[code]

If there's a better way of replicating ZM's streaming behaviour in a shell, I'll give anything a go to debug this issue.

[MrMagoo]

I was thinking more of checking you could grab useable data from the camera in the first instance and checking the quality from a sample file.

[llama]

I was thinking more of checking you could grab useable data from the camera in the first instance and checking the quality from a sample file.

As in just record the camera over the network to a file and visually inspect the output? If so, that's what I meaning when I said I'd used ffmpeg to stream from the camera to a file -- I'd checked both the ffmeg stream logs and the actual file itself and the output file plays without issue in ffplay or VLC.

ZoneMinder's issue seems to pertain to either its own internal communications (eg zmc/zma/etc) failing or something about the way ZM is talking to ffmpeg. I feel I've ruled out networking (as streaming via ffmpeg directly works) and the cameras themselves (as streaming another source also fails) -- not much more to narrow down but I'm very open to suggestions.

Unless it's something quirky about ZoneMinder on FreeBSD -- anyone out there successfully running it on FreeBSD?

[Pedulla]

I had issues like this with my Hikvision cameras when I had old versions of firmware in the cams and I did not match exactly the dimensions reported by ffmpeg. Also look at issues of the key frames being too far apart.

Also try the straight H264 encoding rather than passthrough and see if you get different results.
Some of my cheap chinese hikvision cams just won't do h264 passthrough.

As to the OS, I'm a rocksolid rider of UB18.04

[llama]

Also try the straight H264 encoding rather than passthrough and see if you get different results.
Some of my cheap chinese hikvision cams just won't do h264 passthrough.

I had tried this but the reason I couldn't use it was because of this issue where ZM produces H264 files that are empty (viewtopic.php?f=38&t=27916). Changing the cameras over from Passthrough to X264 again now shows the same issue but the capture processes are staying up and running (30 mins and stable). Events get registered and displayed but their content is empty, because the aforementioned issue. This might be an option, if that other issue can be fixed.

What's ZM doing differently between Video Writers that prevents H264 Passthrough from working? My cameras are sending H264 video, which seems to match what the docs say. Here's output from manual ffmpeg:

Code: Select all

Input #0, rtsp, from 'rtsp://10.0.0.123/unicast':
  Metadata:
    title           : LIVE555 Streaming Media v2014.07.04
    comment         : LIVE555 Streaming Media v2014.07.04
  Duration: N/A, start: 0.000750, bitrate: N/A
    Stream #0:0: Video: h264 (High), yuv420p(progressive), 1920x1080, 90k tbr, 90k tbn, 180k tbc
    Stream #0:1: Audio: pcm_alaw, 8000 Hz, mono, s16, 64 kb/s

And the dimensions are definitely set correctly in my Monitor settings. Looking at the Github issue tracker, there's some various bugs about Passthrough failing with certain formats etc -- perhaps something along those lines?

[kitkat]

Have you tried using MediaInfo to inspect a stream saved using FFMpeg and -codec copy? That might provide some clues.

[llama]

Have you tried using MediaInfo to inspect a stream saved using FFMpeg and -codec copy? That might provide some clues.

Thanks for the suggestion. I'd been using -c:v copy and forgetting that my streams featured audio as well so I thought I was onto something when I saw this error:

Code: Select all

[mp4 @ 0x7fb13b800a00] Could not find tag for codec pcm_alaw in stream #1, codec not currently supported in container
Could not write header for output file #0 (incorrect codec parameters ?): Invalid argument

and the stream fails to capture, with ffmpeg exiting. Turning off the audio stream on my cameras has produced some inconsistencies: I thought it had fixed the issue as two streams have been stable for a few hours, but the third capture still fails like it did before, getting into the restart loop. The monitor settings are identical and as best I can tell, so are the cameras, their streams and configuration so it seems that's not the underlying issue.

I've started digging into what's going and narrowed it down to when zmc -m X is run — zmc appears to start and run successfully but isn't working. Zoneminder starts zmc and zmc opens the stream, it goes awry immediately (logging says it's capturing at 50 or 100 FPS when it isn't at all, plus it should be 25fps). zmc "freezes" in some way, then zma fails because of no data, then zmwatch comes along after the given timeout period, restarts zmc/zma because no data was detected and the cycle begins again. I'll see what debugging info I can get out of zmc and hopefully that'll yield the answer.

[rockedge]

On Puppy Linux (Ubuntu binaries) running ZM versions between 1.31.1 and 1.32.3 I experienced the same refresh issue. Finally from 1.32.3 upwards the problem ended. Not quite sure what it was.......I posted about it at the time

[iconnor]

Remove the 30 from Max FPS and Alarm Max FPS. They aren't needed anymore and I've seen some cases where zm was trying to satisfy the 30fps requirement and starving the ffmpeg libs for CPU time.

Isaac

[llama]

Remove the 30 from Max FPS and Alarm Max FPS. They aren't needed anymore and I've seen some cases where zm was trying to satisfy the 30fps requirement and starving the ffmpeg libs for CPU time.

Isaac

Wow, yep that looks like the issue -- thank you!! Instantly sees all monitors now capturing correctly with the right frame rates and with audio included (with H264 Passthrough set). H264 files are saved to disk correctly.

These two fields were set at 30 FPS by default when I added the monitors so I'll make a note to always clear them out in future -- are they being removed or blanked by default in future versions?