MD array keeps resyncing after rebooting

MD array keeps resyncing after rebooting

[Francis Moreau]

Hello,

I'm using a RAID1 with DDF metadata format. The array has been
initialized by the bios and contains my root partition.

After booting I waited for the RAID1 array to finish syncing then rebooting.

Then I rebooted but the sync restarts again:

# cat /proc/mdstat
Personalities : [raid1]
md126 : active raid1 sdb[1] sda[0]
      975585280 blocks super external:/md127/0 [2/2] [UU]
      [=>...................]  resync =  7.3% (71783424/975585280)
finish=112.1min speed=134299K/sec

md127 : inactive sdb[1](S) sda[0](S)
      2354608 blocks super external:ddf

unused devices: <none>

Could anybody tell me what's happening ?

Thanks
--
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

On Tue, Jul 23, 2013 at 11:46 AM, Francis Moreau <francis.moro@gmail.com> wrote:
> Hello,
>
> I'm using a RAID1 with DDF metadata format. The array has been
> initialized by the bios and contains my root partition.
>
> After booting I waited for the RAID1 array to finish syncing then rebooting.
>
> Then I rebooted but the sync restarts again:
>
> # cat /proc/mdstat
> Personalities : [raid1]
> md126 : active raid1 sdb[1] sda[0]
>       975585280 blocks super external:/md127/0 [2/2] [UU]
>       [=>...................]  resync =  7.3% (71783424/975585280)
> finish=112.1min speed=134299K/sec
>
> md127 : inactive sdb[1](S) sda[0](S)
>       2354608 blocks super external:ddf
>
> unused devices: <none>
>
> Could anybody tell me what's happening ?
>

More information taken from kernel logs:

[    2.175802] SCSI subsystem initialized
[    2.178912] libata version 3.00 loaded.
[    2.184876] isci: Intel(R) C600 SAS Controller Driver - version 1.1.0
[    2.185057] isci 0000:0e:00.0: driver configured for rev: 6 silicon
[    2.185212] isci 0000:0e:00.0: OEM SAS parameters (version: 1.3)
loaded (firmware)
[    2.188451] isci 0000:0e:00.0: SCU controller 0: phy 3-0 cables:
{short, short, short, short}
[    2.191041] scsi0 : isci
[    2.191755] isci 0000:0e:00.0: irq 71 for MSI/MSI-X
[    2.191764] isci 0000:0e:00.0: irq 72 for MSI/MSI-X
[    2.442020] Refined TSC clocksource calibration: 1799.999 MHz.
[    2.442059] sas: phy-0:0 added to port-0:0, phy_mask:0x1 (5fcfffff00000001)
[    2.442141] Switching to clocksource tsc
[    2.491953] sas: DOING DISCOVERY on port 0, pid:5
[    2.491976] sas: DONE DISCOVERY on port 0, pid:5, result:0
[    2.491985] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[    2.492191] sas: ata1: end_device-0:0: dev error handler
[    2.842323] ata1.00: ATA-8: ST1000NM0011         81Y9807
81Y3867IBM, BB4A, max UDMA/133
[    2.842469] ata1.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[    2.843622] ata1.00: configured for UDMA/133
[    2.843791] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0
[    2.861663] scsi 0:0:0:0: Direct-Access     ATA      ST1000NM0011
  BB4A PQ: 0 ANSI: 5
[    2.865250] ahci 0000:00:1f.2: version 3.0
[    2.865352] ahci 0000:00:1f.2: irq 73 for MSI/MSI-X
[    2.865408] ahci 0000:00:1f.2: AHCI 0001.0300 32 slots 6 ports 1.5
Gbps 0x1 impl SATA mode
[    2.865555] ahci 0000:00:1f.2: flags: 64bit ncq sntf led clo pio
slum part ems apst
[    2.865700] ahci 0000:00:1f.2: setting latency timer to 64
[    2.866183] scsi1 : ahci
[    2.866466] scsi2 : ahci
[    2.866746] scsi3 : ahci
[    2.867032] scsi4 : ahci
[    2.867316] scsi5 : ahci
[    2.867562] scsi6 : ahci
[    2.867722] ata2: SATA max UDMA/133 abar m2048@0x902ff000 port
0x902ff100 irq 73
[    2.867865] ata3: DUMMY
[    2.867973] ata4: DUMMY
[    2.868081] ata5: DUMMY
[    2.868188] ata6: DUMMY
[    2.868296] ata7: DUMMY
[    3.210812] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    3.211262] ata2.00: ATAPI: IBM SATA DEVICE 81Y3666, IB00, max UDMA/100
[    3.212441] ata2.00: configured for UDMA/100
[    3.214231] scsi 1:0:0:0: CD-ROM            IBM SATA DEVICE 81Y3666
  IB00 PQ: 0 ANSI: 5
[    3.284669] sd 0:0:0:0: [sda] 1953525168 512-byte logical blocks:
(1.00 TB/931 GiB)
[    3.284855] sd 0:0:0:0: [sda] Write Protect is off
[    3.284970] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    3.285008] sd 0:0:0:0: [sda] Write cache: disabled, read cache:
enabled, doesn't support DPO or FUA
[    3.402209] md: bind<sda>
[    3.408409] md: bind<sda>
[    3.430547] sas: phy-0:1 added to port-0:1, phy_mask:0x2 (5fcfffff00000002)
[    3.430564] sas: DOING DISCOVERY on port 1, pid:88
[    3.430647] sas: DONE DISCOVERY on port 1, pid:88, result:0
[    3.430694] sas: Enter sas_scsi_recover_host busy: 0 failed: 0
[    3.430741] sas: ata1: end_device-0:0: dev error handler
[    3.430754] sas: ata8: end_device-0:1: dev error handler
[    3.660124] usb 1-1: new high-speed USB device number 2 using ehci_hcd
[    3.810483] usb 1-1: New USB device found, idVendor=8087, idProduct=0024
[    3.810605] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.811114] hub 1-1:1.0: USB hub found
[    3.811313] hub 1-1:1.0: 6 ports detected
[    3.850059] ata8.00: ATA-8: WD1003FBYX-23        81Y9807
81Y3867IBM,     WB35, max UDMA/133
[    3.850207] ata8.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[    3.851914] ata8.00: configured for UDMA/133
[    3.852068] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 0
[    3.870029] scsi 0:0:1:0: Direct-Access     ATA      WD1003FBYX-23
  n/a  PQ: 0 ANSI: 5
[    3.870326] sd 0:0:1:0: [sdb] 1953525168 512-byte logical blocks:
(1.00 TB/931 GiB)
[    3.870710] sd 0:0:1:0: [sdb] Write Protect is off
[    3.870827] sd 0:0:1:0: [sdb] Mode Sense: 00 3a 00 00
[    3.870862] sd 0:0:1:0: [sdb] Write cache: disabled, read cache:
enabled, doesn't support DPO or FUA
[    3.899616]  sdb: sdb1 sdb2 < sdb5 sdb6 >
[    3.900677] sd 0:0:1:0: [sdb] Attached SCSI disk
[    3.929662] usb 2-1: new high-speed USB device number 2 using ehci_hcd
[    3.976356] md: bind<sdb>
[    3.980302] md: bind<sdb>
[    3.980487] md: export_rdev(sda)
[    3.982381] md: raid1 personality registered for level 1
[    3.982798] bio: create slab <bio-1> at 1
[    3.983026] md/raid1:md126: not clean -- starting background reconstruction
[    3.983155] md/raid1:md126: active with 2 out of 2 mirrors
[    3.983288] md126: detected capacity change from 0 to 998999326720
[    3.984714]  md126: p1 p2 < p5 p6 >
[    4.362728] md: md126 switched to read-write mode.
[    4.362980] md: resync of RAID array md126
[    4.363107] md: minimum _guaranteed_  speed: 1000 KB/sec/disk.
[    4.363224] md: using maximum available idle IO bandwidth (but not
more than 200000 KB/sec) for resync.
[    4.363437] md: using 128k window, over a total of 975585280k.

Thanks
--
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

Which MD version are you using?

What you describe looks suspiciously like the problem I tried to solve
with my patch "DDF: use existing locations for primary and secondary DDF
structure".

Please give the current git version of mdadm a try.

Martin

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

On 07/23/2013 08:52 PM, Martin Wilck wrote:
> Which MD version are you using?

I meant: which mdadm version. Sorry.

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin

On Tue, Jul 23, 2013 at 8:52 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 07/23/2013 08:52 PM, Martin Wilck wrote:
>> Which MD version are you using?
>
> I meant: which mdadm version. Sorry.
>

I'm using mdadm version 3.2.3

I'll give the current git version a try tomorrow.

The thing is that I need to wait the sync to finish in order to test
this problem. But the sync takes a while (> 4 hours, I don't remember
exactly). Are there any ways to speed up the process ?

Thanks
--
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

On 07/23/2013 10:01 PM, Francis Moreau wrote:
> Hello Martin
> 
> On Tue, Jul 23, 2013 at 8:52 PM, Martin Wilck <mwilck@arcor.de> wrote:
>> On 07/23/2013 08:52 PM, Martin Wilck wrote:
>>> Which MD version are you using?
>>
>> I meant: which mdadm version. Sorry.
>>
> 
> I'm using mdadm version 3.2.3
> 
> I'll give the current git version a try tomorrow.
> 
> The thing is that I need to wait the sync to finish in order to test
> this problem. But the sync takes a while (> 4 hours, I don't remember
> exactly). Are there any ways to speed up the process ?

MD will adjust its speed while initializing, thus the fastest way is to
do nothing on the system, avoiding any other disk IO. This will cause MD
to use max bandwidth.

One thing you can do for testing is to create a smaller array which will
of course initialize faster.

Please run mdadm -E /dev/sdX for all RAID disks before and after reboot
and watch out for differences.

Martin

> 
> Thanks
> --
> Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

On Tue, Jul 23, 2013 at 11:21 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 07/23/2013 10:01 PM, Francis Moreau wrote:
>> Hello Martin
>>
>> On Tue, Jul 23, 2013 at 8:52 PM, Martin Wilck <mwilck@arcor.de> wrote:
>>> On 07/23/2013 08:52 PM, Martin Wilck wrote:
>>>> Which MD version are you using?
>>>
>>> I meant: which mdadm version. Sorry.
>>>
>>
>> I'm using mdadm version 3.2.3
>>
>> I'll give the current git version a try tomorrow.
>>
>> The thing is that I need to wait the sync to finish in order to test
>> this problem. But the sync takes a while (> 4 hours, I don't remember
>> exactly). Are there any ways to speed up the process ?
>
> MD will adjust its speed while initializing, thus the fastest way is to
> do nothing on the system, avoiding any other disk IO. This will cause MD
> to use max bandwidth.
>
> One thing you can do for testing is to create a smaller array which will
> of course initialize faster.

Unfortunately I can't do that: the array was created by the BIOS and
AFAICS it does on the whole disks.

>
> Please run mdadm -E /dev/sdX for all RAID disks before and after reboot
> and watch out for differences.

Will do.

Thanks.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

On Wed, Jul 24, 2013 at 6:32 AM, Francis Moreau <francis.moro@gmail.com> wrote:
> On Tue, Jul 23, 2013 at 11:21 PM, Martin Wilck <mwilck@arcor.de> wrote:
>> On 07/23/2013 10:01 PM, Francis Moreau wrote:
>>> Hello Martin
>>>
>>> On Tue, Jul 23, 2013 at 8:52 PM, Martin Wilck <mwilck@arcor.de> wrote:
>>>> On 07/23/2013 08:52 PM, Martin Wilck wrote:
>>>>> Which MD version are you using?
>>>>
>>>> I meant: which mdadm version. Sorry.
>>>>
>>>
>>> I'm using mdadm version 3.2.3
>>>
>>> I'll give the current git version a try tomorrow.
>>>
>>> The thing is that I need to wait the sync to finish in order to test
>>> this problem. But the sync takes a while (> 4 hours, I don't remember
>>> exactly). Are there any ways to speed up the process ?
>>
>> MD will adjust its speed while initializing, thus the fastest way is to
>> do nothing on the system, avoiding any other disk IO. This will cause MD
>> to use max bandwidth.
>>
>> One thing you can do for testing is to create a smaller array which will
>> of course initialize faster.
>
> Unfortunately I can't do that: the array was created by the BIOS and
> AFAICS it does on the whole disks.
>
>>
>> Please run mdadm -E /dev/sdX for all RAID disks before and after reboot
>> and watch out for differences.
>
> Will do.
>

So I let the sync to finish, it was with my old version of mdadm (3.2.3).

While syncing, I installed the latest mdadm git version:

 $ mdadm --version
 mdadm - v3.3-rc1-94-g4441541 - 23th July 2013

Note that I only installed the 2 binaries mdadm/mdmon, I leave the
udev rules for md devices untouched.

I regenerated the initramfs in order to use the new binaries when
booting and now I can see some new warnings:

  $ dracut -f
  mdmon: Failed to load secondary DDF header on /dev/block/8:0
  mdmon: Failed to load secondary DDF header on /dev/block/8:16
  ...

I ignored them for now.

Now the latest version of mdadm is used :

  $ cat /proc/mdstat
  Personalities : [raid1]
  md126 : active raid1 sdb[1] sda[0]
        975585280 blocks super external:/md127/0 [2/2] [UU]

  md127 : inactive sdb[1](S) sda[0](S)
        2354608 blocks super external:ddf

I run mdadm -E /dev/sdX for all RAID disks before and after reboot.
I'm still having this warning:

   mdmon: Failed to load secondary DDF header on /dev/sda

You can find the differences below:

diff -Nurp before/sda.txt after/sda.txt
--- before/sda.txt      2013-07-24 15:15:33.304015379 +0200
+++ after/sda.txt       2013-07-24 15:49:09.520132838 +0200
@@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
   Redundant hdr : yes
   Virtual Disks : 1

-      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
-                  (LSI      07/24/13 12:18:08)
+      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
+                  (LSI      07/24/13 15:43:29)
          unit[0] : 0
         state[0] : Optimal, Not Consistent
-   init state[0] : Fully Initialised
+   init state[0] : Not Initialised
        access[0] : Read/Write
          Name[0] : array0
  Raid Devices[0] : 2 (0 1)
diff -Nurp before/sdb.txt after/sdb.txt
--- before/sdb.txt      2013-07-24 15:17:50.300581049 +0200
+++ after/sdb.txt       2013-07-24 15:49:15.159997204 +0200
@@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
   Redundant hdr : yes
   Virtual Disks : 1

-      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
-                  (LSI      07/24/13 12:18:08)
+      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
+                  (LSI      07/24/13 15:43:29)
          unit[0] : 0
         state[0] : Optimal, Not Consistent
-   init state[0] : Fully Initialised
+   init state[0] : Not Initialised
        access[0] : Read/Write
          Name[0] : array0
  Raid Devices[0] : 2 (0 1)


Does this help ?

Thanks
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

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

On 07/24/2013 03:50 PM, Francis Moreau wrote:

> I regenerated the initramfs in order to use the new binaries when
> booting and now I can see some new warnings:
> 
>   $ dracut -f
>   mdmon: Failed to load secondary DDF header on /dev/block/8:0
>   mdmon: Failed to load secondary DDF header on /dev/block/8:16
>   ...
> 
> I ignored them for now.

The message is non-fatal. But is certainly strange, given that you have
a LSI BIOS. It looks as if something was wrong with your secondary
header. You may try the attached patch to understand the problem better.

> Now the latest version of mdadm is used :
> 
>   $ cat /proc/mdstat
>   Personalities : [raid1]
>   md126 : active raid1 sdb[1] sda[0]
>         975585280 blocks super external:/md127/0 [2/2] [UU]
> 
>   md127 : inactive sdb[1](S) sda[0](S)
>         2354608 blocks super external:ddf

So you did another rebuild of the array with the updated mdadm?

> I run mdadm -E /dev/sdX for all RAID disks before and after reboot.
> I'm still having this warning:
> 
>    mdmon: Failed to load secondary DDF header on /dev/sda
> 
> You can find the differences below:
> 
> diff -Nurp before/sda.txt after/sda.txt
> --- before/sda.txt      2013-07-24 15:15:33.304015379 +0200
> +++ after/sda.txt       2013-07-24 15:49:09.520132838 +0200
> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>    Redundant hdr : yes
>    Virtual Disks : 1
> 
> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
> -                  (LSI      07/24/13 12:18:08)
> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
> +                  (LSI      07/24/13 15:43:29)

This is weird. it looks as if the array had been recreated by the BIOS.
Normally the GUID should stay constant over reboots.

>           unit[0] : 0
>          state[0] : Optimal, Not Consistent
> -   init state[0] : Fully Initialised

Not Consistent and Fully Initialized - This looks as if the array didn't
close down cleanly. Is this the result of rebuilding the array with
mdmon 3.3-rc1?

Thinking about it - you did some coding of your own to start mdmon in
the initrd, right? Do you also make sure that mdadm -Ss is called after
umounting the file systems, but before shutdown? If not, an inconsistent
state might result.

> +   init state[0] : Not Initialised
>         access[0] : Read/Write
>           Name[0] : array0
>   Raid Devices[0] : 2 (0 1)
> diff -Nurp before/sdb.txt after/sdb.txt
> --- before/sdb.txt      2013-07-24 15:17:50.300581049 +0200
> +++ after/sdb.txt       2013-07-24 15:49:15.159997204 +0200
> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>    Redundant hdr : yes
>    Virtual Disks : 1
> 
> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
> -                  (LSI      07/24/13 12:18:08)
> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
> +                  (LSI      07/24/13 15:43:29)

Again, new GUID. Did you recreate the array?

Regards
Martin


[-- Attachment #2: load-ddf-header-logging.patch --]
[-- Type: text/x-patch, Size: 1410 bytes --]

From 4e689b7d63e21db21f5bbc0e06b011648265705d Mon Sep 17 00:00:00 2001
From: Martin Wilck <mwilck@arcor.de>
Date: Thu, 25 Jul 2013 21:48:32 +0200
Subject: [PATCH] DDF: load_ddf_header: more error logging

Try to determine problem if load_ddf_header fails.
---
 super-ddf.c |   12 +++++++++---
 1 files changed, 9 insertions(+), 3 deletions(-)

diff --git a/super-ddf.c b/super-ddf.c
index 234d816..fdfc1d5 100644
--- a/super-ddf.c
+++ b/super-ddf.c
@@ -754,18 +754,24 @@ static int load_ddf_header(int fd, unsigned long long lba,
 	if (read(fd, hdr, 512) != 512)
 		return 0;
 
-	if (!be32_eq(hdr->magic, DDF_HEADER_MAGIC))
+	if (!be32_eq(hdr->magic, DDF_HEADER_MAGIC)) {
+		pr_err("%s: bad header magic\n", __func__);
 		return 0;
-	if (!be32_eq(calc_crc(hdr, 512), hdr->crc))
+	}
+	if (!be32_eq(calc_crc(hdr, 512), hdr->crc)) {
+		pr_err("%s: bad CRC\n", __func__);
 		return 0;
+	}
 	if (memcmp(anchor->guid, hdr->guid, DDF_GUID_LEN) != 0 ||
 	    memcmp(anchor->revision, hdr->revision, 8) != 0 ||
 	    !be64_eq(anchor->primary_lba, hdr->primary_lba) ||
 	    !be64_eq(anchor->secondary_lba, hdr->secondary_lba) ||
 	    hdr->type != type ||
 	    memcmp(anchor->pad2, hdr->pad2, 512 -
-		   offsetof(struct ddf_header, pad2)) != 0)
+		   offsetof(struct ddf_header, pad2)) != 0) {
+		pr_err("%s: header mismatch\n", __func__);
 		return 0;
+	}
 
 	/* Looks good enough to me... */
 	return 1;
-- 
1.7.1

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

On 07/25/2013 08:58 PM, Martin Wilck wrote:

> Thinking about it - you did some coding of your own to start mdmon in
> the initrd, right? Do you also make sure that mdadm -Ss is called after
> umounting the file systems, but before shutdown? If not, an inconsistent
> state might result.

I forgot - mdadm -Ss needs to be run after unmounting file systems,
killing logical volumes, etc, but before killing mdmon.

This can be bit tricky.
However if your distro supports md with IMSM, the code should be in place.

Martin

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

On Thu, Jul 25, 2013 at 9:06 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 07/25/2013 08:58 PM, Martin Wilck wrote:
>
>> Thinking about it - you did some coding of your own to start mdmon in
>> the initrd, right? Do you also make sure that mdadm -Ss is called after
>> umounting the file systems, but before shutdown? If not, an inconsistent
>> state might result.
>
> I forgot - mdadm -Ss needs to be run after unmounting file systems,
> killing logical volumes, etc, but before killing mdmon.
>
> This can be bit tricky.
> However if your distro supports md with IMSM, the code should be in place.

I need to check how systemd shutdown the service related to DM devices.

I'll keep you informed.

Thanks.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin

On Thu, Jul 25, 2013 at 10:23 PM, Francis Moreau <francis.moro@gmail.com> wrote:
> On Thu, Jul 25, 2013 at 9:06 PM, Martin Wilck <mwilck@arcor.de> wrote:
>> On 07/25/2013 08:58 PM, Martin Wilck wrote:
>>
>>> Thinking about it - you did some coding of your own to start mdmon in
>>> the initrd, right? Do you also make sure that mdadm -Ss is called after
>>> umounting the file systems, but before shutdown? If not, an inconsistent
>>> state might result.
>>
>> I forgot - mdadm -Ss needs to be run after unmounting file systems,
>> killing logical volumes, etc, but before killing mdmon.
>>
>> This can be bit tricky.
>> However if your distro supports md with IMSM, the code should be in place.
>
> I need to check how systemd shutdown the service related to DM devices.
>

This part is still not cleared to me, I need to investigate to
understand how the system stops MD device.

In the meantime I applied your patch and now I can see this from mdadm's output:

  # ./mdadm -E /dev/sda
  mdmon: load_ddf_header: header mismatch
  mdmon: load_ddf_header: header mismatch
  mdmon: load_ddf_header: header mismatch
  mdmon: Failed to load secondary DDF header on /dev/sda
  ....

Thanks
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin,

Thanks for looking at this,

On Thu, Jul 25, 2013 at 8:58 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 07/24/2013 03:50 PM, Francis Moreau wrote:
>
>> I regenerated the initramfs in order to use the new binaries when
>> booting and now I can see some new warnings:
>>
>>   $ dracut -f
>>   mdmon: Failed to load secondary DDF header on /dev/block/8:0
>>   mdmon: Failed to load secondary DDF header on /dev/block/8:16
>>   ...
>>
>> I ignored them for now.
>
> The message is non-fatal. But is certainly strange, given that you have
> a LSI BIOS. It looks as if something was wrong with your secondary
> header. You may try the attached patch to understand the problem better.

I'll do that, but unfortunately I won't be able to do any testings
before next monday.

>
>> Now the latest version of mdadm is used :
>>
>>   $ cat /proc/mdstat
>>   Personalities : [raid1]
>>   md126 : active raid1 sdb[1] sda[0]
>>         975585280 blocks super external:/md127/0 [2/2] [UU]
>>
>>   md127 : inactive sdb[1](S) sda[0](S)
>>         2354608 blocks super external:ddf
>
> So you did another rebuild of the array with the updated mdadm?

No. I did the rebuilding/syncing with the old mdadm/mdmon.

>
>> I run mdadm -E /dev/sdX for all RAID disks before and after reboot.
>> I'm still having this warning:
>>
>>    mdmon: Failed to load secondary DDF header on /dev/sda
>>
>> You can find the differences below:
>>
>> diff -Nurp before/sda.txt after/sda.txt
>> --- before/sda.txt      2013-07-24 15:15:33.304015379 +0200
>> +++ after/sda.txt       2013-07-24 15:49:09.520132838 +0200
>> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>>    Redundant hdr : yes
>>    Virtual Disks : 1
>>
>> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
>> -                  (LSI      07/24/13 12:18:08)
>> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
>> +                  (LSI      07/24/13 15:43:29)
>
> This is weird. it looks as if the array had been recreated by the BIOS.
> Normally the GUID should stay constant over reboots.
>
>>           unit[0] : 0
>>          state[0] : Optimal, Not Consistent
>> -   init state[0] : Fully Initialised
>
> Not Consistent and Fully Initialized - This looks as if the array didn't
> close down cleanly. Is this the result of rebuilding the array with
> mdmon 3.3-rc1?

No. I did the rebuilding/syncing with the old mdadm/mdmon. Therefore
"Not Consistent and Fully Initialized" was the state of the array
before rebooting created by the old mdmon (3.2.3)

During the rebuild I installed the latest mdadm version so the next
reboot was using the new version of mdadm.

>
> Thinking about it - you did some coding of your own to start mdmon in
> the initrd, right?

Not really I simply reacreated initrd in order to be sure that it uses
the latest version of mdadm.

> Do you also make sure that mdadm -Ss is called after
> umounting the file systems, but before shutdown? If not, an inconsistent
> state might result.

Ah, I need to check how the unmounting is done by systemd.

>
>> +   init state[0] : Not Initialised
>>         access[0] : Read/Write
>>           Name[0] : array0
>>   Raid Devices[0] : 2 (0 1)
>> diff -Nurp before/sdb.txt after/sdb.txt
>> --- before/sdb.txt      2013-07-24 15:17:50.300581049 +0200
>> +++ after/sdb.txt       2013-07-24 15:49:15.159997204 +0200
>> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>>    Redundant hdr : yes
>>    Virtual Disks : 1
>>
>> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
>> -                  (LSI      07/24/13 12:18:08)
>> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
>> +                  (LSI      07/24/13 15:43:29)
>
> Again, new GUID. Did you recreate the array?
>

Well during the next reboot, I can see this from the traces (shown in
my previous email):

[    3.983026] md/raid1:md126: not clean -- starting background reconstruction

so my guess is that the array was recreated here.

Thanks for your help.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin,

I finally managed to get more information.

After the resync finished I have the following state:

partial content of /sys/block/md126/md:
--------------------------------------
array_size           default
array_state          active
chunk_size           65536
component_size       975585280
degraded             0
layout               0
level                raid1
max_read_errors      20
metadata_version     external:/md127/0
mismatch_cnt         0
raid_disks           2
reshape_position     none
resync_start         none
safe_mode_delay      0.000
suspend_hi           0
suspend_lo           0
sync_action          idle
sync_completed       none

# cat /proc/mdstat
Personalities : [raid1]
md126 : active raid1 sdb[1] sda[0]
      975585280 blocks super external:/md127/0 [2/2] [UU]

md127 : inactive sdb[1](S) sda[0](S)
      2354608 blocks super external:ddf

unused devices: <none>

# mdadm -E /dev/sda | egrep "GUID|state"
Controller GUID : 4C534920:20202020:FFFFFFFF:FFFFFFFF:FFFFFFFF:FFFFFFFF
 Container GUID : 4C534920:20202020:80861D6B:10140432:3F14FDAD:5271FC67
      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2A56A7:00001450
        state[0] : Optimal, Not Consistent
   init state[0] : Fully Initialised

Same for /dev/sdb

As you noticed the state is "Not Consistent". In my understanding it
becomes "Consistent" when  the array is stopped.

I checked during the shudown process that the array is correctly
stopped since at that point I got:

# mdadm -E /dev/sda | egrep "state"
        state[0] : Optimal, Consistent
   init state[0] : Fully Initialised

After rebooting, it appears that the BIOS changed a part of VD
GUID[0]. I'm not sure if that can confuse the kernel and if it's the
reason why the kernel shows:

    [  832.944623] md/raid1:md126: not clean -- starting background
reconstruction

but this is obviously where a resync is triggered during each reboot
whatever the initial state of the array. The kernel message is
actually issued by drivers/md/raid1.c, in particular:

        if (mddev->recovery_cp != MaxSector)
                printk(KERN_NOTICE "md/raid1:%s: not clean"
                       " -- starting background reconstruction\n",
                       mdname(mddev));

I don't understand the condition and how a resync can be triggered there.

Oh, this is with kernel 3.4.54.

Can you (or anyone else) spot something wrong with these information ?

Thanks

On Thu, Jul 25, 2013 at 8:58 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 07/24/2013 03:50 PM, Francis Moreau wrote:
>
>> I regenerated the initramfs in order to use the new binaries when
>> booting and now I can see some new warnings:
>>
>>   $ dracut -f
>>   mdmon: Failed to load secondary DDF header on /dev/block/8:0
>>   mdmon: Failed to load secondary DDF header on /dev/block/8:16
>>   ...
>>
>> I ignored them for now.
>
> The message is non-fatal. But is certainly strange, given that you have
> a LSI BIOS. It looks as if something was wrong with your secondary
> header. You may try the attached patch to understand the problem better.
>
>> Now the latest version of mdadm is used :
>>
>>   $ cat /proc/mdstat
>>   Personalities : [raid1]
>>   md126 : active raid1 sdb[1] sda[0]
>>         975585280 blocks super external:/md127/0 [2/2] [UU]
>>
>>   md127 : inactive sdb[1](S) sda[0](S)
>>         2354608 blocks super external:ddf
>
> So you did another rebuild of the array with the updated mdadm?
>
>> I run mdadm -E /dev/sdX for all RAID disks before and after reboot.
>> I'm still having this warning:
>>
>>    mdmon: Failed to load secondary DDF header on /dev/sda
>>
>> You can find the differences below:
>>
>> diff -Nurp before/sda.txt after/sda.txt
>> --- before/sda.txt      2013-07-24 15:15:33.304015379 +0200
>> +++ after/sda.txt       2013-07-24 15:49:09.520132838 +0200
>> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>>    Redundant hdr : yes
>>    Virtual Disks : 1
>>
>> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
>> -                  (LSI      07/24/13 12:18:08)
>> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
>> +                  (LSI      07/24/13 15:43:29)
>
> This is weird. it looks as if the array had been recreated by the BIOS.
> Normally the GUID should stay constant over reboots.
>
>>           unit[0] : 0
>>          state[0] : Optimal, Not Consistent
>> -   init state[0] : Fully Initialised
>
> Not Consistent and Fully Initialized - This looks as if the array didn't
> close down cleanly. Is this the result of rebuilding the array with
> mdmon 3.3-rc1?
>
> Thinking about it - you did some coding of your own to start mdmon in
> the initrd, right? Do you also make sure that mdadm -Ss is called after
> umounting the file systems, but before shutdown? If not, an inconsistent
> state might result.
>
>> +   init state[0] : Not Initialised
>>         access[0] : Read/Write
>>           Name[0] : array0
>>   Raid Devices[0] : 2 (0 1)
>> diff -Nurp before/sdb.txt after/sdb.txt
>> --- before/sdb.txt      2013-07-24 15:17:50.300581049 +0200
>> +++ after/sdb.txt       2013-07-24 15:49:15.159997204 +0200
>> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>>    Redundant hdr : yes
>>    Virtual Disks : 1
>>
>> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
>> -                  (LSI      07/24/13 12:18:08)
>> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
>> +                  (LSI      07/24/13 15:43:29)
>
> Again, new GUID. Did you recreate the array?
>
> Regards
> Martin
>



-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

On Wed, Jul 31, 2013 at 9:36 PM, Francis Moreau <francis.moro@gmail.com> wrote:
> Hello Martin,
>
> I finally managed to get more information.
>
> After the resync finished I have the following state:
>
> partial content of /sys/block/md126/md:
> --------------------------------------
> array_size           default
> array_state          active
> chunk_size           65536
> component_size       975585280
> degraded             0
> layout               0
> level                raid1
> max_read_errors      20
> metadata_version     external:/md127/0
> mismatch_cnt         0
> raid_disks           2
> reshape_position     none
> resync_start         none
> safe_mode_delay      0.000
> suspend_hi           0
> suspend_lo           0
> sync_action          idle
> sync_completed       none
>
> # cat /proc/mdstat
> Personalities : [raid1]
> md126 : active raid1 sdb[1] sda[0]
>       975585280 blocks super external:/md127/0 [2/2] [UU]
>
> md127 : inactive sdb[1](S) sda[0](S)
>       2354608 blocks super external:ddf
>
> unused devices: <none>
>
> # mdadm -E /dev/sda | egrep "GUID|state"
> Controller GUID : 4C534920:20202020:FFFFFFFF:FFFFFFFF:FFFFFFFF:FFFFFFFF
>  Container GUID : 4C534920:20202020:80861D6B:10140432:3F14FDAD:5271FC67
>       VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2A56A7:00001450
>         state[0] : Optimal, Not Consistent
>    init state[0] : Fully Initialised
>
> Same for /dev/sdb
>
> As you noticed the state is "Not Consistent". In my understanding it
> becomes "Consistent" when  the array is stopped.
>
> I checked during the shudown process that the array is correctly
> stopped since at that point I got:
>
> # mdadm -E /dev/sda | egrep "state"
>         state[0] : Optimal, Consistent
>    init state[0] : Fully Initialised
>
> After rebooting, it appears that the BIOS changed a part of VD
> GUID[0]. I'm not sure if that can confuse the kernel and if it's the
> reason why the kernel shows:

To be more accurate, I stopped during the initramfs execution before
udev is started, therefore I'm pretty sure that no mdadm commands have
been issued.

And at this point, the kernel message "md/raid1:md126: not clean --
starting background
reconstruction" has not been emitted and I can see this:

# mdadm -E /dev/sda | egrep "state"
        state[0] : Optimal, Consistent
   init state[0] : Not Initialised

So the "init state[0]" has been changed from "Initialised" to "Not Initialised".

How is this possible ?

Help much appreciated.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

Hello Francis,
> 
> As you noticed the state is "Not Consistent". In my understanding it
> becomes "Consistent" when  the array is stopped.

Correct.

> I checked during the shudown process that the array is correctly
> stopped since at that point I got:
> 
> # mdadm -E /dev/sda | egrep "state"
>         state[0] : Optimal, Consistent
>    init state[0] : Fully Initialised

This looks as it should, actually. This looks as if md is doing what
it's supposed to.

> After rebooting, it appears that the BIOS changed a part of VD
> GUID[0]. I'm not sure if that can confuse the kernel and if it's the
> reason why the kernel shows:
> 
>     [  832.944623] md/raid1:md126: not clean -- starting background
> reconstruction

The BIOS obviously changes the meta data. The GUID itself shouldn't be
the problem as long as it's consistently changed everywhere, but it's
certainly strange to change it - it's meant to be constant and unique
for this array.

It would be important to see the state of the meta data after md
shutdown and immediately after boot (before md actually starts), so that
we can exactly see what the BIOS has done.

> but this is obviously where a resync is triggered during each reboot
> whatever the initial state of the array. The kernel message is
> actually issued by drivers/md/raid1.c, in particular:
> 
>         if (mddev->recovery_cp != MaxSector)
>                 printk(KERN_NOTICE "md/raid1:%s: not clean"
>                        " -- starting background reconstruction\n",
>                        mdname(mddev));
> 
> I don't understand the condition and how a resync can be triggered there.

The kernel is just reacting to something it has been told by
mdadm/mdmon. mdadm, in turn, just reads the meta data. It is highly
likely that the meta data indicated that the array was not, or only
partially, initialized. In this case mdadm will always start a full
reconstruction.

> Oh, this is with kernel 3.4.54.
> 
> Can you (or anyone else) spot something wrong with these information ?

Well, obviously the BIOS made a change to the meta data. Why so? We can
only guess; perhaps something that mdadm wrote to the meta data didn't
please the BIOS code, and it "thought" it needed to do something
differently.

mdadm -E may not be enough here. We need to inspect the raw meta data
1. after BIOS created the array and before mdadm started
2. after mdadm shutdown
3. after BIOS reboot, before mdadm started.
4. (if you have a windows driver, it might be interesting to see how the
meta data looks after windows has shut down after step 1.)

You can dump the metadata with mdadm --dump, but the result is difficult
to handle because it's a sparse image the size of your disk.
Unless all your tools handle sparse files well, you will get stuck.

Here is a slightly more type-intensive but safer method:

Use "sg_readcap /dev/sda" to print the LBA of the last block.
Using this number, run

 dd if=/dev/sda of=/tmp/sda bs=1b skip=$LBA

then do hexdump -C /tmp/sda. You see your "DDF anchor" structure. At
offsets 0x0060 and 0x0068, you find the LBAs of the primary and
secondary header, in big endian. Use the smaller number of the two
(usually the secondary header at 0x0068). In may case the hexdump line reads

00000060  00 00 00 00 3a 37 c0 40  00 00 00 00 3a 37 20 50

The primary LBA is 0x3a37c040, the secondary 3a372050, which is less.
Next, using the smaller number, run

dd if=/dev/sda bs=1b skip=$((0x3a372050)) | gzip -c /tmp/sda-ddf.gz

Put the results somewhere where I can pick them up.

Martin

> 
> Thanks
> 
> On Thu, Jul 25, 2013 at 8:58 PM, Martin Wilck <mwilck@arcor.de> wrote:
>> On 07/24/2013 03:50 PM, Francis Moreau wrote:
>>
>>> I regenerated the initramfs in order to use the new binaries when
>>> booting and now I can see some new warnings:
>>>
>>>   $ dracut -f
>>>   mdmon: Failed to load secondary DDF header on /dev/block/8:0
>>>   mdmon: Failed to load secondary DDF header on /dev/block/8:16
>>>   ...
>>>
>>> I ignored them for now.
>>
>> The message is non-fatal. But is certainly strange, given that you have
>> a LSI BIOS. It looks as if something was wrong with your secondary
>> header. You may try the attached patch to understand the problem better.
>>
>>> Now the latest version of mdadm is used :
>>>
>>>   $ cat /proc/mdstat
>>>   Personalities : [raid1]
>>>   md126 : active raid1 sdb[1] sda[0]
>>>         975585280 blocks super external:/md127/0 [2/2] [UU]
>>>
>>>   md127 : inactive sdb[1](S) sda[0](S)
>>>         2354608 blocks super external:ddf
>>
>> So you did another rebuild of the array with the updated mdadm?
>>
>>> I run mdadm -E /dev/sdX for all RAID disks before and after reboot.
>>> I'm still having this warning:
>>>
>>>    mdmon: Failed to load secondary DDF header on /dev/sda
>>>
>>> You can find the differences below:
>>>
>>> diff -Nurp before/sda.txt after/sda.txt
>>> --- before/sda.txt      2013-07-24 15:15:33.304015379 +0200
>>> +++ after/sda.txt       2013-07-24 15:49:09.520132838 +0200
>>> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>>>    Redundant hdr : yes
>>>    Virtual Disks : 1
>>>
>>> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
>>> -                  (LSI      07/24/13 12:18:08)
>>> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
>>> +                  (LSI      07/24/13 15:43:29)
>>
>> This is weird. it looks as if the array had been recreated by the BIOS.
>> Normally the GUID should stay constant over reboots.
>>
>>>           unit[0] : 0
>>>          state[0] : Optimal, Not Consistent
>>> -   init state[0] : Fully Initialised
>>
>> Not Consistent and Fully Initialized - This looks as if the array didn't
>> close down cleanly. Is this the result of rebuilding the array with
>> mdmon 3.3-rc1?
>>
>> Thinking about it - you did some coding of your own to start mdmon in
>> the initrd, right? Do you also make sure that mdadm -Ss is called after
>> umounting the file systems, but before shutdown? If not, an inconsistent
>> state might result.
>>
>>> +   init state[0] : Not Initialised
>>>         access[0] : Read/Write
>>>           Name[0] : array0
>>>   Raid Devices[0] : 2 (0 1)
>>> diff -Nurp before/sdb.txt after/sdb.txt
>>> --- before/sdb.txt      2013-07-24 15:17:50.300581049 +0200
>>> +++ after/sdb.txt       2013-07-24 15:49:15.159997204 +0200
>>> @@ -9,11 +9,11 @@ Controller GUID : 4C534920:20202020:FFFF
>>>    Redundant hdr : yes
>>>    Virtual Disks : 1
>>>
>>> -      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F2103E0:00001450
>>> -                  (LSI      07/24/13 12:18:08)
>>> +      VD GUID[0] : 4C534920:20202020:80861D60:00000000:3F213401:00001450
>>> +                  (LSI      07/24/13 15:43:29)
>>
>> Again, new GUID. Did you recreate the array?
>>
>> Regards
>> Martin
>>
> 
> 
> 

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin,

Thanks a lot for your help, that's really appreciated :)

On Thu, Aug 1, 2013 at 8:15 PM, Martin Wilck <mwilck@arcor.de> wrote:

>
> Put the results somewhere where I can pick them up.
>

Sent them privately since the result is quite small.

Thanks.

-- 
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

On 08/02/2013 02:46 PM, Francis Moreau wrote:

> Please tell me if you can find something suspicous.

One thing that I can see is that your BIOS seems to use the same time
stamp everywhere. It is clear from the dump that the BIOS has changed
the timestamp in the VD GUID, too. The timestamp used in the
"before-bios" data is 2013-08-02 08:21:10, the timestamp after is
2013-08-02 14:27:27. Wonder if that fits?

The spec says that the VD GUID consists of the vendor ID ("LSI     " in
your case), controller type (the controller's PCI ID,
8086:1d60:0000:0000), the 4-byte time stamp, and a "random number"
(0000 1450). Strangely, I also have an LSI fake RAID and it uses the
same random number. It even generated the same number through several
RAID creations. Seems to be a truly strange random number generator :-)

All in all, this makes your controller's RAID GUIDs very predictable.
But they change whenever the timestamp changes. It also explains why
this controller can't have more than a single array.

But that's not what you wanted to know, right? Besides the time stamp,
sequence number, and CRC32, there is actually no difference between the
two dumps. The suspicious part is here, same in both dumps:

00000860  00 00 ff ff ff ff ff ff  ff ff ff ff ff ff ff ff

The first two bytes in thus line are the state and init state, and the
meaning is "Optimal, consistent, *not initialized*".
And this is before *and* after BIOS started. Suspiciously, this doesn't
match what you wrote before:

> I checked during the shudown process that the array is correctly
> > stopped since at that point I got:
> >
> > # mdadm -E /dev/sda | egrep "state"
> >         state[0] : Optimal, Consistent
> >    init state[0] : Fully Initialised

This would correspond to "00 02", and it's what we should see after
initialization. On my system the BIOS sets "00 01" (Optimal, consistent,
Quick Init in progress) when it first creates an array, because the BIOS
doesn't do a full initialization. But "not initialized" is weird. The
mdadm DDF code won't set this by itself, AFAIK. Please make sure again
that the "before" data matches what mdadm/mdmon wrote just after
stopping during shutdown.

Regards
Martin

Re: MD array keeps resyncing after rebooting

[Sam Bingner]

On 8/2/13 8:19 AM, "Martin Wilck" <mwilck@arcor.de> wrote:

>On 08/02/2013 02:46 PM, Francis Moreau wrote:
>
>>Please tell me if you can find something suspicous.
>
>The spec says that the VD GUID consists of the vendor ID ("LSI " in
>your case), controller type (the controller's PCI ID,
>8086:1d60:0000:0000), the 4-byte time stamp, and a "random number"
>(0000 1450). Strangely, I also have an LSI fake RAID and it uses the
>same random number. It even generated the same number through several
>RAID creations. Seems to be a truly strange random number generator :-)
>

Perhaps the author reads xkcd and wrote something similar to the following:

int getRandomNumber()
{
	return 0x1450;	// chosen by fair dice roll.
			// guaranteed to be random.
}

http://xkcd.com/221/

Sam

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin,

First of all, thanks a lot for your detailed analysis.

On Fri, Aug 2, 2013 at 8:19 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 08/02/2013 02:46 PM, Francis Moreau wrote:
>
>> Please tell me if you can find something suspicous.
>
> One thing that I can see is that your BIOS seems to use the same time
> stamp everywhere. It is clear from the dump that the BIOS has changed
> the timestamp in the VD GUID, too. The timestamp used in the
> "before-bios" data is 2013-08-02 08:21:10, the timestamp after is
> 2013-08-02 14:27:27. Wonder if that fits?

Probably. I booted the system at 8:21, let the resync finish and did
the dump after. So it seems to fit.

>
> The spec says that the VD GUID consists of the vendor ID ("LSI     " in
> your case), controller type (the controller's PCI ID,
> 8086:1d60:0000:0000), the 4-byte time stamp, and a "random number"
> (0000 1450). Strangely, I also have an LSI fake RAID and it uses the
> same random number. It even generated the same number through several
> RAID creations. Seems to be a truly strange random number generator :-)
>
> All in all, this makes your controller's RAID GUIDs very predictable.
> But they change whenever the timestamp changes. It also explains why
> this controller can't have more than a single array.
>
> But that's not what you wanted to know, right?

Well that was very instructive, thanks.

> Besides the time stamp,
> sequence number, and CRC32, there is actually no difference between the
> two dumps. The suspicious part is here, same in both dumps:
>
> 00000860  00 00 ff ff ff ff ff ff  ff ff ff ff ff ff ff ff
>
> The first two bytes in thus line are the state and init state, and the
> meaning is "Optimal, consistent, *not initialized*".
> And this is before *and* after BIOS started. Suspiciously, this doesn't
> match what you wrote before:
>
>> I checked during the shudown process that the array is correctly
>> > stopped since at that point I got:
>> >
>> > # mdadm -E /dev/sda | egrep "state"
>> >         state[0] : Optimal, Consistent
>> >    init state[0] : Fully Initialised
>
> This would correspond to "00 02", and it's what we should see after
> initialization. On my system the BIOS sets "00 01" (Optimal, consistent,
> Quick Init in progress) when it first creates an array, because the BIOS
> doesn't do a full initialization. But "not initialized" is weird. The
> mdadm DDF code won't set this by itself, AFAIK. Please make sure again
> that the "before" data matches what mdadm/mdmon wrote just after
> stopping during shutdown.

I'm pretty sure that's the "before" dump was just after stopping the
array, this is how I proceed: during the shutdown, I stop the system
right after "mdadm -S", then I checked the state  of the array with
"mdadm -E", which was initialized for sure. Then I powered off the
machine, removed one disk and did the "before" dump from my laptop.
After that I booted the machine with the disk in place until grub menu
appeared. I then powered off the machine and did the same procedure as
previously to get "after" dump.

Perhaps some data were still in a "cache" and was not written to the
disk when the power-off/reboot did happen ?

Maybe one thing that worths to note is that the same disk array
configuration with the same system works fine on qemu.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hello Martin,

On Fri, Aug 2, 2013 at 8:19 PM, Martin Wilck <mwilck@arcor.de> wrote:
> On 08/02/2013 02:46 PM, Francis Moreau wrote:
>
>> >
>> > # mdadm -E /dev/sda | egrep "state"
>> >         state[0] : Optimal, Consistent
>> >    init state[0] : Fully Initialised
>
> This would correspond to "00 02", and it's what we should see after
> initialization. On my system the BIOS sets "00 01" (Optimal, consistent,
> Quick Init in progress) when it first creates an array, because the BIOS
> doesn't do a full initialization. But "not initialized" is weird. The
> mdadm DDF code won't set this by itself, AFAIK. Please make sure again
> that the "before" data matches what mdadm/mdmon wrote just after
> stopping during shutdown.

I did it again and got the same result: both disks have:

00000860  00 00 ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|

and I checked again that "mdadm -E" reported an initialized state.

Moreover this time I did a "sync" before dumping the ddf headers.

So I'm quite lost, I can see only 2 cases:

  - with my HW setup some metadata are not written to disks by the
kernel but stood somewhere in RAM (cache)

  - the state is not stored at address 00000860 (very unlikely)

  - the dumps are incorrect

How can I debug this more ?

Thanks for your help.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

Hi Francis,

> On Fri, Aug 2, 2013 at 8:19 PM, Martin Wilck <mwilck@arcor.de> wrote:
>> On 08/02/2013 02:46 PM, Francis Moreau wrote:
>>
>>>>
>>>> # mdadm -E /dev/sda | egrep "state"
>>>>         state[0] : Optimal, Consistent
>>>>    init state[0] : Fully Initialised
>>
>> This would correspond to "00 02", and it's what we should see after
>> initialization. On my system the BIOS sets "00 01" (Optimal, consistent,
>> Quick Init in progress) when it first creates an array, because the BIOS
>> doesn't do a full initialization. But "not initialized" is weird. The
>> mdadm DDF code won't set this by itself, AFAIK. Please make sure again
>> that the "before" data matches what mdadm/mdmon wrote just after
>> stopping during shutdown.
> 
> I did it again and got the same result: both disks have:
> 
> 00000860  00 00 ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
> 
> and I checked again that "mdadm -E" reported an initialized state.
> 
> Moreover this time I did a "sync" before dumping the ddf headers.
> 
> So I'm quite lost, I can see only 2 cases:
> 
>   - with my HW setup some metadata are not written to disks by the
> kernel but stood somewhere in RAM (cache)
> 
>   - the state is not stored at address 00000860 (very unlikely)
> 
>   - the dumps are incorrect
> 
> How can I debug this more ?
> 
> Thanks for your help.

have you got any further insight? I have LSI DDF fake RAID with mdadm
running on my system right now, and it seems to work nicely; no problems
over reboots.

You may want to retry with my latest patch set. In particular, "DDF:
container_content_ddf: set safe_mode_delay > 0" might help.

Martin

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hi Martin,

On Sat, Aug 24, 2013 at 8:54 PM, Martin Wilck <mwilck@arcor.de> wrote:
> Hi Francis,
>
>> On Fri, Aug 2, 2013 at 8:19 PM, Martin Wilck <mwilck@arcor.de> wrote:
>>> On 08/02/2013 02:46 PM, Francis Moreau wrote:
>>>
>>>>>
>>>>> # mdadm -E /dev/sda | egrep "state"
>>>>>         state[0] : Optimal, Consistent
>>>>>    init state[0] : Fully Initialised
>>>
>>> This would correspond to "00 02", and it's what we should see after
>>> initialization. On my system the BIOS sets "00 01" (Optimal, consistent,
>>> Quick Init in progress) when it first creates an array, because the BIOS
>>> doesn't do a full initialization. But "not initialized" is weird. The
>>> mdadm DDF code won't set this by itself, AFAIK. Please make sure again
>>> that the "before" data matches what mdadm/mdmon wrote just after
>>> stopping during shutdown.
>>
>> I did it again and got the same result: both disks have:
>>
>> 00000860  00 00 ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
>>
>> and I checked again that "mdadm -E" reported an initialized state.
>>
>> Moreover this time I did a "sync" before dumping the ddf headers.
>>
>> So I'm quite lost, I can see only 2 cases:
>>
>>   - with my HW setup some metadata are not written to disks by the
>> kernel but stood somewhere in RAM (cache)
>>
>>   - the state is not stored at address 00000860 (very unlikely)
>>
>>   - the dumps are incorrect
>>
>> How can I debug this more ?
>>
>> Thanks for your help.
>
> have you got any further insight?

Unfortunately no progress on this issue, I'm really stuck. I'll try to
test a different distribution to see if the same issue persist. Maybe
CentOS ;)

> I have LSI DDF fake RAID with mdadm
> running on my system right now, and it seems to work nicely; no problems
> over reboots.
>
> You may want to retry with my latest patch set. In particular, "DDF:
> container_content_ddf: set safe_mode_delay > 0" might help.

Will give it a test.

Thanks.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Francis Moreau]

Hi Martin,

Sorry for replying lately but I hadn't access to the machine until now.

On Sat, Aug 24, 2013 at 8:54 PM, Martin Wilck <mwilck@arcor.de> wrote:
> Hi Francis,
>
>> On Fri, Aug 2, 2013 at 8:19 PM, Martin Wilck <mwilck@arcor.de> wrote:
>>> On 08/02/2013 02:46 PM, Francis Moreau wrote:
>>>
>>>>>
>>>>> # mdadm -E /dev/sda | egrep "state"
>>>>>         state[0] : Optimal, Consistent
>>>>>    init state[0] : Fully Initialised
>>>
>>> This would correspond to "00 02", and it's what we should see after
>>> initialization. On my system the BIOS sets "00 01" (Optimal, consistent,
>>> Quick Init in progress) when it first creates an array, because the BIOS
>>> doesn't do a full initialization. But "not initialized" is weird. The
>>> mdadm DDF code won't set this by itself, AFAIK. Please make sure again
>>> that the "before" data matches what mdadm/mdmon wrote just after
>>> stopping during shutdown.
>>
>> I did it again and got the same result: both disks have:
>>
>> 00000860  00 00 ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
>>
>> and I checked again that "mdadm -E" reported an initialized state.
>>
>> Moreover this time I did a "sync" before dumping the ddf headers.
>>
>> So I'm quite lost, I can see only 2 cases:
>>
>>   - with my HW setup some metadata are not written to disks by the
>> kernel but stood somewhere in RAM (cache)
>>
>>   - the state is not stored at address 00000860 (very unlikely)
>>
>>   - the dumps are incorrect
>>
>> How can I debug this more ?
>>
>> Thanks for your help.
>
> have you got any further insight? I have LSI DDF fake RAID with mdadm
> running on my system right now, and it seems to work nicely; no problems
> over reboots.
>
> You may want to retry with my latest patch set. In particular, "DDF:
> container_content_ddf: set safe_mode_delay > 0" might help.
>
> Martin

Man, your my hero :)

Your latest patch set fix the issue.

good work.
-- 
Francis

Re: MD array keeps resyncing after rebooting

[Martin Wilck]

On 08/31/2013 09:23 PM, Francis Moreau wrote:
> Hi Martin,
> 
>> You may want to retry with my latest patch set. In particular, "DDF:
>> container_content_ddf: set safe_mode_delay > 0" might help.
>>
>> Martin
> 
> Man, your my hero :)
> 
> Your latest patch set fix the issue.
> 
> good work.

Thanks for your testing!

Martin

Re: MD array keeps resyncing after rebooting

[NeilBrown]

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

On Thu, 01 Aug 2013 20:15:31 +0200 Martin Wilck <mwilck@arcor.de> wrote:

> Hello Francis,
> > 
> > As you noticed the state is "Not Consistent". In my understanding it
> > becomes "Consistent" when  the array is stopped.
> 
> Correct.
> 
> > I checked during the shudown process that the array is correctly
> > stopped since at that point I got:
> > 
> > # mdadm -E /dev/sda | egrep "state"
> >         state[0] : Optimal, Consistent
> >    init state[0] : Fully Initialised
> 
> This looks as it should, actually. This looks as if md is doing what
> it's supposed to.
> 
> > After rebooting, it appears that the BIOS changed a part of VD
> > GUID[0]. I'm not sure if that can confuse the kernel and if it's the
> > reason why the kernel shows:
> > 
> >     [  832.944623] md/raid1:md126: not clean -- starting background
> > reconstruction
> 
> The BIOS obviously changes the meta data. The GUID itself shouldn't be
> the problem as long as it's consistently changed everywhere, but it's
> certainly strange to change it - it's meant to be constant and unique
> for this array.
> 
> It would be important to see the state of the meta data after md
> shutdown and immediately after boot (before md actually starts), so that
> we can exactly see what the BIOS has done.
> 
> > but this is obviously where a resync is triggered during each reboot
> > whatever the initial state of the array. The kernel message is
> > actually issued by drivers/md/raid1.c, in particular:
> > 
> >         if (mddev->recovery_cp != MaxSector)
> >                 printk(KERN_NOTICE "md/raid1:%s: not clean"
> >                        " -- starting background reconstruction\n",
> >                        mdname(mddev));
> > 
> > I don't understand the condition and how a resync can be triggered there.
> 
> The kernel is just reacting to something it has been told by
> mdadm/mdmon. mdadm, in turn, just reads the meta data. It is highly
> likely that the meta data indicated that the array was not, or only
> partially, initialized. In this case mdadm will always start a full
> reconstruction.
> 
> > Oh, this is with kernel 3.4.54.
> > 
> > Can you (or anyone else) spot something wrong with these information ?
> 
> Well, obviously the BIOS made a change to the meta data. Why so? We can
> only guess; perhaps something that mdadm wrote to the meta data didn't
> please the BIOS code, and it "thought" it needed to do something
> differently.
> 
> mdadm -E may not be enough here. We need to inspect the raw meta data
> 1. after BIOS created the array and before mdadm started
> 2. after mdadm shutdown
> 3. after BIOS reboot, before mdadm started.
> 4. (if you have a windows driver, it might be interesting to see how the
> meta data looks after windows has shut down after step 1.)
> 
> You can dump the metadata with mdadm --dump, but the result is difficult
> to handle because it's a sparse image the size of your disk.
> Unless all your tools handle sparse files well, you will get stuck.
> 
> Here is a slightly more type-intensive but safer method:
> 
> Use "sg_readcap /dev/sda" to print the LBA of the last block.
> Using this number, run
> 
>  dd if=/dev/sda of=/tmp/sda bs=1b skip=$LBA
> 
> then do hexdump -C /tmp/sda. You see your "DDF anchor" structure. At
> offsets 0x0060 and 0x0068, you find the LBAs of the primary and
> secondary header, in big endian. Use the smaller number of the two
> (usually the secondary header at 0x0068). In may case the hexdump line reads
> 
> 00000060  00 00 00 00 3a 37 c0 40  00 00 00 00 3a 37 20 50
> 
> The primary LBA is 0x3a37c040, the secondary 3a372050, which is less.
> Next, using the smaller number, run
> 
> dd if=/dev/sda bs=1b skip=$((0x3a372050)) | gzip -c /tmp/sda-ddf.gz
> 

For future reference, with mdadm 3.3 you can
 mkdir /tmp/md
 mdadm --dump /tmp/md /dev/sd*
 tar czSvf /tmp/md.tgz /tmp/md

The files in /tmp/md are sparse (lots of zeros). 
The 'S' flag to tar tells it to handle these well.
So

 tar xvf /tmp/md.tgz

will recover the sparse files which will have the metadata and nothing else.

NeilBrown

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]