newrelic / newrelic-python-agent

New Relic Python Agent
https://docs.newrelic.com/docs/agents/python-agent
Apache License 2.0
178 stars 103 forks source link

_obfuscate_sql crashes with null parameter #788

Open mullman-mission opened 1 year ago

mullman-mission commented 1 year ago

We've recently bumped our newrelic python package from 7.4.0.172 to 8.7.1 and are now frequently encountering exceptions when our Flask application processes HTTP requests.

Description

2023-03-27 15:35:35,417 newrelic.api.transaction ERROR    Runtime instrumentation error. Exception occurred during exit. Report this issue to New Relic support.
Traceback (most recent call last):
  File ".venv/lib/python3.11/site-packages/newrelic/api/wsgi_application.py", line 681, in _nr_wsgi_application_wrapper_
    result = _WSGIApplicationMiddleware(wrapped, environ, _start_response, transaction)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/api/wsgi_application.py", line 199, in __init__
    self.iterable = self.application(self.request_environ, self.start_response)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/sentry_sdk/integrations/flask.py", line 88, in sentry_patched_wsgi_app
    return SentryWsgiMiddleware(lambda *a, **kw: old_app(self, *a, **kw))(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/sentry_sdk/integrations/wsgi.py", line 144, in __call__
    reraise(*_capture_exception(hub))
  File ".venv/lib/python3.11/site-packages/sentry_sdk/_compat.py", line 60, in reraise
    raise value
  File ".venv/lib/python3.11/site-packages/sentry_sdk/integrations/wsgi.py", line 137, in __call__
    rv = self.app(
         ^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/sentry_sdk/integrations/flask.py", line 88, in <lambda>
    return SentryWsgiMiddleware(lambda *a, **kw: old_app(self, *a, **kw))(
                                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/app.py", line 2551, in __call__
    return self.wsgi_app(environ, start_response)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/werkzeug/middleware/proxy_fix.py", line 187, in __call__
    return self.app(environ, start_response)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "services/web/flask/flask_sockets.py", line 38, in __call__
    return self.wsgi_app(environ, start_response)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/api/wsgi_application.py", line 577, in _nr_wsgi_application_wrapper_
    return wrapped(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/app.py", line 2531, in wsgi_app
    response = self.handle_exception(e)
               ^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_restx/api.py", line 674, in error_router
    return original_handler(e)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_restx/api.py", line 674, in error_router
    return original_handler(e)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_restx/api.py", line 674, in error_router
    return original_handler(e)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_cors/extension.py", line 165, in wrapped_function
    return cors_after_request(app.make_response(f(*args, **kwargs)))
                                                ^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/hooks/framework_flask.py", line 148, in _nr_wrapper_Flask_handle_exception_
    return FunctionTraceWrapper(wrapped, name=name)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/api/function_trace.py", line 166, in literal_wrapper
    return wrapped(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/app.py", line 2528, in wsgi_app
    response = self.full_dispatch_request()
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/app.py", line 1825, in full_dispatch_request
    rv = self.handle_user_exception(e)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_restx/api.py", line 674, in error_router
    return original_handler(e)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_restx/api.py", line 674, in error_router
    return original_handler(e)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_restx/api.py", line 674, in error_router
    return original_handler(e)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_cors/extension.py", line 165, in wrapped_function
    return cors_after_request(app.make_response(f(*args, **kwargs)))
                                                ^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/hooks/framework_flask.py", line 148, in _nr_wrapper_Flask_handle_exception_
    return FunctionTraceWrapper(wrapped, name=name)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/api/function_trace.py", line 166, in literal_wrapper
    return wrapped(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/app.py", line 1823, in full_dispatch_request
    rv = self.dispatch_request()
         ^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/app.py", line 1799, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/hooks/framework_flask.py", line 82, in _nr_wrapper_handler_
    return wrapped(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_login/utils.py", line 290, in decorated_view
    return current_app.ensure_sync(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask/views.py", line 107, in view
    return current_app.ensure_sync(self.dispatch_request)(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "services/core/gql/csrf_view.py", line 62, in dispatch_request
    return super().dispatch_request()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "services/core/gql/flask_view.py", line 144, in dispatch_request
    response = super().dispatch_request()
               ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/flask_graphql/graphqlview.py", line 82, in dispatch_request
    execution_results, all_params = run_http_query(
                                    ^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/graphql_server/__init__.py", line 136, in run_http_query
    response_promises = [
                        ^
  File ".venv/lib/python3.11/site-packages/graphql_server/__init__.py", line 137, in <listcomp>
    response_executor.execute(
  File ".venv/lib/python3.11/site-packages/graphql/execution/executors/sync.py", line 16, in execute
    return fn(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/hooks/component_graphqlserver.py", line 42, in wrap_get_response
    with GraphQLOperationTrace() as trace:
  File ".venv/lib/python3.11/site-packages/newrelic/api/time_trace.py", line 186, in __exit__
    self._complete_trace()
  File ".venv/lib/python3.11/site-packages/newrelic/api/time_trace.py", line 490, in _complete_trace
    self.finalize_data(transaction, *exc_data)
  File ".venv/lib/python3.11/site-packages/newrelic/api/graphql_trace.py", line 79, in finalize_data
    self.graphql = graphql = self.formatted[:limit]
                             ^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/api/graphql_trace.py", line 65, in formatted
    return self.statement.formatted(self.graphql_format)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/core/database_utils.py", line 888, in formatted
    return self.obfuscated
           ^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/core/database_utils.py", line 864, in obfuscated
    self._obfuscated = _uncomment_sql(_obfuscate_sql(self.sql,
                                      ^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.11/site-packages/newrelic/core/database_utils.py", line 106, in _obfuscate_sql
    sql = quotes_re.sub('?', sql)
          ^^^^^^^^^^^^^^^^^^^^^^^
TypeError: expected string or bytes-like object, got 'NoneType'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File ".venv/lib/python3.11/site-packages/newrelic/api/transaction.py", line 429, in __exit__
    root.complete_root()
  File ".venv/lib/python3.11/site-packages/newrelic/api/transaction.py", line 118, in complete_root
    trace_cache().complete_root(self)
  File ".venv/lib/python3.11/site-packages/newrelic/core/trace_cache.py", line 304, in complete_root
    task_ids = (id(task) for task in all_tasks(self.asyncio))
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: 'NoneType' object is not iterable

Expected Behavior

For it to not throw an exception

Troubleshooting or NR Diag results

Steps to Reproduce

I unfortunately haven't had time to put together a sample app that reproduces this issue and I cannot share the code base behind this. I may be able to find some time this week to do so, though, unless you all have an idea what's going on.

Your Environment

The main players in this scenario seems to be Flask 2.2.3, Flask-SQLAlchemy 3.0.3, and SQLAlchemy 1.4.46. Python 3.11.2.

Additional context

Sorry this is an extremely dry bug report, let me know if I should include any info on dependency versions that seem related to this crash.

mullman-mission commented 1 year ago

Update: poked around at this some more, and it seems to only occur when we send a GET request to our GraphQL server which returns GraphiQL, so I think that https://github.com/newrelic/newrelic-python-agent/blob/main/newrelic/hooks/component_graphqlserver.py#L38 should just return wrapped if query is None, or don't hook in to calls other than POST.

lrafeei commented 1 year ago

Hello--I cannot seem to be able to replicate this, so would you be able to supply a sample app?

maroskucera commented 1 year ago

Hello, I too have encountered this error in my application and prepared a sample app:

from flask import Flask
from flask_graphql import GraphQLView

from graphene import ObjectType, String, Schema

class Query(ObjectType):
    hello = String(first_name=String(default_value="stranger"))
    goodbye = String()

    def resolve_hello(root, info, first_name):
        return f"Hello {first_name}!"

    def resolve_goodbye(root, info):
        return "See ya!"

schema = Schema(query=Query)

app = Flask(__name__)

app.add_url_rule(
    "/graphql",
    view_func=GraphQLView.as_view(
        "graphql",
        schema=schema,
        graphiql=True,
    ),
)

if __name__ == "__main__":
    app.run()

I put that in a file called example.py inside a new virtualenv created on an M1 Mac running macOS 13.3 with Python 3.11 installed from the Python website. Inside the virtualenv, I installed dependencies with this

pip install flask flask-graphql graphene newrelic

and ran the app like this

FLASK_DEBUG=True NEW_RELIC_CONFIG_FILE=newrelic.ini newrelic-admin run-program python example.py

I used a newly created New Relic application/service and a default newrelic.ini downloaded for it from the panel. By default, Flask will serve on 127.0.0.1:5000, so I hit 127.0.0.1:5000/graphql. On the first load, it worked (I haven't had time to investigate why it works on first load). But when I refreshed, just like with my app, it crashed with the message mentioned above

...
  File "lib/python3.11/site-packages/newrelic/core/database_utils.py", line 106, in _obfuscate_sql
    sql = quotes_re.sub('?', sql)
          ^^^^^^^^^^^^^^^^^^^^^^^
TypeError: expected string or bytes-like object, got 'NoneType'

The first request after startup, both in my app and in this example, is always okay. It doesn't matter whether it's a browser request to load GraphiQL or an actual GraphQL POST request containing the query. Only after that first request does the error show up on an attempt to load GraphiQL.

I hope this helps 🙂

stale[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

maroskucera commented 1 year ago

Is there anything I can do to help resolve this? From my limited investigation, what mullman-mission suggested seems to be the cleanest possible solution. Since May, we patch the library on our deployments to do exactly that and encountered no issues. However, patching like this is of course sub-optimal. I can prepare the PR if needed...

terrafied commented 1 year ago

We're still dealing with this error and it's rather annoying. @maroskucera I'd at least love your deployment patch solution.

maroskucera commented 1 year ago

After each update of the library, we find the wrap_get_response function in the newrelic/hooks/component_graphqlserver.py file in our virtualenv's site-packages and add

if query is None:
    return wrapped(*args, **kwargs)

after

transaction.set_transaction_name(callable_name(wrapped), "GraphQL", priority=10)

which is at line 40 as of v8.11.0. What is noteworthy here is that this stops before creating a trace, which is fine for us. I tried using

if query is None:
    query = ""

and that ran okay as well, that should create a trace if you want/need that. However, I tested it only briefly and only locally.

kviktor commented 8 months ago

Not sure if related but we are also seeing the same(ish) error message when our gunicorn workers times out in the newrelic part of the code.

image