All pastes #168798 Raw Edit

libata_hotplug_md

public text v1 · immutable
#168798 ·published 2006-09-13 10:11 UTC
rendered paste body
>>> Relevant kernel boot messages <<<

[4294667.296000] Linux version 2.6.17.11-axon1 (leon@blaze) (gcc version 4.0.3 (Ubuntu 4.0.3-1ubuntu5)) #1 SMP PREEMPT Thu Sep 7 17:40:21 CEST 2006
...
[4294672.021000] libata version 2.00 loaded.
[4294672.021000] ahci 0000:00:1f.2: version 2.0
[4294672.021000] acpi_bus-0201 [01] bus_set_power         : Device is not power manageable
[4294672.021000] ACPI: PCI Interrupt 0000:00:1f.2[B] -> GSI 19 (level, low) -> IRQ 225
[4294673.069000] PCI: Setting latency timer of device 0000:00:1f.2 to 64
[4294673.069000] ahci 0000:00:1f.2: AHCI 0001.0000 32 slots 4 ports 1.5 Gbps 0xf impl IDE mode
[4294673.069000] ahci 0000:00:1f.2: flags: 64bit ncq pm led slum part 
[4294673.069000] ata1: SATA max UDMA/133 cmd 0xE001C100 ctl 0x0 bmdma 0x0 irq 225
[4294673.069000] ata2: SATA max UDMA/133 cmd 0xE001C180 ctl 0x0 bmdma 0x0 irq 225
[4294673.069000] ata3: SATA max UDMA/133 cmd 0xE001C200 ctl 0x0 bmdma 0x0 irq 225
[4294673.069000] ata4: SATA max UDMA/133 cmd 0xE001C280 ctl 0x0 bmdma 0x0 irq 225
[4294673.069000] scsi0 : ahci
[4294673.531000] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[4294673.532000] ata1.00: ATA-7, max UDMA/133, 781422768 sectors: LBA48 
[4294673.532000] ata1.00: ata1: dev 0 multi count 16
[4294673.534000] ata1.00: configured for UDMA/133
[4294673.534000] scsi1 : ahci
[4294673.992000] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[4294673.994000] ata2.00: ATA-7, max UDMA/133, 781422768 sectors: LBA48 
[4294673.994000] ata2.00: ata2: dev 0 multi count 16
[4294673.996000] ata2.00: configured for UDMA/133
[4294673.996000] scsi2 : ahci
[4294674.454000] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[4294674.456000] ata3.00: ATA-7, max UDMA/133, 781422768 sectors: LBA48 
[4294674.456000] ata3.00: ata3: dev 0 multi count 16
[4294674.458000] ata3.00: configured for UDMA/133
[4294674.458000] scsi3 : ahci
[4294674.916000] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[4294674.918000] ata4.00: ATA-7, max UDMA/133, 781422768 sectors: LBA48 
[4294674.918000] ata4.00: ata4: dev 0 multi count 16
[4294674.920000] ata4.00: configured for UDMA/133
[4294674.920000]   Vendor: ATA       Model: HDS724040KLSA80   Rev: KFAO
[4294674.920000]   Type:   Direct-Access                      ANSI SCSI revision: 05
[4294674.920000]   Vendor: ATA       Model: HDS724040KLSA80   Rev: KFAO
[4294674.921000]   Type:   Direct-Access                      ANSI SCSI revision: 05
[4294674.921000]   Vendor: ATA       Model: HDS724040KLSA80   Rev: KFAO
[4294674.921000]   Type:   Direct-Access                      ANSI SCSI revision: 05
[4294674.921000]   Vendor: ATA       Model: HDS724040KLSA80   Rev: KFAO
[4294674.921000]   Type:   Direct-Access                      ANSI SCSI revision: 05
[4294674.922000] SCSI device sda: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.922000] sda: Write Protect is off
[4294674.922000] sda: Mode Sense: 00 3a 00 00
[4294674.922000] SCSI device sda: drive cache: write back
[4294674.922000] SCSI device sda: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.922000] sda: Write Protect is off
[4294674.922000] sda: Mode Sense: 00 3a 00 00
[4294674.922000] SCSI device sda: drive cache: write back
[4294674.922000]  sda: sda1 sda2
[4294674.938000] sd 0:0:0:0: Attached scsi disk sda
[4294674.938000] SCSI device sdb: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.938000] sdb: Write Protect is off
[4294674.938000] sdb: Mode Sense: 00 3a 00 00
[4294674.938000] SCSI device sdb: drive cache: write back
[4294674.939000] SCSI device sdb: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.939000] sdb: Write Protect is off
[4294674.939000] sdb: Mode Sense: 00 3a 00 00
[4294674.939000] SCSI device sdb: drive cache: write back
[4294674.939000]  sdb: sdb1 sdb2
[4294674.946000] sd 1:0:0:0: Attached scsi disk sdb
[4294674.946000] SCSI device sdc: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.946000] sdc: Write Protect is off
[4294674.946000] sdc: Mode Sense: 00 3a 00 00
[4294674.946000] SCSI device sdc: drive cache: write back
[4294674.946000] SCSI device sdc: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.946000] sdc: Write Protect is off
[4294674.946000] sdc: Mode Sense: 00 3a 00 00
[4294674.946000] SCSI device sdc: drive cache: write back
[4294674.946000]  sdc: sdc1 sdc2
[4294674.962000] sd 2:0:0:0: Attached scsi disk sdc
[4294674.962000] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.962000] sdd: Write Protect is off
[4294674.962000] sdd: Mode Sense: 00 3a 00 00
[4294674.962000] SCSI device sdd: drive cache: write back
[4294674.962000] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[4294674.962000] sdd: Write Protect is off
[4294674.962000] sdd: Mode Sense: 00 3a 00 00
[4294674.962000] SCSI device sdd: drive cache: write back
[4294674.962000]  sdd: sdd1 sdd2
[4294674.975000] sd 3:0:0:0: Attached scsi disk sdd
[4294674.976000] sd 0:0:0:0: Attached scsi generic sg0 type 0
[4294674.976000] sd 1:0:0:0: Attached scsi generic sg1 type 0
[4294674.976000] sd 2:0:0:0: Attached scsi generic sg2 type 0
[4294674.976000] sd 3:0:0:0: Attached scsi generic sg3 type 0
...
[4294675.670000] md: faulty personality registered for level -5
[4294675.670000] md: md driver 0.90.3 MAX_MD_DEVS=256, MD_SB_DISKS=27
[4294675.670000] md: bitmap version 4.39
...
[4294678.136000] SCSI device sda: 781422768 512-byte hdwr sectors (400088 MB)
[4294678.136000] sda: Write Protect is off
[4294678.136000] sda: Mode Sense: 00 3a 00 00
[4294678.136000] SCSI device sda: drive cache: write back
[4294678.137000]  sda: sda1 sda2
[4294679.147000] SCSI device sdb: 781422768 512-byte hdwr sectors (400088 MB)
[4294679.147000] sdb: Write Protect is off
[4294679.147000] sdb: Mode Sense: 00 3a 00 00
[4294679.147000] SCSI device sdb: drive cache: write back
[4294679.147000]  sdb: sdb1 sdb2
[4294680.158000] SCSI device sdc: 781422768 512-byte hdwr sectors (400088 MB)
[4294680.158000] sdc: Write Protect is off
[4294680.158000] sdc: Mode Sense: 00 3a 00 00
[4294680.158000] SCSI device sdc: drive cache: write back
[4294680.158000]  sdc: sdc1 sdc2
[4294681.169000] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[4294681.169000] sdd: Write Protect is off
[4294681.169000] sdd: Mode Sense: 00 3a 00 00
[4294681.169000] SCSI device sdd: drive cache: write back
[4294681.169000]  sdd: sdd1 sdd2
[4294683.175000] md: md0 stopped.
[4294683.176000] md: bind<sdc1>
[4294683.177000] md: bind<sdd1>
[4294683.177000] md: bind<sda1>
[4294683.177000] md: bind<sdb1>
[4294683.177000] md: kicking non-fresh sda1 from array!
[4294683.177000] md: unbind<sda1>
[4294683.177000] md: export_rdev(sda1)
[4294683.179000] raid5: device sdb1 operational as raid disk 1
[4294683.179000] raid5: device sdd1 operational as raid disk 3
[4294683.179000] raid5: device sdc1 operational as raid disk 2
[4294683.180000] raid5: allocated 4208kB for md0
[4294683.180000] raid5: raid level 5 set md0 active with 3 out of 4 devices, algorithm 2
[4294683.180000] RAID5 conf printout:
[4294683.180000]  --- rd:4 wd:3 fd:1
[4294683.180000]  disk 1, o:1, dev:sdb1
[4294683.180000]  disk 2, o:1, dev:sdc1
[4294683.180000]  disk 3, o:1, dev:sdd1
[4294683.180000] md: bind<sda1>
[4294683.204000] RAID5 conf printout:
[4294683.204000]  --- rd:4 wd:3 fd:1
[4294683.204000]  disk 0, o:1, dev:sda1
[4294683.204000]  disk 1, o:1, dev:sdb1
[4294683.204000]  disk 2, o:1, dev:sdc1
[4294683.204000]  disk 3, o:1, dev:sdd1
[4294683.204000] md: syncing RAID array md0
[4294683.204000] md: minimum _guaranteed_ reconstruction speed: 1000 KB/sec/disc.
[4294683.204000] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for reconstruction.
[4294683.204000] md: using 128k window, over a total of 390620352 blocks.
[4294683.205000] md: could not bd_claim sdb1.
[4294683.205000] md: error, md_import_device() returned -16
[4294683.206000] md: could not bd_claim sdc1.
[4294683.206000] md: error, md_import_device() returned -16
[4294683.206000] md: could not bd_claim sdd1.
[4294683.206000] md: error, md_import_device() returned -16
...
[4294705.772000] EXT3 FS on md0, internal journal
[4294705.772000] EXT3-fs: mounted filesystem with ordered data mode.


>>> Userspace /proc/mdstat and mdadm --detail output, before unplugging <<<

Personalities : [linear] [raid0] [raid1] [raid10] [raid5] [raid4] [raid6] [multipath] [faulty] 
md0 : active raid5 sda1[4] sdb1[1] sdd1[3] sdc1[2]
      1171861056 blocks level 5, 64k chunk, algorithm 2 [4/3] [_UUU]
      [>....................]  recovery =  4.9% (19172224/390620352) finish=160.6min speed=38523K/sec
      
unused devices: <none>

/dev/md0:
        Version : 00.90.03
  Creation Time : Tue May 27 22:12:16 2003
     Raid Level : raid5
     Array Size : 1171861056 (1117.57 GiB 1199.99 GB)
    Device Size : 390620352 (372.52 GiB 400.00 GB)
   Raid Devices : 4
  Total Devices : 4
Preferred Minor : 0
    Persistence : Superblock is persistent

    Update Time : Mon Jun  2 01:10:33 2003
          State : active, degraded, recovering
 Active Devices : 3
Working Devices : 4
 Failed Devices : 0
  Spare Devices : 1

         Layout : left-symmetric
     Chunk Size : 64K

 Rebuild Status : 5% complete

           UUID : 84fb4d1b:3a7740cc:b7005766:aae7d7b2
         Events : 0.76363

    Number   Major   Minor   RaidDevice State
       4       8        1        0      spare rebuilding   /dev/sda1
       1       8       17        1      active sync   /dev/sdb1
       2       8       33        2      active sync   /dev/sdc1
       3       8       49        3      active sync   /dev/sdd1

>>> Unplugging physical drive 0,0,0,0 from SATA connection, kernel messages <<<

[4295286.546000] ata1.00: exception Emask 0x10 SAct 0x0 SErr 0x400100 action 0x2 frozen
[4295286.546000] ata1.00: (irq_stat 0x08000000, interface fatal error)
[4295286.546000] ata1.00: tag 0 cmd 0x35 Emask 0x10 stat 0x50 err 0x0 (ATA bus error)
[4295288.751000] ata1: soft resetting port
[4295288.751000] ata1: SATA link down (SStatus 11 SControl 300)
[4295288.751000] ata1: failed to recover some devices, retrying in 5 secs
[4295293.752000] ata1: hard resetting port
[4295294.057000] ata1: SATA link down (SStatus 0 SControl 300)
[4295294.057000] ata1: failed to recover some devices, retrying in 5 secs
[4295299.058000] ata1: hard resetting port
[4295299.363000] ata1: SATA link down (SStatus 0 SControl 300)
[4295299.363000] ata1.00: disabled
[4295299.864000] sd 0:0:0:0: SCSI error: return code = 0x8000002
[4295299.864000] sda: Current: sense key: Aborted Command
[4295299.864000]     Additional sense: No additional sense information
[4295299.864000] end_request: I/O error, dev sda, sector 42414481
[4295299.864000] raid5: Disk failure on sda1, disabling device. Operation continuing on 3 devices
[4295299.864000] sd 0:0:0:0: rejecting I/O to offline device
[4295299.864000] sd 0:0:0:0: rejecting I/O to offline device
[4295299.864000] sd 0:0:0:0: rejecting I/O to offline device
[4295299.864000] sd 0:0:0:0: rejecting I/O to offline device
[4295299.864000] ata1: EH complete
[4295299.864000] ata1.00: detaching (SCSI 0:0:0:0)
[4295299.900000] md: md0: sync done.
[4295300.008000] RAID5 conf printout:
[4295300.008000]  --- rd:4 wd:3 fd:1
[4295300.008000]  disk 0, o:0, dev:sda1
[4295300.008000]  disk 1, o:1, dev:sdb1
[4295300.008000]  disk 2, o:1, dev:sdc1
[4295300.008000]  disk 3, o:1, dev:sdd1
[4295300.011000] RAID5 conf printout:
[4295300.011000]  --- rd:4 wd:3 fd:1
[4295300.011000]  disk 1, o:1, dev:sdb1
[4295300.011000]  disk 2, o:1, dev:sdc1
[4295300.011000]  disk 3, o:1, dev:sdd1

>>> Unplugging physical drive 0,0,0,0 from SATA connection, udev messages <<<

UEVENT[1054516293.870127] remove@/class/scsi_generic/sg0
UEVENT[1054516293.870176] remove@/class/scsi_device/0:0:0:0
UEVENT[1054516293.870188] remove@/class/scsi_disk/0:0:0:0
UEVENT[1054516293.870197] remove@/block/sda/sda2
UEVENT[1054516293.870206] remove@/block/sda/sda1
UEVENT[1054516293.870215] remove@/block/sda
UEVENT[1054516293.870225] remove@/devices/pci0000:00/0000:00:1f.2/host0/target0:0:0/0:0:0:0
UDEV  [1054516293.870906] remove@/class/scsi_generic/sg0
UDEV  [1054516293.871638] remove@/class/scsi_disk/0:0:0:0
UDEV  [1054516293.871939] remove@/class/scsi_device/0:0:0:0
UDEV  [1054516293.873071] remove@/block/sda/sda2
UDEV  [1054516293.873123] remove@/block/sda/sda1
UDEV  [1054516293.874521] remove@/block/sda
UDEV  [1054516293.874670] remove@/devices/pci0000:00/0000:00:1f.2/host0/target0:0:0/0:0:0:0

>>> Userspace /proc/mdstat and mdadm --detail output, after unplugging <<<

Personalities : [linear] [raid0] [raid1] [raid10] [raid5] [raid4] [raid6] [multipath] [faulty] 

md0 : active raid5 sda1[4](F) sdb1[1] sdd1[3] sdc1[2]
      1171861056 blocks level 5, 64k chunk, algorithm 2 [4/3] [_UUU]
      
unused devices: <none>
/dev/md0:
        Version : 00.90.03
  Creation Time : Tue May 27 22:12:16 2003
     Raid Level : raid5
     Array Size : 1171861056 (1117.57 GiB 1199.99 GB)
    Device Size : 390620352 (372.52 GiB 400.00 GB)
   Raid Devices : 4
  Total Devices : 4
Preferred Minor : 0
    Persistence : Superblock is persistent

    Update Time : Mon Jun  2 01:13:01 2003
          State : clean, degraded
 Active Devices : 3
Working Devices : 3
 Failed Devices : 1
  Spare Devices : 0

         Layout : left-symmetric
     Chunk Size : 64K

           UUID : 84fb4d1b:3a7740cc:b7005766:aae7d7b2
         Events : 0.76609

    Number   Major   Minor   RaidDevice State
   -1208726704       0        0      564      removed
       1       8       17        1      active sync   /dev/sdb1
       2       8       33        2      active sync   /dev/sdc1
       3       8       49        3      active sync   /dev/sdd1

       4       8        1        -      faulty spare


>>> Replugging physical drive to the SATA connector, kernel messages <<<

[4295329.083000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x4040000 action 0x42 frozen
[4295329.083000] ata1: (irq_stat 0x00000040, connection status changed)
[4295329.630000] ata1: waiting for device to spin up (8 secs)
[4295337.804000] ata1: soft resetting port
[4295337.804000] ata1: softreset failed (port busy but CLO unavailable)
[4295337.804000] ata1: softreset failed, retrying in 5 secs
[4295342.805000] ata1: hard resetting port
[4295350.569000] ata1: port is slow to respond, please be patient
[4295373.572000] ata1: port failed to respond (30 secs)
[4295373.572000] ata1: COMRESET failed (device not ready)
[4295373.572000] ata1: hardreset failed, retrying in 5 secs
[4295378.573000] ata1: hard resetting port
[4295379.296000] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[4295379.304000] ata1.00: ATA-7, max UDMA/133, 781422768 sectors: LBA48 
[4295379.304000] ata1.00: ata1: dev 0 multi count 0
[4295379.306000] ata1.00: configured for UDMA/133
[4295379.306000] ata1: EH complete
[4295379.306000]   Vendor: ATA       Model: HDS724040KLSA80   Rev: KFAO
[4295379.306000]   Type:   Direct-Access                      ANSI SCSI revision: 05
[4295379.307000] SCSI device sde: 781422768 512-byte hdwr sectors (400088 MB)
[4295379.307000] sde: Write Protect is off
[4295379.307000] sde: Mode Sense: 00 3a 00 00
[4295379.307000] SCSI device sde: drive cache: write back
[4295379.307000] SCSI device sde: 781422768 512-byte hdwr sectors (400088 MB)
[4295379.307000] sde: Write Protect is off
[4295379.307000] sde: Mode Sense: 00 3a 00 00
[4295379.307000] SCSI device sde: drive cache: write back
[4295379.307000]  sde: sde1 sde2
[4295379.328000] sd 0:0:0:0: Attached scsi disk sde
[4295379.328000] sd 0:0:0:0: Attached scsi generic sg0 type 0

>>> Replugging physical drive to the SATA connector, userspace messages <<<

UEVENT[1054516373.298514] add@/devices/pci0000:00/0000:00:1f.2/host0/target0:0:0/0:0:0:0
UEVENT[1054516373.298595] add@/class/scsi_disk/0:0:0:0
UEVENT[1054516373.319950] add@/block/sde
UEVENT[1054516373.319995] add@/block/sde/sde1
UEVENT[1054516373.320038] add@/block/sde/sde2
UEVENT[1054516373.320207] add@/class/scsi_device/0:0:0:0
UEVENT[1054516373.321231] add@/class/scsi_generic/sg0
UDEV  [1054516373.342240] add@/devices/pci0000:00/0000:00:1f.2/host0/target0:0:0/0:0:0:0
UDEV  [1054516373.342398] add@/class/scsi_disk/0:0:0:0
UDEV  [1054516373.343965] add@/class/scsi_device/0:0:0:0
UDEV  [1054516373.345360] add@/class/scsi_generic/sg0
UDEV  [1054516373.381867] add@/block/sde
UDEV  [1054516373.397299] add@/block/sde/sde1
UDEV  [1054516373.431358] add@/block/sde/sde2