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 »

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 »

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 »

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: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

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.
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

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: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

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?
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

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: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

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']
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

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: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

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.
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

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: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

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.
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Does it crash/display any error if you run it manually after triggering an event?
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

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: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

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
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
Locked