zigbee2mqtt icon indicating copy to clipboard operation
zigbee2mqtt copied to clipboard

Published 20 hours ago • verified publisher icon Koenkk

IKEA Parasoll sensors going offline

Open stephenmahood opened this issue 9 months ago • 172 comments

What happened?

I've 14 IKEA Parasoll sensors connected to my zigbee network.

The sensors are going offline in Zigbee2MQTT after they should have checked in for the availability check.

My availability settings are set to advanced, 10 min timeout for active devices and 120 mins for passive.

The sensors all have new IKEA LADDA batteries which are the 1.2V type based on other known issues.

The same issue with going offline doesn't appear to happen with ZHA so the issue doesn't appear to be device related

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

1.37.0

Adapter firmware version

20221226

Adapter

SONFF Zigbee Dongle-P

Setup

Add-on within Home Assistant within Proxmox VM on Intel NUC

Debug log

log1.log

Example:

[2024-05-10 10:32:54] debug: z2m: Passive device 'Back Bedroom Right Window' was last seen '2.00' hours ago. [2024-05-10 10:32:54] debug: z2m: MQTT publish: topic 'zigbee2mqtt/Back Bedroom Right Window/availability', payload '{"state":"offline"}'

stephenmahood avatar May 10 '24 10:05 stephenmahood

I have two of them. One is working fine (for weeks/months), the other is going offline after a few hours (also after repairing).

JBS5 avatar May 13 '24 12:05 JBS5

I humbled across this issue and I just wanted to share my experience with the Parasoll Sensor - due to the same reasons with the new IKEA sensors I put in 1,2V batteries (IKEA Ladda and another brand) as well and my sensor dropped off after few minutes.. ironically I then put in cheap 1,5V discounter batteries (Tronic by Lidl) and my sensor is now running fine since 4 days.

Until today I only had this one Parasoll sensor, but I bought two additional Parasoll, where I put in same brand 1,5V as well - in case this experience changes with the other sensors I'll let you know.

I also have a similar setup:

Adapter SONFF Zigbee Dongle-P

Setup Add-on within Home Assistant within Proxmox VM on HP Laptop (which I recycled as server)

RollOfDeath avatar May 14 '24 20:05 RollOfDeath

Same issue here, with a large number of Parasoll sensors and a mix of Ikea Ladda and another brand rechargeables. The sensors connect fine, and they work fine for a few hours, but then they stop reporting into Z2M. For another few hours, they are still shown as Online in the Z2M web interface, but state changes aren't reflected anymore. After that, they eventually move to offline, and another day or so later, the battery is drained.

I went through all of them yesterday and they were working, now (~16 hours later) found a few already which aren't updating anymore. I have found a few sub-cases while doing that:

  • the sensor is still seemingly working (blinks when opening/closing the window), but the state isn't reflected in Z2M; either pressing the reset button, or removing and reinserting the battery brings it back into the network;
  • the sensor is completely dead (no reaction when opening/closing the window - battery likely drained); replacing the battery brings it back into the network;
  • on a few occasions, I have found the sensors with the led 'on' and not reacting to window opening/closing; I assume this is some form of error or signalling an impeding battery exhaustion; replacing the battery brings it back into the network. On all of the above, the situation is the same - once back into the network, they work for a few hours, then silently drop off.

The issue is quite universal, regardless of whether the sensors are connected to the coordinator or one of the routers in the network. There doesn't seem to be any relation to signal strength, location, frequency of usage or anything that I can think of. Other Zigbee devices in my network (including various other Ikea products) seem to be working fine.

I tried this with both drivers (ember and ezsp), and a few successive versions of Z2M, and of dongle firmware - same behaviour. I didn't test yet with a different software, but some reports online suggest that the issue only occurs with Z2M (they seem to work fine in ZHA), which would indicate an issue specific to Z2M.

I am not a Z2M expert, so not sure what logs are relevant and what not. Last time I enabled debug logging, I ended up with a machine freeze after a few hours, so I am a little cautious about doing that again. Happy to help with debugging, if someone can point me in the right direction.

9shearer avatar Jun 07 '24 07:06 9shearer

After upgrading the firmware of my Sonoff Zigbee USB Dongle Plus (P) coordinator to 20230507, both of my PARASOLL sensors are online and reporting fine, for a few weeks now.

Also using the LADDA rechargables.

JBS5 avatar Jun 07 '24 09:06 JBS5

I see a similiar issue with the PARASOLL sensors using LADDA rechargables. They get unavailable after approx. 2 weeks.

Running Sonoff ZBDongle-E with MultiPAN RCP firmware 4.3.1.

meiser79 avatar Jun 09 '24 05:06 meiser79

Dongle-E as well myself, various versions of the NCP firmware. I gave up for now, unless someone has some ideas for troubleshooting.

9shearer avatar Jun 09 '24 11:06 9shearer

I switched to NCP 7.4.2.0 FW and the ember driver. Let's see if this helps.

@9shearer Do you use the ezsp or ember driver?

meiser79 avatar Jun 15 '24 08:06 meiser79

@meiser79 I am facing the same issue on ember and on ezsp (both NCP). Is there a way to enable debug logging for one specific device? I went through the docs and I see ways to exclude devices, but given the size of my network, that would be a tad impractical.

9shearer avatar Jun 16 '24 08:06 9shearer

@Koenkk Hi, may we ask for some advice how we could troubleshoot this issue? Thanks a lot!

meiser79 avatar Jun 16 '24 17:06 meiser79

  • Does the same problem occur with the ember adapter? (not ezsp)
  • Scrolling through this issue, it seems that the batteries affect this, isnt this just a battery problem?

Koenkk avatar Jun 17 '24 08:06 Koenkk

After upgrading the firmware of my Sonoff Zigbee USB Dongle Plus (P) coordinator to 20230507, both of my PARASOLL sensors are online and reporting fine, for a few weeks now.

Also using the LADDA rechargables.

To add to the user reports: I am in the same situation of @JBS5 from the beginning of the addition of the 4 Parasoll sensors to my Zigbee network, and I haven't had any connectivity issues ever since (3 months at the time of writing).

I use a Sonoff ZB-Dongle-P with firmware Z-Stack_3.x.0_coordinator_20230507 and I used Ladda batteries for all of the 4 Parasolls - I charged those batteries with the IKEA charger, the Stenkol, before putting them inside the sensors. I started with version 1.36.0 of Zigbee2MQTT and I am currently running version 1.38.0

Procsiab avatar Jun 17 '24 08:06 Procsiab

  • Does the same problem occur with the ember adapter? (not ezsp)

Yes. Tested with both EZSP and Ember on 7.4.2.0 (and a couple of prior versions on EZSP), no change. If you have some suggestions for targeted logging, I am happy to re-power a few of the sensors (gave up on changing batteries on a daily basis - I do have quite a few of them) and pull data.

  • Scrolling through this issue, it seems that the batteries affect this, isnt this just a battery problem?

Not in my case. I have a bunch of Parasoll sensors running with a mix of power sources (Ikea Ladda and other generic brand rechargeables, generic one-time batteries). The behavior is always the same:

  • after ~2-3 days, the sensor first stops reporting changes, but continues showing as "online" (with whichever the last state was, i.e. open or closed) -- If I catch it quickly (typically within a day), a power cycle of the sensor (removing/reinserting the battery) brings it back into the network, and it reports state changes as before (until it drops off again)
  • after another day or two, the sensor drops completely off the network (shows as "unavailable"/"offline") -- If I don't catch it early, the battery eventually gets exhausted.

9shearer avatar Jun 17 '24 10:06 9shearer

Any suggestion regarding targeted logging, @Koenkk ? Setting a global debug and then excluding devices one by one isn't very effective in my case, as I have a lot of devices. In the meanwhile, I think we can also rule out the number of devices as a potential cause. I only had one Parasoll left active in the network, which worked for ~4-5 days and then went missing as well. It had a freshly loaded Ladda battery, and it is 1.5m from the nearest Zigbee router.

9shearer avatar Jun 20 '24 07:06 9shearer

This is probably not going to do anything, but it's worth a shot.

If you can run de dev/edge release, try binding the manuSpecificIkeaUnknown cluster to the coordinator. Screenshot 2024-06-20 at 10 44 57

sjorge avatar Jun 20 '24 08:06 sjorge

@sjorge I get below error when trying to bind manuSpecificIkeaUnknown to the cluster.

Error 2024-06-24 07:03:18z2m: Failed to bind cluster 'manuSpecificIkeaUnknown' from 'PARASOLL Bad' to 'Coordinator' (Error: Bind 0x048727fffeb82ce4/1 manuSpecificIkeaUnknown from '0xe0798dfffeeaed17/1' failed (Delivery failed for {"profileId":0,"clusterId":33,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":8}))

BTW, the LADDA battery lasts for one week in the PARASALL sensor.

meiser79 avatar Jun 24 '24 05:06 meiser79

Delivery failed for I've never seen that error before :| I wonder if it's similar to a timeout. Was de BADRING awake when you tried to bind?

sjorge avatar Jun 24 '24 05:06 sjorge

The PARASOLL sensor was at least shown as available. And I opened the window once to somehow wake it up.

meiser79 avatar Jun 24 '24 06:06 meiser79

Ive had the same issues and just been replacing the battery thinking it was dead (despite it reporting 100% in Z2M) and after changing the battery is back online. But again about 2 weeks or so and it doesn't show as unavailable or offline, just doesn't update to open or close

jonny190 avatar Jun 24 '24 13:06 jonny190

• 3 IKEA Parasoll Sensors running • Zigbee2Mqtt with Sonoff P • First failure: 4-8 weeks? (most active sensor) • Reinserting the same battery did not work - new battery worked • Measured voltage: 0,8V • Battery type: IKEA AAA Rechargeable

There's obviously something draining the batteries.

The device which failed had a battery state of 83%. My two others currently have a battery state of 83% and 86%. I'm giving them two more weeks before failing.

Is this an IKEA firmware bug, IKEA hardware bug, or a Zigbee2MQTT thing where it's somehow polling on and on and destroying the battery life?

atle85 avatar Jul 01 '24 11:07 atle85

• 3 IKEA Parasoll Sensors running • Zigbee2Mqtt with Sonoff P • First failure: 4-8 weeks? (most active sensor) • Reinserting the same battery did not work - new battery worked • Measured voltage: 0,8V • Battery type: IKEA AAA Rechargeable

There's obviously something draining the batteries.

The device which failed had a battery state of 81%. My two others currently have a battery state of 83%. I'm giving them two more weeks before failing.

Is this an IKEA firmware bug, IKEA hardware bug, or a Zigbee2MQTT thing where it's somehow polling on and on and destroying the battery life?

Are you thinking something like this issue? https://github.com/Koenkk/zigbee2mqtt/issues/14157

jonny190 avatar Jul 01 '24 11:07 jonny190

• 3 IKEA Parasoll Sensors running • Zigbee2Mqtt with Sonoff P • First failure: 4-8 weeks? (most active sensor) • Reinserting the same battery did not work - new battery worked • Measured voltage: 0,8V • Battery type: IKEA AAA Rechargeable There's obviously something draining the batteries. The device which failed had a battery state of 81%. My two others currently have a battery state of 83%. I'm giving them two more weeks before failing. Is this an IKEA firmware bug, IKEA hardware bug, or a Zigbee2MQTT thing where it's somehow polling on and on and destroying the battery life?

Are you thinking something like this issue? #14157

Tried the solution described there (disabling the PowerCfg report) - no effect. I replaced the rechargeables in 4 sensors, all close to each other (so presumably similar signal levels). Used 2x Ikea Ladda, 2x other brand, all fully charged upon installation. Now (less than 24h later), after I opened/closed all the 4 doors/windows 5 minutes ago, 3 of the sensors aren't working anymore, as follows:

  • 2 sensors (let's call them Sensor A and Sensor B) have a "last_seen" of 7-8h ago. Their LED still blinks when opening the door/window, but state (contact open/closed) isn't updated in Z2M. The last reported battery level is 90+ for both.
  • 1 sensor (let's call it Sensor C) has a "last_seen" of 1 minute ago (very recent). The LED still blinks when opening the door/window, but state (contact open/closed) isn't updated in Z2M. Battery level is 94%. There is something funny I noticed for this one - see next post.
  • 1 sensor (still) works normally (calling it Sensor D). The LED blinks when opening the door/window, state (contact is true/false) gets updated in Z2M as expected. Battery level is 97%. FWIW, I have a few (also Ikea) battery-operated switches, and they work perfectly fine - same batteries for weeks now.

9shearer avatar Jul 06 '24 09:07 9shearer

Here's the funny behaviour I noticed for Sensor C mentioned above, while pulling the states for this. When checking first in Z2M (State tab), it looked like this:

{
    "ac_status": false,
    "battery": 94,
    "battery_defect": false,
    "battery_low": false,
    "contact": true,
    "last_seen": "2024-07-06T09:39:46.149Z",
    "linkquality": 96,
    "restore_reports": false,
    "supervision_reports": false,
    "tamper": false,
    "test": false,
    "trouble": false,
    "update": {
        "installed_version": -1,
        "latest_version": -1,
        "state": "idle"
    },
    "update_available": null
}

In the Devices list, it was showing as "last seen" 'just now' or very recently. I went to test it again by opening the respective door/window, and I refreshed the tab where I had the state in Z2M. And this is where I noticed something funny: the "last_seen" entry in the state JSON changed A FEW TIMES in 'real time' - so basically "...09:39:46.149Z" was "09:39:45.xxxZ", then it became "09:39:45.yyyZ", then it became the value listed above and it stopped updating. Throughout all these quick changes, the "contact" value remained unchanged, even if I had opened the respective door/window, and the LED was blinking accordingly. ==> It seemed like the sensor was continuously talking to Z2M, but without sending the new state (door/window opened/closed)

Once the "last_seen" stopped updating, the state tab remained fixed at

{
    "ac_status": false,
    "battery": 94,
    "battery_defect": false,
    "battery_low": false,
    "contact": true,
    "last_seen": "2024-07-06T09:40:21.154Z",
    "linkquality": 96,
    "restore_reports": false,
    "supervision_reports": false,
    "tamper": false,
    "test": false,
    "trouble": false,
    "update": {
        "state": "idle"
    }
}

The "contact" didn't update at all throughout the changes (it stayed 'true', i.e. door/window closed), even if I opened it multiple times and watched the State tab in Z2M in real time - no change whatsoever with regard to the contact tab, but the displayed JSON fluctuated between the two formats above (basically update... -1 and update... idle), and the last_seen value did get updated.

I went to repeat the experiment once more (same sensor, same approach) and now I am even more puzzled. The sensor continued the behaviour described above, but this time the "contact" in Z2M got updated once to "false" (i.e. door/window open) and it stayed like that. No matter if I opened it several times more, it still displayed "false".

I am really confused how this can happen:

  • some parts of the JSON getting updated, others not, in a seemingly random fashion
  • the state not getting reflected, even if the sensor is physically working (as attested by the blinking LED upon opening/closing, and the erratic update of the states)

My coordinator is a ZB-Dongle-E, with firmware 7.4.2.0 (flashed with the web flasher from darkxst), on Z2M 1.39.0, driver Ember. I have tens of other devices in the same network which seem to be working just fine.

9shearer avatar Jul 06 '24 10:07 9shearer

OK a bit more info. I decided to watch the other sensor that was still working (Sensor D), and it now behaves the same as Sensor C. The "last seen" gets updated several times in quick succession every ~17 seconds (not a scientific measurement), but the open/closed state doesn't get updated anymore. This sensor was working half an hour ago, so I guess it has now also "gone off" and will soon exhaust the battery.

The battery level of Sensor D went from 97% to 86% in approximately 45 minutes. This was plugged in with a freshly-loaded rechargeable less than 24 hours ago. Up until now, it was working perfectly fine (open/close states were reflected correctly in Z2M).

9shearer avatar Jul 06 '24 10:07 9shearer

Further experimentation - Sensor A was offline for several hours, LED blinking when door/window was opened/closed, but no updates at all in Z2M (neither contact, neither last_seen, marked as "offline" in the device list).

Pressing the reset button once - no change.

Removing and reinserting the battery - sensor back to normal. Contact state is updated and reflected in Z2M, last_seen is current, no rapid updates of last_seen, battery level is 90% (same as it was when it had gone off the network).

Sensors C and D - which had gone into the "rapid update every ~17 seconds, but no state changes" mode: just noticed their LED had become permanently 'on'. The same "rapid updates" were still happening, but this time the LED wasn't blinking anymore when opening/closing the door/window. Removing and reinserting the battery brought them back to normal behaviour (no rapid last_seen updates, proper reporting of the state in Z2M).

My empiric guess of the state changes is:

  1. Sensor works normally for a few hours
  2. At some point, it stops reporting state changes (open/closed) to Z2M, even if its LED still works as expected (blinking on open/close)
  3. The last_seen starts to update rapidly (several times within a second), every ~17 seconds;
  4. The sensor eventually becomes offline in Z2M
  5. If left unattended, it will at some point exhaust the battery. If the battery is removed/reinserted, it goes back to normal behaviour. I am not sure (and don't have any efficient means of testing) if states 2 and 3 occur at the same moment.

@Koenkk or anyone else, any ideas? Happy to do any specific troubleshooting / logging with a bit of guidance.

9shearer avatar Jul 06 '24 10:07 9shearer

@9shearer could you provide the debug logging of a "everything works situation" till step 3?

Koenkk avatar Jul 06 '24 10:07 Koenkk

@Koenkk gladly. Is there a way to enable debug logging for only one / a few devices?

I have tens of Zigbee devices (most of them working fine) and enabling debug logging globally doesn't work (tried once and it killed the machine where Z2M is installed). Conversely, excluding devices one by one (I believe that's what's described in the docs) is pretty cumbersome - might go down that path if there is no other way.

9shearer avatar Jul 06 '24 11:07 9shearer

I gave it a shot and enabled debug logging globally last night. I think we might be on to something, as despite the log files not catching the whole interval, I think they did manage to catch the interval when one of the sensors went from "all good" into "rapid fire updates every 17 seconds" behavior (so basically the transition from steps 1 to 2 (or 2 to 3).

Check this out (output of "grep 0x..." from the log file directory with the address of the problem_sensor_C).

Good behaviour (presumably):

log2.log:[2024-07-07 06:04:57] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=5246]
log2.log:[2024-07-07 06:13:29] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=5246]
log2.log:[2024-07-07 06:44:06] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=5246]
log1.log:[2024-07-07 07:03:11] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=5246]
log1.log:[2024-07-07 07:24:59] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=5246]
log1.log:[2024-07-07 08:01:25] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=5246]

While I am wondering about the timing (it seems to check in randomly), I would be happy with it working.

Bad behaviour ("updates" every 17 seconds, but nothing seen in the frontend):

log1.log:[2024-07-07 08:16:03] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:03] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:03] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:03] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:03] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:03] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:03] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:03] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:21] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=54147]
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=54147]
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:21] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:21] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:22] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:22] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:22] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:22] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:22] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:23] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:23] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:23] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:23] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:23] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:23] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:23] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:23] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:23] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:23] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:40] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:40] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:40] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:40] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:40] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:40] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:40] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:40] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:41] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:41] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:41] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:41] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:41] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:42] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:42] debug:   zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=24132], [sourceEui=0x059731fffe23ac1f], [lastHopLqi=92], [lastHopRssi=-77], [relayCount=2], [relayList=62431,21066]
log1.log:[2024-07-07 08:16:42] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:42] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:42] debug:   zh:ember:ezsp: ezspIncomingSenderEui64Handler(): callback called with: [senderEui64=0x059731fffe23ac1f]
log1.log:[2024-07-07 08:16:42] debug:   zh:ember:ezsp: <=== [ZDO END_DEVICE_ANNOUNCE nodeId=24132 eui64=0x059731fffe23ac1f capabilities=10000000]
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device announce '0x059731fffe23ac1f'
log1.log:[2024-07-07 08:16:42] info:    z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"problem_sensor_C","ieee_address":"0x059731fffe23ac1f"},"type":"device_announce"}'
log1.log:[2024-07-07 08:16:42] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:42] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'
log1.log:[2024-07-07 08:16:43] debug:   zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=24132], [newNodeEui64=0x059731fffe23ac1f], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=62431]
log1.log:[2024-07-07 08:16:43] debug:   zh:controller: Device '0x059731fffe23ac1f' joined
log1.log:[2024-07-07 08:16:43] debug:   zh:controller: Device '0x059731fffe23ac1f' accepted by handler
log1.log:[2024-07-07 08:16:43] debug:   zh:controller: Not interviewing '0x059731fffe23ac1f', completed 'true', in progress 'false'

9shearer avatar Jul 07 '24 08:07 9shearer

@Koenkk I hope the above helps. With my little knowledge, I guess the issue occurs when the "check-in method" switches from ezspIncomingRouteRecordHandler to ezspTrustCenterJoinHandler (no idea why/how that works). And despite nothing changing (IEEE address, node ID etc) and the ezspTrustCenterJoinHandler seemingly working (device... joined, device ... accepted, not interviewing...), this seems to go into a loop. Which, if left alone for long enough, will kill the battery. I further guess the battery removal (if done before the battery gets exhausted) breaks this infinite loop, which puts the device back into the "good" state - until whatever causes the switch mentioned above happens again, and then it goes into the loop, and so on.

9shearer avatar Jul 07 '24 08:07 9shearer

Did a little research in the meanwhile and the issue seems superficially similar to 22611. Quote from that thread:

When I push button, last seen is refresh in Z2M but no action is received and so on, send to MQTT....

And the same calls to ezspTrustCenterJoinHandler() for the misbehaving device, although it does seem that in the other thread, this is a permanent rather than temporary situation (the devices there don't work at all, while my Ikea Parasolls work for some time, until they don't).

9shearer avatar Jul 07 '24 10:07 9shearer

Just want to chime in that I see the exact same issue as @9shearer.

  1. Sensor works normally for a few hours
  2. At some point, it stops reporting state changes (open/closed) to Z2M, even if its LED still works as expected (blinking on open/close)
  3. The last_seen starts to update rapidly (several times within a second), every ~17 seconds;
  4. The sensor eventually becomes offline in Z2M
  5. If left unattended, it will at some point exhaust the battery. If the battery is removed/reinserted, it goes back to normal behaviour.
  6. I am not sure (and don't have any efficient means of testing) if states 2 and 3 occur at the same moment.

Just catched one at step 2 and reinserted the battery to get it going again. Battery went from 66% to 37% in a matter of 2.5h.

lorenzspenger avatar Jul 09 '24 10:07 lorenzspenger