Timeouts during startup when using JRuby

Hi, I moved some of my rules triggering on status changes of things from DSL to JRuby. While the rules work fine, I do see startup problems now, with timeout error messages:

2025-05-30 15:37:43.017 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing ‘mqtt:homeassistant:288012f205:zwavejs2mqtt_5F0xe449d1cf_5Fnode119’ takes more than 5000ms.

I also observe that updating the JRuby rules with a new file can make the system crash after sending error messages like:

2025-05-30 15:28:55.806 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber ‘org.openhab.core.internal.items.ItemUpdater@1fa943c’ takes more than 5000ms.

CPU load is at 100% (single core usage as it seems). Those messages disappear if I uninstall JRuby again. I have OH 4.3.3 on a RP4 with openhabian, 32 bit system.

Depending on specifically how this rule is triggered, it might get pounded heavily during a startup which I imagine could cause problems.

If the rule is disabled, restart OH and only enable it after the Things have settled down a bit does the problem go away or at least lessen? If so that could point to the root cause of the problem.

It also points to a workaround you can use until the root problem gets fixed. openhab-js/CHANGELOG.md at v5.11.1 · openhab/openhab-js · GitHub. This rule template will disable the selected rules until a certain amount of time after startlevel 70 is reached.

In the mean time, also make sure you have enouigh resources on your machine. What’s the system load when these errors start? What’s the swap usage?

I thought so too, that this is probably load related. I had the same rules (trigger for each thing, a LOOONG list) as DSL, but this was a mess to maintain, so I went to JRuby to use the generic features. I have a look how to turn off the rules.

I forgot to add that because of the timeouts a lot of items stay in status offline after startup and I have to trigger them by hand.

Concerning the load, the machine is usually really not doing much, meaning typically 5% CPU load, no swapping or so. Only after installing JRuby and changing the rules from DSL to JRuby this started.

Hi, I couldn’t figure out how to delay the enabling of the rules. I went from JRuby to Javascript and dynamically create the triggers for all Things. This seems to work without the timeouts, since JRuby is not installed no longer.

Did it happen simply when the add-on was installed without any rules defined in jruby?

Can you post your jruby rules to help us pinpoint the issue?

I was running with the rules, so far I didn’t try just with JRuby but without rules. My few rules are here:

############################################################################
# JRuby rules for ThingStatus
############################################################################

# Define the updateThingStatus lambda (proc)
updateThingStatus = ->(thing,thing_status_item) {
    thing_status = thing.status
    if thing_status.nil?
        thing_status_item.update "UNKNOWN"
        logger.info "JRuby --> Status of #{thing_status_item.name} set to #{thing_status_item.state}"
    elsif thing_status.to_s != thing_status_item.state
        thing_status_item.update thing_status.to_s
        logger.info "JRuby --> Status of #{thing_status_item.name} set to #{thing_status_item.state}"
    end
}

############################################################################
# JRuby rules for Thing Status Item updates if Thing changes
############################################################################

rule 'JRuby: Thing_Status rule when any thing is changing status' do
    changed things
    only_if { Delayed_Startup.on? } # Run rule only if startup is passed
    run do |event|
        # Find the corresponding status item in the Node_Status group by matching label substring
        the_status_item = Thing_Status.members.find do |item|
            thingUID = item.metadata['thingUID']
            if thingUID 
                event.thingUID == thingUID.value
            end
        end
        if the_status_item.nil?
            logger.warn "JRuby ---> Not finding Status Item for Thing #{event.thingUID}"
        else
            # Call your existing updateThingStatus proc or method
            updateThingStatus.call(event,the_status_item)
        end
    end
end

############################################################################
# JRuby rules for Thing Status Item updates if triggered
############################################################################

rule 'JRuby: Thing_Status update triggered' do
    cron "0 9,39 * ? * * *"
    received_command Trigger_Things
    only_if { Delayed_Startup.on? } # Run rule only if startup is passed
    run {
        logger.info "JRuby ---> Run Thing Status update"
        # Loop over members of Thing_Status
        Thing_Status.members.each do |item|
            thingUID = item.metadata['thingUID']
            if thingUID
                # get the thing 
                thing = things[thingUID.value]
                if thing.nil?
                    logger.warn "JRuby ---> Thing not found for UID: #{thingUID.value}"
                else
                    updateThingStatus.call(thing,item)
                end
            else
                logger.warn "JRuby ---> Status item #{item.name} has no Metadata for ThingUID"
            end
        end
    }
end

############################################################################
# JRuby rules for a Node_Action command
############################################################################

rule 'JRuby: Node_Action received command' do
    received_command Node_Action.members
    run do |event|
        # get the nodeID
        nodeID = event.item.metadata['nodeID']
        if nodeID
            topic = nil
            case event.command
            when ON
                logger.info "JRuby --> Node #{nodeID.value} received REFRESH VALUES command, sending MQTT"
                topic = "zwave/_CLIENTS/ZWAVE_GATEWAY-zwave-js-ui/api/refreshValues/set"
            when OFF
                logger.info "JRuby --> Node #{nodeID.value} received RE-INTERVIEW command, sending MQTT"
                topic = "zwave/_CLIENTS/ZWAVE_GATEWAY-zwave-js-ui/api/refreshInfo/set"
            else
                logger.warn "JRuby ---> Unsupported command: #{event.command}"
                next
            end
            payload = %{{"args": [#{nodeID.value}]}}
            # get the thingUID of the MQTT broker from metadata !
            MQTT_ThingUID = MQTTBroker_Status.metadata['thingUID']  
            if MQTT_ThingUID
                things[MQTT_ThingUID.value].publish_mqtt(topic,payload)
            else
                logger.warn "JRuby ---> MQTTBroker_Status has no Metadata for thingUID, this should not happen !"
            end     
        else
            logger.warn "JRuby ---> Status item #{event.item.name} has no Metadata for nodeID"
        end
        # reset triggering item in UI
        sleep 2
        event.item.update nil 
    end
end

There are some things that could be written/done better, but nothing that would cause the problem described. The only “error” I can see is the code below, it should be updateThingStatus.call(event.thing, the_status_item) instead.

However, this may sound like a bug somewhere, because it shouldn’t happen even without the change above. So if you could help with the troubleshooting, it would be appreciated.

Can you post the config/thing definition for this Thing?
Did it always happen with the same message caused by the same Thing on startup?

Exactly what’s the whole content of this file? Is it the one you posted above?

One possibility, I haven’t looked into it deeply, but try this:

rule 'JRuby: Thing_Status rule when any thing is changing status' do
    changed things
    only_if { Delayed_Startup.on? } # Run rule only if startup is passed
    delay 0.1.seconds # <==== ADD THIS
    run do |event|
....

What it does is instead of tying up the rule execution, it simply creates a timer and returns immediately. That might solve the startup problem.

To create a rule in a disabled state, simply add:

myrule = rule "xxxx" do
  uid: "give_it_a_uid"
  enabled false
  ...
end

# later on when you want to enable it:
myrule.enable
# or
rules["give_it_a_uid"].enable

I can also offer alternative ways of writing your rules if you like.

Hi, thanks for the suggestions, much appreciated and helpful. The version with Javascript runs without problems will all triggers, no disabling. Maybe the underlying problem is the sync of JRuby with the item/thing states. For now I think I am fine running like this. JRuby is definitely more elegant, so I will switch back once the resource issue is solved.

I need your help to resolve this

Hi, not sure what I can contribute to resolve this, I know too little about the internals of openhab and how the JRuby integration works and what may cause the delays. SInce I moved to JS rules it is fine, so it seems to be related that as soon as one adds JRuby the CPU goes up during init and when all of the objects get initialised, persistency, startup rules, and MQTT things get online. It seems there is additional compute needed to have JRuby working, isn’t it.

Can you please test my suggestion above?

Hi, I think the disabling thing does not work in practice, I could try this for testing, but for a real system this would leave the states uninitialised without further code to recover. The delay 0.1 I could try. But I doubt this is the rule execution itself, as with JS rules (and with DSL rules with a long explicit list of thing UIDs) there is no such problem. Would the delay 0.1 create individual timers, that are not overwritten ?

PS: I can not do this today, I hope that one of the next evenings I could try it.

What does your js rule looks like?

Simple translation, note there are no protections for the startup or something, it just works.

// ----------------------------------------------------------
// JavaScript rules for ThingStatus
// ----------------------------------------------------------

const logger = log("JS.ThingStatus");

// ----------------------------------------------------------
// Define the updateThingStatus function
// ----------------------------------------------------------

function updateThingStatus(thing, statusItem) {
  const thingStatus = thing.status;

  if (!thingStatus) {
    statusItem.postUpdate("UNKNOWN");
    logger.info(`JS --> Status of ${statusItem.name} set to UNKNOWN`);
  } else if (thingStatus.toString() !== statusItem.state) {
    statusItem.postUpdate(thingStatus.toString());
    logger.info(`JS --> Status of ${statusItem.name} set to ${thingStatus.toString()}`);
  }
}

// ----------------------------------------------------------
// Define the MQTTpublish function
// ----------------------------------------------------------

function MQTTpublish(topic, payload) {

  const MQTTMeta = items.getItem("MQTTBroker_Status").getMetadata("thingUID");
  if (!MQTTMeta) {
    logger.warn(`JS ---> MQTTBroker_Status has no metadata for thingUID, this should not happen!`);
    return;
  }
  const MQTT = MQTTMeta.value

  const MQTTActions = actions.get("mqtt",MQTT);
  if (!MQTTActions) {
    logger.warn(`JS ---> Could not get MQTT actions for thing: ${MQTT}`);
    return;
  }

  logger.info(`JS ---> Publishing MQTT to topic: ${topic}, payload: ${payload}`);
  MQTTActions.publishMQTT(topic, payload, true);
}

// ----------------------------------------------------------
// Dynamically create rules to Subscribe to thing status changes
// ----------------------------------------------------------

// Get all members of the group 'Node_Action'
const groupMembers = items.getItem("Thing_Status").members;

// Build an array of command triggers dynamically
const dynamicTriggers = groupMembers.map(member => {
  const meta = member.getMetadata("thingUID");
  logger.info(`JS ---> Create trigger for Thing ${meta.value}`);
  return triggers.ThingStatusChangeTrigger(meta.value);
});

rules.JSRule({
  name: "JS: Thing_Status rule when any thing is changing status",
  description: "Update Thing_Status items when corresponding Thing changes status",
  triggers: dynamicTriggers,
  //conditions: [
  //  () => items.getItem("Delayed_Startup").state === "ON"
  //],
  execute: (event) => {
    const thingUID = event.thingUID;

    const group = items.getItem("Thing_Status");

    // Find matching status item in Thing_Status group by thingUID metadata
    const statusItem = group.members.find(item => {
      const meta = item.getMetadata("thingUID");
      return meta && meta.value === thingUID;
    });

    if (!statusItem) {
      logger.warn(`JS ---> Not finding Status Item for Thing ${thingUID}`);
      return;
    }

    const thing = things.getThing(thingUID);
    if (!thing) {
      logger.warn(`JS ---> Thing not found for UID: ${thingUID}`);
      return;
    }

    updateThingStatus(thing, statusItem);
  }
});

// ----------------------------------------------------------
// Rule: Periodic/manual update of Thing status items
// ----------------------------------------------------------

rules.JSRule({
  name: "JS: Thing_Status update on Trigger_Things",
  description: "Updates all Thing_Status items on command",
  triggers: [
    triggers.ItemCommandTrigger("Trigger_Things"),
    triggers.GenericCronTrigger("0 9,39 * ? * * *")
  ],
  //conditions: [
  // () => items.getItem("Delayed_Startup").state === "ON"
  //],
  execute: () => {
    logger.info("JS ---> Run Thing Status update");

    const group = items.getItem("Thing_Status");

    group.members.forEach((item) => {
      const meta = item.getMetadata("thingUID");
      if (!meta) {
        logger.warn(`JS ---> Status item ${item.name} has no Metadata for ThingUID`);
        return;
      }

      const thing = things.getThing(meta.value);
      if (!thing) {
        logger.warn(`JS ---> Thing not found for UID: ${meta.value}`);
        return;
      }

      updateThingStatus(thing, item);
    });
  }
});

// ----------------------------------------------------------
// Javascript rules for a Node_Action command
// ----------------------------------------------------------

rules.JSRule({
  name: "JS: Node_Action received command",
  description: "Handles ON/OFF commands on Node_Action items by sending MQTT commands to zwave-js-ui",
  triggers: [triggers.GroupCommandTrigger('Node_Action')],
  execute: (event) => {

    const item = items.getItem(event.itemName);
    const command = event.receivedCommand;

    const nodeIDMeta = item.getMetadata("nodeID");
    if (!nodeIDMeta) {
      logger.warn(`JS ---> Status item ${nodeIDMeta.value} has no metadata for nodeID`);
      return;
    }
    const nodeID = nodeIDMeta.value

    let topic;
    switch (command) {
      case "ON":
        logger.info(`JS ---> Node ${nodeID} received REFRESH VALUES command, sending to MQTT`);
        topic = "zwave/_CLIENTS/ZWAVE_GATEWAY-zwave-js-ui/api/refreshValues/set";
        break;
      case "OFF":
        logger.info(`JS ---> Node ${nodeID} received RE-INTERVIEW command, sending to MQTT`);
        topic = "zwave/_CLIENTS/ZWAVE_GATEWAY-zwave-js-ui/api/refreshInfo/set";
        break;
      default:
        logger.warn(`JS ---> Unsupported command: ${command}`);
        return;
    }

    const payload = '{"args": [' + nodeID + ']}';

    MQTTpublish(topic,payload);

    // Delay reset of item
    java.lang.Thread.sleep(2000);
    item.postUpdate(null);
  }
});

// ----------------------------------------------------------
// Javascript rules for a Device_Action command
// ----------------------------------------------------------

rules.JSRule({
  name: "JS: Device_Action received command",
  description: "Handles OFF commands on Device_Action items by sending MQTT commands to zigbee2mqtt",
  triggers: [triggers.GroupCommandTrigger('Device_Action')],
  execute: (event) => {

    const item = items.getItem(event.itemName);
    const command = event.receivedCommand;

    const IEEEAddrMeta = item.getMetadata("IEEEAddr");
    if (!IEEEAddrMeta) {
      logger.warn(`JS ---> Status item ${IEEEAddrMeta.value} has no metadata for nodeID`);
      return;
    }
    const IEEEAddr = IEEEAddrMeta.value

    let topic;
    switch (command) {
      case "ON":
        logger.info(`JS ---> Device ${IEEEAddr} received INTERVIEW command, sending to MQTT`);
        topic = "zigbee2mqtt/bridge/request/device/interview";
        break;
      case "OFF":
        logger.info(`JS ---> Device ${IEEEAddr} received CONFIGURE command, sending to MQTT`);
        topic = "zigbee2mqtt/bridge/request/device/configure";
        break;
      default:
        logger.warn(`JS ---> Unsupported command: ${command}`);
        return;
    }

    const payload = '{"id": "' + IEEEAddr + '"}';

    MQTTpublish(topic,payload);

    // Delay reset of item
    java.lang.Thread.sleep(2000);
    item.postUpdate(null);
  }
});

The difference is that it doesn’t trigger on all things

Your first two rules can be written like this:

rule 'JRuby: Thing_Status rule when its Thing status changed' do
  Thing_Status.members.each do |thing_status_item|
    thing = things[thing_status_item.metadata["thingUID"]&.value]
    changed thing, attach: thing_status_item if thing
  end
  only_if { Delayed_Startup.on? } # Run rule only if startup is passed
  run do |event|
    event.attachment.ensure.update event.status
  end
end

rule "Update status on load" do
  on_load delay: 5.seconds
  run do
    Thing_Status.members.each do |thing_status_item|
      thing = things[thing_status_item.metadata["thingUID"]&.value]
      thing_status_item.update(thing&.status || "UNKNOWN")
    end
  end
end

You shouldn’t really need to regularly update them using cron or custom command. Just need to initialize them on startup. After that, the thing status change should update it.

If these things are MQTT, you can probably just create a special Item linked to the same availability topic as the Thing’s and then you won’t need any of these rules at all.