On Thu, Dec 17, 2020 at 4:56 PM Michael Labriola
<michael.d.labriola@xxxxxxxxx> wrote:
>
> On Thu, Dec 17, 2020 at 3:25 PM Amir Goldstein <amir73il@xxxxxxxxx> wrote:
> >
> > On Thu, Dec 17, 2020 at 9:46 PM Michael Labriola
> > <michael.d.labriola@xxxxxxxxx> wrote:
> > >
> > > On Thu, Dec 17, 2020 at 1:07 PM Amir Goldstein <amir73il@xxxxxxxxx> 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@xxxxxxxxx> 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. ;-)
