System runlevel 100 rule triggered twice during OH startup

[dilyanpalauzov]

I have this rule

rule "System started"
when
    System reached start level 100
then
  logDebug('l', 'System reached start level 100')
end

I stop OpenHAB 4.2.2, then start openhab. I expect, that OpenHAB will eventually print "System reached start level 100” once.

But usually it prints it twice with a delay of approximately 30 seconds.

[Laith-Budairi]

I tried reproducing it, but nothing shows up in the log. Do you have log level DEBUG enabled?

[dilyanpalauzov]

Probably I have DEBUG enabled. How do I see what I have enabled? You could use logError instead.

logError and setting the log level are mentioned also at https://www.openhab.org/docs/configuration/rules-dsl.html#logging . Unfortunately in openhab-cli I see a command to change the log level, but not a command to see the current log level:

openhab> log<TAB to show the completions>
log log:log                                                  (Log a message)
log:clear                                                (Clear log entries)
log:display                                           (Displays log entries)
log:exception-display    (Displays the last occurred exception from the log)
log:get                                  (Shows the currently set log level)
log:list
log:load-test                                                (Load test log)
log:set                                                 (Sets the log level)
log:tail (Continuously display log entries. Use ctrl-c to quit this command)
logout                              (Disconnects shell from current session)

[Laith-Budairi]

Probably I have DEBUG enabled. How do I see what I have enabled? You could use logError instead.

logError and setting the log level are mentioned also at https://www.openhab.org/docs/configuration/rules-dsl.html#logging . Unfortunately in openhab-cli I see a command to change the log level, but not a command to see the current log level:

openhab> log<TAB to show the completions>
log log:log                                                  (Log a message)
log:clear                                                (Clear log entries)
log:display                                           (Displays log entries)
log:exception-display    (Displays the last occurred exception from the log)
log:get                                  (Shows the currently set log level)
log:list
log:load-test                                                (Load test log)
log:set                                                 (Sets the log level)
log:tail (Continuously display log entries. Use ctrl-c to quit this command)
logout                              (Disconnects shell from current session)

I normally use log:set DEBUG

you can see the current log level with log:get

[dilyanpalauzov]

Yes, I have DEBUG log level.

[Laith-Budairi]

ok I can see it in the logs when I have ERROR level enabled. So what is the issue exactly? I clicked run and it logged it

[dilyanpalauzov]

The issue is that once the script is installed and the system starts, this text is logged twice. It should be printed exactly once.

[Laith-Budairi]

The issue is that once the script is installed and the system starts, this text is logged twice. It should be printed exactly once.

I did try to start openHAB again but I it doesn't log the message when it does

[dilyanpalauzov]

The issue is that once the script is installed and the system starts, this text is logged twice. It should be printed exactly once.

I did try to start openHAB again but I it doesn't log the message when it does

Your message is ambigous: it could mean that it logs zero times the message, or that it logs once the message. In any case the problem report is that the message is sometimes printed twice and sometimes once.

To be precise it is indeed sometimes not printed, like after a fresh upgrade, where the new addons have not yet been downloaded, but this happens so soldom that I decided not to file a case for it.

[rkoshak]

To determine whether the runlevel event occurs twice or whether something else if going on with the rule itself, set the level of openhab.event.StartlevelEvent to INFO. This will add the system runlevel events to events.log. You can see there whether the event is in fact happeing twice or if the rule is being triggered twice for some reason.

Note, if this rule is in a .rules file and for some reason that file gets reloaded after the system finishes starting up it will be called a second time on that second load. Verify that's not happening by looking for a "loaded model..." for that .rules file in openhab.log.

[dilyanpalauzov]

I have set log:set ERROR openhab.event.StartlevelEvent. Before and after the this log level, the log contains: Loading model '100.rules' once and the message System reached start level 100 is emitted twice.

runtimeInfo:
  version: 4.2.2
  buildString: Release Build
locale: bg-BG
systemInfo:
  configFolder: /etc/openhab
  userdataFolder: /var/lib/openhab
  logFolder: /var/log/openhab
  javaVersion: 17.0.13
  javaVendor: Raspbian
  osName: Linux
  osVersion: 6.1.21-v7l+
  osArchitecture: arm
  availableProcessors: 4
  freeMemory: 83053720
  totalMemory: 233377792
  uptime: 613
  startLevel: 100
addons:
  - automation-groovyscripting
  - binding-enocean
  - binding-mqtt
  - binding-network
  - binding-systeminfo
  - persistence-jdbc-sqlite
  - persistence-mapdb
  - transformation-jsonpath
  - transformation-map
  - ui-basic
clientInfo:
  device:
    ios: false
    android: false
    androidChrome: false
    desktop: true
    iphone: false
    ipod: false
    ipad: false
    edge: false
    ie: false
    firefox: true
    macos: false
    windows: false
    cordova: false
    phonegap: false
    electron: false
    nwjs: false
    webView: false
    webview: false
    standalone: false
    pixelRatio: 1
    prefersColorScheme: dark
  isSecureContext: true
  locationbarVisible: true
  menubarVisible: true
  navigator:
    cookieEnabled: true
    deviceMemory: N/A
    hardwareConcurrency: 4
    language: bg
    languages:
      - bg
      - en
      - en-GB
      - de
    onLine: true
    platform: Linux x86_64
  screen:
    width: 1920
    height: 1080
    colorDepth: 24
  support:
    touch: false
    pointerEvents: true
    observer: true
    passiveListener: true
    gestures: false
    intersectionObserver: true
  themeOptions:
    dark: dark
    filled: true
    pageTransitionAnimation: default
    bars: light
    homeNavbar: default
    homeBackground: default
    expandableCardAnimation: default
    blocklyRenderer: null
  userAgent: Mozilla/5.0 (X11; Linux x86_64; rv:132.0) Gecko/20100101 Firefox/132.0
timestamp: 2024-11-07T05:21:48.060Z

[dilyanpalauzov]

Above I had set the log level to ERROR. After log:set INFO openhab.event.StartlevelEvent, nothing changes.

[rkoshak]

Above I had set the log level to ERROR. After log:set INFO openhab.event.StartlevelEvent, nothing changes.

The procedure is as follows:

1. log:set INFO openhab.event.StartlevelEvent
2. restart OH
3. look in events.log for StartlevelEvent statements, do you see two for runlevel 100 or just one?

If once, the problem is caused by your rule triggering twice for some reason.

If twice, the problem is the runlevel 100 event occurs twice for some reason.

The next steps are radically different depending on the reason the rule is running twice.

[dilyanpalauzov]

So with

openhab> log:get  openhab.event.StartlevelEvent
INFO

restarting openhab, events.log contains a single Startlevel '100' reached. openhab.log contains for that DSL also a single Loading model … message. But the rule … when System reached start level 100 is executed twice.

[rkoshak]

OK, that narrows down the issue significantly. You might chnage the title of the issue to reflect this new information:

"System runlevel 100 rule triggered twice during OH startup"

The system isn't reaching runlevel twice. There is only the one event. But something is causing your rule to run twice. And that something isn't that the .rules file is reloaded after the startup (no loading model log message).