[SOLVED] Global name 'events' is not defined in <script>

lukics · May 16, 2019, 3:41pm

Making my first steps in js223 and jython.

I have following test setup (nothing productive just a toggle of a switch item):

in lib/python/personal/myLib.py

def turnOFF(itm):
    from core.log import logging, LOG_PREFIX
    log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")
    log.info("timer fired")
    events.sendCommand(itm,"OFF") 
    return None

in jsr223/personal/testTimer.py

from threading import Timer
from core.log import logging, LOG_PREFIX
from  personal.myLib import  myLog, timerOff, turnOFF
 
log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")

events.sendCommand("ProxySwitch","ON")  
Timer(4, turnOFF(ir.getItem("ProxySwitch"))).start()
log.info("timer initiated")

when I save/run testTimer.py I get an error in the log

2019-05-16 17:39:18.615 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'personal/testTimer.py'
2019-05-16 17:39:18.747 [INFO ] [jsr223.jython.this.is.my.log        ] - timer fired
2019-05-16 17:39:18.754 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/openhab/conf/automation/jsr223/personal/testTimer.py': NameError: global name 'events' is not defined in <script> at line number 8
2019-05-16 17:39:18.758 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: personal/testTimer.py

I seems that “events” is globally not in scope to the loaded library myLib.
I hope I do not need to pass events all over?

5iver · May 16, 2019, 4:05pm

Modules have nothing in their context. More detail on the jsr223 module. You will need to use…

from core.jsr223 import scope
scope.events.sendCommand(itm,"OFF")

Also, just send the Item’s name here and you need to use a lambda…

Timer(4, lambda: turnOFF("ProxySwitch")).start()

lukics · May 16, 2019, 4:26pm

I was disappointed to realise that lambdas are capable to hold just one command (no multiline)

5iver · May 16, 2019, 4:29pm

Adding the function is a bit of a pain, but they’re reusable.

lukics · May 16, 2019, 5:39pm

I cannot explain this strange behaviour:

In the setup obove the timer is in testTimer.py the function inside the lambada is implemented in myLib.py
This way it works

When move the timer initialisation into a fuction in myLib.py it behaves different:

in lib/python/personal/myLib.py

def timerOff(itm, timeout):
    from core.log import logging, LOG_PREFIX
    from threading import Timer
    log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")
    Timer(timeout, lambda: turnOFF(itm)).start()
    log.info("timer initiated! item : " + str(itm))
    return None

def turnOFF(itm):
    from core.jsr223 import scope
    from core.log import logging, LOG_PREFIX
    log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")
    log.info("Before sendCommand")
    scope.events.sendCommand(itm,"OFF")
    log.info("After sendCommand")
    return None

in jsr223/personal/testTimer.py

import personal.myLib
reload(personal.myLib)
import personal.myLib
from threading import Timer
from core.log import logging, LOG_PREFIX
from  personal.myLib import  myLog, timerOff, turnOFF
 
log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")

events.sendCommand("ProxySwitch","ON")   
#Timer(10, lambda: turnOFF(ir.getItem("ProxySwitch"))).start()
timerOff(ir.getItem("ProxySwitch"), 3) 

log.info("timer initiated")

the log output

2019-05-16 19:34:30.987 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'personal/testTimer.py'
2019-05-16 19:34:31.173 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated! item : ProxySwitch (Type=SwitchItem, State=ON, Label=Proxy Switch, Category=null)
2019-05-16 19:34:31.182 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated
2019-05-16 19:34:31.186 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: personal/testTimer.py
2019-05-16 19:34:34.178 [INFO ] [jsr223.jython.this.is.my.log        ] - Before sendCommand

scope.events.sendCommand(itm,“OFF”) never executes
if I switch to Timer(10, lambda: turnOFF(ir.getItem(“ProxySwitch”))).start()

#events.sendCommand("ProxySwitch","ON")   
Timer(3, lambda: turnOFF(ir.getItem("ProxySwitch"))).start()

the log is

2019-05-16 19:37:53.997 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'personal/testTimer.py'
2019-05-16 19:37:54.160 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated! item : ProxySwitch (Type=SwitchItem, State=ON, Label=Proxy Switch, Category=null)
2019-05-16 19:37:54.168 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated
2019-05-16 19:37:54.171 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: personal/testTimer.py
==> /openhab/userdata/logs/events.log <==
2019-05-16 19:37:57.220 [ome.event.ItemCommandEvent] - Item 'ProxySwitch' received command OFF
2019-05-16 19:37:57.236 [vent.ItemStateChangedEvent] - ProxySwitch changed from ON to OFF
2019-05-16 19:37:57.256 [.event.RuleStatusInfoEvent] - 972e18bb-1b66-45cb-99f6-fe89c8801684 updated: RUNNING
2019-05-16 19:37:57.263 [ome.event.ItemCommandEvent] - Item 'ProxySwitchText' received command Proxy gone to OFF
2019-05-16 19:37:57.269 [.event.RuleStatusInfoEvent] - 972e18bb-1b66-45cb-99f6-fe89c8801684 updated: IDLE
2019-05-16 19:37:57.293 [vent.ItemStateChangedEvent] - ProxySwitchText changed from Proxy gone to ON to Proxy gone to OFF
==> /openhab/userdata/logs/openhab.log <==
2019-05-16 19:37:57.177 [INFO ] [jsr223.jython.this.is.my.log        ] - Before sendCommand
2019-05-16 19:37:57.194 [INFO ] [jsr223.jython.this.is.my.log        ] - Before sendCommand
2019-05-16 19:37:57.210 [INFO ] [jsr223.jython.this.is.my.log        ] - After sendCommand
2019-05-16 19:37:57.239 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Item-ProxySwitch-changed' of rule '972e18bb-1b66-45cb-99f6-fe89c8801684' is triggered.
2019-05-16 19:37:57.261 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule '972e18bb-1b66-45cb-99f6-fe89c8801684' is executed.

No guess why tis is this way

5iver · May 16, 2019, 9:55pm

You don’t need these.

It’s usually best to put imports outside the function to speed things up and to reuse them

Use format. The + operator is slower and you won’t need to convert to str…

log.info("timer initiated! item : [{}]".format(itm))

But again… stop sending the Item and just use the name for the Item.

There is also a rule running here, but there is no rule in the script, so you must not be sharing everything that is going on. Hard to figure things out without the whole picture…

lukics · May 17, 2019, 12:40pm

I reformated as suggested:

myLib.py

from core.jsr223 import scope
from core.log import logging, LOG_PREFIX
from threading import Timer
log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")

def turnOFF(itm):
    log.info("Before sendCommand")
    scope.events.sendCommand(itm,"OFF")
    log.info("After sendCommand")

def timerOff(itm, timeout):
    Timer(timeout, lambda: turnOFF(itm)).start()
    log.info("timer initiated! item : [{}]".format(itm))

testTimer.py

import personal.myLib
reload(personal.myLib)
import personal.myLib
from threading import Timer
from core.log import logging, LOG_PREFIX
from  personal.myLib import  myLog, timerOff, turnOFF
from core.rules import rule
from core.triggers import when
 
log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")

@rule("test time rule", tags=["Tag 1", "Tag 2"])
@when("Channel homematic:HM-PB-6-WM55:3014F711A061A7D5698CE994:NEQ1001667:1#BUTTON triggered SHORT_PRESSED")
@when("Channel homematic:HM-PB-6-WM55:3014F711A061A7D5698CE994:NEQ1001667:1#BUTTON triggered DOUBLE_PRESSED")
def testChannelFnc(event):
    events.sendCommand("ProxySwitch","ON")   
    #Timer(3, lambda: turnOFF(ir.getItem("ProxySwitch"))).start()
    timerOff("ProxySwitch", 3) 
    log.info("timer initiated")

log output when “timerOff(“ProxySwitch”, 3)” is called --> Before sendCommnd stuck

==> /openhab/userdata/logs/events.log <==
2019-05-17 14:30:24.366 [vent.ChannelTriggeredEvent] - homematic:HM-PB-6-WM55:3014F711A061A7D5698CE994:NEQ1001667:1#BUTTON triggered SHORT_PRESSED
2019-05-17 14:30:24.382 [.event.RuleStatusInfoEvent] - 8d58068a-72e2-40c5-9b57-9f3069ff97f5 updated: RUNNING
2019-05-17 14:30:24.398 [ome.event.ItemCommandEvent] - Item 'ProxySwitch' received command ON
2019-05-17 14:30:24.431 [.event.RuleStatusInfoEvent] - 8d58068a-72e2-40c5-9b57-9f3069ff97f5 updated: IDLE
==> /openhab/userdata/logs/openhab.log <==
2019-05-17 14:30:24.376 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Channel-homematic_HM-PB-6-WM55_3014F711A061A7D5698CE994_NEQ1001667_1_BUTTON-triggered-SHORT_PRESSED' of rule '8d58068a-72e2-40c5-9b57-9f3069ff97f5' is triggered.
2019-05-17 14:30:24.404 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated! item : [ProxySwitch]
2019-05-17 14:30:24.422 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated
2019-05-17 14:30:24.426 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule '8d58068a-72e2-40c5-9b57-9f3069ff97f5' is executed.
2019-05-17 14:30:27.427 [INFO ] [jsr223.jython.this.is.my.log        ] - Before sendCommand

log ouput when “Timer(3, lambda: turnOFF(ir.getItem(“ProxySwitch”))).start()” is called (commented out above) --> complete execution

==> /openhab/userdata/logs/events.log <==
2019-05-17 14:32:49.117 [vent.ChannelTriggeredEvent] - homematic:HM-PB-6-WM55:3014F711A061A7D5698CE994:NEQ1001667:1#BUTTON triggered SHORT_PRESSED
2019-05-17 14:32:49.134 [.event.RuleStatusInfoEvent] - 1d20b4fd-5faf-4a36-9ee4-448118a7b90d updated: RUNNING
2019-05-17 14:32:49.150 [ome.event.ItemCommandEvent] - Item 'ProxySwitch' received command ON
2019-05-17 14:32:49.198 [.event.RuleStatusInfoEvent] - 1d20b4fd-5faf-4a36-9ee4-448118a7b90d updated: IDLE
==> /openhab/userdata/logs/openhab.log <==
2019-05-17 14:32:49.115 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger 'Channel-homematic_HM-PB-6-WM55_3014F711A061A7D5698CE994_NEQ1001667_1_BUTTON-triggered-SHORT_PRESSED' of rule '1d20b4fd-5faf-4a36-9ee4-448118a7b90d' is triggered.
2019-05-17 14:32:49.190 [INFO ] [jsr223.jython.this.is.my.log        ] - timer initiated
2019-05-17 14:32:49.194 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule '1d20b4fd-5faf-4a36-9ee4-448118a7b90d' is executed.
==> /openhab/userdata/logs/events.log <==
2019-05-17 14:32:52.231 [ome.event.ItemCommandEvent] - Item 'ProxySwitch' received command OFF
2019-05-17 14:32:52.246 [vent.ItemStateChangedEvent] - ProxySwitch changed from ON to OFF
==> /openhab/userdata/logs/openhab.log <==
2019-05-17 14:32:52.218 [INFO ] [jsr223.jython.this.is.my.log        ] - Before sendCommand
2019-05-17 14:32:52.242 [INFO ] [jsr223.jython.this.is.my.log        ] - After sendCommand

It seems that there is a context missing when Timer is initiated outside the rule file

lukics · May 17, 2019, 1:02pm

added exception handling:

def turnOFF(itm):
    try:
        log.info("Before sendCommand")
        scope.events.sendCommand(itm,"OFF")
        log.info("After sendCommand")
    except:    
        log.info("!!!!!Exception caught!!!!!!!")
        core.JythonExtensionProvider = None
        import traceback
        log.error(traceback.format_exc())

log

......
2019-05-17 14:59:28.928 [INFO ] [jsr223.jython.this.is.my.log        ] - Before sendCommand
2019-05-17 14:59:28.971 [INFO ] [jsr223.jython.this.is.my.log        ] - !!!!!Exception caught!!!!!!!
2019-05-17 14:59:29.007 [ERROR] [jsr223.jython.this.is.my.log        ] - Traceback (most recent call last):
  File "/openhab/conf/automation/lib/python/personal/myLib.py", line 26, in turnOFF
    scope.events.sendCommand(itm,"OFF")
  File "/openhab/conf/automation/lib/python/core/jsr223.py", line 28, in __getattr__
    scope = get_scope()
  File "/openhab/conf/automation/lib/python/core/jsr223.py", line 14, in get_scope
    raise EnvironmentError("No JSR223 scope is available")
EnvironmentError: No JSR223 scope is available

Seems that when the call stack is:
rule -> custom module -> function -> Timer -> function -> imported scope is lost
rule -> Timer -> custom module -> function -> imported scope is ok
rule -> custom module -> function -> function -> imported scope ist ok

That means that if timer is called inside a custom module the scope is lost
how to pass scope here?

5iver · May 17, 2019, 7:15pm

This is getting a bit beyond my knowledge level, so my explanation may not be accurate, but this is how I understand this behavior. A timer runs in it’s own thread and inherits its context from the module or script that it was called from, at the time it is started. At the time it is called from a module, core.jsr223.scope goes out to the script context that loaded the module to find what you are asking for. That obviously breaks in a timer, since the script is unreachable (different thread, different context). The solution, is to load what the timer needs into the module context before it is started…

from core.jsr223.scope import events

In your script, you don’t need to import core.log fro logging inside the rule function, since core.rules.rule adds it as an attribute…

testChannelFnc.log.info("timer initiated")

Take a look at core.log.log_traceback. This is a decorator that basically wraps functions in a try/except and logs the exception. If you’ve set adminEmail in configuration.py and have myopenhab setup, you’ll get a notification when errors occur. All rule functions are wrapped with this too. The logging of exceptions occurring in a module is discussed here, and I’ve submitted an OH PR that may help, but it will need to be reworked before it will be accepted.

lukics · May 17, 2019, 7:37pm

I do not understand this?

5iver · May 17, 2019, 7:39pm

Try this…

from core.jsr223.scope import events
from core.log import logging, LOG_PREFIX
from threading import Timer
log = logging.getLogger(LOG_PREFIX + ".this.is.my.log")

def turnOFF(itm):
    log.info("Before sendCommand")
    events.sendCommand(itm,"OFF")
    log.info("After sendCommand")

def timerOff(itm, timeout):
    Timer(timeout, turnOFF, [itm]).start()
    log.info("timer initiated! item : [{}]".format(itm))

Edit: It will work with the lambda, but this is more proper (I always forget the format and just use lambdas ).

lukics · May 17, 2019, 7:43pm

Works, thanks