[SOLVED] jython - LogAction not working

I can’t get LogAction to work.

I’m currently running a recent snapshot: openHAB 2.5.0 Build #1624.

Here’s the manual.

Minimal example:

"""
This is a test rule.
"""

from core.rules import rule
from core.triggers import when

# Logging:
from core.actions import LogAction

@rule("myRuleTest - System started", description="Initialize globals when the rule is reloaded")
@when("System started")
def myRuleTest_SystemStarted(event):
    LogAction.logInfo("EXAMPLE", "myRuleTest_SystemStarted() - START")

Log output:

2019-06-27 19:29:25.171 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {groovy=[file:/etc/openhab2/automation/jsr223/groovy/core/000_startup_delay.groovy], md=[file:/etc/openhab2/automation/jsr223/python/personal/README.md, file:/etc/openhab2/automation/jsr223/groovy/community/README.md, file:/etc/openhab2/automation/jsr223/javascript/personal/README.md, file:/etc/openhab2/automation/jsr223/python/community/README.md, file:/etc/openhab2/automation/jsr223/javascript/community/README.md, file:/etc/openhab2/automation/jsr223/groovy/personal/README.md]}
2019-06-27 19:29:25.181 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/test.py'
2019-06-27 19:29:25.187 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/personal/test.py
2019-06-27 19:29:25.331 [ERROR] [org.openhab.core.ephemeris          ] - bundle org.openhab.core.ephemeris:2.5.0.201906270306 (147)[org.openhab.ephemeris(76)] : The activate method has thrown an exception
java.lang.IllegalArgumentException: No enum constant java.time.DayOfWeek."MONDAY
	at java.lang.Enum.valueOf(Enum.java:238) ~[?:?]
	at java.time.DayOfWeek.valueOf(DayOfWeek.java:109) ~[?:?]
	at org.eclipse.smarthome.core.ephemeris.internal.EphemerisManagerImpl.lambda$2(EphemerisManagerImpl.java:104) ~[?:?]
	at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948) ~[?:?]
	at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580) ~[?:?]
	at org.eclipse.smarthome.core.ephemeris.internal.EphemerisManagerImpl.lambda$1(EphemerisManagerImpl.java:103) ~[?:?]
	at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) ~[?:?]
	at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:?]
	at java.util.Iterator.forEachRemaining(Iterator.java:116) ~[?:?]
	at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) ~[?:?]
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:?]
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:?]
	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) ~[?:?]
	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) ~[?:?]
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
	at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418) ~[?:?]
	at org.eclipse.smarthome.core.ephemeris.internal.EphemerisManagerImpl.modified(EphemerisManagerImpl.java:98) ~[?:?]
	at org.eclipse.smarthome.core.ephemeris.internal.EphemerisManagerImpl.activate(EphemerisManagerImpl.java:93) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:340) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:982) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:955) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:86) ~[?:?]
	at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:664) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2308) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.prebind(DependencyManager.java:1154) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1568) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1029) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:935) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:186) ~[?:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:204) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:478) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:482) ~[?:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:141) ~[?:?]
	at core.osgi$py.find_services$2(/etc/openhab2/automation/lib/python/core/osgi/__init__.py:24) ~[?:?]
	at core.osgi$py.call_function(/etc/openhab2/automation/lib/python/core/osgi/__init__.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:153) ~[?:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:423) ~[?:?]
	at core.actions$py.f$0(/etc/openhab2/automation/lib/python/core/actions.py:40) ~[?:?]
	at core.actions$py.call_function(/etc/openhab2/automation/lib/python/core/actions.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
	at org.python.core.imp.createFromCode(imp.java:436) ~[?:?]
	at org.python.core.imp.createFromPyClass(imp.java:236) ~[?:?]
	at org.python.core.imp.createFromPyClass(imp.java:205) ~[?:?]
	at org.python.core.imp.loadFromSource(imp.java:651) ~[?:?]
	at org.python.core.imp.find_module(imp.java:543) ~[?:?]
	at org.python.core.PyModule.impAttr(PyModule.java:106) ~[?:?]
	at org.python.core.imp.import_next(imp.java:842) ~[?:?]
	at org.python.core.imp.import_logic(imp.java:904) ~[?:?]
	at org.python.core.imp.import_module_level(imp.java:978) ~[?:?]
	at org.python.core.imp.importName(imp.java:1062) ~[?:?]
	at org.python.core.ImportFunction.__call__(__builtin__.java:1280) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:431) ~[?:?]
	at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
	at org.python.core.imp.importFromAs(imp.java:1156) ~[?:?]
	at org.python.core.imp.importFrom(imp.java:1132) ~[?:?]
	at org.python.pycode._pyx186.f$0(<script>:11) ~[?:?]
	at org.python.pycode._pyx186.call_function(<script>) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
	at org.python.core.Py.runCode(Py.java:1386) ~[?:?]
	at org.python.core.__builtin__.eval(__builtin__.java:497) ~[?:?]
	at org.python.core.__builtin__.eval(__builtin__.java:501) ~[?:?]
	at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:259) ~[?:?]
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:40) ~[?:?]
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:47) ~[?:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:249) ~[?:?]
	at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:147) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:177) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:144) ~[?:?]
	at org.eclipse.smarthome.core.service.WatchQueueReader.lambda$3(WatchQueueReader.java:323) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-06-27 19:29:25.498 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/python/personal/test.py': AttributeError: 'NoneType' object has no attribute 'actionClass' in <script> at line number 9
2019-06-27 19:29:25.480 [WARN ] [org.openhab.core.ephemeris          ] - FrameworkEvent WARNING - org.openhab.core.ephemeris
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:86) ~[?:?]
	at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:664) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2308) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.prebind(DependencyManager.java:1154) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1568) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1029) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:935) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:186) ~[?:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:204) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:478) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:482) ~[?:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:141) ~[?:?]
	at core.osgi$py.find_services$2(/etc/openhab2/automation/lib/python/core/osgi/__init__.py:24) ~[?:?]
	at core.osgi$py.call_function(/etc/openhab2/automation/lib/python/core/osgi/__init__.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:153) ~[?:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:423) ~[?:?]
	at core.actions$py.f$0(/etc/openhab2/automation/lib/python/core/actions.py:40) ~[?:?]
	at core.actions$py.call_function(/etc/openhab2/automation/lib/python/core/actions.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
	at org.python.core.imp.createFromCode(imp.java:436) ~[?:?]
	at org.python.core.imp.createFromPyClass(imp.java:236) ~[?:?]
	at org.python.core.imp.createFromPyClass(imp.java:205) ~[?:?]
	at org.python.core.imp.loadFromSource(imp.java:651) ~[?:?]
	at org.python.core.imp.find_module(imp.java:543) ~[?:?]
	at org.python.core.PyModule.impAttr(PyModule.java:106) ~[?:?]
	at org.python.core.imp.import_next(imp.java:842) ~[?:?]
	at org.python.core.imp.import_logic(imp.java:904) ~[?:?]
	at org.python.core.imp.import_module_level(imp.java:978) ~[?:?]
	at org.python.core.imp.importName(imp.java:1062) ~[?:?]
	at org.python.core.ImportFunction.__call__(__builtin__.java:1280) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:431) ~[?:?]
	at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
	at org.python.core.imp.importFromAs(imp.java:1156) ~[?:?]
	at org.python.core.imp.importFrom(imp.java:1132) ~[?:?]
	at org.python.pycode._pyx186.f$0(<script>:11) ~[?:?]
	at org.python.pycode._pyx186.call_function(<script>) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
	at org.python.core.Py.runCode(Py.java:1386) ~[?:?]
	at org.python.core.__builtin__.eval(__builtin__.java:497) ~[?:?]
	at org.python.core.__builtin__.eval(__builtin__.java:501) ~[?:?]
	at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:259) ~[?:?]
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:40) ~[?:?]
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:47) ~[?:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:249) ~[?:?]
	at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:147) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:177) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:144) ~[?:?]
	at org.eclipse.smarthome.core.service.WatchQueueReader.lambda$3(WatchQueueReader.java:323) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:?]
	at java.lang.Thread.run(Thread.java:748) ~[?:?]
2019-06-27 19:29:25.542 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: python/personal/test.py
2019-06-27 19:29:25.544 [WARN ] [org.openhab.core.model.script       ] - FrameworkEvent WARNING - org.openhab.core.model.script
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:186) ~[?:?]
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:204) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:478) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:482) ~[?:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:141) ~[?:?]
	at core.osgi$py.find_services$2(/etc/openhab2/automation/lib/python/core/osgi/__init__.py:24) ~[?:?]
	at core.osgi$py.call_function(/etc/openhab2/automation/lib/python/core/osgi/__init__.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:153) ~[?:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:423) ~[?:?]
	at core.actions$py.f$0(/etc/openhab2/automation/lib/python/core/actions.py:40) ~[?:?]
	at core.actions$py.call_function(/etc/openhab2/automation/lib/python/core/actions.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
	at org.python.core.imp.createFromCode(imp.java:436) ~[?:?]
	at org.python.core.imp.createFromPyClass(imp.java:236) ~[?:?]
	at org.python.core.imp.createFromPyClass(imp.java:205) ~[?:?]
	at org.python.core.imp.loadFromSource(imp.java:651) ~[?:?]
	at org.python.core.imp.find_module(imp.java:543) ~[?:?]
	at org.python.core.PyModule.impAttr(PyModule.java:106) ~[?:?]
	at org.python.core.imp.import_next(imp.java:842) ~[?:?]
	at org.python.core.imp.import_logic(imp.java:904) ~[?:?]
	at org.python.core.imp.import_module_level(imp.java:978) ~[?:?]
	at org.python.core.imp.importName(imp.java:1062) ~[?:?]
	at org.python.core.ImportFunction.__call__(__builtin__.java:1280) ~[?:?]
	at org.python.core.PyObject.__call__(PyObject.java:431) ~[?:?]
	at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
	at org.python.core.imp.importFromAs(imp.java:1156) ~[?:?]
	at org.python.core.imp.importFrom(imp.java:1132) ~[?:?]
	at org.python.pycode._pyx186.f$0(<script>:11) ~[?:?]
	at org.python.pycode._pyx186.call_function(<script>) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
	at org.python.core.Py.runCode(Py.java:1386) ~[?:?]
	at org.python.core.__builtin__.eval(__builtin__.java:497) ~[?:?]
	at org.python.core.__builtin__.eval(__builtin__.java:501) ~[?:?]
	at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:259) ~[?:?]
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:40) ~[?:?]
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:47) ~[?:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:249) ~[?:?]
	at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:147) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:177) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:144) ~[?:?]
	at org.eclipse.smarthome.core.service.WatchQueueReader.lambda$3(WatchQueueReader.java:323) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:?]
	at java.lang.Thread.run(Thread.java:748) ~[?:?]

What am I doing wrong?

I’m on S1624 and your example runs fine. However, I do not have Ephemeris installed, as it still has some issues. It must also be implementing an Action that either has problems or core.actions will need to be adjusted for. My suggestion is to remove Ephemeris or not use core.actions.

The rule decorator adds a log attribute to the decorated function, so you can just do this…

myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START")

… to get…

2019-06-27 14:09:48.052 [INFO ] [jsr223.jython.myRuleTest - System started] - myRuleTest_SystemStarted() - START

I never installed Ephemeris, it appeared out of the blue in a snapshot released in June. But it invariably keeps emitting lots of logfile noise.

Sadly there’s nowhere a clue how to disable or uninstall Ephemeris.

Here’s what I see on the Karaf console:

openhab> bundle:list | grep -i ephe
147 │ Waiting │  80 │ 2.5.0.201906270306    │ openHAB Core :: Bundles :: Ephemeris
openhab> feature:list | grep -i ephe
openhab-core-ephemeris                            │ 2.5.0.SNAPSHOT   │          │ Started     │ distro-2.5.0-SNAPSHOT         │

I know, but I’m tracking down a couple of Jython logging problems. For instance, in many cases I can’t render len(myList) in a "{}" substitution. so I wanted to see if I could use a different logger exposed to Jython and see if this way I can avoid these confusing errors.

Look into str.format() (oops… not the link I intended… https://docs.python.org/2/library/string.html#custom-string-formatting). It will do conversions and makes it easy to concatenate…

myRuleTest_SystemStarted.log.info("Test [{}]".format(len(myList)))

That wasn’t working either. It invariably threw the same exception:

019-06-27 13:59:45.091 [ERROR] [Rule Title] - Traceback (most recent call last):
  File "/etc/openhab2/automation/lib/python/core/log.py", line 51, in wrapper
    return fn(*args, **kwargs)
  File "<script>", line NN, in RuleName
TypeError: info(): 1st arg can't be coerced to org.slf4j.Marker

What is the line in the script?

I see! I thought this was a binding, but looks like a core feature

147 x Active x  80 x 2.5.0.201906270306    x org.openhab.core.ephemeris

I don’t see those errors in S1624, and there has been a bit of activity recently for ephemeris in the core repo. But nothing in the docs :roll_eyes:! Which version are you running?

I don’t have that code anymore as it was not working. I just cleaned the OH cache now.

But the following minimalistic example (using the logger provided by the decorator) also throws errors:

from core.rules import rule
from core.triggers import when

@rule("myRuleTest - System started", description="Initialize globals when the rule is reloaded")
@when("System started")
def myRuleTest_SystemStarted(event):
    # Works:
    myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START")
    # Triggers exception:
    myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START - item registry contains {} items",
        len(ir.getItems())
    )
    # Triggers exception:
    myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START - item registry contains {} items",
        len(list(ir.getItems()))
    )
    # Triggers exception:
    myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START - item registry contains {} items",
        format(len(ir.getItems()))
    )
    # Triggers exception:
    myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START - item registry contains {} items",
        format(len(list(ir.getItems())))
    )

Here’s the error message:

==> /var/log/openhab2/openhab.log <==
2019-06-27 21:46:48.083 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: python/personal/test.py
2019-06-27 21:46:49.096 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger 'System_started' of rule '24bdb7e0-e705-4910-82cc-6c611b74446b' is triggered.

==> /var/log/openhab2/events.log <==
2019-06-27 21:46:49.102 [.event.RuleStatusInfoEvent] - 24bdb7e0-e705-4910-82cc-6c611b74446b updated: RUNNING

==> /var/log/openhab2/openhab.log <==
2019-06-27 21:46:49.124 [INFO ] [3.jython.myRuleTest - System started] - myRuleTest_SystemStarted() - START
2019-06-27 21:46:49.175 [ERROR] [3.jython.myRuleTest - System started] - Traceback (most recent call last):
  File "/etc/openhab2/automation/lib/python/core/log.py", line 51, in wrapper
    return fn(*args, **kwargs)
  File "<script>", line 16, in myRuleTest_SystemStarted
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 1151, in info
    self._log(INFO, msg, args, **kwargs)
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 1270, in _log
    self.handle(record)
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 1280, in handle
    self.callHandlers(record)
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 1320, in callHandlers
    hdlr.handle(record)
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 751, in handle
    self.emit(record)
  File "/etc/openhab2/automation/lib/python/core/log.py", line 25, in emit
    message = self.format(record)
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 726, in format
    return fmt.format(record)
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 466, in format
    record.message = record.getMessage()
  File "/etc/openhab2/automation/jython/jython-standalone-2.7.0.jar/Lib/logging/__init__.py", line 330, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting

2019-06-27 21:46:49.182 [ERROR] [e.automation.internal.RuleEngineImpl] - Failed to execute rule '24bdb7e0-e705-4910-82cc-6c611b74446b': Fail to execute action: 1
2019-06-27 21:46:49.188 [DEBUG] [e.automation.internal.RuleEngineImpl] - 
java.lang.RuntimeException: Fail to execute action: 1
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1199) ~[242:org.openhab.core.automation:2.5.0.201906270304]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:995) [242:org.openhab.core.automation:2.5.0.201906270304]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:91) [242:org.openhab.core.automation:2.5.0.201906270304]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.python.core.PyException
	at org.python.core.Py.AttributeError(Py.java:205) ~[?:?]
	at org.python.core.PyObject.noAttributeError(PyObject.java:1013) ~[?:?]
	at org.python.core.PyObject.__getattr__(PyObject.java:1008) ~[?:?]
	at core.rules$py.execute$4(/etc/openhab2/automation/lib/python/core/rules.py:50) ~[?:?]
	at core.rules$py.call_function(/etc/openhab2/automation/lib/python/core/rules.py) ~[?:?]
	at org.python.core.PyTableCode.call(PyTableCode.java:167) ~[?:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:307) ~[?:?]
	at org.python.core.PyBaseCode.call(PyBaseCode.java:198) ~[?:?]
	at org.python.core.PyFunction.__call__(PyFunction.java:482) ~[?:?]
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237) ~[?:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:228) ~[?:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:218) ~[?:?]
	at org.python.core.PyMethod.__call__(PyMethod.java:213) ~[?:?]
	at org.python.core.PyObject._jcallexc(PyObject.java:3626) ~[?:?]
	at org.python.core.PyObject._jcall(PyObject.java:3658) ~[?:?]
	at org.python.proxies.core.rules$_FunctionRule$16.execute(Unknown Source) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.shared.simple.SimpleRuleActionHandlerDelegate.execute(SimpleRuleActionHandlerDelegate.java:34) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.delegates.SimpleActionHandlerDelegate.execute(SimpleActionHandlerDelegate.java:60) ~[?:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1191) ~[?:?]
	... 7 more

==> /var/log/openhab2/events.log <==
2019-06-27 21:46:49.224 [.event.RuleStatusInfoEvent] - 24bdb7e0-e705-4910-82cc-6c611b74446b updated: IDLE

That is the slf4j parameterized logging format. Use…

myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START - item registry contains {} items".format(len(ir.getItems()))
1 Like

BIG FOREHEAD SLAP

Of course! The Python format(). I typically name my parameters.

Geeze, I definitely can use some sleep!

This works:

    myRuleTest_SystemStarted.log.info("myRuleTest_SystemStarted() - START - item registry contains {num} items".format(
        num = len(ir.getItems())
    ))

Thanks!

1 Like

Do you still get the ephemeris exception after clearing the cache, and can you also use LogAction? There is a getActionClass(), so I’m surprised that you’d get this error. If you still are getting it, you should open an issue for it.

Yes, and No.

2019-06-27 22:24:40.942 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {groovy=[file:/etc/openhab2/automation/jsr223/groovy/core/000_startup_delay.groovy], md=[file:/etc/openhab2/automation/jsr223/python/personal/README.md, file:/etc/openhab2/automation/jsr223/groovy/community/README.md, file:/etc/openhab2/automation/jsr223/javascript/personal/README.md, file:/etc/openhab2/automation/jsr223/python/community/README.md, file:/etc/openhab2/automation/jsr223/javascript/community/README.md, file:/etc/openhab2/automation/jsr223/groovy/personal/README.md]}
2019-06-27 22:24:40.945 [INFO ] [ort.shared.ScriptedAutomationManager] - removeAll added handlers
2019-06-27 22:24:40.960 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/test.py'

==> /var/log/openhab2/events.log <==
2019-06-27 22:24:40.961 [ome.event.RuleRemovedEvent] - Rule 'd648442b-958c-4ba3-b96b-31b3ed76a8e9' has been removed.

==> /var/log/openhab2/openhab.log <==
2019-06-27 22:24:40.968 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/personal/test.py
2019-06-27 22:24:41.059 [ERROR] [org.openhab.core.ephemeris          ] - bundle org.openhab.core.ephemeris:2.5.0.201906270306 (147)[org.openhab.ephemeris(76)] : The activate method has thrown an exception
java.lang.IllegalArgumentException: No enum constant java.time.DayOfWeek."""MONDAY

Something is badly wrong with the Ephemeris configuration as it seems to double-stringify the settings. In Paper UI I could once set the weekend days, but now the setting is no longer editable from Paper UI. In HABMIN I could edit it but then I have the following value:

( "( "SATURDAY", "SUNDAY", )", )

where I would have expected to see:

( "SATURDAY", "SUNDAY", )

There’s already an issue relating to this, apparently:

My feeling is that there’s a name clash somewhere.

I assumed you hadn’t configured anything for ephemeris. I just tried to configure weekdays through Paper UI, but it never saves. Did you put a setting in ephemeris.cfg?

Nevermind… you’d mentioned you configured through Habmin.

The first time I saw Ephemeris appear in the logs I went to the System configuration in Paper UI. I could pick values from a check list.

Since then the settings were readonly.

I’ve reproduced the issue you reported by configuring through Habmin. I also got rid of the issue by deleting the ephemeris.config and org.openhab.ephemeris.cfg files (search for them in userdata) and restarting OH. I’m digging deeper… there’s obviously an issue with ephemeris, but this may also reveal the issue with the display of associations in Habmin and Paper UI. When you configure ephemeris in Paper UI, it looks blank after the pages refreshes, but the values are actually still there… just a display issue. Habmin displays them as Xs.

Thanks for figuring this out!

I cleared the cache, deleted both offending configuration files. As you can see, the Ephemeris configuration was completely garbled (multiple-times-re-stringified), and the binding apparently doesn’t know how to gracefully manage these setting errors.

File /var/lib/openhab2/config/org/openhab/ephemeris.config:

:org.apache.felix.configadmin.revision:=L"7"
dayset-school="\"\"\"Monday,Tuesday,Wednesday,Thursday,Friday\"\"\""
dayset-weekend="\"\"\"Saturday,Sunday\"\"\""
felix.fileinstall.filename="file:/var/lib/openhab2/etc/org.openhab.ephemeris.cfg"
service.bundleLocation="?"
service.pid="org.openhab.ephemeris"
weekendDays="(\ \"(\ \"SATURDAY\",\ \"SUNDAY\",\ )\",\ )"

File /var/lib/openhab2/etc/org.openhab.ephemeris.cfg:


dayset-weekend = "\"\"Saturday,Sunday\"\""
dayset-school = "\"\"Monday,Tuesday,Wednesday,Thursday,Friday\"\""
weekendDays = ( \
  "( \"SATURDAY\", \"SUNDAY\", )", \
)

Meanwhile I upgraded to 2.5.0~S1625-1.

After cleaning the cache and restarting OH (twice), no more nasty Ephemeris exceptions are thrown, and I can indeed use LogAction now from within my Jython scripts.

1 Like

In my case these ephemeris errors started to show up after upgrade from 2.5.0.M1 to 2.5.0.M2
What would you advice to get rid of them?

Delete these two files:

/var/lib/openhab2/config/org/openhab/ephemeris.config
/var/lib/openhab2/etc/org.openhab.ephemeris.cfg

clean the cache anf finaly restart the service?

The decision was made to release 2.5M2 even though Ephemeris (a new feature) had open issues. You will need to wait for 2.5M3 or use a snapshot build once these issues are resolved.

https://github.com/orgs/openhab/projects/2#column-6177853

I upgraded openHAB from 2.4 to 2.5 and it was broken until I deleted ephemeris.config and restarted openHAB. Thank you very much for the fix.

1 Like