HABApp: items some times None

Apps & Services 3rd Party
1

I’m struggling with items which have sometimes the correct values and sometimes they are None. The behaviour is on HABApp 1.0.5 and openHAB 3.4.0.M3, but it existed at least also in HABApp 1.0.4 and openHAB 3.4.0.M2.
For me it seems to be a matter of the initialization of the items while start up as it is either fine or bad after a restart. It won’t change over the time.

Any idea how to get a stable behavior would be appreciated.

The items are defined as:

Number:Time             num_Heating_Maintenance_Pellets            "Betriebsstunden Pelletslieferung Ist [%d h]"      <none>        (gHeating, gRestoreOnStartup)
Number:Volume           num_Softener_WaterCounter_PreviousDay      "Wasserzähler [%d l]"                              <water>       (gSoftener, gRestoreOnStartup, gLog, gDel1M)    ["Point"]

Test code in Jython:

    PelletMaintItem = ir.getItem("num_Heating_Maintenance_Pellets")
    LogAction.logInfo(LOGGER, "{}: {}".format(PelletMaintItem.name, PelletMaintItem.state))

    WaterCounterPrevItem = ir.getItem("num_Softener_WaterCounter_PreviousDay")
    LogAction.logInfo(LOGGER, "{}: {}".format(WaterCounterPrevItem.name, WaterCounterPrevItem.state))

and test code in Python:

        PelletMaintItem = NumberItem.get_item("num_Heating_Maintenance_Pellets")
        self.log.info(LOGGER + "{}: {}".format(PelletMaintItem.name, PelletMaintItem.value))

        WaterCounterPrevItem = NumberItem.get_item("num_Softener_WaterCounter_PreviousDay")
        self.log.info(LOGGER + "{}: {}".format(WaterCounterPrevItem.name, WaterCounterPrevItem.value))

The result:

==> /var/log/openhab/HABApp.log <==
2022-10-29 17:45:40.816 [INFO ] [HABApp          ] - TestEnvironment.TestRuleContent num_Heating_Maintenance_Pellets: None
2022-10-29 17:45:40.818 [INFO ] [HABApp          ] - TestEnvironment.TestRuleContent num_Softener_WaterCounter_PreviousDay: 374027.0

==> /var/log/openhab/openhab.log <==
2022-10-29 17:45:41.316 [INFO ] [nhab.core.model.script.test.TestRule] - num_Heating_Maintenance_Pellets: 14382 h
2022-10-29 17:45:41.319 [INFO ] [nhab.core.model.script.test.TestRule] - num_Softener_WaterCounter_PreviousDay: 374027 l
2

The HABApp rule runs half a second earlier.
Could it be that during this time the restore from mapdb happens?
Could you search for both the items in the HABApp_events.log (from 17:45:40 - 17:45:45) and post it here?

3

The reason why there is a delay between both timestamps is, because I triggered both test programs manually.
The values will change rarely (num_Heating_Maintenance_Pellets, manually triggered, once in two years; num_Softener_WaterCounter_PreviousDay, once a day, close to midnight)

The last start of the system was a couple of days ago, so a restore via mapdb shouldn’t take place.

[2022-10-29 17:45:39,900] [          HABApp.EventBus]     INFO | num_Server_Storage_AvailablePercent: <ItemStateEvent name: num_Server_Storage_AvailablePercent, value: 93.1>
[2022-10-29 17:45:40,811] [          HABApp.EventBus]     INFO | swi_System_HABAppTest: <ItemCommandEvent name: swi_System_HABAppTest, value: ON>
[2022-10-29 17:45:40,823] [          HABApp.EventBus]     INFO | swi_System_HABAppTest: <ItemStateEvent name: swi_System_HABAppTest, value: ON>
[2022-10-29 17:45:40,832] [          HABApp.EventBus]     INFO | swi_System_HABAppTest: <ItemStateChangedEvent name: swi_System_HABAppTest, value: ON, old_value: OFF>
[2022-10-29 17:45:40,847] [          HABApp.EventBus]     INFO | swi_System_HABAppTest: <ItemCommandEvent name: swi_System_HABAppTest, value: OFF>
[2022-10-29 17:45:40,850] [          HABApp.EventBus]     INFO | swi_System_HABAppTest: <ItemStateEvent name: swi_System_HABAppTest, value: OFF>
[2022-10-29 17:45:40,853] [          HABApp.EventBus]     INFO | swi_System_HABAppTest: <ItemStateChangedEvent name: swi_System_HABAppTest, value: OFF, old_value: ON>
[2022-10-29 17:45:41,322] [          HABApp.EventBus]     INFO |      swi_System_Test: <ItemStateEvent name: swi_System_Test, value: OFF>
[2022-10-29 17:45:41,326] [          HABApp.EventBus]     INFO |      swi_System_Test: <ItemStateChangedEvent name: swi_System_Test, value: OFF, old_value: ON>
[2022-10-29 17:45:42,044] [          HABApp.EventBus]     INFO | swi_Network_ShellyEM2_Online: <ItemStateEvent name: swi_Network_ShellyEM2_Online, value: OFF>
[2022-10-29 17:45:42,635] [          HABApp.EventBus]     INFO | dtm_Astro_Rise_Start: <ItemStateEvent name: dtm_Astro_Rise_Start, value: 2022-10-29 07:58:00>
[2022-10-29 17:45:42,639] [          HABApp.EventBus]     INFO |   dtm_Astro_Rise_End: <ItemStateEvent name: dtm_Astro_Rise_End, value: 2022-10-29 08:01:00>
[2022-10-29 17:45:42,643] [          HABApp.EventBus]     INFO |  dtm_Astro_Set_Start: <ItemStateEvent name: dtm_Astro_Set_Start, value: 2022-10-29 18:02:00>
[2022-10-29 17:45:42,646] [          HABApp.EventBus]     INFO |    dtm_Astro_Set_End: <ItemStateEvent name: dtm_Astro_Set_End, value: 2022-10-29 18:05:00>
[2022-10-29 17:45:42,649] [          HABApp.EventBus]     INFO | dtm_Astro_CivilDawn_Start: <ItemStateEvent name: dtm_Astro_CivilDawn_Start, value: 2022-10-29 07:26:00>
[2022-10-29 17:45:42,653] [          HABApp.EventBus]     INFO | dtm_Astro_CivilDawn_End: <ItemStateEvent name: dtm_Astro_CivilDawn_End, value: 2022-10-29 07:58:00>
[2022-10-29 17:45:42,654] [          HABApp.EventBus]     INFO | dtm_Astro_CivilDusk_Start: <ItemStateEvent name: dtm_Astro_CivilDusk_Start, value: 2022-10-29 18:05:00>
[2022-10-29 17:45:42,657] [          HABApp.EventBus]     INFO | dtm_Astro_CivilDusk_End: <ItemStateEvent name: dtm_Astro_CivilDusk_End, value: 2022-10-29 18:38:00>
[2022-10-29 17:45:42,667] [          HABApp.EventBus]     INFO | num_Astro_SunPos_Horizontal: <ItemStateEvent name: num_Astro_SunPos_Horizontal, value: 247.08113019600614 °>
[2022-10-29 17:45:42,676] [          HABApp.EventBus]     INFO | num_Astro_SunPos_Vertical: <ItemStateEvent name: num_Astro_SunPos_Vertical, value: 2.0852916255597878 °>
[2022-10-29 17:45:42,679] [          HABApp.EventBus]     INFO | num_Astro_SunPos_Horizontal: <ItemStateChangedEvent name: num_Astro_SunPos_Horizontal, value: 247.08113019600614 °, old_value: 246.13722652498802 °>
[2022-10-29 17:45:42,682] [          HABApp.EventBus]     INFO | num_Astro_SunPos_Vertical: <ItemStateChangedEvent name: num_Astro_SunPos_Vertical, value: 2.0852916255597878 °, old_value: 2.8525500106635806 °>
[2022-10-29 17:45:43,333] [          HABApp.EventBus]     INFO | dtm_Astro_MoonRise_Start: <ItemStateEvent name: dtm_Astro_MoonRise_Start, value: 2022-10-29 13:02:00>
[2022-10-29 17:45:43,343] [          HABApp.EventBus]     INFO | dtm_Astro_MoonSet_End: <ItemStateEvent name: dtm_Astro_MoonSet_End, value: 2022-10-29 20:37:00>
[2022-10-29 17:45:43,349] [          HABApp.EventBus]     INFO | num_Astro_MoonPhase_Illum: <ItemStateEvent name: num_Astro_MoonPhase_Illum, value: 21.5643322497035 %>
[2022-10-29 17:45:43,351] [          HABApp.EventBus]     INFO | str_Astro_MoonPhase_Name: <ItemStateEvent name: str_Astro_MoonPhase_Name, value: WAXING_CRESCENT>
[2022-10-29 17:45:43,352] [          HABApp.EventBus]     INFO | num_Astro_MoonPhase_Illum: <ItemStateChangedEvent name: num_Astro_MoonPhase_Illum, value: 21.5643322497035 %, old_value: 21.531001260939693 %>
[2022-10-29 17:45:44,444] [          HABApp.EventBus]     INFO |          HABApp_Ping: <ItemStateEvent name: HABApp_Ping, value: 14.5>
[2022-10-29 17:45:44,448] [          HABApp.EventBus]     INFO |          HABApp_Ping: <ItemStateChangedEvent name: HABApp_Ping, value: 14.5, old_value: 22.5>
[2022-10-29 17:45:46,431] [          HABApp.EventBus]     INFO |     dtm_Weather_Time: <ItemStateEvent name: dtm_Weather_Time, value: 2022-10-29 19:00:00>
4

Okay - I was under the impression the issue is happening during startup.
This seems really strange and we might do some digging.

Could you create a new HABApp installation on your main machine for this?
Set the listen_only flag in the config so you don’t accidentally modify things from your openhab instance and set openHAB host, pw, etc.
Set the logging level to debug and create just one rule which will output the items:

'{}'.format(NumberItem.get_item("PelletMaintItem"))
'{}'.format(NumberItem.get_item("num_Softener_WaterCounter_PreviousDay"))

Then start HABApp locally and observe the output of the event log and the logfile.
Please also paste the response from the API Explorer for both items (GET /items/{itemname})

5

I tried to reproduce, but after restart of HABApp, the behavior didn’t come up again, neither with the reduced configuration or with the production config.

Here is a extract of several restarts

2022-10-31 14:31:44.016 [INFO ] [HABApp          ] - TestEnvironment.TestRuleContent num_Heating_Maintenance_Pellets: None
2022-10-31 14:31:44.019 [INFO ] [HABApp          ] - TestEnvironment.TestRuleContent num_Softener_WaterCounter_PreviousDay: 374494.0

- restart of HABApp with regular content - 
2022-10-31 14:54:37.037 [INFO ] [HABApp          ] - <NumberItem name: num_Heating_Maintenance_Pellets, value: 14382, last_change: 2022-10-31T14:54:31.777894, last_update: 2022-10-31T14:54:31.777894>
2022-10-31 14:54:37.043 [INFO ] [HABApp          ] - <NumberItem name: num_Softener_WaterCounter_PreviousDay, value: 374494, last_change: 2022-10-31T14:54:31.748875, last_update: 2022-10-31T14:54:31.748875>

2022-10-31 14:57:20.802 [INFO ] [HABApp          ] - TestEnvironment.TestRuleContent num_Heating_Maintenance_Pellets: 14382
2022-10-31 14:57:20.805 [INFO ] [HABApp          ] - TestEnvironment.TestRuleContent num_Softener_WaterCounter_PreviousDay: 374494

- restart of HABApp with reduced content - 
2022-10-31 17:32:48.514 [INFO ] [HABApp                              ] - <NumberItem name: num_Heating_Maintenance_Pellets, value: 14382, last_change: 2022-10-31T17:32:44.780254, last_update: 2022-10-31T17:32:44.780254>
2022-10-31 17:32:48.515 [INFO ] [HABApp                              ] - <NumberItem name: num_Softener_WaterCounter_PreviousDay, value: 371080, last_change: 2022-10-31T17:32:44.617914, last_update: 2022-10-31T17:32:44.617914>

But what’s visible, is that the data type of the “working” item has changed from float to int.
All I’ve changed was to restart HABApp (with both configurations).

It’s a bit unsatisfying as it is unclear if and when it will happen again.

6

Hi Sebastian,
I have seen an interesting behavior:

2022-11-04 00:01:15.155 [INFO ] [HABApp          ] - Heating_Maintenance.ForecastPellets <NumberItem name: num_Heating_Maintenance_Pellets, value: None, last_change: 2022-11-02T18:49:50.732198, last_update: 2022-11-02T18:49:50.732198>

The time stamp is from the early startup of HABApp.

[2022-11-02 18:48:41,379] [          HABApp.EventBus]     INFO |         HABApp.Files: <RequestFileLoadEvent filename: params/credentials.yml>
[2022-11-02 18:49:50,971] [          HABApp.EventBus]     INFO |          HABApp_Ping: <ItemStateEvent name: HABApp_Ping, value: None>
[2022-11-02 18:49:55,690] [          HABApp.EventBus]     INFO |         HABApp.Files: <RequestFileLoadEvent filename: rules/TestEnvironment.py>

but the event log shows an update which is later than the timestamp of the update of the item:

grep "num_Heating_Maintenance_Pellets:" /var/log/openhab/HABApp_events.log* 
/var/log/openhab/HABApp_events.log.2:[2022-11-02 18:50:31,004] [          HABApp.EventBus]     INFO | num_Heating_Maintenance_Pellets: <ItemStateChangedEvent name: num_Heating_Maintenance_Pellets, value: 14382 h, old_value: None>
/var/log/openhab/HABApp_events.log.4:[2022-11-01 14:44:18,719] [          HABApp.EventBus]     INFO | num_Heating_Maintenance_Pellets: <ItemStateChangedEvent name: num_Heating_Maintenance_Pellets, value: 14382 h, old_value: None>

http://192.168.43.7:8080/rest/items/num_Heating_Maintenance_Pellets?recursive=true:
{
  "link": "http://192.168.43.7:8080/rest/items/num_Heating_Maintenance_Pellets",
  "state": "14382 h",
  "stateDescription": {
    "pattern": "%d h",
    "readOnly": false,
    "options": []
  },
  "editable": false,
  "type": "Number:Time",
  "name": "num_Heating_Maintenance_Pellets",
  "label": "Betriebsstunden Pelletslieferung Ist",
  "category": "none",
  "tags": [],
  "groupNames": [
    "gHeating",
    "gRestoreOnStartup"
  ]
}
7

That’s really strange. The event log indicates that the item was also NULL / None on the openHAB side (value of old_value). So I am not sure this is a sync issue. Do you see the corresponding events in the events.log?

8

The dates we see here are also from startup (restore on startup) of the system. They match with the ones from HABApp_events.

grep "num_Heating_Maintenance_Pellets'" /var/log/openhab/events.log /var/log/openhab/History/events.log.*
/var/log/openhab/History/events.log.3:2022-11-02 18:50:31.001 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'num_Heating_Maintenance_Pellets' changed from NULL to 14382 h
/var/log/openhab/History/events.log.4:2022-11-01 14:44:18.713 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'num_Heating_Maintenance_Pellets' changed from NULL to 14382 h
9

Do I see it correct that you do not get an ItemStateEvent for the item in the HABApp logs?

10

Yes, that’s correct. No ItemStateEvent, only ItemStateChangedEvent.

11

That’s the reason why the item state does not match because HABApp sets the item state on the ItemStateEvent.
This might be an openhab bug. A proper fix is already in the making but will probably not come with 3.4

Do you observe this behavior only when you restart you openhab machine?

12

I did a test and modified the Item num_Heating_Maintenance_Pellets by jython script. The change of the value was than also visible from HABApp.

I also compared the values of all items available in HABApp and available via REST interface. The result is not 100% clear due to many false positives, but it seems that there are many items targeted by that problem and they seem all to be changed rarely. I assume that it is a problem with the RestoreOnStartup.
There are NumberItems with and without UoM, SwitchItems, DatetimeItems, … It seems to be a general problem.

Your statement about the possible openHAB bug is good and bad. Good that there is already something identified, which could fix it, bad that it might take months to get it solved. So the system would be partly unreliable for that time.
The discussion behind the provided link, I haven’t fully understood. But it looks like that there is no real workaround?

13

In the config.yml you can try to set openhab → general → min_start_level to 100.
That should effectively solve your issue.
This works only for clean installations where all things initialize properly, that’s why it’s not 100 by default.

14

@usambara
Have you tried it?

15

Yes, I tried it and with HABApp 1.0.5 and OpenHAB 3.4.0.M3 it worked as expected.
No uninitalized items anymore!

No, with HABApp 1.0.6 and OpenHAB 3.4.0.M4 it does not work as expected.
With min_start_level 100 it waits forever, although in the OH console the start level is
specified as 100.

> system:start-level                                                               
Level 100

Same happens with min_start_level 80. Only with min_start_level 70 it starts correctly.
A behaviour I’ve seen a couple of weeks before when I’ve played with the different start
levels (don’t know anymore with which versions).

So I wrote a little jython rule as a workaround to restart HABApp. That helps but is not
nice.

16

This is not a HABApp issue but rather openhab is not starting properly.
You can double check through API Explorer → systeminfo → startLevel.

Typically this is thing that is still pending or a thing where the configuration is not correct.
If console status and rest endpoint don’t match it’s most likely a bug.

17

Yes, i’ve already identified the systeminfo binding as responsible . The discussion ist already opened.