Strange behaviour with JSScripting Rule

Hi all,

I’ve begun migrating my RuleDSL files to JSRule files. Unfortunately, experiencing some strange behaviour…

Essentially, I’ve got the below rule that will trigger certain items based on the time of day (this worked like a charm without fail in RulseDSL):

// Daily Automation

//const tod = items.getItem('TimeOfDay');

const blinds = items.getItem('gBlinds');

const porchLight = items.getItem('PorchLight_Power');

const blindsLog = 'Blinds';

const porchLightLog = 'Porch light';

const logger = log('Daily.Automation');

rules.JSRule({

   id: 'DailyHomeAutomation',

   name: 'Daily Home Automation',

   description: 'Daily home automation to be run at given time of day',

   triggers: [triggers.ItemCommandTrigger('TimeOfDay')],

   execute: logic => {

     if (items.getItem('TimeOfDay').state == 'SUNRISE') {

        blinds.sendCommand('0');

        logger.info(blindsLog + ' going up');

        logger.info("Current time of day: " + items.getItem('TimeOfDay').state);

    } else if (items.getItem('TimeOfDay').state == 'SUNSET') {

        porchLight.sendCommand('ON');

        logger.info(porchLightLog + ' on');

        logger.info("Current time of day: " + items.getItem('TimeOfDay').state);

    } else if (items.getItem('TimeOfDay').state == 'NIGHT') {

        blinds.sendCommand('100');

        logger.info(blindsLog + ' going down');

        logger.info("Current time of day: " + items.getItem('TimeOfDay').state);

    } else if (items.getItem('TimeOfDay').state == 'BED') {

        porchLight.sendCommand('OFF');

        logger.info(porchLightLog + ' off');

        logger.info("Current time of day: " + items.getItem('TimeOfDay').state);

    }

   }

 });

Now, what I’ve found is that the rule will run irrespective of the time of day and actually falls into an if statements and runs which is very strange! (sometimes I’ve seen it uses the previous state of TimeOfDay item…)

Extract from the logs;

events.log:

2022-01-12 08:16:00.046 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'TimeOfDay' received command SUNRISE
2022-01-12 08:16:00.055 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'TimeOfDay' changed from BED to SUNRISE
2022-01-12 08:16:00.076 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'gBlinds' received command 0
2022-01-12 09:00:00.010 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'TimeOfDay' received command DAY
2022-01-12 09:00:00.016 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'TimeOfDay' changed from SUNRISE to DAY
2022-01-12 09:00:00.027 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'gBlinds' received command 0

openhab.log:

2022-01-12 08:16:00.030 [INFO ] [del.script.Rules.rules_toold.Time_SM] - Transitioning Time of Day from BED to SUNRISE
2022-01-12 08:16:00.069 [INFO ] [b.automation.script.daily.automation] - Blinds going up
2022-01-12 08:16:00.077 [INFO ] [b.automation.script.daily.automation] - Current time of day: SUNRISE
2022-01-12 09:00:00.022 [INFO ] [b.automation.script.daily.automation] - Blinds going up
2022-01-12 09:00:00.031 [INFO ] [b.automation.script.daily.automation] - Current time of day: DAY

Notice that ‘TimeOfDay’ equalling ‘DAY’ is not included in the rule, so why is it going there? I did have more logs, but sadly cleared the cache last night to ensure its not a caching issue…

Any help would be greatly appreciated as I’ve been trying different things over the last couple of days… (no doubt its in my code somewhere!)

Many thanks in advanced :slight_smile:

Doomed to failure. Commands are not states; when this rule triggers, the Item being commanded will be at some previous state. Maybe its state will change in response to the command later, maybe part way through the rule. Maybe it simply won’t change at all; it depends on other factors.

I think you might want to trigger on state change, or use received command within your rule.

Right, okay…so should I be using:

ItemStateChangeTrigger

OR

ItemStateUpdateTrigger

If I look at the rule in MainUI using below trigger:

ItemCommandTrigger

It is ‘Received Command’, please see below:

As always thank you :slight_smile:

It really all depends exactly what you want to do. The different triggers have been provided for a reason.
The key things to grasp -

Commands are not states. State may not be related to command at all (think about Dimmer with 50% state and INCREASE command)

If a command actually does something to state at all, it takes real time.

Update and change are not the same - you can update-to-same value.

So here, you would think carefully about what happens to your ‘TimeOfDay’ Item , and when. Then work out when you want your rule to run, and choose the trigger.

What I meant by that is that if your rule is triggered by a command, within the body of the rule you can examine that ‘received command’ instead of state.

Understood, ultimately what I require is:

  1. Rule to be triggered when a new ‘TimeOfDay’ is set
  2. Based on the new state of ‘TimeOfDay’ send a command to another item. For instance, Porch Light on when ‘TimeOfDay’ equals ‘SUNSET’

If I’ve understood this correctly, I think I should be using ‘ItemStateChangeTrigger’.

Would you agree?

Be careful with putting these outside the rule. That means they only get set up and populated when the script is loaded. That was definitely a problem in Rules DSL and I would expect it might be a problem here too. If for some reason that Item Object goes stale (e.g. you’ve reloaded the .items file and the Items in that file were all deleted and recreated as a result) blinds and porchLight will no longer be connected to an active Item and no longer reflect the current state of the Items.

Better to get the Item and it’s state inside the rule so you know you always have the most recent and active Items and states.

It’s somewhat cleaner and avoids a problem with how commands are processed to use logic.itemCommand (for command triggered rules) and logic.itemState for update and change triggered rules. (NOTE: in execute: logic => {, logic is the name of the argument passed to your execute function. In files based rules you can name it what you want (in this case you’ve named it “logic”. In UI rules and in most of the examples you will see this is named event since it represents the event that triggered the rule.

Given that’s what this does, “logic” is kind of an odd name really and I’d recommend changing it.

So, if you keep the command trigger:

if(logic.itemCommand.toString() == 'SUNRISE')

or if you change to changed trigger:

if(logic.itemState.toString() == 'SUNRISE')

I’m not 100% certain the toString is required here and include it just in case.

One important distinction (and not one I necessarily agree with but it is what it is) is items.getItem('MyItem').state always returns the string representation of the Item’s state. However, that event Object that gets passed to the rule will have the “raw” Item State Objects, the same as if you called `items.getItem(‘MyItem’).rawState;

1 Like

Thanks for the informative response @rlkoshak :slight_smile:

Taken onboard and moved within the rule :slight_smile:

Also taken your recommendation here and updated to ‘event’, as you mention certainly a more accurate.

When I manually ran the script, if I retained toString I was getting an error, so removed it.

However, with all the above changes - item ‘TimeOfDay’ has just changed to SUNSET and the rule has not triggered at all :frowning:

Please see updated rule below:

// Daily Automation

rules.JSRule({

   id: 'DailyHomeAutomation',

   name: 'Daily Home Automation',

   description: 'Daily home automation to be run at given time of day',

   triggers: [triggers.ItemCommandTrigger('TimeOfDay')],

   execute: event => {

        // Define all variables

        const blinds = items.getItem('gBlinds');

        const porchLight = items.getItem('PorchLight_Power');

        const blindsLog = 'Blinds';

        const porchLightLog = 'Porch light';

        const logger = log('Daily.Automation');

        if(event.itemCommand == 'SUNRISE') {

            blinds.sendCommand('0');

            logger.info(blindsLog + ' going up');

        } else if (event.itemCommand == 'SUNSET') {

            porchLight.sendCommand('ON');

            logger.info(porchLightLog + ' on');

        } else if (event.itemCommand == 'NIGHT') {

            blinds.sendCommand('100');

            logger.info(blindsLog + ' going down');

        } else if (event.itemCommand == 'BED') {

            porchLight.sendCommand('OFF');

            logger.info(porchLightLog + ' off');

        }

    }

});

Should I be using ‘ItemStateChangeTrigger’ instead?

As always thanks very much for all the help :slight_smile:

Note, there won’t be an itemState or itemCommand when you run the rule manually. There was no such Item event that occurred. That’s why the toString failed. You tried to call toString on something that doesn’t exist.

If you want also be able to run this rule using triggers that are not Item events, you cannot rely on event.

I don’t know. was the Item TimeOfDay commanded? How do you know the rule didn’t run and instead it just failed? Add logging. I’d guess the removal of the toString() calls is why the rule didn’t do anything.

Fair point there @rlkoshak! I’ve reinstated the toString.

I’m sorry I should have added the logs I was looking at!

events.logs:

2022-01-12 16:15:00.019 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'TimeOfDay' received command SUNSET
2022-01-12 16:15:00.050 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'TimeOfDay' changed from DAY to SUNSET

Nothing after this in relation to the rule :frowning:

I’ll keep you posted when the next update to ‘TimeOfDay’ item happens :slight_smile:

Walk through your rule line by line.

  1. Unless there is an error your rule will never output anything to openhab.log unless one of your if/else if statements evaluate to true.
  2. It is highly likely that event.itemCommand == 'SUNRISE' will never be true because evetn.itemCommand is, in this case a StringType, not a string (that’s why we need the toString().

Therefore, none of your if/else if statements evaluate to true (2.) so there will be no evidence in your logs that the rule ran (1.). There is no evidence what-so-ever to tell you whether the rule ran or not. You just can’t assume it didn’t run, it might have run and exited without doing anything.

You need to add a log statement to the rule to show that it ran (or modify the events logger so show rule events in events.log). Maybe add an else that logs an error when none of your if statements match. Maybe just a log statement at the top of the rule to show it was triggered.

Never make assumptions. If your assumptions were correct, the rule would work. You have to prove to yourself with evidence what is going on in the rule. If your assumption was that the rule didn’t run, add some logging to prove it didn’t run.

1 Like

All your points are completely valid @rlkoshak, can’t argue at all :slight_smile:

I’ve gone ahead and added some additional logs; 1 at the start/end of the rule and also ‘else’, if none of the criteria is met.

I have found some error, after forcing the ‘TimeOfDay’ item to change shown below:

2022-01-12 18:20:58.542 [INFO ] [b.automation.script.daily.automation] - Daily Automation Script - Start
2022-01-12 18:20:58.753 [ERROR] [org.openhab.automation.script.rules ] - Failed to execute rule DailyHomeAutomation: TypeError: undefined has no such function "toString": TypeError: undefined has no such function "toString"
	at execute (home.js:18)
	at doExecute (webpack://openhab/./node_modules/openhab/rules/rules.js?:110)
2022-01-12 18:20:58.827 [ERROR] [e.automation.internal.RuleEngineImpl] - Failed to execute rule 'DailyHomeAutomation': Fail to execute action: 1

Any ideas?

As always thank you! :slight_smile:

Show the full rule as it is now.

event.itemCommand doesn’t exist.

Sure, it’s as follows:

// Daily Automation

rules.JSRule({

   id: 'DailyHomeAutomation',

   name: 'Daily Home Automation',

   description: 'Daily home automation to be run at given time of day',

   triggers: [triggers.ItemCommandTrigger('TimeOfDay')],

   execute: event => {

        // Define all variables

        const blinds = items.getItem('gBlinds');

        const porchLight = items.getItem('PorchLight_Power');

        const blindsLog = 'Blinds';

        const porchLightLog = 'Porch light';

        const logger = log('Daily.Automation');

        logger.info("Daily Automation Script - Start");

        if(event.itemCommand.toString() == 'SUNRISE') {

            blinds.sendCommand('0');

            logger.info(blindsLog + ' going up');

        } else if (event.itemCommand.toString() == 'SUNSET') {

            porchLight.sendCommand('ON');

            logger.info(porchLightLog + ' on');

        } else if (event.itemCommand.toString() == 'NIGHT') {

            blinds.sendCommand('100');

            logger.info(blindsLog + ' going down');

        } else if (event.itemCommand.toString() == 'BED') {

            porchLight.sendCommand('OFF');

            logger.info(porchLightLog + ' off');

        } else {

            logger.info('No criteria met!');

        }

        logger.info("Daily Automation Script - End");

       

    }

});

Thank you :slight_smile:

OK, and when you changed the Item, you sent it a Command, right?

At the top of the file add:

console.log(event, event.itemCommand);

What gets logged?

Certainly did :slight_smile:

As follows:

2022-01-12 19:54:30.974 [INFO ] [del.script.Rules.rules_toold.Time_SM] - Today is a default day.
2022-01-12 19:55:30.994 [INFO ] [del.script.Rules.rules_toold.Time_SM] - The current time of day is SUNSET
2022-01-12 19:55:31.006 [INFO ] [b.automation.script.daily.automation] - Daily Automation Script - Start
2022-01-12 19:55:31.014 [INFO ] [org.openhab.automation.script       ] - {
  "eventType": "command",
  "triggerType": "ItemCommandTrigger",
  "receivedCommand": {},
  "oldState": "null",
  "newState": "null",
  "itemName": "TimeOfDay"
} undefined
2022-01-12 19:55:31.021 [ERROR] [org.openhab.automation.script.rules ] - Failed to execute rule DailyHomeAutomation: TypeError: undefined has no such function "toString": TypeError: undefined has no such function "toString"
	at execute (home.js:19)
	at doExecute (webpack://openhab/./node_modules/openhab/rules/rules.js?:110)
2022-01-12 19:55:31.027 [ERROR] [e.automation.internal.RuleEngineImpl] - Failed to execute rule 'DailyHomeAutomation': Fail to execute action: 1

Thank you :slight_smile:

I’ve not seen that before. I wonder what is going on here. receivedCommand is an empty dict, not the expected StringType.

I don’t use file based rules but can’t imagine this is done differently in files compared to UI rules.

What happens when you adjust the trigger to a Change and change the comparisons to check event.newState? Leave the console.log statement in place and post those logs as well.

Right Rich, now that seems to work as expected after forcing an update to ‘TimeOfDay’ item! :smiley:

Logs are as follows:

2022-01-12 21:07:17.174 [INFO ] [del.script.Rules.rules_toold.Time_SM] - Today is a default day.
2022-01-12 21:08:17.203 [INFO ] [del.script.Rules.rules_toold.Time_SM] - The current time of day is SUNSET
2022-01-12 21:08:17.233 [INFO ] [b.automation.script.daily.automation] - Daily Automation Script - Start
2022-01-12 21:08:17.239 [INFO ] [org.openhab.automation.script       ] - {
  "oldState": "TEST",
  "newState": "SUNSET",
  "state": "null",
  "receivedCommand": null,
  "receivedState": null,
  "receivedTrigger": null,
  "itemName": "TimeOfDay",
  "payload": {
    "type": "String",
    "value": "SUNSET",
    "oldType": "String",
    "oldValue": "TEST"
  },
  "eventType": "change",
  "triggerType": "ItemStateChangeTrigger"
} "SUNSET"
2022-01-12 21:08:17.269 [INFO ] [b.automation.script.daily.automation] - Porch light on
2022-01-12 21:08:17.275 [INFO ] [b.automation.script.daily.automation] - Daily Automation Script - End

Question: Do I still need to have the toString function if the payload format is String too?

Try it out and see what happens. What is weird is this doesn’t look like the event Object I’m used to. I think the openhab-js library is monkeying around with the Java Object before sending it on. I’m not sure I like this difference between UI rules and text based rules if that is the case.

That’s very strange indeed! However, I can confirm that without the toString function the rule still works as expected.

Thank you very much for all the help as always @rlkoshak!

Hi I see Jeevs was able to work around the issue by changing the rule to react to a state change of an Item. However, I need a rule that reacts to the command an item receives and that command may be the same, so reacting to a state change doesn’t work. To simplify things I trimmed down my rule to logging only, to see what is happening. BTW I am also using file based rules.

My rule is.

rules.JSRule({
  name: "Light select rule",
  description: "Select light",
  triggers: [triggers.ItemCommandTrigger('LightSelect')],
  execute: event => {
	var myCommand = String(event.itemCommand);
	console.log("event", event);
	console.log("ItemCommand", event.itemCommand);
	console.log("ItemCommand", myCommand);
	console.log("itemName", event.itemName);
  }
});

When I send a command to my item get:

2022-01-18 22:57:39.436 [INFO ] [org.openhab.automation.script       ] - event {
  "eventType": "command",
  "triggerType": "ItemCommandTrigger",
  "receivedCommand": {},
  "oldState": "null",
  "newState": "null",
  "itemName": "LightSelect"
}
2022-01-18 22:57:39.478 [INFO ] [org.openhab.automation.script       ] - ItemCommand undefined
2022-01-18 22:57:39.486 [INFO ] [org.openhab.automation.script       ] - ItemCommand undefined
2022-01-18 22:57:39.490 [INFO ] [org.openhab.automation.script       ] - itemName LightSelect

So what I am noticing is that the event.itemCommand is undefined. That looks like it is not possible to pick up the command itself. That is a basis fuction of openhab, so I must be missing something, but I cannot figue out what.