poll.py RuntimeError: dictionary changed size during iteration

[j3kestrel]

tyson@watatic:/var/log$ sudo systemctl status insteon-mqtt
● insteon-mqtt.service - Insteon MQTT Bridge
   Loaded: loaded (/etc/systemd/system/insteon-mqtt.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Wed 2018-02-07 19:21:58 EST; 2h 47min ago
  Process: 512 ExecStart=/opt/insteon-mqtt/bin/insteon-mqtt config.yaml start (code=exited, status=1/FAILURE)
 Main PID: 512 (code=exited, status=1/FAILURE)

Feb 07 19:21:57 watatic insteon-mqtt[512]:   File "/opt/insteon-mqtt/lib/python3.5/site-packages/insteon_mqtt/cmd_line/main.py", line 266, in ma
Feb 07 19:21:57 watatic insteon-mqtt[512]:     return args.func(args, cfg)
Feb 07 19:21:57 watatic insteon-mqtt[512]:   File "/opt/insteon-mqtt/lib/python3.5/site-packages/insteon_mqtt/cmd_line/start.py", line 46, in st
Feb 07 19:21:57 watatic insteon-mqtt[512]:     loop.select()
Feb 07 19:21:57 watatic insteon-mqtt[512]:   File "/opt/insteon-mqtt/lib/python3.5/site-packages/insteon_mqtt/network/poll.py", line 225, in sel
Feb 07 19:21:57 watatic insteon-mqtt[512]:     for link in self.links.values():
Feb 07 19:21:57 watatic insteon-mqtt[512]: RuntimeError: dictionary changed size during iteration
Feb 07 19:21:58 watatic systemd[1]: insteon-mqtt.service: Main process exited, code=exited, status=1/FAILURE
Feb 07 19:21:58 watatic systemd[1]: insteon-mqtt.service: Unit entered failed state.
Feb 07 19:21:58 watatic systemd[1]: insteon-mqtt.service: Failed with result 'exit-code'.

insteon-mqtt log file:

2018-02-07 18:35:31 DEBUG Switch: Switch 15.64.a3 ACK: Std: 15.64.a3->49.f7.37 Type.DIRECT_ACK cmd: 13 00
2018-02-07 18:35:31 INFO Switch: Setting device 15.64.a3 (gr_stairs) on False
2018-02-07 18:35:31 INFO Switch: MQTT received active change 15.64.a3 (gr_stairs) = False
2018-02-07 18:35:31 DEBUG Mqtt: MQTT publish insteon/15.64.a3/state OFF qos=1 ret=1
2018-02-07 18:35:31 DEBUG Protocol: Write handler finished
2018-02-07 18:35:31 DEBUG Mqtt: MQTT writing
2018-02-07 18:35:51 INFO Protocol: Read 0x50: Std: 15.a4.68 Type.ALL_LINK_BROADCAST grp: 01 cmd: 13 00
2018-02-07 18:35:51 INFO Broadcast: Handling all link broadcast for 15.a4.68 'downstairs_middle'
2018-02-07 18:35:51 INFO Switch: Switch 15.a4.68 broadcast OFF grp: 1
2018-02-07 18:35:51 INFO Switch: Setting device 15.a4.68 (downstairs_middle) on False
2018-02-07 18:35:51 INFO Switch: MQTT received active change 15.a4.68 (downstairs_middle) = False
2018-02-07 18:35:51 DEBUG Mqtt: MQTT publish insteon/15.a4.68/state OFF qos=1 ret=1
2018-02-07 18:35:51 DEBUG Base: Found 4 responders in group 1
2018-02-07 18:35:51 DEBUG Base: Group 1 -> ['15.63.c5', '43.6b.a2', '49.f7.37', '15.64.a3']
2018-02-07 18:35:51 INFO Base: 15.a4.68 (downstairs_middle) broadcast to 15.63.c5 for group 1
2018-02-07 18:35:51 ERROR Dimmer: Dimmer 15.63.c5 has no group 1 entry from 15.a4.68
2018-02-07 18:35:51 WARNING Base: 15.a4.68 (downstairs_middle) broadcast - device 43.6b.a2 not found
2018-02-07 18:35:51 INFO Base: 15.a4.68 (downstairs_middle) broadcast to 49.f7.37 for group 1
2018-02-07 18:35:51 INFO Base: 15.a4.68 (downstairs_middle) broadcast to 15.64.a3 for group 1
2018-02-07 18:35:51 INFO Switch: Setting device 15.64.a3 (gr_stairs) on False
2018-02-07 18:35:51 INFO Switch: MQTT received active change 15.64.a3 (gr_stairs) = False
2018-02-07 18:35:51 DEBUG Mqtt: MQTT publish insteon/15.64.a3/state OFF qos=1 ret=1
2018-02-07 18:35:51 DEBUG Mqtt: MQTT writing
2018-02-07 18:35:54 INFO Protocol: Read 0x50: Std: 15.a4.68 Type.ALL_LINK_CLEANUP grp: 01 cmd: 13 01
2018-02-07 19:21:57 INFO Mqtt: MQTT disconnection 192.168.86.155 1883
2018-02-07 19:21:57 DEBUG poll: Link removed MQTT 192.168.86.155:1883
2018-02-07 19:21:57 INFO Mqtt: MQTT disconnection 192.168.86.155 1883

mosquito log file:

 1518040580: Saving in-memory database to /data/mosquitto.db.
1518042381: Saving in-memory database to /data/mosquitto.db.
1518044182: Saving in-memory database to /data/mosquitto.db.
1518045983: Saving in-memory database to /data/mosquitto.db.
1518047784: Saving in-memory database to /data/mosquitto.db.
1518049302: Client insteon-mqtt has exceeded timeout, disconnecting.
1518049302: Socket error on client insteon-mqtt, disconnecting.
1518049585: Saving in-memory database to /data/mosquitto.db.
1518051386: Saving in-memory database to /data/mosquitto.db.
1518053187: Saving in-memory database to /data/mosquitto.db.
1518054988: Saving in-memory database to /data/mosquitto.db.
1518056789: Saving in-memory database to /data/mosquitto.db.
1518058590: Saving in-memory database to /data/mosquitto.db.
1518059138: New connection from 192.168.86.69 on port 1883.
1518059138: New client connected from 192.168.86.69 as MQTT_FX_Client (c1, k60).

[TD22057]

The poll call in that traceback is required by the mqtt client code and I didn't allow for it to close the connection because I didn't that was possible. I have no idea why the MQTT poll would close the connection but clearly that can happen. Generally that's not a problem as the client immediately reconnects but in this case obvious it doesn't work. Should be a fairly easy fix - I'll try and push something out tomorrow. If you need an immediate work around, you can probably set the keep alive time to be longer on the MQTT broker side which might prevent this from happening.

[TD22057]

If you're OK grabbing the dev branch, please give this is a try. Otherwise, I'll run some more tests over the next day or so and release a bug fix update with the fix in it and you can try that.

[j3kestrel]

I will try to test the dev branch this weekend. Since I've only seen the problem once in about 2 or 3 weeks, it won't be conclusive that the problem is fixed, but I can at least test that it nominally still works.

[j3kestrel]

The dev branch is working for me. I don't know that it fixed the problem, but the diff set looks appropriate to the error message.

[TD22057]

I'm going to close this as I think it will work fine now. We can always re-open if it shows up again.