Zemismart Wireless Wall Switch _TZ3000_tk3s5tyg Tuya TS0041 - Fast discharge + device announcements

robertalexa commented 3 years ago

Hi,

For the last 4 months I have been using 4 Zemismart Wireless Wall Switches 1 Gang available at https://www.aliexpress.com/item/4001227549409.html

In these 4 months I have changed the batteries more than once per month for each of these devices. I have tried different brands including Duracell without noticing any difference in their longevity.

In this post I will be using only 1 of my devices as reference.

On top of that, despite the device "allegedly" reporting the battery state, the battery level never changes once the device is paired up. For example, new battery, pair the device, it usually says 90% battery, and it remains at 90 all the way until the battery dies.

Here is the device information from the database file.

{"id":7,"type":"EndDevice","ieeeAddr":"0x804b50fffe0b6a8f","nwkAddr":14083,"manufId":4098,"manufName":"_TZ3000_tk3s5tyg","powerSource":"Battery","modelId":"TS0041","epList":[1],"endpoints":{"1":{"profId":260,"epId":1,"devId":0,"inClusterList":[0,1,6],"outClusterList":[25,10],"clusters":{"genBasic":{"attributes":{"modelId":"TS0041","manufacturerName":"_TZ3000_tk3s5tyg","powerSource":3,"zclVersion":3,"appVersion":65,"stackVersion":0,"hwVersion":1,"dateCode":""}},"genPowerCfg":{"attributes":{"batteryPercentageRemaining":180}}},"binds":[{"cluster":1,"type":"endpoint","deviceIeeeAddress":"0x00124b0021b953c1","endpointID":1}],"configuredReportings":[{"cluster":1,"attrId":33,"minRepIntval":3600,"maxRepIntval":62000,"repChange":0}],"meta":{}}},"appVersion":65,"stackVersion":0,"hwVersion":1,"dateCode":"","zclVersion":3,"interviewCompleted":true,"meta":{"configured":1},"lastSeen":1626691841882}

On top of this, I have noticed that the devices announce themselves approximately every hour and 1 or 2 minutes. Here is everything for this device for the last few hours (the device was not pressed so you won't see any actions).

Zigbee2MQTT:debug 2021-07-19 08:45:19: Device 'Rob's Nightstand Light Switch' announced itself,
Zigbee2MQTT:info  2021-07-19 08:45:19: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}',
Zigbee2MQTT:info  2021-07-19 08:45:19: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}',
Zigbee2MQTT:debug 2021-07-19 08:45:22: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0,
Zigbee2MQTT:debug 2021-07-19 09:47:05: Device 'Rob's Nightstand Light Switch' announced itself,
Zigbee2MQTT:info  2021-07-19 09:47:05: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}',
Zigbee2MQTT:info  2021-07-19 09:47:05: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}',
Zigbee2MQTT:debug 2021-07-19 09:47:09: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0,
Zigbee2MQTT:debug 2021-07-19 10:48:53: Device 'Rob's Nightstand Light Switch' announced itself,
Zigbee2MQTT:info  2021-07-19 10:48:53: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}',
Zigbee2MQTT:info  2021-07-19 10:48:53: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}',
Zigbee2MQTT:debug 2021-07-19 10:48:53: Device 'Rob's Nightstand Light Switch' announced itself,
Zigbee2MQTT:info  2021-07-19 10:48:53: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}',
Zigbee2MQTT:info  2021-07-19 10:48:53: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}',
Zigbee2MQTT:debug 2021-07-19 10:48:56: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0,
Zigbee2MQTT:debug 2021-07-19 11:50:37: Device 'Rob's Nightstand Light Switch' announced itself,
Zigbee2MQTT:info  2021-07-19 11:50:37: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}',
Zigbee2MQTT:info  2021-07-19 11:50:37: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}',
Zigbee2MQTT:debug 2021-07-19 11:50:41: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0,
Zigbee2MQTT:debug 2021-07-19 12:52:23: Device 'Rob's Nightstand Light Switch' announced itself,
Zigbee2MQTT:info  2021-07-19 12:52:23: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}',
Zigbee2MQTT:info  2021-07-19 12:52:23: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}',
Zigbee2MQTT:debug 2021-07-19 12:52:27: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0

I am not sure if this means:

the device falls off the network (but I have nothing in the logs to make me think of that. The devices are close to other powered devices in the mesh, and there are other zigbee devices connected to the same nodes that do not disconnect)
fall into deep sleep (idk if devices announce themselves again when they come back?)
or they are just crappy devices?

Regarding the deep sleep, there are many occasions where i press the switch and nothing happens for the first action (single, double, hold) but then it does work if i repeat the action (this is really annoying me) - because this happens sporadically (basically when i go to bed) I have not found the chance to investigate the logs. So I am not sure if the device is sleeping or what, this is just a guess.

I was hoping that maybe some of you have this device and can share their story, or if anyone else can spot an issue here, or can come with some recommendations.

TLDR:

device announces itself every hour
battery drains super fast for a device that gets barely used - roughly dies every 2 weeks
sometimes first action doesn't do anything but works on second try

Many thanks, Rob

Debug info

Zigbee2MQTT version: 1.20.0-1 Adapter hardware: Electrolama zig-a-zig-ah!

MattWestb commented 3 years ago

The device announce and that the firs key press not working is the same problem. Its one Zigbee 3 device and its checking in to its parent between its being in sleep mode. If its to long between the checkins its its must doing handshake with its parent for going back in to thee network.

It can also being that the pull control cluster in the parent is not being OK configured or the host system is setting it up wrongly (or the device is making it bad it self). I was testing the problem that IKEA controllers super draining batteries and is setting the checkin interval longer then the device is requesting from its parent (child time out request then pairing) was the device doing device announce then every pull of its parent = very bad for battery and system performance.

One more thing tuya have one old version of the device with TYZS5 that is having one MG13 with 512 kb flash and 64 kb ram that is enough (the dark module with pads on 2 sides) but dont have enough pins for the 4 button model. The newer variant is with MG21 (white with pads on 3 sides) that is having more then the double hardware performance and IO pads that is one of the best on the market but both is being bad mounted and the antenna is very disturbed of metal on the PCB so the layout is pity bad from the radio part.

Sniffing the Zigbe traffic is the only way to see wot is going wrong between the device and its parent.

robertalexa commented 3 years ago

@MattWestb Hi Matt and thank you for your reply.

In my case:

I don't think the problem is with the parent. The reason for my assumption is that i have 4 switches that suffer from this problem. 2 of them are connected to the device in the screenshot, 1 is connected to a different type of plug and the last 1 is connected directly to coordinator.

I also don't think it is a problem with range or signal. All 4 devices are within 1 metre from their parent. Also i would most likely see variation in the timestamp when the devices announce themselves, rather than 1h and 1 or 2 minutes every time.

So the other option from your suggestions is regarding the polling of devices. But as mentioned above, the devices are connected to different parents, including coordinator. So idk where to go at this point.

@Koenkk do you have any thoughts please?

Rob

Koenkk commented 3 years ago

@robertalexa device announcement are usually send when the device boots (e.g. after power loss of a AC powered bulb or if a device crashes due to some issue in the firmware). Do you maybe have the original gateway, if yes does the same issue happen here?

robertalexa commented 3 years ago

@Koenkk Thanks for your prompt reply!

Unfortunately i don't have a tuya gateway, but i am tempted to buy one purely on this basis of sniffing and testing.

As to your statement, i was imagining the same to be true, but this happens with brand new batteries too. And it is super weird how it happens every hour and 1 minute or 2.

github-actions[bot] commented 3 years ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days

robertalexa commented 2 years ago

@Koenkk a lot of time has passed since this, but I have finally found some time to purchase a tuya gateway and sniff the traffic between this switch and it. I have left it running for a few hours and did NOT see the same behaviour. The device does not re announce itself, nor does the blue light flash (as it does when announcing on z2m).

Would you be kind to have a look and see if you notice anything that is handled differently than in z2m? Currently I have 4 of these switches in use with z2m. The full description of the issue is in the first comment.

Thanks in advance

Notes:

i had to zip the file because github doesn't like pcapng files
the sniff should show the device first pairing, while doing that i have also added the required key to decrypt
there is only communication from 2 devices: gateway and switch
the command for single/double/hold shows as unknown in wireshark.

Tuya Gateway Sniff

switch-wireshark.zip

robertalexa commented 2 years ago

To further add to this. Using the tuya gateway, i can check for device connection quality:

after the switch has been used the results comes with excellent
after a while (in my testing a bit over an hour) the device can't be reached. Note: tuya says make sure to wake up battery devices before doing this. But i didn't just to confirm the device is actually sleeping

Knowing the device is sleeping, i press the button and the tuya automation triggers first time, unlike z2m. In z2m the device will most likely need to re-announce, re-connect, and on second attempt it will work fine. That is for another while when it goes to sleep. Though every hourish the device re-announces, and if you press the button for the first time (coincidentaly) after that time, it will work first try

Koenkk commented 2 years ago

@robertalexa could you try with the following definition (I modified the configure to match the commands send by the tuya gateway)

{
        zigbeeModel: ['TS0041'],
        fingerprint: [{manufacturerName: '_TZ3000_tk3s5tyg'}],
        model: 'TS0041',
        vendor: 'TuYa',
        description: 'Wireless switch with 1 button',
        whiteLabel: [{vendor: 'Smart9', model: 'S9TSZGB'}, {vendor: 'Lonsonho', model: 'TS0041'}, {vendor: 'Benexmart', model: 'ZM-sui1'}],
        exposes: [e.battery(), e.action(['single', 'double', 'hold'])],
        fromZigbee: [fz.tuya_on_off_action, fz.battery],
        toZigbee: [],
        configure: async (device, coordinatorEndpoint, logger) => {
            const endpoint = device.getEndpoint(1);
            await endpoint.read('genBasic', [0x0004, 0x000, 0x0001, 0x0005, 0x0007, 0xfffe]);
            await endpoint.write('genBasic', {0xffde: {value: 0x13, type: 0x20}});
            await reporting.bind(endpoint, coordinatorEndpoint, ['genPowerCfg']);
            try {
                await reporting.batteryPercentageRemaining(endpoint);
            } catch (error) {/* Fails for some: https://github.com/Koenkk/zigbee2mqtt/issues/6313 */}
        },
    }

robertalexa commented 2 years ago

@Koenkk Thanks a lot for your prompt reply.

Could you please clarify sth for me? Once adding this in (via portainer on HA addon and restarting via portainer for the changes to persist), is it necessary to press the reconfigure button for each device (since this is in configure)?

robertalexa commented 2 years ago

Ive done it anyway.

One thing to note is that configuration fails (but it failed before anyway) - but maybe only the first attempt failed?

Info Configuring 'Rob's Nightstand Light Switch'
Error Failed to configure 'Rob's Nightstand Light Switch', attempt 1 (Error: Read 0x804b50fffe0b6a8f/1 genBasic([4,0,1,5,7,65534], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 14083 - 1 - 41 - 0 - 1 after 10000ms) at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:64:35) at listOnTimeout (internal/timers.js:557:17) at processTimers (internal/timers.js:500:7))
Info MQTT publish: topic 'zigbee2mqtt/bridge/response/device/configure', payload '{"data":{"id":"Rob's Nightstand Light Switch"},"error":"Failed to configure (Read 0x804b50fffe0b6a8f/1 genBasic([4,0,1,5,7,65534], {\"timeout\":10000,\"disableResponse\":false,\"disableRecovery\":false,\"disableDefaultResponse\":true,\"direction\":0,\"srcEndpoint\":null,\"reservedBits\":0,\"manufacturerCode\":null,\"transactionSequenceNumber\":null,\"writeUndiv\":false}) failed (Timeout - 14083 - 1 - 41 - 0 - 1 after 10000ms))","status":"error","transaction":"7ap2o-3"}'
Info MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":"single","battery":100,"last_seen":1642524978616,"linkquality":102,"voltage":3000}'
Info MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":"","battery":100,"last_seen":1642524978616,"linkquality":102,"voltage":3000}'
Info MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch/action', payload 'single'
Info MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642524978748,"linkquality":102,"voltage":3000}'
Info MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642524978791,"linkquality":102,"voltage":3000}'

Throughout the use of these devices over the last year or so I have never seen a battery change more than the initial value.

The battery is reported with the tuya gateway, but i have yet to see a decrease, only set this up a few days back with a brand new battery. So i will keep an eye on this one and come back with further findings. I wonder is this is also sth that is broken?

Koenkk commented 2 years ago

@robertalexa have you tried to force remove and repair the device?

robertalexa commented 2 years ago

@Koenkk Just for peach of mind i did that now with all 4 devices. This emulates a fresh/cold start. Device paired and configured successfully. (they were configured before anyway, but the battery percent never changed, not even when the batteries died).

I will continue normal use and report once I have more. It should only take me a few nights to notice if the light is randomly flashing (meaning it was re-announced) or not. If they don't then that might be a very good sign, and hopefully that increased the battery life span.

Thanks for your help, will comment here with findings.

robertalexa commented 2 years ago

@Koenkk

Devices are still re-announcing themselves (flashing blue light when they do it)

All devices:

Zigbee2MQTT:debug 2022-01-19 05:46:52: Device 'Steph's Armchair Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 05:49:30: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 05:51:58: Device 'Steph's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 06:45:27: Device 'Hallway Secondary Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 06:48:38: Device 'Steph's Armchair Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 06:51:17: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 06:53:46: Device 'Steph's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 07:47:12: Device 'Hallway Secondary Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 07:50:23: Device 'Steph's Armchair Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 07:53:04: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 07:55:35: Device 'Steph's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 08:48:57: Device 'Hallway Secondary Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 08:52:09: Device 'Steph's Armchair Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 08:54:52: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 08:57:24: Device 'Steph's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 09:50:42: Device 'Hallway Secondary Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 09:53:54: Device 'Steph's Armchair Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 09:56:39: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 09:59:13: Device 'Steph's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 10:52:27: Device 'Hallway Secondary Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 10:55:40: Device 'Steph's Armchair Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 10:58:25: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:debug 2022-01-19 11:01:02: Device 'Steph's Nightstand Light Switch' announced itself

1 device in detail (last roughly 6 hours, the device was not used in this time at all)

Zigbee2MQTT:info  2022-01-19 05:49:30: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642571370438,"linkquality":66,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 05:49:30: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642571370711,"linkquality":66,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 05:49:30: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:info  2022-01-19 05:49:30: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-19 05:49:30: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-19 05:49:32: Retrieving state of 'Rob's Nightstand Light Switch' after reconnect
Zigbee2MQTT:debug 2022-01-19 05:49:34: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 05:49:34: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642571374234,"linkquality":66,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 05:49:35: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 05:49:35: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642571375864,"linkquality":66,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 05:49:36: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 05:49:36: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642571376089,"linkquality":66,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 05:51:34: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65503":"�bz)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 05:51:34: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642571494423,"linkquality":69,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 06:09:27: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":180,"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 06:09:27: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642572567782,"linkquality":96,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 06:51:17: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642575077640,"linkquality":96,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 06:51:17: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642575077869,"linkquality":96,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 06:51:17: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:info  2022-01-19 06:51:18: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-19 06:51:18: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-19 06:51:20: Retrieving state of 'Rob's Nightstand Light Switch' after reconnect
Zigbee2MQTT:debug 2022-01-19 06:51:21: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 06:51:21: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642575081190,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 06:51:23: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 06:51:23: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642575083073,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 06:51:23: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 06:51:23: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642575083289,"linkquality":69,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 06:53:11: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65503":"qqz)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 06:53:11: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642575191314,"linkquality":69,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 07:11:14: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":180,"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 07:11:14: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642576274925,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 07:53:04: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642578784799,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 07:53:04: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642578784990,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 07:53:04: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:info  2022-01-19 07:53:05: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-19 07:53:05: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-19 07:53:07: Retrieving state of 'Rob's Nightstand Light Switch' after reconnect
Zigbee2MQTT:debug 2022-01-19 07:53:08: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 07:53:08: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642578788419,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 07:53:10: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 07:53:10: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":90,"last_seen":1642578790177,"linkquality":72,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 07:53:10: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 07:53:10: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642578790395,"linkquality":72,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 07:54:20: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65503":"�z)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 07:54:20: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642578860938,"linkquality":69,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 08:13:02: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":182,"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 08:13:02: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642579982007,"linkquality":48,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 08:54:51: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642582491809,"linkquality":48,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 08:54:51: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642582491811,"linkquality":48,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 08:54:52: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642582492043,"linkquality":48,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 08:54:52: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:info  2022-01-19 08:54:52: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-19 08:54:52: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-19 08:54:54: Retrieving state of 'Rob's Nightstand Light Switch' after reconnect
Zigbee2MQTT:debug 2022-01-19 08:54:56: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 08:54:56: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642582496029,"linkquality":96,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 08:54:57: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 08:54:57: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642582497238,"linkquality":96,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 08:54:57: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 08:54:57: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642582497446,"linkquality":96,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 08:56:20: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65503":"g�z)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 08:56:20: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642582580816,"linkquality":99,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 09:14:49: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":182,"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 09:14:49: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642583689035,"linkquality":99,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 09:56:38: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642586198768,"linkquality":99,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 09:56:38: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642586198771,"linkquality":99,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 09:56:39: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642586199077,"linkquality":99,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 09:56:39: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:info  2022-01-19 09:56:39: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-19 09:56:39: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-19 09:56:41: Retrieving state of 'Rob's Nightstand Light Switch' after reconnect
Zigbee2MQTT:debug 2022-01-19 09:56:42: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 09:56:42: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642586202511,"linkquality":105,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 09:56:44: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 09:56:44: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642586204231,"linkquality":105,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 09:56:44: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 09:56:44: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642586204449,"linkquality":105,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 09:58:19: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65503":"�z)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 09:58:19: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642586299507,"linkquality":105,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 10:16:36: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":182,"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 10:16:36: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642587396013,"linkquality":105,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 10:58:25: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642589905674,"linkquality":105,"voltage":2900}'
Zigbee2MQTT:info  2022-01-19 10:58:25: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642589905897,"linkquality":105,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 10:58:25: Device 'Rob's Nightstand Light Switch' announced itself
Zigbee2MQTT:info  2022-01-19 10:58:26: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"Rob's Nightstand Light Switch","ieee_address":"0x804b50fffe0b6a8f"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-19 10:58:26: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"Rob's Nightstand Light Switch"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-19 10:58:28: Retrieving state of 'Rob's Nightstand Light Switch' after reconnect
Zigbee2MQTT:debug 2022-01-19 10:58:30: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 10:58:30: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642589910059,"linkquality":87,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 10:58:31: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 10:58:31: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642589911116,"linkquality":87,"voltage":2900}'
Zigbee2MQTT:debug 2022-01-19 10:58:31: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 10:58:31: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642589911338,"linkquality":87,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 11:00:14: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genBasic', data '{"65503":"^�z)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 11:00:14: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":100,"last_seen":1642590014415,"linkquality":78,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-19 11:18:22: Received Zigbee message from 'Rob's Nightstand Light Switch', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":182,"batteryVoltage":29}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-19 11:18:22: MQTT publish: topic 'zigbee2mqtt/Rob's Nightstand Light Switch', payload '{"action":null,"battery":91,"last_seen":1642591102912,"linkquality":78,"voltage":2900}'

Koenkk commented 2 years ago

@robertalexa could you make a sniff when these device are paired to z2m and the device announce happens?

robertalexa commented 2 years ago

I think if i do it in my current setup the sniff will be super noisy because there are almost 40 devices.

I will try to unpair one of them and pair it to my test setup and then keep an eye on its behaviour. I will let you know when i have it.

Thank you for your time!

robertalexa commented 2 years ago

Log from pairing all the way to after device re-announce

Zigbee2MQTT:info  2022-01-21 13:18:42: Started frontend on port 0.0.0.0:8080
Zigbee2MQTT:info  2022-01-21 13:18:42: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"commit":"c2b5229f","coordinator":{"meta":{"maintrel":3,"majorrel":2,"minorrel":6,"product":0,"revision":20201128,"transportrev":2},"type":"zStack12"},"log_level":"debug","network":{"channel":14,"extendedPanID":"0x00124b0018e32e48","panID":6754},"permit_join":false,"version":"1.22.1"}'
Zigbee2MQTT:debug 2022-01-21 13:18:56: Received MQTT message on 'zigbee2mqtt/bridge/request/permit_join' with data '{"device":null,"time":254,"transaction":"oqen3-1","value":true}'
Zigbee2MQTT:info  2022-01-21 13:18:56: Zigbee: allowing new devices to join.
Zigbee2MQTT:info  2022-01-21 13:18:57: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{"time":254,"value":true},"status":"ok","transaction":"oqen3-1"}'
Zigbee2MQTT:warn  2022-01-21 13:19:18: Device '0x5c0272fffe248c72' left the network
Zigbee2MQTT:info  2022-01-21 13:19:18: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_leave"}'
Zigbee2MQTT:info  2022-01-21 13:19:18: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"left_network","meta":{"friendly_name":"0x5c0272fffe248c72"},"type":"device_removed"}'
Zigbee2MQTT:info  2022-01-21 13:19:22: Device '0x5c0272fffe248c72' joined
Zigbee2MQTT:info  2022-01-21 13:19:22: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_joined"}'
Zigbee2MQTT:info  2022-01-21 13:19:22: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":{"friendly_name":"0x5c0272fffe248c72"},"type":"device_connected"}'
Zigbee2MQTT:info  2022-01-21 13:19:22: Starting interview of '0x5c0272fffe248c72'
Zigbee2MQTT:info  2022-01-21 13:19:22: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72","status":"started"},"type":"device_interview"}'
Zigbee2MQTT:info  2022-01-21 13:19:22: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"interview_started","meta":{"friendly_name":"0x5c0272fffe248c72"},"type":"pairing"}'
Zigbee2MQTT:debug 2022-01-21 13:19:22: Device '0x5c0272fffe248c72' announced itself
Zigbee2MQTT:info  2022-01-21 13:19:22: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-21 13:19:22: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"0x5c0272fffe248c72"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-21 13:19:22: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"manufacturerName":"_TZ3000_tk3s5tyg","modelId":"TS0041"}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:22: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:23: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"powerSource":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:23: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:23: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"zclVersion":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:23: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:23: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:23: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:23: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"stackVersion":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:23: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:24: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"hwVersion":1}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:24: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:25: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"dateCode":""}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:25: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-21 13:19:26: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:26: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:info  2022-01-21 13:19:26: Successfully interviewed '0x5c0272fffe248c72', device has successfully been paired
Zigbee2MQTT:info  2022-01-21 13:19:26: Device '0x5c0272fffe248c72' is supported, identified as: TuYa Wireless switch with 1 button (TS0041)
Zigbee2MQTT:info  2022-01-21 13:19:26: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"definition":{"description":"Wireless switch with 1 button","exposes":[{"access":1,"description":"Remaining battery in %","name":"battery","property":"battery","type":"numeric","unit":"%","value_max":100,"value_min":0},{"access":1,"description":"Triggered action (e.g. a button click)","name":"action","property":"action","type":"enum","values":["single","double","hold"]},{"access":1,"description":"Link quality (signal strength)","name":"linkquality","property":"linkquality","type":"numeric","unit":"lqi","value_max":255,"value_min":0}],"model":"TS0041","options":[],"supports_ota":false,"vendor":"TuYa"},"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72","status":"successful","supported":true},"type":"device_interview"}'
Zigbee2MQTT:info  2022-01-21 13:19:26: Configuring '0x5c0272fffe248c72'
Zigbee2MQTT:info  2022-01-21 13:19:26: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"interview_successful","meta":{"description":"Wireless switch with 1 button","friendly_name":"0x5c0272fffe248c72","model":"TS0041","supported":true,"vendor":"TuYa"},"type":"pairing"}'
Zigbee2MQTT:debug 2022-01-21 13:19:27: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"65534":0,"appVersion":65,"manufacturerName":"_TZ3000_tk3s5tyg","modelId":"TS0041","powerSource":3,"zclVersion":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:27: Received Zigbee message from '0x5c0272fffe248c72', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 13:19:30: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-21 13:19:30: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"battery":100,"linkquality":68}'
Zigbee2MQTT:info  2022-01-21 13:19:30: Successfully configured '0x5c0272fffe248c72'
Zigbee2MQTT:debug 2022-01-21 13:19:42: Received Zigbee message from '0x5c0272fffe248c72', type 'raw', cluster 'genOnOff', data '{"data":[1,85,253,0],"type":"Buffer"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-21 13:19:42: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"action":"single","battery":100,"linkquality":63}'
Zigbee2MQTT:debug 2022-01-21 13:23:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:28:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:33:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:38:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:39:26: Received Zigbee message from '0x5c0272fffe248c72', type 'raw', cluster 'genOnOff', data '{"data":[1,86,253,0],"type":"Buffer"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-21 13:39:26: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"action":"single","battery":100,"linkquality":86}'
Zigbee2MQTT:debug 2022-01-21 13:43:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:48:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:53:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 13:58:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 14:03:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 14:08:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 14:13:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 14:18:41: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-21 14:21:14: Device '0x5c0272fffe248c72' announced itself
Zigbee2MQTT:info  2022-01-21 14:21:14: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_announce"}'
Zigbee2MQTT:info  2022-01-21 14:21:14: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"0x5c0272fffe248c72"},"type":"device_announced"}'
Zigbee2MQTT:debug 2022-01-21 14:21:16: Retrieving state of '0x5c0272fffe248c72' after reconnect
Zigbee2MQTT:debug 2022-01-21 14:21:18: Received Zigbee message from '0x5c0272fffe248c72', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 14:21:20: Received Zigbee message from '0x5c0272fffe248c72', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-21 14:21:20: Received Zigbee message from '0x5c0272fffe248c72', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-21 14:21:20: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"battery":100,"linkquality":84,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-21 14:23:12: Received Zigbee message from '0x5c0272fffe248c72', type 'attributeReport', cluster 'genBasic', data '{"65503":"�k})\u0013�k})\u0012\u0005l})\u0012)m})\u0012go})\u0012�}})\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
^CZigbee2MQTT:debug 2022-01-21 14:23:28: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:info  2022-01-21 14:23:28: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'offline'
Zigbee2MQTT:info  2022-01-21 14:23:28: Disconnecting from MQTT server
Zigbee2MQTT:info  2022-01-21 14:23:28: Stopping zigbee-herdsman...
Zigbee2MQTT:info  2022-01-21 14:23:29: Stopped zigbee-herdsman
Zigbee2MQTT:info  2022-01-21 14:23:29: Stopped Zigbee2MQTT

Wireshark file

announce.zip

The sniff starts with a button press (after pairing) which matches the timestamp in the z2m logs

Zigbee2MQTT:debug 2022-01-21 13:39:26: Received Zigbee message from '0x5c0272fffe248c72', type 'raw', cluster 'genOnOff', data '{"data":[1,86,253,0],"type":"Buffer"}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-21 13:39:26: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"action":"single","battery":100,"linkquality":86}'

Note: The network is made up from only coordinator and device and they are placed one next to the other.

Thanks for your help @Koenkk

Koenkk commented 2 years ago

Thanks, could you provide me your network key?

robertalexa commented 2 years ago

Testing setup is using the default key that z2m generates on a fresh set up. Not currently around my computer. The only custom configuration i had was frontend, debug level and channel 14.

Unless i misunderstand your question?

Koenkk commented 2 years ago

I was confused because it seems another network is active on the same channel. The coordinator is using a sillicon labs chip so its no z2m, I guess it is the tuya bridge? I'm wondering if this has something to do with the device announes, can you try running the z2m setup on a different channel and provide a sniff again?

robertalexa commented 2 years ago

Hi Koen,

Just to clarify:

my main "production" (and only - unless bench testing) network is using the Electrolama zzh and is on channel 11 and has aprox 40 devices
my tuya gateway, which is powered on just to test the behaviour of this particular device, is on channel 20 and is only connected to this switch (but not while i did the test above)
my testing rig, using a CC2531 running z2m as an npm application, on an Ubuntu laptop, is on channel 14 and at the time of the test only had the switch paired.
my sniffing setup which is a Windows machine using a different CC2531 which is dedicated to sniffing and of course, only in use when needed

During my normal operation times there is 1 single zigbee network in my house (zzh), and the device announcements happen then too. Arguably the only other zigbee network that exists in my house the the one between my smart meters (uk) and the in-home-display, but i don't know the channel it operates on as smart meters are super security restricted.

Let me attempt another test without the tuya gateway being on, and switching my testing setup to channel 20 to be as far away as possible from my main network.

I will get back to you ASAP

Thanks again

robertalexa commented 2 years ago

Btw, is there any problem having multiple transport keys configured in Wireshark? Of course the sniffing will be on a dedicated channel, but do they interfere with each other?

robertalexa commented 2 years ago

Hi Koen,

Turns out that Silicon device is the actual switch in question.

Full log from Allow join, Pair device, Device re-announces.

Zigbee2MQTT:warn  2022-01-22 18:53:30: Using experimental new availability feature
Zigbee2MQTT:info  2022-01-22 18:53:30: Started frontend on port 0.0.0.0:8080
Zigbee2MQTT:debug 2022-01-22 18:57:14: Received MQTT message on 'zigbee2mqtt/bridge/request/permit_join' with data '{"device":null,"time":254,"transaction":"szmz4-1","value":true}'
Zigbee2MQTT:info  2022-01-22 18:57:14: Zigbee: allowing new devices to join.
Zigbee2MQTT:info  2022-01-22 18:57:14: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{"time":254,"value":true},"status":"ok","transaction":"szmz4-1"}'
Zigbee2MQTT:info  2022-01-22 18:57:28: Device '0x5c0272fffe248c72' joined
Zigbee2MQTT:info  2022-01-22 18:57:28: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_joined"}'
Zigbee2MQTT:info  2022-01-22 18:57:28: Starting interview of '0x5c0272fffe248c72'
Zigbee2MQTT:info  2022-01-22 18:57:28: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72","status":"started"},"type":"device_interview"}'
Zigbee2MQTT:debug 2022-01-22 18:57:29: Device '0x5c0272fffe248c72' announced itself
Zigbee2MQTT:info  2022-01-22 18:57:29: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_announce"}'
Zigbee2MQTT:debug 2022-01-22 18:57:29: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"manufacturerName":"_TZ3000_tk3s5tyg","modelId":"TS0041"}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:29: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:29: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"powerSource":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:29: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:30: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"zclVersion":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:30: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:30: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:30: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:30: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"stackVersion":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:30: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:31: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"hwVersion":1}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:31: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:32: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"dateCode":""}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:32: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:debug 2022-01-22 18:57:34: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:34: Skipping message, definition is undefined and still interviewing
Zigbee2MQTT:info  2022-01-22 18:57:34: Successfully interviewed '0x5c0272fffe248c72', device has successfully been paired
Zigbee2MQTT:info  2022-01-22 18:57:34: Device '0x5c0272fffe248c72' is supported, identified as: TuYa Wireless switch with 1 button (TS0041)
Zigbee2MQTT:info  2022-01-22 18:57:34: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"definition":{"description":"Wireless switch with 1 button","exposes":[{"access":1,"description":"Remaining battery in %","name":"battery","property":"battery","type":"numeric","unit":"%","value_max":100,"value_min":0},{"access":1,"description":"Triggered action (e.g. a button click)","name":"action","property":"action","type":"enum","values":["single","double","hold"]},{"access":1,"description":"Link quality (signal strength)","name":"linkquality","property":"linkquality","type":"numeric","unit":"lqi","value_max":255,"value_min":0}],"model":"TS0041","options":[],"supports_ota":false,"vendor":"TuYa"},"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72","status":"successful","supported":true},"type":"device_interview"}'
Zigbee2MQTT:info  2022-01-22 18:57:34: Configuring '0x5c0272fffe248c72'
Zigbee2MQTT:debug 2022-01-22 18:57:34: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genBasic', data '{"65534":0,"appVersion":65,"manufacturerName":"_TZ3000_tk3s5tyg","modelId":"TS0041","powerSource":3,"zclVersion":3}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:34: Received Zigbee message from '0x5c0272fffe248c72', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 18:57:37: Received Zigbee message from '0x5c0272fffe248c72', type 'readResponse', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-22 18:57:37: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"battery":100,"linkquality":68}'
Zigbee2MQTT:info  2022-01-22 18:57:37: Successfully configured '0x5c0272fffe248c72'
Zigbee2MQTT:debug 2022-01-22 18:58:22: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:03:22: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:08:22: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:13:22: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:18:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:23:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:28:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:33:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:38:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:43:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:48:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:53:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:58:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:debug 2022-01-22 19:59:20: Device '0x5c0272fffe248c72' announced itself
Zigbee2MQTT:info  2022-01-22 19:59:20: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x5c0272fffe248c72","ieee_address":"0x5c0272fffe248c72"},"type":"device_announce"}'
Zigbee2MQTT:debug 2022-01-22 19:59:22: Retrieving state of '0x5c0272fffe248c72' after reconnect
Zigbee2MQTT:debug 2022-01-22 19:59:24: Received Zigbee message from '0x5c0272fffe248c72', type 'read', cluster 'genTime', data '["localTime"]' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 19:59:25: Received Zigbee message from '0x5c0272fffe248c72', type 'attributeReport', cluster 'genBasic', data '{"65506":31,"65508":1,"appVersion":65}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 19:59:25: Received Zigbee message from '0x5c0272fffe248c72', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200,"batteryVoltage":30}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2022-01-22 19:59:25: MQTT publish: topic 'zigbee2mqtt/0x5c0272fffe248c72', payload '{"battery":100,"linkquality":70,"voltage":3000}'
Zigbee2MQTT:debug 2022-01-22 20:01:18: Received Zigbee message from '0x5c0272fffe248c72', type 'attributeReport', cluster 'genBasic', data '{"65503":")\u0010)\u0012�\u001e)\u0019\u0000\u0000\u0000\u0000\u0007\u0000\u0000\u0000\u0000\u0011"}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2022-01-22 20:03:21: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
^CZigbee2MQTT:debug 2022-01-22 20:03:48: Saving state to file /home/rob/Projects/zigbee2mqtt/data/state.json
Zigbee2MQTT:info  2022-01-22 20:03:48: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'offline'
Zigbee2MQTT:info  2022-01-22 20:03:48: Disconnecting from MQTT server
Zigbee2MQTT:info  2022-01-22 20:03:48: Stopping zigbee-herdsman...
Zigbee2MQTT:info  2022-01-22 20:03:49: Stopped zigbee-herdsman
Zigbee2MQTT:info  2022-01-22 20:03:49: Stopped Zigbee2MQTT

Sniff just the same. Allow join, pair, device re-announce announce2.zip

Device in question is 0x4003

Thanks for your help

Koenkk commented 2 years ago

Thanks, the announce2 sniff looks good.

The problem is that somehow the device does not stay connected to the network, as can be seen the device rejoins the network when you press the button:

I'm wondering if this has something to do with z2m not responding to the end device timeout request:

The screenshot below is from the sniff with the TuYa gateway, which responds to the timeout request:

The end device timeout request is a zigbee 3.0 feature, assuming you are using a 1.2 firmware on your CC2531 it is expected that no response is send. However on your production network (since you are using a zzh there) it should send a response. Could you sniff this response? I'm interested in the payload of it.

robertalexa commented 2 years ago

Hi Koen, thanks for your time looking into this and the detailed feedback

as can be seen the device rejoins the network when you press the button:

The device rejoins aprox every 1h and 2min even without button press.

assuming you are using a 1.2 firmware on your CC2531 it is expected that no response is send. However on your production network (since you are using a zzh there) it should send a response

You are correct:

Testing CC2531

Production zzh

I will provide a sniff of it happening in production, but be warned the traffic will be crazy, due to the number of devices. Unfortunately I can't really replicate my production setup in just a coordinator + device setup. I will however provide the device ID to hopefully make it easier.

PS: is it safe to upgrade my zzh firmware to the latest without the need to re-pair everything? The info i found seem to indicate that yes, it will work, because of the coordinator_backup file. But just wanted to check before i make a big boo boo

Scrap that, I have successfully updated my zzh to latest firmware

robertalexa commented 2 years ago

@Koenkk I have managed to time this sniff so perfectly that I managed to only capture 6.7 seconds of traffic, but the announcement happened right after i restarted the capture.

announce-production.zip

The device is 0xbcb8. I hope this is enough data?

Alternatively I can try to flash my testing CC with zstack 3 and redo the test in a more contained fashion.

robertalexa commented 2 years ago

announce-production-longer.zip

Find attached a much longer one. I was paranoid that the one above was started too late or ended too early.

The device announcement happens at command number 33095, 290 seconds into the sniff

Koenkk commented 2 years ago

@robertalexa I'm only interested in what is send as a response to the end device timeout request when joining the device with your zzh, so just a screenshot like below is enough:

robertalexa commented 2 years ago

Hey @Koenkk

From production sniff

And production-longer (another switch, same model) This one however does not have an "End Device Timeout Response, Success" like above despite both devices relaying through 0x8FA9 which is https://www.zigbee2mqtt.io/devices/TS0204.html#cr%2520smart%2520home-ts0204

Koenkk commented 2 years ago

@robertalexa so if I understand correctly, even when and end device timeout response is send to the device, it still reannounces itself?

robertalexa commented 2 years ago

@Koenkk that is correct. But only this device model, all 5 of them that i own.

Notice how the payload is different in my production 0x03 vs 0x01 in your screenshot. Would this matter?

Also, do zigbee 1.2 router devices pass zigbee 3.0 functions along to the coordinator? Could this be the reason?

robertalexa commented 2 years ago

Also, should i flash my testing CC to zigbee 3 and see if the same happens, without routers?

Koenkk commented 2 years ago

Also, should i flash my testing CC to zigbee 3 and see if the same happens, without routers?

yes, worth a try

r-vit commented 2 years ago

I encountered the same problem, with the Zemismart device and the Moes one (TS0041 _TZ3000_axpdxqgu) - the batteries die pretty fast, the longest were about 2 months

r-vit commented 2 years ago

@robertalexa, have you been able to solve the issue? my batteries keep dying and I have no idea how to solve it. FWIW I don't think it's z2m's problem - sonoff zbbridge behaves the same

robertalexa commented 2 years ago

@r-vit Hey man, sorry but didn't get a chance to look into it further. Unfortunately some family issues.

This is still on my to do list for sure, so i do intend to continue investigating, but unfortunately i do not know when i will be able to come back with updates.

r-vit commented 2 years ago

@robertalexa thanks anyway! hope you'll get a chance to check it eventually

robertalexa commented 2 years ago

I have finally had to chance to pick this back up and spend some time on it.

Because a lot of time has passed, here is a new sniff from the Tuya Gateway. This will show, pairing, configuration and a button press. Using the official gateway the device does NOT re-announce every hour

tuya-gateway.zip

Also here is a new sniff on a CC2351 running 3.0.x. This will show pairing, configuration, 1h of no activity basically followed by a device announcement and rejoining, without any key presses.

cc2531-z30x.zip

Both networks contained just 1 coordinator and 1 device - switch. This shows that the issue is not created by router devices, and happens on both zigbee stacks 1.2 (expected - also seen in previous CC2351 testing) and 3.0 (zzh in my production but also CC2351 in this testing)

@Koenkk Any chance you can compare the 2 files and provide some support please?

PS: The test was running z2m 1.28.0. I have not included the custom changes you have suggested https://github.com/Koenkk/zigbee2mqtt/issues/8072#issuecomment-1015571807

MattWestb commented 2 years ago

Both sniffs / Zip files is the same cap file from the tuya ZBGW.

Sequence 35 = casting tuya magic. Sequence 68 = unknown command 0xf0 to clucter 0x0000 (basic).


IEEE 802.15.4 Data, Dst: 0xeaad, Src: 0x0000
ZigBee Network Layer Data, Dst: 0xeaad, Src: 0x0000
ZigBee Application Support Layer Data, Dst Endpt: 1, Src Endpt: 1
    Frame Control Field: Data (0x40)
        .... ..00 = Frame Type: Data (0x0)
        .... 00.. = Delivery Mode: Unicast (0x0)
        ..0. .... = Security: False
        .1.. .... = Acknowledgement Request: True
        0... .... = Extended Header: False
    Destination Endpoint: 1
    Cluster: Basic (0x0000)
    Profile: Home Automation (0x0104)
    Source Endpoint: 1
    Counter: 219
ZigBee Cluster Library Frame
    Frame Control Field: Cluster-specific (0x11)
        .... ..01 = Frame Type: Cluster-specific (0x1)
        .... .0.. = Manufacturer Specific: False
        .... 0... = Direction: Client to Server
        ...1 .... = Disable Default Response: True
    Sequence Number: 12
    Command: Unknown (0xf0)

Sequence 86, 90 and 99 = write unknown attribute 0xffde that i think is one part of tuya magic casting.

Then its one normal updating the TC-link key and verifying it OK and the device is requesting time from the coordinator and getting it and then tuya is closing the joining = finished.

robertalexa commented 2 years ago

@MattWestb Apologies for my mistake. I have now swapped the file for the correct one. If either you or Koen have any advice I would happily test it out. Thanks again for the help!

MattWestb commented 2 years ago

Very interesting sniffing !!!

The Zigbee 3 Sleeping end device is getting the network key OK. Then its requesting End Device Timeout Request from its parent router as Zigbee 3 SED shall doing (47 and 695) and its not getting any replay from the TI router (coordinator is one router with trust center) = not ZB3 compliant.

Then the ZB3 SED like updating its TC-Link key and requesting one node description of the coordinator (104 and 760) and getting replay (126 and 768)

ZigBee Network Layer Data, Dst: 0x781b, Src: 0x0000
ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
ZigBee Device Profile, Node Descriptor Response, Nwk Addr: 0x0000, Status: Success
    Sequence Number: 132
    Status: Success (0)
    Nwk Addr of Interest: 0x0000
    Node Descriptor
        .... .... .... .000 = Type: 0 (Coordinator)
        .... .... .... 0... = Complex Descriptor: False
        .... .... ...0 .... = User Descriptor: False
        .... 0... .... .... = 868MHz BPSK Band: False
        ..0. .... .... .... = 902MHz BPSK Band: False
        .1.. .... .... .... = 2.4GHz OQPSK Band: True
        0... .... .... .... = EU Sub-GHz FSK Band: False
        Capability Information: 0x8f
        Manufacturer Code: 0x0000
        Max Buffer Size: 80
        Max Incoming Transfer Size: 160
        Server Flags: 0x0001
            .... .... .... ...1 = Primary Trust Center: True
            .... .... .... ..0. = Backup Trust Center: False
            .... .... .... .0.. = Primary Binding Table Cache: False
            .... .... .... 0... = Backup Binding Table Cache: False
            .... .... ...0 .... = Primary Discovery Cache: False
            .... .... ..0. .... = Backup Discovery Cache: False
            .... .... .0.. .... = Network Manager: False
            0000 000. .... .... = Stack Compliance Revision: 0
        Max Outgoing Transfer Size: 160
        Descriptor Capability Field: 0x00
            .... ...0 = Extended Active Endpoint List Available: False
            .... ..0. = Extended Simple Descriptor List Available: False

The Stack Compliance Revision: 0 is saying the network is not ZigbeePRO = old Zigbee HA 1.0 or older so the device is not requesting updating its TC-link key.

So your network is not Zigbee 3 and is more then likely having problem with many device that cant using Zigbee 3 functionality and security. I dont knoing if its in the IT firmware or in the config of Z2M (i think its in the firmware then ZHA is also having large problem with the new TI coordinator).

Get the network working as one Zigbee 3 network so devices can updating TC-Link key and also getting end device timeout request working it shall working OK and perhaps casting the tuya magic spell on the device but that its not the core issue here is Zigbee HA 1.x formed network ala CC-253X.

robertalexa commented 2 years ago

Hi @MattWestb

Thanks for looking into this. I am not sure what the next steps are. Any ideas?

In the case of the testing sniff the CC2351 was flashed with coordinator 3.0.x firmware. But I am experiencing the same issue in my production setup which is running zzh coordinator zStack3x0

Would you like me to do a sniff of the same device getting paired in my production? But this will be super noizy because there are already 40 other devices in the network?

Thanks

MattWestb commented 2 years ago

@robertalexa I think its better wait and see wot @Koenkk is saying then i dont like user sending sniffing from production network with joining device = all can "extracting" your beloved network key.

Also hi is knowing if the zzh is doing the joining the same way and if its no you can do the sniffing later (hi can also do it self and comparing it with your tuya ZBGW sniff).

So for @Koenkk getting Zigbee3 joining working with updating TC-Link key and also End Device Timeout and i think it shall working OK with real Zigbee 3 devices.

Do you have some EZSP coordinator laying around ? If yes we have getting it working great with Zigbee 3 joining after little deep digging and some "code enchantments" for 2 weeks ago and is interesting if its doing joining OK on this device 2.

robertalexa commented 2 years ago

@MattWestb No unfortunately i don't. As to providing a sniff from production, meh, i don't mind. The chances of someone randomly on the internet finding me and wondering around my house sniffing my zigbee traffic is something i can live with 😄

Let's see if @Koenkk can help and what his suggestions are

Thank you again for spending time looking into this

Koenkk commented 1 year ago

The end device timeout request should indeed be answered. Can you provide a sniff of just pairing it with your CC2652R? (to confirm the end device timeout request is also not answered there)

robertalexa commented 1 year ago

@Koenkk

This is a very noisy sniff because of all device activity zzh.zip

Device in question: SiliconL_ff:fe:24:8c:72 (5c:02:72:ff:fe:24:8c:72) - 0x2fa3 key: 07:03:09:01:05:0F:0D:0B:04:02:00:06:0A:08:0E:0C

1732 Association Request 2256 Association Request 2277 Association Response Followed by communication with the device

The end device timeout request was successfully answered, but we have seen the same in my previous production sniffs. The device re-announced after an hour, same issue

PS: idk if this might be relevant, but the device refused to pair via any router nodes (allow pair all or allow pair on particular device). I had to get it close to the coordinator for it to accept pairing. Though i wouldn't say this might hold any reason. In my production setup I have 2 of these switches upstairs, away from coordinator but close to multiple routers and another 1 super close to the coordinator. All 3 devices present the issue

Koenkk commented 1 year ago

Then the end device timeout request is probably not the issue.

Once diff I found is that the TuYa gateway does not bind genPowerCfg and does not setup reporting for the batteryPercentageRemaining. Given that z2m does this with a max interval of 1 hour, and that the device announce happens after +- 1 hour maybe this is what causes the issue.

Can you use the following converter and re-pair the device after that? (such that the device is factory reset)

const fz = require('zigbee-herdsman-converters/converters/fromZigbee');
const tz = require('zigbee-herdsman-converters/converters/toZigbee');
const exposes = require('zigbee-herdsman-converters/lib/exposes');
const reporting = require('zigbee-herdsman-converters/lib/reporting');
const extend = require('zigbee-herdsman-converters/lib/extend');
const ota = require('zigbee-herdsman-converters/lib/ota');
const tuya = require('zigbee-herdsman-converters/lib/tuya');
const utils = require('zigbee-herdsman-converters/lib/utils');
const e = exposes.presets;
const ea = exposes.access;

const definition = {
    zigbeeModel: ['TS0041'],
    fingerprint: [{manufacturerName: '_TZ3000_tk3s5tyg'}],
    model: 'TS0041',
    vendor: 'TuYa',
    description: 'Wireless switch with 1 button',
    whiteLabel: [{vendor: 'Smart9', model: 'S9TSZGB'}, {vendor: 'Lonsonho', model: 'TS0041'}, {vendor: 'Benexmart', model: 'ZM-sui1'}],
    exposes: [e.battery(), e.action(['single', 'double', 'hold'])],
    fromZigbee: [fz.tuya_on_off_action, fz.battery],
    toZigbee: [],
    configure: async (device, coordinatorEndpoint, logger) => {
        const endpoint = device.getEndpoint(1);
        await endpoint.read('genBasic', [0x0004, 0x000, 0x0001, 0x0005, 0x0007, 0xfffe]);
        await endpoint.write('genBasic', {0xffde: {value: 0x13, type: 0x20}});

        // await reporting.bind(endpoint, coordinatorEndpoint, ['genPowerCfg']);
        // try {
        //     await reporting.batteryPercentageRemaining(endpoint);
        // } catch (error) {/* Fails for some: https://github.com/Koenkk/zigbee2mqtt/issues/6313 */}
    },
};

module.exports = definition;

MattWestb commented 1 year ago

The first try is failing then the router 0x8fa9 is not replaying with association response (bad router like OSRAM plungs).

The second is joining OK and doing end device time out request for 256 min and the router is acking it 0xe873 and also updating key is OK and its being flagged OK and acked from both side as good so full Zigbee 3 end device joining.

The device ts not paring direct with the coordinator its using the 0xe873 as parent.

Use this as filter if only like see traffic to and from the device in wireshark ((zbee_nwk.dst == 0x2fa3) ) || (zbee_nwk.src == 0x2fa3).

Is you sure the device was rejoining after one hours then its one beacon request in the end but its not possible see witch IEEE the sender is having in the 801154 protocol.

I think casting the tuya magic that is proposed can being the key then the device have OK joined the network.

Abut tuya devices is tuya normally doing nothing and they is reporting without binding and reporting configuration to its coordinator but most / all new device is needing zuya magic being casted then joining them (like LIDL power strip with updated firmware).

MattWestb commented 1 year ago

The first try is failing then the router 0x8fa9 is not replaying with association response (bad router like OSRAM plungs).

The second is joining OK and doing end device time out request for 256 min and the router is acking it 0xe873 and also updating key is OK and its being flagged OK and acked from both side as good so full Zigbee 3 end device joining.

The device ts not paring direct with the coordinator its using the 0xe873 as parent.

Use this as filter if only like see traffic to and from the device in wireshark ((zbee_nwk.dst == 0x2fa3) ) || (zbee_nwk.src == 0x2fa3).

Is you sure the device was rejoining after one hours then its one beacon request in the end but its not possible see witch IEEE the sender is having in the 801154 protocol.

I think casting the tuya magic that is proposed can being the key then the device have OK joined the network.

Abut tuya devices is tuya normally doing nothing and they is reporting without binding and reporting configuration to its coordinator but most / all new device is needing zuya magic being casted then joining them (like LIDL power strip with updated firmware).

robertalexa commented 1 year ago

@Koenkk Removing the battery reporting did the trick. I have left the device paired for more than 2 hours, and upon pressing the button the action was sent first time, without the device reannouncing and joining. So just adding the extra read and write as per your original suggestion is not enough.

With regards to the battery level, when initially paired the battery level was null, but after some minutes it showed as 100%. Historically I would always get 100% (sometimes 98 i guess depending on the battery) very early after the pairing process and the value never updated. But it is too early now to say how this will last/behave with the new changes.

Looking at quite a few issues here it appears that not only TS0041 (device in question) is affected by the exact behaviour (short battery life, needing to click twice for the action to happen, light flashing on the device at 1 hour interval) but also TS0042, TS0043 and TS0044 (basically 1 key, 2, 3 or 4 keys variants).

My suggestion is to remove the reporting from all 4, i know in a previous issue in 2021 you have wrapped it in a try catch, because some devices threw errors when configuring, but it feels like despite some devices accepting the configuring, it creates more harm than it resolves.

As a result, I have raised the following PR (no credits taken, just to save you some time Koen): https://github.com/Koenkk/zigbee-herdsman-converters/pull/4742

Thank you for your help with this Koen and @MattWestb

LE: The above was tested on my testing environment with the CC2351 3.0.x

I will now set an external converter in my production, re-pair all my switches and leave them running for a while, this way I can come back with more feedback if necessary before the next release of z2m. Behaviour and battery level indicator

MattWestb commented 1 year ago

You are more then welcome. The TS004F is automatically reporting battery the pressing button 2 (or its 3) and dont need reporting if the device is being used but i dont know how its have its default config in the firmware and reporting at all i not being used and not configured. Very likely new version of TS004X can have getting more functions and bugs from the TS004F that is one later product on the market.

I think you shall looking if you have one or more bad routers in your network then they shall normally not rejoining the network if not being re powered or the firmware have crashing.

Koenkk / zigbee2mqtt

Zemismart Wireless Wall Switch _TZ3000_tk3s5tyg Tuya TS0041 - Fast discharge + device announcements #8072

Debug info