Filter suddenly stopped sending emails

[goldielocks]

I have a filter set up to send emails on alarms, and until earlier today it's worked perfectly. Now for some reason, it doesn't appear to be doing anything. In the logs I see the filter starting and "scanning for events using filter id 3" then nothing else, when usually it then proceeds to send the emails. If I click list matches, or execute, then I see events in the list without an "emailed" tag...

I've clicked Save a number of times as I know that sometimes kicks things off or restarts the filter, and also restarted the whole box, and nothing.

What's gone wrong?

[Magic919]

Try running on the commandline and see if you get any useful output.

[goldielocks]

Do you mean run the same zmfilter command? If so, that's no help :

root@security:/home/andy# zmfilter.pl --filter_id=3
11/02/20 19:36:46.267878 zmfilter_3[3327].INF [main:180] [Scanning for events using filter id '3']

Then it's finished with no more output..

[iconnor]

perhaps there is a lock on the db table and it is unable to proceed... it should time out and log an error though in that case.

Turn on debug, look at logs, cutnpaste the sql into mysql and see what you get.

[goldielocks]

No, doesn't appear to be a deadlock of any kind, the query comes back very quick but with zero results. I've even forced an event and then watched the logs for the minute later and it doesn't come up, still shows zero events found. Yet "list matches" on the filter page shows me all the events fine...

Nov 2 20:50:01 security zmfilter_3[4058]: DBG [Filter::Execute SQL (SELECT E.*,#012 unix_timestamp(E.StartTime) as Time,#012 M.Name as MonitorName,#012 M.DefaultRate,#012 M.DefaultScale#012 FROM Events as E#012 INNER JOIN Monitors as M on M.Id = E.MonitorId#012 LEFT JOIN Storage as S on S.Id = E.StorageId#012 WHERE (E.EndTime IS NOT NULL) AND ( E.AlarmFrames > 0 and E.EndTime < '2020-11-02 10:00:00' and E.Length <= 30 and E.EndTime >= '2020-11-01 20:50:01' ) AND ( E.Emailed = 0 ) ORDER BY E.Id ASC LIMIT 0,1000000)]

Nov 2 20:50:01 security zmfilter_3[4058]: DBG [Loaded 0 events for filter Email Short Alarms using query (SELECT E.*,#012 unix_timestamp(E.StartTime) as Time,#012 M.Name as MonitorName,#012 M.DefaultRate,#012 M.DefaultScale#012 FROM Events as E#012 INNER JOIN Monitors as M on M.Id = E.MonitorId#012 LEFT JOIN Storage as S on S.Id = E.StorageId#012 WHERE (E.EndTime IS NOT NULL) AND ( E.AlarmFrames > 0 and E.EndTime < '2020-11-02 10:00:00' and E.Length <= 30 and E.EndTime >= '2020-11-01 20:50:01' ) AND ( E.Emailed = 0 ) ORDER BY E.Id ASC LIMIT 0,1000000)]

Nov 2 20:50:01 security zmfilter_3[4058]: DBG [Checking filter Email Short Alarms email returned 0 events ]

Please help!! Pulling my hair out here :S

[goldielocks]

In fact reading that query sql it shows only asking for events before 10am today, yet the filter page has end date time less than 10 seconds ago.. current time here is 9pm. I've restarted the whole machine, at about 4pm, why is that value not updating to be the current time -10 seconds?

[Magic919]

That filter query references end date/time twice. I would clean it up and test again.

[iconnor]

I don't actually see anything wrong with reference EndTime twice.

I wouldn't use the concurrent feature, I implemented it because I thought I needed it, but it actually just made the problem worse.

I suspect there just aren't any events matching the SQL as that is what is shown by your debug logs. The key is the extra EMailed=0 term. It is there so that you don't get multiple emails for the same event. So it thinks it has emailed you. Maybe the issue is in mail delivery and not ZM at all.

[goldielocks]

Thanks for your reply. I only really added the concurrent tick as I thought it might fix it but didn't.

What was strange was the missing "emailed" labels on the list results page. And removing the enddate fields fixed it and I suddenly got a backlog of 50 emails sent to me!

I think for whatever reason the enddate wasn't updating with the correct time in the sql, hence the logs saying the sql said 10am when the time was more like 6pm. Never mind tho, working okay now without either criteria.