Zigbee CLI communication failure

[DaKa]

Hello,

I am able to use the Zigbee CLI Agent and send some commands. I am using the zb-cli-wrapper python package to send commands from python. I wrote an application that configures the module as a zigbee coordinator. If it is already configured as such, that means if the zigbee stack is already running, I just connect the cli with bdb start command (so it will not create a new network). Then, when nodes join the network, I retrieve some information using simple descriptor command. Once I have all the informations about the network, I want to be able to control and monitor the nodes.

But for some reason that I don't understand, after sending some commands to the CLI, the communication stops working. I can not communicate with the CLI until I reset the module. What could be the issue? Do you think that I am sending commands too fast? Because when I send commands manually using Minicom, it never crashes or hangs.

Best regards,

Damien

[Marjeris Romero]

Hi,

Do you think that I am sending commands too fast?

I don't think this should be a problem.

What SDK version are you using? Can you post the python script you are using?

[DaKa]

Hi,

I am using the nRF5 SDK Thread and Zigbee v4.0 and zb-cli-wrapper 3.0 (that I modified because it is not complete).
The python script that uses zb-cli-wrapper is a component of a quite big event based application that implements different protocols. I don't think posting it here will help since it is quite big and maybe complicated to understand if you don't know how the application is working.
But what my component is doing is basically:
- Create a network by configuring the zigbee module as coordinator or connect to the CLI if the Zigbee Stack is already running (bdb start).
- Get all the information about the coordinator (panID, ieee, nwk, channel...)
- Get lqi entries (zdo mgmt_lqi) to get the nodes in the network.
- Create node objects for each lqi entry with their infos (nwk, ieee, ...)
- Create endpoint objects for each active endpoint of a node. (zdo active_ep)
- Create cluster objects for each cluster supported by an endpoint. (zdo simple_desc)
- Go through the network to check the device types of the nodes in the network. For example if a thermostat cluster is found, I create an entity that will then use zcl to send commands with zcl cmd...
- Same with attribute reading...

Creating the network tree containing all these objects works good. But then when I try to send commands, it has strange behaviors sometimes. Also, I use asynchronous programming. I probably do something wrong that makes the CLI on the module side to crash, because sometimes it just doesn't reply until I reset the module.

[Marjeris Romero]

Hi,

What kind of "strange behaviors" does the coordinator have? Have you check with a sniffer trace to see that you are able to send the ZCL commands?
Have you seen the readme.md file inside the wrapper folder for documentation on how to send generic commands?
I don't know if I have any more ideas on what could be failing without having more information. Perhaps you can try to strip the python script of everything that doesn't involve the communication with the CLI module and see if the problem persists or send me the modified script?

Best regards,

Marjeris

[DaKa]

Hi,

I don't have a sniffer unfortunately. 
Following are the logs to see the "strange behaviors"

raw log from the newline handler in zb-cli-wrapper:

07:53:58.039 send: b'log enable info app\r\n'
07:53:58.131 rcvd: b'log enable info app\r\n'
07:53:59.057 send: b'log enable info zigbee.report\r\n'
07:53:59.139 rcvd: b'\x1b[1;32m> \x1b[1;37mlog enable info zigbee.report\r\n'
07:54:00.088 send: b'bdb channel 007FF800\r\n'
07:54:00.147 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb channel 007FF800\r\n'
07:54:00.148 rcvd: b'\x1b[1;31mError: Stack already started\r\r\n'
07:54:00.163 send: b'bdb start\r\n'
07:54:00.243 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mbdb start\r\n'
07:54:00.243 rcvd: b'Done\r\r\n'
07:54:00.253 send: b'zdo short\r\n'
07:54:00.339 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo short\r\n'
07:54:00.340 rcvd: b'0000\r\r\n'
07:54:00.342 rcvd: b'Done\r\r\n'
07:54:00.359 send: b'bdb legacy enable\r\n'
07:54:00.435 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb legacy enable\r\n'
07:54:00.455 rcvd: b'Done\r\r\n'
07:54:00.468 send: b'bdb role \r\n'
07:54:00.547 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb role \r\n'
07:54:00.548 rcvd: b'zc\r\r\n'
07:54:00.548 rcvd: b'Done\r\r\n'
07:54:00.558 send: b'bdb channel\r\n'
07:54:00.643 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb channel\r\n'
07:54:00.644 rcvd: b'Primary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:00.660 rcvd: b'Secondary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:00.661 rcvd: b'Done\r\r\n'
07:54:00.676 send: b'bdb panid \r\n'
07:54:00.723 rcvd: b'\x1b[1;32m> \x1b[1;37m\x1b[2D\x1b[J\x1b[0m<info> app: Joined network successfully (Extended PAN ID: f4ce365c7c69c2cc, PAN ID: 0xCDA5)\x1b[0m\r\r\n'
07:54:00.739 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb panid \r\n'
07:54:00.740 rcvd: b'CDA5\r\r\n'
07:54:00.740 rcvd: b'Done\r\r\n'
07:54:00.749 send: b'bdb extpanid\r\n'
07:54:00.851 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb extpanid\r\n'
07:54:00.852 rcvd: b'f4ce365c7c69c2cc\r\r\n'
07:54:00.853 rcvd: b'Done\r\r\n'
07:54:00.864 send: b'zdo eui64\r\n'
07:54:00.947 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo eui64\r\n'
07:54:00.948 rcvd: b'f4ce365c7c69c2cc\r\r\n'
07:54:00.949 rcvd: b'Done\r\r\n'
07:54:00.964 send: b'zdo short\r\n'
07:54:01.043 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo short\r\n'
07:54:01.044 rcvd: b'0000\r\r\n'
07:54:01.045 rcvd: b'Done\r\r\n'
07:54:01.069 send: b'zdo mgmt_lqi 0000\r\n'
07:54:01.155 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo mgmt_lqi 0000\r\n'
07:54:01.156 rcvd: b'\x1b[1;32m> \x1b[1;37m\r\r\n'
07:54:01.157 rcvd: b'[idx] ext_pan_id       ext_addr         short_addr flags permit_join depth lqi\r\r\n'
07:54:01.171 rcvd: b'[  0] f4ce365c7c69c2cc 90fd9ffffe1f6e3a 0x547F     0x95  0           1     108\r\r\n'
07:54:01.172 rcvd: b'\r\r\n'
07:54:01.173 rcvd: b'ZDO request 8 complete\r\r\n'
07:54:01.173 rcvd: b'\r\r\n'
07:54:01.174 rcvd: b'Done\r\r\n'
07:54:01.187 send: b'zdo active_ep 0x547f\r\n'
07:54:01.251 rcvd: b'zdo active_ep 0x547f\r\n'
07:54:01.298 rcvd: b'\x1b[1;32m> \x1b[1;37m\r\r\n'
07:54:01.300 rcvd: b'src_addr=547F ep=1 \r\r\n'
07:54:01.302 rcvd: b'Done\r\r\n'
07:54:01.316 send: b'zdo simple_desc_req 0x547f 1\r\n'
07:54:01.347 rcvd: b'zdo simple_desc_req 0x547f 1\r\n'
07:54:01.411 rcvd: b'\x1b[1;32m> \x1b[1;37m\r\r\n'
07:54:01.428 rcvd: b'src_addr=0x547F ep=1 profile_id=0xC05E app_dev_id=0x100 app_dev_ver=0x2 in_clusters=0x0000,0x0003,0x0004,0x0005,0x0006,0x0008,0x0B05,0x1000 out_clusters=0x0005,0x0019,0x0020,0x1000 \r\r\n'
07:54:01.429 rcvd: b'Done\r\r\n'
07:54:01.435 send: b'zdo bind on 90FD9FFFFE1F6E3A 1 F4CE365C7C69C2CC 64 8 547F\r\n'
07:54:01.459 rcvd: b'zdo bind on 90FD9FFFFE1FQable info zigbee.report\r\n'
07:54:01.460 rcvd: b'\x1b[1;31mError: Incorrect number of arguments\r\r\n'
07:54:01.461 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mbdb channel 007FF800\r\n'
07:54:01.463 rcvd: b'\x1b[1;31mError: Stack already started\r\r\n'
07:54:01.464 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mbdb start\r\n'
07:54:01.464 rcvd: b'Done\r\r\n'
07:54:01.476 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo short\r\n'
07:54:01.477 rcvd: b'0000\r\r\n'
07:54:01.478 rcvd: b'Done\r\r\n'
07:54:01.479 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb legacy enable\r\n'
07:54:01.480 rcvd: b'Done\r\r\n'
07:54:01.481 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb rol$\r\n'
07:54:01.484 rcvd: b'\x1b[1;31mPlease specify a subcommand.\r\n'
07:54:01.487 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mbdb channel\r\n'
07:54:01.494 rcvd: b'Primary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:01.495 rcvd: b'Secondary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:01.496 rcvd: b'Done\r\r\n'
07:54:01.498 rcvd: b'\x1b[1;32m> \x1b[1;37mbdb panTd \r\n'
07:54:01.499 rcvd: b'\x1b[1;31mPlease specify a subcommand.\r\n'
07:54:01.507 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mbdb extpanid\r\n'
07:54:01.507 rcvd: b'f4ce365c7c69c2cc\r\r\n'
07:54:01.508 rcvd: b'Done\r\r\n'
07:54:01.509 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo eS64\r\n'
07:54:01.509 rcvd: b'\x1b[1;31mPlease specify a subcommand.\r\n'
07:54:01.512 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mzdo short\r\n'
07:54:01.513 rcvd: b'0000\r\r\n'
07:54:01.513 rcvd: b'Done\r\r\n'
07:54:01.523 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo mgm_lqi 0000\r\n'
07:54:01.524 rcvd: b'\x1b[1;31mPlease specify a subcommand.\r\n'
07:54:01.524 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mzdo active_e 0x547f\r\n'
07:54:01.527 rcvd: b'\x1b[1;31mPlease specify a subcommand.\r\n'
07:54:01.538 rcvd: b'\x1b[1;37m\x1b[1;32m> \x1b[1;37mzdo simple_desc_req 0x547f 1\r\n'
07:54:01.587 rcvd: b'\x1b[1;32m> \x1b[1;37mzdo bind on 90FD9FFFFE1FQable in\r\r\n'
07:54:01.604 rcvd: b'src_addr=0x547F ep=1 profile_id=0xC05E app_dev_id=0x100 app_dev_ver=0x2 in_clusters=0x0000,0x0003,0x0004,0x0005,0x0006,0x0008,0x0B05,0x1000 out_clusters=0x0005,0x0019,0x0020,0x1000 \r\r\n'
07:54:01.605 rcvd: b'Done\r\r\n'
07:54:01.940 rcvd: b'\x1b[34D\x1b[J\x1b[0m<info> app: Joined network successfully (Extended PAN ID: f4ce365c7c69c2cc, PAN ID: 0xCDA5)\x1b[0m\r\r\n'

same log but without useless stuff:

07:53:58.039 send: b'log enable info app\r\n'
07:53:58.131 rcvd: b'log enable info app\r\n'
07:53:59.057 send: b'log enable info zigbee.report\r\n'
07:53:59.139 rcvd: b'log enable info zigbee.report\r\n'
07:54:00.088 send: b'bdb channel 007FF800\r\n'
07:54:00.147 rcvd: b'bdb channel 007FF800\r\n'
07:54:00.148 rcvd: b'Error: Stack already started\r\r\n'
07:54:00.163 send: b'bdb start\r\n'
07:54:00.243 rcvd: b'bdb start\r\n'
07:54:00.243 rcvd: b'Done\r\r\n'
07:54:00.253 send: b'zdo short\r\n'
07:54:00.339 rcvd: b'zdo short\r\n'
07:54:00.340 rcvd: b'0000\r\r\n'
07:54:00.342 rcvd: b'Done\r\r\n'
07:54:00.359 send: b'bdb legacy enable\r\n'
07:54:00.435 rcvd: b'bdb legacy enable\r\n'
07:54:00.455 rcvd: b'Done\r\r\n'
07:54:00.468 send: b'bdb role \r\n'
07:54:00.547 rcvd: b'bdb role \r\n'
07:54:00.548 rcvd: b'zc\r\r\n'
07:54:00.548 rcvd: b'Done\r\r\n'
07:54:00.558 send: b'bdb channel\r\n'
07:54:00.643 rcvd: b'bdb channel\r\n'
07:54:00.644 rcvd: b'Primary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:00.660 rcvd: b'Secondary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:00.661 rcvd: b'Done\r\r\n'
07:54:00.676 send: b'bdb panid \r\n'
07:54:00.723 rcvd: b'<info> app: Joined network successfully (Extended PAN ID: f4ce365c7c69c2cc, PAN ID: 0xCDA5)\x1b[0m\r\r\n'
07:54:00.739 rcvd: b'bdb panid \r\n'
07:54:00.740 rcvd: b'CDA5\r\r\n'
07:54:00.740 rcvd: b'Done\r\r\n'
07:54:00.749 send: b'bdb extpanid\r\n'
07:54:00.851 rcvd: b'bdb extpanid\r\n'
07:54:00.852 rcvd: b'f4ce365c7c69c2cc\r\r\n'
07:54:00.853 rcvd: b'Done\r\r\n'
07:54:00.864 send: b'zdo eui64\r\n'
07:54:00.947 rcvd: b'zdo eui64\r\n'
07:54:00.948 rcvd: b'f4ce365c7c69c2cc\r\r\n'
07:54:00.949 rcvd: b'Done\r\r\n'
07:54:00.964 send: b'zdo short\r\n'
07:54:01.043 rcvd: b'zdo short\r\n'
07:54:01.044 rcvd: b'0000\r\r\n'
07:54:01.045 rcvd: b'Done\r\r\n'
07:54:01.069 send: b'zdo mgmt_lqi 0000\r\n'
07:54:01.155 rcvd: b'zdo mgmt_lqi 0000\r\n'
07:54:01.156 rcvd: b'\r\r\n'
07:54:01.157 rcvd: b'[idx] ext_pan_id       ext_addr         short_addr flags permit_join depth lqi\r\r\n'
07:54:01.171 rcvd: b'[  0] f4ce365c7c69c2cc 90fd9ffffe1f6e3a 0x547F     0x95  0           1     108\r\r\n'
07:54:01.172 rcvd: b'\r\r\n'
07:54:01.173 rcvd: b'ZDO request 8 complete\r\r\n'
07:54:01.173 rcvd: b'\r\r\n'
07:54:01.174 rcvd: b'Done\r\r\n'
07:54:01.187 send: b'zdo active_ep 0x547f\r\n'
07:54:01.251 rcvd: b'zdo active_ep 0x547f\r\n'
07:54:01.298 rcvd: b'\r\r\n'
07:54:01.300 rcvd: b'src_addr=547F ep=1 \r\r\n'
07:54:01.302 rcvd: b'Done\r\r\n'
07:54:01.316 send: b'zdo simple_desc_req 0x547f 1\r\n'
07:54:01.347 rcvd: b'zdo simple_desc_req 0x547f 1\r\n'
07:54:01.411 rcvd: b'\r\r\n'
07:54:01.428 rcvd: b'src_addr=0x547F ep=1 profile_id=0xC05E app_dev_id=0x100 app_dev_ver=0x2 in_clusters=0x0000,0x0003,0x0004,0x0005,0x0006,0x0008,0x0B05,0x1000 out_clusters=0x0005,0x0019,0x0020,0x1000 \r\r\n'
07:54:01.429 rcvd: b'Done\r\r\n'
07:54:01.435 send: b'zdo bind on 90FD9FFFFE1F6E3A 1 F4CE365C7C69C2CC 64 8 547F\r\n'
07:54:01.459 rcvd: b'zdo bind on 90FD9FFFFE1FQable info zigbee.report\r\n'
07:54:01.460 rcvd: b'Error: Incorrect number of arguments\r\r\n'
07:54:01.461 rcvd: b'bdb channel 007FF800\r\n'
07:54:01.463 rcvd: b'Error: Stack already started\r\r\n'
07:54:01.464 rcvd: b'bdb start\r\n'
07:54:01.464 rcvd: b'Done\r\r\n'
07:54:01.476 rcvd: b'zdo short\r\n'
07:54:01.477 rcvd: b'0000\r\r\n'
07:54:01.478 rcvd: b'Done\r\r\n'
07:54:01.479 rcvd: b'bdb legacy enable\r\n'
07:54:01.480 rcvd: b'Done\r\r\n'
07:54:01.481 rcvd: b'bdb rol$\r\n'
07:54:01.484 rcvd: b'Please specify a subcommand.\r\n'
07:54:01.487 rcvd: b'bdb channel\r\n'
07:54:01.494 rcvd: b'Primary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:01.495 rcvd: b'Secondary channel(s): 11 12 13 14 15 16 17 18 19 20 21 22\r\r\n'
07:54:01.496 rcvd: b'Done\r\r\n'
07:54:01.498 rcvd: b'bdb panTd \r\n'
07:54:01.499 rcvd: b'Please specify a subcommand.\r\n'
07:54:01.507 rcvd: b'bdb extpanid\r\n'
07:54:01.507 rcvd: b'f4ce365c7c69c2cc\r\r\n'
07:54:01.508 rcvd: b'Done\r\r\n'
07:54:01.509 rcvd: b'zdo eS64\r\n'
07:54:01.509 rcvd: b'Please specify a subcommand.\r\n'
07:54:01.512 rcvd: b'zdo short\r\n'
07:54:01.513 rcvd: b'0000\r\r\n'
07:54:01.513 rcvd: b'Done\r\r\n'
07:54:01.523 rcvd: b'zdo mgm_lqi 0000\r\n'
07:54:01.524 rcvd: b'Please specify a subcommand.\r\n'
07:54:01.524 rcvd: b'zdo active_e 0x547f\r\n'
07:54:01.527 rcvd: b'Please specify a subcommand.\r\n'
07:54:01.538 rcvd: b'zdo simple_desc_req 0x547f 1\r\n'
07:54:01.587 rcvd: b'zdo bind on 90FD9FFFFE1FQable in\r\r\n'
07:54:01.604 rcvd: b'src_addr=0x547F ep=1 profile_id=0xC05E app_dev_id=0x100 app_dev_ver=0x2 in_clusters=0x0000,0x0003,0x0004,0x0005,0x0006,0x0008,0x0B05,0x1000 out_clusters=0x0005,0x0019,0x0020,0x1000 \r\r\n'
07:54:01.605 rcvd: b'Done\r\r\n'
07:54:01.940 rcvd: b'<info> app: Joined network successfully (Extended PAN ID: f4ce365c7c69c2cc, PAN ID: 0xCDA5)\x1b[0m\r\r\n'

We can clearly see that something goes wrong... from the timestamp "07:54:01.435" it goes wild after sending the bind command. And that is not the only example, it also happened for other commands like an attribute read command. So basically, when I send a valid command, the CLI sometimes complains that I sent something wrong even if my command was correct. It looks like it is mixing with commands that I sent before. Do you have any idea what is going on?

Also, I struggle to connect end devices because of channels I guess. But that is another topic, so I think I might create a new ticket for that later...

Damien

[DaKa]

Hi,

I still struggle to find the issue. I am not sure but maybe something goes wrong with threading. The memory is locked by the cli device thread when it handles a new line. But when sending a command using the write methods, the memory is never locked. Could that be that because it is not locked, it mixes stuff and sends a wrong command? I am not in ease with threading so... it is a bit hard for me to understand exactly how it works.

BR,
Damien