Re: failed open: No data available

On Fri, Dec 18, 2020 at 1:47 AM Michael Labriola
[off-list ref] wrote:

On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
[off-list ref] wrote:

quoted

On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein [off-list ref] wrote:

quoted

On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
[off-list ref] wrote:

quoted

On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein [off-list ref] wrote:

quoted

On Thu, Dec 17, 2020 at 6:22 PM Michael Labriola

*snip*

quoted

quoted

On Thu, Dec 17, 2020 at 7:00 AM Amir Goldstein [off-list ref] 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...

quoted

[  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.