Accounts plugin leaks existence of accounts

[glasserc]

In this example, ethan is a real user.

> time http --auth ethan:test 'localhost:8888/v1/buckets?expected="123"'
HTTP/1.1 200 OK
Access-Control-Expose-Headers: Last-Modified, Total-Records, ETag, Retry-After, Backoff, Next-Page, Alert, Pragma, Cache-Control, Expires, Content-Length
Cache-Control: no-cache, no-store
Content-Length: 11
Content-Type: application/json
Date: Wed, 17 Oct 2018 02:54:57 GMT
Etag: "1539744794645"
Last-Modified: Wed, 17 Oct 2018 02:53:14 GMT
Server: waitress
Total-Records: 0
X-Content-Type-Options: nosniff

{
    "data": []
}

0.25user 0.03system 0:00.93elapsed 31%CPU (0avgtext+0avgdata 35812maxresident)k
0inputs+8outputs (0major+11538minor)pagefaults 0swaps

Elapsed: almost a second.

> time http --auth test:test 'localhost:8888/v1/buckets?expected="123"'
HTTP/1.1 200 OK
Access-Control-Expose-Headers: Last-Modified, Total-Records, ETag, Retry-After, Backoff, Next-Page, Alert, Pragma, Cache-Control, Expires, Content-Length
Cache-Control: no-cache, no-store
Content-Length: 11
Content-Type: application/json
Date: Wed, 17 Oct 2018 02:55:03 GMT
Etag: "1539744794645"
Last-Modified: Wed, 17 Oct 2018 02:53:14 GMT
Server: waitress
Total-Records: 0
X-Content-Type-Options: nosniff

{
    "data": []
}

0.24user 0.04system 0:00.29elapsed 98%CPU (0avgtext+0avgdata 35820maxresident)k
0inputs+8outputs (0major+11498minor)pagefaults 0swaps

Elapsed: 0.3 seconds.

[leplatrem]

We have to figure out what is going on during this 1 second. It's far too much for a couple of DB lookups.

[leplatrem]

How long does it take if given password is wrong for ethan?

[glasserc]

The 1 second was when the password was wrong. If it's right, it drops a little bit:

> time http --auth ethan:trustno1 'localhost:8888/v1/buckets?expected="123"'
HTTP/1.1 200 OK
Access-Control-Expose-Headers: Last-Modified, Total-Records, ETag, Retry-After, Backoff, Next-Page, Alert, Pragma, Cache-Control, Expires, Content-Length
Cache-Control: no-cache, no-store
Content-Length: 11
Content-Type: application/json
Date: Wed, 17 Oct 2018 16:13:47 GMT
Etag: "1539792827723"
Last-Modified: Wed, 17 Oct 2018 16:13:47 GMT
Server: waitress
Total-Records: 0
X-Content-Type-Options: nosniff

{
    "data": []
}

0.34user 0.09system 0:00.58elapsed 75%CPU (0avgtext+0avgdata 35792maxresident)k
46040inputs+8outputs (113major+11486minor)pagefaults 0swaps

Elapsed: 0.58s.

[slav0nic]

Normal request profiling stack

Slow with wrong password

so, as i understand bcrypt.checkpw called 2 times, bcrypt slow by design, but second call looks strange (in error view)

as i see, internally successfully logins cached in kinto: https://github.com/Kinto/kinto/blob/9acb793a84f9ca72625b2c6cb24bbaccad7c4975/kinto/plugins/accounts/authentication.py#L50-L52

but on every access to request.effective_principals -> request.authenticated_userid -> bcrypt call

here is how problem like this solved in pyramid2 tutorial via per-request cache: https://github.com/Pylons/pyramid/blob/683bc742f7b08db563f3385796809c09babf004b/docs/tutorials/wiki2/src/authorization/tutorial/security.py#L31-L34

[leplatrem]

Thanks for the investigation!

We also have a sort a request cache in kinto (request.bound_data) that could solve this.

(Slightly related to #621)