Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Overly verbose stack trace dumped to logs when we fail to resolve state due to missing prev_events #14344

Closed
DMRobertson opened this issue Nov 1, 2022 · 1 comment · Fixed by #14346
Closed

Overly verbose stack trace dumped to logs when we fail to resolve state due to missing prev_events #14344

DMRobertson opened this issue Nov 1, 2022 · 1 comment · Fixed by #14346
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. O-Occasional Affects or can be seen by some users regularly or most users rarely S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. z-WTF Causing the user to exclaim! These issues are high impact and low effort.

Comments

@DMRobertson
Copy link
Contributor

DMRobertson commented Nov 1, 2022 •
edited
Loading

It ends up as 9001 sentry events because it goes to stderr.

2022-11-01 16:50:10,522 - synapse.handlers.federation_event - 1069 - WARNING - GET-763620af9a19a531-GRU-----$[EVENT_ID]-- - Error attempting to resolve state at missing prev_events
Capture point (most recent call last):
  File "/usr/lib/python3.9/runpy.py", line 197, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/lib/python3.9/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/home/synapse/src/synapse/app/generic_worker.py", line 491, in <module>
    main()
  File "/home/synapse/src/synapse/app/generic_worker.py", line 487, in main
    start(sys.argv[1:])
  File "/home/synapse/src/synapse/app/generic_worker.py", line 482, in start
    _base.start_worker_reactor("synapse-generic-worker", config)
  File "/home/synapse/src/synapse/app/_base.py", line 124, in start_worker_reactor
    start_reactor(
  File "/home/synapse/src/synapse/app/_base.py", line 189, in start_reactor
    run()
  File "/home/synapse/src/synapse/app/_base.py", line 171, in run
    run_command()
  File "/home/synapse/src/synapse/app/_base.py", line 109, in <lambda>
    run_command: Callable[[], None] = lambda: reactor.run(),
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/base.py", line 1318, in run
    self.mainLoop()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/base.py", line 1331, in mainLoop
    reactorBaseSelf.doIteration(t)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/epollreactor.py", line 244, in doPoll
    log.callWithLogger(selectable, _drdw, selectable, fd, event)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/python/log.py", line 96, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/python/log.py", line 80, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/python/context.py", line 117, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/python/context.py", line 82, in callWithContext
    return func(*args, **kw)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/posixbase.py", line 683, in _doReadOrWrite
    why = selectable.doRead()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/tcp.py", line 248, in doRead
    return self._dataReceived(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/tcp.py", line 253, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/endpoints.py", line 147, in dataReceived
    return self._wrappedProtocol.dataReceived(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/protocols/tls.py", line 329, in dataReceived
    self._flushReceiveBIO()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/protocols/tls.py", line 295, in _flushReceiveBIO
    ProtocolWrapper.dataReceived(self, bytes)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/protocols/policies.py", line 110, in dataReceived
    self.wrappedProtocol.dataReceived(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 1651, in dataReceived
    self._parser.dataReceived(bytes)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 384, in dataReceived
    HTTPParser.dataReceived(self, data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/protocols/basic.py", line 555, in dataReceived
    why = self.rawDataReceived(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 302, in rawDataReceived
    self.bodyDecoder.dataReceived(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/http.py", line 2060, in dataReceived
    goOn = getattr(self, "_dataReceived_" + self.state)()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/http.py", line 2019, in _dataReceived_TRAILER
    self.finishCallback(data)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 445, in _finished
    self.finisher(rest)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 1043, in dispatcher
    return func(*args, **kwargs)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 1609, in _finishResponse_WAITING
    self._disconnectParser(reason)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 1633, in _disconnectParser
    parser.connectionLost(reason)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 555, in connectionLost
    self.response._bodyDataFinished()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 1043, in dispatcher
    return func(*args, **kwargs)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/web/_newclient.py", line 1283, in _bodyDataFinished_CONNECTED
    self._bodyProtocol.connectionLost(reason)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/treq/content.py", line 37, in connectionLost
    self.finished.callback(None)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 695, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 797, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 891, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/home/synapse/src/synapse/util/async_helpers.py", line 660, in success_cb
    new_d.callback(val)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 695, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 797, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 891, in _runCallbacks
    current.result = callback(  # type: ignore[misc]
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 1791, in gotResult
    _inlineCallbacks(r, gen, status, context)
  File "/home/synapse/env-poetry/lib/python3.9/site-packages/twisted/internet/defer.py", line 1696, in _inlineCallbacks
    result = context.run(gen.send, result)
  File "/home/synapse/src/synapse/http/server.py", line 229, in wrapped_async_request_handler
    await h(self, request)
  File "/home/synapse/src/synapse/http/server.py", line 307, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "/home/synapse/src/synapse/http/server.py", line 513, in _async_render
    callback_return = await raw_callback_return
  File "/home/synapse/src/synapse/rest/client/room.py", line 679, in on_GET
    msgs = await self.pagination_handler.get_messages(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/handlers/pagination.py", line 502, in get_messages
    await self.hs.get_federation_handler().maybe_backfill(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/handlers/federation.py", line 202, in maybe_backfill
    return await self._maybe_backfill_inner(
  File "/home/synapse/src/synapse/handlers/federation.py", line 508, in _maybe_backfill_inner
    success = await try_backfill(likely_domains)
  File "/home/synapse/src/synapse/handlers/federation.py", line 438, in try_backfill
    await self._federation_event_handler.backfill(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/handlers/federation_event.py", line 653, in backfill
    await self._process_pulled_events(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/handlers/federation_event.py", line 839, in _process_pulled_events
    await self._process_pulled_event(origin, ev, backfilled=backfilled)
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/handlers/federation_event.py", line 899, in _process_pulled_event
    context = await self._compute_event_context_with_maybe_missing_prevs(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
Traceback (most recent call last):
  File "/home/synapse/src/synapse/handlers/federation_event.py", line 1052, in _compute_event_context_with_maybe_missing_prevs
    await self._get_state_ids_after_missing_prev_event(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/handlers/federation_event.py", line 1116, in _get_state_ids_after_missing_prev_event
    ) = await self._federation_client.get_room_state_ids(
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/logging/opentracing.py", line 889, in _wrapper
    return await func(*args, **kwargs)  # type: ignore[misc]
  File "/home/synapse/src/synapse/federation/federation_client.py", line 503, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/home/synapse/src/synapse/federation/transport/client.py", line 78, in get_room_state_ids
    return await self.client.get_json(
  File "/home/synapse/src/synapse/http/matrixfederationclient.py", line 1078, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/home/synapse/src/synapse/http/matrixfederationclient.py", line 406, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/home/synapse/src/synapse/http/matrixfederationclient.py", line 668, in _send_request
    raise exc
synapse.api.errors.HttpResponseException: 404: Not Found
@DMRobertson DMRobertson added z-WTF Causing the user to exclaim! These issues are high impact and low effort. Z-Sentry Issue was discovered by looking at Sentry reports on Matrix.org labels Nov 1, 2022
@DMRobertson
Copy link
Contributor Author

This did not appear in Sentry. (It is logged at warning and comes from

synapse/synapse/handlers/federation_event.py

Lines 1068 to 1072 in b7a7ff6

except Exception:
logger.warning(
"Error attempting to resolve state at missing prev_events",
exc_info=True,
)

which I think is needlessly verbose.) I thought it came from sentry because I was grepping for a line that appears in basically all of our stack traces.

@DMRobertson DMRobertson added A-Logging Synapse's logs (structured or otherwise). Not metrics. S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. O-Occasional Affects or can be seen by some users regularly or most users rarely and removed Z-Sentry Issue was discovered by looking at Sentry reports on Matrix.org labels Nov 1, 2022
@DMRobertson DMRobertson changed the title Utterly monstrous traceback in Sentry Overly verbose stack trace dumped to logs when we fail to resolve state due to missing prev_events Nov 1, 2022
DMRobertson pushed a commit that referenced this issue Nov 1, 2022
Quieter logging for stateres failure at missing prev events
ae9cd99 
Fixes #14344.
@DMRobertson DMRobertson mentioned this issue Nov 1, 2022
Merged
DMRobertson pushed a commit that referenced this issue Nov 1, 2022
Quieter logging for stateres failure at missing prev events
211068b 
Fixes #14344.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. O-Occasional Affects or can be seen by some users regularly or most users rarely S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. z-WTF Causing the user to exclaim! These issues are high impact and low effort.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Quieter logging for stateres failure at missing prev events matrix-org/synapse
1 participant
@DMRobertson