Bug#502224: Stopping root MD array fails because it's busy

[Martin Michlmayr]

Package: mdadm
Version: 2.6.7-3.1
Severity: important

I noticed on a NAS device running Debian that the root MD array always
fails to be stopped during shutdown because it's busy.  I'm not sure
why this is or whether this is a problem, but I thought I'd report it.
The problem happens on every shutdown.

Here's what happens:

Unmounting local filesystems...done.
[42949430.610000] md: md2 stopped.
[42949430.610000] md: unbind<sda4>
[42949430.610000] md: export_rdev(sda4)
[42949430.620000] md: md1 still in use.
[42949430.660000] md: md0 stopped.
[42949430.660000] md: unbind<sda1>
[42949430.660000] md: export_rdev(sda1)
[42949430.670000] md: md1 still in use.
[42949430.670000] md: md1 still in use.
Stopping MD array md2...done (stopped).
Stopping MD array md0...done (stopped).
Stopping MD array md1...failed (busy). <-------
Will now halt.

Is there any way to find out why md1 is still busy?

The full log is attached.
-- 
Martin Michlmayr
http://www.cyrius.com/
-------------- next part --------------
Uncompressing Linux.......................................................................................... done, booting the kernel.
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 2.6.26-1-orion5x (Debian 2.6.26-5) (waldi at debian.org) (gcc version 4.1.3 20080623 (prerelease) (Debian 4.1.2-23)) #1 Thu Sep 11 13:28:52 UTC 2008
[    0.000000] CPU: Feroceon [41069260] revision 0 (ARMv5TEJ), cr=00053177
[    0.000000] Machine: QNAP TS-409
[    0.000000] Clearing invalid memory bank 0KB at 0x00000000
[    0.000000] Clearing invalid memory bank 0KB at 0x00000000
[    0.000000] Clearing invalid memory bank 0KB at 0x00000000
[    0.000000] Ignoring unrecognised tag 0x00000000
[    0.000000] Ignoring unrecognised tag 0x00000000
[    0.000000] Ignoring unrecognised tag 0x00000000
[    0.000000] Ignoring unrecognised tag 0x41000403
[    0.000000] Memory policy: ECC disabled, Data cache writeback
[    0.000000] CPU0: D VIVT write-back cache
[    0.000000] CPU0: I cache: 32768 bytes, associativity 1, 32 byte lines, 1024 sets
[    0.000000] CPU0: D cache: 32768 bytes, associativity 4, 32 byte lines, 256 sets
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 65024
[    0.000000] Kernel command line: console=ttyS0,115200n8 root=/dev/ram rw initrd=0x800000,0x3fffff
[    0.000000] PID hash table entries: 1024 (order: 10, 4096 bytes)
[42949372.960000] Console: colour dummy device 80x30
[42949372.960000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
[42949372.960000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
[42949372.980000] Memory: 256MB = 256MB total
[42949372.980000] Memory: 252672KB available (2532K code, 358K data, 116K init)
[42949373.230000] Security Framework initialized
[42949373.230000] SELinux:  Disabled at boot.
[42949373.230000] Capability LSM initialized
[42949373.230000] Mount-cache hash table entries: 512
[42949373.230000] Initializing cgroup subsys ns
[42949373.230000] Initializing cgroup subsys cpuacct
[42949373.230000] Initializing cgroup subsys devices
[42949373.230000] CPU: Testing write buffer coherency: ok
[42949373.230000] net_namespace: 652 bytes
[42949373.230000] NET: Registered protocol family 16
[42949373.230000] Orion ID: MV88F5281-D0. TCLK=166666667.
[42949373.230000] Orion: Applying 5281 D0 WFI workaround.
[42949373.240000] tsx09: found ethernet mac address 00:08:9b:ac:68:df.
[42949373.240000] PCI: bus0: Fast back to back transfers disabled
[42949373.240000] PCI: bus1: Fast back to back transfers enabled
[42949373.240000] qnap_ts409_pci_map_irq failed, unknown bus
[42949373.280000] NET: Registered protocol family 2
[42949373.370000] IP route cache hash table entries: 2048 (order: 1, 8192 bytes)
[42949373.370000] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[42949373.370000] TCP bind hash table entries: 8192 (order: 3, 32768 bytes)
[42949373.370000] TCP: Hash tables configured (established 8192 bind 8192)
[42949373.370000] TCP reno registered
[42949373.400000] NET: Registered protocol family 1
[42949373.400000] checking if image is initramfs... it is
[42949374.920000] Freeing initrd memory: 4095K
[42949374.920000] NetWinder Floating Point Emulator V0.97 (double precision)
[42949374.920000] audit: initializing netlink socket (disabled)
[42949374.920000] type=2000 audit(1.960:1): initialized
[42949374.920000] VFS: Disk quotas dquot_6.5.1
[42949374.920000] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[42949374.920000] msgmni has been set to 501
[42949374.920000] async_tx: api initialized (async)
[42949374.920000] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[42949374.920000] io scheduler noop registered
[42949374.920000] io scheduler anticipatory registered
[42949374.920000] io scheduler deadline registered
[42949374.920000] io scheduler cfq registered (default)
[42949374.940000] Serial: 8250/16550 driver $Revision: 1.90 $ 2 ports, IRQ sharing disabled
[42949374.950000] serial8250.0: ttyS0 at MMIO 0xf1012000 (irq = 3) is a 16550A
[42949374.950000] console [ttyS0] enabled
[42949375.300000] serial8250.0: ttyS1 at MMIO 0xf1012100 (irq = 4) is a 16550A
[42949375.320000] brd: module loaded
[42949375.320000] NFTL driver: nftlcore.c $Revision: 1.98 $, nftlmount.c $Revision: 1.41 $
[42949375.330000] physmap platform flash device: 00800000 at ff800000
[42949375.340000] physmap-flash.0: Found 1 x16 devices at 0x0 in 8-bit bank
[42949375.340000]  Intel/Sharp Extended Query Table at 0x0031
[42949375.350000] Using buffer write method
[42949375.350000] cfi_cmdset_0001: Erase suspend on write enabled
modprobe: FATAL: Could not load /lib/modules/2.6.26-1-orion5x/modules.dep: No such file or directory


[42949375.400000] RedBoot partition parsing not available
[42949375.400000] Using physmap partition information
[42949375.410000] Creating 6 MTD partitions on "physmap-flash.0":
[42949375.410000] 0x00780000-0x00800000 : "U-Boot"
[42949375.420000] ftl_cs: FTL header not found.
[42949375.420000] 0x00000000-0x00200000 : "Kernel"
[42949375.430000] ftl_cs: FTL header not found.
[42949375.430000] 0x00200000-0x00600000 : "RootFS1"
[42949375.440000] ftl_cs: FTL header not found.
[42949375.440000] 0x00600000-0x00700000 : "RootFS2"
[42949375.450000] ftl_cs: FTL header not found.
[42949375.450000] 0x00760000-0x00780000 : "U-Boot Config"
[42949375.460000] ftl_cs: FTL header not found.
[42949375.470000] 0x00700000-0x00760000 : "NAS Config"
[42949375.470000] ftl_cs: FTL header not found.
[42949375.480000] mice: PS/2 mouse device common for all mice
[42949375.490000] i2c /dev entries driver
[42949375.500000] rtc-s35390a 0-0030: rtc core: registered rtc-s35390a as rtc0
[42949375.500000] Registered led device: ts409:red:sata1
[42949375.510000] Registered led device: ts409:red:sata2
[42949375.510000] Registered led device: ts409:red:sata3
[42949375.520000] Registered led device: ts409:red:sata4
[42949375.530000] TCP cubic registered
[42949375.530000] NET: Registered protocol family 17
[42949375.540000] VFP support v0.3: implementor 41 architecture 1 part 10 variant 9 rev 0
[42949375.550000] registered taskstats version 1
[42949375.550000] rtc-s35390a 0-0030: setting system clock to 2008-10-14 16:37:53 UTC (1224002273)
[42949375.560000] Freeing init memory: 116K
Loading, please wait...
Begin: Loading essential drivers ... [42949375.980000] SCSI subsystem initialized
[42949376.110000] sata_mv 0000:00:01.0: version 1.24
[42949376.110000] sata_mv 0000:00:01.0: Gen-IIE 32 slots 4 ports SCSI mode IRQ via INTx
[42949376.120000] scsi0 : sata_mv
[42949376.130000] scsi1 : sata_mv
[42949376.130000] scsi2 : sata_mv
[42949376.140000] scsi3 : sata_mv
[42949376.140000] ata1: SATA max UDMA/133 mmio m1048576 at 0xe0000000 port 0xe0022000 irq 11
[42949376.150000] ata2: SATA max UDMA/133 mmio m1048576 at 0xe0000000 port 0xe0024000 irq 11
[42949376.160000] ata3: SATA max UDMA/133 mmio m1048576 at 0xe0000000 port 0xe0026000 irq 11
[42949376.160000] ata4: SATA max UDMA/133 mmio m1048576 at 0xe0000000 port 0xe0028000 irq 11
[42949377.640000] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[42949377.680000] ata1.00: ATA-7: WDC WD3200JS-22PDB0, 21.00M21, max UDMA/133
[42949377.680000] ata1.00: 625142448 sectors, multi 0: LBA48 NCQ (depth 1)
[42949377.730000] ata1.00: configured for UDMA/133
[42949378.080000] ata2: SATA link down (SStatus 0 SControl 300)
[42949378.430000] ata3: SATA link down (SStatus 0 SControl 300)
[42949378.780000] ata4: SATA link down (SStatus 0 SControl 300)
[42949378.780000] scsi 0:0:0:0: Direct-Access     ATA      WDC WD3200JS-22P 21.0 PQ: 0 ANSI: 5
done.
Begin: Running /scripts/init-premount ... [42949380.500000] Driver 'sd' needs updating - please use bus_type methods
[42949380.510000] sd 0:0:0:0: [sda] 625142448 512-byte hardware sectors (320073 MB)
[42949380.520000] sd 0:0:0:0: [sda] Write Protect is off
[42949380.520000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[42949380.540000] sd 0:0:0:0: [sda] 625142448 512-byte hardware sectors (320073 MB)
[42949380.540000] sd 0:0:0:0: [sda] Write Protect is off
[42949380.550000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[42949380.560000]  sda: sda1 sda2 sda3 sda4
[42949380.580000] sd 0:0:0:0: [sda] Attached SCSI disk
done.
Begin: Mounting root file system ... Begin: Running /scripts/local-top ... Begin: Loading[42949381.740000] md: raid1 personality registered for level 1
Success: loaded module raid1.
done.
Begin: Assembling all MD arrays ... [42949381.830000] md: md0 stopped.
[42949381.900000] md: bind<sda1>
[42949381.920000] raid1: raid set md0 active with 1 out of 2 mirrors
mdadm: /dev/md0 has been started with 1 drive (out of 2).
[42949381.990000] md: md1 stopped.
[42949382.030000] md: bind<sda3>
[42949382.060000] raid1: raid set md1 active with 1 out of 2 mirrors
mdadm: /dev/md1 has been started with 1 drive (out of 2).
[42949382.120000] md: md2 stopped.
[42949382.190000] md: bind<sda4>
[42949382.210000] raid1: raid set md2 active with 1 out of 2 mirrors
mdadm: /dev/md2 has been started with 1 drive (out of 2).
Success: assembled all arrays.
done.
Begin: Waiting for udev to process events ... done.
done.
Begin: Running /scripts/local-premount ... done.
[42949382.640000] kjournald starting.  Commit interval 5 seconds
[42949382.690000] EXT3 FS on md1, internal journal
[42949382.690000] EXT3-fs: mounted filesystem with ordered data mode.
Begin: Running /scripts/local-bottom ... done.
done.
Begin: Running /scripts/init-bottom ... done.

INIT: version 2.86 booting

Starting the hotplug events dispatcher: udevd[42949385.500000] udevd version 125 started
.
Synthesizing the initial hotplug events...done.
Waiting for /dev to be fully populated...[42949391.330000] input: gpio-keys as /class/input/input0
[42949391.570000] MV-643xx 10/100/1000 Ethernet Driver
[42949391.580000] eth0: port 0 with MAC address 00:08:9b:ac:68:df
[42949391.580000] eth0: Scatter Gather Enabled
[42949391.590000] eth0: TX TCP/IP Checksumming Supported
[42949391.590000] eth0: RX TCP/UDP Checksum Offload ON 
[42949391.600000] eth0: RX NAPI Enabled 
[42949391.720000] usbcore: registered new interface driver usbfs
[42949391.720000] usbcore: registered new interface driver hub
[42949391.890000] usbcore: registered new device driver usb
[42949391.940000] orion-ehci orion-ehci.0: Marvell Orion EHCI
[42949391.950000] orion-ehci orion-ehci.0: new USB bus registered, assigned bus number 1
[42949392.000000] orion-ehci orion-ehci.0: irq 17, io mem 0xf1050000
[42949392.020000] orion-ehci orion-ehci.0: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[42949392.020000] usb usb1: configuration #1 chosen from 1 choice
[42949392.030000] hub 1-0:1.0: USB hub found
[42949392.030000] hub 1-0:1.0: 1 port detected
[42949392.150000] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[42949392.150000] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[42949392.160000] usb usb1: Product: Marvell Orion EHCI
[42949392.170000] usb usb1: Manufacturer: Linux 2.6.26-1-orion5x ehci_hcd
[42949392.170000] usb usb1: SerialNumber: orion-ehci.0
[42949392.460000] usb 1-1: new high speed USB device using orion-ehci and address 2
[42949392.610000] usb 1-1: configuration #1 chosen from 1 choice
[42949392.610000] hub 1-1:1.0: USB hub found
[42949392.620000] hub 1-1:1.0: 4 ports detected
[42949392.740000] usb 1-1: New USB device found, idVendor=05e3, idProduct=0607
[42949392.740000] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[42949392.750000] usb 1-1: Product: USB2.0 Hub
done.
Setting parameters of disc: (none).
Setting the system clock.
Activating swap...[42949395.120000] Adding 996020k swap on /dev/sda2.  Priority:-1 extents:1 across:996020k
done.
Checking root file system...fsck 1.41.2 (02-Oct-2008)
e2fsck 1.41.2 (02-Oct-2008)
/dev/md1: clean, 19521/366480 files, 178263/1463904 blocks
done.
[42949395.720000] EXT3 FS on md1, internal journal
Setting the system clock.
Cleaning up ifupdown....
Loading kernel modules...[42949397.940000] loop: module loaded
done.
Generating udev events for MD arrays...done.
Checking file systems...fsck 1.41.2 (02-Oct-2008)
e2fsck 1.41.2 (02-Oct-2008)
/dev/md0: clean, 18/124496 files, 22635/248896 blocks
e2fsck 1.41.2 (02-Oct-2008)
/dev/md2: clean, 17/19095552 files, 40360917/76366960 blocks
done.
Setting kernel variables (/etc/sysctl.conf)...Unknown HZ value! (91) Assume 100.
done.
Mounting local filesystems...[42949401.510000] kjournald starting.  Commit interval 5 seconds
[42949401.550000] EXT3 FS on md2, internal journal
[42949401.560000] EXT3-fs: mounted filesystem with ordered data mode.
done.
Activating swapfile swap...done.
Setting up networking....
Configuring network interfaces...done.
Starting portmap daemon....
Starting NFS common utilities: statd.
Setting console screen modes and fonts.

INIT: Entering runlevel: 2

Starting enhanced syslogd: rsyslogd.
Starting OpenBSD Secure Shell server: sshd[42949406.890000] NET: Registered protocol family 10
[42949406.900000] lo: Disabled Privacy Extensions
.
Starting MTA: exim4.
Starting disk temperature monitoring daemon: hddtemp:  /dev/sda..
Starting NFS common utilities: statd.
Starting internet superserver: inetd.
Starting MD monitoring service: mdadm --monitor.
Starting deferred execution scheduler: atd.
Starting periodic command scheduler: crond.
System boot completed.

Debian GNU/Linux lenny/sid debian ttyS0

debian login: root
Password: 
Last login: Tue Oct 14 18:35:45 CEST 2008 from 192.168.1.2 on pts/0
Linux debian 2.6.26-1-orion5x #1 Thu Sep 11 13:28:52 UTC 2008 armv5tel

The programs included with the Debian GNU/Linux system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
permitted by applicable law.
debian:~# halt


Broadcast message from root at debian (ttyS0) (Tue Oct 14 18:38:42 2008):




The system is going down for system halt NOW!


INIT: Switching to run
INIT: SenPreparing for shutdown.
Stopping deferred execution scheduler: atd.
Stopping MTA: exim4_listener.
Stopping disk temperature monitoring daemon: hddtemp.
Stopping NFS common utilities: statd.
Stopping internet superserver: inetd.
Saving the system clock.
Stopping MD monitoring service: mdadm --monitor.
Stopping enhanced syslogd: rsyslogd.
Asking all remaining processes to terminate...done.
All processes ended within 1 seconds....done.
Stopping portmap daemon....
Deconfiguring network interfaces...There is already a pid file /var/run/dhclient.eth0.pid with pid 1520
removed stale PID file
Internet Systems Consortium DHCP Client V3.1.1
Copyright 2004-2008 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

Listening on LPF/eth0/00:08:9b:ac:68:df
Sending on   LPF/eth0/00:08:9b:ac:68:df
Sending on   Socket/fallback
DHCPRELEASE on eth0 to 192.168.1.1 port 67
done.
Cleaning up ifupdown....
Deactivating swap...done.
Unmounting local filesystems...done.
[42949430.610000] md: md2 stopped.
[42949430.610000] md: unbind<sda4>
[42949430.610000] md: export_rdev(sda4)
[42949430.620000] md: md1 still in use.
[42949430.660000] md: md0 stopped.
[42949430.660000] md: unbind<sda1>
[42949430.660000] md: export_rdev(sda1)
[42949430.670000] md: md1 still in use.
[42949430.670000] md: md1 still in use.
Stopping MD array md2...done (stopped).
Stopping MD array md0...done (stopped).
Stopping MD array md1...failed (busy).
Will now halt.
[42949433.110000] md: stopping all md devices.
[42949433.120000] md: md1 still in use.
[42949434.130000] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[42949434.130000] sd 0:0:0:0: [sda] Stopping disk
[42949434.180000] Power down.
[42949434.180000] qnap_tsx09_power_off: triggering power-off...
[42949434.190000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
[42949434.200000] ata1: edma_err_cause=00000020 pp_flags=00000002, SError=00180000
[42949434.210000] ata1: SError: { 10B8B Dispar }
[42949434.210000] ata1: hard resetting link