Input/Output error with libc.so.6 when using udba=none on kernel 5.10+ during remount loop

[arturpzol]

I have encountered an issue with the AUFS filesystem that occurs sporadically during system startup. The error message I receive is:

error while loading shared libraries: libc.so.6: cannot open shared object file: Input/output error

Upon further investigation, I found that this issue also occurs when I run a remount loop:

mount |grep aufs
aufs on / type aufs (rw,relatime,sync,si=57b4c9ce733e61da,udba=none,nowarn_perm)
while true; do mount -o remount / ; done

After some time, the following errors appear:

mount: error while loading shared libraries: libc.so.6: cannot open shared object file: Input/output error
mount: error while loading shared libraries: libc.so.6: cannot open shared object file: Input/output error
mount: error while loading shared libraries: libc.so.6: cannot open shared object file: Input/output error

From that point on, it becomes impossible to run any command in the system as all attempts result in an "Input/output error."

The issue occurs on the latest kernel (6.10.6) and AUFS version (6.10-20240722). After conducting some tests, I found that this problem started appearing with kernel 5.10 and has not occurred on kernel 5.9 (aufs 5.9-20210906). Something must have changed starting with kernel 5.10 that causes this issue to appear.

The issue only arises when udba=none is set while mounting AUFS. When udba=notify is used, the problem does not occur.

I understand that running a remount loop is not typical in normal environments, but the fact that it leads to such critical issues suggests a potential bug in AUFS.

@sfjro , would you be able to run a remount loop on your setup with AUFS using udba=none and check if the issue occurs for you as well?

[sfjro]

Hello Artur,

Artur Piechocki:

I have encountered an issue with the AUFS filesystem that occurs sporadically during system startup. The error message I receive is:

error while loading shared libraries: libc.so.6: cannot open shared object file: Input/output error :::

mount |grep aufs
aufs on / type aufs (rw,relatime,sync,si=57b4c9ce733e61da,udba=none,nowarn_perm)
while true; do mount -o remount / ; done

::: @sfjro , would you be able to run a remount loop on your setup with AUFS using udba=none and check if the issue occurs for you as well?

Thanx for the report. I have tried hundreds times on aufs6.x-rcN (for linux-v6.11-rc4) but could not reproduce. It may be related to my regular test environment whose root dir is not aufs.

I have some questions for you.

• How did you mount your root aufs at the beginning? initramfs + busybox + swtich_root?
• How may branches does your root aufs have?
• Which branch contains libc.so.6?

I need to know which process got that error. Busybox(mount), /bin/mount, or /sbin/mount.aufs? Could you try strace or something?

Also

• Are there any kernel log left?
• Have you installed aufs-util.git on your system?
• Is your kernel patched by a linux distribution?
• How is your aufs configuration (define/undefine CONFIG_AUFS_xxx)?
• How is your LSM setting?

J. R. Okajima

[arturpzol]

@sfjro thank you for attempting to reproduce the problem in your environment.

The issue I occasionally experience during system startup is very rare, and I have no way to retrieve any logs from that startup. However, the loop that remounts the main file system tends to trigger the problem relatively quickly. It's possible that these are two separate issues...

Answers to your questions:

• How did you mount your root aufs at the beginning? initramfs + busybox + swtich_root?

yes exacly, it is initramfs + busybox + swtich_root

• How may branches does your root aufs have?

The number of branches seems to be irrelevant here, as the problem occurs with both 3 and 10 branches, for example. However, in my case, I have this native configuration::

find /sys/fs/aufs/si_876424372235a759/*
/sys/fs/aufs/si_876424372235a759/br0
/sys/fs/aufs/si_876424372235a759/br1
/sys/fs/aufs/si_876424372235a759/br2
/sys/fs/aufs/si_876424372235a759/br3
/sys/fs/aufs/si_876424372235a759/br4
/sys/fs/aufs/si_876424372235a759/brid0
/sys/fs/aufs/si_876424372235a759/brid1
/sys/fs/aufs/si_876424372235a759/brid2
/sys/fs/aufs/si_876424372235a759/brid3
/sys/fs/aufs/si_876424372235a759/brid4
/sys/fs/aufs/si_876424372235a759/xi_path

cat /sys/fs/aufs/si_876424372235a759/*
/mnt/live/changes=rw
/mnt/live/images/ssh.lzm=rr+wh
/mnt/live/images/linux-6.10-oe64.lzm=rr+wh
/mnt/live/images/baseosx-apache.lzm=rr+wh
/mnt/live/images/baseos.lzm=rr+wh
64
68
67
66
65
/mnt/live/xino/.aufs.xino

• Which branch contains libc.so.6?

baseos.lzm

I need to know which process got that error. Busybox(mount), /bin/mount, or /sbin/mount.aufs? Could you try strace or something?

In the case of a bash loop that is executed and remounts /, it uses /bin/mount.

The initial problem that occurs during system startup is triggered by various commands. For example, I get:

INIT: Id "2" respawning too fast: disabled for 5 minutes
INIT: Id "3" respawning too fast: disabled for 5 minutes/sbin/getty: error while loading shared libraries: 
libc.so.6: cannot open shared object file: Input/output error
/sbin/getty: error while loading shared libraries: libc.so.6: cannot open shared object file: Input/
/sbin/getty: error while loading shared libraries: libc.so.6: cannot open shared object file: Input/
output error
INIT: Id "4" respawning too fast: disabled for 5 minutes
INIT: Id "5" respawning too fast: disabled for 5 minutes
INIT: Id "6" respawning too fast: disabled for 5 minutes

• Are there any kernel log left?

No, there are no call traces or other errors in the kernel logs that would indicate the cause of the problem.

• Have you installed aufs-util.git on your system?

aufs-util.git is installed.

• Is your kernel patched by a linux distribution?

it is vanila 6.10.6 kernel with aufs 6.10-20240722 compiled by me.

• How is your aufs configuration (define/undefine CONFIG_AUFS_xxx)?

AUFS configuration:

cat /sys/fs/aufs/config              
CONFIG_AUFS_FS=m
CONFIG_AUFS_BRANCH_MAX_127=y
CONFIG_AUFS_SBILIST=y
CONFIG_AUFS_HNOTIFY=y
CONFIG_AUFS_HFSNOTIFY=y
CONFIG_AUFS_EXPORT=y
CONFIG_AUFS_INO_T_64=y
CONFIG_AUFS_BDEV_LOOP=y
CONFIG_AUFS_DEBUG=y
CONFIG_AUFS_MAGIC_SYSRQ=y

• How is your LSM setting?

no any LSM settings

Strace from while true; do strace mount -o remount / ; done

...
...
execve("/bin/mount", ["mount", "-o", "remount", "/"], [/* 18 vars */]) = 0
brk(0)                                  = 0x6daa000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f227000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=59821, ...}) = 0
mmap(NULL, 59821, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f058f211000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libmount.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\254\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=284096, ...}) = 0
mmap(NULL, 2383648, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058ec00000
mprotect(0x7f058ec43000, 2097152, PROT_NONE) = 0
mmap(0x7f058ee43000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x43000) = 0x7f058ee43000
mmap(0x7f058ee45000, 3872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f058ee45000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20c\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=142728, ...}) = 0
mmap(NULL, 2246896, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058e800000
mprotect(0x7f058e821000, 2097152, PROT_NONE) = 0
mmap(0x7f058ea21000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x21000) = 0x7f058ea21000
mmap(0x7f058ea23000, 6384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f058ea23000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1738176, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f226000
mmap(NULL, 3844640, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058e400000
mprotect(0x7f058e5a1000, 2097152, PROT_NONE) = 0
mmap(0x7f058e7a1000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a1000) = 0x7f058e7a1000
mmap(0x7f058e7a7000, 14880, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f058e7a7000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libblkid.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\210\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=258688, ...}) = 0
mmap(NULL, 2358248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058e000000
mprotect(0x7f058e03b000, 2097152, PROT_NONE) = 0
mmap(0x7f058e23b000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3b000) = 0x7f058e23b000
mmap(0x7f058e23f000, 3048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f058e23f000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20\27\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=448440, ...}) = 0
mmap(NULL, 2543976, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058dc00000
mprotect(0x7f058dc6c000, 2097152, PROT_NONE) = 0
mmap(0x7f058de6c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6c000) = 0x7f058de6c000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=14664, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f225000
mmap(NULL, 2109712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058d800000
mprotect(0x7f058d803000, 2093056, PROT_NONE) = 0
mmap(0x7f058da02000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f058da02000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libuuid.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \26\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=18904, ...}) = 0
mmap(NULL, 2113952, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058d400000
mprotect(0x7f058d404000, 2093056, PROT_NONE) = 0
mmap(0x7f058d603000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f058d603000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320n\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=137384, ...}) = 0
mmap(NULL, 2213008, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f058d000000
mprotect(0x7f058d018000, 2093056, PROT_NONE) = 0
mmap(0x7f058d217000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7f058d217000
mmap(0x7f058d219000, 13456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f058d219000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f224000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f223000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f20f000
arch_prctl(ARCH_SET_FS, 0x7f058f20f840) = 0
mprotect(0x7f058e7a1000, 16384, PROT_READ) = 0
mprotect(0x7f058d217000, 4096, PROT_READ) = 0
mprotect(0x7f058d603000, 4096, PROT_READ) = 0
mprotect(0x7f058da02000, 4096, PROT_READ) = 0
mprotect(0x7f058de6c000, 4096, PROT_READ) = 0
mprotect(0x7f058e23b000, 12288, PROT_READ) = 0
mprotect(0x7f058ea21000, 4096, PROT_READ) = 0
mprotect(0x7f058ee43000, 4096, PROT_READ) = 0
mprotect(0x608000, 4096, PROT_READ)     = 0
mprotect(0x7f058f220000, 4096, PROT_READ) = 0
munmap(0x7f058f211000, 59821)           = 0
set_tid_address(0x7f058f20fb10)         = 31590
set_robust_list(0x7f058f20fb20, 24)     = 0
rt_sigaction(SIGRTMIN, {0x7f058d0069b0, [], SA_RESTORER|SA_SIGINFO, 0x7f058d00f890}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x7f058d006a40, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f058d00f890}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
statfs("/sys/fs/selinux", 0x7ffcb7d1f500) = -1 ENOENT (No such file or directory)
statfs("/selinux", {f_type=0x61756673, f_bsize=4096, f_blocks=1013432, f_bfree=996590, f_bavail=940078, f_files=262144, f_ffree=255896, f_fsid={0, 0}, f_namelen=242, f_frsize=4096}) = 0
brk(0)                                  = 0x6daa000
brk(0x6dcb000)                          = 0x6dcb000
open("/proc/filesystems", O_RDONLY)     = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f21f000
read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 413
read(3, "", 1024)                       = 0
close(3)                                = 0
munmap(0x7f058f21f000, 4096)            = 0
getuid()                                = 0
geteuid()                               = 0
getuid()                                = 0
geteuid()                               = 0
getgid()                                = 0
getegid()                               = 0
prctl(PR_GET_DUMPABLE)                  = 1
stat("/etc/fstab", {st_mode=S_IFREG|0644, st_size=79, ...}) = 0
open("/etc/fstab", O_RDONLY|O_CLOEXEC)  = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=79, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f21f000
read(3, "aufs       /    rootfs  sync\t\t0 "..., 1024) = 79
read(3, "", 1024)                       = 0
close(3)                                = 0
munmap(0x7f058f21f000, 4096)            = 0
stat("/sbin/mount.rootfs", 0x7ffcb7d1e280) = -1 ENOENT (No such file or directory)
stat("/sbin/fs.d/mount.rootfs", 0x7ffcb7d1e280) = -1 ENOENT (No such file or directory)
stat("/sbin/fs/mount.rootfs", 0x7ffcb7d1e280) = -1 ENOENT (No such file or directory)
getuid()                                = 0
geteuid()                               = 0
getgid()                                = 0
getegid()                               = 0
prctl(PR_GET_DUMPABLE)                  = 1
getuid()                                = 0
geteuid()                               = 0
getgid()                                = 0
getegid()                               = 0
prctl(PR_GET_DUMPABLE)                  = 1
stat("/run", {st_mode=S_IFDIR|0755, st_size=1200, ...}) = 0
lstat("/etc/mtab", {st_mode=S_IFLNK|0777, st_size=12, ...}) = 0
lstat("/run/mount/utab", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
open("/run/mount/utab", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 3
close(3)                                = 0
mount("aufs", "/", 0x6daa2d0, MS_MGC_VAL|MS_SYNCHRONOUS|MS_REMOUNT, NULL) = 0
access("/", W_OK)                       = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++
-bash: /usr/bin/strace: Input/output error
-bash: /usr/bin/strace: Input/output error
-bash: /usr/bin/strace: Input/output error

It seems that the remount is successful because the exit code is 0, but everything afterward results in an Input/output error.

I enabled debug mode for AUFS, but there are a lot of logs, so I'm pasting a snippet where a -5 error occurs:

<7>[  283.876619][T10391] aufs aufs_open_nondir:90:mount[10391]: DEBUG: ld.so.cache, f_flags 0x8000, f_mode 0x801d
<7>[  283.876641][T10391] aufs au_reval_and_lock_fdi:755:mount[10391]: DEBUG: sigen 23, figen 22
<7>[  283.876651][T10391] aufs au_refresh_dentry:792:mount[10391]: DEBUG: dentry
<7>[  283.876654][T10391] d-1: 000000006c6ca199, etc/ld.so.cache?, aufs, cnt 1, flags 0x480040, hashed
<7>[  283.876661][T10391] i-1: 00000000fda5122e, i33, aufs, cnt 1, nl 1, 0100644, sz 59083, blk 120, hn -1, ct 36345, np 0, st 0x0, f 0x0, v 2, g d525d45
<7>[  283.876666][T10391] d-1: btop 0, bbot 0, bwh -1, bdiropq -1, gen 22, tmp 0
<7>[  283.876668][T10391] d0: 00000000ed6e068d, etc/ld.so.cache?, ext4, cnt 2, flags 0x480040, hashed
<7>[  283.876670][T10391] i0: 00000000c27efab9, i136782, ext4, cnt 2, nl 1, 0100644, sz 59083, blk 120, hn -1, ct 36345, np 15, st 0x0, f 0x0, v 1, g 28a3fb87
<7>[  283.876677][T10391] aufs au_lkup_dentry:231:mount[10391]: DEBUG: positive
<7>[  283.876679][T10391] aufs au_refresh_dentry:804:mount[10391]: DEBUG: dentry
<7>[  283.876681][T10391] d-1: 000000006c6ca199, etc/ld.so.cache?, aufs, cnt 1, flags 0x480040, hashed
<7>[  283.876683][T10391] i-1: 00000000fda5122e, i33, aufs, cnt 1, nl 1, 0100644, sz 59083, blk 120, hn -1, ct 36345, np 0, st 0x0, f 0x0, v 2, g d525d45
<7>[  283.876686][T10391] d-1: btop 0, bbot 0, bwh -1, bdiropq -1, gen 22, tmp 0
<7>[  283.876688][T10391] d0: 00000000ed6e068d, etc/ld.so.cache?, ext4, cnt 3, flags 0x480040, hashed
<7>[  283.876690][T10391] i0: 00000000c27efab9, i136782, ext4, cnt 2, nl 1, 0100644, sz 59083, blk 120, hn -1, ct 36345, np 15, st 0x0, f 0x0, v 1, g 28a3fb87
<7>[  283.876693][T10391] aufs au_refresh_dentry:810:mount[10391]: DEBUG: dentry
<7>[  283.876695][T10391] d-1: 000000006c6ca199, etc/ld.so.cache?, aufs, cnt 1, flags 0x480040, hashed
<7>[  283.876696][T10391] i-1: 00000000fda5122e, i33, aufs, cnt 1, nl 1, 0100644, sz 59083, blk 120, hn -1, ct 36345, np 0, st 0x0, f 0x0, v 2, g d525d45
<7>[  283.876699][T10391] d-1: btop 0, bbot 0, bwh -1, bdiropq -1, gen 22, tmp 0
<7>[  283.876701][T10391] d0: 00000000ed6e068d, etc/ld.so.cache?, ext4, cnt 3, flags 0x480040, hashed
<7>[  283.876702][T10391] i0: 00000000c27efab9, i136782, ext4, cnt 2, nl 1, 0100644, sz 59083, blk 120, hn -1, ct 36345, np 15, st 0x0, f 0x0, v 1, g 28a3fb87
<7>[  283.876706][T10391] aufs au_refresh_by_dinfo:663:mount[10391]: DEBUG: positive originally
<7>[  283.876707][T10391] aufs au_refresh_by_dinfo:676:mount[10391]: DEBUG: positive --> positive, same type
<7>[  283.876752][T10391] aufs aufs_atomic_open:352:mount[10391]: DEBUG: open_flag 0100000
<7>[  283.876754][T10391] aufs aufs_atomic_open:353:mount[10391]: DEBUG: dentry
<7>[  283.876756][T10391] d-1: 0000000075755c48, x86_64-linux-gnu/libmount.so.1?, aufs, cnt 1, flags 0x10000000, unhashed
<7>[  283.876759][T10391] i-1: err 0
<7>[  283.876766][T10391] aufs au_lkup_dentry:231:mount[10391]: DEBUG: positive
<7>[  283.876777][T10391] aufs au_new_inode:414:mount[10391]: DEBUG: i2381
<7>[  283.876785][T10391] aufs au_new_inode:420:mount[10391]: DEBUG: 8, new 1
<7>[  283.876798][T10391] aufs aufs_atomic_open:374:mount[10391]: DEBUG: dentry
<7>[  283.876799][T10391] d-1: 0000000075755c48, x86_64-linux-gnu/libmount.so.1?, aufs, cnt 1, flags 0x600000, hashed
<7>[  283.876801][T10391] i-1: 00000000bcc9aa1d, i2381, aufs, cnt 1, nl 1, 0120777, sz 17, blk 0, hn -1, ct 55296, np 0, st 0x0, f 0x0, v 2, g d5261ab
<7>[  283.876805][T10391] d-1: btop 14, bbot 14, bwh -1, bdiropq -1, gen 23, tmp 0
<7>[  283.876807][T10391] d14: 00000000683fcaae, x86_64-linux-gnu/libmount.so.1?, squashfs, cnt 1, flags 0x680040, hashed
<7>[  283.876809][T10391] i14: 00000000fbbaf3f7, i2887, squashfs, cnt 2, nl 1, 0120777, sz 17, blk 0, hn -1, ct 55296, np 1, st 0x0, f 0x0, v 0, g 0
<7>[  283.876813][T10391] aufs au_aopen_no_open:326:mount[10391]: DEBUG: here
<7>[  283.876815][T10391] aufs aufs_atomic_open:446:mount[10391]: DEBUG: file
<7>[  283.876816][T10391] f-1: mode 0x1, flags 0100000, cnt 1, v 0, pos 0
<7>[  283.876819][T10391] d-1: 0000000075755c48, x86_64-linux-gnu/libmount.so.1?, aufs, cnt 2, flags 0x600000, hashed
<7>[  283.876820][T10391] i-1: 00000000bcc9aa1d, i2381, aufs, cnt 1, nl 1, 0120777, sz 17, blk 0, hn -1, ct 55296, np 0, st 0x0, f 0x0, v 2, g d5261ab
<7>[  283.876825][T10391] aufs aufs_get_link:1366:mount[10391]: DEBUG: page_get_link
<7>[  283.876834][T10391] aufs aufs_get_link:1367:mount[10391]: DEBUG: h_dentry
<7>[  283.876835][T10391] d-1: 00000000683fcaae, x86_64-linux-gnu/libmount.so.1?, squashfs, cnt 2, flags 0x680040, hashed
<7>[  283.876836][T10391] i-1: 00000000fbbaf3f7, i2887, squashfs, cnt 2, nl 1, 0120777, sz 17, blk 0, hn -1, ct 55296, np 1, st 0x0, f 0x0, v 0, g 0
<7>[  283.876844][T10391] aufs aufs_open_nondir:90:mount[10391]: DEBUG: libmount.so.1.1.0, f_flags 0x8000, f_mode 0x801d
<7>[  283.876943][T10391] aufs aufs_open_nondir:90:mount[10391]: DEBUG: libselinux.so.1, f_flags 0x8000, f_mode 0x801d
<7>[  283.877015][T10391] aufs aufs_get_link:1378:mount[10391]: DEBUG: err -5
<7>[  283.877088][T10391] aufs aufs_get_link:1378:mount[10391]: DEBUG: err -5
<7>[  283.878446][T10392] aufs aufs_open_nondir:90:bash[10392]: DEBUG: mount, f_flags 0x8020, f_mode 0x801d
<7>[  283.878467][T10392] aufs aufs_get_link:1366:bash[10392]: DEBUG: page_get_link
<7>[  283.878471][T10392] aufs aufs_get_link:1367:bash[10392]: DEBUG: h_dentry
<7>[  283.878473][T10392] d-1: 000000007e2efab5, lib64/ld-linux-x86-64.so.2?, squashfs, cnt 2, flags 0x680040, hashed
<7>[  283.878477][T10392] i-1: 00000000ff8c3b4a, i3147, squashfs, cnt 2, nl 1, 0120777, sz 32, blk 0, hn -1, ct 55296, np 1, st 0x0, f 0x0, v 0, g 0
<7>[  283.878484][T10392] aufs aufs_open_nondir:90:bash[10392]: DEBUG: ld-2.19.so, f_flags 0x8020, f_mode 0x801d
<7>[  283.878709][T10392] aufs aufs_open_nondir:90:mount[10392]: DEBUG: ld.so.cache, f_flags 0x8000, f_mode 0x801d
<7>[  283.878734][T10392] aufs aufs_get_link:1366:mount[10392]: DEBUG: page_get_link
<7>[  283.878738][T10392] aufs aufs_get_link:1367:mount[10392]: DEBUG: h_dentry
<7>[  283.878740][T10392] d-1: 00000000683fcaae, x86_64-linux-gnu/libmount.so.1?, squashfs, cnt 2, flags 0x680040, hashed
<7>[  283.878743][T10392] i-1: 00000000fbbaf3f7, i2887, squashfs, cnt 2, nl 1, 0120777, sz 17, blk 0, hn -1, ct 55296, np 1, st 0x0, f 0x0, v 0, g 0
<7>[  283.878748][T10392] aufs aufs_open_nondir:90:mount[10392]: DEBUG: libmount.so.1.1.0, f_flags 0x8000, f_mode 0x801d
<7>[  283.878806][T10392] aufs aufs_open_nondir:90:mount[10392]: DEBUG: libselinux.so.1, f_flags 0x8000, f_mode 0x801d
<7>[  283.878862][T10392] aufs aufs_get_link:1378:mount[10392]: DEBUG: err -5
<7>[  283.878890][T10392] aufs aufs_get_link:1378:mount[10392]: DEBUG: err -5
<7>[  283.886528][T10393] aufs aufs_open_nondir:90:bash[10393]: DEBUG: mount, f_flags 0x8020, f_mode 0x801d
<7>[  283.886568][T10393] aufs aufs_get_link:1366:bash[10393]: DEBUG: page_get_link
<7>[  283.886577][T10393] aufs aufs_get_link:1367:bash[10393]: DEBUG: h_dentry
<7>[  283.886579][T10393] d-1: 000000007e2efab5, lib64/ld-linux-x86-64.so.2?, squashfs, cnt 2, flags 0x680040, hashed
<7>[  283.886585][T10393] i-1: 00000000ff8c3b4a, i3147, squashfs, cnt 2, nl 1, 0120777, sz 32, blk 0, hn -1, ct 55296, np 1, st 0x0, f 0x0, v 0, g 0
<7>[  283.886632][T10393] aufs aufs_open_nondir:90:bash[10393]: DEBUG: ld-2.19.so, f_flags 0x8020, f_mode 0x801d
<7>[  283.887012][T10393] aufs aufs_open_nondir:90:mount[10393]: DEBUG: ld.so.cache, f_flags 0x8000, f_mode 0x801d
<7>[  283.887044][T10393] aufs aufs_get_link:1366:mount[10393]: DEBUG: page_get_link
<7>[  283.887048][T10393] aufs aufs_get_link:1367:mount[10393]: DEBUG: h_dentry
<7>[  283.887050][T10393] d-1: 00000000683fcaae, x86_64-linux-gnu/libmount.so.1?, squashfs, cnt 2, flags 0x680040, hashed
<7>[  283.887053][T10393] i-1: 00000000fbbaf3f7, i2887, squashfs, cnt 2, nl 1, 0120777, sz 17, blk 0, hn -1, ct 55296, np 1, st 0x0, f 0x0, v 0, g 0
<7>[  283.887061][T10393] aufs aufs_open_nondir:90:mount[10393]: DEBUG: libmount.so.1.1.0, f_flags 0x8000, f_mode 0x801d
<7>[  283.887141][T10393] aufs aufs_open_nondir:90:mount[10393]: DEBUG: libselinux.so.1, f_flags 0x8000, f_mode 0x801d
<7>[  283.887209][T10393] aufs aufs_get_link:1378:mount[10393]: DEBUG: err -5
<7>[  283.887249][T10393] aufs aufs_get_link:1378:mount[10393]: DEBUG: err -5

I noticed that in the kernel between 5.9 and 5.10 (from which the problem started) there were several changes in aufs_remount_fs, au_remount_refresh and the like. Maybe the problem started somewhere here?

[sfjro]

Artur Piechocki:

Strace from while true; do strace mount -o remount / ; done

...
...
execve("/bin/mount", ["mount", "-o", "remount", "/"], [/* 18 vars */]) = 0
:::
stat("/etc/fstab", {st_mode=S_IFREG|0644, st_size=79, ...}) = 0
open("/etc/fstab", O_RDONLY|O_CLOEXEC)  = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=79, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f058f21f000
read(3, "aufs       /    rootfs  sync\t\t0 "..., 1024) = 79

It is wrong. The line in /etc/fstab should be aufs instead of rootfs.

stat("/sbin/mount.rootfs", 0x7ffcb7d1e280) = -1 ENOENT (No such file or directory) stat("/sbin/fs.d/mount.rootfs", 0x7ffcb7d1e280) = -1 ENOENT (No such file or directory) stat("/sbin/fs/mount.rootfs", 0x7ffcb7d1e280) = -1 ENOENT (No such file or directory)

If you change /etc/fstab, these stat(".../mount.rootfs") will change to ".../mount.aufs" (and should be found and executed). But it may NOT be related to the problem.

I enabled debug mode for AUFS, but there are a lot of logs, so I'm pasting a snippet where a -5 error occurs:

:::
<7>[  283.876844][T10391] aufs aufs_open_nondir:90:mount[10391]: DEBUG: libmount.so.1.1.0, f_flags 0x8000, f_mode 0x801d
<7>[  283.876943][T10391] aufs aufs_open_nondir:90:mount[10391]: DEBUG: libselinux.so.1, f_flags 0x8000, f_mode 0x801d
<7>[  283.877015][T10391] aufs aufs_get_link:1378:mount[10391]: DEBUG: err -5
<7>[  283.877088][T10391] aufs aufs_get_link:1378:mount[10391]: DEBUG: err -5
:::

Why 2? Threaded? Logging order? Anyway, aufs_get_link() got the error EIO, which comes from aufs_read_lock(). aufs_read_lock() gets EIO when the generation of either the root dentry and/or inode are unmatched with the generation of superblock. This may be an unknown bug. I will investigate more.

J. R. Okajima

[arturpzol]

@sfjro

If you change /etc/fstab, these stat(".../mount.rootfs") will change to ".../mount.aufs" (and should be found and executed). But it may NOT be related to the problem.

Even after switching from rootfs to aufs in fstab and using the mount.aufs command, the input/output error still persists.

Why 2? Threaded? Logging order?

This issue might be related to the order in which logs are being written via syslog.

This may be an unknown bug. I will investigate more.

Thank you.

If you need any additional logs or debugging information, please let me know. I will also try to analyze the issue on my side.

[sfjro]

Artur Piechocki:

• How did you mount your root aufs at the beginning? initramfs + busybox + swtich_root?

yes exacly, it is initramfs + busybox + swtich_root

OK then, did you run "mount --move" for your all branches before you mount aufs? I want to make sure that your branhces (/mnt/live/changes and /mnt/live/iamges/*.lzm) are living there after swtich_root.

J. R. Okajima

[sfjro]

Artur Piechocki:

If you need any additional logs or debugging information, please let me know. I will also try to analyze the issue on my side.

Thank you. I'd ask you try this debug patch. It doesn't fix the problem, but will help us to identify the cause. The debug log is LOG_INFO, so you may need to customize your /proc/sys/kernel/printk.

And the base version of this patch is aufs-6.x-rcN for linux-v6.11-rc5. I hope it doesn't matter for you.

J. R. Okajima

diff --git a/fs/aufs/dentry.c b/fs/aufs/dentry.c index 7eae27d1e9b1..bafdd54776aa 100644 --- a/fs/aufs/dentry.c +++ b/fs/aufs/dentry.c @@ -485,7 +485,8 @@ static int au_do_refresh_hdentry(struct dentry dentry, struct dentry parent) err = 0; break; }

• }
• } else

• pr_info("%pd2??, btop %d\n", dentry, dinfo->di_btop);

  AuTraceErr(err); return err; diff --git a/fs/aufs/dinfo.c b/fs/aufs/dinfo.c index 318aedd357e4..b130d8a1e67a 100644 --- a/fs/aufs/dinfo.c +++ b/fs/aufs/dinfo.c @@ -486,6 +486,7 @@ void au_update_dbrange(struct dentry *dentry, int do_put_zero) if (dinfo->di_btop > dinfo->di_bbot) { dinfo->di_btop = -1; dinfo->di_bbot = -1;

• pr_info("%pd2??, btop %d\n", dentry, dinfo->di_btop); return; }

diff --git a/fs/aufs/fsctx.c b/fs/aufs/fsctx.c index 008a5aaf11e7..b966e45141ee 100644 --- a/fs/aufs/fsctx.c +++ b/fs/aufs/fsctx.c @@ -63,9 +63,19 @@ static int au_fsctx_reconfigure(struct fs_context *fc) goto out; di_write_lock_child(root);

+pr_info("sigen %u, digen %u, iigen %u\n",

• au_sbi(sb)->si_generation,
• au_digen(root),
• au_iigen(inode, /igflags/NULL));

• / au_opts_remount() may return an error / err = au_opts_remount(sb, &a->opts);

+pr_info("sigen %u, digen %u, iigen %u\n",

• au_sbi(sb)->si_generation,
• au_digen(root),
• au_iigen(inode, /igflags/NULL));

• if (au_ftest_opts(a->opts.flags, REFRESH)) au_remount_refresh(sb, au_ftest_opts(a->opts.flags, REFRESH_IDOP)); diff --git a/fs/aufs/i_op.c b/fs/aufs/i_op.c index 662704a62d96..ee63f9d83f7d 100644 --- a/fs/aufs/i_op.c +++ b/fs/aufs/i_op.c @@ -1332,19 +1332,28 @@ static const char aufs_get_link(struct dentry dentry, struct inode *inode, goto out;

  err = aufs_read_lock(dentry, AuLock_IR | AuLock_GEN);

• if (unlikely(err))
• if (unlikely(err)) {
• pr_info("%pd2??, digen %u, btop %d\n",
• dentry, au_digen(dentry), au_dbtop(dentry)); goto out;

• }

  err = au_d_hashed_positive(dentry);

• if (unlikely(err))
• if (unlikely(err)) {
• pr_info("%pd2??, digen %u, btop %d\n",
• dentry, au_digen(dentry), au_dbtop(dentry)); goto out_unlock;

• }

  err = -EINVAL; inode = d_inode(dentry); bindex = au_ibtop(inode); h_inode = au_h_iptr(inode, bindex);

• if (unlikely(!h_inode->i_op->get_link))
• if (unlikely(!h_inode->i_op->get_link)) {
• pr_info("%pd2??, digen %u, btop %d\n",
• dentry, au_digen(dentry), au_dbtop(dentry)); goto out_unlock;

• }

  err = -EBUSY; h_dentry = NULL; @@ -1357,11 +1366,16 @@ static const char aufs_get_link(struct dentry dentry, struct inode *inode, h_dentry = d_find_any_alias(h_inode); if (IS_ERR(h_dentry)) { err = PTR_ERR(h_dentry);

• pr_info("%pd2??, digen %u, btop %d\n",
• dentry, au_digen(dentry), au_dbtop(dentry)); goto out_unlock; } }
• if (unlikely(!h_dentry))
• if (unlikely(!h_dentry)) {
• pr_info("%pd2??, digen %u, btop %d\n",
• dentry, au_digen(dentry), au_dbtop(dentry)); goto out_unlock;

• }

  err = 0; AuDbg("%ps\n", h_inode->i_op->get_link);

[arturpzol]

@sfjro in the aufs_debug_io_error.log file, I have included logs from the enabled debug mode in AUFS (kernel v6.10.6) along with the additional proposed logging for digen and btop. The first occurrence of the input/output error happened around the timestamp value 952.

OK then, did you run "mount --move" for your all branches before you mount aufs? I want to make sure that your branhces (/mnt/live/changes and /mnt/live/iamges/*.lzm) are living there after swtich_root.

Yes, I perform a mount --move on my branches before mounting AUFS.

[sfjro]

Artur Piechocki:

@sfjro in the aufs_debug_io_error.log file, I have included logs from the enabled debug mode in AUFS (kernel v6.10.6) along with the additional proposed logging for digen and btop. The first occurrence of the input/output error happened around the timestamp value 952.

Thanks for the log. But it looks a little weird. "mount -o remount /" should enter aufs/fsctx.c:au_fsctx_reconfigure() which contains pr_info("sigen %u, digen %u, iigen %u\n", ...) two places as previous debug patch.

I am expecting this debug log but cannot find in your aufs_debug_io_error.log. Is the log full version?

J. R. Okajima

[arturpzol]

@sfjro

The previous log had to be truncated by logrotate. Sorry for that.

I am resending the logs aufs_io_error.log , but without debugging enabled in aufs (echo 1 > /sys/module/aufs/parameters/debug) because with debugging enabled, it is very difficult to reproduce the problem due to the large amount of generated logs. My system cannot handle processing such a large number of logs.

Anyway let me know if you need the full logs with debugging enabled in aufs, and I will keep trying until I succeed.

[sfjro]

Artur Piechocki:

I am resending the logs aufs_io_error.log , but without debugging enabled in aufs (echo 1 > /sys/module/aufs/parameters/debug) because with debugging enabled, it is very difficult to reproduce the problem due to the large amount of generated logs. My system cannot handle processing such a large number of logs.

Thanx for the log. But it was not enough. Would you try this additional patch, which enables DEBUG during remount only?

J. R. Okajima

diff --git a/fs/aufs/fsctx.c b/fs/aufs/fsctx.c index 008a5aaf11e7..de4d68b19b36 100644 --- a/fs/aufs/fsctx.c +++ b/fs/aufs/fsctx.c @@ -43,6 +43,7 @@ static int au_fsctx_reconfigure(struct fs_context fc) struct inode inode; struct au_fsctx_opts *a = fc->fs_private;

+au_debug_on(); AuDbg("fc %p\n", fc);

root = fc->root;

@@ -84,6 +95,7 @@ static int au_fsctx_reconfigure(struct fs_context *fc) err = cvt_err(err); AuTraceErr(err);

+au_debug_off(); return err; }

[arturpzol]

@sfjro additional logs aufs_debug_io_error1.log with debug for remount.

Thank You

[sfjro]

Artur Piechocki:

@sfjro additional logs aufs_debug_io_error1.log with debug for remount.

Unfortunately the log is still not enough. I'm afraid several parts of the log are lost. I'd suggest you to try increasing 'log_buf_len' in your kernel command line.

Also 'cron' daemon looks invoked very frequently in a short time. Is it expected behaviour?

J. R. Okajima

[arturpzol]

@sfjro

What kind of logs do you think are missing (debug from fsctx.c file ?) The last logs were generated while skipping syslog. I'm using the dmesg -n8 && cat /proc/kmsg command, so it seems strange that log_buf_len would matter here. All kernel logs are currently shown in the terminal, then I copy the contents of the terminal and put them in a log file (additionally, I set the terminal history to infinite). I do this on purpose to bypass system services such as syslog which would not be able to write anything in the event of an input/output error.

The cron job is intentionally set to run every minute because the more commands are executed on the system during the remount, the faster I can reproduce the problem.

[sfjro]

Artur Piechocki:

What kind of logs do you think are missing (debug from fsctx.c file ?)

Mainly yes. Applying the debug patch, au_fsctx_reconfigure() prints two "sigen %d..." logs. But there is only one log for "sigen 17" in your aufs_debug_io_error1.log.

1162: aufs au_fsctx_reconfigure:80:mount[19848]: sigen 16, digen 16, iigen 16 1164: aufs au_fsctx_reconfigure:88:mount[19848]: sigen 16, digen 16, iigen 16 3069: aufs au_fsctx_reconfigure:88:mount[14731]: sigen 17, digen 17, iigen 17 16422: aufs au_fsctx_reconfigure:80:mount[14732]: sigen 18, digen 18, iigen 18 16425: aufs au_fsctx_reconfigure:88:mount[14732]: sigen 18, digen 18, iigen 18

That is the main reason why I'm afraid the log is not meaningful.

J. R. Okajima

[arturpzol]

@sfjro

I'm sending the logs again aufs_debug_io_error2.log. I set log_buf_len to 10M and made sure that each log with sigen information for a given process is duplicated.

Thank You

[sfjro]

Artur Piechocki:

I'm sending the logs again aufs_debug_io_error2.log. I set log_buf_len to 10M and made sure that each log with sigen information for a given process is duplicated.

OK thanks. But this log still looks weird. It has several "/bin/mount: Input/output error" logs, but no "aufs_get_link: err -5" log at all. I am not sure where EIO comes from. Assuming all logs were collected, EIO has to come from other than aufs. (well, it's doubtful).

Would you apply this another additional debug patch?

diff --git a/fs/fsopen.c b/fs/fsopen.c index 6593ae518115..83355c676ecf 100644 --- a/fs/fsopen.c +++ b/fs/fsopen.c @@ -266,6 +266,10 @@ static int vfs_cmd_reconfigure(struct fs_context fc) down_write(&sb->s_umount); ret = reconfigure_super(fc); up_write(&sb->s_umount); +if(ret)pr_info("%s:%d:%.s[%d]: ret %d\n",

• func, LINE,
• (int)sizeof(current->comm), current->comm, current->pid,
• ret); if (ret) { fc->phase = FS_CONTEXT_FAILED; return ret; diff --git a/fs/namespace.c b/fs/namespace.c index d3b682cb7704..a2461a5a5f09 100644 --- a/fs/namespace.c +++ b/fs/namespace.c @@ -1708,6 +1708,10 @@ static int do_umount_root(struct super_block sb) } } up_write(&sb->s_umount); +if(ret)pr_info("%s:%d:%.s[%d]: ret %d\n",
• func, LINE,
• (int)sizeof(current->comm), current->comm, current->pid,
• ret); return ret; }

@@ -2912,6 +2916,10 @@ static int do_remount(struct path *path, int ms_flags, int sb_flags, mnt_warn_timestamp_expiry(path, &mnt->mnt);

put_fs_context(fc);

+if(err)pr_info("%s:%d:%.*s[%d]: err %d\n",

• func, LINE,
• (int)sizeof(current->comm), current->comm, current->pid,
• err); return err; }

diff --git a/fs/super.c b/fs/super.c index 095ba793e10c..d2d261679d5a 100644 --- a/fs/super.c +++ b/fs/super.c @@ -1097,6 +1097,10 @@ int reconfigure_super(struct fs_context *fc)

cancel_readonly: sb_end_ro_state_change(sb); +if(retval)pr_info("%s:%d:%.*s[%d]: retval %d\n",

• func, LINE,
• (int)sizeof(current->comm), current->comm, current->pid,
• retval); return retval; }

@@ -1734,6 +1738,10 @@ int reconfigure_single(struct super_block s, ret = reconfigure_super(fc); out: put_fs_context(fc); +if(ret)pr_info("%s:%d:%.s[%d]: ret %d\n",

• func, LINE,
• (int)sizeof(current->comm), current->comm, current->pid,
• ret); return ret; }

[arturpzol]

error" logs, but no "aufs_get_link: err -5" log at all. I am not sure where EIO comes from.

Could it be that debug wasn't enabled in AUFS? As I mentioned, it's difficult to reproduce the issue when debug is enabled, but I kept trying until I succeeded, and the file aufs_debug_io_error2.log now contains another log, this time with debug enabled.

Would you apply this another additional debug patch?

I'm having a bit of a problem here: despite the patch being applied (I double-checked), there is no debug (from the last patch) information in the log. It's as if the condition is always false and never enters the pr_info function.

However, I hope that the log with debugging enabled (echo 1 > /sys/module/aufs/parameters/debug) will be now more useful.

[sfjro]

Artur Piechocki:

Could it be that debug wasn't enabled in AUFS? As I mentioned, it's difficult to reproduce the issue when debug is enabled, but I kept trying until I succeeded, and the file aufs_debug_io_error2.log now contains another log, this time with debug enabled.

Enabling debug is helpful here. Please be patient. By new aufs_debug_io_error2.log, I am narrowing down the (possible) bug. Here is a first trial to fix. Please test this patch.

I'm having a bit of a problem here: despite the patch being applied (I double-checked), there is no debug (from the last patch) information in the log. It's as if the condition is always false and never enters the pr_info function.

Ok, the must be in aufs.

J. R. Okajima

diff --git a/fs/aufs/sbinfo.c b/fs/aufs/sbinfo.c index fc1d958bcaa5..d83e13462061 100644 --- a/fs/aufs/sbinfo.c +++ b/fs/aufs/sbinfo.c @@ -239,8 +239,10 @@ int aufs_read_lock(struct dentry dentry, int flags) err = au_digen_test(dentry, au_sigen(sb)); if (!au_opt_test(au_mntflags(sb), UDBA_NONE)) AuDebugOn(!err && au_dbrange_test(dentry)); +/ else if (!err) err = au_dbrange_test(dentry); +*/ if (unlikely(err)) aufs_read_unlock(dentry, flags); }

[arturpzol]

@sfjro

Despite applying the potential fix, the problem is still reproducible. I am sending debug logs aufs_debug_io_error_with_potential_fix.log with the latest patch applied.

Please note that the issue only occurs when udba=none. When udba=notify is set, the problem does not occur.

[sfjro]

Artur Piechocki:

Despite applying the potential fix, the problem is still reproducible. I am sending debug logs aufs_debug_io_error_with_potential_fix.log with the latest patch applied.

OK, thanks for your repeated tests. Now I want you to find all the directories named 'x86_64-linux-gnu', and all the entries (regular file, symlink, etc) named 'libc.so.6' on your all branches. It is to know whether multiple entires exist or not.

And here is another possible/potential fix patch. Please try.

Please note that the issue only occurs when udba=none. When udba=notify is set, the problem does not occur.

Yes, my previous patch was meaningless here. Probably I was crazy.

J. R. Okajima

diff --git a/fs/aufs/dcsub.c b/fs/aufs/dcsub.c index 842063a3c314..1e27ba9f42ba 100644 --- a/fs/aufs/dcsub.c +++ b/fs/aufs/dcsub.c @@ -122,9 +122,9 @@ static enum d_walk_ret au_call_dpages_append(void _arg, struct dentry dentry) ret = D_WALK_CONTINUE; if (dentry->d_sb == arg->sb && !IS_ROOT(dentry)

• && au_dcount(dentry) > 0 +/* && au_dcount(dentry) > 0 && au_di(dentry)

• && (!arg->test || arg->test(dentry, arg->arg))) { +/ && (!arg->test || arg->test(dentry, arg->arg))) { arg->err = au_dpages_append(arg->dpages, dentry, GFP_ATOMIC); if (unlikely(arg->err)) ret = D_WALK_QUIT; diff --git a/fs/aufs/super.c b/fs/aufs/super.c index 07d3412e950f..10a80f4f8c22 100644 --- a/fs/aufs/super.c +++ b/fs/aufs/super.c @@ -577,7 +577,7 @@ static int au_do_refresh_d(struct dentry dentry, unsigned int sigen,

  err = 0; parent = dget_parent(dentry);

• if (!au_digen_test(parent, sigen) && au_digen_test(dentry, sigen)) {
• if (/!au_digen_test(parent, sigen) &&/ au_digen_test(dentry, sigen)) { if (d_really_is_positive(dentry)) { if (!d_is_dir(dentry)) err = au_do_refresh(dentry, /dir_flags/0,

[arturpzol]

@sfjro

Unfortunately, the proposed second fix causes a kernel panic. Here is the log aufs_panic_fix2.log

Now I want you to find all the directories named 'x86_64-linux-gnu',

I have two branches that have a directory /lib/x86_64-linux-gnu and /usr/lib/x86_64-linux-gnu with various library files.

and all the entries (regular file, symlink, etc) named 'libc.so.6' on

Only one branch has libc.so.6.

[sfjro]

Artur Piechocki:

Unfortunately, the proposed second fix causes a kernel panic. Here is the log aufs_panic_fix2.log

Ok, that was my bad. Please modify fs/aufs/dcsub.c (which is patched by my last patch) like this. (see attached)

and all the entries (regular file, symlink, etc) named 'libc.so.6' on

Only one branch has libc.so.6.

And it is a symlink on your 14th branch? What is the target, and where is it?

J. R. Okajima

diff --git a/fs/aufs/dcsub.c b/fs/aufs/dcsub.c index 842063a3c314..ee2a177b4188 100644 --- a/fs/aufs/dcsub.c +++ b/fs/aufs/dcsub.c @@ -86,7 +86,7 @@ static int au_dpages_append(struct au_dcsub_pages *dpages, dpages->ndpage++; }

• AuDebugOn(au_dcount(dentry) <= 0);
• //AuDebugOn(au_dcount(dentry) <= 0); dpage->dentries[dpage->ndentry++] = dget_dlock(dentry); return 0; / success /

@@ -122,8 +122,8 @@ static enum d_walk_ret au_call_dpages_append(void _arg, struct dentry dentry) ret = D_WALK_CONTINUE; if (dentry->d_sb == arg->sb && !IS_ROOT(dentry)

• && au_dcount(dentry) > 0
• && au_di(dentry) +/ && au_dcount(dentry) > 0 +/ && au_di(dentry) && (!arg->test || arg->test(dentry, arg->arg))) { arg->err = au_dpages_append(arg->dpages, dentry, GFP_ATOMIC); if (unlikely(arg->err))

[arturpzol]

@sfjro

And it is a symlink on your 14th branch? What is the target, and where is it?

Yes, it is symlink on 14th branch which target is libc-2.19.so. Target is also on the same 14th branch.

ls -al /lib/x86_64-linux-gnu/libc.so.6
lrwxrwxrwx 1 root root 12 May 17  2016 /lib/x86_64-linux-gnu/libc.so.6 -> libc-2.19.so

Please modify fs/aufs/dcsub.c (which is patched by my last patch) like this. (see attached)

Now it looks like the fix is ​​working and the issue is gone. Is this the target fix or just for analysis purposes?