Dual Band KepadLinc Relay v.41, pairing error #231
Comments
|
Not sure anyone else has had that many entries in their link table before. It looks like you are getting this: ERROR: 20.42.ac db mod NAK: Pre NAK in case database search takes too long, Message: Std: 20.42.ac->53.bf.6b Type.DIRECT_NAK cmd: 2f fc I suspect that NAK isn't properly handled in the code. It should probably just be reported and ignored. |
|
I am unable to get any of my keypads to pair. They all fail with timeouts. I have a large system with over 200 devices and I have 23 keypads in the system. When I first tried insteon-mqtt I used a script to pair/join everything. That script failed with errors everywhere. I am going back through the devices one by one manually to check them. I can see now that my root problem is that none of my keypads are in the system. (I also have a ISY994, that is how everything got setup). |
|
So at least with this device, it looks like you got a long way into the process, before it failed. There is really no documentation for how this is supposed to be handled. Interestingly, the document below seems to suggest that we shouldn't see this error until 150 links. While you have a lot, there are not anywhere near that many. http://cache.insteon.com/developer/i2CSdev-022012-en.pdf I am curious, what happens if you keep running this command on this device? Does it fail at the same point in the same way everytime? I am wondering if there is some number of links at which point we will always receive this message. I can probably write a patch to try and help you, but since there is no documentation it might take some testing. I don't know if we can just increase our wait time and ignore the message or if something else is necessary. Are you willing to try checking out a different branch and testing this? |
If receive a Pre NAK, add to wait time and wait for actual NAK. This is a strange NAK which is sent when the device db is large and searching it would take more time that permitted in normal message ACK. This may fix TD22057#231
|
If you can, try this branch out, it might solve this issue, it is based of the dev branch: https://github.com/krkeegan/insteon-mqtt/tree/Fix_231 |
|
I am on the Fix_231 branch... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 25.0e.48 ERROR: 25.0e.48 db mod NAK: , Message: Std: 25.0e.48->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 ------------------------------ Debug ------------------------------------------- 2020-11-25 16:37:00 INFO Mqtt: MQTT message insteon/command/25.0e.48 b'{"cmd": "pair", "session": "365943604"}' 2020-11-25 16:37:24 DEBUG Mqtt: MQTT publish insteon/command/25.0e.48/session/365943604 {"type": "MESSAGE", "data": "25.0e.48 database download complete\nDeviceDb: (delta 17)\n 0ea7: 53.bf.6b grp: 5 type: CTRL data: 0x03 0x00 0x05\n 0eaf: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04\n 0eb7: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03\n 0ebf: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02\n 0ec7: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01\n 0ecf: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01\n 0ed7: 2a.14.1b grp: 1 type: RESP data: 0x00 0x1c 0x01\n 0edf: 52.5d.ed grp: 4 type: RESP data: 0xd8 0x1c 0x01\n 0ee7: 24.11.1b grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0eef: 24.10.d8 grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0ef7: 52.5d.ed grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0eff: 24.11.1b grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f07: 24.10.d8 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f0f: 50.d0.7e grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f17: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06\n 0f1f: 52.d5.97 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f27: 52.71.b9 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f2f: 50.a7.1b grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f37: 13.1b.7f grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f3f: 50.a4.3e grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f47: 52.5d.ed grp: 3 type: RESP data: 0xff 0x1f 0x06\n 0f4f: 52.72.c8 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f57: 12.db.41 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f5f: 12.db.3f grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f67: 08.09.e3 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0f6f: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05\n 0f7f: 13.1d.70 grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0f87: 13.1c.ce grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0f8f: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04\n 0f97: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03\n 0f9f: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01\n 0fa7: 50.a7.1b grp: 1 type: CTRL data: 0xff 0x1f 0x01\n 0faf: 07.55.bb grp: 1 type: CTRL data: 0xff 0x1f 0x01\n 0fb7: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\n 0fbf: 07.55.bb grp: 1 type: RESP data: 0xd8 0x1c 0x01\n 0fc7: 3c.48.88 grp: 20 type: RESP data: 0xd8 0x1c 0x01\n 0fcf: 50.a7.1b grp: 1 type: RESP data: 0xd8 0x1c 0x01\n 0fd7: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x06\n 0fdf: 13.1c.ce grp: 1 type: RESP data: 0xff 0x1f 0x05\n 0fe7: 13.1d.70 grp: 1 type: RESP data: 0xff 0x1f 0x05\n 0fef: 13.3e.92 grp: 1 type: RESP data: 0xff 0x1f 0x05\n 0ff7: 3c.48.88 grp: 59 type: RESP data: 0xff 0x1f 0x05\nUnused:\nLast:\n 0e9f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['07.55.bb', '50.a7.1b', '3c.48.88', '24.10.d8', '24.11.1b', '53.bf.6b']\n 3 -> ['3c.48.88', '53.bf.6b']\n 4 -> ['3c.48.88', '53.bf.6b']\n 5 -> ['13.1c.ce', '13.1d.70', '3c.48.88', '53.bf.6b']\n 6 -> ['08.09.e3', '12.db.3f', '12.db.41', '52.72.c8', '50.a4.3e', '13.1b.7f', '50.a7.1b', '52.71.b9', '52.d5.97', '3c.48.88', '50.d0.7e', '24.10.d8', '24.11.1b', '52.5d.ed']\n 2 -> ['53.bf.6b']\n"} qos=0 ret=False |
|
Sometimes it drops out quickly... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 25.0e.48 -----------------------------------------------------Debug----------------------------------- 2020-11-25 17:05:36 INFO Mqtt: MQTT message insteon/command/25.0e.48 b'{"cmd": "pair", "session": "2127987448"}' |
|
I just noticed I am using a different keypad. The first keypad, 20.42.ac Dual Band KepadLinc Relay v.41, is able to pair now using the fix_231 code. The different one in the previous two failures is a (2334-2) KeypadLinc Dimmer 5 buttons v.43. |
|
I notice that this is another device. Does this fix anything with the original device? Edit: Well that is good, that seems like progress on the original problem. This new device has different failure reasons sadly: 2020-11-25 16:37:25 ERROR DeviceDbModify: 25.0e.48 db mod NAK: , Message: Std: 25.0e.48->53.bf.6b Type.DIRECT_NAK cmd: 2f 00 That is just a generic NAK failure. The cmd2 value of 0x00 doesn't provide any details. It is possible this device is just overloaded? Too many messages being sent to it? The error is happening even when we are just asking for the db contents. This starts too look like some of the fragile nature of the insteon protocol and I don't want to start making fixes for a specific device unless it is truly necessary. Can you restart this device? Pull the set button out for 10 seconds and then push it back in? I know that seems weird, but I have seen devices become overwhelmed before. |
|
This is another keypad... 2334-2 KeypadLinc Dimmer 8 buttons v.45. It has been idle for several hours... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 3d.7a.fe ------------------------- Debug ------------------------------------------------- 2020-11-25 17:19:40 INFO Mqtt: MQTT message insteon/command/3d.7a.fe b'{"cmd": "pair", "session": "271532832"}' |
|
Another keypad, fairly new, 2334-2 Keypadlinc Dimmer 5 buttons v.45 (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 ----------------------- Debug ------------------------------------------- 2020-11-25 17:22:18 INFO Mqtt: MQTT message insteon/command/52.5b.c0 b'{"cmd": "pair", "session": "498060667"}' |
|
All of these devices are working fine with ISY994 |
|
OK, those ones are ok. Apparently the Pre-NAK can be sent on the db get request as well. Let me add another patch to the branch real quick. |
|
Alright, I just pushed another commit, it should solve the ones failing with Pre-NAK on database get requests. |
|
(venv) jonsmirl@ares: ----------------de bug ----- 2020-11-25 17:29:23 INFO Mqtt: MQTT message insteon/command/52.5b.c0 b'{"cmd": "pair", "session": "1603648068"}' commit 8761793 (HEAD -> jds, keegan/Fix_231) commit bc4278d |
|
hrm, apparently I have missed something. Give me a minute. |
|
I joined it again and it is going further venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 ERROR: 52.5b.c0 device NAK error: Std: 52.5b.c0->53.bf.6b Type.DIRECT_NAK cmd: 10 fc ---------------------- Debug --------------------------------- ... |
|
Another error variation... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 Device 52.5b.c0 received model information: DIMMABLE_LIGHTING (0x01): '2334-222' (0x41) 'Keypad Dimmer Dual-Band, 8 Button' firmware: 0x45 --------------------------------------------- Debug ------------------------------------- 020-11-25 17:40:42 UI DeviceRefresh: 52.5b.c0 database download complete 2020-11-25 17:40:42 DEBUG Mqtt: MQTT publish insteon/command/52.5b.c0/session/2388968369 {"type": "MESSAGE", "data": "52.5b.c0 database download complete\nDeviceDb: (delta 4)\n 0f17: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01\n 0f1f: 24.0e.81 grp: 1 type: CTRL data: 0x03 0x1c 0x01\n 0f27: 50.c4.7e grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0f47: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x07\n 0f4f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x06\n 0f5f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x04\n 0f67: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x03\n 0f77: 50.2c.83 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f7f: 3c.48.88 grp: 98 type: RESP data: 0xff 0x1f 0x04\n 0f87: 50.10.14 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f8f: 3c.48.88 grp: 97 type: RESP data: 0xff 0x1f 0x03\n 0f97: 50.d0.70 grp: 2 type: CTRL data: 0x01 0x00 0x02\n 0f9f: 3c.48.88 grp: 96 type: RESP data: 0xff 0x1f 0x02\n 0fa7: 25.0e.3c grp: 6 type: RESP data: 0xff 0x1f 0x01\n 0faf: 29.48.4c grp: 7 type: RESP data: 0xff 0x1f 0x01\n 0fb7: 3c.48.88 grp: 51 type: RESP data: 0xff 0x1f 0x01\n 0fbf: 3c.48.88 grp: 8 type: CTRL data: 0x01 0x00 0x08\n 0fc7: 3c.48.88 grp: 7 type: CTRL data: 0x01 0x00 0x07\n 0fcf: 3c.48.88 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0fd7: 3c.48.88 grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0fe7: 3c.48.88 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fef: 3c.48.88 grp: 2 type: CTRL data: 0x01 0x00 0x02\n 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\nUnused:\nLast:\n 0f0f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['3c.48.88', '24.0e.81']\n 2 -> ['3c.48.88', '50.d0.70']\n 3 -> ['3c.48.88', '50.10.14']\n 5 -> ['3c.48.88', '50.c4.7e']\n 6 -> ['3c.48.88']\n 7 -> ['3c.48.88']\n 8 -> ['3c.48.88']\n 4 -> ['50.2c.83']\n"} qos=0 ret=False |
|
Just to confirm, you are restarting insteon-mqtt after you pull the new branch in? |
|
yes. no i lied, I forgot to install it into the venv |
|
ok, that might solve some of my confusion. You did identify another instance of it in a get_model request above which we can patch too. At this point though, I think we may need to think about patching this in every possible response, it is showing up in places I would not have expected from the brief description in the documentation. That said, I would like to see some improvement, to at least tell us that this is a valid solution. |
|
In one terminal I did other one (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 Device 52.5b.c0 add db already exists for 53.bf.6b grp 1 RESP --------------- debug ---------------------------- 2020-11-25 17:56:53 INFO Mqtt: MQTT message insteon/command/52.5b.c0 b'{"cmd": "pair", "session": "1082199147"}' 2020-11-25 17:58:22 DEBUG Mqtt: MQTT publish insteon/command/52.5b.c0/session/1082199147 {"type": "MESSAGE", "data": "52.5b.c0 database download complete\nDeviceDb: (delta 6)\n 0f17: 53.bf.6b grp: 1 type: RESP data: 0xff 0x1f 0x01\n 0f1f: 24.0e.81 grp: 1 type: CTRL data: 0x03 0x1c 0x01\n 0f27: 50.c4.7e grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0f2f: 3c.48.88 grp: 100 type: RESP data: 0xff 0x1f 0x05\n 0f37: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x01\n 0f3f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x08\n 0f47: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x07\n 0f4f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x06\n 0f57: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x05\n 0f5f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x04\n 0f67: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x03\n 0f6f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x02\n 0f77: 50.2c.83 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f7f: 3c.48.88 grp: 98 type: RESP data: 0xff 0x1f 0x04\n 0f87: 50.10.14 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f8f: 3c.48.88 grp: 97 type: RESP data: 0xff 0x1f 0x03\n 0f97: 50.d0.70 grp: 2 type: CTRL data: 0x01 0x00 0x02\n 0f9f: 3c.48.88 grp: 96 type: RESP data: 0xff 0x1f 0x02\n 0fa7: 25.0e.3c grp: 6 type: RESP data: 0xff 0x1f 0x01\n 0faf: 29.48.4c grp: 7 type: RESP data: 0xff 0x1f 0x01\n 0fb7: 3c.48.88 grp: 51 type: RESP data: 0xff 0x1f 0x01\n 0fbf: 3c.48.88 grp: 8 type: CTRL data: 0x01 0x00 0x08\n 0fc7: 3c.48.88 grp: 7 type: CTRL data: 0x01 0x00 0x07\n 0fcf: 3c.48.88 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0fd7: 3c.48.88 grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0fdf: 3c.48.88 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0fe7: 3c.48.88 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fef: 3c.48.88 grp: 2 type: CTRL data: 0x01 0x00 0x02\n 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\nUnused:\nLast:\n 0f0f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['3c.48.88', '24.0e.81']\n 3 -> ['3c.48.88', '50.10.14']\n 4 -> ['3c.48.88', '50.2c.83']\n 5 -> ['3c.48.88', '50.c4.7e']\n 6 -> ['3c.48.88']\n 7 -> ['3c.48.88']\n 8 -> ['3c.48.88']\n 2 -> ['50.d0.70', '3c.48.88']\n"} qos=0 ret=False |
|
Another pair try on the same device... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 Device 52.5b.c0 add db already exists for 53.bf.6b grp 1 RESP ------------------- debug -------------------------------- 2020-11-25 18:00:45 INFO Mqtt: MQTT message insteon/command/52.5b.c0 b'{"cmd": "pair", "session": "1805311423"}' 2020-11-25 18:01:20 DEBUG Mqtt: MQTT publish insteon/command/52.5b.c0/session/1805311423 {"type": "MESSAGE", "data": "52.5b.c0 database download complete\nDeviceDb: (delta 7)\n 0f17: 53.bf.6b grp: 1 type: RESP data: 0xff 0x1f 0x01\n 0f1f: 24.0e.81 grp: 1 type: CTRL data: 0x03 0x1c 0x01\n 0f27: 50.c4.7e grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0f2f: 3c.48.88 grp: 100 type: RESP data: 0xff 0x1f 0x05\n 0f37: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x01\n 0f3f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x08\n 0f4f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x06\n 0f57: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x05\n 0f5f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x04\n 0f67: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x03\n 0f6f: 3c.48.88 grp: 99 type: RESP data: 0xff 0x1f 0x02\n 0f77: 50.2c.83 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f7f: 3c.48.88 grp: 98 type: RESP data: 0xff 0x1f 0x04\n 0f87: 50.10.14 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f8f: 3c.48.88 grp: 97 type: RESP data: 0xff 0x1f 0x03\n 0f97: 50.d0.70 grp: 2 type: CTRL data: 0x01 0x00 0x02\n 0f9f: 3c.48.88 grp: 96 type: RESP data: 0xff 0x1f 0x02\n 0fa7: 25.0e.3c grp: 6 type: RESP data: 0xff 0x1f 0x01\n 0faf: 29.48.4c grp: 7 type: RESP data: 0xff 0x1f 0x01\n 0fb7: 3c.48.88 grp: 51 type: RESP data: 0xff 0x1f 0x01\n 0fbf: 3c.48.88 grp: 8 type: CTRL data: 0x01 0x00 0x08\n 0fcf: 3c.48.88 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0fd7: 3c.48.88 grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0fdf: 3c.48.88 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0fe7: 3c.48.88 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fef: 3c.48.88 grp: 2 type: CTRL data: 0x01 0x00 0x02\n 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\nUnused:\nLast:\n 0f0f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['3c.48.88', '24.0e.81']\n 2 -> ['3c.48.88', '50.d0.70']\n 3 -> ['3c.48.88', '50.10.14']\n 4 -> ['3c.48.88', '50.2c.83']\n 5 -> ['3c.48.88', '50.c4.7e']\n 6 -> ['3c.48.88']\n 8 -> ['3c.48.88']\n"} qos=0 ret=False |
|
Here is the ISY994 log from restoring the same Keypad Wed 11/25/2020 06:11:33 PM : [ 52 5B C0 1] Preparing Device 'Theater KP.1' for Restore --------------------------- low level log ----------------------------------------------------------------- It gets an error and then recovers... Wed 11/25/2020 06:14:07 PM : [ 52 5B C0 1] Preparing Device 'Theater KP.1' for Restore ---- I dump the device links table --------- Wed 11/25/2020 06:18:36 PM : [INST-TX-I2CS] 02 62 52 5B C0 1F 2F 00 00 00 0F FF 01 00 00 00 00 00 00 00 00 C2 |
|
So, in one sense it looks like part of this may be working: There, we just waited longer for the response to the DBGet to come through and it eventually did. However, later on the same device: There we waited 6 seconds! And nothing else came in. That isn't good. In your second post this looks like normal the normal insteon mess. Here this is a write attempt on the modem. It looks like a spurious message comes. That causes the modem to get confused and things fail. This happens. I am a little more interested in the first post. It seems like we are not retrying that message, that doesn't seem right. |
|
Example of ISY994 recovering from errors. This is dumping a link 52 entry link database from a keypad. Wed 11/25/2020 06:25:27 PM : [INST-TX-I2CS] 02 62 25 0E 3C 1F 2F 00 00 00 0F FF 01 00 00 00 00 00 00 00 00 C2 |
|
OK, there is a lot of Yak shearing going on here. I pushed another commit that changes the retry count for dbget and dbmodify to 3. Not sure why these were set to 0 retries, I couldn't find any evidence that this as an intentional decision. So try again and see what we get. |
|
first one seems to be confused, this is a fresh keypad.... (venv) jonsmirl@ares: Device 52.5d.ed received model information: DIMMABLE_LIGHTING (0x01): '2334-232' (0x42) 'Keypad Dimmer Dual-Band, 6 Button' firmware: 0x45 --- debug -------------- 2020-11-25 19:19:08 INFO Mqtt: MQTT message insteon/command/52.5d.ed b'{"cmd": "pair", "session": "1709680973"}' 2020-11-25 19:19:50 DEBUG Mqtt: MQTT publish insteon/command/52.5d.ed/session/2229040263 {"type": "MESSAGE", "data": "52.5d.ed database download complete\nDeviceDb: (delta 2)\n 0f07: 24.11.1b grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f0f: 24.10.d8 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f17: 25.0e.48 grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f1f: 25.0e.48 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f27: 50.a7.1b grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f2f: 50.a7.1b grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f37: 07.55.bb grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f3f: 07.55.bb grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f47: 3c.48.88 grp: 20 type: RESP data: 0xff 0x1f 0x04\n 0f4f: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01\n 0f57: 24.10.d8 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f5f: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f67: 25.0e.48 grp: 6 type: RESP data: 0xff 0x1f 0x01\n 0f6f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x1c 0x01\n 0f77: 13.1b.7f grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f7f: 50.a7.1b grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f87: 52.71.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f8f: 12.db.3f grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f97: 12.db.41 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f9f: 52.d5.97 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fa7: 08.09.e3 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fb7: 50.a4.3e grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fbf: 3c.48.88 grp: 73 type: RESP data: 0xff 0x1f 0x01\n 0fc7: 25.0e.48 grp: 6 type: RESP data: 0xff 0x1f 0x03\n 0fcf: 3c.48.88 grp: 73 type: RESP data: 0xff 0x1f 0x03\n 0fd7: 3c.48.88 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0fdf: 3c.48.88 grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0fe7: 3c.48.88 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0fef: 3c.48.88 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\n f053: 52.72.c8 grp: 3 type: CTRL data: 0x01 0x00 0x03\nUnused:\n 0eff: 50.d0.2c grp: 3 type: CTRL data: 0x01 0x00 0x03 (UNUSED)\nLast:\n 0ef7: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['3c.48.88', '53.bf.6b']\n 3 -> ['3c.48.88', '50.a4.3e', '52.72.c8', '08.09.e3', '52.d5.97', '12.db.41', '12.db.3f', '52.71.b9', '50.a7.1b', '13.1b.7f', '50.d0.7e', '24.10.d8']\n 4 -> ['3c.48.88', '07.55.bb', '50.a7.1b', '25.0e.48', '24.10.d8', '24.11.1b']\n 5 -> ['3c.48.88']\n 6 -> ['3c.48.88']\n"} qos=0 ret=False |
|
That looks ok. It handled it just fine where I fixed things. But yeah, it looks like we are going to need to do this for every handler. That error gets sent at times that don't match the spec at all. |
|
I pushed a commit that fixes all instances where NAKs are handled, at least to my knowledge. This should fix a lot of your errors. It likely won't fix all of them. You have a very large network with lots of links. Sadly our experience has been that Insteon has some inherent errors and the larger things get the more frequently you see them. I have no doubt that the ISY is encountering many of the same errors and is just brute forcing things. I think the goal here is to try and stick to the spec as much as possible. So if a message is getting garbled or a device responds poorly it may result in an error that is reported to the user. But you should able to repeat the command again and hopefully things will work. If you are repeatedly getting the same error on the same device and cannot complete a task, then we should dig into why that is and see what we can do. You will continue to see the Pre NAK show up as a warning. But if you are finding places where it is still reporting an ERROR and causing things to break let me know. |
|
with commit 38faf43 GroupMap 52.5d.ed Pre-NAK: Pre NAK in case database search takes too long, Message: Std: 52.5d.ed->53.bf.6b Type.DIRECT_NAK cmd: 2f fc ------------------- debug -------------------------------- 2020-11-25 20:28:54 INFO Mqtt: MQTT message insteon/command/52.5d.ed b'{"cmd": "pair", "session": "3887783762"}' 2020-11-25 20:29:19 DEBUG Mqtt: MQTT publish insteon/command/52.5d.ed/session/2597527258 {"type": "MESSAGE", "data": "52.5d.ed database download complete\nDeviceDb: (delta 15)\n 0eef: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04\n 0ef7: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03\n 0eff: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02\n 0f07: 24.11.1b grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f0f: 24.10.d8 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f17: 25.0e.48 grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f1f: 25.0e.48 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f27: 50.a7.1b grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f2f: 50.a7.1b grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f37: 07.55.bb grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f3f: 07.55.bb grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0f47: 3c.48.88 grp: 20 type: RESP data: 0xff 0x1f 0x04\n 0f4f: 53.bf.6b grp: 1 type: RESP data: 0x00 0x1c 0x01\n 0f57: 24.10.d8 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f5f: 50.d0.7e grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f67: 25.0e.48 grp: 6 type: RESP data: 0xff 0x1f 0x01\n 0f6f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01\n 0f77: 13.1b.7f grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f7f: 50.a7.1b grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f87: 52.71.b9 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f8f: 12.db.3f grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f97: 12.db.41 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0f9f: 52.d5.97 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fa7: 08.09.e3 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0faf: 52.72.c8 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fb7: 50.a4.3e grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0fbf: 3c.48.88 grp: 73 type: RESP data: 0xff 0x1f 0x01\n 0fc7: 25.0e.48 grp: 6 type: RESP data: 0xff 0x1f 0x03\n 0fcf: 3c.48.88 grp: 73 type: RESP data: 0xff 0x1f 0x03\n 0fd7: 3c.48.88 grp: 6 type: CTRL data: 0x01 0x00 0x06\n 0fdf: 3c.48.88 grp: 5 type: CTRL data: 0x01 0x00 0x05\n 0fe7: 3c.48.88 grp: 4 type: CTRL data: 0x01 0x00 0x04\n 0fef: 3c.48.88 grp: 3 type: CTRL data: 0x01 0x00 0x03\n 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0x01 0x00 0x01\n 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\nUnused:\nLast:\n 0ee7: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['3c.48.88', '53.bf.6b']\n 3 -> ['3c.48.88', '50.a4.3e', '52.72.c8', '08.09.e3', '52.d5.97', '12.db.41', '12.db.3f', '52.71.b9', '50.a7.1b', '13.1b.7f', '50.d0.7e', '24.10.d8', '53.bf.6b']\n 4 -> ['3c.48.88', '07.55.bb', '50.a7.1b', '25.0e.48', '24.10.d8', '24.11.1b', '53.bf.6b']\n 5 -> ['3c.48.88']\n 6 -> ['3c.48.88']\n 2 -> ['53.bf.6b']\n"} qos=0 ret=False |
|
After about five tries I got 52.5d.ed to pair. |
|
The checksum fail is a sign that messages are getting garbled in transit. Glad it finally paired completely. |
|
what is going on here? This one command times out, but the replies keep coming. I see something similar in the ISY994. In some cases it decides to no retry a command because it is getting the data. It is like the initial ACK got lost. The ISY then ignores the command that failed because it got the data anyway. (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 52.5b.c0 |
|
My keypads are often failing with this quick error... (venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 29.53.46 --- but then if you look at the debug, the database keeps coming in for another minute. ---- 2020-11-26 15:40:12 INFO Mqtt: MQTT message insteon/command/29.53.46 b'{"cmd": "pair", "session": "854463417"}' |
If receive a Pre NAK, add to wait time and wait for actual NAK. This is a strange NAK which is sent when the device db is large and searching it would take more time that permitted in normal message ACK. This may fix TD22057#231
The notes in the device db contain the following: The last entry in the database. Devices show an unused, null (all zeros) marked with the LAST bit set in the db. From the docs this shouldn't be required - the LAST bit can be a usable entry but it doesn't appear to work. Which suggests that having the last entry be a usable one doesn't work. But some of the errors in #231 suggest that maybe duplicating entries no longer works. This instead sets the last entry to all 0x00s which is what a factory reset entry looks like. I have hopes that this may solve generic NAK errors on new devices when adding entries using a new address.
I can not get this one to pair without errors....
(venv) jonsmirl@ares:~/aosp/insteon-mqtt$ insteon-mqtt config.yaml pair 20.42.ac
Commanding keypad_linc_sw device 20.42.ac (1st / butler / bulter hall cabinet.1.1) cmd=pair
KeypadLinc 20.42.ac setting LED bits 11000000
KeypadLinc 20.42.ac refresh at level 0
Device 20.42.ac db out of date (got 11 vs 7), refreshing
Entry: 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01
Entry: 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01
Entry: 0fef: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03
Entry: 0fe7: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04
Entry: 0fdf: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05
Entry: 0fd7: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06
Entry: 0fcf: 3c.48.88 grp: 43 type: RESP data: 0xff 0x1f 0x05
Entry: 0fc7: 4a.e9.67 grp: 5 type: CTRL data: 0xff 0x1f 0x05
Entry: 0fbf: 4a.e9.67 grp: 1 type: RESP data: 0xff 0x1f 0x05
Entry: 0fb7: 1e.47.59 grp: 45 type: RESP data: 0xff 0x1f 0x06
Entry: 0faf: 13.18.5d grp: 6 type: CTRL data: 0xff 0x1f 0x06
Entry: 0fa7: 13.18.5d grp: 1 type: RESP data: 0xff 0x1f 0x06
Entry: 0f9f: 3c.48.88 grp: 44 type: RESP data: 0xff 0x1f 0x03
Entry: 0f97: 4a.ed.f8 grp: 3 type: CTRL data: 0xff 0x1f 0x03
Entry: 0f8f: 4a.ed.f8 grp: 1 type: RESP data: 0xff 0x1f 0x03
Entry: 0f87: 3c.48.88 grp: 47 type: RESP data: 0xff 0x1f 0x04
Entry: 0f7f: 13.1b.dd grp: 4 type: CTRL data: 0xff 0x1f 0x04
Entry: 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04
Entry: 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04
Entry: 0f6f: 3c.48.88 grp: 82 type: RESP data: 0xff 0x1f 0x04
Entry: 0f67: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1c 0x01
Entry: 0f5f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01
Entry: 0f57: 52.bb.ce grp: 1 type: CTRL data: 0x03 0x1c 0x01
Entry: 0f4f: 53.bf.6b grp: 1 type: RESP data: 0xff 0x00 0x01
Entry: 0f47: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02
Entry: 0f3f: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03
Entry: 0f37: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04
Entry: 0f2f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
20.42.ac database download complete
DeviceDb: (delta 11)
0f37: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04
0f3f: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03
0f47: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02
0f4f: 53.bf.6b grp: 1 type: RESP data: 0xff 0x00 0x01
0f57: 52.bb.ce grp: 1 type: CTRL data: 0x03 0x1c 0x01
0f5f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01
0f67: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1c 0x01
0f6f: 3c.48.88 grp: 82 type: RESP data: 0xff 0x1f 0x04
0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04
0f7f: 13.1b.dd grp: 4 type: CTRL data: 0xff 0x1f 0x04
0f87: 3c.48.88 grp: 47 type: RESP data: 0xff 0x1f 0x04
0f8f: 4a.ed.f8 grp: 1 type: RESP data: 0xff 0x1f 0x03
0f97: 4a.ed.f8 grp: 3 type: CTRL data: 0xff 0x1f 0x03
0f9f: 3c.48.88 grp: 44 type: RESP data: 0xff 0x1f 0x03
0fa7: 13.18.5d grp: 1 type: RESP data: 0xff 0x1f 0x06
0faf: 13.18.5d grp: 6 type: CTRL data: 0xff 0x1f 0x06
0fb7: 1e.47.59 grp: 45 type: RESP data: 0xff 0x1f 0x06
0fbf: 4a.e9.67 grp: 1 type: RESP data: 0xff 0x1f 0x05
0fc7: 4a.e9.67 grp: 5 type: CTRL data: 0xff 0x1f 0x05
0fcf: 3c.48.88 grp: 43 type: RESP data: 0xff 0x1f 0x05
0fd7: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06
0fdf: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05
0fe7: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04
0fef: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03
0ff7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01
0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01
Unused:
Last:
0f2f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
GroupMap
1 -> ['3c.48.88', '53.bf.6b', '52.bb.ce']
3 -> ['3c.48.88', '4a.ed.f8', '53.bf.6b']
4 -> ['3c.48.88', '13.1b.dd', '53.bf.6b']
5 -> ['3c.48.88', '4a.e9.67']
6 -> ['3c.48.88', '13.18.5d']
2 -> ['53.bf.6b']
Device 20.42.ac add db already exists for 53.bf.6b grp 1 RESP
Modem add db already exists for 20.42.ac grp 1 CTRL
Device 20.42.ac add db already exists for 53.bf.6b grp 1 CTRL
Modem add db already exists for 20.42.ac grp 1 RESP
Device 20.42.ac add db already exists for 53.bf.6b grp 2 CTRL
Modem add db already exists for 20.42.ac grp 2 RESP
Device 20.42.ac add db already exists for 53.bf.6b grp 3 CTRL
Modem add db already exists for 20.42.ac grp 3 RESP
Device 20.42.ac add db already exists for 53.bf.6b grp 4 CTRL
ERROR: 20.42.ac db mod NAK: Pre NAK in case database search takes too long, Message: Std: 20.42.ac->53.bf.6b Type.DIRECT_NAK cmd: 2f fc
ERROR: Device database update failed. Pre NAK in case database search takes too long
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-11-25 13:42:42 INFO Mqtt: MQTT message insteon/command/20.42.ac b'{"cmd": "pair", "session": "806609784"}'
2020-11-25 13:42:42 UI Mqtt: Commanding keypad_linc_sw device 20.42.ac (1st / butler / bulter hall cabinet.1.1) cmd=pair
2020-11-25 13:42:42 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Commanding keypad_linc_sw device 20.42.ac (1st / butler / bulter hall cabinet.1.1) cmd=pair"} qos=0 ret=False
2020-11-25 13:42:42 INFO KeypadLinc: KeypadLinc 20.42.ac pairing
2020-11-25 13:42:42 DEBUG CommandSeq: Running command 1 of 11
2020-11-25 13:42:42 INFO KeypadLinc: KeypadLinc 20.42.ac cmd: keypad status refresh
2020-11-25 13:42:42 DEBUG CommandSeq: Running command 1 of 3
2020-11-25 13:42:42 INFO Protocol: Write message to modem: Std: 20.42.ac, Type.DIRECT, 19 01
2020-11-25 13:42:42 DEBUG Protocol: Write bytes to modem: 02622042ac0f1901
2020-11-25 13:42:42 DEBUG Serial: Wrote 8 bytes to serial /dev/insteon
2020-11-25 13:42:42 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:42 INFO Protocol: Read 0x62: Std: 20.42.ac, Type.DIRECT, 19 01 ack: True
2020-11-25 13:42:42 DEBUG Protocol: Passing msg to write handler: DeviceRefresh handler
2020-11-25 13:42:42 DEBUG DeviceRefresh: 20.42.ac ACK response
2020-11-25 13:42:42 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 0b c0
2020-11-25 13:42:42 DEBUG Protocol: Setting next write time: 1606329762.823309
2020-11-25 13:42:42 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:42 DEBUG Protocol: Passing msg to write handler: DeviceRefresh handler
2020-11-25 13:42:42 UI KeypadLinc: KeypadLinc 20.42.ac setting LED bits 11000000
2020-11-25 13:42:42 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "KeypadLinc 20.42.ac setting LED bits 11000000"} qos=0 ret=False
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 1 old: 0 new 0
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 2 old: 0 new 0
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 3 old: 0 new 0
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 4 old: 0 new 0
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 5 old: 0 new 0
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 6 old: 0 new 0
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 7 old: 1 new 1
2020-11-25 13:42:42 DEBUG KeypadLinc: Btn 8 old: 1 new 1
2020-11-25 13:42:42 DEBUG CommandSeq: Running command 2 of 3
2020-11-25 13:42:42 DEBUG Protocol: Write handler finished
2020-11-25 13:42:42 INFO Protocol: Write message to modem: Std: 20.42.ac, Type.DIRECT, 19 00
2020-11-25 13:42:42 DEBUG Protocol: Write bytes to modem: 02622042ac0f1900
2020-11-25 13:42:42 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:42 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 0b c0
2020-11-25 13:42:42 DEBUG Protocol: Setting next write time: 1606329762.753773
2020-11-25 13:42:42 INFO Protocol: Ignored duplicate Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 0b c0
2020-11-25 13:42:42 DEBUG Serial: Wrote 8 bytes to serial /dev/insteon
2020-11-25 13:42:42 INFO Protocol: Read 0x62: Std: 20.42.ac, Type.DIRECT, 19 00 ack: True
2020-11-25 13:42:42 DEBUG Protocol: Passing msg to write handler: DeviceRefresh handler
2020-11-25 13:42:42 DEBUG DeviceRefresh: 20.42.ac ACK response
2020-11-25 13:42:43 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 0b 00
2020-11-25 13:42:43 DEBUG Protocol: Setting next write time: 1606329763.398141
2020-11-25 13:42:43 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:43 DEBUG Protocol: Passing msg to write handler: DeviceRefresh handler
2020-11-25 13:42:43 UI KeypadLinc: KeypadLinc 20.42.ac refresh at level 0
2020-11-25 13:42:43 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "KeypadLinc 20.42.ac refresh at level 0"} qos=0 ret=False
2020-11-25 13:42:43 INFO KeypadLinc: Setting device 20.42.ac (1st / butler / bulter hall cabinet.1.1) grp=1 on=0 normalrefresh
2020-11-25 13:42:43 INFO KeypadLinc: MQTT received button press 20.42.ac (1st / butler / bulter hall cabinet.1.1) = btn 1 at 0 normal refresh
2020-11-25 13:42:43 DEBUG Mqtt: MQTT publish insteon/20.42.ac/state/1 OFF qos=1 ret=1
2020-11-25 13:42:43 UI DeviceRefresh: Device 20.42.ac db out of date (got 11 vs 7), refreshing
2020-11-25 13:42:43 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Device 20.42.ac db out of date (got 11 vs 7), refreshing"} qos=0 ret=False
2020-11-25 13:42:43 DEBUG MsgHistory: Average hops 0.2, using 1
2020-11-25 13:42:43 DEBUG Protocol: Write handler finished
2020-11-25 13:42:43 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2020-11-25 13:42:43 DEBUG Protocol: Write bytes to modem: 02622042ac152f0000000000000000000000000000d1
2020-11-25 13:42:43 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:43 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:43 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 00 00 00 00 00 00 00 00 00 00 00 00 d1
2020-11-25 13:42:43 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:43 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:43 DEBUG Protocol: Setting next write time: 1606329763.814567
2020-11-25 13:42:43 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:43 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:43 INFO DeviceDbGet: 20.42.ac device ACK response
2020-11-25 13:42:43 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:43 DEBUG Protocol: Setting next write time: 1606329763.823379
2020-11-25 13:42:43 DEBUG MsgHistory: Received 1 hops, total 3 for 11 entries
2020-11-25 13:42:43 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:43 INFO DeviceDbGet: 20.42.ac device ACK response
2020-11-25 13:42:43 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f ff 20 a2 00 3c 48 88 ff 1f 01 d5
2020-11-25 13:42:43 DEBUG MsgHistory: Received 0 hops, total 3 for 11 entries
2020-11-25 13:42:43 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:43 UI DeviceDbGet: Entry: 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01
2020-11-25 13:42:43 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01"} qos=0 ret=False
2020-11-25 13:42:43 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:44 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f f7 20 e2 01 3c 48 88 ff 1f 01 9c
2020-11-25 13:42:44 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:44 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:44 UI DeviceDbGet: Entry: 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01
2020-11-25 13:42:44 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01"} qos=0 ret=False
2020-11-25 13:42:44 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:44 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f ef 20 e2 03 3c 48 88 ff 1f 03 a0
2020-11-25 13:42:44 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:44 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:44 UI DeviceDbGet: Entry: 0fef: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03
2020-11-25 13:42:44 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fef: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03"} qos=0 ret=False
2020-11-25 13:42:44 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:45 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f e7 20 e2 04 3c 48 88 ff 1f 04 a6
2020-11-25 13:42:45 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:45 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:45 UI DeviceDbGet: Entry: 0fe7: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04
2020-11-25 13:42:45 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fe7: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04"} qos=0 ret=False
2020-11-25 13:42:45 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:45 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f df 20 e2 05 3c 48 88 ff 1f 05 ac
2020-11-25 13:42:45 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:45 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:45 UI DeviceDbGet: Entry: 0fdf: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05
2020-11-25 13:42:45 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fdf: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05"} qos=0 ret=False
2020-11-25 13:42:45 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:45 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f d7 20 e2 06 3c 48 88 ff 1f 06 b2
2020-11-25 13:42:45 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:45 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:45 UI DeviceDbGet: Entry: 0fd7: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06
2020-11-25 13:42:45 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fd7: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06"} qos=0 ret=False
2020-11-25 13:42:45 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:46 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f cf 20 a2 2b 3c 48 88 ff 1f 05 d6
2020-11-25 13:42:46 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:46 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:46 UI DeviceDbGet: Entry: 0fcf: 3c.48.88 grp: 43 type: RESP data: 0xff 0x1f 0x05
2020-11-25 13:42:46 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fcf: 3c.48.88 grp: 43 type: RESP data: 0xff 0x1f 0x05"} qos=0 ret=False
2020-11-25 13:42:46 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:46 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f c7 20 e2 05 4a e9 67 ff 1f 05 36
2020-11-25 13:42:46 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:46 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:46 UI DeviceDbGet: Entry: 0fc7: 4a.e9.67 grp: 5 type: CTRL data: 0xff 0x1f 0x05
2020-11-25 13:42:46 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fc7: 4a.e9.67 grp: 5 type: CTRL data: 0xff 0x1f 0x05"} qos=0 ret=False
2020-11-25 13:42:46 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:47 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f bf 20 a2 01 4a e9 67 ff 1f 05 82
2020-11-25 13:42:47 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:47 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:47 UI DeviceDbGet: Entry: 0fbf: 4a.e9.67 grp: 1 type: RESP data: 0xff 0x1f 0x05
2020-11-25 13:42:47 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fbf: 4a.e9.67 grp: 1 type: RESP data: 0xff 0x1f 0x05"} qos=0 ret=False
2020-11-25 13:42:47 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:47 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f b7 20 a2 2d 1e 47 59 ff 1f 06 39
2020-11-25 13:42:47 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:47 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:47 UI DeviceDbGet: Entry: 0fb7: 1e.47.59 grp: 45 type: RESP data: 0xff 0x1f 0x06
2020-11-25 13:42:47 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fb7: 1e.47.59 grp: 45 type: RESP data: 0xff 0x1f 0x06"} qos=0 ret=False
2020-11-25 13:42:47 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:48 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f af 20 e2 06 13 18 5d ff 1f 06 5e
2020-11-25 13:42:48 DEBUG MsgHistory: Received 1 hops, total 1 for 11 entries
2020-11-25 13:42:48 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:48 UI DeviceDbGet: Entry: 0faf: 13.18.5d grp: 6 type: CTRL data: 0xff 0x1f 0x06
2020-11-25 13:42:48 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0faf: 13.18.5d grp: 6 type: CTRL data: 0xff 0x1f 0x06"} qos=0 ret=False
2020-11-25 13:42:48 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:48 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f a7 20 a2 01 13 18 5d ff 1f 06 ab
2020-11-25 13:42:48 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:48 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:48 UI DeviceDbGet: Entry: 0fa7: 13.18.5d grp: 1 type: RESP data: 0xff 0x1f 0x06
2020-11-25 13:42:48 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0fa7: 13.18.5d grp: 1 type: RESP data: 0xff 0x1f 0x06"} qos=0 ret=False
2020-11-25 13:42:48 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:48 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 9f 20 a2 2c 3c 48 88 ff 1f 03 07
2020-11-25 13:42:48 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:48 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:48 UI DeviceDbGet: Entry: 0f9f: 3c.48.88 grp: 44 type: RESP data: 0xff 0x1f 0x03
2020-11-25 13:42:48 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f9f: 3c.48.88 grp: 44 type: RESP data: 0xff 0x1f 0x03"} qos=0 ret=False
2020-11-25 13:42:48 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:48 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 97 20 e2 03 4a ed f8 ff 1f 03 d5
2020-11-25 13:42:48 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:48 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:48 UI DeviceDbGet: Entry: 0f97: 4a.ed.f8 grp: 3 type: CTRL data: 0xff 0x1f 0x03
2020-11-25 13:42:48 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f97: 4a.ed.f8 grp: 3 type: CTRL data: 0xff 0x1f 0x03"} qos=0 ret=False
2020-11-25 13:42:48 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:49 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 8f 20 a2 01 4a ed f8 ff 1f 03 1f
2020-11-25 13:42:49 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:49 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:49 UI DeviceDbGet: Entry: 0f8f: 4a.ed.f8 grp: 1 type: RESP data: 0xff 0x1f 0x03
2020-11-25 13:42:49 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f8f: 4a.ed.f8 grp: 1 type: RESP data: 0xff 0x1f 0x03"} qos=0 ret=False
2020-11-25 13:42:49 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:49 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 87 20 a2 2f 3c 48 88 ff 1f 04 1b
2020-11-25 13:42:49 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:49 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:49 UI DeviceDbGet: Entry: 0f87: 3c.48.88 grp: 47 type: RESP data: 0xff 0x1f 0x04
2020-11-25 13:42:49 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f87: 3c.48.88 grp: 47 type: RESP data: 0xff 0x1f 0x04"} qos=0 ret=False
2020-11-25 13:42:49 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:49 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 7f 20 e2 04 13 1b dd ff 1f 04 0f
2020-11-25 13:42:49 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:49 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:49 UI DeviceDbGet: Entry: 0f7f: 13.1b.dd grp: 4 type: CTRL data: 0xff 0x1f 0x04
2020-11-25 13:42:49 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f7f: 13.1b.dd grp: 4 type: CTRL data: 0xff 0x1f 0x04"} qos=0 ret=False
2020-11-25 13:42:49 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:50 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 77 20 a2 01 13 1b dd ff 1f 04 5a
2020-11-25 13:42:50 DEBUG MsgHistory: Received 1 hops, total 2 for 11 entries
2020-11-25 13:42:50 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:50 UI DeviceDbGet: Entry: 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04
2020-11-25 13:42:50 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04"} qos=0 ret=False
2020-11-25 13:42:50 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:50 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 77 20 a2 01 13 1b dd ff 1f 04 5a
2020-11-25 13:42:50 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:50 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:50 UI DeviceDbGet: Entry: 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04
2020-11-25 13:42:50 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04"} qos=0 ret=False
2020-11-25 13:42:50 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:51 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 6f 20 a2 52 3c 48 88 ff 1f 04 10
2020-11-25 13:42:51 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:51 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:51 UI DeviceDbGet: Entry: 0f6f: 3c.48.88 grp: 82 type: RESP data: 0xff 0x1f 0x04
2020-11-25 13:42:51 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f6f: 3c.48.88 grp: 82 type: RESP data: 0xff 0x1f 0x04"} qos=0 ret=False
2020-11-25 13:42:51 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:51 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 67 20 aa 00 3c 48 88 ff 1c 01 68
2020-11-25 13:42:51 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:51 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:51 UI DeviceDbGet: Entry: 0f67: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1c 0x01
2020-11-25 13:42:51 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f67: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1c 0x01"} qos=0 ret=False
2020-11-25 13:42:51 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:51 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 5f 20 e2 01 53 bf 6b 03 00 01 de
2020-11-25 13:42:51 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:51 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:51 UI DeviceDbGet: Entry: 0f5f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01
2020-11-25 13:42:51 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f5f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01"} qos=0 ret=False
2020-11-25 13:42:51 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:52 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 57 20 ea 01 52 bb ce 03 1c 01 64
2020-11-25 13:42:52 DEBUG MsgHistory: Received 1 hops, total 2 for 11 entries
2020-11-25 13:42:52 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:52 UI DeviceDbGet: Entry: 0f57: 52.bb.ce grp: 1 type: CTRL data: 0x03 0x1c 0x01
2020-11-25 13:42:52 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f57: 52.bb.ce grp: 1 type: CTRL data: 0x03 0x1c 0x01"} qos=0 ret=False
2020-11-25 13:42:52 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:52 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 4f 20 a2 01 53 bf 6b ff 00 01 32
2020-11-25 13:42:52 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:52 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:52 UI DeviceDbGet: Entry: 0f4f: 53.bf.6b grp: 1 type: RESP data: 0xff 0x00 0x01
2020-11-25 13:42:52 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f4f: 53.bf.6b grp: 1 type: RESP data: 0xff 0x00 0x01"} qos=0 ret=False
2020-11-25 13:42:52 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:53 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 47 20 e2 02 53 bf 6b 03 00 02 f4
2020-11-25 13:42:53 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:53 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:53 UI DeviceDbGet: Entry: 0f47: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02
2020-11-25 13:42:53 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f47: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02"} qos=0 ret=False
2020-11-25 13:42:53 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:53 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 3f 20 e2 03 53 bf 6b 03 00 03 fa
2020-11-25 13:42:53 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:53 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:53 UI DeviceDbGet: Entry: 0f3f: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03
2020-11-25 13:42:53 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f3f: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03"} qos=0 ret=False
2020-11-25 13:42:53 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:53 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 37 20 e2 04 53 bf 6b 03 00 04 00
2020-11-25 13:42:53 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:53 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:53 UI DeviceDbGet: Entry: 0f37: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04
2020-11-25 13:42:53 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f37: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04"} qos=0 ret=False
2020-11-25 13:42:53 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:54 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2f 00
00 01 0f 2f 20 20 00 00 00 00 00 00 00 52
2020-11-25 13:42:54 DEBUG MsgHistory: Received 0 hops, total 2 for 11 entries
2020-11-25 13:42:54 DEBUG Protocol: Passing msg to write handler: DeviceDbGet handler
2020-11-25 13:42:54 UI DeviceDbGet: Entry: 0f2f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
2020-11-25 13:42:54 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Entry: 0f2f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)"} qos=0 ret=False
2020-11-25 13:42:54 UI DeviceRefresh: 20.42.ac database download complete
DeviceDb: (delta 11)
0f37: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04
0f3f: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03
0f47: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02
0f4f: 53.bf.6b grp: 1 type: RESP data: 0xff 0x00 0x01
0f57: 52.bb.ce grp: 1 type: CTRL data: 0x03 0x1c 0x01
0f5f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01
0f67: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1c 0x01
0f6f: 3c.48.88 grp: 82 type: RESP data: 0xff 0x1f 0x04
0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04
0f7f: 13.1b.dd grp: 4 type: CTRL data: 0xff 0x1f 0x04
0f87: 3c.48.88 grp: 47 type: RESP data: 0xff 0x1f 0x04
0f8f: 4a.ed.f8 grp: 1 type: RESP data: 0xff 0x1f 0x03
0f97: 4a.ed.f8 grp: 3 type: CTRL data: 0xff 0x1f 0x03
0f9f: 3c.48.88 grp: 44 type: RESP data: 0xff 0x1f 0x03
0fa7: 13.18.5d grp: 1 type: RESP data: 0xff 0x1f 0x06
0faf: 13.18.5d grp: 6 type: CTRL data: 0xff 0x1f 0x06
0fb7: 1e.47.59 grp: 45 type: RESP data: 0xff 0x1f 0x06
0fbf: 4a.e9.67 grp: 1 type: RESP data: 0xff 0x1f 0x05
0fc7: 4a.e9.67 grp: 5 type: CTRL data: 0xff 0x1f 0x05
0fcf: 3c.48.88 grp: 43 type: RESP data: 0xff 0x1f 0x05
0fd7: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06
0fdf: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05
0fe7: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04
0fef: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03
0ff7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01
0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01
Unused:
Last:
0f2f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
GroupMap
1 -> ['3c.48.88', '53.bf.6b', '52.bb.ce']
3 -> ['3c.48.88', '4a.ed.f8', '53.bf.6b']
4 -> ['3c.48.88', '13.1b.dd', '53.bf.6b']
5 -> ['3c.48.88', '4a.e9.67']
6 -> ['3c.48.88', '13.18.5d']
2 -> ['53.bf.6b']
2020-11-25 13:42:54 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "20.42.ac database download complete\nDeviceDb: (delta 11)\n 0f37: 53.bf.6b grp: 4 type: CTRL data: 0x03 0x00 0x04\n 0f3f: 53.bf.6b grp: 3 type: CTRL data: 0x03 0x00 0x03\n 0f47: 53.bf.6b grp: 2 type: CTRL data: 0x03 0x00 0x02\n 0f4f: 53.bf.6b grp: 1 type: RESP data: 0xff 0x00 0x01\n 0f57: 52.bb.ce grp: 1 type: CTRL data: 0x03 0x1c 0x01\n 0f5f: 53.bf.6b grp: 1 type: CTRL data: 0x03 0x00 0x01\n 0f67: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1c 0x01\n 0f6f: 3c.48.88 grp: 82 type: RESP data: 0xff 0x1f 0x04\n 0f77: 13.1b.dd grp: 1 type: RESP data: 0xff 0x1f 0x04\n 0f7f: 13.1b.dd grp: 4 type: CTRL data: 0xff 0x1f 0x04\n 0f87: 3c.48.88 grp: 47 type: RESP data: 0xff 0x1f 0x04\n 0f8f: 4a.ed.f8 grp: 1 type: RESP data: 0xff 0x1f 0x03\n 0f97: 4a.ed.f8 grp: 3 type: CTRL data: 0xff 0x1f 0x03\n 0f9f: 3c.48.88 grp: 44 type: RESP data: 0xff 0x1f 0x03\n 0fa7: 13.18.5d grp: 1 type: RESP data: 0xff 0x1f 0x06\n 0faf: 13.18.5d grp: 6 type: CTRL data: 0xff 0x1f 0x06\n 0fb7: 1e.47.59 grp: 45 type: RESP data: 0xff 0x1f 0x06\n 0fbf: 4a.e9.67 grp: 1 type: RESP data: 0xff 0x1f 0x05\n 0fc7: 4a.e9.67 grp: 5 type: CTRL data: 0xff 0x1f 0x05\n 0fcf: 3c.48.88 grp: 43 type: RESP data: 0xff 0x1f 0x05\n 0fd7: 3c.48.88 grp: 6 type: CTRL data: 0xff 0x1f 0x06\n 0fdf: 3c.48.88 grp: 5 type: CTRL data: 0xff 0x1f 0x05\n 0fe7: 3c.48.88 grp: 4 type: CTRL data: 0xff 0x1f 0x04\n 0fef: 3c.48.88 grp: 3 type: CTRL data: 0xff 0x1f 0x03\n 0ff7: 3c.48.88 grp: 1 type: CTRL data: 0xff 0x1f 0x01\n 0fff: 3c.48.88 grp: 0 type: RESP data: 0xff 0x1f 0x01\nUnused:\nLast:\n 0f2f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)\nGroupMap\n 1 -> ['3c.48.88', '53.bf.6b', '52.bb.ce']\n 3 -> ['3c.48.88', '4a.ed.f8', '53.bf.6b']\n 4 -> ['3c.48.88', '13.1b.dd', '53.bf.6b']\n 5 -> ['3c.48.88', '4a.e9.67']\n 6 -> ['3c.48.88', '13.18.5d']\n 2 -> ['53.bf.6b']\n"} qos=0 ret=False
2020-11-25 13:42:54 DEBUG CommandSeq: Running command 3 of 3
2020-11-25 13:42:54 DEBUG Protocol: Write handler finished
2020-11-25 13:42:54 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00
2020-11-25 13:42:54 DEBUG Protocol: Write bytes to modem: 02622042ac1f2e0001000000000000000000000000d1
2020-11-25 13:42:54 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:54 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:54 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2e 00 ack: True 01 00 00 00 00 00 00 00 00 00 00 00 00 d1
2020-11-25 13:42:54 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler
2020-11-25 13:42:54 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2e 00
2020-11-25 13:42:54 DEBUG Protocol: Setting next write time: 1606329775.258221
2020-11-25 13:42:54 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:54 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler
2020-11-25 13:42:54 INFO ExtendedCmdResponse: 20.42.ac device ACK response, waiting for ext payload
2020-11-25 13:42:55 INFO Protocol: Read 0x51: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2e 00
01 01 00 00 20 20 1c ff 3f 00 c0 00 00 00
2020-11-25 13:42:55 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:55 DEBUG Protocol: Passing msg to write handler: ExtendedCmdResponse handler
2020-11-25 13:42:55 DEBUG KeypadLinc: KeypadLinc 20.42.ac get button state: Ext: 20.42.ac->53.bf.6b Type.DIRECT ext cmd: 2e 00
01 01 00 00 20 20 1c ff 3f 00 c0 00 00 00
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 11
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 WARNING Device: Device 20.42.ac add db already exists for 53.bf.6b grp 1 RESP
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Device 20.42.ac add db already exists for 53.bf.6b grp 1 RESP"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:55 WARNING Modem: Modem add db already exists for 20.42.ac grp 1 CTRL
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Modem add db already exists for 20.42.ac grp 1 CTRL"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 3 of 11
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 WARNING Device: Device 20.42.ac add db already exists for 53.bf.6b grp 1 CTRL
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Device 20.42.ac add db already exists for 53.bf.6b grp 1 CTRL"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:55 WARNING Modem: Modem add db already exists for 20.42.ac grp 1 RESP
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Modem add db already exists for 20.42.ac grp 1 RESP"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 4 of 11
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 WARNING Device: Device 20.42.ac add db already exists for 53.bf.6b grp 2 CTRL
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Device 20.42.ac add db already exists for 53.bf.6b grp 2 CTRL"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:55 WARNING Modem: Modem add db already exists for 20.42.ac grp 2 RESP
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Modem add db already exists for 20.42.ac grp 2 RESP"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 5 of 11
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 WARNING Device: Device 20.42.ac add db already exists for 53.bf.6b grp 3 CTRL
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Device 20.42.ac add db already exists for 53.bf.6b grp 3 CTRL"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:55 WARNING Modem: Modem add db already exists for 20.42.ac grp 3 RESP
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Modem add db already exists for 20.42.ac grp 3 RESP"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 6 of 11
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 WARNING Device: Device 20.42.ac add db already exists for 53.bf.6b grp 4 CTRL
2020-11-25 13:42:55 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "MESSAGE", "data": "Device 20.42.ac add db already exists for 53.bf.6b grp 4 CTRL"} qos=0 ret=False
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:55 DEBUG Protocol: Write handler finished
2020-11-25 13:42:55 INFO Protocol: Write message to modem: OutAllLinkUpdate: 20.42.ac grp: 4 Cmd.ADD_RESPONDER
2020-11-25 13:42:55 DEBUG Protocol: Write bytes to modem: 026f41a2042042ac040000
2020-11-25 13:42:55 DEBUG Serial: Wrote 11 bytes to serial /dev/insteon
2020-11-25 13:42:55 DEBUG Mqtt: MQTT writing
2020-11-25 13:42:55 INFO Protocol: Read 0x6f: OutAllLinkUpdate: 20.42.ac grp: 4 Cmd.ADD_RESPONDER ack: True
2020-11-25 13:42:55 DEBUG Protocol: Passing msg to write handler: ModemDbModify handler
2020-11-25 13:42:55 INFO ModemDbModify: Adding modem db record for 20.42.ac type: RESP grp: 4 data: bytearray(b'\x04\x00\x00')
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 7 of 11
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 INFO Device: Device 20.42.ac adding db: 53.bf.6b grp 5 CTRL b'\x03\x00\x05'
2020-11-25 13:42:55 INFO Device: Device 20.42.ac appending new record at mem 0x0f2f
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:55 DEBUG MsgHistory: Average hops 0.1, using 1
2020-11-25 13:42:55 DEBUG Protocol: Write handler finished
2020-11-25 13:42:55 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 27 08 20 00 00 00 00 00 00 00 00
2020-11-25 13:42:55 DEBUG Protocol: Write bytes to modem: 02622042ac152f0000020f2708200000000000000071
2020-11-25 13:42:55 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:55 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 27 08 20 00 00 00 00 00 00 00 71
2020-11-25 13:42:55 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:55 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:55 DEBUG Protocol: Setting next write time: 1606329776.042050
2020-11-25 13:42:55 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:55 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:55 INFO DeviceDbModify: Updating entry: 0f27: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
2020-11-25 13:42:55 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:55 DEBUG MsgHistory: Average hops 0.1, using 1
2020-11-25 13:42:55 DEBUG Protocol: Write handler finished
2020-11-25 13:42:55 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 2f 08 e2 05 53 bf 6b 03 00 05 00
2020-11-25 13:42:55 DEBUG Protocol: Write bytes to modem: 02622042ac152f0000020f2f08e20553bf6b0300051d
2020-11-25 13:42:56 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:56 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 2f 08 e2 05 53 bf 6b 03 00 05 1d
2020-11-25 13:42:56 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:56 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:56 DEBUG Protocol: Setting next write time: 1606329776.456978
2020-11-25 13:42:56 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:56 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:56 INFO DeviceDbModify: Updating entry: 0f2f: 53.bf.6b grp: 5 type: CTRL data: 0x03 0x00 0x05
2020-11-25 13:42:56 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:56 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:56 DEBUG Protocol: Write handler finished
2020-11-25 13:42:56 INFO Protocol: Write message to modem: OutAllLinkUpdate: 20.42.ac grp: 5 Cmd.ADD_RESPONDER
2020-11-25 13:42:56 DEBUG Protocol: Write bytes to modem: 026f41a2052042ac050000
2020-11-25 13:42:56 DEBUG Serial: Wrote 11 bytes to serial /dev/insteon
2020-11-25 13:42:56 INFO Protocol: Read 0x6f: OutAllLinkUpdate: 20.42.ac grp: 5 Cmd.ADD_RESPONDER ack: True
2020-11-25 13:42:56 DEBUG Protocol: Passing msg to write handler: ModemDbModify handler
2020-11-25 13:42:56 INFO ModemDbModify: Adding modem db record for 20.42.ac type: RESP grp: 5 data: bytearray(b'\x05\x00\x00')
2020-11-25 13:42:56 DEBUG CommandSeq: Running command 8 of 11
2020-11-25 13:42:56 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:56 INFO Device: Device 20.42.ac adding db: 53.bf.6b grp 6 CTRL b'\x03\x00\x06'
2020-11-25 13:42:56 INFO Device: Device 20.42.ac appending new record at mem 0x0f27
2020-11-25 13:42:56 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:56 DEBUG MsgHistory: Average hops 0.1, using 1
2020-11-25 13:42:56 DEBUG Protocol: Write handler finished
2020-11-25 13:42:56 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 1f 08 20 00 00 00 00 00 00 00 00
2020-11-25 13:42:56 DEBUG Protocol: Write bytes to modem: 02622042ac152f0000020f1f08200000000000000079
2020-11-25 13:42:56 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:56 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 1f 08 20 00 00 00 00 00 00 00 79
2020-11-25 13:42:56 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:57 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:57 DEBUG Protocol: Setting next write time: 1606329777.159230
2020-11-25 13:42:57 DEBUG MsgHistory: Received 0 hops, total 1 for 11 entries
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:57 INFO DeviceDbModify: Updating entry: 0f1f: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:57 DEBUG MsgHistory: Average hops 0.0, using 0
2020-11-25 13:42:57 DEBUG Protocol: Write handler finished
2020-11-25 13:42:57 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 27 08 e2 06 53 bf 6b 03 00 06 00
2020-11-25 13:42:57 DEBUG Protocol: Write bytes to modem: 02622042ac102f0000020f2708e20653bf6b03000623
2020-11-25 13:42:57 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:57 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 27 08 e2 06 53 bf 6b 03 00 06 23
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:57 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:57 DEBUG Protocol: Setting next write time: 1606329777.391529
2020-11-25 13:42:57 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:57 INFO DeviceDbModify: Updating entry: 0f27: 53.bf.6b grp: 6 type: CTRL data: 0x03 0x00 0x06
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:57 DEBUG Protocol: Write handler finished
2020-11-25 13:42:57 INFO Protocol: Write message to modem: OutAllLinkUpdate: 20.42.ac grp: 6 Cmd.ADD_RESPONDER
2020-11-25 13:42:57 DEBUG Protocol: Write bytes to modem: 026f41a2062042ac060000
2020-11-25 13:42:57 DEBUG Serial: Wrote 11 bytes to serial /dev/insteon
2020-11-25 13:42:57 INFO Protocol: Read 0x6f: OutAllLinkUpdate: 20.42.ac grp: 6 Cmd.ADD_RESPONDER ack: True
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: ModemDbModify handler
2020-11-25 13:42:57 INFO ModemDbModify: Adding modem db record for 20.42.ac type: RESP grp: 6 data: bytearray(b'\x06\x00\x00')
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 9 of 11
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:57 INFO Device: Device 20.42.ac adding db: 53.bf.6b grp 7 CTRL b'\x03\x00\x07'
2020-11-25 13:42:57 INFO Device: Device 20.42.ac appending new record at mem 0x0f1f
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:57 DEBUG MsgHistory: Average hops 0.0, using 0
2020-11-25 13:42:57 DEBUG Protocol: Write handler finished
2020-11-25 13:42:57 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 17 08 20 00 00 00 00 00 00 00 00
2020-11-25 13:42:57 DEBUG Protocol: Write bytes to modem: 02622042ac102f0000020f1708200000000000000081
2020-11-25 13:42:57 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:57 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 17 08 20 00 00 00 00 00 00 00 81
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:57 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:57 DEBUG Protocol: Setting next write time: 1606329777.902384
2020-11-25 13:42:57 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:57 INFO DeviceDbModify: Updating entry: 0f17: 00.00.00 grp: 0 type: RESP data: 0x00 0x00 0x00 (UNUSED) (LAST)
2020-11-25 13:42:57 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:57 DEBUG MsgHistory: Average hops 0.0, using 0
2020-11-25 13:42:57 DEBUG Protocol: Write handler finished
2020-11-25 13:42:57 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 1f 08 e2 07 53 bf 6b 03 00 07 00
2020-11-25 13:42:57 DEBUG Protocol: Write bytes to modem: 02622042ac102f0000020f1f08e20753bf6b03000729
2020-11-25 13:42:57 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:57 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 1f 08 e2 07 53 bf 6b 03 00 07 29
2020-11-25 13:42:57 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:58 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_ACK cmd: 2f 00
2020-11-25 13:42:58 DEBUG Protocol: Setting next write time: 1606329778.141873
2020-11-25 13:42:58 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries
2020-11-25 13:42:58 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:58 INFO DeviceDbModify: Updating entry: 0f1f: 53.bf.6b grp: 7 type: CTRL data: 0x03 0x00 0x07
2020-11-25 13:42:58 DEBUG CommandSeq: Running command 2 of 2
2020-11-25 13:42:58 DEBUG CommandSeq: Running command 1 of 1
2020-11-25 13:42:58 DEBUG Protocol: Write handler finished
2020-11-25 13:42:58 INFO Protocol: Write message to modem: OutAllLinkUpdate: 20.42.ac grp: 7 Cmd.ADD_RESPONDER
2020-11-25 13:42:58 DEBUG Protocol: Write bytes to modem: 026f41a2072042ac070000
2020-11-25 13:42:58 DEBUG Serial: Wrote 11 bytes to serial /dev/insteon
2020-11-25 13:42:58 INFO Protocol: Read 0x6f: OutAllLinkUpdate: 20.42.ac grp: 7 Cmd.ADD_RESPONDER ack: True
2020-11-25 13:42:58 DEBUG Protocol: Passing msg to write handler: ModemDbModify handler
2020-11-25 13:42:58 INFO ModemDbModify: Adding modem db record for 20.42.ac type: RESP grp: 7 data: bytearray(b'\x07\x00\x00')
2020-11-25 13:42:58 DEBUG CommandSeq: Running command 10 of 11
2020-11-25 13:42:58 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:58 INFO Device: Device 20.42.ac adding db: 53.bf.6b grp 8 CTRL b'\x03\x00\x08'
2020-11-25 13:42:58 INFO Device: Device 20.42.ac appending new record at mem 0x0f17
2020-11-25 13:42:58 DEBUG CommandSeq: Running command 1 of 2
2020-11-25 13:42:58 DEBUG MsgHistory: Average hops 0.0, using 0
2020-11-25 13:42:58 DEBUG Protocol: Write handler finished
2020-11-25 13:42:58 INFO Protocol: Write message to modem: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 00 02 0f 0f 08 20 00 00 00 00 00 00 00 00
2020-11-25 13:42:58 DEBUG Protocol: Write bytes to modem: 02622042ac102f0000020f0f08200000000000000089
2020-11-25 13:42:58 DEBUG Serial: Wrote 22 bytes to serial /dev/insteon
2020-11-25 13:42:58 INFO Protocol: Read 0x62: Ext: 20.42.ac, Type.DIRECT ext, 2f 00 ack: True 00 02 0f 0f 08 20 00 00 00 00 00 00 00 89
2020-11-25 13:42:58 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:58 INFO Protocol: Read 0x50: Std: 20.42.ac->53.bf.6b Type.DIRECT_NAK cmd: 2f fc
2020-11-25 13:42:58 DEBUG Protocol: Setting next write time: 1606329778.652714
2020-11-25 13:42:58 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries
2020-11-25 13:42:58 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-11-25 13:42:58 ERROR DeviceDbModify: 20.42.ac db mod NAK: Pre NAK in case database search takes too long, Message: Std: 20.42.ac->53.bf.6b Type.DIRECT_NAK cmd: 2f fc
2020-11-25 13:42:58 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "ERROR", "data": "20.42.ac db mod NAK: Pre NAK in case database search takes too long, Message: Std: 20.42.ac->53.bf.6b Type.DIRECT_NAK cmd: 2f fc"} qos=0 ret=False
2020-11-25 13:42:58 ERROR Mqtt: Device database update failed. Pre NAK in case database search takes too long
2020-11-25 13:42:58 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "ERROR", "data": "Device database update failed. Pre NAK in case database search takes too long"} qos=0 ret=False
2020-11-25 13:42:58 DEBUG Mqtt: MQTT publish insteon/command/20.42.ac/session/806609784 {"type": "END", "data": null} qos=0 ret=False
2020-11-25 13:42:58 DEBUG Protocol: Write handler finished
2020-11-25 13:42:58 DEBUG Mqtt: MQTT writing
The text was updated successfully, but these errors were encountered: