Reset EZSP stack on error frames or missing heartbeats #147

Adminiuga · 2019-02-28T21:23:26Z

This is one of the fixes targeted to address #124

Reset EZSP if we receive error frames
Reset EZSP if there're missing heartbeats (EZSP nop command) from EZSP
Reset EZSP if serial connection is lost

in my test it would successfully reconnect on USB stick un-plug/plug back in. I was able to reproduce the Error farme with "Maximum NAK exceeded" condition, by artificially suppressing sending ACKs to NCP and successfully recovering from it.
With that said, I'm looking for volunteers to test drive it and additional feedback.

walthowd · 2019-02-28T21:28:09Z

I can throw this on my old problematic system early next week and do some testing for you.

Adminiuga · 2019-02-28T21:39:27Z

@walthowd I appreciate the feedback. Keep in mind this PR addresses one area only (resseting NCP on error frame) so I does not include any other work arrounds related to pending sequence handling.

Adminiuga · 2019-02-28T21:49:05Z

and please also keep in mind that HA dev tree depends on bellows-homeassistant now so you may need to update the dependencies in homeassistant/components/zha/__init__.py

Adminiuga · 2019-03-02T22:21:17Z

please merge after PR #150 which should make code much cleaner

walthowd · 2019-03-05T18:13:22Z

@Adminiuga Running on my old system today, I pulled the USB adapter out at 12:09:53 and it was successfully reset and ZHA commands continued to work after it was reset.

I'll leave it running longer today and see if I can get a real UART error

https://www.dropbox.com/s/ysiaa1sipy44xsd/home-assistant-serial-reset.txt?dl=0

Adminiuga · 2019-03-05T19:53:54Z

That's really good feedback and offers some more visibility into what was happening (but not why)

2019-03-05 12:09:38 ERROR (MainThread) [bellows.uart] Lost serial connection: read failed: [Errno 6] Device not configured
2019-03-05 12:09:38 DEBUG (MainThread) [bellows.ezsp] /dev/tty.GoControl_zigbee connection lost unexpectedly: read failed: [Errno 6] Device not configured
2019-03-05 12:09:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2019-03-05 12:09:38 DEBUG (MainThread) [bellows.zigbee.application] Resetting ControllerApplication. Cause: 'Serial connection loss: read failed: [Errno 6] Device not configured'
2019-03-05 12:09:38 DEBUG (MainThread) [bellows.ezsp] Reconnecting /dev/tty.GoControl_zigbee serial port on 57600 bauds
2019-03-05 12:09:38 DEBUG (MainThread) [bellows.zigbee.application] ControllerApplication reset unsuccessful: [Errno 2] could not open port /dev/tty.GoControl_zigbee: [Errno 2] No such file or directory: '/dev/tty.GoControl_zigbee'
2019-03-05 12:09:43 DEBUG (MainThread) [bellows.ezsp] Reconnecting /dev/tty.GoControl_zigbee serial port on 57600 bauds
2019-03-05 12:09:43 DEBUG (MainThread) [bellows.zigbee.application] ControllerApplication reset unsuccessful: [Errno 2] could not open port /dev/tty.GoControl_zigbee: [Errno 2] No such file or directory: '/dev/tty.GoControl_zigbee'
 ...[skipping  some noise] ...
2019-03-05 12:09:48 DEBUG (MainThread) [bellows.ezsp] Reconnecting /dev/tty.GoControl_zigbee serial port on 57600 bauds
2019-03-05 12:09:48 DEBUG (MainThread) [bellows.zigbee.application] ControllerApplication reset unsuccessful: [Errno 2] could not open port /dev/tty.GoControl_zigbee: [Errno 2] No such file or directory: '/dev/tty.GoControl_zigbee'
2019-03-05 12:09:53 DEBUG (MainThread) [bellows.ezsp] Reconnecting /dev/tty.GoControl_zigbee serial port on 57600 bauds
2019-03-05 12:09:53 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP
2019-03-05 12:09:53 DEBUG (MainThread) [bellows.uart] Resetting ASH
2019-03-05 12:09:53 DEBUG (MainThread) [bellows.uart] Sending: b'1ac038bc7e'
2019-03-05 12:09:54 DEBUG (MainThread) [bellows.uart] RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
2019-03-05 12:09:54 DEBUG (MainThread) [bellows.ezsp] Send command version

For whatever reason it looks like the serial port is disconnected, like when the device is unplugged. You get that weird device not configure error on connection loss and then the actual device file is gone for like 12s before HASS can access the serial device TTY again. I don't know why OS looses the device, but bellows did not handle serial port disconnects at all until this PR
I also think the EZSP itself was not resetting, just the serial connection flipping off and on. That could explain why are never were seeing some of the messageSent callback frames causing TSN leak.

PS: this does not mean that exactly the same issue was happening to everyone else with the similar symptoms.

Adminiuga · 2019-03-05T19:59:44Z

@walthowd do you mind runing PR 150, 149 and 148 mashup branch? It has all three PRs mashed together and shouldn't leak any TSNs

walthowd · 2019-03-06T03:12:58Z

@Adminiuga I pulled the mashup branch and ran the system for another few hours -- no natural occurring errors but I pulled the USB again at 19:26:21 - same behaviour as before.

https://www.dropbox.com/s/vu6kdqud9yv07wk/home-assistant-serial-reset.log.gz?dl=0

It looks like the mashup branch does not have the extra logging to see if any sequence IDs are leaking?

Adminiuga · 2019-03-06T03:28:03Z

Nah, don't have any extra debug logging in this branch as I'm hope to get it included into upstream. I'd be very surprised if it leaks any TSNs, as everything is cleaned up by the "context manager" exception or no exception.

This line pushes new "pending" request to self._pending so would be a good place to check for other pending TSNs. Something like

for tsn, req in self._pending.items():
    LOGGER.debug("Currently pending TSN %03i: Send: %s, Reply: %s", tsn, req.send, req.reply)
LOGGER.debug("Adding new TSN %03i", self.sequence

Make ControllerApplication.initialize() a retryable method. Add bellows specific exceptions. Handle EzspError exception in requests.

Refactor ControllerApplication reset flow. Reset ControllerApplication on watchod failures. Allow UART reconnects. Initiate ControllerApplication reset on UART connection loss.

Serial connection loss restarts reset task. Error frames do not pre-empts a running reset task.

If we receive a Reset ACK frame to a reset we've not initiated, then request ControllerApplication reset.

New ControllerError exception. Execute broadacast() and/or request() only if ControllerApplication is running.

dmulcahey · 2019-03-22T11:57:14Z

@damarco any chance we can get this in a release in time for .91?

Adminiuga · 2019-03-22T13:22:52Z

give me two days, need to do some more testing, but so far I was satisfied with the results on Pi2

Adminiuga · 2019-03-23T00:29:20Z

I think this is the version I want to go with. Will be running it for a few days and remove WIP tag once the dust settles.

Adminiuga · 2019-03-25T15:55:52Z

@damarco @dmulcahey I'm ready with this one.
For the note: this still doesn't make Pi2 a great platform for running ZHA, but at least now it can run more or less.

Properly handle replies arriving past EZSP cmd timeout.

Stop watchdog on controller shutdown.

damarco · 2019-03-27T19:37:42Z

Thanks!

rjgrandy · 2019-03-27T22:43:15Z

I believe I have similar issue from #124 (zigbee devices initially work, after some time they stop), is there a way I can test this new code on my system? I can provide feedback on the the effect.

Adminiuga · 2019-03-27T23:53:01Z

@rjgrandy what hardware are you running on and what environment. I hope this would make into 0.92

rjgrandy · 2019-03-28T01:28:54Z

@Adminiuga I am using a HUSBZB with a RPI3B+, I have everything running using docker.

I get a number of the below errors:

2019-03-26 07:17:53 DEBUG (MainThread) [bellows.uart] Error frame: b'c20251a8bd7e'

Then I start getting the below message over and over:

2019-03-26 07:18:10 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30

Adminiuga · 2019-03-29T21:12:04Z

@rjgrandy looks like it would be in HA 0.91 next Wed. It is in beta now.

rjgrandy · 2019-03-29T21:33:59Z

@Adminiuga Ok awesome, if I install one of the betas now, I can check to see if it helps my issue?

Adminiuga · 2019-03-29T21:35:47Z

yes

…

On Fri, 29 Mar 2019 at 17:34, rjgrandy ***@***.***> wrote: @Adminiuga <https://github.com/Adminiuga> Ok awesome, if I install one of the betas now, I can check to see if it helps my issue? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#147 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFjmcDBE18k20pRoLWBVu_MLKIVyGKEgks5vbobIgaJpZM4bXw7-> .

rjgrandy · 2019-03-30T01:41:53Z

@Adminiuga I pulled the beta2, so far my zigbee devices do seem to be able to maintain controllability, however it is putting out a lot more to the log than before (i do have all the relevant zigbee on debug in the logger) the zigbee devices appear to react slowly and it looks like it is constantly resetting EZSP and ASH.

2019-03-30 01:32:47 DEBUG (MainThread) [bellows.ezsp] Reconnecting /dev/zigbee serial port on 57600 bauds
2019-03-30 01:32:47 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP
2019-03-30 01:32:47 DEBUG (MainThread) [bellows.uart] Resetting ASH
2019-03-30 01:32:47 DEBUG (MainThread) [bellows.uart] Sending: b'1ac038bc7e'

rjgrandy · 2019-03-30T16:49:23Z

Just to follow up on my last comment, I installed beta3 this morning, disabled all logger debug output for zigbee related things, deleted the home-assistant_v2.db (it was almost 3GB). After this, so far the zigbee devices seem pretty stable and responsive.

Also I like the new ZHA "Add Devices" screen :)

Adminiuga mentioned this pull request Mar 1, 2019

Wrap send_fut in a timeout #148

Merged

dmulcahey approved these changes Mar 1, 2019

View reviewed changes

Adminiuga force-pushed the fixes/reset-ncp branch from 46f32c7 to f64cd7c Compare March 1, 2019 18:07

Adminiuga changed the title ~~RFC: Reset EZSP stack on error frames or missing heartbeats~~ WIP & RFC: Reset EZSP stack on error frames or missing heartbeats Mar 1, 2019

Adminiuga changed the title ~~WIP & RFC: Reset EZSP stack on error frames or missing heartbeats~~ RFC: Reset EZSP stack on error frames or missing heartbeats Mar 1, 2019

Adminiuga changed the title ~~RFC: Reset EZSP stack on error frames or missing heartbeats~~ RFC & WIP: Reset EZSP stack on error frames or missing heartbeats Mar 2, 2019

Adminiuga force-pushed the fixes/reset-ncp branch from 177edea to 63615f8 Compare March 6, 2019 03:04

Adminiuga added 11 commits March 10, 2019 10:57

Decode error frame.

baaa4bd

Reset bellows on receiving an error frame.

245ed56

Add timeout to all EZSP commands.

0129a63

Add timeout to Gateway.reset().

d6033ba

Add EZSP running event.

d6ea6a5

Make ControllerApplication.initialize() a retryable method. Add bellows specific exceptions. Handle EzspError exception in requests.

Implement ConntrollerApplication watchdog.

73aecc5

Refactor ControllerApplication reset flow. Reset ControllerApplication on watchod failures. Allow UART reconnects. Initiate ControllerApplication reset on UART connection loss.

Make reset task pre-emptable.

b6b88bc

Serial connection loss restarts reset task. Error frames do not pre-empts a running reset task.

Update unit tests.

d74d6d0

Reset ControllerApllication on reset ACK frames.

ccdbfa8

If we receive a Reset ACK frame to a reset we've not initiated, then request ControllerApplication reset.

Stop EZSP if closing serial port.

f211662

Execute requests only if controller app is running.

7308f2a

New ControllerError exception. Execute broadacast() and/or request() only if ControllerApplication is running.

Adminiuga force-pushed the fixes/reset-ncp branch from 3c65b1b to 3d08520 Compare March 10, 2019 20:52

Adminiuga mentioned this pull request Mar 20, 2019

zha lights work OK following homeassistant.restart, but stop responding within hours #124

Closed

Adminiuga force-pushed the fixes/reset-ncp branch 4 times, most recently from 8e2606b to ddbfa2e Compare March 23, 2019 00:17

Adminiuga changed the title ~~RFC & WIP: Reset EZSP stack on error frames or missing heartbeats~~ Reset EZSP stack on error frames or missing heartbeats Mar 25, 2019

Adminiuga added 3 commits March 25, 2019 19:38

Increase EZSP command timeout.

197f728

Properly handle replies arriving past EZSP cmd timeout.

shutdownd() method for ControllerApplication.

7a813c2

Stop watchdog on controller shutdown.

Always preempt reset task.

a4c89db

Adminiuga force-pushed the fixes/reset-ncp branch from ddbfa2e to a4c89db Compare March 25, 2019 23:38

damarco merged commit 55a1345 into zigpy:master Mar 27, 2019

Adminiuga deleted the fixes/reset-ncp branch March 27, 2019 23:46

Adminiuga mentioned this pull request May 23, 2019

Application should re-establish connection to uart after error #37

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Reset EZSP stack on error frames or missing heartbeats #147

Reset EZSP stack on error frames or missing heartbeats #147

Adminiuga commented Feb 28, 2019

walthowd commented Feb 28, 2019

Adminiuga commented Feb 28, 2019

Adminiuga commented Feb 28, 2019

Adminiuga commented Mar 2, 2019

walthowd commented Mar 5, 2019

Adminiuga commented Mar 5, 2019 •

edited

Loading

Adminiuga commented Mar 5, 2019

walthowd commented Mar 6, 2019

Adminiuga commented Mar 6, 2019

dmulcahey commented Mar 22, 2019

Adminiuga commented Mar 22, 2019

Adminiuga commented Mar 23, 2019

Adminiuga commented Mar 25, 2019

damarco commented Mar 27, 2019

rjgrandy commented Mar 27, 2019

Adminiuga commented Mar 27, 2019

rjgrandy commented Mar 28, 2019

Adminiuga commented Mar 29, 2019

rjgrandy commented Mar 29, 2019

Adminiuga commented Mar 29, 2019 via email

rjgrandy commented Mar 30, 2019

rjgrandy commented Mar 30, 2019

Reset EZSP stack on error frames or missing heartbeats #147

Reset EZSP stack on error frames or missing heartbeats #147

Conversation

Adminiuga commented Feb 28, 2019

walthowd commented Feb 28, 2019

Adminiuga commented Feb 28, 2019

Adminiuga commented Feb 28, 2019

Adminiuga commented Mar 2, 2019

walthowd commented Mar 5, 2019

Adminiuga commented Mar 5, 2019 • edited Loading

Adminiuga commented Mar 5, 2019

walthowd commented Mar 6, 2019

Adminiuga commented Mar 6, 2019

dmulcahey commented Mar 22, 2019

Adminiuga commented Mar 22, 2019

Adminiuga commented Mar 23, 2019

Adminiuga commented Mar 25, 2019

damarco commented Mar 27, 2019

rjgrandy commented Mar 27, 2019

Adminiuga commented Mar 27, 2019

rjgrandy commented Mar 28, 2019

Adminiuga commented Mar 29, 2019

rjgrandy commented Mar 29, 2019

Adminiuga commented Mar 29, 2019 via email

rjgrandy commented Mar 30, 2019

rjgrandy commented Mar 30, 2019

Adminiuga commented Mar 5, 2019 •

edited

Loading