ST2api Log Fix So That Querying a Non-Existent Key in the Datastore Will Not Print Traceback

[saucetray]

ST2api.log will print a traceback when you attempt to query a non-existent key in the datastore. This should fix that.

Fixes #4979

[amanda11]

Currently exceptions raised are re-thrown in router.py and then caught higher up.
In api.py at https://github.com/StackStorm/st2/blob/master/st2api/st2api/app.py#L82 defines the generic error handling middleware.
And then in st2common you've got this code to convert any exceptions that bubble-up into http response codes

st2/st2common/st2common/middleware/error_handling.py

Line 38 in 8f507d6

def __call__(self, environ, start_response):

One possible solution would be to keep the throw of StackStormDBObjectNotFoundError. Then add an explicit catch next to https://github.com/StackStorm/st2/blob/master/st2common/st2common/router.py#L514-L519 for the StackStormDBObjectNotFoundError, still re-raise so you get the http response code handling as before. But rather than use a LOG.exception use a LOG that just logs the exception msg, rather than the full stack trace.
So you handle the permitted exceptions of objectnotfound by just keeping the message and not stack, and for non-expected exceptions you then log the full stack trace, so you don't loose it when you rethrow it?

[guzzijones]

@amanda11 +1 for that solution

[amanda11]

Looks good, but I wonder if warning rather than error would be more appropriate? But I don’t know if that would normally come out or not - but if they did it maybe is more a warning than an error?
I also was originally thinking you would want to still include the text that was in the log.exception call, eg keep the “Failed to call the controller ...” message with its parameters, and just add on the exception msg as well - rather than just the exception message.

[saucetray]

Oh. Okay, right. That sounds better.

[amanda11]

I think I've found a problem with making it extend base exception.

There are a number of calls made to get_by_scope_and_name that check if the DBObjectNotFoundError is returned and act on it. So I think by changing it to a new exception (that doesn't extend DbObjectNotFoundError) then we will break these, e.g.
in st2common/st2common/services/keyvalues.py and st2common/st2common/services/config.py

So I think it might be better to change this new exception to extend DBObjectNotFoundError.

[amanda11]

ermmm

91961) FAIL: test_process_wrapper_exits_in_reasonable_timeframe (tests.integration.test_python_action_process_wrapper.PythonRunnerActionWrapperProcessTestCase)
9197----------------------------------------------------------------------
9198   Traceback (most recent call last):
9199    contrib/runners/python_runner/tests/integration/test_python_action_process_wrapper.py line 101 in test_process_wrapper_exits_in_reasonable_timeframe
9200      self.assertTrue(avg_run_time_seconds <= WRAPPER_PROCESS_RUN_TIME_UPPER_LIMIT, assertion_msg)
9201   AssertionError: False is not true : Python wrapper process script took more than 0.31 seconds to execute (0.31875). This most likely means
9202   that a direct or in-direct import of a module which takes a long time to load has been added (e.g.
9203   jsonschema, pecan, kombu, etc).
9204   
9205   Please review recently changed and added code for potential slow import issues and refactor /
9206   re-organize code if possible.

That's not you. It's a known test that occassionally runs slow.... We've not yet worked out how to resolve this one.

[amanda11]

@saucetray There is however a lint error that needs fixing

". virtualenv/bin/activate; flake8 --config ./lint-configs/python/.flake8 st2actions st2api st2auth st2client st2common st2debug st2exporter st2reactor st2stream st2tests
st2common/st2common/exceptions/keyvalue.py:33:1: E302 expected 2 blank lines, found 1"

[saucetray]

oh yeah I fixed that already I'm seeing if there's any other errors before I start this

[punkrokk]

Thanks @saucetray

[saucetray]

2020-07-31 18:58:15,737 140482139303256 WARNING (unknown file) [-] Failed to call controller function "get_one" for operation "st2api.controllers.v1.keyvalue:key_value_pair_controller.get_one": The key "aws.inspector.mapping_dict" does not exist in the StackStorm datastore., The key "aws.inspector.mapping_dict" does not exist in the StackStorm datastore.

@armab @punkrokk @amanda11 that's the log now... maybe it should be pretty printed better?

[arm4b]

At least it shouldn't print some information 2 times in one message.

[amanda11]

LGTM

[blag]

Indentation not quite fixed.

[arm4b]

LGTM!

Thanks @saucetray for the PR, @amanda11 for review and @punkrokk @blag for the pointers!