Delayed SMTP notifications

[trialnerror]

I've been using AD for about a month. SMTP notifications had been nearly instantaneous. Around March 1 they started to have serious lags, some being delivered up to an hour after a zone was faulted/restored, and some faults/restores being missed completely. The AD logs showed this delay too in their timestamps. I explored a bit and found out that SMTP sending in python is blocking, i.e., it will prevent further processing until a message sends or times out. Many messages queued, and an intermittently responding mail service (AOL) seems to be the culprit behind this behavior. I think the take-away is AD SMTP notifications require a reliable service to work reliably. It might be prudent to set up multiple notification vectors for critical alerts.

Googling shows there is an async way to send SMTP in python called "Twisted". While it wouldn't fix a non-responsive service like AOL, it could keep AD from missing events and putting wrong time stamps on them. If I manage to get it working, I'll post here as I don't know how the git/pull/opensource realm works.

[kevin]

You can set up as many notification types for the same events that you want.

If you want to get emails as well as SMS via Twilio for an alarm, then configure two different notifications

[trialnerror]

Thinking about this a bit more, Im wondering if the smtp blocking delay would delay other Message vectors too? Are they in the same serial processing chain, or in parallel? I'll give it a shot.

[kevin]

Looking at it, it would be a pretty trivial drop in https://twistedmatrix.com/documents/17. ... -mail.html

[trialnerror]

Yeah, I've started playing with that mod. Looking at ways to implement with smtp plain,ssl,tls options currently implemented in AD. Should be straight forward. I also got a stand alone python program working with smtp to gmail using OAuth. May try to stick that in too. Main constraint is my very limited knowledge of anything python and AD code (I found Twisted by googling python, smtp, asynchronous). Also, test environment is copying code to AD2PI and seeing if it runs; not great for debugging. I'll probably hardwire any variables I'm not sure how to pass in and see if dev team can add glue to bring them in from the user interface. If I don't hit a wall my plan is: Phase 1) Twisted smtp plain,ssl,tls. Phase 2) OAuth smtp with hardwired credentials. Phase 3) log notify failures for timeouts. Phase 4) see if twisted asynch can be applied to other notification mechanisms. Thanks for the bread crumbs.

[trialnerror]

A friend warned me off of twisted as an overly complicated solution and suggested I just use threading. I managed to get something working with the entire send process in a separate thread, but retry warning/failure reporting is only vial the app log. The main app always says 'sent successfully'. Also, not being a socket guy, I don't know if it's better to let a socket hang on the connect for an hour, or to try for 30 seconds and then retry in an hour. I think I'm going to settle for a 10sec connect attempt in the main thread. If that connect fails (vs. authorization failure, etc.) then I'll dump to the retry thread. That way with a successful connect, at least authorization errors, etc., will still be handled by the main program.

[kevin]

Going to be interesting to see how this pans out since the notification system is already in its own separate thread, hopefully doesn't make it too tricky to work out

[trialnerror]

It's working well with a few test cases. I'm still tweaking a bit. I'll set my system to notify on all zone faults and have the threads stack up for a day or so and see what that does. In retrospect a better approach would probably be setting up a local mail client on the pi and letting it handle delivery delays. I thought I saw a smtp server listening on port 25 already when looking at processes. At least the threads can talk back to the AD log so if a massage isn't delivered in a specified time (specified in code) it can log the failure.

However, if the notifications are already in a separate thread, perhaps connection blocking only blocks in that thread and the main AD churns along just fine? If that's the case, then spinning off yet another blocked thread won't really have accomplished much other than teach me a bit of python. On the test notification, the 'save and test' web page is blocked while the smtp send is blocking, and it isn't in my tweek, but perhaps that's just how the test page works whereas regular notifications aren't blocked? Rereading my initial post I was under the impression the processing of AD events, as shown in the log, were also delayed when SMTP was blocked. I'll have to experiment some more to see if that was actually the case and that this fix is actually solving a problem.

[trialnerror]

So I characterized the issue a bit more using SMTP notifications, but I suspect this extends to any blocked notification. When a notification is blocked, AD waits (2 min on my factory Pi image) before timing out and moving on to the next notification. However, during this time, other zone events aren't being logged. When the SMTP blocking ends, other events are processed, but they're given the timestamp of the time the logger gets to them, not when they occurred.

To demonstrate:
I blocked SMTP with an iptables rule and then opened/closed a door (ENTRY Laundry & Side Doors) that sends a SMTP notification for both events. I then walked around triggering other events. No events showed up in the log until door open + 2min at which point the door open event showed up with a 2 min delayed timestamp. At this point I presume AD moves to the next event, the door close, and tries to send its SMTP notification. The log was again silent for 2 more min at which point the door close showed up. AD then moves on to the next event(s) and they all show up with effectively the same timestamp as the door close timestamp. The MOTION Kitchen zone was the last zone triggered just before the first door open notification would be attempted.

AD Events Log:

Code: Select all

2018-3-20 9:00:44 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:44 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:44 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:44 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:44 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:44 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:44 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:44 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:44 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:44 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:44 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:43 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:43 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:43 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:43 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:43 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:43 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:43 AM   ZONE RESTORE   Zone ENTRY Rear Sliding Doors (3) has been restored.
2018-3-20 9:00:43 AM   ZONE FAULT   Zone ENTRY Rear Sliding Doors (3) has been faulted.
2018-3-20 9:00:42 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:42 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:42 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:42 AM   ZONE FAULT   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been faulted.
2018-3-20 9:00:42 AM   ZONE RESTORE   Zone MOTION Kitchen (47) has been restored.
2018-3-20 9:00:42 AM   ZONE RESTORE   Zone DOOR Basement, MOTION Fmly-Foyer (5) has been restored.
2018-3-20 9:00:42 AM   ZONE RESTORE   Zone ENTRY Laundry & Side Doors (2) has been restored.
2018-3-20 8:58:29 AM   ZONE FAULT   Zone ENTRY Laundry & Side Doors (2) has been faulted.
2018-3-20 8:56:07 AM   ZONE FAULT   Zone MOTION Kitchen (47) has been faulted.

So while the main AD thread is clearly recording events, the "blocking" problem is that logging and notification seem to be in the same thread, so blocking in the notification also blocks logging in the thread, resulting in incorrect timestamps on the zone events. Things come out in the correct order, just with the wrong time. The wrong time would presumably appear in the notification timestamps of other notification vectors that aren't blocked too. If you're doing a lot of notifications that are blocked, and there are a lot of events, the timestamps become meaningless until events that happen subsequent to when the blocked notifications clear. So, that's the problem I'll look at. If logging can be done before sending notifications off to a thread, or an accurate timestamp recorded and propagated through the logging and notification thread, that should solve the problem. A second thing to look at will be threading out each notification separately, so unblocked notification vectors aren't held sending up by blocked vectors.

[kevin]

The reason the logs are like that is because LogNotification is a notification type - the only default enforced notification the system has... but yeah, you're right that the timestamp is a problem - it is possible to modify the code to issue the timestamp at notification creation rather than send, or you may just adjust timeouts to like 10s to get around it... whatever works for you really