MQTT Numbers are persisted, but not restored on startup

[lsiepel]

Using Mysql persistence i can’t get items states to restore on startup.I have this problem for a while, but always tought something is wrong with my setup. But after reading and fiddling with all the settings i can’t seem to fix it.

mysql.persist

Strategies {
	everyHour			: "0	0	*	*	* ?"
	default = everyChange
}

Items {
	_grpPersist*				: strategy = restoreOnStartup, everyChange
	_grpMeterstand*				: strategy = restoreOnStartup, everyHour
}

Meterstand.Items

Number	verd0_meterkast_stroom_in_laag		"Meterstand in laagtarief [%.0f kwh] "		    <energy>	(_grpVerd0,_grpEnergie,_grpMeterstand)      { channel="mqtt:topic:lplxvibroker:slimmemeter:stroom_in_stand_laag"}
Number	verd0_meterkast_stroom_in_hoog		"Meterstand in hoogtarief [%.0f kwh]"		    <energy>	(_grpVerd0,_grpEnergie,_grpMeterstand)      { channel="mqtt:topic:lplxvibroker:slimmemeter:stroom_in_stand_hoog"}
Number	verd0_meterkast_stroom_uit_laag		"Meterstand uit laagtarief [%.0f kwh] "		    <energy>	(_grpVerd0,_grpEnergie,_grpMeterstand)      { channel="mqtt:topic:lplxvibroker:slimmemeter:stroom_uit_stand_laag"}
Number	verd0_meterkast_stroom_uit_hoog		"Meterstand uit hoogtarief [%.0f kwh]"		    <energy>	(_grpVerd0,_grpEnergie,_grpMeterstand)      { channel="mqtt:topic:lplxvibroker:slimmemeter:stroom_uit_stand_hoog"}

I checked if the values are persisted and i didn’t find any problem with that:

SELECT * FROM `Items` where ItemName in ('verd0_meterkast_stroom_in_laag','verd0_meterkast_stroom_in_hoog','verd0_meterkast_stroom_uit_laag','verd0_meterkast_stroom_uit_hoog')
// 4 records: Item18, 56, 132 and 135

SELECT * FROM Item18 ORDER BY Time desc LIMIT 1
// did this for all 4 items. They return the same time: '2019-08-01 10:00:00' and similar value (double): '970.072'

Logfile snippet when system startup with log:set DEBUG org.openhab.persistence.mysql

2019-08-01 11:57:50.086 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is verd0_meterkast_stroom_in_hoog
2019-08-01 11:57:50.087 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item56 ORDER BY Time DESC LIMIT 0,1
2019-08-01 11:57:50.088 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 1 rows in 2ms
2019-08-01 11:57:50.094 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is verd0_meterkast_stroom_uit_laag
2019-08-01 11:57:50.095 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item132 ORDER BY Time DESC LIMIT 0,1
2019-08-01 11:57:50.097 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 1 rows in 2ms
2019-08-01 11:57:50.103 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is verd0_meterkast_stroom_uit_hoog
2019-08-01 11:57:50.104 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item135 ORDER BY Time DESC LIMIT 0,1
2019-08-01 11:57:50.105 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 1 rows in 1ms
2019-08-01 11:57:50.112 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is verd0_meterkast_stroom_in_laag
2019-08-01 11:57:50.113 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item18 ORDER BY Time DESC LIMIT 0,1
2019-08-01 11:57:50.115 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 1 rows in 2ms

So it looks like eveything works as expected. BUT i don’t see the the values in basicUI or PaperUI:

What else can i do to check?

Edit 1: So i removed the channel declaration from the Item and now the value is restoredOnStartup. So all the persistence stuff is ok. The MQTT binding (or configuration) is now the first suspect for not restoring the values at startup.

Bridge configuration:

Bridge mqtt:broker:lplxvibroker "Bridge Label" [host="192.168.1.10", port=1883, secure="OFF",retainMessages=true] {
    Thing topic slimmemeter "MQTT Slimmemeter" {
        Channels:
        Type number : stroom_in_stand_laag      "Meterstand in laag"    [ stateTopic="/lplxvi/meterkast/stroom/in/laag" ]
        Type number : stroom_in_stand_hoog      "Meterstand in hoog"    [ stateTopic="/lplxvi/meterkast/stroom/in/hoog" ]
        Type number : stroom_uit_stand_laag     "Meterstand uit laag"   [ stateTopic="/lplxvi/meterkast/stroom/uit/laag" ]
        Type number : stroom_uit_stand_hoog     "Meterstand uit hoog"   [ stateTopic="/lplxvi/meterkast/stroom/uit/hoog" ]
    }
}

Edit2: I also set the MQTT binding in debug mode (but that isn’t showing anything usefull:

2019-08-01 20:21:35.171 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-08-01 20:21:35.180 [DEBUG] [org.openhab.binding.mqtt.generic    ] - BundleEvent STARTING - org.openhab.binding.mqtt.generic
2019-08-01 20:21:35.182 [DEBUG] [org.openhab.binding.mqtt.generic    ] - BundleEvent STARTED - org.openhab.binding.mqtt.generic
2019-08-01 20:21:35.187 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.mqtt.generic.MqttChannelStateDescriptionProvider}={service.id=482, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.MqttChannelStateDescriptionProvider, component.id=291} - org.openhab.binding.mqtt.generic
2019-08-01 20:21:35.196 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.ChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelGroupTypeProvider, org.openhab.binding.mqtt.generic.MqttChannelTypeProvider}={service.id=483, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.MqttChannelTypeProvider, component.id=292} - org.openhab.binding.mqtt.generic
2019-08-01 20:21:35.202 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=484, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.internal.MqttThingHandlerFactory, component.id=293} - org.openhab.binding.mqtt.generic
2019-08-01 20:21:36.686 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:lplxvibroker:slimmemeter:stroom_in_stand_laag
2019-08-01 20:21:36.688 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:lplxvibroker:slimmemeter:stroom_in_stand_hoog
2019-08-01 20:21:36.695 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:lplxvibroker:slimmemeter:stroom_uit_stand_laag
2019-08-01 20:21:36.696 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:lplxvibroker:slimmemeter:stroom_uit_stand_hoog
2019-08-01 20:21:36.778 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:lplxvibroker:slimmemeter:stroom_uit_stand_hoog to topic: /lplxvi/meterkast/stroom/uit/hoog
2019-08-01 20:21:36.780 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:lplxvibroker:slimmemeter:stroom_in_stand_hoog to topic: /lplxvi/meterkast/stroom/in/hoog
2019-08-01 20:21:36.781 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:lplxvibroker:slimmemeter:stroom_uit_stand_laag to topic: /lplxvi/meterkast/stroom/uit/laag
2019-08-01 20:21:36.785 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:lplxvibroker:slimmemeter:stroom_in_stand_laag to topic: /lplxvi/meterkast/stroom/in/laag
2019-08-01 20:21:36.990 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - BundleEvent STARTING - org.openhab.binding.mqtt.homeassistant
2019-08-01 20:21:36.993 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - BundleEvent STARTED - org.openhab.binding.mqtt.homeassistant
2019-08-01 20:21:36.999 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=485, service.bundleid=241, service.scope=bundle, component.name=org.openhab.binding.mqtt.homeassistant.generic.internal.MqttThingHandlerFactory, component.id=294} - org.openhab.binding.mqtt.homeassistant
2019-08-01 20:21:37.139 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=486, service.bundleid=241, service.scope=bundle, component.name=org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery, component.id=295} - org.openhab.binding.mqtt.homeassistant
2019-08-01 20:21:37.158 [DEBUG] [org.openhab.binding.mqtt.homie      ] - BundleEvent STARTING - org.openhab.binding.mqtt.homie
2019-08-01 20:21:37.159 [DEBUG] [org.openhab.binding.mqtt.homie      ] - BundleEvent STARTED - org.openhab.binding.mqtt.homie
2019-08-01 20:21:37.165 [DEBUG] [org.openhab.binding.mqtt.homie      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=487, service.bundleid=242, service.scope=bundle, component.name=org.openhab.binding.mqtt.homie.generic.internal.MqttThingHandlerFactory, component.id=296} - org.openhab.binding.mqtt.homie
2019-08-01 20:21:46.957 [DEBUG] [org.openhab.binding.mqtt.homie      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=488, service.bundleid=242, service.scope=bundle, component.name=org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery, component.id=297} - org.openhab.binding.mqtt.homie
2019-08-01 20:21:47.012 [DEBUG] [qtt.generic.AbstractMQTTThingHandler] - Successfully published value 19.5 to topic events/central_heating/otmonitor/setpoint

Edit3:
I noticed that when i set the value for this item in paperUI Control a error is shown in the dev console:

angular.min.js:117 Error: [ngModel:numfmt] http://errors.angularjs.org/1.5.7/ngModel/numfmt?p0=UNDEF
    at angular.min.js:6
    at Array.<anonymous> (angular.min.js:268)
    at angular.min.js:287
    at m.$digest (angular.min.js:142)
    at m.$apply (angular.min.js:145)
    at angular.min.js:158
    at e (angular.min.js:45)
    at angular.min.js:48

[rossko57]

@lsiepel

The MQTT binding (or configuration) is now the first suspect for not restoring the values at startup

To interpret this a different way, restore on startup is working quite happily. But when MQTT subscribes to your broker it gets UNDEF (probably?) values.
I’d make a guess that MQTT “retain” is involved here, and it is unpopulated at OH startup.

@lsiepel

retainMessages=true

Aha. So at MQTT binding startup, it asks the broker for updates and tramples your restore-on-startup values?

[lsiepel]

The retained message is a valid message (it is the actual number that was stored in the database). Just to be sure i set the retainMessages=false and restarted the whole server and clients.

Still no luck. I noticed something else. Just like the restoreonstartup is not doing anything. When i set a value from a rule, it immediate resets back to the old value. I think that is also happening with the restoreOnStartUp.

rule  "Initialise all energy stuff"
when
    Item virtual_switch changed
then
    verd0_meterkast_stroom.sendCommand(12.3)   
end

Leads to:

2019-08-01 23:24:38.850 [vent.ItemStateChangedEvent] - verd0_meterkast_stroom_in_laag changed from UNDEF to 12.3
2019-08-01 23:24:38.851 [vent.ItemStateChangedEvent] - verd0_meterkast_stroom_in_laag changed from 12.3 to UNDEF

Why is it reset to the old state within one ms ? Nothing shows up on the debug log. And this is in a sandbox instance of openHAB with just this rule, item and mqtt binding. Just to be sure nothing else interferes

[rossko57]

UNDEF comes from the binding. This will trample over restore-on-startup and postUpdates.

It’s typically what you would get in case of a serious communications error, or perhaps a misconfiguration. There do not seem to be any transformations involved in your case here,
You need to figure out why you are not getting sensible values from your broker. Unless your targets set “retain” on their publishings, you’d normally get nothing until the target speaks up.

Start with a look at Thing status.

[lsiepel]

@rossko57

would get in case of a serious communications error, or perhaps a misconfiguration. There

The MQTT topic is updated every 10 seconds (if changed) from the smart meter. The value’s are shown in the UI and stored in the DB correctly. I don;t see a communication error. It looks like something is going wrong in the binding when it’s value is updated not from the topic. (eg. rule or persistence).
No mather what the item’s value is, as soon as i postUpdate or restoreOnStart a value to it, it immidiate (1ms) returns UNDEF. So i’d rather think it’s a misconfigration or a MQTT binding bug.

For what mqtt namespaces should i set the debug log to see what is going on there?

[rossko57]

Alrighty, this looks like known MQTT 2.4 binding misbehaviour.

UNDEF Values in MQTT v2.4 Binding after Openhab2 restart

Hi, everybody! I migrated all of my mqtt v1 Items to the new mqtt V2.4 Binding. I created the things changed and linked the items. So far everything is working. I have installed the mapdb Binding for persisting the MQTT Items states. Now I have the following problem: When I restart the Openhab2 System, all of the item states are restored via mapdb binding. But the mqtt v2.4 is starting after the mapdb binding. After the mqtt v2.4 Binding is started, all MQTT Item states are set to “UNDEF”. …

It’s all a bit bizarre; setting UNDEF once would be a reasonable thing to do at startup, while awaiting first topic publish. But not continuing to force it.

This looks to be a fix

[SOLVED] MQTT 2.4 binding: Items go to UNDEF after reboot

Hooray! You’re right, the code was already merged, but later than the 2.5M1 was released. I today switched to the SNAPSHOT version 2.5.0~S1549-1 (Build #1549), and there it works: After a restart of OpenHab, the binding collects all topics for all items, and the items get valid states! Also setting of items works now (except for a smaller issue that I reported here). Thank you! Regards, stedon81

If you prefer not to go to snapshot binding version, review why you would want to restore-on-startup Items that you are expecting to update every 10 secs anyway?

[lsiepel]

Thanks for looking into this. All above is done with snapshot # 1650, no luck there. The value is only posted to the topic when it is changed with a max rate of once per 10 secs. Sometimes it can take 2-3 days before a new value is published.

But i think i made some progress!
The binding returns the last value before doing the sendCommand/restoreOnStartUp and that was in the above case always UNDEF. I did that test again with an item that had an actual value from a topic and now that topic value is returned instead of the sendCommand value.

That lead me to think it is in some read-only mode. I read about that in the binding documenation, never realized it would actively prevent you from doing restoreOnStartUp. The channel is read-only if there is no commndTopic according to the docs.

I did test this before, but you have to restart openHAB (wich i didn’t) before adding/removing the commandTopic is effective. Possible due to https://github.com/openhab/openhab2-addons/pull/5868 and found https://github.com/openhab/openhab2-addons/issues/4731 that seems to be the same. I also noticed that after changing the things file, no new published value’s are shown in the UI.

Anyway, i think i have to file a bug/feautre request as i don’t need a commandTopic but i do want to set the value with restoreOnStartup. The sendCommand is not needed when the channel is in read-only mode, postUpdate works fine enough.

[rossko57]

@lsiepel

Anyway, i think i have to file a bug/feautre request

Absolutely. I’m not fully sure I follow where sendCommand comes into it here - but it is legitimate for any Item to be linked to multiple channels/bindings. One bindings “read only” opinion should not block other bindings or services dealing properly with commands or updates. The channel is fine as read only - this should not influence the Item.

I wondered if Autoupdate comes into play here - its “predictions” about the outcome of commands can be influenced/vetoed by bindings. But that should not be involved in restore-on-startup or postUpdate actions.

Nasty trap - I think I was kind characterizing this as “misbehaviour”

[lsiepel]

Issue: [mqtt] restoreOnStartUp not working with read-only channel

Issue: [mqtt] sendCommand to read-only topic silently ignores