Re: failed open: No data available

[Amir Goldstein <amir73il@gmail.com>]

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.