RuntimeError: maximum recursion depth exceeded (Java StackOverflowError) in <script> at line number 82

Tags: #<Tag:0x00007f616f66b9f8> #<Tag:0x00007f616f66b8e0>

Platform Information
Hardware: Raspberry Pi 3B+
OS: Raspberry Pi OS (32 Bit - Buster)
Java Runtime Environment:
openjdk version “1.8.0_152”
OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
Jython 2.7.0
openHAB 2.5.5 (Release Build)

Hello Community,

I’m migrating rules to NGRE using the Beta Helper Libraries. This evening I ran across a “RuntimeError: maximum recursion depth exceeded (Java StackOverflowError) in at line number 82.” Does anyone have any ideas what’s causing the error? It seems to be related to the “log_traceback” decorator. When comment out that decorator startup after and openhab restart appears normal. The odd thing about this was that I was using the decorator successfully, on and off for a few hours debugging rules. Then Java crashed with a flurry of exceptions, and I was not able to restart openHAB. I ended up rebooting the system and stopping openhab, and clearing the cache. Logs and rule follow.

openhab.log

2020-06-09 22:23:17.823 [INFO ] [jsr223.jython.core.startup_delay    ] - Checking for initialized context
2020-06-09 22:23:17.829 [INFO ] [jsr223.jython.core.startup_delay    ] - Context initialized... waiting 30s before allowing scripts to load
2020-06-09 22:23:47.832 [INFO ] [jsr223.jython.core.startup_delay    ] - Complete
2020-06-09 22:23:47.838 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/100_DirectoryTrigger.py'
2020-06-09 22:23:47.840 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/100_DirectoryTrigger.py
2020-06-09 22:23:49.847 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/python/core/components/100_DirectoryTrigger.py': RuntimeError: maximum recursion depth exceeded (Java StackOverflowError) in <script> at line number 82
2020-06-09 22:23:49.854 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/100_OsgiEventTrigger.py'
2020-06-09 22:23:49.857 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/100_OsgiEventTrigger.py
2020-06-09 22:23:50.937 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/python/core/components/100_OsgiEventTrigger.py': SystemError: Automatic proxy initialization should only occur on proxy classes in <script> at line number 72
2020-06-09 22:23:50.942 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/100_StartupTrigger.py'
2020-06-09 22:23:50.944 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/100_StartupTrigger.py
2020-06-09 22:23:51.007 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/python/core/components/100_StartupTrigger.py': RuntimeError: maximum recursion depth exceeded (Java StackOverflowError) in <script> at line number 49
2020-06-09 22:23:51.011 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonBindingInfoProvider.py'
2020-06-09 22:23:51.014 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonBindingInfoProvider.py
2020-06-09 22:23:51.219 [WARN ] [ython.core.JythonBindingInfoProvider] - Traceback (most recent call last):
  File "<script>", line 39, in <module>
SystemError: Automatic proxy initialization should only occur on proxy classes

2020-06-09 22:23:51.224 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonExtensionProvider.py'
2020-06-09 22:23:51.227 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonExtensionProvider.py
2020-06-09 22:23:52.695 [DEBUG] [.jython.core.JythonExtensionProvider] - Start init
2020-06-09 22:23:52.753 [DEBUG] [.jython.core.JythonExtensionProvider] - End init
2020-06-09 22:23:52.762 [WARN ] [.jython.core.JythonExtensionProvider] - Traceback (most recent call last):
  File "<script>", line 87, in <module>
SystemError: Automatic proxy initialization should only occur on proxy classes

2020-06-09 22:23:52.769 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonItemChannelLinkProvider.py'
2020-06-09 22:23:52.771 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonItemChannelLinkProvider.py
2020-06-09 22:23:52.888 [WARN ] [n.core.JythonItemChannelLinkProvider] - Traceback (most recent call last):
  File "<script>", line 52, in <module>
SystemError: Automatic proxy initialization should only occur on proxy classes

2020-06-09 22:23:52.894 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonItemProvider.py'
2020-06-09 22:23:52.899 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonItemProvider.py
2020-06-09 22:23:53.060 [ERROR] [sr223.jython.core.JythonItemProvider] - Traceback (most recent call last):
  File "<script>", line 57, in <module>
SystemError: Automatic proxy initialization should only occur on proxy classes

2020-06-09 22:23:53.066 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonThingProvider.py'
2020-06-09 22:23:53.069 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonThingProvider.py
2020-06-09 22:23:53.189 [ERROR] [r223.jython.core.JythonThingProvider] - Traceback (most recent call last):
  File "<script>", line 50, in <module>
SystemError: Automatic proxy initialization should only occur on proxy classes

2020-06-09 22:23:53.196 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonThingTypeProvider.py'
2020-06-09 22:23:53.199 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonThingTypeProvider.py
2020-06-09 22:23:53.318 [ERROR] [.jython.core.JythonThingTypeProvider] - Traceback (most recent call last):
  File "<script>", line 39, in <module>
SystemError: Automatic proxy initialization should only occur on proxy classes

2020-06-09 22:23:53.326 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/core/components/200_JythonTransform.py'
2020-06-09 22:23:53.329 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/core/components/200_JythonTransform.py
2020-06-09 22:23:53.389 [ERROR] [hon.core.JythonTransformationService] - Traceback (most recent call last):
  File "<script>", line 28, in <module>
RuntimeError: maximum recursion depth exceeded (Java StackOverflowError)

2020-06-09 22:23:53.394 [INFO ] [me.core.service.AbstractWatchService] - Loading script 'python/personal/python_test.py'
2020-06-09 22:23:53.396 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'py' with identifier: file:/etc/openhab2/automation/jsr223/python/personal/python_test.py
2020-06-09 22:23:58.946 [DEBUG] [jsr223.jython.core.triggers         ] - when: target=[Time cron 0/10 * * * * ?], target_type=Time, trigger_target=cron, trigger_type=0/10 * * * * ?, old_state=None, new_state=None
2020-06-09 22:24:00.137 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/python/personal/python_test.py': SystemError: Automatic proxy initialization should only occur on proxy classes in <script> at line number 10

python_test.py

from core.rules import rule
from core.triggers import when
from core.actions import ScriptExecution
from core.log import log_traceback

from datetime import datetime, date, time
import re


@rule("Lights On When Waking Up for High School2")
@when("Time cron 0/10 * * * * ?")
#@when("Time cron 0 00 17 ? * MON-FRI *")
@log_traceback
def lights_on_when_waking_up_for_high_school2(event):
    now=datetime.now()
    time_now=now.time()
    date_now=now.date()
    item_Mehlville_School_District_current_event_name=itemRegistry.getItem("Mehlville_School_District_current_event_name")
    First_Day_of_School="2020-06-08"
    Last_Day_of_School="2021-06-08"
    First_Day_of_School_Date=datetime.strptime(First_Day_of_School, "%Y-%m-%d").date()
    Last_Day_of_School_Date=datetime.strptime(Last_Day_of_School, "%Y-%m-%d").date()
    if date_now >= First_Day_of_School_Date and date_now <= Last_Day_of_School_Date and not item_Mehlville_School_District_current_event_name.startswith("No School"):
        events.sendCommand("gUpstairs_Hallway_Lights", "ON")
        str_Sunrise_Start_Time=itemRegistry.getItem("Sunrise_Start_Time").state.toString()
        Sunrise_Start_DateTime=re.sub(r"\..*", "", str_Sunrise_Start_Time)
        Sunrise_Start_Time=datetime.strptime(Sunrise_Start_DateTime, "%Y-%m-%dT%H:%M:%S").time()
        if Sunrise_Start_Time > time_now:
            events.sendCommand("gKitchen_Island_Lights", "ON")
            events.sendCommand("gLiving_Room_Lights", "ON")
            lights_on_when_waking_up_for_high_school2.log.info("Rule: 'Lights On When Waking Up for High School' fired.")

Regards,
Burzin

No biggie, but the Jython helper libraries are definitely not beta. The Jython addon is beta, but it’s been working great for over 6 months now :slightly_smiling_face:!

Check this out…

core.rules.rule takes care of the log_traceback for you :wink:. I’ve never seen the error you’re reporting, but it does not look to be related to the Jython addon. There does appear to be something here, but I think it’s safe to just “don’t do that” for now and see if it turns up again. WDYT?

As for your rule, there is no need to hit the ItemRegistry to get an Item’s state…

str_Sunrise_Start_Time=itemRegistry.getItem("Sunrise_Start_Time").state.toString()

Instead, use items

str_Sunrise_Start_Time = items["Sunrise_Start_Time"].toString()

The biggest thing I saw was your handling of DateTimeTypes. It is always best to do things in Java or OH classes or methods. You should definitely take a look at Mode (Time of Day). Also, if you are using VS Code, which you should, definitely use the pylint extension to clean things up. I’ll have an update to the docs very soon with details. Running this rule every 10s is WAY too often! This sort of thing is usually done by using an Item to represent a mode or time of day. In case you choose not to change it, you should be fine running it every 5 minutes. Here’s what I’m talking about…

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

@rule("Lights On When Waking Up for High School2")
@when("Time cron 0 0/5 * * * ?")
def lights_on_when_waking_up_for_high_school2(event):
    current_zdtime = DateTimeType().zonedDateTime
    First_Day_of_School = current_zdtime.withYear(2020).withMonth(6).withDayOfMonth(8).withHour(7).withMinute(0).withSecond(0).withNano(0)#"2020-06-08"
    Last_Day_of_School = current_zdtime.withYear(2021).withMonth(6).withDayOfMonth(8).withHour(7).withMinute(0).withSecond(0).withNano(0)#"2021-06-08"
    if not items["Mehlville_School_District_current_event_name"].toString().startswith("No School") and current_zdtime.isAfter(First_Day_of_School) and current_zdtime.isBefore(Last_Day_of_School):
        events.sendCommand("gUpstairs_Hallway_Lights", "ON")
        if current_zdtime.isBefore(items["Sunrise_Start_Time"].zondDateTime):
            events.sendCommand("gKitchen_Island_Lights", "ON")
            events.sendCommand("gLiving_Room_Lights", "ON")
            lights_on_when_waking_up_for_high_school2.log.info("Rule: 'Lights On When Waking Up for High School' fired.")

Thanks for the pointers and the corrections Scott. (The 10 second rule firing was just for test purposes though. The real rule is meant to fire 1 time a day.) I’ll take another look in the evening.

The biggest problems that I’m running into with Jython is the lack of error messages pointing out syntax errors. I just modified and tested the hello_world.example script with a bogus python line, and sure enough, the problem was reported in the openhab.log. I added the same bogus line to my test script and the problem was reported there as well. I removed the line and now I’m getting this:

2020-06-10 05:19:15.770 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/python/personal/python_test.py': SystemError: Automatic proxy initialization should only occur on proxy classes in <script> at line number 10

Line number 10 refers to the line with the rule decorator. My script is essentially the same as what you commented on. I just commented out the “log_traceback” decorator and bumped the cron to fire every 5 minutes for grins to see if that was causing anomalous behavior…

OK… I’ll look into this further, but after I push a bunch of PRs this weekend. Maybe today, if I stay out of the heat!

Hello,

Just an update…

I removed “org.openhab.core.automation.module.script.scriptenginefactory.jython-2.5.0-SNAPSHOT.jar” from the addons directory and uninstalled it using the Karaf console. I’m not sure if the following were also necessary, but I then stopped openHAB and cleared the cache-cache, and restarted the Pi for good measure. After doing this, scripting appears to be working as expected. (I previously had Jython installed.). I’ll download a fresh copy of the snapshot JAR and add it to the addons directory after I finish converting my rules.

Regards,
Burzin

By previously installed, do you mean you had a Jython jar still added to the bootclasspath through EXTRA_JAVA_OPTS? This can cause issues. The beta addon can’t be used along with a manual install of Jython.

Ah that explains things. I missed that prohibition. I know the shapshot JAR has its own Jython JAR and would use it, but I did not realize that it would conflict with the standalone Jython JAR.

I actually did the full Jython installation earlier. Its Jython JAR (jython.jar) is in the jython directory along with two different versions of the standalone JAR. However, the EXTRA_JAVA_OPTS only points to one version (jython-standalone-2.7.0.jar).
.

I haven’t tested to see how/if it blows up, but best not to have multiple Jythons setup!