element-hq / element-hq/synapse

Login failed, leaving an suspicious-looking device entry littered around with no last_seen or IP metadata

Open
#6,316 0 comments 0 reactions 0 assignees View on GitHub
A-Login O-Uncommon S-Minor T-Defect
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.