Unhandled exception (notifications.log) on container stopping

[ghost]

Steps To Reproduce

1. Start the container: docker compose up --detach
2. Wait till everything is up and running
3. Stop the container: docker compose down or docker stop bitwarden

Expected Result

No unhandled exceptions

Actual Result

::::::::::::::
/var/log/bitwarden/notifications.log
::::::::::::::
info: Microsoft.Hosting.Lifetime[0]
Application is shutting down...
warn: Bit.Notifications.AzureQueueHostedService[0]
Stopping service.
Unhandled exception. System.AggregateException: One or more hosted services failed to stop. (The operation was canceled.)
---> System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at Bit.Notifications.HeartbeatHostedService.StopAsync(CancellationToken cancellationToken) in /source/src/Notifications/HeartbeatHostedService.cs:line 41
at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
--- End of inner exception stack trace ---
at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.WaitForShutdownAsync(IHost host, CancellationToken token)
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.Notifications.Program.Main(String[] args) in /source/src/Notifications/Program.cs:line 10

Screenshots or Videos

No response

Additional Context

The output of docker logs bitwarden shows that the notifications service get terminated by SIGABRT:

2023-01-21 16:11:12,442 WARN received SIGTERM indicating exit request
2023-01-21 16:11:12,443 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-21 16:11:15,473 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-21 16:11:18,478 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-21 16:11:22,128 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-21 16:11:23,129 INFO stopped: notifications (terminated by SIGABRT (core dumped))
2023-01-21 16:11:23,139 INFO stopped: nginx (exit status 0)
2023-01-21 16:11:24,205 INFO stopped: icons (exit status 0)
2023-01-21 16:11:25,208 INFO waiting for identity, admin, api to die
2023-01-21 16:11:26,389 INFO stopped: api (exit status 0)
2023-01-21 16:11:27,502 INFO stopped: admin (exit status 0)
2023-01-21 16:11:28,602 INFO stopped: identity (exit status 0)

Githash Version

76ed711-dirty

Environment Details

• Raspberry Pi 4 (8 GB)
• Raspberry Pi OS (64-bit, bullseye)
• Docker Engine 20.10.23
• Docker Compose 2.15.1

Database Image

sqlite:3

Issue-Link

#2480

Issue Tracking Info

• I understand that work is tracked outside of Github. A PR will be linked to this issue should one be opened to address it, but Bitwarden doesn't use fields like "assigned", "milestone", or "project" to track progress.

[kspearrin]

Hmm. I am not sure why AzureQueueHostedService is even running. That shouldn't be use don self host instances.

[ghost]

Can I help troubleshoot, or can you reproduce the issue?

[kspearrin]

I found the issue that explains the unexpected error message. It is actually coming from the HeartbeatHostedService, which is using the wrong logger and showing them as AzureQueueHostedService. That is not what is causing your issues with notifications crashing, though.

We need to find more logs for notifications service. Are there any more errors in the /etc/bitwarden/logs/notifications.log that would tell us something interesting? You could also look in /var/log/bitwarden/notifications.log

[ghost]

I recreated the container with the latest dev-build.
All logs i got from start till stop...

/var/log/bitwarden/notifications.log:

warn: Microsoft.AspNetCore.DataProtection.Repositories.EphemeralXmlRepository[50]
Using an in-memory repository. Keys will not be persisted to storage.
warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[59]
Neither user profile nor HKLM registry available. Using an ephemeral key repository. Protected data will be unavailable when application exits.
warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[35]
No XML encryptor configured. Key {ba36a9dc-c5de-4725-b56d-cf036186c8b7} may be persisted to storage in unencrypted form.
info: Microsoft.Hosting.Lifetime[14]
Now listening on: http://0.0.0.0:5006
info: Microsoft.Hosting.Lifetime[0]
Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
Content root path: /app/Notifications
info: Microsoft.Hosting.Lifetime[0]
Application is shutting down...
warn: Bit.Notifications.HeartbeatHostedService[0]
Stopping service.
Unhandled exception. System.AggregateException: One or more hosted services failed to stop. (The operation was canceled.)
---> System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at Bit.Notifications.HeartbeatHostedService.StopAsync(CancellationToken cancellationToken) in /source/src/Notifications/HeartbeatHostedService.cs:line 41
at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
--- End of inner exception stack trace ---
at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.WaitForShutdownAsync(IHost host, CancellationToken token)
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.Notifications.Program.Main(String[] args) in /source/src/Notifications/Program.cs:line 10

/etc/bitwarden/logs/notifications.log:

2023-01-31 16:20:06.730 +01:00 [WRN] Using an in-memory repository. Keys will not be persisted to storage.
2023-01-31 16:20:06.900 +01:00 [WRN] Neither user profile nor HKLM registry available. Using an ephemeral key repository. Protected data will be unavailable
when application exits.
2023-01-31 16:20:07.111 +01:00 [WRN] No XML encryptor configured. Key {ba36a9dc-c5de-4725-b56d-cf036186c8b7} may be persisted to storage in unencrypted form.
2023-01-31 16:20:55.434 +01:00 [WRN] Stopping service.

docker logs Bitwarden:

Adding group bitwarden' (GID 1000) ... Done. Adding user bitwarden' ...
Adding new user bitwarden' (1000) with group bitwarden' ...
Not creating home directory `/home/bitwarden'.
Generating a RSA private key
.......................................++++
...................................................++++
writing new private key to '/etc/bitwarden/identity.key'

2023-01-31 16:20:03,352 INFO Included extra file "/etc/supervisor.d/admin.ini" during parsing
2023-01-31 16:20:03,353 INFO Included extra file "/etc/supervisor.d/api.ini" during parsing
2023-01-31 16:20:03,353 INFO Included extra file "/etc/supervisor.d/events.ini" during parsing
2023-01-31 16:20:03,353 INFO Included extra file "/etc/supervisor.d/icons.ini" during parsing
2023-01-31 16:20:03,354 INFO Included extra file "/etc/supervisor.d/identity.ini" during parsing
2023-01-31 16:20:03,354 INFO Included extra file "/etc/supervisor.d/nginx.ini" during parsing
2023-01-31 16:20:03,354 INFO Included extra file "/etc/supervisor.d/notifications.ini" during parsing
2023-01-31 16:20:03,355 INFO Included extra file "/etc/supervisor.d/scim.ini" during parsing
2023-01-31 16:20:03,355 INFO Included extra file "/etc/supervisor.d/sso.ini" during parsing
2023-01-31 16:20:03,365 INFO RPC interface 'supervisor' initialized
2023-01-31 16:20:03,365 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2023-01-31 16:20:03,366 INFO supervisord started with pid 1
2023-01-31 16:20:04,371 INFO spawned: 'identity' with pid 72
2023-01-31 16:20:04,376 INFO spawned: 'admin' with pid 73
2023-01-31 16:20:04,380 INFO spawned: 'api' with pid 74
2023-01-31 16:20:04,386 INFO spawned: 'icons' with pid 75
2023-01-31 16:20:04,392 INFO spawned: 'nginx' with pid 76
2023-01-31 16:20:04,397 INFO spawned: 'notifications' with pid 77
2023-01-31 16:20:19,841 INFO success: identity entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
2023-01-31 16:20:19,842 INFO success: admin entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
2023-01-31 16:20:19,843 INFO success: api entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
2023-01-31 16:20:19,844 INFO success: icons entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
2023-01-31 16:20:19,845 INFO success: nginx entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
2023-01-31 16:20:19,847 INFO success: notifications entered RUNNING state, process has stayed up for > than 15 seconds (startsecs)
2023-01-31 16:20:53,374 WARN received SIGTERM indicating exit request
2023-01-31 16:20:53,375 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-31 16:20:56,437 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-31 16:20:59,442 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-31 16:21:03,004 INFO waiting for identity, admin, api, icons, nginx, notifications to die
2023-01-31 16:21:04,007 INFO stopped: notifications (terminated by SIGABRT (core dumped))
2023-01-31 16:21:04,014 INFO stopped: nginx (exit status 0)
2023-01-31 16:21:05,074 INFO stopped: icons (exit status 0)
2023-01-31 16:21:06,077 INFO waiting for identity, admin, api to die
2023-01-31 16:21:07,218 INFO stopped: api (exit status 0)
2023-01-31 16:21:08,357 INFO stopped: admin (exit status 0)
2023-01-31 16:21:09,429 INFO stopped: identity (exit status 0)

[kspearrin]

The logs you posted seem to indicate that everything was up and running fine until you shut things down at 16:20:53, which sends Application is shutting down... to the notifications service.

[ghost]

Correct, but unfortunately no meaningful logging informations.

[kspearrin]

Was there any problems in the example you just posted? It seems notifications was up and running without issue.

[ghost]

No, and I just recreated the container again to include the "Fix HeartbeatHostedService logger".

Edit: By the way, the push to Android and the Chrome extensions works perfectly.

[kspearrin]

So can this issue be closed now?

[ghost]

It still throws the "Unhandled exception" on shutdown. I don't think that's okay. 🤷‍♂️

[kspearrin]

Ok, I guess I originally misunderstood that this was causing some problem with the notifications service running.

The shutdown exceptions should be resolved with #2654 . Can you pull and test the dev tag again to see if you encounter the problem?

[ghost]

@kspearrin Fixed! 🥳