Astro actions in jruby

Hi,

I am trying to access the actions of the astro binding in jruby, and seem to fail in spectacular fashion.

My PoC code:

require 'openhab'

astroSun = actions("astro", "astro:sun:local")

rule 'Testing actions' do
  every :minute

  run do
    astroTime = astroSun.getEventTime("SUN_SET")
    logger.info("We have some astro time: #{astroTime.to_s}")
  end
end

I would expect this to log the time that the sun will set today.

It however logs nothing, and starts loading the CPU, until the point openHAB crashes.

Any help would be appreciated :slight_smile:

I donā€™t use jRuby but often in the other languages, the rules file can be parsed before the Thing is online and available. If that occurs, astroTime will be null (or what ever they call it in Ruby). You should pull the action inside the rule just before you use it.

Beyond that, I canā€™t help.

Try this:

require 'openhab'

rule 'Testing actions' do
  every :minute
  run do
    astro_time = things['astro:sun:local'].getEventTime('SUN_SET', nil, nil)
    logger.info("We have some astro time: #{astro_time}")
  end
end

I couldnā€™t reproduce this high CPU issue on my system using your code. Iā€™ve even set my rule to run every second instead of minute.

1 Like

Thanks! That example works!

Now if I replace things['astro:sun:local'] with actions('astro', 'astro:sun:local'), as I would have deducted from the documentation, my instance explodes again.

2022-07-26 12:25:31.366 [WARN ] [.util.thread.strategy.EatWhatYouKill] -
java.lang.OutOfMemoryError: Java heap space
2022-07-26 12:25:31.367 [ERROR] [org.apache.felix.fileinstall        ] - In main loop, we have serious trouble
java.lang.OutOfMemoryError: Java heap space

Itā€™s about to get weirdā€¦

Changing the existing rule makes it crash, restarting openHAB makes it work.

So if I save the rule with syntax a, check that it works, and then change it to syntax b, it will run out of memory and crash.
If I then restart openHAB, it will just work fine with syntax b.

During testing I noticed that often, I see 2 lines in my logs when changing (reloading) a script:

2022-07-26 12:17:18.164 [INFO ] [rulesupport.loader.ScriptFileWatcher] - Loading script '/etc/openhab/automation/jsr223/ruby/personal/test.rb'
2022-07-26 12:17:26.330 [INFO ] [rulesupport.loader.ScriptFileWatcher] - Loading script '/etc/openhab/automation/jsr223/ruby/personal/test.rb'

Is that usual?

I tried this on my system, it worked fine:

require 'openhab'

astroSun = actions('astro', 'astro:sun:home')

rule 'Testing actions' do
  every :second
  run do
    astroTime = astroSun.getEventTime('SUN_SET', nil, nil)
    logger.info("We have some astro time: #{astroTime}")
  end
end

I only saw this once in my log when saving the file:

21:16:12.305 [INFO ] [.rulesupport.loader.ScriptFileWatcher] - Loading script '/openhab/conf/automation/jsr223/ruby/personal/test1.rb'

As @rlkoshak suggested, itā€™s best to put the actions call or the things[ā€˜xxxxā€™] inside the rule run block in case the thing isnā€™t yet loaded.

Is this reproducible or a one off issue?

Itā€™s pretty reproducible. Open the script, change a couple of letters in the variable name, save, and watch it burn.

Using the following code at the moment

require 'openhab'

rule 'Testing actions' do
  every :minute
  run do
    astro_t = actions('astro', 'astro:sun:local').getEventTime("SUN_SET", nil, nil)
    logger.info("We have some astro time: #{astro_t}")
  end
end

And changing the astro_t variable name is enough to make it go out of control.

The double log entry seems pretty consistent as well. Open and edit any script, save it, and there will be two entries.
Iā€™ve checked and there is only one JRuby bundle loaded

openhab> bundle:list | grep -i jruby
312 ā”‚ Active ā”‚  80 ā”‚ 3.3.0                  ā”‚ openHAB Add-ons :: Bundles :: Automation :: JRuby Scripting

This may depend on your mystery editor. Some update a target file twice, and both fiddlings may be seen by openhabā€™s filewatcher.

That would be plain vim, but you might have a point there. Just touchā€™ing the file wonā€™t trigger the double entries.

Iā€™ve been using vscode and it doesnā€™t cause the double notify / double loading. Try vim inotify twice - Google Suche and see whether itā€™s related to your openhab crashing.

I can now confirm :slight_smile:

sed -i 's/astro_t/astro_time/' test.rb
sed -i 's/astro_time/astro_t/' test.rb

No issues whatsoever. A single ScriptFileWatcher line per command.

vim -c ':%s/astro_t/astro_time/g' -c ':wq' test.rb
vim -c ':%s/astro_time/astro_t/g' -c ':wq' test.rb

Double log entries, and the system is going down.

Iā€™ve been editing the script files using vim for quite some time now, and with these astro actions, its the first time this manifests itself.
I guess itā€™s good to know, and might also be related to the limited CPU power of the device openHAB is running on.

Sorry for sending you all down a rabbit-hole!

1 Like

Itā€™s hardly obvious. Well done for spotting and reporting the double rule load, few would.

Guess the underlying issue is some horror about (re) loading rules before last attempt has finished, and likely about Actions in general or Astro in particular.

It would be ā€œniceā€ to get that fixed, because Iā€™ll bet it can manifest in other nasty obscure ways. So Iā€™d recommend if you could log a Github issue for posterity, outlining how you could reproduce this.
I doubt itā€™ll get looked at to be honest,but it might help someone else one day

I have encountered this double loading although not related to vim. It happens programmatically when moving a (temp) script file from a different mountpoint in a linux filesystem to conf/automation/jsr223/ruby/personal/. I just implemented a workaround by creating that temp file in the same mountpoint before moving it. Since this was easily avoidable I didnā€™t bother opening an issue with openhab-core and just moved on.

Come to think of it, I have had CPUs going crazy (caused by openhab) on my development laptop too but I didnā€™t link the two issues together, and instead just moved development into a linux server. Iā€™m not sure that I experienced or noticed the double loading on my laptop, so Iā€™m not sure if theyā€™re related.

I can confirm that this happened on my system too, except my openhab process didnā€™t crash nor did it cause a cpu spike. My system has lots of RAM so perhaps that helped. I am also using an openhab 3.4-snapshot from a few days ago.

Furthermore, I tried this on a RulesDSL file in conf/rules/test.rules and yes, openhab loaded the rule twice there too.

This vim command will not trigger the double loading:

vim -c ':set nowritebackup' -c ':set nobackup' -c ':%s/astro_t1/astro_t2/g' -c ':wq' test.rules 

I thought it might be nice to share were I was going with this. Maybe someone else can take inspiration from it :slight_smile:

This is part of my bedroom automation, closing the blinds when the sunā€™s down and the lights are turned on.

require 'openhab'

BEDROOM_LIGHTS = Bedroom
  .equipments(Semantics::Lightbulb)
  .members
  .points(Semantics::Control)

rule 'Turn off lights when sleep tracking has started' do
  changed SleepasAndroid_Event,
    from: ->f { ! ['sleep_tracking_started', 'sleep_tracking_paused'].include?(f) },
    to:   ->t {   ['sleep_tracking_started', 'sleep_tracking_paused'].include?(t) }

  delay 5.seconds

  run do
    # Turn the lights off
    BEDROOM_LIGHTS.ensure.off

    # Close the blnnds
    BlindsBedroomWindow_Vane.ensure.command(0)
  end
end

rule 'Close blinds when it is dark outside and lights are on' do
  changed BEDROOM_LIGHTS, to: ->t { t.on? }

  run do |event|
    logger.info("#{event.item} turned on while dark outside, closing the blinds")
    BlindsBedroomWindow_Position.ensure.down
    BlindsBedroomWindow_Vane.ensure.command(0)
  end

  only_if { actions("astro","astro:sun:local").getElevation(nil) <= -6 }
end

Interesting use of lambda! I assume itā€™s because your lights can either be a switch or a dimmer, so using lambda -> t { t.on? } covers both cases?

Would you mind sharing which blinds youā€™re using?

Iā€™m also wondering why you arenā€™t simply using this trigger:

rule 'Turn off lights when sleep tracking has started' do
  changed SleepasAndroid_Event, to: %w[sleep_tracking_started sleep_tracking_paused]

You are completely right. I have a switched light, and a ceiling dimmer in the bedroom. The on? method works on both.

Sure! I have Luxaflex (HunterDouglas) Powerview blinds around the house, the vertical venetian type. In the bedroom they have room darkening fabric, which works really well :slight_smile:

For one I totally forgot about the word-array operator in ruby, and the fact you can pass the to: parameter an array. But! there is also a issue I ran into;
Iā€™d like to trigger the rule only at the very start of sleep tracking. When SleepAsAndroid starts the session, it will pause tracking for a couple of minutes, sending the sleep_tracking_started and sleep_tracking_paused in very quick succession. While both end up fine on the MQTT broker, openHAB seems to have trouble keeping up, and just sometimes skips the first sleep_tracking_started state.

Without this bug, it could be just simply to: "sleep_tracking_started".

If openhab skips it, I would call that a bug in openhab! In any case, even if you got only one of them, wonā€™t it work the same anyway?