Message-ID: <CAMz9Wg8bhCG=qSLia943dwr=LV7Kum=bZPq2s_2coV6a_bmDeA@mail.gmail.com>
Date:   Wed, 6 Sep 2023 14:26:30 +0800
From:   AceLan Kao <acelan@...il.com>
To:     Mariusz Tkaczyk <mariusz.tkaczyk@...ux.intel.com>
Cc:     Yu Kuai <yukuai1@...weicloud.com>, Song Liu <song@...nel.org>,
        Guoqing Jiang <guoqing.jiang@...ux.dev>,
        Bagas Sanjaya <bagasdotme@...il.com>,
        Christoph Hellwig <hch@....de>,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Linux Regressions <regressions@...ts.linux.dev>,
        Linux RAID <linux-raid@...r.kernel.org>,
        "yukuai (C)" <yukuai3@...wei.com>
Subject: Re: Infiniate systemd loop when power off the machine with multiple
 MD RAIDs

Hi,

Mariusz Tkaczyk <mariusz.tkaczyk@...ux.intel.com> 於 2023年8月31日 週四 下午2:51寫道：
>
> On Thu, 31 Aug 2023 10:28:44 +0800
> Yu Kuai <yukuai1@...weicloud.com> wrote:
>
> > Hi, Acelan,
> >
> > 在 2023/08/28 21:50, Yu Kuai 写道:
> > > Hi,
> > >
> > > 在 2023/08/28 13:20, Song Liu 写道:
> > >> Hi AceLan,
> > >>
> > >> Thanks for running the experiments.
> > >>
> > >> On Fri, Aug 25, 2023 at 9:32 PM AceLan Kao <acelan@...il.com> wrote:
> > >> [...]
> > >>>>
> > >>>> Could you please run the follow two experiments?
> > >>>>
> > >>>> 1. Confirm 12a6caf273240a triggers this. Specifically:
> > >>>>     git checkout 12a6caf273240a => repros
> > >>>>     git checkout 12a6caf273240a~1 => cannot repro
> > >>> Yes, I'm pretty sure about this, that's my bisect result and I just
> > >>> confirmed it again.
> > >>> I also tried reverting 12a6caf273240a and the issue is gone.
> > >>
> > >> The log doesn't match my guess. Specifically:
> > >>
> > >> [  420.068142] systemd-shutdown[1]: Stopping MD /dev/md123 (9:123).
> > >> [  420.074718] md_open:md123 openers++ = 1 by systemd-shutdow
> > >> [  420.080787] systemd-shutdown[1]: Failed to sync MD block device
> > >> /dev/md123, ignoring: Input/output error
> > >> [  420.090831] md: md123 stopped.
> > >> [  420.094465] systemd-shutdown[1]: Stopping MD /dev/md122 (9:122).
> > >> [  420.101045] systemd-shutdown[1]: Could not stop MD /dev/md122:
> > >> Device or resource busy
> > >
> > > I see that:
> > >
> > > systemd-shutdown[1]: Couldn't finalize remaining  MD devices, trying again.
> > >
> > > Can we make sure is this why power off hang?
> > >
> > > Because in my VM, power off is not hang and I got:
> > >
> > > systemd-shutdown[1]: Could not stop MD /dev/md1: Device or resource busy
> > > systemd-shutdown[1]: Failed to finalize MD devices, ignoring.
> > >>
> > >> For a successful stop on md123, we reach the pr_info() in md_open().
> > >> For a failed stop on md122, the kernel returns -EBUSY before that
> > >> pr_info() in md_open(). There are some changes in md_open() in
> > >> the past few release, so I am not quite sure we are looking at the
> > >> same code.
> > >
> > > By the way, based on code review, looks like md_open never return
> > > -EBUSY, and I think following is the only place can return -EBUSY before
> > > md_open() is called:
> > >
> > > blkdev_open
> > >   blkdev_get_by_dev
> > >    bd_prepare_to_claim
> > >     bd_may_claim     -> -EBUSY
> > >
> > > Acelan, can you add following debug patch on the top of Song's patch
> > > and reporduce it again? Hope it'll confirm why stop array failed with
> > > -EBUSY.
> > >
> >
> > I saw your reply:
> >
> > https://lore.kernel.org/all/CAMz9Wg9VXJzZkKWCosm0_=Rz6gG9r3pCMrhvBZQVCQb8i0kd-w@mail.gmail.com/
> >
> > But I didn't recieve you emails, please reply to me through this email
> > address: yukuai3@...wei.com. yukuai1@...weicloud.com is just used for
> > sending, and I always missing emails from huaweicloud.com, my apologize
> > for this inconvenience, I have to do it this way due to my company
> > policy.
> >
> > There is something interesting on test result:
> >
> > At first, md122 is the root device, I guess this is why I can't repoduce
> > this problem in my local VM.
> > [   14.478619] systemd-gpt-auto-generator[585]: md122p3: Root device
> > /dev/md122.
> > [   14.481823] block md122: the capability attribute has been deprecated.
> >
> > Then, before trying to stop md122, following log shows that md122 is
> > still mounted:
> > [ 1368.369926] [3462]: Remounting '/' read-only with options
> > 'errors=remount-ro,stripe=128'.
> > [ 1368.396287] EXT4-fs (md122p3): re-mounted
> > 6d53dc8e-3f45-4efa-bc0e-4af477fac217 ro. Quota mode: none.
> >
> > And since then, there is no log aboug md_open(), which means no one
> > ever open md122 since this remount.
> >
> > At last, there are lots of log shows that md122 can't be opened
> > exclusively:
> > [ 1368.812952] md122:systemd-shutdow bd_prepare_to_claim return -16
> > [ 1368.819189] md122:systemd-shutdow blkdev_get_by_dev return -16
> >
> > Which indicate that md122 is still mounted, and systemd-shutdow can't
> > stop this array. This behaviour looks correct to me, because rootfs
> > can't be umounted while systemd-shutdown is still running.
> >
> > However, there are some questions I don't have answers for now, I'm not
> > familiar with how systemd works:
> >
> > 1) In the normal case that raid is root device, how can systemd-shutdown
> > make progress and how is rootfs unmounted?
>
> Thanks for digging into!
>
> In that case systemd-shutdown should skip this device. It should be umounted by
> dracut. systemd-shutdown implements naive way to try stop MD devices, simple
> ioctl(fd, STOP_ARRAY, NULL).
> We are expecting failure if resource is still mounted.
>
> Here dracut code:
> https://github.com/dracutdevs/dracut/blob/master/modules.d/90mdraid/md-shutdown.sh
>
> Ohh, it is ubuntu so it is handled by initramfs-tools not by dracut, but I hope
> you will find it useful for the future.
>
> and system-shutdown:
> https://github.com/systemd/systemd/blob/main/src/shutdown/shutdown.c#L483C7-L483C7
>
> When the functionality in systemd-shutdown was fixed by me, I asked if we can
> make it configurable- Lennart disagreed so there is now way to disable it now.
>
> > 2) How does this scenario related to commit 12a6caf273240a.
>
> I'm unable to reproduce it on Redhat, Ubuntu is on the way now.
> I'm starting to be convinced that it could be related with initramfs-tools but
> I cannot prove this theory yet. I need to reproduce the issue first.
>
> Thanks,
> Mariusz
> >
> > I must read systemd source code to get answers, and it'll be appreciated
> > if someone has answers.
> >
> > Thanks,
> > Kuai
> >
> > > diff --git a/block/bdev.c b/block/bdev.c
> > > index 979e28a46b98..699739223dcb 100644
> > > --- a/block/bdev.c
> > > +++ b/block/bdev.c
> > > @@ -789,8 +789,11 @@ struct block_device *blkdev_get_by_dev(dev_t dev,
> > > blk_mode_t mode, void *holder,
> > >          if (holder) {
> > >                  mode |= BLK_OPEN_EXCL;
> > >                  ret = bd_prepare_to_claim(bdev, holder, hops);
> > > -               if (ret)
> > > +               if (ret) {
> > > +                       pr_warn("%s:%s bd_prepare_to_claim return %d\n",
> > > +                               disk->disk_name, current->comm, ret);
> > >                          goto put_blkdev;
> > > +               }
> > >          } else {
> > >                  if (WARN_ON_ONCE(mode & BLK_OPEN_EXCL)) {
> > >                          ret = -EIO;
> > > diff --git a/block/fops.c b/block/fops.c
> > > index eaa98a987213..2d69119c71f6 100644
> > > --- a/block/fops.c
> > > +++ b/block/fops.c
> > > @@ -587,8 +587,11 @@ static int blkdev_open(struct inode *inode, struct
> > > file *filp)
> > >
> > >          bdev = blkdev_get_by_dev(inode->i_rdev, file_to_blk_mode(filp),
> > >                                   filp->private_data, NULL);
> > > -       if (IS_ERR(bdev))
> > > +       if (IS_ERR(bdev)) {
> > > +               pr_warn("%pD:%s blkdev_get_by_dev return %ld\n",
> > > +                       filp, current->comm, PTR_ERR(bdev));
> > >                  return PTR_ERR(bdev);
> > > +       }
> > >
> > >          if (bdev_nowait(bdev))
> > >                  filp->f_mode |= FMODE_NOWAIT;
> > >
> > > Thanks,
> > > Kuai
> > >
> > >>
> > >> Therefore, could you please help clarify:
> > >>
> > >> 1. Which base kernel are you using?
> > >>
> > >>> From the log, you are using 6.5-rc7-706a74159504. However,
> > >> I think we cannot cleanly revert 12a6caf273240a on top of
> > >> 6.5-rc7-706a74159504. Did you manually fix some issue in the
> > >> revert? If so, could you please share the revert commit?
> > >>
> > >> 2. If you are not using 6.5-rc7-706a74159504 as base kernel, which
> > >> one are you using?
> > >>
> > >> Thanks,
> > >> Song
> > >>
> > >>>
> > >>>>
> > >>>> 2. Try with the following change (add debug messages), which hopefully
> > >>>>     shows which command is holding a reference on mddev->openers.
> > >>>>
> > >>>> Thanks,
> > >>>> Song
> > >>>>
> > >>>> diff --git i/drivers/md/md.c w/drivers/md/md.c
> > >>>> index 78be7811a89f..3e9b718b32c1 100644
> > >>>> --- i/drivers/md/md.c
> > >>>> +++ w/drivers/md/md.c
> > >>>> @@ -7574,11 +7574,15 @@ static int md_ioctl(struct block_device *bdev,
> > >>>> blk_mode_t mode,
> > >>>>                  if (mddev->pers && atomic_read(&mddev->openers) > 1) {
> > >>>>                          mutex_unlock(&mddev->open_mutex);
> > >>>>                          err = -EBUSY;
> > >>>> +                       pr_warn("%s return -EBUSY for %s with
> > >>>> mddev->openers = %d\n",
> > >>>> +                               __func__, mdname(mddev),
> > >>>> atomic_read(&mddev->openers));
> > >>>>                          goto out;
> > >>>>                  }
> > >>>>                  if (test_and_set_bit(MD_CLOSING, &mddev->flags)) {
> > >>>>                          mutex_unlock(&mddev->open_mutex);
> > >>>>                          err = -EBUSY;
> > >>>> +                       pr_warn("%s return -EBUSY for %s with
> > >>>> MD_CLOSING bit set\n",
> > >>>> +                               __func__, mdname(mddev));
> > >>>>                          goto out;
> > >>>>                  }
> > >>>>                  did_set_md_closing = true;
> > >>>> @@ -7789,6 +7793,8 @@ static int md_open(struct gendisk *disk,
> > >>>> blk_mode_t mode)
> > >>>>                  goto out_unlock;
> > >>>>
> > >>>>          atomic_inc(&mddev->openers);
> > >>>> +       pr_info("%s:%s openers++ = %d by %s\n", __func__,
> > >>>> mdname(mddev),
> > >>>> +               atomic_read(&mddev->openers), current->comm);
> > >>>>          mutex_unlock(&mddev->open_mutex);
> > >>>>
> > >>>>          disk_check_media_change(disk);
> > >>>> @@ -7807,6 +7813,8 @@ static void md_release(struct gendisk *disk)
> > >>>>
> > >>>>          BUG_ON(!mddev);
> > >>>>          atomic_dec(&mddev->openers);
> > >>>> +       pr_info("%s:%s openers-- = %d by %s\n", __func__,
> > >>>> mdname(mddev),
> > >>>> +               atomic_read(&mddev->openers), current->comm);
> > >>>>          mddev_put(mddev);
> > >>>>   }
> > >>> It's pretty strange that I can't reproduce the issue after applied
> > >>> the patch.
> > >>>
> > >>> I tried to figure out which part affect the issue and found when I
> > >>> comment out the pr_info() In md_release(), the issue could be
> > >>> reproduced.
> > >>>
>From previous testing, I don't think it's an issue in systemd, so I
did a simple test and found the issue is gone.
You only need to add a small delay in md_release(), then the issue
can't be reproduced.

diff --git a/drivers/md/md.c b/drivers/md/md.c
index 78be7811a89f..ef47e34c1af5 100644
--- a/drivers/md/md.c
+++ b/drivers/md/md.c
@@ -7805,6 +7805,7 @@ static void md_release(struct gendisk *disk)
{
       struct mddev *mddev = disk->private_data;

+       msleep(10);
       BUG_ON(!mddev);
       atomic_dec(&mddev->openers);
       mddev_put(mddev);

Powered by blists - more mailing lists