Jython broken object references

[HolgerHees]

I have a very stange jython behavior running my new python rules in openhab 2.3. I tried already some debugging to get some deeper understanding whats happen.

I ported my first 40 rules to python and in the beginning they are running fine. But after a while I get a lot of "org.python.core.PyException" if I try to get their state.

So I added some debug statements. I'm logging the string representation of each item where I want to get the state. If everything runs well I get a string representation like

PlantSensorInfo (Type=StringItem, State=Feucht genug, Label=Planzen Status, Category=selfrain)

This looks like a normal python object. Here I can access the state without any problems. But after a while, some items are becomming "dirty". I'm not able to access their state. Every time I try to call getState I'm getting this "org.python.core.PyException" exception.

A string representation of this problematic items looks like this

PlantSensorInfo <org.eclipse.smarthome.core.library.items.StringItem object at 0x16>

and the StackTrace looks like this

2018-06-14 10:50:01.798 [ERROR] [.automation.core.internal.RuleEngine] - Failed to execute rule '81f67cf1-b773-47cc-bfd2-f35e07664e23': Failed to execute action '1': null
2018-06-14 10:50:01.798 [DEBUG] [.automation.core.internal.RuleEngine] - 
java.lang.RuntimeException: Failed to execute action '1': null
        at org.eclipse.smarthome.automation.core.internal.RuleEngine.executeActions(RuleEngine.java:1013) [207:org.eclipse.smarthome.automation.core:0.10.0.oh230]
        at org.eclipse.smarthome.automation.core.internal.RuleEngine.runRule(RuleEngine.java:823) [207:org.eclipse.smarthome.automation.core:0.10.0.oh230]
        at org.eclipse.smarthome.automation.core.internal.RuleEngineCallbackImpl$TriggerData.run(RuleEngineCallbackImpl.java:91) [207:org.eclipse.smarthome.automation.core:0.10.0.oh230]
        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.SystemError(Py.java:275) ~[?:?]
        at org.python.core.Deriveds.__findattr_ex__(Deriveds.java:59) ~[?:?]
        at org.python.core.PyObjectDerived.__findattr_ex__(PyObjectDerived.java:1036) ~[?:?]
        at org.python.core.PyObject.__getattr__(PyObject.java:1025) ~[?:?]
        at marvin.helper$py.getItemState$2(/dataDisk/openhab-runtime/python/marvin/helper.py:23) ~[?:?]
        at marvin.helper$py.call_function(/dataDisk/openhab-runtime/python/marvin/helper.py) ~[?:?]
        at org.python.core.PyTableCode.call(PyTableCode.java:171) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:139) ~[?:?]
        at org.python.core.PyFunction.__call__(PyFunction.java:413) ~[?:?]
        at org.python.pycode._pyx104.execute$6(<script>:48) ~[?:?]
        at org.python.pycode._pyx104.call_function(<script>) ~[?:?]
        at org.python.core.PyTableCode.call(PyTableCode.java:171) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:308) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:199) ~[?:?]
        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:3644) ~[?:?]
        at org.python.core.PyObject._jcall(PyObject.java:3676) ~[?:?]
        at org.python.proxies.__builtin__$MyDetailRule$281.execute(Unknown Source) ~[?:?]
        at org.eclipse.smarthome.automation.module.script.rulesupport.shared.simple.SimpleRuleActionHandlerDelegate.execute(SimpleRuleActionHandlerDelegate.java:34) ~[?:?]
        at org.eclipse.smarthome.automation.module.script.rulesupport.internal.delegates.SimpleActionHandlerDelegate.execute(SimpleActionHandlerDelegate.java:60) ~[?:?]
        at org.eclipse.smarthome.automation.core.internal.RuleEngine.executeActions(RuleEngine.java:1005) ~[?:?]
        ... 7 more

this are just examples. It does not happen for the same item every time. So the items which becomes dirty is a random item every time. Some items are also recovering their reference after a while.

I guess that the python objects are losing their reference to the java counterpart.

has anyone an idea or hint how to solve this or how to debug it deeper.

[sjsf]

I'm not that much into the details of the scripting integration, so I can't really help here, I'm afraid - @smerschjohann maybe?

[HolgerHees]

I found a temporary workaround for me.

Instead of calling

itemRegistry.getItem(<name>).getState() 

I'm using now

items.get(<name>)

to get the State. With this change it was not crashing anymore since a day now. But I can restore the old behavior quickly if someone needs more debug information.

I guess it is not crashing anymore because it avoids a lot of object wraps between java and python objects and is using now a much simpler way like this item state map.

Maybe there is a problem with the itemRegistry together with a lot of item calls. In my case 20 - 100 per minute. Depending which rule was triggered.

[sjsf]

Thanks for the update - good to know there is a workaround.

[HolgerHees]

My workaround was just reducing the amount of errors. Yesterday I got other errors like

File "/dataDisk/openhab-runtime/python/marvin/helper.py", line 28, in func_wrapper
func(self,module,input)
File "<script>", line 62, in execute
File "/dataDisk/openhab-runtime/python/marvin/helper.py", line 95, in itemStateNewerThen
SystemError: __getattribute__ not found on type DateTimeType. See http://bugs.jython.org/issue2487 for details.

also some null pointer exceptions when I tried to fetch the item state. But this time I got this hint about a jython issues (2487) and they refactored something to avoid synchronization issues between java and python objects.

I upgraded now my jython installation from 2.7.1 to the latest master branch. Lets see if it is solving my problems.

[5iver]

@HolgerHees , I reported an issue lately in another... https://github.com/eclipse/smarthome/issues/6392#issuecomment-456147182. Updating to 2.7.1.patch2618 resolved it. Are you still seeing this, or can this one be closed? You may be interested in the other discussion too, if you've seen some of the other reported issues with 2.7.1.

[HolgerHees]

@openhab-5iver since my last comment, when I updated to version 2.7.1 it works for me without any problem.

But at the same time I changed also the way how I get item states. Before I was getting the item and then the state from them. After I get the state from this item state map without fetching the item first. So I don't really know which change was fixing it. :-)