Bitwarden keeps failing after a few minutes

Markfree · November 27, 2022, 3:57pm

I’ve installed bitwarden on a local host and recently it is just failing somehow.
When I try to access the web frontend, nginx fails with:

502 Bad Gateway

Checking Nginx logs, I see this route error:

2022/11/27 15:42:34 [error] 58#58: *297 connect() failed (113: No route to host) while connecting to upstream, client: 192.168.7.212, server: bitwarden.my.domain, request: "GET / HTTP/1.1", upstream: "http://172.22.0.2:5000/", host: "bitwarden.my.domain"
2022/11/27 15:42:41 [error] 56#56: *300 connect() failed (113: No route to host) while connecting to upstream, client: 192.168.7.3, server: bitwarden.my.domain, request: "GET / HTTP/2.0", upstream: "http://172.22.0.2:5000/", host: "bitwarden.my.domain"
2022/11/27 15:42:44 [error] 56#56: *300 connect() failed (113: No route to host) while connecting to upstream, client: 192.168.7.3, server: bitwarden.my.domain, request: "GET /favicon.ico HTTP/2.0", upstream: "http://172.22.0.2:5000/favicon.ico", host: "bitwarden.my.domain", referrer: "https://bitwarden.my.domain/"

When I check docker containers, I see they are all running.

$ docker ps
CONTAINER ID   IMAGE                               COMMAND            CREATED             STATUS                       PORTS                                                                                    NAMES
55fa3867bd23   bitwarden/nginx:2022.10.0           "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   80/tcp, 0.0.0.0:80->8080/tcp, :::80->8080/tcp, 0.0.0.0:443->8443/tcp, :::443->8443/tcp   bitwarden-nginx
3f404e0bb374   bitwarden/admin:2022.10.0           "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-admin
b44ebfcf7a1d   bitwarden/icons:2022.10.0           "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-icons
fe2984cfc098   bitwarden/api:2022.10.0             "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-api
43b05ff38fc8   bitwarden/events:2022.10.0          "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-events
da5a5c24961b   bitwarden/identity:2022.10.0        "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-identity
2851b5c3bb7a   bitwarden/web:2022.10.0             "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)                                                                                            bitwarden-web
dcd7294b8be7   bitwarden/sso:2022.10.0             "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-sso
1b1857280da0   bitwarden/mssql:2022.10.0           "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)                                                                                            bitwarden-mssql
50eb3629219e   bitwarden/notifications:2022.10.0   "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)   5000/tcp                                                                                 bitwarden-notifications
79b5487ac99e   bitwarden/attachments:2022.10.0     "/entrypoint.sh"   About an hour ago   Up About an hour (healthy)                                                                                            bitwarden-attachments

Usually, restarting Bitwarden resolves the issue, but only for a few minutes.
I’m not sure what’s going on.
Any idea?

dh024 · November 27, 2022, 7:24pm

I am not sure if this is related, but is see two different server IPs in your nginx logs:

192.168.7.212, which points to http traffic

and

192.168.7.3, which points to https traffic

Markfree · November 27, 2022, 8:08pm

Thanks for your comment, @dh024 .
The 7.212 client is just a “Dashy” dashboard checking for Bitwarden’s frontend. It uses http for that and usually gets a http 401 code.

The second client, 7.3, was my pc trying to open Bitwarden’s frontend.

dh024 · November 27, 2022, 8:15pm

OK, understood. So no http traffic is forwarded to the Bitwarden instance then. Gotcha.

Given that your ‘Dashy’ dashboard is showing failed in the logs, it seems to confirm that the problem is with your nginx reverse proxy setup, and your Bitwarden server instance is probably running just fine. I am an Apache user, so I can’t really provide any concrete advice here, I am so sorry. I hope someone else with experience with nginx can help you out. Cheers.

Markfree · November 29, 2022, 1:25pm

Today I had a sudden CPU load spike with Bitwarden.
The VM’s host showed a high CPU usage from Bitwarden’s processes, but I forgot to print that.

I was unable to access the VM console due to its high CPU load. So, I had to shutdown the VM and reboot it.

Looking at the logs, I could only find errors from MSSQL about a failed backup.

$ tail -n 12 bwdata/logs/mssql/errorlog.1
2022-11-27 15:55:59.83 spid52      Starting up database 'bitwarden'.
2022-11-27 15:55:59.88 spid52      Parallel redo is started for database 'bitwarden' with worker pool size [4].
2022-11-27 15:55:59.91 spid52      Parallel redo is shutdown for database 'bitwarden' with worker pool size [4].
2022-11-28 00:00:00.12 Backup      Error: 3041, Severity: 16, State: 1.
2022-11-28 00:00:00.12 Backup      BACKUP failed to complete the command BACKUP DATABASE vault. Check the backup application log for detailed messages.
2022-11-29 00:00:00.21 Backup      Error: 3041, Severity: 16, State: 1.
2022-11-29 00:00:00.21 Backup      BACKUP failed to complete the command BACKUP DATABASE vault. Check the backup application log for detailed messages.
2022-11-29 12:52:49.37 spid8s      Always On: The availability replica manager is going offline because SQL Server is shutting down. This is an informational message only. No user action is required.
2022-11-29 12:52:49.41 spid8s      SQL Server is terminating in response to a 'stop' request from Service Control Manager. This is an informational message only. No user action is required.
2022-11-29 12:52:49.53 spid24s     Service Broker manager has shut down.
2022-11-29 12:52:49.54 spid8s      .NET Framework runtime has been stopped.
2022-11-29 12:52:49.64 spid8s      SQL Trace was stopped due to server shutdown. Trace ID = '1'. This is an informational message only; no user action is required.

Also, SSO logs display some errors which seem to relate to MS DB.

2022-11-29 12:41:36.820 +00:00 [Error] An unhandled exception has occurred while executing the request.
System.Data.SqlClient.SqlException (0x80131904): A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was
not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: TCP Provider, err
or: 35 - An internal exception was caught)
 ---> System.Net.Internals.SocketExceptionFactory+ExtendedSocketException (00000001, 11): Resource temporarily unavailable
   at System.Net.Dns.GetHostEntryOrAddressesCore(String hostName, Boolean justAddresses, AddressFamily addressFamily, ValueStopwatch stopwatch)
   at System.Net.Dns.GetHostAddresses(String hostNameOrAddress, AddressFamily family)
   at System.Data.SqlClient.SNI.SNITCPHandle.Connect(String serverName, Int32 port, TimeSpan timeout)
   at System.Data.SqlClient.SNI.SNITCPHandle..ctor(String serverName, Int32 port, Int64 timerExpire, Object callbackObject, Boolean parallel)
   at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object
 providerInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSe
ssionData, Boolean applyTransientFaultHandling, String accessToken)
   at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectio
nPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnection
PoolKey poolKey, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOn
eCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionPool.WaitForPendingOpen()
--- End of stack trace from previous location ---
   at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 417
   at Bit.Infrastructure.Dapper.Repositories.SsoConfigRepository.GetManyByRevisionNotBeforeDate(Nullable`1 notBefore) in /home/runner/work/server/server/src/Infrastr
ucture.Dapper/Repositories/SsoConfigRepository.cs:line 57
   at Bit.Core.Business.Sso.DynamicAuthenticationSchemeProvider.LoadAllDynamicSchemesIntoCacheAsync() in /home/runner/work/server/server/bitwarden_license/src/Sso/Ut
ilities/DynamicAuthenticationSchemeProvider.cs:line 152
   at Bit.Core.Business.Sso.DynamicAuthenticationSchemeProvider.GetRequestHandlerSchemesAsync() in /home/runner/work/server/server/bitwarden_license/src/Sso/Utilitie
s/DynamicAuthenticationSchemeProvider.cs:line 132
   at Bit.Sso.Utilities.SsoAuthenticationMiddleware.Invoke(HttpContext context) in /home/runner/work/server/server/bitwarden_license/src/Sso/Utilities/SsoAuthenticationMiddleware.cs:line 36
   at IdentityServer4.Hosting.BaseUrlMiddleware.Invoke(HttpContext context)
   at Bit.Core.Utilities.CurrentContextMiddleware.Invoke(HttpContext httpContext, ICurrentContext currentContext, GlobalSettings globalSettings) in /home/runner/work/server/server/src/Core/Utilities/CurrentContextMiddleware.cs:line 20
   at Microsoft.AspNetCore.Localization.RequestLocalizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
ClientConnectionId:00000000-0000-0000-0000-000000000000

Markfree · December 18, 2022, 2:42pm

I’m having lots of CPU spikes with BitWarden. These are mostly caused by “dockerd” and “containerd” high CPU usage.
With that, I’m constantly losing connection with the VM.
Even a simple “dnf update” is failing.

We can see the high CPU usage in Proxmox dashboard.

My guess is that MSSQL container is the cause of all this issue since it seems to be the most demanding one.
But “docker stats” is not working properly at all.

The only thing that temporally solves the issue is rebooting the VM.

Any tips on how to diagnose that?

dh024 · December 18, 2022, 3:38pm

Have you checked the SQL Server logs? There should be some clues in there if it is the culprit.

Markfree · December 19, 2022, 8:17pm

Besides from the previous logs I posted above, what I could find so far is that most MSSQL “errorlog” files are very short and seem to indicate a frequent restart.
Every “errolog.xx” only shows the DBMS start up.

Right in the log’s beginning, I can see the following error (4th line). Then, it goes on with a normal DB start-up.

$ cat bwdata/logs/mssql/errorlog
2022-12-18 16:18:42.82 spid10s     Starting up database 'master'.
2022-12-18 16:18:42.84 Server      CLR version v4.0.30319 loaded.
2022-12-18 16:18:43.06 spid10s     Service Master Key could not be decrypted using one of its encryptions. See sys.key_encryptions for details.
2022-12-18 16:18:43.06 spid10s     An error occurred during Service Master Key initialization. SQLErrorCode=33095, State=8, LastOsError=0.
2022-12-18 16:18:43.09 spid10s     SQL Server Audit is starting the audits. This is an informational message. No user action is required.
2022-12-18 16:18:43.09 spid10s     SQL Server Audit has started the audits. This is an informational message. No user action is required.
2022-12-18 16:18:43.18 spid10s     SQL Trace ID 1 was started by login "sa".
(...)
2022-12-18 16:18:43.24 spid12s     Starting up database 'mssqlsystemresource'.
2022-12-18 16:18:43.26 spid10s     Starting up database 'msdb'.
(...)

And stops right after starting the “bitwarden” DB.

2022-12-18 16:19:05.02 spid52      Starting up database 'bitwarden'.
2022-12-18 16:19:05.07 spid52      Parallel redo is started for database 'bitwarden' with worker pool size [4].
2022-12-18 16:19:05.10 spid52      Parallel redo is shutdown for database 'bitwarden' with worker pool size [4].

Waiting a few hours, I could find the following error message in the latest errorlog.

2022-12-19 00:00:00.22 Backup      Error: 3041, Severity: 16, State: 1.
2022-12-19 00:00:00.22 Backup      BACKUP failed to complete the command BACKUP DATABASE vault. Check the backup application log for detailed messages.

The message points to a “backup application log” which I could not find.

Checking “core.sqlservr” directories, I could find some crash logs and system dumps. The latest is the following.

$ cat bwdata/logs/mssql/core.sqlservr.12_18_2022_13_29_10.40.d/crash.txt
This program has encountered a fatal error and cannot continue running at Sun Dec 18 13:28:44 2022
The following diagnostic information is available:

         Reason: 0x00000004
        Message: RETAIL ASSERT: Expression=(!"A timeout or deadlock was encountered while waiting" " for a thread to terminate/suspend/resume.") File=NtumWaiter.cpp Line=702
    Stack Trace:
                 file://package4/windows/system32/sqlpal.dll+0x000000000000E16F
                 file://package4/windows/system32/sqlpal.dll+0x000000000000CEF3
                 file://package4/windows/system32/sqlpal.dll+0x0000000000013F3B
                 file://package4/windows/system32/sqlpal.dll+0x00000000000A271E
                 file://package4/windows/system32/sqlpal.dll+0x000000000006B929
                 file://package4/windows/system32/sqlpal.dll+0x000000000005D621
                 file://package4/windows/system32/sqlpal.dll+0x000000000005D19C
                 file://package4/windows/system32/sqlpal.dll+0x0000000000057EEF
                 file://package4/windows/system32/sqlpal.dll+0x00000000000678B5
                 file://package4/windows/system32/sqlpal.dll+0x00000000000677B7
                 file://package4/windows/system32/sqlpal.dll+0x0000000000066596
                 file://package4/windows/system32/sqlpal.dll+0x000000000006665B
                 file://package4/windows/system32/sqlpal.dll+0x0000000000003D1F
                 file://package4/windows/system32/sqlpal.dll+0x0000000000202398
                 file:///windows/system32/ntdll.dll+0x0000000000026F20
                 file:///Windows/SYSTEM32/KERNEL32.DLL+0x0000000000014414
                 file:///windows/system32/ntdll.dll+0x0000000000075541
        Modules:
                 file://package4/windows/system32/sqlpal.dll=2783696C75EB41553CC5480CD7503AC51
                 file:///windows/system32/ntdll.dll=45137AA3F9814512B3123991067EEE6E2
                 file:///Windows/SYSTEM32/KERNEL32.DLL=C715300FB2664729A6126A3F591E6F302
        Process: 40 - sqlservr
         Thread: 84 (application thread 0xb0)
    Instance Id: 4192c1b7-b52c-4fce-b426-4054ca863554
       Crash Id: f52d18bd-76d0-466c-8f81-1a0412d7bf9f
    Build stamp: e5dea205d0938e2848fb2509856a7e8f30783e6d5f62d0c88355e288de0db89a
   Distribution: Ubuntu 20.04.4 LTS
     Processors: 12
   Total Memory: 33519669248 bytes
      Timestamp: Sun Dec 18 13:28:44 2022
     Last errno: 2
Last errno text: No such file or directory

BTW, I’m using Oracle Linux 9.1

dh024 · December 19, 2022, 8:52pm

Try these logs - they may provide some additional information that is more helpful:

docker logs bitwarden-mssql 

docker exec -it bitwarden-mssql cat /var/opt/mssql/log/errorlog