Multiple issues since upgrade to 0.8.1 #366

djfjeff · 2021-03-23T00:53:21Z

I will add more details tomorrow as I am not in front of my laptop right now but since updating to 0.8.1 from 0.8.0, my environment now has multiple issues... I wanted to raise this rapidly to warn of a possible issue.

First, I needed to set qos = 1 in my config (instead of 2 like I use since a couple of years). Without this, insteon-mqtt did not send anything to Mosquito.

Now I see that all my 3-way automation do not work anymore. The data never get to MQTT. The physical 3-way works but it is never reflected like before in HA.

The text was updated successfully, but these errors were encountered:

djfjeff · 2021-03-23T12:01:03Z

I now have more information to share. It seems insteon-mqtt stopped writing to my MQTT broker (mosquitto) but it seems random... Some lights works well but some other don't.

Here is a log from a light that I turn on in HA but the toggle remains off. The light turn on OK. The data never get written in MQTT :

2021-03-23 07:56:44.096 INFO Dimmer: Dimmer message insteon/42.7e.7c/level b'{"state": "ON"}'
2021-03-23 07:56:44.097 DEBUG MsgTemplate: Input template render: '{ "cmd" : "on"
   }'
2021-03-23 07:56:44.097 INFO Dimmer: Dimmer input command: {'cmd': 'on'}
2021-03-23 07:56:44.097 INFO ResponderBase: Device 42.7e.7c grp: 1 cmd: on normal
2021-03-23 07:56:44.098 INFO Protocol: Write message to modem: Std: 42.7e.7c, Type.DIRECT mh:3 hl:3, 11 ff 
2021-03-23 07:56:44.098 DEBUG Protocol: Write bytes to modem: 0262427e7c0f11ff
2021-03-23 07:56:44.098 DEBUG Serial: Wrote 8 bytes to serial /dev/ttyUSB0
2021-03-23 07:56:44.119 INFO Protocol: Read 0x62: Std: 42.7e.7c, Type.DIRECT mh:3 hl:3, 11 ff ack: True
2021-03-23 07:56:44.119 DEBUG Protocol: Passing msg to write handler: StandardCmd handler
2021-03-23 07:56:44.120 DEBUG StandardCmd: 42.7e.7c got PLM ACK
2021-03-23 07:56:44.407 INFO Protocol: Read 0x50: Std: 42.7e.7c->49.f7.73 Type.DIRECT_ACK mh:3 hl:3 cmd: 11 ff
2021-03-23 07:56:44.407 DEBUG Protocol: Setting next write time: 07:56:44.668
2021-03-23 07:56:44.409 DEBUG MsgHistory: Received 0 hops, total 0 for 1 entries
2021-03-23 07:56:44.410 DEBUG Protocol: Passing msg to write handler: StandardCmd handler
2021-03-23 07:56:44.411 DEBUG ResponderBase: Device 42.7e.7c ACK: Std: 42.7e.7c->49.f7.73 Type.DIRECT_ACK mh:3 hl:3 cmd: 11 ff
2021-03-23 07:56:44.412 INFO Base: Setting device 42.7e.7c (bedroom_light_2) on True level 255 normal command
2021-03-23 07:56:44.412 INFO StateTopic: MQTT received state 42.7e.7c (bedroom_light_2) on: {'is_on': True, 'level': 255, 'mode': <Mode.NORMAL: 'normal'>, 'button': None, 'reason': 'command'}
2021-03-23 07:56:44.414 DEBUG Mqtt: MQTT publish insteon/42.7e.7c/state { "state" : "ON", "brightness" : 255 } qos=1 ret=1
2021-03-23 07:56:44.415 DEBUG Protocol: Write handler finished
2021-03-23 07:56:44.416 DEBUG Mqtt: MQTT writing

And here is the result in my MQTT broker :

djfjeff · 2021-03-23T12:06:46Z

Also, here is the result when I turn on the button 1 (load) on one of my keypad. The lights turn on OK but the button in HA stay toggled off :

2021-03-23 08:04:12.082 DEBUG SetTopic: SetTopic message insteon/42.16.0c/set/1 b'ON'
2021-03-23 08:04:12.083 DEBUG MsgTemplate: Input template render: '{ "cmd" : "on" }'
2021-03-23 08:04:12.083 INFO SetTopic: SetTopic input command: {'cmd': 'on'}
2021-03-23 08:04:12.084 INFO ResponderBase: Device 42.16.0c grp: 1 cmd: on normal
2021-03-23 08:04:12.084 INFO Protocol: Write message to modem: Std: 42.16.0c, Type.DIRECT mh:3 hl:3, 11 ff 
2021-03-23 08:04:12.084 DEBUG Protocol: Write bytes to modem: 026242160c0f11ff
2021-03-23 08:04:12.084 DEBUG Serial: Wrote 8 bytes to serial /dev/ttyUSB0
2021-03-23 08:04:12.097 INFO Protocol: Read 0x62: Std: 42.16.0c, Type.DIRECT mh:3 hl:3, 11 ff ack: True
2021-03-23 08:04:12.097 DEBUG Protocol: Passing msg to write handler: StandardCmd handler
2021-03-23 08:04:12.097 DEBUG StandardCmd: 42.16.0c got PLM ACK
2021-03-23 08:04:12.401 INFO Protocol: Read 0x50: Std: 42.16.0c->49.f7.73 Type.DIRECT_ACK mh:3 hl:3 cmd: 11 ff
2021-03-23 08:04:12.401 DEBUG Protocol: Setting next write time: 08:04:12.662
2021-03-23 08:04:12.402 DEBUG MsgHistory: Received 0 hops, total 0 for 1 entries
2021-03-23 08:04:12.402 DEBUG Protocol: Passing msg to write handler: StandardCmd handler
2021-03-23 08:04:12.402 DEBUG ResponderBase: Device 42.16.0c ACK: Std: 42.16.0c->49.f7.73 Type.DIRECT_ACK mh:3 hl:3 cmd: 11 ff
2021-03-23 08:04:12.402 INFO Base: Setting device 42.16.0c (entry_keypad) on True level 255 normal command
2021-03-23 08:04:12.403 INFO StateTopic: MQTT received state 42.16.0c (entry_keypad) on: {'is_on': True, 'level': 255, 'mode': <Mode.NORMAL: 'normal'>, 'button': None, 'reason': 'command'}
2021-03-23 08:04:12.403 DEBUG Mqtt: MQTT publish insteon/42.16.0c/state/ ON qos=1 ret=1
2021-03-23 08:04:12.403 DEBUG Protocol: Write handler finished
2021-03-23 08:04:12.404 DEBUG Mqtt: MQTT writing

And the very weird result in MQTT :

You can see the insteon-mqtt send a MQTT write to a no button state...

Here is the config for this specific button in HA :

- platform: mqtt
  name: "Porch Light"
  state_topic: "insteon/42.16.0c/state/1"
  command_topic: "insteon/42.16.0c/set/1"
  unique_id: 42160c1

All of this was working fine yesterday morning before I update to HA 2021.4 and insteon-mqtt 0.8.1

krkeegan · 2021-03-23T22:04:55Z

Hmm:

The 0.8.1 update didn't touch anything MQTT related. Here is the compare. Of course it is possible some earlier change caused an issue you are just noticing now.
I think you have some issue with your MQTT broker or connection to it. Nothing has changed at the low level that would be affected by the MQTT QOS for more than a year. Plus going from 2 to 1 and having more success is counter-intuitive.
As to your dimmer I see this line in the log:
2021-03-23 07:56:44.414 DEBUG Mqtt: MQTT publish insteon/42.7e.7c/state { "state" : "ON", "brightness" : 255 } qos=1 ret=1
That is the log message of the correct payload being published. We do not have any logging below this level because everything else is handled by the PAHO MQTT library. Running the same command on a dimmer in my setup is working just fine. I would suspect the issue is in the connection to your MQTT broker or the broker itself.
As to your Keypad Switchlinc. That does look like a bug. It looks like this broke back in 0.7.5 and we didn't notice. It only seems to affect Keypads of the Switch variety and not the Dimmer variety. I made a small PR Add Button to Decode_On_Level; Add Unit Tests #368 to fix this.
I am only on HA core-2021.3.4 the most recent release, you mentioned 2021.4 which isn't currently released. Are you on some pre-release version of HA? That could be the source, but it looks like you are running your own MQTT broker and not the mosquitto addon, so maybe not.

I would try the following:

See if Add Button to Decode_On_Level; Add Unit Tests #368 solves the KPL issue.
See if you can get some debugging from your MQTT broker.

djfjeff · 2021-03-23T22:15:41Z

I am sorry, I am effectively on core 2021.3.4, this was a typo. And also, I am using the Mosquitto addons with no customization.

I will try to get debug log from my broker but like I said, it was working fine before the update. Also, my broker serve for other components (rtl, tasmota, etc) and they all work like before.

Like you said, I did the compare of the changes for 0.8.1 and effectively, I could not see an area that might cause the issue.

However, it might be possible that the issue was present in 0.8.0 as I upgraded to this release not long ago and I did not have time to completely test my environment after. I upgraded to 0.8.1 not long after and I saw the weird behavior then.

krkeegan · 2021-03-23T22:21:51Z

Sorry, the screenshots of the MQTT state made me think that this was some other broker.

Why don't you try:

Config -> Integrations -> MQTT -> Configure -> Listen to Topic:
insteon/42.7e.7c/state

And see what you get. You should see all of the messages published.

krkeegan · 2021-03-23T22:26:52Z

I see this note on the Mosquitto addon:

Known issues and limitations
Since version 4.1 of the add-on, an explicit ACL definition is now required if you plan to use legacy logins and "anonymous": true see these instructions.

Is it possible you are using an anonymous account to connect Insteon-MQTT to the broker?

djfjeff · 2021-03-23T22:30:49Z

Thanks for checking this! I am using a username/password to log in to Mosquito so ot should not be an issue.

I am not home right now, I will get back to you with the MQTT debug and listening data when I get back.

Also, I am new to the HassIO stuff as I migrated to it only a month ago (from an old venv environment). I am still not sure how I could test your PR for the keypad linc but I will try to report on this too.

krkeegan · 2021-03-23T22:46:33Z

I wrote up some instructions that might help you, depending on how comfortable you are with ssh and git:

https://github.com/TD22057/insteon-mqtt/blob/master/docs/hassio_development.md

djfjeff · 2021-03-24T11:04:46Z

This morning, out of nowhere, my light that was not working yesterday was now working. So I could not fetch the log... But as I know I was not crazy and something changed, I reverted to my old Insteon MQTT config with qos = 2 and here is the log not working.

When I toggle the light ON in HA, here is the log from insteon-mqtt :

2021-03-24 06:54:51.247 INFO Dimmer: Dimmer message insteon/42.7e.7c/level b'{"state": "ON"}'
2021-03-24 06:54:51.249 DEBUG MsgTemplate: Input template render: '{ "cmd" : "on"
   }'
2021-03-24 06:54:51.250 INFO Dimmer: Dimmer input command: {'cmd': 'on'}
2021-03-24 06:54:51.251 INFO ResponderBase: Device 42.7e.7c grp: 1 cmd: on normal
2021-03-24 06:54:51.254 DEBUG MsgHistory: Average hops 0.0, using 0
2021-03-24 06:54:51.255 INFO Protocol: Write message to modem: Std: 42.7e.7c, Type.DIRECT mh:0 hl:0, 11 ff 
2021-03-24 06:54:51.256 DEBUG Protocol: Write bytes to modem: 0262427e7c0011ff
2021-03-24 06:54:51.257 DEBUG Serial: Wrote 8 bytes to serial /dev/ttyUSB0
2021-03-24 06:54:51.286 INFO Protocol: Read 0x62: Std: 42.7e.7c, Type.DIRECT mh:0 hl:0, 11 ff ack: True
2021-03-24 06:54:51.286 DEBUG Protocol: Passing msg to write handler: StandardCmd handler
2021-03-24 06:54:51.287 DEBUG StandardCmd: 42.7e.7c got PLM ACK
2021-03-24 06:54:51.428 INFO Protocol: Read 0x50: Std: 42.7e.7c->49.f7.73 Type.DIRECT_ACK mh:0 hl:0 cmd: 11 ff
2021-03-24 06:54:51.429 DEBUG Protocol: Setting next write time: 06:54:51.428
2021-03-24 06:54:51.430 DEBUG MsgHistory: Received 0 hops, total 0 for 2 entries
2021-03-24 06:54:51.431 DEBUG Protocol: Passing msg to write handler: StandardCmd handler
2021-03-24 06:54:51.431 DEBUG ResponderBase: Device 42.7e.7c ACK: Std: 42.7e.7c->49.f7.73 Type.DIRECT_ACK mh:0 hl:0 cmd: 11 ff
2021-03-24 06:54:51.432 INFO Base: Setting device 42.7e.7c (bedroom_light_2) on True level 255 normal command
2021-03-24 06:54:51.433 INFO StateTopic: MQTT received state 42.7e.7c (bedroom_light_2) on: {'is_on': True, 'level': 255, 'mode': <Mode.NORMAL: 'normal'>, 'button': None, 'reason': 'command'}
2021-03-24 06:54:51.435 DEBUG Mqtt: MQTT publish insteon/42.7e.7c/state { "state" : "ON", "brightness" : 255 } qos=2 ret=1
2021-03-24 06:54:51.436 DEBUG Protocol: Write handler finished
2021-03-24 06:54:51.437 DEBUG Mqtt: MQTT writing

And when I listen to the insteon/42.7e.7c/state topic, I see nothing get pushed there, no change... There was nothing of interest in the MQTT log from my broker, so it seems the message never gets there at all...

djfjeff · 2021-03-24T13:44:56Z

Ok, weirdly enough, I think I solved my issues... (except the Keypad Linc, which I did not have time to try the PR).

It seems that when I migrate to 0.8.1 and migrate my config.yaml to the new default one (to include the new settings like the hidden sensor, etc), I forgot to change the storage: setting from data back to /config/insteon-mqtt/data. So it seems insteon-mqtt was not loading the db for my devices and weird things were happening.

To be honest, I am not sure this is the resolution but my lights started to work correctly again...

krkeegan · 2021-03-24T17:04:26Z

Yeah, I share your skepticism. I tested out setting my storage location to a nonexistent directory. That causes a crash on startup. I tried setting it to an existing directory that it didn't have write permissions to and that resulted in a logged error, but everything was able to startup. I tested MQTT messages and they still worked. Having an empty directory wouldn't cause an error either because that is how we start out.

Anything is possible, but it seems a strange result to me.

Is there anything else that may changed in the config file? Are there any strange characters on the topic templates or something?

I am going to add another PR that enables support for debug logging from the Paho MQTT client. The logging only provides slightly more detail, it looks like the log below (it uses the prefix client), but maybe if you are having errors it would provide more detail:

2021-03-24 09:58:53.700 DEBUG ResponderBase: Device 4f.23.38 ACK: Std: 4f.23.38->41.ee.e6 Type.DIRECT_ACK mh:3 hl:3 cmd: 13 00
2021-03-24 09:58:53.700 INFO Base: Setting device 4f.23.38 (dimmer) on False level 0 normal command
2021-03-24 09:58:53.701 INFO StateTopic: MQTT received state 4f.23.38 (dimmer) on: {'is_on': False, 'level': 0, 'mode': <Mode.NORMAL: 'normal'>, 'button': None, 'reason': 'command'}
2021-03-24 09:58:53.701 DEBUG client: Sending PUBLISH (d0, q1, r1, m28), 'b'insteon/4f.23.38/state'', ... (37 bytes)
2021-03-24 09:58:53.702 DEBUG Mqtt: MQTT publish insteon/4f.23.38/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1
2021-03-24 09:58:53.702 UI Mqtt: Device state updated to on=False
2021-03-24 09:58:53.703 DEBUG Protocol: Write handler finished
2021-03-24 09:58:53.703 DEBUG client: Received PUBACK (Mid: 28)
2021-03-24 09:58:53.703 DEBUG Mqtt: MQTT writing
2021-03-24 09:59:23.726 DEBUG client: Sending PINGREQ
2021-03-24 09:59:23.727 DEBUG client: Received PINGRESP

krkeegan · 2021-03-24T18:42:11Z

Oh, another thing I just though of. Are you seeing anything interesting in the Insteon-MQTT logs on startup? I don't need the whole log from startup, just thinking that maybe an error is being thrown once at the start that might help us.

djfjeff · 2021-03-24T19:22:57Z

Sorry, the logging to a standard file was not enabled in my config.yaml previously... Like I said, I am new to this HassOS thing and I was using the log in the web interface. It is easier to manage than my old venv but it is a lot less flexible than what I am used to...

I remember seeing db doesn't exist message but I don't have them anymore. I will continue to test and look for possible issue.

krkeegan · 2021-03-24T19:47:54Z

No problem. Agree, the Supervisor design is a little less free wheeling, but I think the additional security, stability, and ease of management makes up for it. I have been able to find solutions to most of my needs, it just requires doing things differently than I am used to.

So, we did previously have the ability to log messages from the Paho Client, but the setting was obscure. So if there were errors, it was not being logged even if you had Debug level enabled. I have a PR #369 that moves all Paho Client messages into the log at their assigned levels. It doesn't add much additional logging so it shouldn't be a big deal, but it should now properly log warning and error messages which might provide some more clues.

djfjeff · 2021-03-26T14:19:50Z

It seems some of my MQTT message from insteon-mqtt does not make it to mosquitto, at random. For example this morning, my wife switched the closet light from the switch and turn if off from the switch a little bit later. The light worked fine physically, the logs in insteon-mqtt seems to be good, I have no error in my HA or Mosquitto logs.

But the message never maked it to my broker. In my broker, the state is still reporting ON and the light still show as ON in HA. Here is the insteon-mqtt log :

2021-03-26 07:27:26.166 INFO Broadcast: Handling all link broadcast for 48.b9.23 'master_bedroom_closet'
2021-03-26 07:27:26.166 INFO Base: Device 48.b9.23 broadcast grp: 1 on: True mode: normal  
2021-03-26 07:27:26.167 INFO Base: Setting device 48.b9.23 (master_bedroom_closet) on True level 255 normal device
2021-03-26 07:27:26.167 INFO StateTopic: MQTT received state 48.b9.23 (master_bedroom_closet) on: {'is_on': True, 'level': 255, 'mode': <Mode.NORMAL: 'normal'>, 'button': 1, 'reason': 'device'}
2021-03-26 07:27:26.169 INFO Base: 48.b9.23 (master_bedroom_closet) broadcast to 49.f7.73 for group 1
2021-03-26 07:27:26.419 INFO Protocol: Read 0x50: Std: 48.b9.23 Type.ALL_LINK_CLEANUP mh:0 hl:0 grp: 01 cmd: 11 01
2021-03-26 07:27:26.516 INFO Protocol: Read 0x50: Std: 48.b9.23 Type.ALL_LINK_BROADCAST mh:3 hl:3 grp: 01 cmd: 06 00
2021-03-26 07:34:38.307 INFO Protocol: Read 0x50: Std: 48.ae.bf Type.ALL_LINK_BROADCAST mh:3 hl:3 grp: 01 cmd: 11 00
....
2021-03-26 07:35:36.634 INFO Broadcast: Handling all link broadcast for 48.b9.23 'master_bedroom_closet'  
2021-03-26 07:35:36.634 INFO Base: Device 48.b9.23 broadcast grp: 1 on: False mode: normal
2021-03-26 07:35:36.635 INFO Base: Setting device 48.b9.23 (master_bedroom_closet) on False level 0 normal device
2021-03-26 07:35:36.636 INFO StateTopic: MQTT received state 48.b9.23 (master_bedroom_closet) on: {'is_on': False, 'level': 0, 'mode': <Mode.NORMAL: 'normal'>, 'button': 1, 'reason': 'device'}
2021-03-26 07:35:36.638 INFO Base: 48.b9.23 (master_bedroom_closet) broadcast to 49.f7.73 for group 1
2021-03-26 07:35:36.887 INFO Protocol: Read 0x50: Std: 48.b9.23 Type.ALL_LINK_CLEANUP mh:0 hl:0 grp: 01 cmd: 13 01
2021-03-26 07:35:36.982 INFO Protocol: Read 0x50: Std: 48.b9.23 Type.ALL_LINK_BROADCAST mh:3 hl:3 grp: 01 cmd: 06 00
2021-03-26 07:45:13.613 INFO Protocol: Read 0x50: Std: 48.ae.bf Type.ALL_LINK_BROADCAST mh:3 hl:3 grp: 01 cmd: 13 00

Here is a screenshot of my MQTT broker (using MQTT Explorer) :

Here is a screenshot of the HA logbook (notice there is no turn off event ever received :

I am a bit at a lost here. I was always working fine before, I run HassIO, so everything is local to the same system (so network issue are probably out of the loop), etc. I will continue to investigate and when you get a new release out with the paho-mqtt logging stuff, I will try it and see if I can find something.

krkeegan · 2021-03-26T22:41:18Z

OK, I pushed out 0.8.2. Hopefully that will help you debug what is going on.

djfjeff · 2021-03-30T12:50:41Z

It seems the new update fixed the issue with the keypad linc button 1 (maybe it's because it is now considered a switch, but the light bulb inside the HA dashboard does not turn on when the light is on now).

However, I am still seeing the issue with MQTT, with nothing in the log... Here is a log from a 3-way switch. The first switch (bathroom_vanity_light) was turned off, it also turned off the second switch correctly (bathroom_light) physically. However, in HA, only bathroom_vanity_light was turned off. The bathroom_light was still showing as ON in HA (and in MQTT)... :

2021-03-30 08:15:28.361 INFO Protocol: Read 0x50: Std: 48.b7.d8 Type.ALL_LINK_BROADCAST mh:3 hl:3 grp: 01 cmd: 13 00
2021-03-30 08:15:28.362 DEBUG Protocol: Setting next write time: 08:15:28.622                         
2021-03-30 08:15:28.364 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries                       
2021-03-30 08:15:28.365 INFO Broadcast: Handling all link broadcast for 48.b7.d8 'bathroom_vanity_light'
2021-03-30 08:15:28.365 DEBUG Protocol: Setting next write time: 08:15:29.909                                  
2021-03-30 08:15:28.366 INFO Base: Device 48.b7.d8 broadcast grp: 1 on: False mode: normal       
2021-03-30 08:15:28.366 INFO Base: Setting device 48.b7.d8 (bathroom_vanity_light) on False level 0 normal device
2021-03-30 08:15:28.367 INFO StateTopic: MQTT received state 48.b7.d8 (bathroom_vanity_light) on: {'is_on': False, 'level': 0, 'mode': <Mode.NORMAL: 'normal'>, 'button': 1, 'reason': 'device'}
2021-03-30 08:15:28.368 DEBUG Mqtt: Sending PUBLISH (d0, q1, r1, m360), 'b'insteon/48.b7.d8/state'', ... (37 bytes)
2021-03-30 08:15:28.369 DEBUG Mqtt: MQTT publish insteon/48.b7.d8/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1
2021-03-30 08:15:28.370 DEBUG Base: Found 2 responders in group 1                                         
2021-03-30 08:15:28.370 DEBUG Base: Group 1 -> ['49.f7.73', '48.ae.bf']                            
2021-03-30 08:15:28.371 INFO Base: 48.b7.d8 (bathroom_vanity_light) broadcast to 49.f7.73 for group 1
2021-03-30 08:15:28.372 INFO Base: 48.b7.d8 (bathroom_vanity_light) broadcast to 48.ae.bf for group 1         
2021-03-30 08:15:28.373 INFO ResponderBase: Device 48.ae.bf (bathroom_light) processing on/off group 1 cmd from 48.b7.d8
2021-03-30 08:15:28.373 INFO Base: Setting device 48.ae.bf (bathroom_light) on False level 0 normal scene
2021-03-30 08:15:28.374 INFO StateTopic: MQTT received state 48.ae.bf (bathroom_light) on: {'is_on': False, 'level': 0, 'mode': <Mode.NORMAL: 'normal'>, 'button': 1, 'reason': 'scene'}
2021-03-30 08:15:28.375 DEBUG Mqtt: Sending PUBLISH (d0, q1, r1, m361), 'b'insteon/48.ae.bf/state'', ... (37 bytes)           
2021-03-30 08:15:28.376 DEBUG Mqtt: MQTT publish insteon/48.ae.bf/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1
2021-03-30 08:15:28.376 DEBUG Mqtt: Received PUBACK (Mid: 360)                                                                                                                               
2021-03-30 08:15:28.377 DEBUG Mqtt: Received PUBACK (Mid: 361)                                                                
2021-03-30 08:15:28.377 DEBUG Mqtt: MQTT writing                                                                         
2021-03-30 08:15:28.601 INFO Protocol: Read 0x50: Std: 48.b7.d8 Type.ALL_LINK_CLEANUP mh:0 hl:0 grp: 01 cmd: 13 01                                                                         
2021-03-30 08:15:28.602 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries                                             
2021-03-30 08:15:28.809 INFO Protocol: Read 0x50: Std: 48.b7.d8 Type.ALL_LINK_BROADCAST mh:3 hl:3 grp: 01 cmd: 06 00
2021-03-30 08:15:28.810 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries                                                                                                         
2021-03-30 08:15:28.810 DEBUG Protocol: Setting next write time: 08:15:28.810                                       
2021-03-30 08:15:28.810 DEBUG Protocol: Setting next write time: 08:15:29.070             
2021-03-30 08:15:28.811 DEBUG Broadcast: Cleanup report for 48.b7.d8, grp 1 success.

Turning off the bathroom_light in HA switched the status correctly both in HA and MQTT :

2021-03-30 08:40:03.662 DEBUG Mqtt: Received PUBLISH (d0, q0, r0, m0), 'insteon/48.ae.bf/level', ...  (16 bytes)    
2021-03-30 08:40:03.663 INFO Dimmer: Dimmer message insteon/48.ae.bf/level b'{"state": "OFF"}'        
2021-03-30 08:40:03.663 DEBUG MsgTemplate: Input template render: '{ "cmd" : "off"                      
   }'                                                                                                   
2021-03-30 08:40:03.663 INFO Dimmer: Dimmer input command: {'cmd': 'off'}                                      
2021-03-30 08:40:03.664 INFO ResponderBase: Device 48.ae.bf grp: 1 cmd: off normal               
2021-03-30 08:40:03.664 DEBUG MsgHistory: Average hops 0.0, using 0                                              
2021-03-30 08:40:03.664 INFO Protocol: Write message to modem: Std: 48.ae.bf, Type.DIRECT mh:0 hl:0, 13 00                                                                                      
2021-03-30 08:40:03.665 DEBUG Protocol: Write bytes to modem: 026248aebf001300                                     
2021-03-30 08:40:03.665 DEBUG Serial: Wrote 8 bytes to serial /dev/ttyUSB0                                               
2021-03-30 08:40:03.685 INFO Protocol: Read 0x62: Std: 48.ae.bf, Type.DIRECT mh:0 hl:0, 13 00 ack: True   
2021-03-30 08:40:03.685 DEBUG Protocol: Passing msg to write handler: StandardCmd handler          
2021-03-30 08:40:03.685 DEBUG StandardCmd: 48.ae.bf got PLM ACK                                      
2021-03-30 08:40:03.829 INFO Protocol: Read 0x50: Std: 48.ae.bf->49.f7.73 Type.DIRECT_ACK mh:0 hl:0 cmd: 13 00
2021-03-30 08:40:03.831 DEBUG Protocol: Setting next write time: 08:40:03.829                                           
2021-03-30 08:40:03.832 DEBUG MsgHistory: Received 0 hops, total 0 for 11 entries                        
2021-03-30 08:40:03.833 DEBUG Protocol: Passing msg to write handler: StandardCmd handler                                                                                               
2021-03-30 08:40:03.834 DEBUG ResponderBase: Device 48.ae.bf ACK: Std: 48.ae.bf->49.f7.73 Type.DIRECT_ACK mh:0 hl:0 cmd: 13 00
2021-03-30 08:40:03.835 INFO Base: Setting device 48.ae.bf (bathroom_light) on False level 0 normal command              
2021-03-30 08:40:03.836 INFO StateTopic: MQTT received state 48.ae.bf (bathroom_light) on: {'is_on': False, 'level': 0, 'mode': <Mode.NORMAL: 'normal'>, 'button': None, 'reason': 'command'}
2021-03-30 08:40:03.838 DEBUG Mqtt: Sending PUBLISH (d0, q1, r1, m363), 'b'insteon/48.ae.bf/state'', ... (37 bytes)           
2021-03-30 08:40:03.840 DEBUG Mqtt: MQTT publish insteon/48.ae.bf/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1
2021-03-30 08:40:03.841 DEBUG Protocol: Write handler finished                                                                                                                             
2021-03-30 08:40:03.842 DEBUG Mqtt: MQTT writing                                                                              
2021-03-30 08:40:03.912 DEBUG Mqtt: Received PUBACK (Mid: 363)

Any idea? I am running out of option on where to check for this one...

krkeegan · 2021-03-30T17:00:13Z

Well that log makes it pretty clear that the problem is somewhere between the MQTT Broker and HA. We have a log of the message sent to the Broker and the Ack of it back from the broker.

2021-03-30 08:40:03.838 DEBUG Mqtt: Sending PUBLISH (d0, q1, r1, m363), 'b'insteon/48.ae.bf/state'', ... (37 bytes)           
2021-03-30 08:40:03.840 DEBUG Mqtt: MQTT publish insteon/48.ae.bf/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1
2021-03-30 08:40:03.841 DEBUG Protocol: Write handler finished                                                                                                                             
2021-03-30 08:40:03.842 DEBUG Mqtt: MQTT writing                                                                              
2021-03-30 08:40:03.912 DEBUG Mqtt: Received PUBACK (Mid: 363)

So I would guess something in the HA configuration. Maybe the look in the HA forums for anything similar about MQTT?

djfjeff · 2021-03-30T17:33:39Z

No, this is the issue I have. Even if we see the ACK in insteon-mqtt log, the data in my broker is not updated and still report as ON (which is why HA still report as ON as well). I am not sure HA is involved in that at all.

In fact, in the last message, everything was done outside of HA. I toggled the switch physically and the data in my broker was still reporting ON.

TD22057 · 2021-03-30T17:48:22Z

Could there be 2 brokers running? It's hard to believe that Insteon-MQTT gets an ACK back from the broker for a publish and the message in the broker isn't there. That's just not how the broker works. I know HA has a builtin broker and so you can end up w/ multiple brokers running. Perhaps try running mosquitto_sub -h HOST -p PORT -v -t # for the host/port that IM is connected to and see what retained state messages are there (be sure you have retain=1 in the IM config file before hand). That should show the last published message in the broker and tell you whether the IM->broker publish is happening or not.

djfjeff · 2021-03-30T18:02:46Z

I am sure I only have 1 broker running. I am running HassIO with the built in Mosquitto addon.

My insteon-mqtt config point to the core-mosquitto broker (so the one provided by the addon). This hostname resolve internally to HassIO, so there is no outside network involved.

I will leave a mosquitto_sub command running overnight to monitor the insteon topic and see tomorrow if I still have inaccuracies between my physical state and what Mosquitto is reporting.

TD22057 · 2021-03-30T18:42:13Z

OK - but IMO you shouldn't need to leave it running to get some info. As long as retain was set, the broker has all the last messages for each topic. So the first thing to check is that the message that was ACK'ed in the IM log is on the broker as the last message for that topic. If that's true, then the issue is in the broker->HA connection or how the messages in HA are being parsed. It could be something like an incorrect payload template in the HA config which means the message isn't being parsed so the state isn't updating. Or the reverse - the IM payload config could be wrong and so IM is not parsing messages (or sending what HA expects).

djfjeff · 2021-03-30T18:50:06Z

Ok, but like I said previously, I think HA is out of the scope here.

I can see in my broker (using MQTT Explorer) that the message is not there (the state still report ON) even after I see the ACK in insteon-mqtt that the state was set to OFF.

In my insteon-mqtt log, I have this :

2021-03-30 08:40:03.838 DEBUG Mqtt: Sending PUBLISH (d0, q1, r1, m363), 'b'insteon/48.ae.bf/state'', ... (37 bytes)           
2021-03-30 08:40:03.840 DEBUG Mqtt: MQTT publish insteon/48.ae.bf/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1
2021-03-30 08:40:03.841 DEBUG Protocol: Write handler finished                                                                                                                             
2021-03-30 08:40:03.842 DEBUG Mqtt: MQTT writing                                                                              
2021-03-30 08:40:03.912 DEBUG Mqtt: Received PUBACK (Mid: 363)

But in my broker, I still have this :

insteon/48.ae.bf/state { "state" : "ON", "brightness" : 255 }

Having that still in my broker, this is why HA still report the light as ON. But I do not think HA is part of the issue.

krkeegan · 2021-03-30T19:08:58Z

I still think the issue is somewhere between the broker and HA. That doesn't mean HA is it, it could just be the broker. I can see a few things:

Multiple brokers as Ted points out
The broker is broken is someway.
Something is overwriting the messages immediately (some sort of automation in HA?)
Whatever broker you are connecting to to check the state is not the same one Insteon-mqtt is connecting to.

You could probably discern the issue with a verbose log from the broker itself.

But, the issue of whether the message was delivered from Insteon-MQTT to a broker is answered.

Again the logs show us sending the message id 363 with qos=1 and retain set to true, to the topic insteon/48.ae.bf/state:

2021-03-30 08:40:03.838 DEBUG Mqtt: Sending PUBLISH (d0, q1, r1, m363), 'b'insteon/48.ae.bf/state'', ... (37 bytes)

The payload as reported in the log is:

2021-03-30 08:40:03.840 DEBUG Mqtt: MQTT publish insteon/48.ae.bf/state { "state" : "OFF", "brightness" : 0 } qos=1 ret=1

A broker then confirms receiving message id 363

2021-03-30 08:40:03.912 DEBUG Mqtt: Received PUBACK (Mid: 363)

Something is confirming receiving the message.

Again, at this point, I would try to get a verbose log from your MQTT broker and see what it says. Using mosquitto_sub is likely not telling us the full story.

djfjeff · 2021-03-30T19:16:48Z

Multiple brokers as Ted points out
This I am sure is not the case. This is a brand new HassIO install, I only added the Mosquitto addon and this is the only MQTT broker I have on my network.
The broker is broken is someway.
Maybe, this might be what is causing the issue. The weird thing is all my RTL and Tasmota devices are working fine (at least, I did not see any issue).
Something is overwriting the messages immediately (some sort of automation in HA?)
Again, maybe, but I did not change anything in HA for a long while (having everyone at home full time reduce my window to play and test automation!).
Whatever broker you are connecting to to check the state is not the same one Insteon-mqtt is connecting to.
This is also something that I am sure that is not an issue. Everything on HassIO connect to core-mosquitto, which is the internal hostname of my Mosquitto broker.

I hope using mosquitto_sub will show me a history of what my broker received (and confirm if something is overwriting).

I need to find how to enable verbose log in the Mosquitto addon, I searched but did not found anything. This is the area I find HassIO more difficult to work with.

krkeegan · 2021-03-30T19:42:58Z

changing the supervisor logging levels to debug $>ha supervisor options -l debug

and then restarting the MQTT broker should do it.

krkeegan · 2021-03-30T19:53:52Z

Also, I see this rather lengthy issue suggesting the broker may have an issue:

home-assistant/addons#1887

krkeegan · 2021-03-30T23:56:34Z

I looked at the code for the mosquitto broker addon. Sadly, it doesn't look like it is configured to allow for log_type all which would have been ideal. But you should still try setting the logging to debug level and see if we get any helpful information from it.

djfjeff · 2021-04-08T11:34:27Z

Just an update, I do still have issue on my end and, like you mentioned before, it might come from my MQTT addons issue...

I will try to downgrade to the previous version and see if the issue persist.

djfjeff · 2021-05-13T11:56:40Z

I did not have much success to find where this issue really come from. I did not touch anything except to update to latest HA and InsteonMQTT version (the MQTT addon did not push an update still). It seems the issue happen a lot less than before.

In any case, it seems it is now clear the issue does not come from InsteonMQTT so I will go ahead and close this issue. Thanks a lot for your help in debugging this issue!

krkeegan mentioned this issue Mar 23, 2021

Add Button to Decode_On_Level; Add Unit Tests #368

Merged

5 tasks

krkeegan mentioned this issue Mar 24, 2021

Move Paho Client Log Messages into Log at Same Level #369

Merged

4 tasks

djfjeff closed this as completed May 13, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Multiple issues since upgrade to 0.8.1 #366

Multiple issues since upgrade to 0.8.1 #366

djfjeff commented Mar 23, 2021

djfjeff commented Mar 23, 2021 •

edited

Loading

djfjeff commented Mar 23, 2021 •

edited

Loading

krkeegan commented Mar 23, 2021

djfjeff commented Mar 23, 2021

krkeegan commented Mar 23, 2021

krkeegan commented Mar 23, 2021

djfjeff commented Mar 23, 2021

krkeegan commented Mar 23, 2021

djfjeff commented Mar 24, 2021

djfjeff commented Mar 24, 2021

krkeegan commented Mar 24, 2021

krkeegan commented Mar 24, 2021

djfjeff commented Mar 24, 2021

krkeegan commented Mar 24, 2021

djfjeff commented Mar 26, 2021

krkeegan commented Mar 26, 2021

djfjeff commented Mar 30, 2021

krkeegan commented Mar 30, 2021

djfjeff commented Mar 30, 2021

TD22057 commented Mar 30, 2021

djfjeff commented Mar 30, 2021

TD22057 commented Mar 30, 2021

djfjeff commented Mar 30, 2021

krkeegan commented Mar 30, 2021

djfjeff commented Mar 30, 2021

krkeegan commented Mar 30, 2021

krkeegan commented Mar 30, 2021

krkeegan commented Mar 30, 2021

djfjeff commented Apr 8, 2021

djfjeff commented May 13, 2021

Multiple issues since upgrade to 0.8.1 #366

Multiple issues since upgrade to 0.8.1 #366

Comments

djfjeff commented Mar 23, 2021

djfjeff commented Mar 23, 2021 • edited Loading

djfjeff commented Mar 23, 2021 • edited Loading

krkeegan commented Mar 23, 2021

djfjeff commented Mar 23, 2021

krkeegan commented Mar 23, 2021

krkeegan commented Mar 23, 2021

djfjeff commented Mar 23, 2021

krkeegan commented Mar 23, 2021

djfjeff commented Mar 24, 2021

djfjeff commented Mar 24, 2021

krkeegan commented Mar 24, 2021

krkeegan commented Mar 24, 2021

djfjeff commented Mar 24, 2021

krkeegan commented Mar 24, 2021

djfjeff commented Mar 26, 2021

krkeegan commented Mar 26, 2021

djfjeff commented Mar 30, 2021

krkeegan commented Mar 30, 2021

djfjeff commented Mar 30, 2021

TD22057 commented Mar 30, 2021

djfjeff commented Mar 30, 2021

TD22057 commented Mar 30, 2021

djfjeff commented Mar 30, 2021

krkeegan commented Mar 30, 2021

djfjeff commented Mar 30, 2021

krkeegan commented Mar 30, 2021

krkeegan commented Mar 30, 2021

krkeegan commented Mar 30, 2021

djfjeff commented Apr 8, 2021

djfjeff commented May 13, 2021

djfjeff commented Mar 23, 2021 •

edited

Loading

djfjeff commented Mar 23, 2021 •

edited

Loading