* xfs umount hang in xfs_ail_push_all_sync on i/o error
@ 2014-04-28 22:29 Bob Mastors
2014-04-28 23:45 ` Dave Chinner
0 siblings, 1 reply; 8+ messages in thread
From: Bob Mastors @ 2014-04-28 22:29 UTC (permalink / raw)
To: xfs
[-- Attachment #1.1: Type: text/plain, Size: 3827 bytes --]
Greetings,
I have an xfs umount hang caused by forcing the block device to return
i/o errors while copying files to the filesystem.
Detailed steps to reproduce the problem on virtualbox are below.
The linux version is a recent pull and reports as 3.15.0-rc3.
[ 2040.248096] INFO: task umount:10303 blocked for more than 120 seconds.
[ 2040.323947] Not tainted 3.15.0-rc3 #4
[ 2040.343423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 2040.352665] umount D ffffffff8180fe40 0 10303 8691
0x00000000
[ 2040.404918] ffff88001e33dd58 0000000000000086 ffff88001e33dd48
ffffffff81080f82
[ 2040.489901] ffff88001b311900 0000000000013180 ffff88001e33dfd8
0000000000013180
[ 2040.534772] ffff88003daa3200 ffff88001b311900 ffff88002421aec0
ffff88002421ae80
[ 2040.587450] Call Trace:
[ 2040.592176] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 2040.620212] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 2040.627685] [<ffffffffa04c4cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 2040.632236] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 2040.659105] [<ffffffffa04731a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 2040.691774] [<ffffffffa0478f65>] ? kmem_free+0x35/0x40 [xfs]
[ 2040.698610] [<ffffffffa0474cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 2040.706838] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 2040.723958] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 2040.734963] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 2040.745485] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 2040.751274] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 2040.755894] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 2040.761032] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ .060058] XFS (sdb): xfs_log_force: error 5 returned.
[ 268059] XFS (sdb): xfs_log_force: error 5 returned.
I took a look at xfs_ail_push_all_sync and it is pretty easy to see
the hang. But it is not obvious to me how to fix it.
Any ideas would be appreciated.
I am available to run additional tests or capture more logging
or whatever if that would help.
Thanks,
Bob
virtual box setup
-----------------
1 GB ram
8 GB disk
4 processors
Operating System: Linux
Version: Debian (64 bit)
Bridged networking
iso: debian-7.4.0-amd64-netinst.iso
Software selection
select SSH server
select Standard system utilities
deselect everything else
dhcp ip address: 172.17.5.129
upgrade linux to 3.15.0-rc3
---------------------------
ssh 172.17.5.129
su
cd /mnt/ksrc/linux
make modules_install
make install
reboot
install tools
-------------
ssh 172.17.5.129
su
apt-get install xfsprogs
apt-get install open-iscsi
apt-get install --no-install-recommends targetcli python-urwid
reboot
reproduce bug
-------------
ssh 172.17.5.129
su
targetcli
cd backstores
fileio/ create name=file_backend2 file_or_dev=my_disk2 size=1G
/iscsi create
portals/ create 172.17.5.129
cd <
luns/ create /backstores/fileio/file_backend2
cd <
set attribute authentication=0 demo_mode_write_protect=0
generate_node_acls=1 cache_dynamic_acls=1
exit
iscsiadm -m discovery -t sendtargets -p 172.17.5.129
iscsiadm -m node --login --target iqn.from_previous_iscsiadm_cmd_output
fdisk -l
mkfs -t xfs -f /dev/sdXX
mkdir /mnt/vola
put following lines in a shell script "foo.sh", fix up target and block
device
set -x
iscsiadm -m node --target
iqn.2003-01.org.linux-iscsi.debian.x8664:sn.51ab79ac3ce2 --login
sleep 1
mount -t xfs /dev/sdb /mnt/vola
sleep 10
iscsiadm -m node -U all
sleep 1
umount /mnt/vola
run the shell script in a loop like:
while true; do ./foo.sh; done
in another terminal run the following:
while true; do cp -r /usr/lib /mnt/vola; done
The hang seems to take from two to ten minutes to occur.
[-- Attachment #1.2: Type: text/html, Size: 5245 bytes --]
[-- Attachment #2: Type: text/plain, Size: 121 bytes --]
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
2014-04-28 22:29 xfs umount hang in xfs_ail_push_all_sync on i/o error Bob Mastors
@ 2014-04-28 23:45 ` Dave Chinner
2014-04-28 23:51 ` Bob Mastors
0 siblings, 1 reply; 8+ messages in thread
From: Dave Chinner @ 2014-04-28 23:45 UTC (permalink / raw)
To: Bob Mastors; +Cc: xfs
On Mon, Apr 28, 2014 at 04:29:02PM -0600, Bob Mastors wrote:
> Greetings,
>
> I have an xfs umount hang caused by forcing the block device to return
> i/o errors while copying files to the filesystem.
> Detailed steps to reproduce the problem on virtualbox are below.
>
> The linux version is a recent pull and reports as 3.15.0-rc3.
>
> [ 2040.248096] INFO: task umount:10303 blocked for more than 120 seconds.
> [ 2040.323947] Not tainted 3.15.0-rc3 #4
> [ 2040.343423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [ 2040.352665] umount D ffffffff8180fe40 0 10303 8691
> 0x00000000
> [ 2040.404918] ffff88001e33dd58 0000000000000086 ffff88001e33dd48
> ffffffff81080f82
> [ 2040.489901] ffff88001b311900 0000000000013180 ffff88001e33dfd8
> 0000000000013180
> [ 2040.534772] ffff88003daa3200 ffff88001b311900 ffff88002421aec0
> ffff88002421ae80
> [ 2040.587450] Call Trace:
> [ 2040.592176] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
> [ 2040.620212] [<ffffffff816c54d9>] schedule+0x29/0x70
> [ 2040.627685] [<ffffffffa04c4cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
> [ 2040.632236] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
> [ 2040.659105] [<ffffffffa04731a3>] xfs_unmountfs+0x63/0x160 [xfs]
> [ 2040.691774] [<ffffffffa0478f65>] ? kmem_free+0x35/0x40 [xfs]
> [ 2040.698610] [<ffffffffa0474cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
> [ 2040.706838] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
> [ 2040.723958] [<ffffffff811956d0>] kill_block_super+0x30/0x80
> [ 2040.734963] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
> [ 2040.745485] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
> [ 2040.751274] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
> [ 2040.755894] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
> [ 2040.761032] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
> [ .060058] XFS (sdb): xfs_log_force: error 5 returned.
> [ 268059] XFS (sdb): xfs_log_force: error 5 returned.
>
> I took a look at xfs_ail_push_all_sync and it is pretty easy to see
> the hang. But it is not obvious to me how to fix it.
> Any ideas would be appreciated.
>
> I am available to run additional tests or capture more logging
> or whatever if that would help.
What's the entire log output from the first shutdown message?
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
2014-04-28 23:45 ` Dave Chinner
@ 2014-04-28 23:51 ` Bob Mastors
2014-04-29 1:01 ` Dave Chinner
0 siblings, 1 reply; 8+ messages in thread
From: Bob Mastors @ 2014-04-28 23:51 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
[-- Attachment #1.1: Type: text/plain, Size: 2678 bytes --]
Log output attached.
The xfs filesystem being mounted and unmounted is the only xfs filesystem
on the system.
Bob
On Mon, Apr 28, 2014 at 5:45 PM, Dave Chinner <david@fromorbit.com> wrote:
> On Mon, Apr 28, 2014 at 04:29:02PM -0600, Bob Mastors wrote:
> > Greetings,
> >
> > I have an xfs umount hang caused by forcing the block device to return
> > i/o errors while copying files to the filesystem.
> > Detailed steps to reproduce the problem on virtualbox are below.
> >
> > The linux version is a recent pull and reports as 3.15.0-rc3.
> >
> > [ 2040.248096] INFO: task umount:10303 blocked for more than 120 seconds.
> > [ 2040.323947] Not tainted 3.15.0-rc3 #4
> > [ 2040.343423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables
> > this message.
> > [ 2040.352665] umount D ffffffff8180fe40 0 10303 8691
> > 0x00000000
> > [ 2040.404918] ffff88001e33dd58 0000000000000086 ffff88001e33dd48
> > ffffffff81080f82
> > [ 2040.489901] ffff88001b311900 0000000000013180 ffff88001e33dfd8
> > 0000000000013180
> > [ 2040.534772] ffff88003daa3200 ffff88001b311900 ffff88002421aec0
> > ffff88002421ae80
> > [ 2040.587450] Call Trace:
> > [ 2040.592176] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
> > [ 2040.620212] [<ffffffff816c54d9>] schedule+0x29/0x70
> > [ 2040.627685] [<ffffffffa04c4cd6>] xfs_ail_push_all_sync+0x96/0xd0
> [xfs]
> > [ 2040.632236] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
> > [ 2040.659105] [<ffffffffa04731a3>] xfs_unmountfs+0x63/0x160 [xfs]
> > [ 2040.691774] [<ffffffffa0478f65>] ? kmem_free+0x35/0x40 [xfs]
> > [ 2040.698610] [<ffffffffa0474cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
> > [ 2040.706838] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
> > [ 2040.723958] [<ffffffff811956d0>] kill_block_super+0x30/0x80
> > [ 2040.734963] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
> > [ 2040.745485] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
> > [ 2040.751274] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
> > [ 2040.755894] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
> > [ 2040.761032] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
> > [ .060058] XFS (sdb): xfs_log_force: error 5 returned.
> > [ 268059] XFS (sdb): xfs_log_force: error 5 returned.
> >
> > I took a look at xfs_ail_push_all_sync and it is pretty easy to see
> > the hang. But it is not obvious to me how to fix it.
> > Any ideas would be appreciated.
> >
> > I am available to run additional tests or capture more logging
> > or whatever if that would help.
>
> What's the entire log output from the first shutdown message?
>
> Cheers,
>
> Dave.
> --
> Dave Chinner
> david@fromorbit.com
>
[-- Attachment #1.2: Type: text/html, Size: 3535 bytes --]
[-- Attachment #2: vb-debian2.log --]
[-- Type: text/x-log, Size: 66781 bytes --]
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 3.15.0-rc3 (rmastors@rmastors) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #4 SMP Mon Apr 28 14:40:30 MDT 2014
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.15.0-rc3 root=UUID=fcbf6f4a-1967-44fc-a79e-d0d9a704a88d ro console=tty console=ttyS0,115200n8
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] e820: BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffeffff] usable
[ 0.000000] BIOS-e820: [mem 0x000000003fff0000-0x000000003fffffff] ACPI data
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.5 present.
[ 0.000000] No AGP bridge found
[ 0.000000] e820: last_pfn = 0x3fff0 max_arch_pfn = 0x400000000
[ 0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[ 0.000000] CPU MTRRs all blank - virtualized system.
[ 0.000000] found SMP MP-table at [mem 0x0009fff0-0x0009ffff] mapped at [ffff88000009fff0]
[ 0.000000] Scanning 1 areas for low memory corruption
[ 0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[ 0.000000] init_memory_mapping: [mem 0x3fc00000-0x3fdfffff]
[ 0.000000] init_memory_mapping: [mem 0x3c000000-0x3fbfffff]
[ 0.000000] init_memory_mapping: [mem 0x00100000-0x3bffffff]
[ 0.000000] init_memory_mapping: [mem 0x3fe00000-0x3ffeffff]
[ 0.000000] RAMDISK: [mem 0x28dac000-0x306cdfff]
[ 0.000000] ACPI: RSDP 0x00000000000E0000 000024 (v02 VBOX )
[ 0.000000] ACPI: XSDT 0x000000003FFF0030 00003C (v01 VBOX VBOXXSDT 00000001 ASL 00000061)
[ 0.000000] ACPI: FACP 0x000000003FFF00F0 0000F4 (v04 VBOX VBOXFACP 00000001 ASL 00000061)
[ 0.000000] ACPI: DSDT 0x000000003FFF0480 001B96 (v01 VBOX VBOXBIOS 00000002 INTL 20100528)
[ 0.000000] ACPI: FACS 0x000000003FFF0200 000040
[ 0.000000] ACPI: APIC 0x000000003FFF0240 00006C (v02 VBOX VBOXAPIC 00000001 ASL 00000061)
[ 0.000000] ACPI: SSDT 0x000000003FFF02B0 0001CC (v01 VBOX VBOXCPUT 00000002 INTL 20100528)
[ 0.000000] No NUMA configuration found
[ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000003ffeffff]
[ 0.000000] Initmem setup node 0 [mem 0x00000000-0x3ffeffff]
[ 0.000000] NODE_DATA [mem 0x3ffeb000-0x3ffeffff]
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x00001000-0x00ffffff]
[ 0.000000] DMA32 [mem 0x01000000-0xffffffff]
[ 0.000000] Normal empty
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x00001000-0x0009efff]
[ 0.000000] node 0: [mem 0x00100000-0x3ffeffff]
[ 0.000000] ACPI: PM-Timer IO Port: 0x4008
[ 0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x02] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x03] enabled)
[ 0.000000] ACPI: IOAPIC (id[0x04] address[0xfec00000] gsi_base[0])
[ 0.000000] IOAPIC[0]: apic_id 4, version 17, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[ 0.000000] e820: [mem 0x40000000-0xfffbffff] available for PCI devices
[ 0.000000] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:4 nr_node_ids:1
[ 0.000000] PERCPU: Embedded 27 pages/cpu @ffff88003fc00000 s81536 r8192 d20864 u524288
[ 0.000000] Built 1 zonelists in Node order, mobility grouping on. Total pages: 257913
[ 0.000000] Policy zone: DMA32
[ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.15.0-rc3 root=UUID=fcbf6f4a-1967-44fc-a79e-d0d9a704a88d ro console=tty console=ttyS0,115200n8
[ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.000000] Checking aperture...
[ 0.000000] No AGP bridge found
[ 0.000000] Memory: 891228K/1048120K available (6997K kernel code, 1065K rwdata, 3272K rodata, 1196K init, 1068K bss, 156892K reserved)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] RCU dyntick-idle grace-period acceleration is enabled.
[ 0.000000] RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[ 0.000000] NR_IRQS:16640 nr_irqs:712 16
[ 0.000000] Console: colour VGA+ 80x25
[ 0.000000] console [tty0] enabled
[ 0.000000] console [ttyS0] enabled
[ 0.000000] allocated 4194304 bytes of page_cgroup
[ 0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups
[ 0.000000] tsc: Fast TSC calibration using PIT
[ 0.000000] tsc: Detected 3377.063 MHz processor
[ 0.008025] Calibrating delay loop (skipped), value calculated using timer frequency.. 6754.12 BogoMIPS (lpj=13508252)
[ 0.016004] pid_max: default: 32768 minimum: 301
[ 0.016738] ACPI: Core revision 20140214
[ 0.017941] ACPI: All ACPI Tables successfully acquired
[ 0.018898] Security Framework initialized
[ 0.020012] AppArmor: AppArmor initialized
[ 0.020695] Yama: becoming mindful.
[ 0.021347] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[ 0.022431] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[ 0.023617] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes)
[ 0.024005] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes)
[ 0.025076] Initializing cgroup subsys memory
[ 0.025774] Initializing cgroup subsys devices
[ 0.026476] Initializing cgroup subsys freezer
[ 0.028004] Initializing cgroup subsys net_cls
[ 0.028750] Initializing cgroup subsys blkio
[ 0.029415] Initializing cgroup subsys perf_event
[ 0.030240] CPU: Physical Processor ID: 0
[ 0.030886] CPU: Processor Core ID: 0
[ 0.031506] mce: CPU supports 0 MCE banks
[ 0.032088] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
[ 0.032088] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[ 0.032088] tlb_flushall_shift: 6
[ 0.034406] Freeing SMP alternatives memory: 24K (ffffffff81e37000 - ffffffff81e3d000)
[ 0.035618] ftrace: allocating 26655 entries in 105 pages
[ 0.048346] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.095741] smpboot: CPU0: Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz (fam: 06, model: 3c, stepping: 03)
[ 0.112000] Performance Events: unsupported p6 CPU model 60 no PMU driver, software events only.
[ 0.121071] NMI watchdog: disabled (cpu0): hardware events not enabled
[ 0.124144] x86: Booting SMP configuration:
[ 0.128002] .... node #0, CPUs: #1
[ 0.012000] mce: CPU supports 0 MCE banks
[ 0.164000] TSC synchronization [CPU#0 -> CPU#1]:
[ 0.164000] Measured 78212 cycles TSC warp between CPUs, turning off TSC clock.
[ 0.164000] tsc: Marking TSC unstable due to check_tsc_sync_source failed
[ 0.164180] #2
[ 0.012000] mce: CPU supports 0 MCE banks
[ 0.209299] #3
[ 0.012000] mce: CPU supports 0 MCE banks
[ 0.233938] x86: Booted up 1 node, 4 CPUs
[ 0.234582] smpboot: Total of 4 processors activated (27016.50 BogoMIPS)
[ 0.236298] devtmpfs: initialized
[ 0.237852] evm: security.selinux
[ 0.238391] evm: security.SMACK64
[ 0.239088] evm: security.capability
[ 0.240757] regulator-dummy: no parameters
[ 0.241571] RTC time: 21:35:15, date: 04/28/14
[ 0.242307] NET: Registered protocol family 16
[ 0.243116] cpuidle: using governor ladder
[ 0.256008] cpuidle: using governor menu
[ 0.268026] ACPI: bus type PCI registered
[ 0.288002] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[ 0.316077] PCI: Using configuration type 1 for base access
[ 0.344571] ACPI: Added _OSI(Module Device)
[ 0.356002] ACPI: Added _OSI(Processor Device)
[ 0.356691] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.357551] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.360164] ACPI: Executed 1 blocks of module-level executable AML code
[ 0.362767] ACPI: Interpreter enabled
[ 0.363468] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S1_] (20140214/hwxface-580)
[ 0.365047] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20140214/hwxface-580)
[ 0.367172] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S3_] (20140214/hwxface-580)
[ 0.368444] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S4_] (20140214/hwxface-580)
[ 0.370107] ACPI: (supports S0 S5)
[ 0.370725] ACPI: Using IOAPIC for interrupt routing
[ 0.371495] PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
[ 0.373297] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.376004] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[ 0.376933] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
[ 0.377835] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[ 0.380070] PCI host bridge to bus 0000:00
[ 0.380733] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.381514] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.382363] pci_bus 0000:00: root bus resource [mem 0x00000000-0x7fffffffff]
[ 0.384613] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
[ 0.385673] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
[ 0.386556] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
[ 0.387533] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
[ 0.409461] ACPI: PCI Interrupt Link [LNKA] (IRQs *5 9 10 11)
[ 0.416890] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 9 10 *11)
[ 0.418351] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 9 *10 11)
[ 0.428935] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 *9 10 11)
[ 0.452091] ACPI: Enabled 1 GPEs in block 00 to 07
[ 0.472117] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[ 0.476003] vgaarb: loaded
[ 0.476515] vgaarb: bridge control possible 0000:00:02.0
[ 0.477540] SCSI subsystem initialized
[ 0.480046] ACPI: bus type USB registered
[ 0.480046] usbcore: registered new interface driver usbfs
[ 0.480818] usbcore: registered new interface driver hub
[ 0.481598] usbcore: registered new device driver usb
[ 0.484139] PCI: Using ACPI for IRQ routing
[ 0.485188] NetLabel: Initializing
[ 0.485188] NetLabel: domain hash size = 128
[ 0.485188] NetLabel: protocols = UNLABELED CIPSOv4
[ 0.485474] NetLabel: unlabeled traffic allowed by default
[ 0.488108] Switched to clocksource refined-jiffies
[ 0.490475] AppArmor: AppArmor Filesystem Enabled
[ 0.500025] pnp: PnP ACPI init
[ 0.500627] ACPI: bus type PNP registered
[ 0.501621] pnp: PnP ACPI: found 5 devices
[ 0.502289] ACPI: bus type PNP unregistered
[ 0.514386] Switched to clocksource acpi_pm
[ 0.515084] NET: Registered protocol family 2
[ 0.517215] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.518191] TCP bind hash table entries: 8192 (order: 5, 131072 bytes)
[ 0.523156] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.524260] TCP: reno registered
[ 0.524871] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.525769] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.526733] NET: Registered protocol family 1
[ 0.527542] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.528589] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.530585] Trying to unpack rootfs image as initramfs...
[ 1.852346] Freeing initrd memory: 124040K (ffff880028dac000 - ffff8800306ce000)
[ 1.884274] platform rtc_cmos: registered platform RTC device (no PNP device found)
[ 1.887780] Scanning for low memory corruption every 60 seconds
[ 1.888960] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 1.889830] Initialise system trusted keyring
[ 1.890527] audit: initializing netlink subsys (disabled)
[ 1.891335] audit: type=2000 audit(1398720915.887:1): initialized
[ 1.910106] bounce pool size: 64 pages
[ 1.910767] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[ 1.912936] VFS: Disk quotas dquot_6.5.2
[ 1.913630] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 1.914762] fuse init (API version 7.23)
[ 1.915576] msgmni has been set to 1982
[ 1.919063] Key type asymmetric registered
[ 1.920003] Asymmetric key parser 'x509' registered
[ 1.921103] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[ 1.953156] io scheduler noop registered
[ 1.953815] io scheduler deadline registered (default)
[ 1.954817] io scheduler cfq registered
[ 1.955546] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[ 1.957103] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[ 1.958212] ACPI: AC Adapter [AC] (on-line)
[ 1.958988] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 1.960211] ACPI: Power Button [PWRF]
[ 1.960758] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
[ 1.961950] ACPI: Sleep Button [SLPF]
[ 1.963136] GHES: HEST is not enabled!
[ 1.964058] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[ 1.986191] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[ 1.992698] Linux agpgart interface v0.103
[ 1.995407] brd: module loaded
[ 1.997372] loop: module loaded
[ 1.998657] scsi0 : ata_piix
[ 2.000945] scsi1 : ata_piix
[ 2.001534] ata1: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
[ 2.002844] ata2: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
[ 2.004087] libphy: Fixed MDIO Bus: probed
[ 2.004848] tun: Universal TUN/TAP device driver, 1.6
[ 2.005611] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[ 2.006630] PPP generic driver version 2.4.2
[ 2.007435] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 2.008493] ehci-pci: EHCI PCI platform driver
[ 2.009293] ehci-platform: EHCI generic platform driver
[ 2.010157] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[ 2.023449] ohci-pci: OHCI PCI platform driver
[ 2.024600] ohci-pci 0000:00:06.0: OHCI PCI host controller
[ 2.025425] ohci-pci 0000:00:06.0: new USB bus registered, assigned bus number 1
[ 2.026680] ohci-pci 0000:00:06.0: irq 22, io mem 0xf0804000
[ 2.080251] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001
[ 2.081271] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 2.082467] usb usb1: Product: OHCI PCI host controller
[ 2.083257] usb usb1: Manufacturer: Linux 3.15.0-rc3 ohci_hcd
[ 2.084301] usb usb1: SerialNumber: 0000:00:06.0
[ 2.085175] hub 1-0:1.0: USB hub found
[ 2.085831] hub 1-0:1.0: 8 ports detected
[ 2.086739] ohci-platform: OHCI generic platform driver
[ 2.087672] uhci_hcd: USB Universal Host Controller Interface driver
[ 2.088636] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
[ 2.090395] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 2.092452] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 2.093473] mousedev: PS/2 mouse device common for all mice
[ 2.094679] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input2
[ 2.096362] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
[ 2.097462] rtc_cmos rtc_cmos: alarms up to one day, 114 bytes nvram
[ 2.098683] device-mapper: uevent: version 1.0.3
[ 2.099739] device-mapper: ioctl: 4.27.0-ioctl (2013-10-30) initialised: dm-devel@redhat.com
[ 2.101183] ledtrig-cpu: registered to indicate activity on CPUs
[ 2.102159] TCP: cubic registered
[ 2.102863] NET: Registered protocol family 10
[ 2.103894] NET: Registered protocol family 17
[ 2.104708] Key type dns_resolver registered
[ 2.105864] Loading compiled-in X.509 certificates
[ 2.107153] Loaded X.509 cert 'Magrathea: Glacier signing key: b13bc5c201febce6cb8393db54ea2546832af337'
[ 2.108722] registered taskstats version 1
[ 2.111648] Key type trusted registered
[ 2.114313] Key type encrypted registered
[ 2.116896] AppArmor: AppArmor sha1 policy hashing enabled
[ 2.118851] Magic number: 10:350:602
[ 2.119625] rtc_cmos rtc_cmos: setting system clock to 2014-04-28 21:35:17 UTC (1398720917)
[ 2.121153] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[ 2.122083] EDD information not available.
[ 2.160415] ata2.00: ATAPI: VBOX CD-ROM, 1.0, max UDMA/133
[ 2.167209] ata2.00: configured for UDMA/33
[ 2.170480] scsi 1:0:0:0: CD-ROM VBOX CD-ROM 1.0 PQ: 0 ANSI: 5
[ 2.180553] sr0: scsi3-mmc drive: 32x/32x xa/form2 tray
[ 2.183433] cdrom: Uniform CD-ROM driver Revision: 3.20
[ 2.184721] sr 1:0:0:0: Attached scsi generic sg0 type 5
[ 2.186344] Freeing unused kernel memory: 1196K (ffffffff81d0c000 - ffffffff81e37000)
[ 2.188483] Write protecting the kernel read-only data: 12288k
[ 2.193950] Freeing unused kernel memory: 1184K (ffff8800016d8000 - ffff880001800000)
[ 2.198999] Freeing unused kernel memory: 824K (ffff880001b32000 - ffff880001c00000)
Loading, please wait...
[ 2.209981] udevd[107]: starting version 175
[ 2.245930] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[ 2.247547] e1000: Copyright (c) 1999-2006 Intel Corporation.
[ 2.492170] usb 1-1: new full-speed USB device number 2 using ohci-pci
[ 2.625023] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 08:00:27:6d:e0:4d
[ 2.728530] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 2.749478] ahci 0000:00:0d.0: SSS flag set, parallel bus scan disabled
[ 2.750632] ahci 0000:00:0d.0: AHCI 0001.0100 32 slots 1 ports 3 Gbps 0x1 impl SATA mode
[ 2.751919] ahci 0000:00:0d.0: flags: 64bit ncq stag only ccc
[ 2.753510] scsi2 : ahci
[ 2.754177] ata3: SATA max UDMA/133 abar m8192@0xf0806000 port 0xf0806100 irq 21
[ 2.756134] usb 1-1: New USB device found, idVendor=80ee, idProduct=0021
[ 2.757165] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=0
[ 2.758197] usb 1-1: Product: USB Tablet
[ 2.758842] usb 1-1: Manufacturer: VirtualBox
[ 2.766277] hidraw: raw HID events driver (C) Jiri Kosina
[ 2.816225] usbcore: registered new interface driver usbhid
[ 2.832814] usbhid: USB HID core driver
[ 2.839188] input: VirtualBox USB Tablet as /devices/pci0000:00/0000:00:06.0/usb1/1-1/1-1:1.0/0003:80EE:0021.0001/input/input4
[ 2.869355] hid-generic 0003:80EE:0021.0001: input,hidraw0: USB HID v1.10 Mouse [VirtualBox USB Tablet] on usb-0000:00:06.0-1/input0
[ 3.072489] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 3.090662] ata3.00: ATA-6: VBOX HARDDISK, 1.0, max UDMA/133
[ 3.091536] ata3.00: 16777216 sectors, multi 128: LBA48 NCQ (depth 31/32)
[ 3.092668] ata3.00: configured for UDMA/133
[ 3.093673] scsi 2:0:0:0: Direct-Access ATA VBOX HARDDISK 1.0 PQ: 0 ANSI: 5
[ 3.095583] sd 2:0:0:0: [sda] 16777216 512-byte logical blocks: (8.58 GB/8.00 GiB)
[ 3.095617] sd 2:0:0:0: Attached scsi generic sg1 type 0
[ 3.098748] sd 2:0:0:0: [sda] Write Protect is off
[ 3.100155] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 3.103823] sda: sda1 sda2 < sda5 >
[ 3.126424] sd 2:0:0:0: [sda] Attached SCSI disk
[ 5.268864] floppy0: no floppy controllers found
Begin: Loading essential drivers ... done.
Begin: Running /scripts/init-premount ... done.
Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done.
Begin: Running /scripts/local-premount ... [ 5.350375] PM: Starting manual resume from disk
done.
[ 5.354008] EXT4-fs (sda1): INFO: recovery required on readonly filesystem
[ 5.368430] EXT4-fs (sda1): write access will be enabled during recovery
[ 5.389113] EXT4-fs (sda1): recovery complete
[ 5.396057] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
Begin: Running /scripts/local-bottom ... done.
done.
Begin: Running /scripts/init-bottom ... done.
\rINIT: version 2.88 booting
[^[[36minfo^[[39;49m] Using makefile-style concurrent boot in runlevel S.
[....] Starting the hotplug events dispatcher: udevd[ 5.631682] udevd[392]: starting version 175
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Synthesizing the initial hotplug events...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[ 5.678890] piix4_smbus 0000:00:07.0: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
[....] Waiting for /dev to be fully populated...[ 5.689476] input: PC Speaker as /devices/platform/pcspkr/input/input5
[ 5.723416] parport_pc 00:03: reported by Plug and Play ACPI
[ 5.750729] Error: Driver 'pcspkr' is already registered, aborting...
[ 5.924809] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input6
[ 6.084098] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 55432 usecs (11568 samples)
[ 6.191146] snd_intel8x0 0000:00:05.0: measured clock 208688 rejected
[ 6.552162] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 55953 usecs (11299 samples)
[ 6.607127] snd_intel8x0 0000:00:05.0: measured clock 201937 rejected
[ 6.980137] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 55976 usecs (11317 samples)
[ 6.984331] snd_intel8x0 0000:00:05.0: measured clock 202175 rejected
[ 6.985243] snd_intel8x0 0000:00:05.0: clocking to 48000
[ 8.740740] floppy0: no floppy controllers found
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Setting preliminary keymap...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Activating swap...[ 8.957871] Adding 392188k swap on /dev/sda5. Priority:-1 extents:1 across:392188k FS
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[ 8.975823] EXT4-fs (sda1): re-mounted. Opts: (null)
[....] Checking root file system...fsck from util-linux 2.20.1
/dev/sda1: clean, 66772/499712 files, 1728141/1998336 blocks
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[ 9.025968] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
[^[[36minfo^[[39;49m] Loading kernel module loop.
[....] Cleaning up temporary files... /tmp^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
[....] Activating lvm and md swap...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Checking file systems...fsck from util-linux 2.20.1
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Mounting local filesystems...[mntent]: line 1 in /etc/fstab is bad
[mntent]: line 3 in /etc/fstab is bad
[mntent]: line 4 in /etc/fstab is bad
[mntent]: line 5 in /etc/fstab is bad
[mntent]: line 7 in /etc/fstab is bad; rest of file ignored
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Activating swapfile swap...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Cleaning up temporary files...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[ 9.445333] random: nonblocking pool is initialized
[....] Setting kernel variables ...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Configuring network interfaces...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[....] Starting rpcbind daemon...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting NFS common utilities: statd[ 9.644459] RPC: Registered named UNIX socket transport module.
[ 9.645791] RPC: Registered udp transport module.
[ 9.646543] RPC: Registered tcp transport module.
[ 9.647439] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 9.666228] FS-Cache: Loaded
[ 9.767163] FS-Cache: Netfs 'nfs' registered for caching
[ 9.773025] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 9.778351] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 9.824528] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 9.853903] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
idmapd^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Cleaning up temporary files...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[^[[36minfo^[[39;49m] Setting console screen modes.
setterm: cannot (un)set powersave mode: Inappropriate ioctl for device
^[[9;30]^[[14;30][^[[36minfo^[[39;49m] Skipping font and keymap setup (handled by console-setup).
[....] Setting up console font and keymap...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0cdone.
[ 10.179170] Loading iSCSI transport class v2.0-870.
[....] Setting up X socket directories... /tmp/.X11-unix /tmp/.ICE-unix^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting iSCSI initiator service: iscsid[ 10.198439] iscsi: registered transport (tcp)
[ 10.268938] iscsi: registered transport (iser)
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Setting up iSCSI targets:
iscsiadm: No records found
^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Mounting network filesystems:^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
\rINIT: Entering runlevel: 2
[^[[36minfo^[[39;49m] Using makefile-style concurrent boot in runlevel 2.
[....] Starting rpcbind daemon...[....] Already running.^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting NFS common utilities: statd idmapd^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting VirtualBox AdditionsVBoxService: error: VbglR3Init failed with rc=VERR_FILE_NOT_FOUND
^[[?25l^[[?1c^[7^[[1G[^[[31mFAIL^[[39;49m^[8^[[?25h^[[?0c ^[[31mfailed!^[[39;49m
[....] Starting enhanced syslogd: rsyslogd^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting deferred execution scheduler: atd^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting periodic command scheduler: cron^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting OpenBSD Secure Shell server: sshd^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[ 10.499747] Rounding down aligned max_sectors from 4294967295 to 4294967288
[....] Starting ACPI services...^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
[....] Starting MTA: exim4^[[?25l^[[?1c^[7^[[1G[^[[32m ok ^[[39;49m^[8^[[?25h^[[?0c.
Loading target_core_mod/ConfigFS core: [OK]
Calling ConfigFS script /etc/target/tcm_start.sh for target_core_mod: [OK]
Calling ConfigFS script /etc/target/lio_start.sh for iscsi_target_mod: [OK]
Calling ConfigFS script /etc/target/fc_start.sh: [OK]
Calling ConfigFS script /etc/target/loopback_start.sh: [OK]
Calling ConfigFS script /etc/target/qla2xxx_start.sh: [ 11.921930] qla2xxx [0000:00:00.0]-0005: : QLogic Fibre Channel HBA Driver: 8.07.00.02-k.
[OK]
Calling ConfigFS script /etc/target/srpt_start.sh: [OK]
[....] startpar: service(s) returned failure: virtualbox-guest-utils ...^[[?25l^[[?1c^[7^[[1G[^[[31mFAIL^[[39;49m^[8^[[?25h^[[?0c ^[[31mfailed!^[[39;49m
[ 1060.920695] scsi3 : iSCSI Initiator over TCP/IP
[ 1061.197777] scsi 3:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1061.200937] sd 3:0:0:0: Attached scsi generic sg2 type 0
[ 1061.201122] sd 3:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1061.201975] sd 3:0:0:0: [sdb] Write Protect is off
[ 1061.202273] sd 3:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1061.205080] sdb: unknown partition table
[ 1061.207619] sd 3:0:0:0: [sdb] Attached SCSI disk
[ 1168.271255] SGI XFS with ACLs, security attributes, realtime, large block/inode numbers, no debug enabled
[ 1168.374912] XFS (sdb): Mounting Filesystem
[ 1168.404910] XFS (sdb): Ending clean mount
[ 1179.960553] XFS (sdb): metadata I/O error: block 0x100022 ("xlog_iodone") error 19 numblks 64
[ 1179.964431] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1179.966215] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1179.967180] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1179.969179] XFS (sdb): Unable to update superblock counters. Freespace may not be correct on next mount.
[ 1179.971418] XFS (sdb): xfs_log_force: error 5 returned.
[ 1214.547781] scsi4 : iSCSI Initiator over TCP/IP
[ 1214.862072] scsi 4:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1214.880146] sd 4:0:0:0: Attached scsi generic sg2 type 0
[ 1214.880220] sd 4:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1214.880996] sd 4:0:0:0: [sdb] Write Protect is off
[ 1214.881315] sd 4:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1214.883864] sdb: unknown partition table
[ 1214.892436] sd 4:0:0:0: [sdb] Attached SCSI disk
[ 1215.903510] XFS (sdb): Mounting Filesystem
[ 1215.957308] XFS (sdb): Ending clean mount
[ 1227.500594] XFS (sdb): metadata I/O error: block 0x100022 ("xlog_iodone") error 19 numblks 64
[ 1227.532491] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1227.534129] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1227.535085] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1227.536330] XFS (sdb): Unable to update superblock counters. Freespace may not be correct on next mount.
[ 1227.537738] XFS (sdb): xfs_log_force: error 5 returned.
[ 1246.277297] scsi5 : iSCSI Initiator over TCP/IP
[ 1246.545729] scsi 5:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1246.608288] sd 5:0:0:0: Attached scsi generic sg2 type 0
[ 1246.608428] sd 5:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1246.609229] sd 5:0:0:0: [sdb] Write Protect is off
[ 1246.609515] sd 5:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1246.611411] sdb: unknown partition table
[ 1246.617654] sd 5:0:0:0: [sdb] Attached SCSI disk
[ 1247.628210] XFS (sdb): Mounting Filesystem
[ 1247.659319] XFS (sdb): Ending clean mount
[ 1259.292478] XFS (sdb): metadata I/O error: block 0x100022 ("xlog_iodone") error 19 numblks 64
[ 1259.298835] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1259.300609] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1259.301586] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1259.302787] XFS (sdb): Unable to update superblock counters. Freespace may not be correct on next mount.
[ 1259.304267] XFS (sdb): xfs_log_force: error 5 returned.
[ 1259.563420] scsi6 : iSCSI Initiator over TCP/IP
[ 1259.823221] scsi 6:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1259.826101] sd 6:0:0:0: Attached scsi generic sg2 type 0
[ 1259.826352] sd 6:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1259.827234] sd 6:0:0:0: [sdb] Write Protect is off
[ 1259.827519] sd 6:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1259.829586] sdb: unknown partition table
[ 1259.837776] sd 6:0:0:0: [sdb] Attached SCSI disk
[ 1260.840659] XFS (sdb): Mounting Filesystem
[ 1260.901454] XFS (sdb): Ending clean mount
[ 1272.437772] XFS (sdb): metadata I/O error: block 0x100022 ("xlog_iodone") error 19 numblks 64
[ 1272.447629] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1272.461665] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1272.462570] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1272.498291] XFS (sdb): Unable to update superblock counters. Freespace may not be correct on next mount.
[ 1272.500889] XFS (sdb): xfs_log_force: error 5 returned.
[ 1272.758239] scsi7 : iSCSI Initiator over TCP/IP
[ 1273.106049] scsi 7:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1273.212466] sd 7:0:0:0: Attached scsi generic sg2 type 0
[ 1273.212970] sd 7:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1273.213759] sd 7:0:0:0: [sdb] Write Protect is off
[ 1273.214252] sd 7:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1273.216546] sdb: unknown partition table
[ 1273.221570] sd 7:0:0:0: [sdb] Attached SCSI disk
[ 1274.230699] XFS (sdb): Mounting Filesystem
[ 1274.279735] XFS (sdb): Ending clean mount
[ 1285.916854] XFS (sdb): metadata I/O error: block 0x100022 ("xlog_iodone") error 19 numblks 64
[ 1285.920326] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1285.923274] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1285.924413] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1285.925682] XFS (sdb): Unable to update superblock counters. Freespace may not be correct on next mount.
[ 1285.928770] XFS (sdb): xfs_log_force: error 5 returned.
[ 1286.185785] scsi8 : iSCSI Initiator over TCP/IP
[ 1286.441840] scsi 8:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1286.547719] sd 8:0:0:0: Attached scsi generic sg2 type 0
[ 1286.548063] sd 8:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1286.548717] sd 8:0:0:0: [sdb] Write Protect is off
[ 1286.548900] sd 8:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1286.552043] sdb: unknown partition table
[ 1286.558140] sd 8:0:0:0: [sdb] Attached SCSI disk
[ 1287.567265] XFS (sdb): Mounting Filesystem
[ 1287.593622] XFS (sdb): Ending clean mount
[ 1297.626205] Buffer I/O error on device sdb, logical block 210607
[ 1297.632907] lost page write due to I/O error on sdb
[ 1297.633569] Buffer I/O error on device sdb, logical block 760
[ 1297.633571] lost page write due to I/O error on sdb
[ 1297.633604] Buffer I/O error on device sdb, logical block 761
[ 1297.633606] lost page write due to I/O error on sdb
[ 1297.638913] Buffer I/O error on device sdb, logical block 210608
[ 1297.640916] lost page write due to I/O error on sdb
[ 1297.645724] Buffer I/O error on device sdb, logical block 210609
[ 1297.646026] Buffer I/O error on device sdb, logical block 762
[ 1297.646026] lost page write due to I/O error on sdb
[ 1297.646027] Buffer I/O error on device sdb, logical block 763
[ 1297.646027] lost page write due to I/O error on sdb
[ 1297.646028] Buffer I/O error on device sdb, logical block 764
[ 1297.646028] lost page write due to I/O error on sdb
[ 1297.646029] Buffer I/O error on device sdb, logical block 765
[ 1297.646029] lost page write due to I/O error on sdb
[ 1297.653592] lost page write due to I/O error on sdb
[ 1297.654668] Buffer I/O error on device sdb, logical block 210610
[ 1297.655761] lost page write due to I/O error on sdb
[ 1297.676528] XFS (sdb): metadata I/O error: block 0x1015a5 ("xlog_iodone") error 5 numblks 64
[ 1297.678654] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1297.681086] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1297.682080] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1297.683592] XFS (sdb): xfs_log_force: error 5 returned.
[ 1299.273455] XFS (sdb): xfs_log_force: error 5 returned.
[ 1299.277383] XFS (sdb): xfs_log_force: error 5 returned.
[ 1299.278827] XFS (sdb): xfs_log_force: error 5 returned.
[ 1299.535818] scsi9 : iSCSI Initiator over TCP/IP
[ 1299.793601] scsi 9:0:0:0: Direct-Access LIO-ORG FILEIO 4.0 PQ: 0 ANSI: 5
[ 1299.804477] sd 9:0:0:0: Attached scsi generic sg2 type 0
[ 1299.804954] sd 9:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
[ 1299.807208] sd 9:0:0:0: [sdb] Write Protect is off
[ 1299.808239] sd 9:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 1299.811284] sdb: unknown partition table
[ 1299.815687] sd 9:0:0:0: [sdb] Attached SCSI disk
[ 1300.817795] XFS (sdb): Mounting Filesystem
[ 1300.876803] XFS (sdb): Starting recovery (logdev: internal)
[ 1301.757722] XFS (sdb): Ending recovery (logdev: internal)
[ 1317.564295] connection7:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4295219182, last ping 4295220434, now 4295221688
[ 1317.698373] connection7:0: detected conn error (1011)
[ 1317.952194] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.004545] sd 9:0:0:0: [sdb]
[ 1318.027827] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.092606] sd 9:0:0:0: [sdb] CDB:
[ 1318.124494] Write(10): 2a 00 00 1e e7 00 00 04 00 00
[ 1318.152442] end_request: recoverable transport error, dev sdb, sector 2025216
[ 1318.153600] quiet_error: 7825 callbacks suppressed
[ 1318.154314] Buffer I/O error on device sdb, logical block 209591
[ 1318.155138] lost page write due to I/O error on sdb
[ 1318.155852] Buffer I/O error on device sdb, logical block 209592
[ 1318.156808] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.157592] sd 9:0:0:0: [sdb]
[ 1318.158165] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.159058] sd 9:0:0:0: [sdb] CDB:
[ 1318.159647] Write(10): 2a 00 00 1e 8c 80 00 04 00 00
[ 1318.161411] end_request: recoverable transport error, dev sdb, sector 2002048
[ 1318.162346] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.163234] sd 9:0:0:0: [sdb]
[ 1318.163805] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.164746] sd 9:0:0:0: [sdb] CDB:
[ 1318.165389] Write(10): 2a 00 00 19 86 38 00 04 00 00
[ 1318.167047] end_request: recoverable transport error, dev sdb, sector 1672760
[ 1318.168063] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.168804] sd 9:0:0:0: [sdb]
[ 1318.169352] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.170240] sd 9:0:0:0: [sdb] CDB:
[ 1318.170841] Write(10): 2a 00 00 19 8a 38 00 04 00 00
[ 1318.188744] end_request: recoverable transport error, dev sdb, sector 1673784
[ 1318.198671] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.199603] sd 9:0:0:0: [sdb]
[ 1318.200213] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.203254] sd 9:0:0:0: [sdb] CDB:
[ 1318.203831] Write(10): 2a 00 00 1e a4 00 00 01 70 00
[ 1318.205576] end_request: recoverable transport error, dev sdb, sector 2008064
[ 1318.206506] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.207215] sd 9:0:0:0: [sdb]
[ 1318.207798] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.208783] sd 9:0:0:0: [sdb] CDB:
[ 1318.209427] Write(10): 2a 00 00 1e ab 00 00 04 00 00
[ 1318.211482] end_request: recoverable transport error, dev sdb, sector 2009856
[ 1318.253685] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.254443] sd 9:0:0:0: [sdb]
[ 1318.255028] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.255946] sd 9:0:0:0: [sdb] CDB:
[ 1318.256696] Write(10): 2a 00 00 1e a7 00 00 04 00 00
[ 1318.260771] end_request: recoverable transport error, dev sdb, sector 2008832
[ 1318.343810] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.392563] sd 9:0:0:0: [sdb]
[ 1318.424511] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.496617] sd 9:0:0:0: [sdb] CDB:
[ 1318.497282] Write(10): 2a 00 00 1e 88 80 00 04 00 00
[ 1318.499156] end_request: recoverable transport error, dev sdb, sector 2001024
[ 1318.500201] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.500981] sd 9:0:0:0: [sdb]
[ 1318.501563] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.502508] sd 9:0:0:0: [sdb] CDB:
[ 1318.503132] Write(10): 2a 00 00 1e eb 00 00 04 00 00
[ 1318.504934] end_request: recoverable transport error, dev sdb, sector 2026240
[ 1318.505919] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.506673] sd 9:0:0:0: [sdb]
[ 1318.507252] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.508256] sd 9:0:0:0: [sdb] CDB:
[ 1318.508940] Write(10): 2a 00 00 1e 83 00 00 00 a8 00
[ 1318.510793] end_request: recoverable transport error, dev sdb, sector 1999616
[ 1318.511778] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.512553] sd 9:0:0:0: [sdb]
[ 1318.513169] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.514103] sd 9:0:0:0: [sdb] CDB:
[ 1318.514725] Write(10): 2a 00 00 1e d3 00 00 04 00 00
[ 1318.516559] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.517305] sd 9:0:0:0: [sdb]
[ 1318.517882] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.518821] sd 9:0:0:0: [sdb] CDB:
[ 1318.519433] Write(10): 2a 00 00 19 8e 38 00 02 90 00
[ 1318.521266] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.522017] sd 9:0:0:0: [sdb]
[ 1318.522600] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.523668] sd 9:0:0:0: [sdb] CDB:
[ 1318.524312] Write(10): 2a 00 00 1a 18 50 00 03 90 00
[ 1318.526082] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.526836] sd 9:0:0:0: [sdb]
[ 1318.527421] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.528436] sd 9:0:0:0: [sdb] CDB:
[ 1318.529086] Write(10): 2a 00 00 1e c3 00 00 04 00 00
[ 1318.530827] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.531569] sd 9:0:0:0: [sdb]
[ 1318.532194] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.533181] sd 9:0:0:0: [sdb] CDB:
[ 1318.533795] Write(10): 2a 00 00 1e b7 00 00 04 00 00
[ 1318.537088] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.537838] sd 9:0:0:0: [sdb]
[ 1318.538414] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.539363] sd 9:0:0:0: [sdb] CDB:
[ 1318.539974] Write(10): 2a 00 00 1e b3 00 00 04 00 00
[ 1318.541807] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.542553] sd 9:0:0:0: [sdb]
[ 1318.543133] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.544197] sd 9:0:0:0: [sdb] CDB:
[ 1318.544948] Write(10): 2a 00 00 1e f3 00 00 04 00 00
[ 1318.546687] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.548760] sd 9:0:0:0: [sdb]
[ 1318.549380] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.550315] sd 9:0:0:0: [sdb] CDB:
[ 1318.550940] Write(10): 2a 00 00 1e d7 00 00 04 00 00
[ 1318.552895] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.554495] sd 9:0:0:0: [sdb]
[ 1318.555082] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.556084] sd 9:0:0:0: [sdb] CDB:
[ 1318.556739] Write(10): 2a 00 00 1e f7 00 00 04 00 00
[ 1318.558479] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.559368] sd 9:0:0:0: [sdb]
[ 1318.559947] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.560939] sd 9:0:0:0: [sdb] CDB:
[ 1318.561618] Write(10): 2a 00 00 1e c7 00 00 04 00 00
[ 1318.563365] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.564184] sd 9:0:0:0: [sdb]
[ 1318.564819] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.565759] sd 9:0:0:0: [sdb] CDB:
[ 1318.566372] Write(10): 2a 00 00 1e af 00 00 04 00 00
[ 1318.568171] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.568950] sd 9:0:0:0: [sdb]
[ 1318.569533] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.570471] sd 9:0:0:0: [sdb] CDB:
[ 1318.571229] Write(10): 2a 00 00 1e bf 00 00 04 00 00
[ 1318.573106] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.573856] sd 9:0:0:0: [sdb]
[ 1318.574442] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.575384] sd 9:0:0:0: [sdb] CDB:
[ 1318.576061] Write(10): 2a 00 00 1e 90 80 00 03 a0 00
[ 1318.577834] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.578579] sd 9:0:0:0: [sdb]
[ 1318.579161] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.580142] sd 9:0:0:0: [sdb] CDB:
[ 1318.580795] Write(10): 2a 00 00 1e a5 80 00 01 50 00
[ 1318.582533] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.583419] sd 9:0:0:0: [sdb]
[ 1318.584000] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.584994] sd 9:0:0:0: [sdb] CDB:
[ 1318.585648] Write(10): 2a 00 00 1e bb 00 00 04 00 00
[ 1318.587398] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.588208] sd 9:0:0:0: [sdb]
[ 1318.588846] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.589783] sd 9:0:0:0: [sdb] CDB:
[ 1318.590402] Write(10): 2a 00 00 1e e3 00 00 04 00 00
[ 1318.592371] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.593121] sd 9:0:0:0: [sdb]
[ 1318.593702] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.594636] sd 9:0:0:0: [sdb] CDB:
[ 1318.595398] Write(10): 2a 00 00 1e df 00 00 04 00 00
[ 1318.597208] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.597955] sd 9:0:0:0: [sdb]
[ 1318.598535] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.599481] sd 9:0:0:0: [sdb] CDB:
[ 1318.600138] Write(10): 2a 00 00 1e ef 00 00 04 00 00
[ 1318.601904] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.602649] sd 9:0:0:0: [sdb]
[ 1318.603229] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.604205] sd 9:0:0:0: [sdb] CDB:
[ 1318.604854] Write(10): 2a 00 00 1e 84 80 00 04 00 00
[ 1318.607524] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.608295] sd 9:0:0:0: [sdb]
[ 1318.609019] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.609964] sd 9:0:0:0: [sdb] CDB:
[ 1318.610578] Write(10): 2a 00 00 1e cf 00 00 04 00 00
[ 1318.613299] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.614000] sd 9:0:0:0: [sdb]
[ 1318.614563] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.616727] sd 9:0:0:0: [sdb] CDB:
[ 1318.617718] Write(10): 2a 00 00 1e db 00 00 04 00 00
[ 1318.619568] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.620338] sd 9:0:0:0: [sdb]
[ 1318.620923] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.621822] sd 9:0:0:0: [sdb] CDB:
[ 1318.622416] Write(10): 2a 00 00 1e fb 00 00 04 00 00
[ 1318.624191] sd 9:0:0:0: [sdb] Unhandled error code
[ 1318.624985] sd 9:0:0:0: [sdb]
[ 1318.625529] Result: hostbyte=DID_TRANSPORT_FAILFAST driverbyte=DRIVER_OK
[ 1318.626430] sd 9:0:0:0: [sdb] CDB:
[ 1318.627068] Write(10): 2a 00 00 1e cb 00 00 04 00 00
[ 1318.634723] lost page write due to I/O error on sdb
[ 1318.685066] Buffer I/O error on device sdb, logical block 209593
[ 1318.745204] lost page write due to I/O error on sdb
[ 1318.790152] Buffer I/O error on device sdb, logical block 209594
[ 1318.805509] lost page write due to I/O error on sdb
[ 1318.806278] Buffer I/O error on device sdb, logical block 209595
[ 1318.807145] lost page write due to I/O error on sdb
[ 1318.807875] Buffer I/O error on device sdb, logical block 209596
[ 1318.808818] lost page write due to I/O error on sdb
[ 1318.809585] Buffer I/O error on device sdb, logical block 209597
[ 1318.810423] lost page write due to I/O error on sdb
[ 1318.811551] Buffer I/O error on device sdb, logical block 209598
[ 1318.812477] lost page write due to I/O error on sdb
[ 1318.813273] Buffer I/O error on device sdb, logical block 209599
[ 1318.814111] lost page write due to I/O error on sdb
[ 1318.814866] Buffer I/O error on device sdb, logical block 209600
[ 1318.815726] lost page write due to I/O error on sdb
[ 1318.816643] XFS (sdb): metadata I/O error: block 0x19fc80 ("xfs_buf_iodone_callbacks") error 5 numblks 16
[ 1318.818080] XFS (sdb): metadata I/O error: block 0x1025cf ("xlog_iodone") error 5 numblks 64
[ 1318.819350] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.821089] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 1318.822301] XFS (sdb): xfs_log_force: error 5 returned.
[ 1318.822308] XFS (sdb): xfs_log_force: error 5 returned.
[ 1318.822311] XFS (sdb): Detected failing async write on buffer block 0x19fca0. Retrying async write.
[ 1318.822311]
[ 1318.822322] XFS (sdb): metadata I/O error: block 0x180010 ("xfs_trans_read_buf_map") error 5 numblks 8
[ 1318.834339] XFS (sdb): Please umount the filesystem and rectify the problem(s)
[ 1318.835687] XFS (sdb): metadata I/O error: block 0x10260f ("xlog_iodone") error 5 numblks 64
[ 1318.837029] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.838949] XFS (sdb): metadata I/O error: block 0x10264f ("xlog_iodone") error 5 numblks 64
[ 1318.840312] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.842030] XFS (sdb): metadata I/O error: block 0x10268f ("xlog_iodone") error 5 numblks 64
[ 1318.844545] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.846235] XFS (sdb): metadata I/O error: block 0x1026cf ("xlog_iodone") error 5 numblks 64
[ 1318.847730] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.850007] XFS (sdb): metadata I/O error: block 0x10270f ("xlog_iodone") error 5 numblks 64
[ 1318.852163] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.856124] XFS (sdb): metadata I/O error: block 0x10274f ("xlog_iodone") error 5 numblks 64
[ 1318.859494] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.861634] XFS (sdb): metadata I/O error: block 0x10278f ("xlog_iodone") error 5 numblks 64
[ 1318.863792] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
[ 1318.870242] XFS (sdb): xfs_log_force: error 5 returned.
[ 1319.940356] XFS (sdb): xfs_log_force: error 5 returned.
[ 1319.946209] XFS (sdb): xfs_log_force: error 5 returned.
[ 1331.804065] XFS (sdb): xfs_log_force: error 5 returned.
[ 1361.884072] XFS (sdb): xfs_log_force: error 5 returned.
[ 1391.964074] XFS (sdb): xfs_log_force: error 5 returned.
[ 44064] XFS (sdb): xfs_log_force: error 5 returned.
[ 1440.340105] INFO: task umount:5117 blocked for more than 120 seconds.
[ 1440.369364] Not tainted 3.15.0-rc3 #4
[ 1440.370368] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1440.372658] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 1440.388183] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 1440.406376] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 1440.409408] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 1440.412141] Call Trace:
[ 1440.412958] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 1440.414429] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 1440.415607] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 1440.417242] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 1440.418424] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 1440.421233] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 1440.425154] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 1440.432427] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 1440.433528] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 1440.434370] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 1440.435315] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 1440.436235] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 1440.437311] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 1440.438655] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 1452.380428] XFS (sdb): xfs_log_force: error 5 returned.
[ 1482.588354] XFS (sdb): xfs_log_force: error 5 returned.
[ 1512.668073] XFS (sdb): xfs_log_force: error 5 returned.
[ 1542.748182] XFS (sdb): xfs_log_force: error 5 returned.
[ 1560.440219] INFO: task umount:5117 blocked for more than 120 seconds.
[ 1560.532168] Not tainted 3.15.0-rc3 #4
[ 1560.587829] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1560.608207] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 1560.609583] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 1560.611451] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 1560.613365] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 1560.615075] Call Trace:
[ 1560.615649] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 1560.616656] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 1560.617448] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 1560.618388] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 1560.619239] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 1560.620157] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 1560.621024] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 1560.621912] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 1560.622801] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 1560.623759] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 1560.624711] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 1560.625559] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 1560.626405] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 1560.627199] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 1572.829210] XFS (sdb): xfs_log_force: error 5 returned.
[ 1602.908342] XFS (sdb): xfs_log_force: error 5 returned.
[ 1632.988399] XFS (sdb): xfs_log_force: error 5 returned.
[ 1663.132499] XFS (sdb): xfs_log_force: error 5 returned.
[ 1680.628549] INFO: task umount:5117 blocked for more than 120 seconds.
[ 1680.704429] Not tainted 3.15.0-rc3 #4
[ 1680.731395] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1680.732632] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 1680.733926] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 1680.735410] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 1680.737172] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 1680.738648] Call Trace:
[ 1680.739157] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 1680.739963] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 1680.740791] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 1680.741727] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 1680.742548] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 1680.744570] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 1680.745419] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 1680.746926] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 1680.747814] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 1680.748676] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 1680.749578] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 1680.750390] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 1680.751211] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 1680.752020] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 1693.276142] XFS (sdb): xfs_log_force: error 5 returned.
[ 1723.420457] XFS (sdb): xfs_log_force: error 5 returned.
[ 1753.564430] XFS (sdb): xfs_log_force: error 5 returned.
[ 1783.644139] XFS (sdb): xfs_log_force: error 5 returned.
[ 1800.752116] INFO: task umount:5117 blocked for more than 120 seconds.
[ 1800.815100] Not tainted 3.15.0-rc3 #4
[ 1800.837282] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1800.840393] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 1800.842290] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 1800.843779] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 1800.845238] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 1800.846717] Call Trace:
[ 1800.847227] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 1800.848078] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 1800.848899] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 1800.849863] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 1800.850705] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 1800.851679] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 1800.852586] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 1800.853471] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 1800.854359] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 1800.855195] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 1800.871631] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 1800.872580] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 1800.873425] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 1800.874193] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 1813.724486] XFS (sdb): xfs_log_force: error 5 returned.
[ 1843.804165] XFS (sdb): xfs_log_force: error 5 returned.
[ 1874.013249] XFS (sdb): xfs_log_force: error 5 returned.
[ 1904.156390] XFS (sdb): xfs_log_force: error 5 returned.
[ 1920.872443] INFO: task umount:5117 blocked for more than 120 seconds.
[ 1920.973873] Not tainted 3.15.0-rc3 #4
[ 1921.044680] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1921.181109] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 1921.271615] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 1921.349559] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 1921.378518] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 1921.380217] Call Trace:
[ 1921.380546] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 1921.381432] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 1921.382225] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 1921.383205] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 1921.384239] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 1921.385186] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 1921.386059] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 1921.387159] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 1921.388081] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 1921.389140] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 1921.462908] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 1921.493111] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 1921.494067] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 1921.496574] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 1934.300153] XFS (sdb): xfs_log_force: error 5 returned.
[ 1964.444113] XFS (sdb): xfs_log_force: error 5 returned.
[ 1994.588333] XFS (sdb): xfs_log_force: error 5 returned.
[ 2024.668416] XFS (sdb): xfs_log_force: error 5 returned.
[ 2041.496128] INFO: task umount:5117 blocked for more than 120 seconds.
[ 2041.607517] Not tainted 3.15.0-rc3 #4
[ 2041.608291] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2041.609861] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 2041.613183] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 2041.614728] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 2041.616395] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 2041.617939] Call Trace:
[ 2041.618457] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 2041.666536] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 2041.667611] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 2041.668619] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 2041.669631] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 2041.670524] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 2041.671411] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 2041.672387] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 2041.673333] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 2041.674198] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 2041.676633] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 2041.677604] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 2041.678469] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 2041.679417] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 2054.748423] XFS (sdb): xfs_log_force: error 5 returned.
[ 2084.892394] XFS (sdb): xfs_log_force: error 5 returned.
[ 2115.036504] XFS (sdb): xfs_log_force: error 5 returned.
[ 2145.180141] XFS (sdb): xfs_log_force: error 5 returned.
[ 2161.680165] INFO: task umount:5117 blocked for more than 120 seconds.
[ 2161.798381] Not tainted 3.15.0-rc3 #4
[ 2161.881813] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2161.992806] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 2162.109607] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 2162.264618] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 2162.406185] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 2162.531958] Call Trace:
[ 2162.576437] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 2162.667872] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 2162.689774] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 2162.690657] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 2162.691420] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 2162.692226] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 2162.693053] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 2162.693849] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 2162.694653] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 2162.696593] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 2162.697501] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 2162.698276] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 2162.699194] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 2162.699924] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[ 2175.261310] XFS (sdb): xfs_log_force: error 5 returned.
[ 2205.404402] XFS (sdb): xfs_log_force: error 5 returned.
[ 2235.548495] XFS (sdb): xfs_log_force: error 5 returned.
[ 2265.692166] XFS (sdb): xfs_log_force: error 5 returned.
[ 2282.700195] INFO: task umount:5117 blocked for more than 120 seconds.
[ 2282.818341] Not tainted 3.15.0-rc3 #4
[ 2282.856752] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2282.927098] umount D ffffffff8180fe40 0 5117 4245 0x00000000
[ 2283.042593] ffff880030285d58 0000000000000082 ffff880030285d48 ffffffff81080f82
[ 2283.089039] ffff88002f9b8000 0000000000013180 ffff880030285fd8 0000000000013180
[ 2283.090537] ffff88003daa0000 ffff88002f9b8000 ffff88001bbeb0c0 ffff88001bbeb080
[ 2283.092045] Call Trace:
[ 2283.093129] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
[ 2283.138571] [<ffffffff816c54d9>] schedule+0x29/0x70
[ 2283.228649] [<ffffffffa04c0cd6>] xfs_ail_push_all_sync+0x96/0xd0 [xfs]
[ 2283.338136] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
[ 2283.422283] [<ffffffffa046f1a3>] xfs_unmountfs+0x63/0x160 [xfs]
[ 2283.423137] [<ffffffffa0474f65>] ? kmem_free+0x35/0x40 [xfs]
[ 2283.423931] [<ffffffffa0470cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
[ 2283.424842] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
[ 2283.475973] [<ffffffff811956d0>] kill_block_super+0x30/0x80
[ 2283.486258] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
[ 2283.488865] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
[ 2283.489710] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
[ 2283.490723] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
[ 2283.491501] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
[-- Attachment #3: Type: text/plain, Size: 121 bytes --]
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
2014-04-28 23:51 ` Bob Mastors
@ 2014-04-29 1:01 ` Dave Chinner
2014-04-29 1:11 ` Bob Mastors
[not found] ` <CALjwKZBj0f_y7MPp-PLqhLDOnfmf2OWsvv_vbnX08ubevqM+Bg@mail.gmail.com>
0 siblings, 2 replies; 8+ messages in thread
From: Dave Chinner @ 2014-04-29 1:01 UTC (permalink / raw)
To: Bob Mastors; +Cc: xfs
On Mon, Apr 28, 2014 at 05:51:31PM -0600, Bob Mastors wrote:
> Log output attached.
> The xfs filesystem being mounted and unmounted is the only xfs filesystem
> on the system.
> Bob
>
>
> On Mon, Apr 28, 2014 at 5:45 PM, Dave Chinner <david@fromorbit.com> wrote:
>
> > On Mon, Apr 28, 2014 at 04:29:02PM -0600, Bob Mastors wrote:
> > > Greetings,
> > >
> > > I have an xfs umount hang caused by forcing the block device to return
> > > i/o errors while copying files to the filesystem.
> > > Detailed steps to reproduce the problem on virtualbox are below.
> > >
> > > The linux version is a recent pull and reports as 3.15.0-rc3.
> > >
> > > [ 2040.248096] INFO: task umount:10303 blocked for more than 120 seconds.
> > > [ 2040.323947] Not tainted 3.15.0-rc3 #4
> > > [ 2040.343423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables
> > > this message.
> > > [ 2040.352665] umount D ffffffff8180fe40 0 10303 8691
> > > 0x00000000
> > > [ 2040.404918] ffff88001e33dd58 0000000000000086 ffff88001e33dd48
> > > ffffffff81080f82
> > > [ 2040.489901] ffff88001b311900 0000000000013180 ffff88001e33dfd8
> > > 0000000000013180
> > > [ 2040.534772] ffff88003daa3200 ffff88001b311900 ffff88002421aec0
> > > ffff88002421ae80
> > > [ 2040.587450] Call Trace:
> > > [ 2040.592176] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
> > > [ 2040.620212] [<ffffffff816c54d9>] schedule+0x29/0x70
> > > [ 2040.627685] [<ffffffffa04c4cd6>] xfs_ail_push_all_sync+0x96/0xd0
> > [xfs]
> > > [ 2040.632236] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
> > > [ 2040.659105] [<ffffffffa04731a3>] xfs_unmountfs+0x63/0x160 [xfs]
> > > [ 2040.691774] [<ffffffffa0478f65>] ? kmem_free+0x35/0x40 [xfs]
> > > [ 2040.698610] [<ffffffffa0474cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
> > > [ 2040.706838] [<ffffffff8119561e>] generic_shutdown_super+0x7e/0x100
> > > [ 2040.723958] [<ffffffff811956d0>] kill_block_super+0x30/0x80
> > > [ 2040.734963] [<ffffffff8119591d>] deactivate_locked_super+0x4d/0x80
> > > [ 2040.745485] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
> > > [ 2040.751274] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
> > > [ 2040.755894] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
> > > [ 2040.761032] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
> > > [ .060058] XFS (sdb): xfs_log_force: error 5 returned.
> > > [ 268059] XFS (sdb): xfs_log_force: error 5 returned.
> > >
> > > I took a look at xfs_ail_push_all_sync and it is pretty easy to see
> > > the hang. But it is not obvious to me how to fix it.
> > > Any ideas would be appreciated.
> > >
> > > I am available to run additional tests or capture more logging
> > > or whatever if that would help.
> >
> > What's the entire log output from the first shutdown message?
So what is the AIL stuck on? Can you trace the xfs_ail* trace points
when it is in shutdown like this and post the output of the report?
> [ 1318.816643] XFS (sdb): metadata I/O error: block 0x19fc80 ("xfs_buf_iodone_callbacks") error 5 numblks 16
> [ 1318.818080] XFS (sdb): metadata I/O error: block 0x1025cf ("xlog_iodone") error 5 numblks 64
> [ 1318.819350] XFS (sdb): xfs_do_force_shutdown(0x2) called from line 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
> [ 1318.821089] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
> [ 1318.822301] XFS (sdb): xfs_log_force: error 5 returned.
> [ 1318.822308] XFS (sdb): xfs_log_force: error 5 returned.
> [ 1318.822311] XFS (sdb): Detected failing async write on buffer block 0x19fca0. Retrying async write.
That's the only thing that is unusual about the hang. Does this
always appear when a hang occurs?
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
2014-04-29 1:01 ` Dave Chinner
@ 2014-04-29 1:11 ` Bob Mastors
[not found] ` <CALjwKZBj0f_y7MPp-PLqhLDOnfmf2OWsvv_vbnX08ubevqM+Bg@mail.gmail.com>
1 sibling, 0 replies; 8+ messages in thread
From: Bob Mastors @ 2014-04-29 1:11 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
[-- Attachment #1.1: Type: text/plain, Size: 4187 bytes --]
On Mon, Apr 28, 2014 at 7:01 PM, Dave Chinner <david@fromorbit.com> wrote:
> On Mon, Apr 28, 2014 at 05:51:31PM -0600, Bob Mastors wrote:
> > Log output attached.
> > The xfs filesystem being mounted and unmounted is the only xfs filesystem
> > on the system.
> > Bob
> >
> >
> > On Mon, Apr 28, 2014 at 5:45 PM, Dave Chinner <david@fromorbit.com>
> wrote:
> >
> > > On Mon, Apr 28, 2014 at 04:29:02PM -0600, Bob Mastors wrote:
> > > > Greetings,
> > > >
> > > > I have an xfs umount hang caused by forcing the block device to
> return
> > > > i/o errors while copying files to the filesystem.
> > > > Detailed steps to reproduce the problem on virtualbox are below.
> > > >
> > > > The linux version is a recent pull and reports as 3.15.0-rc3.
> > > >
> > > > [ 2040.248096] INFO: task umount:10303 blocked for more than 120
> seconds.
> > > > [ 2040.323947] Not tainted 3.15.0-rc3 #4
> > > > [ 2040.343423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > > disables
> > > > this message.
> > > > [ 2040.352665] umount D ffffffff8180fe40 0 10303 8691
> > > > 0x00000000
> > > > [ 2040.404918] ffff88001e33dd58 0000000000000086 ffff88001e33dd48
> > > > ffffffff81080f82
> > > > [ 2040.489901] ffff88001b311900 0000000000013180 ffff88001e33dfd8
> > > > 0000000000013180
> > > > [ 2040.534772] ffff88003daa3200 ffff88001b311900 ffff88002421aec0
> > > > ffff88002421ae80
> > > > [ 2040.587450] Call Trace:
> > > > [ 2040.592176] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
> > > > [ 2040.620212] [<ffffffff816c54d9>] schedule+0x29/0x70
> > > > [ 2040.627685] [<ffffffffa04c4cd6>] xfs_ail_push_all_sync+0x96/0xd0
> > > [xfs]
> > > > [ 2040.632236] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
> > > > [ 2040.659105] [<ffffffffa04731a3>] xfs_unmountfs+0x63/0x160 [xfs]
> > > > [ 2040.691774] [<ffffffffa0478f65>] ? kmem_free+0x35/0x40 [xfs]
> > > > [ 2040.698610] [<ffffffffa0474cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
> > > > [ 2040.706838] [<ffffffff8119561e>]
> generic_shutdown_super+0x7e/0x100
> > > > [ 2040.723958] [<ffffffff811956d0>] kill_block_super+0x30/0x80
> > > > [ 2040.734963] [<ffffffff8119591d>]
> deactivate_locked_super+0x4d/0x80
> > > > [ 2040.745485] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
> > > > [ 2040.751274] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
> > > > [ 2040.755894] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
> > > > [ 2040.761032] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
> > > > [ .060058] XFS (sdb): xfs_log_force: error 5 returned.
> > > > [ 268059] XFS (sdb): xfs_log_force: error 5 returned.
> > > >
> > > > I took a look at xfs_ail_push_all_sync and it is pretty easy to see
> > > > the hang. But it is not obvious to me how to fix it.
> > > > Any ideas would be appreciated.
> > > >
> > > > I am available to run additional tests or capture more logging
> > > > or whatever if that would help.
> > >
> > > What's the entire log output from the first shutdown message?
>
> So what is the AIL stuck on? Can you trace the xfs_ail* trace points
> when it is in shutdown like this and post the output of the report?
>
I will try to get this info.
Might take a couple of days.
>
> > [ 1318.816643] XFS (sdb): metadata I/O error: block 0x19fc80
> ("xfs_buf_iodone_callbacks") error 5 numblks 16
> > [ 1318.818080] XFS (sdb): metadata I/O error: block 0x1025cf
> ("xlog_iodone") error 5 numblks 64
> > [ 1318.819350] XFS (sdb): xfs_do_force_shutdown(0x2) called from line
> 1170 of file fs/xfs/xfs_log.c. Return address = 0xffffffffa04b9859
> > [ 1318.821089] XFS (sdb): Log I/O Error Detected. Shutting down
> filesystem
> > [ 1318.822301] XFS (sdb): xfs_log_force: error 5 returned.
> > [ 1318.822308] XFS (sdb): xfs_log_force: error 5 returned.
> > [ 1318.822311] XFS (sdb): Detected failing async write on buffer block
> 0x19fca0. Retrying async write.
>
> That's the only thing that is unusual about the hang. Does this
> always appear when a hang occurs?
>
I don't think so but I have not been keeping all of the logs.
I will run the test some more and see if it always appears or not.
Thanks,
Bob
>
> Cheers,
>
> Dave.
> --
> Dave Chinner
> david@fromorbit.com
>
[-- Attachment #1.2: Type: text/html, Size: 5809 bytes --]
[-- Attachment #2: Type: text/plain, Size: 121 bytes --]
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
[not found] ` <CALjwKZBj0f_y7MPp-PLqhLDOnfmf2OWsvv_vbnX08ubevqM+Bg@mail.gmail.com>
@ 2014-04-30 3:22 ` Dave Chinner
[not found] ` <CALjwKZDeTcOSJDtRcNa3KtLraPKvWUB0jvQrwSANxB0RHds0Rg@mail.gmail.com>
0 siblings, 1 reply; 8+ messages in thread
From: Dave Chinner @ 2014-04-30 3:22 UTC (permalink / raw)
To: Bob Mastors; +Cc: xfs
On Tue, Apr 29, 2014 at 03:47:15PM -0600, Bob Mastors wrote:
> On Mon, Apr 28, 2014 at 7:01 PM, Dave Chinner <david@fromorbit.com> wrote:
>
> > On Mon, Apr 28, 2014 at 05:51:31PM -0600, Bob Mastors wrote:
> > > Log output attached.
> > > The xfs filesystem being mounted and unmounted is the only xfs filesystem
> > > on the system.
> > > Bob
> > >
> > >
> > > On Mon, Apr 28, 2014 at 5:45 PM, Dave Chinner <david@fromorbit.com>
> > wrote:
> > >
> > > > On Mon, Apr 28, 2014 at 04:29:02PM -0600, Bob Mastors wrote:
> > > > > Greetings,
> > > > >
> > > > > I have an xfs umount hang caused by forcing the block device to
> > return
> > > > > i/o errors while copying files to the filesystem.
> > > > > Detailed steps to reproduce the problem on virtualbox are below.
> > > > >
> > > > > The linux version is a recent pull and reports as 3.15.0-rc3.
> > > > >
> > > > > [ 2040.248096] INFO: task umount:10303 blocked for more than 120
> > seconds.
> > > > > [ 2040.323947] Not tainted 3.15.0-rc3 #4
> > > > > [ 2040.343423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > > > disables
> > > > > this message.
> > > > > [ 2040.352665] umount D ffffffff8180fe40 0 10303 8691
> > > > > 0x00000000
> > > > > [ 2040.404918] ffff88001e33dd58 0000000000000086 ffff88001e33dd48
> > > > > ffffffff81080f82
> > > > > [ 2040.489901] ffff88001b311900 0000000000013180 ffff88001e33dfd8
> > > > > 0000000000013180
> > > > > [ 2040.534772] ffff88003daa3200 ffff88001b311900 ffff88002421aec0
> > > > > ffff88002421ae80
> > > > > [ 2040.587450] Call Trace:
> > > > > [ 2040.592176] [<ffffffff81080f82>] ? try_to_wake_up+0x232/0x2b0
> > > > > [ 2040.620212] [<ffffffff816c54d9>] schedule+0x29/0x70
> > > > > [ 2040.627685] [<ffffffffa04c4cd6>] xfs_ail_push_all_sync+0x96/0xd0
> > > > [xfs]
> > > > > [ 2040.632236] [<ffffffff81092230>] ? __wake_up_sync+0x20/0x20
> > > > > [ 2040.659105] [<ffffffffa04731a3>] xfs_unmountfs+0x63/0x160 [xfs]
> > > > > [ 2040.691774] [<ffffffffa0478f65>] ? kmem_free+0x35/0x40 [xfs]
> > > > > [ 2040.698610] [<ffffffffa0474cf5>] xfs_fs_put_super+0x25/0x60 [xfs]
> > > > > [ 2040.706838] [<ffffffff8119561e>]
> > generic_shutdown_super+0x7e/0x100
> > > > > [ 2040.723958] [<ffffffff811956d0>] kill_block_super+0x30/0x80
> > > > > [ 2040.734963] [<ffffffff8119591d>]
> > deactivate_locked_super+0x4d/0x80
> > > > > [ 2040.745485] [<ffffffff8119652e>] deactivate_super+0x4e/0x70
> > > > > [ 2040.751274] [<ffffffff811b1d42>] mntput_no_expire+0xd2/0x160
> > > > > [ 2040.755894] [<ffffffff811b2fff>] SyS_umount+0xaf/0x3b0
> > > > > [ 2040.761032] [<ffffffff816d1592>] system_call_fastpath+0x16/0x1b
> > > > > [ .060058] XFS (sdb): xfs_log_force: error 5 returned.
> > > > > [ 268059] XFS (sdb): xfs_log_force: error 5 returned.
> > > > >
> > > > > I took a look at xfs_ail_push_all_sync and it is pretty easy to see
> > > > > the hang. But it is not obvious to me how to fix it.
> > > > > Any ideas would be appreciated.
> > > > >
> > > > > I am available to run additional tests or capture more logging
> > > > > or whatever if that would help.
> > > >
> > > > What's the entire log output from the first shutdown message?
> >
> > So what is the AIL stuck on? Can you trace the xfs_ail* trace points
> > when it is in shutdown like this and post the output of the report?
> >
>
>
> # tracer: function
> #
> # entries-in-buffer/entries-written: 32/32 #P:4
> #
> # _-----=> irqs-off
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| / delay
> # TASK-PID CPU# |||| TIMESTAMP FUNCTION
> # | | | |||| | |
> umount-2995 [003] .... 1125.524090: xfs_unmountfs <-xfs_fs_put_super
> umount-2995 [003] .... 1125.524099: xfs_ail_push_all_sync <-xfs_unmountfs
> umount-2995 [003] .... 1125.527498: xfs_ail_push_all_sync <-xfs_log_quiesce
> kswapd0-43 [002] .... 1148.078330: xfs_ail_push_all <-xfs_reclaim_inodes_nr
> kswapd0-43 [002] .... 1148.078332: xfs_ail_push <-xfs_ail_push_all
> xfsaild/sdb-3005 [002] .... 1148.128311: xfs_ail_min_lsn <-xfsaild
> kswapd0-43 [001] .... 1149.971684: xfs_ail_push_all <-xfs_reclaim_inodes_nr
> kswapd0-43 [001] .... 1149.971695: xfs_ail_push <-xfs_ail_push_all
> xfsaild/sdb-3005 [003] .... 1150.023104: xfs_ail_min_lsn <-xfsaild
> umount-3013 [000] .N.. 1153.035350: xfs_unmountfs <-xfs_fs_put_super
> umount-3013 [000] .... 1153.093488: xfs_ail_push_all_sync <-xfs_unmountfs
> umount-3013 [000] .... 1153.122459: xfs_ail_push_all_sync <-xfs_log_quiesce
> kswapd0-43 [003] .... 1186.232408: xfs_ail_push_all <-xfs_reclaim_inodes_nr
> kswapd0-43 [003] .... 1186.232411: xfs_ail_push <-xfs_ail_push_all
> xfsaild/sdb-3035 [001] .... 1186.288258: xfs_ail_min_lsn <-xfsaild
> umount-3043 [001] .... 1188.653981: xfs_unmountfs <-xfs_fs_put_super
> umount-3043 [001] .... 1188.653991: xfs_ail_push_all_sync <-xfs_unmountfs
> kworker/0:0-2865 [000] .... 1199.903174: xfs_ail_min_lsn <-xfs_log_need_covered
> kworker/0:0-2865 [000] .... 1199.903179: xfs_ail_push_all <-xfs_log_worker
> kworker/0:0-2865 [000] .... 1199.903180: xfs_ail_push <-xfs_ail_push_all
> kworker/0:0-2865 [000] .... 1229.837372: xfs_ail_min_lsn <-xfs_log_need_covered
> kworker/0:0-2865 [000] .... 1229.837377: xfs_ail_push_all <-xfs_log_worker
> kworker/0:0-2865 [000] .... 1229.837378: xfs_ail_push <-xfs_ail_push_all
> kworker/0:0-2865 [000] .... 1259.835355: xfs_ail_min_lsn <-xfs_log_need_covered
> kworker/0:0-2865 [000] .... 1259.835360: xfs_ail_push_all <-xfs_log_worker
> kworker/0:0-2865 [000] .... 1259.835360: xfs_ail_push <-xfs_ail_push_all
> kworker/0:0-2865 [000] .... 1289.834315: xfs_ail_min_lsn <-xfs_log_need_covered
> kworker/0:0-2865 [000] .... 1289.834320: xfs_ail_push_all <-xfs_log_worker
> kworker/0:0-2865 [000] .... 1289.834321: xfs_ail_push <-xfs_ail_push_all
> kworker/0:0-2865 [000] .... 1319.831564: xfs_ail_min_lsn <-xfs_log_need_covered
> kworker/0:0-2865 [000] .... 1319.831569: xfs_ail_push_all <-xfs_log_worker
> kworker/0:0-2865 [000] .... 1319.831570: xfs_ail_push <-xfs_ail_push_all
>
> The first two xfs_unmountfs in the above log worked fine, no hang.
> The third one hung.
Well, I guess I should been more specific. ftrace is pretty much
useless here - we need the information taht is recorded by the
events, not the timing of the events.
# trace-cmd record -e xfs_ail*
....
^C
....
# trace-cmd report
version = 6
cpus=1
kworker/0:1H-1269 [000] 104529.901271: xfs_ail_insert: dev 253:16 lip 0x0xffff880017a4b740 old lsn 0/0 new lsn 1/20 type XFS_LI_BUF flags IN_AIL
kworker/0:1H-1269 [000] 104529.901273: xfs_ail_insert: dev 253:16 lip 0x0xffff880017a4bbc8 old lsn 0/0 new lsn 1/20 type XFS_LI_BUF flags IN_AIL
kworker/0:1H-1269 [000] 104529.901273: xfs_ail_insert: dev 253:16 lip 0x0xffff88001b6f8098 old lsn 0/0 new lsn 1/20 type XFS_LI_INODE flags IN_AIL
kworker/0:1H-1269 [000] 104529.901274: xfs_ail_insert: dev 253:16 lip 0x0xffff880027600c80 old lsn 0/0 new lsn 1/20 type XFS_LI_EFI flags IN_AIL
kworker/0:1H-1269 [000] 104529.901274: xfs_ail_insert: dev 253:16 lip 0x0xffff88001b6f81c8 old lsn 0/0 new lsn 1/20 type XFS_LI_INODE flags IN_AIL
kworker/0:1H-1269 [000] 104529.901274: xfs_ail_insert: dev 253:16 lip 0x0xffff88001b6f8130 old lsn 0/0 new lsn 1/20 type XFS_LI_INODE flags IN_AIL
kworker/0:1H-1269 [000] 104529.901274: xfs_ail_insert: dev 253:16 lip 0x0xffff880017a4b488 old lsn 0/0 new lsn 1/20 type XFS_LI_BUF flags IN_AIL
kworker/0:1H-1269 [000] 104529.901275: xfs_ail_insert: dev 253:16 lip 0x0xffff880017a4bcb0 old lsn 0/0 new lsn 1/20 type XFS_LI_BUF flags IN_AIL
kworker/0:1H-1269 [000] 104529.901275: xfs_ail_insert: dev 253:16 lip 0x0xffff880017a4b910 old lsn 0/0 new lsn 1/20 type XFS_LI_BUF flags IN_AIL
kworker/0:1H-1269 [000] 104529.901275: xfs_ail_insert: dev 253:16 lip 0x0xffff88001b6f8000 old lsn 0/0 new lsn 1/20 type XFS_LI_INODE flags IN_AIL
kworker/0:1H-1269 [000] 104529.901277: xfs_ail_delete: dev 253:16 lip 0x0xffff880027600c80 old lsn 1/20 new lsn 1/20 type XFS_LI_EFI flags IN_AIL
xfsaild/vdb-14828 [000] 104529.901338: xfs_ail_push: dev 253:16 lip 0x0xffff88001b6f8000 lsn 1/20 type XFS_LI_INODE flags IN_AIL
xfsaild/vdb-14828 [000] 104529.901339: xfs_ail_push: dev 253:16 lip 0x0xffff880017a4b910 lsn 1/20 type XFS_LI_BUF flags IN_AIL
xfsaild/vdb-14828 [000] 104529.901339: xfs_ail_push: dev 253:16 lip 0x0xffff880017a4bcb0 lsn 1/20 type XFS_LI_BUF flags IN_AIL
xfsaild/vdb-14828 [000] 104529.901340: xfs_ail_push: dev 253:16 lip 0x0xffff880017a4b488 lsn 1/20 type XFS_LI_BUF flags IN_AIL
.....
> [ 240.930278] xfsaild/sdb D ffffffff8180fe40 0 5640 2 0x00000000
> [ 240.931408] ffff88003cd5dc58 0000000000000046 ffff88003cd5dc68 ffffffff81069029
> [ 240.933116] ffff88003cdc8000 0000000000013180 ffff88003cd5dfd8 0000000000013180
> [ 240.934655] ffff88003daa1900 ffff88003cdc8000 ffff88003cd5dc28 0000000000000011
> [ 240.936328] Call Trace:
> [ 240.936862] [<ffffffff81069029>] ? flush_work+0x139/0x1e0
> [ 240.937755] [<ffffffff816c54d9>] schedule+0x29/0x70
> [ 240.938532] [<ffffffffa04be2b2>] xlog_cil_force_lsn+0x192/0x200 [xfs]
> [ 240.939452] [<ffffffff81081000>] ? try_to_wake_up+0x2b0/0x2b0
> [ 240.940366] [<ffffffffa04bc4ad>] _xfs_log_force+0x6d/0x2b0 [xfs]
> [ 240.941302] [<ffffffffa04bc729>] xfs_log_force+0x39/0xc0 [xfs]
> [ 240.942174] [<ffffffffa04c1567>] xfsaild+0x137/0x6e0 [xfs]
> [ 240.943008] [<ffffffffa04c1430>] ? xfs_trans_ail_cursor_first+0xa0/0xa0 [xfs]
> [ 240.944240] [<ffffffff81071ae9>] kthread+0xc9/0xe0
> [ 240.945001] [<ffffffff81071a20>] ? flush_kthread_worker+0xb0/0xb0
> [ 240.945884] [<ffffffff816d14ec>] ret_from_fork+0x7c/0xb0
> [ 240.946696] [<ffffffff81071a20>] ? flush_kthread_worker+0xb0/0xb0
Try the patch here:
http://oss.sgi.com/pipermail/xfs/2014-April/035870.html
Needs a minor fix to compile as noted here:
http://oss.sgi.com/pipermail/xfs/2014-April/035878.html
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
[not found] ` <CALjwKZDeTcOSJDtRcNa3KtLraPKvWUB0jvQrwSANxB0RHds0Rg@mail.gmail.com>
@ 2014-05-03 0:05 ` Dave Chinner
2014-05-03 0:47 ` Bob Mastors
0 siblings, 1 reply; 8+ messages in thread
From: Dave Chinner @ 2014-05-03 0:05 UTC (permalink / raw)
To: Bob Mastors; +Cc: xfs
On Fri, May 02, 2014 at 11:32:19AM -0600, Bob Mastors wrote:
> On Tue, Apr 29, 2014 at 9:22 PM, Dave Chinner <david@fromorbit.com> wrote:
> > Well, I guess I should been more specific. ftrace is pretty much
> > useless here - we need the information taht is recorded by the
> > events, not the timing of the events.
> >
> Heh, I have been trying to bluff my way through this.
> I have hacked on file systems but am new to linux and xfs.
I wouldn't have guessed that. Most of the time the response is
"trace events? what are they?". :)
> Output file attached but it all looks like this:
>
> xfsaild/sdb-3613 [001] 445.757616: xfs_ail_flushing: dev 8:16
> lip 0x0xffff88001d3017b8 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> xfsaild/sdb-3613 [001] 445.757617: xfs_ail_flushing: dev 8:16
> lip 0x0xffff88001d301850 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> xfsaild/sdb-3613 [001] 445.757618: xfs_ail_flushing: dev 8:16
> lip 0x0xffff88001de63ed8 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> xfsaild/sdb-3613 [001] 445.757618: xfs_ail_flushing: dev 8:16
> lip 0x0xffff88001cd24720 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> xfsaild/sdb-3613 [001] 445.757618: xfs_ail_flushing: dev 8:16
> lip 0x0xffff88001cd248e8 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> xfsaild/sdb-3613 [001] 445.757619: xfs_ail_flushing: dev 8:16
> lip 0x0xffff88002c435ab0 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
That's very enlightening - a bunch of inodes returning
XFS_ITEM_FLUSHING from attempts to push them.
> The addresses repeat.
> I started the record as soon as I noticed the umount hanging, probably
> within 20 seconds or so.
> Also attached is the console output.
>
> This was done with your patch applied.
>
> Seems like xfsaild_push is missing a check that the file system is
> XFS_FORCED_SHUTDOWN.
It might look that way, but what is supposed to happen is that
everything else is supposed to handle shutdown situations and empty
the AIL. i.e. the act of issuing IO by the AIL is supposed to
trigger shutdown processing on the objects, and so having the AIL
shut down itself won't help.
So, what's the problem? Well, the inodes have been flushed,
triggering the inode buffer to be written. However, then inode
buffer has had an IO error (i.e. the async write error), is retried,
and then we stop retrying the IO. The idea is that the AIL will push
it again soon and the IO will be retried.
What is happening is that the inodes in the buffer are already
marked as "being flushed" and hence the AIL does not push the inode
buffer again, and hence the IO completion callbacks on the buffer
that will remove the inodes from the AIL are never called. Not sure
how to fix this one yet....
> Let me know if there is any other info I can capture that would be
> interesting.
I know what the problem is now, so testing a fix will be the next
step. But I need to think about how to fix this, and that can wait
till Monday. ;)
Thanks for following up with the trace information, Bob!
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs umount hang in xfs_ail_push_all_sync on i/o error
2014-05-03 0:05 ` Dave Chinner
@ 2014-05-03 0:47 ` Bob Mastors
0 siblings, 0 replies; 8+ messages in thread
From: Bob Mastors @ 2014-05-03 0:47 UTC (permalink / raw)
To: Dave Chinner; +Cc: xfs
[-- Attachment #1.1: Type: text/plain, Size: 3535 bytes --]
On Fri, May 2, 2014 at 6:05 PM, Dave Chinner <david@fromorbit.com> wrote:
> On Fri, May 02, 2014 at 11:32:19AM -0600, Bob Mastors wrote:
> > On Tue, Apr 29, 2014 at 9:22 PM, Dave Chinner <david@fromorbit.com>
> wrote:
> > > Well, I guess I should been more specific. ftrace is pretty much
> > > useless here - we need the information taht is recorded by the
> > > events, not the timing of the events.
> > >
> > Heh, I have been trying to bluff my way through this.
> > I have hacked on file systems but am new to linux and xfs.
>
> I wouldn't have guessed that. Most of the time the response is
> "trace events? what are they?". :)
>
> > Output file attached but it all looks like this:
> >
> > xfsaild/sdb-3613 [001] 445.757616: xfs_ail_flushing: dev 8:16
> > lip 0x0xffff88001d3017b8 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> > xfsaild/sdb-3613 [001] 445.757617: xfs_ail_flushing: dev 8:16
> > lip 0x0xffff88001d301850 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> > xfsaild/sdb-3613 [001] 445.757618: xfs_ail_flushing: dev 8:16
> > lip 0x0xffff88001de63ed8 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> > xfsaild/sdb-3613 [001] 445.757618: xfs_ail_flushing: dev 8:16
> > lip 0x0xffff88001cd24720 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> > xfsaild/sdb-3613 [001] 445.757618: xfs_ail_flushing: dev 8:16
> > lip 0x0xffff88001cd248e8 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
> > xfsaild/sdb-3613 [001] 445.757619: xfs_ail_flushing: dev 8:16
> > lip 0x0xffff88002c435ab0 lsn 32/3573 type XFS_LI_INODE flags IN_AIL
>
> That's very enlightening - a bunch of inodes returning
> XFS_ITEM_FLUSHING from attempts to push them.
>
> > The addresses repeat.
> > I started the record as soon as I noticed the umount hanging, probably
> > within 20 seconds or so.
> > Also attached is the console output.
> >
> > This was done with your patch applied.
> >
> > Seems like xfsaild_push is missing a check that the file system is
> > XFS_FORCED_SHUTDOWN.
>
> It might look that way, but what is supposed to happen is that
> everything else is supposed to handle shutdown situations and empty
> the AIL. i.e. the act of issuing IO by the AIL is supposed to
> trigger shutdown processing on the objects, and so having the AIL
> shut down itself won't help.
>
> So, what's the problem? Well, the inodes have been flushed,
> triggering the inode buffer to be written. However, then inode
> buffer has had an IO error (i.e. the async write error), is retried,
> and then we stop retrying the IO. The idea is that the AIL will push
> it again soon and the IO will be retried.
>
> What is happening is that the inodes in the buffer are already
> marked as "being flushed" and hence the AIL does not push the inode
> buffer again, and hence the IO completion callbacks on the buffer
> that will remove the inodes from the AIL are never called. Not sure
> how to fix this one yet....
>
Thanks for the explanation.
It clears up some questions I had.
>
> > Let me know if there is any other info I can capture that would be
> > interesting.
>
> I know what the problem is now, so testing a fix will be the next
> step. But I need to think about how to fix this, and that can wait
> till Monday. ;)
>
Just an fyi next week is busy for me with some other stuff so I
won't be able to try out a fix until the following week.
>
> Thanks for following up with the trace information, Bob!
>
Not a problem.
Thanks,
Bob
>
> Cheers,
>
> Dave.
> --
> Dave Chinner
> david@fromorbit.com
>
[-- Attachment #1.2: Type: text/html, Size: 5016 bytes --]
[-- Attachment #2: Type: text/plain, Size: 121 bytes --]
_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2014-05-03 0:47 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2014-04-28 22:29 xfs umount hang in xfs_ail_push_all_sync on i/o error Bob Mastors
2014-04-28 23:45 ` Dave Chinner
2014-04-28 23:51 ` Bob Mastors
2014-04-29 1:01 ` Dave Chinner
2014-04-29 1:11 ` Bob Mastors
[not found] ` <CALjwKZBj0f_y7MPp-PLqhLDOnfmf2OWsvv_vbnX08ubevqM+Bg@mail.gmail.com>
2014-04-30 3:22 ` Dave Chinner
[not found] ` <CALjwKZDeTcOSJDtRcNa3KtLraPKvWUB0jvQrwSANxB0RHds0Rg@mail.gmail.com>
2014-05-03 0:05 ` Dave Chinner
2014-05-03 0:47 ` Bob Mastors
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox