This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

RTOS/CC2652R: CC2652R ZNP stability problems

Part Number: CC2652R
Other Parts Discussed in Thread: CC2531, Z-STACK, SIMPLELINK-CC13X2-26X2-SDK, CC1352R, CC2530, CC1352P

Tool/software: TI-RTOS

Hi,

I'm working on the integration of the CC2652R with Zigbee2mqtt (https://github.com/koenkk/zigbee2mqtt) and encountered a stability problem:

- It works fine for +- a day

- At the moment it stops working, most of the times it doesn't respond to a command anymore (e.g. AF dataRequest). 

- Sometimes it does respond with error 0x10 (ZmemError)

- Details about the firmware I use can be found here: https://github.com/Koenkk/Z-Stack-firmware/tree/94212b39f99c921984068da8f377bdb04f7d0aeb/coordinator/Z-Stack_3.x.0 (especially firmware.patch is interesting)

- With the CC2531 on Z-Stack HA 1.2 I encountered similar problems which have been fixed by increasing the MAXMEMHEAP

  • Hi Koen,

    You are encountering a well known SIMPLELINK-CC13X2-26X2-SDK NVOCTP driver issue which is currently being addressed internally, but until it is resolved you cannot increase ZDSECMGR_TC_DEVICE_MAX or other macros expansively as this will exceed the current one-page NV memory restriction.

    e2e.ti.com/.../
    e2e.ti.com/.../


    Regards,
    Ryan
  • Hi Ryan,

    Thanks for your response, I've reduced the device tables to:

    #define MAX_RTG_SRC_ENTRIES 100
    #define SRC_RTG_EXPIRY_TIME 255
    #define NWK_MAX_DEVICE_LIST 30
    #define MAX_NEIGHBOR_ENTRIES 20
    #define MAX_RTG_ENTRIES 100

    However, I'm still experiencing stability problems. Is there a way to check if I stay within the one-page NV memory restriction?

  • Hi Koen,

    I unfortunately do not know of a straightforward solution for checking the NV memory outside of checking the contents inside of a debugger's memory window or calculating the expected allocation by hand. Does the issue persist if the default ZNP values are used and are you able to replicate the problem in a quicker time frame than a day?

    Regards,
    Ryan
  • I'm not able to replicate it in quicker than a day. 

    My attempt with the options below also crashed after +- 1 day:

    #define CONCENTRATOR_ENABLE TRUE
    #define CONCENTRATOR_DISCOVERY_TIME 60
    #define CONCENTRATOR_ROUTE_CACHE TRUE
    #define MAX_RTG_SRC_ENTRIES 40
    #define SRC_RTG_EXPIRY_TIME 255
    #define INCLUDE_REVISION_INFORMATION
    #define MT_SYS_KEY_MANAGEMENT 1
    #define SECURE 1
    #define MULTICAST_ENABLED FALSE
    #define NWK_LINK_STATUS_PERIOD 60

    I'm now going to try without CONCENTRATOR_ENABLE, will let you know soon if it stays stable.

    #define INCLUDE_REVISION_INFORMATION
    #define MT_SYS_KEY_MANAGEMENT 1
    #define SECURE 1
    #define MULTICAST_ENABLED FALSE
    #define NWK_LINK_STATUS_PERIOD 60

  • Koen Kanters said:

    I'm now going to try without CONCENTRATOR_ENABLE, will let you know soon if it stays stable.

    #define INCLUDE_REVISION_INFORMATION
    #define MT_SYS_KEY_MANAGEMENT 1
    #define SECURE 1
    #define MULTICAST_ENABLED FALSE
    #define NWK_LINK_STATUS_PERIOD 60

    Even with these settings, it's crashed (error 0x10), but now after a much longer time (3 days instead of 1 - 1.5 days).

    How can I further debug this issue?

  • Hi Koen,

    Which SIMPLELINK-CC13X2-26X2-SDK version are you evaluating and are any changes from the default ZNP project necessary to replicate the issue? You could attempt to debug the ZNP inside CCS using the ROV to further identify where the memory leak could be located.

    Regards,
    Ryan
  • Hi Ryan,

    - I'm using SIMPLELINK-CC13X2-26X2-SDK_3.10.00.53. 

    - Compilation instructions that I've used can be found here: https://github.com/Koenkk/Z-Stack-firmware/blob/dev/coordinator/Z-Stack_3.x.0/COMPILE.md

    - All my changes can be found here: https://github.com/Koenkk/Z-Stack-firmware/blob/dev/coordinator/Z-Stack_3.x.0/firmware.patch (I've applied the same changes to Z-Stack 1.2 on CC253x which ran without problems)

    EDIT: Every-time I change the firmware, I restore the network using https://sunmaysky.blogspot.com/2016/01/how-to-clone-existing-z-stack.html. Are any parameters restored which could create such issue? The backup originally comes from the firmware with very large device tables.

  • Once again, have you evaluated the ZNP out-of-box? This will help determine if the issue involves an issue with firmware.patch and the involved Z-Stack file changes.

    Edit: I would expect issues if you are copying NV into a firmware setup for which such allocations are not currently allowed.  I suppose you could also test for the issue when not restoring the network.

    Regards,
    Ryan

  • Hi Ryan,

    - I will do a test with an as default as possible ZNP

    - About the NIB. Let's image we have firmware A where e.g. CONCENTRATOR_ENABLE is set to FALSE during compilation. This would result in _NIB.nwkIsConcentrator = zgConcentratorEnable;. Now we have a new firmware B where CONCENTRATOR_ENABLE is set to TRUE. In order to update without re-pairing, we restore, among other things, the NIB. Will this coordinator then become a concentrator?

    - If this is not the case (meaning that we can only update things in the NIB WITHOUT restoring), would there be another way to let the coordinator rejoin an existing PAN (assuming that we know the network key, channel, extended pan id, etc.)?

  • Yes, the NIB is stored in NV item ZCD_NV_NIB (ID 0x21) and will not re-init so long as there are valid NV items available.

    Regards,
    Ryan
  • - I've compiled an as clean as possible firmware (with only minimal changes which are required to get it working with zigbee2mqtt).

    - It already crashed +- 8 hours after uptime, and crashed after an other 8 hours after I replugged it

    - I think it's unlikely that this is caused by the above changes.

    - When defining INCLUDE_REVISION_INFORMATION the firmware does not compile by default (need to move the sblRev out of the ifdef) (see above diff)

    - I'm going to try with a much smaller setup (CC2652R coordinator + Xiaomi end device + Xiaomi router)

  • Thanks for the update Koen, we are attempting to replicate this on our end as well.

    Ryan
  • Can you share an OTA log to see what is your device doing on your testing?

  • Do you mean a wireshark log? For what duration should I capture traffic?

  • It will be helpful if you provide a log that have frames before and after the crash, to see the kind of traffic that you have on that network.
  • Update from my side:

    - I've made a simple test setup consisting of: CC2652R coordinator, 2x Xiaomi RTCGQ11LM occupancy + illuminance sensor, 1x Xiaomi RTCGQ10LM occupancy sensor, 1x Xiaomi ZNCZ02LM power plug, 1x OSRAM AB3257001NJ plug. All devices are within 50 cm of each other (to make sure range is not an issue).

    - Complete Zigbee2mqtt log can be found here: https://www.pastefs.com/pid/117330

    - Started on 1 May

    - To check if the setup still worked, every day I toggled the power plugs a few times

    - On 6 May it failed for this first time (line 25669 = Xiaomi plug), the CC2652R responded with a aps no ack (0xB7). I've also tried to control the OSRAM plug but this gave the same error (line 25696). However, the OSRAM plug was still able to send messages to the CC2652R when I pushed the toggle button on the plug manually (line 25699).

    - On 7 May I tried to control the plugs again, this is the first time the memory errors started appearing (0x10) (line 29067)

    - All 3 occupancy sensors and both plugs are still able to send messages to the CC2652R (and to zigbee2mqtt). After the errors started appearing, I was not able to control any of the plugs.

    - Attached is a wireshark log (+- 3 min) of AFTER the crash. During this period I tried to toggle both plugs using the CC2652R, but the CC2652R didn't produce any corresponding  Zigbee message. The only messages that the CC2652R send were 2 link status message (no. 17 and 46).

    - To view the wireshark log you need the following 2 keys: 01:03:05:07:09:0B:0D:0F:00:02:04:06:08:0A:0C:0D    and    5A:69:67:42:65:65:41:6C:6C:69:61:6E:63:65:30:39 dump.pcapng.zip

  • Are you still using the changes made to afIncomingData() from your pach? you should use the AF_REGISTER MT command to register the endpoint instead of hacking this afIncomingData() function. How are you controlling the ZNP device?

    Also I noticed from your wireshark log that the link status period of the ZNP is 1 minute. Did you change the default value or the other frames are just lost from the log?
  • I'm not using those changes anymore, here you can find all the current changes: e2e.ti.com/.../2951499

    The ZNP device is controlled using zigbee-shepherd github.com/.../zigbee-shepherd

    The link status period is still 1 minute, I also found it strange that some of them didn't appear.
  • Can you provide a step by step to recreate your current setup? Which data are you processing with your gateway and how I can setup this gateway as well.

  • In order to reproduce the problem, you have to setup zigbee2mqtt (http://www.zigbee2mqtt.io/getting_started/running_zigbee2mqtt.html) (at least zigbee2mqtt 1.4 required) in combination with the following CC2652R firmware: https://github.com/Koenkk/Z-Stack-firmware/tree/master/coordinator/Z-Stack_3.x.0/bin

    Side note: I've migrated my network to Z-Stack 3.0.2 on the CC2531 which seems to stay stable (1 week uptime now).

  • Hi Koen,

    I'm not able to run the zigbee2mqtt gateway with the firmware from your repo, can you tell something from my error message?, his is the error that I'm getting:

    > zigbee2mqtt@1.4.0 start /opt/zigbee2mqtt
    > node index.js
    
      zigbee2mqtt:info 5/13/2019, 3:33:43 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-05-13.15-33-42'
      zigbee2mqtt:info 5/13/2019, 3:33:43 PM Starting zigbee2mqtt version 1.4.0 (commit #6b75465)
      zigbee2mqtt:info 5/13/2019, 3:33:43 PM Starting zigbee-shepherd
      zigbee2mqtt:info 5/13/2019, 3:33:50 PM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (Error: request timeout)
      zigbee2mqtt:info 5/13/2019, 3:34:50 PM Starting zigbee-shepherd
      zigbee2mqtt:error 5/13/2019, 3:34:57 PM Error while starting zigbee-shepherd! (Error: request timeout)
      zigbee2mqtt:error 5/13/2019, 3:34:57 PM Press the reset button on the stick (the one closest to the USB) and start again
      zigbee2mqtt:error 5/13/2019, 3:34:57 PM Failed to start
    	{"message":"request timeout","stack":"Error: request timeout\n    at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:269:22)\n    at Object.onceWrapper (events.js:277:13)\n    at CcZnp.emit (events.js:189:13)\n    at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:248:18)\n    at ontimeout (timers.js:436:11)\n    at tryOnTimeout (timers.js:300:5)\n    at listOnTimeout (timers.js:263:5)\n    at Timer.processTimers (timers.js:223:10)"}
      zigbee2mqtt:error 5/13/2019, 3:34:57 PM Exiting...
    npm ERR! code ELIFECYCLE
    npm ERR! errno 1
    npm ERR! zigbee2mqtt@1.4.0 start: `node index.js`
    npm ERR! Exit status 1
    npm ERR! 
    npm ERR! Failed at the zigbee2mqtt@1.4.0 start script.
    

  • Do you have the E revision of the board? Older revisions might cause issues

    Somebody else also had issues with this: https://github.com/Koenkk/zigbee2mqtt/issues/1429#issuecomment-491565959  https://github.com/Koenkk/zigbee2mqtt/issues/1429#issuecomment-491574095 

  • Yes I have revision E.
  • Could you provide the log when starting with DEBUG=* npm start ?

  • I hope this helps:

    > zigbee2mqtt@1.4.0 start /opt/zigbee2mqtt
    > node index.js
    
      zigbee2mqtt:info 5/14/2019, 11:17:59 AM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-05-14.11-17-59'
      serialport/bindings loading LinuxBinding +0ms
      zigbee2mqtt:debug 5/14/2019, 11:17:59 AM Using zigbee-shepherd with settings: '{"net":{"panId":6754,"extPanId":[221,221,221,221,221,221,221,221],"channelList":[11],"precfgkey":"HIDDEN"},"dbPath":"/opt/zigbee2mqtt/data/database.db","coordBackupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","sp":{"baudRate":115200,"rtscts":true}}'
      zigbee2mqtt:debug 5/14/2019, 11:17:59 AM Loaded state from file /opt/zigbee2mqtt/data/state.json
      zigbee2mqtt:debug 5/14/2019, 11:17:59 AM Saving state to file /opt/zigbee2mqtt/data/state.json
      zigbee2mqtt:info 5/14/2019, 11:17:59 AM Starting zigbee2mqtt version 1.4.0 (commit #6b75465)
      zigbee2mqtt:info 5/14/2019, 11:17:59 AM Starting zigbee-shepherd
      zigbee-shepherd:init zigbee-shepherd booting... +0ms
      cc-znp Initialize, opening serial port +0ms
      serialport/stream opening path: /dev/ttyACM0 +0ms
      serialport/binding-abstract open +0ms
      serialport/stream _read queueing _read for after open +1ms
      serialport/bindings/poller Creating poller +0ms
      serialport/stream opened path: /dev/ttyACM0 +8ms
      serialport/stream _write 1 bytes of data +1ms
      serialport/binding-abstract write 1 bytes +10ms
      serialport/stream _read reading +0ms
      serialport/binding-abstract read +0ms
      serialport/bindings/unixWrite Starting write 1 bytes offset 0 bytesToWrite 1 +0ms
      serialport/bindings/unixRead Starting read +0ms
      serialport/bindings/unixWrite write returned null 1 +4ms
      serialport/bindings/unixWrite wrote 1 bytes +0ms
      serialport/bindings/unixWrite Finished writing 1 bytes +0ms
      serialport/stream binding.write write finished +5ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +4ms
      serialport/bindings/poller Polling for "readable" +8ms
      cc-znp The serialport /dev/ttyACM0 is opened. +1s
      zigbee-shepherd:request REQ --> SYS:version +0ms
      cc-znp:SREQ --> SYS:version, {} +0ms
      serialport/stream _write 5 bytes of data +1s
      serialport/binding-abstract write 5 bytes +1s
      serialport/bindings/unixWrite Starting write 5 bytes offset 0 bytesToWrite 5 +1s
      serialport/bindings/unixWrite write returned null 5 +1ms
      serialport/bindings/unixWrite wrote 5 bytes +2ms
      serialport/bindings/unixWrite Finished writing 5 bytes +0ms
      serialport/stream binding.write write finished +6ms
      cc-znp:SRSP <-- SYS:version, __timeout__ +0ms
      zigbee-shepherd:request RSP <-- SYS:version +3s
      zigbee-shepherd:request REQ --> SYS:osalNvRead +2ms
      cc-znp:SREQ --> SYS:osalNvRead, { id: 3840, offset: 0, len: 1, value: [ 85 ] } +3s
      serialport/stream _write 8 bytes of data +3s
      serialport/binding-abstract write 8 bytes +3s
      serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +3s
      serialport/bindings/unixWrite write returned null 8 +1ms
      serialport/bindings/unixWrite wrote 8 bytes +0ms
      serialport/bindings/unixWrite Finished writing 8 bytes +0ms
      serialport/stream binding.write write finished +3ms
      cc-znp:SRSP <-- SYS:osalNvRead, __timeout__ +3s
      zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
      zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
        at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:269:22)
        at Object.onceWrapper (events.js:277:13)
        at CcZnp.emit (events.js:189:13)
        at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:248:18)
        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) +0ms
      zigbee2mqtt:info 5/14/2019, 11:18:06 AM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (Error: request timeout)
      serialport/stream #flush +3s
      serialport/binding-abstract flush +3s
      serialport/stream binding.flush finished +1ms
      serialport/stream #close +1ms
      serialport/binding-abstract close +2ms
      serialport/bindings/poller Stopping poller +7s
      serialport/bindings/poller Destroying poller +1ms
      serialport/stream binding.read error { Error: Canceled
        at Poller.emitCanceled (/opt/zigbee2mqtt/node_modules/cc-znp/node_modules/@serialport/bindings/lib/poller.js:101:17)
        at Poller.stop (/opt/zigbee2mqtt/node_modules/cc-znp/node_modules/@serialport/bindings/lib/poller.js:91:10)
        at close.then (/opt/zigbee2mqtt/node_modules/cc-znp/node_modules/@serialport/bindings/lib/linux.js:48:19) canceled: true } +1ms
      serialport/stream _read queueing _read for after open +1ms
      serialport/stream binding.close finished +60ms
      cc-znp The serialport /dev/ttyACM0 is closed. +6s
      zigbee2mqtt:info 5/14/2019, 11:19:06 AM Starting zigbee-shepherd
      zigbee-shepherd:init zigbee-shepherd booting... +1m
      cc-znp Initialize, opening serial port +60s
      serialport/stream opening path: /dev/ttyACM0 +60s
      serialport/binding-abstract open +1m
      serialport/stream _read queueing _read for after open +0ms
      serialport/bindings/poller Creating poller +1m
      serialport/stream opened path: /dev/ttyACM0 +6ms
      serialport/stream _write 1 bytes of data +7ms
      serialport/binding-abstract write 1 bytes +13ms
      serialport/stream _read reading +1ms
      serialport/binding-abstract read +1ms
      serialport/bindings/unixWrite Starting write 1 bytes offset 0 bytesToWrite 1 +1m
      serialport/bindings/unixRead Starting read +1m
      serialport/bindings/unixWrite write returned null 1 +3ms
      serialport/bindings/unixWrite wrote 1 bytes +0ms
      serialport/bindings/unixWrite Finished writing 1 bytes +0ms
      serialport/stream binding.write write finished +3ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +3ms
      serialport/bindings/poller Polling for "readable" +16ms
      cc-znp The serialport /dev/ttyACM0 is opened. +1s
      zigbee-shepherd:request REQ --> SYS:version +1m
      cc-znp:SREQ --> SYS:version, {} +1m
      serialport/stream _write 5 bytes of data +1s
      serialport/binding-abstract write 5 bytes +1s
      serialport/bindings/unixWrite Starting write 5 bytes offset 0 bytesToWrite 5 +1s
      serialport/bindings/unixWrite write returned null 5 +1ms
      serialport/bindings/unixWrite wrote 5 bytes +0ms
      serialport/bindings/unixWrite Finished writing 5 bytes +0ms
      serialport/stream binding.write write finished +1ms
      cc-znp:SRSP <-- SYS:version, __timeout__ +1m
      zigbee-shepherd:request RSP <-- SYS:version +3s
      zigbee-shepherd:request REQ --> SYS:osalNvRead +1ms
      cc-znp:SREQ --> SYS:osalNvRead, { id: 3840, offset: 0, len: 1, value: [ 85 ] } +3s
      serialport/stream _write 8 bytes of data +3s
      serialport/binding-abstract write 8 bytes +3s
      serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +3s
      serialport/bindings/unixWrite write returned null 8 +0ms
      serialport/bindings/unixWrite wrote 8 bytes +1ms
      serialport/bindings/unixWrite Finished writing 8 bytes +0ms
      serialport/stream binding.write write finished +2ms
      cc-znp:SRSP <-- SYS:osalNvRead, __timeout__ +3s
      zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
      zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
        at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:269:22)
        at Object.onceWrapper (events.js:277:13)
        at CcZnp.emit (events.js:189:13)
        at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:248:18)
        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) +1m
      zigbee2mqtt:error 5/14/2019, 11:19:13 AM Error while starting zigbee-shepherd! (Error: request timeout)
      zigbee2mqtt:error 5/14/2019, 11:19:13 AM Press the reset button on the stick (the one closest to the USB) and start again
      zigbee2mqtt:error 5/14/2019, 11:19:13 AM Failed to start
    	{"message":"request timeout","stack":"Error: request timeout\n    at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:269:22)\n    at Object.onceWrapper (events.js:277:13)\n    at CcZnp.emit (events.js:189:13)\n    at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:248:18)\n    at ontimeout (timers.js:436:11)\n    at tryOnTimeout (timers.js:300:5)\n    at listOnTimeout (timers.js:263:5)\n    at Timer.processTimers (timers.js:223:10)"}
      zigbee2mqtt:error 5/14/2019, 11:19:13 AM Exiting...
    npm ERR! code ELIFECYCLE
    npm ERR! errno 1
    npm ERR! zigbee2mqtt@1.4.0 start: `node index.js`
    npm ERR! Exit status 1
    npm ERR! 
    npm ERR! Failed at the zigbee2mqtt@1.4.0 start script.
    

  • What is the output of ls /dev and what did you specify for port in configuration.yaml?
  • I have ttyACM0 in /dev and configuration.yaml has ttyACM0 as well.
  • What is the output of ls " -l /dev/serial/by-id " ?
  • total 0
    lrwxrwxrwx 1 root root 13 may 14 11:17 usb-Texas_Instruments_XDS110__02.03.00.16__Embed_with_CMSIS-DAP_L11007PW-if00 -> ../../ttyACM0
    lrwxrwxrwx 1 root root 13 may 14 11:17 usb-Texas_Instruments_XDS110__02.03.00.16__Embed_with_CMSIS-DAP_L11007PW-if03 -> ../../ttyACM1
    

  • Could you also try with /dev/ttyAMC1 and starting as root?
  • Also, on what OS are you running zigbee2mqtt?
  • Same error with ttyACM1, however ttyACM0 is always the serial data port and ttyACM1 the debugger port. I'm using Ubuntu 19.04 on a virtual machine.
  • I removed ModemManager but the error stills the same. Which OS do you use?
  • I think the issue is with the virtualization, can you try on a native machine? It works on both macOS and Linux.
  • I will need to setup a native environment to give it a try. So give me some time to do that and I'll be back with my results.
  • Now on native ubuntu 19.04 I'm getting something different, the process stops in the "Starting zigbee-shepherd" step, I'm using everything as it comes from the repo:

    DEBUG=* npm start
    
    > zigbee2mqtt@1.4.0 start /opt/zigbee2mqtt
    > node index.js
    
      zigbee2mqtt:info 5/14/2019, 1:58:14 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-05-14.13-58-14'
      serialport/bindings loading LinuxBinding +0ms
      zigbee2mqtt:debug 5/14/2019, 1:58:14 PM Using zigbee-shepherd with settings: '{"net":{"panId":6754,"extPanId":[221,221,221,221,221,221,221,221],"channelList":[11],"precfgkey":"HIDDEN"},"dbPath":"/opt/zigbee2mqtt/data/database.db","coordBackupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","sp":{"baudRate":115200,"rtscts":true}}'
      zigbee2mqtt:debug 5/14/2019, 1:58:14 PM Loaded state from file /opt/zigbee2mqtt/data/state.json
      zigbee2mqtt:debug 5/14/2019, 1:58:14 PM Saving state to file /opt/zigbee2mqtt/data/state.json
      zigbee2mqtt:info 5/14/2019, 1:58:14 PM Starting zigbee2mqtt version 1.4.0 (commit #6b75465)
      zigbee2mqtt:info 5/14/2019, 1:58:14 PM Starting zigbee-shepherd
      zigbee-shepherd:init zigbee-shepherd booting... +0ms
      cc-znp Initialize, opening serial port +0ms
      serialport/stream opening path: /dev/ttyACM0 +0ms
      serialport/binding-abstract open +0ms
      serialport/stream _read queueing _read for after open +1ms
      serialport/bindings/poller Creating poller +0ms
      serialport/stream opened path: /dev/ttyACM0 +2ms
      serialport/stream _write 1 bytes of data +0ms
      serialport/binding-abstract write 1 bytes +3ms
      serialport/stream _read reading +1ms
      serialport/binding-abstract read +1ms
      serialport/bindings/unixWrite Starting write 1 bytes offset 0 bytesToWrite 1 +0ms
      serialport/bindings/unixRead Starting read +0ms
      serialport/bindings/unixWrite write returned null 1 +1ms
      serialport/bindings/unixWrite wrote 1 bytes +0ms
      serialport/bindings/unixWrite Finished writing 1 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms
      serialport/bindings/poller Polling for "readable" +3ms
      cc-znp The serialport /dev/ttyACM0 is opened. +1s
      zigbee-shepherd:request REQ --> SYS:version +0ms
      cc-znp:SREQ --> SYS:version, {} +0ms
      serialport/stream _write 5 bytes of data +1s
      serialport/binding-abstract write 5 bytes +1s
      serialport/bindings/unixWrite Starting write 5 bytes offset 0 bytesToWrite 5 +1s
      serialport/bindings/unixWrite write returned null 5 +0ms
      serialport/bindings/unixWrite wrote 5 bytes +0ms
      serialport/bindings/unixWrite Finished writing 5 bytes +1ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +1s
      serialport/binding-abstract read +2ms
      serialport/bindings/unixRead Starting read +1s
      serialport/bindings/unixRead Finished read 8 bytes +0ms
      serialport/stream binding.read finished +2ms
      serialport/stream _read reading +2ms
      serialport/binding-abstract read +3ms
      serialport/bindings/unixRead Starting read +3ms
      serialport/bindings/unixRead Finished read 11 bytes +0ms
      serialport/stream binding.read finished +1ms
      cc-znp { sof: 254,
      cc-znp   len: 14,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'SYS',
      cc-znp   cmd: 'version',
      cc-znp   payload:
      cc-znp    { transportrev: 2,
      cc-znp      product: 1,
      cc-znp      majorrel: 2,
      cc-znp      minorrel: 7,
      cc-znp      maintrel: 1,
      cc-znp      revision: 20190426 },
      cc-znp   fcs: 145,
      cc-znp   csum: 145 } +18ms
      serialport/stream _read reading +4ms
      serialport/binding-abstract read +5ms
      serialport/bindings/unixRead Starting read +4ms
      cc-znp:SRSP <-- SYS:version, { transportrev: 2, product: 1, majorrel: 2, minorrel: 7, maintrel: 1, revision: 20190426 } +0ms
      zigbee-shepherd:request RSP <-- SYS:version +20ms
      zigbee-shepherd:request REQ --> SYS:osalNvRead +0ms
      cc-znp:SREQ --> SYS:osalNvRead, { id: 96, offset: 0, len: 1, value: [ 85 ] } +17ms
      serialport/stream _write 8 bytes of data +2ms
      serialport/binding-abstract write 8 bytes +2ms
      serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +12ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +3ms
      serialport/bindings/poller Polling for "readable" +11ms
      serialport/bindings/unixWrite write returned null 8 +0ms
      serialport/bindings/unixWrite wrote 8 bytes +0ms
      serialport/bindings/unixWrite Finished writing 8 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +4ms
      serialport/binding-abstract read +5ms
      serialport/bindings/unixRead Starting read +4ms
      serialport/bindings/unixRead Finished read 8 bytes +0ms
      serialport/stream binding.read finished +5ms
      cc-znp { sof: 254,
      cc-znp   len: 3,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'SYS',
      cc-znp   cmd: 'osalNvRead',
      cc-znp   payload: { status: 0, len: 1, value: <Buffer 55> },
      cc-znp   fcs: 62,
      cc-znp   csum: 62 } +11ms
      serialport/stream _read reading +1ms
      serialport/binding-abstract read +2ms
      serialport/bindings/unixRead Starting read +2ms
      cc-znp:SRSP <-- SYS:osalNvRead, { status: 0, len: 1, value: <Buffer 55> } +9ms
      zigbee-shepherd:request RSP <-- SYS:osalNvRead, status: 0 +9ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms
      serialport/bindings/poller Polling for "readable" +3ms
      zigbee-shepherd:request REQ --> SYS:osalNvRead +11ms
      cc-znp:SREQ --> SYS:osalNvRead, { id: 132, len: 4, offset: 0, value: [ 0, 8, 0, 0 ] } +20ms
      serialport/stream _write 8 bytes of data +12ms
      serialport/binding-abstract write 8 bytes +13ms
      serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +19ms
      serialport/bindings/unixWrite write returned null 8 +0ms
      serialport/bindings/unixWrite wrote 8 bytes +0ms
      serialport/bindings/unixWrite Finished writing 8 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +14ms
      serialport/binding-abstract read +2ms
      serialport/bindings/unixRead Starting read +15ms
      serialport/bindings/unixRead Finished read 8 bytes +0ms
      serialport/stream binding.read finished +3ms
      serialport/stream _read reading +0ms
      serialport/binding-abstract read +1ms
      serialport/bindings/unixRead Starting read +0ms
      serialport/bindings/unixRead Finished read 3 bytes +1ms
      serialport/stream binding.read finished +1ms
      cc-znp { sof: 254,
      cc-znp   len: 6,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'SYS',
      cc-znp   cmd: 'osalNvRead',
      cc-znp   payload: { status: 0, len: 4, value: <Buffer 00 08 00 00> },
      cc-znp   fcs: 99,
      cc-znp   csum: 99 } +18ms
      serialport/stream _read reading +1ms
      serialport/binding-abstract read +3ms
      serialport/bindings/unixRead Starting read +2ms
      cc-znp:SRSP <-- SYS:osalNvRead, { status: 0, len: 4, value: <Buffer 00 08 00 00> } +19ms
      zigbee-shepherd:request RSP <-- SYS:osalNvRead, status: 0 +7ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +0ms
      serialport/bindings/poller Polling for "readable" +4ms
      zigbee-shepherd:request REQ --> SYS:osalNvRead +10ms
      cc-znp:SREQ --> SYS:osalNvRead, { id: 99, len: 1, offset: 0, value: [ 0 ] } +17ms
      serialport/stream _write 8 bytes of data +12ms
      serialport/binding-abstract write 8 bytes +12ms
      serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +18ms
      serialport/bindings/unixWrite write returned null 8 +0ms
      serialport/bindings/unixWrite wrote 8 bytes +0ms
      serialport/bindings/unixWrite Finished writing 8 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +17ms
      serialport/binding-abstract read +5ms
      serialport/bindings/unixRead Starting read +17ms
      serialport/bindings/unixRead Finished read 8 bytes +0ms
      serialport/stream binding.read finished +5ms
      cc-znp { sof: 254,
      cc-znp   len: 3,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'SYS',
      cc-znp   cmd: 'osalNvRead',
      cc-znp   payload: { status: 0, len: 1, value: <Buffer 00> },
      cc-znp   fcs: 107,
      cc-znp   csum: 107 } +20ms
      serialport/stream _read reading +2ms
      serialport/binding-abstract read +3ms
      serialport/bindings/unixRead Starting read +3ms
      cc-znp:SRSP <-- SYS:osalNvRead, { status: 0, len: 1, value: <Buffer 00> } +20ms
      zigbee-shepherd:request RSP <-- SYS:osalNvRead, status: 0 +10ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +0ms
      serialport/bindings/poller Polling for "readable" +4ms
      zigbee-shepherd:request REQ --> SYS:osalNvRead +11ms
      cc-znp:SREQ --> SYS:osalNvRead, { id: 98, len: 16, offset: 0, value: [ 1, 3, 5, 7, 9, 11, 13, 15, 0, 2, 4, 6, 8, 10, 12, 13 ] } +22ms
      serialport/stream _write 8 bytes of data +14ms
      serialport/binding-abstract write 8 bytes +13ms
      serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +21ms
      serialport/bindings/unixWrite write returned null 8 +0ms
      serialport/bindings/unixWrite wrote 8 bytes +1ms
      serialport/bindings/unixWrite Finished writing 8 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +17ms
      serialport/binding-abstract read +5ms
      serialport/bindings/unixRead Starting read +18ms
      serialport/bindings/unixRead Finished read 8 bytes +1ms
      serialport/stream binding.read finished +5ms
      serialport/stream _read reading +0ms
      serialport/binding-abstract read +1ms
      serialport/bindings/unixRead Starting read +0ms
      serialport/bindings/unixRead Finished read 15 bytes +1ms
      serialport/stream binding.read finished +1ms
      cc-znp { sof: 254,
      cc-znp   len: 18,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'SYS',
      cc-znp   cmd: 'osalNvRead',
      cc-znp   payload:
      cc-znp    { status: 0,
      cc-znp      len: 16,
      cc-znp      value: <Buffer 01 03 05 07 09 0b 0d 0f 00 02 04 06 08 0a 0c 0d> },
      cc-znp   fcs: 104,
      cc-znp   csum: 104 } +22ms
      serialport/stream _read reading +2ms
      serialport/binding-abstract read +3ms
      serialport/bindings/unixRead Starting read +2ms
      cc-znp:SRSP <-- SYS:osalNvRead, { status: 0, len: 16, value: <Buffer 01 03 05 07 09 0b 0d 0f 00 02 04 06 08 0a 0c 0d> } +22ms
      zigbee-shepherd:request RSP <-- SYS:osalNvRead, status: 0 +12ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +1ms
      serialport/bindings/poller Polling for "readable" +5ms
      zigbee-shepherd:request REQ --> UTIL:getDeviceInfo +11ms
      cc-znp:SREQ --> UTIL:getDeviceInfo, {} +22ms
      serialport/stream _write 5 bytes of data +13ms
      serialport/binding-abstract write 5 bytes +13ms
      serialport/bindings/unixWrite Starting write 5 bytes offset 0 bytesToWrite 5 +21ms
      serialport/bindings/unixWrite write returned null 5 +0ms
      serialport/bindings/unixWrite wrote 5 bytes +1ms
      serialport/bindings/unixWrite Finished writing 5 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +17ms
      serialport/binding-abstract read +5ms
      serialport/bindings/unixRead Starting read +17ms
      serialport/bindings/unixRead Finished read 8 bytes +0ms
      serialport/stream binding.read finished +4ms
      serialport/stream _read reading +1ms
      serialport/binding-abstract read +1ms
      serialport/bindings/unixRead Starting read +1ms
      serialport/bindings/unixRead Finished read 11 bytes +0ms
      serialport/stream binding.read finished +0ms
      cc-znp { sof: 254,
      cc-znp   len: 14,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'UTIL',
      cc-znp   cmd: 'getDeviceInfo',
      cc-znp   payload:
      cc-znp    { status: 0,
      cc-znp      ieeeaddr: '0x00124b0014f42265',
      cc-znp      shortaddr: 0,
      cc-znp      devicetype: 7,
      cc-znp      devicestate: 8,
      cc-znp      numassocdevices: 0,
      cc-znp      assocdeviceslist: <Buffer > },
      cc-znp   fcs: 152,
      cc-znp   csum: 152 } +24ms
      serialport/stream _read reading +5ms
      serialport/binding-abstract read +5ms
      serialport/bindings/unixRead Starting read +5ms
      cc-znp:SRSP <-- UTIL:getDeviceInfo, { status: 0, ieeeaddr: '0x00124b0014f42265', shortaddr: 0, devicetype: 7, devicestate: 8, numassocdevices: 0, assocdeviceslist: <Buffer > } +24ms
      zigbee-shepherd:request RSP <-- UTIL:getDeviceInfo, status: 0 +12ms
      zigbee-shepherd:init Start the ZNP as a coordinator... +0ms
      zigbee-shepherd:request REQ --> ZDO:startupFromApp +1ms
      cc-znp:SREQ --> ZDO:startupFromApp, { startdelay: 100 } +13ms
      serialport/stream _write 7 bytes of data +1ms
      serialport/binding-abstract write 7 bytes +1ms
      serialport/bindings/unixWrite Starting write 7 bytes offset 0 bytesToWrite 7 +12ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +2ms
      serialport/bindings/poller Polling for "readable" +8ms
      serialport/bindings/unixWrite write returned null 7 +0ms
      serialport/bindings/unixWrite wrote 7 bytes +0ms
      serialport/bindings/unixWrite Finished writing 7 bytes +0ms
      serialport/stream binding.write write finished +1ms
      serialport/bindings/poller received "readable" +2ms
      serialport/binding-abstract read +3ms
      serialport/bindings/unixRead Starting read +2ms
      serialport/bindings/unixRead Finished read 6 bytes +0ms
      serialport/stream binding.read finished +2ms
      cc-znp { sof: 254,
      cc-znp   len: 1,
      cc-znp   type: 'SRSP',
      cc-znp   subsys: 'ZDO',
      cc-znp   cmd: 'startupFromApp',
      cc-znp   payload: { status: 0 },
      cc-znp   fcs: 36,
      cc-znp   csum: 36 } +6ms
      serialport/stream _read reading +1ms
      serialport/binding-abstract read +1ms
      serialport/bindings/unixRead Starting read +1ms
      cc-znp:SRSP <-- ZDO:startupFromApp, { status: 0 } +5ms
      serialport/bindings/unixRead waiting for readable because of code: EAGAIN +0ms
      serialport/bindings/poller Polling for "readable" +2ms
    

  • Please take a look to the attached log instead. For some reason I get "Not connected to MQTT server!" error.

    log.txt

  • Did you setup a MQTT server and configured it in configuration.yaml?

  • Do you mean to run a daemon with systemctl? I was missing that part. Now I have this running and these are my outputs, I'm still having a server error so I must be missing something else:

    systemctl status zigbee2mqtt.service
    ● zigbee2mqtt.service - zigbee2mqtt
       Loaded: loaded (/etc/systemd/system/zigbee2mqtt.service; disabled; vendor pr
       Active: active (running) since Tue 2019-05-14 16:01:35 PDT; 602ms ago
     Main PID: 5500 (npm)
        Tasks: 27 (limit: 4915)
       Memory: 46.7M
       CGroup: /system.slice/zigbee2mqtt.service
               ├─5500 npm
               ├─5513 sh -c node index.js
               ├─5514 node index.js
               ├─5525 /bin/sh -c git log -1 --pretty=format:"%h,%H,%s,%f,%b,%at,%ct
               └─5530 git tag --contains HEAD
    
    may 14 16:01:35 vizio-CN15 systemd[1]: Started zigbee2mqtt.
    may 14 16:01:36 vizio-CN15 npm[5500]: > zigbee2mqtt@1.4.0 start /opt/zigbee2mqt
    may 14 16:01:36 vizio-CN15 npm[5500]: > node index.js
    may 14 16:01:36 vizio-CN15 npm[5500]:   zigbee2mqtt:info 5/14/2019, 4:01:36 PM 
    

    npm start

    > zigbee2mqtt@1.4.0 start /opt/zigbee2mqtt
    > node index.js

      zigbee2mqtt:info 5/14/2019, 4:02:46 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-05-14.16-02-46'
      zigbee2mqtt:info 5/14/2019, 4:02:46 PM Starting zigbee2mqtt version 1.4.0 (commit #6b75465)
      zigbee2mqtt:info 5/14/2019, 4:02:46 PM Starting zigbee-shepherd
      zigbee2mqtt:info 5/14/2019, 4:02:47 PM zigbee-shepherd started
      zigbee2mqtt:info 5/14/2019, 4:02:47 PM Coordinator firmware version: '20190426'
      zigbee2mqtt:info 5/14/2019, 4:02:47 PM Currently 0 devices are joined:
      zigbee2mqtt:warn 5/14/2019, 4:02:47 PM `permit_join` set to  `true` in configuration.yaml.
      zigbee2mqtt:warn 5/14/2019, 4:02:47 PM Allowing new devices to join.
      zigbee2mqtt:warn 5/14/2019, 4:02:47 PM Set `permit_join` to `false` once you joined all devices.
      zigbee2mqtt:info 5/14/2019, 4:02:47 PM Zigbee: allowing new devices to join.
      zigbee2mqtt:info 5/14/2019, 4:02:47 PM Connecting to MQTT server at mqtt://localhost
      zigbee2mqtt:info 5/14/2019, 4:02:47 PM zigbee-shepherd ready
      zigbee2mqtt:error 5/14/2019, 4:02:57 PM Not connected to MQTT server!

  • Is required to use something like "Eclipse Mosquitto"?, if that's the case I wold appreciate if you provide an step by step setup in order to have an environment as close as possible to the one you have, otherwise I'll not be able to debug the ZNP properly.

  • Now I'm running the "zigbee-shepherd" and "mosquitto" at the same time and now the MQTT server is running. I still need you to provide the setup of the environment to validate what I have and also your test setup for the zigbee network, lets say the binds and groups that you are using.

    sudo npm start
    
    > zigbee2mqtt@1.4.0 start /opt/zigbee2mqtt
    > node index.js
    
      zigbee2mqtt:info 5/14/2019, 5:36:09 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-05-14.17-36-09'
      zigbee2mqtt:info 5/14/2019, 5:36:10 PM Starting zigbee2mqtt version 1.4.0 (commit #6b75465)
      zigbee2mqtt:info 5/14/2019, 5:36:10 PM Starting zigbee-shepherd
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM zigbee-shepherd started
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM Coordinator firmware version: '20190426'
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM Currently 0 devices are joined:
      zigbee2mqtt:warn 5/14/2019, 5:36:12 PM `permit_join` set to  `true` in configuration.yaml.
      zigbee2mqtt:warn 5/14/2019, 5:36:12 PM Allowing new devices to join.
      zigbee2mqtt:warn 5/14/2019, 5:36:12 PM Set `permit_join` to `false` once you joined all devices.
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM Zigbee: allowing new devices to join.
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM Connecting to MQTT server at mqtt://localhost
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM zigbee-shepherd ready
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM Connected to MQTT server
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
      zigbee2mqtt:info 5/14/2019, 5:36:12 PM MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.4.0","commit":"6b75465","coordinator":20190426,"log_level":"info","permit_join":true}'
    

  • Great!

    You can find details about my test setup here: http://e2e.ti.com/support/wireless-connectivity/zigbee-and-thread/f/158/p/794106/2957256#2957256 

    However note that you probably don't need the exact same setup to reproduce it. I guess you will be able to reproduce it by just pairing a few sensors and bulbs or switches, the more devices you pair, the faster it seems to crash. You don't have to setup any groups or binds manually.

  • Any additional configuration or you just made the devices to join?
  • Can you provide the changes made to the CC2652 ZNP firmware? from my log is clear that the link status command is sent over 1 minute period instead of 15 seconds. The link status period must be 15 seconds or lower for a zigbee compliant device.

    Are you aware of this change in your firmware or is something on zigbee2mqtt service doing this?
  • - No additional configuration is needed, just join the devices

    - The firmware I provided you indeed contains these changes

    - I've created a new firmware without these changes: github.com/.../CC2652R_20190515.zip
    - All changes to this firmware can be found here: github.com/.../firmware.patch (these are the minimal changes needed in order to get it working with zigbee2mqtt)
  • This image has the link status period as expected. Please try again with this image to see if you get the issue again, I'll setup a test as well.
  • I've already tried that and it crashed (never published that firmware on github). This was the attempt: e2e.ti.com/.../2951499
  • Thanks for the advice. Then I'll try to reproduce the issue with this image.
  • Can you help me to understand how to setup a bind. I'm looking to www.zigbee2mqtt.io/.../binding.html.