Massive 8GB logfile with 124M repeating lines of messages and suddenly stopping again?!

Help
1

This night I got an email from Cloudflare stating the following:

We’ve aggregated data from 1 of your Cloudflare sites during the month of August. Cloudflare served 67.53 GB of data, and mitigated firewall events.

I’m only using Cloudflare as a reverse proxy for Vaultwarden… so 67GB???

I VPN’d home and stopped the Vaultwarden container (for whatever that would be worth). At home I first logged in to Cloudflare to see if could narrow it down a bit. Looking at the traffic stats I saw this:

Bandwith
Bandwith1283×625 24.3 KB

So something happened/started at the end of the 27th of august… Opened the appdata folder of Vaultwarden to see that Bitwarden.log was over 8GB large! 124 million lines! Notepad++ had a really hard time opening the file. Trying to search the file for the date crashed it immediately. Anyway, I finaly found the start of the problem.

All looked normal until the 27th, but on the 28th it suddenly went beserk. And on the 7th it all just went back to normal.

[2023-08-27 16:56:47.097][response][INFO] (icon_internal) GET /icons/<domain>/icon.png => 200 OK
[2023-08-28 01:39:49.860][request][INFO] GET /api/config
[2023-08-28 01:39:49.860][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.892][request][INFO] GET /api/config
[2023-08-28 01:39:49.892][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.898][request][INFO] GET /api/config
[2023-08-28 01:39:49.899][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.920][request][INFO] GET /api/config
[2023-08-28 01:39:49.920][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.921][request][INFO] GET /api/config
[2023-08-28 01:39:49.921][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.945][request][INFO] GET /api/config
[2023-08-28 01:39:49.945][request][INFO] GET /api/config
[2023-08-28 01:39:49.946][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.945][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.950][request][INFO] GET /api/config
[2023-08-28 01:39:49.951][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.968][request][INFO] GET /api/config
[2023-08-28 01:39:49.969][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.969][request][INFO] GET /api/config
[2023-08-28 01:39:49.969][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.971][request][INFO] GET /api/config
[2023-08-28 01:39:49.972][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.989][request][INFO] GET /api/config
[2023-08-28 01:39:49.989][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.992][request][INFO] GET /api/config
[2023-08-28 01:39:49.992][request][INFO] GET /api/config
[2023-08-28 01:39:49.992][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:49.993][response][INFO] (config) GET /api/config => 200 OK
[2023-08-28 01:39:50.012][request][INFO] GET /api/config

ETC.

[2023-09-07 17:10:54.043][request][INFO] GET /api/config
[2023-09-07 17:10:54.043][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.115][request][INFO] GET /api/config
[2023-09-07 17:10:54.116][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.116][request][INFO] GET /api/config
[2023-09-07 17:10:54.117][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.133][request][INFO] GET /api/config
[2023-09-07 17:10:54.133][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.198][request][INFO] GET /api/config
[2023-09-07 17:10:54.198][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.260][request][INFO] GET /api/config
[2023-09-07 17:10:54.260][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.267][request][INFO] GET /api/config
[2023-09-07 17:10:54.267][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.290][request][INFO] GET /api/config
[2023-09-07 17:10:54.290][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.349][request][INFO] GET /api/config
[2023-09-07 17:10:54.349][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.432][request][INFO] GET /api/config
[2023-09-07 17:10:54.433][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.495][request][INFO] GET /api/config
[2023-09-07 17:10:54.496][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.496][request][INFO] GET /api/config
[2023-09-07 17:10:54.496][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.567][request][INFO] GET /api/config
[2023-09-07 17:10:54.567][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.574][request][INFO] GET /api/config
[2023-09-07 17:10:54.574][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:10:54.635][request][INFO] GET /api/devices/knowndevice
[2023-09-07 17:10:54.635][response][INFO] (get_known_device) GET /api/devices/knowndevice => 200 OK
[2023-09-07 17:11:01.365][request][INFO] POST /identity/accounts/prelogin
[2023-09-07 17:11:01.366][response][INFO] (prelogin) POST /identity/accounts/prelogin => 200 OK
[2023-09-07 17:11:01.528][request][INFO] POST /identity/connect/token
[2023-09-07 17:11:01.589][error][ERROR] 2FA token not provided
[2023-09-07 17:11:01.589][response][INFO] (login) POST /identity/connect/token => 400 Bad Request
[2023-09-07 17:11:34.583][request][INFO] POST /identity/connect/token
[2023-09-07 17:11:34.647][vaultwarden::api::identity][INFO] User [my_user_email] logged in successfully. IP: 141.101.76.9
[2023-09-07 17:11:34.647][response][INFO] (login) POST /identity/connect/token => 200 OK
[2023-09-07 17:11:34.909][request][INFO] GET /api/config
[2023-09-07 17:11:34.909][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:11:34.909][request][INFO] GET /api/config
[2023-09-07 17:11:34.909][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:12:12.423][request][INFO] GET /api/devices/knowndevice
[2023-09-07 17:12:12.424][response][INFO] (get_known_device) GET /api/devices/knowndevice => 200 OK
[2023-09-07 17:12:48.225][request][INFO] GET /api/devices/knowndevice
[2023-09-07 17:12:48.225][response][INFO] (get_known_device) GET /api/devices/knowndevice => 200 OK
[2023-09-07 17:12:56.559][request][INFO] POST /identity/accounts/prelogin
[2023-09-07 17:12:56.559][response][INFO] (prelogin) POST /identity/accounts/prelogin => 200 OK
[2023-09-07 17:12:56.735][request][INFO] POST /identity/connect/token
[2023-09-07 17:12:56.785][error][ERROR] 2FA token not provided
[2023-09-07 17:12:56.785][response][INFO] (login) POST /identity/connect/token => 400 Bad Request
[2023-09-07 17:13:06.646][request][INFO] POST /identity/connect/token
[2023-09-07 17:13:06.697][vaultwarden::api::identity][INFO] User [my_user_email] logged in successfully. IP: 172.71.102.114
[2023-09-07 17:13:06.697][response][INFO] (login) POST /identity/connect/token => 200 OK
[2023-09-07 17:13:06.948][request][INFO] GET /api/config
[2023-09-07 17:13:06.948][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:13:07.070][request][INFO] GET /api/config
[2023-09-07 17:13:07.071][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:15:46.071][request][INFO] POST /identity/connect/token
[2023-09-07 17:15:46.075][response][INFO] (login) POST /identity/connect/token => 200 OK
[2023-09-07 17:15:46.521][request][INFO] GET /api/sync?excludeDomains=true
[2023-09-07 17:15:46.598][response][INFO] (sync) GET /api/sync?<data..> => 200 OK
[2023-09-07 17:15:48.759][request][INFO] GET /api/config
[2023-09-07 17:15:48.759][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:18:07.707][vaultwarden::api::notifications][INFO] Closing WS connection from 172.18.0.3
[2023-09-07 17:18:17.182][request][INFO] GET /api/config
[2023-09-07 17:18:17.182][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:18:17.211][request][INFO] POST /identity/connect/token
[2023-09-07 17:18:17.214][response][INFO] (login) POST /identity/connect/token => 200 OK
[2023-09-07 17:18:17.578][request][INFO] GET /api/sync?excludeDomains=true
[2023-09-07 17:18:17.681][response][INFO] (sync) GET /api/sync?<data..> => 200 OK
[2023-09-07 17:18:20.215][request][INFO] GET /api/config
[2023-09-07 17:18:20.216][response][INFO] (config) GET /api/config => 200 OK
[2023-09-07 17:18:29.118][request][INFO] POST /identity/connect/token
[2023-09-07 17:18:29.127][response][INFO] (login) POST /identity/connect/token => 200 OK
[2023-09-07 17:18:29.504][vaultwarden::api::notifications][INFO] Accepting WS connection from 172.18.0.3:50338
[2023-09-07 17:18:29.555][request][INFO] GET /api/accounts/revision-date
[2023-09-07 17:18:29.556][response][INFO] (revision_date) GET /api/accounts/revision-date => 200 OK

124M lines, 62M requests using ~1KB = 67GB. So yeah, found the issue. But what the hell?

How am I running Vaultwarden:
Unraid + Docker + Swag + Cloudflare.

How am I using Vaultwarden:
Main PC running Windows 10 with Bitwarden Desktop installed with Chocolatey, running auto upgrade at boot. Also browser plugins.

Thoughts and possible cause?

  • I know that Vaultwarden was updated on the 27th of august around 13:00. Well before this started, but it could be related? A coincidence?
  • I don’t remember what I was doing on the 28th, but i’m pretty sure I was behind my computer when this all started. Possibly starting my PC at that time. I’m using Chocolatey and running auto upgrade at boot. Bitwarden desktop application could have possibly been updated around this time. I was thinking maybe the Bitwarden desktop application caused this somehow. It almost perfectly correlates with the version history dates on chocolatey Chocolatey Software | Bitwarden 2023.10.1
    2023.8.2 = 28th of august
    2023.8.3 = 6th of september
  • I know that Vaultwarden also updated on the 3rd of september around 13:00. But I can’t find any sign of that in the log. The log just keeps going and going with the same message. No sign of Vaultwarden stopping / updating / starting.
  • I know that the Bitwarden desktop application on my main computer running Windows 10 was acting up the last couple of weeks. Window Hello not working. Finally prompting me to login again with my master password and asking for my 2FA code. Which I at first clicked away because I didn’t have my yubikey at hand. The last lines of the log I pasted above are (I think) those login attempts. It’s my user email at least. The IP’s are Cloudflare’s. After these lines all went back to normal as far as I can tell.

.
So my guess is the desktop application is to blame somehow, but I don’t see how this could have caused Vaultwarden to spit out these log messages, even when the PC was turned off?

Please advice on what to do now? Just delete the 8GB logfile and start up the container again?

Thank you for reading and your help in advance.

2

You have a client which is causing an issue. That could be any client, even your mobile client. Check your logs and see in your reverse-proxy/cloudflare logs if there is a user-agent which you can see that causes this. Also try to force stop/restart all the clients you have and see if that solves it.

We have had just one report of this from someone else, and there his Linux client was causing the issue for some reason.

3

Think I figured it out. Went looking for the user-agent involved like you suggested and according to the access.log file (also 9GB large…) the user-agent involved is:
Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.5615.50 Safari/537.36

  • So it’s Chrome version 112. Which means the Bitwarden Chrome Extension?
  • Originating from my country. The IP logged is that of Cloudflare and I’m unable to figure out the real IP behind these requests. Cloudflare seems to only log blocked requests, which is everything not originating from my country.
  • Most likely coming from my PC as it started at or around the same time I booted up my PC.

And I now remember that I indeed deleted and installed the Bitwarden Chrome Extension because of the trouble (known bug) with Windows Hello. Don’t know the exact date anymore unfortunately. Looking at the Chrome Extension history I see that it was last updated on september 6th to version 2023.8.3. On the 7th everything went back to normal so my best guess is that the previous update to version 2023.8.2. was bugged?

But what I don’t understand

  • Chrome version 112 is from april this year. Chrome has been updated on my computer for sure since then. So why is such an old version logged?
  • The request go on 24/7 for 10 days straight as far as I can tell. My PC has been shutdown for sure in that time period. So how is it possible the requests continued?

Anyway, this must have been the culprit right?

I’ve compressed and archived the old log file. Deleted the 8GB file and started Vaultwarden again. All seems fine.

4

That looks like the Bitwarden Desktop client actually.
https://releases.electronjs.org/release/v24.0.0

5

After reading this I went and checked my log, which looks quite OK (1.6MB for ~2 months).

But just in case, I want to add it to my log rotation script, which brings the question of how the docker instance reacts to the log file being truncated (I use “truncate -s0 /path/to/log/file”.

Will I need to restart the container after that, or will it “just work”.
Thanks in advance for your reply!

6

Thank you. Then my original theory was correct. They seem to be messing up the updates lately…

7

If you truncate and not move, then it’s fine. I actually never tested moving.

1 Like
8

Yeah, I had the desktop client do this a few weeks ago, thought i was getting attacked with the log so large so was freaking out trying to find what it was.closed desktop app and opened it again and it went away for a bit. hasnt happened in a couple weeks.