New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Insteon component stopped working with introduction of home assistant 0.77 #16342
Comments
I am also seeing the "File 'uvloop/cbhandles.pyx', line 64, in uvloop.loop.Handle._run" error using the Insteon component with an Insteon Hub (Hub2-V04-20140904). |
The error mentioned above does appear to be connected to the new Hub code for Insteon, however; it does not appear to be the reason why devices would not show up. I receive the same error but my system works as expected. My Hub is a Hub2-V04-20140904 as well. Can you place the following code in your
The inital startup process may take up to 10 minutes to find all of the devices. Auto discovery for this component first loads the modem's (Hub or PLM) All-Link database then it queries the device for the device information. This can take a while. |
For reference, I have 28 devices connected to my Hub. It takes almost exactly 1 min to read the ALDB then another 2 minutes to get the device info for each device. At that point, HA sees all of the devices. Subsequent startups see the devices right away because it uses cached device info. |
That last message came in over ten minutes ago, nothing since. Not sure if I should see more Insteon messages as it discovers or if that last HA log message means something else is hosed and it's not going to log further. Is there anything I should clear from the log (other than IP address) before posting? Edit: this is using hass.io on a Raspberry Pi 3B+ if that matters. |
If you want to be ultra secure, replace the Insteon address of the hub or any other device. Just FYI, how many devices do you have and what are they? |
I'm seeing some device discovery now but I seem to be unable to do anything with it. Am I correct in guessing that if I:
...that it should turn the light on? I have four dimmer wall switch devices and a few mini remote control keypads, though I'm just trying to get the wall switches to toggle/read. |
This is the section of the log that concerns me:
The first line is a request for the All-Link database. The last line says you have reached the end of the All-Link database. So no links were loaded. Are you sure you have linked your devices to the Hub? The wall switches should work easy if they are linked correctly. The mini-remote, because it is battery powered, may require a device override. But let's get the wall switches first. I would suggest you relink the devices. It won't hurt anything and will likely get them to show up right away. To do this in HA:
This has just set the Hub as a controller of the device. Now we need to set the Hub to be a responder to the device.
Note the change of the group from 0 to 1 and the order of the pressing of the set button and the call service button. |
That seems to have done the trick for me! My Insteon Hub was an RMA for a broken one so I wonder if somehow the replacement one never got properly linked (though the iOS app worked?). In any event, that's great, thank you so much! If you can point me at insight about linking the remotes that'd be good but this was my main concern. |
For the remotes repeat the two steps above for linking as a controller first then a responder but when linking as a responder do this for each button (i.e if you have an 8 button remote, link to groups 1 through 8). The remote does not show up in HA as an entity. The way it is designed to work is a trigger of automations. Have a look here and let me know if you have questions: |
Also, if for some reason this does not work, you may still need to add the device to the
All mini-remotes have a category (cat) of 0x00. The subcat is what tells you which one it is. Here is the list:
|
@brucek1642 Happy to see if this linking solution helps you too. If not let me know. |
I've done some more digging and it looks like my issue is that I have the pre-2014 hub. It is expecting the traffic to come over tcp to port 9761. And there is no username or password. It works fine with insteon-terminal setup this way. ie It accesses the raw plm port 9761 to do its job. I had a quick look through your code and it looks like it does not offer this third type of connection. I attached a copy of my init.py from insteon-terminal (renamed to a text file) Thanks |
Yup. I see what you mean. I will get a fix ready. How literate are you at downloading repos and installing them. This is not that hard of a fix I think and it just requires that the username and password be optional. If I can post a fix would you be able to install and test? |
BTW, did this work with the insteon_local component? |
I can't say that I have ever downloaded a repo outside of the ones that automatically come with home assistant, but I am sure I can work through it. I would be more that happy to install and test the code. Yes this did work with insteon_local component but .... it was not very reliable. It polled the hub every 30 seconds or so and if there was too much traffic it confused the hub. Then a power cycle was required for the hub to bring it back to life. I was using curl commands to use the x-10 feature via port 25105. There were two strings sent to the X-10. The first was to select the x-10 device, a pause then the second string to tell it to turn on or off. Too many of these and it overflowed the buffer ( i assume ) From what have been able to try out port 25105 works but is not very reliable due to the polling aspect. Using port 9761 is preferred since uses direct access to the internal plm |
Since you are using hass.io I am not sure it is possible to load from a custom repo. We can try though. Working on the fix now. Should be done today. But I cannot test so it is a bit of a shot in the dark. One thing you could do for me is confirm the size of the buffer. Can you send the output of the following command inside a browser: |
Looking at this further, |
Hmm didn't work, so I went looking and ended up find this link ( which had some useful links at the bottom) https://openremote.github.io/archive-dotorg/forums/attachments/22882151/23036475.pdf 172.16.0.135:25105/buffstatus.xml did work and got back | 02622E64860F19000602502E64862CB16D2F0000000000000000000000000000000000000000000000000000000000000000 I also found the attached developers guide who's file name matches my insteon hub model 2242-222 which maybe helpful is says the The INSTEON buffer can be read from “/buffstatus.xml” and can hold up to 100 characters or 50 |
That's what I was afraid of. The reason you were seeing poor performance from This is more than a quick fix. I need to make changes to the underlying library and without the device that will be tough. But I did figure out how to get the code to you for testing. I just have to package it up as a custom component. |
Here is a first attempt at a fix. Drop this into your config directory and set the configuration.yaml as follows:
|
I upgrade from 0.76.2 to 0.77.3 first.
On main screen get "invalid config: insteon_custom
In the log file get
2018-09-04 12:29:57 INFO (MainThread) [homeassistant.loader] Loaded
insteon_custom from custom_components.insteon_custom 2018-09-04 12:29:57
WARNING (MainThread) [homeassistant.loader] You are using a custom
component for insteon_custom which has not been tested by Home Assistant.
This component might cause stability problems, be sure to disable it if you
do experience issues with Home Assistant. 2018-09-04 12:29:57 INFO
(MainThread) [homeassistant.setup] Setting up insteon_custom 2018-09-04
12:29:57 ERROR (MainThread) [homeassistant.setup] Error during setup of
component insteon_custom Traceback (most recent call last): File
"/usr/local/lib/python3.6/site-packages/homeassistant/setup.py", line 145,
in _async_setup_component hass, processed_config) File
"/config/custom_components/insteon_custom/__init__.py", line 134, in
async_setup ipdb = IPDB() File
"/config/custom_components/insteon_custom/__init__.py", line 350, in
__init__ from insteonplm.states.cover import Cover ModuleNotFoundError: No
module named 'insteonplm.states.cover' 2018-09-04 12:29:57 INFO
(MainThread) [homeassistant.components.sensor] Setting up sensor.rest
2018-09-04 12:29:57 INFO (MainThread) [homeassistant.core] Bus:Handling
<Event state_changed[L]: entity_id=sun.sun, old_state=None,
new_state=<state sun.sun=above_horizon;
next_dawn=2018-09-05T10:18:05+00:00, next_dusk=2018-09-05T00:20:05+00:00,
next_midnight=2018-09-05T05:17:56+00:00,
next_noon=2018-09-04T17:18:30+00:00, next_rising=2018-09-05T10:47:15+00:00,
next_setting=2018-09-04T23:50:52+00:00, elevation=51.93, azimuth=160.38,
friendly_name=Sun @ 2018-09-04T12:29:57.733468-04:00>> 2018-09-04 12:29:57
INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]:
domain=persistent_notification, service=create, service_data=title=Invalid
config, message=The following components and platforms could not be set up:
- [insteon-custom](https://home-assistant.io/components/insteon_custom/)
Please check your config., notification_id=invalid_config> 2018-09-04
12:29:57 INFO (MainThread) [homeassistant.setup] Setting up cast 2018-09-04
12:29:57 INFO (MainThread) [homeassistant.setup] Setup of domain cast took
0.0 seconds. 2018-09-04 12:29:57 INFO (MainThread) [homeassistant.core]
Bus:Handling <Event component_loaded[L]: component=cast> 2018-09-04
12:29:57 INFO (MainThread) [homeassistant.core] Bus:Handling <Event
state_changed[L]: entity_id=persistent_notification.invalid_config,
old_state=None, new_state=<state
persistent_notification.invalid_config=notifying; title=Invalid config,
message=The following components and platforms could not be set up: -
[insteon-custom](https://home-assistant.io/components/insteon_custom/)
Please check your config. @ 2018-09-04T12:29:57.777523-04:00>>
…On Mon, Sep 3, 2018 at 9:19 PM Tom Harris ***@***.***> wrote:
Here is a first attempt at a fix. Drop this into your config directory and
set the configuration.yaml as follows:
insteon_custom:
host: <your ip address>
custom_components.zip
<https://github.com/home-assistant/home-assistant/files/2346824/custom_components.zip>
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#16342 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/Ao5RIQQY1-95ZteWdVwtGEs4Hhhl8WLXks5uXdUsgaJpZM4WWBJM>
.
|
I forgot to say the configuration validation tool comes back with
configuration valid!
…On Mon, Sep 3, 2018 at 9:19 PM Tom Harris ***@***.***> wrote:
Here is a first attempt at a fix. Drop this into your config directory and
set the configuration.yaml as follows:
insteon_custom:
host: <your ip address>
custom_components.zip
<https://github.com/home-assistant/home-assistant/files/2346824/custom_components.zip>
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#16342 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/Ao5RIQQY1-95ZteWdVwtGEs4Hhhl8WLXks5uXdUsgaJpZM4WWBJM>
.
|
OK, I gave you a file that is for a newer version than what you have. Sorry. That one is for 0.78 not 0.77. Let me fix that quickly. Also, please use the following in your configuration.yaml:
|
Sorry still no go
2018-09-04 20:17:43 WARNING (Recorder) [homeassistant.components.recorder]
Ended unfinished session (id=78 from 2018-09-04 16:29:41.728464) 2018-09-04
20:17:44 WARNING (MainThread) [homeassistant.components.http]
legacy_api_password support has been enabled. If you don't require it,
remove the 'api_password' from your http config. 2018-09-04 20:17:55
WARNING (MainThread) [homeassistant.loader] You are using a custom
component for insteon_custom which has not been tested by Home Assistant.
This component might cause stability problems, be sure to disable it if you
do experience issues with Home Assistant. 2018-09-04 20:17:55 INFO
(MainThread) [custom_components.insteon_custom] Connecting to Insteon Hub
on 172.16.0.135 2018-09-04 20:17:55 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting Connection.create
2018-09-04 20:17:55 DEBUG (MainThread) [insteonplm.devices] Registering
messages for 00.00.00 2018-09-04 20:17:55 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 00.00.00, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-04 20:17:55 DEBUG
(MainThread) [custom_components.insteon_custom.insteonplm] starting
Connection.reconnect 2018-09-04 20:17:55 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 20:17:55 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761 2018-09-04 20:17:55 ERROR (MainThread)
[homeassistant.setup] Error during setup of component insteon_custom
Traceback (most recent call last): File
"/usr/local/lib/python3.6/site-packages/homeassistant/setup.py", line 145,
in _async_setup_component hass, processed_config) File
"/config/custom_components/insteon_custom/__init__.py", line 280, in
async_setup workdir=hass.config.config_dir) File
"/config/custom_components/insteon_custom/insteonplm/__init__.py", line
164, in create yield from conn.reconnect() File
"/config/custom_components/insteon_custom/insteonplm/__init__.py", line
188, in reconnect yield from self._connect() File
"/config/custom_components/insteon_custom/insteonplm/__init__.py", line
242, in _connect connected = yield from self._connect_serial() File
"/config/custom_components/insteon_custom/insteonplm/__init__.py", line
279, in _connect_serial ser, baudrate=19200) File
"/usr/local/lib/python3.6/asyncio/coroutines.py", line 212, in coro res =
func(*args, **kw) File
"/usr/local/lib/python3.6/site-packages/serial/aio.py", line 358, in
create_serial_connection ser = serial.serial_for_url(*args, **kwargs) File
"/usr/local/lib/python3.6/site-packages/serial/__init__.py", line 86, in
serial_for_url instance.port = url File
"/usr/local/lib/python3.6/site-packages/serial/serialutil.py", line 206, in
port raise ValueError('"port" must be None or a string, not
{}'.format(type(port))) ValueError: "port" must be None or a string, not
<class 'serial.urlhandler.protocol_socket.Serial'> 2018-09-04 20:18:06
WARNING (MainThread) [homeassistant.setup] Setup of config is taking over
10 seconds. 2018-09-04 20:18:17 ERROR (Recorder)
[homeassistant.components.recorder.util] Error executing query:
(sqlite3.DatabaseError) database disk image is malformed [SQL: 'INSERT INTO
events (event_type, event_data, origin, time_fired, created, context_id,
context_user_id) VALUES (?, ?, ?, ?, ?, ?, ?)'] [parameters:
('service_registered', '{"domain": "recorder", "service": "purge"}',
'LOCAL', '2018-09-05 00:17:39.730209', '2018-09-05 00:18:17.977886',
'892db120a75b47efa5fc0210c17bda6d', None)] (Background on this error at:
http://sqlalche.me/e/4xp6) 2018-09-04 20:19:09 ERROR (MainThread)
[homeassistant.core] Timer got out of sync. Resetting
…On Tue, Sep 4, 2018 at 4:25 PM Tom Harris ***@***.***> wrote:
OK, I gave you a file that is for a newer version than what you have.
Sorry. That one is for 0.78 not 0.77. Let me fix that quickly. Also, please
use the following in your configuration.yaml:
insteon_custom:
host: 192.168.1.136
ip_port: 9761
hub_version: 1
logger:
default: warn
logs:
insteonplm: debug
custom_components.insteon_custom: debug
custom_components.zip
<https://github.com/home-assistant/home-assistant/files/2350114/custom_components.zip>
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#16342 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/Ao5RIdLRMyg7s23B3Hh8pwhumT0giQUqks5uXuG0gaJpZM4WWBJM>
.
|
This is actually encouraging. This message: |
Updated file. Feel pretty good about this one based on debugging. |
Sorry looks like there still is an issue. This one really slows down the
boot time. Once booted I can connect via ssh, samba and the configurator,
but not the main login.
2018-09-05 09:04:09 WARNING (Recorder) [homeassistant.components.recorder]
Ended unfinished session (id=81 from 2018-09-05 03:24:36.800296)
2018-09-05 09:04:10 WARNING (MainThread) [homeassistant.components.http]
legacy_api_password support has been enabled. If you don't require it,
remove the 'api_password' from your http config.
2018-09-05 09:04:21 WARNING (MainThread) [homeassistant.loader] You are
using a custom component for insteon_custom which has not been tested by
Home Assistant. This component might cause stability problems, be sure to
disable it if you do experience issues with Home Assistant.
2018-09-05 09:04:21 INFO (MainThread) [custom_components.insteon_custom]
Connecting to Insteon Hub on 172.16.0.135
2018-09-05 09:04:21 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting Connection.create
2018-09-05 09:04:21 DEBUG (MainThread) [insteonplm.devices] Registering
messages for 00.00.00
2018-09-05 09:04:21 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 00.00.00, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06}
2018-09-05 09:04:21 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection.reconnect
2018-09-05 09:04:21 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:04:21 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:04:26 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:04:26 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:04:26 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in 1
seconds: 172.16.0.135
2018-09-05 09:04:28 WARNING (MainThread) [homeassistant.setup] Setup of
group is taking over 10 seconds.
2018-09-05 09:04:28 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:04:29 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:04:29 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:04:34 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:04:34 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:04:34 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:04:34 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in 2
seconds: 172.16.0.135
2018-09-05 09:04:34 WARNING (MainThread) [homeassistant.setup] Setup of
insteon_custom is taking over 10 seconds.
2018-09-05 09:04:36 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:04:36 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:04:36 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:04:42 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:04:42 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:04:42 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:04:42 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in 3
seconds: 172.16.0.135
2018-09-05 09:04:42 WARNING (MainThread) [homeassistant.setup] Setup of
config is taking over 10 seconds.
2018-09-05 09:04:45 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:04:45 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:04:45 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:04:50 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:04:50 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:04:50 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:04:50 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in 5
seconds: 172.16.0.135
2018-09-05 09:04:55 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:04:55 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:04:55 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:05:01 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:05:01 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:05:01 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:05:01 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in 7
seconds: 172.16.0.135
2018-09-05 09:05:08 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:05:08 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:05:08 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:05:14 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:05:14 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:05:14 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:05:14 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
11 seconds: 172.16.0.135
2018-09-05 09:05:25 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:05:25 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:05:25 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:05:30 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:05:30 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:05:30 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:05:30 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
17 seconds: 172.16.0.135
2018-09-05 09:05:47 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:05:47 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:05:47 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:05:53 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:05:53 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:05:53 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:05:53 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
25 seconds: 172.16.0.135
2018-09-05 09:06:18 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:06:18 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:06:18 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:06:24 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:06:24 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:06:24 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:06:24 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
38 seconds: 172.16.0.135
2018-09-05 09:07:02 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:07:02 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:07:02 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:07:08 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:07:08 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:07:08 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:07:08 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
57 seconds: 172.16.0.135
2018-09-05 09:08:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:08:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:08:05 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:08:11 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:08:11 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:08:11 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:08:11 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
86 seconds: 172.16.0.135
2018-09-05 09:09:37 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:09:37 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:09:37 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:09:43 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:09:43 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:09:43 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:09:43 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
129 seconds: 172.16.0.135
2018-09-05 09:11:52 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:11:52 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:11:52 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:11:58 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:11:58 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:11:58 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:11:58 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
194 seconds: 172.16.0.135
2018-09-05 09:15:12 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:15:12 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:15:12 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:15:18 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:15:18 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:15:18 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:15:18 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
291 seconds: 172.16.0.135
2018-09-05 09:20:10 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-05 09:20:10 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 09:20:10 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761
2018-09-05 09:20:15 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 09:20:15 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending
Connection._retry_connection
2018-09-05 09:20:15 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting
Connection._retry_connection
2018-09-05 09:20:15 WARNING (MainThread)
[custom_components.insteon_custom.insteonplm] Connection failed, retry in
300 seconds: 172.16.0.135
…On Tue, Sep 4, 2018 at 10:06 PM Tom Harris ***@***.***> wrote:
Updated file. Feel pretty good about this one based on debugging.
custom_components.zip
<https://github.com/home-assistant/home-assistant/files/2350915/custom_components.zip>
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#16342 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/Ao5RIfcvkWYYl8X5iyQxm2-DqG5mWvf3ks5uXzG6gaJpZM4WWBJM>
.
|
Thanks for the patients. Can you try this one? |
Will do later today when I get back home. No problem with the patience, for
me that's part of being Canadian. We spend all our time apologizing. Lol
I appreciate all your help
…On Wed, Sep 5, 2018, 1:30 PM pyinsteon ***@***.***> wrote:
Thanks for the patients. Can you try this one?
custom_components.zip
<https://github.com/home-assistant/home-assistant/files/2353907/custom_components.zip>
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#16342 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/Ao5RIcPv59AQI7KNr7fl6G-PqZZKmwIwks5uYApPgaJpZM4WWBJM>
.
|
Another update. |
Woo hoo
Things are looking pretty good. The startup appears to have found all 4
devices devices plus the hub. Picked one ( 2E.63.C8) and turned it on then
off. All went well.
2018-09-05 17:58:54 WARNING (Recorder) [homeassistant.components.recorder]
Ended unfinished session (id=82 from 2018-09-05 13:04:06.387289)
2018-09-05 17:58:55 WARNING (MainThread) [homeassistant.components.http]
legacy_api_password support has been enabled. If you don't require it,
remove the 'api_password' from your http config. 2018-09-05 17:59:05
WARNING (MainThread) [homeassistant.loader] You are using a custom
component for insteon_custom which has not been tested by Home Assistant.
This component might cause stability problems, be sure to disable it if you
do experience issues with Home Assistant. 2018-09-05 17:59:05 INFO
(MainThread) [custom_components.insteon_custom] Connecting to Insteon Hub
on 172.16.0.135 2018-09-05 17:59:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Starting Connection.create
2018-09-05 17:59:05 DEBUG (MainThread) [insteonplm.devices] Registering
messages for 00.00.00 2018-09-05 17:59:05 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 00.00.00, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:05 DEBUG
(MainThread) [custom_components.insteon_custom.insteonplm] starting
Connection.reconnect 2018-09-05 17:59:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-05 17:59:05 INFO (MainThread)
[custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1
on socket://172.16.0.135:9761 2018-09-05 17:59:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-05 17:59:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] ending Connection.reconnect
2018-09-05 17:59:05 DEBUG (MainThread)
[custom_components.insteon_custom.insteonplm] Ending Connection.create
2018-09-05 17:59:05 DEBUG (MainThread) [insteonplm.linkedDevices] Added new
callback <function async_setup.<locals>.async_new_insteon_device at
0x73523f60> 2018-09-05 17:59:06 INFO (MainThread) [insteonplm.plm]
Connection established to PLM 2018-09-05 17:59:07 DEBUG (MainThread)
[insteonplm.plm] Starting Insteon Modem write message from send queue
2018-09-05 17:59:07 DEBUG (MainThread) [insteonplm.plm] Aquiring write lock
2018-09-05 17:59:07 DEBUG (MainThread) [insteonplm.linkedDevices] Loading
saved device info. 2018-09-05 17:59:07 DEBUG (MainThread)
[insteonplm.linkedDevices] Really Loading saved device info. 2018-09-05
17:59:07 DEBUG (MainThread) [insteonplm.linkedDevices] Saved device file
not found 2018-09-05 17:59:07 DEBUG (MainThread) [insteonplm.plm] Found 0
saved devices 2018-09-05 17:59:07 INFO (MainThread) [insteonplm.plm]
Requesting Insteon Modem Info 2018-09-05 17:59:07 DEBUG (MainThread)
[insteonplm.plm] Queueing msg: {'code': 0x60, 'address': 00.00.00,
'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, 'acknak':
0xNone} 2018-09-05 17:59:07 DEBUG (MainThread) [insteonplm.plm] Starting:
_load_all_link_database 2018-09-05 17:59:07 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_first_all_link_record 2018-09-05 17:59:07
INFO (MainThread) [insteonplm.plm] Requesting ALL-Link Records 2018-09-05
17:59:07 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x69,
'acknak': 0xNone} 2018-09-05 17:59:07 DEBUG (MainThread) [insteonplm.plm]
Ending: _get_first_all_link_record 2018-09-05 17:59:07 DEBUG (MainThread)
[insteonplm.plm] Ending: _load_all_link_database 2018-09-05 17:59:07 DEBUG
(MainThread) [insteonplm.plm] Ending _setup_devices in IM 2018-09-05
17:59:07 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address':
00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone,
'acknak': 0xNone} 2018-09-05 17:59:07 DEBUG (MainThread) [insteonplm.plm]
Waiting for ACK or NAK message 2018-09-05 17:59:08 DEBUG (MainThread)
[insteonplm.plm] Starting: data_received 2018-09-05 17:59:08 DEBUG
(MainThread) [insteonplm.plm] Received 9 bytes from PLM:
b'02602cb16d03379d06' 2018-09-05 17:59:08 DEBUG (MainThread)
[insteonplm.plm] Finishing: data_received 2018-09-05 17:59:09 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'02602cb16d03379d06'
2018-09-05 17:59:09 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:09 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 1 2018-09-05 17:59:09 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x60, 'address': 2C.B1.6D, 'category': 0x03,
'subcategory': 0x37, 'firmware': 0x9d, 'acknak': 0x06} 2018-09-05 17:59:09
DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2018-09-05 17:59:09 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2018-09-05 17:59:09 DEBUG (MainThread) [insteonplm.plm] Starting
_handle_get_plm_info 2018-09-05 17:59:09 DEBUG (MainThread)
[insteonplm.plm] Ending _handle_get_plm_info 2018-09-05 17:59:09 DEBUG
(SyncWorker_6) [custom_components.insteon_custom] Insteon Services
registered 2018-09-05 17:59:09 DEBUG (MainThread) [insteonplm.plm] TX:
{'code': 0x69, 'acknak': 0xNone} 2018-09-05 17:59:09 DEBUG (MainThread)
[insteonplm.plm] Waiting for ACK or NAK message 2018-09-05 17:59:10 DEBUG
(MainThread) [insteonplm.plm] Starting: data_received 2018-09-05 17:59:10
DEBUG (MainThread) [insteonplm.plm] Received 13 bytes from PLM:
b'0269060257e2001fb59b010000' 2018-09-05 17:59:10 DEBUG (MainThread)
[insteonplm.plm] Finishing: data_received 2018-09-05 17:59:10 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0269060257e2001fb59b010000'
2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'0257e2001fb59b010000' 2018-09-05 17:59:10 DEBUG (MainThread)
[insteonplm.plm] Buffer too short to have a message 2018-09-05 17:59:10
DEBUG (MainThread) [insteonplm.plm] Messages in queue: 2 2018-09-05
17:59:10 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x69, 'acknak':
0x06} 2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm] RX: {'code':
0x57, 'controlFlags': 0xe2, 'group': 0x00, 'address': 1F.B5.9B,
'linkdata1': 0x01, 'linkdata2': 0x00, 'linkdata3': 0x00} 2018-09-05
17:59:10 DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue
reached. 2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm] ACK or NAK
received 2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm] Found all
link record for device 1fb59b 2018-09-05 17:59:10 DEBUG (MainThread)
[insteonplm.plm] ALDB Data: address 1fb59b data1: 01 data1: 00 data3: 00
2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.devices] Registering
messages for 1F.B5.9B 2018-09-05 17:59:10 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 1F.B5.9B, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:10 DEBUG
(MainThread) [insteonplm.states] Registering callbacks for DimmableSwitch
device 1F.B5.9B 2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm]
Found new device 1fb59b 2018-09-05 17:59:10 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 1F.B5.9B 2018-09-05 17:59:10
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm] Starting:
_get_next_all_link_record 2018-09-05 17:59:10 DEBUG (MainThread)
[insteonplm.plm] Requesting Next All-Link Record 2018-09-05 17:59:10 DEBUG
(MainThread) [insteonplm.plm] Queueing msg: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:10 DEBUG (MainThread) [insteonplm.plm] Ending:
_get_next_all_link_record 2018-09-05 17:59:11 DEBUG (MainThread)
[insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:11
DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] Starting:
data_received 2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm]
Received 13 bytes from PLM: b'026a060257a2011fb59b000000' 2018-09-05
17:59:12 DEBUG (MainThread) [insteonplm.plm] Finishing: data_received
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'026a060257a2011fb59b000000' 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.plm] Total buffer: b'0257a2011fb59b000000' 2018-09-05 17:59:12
DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] Messages in queue:
2 2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] RX: {'code':
0x6a, 'acknak': 0x06} 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x57, 'controlFlags': 0xa2, 'group': 0x01,
'address': 1F.B5.9B, 'linkdata1': 0x00, 'linkdata2': 0x00, 'linkdata3':
0x00} 2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.devices] Starting
Device.receive_message 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.devices] Ending Device.receive_message 2018-09-05 17:59:12
DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] Found all link
record for device 1fb59b 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.plm] ALDB Data: address 1fb59b data1: 00 data1: 00 data3: 00
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.devices] Registering
messages for 1F.B5.9B 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 1F.B5.9B, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:12 DEBUG
(MainThread) [insteonplm.plm] Found new device 1fb59b 2018-09-05 17:59:12
DEBUG (MainThread) [insteonplm.devices] Registering messages for 1F.B5.9B
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:12
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:12 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:12
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:12 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:13 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e2002e6486010000'
2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e2002e6486010000' 2018-09-05 17:59:13 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e2002e6486010000'
2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:13 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:13
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x00, 'address': 2E.64.86, 'linkdata1': 0x01, 'linkdata2':
0x00, 'linkdata3': 0x00} 2018-09-05 17:59:13 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:13
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:13
DEBUG (MainThread) [insteonplm.plm] Found all link record for device 2e6486
2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address
2e6486 data1: 01 data1: 00 data3: 00 2018-09-05 17:59:13 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 2E.64.86 2018-09-05 17:59:13
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
2E.64.86, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:13 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 2E.64.86 2018-09-05 17:59:14 DEBUG
(MainThread) [insteonplm.plm] Found new device 2e6486 2018-09-05 17:59:14
DEBUG (MainThread) [insteonplm.devices] Registering messages for 2E.64.86
2018-09-05 17:59:14 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 2E.64.86, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:14 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:14
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:14 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:14 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:14
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:14 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257a2012e6486000000'
2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257a2012e6486000000' 2018-09-05 17:59:15 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257a2012e6486000000'
2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:15
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xa2, 'group': 0x01, 'address': 2E.64.86, 'linkdata1': 0x00, 'linkdata2':
0x00, 'linkdata3': 0x00} 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.devices] Starting Device.receive_message 2018-09-05 17:59:15
DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm] Last item in
self._recv_queue reached. 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.plm] ACK or NAK received 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.plm] Found all link record for device 2e6486 2018-09-05
17:59:15 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address 2e6486
data1: 00 data1: 00 data3: 00 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 2E.64.86 2018-09-05 17:59:15
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
2E.64.86, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm] Found new device
2e6486 2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.devices]
Registering messages for 2E.64.86 2018-09-05 17:59:15 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 2E.64.86, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:15 DEBUG
(MainThread) [insteonplm.plm] Starting: _get_next_all_link_record
2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm] Requesting Next
All-Link Record 2018-09-05 17:59:15 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:15 DEBUG
(MainThread) [insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05
17:59:16 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:16 DEBUG (MainThread) [insteonplm.plm] Waiting for
ACK or NAK message 2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e2002e63c8010000'
2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e2002e63c8010000' 2018-09-05 17:59:17 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e2002e63c8010000'
2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:17
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x00, 'address': 2E.63.C8, 'linkdata1': 0x01, 'linkdata2':
0x00, 'linkdata3': 0x00} 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:17
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:17
DEBUG (MainThread) [insteonplm.plm] Found all link record for device 2e63c8
2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address
2e63c8 data1: 01 data1: 00 data3: 00 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 2E.63.C8 2018-09-05 17:59:17
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
2E.63.C8, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 2E.63.C8 2018-09-05 17:59:17 DEBUG
(MainThread) [insteonplm.plm] Found new device 2e63c8 2018-09-05 17:59:17
DEBUG (MainThread) [insteonplm.devices] Registering messages for 2E.63.C8
2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 2E.63.C8, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:17
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:17
WARNING (MainThread) [homeassistant.setup] Setup of config is taking over
10 seconds. 2018-09-05 17:59:17 DEBUG (MainThread) [insteonplm.plm] TX:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:17 DEBUG (MainThread)
[insteonplm.plm] Waiting for ACK or NAK message 2018-09-05 17:59:18 DEBUG
(MainThread) [insteonplm.plm] Starting: data_received 2018-09-05 17:59:18
DEBUG (MainThread) [insteonplm.plm] Received 13 bytes from PLM:
b'026a060257a2012e63c8000000' 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.plm] Finishing: data_received 2018-09-05 17:59:18 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'026a060257a2012e63c8000000'
2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'0257a2012e63c8000000' 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.plm] Buffer too short to have a message 2018-09-05 17:59:18
DEBUG (MainThread) [insteonplm.plm] Messages in queue: 2 2018-09-05
17:59:18 DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x6a, 'acknak':
0x06} 2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.plm] RX: {'code':
0x57, 'controlFlags': 0xa2, 'group': 0x01, 'address': 2E.63.C8,
'linkdata1': 0x00, 'linkdata2': 0x00, 'linkdata3': 0x00} 2018-09-05
17:59:18 DEBUG (MainThread) [insteonplm.devices] Starting
Device.receive_message 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.devices] Ending Device.receive_message 2018-09-05 17:59:18
DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.plm] Found all link
record for device 2e63c8 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.plm] ALDB Data: address 2e63c8 data1: 00 data1: 00 data3: 00
2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.devices] Registering
messages for 2E.63.C8 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 2E.63.C8, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:18 DEBUG
(MainThread) [insteonplm.plm] Found new device 2e63c8 2018-09-05 17:59:18
DEBUG (MainThread) [insteonplm.devices] Registering messages for 2E.63.C8
2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 2E.63.C8, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:18
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:18 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:18 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:19
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:19 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e20a1fb59b022a42'
2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e20a1fb59b022a42' 2018-09-05 17:59:20 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e20a1fb59b022a42'
2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:20
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x0a, 'address': 1F.B5.9B, 'linkdata1': 0x02, 'linkdata2':
0x2a, 'linkdata3': 0x42} 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.devices] Starting Device.receive_message 2018-09-05 17:59:20
DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm] Last item in
self._recv_queue reached. 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.plm] ACK or NAK received 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.plm] Found all link record for device 1fb59b 2018-09-05
17:59:20 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address 1fb59b
data1: 02 data1: 2a data3: 42 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 1F.B5.9B 2018-09-05 17:59:20
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm] Found new device
1fb59b 2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.devices]
Registering messages for 1F.B5.9B 2018-09-05 17:59:20 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 1F.B5.9B, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:20 DEBUG
(MainThread) [insteonplm.plm] Starting: _get_next_all_link_record
2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm] Requesting Next
All-Link Record 2018-09-05 17:59:20 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:20 DEBUG
(MainThread) [insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05
17:59:21 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:21 DEBUG (MainThread) [insteonplm.plm] Waiting for
ACK or NAK message 2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e2012e6486010e43'
2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e2012e6486010e43' 2018-09-05 17:59:22 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e2012e6486010e43'
2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:22
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x01, 'address': 2E.64.86, 'linkdata1': 0x01, 'linkdata2':
0x0e, 'linkdata3': 0x43} 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.devices] Starting Device.receive_message 2018-09-05 17:59:22
DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm] Last item in
self._recv_queue reached. 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.plm] ACK or NAK received 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.plm] Found all link record for device 2e6486 2018-09-05
17:59:22 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address 2e6486
data1: 01 data1: 0e data3: 43 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 2E.64.86 2018-09-05 17:59:22
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
2E.64.86, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 2E.64.86 2018-09-05 17:59:22 DEBUG
(MainThread) [insteonplm.plm] Found new device 2e6486 2018-09-05 17:59:22
DEBUG (MainThread) [insteonplm.devices] Registering messages for 2E.64.86
2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 2E.64.86, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:22
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:22 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:22 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:23
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:23 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e2091fb59b010009'
2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e2091fb59b010009' 2018-09-05 17:59:24 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e2091fb59b010009'
2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:24
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x09, 'address': 1F.B5.9B, 'linkdata1': 0x01, 'linkdata2':
0x00, 'linkdata3': 0x09} 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.devices] Starting Device.receive_message 2018-09-05 17:59:24
DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm] Last item in
self._recv_queue reached. 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.plm] ACK or NAK received 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.plm] Found all link record for device 1fb59b 2018-09-05
17:59:24 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address 1fb59b
data1: 01 data1: 00 data3: 09 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 1F.B5.9B 2018-09-05 17:59:24
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 1F.B5.9B 2018-09-05 17:59:24 DEBUG
(MainThread) [insteonplm.plm] Found new device 1fb59b 2018-09-05 17:59:24
DEBUG (MainThread) [insteonplm.devices] Registering messages for 1F.B5.9B
2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:24
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:24 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:24 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:25
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:25 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:26 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e2003e3781010000'
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e2003e3781010000' 2018-09-05 17:59:26 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e2003e3781010000'
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:26 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x00, 'address': 3E.37.81, 'linkdata1': 0x01, 'linkdata2':
0x00, 'linkdata3': 0x00} 2018-09-05 17:59:26 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.plm] Found all link record for device 3e3781
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address
3e3781 data1: 01 data1: 00 data3: 00 2018-09-05 17:59:26 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 3E.37.81 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
3E.37.81, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 3E.37.81 2018-09-05 17:59:26 DEBUG
(MainThread) [insteonplm.plm] Found new device 3e3781 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.devices] Registering messages for 3E.37.81
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 3E.37.81, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:26 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:26 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:26
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:26 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257a2013e3781000000'
2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257a2013e3781000000' 2018-09-05 17:59:27 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257a2013e3781000000'
2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:27
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xa2, 'group': 0x01, 'address': 3E.37.81, 'linkdata1': 0x00, 'linkdata2':
0x00, 'linkdata3': 0x00} 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.devices] Starting Device.receive_message 2018-09-05 17:59:27
DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm] Last item in
self._recv_queue reached. 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.plm] ACK or NAK received 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.plm] Found all link record for device 3e3781 2018-09-05
17:59:27 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address 3e3781
data1: 00 data1: 00 data3: 00 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 3E.37.81 2018-09-05 17:59:27
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
3E.37.81, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm] Found new device
3e3781 2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.devices]
Registering messages for 3E.37.81 2018-09-05 17:59:27 DEBUG (MainThread)
[insteonplm.devices] ID ACK: {'code': 0x62, 'address': 3E.37.81, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:27 DEBUG
(MainThread) [insteonplm.plm] Starting: _get_next_all_link_record
2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm] Requesting Next
All-Link Record 2018-09-05 17:59:27 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:27 DEBUG
(MainThread) [insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05
17:59:28 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:28 DEBUG (MainThread) [insteonplm.plm] Waiting for
ACK or NAK message 2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.plm] Received 13 bytes from PLM: b'026a060257e20b3e3781012045'
2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm] Total
buffer: b'026a060257e20b3e3781012045' 2018-09-05 17:59:29 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'0257e20b3e3781012045'
2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 2 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x06} 2018-09-05 17:59:29
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x57, 'controlFlags':
0xe2, 'group': 0x0b, 'address': 3E.37.81, 'linkdata1': 0x01, 'linkdata2':
0x20, 'linkdata3': 0x45} 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.devices] Starting Device.receive_message 2018-09-05 17:59:29
DEBUG (MainThread) [insteonplm.devices] Ending Device.receive_message
2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm] Last item in
self._recv_queue reached. 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.plm] ACK or NAK received 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.plm] Found all link record for device 3e3781 2018-09-05
17:59:29 DEBUG (MainThread) [insteonplm.plm] ALDB Data: address 3e3781
data1: 01 data1: 20 data3: 45 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 3E.37.81 2018-09-05 17:59:29
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
3E.37.81, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 3E.37.81 2018-09-05 17:59:29 DEBUG
(MainThread) [insteonplm.plm] Found new device 3e3781 2018-09-05 17:59:29
DEBUG (MainThread) [insteonplm.devices] Registering messages for 3E.37.81
2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 3E.37.81, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.plm] Starting: _get_next_all_link_record 2018-09-05 17:59:29
DEBUG (MainThread) [insteonplm.plm] Requesting Next All-Link Record
2018-09-05 17:59:29 DEBUG (MainThread) [insteonplm.plm] Queueing msg:
{'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:29 DEBUG (MainThread)
[insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05 17:59:30
DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone}
2018-09-05 17:59:30 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:31 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:31 DEBUG (MainThread)
[insteonplm.plm] Received 3 bytes from PLM: b'026a15' 2018-09-05 17:59:31
DEBUG (MainThread) [insteonplm.plm] Finishing: data_received 2018-09-05
17:59:31 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'026a15'
2018-09-05 17:59:31 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:31 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 1 2018-09-05 17:59:31 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x15} 2018-09-05 17:59:31
DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2018-09-05 17:59:31 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2018-09-05 17:59:31 DEBUG (MainThread) [insteonplm.plm] Starting:
_get_next_all_link_record 2018-09-05 17:59:31 DEBUG (MainThread)
[insteonplm.plm] Requesting Next All-Link Record 2018-09-05 17:59:31 DEBUG
(MainThread) [insteonplm.plm] Queueing msg: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:31 DEBUG (MainThread) [insteonplm.plm] Ending:
_get_next_all_link_record 2018-09-05 17:59:31 DEBUG (MainThread)
[insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:31
DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm] Starting:
data_received 2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm]
Received 3 bytes from PLM: b'026a15' 2018-09-05 17:59:33 DEBUG (MainThread)
[insteonplm.plm] Finishing: data_received 2018-09-05 17:59:33 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'026a15' 2018-09-05 17:59:33
DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm] Messages in queue:
1 2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm] RX: {'code':
0x6a, 'acknak': 0x15} 2018-09-05 17:59:33 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:33
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:33
DEBUG (MainThread) [insteonplm.plm] Starting: _get_next_all_link_record
2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm] Requesting Next
All-Link Record 2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:33 DEBUG
(MainThread) [insteonplm.plm] Ending: _get_next_all_link_record 2018-09-05
17:59:33 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:33 DEBUG (MainThread) [insteonplm.plm] Waiting for
ACK or NAK message 2018-09-05 17:59:34 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:34 DEBUG (MainThread)
[insteonplm.plm] Received 3 bytes from PLM: b'026a15' 2018-09-05 17:59:34
DEBUG (MainThread) [insteonplm.plm] Finishing: data_received 2018-09-05
17:59:34 DEBUG (MainThread) [insteonplm.plm] Total buffer: b'026a15'
2018-09-05 17:59:34 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:34 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 1 2018-09-05 17:59:34 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x6a, 'acknak': 0x15} 2018-09-05 17:59:34
DEBUG (MainThread) [insteonplm.plm] Last item in self._recv_queue reached.
2018-09-05 17:59:34 DEBUG (MainThread) [insteonplm.plm] ACK or NAK received
2018-09-05 17:59:34 DEBUG (MainThread) [insteonplm.plm] Starting:
_get_next_all_link_record 2018-09-05 17:59:34 DEBUG (MainThread)
[insteonplm.plm] Requesting Next All-Link Record 2018-09-05 17:59:34 DEBUG
(MainThread) [insteonplm.plm] Queueing msg: {'code': 0x6a, 'acknak':
0xNone} 2018-09-05 17:59:34 DEBUG (MainThread) [insteonplm.plm] Ending:
_get_next_all_link_record 2018-09-05 17:59:34 ERROR (Recorder)
[homeassistant.components.recorder.util] Error executing query:
(sqlite3.DatabaseError) database disk image is malformed [SQL: 'INSERT INTO
events (event_type, event_data, origin, time_fired, created, context_id,
context_user_id) VALUES (?, ?, ?, ?, ?, ?, ?)'] [parameters:
('service_registered', '{"domain": "recorder", "service": "purge"}',
'LOCAL', '2018-09-05 21:58:50.857821', '2018-09-05 21:59:34.899640',
'0365d45af41247c8be7a0a5bb25f6c28', None)] (Background on this error at:
http://sqlalche.me/e/4xp6) 2018-09-05 17:59:35 DEBUG (MainThread)
[insteonplm.plm] TX: {'code': 0x6a, 'acknak': 0xNone} 2018-09-05 17:59:35
DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm] Starting:
data_received 2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm]
Received 3 bytes from PLM: b'026a15' 2018-09-05 17:59:36 DEBUG (MainThread)
[insteonplm.plm] Finishing: data_received 2018-09-05 17:59:36 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'026a15' 2018-09-05 17:59:36
DEBUG (MainThread) [insteonplm.plm] Buffer too short to have a message
2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm] Messages in queue:
1 2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm] RX: {'code':
0x6a, 'acknak': 0x15} 2018-09-05 17:59:36 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:36
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:36
DEBUG (MainThread) [insteonplm.plm] All-Link device records found in ALDB:
4 2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm] Starting
_get_device_info 2018-09-05 17:59:36 DEBUG (MainThread)
[insteonplm.linkedDevices] Added new callback <bound method
IM._new_device_added of <insteonplm.plm.PLM object at 0x735babd0>>
2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm] Getting device info
for 1F.B5.9B 2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.devices]
caller name: _get_device_info 2018-09-05 17:59:36 DEBUG (MainThread)
[insteonplm.plm] Queueing msg: {'code': 0x62, 'address': 1F.B5.9B, 'flags':
0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:36
DEBUG (MainThread) [insteonplm.plm] Getting device info for 2E.64.86
2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.devices] caller name:
_get_device_info 2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x62, 'address': 2E.64.86, 'flags': 0x00, 'cmd1':
0x10, 'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:36 DEBUG
(MainThread) [insteonplm.plm] Getting device info for 2E.63.C8 2018-09-05
17:59:36 DEBUG (MainThread) [insteonplm.devices] caller name:
_get_device_info 2018-09-05 17:59:36 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x62, 'address': 2E.63.C8, 'flags': 0x00, 'cmd1':
0x10, 'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:37 DEBUG
(MainThread) [insteonplm.plm] Getting device info for 3E.37.81 2018-09-05
17:59:37 DEBUG (MainThread) [insteonplm.devices] caller name:
_get_device_info 2018-09-05 17:59:37 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x62, 'address': 3E.37.81, 'flags': 0x00, 'cmd1':
0x10, 'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:37 DEBUG
(MainThread) [insteonplm.plm] Ending _get_device_info 2018-09-05 17:59:37
DEBUG (MainThread) [insteonplm.linkedDevices] Writing 0 devices to save
file 2018-09-05 17:59:37 DEBUG (MainThread) [insteonplm.plm] TX: {'code':
0x62, 'address': 1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00,
'acknak': 0xNone} 2018-09-05 17:59:37 DEBUG (MainThread) [insteonplm.plm]
Waiting for ACK or NAK message 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.plm] Starting: data_received 2018-09-05 17:59:38 DEBUG
(MainThread) [insteonplm.plm] Received 42 bytes from PLM:
b'02621fb59b0010000602501fb59b2cb16d20100002501fb59b022a428f010002501fb59b022a428f0100'
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] Total
buffer:
b'02621fb59b0010000602501fb59b2cb16d20100002501fb59b022a428f010002501fb59b022a428f0100'
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'02501fb59b2cb16d20100002501fb59b022a428f010002501fb59b022a428f0100'
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'02501fb59b022a428f010002501fb59b022a428f0100' 2018-09-05 17:59:38 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'02501fb59b022a428f0100'
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 4 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x62, 'address': 1F.B5.9B, 'flags': 0x00,
'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:38 DEBUG
(MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] DA queue: {}
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Message ACK
with no callback 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.devices] Scheduling msg callback: <bound method
Device._handle_get_device_info_ack of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x72d852b0>>
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x50, 'address': 1F.B5.9B, 'target':
2C.B1.6D, 'flags': 0x20, 'cmd1': 0x10, 'cmd2': 0x00} 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK
message 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] But
Direct ACK not expected 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.devices] Ending Device.receive_message 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 1F.B5.9B,
'target': 02.2A.42, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x00} 2018-09-05
17:59:38 DEBUG (MainThread) [insteonplm.devices] Starting
Device.receive_message 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.devices] Scheduling msg callback: <bound method
Device._handle_device_info_response of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x72d852b0>>
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x50, 'address': 1F.B5.9B, 'target':
02.2A.42, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x00} 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Scheduling msg
callback: <bound method Device._handle_device_info_response of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x72d852b0>>
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.devices] Starting
_handle_get_device_info_ack with message: 2018-09-05 17:59:38 DEBUG
(MainThread) [insteonplm.devices] {'code': 0x62, 'address': 1F.B5.9B,
'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05
17:59:38 DEBUG (MainThread) [insteonplm.devices] Got device_id for 1F.B5.9B
in 1F.B5.9B 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Got
device_id for 1F.B5.9B in 1F.B5.9B 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.devices] Starting _wait_device_info for device 1F.B5.9B in
1F.B5.9B 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices]
_wait_device_info got device_id message {'code': 0x50, 'address': 1F.B5.9B,
'target': 02.2A.42, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x00} 2018-09-05
17:59:38 DEBUG (MainThread) [insteonplm.devices] Received Device ID with
address: 1fb59b cat: 0x2 subcat: 0x2a 2018-09-05 17:59:38 DEBUG
(MainThread) [insteonplm.devices] Registering messages for 1F.B5.9B
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] ID ACK:
{'code': 0x62, 'address': 1F.B5.9B, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0x06} 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.linkedDevices] New INSTEON Device '1fb59b': SwitchLinc Relay
(Dual-Band) (02:2a) 2018-09-05 17:59:38 INFO (MainThread)
[custom_components.insteon_custom] New INSTEON device: 1fb59b (lightOnOff)
switch 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] Removed ALDB
device 1fb59b 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.plm] ALDB
device count: 3 2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices]
Starting Device._send_msg 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.devices] Ending Device._send_msg 2018-09-05 17:59:38 DEBUG
(MainThread) [insteonplm.devices] Device with id 1fb59b added to device
list. 2018-09-05 17:59:38 INFO (MainThread) [insteonplm.devices] Total
Insteon devices found: 1 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.plm] Device 1fb59b not in ALDB device list 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.plm] ALDB device count: 3 2018-09-05
17:59:38 DEBUG (MainThread) [insteonplm.devices] Starting
Device._process_send_queue 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.devices] Lock is locked from yeild from 2018-09-05 17:59:38
DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x62, 'address':
1F.B5.9B, 'flags': 0x00, 'cmd1': 0x19, 'cmd2': 0x00, 'acknak': 0xNone}
2018-09-05 17:59:38 DEBUG (MainThread) [insteonplm.devices] Ending
Device._process_send_queue 2018-09-05 17:59:38 DEBUG (MainThread)
[insteonplm.linkedDevices] Writing 1 devices to save file 2018-09-05
17:59:38 WARNING (MainThread) [homeassistant.loader] You are using a custom
component for switch.insteon_custom which has not been tested by Home
Assistant. This component might cause stability problems, be sure to
disable it if you do experience issues with Home Assistant. 2018-09-05
17:59:38 DEBUG (MainThread) [custom_components.insteon_custom] Tracking
updates for device 1F.B5.9B group 1 statename lightOnOff 2018-09-05
17:59:38 DEBUG (MainThread) [insteonplm.states] Registered callback for
state: lightOnOff 2018-09-05 17:59:39 DEBUG (MainThread) [insteonplm.plm]
TX: {'code': 0x62, 'address': 2E.64.86, 'flags': 0x00, 'cmd1': 0x10,
'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:39 DEBUG (MainThread)
[insteonplm.plm] Waiting for ACK or NAK message 2018-09-05 17:59:40 DEBUG
(MainThread) [insteonplm.plm] Starting: data_received 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.plm] Received 42 bytes from PLM:
b'02622e64860010000602502e64862cb16d20100002502e6486010e438f013602502e6486010e438f0136'
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.plm] Total
buffer:
b'02622e64860010000602502e64862cb16d20100002502e6486010e438f013602502e6486010e438f0136'
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'02502e64862cb16d20100002502e6486010e438f013602502e6486010e438f0136'
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'02502e6486010e438f013602502e6486010e438f0136' 2018-09-05 17:59:40 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'02502e6486010e438f0136'
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 4 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x62, 'address': 2E.64.86, 'flags': 0x00,
'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:40 DEBUG
(MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] DA queue: {}
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Message ACK
with no callback 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.devices] Scheduling msg callback: <bound method
Device._handle_get_device_info_ack of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x706d97b0>>
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x50, 'address': 2E.64.86, 'target':
2C.B1.6D, 'flags': 0x20, 'cmd1': 0x10, 'cmd2': 0x00} 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK
message 2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] But
Direct ACK not expected 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.devices] Ending Device.receive_message 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 2E.64.86,
'target': 01.0E.43, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x36} 2018-09-05
17:59:40 DEBUG (MainThread) [insteonplm.devices] Starting
Device.receive_message 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.devices] Scheduling msg callback: <bound method
Device._handle_device_info_response of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x706d97b0>>
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x50, 'address': 2E.64.86, 'target':
01.0E.43, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x36} 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Scheduling msg
callback: <bound method Device._handle_device_info_response of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x706d97b0>>
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.devices] Starting
_handle_get_device_info_ack with message: 2018-09-05 17:59:40 DEBUG
(MainThread) [insteonplm.devices] {'code': 0x62, 'address': 2E.64.86,
'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05
17:59:40 DEBUG (MainThread) [insteonplm.devices] Got device_id for 2E.64.86
in 2E.64.86 2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Got
device_id for 2E.64.86 in 2E.64.86 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.devices] Starting _wait_device_info for device 2E.64.86 in
2E.64.86 2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices]
_wait_device_info got device_id message {'code': 0x50, 'address': 2E.64.86,
'target': 01.0E.43, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x36} 2018-09-05
17:59:40 DEBUG (MainThread) [insteonplm.devices] Received Device ID with
address: 2e6486 cat: 0x1 subcat: 0xe 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 2E.64.86 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
2E.64.86, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 2E.64.86 2018-09-05 17:59:40 DEBUG
(MainThread) [insteonplm.linkedDevices] New INSTEON Device '2e6486':
LampLinc Dimmer (01:0e) 2018-09-05 17:59:40 INFO (MainThread)
[custom_components.insteon_custom] New INSTEON device: 2e6486
(lightOnLevel) light 2018-09-05 17:59:40 DEBUG (MainThread)
[insteonplm.plm] Removed ALDB device 2e6486 2018-09-05 17:59:40 DEBUG
(MainThread) [insteonplm.plm] ALDB device count: 2 2018-09-05 17:59:40
DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2018-09-05 17:59:40 DEBUG (MainThread) [insteonplm.devices] Ending
Device._send_msg 2018-09-05 17:59:41 DEBUG (MainThread)
[insteonplm.devices] Device with id 2e6486 added to device list. 2018-09-05
17:59:41 INFO (MainThread) [insteonplm.devices] Total Insteon devices
found: 2 2018-09-05 17:59:41 DEBUG (MainThread) [insteonplm.plm] Device
2e6486 not in ALDB device list 2018-09-05 17:59:41 DEBUG (MainThread)
[insteonplm.plm] ALDB device count: 2 2018-09-05 17:59:41 DEBUG
(MainThread) [insteonplm.devices] Starting Device._process_send_queue
2018-09-05 17:59:41 DEBUG (MainThread) [insteonplm.devices] Lock is locked
from yeild from 2018-09-05 17:59:41 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x62, 'address': 2E.64.86, 'flags': 0x00, 'cmd1':
0x19, 'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:41 DEBUG
(MainThread) [insteonplm.devices] Ending Device._process_send_queue
2018-09-05 17:59:41 DEBUG (MainThread) [insteonplm.linkedDevices] Writing 2
devices to save file 2018-09-05 17:59:41 WARNING (MainThread)
[homeassistant.loader] You are using a custom component for
light.insteon_custom which has not been tested by Home Assistant. This
component might cause stability problems, be sure to disable it if you do
experience issues with Home Assistant. 2018-09-05 17:59:41 DEBUG
(MainThread) [custom_components.insteon_custom] Tracking updates for device
2E.64.86 group 1 statename lightOnLevel 2018-09-05 17:59:41 DEBUG
(MainThread) [insteonplm.states] Registered callback for state:
lightOnLevel 2018-09-05 17:59:42 DEBUG (MainThread) [insteonplm.plm] TX:
{'code': 0x62, 'address': 2E.63.C8, 'flags': 0x00, 'cmd1': 0x10, 'cmd2':
0x00, 'acknak': 0xNone} 2018-09-05 17:59:42 DEBUG (MainThread)
[insteonplm.plm] Waiting for ACK or NAK message 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.plm] Starting: data_received 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.plm] Received 42 bytes from PLM:
b'02622e63c80010000602502e63c82cb16d20100002502e63c8010e438f013602502e63c8010e438f0136'
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm] Finishing:
data_received 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm] Total
buffer:
b'02622e63c80010000602502e63c82cb16d20100002502e63c8010e438f013602502e63c8010e438f0136'
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'02502e63c82cb16d20100002502e63c8010e438f013602502e63c8010e438f0136'
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm] Total buffer:
b'02502e63c8010e438f013602502e63c8010e438f0136' 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.plm] Total buffer: b'02502e63c8010e438f0136'
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm] Buffer too short to
have a message 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm]
Messages in queue: 4 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x62, 'address': 2E.63.C8, 'flags': 0x00,
'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Got Message ACK
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] DA queue: {}
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Message ACK
with no callback 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.devices] Scheduling msg callback: <bound method
Device._handle_get_device_info_ack of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x72d28c70>>
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x50, 'address': 2E.63.C8, 'target':
2C.B1.6D, 'flags': 0x20, 'cmd1': 0x10, 'cmd2': 0x00} 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Got Direct ACK
message 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] But
Direct ACK not expected 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.devices] Ending Device.receive_message 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.plm] RX: {'code': 0x50, 'address': 2E.63.C8,
'target': 01.0E.43, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x36} 2018-09-05
17:59:43 DEBUG (MainThread) [insteonplm.devices] Starting
Device.receive_message 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.devices] Scheduling msg callback: <bound method
Device._handle_device_info_response of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x72d28c70>>
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.plm] RX: {'code': 0x50, 'address': 2E.63.C8, 'target':
01.0E.43, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x36} 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.devices] Starting Device.receive_message
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Scheduling msg
callback: <bound method Device._handle_device_info_response of
<insteonplm.devices.unknowndevice.UnknownDevice object at 0x72d28c70>>
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Ending
Device.receive_message 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.plm] Last item in self._recv_queue reached. 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.plm] ACK or NAK received 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.devices] Starting
_handle_get_device_info_ack with message: 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.devices] {'code': 0x62, 'address': 2E.63.C8,
'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06} 2018-09-05
17:59:43 DEBUG (MainThread) [insteonplm.devices] Got device_id for 2E.63.C8
in 2E.63.C8 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Got
device_id for 2E.63.C8 in 2E.63.C8 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.devices] Starting _wait_device_info for device 2E.63.C8 in
2E.63.C8 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices]
_wait_device_info got device_id message {'code': 0x50, 'address': 2E.63.C8,
'target': 01.0E.43, 'flags': 0x8f, 'cmd1': 0x01, 'cmd2': 0x36} 2018-09-05
17:59:43 DEBUG (MainThread) [insteonplm.devices] Received Device ID with
address: 2e63c8 cat: 0x1 subcat: 0xe 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.devices] Registering messages for 2E.63.C8 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address':
2E.63.C8, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x06}
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.states] Registering
callbacks for DimmableSwitch device 2E.63.C8 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.linkedDevices] New INSTEON Device '2e63c8':
LampLinc Dimmer (01:0e) 2018-09-05 17:59:43 INFO (MainThread)
[custom_components.insteon_custom] New INSTEON device: 2e63c8
(lightOnLevel) light 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.plm] Removed ALDB device 2e63c8 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.plm] ALDB device count: 1 2018-09-05 17:59:43
DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Ending
Device._send_msg 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.devices] Device with id 2e63c8 added to device list. 2018-09-05
17:59:43 INFO (MainThread) [insteonplm.devices] Total Insteon devices
found: 3 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm] Device
2e63c8 not in ALDB device list 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.plm] ALDB device count: 1 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.devices] Starting Device._process_send_queue
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.devices] Lock is locked
from yeild from 2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.plm]
Queueing msg: {'code': 0x62, 'address': 2E.63.C8, 'flags': 0x00, 'cmd1':
0x19, 'cmd2': 0x00, 'acknak': 0xNone} 2018-09-05 17:59:43 DEBUG
(MainThread) [insteonplm.devices] Ending Device._process_send_queue
2018-09-05 17:59:43 DEBUG (MainThread) [insteonplm.linkedDevices] Writing 3
devices to save file 2018-09-05 17:59:43 DEBUG (MainThread)
[custom_components.insteon_custom] Tracking updates for device 2E.63.C8
group 1 statename lightOnLevel 2018-09-05 17:59:43 DEBUG (MainThread)
[insteonplm.states] Registered callback for state: lightOnLevel 2018-09-05
17:59:45 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x62, 'address':
3E.37.81, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0xNone}
2018-09-05 17:59:45 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or
NAK message 2018-09-05 17:59:46 DEBUG (MainThread) [insteonplm.plm]
Starting: data_received 2018-09-05 17:59:46 DEBUG (MainThread)
[insteonplm.plm] Received 42 bytes from PLM:
b'02623e37810010000602503e37812cb16d20100002503e378101
|
Excellent! use that temp fix until I can get something in production. Leave this issue open until then. |
Please don't post endless unformatted log messages. Use triple backtics to format into code block and hide long logs with details tag: https://gist.github.com/ericclemmons/b146fe5da72ca1f706b2ef72a20ac39d |
I installed ha 0.78 last night and everything is looking good. Two positive side effects. It is much faster, ie the google assistant responses comes before the turn on / off action like it should. Secondly the the turn on of a dimmer at the wall switch properly updates HA. Before only turn off was updating. If you ever need a tester for older model of Insteon hub, feel free to drop me a note. Thanks |
Home Assistant release with the issue:
hassio -- version 1.3.1Last working Home Assistant release (if known):
0.76.2
Operating environment (Hass.io/Docker/Windows/etc.):
Hass.ioMy Insteon device is a pre-2014 Hub
Component/platform:
https://www.home-assistant.io/components/insteon/Description of problem:
The code does not find any of the insteon devices. Prior to this version I was using curl commands to access x-10 devices and that code still works under home assistant 0.77
Problem-relevant
configuration.yaml
entries and (fill out even if it seems unimportant):Traceback (if applicable):
Additional information:
The text was updated successfully, but these errors were encountered: