A couple of error reports

[MrGibbage]

Using the new 0.7.4. Everything seems to be working, but I have noticed a couple of traceback reports in the logs. Sorry, but I don't have a lot of context for any of these, other than the lines that I grabbed from right before the report. Everything seems to be working fine, so I haven't been too bothered by any of these, but I thought you might want to know about them. If they aren't helpful, then disregard.

2020-12-30 07:49:00 DEBUG Protocol: Write bytes to modem: 02621341991a2f0000020fd70822013bce0cff1f018a
2020-12-30 07:49:00 DEBUG Serial: Wrote 22 bytes to serial /dev/ttyUSB0
2020-12-30 07:49:00 INFO Protocol: Read 0x62: Ext: 13.41.99, Type.DIRECT ext, 2f 00 ack: True 00 02 0f d7 08 22 01 3b ce 0c ff 1f 01 8a 
2020-12-30 07:49:00 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-12-30 07:49:01 INFO Protocol: Read 0x50: Std: 13.41.99->53.c1.0e Type.DIRECT_ACK cmd: 2f 00
2020-12-30 07:49:01 DEBUG Protocol: Setting next write time: 1609332541.524897
2020-12-30 07:49:01 DEBUG MsgHistory: Received 1 hops, total 21 for 11 entries
2020-12-30 07:49:01 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-12-30 07:49:01 INFO DeviceDbModify: Updating entry: 0fd7: 3b.ce.0c (hall remote foy grp:   1 type: RESP data: 0xff 0x1f 0x01 (UNUSED)
2020-12-30 07:49:01 ERROR Serial: Serial read error from /dev/ttyUSB0
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/network/Serial.py", line 184, in read_from_link
    self.signal_read.emit(self, data)
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/Signal.py", line 47, in emit
    slot(*args, **kwargs)
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/Protocol.py", line 355, in _data_read
    self._process_msg(msg)
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/Protocol.py", line 436, in _process_msg
    status = handler.msg_received(self, msg)
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/handler/DeviceDbModify.py", line 76, in msg_received
    self.db.set_delta(self.db.delta + 1)
TypeError: unsupported operand type(s) for +: 'NoneType' and 'int'
2020-12-30 07:49:07 WARNING Base: Handler timed out 1 of 3 sent: Ext: 13.41.99, Type.DIRECT ext, 2f 00 00 02 0f d7 08 22 01 3b ce 0c ff 1f 01 00 

and

2020-12-30 08:31:45 DEBUG MsgHistory: Average hops 0.2, using 1
2020-12-30 08:31:45 DEBUG Protocol: Write handler finished
2020-12-30 08:31:45 INFO Protocol: Write message to modem: Ext: 34.b8.37, Type.DIRECT ext, 2f 00 00 02 0f e7 08 62 01 3b ac 52 03 1c 01 00 
2020-12-30 08:31:45 DEBUG Protocol: Write bytes to modem: 026234b837152f0000020fe70862013bac52031c0115
2020-12-30 08:31:45 DEBUG Serial: Wrote 22 bytes to serial /dev/ttyUSB0
2020-12-30 08:31:45 DEBUG Serial: Wrote 22 bytes to serial /dev/ttyUSB0
2020-12-30 08:31:45 ERROR Serial: Serial write error from /dev/ttyUSB0
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/network/Serial.py", line 228, in write_to_link
    self.signal_wrote.emit(self, data)
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/Signal.py", line 47, in emit
    slot(*args, **kwargs)
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/Protocol.py", line 503, in _msg_written
    assert self._write_status == WriteStatus.PENDING_WRITE
AssertionError
2020-12-30 08:31:45 INFO Protocol: Read 0x62: Ext: 34.b8.37, Type.DIRECT ext, 2f 00 ack: False 00 02 0f ef 08 22 16 48 e9 ab ff 1f 01 96 
2020-12-30 08:31:45 DEBUG Protocol: Passing msg to write handler: DeviceDbModify handler
2020-12-30 08:31:45 ERROR DeviceDbModify: Device NAK of device db modify: Ext: 34.b8.37, Type.DIRECT ext, 2f 00 ack: False 00 02 0f ef 08 22 16 48 e9 ab ff 1f 01 96 

and

2020-12-31 08:37:18 INFO Mqtt: MQTT message insteon/command/3c.31.e8 b'{"cmd":"scene","name":"garage","is_on":1}'
2020-12-31 08:37:18 UI Mqtt: Commanding switch device 3c.31.e8 (garage) cmd=scene
2020-12-31 08:37:18 ERROR Mqtt: Error running command scene on device 3c.31.e8 (garage)
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/insteon_mqtt/mqtt/Mqtt.py", line 280, in handle_cmd
    cmd_func(on_done=on_done, **data)
TypeError: scene() got an unexpected keyword argument 'name'

[krkeegan]

Yes, please always report these, this is helpful.

1. I think I can figure this one out, although I am not sure how a database write was happening if we didn't know the state of the database.
2. Can you provide more of the log before this error occurred? This is a really weird one.
3. This is not an error in the program. Only scene commands on the Modem have names. Scene commands on specific devices do not have the name attribute. You can keep using the scene command through the general command interface, but you can't specify a name for a scene on a device. Or you can also use the scene topics that such as insteon/{{address}}/scene the payload for that topic is by default just on or off.

[MrGibbage]

Unfortunately, I do not have access to that second Traceback. I am a newbie when it comes to Home Assistant, and I haven't figured out how to get to the actual log file that inteon-mqtt writes to. The only way I know how to view the insteon-mqtt log is through the add-on web page. I have tried adding the logging: file: section to my config file, but it doesn't seem to do anything.

Yesterday I was adding a bunch of devices to my setup, and that is when I saw the errors. I still have more to add. If I see them again today, I'll be sure to grab as much information as I can.

[krkeegan]

No problem, I believe you are running this as a Home Assistant Add-On, if so, using these settings in your config.yaml will get you a file you can read:

logging:
  # 10=DEBUG, 20=INFO, 30=WARNING, 40=ERROR
  level: 10

  # Print messages to a file.
  file: /config/insteon-mqtt/insteon_mqtt.log

[krkeegan]

The second issue looks like a long standing bug. I can see it in my logs all the way back in April.

It looks like the write_to_link in Serial is running twice over the same outgoing data. It also seems to happen over and over again when I am sending a Modem Scene command of only 8 bytes. In most instances it sends 8 and then repeats 5. But a few times it is 8 and 8.

The reported bug arises on an extended message of 22 bytes, and sends the whole thing twice.

I suspect we have an issue with partially clearing the buffer.

[krkeegan]

I have merged a fix for your first issue.

The second one is more difficult to find. I may have found it, but the logging that you saw doesn't quite match what I would expect to see, so maybe it isn't fixed. I also improved the logging around this error, so there is a hope that if the error happens again we will get better information.

The error shows up rarely in my logs, so I am going to leave this issue open for a month or so and we can check back in the logs then and see if we still see it.