ONVIF events?

Current Development version likely to have breaking changes
Post Reply
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

ONVIF events?

Post by pygr »

Version: 1.37.40~20230524183143-focal

To verify camera functionality, ONVIF Device Manager (ODM) was used (running on a Windows PC) with URI http://<camera IP>/onvif/device_service. Properly functioning motion detection can be seen on the camera webUI and both Base and Pullpoint notifications can be seen with ODM.

When the same URI is entered into the ZoneMinder ONVIF Event configuration and a 15-20 second motion event is carried out, only the first 2 seconds are recorded by ZoneMinder and the following shows up in /var/log/zm/zmc_m2.log:

Code: Select all

05/25/23 09:35:22.285005 zmc_m2[177246].INF-zm_monitor.cpp/1729 [AV5426PMIR-S: 400 - Capturing at 5.00 fps, capturing bandwidth 525856bytes/sec Analysing at 0.00 fps]
05/25/23 09:35:24.727262 zmc_m2[177251].INF-zm_monitor.cpp/2088 [AV5426PMIR-S: 411 - ExtAlm - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
05/25/23 09:35:24.791228 zmc_m2[177251].INF-zm_monitor.cpp/2210 [AV5426PMIR-S: 408 - Opening new event 3064, alarm start]
05/25/23 09:35:25.649977 zmc_m2[177249].ERR-zm_signal.cpp/50 [Got signal 11 (Segmentation fault), crashing]
05/25/23 09:35:27.247709 zmc_m2[177267].INF-zmc.cpp/221 [Starting Capture version 1.37.40]
05/25/23 09:35:35.430121 zmc_m2[177271].ERR-zm_signal.cpp/50 [Got signal 11 (Segmentation fault), crashing]
05/25/23 09:35:40.836031 zmc_m2[177274].INF-zmc.cpp/221 [Starting Capture version 1.37.40]
05/25/23 09:35:47.769990 zmc_m2[177276].ERR-zm_signal.cpp/50 [Got signal 11 (Segmentation fault), crashing]
05/25/23 09:35:57.168494 zmc_m2[177279].INF-zmc.cpp/221 [Starting Capture version 1.37.40]
05/25/23 09:36:06.125248 zmc_m2[177279].INF-zm_monitor.cpp/1729 [AV5426PMIR-S: 10 - Capturing at 1.36 fps, capturing bandwidth 140913bytes/sec Analysing at 0.00 fps]
and later in the log:

Code: Select all

05/25/23 09:47:04.118653 zmc_m2[177279].INF-zm_monitor.cpp/1729 [AV5426PMIR-S: 3300 - Capturing at 5.00 fps, capturing bandwidth 565092bytes/sec Analysing at 0.00 fps]
05/25/23 09:47:10.032085 zmc_m2[177282].ERR-zm_monitor.cpp/1769 [Failed to get ONVIF messages! (null)]
05/25/23 09:47:24.118264 zmc_m2[177279].INF-zm_monitor.cpp/1729 [AV5426PMIR-S: 3400 - Capturing at 5.00 fps, capturing bandwidth 546475bytes/sec Analysing at 0.00 fps]

I'm not a programmer, but could someone give some hints as to how one might track down the cause of the segmentation fault?

pygr
User avatar
iconnor
Posts: 2862
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:

Re: ONVIF events?

Post by iconnor »

Step 1 turn on debug logging. Options->Logging->Debug

If the resulting logs don't help, then you can run it under valgrind.

sudo zmdc.pl stop zmwatch.pl
sudo zmdc.pl stop zmc -m 2
sudo su -s/bin/bash -c"valgrind -v zmc -m 2" www-data
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

OK

The commands

Code: Select all

sudo zmdc.pl stop zmwatch.pl
sudo zmdc.pl stop zmc -m 2
sudo su -s/bin/bash -c'valgrind --log-file="/zm-events/grind.txt" -v zmc -m 2' www-data
resulted in

Code: Select all

05/26/23 14:55:07.309424 zmc_m2[196434].ERR-zm_signal.cpp/50 [Got signal 11 (Segmentation fault), crashing]
in the terminal window. And a 175kB grind.txt file. Here it is on pastebin.com https://pastebin.com/XWzCevMY

pygr
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Version: 1.37.40~20230525173249-focal

Here is a section of zmc_m2.log that starts right after a segmentation fault and runs to the next segmentation fault. It looks like the ONVIF pullpoint subscription is properly established and event notifications are received by ZM.

Code: Select all

05/26/23 14:54:54.369996 zmc_m2[196427].DB1-zm_logger.cpp/225 [LogOpts: level=DB1 effective=DB1, screen=WAR, database=WAR, logfile=DB9->/var/log/zm/zmc_m2.log, syslog=DB9]
05/26/23 14:54:54.551859 zmc_m2[196427].DB1-zm_utils.cpp/277 [Detected ARM (AArch64) processor with Neon]
05/26/23 14:54:54.629458 zmc_m2[196427].DB1-zm_storage.cpp/79 [Loaded Storage area 2 'zm-events']
05/26/23 14:54:54.631181 zmc_m2[196427].DB1-zm_monitor.cpp/379 [Have camera type Ffmpeg]
05/26/23 14:54:54.641157 zmc_m2[196427].DB1-zm_packetqueue.cpp/725 [Setting pre_event_video_packet_count to 10]
05/26/23 14:54:54.642313 zmc_m2[196427].DB1-zm_packetqueue.cpp/719 [Setting max_video_packet_count to 0]
05/26/23 14:54:54.657336 zmc_m2[196427].DB1-zm_ffmpeg.cpp/85 [Not enabling ffmpeg logs, as LOG_FFMPEG and/or LOG_DEBUG is disabled in options, or this monitor is not part of your debug targets]
05/26/23 14:54:54.668246 zmc_m2[196427].INF-zmc.cpp/221 [Starting Capture version 1.37.40]
05/26/23 14:54:54.675400 zmc_m2[196427].DB1-zm_zone.cpp/844 [Got 0 zones for monitor AV5426PMIR-S]
05/26/23 14:54:54.678138 zmc_m2[196427].DB1-zm_monitor.cpp/2364 [Reloading zones for monitor AV5426PMIR-S have 0]
05/26/23 14:54:54.680379 zmc_m2[196427].DB1-zm_monitor.cpp/833 [SharedData=840 TriggerData=560 zone_count 0 * sizeof int 4 VideoStoreData=4128 timestamps=64 images=4x20155392 = 80621568 analysis images=4x20155392 = 80621568 image_format = 4x4 = 16 total=161248808]
05/26/23 14:54:54.682960 zmc_m2[196427].DB1-zm_monitor.cpp/904 [Unable to map file /dev/shm/zm.mmap.2 (161248808 bytes) to locked memory, trying unlocked]
05/26/23 14:54:54.683895 zmc_m2[196427].DB1-zm_monitor.cpp/907 [Mapped file /dev/shm/zm.mmap.2 (161248808 bytes) to unlocked memory]
05/26/23 14:54:54.893552 zmc_m2[196427].DB1-zm_monitor.cpp/2370 [Reloading linked monitors for monitor AV5426PMIR-S, '']
05/26/23 14:54:54.895441 zmc_m2[196427].DB1-zm_monitor.cpp/1013 [Starting ONVIF]
05/26/23 14:54:54.976684 zmc_m2[196427].DB1-zm_monitor.cpp/1035 [ONVIF Endpoint: http://10.137.113.143/onvif/device_service/Events]
05/26/23 14:54:56.552243 zmc_m2[196427].DB1-zm_monitor.cpp/1053 [Good Initial ONVIF Pull]
05/26/23 14:54:56.555954 zmc_m2[196427].DB1-zm_db.cpp/191 [Success running sql query INSERT INTO Monitor_Status (MonitorId,Status,CaptureFPS,AnalysisFPS) VALUES (2, 'Running',0,0) ON DUPLICATE KEY UPDATE Status='Running',CaptureFPS=0,AnalysisFPS=0, thread_id: 38827]
05/26/23 14:54:56.558110 zmc_m2[196427].DB1-zm_ffmpeg_camera.cpp/178 [Priming capture from rtsp://10.137.113.143:554/stream1]
05/26/23 14:54:56.563217 zmc_m2[196427].DB1-zm_ffmpeg_camera.cpp/318 [Calling avformat_open_input for rtsp://10.137.113.143:554/stream1]
05/26/23 14:54:56.577306 zmc_m2[196427].DB1-zm_ffmpeg_camera.cpp/328 [Rebuilt URI with encoded parameters: 'rtsp://admin:IPC%5C271828gr@10.137.113.143:554/stream1']
05/26/23 14:55:07.046465 zmc_m2[196427].DB1-zm_ffmpeg_camera.cpp/601 [timeout in ffmpeg camera now 256425 - 256415 > 10 s]
05/26/23 14:55:07.084543 zmc_m2[196427].DB1-zm_ffmpeg_camera.cpp/394 [Failed to find decoder auto, falling back to auto]
05/26/23 14:55:07.087688 zmc_m2[196427].DB1-zm_ffmpeg.cpp/246 [Dumping stream index i(0) index(0)]
05/26/23 14:55:07.088655 zmc_m2[196427].DB1-zm_ffmpeg.cpp/252 [    Stream #0:0]
05/26/23 14:55:07.089521 zmc_m2[196427].DB1-zm_ffmpeg.cpp/260 [frame_size:0 stream timebase: 1/90000]
05/26/23 14:55:07.091009 zmc_m2[196427].DB1-zm_ffmpeg.cpp/265 [codec: h264 video]
05/26/23 14:55:07.091729 zmc_m2[196427].DB1-zm_ffmpeg.cpp/283 [, SAR 0:1 ]
05/26/23 14:55:07.093413 zmc_m2[196427].DB1-zm_ffmpeg.cpp/177 [90k stream tb numerator]
05/26/23 14:55:07.112631 zmc_m2[196427].DB1-zm_ffmpeg_camera.cpp/519 [Thread count? 1]
05/26/23 14:55:07.116895 zmc_m2[196427].DB1-zm_ffmpeg.cpp/215 [Dumping codec_context codec_type 0 video codec_id 27 h264 width 2592 height 1944 timebase 0/2 format yuvj420p profile 77 level 50 gop_size 12 has_b_frames 0 max_b_frames 0 me_cmp 0 me_range 0 qmin 2 qmax 31 bit_rate 0 extradata:28:00000001674d00329da80a203d7e59b8080808100000000168ee3c80]
05/26/23 14:55:07.118877 zmc_m2[196427].DB1-zm_ffmpeg.cpp/246 [Dumping stream index i(1) index(0)]
05/26/23 14:55:07.119399 zmc_m2[196427].DB1-zm_ffmpeg.cpp/252 [    Stream #0:1]
05/26/23 14:55:07.119725 zmc_m2[196427].DB1-zm_ffmpeg.cpp/260 [frame_size:0 stream timebase: 1/8000]
05/26/23 14:55:07.120195 zmc_m2[196427].DB1-zm_ffmpeg.cpp/265 [codec: pcm_mulaw audio]
05/26/23 14:55:07.120521 zmc_m2[196427].DB1-zm_ffmpeg.cpp/283 [, SAR 0:1 ]
05/26/23 14:55:07.121142 zmc_m2[196427].DB1-zm_ffmpeg.cpp/296 [profile -99 channels 1 sample_rate 8000]
05/26/23 14:55:07.202954 zmc_m2[196427].DB1-zm_packetqueue.cpp/681 [Didn't find a keyframe for stream 0, so returning the it to it]
05/26/23 14:55:07.205722 zmc_m2[196427].DB1-zm_monitor.cpp/3256 [Creating decoder thread]
05/26/23 14:55:07.295039 zmc_m2[196434].DB1-zm_monitor.cpp/1773 [Got Good Response! 0]
05/26/23 14:55:07.297581 zmc_m2[196434].DB1-zm_monitor.cpp/1783 [Got Motion Alarm!]
05/26/23 14:55:07.299318 zmc_m2[196434].DB1-zm_monitor.cpp/1793 [Triggered off ONVIF]
05/26/23 14:55:07.301335 zmc_m2[196434].DB1-zm_monitor.cpp/1797 [Setting ClosesEvent]
05/26/23 14:55:07.302765 zmc_m2[196434].DB1-zm_monitor.cpp/1783 [Got Motion Alarm!]
05/26/23 14:55:07.303840 zmc_m2[196434].DB1-zm_monitor.cpp/1793 [Triggered off ONVIF]
05/26/23 14:55:07.309424 zmc_m2[196434].ERR-zm_signal.cpp/50 [Got signal 11 (Segmentation fault), crashing]
05/26/23 14:55:07.358948 zmc_m2[196427].DB1-zm_monitor.cpp/3263 [Done restarting decoder]
05/26/23 14:55:07.373243 zmc_m2[196427].DB1-zm_monitor.cpp/3265 [getting analysis_it]
05/26/23 14:55:07.380564 zmc_m2[196427].DB1-zm_packetqueue.cpp/681 [Didn't find a keyframe for stream 0, so returning the it to it]
05/26/23 14:55:07.388163 zmc_m2[196427].DB1-zm_monitor.cpp/3271 [Starting an analysis thread for monitor (2)]
05/26/23 14:55:07.470631 zmc_m2[196432].DB1-zm_db.cpp/191 [Success running sql query INSERT INTO `Logs` ( `TimeKey`, `Component`, `ServerId`, `Pid`, `Level`, `Code`, `Message`, `File`, `Line` ) VALUES ( 1685138107.309424, 'zmc_m2', 0, 196434, -2, 'ERR', 'Got signal 11 (Segmentation fault), crashing', 'zm_signal.cpp', 50 ), thread_id: 38827]
That last thing that happened before the crash was an analysis thread was started for monitor 2?

Is analysis called for when Motion Detection is selected to be "None" on the Analysis configuration tab for monitor 2?

pygr
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Version: 1.37.40~20230526163907-focal

In the thread starter I should have mentioned that triggers from a linked monitor result in the expected recordings. So getting streams from the camera and recording them are achievable with my setup.

It's when the trigger is an ONVIF event that issues occur: signal 6 abort, signal 11 segmentation fault, an incomplete mp4 recording and just 4 jpg files.

pygr
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Some more observations:

On first glance at the events view, some things stand out:

1) The event name is "New Event" in contrast to "Event-XXXX" for events which are triggered by a linked monitor.

2) The end times for multiple ONVIF events listed can be the same and all display the time that the event view was refreshed; refreshing the window updates all the reported event end times to the current time.

3) Sometimes the number of frames and alarm frames are shown as "null" even though viewable jpg files are in the event image + video directory along with a short "incomplete.mp4", which is not playable for some ONVIF triggered recordings.

4) DiskSpace for the event is usually in the MB range.


pygr
User avatar
iconnor
Posts: 2862
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:

Re: ONVIF events?

Post by iconnor »

I've made a change that might fix it. If not, please install the debug symbols and do valgrind again so that it can actually tell us the line that is crashing.
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Hi Isaac,

Version: 1.37.40~20230528172955-jammy

Segfaults are still occurring.

I enabled core dumps and looked for them, but couldn't find any.
... install the debug symbols ...
-- I think I found instructions on how to do that: https://wiki.ubuntu.com/Debug%20Symbol%20Packages. After doing that, I'll report back.

pygr
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Version: 1.37.40~20230528172955-focal

Installed debug symbols for ZoneMinder:

Code: Select all

sudo apt install zoneminder-dbg
Stopped zmwatch and zmc and ran valgrind:

Code: Select all

sudo zmdc.pl stop zmwatch.pl
sudo zmdc.pl stop zmc -m 2
sudo su -s/bin/bash -c'valgrind --log-file="/zm-events/grind.txt" -v zmc -m 2' www-data

Here is the output: https://pastebin.com/EMAfDHCr

To my eye, there's nothing that stands out as the cause of the segfault that occurred.
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

I don't know the implications, but I found this:

Code: Select all

ERROR: apport (pid 226285) Sun May 28 10:16:27 2023: called for pid 226223, signal 11, core limit 0, dump mode 1
ERROR: apport (pid 226285) Sun May 28 10:16:27 2023: executable: /usr/lib/zoneminder/cgi-bin/zms (command line "/usr/lib/zoneminder/cgi-bin/nph-zms")
ERROR: apport (pid 226285) Sun May 28 10:16:27 2023: is_closing_session(): no DBUS_SESSION_BUS_ADDRESS in environment
ERROR: apport (pid 226285) Sun May 28 10:16:31 2023: wrote report /var/crash/_usr_lib_zoneminder_cgi-bin_zms.33.crash
in /var/log/apport.log.1, which was recorded yesterday before debug symbols were installed.

The report in /var/crash starts off with:

Code: Select all

ProblemType: Crash
Architecture: arm64
Date: Sun May 28 10:16:27 2023
DistroRelease: Ubuntu 20.04
ExecutablePath: /usr/lib/zoneminder/cgi-bin/zms
ExecutableTimestamp: 1685133546
ProcCmdline: /usr/lib/zoneminder/cgi-bin/nph-zms
ProcCwd: /usr/lib/zoneminder/cgi-bin
ProcEnviron: PATH=(custom, no user)
ProcMaps:
 5565cf1000-5565f7e000 r-xp 00000000 08:02 144894                         /usr/lib/zoneminder/cgi-bin/zms
 5565f8d000-5565f97000 r--p 0028c000 08:02 144894                         /usr/lib/zoneminder/cgi-bin/zms
 5565f97000-5565f99000 rw-p 00296000 08:02 144894                         /usr/lib/zoneminder/cgi-bin/zms
 5565f99000-5569ba4000 rw-p 00000000 00:00 0 
 5589861000-558adb2000 rw-p 00000000 00:00 0                              [heap]
 7f94000000-7f94021000 rw-p 00000000 00:00 0 
 7f94021000-7f98000000 ---p 00000000 00:00 0 
 7f99121000-7f99122000 ---p 00000000 00:00 0 
 7f99122000-7f99922000 rw-p 00000000 00:00 0 
 7f9c000000-7f9c021000 rw-p 00000000 00:00 0 
 7f9c021000-7fa0000000 ---p 00000000 00:00 0 
 7fa32ea000-7fa3313000 rw-p 00000000 00:00 0 
 7fa3313000-7fa331e000 r-xp 00000000 08:02 916                            /lib/aarch64-linux-gnu/libnss_files-2.31.so
 7fa331e000-7fa332e000 ---p 0000b000 08:02 916                            /lib/aarch64-linux-gnu/libnss_files-2.31.so
 7fa332e000-7fa332f000 r--p 0000b000 08:02 916                            /lib/aarch64-linux-gnu/libnss_files-2.31.so
 7fa332f000-7fa3330000 rw-p 0000c000 08:02 916                            /lib/aarch64-linux-gnu/libnss_files-2.31.so
 ...
and is mostly

Code: Select all

CoreDump: base64
 H4sICAAAAAAC/0NvcmVEdW1wAA==
7H0LYBxVuf9pu4EAhU6fhLbQoQUNj7aTPlMpMFAeBSouKhABYdM0bQJ5jElbAsJl0QJB4d4VqgSs11UKBEUZFSRAgZELGgVkwSLhIS7I1ei/wKIoqYL8d+f8vpPM2TnNHB90w+1o+Pr75vt95/2YM7PnXHb8ihNGjxr
F6Iqxe9ggYsxmxZfNqtl9Y8ieX7lMiGH+Omd7uL4QRlnhHxmEZjxZf/pQAwMyUxnAoyjMLHiZgSAvLckhvN0K/0iO5gpne5BnSlLmpcFLSTzXGxOQMi/+P9BfeXUwfaePCkqJl6gog+XGywK80ZIc5PF0TS3D/SCPrty ...
pygr
User avatar
iconnor
Posts: 2862
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:

Re: ONVIF events?

Post by iconnor »

Invalid read of size 8
==7216== at 0x15FC94: Monitor::Poll() (zm_monitor.cpp:1774)
==7216== by 0x28F70B: PollThread::Run() (zm_poll_thread.cpp:30)
==7216== by 0x6D2BFAB: ??? (in /usr/lib/aarch64-linux-gnu/libstdc++.so.6.0.28)
==7216== by 0x63F2623: start_thread (pthread_create.c:477)
==7216== by 0x6FE649B: thread_start (clone.S:78)
==7216== Address 0x40 is not stack'd, malloc'd or (recently) free'd

This is the important bit. The code in question looks like:
if ( (msg->Topic->__any.text != nullptr) &&
std::strstr(msg->Topic->__any.text, onvif_alarm_txt.c_str()) &&
(msg->Message.__any.elts != nullptr) &&
(msg->Message.__any.elts->next != nullptr) &&
(msg->Message.__any.elts->next->elts != nullptr) &&
(msg->Message.__any.elts->next->elts->atts != nullptr) &&
(msg->Message.__any.elts->next->elts->atts->next != nullptr) &&
(msg->Message.__any.elts->next->elts->atts->next->text != nullptr)
) {

Pretty nasty. I'm hoping that maybe msg->Topic is null or something. I've added a test for it. Thing is, if any of these pointers is not null, but also not valid... bad stuff will happen. Going to have to add a bunch of lines to test each and every pointer.

For now I added a test for msg->Topic... and we no longer exit on segfault, so any future valgrind traces should be less cluttered. But we shouldn't need valgrind traces now, we know where the problem is. So just debug logs.
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Hi Isaac,

Version: 1.37.40~20230530094110-focal

Things are better now. Camera motion detection causes ONVIF events that ZoneMinder properly records (without segfaults).

Here is a snippet from zmc_m2.log:

Code: Select all

05/30/23 08:32:24.984703 zmc_m2[19651].DB1-zm_event.cpp/506 [Not Adding 4 frames to DB because write_to_db:0 or frames > analysis fps 5.002418 or BULK]
05/30/23 08:32:24.999598 zmc_m2[19625].DB1-zm_monitor.cpp/2570 [Unknown codec type 2]
05/30/23 08:32:25.078959 zmc_m2[19631].DB1-zm_monitor.cpp/1869 [Triggered on ONVIF]
05/30/23 08:32:25.078978 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.112403 zmc_m2[19631].DB1-zm_monitor.cpp/1869 [Triggered on ONVIF]
05/30/23 08:32:25.112473 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.118266 zmc_m2[19629].DB1-zm_monitor.cpp/1771 [Got Good Response! 0]
05/30/23 08:32:25.118287 zmc_m2[19629].DB1-zm_monitor.cpp/1773 [Got msg ]
05/30/23 08:32:25.118295 zmc_m2[19629].DB1-zm_monitor.cpp/1784 [Got Motion Alarm!]
05/30/23 08:32:25.118301 zmc_m2[19629].DB1-zm_monitor.cpp/1794 [Triggered off ONVIF]
05/30/23 08:32:25.118307 zmc_m2[19629].DB1-zm_monitor.cpp/1773 [Got msg ]
05/30/23 08:32:25.118313 zmc_m2[19629].DB1-zm_monitor.cpp/1784 [Got Motion Alarm!]
05/30/23 08:32:25.118319 zmc_m2[19629].DB1-zm_monitor.cpp/1794 [Triggered off ONVIF]
05/30/23 08:32:25.118324 zmc_m2[19629].DB1-zm_monitor.cpp/1773 [Got msg ]
05/30/23 08:32:25.118330 zmc_m2[19629].DB1-zm_monitor.cpp/1802 [Got a message that we couldn't parse]
05/30/23 08:32:25.118335 zmc_m2[19629].DB1-zm_monitor.cpp/1773 [Got msg ]
05/30/23 08:32:25.118341 zmc_m2[19629].DB1-zm_monitor.cpp/1802 [Got a message that we couldn't parse]
05/30/23 08:32:25.118346 zmc_m2[19629].DB1-zm_monitor.cpp/1773 [Got msg ]
05/30/23 08:32:25.118351 zmc_m2[19629].DB1-zm_monitor.cpp/1802 [Got a message that we couldn't parse]
05/30/23 08:32:25.145899 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.179364 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.212832 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.246282 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.279753 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.329477 zmc_m2[19630].DB1-zm_packet.cpp/124 [got frame: format 12 yuvj420p 2592x1944 linesize:2592x1296 pts: 14393647 keyframe: 0]
05/30/23 08:32:25.329558 zmc_m2[19630].DB1-zm_image.cpp/196 [line size: 10368 =? 10368 width 2592 Size 20155392 ?= 20155392]
05/30/23 08:32:25.329576 zmc_m2[19630].DB1-zm_image.cpp/265 [PopulateFrame: width 2592 height 1944 linesize 10368 colours 4 imagesize 20155392 rgba]
05/30/23 08:32:25.329613 zmc_m2[19630].DB1-zm_image.cpp/294 [Image.Populate(frame): format 26 rgba 2592x1944 linesize:10368x0 pts: -9223372036854775808 keyframe: 1]
05/30/23 08:32:25.329623 zmc_m2[19630].DB1-zm_image.cpp/326 [source frame before convert: format 12 yuvj420p 2592x1944 linesize:2592x1296 pts: 14393647 keyframe: 0]
05/30/23 08:32:25.329630 zmc_m2[19630].DB1-zm_image.cpp/329 [Assign src linesize: 2592, dest linesize: 10368]
05/30/23 08:32:25.336603 zmc_m2[19630].DB1-zm_image.cpp/341 [dest frame after convert: format 26 rgba 2592x1944 linesize:10368x0 pts: 14393647 keyframe: 1]
05/30/23 08:32:25.336800 zmc_m2[19630].DB1-zm_image.cpp/831 [Doing full copy line size 10368 != 10368]
05/30/23 08:32:25.342041 zmc_m2[19631].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 08:32:25.342104 zmc_m2[19631].DB1-zm_monitor.cpp/2079 [Not analysing 1]
05/30/23 08:32:25.342115 zmc_m2[19631].DB1-zm_monitor.cpp/2142 [!score ALARM]
05/30/23 08:32:25.342122 zmc_m2[19631].INF-zm_monitor.cpp/2146 [ipc3-high-res: 773 - Gone into alert state]
05/30/23 08:32:25.342157 zmc_m2[19651].DB1-zm_event.cpp/693 [Adding packet 775]
05/30/23 08:32:25.342170 zmc_m2[19651].DB1-zm_videostore.cpp/968 [Queue size for 0 is 0]
05/30/23 08:32:25.342179 zmc_m2[19651].DB1-zm_videostore.cpp/997 [Pushing on queue 0, size is 1]
05/30/23 08:32:25.342243 zmc_m2[19651].DB1-zm_event.cpp/402 [Have frame type Normal from score(0) state 4 frames 94 bulk frame interval 100 and mod94]
05/30/23 08:32:25.342254 zmc_m2[19651].DB1-zm_event.cpp/417 [frames 94, score 0 max_score 9]
05/30/23 08:32:25.342260 zmc_m2[19651].DB1-zm_event.cpp/425 [Not Writing snapshot because frames 94 score 0 > max 9]
05/30/23 08:32:25.342267 zmc_m2[19651].DB1-zm_event.cpp/473 [Frame delta is 1685460745.08 s - 1685460726.49 s = 18.59 s, score 0 zone_stats.size 0]
05/30/23 08:32:25.342286 zmc_m2[19651].DB1-zm_event.cpp/506 [Not Adding 5 frames to DB because write_to_db:0 or frames > analysis fps 5.002418 or BULK]
05/30/23 08:32:25.367972 zmc_m2[19630].DB1-zm_packet.cpp/124 [got frame: format 12 yuvj420p 2592x1944 linesize:2592x1296 pts: 14411644 keyframe: 0]
05/30/23 08:32:25.368044 zmc_m2[19630].DB1-zm_image.cpp/196 [line size: 10368 =? 10368 width 2592 Size 20155392 ?= 20155392]
05/30/23 08:32:25.368062 zmc_m2[19630].DB1-zm_image.cpp/265 [PopulateFrame: width 2592 height 1944 linesize 10368 colours 4 imagesize 20155392 rgba]
05/30/23 08:32:25.368072 zmc_m2[19630].DB1-zm_image.cpp/294 [Image.Populate(frame): format 26 rgba 2592x1944 linesize:10368x0 pts: -9223372036854775808 keyframe: 1]
05/30/23 08:32:25.368081 zmc_m2[19630].DB1-zm_image.cpp/326 [source frame before convert: format 12 yuvj420p 2592x1944 linesize:2592x1296 pts: 14411644 keyframe: 0]
05/30/23 08:32:25.368088 zmc_m2[19630].DB1-zm_image.cpp/329 [Assign src linesize: 2592, dest linesize: 10368]
05/30/23 08:32:25.375016 zmc_m2[19630].DB1-zm_image.cpp/341 [dest frame after convert: format 26 rgba 2592x1944 linesize:10368x0 pts: 14411644 keyframe: 1]
pygr
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

Occasionally, a 500 response code is received from the camera. If I'm reading the code correctly, that means ZoneMinder stops polling for ONVIF events. Not good.

Rebooting the camera and restarting polling (Console->Select Monitor->ONVIF-> SAVE) appeared to fix the issue.

I'm not sure if the camera reboot was necessary. Next time 500 is received I'll try recovery by just restarting polling.

A snippet from zmc_m2.log:

Code: Select all

05/30/23 09:32:39.016506 zmc_m2[20307].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
05/30/23 09:32:39.016565 zmc_m2[20307].DB1-zm_monitor.cpp/2079 [Not analysing 1]
05/30/23 09:32:39.016574 zmc_m2[20307].DB1-zm_monitor.cpp/2142 [!score IDLE]
05/30/23 09:32:39.016581 zmc_m2[20307].DB1-zm_monitor.cpp/2173 [State 1 IDLE because analysis_image_count(5982)-last_alarm_count(1327) = 4655 > post_event_count(15) and timestamp.tv_sec(1685464358) - recording.tv_src(0) >= min_section_length(10)]
05/30/23 09:32:39.016591 zmc_m2[20307].DB1-zm_monitor.cpp/2314 [Deleting image data for 5982]
05/30/23 09:32:39.146497 zmc_m2[20305].ERR-zm_monitor.cpp/1767 [Failed to get ONVIF messages! 500 (null)]
05/30/23 09:32:39.177999 zmc_m2[20306].DB1-zm_packet.cpp/124 [got frame: format 12 yuvj420p 2592x1944 linesize:2592x1296 pts: 108176856 keyframe: 0]
05/30/23 09:32:39.178075 zmc_m2[20306].DB1-zm_image.cpp/196 [line size: 10368 =? 10368 width 2592 Size 20155392 ?= 20155392]
05/30/23 09:32:39.178090 zmc_m2[20306].DB1-zm_image.cpp/265 [PopulateFrame: width 2592 height 1944 linesize 10368 colours 4 imagesize 20155392 rgba]
05/30/23 09:32:39.178101 zmc_m2[20306].DB1-zm_image.cpp/294 [Image.Populate(frame): format 26 rgba 2592x1944 linesize:10368x0 pts: -9223372036854775808 keyframe: 1]
05/30/23 09:32:39.178109 zmc_m2[20306].DB1-zm_image.cpp/326 [source frame before convert: format 12 yuvj420p 2592x1944 linesize:2592x1296 pts: 108176856 keyframe: 0]
05/30/23 09:32:39.178144 zmc_m2[20306].DB1-zm_image.cpp/329 [Assign src linesize: 2592, dest linesize: 10368]
05/30/23 09:32:39.185212 zmc_m2[20306].DB1-zm_image.cpp/341 [dest frame after convert: format 26 rgba 2592x1944 linesize:10368x0 pts: 108176856 keyframe: 1]
05/30/23 09:32:39.185412 zmc_m2[20306].DB1-zm_image.cpp/831 [Doing full copy line size 10368 != 10368]
05/30/23 09:32:39.190694 zmc_m2[20307].DB1-zm_monitor.cpp/1975 [Not linked_monitors]
A snippet from a camera log from the same time as the ZM entry "Failed to get ONVIF messages! 500 (null)":

Code: Select all

May 30 09:32:39 lighttpd[1044]: (mod_fastcgi.c.2828) backend is overloaded; we'll disable it for 1 seconds and send the request to another backend instead: reconnects: 0 load: 134
pygr
pygr
Posts: 48
Joined: Fri Apr 21, 2023 11:49 pm

Re: ONVIF events?

Post by pygr »

It looks like ZM turns off pullpoint polling (zm_monitor.cpp line 1768) if it fails to receive an ONVIF response.

The problem is that it is not unusual for my camera's web server to go into overload for a few seconds and sends out a 500 response code if contacted while it resets. It does look like it recovers by itself, but ZM requires manual intervention to start polling again.

It would be nice if ZM would deal with the camera 500 response code by trying to poll again a few seconds later. And perhaps make a WAR level log entry to inform the user.

pygr
Post Reply