Constant polling of database file due to hash checks

[serpro69]

Current Behavior

I can see that the database file is constantly accessed after upgrading to 2.5.0.
The same behavior can be seen if do strace on the pid of the keepassxc process.

This started happening when I updated to 2.5.0 though I've been using the ppa for Ubuntu 18.04 and the last previous version available is 2.3.1

Debug Info

KeePassXC - 2.5.0
Operating system: Ubuntu 18.04
Kernel: 5.0.0-32-generic

[phoerious]

What file system are you storing your DB on? Polling for changes in the database file is the fallback if inode watching isn't possible. This happens mostly on FUSE remote file systems.

[MartinX3]

KeePassXC - 2.5.0
Operating system: Ubuntu 18.04
Kernel: 5.0.0-32-generic
Filesystem: ext4
Did run it for 10 seconds

strace.log

[serpro69]

My db file is on Dropbox and encrypted with Cryptomator.
In Cryptomator I can see that it's being constantly accessed. Same can be seen with strace:

restart_syscall(<... resuming interrupted poll ...>) = 0
openat(AT_FDCWD, "/home/sergio/.local/share/Cryptomator/mnt/dropbox-vault/Documents/db.kdbx", O_RDONLY|O_CLOEXEC) = 37
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
read(37, "\3\331\242\232g\373K\265\1\0\3\0\2\20\0001\301\362\346\277qCP\276X\5!j\374Z\377\3"..., 16384) = 16384
read(37, "OKr0\17\0261^\345\273\220,\26\330\353e\21\205`lSqS8jY\344\372\315'\27\335"..., 16384) = 16384
read(37, "&\224\246|\376Q\370\257a\250\t\326\305\325\244W\207\205\220\373\262\352\254\243\276\201\230\372\0028Y\373"..., 16384) = 6030
read(37, "", 10354)                     = 0
read(37, "", 16384)                     = 0
read(37, "", 16384)                     = 0
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
close(37)                               = 0
poll([{fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=12, events=POLLIN}, {fd=14, events=POLLIN}, {fd=16, events=POLLIN}, {fd=30, events=POLLIN}, {fd=31, events=POLLIN}, {fd=33, events=POLLIN}, {fd=35, events=POLLIN}, {fd=39, events=POLLIN}, {fd=42, events=POLLIN}], 11, 990) = 0 (Timeout)
openat(AT_FDCWD, "/home/sergio/.local/share/Cryptomator/mnt/dropbox-vault/Documents/db.kdbx", O_RDONLY|O_CLOEXEC) = 37
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
read(37, "\3\331\242\232g\373K\265\1\0\3\0\2\20\0001\301\362\346\277qCP\276X\5!j\374Z\377\3"..., 16384) = 16384
read(37, "OKr0\17\0261^\345\273\220,\26\330\353e\21\205`lSqS8jY\344\372\315'\27\335"..., 16384) = 16384
read(37, "&\224\246|\376Q\370\257a\250\t\326\305\325\244W\207\205\220\373\262\352\254\243\276\201\230\372\0028Y\373"..., 16384) = 6030
read(37, "", 10354)                     = 0
read(37, "", 16384)                     = 0
read(37, "", 16384)                     = 0
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
close(37)                               = 0
poll([{fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=12, events=POLLIN}, {fd=14, events=POLLIN}, {fd=16, events=POLLIN}, {fd=30, events=POLLIN}, {fd=31, events=POLLIN}, {fd=33, events=POLLIN}, {fd=35, events=POLLIN}, {fd=39, events=POLLIN}, {fd=42, events=POLLIN}], 11, 982) = 0 (Timeout)
openat(AT_FDCWD, "/home/sergio/.local/share/Cryptomator/mnt/dropbox-vault/Documents/db.kdbx", O_RDONLY|O_CLOEXEC) = 37
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
fstat(37, {st_mode=S_IFREG|0664, st_size=38798, ...}) = 0
read(37, "\3\331\242\232g\373K\265\1\0\3\0\2\20\0001\301\362\346\277qCP\276X\5!j\374Z\377\3"..., 16384) = 16384
read(37, "OKr0\17\0261^\345\273\220,\26\330\353e\21\205`lSqS8jY\344\372\315'\27\335"..., 16384) = 16384

Strangely this only started happening with the latest update of keepassxc, hence I assumed the issue was here.

[phoerious]

I can reproduce constant polling of various sockets. Two being inotify sockets, the other two probably related to DBus and X11. Enabling browser integration adds another socket to the list. I cannot reproduce KeePassXC actually reading the file (that's what inotify is for anyway).

What you are seeing may be introduced by #3612, though. Since I do not see inotify polls in your strace logs, I assume that for some reason inotify polling failed, so KeePassXC resorts to comparing file hashes instead.

[MartinX3]

Now I get browser add-on access questions on a regular base.
And always there is a website I did not open in my browser in this access list.

[phoerious]

KeePassXC-Browser issues are not related to file polling. Please report those in a separate bug report.

[serpro69]

@phoerious thanks for your inputs. Anything else I can do from my side to give more detail or help in debugging this?

[droidmonkey]

No need to debug further, this is the new hashing check. It does it every second. We will be looking into that frequency in 2.5.1

[danoe]

Just fyi, on an SMB share with two databases (72K and 232K in size) this causes a constant downstream of 2.5Mbps.

[droidmonkey]

Uh how is that possible if we poll once per second?

[danoe]

Ok, slight correction, nethogs and iftop probably poll only once per second, running nethogs -d 0.5 or even 0.2 i see it's not truly constant but still.

[droidmonkey]

Don't worry I have an idea on how to fix this and also reduce data usage. I totally neglected the fact that ANY change to the database will cause the encrypted portion to be totally different. As such, I really only need to hash the first KiB or two of the file to determine if it changed.

[theCalcaholic]

It would probably be a good idea to rely on async I/O if possible. If the network is unreliable or was lost in-between, the file check would trigger a remount of e.g. a network share (webdav/sftp/...) which causes a big delay independent from the actual amount of data that is being transferred.

Implementing file access in a non-blocking way would probably lead to a much smoother experience with unreliable network situations.

For reference: #1799 is the feature which causes the problem

[droidmonkey]

That feature has been merged since 2.4.0. Agree though, we should be doing the hash check asynchronously.

[ubmarco]

I experience the same issue on Manjaro with version 2.5.0.
2 Keepass containers in a Cryptomator FUSE mount produce a constant 2.5MB/s IO, measured with iotop.