search

bitwarden / server

Bitwarden infrastructure/backend (API, database, Docker, etc).
https://bitwarden.com
Other
15.69k stars 1.32k forks source link

Visiting admin page shows 502 Bad Gateway nginx #3635

Closed mitchellvanbijleveld closed 10 months ago

mitchellvanbijleveld commented 10 months ago

Steps To Reproduce

Upgrading the Bitwarden installation from the December beta release to the beta release of the 2nd of January, 2024.

Expected Result

The browser shows Bitwarden's admin page to put in an email address to get a login link.

Actual Result

The browser shows: 502 Bad Gateway nginx

Screenshots or Videos

No response

Additional Context

nginx shows errors, something like

connect() failed (111: Connection refused) while connecting to upstream, client:

Also, data/bitwarden/logs/admin.log shows:

2024-01-02 21:20:00.189 +00:00 [INF] Starting job DeleteSendsJob at "2024-01-02T21:20:00.1889573Z".
2024-01-02 21:20:01.980 +00:00 [INF] Migrating database.
2024-01-02 21:20:02.242 +00:00 [ERR] Failed executing DbCommand (3ms) [Parameters=[], CommandType='"Text"', CommandTimeout='30']
CALL POMELO_BEFORE_DROP_PRIMARY_KEY(NULL, 'Grant');
ALTER TABLE `Grant` DROP PRIMARY KEY;

Githash Version

919d759f-dirty

Environment Details

Running Debian 12, AMD64. This is nginx's config file:

server {
    listen 443 ssl http2; # managed by Certbot
    listen [::]:443 ssl http2; # managed by Certbot

    server_name <url>;

    ssl_certificate /etc/letsencrypt/live/<url>/fullchain.pem; # managed by Certbot
    ssl_certificate_key /etc/letsencrypt/live/<url>/privkey.pem; # managed by Certbot
    include /etc/letsencrypt/options-ssl-nginx.conf; # managed by Certbot
    ssl_dhparam /etc/letsencrypt/ssl-dhparams.pem; # managed by Certbot

    add_header Strict-Transport-Security "max-age=31536000" always; # managed by Certbot

    ssl_trusted_certificate /etc/letsencrypt/live/<url>/chain.pem; # managed by Certbot
    ssl_stapling on; # managed by Certbot
    ssl_stapling_verify on; # managed by Certbot

    location / {
        proxy_pass http://localhost:8080;
        proxy_set_header Host $host;
    }

}

server {
    if ($host = <url>) {
        return 301 https://$host$request_uri;
    } # managed by Certbot

    listen 80 ;
    listen [::]:80 ;

    server_name <url>;
}

Database Image

docker-compose.yml:

version: "3.8"

services:
  bitwarden:
    depends_on:
      - db
    env_file:
      - /XXX.env
    image: bitwarden/self-host:beta
    restart: always
    ports:
      - "8080:8080"
    volumes:
      - /XXX:/etc/bitwarden

  db:
    environment:
      MARIADB_USER: "<HIDDEN>"
      MARIADB_PASSWORD: "<HIDDEN>"
      MARIADB_DATABASE: "<HIDDEN>"
      MARIADB_RANDOM_ROOT_PASSWORD: "true"
    image: mariadb:10
    restart: always
    volumes:
      - /XXX:/var/lib/mysql

Issue-Link

https://github.com/bitwarden/server/issues/2480

Issue Tracking Info

juanmanuelbc commented 10 months ago

More or less the same here.

Just updated my unified self-host container and this is what I get in the logs: imatge

Any help will be apreciated.

Thank you...

karolszklarski commented 10 months ago

gitHash cf4d8a4 is working, ea162d5 is not

That commit modifies GrantRepository, and logs say something about 'grant' table

Duplicate: https://github.com/bitwarden/server/issues/3637

karolszklarski commented 10 months ago

Working older version (11 days ago): docker image pull bitwarden/self-host@sha256:495424ccf31ca2ce0dca4b96774531efbc49ab595600d004694a78a31170bc2c

Krychaz commented 10 months ago

Hi there,

Thank you for your report!

I was able to reproduce this issue, and I have flagged this to our engineering team.

If you wish to add any further information/screenshots/recordings etc., please feel free to do so at any time - our engineering team will be happy to review these.

Thanks once again!

DuckThom commented 10 months ago

As I've just upgraded my Bitwarden install from 2023.12.0 to 2024.1.0, I too ran into this issue. However, I've done some digging around and added some findings to this issue: https://github.com/bitwarden/server/issues/3651#issuecomment-1885849819

To summarize, what I could see was that ALTER TABLEGrantADD CONSTRAINTPK_GrantPRIMARY KEY (Id); is actually the migration that's failing due to the existing data. The error Can't DROP INDEXPRIMARY; check that it exists is a side-effect because of the system attempting to re-run migrations that have already altered the database.

I do like to point out though that I am running MySQL 8.0.35 and the platform is ARM64, so this issue does not appear to be specific to MariaDB nor AMD64.

I did find a way to somewhat work around the issue which involved some manual queries but I managed to get the Bitwarden instance running again

(Warning for anyone attempting this manual "fix": these commands are destructive and can cause data loss if you're not careful. Make sure you know what you are doing!)

  1. Create a backup of your database Very important
  2. Stop bitwarden process
  3. Log into the DB: mysql -u root -p bitwarden_vault
  4. Check the state of the Grant table: show create table `Grant`;. There should not be a PRIMARY KEY and there should be an Id column.
  5. Remove Id with alter table `Grant` drop column Id;
  6. Re-add PRIMARY KEY: alter table `Grant` add constraint PK_Grant_Id PRIMARY KEY (`Key`); (Note: I made the assumption that Key was the original PK, not 100% sure but it's just to make the migration dropping the PK not fail)
  7. Exit mysql
  8. Create dump of table: mysqldump --no-create-info --complete-insert -u root -p bitwarden_vault Grant > grant.sql. Make sure to not lose this file, you'll need it later on!
  9. Log into the DB: mysql -u root -p bitwarden_vault
  10. Truncate table: TRUNCATE `Grant`; (DESTRUCTIVE)
  11. Exit mysql
  12. Start bitwarden
  13. Check admin.log output, ie. docker compose exec bitwarden tail -f /var/log/bitwarden/admin.log
  14. Ensure it logs: Application is shutting down... and Application started. Press Ctrl+C to shut down. shortly after.
  15. Stop bitwarden process
  16. Import dump made in step 7: mysql -u root -p bitwarden_vault < grant.sql
  17. Exit mysql
  18. Start bitwarden process
withinfocus commented 10 months ago

@mitchellvanbijleveld can you pull the latest from main and give this a try? We made a modification to the database migration.

mitchellvanbijleveld commented 10 months ago

@withinfocus I am sorry to have you ask, but pulling from main? I might be confused but the Docker self-host image is only available as dev/beta, right? I tried the dev which was updated like 15 minutes ago but that one isn't working.

The docker compose logs shows a lot of MariaDB related connection errors:

bitwarden-db-1  | 2024-01-11 21:33:58 126 [Warning] Aborted connection 126 to db: 'unconnected' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
bitwarden-db-1  | 2024-01-11 21:34:23 132 [Warning] Aborted connection 132 to db: 'BWUSER' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
bitwarden-db-1  | 2024-01-11 21:34:23 130 [Warning] Aborted connection 130 to db: 'unconnected' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
bitwarden-db-1  | 2024-01-11 21:34:47 136 [Warning] Aborted connection 136 to db: 'BWUSER' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
bitwarden-db-1  | 2024-01-11 21:34:47 134 [Warning] Aborted connection 134 to db: 'unconnected' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
bitwarden-db-1  | 2024-01-11 21:35:12 139 [Warning] Aborted connection 139 to db: 'BWUSER' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
bitwarden-db-1  | 2024-01-11 21:35:12 138 [Warning] Aborted connection 138 to db: 'unconnected' user: 'BWUSER' host: '172.21.0.3' (Got an error reading communication packets)
mitchellvanbijleveld commented 10 months ago

@withinfocus the admin logs show the following:

fail: Microsoft.EntityFrameworkCore.Database.Command[20102]
      Failed executing DbCommand (4ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      CALL POMELO_BEFORE_DROP_PRIMARY_KEY(NULL, 'Grant');
      ALTER TABLE `Grant` DROP PRIMARY KEY;
Unhandled exception. MySqlConnector.MySqlException (0x80004005): Can't DROP INDEX `PRIMARY`; check that it exists
   at MySqlConnector.Core.ResultSet.ReadResultSetHeaderAsync(IOBehavior ioBehavior) in /_/src/MySqlConnector/Core/ResultSet.cs:line 43
   at MySqlConnector.MySqlDataReader.ActivateResultSet(CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlDataReader.cs:line 130
   at MySqlConnector.MySqlDataReader.CreateAsync(CommandListPosition commandListPosition, ICommandPayloadCreator payloadCreator, IDictionary`2 cachedProcedures, IMySqlCommand command, CommandBehavior behavior, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlDataReader.cs:line 468
   at MySqlConnector.Core.CommandExecutor.ExecuteReaderAsync(IReadOnlyList`1 commands, ICommandPayloadCreator payloadCreator, CommandBehavior behavior, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/CommandExecutor.cs:line 56
   at MySqlConnector.MySqlCommand.ExecuteNonQueryAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlCommand.cs:line 296
   at MySqlConnector.MySqlCommand.ExecuteNonQuery() in /_/src/MySqlConnector/MySqlCommand.cs:line 107
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteNonQuery(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Migrations.MigrationCommand.ExecuteNonQuery(IRelationalConnection connection, IReadOnlyDictionary`2 parameterValues)
   at Microsoft.EntityFrameworkCore.Migrations.Internal.MigrationCommandExecutor.ExecuteNonQuery(IEnumerable`1 migrationCommands, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Migrations.Internal.Migrator.Migrate(String targetMigration)
   at Microsoft.EntityFrameworkCore.RelationalDatabaseFacadeExtensions.Migrate(DatabaseFacade databaseFacade)
   at Bit.MySqlMigrations.MySqlDbMigrator.MigrateDatabase(Boolean enableLogging, CancellationToken cancellationToken) in /source/util/MySqlMigrations/MySqlDbMigrator.cs:line 30
   at Bit.Admin.HostedServices.DatabaseMigrationHostedService.StartAsync(CancellationToken cancellationToken) in /source/src/Admin/HostedServices/DatabaseMigrationHostedService.cs:line 29
   at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.Run(IHost host)
   at Bit.Admin.Program.Main(String[] args) in /source/src/Admin/Program.cs:line 9
mitchellvanbijleveld commented 10 months ago

And here is another example of docker compose logs:

bitwarden-bitwarden-1  | 2024-01-11 21:41:54,225 INFO spawned: 'admin' with pid 486
bitwarden-bitwarden-1  | 2024-01-11 21:42:09,244 INFO success: admin entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
bitwarden-bitwarden-1  | 2024-01-11 21:42:17,969 INFO exited: admin (terminated by SIGABRT (core dumped); not expected)
bitwarden-bitwarden-1  | 2024-01-11 21:42:18,972 INFO spawned: 'admin' with pid 507
bitwarden-bitwarden-1  | 2024-01-11 21:42:33,990 INFO success: admin entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
bitwarden-bitwarden-1  | 2024-01-11 21:42:42,636 INFO exited: admin (terminated by SIGABRT (core dumped); not expected)
bitwarden-bitwarden-1  | 2024-01-11 21:42:43,638 INFO spawned: 'admin' with pid 527
bitwarden-bitwarden-1  | 2024-01-11 21:42:58,657 INFO success: admin entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
bitwarden-bitwarden-1  | 2024-01-11 21:43:07,314 INFO exited: admin (terminated by SIGABRT (core dumped); not expected)
bitwarden-bitwarden-1  | 2024-01-11 21:43:08,316 INFO spawned: 'admin' with pid 550
withinfocus commented 10 months ago

You don't seem to have the latest is all -- I was referring to code merges in this repo, specifically commit db4d7aa60932d867b5c18a42ac3ca567a68dca32.

Nicolaj-H commented 10 months ago

Having the same issue with self-host:beta and self-host:2024.1.0-beta, so tried pulling the self-host:dev that have been updated 11 hours ago and the issue is still there.

for now i reverted back to running self-host:2023.12.0-beta

admin.log:

  Failed executing DbCommand (3ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      INSERT INTO "ef_temp_Grant" ("Id", "ClientId", "ConsumedDate", "CreationDate", "Data", "Description", "ExpirationDate", "Key", "SessionId", "SubjectId", "Type")
      SELECT "Id", IFNULL("ClientId", ''), "ConsumedDate", "CreationDate", IFNULL("Data", ''), "Description", "ExpirationDate", "Key", "SessionId", "SubjectId", IFNULL("Type", '')
      FROM "Grant";
Unhandled exception. Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 19: 'UNIQUE constraint failed: ef_temp_Grant.Id'.
   at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
   at Microsoft.Data.Sqlite.SqliteDataReader.NextResult()
   at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader()
   at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteNonQuery(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Migrations.MigrationCommand.ExecuteNonQuery(IRelationalConnection connection, IReadOnlyDictionary`2 parameterValues)
   at Microsoft.EntityFrameworkCore.Migrations.Internal.MigrationCommandExecutor.ExecuteNonQuery(IEnumerable`1 migrationCommands, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Migrations.Internal.Migrator.Migrate(String targetMigration)
   at Microsoft.EntityFrameworkCore.RelationalDatabaseFacadeExtensions.Migrate(DatabaseFacade databaseFacade)
   at Bit.SqliteMigrations.SqliteDbMigrator.MigrateDatabase(Boolean enableLogging, CancellationToken cancellationToken) in /source/util/SqliteMigrations/SqliteDbMigrator.cs:line 30
   at Bit.Admin.HostedServices.DatabaseMigrationHostedService.StartAsync(CancellationToken cancellationToken) in /source/src/Admin/HostedServices/DatabaseMigrationHostedService.cs:line 29
   at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.Run(IHost host)
   at Bit.Admin.Program.Main(String[] args) in /source/src/Admin/Program.cs:line 9
juanmanuelbc commented 10 months ago

for now i reverted back to running self-host:2023.12.0-beta

Yes, this is the same one I'm using too until testing each new version with positive results...

Nicolaj-H commented 10 months ago

This seems to be fixed with commit "PM-5519] PM-5526 PM-5600 More Grant SQL fixes"

I'm running self-host:beta again, version number says 2024.1.2

juanmanuelbc commented 10 months ago

This seems to be fixed with commit "PM-5519](https://bitwarden.atlassian.net/browse/PM-5519?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ) PM-5526 PM-5624 PM-5600 More Grant SQL fixes"

Yes, it's working again!!!

I'm running self-host:beta again, version number says 2024.1.2

I'm running self-host:beta too, but my version number says 2024.1.1...

mitchellvanbijleveld commented 10 months ago

Great! Let me check this afternoon :).

karolszklarski commented 10 months ago

self-host:beta 2024.1.2 dca8d00f-dirty still gives me the same error

withinfocus commented 10 months ago

You wouldn't get the same error as the MySQL migration changed. It now runs what you can see at https://github.com/bitwarden/server/blob/main/util/MySqlMigrations/Migrations/20231214162533_GrantIdWithIndexes.cs#L75-L90 that will delete and re-add the new Id column. You won't see those same Pomelo errors that caused the initial issue.