Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Devices spamming network after dev update. #2092

Closed
Kryzek opened this issue Oct 7, 2019 · 12 comments
Closed

Devices spamming network after dev update. #2092

Kryzek opened this issue Oct 7, 2019 · 12 comments

Comments

@Kryzek
Copy link

Kryzek commented Oct 7, 2019

First I thought it would be more of an herdsman issue so I have this issue here too:
Koenkk/zigbee-herdsman#57

It seems that after update this morning my Airam devices (I have two of them) are spamming the zigbee network nonstop. I have turned all other router devices off (disconnected from power supply) and I still get a lot of messages from my single bulb:

  zigbee2mqtt:info 10/7/2019, 4:06:11 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"state":"OFF","linkquality":36,"brightness":242}'
  zigbee2mqtt:info 10/7/2019, 4:06:13 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"state":"OFF","linkquality":34,"brightness":242}'
  zigbee2mqtt:info 10/7/2019, 4:06:13 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"state":"OFF","linkquality":36,"brightness":242}'
  zigbee2mqtt:info 10/7/2019, 4:06:13 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"state":"OFF","linkquality":36,"brightness":242}'

I cannot get them to configure themselves with older version. Need to try repairing...
@Kryzek
Copy link
Author

Kryzek commented Oct 7, 2019

I did not get it to work with my usual stick after removing my usual coordinator stick after removing bulbs from database and configuration file. Instead I was greeted by this:

DEBUG=* npm start

> zigbee2mqtt@1.6.0 start /opt/zigbee2mqtt-backup
> node index.js

  serialport/bindings loading LinuxBinding +0ms
  zigbee2mqtt:info 10/7/2019, 4:59:38 PM Logging to directory: '/opt/zigbee2mqtt-backup/data/log/2019-10-07.16-59-37'
  zigbee2mqtt:debug 10/7/2019, 4:59:38 PM Removing old log directory '/opt/zigbee2mqtt-backup/data/log/2019-10-07.16-03-46'
  zigbee2mqtt:debug 10/7/2019, 4:59:38 PM Loaded state from file /opt/zigbee2mqtt-backup/data/state.json
  zigbee2mqtt:info 10/7/2019, 4:59:38 PM Starting zigbee2mqtt version 1.6.0 (commit #9d4705f)
  zigbee2mqtt:info 10/7/2019, 4:59:38 PM Starting zigbee-herdsman...
  zigbee2mqtt:debug 10/7/2019, 4:59:38 PM Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extenedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/opt/zigbee2mqtt-backup/data/database.db","backupPath":"/opt/zigbee2mqtt-backup/data/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"}}'
  zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[hidden],"panID":6754,"extenedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"},"databasePath":"/opt/zigbee2mqtt-backup/data/database.db","backupPath":"/opt/zigbee2mqtt-backup/data/coordinator_backup.json"}' +0ms
  zigbee-herdsman:znp:log Opening with /dev/ttyACM0 and {"baudRate":115200,"rtscts":true,"autoOpen":false} +0ms
  serialport/stream opening path: /dev/ttyACM0 +0ms
  serialport/binding-abstract open +0ms
  serialport/stream _read queueing _read for after open +8ms
  serialport/bindings/poller Creating poller +0ms
  serialport/stream opened path: /dev/ttyACM0 +4ms
  serialport/stream _read reading { start: 0, toRead: 65536 } +2ms
  serialport/binding-abstract read +28ms
  zigbee-herdsman:znp:log Serialport opened +46ms
  zigbee-herdsman:znp:log Writing skip bootloader payload +1ms
  zigbee-herdsman:unpi:writer --> buffer [239] +0ms
  serialport/stream _write 1 bytes of data +25ms
  serialport/binding-abstract write 1 bytes +11ms
  serialport/bindings/unixWrite Starting write 1 bytes offset 0 bytesToWrite 1 +0ms
  serialport/bindings/unixRead Starting read +0ms
  serialport/bindings/unixWrite write returned: wrote 1 bytes +5ms
  serialport/bindings/unixWrite Finished writing 1 bytes +0ms
  serialport/stream binding.write write finished +12ms
  serialport/bindings/unixRead waiting for readable because of code: EAGAIN +6ms
  serialport/bindings/poller Polling for "readable" +44ms
  serialport/bindings/poller error [Error: bad file descriptor] +147ms
  serialport/stream binding.read error [Error: bad file descriptor] +157ms
  serialport/stream disconnected [Error: bad file descriptor] +2ms
  serialport/stream #close +2ms
  serialport/binding-abstract close +173ms
  serialport/stream _read queueing _read for after open +3ms
  serialport/bindings/poller Stopping poller +13ms
  serialport/bindings/poller Destroying poller +2ms
  serialport/stream binding.close finished +4ms
  zigbee-herdsman:znp:SREQ --> SYS - version - {} +0ms
  zigbee-herdsman:unpi:writer --> frame [254,0,33,2,35] +1s
  zigbee2mqtt:error 10/7/2019, 4:59:45 PM Error while starting zigbee-herdsman
  zigbee2mqtt:error 10/7/2019, 4:59:45 PM Error: SRSP - SYS - version after 6000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-backup/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10)
  zigbee2mqtt:error 10/7/2019, 4:59:45 PM Failed to start zigbee
  zigbee2mqtt:error 10/7/2019, 4:59:45 PM Exiting...
  zigbee2mqtt:error 10/7/2019, 4:59:45 PM Error: SRSP - SYS - version after 6000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-backup/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10)

I switched to another USB-stick and I'm up and running again after repairing Airam bulbs with older commit version #9d4705f

@Koenkk
Copy link
Owner

Koenkk commented Oct 7, 2019

  • Do you use the report feature? report: true in configuration.yaml
  • Can you share the log of the spamming when running with debug logging.

To enable debug logging set in configuration.yaml:

advanced:
  log_level: debug

@Kryzek
Copy link
Author

Kryzek commented Oct 8, 2019

No I do not have reporting in use.

I need to get my another usb-stick reprogrammed since I cannot get Z2M to start with it anymore. I’ll test after with only one bulb in test environment. I will report back after.

@Kryzek
Copy link
Author

Kryzek commented Oct 9, 2019

I noticed that after repairing Airam bulbs are not reporting their state when controlled via their own remote or when powered on. Devices do not report their states periodically anymore either.

I did not have report: true in configuration file, but reporting was configured via devices.js from the time support for the device was added (Koenkk/zigbee-herdsman-converters#196). I believe this would mean I did have device reporting turned on from earlier time?

@Koenkk
Copy link
Owner

Koenkk commented Oct 9, 2019 •
edited
Loading

I think you should actually use reporting and that the configure should be removed for this bulb. This makes it consitent with the integration of other bulbs

@Kryzek
Copy link
Author

Kryzek commented Oct 13, 2019

I tried today with some time in hand to update to latest dev version. Now any of my devices do not talk with Z2M anymore,
I'm getting these

zigbee2mqtt:error 2019-10-13T11:02:31: Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'
zigbee2mqtt:info  2019-10-13T11:02:31: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'","meta":{"friendly_name":"0x00158d0001d0f272"}}'
zigbee2mqtt:error 2019-10-13T11:02:38: Failed to configure '0x00158d0001cded1c', attempt 1 (Error: AREQ - ZDO - bindRsp after 10000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-herdsman/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10))
zigbee2mqtt:info  2019-10-13T11:02:38: Configuring '0x00158d0001cca9aa'
zigbee2mqtt:error 2019-10-13T11:02:48: Failed to configure '0x00158d0001cca9aa', attempt 1 (Error: AREQ - ZDO - bindRsp after 10000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-herdsman/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10))
zigbee2mqtt:info  2019-10-13T11:02:48: Configuring '0x00158d0001cd1ef3'
zigbee2mqtt:error 2019-10-13T11:02:58: Failed to configure '0x00158d0001cd1ef3', attempt 1 (Error: AREQ - ZDO - bindRsp after 10000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-herdsman/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10))
zigbee2mqtt:info  2019-10-13T11:02:58: Configuring '0x00158d0001cc7354'
zigbee2mqtt:error 2019-10-13T11:03:08: Failed to configure '0x00158d0001cc7354', attempt 1 (Error: AREQ - ZDO - bindRsp after 10000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-herdsman/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10))
zigbee2mqtt:info  2019-10-13T11:03:08: Configuring '0x00158d0001d0f272'
zigbee2mqtt:error 2019-10-13T11:03:18: Failed to configure '0x00158d0001d0f272', attempt 1 (Error: AREQ - ZDO - bindRsp after 10000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt-herdsman/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10))
zigbee2mqtt:error 2019-10-13T11:03:29: Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'
zigbee2mqtt:info  2019-10-13T11:03:29: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'","meta":{"friendly_name":"0x00158d0001d0f272"}}'

Same with DEBUG=*

winston:file logged 21318 debug 2019-10-13T11:07:38: Received MQTT message on 'zigbee2mqtt/0x00158d0001d0f272/set' with data '{"state": "OFF"}'

winston:file logged 21394 debug 2019-10-13T11:07:38: Publishing 'set' 'state' to '0x00158d0001d0f272'

  serialport/bindings/unixWrite Starting write 18 bytes offset 0 bytesToWrite 18 +20s
  serialport/bindings/unixWrite write returned: wrote 18 bytes +3ms
  serialport/bindings/unixWrite Finished writing 18 bytes +1ms
  serialport/stream binding.write write finished +10ms
  serialport/bindings/poller received "readable" +20s
  serialport/binding-abstract read +22ms
  serialport/bindings/unixRead Starting read +20s
  serialport/bindings/unixRead Finished read { bytesRead: 6,
  buffer:
   <Buffer fe 0e 61 02 02 00 02 06 03 90 15 34 01 02 00 00 00 00 da fe 03 61 08 00 01 55 3e fe 03 61 08 00 01 55 3e fe 06 61 08 00 04 00 08 00 00 63 fe 03 61 08 ... > } bytes +2ms
  serialport/stream binding.read finished { bytesRead: 6 } +17ms
  zigbee-herdsman:zStack:unpi:parser <-- [254,1,100,1,0,100] +20s
  zigbee-herdsman:zStack:unpi:parser --- parseNext [254,1,100,1,0,100] +1ms
  zigbee-herdsman:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [] - 100 +2ms
  zigbee-herdsman:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +20s
  zigbee-herdsman:zStack:unpi:parser --- parseNext [] +3ms
  serialport/stream _read reading { start: 231, toRead: 65305 } +10ms
  serialport/binding-abstract read +16ms
  serialport/bindings/unixRead Starting read +14ms
  serialport/bindings/unixRead waiting for readable because of code: EAGAIN +2ms
  serialport/bindings/poller Polling for "readable" +21ms
  serialport/bindings/poller received "readable" +572ms
  serialport/binding-abstract read +576ms
  serialport/bindings/unixRead Starting read +574ms
  serialport/bindings/unixRead Finished read { bytesRead: 8,
  buffer:
   <Buffer fe 0e 61 02 02 00 02 06 03 90 15 34 01 02 00 00 00 00 da fe 03 61 08 00 01 55 3e fe 03 61 08 00 01 55 3e fe 06 61 08 00 04 00 08 00 00 63 fe 03 61 08 ... > } bytes +2ms
  serialport/stream binding.read finished { bytesRead: 8 } +581ms
  zigbee-herdsman:zStack:unpi:parser <-- [254,3,68,128,205,1,1,10] +585ms
  zigbee-herdsman:zStack:unpi:parser --- parseNext [254,3,68,128,205,1,1,10] +1ms
  zigbee-herdsman:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [�] - 10 +0ms
  zigbee-herdsman:zStack:znp:AREQ <-- AF - dataConfirm - {"status":205,"endpoint":1,"transid":1} +1m
  zigbee-herdsman:zStack:unpi:parser --- parseNext [] +2ms
zigbee2mqtt:error 2019-10-13T11:07:39: Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'
winston:file written true false
zigbee2mqtt:info  2019-10-13T11:07:39: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'","meta":{"friendly_name":"0x00158d0001d0f272"}}'
winston:file written true false
  serialport/stream _read reading { start: 239, toRead: 65297 } +27ms
  serialport/binding-abstract read +32ms
winston:file logged 21541 error 2019-10-13T11:07:39: Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'

winston:file logged 21834 info  2019-10-13T11:07:39: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Publish 'set' 'state' to '0x00158d0001d0f272' failed: 'Error: Data request failed with error: 'No network route' (205)'","meta":{"friendly_name":"0x00158d0001d0f272"}}'

I'll try to remove all devices and re-pair everything with latest version...

@Kryzek
Copy link
Author

Kryzek commented Oct 13, 2019

It seems I am unable to pair anything with fresh install either. I did re-programming too and I'm still unable to pair anything.

@Kryzek
Copy link
Author

Kryzek commented Oct 13, 2019

I did manage to get Airam bulb paired and it is spamming network a little bit less now.
I replaced my devices.js with lines I had in first commig (linked earlier) and I got it paired. Device seems to be spamming network still, and network does not crash anymore.

zigbee2mqtt:debug 2019-10-13T12:36:23: Received Zigbee message from '0x00158d0001cded1c', type 'attributeReport', cluster 'genLevelCtrl', data '{"currentLevel":254}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-13T12:36:23: MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":254,"linkquality":120,"state":"ON"}'
zigbee2mqtt:debug 2019-10-13T12:36:26: Received Zigbee message from '0x00158d0001cded1c', type 'attributeReport', cluster 'genLevelCtrl', data '{"currentLevel":254}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-13T12:36:26: MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":254,"linkquality":120,"state":"ON"}'
zigbee2mqtt:debug 2019-10-13T12:36:29: Received Zigbee message from '0x00158d0001cded1c', type 'attributeReport', cluster 'genLevelCtrl', data '{"currentLevel":254}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2019-10-13T12:36:29: MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":254,"linkquality":120,"state":"ON"}'
zigbee2mqtt:debug 2019-10-13T12:36:32: Received Zigbee message from '0x00158d0001cded1c', type 'attributeReport', cluster 'genLevelCtrl', data '{"currentLevel":254}' from endpoint 1 with groupID 0

@Kryzek
Copy link
Author

Kryzek commented Oct 13, 2019

I tried returning device.js lines to what they are on latest dev and yet again turning Airam bulb on after configure going through it starts spamming and network crashes.

@Kryzek
Copy link
Author

Kryzek commented Oct 13, 2019

I tried using reporting (it didn't change a thing) and turning it on afterwards. This did nothing either.

@Kryzek
Copy link
Author

Kryzek commented Oct 13, 2019

Ahha!
It seems this bulb is obeying the value of minimumReportInterval on reporting period. It seems minimumReportInterval is configured with 0 per default and device reported nonstop and network choke.

I frankensteined(tm) out this fix and my bulbs seems to be working again after re-pairing with this setup:
Koenkk/zigbee-herdsman-converters@d0f3de6

@Kryzek
Copy link
Author

Kryzek commented Oct 22, 2019

Fixed with Koenkk/zigbee-herdsman-converters#703

@Kryzek Kryzek closed this as completed Oct 22, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Koenkk @Kryzek