Python Plugin Problem : Pushing 'onHeartbeatCallback' on to queue

[febalci]

Domoticz: 4.9701 stable
OS: Ubuntu 18.04
Python: 3.6.5

Using Crow Alarm plugin: https://github.com/febalci/DomoticzCrowAlarm

Every once in a while, plugin stops responding. Log file is as follows:

Code: Select all

2018-08-13 05:19:31.712  (Crow) onHeartbeat called
2018-08-13 05:19:31.712  (Crow) Pushing 'WriteDirective' on to queue
2018-08-13 05:19:31.712  (Crow) STATUS Message Sent
2018-08-13 05:19:31.712  (Crow) Processing 'WriteDirective' message
2018-08-13 05:19:31.712  (Crow) Sending 9 bytes of data
2018-08-13 05:19:31.712  (Crow)     53 54 41 54 55 53 20 0d 0a .. .. .. .. .. .. .. .. .. .. ..     STATUS...
2018-08-13 05:19:31.737  (Crow) Pushing 'ReadEvent' on to queue
2018-08-13 05:19:31.763  (Crow) Processing 'ReadEvent' message
2018-08-13 05:19:31.763  (Crow) Received 12 bytes of data
2018-08-13 05:19:31.763  (Crow)     44 41 0d 0a 44 42 0d 0a 52 4f 0d 0a .. .. .. .. .. .. .. ..     DA..DB..RO..
2018-08-13 05:19:31.763  (Crow) Pushing 'onMessageCallback' on to queue
2018-08-13 05:19:31.763  (Crow) Pushing 'onMessageCallback' on to queue
2018-08-13 05:19:31.763  (Crow) Pushing 'onMessageCallback' on to queue
2018-08-13 05:19:31.763  (Crow) Processing 'onMessageCallback' message
2018-08-13 05:19:31.763  (Crow) Calling message handler 'onMessage'.
2018-08-13 05:19:31.763  (Crow) onMessage called with Data: 'DA'
2018-08-13 05:19:31.763  (Crow) Message:DA
2018-08-13 05:19:31.763  (Crow) Processing 'onMessageCallback' message
2018-08-13 05:19:31.764  (Crow) Calling message handler 'onMessage'.
2018-08-13 05:19:31.764  (Crow) onMessage called with Data: 'DB'
2018-08-13 05:19:31.764  (Crow) Message:DB
2018-08-13 05:19:31.764  (Crow) Unknown: Action DB ignored.
2018-08-13 05:19:31.764  (Crow) Processing 'onMessageCallback' message
2018-08-13 05:19:31.764  (Crow) Calling message handler 'onMessage'.
2018-08-13 05:19:31.764  (Crow) onMessage called with Data: 'RO'
2018-08-13 05:19:31.764  (Crow) Message:RO
2018-08-13 05:19:31.764  (Crow) Ready On - All Zones Sealed
2018-08-13 05:20:01.709  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:20:31.724  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:21:01.740  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:21:31.755  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:22:01.770  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:22:31.783  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:22:50.753  (Crow) Queued asyncronous read aborted (192.168.1.195:5002).
2018-08-13 05:22:50.753  (Crow) Pushing 'DisconnectedEvent' on to queue
2018-08-13 05:23:01.799  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:23:31.814  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:24:01.829  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 05:24:31.845  (Crow) Pushing 'onHeartbeatCallback' on to queue

On 05:19:31 everything works fine. However the call on heartbeat at 05:20.01 and from there on the plugin stops responding. From then on even stopping and restarting the plugin doesnt work:

Code: Select all

2018-08-13 10:07:40.480  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 10:08:10.494  (Crow) Pushing 'onHeartbeatCallback' on to queue
2018-08-13 10:08:10.808  Status: (Crow) Stop directive received.
2018-08-13 10:08:10.809  (Crow) Pushing 'DisconnectDirective' on to queue
2018-08-13 10:08:10.994  Status: (Crow) Exiting work loop.
2018-08-13 10:08:40.886  Error: (Crow) Plugin did not stop after 30 seconds, flushing event queue...
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Sony Bravia 4K TV'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Salon UPS'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Synology UPS'
2018-08-13 10:08:40.888  Error: (Crow) Callback event 'onHeartbeatCallback' (Python call 'onHeartbeat') discarded.
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Sony Bravia 4K TV'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'AQI'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Traffic'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Salon UPS'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Synology UPS'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Synology UPS'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Traffic'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Salon UPS'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Sony Bravia 4K TV'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'AQI'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Salon UPS'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'AQI'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Sony Bravia 4K TV'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Traffic'
2018-08-13 10:08:40.888  (Crow) requeuing 'onHeartbeatCallback' message for 'Synology UPS'

Domoticz hangs a few minutes and at last stops all the plugins. But to get everything back to normal is only restarting of the domoticz service is required. What may be the problem??

[emontnemery]

Can you try with latest beta?
It has improved logging of these kind of hangs, which will make it easier to debug.
(Please make backup of your database so you can go back to stable version after testing)

[Dnpwwo]

@febalci,

You appear to have your "STATUS Poll Period" value set to 30 seconds which is too high, it should be less than 30 seconds otherwise Domoticz thinks the hardware has failed.

It looks like there was a disconnect at 05:22:50 that was the real cause of the problem. Did you force that?

The updated logging should give a better idea