I’m toggling the buttons physically, if i toggle it on HA the log shows:
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.states.onOff] OnOffKeypadLed._send_led_on_off_request was called
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Ending Device._send_msg
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Starting 50.A2.74 Device._process_send_queue
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Lock is locked from yield from
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.f8.00.00.00.00.00.00.00.00.00.00.d0, 'acknak': 0xNone}
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Ending 50.A2.74 Device._process_send_queue
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.f8.00.00.00.00.00.00.00.00.00.00.d0, 'acknak': 0xNone}
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.222:25105/3?026250a274102e000109f800000000000000000000d0=I=3
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm] Post status: 200
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm] Buffer from 0 to 46
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm] New buffer: 026250A274102E000109F800000000000000000000D006
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Received 23 bytes from PLM: b'026250a274102e000109f800000000000000000000d006'
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'026250a274102e000109f800000000000000000000d006'
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.f8.00.00.00.00.00.00.00.00.00.00.d0, 'acknak': 0x06}
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Look for direct ACK
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2019-07-08 09:49:42 DEBUG (MainThread) [insteonplm.devices] Starting Device._wait_for_direct_ACK
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm] Buffer from 46 to 68
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm] New buffer: 025050A2744CFB6F252E00
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Received 11 bytes from PLM: b'025050a2744cfb6f252e00'
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'025050a2744cfb6f252e00'
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x25, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK message
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Direct ACK: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x25, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Releasing lock after processing direct ACK
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Device 50.A2.74 msg_lock unlocked
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 1 was off now is off
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 1
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 2 was off now is off
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 2
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 was on now is off
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315490>>
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 LED changed from 1 to 0
2019-07-08 09:49:43 DEBUG (MainThread) [homeassistant.components.insteon] Received update for device 50.A2.74 group 3 value 0
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 was on now is on
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315fb0>>
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 LED changed from 1 to 1
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 was on now is on
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319950>>
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 LED changed from 1 to 1
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 was on now is on
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319f30>>
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 LED changed from 1 to 1
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 7 was on now is on
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 7
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] Button 8 was on now is on
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 8
2019-07-08 09:49:43 DEBUG (MainThread) [insteonplm.devices] Ending Device._wait_for_direct_ACK
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.states.onOff] OnOffKeypadLed._send_led_on_off_request was called
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Ending Device._send_msg
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Starting 50.A2.74 Device._process_send_queue
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Lock is locked from yield from
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.f0.00.00.00.00.00.00.00.00.00.00.d8, 'acknak': 0xNone}
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Ending 50.A2.74 Device._process_send_queue
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.f0.00.00.00.00.00.00.00.00.00.00.d8, 'acknak': 0xNone}
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.222:25105/3?026250a274102e000109f000000000000000000000d8=I=3
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm] Post status: 200
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm] Buffer from 0 to 46
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm] New buffer: 026250A274102E000109F000000000000000000000D806
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Received 23 bytes from PLM: b'026250a274102e000109f000000000000000000000d806'
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'026250a274102e000109f000000000000000000000d806'
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.f0.00.00.00.00.00.00.00.00.00.00.d8, 'acknak': 0x06}
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Look for direct ACK
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2019-07-08 09:49:50 DEBUG (MainThread) [insteonplm.devices] Starting Device._wait_for_direct_ACK
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm] Buffer from 46 to 68
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm] New buffer: 025050A2744CFB6F252E00
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Received 11 bytes from PLM: b'025050a2744cfb6f252e00'
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'025050a2744cfb6f252e00'
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x25, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK message
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Direct ACK: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x25, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Releasing lock after processing direct ACK
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Device 50.A2.74 msg_lock unlocked
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 1 was off now is off
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 1
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 2 was off now is off
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 2
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 was off now is off
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315490>>
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 LED changed from 0 to 0
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 was on now is off
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315fb0>>
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 LED changed from 1 to 0
2019-07-08 09:49:51 DEBUG (MainThread) [homeassistant.components.insteon] Received update for device 50.A2.74 group 4 value 0
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 was on now is on
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319950>>
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 LED changed from 1 to 1
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 was on now is on
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319f30>>
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 LED changed from 1 to 1
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 7 was on now is on
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 7
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] Button 8 was on now is on
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 8
2019-07-08 09:49:51 DEBUG (MainThread) [insteonplm.devices] Ending Device._wait_for_direct_ACK
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.states.onOff] OnOffKeypadLed._send_led_on_off_request was called
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Ending Device._send_msg
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Starting 50.A2.74 Device._process_send_queue
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Lock is locked from yield from
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.e0.00.00.00.00.00.00.00.00.00.00.e8, 'acknak': 0xNone}
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Ending 50.A2.74 Device._process_send_queue
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.e0.00.00.00.00.00.00.00.00.00.00.e8, 'acknak': 0xNone}
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.222:25105/3?026250a274102e000109e000000000000000000000e8=I=3
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm] Post status: 200
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm] Buffer from 0 to 46
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm] New buffer: 026250A274102E000109E000000000000000000000E806
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Received 23 bytes from PLM: b'026250a274102e000109e000000000000000000000e806'
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'026250a274102e000109e000000000000000000000e806'
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.e0.00.00.00.00.00.00.00.00.00.00.e8, 'acknak': 0x06}
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Look for direct ACK
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2019-07-08 09:49:56 DEBUG (MainThread) [insteonplm.devices] Starting Device._wait_for_direct_ACK
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm] Buffer from 46 to 68
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm] New buffer: 025050A2744CFB6F252E00
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Received 11 bytes from PLM: b'025050a2744cfb6f252e00'
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'025050a2744cfb6f252e00'
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x25, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK message
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Direct ACK: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x25, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Releasing lock after processing direct ACK
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Device 50.A2.74 msg_lock unlocked
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 1 was off now is off
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 1
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 2 was off now is off
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 2
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 was off now is off
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315490>>
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 LED changed from 0 to 0
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 was off now is off
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315fb0>>
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 LED changed from 0 to 0
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 was on now is off
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319950>>
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 LED changed from 1 to 0
2019-07-08 09:49:57 DEBUG (MainThread) [homeassistant.components.insteon] Received update for device 50.A2.74 group 5 value 0
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 was on now is on
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319f30>>
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 LED changed from 1 to 1
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 7 was on now is on
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 7
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] Button 8 was on now is on
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 8
2019-07-08 09:49:57 DEBUG (MainThread) [insteonplm.devices] Ending Device._wait_for_direct_ACK
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] OnOffKeypadLed._send_led_on_off_request was called
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Ending Device._send_msg
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Starting 50.A2.74 Device._process_send_queue
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Lock is locked from yield from
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.c0.00.00.00.00.00.00.00.00.00.00.08, 'acknak': 0xNone}
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Ending 50.A2.74 Device._process_send_queue
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.c0.00.00.00.00.00.00.00.00.00.00.08, 'acknak': 0xNone}
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.222:25105/3?026250a274102e000109c00000000000000000000008=I=3
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm] Post status: 200
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm] Buffer from 0 to 68
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm] New buffer: 026250A274102E000109C0000000000000000000000806025050A2744CFB6F202E00
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Received 34 bytes from PLM: b'026250a274102e000109c0000000000000000000000806025050a2744cfb6f202e00'
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'026250a274102e000109c0000000000000000000000806025050a2744cfb6f202e00'
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'025050a2744cfb6f202e00'
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 2
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x62, 'address': 50.A2.74, 'flags': 0x10, 'cmd1': 0x2e, 'cmd2': 0x00, 'userdata': 0x01.09.c0.00.00.00.00.00.00.00.00.00.00.08, 'acknak': 0x06}
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Look for direct ACK
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x20, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Starting Device._wait_for_direct_ACK
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Direct ACK: {'code': 0x50, 'address': 50.A2.74, 'target': 4C.FB.6F, 'flags': 0x20, 'cmd1': 0x2e, 'cmd2': 0x00}
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Releasing lock after processing direct ACK
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Device 50.A2.74 msg_lock unlocked
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 1 was off now is off
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 1
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 2 was off now is off
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 2
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 was off now is off
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315490>>
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 3 LED changed from 0 to 0
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 was off now is off
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f315fb0>>
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 4 LED changed from 0 to 0
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 was off now is off
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319950>>
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 5 LED changed from 0 to 0
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 was on now is off
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Calling button update callback <bound method OnOffKeypad.led_changed of <insteonplm.states.onOff.OnOffKeypad object at 0x6f319f30>>
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 6 LED changed from 1 to 0
2019-07-08 09:49:59 DEBUG (MainThread) [homeassistant.components.insteon] Received update for device 50.A2.74 group 6 value 0
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 7 was on now is on
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 7
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] Button 8 was on now is on
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.states.onOff] No callbacks found for button 8
2019-07-08 09:49:59 DEBUG (MainThread) [insteonplm.devices] Ending Device._wait_for_direct_ACK