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

"Fatal Python error: Cannot recover from stack overflow" when on DEBUG logging level #8267

Closed
jaywink opened this issue Sep 7, 2020 · 5 comments · Fixed by #8278
Closed

"Fatal Python error: Cannot recover from stack overflow" when on DEBUG logging level #8267

jaywink opened this issue Sep 7, 2020 · 5 comments · Fixed by #8278

Comments

@jaywink
Copy link
Member

jaywink commented Sep 7, 2020

Description

An EMS host which was on DEBUG logging level went into crash loop until log level was changed. Real error not visible but recent log info as follows below.

Version information

Synapse version: v1.19.1 (EMS, Docker)

2020-09-07 10:05:19,598 - synapse.storage.txn - 402 - DEBUG - GET-0- [TXN START] {get_rooms_for_user_with_stream_ordering-13}
2020-09-07 10:05:19,600 - synapse.storage.txn - 491 - DEBUG - GET-0- [TXN END] {get_rooms_for_user_with_stream_ordering-13} 0.001584 sec
2020-09-07 10:05:19,595 - synapse.storage.txn - 491 - DEBUG - GET-0- [TXN END] {count_users-11} 0.001219 sec
2020-09-07 10:05:19,596 - synapse.storage.txn - 402 - DEBUG - GET-0- [TXN START] {is_support_user-12}
2020-09-07 10:05:19,596 - synapse.storage.txn - 491 - DEBUG - GET-0- [TXN END] {is_support_user-12} 0.000923 sec
2020-09-07 10:05:19,597 - synapse.rest.client.v2_alpha.sync - 119 - DEBUG - GET-0- /sync: user=@ems_performance_monitor:**********.modular.im, timeout=30000, since='s195995_275179_924_1941_2075_1_1070_2408_1', set_presence='online', filter_id=None, device_id='***********'
2020-09-07 10:05:19,598 - synapse.util.caches.response_cache - 148 - DEBUG - GET-0- [sync]: no cached result for [(@ems_performance_monitor:**************.modular.im, 30000, 's195995_275179_924_1941_2075_1_1070_2408_1', None, False, '******************')], calculating new one
2020-09-07 10:05:19,598 - synapse.storage.txn - 402 - DEBUG - GET-0- [TXN START] {get_rooms_for_user_with_stream_ordering-13}
2020-09-07 10:05:19,600 - synapse.storage.txn - 491 - DEBUG - GET-0- [TXN END] {get_rooms_for_user_with_stream_ordering-13} 0.001584 sec
Fatal Python error: Cannot recover from stack overflow.

Thread 0x00007f9d257fa700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/worker.py", line 132 in _target
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/threading.py", line 67 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d25ffb700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/threading.py", line 67 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d267fc700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/threading.py", line 67 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d26ffd700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d277fe700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d27fff700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d2ce67700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9d2d668700 (most recent call first):
  File "/usr/local/lib/python3.7/threading.py", line 296 in wait
  File "/usr/local/lib/python3.7/queue.py", line 170 in get
  File "/usr/local/lib/python3.7/site-packages/twisted/_threads/_threadworker.py", line 45 in work
  File "/usr/local/lib/python3.7/threading.py", line 870 in run
  File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap

Current thread 0x00007f9d34ba1740 (most recent call first):
  File "/usr/local/lib/python3.7/traceback.py", line 473 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 497 in __init__
  File "/usr/local/lib/python3.7/traceback.py", line 104 in print_exception
  File "/usr/local/lib/python3.7/logging/__init__.py", line 947 in handleError
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1033 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1311 in flush
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1235 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1586 in callHandlers
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/logging.py", line 85 in sentry_patched_callhandlers
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1524 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1514 in _log
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1444 in log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_stdlib.py", line 120 in __call__
  File "/usr/local/lib/python3.7/site-packages/synapse/config/logger.py", line 231 in _log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_observer.py", line 131 in __call__
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_logger.py", line 144 in emit
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_io.py", line 170 in write
  File "/usr/local/lib/python3.7/logging/__init__.py", line 946 in handleError
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1033 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1311 in flush
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1235 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1586 in callHandlers
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/logging.py", line 85 in sentry_patched_callhandlers
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1524 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1514 in _log
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1444 in log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_stdlib.py", line 120 in __call__
  File "/usr/local/lib/python3.7/site-packages/synapse/config/logger.py", line 231 in _log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_observer.py", line 131 in __call__
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_logger.py", line 144 in emit
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_io.py", line 170 in write
  File "/usr/local/lib/python3.7/logging/__init__.py", line 946 in handleError
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1033 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1311 in flush
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1235 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1586 in callHandlers
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/logging.py", line 85 in sentry_patched_callhandlers
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1524 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1514 in _log
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1444 in log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_stdlib.py", line 120 in __call__
  File "/usr/local/lib/python3.7/site-packages/synapse/config/logger.py", line 231 in _log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_observer.py", line 131 in __call__
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_logger.py", line 144 in emit
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_io.py", line 170 in write
  File "/usr/local/lib/python3.7/logging/__init__.py", line 946 in handleError
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1033 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1311 in flush
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1235 in emit
  File "/usr/local/lib/python3.7/logging/__init__.py", line 894 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1586 in callHandlers
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/logging.py", line 85 in sentry_patched_callhandlers
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1524 in handle
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1514 in _log
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1444 in log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_stdlib.py", line 120 in __call__
  File "/usr/local/lib/python3.7/site-packages/synapse/config/logger.py", line 231 in _log
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_observer.py", line 131 in __call__
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_logger.py", line 144 in emit
  File "/usr/local/lib/python3.7/site-packages/twisted/logger/_io.py", line 170 in write
  File "/usr/local/lib/python3.7/logging/__init__.py", line 946 in handleError
@richvdh
Copy link
Member

richvdh commented Sep 7, 2020

I think this is a dup of #4240, which coincidentally I've been looking at this morning: basically there's an error in the logging system, which gets logged, etc.

@jaywink what was the complete log config at the time you had a problem?

@jaywink
Copy link
Member Author

jaywink commented Sep 8, 2020 •
edited
Loading

@richvdh here:

    version: 1

    formatters:
      precise:
       format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s- %(message)s'

    filters:
      context:
        (): synapse.util.logcontext.LoggingContextFilter
        request: ""

    handlers:
      console:
        class: logging.StreamHandler
        formatter: precise
      buffer:
        class: logging.handlers.MemoryHandler
        target: console
        capacity: 10
        flushLevel: 30

    loggers:
        synapse:
            level: DEBUG

        synapse.storage.SQL:
            # beware: increasing this to DEBUG will make synapse log sensitive
            # information such as access tokens.
            level: WARNING

    root:
        level: DEBUG
        handlers: [buffer]

@richvdh
Copy link
Member

richvdh commented Sep 8, 2020

weird. I can't really see what would cause a problem there. Where was the python process's stderr directed to?

@jaywink
Copy link
Member Author

jaywink commented Sep 8, 2020

weird. I can't really see what would cause a problem there. Where was the python process's stderr directed to?

It's the official Synapse docker image. I don't see that we would anywhere define stderr separately.

@richvdh
Copy link
Member

richvdh commented Sep 8, 2020

Thanks @jaywink. I think I've tracked it down.

richvdh added a commit that referenced this issue Sep 8, 2020
@richvdh
Use the right constructor for log records
dea97c0 
Update `log_function` to use the right factory to create log records, to make
sure that they have `request` attributes.

Fixes: #8267.
@richvdh richvdh mentioned this issue Sep 8, 2020
Merged
richvdh added a commit that referenced this issue Sep 8, 2020
@richvdh
Use the right constructor for log records (#8278)
703e2b8 
Update `log_function` to use the right factory to create log records, to make
sure that they have `request` attributes.

Fixes: #8267.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Use the right constructor for log records matrix-org/synapse
2 participants
@jaywink @richvdh