MetaEvictor: access some file cause panic when evict inodes which are still referenced by the kernel

[leoliulei]

ENV

os: Debian GNU/Linux 10
geesefs version 0.42.3

Steps to reproduce

1. mount
   /geesefs/geesefs -o allow_other -f --entry-limit 1 --debug_fuse --endpoint http://xxx:xxx xxx: mnt

2. access file

cd test2 && ls

3. MetaEvictor
   2025/02/06 10:59:30.798074 main.DEBUG metadata cache: alive 3, scanned 2, evicted 2

4. access file
   ls

[leoliulei]

I think the InvalidateEntry method of FUSE should be called when evicting an inode, and then use the forgetInode method to release the reference. The inode should only be deleted when the reference count reaches zero.

[vitalif]

Hi, currently MetaEvictor only forgets expired entries. I researched FUSE behaviour during implementation and it turns out that the correct way is to forget expired entries without opened file descriptors, but regardless of their reference count. I tried removing forgotten entries, but that's actually incorrect because the kernel doesn't bother to send Forget requests for expired entries. That's how it's implemented currently, and it seems to work correctly on systems where I test it. Maybe you use an old kernel? I use debian unstable + linux 6.8 and when I try to set --entry-limit 1 I just get "alive: ~2000" and nothing gets evicted, and I don't get any errors.

[leoliulei]

Hi, currently MetaEvictor only forgets expired entries. I researched FUSE behaviour during implementation and it turns out that the correct way is to forget expired entries without opened file descriptors, but regardless of their reference count. I tried removing forgotten entries, but that's actually incorrect because the kernel doesn't bother to send Forget requests for expired entries. That's how it's implemented currently, and it seems to work correctly on systems where I test it. Maybe you use an old kernel? I use debian unstable + linux 6.8 and when I try to set --entry-limit 1 I just get "alive: ~2000" and nothing gets evicted, and I don't get any errors.

Currently, geesefs does not check whether the reference count of a directory inode is zero when evicting expired directory inodes. As a result, after the metadata expires (default 60s), the directory inode will be evicted.

[vitalif]

Yes, this is what I said :-)

[leoliulei]

I'm using Linux 5.4 kernel here. After metadata eviction occurs (you need to wait for 60 seconds), will it panic if you access again according to my reproduction steps?

[vitalif]

No, for me it doesn't panic.

[VikNorway]

Hello everyone.
My geesefs crashes after metadata eviction.

GeeseFS 0.43.0
Ubuntu 24.04.2 LTS
Kernel 6.8.0-55-generic
fstab: geesefs#datastor /mnt/data fuse _netdev,allow_other,--file-mode=0666,--dir-mode=0777,--memory-limit=4096,--stat-cache-ttl=1m0s,--entry-limit=100000,--no-implicit-dir,--no-preload-dir,--log-file=/var/log/geesefs.log,--debug_fuse,--debug_s3 0 0
But with default fstab the same behavior.

The logs are empty, they just break off.

2025/03/24 23:00:47.973679 s3.DEBUG DEBUG: Request s3/ListObjectsV1Ext Details:
---[ REQUEST POST-SIGN ]-----------------------------
GET /datastor?delimiter=%2F&list-type=ext-v1&prefix=datadir%2F&start-after= HTTP/1.1
Host: storage.yandexcloud.net
User-Agent: GeeseFS/0.43.0 (go1.22.12; linux; amd64)
Accept-Encoding: identity
Authorization: AWS4-HMAC-SHA256 Credential=YCAJEkhdjncjsdq3cgtzlipIgn/20250324/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=e7bf214387b85c32dfbd427
a58fcc67b4d41183a79dc7ab4dabfbf9c6246341e
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20250324T230047Z


-----------------------------------------------------
2025/03/24 23:00:47.988470 s3.DEBUG DEBUG: Response s3/ListObjectsV1Ext Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Content-Length: 1711
Connection: keep-alive
Content-Type: application/xml; charset=UTF-8
Date: Mon, 24 Mar 2025 23:00:47 GMT
Keep-Alive: timeout=60
Server: nginx
X-Amz-Request-Id: 9c6f39a624c00bc5


-----------------------------------------------------
2025/03/24 23:00:47.988611 s3.DEBUG &{[datadir/0/ datadir/1/ datadir/2/ datadir/3/ datadir/4/ datadir/5/ datadir/6/ datadir/7/ datadir/8/ datadir/9/ datadir/a/ datadir/b/ datadir/c/ datadir/d/ datadir/e/ r
ieker/f/ datadir/pdf/ datadir/scorm/ datadir/zip/] [datadir/: 0] <nil> false 9c6f39a624c00bc5: }
2025/03/24 23:00:47.988794 fuse.DEBUG Op 0x0000aade        connection.go:543] -> ReadDir ()
2025/03/24 23:00:47.991788 fuse.DEBUG Op 0x0000aae0        connection.go:443] <- ReleaseDirHandle (PID 0)
2025/03/24 23:00:47.991951 fuse.DEBUG ReleaseDirHandle datadir
2025/03/24 23:00:47.992096 fuse.DEBUG Op 0x0000aae0        connection.go:543] -> ReleaseDirHandle ()
2025/03/24 23:00:48.838832 main.INFO I/O: 0.00 read/s, 0.00 % hits, 0.00 write/s; metadata: 223.91 read/s, 0.00 write/s, 159.48 noop/s, 99916 alive, 728.53 evict/s; 0.00 flush/s
2025/03/24 23:00:49.046987 fuse.DEBUG Op 0x0000aae2        connection.go:443] <- GetInodeAttributes (inode 5054, PID 910611)
*****EOF*****

But the strace shows panic due to Bad file descriptor.

4102215 write(8, "2025/03/24 23:00:48.838832 main.INFO I/O: 0.00 read/s, 0.00 % hits, 0.00 write/s; metadata: 223.91 read/s, 0.00 write/s, 159.48 noop/s, 99916 alive, 728.53 evict/s; 0.00 fl
ush/s\n", 178 <unfinished ...>
3969772 epoll_pwait(5,  <unfinished ...>
4102215 <... write resumed>)            = 178
3969772 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
3969416 <... nanosleep resumed>NULL)    = 0
4102215 epoll_pwait(5,  <unfinished ...>
3969772 epoll_pwait(5,  <unfinished ...>
3969416 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
4102215 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
4102215 futex(0xc00068a948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
3969416 <... nanosleep resumed>NULL)    = 0
3969416 futex(0x1b29300, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=489486397} <unfinished ...>
3969427 <... read resumed>"8\0\0\0\3\0\0\0\342\252\0\0\0\0\0\0\276\23\0\0\0\0\0\0\350\32\0\0\350\32\0\0\23\345\r\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 135168) = 56
3969427 futex(0x1b29300, FUTEX_WAKE_PRIVATE, 1) = 1
3969416 <... futex resumed>)            = 0
3969427 futex(0xc00068a948, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
3969416 getpid( <unfinished ...>
3969427 <... futex resumed>)            = 1
3969416 <... getpid resumed>)           = 3969415
4102215 <... futex resumed>)            = 0
3969427 write(8, "2025/03/24 23:00:49.046987 fuse.DEBUG Op 0x0000aae2        connection.go:443] <- GetInodeAttributes (inode 5054, PID 910611)\n", 125 <unfinished ...>
3969416 tgkill(3969415, 3969427, SIGURG <unfinished ...>
4102215 futex(0xc000701148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
3969427 <... write resumed>)            = 125
4102215 <... futex resumed>)            = 1
3969427 futex(0xc000600948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
3969416 <... tgkill resumed>)           = 0
3969887 <... futex resumed>)            = 0
3969427 <... futex resumed>)            = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
4102215 read(10,  <unfinished ...>
3969416 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
3969887 futex(0xc000600948, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
3969427 --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=3969415, si_uid=0} ---
3969887 <... futex resumed>)            = 0
3969427 rt_sigreturn({mask=[]})         = 202
3969427 futex(0xc000600948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
3969887 nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
3969427 <... futex resumed>)            = -1 EAGAIN (Resource temporarily unavailable)
3969416 <... nanosleep resumed>NULL)    = 0
3969427 futex(0xc000600948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
3969416 futex(0x1b29300, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=281319672} <unfinished ...>
3969887 <... nanosleep resumed>NULL)    = 0
3969887 nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0
3969887 write(2, "panic: ", 7)          = -1 EBADF (Bad file descriptor)
3969887 write(2, "Unknown inode: 5054", 19) = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "goroutine ", 10)      = -1 EBADF (Bad file descriptor)
3969887 write(2, "31471", 5)            = -1 EBADF (Bad file descriptor)
3969887 write(2, " [", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "running", 7)          = -1 EBADF (Bad file descriptor)
3969887 write(2, "]:\n", 3)             = -1 EBADF (Bad file descriptor)
3969887 write(2, "github.com/yandex-cloud/geesefs/core.(*Goofys).getInodeOrDie", 60) = -1 EBADF (Bad file descriptor)
3969887 write(2, "(", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc0000fa788", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0x13be", 6)           = -1 EBADF (Bad file descriptor)
3969887 write(2, ")\n", 2)              = -1 EBADF (Bad file descriptor)
3969887 write(2, "\t", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "/home/runner/work/geesefs/geesefs/core/goofys.go", 48) = -1 EBADF (Bad file descriptor)
3969887 write(2, ":", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "440", 3)              = -1 EBADF (Bad file descriptor)
3969887 write(2, " +", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xf9", 4)             = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "github.com/yandex-cloud/geesefs/core.(*GoofysFuse).GetInodeAttributes", 69) = -1 EBADF (Bad file descriptor)
3969887 write(2, "(", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc000735600", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "{", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc005f8d200", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, "?", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc00b4acf00", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, "?", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "}", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc001c98000", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, ")\n", 2)              = -1 EBADF (Bad file descriptor)
3969887 write(2, "\t", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "/home/runner/work/geesefs/geesefs/core/goofys_fuse.go", 53) = -1 EBADF (Bad file descriptor)
3969887 write(2, ":", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "97", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, " +", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0x3b", 4)             = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).handleOp", 61) = -1 EBADF (Bad file descriptor)
3969887 write(2, "(", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc000754ce0", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc00074c000", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "{", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "0x139b018", 9)        = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc0094ddd40", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, "}", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "{", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xee6880", 8)         = -1 EBADF (Bad file descriptor)
3969887 write(2, "?", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, ", ", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xc001c98000", 12)    = -1 EBADF (Bad file descriptor)
3969887 write(2, "}", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, ")\n", 2)              = -1 EBADF (Bad file descriptor)
3969887 write(2, "\t", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "/home/runner/go/pkg/mod/github.com/vitalif/fusego@v0.0.0-20241023174951-7a12c251bb93/fuseutil/file_system.go", 108) = -1 EBADF (Bad file descriptor)
3969887 write(2, ":", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "153", 3)              = -1 EBADF (Bad file descriptor)
3969887 write(2, " +", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0xd8", 4)             = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "created by ", 11)     = -1 EBADF (Bad file descriptor)
3969887 write(2, "github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps", 61) = -1 EBADF (Bad file descriptor)
3969887 write(2, " in goroutine ", 14)  = -1 EBADF (Bad file descriptor)
3969887 write(2, "76", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "\t", 1)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "/home/runner/go/pkg/mod/github.com/vitalif/fusego@v0.0.0-20241023174951-7a12c251bb93/fuseutil/file_system.go", 108) = -1 EBADF (Bad file descriptor)
3969887 write(2, ":", 1)                = -1 EBADF (Bad file descriptor)
3969887 write(2, "129", 3)              = -1 EBADF (Bad file descriptor)
3969887 write(2, " +", 2)               = -1 EBADF (Bad file descriptor)
3969887 write(2, "0x1da", 5)            = -1 EBADF (Bad file descriptor)
3969887 write(2, "\n", 1)               = -1 EBADF (Bad file descriptor)
3969887 exit_group(2 <unfinished ...>
4102215 <... read resumed> <unfinished ...>) = ?
3973469 <... futex resumed>)            = ?
3969890 <... futex resumed>)            = ?
3969889 <... futex resumed>)            = ?
3969888 <... futex resumed>)            = ?
3969887 <... exit_group resumed>)       = ?
3969775 <... futex resumed>)            = ?
3969773 <... futex resumed>)            = ?
3969772 <... epoll_pwait resumed> <unfinished ...>) = ?
3969427 <... futex resumed>)            = ?
3969426 <... futex resumed>)            = ?
3969425 <... futex resumed>)            = ?
3969424 <... futex resumed>)            = ?
3969423 <... futex resumed>)            = ?
3969774 <... futex resumed>)            = ?
3969422 <... futex resumed>)            = ?
3969421 <... futex resumed>)            = ?
3969420 <... futex resumed>)            = ?
3969419 <... futex resumed>)            = ?
3969418 <... futex resumed>)            = ?
3969417 <... futex resumed>)            = ?
3969416 <... futex resumed>)            = ?
3969415 <... futex resumed>)            = ?
4102215 +++ exited with 2 +++
3973469 +++ exited with 2 +++
3969890 +++ exited with 2 +++
3969889 +++ exited with 2 +++
3969888 +++ exited with 2 +++
3969887 +++ exited with 2 +++
3969775 +++ exited with 2 +++
3969774 +++ exited with 2 +++
3969773 +++ exited with 2 +++
3969772 +++ exited with 2 +++
3969427 +++ exited with 2 +++
3969426 +++ exited with 2 +++
3969425 +++ exited with 2 +++
3969424 +++ exited with 2 +++
3969423 +++ exited with 2 +++
3969422 +++ exited with 2 +++
3969421 +++ exited with 2 +++
3969420 +++ exited with 2 +++
3969419 +++ exited with 2 +++
3969418 +++ exited with 2 +++
3969417 +++ exited with 2 +++
3969416 +++ exited with 2 +++
3969415 +++ exited with 2 +++

[VikNorway]

I completely forgot to say that the mount point is /mnt/data, and, for example, /mnt/data/dir1 is the volume of first the docker containers, /mnt/data/dir2 is the volume of the second container, /mnt/data/dir3 is the volume of the third container, etc. Maybe when evicting metadata, the container accesses old inodes of dir1, dir2, dir, etc? That is, the inode /mnt/data/dir1 is evicted, and the container accesses the old inode and we get an error.
Then how to force the container to update the inode data or to make sure that geesefs does not evict the inodes of the folders mounted in the containers?

Also, my apologies for my english.

[VikNorway]

Well, my guess was right. It was about mounting docker volumes.
I made a small patch where I added the --no-evict-root-childs flag. It prevents eviction of child directories of the root inode and updates their ExpiredTime. It seems to work fine, but there is a small bug: when --entry-limit is small (less than the number of child directories), MetaEvictor starts an infinite loop of eviction attempts. When --entry-limit is large, everything works fine.
I can make a pull request if this feature can be useful for other people. However, I don't know Go very well (at all, to be honest), so my code most likely leaves much to be desired. But it works!

[leoliulei]

Well, my guess was right. It was about mounting docker volumes. I made a small patch where I added the --no-evict-root-childs flag. It prevents eviction of child directories of the root inode and updates their ExpiredTime. It seems to work fine, but there is a small bug: when --entry-limit is small (less than the number of child directories), MetaEvictor starts an infinite loop of eviction attempts. When --entry-limit is large, everything works fine. I can make a pull request if this feature can be useful for other people. However, I don't know Go very well (at all, to be honest), so my code most likely leaves much to be desired. But it works!

only root-childs can cause error?

[VikNorway]

only root-childs can cause error?

Yeah, in my case. If one bucket is mounted and child folders are mounted as a volume in docker, geesefs crashed with the error "Bad file descriptor" after MetaEvictor run. After I excluded evicting child folders, the error no longer appears.
But I'm sure that the error will repeat if you mount a child folder of a child folder in docker. That is, for example, /mnt/data is the mount point of the bucket. Then mounting /mnt/data/dir1 in docker will not cause an error, but /mnt/data/dir1/subdir1 will.

[VikNorway]

I made a pull request with my changes.
#136

[VVoidV]

@VikNorway My scenario is that I stay in a subdirectory of geesefs and wait for an eviction to occur. Then, if I run ls, it crashes.
However, if I configure geesefs not to evict inodes whose refcnt is greater than 1 (which means the kernel is still caching them in dentry/inode_cache), everything works fine.
But the evictor keeps scanning inodes_by_time, consuming a huge amount of CPU cycles, and the memory cost is also high.

[VikNorway]

Hi, @VVoidV !
It looks very similar to my case with docker. Perhaps ls also tries to read file data directly from the inode cache, and since it is cleared, geesefs panics and crashes. This is definitely due to the getInodeOrDie function. But I think it is not made without reason.
The fact that you disable eviction essentially turns geesefs into goofys, but with an infinitely running metaevictor. I don't think that disabling metaevictor completely is a good idea, because metaevictor is a geesefs killer feature, IMHO. Without metaevictor, memory consumption will constantly grow. As, in fact, happens in goofys. This is exactly why I switched to geesefs.
I solved my problem with a small patch, which I described above. Now geesefs with this patch has been working for me for almost two months without crashes. At the same time, memory and CPU consumption remains at an acceptable level. But I had a problem only with the child objects of the root folder (inode 1).