Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Zigpy Zigate Wifi - Close connection to ZHA #89

Open
baimard opened this issue May 16, 2021 · 71 comments
Open

Zigpy Zigate Wifi - Close connection to ZHA #89

baimard opened this issue May 16, 2021 · 71 comments

Comments

@baimard
Copy link

baimard commented May 16, 2021

Dear,

Home Assistant : 2021.5.4
ZHA : Last version in HASS
ZiGate-WiFi v2.00 with esp-link v3.2.50-gfe4f565-dirty

I use Zigate wifi with ZHA in Home Assistant, after random time (30 min to 4hours), Home Assistant show that :

Logger: zigpy_zigate.api
Source: /usr/local/lib/python3.8/site-packages/zigpy_zigate/api.py:138
First occurred: 19:46:24 (20 occurrences)
Last logged: 19:47:26

No response to command 0x0530
----
Logger: asyncio
Source: /usr/local/lib/python3.8/asyncio/selector_events.py:903
First occurred: 19:46:54 (16 occurrences)
Last logged: 19:47:25

socket.send() raised exception.

After this message, all my sensor light etc. not work with the device.

Home assistant don't send any request to my zigate wifi.

Tcpdump :
192.168.4.252 si my HASS
192.168.4.227 Zigate Wifi

19:22:09.071920 ARP, Request who-has 192.168.4.227 tell 192.168.4.252, length 46
19:22:09.073167 ARP, Reply 192.168.4.227 is-at 3c:61:05:d1:1f:d6, length 46
19:25:59.740061 IP 192.168.4.227.9999 > 192.168.4.252.54258: Flags [P.], seq 2250:2330, ack 860, win 1824, length 80
19:25:59.740679 IP 192.168.4.252.54258 > 192.168.4.227.9999: Flags [.], ack 2330, win 64068, length 0
19:25:59.741956 IP 192.168.4.227.9999 > 192.168.4.252.54258: Flags [P.], seq 2330:2340, ack 860, win 1824, length 10
19:25:59.743470 IP 192.168.4.252.54258 > 192.168.4.227.9999: Flags [.], ack 2340, win 64068, length 0
19:26:04.848226 ARP, Request who-has 192.168.4.227 tell 192.168.4.252, length 46
19:26:04.850873 ARP, Reply 192.168.4.227 is-at 3c:61:05:d1:1f:d6, length 46
19:30:59.877528 IP 192.168.4.227.9999 > 192.168.4.252.54258: Flags [F.], seq 2340, ack 860, win 1824, length 0
19:30:59.879422 IP 192.168.4.252.54258 > 192.168.4.227.9999: Flags [F.], seq 860, ack 2341, win 64068, length 0
19:30:59.880991 IP 192.168.4.227.9999 > 192.168.4.252.54258: Flags [.], ack 861, win 1823, length 0
19:31:05.139535 ARP, Request who-has 192.168.4.227 tell 192.168.4.252, length 46
19:31:05.141093 ARP, Reply 192.168.4.227 is-at 3c:61:05:d1:1f:d6, length 46
19:37:21.514434 ARP, Request who-has 192.168.4.227 tell 192.168.4.1, length 46

So two questions :

  • Why zigate Wifi close the connection ?
  • Is it possible to make ZHA restart the connection ?

Thank you

@totof129
Copy link

Hi,

your bug seems to be similar to issue #55
Did you upgrade Zigate's firmware ?
A new release (3.1e) has just been delivered

@baimard
Copy link
Author

baimard commented May 17, 2021

Do you know how I could watch my firmware version of zigate ?

@totof129
Copy link

you should be able to see it in the visualization tab in ZHA configuation

@baimard
Copy link
Author

baimard commented May 17, 2021

3.1d for me, new question ... where is the last firmware ...

@totof129
Copy link

@baimard
Copy link
Author

baimard commented May 17, 2021

Merci beaucoup !

Je vais essayer voir si ça corrige.

@baimard
Copy link
Author

baimard commented May 18, 2021

another bug :

home_assistant.1.mag30mglug26@x-kaki    | 2021-05-18 22:55:43 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8012
home_assistant.1.mag30mglug26@x-kaki    | 2021-05-18 22:55:43 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8012
home_assistant.1.mag30mglug26@x-kaki    | 2021-05-18 22:55:44 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8012
home_assistant.1.mag30mglug26@x-kaki    | 2021-05-18 22:55:44 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8012
home_assistant.1.mag30mglug26@x-kaki    | 2021-05-18 22:55:44 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8012
home_assistant.1.mag30mglug26@x-kaki    | 2021-05-18 22:55:44 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8012

Always same deconnection ...

home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:57 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=light.beta_level_on_off>
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:57 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x5231, 260, 6, 1, 1, 18, b'\x01\x12\x00', True, False)
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:57 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'025231010100060104000003011200'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:57 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0fH\x02R1\x01\x01\x00\x06\x01\x04\x00\x00\x03\x01\x12\x00'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:57 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1fH\x02\x12R1\x02\x11\x02\x11\x02\x10\x02\x16\x02\x11\x02\x14\x02\x10\x02\x10\x02\x13\x02\x11\x12\x02\x10'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:58 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:58 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:58 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'025231010100060104000003011200'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:58 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0fH\x02R1\x01\x01\x00\x06\x01\x04\x00\x00\x03\x01\x12\x00'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:25:58 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1fH\x02\x12R1\x02\x11\x02\x11\x02\x10\x02\x16\x02\x11\x02\x14\x02\x10\x02\x10\x02\x13\x02\x11\x12\x02\x10'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:26:00 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:26:00 DEBUG (MainThread) [zigpy.device] [0x5231] Delivery error for seq # 0x12, on endpoint id 1 cluster 0x0006: ZiGate doesn't answer to command
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:26:00 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5231:1:0x0006]: command failed: 'off' args: '()' kwargs '{}' exception: '[0x5231:1:0x0006]: Message send failure'
home_assistant.1.k28tajqju8bv@x-kaki    | 2021-05-18 23:26:00 DEBUG (MainThread) [homeassistant.components.zha.entity] light.beta_level_on_off: turned off: [0x5231:1:0x0006]: Message send failure

There is a really big problem, I can't identify what happend. I can do every debug you want, to try to solve this issue !

Could you please take this problem in consideration ?

home-assistant/core#43962

@letroll
Copy link

letroll commented Jun 14, 2021

Same here, I can also help with debug if you need information

@tygerlord
Copy link

I use firmware 3.1e
Yesterday all is working. This morning: devices Offlines

@Alindil
Copy link

Alindil commented Jun 14, 2021

Hi,
I have the same problem.
There is a query that is disconnected and no longer makes the plugin work. A little try catch would at least prevent the plugin from crashing

@tygerlord
Copy link

tygerlord commented Jun 14, 2021

2021-06-13 21:04:43 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530                                                               ┤
│2021-06-13 21:04:43 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530                                                                        ┤
│2021-06-13 21:04:43 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02a6e10101000001040000050057000400'                                           ┤
│2021-06-13 21:04:43 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x112\x02\xa6\xe1\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00W\x00\x04\┤
│2021-06-13 21:04:43 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x112\x02\x12\xa6\xe1\x02\x11\x02\x11\x02\x10\x02\x10\x02\x┤
│2021-06-13 21:04:44 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530                                                               ┤
│2021-06-13 21:04:44 DEBUG (MainThread) [zigpy.device] [0xa6e1] Delivery error for seq # 0x57, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command│

And after nothing

@ZeGuigui
Copy link

I just performed a test against the code in the dev branch which is supposed to implement the reconnect feature.

2021-06-14 14:51:37 DEBUG (MainThread) [zigpy_zigate.uart] Closed serial connection

but no reconnection attempt was made by the lib. I had to force integration reload to have the connection back:

2021-06-14 14:55:06 DEBUG (MainThread) [zigpy_zigate.uart] Connection made

@ZeGuigui
Copy link

I added some debug code into the lib, just to be sure.

    def connection_lost(self, exc) -> None:
        """Port was closed expecteddly or unexpectedly."""
        if self._connected_future and not self._connected_future.done():
            if exc is None:
                LOGGER.info("Connection lost - no exception");
                self._connected_future.set_result(True)
            else:
                LOGGER.info("Connection lost with exception %s", exc);
                self._connected_future.set_exception(exc)
        if exc is None:
            LOGGER.debug("Closed serial connection")
            return

        LOGGER.error("Lost serial connection: %s", exc)
        self._api.connection_lost(exc)

The "connection lost" messages I added are never called when we hit a disconnect. We might need to examine zigpy implementation in details to understand if this code (which is common to xbee, combee...) do work with other devices or if there is just a duplicated bug. Connection lost with USB devices is probably a rare issue

@tygerlord
Copy link

Like it seems to come after 'No response to command 0x0530', that is to say, a 'hardware' crash, this is probably common to xbee, combee and other but they don't crash so we don't see the same trouble.

I think we are dealing with 2 bugs. To check.

@baimard
Copy link
Author

baimard commented Jun 16, 2021

Like it seems to come after 'No response to command 0x0530', that is to say, a 'hardware' crash, this is probably common to xbee, combee and other but they don't crash so we don't see the same trouble.

I think we are dealing with 2 bugs. To check.

For me it's a global connection problem. After a delay, connection crash and we have lot of errors.

Depending on the command that we send we have a different return. But the basic problem is the connection

@pipiche38
Copy link

My 2 cents, don't know if this is related, but in Wifi, the plugin needs to maintain the IP connection, otherwise after a Timeout ( 4 or 5 minutes) the line is droped

@baimard
Copy link
Author

baimard commented Jun 16, 2021

is it possible to add simply a "ping" or other every 30s to maintain the connection ?

@tygerlord
Copy link

Like it seems to come after 'No response to command 0x0530', that is to say, a 'hardware' crash, this is probably common to xbee, combee and other but they don't crash so we don't see the same trouble.
I think we are dealing with 2 bugs. To check.

For me it's a global connection problem. After a delay, connection crash and we have lot of errors.

Depending on the command that we send we have a different return. But the basic problem is the connection

Do other Zigbee radio modules have the same troubles ?

@baimard
Copy link
Author

baimard commented Jun 16, 2021

Like it seems to come after 'No response to command 0x0530', that is to say, a 'hardware' crash, this is probably common to xbee, combee and other but they don't crash so we don't see the same trouble.
I think we are dealing with 2 bugs. To check.

For me it's a global connection problem. After a delay, connection crash and we have lot of errors.
Depending on the command that we send we have a different return. But the basic problem is the connection

Do other Zigbee radio modules have the same troubles ?

that a very good question, with the title of this issue I don't know if other product owner read this thread

@ZeGuigui
Copy link

Most other zigbee radio modules are USB modules

@letroll
Copy link

letroll commented Jun 16, 2021

I can confirm I'm affected with zigate on usb. For now I have rollback to HASS version 2021.3.0 (docker install)

@MattWestb
Copy link

deCONZ radios have much problems with USB disconnections and comports is not mapped OK in docker (in native deCONZ and ZHA).

Tasmota, and ESPHome that using ESP chips looks working OK with EFR32 and TI chips also tuya ZBGW is working OK with EFR32 radios over Ethernet.

EFR32 / bellows is going in fault state if the counter is going of sync then loosing packages in the WiFi / Eth network but is nicely logged in the error log.

@tygerlord
Copy link

I can confirm I'm affected with zigate on usb. For now I have rollback to HASS version 2021.3.0 (docker install)

Interesting, can you confirm that you don't use any wifi between zigate/usb and your home assistant ?

@letroll
Copy link

letroll commented Jun 16, 2021

I confirm. I'm using Hass with docker on a NUC running archlinux. I don't know if it can influence but my USB Zigate is on a USB hub. I can try without tonight if you want?

@tygerlord
Copy link

I confirm. I'm using Hass with docker on a NUC running archlinux. I don't know if it can influence but my USB Zigate is on a USB hub. I can try without tonight if you want?

Thank you, I don't think that it's necessary. The main point is that wifi seem not be the cause. As far as I'm remember when I put my PiZigate directly on my raspberry pi3, I already have 'Devices Offline' disconnects on my zigbee2mqtt, so this seems to exonerate wifi

@tygerlord
Copy link

is it possible to add simply a "ping" or other every 30s to maintain the connection ?

I need to check logs, but I think that plugin already ask periodically for state of sensors...

@tygerlord
Copy link

2021-06-13 21:04:43 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530                                                               ┤
│2021-06-13 21:04:43 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530                                                                        ┤
│2021-06-13 21:04:43 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02a6e10101000001040000050057000400'                                           ┤
│2021-06-13 21:04:43 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x112\x02\xa6\xe1\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00W\x00\x04\┤
│2021-06-13 21:04:43 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x112\x02\x12\xa6\xe1\x02\x11\x02\x11\x02\x10\x02\x10\x02\x┤
│2021-06-13 21:04:44 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530                                                               ┤
│2021-06-13 21:04:44 DEBUG (MainThread) [zigpy.device] [0xa6e1] Delivery error for seq # 0x57, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command│

And after nothing

To my mind, after Retry command, if module don't answer again then we should initialize connection like we do on start. What do you think about?

@tygerlord
Copy link

Citation de pipiche le 16 juin 2021, 15 h 27 min
Domoticz ping régulièrement la ZiGate (si il n'y a pas eu de communication In et Out depuis un laps de temps)
Si on ne reçoit pas de réponse au ping, on va insister
Si malgré les retry pas de réponse, alors le plugin est relancé avec un restart de la ZiGate

This seems a good process.

@baimard
Copy link
Author

baimard commented Nov 16, 2021

so I do that simply ...

    async def connect(self):
        assert self._uart is None
        self._uart = await zigpy_zigate.uart.connect(self._config, self)
        self._thread = threading.Thread(target=self.loop_check_connection) #89
        self._thread.start() #89
    def loop_check_connection(self):
        while True:
            time.sleep(300)
            LOGGER.warning("Check ---")
            try:
                asyncio.run(self.get_network_state())
            except:
                LOGGER.warning("thread error") #Because of concurrent access

I have no more error ... :

logs

home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:20:18 WARNING (Thread-4) [zigpy_zigate.api] Check ---
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:20:18 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:20:18 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:21:50 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received
home_assistant.1.01xbc0atho3i@ocre    | 2021-11-16 10:23:02 WARNING (MainThread) [zigpy_zigate.api] data_received

Entyre file :
api.py

import asyncio
import binascii
import functools
import logging
import enum
import datetime
from typing import Any, Dict

import serial
import zigpy.exceptions

import zigpy_zigate.config
import zigpy_zigate.uart

from . import types as t

import time
import threading

LOGGER = logging.getLogger(__name__)

COMMAND_TIMEOUT = 1.5
PROBE_TIMEOUT = 3.0

RESPONSES = {
    0x004D: (t.NWK, t.EUI64, t.uint8_t, t.uint8_t),
    0x8000: (t.uint8_t, t.uint8_t, t.uint16_t, t.Bytes),
    0x8002: (t.uint8_t, t.uint16_t, t.uint16_t, t.uint8_t, t.uint8_t,
             t.Address, t.Address, t.Bytes),
    0x8009: (t.NWK, t.EUI64, t.uint16_t, t.uint64_t, t.uint8_t),
    0x8010: (t.uint16_t, t.uint16_t),
    0x8011: (t.uint8_t, t.NWK, t.uint8_t, t.uint16_t, t.uint8_t),
    0x8012: (t.uint32_t,),
    0x8017: (t.uint32_t,),
    0x8024: (t.uint8_t, t.NWK, t.EUI64, t.uint8_t),
    0x8035: (t.uint8_t, t.uint32_t),
    0x8048: (t.EUI64, t.uint8_t),
    0x8701: (t.uint8_t, t.uint8_t),
    0x8702: (t.uint8_t, t.uint8_t, t.uint8_t, t.Address, t.uint8_t),
    0x8806: (t.uint8_t,),
}

COMMANDS = {
    0x0002: (t.uint8_t,),
    0x0016: (t.uint32_t,),
    0x0018: (t.uint8_t,),
    0x0019: (t.uint8_t,),
    0x0020: (t.uint64_t,),
    0x0021: (t.uint32_t,),
    0x0026: (t.EUI64, t.EUI64),
    0x0049: (t.NWK, t.uint8_t, t.uint8_t),
    0x0530: (t.uint8_t, t.NWK, t.uint8_t, t.uint8_t, t.uint16_t, t.uint16_t, t.uint8_t, t.uint8_t, t.LBytes),
    0x0806: (t.uint8_t,),
}


class AutoEnum(enum.IntEnum):
    def _generate_next_value_(name, start, count, last_values):
        return count


class PDM_EVENT(AutoEnum):
    E_PDM_SYSTEM_EVENT_WEAR_COUNT_TRIGGER_VALUE_REACHED = enum.auto()
    E_PDM_SYSTEM_EVENT_DESCRIPTOR_SAVE_FAILED = enum.auto()
    E_PDM_SYSTEM_EVENT_PDM_NOT_ENOUGH_SPACE = enum.auto()
    E_PDM_SYSTEM_EVENT_LARGEST_RECORD_FULL_SAVE_NO_LONGER_POSSIBLE = enum.auto()
    E_PDM_SYSTEM_EVENT_SEGMENT_DATA_CHECKSUM_FAIL = enum.auto()
    E_PDM_SYSTEM_EVENT_SEGMENT_SAVE_OK = enum.auto()
    E_PDM_SYSTEM_EVENT_EEPROM_SEGMENT_HEADER_REPAIRED = enum.auto()
    E_PDM_SYSTEM_EVENT_SYSTEM_INTERNAL_BUFFER_WEAR_COUNT_SWAP = enum.auto()
    E_PDM_SYSTEM_EVENT_SYSTEM_DUPLICATE_FILE_SEGMENT_DETECTED = enum.auto()
    E_PDM_SYSTEM_EVENT_SYSTEM_ERROR = enum.auto()
    E_PDM_SYSTEM_EVENT_SEGMENT_PREWRITE = enum.auto()
    E_PDM_SYSTEM_EVENT_SEGMENT_POSTWRITE = enum.auto()
    E_PDM_SYSTEM_EVENT_SEQUENCE_DUPLICATE_DETECTED = enum.auto()
    E_PDM_SYSTEM_EVENT_SEQUENCE_VERIFY_FAIL = enum.auto()
    E_PDM_SYSTEM_EVENT_PDM_SMART_SAVE = enum.auto()
    E_PDM_SYSTEM_EVENT_PDM_FULL_SAVE = enum.auto()


class NoResponseError(zigpy.exceptions.APIException):
    pass

class ZiGate:
    def __init__(self, device_config: Dict[str, Any]):
        self._app = None
        self._config = device_config
        self._uart = None
        self._awaiting = {}
        self._status_awaiting = {}
        self._lock = asyncio.Lock()
        self.network_state = None

    @classmethod
    async def new(cls, config: Dict[str, Any], application=None) -> "ZiGate":
        api = cls(config)
        await api.connect()
        api.set_application(application)
        return api

    async def connect(self):
        assert self._uart is None
        self._uart = await zigpy_zigate.uart.connect(self._config, self)
        self._thread = threading.Thread(target=self.loop_check_connection)
        self._thread.start()

    def loop_check_connection(self):
        while True:
            time.sleep(300)
            LOGGER.warning("Check ---")
            try:
                asyncio.run(self.get_network_state())
            except:
                LOGGER.warning("thread error")

    def close(self):
        if self._uart:
            self._uart.close()
            self._uart = None

    def set_application(self, app):
        self._app = app

    def data_received(self, cmd, data, lqi):
        #LOGGER.warning("data_received")
        LOGGER.warning("data received %s %s LQI:%s", hex(cmd),
                     binascii.hexlify(data), lqi)
        if cmd not in RESPONSES:
            LOGGER.error('Received unhandled response 0x%04x', cmd)
            return
        data, rest = t.deserialize(data, RESPONSES[cmd])
        if cmd == 0x8000:
            if data[2] in self._status_awaiting:
                fut = self._status_awaiting.pop(data[2])
                fut.set_result((data, lqi))
        if cmd in self._awaiting:
            fut = self._awaiting.pop(cmd)
            fut.set_result((data, lqi))
        self.handle_callback(cmd, data, lqi)

    async def command(self, cmd, data=b'', wait_response=None, wait_status=True):
        tries = 2
        while tries > 0:
            tries -= 1
            await self._lock.acquire()
            try:
                return await asyncio.wait_for(
                    self._command(cmd, data, wait_response, wait_status),
                    timeout=COMMAND_TIMEOUT
                )
            except asyncio.TimeoutError:
                LOGGER.warning("No response to command 0x%04x", cmd)
                if tries > 0:
                    LOGGER.warning("Retry command 0x%04x", cmd)
                    LOGGER.warning("Close uart")
                    self.close()
                    LOGGER.warning("connect uart")
                    await self.connect()
                else:
                    raise NoResponseError
            finally:
                self._lock.release()

    def _command(self, cmd, data=b'', wait_response=None, wait_status=True):
        self.lock = True
        self._uart.send(cmd, data)
        if wait_status:
            fut = asyncio.Future()
            self._status_awaiting[cmd] = fut

        if wait_response:
            fut = asyncio.Future()
            self._awaiting[wait_response] = fut
        self.lock = False
        if wait_status or wait_response:
            return fut

    async def version(self):
        return await self.command(0x0010, wait_response=0x8010)

    async def version_str(self):
        version, lqi = await self.version()
        version = '{:x}'.format(version[1])
        version = '{}.{}'.format(version[0], version[1:])
        return version

    async def get_network_state(self):
        return await self.command(0x0009, wait_response=0x8009)

    async def set_raw_mode(self, enable=True):
        data = t.serialize([enable], COMMANDS[0x0002])
        await self.command(0x0002, data)

    async def reset(self):
        self._command(0x0011, wait_status=False)

    async def erase_persistent_data(self):
        self._command(0x0012, wait_status=False)

    async def set_time(self, dt=None):
        """ set internal time
        if timestamp is None, now is used
        """
        dt = dt or datetime.datetime.now()
        timestamp = int((dt - datetime.datetime(2000, 1, 1)).total_seconds())
        data = t.serialize([timestamp], COMMANDS[0x0016])
        self._command(0x0016, data)

    async def get_time_server(self):
        timestamp, lqi = await self._command(0x0017, wait_response=0x8017)
        dt = datetime.datetime(2000, 1, 1) + datetime.timedelta(seconds=timestamp[0])
        return dt

    async def set_led(self, enable=True):
        data = t.serialize([enable], COMMANDS[0x0018])
        await self.command(0x0018, data)

    async def set_certification(self, typ='CE'):
        cert = {'CE': 1, 'FCC': 2}[typ]
        data = t.serialize([cert], COMMANDS[0x0019])
        await self.command(0x0019, data)

    async def set_tx_power(self, power=63):
        if power > 63:
            power = 63
        if power < 0:
            power = 0
        data = t.serialize([power], COMMANDS[0x0806])
        power, lqi = await self.command(0x0806, data, wait_response=0x8806)
        return power[0]

    async def set_channel(self, channels=None):
        channels = channels or [11, 14, 15, 19, 20, 24, 25, 26]
        if not isinstance(channels, list):
            channels = [channels]
        mask = functools.reduce(lambda acc, x: acc ^ 2 ** x, channels, 0)
        data = t.serialize([mask], COMMANDS[0x0021])
        await self.command(0x0021, data),

    async def set_extended_panid(self, extended_pan_id):
        data = t.serialize([extended_pan_id], COMMANDS[0x0020])
        await self.command(0x0020, data)

    async def permit_join(self, duration=60):
        data = t.serialize([0xfffc, duration, 0], COMMANDS[0x0049])
        return await self.command(0x0049, data)

    async def start_network(self):
        return await self.command(0x0024, wait_response=0x8024)

    async def remove_device(self, zigate_ieee, ieee):
        data = t.serialize([zigate_ieee, ieee], COMMANDS[0x0026])
        return await self.command(0x0026, data)

    async def raw_aps_data_request(self, addr, src_ep, dst_ep, profile,
                                   cluster, payload, addr_mode=2, security=0):
        '''
        Send raw APS Data request
        '''
        radius = 0
        data = t.serialize([addr_mode, addr,
                           src_ep, dst_ep, cluster, profile,
                           security, radius, payload], COMMANDS[0x0530])
        return await self.command(0x0530, data)

    def handle_callback(self, *args):
        """run application callback handler"""
        if self._app:
            try:
                self._app.zigate_callback_handler(*args)
            except Exception as e:
                LOGGER.exception("Exception running handler", exc_info=e)

    @classmethod
    async def probe(cls, device_config: Dict[str, Any]) -> bool:
        """Probe port for the device presence."""
        api = cls(zigpy_zigate.config.SCHEMA_DEVICE(device_config))
        try:
            await asyncio.wait_for(api._probe(), timeout=PROBE_TIMEOUT)
            return True
        except (
            asyncio.TimeoutError,
            serial.SerialException,
            zigpy.exceptions.ZigbeeException,
        ) as exc:
            LOGGER.debug(
                "Unsuccessful radio probe of '%s' port",
                device_config[zigpy_zigate.config.CONF_DEVICE_PATH],
                exc_info=exc,
            )
        finally:
            api.close()

        return False

    async def _probe(self) -> None:
        """Open port and try sending a command"""
        try:
            device = next(serial.tools.list_ports.grep(self._config[zigpy_zigate.config.CONF_DEVICE_PATH]))
            if device.description == 'ZiGate':
                return
        except StopIteration:
            pass
        await self.connect()
        await self.set_raw_mode()

@pipiche38
Copy link

Why are you not submitting a PR ? so your patch would be merge into the code

@baimard
Copy link
Author

baimard commented Dec 12, 2021

Because I've tested, and I have an other error I need to solve that before the PR.

After 24 h of usage I have this : the thread goes into an error, and I don't know why :(

home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:07:15 ERROR (Thread-4) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:11 ERROR (Thread-566) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:11 ERROR (Thread-559) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:13 WARNING (Thread-554) [zigpy_zigate.api] No response to command 0x0009
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:13 WARNING (Thread-554) [zigpy_zigate.api] Retry command 0x0009
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:13 WARNING (Thread-554) [zigpy_zigate.api] Close uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:13 ERROR (Thread-554) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:15 WARNING (Thread-571) [zigpy_zigate.api] No response to command 0x0009
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:15 WARNING (Thread-571) [zigpy_zigate.api] Retry command 0x0009
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:15 WARNING (Thread-571) [zigpy_zigate.api] Close uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:15 WARNING (Thread-571) [zigpy_zigate.api] connect uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:15 ERROR (Thread-4) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:16 WARNING (Thread-571) [zigpy_zigate.api] No response to command 0x0009
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:12:16 ERROR (Thread-571) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:13 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:13 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:13 WARNING (MainThread) [zigpy_zigate.api] Close uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:13 WARNING (MainThread) [zigpy_zigate.api] connect uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:15 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:15 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:15 WARNING (MainThread) [zigpy_zigate.api] Close uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:15 WARNING (MainThread) [zigpy_zigate.api] connect uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:17 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:13:18 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:16:25 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:16:25 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:16:25 WARNING (MainThread) [zigpy_zigate.api] Close uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:16:25 WARNING (MainThread) [zigpy_zigate.api] connect uart
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:17:12 ERROR (Thread-559) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:17:13 ERROR (Thread-554) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:17:15 ERROR (Thread-577) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:18:15 ERROR (Thread-580) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:22:13 ERROR (Thread-554) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:22:13 ERROR (Thread-566) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:22:16 ERROR (Thread-4) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:23:15 ERROR (Thread-579) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:27:13 ERROR (Thread-554) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:27:13 ERROR (Thread-559) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:27:16 ERROR (Thread-577) [zigpy_zigate.api] thread error
home_assistant.1.5ktr66b42u1p@ocre    | 2021-12-11 20:28:17 ERROR (Thread-580) [zigpy_zigate.api] thread error

@puddly
Copy link
Collaborator

puddly commented Dec 13, 2021

You don't need to use threads when working with asyncio, you can use tasks:

async def connect(self):
    ...
    self._watchdog_task = asyncio.create_task(self.watchdog_loop())

def close(self):
    ...
    self._watchdog_task.cancel()

async def watchdog_loop(self):
    while True:
        await asyncio.sleep(30)
        LOGGER.warning("Check ---")

        try:
            await self.get_network_state()
        except Exception as exc:
            LOGGER.warning("Failed to get network state, treating as disconnect", exc_info=exc)

            self.connection_lost(exc)  # Treat this as a disconnect
            break

I don't have a ZiGate to test but this is roughly what other radio libraries do.

@baimard
Copy link
Author

baimard commented Dec 13, 2021

I don't know why I can't deal with asyncio, but I'm gone try again with your sample code. Thank you.

@baimard
Copy link
Author

baimard commented Mar 16, 2022

I tried updating to 0.8.0, it just doesn't work, my solution still works with the 0.7.3 package. I downgrade everything to HASS...

Very sad situation!

@puddly
Copy link
Collaborator

puddly commented Mar 16, 2022

@baimard What does the debug log show with 0.8.0? https://www.home-assistant.io/integrations/zha/#debug-logging

@baimard
Copy link
Author

baimard commented Mar 16, 2022

home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:17 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 133
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:17 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 133
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:17 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 133
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:17 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 131
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:17 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 131
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:17 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x1500:1:0x0001]: async_initialize: all attempts have failed: [DeliveryError('[0x1500:1:0x0001]: Message send failure'), DeliveryError('[0x1500:1:0x0001]: Message send failure'), DeliveryError('[0x1500:1:0x0001]: Message send failure'), DeliveryError('[0x1500:1:0x0001]: Message send failure')]
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:18 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 133
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:18 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 131
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:18 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code 131
home_assistant.1.iayelvp8clwa@home3    | 2022-03-16 20:52:18 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x1500:1:0x0405]: async_initialize: all attempts have failed: [DeliveryError('[0x1500:1:0x0405]: Message send failure'), DeliveryError('[0x1500:1:0x0405]: Message send failure'), DeliveryError('[0x1500:1:0x0405]: Message send failure'), DeliveryError('[0x1500:1:0x0405]: Message send failure')]

you need more ?

@puddly
Copy link
Collaborator

puddly commented Mar 16, 2022

The whole debug log, not just the warnings.

The two status codes are:

  • 131 = NoFreeAPSAckHandles
  • 133 = NoFreeMCPSReqDesc

@baimard
Copy link
Author

baimard commented Mar 16, 2022

ok I will show you tomorow.

@baimard
Copy link
Author

baimard commented Mar 28, 2022

Sorry for delay, I have new born at home :)

home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:00:32 INFO (MainThread) [homeassistant.components.camera] Setting up camera.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:00:32 INFO (MainThread) [homeassistant.components.climate] Setting up climate.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:00:32 INFO (MainThread) [homeassistant.components.light] Setting up light.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:00:32 INFO (MainThread) [homeassistant.components.select] Setting up select.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.netatmo_chambre_co2, old_state=<state sensor.netatmo_chambre_co2=1299; state_class=measurement, attribution=Data provided by Netatmo, unit_of_measurement=ppm, device_class=carbon_dioxide, friendly_name=Netatmo Chambre CO2 @ 2022-03-28T10:51:14.106610+02:00>, new_state=<state sensor.netatmo_chambre_co2=1265; state_class=measurement, attribution=Data provided by Netatmo, unit_of_measurement=ppm, device_class=carbon_dioxide, friendly_name=Netatmo Chambre CO2 @ 2022-03-28T11:01:14.181534+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.netatmo_chambre_pressure, old_state=<state sensor.netatmo_chambre_pressure=1018.6; state_class=measurement, attribution=Data provided by Netatmo, unit_of_measurement=mbar, device_class=pressure, friendly_name=Netatmo Chambre Pressure @ 2022-03-28T10:45:14.113598+02:00>, new_state=<state sensor.netatmo_chambre_pressure=1018.5; state_class=measurement, attribution=Data provided by Netatmo, unit_of_measurement=mbar, device_class=pressure, friendly_name=Netatmo Chambre Pressure @ 2022-03-28T11:01:14.182445+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.netatmo_chambre_noise, old_state=<state sensor.netatmo_chambre_noise=40; state_class=measurement, attribution=Data provided by Netatmo, unit_of_measurement=dB, icon=mdi:volume-high, friendly_name=Netatmo Chambre Noise @ 2022-03-28T10:51:14.107684+02:00>, new_state=<state sensor.netatmo_chambre_noise=38; state_class=measurement, attribution=Data provided by Netatmo, unit_of_measurement=dB, icon=mdi:volume-high, friendly_name=Netatmo Chambre Noise @ 2022-03-28T11:01:14.183131+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xFB80](TRADFRIbulbE14WWclear250lm): Attempting to checkin with device - missed checkins: 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xFB80, 260, 0, 1, 1, 33, b'\x00!\x00\x04\x00', True, False)
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02fb800101000001040000050021000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11x\x02\xfb\x80\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00!\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11x\x02\x12\xfb\x80\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x10!\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:28 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 DEBUG (MainThread) [zigpy_zigate.api] Tries count 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02fb800101000001040000050021000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11x\x02\xfb\x80\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00!\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11x\x02\x12\xfb\x80\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x10!\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:30 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 DEBUG (MainThread) [zigpy_zigate.api] Tries count 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02fb800101000001040000050021000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11x\x02\xfb\x80\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00!\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11x\x02\x12\xfb\x80\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x10!\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:31 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:33 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:33 DEBUG (MainThread) [zigpy_zigate.api] Tries count 0
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:01:33 DEBUG (MainThread) [zigpy.device] [0xfb80] Delivery error for seq # 0x21, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xFB80](TRADFRIbulbE14WWclear250lm): Attempting to checkin with device - missed checkins: 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xFB80, 260, 0, 1, 1, 34, b'\x00"\x00\x04\x00', True, False)
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02fb800101000001040000050022000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11{\x02\xfb\x80\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00"\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11{\x02\x12\xfb\x80\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x10"\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:37 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 DEBUG (MainThread) [zigpy_zigate.api] Tries count 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02fb800101000001040000050022000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11{\x02\xfb\x80\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00"\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11{\x02\x12\xfb\x80\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x10"\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:39 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 DEBUG (MainThread) [zigpy_zigate.api] Tries count 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02fb800101000001040000050022000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11{\x02\xfb\x80\x01\x01\x00\x00\x01\x04\x00\x00\x05\x00"\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11{\x02\x12\xfb\x80\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x10"\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:40 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:42 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:42 DEBUG (MainThread) [zigpy_zigate.api] Tries count 0
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:02:42 DEBUG (MainThread) [zigpy.device] [0xfb80] Delivery error for seq # 0x22, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:03:01 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2022-03-29T05:19:54.223247+00:00, next_dusk=2022-03-28T18:55:18.150399+00:00, next_midnight=2022-03-29T00:07:48+00:00, next_noon=2022-03-28T12:08:15+00:00, next_rising=2022-03-29T05:49:54.595720+00:00, next_setting=2022-03-28T18:25:14.259006+00:00, elevation=31.18, azimuth=120.98, rising=True, friendly_name=Sun @ 2022-03-28T09:35:01.823757+02:00>, new_state=<state sun.sun=above_horizon; next_dawn=2022-03-29T05:19:54.223247+00:00, next_dusk=2022-03-28T18:55:18.150399+00:00, next_midnight=2022-03-29T00:07:48+00:00, next_noon=2022-03-28T12:08:15+00:00, next_rising=2022-03-29T05:49:54.595720+00:00, next_setting=2022-03-28T18:25:14.259006+00:00, elevation=31.79, azimuth=121.92, rising=True, friendly_name=Sun @ 2022-03-28T09:35:01.823757+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:03:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fp3_battery_level, old_state=<state sensor.fp3_battery_level=89; state_class=measurement, unit_of_measurement=%, device_class=battery, icon=mdi:battery-80, friendly_name=FP3 Battery Level @ 2022-03-28T10:59:25.574929+02:00>, new_state=<state sensor.fp3_battery_level=91; state_class=measurement, unit_of_measurement=%, device_class=battery, icon=mdi:battery-90, friendly_name=FP3 Battery Level @ 2022-03-28T11:03:08.253416+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 11:03:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fp3_battery_temperature, old_state=<state sensor.fp3_battery_temperature=30.2; state_class=measurement, unit_of_measurement=°C, device_class=temperature, icon=mdi:battery, friendly_name=FP3 Battery Temperature @ 2022-03-28T10:59:34.856810+02:00>, new_state=<state sensor.fp3_battery_temperature=29.7; state_class=measurement, unit_of_measurement=°C, device_class=temperature, icon=mdi:battery, friendly_name=FP3 Battery Temperature @ 2022-03-28T11:03:08.254379+02:00>>

@baimard
Copy link
Author

baimard commented Mar 28, 2022

As you can see (the dish on the chart), after changing my ZHA librairy I can't retrieve temperature information.

Capture d’écran de 2022-03-28 13-16-04

@baimard
Copy link
Author

baimard commented Mar 28, 2022

After a while (look last log line)

t_home; source_type=gps, latitude=44.8671356, longitude=-0.7290534, gps_accuracy=87, altitude=82, course=0, speed=0, vertical_accuracy=14, friendly_name=FP3 @ 2022-03-28T16:27:29.701762+02:00>, new_state=<state device_tracker.fp3_2=not_home; source_type=gps, latitude=44.8871812, longitude=-0.7411826, gps_accuracy=19, altitude=82, course=0, speed=0, vertical_accuracy=3, friendly_name=FP3 @ 2022-03-28T16:30:32.719032+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:30:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=person.benjamin, old_state=<state person.benjamin=not_home; editable=False, id=benjamin, latitude=44.8671356, longitude=-0.7290534, gps_accuracy=87, source=device_tracker.fp3_2, user_id=8274e2fea1344dc795b63f9d4b49db97, entity_picture=/api/image/serve/47ffc39db49252b0e9cf22e30e8baddc/512x512, friendly_name=Benjamin @ 2022-03-28T13:42:57.492469+02:00>, new_state=<state person.benjamin=not_home; editable=False, id=benjamin, latitude=44.8871812, longitude=-0.7411826, gps_accuracy=19, source=device_tracker.fp3_2, user_id=8274e2fea1344dc795b63f9d4b49db97, entity_picture=/api/image/serve/47ffc39db49252b0e9cf22e30e8baddc/512x512, friendly_name=Benjamin @ 2022-03-28T13:42:57.492469+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1500](TH01): Attempting to checkin with device - missed checkins: 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [zigpy.device] [0x1500] Extending timeout for 0x32 request
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x1500, 260, 0, 1, 1, 50, b'\x002\x00\x04\x00', True, False)
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'0215000101000001040000050032000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\x05\x02\x15\x00\x01\x01\x00\x00\x01\x04\x00\x00\x05\x002\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\x02\x15\x02\x12\x15\x02\x10\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x102\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:29 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 DEBUG (MainThread) [zigpy_zigate.api] Tries count 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'0215000101000001040000050032000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\x05\x02\x15\x00\x01\x01\x00\x00\x01\x04\x00\x00\x05\x002\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\x02\x15\x02\x12\x15\x02\x10\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x102\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:30 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 DEBUG (MainThread) [zigpy_zigate.api] Tries count 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'0215000101000001040000050032000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\x05\x02\x15\x00\x01\x01\x00\x00\x01\x04\x00\x00\x05\x002\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\x02\x15\x02\x12\x15\x02\x10\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x102\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:32 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:33 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:33 DEBUG (MainThread) [zigpy_zigate.api] Tries count 0
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:31:33 DEBUG (MainThread) [zigpy.device] [0x1500] Delivery error for seq # 0x32, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2022-03-29T05:19:54.223247+00:00, next_dusk=2022-03-28T18:55:18.150399+00:00, next_midnight=2022-03-29T00:07:48+00:00, next_noon=2022-03-29T12:07:57+00:00, next_rising=2022-03-29T05:49:54.595720+00:00, next_setting=2022-03-28T18:25:14.259006+00:00, elevation=38.17, azimuth=226.81, rising=False, friendly_name=Sun @ 2022-03-28T09:35:01.823757+02:00>, new_state=<state sun.sun=above_horizon; next_dawn=2022-03-29T05:19:54.223247+00:00, next_dusk=2022-03-28T18:55:18.150399+00:00, next_midnight=2022-03-29T00:07:48+00:00, next_noon=2022-03-29T12:07:57+00:00, next_rising=2022-03-29T05:49:54.595720+00:00, next_setting=2022-03-28T18:25:14.259006+00:00, elevation=37.65, azimuth=227.89, rising=False, friendly_name=Sun @ 2022-03-28T09:35:01.823757+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1500](TH01): Attempting to checkin with device - missed checkins: 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [zigpy.device] [0x1500] Extending timeout for 0x33 request
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x1500, 260, 0, 1, 1, 51, b'\x003\x00\x04\x00', True, False)
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'0215000101000001040000050033000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\x04\x02\x15\x00\x01\x01\x00\x00\x01\x04\x00\x00\x05\x003\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\x02\x14\x02\x12\x15\x02\x10\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x103\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:44 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 DEBUG (MainThread) [zigpy_zigate.api] Tries count 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'0215000101000001040000050033000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\x04\x02\x15\x00\x01\x01\x00\x00\x01\x04\x00\x00\x05\x003\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\x02\x14\x02\x12\x15\x02\x10\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x103\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:45 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 DEBUG (MainThread) [zigpy_zigate.api] Tries count 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'0215000101000001040000050033000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\x04\x02\x15\x00\x01\x01\x00\x00\x01\x04\x00\x00\x05\x003\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\x02\x14\x02\x12\x15\x02\x10\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x103\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:47 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:48 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:48 DEBUG (MainThread) [zigpy_zigate.api] Tries count 0
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:32:48 DEBUG (MainThread) [zigpy.device] [0x1500] Delivery error for seq # 0x33, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xAD7F](TH01): Attempting to checkin with device - missed checkins: 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [zigpy.device] [0xad7f] Extending timeout for 0x34 request
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xAD7F, 260, 0, 1, 1, 52, b'\x004\x00\x04\x00', True, False)
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02ad7f0101000001040000050034000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\xc4\x02\xad\x7f\x01\x01\x00\x00\x01\x04\x00\x00\x05\x004\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\xc4\x02\x12\xad\x7f\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x104\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 INFO (MainThread) [homeassistant.components.camera] Setting up camera.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 INFO (MainThread) [homeassistant.components.climate] Setting up climate.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 INFO (MainThread) [homeassistant.components.light] Setting up light.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:32 INFO (MainThread) [homeassistant.components.select] Setting up select.netatmo
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 DEBUG (MainThread) [zigpy_zigate.api] Tries count 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02ad7f0101000001040000050034000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\xc4\x02\xad\x7f\x01\x01\x00\x00\x01\x04\x00\x00\x05\x004\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\xc4\x02\x12\xad\x7f\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x104\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:33 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:34 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=device_tracker.fp3_2, old_state=<state device_tracker.fp3_2=not_home; source_type=gps, latitude=44.8871812, longitude=-0.7411826, gps_accuracy=19, altitude=82, course=0, speed=0, vertical_accuracy=3, friendly_name=FP3 @ 2022-03-28T16:30:32.719032+02:00>, new_state=<state device_tracker.fp3_2=not_home; source_type=gps, latitude=44.8939581, longitude=-0.7595635, gps_accuracy=113, altitude=87, course=0, speed=0, vertical_accuracy=4, friendly_name=FP3 @ 2022-03-28T16:33:34.238115+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:34 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=person.benjamin, old_state=<state person.benjamin=not_home; editable=False, id=benjamin, latitude=44.8871812, longitude=-0.7411826, gps_accuracy=19, source=device_tracker.fp3_2, user_id=8274e2fea1344dc795b63f9d4b49db97, entity_picture=/api/image/serve/47ffc39db49252b0e9cf22e30e8baddc/512x512, friendly_name=Benjamin @ 2022-03-28T13:42:57.492469+02:00>, new_state=<state person.benjamin=not_home; editable=False, id=benjamin, latitude=44.8939581, longitude=-0.7595635, gps_accuracy=113, source=device_tracker.fp3_2, user_id=8274e2fea1344dc795b63f9d4b49db97, entity_picture=/api/image/serve/47ffc39db49252b0e9cf22e30e8baddc/512x512, friendly_name=Benjamin @ 2022-03-28T13:42:57.492469+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 DEBUG (MainThread) [zigpy_zigate.api] Tries count 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02ad7f0101000001040000050034000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\xc4\x02\xad\x7f\x01\x01\x00\x00\x01\x04\x00\x00\x05\x004\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\xc4\x02\x12\xad\x7f\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x104\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:35 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:36 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:36 DEBUG (MainThread) [zigpy_zigate.api] Tries count 0
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:36 DEBUG (MainThread) [zigpy.device] [0xad7f] Delivery error for seq # 0x34, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:59 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:12:4b:00:22:e9:79:de, unique_id=00:12:4b:00:22:e9:79:de, device_id=ca3958be73316f69ac93c6fa3fef7bc2, device_event_type=device_offline>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:59 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.chambre_power, old_state=<state sensor.chambre_power=67; state_class=measurement, battery_voltage=2.9, unit_of_measurement=%, device_class=battery, friendly_name=chambre power @ 2022-03-28T09:35:29.414600+02:00>, new_state=<state sensor.chambre_power=unavailable; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=chambre power @ 2022-03-28T16:33:59.159983+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:59 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.chambre_temperature, old_state=<state sensor.chambre_temperature=19.8; state_class=measurement, unit_of_measurement=°C, device_class=temperature, friendly_name=enfants @ 2022-03-28T10:15:49.417955+02:00>, new_state=<state sensor.chambre_temperature=unavailable; state_class=measurement, unit_of_measurement=°C, device_class=temperature, friendly_name=enfants @ 2022-03-28T16:33:59.160654+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:59 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.chambre_humidity, old_state=<state sensor.chambre_humidity=55.0; state_class=measurement, unit_of_measurement=%, device_class=humidity, friendly_name=chambre humidity @ 2022-03-28T10:27:48.710002+02:00>, new_state=<state sensor.chambre_humidity=unavailable; state_class=measurement, unit_of_measurement=%, device_class=humidity, friendly_name=chambre humidity @ 2022-03-28T16:33:59.161259+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:33:59 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=button.ewelink_th01_de79e922_identify, old_state=<state button.ewelink_th01_de79e922_identify=unknown; device_class=update, friendly_name=eWeLink TH01 de79e922 identify @ 2022-03-28T09:35:29.419909+02:00>, new_state=<state button.ewelink_th01_de79e922_identify=unavailable; device_class=update, friendly_name=eWeLink TH01 de79e922 identify @ 2022-03-28T16:33:59.161816+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:34:45 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fp3_battery_level, old_state=<state sensor.fp3_battery_level=78; state_class=measurement, unit_of_measurement=%, device_class=battery, icon=mdi:battery-70, friendly_name=FP3 Battery Level @ 2022-03-28T16:25:13.700714+02:00>, new_state=<state sensor.fp3_battery_level=75; state_class=measurement, unit_of_measurement=%, device_class=battery, icon=mdi:battery-70, friendly_name=FP3 Battery Level @ 2022-03-28T16:34:45.017700+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:34:45 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fp3_battery_temperature, old_state=<state sensor.fp3_battery_temperature=34.8; state_class=measurement, unit_of_measurement=°C, device_class=temperature, icon=mdi:battery, friendly_name=FP3 Battery Temperature @ 2022-03-28T16:25:13.701699+02:00>, new_state=<state sensor.fp3_battery_temperature=33.6; state_class=measurement, unit_of_measurement=°C, device_class=temperature, icon=mdi:battery, friendly_name=FP3 Battery Temperature @ 2022-03-28T16:34:45.018687+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xAD7F](TH01): Attempting to checkin with device - missed checkins: 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [zigpy.device] [0xad7f] Extending timeout for 0x35 request
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xAD7F, 260, 0, 1, 1, 53, b'\x005\x00\x04\x00', True, False)
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02ad7f0101000001040000050035000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\xc5\x02\xad\x7f\x01\x01\x00\x00\x01\x04\x00\x00\x05\x005\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\xc5\x02\x12\xad\x7f\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x105\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:01 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.saint_medard_en_jalles_next_rain, old_state=<state sensor.saint_medard_en_jalles_next_rain=unknown; forecast_time_ref=2022-03-28T14:40:00+00:00, 1_hour_forecast=0 min=Temps sec, 5 min=Temps sec, 10 min=Temps sec, 15 min=Temps sec, 20 min=Temps sec, 25 min=Temps sec, 35 min=Temps sec, 45 min=Temps sec, 55 min=Temps sec, attribution=Data provided by Météo-France, device_class=timestamp, friendly_name=Saint-Médard-en-Jalles Next rain @ 2022-03-28T09:35:02.530979+02:00>, new_state=<state sensor.saint_medard_en_jalles_next_rain=unknown; forecast_time_ref=2022-03-28T14:45:00+00:00, 1_hour_forecast=0 min=Temps sec, 5 min=Temps sec, 10 min=Temps sec, 15 min=Temps sec, 20 min=Temps sec, 25 min=Temps sec, 35 min=Temps sec, 45 min=Temps sec, 55 min=Temps sec, attribution=Data provided by Météo-France, device_class=timestamp, friendly_name=Saint-Médard-en-Jalles Next rain @ 2022-03-28T09:35:02.530979+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=weather.saint_medard_en_jalles, old_state=<state weather.saint_medard_en_jalles=partlycloudy; temperature=21.2, humidity=40, pressure=1018.2, wind_bearing=70, wind_speed=7, forecast=[{'datetime': datetime.datetime(2022, 3, 28, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'sunny', 'temperature': 22.3, 'templow': 7.3, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 3, 29, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 19.5, 'templow': 10.7, 'precipitation': 1.5}, {'datetime': datetime.datetime(2022, 3, 30, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 15.1, 'templow': 9.7, 'precipitation': 0.9}, {'datetime': datetime.datetime(2022, 3, 31, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 13.4, 'templow': 7.4, 'precipitation': 6.2}, {'datetime': datetime.datetime(2022, 4, 1, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 9.1, 'templow': 0.5, 'precipitation': 1.2}, {'datetime': datetime.datetime(2022, 4, 2, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 9.8, 'templow': -1, 'precipitation': 0.8}, {'datetime': datetime.datetime(2022, 4, 3, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 10.9, 'templow': -1.7, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 4, 4, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 12.8, 'templow': -1.1, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 4, 5, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 14.5, 'templow': 1.6, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 4, 6, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 15.2, 'templow': 3.6, 'precipitation': 0.1}, {'datetime': datetime.datetime(2022, 4, 7, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 15.2, 'templow': 4.4, 'precipitation': 0.6}, {'datetime': datetime.datetime(2022, 4, 8, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 15.4, 'templow': 5.6, 'precipitation': 1.2}, {'datetime': datetime.datetime(2022, 4, 9, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 16, 'templow': 6.2, 'precipitation': 1.1}, {'datetime': datetime.datetime(2022, 4, 10, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 16.9, 'templow': 6.8, 'precipitation': 0.8}, {'datetime': datetime.datetime(2022, 4, 11, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 17, 'templow': 7.1, 'precipitation': 1.1}], attribution=Data provided by Météo-France, friendly_name=Saint-Médard-en-Jalles @ 2022-03-28T15:05:02.070731+02:00>, new_state=<state weather.saint_medard_en_jalles=partlycloudy; temperature=21.2, humidity=35, pressure=1018.2, wind_bearing=45, wind_speed=11, forecast=[{'datetime': datetime.datetime(2022, 3, 28, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'sunny', 'temperature': 22.3, 'templow': 7.3, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 3, 29, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 19.5, 'templow': 10.7, 'precipitation': 1.5}, {'datetime': datetime.datetime(2022, 3, 30, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 15.1, 'templow': 9.7, 'precipitation': 0.9}, {'datetime': datetime.datetime(2022, 3, 31, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 13.4, 'templow': 7.4, 'precipitation': 6.2}, {'datetime': datetime.datetime(2022, 4, 1, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 9.1, 'templow': 0.5, 'precipitation': 1.2}, {'datetime': datetime.datetime(2022, 4, 2, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 9.8, 'templow': -1, 'precipitation': 0.8}, {'datetime': datetime.datetime(2022, 4, 3, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 10.9, 'templow': -1.7, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 4, 4, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 12.8, 'templow': -1.1, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 4, 5, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 14.5, 'templow': 1.6, 'precipitation': 0}, {'datetime': datetime.datetime(2022, 4, 6, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'partlycloudy', 'temperature': 15.2, 'templow': 3.6, 'precipitation': 0.1}, {'datetime': datetime.datetime(2022, 4, 7, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 15.2, 'templow': 4.4, 'precipitation': 0.6}, {'datetime': datetime.datetime(2022, 4, 8, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 15.4, 'templow': 5.6, 'precipitation': 1.2}, {'datetime': datetime.datetime(2022, 4, 9, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 16, 'templow': 6.2, 'precipitation': 1.1}, {'datetime': datetime.datetime(2022, 4, 10, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 16.9, 'templow': 6.8, 'precipitation': 0.8}, {'datetime': datetime.datetime(2022, 4, 11, 2, 0, tzinfo=<DstTzInfo 'Europe/Paris' CEST+2:00:00 DST>), 'condition': 'rainy', 'temperature': 17, 'templow': 7.1, 'precipitation': 1.1}], attribution=Data provided by Météo-France, friendly_name=Saint-Médard-en-Jalles @ 2022-03-28T15:05:02.070731+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=camera.stmed, old_state=<state camera.stmed=idle; access_token=583bd279a918ac3ca1b795084909fc668298ef20ba64fd8cb950abdc7bbf03a9, frontend_stream_type=hls, entity_picture=/api/camera_proxy/camera.stmed?token=583bd279a918ac3ca1b795084909fc668298ef20ba64fd8cb950abdc7bbf03a9, friendly_name=Stmed, supported_features=2 @ 2022-03-28T09:35:02.514828+02:00>, new_state=<state camera.stmed=idle; access_token=2ab797bb486adb190f5c7c3e3394169b8e35a9038a60a545e4d9357157418355, frontend_stream_type=hls, entity_picture=/api/camera_proxy/camera.stmed?token=2ab797bb486adb190f5c7c3e3394169b8e35a9038a60a545e4d9357157418355, friendly_name=Stmed, supported_features=2 @ 2022-03-28T09:35:02.514828+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=camera.stmed_ch, old_state=<state camera.stmed_ch=idle; access_token=0e48b31bc5912fff93aeb93d1d68d778791c1422362d431c5400b29eb2a7c54b, frontend_stream_type=hls, entity_picture=/api/camera_proxy/camera.stmed_ch?token=0e48b31bc5912fff93aeb93d1d68d778791c1422362d431c5400b29eb2a7c54b, friendly_name=Stmed_ch, supported_features=2 @ 2022-03-28T09:35:02.515222+02:00>, new_state=<state camera.stmed_ch=idle; access_token=63be3cf53fbe2eb9cf75041dc4b4d53888f5907521aa1859a5ae247bf71f4e6e, frontend_stream_type=hls, entity_picture=/api/camera_proxy/camera.stmed_ch?token=63be3cf53fbe2eb9cf75041dc4b4d53888f5907521aa1859a5ae247bf71f4e6e, friendly_name=Stmed_ch, supported_features=2 @ 2022-03-28T09:35:02.515222+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=camera.appartsalon2, old_state=<state camera.appartsalon2=idle; access_token=ffa9df73240f14d8e6ba61c46473c38cf92553537a348af4f634c70101ad72df, frontend_stream_type=hls, entity_picture=/api/camera_proxy/camera.appartsalon2?token=ffa9df73240f14d8e6ba61c46473c38cf92553537a348af4f634c70101ad72df, friendly_name=AppartSalon2, supported_features=2 @ 2022-03-28T09:35:02.515596+02:00>, new_state=<state camera.appartsalon2=idle; access_token=9b4ccde8e5a3ce9a5b6a198e9b89f0397c0a295d82f01d9bf49d2d64237e3dca, frontend_stream_type=hls, entity_picture=/api/camera_proxy/camera.appartsalon2?token=9b4ccde8e5a3ce9a5b6a198e9b89f0397c0a295d82f01d9bf49d2d64237e3dca, friendly_name=AppartSalon2, supported_features=2 @ 2022-03-28T09:35:02.515596+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=camera.appartsalon, old_state=<state camera.appartsalon=idle; access_token=48af1682a757a056662a936fcad4547fe6f654723fe08f72438492cec0dc3135, entity_picture=/api/camera_proxy/camera.appartsalon?token=48af1682a757a056662a936fcad4547fe6f654723fe08f72438492cec0dc3135, friendly_name=AppartSalon, supported_features=0 @ 2022-03-28T09:35:02.522775+02:00>, new_state=<state camera.appartsalon=idle; access_token=26b09e9e6b088b7dc5fc810de505b847c36e0f2449b652a6ddf8d45d99c3030d, entity_picture=/api/camera_proxy/camera.appartsalon?token=26b09e9e6b088b7dc5fc810de505b847c36e0f2449b652a6ddf8d45d99c3030d, friendly_name=AppartSalon, supported_features=0 @ 2022-03-28T09:35:02.522775+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [zigpy_zigate.api] Tries count 2
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02ad7f0101000001040000050035000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\xc5\x02\xad\x7f\x01\x01\x00\x00\x01\x04\x00\x00\x05\x005\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\xc5\x02\x12\xad\x7f\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x105\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:02 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 DEBUG (MainThread) [zigpy_zigate.api] Tries count 1
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0530 b'02ad7f0101000001040000050035000400'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x11\xc5\x02\xad\x7f\x01\x01\x00\x00\x01\x04\x00\x00\x05\x005\x00\x04\x00'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x11\xc5\x02\x12\xad\x7f\x02\x11\x02\x11\x02\x10\x02\x10\x02\x11\x02\x14\x02\x10\x02\x10\x02\x15\x02\x105\x02\x10\x02\x14\x02\x10'
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 WARNING (MainThread) [asyncio] socket.send() raised exception.
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:04 DEBUG (MainThread) [zigpy_zigate.api] Wait for status to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:05 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0530
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:05 DEBUG (MainThread) [zigpy_zigate.api] Tries count 0
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:05 DEBUG (MainThread) [zigpy.device] [0xad7f] Delivery error for seq # 0x35, on endpoint id 1 cluster 0x0000: ZiGate doesn't answer to command
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.paymium_btc, old_state=<state sensor.paymium_btc=43477; unit_of_measurement=BTC, friendly_name=Paymium BTC @ 2022-03-28T16:20:08.275992+02:00>, new_state=<state sensor.paymium_btc=43474; unit_of_measurement=BTC, friendly_name=Paymium BTC @ 2022-03-28T16:35:08.618347+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.binance_btc, old_state=<state sensor.binance_btc=43416; unit_of_measurement=BTC, friendly_name=Binance BTC @ 2022-03-28T16:30:08.277652+02:00>, new_state=<state sensor.binance_btc=43355; unit_of_measurement=BTC, friendly_name=Binance BTC @ 2022-03-28T16:35:08.619297+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:35:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.coinbase_btc, old_state=<state sensor.coinbase_btc=43314; unit_of_measurement=BTC, friendly_name=Coinbase BTC @ 2022-03-28T16:30:08.278510+02:00>, new_state=<state sensor.coinbase_btc=43313; unit_of_measurement=BTC, friendly_name=Coinbase BTC @ 2022-03-28T16:35:08.620186+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event android.zone_entered[R]: accuracy=5.0, altitude=87.0, bearing=235.0, latitude=44.89406883716583, longitude=-0.7660657167434692, provider=gps, time=1648478170000, vertical_accuracy=0, zone=zone.home, device_id=dad86d0e705a1136>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=device_tracker.fp3_2, old_state=<state device_tracker.fp3_2=not_home; source_type=gps, latitude=44.8939581, longitude=-0.7595635, gps_accuracy=113, altitude=87, course=0, speed=0, vertical_accuracy=4, friendly_name=FP3 @ 2022-03-28T16:33:34.238115+02:00>, new_state=<state device_tracker.fp3_2=home; source_type=gps, latitude=44.89406883716583, longitude=-0.7660657167434692, gps_accuracy=5, altitude=87, course=235, speed=0, vertical_accuracy=0, friendly_name=FP3 @ 2022-03-28T16:36:10.375087+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=person.benjamin, old_state=<state person.benjamin=not_home; editable=False, id=benjamin, latitude=44.8939581, longitude=-0.7595635, gps_accuracy=113, source=device_tracker.fp3_2, user_id=8274e2fea1344dc795b63f9d4b49db97, entity_picture=/api/image/serve/47ffc39db49252b0e9cf22e30e8baddc/512x512, friendly_name=Benjamin @ 2022-03-28T13:42:57.492469+02:00>, new_state=<state person.benjamin=home; editable=False, id=benjamin, latitude=44.89406883716583, longitude=-0.7660657167434692, gps_accuracy=5, source=device_tracker.fp3_2, user_id=8274e2fea1344dc795b63f9d4b49db97, entity_picture=/api/image/serve/47ffc39db49252b0e9cf22e30e8baddc/512x512, friendly_name=Benjamin @ 2022-03-28T16:36:10.376342+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=01_Benjamin rentre, entity_id=automation.envoie_de_message_quand_benjamin_rentre, source=person.benjamin entering Maison>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.envoie_de_message_quand_benjamin_rentre, old_state=<state automation.envoie_de_message_quand_benjamin_rentre=on; last_triggered=2022-03-27T18:25:20.808147+02:00, mode=single, current=0, id=1603201804595, friendly_name=01_Benjamin rentre @ 2022-03-28T09:35:02.549334+02:00>, new_state=<state automation.envoie_de_message_quand_benjamin_rentre=on; last_triggered=2022-03-28T16:36:10.381590+02:00, mode=single, current=1, id=1603201804595, friendly_name=01_Benjamin rentre @ 2022-03-28T09:35:02.549334+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 INFO (MainThread) [homeassistant.components.automation.envoie_de_message_quand_benjamin_rentre] 01_Benjamin rentre: Running automation actions
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 INFO (MainThread) [homeassistant.components.automation.envoie_de_message_quand_benjamin_rentre] 01_Benjamin rentre: Executing step call service
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=notify, service=mobile_app_redmi_note_9_pro, service_data=message=ton amoureux vient de rentrer !>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 INFO (MainThread) [homeassistant.components.mobile_app.notify] mobile_app push notification rate limits for Redmi Note 9 Pro: 2 sent, 500 allowed, 0 errors, resets in 9:23:49
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 INFO (MainThread) [homeassistant.components.automation.envoie_de_message_quand_benjamin_rentre] 01_Benjamin rentre: Executing step call service
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=notify, service=notifier_free, service_data=message=tu es rentré !>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 INFO (MainThread) [homeassistant.components.automation.envoie_de_message_quand_benjamin_rentre] 01_Benjamin rentre: Executing step device automation
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.entree>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.envoie_de_message_quand_benjamin_rentre, old_state=<state automation.envoie_de_message_quand_benjamin_rentre=on; last_triggered=2022-03-28T16:36:10.381590+02:00, mode=single, current=1, id=1603201804595, friendly_name=01_Benjamin rentre @ 2022-03-28T09:35:02.549334+02:00>, new_state=<state automation.envoie_de_message_quand_benjamin_rentre=on; last_triggered=2022-03-28T16:36:10.381590+02:00, mode=single, current=0, id=1603201804595, friendly_name=01_Benjamin rentre @ 2022-03-28T09:35:02.549334+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2022-03-29T05:19:54.223247+00:00, next_dusk=2022-03-28T18:55:18.150399+00:00, next_midnight=2022-03-29T00:07:48+00:00, next_noon=2022-03-29T12:07:57+00:00, next_rising=2022-03-29T05:49:54.595720+00:00, next_setting=2022-03-28T18:25:14.259006+00:00, elevation=37.65, azimuth=227.89, rising=False, friendly_name=Sun @ 2022-03-28T09:35:01.823757+02:00>, new_state=<state sun.sun=above_horizon; next_dawn=2022-03-29T05:19:54.223247+00:00, next_dusk=2022-03-28T18:55:18.150399+00:00, next_midnight=2022-03-29T00:07:48+00:00, next_noon=2022-03-29T12:07:57+00:00, next_rising=2022-03-29T05:49:54.595720+00:00, next_setting=2022-03-28T18:25:14.259006+00:00, elevation=37.12, azimuth=228.95, rising=False, friendly_name=Sun @ 2022-03-28T09:35:01.823757+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:12:4b:00:22:69:49:e1, unique_id=00:12:4b:00:22:69:49:e1, device_id=125b5fb214c15a2303d3f23476065167, device_event_type=device_offline>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.temperaturesalon_power, old_state=<state sensor.temperaturesalon_power=61; state_class=measurement, battery_voltage=2.9, unit_of_measurement=%, device_class=battery, friendly_name=temperaturesalon power @ 2022-03-28T09:35:29.417243+02:00>, new_state=<state sensor.temperaturesalon_power=unavailable; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=temperaturesalon power @ 2022-03-28T16:36:30.099187+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.temperaturesalon_temperature, old_state=<state sensor.temperaturesalon_temperature=20.1; state_class=measurement, unit_of_measurement=°C, device_class=temperature, friendly_name=salon @ 2022-03-28T10:32:38.727639+02:00>, new_state=<state sensor.temperaturesalon_temperature=unavailable; state_class=measurement, unit_of_measurement=°C, device_class=temperature, friendly_name=salon @ 2022-03-28T16:36:30.099883+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.temperaturesalon_humidity, old_state=<state sensor.temperaturesalon_humidity=57.7; state_class=measurement, unit_of_measurement=%, device_class=humidity, friendly_name=temperaturesalon humidity @ 2022-03-28T10:29:48.650053+02:00>, new_state=<state sensor.temperaturesalon_humidity=unavailable; state_class=measurement, unit_of_measurement=%, device_class=humidity, friendly_name=temperaturesalon humidity @ 2022-03-28T16:36:30.100456+02:00>>
home_assistant.1.tuok51suk2y3@home3    | 2022-03-28 16:36:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling **<Event state_changed[L]: entity_id=button.ewelink_th01_e1496922_identify, old_state=<state button.ewelink_th01_e1496922_identify=unknown; device_class=update, friendly_name=eWeLink TH01 e1496922 identify @ 2022-03-28T09:35:29.423165+02:00>, new_state=<state button.ewelink_th01_e1496922_identify=unavailable; device_class=update, friendly_name=eWeLink TH01 e1496922 identify @ 2022-03-28T16:36:30.100990+02:00>>**

@max5962
Copy link

max5962 commented Apr 13, 2022

Same issue.
I have to unplug/plug and reboot my VM twice a day :-(

@baimard
Copy link
Author

baimard commented Apr 21, 2022

any news ?

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

I have the same issue. I don't even have that many devices, maybe 14. NoFreeAPSAckHandles is the most common error I get. None of my automation sees anything at this time. Sensors go dead as well. I'm on the latest ZiGate firmware too. It was working fine until I added six new devices today.

What gives?

@puddly
Copy link
Collaborator

puddly commented Jul 12, 2022

What version of Home Assistant are you running? Can post post debug logs?

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Absolutely, what logs do you want?

I'm on the latest version of HA on top of Fedora 36 ARM64. I'm using the serial UART ZiGate, not the Wi-Fi one.

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Some warning logs:

Jul 12 17:43:14 verena.dragonfear systemd[1]: systemd-unit-state-collector.service: Consumed 1.481s CPU time.
Jul 12 17:43:18 verena.dragonfear hass[873]: 2022-07-12 17:43:18 INFO (SyncWorker_5) [homeassistant.components.ubus.device_tracker] Checking hostapd
Jul 12 17:43:28 verena.dragonfear hass[873]: 2022-07-12 17:43:28 INFO (SyncWorker_7) [homeassistant.components.ubus.device_tracker] Checking hostapd
Jul 12 17:43:38 verena.dragonfear hass[873]: 2022-07-12 17:43:38 INFO (SyncWorker_8) [homeassistant.components.ubus.device_tracker] Checking hostapd
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:43 verena.dragonfear hass[873]: 2022-07-12 17:43:43 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:44 verena.dragonfear hass[873]: 2022-07-12 17:43:44 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:44 verena.dragonfear hass[873]: 2022-07-12 17:43:44 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:44 verena.dragonfear hass[873]: 2022-07-12 17:43:44 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:46 verena.dragonfear kernel: hrtimer: interrupt took 52969 ns
Jul 12 17:43:48 verena.dragonfear hass[873]: 2022-07-12 17:43:48 INFO (SyncWorker_9) [homeassistant.components.ubus.device_tracker] Checking hostapd
Jul 12 17:43:57 verena.dragonfear hass[873]: 2022-07-12 17:43:57 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Running automation actions
Jul 12 17:43:57 verena.dragonfear hass[873]: 2022-07-12 17:43:57 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Executing step call service
Jul 12 17:43:57 verena.dragonfear hass[873]: 2022-07-12 17:43:57 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:57 verena.dragonfear hass[873]: 2022-07-12 17:43:57 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Running automation actions
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Executing step call service
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Running automation actions
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Executing step call service
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Running automation actions
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Executing step call service
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (SyncWorker_7) [homeassistant.components.ubus.device_tracker] Checking hostapd
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Running automation actions
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Executing step call service
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Running automation actions
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 INFO (MainThread) [homeassistant.components.automation.nook_shortcut_button_toggles_lamp] Nook: button toggles lamp: Executing step call service
Jul 12 17:43:58 verena.dragonfear hass[873]: 2022-07-12 17:43:58 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeAPSAckHandles
Jul 12 17:44:08 verena.dragonfear hass[873]: 2022-07-12 17:44:08 INFO (SyncWorker_5) [homeassistant.components.ubus.device_tracker] Checking hostapd

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

To me it looks like there is a resource leak somewhere, and the HA system runs out of "APSAckHandles" (whatever those are) shortly after startup. I'm going to try and reload the integration and see if that makes a difference.

@puddly
Copy link
Collaborator

puddly commented Jul 12, 2022

2022.7.3? The ZHA debug logs: https://www.home-assistant.io/integrations/zha/#debug-logging

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Yes that version. Restarting HA now.

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Coming online again... please wait a few minutes. Thank you for your prompt response!

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Hot damn, restarted Home Assistant and nothing is wrong now. WTF.

Hang on, I may have spoken too soon tho.

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Yeah spoke too soon. I'm not seeing any errors in the logs right now, but my sensors definitely aren't updating.

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

I pushed the presence buttons on my sensors and that caused some of them to update, but not all.

Will attach the log right now.

debuglogs.txt

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Yeah, unless I push the button on a sensor, the sensor will not update its values in HASS. There can be many minutes, or many hours, before an update comes in. I must be doing something wrong in my configuration?

@zigbeefordomoticz
Copy link

zigbeefordomoticz commented Jul 12, 2022 via email

@Rudd-O
Copy link

Rudd-O commented Jul 12, 2022

Finally got the errors again:

Jul 12 21:41:26 verena.dragonfear hass[1256]: 2022-07-12 21:41:26 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.ACK_DATA [<Status.Success: 0>, 0x4120, 1, 2820, 210]
Jul 12 21:41:26 verena.dragonfear hass[1256]: 2022-07-12 21:41:26 DEBUG (MainThread) [zigpy_zigate.zigbee.application] ACK Data received 210 Status.Success
Jul 12 21:41:27 verena.dragonfear hass[1256]: 2022-07-12 21:41:27 INFO (SyncWorker_1) [homeassistant.components.ubus.device_tracker] Checking hostapd
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 99990002878500
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] data received 0x9999 b'85' LQI:0
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.EXTENDED_ERROR [<Status.NoFreeMCPSReqDesc: 133>]
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeMCPSReqDesc
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 99990002878500
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] data received 0x9999 b'85' LQI:0
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.EXTENDED_ERROR [<Status.NoFreeMCPSReqDesc: 133>]
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeMCPSReqDesc
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 80020016000001040b0401010262a602000008000a08052118006c
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'0001040b0401010262a602000008000a0805211800' LQI:108
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.DATA_INDICATION [<Status.Success: 0>, 260, 2820, 1, 1, <Address address_mode=AddressMode.NWK address=0x62a6>, <Address address_mode=AddressMode.NWK address=0x0000>, b'\x08\x00\n\x08\x05!\x18\x00']
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Received ZCL frame: b'\x08\x00\n\x08\x05!\x18\x00'
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=0, command_id=10, *is_reply=True)
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0508, value=TypeValue(type=uint16_t, value=24))])
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Received command 0x0A (TSN 0): Report_Attributes(attribute_reports=[Attribute(attrid=0x0508, value=TypeValue(type=uint16_t, value=24))])
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Attribute report received: rms_current=24
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=0, command_id=<GeneralCommand.Default_Response: 11>, *is_reply=True)
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy.zcl] [0x62A6:1:0x0b04] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 99990002878500
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] data received 0x9999 b'85' LQI:0
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.EXTENDED_ERROR [<Status.NoFreeMCPSReqDesc: 133>]
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 WARNING (MainThread) [zigpy_zigate.zigbee.application] Extended error code Status.NoFreeMCPSReqDesc
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 8012000a820001010262a6d30b0400
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8012 b'0001010262a6d30b04' LQI:0
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.APS_DATA_CONFIRM [<Status.Success: 0>, 1, 1, <Address address_mode=AddressMode.NWK address=0x62a6>, 211]
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] ZPS Event APS data confirm, message routed to <Address address_mode=AddressMode.NWK address=0x62a6> Status.Success
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 80110008800062a6010b04d300
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8011 b'0062a6010b04d3' LQI:0
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler ResponseId.ACK_DATA [<Status.Success: 0>, 0x62a6, 1, 2820, 211]
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] ACK Data received 211 Status.Success
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x62A6, 260, 2820, 1, 1, 0, b'\x18\x00\x0b\n\x00', False, False)
Jul 12 21:41:29 verena.dragonfear hass[1256]: 2022-07-12 21:41:29 DEBUG (MainThread) [zigpy_zigate.api] Sending CommandId.SEND_RAW_APS_DATA_PACKET (b'\x02b\xa6\x01\x01\x0b\x04\x01\x04\x00\x00\x05\x18\x00\x0b\n\x00'), waiti

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests