search

zigpy / bellows

A Python 3 project to implement EZSP for EmberZNet devices
GNU General Public License v3.0
184 stars 87 forks source link

NCP entered failed state. #179

Closed causefx closed 4 years ago

causefx commented 5 years ago

For some odd reason my bellows "crashes" every few days. I will have this message in my logs:

2019-08-09 02:20:01 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart

Then absolutely nothing after that as HA is no longer responsive.

I'm not sure where to troubleshoot as there is nothing beside that in the logs.

Throughout the day I will have a few of these:

2019-08-09 07:32:26 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 365, in request
    res = await asyncio.wait_for(req.send, timeout=APS_ACK_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 442, in wait_for
    return fut.result()
zigpy.exceptions.DeliveryError: [0xbde4:0:0x8006]: message send failure: EmberStatus.DELIVERY_FAILED

Thanks!

Adminiuga commented 5 years ago

What version?

causefx commented 5 years ago 
bellows-homeassistant==0.9.0

looks like 0.9.0

perosb commented 4 years ago

In my case I see this daily. Not sure if the cause is the same as yours. The devices in my case are mapped into the docker container. There is nothing else than hass in docker that should be using the device. v0.11.0


2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'459621adcd107e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5596a1adcd2f7e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2019-12-07 09:54:52 DEBUG (MainThread) [bellows.ezsp] Application frame 5 (nop) received: b''
2019-12-07 09:54:52 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xbe71, <EmberApsFrame profileId=260 clusterId=6 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=91>, 92, b'\x01[\x01')
2019-12-07 09:54:52 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7ce2, <EmberApsFrame profileId=260 clusterId=6 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=93>, 94, b'\x01]\x01')
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'5697219c545babb658924a24ab1593499c157ba8ec956621827e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6697a19c54d445af7e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2019-12-07 09:54:52 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'00fe'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'6794219c54c869b658924a24ab1593499c7d3379a8ec93667d5de57e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7794a19c54d5e4787e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2019-12-07 09:54:52 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'00ff'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0794b1f12594ded3696ab572a1556d8d9c327d7e'
2019-12-07 09:54:52 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received: b'71becb6130feff570b00ffc400'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1794b1f12594ded3696ab572a1556d8d9c2c7c7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0xbe71, 00:0b:57:ff:fe:30:61:cb, 255, -60, []]
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received: b'71becb6130feff570b00ffc400'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0xbe71, 00:0b:57:ff:fe:30:61:cb, 255, -60, []]
2019-12-07 09:54:53 ERROR (bellows.thread_0) [bellows.uart] Lost serial connection: read failed: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] /dev/ttyUSB-zha connection lost unexpectedly: read failed: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2019-12-07 09:54:53 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.zigbee.application] Received _reset_controller_application frame with ('Serial connection loss: read failed: device reports readiness to read but returned no data (device disconnected or multiple access on port?)',)
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.zigbee.application] Resetting ControllerApplication. Cause: 'Serial connection loss: read failed: device reports readiness to read but returned no data (device disconnected or multiple access on port?)'
2019-12-07 09:54:53 WARNING (MainThread) [bellows.thread] Attempted to use a closed event loop
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Reconnecting /dev/ttyUSB-zha serial port on 57600 bauds
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Resetting ASH
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'1ac038bc7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command version: (4,)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'004221a850ed2c7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0142a1a8502815e23c957e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 0 (version) received: b'04020050'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command version: (4,)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d314321a85035937e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1243a1a8502815e271357e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 0 (version) received: b'04020050'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Switched to EZSP protocol version 4
2019-12-07 09:54:53 INFO (MainThread) [bellows.ezsp] EZSP Stack Type: 2, Stack Version: 20480
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_STACK_PROFILE: 12>, 2)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'224021fb5828158cc87e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2340a1fb54c6107e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>, 5)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'334121fb592f15e8d57e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3441a1fb54d32a7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_SUPPORTED_NETWORKS: 45>, 1)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'444621fb792b15f7b37e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4546a1fb5435d07e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS: 42>, 3)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'554721fb7d5e2915defb7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5647a1fb54a9ec7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_PAN_ID_CONFLICT_REPORT_THRESHOLD: 34>, 2)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'664421fb7628150b847e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6744a1fb54948f7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 25>, 2)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'774521fb4d2815f46a7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7045a1fb5481b57e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_ADDRESS_TABLE_SIZE: 5>, 16)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'004a21fb513a15ff5f7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'014aa1fb54e28c7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_SOURCE_ROUTE_TABLE_SIZE: 26>, 8)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d314b21fb4e2215d06d7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'124ba1fb547eb07e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_MAX_END_DEVICE_CHILDREN: 17>, 32)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'224821fb450a15e03c7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2348a1fb5443d37e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT: 18>, 7680)
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'334921fb462a0b86cf7e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3449a1fb5456e97e'
2019-12-07 09:54:53 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2019-12-07 09:54:53 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_KEY_TABLE_SIZE: 30>, 1)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'444e21fb4a2b1566047e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'454ea1fb54b0137e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRANSIENT_KEY_TIMEOUT_S: 54>, 180)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'554f21fb629e1562217e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'564fa1fb636a9b7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'37'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT: 19>, 60)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'664c21fb471615d2c97e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'674ca1fb54114c7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT_SHIFT: 27>, 8)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'774d21fb4f221578837e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'704da1fb5404767e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>, 16)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'005221fb523a15b1c97e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0152a1fb547ce87e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_PACKET_BUFFER_COUNT: 1>, 255)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d315321fb55d515fe6f7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1253a1fb54e0d47e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getConfigurationValue: (<EzspConfigId.CONFIG_APS_UNICAST_MESSAGE_COUNT: 3>,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'225021fa574fee7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2350a1fa54201586817e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 82 (getConfigurationValue) received: b'000a00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.zigbee.application] APS_UNICAST_MESSAGE_COUNT is set to 10
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command addEndpoint: (1, 260, 48879, 0, 0, 1, [], [1280])
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'335121aa552e145de7944a24aa50e0797e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3451a1aa54f5037e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 2 (addEndpoint) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.zigbee.application] Ezsp adding endpoint: [<EzspStatus.SUCCESS: 0>]
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command networkInit: ()
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'445621bfaf207e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4556a5bf5433bf7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5556b1b1c408f07e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 23 (networkInit) received: b'00'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getNetworkParameters: ()
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'56572180a9637e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 25 (stackStatusHandler) received: b'90'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6657a180542ba69099cb32bab33aaf77944127abedce677302c1083c7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 40 (getNetworkParameters) received: b'0001b322c05f789f196f3d3e080f0000000000f8ff07'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setPolicy: (<EzspPolicyId.TC_KEY_REQUEST_POLICY: 5>, <EzspDecisionId.DENY_TC_KEY_REQUESTS: 80>)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'675421fd517a07d77e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7754a1fd5421d47e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 85 (setPolicy) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setPolicy: (<EzspPolicyId.APP_KEY_REQUEST_POLICY: 6>, <EzspDecisionId.ALLOW_APP_KEY_REQUESTS: 97>)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'705521fd524b0c627e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0055a1fd542d327e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 85 (setPolicy) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command setPolicy: (<EzspPolicyId.TRUST_CENTER_POLICY: 0>, <EzspDecisionId.ALLOW_PRECONFIGURED_KEY_JOINS: 1>)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'015a21fd542bafa77e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'115aa1fd5457d77e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 85 (setPolicy) received: b'00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getNodeId: ()
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'125b218f89807e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'225ba18f542a856f7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 39 (getNodeId) received: b'0000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getEui64: ()
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'2358218e9aac7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3358a18e3d1310bf59fb4725ce387e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 38 (getEui64) received: b'6939050d006f0d00'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.zigbee.application] EZSP nwk=0x0000, IEEE=00:0d:6f:00:0d:05:39:69
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (0,)
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.zigbee.application] Starting EZSP watchdog
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'345921cb5473817e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4459a1cb542a15b2f7c57e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[0] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (1,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'455e21cb55855a7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'555ea1cb542a15b294e67e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[1] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (2,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'565f21cb5629057e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'665fa1cb542a15b2a22e7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[2] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (3,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'675c21cb5704477e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'775ca1cb542a15b200cb7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[3] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (4,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'705d21cb50619a7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'005da1cb542a15b2cfbe7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[4] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (5,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'016221cb513e6b7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1162a1cb542a15b266bd7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[5] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (6,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'126321cb5292347e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2263a1cb542a15b250757e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[6] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (7,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'236021cb53bf767e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3360a1cb542a15b2f2907e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[7] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (8,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'346121cb5c5ba37e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4461a1cb542a15b23de57e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[8] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (9,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'456621cb5dad787e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5566a1cb542a15b25ec67e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[9] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (10,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'566721cb5e01277e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6667a1cb542a15b2680e7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[10] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (11,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'676421cb5f2c657e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7764a1cb542a15b2caeb7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[11] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (12,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'706521cb5849b87e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0065a1cb542a15b2059e7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[12] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (13,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'016a21cb593aa07e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'116aa1cb542a15b2f5107e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[13] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (14,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'126b21cb5a96ff7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'226ba1cb542a15b2c3d87e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[14] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Send command getMulticastTableEntry: (15,)
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'236821cb5bbbbd7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3368a1cb542a15b2613d7e'
2019-12-07 09:54:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.ezsp] Application frame 99 (getMulticastTableEntry) received: b'00000000'
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.multicast] MulticastTableEntry[15] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
2019-12-07 09:54:54 DEBUG (MainThread) [bellows.zigbee.application] ControllerApplication successfully reset```
perosb commented 4 years ago

I believe I found the root cause for my issue. When issuing too many commands, it need more Voltage.

Dec 07 12:37:15 arrakis kernel: Under-voltage detected! (0x00050005)
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: usb_serial_generic_write_bulk_callback - urb stopped: -32
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: usb_serial_generic_write_bulk_callback - urb stopped: -32
Dec 07 12:37:18 arrakis kernel: usb 1-1.4: USB disconnect, device number 120
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: failed set request 0x7 status: -19
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: failed set request 0x12 status: -19
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: failed set request 0x0 status: -19
Dec 07 12:37:18 arrakis kernel: cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
Dec 07 12:37:18 arrakis kernel: cp210x 1-1.4:1.0: device disconnected
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: new full-speed USB device number 121 using dwc_otg
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: New USB device found, idVendor=10c4, idProduct=8293, bcdDevice= 1.00
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: Product: Telegesis USB Device
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: Manufacturer: Silicon Labs
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: SerialNumber: 04000B22
Dec 07 12:37:19 arrakis kernel: cp210x 1-1.4:1.0: cp210x converter detected
Dec 07 12:37:19 arrakis kernel: usb 1-1.4: cp210x converter now attached to ttyUSB0

Probably need a new power adapter.

Edit: Maybe not...hmm..Even unplugging everything else I get the below. And ther eis no mention of under voltage.

Dec 07 13:15:28 arrakis kernel: cp210x ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
Dec 07 13:15:28 arrakis kernel: cp210x ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
Dec 07 13:15:28 arrakis kernel: usb 1-1.4: USB disconnect, device number 65
Dec 07 13:15:28 arrakis kernel: cp210x ttyUSB0: failed set request 0x7 status: -19
Dec 07 13:15:28 arrakis kernel: cp210x ttyUSB0: failed set request 0x12 status: -19
Dec 07 13:15:28 arrakis kernel: cp210x ttyUSB0: failed set request 0x0 status: -19
Dec 07 13:15:28 arrakis kernel: cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
Adminiuga commented 4 years ago

Try a different power adapter. Sometimes they go bad. Try a different USB port as well

hayatae commented 4 years ago

I just ran into a similar problem today. Seriously doubt it's a power supply issue in my case since I have home assistant running on a full desktop PC. It looks like connection to the physical device was lost and never recovered?

2020-04-12 08:51:04 ERROR (bellows.thread_0) [bellows.uart] Lost serial connection: read failed: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2020-04-12 08:51:04 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart

Even though a restart was requested, the Application Controller remains not running even hours later. I'm going to try switching to a different USB port and see if there is any improvement.

meremortals70 commented 4 years ago

I am also receiving the same result when I try and change the zigbee channel

Adminiuga commented 4 years ago

If it lost serial connection, then restart won't succeed until connection is re-established. It may never happen if the connection is not established. You'll have to enable debug logging to get more insight

CanDoAnything commented 4 years ago

I've started getting these odd bellows errors recently as described above and I haven't had any luck in figuring it out. The only change I've made recently is adding a very low power case fan. I've since removed it and the problem persists.

My setup: I'm running HA in docker on an RPi4 on raspbian. I'm using the GoControl CECOMINOD016164 HUSBZB-1 USB Hub I'm running raspbian from a USB hard drive (this usb3 128gb)

Specific errors and odd log entries:

Things I've tried:

  1. Restarted the rpi
  2. Changed the zigbee stick to a different USB port
  3. Tried a different power adapter for the rpi
  4. Deleted zigbee.db and let HA recreate a fresh db
  5. Changed the volume / working directory of my HA entry in my docker-compose.yml from /home/pi/homeassistant:/config to /home/pi/homeassistant2:/config (basically HA was treated as a fresh install)

None of these prevented those errors from appearing. Zigbee calls will work, and then just randomly stop working for a period of a few seconds to a minute or so. For example, i can do a few subsequent changes to a zigbee light (change to 10%, then 30%, then 100%, then back to 20%, etc) at some point it'll just stop responding and those errors will appear in the log. That light (and all other zigbee devices) will be unresponsive for ~30-1min+.

Because of 4 and 5 above and the "lost serial connection" error, it makes me believe it's a hardware or power issue. Also, I've come across this article , which leads me to the same: a hardware or power issue. I'm thinking my next step is to try a powered USB hub?

suggestions appreciated!! 😁

Adminiuga commented 4 years ago

check that /config/home-assistant_v2.db is under 300MB

CanDoAnything commented 4 years ago

@Adminiuga - I'm using a MySQL instance on another machine for the main recorder/db

Vlad-Star commented 3 years ago

Same problem here. Nortek stick, was getting NCP errors. Upgraded NCP to version 6.6.3, still getting the same errors. Situation became much worse with HA upgrade from 0.114 to 0.117.4 (heavy delays, constantly missed automations etc.). home-assistant_v2.db file is 392Mb.

2020-11-13 07:56:36 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:36 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:36 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:37 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:37 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:37 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:37 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:38 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2020-11-13 07:56:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.2nd_floor_salt_lamp_power is taking over 10 seconds
2020-11-13 07:56:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.master_bedroom_salt_lamp_power is taking over 10 seconds
2020-11-13 07:56:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.living_room_salt_lamp_power is taking over 10 seconds
2020-11-13 07:56:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.front_door_entrance_salt_lamp_power is taking over 10 seconds
2020-11-13 07:57:20 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30
2020-11-13 07:57:50 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30
CanDoAnything commented 3 years ago

I believe the issue is a failing SD card.Run the raspberry pi health check. It's under accessories> raspberry pi diagnostics. My write speeds were absolutely terrible.

I bought a new SD card and did a fresh install of everything and I'm working like normal.

After some basic researching I ended up on a kingston card. https://www.amazon.com/dp/B0858B1HBT

Vlad-Star commented 3 years ago

@CanDoAnything Thank you for the suggestion, though I doubt this is the case (see below, SD access speed is 44MB/s).

I am running Hassio (not a docker container under Raspbian) on top of Samsung EVO 64Mb SD card (that is less than 6 months old). I didn't have such issues with the initial installation HassOS 4.12 image (latest as of 08/12/2020, I believe with HA 0.111) but upgrade to HassOS 4.15/HA 0.114 made the problem "visible" (once in a while) and upgrade to HassOS 4.16/HA 0.117 made it even worse (50% of the time Zigbee motion sensor doesn't trigger the basement stairs GE Zwave dimmer). Surely I added few integrations since the initial installation, but they didn't affect functionality at the time when I added them.

# df -h /mnt/data
Filesystem                Size      Used Available Use% Mounted on
/dev/mmcblk0p8           58.0G      8.0G     47.0G  15% /mnt/data
# hdparm -tT /dev/mmcblk0p8

/dev/mmcblk0p8:
Timing buffer-cache reads:  1020 MB in 0.50 seconds = 2049941 kB/s
Timing buffered disk reads:  130 MB in 3.01 seconds = 44188 kB/s
#
Vlad-Star commented 3 years ago

I'll be happy to provide whatever logs are needed to get the problem solved - just let me know what exactly to do.

Adminiuga commented 3 years ago

Do you have any add-ons which are disk IO heavy?

CanDoAnything commented 3 years ago

@CanDoAnything Thank you for the suggestion, though I doubt this is the case (see below, SD access speed is 44MB/s).

Isn't that speed sequential though? My understanding is that SD cards need good random read and write speeds to perform adequately on a PI. The card I replaced was a 32gb Samsung EVO Select -- when I ran the test on that card test its sequential speeds were fine, but the random write/read IOPS were failing. https://www.raspberrypi.org/blog/sd-card-speed-test/

Depending on how much is being written to that card ~6 months might be enough to start to wear it down and cause speed degradation. Especially if you have the sqlite db saving on the card. @Adminiuga , do you agree?

In addition to that Kingson sd card; I also ordered a Sandisk extreme (the gold /red one) as i wanted to compare them since they both were rated highly. My quick bs test has the Kingston performs much better:

https://www.amazon.com/dp/B0858B1HBT

Raspberry Pi Diagnostics - version 0.5
Sat Nov 14 10:47:00 2020

Test : SD Card Speed Test
Run 1
prepare-file;0;0;32768;64
seq-write;0;0;32866;64
rand-4k-write;0;0;5707;1426
rand-4k-read;12013;3003;0;0
Sequential write speed 32866 KB/sec (target 10000) - PASS
Random write speed 1426 IOPS (target 500) - PASS
Random read speed 3003 IOPS (target 1500) - PASS
Test PASS

https://www.amazon.com/gp/product/B07FCMBLV6

Raspberry Pi Diagnostics - version 0.5
Sun Nov 15 03:57:21 2020

Test : SD Card Speed Test
Run 1
prepare-file;0;0;19974;39
seq-write;0;0;19168;37
rand-4k-write;0;0;3481;870
rand-4k-read;8379;2094;0;0
Sequential write speed 19168 KB/sec (target 10000) - PASS
Random write speed 870 IOPS (target 500) - PASS
Random read speed 2094 IOPS (target 1500) - PASS
Test PASS
Vlad-Star commented 3 years ago

@Adminiuga I don't think so.

Here is a list of add-ons that I have:

Integrations:

Plus few non-standard integrations:

GreenEye monitor may be periodically writing sensor's data (load, temperatures etc.), back to the SD card but shouldn't cause any problems, it should be few kilobytes per minute. I can disable all 3 of them if needed.

I am also attaching my full home-assistant log - according to it, something bad is happening to bellows.zigbee.application and EZSP process. 20201115-home-assistant-log.zip

Vlad-Star commented 3 years ago

@CanDoAnything thank you for the link! I've ordered Kingston, it should arrive tomorrow. I will clone my existing card to it and let you know.

Adminiuga commented 3 years ago

Yeah, random writes are more important, than sequential. Although I had evo 32gb cards running with full debug for quite a while before it gave up. In one specific case, it was the bad power supply causing the issue.

Vlad-Star commented 3 years ago

@CanDoAnything @Adminiuga Thank you folks for helping me out, I really appreciate it!

It turned out that Kingston 64G SD card had fewer blocks compared to Samsung EVO 64G, so I couldn't clone it directly. Instead, I've created a snapshot, downloaded and installed fresh HA 0.117 to Kingston SD card and then restored configuration from the snapshot. It worked like a charm and no longer reports those NCP errors. Not sure what exactly was wrong, but the issue is now resolved.

In addition, to put a relief on SD card, I moved recorder from sqlite (homeassistant_v2.db) to mysql (which I run on the adjacent server anyway).

salvq commented 3 years ago

I suspect this is related to Wi-Fi <-> Zigbee controllers, zigbee requires stable connection, see below

Warning about Zigbee to WiFi bridges zigpy requires a robust connection between the zigpy radio library and the serial port of the Zigbee radio. With solutions such as ITEAD Sonoff ZBBridge or a Ser2Net serial proxy connection over a WiFi network it is expected to see NCP entered failed state. Requesting APP controller restart in the logs. This is a normal part of the operation and indicates there was a drop in communication which caused packet loss to occurred between the zigpy radio library and the Zigbee radio. The use of serial network proxies/bridges/servers over WiFi is therefore not recommended when wanting a stable Zigbee environment with zigpy.

Github bellows

FARKIr commented 1 year ago

skontrolujte, či /config/home-assistant_v2.dbje menej ako 300 MB

https://prnt.sc/501qtpxt2pqk