search

nugget / python-insteonplm

Python 3 asyncio module for interfacing with Insteon Powerline modems
MIT License
33 stars 19 forks source link

Problem with hub (2242) and not able to control anything #98

Closed TLMNicolas closed 5 years ago

TLMNicolas commented 6 years ago

Im running the latest home assistant on a windows machine, 64 bit (but using 32bit python 3.6). The insteon hub is the 2242 variety.

From the console output, I can see that HA connects to the hub and is trying to send commands. However I cant get it to load the list of devices synched in the hub, and using the device_override functionality doesnt work either.

There is an exception right after the call to " Requesting ALL-Link Records" which may be related to the problem. Im wondering if for some reason its not getting back the data from the http request.

Well any help is greatly appreciated

Here is the configuration lines

insteon:
  host: 192.168.0.42
  ip_port: 25105
  username: ***********
  password: ***************
  device_override:
    - address: 2B.17.26
      cat: 0x02
      subcat: 0x2F

logger:
  default: error
  logs:
    insteon: debug

The log when it starts up...

2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Starting Connection.create
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.devices] Registering messages for 00.00.00
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address': 00.00.00, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x0
6}
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] starting Connection._reconnect
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] starting Connection._connect
2018-09-03 11:53:58 INFO (MainThread) [insteonplm] Connecting to Insteon Hub on 192.168.0.42
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Creating http connection
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Starting the reader in HttpTrasnport __init__
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] create_http_connection Finished creating connection
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Test connection status is 200
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Starting the buffer reader
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] ending Connection._connect
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] ending Connection._reconnect
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Ending Connection.create
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] New override for 2b1726 cat is 2
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] New override for 2b1726 subcat is 47
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] Added new callback <function async_setup.<locals>.async_new_insteon_device at 0x07A300C0>
2018-09-03 11:53:58 INFO (MainThread) [insteonplm] Insteon Hub reader started
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] ..................Clearing the buffer..............
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.0.42:25105/1?XB=M=1
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Post status: 200
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Calling connection made
2018-09-03 11:53:58 INFO (MainThread) [insteonplm.plm] Connection established to Hub
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Transport: <insteonplm.HttpTransport object at 0x081BD7D0>
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Starting Insteon Modem write message from send queue
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Aquiring write lock
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] Loading saved device info.
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] Really Loading saved device info.
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] Saved device file not found
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Found 0 saved devices
2018-09-03 11:53:58 INFO (MainThread) [insteonplm.plm] Requesting Insteon Modem Info
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware':
 0xNone, 'acknak': 0xNone}
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.devices] Registering messages for 2B.17.26
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address': 2B.17.26, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x0
6}
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] Device with id 2b1726 added to device list from device override data.
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.linkedDevices] New INSTEON Device '2b1726': Micro On/Off (02:2f)
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Starting: _load_all_link_database
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Starting: _get_first_all_link_record
2018-09-03 11:53:58 INFO (MainThread) [insteonplm.plm] Requesting ALL-Link Records
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x69, 'acknak': 0xNone}
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Ending: _get_first_all_link_record
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Ending: _load_all_link_database
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Ending _setup_devices in IM
2018-09-03 11:53:58 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback None()
Traceback (most recent call last):
  File "c:\users\administrator\appdata\local\programs\python\python36-32\lib\asyncio\events.py", line 145, in _run
    self._callback(*self._args)
TypeError: 'NoneType' object is not callable
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, '
acknak': 0xNone}
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.0.42:25105/3?0260=I=3
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnOff
2018-09-03 11:53:58 DEBUG (MainThread) [insteonplm] Post status: 200
2018-09-03 11:54:00 DEBUG (MainThread) [insteonplm.plm] No ACK or NAK message received.
2018-09-03 11:54:00 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, '
acknak': 0xNone}

Log when i try to toggle the device_override switch i setup:

2018-09-03 11:56:56 DEBUG (MainThread) [insteonplm] ..................Writing a message..............
2018-09-03 11:56:56 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-03 11:56:56 DEBUG (MainThread) [insteonplm] Writing message: http://192.168.0.42:25105/3?0260=I=3
2018-09-03 11:56:56 DEBUG (MainThread) [insteonplm] Post status: 200
2018-09-03 11:56:57 DEBUG (MainThread) [insteonplm.devices] Starting Device._send_msg
2018-09-03 11:56:57 DEBUG (MainThread) [insteonplm.devices] Ending Device._send_msg
2018-09-03 11:56:57 DEBUG (MainThread) [insteonplm.devices] Starting Device._process_send_queue
2018-09-03 11:56:58 DEBUG (MainThread) [insteonplm.plm] No ACK or NAK message received.
2018-09-03 11:56:58 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, '
acknak': 0xNone}
TLMNicolas commented 6 years ago

Forgot to add that support for the 2242 was streamlined in issue #20

teharris1 commented 6 years ago

Had another HA user raise an issue and it now is clear that this component only supports the 2245 hub, not the 2242 hub. Working on a fix. If I give you code can you drop it in and test?

teharris1 commented 6 years ago

Here is an attempt at a fix. It does not fix the core module. It is a custom_component. Trying the fix there first then going to add it to HA and insteonplm if it fixes the issue. I am a little concerned about the buffer management but it is clear that the http interface via port 25105 is terrible on the 2442. I think there may be a better option via port 9761 but that will require a lot of playing with the device.

Anyway, here is the file to try. Unzip it to your home assistant config directory and add the following to your configuration.yaml:

insteon_custom:
  host: <your ip address>

custom_components.zip

TLMNicolas commented 6 years ago

Certainly will try anything you want me too.

Ive moved to this https://github.com/TD22057/insteon-mqtt and got it working quite nicely. I dont like that I have to define the switches in two places (HA + that code) but its neat as it allows me to control insteon things from other IOT "things" due to the mqtt-ness of it, bypassing HA as needed. It uses the PLM over network interface on port 9761.

In my debugging of the insteon module for HA i noticed something very strange. I saw it making queries like http://192.168.0.42:25105/3?0260=I=3 When i went to that URL in my browser nothing comes up (tried with Postman with get/post and also nothing returned), looking at the documentation for the API http://cache.insteon.com/developer/2242-222dev-062013-en.pdf the above is supposed to work, and return ~9 bytes. EDIT: I tried a "off" command to a device, and it worked - so the http api works, for some reason no data is being returned when the docs suggest it should. Odd EDIT2: My misunderstanding of the API is why the url response was blank (correct). It appears that API returns data via a seperate url buffstatus.xml (ugly right?!?)

I know that in the past there was some contention about the 2242 http api only allowing one client at a time - unsure if that is still the case or not. I dont see why that would be a limitation since the http on the 2242 is not long lived. See https://github.com/automategreen/home-controller/blob/master/Readme.md#http-client for that codes explanation of the problem.

Im going to grab the code you provided and try it out.

TLMNicolas commented 6 years ago

Got this error: File "D:\HomeAssistant\config\custom_components\insteon_custom\insteonplm__init__.py", line 12, in from serial.aio import create_serial_connection ModuleNotFoundError: No module named 'serial'

If anyone else gets the above error, see https://github.com/nugget/python-insteonplm/issues/19#issuecomment-321983030 for the solution. Dont install pyserial as is, you need to install an older 3.2 version

Down the rabbit hole @teharris1 ... ill stop posting edits until i give up or get something working.

TLMNicolas commented 6 years ago

I got it all running eventually with your custom components, but i could not get it to turn on/off a device. Tried using the device_override functionality and no luck. I know its trying to communicate because if I leave the username/password empty then i get an authentication error.

In the log there was this:

Config directory: D:\HomeAssistant\.\config
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_off>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_on>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=toggle>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=stop>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=restart>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=check_config>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=reload_core_config>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=create>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=dismiss>
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.loader] Loaded logger from homeassistant.components.logger
2018-09-03 22:09:28 INFO (MainThread) [homeassistant.setup] Setting up logger
2018-09-03 22:09:30 ERROR (MainThread) [custom_components.insteon_custom.insteonplm] CUSTOM CODE
teharris1 commented 6 years ago

How did you get it working with insteon-mqtt? I don't see anything in their code that supports the hub. Is that a socket-based connection?

Can you send me the error message when you leave the username and password blank? I thought that the hub v1 did not support a username or password.

teharris1 commented 6 years ago

Crazy experiment but in my original code, can you try this in your configuration.yaml file:

insteon:
  device: socket://<your ip address>:9761
teharris1 commented 6 years ago

nevermind that will not work. Replace the custom component with this file and use the following 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

teharris1 commented 6 years ago

Updated file. Feel pretty good about this one based on debugging. Use the same yaml as above. custom_components.zip

TLMNicolas commented 6 years ago

insteon-mqtt uses the PLM over network interface on port 9761, keeps a connection open so it can talk directly to the plm. I assume the insteon-local component for HA could be repurposed to work with that interface since its the same as over a serial port, except over a tcp socket.

TLMNicolas commented 6 years ago

No dice with your files from 2 hours ago (latest one).... I made sure to turn off the insteon-mqtt to free up the 9761 port on the hub. Tested the port on the hub was open, by connecting with a TCP utility i have to that port.

Remmeber im on windows, in case sockets or such are being used.

2018-09-04 20:50:01 INFO (MainThread) [homeassistant.setup] Setting up logger
2018-09-04 20:50:02 WARNING (MainThread) [homeassistant.loader] You are using a custom component for insteon_custom which has not been tested by Hom
 This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2018-09-04 20:50:03 INFO (MainThread) [custom_components.insteon_custom] Connecting to Insteon Hub on 192.168.0.42
2018-09-04 20:50:03 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting Connection.create
2018-09-04 20:50:03 DEBUG (MainThread) [insteonplm.devices] Registering messages for 00.00.00
2018-09-04 20:50:03 DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address': 00.00.00, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, '
6}
2018-09-04 20:50:03 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection.reconnect
2018-09-04 20:50:03 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 20:50:03 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 20:50:08 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 20:50:08 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._retry_connection
2018-09-04 20:50:08 WARNING (MainThread) [custom_components.insteon_custom.insteonplm] Connection failed, retry in 1 seconds: 192.168.0.42
2018-09-04 20:50:09 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-04 20:50:09 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 20:50:09 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 20:50:14 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 20:50:14 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._retry_connection
2018-09-04 20:50:14 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._retry_connection
2018-09-04 20:50:14 WARNING (MainThread) [custom_components.insteon_custom.insteonplm] Connection failed, retry in 2 seconds: 192.168.0.42
2018-09-04 20:50:14 WARNING (MainThread) [homeassistant.setup] Setup of insteon_custom is taking over 10 seconds.
2018-09-04 20:50:16 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-04 20:50:16 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 20:50:16 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 20:50:21 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 20:50:21 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._retry_connection
2018-09-04 20:50:21 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._retry_connection
2018-09-04 20:50:21 WARNING (MainThread) [custom_components.insteon_custom.insteonplm] Connection failed, retry in 3 seconds: 192.168.0.42
2018-09-04 20:50:25 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-04 20:50:25 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 20:50:25 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 20:50:30 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 20:50:30 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._retry_connection
2018-09-04 20:50:30 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._retry_connection
2018-09-04 20:50:30 WARNING (MainThread) [custom_components.insteon_custom.insteonplm] Connection failed, retry in 5 seconds: 192.168.0.42
2018-09-04 20:50:35 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting _connect
2018-09-04 20:50:35 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 20:50:35 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 20:50:40 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 20:50:40 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._retry_connection
2018-09-04 20:50:40 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._retry_connection
2018-09-04 20:50:40 WARNING (MainThread) [custom_components.insteon_custom.insteonplm] Connection failed, retry in 7 seconds: 192.168.0.42
TLMNicolas commented 6 years ago

I see you are using serial.serial_for_url(url) of pySerial. As part of your earlier test code, i installed version 3.2 of pySerial, should i try the newer version ?

EDIT: I think you may be trying to connect the socket wrong. See my attempts at changing the code and the resulting log. (it still not able to control lights, but it seems to connectand provide some feedback, im unsure the proper code usage and what to set protocol to)

I tried the following 

            if self._hub_version == 1:
                url = 'socket://{}:{}'.format(self._host, self._port)
                _LOGGER.info('Connecting to Insteon Hub v1 on %s', url)
                ser = serial.serial_for_url(url) 
                # pylint: disable=unused-variable
                #transport, protocol = yield from create_serial_connection(
                #    self._loop, lambda: self.protocol,
                #    url, baudrate=19200)
                transport = ser  #new line

And got sligtly closer...

2018-09-04 21:18:17 INFO (MainThread) [custom_components.insteon_custom] Connecting to Insteon Hub on 192.168.0.42
2018-09-04 21:18:17 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting Connection.create
2018-09-04 21:18:17 DEBUG (MainThread) [insteonplm.devices] Registering messages for 00.00.00
2018-09-04 21:18:17 DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address': 00.00.00, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0
6}
2018-09-04 21:18:17 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection.reconnect
2018-09-04 21:18:17 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 21:18:17 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 21:18:17 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 21:18:17 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection.reconnect
2018-09-04 21:18:17 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Ending Connection.create
2018-09-04 21:18:17 DEBUG (MainThread) [insteonplm.linkedDevices] Added new callback <function async_setup.<locals>.async_new_insteon_device at 0x0713BB28>
2018-09-04 21:18:18 DEBUG (SyncWorker_3) [custom_components.insteon_custom] Insteon Services registered

EDIT 2: I realized maybe calling the code twice was causing the 2nd one to fail to connect. So I commented out the serial.serial_for_url, and it connected... You will see in the output log, an exception (I think thats what is preventing it from reading the data coming back) AttributeError: 'Serial' object has no attribute 'fd'

if self._hub_version == 1:
                url = 'socket://{}:{}'.format(self._host, self._port)
                _LOGGER.info('Connecting to Insteon Hub v1 on %s', url)
                #ser = serial.serial_for_url(url)   #this opens the socket, and so does create_create_serial, so doing twice means the 2nd fails to connect. dont do it ?
                # pylint: disable=unused-variable
                transport, protocol = yield from create_serial_connection(
                    self._loop, lambda: self.protocol,
                    url, baudrate=19200)

LOG:

2018-09-04 21:27:59 INFO (MainThread) [homeassistant.setup] Setting up logger
2018-09-04 21:28:01 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 21:28:01 INFO (MainThread) [custom_components.insteon_custom] Connecting to Insteon Hub on 192.168.0.42
2018-09-04 21:28:01 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Starting Connection.create
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.devices] Registering messages for 00.00.00
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address': 00.00.00, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x0
6}
2018-09-04 21:28:01 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection.reconnect
2018-09-04 21:28:01 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] starting Connection._connect
2018-09-04 21:28:01 INFO (MainThread) [custom_components.insteon_custom.insteonplm] Connecting to Insteon Hub v1 on socket://192.168.0.42:9761
2018-09-04 21:28:01 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection._connect
2018-09-04 21:28:01 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] ending Connection.reconnect
2018-09-04 21:28:01 DEBUG (MainThread) [custom_components.insteon_custom.insteonplm] Ending Connection.create
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] New override for 2b1726 cat is 2
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] New override for 2b1726 subcat is 47
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] Added new callback <function async_setup.<locals>.async_new_insteon_device at 0x0739C7C8>
2018-09-04 21:28:01 INFO (MainThread) [insteonplm.plm] Connection established to PLM
2018-09-04 21:28:01 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback SerialTransport._ensure_reader()
Traceback (most recent call last):
  File "C:\Users\Administrator\AppData\Local\Programs\Python\Python36-32\lib\asyncio\events.py", line 145, in _run
    self._callback(*self._args)
  File "d:\homeassistant\homeassistant\lib\site-packages\serial\aio.py", line 260, in _ensure_reader
    self._loop.add_reader(self._serial.fd, self._read_ready)
AttributeError: 'Serial' object has no attribute 'fd'
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Starting Insteon Modem write message from send queue
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Aquiring write lock
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] Loading saved device info.
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] Really Loading saved device info.
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] Saved device file not found
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Found 0 saved devices
2018-09-04 21:28:01 INFO (MainThread) [insteonplm.plm] Requesting Insteon Modem Info
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware':
 0xNone, 'acknak': 0xNone}
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.devices] Registering messages for 2B.17.26
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.devices] ID ACK: {'code': 0x62, 'address': 2B.17.26, 'flags': 0x00, 'cmd1': 0x10, 'cmd2': 0x00, 'acknak': 0x0
6}
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] Device with id 2b1726 added to device list from device override data.
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.linkedDevices] New INSTEON Device '2b1726': Micro On/Off (02:2f)
2018-09-04 21:28:01 INFO (MainThread) [custom_components.insteon_custom] New INSTEON device: 2b1726 (lightOnOff) switch
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Starting: _load_all_link_database
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Starting: _get_first_all_link_record
2018-09-04 21:28:01 INFO (MainThread) [insteonplm.plm] Requesting ALL-Link Records
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Queueing msg: {'code': 0x69, 'acknak': 0xNone}
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Ending: _get_first_all_link_record
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Ending: _load_all_link_database
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Ending _setup_devices in IM
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, '
acknak': 0xNone}
2018-09-04 21:28:01 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-04 21:28:01 DEBUG (SyncWorker_7) [custom_components.insteon_custom] Insteon Services registered
2018-09-04 21:28:01 WARNING (MainThread) [homeassistant.loader] You are using a custom component for switch.insteon_custom which has not been tested by Home Ass
istant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2018-09-04 21:28:02 DEBUG (MainThread) [custom_components.insteon_custom] Tracking updates for device 2B.17.26 group 1 statename lightOnOff
2018-09-04 21:28:02 DEBUG (MainThread) [insteonplm.states] Registered callback for state: lightOnOff
2018-09-04 21:28:03 DEBUG (MainThread) [insteonplm.plm] No ACK or NAK message received.
2018-09-04 21:28:03 DEBUG (MainThread) [insteonplm.plm] TX: {'code': 0x60, 'address': 00.00.00, 'category': 0xNone, 'subcategory': 0xNone, 'firmware': 0xNone, '
acknak': 0xNone}
2018-09-04 21:28:03 DEBUG (MainThread) [insteonplm.plm] Waiting for ACK or NAK message
2018-09-04 21:28:05 DEBUG (MainThread) [insteonplm.plm] No ACK or NAK message received.
TLMNicolas commented 6 years ago

Tried doing the changes in this patch to my 3.2 pyserial, https://github.com/iiSeymour/pyserial-asyncio/commit/90d4cd77be98586ac254d98115e59bb01476cb18 but then I got a not implemented error related to the fileno() not working on windows I think. Tried pyserial 3.4 and got a whole other set of errors related to logger and such. I think im stuck between a rock and a hard place - windows.

I will continue to test anything you want me too, but maybe have someone on a linux machine try it out in case what Iam seeing is specific to windows/pyserial.

teharris1 commented 6 years ago

I was attempting to create a second connection to the hub and that may be why it was failing. Try this one. custom_components.zip

teharris1 commented 6 years ago

re-reading your message, it appears you already figured out that I was opening the connection twice. That is the same line I commented out. Not sure why you are getting the error with serial the 'fd' attribute. I am testing on Windows and not getting that error.

teharris1 commented 6 years ago

Can you check the version of pyserial-asyncio you are running? It should be version 0.4, which was released in March 2017. The patch you applied should have already been in the 0.4 version. You also should be running pyserial version 3.2.0. Any version above that has issues with pyserial-asyncio.

If this does not fix the issue, then I need to rewrite pyserial-asyncio to work with sockets. Not horrible but not something I am hoping to have to do.

teharris1 commented 6 years ago

OK, I think I got it this time. I was incorrectly referencing pyserial-asyncio. I told you there was an issue with pyserial above version 3.2.0. That is still the case by the 'old' way to get to pyserial_asyncio was to refrence serial.aio. Well, that still "worked" except on Windows. The aio developers broke out the solution into pyserial-asyncio but that changed the way the reference had to be derrived. I have now fixed it, created a dummy service to make a socket connection to and can now see reads coming in from the dummy service.

custom_components.zip

teharris1 commented 6 years ago

@TLMNicolas I had another user (on HASS.IO) identify the same issue. Working with him and because of your work above, I was able to get him working. I was also able to get Windows working in general for USB based PLMs so thanks for your help.

I have pushed a change to insteonplm and HA and would expect it to be in version 0.78 or 0.79.

teharris1 commented 5 years ago

@TLMNicolas Can I close this issue?

TLMNicolas commented 5 years ago

Yes go ahead thanks

On Sun, Sep 30, 2018, 9:58 AM Tom Harris, notifications@github.com wrote:

@TLMNicolas https://github.com/TLMNicolas Can I close this issue?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/nugget/python-insteonplm/issues/98#issuecomment-425734985, or mute the thread https://github.com/notifications/unsubscribe-auth/APVJ6I9IzeVlex7nMSazyrhvwvB7NJsgks5ugPgogaJpZM4WX96S .