System Started

Olymp · November 1, 2017, 1:34am

Platform information:
- Hardware: Hyper-V
- OS: Ubuntu 16.04
- Java Runtime Environment: 1.8.0_151-b12
- openHAB version: openHAB 2.2.0 Build #1072

I have a rule:

rule "System started"
when
    System started
then
    logInfo("RULE.SystemStarted","<-- System Started")
end

Why when starting OpenHAB, it works several times?

2017-11-01 08:59:02.316 [INFO ] [egram.internal.TelegramActionService] - Bot bot1 loaded from config file
2017-11-01 08:59:02.789 [INFO ] [voicerss.internal.VoiceRSSTTSService] - Using VoiceRSS cache folder /var/lib/openhab2/voicerss/cache
2017-11-01 08:59:10.401 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = b5633553-b5ca-442e-ab89-0a9004b1719e, base URL = http://localhost:8080)
2017-11-01 08:59:18.888 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'connectsdk.items'
2017-11-01 08:59:19.054 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'co2.items'
2017-11-01 08:59:19.106 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'gateway.items'
2017-11-01 08:59:19.182 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'router.items'
2017-11-01 08:59:19.236 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'bell.items'
2017-11-01 08:59:19.334 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2017-11-01 08:59:19.606 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hiaomi.items'
2017-11-01 08:59:19.879 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.items'
2017-11-01 08:59:19.989 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'climate.items'
2017-11-01 08:59:20.100 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'monitor.items'
2017-11-01 08:59:20.120 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'audio.items'
2017-11-01 08:59:20.160 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'main.items'
2017-11-01 08:59:20.222 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'milight.items'
2017-11-01 08:59:20.414 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff.items'
2017-11-01 08:59:21.561 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2017-11-01 08:59:32.753 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff.rules'
2017-11-01 08:59:33.319 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'audio.rules'
2017-11-01 08:59:34.074 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'group.rules'
2017-11-01 08:59:35.697 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'climate.rules'
2017-11-01 08:59:40.404 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hiaomi.rules'
2017-11-01 08:59:40.862 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.rules'
2017-11-01 08:59:40.926 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lightbox.rules'
2017-11-01 08:59:41.463 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'co2.rules'
2017-11-01 08:59:41.772 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.rules'
2017-11-01 08:59:42.356 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'update.rules'
2017-11-01 08:59:42.502 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'start.rules'
2017-11-01 08:59:43.463 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'garage.sitemap'
2017-11-01 08:59:43.529 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telefon.sitemap'
2017-11-01 08:59:44.303 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'milight.things'
2017-11-01 08:59:44.589 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.things'
2017-11-01 08:59:44.882 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2017-11-01 08:59:45.579 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2017-11-01 08:59:46.328 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2017-11-01 08:59:46.362 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 60 seconds
2017-11-01 08:59:48.506 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.215.111:8080
2017-11-01 08:59:48.508 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.215.111:8443
2017-11-01 08:59:48.849 [INFO ] [thome.model.lsp.internal.ModelServer] - Language Server started on port 5007
2017-11-01 08:59:49.012 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started
2017-11-01 08:59:49.764 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-11-01 08:59:50.101 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-11-01 08:59:51.759 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been started
2017-11-01 08:59:52.052 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-11-01 08:59:52.061 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqtt-loc'
2017-11-01 08:59:53.027 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqtt-net'
2017-11-01 08:59:53.348 [INFO ] [e.smarthome.model.script.RULE.CO2Box] - <-- CO2 - 581.68
2017-11-01 08:59:53.356 [INFO ] [.smarthome.model.script.RULE.CO2Room] - <-- CO2 - 500.33
2017-11-01 08:59:55.271 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-11-01 09:00:03.469 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started
2017-11-01 09:00:10.355 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started

rlkoshak · November 1, 2017, 6:41pm

I do not know the answer. I don’t know that there is a guarantee anywhere that says it should only be triggered once but as a user I certainly expect that the rule would only be triggered once.

Does it trigger twice when you change the .rules file that contains that rule?

Olymp · November 2, 2017, 1:53am

No. Here are three attempts:

2017-11-02 09:47:41.170 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'start.rules'
2017-11-02 09:47:46.255 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started
2017-11-02 09:49:12.782 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'start.rules'
2017-11-02 09:49:17.909 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started
2017-11-02 09:50:52.026 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'start.rules'
2017-11-02 09:50:57.136 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started

mhilbush · November 2, 2017, 11:18am

I see this all the time with my System started rules at startup, and also when I change something in an .items file. The rules run and fail because all items are not loaded yet. This happens 2 or 3 times until the rules run successfully.

There are numerous reports of this, such as here.

Hoping that this resolves the issue.

Olymp · November 3, 2017, 1:53am

Thank you all! Now I know that it’s not just me. I’ll have to abandon the rules when running OpenHAB

rlkoshak · November 3, 2017, 3:25pm

Not necessarily. It depends on what you need to do in that System started rule. There are ways to make sure it only runs once even though it is triggered multiple times and other ways to make it so it doesn’t matter that it runs multiple times.