System started rule not executing on build #1034

Is there any know issue with the System started rule not executing at all?
I have some logging setup but I cant see it invoking.
It used to work on OH2.0 without problem, also saving a rule file used to invoke system started but it seems not anymore

And just make sure that the
sudo systemctl restart openhab2.service should triger system started rule in OH.2.2 snapshot?

Maciej

This is the first I’ve seen such a problem reported. Are you certain there isn’t a syntax error in your rules file and that the Rule is actually being loaded into OH?

Are there errors in the logs?

The Rule should execute when OH starts and when you change that .rules file.

The rule file does load with warnings. in another post I’m reaserching how to get rid of them,. All other rules are working fine except the System started not executing.

2017-09-18 19:44:01.577 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'default.rules'
2017-09-18 19:44:01.602 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'default.rules' is either empty or cannot be parsed correctly!
2017-09-18 19:44:22.941 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'default.rules', using it anyway:
The use of wildcard imports is deprecated.
The value of the local variable water_setpoint is not used
The value of the local variable temp_deficit_nextroom is not used
The value of the local variable time_morning_status is not used
The value of the local variable time_evening_status is not used
2017-09-18 19:44:22.948 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'

And the system started is nothing special just setting some setpoints

	rule "variable startup"
    when
        System started
    then
	
	logDebug("OTHER","System started initial setpoint startup!" )
	
	if (B_Temperature_Water_Setpoint.state == NULL) postUpdate(B_Temperature_Water_Setpoint,21.0)
	If (B_Temp_Setpoint_Bedroom == NULL) postUpdate(B_Temp_Setpoint_Bedroom, 21)
	if (B_Temp_Setpoint_Office == NULL) postUpdate(B_Temp_Setpoint_Office, 23)
	if (GF_Temp_Setpoint_Living == NULL) postUpdate(GF_Temp_Setpoint_Living, 23)
	if (GF_Temp_Setpoint_Bedroom == NULL) postUpdate(GF_Temp_Setpoint_Bedroom, 21)
	if (B_boiler_heating_mode == NULL) 	postUpdate(B_boiler_heating_mode, 1) 
	if (B_boiler_domestic_water_surplus_setpoint == NULL) postUpdate(B_boiler_domestic_water_surplus_setpoint, 80) 
	if (B_boiler_domestic_water_temp_setpoint == NULL)     postUpdate(B_boiler_domestic_water_temp_setpoint, 40)
	if (B_Power_PV_Sum == NULL) postUpdate(B_Power_PV_Sum, 0)
	if (B_Power_Battery_Current_Sum == NULL) postUpdate(B_Power_Battery_Current_Sum,0)
	
	GF_kitchen_outa0_cup.sendCommand(ON)
	
    end

And you are certain the rule never fires. It isn’t just delayed for a few minutes?

Ok here is the update, the rule does accualy fire up on rules file update, it just quite delayed. but I’m positive it did not start on the reboot that happend at 16:17 as the first occurrence of it being logged is 2h later. I noticed plenty of rules errors due to the NULL values in the variables and that should not be the case since this rule should fire upon startup and fix those.

[23:08:58] pi@rpi-openhab2:~$ uptime
 23:09:00 up  6:52,  2 users,  load average: 0.20, 0.32, 0.32
[23:09:00] pi@rpi-openhab2:~$ tail -n 10000  /var/log/openhab2/openhab.log | grep started
2017-09-10 00:30:10.030 [INFO ] [b.core.service.AbstractActiveService] - SNMP Refresh Service has been started
2017-09-11 20:29:50.324 [INFO ] [b.core.service.AbstractActiveService] - SNMP Refresh Service has been started
2017-09-18 14:31:01.742 [INFO ] [b.core.service.AbstractActiveService] - SNMP Refresh Service has been started
2017-09-18 16:41:31.825 [INFO ] [b.core.service.AbstractActiveService] - Tinkerforge Refresh Service has been started
2017-09-18 16:41:32.315 [INFO ] [b.core.service.AbstractActiveService] - SNMP Refresh Service has been started
2017-09-18 16:50:21.345 [INFO ] [b.core.service.AbstractActiveService] - Tinkerforge Refresh Service has been started
2017-09-18 16:50:22.921 [INFO ] [b.core.service.AbstractActiveService] - SNMP Refresh Service has been started
2017-09-18 18:49:25.277 [DEBUG] [eclipse.smarthome.model.script.OTHER] - System started initial setpoint startup!
2017-09-18 19:44:49.792 [DEBUG] [eclipse.smarthome.model.script.OTHER] - System started initial setpoint startup!
2017-09-18 20:14:39.910 [DEBUG] [eclipse.smarthome.model.script.OTHER] - System started initial setpoint startup!
2017-09-18 20:17:27.499 [DEBUG] [eclipse.smarthome.model.script.OTHER] - System started initial setpoint startup!
2017-09-18 20:19:16.227 [DEBUG] [eclipse.smarthome.model.script.OTHER] - System started initial setpoint startup!
[23:09:09] pi@rpi-openhab2:~$

Also shouldn’t it be that if I have restoreOnStartup in the persistence strategy that I do not get NULL for the crucial variables but it should load previous state?

This is looking more and more like a bug. There was a recent change to ESH to fix a problem with System started rules blocking all other rules from executing. I don’t know if that has made it into the OH baseline yet. I recommend opening an issue on the Eclipse Smarthome github. Be sure to reference this thread in the issue.

If you persistence isn’t working, is misconfigured, or isn’t done initializing your Items before Rules start to execute you will still get NULLs. Do these Rules trigger with changed triggers? That will cause the Rule to fire on the restoreOnStartup itself which could be causing your Rules to fire prematurely.

The persistence is working fine it is just that usually in previous versions it was taking maybe 2 minutes to restore all the values from the DB to its previous states but this time that did not happen. I’ll just reboot the system again in order to see if i can replicate that.

And what I see just after restart is plenty of those errors that looks like an attempt to set the value from the previous state but it fails for some reason.

2017-09-19 00:49:25.810 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2017-09-19 00:49:26.853 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 1.0 (StringType) on item B_Provent_bypass_active of type NumberItem, ignoring it
2017-09-19 00:49:26.950 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 0.0 (StringType) on item G_outdoor_deck of type SwitchItem, ignoring it
2017-09-19 00:49:27.864 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 19.0 (StringType) on item GF_Temp_Setpoint_Living of type NumberItem, ignoring it
2017-09-19 00:49:27.885 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 1294.432 (StringType) on item B_Power_energy_monthly_log of type NumberItem, ignoring it
2017-09-19 00:49:28.261 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 5.0 (StringType) on item B_Provent_gear_selected of type NumberItem, ignoring it
2017-09-19 00:49:28.287 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 0.0 (StringType) on item watering_rel8_3way_valve of type SwitchItem, ignoring it
2017-09-19 00:49:28.654 [ERROR] [pse.smarthome.core.items.GenericItem] - Tried to set invalid state 518.0 (StringType) on item B_Power_AC_Load of type NumberItem, ignoring it

And on the way I noticed one bug in my System started rule. All the IF’s except first were missing .state in the condition check, thats why they were not executing. !!! My bad.

Still I dont know why the state revert fails on the startup. that worked on 2.0 It looks like type mismatch.

What are you running on? Is it under powered like an original RPi it something?

2 minutes for restoreOnStartup, 2 hours to run Staten stated rules. I’m starting to think something statements is going on.

I’m not sure about the state issue. What DB are you taking?

I’m running on RPI3, it was fine before upgrade to 2.2 snaphot. And influxdb. After more of the investigation my main problem is not system started rule as it was having syntax errors (that I now corrected) but restore on startup failing that is causing hell lot of problems with a lot of setpoints in NULL condition.

I actually recommend using Design Pattern: Group Based Persistence and use MapDB for your restoreOnStartup. It is much lighter weight and should help with the problem. I can’t answer why InfluxDB is being slow, maybe you have too many Items to work well with InfluxDB on a RPi.

Yep that is what I will do for the next host, but why the restore is failing on 2.2 while on the 2.0 it was fine. It is not the matter of it being slow. There is some type mismatch logged that was not there before.

Tried to set invalid state 518.0 (StringType) on item B_Power_AC_Load of type NumberItem, ignoring it

I’m not familiar with InfluxDB, but I recently realized errors like you are getting. I use JDBC for persistence with a MariaDB database that had been used since OH1. The error was coming up for me because I needed to do some maintenance to clean up items that had originally been created with the wrong item type and changed. I cleaned it up by turning on DEBUG for persistence, which provided the table name in the error, and changing the data type in the database for the value column in the tables for the items with errors. It looks like your items are Number but the database is storing them as String. Did you originally create the items as String and then change to Number? In MariaDB, you’d change VARCHAR to DOUBLE, and the db will take care of the conversion of the previous data.

I didn’t notice the errors in the log until 2.2.0 snapshot build 1033, but they may have been in there earlier.

So influx is picky and will not allow writing to db a value of a different type that the first write you made. you cant change datatype after it is written, and I had some problems with that before so I make sure I always start numerical data as float.
All my datatype is float, this is one of many that failed with above error.

  B_Power_AC_Load
  fieldKey	fieldType
  value	    "float"

So i do not understand why restore on startup routine is reading them as Strings and fails.