keys/query fails with a 500 if there is non-ascii in the database

[richvdh]

Looks like we're failing to unpack the funny escaping that postgres/psycopg gives us:

2018-11-28 17:35:46,329 - synapse.access.http.8008 - 233 - INFO - POST-80- 10.5.67.143 - 8008 - Received request: POST /_matrix/client/unstable/keys/query
2018-11-28 17:35:46,334 - synapse.storage.txn - 234 - DEBUG - POST-80- [TXN START] {get_e2e_device_keys-162}
2018-11-28 17:35:46,404 - synapse.storage.txn - 290 - DEBUG - POST-80- [TXN END] {get_e2e_device_keys-162} 0.069703 sec
2018-11-28 17:35:46,405 - root - 1247 - WARNING - POST-80- Tried to decode 'u'\\x7b...<redacted>...7d'' as JSON and failed
2018-11-28 17:35:46,408 - synapse.http.server - 112 - ERROR - POST-80- Failed handle request via <function _async_render at 0x7facbeb55c80>: <SynapseRequest at 0x7facb0742d88 method=u'POST' uri=u'/_matrix/client/unstable/keys/query' clientproto=u'HTTP/1.1' site=8008>: Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python2.7/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/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/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python2.7/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python2.7/dist-packages/synapse/http/server.py", line 316, in _async_render
    callback_return = yield callback(request, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python2.7/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python2.7/dist-packages/synapse/rest/client/v2_alpha/keys.py", line 149, in on_POST
    result = yield self.e2e_keys_handler.query_devices(body, timeout)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python2.7/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python2.7/dist-packages/synapse/handlers/e2e_keys.py", line 86, in query_devices
    local_result = yield self.query_local_devices(local_query)
  File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/local/lib/python2.7/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/local/lib/python2.7/dist-packages/synapse/handlers/e2e_keys.py", line 181, in query_local_devices
    results = yield self.store.get_e2e_device_keys(local_query)
  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/storage/end_to_end_keys.py", line 96, in get_e2e_device_keys
    device_info["keys"] = db_to_json(device_info.pop("key_json"))
  File "/usr/local/lib/python2.7/dist-packages/synapse/storage/_base.py", line 1245, in db_to_json
    return json.loads(db_content)
  File "/usr/local/lib/python2.7/dist-packages/simplejson/__init__.py", line 518, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python2.7/dist-packages/simplejson/decoder.py", line 370, in decode
    obj, end = self.raw_decode(s)
  File "/usr/local/lib/python2.7/dist-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)

The redacted string, once you remove the \x-escaping, is a valid-looking JSON key string containing only characters < 0x7f, so I don't really know where the escaping is coming from. Perhaps it's in the database like that? Have asked the user for more info.

This was on 0.33.9, on python 2.7.

[richvdh]

db query gives:

select * from e2e_device_keys_json where user_id='...' and device_id='MTQEGKIYGU';   
           user_id           | device_id  |  ts_added_ms  | key_json 
-----------------------------+------------+---------------+-----------------------------
 @...                        | MTQEGKIYGU | 1539156284505 | \x7b22...7d
(1 row)

so I think that means that it's in the database with the weird escaping?

[hawkowl]

We set it to:

        # Set the bytea output to escape, vs the default of hex
        cursor = db_conn.cursor()
        cursor.execute("SET bytea_output TO escape")

[andreaspeters]

I delete the wired item but it didn't had a impact to my federation bug issue: #4239

[richvdh]

I think this got fixed in #4164. Related: #4475.