ONVIF Cameras without stop/close event fail to trigger recording after first event closed

[NothingTooSerious]

First up, thank you for ZM. The improvements in 1.37 branch is significant.

I looked into this problem and possibly identified the issue and logic fix. Not being familiar with ZM code base though, I am hesitant to produce a pull request until a review of the logic and impact assessment.

Environment

• Tested with a camera that only generates 'start' ONVIF motion events
• ZoneMinder version 1.37.65 commit 15dfaa5

Expected
Whenever ZM receives a start ONVIF Motion Event it will trigger or continue recording. Recording will stop from ZM normal stop recording settings.

Observed
ZM starts the initial recording then stops the initial recording. Any additional start ONVIF Motion Events fail to trigger any further recordings.

Evidence
The logs below demonstrate this.

Start the camera. The first ONVIF motion alarm triggers a recording as noted by the Triggered Start Event on ONVIF log.

INF-zmc.cpp/221 [Starting Capture version 1.37.65]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/208 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1286 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2367 [Slate: 1286 - Opening event timestamp 1733853846 % 246]
INF-zm_monitor.cpp/2369 [Opened new event 13 ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1256 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1261 - Left alert state]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor.cpp/2344 [Slate: 2134 - Closing event 13 1733853875 - 1733853845 = 30 >= 600]

After this, logs are just the following repeated ad nauseam. There is no further triggering of recording.

INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]

Explaining why

There are two source files involved being zm_monitor.cpp and zm_monitor_onvif.cpp.

In zm_monitor_onvif.cpp void Monitor::ONVIF::WaitForMessage() a motionAlert event triggers the following code on line 202:

  } else {
    // Event Start
    Info("Triggered Start on ONVIF");
    if (alarms.count(last_topic) == 0) {
      alarms[last_topic] = last_value;
      if (!alarmed) {
        Info("Triggered Start Event on ONVIF");
        alarmed = true;
        // Why sleep?
        std::this_thread::sleep_for(std::chrono::seconds(1)); //thread sleep
      }
    }
  }

So we need to understand this code further. There are two types of cameras, one capable of generating Motion off / stop events, and one that only generates Motion on / start events. The code logic needs to handle both types.

Initially a camera is marked as only producing start events. This is done by Monitor::Monitor() : Event_Poller_Closes_Event(false) in zm_monitor.cpp line 319.

When an off event is received, Event_Poller_Closes_Event is set to true and off events are then expected for event termination. zm_monitor_onvif.cpp line 198.

if (!parent->Event_Poller_Closes_Event) { //If we get a close event, then we know to expect them.
  parent->Event_Poller_Closes_Event = true;
  Info("Setting ClosesEvent");
}

So, we need to understand what receiving an off event does. zm_monitor.cpp lines 190 to 197 relevant code.

{
  std::unique_lock<std::mutex> lck(alarms_mutex);
  alarms.erase(last_topic);
}

if (alarms.empty()) {
  alarmed = false;
}

Whenever an off / close event happens, the alarm is erased and if it was the last alarm message type received, the ONVIF camera is removed from alarmed state.

What happens for ONVIF cameras that don't generate an off / close event. zm_monitor.cpp lines 1960 gives us the answer

    // If the camera isn't going to send an event close, we need to close it here, but only after it has actually triggered an alarm.
        if (!Event_Poller_Closes_Event && state == ALARM)
            onvif->setAlarmed(false);
    }  // end ONVIF_Trigger
}  // end if (onvif_event_listener  && Event_Poller_Healthy)

If the camera does not generate ONVIF off / close events then the camera alarmed is set to false upon receipt.

What happens to the alarms array? Only the alarmed state variable gets updated. Alarms array remains untouched.

Going back to the Event Start code

  } else {
    // Event Start
    Info("Triggered Start on ONVIF");
    if (alarms.count(last_topic) == 0) {
      alarms[last_topic] = last_value;
      if (!alarmed) {
        Info("Triggered Start Event on ONVIF");
        alarmed = true;
        // Why sleep?
        std::this_thread::sleep_for(std::chrono::seconds(1)); //thread sleep
      }
    }
  }

On the first motion start event received, the alarms.count for the message will be 0. So the alarm message is recorded and the camera is alarmed.

On subsequent motion start events received, the alarms.count is not zero and alarms[last_topic] will contain the same value.

The if statement will not be true and the camera will never trigger a further start event recording because alarmed state will never be set again.

Let's test this logic out replacing the above code at line 202 in zm_monitor_onvif.cpp with the following code

} else {
    // Event Start
    Info("Triggered Start on ONVIF");
    if (alarms.count(last_topic) == 0) {
        // Support close event logic and only trigger alarmed state once.
        alarms[last_topic] = last_value;
        if (!alarmed) {
            Info("Triggered Start Event on ONVIF");
            alarmed = true;
        }
    } else {
        // zm_monitor will generate a pseudo close event for us. Need to trigger on every start event.
        if (!alarmed) {
            Info("Triggered Start Event on ONVIF");
            alarmed = true;
        }
    }
}

By the way, that sleep_for line is deleted. Can't see any justification for it.

Testing the camera and ZM out gives us the below logs:

INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1506781 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2367 [Slate: 1506781 - Opening event timestamp 1734083109 % 309]
INF-zm_monitor.cpp/2369 [Opened new event 891 ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1506751 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1506756 - Left alert state]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1507230 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1507199 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1507204 - Left alert state]
INF-zm_monitor.cpp/2344 [Slate: 1510234 - Closing event 891 1734083224 - 1734083104 = 120 >= 600]

INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1513741 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2367 [Slate: 1513741 - Opening event timestamp 1734083341 % 541]
INF-zm_monitor.cpp/2369 [Opened new event 892 ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1513711 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1513716 - Left alert state]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1514191 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1514161 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1514166 - Left alert state]
INF-zm_monitor.cpp/2344 [Slate: 1517194 - Closing event 892 1734083456 - 1734083336 = 120 >= 600]

INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1517611 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2367 [Slate: 1517611 - Opening event timestamp 1734083470 % 70]
INF-zm_monitor.cpp/2369 [Opened new event 893 ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1517581 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1517586 - Left alert state]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1518061 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1518031 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1518036 - Left alert state]
INF-zm_monitor_onvif.cpp/186 [ONVIF Got Motion Alarm! tns1:VideoSource/MotionAlarm State]
INF-zm_monitor_onvif.cpp/204 [Triggered Start on ONVIF]
INF-zm_monitor_onvif.cpp/215 [Triggered Start Event on ONVIF]
INF-zm_monitor.cpp/2179 [Slate: 1518525 - Gone into alarm state PreAlarmCount: 0 > AlarmFrameCount:1 Cause:ONVIF]
INF-zm_monitor.cpp/2211 [Slate: 1518495 - Gone into alert state]
INF-zm_monitor.cpp/2216 [Slate: 1518500 - Left alert state]
INF-zm_monitor.cpp/2344 [Slate: 1521094 - Closing event 893 1734083586 - 1734083466 = 120 >= 600]

Three recording events successfully triggered. Much better outcome. The alarms not being erased seems a non issue and does not leak memory.

So the logic appears incorrect as demonstrated by the test code.

I am running the test code change for a few days now without observing any issue.

I hope the above code review assists in developing a proper fix.

[welcome]

Thanks for opening your first issue here! Just a reminder, this forum is for Bug Reports only. Be sure to follow the issue template!

[NothingTooSerious]

Is there anything else I could do to have this issue advance?

[connortechnology]

I will take a look this week. I want to release 1.38 by end of month. So it would be nice to get this in by then.

[connortechnology]

K, I see what you are saying, great job on a detail analysis... I'm just thinking instead of the suggested code change, should we not simply clear the alarms array when we set alarmed=false from zm_monitor?

I don't actually like that zm_monitor adjusts the state of monitor_onvif... I feel like when the timeout in WaitForMessage happens, we should just automatically become unalarmed...

[connortechnology]

Can you turn on debug please? Level 1 will do.

It seems to me, we should get an OK, but empty SOAP response, in which case we should become unalarmed.

[connortechnology]

What do you think of removing the code in zm_monitor, and using the following around line 227:

Debug(1, "ONVIF polling : Got Good Response! %i", result);
if (!tev__PullMessagesResponse.wsnt__NotificationMessage.size()) {
if (!parent->Event_Poller_Closes_Event and alarmed) {
alarmed = false;
alarms.clear();
}
}

[NothingTooSerious]

I will need to revisit the code and walk through its logic and impact from proposed changes.

Should be able to do it in next day and a half.

[NothingTooSerious]

Level 1 debug logs attached as requested.
This was generated with zoneminder commit 52e68b0
Several event detections were successfully triggered and stopped.

zm_onvif_debug_level1.log.gz

[NothingTooSerious]

Reviewed the code change proposed and tested it.

Identified some potential issues:

1. Does the proposed code on zm_monitor_onvif.cpp 222 code introduces a race condition?

It appears a new ONVIF event received could deactivate ONVIF alarm before the ONVIF triggered start event is raised in zm_monitor.cpp line 1957 causing a valid alarm to be missed.

Line 1958 of zm_monitor.cpp references onvif->isAlarmed(). This is updated independently by the new code introduced starting at line 222 of zm_monitor_onvif.cpp introducing the race condition between Alarm event and ONVIF event reception.

2. Alarmed state needs another non stop type ONVIF message to be received before it is cancelled.

3. Seeing Alarm frame counts and total score significantly higher since using this version.

Before: Alarm frames 6 - 20 and score 50 - 108.
After: Alarm frames 1400 - 4000 and score 12000 to 35388

This is for 2 - 3 minute duration events.

[connortechnology]

1. Yes there is a race condition, but it was always there... we should get the lock in isAlarmed, and get it immediately after message reception.
2. Not necessarily, the poll has a timeout (20s). My assumption is that if there isn't any events before the timeout occurs, then there isn't any motion, hence the transition to unalarmed.
3. I would expect so. We were unalarming almost instantly. Now we should be unalarming after 20s.