Insteon Issue: Lost connection to Insteon Modem: True

I recently upgraded my venv to Python3.7
My ha version is 0.101.2
insteonplm-0.16.5
Insteon Hub 2245
Hub Version 1018

configuration.yaml

insteon:
  host:
  username:
  password:

All plm logs from fresh hass start

2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.78:25105/3?0260=I=3
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnLevel
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnLevel
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: ioLincSensor
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnLevel
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnLevel
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnLevel
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnLevel
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] We want to reconnect so we do...
2019-11-05 08:30:43 WARNING (MainThread) [insteonplm.plm] Lost connection to Insteon Modem: True
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] Reconnecting to transport
2019-11-05 08:30:43 INFO (MainThread) [insteonplm] Insteon Hub reader stopped
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] starting Connection.reconnect
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] starting Connection._connect
2019-11-05 08:30:43 INFO (MainThread) [insteonplm] Connecting to Insteon Hub on 192.168.1.78
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] Creating http connection
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] Starting the reader in HttpTrasnport __init__
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] create_http_connection Finished creating connection
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] Test connection status is 200
2019-11-05 08:30:43 DEBUG (MainThread) [insteonplm] Starting the buffer reader
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] ending Connection._connect
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] ending Connection.reconnect
2019-11-05 08:30:44 INFO (MainThread) [insteonplm] Insteon Hub reader started
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] ..................Clearing the buffer..............
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.78:25105/1?XB=M=1
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] Post status: 200
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] Calling connection made
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm] Protocol: <insteonplm.plm.Hub object at 0xffff5c43bac8>
2019-11-05 08:30:44 INFO (MainThread) [insteonplm.plm] Connection established to Hub
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Transport: <insteonplm.HttpTransport object at 0xffff1ecf8438>
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Loading saved device info.
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Really Loading saved device info.
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Saved device file loaded
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 187162
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 187e4a
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 1600cb
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 19e1ae
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 1923f2
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 1872ac
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 164858
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 164819
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 18807b
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.linkedDevices] Found saved device with address 18b4c3
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Found 10 saved devices
2019-11-05 08:30:44 INFO (MainThread) [insteonplm.plm] Requesting Insteon Modem Info
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, 'acknak': 0xNone}
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Starting: _load_all_link_database
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Starting: _get_first_all_link_record
2019-11-05 08:30:44 INFO (MainThread) [insteonplm.plm] Requesting ALL-Link Records
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x69, 'acknak': 0xNone}
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Ending: _get_first_all_link_record
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Ending: _load_all_link_database
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.plm] Ending _setup_devices in IM
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnOff
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: openClosedRelay
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: keypadButtonMain
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: onOffButtonA
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: onOffButtonB
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: onOffButtonC
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: onOffButtonD
2019-11-05 08:30:44 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnOff
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] No ACK or NAK message received.
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, 'acknak': 0xNone}
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.78:25105/3?0260=I=3
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] Post status: 200
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] Buffer from 0 to 18
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] New buffer: 0260391EC60333A406
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Received 9 bytes from PLM: b'0260391ec60333a406'
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'0260391ec60333a406'
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 1
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x60, 'address': 39.1E.C6, 'category': 0x03, 'subcategory': 0x33, 'firmware': 0xa4, 'acknak': 0x06}
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Starting _handle_get_plm_info
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Ending _handle_get_plm_info
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x69, 'acknak': 0xNone}
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.1.78:25105/3?0269=I=3
2019-11-05 08:30:45 DEBUG (MainThread) [insteonplm] Post status: 200
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm] Buffer from 0 to 26
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm] New buffer: 0269060257E200187162030E3B
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Starting: data_received
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Received 13 bytes from PLM: b'0269060257e200187162030e3b'
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'0269060257e200187162030e3b'
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'0257e200187162030e3b'
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Messages in queue: 2
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x69, 'acknak': 0x06}
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags': 0xe2, 'group': 0x00, 'address': 18.71.62, 'linkdata1': 0x03, 'linkdata2': 0x0e, 'linkdata3': 0x3b}
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Found all link record for device 187162
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Starting: _get_next_all_link_record
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x6a, 'acknak': 0xNone}
2019-11-05 08:30:46 DEBUG (MainThread) [insteonplm.plm] Ending: _get_next_all_link_record

I then try to turn on the dimmer @ 16.48.58
Nothing actually turns on. Below are the logs.
I can manually control the dimmer from the insteon app and insteonplm_interactive

2019-11-05 08:34:34 DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2019-11-05 08:34:34 DEBUG (MainThread) [insteonplm.devices] Ending Device._send_msg
2019-11-05 08:34:34 DEBUG (MainThread) [insteonplm.devices] Starting 16.48.58 Device._process_send_queue
2019-11-05 08:34:34 DEBUG (MainThread) [insteonplm.devices] Lock is locked from yield from
2019-11-05 08:34:34 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x62, 'address': 16.48.58, 'flags': 0x00, 'cmd1': 0x11, 'cmd2': 0xff, 'acknak': 0xNone}
2019-11-05 08:34:34 DEBUG (MainThread) [insteonplm.devices] Ending 16.48.58 Device._process_send_queue

I’ve recently been having the same issue. I’m losing connection to the modem all the time. I know insteon has been working on an update for their app. I wonder if anything changed in their API?

1 Like

I was thinking that too. But insteonplm_interactive does not suffer these issues, it just works. There is an issue if you specify a port in your hub configuration with insteonplm_interactive. I’ll open an issue on github for that.

https://github.com/nugget/python-insteonplm/issues/198

The issue is with
site-packages/insteonplm/tools.py
It’s wants the port as an int but it isn’t coming in that way.
As a quick hack I changed line 647

self.tools.port = port 

to

self.tools.port = int(port)

This isn’t a proper fix, there should be error checking to make sure a valid port was entered.

1 Like

Having issues also! Only works for a few minutes after reboot.
Does this hack fix the issue?

I don’t see how this would fix an issue with HA since tools.py is not used by HA at all. That is only used by the command line tools. I will have a look and see what I can find. The insteon_plm module did not change since about release 0.95.

2 Likes

Would be happy to help in any way to troubleshoot. Mine stops responding to commands after 20-30 minutes after reboot.

I did a long overdue upgrade to 0.103.0 (docker) and am also experiencing these insteon issues. It usually works for about 30 mins, then requires a reboot to pick things back up. Going to dig into the code a bit, but am also more than willing to help troubleshoot if someone is already looking at it.

I’m getting the following pair of errors in the logs…

Lost connection to Insteon Modem: True
7:07 PM __main__.py (WARNING)

Reconnect to Hub (TimeoutError)
7:07 PM __main__.py (ERROR)

Edit: other relevant data points…

  • hub model 2245-222
  • rev 3.3 - 5218
1 Like

There is a fix in the current 0.105 beta release if you can test it out.