search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
923 stars 424 forks source link

[rule] StartupTrigger only works when setting to 50 or 70 start level 80 or 100 seems to be never reached #1967

Closed LukasA83 closed 3 years ago

LukasA83 commented 3 years ago

I'm using openhab 3 snaphost, build 2090 on raspi 4 docker environment. I'm struggling to get the new startuptrigger to work. I realized, by putting the StartLevelService log level to DEBUG, that my system shows at latest "Reached start level 70", but never 80 or 100 and therefore my startuptrigger at 80 or 100 is not fired for the rule. The rule has been defined in WebUI. Tried Blocky and ruledsl format with the same result.

Log:

2020-12-19 21:51:10.565 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2020-12-19 21:51:10.640 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ''.
2020-12-19 21:51:10.649 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2020-12-19 21:51:10.661 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2020-12-19 21:51:11.569 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 10
2020-12-19 21:51:27.689 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2020-12-19 21:51:28.764 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2020-12-19 21:51:29.586 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Home.sitemap'
2020-12-19 21:51:40.517 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-19 21:51:41.496 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/BrunnenpumpeTimer.js'
2020-12-19 21:51:41.515 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 20
2020-12-19 21:51:46.518 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 30
2020-12-19 21:51:46.519 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2020-12-19 21:51:46.527 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 40
2020-12-19 21:51:48.332 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 50880
2020-12-19 21:51:50.957 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:weekdays every 300 seconds
2020-12-19 21:51:51.518 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 50
2020-12-19 21:51:51.524 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 70
2020-12-19 21:51:52.664 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'openweathermap:weather-and-forecast:wetterHerne:local' to inbox.
2020-12-19 21:51:52.731 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'openweathermap:uvindex:wetterHerne:local' to inbox.
2020-12-19 21:51:52.877 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'openweathermap:onecall-history:wetterHerne:local' to inbox.
2020-12-19 21:51:55.830 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mosquitto-server' with clientid openhabClientProd
2020-12-19 21:51:56.414 [WARN ] [org.openhab.rule.b0c29be2a7         ] - startup2
2020-12-19 21:51:57.466 [INFO ] [ding.smartmeter.internal.MeterDevice] - Opening connection to smartmeter:meter:hausStromzaehler
2020-12-19 21:51:59.699 [INFO ] [ding.smartmeter.internal.MeterDevice] - Read out following values: Device: smartmeter:meter:hausStromzaehler
Obis: 1-0:61.7.0*255 MeterValue [obis=1-0:61.7.0*255, value=000353.70, unit=W]
2020-12-19 21:52:01.037 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/Garage.js'
2020-12-19 21:52:09.545 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/SetLcn.js'
2020-12-19 21:52:13.673 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/HeizungsSteuerungRules.js'
2020-12-19 21:52:20.030 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/VirtualSensors.js'
2020-12-19 21:52:22.284 [WARN ] [ding.lcn.internal.connection.ModInfo] - S000M092: Failed to receive status message: Output 1: Failed finally after 3 tries
2020-12-19 21:52:22.313 [WARN ] [ding.lcn.internal.connection.ModInfo] - S000M051: Failed to receive status message: Output 1: Failed finally after 3 tries
2020-12-19 21:52:24.333 [WARN ] [ding.lcn.internal.connection.ModInfo] - S000M031: Failed to receive status message: Output 2: Failed finally after 3 tries
2020-12-19 21:52:25.329 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/JalousienTimerRules.js'
2020-12-19 21:52:25.380 [WARN ] [ding.lcn.internal.connection.ModInfo] - S000M050: Failed to receive status message: VARIABLE 2: Failed finally after 3 tries
2020-12-19 21:52:26.456 [WARN ] [ding.lcn.internal.connection.ModInfo] - S000M080: Failed to receive status message: VARIABLE 3: Failed finally after 3 tries
2020-12-19 21:52:31.612 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/SetHolidayAndWeekendRules.js'
2020-12-19 21:52:35.086 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/AussenlichtTimerRules.js'
2020-12-19 21:52:38.749 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/TimerTest.js'
2020-12-19 21:52:41.432 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/BabykameraRules.js'
2020-12-19 21:52:44.832 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/BenachrichtigungenRules.js'
2020-12-19 21:52:52.926 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/WarmwasserBereitungs.js'
2020-12-19 21:52:56.681 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/proxyRules.js'
2020-12-19 21:53:04.992 [INFO ] [ab.core.service.AbstractWatchService] - Loading script '/openhab/conf/automation/jsr223/javascript/personal/TimetableHelperRules.js'
kaikreuzer commented 3 years ago

Start level 80 means that all your things are initialized. I assume that you have some things for which the binding might be missing or their handlers cannot be found for other reasons. Have you checked that?

LukasA83 commented 3 years ago

I had two disabled Things, because the loan mower is taking some winter rest... after enabling it has been triggered. Is that the desired behaviour that intentionally disabled things are preventing level 80/100?

kaikreuzer commented 3 years ago

No, this is clearly not intended. So thanks for your report and your analysis - I have created #1968 as a fix.

lolodomo commented 3 years ago

Kai, this is a current scenario while you uninstall temporarily a binding, keeping the things. Does it mean that OH will not start if you don't have 1 binding for each thing? Maybe you could consider a timeout, long enough.

lolodomo commented 3 years ago

And you have the standard user that will uninstall definitely a binding without even thinking about the things he created.

kaikreuzer commented 3 years ago

If you deinstall stuff and do not deactivate the according things, you seem to be fine to not reach the "all thing initialized" start level. There is no reason to define any rules with startlevels higher 70 and the system will work just fine - it itself does nowhere depend on any of the higher start levels.

lolodomo commented 3 years ago

Ok, thank you for the clarification.