Traceback breaking Python rules

[iwilltry42]

Hi there,
we're using the fluent-plugin-detect-exceptions to get multiline Python tracebacks in Elasticsearch and it works great so far (thanks for that!).
However, we just found an issue.
The following traceback breaks the python rule and makes it sending a traceback stack before it's finished:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/flask/app.py", line 2292, in wsgi_app
    response = self.full_dispatch_request()
  File "/usr/local/lib/python3.6/site-packages/flask/app.py", line 1815, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/usr/local/lib/python3.6/site-packages/flask/app.py", line 1718, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "/usr/local/lib/python3.6/site-packages/flask/_compat.py", line 35, in reraise
    raise value
  File "/usr/local/lib/python3.6/site-packages/flask/app.py", line 1813, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/local/lib/python3.6/site-packages/flask/app.py", line 1799, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/usr/local/lib/python3.6/site-packages/dash/dash.py", line 1152, in dispatch
    response.set_data(self.callback_map[output]['callback'](*args))
  File "/usr/local/lib/python3.6/site-packages/dash/dash.py", line 1038, in add_context
    output_value = func(*args, **kwargs)
  File "/app/src/.....changes.py", line 83, in get_target_issue_changes
    data, columns = ....changes_data(targets)
  File "/usr/local/lib/python3.6/site-packages/flask_caching/__init__.py", line 795, in decorated_function
    rv = f(*args, **kwargs)
  File "/app/src/....changes.py", line 24, in get_target_issue_changes_data
    target_issue_changes.c.locale_code).in_(targets))
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/operators.py", line 593, in in_
    return self.operate(in_op, other)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 707, in operate
    return op(self.comparator, *other, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/operators.py", line 1219, in in_op
    return a.in_(b)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/operators.py", line 593, in in_
    return self.operate(in_op, other)
  File "<string>", line 1, in <lambda>
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/type_api.py", line 66, in operate
    return o[0](self.expr, op, *(other + o[1:]), **kwargs)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/default_comparator.py", line 194, in _in_impl
    for o in seq_or_selectable:
TypeError: 'NoneType' object is not iterable

The last four lines of this traceback are being sent separately (line by line):

    return o[0](self.expr, op, *(other + o[1:]), **kwargs)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/default_comparator.py", line 194, in _in_impl
    for o in seq_or_selectable:
TypeError: 'NoneType' object is not iterable

We already figured out, that it's being caused by this line combination:

  File "<string>", line 1, in <lambda>
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/sql/type_api.py", line 66, in operate

Python Rules are:

    PYTHON_RULES = [
      rule(:start_state, /^Traceback \(most recent call last\):$/, :python),
      rule(:python, /^[\t ]+File /, :python_code), # A
      rule(:python_code, /[^\t ]/, :python),          # B
      rule(:python, /^(?:[^\s.():]+\.)*[^\s.():]+:/, :start_state)
    ].freeze

It seems like it's exiting at rule(:python, /^[\t ]+File /, :python_code) # A, because it's expecting the next line to start with File again, which is not the case in this traceback.

Couldn't the rules marked with A and B be merged into some rule like "starts with at least one \t followed by some text instead of distinguishing between lines starting with File and lines that just contain some code?

Thanks in advance for any help :)

[jkschulz]

Hi, thanks for the report! That sounds reasonable; if you'd like to make a PR for it, I'd be happy to review it.

[igorpeshansky]

It should be possible just to add a transition from :python_code to :python_code on matching File...

[iwilltry42]

@igorpeshansky, that would definitely work as well:

PYTHON_RULES = [
      rule(:start_state, /^Traceback \(most recent call last\):$/, :python), # Start: line is exactly `Traceback (most recent call last):`
      rule([:python, python_code], /^[\t ]+File /, :python_code), # starts with one or more tabs, followed by `File`
      rule(:python_code, /[^\t ]/, :python), # anything that's not a tab
      rule(:python, /^(?:[^\s.():]+\.)*[^\s.():]+:/, :start_state) # End: matches output of the actual Error (unindented line)
    ].freeze

But wouldn't the following be much simpler and still work fine? (We used this with gliderlabs/logspout before we moved to fluentd):

PYTHON_RULES = [
      rule(:start_state, /^Traceback \(most recent call last\):$/, :python), # Start: line is exactly `Traceback (most recent call last):`
      rule(:python, /^[\t ]+[\S]+.*/, :python), # starts with one or more tabs, followed by at least one non-whitespace character, followed by whatever
      rule(:python, /^(?:[^\s.():]+\.)*[^\s.():]+:/, :start_state) # End: matches output of the actual Error (unindented line)
    ].freeze

This would reduce the rule to only 2 states and a single regex for matching anything between the Traceback and the actual Error.

WDYT?

[igorpeshansky]

@iwilltry42 It would work fine for gathering tracebacks when they are present, but may perennially do more work in the common case where there is no traceback. Pulling out the File match lets it fail earlier.

[iwilltry42]

Okay, I guess I just don't know enough about how the plugin works.
I will change my PR to the other option then.
Can you maybe explain a bit more, why it would cause more work? It would only hit this rule, if /^Traceback \(most recent call last\):$/ triggered the state transition, right?

[jkohen]

@igorpeshansky assigning to you, since it looks you're on it.

[Rohlik]

Any progress @igorpeshansky 🙏🏼?