search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.58k forks source link

[mqtt] Connection becomes null or channel becomes read-only #5020

Closed boc-tothefuture closed 5 years ago

boc-tothefuture commented 5 years ago

Encountering an issue in which a device configured with the homie convention goes offline eventually. I get notified after I try and send a message to it. I still see this issue in 2.5M1.

Here is the rule:

rule 'Update Chomecast Track'
when Item ChromecastStatusTrack changed
then
  logInfo("Nuvo", "Updating Nuvo Chromecast Track")
  sendCommand(Nuvo_Source_5_Display_Line_1, ChromecastStatusTrack.state)
end

When that rule gets called, I get the following error in my openhab.log:

2019-01-07 06:39:47.923 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Update Chomecast Track': An error occurred during the script execution: Could not invoke method: org.eclipse.smarthome.model.script.actions.BusEvent.sendCommand(org.eclipse.smarthome.core.items.Item,org.eclipse.smarthome.core.types.Command) on instance: null

So the item is now null for some reason.

I see this in the event.log at the same time:

2019-01-07 06:39:47.893 [hingStatusInfoChangedEvent] - 'mqtt:homie300:mosquitto:nuvo' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): No connection or readOnly channel!

From what I can, there is only one location in the code that would have the “No connection or readOnly channel!” error. Which is here

it looks like that is only thrown if the connection is null or the channel is read only.

bodiroga commented 5 years ago

Hi @davidgraeff!

I can see that you have labeled the issue as a "bug", but I just want to confirm that the error is still present in the latest snapshot version of openHAB (openHAB 2.5.0 Build #1557).

Thank you SOOOO much for all the work you have done with MQTT and Homie, let's see if we can finally get a stable version of the binding (the integration with Homie is awesome, but we have to polish some details :wink: )

Best regards,

Aitor

bodiroga commented 5 years ago

Hi @boc-tothefuture!

What type of broker are you using? Mosquitto or the embedded mqtt broker (moquette)?

I have been doing some tests and it seems that I can not reproduce the issue when I use an external broker such as Mosquitto :confused: So perhaps the issue is related to #4774, where @cubistico discovered that the embedded broker doesn't store retained messages between reboots. @davidgraeff has already created a PR to update Moquette to the latest version (#5194) and he claims that that fixes the mentioned bug, so we will see if something changes when the PR is merged :+1:

boc-tothefuture commented 5 years ago

Hi @bodiroga I am seeing this using Mosquitto.

bodiroga commented 5 years ago

Ummmm... this is really strange, I have tried with a Homie-ESP8266 device (NodeMCU V2) and a python script (using the homie-python library) and after rebooting the Eclipse IDE many times (I'm building openHAB from source) I'm unable to reproduce the issue with Mosquitto :man_facepalming: It's true that the units are lost

@boc-tothefuture, in the first message you have mention that you have tried with openHAB 2.5.0M1, but what about openHAB 2.5.0 SNAPSHOT? I don't know if you want to messed up with your openHAB installation, but if you test the issue with the latest snapshot version it would be awesome.

davidgraeff commented 5 years ago

The homie channel is a read-only channel (a sensor state etc) and cannot be published to. The device should not go offline because of that though. Fixed in my recent mqtt migration pr.

boc-tothefuture commented 5 years ago

@davidgraeff - What is odd is that the channel in question here should not be readonly. Here is the output from mosquitto_sub:

omie/nuvo/source5/displayline1/$name Source 5 Display Line 1
homie/nuvo/source5/displayline1/$settable true
homie/nuvo/source5/displayline1/$retained true
homie/nuvo/source5/displayline1/$datatype string

Does something default to read-only somehow?

davidgraeff commented 5 years ago

As soon as no command topic is known the binding switches to readonly mode for a channel. The "$settable true" should prevent that.

I have increased the waiting timeout for a property to 2.5s. Maybe the property was not fast enough send by the broker (the former timeout was 200 milliseconds for all attributes).

J-N-K commented 5 years ago

Is this still present in latest snapshots?

boc-tothefuture commented 5 years ago

@J-N-K now that we have an M2 build I will upgrade and test this weekend.

boc-tothefuture commented 5 years ago

With 2.5M2 I am no longer seeing the error message. Although I am seeing the same behavior as before. 

2019-08-17 18:09:07.469 [vent.ItemStateChangedEvent] - ChromecastStatusAlbum changed from UNDEF to Fire! The Very Best of The Pointer Sisters

2019-08-17 18:09:07.469 [vent.ItemStateChangedEvent] - ChromecastStatusArtist changed from UNDEF to The Pointer Sisters

2019-08-17 18:09:07.470 [vent.ItemStateChangedEvent] - ChromecastStatusTitle changed from UNDEF to Jump (For My Love)

2019-08-17 18:09:07.470 [ome.event.ItemCommandEvent] - Item 'Nuvo_Source_5_Display_Line_3' received command The Pointer Sisters

2019-08-17 18:09:07.472 [ome.event.ItemCommandEvent] - Item 'Nuvo_Source_5_Display_Line_2' received command Fire! The Very Best of The Pointer Sisters

2019-08-17 18:09:07.474 [ome.event.ItemCommandEvent] - Item 'Nuvo_Source_5_Display_Line_4' received command Jump (For My Love)

2019-08-17 18:09:07.476 [nt.ItemStatePredictedEvent] - Nuvo_Source_5_Display_Line_3 predicted to become The Pointer Sisters

2019-08-17 18:09:07.477 [nt.ItemStatePredictedEvent] - Nuvo_Source_5_Display_Line_2 predicted to become Fire! The Very Best of The Pointer Sisters

2019-08-17 18:09:07.478 [nt.ItemStatePredictedEvent] - Nuvo_Source_5_Display_Line_4 predicted to become Jump (For My Love)

2019-08-17 18:09:07.480 [vent.ItemStateChangedEvent] - Nuvo_Source_5_Display_Line_3 changed from Tracy Chapman to The Pointer Sisters

2019-08-17 18:09:07.480 [vent.ItemStateChangedEvent] - Nuvo_Source_5_Display_Line_2 changed from Tracy Chapman to Fire! The Very Best of The Pointer Sisters

2019-08-17 18:09:07.482 [vent.ItemStateChangedEvent] - Nuvo_Source_5_Display_Line_4 changed from Fast Car to Jump (For My Love)

2019-08-17 18:09:07.482 [vent.ItemStateChangedEvent] - Nuvo_Source_5_Display_Line_3 changed from The Pointer Sisters to Tracy Chapman

2019-08-17 18:09:07.482 [vent.ItemStateChangedEvent] - Nuvo_Source_5_Display_Line_2 changed from Fire! The Very Best of The Pointer Sisters to Tracy Chapman

2019-08-17 18:09:07.482 [vent.ItemStateChangedEvent] - Nuvo_Source_5_Display_Line_4 changed from Jump (For My Love) to Fast Car

Essentially:

  1. MQTT Item receives command from rule
  2. Item predicts to be changed to new state
  3. Item briefly changes to new state
  4. Item falls back to previous state (because nothing was published- validated with mosquitto_sub)

A restart of openhab fixes it (for a while).

@J-N-K - Since I no longer get the error message, should I close this one and open new one?

J-N-K commented 5 years ago

Yes. Seems to be a different cause.