zmfilter polling slow.

Forum for questions and support relating to the 1.28.x releases only.
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 8:52 pm

asker wrote:So I'm confused - where are we now?
3 to 5 minute batch processing, still. I thought I had seen an improvement, but it was just likely early in the tick cycle when I hit the alarm, so the results were fast.

gist github com segordon 2087ccb611440c7beb56

Also, we're now getting this :

Code: Select all

2015-08-12 13:45:47.762450	zmdc	5698	ERR	'zmfilter.pl ' exited abnormally, exit status 9	zmdc.pl

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 8:54 pm

asker wrote:So I'm confused - where are we now?
The "PP - Force closing DB just to test" log should occur every 20 seconds. Your latest log seems to show it recurring in minutes. You might have changed the wrong variable.

Please make sure:
FILTER_RELOAD_DELAY = 300
FILTER_EXECUTE_INTERVAL = 20

and restart ZM
logs were taken with FILTER_RELOAD_DELAY = 60 (we were testing earlier) and FILTER_EXECUTE_INTERVAL = 20.


Will reset to 300s delay on FILTER_RELOAD_DELAY and restart now.

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 9:10 pm

The 'Force closing..' message stops re-appearing every 20 seconds after the first abnormal exit, and then the timer is increased from the every 20s to every 3-5 minutes.

The abnormal exit seems to happen every time it hits a valid event, so it'll hit that first event quickly and then revert back to the old behavior.

Could we be witnessing a watchdog script restarting zmfilters after it realizes its been dead after 3-5 minutes, just to let zmfilter crash itself next event?

Did you do anything to alter how email events work? For the sake of experimentation I enabled the email filter as well, it's not executed even when the event is found now, zmfilters could be exiting before it has the chance to?

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Wed Aug 12, 2015 9:52 pm

segordon wrote:The 'Force closing..' message stops re-appearing every 20 seconds after the first abnormal exit, and then the timer is increased from the every 20s to every 3-5 minutes.

The abnormal exit seems to happen every time it hits a valid event, so it'll hit that first event quickly and then revert back to the old behavior.

Could we be witnessing a watchdog script restarting zmfilters after it realizes its been dead after 3-5 minutes, just to let zmfilter crash itself next event?

Did you do anything to alter how email events work? For the sake of experimentation I enabled the email filter as well, it's not executed even when the event is found now, zmfilters could be exiting before it has the chance to?
Can you please post detailed logs of what is going on? Please don't truncate.

No, I did not modify how email events work. We wrote a script earlier to check if zmfilter is being restarted. You may want to run that again to make sure.
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 10:14 pm

asker wrote:Can you please post detailed logs of what is going on? Please don't truncate.
Sure. Here is /var/log/zm/* with logging enabled.

gist github com segordon 53558a3a0552f180f1b8

Four events forced in that log. 14:57:43, 15:00:59, 15:03:35, and 15:04:10.

take a look at the zmdc lines in the linked log. zmfilter is being restarted and getting a new pid. This timing occurs slightly before each new 'Scanning' event, which is what finds the batched events. I don't know if this is a valid concern, however, since zmfilter was not restarting as far as we could tell until we implemented that new zmfilter.pl

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Wed Aug 12, 2015 10:36 pm

I just re-created your settings at home:
a) set a filter to send email
b) reload 300
c) interval 20

Force generated events and each time my logs showed the filter executing and I get the email right then (in a matter of seconds)

I'm curious why zmfilter is crashing for you. I am using the same zmfilter you are (modified version)

I'll take a look at you logs - how often is the new zmfilter crashing for you? each time a new event occurs?
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 10:45 pm

asker wrote:I'll take a look at you logs - how often is the new zmfilter crashing for you? each time a new event occurs?
The crashes coincide with the modified entries we added, zmfilter seems to crash when those appear in the log.

gist github com segordon 0b307b0239b6859548f5

worst case i'll purge the PPA and install from scratch without a premade package to see if it resolves things.

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Wed Aug 12, 2015 11:16 pm

I don't see zmfilter crashing at all in the large gist you provided at
https://gist.github.com/segordon/53558a3a0552f180f1b8

IT only crashed right at the start - lets assume thats because all of ZM did not start.

It's hard to debug logs if you only post a small snapshot like the latest one which is only 3 lines, so I have no context of how often it occurs and what state ZM was in.

Based on the large gist - I see multiple entries like this without crashing afterwards and they happen within less than a minute of each other
08/12/2015 15:02:40.694405 zmfilter[18541].INF [PP:Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/14/57/43']
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 11:21 pm

Perhaps I am misinterpreting lines 142-166? Abnormal exit status on zmfilter being reported by zmdc, along with new pids every restart? Referring to that big gist.

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Wed Aug 12, 2015 11:28 pm

segordon wrote:Perhaps I am misinterpreting lines 142-166? Abnormal exit status on zmfilter being reported by zmdc, along with new pids every restart? Referring to that big gist.
I think those should be ignored - that's happening when ZM is initializing. I've forced DB connections that may be causing this.
If you go further down, when all components are loaded, what I am seeing is zmfilter kick in with your configured filter and in multiple cases, less than a minute which seems to indicate its working.
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Wed Aug 12, 2015 11:32 pm

asker wrote:
segordon wrote:Perhaps I am misinterpreting lines 142-166? Abnormal exit status on zmfilter being reported by zmdc, along with new pids every restart? Referring to that big gist.
I think those should be ignored - that's happening when ZM is initializing. I've forced DB connections that may be causing this.
If you go further down, when all components are loaded, what I am seeing is zmfilter kick in with your configured filter and in multiple cases, less than a minute which seems to indicate its working.
is the format confusing you perhaps? I cat'd the log files together, they are out of order and the timestamp should be referred to on a per-line basis. the unix 'sort' tool can help make it easier to read. The log starts from 14:57 and ends around 15:05. zmfilter is getting restarted between 15:02 and 15:05.

Is ZM initialized more than once during the alert process and I am misunderstanding?

I'll break up each file with a new line or the filename or something next time I combine them to make it easier to think about.

here's a time sorted one. gist github com segordon c612301a61c8a39ff50a the same big gist, but sorted.

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Wed Aug 12, 2015 11:42 pm

segordon wrote:
asker wrote:
segordon wrote: I'll break up each file with a new line or the filename or something next time I combine them to make it easier to think about.

here's a time sorted one. gist github com segordon c612301a61c8a39ff50a the same big gist, but sorted.

*sigh* You're right. It's crashing every time the event matches, but after completing the action. I'll try and dive in tomorrow.
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Wed Aug 12, 2015 11:49 pm

Does it crash/display any error if you run it manually after triggering an event?
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon » Thu Aug 13, 2015 12:14 am

asker wrote:Does it crash/display any error if you run it manually after triggering an event?
Good question. something new.

Code: Select all

╰─$ zmfilter.pl alertFile                                                 130 ↵
Name "Net::SFTP::Foreign::debug" used only once: possible typo at /usr/bin/zmfilter.pl line 821.
Can't locate object method "prepare_cached" via package "dbh" (perhaps you forgot to load "dbh"?) at /usr/bin/zmfilter.pl line 1175.
which exits zmfilter.

User avatar
asker
Posts: 1419
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker » Thu Aug 13, 2015 12:55 am

segordon wrote:
asker wrote:Does it crash/display any error if you run it manually after triggering an event?
Good question. something new.

Code: Select all

╰─$ zmfilter.pl alertFile                                                 130 ↵
Name "Net::SFTP::Foreign::debug" used only once: possible typo at /usr/bin/zmfilter.pl line 821.
Can't locate object method "prepare_cached" via package "dbh" (perhaps you forgot to load "dbh"?) at /usr/bin/zmfilter.pl line 1175.
which exits zmfilter.
This (prepare_cache not found) can't be happening just with the new zmfilter.pl. Try with your old zmfilter.pl (without any of the changes we did) and run it manually after you trigger an event. If you see this problem then that is the core problem. You can ignore the Foreign::Debug warning
Please don't ask me questions via PM. Feel free to post in the forums or Github

My collection of ZoneMinder learnings:
https://wiki.zoneminder.com/Various_ZM_thoughts

Post Reply

Who is online

Users browsing this forum: No registered users and 1 guest