Synapse master explodes on python 3

[richvdh]

The main problem seems to be:

2018-11-01 14:03:59,188 - twisted - 243 - ERROR - GET-22858 - --- Logging error ---
2018-11-01 14:03:59,190 - twisted - 243 - ERROR - GET-22858 - Traceback (most recent call last):
2018-11-01 14:03:59,190 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/hawkowl/Python-3.6.6/Lib/logging/__init__.py", line 995, in emit
2018-11-01 14:03:59,190 - twisted - 243 - ERROR - GET-22858 -     stream.write(msg)
2018-11-01 14:03:59,190 - twisted - 243 - ERROR - GET-22858 - UnicodeEncodeError: 'ascii' codec can't encode character '\u2019' in position 276: ordinal not in range(128)
2018-11-01 14:03:59,190 - twisted - 243 - ERROR - GET-22858 - Call stack:
2018-11-01 14:03:59,192 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/hawkowl/Python-3.6.6/Lib/runpy.py", line 193, in _run_module_as_main
2018-11-01 14:03:59,192 - twisted - 243 - ERROR - GET-22858 -     "__main__", mod_spec)
2018-11-01 14:03:59,192 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/hawkowl/Python-3.6.6/Lib/runpy.py", line 85, in _run_code
2018-11-01 14:03:59,192 - twisted - 243 - ERROR - GET-22858 -     exec(code, run_globals)
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/app/homeserver.py", line 596, in <module>
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -     main()
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/app/homeserver.py", line 592, in main
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -     run(hs)
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/app/homeserver.py", line 583, in run
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -     logger,
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/app/_base.py", line 115, in start_reactor
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -     daemon.start()
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/daemonize.py", line 245, in start
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -     self.action(*privileged_action_result)
2018-11-01 14:03:59,193 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/app/_base.py", line 104, in run
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -     reactor.run()
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/internet/base.py", line 1267, in run
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -     self.mainLoop()
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/internet/base.py", line 1279, in mainLoop
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -     self.doIteration(t)
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/internet/epollreactor.py", line 235, in doPoll
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -     log.callWithLogger(selectable, _drdw, selectable, fd, event)
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/python/log.py", line 103, in callWithLogger
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -     return callWithContext({"system": lp}, func, *args, **kw)
2018-11-01 14:03:59,194 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/python/log.py", line 86, in callWithContext
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -     return context.call({ILogContext: newCtx}, func, *args, **kw)
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -     return self.currentContext().callWithContext(ctx, func, *args, **kw)
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -     return func(*args,**kw)
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 614, in _doReadOrWrite
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -     why = selectable.doRead()
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/internet/tcp.py", line 243, in doRead
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -     return self._dataReceived(data)
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/internet/tcp.py", line 249, in _dataReceived
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -     rval = self.protocol.dataReceived(data)
2018-11-01 14:03:59,195 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/web/http.py", line 2912, in dataReceived
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -     return self._channel.dataReceived(data)
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/web/http.py", line 2211, in dataReceived
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -     return basic.LineReceiver.dataReceived(self, data)
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/protocols/basic.py", line 572, in dataReceived
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -     why = self.lineReceived(line)
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/web/http.py", line 2099, in lineReceived
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -     self.allContentReceived()
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/web/http.py", line 2190, in allContentReceived
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -     req.requestReceived(command, path, version)
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/web/http.py", line 917, in requestReceived
2018-11-01 14:03:59,196 - twisted - 243 - ERROR - GET-22858 -     self.process()
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/.synapse-py3/lib/python3.6/site-packages/twisted/web/server.py", line 199, in process
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 -     self.render(resrc)
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/http/site.py", line 129, in render
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 -     self._started_processing(servlet_name)
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 -   File "/home/matrix/synapse/synapse/http/site.py", line 233, in _started_processing
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 -     self.get_redacted_uri()
2018-11-01 14:03:59,197 - twisted - 243 - ERROR - GET-22858 - Message: 'trying to create_pusher for %r'

[richvdh]

It seems like this was fixed by setting the log encoding to UTF-8.

[richvdh]

otoh: it's definitely a footgun that we should remind people about when switching to py3. How can we remember to do this? Something in the changelog, maybe?

[richvdh]

Summary of the fix for this is that you should add encoding: utf8 to your log config as per #4138.

[richvdh]

otoh: it's definitely a footgun that we should remind people about when switching to py3. How can we remember to do this? Something in the changelog, maybe?

I've written some words in the UPGRADE.rst in #4260, which I will link from the changelog. Hopefully that will do.