Bitwarden Stops Working

[will]

Over the last few weeks bitwarden crashes and refuses to work, web interface and clients cannot connect. An app restart fixes things.
I got the following symptoms.

Copy & Pasted:
May 20 12:13:03 [Wed May 20 16:13:03.755985 2020] [proxy:error] [pid 18] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 20 12:13:03 [Wed May 20 16:13:03.756011 2020] [proxy_http:error] [pid 18] [client 172.18.0.1:43974] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
May 20 12:13:03 172.18.0.1 - - [20/May/2020:16:13:03 +0000] "POST /identity/connect/token HTTP/1.1" 503 570 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.113 Safari/537.36"
May 20 12:13:10 172.18.0.1 - - [20/May/2020:16:13:10 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
May 20 12:13:13 [Wed May 20 16:13:13.588588 2020] [proxy:error] [pid 17] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 20 12:13:13 [Wed May 20 16:13:13.588615 2020] [proxy_http:error] [pid 17] [client 172.18.0.1:44212] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
May 20 12:13:13 172.18.0.1 - - [20/May/2020:16:13:13 +0000] "GET / HTTP/1.1" 503 570 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36"
May 20 12:13:13 [Wed May 20 16:13:13.696418 2020] [proxy:error] [pid 19] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 20 12:13:13 [Wed May 20 16:13:13.696444 2020] [proxy_http:error] [pid 19] [client 172.18.0.1:44218] AH01114: HTTP: failed to make connection to backend: 127.0.0.1, referer: https://vault.famfam.us/
May 20 12:13:13 172.18.0.1 - - [20/May/2020:16:13:13 +0000] "GET /favicon.ico HTTP/1.1" 503 570 "https://vault.famfam.us/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36"
May 20 12:13:16 [Wed May 20 16:13:16.488998 2020] [proxy:error] [pid 16] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 20 12:13:16 [Wed May 20 16:13:16.489024 2020] [proxy_http:error] [pid 16] [client 172.18.0.1:44232] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
May 20 12:13:16 172.18.0.1 - - [20/May/2020:16:13:16 +0000] "GET / HTTP/1.1" 503 570 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36"
May 20 12:13:16 [Wed May 20 16:13:16.597252 2020] [proxy:error] [pid 15] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 20 12:13:16 [Wed May 20 16:13:16.597278 2020] [proxy_http:error] [pid 15] [client 172.18.0.1:44240] AH01114: HTTP: failed to make connection to backend: 127.0.0.1, referer: https://vault.famfam.us/
May 20 12:13:16 172.18.0.1 - - [20/May/2020:16:13:16 +0000] "GET /favicon.ico HTTP/1.1" 503 570 "https://vault.famfam.us/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36"

[girish]

@will Unfortunately, the app hasn't been packaged correctly to log by default it seems. I am making a new release.

[girish]

@will I have pushed an update now. There are logs at /run/bitwardenrs/bitwardenrs.log . Do you see anything there? You can also edit /app/data/config.env and set log level to debug and restart the app for more detailed logs.

[will]

@girish Unfortunately I updated before I read your reply
The issue is intermittent, I'll pull logs when/if it happens again.

[will]

@girish Ok the issue happened again. I'm going to download full logs, and copy and paste what look like relevant parts below.

May 27 11:20:29 box:tasks setCompleted - 1670: {"result":null,"error":{"stack":"BoxError: Unknown install command in apptask:installed\n at /home/yellowtent/box/src/apptask.js:1049:29\n at /home/yellowtent/box/src/apps.js:520:13\n at /home/yellowtent/box/src/appdb.js:147:13\n at Query.args.(anonymous function) (/home/yellowtent/box/src/database.js:165:9)\n at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10)\n at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16)\n at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24)\n at Query._handleFinalResultPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:149:8)\n at Query.EofPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:133:8)\n at Protocol._parsePacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/Protocol.js:291:23)","name":"BoxError","reason":"Internal Error","details":{},"message":"Unknown install command in apptask:installed"}}
May 27 11:20:29 box:tasks 1670: {"percent":100,"result":null,"error":{"stack":"BoxError: Unknown install command in apptask:installed\n at /home/yellowtent/box/src/apptask.js:1049:29\n at /home/yellowtent/box/src/apps.js:520:13\n at /home/yellowtent/box/src/appdb.js:147:13\n at Query.args.(anonymous function) (/home/yellowtent/box/src/database.js:165:9)\n at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10)\n at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16)\n at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24)\n at Query._handleFinalResultPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:149:8)\n at Query.EofPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:133:8)\n at Protocol._parsePacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/Protocol.js:291:23)","name":"BoxError","reason":"Internal Error","details":{},"message":"Unknown install command in apptask:installed"}}

And later in the logs:
May 28 14:54:04 [Thu May 28 18:54:04.379181 2020] [proxy:error] [pid 26] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 28 14:54:04 [Thu May 28 18:54:04.379209 2020] [proxy_http:error] [pid 26] [client 172.18.0.1:45284] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
May 28 14:54:04 172.18.0.1 - - [28/May/2020:18:54:04 +0000] "POST /api/accounts/prelogin HTTP/1.1" 503 572 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:74.0) Gecko/20100101 Firefox/74.0"
May 28 14:54:07 [Thu May 28 18:54:07.475498 2020] [proxy:error] [pid 19] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 28 14:54:07 [Thu May 28 18:54:07.475529 2020] [proxy_http:error] [pid 19] [client 172.18.0.1:45292] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
May 28 14:54:07 172.18.0.1 - - [28/May/2020:18:54:07 +0000] "POST /api/accounts/prelogin HTTP/1.1" 503 572 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:74.0) Gecko/20100101 Firefox/74.0"
May 28 14:54:10 172.18.0.1 - - [28/May/2020:18:54:10 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
May 28 14:54:20 172.18.0.1 - - [28/May/2020:18:54:20 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
May 28 14:54:30 172.18.0.1 - - [28/May/2020:18:54:30 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
May 28 14:54:40 172.18.0.1 - - [28/May/2020:18:54:40 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
May 28 14:54:40 [Thu May 28 18:54:40.161101 2020] [proxy:error] [pid 26] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
May 28 14:54:40 [Thu May 28 18:54:40.161127 2020] [proxy_http:error] [pid 26] [client 172.18.0.1:45658] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
May 28 14:54:40 172.18.0.1 - - [28/May/2020:18:54:40 +0000] "POST /api/accounts/prelogin HTTP/1.1" 503 572 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:74.0) Gecko/20100101 Firefox/74.0"

[girish]

@will said in Bitwarden Stops Working:

Unknown install command in apptask:installed

The above is really strange. I wonder why apptask was called for an installed app. @will So a restart fixes it?

[will]

@girish Correct

[msbt]

@girish said in Bitwarden Stops Working:

/run/bitwardenrs/bitwardenrs.log

happened to me as well now, this is what the log file is showing:

[2020-07-01 21:28:13][panic][ERROR] thread 'main' panicked at 'Can't connect to DB: BadConnection("Can\'t connect to MySQL server on \'mysql\' (111)")': src/main.rs:235
   0: bitwarden_rs::init_logging::{{closure}}
   1: std::panicking::rust_panic_with_hook
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/panicking.rs:490
   2: rust_begin_unwind
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/panicking.rs:388
   3: core::panicking::panic_fmt
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libcore/panicking.rs:101
   4: core::option::expect_none_failed
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libcore/option.rs:1272
   5: bitwarden_rs::main
   6: std::rt::lang_start::{{closure}}
   7: std::rt::lang_start_internal::{{closure}}
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/rt.rs:52
      std::panicking::try::do_call
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/panicking.rs:297
      std::panicking::try
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/panicking.rs:274
      std::panic::catch_unwind
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/panic.rs:394
      std::rt::lang_start_internal
             at /rustc/74e80468347471779be6060d8d7d6d04e98e467f/src/libstd/rt.rs:51
   8: main
   9: __libc_start_main
  10: _start

[imc67]

My BW app also seemd to be crashed, bad thing is that Cloudron Healthcheck didn't noticed:

box:tasks 4110: {"percent":100,"result":null,"error":{"stack":"BoxError: Unknown install command in apptask:installed\n at /home/yellowtent/box/src/apptask.js:1048:29\n at /home/yellowtent/box/src/apps.js:520:13\n at Query.<anonymous> (/home/yellowtent/box/src/appdb.js:147:13)\n at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10)\n at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16)\n at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24)\n at Query._handleFinalResultPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:149:8)\n at Query.EofPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:133:8)\n at Protocol._parsePacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/Protocol.js:291:23)\n at Parser._parsePacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/Parser.js:433:10)","name":"BoxError","reason":"Internal Error","details":{},"message":"Unknown install command in apptask:installed"}}
Jul 04 14:35:30 172.18.0.1 - - [04/Jul/2020:12:35:30 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
Jul 04 14:35:40 172.18.0.1 - - [04/Jul/2020:12:35:40 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"
Jul 04 14:35:50 172.18.0.1 - - [04/Jul/2020:12:35:50 +0000] "GET /healthcheck HTTP/1.1" 200 173 "-" "Mozilla (CloudronHealth)"

[imc67]

Today, after a security reboot, the Bitwarden app didn't came up, same error and also healthcheck didn't noticed.

In-app restart solved it.

This is really annoying.

[nebulon]

Yes, I have seen that as well sometimes after a server reboot, not with bitwarden particularily but with other apps not coming up well and requiring an app restart. So far I wasn't able to point a finger but generally we may have to start containers maybe slower in sequence to not overload the system at once.

[msbt]

yea i have that with teamspeak, almost everytime it needs another restart because mysql wasn't ready yet or something.

[d19dotca]

@nebulon I've never personally seen this issue on reboot, but I have seen the original issue at times with sometimes an app stops responding but there's no notification of it and I learn of it reactively instead of proactively to restart the app. Almost like the monitor still sees it as healthy when it's not actually responding to any client requests to the website.

[girish]

When the database restarts, some apps cannot deal with the loss of connectivity. In fact, we have special code on Cloudron to restart all the corresponding apps whenever the database is updated. I guess we need similar logic for database restart. I think docker has some way to get these event notifications. Something to keep in mind when debugging this.

[nebulon]

The latest version now retries apparently. So I guess this is solved.

[d19dotca]

@nebulon Ah yes I see what you mean. Let's hope this does the trick. From the changelog: "Now the initial database connection doesn't fail instantly when there's an error, but retries for up to 15 times by default, adjustable with the DB_CONNECTION_RETRIES option."