search

TD22057 / insteon-mqtt

Python Insteon PLM <-> MQTT bridge
GNU General Public License v3.0
99 stars 43 forks source link

Dumping the database using the ISY994, it does it one record at a time. #233

Closed jonsmirl closed 3 years ago

jonsmirl commented 4 years ago

Note that the ISY994 reads the database one record at a time and does not use the DUMP ALL option. I am unable to pair this device using insteon-mqtt. It is a fairly recent 2334-2 KeypadLinc Dimmer 5 Buttons v.43

Thu 11/26/2020 03:52:27 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F FF 01 00 00 00 00 00 00 00 00 C2 Thu 11/26/2020 03:52:27 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F FF 01 00 00 00 00 00 00 00 00 C2 06 (00) Thu 11/26/2020 03:52:28 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:28 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:28 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:28 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:28 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F FF 20 A2 48 3C 48 88 FF 1F 06 88 Thu 11/26/2020 03:52:28 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:28 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F F7 01 00 00 00 00 00 00 00 00 CA Thu 11/26/2020 03:52:28 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F F7 01 00 00 00 00 00 00 00 00 CA 06 (00) Thu 11/26/2020 03:52:29 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:29 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:29 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:29 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:29 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 15 2F 00 00 01 0F F7 20 A2 48 3C 48 88 FF 1F 05 91 Thu 11/26/2020 03:52:29 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=1 Thu 11/26/2020 03:52:29 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F EF 01 00 00 00 00 00 00 00 00 D2 Thu 11/26/2020 03:52:29 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F EF 01 00 00 00 00 00 00 00 00 D2 06 (00) Thu 11/26/2020 03:52:32 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:32 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:32 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:32 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:32 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F EF 20 A2 48 3C 48 88 FF 1F 04 9A Thu 11/26/2020 03:52:32 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:32 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F E7 01 00 00 00 00 00 00 00 00 DA Thu 11/26/2020 03:52:32 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F E7 01 00 00 00 00 00 00 00 00 DA 06 (00) Thu 11/26/2020 03:52:32 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 16 2F 00 00 01 0F EF 20 A2 48 3C 48 88 FF 1F 04 9A Thu 11/26/2020 03:52:32 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=1 Thu 11/26/2020 03:52:32 PM : [Ext MH ] Unexpected Response (i.e. DB range): ignored Thu 11/26/2020 03:52:33 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:33 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:34 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F E7 20 A2 48 3C 48 88 FF 1F 03 A3 Thu 11/26/2020 03:52:34 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:34 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F DF 01 00 00 00 00 00 00 00 00 E2 Thu 11/26/2020 03:52:34 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F DF 01 00 00 00 00 00 00 00 00 E2 06 (00) Thu 11/26/2020 03:52:34 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:34 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:35 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:35 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:35 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F DF 20 A2 3F 3C 48 88 FF 1F 06 B1 Thu 11/26/2020 03:52:35 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:35 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F D7 01 00 00 00 00 00 00 00 00 EA Thu 11/26/2020 03:52:35 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F D7 01 00 00 00 00 00 00 00 00 EA 06 (00) Thu 11/26/2020 03:52:35 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:35 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:36 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F D7 20 A2 3E 3C 48 88 FF 1F 03 BD Thu 11/26/2020 03:52:36 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:36 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F CF 01 00 00 00 00 00 00 00 00 F2 Thu 11/26/2020 03:52:36 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F CF 01 00 00 00 00 00 00 00 00 F2 06 (00) Thu 11/26/2020 03:52:36 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:36 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:37 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F CF 20 A2 3D 3C 48 88 FF 1F 04 C5 Thu 11/26/2020 03:52:37 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:37 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F C7 01 00 00 00 00 00 00 00 00 FA Thu 11/26/2020 03:52:37 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F C7 01 00 00 00 00 00 00 00 00 FA 06 (00) Thu 11/26/2020 03:52:37 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 16 2F 00 00 01 0F CF 20 A2 3D 3C 48 88 FF 1F 04 C5 Thu 11/26/2020 03:52:37 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=1 Thu 11/26/2020 03:52:37 PM : [Ext MH ] Unexpected Response (i.e. DB range): ignored Thu 11/26/2020 03:52:38 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:38 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:38 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:38 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:38 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 15 2F 00 00 01 0F C7 20 A2 3F 3C 48 88 FF 1F 01 CE Thu 11/26/2020 03:52:38 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=1 Thu 11/26/2020 03:52:38 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F BF 01 00 00 00 00 00 00 00 00 02 Thu 11/26/2020 03:52:38 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F BF 01 00 00 00 00 00 00 00 00 02 06 (00) Thu 11/26/2020 03:52:39 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:39 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:39 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F BF 20 A2 48 3C 48 88 D8 1C 01 F7 Thu 11/26/2020 03:52:39 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:39 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F B7 01 00 00 00 00 00 00 00 00 0A Thu 11/26/2020 03:52:40 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F B7 01 00 00 00 00 00 00 00 00 0A 06 (00) Thu 11/26/2020 03:52:40 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:40 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:41 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F B7 20 A2 3E 3C 48 88 FF 1F 01 DF Thu 11/26/2020 03:52:41 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:41 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F AF 01 00 00 00 00 00 00 00 00 12 Thu 11/26/2020 03:52:41 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F AF 01 00 00 00 00 00 00 00 00 12 06 (00) Thu 11/26/2020 03:52:41 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:41 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:42 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F AF 20 A2 3D 3C 48 88 FF 1F 01 E8 Thu 11/26/2020 03:52:42 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:42 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F A7 01 00 00 00 00 00 00 00 00 1A Thu 11/26/2020 03:52:42 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F A7 01 00 00 00 00 00 00 00 00 1A 06 (00) Thu 11/26/2020 03:52:42 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:42 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:43 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F A7 20 A2 00 3C 48 88 FF 1F 01 2D Thu 11/26/2020 03:52:43 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:43 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 9F 01 00 00 00 00 00 00 00 00 22 Thu 11/26/2020 03:52:43 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 9F 01 00 00 00 00 00 00 00 00 22 06 (00) Thu 11/26/2020 03:52:43 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:43 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:44 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:44 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:44 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 9F 20 E2 01 3C 48 88 FF 1F 01 F4 Thu 11/26/2020 03:52:44 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:44 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 97 01 00 00 00 00 00 00 00 00 2A Thu 11/26/2020 03:52:44 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 97 01 00 00 00 00 00 00 00 00 2A 06 (00) Thu 11/26/2020 03:52:46 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:46 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:46 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:46 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:47 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 15 2F 00 00 01 0F 97 20 E2 03 12 DE B9 01 00 03 78 Thu 11/26/2020 03:52:47 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=1 Thu 11/26/2020 03:52:47 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 8F 01 00 00 00 00 00 00 00 00 32 Thu 11/26/2020 03:52:47 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 8F 01 00 00 00 00 00 00 00 00 32 06 (00) Thu 11/26/2020 03:52:47 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:47 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:47 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:47 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:48 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 16 2F 00 00 01 0F 8F 20 E2 03 3C 48 88 FF 1F 03 00 Thu 11/26/2020 03:52:48 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=1 Thu 11/26/2020 03:52:48 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 87 01 00 00 00 00 00 00 00 00 3A Thu 11/26/2020 03:52:48 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 87 01 00 00 00 00 00 00 00 00 3A 06 (00) Thu 11/26/2020 03:52:49 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:49 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:49 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:49 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:49 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 1A 2F 00 00 01 0F 87 20 E2 03 50 D0 2C 01 00 03 E5 Thu 11/26/2020 03:52:49 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=2 Thu 11/26/2020 03:52:49 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 7F 01 00 00 00 00 00 00 00 00 42 Thu 11/26/2020 03:52:50 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 7F 01 00 00 00 00 00 00 00 00 42 06 (00) Thu 11/26/2020 03:52:50 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:50 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:51 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 7F 20 E2 03 50 D0 7E 01 00 03 9B Thu 11/26/2020 03:52:51 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:51 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 77 01 00 00 00 00 00 00 00 00 4A Thu 11/26/2020 03:52:51 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 77 01 00 00 00 00 00 00 00 00 4A 06 (00) Thu 11/26/2020 03:52:51 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:51 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:52 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 77 20 E2 03 52 76 08 01 00 03 71 Thu 11/26/2020 03:52:52 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:52 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 6F 01 00 00 00 00 00 00 00 00 52 Thu 11/26/2020 03:52:52 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 6F 01 00 00 00 00 00 00 00 00 52 06 (00) Thu 11/26/2020 03:52:52 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:52:52 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:52:53 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:52:53 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:52:53 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 6F 20 E2 03 52 D6 CC 01 00 03 55 Thu 11/26/2020 03:52:53 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:53 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 67 01 00 00 00 00 00 00 00 00 5A Thu 11/26/2020 03:52:53 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 67 01 00 00 00 00 00 00 00 00 5A 06 (00) Thu 11/26/2020 03:52:54 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:54 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:54 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 16 2F 00 00 01 0F 67 20 E2 04 13 3A 7A 01 00 04 88 Thu 11/26/2020 03:52:54 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=1 Thu 11/26/2020 03:52:54 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 5F 01 00 00 00 00 00 00 00 00 62 Thu 11/26/2020 03:52:54 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 5F 01 00 00 00 00 00 00 00 00 62 06 (00) Thu 11/26/2020 03:52:55 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:52:55 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:52:56 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 5F 20 E2 04 3C 48 88 FF 1F 04 2E Thu 11/26/2020 03:52:56 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:52:56 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 57 01 00 00 00 00 00 00 00 00 6A Thu 11/26/2020 03:52:56 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 57 01 00 00 00 00 00 00 00 00 6A 06 (00) Thu 11/26/2020 03:52:57 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 17 2F 00 00 01 0F 5F 20 E2 04 3C 48 88 FF 1F 04 2E Thu 11/26/2020 03:52:57 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 Thu 11/26/2020 03:52:57 PM : [Ext MH ] Unexpected Response (i.e. DB range): ignored Thu 11/26/2020 03:53:06 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 57 01 00 00 00 00 00 00 00 00 6A Thu 11/26/2020 03:53:06 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 57 01 00 00 00 00 00 00 00 00 6A 06 (00) Thu 11/26/2020 03:53:06 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:53:06 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:53:07 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 57 20 E2 04 52 7B 53 01 00 04 3F Thu 11/26/2020 03:53:07 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:07 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 4F 01 00 00 00 00 00 00 00 00 72 Thu 11/26/2020 03:53:07 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 4F 01 00 00 00 00 00 00 00 00 72 06 (00) Thu 11/26/2020 03:53:08 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:53:08 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:53:08 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 4F 20 E2 05 3C 48 88 FF 1F 05 3C Thu 11/26/2020 03:53:08 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:08 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 47 01 00 00 00 00 00 00 00 00 7A Thu 11/26/2020 03:53:08 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 47 01 00 00 00 00 00 00 00 00 7A 06 (00) Thu 11/26/2020 03:53:08 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:08 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:09 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:53:09 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:53:09 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 47 20 E2 06 12 DE B9 01 00 06 C2 Thu 11/26/2020 03:53:09 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:09 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 3F 01 00 00 00 00 00 00 00 00 82 Thu 11/26/2020 03:53:09 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 3F 01 00 00 00 00 00 00 00 00 82 06 (00) Thu 11/26/2020 03:53:10 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:10 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:10 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 3F 20 E2 06 13 3A 7A 01 00 06 AC Thu 11/26/2020 03:53:10 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:10 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 37 01 00 00 00 00 00 00 00 00 8A Thu 11/26/2020 03:53:10 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 37 01 00 00 00 00 00 00 00 00 8A 06 (00) Thu 11/26/2020 03:53:11 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:11 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:11 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:53:11 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:53:11 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 37 20 E2 06 13 3E 10 01 00 06 1A Thu 11/26/2020 03:53:11 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:11 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 2F 01 00 00 00 00 00 00 00 00 92 Thu 11/26/2020 03:53:11 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 2F 01 00 00 00 00 00 00 00 00 92 06 (00) Thu 11/26/2020 03:53:12 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:12 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:12 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:53:12 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:53:12 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 2F 20 E2 06 3C 48 88 FF 1F 06 5A Thu 11/26/2020 03:53:12 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:12 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 27 01 00 00 00 00 00 00 00 00 9A Thu 11/26/2020 03:53:12 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 27 01 00 00 00 00 00 00 00 00 9A 06 (00) Thu 11/26/2020 03:53:13 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:13 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:13 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 27 20 E2 06 50 D0 7E 01 00 06 ED Thu 11/26/2020 03:53:13 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:13 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 1F 01 00 00 00 00 00 00 00 00 A2 Thu 11/26/2020 03:53:13 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 1F 01 00 00 00 00 00 00 00 00 A2 06 (00) Thu 11/26/2020 03:53:14 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:53:14 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:53:14 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 15 2F 00 00 01 0F 1F 20 E2 06 52 D6 CC 01 00 06 9F Thu 11/26/2020 03:53:14 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=1 Thu 11/26/2020 03:53:14 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 17 01 00 00 00 00 00 00 00 00 AA Thu 11/26/2020 03:53:14 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 17 01 00 00 00 00 00 00 00 00 AA 06 (00) Thu 11/26/2020 03:53:15 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:15 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:15 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 1A D0 C0 00 01 0F 17 20 AA 01 53 BF 6B 00 1C 01 45 Thu 11/26/2020 03:53:15 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=2 Thu 11/26/2020 03:53:24 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 17 01 00 00 00 00 00 00 00 00 AA Thu 11/26/2020 03:53:24 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 17 01 00 00 00 00 00 00 00 00 AA 06 (00) Thu 11/26/2020 03:53:25 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2B 2F 00 (00) Thu 11/26/2020 03:53:25 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 11/26/2020 03:53:25 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 11 2F 00 00 01 0F 17 20 AA 01 53 BF 6B 00 1C 01 45 Thu 11/26/2020 03:53:25 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Thu 11/26/2020 03:53:25 PM : [INST-TX-I2CS] 02 62 29 53 46 1F 2F 00 00 00 0F 0F 01 00 00 00 00 00 00 00 00 B2 Thu 11/26/2020 03:53:25 PM : [INST-ACK ] 02 62 29.53.46 1F 2F 00 00 00 0F 0F 01 00 00 00 00 00 00 00 00 B2 06 (00) Thu 11/26/2020 03:53:26 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 2F 2F 00 (00) Thu 11/26/2020 03:53:26 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Thu 11/26/2020 03:53:26 PM : [INST-SRX ] 02 50 29.53.46 3C.48.88 23 2F 00 (00) Thu 11/26/2020 03:53:26 PM : [Std-Direct Ack] 29.53.46-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Thu 11/26/2020 03:53:27 PM : [INST-ERX ] 02 51 29 53 46 3C 48 88 16 2F 00 00 01 0F 0F 20 00 01 53 BF 6B 00 1C 01 F7 Thu 11/26/2020 03:53:27 PM : [Ext-Direct ] 29.53.46-->ISY/PLM Group=0, Max Hops=2, Hops Left=1 Thu 11/26/2020 03:53:27 PM : [All ] Writing 0 bytes to devices Thu 11/26/2020 03:53:27 PM : [All ] Writing 0 bytes to devices Thu 11/26/2020 03:55:31 PM : [ Time] 15:55:32 11(0)

krkeegan commented 3 years ago

That's fine. I might have a guess at a solution, but it would be nice to confirm the error.

jonsmirl commented 3 years ago

(venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.46 Commanding keypad_linc device 29.53.46 (mb chandelier) cmd=pair KeypadLinc 29.53.46 setting LED bits 11000000 KeypadLinc 29.53.46 refresh at level 0 Device 29.53.46 db out of date (got 161 vs None), refreshing Entry: 0fff: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x06 Entry: 0ff7: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x04 Entry: 0fef: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x03 Entry: 0fe7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x06 Entry: 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 Entry: 0fd7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x04 Entry: 0fcf: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 Entry: 0fc7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x01 Entry: 0fbf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x01 Entry: 0fb7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x01 Entry: 0faf: 3c.48.88 grp: 72 type: RESP data: 0xd8 0x1c 0x01 Entry: 0fa7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 Entry: 0fa7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 Entry: 0fa7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 Entry: 0f9f: 12.de.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03 No read handler found for message type 0x50: Std: 2d.43.46->53.bf.6b Type.CLEANUP_NAK cmd: d0 c0 Entry: 0f97: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03 Entry: 0f8f: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f87: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f7f: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f77: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f6f: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f6f: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f67: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04 Entry: 0f5f: 52.7b.53 grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f57: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 Entry: 0f57: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 Entry: 0f4f: 12.de.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f47: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f3f: 13.3e.10 grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 Entry: 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 Entry: 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 Entry: 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 Entry: 0f2f: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f27: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f27: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f1f: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01 Entry: 0f17: 52.d6.cc grp: 5 type: RESP data: 0x01 0x00 0x05 (UNUSED) (LAST) 29.53.46 database download complete DeviceDb: (delta 161) 0f1f: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01 0f27: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 0f2f: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 0f3f: 13.3e.10 grp: 6 type: CTRL data: 0x01 0x00 0x06 0f47: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 0f4f: 12.de.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06 0f57: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 0f5f: 52.7b.53 grp: 4 type: CTRL data: 0x01 0x00 0x04 0f67: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04 0f6f: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 0f77: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 0f7f: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 0f87: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03 0f8f: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 0f97: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03 0f9f: 12.de.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03 0fa7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 0faf: 3c.48.88 grp: 72 type: RESP data: 0xd8 0x1c 0x01 0fb7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x01 0fbf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x01 0fc7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x01 0fcf: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 0fd7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x04 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 0fe7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x06 0fef: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x03 0ff7: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x04 0fff: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x06 Unused: Last: 0f17: 52.d6.cc grp: 5 type: RESP data: 0x01 0x00 0x05 (UNUSED) (LAST) GroupMap 1 -> ['3c.48.88'] 3 -> ['12.de.b9', '3c.48.88', '50.d0.2c', '50.d0.7e', '52.76.08', '52.d6.cc'] 4 -> ['13.3a.7a', '3c.48.88', '52.7b.53'] 5 -> ['3c.48.88'] 6 -> ['12.de.b9', '13.3a.7a', '13.3e.10', '3c.48.88', '50.d0.7e', '52.d6.cc']

ERROR: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem (venv) jonsmirl@ares:~/aosp/insteon-mqtt$

--- debug ---- 2020-12-13 15:06:33 DEBUG CommandSeq: Running command 2 of 11 2020-12-13 15:06:33 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:06:33 INFO Device: Device 29.53.46 adding db: 44.85.11 grp 1 RESP b'\xff\x1f\x01' 2020-12-13 15:06:33 INFO Device: Device 29.53.46 appending new record at mem 0x0f17 2020-12-13 15:06:33 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:06:33 DEBUG MsgHistory: Average hops 1.0, using 1 2020-12-13 15:06:33 DEBUG Protocol: Write handler finished 2020-12-13 15:06:33 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 0f 08 20 05 52 d6 cc 01 00 05 00 2020-12-13 15:06:33 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x0f\x08 \x05R\xd6\xcc\x01\x00\x05\x8a' 2020-12-13 15:06:33 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 15:06:33 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 0f 08 20 05 52 d6 cc 01 00 05 8a 2020-12-13 15:06:33 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:06:34 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_ACK cmd: 2f 00 2020-12-13 15:06:34 DEBUG Protocol: Setting next write time: 1607889994.972440 2020-12-13 15:06:34 DEBUG MsgHistory: Received 1 hops, total 11 for 11 entries 2020-12-13 15:06:34 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:06:34 INFO DeviceDbModify: Updating entry: 0f0f: 52.d6.cc grp: 5 type: RESP data: 0x01 0x00 0x05 (UNUSED) (LAST) 2020-12-13 15:06:34 DEBUG CommandSeq: Running command 2 of 2 2020-12-13 15:06:34 DEBUG MsgHistory: Average hops 1.0, using 1 2020-12-13 15:06:34 DEBUG Protocol: Write handler finished 2020-12-13 15:06:34 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 17 08 a2 01 44 85 11 ff 1f 01 00 2020-12-13 15:06:34 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x17\x08\xa2\x01D\x85\x11\xff\x1f\x01\x05' 2020-12-13 15:06:34 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 15:06:34 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 17 08 a2 01 44 85 11 ff 1f 01 05 2020-12-13 15:06:34 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:06:35 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_ACK cmd: 2f 00 2020-12-13 15:06:35 DEBUG Protocol: Setting next write time: 1607889995.364311 2020-12-13 15:06:35 DEBUG MsgHistory: Received 1 hops, total 11 for 11 entries 2020-12-13 15:06:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:06:35 INFO DeviceDbModify: Updating entry: 0f17: 44.85.11 grp: 1 type: RESP data: 0xff 0x1f 0x01 2020-12-13 15:06:35 DEBUG CommandSeq: Running command 2 of 2 2020-12-13 15:06:35 DEBUG CommandSeq: Running command 1 of 1 2020-12-13 15:06:35 DEBUG Protocol: Write handler finished 2020-12-13 15:06:35 INFO Protocol: Write message to modem: OutAllLinkUpdate: 29.53.46 grp: 1 Cmd.UPDATE 2020-12-13 15:06:35 DEBUG Protocol: Write bytes to modem: b'\x02o \xe2\x01)SF\x01\x00\x00' 2020-12-13 15:06:35 DEBUG Serial: Wrote 11 bytes to serial /dev/insteon 2020-12-13 15:06:35 INFO Protocol: Read 0x6f: OutAllLinkUpdate: 29.53.46 grp: 1 Cmd.UPDATE ack: True 2020-12-13 15:06:35 DEBUG Protocol: Passing msg to write handler: ModemDbModify handler 2020-12-13 15:06:35 INFO ModemDbModify: Updating modem db record for 29.53.46 grp: 1 data: bytearray(b'\x01\x00\x00') 2020-12-13 15:06:35 DEBUG CommandSeq: Running command 3 of 11 2020-12-13 15:06:35 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:06:35 INFO Device: Device 29.53.46 adding db: 44.85.11 grp 1 CTRL b'\x03\x00\x01' 2020-12-13 15:06:35 INFO Device: Device 29.53.46 appending new record at mem 0x0f0f 2020-12-13 15:06:35 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:06:35 DEBUG MsgHistory: Average hops 1.0, using 1 2020-12-13 15:06:35 DEBUG Protocol: Write handler finished 2020-12-13 15:06:35 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 07 08 20 05 52 d6 cc 01 00 05 00 2020-12-13 15:06:35 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x07\x08 \x05R\xd6\xcc\x01\x00\x05\x92' 2020-12-13 15:06:35 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 15:06:35 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 07 08 20 05 52 d6 cc 01 00 05 92 2020-12-13 15:06:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:06:35 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 2020-12-13 15:06:35 DEBUG Protocol: Setting next write time: 1607889996.073925 2020-12-13 15:06:35 DEBUG MsgHistory: Received 0 hops, total 10 for 11 entries 2020-12-13 15:06:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:06:35 ERROR DeviceDbModify: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 2020-12-13 15:06:35 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3638700642 {"type": "ERROR", "data": "29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00"} qos=0 ret=False 2020-12-13 15:06:35 ERROR Mqtt: Device database update failed. 2020-12-13 15:06:35 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3638700642 {"type": "ERROR", "data": "Device database update failed. "} qos=0 ret=False 2020-12-13 15:06:35 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3638700642 {"type": "END", "data": null} qos=0 ret=False 2020-12-13 15:06:35 DEBUG Protocol: Write handler finished 2020-12-13 15:06:35 DEBUG Mqtt: MQTT writing

krkeegan commented 3 years ago

ok, do one more thing for me. Try and run pair again. It may cause the full refresh to happen in the process. I wonder if we get one step farther each time.

jonsmirl commented 3 years ago

It goes back into the quick fail mode... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.46 Commanding keypad_linc device 29.53.46 (mb chandelier) cmd=pair KeypadLinc 29.53.46 setting LED bits 11000000 KeypadLinc 29.53.46 refresh at level 0 Device 29.53.46 db out of date (got 165 vs 163), refreshing ERROR: 29.53.46 device NAK error: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Database command NAK. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

now I refreshed the modem...

(venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.46 Commanding keypad_linc device 29.53.46 (mb chandelier) cmd=pair KeypadLinc 29.53.46 setting LED bits 11000000 KeypadLinc 29.53.46 refresh at level 0 Device 29.53.46 db out of date (got 165 vs None), refreshing Entry: 0fff: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x06 Entry: 0ff7: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x04 Entry: 0fef: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x03 Entry: 0fe7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x06 Entry: 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 Entry: 0fd7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x04 Entry: 0fcf: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 Entry: 0fc7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x01 Entry: 0fbf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x01 Entry: 0fb7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x01 Entry: 0faf: 3c.48.88 grp: 72 type: RESP data: 0xd8 0x1c 0x01 Entry: 0fa7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 Entry: 0f9f: 12.de.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f97: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03 Entry: 0f8f: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f8f: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f8f: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f87: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f7f: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f7f: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f77: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f77: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f6f: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f67: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04 Entry: 0f5f: 52.7b.53 grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f57: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 Entry: 0f4f: 12.de.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f47: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f47: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f3f: 13.3e.10 grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 Entry: 0f2f: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f27: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f1f: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01 Entry: 0f17: 44.85.11 grp: 1 type: RESP data: 0xff 0x1f 0x01 Entry: 0f0f: 52.d6.cc grp: 5 type: RESP data: 0x01 0x00 0x05 (UNUSED) (LAST) 29.53.46 database download complete DeviceDb: (delta 165) 0f17: 44.85.11 grp: 1 type: RESP data: 0xff 0x1f 0x01 0f1f: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01 0f27: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 0f2f: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06 0f37: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 0f3f: 13.3e.10 grp: 6 type: CTRL data: 0x01 0x00 0x06 0f47: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 0f4f: 12.de.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06 0f57: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 0f5f: 52.7b.53 grp: 4 type: CTRL data: 0x01 0x00 0x04 0f67: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04 0f6f: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 0f77: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 0f7f: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 0f87: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03 0f8f: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 0f97: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03 0f9f: 12.de.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03 0fa7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 0faf: 3c.48.88 grp: 72 type: RESP data: 0xd8 0x1c 0x01 0fb7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x01 0fbf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x01 0fc7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x01 0fcf: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 0fd7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x04 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 0fe7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x06 0fef: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x03 0ff7: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x04 0fff: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x06 Unused: Last: 0f0f: 52.d6.cc grp: 5 type: RESP data: 0x01 0x00 0x05 (UNUSED) (LAST) GroupMap 1 -> ['3c.48.88'] 3 -> ['12.de.b9', '3c.48.88', '50.d0.2c', '50.d0.7e', '52.76.08', '52.d6.cc'] 4 -> ['13.3a.7a', '3c.48.88', '52.7b.53'] 5 -> ['3c.48.88'] 6 -> ['12.de.b9', '13.3a.7a', '13.3e.10', '3c.48.88', '50.d0.7e', '52.d6.cc']

Handler timed out 1 of 3 sent: Ext: 29.53.46, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 Device 29.53.46 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 29.53.46 grp 1 CTRL ERROR: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

--- debug ----

2020-12-13 15:46:26 DEBUG Mqtt: MQTT writing 2020-12-13 15:46:26 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2e 00 ack: True 01 00 00 00 00 00 00 00 00 00 00 00 00 d1 2020-12-13 15:46:26 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler 2020-12-13 15:46:32 WARNING Base: Handler timed out 1 of 3 sent: Ext: 29.53.46, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 2020-12-13 15:46:32 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3510535700 {"type": "MESSAGE", "data": "Handler timed out 1 of 3 sent: Ext: 29.53.46, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 "} qos=0 ret=False 2020-12-13 15:46:32 DEBUG Base: Increasing max_hops to 3 2020-12-13 15:46:32 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 2020-12-13 15:46:32 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x1f.\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xd1' 2020-12-13 15:46:32 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 15:46:32 DEBUG Mqtt: MQTT writing 2020-12-13 15:46:32 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2e 00 ack: True 01 00 00 00 00 00 00 00 00 00 00 00 00 d1 2020-12-13 15:46:32 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler 2020-12-13 15:46:33 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_ACK cmd: 2e 00 2020-12-13 15:46:33 DEBUG Protocol: Setting next write time: 1607892393.587141 2020-12-13 15:46:33 DEBUG MsgHistory: Received 0 hops, total 8 for 11 entries 2020-12-13 15:46:33 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler 2020-12-13 15:46:33 INFO ExtendedCmdResponse: 29.53.46 device ACK response, waiting for ext payload 2020-12-13 15:46:34 INFO Protocol: Read 0x51: Ext: 29.53.46->53.bf.6b Type.DIRECT ext cmd: 2e 00 01 01 00 00 20 20 1c fe 05 00 c0 00 00 00 2020-12-13 15:46:34 DEBUG MsgHistory: Received 1 hops, total 9 for 11 entries 2020-12-13 15:46:34 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler 2020-12-13 15:46:34 DEBUG KeypadLinc: KeypadLinc 29.53.46 get button state: Ext: 29.53.46->53.bf.6b Type.DIRECT ext cmd: 2e 00 01 01 00 00 20 20 1c fe 05 00 c0 00 00 00 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 2 of 11 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:46:34 WARNING Device: Device 29.53.46 add db already exists for 44.85.11 grp 1 RESP 2020-12-13 15:46:34 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3510535700 {"type": "MESSAGE", "data": "Device 29.53.46 add db already exists for 44.85.11 grp 1 RESP"} qos=0 ret=False 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 2 of 2 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 1 of 1 2020-12-13 15:46:34 WARNING Modem: Modem add db already exists for 29.53.46 grp 1 CTRL 2020-12-13 15:46:34 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3510535700 {"type": "MESSAGE", "data": "Modem add db already exists for 29.53.46 grp 1 CTRL"} qos=0 ret=False 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 3 of 11 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:46:34 INFO Device: Device 29.53.46 adding db: 44.85.11 grp 1 CTRL b'\x03\x00\x01' 2020-12-13 15:46:34 INFO Device: Device 29.53.46 appending new record at mem 0x0f0f 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 15:46:34 DEBUG MsgHistory: Average hops 0.8, using 1 2020-12-13 15:46:34 DEBUG Protocol: Write handler finished 2020-12-13 15:46:34 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 07 08 20 05 52 d6 cc 01 00 05 00 2020-12-13 15:46:34 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x07\x08 \x05R\xd6\xcc\x01\x00\x05\x92' 2020-12-13 15:46:34 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 15:46:34 DEBUG Mqtt: MQTT writing 2020-12-13 15:46:34 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 07 08 20 05 52 d6 cc 01 00 05 92 2020-12-13 15:46:34 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:46:34 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_ACK cmd: 2f 00 2020-12-13 15:46:34 DEBUG Protocol: Setting next write time: 1607892394.770077 2020-12-13 15:46:34 DEBUG MsgHistory: Received 0 hops, total 8 for 11 entries 2020-12-13 15:46:34 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:46:34 INFO DeviceDbModify: Updating entry: 0f07: 52.d6.cc grp: 5 type: RESP data: 0x01 0x00 0x05 (UNUSED) (LAST) 2020-12-13 15:46:34 DEBUG CommandSeq: Running command 2 of 2 2020-12-13 15:46:34 DEBUG MsgHistory: Average hops 0.7, using 1 2020-12-13 15:46:34 DEBUG Protocol: Write handler finished 2020-12-13 15:46:34 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 0f 08 e2 01 44 85 11 03 00 01 00 2020-12-13 15:46:34 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x0f\x08\xe2\x01D\x85\x11\x03\x00\x01\xe8' 2020-12-13 15:46:34 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 15:46:34 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 0f 08 e2 01 44 85 11 03 00 01 e8 2020-12-13 15:46:34 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:46:35 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 2020-12-13 15:46:35 DEBUG Protocol: Setting next write time: 1607892395.185270 2020-12-13 15:46:35 DEBUG MsgHistory: Received 0 hops, total 7 for 11 entries 2020-12-13 15:46:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 15:46:35 ERROR DeviceDbModify: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 2020-12-13 15:46:35 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3510535700 {"type": "ERROR", "data": "29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00"} qos=0 ret=False 2020-12-13 15:46:35 ERROR Mqtt: Device database update failed. 2020-12-13 15:46:35 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3510535700 {"type": "ERROR", "data": "Device database update failed. "} qos=0 ret=False 2020-12-13 15:46:35 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/3510535700 {"type": "END", "data": null} qos=0 ret=False 2020-12-13 15:46:35 DEBUG Protocol: Write handler finished 2020-12-13 15:46:35 DEBUG Mqtt: MQTT writing

krkeegan commented 3 years ago

OK, I have a guess that this could be related to #250. I am grabbing some food. But I should have a branch for you to try in an hour or so?

jonsmirl commented 3 years ago

Sure. I have to run out to Home Depot probably be back about same time.

krkeegan commented 3 years ago

Alright, checkout this branch krkeegan/Jon_Branch

It has a minor change wherein we are writing the new last entry in the database as all 0s rather than copying the existing last entry.

There could be a few things at play here:

  1. Some difference in how the ISY handles the DB and how insteon-mqtt does. ISY looks like it may use the entry marked as last, which I also thought was permissible. But Ted has a note in here that this didn't work for him. Not sure why and not sure why we were able to get your other devices to work and it is only this one acting up.

  2. Also a potential, is that newer devices don't like duplicate entries? We previously moved the last entry by just copying it. But that briefly created a duplicate entry. This now just adds an empty entry on the end instead. So it might solve your issue.

krkeegan commented 3 years ago

Hold off for a minute, I just realized one more thing.

krkeegan commented 3 years ago

OK, now that is better. I hope I solved your issue. I think it has to do with how the ISY uses the database.

krkeegan commented 3 years ago

If I am right, the ISY uses the last mem_loc in the database. This is different from how we do it and how insteon devices seem to do it. The code in this branch should now deal with this.

I 'think' it is possible that the device as sending a NAK because we were writing a used entry below the last entry. Although it isn't clear why this worked sometimes for you. Perhaps the firmware on this device is just new enough to cause the issue.

jonsmirl commented 3 years ago

No change....

ERROR: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

0-12-13 19:56:35 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler 2020-12-13 19:56:35 DEBUG KeypadLinc: KeypadLinc 29.53.46 get button state: Ext: 29.53.46->53.bf.6b Type.DIRECT ext cmd: 2e 00 01 01 00 00 20 20 1c fe 05 00 c0 00 00 00 2020-12-13 19:56:35 DEBUG CommandSeq: Running command 2 of 11 2020-12-13 19:56:35 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 19:56:35 INFO Device: Device 29.53.46 adding db: 44.85.11 grp 1 RESP b'\xff\x1f\x01' 2020-12-13 19:56:35 DEBUG CommandSeq: Running command 1 of 2 2020-12-13 19:56:35 DEBUG MsgHistory: Average hops 0.7, using 1 2020-12-13 19:56:35 DEBUG Protocol: Write handler finished 2020-12-13 19:56:35 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 0f 08 a2 01 44 85 11 ff 1f 01 00 2020-12-13 19:56:35 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x0f\x08\xa2\x01D\x85\x11\xff\x1f\x01\r' 2020-12-13 19:56:35 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 19:56:35 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 0f 08 a2 01 44 85 11 ff 1f 01 0d 2020-12-13 19:56:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 19:56:35 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_ACK cmd: 2f 00 2020-12-13 19:56:35 DEBUG Protocol: Setting next write time: 1607907395.814428 2020-12-13 19:56:35 DEBUG MsgHistory: Received 0 hops, total 7 for 11 entries 2020-12-13 19:56:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 19:56:35 INFO DeviceDbModify: Updating entry: 0f0f: 44.85.11 (modem) grp: 1 type: RESP data: 0xff 0x1f 0x01 2020-12-13 19:56:35 DEBUG CommandSeq: Running command 2 of 2 2020-12-13 19:56:35 DEBUG MsgHistory: Average hops 0.6, using 1 2020-12-13 19:56:35 DEBUG Protocol: Write handler finished 2020-12-13 19:56:35 INFO Protocol: Write message to modem: Ext: 29.53.46, Type.DIRECT ext, 2f 00 00 02 0f 07 08 20 00 00 00 00 00 00 00 00 2020-12-13 19:56:35 DEBUG Protocol: Write bytes to modem: b'\x02b)SF\x15/\x00\x00\x02\x0f\x07\x08 \x00\x00\x00\x00\x00\x00\x00\x91' 2020-12-13 19:56:35 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon 2020-12-13 19:56:35 INFO Protocol: Read 0x62: Ext: 29.53.46, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 07 08 20 00 00 00 00 00 00 00 91 2020-12-13 19:56:35 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 19:56:36 INFO Protocol: Read 0x50: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 2020-12-13 19:56:36 DEBUG Protocol: Setting next write time: 1607907396.245262 2020-12-13 19:56:36 DEBUG MsgHistory: Received 0 hops, total 6 for 11 entries 2020-12-13 19:56:36 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler 2020-12-13 19:56:36 ERROR DeviceDbModify: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 2020-12-13 19:56:36 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/2562159342 {"type": "ERROR", "data": "29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00"} qos=0 ret=False 2020-12-13 19:56:36 ERROR Mqtt: Device database update failed. 2020-12-13 19:56:36 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/2562159342 {"type": "ERROR", "data": "Device database update failed. "} qos=0 ret=False 2020-12-13 19:56:36 DEBUG Mqtt: MQTT publish insteon/command/29.53.46/session/2562159342 {"type": "END", "data": null} qos=0 ret=False 2020-12-13 19:56:36 DEBUG Protocol: Write handler finished 2020-12-13 19:56:36 DEBUG Mqtt: MQTT writing

jonsmirl commented 3 years ago

(venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.46 Commanding keypad_linc device 29.53.46 (mb chandelier) cmd=pair KeypadLinc 29.53.46 setting LED bits 11000000 KeypadLinc 29.53.46 refresh at level 0 Device 29.53.46 db out of date (got 204 vs None), refreshing Entry: 0fff: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x06 Entry: 0ff7: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x04 Entry: 0fef: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x03 Entry: 0fe7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x06 Entry: 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 Entry: 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 Entry: 0fd7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x04 Entry: 0fcf: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x03 Entry: 0fc7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x01 Entry: 0fbf: 3c.48.88 grp: 72 type: RESP data: 0xd8 0x1c 0x01 Entry: 0fb7: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x01 Entry: 0faf: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x01 Entry: 0fa7: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 Entry: 0fa7: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 Entry: 0f9f: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 Entry: 0f97: 12.de.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f8f: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03 Entry: 0f87: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f7f: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f77: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f6f: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f6f: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 Entry: 0f67: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f5f: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04 Entry: 0f57: 52.7b.53 grp: 4 type: CTRL data: 0x01 0x00 0x04 Entry: 0f4f: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 Entry: 0f47: 12.de.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f3f: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f37: 13.3e.10 grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f2f: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 Entry: 0f27: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f1f: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 Entry: 0f17: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01 Entry: 0f0f: 44.85.11 (modem) grp: 1 type: RESP data: 0x03 0x00 0x01 (UNUSED) (LAST) 29.53.46 database download complete DeviceDb: (delta 204) 0f17: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01 0f1f: 52.d6.cc grp: 6 type: CTRL data: 0x01 0x00 0x06 0f27: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06 0f2f: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06 0f37: 13.3e.10 grp: 6 type: CTRL data: 0x01 0x00 0x06 0f3f: 13.3a.7a grp: 6 type: CTRL data: 0x01 0x00 0x06 0f47: 12.de.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06 0f4f: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05 0f57: 52.7b.53 grp: 4 type: CTRL data: 0x01 0x00 0x04 0f5f: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04 0f67: 13.3a.7a grp: 4 type: CTRL data: 0x01 0x00 0x04 0f6f: 52.d6.cc grp: 3 type: CTRL data: 0x01 0x00 0x03 0f77: 52.76.08 grp: 3 type: CTRL data: 0x01 0x00 0x03 0f7f: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03 0f87: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 0f8f: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03 0f97: 12.de.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03 0f9f: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01 0fa7: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01 0faf: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x01 0fb7: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x01 0fbf: 3c.48.88 grp: 72 type: RESP data: 0xd8 0x1c 0x01 0fc7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x01 0fcf: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x03 0fd7: 3c.48.88 grp: 61 type: RESP data: 0xff 0x1f 0x04 0fdf: 3c.48.88 grp: 62 type: RESP data: 0xff 0x1f 0x03 0fe7: 3c.48.88 grp: 63 type: RESP data: 0xff 0x1f 0x06 0fef: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x03 0ff7: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x04 0fff: 3c.48.88 grp: 72 type: RESP data: 0xff 0x1f 0x06 Unused: 0f0f: 44.85.11 (modem) grp: 1 type: RESP data: 0x03 0x00 0x01 (UNUSED) (LAST) Last: 0f0f: 44.85.11 (modem) grp: 1 type: RESP data: 0x03 0x00 0x01 (UNUSED) (LAST) GroupMap 1 -> ['3c.48.88'] 3 -> ['12.de.b9', '3c.48.88', '50.d0.2c', '50.d0.7e', '52.76.08', '52.d6.cc'] 4 -> ['13.3a.7a', '3c.48.88', '52.7b.53'] 5 -> ['3c.48.88'] 6 -> ['12.de.b9', '13.3a.7a', '13.3e.10', '3c.48.88', '50.d0.7e', '52.d6.cc']

ERROR: 29.53.46 db mod NAK: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem (venv) jonsmirl@ares:~/aosp/insteon-mqtt$

jonsmirl commented 3 years ago

Here are my keypads....

keypad_linc_sw:
  - 20.42.ac: 'Butler Hall 8'

9 -> ['53.bf.6b'] ERROR: 20.42.ac device NAK error: , Message: Std: 20.42.ac->53.bf.6b Type.DIRECT_NAK cmd: 2e 00 ERROR: Device command NAK. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

  - 20.43.0d: 'Mud garage 8'

pairs

 keypad_linc:
 - 25.0b.1a: 'Mudroom stair 5'

9 -> ['53.bf.6b'] ERROR: Serial write error from /dev/insteon ERROR: Device NAK of device db modify: Ext: 25.0b.1a, Type.DIRECT ext, 2f 00 ack: False 00 02 0f 07 08 e2 01 44 85 11 03 00 01 f0 ERROR: Device database update failed Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

  - 25.0e.3c: 'Basement Hall 5'

Device 25.0e.3c add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 25.0e.3c grp 1 CTRL Device 25.0e.3c add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 25.0e.3c grp 1 RESP ERROR: 25.0e.3c db mod NAK: , Message: Std: 25.0e.3c->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

  - 25.0e.48: 'MBR right 5'

25.0e.48 Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 25.0e.48->53.bf.6b Type.DIRECT_NAK cmd: 2e fc Modem add db already exists for 25.0e.48 grp 1 RESP ERROR: 25.0e.48 db mod NAK: , Message: Std: 25.0e.48->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

  - 29.53.46: 'MB Chandelier 5'

ERROR: 29.53.46 device NAK error: , Message: Std: 29.53.46->53.bf.6b Type.DIRECT_NAK cmd: 2e 00 ERROR: Device command NAK. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

  - 29.53.f8: 'Dining KP 5'

pairs

ERROR: 2a.17.1b device NAK error: , Message: Std: 2a.17.1b->53.bf.6b Type.DIRECT_NAK cmd: 2e 00 ERROR: Device command NAK. Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem

  - 2a.8f.85: '1st Formal 8'

pairs

------ Now I unplugged ISY....

keypad_linc_sw:
  - 20.42.ac: 'Butler Hall 8'

pairs now

So I am finally able to pair all of the keypads.

1) Could the insteon-mqtt db writes be triggering an action from the ISY? Does the ISY monitor the devices, see the db writes, and then read the DB to see what changed? And that read traffic then conflicts and delays with further insteon-mqtt commands? 2) Is this NAK really a fail? ERROR: 2a.14.1b db mod NAK: , Message: Std: 2a.14.1b->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ERROR: Device database update failed.

or it is saying -- Wait for a while, updating the EEPROM is really slow? --- my ID keeps incrementing on each fail...

Device 2a.17.1b db out of date (got 4 vs 3), refreshing Device 2a.17.1b db out of date (got 5 vs 4), refreshing Device 2a.17.1b db out of date (got 10 vs 8), refreshing Device 2a.17.1b db out of date (got 14 vs 11), refreshing Device 2a.17.1b db out of date (got 16 vs 15), refreshing Device 2a.17.1b db out of date (got 17 vs 16), refreshing Device 2a.17.1b db out of date (got 17 vs None), refreshing (joined again) Device 2a.17.1b db out of date (got 18 vs 17), refreshing Device 2a.17.1b db out of date (got 20 vs 19), refreshing Device 2a.17.1b db out of date (got 20 vs None), refreshing (joined again) Device 2a.17.1b db out of date (got 22 vs 21), refreshing

krkeegan commented 3 years ago

It doesn't look like you are running the branch that I asked you to.

krkeegan commented 3 years ago

Please run branch krkeegan/Jon_Branch

jonsmirl commented 3 years ago

I am on it.... if I am not on it I can't pair at all. But... I may have forgotten to restart the insteon_mqtt server I will run the tests again.

and I added a githook to run pip install . when I check out.

(venv) jonsmirl@ares:~/aosp/insteon-mqtt$ git log --pretty=format:"%h%x09%an%x09%ad%x09%s" 3425394 KRKeegan Sun Dec 13 15:41:36 2020 -0800 Merge branch 'Fix_250' into Jon_Branch 055b4cc KRKeegan Sun Dec 13 15:37:49 2020 -0800 Don't Assume Last Mem Location is Unused 5f1274f KRKeegan Sun Dec 13 13:51:41 2020 -0800 Merge branch 'Pre_NAK' into Jon_Branch b6c2c17 KRKeegan Sun Dec 13 13:48:50 2020 -0800 When Adding Last Entry Set it to All 0x00 0ccf11e Kevin Robert Keegan Sun Dec 13 11:34:05 2020 -0800 Merge pull request #239 from krkeegan/Dev_Name_in_DB c1611a0 KRKeegan Sun Dec 13 11:32:57 2020 -0800 Add History Details f0f5df8 KRKeegan Sun Dec 13 11:30:23 2020 -0800 Merge branch 'dev' into Dev_Name_in_DB 256ebbd Kevin Robert Keegan Sun Dec 13 11:25:46 2020 -0800 Merge pull request #251 from krkeegan/P219Doc 3b8477f Kevin Robert Keegan Sun Dec 13 11:25:30 2020 -0800 Merge pull request #219 from embak/EZIO4O ebe57d3 KRKeegan Sun Dec 13 11:21:39 2020 -0800 History Update for EZIO4O 373c1ae KRKeegan Sat Dec 12 13:43:35 2020 -0800 Merge branch 'dev' into Pre_NAK 97b819b Kevin Robert Keegan Sat Dec 12 13:40:22 2020 -0800 Merge pull request #248 from krkeegan/Increment_Delta 7f17ac7 KRKeegan Sat Dec 12 13:39:36 2020 -0800 Update History c461d5f KRKeegan Sat Dec 12 13:31:01 2020 -0800 Merge branch 'dev' into Increment_Delta 57dec45 Kevin Robert Keegan Sat Dec 12 13:26:18 2020 -0800 Merge branch 'dev' into Pre_NAK 7caa75e Kevin Robert Keegan Sat Dec 12 12:57:55 2020 -0800 Merge pull request #240 from krkeegan/Battery_Queueing 2c6e27e Kevin Robert Keegan Sat Dec 12 12:56:37 2020 -0800 Update History 4611a95 Kevin Robert Keegan Sat Dec 12 12:52:10 2020 -0800 Merge branch 'dev' into Battery_Queueing 6cfa5fc Kevin Robert Keegan Sat Dec 12 12:36:38 2020 -0800 Merge pull request #197 from krkeegan/IOLinc_Improvements a3f61b8 Kevin Robert Keegan Sat Dec 12 12:34:51 2020 -0800 Update History 77a4600 Kevin Robert Keegan Sat Dec 12 12:20:50 2020 -0800 Merge branch 'dev' into HEAD 3f93419 Kevin Robert Keegan Sat Dec 12 11:47:40 2020 -0800 Increment Database Delta on Writing 8aca02d Kevin Robert Keegan Fri Dec 11 16:22:13 2020 -0800 Merge pull request #245 from krkeegan/Release0.7.3 ec15403 KRKeegan Fri Dec 11 16:19:22 2020 -0800 Bump 0.7.2 -> 0.7.3 e036b3d Kevin Robert Keegan Fri Dec 11 15:54:56 2020 -0800 Merge pull request #237 from krkeegan/DB_Retry_Timeout cb6726c Kevin Robert Keegan Fri Dec 11 15:52:55 2020 -0800 Merge pull request #227 from kpflemin

jonsmirl commented 3 years ago

Check this out... this is all of my keypads running the PAIR command and none of them failed... I need to drop a couple kids off, when I get back I will check out the rest of my devices. This is looking much better!

(venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 25.0b.1a Commanding keypad_linc device 25.0b.1a (mudroom stair 5) cmd=pair KeypadLinc 25.0b.1a setting LED bits 11000000 Device database is current at delta 20 KeypadLinc 25.0b.1a refresh at level 0 Device 25.0b.1a add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 25.0b.1a grp 1 CTRL Device 25.0b.1a add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 25.0b.1a grp 1 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 25.0b.1a grp 2 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 25.0b.1a grp 3 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 25.0b.1a grp 4 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 25.0b.1a grp 5 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 25.0b.1a grp 6 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 25.0b.1a grp 7 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 25.0b.1a grp 8 RESP Device 25.0b.1a add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 25.0b.1a grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 25.0e.3c Commanding keypad_linc device 25.0e.3c (basement hall 5) cmd=pair KeypadLinc 25.0e.3c setting LED bits 11000000 Device database is current at delta 0 KeypadLinc 25.0e.3c refresh at level 0 25.0e.3c Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 25.0e.3c->53.bf.6b Type.DIRECT_NAK cmd: 2e fc Device 25.0e.3c add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 25.0e.3c grp 1 CTRL Device 25.0e.3c add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 25.0e.3c grp 1 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 25.0e.3c grp 2 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 25.0e.3c grp 3 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 25.0e.3c grp 4 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 25.0e.3c grp 5 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 25.0e.3c grp 6 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 25.0e.3c grp 7 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 25.0e.3c grp 8 RESP Device 25.0e.3c add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 25.0e.3c grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 25.0e.48 Commanding keypad_linc device 25.0e.48 (mbr right 5) cmd=pair KeypadLinc 25.0e.48 setting LED bits 11010000 Device database is current at delta 21 KeypadLinc 25.0e.48 refresh at level 208 No read handler found for message type 0x62: Std: 25.0e.48, Type.DIRECT, 19 00 ack: False Handler timed out 1 of 3 sent: Ext: 25.0e.48, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 Device 25.0e.48 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 25.0e.48 grp 1 CTRL Device 25.0e.48 add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 25.0e.48 grp 1 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 25.0e.48 grp 2 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 25.0e.48 grp 3 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 25.0e.48 grp 4 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 25.0e.48 grp 5 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 25.0e.48 grp 6 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 25.0e.48 grp 7 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 25.0e.48 grp 8 RESP Device 25.0e.48 add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 25.0e.48 grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.46 Commanding keypad_linc device 29.53.46 (mb chandelier 5) cmd=pair KeypadLinc 29.53.46 setting LED bits 11000000 Device database is current at delta 226 KeypadLinc 29.53.46 refresh at level 0 Device 29.53.46 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 29.53.46 grp 1 CTRL Device 29.53.46 add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 29.53.46 grp 1 RESP Device 29.53.46 add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 29.53.46 grp 2 RESP Device 29.53.46 add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 29.53.46 grp 3 RESP Device 29.53.46 add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 29.53.46 grp 4 RESP Device 29.53.46 add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 29.53.46 grp 5 RESP Device 29.53.46 add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 29.53.46 grp 6 RESP Device 29.53.46 add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 29.53.46 grp 7 RESP Device 29.53.46 add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 29.53.46 grp 8 RESP Device 29.53.46 add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 29.53.46 grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.f8 Commanding keypad_linc device 29.53.f8 (dining kp 5) cmd=pair KeypadLinc 29.53.f8 setting LED bits 11000000 Device database is current at delta 21 KeypadLinc 29.53.f8 refresh at level 0 29.53.f8 Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 29.53.f8->53.bf.6b Type.DIRECT_NAK cmd: 2e fc Device 29.53.f8 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 29.53.f8 grp 1 CTRL Device 29.53.f8 add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 29.53.f8 grp 1 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 29.53.f8 grp 2 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 29.53.f8 grp 3 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 29.53.f8 grp 4 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 29.53.f8 grp 5 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 29.53.f8 grp 6 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 29.53.f8 grp 7 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 29.53.f8 grp 8 RESP Device 29.53.f8 add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 29.53.f8 grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.47.a2 Commanding keypad_linc device 29.47.a2 (1st family 8) cmd=pair KeypadLinc 29.47.a2 setting LED bits 00111111 Device database is current at delta 0 KeypadLinc 29.47.a2 refresh at level 255 29.47.a2 Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 29.47.a2->53.bf.6b Type.DIRECT_NAK cmd: 2e fc Device 29.47.a2 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 29.47.a2 grp 1 CTRL Device 29.47.a2 add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 29.47.a2 grp 1 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 29.47.a2 grp 2 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 29.47.a2 grp 3 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 29.47.a2 grp 4 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 29.47.a2 grp 5 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 29.47.a2 grp 6 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 29.47.a2 grp 7 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 29.47.a2 grp 8 RESP Device 29.47.a2 add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 29.47.a2 grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.48.4c Commanding keypad_linc device 29.48.4c (1st breakfast 8) cmd=pair No read handler found for message type 0x50: Std: 29.4f.b0->53.bf.6b Type.DIRECT_ACK cmd: df c2 Handler timed out 1 of 3 sent: Std: 29.48.4c, Type.DIRECT, 19 01 KeypadLinc 29.48.4c setting LED bits 00000010 Device database is current at delta 32 KeypadLinc 29.48.4c refresh at level 0 Device 29.48.4c add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 29.48.4c grp 1 CTRL Device 29.48.4c add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 29.48.4c grp 1 RESP Device 29.48.4c add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 29.48.4c grp 2 RESP Device 29.48.4c add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 29.48.4c grp 3 RESP Device 29.48.4c add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 29.48.4c grp 4 RESP Device 29.48.4c add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 29.48.4c grp 5 RESP Device 29.48.4c add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 29.48.4c grp 6 RESP Device 29.48.4c add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 29.48.4c grp 7 RESP Device 29.48.4c add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 29.48.4c grp 8 RESP Device 29.48.4c add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 29.48.4c grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 2a.14.1b Commanding keypad_linc device 2a.14.1b (formal outer 5) cmd=pair KeypadLinc 2a.14.1b setting LED bits 00111111 Device database is current at delta 27 KeypadLinc 2a.14.1b refresh at level 84 2a.14.1b Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 2a.14.1b->53.bf.6b Type.DIRECT_NAK cmd: 2e fc Device 2a.14.1b add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 2a.14.1b grp 1 CTRL Device 2a.14.1b add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 2a.14.1b grp 1 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 2a.14.1b grp 2 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 2a.14.1b grp 3 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 2a.14.1b grp 4 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 2a.14.1b grp 5 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 2a.14.1b grp 6 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 2a.14.1b grp 7 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 2a.14.1b grp 8 RESP Device 2a.14.1b add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 2a.14.1b grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 2a.17.1b Commanding keypad_linc device 2a.17.1b (basement art 5) cmd=pair KeypadLinc 2a.17.1b setting LED bits 11000000 Device database is current at delta 25 KeypadLinc 2a.17.1b refresh at level 0 Device 2a.17.1b add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 2a.17.1b grp 1 CTRL Device 2a.17.1b add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 2a.17.1b grp 1 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 2a.17.1b grp 2 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 2a.17.1b grp 3 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 2a.17.1b grp 4 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 2a.17.1b grp 5 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 2a.17.1b grp 6 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 2a.17.1b grp 7 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 2a.17.1b grp 8 RESP Device 2a.17.1b add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 2a.17.1b grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 2a.8f.85 Commanding keypad_linc device 2a.8f.85 (1st formal 8) cmd=pair KeypadLinc 2a.8f.85 setting LED bits 11111111 Device database is current at delta 58 KeypadLinc 2a.8f.85 refresh at level 96 Device 2a.8f.85 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 2a.8f.85 grp 1 CTRL Device 2a.8f.85 add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 2a.8f.85 grp 1 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 2a.8f.85 grp 2 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 2a.8f.85 grp 3 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 2a.8f.85 grp 4 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 2a.8f.85 grp 5 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 2a.8f.85 grp 6 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 2a.8f.85 grp 7 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 2a.8f.85 grp 8 RESP Device 2a.8f.85 add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 2a.8f.85 grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 3d.7a.fe Commanding keypad_linc device 3d.7a.fe (frontdoor 8) cmd=pair KeypadLinc 3d.7a.fe setting LED bits 00000101 Device database is current at delta 35 KeypadLinc 3d.7a.fe refresh at level 127 Device 3d.7a.fe add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 3d.7a.fe grp 1 CTRL Device 3d.7a.fe add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 3d.7a.fe grp 1 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 3d.7a.fe grp 2 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 3d.7a.fe grp 3 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 3d.7a.fe grp 4 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 3d.7a.fe grp 5 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 3d.7a.fe grp 6 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 3d.7a.fe grp 7 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 3d.7a.fe grp 8 RESP Device 3d.7a.fe add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 3d.7a.fe grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5d.ed Commanding keypad_linc device 52.5d.ed (mbr chandlier 5) cmd=pair KeypadLinc 52.5d.ed setting LED bits 11000000 Device database is current at delta 26 KeypadLinc 52.5d.ed refresh at level 0 No read handler found for message type 0x50: Std: 5a.5d.ed->53.bf.6b Type.DIRECT_ACK cmd: 1b c0 Device 52.5d.ed add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 52.5d.ed grp 1 CTRL Device 52.5d.ed add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 52.5d.ed grp 1 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 52.5d.ed grp 2 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 52.5d.ed grp 3 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 52.5d.ed grp 4 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 52.5d.ed grp 5 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 52.5d.ed grp 6 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 52.5d.ed grp 7 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 52.5d.ed grp 8 RESP Device 52.5d.ed add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 52.5d.ed grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 Commanding keypad_linc device 52.5b.c0 (theater 8) cmd=pair KeypadLinc 52.5b.c0 setting LED bits 00000000 Device database is current at delta 40 KeypadLinc 52.5b.c0 refresh at level 0 No read handler found for message type 0x62: Std: 52.5b.c0, Type.DIRECT, 19 00 ack: False Handler timed out 1 of 3 sent: Ext: 52.5b.c0, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 Device 52.5b.c0 add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 52.5b.c0 grp 1 CTRL Device 52.5b.c0 add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 52.5b.c0 grp 1 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 52.5b.c0 grp 2 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 52.5b.c0 grp 3 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 52.5b.c0 grp 4 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 52.5b.c0 grp 5 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 52.5b.c0 grp 6 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 52.5b.c0 grp 7 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 52.5b.c0 grp 8 RESP Device 52.5b.c0 add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 52.5b.c0 grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.49.6f ERROR: Unknown Insteon device '52.49.6f' Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 53.49.6f Commanding keypad_linc device 53.49.6f (3rd hall 5) cmd=pair KeypadLinc 53.49.6f setting LED bits 00000111 Device database is current at delta 37 KeypadLinc 53.49.6f refresh at level 131 Device 53.49.6f add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 53.49.6f grp 1 CTRL Device 53.49.6f add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 53.49.6f grp 1 RESP Device 53.49.6f add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 53.49.6f grp 2 RESP Device 53.49.6f add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 53.49.6f grp 3 RESP Device 53.49.6f add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 53.49.6f grp 4 RESP Device 53.49.6f add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 53.49.6f grp 5 RESP Device 53.49.6f add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 53.49.6f grp 6 RESP Device 53.49.6f add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 53.49.6f grp 7 RESP Device 53.49.6f add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 53.49.6f grp 8 RESP Device 53.49.6f add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 53.49.6f grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 20.42.ac Commanding keypad_linc_sw device 20.42.ac (butler hall 8) cmd=pair KeypadLinc 20.42.ac setting LED bits 00000000 Handler timed out 1 of 3 sent: Std: 20.42.ac, Type.DIRECT, 19 00 Device database is current at delta 23 KeypadLinc 20.42.ac refresh at level 0 Device 20.42.ac add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 20.42.ac grp 1 CTRL Device 20.42.ac add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 20.42.ac grp 1 RESP Device 20.42.ac add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 20.42.ac grp 2 RESP Device 20.42.ac add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 20.42.ac grp 3 RESP Device 20.42.ac add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 20.42.ac grp 4 RESP Device 20.42.ac add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 20.42.ac grp 5 RESP Device 20.42.ac add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 20.42.ac grp 6 RESP Device 20.42.ac add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 20.42.ac grp 7 RESP Device 20.42.ac add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 20.42.ac grp 8 RESP Device 20.42.ac add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 20.42.ac grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 20.43.0d Commanding keypad_linc_sw device 20.43.0d (mud garage 8) cmd=pair KeypadLinc 20.43.0d setting LED bits 11000000 Device database is current at delta 34 KeypadLinc 20.43.0d refresh at level 0 20.43.0d Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 20.43.0d->53.bf.6b Type.DIRECT_NAK cmd: 2e fc Device 20.43.0d add db already exists for 44.85.11 grp 1 RESP Modem add db already exists for 20.43.0d grp 1 CTRL Device 20.43.0d add db already exists for 44.85.11 grp 1 CTRL Modem add db already exists for 20.43.0d grp 1 RESP Device 20.43.0d add db already exists for 44.85.11 grp 2 CTRL Modem add db already exists for 20.43.0d grp 2 RESP Device 20.43.0d add db already exists for 44.85.11 grp 3 CTRL Modem add db already exists for 20.43.0d grp 3 RESP Device 20.43.0d add db already exists for 44.85.11 grp 4 CTRL Modem add db already exists for 20.43.0d grp 4 RESP Device 20.43.0d add db already exists for 44.85.11 grp 5 CTRL Modem add db already exists for 20.43.0d grp 5 RESP Device 20.43.0d add db already exists for 44.85.11 grp 6 CTRL Modem add db already exists for 20.43.0d grp 6 RESP Device 20.43.0d add db already exists for 44.85.11 grp 7 CTRL Modem add db already exists for 20.43.0d grp 7 RESP Device 20.43.0d add db already exists for 44.85.11 grp 8 CTRL Modem add db already exists for 20.43.0d grp 8 RESP Device 20.43.0d add db already exists for 44.85.11 grp 9 CTRL Modem add db already exists for 20.43.0d grp 9 RESP KeypadLinc paired (venv) jonsmirl@ares:/aosp/insteon-mqtt$

krkeegan commented 3 years ago

Well that is a good sign.

jonsmirl commented 3 years ago

I have 55 on-switches added now without any abnormal errors. A few I had to try twice to pair, but they paired on the second try. I am starting the dimmers, 105 of them.

What was going on before? Was the ISY994 fighting with insteon-mqtt?

krkeegan commented 3 years ago

I think so. At least in what I could see from your logs, I don't have an ISY myself. I am making an assumption about how the ISYs work here, but it is possible that this all happened for other reasons caused by other errors.

Insteon Spec

Each link entry in a device database has two flags, USED and LAST.

Any entry can have the USED flag set to 0 or 1. Imagine you remove a device in your house, rather than reorganize the database, that entry just gets marked as 0, or unused.

However, there should only be one entry marked LAST. Or at least starting from the highest memory address working down, the first entry encountered that has the LAST flag set is where the device stops reading entries. Devices have tens or hundreds of memory locations for storing entries and reading a bunch of empty addresses would slow things down.

How Insteon Writes Links

When you manually pair Insteon devices, use the Insteon Hub, or the old Houselinc software the entry marked LAST is also unUSED. So if you read the database you will see that the entry at the lowest memory location looks like 0x00 0x00 0x00 (Unused)(Last)

In my opinion, this happens because Insteon never marks an entry as LAST. It relies on the fact that a factory reset device has all of its entries zeroed out and marked LAST. So when it writes a new entry at the top of the memory addresses it writes that entry as unUSED and notLAST. And it relies on the default state that the next memory location will be marked LAST. But this is not described as a guarantee in the spec, nothing says you can rely on unseen memory locations to be marked LAST or even UNUSED.

Insteon-mqtt

Writing new entries in Insteon-mqtt works like this, in this order 1) Mark the memory location just below the current last_entry as LAST, 2) Write the new entry in the previous last_entry location marking this entry as USED and notLAST.

It is making one more write to the database than is necessary to mimic how insteon did things, but it is a cautious approach because it doesn't rely on the unstated feature that unseen memory locations are empty and marked LAST. So, it is probably worth keeping.

Where things got weird

It appears to me that you can mark an entry as LAST and USED, which is what I think ISY is doing. So the last entry in a database had a valid USED entry for the link table. And obviously things work on that device. I don't see anything wrong with this per the spec. It should be allowed.

But nothing does that, except ISY.

This caused 2 issues for Insteon-mqtt.

Issue 1) Insteon-mqtt previously did a silly thing where were when writing the new last entry it didn't write it as all 0x00s, instead it copied the previous last entry including the state of the USED flag. This is where I think your generic NAK was happening. If the existing last_entry was marked as USED, then when we copied it and tried to write it back at a lower address, we were writing a USED entry below an entry marked LAST. Remember we write the new last entry first before altering the original last entry.

It isn't clear why we were copying the prior last_entry. It may have been a conservative approach since we don't always understand what Insteon is doing. This works fine, in most environments, because the entry marked LAST on a device is also unUSED. So when copying the entry, we were generally writing an unUSED entry below the LAST entry, the devices didn't care about this.

Issue 2) There was also a subtle error in that we were always assuming a LAST entry to be UNUSED in part of the code. I wasn't able to figure out what exact error this caused, but it could have also created an issue.

The Solution

The easy part, is properly treat an entry as USED if it is marked used.

The more fundamental problem was how to write entries to the database when it is full.

I think ISY's approach is wrong. When adding a new entry, they need to re-write the existing last_entry first and mark it not LAST, before adding a new entry below it marked LAST. There is no way to only write the flags on i2 devices, so this requires writing the full entry again, which could result in an error. I think it is preferable not to touch existing links if it can be avoided, otherwise a user adds a new link and then discovers that some other link they believe to be unrelated is not working. The resulting error isn't very intuitive.

So I stuck with our approach of the LAST entry also being unUSED. This means that if we encounter a USED LAST entry we first have to mark it last. Then add 2 more entries (a new entry and a new last entry). So we have to make 3 writes the first time we encounter this. But after that, everything is how we expect it and future adds only require 2 writes.

The write process is also reorganized now, we write to the current last_entry location and then write the new all 0x00 unUSED LAST entry to the new last entry location. The risk here, is if the process fails before we write that new last entry we may have inadvertently enabled a bunch of previously hidden entries. But I think this is extremely unlikely to occur.

The resulting database is fully compatible with ISY. It won't care. Again, I only think this is how ISY is doing things, this could have been caused by some other error along the way.

Anyways, that is more words than were necessary to fix the code, sorry for the long winded explanation.

jonsmirl commented 3 years ago

So far I am 0/4 on getting I1 protocol devices to work. I am just replacing them with new Dual Band devices when I encounter them. I need to go replace #4 now, I might have one or two more to replace. I1 support shouldn't be critical, how many people have Insteon devices over 10 years old that still function besides me?

Other than no luck with I1 devices I am proceeding without significant issues. I do get the occasional retransmit failure, but it has always worked on the second try. 57 dimmers left to check.

Thanks for the work, the Jon_Branch appears to be functioning pretty well --- way, way better than my initial problems. I'd say check it into the main app and get more people testing it. The only weird Insteon device I have is a leak sensor so I don't have any way to test the unusual devices.

(venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml join 08.09.e3 Commanding dimmer device 08.09.e3 (2nd / mbr / mbr main 7) cmd=join Device 08.09.e3 engine version: i1 Operation Complete (venv) jonsmirl@ares:/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 08.09.e3 Commanding dimmer device 08.09.e3 (2nd / mbr / mbr main 7) cmd=pair Dimmer 08.09.e3 refresh at level 0 Device 08.09.e3 db out of date (got 0 vs 59), refreshing No read handler found for message type 0x50: Std: 08.09.e3->53.bf.6b Type.DIRECT_ACK cmd: 28 0f Entry: 0fff: 53.3c.88 grp: 83 type: RESP data: 0xff 0x1f 0xa2 Entry: 0ff7: 3c.48.48 grp: 1 type: CTRL data: 0xff 0x1f 0x01 Entry: 0fef: 53.53.01 grp: 162 type: RESP data: 0xff 0xff 0x01 (UNUSED) (LAST) 08.09.e3 database download complete DeviceDb: (delta 0) 0ff7: 3c.48.48 grp: 1 type: CTRL data: 0xff 0x1f 0x01 0fff: 53.3c.88 grp: 83 type: RESP data: 0xff 0x1f 0xa2 Unused: 0fef: 53.53.01 grp: 162 type: RESP data: 0xff 0xff 0x01 (UNUSED) (LAST) Last: 0fef: 53.53.01 grp: 162 type: RESP data: 0xff 0xff 0x01 (UNUSED) (LAST) GroupMap 1 -> ['3c.48.48']

ERROR: Serial read error from /dev/insteon ERROR: Serial read error from /dev/insteon Handler timed out 1 of 3 sent: Std: 08.09.e3, Type.DIRECT, 29 01 ERROR: Serial read error from /dev/insteon Handler timed out 2 of 3 sent: Std: 08.09.e3, Type.DIRECT, 29 01 ERROR: Serial read error from /dev/insteon Handler timed out 3 of 3 sent: Std: 08.09.e3, Type.DIRECT, 29 01 ERROR: Serial read error from /dev/insteon Handler timed out - no more retries (3 sent) ERROR: Command timed out Pairing may fail if the modem db is out of date. Try running the following and then re-try the pair command. insteont-mqtt config.py refresh modem (venv) jonsmirl@ares:~/aosp/insteon-mqtt$

krkeegan commented 3 years ago

the ERROR: Serial read error from /dev/insteon almost certainly means I have an error in the code.

And it did. I pushed a new commit to the branch that fixes it for you.