log_traceback to decorate wrapper function correctly

ssalonen commented 4 years ago

To my understanding, the code did not actually decorate the wrapper function at all.

See https://docs.python.org/2/library/functools.html#functools.wraps

I haven't tested this in practice, should definitely be done to avoid any issues / unexpected changes in tracebacks.

Signed-off-by: Sami Salonen ssalonen@gmail.com

5iver commented 4 years ago

If you haven't tested this and it is functioning OK, I'm not sure there is any need to change things.

ssalonen commented 4 years ago

Fair point @openhab-5iver. Will revert once I have tested with the results.

With the correct wrapping, I would expect the tracebacks to be more readable, omitting internals of the supporting library (log_traceback)

Let's keep this WIP for now.

ssalonen commented 4 years ago

tl;dr

openHAB cloud notifications were not sent when @rule function raised exception. This also means it should be unnecessary to wrap functions in log_traceback if they are called from @rule.
extra stack trace error were logged when @rule function raised exception. This extra error did not really specify the crash site properly due improper functools.wraps in log_traceback
potentially other uses of log_traceback are now more readable as well

OK, turned out it was worth investigating this.

I tested how errors show up with this simple test script

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

@rule("hello_world")
@when("Time cron 0/10 * * * * ?")
def hello_world(event):
    hello_world.log.info('starting hello world rule')
    2/0  # divizion by zero line 9 in hello_world.py
    hello_world.log.info('ending hello world rule')

from core.triggers import CronTrigger

@rule("hello_world (rule)")
class ExampleExtensionRule(object):
    def __init__(self):
        self.triggers = [CronTrigger("0/10 * * * * ?").trigger]

    def execute(self, module, inputs):
        hello_world.log.info('starting hello world rule (class)')
        2/0  # divizion by zero line 21 in hello_world.py
        hello_world.log.info('ending hello world rule (class)')

The errors from the class-based approach (ExampleExtensionRule) show properly:

21:01:50.793 [INFO ] [jsr223.jython.hello_world            ] - starting hello world rule (class)
21:01:50.795 [ERROR] [jsr223.jython.hello_world (rule)     ] - Traceback (most recent call last):
  File "/OMITTED/openhab-2.5.3-jython/conf/automation/lib/python/core/log.py", line 51, in wrapper
    return fn(*args, **kwargs)
  File "<script>", line 21, in execute
ZeroDivisionError: integer division or modulo by zero

21:01:50.796 [DEBUG] [re.automation.internal.RuleEngineImpl] - The rule '685f46f8-1109-4465-803e-a6b74622eeb7' is executed.

However, the function based approach logs extra noise:

21:17:20.259 [INFO ] [jsr223.jython.hello_world            ] - starting hello world rule
21:17:20.263 [ERROR] [jsr223.jython.hello_world            ] - Traceback (most recent call last):
  File "/OMITTED/openhab-2.5.3-jython/conf/automation/lib/python/core/log.py", line 51, in wrapper
    return fn(*args, **kwargs)
  File "<script>", line 9, in hello_world
ZeroDivisionError: integer division or modulo by zero

21:17:20.264 [ERROR] [re.automation.internal.RuleEngineImpl] - Failed to execute rule '9d800733-21b8-4c4e-92a2-408dd487b782': Fail to execute action: 1
21:17:20.265 [DEBUG] [re.automation.internal.RuleEngineImpl] -
java.lang.RuntimeException: Fail to execute action: 1
    at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1197) ~[bundleFile:?]
    at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:993) [bundleFile:?]
    at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:91) [bundleFile:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_202]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_202]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_202]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_202]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
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$6(/OMITTED/openhab-2.5.3-jython/conf/automation/lib/python/core/rules.py:110) ~[?:?]
    at core.rules$py.call_function(/OMITTED/openhab-2.5.3-jython/conf/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:59) ~[?:?]
    at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1189) ~[bundleFile:?]
    ... 7 more

If you check the stack trace closely, you can see that this is logged from core/rules.py:110, and the reason is due to access to non-existing attribute in some part of the code (correct source is not listed):

    at org.python.core.PyObject.noAttributeError(PyObject.java:1013) ~[?:?]
    at org.python.core.PyObject.__getattr__(PyObject.java:1008) ~[?:?]

core/rules.py:110 is actually catch-all handler in _FunctionRule in case log_traceback-wrapped function raises exception

https://github.com/openhab-scripters/openhab-helper-libraries/blob/f40d84486d4bf0a2d74de9b31b09a5da70c6611f/Core/automation/lib/python/core/rules.py#L109-L110

Note that with quick glance it looks like log_traceback should not re-raise anything, it should just log it but not re-raise it.

Turns out this is due missing name property in the rule function. We can fix the error stack-trace by turning the no-op functools.wraps into properly-wrapping the underlying function, that is adding the @ in functools.wraps call: https://github.com/openhab-scripters/openhab-helper-libraries/blob/f40d84486d4bf0a2d74de9b31b09a5da70c6611f/Core/automation/lib/python/core/log.py#L48-L49

After this change, the functools.wraps is no longer no-op and we get the correct stack trace logged from the core/rules.py:110 catch-all handler:

21:30:40.917 [ERROR] [jsr223.jython.hello_world            ] - Traceback (most recent call last):
  File "/OMITTED/openhab-2.5.3-jython/conf/automation/lib/python/core/rules.py", line 107, in execute
    self.callback(inputs.get('event'))
  File "/OMITTED/openhab-2.5.3-jython/conf/automation/lib/python/core/log.py", line 56, in wrapper
    rule_name = fn.name
AttributeError: 'function' object has no attribute 'name'

In context, the log_traceback is simply trying to use the rule's own logger: https://github.com/openhab-scripters/openhab-helper-libraries/blob/f40d84486d4bf0a2d74de9b31b09a5da70c6611f/Core/automation/lib/python/core/log.py#L54-L56

Even worse, since it crashes at that point, the log_traceback never even gets to send notifications over NotificationAction. Note that this applies only to function rules, but not ad-hoc functions decorated with log_traceback, and not class based rules.

So in this PR we also "enrich" rule function with the provided name, right along with log.

As result, we get clean exceptions logged (tested with the above rules) and the NotificationAction should work as well.

5iver commented 4 years ago

@ssalonen, I apologize for the delay! Your analysis is fantastic, thank you! I had also come across the missing callback.name. I have also removed the log_traceback from the callback and then decorated the execute method with it. I have a few other changes in core.rules to merge. I do not notice a difference with/without the @, but I don't see any harm in it. I have a number of changes to merge for core.rules and core.log. Would you mind if I include these changes with the others? This should save us some time rebasing.

ssalonen commented 4 years ago

I have also removed the log_traceback from the callback and then decorated the execute method with it.

Makes sense to me. By wrapping the outer function (execute) we are able to log everything.

But please note that since execute has catch-all, the decoration will have no role -- there will be never exception to handle. This is why you do not see difference with/without @, it is dead code even when properly decorated with @.

We should perhaps remove the catch-all in execute if we have the decoration in place? They are serving similar function.

What's the harm? Catch-all in execute is logging errors so that is good. But all the notification functionality of the log_traceback is not there so notifications will not be sent.

I think we should consider investing some time to introduce a test for this to catch any further regressions.

5iver commented 3 years ago

This was implemented in #372. @ssalonen, please let me know if this works out for you! Thank you!

openhab-scripters / openhab-helper-libraries

log_traceback to decorate wrapper function correctly #310