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

Failing to control zigbee devices after update to herdsman 2.1.9 with no error raised #1294

Open
asgothian opened this issue Jan 14, 2025 · 8 comments
Open

Failing to control zigbee devices after update to herdsman 2.1.9 with no error raised #1294

asgothian opened this issue Jan 14, 2025 · 8 comments

Comments

@asgothian
Copy link
Contributor

asgothian commented Jan 14, 2025 •
edited
Loading

Hello,

I have again a strange issue, which affects a number of installations using the cc2531 / cc2538 coordinators. I have been trying to catch it for about 2 months now, but never had direct access to an affected installation. Now I do.

The situation is:
I have a working installation with a cc2538 using zigbee-herdsman 0.41.2 with approx 30 devices (good mix of routers / end devices where communication to the devices work flawlessly.
After an update to the current stable zigbee adapter, which uses zigbee-herdsman 2.1.9 and latest 20.x zigbee-herdsman-converters, the system does no longer work properly.

The coordinator receives messages from the zigbee-network as before. All devices can report their status changes, and remotes will work as intended. But it no longer sends any data to the devices. It is impossible to control any device, open the network, etc. What confuses me is that no error is raised, the code simply stops, as is visible in this example of log messages:

Trying to set a state on a plug with the zigbee-herdsman 2.1.9 on an old database:

2025-01-14 12:36:09.589  - warn: zigbee.0 (24865) ELEVATED O01: User state change of state zigbee.0.842e14fffe28bb30.state with value true (ack: false) from system.adapter.admin.0
2025-01-14 12:36:09.603  - warn: zigbee.0 (24865) ELEVATED O02: Change state 'state' at device 0x842e14fffe28bb30 type 'HG06619'
2025-01-14 12:36:09.610  - warn: zigbee.0 (24865) ELEVATED O03: Publishing to 0x842e14fffe28bb30 of model HG06619 
2025-01-14 12:36:09.611  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["state","on_time","off_wait_time"]
2025-01-14 12:36:09.612  - warn: zigbee.0 (24865) ELEVATED O4.1: Setting' converter to converter with key(s)'["state","on_time","off_wait_time"]}
2025-01-14 12:36:09.613  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["power_on_behavior","power_outage_memory"]
2025-01-14 12:36:09.613  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["scene_store"]
2025-01-14 12:36:09.614  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["scene_recall"]
2025-01-14 12:36:09.615  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["scene_add"]
2025-01-14 12:36:09.615  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["scene_remove"]
2025-01-14 12:36:09.617  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["scene_remove_all"]
2025-01-14 12:36:09.618  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["scene_rename"]
2025-01-14 12:36:09.618  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["read"]
2025-01-14 12:36:09.619  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["write"]
2025-01-14 12:36:09.620  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["command"]
2025-01-14 12:36:09.620  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["reset"]
2025-01-14 12:36:09.621  - warn: zigbee.0 (24865) EX Type of toZigbee is 'object', Contains key ["zclcommand"]
2025-01-14 12:36:09.622  - warn: zigbee.0 (24865) EX: converter found for ["state","on_time","off_wait_time"]
2025-01-14 12:36:09.623  - warn: zigbee.0 (24865) ELEVATED O4: convert state, "ON", {} for device 0x842e14fffe28bb30 with Endpoint state
2025-01-14 12:36:09.626  - warn: zigbee.0 (24865) EX: target is {"_events":{},"_eventsCount":0,"_maxListeners":100,"deviceID":9,"inputClusters":[0,3,4,5,6],"outputClusters":[25,10],"profileID":260,"ID":1,"clusters":{"genBasic":{"attributes":{"modelId":"TS0101","manufacturerName":"_TZ3000_pnzfdr9y","powerSource":1,"zclVersion":3,"appVersion":65,"stackVersion":0,"hwVersion":1,"dateCode":""}},"genOnOff":{"attributes":{"onOff":1}}},"deviceIeeeAddress":"0x842e14fffe28bb30","deviceNetworkAddress":18358,"_binds":[{"cluster":6,"type":"endpoint","deviceIeeeAddress":"0x00124b0009d6cafe","endpointID":1}],"_configuredReportings":[{"cluster":6,"attrId":0,"minRepIntval":0,"maxRepIntval":3600,"repChange":0}],"meta":{},"pendingRequests":{"sendInProgress":false,"ID":1,"deviceIeeeAddress":"0x842e14fffe28bb30"}}
2025-01-14 12:36:09.627  - warn: zigbee.0 (24865) ELEVATED OX: calling convertSet with Parameters {"_events":{},"_eventsCount":0,"_maxListeners":100,"deviceID":9,"inputClusters":[0,3,4,5,6],"outputClusters":[25,10],"profileID":260,"ID":1,"clusters":{"genBasic":{"attributes":{"modelId":"TS0101","manufacturerName":"_TZ3000_pnzfdr9y","powerSource":1,"zclVersion":3,"appVersion":65,"stackVersion":0,"hwVersion":1,"dateCode":""}},"genOnOff":{"attributes":{"onOff":1}}},"deviceIeeeAddress":"0x842e14fffe28bb30","deviceNetworkAddress":18358,"_binds":[{"cluster":6,"type":"endpoint","deviceIeeeAddress":"0x00124b0009d6cafe","endpointID":1}],"_configuredReportings":[{"cluster":6,"attrId":0,"minRepIntval":0,"maxRepIntval":3600,"repChange":0}],"meta":{},"pendingRequests":{"sendInProgress":false,"ID":1,"deviceIeeeAddress":"0x842e14fffe28bb30"}},"state","ON","{,endpoint_name: undefined,options: undefined,device: \"zigbee device\",mapped: undefined,message: undefined,logger: undefined,state: undefined,}"
2025-01-14 12:38:06.105  - warn: zigbee.0 (24865) ELEVATED O01: User state change of state zigbee.0.842e14fffe28bb30.state with value false (ack: false) from system.adapter.admin.0

Note that no error message appears before the next attempt to switch the device is made (last log entry)

Below is another test I made after some manual intervention.
This is the same device, using the same hardware (coordinator, computer) with the identical code as the one above, and identical network parameters (PanID, ExtPanID, Channel, TransportKey). The only thing which was done was to start the instance with no devices to generate shepherd.db and nvbackup.json, then stop it, copy the entry from the shepherd.db for this device from the shepherd.db of the 'nonworking' instance to the new instance, before starting it again.

2025-01-14 12:27:37.238  - warn: zigbee.1 (24239) ELEVATED O01: User state change of state zigbee.1.842e14fffe28bb30.state with value true (ack: false) from system.adapter.admin.0
2025-01-14 12:27:37.258  - warn: zigbee.1 (24239) ELEVATED O02: Change state 'state' at device 0x842e14fffe28bb30 type 'HG06619'
2025-01-14 12:27:37.269  - warn: zigbee.1 (24239) ELEVATED O03: Publishing to 0x842e14fffe28bb30 of model HG06619 
2025-01-14 12:27:37.274  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["state","on_time","off_wait_time"]
2025-01-14 12:27:37.275  - warn: zigbee.1 (24239) ELEVATED O4.1: Setting' converter to converter with key(s)'["state","on_time","off_wait_time"]}
2025-01-14 12:27:37.276  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["power_on_behavior","power_outage_memory"]
2025-01-14 12:27:37.277  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["scene_store"]
2025-01-14 12:27:37.277  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["scene_recall"]
2025-01-14 12:27:37.278  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["scene_add"]
2025-01-14 12:27:37.279  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["scene_remove"]
2025-01-14 12:27:37.280  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["scene_remove_all"]
2025-01-14 12:27:37.280  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["scene_rename"]
2025-01-14 12:27:37.281  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["read"]
2025-01-14 12:27:37.282  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["write"]
2025-01-14 12:27:37.283  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["command"]
2025-01-14 12:27:37.283  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["reset"]
2025-01-14 12:27:37.284  - warn: zigbee.1 (24239) EX Type of toZigbee is 'object', Contains key ["zclcommand"]
2025-01-14 12:27:37.285  - warn: zigbee.1 (24239) EX: converter found for ["state","on_time","off_wait_time"]
2025-01-14 12:27:37.286  - warn: zigbee.1 (24239) ELEVATED O4: convert state, "ON", {} for device 0x842e14fffe28bb30 with Endpoint state
2025-01-14 12:27:37.288  - warn: zigbee.1 (24239) EX: target is {"_events":{},"_eventsCount":0,"_maxListeners":100,"deviceID":9,"inputClusters":[0,3,4,5,6],"outputClusters":[25,10],"profileID":260,"ID":1,"clusters":{"genBasic":{"attributes":{"modelId":"TS0101","manufacturerName":"_TZ3000_pnzfdr9y","powerSource":1,"zclVersion":3,"appVersion":65,"stackVersion":0,"hwVersion":1,"dateCode":""}},"genOnOff":{"attributes":{"onOff":0}}},"deviceIeeeAddress":"0x842e14fffe28bb30","deviceNetworkAddress":18358,"_binds":[{"cluster":6,"type":"endpoint","deviceIeeeAddress":"0x00124b0009d6cafe","endpointID":1}],"_configuredReportings":[{"cluster":6,"attrId":0,"minRepIntval":0,"maxRepIntval":3600,"repChange":0}],"meta":{},"pendingRequests":{"sendInProgress":false,"ID":1,"deviceIeeeAddress":"0x842e14fffe28bb30"}}
2025-01-14 12:27:37.290  - warn: zigbee.1 (24239) ELEVATED OX: calling convertSet with Parameters {"_events":{},"_eventsCount":0,"_maxListeners":100,"deviceID":9,"inputClusters":[0,3,4,5,6],"outputClusters":[25,10],"profileID":260,"ID":1,"clusters":{"genBasic":{"attributes":{"modelId":"TS0101","manufacturerName":"_TZ3000_pnzfdr9y","powerSource":1,"zclVersion":3,"appVersion":65,"stackVersion":0,"hwVersion":1,"dateCode":""}},"genOnOff":{"attributes":{"onOff":0}}},"deviceIeeeAddress":"0x842e14fffe28bb30","deviceNetworkAddress":18358,"_binds":[{"cluster":6,"type":"endpoint","deviceIeeeAddress":"0x00124b0009d6cafe","endpointID":1}],"_configuredReportings":[{"cluster":6,"attrId":0,"minRepIntval":0,"maxRepIntval":3600,"repChange":0}],"meta":{},"pendingRequests":{"sendInProgress":false,"ID":1,"deviceIeeeAddress":"0x842e14fffe28bb30"}},"state","ON","{,endpoint_name: undefined,options: undefined,device: \"zigbee device\",mapped: undefined,message: undefined,logger: undefined,state: undefined,}"
2025-01-14 12:27:43.492  - warn: zigbee.1 (24239) DeviceAvailability:Failed to ping 0xa4c138c4d9181b0a TS011F
2025-01-14 12:27:43.552  - warn: zigbee.1 (24239) ELEVATED O05: convert result {"state":{"state":"ON"}} sent to device 0x842e14fffe28bb30
2025-01-14 12:27:43.607  - warn: zigbee.1 (24239) ELEVATED I0: Zigbee Event of Type attributeReport from device "0x842e14fffe28bb30", incoming event: {"type":"attributeReport","device":"0x842e14fffe28bb30","endpoint":1,"data":{"onOff":1},"linkquality":110,"groupID":0,"cluster":"genOnOff"}
2025-01-14 12:27:43.622  - warn: zigbee.1 (24239) ELEVATED I1: message received '{"linkquality":110}' from device 842e14fffe28bb30 type 'HG06619'
2025-01-14 12:27:43.623  - warn: zigbee.1 (24239) ELEVATED I2: value generated '110' from device 842e14fffe28bb30 for 'Link quality'
2025-01-14 12:27:43.631  - warn: zigbee.1 (24239) ELEVATED I1: message received '{"state":"ON"}' from device 842e14fffe28bb30 type 'HG06619'
2025-01-14 12:27:43.631  - warn: zigbee.1 (24239) ELEVATED I2: value generated 'true' from device 842e14fffe28bb30 for 'On/off state of the switch'

Note that the message with the tag ELEVATED O05 comes approx 280 ms after the message tagged ELEVATED OX. The following ELEVATED I.. tagged messages show the response from the device - with this instance, I am able to control the device.

Here is the appropriate code:

                try {
                    if (has_elevated_debug) {
                        let metastring = ['{'];
                        for (const prop in meta) {
                            if (prop != 'device')
                                metastring.push(`${prop}: ${JSON.stringify(meta.prop)}`);
                            else
                            metastring.push(`${prop}: "zigbee device"`);
                        }
                        metastring.push('}');
                        this.log.warn(`ELEVATED OX: calling convertSet with Parameters ${safeJsonStringify(target)},${safeJsonStringify(key)},${safeJsonStringify(preparedValue)},${safeJsonStringify(metastring.join(','))}`);
                    }
                    const result = await converter.convertSet(target, key, preparedValue, meta);
                    if (has_elevated_debug)
                        this.log.warn(`ELEVATED O05: convert result ${safeJsonStringify(result)} sent to device ${deviceId}`);
                    else
                        this.log.debug(`convert result ${safeJsonStringify(result)}`);
                    if (result !== undefined) {
                        if (stateModel && !isGroup) {
                            this.acknowledgeState(deviceId, model, stateDesc, value);
                        }
                        // process sync state list
                        this.processSyncStatesList(deviceId, model, syncStateList);
                    }
                    else
                        if (has_elevated_debug)
                            this.log.error(`ELEVATED OE2: Error convert result for ${key} with ${safeJsonStringify(preparedValue)} is undefined on device ${deviceId}.`);

                } catch (error) {
                    if (has_elevated_debug)
                        this.log.error(`ELEVATED OE3: caught error ${safeJsonStringify(error)} when setting value for device ${deviceId}.`);
                    this.filterError(`Error ${error.code} on send command to ${deviceId}.` +
                        ` Error: ${error.stack}`, `Send command to ${deviceId} failed with`, error);
                }

Note how the only call between the two messages is the call to convertSet ?

I have to admit that I am completely at a loss as to what is causing this, but there are a significant number of installations out there using the cc2538 coordinator still, and I would love to be able to offer them a way to retain their zigbee Networks while migrating to the current zigbee-herdsman and converters.

A.
p.s. these tests are made with 2.1.9 due to the fact that 3.0 and the converters 21.x introduce changes to a large number of devices which requires a significant amount of work before I can move to this.
@juergiboy
Copy link

Hello,
I have the same problem with my cc2538 coordinator.
Receiving data (temp-sensor, window-sensor etc) works, but sending data (bulbs) doesn't work.

@asgothian
Copy link
Contributor Author

@juergiboy Are you using the iobroker zigbee adapter or zigbee2mqtt.io ?

@juergiboy
Copy link

@asgothian I am using both at this time.
The iobroker zigbee adapter with the cc2538 coordinator, i habe upgraded this in a first step.
And in another proxmox container i am using Zigbee2Mqtt with a cc2652. I don't upgraded this container yet.

@asgothian
Copy link
Contributor Author

But the error itself you described only affects the zigbee adapter ? I would love to know if a similar error also affects zigbee2mqtt.io installations which move from an older version with the 0.4.x herdsman to installations with the 2.1.9 herdsman.

@juergiboy
Copy link

@asgothian Yes, the error affects the zigbee adapter.
After this experience I have not yet dared to upgrade the z2m installation :-)

@asgothian
Copy link
Contributor Author

  • what zigbee-herdsman and zigbee-herdsman-converters are active in the z2m installation ?
  • considering you use a cc2652 coordinator, I would not expect this bug to affect your z2m installation in any case. There may be other effects when upgrading to z2m 2.0, though (see list of device changes)

A.

@juergiboy
Copy link

grafik

considering you use a cc2652 coordinator, I would not expect this bug to affect your z2m installation in any case. There may be other effects when upgrading to z2m 2.0, though (see list of device changes)

I am also think so, i will try the upgrade next days.

@asgothian
Copy link
Contributor Author

Make sure you read the change notes for the devices which have changed since then. There are quite a lot of devices which have significant changes in their message structure.

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
@asgothian @juergiboy