element-hq / element-hq/synapse
Login failed, leaving an suspicious-looking device entry littered around with no last_seen or IP metadata
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
This issue has been migrated from [#6316](https://github.com/matrix-org/synapse/issues/6316).
---
I just tried to log in on riot.im/develop in a new browser.
a) it failed with an M_UNKNOWN error.
b) this left a device with ID XHAPHXFIMF around in my devices lists, but with no entry in user_ips, which then looks suspicious as it's listed as a device with no details about creation time or last_seen etc:
```
matrix=> select * from matrix.devices where device_id='XHAPHXFIMF';
user_id | device_id | display_name | last_seen | ip | user_agent | hidden
---------------------+------------+-----------------------------------------------+-----------+----+------------+--------
@matthew:matrix.org | XHAPHXFIMF | https://riot.im/develop/ via Chrome on Mac OS | | | | f
```
The request which created the 'bad' device was:
```
momus:/home/synapse/var$ tail -1000000 homeserver.log | grep POST-21768600
2019-11-02 17:38:19,653 - synapse.access.http.9092 - 233 - INFO - POST-21768600 - ::ffff:10.101.0.5 - 9092 - Received request: POST /_synapse/replication/device_check_registered/%40matthew%3Amatrix.org/DWSMQfIHgJ
2019-11-02 17:38:19,653 - synapse.util.caches.response_cache - 148 - INFO - POST-21768600 - [repl.device_check_registered]: no cached result for [DWSMQfIHgJ], calculating new one
2019-11-02 17:39:19,671 - synapse.http.site - 203 - WARNING - POST-21768600 - Error processing request : Connection to the other side was lost in a non-clean fashion.
2019-11-02 17:39:27,983 - synapse.handlers.device - 428 - DEBUG - POST-21768600 - Notifying about update '@matthew:matrix.org'/'XHAPHXFIMF', ID: 18286090
2019-11-02 17:39:27,987 - synapse.handlers.device - 437 - INFO - POST-21768600 - Sending device list update notif for '@matthew:matrix.org' to: { ridiculous list of homeservers }
2019-11-02 17:39:28,640 - synapse.handlers.auth - 468 - INFO - POST-21768600 - Logging in user @matthew:matrix.org on device XHAPHXFIMF
2019-11-02 17:39:29,101 - synapse.http.server - 458 - WARNING - POST-21768600 - Not sending response to request , already disconnected.
2019-11-02 17:39:29,101 - synapse.access.http.9092 - 302 - INFO - POST-21768600 - ::ffff:10.101.0.5 - 9092 - {None} Processed request: 69.448sec/-9.430sec (1.600sec, 0.436sec) (7.170sec/27.251sec/2035) 0B 200! "POST /_synapse/replication/device_check_registered/%40matthew%3Amatrix.org/DWSMQfIHgJ HTTP/1.1" "Synapse/1.5.0rc2 (b=matrix-org-hotfixes,33b4aa8d9)" [0 dbevts]
```
N.B. that this is the synapse master processing a "device_check_registered" request which apparently took more than a minute (69s) to execute, which was enough for the original request on the login worker to give up.
```
kratos:/home/synapse/var$ tail -n4000000 client_reader2.log | grep POST-8752600
2019-11-02 17:38:19,397 - synapse.access.http.8090 - 233 - INFO - POST-8752600 - 213.181.114.173 - 8090 - Received request: POST /_matrix/client/r0/login
2019-11-02 17:38:19,398 - synapse.rest.client.v1.login - 176 - INFO - POST-8752600 - Got login request with identifier: {'type': 'm.id.user', 'user': 'matthew'}, medium: None, address: None, user: None
2019-11-02 17:38:19,652 - synapse.http.client - 271 - INFO - POST-8752600- - Sending request POST http://10.101.0.6:9092/_synapse/replication/device_check_registered/%40matthew%3Amatrix.org/DWSMQfIHgJ
2019-11-02 17:39:19,654 - synapse.http.client - 318 - INFO - POST-8752600-- - Error sending request to POST http://10.101.0.6:9092/_synapse/replication/device_check_registered/%40matthew%3Amatrix.org/DWSMQfIHgJ: ResponseNeverReceived []
2019-11-02 17:39:19,657 - synapse.http.server - 109 - ERROR - POST-8752600 - Failed handle request via 'LoginRestServlet':
2019-11-02 17:39:19,671 - synapse.access.http.8090 - 302 - INFO - POST-8752600 - 213.181.114.173 - 8090 - {None} Processed request: 60.272sec/0.002sec (0.236sec, 0.004sec) (0.001sec/0.002sec/1) 55B 500 "POST /_matrix/client/r0/login HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36" [0 dbevts]
```
So:
1. why did /device_check_registered take over a minute to execute on the master?
2. can we avoid leaving suspicious-looking devices around when this happens?
Contributor guide
Assessment
This issue has not been assessed yet.