Simplified Jython rule definition (similar to Rules DSL) using a universal decorator

Why is it so that they have to be unique?

I have one test script with same kind of content but never got any problems? I always name them

def execute(event, log) 
    blah blah... 

I guess when you don’t use these decorators the identical class name would be a problem?

I’m using M5 with a standalone jython2.7.1. The str() might not be necessary in the immediate context – I started doing it routinely because concatenation in log.X statements doesn’t like non-strings.
I’ll re-insert some naked logging of the event.itemName — although I believe that in some earlier iterations I was using a construct similar to:

def mainFunction(event):
    triggeredby=event.itemName
    thisItem = ir.getItem(triggeredby)
## DO STUFF

The NPE first started showing up under this type of wiring (AFAIR – it’s been an intense few days).
Nonetheless, I will put logging (back) in as you suggest and go snipe-hunting.

Also changing to unique function names – although (like @gitMiguel ) I have gotten no error messages or other misbehavior from this. (?? maybe you mean the “@rule” contents — uniqueness there would be consistent with Xtend…)

Could this be a 2.7.1 problem?

Why would you want to redefine all of your functions? :slight_smile: The second time you define a function to the same name, you are redefining the function:

def test():
    log.debug("JSR223: test: inside 1")

log.debug("JSR223: test: outside 1")
test()

def test():
    log.debug("JSR223: test: inside 2")

log.debug("JSR223: test: outside 2")
test()

This will log

2018-11-16 15:10:39.253 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: test: outside 1
2018-11-16 15:10:39.253 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: test: inside 1
2018-11-16 15:10:39.254 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: test: outside 2
2018-11-16 15:10:39.254 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: test: inside 2

If you don’t have issues with redefining the functions, that’s good to know. But are you sure that this isn’t/won’t cause any problems? I’m not so sure, I’ve never tested it, and I did not intend for the functions to be redefined when I wrote the decorators. That’s why I pointed it out. It would be good to test with unique function names to see if this might resolve the problem. If it doesn’t, I still would not recommend it as it could cause other issues. And if anything, it’s just smelly code!

Redefining the functions means you can’t call them from other rules, and you can’t call them directly in the script when it loads, as a replacement for the StartupTrigger.

Try using format. It can take about anything and turn it into a string, and can do some conversions too.

log.debug("Member of Group_01 changed: [{}]: [{}]".format(event.itemName, thisItem.label))

There are known issues with 2.7.1. It would be best to use 2.7.0 until they are resolved. Not sure if it would cause the issue, but possible. If you’re running M5, then you have the fix for ItemStateChangeTrigger.

No, I meant the function names. The rule names actually do not have to be unique, but I recently added this as a requirement so that the rules can be iterated by name. You will get an error in the log when a rule is being added with a name that matches another rule.

Are you running off an SD card? Could possibly be a sign of a the card having issues?

In no particular order:

  1. I am running off a USB stick not an SD card.
  2. I have no problems switching to 2.7.0 if necessary.
  3. Using .format makes sense to try…(just being “old-school” I guess.)

As a “play-by-play” report – since I made earlier changes supra, problem has not recurred. To be fair, it often took a few hours to manifest when it was failing “regularly” so that is not conclusive, but just reporting.

[ On a pure “gut level”, this has smelled like some sort of timing heisenbug from early on, so adding logging injections could easily mask the root cause — not an intellectually-complete answer but pragmatic (if it holds up). ]

Will keep the thread posted as things go on.

ok, I finally realized what is going on with the timer - you cannot cancel a timer once it has been started it seems?

https://docs.python.org/2.4/lib/timer-objects.html

I don’t quite follow you here. I understand what you mean but this aplies e.g. for global functions defined in top of single script file:

That is not the same as in Bobs post or my post. Aren’t we talking about two separate rules callback functions in a single file? As in Bobs post:

My example was illustrating redefining a function, which is what Bob is doing. I am surprised the decorators and rule engine handle it. This was not intended or tested, so there is a chance of it causing unexpected side effects. :boom:

I am also confused ( like @gitMiguel )— unless the “@rule” decorator invocations are all emitting functions to the same class – there is no redefinition here. Seems like each rule definition might be a subclass of a super “Rule” or a “Member of group”-rule subclass.

(I did change all my function names to be unique – just to eliminate that as a source of noise in figuring this issue out…but NOT clear on the reasoning here.)

Also switched back to Jython 2.7.0

@bob_dickenson and @gitMiguel, in your code you created two function objects with the name, mainFunction, within the same scope. The second definition effectively overwrites the first within that scope. The decorators don’t replace mainFunction(), they simply wrap it. @5iver’s reasoning makes sense to me.

2 Likes

so you are saying that all “@rule” share the same scope–ergo all function names must be unique ? If that is so, then why allow function definitions outside of “@rule” since they all have the same scope. That just seems “wrong” and un-pythonic.

[Updated script to use repr(mainFunc), which shows that the location of mainFunc() changes from the first definition to the second.]

Yes, in this case all rules within your script share the same scope, as do the functions they wrap. The redefinition of the object known as mainFunction replaces the first definition, but the code from the first definition is not replaced, only the association of the global name mainFunction with that code is lost. After the second definition, the name mainFunction becomes associated with the code found in the body of the second definition. That’s not un-pythonic, that’s just how scope works in python. Here’s a simple script with its output that I hope illustrates what I’m trying to describe:

from org.slf4j import Logger, LoggerFactory

from openhab.rules import rule
from openhab.triggers import when


logger = LoggerFactory.getLogger("org.eclipse.smarthome.model.script.jsr223")

@rule("Rule 1")
@when("Member of gScene_Monitor_Scene_01 changed")
def mainFunction(event):
    logger.info("Rule 1 triggered by: %s" % event.itemName)
    logger.info("1st mainFunction def, objects at local scope:  %s" % ", ".join(locals()))
    logger.info("1st mainFunction def, objects at global scope: %s" % ", ".join(globals()))

logger.info("mainFunc: %s" % repr(mainFunction))
logger.info("objects at global scope: %s" % ", ".join(globals()))

@rule("Rule 2")
@when("Member of gScene_Monitor_Scene_02 changed")
def mainFunction(event):
    logger.info("Rule 2 triggered by: %s" % event.itemName)
    logger.info("2nd mainFunction def, objects at local scope:  %s" % ", ".join(locals()))
    logger.info("2nd mainFunction def, objects at global scope: %s" % ", ".join(globals()))

logger.info("mainFunc: %s" % repr(mainFunction))
logger.info("objects at global scope: %s" % ", ".join(globals()))
2018-11-17 07:53:09.534 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'explore-scope-vars.py'
2018-11-17 07:53:09.743 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: target=[Member of gScene_Monitor_Scene_01 changed], target_type=Member of, trigger_target=gScene_Monitor_Scene_01, trigger_type=changed, old_state=None, new_state=None
2018-11-17 07:53:09.759 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: Created item_trigger: [Item-OfcTblLamp-changed]
2018-11-17 07:53:09.763 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: Created item_trigger: [Item-OfficeFanLts-changed]
2018-11-17 07:53:09.766 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: Created item_trigger: [Item-TstLamp1-changed]
2018-11-17 07:53:09.769 [DEBUG] [omation.core.internal.RuleEngineImpl] - _FunctionRule: self.name: 
2018-11-17 07:53:09.784 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=664, service.bundleid=227, service.scope=singleton, event.topics=smarthome/items/OfcTblLamp/*} - org.eclipse.smarthome.automation.module.core
2018-11-17 07:53:09.796 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=665, service.bundleid=227, service.scope=singleton, event.topics=smarthome/items/OfficeFanLts/*} - org.eclipse.smarthome.automation.module.core
2018-11-17 07:53:09.807 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=666, service.bundleid=227, service.scope=singleton, event.topics=smarthome/items/TstLamp1/*} - org.eclipse.smarthome.automation.module.core
2018-11-17 07:53:09.815 [INFO ] [clipse.smarthome.model.script.jsr223] - mainFunc: <function mainFunction at 0x6>
2018-11-17 07:53:09.831 [INFO ] [clipse.smarthome.model.script.jsr223] - objects at global scope: Action, ActionBuilder, CLOSED, Command, Condition, ConditionBuilder, Configuration, DECREASE, DOWN, DateTimeType, DecimalType, FASTFORWARD, File, FileUtils, FilenameUtils, HSBType, INCREASE, ImperialUnits, IncreaseDecreaseType, Logger, LoggerFactory, MOVE, MetricPrefix, ModuleBuilder, NEXT, NULL, NextPreviousType, OFF, ON, OPEN, OnOffType, OpenClosedType, PAUSE, PLAY, PREVIOUS, PercentType, PlayPauseType, PointType, QuantityType, REWIND, RawType, RewindFastforwardType, Rule, SIUnits, STOP, SmartHomeUnits, State, StopMoveType, StringListType, StringType, StringUtils, Trigger, TriggerBuilder, UNDEF, UP, URLEncoder, UnDefType, UpDownType, __builtins__, audio, automationManager, events, ir, itemRegistry, items, logger, mainFunction, rule, ruleRegistry, rules, scriptExtension, se, things, voice, when
2018-11-17 07:53:09.838 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: target=[Member of gScene_Monitor_Scene_02 changed], target_type=Member of, trigger_target=gScene_Monitor_Scene_02, trigger_type=changed, old_state=None, new_state=None
2018-11-17 07:53:09.842 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: Created item_trigger: [Item-OfcTblLamp-changed]
2018-11-17 07:53:09.847 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: Created item_trigger: [Item-OfficeFanLts-changed]
2018-11-17 07:53:09.851 [DEBUG] [omation.core.internal.RuleEngineImpl] - @when: Created item_trigger: [Item-TstLamp1-changed]
2018-11-17 07:53:09.854 [DEBUG] [omation.core.internal.RuleEngineImpl] - _FunctionRule: self.name: 
2018-11-17 07:53:09.866 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=667, service.bundleid=227, service.scope=singleton, event.topics=smarthome/items/OfcTblLamp/*} - org.eclipse.smarthome.automation.module.core
2018-11-17 07:53:09.877 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=668, service.bundleid=227, service.scope=singleton, event.topics=smarthome/items/OfficeFanLts/*} - org.eclipse.smarthome.automation.module.core
2018-11-17 07:53:09.888 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=669, service.bundleid=227, service.scope=singleton, event.topics=smarthome/items/TstLamp1/*} - org.eclipse.smarthome.automation.module.core
2018-11-17 07:53:09.898 [INFO ] [clipse.smarthome.model.script.jsr223] - mainFunc: <function mainFunction at 0x7>
2018-11-17 07:53:09.904 [INFO ] [clipse.smarthome.model.script.jsr223] - objects at global scope: Action, ActionBuilder, CLOSED, Command, Condition, ConditionBuilder, Configuration, DECREASE, DOWN, DateTimeType, DecimalType, FASTFORWARD, File, FileUtils, FilenameUtils, HSBType, INCREASE, ImperialUnits, IncreaseDecreaseType, Logger, LoggerFactory, MOVE, MetricPrefix, ModuleBuilder, NEXT, NULL, NextPreviousType, OFF, ON, OPEN, OnOffType, OpenClosedType, PAUSE, PLAY, PREVIOUS, PercentType, PlayPauseType, PointType, QuantityType, REWIND, RawType, RewindFastforwardType, Rule, SIUnits, STOP, SmartHomeUnits, State, StopMoveType, StringListType, StringType, StringUtils, Trigger, TriggerBuilder, UNDEF, UP, URLEncoder, UnDefType, UpDownType, __builtins__, audio, automationManager, events, ir, itemRegistry, items, logger, mainFunction, rule, ruleRegistry, rules, scriptExtension, se, things, voice, when
2018-11-17 07:53:09.907 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: explore-scope-vars.py
2018-11-17 07:53:20.888 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Item-TstLamp1-received-update' of rule 'e8b03910-e9fa-4d55-8814-d50fe90c5421' is triggered.
2018-11-17 07:53:20.979 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule 'e8b03910-e9fa-4d55-8814-d50fe90c5421' is executed.
2018-11-17 07:53:21.004 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Item-TstLamp1-changed' of rule '82dbd384-3348-4397-9ac0-94c1814546c5' is triggered.
2018-11-17 07:53:21.007 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Item-TstLamp1-changed' of rule 'cd0c197d-ca04-445e-97f6-fdbb8ecbb5dc' is triggered.
2018-11-17 07:53:21.014 [INFO ] [clipse.smarthome.model.script.jsr223] - Rule 1 triggered by: TstLamp1
2018-11-17 07:53:21.014 [INFO ] [clipse.smarthome.model.script.jsr223] - Rule 2 triggered by: TstLamp1
2018-11-17 07:53:21.027 [INFO ] [clipse.smarthome.model.script.jsr223] - 1st mainFunction def, objects at local scope:  event
2018-11-17 07:53:21.027 [INFO ] [clipse.smarthome.model.script.jsr223] - 2nd mainFunction def, objects at local scope:  event
2018-11-17 07:53:21.034 [INFO ] [clipse.smarthome.model.script.jsr223] - 1st mainFunction def, objects at global scope: Action, ActionBuilder, CLOSED, Command, Condition, ConditionBuilder, Configuration, DECREASE, DOWN, DateTimeType, DecimalType, FASTFORWARD, File, FileUtils, FilenameUtils, HSBType, INCREASE, ImperialUnits, IncreaseDecreaseType, Logger, LoggerFactory, MOVE, MetricPrefix, ModuleBuilder, NEXT, NULL, NextPreviousType, OFF, ON, OPEN, OnOffType, OpenClosedType, PAUSE, PLAY, PREVIOUS, PercentType, PlayPauseType, PointType, QuantityType, REWIND, RawType, RewindFastforwardType, Rule, SIUnits, STOP, SmartHomeUnits, State, StopMoveType, StringListType, StringType, StringUtils, Trigger, TriggerBuilder, UNDEF, UP, URLEncoder, UnDefType, UpDownType, __builtins__, audio, automationManager, events, ir, itemRegistry, items, logger, mainFunction, rule, ruleRegistry, rules, scriptExtension, se, things, voice, when
2018-11-17 07:53:21.036 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule '82dbd384-3348-4397-9ac0-94c1814546c5' is executed.
2018-11-17 07:53:21.053 [INFO ] [clipse.smarthome.model.script.jsr223] - 2nd mainFunction def, objects at global scope: Action, ActionBuilder, CLOSED, Command, Condition, ConditionBuilder, Configuration, DECREASE, DOWN, DateTimeType, DecimalType, FASTFORWARD, File, FileUtils, FilenameUtils, HSBType, INCREASE, ImperialUnits, IncreaseDecreaseType, Logger, LoggerFactory, MOVE, MetricPrefix, ModuleBuilder, NEXT, NULL, NextPreviousType, OFF, ON, OPEN, OnOffType, OpenClosedType, PAUSE, PLAY, PREVIOUS, PercentType, PlayPauseType, PointType, QuantityType, REWIND, RawType, RewindFastforwardType, Rule, SIUnits, STOP, SmartHomeUnits, State, StopMoveType, StringListType, StringType, StringUtils, Trigger, TriggerBuilder, UNDEF, UP, URLEncoder, UnDefType, UpDownType, __builtins__, audio, automationManager, events, ir, itemRegistry, items, logger, mainFunction, rule, ruleRegistry, rules, scriptExtension, se, things, voice, when
2018-11-17 07:53:21.058 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule 'cd0c197d-ca04-445e-97f6-fdbb8ecbb5dc' is executed.
2018-11-17 07:53:23.710 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Item-TstLamp1-received-update' of rule 'e8b03910-e9fa-4d55-8814-d50fe90c5421' is triggered.
2018-11-17 07:53:23.717 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule 'e8b03910-e9fa-4d55-8814-d50fe90c5421' is executed.

Note that in the logs of globals, there is only one entry for mainFunction.

2 Likes

@5iver I was trying out some rules based on the timers example, using the jython modules. If I create a Timer object inside my rule function as below, everything works fine and as per the example script, and the timer object type is org.python.core.FunctionThread:

import inspect
from datetime import datetime
from threading import Timer

from openhab.rules import rule
from openhab.triggers import when
from openhab.log import logging

LOG_BASE = "org.eclipse.smarthome.model.script.JS223.test"
hw_timer = None

@rule("Motion Sensor Triggered")
@when ("Member of gMotionSensor received update")
def gMotionSensorItemChanged(event):
    log = logging.getLogger(LOG_BASE + "." + inspect.currentframe().f_code.co_name)

    global hw_timer

    if event.itemName == "Hallway_MotionSensor":
            if hw_timer:
                log.info("hw_timer exists. State: {}, type: {}".format(hw_timer, type(hw_timer)))
                if str(hw_timer.getState()) == "TIMED_WAITING":
                    # log.info("Cancelling hw_timer timer [{}]...".format(hw_timer.name))
                    hw_timer.stop()

            if not hw_timer or str(hw_timer.getState()) != "TIMED_WAITING":
                timername = 'hw_timer: ' + str(datetime.now())
                hw_timer = Timer(30, motionsensor_timeout, [timername])
                hw_timer.setName(timername)
                hw_timer.start()
                log.info("hw_timer [{}] started (type: {})".format(hw_timer.name, type(hw_timer)))
   ....etc....

However, if I create the timer from inside a class object (within the same script file), the timer object type now shows as threading._Timer, which has different methods than the previous timer type outside of the class, org.python.core.FunctionThread, e.g. timer state is now just a boolean .is_alive() etc.

However, if I use the openHAB timer action instead, this works consistently both within the standard rule function and within the class object.

Is there anyway I can use the original jython timer correctly from within a class object?

Could you please post an example?

You can use Jython timers from a class. Simply assign as a class variable. It looks like you are trying to track occupancy by picking up motion events. I am doing this using events and classes.

import inspect
from collections import namedtuple

from datetime import datetime
from threading import Timer

from openhab.rules import rule
from openhab.triggers import when
from openhab.log import logging

LOG_BASE = "org.eclipse.smarthome.model.script.JS223.test"
controlled_item = None

class MotionControl():
   
    def __init__(self, sensor_name, lightitem_name, timeout_period = 20):
        log = logging.getLogger(LOG_BASE + ".MotionControlClass_" + sensor_name + "_" + inspect.currentframe().f_code.co_name)

        # self.log.info("__init__ called")
        self.sensor = ir.getItem(sensor_name)
        self.name = sensor_name
        self.lightitem = ir.getItem(lightitem_name)
        self.timer = None
        self.timeoutperiod = timeout_period

    def start_timer(self):
        log = logging.getLogger(LOG_BASE + ".MotionControlClass_" + self.sensor.name + "_" + inspect.currentframe().f_code.co_name)
        # self.log.info("start_timer called")
        # if not self.timer or str(self.timer.getState()) != "TIMED_WAITING":

        if  self.timer and self.timer.is_alive(): #str(self.timer.getState()) == "TIMED_WAITING":
                log.info("{}: Cancelling existing timer".format(self.timer.name))
                self.timer.cancel()
            
        self.name = "Timer_" + str(self.sensor.name) + '_' + str(datetime.now())
        self.timer = Timer(self.timeoutperiod, self._timeout)           
        self.timer.name = self.name
        self.timer.start()

        log.info("{}: Started".format(self.name))
        log.info("{}: type: {}".format(self.name, type(self.timer)))

    def _timeout(self):
        log = logging.getLogger(LOG_BASE + ".MotionControlClass_" + self.name + "_" + inspect.currentframe().f_code.co_name)
        log.info(self.name + ": _timeout function called")

Yes, I am looking to migrate my (massive) DSL rule which currently manages 9 motion sensors and corresponding lights, over to Jython to see if it improves performance. I think I’ve got the basics worked out, but was wondering why the timer type changes when inside a class, and how to keep things consistent.

Thanks @5iver and @mjcumming.

Here is what the timer code looks like from my class. I don’t know the is_alive is a method for a Timer but you do need to check to cancel a timer. Also, I would do an inline function like below and not point the timer to a method of your class. See below.


    def start_timer(self, time_out_seconds):
        time_started = datetime.datetime.now()

        def timeout_callback():
            log.info("Occupancy timer for area {} expired, timer was started at {}".format(self.name,time_started)) 
            self.set_area_vacant('Timer Expired')
            self.occupancy_timer = None
            self.occupancy_timeout = None        

        if self.occupancy_timer is not None:
            #log.info("Occupancy timer for area {} canceled".format(self.name)) 
            self.occupancy_timer.cancel()
            self.occupancy_timer = None
            self.occupancy_timeout = None

        self.occupancy_timer = Timer(time_out_seconds, timeout_callback)
        self.occupancy_timer.start()
        self.occupancy_timeout = datetime.datetime.now() + datetime.timedelta(seconds=time_out_seconds)
        log.info("Occupancy Timer for area {} expires at {}".format(self.name,self.occupancy_timeout))

    def cancel_timer(self):
        #log.info ("Occupancy timer for area {} canceled".format(self.name))
        if self.occupancy_timer is not None:
            self.occupancy_timer.cancel()
            self.occupancy_timer = None
            self.occupancy_timeout = None
2 Likes

Thanks @mjcumming .

It looks as if your Timer instance is also the python’s threading._Timer type (https://docs.python.org/2/library/threading.html#timer-objects) and not org.python.core.FunctionThread, which would be the type if the Timer was instantiated outside of the class, as in the jython sample files (https://github.com/OH-Jython-Scripters/openhab2-jython/blob/master/Script%20Examples/timer_example.py).

I’m guessing this as the method you use to cancel the timer is .cancel() in the same way that I have, and not .stop() as in the jython sample file.

Again, any ideas as to why the different types of Timers, depending on whether it is created in the main body of the script or from within a class? It is not an issue for me, as as long as I know which type is being used, as then I can use the appropriate methods etc, but just wanting to understand.

Yes, that makes sense - thanks for pointing out.

I don’t know if there is a reason to choose one timer over the other - unless the Java timer is limited by the number of threads allocated by OH for rule execution. I don’t believe we know if Jython is impacted by thread allocation limits in OH.

I have taken the approach (rightly or wrongly) to use Python modules and convert variables to Python types in my Jython code. Otherwise there were too many gotcha’s.

2 Likes

I don’t have much experience of jython but had assumed (probably incorrectly) that as it is byte compiled to java, the java modules may be more efficient.

That’s useful to know and keep in mind.