Jruby script inconsistent error of "undefined local variable or method `shared_cache' for main:Object"

Setup, Configuration and Use Scripts & Rules
1
  • Platform information:
    • Hardware: Raspberry PI 4B
    • OS: OpenHabianOS 4.1.1
    • Java Runtime Environment: OpenJDK 64 bit 17.0.13
    • openHAB version: 4.1.1
  • Issue of the topic: Rules calling the same Jruby script from an inline Jruby script, shared_cache becomes undefined
  • Descriptions:
    The jruby addon is running in “ThreadSafe” context, while other settings are left at default.
    The inline script that is put in the rule’s “action”, can use the function shared_cache for a pseudo mutex variable and when calling the external script notification_built_in, it will also use shared_cache to rate limit via a quota system also saved in the shared_cache.

But in my testing scenario, the first rule that runs, can complete it successfully. But the other rules that follow through will somehow lose the ability to call the function only when running that external script to fetch the shared caches for the quota system.

  • Please post configurations (if applicable):
    • Rule inline script:
def processNotification() 
  logger.info('running rule 4')  
  shared_cache[:mutexQueue] ||= []
  mutexQueue = shared_cache[:mutexQueue]
  count = 1
  while shared_cache[:mutexQueue].length > 0 do
    count += 1
    if count > 8
      logger.info('rule 4 exceeded sleep')
      return
    end
    sleep 4
    mutexQueue = shared_cache[:mutexQueue]
  end
  shared_cache[:mutexQueue] << {'date' => Time.now.iso8601}

  data = ["+2507"]
  mode = "whatsapp"
  logger.info(data)
  rule_manager = OpenHAB::OSGi.service("org.openhab.core.automation.RuleManager");
  result = rule_manager.run_now('notification_built_in', true, {'data' => data, 'mode' => mode});
  logger.info('finish running rule 4')
  logger.info(result)
  
  shared_cache[:mutexQueue].shift
  return
end

processNotification()
  • Script that they are calling:
require 'json'
require 'time'

def notification_quota_check(target, user_id)
  max_quota = 5
  time_limit = 20
  shared_cache[:notification_quota] ||= []
  curr_time = Time.now
  logger.info( "-=-=-=-=-= Start of notification Quota -=-=-=-=-")
  logger.info( "notificationQuota: #{notification_quota.inspect}")

  if shared_cache[:notification_quota].length >= max_quota
    logger.info( "+++ notificationQuota is full +++")
    allow = false
    old_quota = shared_cache[:notification_quota].dup

    old_quota.each do |entry|
      logger.info( "full Data: #{entry}")
      oldest_time_in_quota = Time.parse(entry['date'])
      minutes_from_curr = (curr_time - oldest_time_in_quota) / 60
      logger.info( "how long ago was it: #{(curr_time - minutes_from_curr * 60).iso8601}")

      if minutes_from_curr > time_limit
        allow = true
        logger.info( "already more than #{time_limit} minutes, we can remove it from Quota")
        shared_cache[:notification_quota].shift
      else
        break
      end
    end

    if allow
        shared_cache[:notification_quota] << { 'date' => curr_time.iso8601, 'number' => target, 'userId' => user_id }
    end

    return false
  else
    logger.info( "--- notificationQuota is not full ---")
    shared_cache[:notification_quota] << { 'date' => curr_time.iso8601, 'number' => target, 'userId' => user_id }
    return true
  end
end

def trigger_notification(data, mode)
  require 'net/http'
  require 'uri'

  logger.info( "trigger notification for #{data}")

  uri = URI.parse("https://www.uchat.com.au/api/iwh/")
  case mode
  when "whatsapp", "application"
    request = Net::HTTP::Post.new(uri)
    request.content_type = "application/json"
    request.body = JSON.dump({ data: data })

    response = Net::HTTP.start(uri.hostname, uri.port, use_ssl: true) do |http|
      http.request(request)
    end
    return response
  when "email"
    response = Net::HTTP.get_response(uri)
    return response
  else
    return nil
  end
end
data = { message: "Your notification message" }
mode = "whatsapp"

if notification_quota_check(data, 12)
  logger.info( "Notification Sending")
  trigger_notification(data, mode)
end
  • Logs generated (theres 7 rules that run the same inline script, triggered by the same thing):
2024-12-17 18:10:40.023 [INFO ] [c4c321db-bfac-4a13-a122-f45c1acb5c0a] - running rule 1

2024-12-17 18:10:40.023 [INFO ] [ion.jrubyscripting.script.2a24776804] - running rule 6

2024-12-17 18:10:40.037 [INFO ] [ion.jrubyscripting.script.2a24776804] - ["+22222222222"]

2024-12-17 18:10:40.038 [INFO ] [ion.jrubyscripting.script.5b8badcc16] - running rule 4

2024-12-17 18:10:40.049 [INFO ] [b47692e2-743b-4f7e-9be4-c95a9de596ab] - running rule 7

2024-12-17 18:10:40.053 [INFO ] [ion.jrubyscripting.script.d08da3248d] - running rule 3

2024-12-17 18:10:40.056 [INFO ] [ion.jrubyscripting.script.815fbdbaf2] - running rule 2

2024-12-17 18:10:40.058 [INFO ] [ion.jrubyscripting.script.088201d9c0] - running rule 5

2024-12-17 18:10:40.182 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'notification_built_in' failed: Error during evaluation of Ruby in <script> at line 7: (NameError) undefined local variable or method `shared_cache' for main:Object

2024-12-17 18:10:40.186 [INFO ] [ion.jrubyscripting.script.2a24776804] - running rule 6

2024-12-17 18:10:40.191 [INFO ] [ion.jrubyscripting.script.2a24776804] - {data=["+22222222222"], mode=whatsapp}

==> /var/log/openhab/events.log <==

2024-12-17 18:10:39.942 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'moorgen_0821ffffffff_01ff_switch' received command ON

2024-12-17 18:10:39.947 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'yo835_switch_gang2_e4e112a09fda' received command ON

2024-12-17 18:10:39.960 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'moorgen_0821ffffffff_01ff_switch' predicted to become ON

2024-12-17 18:10:39.986 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'moorgen_0821ffffffff_01ff_switch' changed from OFF to ON

2024-12-17 18:10:40.011 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'yo835_switch_gang2_e4e112a09fda' predicted to become ON

==> /var/log/openhab/openhab.log <==

2024-12-17 18:10:44.044 [INFO ] [c4c321db-bfac-4a13-a122-f45c1acb5c0a] - ["random"]

2024-12-17 18:10:44.164 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'notification_built_in' failed: Error during evaluation of Ruby in <script> at line 7: (NameError) undefined local variable or method `shared_cache' for main:Object

2024-12-17 18:10:44.169 [INFO ] [c4c321db-bfac-4a13-a122-f45c1acb5c0a] - finish running rule 1

2024-12-17 18:10:44.172 [INFO ] [c4c321db-bfac-4a13-a122-f45c1acb5c0a] - {data=["random"], mode=whatsapp}

2024-12-17 18:10:48.046 [INFO ] [ion.jrubyscripting.script.5b8badcc16] - ["+2507"]

2024-12-17 18:10:48.067 [INFO ] [ripting.script.notification_built_in] - -=-=-=-=-= Start of notification Quota -=-=-=-=-

2024-12-17 18:10:48.083 [INFO ] [ripting.script.notification_built_in] - notificationQuota: #<OpenHAB::Core::Items::StringItem notification_quota "notification_quota" state=NULL category="">

2024-12-17 18:10:48.087 [INFO ] [ripting.script.notification_built_in] - --- notificationQuota is not full ---

2024-12-17 18:10:48.092 [INFO ] [ripting.script.notification_built_in] - Notification Sending

2024-12-17 18:10:48.096 [INFO ] [ripting.script.notification_built_in] - trigger notification for {:message=>"Your notification message"}

2024-12-17 18:10:48.673 [INFO ] [ion.jrubyscripting.script.5b8badcc16] - finish running rule 4

2024-12-17 18:10:48.676 [INFO ] [ion.jrubyscripting.script.5b8badcc16] - {mode=whatsapp, script.result=#<Net::HTTPNotFound:0x49863e80>, data=["+2507"]}

2024-12-17 18:10:52.058 [INFO ] [b47692e2-743b-4f7e-9be4-c95a9de596ab] - ["+44444444"]

2024-12-17 18:10:52.195 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'notification_built_in' failed: Error during evaluation of Ruby in <script> at line 7: (NameError) undefined local variable or method `shared_cache' for main:Object

2024-12-17 18:10:52.200 [INFO ] [b47692e2-743b-4f7e-9be4-c95a9de596ab] - finish running rule 7

2024-12-17 18:10:52.203 [INFO ] [b47692e2-743b-4f7e-9be4-c95a9de596ab] - {data=["+44444444"], mode=whatsapp}

2024-12-17 18:10:56.063 [INFO ] [ion.jrubyscripting.script.815fbdbaf2] - ["+9999"]

2024-12-17 18:10:56.171 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'notification_built_in' failed: Error during evaluation of Ruby in <script> at line 7: (NameError) undefined local variable or method `shared_cache' for main:Object

2024-12-17 18:10:56.178 [INFO ] [ion.jrubyscripting.script.815fbdbaf2] - finish running rule 2

2024-12-17 18:10:56.182 [INFO ] [ion.jrubyscripting.script.815fbdbaf2] - {data=["+9999"], mode=whatsapp}

2024-12-17 18:11:00.065 [INFO ] [ion.jrubyscripting.script.088201d9c0] - ["+111111111"]

2024-12-17 18:11:01.432 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'notification_built_in' failed: Error during evaluation of Ruby in <script> at line 7: (NameError) undefined local variable or method `shared_cache' for main:Object

2024-12-17 18:11:01.439 [INFO ] [ion.jrubyscripting.script.088201d9c0] - finish running rule 5

2024-12-17 18:11:01.443 [INFO ] [ion.jrubyscripting.script.088201d9c0] - {data=["+111111111"], mode=whatsapp}

2024-12-17 18:11:04.067 [INFO ] [ion.jrubyscripting.script.d08da3248d] - ["+6809"]

2024-12-17 18:11:05.803 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'notification_built_in' failed: Error during evaluation of Ruby in <script> at line 7: (NameError) undefined local variable or method `shared_cache' for main:Object

2024-12-17 18:11:05.811 [INFO ] [ion.jrubyscripting.script.d08da3248d] - finish running rule 3

2024-12-17 18:11:05.816 [INFO ] [ion.jrubyscripting.script.d08da3248d] - {data=["+333"], mode=whatsapp}
2

I tried to reproduce this issue but couldn’t trigger that error.

  • Created a script test_shared_cache:
    def test
  shared_cache[:test_shared_cache] ||= Time.now
  logger.info "test called"
  logger.info shared_cache[:test_shared_cache]
end

test
  • Created two rules that trigger on received command, both rules call the above script:
    rules["test_shared_cache"].run

The only issue I encountered was that when a script is running, it cannot be executed again while that script is still running, so I had to add a delay on the second script. This is a limitation imposed by openHAB itself.

I would suggest that instead of using / running a script, you could put those methods in a common file in CONF/automation/ruby/lib/notification.rb and require "notification" from your inline rule.

I’m curious as to the error you saw though.

P.S.: you don’t need to get the osgi service to run a script. It’s provided by DSL.rules

To execute the rule, call #trigger or #run as shown above.

Another point is that you should not store a Ruby object into shared_cache. This is because each instance of a JRubyScriptEngine has its own unique hash id.

Instead, create a Java object and store that. For your purpose, perhaps a Semaphore (Java SE 17 & JDK 17) ?

3

Is there a particular reason you changed JRuby to Threadsafe context? I’m not sure that’s really accomplishing your goals. Regardless of what Ruby is doing, it’s embedded in a highly multithreaded Java environment, so you will always need to deal with thread safety and race conditions. I tried to reproduce with the default setting of SingleThread, and while I could not get your same error, I did get a different error:

2024-12-18 08:25:20.581 [ERROR] [.handler.AbstractScriptModuleHandler] - Script execution of rule with UID 'notification_built_in' failed: java.lang.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2

This could be because of the threading more, or more likely that I’m running Java 21 which I’ve found can have issues with arrays throwing exceptions instead of returning nil (Java behavior instead of Ruby behavior).

I would recommend you make a few changes to your script. First is that you should not use ||= with shared_cache (or any data structure possibly shared among multiple threads), since another thread could write to it after you read the nil, and then your write would destroy their write. This is exactly what the compute_if_absent method is for - atomically checking if a key exists, generating a new value if it doesn’t, and then returning the value regardless of if it already existed or you had to generate it. After that, there’s no need to do additional lookups on shared_cache - the contents of your value might change, but the reference to it from shared_cache doesn’t anymore.

def processNotification() 
  logger.info('running rule 4')
  # @jimtng is right that this should probably just be a Semaphore rather than an array,
  # since you're not actually doing anything with the value. you would then use `tryAcquire`
  # with a timeout, instead of a loop with sleeps below. Then it would return the moment
  # one is available, instead of having to wait for the sleep to finish
  mutexQueue = shared_cache.compute_if_absent(:mutexQueue) { [] } # avoid read-then-write race condition
  count = 1
  until mutexQueue.empty? do
    count += 1
    if count > 8
      logger.info('rule 4 exceeded sleep')
      return
    end
    sleep 4
  end
  mutexQueue << {'date' => Time.now.iso8601}

  data = ["+2507"]
  mode = "whatsapp"
  logger.info(data)
  # Ruby 3.1+ (JRuby 9.4) has a shorthand syntax for hashes, so you don't need to
  # specify both key and value. Also, the `trigger` helper automatically transforms the
  # symbol keys to strings before passing to openHAB core, enabling this shorter syntax
  # also - do you really need to consider_conditions, or can you let that default to false?
  result = rules['notification_built_in'].trigger(consider_conditions: true, data:, mode:)
  logger.info('finish running rule 4')
  logger.info(result)
  
  mutexQueue.shift
  return
end

processNotification()

require 'json'
require 'time'

def notification_quota_check(target, user_id)
  max_quota = 5
  time_limit = 20
  notification_quota = shared_cache.compute_if_absent(:notification_quota]) { [] }
  curr_time = Time.now
  logger.info( "-=-=-=-=-= Start of notification Quota -=-=-=-=-")
  logger.info( "notificationQuota: #{notification_quota.inspect}")

  if notification_quota.length >= max_quota
    logger.info( "+++ notificationQuota is full +++")
    allow = false
    # there are still race conditions here; notification_quote could possibly be modified
    # elsewhere between when you read (and the dup) the current value, and
    # when you decide to shift an entry off
    old_quota = notification_quota.dup

    old_quota.each do |entry|
      logger.info( "full Data: #{entry}")
      time = Time.parse(entry['date'])
      # simplify time math and comparisons here
      logger.info( "how long ago was it: #{(curr_time - minutes_from_curr * 60).iso8601}")

      if time  < time_limit.minutes.ago
        allow = true
        logger.info( "already more than #{time_limit} minutes, we can remove it from Quota")
        notification_quota.shift
      else
        break
      end
    end

    if allow
        notification_quota << { 'date' => curr_time.iso8601, 'number' => target, 'userId' => user_id }
    end

   false
  else
    logger.info( "--- notificationQuota is not full ---")
    notification_quota << { 'date' => curr_time.iso8601, 'number' => target, 'userId' => user_id }
    true
  end
end

def trigger_notification(data, mode)
  require 'net/http'
  require 'uri'

  logger.info( "trigger notification for #{data}")

  uri = URI.parse("https://www.uchat.com.au/api/iwh/")

  # removed return statements, temporarily variables, and
  # `else` case here. they are all unnecessary in Ruby. The
  # last statement of a block is its implicit return value, and this
  # includes conditionals - they have return values. if a condition
  # doesn't match, its return value is `nil`
  case mode
  when "whatsapp", "application"
    request = Net::HTTP::Post.new(uri)
    request.content_type = "application/json"
    request.body = JSON.dump({ data: data })

    Net::HTTP.start(uri.hostname, uri.port, use_ssl: true) do |http|
      http.request(request)
    end
  when "email"
    Net::HTTP.get_response(uri)
  end
end
data = { message: "Your notification message" }
mode = "whatsapp"

if notification_quota_check(data, 12)
  logger.info( "Notification Sending")
  trigger_notification(data, mode)
end

So… after all that, attempting to address your error: Are these your complete rules? If you have an actual class defined that your methods are in, it would make sense. The jruby-scripting helper DSL only adds its methods at the top level, so as not to cause confusion inside of classes if you were to say have your own rules method in the class. If this is the case (or something similar, that you aren’t in the proper lexical scope), you can include OpenHAB::DSL in your class to get access to everything, including shared_cache. Or you can explicitly reference it by calling OpenHAB::DSL.shared_cache. The latter should work in most contexts (use ::OpenHAB::DSL.shared_cache for it to work in all contexts), while the former would only work somewhere you can include a module.

4

@rocketrk420 the local_context needs to be set to singlethread (the default). I believe the issue is caused by the threadsafe setting.

singlethread is the only setting that is known to work within openhab, afaik.