Misleading error location when Jython script raises exception

[diijkstra]

Using JSR223 script backend (Jython), whenever exception is raised during script execution ESH is logging a type of thrown exception and location (line number and file). Unfortunately for Jython scripts, line number is set to the line number of script which is being executed, even if exception was thrown inside imported libraries.

With complicated libraries, it is hard to find out where exactly exception originated from. One can workaround this limitation, by using try/except block and logging exception on Jython side (with pythonic stack trace) - but this requires each script to be contained within gigantic try/except and fails when logger setup throws exception (for example see Issue 59 in OH-Jython-Scripters.

Similar issue can be seen, when rule is being executed. But this time, ESH is logging at least java stack trace. It is not ideal, but one can deduce where and what went wrong on jython side. (And workaround with try/except is easier because one can write wrapper for all rules).

When script is being executed, exception thrown back to java is of ScriptException type. Both python and js script engines, do set the cause of exception which is exception thrown inside script. This exception, contains python stacktrace or js error.

My proposal is to log inner exception as string (not as a java stack trace!) on debug level. This way, user will see his language error and not java wrappers: Improve-logging-exception-from-scripts.patch

Known issues:

• jython exception type has its cause set to itself, js exception does not have cause (at least if it was initial exception)
• whenever jython/js is executing java code and exception is thrown, logging cause will show only jython/js error about receiving java exception (aka nested exceptions are hard to log ;) )

One could also consider similar loggin when executing rules, but not being a java guy I'm having a trouble in identifying if action rule from JSR223 or not. I've opted for dirty solution to add log on runNow() and runRule() level just in case.

Step to reproduce:

• create a jython library which throws exception (ex. invalid python code)
• try to import that library from script Result:

2018-12-30 11:49:46.865 [ERROR] [.m.s.i.ScriptEngineManagerImpl:138  ] - Error during evaluation of script 'file:/[...]': javax.script.ScriptException: NameError: name 'foo' is not defined in <script> at line number 18

With my proposal:

2018-12-30 11:49:46.865 [ERROR] [.m.s.i.ScriptEngineManagerImpl:138  ] - Error during evaluation of script 'file:/[...]': javax.script.ScriptException: NameError: name 'foo' is not defined in <script> at line number 18
2018-12-30 11:49:46.866 [DEBUG] [.m.s.i.ScriptEngineManagerImpl:141  ] - 'file:/[...]'
Traceback (most recent call last):
  File "<script>", line 18, in <module>
  File "[...]lib/python/core/bar.py", line 1, in <module>
    foo
NameError: name 'foo' is not defined

[5iver]

@diijkstra , I made some commits (1, 2), which I do not plan to submit since this was the wrong direction for what I was attempting (including the rule name in the logs, rather than just UID). But while I was in there, I also noticed some missing {} in the log statements in RuleEngineImpl which prevented the exception from being logged. I'll separate out these changes and submit a PR for the logging fixes. This may be all that we need to correct, but getCause() looks useful too.