Filter does not run quickly after event

[bspiegel]

I am using a background filter to run a script when an event is detected. When one event occurs, the script runs quickly after the event closes. When multiple, back-to-back events occur, only the first gets run and the next filter run happens almost 5 minutes later. I'd like the filter to run for all qualifying events shortly after the event concludes.

Please advise how to fix.

Installation is 1.28.1 on Ubuntu 14.04
It uses one IP camera Fcam1 which is a Foscam pan tilt camera.
There are 12 zones defined.
The script that runs take seconds to execute.

Options
FILTER_RELOAD_DELAY = 300
FILTER_EXECUTE_INTERVAL = 20

Filter (I would post an image but some quota has been reached preventing)

Code: Select all

Run in background
Alarm Frames greater than or equal 3
Limit to first <blank>
Execute command on matches /home/bob/zmx.sh

Log - from syslog

Code: Select all

Aug 17 14:47:16 server zma_m1[21839]: INF [Fcam1: 19000 - Processing at 7.75 fps]
Aug 17 14:49:19 server zma_m1[21839]: INF [Fcam1: 19960 - Gone into alarm state]
Aug 17 14:49:20 server zma_m1[21839]: INF [Fcam1: 19960 - Opening new event 131, alarm start]
Aug 17 14:49:20 server zma_m1[21839]: INF [Fcam1: 19961 - Gone into alert state]
Aug 17 14:49:20 server zma_m1[21839]: INF [ExtendAlarm count: 0, ExtendAlarm frames: 0]
Aug 17 14:49:20 server zma_m1[21839]: INF [Fcam1: 19964 - Gone back into alarm state]
Aug 17 14:49:20 server zma_m1[21839]: INF [Fcam1: 19966 - Gone into alert state]
Aug 17 14:49:21 server zma_m1[21839]: INF [ExtendAlarm count: 0, ExtendAlarm frames: 0]
Aug 17 14:49:21 server zma_m1[21839]: INF [Fcam1: 19970 - Gone back into alarm state]
Aug 17 14:49:21 server zma_m1[21839]: INF [Fcam1: 19972 - Gone into alert state]
Aug 17 14:49:24 server zmc_m1[21836]: INF [Fcam1: 20000 - Capturing at 7.75 fps]
Aug 17 14:49:25 server zma_m1[21839]: INF [Fcam1: 20000 - Processing at 7.75 fps]
Aug 17 14:49:28 server zma_m1[21839]: INF [Fcam1: 20022 - Left alarm state (131) - 112(5) images]
Aug 17 14:49:28 server zma_m1[21839]: INF [Fcam1: 20022 - Closing event 131, alarm end]
Aug 17 14:49:30 server zmfilter[21851]: INF [Executing '/home/bob/zmx.sh /usr/share/zoneminder/events/1/131']
Aug 17 14:50:06 server zma_m1[21839]: INF [Fcam1: 20320 - Gone into alarm state]
Aug 17 14:50:06 server zma_m1[21839]: INF [Fcam1: 20320 - Opening new event 132, alarm start]
Aug 17 14:50:06 server zma_m1[21839]: INF [Fcam1: 20322 - Gone into alert state]
Aug 17 14:50:07 server zma_m1[21839]: INF [Fcam1: 20323 - Gone back into alarm state]
Aug 17 14:50:08 server zma_m1[21839]: INF [Fcam1: 20338 - Gone into alert state]
Aug 17 14:50:15 server zma_m1[21839]: INF [Fcam1: 20388 - Left alarm state (132) - 118(17) images]
Aug 17 14:50:15 server zma_m1[21839]: INF [Fcam1: 20388 - Closing event 132, alarm end]
Aug 17 14:51:33 server zmc_m1[21836]: INF [Fcam1: 21000 - Capturing at 7.75 fps]
Aug 17 14:51:34 server zma_m1[21839]: INF [Fcam1: 21000 - Processing at 7.75 fps]
Aug 17 14:52:59 server zmc_m1[21836]: WAR [Select timed out]
Aug 17 14:52:59 server zmc_m1[21836]: ERR [Connection dropped by remote end]
Aug 17 14:52:59 server zmc_m1[21836]: WAR [Unable to capture image, retrying]
Aug 17 14:52:59 server zma_m1[21839]: WAR [Signal: Lost]
Aug 17 14:53:04 server zmc_m1[21836]: WAR [Select timed out]
Aug 17 14:53:04 server zmc_m1[21836]: ERR [Connection dropped by remote end]
Aug 17 14:53:04 server zmc_m1[21836]: WAR [Unable to capture image, retrying]
Aug 17 14:53:07 server zmc_m1[21836]: WAR [Select timed out]
Aug 17 14:53:07 server zmc_m1[21836]: ERR [Connection dropped by remote end]
Aug 17 14:53:07 server zmc_m1[21836]: WAR [Unable to capture image, retrying]
Aug 17 14:53:10 server zmc_m1[21836]: WAR [Select timed out]
Aug 17 14:53:10 server zmc_m1[21836]: ERR [Connection dropped by remote end]
Aug 17 14:53:10 server zmc_m1[21836]: WAR [Unable to capture image, retrying]
Aug 17 14:53:12 server zmc_m1[21836]: WAR [Select timed out]
Aug 17 14:53:12 server zmc_m1[21836]: ERR [Connection dropped by remote end]
Aug 17 14:53:12 server zmc_m1[21836]: WAR [Unable to capture image, retrying]
Aug 17 14:53:15 server zma_m1[21839]: WAR [Signal: Reacquired]
Aug 17 14:53:15 server zma_m1[21839]: INF [Fcam1: 21639 - Gone into alarm state]
Aug 17 14:53:15 server zma_m1[21839]: INF [Fcam1: 21639 - Opening new event 133, alarm start]
Aug 17 14:53:15 server zma_m1[21839]: INF [Fcam1: 21640 - Gone into alert state]
Aug 17 14:53:21 server zma_m1[21839]: INF [Fcam1: 21690 - Left alarm state (133) - 101(1) images]
Aug 17 14:53:21 server zma_m1[21839]: INF [Fcam1: 21690 - Closing event 133, alarm end]
Aug 17 14:54:01 server zmc_m1[21836]: INF [Fcam1: 22000 - Capturing at 6.76 fps]
Aug 17 14:54:01 server zma_m1[21839]: INF [Fcam1: 22000 - Processing at 6.80 fps]
Aug 17 14:54:50 server zmfilter[21851]: INF [Executing '/home/bob/zmx.sh /usr/share/zoneminder/events/1/132']
Aug 17 14:56:10 server zmc_m1[21836]: INF [Fcam1: 23000 - Capturing at 7.75 fps]
Aug 17 14:56:10 server zma_m1[21839]: INF [Fcam1: 23000 - Processing at 7.75 fps]

[asker]

My guess is you are using a relative time field in your filter. Please post a picture of your filter to imgur.com and please post the link. Please put in spaces if you are not yet allowed to post links.

[bspiegel]

Thanks for the response. Here's the filter image.

http://i.imgur.com/le6wxnh.jpg

[asker]

I'm very sorry - I've been very caught up of late and haven't been able to dive into this.
Would you do me a favor please so we can short-circuit the debugging process?

1 Please make a copy of your zmfilter.pl
2. Please download this one: https://gist.githubusercontent.com/plia ... mfilter.pl where the old zmfilter was (/usr/local/bin, possibly)

3. Please restart ZM, please generate event alarms

4. Please monitor the logs and post it as a gist in github (please don't truncate)

[bspiegel]

Downloaded the debug zmfilter.pl and collected the info. Posted the result as an issue on Github.

https://github.com/ZoneMinder/ZoneMinder/issues/1023

[knight-of-ni]

Please continue to troubleshoot this here in the user forum rather than create a duplicate thread in our github forum.
Please post you data here: https://gist.github.com/

[bspiegel]

Sorry, I am new to this. Here's the log:

https://gist.github.com/f2dd3e964f90191647cc.git

[bspiegel]

Sorry, bad link. Try this one:

https://gist.github.com/bspiegel29/f2dd ... gel-zm-log

[knight-of-ni]

Understood. Not a problem.
We do actively monitor the user forums.
Even if you don't get a direct response from us, we are still aware of what is going on and will take appropriate action if it is needed.

[asker]

There is something weird going on in your logs you posted - I've summarized the key logs below.
After collation, it looks like your first event (145) got executed immediately but right after that, future events are taking a very long time.

I am hoping you did not delete any interim logs? A point of concern is I don't see zmfilter running every 20 seconds like it was before your script ran.

If you haven't my first suspect is your script that is executing. I'd like to see how long it is taking. I've updated the script here: https://gist.githubusercontent.com/plia ... mfilter.pl

Its the same as before, except it prints a log when your script completes

Can you please run this and log it?

Finally, what is your script doing? ZM has an email action as well.



Aug 18 21:59:37 server zma_m1[23152]: INF [Fcam1: 1057 - Opening new event 145, alarm start]
Aug 18 21:59:46 server zma_m1[23152]: INF [Fcam1: 1147 - Closing event 145, alarm end]
Aug 18 22:00:06 server zmfilter[23154]: INF [PP - Executing command for event: 145]


Aug 18 22:00:04 server zma_m1[23152]: INF [Fcam1: 1423 - Opening new event 146, alarm start]
Aug 18 22:00:08 server zma_m1[23152]: INF [Fcam1: 1484 - Closing event 146, alarm end]
Aug 18 22:10:28 server zmfilter[23154]: INF [PP - Executing command for event: 146]

Aug 18 22:00:12 server zma_m1[23152]: INF [Fcam1: 1539 - Opening new event 147, alarm start]
Aug 18 22:00:21 server zma_m1[23152]: INF [Fcam1: 1609 - Closing event 147, alarm end]
Aug 18 22:05:27 server zmfilter[23154]: INF [PP - Executing command for event: 147]

Sorry, I am new to this. Here's the log:

https://gist.github.com/f2dd3e964f90191647cc.git

[bspiegel]

I altered my script to run faster and the problem went away. Apparently, when zmfilter starts the script it waits for it to end before checking again. The script ran for about 5 minutes. After it finishes, zmfilter looks at events in descending order, calling the last event first.

I moved my code into another script and have zmx.sh launch it. The new script is:

Code: Select all

bash zm1.sh & disown
exit 0

However, zmfilter still waits for the script to end. I have used Zoneminder's email capability before but have a few other tasks I want to run on each event. I figured it was easier to just use one script. Maybe there's a way to change the launch script to free up zmfilter?