Core: Remove duplicate log entries Unexpected response TSN

[stast1]

Home Assistant release with the issue:

0.98.1

Last working Home Assistant release (if known):

Operating environment (Hass.io/Docker/Windows/etc.):

Hass.io

Component/platform:

ZHA

Description of problem:
These duplicate entries clog the log

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

Traceback (if applicable):

Unexpected response TSN=113 command=11 args=[1, <Status.SUCCESS: 0>]
7:56 __main__.py (WARNING)
Unexpected response TSN=112 command=11 args=[1, <Status.SUCCESS: 0>]
7:56 __main__.py (WARNING)
Unexpected response TSN=111 command=11 args=[1, <Status.SUCCESS: 0>]
7:55 __main__.py (WARNING)
Unexpected response TSN=110 command=11 args=[1, <Status.SUCCESS: 0>]
7:54 __main__.py (WARNING)
Unexpected response TSN=109 command=11 args=[1, <Status.SUCCESS: 0>]
7:53 __main__.py (WARNING)
Unexpected response TSN=108 command=11 args=[1, <Status.SUCCESS: 0>]
7:52 __main__.py (WARNING)
Unexpected response TSN=107 command=11 args=[1, <Status.SUCCESS: 0>]
7:51 __main__.py (WARNING)
Unexpected response TSN=106 command=11 args=[1, <Status.SUCCESS: 0>]
7:50 __main__.py (WARNING)
Unexpected response TSN=105 command=11 args=[1, <Status.SUCCESS: 0>]
7:49 __main__.py (WARNING)
Unexpected response TSN=104 command=11 args=[1, <Status.SUCCESS: 0>]
7:48 __main__.py (WARNING)
Unexpected response TSN=103 command=11 args=[1, <Status.SUCCESS: 0>]
7:47 __main__.py (WARNING)
Unexpected response TSN=102 command=11 args=[1, <Status.SUCCESS: 0>]
7:46 __main__.py (WARNING)
Unexpected response TSN=101 command=11 args=[1, <Status.SUCCESS: 0>]
7:45 __main__.py (WARNING)
Unexpected response TSN=100 command=11 args=[1, <Status.SUCCESS: 0>]
7:44 __main__.py (WARNING)
Unexpected response TSN=99 command=11 args=[1, <Status.SUCCESS: 0>]
7:43 __main__.py (WARNING)
Unexpected response TSN=98 command=11 args=[1, <Status.SUCCESS: 0>]
7:42 __main__.py (WARNING)
Unexpected response TSN=97 command=11 args=[1, <Status.SUCCESS: 0>]
7:42 __main__.py (WARNING)
Unexpected response TSN=96 command=11 args=[1, <Status.SUCCESS: 0>]
7:41 __main__.py (WARNING)
Unexpected response TSN=95 command=11 args=[1, <Status.SUCCESS: 0>]
7:40 __main__.py (WARNING)
Unexpected response TSN=94 command=11 args=[1, <Status.SUCCESS: 0>]
7:39 __main__.py (WARNING)
Unexpected response TSN=93 command=11 args=[1, <Status.SUCCESS: 0>]
7:38 __main__.py (WARNING)
Unexpected response TSN=92 command=11 args=[1, <Status.SUCCESS: 0>]
7:37 __main__.py (WARNING)
Unexpected response TSN=91 command=11 args=[1, <Status.SUCCESS: 0>]
7:36 __main__.py (WARNING)
Unexpected response TSN=90 command=11 args=[1, <Status.SUCCESS: 0>]
7:35 __main__.py (WARNING)
Unexpected response TSN=89 command=11 args=[1, <Status.SUCCESS: 0>]
7:35 __main__.py (WARNING)
Unexpected response TSN=88 command=11 args=[1, <Status.SUCCESS: 0>]
7:34 __main__.py (WARNING)
Unexpected response TSN=87 command=11 args=[1, <Status.SUCCESS: 0>]
7:33 __main__.py (WARNING)
Unexpected response TSN=86 command=11 args=[1, <Status.SUCCESS: 0>]
7:32 __main__.py (WARNING)
Unexpected response TSN=85 command=11 args=[1, <Status.SUCCESS: 0>]
7:31 __main__.py (WARNING)
Unexpected response TSN=84 command=11 args=[1, <Status.SUCCESS: 0>]
7:30 __main__.py (WARNING)
Unexpected response TSN=83 command=11 args=[1, <Status.SUCCESS: 0>]
7:29 __main__.py (WARNING)
Unexpected response TSN=82 command=11 args=[1, <Status.SUCCESS: 0>]
7:28 __main__.py (WARNING)
Unexpected response TSN=81 command=11 args=[1, <Status.SUCCESS: 0>]
7:27 __main__.py (WARNING)
Unexpected response TSN=80 command=11 args=[1, <Status.SUCCESS: 0>]
7:26 __main__.py (WARNING)
Unexpected response TSN=79 command=11 args=[1, <Status.SUCCESS: 0>]
7:25 __main__.py (WARNING)
Unexpected response TSN=78 command=11 args=[1, <Status.SUCCESS: 0>]
7:25 __main__.py (WARNING)
Unexpected response TSN=77 command=11 args=[1, <Status.SUCCESS: 0>]
7:24 __main__.py (WARNING)
Unexpected response TSN=76 command=11 args=[1, <Status.SUCCESS: 0>]
7:23 __main__.py (WARNING)

Additional information:

[probot-home-assistant[bot]]

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as its been labeled with a integration (zha) you are listed as a codeowner for? Thanks!

[Adminiuga]

configure logger component and set level to error for zigpy eg

logger:
  default: info
  logs:
    zigpy: error

[Adminiuga]

just FYI, this usually indicates that device sends the response twice, because it is not getting an acknowledgement, which is a telltale sign of a weak zigbee network.

[Adminiuga]

also, what radio are you using and what hardware.

[stast1]

configure logger component and set level to error for zigpy eg

Does not help. Already configured as follows:

logger:
  default: error

also, what radio are you using and what hardware.

zha:
  radio_type: xbee
  usb_path: /dev/ttyUSB0
  baudrate: 57600

Xiaomi and Akara sensors

Previously, this did not happen, it started with some kind of update

[Adminiuga]

when do you get those messages mostly: startup or normal operation?
enable debug logging for the following:

logger:
  default: info
  logs:
    asyncio: debug
    homeassistant.components.zha: debug
    zigpy: debug
    bellows: debug
    zigpy_xbee: debug
    zigpy_deconz: debug
    zigpy_zigate: debug

and post full debug log here, not copy'n'paste from info panel, as it is useless without timestamps

[Adminiuga]

other than that, there were no changes to zigpy-xbee-homeassistant for a few releases now.

[stast1]

when do you get those messages mostly: startup or normal operation?

normal operation

2019-08-30 17:57:31 DEBUG (MainThread) [zigpy_xbee.uart] Connection made
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Loading application state from /config/zigbee.db
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 8
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.vibration.aq1'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 5
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_cube.aqgl01'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.weather'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 2
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_ht'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_motion.aq2'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_magnet.aq2'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_magnet.aq2'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.plug'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 1
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 10
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_switch'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 10
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_switch'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 11
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_motion'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.remote.b186acn01'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 9
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65520 value: b'\xaa\x10\x05A\x87)\x01\x10\x01'
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 10
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: lumi.sensor_magnet
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1283 value: 76
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1288 value: 4977879875580
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 3 value: 8
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 1
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: Vibration
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 6 value: 09-29-2017
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1285 value: 327680
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65285 value: 500
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: -39.499996185302734
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: rotate_left:-39.499996185302734
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:32 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 7.699174880981445
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xa9\x0b\x03(\x18\x04!\xa8C\x05!\xcf\x00\x06$\x01\x00\x00\x00\x00\n!\x0ba\x97!\x00\x00\x98!\x1d\x00\x99!\x0e\x00\x9a!\x04\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xd1\x0b\x03(\x1c\x04!\xa8C\x05!\x13\x00\x06$\x01\x00\x00\x00\x00\x08!\x08\x03\n!\x0ba\x98!\x1e\x00\x99!\x08\x00\x9a%,\x00\xf2\xff\x94\x04'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 2
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: None
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\x8b\x0b\x04!\xa8C\x05!8\x00\x06$\x01\x00\x00\x00\x00d)\x0f\re!\xaa\tf++\x85\x01\x00\n!\x00\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xc7\x0b\x04!\xa8\x13\x05!\x1b\x00\x06$\x02\x00\x00\x00\x00d)\xa0\ne!+\x10\n!\x00\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xc7\x0b\x03(!\x04!\xa8C\x05!q\x00\x06$\x01\x00\x00\x00\x00\x08!\t\x14\n!\x0ba'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 3343
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 2420
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 996
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 20 value: -1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 16 value: 9961
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: single
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 0.0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 61440 value: 117440765
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 23945.516808262164
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xd1\x0b\x03( \x04!\xa8C\x05!%\x00\x06$\x10\x00\x00\x00\x00\n!\x0bad\x10\x00\x0b!\xf0\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xa9\x0b\x03((\x04!\xa8\x13\x05!4\x00\x06$\x01\x00\x00\x00\x00\n!\x00\x00d\x10\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: d
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xc7\x0b\x03(\x1a\x04!\xa8\x13\x05!%\x00\x06$\x01\x00\x00\x00\x00\n!\x00\x00d\x10\x01'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 8
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.vibration.aq1'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 5
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_cube.aqgl01'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.weather'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 2
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_ht'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_motion.aq2'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_magnet.aq2'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_magnet.aq2'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.plug'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 10
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_switch'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 10
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_switch'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 11
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.sensor_motion'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'LUMI'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'lumi.remote.b186acn01'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 9
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65520 value: b'\xaa\x10\x05A\x87)\x01\x10\x01'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1 value: 10
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: lumi.sensor_magnet
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1283 value: 76
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1288 value: 4977879875580
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 3 value: 8
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: Vibration
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 6 value: 09-29-2017
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1285 value: 327680
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65285 value: 500
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: -39.499996185302734
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: rotate_left:-39.499996185302734
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 3
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 2735
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 3827
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 7.699174880981445
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xa9\x0b\x03(\x18\x04!\xa8C\x05!\xcf\x00\x06$\x01\x00\x00\x00\x00\n!\x0ba\x97!\x00\x00\x98!\x1d\x00\x99!\x0e\x00\x9a!\x04\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 194
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 29
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xd1\x0b\x03(\x1c\x04!\xa8C\x05!\x13\x00\x06$\x01\x00\x00\x00\x00\x08!\x08\x03\n!\x0ba\x98!\x1e\x00\x99!\x08\x00\x9a%,\x00\xf2\xff\x94\x04'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 2
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: None
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\x8b\x0b\x04!\xa8C\x05!8\x00\x06$\x01\x00\x00\x00\x00d)\x0f\re!\xaa\tf++\x85\x01\x00\n!\x00\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 182
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 29
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xc7\x0b\x04!\xa8\x13\x05!\x1b\x00\x06$\x02\x00\x00\x00\x00d)\xa0\ne!+\x10\n!\x00\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xc7\x0b\x03(!\x04!\xa8C\x05!q\x00\x06$\x01\x00\x00\x00\x00\x08!\t\x14\n!\x0ba'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 3343
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 2420
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 996
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 20 value: -1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 16 value: 9961
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 1
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: single
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 85 value: 0.0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 61440 value: 117440765
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 23945.516808262164
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xd1\x0b\x03( \x04!\xa8C\x05!%\x00\x06$\x10\x00\x00\x00\x00\n!\x0bad\x10\x00\x0b!\xf0\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xa9\x0b\x03((\x04!\xa8\x13\x05!4\x00\x06$\x01\x00\x00\x00\x00\n!\x00\x00d\x10\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 194
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 29
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: d
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 65281 value: b'\x01!\xc7\x0b\x03(\x1a\x04!\xa8\x13\x05!%\x00\x06$\x01\x00\x00\x00\x00\n!\x00\x00d\x10\x01'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 33 value: 200
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 32 value: 30
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 0
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy_xbee.api] at command: AP (2,)
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'AP', b'\x02')
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x01AP\x02'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x01AP\x00'
2019-08-30 17:57:33 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:34 DEBUG (MainThread) [zigpy_xbee.api] at command: AO (3,)
2019-08-30 17:57:34 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'AO', b'\x03')
2019-08-30 17:57:34 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x02AO\x03'
2019-08-30 17:57:34 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x02AO\x00'
2019-08-30 17:57:34 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:36 DEBUG (MainThread) [zigpy_xbee.api] at command: SH ()
2019-08-30 17:57:36 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'SH', b'')
2019-08-30 17:57:36 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x03SH'
2019-08-30 17:57:37 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x03SH\x00\x00\x13\xa2\x00'
2019-08-30 17:57:37 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:38 DEBUG (MainThread) [zigpy_xbee.api] at command: SL ()
2019-08-30 17:57:38 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'SL', b'')
2019-08-30 17:57:38 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x04SL'
2019-08-30 17:57:39 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x04SL\x00A\x89d\x89'
2019-08-30 17:57:39 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:40 DEBUG (MainThread) [zigpy_xbee.api] at command: AI ()
2019-08-30 17:57:40 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'AI', b'')
2019-08-30 17:57:40 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x05AI'
2019-08-30 17:57:40 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x05AI\x00\x00'
2019-08-30 17:57:40 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:43 DEBUG (MainThread) [zigpy_xbee.api] at command: MY ()
2019-08-30 17:57:43 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'MY', b'')
2019-08-30 17:57:43 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x06MY'
2019-08-30 17:57:44 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x06MY\x00\x00\x00'
2019-08-30 17:57:44 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:45 DEBUG (MainThread) [zigpy_xbee.api] at command: EE ()
2019-08-30 17:57:45 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'EE', b'')
2019-08-30 17:57:45 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x07EE'
2019-08-30 17:57:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x07EE\x00\x01'
2019-08-30 17:57:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:46 DEBUG (MainThread) [zigpy_xbee.api] at command: EO ()
2019-08-30 17:57:46 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'EO', b'')
2019-08-30 17:57:46 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x08EO'
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x08EO\x00\x02'
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] at command: ZS ()
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'ZS', b'')
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\tZS'
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\tZS\x00\x02'
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] at command: NJ (0,)
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'NJ', b'\x00')
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\nNJ\x00'
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\nNJ\x00'
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] at command: SP (768,)
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'SP', b'\x03\x00')
2019-08-30 17:57:47 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x0bSP\x03\x00'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x0bSP\x00'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] at command: SN (667,)
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'SN', b'\x02\x9b')
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x0cSN\x02\x9b'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x0cSN\x00'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] at command: ID ()
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'ID', b'')
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\rID'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\rID\x00\x00\x00\x00\x00\x00\x00\x00\x00'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] at command: OP ()
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'OP', b'')
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x0eOP'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x0eOP\x00\xc6\x0fHZ25\xc5\xde'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] at command: OI ()
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'OI', b'')
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x0fOI'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x0fOI\x00\x92k'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] at command: CE ()
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'CE', b'')
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08\x10CE'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x10CE\x00\x01'
2019-08-30 17:57:48 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x28aa](lumi.sensor_magnet.aq2): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:ZDO](lumi.sensor_magnet.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet.aq2', ieee='00:15:8d:00:03:09:e2:76', last_seen=1567176729.5263941)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:ZDO](lumi.sensor_magnet.aq2): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x914d](lumi.vibration.aq1): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:ZDO](lumi.vibration.aq1): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.vibration.aq1', ieee='00:15:8d:00:02:b7:67:ed', last_seen=1567173724.5809295)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:ZDO](lumi.vibration.aq1): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0500]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0500]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:2:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x914d:2:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x28aa](lumi.sensor_magnet.aq2): power source: Battery or Unknown
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x28aa](lumi.sensor_magnet.aq2): completed initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x914d](lumi.vibration.aq1): power source: Battery or Unknown
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x914d](lumi.vibration.aq1): completed initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0067](lumi.sensor_cube.aqgl01): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:ZDO](lumi.sensor_cube.aqgl01): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_cube', ieee='00:15:8d:00:02:89:d4:e6', last_seen=1567174420.2200162)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:ZDO](lumi.sensor_cube.aqgl01): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0b71](lumi.weather): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:ZDO](lumi.weather): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.weather', ieee='00:15:8d:00:02:bf:98:0c', last_seen=1567175483.599192)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:ZDO](lumi.weather): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:2:0x0012]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:2:0x0012]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:2:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:2:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:3:0x000c]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:3:0x000c]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:3:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0067:3:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0402]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0402]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0403]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0403]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0405]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x0b71:1:0x0405]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0067](lumi.sensor_cube.aqgl01): power source: Battery or Unknown
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0067](lumi.sensor_cube.aqgl01): completed initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0b71](lumi.weather): power source: Battery or Unknown
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0b71](lumi.weather): completed initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x6c97](lumi.sensor_ht): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:ZDO](lumi.sensor_ht): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sens', ieee='00:15:8d:00:02:4a:2c:b3', last_seen=1567175013.957698)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:ZDO](lumi.sensor_ht): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xb75c](lumi.sensor_motion.aq2): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:ZDO](lumi.sensor_motion.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_motion.aq2', ieee='00:15:8d:00:03:2c:19:22', last_seen=1567176400.063304)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:ZDO](lumi.sensor_motion.aq2): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0402]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0402]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0405]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0405]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:2:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:2:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:3:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x6c97:3:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0400]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0400]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0406]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0406]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0500]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0500]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x6c97](lumi.sensor_ht): power source: Battery or Unknown
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x6c97](lumi.sensor_ht): completed initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xb75c](lumi.sensor_motion.aq2): power source: Battery or Unknown
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xb75c](lumi.sensor_motion.aq2): completed initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4851](lumi.sensor_magnet.aq2): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:ZDO](lumi.sensor_magnet.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet.aq2', ieee='00:15:8d:00:02:eb:d1:49', last_seen=1567176812.02543)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:ZDO](lumi.sensor_magnet.aq2): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] attempting to request fresh state for device - 0x610b:00:15:8d:00:02:71:22:d9 LUMI lumi.plug with power source: Mains
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x610b](lumi.plug): started initialization
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:ZDO](lumi.plug): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.plug', ieee='00:15:8d:00:02:71:22:d9', last_seen=1567176984.1855972)
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:ZDO](lumi.plug): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 1, 1, 6, 260, 0, 32, b'\x00\x01\x00\x00\x00')
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x11\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\x06\x01\x04\x00 \x00\x01\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 1, 1, 0, 260, 0, 32, b'\x00\x02\x00\x07\x00')
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x12\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\x00\x01\x04\x00 \x00\x02\x00\x07\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 2, 2, 12, 260, 0, 32, b'\x00\x03\x00U\x00')
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x13\x00\x15\x8d\x00\x02q"\xd9a\x0b\x02\x02\x00\x0c\x01\x04\x00 \x00\x03\x00U\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4851](lumi.sensor_magnet.aq2): power source: Battery or Unknown
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4851](lumi.sensor_magnet.aq2): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa309](lumi.sensor_switch): started initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:ZDO](lumi.sensor_switch): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_switch', ieee='00:15:8d:00:01:e7:f0:ff', last_seen=1567175622.851523)
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:ZDO](lumi.sensor_switch): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0008]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa309:1:0x0008]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x11a\x0b\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #17
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\x06\x01\x04 \x18\x01\x01\x00\x00\x00\x10\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 6, 32, b'1801010000001000')
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa309](lumi.sensor_switch): power source: Battery or Unknown
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa309](lumi.sensor_switch): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x12a\x0b\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #18
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8fce](lumi.sensor_switch): started initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:ZDO](lumi.sensor_switch): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_switch', ieee='00:15:8d:00:02:72:9d:4a', last_seen=1567174239.3785827)
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:ZDO](lumi.sensor_switch): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\x00\x01\x04 \x18\x02\x01\x07\x00\x000\x01'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 0, 32, b'1802010700003001')
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x13a\x0b\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #19
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x02\x02\x00\x0c\x01\x04 \x08\x03\x01U\x00\x009\x00\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 2, 12, 32, b'0803015500003900000000')
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0008]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x8fce:1:0x0008]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:1:0x0006]: initializing channel: from_cache: False
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8fce](lumi.sensor_switch): power source: Battery or Unknown
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8fce](lumi.sensor_switch): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 3, 3, 12, 260, 0, 32, b'\x00\x04\x00U\x00')
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x14\x00\x15\x8d\x00\x02q"\xd9a\x0b\x03\x03\x00\x0c\x01\x04\x00 \x00\x04\x00U\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:1:0x0000]: initializing channel: from_cache: False
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x95c9](lumi.sensor_motion): started initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:ZDO](lumi.sensor_motion): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_motion', ieee='00:15:8d:00:02:78:0f:43', last_seen=1567176255.1332238)
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:ZDO](lumi.sensor_motion): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:2:0x000c]: initializing channel: from_cache: False
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:2:0x000c]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x14a\x0b\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #20
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x03\x03\x00\x0c\x01\x04 \x08\x04\x01U\x00\x009\xb0_\xf6@'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 3, 12, 32, b'08040155000039b05ff640')
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0406]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0406]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0500]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0500]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x95c9:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x95c9](lumi.sensor_motion): power source: Battery or Unknown
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x95c9](lumi.sensor_motion): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xd092](lumi.sensor_magnet): started initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:ZDO](lumi.sensor_magnet): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet', ieee='00:15:8d:00:02:73:6f:62', last_seen=1567175320.298907)
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:ZDO](lumi.sensor_magnet): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:3:0x000c]: initializing channel: from_cache: False
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:3:0x000c]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0006]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0006]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0008]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0008]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x610b](lumi.plug): power source: Mains
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x610b](lumi.plug): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xd092](lumi.sensor_magnet): power source: Battery or Unknown
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xd092](lumi.sensor_magnet): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa50e](lumi.remote.b186acn01): started initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:ZDO](lumi.remote.b186acn01): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.remote.b186acn01', ieee='00:15:8d:00:02:a5:60:7a', last_seen=1567175985.2480543)
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:ZDO](lumi.remote.b186acn01): channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0000]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0000]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0001]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0001]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0012]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0012]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:1:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:2:0x0012]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:2:0x0012]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:2:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:2:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:3:0x0012]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:3:0x0012]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:3:0x0005]: initializing channel: from_cache: True
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa50e:3:0x0005]: channel: 'async_initialize' stage succeeded
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa50e](lumi.remote.b186acn01): power source: Battery or Unknown
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa50e](lumi.remote.b186acn01): completed initialization
2019-08-30 17:57:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x610b:1:0x0006]: attempting to update onoff state - from cache: False
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 1, 1, 6, 260, 0, 32, b'\x00\x05\x00\x00\x00')
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x15\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\x06\x01\x04\x00 \x00\x05\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x15a\x0b\x00\x00\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #21
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\x06\x01\x04 \x18\x05\x01\x00\x00\x00\x10\x00'
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:57:49 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 6, 32, b'1805010000001000')
2019-08-30 17:57:56 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xd092:1:0x0006]: attempting to update onoff state - from cache: True
2019-08-30 17:57:56 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4851:1:0x0006]: attempting to update onoff state - from cache: True
2019-08-30 17:57:56 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x28aa:1:0x0006]: attempting to update onoff state - from cache: True
2019-08-30 17:58:13 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\n\x01\x04\x00\x10\xf4\x00\x00\x00'
2019-08-30 17:58:13 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:58:13 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 10, 0, b'10f4000000')
2019-08-30 17:58:13 DEBUG (MainThread) [zigpy.zcl] [0x610b:1:0x000a] ZCL request 0x0000: [[0]]
2019-08-30 17:58:13 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 1, 1, 10, 260, 0, 32, b'\x08\x06\x01\x00\x00\x00#\x05\xf6\xfb$')
2019-08-30 17:58:13 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x16\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\n\x01\x04\x00 \x08\x06\x01\x00\x00\x00#\x05\xf6\xfb$'
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x16a\x0b\x00\x00\x00'
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #22
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\n\x01\x04\x00\x10\x06\x0b\x01\x00'
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 10, 0, b'10060b0100')
2019-08-30 17:58:14 DEBUG (MainThread) [zigpy.zcl] [0x610b:1:0x000a] Unexpected ZCL reply 0x000b: [1, <Status.SUCCESS: 0>]
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xff\xff\xff\xff\xff\xff\xff\xff\xb7\\\x01\x01\x04\x00\x01\x04\x00\x18*\n\x00\x00!\xa3\x00'
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (ff:ff:ff:ff:ff:ff:ff:ff, 0xb75c, 1, 1024, 0, b'182a0a000021a300')
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy.zcl] [0xb75c:1:0x0400] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=163>>]]
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy.zcl] [0xb75c:1:0x0400] Attribute report received: measured_value=163
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xff\xff\xff\xff\xff\xff\xff\xff\xb7\\\x01\x01\x04\x06\x01\x04\x00\x18+\n\x00\x00\x18\x01'
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (ff:ff:ff:ff:ff:ff:ff:ff, 0xb75c, 1, 1030, 0, b'182b0a00001801')
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy.zcl] [0xb75c:1:0x0406] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=bitmap8, value=1>>]]
2019-08-30 17:58:31 DEBUG (MainThread) [zigpy.zcl] [0xb75c:1:0x0406] Attribute report received: occupancy=1
2019-08-30 17:58:31 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb75c:1:0x0500]: Updated alarm state: 1
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\n\x01\x04\x00\x10)\x00\x00\x00'
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 10, 0, b'1029000000')
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy.zcl] [0x610b:1:0x000a] ZCL request 0x0000: [[0]]
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:15:8d:00:02:71:22:d9, 0x610b, 1, 1, 10, 260, 0, 32, b'\x08\x07\x01\x00\x00\x00#9\xf6\xfb$')
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x17\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\n\x01\x04\x00 \x08\x07\x01\x00\x00\x00#9\xf6\xfb$'
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x17a\x0b\x00\x00\x00'
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x610b: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #23
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02q"\xd9a\x0b\x01\x01\x00\n\x01\x04\x00\x10\x07\x0b\x01\x00'
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (00:15:8d:00:02:71:22:d9, 0x610b, 1, 10, 0, b'10070b0100')
2019-08-30 17:59:05 DEBUG (MainThread) [zigpy.zcl] [0x610b:1:0x000a] Unexpected ZCL reply 0x000b: [1, <Status.SUCCESS: 0>]

[Adminiuga]

hrm, in the last log, it is the lumi.plug requesting the time cluster, we reply and it is unexpectedly replying back to our "reply".

1. What model is it?
2. do you have a ssh dev access to hassio, in order to install python packages?

[stast1]

1. What model is it?

ZNCZ02LM

1. do you have a ssh dev access to hassio, in order to install python packages?

I have hass.io, I never installed packages ...

[Nemesis24]

It's the same for me, but with lumi.relay.c2acn01
https://github.com/zigpy/zigpy-deconz/issues/59

[Adminiuga]

It is a problem in zigpy:

1. we need to disable default response for ZCL replies https://github.com/zigpy/zigpy/issues/208
2. we actually need to use the same TSN for the replies as in the received request https://github.com/zigpy/zigpy/issues/209

[Adminiuga]

@stast1 @Nemesis24 if you want to test a fix, you need to do the following

1. backup and snapshot your system and most importantly the configuraiton
2. Get dev ssh hassio access https://developers.home-assistant.io/docs/en/hassio_debugging.html#ssh-access-to-the-host
3. uninstall upstream zigpy from HA container, by running the following shell command: docker container exec homeassistant pip3 uninstall -y zigpy-homeassistant
4. install test version of zigpy: docker container exec homeassistant pip3 install https://codeload.github.com/Adminiuga/zigpy/zip/dropin/default-rsp-control
5. restart HA container

[stast1]

@Adminiuga

It seems to work, but there was such a repeating error

2019-09-04 07:50:41 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback SerialTransport._read_ready()
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.7/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_xbee/uart.py", line 75, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.7/site-packages/zigpy_xbee/uart.py", line 83, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.7/site-packages/zigpy_xbee/api.py", line 273, in frame_received
    getattr(self, '_handle_%s' % (command, ))(*data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_xbee/api.py", line 327, in _handle_explicit_rx_indicator
    profile, rx_opts, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_xbee/zigbee/application.py", line 248, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy/application.py", line 82, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy/device.py", line 155, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy/endpoint.py", line 179, in deserialize
    return cluster.deserialize(data)
TypeError: deserialize() missing 4 required positional arguments: 'frame_type', 'is_reply', 'command_id', and 'data'

[stast1]

Rebooted HA again - the error disappeared ...

[Nemesis24]

I've got this for number 3:

docker: command not found

[stast1]

Rebooted HA again - the error disappeared ...

When rebooting, HA periodically climbs out ...

[Adminiuga]

TypeError: deserialize() missing 4 required positional
Yeah, it is quirks for xiaomi devices. I hate xiaomi for doing that.
I'll post an update for zha quirks.

[Adminiuga]

I've got this for number 3:

docker: command not found

Either you are not using hassio or you are not using hassio DEV ssh access, which is different from ssh add-on.

[Adminiuga]

TypeError: deserialize() missing 4 required positional arguments: 'frame_type', 'is_reply',

@stast1 install a patched branch of zha-quirks

1. uninstall upstream zha-quirks from HA container, by running the following shell command: docker container exec homeassistant pip3 uninstall -y zha-quirks
2. install test version of zha-quirks: docker container exec homeassistant pip3 install https://codeload.github.com/Adminiuga/zha-quirks/zip/fixes/zha-default-rsp
3. restart HA container

[Nemesis24]

I'm not using Hassio dev ssh access, but i don't understand how i can use it.

[stast1]

2. https://codeload.github.com/Adminiuga/zha-quirks/zip/fixes/zha-default-rsp

Error 404: Not Found

[stast1]

Found
https://codeload.github.com/Adminiuga/zha-device-handlers/zip/fixes/zha-default-rsp

[stast1]

When rebooting HA, there are no errors. I observe further :-)

[stast1]

2019-09-06 12:09:41 ERROR (MainThread) [zigpy_xbee.zigbee.application] Failed to parse message (b'1c5f11ac0a01ff421f0121c70b0328210421a8430521710006240100000000082109140a210b61') on cluster 0, because Data is too short
2019-09-06 12:59:45 ERROR (MainThread) [zigpy_xbee.zigbee.application] Failed to parse message (b'1c5f11ad0a01ff421f0121c70b0328210421a8430521710006240100000000082109140a210b61') on cluster 0, because Data is too short
2019-09-06 13:49:49 ERROR (MainThread) [zigpy_xbee.zigbee.application] Failed to parse message (b'1c5f11ae0a01ff421f0121c70b0328210421a8430521710006240100000000082109140a210b61') on cluster 0, because Data is too short

[Adminiuga]

yep, getting those too. lemme take a look...

[Adminiuga]

@stast1 yeah, that one was a stupid mistake on my side. Should have used tests. I pushed the new updates, uninstall & reinstall zha-quirks and let me know

[stast1]

@Adminiuga Ok

[stast1]

@Adminiuga So far so good, no mistakes

[stast1]

@Adminiuga Everything works great. Thank!

[dmulcahey]

@Adminiuga is this fixed in the latest libs?

[Adminiuga]

yes, for this particular reason. Should be in the dev shortly.

[Adminiuga]

will close when it hits the dev.

[dmulcahey]

Good to close now that #26746 hit dev? Or are there subsequent changes?

[Adminiuga]

Good to close. Fixed via #26746