create-account not working when password longer then 72 bytes

DynamicOperationsArchitect commented 1 year ago

Background information

Dendrite version or git SHA: 0.12.0 and 0.11.1
SQLite3 or Postgres?: Postgres
Running in Docker?: no
go version: 1.19
Client used (if applicable): n/a

Description

What is the problem: create-account does not function. The script runs, asks for a password, says "Created account" but the account does not get created.
Who is affected: The admin
How is this bug manifesting: When running create-account on the command line.
When did this first appear: Last time I successfully created a user was on 0.10.0. Somewhere on the way to 0.11.1 it stopped working.

Steps to reproduce

execute './bin/create-account -config ./dendrite.yaml -username new-user'
check the Postgres tables userapi_profiles and userapi_accounts

Console output

Create Account:

./bin/create-account -config ./dendrite.yaml -username new-user
Enter Password: 
Confirm Password: 
INFO[0009] Created account: new-user (AccessToken: RemovedForSecurityReasons)

Check Postgres tables:

dendrite=# select * from userapi_profiles WHERE localpart = 'new-user';
 localpart | display_name | avatar_url | server_name 
-----------+--------------+------------+-------------
(0 rows)

dendrite=# select localpart,created_ts from userapi_accounts WHERE localpart = 'new-user';
 localpart | created_ts 
-----------+------------
(0 rows)

S7evinK commented 1 year ago

Do you have any other servers running, e.g. Synapse, listening on http://localhost:8008? If so, you may need to add the -url parameter to connect to Dendrite listening on a different port.

DynamicOperationsArchitect commented 1 year ago

This server is used exclusively for Dendrite, even the database runs on another server. Running 'ss -tulpen' shows me that on 127.0.0.1:8008 Dendrite is listening. On the primary IP of the server, stunnel listens on port 8008 (I can change that if needed). I tried '-url http://localhost:8008' but encounter the same problem.

S7evinK commented 1 year ago

create-account is tested in CI, so wondering why it would pass but not really create the account. Which version did you upgrade from, so I can manually test/verify what is happening?

DynamicOperationsArchitect commented 1 year ago

This server was set up with 0.9.9 and has had every release of Dendrite since. Most recently, I successfully created a user with create-account under 0.10.0. I noticed that create-account does not work under 0.11.1 and 0.12.0.

SLS-Dan commented 1 year ago

I can confirm this behavior. I've been trying to get a fresh install working all day. I've tried with docker and then eventually switched to native postgres and native dendrite. create-account claims to do its job but the login fails. If I enable open registration and attempt to create a user via Element the logs get spammed with these errors constantly while Element hangs: ERRO[2023-03-24T09:14:12.828835174Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=QCV9N6UuXgdF req.method=PUT req.path="/_matrix/client/r0/presence/@userredacted/status" ERRO[2023-03-24T09:14:12.913363885Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=UJRE1jd8tFfO req.method=PUT req.path="/_matrix/client/r0/presence/@userredacted/status" ERRO[2023-03-24T09:14:13.198222289Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=bHientISEUKg req.method=PUT req.path="/_matrix/client/r0/presence/@useredacted/status" ERRO[2023-03-24T09:14:14.451518807Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=JAOKAV1YI28S req.method=GET req.path=/_matrix/client/r0/pushrules/ ERRO[2023-03-24T09:14:20.113400206Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=8V9UMPPRaLqA req.method=GET req.path=/_matrix/client/r0/pushrules/ ERRO[2023-03-24T09:14:27.133161402Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=DpCVI0jIh7AL req.method=GET req.path=/_matrix/client/r0/pushrules/ ERRO[2023-03-24T09:14:31.151961753Z] userAPI.QueryAccessToken failed error="sql: no rows in result set" req.id=DM8r5dSNtTRE req.method=GET req.path=/_matrix/client/r0/pushrules/

mispp commented 1 year ago

Same here. I dont even get anything in the log. LXD container used only for dendrite, running also postgres.

[dendrite@dendrite dendrite]$ ./bin/create-account --config /opt/dendrite/config/dendrite.yaml --username myuser -admin -url http://localhost:8008
Enter Password:
Confirm Password:
FATA[0032] Failed to create the account: unable to create account: Post "http://localhost:8008/_synapse/admin/v1/register": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

[dendrite@dendrite dendrite]$
logout

[root@dendrite logs]# tail dendrite.log
time="2023-04-02T13:31:09.151740917Z" level=debug msg="Setting DB connection limits" func=github.com/matrix-org/dendrite/internal/sqlutil.Open file="/home/dendrite/dendrite/internal/sqlutil/sqlutil.go:45" conn_max_lifetime=-1s data_source_name="postgresql://localhost/dendrite?sslmode=disable" max_idle_conns=5 max_open_conns=90
time="2023-04-02T13:31:09.178033084Z" level=info msg="Enabling shared secret registration at /_synapse/admin/v1/register" func=github.com/matrix-org/dendrite/clientapi/routing.Setup file="/home/dendrite/dendrite/clientapi/routing/routing.go:131"
time="2023-04-02T13:31:09.178588514Z" level=info msg="Enabling server notices at /_synapse/admin/v1/send_server_notice" func=github.com/matrix-org/dendrite/clientapi/routing.Setup file="/home/dendrite/dendrite/clientapi/routing/routing.go:200"
time="2023-04-02T13:31:09.185519877Z" level=debug msg="Setting DB connection limits" func=github.com/matrix-org/dendrite/internal/sqlutil.Open file="/home/dendrite/dendrite/internal/sqlutil/sqlutil.go:45" conn_max_lifetime=-1s data_source_name="postgresql://localhost/dendrite?sslmode=disable" max_idle_conns=5 max_open_conns=90
time="2023-04-02T13:31:09.194538426Z" level=debug msg="Setting DB connection limits" func=github.com/matrix-org/dendrite/internal/sqlutil.Open file="/home/dendrite/dendrite/internal/sqlutil/sqlutil.go:45" conn_max_lifetime=-1s data_source_name="postgresql://localhost/dendrite?sslmode=disable" max_idle_conns=5 max_open_conns=90
time="2023-04-02T13:31:09.229100856Z" level=info msg="Starting external listener on :8008" func=github.com/matrix-org/dendrite/setup/base.SetupAndServeHTTP.func4 file="/home/dendrite/dendrite/setup/base/base.go:194"
time="2023-04-02T13:31:09.229167329Z" level=info msg="Starting external listener on :8448" func=github.com/matrix-org/dendrite/setup/base.SetupAndServeHTTP.func4 file="/home/dendrite/dendrite/setup/base/base.go:194"
time="2023-04-02T13:32:09.134897981Z" level=info msg="Cleaning expired EDUs" func=github.com/matrix-org/dendrite/federationapi.NewInternalAPI.func1 file="/home/dendrite/dendrite/federationapi/federationapi.go:174"
time="2023-04-02T13:32:09.176850874Z" level=info msg="Cleaning old notifications" func=github.com/matrix-org/dendrite/userapi.NewInternalAPI.func2 file="/home/dendrite/dendrite/userapi/userapi.go:142"
time="2023-04-02T13:36:09.150385142Z" level=info msg="Executing UpdateUserDailyVisits" func="github.com/matrix-org/dendrite/userapi/storage/postgres.(*statsStatements).startTimers.func1" file="/home/dendrite/dendrite/userapi/storage/postgres/stats_table.go:238"

S7evinK commented 1 year ago

Unfortunately can't reproduce any of this. Neither with Postgres nor with SQLite.

> go run ../../cmd/create-account/main.go -config dendrite.yaml -username alice2 -admin -url http://localhost:8008
Enter Password: 
Confirm Password: 
INFO[0004] Created account: alice2 (AccessToken: abc) 

> go run ../../cmd/create-account/main.go -config dendrite.yaml -username alice-2 -admin -url http://localhost:8008
Enter Password: 
Confirm Password: 
INFO[0005] Created account: alice-2 (AccessToken: def)

Both accounts are in userapi_accounts. CI is also happy (also for Postgres and SQLite) https://github.com/matrix-org/dendrite/actions/runs/4572991247/jobs/8072956887#step:5:1325 (account creation using create-account) https://github.com/matrix-org/dendrite/actions/runs/4572991247/jobs/8072956887#step:5:1413 (corresponding log line from Dendrite)

@mispp: Do you have a high value set for user_api.bcrypt_cost? If so, you may need to specify the -timeout parameter, as this currently defaults to 30s and that may be too short for a high bcrypt cost.

DynamicOperationsArchitect commented 1 year ago

@S7evinK I have now also gone the way via go run as a test. The user is not created with it either. You create an admin account and I do not. Can it be related to this?

mispp commented 1 year ago

@S7evinK yes, i increased the bcrypt_cost to 20. probably this is the cause. thanks!

DynamicOperationsArchitect commented 1 year ago

@S7evinK From the HTTP point of view the registration of a new user seems to work as expected. Here is what tcpdump captured while trying to register a new user with create-account:

GET /_synapse/admin/v1/register HTTP/1.1
Host: localhost:8008
User-Agent: Go-http-client/1.1
Accept-Encoding: gzip

HTTP/1.1 200 OK
Access-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept, Authorization
Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS
Access-Control-Allow-Origin: *
Content-Type: application/json
Date: Fri, 05 May 2023 08:40:33 GMT
Content-Length: 28

{"nonce":"--removed--"}

POST /_synapse/admin/v1/register HTTP/1.1
Host: localhost:8008
User-Agent: Go-http-client/1.1
Content-Length: 262
Accept-Encoding: gzip

{"username":"test123","password":"--removed--","nonce":"--removed--","mac":"--removed--","admin":false}

HTTP/1.1 200 OK
Access-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept, Authorization
Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS
Access-Control-Allow-Origin: *
Content-Type: application/json
Date: Fri, 05 May 2023 08:40:33 GMT
Content-Length: 150

{"user_id":"@test123:matrix.techn1k.de","access_token":"--removed--","device_id":"shared_secret_registration"}

DynamicOperationsArchitect commented 1 year ago

@S7evinK Looks like the password length might be a problem here. With up to 72 chars create-account works as expected. 73 or more chars are causing the mentioned issue. I can reproduce this on my instance. Currently running 0.12.0+0489d16f

S7evinK commented 1 year ago

@DynamicOperationsArchitect thanks for investigating. :) Turns out that bcrypt doesn't allow for passwords longer than 72 bytes. :/ This currently results in an unexpected error in our code. (the account already exists, while in reality it doesn't, returning a wrong error to clients) I've made the point to maybe switch to argon2 at some point, we'll discuss this in our next meeting.

DynamicOperationsArchitect commented 1 year ago

@S7evinK I think in the meantime its helpful to let create-account fail in case the password is longer then 72 bytes.

dymk commented 1 year ago

I was running into the same issue - setting bcrypt_cost to a lower value fixed the issue for me.

matrix-org / dendrite