Upgrading to Ubuntu 16 and a Mediasonic ProBox HDL-SU3
April 24, 2016
See Ubuntu 16 and a Mediasonic ProBox HDL-SU3 for how I ultimately fixed the problem.
I decided to take the abnormal plunge and install Ubuntu 16.04 a day after it was released. The install went well and I got everything re-installed and setup. I typically do a fresh install to my OS dedicated SSD, where /home and other user data paths are located on separate physical drives.
All went well until I started trying to use my Mediasonic ProBox HDL-SU3 external USB 3.0 hard drive enclosure. It mounts fine, and I could do basic I/O without issue, but I was able to reproduce a pretty severe problem several times by just extracting a large tar.gz file on the drive. It eventually would hang and the whole rest of the system becomes unstable.
I know it's not the hardware (at least not fatally) because this worked fine in Ubuntu 12/14. Ubuntu 16.04 ships with their 4.4.0-21-generic kernel image and presents the following error.
[ 372.097782] sd 8:0:0:0: [sdc] tag#14 uas_eh_abort_handler 0 uas-tag 15 inflight: CMD OUT [ 372.097799] sd 8:0:0:0: [sdc] tag#14 CDB: Write(16) 8a 00 00 00 00 00 e8 c4 41 68 00 00 01 00 00 00 [ 372.098059] sd 8:0:0:0: [sdc] tag#20 uas_eh_abort_handler 0 uas-tag 21 inflight: CMD OUT [ 372.098074] sd 8:0:0:0: [sdc] tag#20 CDB: Write(16) 8a 00 00 00 00 01 48 42 bc 20 00 00 00 70 00 00 [ 372.098273] sd 8:0:0:0: [sdc] tag#2 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD OUT [ 372.098281] sd 8:0:0:0: [sdc] tag#2 CDB: Write(16) 8a 00 00 00 00 01 48 42 b8 20 00 00 04 00 00 00 [ 372.098446] sd 8:0:0:0: [sdc] tag#24 uas_eh_abort_handler 0 uas-tag 25 inflight: CMD OUT [ 372.098462] sd 8:0:0:0: [sdc] tag#24 CDB: Write(16) 8a 00 00 00 00 01 48 42 b4 20 00 00 04 00 00 00 [ 372.098661] sd 8:0:0:0: [sdc] tag#1 uas_eh_abort_handler 0 uas-tag 23 inflight: CMD OUT [ 372.098669] sd 8:0:0:0: [sdc] tag#1 CDB: Write(16) 8a 00 00 00 00 01 48 42 b0 20 00 00 04 00 00 00 [ 372.098927] sd 8:0:0:0: [sdc] tag#22 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD OUT [ 372.098940] sd 8:0:0:0: [sdc] tag#22 CDB: Write(16) 8a 00 00 00 00 01 48 42 ac 20 00 00 04 00 00 00 [ 372.099152] sd 8:0:0:0: [sdc] tag#0 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD OUT [ 372.099165] sd 8:0:0:0: [sdc] tag#0 CDB: Write(16) 8a 00 00 00 00 01 48 42 a8 20 00 00 04 00 00 00 [ 372.099428] sd 8:0:0:0: [sdc] tag#26 uas_eh_abort_handler 0 uas-tag 27 inflight: CMD OUT [ 372.099440] sd 8:0:0:0: [sdc] tag#26 CDB: Write(16) 8a 00 00 00 00 01 48 41 7a b8 00 00 00 c0 00 00 [ 372.099649] sd 8:0:0:0: [sdc] tag#13 uas_eh_abort_handler 0 uas-tag 14 inflight: CMD OUT [ 372.099661] sd 8:0:0:0: [sdc] tag#13 CDB: Write(16) 8a 00 00 00 00 01 48 41 76 b8 00 00 04 00 00 00 [ 372.099928] sd 8:0:0:0: [sdc] tag#7 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD OUT [ 372.099941] sd 8:0:0:0: [sdc] tag#7 CDB: Write(16) 8a 00 00 00 00 01 48 41 72 b8 00 00 04 00 00 00 [ 372.100188] scsi host8: uas_eh_bus_reset_handler start [ 372.214824] usb 9-2: reset SuperSpeed USB device number 3 using xhci_hcd [ 372.237702] scsi host8: uas_eh_bus_reset_handler success [ 382.237567] sd 8:0:0:0: [sdc] tag#7 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD [ 382.237584] sd 8:0:0:0: [sdc] tag#7 CDB: Test Unit Ready 00 00 00 00 00 00 [ 382.237593] scsi host8: uas_eh_bus_reset_handler start [ 387.353496] xhci_hcd 0000:03:00.0: Command completion event does not match command [ 387.353516] xhci_hcd 0000:03:00.0: Timeout while waiting for setup device command [ 392.569390] xhci_hcd 0000:03:00.0: Timeout while waiting for setup device command [ 392.773321] usb 9-2: device not accepting address 3, error -62 [ 393.293820] scsi host8: uas_post_reset: alloc streams error -19 after reset [ 393.293829] usb 9-2: USB disconnect, device number 3 [ 480.431582] INFO: task kworker/u12:5:177 blocked for more than 120 seconds. [ 480.431595] Tainted: G OE 4.4.0-21-generic #37-Ubuntu [ 480.431599] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 480.431605] kworker/u12:5 D ffff8805fcc67508 0 177 2 0x00000000 [ 480.431624] Workqueue: writeback wb_workfn (flush-8:32) [ 480.431631] ffff8805fcc67508 ffffffff810b7fd2 ffff880603f30c80 ffff8805fdbaf080 [ 480.431638] ffff8805fcc68000 ffff88061fc96d00 7fffffffffffffff ffffffff81820bf0 [ 480.431644] ffff8805fcc67660 ffff8805fcc67520 ffffffff818203f5 0000000000000000 [ 480.431651] Call Trace: [ 480.431663] [<ffffffff810b7fd2>] ? enqueue_entity+0x3a2/0xc70 [ 480.431673] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.431680] [<ffffffff818203f5>] schedule+0x35/0x80 [ 480.431687] [<ffffffff81823515>] schedule_timeout+0x1b5/0x270 [ 480.431693] [<ffffffff810b5063>] ? check_preempt_wakeup+0x193/0x220 [ 480.431701] [<ffffffff810f56dc>] ? ktime_get+0x3c/0xb0 [ 480.431707] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.431713] [<ffffffff8181f944>] io_schedule_timeout+0xa4/0x110 [ 480.431719] [<ffffffff81820c0b>] bit_wait_io+0x1b/0x70 [ 480.431725] [<ffffffff8182079d>] __wait_on_bit+0x5d/0x90 [ 480.431731] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.431737] [<ffffffff81820852>] out_of_line_wait_on_bit+0x82/0xb0 [ 480.431745] [<ffffffff810c3a50>] ? autoremove_wake_function+0x40/0x40 [ 480.431753] [<ffffffff812e86c5>] do_get_write_access+0x245/0x490 [ 480.431760] [<ffffffff81243b9a>] ? __find_get_block+0xaa/0x110 [ 480.431765] [<ffffffff81243ecb>] ? __getblk_gfp+0x2b/0x60 [ 480.431772] [<ffffffff812e8961>] jbd2_journal_get_write_access+0x51/0x70 [ 480.431779] [<ffffffff812cbaeb>] __ext4_journal_get_write_access+0x3b/0x80 [ 480.431786] [<ffffffff812d2c2b>] ext4_mb_mark_diskspace_used+0x7b/0x4a0 [ 480.431794] [<ffffffff812d43ce>] ext4_mb_new_blocks+0x33e/0x580 [ 480.431799] [<ffffffff812c3fc9>] ? ext4_find_extent+0x1b9/0x320 [ 480.431807] [<ffffffff810ec484>] ? lock_timer_base.isra.22+0x54/0x70 [ 480.431814] [<ffffffff812c8f68>] ext4_ext_map_blocks+0x7c8/0xec0 [ 480.431822] [<ffffffff8118d2c9>] ? find_get_pages_tag+0x109/0x190 [ 480.431830] [<ffffffff81298bda>] ext4_map_blocks+0x18a/0x4a0 [ 480.431837] [<ffffffff8129c012>] ext4_writepages+0x5e2/0xd50 [ 480.431844] [<ffffffff810ec484>] ? lock_timer_base.isra.22+0x54/0x70 [ 480.431851] [<ffffffff810ec608>] ? del_timer_sync+0x48/0x50 [ 480.431858] [<ffffffff81823491>] ? schedule_timeout+0x131/0x270 [ 480.431867] [<ffffffff8119b7fe>] do_writepages+0x1e/0x30 [ 480.431873] [<ffffffff8123b055>] __writeback_single_inode+0x45/0x330 [ 480.431880] [<ffffffff8123b852>] writeback_sb_inodes+0x262/0x590 [ 480.431887] [<ffffffff8123bc0c>] __writeback_inodes_wb+0x8c/0xc0 [ 480.431894] [<ffffffff8123bf63>] wb_writeback+0x253/0x310 [ 480.431902] [<ffffffff81228af1>] ? get_nr_dirty_inodes+0x51/0x80 [ 480.431908] [<ffffffff8123c87a>] wb_workfn+0x2ea/0x400 [ 480.431916] [<ffffffff81099ff2>] process_one_work+0x162/0x480 [ 480.431923] [<ffffffff8109a35b>] worker_thread+0x4b/0x4c0 [ 480.431929] [<ffffffff8109a310>] ? process_one_work+0x480/0x480 [ 480.431935] [<ffffffff8109a310>] ? process_one_work+0x480/0x480 [ 480.431941] [<ffffffff810a0528>] kthread+0xd8/0xf0 [ 480.431947] [<ffffffff810a0450>] ? kthread_create_on_node+0x1e0/0x1e0 [ 480.431955] [<ffffffff8182488f>] ret_from_fork+0x3f/0x70 [ 480.431960] [<ffffffff810a0450>] ? kthread_create_on_node+0x1e0/0x1e0 [ 480.432048] INFO: task jbd2/sdc1-8:2238 blocked for more than 120 seconds. [ 480.432054] Tainted: G OE 4.4.0-21-generic #37-Ubuntu [ 480.432057] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 480.432061] jbd2/sdc1-8 D ffff8805dd3b3ad8 0 2238 2 0x00000000 [ 480.432068] ffff8805dd3b3ad8 ffff8800da96e400 ffff880603f31900 ffff8800da96e400 [ 480.432075] ffff8805dd3b4000 ffff88061fcd6d00 7fffffffffffffff ffffffff81820bf0 [ 480.432081] ffff8805dd3b3c30 ffff8805dd3b3af0 ffffffff818203f5 0000000000000000 [ 480.432087] Call Trace: [ 480.432093] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.432099] [<ffffffff818203f5>] schedule+0x35/0x80 [ 480.432106] [<ffffffff81823515>] schedule_timeout+0x1b5/0x270 [ 480.432113] [<ffffffff813bab6a>] ? bio_attempt_back_merge+0x8a/0x100 [ 480.432120] [<ffffffff810f56dc>] ? ktime_get+0x3c/0xb0 [ 480.432126] [<ffffffff810f56dc>] ? ktime_get+0x3c/0xb0 [ 480.432132] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.432138] [<ffffffff8181f944>] io_schedule_timeout+0xa4/0x110 [ 480.432144] [<ffffffff81820c0b>] bit_wait_io+0x1b/0x70 [ 480.432150] [<ffffffff8182079d>] __wait_on_bit+0x5d/0x90 [ 480.432156] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.432162] [<ffffffff81820852>] out_of_line_wait_on_bit+0x82/0xb0 [ 480.432169] [<ffffffff810c3a50>] ? autoremove_wake_function+0x40/0x40 [ 480.432175] [<ffffffff81243aa2>] __wait_on_buffer+0x32/0x40 [ 480.432182] [<ffffffff812eabe8>] jbd2_journal_commit_transaction+0xf48/0x1870 [ 480.432191] [<ffffffff810ec58e>] ? try_to_del_timer_sync+0x5e/0x90 [ 480.432198] [<ffffffff812ef12a>] kjournald2+0xca/0x250 [ 480.432205] [<ffffffff810c3a10>] ? wake_atomic_t_function+0x60/0x60 [ 480.432211] [<ffffffff812ef060>] ? commit_timeout+0x10/0x10 [ 480.432217] [<ffffffff810a0528>] kthread+0xd8/0xf0 [ 480.432223] [<ffffffff810a0450>] ? kthread_create_on_node+0x1e0/0x1e0 [ 480.432230] [<ffffffff8182488f>] ret_from_fork+0x3f/0x70 [ 480.432235] [<ffffffff810a0450>] ? kthread_create_on_node+0x1e0/0x1e0 [ 480.432260] INFO: task tar:2536 blocked for more than 120 seconds. [ 480.432265] Tainted: G OE 4.4.0-21-generic #37-Ubuntu [ 480.432268] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 480.432271] tar D ffff8805c58278f8 0 2536 2502 0x00000004 [ 480.432278] ffff8805c58278f8 0000000000000002 ffff880603f32580 ffff8805dbb85780 [ 480.432284] ffff8805c5828000 ffff88061fd16d00 7fffffffffffffff ffffffff81820bf0 [ 480.432290] ffff8805c5827a58 ffff8805c5827910 ffffffff818203f5 0000000000000000 [ 480.432296] Call Trace: [ 480.432302] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.432308] [<ffffffff818203f5>] schedule+0x35/0x80 [ 480.432314] [<ffffffff81823515>] schedule_timeout+0x1b5/0x270 [ 480.432321] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.432327] [<ffffffff8181f944>] io_schedule_timeout+0xa4/0x110 [ 480.432333] [<ffffffff81820c0b>] bit_wait_io+0x1b/0x70 [ 480.432339] [<ffffffff8182079d>] __wait_on_bit+0x5d/0x90 [ 480.432345] [<ffffffff81820bf0>] ? bit_wait+0x60/0x60 [ 480.432351] [<ffffffff81820852>] out_of_line_wait_on_bit+0x82/0xb0 [ 480.432358] [<ffffffff810c3a50>] ? autoremove_wake_function+0x40/0x40 [ 480.432364] [<ffffffff812e86c5>] do_get_write_access+0x245/0x490 [ 480.432370] [<ffffffff81243ecb>] ? __getblk_gfp+0x2b/0x60 [ 480.432377] [<ffffffff812e8961>] jbd2_journal_get_write_access+0x51/0x70 [ 480.432383] [<ffffffff812cbaeb>] __ext4_journal_get_write_access+0x3b/0x80 [ 480.432390] [<ffffffff8129b7e5>] ext4_reserve_inode_write+0x75/0xa0 [ 480.432396] [<ffffffff8129f048>] ? ext4_dirty_inode+0x48/0x70 [ 480.432402] [<ffffffff8129b863>] ext4_mark_inode_dirty+0x53/0x220 [ 480.432409] [<ffffffff8129f048>] ext4_dirty_inode+0x48/0x70 [ 480.432415] [<ffffffff8123ae09>] __mark_inode_dirty+0x179/0x380 [ 480.432422] [<ffffffff812275a9>] generic_update_time+0x79/0xd0 [ 480.432429] [<ffffffff8122773d>] file_update_time+0xbd/0x110 [ 480.432435] [<ffffffff8118f27d>] __generic_file_write_iter+0x9d/0x1e0 [ 480.432441] [<ffffffff81291ffc>] ext4_file_write_iter+0xfc/0x460 [ 480.432449] [<ffffffff8120ed71>] ? __sb_end_write+0x21/0x30 [ 480.432456] [<ffffffff812291de>] ? touch_atime+0xbe/0xd0 [ 480.432463] [<ffffffff812154af>] ? pipe_read+0x28f/0x350 [ 480.432471] [<ffffffff8120bedb>] new_sync_write+0x9b/0xe0 [ 480.432477] [<ffffffff8120bf46>] __vfs_write+0x26/0x40 [ 480.432483] [<ffffffff8120c8c9>] vfs_write+0xa9/0x1a0 [ 480.432490] [<ffffffff8120c804>] ? vfs_read+0x114/0x130 [ 480.432496] [<ffffffff8120d585>] SyS_write+0x55/0xc0 [ 480.432504] [<ffffffff818244f2>] entry_SYSCALL_64_fastpath+0x16/0x71
Knowing that such an obvious error has to have been seen before, I jumped ship to a 4.5 upstream kernel and walla, problem fixed.