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/
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) ([EMAIL PROTECTED]) (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 [EMAIL PROTECTED] [ 0.000000] Clearing invalid memory bank [EMAIL PROTECTED] [ 0.000000] Clearing invalid memory bank [EMAIL PROTECTED] [ 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 [EMAIL PROTECTED] port 0xe0022000 irq 11 [42949376.150000] ata2: SATA max UDMA/133 mmio [EMAIL PROTECTED] port 0xe0024000 irq 11 [42949376.160000] ata3: SATA max UDMA/133 mmio [EMAIL PROTECTED] port 0xe0026000 irq 11 [42949376.160000] ata4: SATA max UDMA/133 mmio [EMAIL PROTECTED] 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 [EMAIL PROTECTED] (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...[31mfailed (busy).[39;49m 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
