Number value NULL after OH update/restart

[grzegorz914]

Hi,

I have observed that after every update/restart OH the Number value are not updated on first run, the values remain NULL as long as the value not changed on S7 or I’m restart the thing manually from UI.
It looks like the values are not updated on first start.

[docbender]

Looks like this is related to #38 issue. Values updated during startup are not transferred to the OH core. Maybe it is system configuration related. Is your OH PC slow or high performance?

[grzegorz914]

Its not related to #38, the Simatic Versinon is never updated. All other internal channel like PDU, Areas, Request, Bytes are updated correct.
The system is Bulseye on RPI4 4GB.
May be the Simatic Bindig is loading before OH is ready to update this value.

[grzegorz914]

Sorry, you are right is related to #38, after restart Simatic:bridge the value is updated.

[grzegorz914]

I think the all values need to be forced update on first run in OnChange mode.
The Version is never updated because is a static string and not changed after binding start. The other values after some time changed on S7 and are also updated in OH.

[grzegorz914]

@docbender
thanks for try to fix this but this PR with delay start does not fix the issue, If the thing is OnChange mode the value are not updated on first start and remain NULL as long as the values not changed on PLC side.
I think you need force push all actual PLC values to the core after Simatic binding initialization complete (only on first cycle), next watching for value changed.

Thanks

[docbender]

What about bridge item values? For example binding version? It is null too?

What about your hardware? Is your hardware slow?

I would need a log dump in OnScan mode to see when the data starts to transfer after PLC is connected. I'm interested in "openhab.event.ItemStateChangedEvent", where you can see value change from NULL.

[grzegorz914]

Bridge same behaviour the version still NULL as long as I pause/start bridge.
My hardware is Raspberry Pi 4B+ 4GB, I think is not slow, CPU usage is 19%

[docbender]

Please collect log after OH restart with org.openhab.binding.simatic set to DEBUG level and openhab.event.ItemStateChangedEvent set to INFO level.

[grzegorz914]

Here the logs, interesant is that the channels with NULL value does not exist in the logs.
events.log.zip
openhab.log.zip

after bridge restart:

2022-03-09 12:09:26.646 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:generic_device:635e89005f' changed from ONLINE to UNINITIALIZED
2022-03-09 12:09:26.667 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:generic_device:635e89005f' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2022-03-09 12:09:26.672 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:bridge:b5f2a79e5c' changed from ONLINE to UNINITIALIZED
2022-03-09 12:09:26.681 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:bridge:b5f2a79e5c' changed from UNINITIALIZED to OFFLINE (COMMUNICATION_ERROR)
2022-03-09 12:09:26.689 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:bridge:b5f2a79e5c' changed from OFFLINE (COMMUNICATION_ERROR) to UNINITIALIZED (DISABLED)
2022-03-09 12:09:26.690 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:generic_device:635e89005f' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-03-09 12:09:28.195 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:bridge:b5f2a79e5c' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2022-03-09 12:09:28.207 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SimaticPLC_Version' changed from NULL to 3.2.1

after generic device restart:
`

2022-03-09 12:09:28.286 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:generic_device:635e89005f' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-03-09 12:09:28.918 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:generic_device:635e89005f' changed from INITIALIZING to OFFLINE (COMMUNICATION_ERROR)
2022-03-09 12:09:34.306 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:bridge:b5f2a79e5c' changed from UNKNOWN to ONLINE
2022-03-09 12:09:34.308 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'simatic:generic_device:635e89005f' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2022-03-09 12:09:34.806 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PiecSpalinyTemp' changed from 58.58 °C to 56.67 °C
2022-03-09 12:09:34.823 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_OczkoPompaCzasOdliczanie' changed from 93142 to 84534
2022-03-09 12:09:34.923 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ZaworyCoStany' changed from NULL to Eco / Zamknięte
2022-03-09 12:09:35.001 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BramaStanZadany' changed from NULL to CLOSED
2022-03-09 12:09:35.024 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BramaStan' changed from NULL to CLOSED
2022-03-09 12:09:35.101 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PiecPompaCoStany' changed from NULL to Auto / Postój
2022-03-09 12:09:35.203 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_CwuPompaCyrkStany' changed from NULL to Auto / Postój
2022-03-09 12:09:35.270 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterKotlowniaRoleta1Stany' changed from NULL to STOPPED
2022-03-09 12:09:35.274 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterKotlowniaRoleta2Stany' changed from NULL to STOPPED
2022-03-09 12:09:35.275 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterPokojRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.276 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterKlatkaSchodowaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.278 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterSalonRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.279 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterJadalniaRoleta1Stany' changed from NULL to STOPPED
2022-03-09 12:09:35.280 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterJadalniaRoleta2Stany' changed from NULL to STOPPED
2022-03-09 12:09:35.283 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterJadalniaRoleta3Stany' changed from NULL to STOPPED
2022-03-09 12:09:35.289 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterKuchniaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.291 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_ParterLazienkaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.294 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PietroGarderobaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.294 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PietroBiuroRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.295 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PietroKamilaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.298 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PietroSypialniaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.299 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PietroLazienkaRoletaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.299 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_TarasMarkizaStany' changed from NULL to STOPPED
2022-03-09 12:09:35.304 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PrzedpokojMalyTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.361 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PrzedpokojMalyZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.429 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PrzedpokojMalyTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.434 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PrzedpokojDuzyTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.442 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PrzedpokojDuzyTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.447 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PrzedpokojDuzyZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.451 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PokojTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.460 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_PokojZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.462 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PokojTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.464 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SalonTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.467 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SalonTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.473 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_SalonZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.481 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'JadalniaTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.484 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'JadalniaTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.488 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_JadalniaZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.495 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KuchniaTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.498 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_KuchniaZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.506 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KuchniaTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.509 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_LazienkaParterZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.512 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LazienkaParterTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.520 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LazienkaParterTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.525 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'GarderobaTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.526 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_GarderobaZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.533 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'GarderobaTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.538 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BiuroTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.574 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BiuroTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.586 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KamilaTermTrybAktualnySlowo' changed from NULL to Chłodzenie
2022-03-09 12:09:35.586 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KamilaTermTrybZadanySlowo' changed from NULL to Auto
2022-03-09 12:09:35.588 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_KamilaZaworStany' changed from NULL to Eco / Zamknięty
2022-03-09 12:09:35.856 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SimaticPLC_Requests' changed from 13 to 1
2022-03-09 12:09:35.857 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SimaticPLC_Bytess' changed from 1355 to 1

[docbender]

Important records from your logs:

2022-03-09 12:01:06.388 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080
2022-03-09 12:01:33.323 [INFO ] [ternal.handler.SimaticHandlerFactory] - Simatic binding (v.3.2.1) has been started.
2022-03-09 12:02:19.832 [DEBUG] [ternal.handler.SimaticGenericHandler] - Simatic S7-1200 - initialize. Channels count=534
2022-03-09 12:02:24.616 [DEBUG] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - open() - connecting...
---- first read from PLC
2022-03-09 12:02:26.132 [DEBUG] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - Reading finished in 16ms. Area=M2-M219
2022-03-09 12:02:32.436 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
---- first value PLC changed
2022-03-09 12:02:33.153 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PLC_OczkoPompaCzasOdliczanie' changed from 507147 to 506152
2022-03-09 12:02:46.798 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 1a790de9-cd89-42a5-b3cf-f6fb306e9bd1, base URL = http://localhost:8080)
2022-03-09 12:02:55.215 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
---- OH start finished

OH start is really slow. There is almost a minute between Simatic binding started and the Rule engine started. 12 seconds between PLC bridge initialization and Rule engine started. After the Rule engine starts, the OH event bus is usually ready (item values are updated).

At the moment I don't know of a solution other than increasing the binding initialization time.

[docbender]

I was thinking about the possibility to change binding start-level value. It is set to 80 for all bundles as default. You can check it in karaf console with this command:

bundle:list

All bundles start in parallel. I tested starting with a higher value and it seems that this should be the solution for your problem.

Try to increase binding start-level from karaf console with this command:

bundle:start-level org.openhab.binding.simatic 81

[grzegorz914]

Thanks for the investigation but this doesn’t solve the problem.
May be use timeout and refresh and push all values to the oh.core (only one time) after initialization complete?

[grzegorz914]

Opps the bundle:start-level was reset to 80 after restart, so I can not test it in this way.

[docbender]

Addon loaded from OH addon folder is started first as you can see in console bundle:list command. This can be only affected by increase value of start level. This behavior does not occur in a standard binding installation.

I added binding into marketplace and if it is installed from here, binding is launched last.

To install binding from marketplace I recommend:

• stop OH
• remove binding from addon folder
• run openhab-cli clean-cache command
• start OH
• install binding again from marketplace

[grzegorz914]

Hi,
I can confirm that after restart OH or cycle power off/on the complete system the values are now updated correct but
the problem stil exist after OH update to new build and first start OH service. After restart services again the values are updated correct.

[docbender]

This whole is OH core behaviour. Obviously a lot happens in OH after an update, like creating a new cache, resulting in further delays in system startup.
There is no other option besides the ones I already mentioned. At least I don't know of any.