Since 0.33.8, homeserver crashes with UnicodeDecodeError in logger

[kiorky]

Description

Since 0.33.8, homeserver crashes with UnicodeDecodeError in logger

Steps to reproduce

I didnt found yet what's the cause but the reactor stops with patterns in logs
one is

ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >]
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 121, in _respond_local_thumbnail
    yield respond_with_responder(request, responder, t_type, t_length)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
    _inlineCallbacks(None, g, status)
--- <exception caught here> ---
  File "/usr/local/lib/python2.7/dist-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 71, in _async_render_GET
    request, media_id, width, height, method, m_type
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 121, in _respond_local_thumbnail
    yield respond_with_responder(request, responder, t_type, t_length)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/_base.py", line 137, in respond_with_responder
    yield responder.write_to_consumer(request)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/media_storage.py", line 263, in write_to_consumer
    FileSender().beginFileTransfer(self.open_file, consumer)
  File "/usr/local/lib/python2.7/dist-packages/twisted/protocols/basic.py", line 923, in beginFileTransfer
    self.consumer.registerProducer(self, False)
  File "/usr/local/lib/python2.7/dist-packages/twisted/web/http.py", line 958, in registerProducer
    self.channel.registerProducer(producer, streaming)
exceptions.AttributeError: 'NoneType' object has no attribute 'registerProducer'
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 121, in _respond_local_thumbnail
    yield respond_with_responder(request, responder, t_type, t_length)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
    _inlineCallbacks(None, g, status)
--- <exception caught here> ---
  File "/usr/local/lib/python2.7/dist-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 71, in _async_render_GET
    request, media_id, width, height, method, m_type
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 121, in _respond_local_thumbnail
    yield respond_with_responder(request, responder, t_type, t_length)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/_base.py", line 137, in respond_with_responder
    yield responder.write_to_consumer(request)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/media/v1/media_storage.py", line 263, in write_to_consumer
    FileSender().beginFileTransfer(self.open_file, consumer)
  File "/usr/local/lib/python2.7/dist-packages/twisted/protocols/basic.py", line 923, in beginFileTransfer
    self.consumer.registerProducer(self, False)
  File "/usr/local/lib/python2.7/dist-packages/twisted/web/http.py", line 958, in registerProducer
    self.channel.registerProducer(producer, streaming)
exceptions.AttributeError: 'NoneType' object has no attribute 'registerProducer'

the other is

2018-11-15 12:24:45,357 - synapse.metrics - 374 - INFO - - Collecting gc 0
2018-11-15 12:24:45,358 - synapse.access.http.8008 - 233 - INFO - OPTIONS-117976- 1.2.3.4 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=0&timeout=30000&since=s543777_21972192_1149_607731_354593_779_10110_44441_153
2018-11-15 12:24:45,358 - twisted - 243 - ERROR - POST-117962- Traceback (most recent call last): 
2018-11-15 12:24:45,359 - twisted - 243 - ERROR - POST-117962-   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit 
2018-11-15 12:24:45,360 - twisted - 243 - ERROR - POST-117962-     if self.shouldRollover(record):
2018-11-15 12:24:45,360 - twisted - 243 - ERROR - POST-117962-   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
2018-11-15 12:24:45,360 - twisted - 243 - ERROR - POST-117962-     msg = "%s\n" % self.format(record)
2018-11-15 12:24:45,360 - twisted - 243 - ERROR - POST-117962-   File "/usr/lib/python2.7/logging/__init__.py", line 732, in format
2018-11-15 12:24:45,361 - twisted - 243 - ERROR - POST-117962-     return fmt.format(record)
2018-11-15 12:24:45,361 - twisted - 243 - ERROR - POST-117962-   File "/usr/lib/python2.7/logging/__init__.py", line 474, in format
2018-11-15 12:24:45,361 - twisted - 243 - ERROR - POST-117962-     s = self._fmt % record.__dict__
2018-11-15 12:24:45,361 - twisted - 243 - ERROR - POST-117962- UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 68: ordinal not in range(128)

Version information

0.33.8 (docker)

[richvdh]

what is your logging config?

[kiorky]

hs.yml

verbose: 0
log_file: "/data/homeserver.log"
log_config: "/data/log.config"

log.config

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:
  file:
    class: logging.handlers.RotatingFileHandler
    formatter: precise
    filename: /data/homeserver.log
    maxBytes: 104857600
    backupCount: 10
    filters: [context]
  console:
    class: logging.StreamHandler
    formatter: precise
    filters: [context]

loggers:
    synapse:
        level: INFO

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

root:
    level: INFO
    handlers: [file, console]

[kiorky]

I was able to workaround the bug by having CRITICAL as the loglevel, ERROR was not enough.

For now, the server hasnt crashed in 4 days.

[richvdh]

@kiorky are you on python 3?

[kiorky]

Nope i didnt had time to finish the py3 image and to switch on it.
IOW, The image i'm using (corpusops/docker-matrix) is still with py2.

The logger bug as we saw with the issues in the tracker seems to be on both versions.

[richvdh]

Ok I've opened #4240 to track this more succinctly. I'm not yet convinced it's the same problem as #4202.

[richvdh]

@kiorky do you have a log_config setting in your hs.yml?

[kiorky]

I already posted all my log config: #4191 (comment)

The crash arrises when loglevel < CRITICAL

[kiorky]

Related to the other bug linked, i ll try to add encoding: utf8 to the handler.

[kiorky]

It's on; now the server may crash in the next days/hours ^^

[richvdh]

I already posted all my log config: #4191 (comment)

In that case, your log.config file is ignored. It is not used unless you have a log_config setting which points to it in your homeserver.yaml.

[kiorky]

What is wrong with my spelling in the former comment ?
Can you be more attentive and see in this one that i posted since the first bug issuance 2 excerpt from homeserver.yml (to show that i have an explicit logfile setting), and the related whole log.config file.

[kiorky]

As i said, i added encoding: utf8 in log.config file handlers, and lowered back to INFO to try to retrigger the bug.
Since 30/11/18 01:00 UTC+1, the server has'nt crashed anymore but it can take up to a week to re-occur.

[aaronraimist]

But do you have a log_config setting?

log_config is not the same as the log_file setting.

your homeserver.yaml should look something like:

# Logging verbosity level.
verbose: 0

# File to write logging to
log_file: "/home/michael/.synapse/homeserver.log"

# A yaml python logging config file
log_config: "/home/michael/.synapse/raim.ist.log.config"

[kiorky]

My bad, brain is a strange thing that make see what he wants.
I update the former comment for posterity, but also see below

hs.yaml

log_file: "/data/homeserver.log"
log_config: "/data/log.config"

[richvdh]

@aaronraimist thanks for helping out.

FWIW if you do have a log_config setting, both log_file and verbose are ignored. None of this is entirely relevant here: I was just trying to confirm that your log.config file was being used.

[kiorky]

As an update, despite the encoding parameter the server just crashed today with the same log.

2018-12-03 16:01:38,062 - synapse.access.http.8008 - 233 - INFO - POST-1029348- 92.88.249.199 - 8008 - Received request: POST /_matrix/client/r0/rooms/!Px
2018-12-03 16:01:38,063 - synapse.metrics - 374 - INFO - - Collecting gc 0
2018-12-03 16:01:38,065 - twisted - 244 - ERROR - POST-1029348- Traceback (most recent call last):
2018-12-03 16:01:38,066 - twisted - 244 - ERROR - POST-1029348-   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
2018-12-03 16:01:38,066 - twisted - 244 - ERROR - POST-1029348-     if self.shouldRollover(record):
2018-12-03 16:01:38,067 - twisted - 244 - ERROR - POST-1029348-   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
2018-12-03 16:01:38,067 - twisted - 244 - ERROR - POST-1029348-     msg = "%s\n" % self.format(record)
2018-12-03 16:01:38,067 - twisted - 244 - ERROR - POST-1029348-   File "/usr/lib/python2.7/logging/__init__.py", line 732, in format
2018-12-03 16:01:38,068 - twisted - 244 - ERROR - POST-1029348-     return fmt.format(record)
2018-12-03 16:01:38,068 - twisted - 244 - ERROR - POST-1029348-   File "/usr/lib/python2.7/logging/__init__.py", line 474, in format
2018-12-03 16:01:38,068 - twisted - 244 - ERROR - POST-1029348-     s = self._fmt % record.__dict__
2018-12-03 16:01:38,068 - twisted - 244 - ERROR - POST-1029348- UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 69: ordinal not in range(128)
2018-12-03 16:01:38,069 - twisted - 244 - ERROR - POST-1029348- Logged from file _base.py, line 254

[kiorky]

Im back to CRITICAL level