task: Excessive logs for user errors

[ogenstad]

Component

API Server / GraphQL

Task Description

If users provide invalid data there are some situations where the logs in Infrahub are excessive. An example is if you try to create a BuiltinTag called "red" and this tag already exists.

The user will be informed that the tag exists and everything seems fine from the users point of view.

However in the logs we get a critical error:

14:34:05.297 | CRITICAL | infrahub.graphql - {'exc_info': ValueError('An object already exist with this value: name: red at name'), 'event': 'Unhandled exception occurred in resolvers', 'request_id': '16ab53b810eb45f6aa07c6627d3e55ec', 'app': 'infrahub.api', 'worker': '36af3e7d-5c7b-432b-b92d-05d9e1fd890b', 'timestamp': '2024-10-09T12:34:05.297274Z', 'logger': 'infrahub.graphql', 'level': 'critical'}

This could be that we're reraising an error we've already defined as the internal ValueError which we then don't do anything about.

Another example is if the user sends in an invalid query:

query MyQuery {
  BuiltinTag {
    edges {
      node {
        id
      }
    }
  }

In the above query we are missing the last closing bracket and when sent into Infrahub even the error message returned looks off:

{
  "errors": [
    {
      "message": "Failed to fetch",
      "stack": "TypeError: Failed to fetch\n    at http://localhost:8080/src/pages/graphql/index.tsx:31:22\n    at http://localhost:8080/node_modules/.vite/deps/chunk-QUUSDRZS.js?v=62db7a3e:14302:33\n    at onClick (http://localhost:8080/node_modules/.vite/deps/chunk-QUUSDRZS.js?v=62db7a3e:16791:19)\n    at overrideProps.<computed> (http://localhost:8080/node_modules/.vite/deps/chunk-Y72ESYVM.js?v=62db7a3e:76:9)\n    at HTMLUnknownElement.callCallback2 (http://localhost:8080/node_modules/.vite/deps/chunk-ZFKBY7OL.js?v=62db7a3e:3674:22)\n    at Object.invokeGuardedCallbackDev (http://localhost:8080/node_modules/.vite/deps/chunk-ZFKBY7OL.js?v=62db7a3e:3699:24)\n    at invokeGuardedCallback (http://localhost:8080/node_modules/.vite/deps/chunk-ZFKBY7OL.js?v=62db7a3e:3733:39)\n    at invokeGuardedCallbackAndCatchFirstError (http://localhost:8080/node_modules/.vite/deps/chunk-ZFKBY7OL.js?v=62db7a3e:3736:33)\n    at executeDispatch (http://localhost:8080/node_modules/.vite/deps/chunk-ZFKBY7OL.js?v=62db7a3e:7014:11)\n    at processDispatchQueueItemsInOrder (http://localhost:8080/node_modules/.vite/deps/chunk-ZFKBY7OL.js?v=62db7a3e:7034:15)"
    }
  ]
}

Here the expectation would be a cleaner log message.

Also within the actual Infrahub logs it's very verbose. We might have an info log for reference if a wrong query comes it, or nothing at all. It should be treated as a user error and reported back in a friendly way.

15:05:16.440 | ERROR   | uvicorn.error - Exception in ASGI application
  + Exception Group Traceback (most recent call last):
  |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/_utils.py", line 77, in collapse_excgroups
  |     yield
  |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 186, in __call__
  |     async with anyio.create_task_group() as task_group:
  |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/anyio/_backends/_asyncio.py", line 736, in __aexit__
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/uvicorn/protocols/http/httptools_impl.py", line 401, in run_asgi
    |     result = await app(  # type: ignore[func-returns-value]
    |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/uvicorn/middleware/proxy_headers.py", line 70, in __call__
    |     return await self.app(scope, receive, send)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/fastapi/applications.py", line 1054, in __call__
    |     await super().__call__(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/applications.py", line 113, in __call__
    |     await self.middleware_stack(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/errors.py", line 187, in __call__
    |     raise exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/errors.py", line 165, in __call__
    |     await self.app(scope, receive, _send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/gzip.py", line 20, in __call__
    |     await responder(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/gzip.py", line 39, in __call__
    |     await self.app(scope, receive, self.send_with_gzip)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/cors.py", line 93, in __call__
    |     await self.simple_response(scope, receive, send, request_headers=headers)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/cors.py", line 144, in simple_response
    |     await self.app(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette_exporter/middleware.py", line 499, in __call__
    |     raise exception
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette_exporter/middleware.py", line 405, in __call__
    |     await self.app(scope, receive, wrapped_send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/asgi_correlation_id/middleware.py", line 90, in __call__
    |     await self.app(scope, receive, handle_outgoing_request)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 185, in __call__
    |     with collapse_excgroups():
    |   File "/Users/patrick/.nix-profile/lib/python3.12/contextlib.py", line 158, in __exit__
    |     self.gen.throw(value)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/_utils.py", line 83, in collapse_excgroups
    |     raise exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 187, in __call__
    |     response = await self.dispatch_func(request, call_next)
    |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/Code/opsmill/infrahub/backend/infrahub/server.py", line 172, in add_telemetry_span_exception
    |     return await call_next(request)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 163, in call_next
    |     raise app_exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 149, in coro
    |     await self.app(scope, receive_or_disconnect, send_no_error)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 185, in __call__
    |     with collapse_excgroups():
    |   File "/Users/patrick/.nix-profile/lib/python3.12/contextlib.py", line 158, in __exit__
    |     self.gen.throw(value)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/_utils.py", line 83, in collapse_excgroups
    |     raise exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 187, in __call__
    |     response = await self.dispatch_func(request, call_next)
    |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/Code/opsmill/infrahub/backend/infrahub/server.py", line 161, in add_process_time_header
    |     response = await call_next(request)
    |                ^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 163, in call_next
    |     raise app_exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 149, in coro
    |     await self.app(scope, receive_or_disconnect, send_no_error)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 185, in __call__
    |     with collapse_excgroups():
    |   File "/Users/patrick/.nix-profile/lib/python3.12/contextlib.py", line 158, in __exit__
    |     self.gen.throw(value)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/_utils.py", line 83, in collapse_excgroups
    |     raise exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 187, in __call__
    |     response = await self.dispatch_func(request, call_next)
    |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/Code/opsmill/infrahub/backend/infrahub/server.py", line 154, in logging_middleware
    |     response = await call_next(request)
    |                ^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 163, in call_next
    |     raise app_exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/base.py", line 149, in coro
    |     await self.app(scope, receive_or_disconnect, send_no_error)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/opentelemetry/instrumentation/asgi/__init__.py", line 631, in __call__
    |     await self.app(scope, otel_receive, otel_send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/middleware/exceptions.py", line 62, in __call__
    |     await wrap_app_handling_exceptions(self.app, conn)(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/_exception_handler.py", line 62, in wrapped_app
    |     raise exc
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/_exception_handler.py", line 51, in wrapped_app
    |     await app(scope, receive, sender)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/routing.py", line 715, in __call__
    |     await self.middleware_stack(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/routing.py", line 735, in app
    |     await route.handle(scope, receive, send)
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/starlette/routing.py", line 288, in handle
    |     await self.app(scope, receive, send)
    |   File "/Users/patrick/Code/opsmill/infrahub/backend/infrahub/graphql/app.py", line 144, in __call__
    |     response = await self._handle_http_request(
    |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/Code/opsmill/infrahub/backend/infrahub/graphql/app.py", line 207, in _handle_http_request
    |     analyzed_query = InfrahubGraphQLQueryAnalyzer(
    |                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/Code/opsmill/infrahub/backend/infrahub/graphql/analyzer.py", line 23, in __init__
    |     super().__init__(query=query, schema=schema)
    |   File "/Users/patrick/Code/opsmill/infrahub/python_sdk/infrahub_sdk/analyzer.py", line 34, in __init__
    |     self.document: DocumentNode = parse(self.query)
    |                                   ^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 113, in parse
    |     return parser.parse_document()
    |            ^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 241, in parse_document
    |     definitions=self.many(TokenKind.SOF, self.parse_definition, TokenKind.EOF),
    |                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 1151, in many
    |     nodes = [parse_fn()]
    |              ^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 300, in parse_definition
    |     return getattr(self, f"parse_{method_name}")()
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 325, in parse_operation_definition
    |     selection_set=self.parse_selection_set(),
    |                   ^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 368, in parse_selection_set
    |     selections=self.many(
    |                ^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 1155, in many
    |     append(parse_fn())
    |            ^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 376, in parse_selection
    |     return (
    |            ^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 383, in parse_field
    |     name_or_alias = self.parse_name()
    |                     ^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 232, in parse_name
    |     token = self.expect_token(TokenKind.NAME)
    |             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/Users/patrick/.virtualenvs/infrahub/lib/python3.12/site-packages/graphql/language/parser.py", line 1047, in expect_token
    |     raise GraphQLSyntaxError(
    | graphql.error.syntax_error.GraphQLSyntaxError: Syntax Error: Expected Name, found <EOF>.
    |
    | GraphQL request:8:4
    | 7 |     }
    | 8 |   }
    |   |    ^
    | 9 |
    +------------------------------------