JSONDecodeError causes 500's while initial syncing or leaving room

[Cadair]

Description

When trying to initial sync a clean device, or when trying to leave the room in question (HQ) I get a 500 error. I get what looks to be this everytime:

2019-10-14 15:23:51,140 - synapse.http.server - 109 - ERROR - POST-65085 - Failed handle request via 'RoomMembershipRestServlet': <XForwardedForRequest at 0x7fce967a4050 method='POST' uri='/_matrix/client/r0/rooms/!QtykxKocfZaZOUrTwp%3Amatrix.org/leave' clientproto='HTTP/1.0' site=8008>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'$1568139640328aHhmJ:200acres.org': {'event_id': '$1568139640328aHhmJ:200acres.org', 'internal_metadata': '{"outlier": false, "soft_failed": true, "stream_ordering": 2553997}', 'json': '{"auth_events": [["$1564954903473544gXBNd:matrix.org", {"sha256": "DJ+cruN2sWXFbpmv5h9Vtd+PtLDcww5pVvVrMzfgnbo"}], ["$152873010877837iaE
ate": [], "redacts": "$15687419811091673hBcYn:matrix.org", "room_id": "!QtykxKocfZaZOUrTwp:matrix.org", "sender": "@risc-j508:matrix.org", "type": "m.room.redaction", "signatures": {"matrix.org": {"ed25519:auto": "wPBUJuabMbJ5kZ5hh5RldAo4a+msvj3U2e4zWPUSWlm5DHwuOHzEE4bBDPYxzHazLYORAoocf3trrTWqvYdoDA"}}, "unsigned": {"age_ts": 1568742008
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/http/server.py", line 77, in wrapped_request_handler
    await h(self, request)
  File "/usr/local/lib/python3.7/site-packages/synapse/http/server.py", line 326, in _async_render
    callback_return = await callback_return
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
... [truncated] ...
  File "/usr/local/lib/python3.7/site-packages/synapse/storage/events_worker.py", line 512, in _get_events_from_db
    d = json.loads(row["json"])
  File "/usr/local/lib/python3.7/site-packages/simplejson/__init__.py", line 518, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.7/site-packages/simplejson/decoder.py", line 370, in decode
    obj, end = self.raw_decode(s)
  File "/usr/local/lib/python3.7/site-packages/simplejson/decoder.py", line 400, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

(Full traceback here: https://gist.github.com/Cadair/130ce1e704f2761415bdde17ef8d8482)

Version information

• Homeserver: cadair.com

• Version: 1.4.0

• Install method: docker

• Platform: debian 9 host, postgres 9.6, docker for everything else

[richvdh]

I wonder if this is the thing that got fixed by #6185/#6186.

Can you show us a SELECT json from event_json where event_id='$15687419811091673hBcYn:matrix.org'?

[Cadair]

Here it is in all it's glory:

homeserver=# SELECT json from event_json where event_id='$15687419811091673hBcYn:matrix.org';
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                json                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 {"auth_events":[["$152873010877837iaEeS:matrix.org",{"sha256":"FadaICEbPU11CFeC8NlvANHQdkviLqR7R3dgLQ7tElE"}],["$152873067778016gOxgX:matrix.org",{"sha256":"6QyXfF6kZQqD69jwk86IW4PVTaTw8fN7rebtTPK8E2k"}],["$156710140811KQJyx:sw1v.org",{"sha256":"oaSn85MM9ViNfH6bRgr2rksRg+B43QasmfpGIdXxb0I"}]],"content":{"membership":"join"},"depth":172121,"event_id":"$15687419811091673hBcYn:matrix.org","hashes":{"sha256":"xvHoQlmHzJYMzEZfaICScd40at5ciPHb3rB3bKvisXA"},"origin":"matrix.org","origin_server_ts":1568741981409,"prev_events":[["$15687401151085258TeyvI:matrix.org",{"sha256":"Awd00/HYc25xTDWwy4oq2zMoxIbfWkoHu/YI4tQgHmA"}]],"prev_state":[],"room_id":"!QtykxKocfZaZOUrTwp:matrix.org","sender":"@risc-j508:matrix.org","signatures":{"matrix.org":{"ed25519:auto":"zwoPV0fSxMpyiGb5mWg2QvQMc5baKssEr49c1UGC5mYXjkXTVtq0As6ud2dog5axZIS0K4xhjJt1xFZOpcq8Bg"}},"state_key":"@risc-j508:matrix.org","type":"m.room.member","unsigned":{"age_ts":1568741981409,"replaces_state":"$156779401432679GPhAt:matrix.org"}}

[richvdh]

Hrm, can't see anything wrong there, but I'm still wondering if it's the same problem as that fixed in #6185/#6186.

Perhaps you could try develop to see if #6186 fixes it?

[Cadair]

I upgraded to develop, and then ended up back on 1.4.0 (because of a VM issue) and it seems to have resolved itself. Presumably due to the database changes?

[richvdh]

makes sense. the issue might come up again though.

[z3ntu]

I experienced a similar problem, I couldn't log in to my account on my homeserver because of a jsondecodeerror. After inspecting the database I found 846 events in the event_json table which had binary data instead of json in the json column.

The only special thing I did was migrating from sqlite to postgres after upgrading to v1.5.0. I've checked the old sqlite database and it had no non-plain-text json columns (SELECT COUNT(*) FROM event_json WHERE json NOT LIKE '{"%';). I'm checking right now if there are any malformed rows in the database after running the synapse_port_db script on an empty postgres database again, I'll update this post.

I've solved the problem for now by removing the offending rows from the db (DELETE FROM event_json WHERE json NOT LIKE '{"%';).

edit: I've ran the migration script again as written above and some 846 jsons are not valid jsons again.

Example row after migration (from postgres):

                   event_id                   |            room_id             |               internal_metadata               |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         json                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | format_version
----------------------------------------------+--------------------------------+-----------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------
 $nI883CoDUnZJaVR_QzESO1VcJwwuzfOiCHQ3JarALO8 | !oQwMqrnmCGzlXfiYnF:matrix.org | {"outlier": false, "stream_ordering": 261345} | \x7b22617574685f6576656e7473223a5b2224523361793251696471314871764943704557786255334b4e2d367a30425365585545515031734d374a3877222c22246967424774365233777051646b794b33564f4e564f6e6f6b6d586f525f73674f496f797a2d526366324c38222c22245f6f346d7542704b3436756c51726953546f37716772704652506e744c6d5868426f6b6e65434a386d5773225d2c22636f6e74656e74223a7b7d2c226465707468223a313332362c22686173686573223a7b22736861323536223a22442f614f2b667159706b30685544564a563934676e335a7946774a704e5944757866654577314856307877227d2c226f726967696e223a226d61747269782e6f7267222c226f726967696e5f7365727665725f7473223a313537323139323536373632372c22707265765f6576656e7473223a5b22246d2d727252486b46416979334a3144454d3844664a625a506a3854693048614a5f6368527a67467154506f225d2c22707265765f7374617465223a5b5d2c22726f6f6d5f6964223a22216f51774d71726e6d43477a6c586669596e463a6d61747269782e6f7267222c2273656e646572223a22406172616c3a6d61747269782e6f7267222c227369676e617475726573223a7b226d61747269782e6f7267223a7b22656432353531393a6175746f223a2275557165416f4143382f78346e724e79726755524b4f4b6c3873475a624c667a4f767762425873704a4972424f6a784d6648374d4f4248684a672b75314b747a4371476d4d555750494f6e486238315a307737724241227d7d2c2274797065223a226d2e726f6f6d2e6d657373616765222c22756e7369676e6564223a7b226167655f7473223a313537323139323536373632377d7d |              3

Row before migration (from sqlite):

$nI883CoDUnZJaVR_QzESO1VcJwwuzfOiCHQ3JarALO8|!oQwMqrnmCGzlXfiYnF:matrix.org|{"outlier": false, "stream_ordering": 261345}|{"auth_events":["$R3ay2Qidq1HqvICpEWxbU3KN-6z0BSeXUEQP1sM7J8w","$igBGt6R3wpQdkyK3VONVOnokmXoR_sgOIoyz-Rcf2L8","$_o4muBpK46ulQriSTo7qgrpFRPntLmXhBokneCJ8mWs"],"content":{},"depth":1326,"hashes":{"sha256":"D/aO+fqYpk0hUDVJV94gn3ZyFwJpNYDuxfeEw1HV0xw"},"origin":"matrix.org","origin_server_ts":1572192567627,"prev_events":["$m-rrRHkFAiy3J1DEM8DfJbZPj8Ti0HaJ_chRzgFqTPo"],"prev_state":[],"room_id":"!oQwMqrnmCGzlXfiYnF:matrix.org","sender":"@aral:matrix.org","signatures":{"matrix.org":{"ed25519:auto":"uUqeAoAC8/x4nrNyrgURKOKl8sGZbLfzOvwbBXspJIrBOjxMfH7MOBHhJg+u1KtzCqGmMUWPIOnHb81Z0w7rBA"}},"type":"m.room.message","unsigned":{"age_ts":1572192567627}}|3

[tailtwo]

Same problem here. Some users reported being unable to login. Deleting the offending rows solved the problem.

postgres=# \c synapse 
You are now connected to database "synapse" as user "postgres".
synapse=# DELETE FROM event_json WHERE json NOT LIKE '{"%';
DELETE 144

[z3ntu]

@richvdh Can this issue be re-opened or should a new one be created?

[richvdh]

actually @z3ntu I'm going to redirect you to #5312. @Cadair had similar symptoms but a different cause.