failed open: No data available

failed open: No data available

[Michael D Labriola]

I'm sporatically getting "no data available" as a reason to fail to
open files on an overlay mount.  Most obvious is during ln of backup
file during apt install.  Only seems to happen on copy_up from lower
layer.  Lower layer is squashfs (I've seen it happen with both the
default zlib and also zstd compression), upper is EXT4.

I've only bumped into this problem recently with 5.9+ kernels.  I'm
gonna go see if I can reproduce in some older kernels I still have
installed.

Anyone else reporting this?

-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Michael D Labriola]

On Mon, Dec 14, 2020 at 6:06 PM Michael D Labriola <michael.d.labriola@gmail.com> wrote:
>
> I'm sporatically getting "no data available" as a reason to fail to
> open files on an overlay mount.  Most obvious is during ln of backup
> file during apt install.  Only seems to happen on copy_up from lower
> layer.  Lower layer is squashfs (I've seen it happen with both the
> default zlib and also zstd compression), upper is EXT4.
>
> I've only bumped into this problem recently with 5.9+ kernels.  I'm
> gonna go see if I can reproduce in some older kernels I still have
> installed.

Rebooting into 5.4 made the problem go away and I can apt upgrade
w/out any problems.  Rebooting an affected virtual machine into 5.8
also fixed the problem, so it looks to be something introduced in 5.9.

I suppose I should try 5.10 and see if this problem has already been
fixed.

>
> Anyone else reporting this?


-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Amir Goldstein]

On Tue, Dec 15, 2020 at 5:33 PM Michael D Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Mon, Dec 14, 2020 at 6:06 PM Michael D Labriola <michael.d.labriola@gmail.com> wrote:
> >
> > I'm sporatically getting "no data available" as a reason to fail to
> > open files on an overlay mount.  Most obvious is during ln of backup
> > file during apt install.  Only seems to happen on copy_up from lower

How do you know that? Do you have some more tracing info?

> > layer.  Lower layer is squashfs (I've seen it happen with both the
> > default zlib and also zstd compression), upper is EXT4.
> >
> > I've only bumped into this problem recently with 5.9+ kernels.  I'm
> > gonna go see if I can reproduce in some older kernels I still have
> > installed.
>
> Rebooting into 5.4 made the problem go away and I can apt upgrade
> w/out any problems.  Rebooting an affected virtual machine into 5.8
> also fixed the problem, so it looks to be something introduced in 5.9.

There are no overlayfs changes v5.8..v5.9 nor squashfs changes.
Are you sure that your reproducer is reliable enough for the bisection?
If it is, please try to bisect the offending commit because I have no idea
where it may be.

>
> I suppose I should try 5.10 and see if this problem has already been
> fixed.
>

Wouldn't hurt.

Thanks,
Amir.

Re: failed open: No data available

[Michael Labriola]

On Tue, Dec 15, 2020 at 11:31 AM Amir Goldstein <amir73il@gmail.com> wrote:
>
> On Tue, Dec 15, 2020 at 5:33 PM Michael D Labriola
> <michael.d.labriola@gmail.com> wrote:
> >
> > On Mon, Dec 14, 2020 at 6:06 PM Michael D Labriola <michael.d.labriola@gmail.com> wrote:
> > >
> > > I'm sporatically getting "no data available" as a reason to fail to
> > > open files on an overlay mount.  Most obvious is during ln of backup
> > > file during apt install.  Only seems to happen on copy_up from lower
>
> How do you know that? Do you have some more tracing info?

I haven't done any tracing, perhaps I overstated.  The problem I'm
seeing only happens when overlayfs goes to create a copy of a lower
layer file in the upper layer.  When the problem occurs, it's always
on a file that exists on lower but not upper, and is about to be
modified.

>
> > > layer.  Lower layer is squashfs (I've seen it happen with both the
> > > default zlib and also zstd compression), upper is EXT4.
> > >
> > > I've only bumped into this problem recently with 5.9+ kernels.  I'm
> > > gonna go see if I can reproduce in some older kernels I still have
> > > installed.
> >
> > Rebooting into 5.4 made the problem go away and I can apt upgrade
> > w/out any problems.  Rebooting an affected virtual machine into 5.8
> > also fixed the problem, so it looks to be something introduced in 5.9.
>
> There are no overlayfs changes v5.8..v5.9 nor squashfs changes.
> Are you sure that your reproducer is reliable enough for the bisection?
> If it is, please try to bisect the offending commit because I have no idea
> where it may be.

I'm having a hard time reproducing the problem.  It's only happening
frequently enough for me to be pretty sure it's a bug.  I've been
using an overlay of squashfs/EXT4 on my development laptop for over a
year, using the squashfs image to fork off disposable virtual machines
for testing.  It's worked flawlessly up until I started testing w/
5.9... but I couldn't correlate my problems to anything specific until
just recently.

More than once now, my host system or a virtual machine has randomly
failed to process an apt update.  Either a backup hardlink creation
fails or some other processing command fails, always with an error
message of "No data available", which makes no sense to me.  Booting
back into my 5.4 or 5.8 kernel and performing the upgrade, then back
into my 5.9 kernel alleviates the problem until it happens again on
some other package.

I have also seen "No data available" pop up in seemingly random
places.  For example, yesterday postfix refused to send mail, and when
I went to restart the service I got this:

postfix/bounce[24836]: fatal: open lock file pid/unix.bounce: cannot
open file: No data available

Today, in 5.9.14, I did an apt upgrade which didn't fail creating
backup files, but instead failed doing a postinstall task like this:

Setting up sudo (1.8.21p2-3ubuntu1.3) ...
chown: changing ownership of '/etc/sudoers': No data available
dpkg: error processing package sudo (--configure):
 installed sudo package post-installation script subprocess returned
error exit status 1

Rebooting the vm resulted in the same problem.  Booting into 5.8.18,
apt upgrade succeeded.  Then I rebooted back into 5.9.

>
> >
> > I suppose I should try 5.10 and see if this problem has already been
> > fixed.
> >
>
> Wouldn't hurt.

Trying that shortly.  Also trying to figure out how to force the
problem to happen...  I'll never get to the bottom of it at this rate.
I was really hoping somebody on the list would recognize the
problem...  :-/  Just my luck.

> Thanks,
> Amir.

-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Amir Goldstein]

On Tue, Dec 15, 2020 at 9:29 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Tue, Dec 15, 2020 at 11:31 AM Amir Goldstein <amir73il@gmail.com> wrote:
> >
> > On Tue, Dec 15, 2020 at 5:33 PM Michael D Labriola
> > <michael.d.labriola@gmail.com> wrote:
> > >
> > > On Mon, Dec 14, 2020 at 6:06 PM Michael D Labriola <michael.d.labriola@gmail.com> wrote:
> > > >
> > > > I'm sporatically getting "no data available" as a reason to fail to
> > > > open files on an overlay mount.  Most obvious is during ln of backup
> > > > file during apt install.  Only seems to happen on copy_up from lower
> >
> > How do you know that? Do you have some more tracing info?
>
> I haven't done any tracing, perhaps I overstated.  The problem I'm
> seeing only happens when overlayfs goes to create a copy of a lower
> layer file in the upper layer.  When the problem occurs, it's always
> on a file that exists on lower but not upper, and is about to be
> modified.
>
> >
> > > > layer.  Lower layer is squashfs (I've seen it happen with both the
> > > > default zlib and also zstd compression), upper is EXT4.
> > > >
> > > > I've only bumped into this problem recently with 5.9+ kernels.  I'm
> > > > gonna go see if I can reproduce in some older kernels I still have
> > > > installed.
> > >
> > > Rebooting into 5.4 made the problem go away and I can apt upgrade
> > > w/out any problems.  Rebooting an affected virtual machine into 5.8
> > > also fixed the problem, so it looks to be something introduced in 5.9.
> >
> > There are no overlayfs changes v5.8..v5.9 nor squashfs changes.
> > Are you sure that your reproducer is reliable enough for the bisection?
> > If it is, please try to bisect the offending commit because I have no idea
> > where it may be.
>
> I'm having a hard time reproducing the problem.  It's only happening
> frequently enough for me to be pretty sure it's a bug.  I've been
> using an overlay of squashfs/EXT4 on my development laptop for over a
> year, using the squashfs image to fork off disposable virtual machines
> for testing.  It's worked flawlessly up until I started testing w/
> 5.9... but I couldn't correlate my problems to anything specific until
> just recently.
>
> More than once now, my host system or a virtual machine has randomly
> failed to process an apt update.  Either a backup hardlink creation
> fails or some other processing command fails, always with an error
> message of "No data available", which makes no sense to me.  Booting
> back into my 5.4 or 5.8 kernel and performing the upgrade, then back
> into my 5.9 kernel alleviates the problem until it happens again on
> some other package.
>
> I have also seen "No data available" pop up in seemingly random
> places.  For example, yesterday postfix refused to send mail, and when
> I went to restart the service I got this:
>
> postfix/bounce[24836]: fatal: open lock file pid/unix.bounce: cannot
> open file: No data available
>
> Today, in 5.9.14, I did an apt upgrade which didn't fail creating
> backup files, but instead failed doing a postinstall task like this:
>
> Setting up sudo (1.8.21p2-3ubuntu1.3) ...
> chown: changing ownership of '/etc/sudoers': No data available
> dpkg: error processing package sudo (--configure):
>  installed sudo package post-installation script subprocess returned
> error exit status 1
>
> Rebooting the vm resulted in the same problem.  Booting into 5.8.18,
> apt upgrade succeeded.  Then I rebooted back into 5.9.
>
> >
> > >
> > > I suppose I should try 5.10 and see if this problem has already been
> > > fixed.
> > >
> >
> > Wouldn't hurt.
>
> Trying that shortly.  Also trying to figure out how to force the
> problem to happen...  I'll never get to the bottom of it at this rate.
> I was really hoping somebody on the list would recognize the
> problem...  :-/  Just my luck.

The problem rings a bell, but I would expect it had something to
do with the change:
a888db310195 ovl: fix regression with re-formatted lower squashfs

From v5.8.0 that was also applied to stable v5.4.y, so there is no
match to your report.

'No data available' means ENODATA error from getxattr()
which is not expected to be returned from operations like chmod() and
link() as you reported that is why the message makes no sense.
I did not find any internal vfs_getxattr() call in overlayfs code where
ENODATA can be exposed to the caller.

I did find that ENODATA could be exposed from lookup via a call to
ovl_verify_origin(), but that implies that the index feature is enabled
and is expected to print "overlayfs: failed to verify..." to kmsg.
We should probably replace the use visible lookup error with EIO,
but that in itself won't help users to understand the problem.

Do you use an existing upper (ext4) dir with a lower squashfs image that
is not the original image used when first mounting overlay with that upper dir
AND enable the index=on feature?
I still don't see how that would be a regression of kernel v5.8 and certainly
not v5.9.

Do you use any non default overlay config/mount options?

Please share the output of '/proc/self/mountinfo' with mounted overlay
and 'grep Y /sys/module/overlay/parameters/*'

Do you see any "overlayfs:" logs in kmsg?

If you do not need nfs export, you could try to create squashfs image with
-no-exports as a possible workaround.

Thanks,
Amir.

Re: failed open: No data available

[Michael Labriola]

On Wed, Dec 16, 2020 at 1:05 AM Amir Goldstein <amir73il@gmail.com> wrote:
>
> On Tue, Dec 15, 2020 at 9:29 PM Michael Labriola
> <michael.d.labriola@gmail.com> wrote:
> >
> > On Tue, Dec 15, 2020 at 11:31 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > >
> > > On Tue, Dec 15, 2020 at 5:33 PM Michael D Labriola
> > > <michael.d.labriola@gmail.com> wrote:
> > > >
> > > > On Mon, Dec 14, 2020 at 6:06 PM Michael D Labriola <michael.d.labriola@gmail.com> wrote:
> > > > >
> > > > > I'm sporatically getting "no data available" as a reason to fail to
> > > > > open files on an overlay mount.  Most obvious is during ln of backup
> > > > > file during apt install.  Only seems to happen on copy_up from lower
> > >
> > > How do you know that? Do you have some more tracing info?
> >
> > I haven't done any tracing, perhaps I overstated.  The problem I'm
> > seeing only happens when overlayfs goes to create a copy of a lower
> > layer file in the upper layer.  When the problem occurs, it's always
> > on a file that exists on lower but not upper, and is about to be
> > modified.
> >
> > >
> > > > > layer.  Lower layer is squashfs (I've seen it happen with both the
> > > > > default zlib and also zstd compression), upper is EXT4.
> > > > >
> > > > > I've only bumped into this problem recently with 5.9+ kernels.  I'm
> > > > > gonna go see if I can reproduce in some older kernels I still have
> > > > > installed.
> > > >
> > > > Rebooting into 5.4 made the problem go away and I can apt upgrade
> > > > w/out any problems.  Rebooting an affected virtual machine into 5.8
> > > > also fixed the problem, so it looks to be something introduced in 5.9.
> > >
> > > There are no overlayfs changes v5.8..v5.9 nor squashfs changes.
> > > Are you sure that your reproducer is reliable enough for the bisection?
> > > If it is, please try to bisect the offending commit because I have no idea
> > > where it may be.
> >
> > I'm having a hard time reproducing the problem.  It's only happening
> > frequently enough for me to be pretty sure it's a bug.  I've been
> > using an overlay of squashfs/EXT4 on my development laptop for over a
> > year, using the squashfs image to fork off disposable virtual machines
> > for testing.  It's worked flawlessly up until I started testing w/
> > 5.9... but I couldn't correlate my problems to anything specific until
> > just recently.
> >
> > More than once now, my host system or a virtual machine has randomly
> > failed to process an apt update.  Either a backup hardlink creation
> > fails or some other processing command fails, always with an error
> > message of "No data available", which makes no sense to me.  Booting
> > back into my 5.4 or 5.8 kernel and performing the upgrade, then back
> > into my 5.9 kernel alleviates the problem until it happens again on
> > some other package.
> >
> > I have also seen "No data available" pop up in seemingly random
> > places.  For example, yesterday postfix refused to send mail, and when
> > I went to restart the service I got this:
> >
> > postfix/bounce[24836]: fatal: open lock file pid/unix.bounce: cannot
> > open file: No data available
> >
> > Today, in 5.9.14, I did an apt upgrade which didn't fail creating
> > backup files, but instead failed doing a postinstall task like this:
> >
> > Setting up sudo (1.8.21p2-3ubuntu1.3) ...
> > chown: changing ownership of '/etc/sudoers': No data available
> > dpkg: error processing package sudo (--configure):
> >  installed sudo package post-installation script subprocess returned
> > error exit status 1
> >
> > Rebooting the vm resulted in the same problem.  Booting into 5.8.18,
> > apt upgrade succeeded.  Then I rebooted back into 5.9.
> >
> > >
> > > >
> > > > I suppose I should try 5.10 and see if this problem has already been
> > > > fixed.
> > > >
> > >
> > > Wouldn't hurt.
> >
> > Trying that shortly.  Also trying to figure out how to force the
> > problem to happen...  I'll never get to the bottom of it at this rate.
> > I was really hoping somebody on the list would recognize the
> > problem...  :-/  Just my luck.
>
> The problem rings a bell, but I would expect it had something to
> do with the change:
> a888db310195 ovl: fix regression with re-formatted lower squashfs
>
> From v5.8.0 that was also applied to stable v5.4.y, so there is no
> match to your report.
>
> 'No data available' means ENODATA error from getxattr()
> which is not expected to be returned from operations like chmod() and
> link() as you reported that is why the message makes no sense.
> I did not find any internal vfs_getxattr() call in overlayfs code where
> ENODATA can be exposed to the caller.
>
> I did find that ENODATA could be exposed from lookup via a call to
> ovl_verify_origin(), but that implies that the index feature is enabled
> and is expected to print "overlayfs: failed to verify..." to kmsg.
> We should probably replace the use visible lookup error with EIO,
> but that in itself won't help users to understand the problem.
>
> Do you use an existing upper (ext4) dir with a lower squashfs image that
> is not the original image used when first mounting overlay with that upper dir
> AND enable the index=on feature?

99% sure the answer to that is No and No.  I've been reusing an existing
EXT4 filesystem, but creating fresh new upper dirs prior to first mount
once in a while when I create a new squashfs image for the lower layer.  I
suppose it is possible that I goofed at some point and left cruft in
upper...  but I doubt it.  And I haven't used index=on or any other special
options, as far as I know.

> I still don't see how that would be a regression of kernel v5.8 and certainly
> not v5.9.

Me either...  maybe it's a freak accident?  Otherwise undetected corruption
of the upper EXT4 filesystem?  I guess that seems unlikely, because it all
of a sudden started effecting multiple virtual machines and my host
system...

> Do you use any non default overlay config/mount options?

Nope.

>
> Please share the output of '/proc/self/mountinfo' with mounted overlay

26 31 253:0 / /mnt/root-true rw,relatime shared:4 - ext4 /dev/root rw
27 31 253:1 / /mnt/sqsh_layerdev ro,relatime shared:2 - ext4
/dev/sqsh_layerdev ro
28 31 7:0 / /mnt/sqsh_layer-aldarion-new-zstd ro,relatime shared:3 -
squashfs /dev/sqsh_layer-aldarion-new-zstd ro
31 1 0:24 / / rw,relatime shared:1 - overlay rootfs
rw,lowerdir=/sqsh_layer-aldarion-new-zstd,upperdir=/tmproot/upper/upper,workdir=/tmproot/upper/work
32 31 0:23 / /sys rw,nosuid,nodev,noexec,relatime shared:5 - sysfs sysfs rw
33 31 0:27 / /proc rw,nosuid,nodev,noexec,relatime shared:13 - proc proc rw
34 31 0:5 / /dev rw,nosuid shared:14 - devtmpfs devtmpfs
rw,size=3879828k,nr_inodes=969957,mode=755
35 32 0:7 / /sys/kernel/security rw,nosuid,nodev,noexec,relatime
shared:6 - securityfs securityfs rw
37 32 0:20 / /sys/fs/selinux rw,relatime shared:7 - selinuxfs selinuxfs rw
36 34 0:28 / /dev/shm rw,nosuid,nodev shared:15 - tmpfs tmpfs rw
38 34 0:29 / /dev/pts rw,nosuid,noexec,relatime shared:16 - devpts
devpts rw,gid=5,mode=620,ptmxmode=000
39 31 0:30 / /run rw,nosuid,nodev shared:17 - tmpfs tmpfs rw,mode=755
40 39 0:31 / /run/lock rw,nosuid,nodev,noexec,relatime shared:18 -
tmpfs tmpfs rw,size=5120k
41 32 0:32 / /sys/fs/cgroup ro,nosuid,nodev,noexec shared:8 - tmpfs
tmpfs ro,mode=755
42 41 0:33 / /sys/fs/cgroup/unified rw,nosuid,nodev,noexec,relatime
shared:9 - cgroup2 cgroup rw,nsdelegate
43 41 0:34 / /sys/fs/cgroup/systemd rw,nosuid,nodev,noexec,relatime
shared:10 - cgroup cgroup rw,xattr,name=systemd
44 32 0:35 / /sys/fs/pstore rw,nosuid,nodev,noexec,relatime shared:11
- pstore pstore rw
45 32 0:36 / /sys/firmware/efi/efivars rw,nosuid,nodev,noexec,relatime
shared:12 - efivarfs efivarfs rw
46 41 0:37 / /sys/fs/cgroup/cpuset rw,nosuid,nodev,noexec,relatime
shared:19 - cgroup cgroup rw,cpuset
47 41 0:38 / /sys/fs/cgroup/net_cls,net_prio
rw,nosuid,nodev,noexec,relatime shared:20 - cgroup cgroup
rw,net_cls,net_prio
48 41 0:39 / /sys/fs/cgroup/cpu,cpuacct
rw,nosuid,nodev,noexec,relatime shared:21 - cgroup cgroup
rw,cpu,cpuacct
49 41 0:40 / /sys/fs/cgroup/devices rw,nosuid,nodev,noexec,relatime
shared:22 - cgroup cgroup rw,devices
50 33 0:41 / /proc/sys/fs/binfmt_misc rw,relatime shared:23 - autofs
systemd-1 rw,fd=27,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=6074
51 34 0:19 / /dev/mqueue rw,relatime shared:24 - mqueue mqueue rw
52 32 0:6 / /sys/kernel/debug rw,relatime shared:25 - debugfs debugfs rw
53 34 0:42 / /dev/hugepages rw,relatime shared:26 - hugetlbfs
hugetlbfs rw,pagesize=2M
54 39 0:43 / /run/rpc_pipefs rw,relatime shared:27 - rpc_pipefs sunrpc rw
86 32 0:21 / /sys/kernel/config rw,relatime shared:28 - configfs configfs rw
90 31 259:1 / /boot rw,relatime shared:29 - vfat /dev/nvme0n1p1
rw,fmask=0022,dmask=0022,codepage=437,iocharset=ascii,shortname=mixed,errors=remount-ro
92 31 253:2 / /scrap rw,noatime shared:30 - ext4 /dev/mapper/vg99-scrap rw
467 39 0:50 / /run/user/121 rw,nosuid,nodev,relatime shared:316 -
tmpfs tmpfs rw,size=778124k,mode=700,uid=121,gid=125
644 39 0:52 / /run/user/1200 rw,nosuid,nodev,relatime shared:447 -
tmpfs tmpfs rw,size=778124k,mode=700,uid=1200,gid=1200
660 644 0:53 / /run/user/1200/gvfs rw,nosuid,nodev,relatime shared:459
- fuse.gvfsd-fuse gvfsd-fuse rw,user_id=1200,group_id=1200
676 32 0:54 / /sys/fs/fuse/connections rw,relatime shared:471 -
fusectl fusectl rw
382 39 0:49 / /run/user/0 rw,nosuid,nodev,relatime shared:239 - tmpfs
tmpfs rw,size=778124k,mode=700

> and 'grep Y /sys/module/overlay/parameters/*'

/sys/module/overlay/parameters/redirect_always_follow:Y
/sys/module/overlay/parameters/xino_auto:Y

>
> Do you see any "overlayfs:" logs in kmsg?

[    4.828299] overlayfs: "xino" feature enabled using 32 upper inode bits.

>
> If you do not need nfs export, you could try to create squashfs image with
> -no-exports as a possible workaround.

If the problem persists, I will try that.  I'm not exporting anything
from the overlay.

-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Michael Labriola]

[-- Attachment #1: Type: text/plain, Size: 12344 bytes --]

On Wed, Dec 16, 2020 at 2:49 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Wed, Dec 16, 2020 at 1:05 AM Amir Goldstein <amir73il@gmail.com> wrote:
> >
> > On Tue, Dec 15, 2020 at 9:29 PM Michael Labriola
> > <michael.d.labriola@gmail.com> wrote:
> > >
> > > On Tue, Dec 15, 2020 at 11:31 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > >
> > > > On Tue, Dec 15, 2020 at 5:33 PM Michael D Labriola
> > > > <michael.d.labriola@gmail.com> wrote:
> > > > >
> > > > > On Mon, Dec 14, 2020 at 6:06 PM Michael D Labriola <michael.d.labriola@gmail.com> wrote:
> > > > > >
> > > > > > I'm sporatically getting "no data available" as a reason to fail to
> > > > > > open files on an overlay mount.  Most obvious is during ln of backup
> > > > > > file during apt install.  Only seems to happen on copy_up from lower
> > > >
> > > > How do you know that? Do you have some more tracing info?
> > >
> > > I haven't done any tracing, perhaps I overstated.  The problem I'm
> > > seeing only happens when overlayfs goes to create a copy of a lower
> > > layer file in the upper layer.  When the problem occurs, it's always
> > > on a file that exists on lower but not upper, and is about to be
> > > modified.
> > >
> > > >
> > > > > > layer.  Lower layer is squashfs (I've seen it happen with both the
> > > > > > default zlib and also zstd compression), upper is EXT4.
> > > > > >
> > > > > > I've only bumped into this problem recently with 5.9+ kernels.  I'm
> > > > > > gonna go see if I can reproduce in some older kernels I still have
> > > > > > installed.
> > > > >
> > > > > Rebooting into 5.4 made the problem go away and I can apt upgrade
> > > > > w/out any problems.  Rebooting an affected virtual machine into 5.8
> > > > > also fixed the problem, so it looks to be something introduced in 5.9.
> > > >
> > > > There are no overlayfs changes v5.8..v5.9 nor squashfs changes.
> > > > Are you sure that your reproducer is reliable enough for the bisection?
> > > > If it is, please try to bisect the offending commit because I have no idea
> > > > where it may be.
> > >
> > > I'm having a hard time reproducing the problem.  It's only happening
> > > frequently enough for me to be pretty sure it's a bug.  I've been
> > > using an overlay of squashfs/EXT4 on my development laptop for over a
> > > year, using the squashfs image to fork off disposable virtual machines
> > > for testing.  It's worked flawlessly up until I started testing w/
> > > 5.9... but I couldn't correlate my problems to anything specific until
> > > just recently.
> > >
> > > More than once now, my host system or a virtual machine has randomly
> > > failed to process an apt update.  Either a backup hardlink creation
> > > fails or some other processing command fails, always with an error
> > > message of "No data available", which makes no sense to me.  Booting
> > > back into my 5.4 or 5.8 kernel and performing the upgrade, then back
> > > into my 5.9 kernel alleviates the problem until it happens again on
> > > some other package.
> > >
> > > I have also seen "No data available" pop up in seemingly random
> > > places.  For example, yesterday postfix refused to send mail, and when
> > > I went to restart the service I got this:
> > >
> > > postfix/bounce[24836]: fatal: open lock file pid/unix.bounce: cannot
> > > open file: No data available
> > >
> > > Today, in 5.9.14, I did an apt upgrade which didn't fail creating
> > > backup files, but instead failed doing a postinstall task like this:
> > >
> > > Setting up sudo (1.8.21p2-3ubuntu1.3) ...
> > > chown: changing ownership of '/etc/sudoers': No data available
> > > dpkg: error processing package sudo (--configure):
> > >  installed sudo package post-installation script subprocess returned
> > > error exit status 1
> > >
> > > Rebooting the vm resulted in the same problem.  Booting into 5.8.18,
> > > apt upgrade succeeded.  Then I rebooted back into 5.9.
> > >
> > > >
> > > > >
> > > > > I suppose I should try 5.10 and see if this problem has already been
> > > > > fixed.
> > > > >
> > > >
> > > > Wouldn't hurt.
> > >
> > > Trying that shortly.  Also trying to figure out how to force the
> > > problem to happen...  I'll never get to the bottom of it at this rate.
> > > I was really hoping somebody on the list would recognize the
> > > problem...  :-/  Just my luck.
> >
> > The problem rings a bell, but I would expect it had something to
> > do with the change:
> > a888db310195 ovl: fix regression with re-formatted lower squashfs
> >
> > From v5.8.0 that was also applied to stable v5.4.y, so there is no
> > match to your report.
> >
> > 'No data available' means ENODATA error from getxattr()
> > which is not expected to be returned from operations like chmod() and
> > link() as you reported that is why the message makes no sense.
> > I did not find any internal vfs_getxattr() call in overlayfs code where
> > ENODATA can be exposed to the caller.
> >
> > I did find that ENODATA could be exposed from lookup via a call to
> > ovl_verify_origin(), but that implies that the index feature is enabled
> > and is expected to print "overlayfs: failed to verify..." to kmsg.
> > We should probably replace the use visible lookup error with EIO,
> > but that in itself won't help users to understand the problem.
> >
> > Do you use an existing upper (ext4) dir with a lower squashfs image that
> > is not the original image used when first mounting overlay with that upper dir
> > AND enable the index=on feature?
>
> 99% sure the answer to that is No and No.  I've been reusing an existing
> EXT4 filesystem, but creating fresh new upper dirs prior to first mount
> once in a while when I create a new squashfs image for the lower layer.  I
> suppose it is possible that I goofed at some point and left cruft in
> upper...  but I doubt it.  And I haven't used index=on or any other special
> options, as far as I know.
>
> > I still don't see how that would be a regression of kernel v5.8 and certainly
> > not v5.9.
>
> Me either...  maybe it's a freak accident?  Otherwise undetected corruption
> of the upper EXT4 filesystem?  I guess that seems unlikely, because it all
> of a sudden started effecting multiple virtual machines and my host
> system...
>
> > Do you use any non default overlay config/mount options?
>
> Nope.
>
> >
> > Please share the output of '/proc/self/mountinfo' with mounted overlay
>
> 26 31 253:0 / /mnt/root-true rw,relatime shared:4 - ext4 /dev/root rw
> 27 31 253:1 / /mnt/sqsh_layerdev ro,relatime shared:2 - ext4
> /dev/sqsh_layerdev ro
> 28 31 7:0 / /mnt/sqsh_layer-aldarion-new-zstd ro,relatime shared:3 -
> squashfs /dev/sqsh_layer-aldarion-new-zstd ro
> 31 1 0:24 / / rw,relatime shared:1 - overlay rootfs
> rw,lowerdir=/sqsh_layer-aldarion-new-zstd,upperdir=/tmproot/upper/upper,workdir=/tmproot/upper/work
> 32 31 0:23 / /sys rw,nosuid,nodev,noexec,relatime shared:5 - sysfs sysfs rw
> 33 31 0:27 / /proc rw,nosuid,nodev,noexec,relatime shared:13 - proc proc rw
> 34 31 0:5 / /dev rw,nosuid shared:14 - devtmpfs devtmpfs
> rw,size=3879828k,nr_inodes=969957,mode=755
> 35 32 0:7 / /sys/kernel/security rw,nosuid,nodev,noexec,relatime
> shared:6 - securityfs securityfs rw
> 37 32 0:20 / /sys/fs/selinux rw,relatime shared:7 - selinuxfs selinuxfs rw
> 36 34 0:28 / /dev/shm rw,nosuid,nodev shared:15 - tmpfs tmpfs rw
> 38 34 0:29 / /dev/pts rw,nosuid,noexec,relatime shared:16 - devpts
> devpts rw,gid=5,mode=620,ptmxmode=000
> 39 31 0:30 / /run rw,nosuid,nodev shared:17 - tmpfs tmpfs rw,mode=755
> 40 39 0:31 / /run/lock rw,nosuid,nodev,noexec,relatime shared:18 -
> tmpfs tmpfs rw,size=5120k
> 41 32 0:32 / /sys/fs/cgroup ro,nosuid,nodev,noexec shared:8 - tmpfs
> tmpfs ro,mode=755
> 42 41 0:33 / /sys/fs/cgroup/unified rw,nosuid,nodev,noexec,relatime
> shared:9 - cgroup2 cgroup rw,nsdelegate
> 43 41 0:34 / /sys/fs/cgroup/systemd rw,nosuid,nodev,noexec,relatime
> shared:10 - cgroup cgroup rw,xattr,name=systemd
> 44 32 0:35 / /sys/fs/pstore rw,nosuid,nodev,noexec,relatime shared:11
> - pstore pstore rw
> 45 32 0:36 / /sys/firmware/efi/efivars rw,nosuid,nodev,noexec,relatime
> shared:12 - efivarfs efivarfs rw
> 46 41 0:37 / /sys/fs/cgroup/cpuset rw,nosuid,nodev,noexec,relatime
> shared:19 - cgroup cgroup rw,cpuset
> 47 41 0:38 / /sys/fs/cgroup/net_cls,net_prio
> rw,nosuid,nodev,noexec,relatime shared:20 - cgroup cgroup
> rw,net_cls,net_prio
> 48 41 0:39 / /sys/fs/cgroup/cpu,cpuacct
> rw,nosuid,nodev,noexec,relatime shared:21 - cgroup cgroup
> rw,cpu,cpuacct
> 49 41 0:40 / /sys/fs/cgroup/devices rw,nosuid,nodev,noexec,relatime
> shared:22 - cgroup cgroup rw,devices
> 50 33 0:41 / /proc/sys/fs/binfmt_misc rw,relatime shared:23 - autofs
> systemd-1 rw,fd=27,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=6074
> 51 34 0:19 / /dev/mqueue rw,relatime shared:24 - mqueue mqueue rw
> 52 32 0:6 / /sys/kernel/debug rw,relatime shared:25 - debugfs debugfs rw
> 53 34 0:42 / /dev/hugepages rw,relatime shared:26 - hugetlbfs
> hugetlbfs rw,pagesize=2M
> 54 39 0:43 / /run/rpc_pipefs rw,relatime shared:27 - rpc_pipefs sunrpc rw
> 86 32 0:21 / /sys/kernel/config rw,relatime shared:28 - configfs configfs rw
> 90 31 259:1 / /boot rw,relatime shared:29 - vfat /dev/nvme0n1p1
> rw,fmask=0022,dmask=0022,codepage=437,iocharset=ascii,shortname=mixed,errors=remount-ro
> 92 31 253:2 / /scrap rw,noatime shared:30 - ext4 /dev/mapper/vg99-scrap rw
> 467 39 0:50 / /run/user/121 rw,nosuid,nodev,relatime shared:316 -
> tmpfs tmpfs rw,size=778124k,mode=700,uid=121,gid=125
> 644 39 0:52 / /run/user/1200 rw,nosuid,nodev,relatime shared:447 -
> tmpfs tmpfs rw,size=778124k,mode=700,uid=1200,gid=1200
> 660 644 0:53 / /run/user/1200/gvfs rw,nosuid,nodev,relatime shared:459
> - fuse.gvfsd-fuse gvfsd-fuse rw,user_id=1200,group_id=1200
> 676 32 0:54 / /sys/fs/fuse/connections rw,relatime shared:471 -
> fusectl fusectl rw
> 382 39 0:49 / /run/user/0 rw,nosuid,nodev,relatime shared:239 - tmpfs
> tmpfs rw,size=778124k,mode=700
>
> > and 'grep Y /sys/module/overlay/parameters/*'
>
> /sys/module/overlay/parameters/redirect_always_follow:Y
> /sys/module/overlay/parameters/xino_auto:Y
>
> >
> > Do you see any "overlayfs:" logs in kmsg?
>
> [    4.828299] overlayfs: "xino" feature enabled using 32 upper inode bits.
>
> >
> > If you do not need nfs export, you could try to create squashfs image with
> > -no-exports as a possible workaround.
>
> If the problem persists, I will try that.  I'm not exporting anything
> from the overlay.

Ok, I can reproduce the problem 100% of the time using the attached
squashfs image in 5.9 or 5.10.  In 5.8.18 and 5.4.83, everything works
just fine.

 mkdir -p t tt ttt
 mount borky2.sqsh t
 mount -t tmpfs tmp tt
 mkdir -p tt/upper/{upper,work}
 mount -t overlay -o \
    lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
[ 1685.825956] overlayfs: "xino" feature enabled using 2 upper inode bits.

 echo hello there > ttt/FOO
zsh: no data available: ttt/FOO

 echo hello there > ttt/BAR
for some reason, that file is editable

 touch ttt/*
touch: cannot touch 'ttt/BAZ': No data available
touch: cannot touch 'ttt/FOO': No data available
touch: cannot touch 'ttt/FOO-symlink': No data available

Things look completely broken now that I'm looking this closely at a
fresh overlay... I'm honestly surprised my system was usable at all.
I guess most of the files on my lower layer had already been
upgraded prior to me starting to use the 5.9 kernel.

I also tried creating a squashfs file w/ -no-exports...  exact same results.

In case it helps, here are the relevant kernel config items:

CONFIG_OVERLAY_FS=y
# CONFIG_OVERLAY_FS_REDIRECT_DIR is not set
CONFIG_OVERLAY_FS_REDIRECT_ALWAYS_FOLLOW=y
# CONFIG_OVERLAY_FS_INDEX is not set
CONFIG_OVERLAY_FS_XINO_AUTO=y
# CONFIG_OVERLAY_FS_METACOPY is not set

CONFIG_SQUASHFS=y
# CONFIG_SQUASHFS_FILE_CACHE is not set
CONFIG_SQUASHFS_FILE_DIRECT=y
# CONFIG_SQUASHFS_DECOMP_SINGLE is not set
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU=y
CONFIG_SQUASHFS_XATTR=y
CONFIG_SQUASHFS_ZLIB=y
CONFIG_SQUASHFS_LZ4=y
CONFIG_SQUASHFS_LZO=y
CONFIG_SQUASHFS_XZ=y
CONFIG_SQUASHFS_ZSTD=y
# CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
# CONFIG_SQUASHFS_EMBEDDED is not set
CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3


-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

[-- Attachment #2: borky2.sqsh --]
[-- Type: application/octet-stream, Size: 4096 bytes --]

Re: failed open: No data available

[Amir Goldstein]

> > > and 'grep Y /sys/module/overlay/parameters/*'
> >
> > /sys/module/overlay/parameters/redirect_always_follow:Y
> > /sys/module/overlay/parameters/xino_auto:Y

That's likely the reason that you are affected.
If you do not need the xino feature, you can set this to N or mount with
xino=off your system should be good.

As the commit a888db3101 message says:

    To avoid the reported regression while still allowing the new features
    with single lower squashfs, do not allow decoding origin with lower null
    uuid unless user opted-in to one of the new features that require
    following the lower inode of non-dir upper (index, xino, metacopy).

You or someone related to your distro opted-in to xino by
CONFIG_OVERLAY_FS_XINO_AUTO=y

which is smart to do IMO, but it probably exposed a bug.

I still do not understand what the bug is, but please try the workaround.

> >
> > >
> > > Do you see any "overlayfs:" logs in kmsg?
> >
> > [    4.828299] overlayfs: "xino" feature enabled using 32 upper inode bits.
> >
> > >
> > > If you do not need nfs export, you could try to create squashfs image with
> > > -no-exports as a possible workaround.
> >
> > If the problem persists, I will try that.  I'm not exporting anything
> > from the overlay.
>
> Ok, I can reproduce the problem 100% of the time using the attached
> squashfs image in 5.9 or 5.10.  In 5.8.18 and 5.4.83, everything works
> just fine.
>
>  mkdir -p t tt ttt
>  mount borky2.sqsh t
>  mount -t tmpfs tmp tt
>  mkdir -p tt/upper/{upper,work}
>  mount -t overlay -o \
>     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> [ 1685.825956] overlayfs: "xino" feature enabled using 2 upper inode bits.
>
>  echo hello there > ttt/FOO
> zsh: no data available: ttt/FOO
>
>  echo hello there > ttt/BAR
> for some reason, that file is editable
>
>  touch ttt/*
> touch: cannot touch 'ttt/BAZ': No data available
> touch: cannot touch 'ttt/FOO': No data available
> touch: cannot touch 'ttt/FOO-symlink': No data available
>
> Things look completely broken now that I'm looking this closely at a
> fresh overlay... I'm honestly surprised my system was usable at all.
> I guess most of the files on my lower layer had already been
> upgraded prior to me starting to use the 5.9 kernel.
>
> I also tried creating a squashfs file w/ -no-exports...  exact same results.
>
> In case it helps, here are the relevant kernel config items:
>
> CONFIG_OVERLAY_FS=y
> # CONFIG_OVERLAY_FS_REDIRECT_DIR is not set
> CONFIG_OVERLAY_FS_REDIRECT_ALWAYS_FOLLOW=y
> # CONFIG_OVERLAY_FS_INDEX is not set
> CONFIG_OVERLAY_FS_XINO_AUTO=y
> # CONFIG_OVERLAY_FS_METACOPY is not set
>
> CONFIG_SQUASHFS=y
> # CONFIG_SQUASHFS_FILE_CACHE is not set
> CONFIG_SQUASHFS_FILE_DIRECT=y
> # CONFIG_SQUASHFS_DECOMP_SINGLE is not set
> # CONFIG_SQUASHFS_DECOMP_MULTI is not set
> CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU=y
> CONFIG_SQUASHFS_XATTR=y
> CONFIG_SQUASHFS_ZLIB=y
> CONFIG_SQUASHFS_LZ4=y
> CONFIG_SQUASHFS_LZO=y
> CONFIG_SQUASHFS_XZ=y
> CONFIG_SQUASHFS_ZSTD=y
> # CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
> # CONFIG_SQUASHFS_EMBEDDED is not set
> CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3
>

Thanks for the reproducer and all the info, but it does not reproduce
on my test machine with v5.10.0.
I even changed my kernel config to match yours.

So I am going to have to ask you to debug this and figure out which
overlayfs execution path is responsible for the error.

First thing in order is to get an strace to see which system call is
failing and try to enable overlayfs debug prints with:
echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control

If that is not enough to pin point the problem, will need to ask you do
add debug prints in overlayfs code to understand the path of failure.

Thanks,
Amir.

Re: failed open: No data available

[Michael Labriola]

On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
>
> > > > and 'grep Y /sys/module/overlay/parameters/*'
> > >
> > > /sys/module/overlay/parameters/redirect_always_follow:Y
> > > /sys/module/overlay/parameters/xino_auto:Y
>
> That's likely the reason that you are affected.
> If you do not need the xino feature, you can set this to N or mount with
> xino=off your system should be good.

I just tried mounting w/ xino=off but everything still behaves the same.

>
> As the commit a888db3101 message says:
>
>     To avoid the reported regression while still allowing the new features
>     with single lower squashfs, do not allow decoding origin with lower null
>     uuid unless user opted-in to one of the new features that require
>     following the lower inode of non-dir upper (index, xino, metacopy).
>
> You or someone related to your distro opted-in to xino by
> CONFIG_OVERLAY_FS_XINO_AUTO=y

Kernel config help for this sounded like something good, plus the
Ubuntu 18.04 kernels all have this set (or did, when I checked last
year).

>
> which is smart to do IMO, but it probably exposed a bug.
>
> I still do not understand what the bug is, but please try the workaround.
>
> > >
> > > >
> > > > Do you see any "overlayfs:" logs in kmsg?
> > >
> > > [    4.828299] overlayfs: "xino" feature enabled using 32 upper inode bits.
> > >
> > > >
> > > > If you do not need nfs export, you could try to create squashfs image with
> > > > -no-exports as a possible workaround.
> > >
> > > If the problem persists, I will try that.  I'm not exporting anything
> > > from the overlay.
> >
> > Ok, I can reproduce the problem 100% of the time using the attached
> > squashfs image in 5.9 or 5.10.  In 5.8.18 and 5.4.83, everything works
> > just fine.
> >
> >  mkdir -p t tt ttt
> >  mount borky2.sqsh t
> >  mount -t tmpfs tmp tt
> >  mkdir -p tt/upper/{upper,work}
> >  mount -t overlay -o \
> >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > [ 1685.825956] overlayfs: "xino" feature enabled using 2 upper inode bits.
> >
> >  echo hello there > ttt/FOO
> > zsh: no data available: ttt/FOO
> >
> >  echo hello there > ttt/BAR
> > for some reason, that file is editable
> >
> >  touch ttt/*
> > touch: cannot touch 'ttt/BAZ': No data available
> > touch: cannot touch 'ttt/FOO': No data available
> > touch: cannot touch 'ttt/FOO-symlink': No data available
> >
> > Things look completely broken now that I'm looking this closely at a
> > fresh overlay... I'm honestly surprised my system was usable at all.
> > I guess most of the files on my lower layer had already been
> > upgraded prior to me starting to use the 5.9 kernel.
> >
> > I also tried creating a squashfs file w/ -no-exports...  exact same results.
> >
> > In case it helps, here are the relevant kernel config items:
> >
> > CONFIG_OVERLAY_FS=y
> > # CONFIG_OVERLAY_FS_REDIRECT_DIR is not set
> > CONFIG_OVERLAY_FS_REDIRECT_ALWAYS_FOLLOW=y
> > # CONFIG_OVERLAY_FS_INDEX is not set
> > CONFIG_OVERLAY_FS_XINO_AUTO=y
> > # CONFIG_OVERLAY_FS_METACOPY is not set
> >
> > CONFIG_SQUASHFS=y
> > # CONFIG_SQUASHFS_FILE_CACHE is not set
> > CONFIG_SQUASHFS_FILE_DIRECT=y
> > # CONFIG_SQUASHFS_DECOMP_SINGLE is not set
> > # CONFIG_SQUASHFS_DECOMP_MULTI is not set
> > CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU=y
> > CONFIG_SQUASHFS_XATTR=y
> > CONFIG_SQUASHFS_ZLIB=y
> > CONFIG_SQUASHFS_LZ4=y
> > CONFIG_SQUASHFS_LZO=y
> > CONFIG_SQUASHFS_XZ=y
> > CONFIG_SQUASHFS_ZSTD=y
> > # CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
> > # CONFIG_SQUASHFS_EMBEDDED is not set
> > CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3
> >
>
> Thanks for the reproducer and all the info, but it does not reproduce
> on my test machine with v5.10.0.
> I even changed my kernel config to match yours.

Figured as much, given that I seem to be the only one reporting this.  ;-)

>
> So I am going to have to ask you to debug this and figure out which
> overlayfs execution path is responsible for the error.

Gladly.

>
> First thing in order is to get an strace to see which system call is
> failing and try to enable overlayfs debug prints with:
> echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
>
> If that is not enough to pin point the problem, will need to ask you do
> add debug prints in overlayfs code to understand the path of failure.

Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
recompiling with that and without CONFIG_OVERLAY_FS_XINO_AUTO to see
if that changes anything.  Here's output of strace touch FOO (from
inside my overlay mount) w/ yesterday's kernel and xino=off while I wait:

execve("/usr/bin/touch", ["touch", "FOO"], 0x7ffe51adb598 /* 22 vars */) = 0
brk(NULL)                               = 0x55bdf16c1000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=180434, ...}) = 0
mmap(NULL, 180434, PROT_READ, MAP_PRIVATE, 3, 0) = 0x151ca6528000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/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\0\20\35\2\0\0\0\0\0"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2030928, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x151ca6526000
mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x151ca5f3b000
mprotect(0x151ca6122000, 2097152, PROT_NONE) = 0
mmap(0x151ca6322000, 24576, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x151ca6322000
mmap(0x151ca6328000, 15072, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x151ca6328000
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x151ca6527540) = 0
mprotect(0x151ca6322000, 16384, PROT_READ) = 0
mprotect(0x55bdf0214000, 4096, PROT_READ) = 0
mprotect(0x151ca6555000, 4096, PROT_READ) = 0
munmap(0x151ca6528000, 180434)          = 0
brk(NULL)                               = 0x55bdf16c1000
brk(0x55bdf16e2000)                     = 0x55bdf16e2000
openat(AT_FDCWD, "FOO", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) =
-1 ENODATA (No data available)
utimensat(AT_FDCWD, "FOO", NULL, 0)     = -1 ENODATA (No data available)
write(2, "touch: ", 7touch: )                  = 7
write(2, "cannot touch 'FOO'", 18cannot touch 'FOO')      = 18
write(2, ": No data available", 19: No data available)     = 19
write(2, "\n", 1
)                       = 1
close(1)                                = 0
close(2)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++


-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Amir Goldstein]

On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> >
> > > > > and 'grep Y /sys/module/overlay/parameters/*'
> > > >
> > > > /sys/module/overlay/parameters/redirect_always_follow:Y
> > > > /sys/module/overlay/parameters/xino_auto:Y
> >
> > That's likely the reason that you are affected.
> > If you do not need the xino feature, you can set this to N or mount with
> > xino=off your system should be good.
>
> I just tried mounting w/ xino=off but everything still behaves the same.
>
> >
> > As the commit a888db3101 message says:
> >
> >     To avoid the reported regression while still allowing the new features
> >     with single lower squashfs, do not allow decoding origin with lower null
> >     uuid unless user opted-in to one of the new features that require
> >     following the lower inode of non-dir upper (index, xino, metacopy).
> >
> > You or someone related to your distro opted-in to xino by
> > CONFIG_OVERLAY_FS_XINO_AUTO=y
>
> Kernel config help for this sounded like something good, plus the
> Ubuntu 18.04 kernels all have this set (or did, when I checked last
> year).
>

Nice :) I didn't know that.

> >
> > which is smart to do IMO, but it probably exposed a bug.
> >
> > I still do not understand what the bug is, but please try the workaround.
> >
> > > >
> > > > >
> > > > > Do you see any "overlayfs:" logs in kmsg?
> > > >
> > > > [    4.828299] overlayfs: "xino" feature enabled using 32 upper inode bits.
> > > >
> > > > >
> > > > > If you do not need nfs export, you could try to create squashfs image with
> > > > > -no-exports as a possible workaround.
> > > >
> > > > If the problem persists, I will try that.  I'm not exporting anything
> > > > from the overlay.
> > >
> > > Ok, I can reproduce the problem 100% of the time using the attached
> > > squashfs image in 5.9 or 5.10.  In 5.8.18 and 5.4.83, everything works
> > > just fine.
> > >
> > >  mkdir -p t tt ttt
> > >  mount borky2.sqsh t
> > >  mount -t tmpfs tmp tt
> > >  mkdir -p tt/upper/{upper,work}
> > >  mount -t overlay -o \
> > >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > > [ 1685.825956] overlayfs: "xino" feature enabled using 2 upper inode bits.
> > >
> > >  echo hello there > ttt/FOO
> > > zsh: no data available: ttt/FOO
> > >
> > >  echo hello there > ttt/BAR
> > > for some reason, that file is editable
> > >
> > >  touch ttt/*
> > > touch: cannot touch 'ttt/BAZ': No data available
> > > touch: cannot touch 'ttt/FOO': No data available
> > > touch: cannot touch 'ttt/FOO-symlink': No data available
> > >
> > > Things look completely broken now that I'm looking this closely at a
> > > fresh overlay... I'm honestly surprised my system was usable at all.
> > > I guess most of the files on my lower layer had already been
> > > upgraded prior to me starting to use the 5.9 kernel.
> > >
> > > I also tried creating a squashfs file w/ -no-exports...  exact same results.
> > >
> > > In case it helps, here are the relevant kernel config items:
> > >
> > > CONFIG_OVERLAY_FS=y
> > > # CONFIG_OVERLAY_FS_REDIRECT_DIR is not set
> > > CONFIG_OVERLAY_FS_REDIRECT_ALWAYS_FOLLOW=y
> > > # CONFIG_OVERLAY_FS_INDEX is not set
> > > CONFIG_OVERLAY_FS_XINO_AUTO=y
> > > # CONFIG_OVERLAY_FS_METACOPY is not set
> > >
> > > CONFIG_SQUASHFS=y
> > > # CONFIG_SQUASHFS_FILE_CACHE is not set
> > > CONFIG_SQUASHFS_FILE_DIRECT=y
> > > # CONFIG_SQUASHFS_DECOMP_SINGLE is not set
> > > # CONFIG_SQUASHFS_DECOMP_MULTI is not set
> > > CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU=y
> > > CONFIG_SQUASHFS_XATTR=y
> > > CONFIG_SQUASHFS_ZLIB=y
> > > CONFIG_SQUASHFS_LZ4=y
> > > CONFIG_SQUASHFS_LZO=y
> > > CONFIG_SQUASHFS_XZ=y
> > > CONFIG_SQUASHFS_ZSTD=y
> > > # CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
> > > # CONFIG_SQUASHFS_EMBEDDED is not set
> > > CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3
> > >
> >
> > Thanks for the reproducer and all the info, but it does not reproduce
> > on my test machine with v5.10.0.
> > I even changed my kernel config to match yours.
>
> Figured as much, given that I seem to be the only one reporting this.  ;-)
>
> >
> > So I am going to have to ask you to debug this and figure out which
> > overlayfs execution path is responsible for the error.
>
> Gladly.
>
> >
> > First thing in order is to get an strace to see which system call is
> > failing and try to enable overlayfs debug prints with:
> > echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> >
> > If that is not enough to pin point the problem, will need to ask you do
> > add debug prints in overlayfs code to understand the path of failure.
>
> Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so

I honestly don't expect to find much in the existing overlay debug prints
but you never know..
I suspect you will have to add debug prints to find the problem.

> recompiling with that and without CONFIG_OVERLAY_FS_XINO_AUTO to see
> if that changes anything.  Here's output of strace touch FOO (from
> inside my overlay mount) w/ yesterday's kernel and xino=off while I wait:
>
> execve("/usr/bin/touch", ["touch", "FOO"], 0x7ffe51adb598 /* 22 vars */) = 0
> brk(NULL)                               = 0x55bdf16c1000
> access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
> access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
> fstat(3, {st_mode=S_IFREG|0644, st_size=180434, ...}) = 0
> mmap(NULL, 180434, PROT_READ, MAP_PRIVATE, 3, 0) = 0x151ca6528000
> close(3)                                = 0
> access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/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\0\20\35\2\0\0\0\0\0"...,
> 832) = 832
> fstat(3, {st_mode=S_IFREG|0755, st_size=2030928, ...}) = 0
> mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x151ca6526000
> mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
> 0) = 0x151ca5f3b000
> mprotect(0x151ca6122000, 2097152, PROT_NONE) = 0
> mmap(0x151ca6322000, 24576, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x151ca6322000
> mmap(0x151ca6328000, 15072, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x151ca6328000
> close(3)                                = 0
> arch_prctl(ARCH_SET_FS, 0x151ca6527540) = 0
> mprotect(0x151ca6322000, 16384, PROT_READ) = 0
> mprotect(0x55bdf0214000, 4096, PROT_READ) = 0
> mprotect(0x151ca6555000, 4096, PROT_READ) = 0
> munmap(0x151ca6528000, 180434)          = 0
> brk(NULL)                               = 0x55bdf16c1000
> brk(0x55bdf16e2000)                     = 0x55bdf16e2000
> openat(AT_FDCWD, "FOO", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) =
> -1 ENODATA (No data available)

As expected that added no new information either, but needed to be sure.

Thanks,
Amir.

Re: failed open: No data available

[Michael Labriola]

On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
>
> On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
*snip*
> > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
>
> I honestly don't expect to find much in the existing overlay debug prints
> but you never know..
> I suspect you will have to add debug prints to find the problem.

Ok, here goes.  I had to setup a new virtual machine that doesn't use
overlayfs for its root filesystem because turning on dynamic debug
gave way too much output for a nice controlled test.  It's exhibiting
the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:

 echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
 mount borky2.sqsh t
 mount -t tmpfs tmp tt
 mkdir -p tt/upper/{upper,work}
 mount -t overlay -o \
    lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
[  164.505193] overlayfs: mkdir(work/work, 040000) = 0
[  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
[  164.505209] overlayfs: create(work/#3, 0100000) = 0
[  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
[  164.505216] overlayfs: unlink(work/#3) = 0
[  164.505217] overlayfs: unlink(work/#4) = 0
[  164.505221] overlayfs: setxattr(work/work,
"trusted.overlay.opaque", "0", 1, 0x0) = 0

 touch ttt/FOO
touch: cannot touch 'ttt/FOO': No data available
[  191.919498] overlayfs: setxattr(upper/upper,
"trusted.overlay.impure", "y", 1, 0x0) = 0
[  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
[  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0

That give you any hints?  I'll start reading through the overlayfs
code.  I've never actually looked at it, so I'll be planting printk
calls at random.  ;-)

-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Amir Goldstein]

On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> >
> > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> *snip*
> > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> >
> > I honestly don't expect to find much in the existing overlay debug prints
> > but you never know..
> > I suspect you will have to add debug prints to find the problem.
>
> Ok, here goes.  I had to setup a new virtual machine that doesn't use
> overlayfs for its root filesystem because turning on dynamic debug
> gave way too much output for a nice controlled test.  It's exhibiting
> the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
>
>  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
>  mount borky2.sqsh t
>  mount -t tmpfs tmp tt
>  mkdir -p tt/upper/{upper,work}
>  mount -t overlay -o \
>     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> [  164.505216] overlayfs: unlink(work/#3) = 0
> [  164.505217] overlayfs: unlink(work/#4) = 0
> [  164.505221] overlayfs: setxattr(work/work,
> "trusted.overlay.opaque", "0", 1, 0x0) = 0
>
>  touch ttt/FOO
> touch: cannot touch 'ttt/FOO': No data available
> [  191.919498] overlayfs: setxattr(upper/upper,
> "trusted.overlay.impure", "y", 1, 0x0) = 0
> [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
>
> That give you any hints?  I'll start reading through the overlayfs
> code.  I've never actually looked at it, so I'll be planting printk
> calls at random.  ;-)

We have seen that open("FOO", O_WRONLY) fails
We know that FOO is lower at that time so that brings us to

ovl_open
  ovl_maybe_copy_up
    ovl_copy_up_flags
      ovl_copy_up_one
        ovl_do_copy_up
          ovl_set_impure
[  191.919498] overlayfs: setxattr(upper/upper,
"trusted.overlay.impure", "y", 1, 0x0) = 0
          ovl_copy_up_tmpfile
            ovl_do_tmpfile
[  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
            ovl_copy_up_inode
This must be were we fail and likely in:
              ovl_copy_xattr
                 vfs_getxattr
which can return -ENODATA, but it is not expected because the
xattrs returned by vfs_listxattr should exist...

So first guess would be to add a debug print for xattr 'name'
and return value of vfs_getxattr().

Good luck!
Thanks,
Amir.

Re: failed open: No data available

[Michael Labriola]

On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@gmail.com> wrote:
>
> On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> <michael.d.labriola@gmail.com> wrote:
> >
> > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> > *snip*
> > > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> > >
> > > I honestly don't expect to find much in the existing overlay debug prints
> > > but you never know..
> > > I suspect you will have to add debug prints to find the problem.
> >
> > Ok, here goes.  I had to setup a new virtual machine that doesn't use
> > overlayfs for its root filesystem because turning on dynamic debug
> > gave way too much output for a nice controlled test.  It's exhibiting
> > the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> > with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> > off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
> >
> >  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> >  mount borky2.sqsh t
> >  mount -t tmpfs tmp tt
> >  mkdir -p tt/upper/{upper,work}
> >  mount -t overlay -o \
> >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> > [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> > [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> > [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> > [  164.505216] overlayfs: unlink(work/#3) = 0
> > [  164.505217] overlayfs: unlink(work/#4) = 0
> > [  164.505221] overlayfs: setxattr(work/work,
> > "trusted.overlay.opaque", "0", 1, 0x0) = 0
> >
> >  touch ttt/FOO
> > touch: cannot touch 'ttt/FOO': No data available
> > [  191.919498] overlayfs: setxattr(upper/upper,
> > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
> >
> > That give you any hints?  I'll start reading through the overlayfs
> > code.  I've never actually looked at it, so I'll be planting printk
> > calls at random.  ;-)
>
> We have seen that open("FOO", O_WRONLY) fails
> We know that FOO is lower at that time so that brings us to
>
> ovl_open
>   ovl_maybe_copy_up
>     ovl_copy_up_flags
>       ovl_copy_up_one
>         ovl_do_copy_up
>           ovl_set_impure
> [  191.919498] overlayfs: setxattr(upper/upper,
> "trusted.overlay.impure", "y", 1, 0x0) = 0
>           ovl_copy_up_tmpfile
>             ovl_do_tmpfile
> [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
>             ovl_copy_up_inode
> This must be were we fail and likely in:
>               ovl_copy_xattr
>                  vfs_getxattr
> which can return -ENODATA, but it is not expected because the
> xattrs returned by vfs_listxattr should exist...
>
> So first guess would be to add a debug print for xattr 'name'
> and return value of vfs_getxattr().

Ok, here we go.  I've added a bunch of printks all over the place.
Here's what we've got.  Things are unchanged during mount.  Trying to
touch FOO now gives me this:

[  114.365444] ovl_open: start
[  114.365450] ovl_maybe_copy_up: start
[  114.365452] ovl_maybe_copy_up: need copy up
[  114.365454] ovl_maybe_copy_up: ovl_want_write succeeded
[  114.365459] ovl_copy_up_one: calling ovl_do_copy_up()
[  114.365460] ovl_do_copy_up: start
[  114.365462] ovl_do_copy_up: impure
[  114.365464] ovl_set_impure: start
[  114.365484] overlayfs: setxattr(upper/upper,
"trusted.overlay.impure", "y", 1, 0x0) = 0
[  114.365486] ovl_copy_up_tmpfile: start
[  114.365507] overlayfs: tmpfile(work/work, 0100644) = 0
[  114.365510] ovl_copy_up_inode: start
[  114.365511] ovl_copy_up_inode: ISREG && !metacopy
[  114.365625] ovl_copy_xattr: start
[  114.365630] ovl_copy_xattr: vfs_listxattr() returned 17
[  114.365632] ovl_copy_xattr: buf allocated good
[  114.365634] ovl_copy_xattr: vfs_listxattr() returned 17
[  114.365636] ovl_copy_xattr: slen=17
[  114.365638] ovl_copy_xattr: name='security.selinux'
[  114.365643] ovl_copy_xattr: vfs_getxattr returned size=-61
[  114.365644] ovl_copy_xattr: cleaning up
[  114.365647] ovl_copy_up_inode: ovl_copy_xattr error=-61
[  114.365649] ovl_copy_up_one: error=-61
[  114.365651] ovl_copy_up_one: calling ovl_copy_up_end()
[  114.365653] ovl_copy_up_flags: ovl_copy_up_one error=-61
[  114.365655] ovl_maybe_copy_up: ovl_copy_up_flags error=-61
[  114.365658] ovl_open: ovl_maybe_copy_up error=-61
[  114.365728] ovl_copy_up_one: calling ovl_do_copy_up()
[  114.365730] ovl_do_copy_up: start
[  114.365731] ovl_do_copy_up: impure
[  114.365733] ovl_set_impure: start
[  114.365735] ovl_copy_up_tmpfile: start
[  114.365748] overlayfs: tmpfile(work/work, 0100644) = 0
[  114.365750] ovl_copy_up_inode: start
[  114.365752] ovl_copy_up_inode: ISREG && !metacopy
[  114.365770] ovl_copy_xattr: start
[  114.365773] ovl_copy_xattr: vfs_listxattr() returned 17
[  114.365774] ovl_copy_xattr: buf allocated good
[  114.365776] ovl_copy_xattr: vfs_listxattr() returned 17
[  114.365778] ovl_copy_xattr: slen=17
[  114.365780] ovl_copy_xattr: name='security.selinux'
[  114.365784] ovl_copy_xattr: vfs_getxattr returned size=-61
[  114.365785] ovl_copy_xattr: cleaning up
[  114.365787] ovl_copy_up_inode: ovl_copy_xattr error=-61
[  114.365789] ovl_copy_up_one: error=-61
[  114.365790] ovl_copy_up_one: calling ovl_copy_up_end()
[  114.365792] ovl_copy_up_flags: ovl_copy_up_one error=-61


And so you can decode my splattering of debug, here's my diff
(although I'm sure gmail will line-wrap it to death):


diff --git a/fs/overlayfs/copy_up.c b/fs/overlayfs/copy_up.c
index d07fb92b7253..f3f25c1bf13e 100644
--- a/fs/overlayfs/copy_up.c
+++ b/fs/overlayfs/copy_up.c
@@ -50,11 +50,13 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)
     int error = 0;
     size_t slen;

+    printk("%s: start\n", __func__);
     if (!(old->d_inode->i_opflags & IOP_XATTR) ||
         !(new->d_inode->i_opflags & IOP_XATTR))
         return 0;

-    list_size = vfs_listxattr(old, NULL, 0);
+    list_size = vfs_listxattr(old, NULL, 0);
+    printk("%s: vfs_listxattr() returned %ld\n", __func__, list_size);
     if (list_size <= 0) {
         if (list_size == -EOPNOTSUPP)
             return 0;
@@ -64,8 +66,10 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)
     buf = kzalloc(list_size, GFP_KERNEL);
     if (!buf)
         return -ENOMEM;
+    printk("%s: buf allocated good\n", __func__);

     list_size = vfs_listxattr(old, buf, list_size);
+    printk("%s: vfs_listxattr() returned %ld\n", __func__, list_size);
     if (list_size <= 0) {
         error = list_size;
         goto out;
@@ -73,7 +77,9 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)

     for (name = buf; list_size; name += slen) {
         slen = strnlen(name, list_size) + 1;
-
+        printk("%s: slen=%ld\n", __func__, slen);
+        printk("%s: name='%s'\n", __func__, name);
+
         /* underlying fs providing us with an broken xattr list? */
         if (WARN_ON(slen > list_size)) {
             error = -EIO;
@@ -81,24 +87,34 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)
         }
         list_size -= slen;

-        if (ovl_is_private_xattr(name))
+        if (ovl_is_private_xattr(name)) {
+            printk("%s: ovl_is_private_xattr, continue\n", __func__);
             continue;
+        }
 retry:
         size = vfs_getxattr(old, name, value, value_size);
-        if (size == -ERANGE)
+        printk("%s: vfs_getxattr returned size=%ld\n", __func__, size);
+
+        if (size == -ERANGE) {
+            printk("%s: ERANGE, trying again\n", __func__);
             size = vfs_getxattr(old, name, NULL, 0);
+            printk("%s: 2nd try size=%ld\n", __func__, size);
+        }

         if (size < 0) {
             error = size;
             break;
         }
+        printk("%s: value_size=%ld\n", __func__, value_size);

         if (size > value_size) {
             void *new;

+            printk("%s: reallocating\n", __func__);
             new = krealloc(value, size, GFP_KERNEL);
             if (!new) {
                 error = -ENOMEM;
+                printk("%s: krealloc error\n", __func__);
                 break;
             }
             value = new;
@@ -107,6 +123,7 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)
         }

         error = security_inode_copy_up_xattr(name);
+        printk("%s: security_inode_copy_up_xattr() error=%d\n",
__func__, error);
         if (error < 0 && error != -EOPNOTSUPP)
             break;
         if (error == 1) {
@@ -114,6 +131,7 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)
             continue; /* Discard */
         }
         error = vfs_setxattr(new, name, value, size, 0);
+        printk("%s: vfs_setxattr() error=%d\n", __func__, error);
         if (error) {
             if (error != -EOPNOTSUPP || ovl_must_copy_xattr(name))
                 break;
@@ -122,6 +140,7 @@ int ovl_copy_xattr(struct dentry *old, struct dentry *new)
             error = 0;
         }
     }
+    printk("%s: cleaning up", __func__);
     kfree(value);
 out:
     kfree(buf);
@@ -485,6 +504,7 @@ static int ovl_link_up(struct ovl_copy_up_ctx *c)
 static int ovl_copy_up_inode(struct ovl_copy_up_ctx *c, struct dentry *temp)
 {
     int err;
+    printk("%s: start\n", __func__);

     /*
      * Copy up data first and then xattrs. Writing data after
@@ -492,6 +512,7 @@ static int ovl_copy_up_inode(struct
ovl_copy_up_ctx *c, struct dentry *temp)
      */
     if (S_ISREG(c->stat.mode) && !c->metacopy) {
         struct path upperpath, datapath;
+        printk("%s: ISREG && !metacopy\n", __func__);

         ovl_path_upper(c->dentry, &upperpath);
         if (WARN_ON(upperpath.dentry != NULL))
@@ -500,13 +521,17 @@ static int ovl_copy_up_inode(struct
ovl_copy_up_ctx *c, struct dentry *temp)

         ovl_path_lowerdata(c->dentry, &datapath);
         err = ovl_copy_up_data(&datapath, &upperpath, c->stat.size);
-        if (err)
+        if (err) {
+            printk("%s: ovl_copy_up_data error=%d\n", __func__, err);
             return err;
+        }
     }

     err = ovl_copy_xattr(c->lowerpath.dentry, temp);
-    if (err)
+    if (err) {
+        printk("%s: ovl_copy_xattr error=%d\n", __func__, err);
         return err;
+    }

     /*
      * Store identifier of lower inode in upper inode xattr to
@@ -516,23 +541,36 @@ static int ovl_copy_up_inode(struct
ovl_copy_up_ctx *c, struct dentry *temp)
      * hard link.
      */
     if (c->origin) {
+        printk("%s: origin\n", __func__);
         err = ovl_set_origin(c->dentry, c->lowerpath.dentry, temp);
-        if (err)
+        if (err) {
+            printk("%s: ovl_set_origin error=%d\n", __func__, err);
             return err;
+        }
     }

     if (c->metacopy) {
+        printk("%s: metacopy\n", __func__);
         err = ovl_check_setxattr(c->dentry, temp, OVL_XATTR_METACOPY,
                      NULL, 0, -EOPNOTSUPP);
-        if (err)
+        if (err) {
+            printk("%s: ovl_check_setxattr error=%d\n", __func__, err);
             return err;
+        }
     }

     inode_lock(temp->d_inode);
-    if (S_ISREG(c->stat.mode))
+    if (S_ISREG(c->stat.mode)) {
+        printk("%s: ISREG\n", __func__);
         err = ovl_set_size(temp, &c->stat);
-    if (!err)
+        if (err)
+            printk("%s: ovl_set_size error=%d\n", __func__, err);
+    }
+    if (!err) {
         err = ovl_set_attr(temp, &c->stat);
+        if (err)
+            printk("%s: ovl_set_attr error=%d\n", __func__, err);
+    }
     inode_unlock(temp->d_inode);

     return err;
@@ -645,6 +683,8 @@ static int ovl_copy_up_tmpfile(struct ovl_copy_up_ctx *c)
     struct ovl_cu_creds cc;
     int err;

+    printk("%s: start\n", __func__);
+
     err = ovl_prep_cu_creds(c->dentry, &cc);
     if (err)
         return err;
@@ -698,6 +738,8 @@ static int ovl_do_copy_up(struct ovl_copy_up_ctx *c)
     struct ovl_fs *ofs = c->dentry->d_sb->s_fs_info;
     bool to_index = false;

+    printk("%s: start\n", __func__);
+
     /*
      * Indexed non-dir is copied up directly to the index entry and then
      * hardlinked to upper dir. Indexed dir is copied up to indexdir,
@@ -705,6 +747,7 @@ static int ovl_do_copy_up(struct ovl_copy_up_ctx *c)
      * Copying dir up to indexdir instead of workdir simplifies locking.
      */
     if (ovl_need_index(c->dentry)) {
+        printk("%s: need index\n", __func__);
         c->indexed = true;
         if (S_ISDIR(c->stat.mode))
             c->workdir = ovl_indexdir(c->dentry->d_sb);
@@ -716,6 +759,7 @@ static int ovl_do_copy_up(struct ovl_copy_up_ctx *c)
         c->origin = true;

     if (to_index) {
+        printk("%s: to_index\n", __func__);
         c->destdir = ovl_indexdir(c->dentry->d_sb);
         err = ovl_get_index_name(c->lowerpath.dentry, &c->destname);
         if (err)
@@ -724,6 +768,7 @@ static int ovl_do_copy_up(struct ovl_copy_up_ctx *c)
         /* Disconnected dentry must be copied up to index dir */
         return -EIO;
     } else {
+        printk("%s: impure\n", __func__);
         /*
          * Mark parent "impure" because it may now contain non-pure
          * upper
@@ -882,12 +927,25 @@ static int ovl_copy_up_one(struct dentry
*parent, struct dentry *dentry,
         if (err > 0)
             err = 0;
     } else {
-        if (!ovl_dentry_upper(dentry))
+        if (!ovl_dentry_upper(dentry)) {
+            printk("%s: calling ovl_do_copy_up()\n", __func__);
             err = ovl_do_copy_up(&ctx);
-        if (!err && parent && !ovl_dentry_has_upper_alias(dentry))
+            if (err)
+                printk("%s: error=%d\n", __func__, err);
+        }
+        if (!err && parent && !ovl_dentry_has_upper_alias(dentry)) {
+            printk("%s: calling ovl_link_up()\n", __func__);
             err = ovl_link_up(&ctx);
-        if (!err && ovl_dentry_needs_data_copy_up_locked(dentry, flags))
+            if (err)
+                printk("%s: error=%d\n", __func__, err);
+        }
+        if (!err && ovl_dentry_needs_data_copy_up_locked(dentry, flags)) {
+            printk("%s: calling ovl_copy_up_meta_inode_data()\n", __func__);
             err = ovl_copy_up_meta_inode_data(&ctx);
+            if (err)
+                printk("%s: error=%d\n", __func__, err);
+        }
+        printk("%s: calling ovl_copy_up_end()\n", __func__);
         ovl_copy_up_end(dentry);
     }
     do_delayed_call(&done);
@@ -929,6 +987,8 @@ static int ovl_copy_up_flags(struct dentry
*dentry, int flags)
         }

         err = ovl_copy_up_one(parent, next, flags);
+        if (err)
+            printk("%s: ovl_copy_up_one error=%d\n", __func__, err);

         dput(parent);
         dput(next);
@@ -957,10 +1017,15 @@ int ovl_maybe_copy_up(struct dentry *dentry, int flags)
 {
     int err = 0;

+    printk("%s: start\n", __func__);
     if (ovl_open_need_copy_up(dentry, flags)) {
+        printk("%s: need copy up\n", __func__);
         err = ovl_want_write(dentry);
         if (!err) {
+            printk("%s: ovl_want_write succeeded\n", __func__);
             err = ovl_copy_up_flags(dentry, flags);
+            if (err)
+                printk("%s: ovl_copy_up_flags error=%d\n", __func__, err);
             ovl_drop_write(dentry);
         }
     }
diff --git a/fs/overlayfs/file.c b/fs/overlayfs/file.c
index 0d940e29d62b..b9de23a17268 100644
--- a/fs/overlayfs/file.c
+++ b/fs/overlayfs/file.c
@@ -144,19 +144,25 @@ static int ovl_open(struct inode *inode, struct
file *file)
     struct file *realfile;
     int err;

+    printk("%s: start\n", __func__);
     err = ovl_maybe_copy_up(file_dentry(file), file->f_flags);
-    if (err)
+    if (err) {
+        printk("%s: ovl_maybe_copy_up error=%d\n", __func__, err);
         return err;
+    }

     /* No longer need these flags, so don't pass them on to underlying fs */
     file->f_flags &= ~(O_CREAT | O_EXCL | O_NOCTTY | O_TRUNC);

     realfile = ovl_open_realfile(file, ovl_inode_realdata(inode));
-    if (IS_ERR(realfile))
+    if (IS_ERR(realfile)) {
+        printk("%s: ovl_open_realfile error=%ld\n", __func__,
PTR_ERR(realfile));
         return PTR_ERR(realfile);
+    }

     file->private_data = realfile;

+    printk("%s: done\n", __func__);
     return 0;
 }

diff --git a/fs/overlayfs/util.c b/fs/overlayfs/util.c
index 56c1f89f20c9..2f0071595ed7 100644
--- a/fs/overlayfs/util.c
+++ b/fs/overlayfs/util.c
@@ -597,6 +597,7 @@ int ovl_set_impure(struct dentry *dentry, struct
dentry *upperdentry)
 {
     int err;

+    printk("%s: start\n", __func__);
     if (ovl_test_flag(OVL_IMPURE, d_inode(dentry)))
         return 0;




-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Michael Labriola]

On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@gmail.com> wrote:
> >
> > On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> > <michael.d.labriola@gmail.com> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > >
> > > > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> > > *snip*
> > > > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> > > >
> > > > I honestly don't expect to find much in the existing overlay debug prints
> > > > but you never know..
> > > > I suspect you will have to add debug prints to find the problem.
> > >
> > > Ok, here goes.  I had to setup a new virtual machine that doesn't use
> > > overlayfs for its root filesystem because turning on dynamic debug
> > > gave way too much output for a nice controlled test.  It's exhibiting
> > > the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> > > with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> > > off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
> > >
> > >  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> > >  mount borky2.sqsh t
> > >  mount -t tmpfs tmp tt
> > >  mkdir -p tt/upper/{upper,work}
> > >  mount -t overlay -o \
> > >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > > [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> > > [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> > > [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> > > [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> > > [  164.505216] overlayfs: unlink(work/#3) = 0
> > > [  164.505217] overlayfs: unlink(work/#4) = 0
> > > [  164.505221] overlayfs: setxattr(work/work,
> > > "trusted.overlay.opaque", "0", 1, 0x0) = 0
> > >
> > >  touch ttt/FOO
> > > touch: cannot touch 'ttt/FOO': No data available
> > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
> > >
> > > That give you any hints?  I'll start reading through the overlayfs
> > > code.  I've never actually looked at it, so I'll be planting printk
> > > calls at random.  ;-)
> >
> > We have seen that open("FOO", O_WRONLY) fails
> > We know that FOO is lower at that time so that brings us to
> >
> > ovl_open
> >   ovl_maybe_copy_up
> >     ovl_copy_up_flags
> >       ovl_copy_up_one
> >         ovl_do_copy_up
> >           ovl_set_impure
> > [  191.919498] overlayfs: setxattr(upper/upper,
> > "trusted.overlay.impure", "y", 1, 0x0) = 0
> >           ovl_copy_up_tmpfile
> >             ovl_do_tmpfile
> > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> >             ovl_copy_up_inode
> > This must be were we fail and likely in:
> >               ovl_copy_xattr
> >                  vfs_getxattr
> > which can return -ENODATA, but it is not expected because the
> > xattrs returned by vfs_listxattr should exist...
> >
> > So first guess would be to add a debug print for xattr 'name'
> > and return value of vfs_getxattr().
>
> Ok, here we go.  I've added a bunch of printks all over the place.
> Here's what we've got.  Things are unchanged during mount.  Trying to
> touch FOO now gives me this:
>
> [  114.365444] ovl_open: start
> [  114.365450] ovl_maybe_copy_up: start
> [  114.365452] ovl_maybe_copy_up: need copy up
> [  114.365454] ovl_maybe_copy_up: ovl_want_write succeeded
> [  114.365459] ovl_copy_up_one: calling ovl_do_copy_up()
> [  114.365460] ovl_do_copy_up: start
> [  114.365462] ovl_do_copy_up: impure
> [  114.365464] ovl_set_impure: start
> [  114.365484] overlayfs: setxattr(upper/upper,
> "trusted.overlay.impure", "y", 1, 0x0) = 0
> [  114.365486] ovl_copy_up_tmpfile: start
> [  114.365507] overlayfs: tmpfile(work/work, 0100644) = 0
> [  114.365510] ovl_copy_up_inode: start
> [  114.365511] ovl_copy_up_inode: ISREG && !metacopy
> [  114.365625] ovl_copy_xattr: start
> [  114.365630] ovl_copy_xattr: vfs_listxattr() returned 17
> [  114.365632] ovl_copy_xattr: buf allocated good
> [  114.365634] ovl_copy_xattr: vfs_listxattr() returned 17
> [  114.365636] ovl_copy_xattr: slen=17
> [  114.365638] ovl_copy_xattr: name='security.selinux'

SELinux?  now that's not suspicious at all...

> [  114.365643] ovl_copy_xattr: vfs_getxattr returned size=-61
> [  114.365644] ovl_copy_xattr: cleaning up
> [  114.365647] ovl_copy_up_inode: ovl_copy_xattr error=-61
> [  114.365649] ovl_copy_up_one: error=-61
> [  114.365651] ovl_copy_up_one: calling ovl_copy_up_end()
> [  114.365653] ovl_copy_up_flags: ovl_copy_up_one error=-61
> [  114.365655] ovl_maybe_copy_up: ovl_copy_up_flags error=-61
> [  114.365658] ovl_open: ovl_maybe_copy_up error=-61
> [  114.365728] ovl_copy_up_one: calling ovl_do_copy_up()
> [  114.365730] ovl_do_copy_up: start
> [  114.365731] ovl_do_copy_up: impure
> [  114.365733] ovl_set_impure: start
> [  114.365735] ovl_copy_up_tmpfile: start
> [  114.365748] overlayfs: tmpfile(work/work, 0100644) = 0
> [  114.365750] ovl_copy_up_inode: start
> [  114.365752] ovl_copy_up_inode: ISREG && !metacopy
> [  114.365770] ovl_copy_xattr: start
> [  114.365773] ovl_copy_xattr: vfs_listxattr() returned 17
> [  114.365774] ovl_copy_xattr: buf allocated good
> [  114.365776] ovl_copy_xattr: vfs_listxattr() returned 17
> [  114.365778] ovl_copy_xattr: slen=17
> [  114.365780] ovl_copy_xattr: name='security.selinux'
> [  114.365784] ovl_copy_xattr: vfs_getxattr returned size=-61
> [  114.365785] ovl_copy_xattr: cleaning up
> [  114.365787] ovl_copy_up_inode: ovl_copy_xattr error=-61
> [  114.365789] ovl_copy_up_one: error=-61
> [  114.365790] ovl_copy_up_one: calling ovl_copy_up_end()
> [  114.365792] ovl_copy_up_flags: ovl_copy_up_one error=-61
>
*snip*

So, the selinux stuff made me raise an eyebrow...  I've got selinux
enabled in my kernel so that it's there if I boot up a RHEL box with
this kernel.  But I'm using Ubuntu right now, and the rest of SELinux
is not installed/enabled.  There shouldn't be any selinux labels in
the files I slurped up into my squashfs image, so there shouldn't be
any in the squashfs, so of course that won't work.

I tried compiling CONFIG_SELINUX=n and guess what, it works now.  So
that's at least a work-around for me.

So, for whatever reason, between 5.8 and 5.9, having CONFIG_SELINUX=y
but no security labels on the filesystem became a problem?  Is this
something that needs to get fixed in overlayfs?  Or do you think it's
a deeper problem that needs fixing elsewhere?

At least I'm getting somewhere.  ;-)

Re: failed open: No data available

[Amir Goldstein]

[-- Attachment #1: Type: text/plain, Size: 7662 bytes --]

On Fri, Dec 18, 2020 at 1:47 AM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
> <michael.d.labriola@gmail.com> wrote:
> >
> > On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> > > <michael.d.labriola@gmail.com> wrote:
> > > >
> > > > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > >
> > > > > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> > > > *snip*
> > > > > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> > > > >
> > > > > I honestly don't expect to find much in the existing overlay debug prints
> > > > > but you never know..
> > > > > I suspect you will have to add debug prints to find the problem.
> > > >
> > > > Ok, here goes.  I had to setup a new virtual machine that doesn't use
> > > > overlayfs for its root filesystem because turning on dynamic debug
> > > > gave way too much output for a nice controlled test.  It's exhibiting
> > > > the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> > > > with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> > > > off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
> > > >
> > > >  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> > > >  mount borky2.sqsh t
> > > >  mount -t tmpfs tmp tt
> > > >  mkdir -p tt/upper/{upper,work}
> > > >  mount -t overlay -o \
> > > >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > > > [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> > > > [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> > > > [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> > > > [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> > > > [  164.505216] overlayfs: unlink(work/#3) = 0
> > > > [  164.505217] overlayfs: unlink(work/#4) = 0
> > > > [  164.505221] overlayfs: setxattr(work/work,
> > > > "trusted.overlay.opaque", "0", 1, 0x0) = 0
> > > >
> > > >  touch ttt/FOO
> > > > touch: cannot touch 'ttt/FOO': No data available
> > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
> > > >
> > > > That give you any hints?  I'll start reading through the overlayfs
> > > > code.  I've never actually looked at it, so I'll be planting printk
> > > > calls at random.  ;-)
> > >
> > > We have seen that open("FOO", O_WRONLY) fails
> > > We know that FOO is lower at that time so that brings us to
> > >
> > > ovl_open
> > >   ovl_maybe_copy_up
> > >     ovl_copy_up_flags
> > >       ovl_copy_up_one
> > >         ovl_do_copy_up
> > >           ovl_set_impure
> > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > >           ovl_copy_up_tmpfile
> > >             ovl_do_tmpfile
> > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > >             ovl_copy_up_inode
> > > This must be were we fail and likely in:
> > >               ovl_copy_xattr
> > >                  vfs_getxattr
> > > which can return -ENODATA, but it is not expected because the
> > > xattrs returned by vfs_listxattr should exist...
> > >
> > > So first guess would be to add a debug print for xattr 'name'
> > > and return value of vfs_getxattr().
> >
> > Ok, here we go.  I've added a bunch of printks all over the place.
> > Here's what we've got.  Things are unchanged during mount.  Trying to
> > touch FOO now gives me this:
> >
> > [  114.365444] ovl_open: start
> > [  114.365450] ovl_maybe_copy_up: start
> > [  114.365452] ovl_maybe_copy_up: need copy up
> > [  114.365454] ovl_maybe_copy_up: ovl_want_write succeeded
> > [  114.365459] ovl_copy_up_one: calling ovl_do_copy_up()
> > [  114.365460] ovl_do_copy_up: start
> > [  114.365462] ovl_do_copy_up: impure
> > [  114.365464] ovl_set_impure: start
> > [  114.365484] overlayfs: setxattr(upper/upper,
> > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > [  114.365486] ovl_copy_up_tmpfile: start
> > [  114.365507] overlayfs: tmpfile(work/work, 0100644) = 0
> > [  114.365510] ovl_copy_up_inode: start
> > [  114.365511] ovl_copy_up_inode: ISREG && !metacopy
> > [  114.365625] ovl_copy_xattr: start
> > [  114.365630] ovl_copy_xattr: vfs_listxattr() returned 17
> > [  114.365632] ovl_copy_xattr: buf allocated good
> > [  114.365634] ovl_copy_xattr: vfs_listxattr() returned 17
> > [  114.365636] ovl_copy_xattr: slen=17
> > [  114.365638] ovl_copy_xattr: name='security.selinux'
>
> SELinux?  now that's not suspicious at all...
>
> > [  114.365643] ovl_copy_xattr: vfs_getxattr returned size=-61
> > [  114.365644] ovl_copy_xattr: cleaning up
> > [  114.365647] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > [  114.365649] ovl_copy_up_one: error=-61
> > [  114.365651] ovl_copy_up_one: calling ovl_copy_up_end()
> > [  114.365653] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > [  114.365655] ovl_maybe_copy_up: ovl_copy_up_flags error=-61
> > [  114.365658] ovl_open: ovl_maybe_copy_up error=-61
> > [  114.365728] ovl_copy_up_one: calling ovl_do_copy_up()
> > [  114.365730] ovl_do_copy_up: start
> > [  114.365731] ovl_do_copy_up: impure
> > [  114.365733] ovl_set_impure: start
> > [  114.365735] ovl_copy_up_tmpfile: start
> > [  114.365748] overlayfs: tmpfile(work/work, 0100644) = 0
> > [  114.365750] ovl_copy_up_inode: start
> > [  114.365752] ovl_copy_up_inode: ISREG && !metacopy
> > [  114.365770] ovl_copy_xattr: start
> > [  114.365773] ovl_copy_xattr: vfs_listxattr() returned 17
> > [  114.365774] ovl_copy_xattr: buf allocated good
> > [  114.365776] ovl_copy_xattr: vfs_listxattr() returned 17
> > [  114.365778] ovl_copy_xattr: slen=17
> > [  114.365780] ovl_copy_xattr: name='security.selinux'
> > [  114.365784] ovl_copy_xattr: vfs_getxattr returned size=-61
> > [  114.365785] ovl_copy_xattr: cleaning up
> > [  114.365787] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > [  114.365789] ovl_copy_up_one: error=-61
> > [  114.365790] ovl_copy_up_one: calling ovl_copy_up_end()
> > [  114.365792] ovl_copy_up_flags: ovl_copy_up_one error=-61
> >
> *snip*
>
> So, the selinux stuff made me raise an eyebrow...  I've got selinux
> enabled in my kernel so that it's there if I boot up a RHEL box with
> this kernel.  But I'm using Ubuntu right now, and the rest of SELinux
> is not installed/enabled.  There shouldn't be any selinux labels in
> the files I slurped up into my squashfs image, so there shouldn't be
> any in the squashfs, so of course that won't work.
>
> I tried compiling CONFIG_SELINUX=n and guess what, it works now.  So
> that's at least a work-around for me.
>
> So, for whatever reason, between 5.8 and 5.9, having CONFIG_SELINUX=y
> but no security labels on the filesystem became a problem?  Is this
> something that needs to get fixed in overlayfs?  Or do you think it's
> a deeper problem that needs fixing elsewhere?
>

It's both :)

Attached two patches that should each fix the issue independently,
but we need to apply both. I only tested that they build.
Please verify that each applied individually solves the problem.

The selinux- patch fixes an selinux regression introduced in kernel v5.9
the regression is manifested in your test case but goes beyond overlayfs.

The ovl- patch is a workaround for the selinux regression, but it is also
a micro optimization that doesn't hurt, so worth applying it anyway.

Thanks,
Amir.

[-- Attachment #2: selinux-fix-inconsistency-between-inode_getxattr-and.patch.txt --]
[-- Type: text/plain, Size: 1908 bytes --]

From 7bb54c1ce106de26a1f52bd90dc3464ff1fb4269 Mon Sep 17 00:00:00 2001
From: Amir Goldstein <amir73il@gmail.com>
Date: Fri, 18 Dec 2020 07:41:21 +0200
Subject: [PATCH] selinux: fix inconsistency between inode_getxattr and
 inode_listsecurity

When inode has no listxattr op of its own (e.g. squashfs) vfs_listxattr
calls the LSM inode_listsecurity hooks to list the xattrs that LSMs will
intercept in inode_getxattr hooks.

When selinux LSM is installed but not initialized, it will list the
security.selinux xattr in inode_listsecurity, but will not intercept it
in inode_getxattr.  This results in -ENODATA for a getxattr call for an
xattr returned by listxattr.

This situation was manifested as overlayfs failure to copy up lower
files from squashfs when selinux is built-in but not initialized,
because ovl_copy_xattr() iterates the lower inode xattrs by
vfs_listxattr() and vfs_getxattr().

Match the logic of inode_listsecurity to that of inode_getxattr and
do not list the security.selinux xattr if selinux is not initialized.

Reported-by: Michael Labriola <michael.d.labriola@gmail.com>
Fixes: c8e222616c7e ("selinux: allow reading labels before policy is loaded")
Cc: stable@vger.kernel.org#v5.9+
Signed-off-by: Amir Goldstein <amir73il@gmail.com>
---
 security/selinux/hooks.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/security/selinux/hooks.c b/security/selinux/hooks.c
index 6b1826fc3658..e132e082a5af 100644
--- a/security/selinux/hooks.c
+++ b/security/selinux/hooks.c
@@ -3406,6 +3406,10 @@ static int selinux_inode_setsecurity(struct inode *inode, const char *name,
 static int selinux_inode_listsecurity(struct inode *inode, char *buffer, size_t buffer_size)
 {
 	const int len = sizeof(XATTR_NAME_SELINUX);
+
+	if (!selinux_initialized(&selinux_state))
+		return 0;
+
 	if (buffer && len <= buffer_size)
 		memcpy(buffer, XATTR_NAME_SELINUX, len);
 	return len;
-- 
2.25.1


[-- Attachment #3: ovl-skip-getxattr-of-security-labels.patch.txt --]
[-- Type: text/plain, Size: 2377 bytes --]

From f31097914fc493373c3bc2c344a70e9057911442 Mon Sep 17 00:00:00 2001
From: Amir Goldstein <amir73il@gmail.com>
Date: Fri, 18 Dec 2020 07:41:21 +0200
Subject: [PATCH] ovl: skip getxattr of security labels

When inode has no listxattr op of its own (e.g. squashfs) vfs_listxattr
calls the LSM inode_listsecurity hooks to list the xattrs that LSMs will
intercept in inode_getxattr hooks.

When selinux LSM is installed but not initialized, it will list the
security.selinux xattr in inode_listsecurity, but will not intercept it
in inode_getxattr.  This results in -ENODATA for a getxattr call for an
xattr returned by listxattr.

This situation was manifested as overlayfs failure to copy up lower
files from squashfs when selinux is built-in but not initialized,
because ovl_copy_xattr() iterates the lower inode xattrs by
vfs_listxattr() and vfs_getxattr().

ovl_copy_xattr() skips copy up of security labels that are indentified by
inode_copy_up_xattr LSM hooks, but it does that after vfs_getxattr().
Since we are not going to copy them, skip vfs_getxattr() of the security
labels.

Reported-by: Michael Labriola <michael.d.labriola@gmail.com>
Fixes: c8e222616c7e ("selinux: allow reading labels before policy is loaded")
Cc: stable@vger.kernel.org#v5.9+
Signed-off-by: Amir Goldstein <amir73il@gmail.com>
---
 fs/overlayfs/copy_up.c | 15 ++++++++-------
 1 file changed, 8 insertions(+), 7 deletions(-)

diff --git a/fs/overlayfs/copy_up.c b/fs/overlayfs/copy_up.c
index e5b616c93e11..0fed532efa68 100644
--- a/fs/overlayfs/copy_up.c
+++ b/fs/overlayfs/copy_up.c
@@ -84,6 +84,14 @@ int ovl_copy_xattr(struct super_block *sb, struct dentry *old,
 
 		if (ovl_is_private_xattr(sb, name))
 			continue;
+
+		error = security_inode_copy_up_xattr(name);
+		if (error < 0 && error != -EOPNOTSUPP)
+			break;
+		if (error == 1) {
+			error = 0;
+			continue; /* Discard */
+		}
 retry:
 		size = vfs_getxattr(old, name, value, value_size);
 		if (size == -ERANGE)
@@ -107,13 +115,6 @@ int ovl_copy_xattr(struct super_block *sb, struct dentry *old,
 			goto retry;
 		}
 
-		error = security_inode_copy_up_xattr(name);
-		if (error < 0 && error != -EOPNOTSUPP)
-			break;
-		if (error == 1) {
-			error = 0;
-			continue; /* Discard */
-		}
 		error = vfs_setxattr(new, name, value, size, 0);
 		if (error) {
 			if (error != -EOPNOTSUPP || ovl_must_copy_xattr(name))
-- 
2.25.1

Re: failed open: No data available

[Michael Labriola]

On Fri, Dec 18, 2020 at 2:02 AM Amir Goldstein <amir73il@gmail.com> wrote:
>
> On Fri, Dec 18, 2020 at 1:47 AM Michael Labriola
> <michael.d.labriola@gmail.com> wrote:
> >
> > On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
> > <michael.d.labriola@gmail.com> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > >
> > > > On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> > > > <michael.d.labriola@gmail.com> wrote:
> > > > >
> > > > > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > >
> > > > > > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> > > > > *snip*
> > > > > > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> > > > > >
> > > > > > I honestly don't expect to find much in the existing overlay debug prints
> > > > > > but you never know..
> > > > > > I suspect you will have to add debug prints to find the problem.
> > > > >
> > > > > Ok, here goes.  I had to setup a new virtual machine that doesn't use
> > > > > overlayfs for its root filesystem because turning on dynamic debug
> > > > > gave way too much output for a nice controlled test.  It's exhibiting
> > > > > the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> > > > > with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> > > > > off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
> > > > >
> > > > >  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> > > > >  mount borky2.sqsh t
> > > > >  mount -t tmpfs tmp tt
> > > > >  mkdir -p tt/upper/{upper,work}
> > > > >  mount -t overlay -o \
> > > > >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > > > > [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> > > > > [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> > > > > [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> > > > > [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> > > > > [  164.505216] overlayfs: unlink(work/#3) = 0
> > > > > [  164.505217] overlayfs: unlink(work/#4) = 0
> > > > > [  164.505221] overlayfs: setxattr(work/work,
> > > > > "trusted.overlay.opaque", "0", 1, 0x0) = 0
> > > > >
> > > > >  touch ttt/FOO
> > > > > touch: cannot touch 'ttt/FOO': No data available
> > > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > > [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > >
> > > > > That give you any hints?  I'll start reading through the overlayfs
> > > > > code.  I've never actually looked at it, so I'll be planting printk
> > > > > calls at random.  ;-)
> > > >
> > > > We have seen that open("FOO", O_WRONLY) fails
> > > > We know that FOO is lower at that time so that brings us to
> > > >
> > > > ovl_open
> > > >   ovl_maybe_copy_up
> > > >     ovl_copy_up_flags
> > > >       ovl_copy_up_one
> > > >         ovl_do_copy_up
> > > >           ovl_set_impure
> > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > >           ovl_copy_up_tmpfile
> > > >             ovl_do_tmpfile
> > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > >             ovl_copy_up_inode
> > > > This must be were we fail and likely in:
> > > >               ovl_copy_xattr
> > > >                  vfs_getxattr
> > > > which can return -ENODATA, but it is not expected because the
> > > > xattrs returned by vfs_listxattr should exist...
> > > >
> > > > So first guess would be to add a debug print for xattr 'name'
> > > > and return value of vfs_getxattr().
> > >
> > > Ok, here we go.  I've added a bunch of printks all over the place.
> > > Here's what we've got.  Things are unchanged during mount.  Trying to
> > > touch FOO now gives me this:
> > >
> > > [  114.365444] ovl_open: start
> > > [  114.365450] ovl_maybe_copy_up: start
> > > [  114.365452] ovl_maybe_copy_up: need copy up
> > > [  114.365454] ovl_maybe_copy_up: ovl_want_write succeeded
> > > [  114.365459] ovl_copy_up_one: calling ovl_do_copy_up()
> > > [  114.365460] ovl_do_copy_up: start
> > > [  114.365462] ovl_do_copy_up: impure
> > > [  114.365464] ovl_set_impure: start
> > > [  114.365484] overlayfs: setxattr(upper/upper,
> > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > [  114.365486] ovl_copy_up_tmpfile: start
> > > [  114.365507] overlayfs: tmpfile(work/work, 0100644) = 0
> > > [  114.365510] ovl_copy_up_inode: start
> > > [  114.365511] ovl_copy_up_inode: ISREG && !metacopy
> > > [  114.365625] ovl_copy_xattr: start
> > > [  114.365630] ovl_copy_xattr: vfs_listxattr() returned 17
> > > [  114.365632] ovl_copy_xattr: buf allocated good
> > > [  114.365634] ovl_copy_xattr: vfs_listxattr() returned 17
> > > [  114.365636] ovl_copy_xattr: slen=17
> > > [  114.365638] ovl_copy_xattr: name='security.selinux'
> >
> > SELinux?  now that's not suspicious at all...
> >
> > > [  114.365643] ovl_copy_xattr: vfs_getxattr returned size=-61
> > > [  114.365644] ovl_copy_xattr: cleaning up
> > > [  114.365647] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > > [  114.365649] ovl_copy_up_one: error=-61
> > > [  114.365651] ovl_copy_up_one: calling ovl_copy_up_end()
> > > [  114.365653] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > > [  114.365655] ovl_maybe_copy_up: ovl_copy_up_flags error=-61
> > > [  114.365658] ovl_open: ovl_maybe_copy_up error=-61
> > > [  114.365728] ovl_copy_up_one: calling ovl_do_copy_up()
> > > [  114.365730] ovl_do_copy_up: start
> > > [  114.365731] ovl_do_copy_up: impure
> > > [  114.365733] ovl_set_impure: start
> > > [  114.365735] ovl_copy_up_tmpfile: start
> > > [  114.365748] overlayfs: tmpfile(work/work, 0100644) = 0
> > > [  114.365750] ovl_copy_up_inode: start
> > > [  114.365752] ovl_copy_up_inode: ISREG && !metacopy
> > > [  114.365770] ovl_copy_xattr: start
> > > [  114.365773] ovl_copy_xattr: vfs_listxattr() returned 17
> > > [  114.365774] ovl_copy_xattr: buf allocated good
> > > [  114.365776] ovl_copy_xattr: vfs_listxattr() returned 17
> > > [  114.365778] ovl_copy_xattr: slen=17
> > > [  114.365780] ovl_copy_xattr: name='security.selinux'
> > > [  114.365784] ovl_copy_xattr: vfs_getxattr returned size=-61
> > > [  114.365785] ovl_copy_xattr: cleaning up
> > > [  114.365787] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > > [  114.365789] ovl_copy_up_one: error=-61
> > > [  114.365790] ovl_copy_up_one: calling ovl_copy_up_end()
> > > [  114.365792] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > >
> > *snip*
> >
> > So, the selinux stuff made me raise an eyebrow...  I've got selinux
> > enabled in my kernel so that it's there if I boot up a RHEL box with
> > this kernel.  But I'm using Ubuntu right now, and the rest of SELinux
> > is not installed/enabled.  There shouldn't be any selinux labels in
> > the files I slurped up into my squashfs image, so there shouldn't be
> > any in the squashfs, so of course that won't work.
> >
> > I tried compiling CONFIG_SELINUX=n and guess what, it works now.  So
> > that's at least a work-around for me.
> >
> > So, for whatever reason, between 5.8 and 5.9, having CONFIG_SELINUX=y
> > but no security labels on the filesystem became a problem?  Is this
> > something that needs to get fixed in overlayfs?  Or do you think it's
> > a deeper problem that needs fixing elsewhere?
> >
>
> It's both :)
>
> Attached two patches that should each fix the issue independently,
> but we need to apply both. I only tested that they build.
> Please verify that each applied individually solves the problem.
>
> The selinux- patch fixes an selinux regression introduced in kernel v5.9
> the regression is manifested in your test case but goes beyond overlayfs.
>
> The ovl- patch is a workaround for the selinux regression, but it is also
> a micro optimization that doesn't hurt, so worth applying it anyway.

Ok, as expected, both patches independently fix the problem for me on
my 5.9 kernel.  FYI, applying the ovl patch failed initially
because ovl_is_private_xattr() grew an extra argument in 5.10.

Woohoo!  Thanks, Amir!

-- 
Michael D Labriola
21 Rip Van Winkle Cir
Warwick, RI 02886
401-316-9844 (cell)

Re: failed open: No data available

[Paul Moore]

On Fri, Dec 18, 2020 at 3:50 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
> On Fri, Dec 18, 2020 at 2:02 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > On Fri, Dec 18, 2020 at 1:47 AM Michael Labriola
> > <michael.d.labriola@gmail.com> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
> > > <michael.d.labriola@gmail.com> wrote:
> > > >
> > > > On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > >
> > > > > On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> > > > > <michael.d.labriola@gmail.com> wrote:
> > > > > >
> > > > > > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > > >
> > > > > > > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> > > > > > *snip*
> > > > > > > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > > > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> > > > > > >
> > > > > > > I honestly don't expect to find much in the existing overlay debug prints
> > > > > > > but you never know..
> > > > > > > I suspect you will have to add debug prints to find the problem.
> > > > > >
> > > > > > Ok, here goes.  I had to setup a new virtual machine that doesn't use
> > > > > > overlayfs for its root filesystem because turning on dynamic debug
> > > > > > gave way too much output for a nice controlled test.  It's exhibiting
> > > > > > the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> > > > > > with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> > > > > > off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
> > > > > >
> > > > > >  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> > > > > >  mount borky2.sqsh t
> > > > > >  mount -t tmpfs tmp tt
> > > > > >  mkdir -p tt/upper/{upper,work}
> > > > > >  mount -t overlay -o \
> > > > > >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > > > > > [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> > > > > > [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> > > > > > [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> > > > > > [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> > > > > > [  164.505216] overlayfs: unlink(work/#3) = 0
> > > > > > [  164.505217] overlayfs: unlink(work/#4) = 0
> > > > > > [  164.505221] overlayfs: setxattr(work/work,
> > > > > > "trusted.overlay.opaque", "0", 1, 0x0) = 0
> > > > > >
> > > > > >  touch ttt/FOO
> > > > > > touch: cannot touch 'ttt/FOO': No data available
> > > > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > > > [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > > >
> > > > > > That give you any hints?  I'll start reading through the overlayfs
> > > > > > code.  I've never actually looked at it, so I'll be planting printk
> > > > > > calls at random.  ;-)
> > > > >
> > > > > We have seen that open("FOO", O_WRONLY) fails
> > > > > We know that FOO is lower at that time so that brings us to
> > > > >
> > > > > ovl_open
> > > > >   ovl_maybe_copy_up
> > > > >     ovl_copy_up_flags
> > > > >       ovl_copy_up_one
> > > > >         ovl_do_copy_up
> > > > >           ovl_set_impure
> > > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > >           ovl_copy_up_tmpfile
> > > > >             ovl_do_tmpfile
> > > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > >             ovl_copy_up_inode
> > > > > This must be were we fail and likely in:
> > > > >               ovl_copy_xattr
> > > > >                  vfs_getxattr
> > > > > which can return -ENODATA, but it is not expected because the
> > > > > xattrs returned by vfs_listxattr should exist...
> > > > >
> > > > > So first guess would be to add a debug print for xattr 'name'
> > > > > and return value of vfs_getxattr().
> > > >
> > > > Ok, here we go.  I've added a bunch of printks all over the place.
> > > > Here's what we've got.  Things are unchanged during mount.  Trying to
> > > > touch FOO now gives me this:
> > > >
> > > > [  114.365444] ovl_open: start
> > > > [  114.365450] ovl_maybe_copy_up: start
> > > > [  114.365452] ovl_maybe_copy_up: need copy up
> > > > [  114.365454] ovl_maybe_copy_up: ovl_want_write succeeded
> > > > [  114.365459] ovl_copy_up_one: calling ovl_do_copy_up()
> > > > [  114.365460] ovl_do_copy_up: start
> > > > [  114.365462] ovl_do_copy_up: impure
> > > > [  114.365464] ovl_set_impure: start
> > > > [  114.365484] overlayfs: setxattr(upper/upper,
> > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > [  114.365486] ovl_copy_up_tmpfile: start
> > > > [  114.365507] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > [  114.365510] ovl_copy_up_inode: start
> > > > [  114.365511] ovl_copy_up_inode: ISREG && !metacopy
> > > > [  114.365625] ovl_copy_xattr: start
> > > > [  114.365630] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365632] ovl_copy_xattr: buf allocated good
> > > > [  114.365634] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365636] ovl_copy_xattr: slen=17
> > > > [  114.365638] ovl_copy_xattr: name='security.selinux'
> > >
> > > SELinux?  now that's not suspicious at all...
> > >
> > > > [  114.365643] ovl_copy_xattr: vfs_getxattr returned size=-61
> > > > [  114.365644] ovl_copy_xattr: cleaning up
> > > > [  114.365647] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > > > [  114.365649] ovl_copy_up_one: error=-61
> > > > [  114.365651] ovl_copy_up_one: calling ovl_copy_up_end()
> > > > [  114.365653] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > > > [  114.365655] ovl_maybe_copy_up: ovl_copy_up_flags error=-61
> > > > [  114.365658] ovl_open: ovl_maybe_copy_up error=-61
> > > > [  114.365728] ovl_copy_up_one: calling ovl_do_copy_up()
> > > > [  114.365730] ovl_do_copy_up: start
> > > > [  114.365731] ovl_do_copy_up: impure
> > > > [  114.365733] ovl_set_impure: start
> > > > [  114.365735] ovl_copy_up_tmpfile: start
> > > > [  114.365748] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > [  114.365750] ovl_copy_up_inode: start
> > > > [  114.365752] ovl_copy_up_inode: ISREG && !metacopy
> > > > [  114.365770] ovl_copy_xattr: start
> > > > [  114.365773] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365774] ovl_copy_xattr: buf allocated good
> > > > [  114.365776] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365778] ovl_copy_xattr: slen=17
> > > > [  114.365780] ovl_copy_xattr: name='security.selinux'
> > > > [  114.365784] ovl_copy_xattr: vfs_getxattr returned size=-61
> > > > [  114.365785] ovl_copy_xattr: cleaning up
> > > > [  114.365787] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > > > [  114.365789] ovl_copy_up_one: error=-61
> > > > [  114.365790] ovl_copy_up_one: calling ovl_copy_up_end()
> > > > [  114.365792] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > > >
> > > *snip*
> > >
> > > So, the selinux stuff made me raise an eyebrow...  I've got selinux
> > > enabled in my kernel so that it's there if I boot up a RHEL box with
> > > this kernel.  But I'm using Ubuntu right now, and the rest of SELinux
> > > is not installed/enabled.  There shouldn't be any selinux labels in
> > > the files I slurped up into my squashfs image, so there shouldn't be
> > > any in the squashfs, so of course that won't work.
> > >
> > > I tried compiling CONFIG_SELINUX=n and guess what, it works now.  So
> > > that's at least a work-around for me.
> > >
> > > So, for whatever reason, between 5.8 and 5.9, having CONFIG_SELINUX=y
> > > but no security labels on the filesystem became a problem?  Is this
> > > something that needs to get fixed in overlayfs?  Or do you think it's
> > > a deeper problem that needs fixing elsewhere?
> > >
> >
> > It's both :)
> >
> > Attached two patches that should each fix the issue independently,
> > but we need to apply both. I only tested that they build.
> > Please verify that each applied individually solves the problem.
> >
> > The selinux- patch fixes an selinux regression introduced in kernel v5.9
> > the regression is manifested in your test case but goes beyond overlayfs.
> >
> > The ovl- patch is a workaround for the selinux regression, but it is also
> > a micro optimization that doesn't hurt, so worth applying it anyway.
>
> Ok, as expected, both patches independently fix the problem for me on
> my 5.9 kernel.  FYI, applying the ovl patch failed initially
> because ovl_is_private_xattr() grew an extra argument in 5.10.
>
> Woohoo!  Thanks, Amir!

Hi Amir, thanks for the patches but would you mind sending them to the
list not as attachments so we can review/comment/merge like we
normally do?

-- 
paul moore
www.paul-moore.com

Re: failed open: No data available

[Amir Goldstein]

On Fri, Dec 18, 2020 at 10:47 PM Michael Labriola
<michael.d.labriola@gmail.com> wrote:
>
> On Fri, Dec 18, 2020 at 2:02 AM Amir Goldstein <amir73il@gmail.com> wrote:
> >
> > On Fri, Dec 18, 2020 at 1:47 AM Michael Labriola
> > <michael.d.labriola@gmail.com> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
> > > <michael.d.labriola@gmail.com> wrote:
> > > >
> > > > On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > >
> > > > > On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> > > > > <michael.d.labriola@gmail.com> wrote:
> > > > > >
> > > > > > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > > >
> > > > > > > On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola
> > > > > > *snip*
> > > > > > > > On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein <amir73il@gmail.com> wrote:
> > > > > > > > Thanks, Amir.  I didn't have CONFIG_DYNAMIC_DEBUG enabled, so
> > > > > > >
> > > > > > > I honestly don't expect to find much in the existing overlay debug prints
> > > > > > > but you never know..
> > > > > > > I suspect you will have to add debug prints to find the problem.
> > > > > >
> > > > > > Ok, here goes.  I had to setup a new virtual machine that doesn't use
> > > > > > overlayfs for its root filesystem because turning on dynamic debug
> > > > > > gave way too much output for a nice controlled test.  It's exhibiting
> > > > > > the same behavior as my previous tests (5.8 good, 5.9 bad).  The is
> > > > > > with a freshly compiled 5.9.15 w/ CONFIG_OVERLAY_FS_XINO_AUTO turned
> > > > > > off and CONFIG_DYNAMIC_DEBUG turned on.  Here's what we get:
> > > > > >
> > > > > >  echo "file fs/overlayfs/*  +p" > /sys/kernel/debug/dynamic_debug/control
> > > > > >  mount borky2.sqsh t
> > > > > >  mount -t tmpfs tmp tt
> > > > > >  mkdir -p tt/upper/{upper,work}
> > > > > >  mount -t overlay -o \
> > > > > >     lowerdir=t,upperdir=tt/upper/upper,workdir=tt/upper/work blarg ttt
> > > > > > [  164.505193] overlayfs: mkdir(work/work, 040000) = 0
> > > > > > [  164.505204] overlayfs: tmpfile(work/work, 0100000) = 0
> > > > > > [  164.505209] overlayfs: create(work/#3, 0100000) = 0
> > > > > > [  164.505210] overlayfs: rename(work/#3, work/#4, 0x4)
> > > > > > [  164.505216] overlayfs: unlink(work/#3) = 0
> > > > > > [  164.505217] overlayfs: unlink(work/#4) = 0
> > > > > > [  164.505221] overlayfs: setxattr(work/work,
> > > > > > "trusted.overlay.opaque", "0", 1, 0x0) = 0
> > > > > >
> > > > > >  touch ttt/FOO
> > > > > > touch: cannot touch 'ttt/FOO': No data available
> > > > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > > > [  191.919788] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > > >
> > > > > > That give you any hints?  I'll start reading through the overlayfs
> > > > > > code.  I've never actually looked at it, so I'll be planting printk
> > > > > > calls at random.  ;-)
> > > > >
> > > > > We have seen that open("FOO", O_WRONLY) fails
> > > > > We know that FOO is lower at that time so that brings us to
> > > > >
> > > > > ovl_open
> > > > >   ovl_maybe_copy_up
> > > > >     ovl_copy_up_flags
> > > > >       ovl_copy_up_one
> > > > >         ovl_do_copy_up
> > > > >           ovl_set_impure
> > > > > [  191.919498] overlayfs: setxattr(upper/upper,
> > > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > >           ovl_copy_up_tmpfile
> > > > >             ovl_do_tmpfile
> > > > > [  191.919523] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > >             ovl_copy_up_inode
> > > > > This must be were we fail and likely in:
> > > > >               ovl_copy_xattr
> > > > >                  vfs_getxattr
> > > > > which can return -ENODATA, but it is not expected because the
> > > > > xattrs returned by vfs_listxattr should exist...
> > > > >
> > > > > So first guess would be to add a debug print for xattr 'name'
> > > > > and return value of vfs_getxattr().
> > > >
> > > > Ok, here we go.  I've added a bunch of printks all over the place.
> > > > Here's what we've got.  Things are unchanged during mount.  Trying to
> > > > touch FOO now gives me this:
> > > >
> > > > [  114.365444] ovl_open: start
> > > > [  114.365450] ovl_maybe_copy_up: start
> > > > [  114.365452] ovl_maybe_copy_up: need copy up
> > > > [  114.365454] ovl_maybe_copy_up: ovl_want_write succeeded
> > > > [  114.365459] ovl_copy_up_one: calling ovl_do_copy_up()
> > > > [  114.365460] ovl_do_copy_up: start
> > > > [  114.365462] ovl_do_copy_up: impure
> > > > [  114.365464] ovl_set_impure: start
> > > > [  114.365484] overlayfs: setxattr(upper/upper,
> > > > "trusted.overlay.impure", "y", 1, 0x0) = 0
> > > > [  114.365486] ovl_copy_up_tmpfile: start
> > > > [  114.365507] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > [  114.365510] ovl_copy_up_inode: start
> > > > [  114.365511] ovl_copy_up_inode: ISREG && !metacopy
> > > > [  114.365625] ovl_copy_xattr: start
> > > > [  114.365630] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365632] ovl_copy_xattr: buf allocated good
> > > > [  114.365634] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365636] ovl_copy_xattr: slen=17
> > > > [  114.365638] ovl_copy_xattr: name='security.selinux'
> > >
> > > SELinux?  now that's not suspicious at all...
> > >
> > > > [  114.365643] ovl_copy_xattr: vfs_getxattr returned size=-61
> > > > [  114.365644] ovl_copy_xattr: cleaning up
> > > > [  114.365647] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > > > [  114.365649] ovl_copy_up_one: error=-61
> > > > [  114.365651] ovl_copy_up_one: calling ovl_copy_up_end()
> > > > [  114.365653] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > > > [  114.365655] ovl_maybe_copy_up: ovl_copy_up_flags error=-61
> > > > [  114.365658] ovl_open: ovl_maybe_copy_up error=-61
> > > > [  114.365728] ovl_copy_up_one: calling ovl_do_copy_up()
> > > > [  114.365730] ovl_do_copy_up: start
> > > > [  114.365731] ovl_do_copy_up: impure
> > > > [  114.365733] ovl_set_impure: start
> > > > [  114.365735] ovl_copy_up_tmpfile: start
> > > > [  114.365748] overlayfs: tmpfile(work/work, 0100644) = 0
> > > > [  114.365750] ovl_copy_up_inode: start
> > > > [  114.365752] ovl_copy_up_inode: ISREG && !metacopy
> > > > [  114.365770] ovl_copy_xattr: start
> > > > [  114.365773] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365774] ovl_copy_xattr: buf allocated good
> > > > [  114.365776] ovl_copy_xattr: vfs_listxattr() returned 17
> > > > [  114.365778] ovl_copy_xattr: slen=17
> > > > [  114.365780] ovl_copy_xattr: name='security.selinux'
> > > > [  114.365784] ovl_copy_xattr: vfs_getxattr returned size=-61
> > > > [  114.365785] ovl_copy_xattr: cleaning up
> > > > [  114.365787] ovl_copy_up_inode: ovl_copy_xattr error=-61
> > > > [  114.365789] ovl_copy_up_one: error=-61
> > > > [  114.365790] ovl_copy_up_one: calling ovl_copy_up_end()
> > > > [  114.365792] ovl_copy_up_flags: ovl_copy_up_one error=-61
> > > >
> > > *snip*
> > >
> > > So, the selinux stuff made me raise an eyebrow...  I've got selinux
> > > enabled in my kernel so that it's there if I boot up a RHEL box with
> > > this kernel.  But I'm using Ubuntu right now, and the rest of SELinux
> > > is not installed/enabled.  There shouldn't be any selinux labels in
> > > the files I slurped up into my squashfs image, so there shouldn't be
> > > any in the squashfs, so of course that won't work.
> > >
> > > I tried compiling CONFIG_SELINUX=n and guess what, it works now.  So
> > > that's at least a work-around for me.
> > >
> > > So, for whatever reason, between 5.8 and 5.9, having CONFIG_SELINUX=y
> > > but no security labels on the filesystem became a problem?  Is this
> > > something that needs to get fixed in overlayfs?  Or do you think it's
> > > a deeper problem that needs fixing elsewhere?
> > >
> >
> > It's both :)
> >
> > Attached two patches that should each fix the issue independently,
> > but we need to apply both. I only tested that they build.
> > Please verify that each applied individually solves the problem.
> >
> > The selinux- patch fixes an selinux regression introduced in kernel v5.9
> > the regression is manifested in your test case but goes beyond overlayfs.
> >
> > The ovl- patch is a workaround for the selinux regression, but it is also
> > a micro optimization that doesn't hurt, so worth applying it anyway.
>
> Ok, as expected, both patches independently fix the problem for me on
> my 5.9 kernel.

Great. I'll add your Tested-by and post.

> FYI, applying the ovl patch failed initially
> because ovl_is_private_xattr() grew an extra argument in 5.10.
>

Good to know, I'll remove the cc:stable because the overlayfs patch
is not really a regression fix. as I wrote it is just a nice to have
micro optimization that doesn't need to be applied to v5.9.

> Woohoo!  Thanks, Amir!

Thank you for the report and help in nailing this strange regression!

Amir.