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

matrix-synapse down and users can not connected #4086

Closed
progserega opened this issue Oct 25, 2018 · 23 comments
Closed

matrix-synapse down and users can not connected #4086

progserega opened this issue Oct 25, 2018 · 23 comments
Labels
z-bug (Deprecated Label)

Comments

@progserega
Copy link

progserega commented Oct 25, 2018 •
edited
Loading

1 Matrix-synapse down and not proccess request to him.
2. Logs show error and no more record.
3. Clients can not connect to server.

    2018-10-25 15:58:33,865 - synapse.access.http.8008 - 233 - INFO - POST-299239- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/unstable/keys/claim
    2018-10-25 15:58:33,874 - synapse.metrics - 374 - INFO - - Collecting gc 0
    2018-10-25 15:58:33,894 - synapse.access.http.8008 - 233 - INFO - POST-299240- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/unstable/keys/claim
    2018-10-25 15:58:33,904 - synapse.access.http.8008 - 233 - INFO - POST-299241- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/unstable/keys/claim
    2018-10-25 15:58:33,913 - synapse.access.http.8008 - 233 - INFO - POST-299242- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/unstable/keys/claim
    2018-10-25 15:58:33,934 - synapse.http.site - 203 - WARNING - GET-299199- Error processing request <SynapseRequest at 0x7f307121d710 method=u'GET' uri=u'/_matrix/client/r0/sync?timeout=30000&filter=0&since=s175379_5832283_2533_182983_    __50569_182_5004_39409_112&set_presence=offline' clientproto=u'HTTP/1.0' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly.
    2018-10-25 15:58:33,955 - synapse.access.http.8008 - 233 - INFO - POST-299243- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/unstable/keys/claim
    2018-10-25 15:58:33,973 - twisted - 243 - ERROR - POST-299240- Traceback (most recent call last): 
    2018-10-25 15:58:33,973 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
    2018-10-25 15:58:33,974 - twisted - 243 - ERROR - POST-299240-     if self.shouldRollover(record):
    2018-10-25 15:58:33,974 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
    2018-10-25 15:58:33,974 - twisted - 243 - ERROR - POST-299240-     msg = "%s\n" % self.format(record)
    2018-10-25 15:58:33,974 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format 
    2018-10-25 15:58:33,975 - twisted - 243 - ERROR - POST-299240-     return fmt.format(record)
    2018-10-25 15:58:33,975 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format 
    2018-10-25 15:58:33,975 - twisted - 243 - ERROR - POST-299240-     raise e
    2018-10-25 15:58:33,977 - twisted - 243 - ERROR - POST-299240- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 46: ordinal not in range(128)
    2018-10-25 15:58:33,978 - twisted - 243 - ERROR - POST-299240- Logged from file _base.py, line 254
    2018-10-25 15:58:33,978 - twisted - 243 - ERROR - POST-299240- Traceback (most recent call last): 
    2018-10-25 15:58:33,978 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
    2018-10-25 15:58:33,978 - twisted - 243 - ERROR - POST-299240-     msg = self.format(record)
    2018-10-25 15:58:33,979 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format 
    2018-10-25 15:58:33,979 - twisted - 243 - ERROR - POST-299240-     return fmt.format(record)
    2018-10-25 15:58:33,979 - twisted - 243 - ERROR - POST-299240-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format 
    2018-10-25 15:58:33,979 - twisted - 243 - ERROR - POST-299240-     raise e
    2018-10-25 15:58:33,980 - twisted - 243 - ERROR - POST-299240- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 46: ordinal not in range(128)
    2018-10-25 15:58:33,980 - twisted - 243 - ERROR - POST-299240- Logged from file _base.py, line 254
    2018-10-25 15:58:33,983 - twisted - 243 - ERROR - POST-299242- Traceback (most recent call last): 
    2018-10-25 15:58:33,984 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
    2018-10-25 15:58:33,984 - twisted - 243 - ERROR - POST-299242-     if self.shouldRollover(record):
    2018-10-25 15:58:33,984 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
    2018-10-25 15:58:33,984 - twisted - 243 - ERROR - POST-299242-     msg = "%s\n" % self.format(record)
    2018-10-25 15:58:33,985 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format 
    2018-10-25 15:58:33,985 - twisted - 243 - ERROR - POST-299242-     return fmt.format(record)
    2018-10-25 15:58:33,985 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format 
    2018-10-25 15:58:33,985 - twisted - 243 - ERROR - POST-299242-     raise e
    2018-10-25 15:58:33,986 - twisted - 243 - ERROR - POST-299242- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 46: ordinal not in range(128)
    2018-10-25 15:58:33,986 - twisted - 243 - ERROR - POST-299242- Logged from file _base.py, line 254
    2018-10-25 15:58:33,986 - twisted - 243 - ERROR - POST-299242- Traceback (most recent call last): 
    2018-10-25 15:58:33,986 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
    2018-10-25 15:58:33,987 - twisted - 243 - ERROR - POST-299242-     msg = self.format(record)
    2018-10-25 15:58:33,987 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format 
    2018-10-25 15:58:33,987 - twisted - 243 - ERROR - POST-299242-     return fmt.format(record)
    2018-10-25 15:58:33,987 - twisted - 243 - ERROR - POST-299242-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format 
    2018-10-25 15:58:33,988 - twisted - 243 - ERROR - POST-299242-     raise e
    2018-10-25 15:58:33,988 - twisted - 243 - ERROR - POST-299242- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 46: ordinal not in range(128)
    2018-10-25 15:58:33,988 - twisted - 243 - ERROR - POST-299242- Logged from file _base.py, line 254
    2018-10-25 15:58:33,990 - twisted - 243 - ERROR - POST-299241- Traceback (most recent call last): 
    2018-10-25 15:58:33,990 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
    2018-10-25 15:58:33,991 - twisted - 243 - ERROR - POST-299241-     if self.shouldRollover(record):
    2018-10-25 15:58:33,991 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
    2018-10-25 15:58:33,991 - twisted - 243 - ERROR - POST-299241-     msg = "%s\n" % self.format(record)
    2018-10-25 15:58:33,991 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format 
    2018-10-25 15:58:33,992 - twisted - 243 - ERROR - POST-299241-     return fmt.format(record)
    2018-10-25 15:58:33,992 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format 
    2018-10-25 15:58:33,992 - twisted - 243 - ERROR - POST-299241-     raise e
    2018-10-25 15:58:33,992 - twisted - 243 - ERROR - POST-299241- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 46: ordinal not in range(128)
    2018-10-25 15:58:33,992 - twisted - 243 - ERROR - POST-299241- Logged from file _base.py, line 254
    2018-10-25 15:58:33,993 - twisted - 243 - ERROR - POST-299241- Traceback (most recent call last): 
    2018-10-25 15:58:33,993 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
    2018-10-25 15:58:33,994 - twisted - 243 - ERROR - POST-299241-     msg = self.format(record)
    2018-10-25 15:58:33,994 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format 
    2018-10-25 15:58:33,995 - twisted - 243 - ERROR - POST-299241-     return fmt.format(record)
    2018-10-25 15:58:33,995 - twisted - 243 - ERROR - POST-299241-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format 
    2018-10-25 15:58:33,996 - twisted - 243 - ERROR - POST-299241-     raise e
    2018-10-25 15:58:33,996 - twisted - 243 - ERROR - POST-299241- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 46: ordinal not in range(128)

Version information

Matrix set from debian oficial repo.

ii  matrix-synapse                  0.33.7-1matrix1                all          Open federated Instant Messaging and VoIP server
ii  python-daemonize                2.3.1-0matrix1                 all          Library to enable your code run as a daemon process on Unix-
ii  python-frozendict               0.4-0matrix1                   all          An immutable dictionary
ii  python-phonenumbers             8.4.0~matrix~jessie1           all          Python port of Google libphonenumber
ii  python-pydenticon               0.2-0matrix1                   all          Library for generating identicons. Port of Sigil

$ curl -v https://matrix.org/_matrix/client/versions 2>&1 | grep "Server:"

Server: nginx/1.10.3
-->

  • Install method: package manager
  • Platform: OS version: Debian 9.5 in lxc-container
@neilisfragile
Copy link
Contributor

Hard to say what is causing this without more data on the contents of the http pokes from the client.

Are you using Riot?

We'll soon have official python 3 packages which should solve this problem for you. In the interim it is also possible to run synapse from source under a py3 virtualenv as per https://github.com/matrix-org/synapse#id11

@neilisfragile neilisfragile added the z-bug (Deprecated Label) label Oct 25, 2018
@progserega
Copy link
Author

Are you using Riot?

yes

We'll soon have official python 3 packages which should solve this problem for you. In the interim it is also possible to run synapse from source under a py3 virtualenv as per https://github.com/matrix-org/synapse#id11

Do it is already stable today for production use?

@progserega
Copy link
Author

Packages will be at week, moth or later? (I need to know this for understand my steps - wait or start from source.)

@progserega
Copy link
Author

server (py2.7) crash again at night:

    2018-10-27 03:59:55,124 - synapse.federation.transport.server - 130 - INFO - PUT-291664- Request from kyriasis.com
    2018-10-27 03:59:55,125 - synapse.federation.transport.server - 336 - INFO - PUT-291664- Received txn 1538665561206 from kyriasis.com. (PDUs: 0, EDUs: 1)
    2018-10-27 03:59:55,125 - synapse.util.async_helpers - 205 - INFO - PUT-291664- Acquired uncontended linearizer lock 'fed_txn_handler' for key (u'kyriasis.com', u'1538665561206')
    2018-10-27 03:59:56,206 - synapse.access.https.8448 - 233 - INFO - PUT-291665- 178.63.27.77 - 8448 - Received request: PUT /_matrix/federation/v1/send/1540534707964/
    2018-10-27 03:59:56,208 - synapse.federation.transport.server - 130 - INFO - PUT-291665- Request from t2bot.io
    2018-10-27 03:59:56,208 - synapse.federation.transport.server - 336 - INFO - PUT-291665- Received txn 1540534707964 from t2bot.io. (PDUs: 0, EDUs: 1)
    2018-10-27 03:59:56,208 - synapse.util.async_helpers - 205 - INFO - PUT-291665- Acquired uncontended linearizer lock 'fed_txn_handler' for key (u't2bot.io', u'1540534707964')
    2018-10-27 03:59:56,234 - synapse.access.http.8008 - 233 - INFO - POST-291666- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/read_markers
    2018-10-27 03:59:56,238 - synapse.metrics - 374 - INFO - - Collecting gc 0
    2018-10-27 03:59:56,945 - synapse.access.http.8008 - 233 - INFO - GET-291667- 127.0.0.1 - 8008 - Received request: GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3568-177694_0_0_0_0_0_0_0_0&dir=f&limit=30
    2018-10-27 03:59:56,952 - synapse.access.http.8008 - 302 - INFO - GET-291667- 127.0.0.1 - 8008 - {@petrov_km:rsprim.ru} Processed request: 0.006sec/0.002sec (0.001sec, 0.000sec) (0.000sec/0.001sec/1) 2791B 200 "GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3568-177694_0_0_0_0_0_0_0_0&di    __r=f&limit=30 HTTP/1.0" "Riot.im/0.8.18 (Linux; U; Android 8.0.0; SM-G930F Build/R16N; Flavour GooglePlay; MatrixAndroidSDK 0.9.12)" [0 dbevts] 
    2018-10-27 03:59:57,815 - synapse.access.http.8008 - 233 - INFO - GET-291668- 127.0.0.1 - 8008 - Received request: GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3598-178437_0_0_0_0_0_0_0_0&dir=f&limit=30
    2018-10-27 03:59:57,823 - synapse.access.http.8008 - 302 - INFO - GET-291668- 127.0.0.1 - 8008 - {@petrov_km:rsprim.ru} Processed request: 0.006sec/0.002sec (0.004sec, 0.000sec) (0.000sec/0.001sec/1) 2762B 200 "GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3598-178437_0_0_0_0_0_0_0_0&di    __r=f&limit=30 HTTP/1.0" "Riot.im/0.8.18 (Linux; U; Android 8.0.0; SM-G930F Build/R16N; Flavour GooglePlay; MatrixAndroidSDK 0.9.12)" [0 dbevts] 
    2018-10-27 03:59:58,544 - synapse.access.http.8008 - 233 - INFO - GET-291669- 127.0.0.1 - 8008 - Received request: GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3628-179315_0_0_0_0_0_0_0_0&dir=f&limit=30
    2018-10-27 03:59:58,550 - synapse.access.http.8008 - 302 - INFO - GET-291669- 127.0.0.1 - 8008 - {@petrov_km:rsprim.ru} Processed request: 0.005sec/0.001sec (0.002sec, 0.000sec) (0.000sec/0.001sec/1) 1619B 200 "GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3628-179315_0_0_0_0_0_0_0_0&di    __r=f&limit=30 HTTP/1.0" "Riot.im/0.8.18 (Linux; U; Android 8.0.0; SM-G930F Build/R16N; Flavour GooglePlay; MatrixAndroidSDK 0.9.12)" [0 dbevts] 
    2018-10-27 03:59:58,899 - synapse.access.http.8008 - 233 - INFO - GET-291670- 127.0.0.1 - 8008 - Received request: GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3641-179624_0_0_0_0_0_0_0_0&dir=f&limit=30
    2018-10-27 03:59:58,903 - synapse.access.http.8008 - 302 - INFO - GET-291670- 127.0.0.1 - 8008 - {@petrov_km:rsprim.ru} Processed request: 0.004sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.001sec/1) 67B 200 "GET /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/messages?from=t3641-179624_0_0_0_0_0_0_0_0&dir=    __f&limit=30 HTTP/1.0" "Riot.im/0.8.18 (Linux; U; Android 8.0.0; SM-G930F Build/R16N; Flavour GooglePlay; MatrixAndroidSDK 0.9.12)" [0 dbevts] 
    2018-10-27 03:59:59,044 - synapse.access.http.8008 - 233 - INFO - POST-291671- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/r0/rooms/!vAkzLFnCuXxlVYAWWz:rsprim.ru/read_markers
    2018-10-27 03:59:59,049 - synapse.metrics - 374 - INFO - - Collecting gc 0
    2018-10-27 03:59:59,314 - twisted - 243 - ERROR - POST-291666- Traceback (most recent call last):
    2018-10-27 03:59:59,315 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
    2018-10-27 03:59:59,315 - twisted - 243 - ERROR - POST-291666-     if self.shouldRollover(record):
    2018-10-27 03:59:59,316 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
    2018-10-27 03:59:59,316 - twisted - 243 - ERROR - POST-291666-     msg = "%s\n" % self.format(record)
    2018-10-27 03:59:59,316 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format
    2018-10-27 03:59:59,316 - twisted - 243 - ERROR - POST-291666-     return fmt.format(record)
    2018-10-27 03:59:59,317 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format
    2018-10-27 03:59:59,317 - twisted - 243 - ERROR - POST-291666-     raise e
    2018-10-27 03:59:59,317 - twisted - 243 - ERROR - POST-291666- UnicodeDecodeError: 'ascii' codec can't decode byte 0xd0 in position 48: ordinal not in range(128)
    2018-10-27 03:59:59,317 - twisted - 243 - ERROR - POST-291666- Logged from file _base.py, line 254 
    2018-10-27 03:59:59,318 - twisted - 243 - ERROR - POST-291666- Traceback (most recent call last):
    2018-10-27 03:59:59,318 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
    2018-10-27 03:59:59,318 - twisted - 243 - ERROR - POST-291666-     msg = self.format(record)
    2018-10-27 03:59:59,319 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/__init__.py", line 734, in format
    2018-10-27 03:59:59,319 - twisted - 243 - ERROR - POST-291666-     return fmt.format(record)
    2018-10-27 03:59:59,320 - twisted - 243 - ERROR - POST-291666-   File "/usr/lib/python2.7/logging/__init__.py", line 476, in format
    2018-10-27 03:59:59,329 - twisted - 243 - ERROR - POST-291671- Traceback (most recent call last):

It is very bad situation - service is very unstable :-(
I think this is critical bug.

@progserega
Copy link
Author

As I understand in log not contain full back trace for understand witch code insert utf8 in log function, which crashes after that?
How I can "enable more logging" for get more information for that? Maybe I must start matrix-server in foreground from console and python show full backtrace log to console?

@aaronraimist
Copy link
Contributor

aaronraimist commented Oct 27, 2018 •
edited
Loading

I also seem to be seeing the 'ascii' codec can't decode byte 0xe2 in position 52: ordinal not in range(128) but my server is not getting killed.

Note the black lines in the scrollbar (each one is an instance of that error) seems to be happening a lot more often recently. Doesn't seem related to updating to 0.33.7rc2 as it didn't start happening much until the 2018-10-23 16:48:57.

screen shot 2018-10-26 at 8 39 41 pm

@aaronraimist
Copy link
Contributor

This problem has occurred in the past here: #2356 and here #1814

@aaronraimist
Copy link
Contributor 

2018-10-26 16:53:54,313 - synapse.http.server - 112 - ERROR - GET-2967066- Failed handle request via <function ThumbnailResource._async_render_GET at 0x7fcfe64752f0>: <XForwardedForRequest at 0x7fcfa472a860 method='GET' uri='/_matrix/media/v1/thumbnail/half-shot.uk/a53f70059979b610338c4e9c9c1da607?width=36&height=36&method=crop' clientproto='HTTP/1.1' site=8008>: Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
--- <exception caught here> ---
  File "/usr/local/lib/python3.6/dist-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python3.6/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 83, in _async_render_GET
    width, height, method, m_type
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python3.6/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 236, in _respond_remote_thumbnail
    media_info = yield self.media_repo.get_remote_media_info(server_name, media_id)
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python3.6/dist-packages/synapse/rest/media/v1/media_repository.py", line 283, in get_remote_media_info
    server_name, media_id,
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python3.6/dist-packages/synapse/rest/media/v1/media_repository.py", line 333, in _get_remote_media_impl
    server_name, media_id, file_id
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/lib/python3.6/dist-packages/synapse/rest/media/v1/media_repository.py", line 406, in _download_remote_file
    _, params = cgi.parse_header(content_disposition[0].decode('ascii'),)
builtins.UnicodeDecodeError: 'ascii' codec can't decode byte 0xce in position 18: ordinal not in range(128)

@hawkowl was this introduced in 02aa418?

@richvdh
Copy link
Member

richvdh commented Oct 27, 2018

Let's not assume that all instances of this message have the same cause.

@progserega as you note part of the problem here is that it's hard to tell where the bad data is being logged. Running synapse in the foreground rather than via synctl, and setting the -n option (no redirect stdio), may give some clues.

@progserega
Copy link
Author

I start synapse in foreground in screen as:
/usr/bin/python -m "synapse.app.homeserver" -n --config-path /etc/matrix-synapse/homeserver.yaml --config-path /etc/matrix-synapse/conf.d/
When and if it break down - I append console log to this issue.
Thank you!

@richvdh
Copy link
Member

richvdh commented Nov 8, 2018

@progserega any progress here? It may well be that -n has fixed the infinite loop in the logs which was taking down your homeserver; however it won't have fixed the underlying problem. Are there any UnicodeDecodeError instances in any of your logs?

@progserega
Copy link
Author

Hmm!
Synapse, started in console - do not wont down :-)

But I found UnicodeDecodeError in logs:

    2018-11-08 16:04:54,450 - synapse.access.http.8008 - 233 - INFO - POST-2203550- 127.0.0.1 - 8008 - Received request: POST /_matrix/client/r0/publicised_groups?
    2018-11-08 16:04:54,453 - synapse.http.matrixfederationclient - 310 - INFO - POST-2203550- {POST-O-786522} [1312.media] Sending request: POST matrix://1312.media/_matrix/federation/v1/get_groups_publicised
    2018-11-08 16:04:54,457 - synapse.http.endpoint - 339 - INFO - POST-2203550- Connecting to lon1.1312.media:8448
    2018-11-08 16:04:55,083 - synapse.http.matrixfederationclient - 350 - WARNING - federation_transaction_transmission_loop-1077071- {PUT-O-786119} [emc.mattkeys.net] Request failed: PUT matrix://emc.mattkeys.net/_matrix/federation/v1/send/1540685555646/: TimeoutError('',)
    2018-11-08 16:04:55,094 - synapse.http.matrixfederationclient - 383 - INFO - GET-2203548- {GET-O-786521} [half-shot.uk] Got response headers: 200 OK 
    2018-11-08 16:04:55,095 - synapse.http.matrixfederationclient - 727 - INFO - GET-2203548- {GET-O-786521} [half-shot.uk] Completed: 200 OK [25069 bytes] 
    2018-11-08 16:04:55,096 - synapse.util.async_helpers - 218 - INFO - GET-2203548- Releasing linearizer lock 'media_remote' for key (u'half-shot.uk', u'a53f70059979b610338c4e9c9c1da607')
    2018-11-08 16:04:55,097 - synapse.http.server - 112 - ERROR - GET-2203548- Failed handle request via <function _async_render_GET at 0x7ff35fea7aa0>: <SynapseRequest at 0x7ff320a228c0 method=u'GET' uri=u'/_matrix/media/v1/thumbnail/half-shot.uk/a53f70059979b610338c4e9c9c1da607?width=12&height=12&method=crop' client    __proto=u'HTTP/1.0' site=8008>: Traceback (most recent call last):
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
        current.result = callback(current.result, *args, **kw)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
        _inlineCallbacks(r, g, deferred)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
    --- <exception caught here> ---
      File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 81, in wrapped_request_handler
        yield h(self, request)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 83, in _async_render_GET
        width, height, method, m_type 
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 236, in _respond_remote_thumbnail
        media_info = yield self.media_repo.get_remote_media_info(server_name, media_id)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 283, in get_remote_media_info
        server_name, media_id,
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 333, in _get_remote_media_impl
        server_name, media_id, file_id
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1386, in _inlineCallbacks
        result = g.send(result)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 406, in _download_remote_file
        _, params = cgi.parse_header(content_disposition[0].decode('ascii'),)
    exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xce in position 18: ordinal not in range(128)
    2018-11-08 16:04:55,099 - synapse.access.http.8008 - 302 - INFO - GET-2203548- 127.0.0.1 - 8008 - {None} Processed request: 0.883sec/0.001sec (0.010sec, 0.004sec) (0.000sec/0.001sec/1) 55B 500 "GET /_matrix/media/v1/thumbnail/half-shot.uk/a53f70059979b610338c4e9c9c1da607?width=12&height=12&method=crop HTTP/1.0" "M    __ozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/68.0.3440.106 Chrome/68.0.3440.106 Safari/537.36" [0 dbevts]
    2018-11-08 16:04:55,100 - synapse.metrics - 374 - INFO - - Collecting gc 0
    2018-11-08 16:04:55,201 - synapse.http.matrixfederationclient - 383 - INFO - POST-2203550- {POST-O-786522} [1312.media] Got response headers: 200 OK 
    2018-11-08 16:04:55,201 - synapse.http.matrixfederationclient - 170 - INFO - POST-2203550- {POST-O-786522} [1312.media] Completed: 200 OK 
    2018-11-08 16:04:55,204 - synapse.http.matrixfederationclient - 310 - INFO - POST-2203550- {POST-O-786523} [maunium.net] Sending request: POST matrix://maunium.net/_matrix/federation/v1/get_groups_publicised
    2018-11-08 16:04:55,547 - synapse.http.endpoint - 339 - INFO - - Connecting to maunium.net:8448
    2018-11-08 16:04:56,198 - synapse.access.http.8008 - 233 - INFO - GET-2203551- 127.0.0.1 - 8008 - Received request: GET /_matrix/client/r0/pushrules/

@progserega
Copy link
Author

And again in other log-file:

    2018-11-08 10:12:38,922 - synapse.http.matrixfederationclient - 383 - INFO - GET-2145252- {GET-O-760505} [half-shot.uk] Got response headers: 200 OK 
    2018-11-08 10:12:38,923 - synapse.http.matrixfederationclient - 727 - INFO - GET-2145252- {GET-O-760505} [half-shot.uk] Completed: 200 OK [25069 bytes] 
    2018-11-08 10:12:38,924 - synapse.util.async_helpers - 218 - INFO - GET-2145252- Releasing linearizer lock 'media_remote' for key (u'half-shot.uk', u'a53f70059979b610338c4e9c9c1da607')
    2018-11-08 10:12:38,925 - synapse.http.server - 112 - ERROR - GET-2145252- Failed handle request via <function _async_render_GET at 0x7ff35fea7aa0>: <SynapseRequest at 0x7ff308789128 method=u'GET' uri=u'/_matrix/media/v1/thumbnail/half-shot.uk/a53f70059979b610338c4e9c9c1da607?width=12&height=12&method=crop' client    __proto=u'HTTP/1.0' site=8008>: Traceback (most recent call last):
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
        current.result = callback(current.result, *args, **kw)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
        _inlineCallbacks(r, g, deferred)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
    --- <exception caught here> ---
      File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 81, in wrapped_request_handler
        yield h(self, request)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 83, in _async_render_GET
        width, height, method, m_type 
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/thumbnail_resource.py", line 236, in _respond_remote_thumbnail
        media_info = yield self.media_repo.get_remote_media_info(server_name, media_id)
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 283, in get_remote_media_info
        server_name, media_id,
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
        result = result.throwExceptionIntoGenerator(g)
      File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 333, in _get_remote_media_impl
        server_name, media_id, file_id
      File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1386, in _inlineCallbacks
        result = g.send(result)
      File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 406, in _download_remote_file
        _, params = cgi.parse_header(content_disposition[0].decode('ascii'),)
    exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xce in position 18: ordinal not in range(128)
    2018-11-08 10:12:38,927 - synapse.access.http.8008 - 302 - INFO - GET-2145252- 127.0.0.1 - 8008 - {None} Processed request: 1.628sec/0.001sec (0.008sec, 0.000sec) (0.000sec/0.000sec/1) 55B 500 "GET /_matrix/media/v1/thumbnail/half-shot.uk/a53f70059979b610338c4e9c9c1da607?width=12&height=12&method=crop HTTP/1.0" "M    __ozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/68.0.3440.106 Chrome/68.0.3440.106 Safari/537.36" [0 dbevts]

@progserega
Copy link
Author

progserega commented Nov 8, 2018 •
edited
Loading

And again one error with such num lines in backtrace (I do not past it here).

@richvdh
Copy link
Member

richvdh commented Nov 8, 2018

ok great, this sounds like #4160 which is already on our radar.

@richvdh
Copy link
Member

richvdh commented Nov 8, 2018

(though that doesn't really explain why your whole synapse was falling over)

@aaronraimist
Copy link
Contributor

aaronraimist commented Nov 8, 2018 •
edited
Loading

@richvdh I think he's saying the problem of it going down is fixed (or at least hasn't happened recently) so this issue can be closed in favor of the other one.

Synapse, started in console - do not wont down :-)

@richvdh
Copy link
Member

richvdh commented Nov 8, 2018

@aaronraimist yeah but the mystery of why it hangs when it is not run in a console remains.

@progserega
Copy link
Author

progserega commented Nov 11, 2018 •
edited
Loading

@richvdh I think he's saying the problem of it going down is fixed (or at least hasn't happened recently) so this issue can be closed in favor of the other one.

Synapse, started in console - do not wont down :-)

I sink it is not good solution. This is a hack.

@aaronraimist yeah but the mystery of why it hangs when it is not run in a console remains.

Can you tell me - why python not show full backtrace in log in first my message at this issue?

@richvdh
Copy link
Member

richvdh commented Nov 12, 2018

Can you tell me - why python not show full backtrace in log in first my message at this issue?

No, no idea.

@progserega
Copy link
Author

progserega commented Nov 26, 2018 •
edited
Loading

And again in other log-file:

    File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1386, in _inlineCallbacks
       result = g.send(result)
     File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 406, in _download_remote_file
       _, params = cgi.parse_header(content_disposition[0].decode('ascii'),)
   exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xce in position 18: ordinal not in range(128)

This bug is fixed now?

@richvdh
Copy link
Member

richvdh commented Nov 26, 2018 

     File "/usr/lib/python2.7/dist-packages/synapse/rest/media/v1/media_repository.py", line 406, in _download_remote_file
      _, params = cgi.parse_header(content_disposition[0].decode('ascii'),)
  exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xce in position 18: ordinal not in range(128)

This is #4160, which is fixed by #4176, which will be fixed in the next version of synapse.

@richvdh richvdh mentioned this issue Nov 29, 2018
Closed
@richvdh
Copy link
Member

richvdh commented Nov 29, 2018

Resolving in favour of #4240 which summarises the issue more succinctly

@richvdh richvdh closed this as completed Nov 29, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
z-bug (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@neilisfragile @progserega @richvdh @aaronraimist and others