Zigate receive NACK on everything

[ronaldbro]

Hi,

I restarted my pi today and now I can't get zigate to work anymore. Admin console says it lost almost everything and when I send a command I get 'Received NACK from ...'
I have firmware 3.1c and the last stable of zigate.

I also tried rejoining devices and that works fine but they don't react to any commands. Also did a soft reset of the devices.

Any suggestions?

Regards and thanks Ronald

[ronaldbro]

I tried the latest beta and the result is the same. Also tried the stable version of last week, but it also fails.

All my Xioami sensors which are connected to the zigate without a router in between work fine, but all Trandfri's, Gledopto's and a Xiaomi power plug keep sending NACK and are in the lost devices list of the portal.

for example:
2020-02-17 10:58:03.003 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 5 (80e0) clusterId: 0006
2020-02-17 10:58:03.117 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 1 (d26e) clusterId: 0006
2020-02-17 10:58:04.532 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 4 (27af) clusterId: 0006
2020-02-17 10:58:16.649 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 5 (80e0) clusterId: 0300
2020-02-17 10:58:25.729 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 4 (27af) clusterId: 0300

I also see this in the logs:
2020-02-17 08:30:01.034 Error: (Zigate) 'onCommand' failed 'ValueError':'not enough values to unpack (expected 3, got 2)'.
2020-02-17 08:30:01.035 Error: (Zigate) ----> Line 862 in '/home/pi/domoticz/plugins/Domoticz-Zigate/plugin.py', function onCommand
2020-02-17 08:30:01.035 Error: (Zigate) ----> Line 524 in '/home/pi/domoticz/plugins/Domoticz-Zigate/plugin.py', function onCommand
2020-02-17 08:30:01.035 Error: (Zigate) ----> Line 1209 in '/home/pi/domoticz/plugins/Domoticz-Zigate/Classes/GroupMgt.py', function processCommand
2020-02-17 08:30:01.035 Error: (Zigate) ----> Line 1052 in '/home/pi/domoticz/plugins/Domoticz-Zigate/Classes/GroupMgt.py', function _updateDeviceListAttribute
2020-02-17 08:30:01.042 Error: (Zigate) 'onCommand' failed 'ValueError':'not enough values to unpack (expected 3, got 2)'.
2020-02-17 08:30:01.042 Error: (Zigate) ----> Line 862 in '/home/pi/domoticz/plugins/Domoticz-Zigat e/plugin.py', function onCommand
2020-02-17 08:30:01.042 Error: (Zigate) ----> Line 524 in '/home/pi/domoticz/plugins/Domoticz-Zigate/plugin.py', function onCommand
2020-02-17 08:30:01.042 Error: (Zigate) ----> Line 1193 in '/home/pi/domoticz/plugins/Domoticz-Zigate/Classes/GroupMgt.py', function processCommand
2020-02-17 08:30:01.042 Error: (Zigate) ----> Line 1052 in '/home/pi/domoticz/plugins/Domoticz-Zigate/Classes/GroupMgt.py', function _updateDeviceListAttribute

[pipiche]

If you have NACK this mean that the device is not reachable any more. So you have to repair them.

For the error seens in the Logs, I'll going to fix it , but as nothing to do with the NACK

[ronaldbro]

Hi Pipiche,

The devices are reachable, some are within 1 meter of the ZiGate. I can also rejoin them and this never fails. I’m sure these are false NACK’s. I got the feeling it’s a bug in the 3.1c firmware.

Which log options can I best use to examine this?

[pipiche]

1/ Please switch to the beta branch if not yet done,
2/ make sure you are on the latest version ( git pull when on beta branch)
3/ Please do provide an export of Web Admin -> Tools -> Device List raw (json)

[ronaldbro]

Hi Pipiche,

See the export attached. (Had to change the file extention to txt to be able to upload)

Regards Ronald

[pipiche]

Thanks. Could you let me know if your LED Strip "Woonkamer LED strip" has RGB and WW colours ? or only RGB ?

[pipiche]

On which Channel is the Zigate ? You can check that from the log when the plugin start, or also from the Web Admin -> Tools Zigate Infos ?
On which Channel is the Wifi 2.4GhZ ?

[ronaldbro]

Hi Pipiche,

The LED stip is indeed RGBWW, it's a project we didn't finish but it's working for my pupose. If you want we can continue working on it when I get it responding again.
See https://www.domoticz.com/forum/viewtopi ... to#p231238

Zigate is on channel 26 and wifi on channel 1. It worked flawless with this for some time.

[ronaldbro]

I also don't have any CRC errors.

[waltervl]

I also see NACK also appearing sometimes since firmware 3.1c.
In my case it is one Ikea bulb (member of a group of 3 similar bulbs) and an Ikea led dimmer. I have to switch the power of the devices to have them connect again. The bulb seems to be an incident, the led dinner has done this already 2 times. I never had these issues before.

[abroeders]

I have the same issue with just one tradfri bulb, just after i restarted the zigate plugin when upgraded from 4.7.1 to 4.7.3 stable.
WiFi channel is 13 and zigbee 11, so they are as far apart as they can.
Already tried to pair again, repairing works, but controlling the bulb gives NACK.

2020-02-17 19:20:50.436 (Zigate) UpdateDevice - (Light Garage inside 1) 1:13
2020-02-17 19:20:56.975 (Zigate) Receive NACK from Garage inside 1 (bd83)
2020-02-17 19:21:00.146 (Zigate) Receive NACK from Garage inside 1 (bd83)
2020-02-17 19:21:00.197 (Zigate) Receive NACK from Garage inside 1 (bd83)

Export devices.json raw:

export.json.txt

devices.json

(264.85 KiB) Downloaded 21 times

[pipiche]

The NACK/ACK was introduced with firmware 3.1c, so it is indeed correct that it is new. However it reports communication issues which were not detected before (because not implemented).

Be carreful as if you change the Zigbee/Zigate channel, you will have to repaire the devices. In principle never change the Zigbee/Zigate channel

[ronaldbro]

Is there any way to log why a NACK is send? I'm sure it is a bug and I'm afraid it's in the firmware. It worked fine and now nothing works anymore.

[ronaldbro]

To be 100% sure it isn't WiFi related I disabled then 2.4Ghz radio on the access point. But it did not matter, still NACK's except for the Xiaomi sensors.
So we can exclude WiFi interference.

Is it possible to downgrade to 3.1a firmware?

[pipiche]

As said moving to 3.1a will of course remove those messages as they are 3.1c related , but won’t solve the issue.

Could you confirm when a device get a NACK you have the domoticz widget in timeout. However if you switch on or off from domoticz it works or not ?

Could you let me know if Polling is enable ?


Envoyé de mon iPhone en utilisant Tapatalk

[ronaldbro]

All the widgets are in timeout (red header), only the group widgets are not. Switching on/off doesn't work. Although I have a script changing color temp every 5 minutes and those commands seem to get through sometimes, but I don't think every time.

Polling is disabled and forcePollingAfterAction is enabled (already tried disabling it). Also tried disabling ping and I disabled OTA.

If you want I can setup a Webex meeting and share my screen so you can have a look yourself.

[pipiche]

All the widgets are in timeout (red header), only the group widgets are not. Switching on/off doesn't work. Although I have a script changing color temp every 5 minutes and those commands seem to get through sometimes, but I don't think every time.

Polling is disabled and forcePollingAfterAction is enabled (already tried disabling it). Also tried disabling ping and I disabled OTA.

If you want I can setup a Webex meeting and share my screen so you can have a look yourself.

Ok, sif the device cannot be controlled anymore ( On/Off doesn't work), this means that the NACK stuff is correct and the device is disconnected from the Zigate.

[ronaldbro]

Just noticed you added a setting to disble ACKNACK, switched it off but I still receive NACK. (But maybe I should have wait until you gave some directions )

I added some extra log. Hope it is usefull.
This is what I get when trying to switch on a Tradfri bulb.

2020-02-18 09:43:40.041 (Zigate) mgtCommand called for Devices[4].Name: Woonkamer: Spot uitbouw 1 SwitchType: 7 Command: On Level: 30 Color:
2020-02-18 09:43:40.041 (Zigate) mgtCommand - NWKID = d26e
2020-02-18 09:43:40.042 (Zigate) mgtCommand : found Device : 416 in Ep 01 ColorControlWW
2020-02-18 09:43:40.042 (Zigate) mgtCommand - List of TypeName : ['ColorControlWW']
2020-02-18 09:43:40.042 (Zigate) mgtCommand - DeviceType : ColorControlWW
2020-02-18 09:43:40.042 (Zigate) mgtCommand : Found Ep 01 for Device 416 Cluster 0300
2020-02-18 09:43:40.042 (Zigate) EPout = 01
2020-02-18 09:43:40.042 (Zigate) mgtCommand : On for Device: d26e EPout: 01 Unit: 4 DeviceType: ColorControlWW
2020-02-18 09:43:40.043 (Zigate) =====> sendZigateCmd - 0092 02d26e010101 Queue Length: 0
2020-02-18 09:43:40.044 (Zigate) UpdateDevice - (Woonkamer: Spot uitbouw 1) 1:On
2020-02-18 09:43:40.184 (Zigate) ReadAttributeRequest_0000 - Key: d26e , Scope: True
2020-02-18 09:43:40.184 (Zigate) --> Full scope
2020-02-18 09:43:40.184 (Zigate) ---- retreive_ListOfAttributesByCluster: List of Attributes for cluster 0000 : 0x0000 0x0001 0x0002 0x0003 0x0004 0x0005 0x0007 0x000a 0x4000
2020-02-18 09:43:40.185 (Zigate) Request Basic via Read Attribute request d26e/01 [0, 1, 2, 3, 4, 5, 7, 10, 16384]
2020-02-18 09:43:40.185 (Zigate) -- normalizedReadAttrReq ---- addr =d26e Cluster = 0000 Attributes = 0x0000, 0x0001, 0x0002
2020-02-18 09:43:40.185 (Zigate) =====> sendZigateCmd - 0100 02d26e010100000000000003000000010002 Queue Length: 0
2020-02-18 09:43:40.186 (Zigate) -- normalizedReadAttrReq ---- addr =d26e Cluster = 0000 Attributes = 0x0003, 0x0004, 0x0005
2020-02-18 09:43:40.186 (Zigate) =====> sendZigateCmd - 0100 02d26e010100000000000003000300040005 Queue Length: 1
2020-02-18 09:43:40.186 (Zigate) -- normalizedReadAttrReq ---- addr =d26e Cluster = 0000 Attributes = 0x0007, 0x000a, 0x4000
2020-02-18 09:43:40.186 (Zigate) =====> sendZigateCmd - 0100 02d26e0101000000000000030007000a4000 Queue Length: 2
2020-02-18 09:43:40.186 (Zigate) ReadAttributeRequest_0001 - Key: d26e
2020-02-18 09:43:40.186 (Zigate) ---- retreive_ListOfAttributesByCluster: List of Attributes for cluster 0001 :
2020-02-18 09:43:40.186 (Zigate) ReadAttributeRequest_0006 - Key: d26e
2020-02-18 09:43:40.187 (Zigate) ---- retreive_ListOfAttributesByCluster: List of Attributes for cluster 0006 : 0x0000 0x4000 0x4001 0x4002 0x4003
2020-02-18 09:43:40.187 (Zigate) Request OnOff status via Read Attribute request: d26e EPout = 01
2020-02-18 09:43:40.187 (Zigate) -- normalizedReadAttrReq ---- addr =d26e Cluster = 0006 Attributes = 0x0000, 0x4000
2020-02-18 09:43:40.187 (Zigate) =====> sendZigateCmd - 0100 02d26e0101000600000000014000 Queue Length: 3
2020-02-18 09:43:40.187 (Zigate) -- normalizedReadAttrReq ---- addr =d26e Cluster = 0006 Attributes = 0x4001, 0x4002, 0x4003
2020-02-18 09:43:40.187 (Zigate) =====> sendZigateCmd - 0100 02d26e010100060000000003400140024003 Queue Length: 4
2020-02-18 09:43:40.213 (Zigate) Decode8702 - IEEE: 14b457fffe4c3e08 Nwkid: d26e Status: d4
2020-02-18 09:43:40.315 (Zigate) Decode8702 - IEEE: 14b457fffe4c3e08 Nwkid: d26e Status: d4
2020-02-18 09:43:40.416 (Zigate) Decode8702 - IEEE: 14b457fffe4c3e08 Nwkid: d26e Status: d4
2020-02-18 09:43:46.526 (Zigate) Decode8011 - Src: d26e, SrcEp: 01, Cluster: 0006, Status: a7 MainPowered: True
2020-02-18 09:43:46.527 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 1 (d26e) clusterId: 0006
2020-02-18 09:43:46.629 (Zigate) Decode8011 - Src: d26e, SrcEp: 01, Cluster: 0000, Status: a7 MainPowered: True
2020-02-18 09:43:46.629 (Zigate) Receive NACK from Woonkamer: Spot uitbouw 1 (d26e) clusterId: 0000

[ronaldbro]

All the widgets are in timeout (red header), only the group widgets are not. Switching on/off doesn't work. Although I have a script changing color temp every 5 minutes and those commands seem to get through sometimes, but I don't think every time.

Polling is disabled and forcePollingAfterAction is enabled (already tried disabling it). Also tried disabling ping and I disabled OTA.

If you want I can setup a Webex meeting and share my screen so you can have a look yourself.

Ok, sif the device cannot be controlled anymore ( On/Off doesn't work), this means that the NACK stuff is correct and the device is disconnected from the Zigate.

They are really not disconnected. When I poweroff and poweron a device I see a rejoin right away followed by a NACK

2020-02-18 09:57:54.870 Status: (Zigate) Device Announcement Addr: f408, IEEE: 086bd7fffe1e23b4 Join Flag: 0x00 - join a network through association RSSI: 126
2020-02-18 09:57:55.888 (Zigate) Decode8701 - Route discovery has been performed for bd6f, status: e1 - MAC - [e1] CSMA/CA channel access failure. Nwk Status: d0 - NWK - [d0] Attempt at route discovery has failed due to any reason except lack of table space
2020-02-18 09:57:58.780 (Zigate) Decode8030 - Bind reponse for f408
2020-02-18 09:57:58.781 (Zigate) Decode8030 - Bind response, Device: f408 Status: 00
2020-02-18 09:58:08.300 (Zigate) Decode8702 - IEEE: 086bd7fffe1e23b4 Nwkid: f408 Status: e1
2020-02-18 09:58:13.647 (Zigate) Decode8702 - IEEE: 086bd7fffe1e23b4 Nwkid: f408 Status: e1
2020-02-18 09:58:14.150 (Zigate) Decode8011 - Src: f408, SrcEp: 01, Cluster: 0001, Status: a7 MainPowered: True
2020-02-18 09:58:14.151 (Zigate) Receive NACK from Keuken: Aanrecht (f408) clusterId: 0001
2020-02-18 09:58:14.905 (Zigate) Decode8702 - IEEE: 086bd7fffe1e23b4 Nwkid: f408 Status: e1
2020-02-18 09:58:19.032 (Zigate) Decode8702 - IEEE: 086bd7fffe1e23b4 Nwkid: f408 Status: e1
2020-02-18 09:58:19.135 (Zigate) Decode8011 - Src: f408, SrcEp: 01, Cluster: 0001, Status: a7 MainPowered: True
2020-02-18 09:58:19.136 (Zigate) Receive NACK from Keuken: Aanrecht (f408) clusterId: 0001
2020-02-18 09:58:20.548 (Zigate) Decode8702 - IEEE: 086bd7fffe1e23b4 Nwkid: f408 Status: e1
2020-02-18 09:58:20.600 (Zigate) Decode8011 - Src: f408, SrcEp: 01, Cluster: 0001, Status: a7 MainPowered: True
2020-02-18 09:58:20.601 (Zigate) Receive NACK from Keuken: Aanrecht (f408) clusterId: 0001
2020-02-18 09:58:24.138 (Zigate) Decode8011 - Src: f408, SrcEp: 01, Cluster: 0008, Status: a7 MainPowered: True
2020-02-18 09:58:24.139 (Zigate) Receive NACK from Keuken: Aanrecht (f408) clusterId: 0008
2020-02-18 09:58:25.593 (Zigate) Decode8011 - Src: f408, SrcEp: 01, Cluster: 0000, Status: a7 MainPowered: True
2020-02-18 09:58:25.594 (Zigate) Receive NACK from Keuken: Aanrecht (f408) clusterId: 0000