2018-08-19 12:08:10 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Received {'type': 'call_service', 'domain': 'zha', 'service': 'permit', 'service_data': {'duration': 120}, 'id': 14}
2018-08-19 12:08:10 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=zha, service=permit, service_data=duration=120>
2018-08-19 12:08:10 INFO (MainThread) [homeassistant.components.zha] Permitting joins for 120s
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] AT command: NJ (120,)
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] Command at (7, b'NJ', b'x')
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x07NJ\x00'
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] AT command: AC ()
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] Command at (8, b'AC', b'')
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\x08AC\x00'
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] AT command: CB (2,)
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] Command at (9, b'CB', b'\x02')
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88\tCB\x00'
2018-08-19 12:08:10 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2018-08-19 12:08:10 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]>
2018-08-19 12:08:10 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 14, 'type': 'result', 'success': True, 'result': None}
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x00\x13\x00\x00\x02\xb0m9\x08\x1c\x16\x02\x00\x8d\x15\x00\x8e'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=2
2018-08-19 12:08:30 INFO (MainThread) [zigpy.application] Device 0x396d (00:15:8d:00:02:16:1c:08) joined the network
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy.zdo] [0x396d:zdo] ZDO request 0x0013: [14701, 00:15:8d:00:02:16:1c:08, 142]
2018-08-19 12:08:30 INFO (MainThread) [zigpy.device] [0x396d] Discovering endpoints
Tries remaining: 3
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 1
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 0, 0, 5, 0, 0, 32, b'\x01m9')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (10, 00:15:8d:00:02:16:1c:08, 14701, 0, 0, 5, 0, 0, 32, b'\x01m9')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\n9m\x00\x00\x00'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [10, 14701, 0, 0, 0]
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x80\x05\x00\x00\x01\x01\x00m9\x04\x01\x02\x03d'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=1
2018-08-19 12:08:30 INFO (MainThread) [zigpy.device] [0x396d] Discovered endpoints: [1, 2, 3, 100]
2018-08-19 12:08:30 INFO (MainThread) [zigpy.endpoint] [0x396d:1] Discovering endpoint information
Tries remaining: 3
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 2
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x02m9\x01')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (11, 00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x02m9\x01')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\x00\x01\x04\x00\x18\xcd\n\x05\x00B\tlumi.plug\x01\x00 \x01'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=0
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy.endpoint] Ignoring unknown cluster ID 0x0000
2018-08-19 12:08:30 WARNING (MainThread) [zigpy_xbee.zigbee.application] Unexpected response TSN=205 command=266 args=b'\x05\x00B\tlumi.plug\x01\x00 \x01'
2018-08-19 12:08:30 WARNING (MainThread) [zigpy.endpoint] [0x396d:1] Message on unknown cluster 0x0000
2018-08-19 12:08:30 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2018-08-20T02:49:01+00:00, next_dusk=2018-08-19T17:27:12+00:00, next_midnight=2018-08-19T22:07:15+00:00, next_noon=2018-08-19T10:07:34+00:00, next_rising=2018-08-20T03:18:09+00:00, next_setting=2018-08-19T16:57:59+00:00, elevation=58.73, azimuth=150.95, friendly_name=Sun @ 2018-08-19T12:06:25.971401+03:00>, new_state=<state sun.sun=above_horizon; next_dawn=2018-08-20T02:49:01+00:00, next_dusk=2018-08-19T17:27:12+00:00, next_midnight=2018-08-19T22:07:15+00:00, next_noon=2018-08-19T10:07:34+00:00, next_rising=2018-08-20T03:18:09+00:00, next_setting=2018-08-19T16:57:59+00:00, elevation=58.82, azimuth=151.38, friendly_name=Sun @ 2018-08-19T12:06:25.971401+03:00>>
2018-08-19 12:08:30 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sun.sun', 'old_state': <state sun.sun=above_horizon; next_dawn=2018-08-20T02:49:01+00:00, next_dusk=2018-08-19T17:27:12+00:00, next_midnight=2018-08-19T22:07:15+00:00, next_noon=2018-08-19T10:07:34+00:00, next_rising=2018-08-20T03:18:09+00:00, next_setting=2018-08-19T16:57:59+00:00, elevation=58.73, azimuth=150.95, friendly_name=Sun @ 2018-08-19T12:06:25.971401+03:00>, 'new_state': <state sun.sun=above_horizon; next_dawn=2018-08-20T02:49:01+00:00, next_dusk=2018-08-19T17:27:12+00:00, next_midnight=2018-08-19T22:07:15+00:00, next_noon=2018-08-19T10:07:34+00:00, next_rising=2018-08-20T03:18:09+00:00, next_setting=2018-08-19T16:57:59+00:00, elevation=58.82, azimuth=151.38, friendly_name=Sun @ 2018-08-19T12:06:25.971401+03:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 30, 726845, tzinfo=<UTC>), 'context': {'id': 'ab5eaabdca3547f2bb92054971d4ded3', 'user_id': None}}}
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\n\x01\x04\x00\x10\xce\x00\x00\x00'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=0
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy.endpoint] Ignoring unknown cluster ID 0x000a
2018-08-19 12:08:30 WARNING (MainThread) [zigpy.endpoint] [0x396d:1] Message on unknown cluster 0x000a
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x0b9m\x00\x00\x00'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [11, 14701, 0, 0, 0]
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x80\x04\x00\x00\x01\x02\x00m9\x1e\x01\x04\x01Q\x00\x01\t\x00\x00\x04\x00\x03\x00\x06\x00\x10\x00\x05\x00\n\x00\x01\x00\x02\x00\x02\x19\x00\n\x00'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=1
2018-08-19 12:08:30 INFO (MainThread) [zigpy.endpoint] [0x396d:1] Discovered endpoint information: <SimpleDescriptor endpoint=1 profile=260 device_type=81 device_version=1 input_clusters=[0, 4, 3, 6, 16, 5, 10, 1, 2] output_clusters=[25, 10]>
2018-08-19 12:08:30 INFO (MainThread) [zigpy.endpoint] [0x396d:2] Discovering endpoint information
Tries remaining: 3
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 3
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x03m9\x02')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (12, 00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x03m9\x02')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x0c9m\x00\x00\x00'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [12, 14701, 0, 0, 0]
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x80\x04\x00\x00\x01\x03\x00m9\x0e\x02\x04\x01\t\x00\x01\x01\x0c\x00\x02\x0c\x00\x04\x00'
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=1
2018-08-19 12:08:30 INFO (MainThread) [zigpy.endpoint] [0x396d:2] Discovered endpoint information: <SimpleDescriptor endpoint=2 profile=260 device_type=9 device_version=1 input_clusters=[12] output_clusters=[12, 4]>
2018-08-19 12:08:30 INFO (MainThread) [zigpy.endpoint] [0x396d:3] Discovering endpoint information
Tries remaining: 3
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 4
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x04m9\x03')
2018-08-19 12:08:30 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (13, 00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x04m9\x03')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\r9m\x00\x00\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [13, 14701, 0, 0, 0]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x80\x04\x00\x00\x01\x04\x00m9\x0c\x03\x04\x01S\x00\x01\x01\x0c\x00\x01\x0c\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=1
2018-08-19 12:08:31 INFO (MainThread) [zigpy.endpoint] [0x396d:3] Discovered endpoint information: <SimpleDescriptor endpoint=3 profile=260 device_type=83 device_version=1 input_clusters=[12] output_clusters=[12]>
2018-08-19 12:08:31 INFO (MainThread) [zigpy.endpoint] [0x396d:100] Discovering endpoint information
Tries remaining: 3
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 5
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x05m9d')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (14, 00:15:8d:00:02:16:1c:08, 14701, 0, 0, 4, 0, 0, 32, b'\x05m9d')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x0e9m\x00\x00\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [14, 14701, 0, 0, 0]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x80\x04\x00\x00\x01\x05\x00m9\x0ed\x04\x01\x07\x01\x02\x01\x0f\x00\x02\x0f\x00\x04\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=1
2018-08-19 12:08:31 INFO (MainThread) [zigpy.endpoint] [0x396d:100] Discovered endpoint information: <SimpleDescriptor endpoint=100 profile=260 device_type=263 device_version=2 input_clusters=[15] output_clusters=[15, 4]>
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Considering <class 'zigpy.quirks.xiaomi.TemperatureHumiditySensor'>
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Fail because endpoint list mismatch: dict_keys([1, 2, 3]) {1, 2, 3, 100}
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Considering <class 'zigpy.quirks.xiaomi.AqaraTemperatureHumiditySensor'>
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Fail because endpoint list mismatch: dict_keys([1]) {1, 2, 3, 100}
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Considering <class 'zigpy.quirks.xiaomi.AqaraOpenCloseSensor'>
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Fail because endpoint list mismatch: dict_keys([1]) {1, 2, 3, 100}
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Considering <class 'zigpy.quirks.xiaomi.AqaraWaterSensor'>
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.quirks] Fail because endpoint list mismatch: dict_keys([1]) {1, 2, 3, 100}
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 6
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 1, 1, 0, 260, 0, 32, b'\x00\x06\x00\x04\x00\x05\x00')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (15, 00:15:8d:00:02:16:1c:08, 14701, 1, 1, 0, 260, 0, 32, b'\x00\x06\x00\x04\x00\x05\x00')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x0f9m\x00\x00\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [15, 14701, 0, 0, 0]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\x00\x01\x04 \x18\x06\x01\x04\x00\x00B\x04LUMI\x05\x00\x00B\tlumi.plug'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=32
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.loader] Loaded switch from homeassistant.components.switch
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.setup] Setting up switch
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=turn_off>
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=turn_on>
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=toggle>
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.setup] Setup of domain switch took 0.0 seconds.
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=switch>
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.switch, platform=zha, discovered=discovery_key=00:15:8d:00:02:16:1c:08-1>
2018-08-19 12:08:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 5, 'type': 'event', 'event': {'event_type': 'service_registered', 'data': {'domain': 'switch', 'service': 'turn_off'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 31, 504128, tzinfo=<UTC>), 'context': {'id': '63eb09e1c0a948dd94ff50b46a0d1fac', 'user_id': None}}}
2018-08-19 12:08:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 5, 'type': 'event', 'event': {'event_type': 'service_registered', 'data': {'domain': 'switch', 'service': 'turn_on'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 31, 504380, tzinfo=<UTC>), 'context': {'id': '95b7c0c964914a1da0a29fc02716745f', 'user_id': None}}}
2018-08-19 12:08:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 5, 'type': 'event', 'event': {'event_type': 'service_registered', 'data': {'domain': 'switch', 'service': 'toggle'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 31, 504618, tzinfo=<UTC>), 'context': {'id': 'b3d592fea9b44d72bc38c19ecc9be53b', 'user_id': None}}}
2018-08-19 12:08:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 4, 'type': 'event', 'event': {'event_type': 'component_loaded', 'data': {'component': 'switch'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 31, 504932, tzinfo=<UTC>), 'context': {'id': '9f77370741d74966b42263a2c403003f', 'user_id': None}}}
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.loader] Loaded switch.zha from homeassistant.components.switch.zha
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.components.switch] Setting up switch.zha
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 7
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 0, 0, 33, 0, 0, 32, b'\x07\x08\x1c\x16\x02\x00\x8d\x15\x00\x01\x06\x00\x03\xd5\x83%A\x00\xa2\x13\x00\x01')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (16, 00:15:8d:00:02:16:1c:08, 14701, 0, 0, 33, 0, 0, 32, b'\x07\x08\x1c\x16\x02\x00\x8d\x15\x00\x01\x06\x00\x03\xd5\x83%A\x00\xa2\x13\x00\x01')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x109m\x00\x00\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [16, 14701, 0, 0, 0]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x00\x00\x80!\x00\x00\x01\x07\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=1
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 8
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 1, 1, 6, 260, 0, 32, b'\x00\x08\x06\x00\x00\x00\x10\x00\x00X\x02')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (17, 00:15:8d:00:02:16:1c:08, 14701, 1, 1, 6, 260, 0, 32, b'\x00\x08\x06\x00\x00\x00\x10\x00\x00X\x02')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x119m\x00\x00\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [17, 14701, 0, 0, 0]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\x06\x01\x04 \x18\x08\x07\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=32
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request seq 9
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Sequenced command: tx_explicit (00:15:8d:00:02:16:1c:08, 14701, 1, 1, 6, 260, 0, 32, b'\x00\t\x00\x00\x00')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (18, 00:15:8d:00:02:16:1c:08, 14701, 1, 1, 6, 260, 0, 32, b'\x00\t\x00\x00\x00')
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b"\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\x00\x01\x04\x00\x1c_\x11\xd0\n\x01\xffB1d\x10\x00\x03(,\x989\x00\x00\x00\x00\x959\x00\x00\x00\x00\x96#\xc4\x08\x00\x00\x05!\x07\x00\x9a \x10\x08!\x16\x13\x07'\x00\x00\x00\x00\x00\x00\x00\x00\t!\x00\x01"
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=0
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.zcl] [0x396d:1:0x0000] ZCL request 0x000a: [[<Attribute attrid=65281 value=<zigpy.zcl.foundation.TypeValue object at 0x7fc51017ac50>>]]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy.zcl] [0x396d:1:0x0000] Attribute report received: 65281=b"d\x10\x00\x03(,\x989\x00\x00\x00\x00\x959\x00\x00\x00\x00\x96#\xc4\x08\x00\x00\x05!\x07\x00\x9a \x10\x08!\x16\x13\x07'\x00\x00\x00\x00\x00\x00\x00\x00\t!\x00\x01"
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x129m\x00\x00\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] tx_status: [18, 14701, 0, 0, 0]
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\x06\x01\x04 \x18\t\x01\x00\x00\x00\x10\x00'
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:31 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=32
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new switch.zha entity: switch.lumi_lumiplug_02161c08_1
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.lumi_lumiplug_02161c08_1, old_state=None, new_state=<state switch.lumi_lumiplug_02161c08_1=off; friendly_name=LUMI lumi.plug @ 2018-08-19T12:08:31.888504+03:00>>
2018-08-19 12:08:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'switch.lumi_lumiplug_02161c08_1', 'old_state': None, 'new_state': <state switch.lumi_lumiplug_02161c08_1=off; friendly_name=LUMI lumi.plug @ 2018-08-19T12:08:31.888504+03:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 31, 888532, tzinfo=<UTC>), 'context': {'id': '113434c835c64f0e8048f0bb83cb23bc', 'user_id': None}}}
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=group, service=set, service_data=object_id=all_switches, name=all switches, entities=['switch.lumi_lumiplug_02161c08_1'], visible=False>
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_switches, old_state=None, new_state=<state group.all_switches=off; entity_id=('switch.lumi_lumiplug_02161c08_1',), order=0, auto=True, friendly_name=all switches, hidden=True @ 2018-08-19T12:08:31.891619+03:00>>
2018-08-19 12:08:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140484382849456: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'group.all_switches', 'old_state': None, 'new_state': <state group.all_switches=off; entity_id=('switch.lumi_lumiplug_02161c08_1',), order=0, auto=True, friendly_name=all switches, hidden=True @ 2018-08-19T12:08:31.891619+03:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 8, 19, 9, 8, 31, 891645, tzinfo=<UTC>), 'context': {'id': '78d5deb20da44265a953a2be5cb65df9', 'user_id': None}}}
2018-08-19 12:08:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]>
2018-08-19 12:08:32 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\x00\x15\x8d\x00\x02\x16\x1c\x089m\x01\x01\x00\x06\x01\x04\x00\x18M\n\x00\x00\x10\x00'
2018-08-19 12:08:32 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2018-08-19 12:08:32 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: opts=0
2018-08-19 12:08:32 DEBUG (MainThread) [zigpy.zcl] [0x396d:1:0x0006] ZCL request 0x000a: [[<Attribute attrid=0 value=<zigpy.zcl.foundation.TypeValue object at 0x7fc5185e53c8>>]]
2018-08-19 12:08:32 DEBUG (MainThread) [zigpy.zcl] [0x396d:1:0x0006] Attribute report received: 0=Bool.false
2018-08-19 12:08:32 DEBUG (MainThread) [homeassistant.components.switch.zha] Attribute updated: <Entity None: off> 0 Bool.false
At this point, I can see and control the state of the switch on GUI, and the gui gets updated when I press the physical on/off button on the plug itself:
After this I restart home assistant, and zha / zigpy throws the exception - please note that the KeyError referenced is the network address (nwk, 14701) of the end device:
After this, home assistant starts, but there is no switch on the gui. I've tried to press the physical button on the plug, it is still paired:
I've also tried with a xiaomi aqara switch, the issue is the same. I have this setup ready, I can test code & provide other info.