From mboxrd@z Thu Jan 1 00:00:00 1970 From: TomK Subject: Re: Kernel 4.8.4: INFO: task kworker/u16:8:289 blocked for more than 120 seconds. Date: Fri, 28 Oct 2016 02:01:16 -0400 Message-ID: References: <0f72bb4a-3cdf-ffd0-db75-5c8b303b921c@mdevsys.com> <64ef386e-8de2-0b1c-9322-f02530a3e783@mdevsys.com> <0851dba9-ad6c-c419-dc92-93c5d7d2f54a@mdevsys.com> <1477291017.19735.26.camel@haakon3.risingtidesystems.com> <58bfd43f-ff17-f724-9adf-ffd1f828a0e9@mdevsys.com> <1477466446.19735.113.camel@haakon3.risingtidesystems.com> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Return-path: Received: from mout.perfora.net ([74.208.4.197]:56126 "EHLO mout.perfora.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756077AbcJ1GBh (ORCPT ); Fri, 28 Oct 2016 02:01:37 -0400 In-Reply-To: Sender: linux-scsi-owner@vger.kernel.org List-Id: linux-scsi@vger.kernel.org To: "Nicholas A. Bellinger" Cc: linux-scsi@vger.kernel.org, Himanshu Madhani , Quinn Tran , Giridhar Malavali , "Gurumurthy, Anil" On 10/26/2016 8:08 AM, TomK wrote: > On 10/26/2016 3:20 AM, Nicholas A. Bellinger wrote: >> Hello TomK & Co, >> >> Comments below. >> >> On Tue, 2016-10-25 at 22:05 -0400, TomK wrote: >>> On 10/25/2016 1:28 AM, TomK wrote: >>>> On 10/24/2016 2:36 AM, Nicholas A. Bellinger wrote: >>>>> Hi TomK, >>>>> >>>>> Thanks for reporting this bug. Comments inline below. >>>>> >>>>> On Mon, 2016-10-24 at 00:45 -0400, TomK wrote: >>>>>> On 10/24/2016 12:32 AM, TomK wrote: >>>>>>> On 10/23/2016 10:03 PM, TomK wrote: >> >> >> >>>>>>> Including the full log: >>>>>>> >>>>>>> http://microdevsys.com/linux-lio/messages-mailing-list >>>>>>> >>>>>> >>>>> >>>>> Thanks for posting with qla2xxx verbose debug enabled on your setup. >>>>> >>>>>> >>>>>> When tryint to shut down target using /etc/init.d/target stop, the >>>>>> following is printed repeatedly: >>>>>> >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e837:20: >>>>>> ABTS_RECV_24XX: instance 0 >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f811:20: >>>>>> qla_target(0): task abort (s_id=1:5:0, tag=1177068, param=0) >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f812:20: >>>>>> qla_target(0): task abort for non-existant session >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f80e:20: >>>>>> Scheduling work (type 1, prm ffff880093365680) to find session for >>>>>> param >>>>>> ffff88010f8c7680 (size 64, tgt ffff880111f06600) >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f800:20: Sess >>>>>> work (tgt ffff880111f06600) >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e806:20: >>>>>> Sending >>>>>> task mgmt ABTS response (ha=ffff88010fae0000, atio=ffff880093365694, >>>>>> status=4 >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e838:20: >>>>>> ABTS_RESP_24XX: compl_status 31 >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e807:20: >>>>>> Sending >>>>>> retry TERM EXCH CTIO7 (ha=ffff88010fae0000) >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e806:20: >>>>>> Sending >>>>>> task mgmt ABTS response (ha=ffff88010fae0000, atio=ffff88010f8c76c0, >>>>>> status=0 >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e838:20: >>>>>> ABTS_RESP_24XX: compl_status 0 >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e872:20: >>>>>> qlt_24xx_atio_pkt_all_vps: qla_target(0): type 6 ox_id 029c >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-3861:20: New >>>>>> command while device ffff880111f06600 is shutting down >>>>>> Oct 24 00:39:48 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e859:20: >>>>>> qla_target: Unable to send command to target for req, ignoring. >>>>>> >>>>>> >>>>> >>>>> At your earliest convenience, please verify the patch using v4.8.y >>>>> with >>>>> the above ABORT_TASK + shutdown scenario. >>>>> >>>>> Also, it would be helpful to understand why this ESX FC host is >>>>> generating ABORT_TASKs. >>>>> >>>>> Eg: Is ABORT_TASK generated due to FC target response packet loss..? >>>>> Or due to target backend I/O latency, that ultimately triggers FC host >>>>> side timeouts...? >>>>> >> >> Ok, so the specific hung task warnings reported earlier above are >> ABORT_TASK due to the target-core backend md array holding onto >> outstanding I/O long enough, for ESX host side SCSI timeouts to begin to >> trigger. >> >>>>>> >>>>>> + when I disable the ports on the brocade switch that we're using >>>>>> then >>>>>> try to stop target, the following is printed: >>>>>> >>>>>> >>>>>> >>>>>> Oct 24 00:41:31 mbpc-pc kernel: qla2xxx [0000:04:00.1]-680a:21: Loop >>>>>> down - seconds remaining 231. >>>>>> Oct 24 00:41:32 mbpc-pc kernel: qla2xxx [0000:04:00.0]-680a:20: Loop >>>>>> down - seconds remaining 153. >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ------------[ cut here ]------------ >>>>>> Oct 24 00:41:32 mbpc-pc kernel: WARNING: CPU: 2 PID: 8615 at >>>>>> lib/list_debug.c:33 __list_add+0xbe/0xd0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: list_add corruption. prev->next >>>>>> should >>>>>> be next (ffff88009e83b330), but was ffff88011fc972a0. >>>>>> (prev=ffff880118ada4c0). >>>>>> Oct 24 00:41:32 mbpc-pc kernel: Modules linked in: tcm_qla2xxx tcm_fc >>>>>> tcm_loop target_core_file target_core_iblock target_core_pscsi >>>>>> target_core_mod configfs ip6table_filter ip6_tables ebtable_nat >>>>>> ebtables >>>>>> nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM >>>>>> iptable_mangle bridge nfsd lockd grace nfs_acl auth_rpcgss autofs4 >>>>>> it87 >>>>>> hwmon_vid bnx2fc cnic uio fcoe libfcoe libfc 8021q garp stp llc ppdev >>>>>> parport_pc parport sunrpc cpufreq_ondemand bonding ipv6 crc_ccitt >>>>>> ipt_REJECT nf_reject_ipv4 xt_multiport iptable_filter ip_tables fuse >>>>>> vfat fat xfs vhost_net macvtap macvlan vhost tun uinput raid456 >>>>>> async_raid6_recov async_pq async_xor xor async_memcpy async_tx >>>>>> raid6_pq >>>>>> libcrc32c joydev sg serio_raw e1000 kvm_amd kvm irqbypass r8169 mii >>>>>> pcspkr k10temp snd_hda_codec_realtek snd_hda_codec_generic >>>>>> snd_hda_intel >>>>>> snd_hda_codec snd_hda_core snd_hwdep snd_seq snd_seq_device snd_pcm >>>>>> snd_timer snd soundcore i2c_piix4 i2c_core wmi acpi_cpufreq shpchp >>>>>> ext4 >>>>>> mbcache jbd2 qla2xxx scsi_transport_fc floppy firewire_ohci f >>>>>> Oct 24 00:41:32 mbpc-pc kernel: irewire_core crc_itu_t sd_mod >>>>>> pata_acpi >>>>>> ata_generic pata_jmicron ahci libahci usb_storage dm_mirror >>>>>> dm_region_hash dm_log dm_mod >>>>>> Oct 24 00:41:32 mbpc-pc kernel: CPU: 2 PID: 8615 Comm: kworker/2:3 >>>>>> Not >>>>>> tainted 4.8.4 #2 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: Hardware name: Gigabyte Technology >>>>>> Co., >>>>>> Ltd. GA-890XA-UD3/GA-890XA-UD3, BIOS FC 08/02/2010 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: 0000000000000000 ffff880092b83b48 >>>>>> ffffffff812e88e9 ffffffff8130753e >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ffff880092b83ba8 ffff880092b83ba8 >>>>>> 0000000000000000 ffff880092b83b98 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ffffffff81066a7d ffff88000058f952 >>>>>> 0000002100000046 ffffffff8101eae8 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: Call Trace: >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> dump_stack+0x51/0x78 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __list_add+0xbe/0xd0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> __warn+0xfd/0x120 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __switch_to+0x398/0x7e0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> warn_slowpath_fmt+0x49/0x50 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> __list_add+0xbe/0xd0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> move_linked_works+0x62/0x90 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> process_one_work+0x25c/0x4e0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> schedule+0x40/0xb0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> worker_thread+0x16d/0x520 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __schedule+0x2fd/0x6a0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> default_wake_function+0x12/0x20 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __wake_up_common+0x56/0x90 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> maybe_create_worker+0x110/0x110 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> schedule+0x40/0xb0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> maybe_create_worker+0x110/0x110 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> kthread+0xcc/0xf0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> schedule_tail+0x1e/0xc0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> ret_from_fork+0x1f/0x40 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> kthread_freezable_should_stop+0x70/0x70 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ---[ end trace 713a9071c9f5f464 ]--- >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ------------[ cut here ]------------ >>>>>> Oct 24 00:41:32 mbpc-pc kernel: WARNING: CPU: 2 PID: 8615 at >>>>>> lib/list_debug.c:36 __list_add+0x9c/0xd0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: list_add double add: >>>>>> new=ffff880118ada4c0, prev=ffff880118ada4c0, next=ffff88009e83b330. >>>>>> Oct 24 00:41:32 mbpc-pc kernel: Modules linked in: tcm_qla2xxx tcm_fc >>>>>> tcm_loop target_core_file target_core_iblock target_core_pscsi >>>>>> target_core_mod configfs ip6table_filter ip6_tables ebtable_nat >>>>>> ebtables >>>>>> nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM >>>>>> iptable_mangle bridge nfsd lockd grace nfs_acl auth_rpcgss autofs4 >>>>>> it87 >>>>>> hwmon_vid bnx2fc cnic uio fcoe libfcoe libfc 8021q garp stp llc ppdev >>>>>> parport_pc parport sunrpc cpufreq_ondemand bonding ipv6 crc_ccitt >>>>>> ipt_REJECT nf_reject_ipv4 xt_multiport iptable_filter ip_tables fuse >>>>>> vfat fat xfs vhost_net macvtap macvlan vhost tun uinput raid456 >>>>>> async_raid6_recov async_pq async_xor xor async_memcpy async_tx >>>>>> raid6_pq >>>>>> libcrc32c joydev sg serio_raw e1000 kvm_amd kvm irqbypass r8169 mii >>>>>> pcspkr k10temp snd_hda_codec_realtek snd_hda_codec_generic >>>>>> snd_hda_intel >>>>>> snd_hda_codec snd_hda_core snd_hwdep snd_seq snd_seq_device snd_pcm >>>>>> snd_timer snd soundcore i2c_piix4 i2c_core wmi acpi_cpufreq shpchp >>>>>> ext4 >>>>>> mbcache jbd2 qla2xxx scsi_transport_fc floppy firewire_ohci f >>>>>> Oct 24 00:41:32 mbpc-pc kernel: irewire_core crc_itu_t sd_mod >>>>>> pata_acpi >>>>>> ata_generic pata_jmicron ahci libahci usb_storage dm_mirror >>>>>> dm_region_hash dm_log dm_mod >>>>>> Oct 24 00:41:32 mbpc-pc kernel: CPU: 2 PID: 8615 Comm: kworker/2:3 >>>>>> Tainted: G W 4.8.4 #2 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: Hardware name: Gigabyte Technology >>>>>> Co., >>>>>> Ltd. GA-890XA-UD3/GA-890XA-UD3, BIOS FC 08/02/2010 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: 0000000000000000 ffff880092b83b48 >>>>>> ffffffff812e88e9 ffffffff8130751c >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ffff880092b83ba8 ffff880092b83ba8 >>>>>> 0000000000000000 ffff880092b83b98 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ffffffff81066a7d ffff88000058f952 >>>>>> 0000002400000046 ffffffff8101eae8 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: Call Trace: >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> dump_stack+0x51/0x78 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __list_add+0x9c/0xd0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> __warn+0xfd/0x120 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __switch_to+0x398/0x7e0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> warn_slowpath_fmt+0x49/0x50 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> __list_add+0x9c/0xd0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> move_linked_works+0x62/0x90 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> process_one_work+0x25c/0x4e0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> schedule+0x40/0xb0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> worker_thread+0x16d/0x520 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __schedule+0x2fd/0x6a0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> default_wake_function+0x12/0x20 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> __wake_up_common+0x56/0x90 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> maybe_create_worker+0x110/0x110 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> schedule+0x40/0xb0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> maybe_create_worker+0x110/0x110 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> kthread+0xcc/0xf0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> schedule_tail+0x1e/0xc0 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] >>>>>> ret_from_fork+0x1f/0x40 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: [] ? >>>>>> kthread_freezable_should_stop+0x70/0x70 >>>>>> Oct 24 00:41:32 mbpc-pc kernel: ---[ end trace 713a9071c9f5f465 ]--- >>>>>> Oct 24 00:41:32 mbpc-pc kernel: qla2xxx [0000:04:00.1]-680a:21: Loop >>>>>> down - seconds remaining 230. >>>>>> Oct 24 00:41:33 mbpc-pc kernel: qla2xxx [0000:04:00.0]-680a:20: Loop >>>>>> down - seconds remaining 152. >>>>>> >>>>>> >>>>> >>>>> Mmmm. Could be a side effect of the target-core regression, but not >>>>> completely sure.. >>>>> >>>>> Adding QLOGIC folks CC'. >>>>> >>>>> -- >>>>> To unsubscribe from this list: send the line "unsubscribe >>>>> linux-scsi" in >>>>> the body of a message to majordomo@vger.kernel.org >>>>> More majordomo info at http://vger.kernel.org/majordomo-info.html >>>>> >> >> Adding Anil CC' >> >>>> >>>> Hey Nicholas, >>>> >>>> >>>>> At your earliest convenience, please verify the patch using v4.8.y >>>>> with >>>>> the above ABORT_TASK + shutdown scenario. >>>>> >>>>> Also, it would be helpful to understand why this ESX FC host is >>>>> generating ABORT_TASKs. >>>>> >>>>> Eg: Is ABORT_TASK generated due to FC target response packet loss..? >>>>> Or due to target backend I/O latency, that ultimately triggers FC host >>>>> side timeouts...? >>>> >>>> >>>> Here is where it gets interesting and to your thought above. Take for >>>> example this log snippet >>>> (http://microdevsys.com/linux-lio/messages-recent): >>>> >>>> Oct 23 22:12:51 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Jan 7 00:36:00 192.168.0.2 syslog: dhcpfwd : dhcp forwarder daemon >>>> successfully started >>>> Oct 23 22:14:14 mbpc-pc kernel: hpet1: lost 9599 rtc interrupts >>>> Oct 23 22:14:14 mbpc-pc kernel: hpet1: lost 1 rtc interrupts >>>> Oct 23 22:15:02 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Oct 23 22:15:41 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Jan 7 00:38:00 192.168.0.2 syslog: dhcpfwd : dhcp forwarder daemon >>>> successfully started >>>> Oct 23 22:16:29 mbpc-pc kernel: hpet1: lost 9599 rtc interrupts >>>> Oct 23 22:17:30 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Jan 7 00:40:00 192.168.0.2 syslog: dhcpfwd : dhcp forwarder daemon >>>> successfully started >>>> Oct 23 22:18:29 mbpc-pc kernel: ABORT_TASK: Found referenced qla2xxx >>>> task_tag: 1195032 >>>> Oct 23 22:18:33 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Oct 23 22:18:42 mbpc-pc kernel: ABORT_TASK: Sending >>>> TMR_FUNCTION_COMPLETE for ref_tag: 1195032 >>>> Oct 23 22:18:42 mbpc-pc kernel: ABORT_TASK: Found referenced qla2xxx >>>> task_tag: 1122276 >>>> Oct 23 22:19:35 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Jan 7 00:42:00 192.168.0.2 syslog: dhcpfwd : dhcp forwarder daemon >>>> successfully started >>>> Oct 23 22:20:41 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Oct 23 22:21:07 mbpc-pc kernel: INFO: task kworker/u16:8:308 blocked >>>> for >>>> more than 120 seconds. >>>> Oct 23 22:21:07 mbpc-pc kernel: Not tainted 4.8.4 #2 >>>> Oct 23 22:21:07 mbpc-pc kernel: "echo 0 > >>>> /proc/sys/kernel/hung_task_timeout_secs" disables this message. >>>> Oct 23 22:21:07 mbpc-pc kernel: kworker/u16:8 D >>>> ffff880111b8fa18 0 >>>> 308 2 0x00000000 >>>> Oct 23 22:21:07 mbpc-pc kernel: Workqueue: tmr-fileio target_tmr_work >>>> [target_core_mod] >>>> Oct 23 22:21:07 mbpc-pc kernel: ffff880111b8fa18 0000000000000400 >>>> ffff880112180480 ffff880111b8f998 >>>> Oct 23 22:21:07 mbpc-pc kernel: ffff88011107a380 ffffffff81f99ca0 >>>> ffffffff81f998ef ffff880100000000 >>>> Oct 23 22:21:07 mbpc-pc kernel: ffffffff812f27d9 0000000000000000 >>>> ffffe8ffffcda000 ffff880000000000 >>>> Oct 23 22:21:07 mbpc-pc kernel: Call Trace: >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> number+0x2e9/0x310 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] schedule+0x40/0xb0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> start_flush_work+0x49/0x180 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> schedule_timeout+0x9c/0xe0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> flush_work+0x1a/0x40 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> console_unlock+0x35c/0x380 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> wait_for_completion+0xc0/0xf0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> try_to_wake_up+0x260/0x260 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> __transport_wait_for_tasks+0xb4/0x1b0 [target_core_mod] >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> vprintk_default+0x1f/0x30 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? printk+0x46/0x48 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> transport_wait_for_tasks+0x44/0x60 [target_core_mod] >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> core_tmr_abort_task+0xf2/0x160 [target_core_mod] >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> target_tmr_work+0x154/0x160 [target_core_mod] >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> process_one_work+0x189/0x4e0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> del_timer_sync+0x4c/0x60 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> maybe_create_worker+0x8e/0x110 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> schedule+0x40/0xb0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> worker_thread+0x16d/0x520 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> default_wake_function+0x12/0x20 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> __wake_up_common+0x56/0x90 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> maybe_create_worker+0x110/0x110 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> schedule+0x40/0xb0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> maybe_create_worker+0x110/0x110 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] kthread+0xcc/0xf0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> schedule_tail+0x1e/0xc0 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] >>>> ret_from_fork+0x1f/0x40 >>>> Oct 23 22:21:07 mbpc-pc kernel: [] ? >>>> kthread_freezable_should_stop+0x70/0x70 >>>> Oct 23 22:21:52 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> Jan 7 00:44:00 192.168.0.2 syslog: dhcpfwd : dhcp forwarder daemon >>>> successfully started >>>> Oct 23 22:23:03 mbpc-pc kernel: hpet1: lost 9600 rtc interrupts >>>> >>>> >>>> And compare it to the following snippet >>>> (http://microdevsys.com/linux-lio/iostat-tkx-interesting-bit.txt) taken >>>> from this bigger iostat session >>>> (http://microdevsys.com/linux-lio/iostat-tkx.txt): >>>> >> >> >> >>>> >>>> >>>> We can see that /dev/sdf ramps up to 100% starting at around >>>> (10/23/2016 >>>> 10:18:18 PM) and stays that way till about the (10/23/2016 10:18:42 PM) >>>> mark when something occurs and it drops down to below 100% numbers. >>>> >>>> So I checked the array which shows all clean, even across reboots: >>>> >>>> [root@mbpc-pc ~]# cat /proc/mdstat >>>> Personalities : [raid6] [raid5] [raid4] >>>> md0 : active raid6 sdb[7] sdf[6] sdd[3] sda[5] sdc[1] sde[8] >>>> 3907045632 blocks super 1.2 level 6, 64k chunk, algorithm 2 [6/6] >>>> [UUUUUU] >>>> bitmap: 1/8 pages [4KB], 65536KB chunk >>>> >>>> unused devices: >>>> [root@mbpc-pc ~]# >>>> >>>> >>>> Then I run smartctl across all disks and sure enough /dev/sdf prints >>>> this: >>>> >>>> [root@mbpc-pc ~]# smartctl -A /dev/sdf >>>> smartctl 5.43 2012-06-30 r3573 [x86_64-linux-4.8.4] (local build) >>>> Copyright (C) 2002-12 by Bruce Allen, >>>> http://smartmontools.sourceforge.net >>>> >>>> Error SMART Values Read failed: scsi error badly formed scsi parameters >>>> Smartctl: SMART Read Values failed. >>>> >>>> === START OF READ SMART DATA SECTION === >>>> [root@mbpc-pc ~]# >>>> >>>> So it would appear we found the root cause, a bad disk. True the disk >>>> is bad and I'll be replacing it however, even with a degraded disk >>>> (checking now) the array functions just fine and I have no data >>>> loss. I >>>> only lost 1. I would have to loose 3 to get a catastrophic failure on >>>> this RAID6: >>>> >>>> [root@mbpc-pc ~]# cat /proc/mdstat >>>> Personalities : [raid6] [raid5] [raid4] >>>> md0 : active raid6 sdf[6](F) sda[5] sde[8] sdb[7] sdd[3] sdc[1] >>>> 3907045632 blocks super 1.2 level 6, 64k chunk, algorithm 2 [6/5] >>>> [UUUU_U] >>>> bitmap: 6/8 pages [24KB], 65536KB chunk >>>> >>>> unused devices: >>>> [root@mbpc-pc ~]# mdadm --detail /dev/md0 >>>> /dev/md0: >>>> Version : 1.2 >>>> Creation Time : Mon Mar 26 00:06:24 2012 >>>> Raid Level : raid6 >>>> Array Size : 3907045632 (3726.05 GiB 4000.81 GB) >>>> Used Dev Size : 976761408 (931.51 GiB 1000.20 GB) >>>> Raid Devices : 6 >>>> Total Devices : 6 >>>> Persistence : Superblock is persistent >>>> >>>> Intent Bitmap : Internal >>>> >>>> Update Time : Tue Oct 25 00:31:13 2016 >>>> State : clean, degraded >>>> Active Devices : 5 >>>> Working Devices : 5 >>>> Failed Devices : 1 >>>> Spare Devices : 0 >>>> >>>> Layout : left-symmetric >>>> Chunk Size : 64K >>>> >>>> Name : mbpc:0 >>>> UUID : 2f36ac48:5e3e4c54:72177c53:bea3e41e >>>> Events : 118368 >>>> >>>> Number Major Minor RaidDevice State >>>> 8 8 64 0 active sync /dev/sde >>>> 1 8 32 1 active sync /dev/sdc >>>> 7 8 16 2 active sync /dev/sdb >>>> 3 8 48 3 active sync /dev/sdd >>>> 8 0 0 8 removed >>>> 5 8 0 5 active sync /dev/sda >>>> >>>> 6 8 80 - faulty /dev/sdf >>>> [root@mbpc-pc ~]# >>>> >>>> Last night I cut power to the /dev/sdf disk to spin it down the removed >>>> it and reinserted it. The array resynced without issue however the >>>> smartctl -A command still failed on it. Today I check and bad blocks >>>> were recorded on the disk and the array has since removed /dev/sdf (per >>>> above). Also I have to say that these ESXi hosts worked in this >>>> configuration, without any hickup, for about 4 months. No LUN failure >>>> on the ESXi side. I haven't changed the LUN in that time (had no >>>> reason >>>> to do so). >>>> >>>> So now here's the real question that I have. Why would the array >>>> continue to function, as intended, with only one disk failure yet the >>>> QLogic / Target drivers stop and error out? The RAID6 (software) array >>>> should care about the failure, and it should handle it. QLogic / >>>> Target >>>> Drivers shouldn't really be too impacted (aside from read speed maybe) >>>> about a disk failing inside the array. That would be my thinking. The >>>> Target / QLogic software seems to have picked up on a failure ahead of >>>> the software RAID 6 detecting it. I've had this RAID6 for over 6 years >>>> now. Aside from the occassional disk replacement, quite rock solid. >> >> The earlier hung task warnings after ABORT_TASK w/ TMR_FUNCTION_COMPLETE >> and after explicit configfs shutdown are likely the missing SCF_ACK_KREF >> bit assignment. Note the bug is specific to high backed I/O latency >> with v4.1+ code, so you'll want to include it for all future builds. >> >> AFAICT thus far the list corruption bug reported here and also from Anil >> & Co looks like a separate bug using tcm_qla2xxx ports. >> >>>> >>>> So anyway, I added the fix you pointed out to the 4.8.4 kernel and >>>> recompiled. I restarted it, with the RAID6 degraded as it is. All >>>> mounted fine and I checked the LUN's from the ESXi side: >>>> >>>> [root@mbpc-pc ~]# /etc/init.d/target start >>>> The Linux SCSI Target is already stopped [ OK ] >>>> [info] The Linux SCSI Target looks properly installed. >>>> The configfs filesystem was not mounted, consider adding it[WARNING] >>>> [info] Loaded core module target_core_mod. >>>> [info] Loaded core module target_core_pscsi. >>>> [info] Loaded core module target_core_iblock. >>>> [info] Loaded core module target_core_file. >>>> Failed to load fabric module ib_srpt [WARNING] >>>> Failed to load fabric module tcm_usb_gadget [WARNING] >>>> [info] Loaded fabric module tcm_loop. >>>> [info] Loaded fabric module tcm_fc. >>>> Failed to load fabric module vhost_scsi [WARNING] >>>> [info] Loaded fabric module tcm_qla2xxx. >>>> Failed to load fabric module iscsi_target_mod [WARNING] >>>> [info] Loading config from /etc/target/scsi_target.lio, this may take >>>> several minutes for FC adapters. >>>> [info] Loaded /etc/target/scsi_target.lio. >>>> Started The Linux SCSI Target [ OK ] >>>> [root@mbpc-pc ~]# >>>> >>>> >>>> Enabled the brocade ports: >>>> >>>> >>>> 18 18 011200 id N4 No_Light FC >>>> 19 19 011300 id N4 No_Sync FC Disabled (Persistent) >>>> 20 20 011400 id N4 No_Light FC >>>> 21 21 011500 id N4 No_Light FC >>>> 22 22 011600 id N4 No_Light FC >>>> 23 23 011700 id N4 No_Light FC Disabled (Persistent) >>>> 24 24 011800 -- N4 No_Module FC (No POD License) Disabled >>>> 25 25 011900 -- N4 No_Module FC (No POD License) Disabled >>>> 26 26 011a00 -- N4 No_Module FC (No POD License) Disabled >>>> 27 27 011b00 -- N4 No_Module FC (No POD License) Disabled >>>> 28 28 011c00 -- N4 No_Module FC (No POD License) Disabled >>>> 29 29 011d00 -- N4 No_Module FC (No POD License) Disabled >>>> 30 30 011e00 -- N4 No_Module FC (No POD License) Disabled >>>> 31 31 011f00 -- N4 No_Module FC (No POD License) Disabled >>>> sw0:admin> portcfgpersistentenable 19 >>>> sw0:admin> portcfgpersistentenable 23 >>>> sw0:admin> date >>>> Tue Oct 25 04:03:42 UTC 2016 >>>> sw0:admin> >>>> >>>> And still after 30 minutes, there is no failure. This run includes the >>>> fix you asked me to ass >>>> (https://github.com/torvalds/linux/commit/527268df31e57cf2b6d417198717c6d6afdb1e3e) >>>> >>>> . If everything works, I will revert the patch and see if I can >>>> reproduce the issue. If I can reproduce it, then the disk might not >>>> have been it, but the patch was. I'll keep you posted on that when I >>>> get a new disk tomorrow. >>>> >>>> >>>> Right now this is a POC setup so I have lots of room to experiment. >>>> >>> >>> Hey Nicholas, >>> >>> I've done some testing up till now. With or without the patch above, as >>> long as the faulty disk is removed from the RAID 6 software array, >>> everything works fine with the Target Driver and ESXi hosts. >> >> Thanks again for the extra debug + feedback, and confirming the earlier >> hung task warnings with md disk failure. >> >>> This is >>> even on a degraded array: >>> >>> [root@mbpc-pc ~]# cat /proc/mdstat >>> Personalities : [raid6] [raid5] [raid4] >>> md0 : active raid6 sdc[1] sda[5] sdd[3] sde[8] sdb[7] >>> 3907045632 blocks super 1.2 level 6, 64k chunk, algorithm 2 [6/5] >>> [UUUU_U] >>> bitmap: 6/8 pages [24KB], 65536KB chunk >>> >>> unused devices: >>> [root@mbpc-pc ~]# >>> >>> So at the moment, the data points to the single failed single disk ( >>> /dev/sdf ) as causing the Target Drivers or QLogic cards to throw an >>> exception. >>> >>> Tomorrow I will insert the failed disk back in to see if the a) array >>> takes it back, b) it causes a failure with the patch applied. >>> >>> Looks like the failed disk /dev/sdf was limping along for months and >>> until I removed the power, it didn't collapse on itself. >>> >> >> AFAICT, the list corruption observed is a separate bug from the hung >> tasks during ABORT_TASK w/ TMR_COMPLETE_FUNCTION with explicit target >> shutdown. >> > > Correct, I will be including the fix either way but will take some time > to test out if I can reproduce the failure by reinserting this bad disk > then a new disk. I want to see if this hang will be reproduced by doing > these actions to the RAID6 Software Raid to determine if this failure is > isolated to a particularly bad disk or any sort of add or remove disk > actions in a RAID6. > 1) As soon as I re-add the bad disk without the patch, I loose the LUN off the ESXi hosts. Same thing happens with the patch. No change. The disk is pulling things down. Worse, the kernel panics and locks me out of the system (http://microdevsys.com/linux-lio/messages-oct-27-2016.txt) : Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f81d:20: Intermediate CTIO received (status 6) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e81c:20: Sending TERM EXCH CTIO (ha=ffff88010ecb0000) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f814:20: qla_target(0): terminating exchange for aborted cmd=ffff88009af9f488 (se_cmd=ffff88009af9f488, tag=1131312) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e81c:20: Sending TERM EXCH CTIO (ha=ffff88010ecb0000) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e851:20: qla_target(0): Terminating cmd ffff88009af9f488 with incorrect state 2 Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e81c:20: Sending TERM EXCH CTIO (ha=ffff88010ecb0000) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f81d:20: Intermediate CTIO received (status 6) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f81d:20: Intermediate CTIO received (status 8) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e81c:20: Sending TERM EXCH CTIO (ha=ffff88010ecb0000) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-f81d:20: Intermediate CTIO received (status 6) Oct 28 01:19:59 mbpc-pc kernel: qla2xxx [0000:04:00.0]-e874:20: qlt_free_cmd: se_cmd[ffff88009af9f488] ox_id 0673 Oct 28 01:19:59 mbpc-pc kernel: ------------[ cut here ]------------ Oct 28 01:19:59 mbpc-pc kernel: kernel BUG at drivers/scsi/qla2xxx/qla_target.c:3319! Oct 28 01:19:59 mbpc-pc kernel: invalid opcode: 0000 [#1] SMP Oct 28 01:19:59 mbpc-pc kernel: Modules linked in: tcm_qla2xxx tcm_fc tcm_loop target_core_file target_core_iblock target_core_pscsi target_core_mod configfs ip6table_filter ip6_tables ebtable_nat ebtables nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM iptable_mangle bridge nfsd lockd grace nfs_acl auth_rpcgss autofs4 it87 hwmon_vid bnx2fc cnic uio fcoe libfcoe libfc 8021q garp stp llc ppdev parport_pc parport sunrpc cpufreq_ondemand bonding ipv6 crc_ccitt ipt_REJECT nf_reject_ipv4 xt_multiport iptable_filter ip_tables fuse vfat fat xfs vhost_net macvtap macvlan vhost tun uinput raid456 async_raid6_recov async_pq async_xor xor async_memcpy async_tx raid6_pq libcrc32c joydev sg serio_raw e1000 r8169 mii kvm_amd kvm snd_hda_codec_realtek snd_hda_codec_generic irqbypass pcspkr k10temp snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd soundcore i2c_piix4 i2c_core wmi shpchp acpi_cpufreq ext4 mbcache jbd2 qla2xxx scsi_transport_fc floppy firewire_ohci f Oct 28 01:19:59 mbpc-pc kernel: irewire_core crc_itu_t sd_mod pata_acpi ata_generic pata_jmicron ahci libahci usb_storage dm_mirror dm_region_hash dm_log dm_mod Oct 28 01:19:59 mbpc-pc kernel: CPU: 0 PID: 296 Comm: kworker/u16:6 Not tainted 4.8.4 #2 Oct 28 01:19:59 mbpc-pc kernel: Hardware name: Gigabyte Technology Co., Ltd. GA-890XA-UD3/GA-890XA-UD3, BIOS FC 08/02/2010 Oct 28 01:19:59 mbpc-pc kernel: Workqueue: tmr-fileio target_tmr_work [target_core_mod] Oct 28 01:19:59 mbpc-pc kernel: task: ffff8801109623c0 task.stack: ffff880110968000 Oct 28 01:19:59 mbpc-pc kernel: RIP: 0010:[] [] qlt_free_cmd+0x160/0x180 [qla2xxx] Oct 28 01:19:59 mbpc-pc kernel: RSP: 0018:ffff88011096bb18 EFLAGS: 00010202 Oct 28 01:19:59 mbpc-pc kernel: RAX: 0000000000000051 RBX: ffff88009af9f488 RCX: 0000000000000006 Oct 28 01:19:59 mbpc-pc kernel: RDX: 0000000000000007 RSI: 0000000000000007 RDI: ffff88011fc0cb40 Oct 28 01:19:59 mbpc-pc kernel: RBP: ffff88011096bb48 R08: 0000000000000000 R09: ffffffff81fa4765 Oct 28 01:19:59 mbpc-pc kernel: R10: 0000000000000074 R11: 0000000000000002 R12: ffff8801137770c0 Oct 28 01:19:59 mbpc-pc kernel: R13: ffff8800a126eaf0 R14: ffff88009af9f510 R15: 0000000000000296 Oct 28 01:19:59 mbpc-pc kernel: FS: 0000000000000000(0000) GS:ffff88011fc00000(0000) knlGS:0000000000000000 Oct 28 01:19:59 mbpc-pc kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Oct 28 01:19:59 mbpc-pc kernel: CR2: 00007f8eef58d000 CR3: 00000000cabad000 CR4: 00000000000006f0 Oct 28 01:19:59 mbpc-pc kernel: Stack: Oct 28 01:19:59 mbpc-pc kernel: ffff880000000673 ffff88009af9f488 ffff8800a126eaf0 ffff88009af9f59c Oct 28 01:19:59 mbpc-pc kernel: ffff88009af9f488 ffff8800a126eaf0 ffff88011096bb58 ffffffffa027f7f4 Oct 28 01:19:59 mbpc-pc kernel: ffff88011096bbb8 ffffffffa08f758c ffff88009af9f510 ffff88009af9f488 Oct 28 01:19:59 mbpc-pc kernel: Call Trace: Oct 28 01:19:59 mbpc-pc kernel: [] tcm_qla2xxx_release_cmd+0x14/0x30 [tcm_qla2xxx] Oct 28 01:19:59 mbpc-pc kernel: [] target_release_cmd_kref+0xac/0x110 [target_core_mod] Oct 28 01:19:59 mbpc-pc kernel: [] target_put_sess_cmd+0x37/0x70 [target_core_mod] Oct 28 01:19:59 mbpc-pc kernel: [] core_tmr_abort_task+0x107/0x160 [target_core_mod] Oct 28 01:19:59 mbpc-pc kernel: [] target_tmr_work+0x154/0x160 [target_core_mod] Oct 28 01:19:59 mbpc-pc kernel: [] process_one_work+0x189/0x4e0 Oct 28 01:19:59 mbpc-pc kernel: [] ? del_timer_sync+0x4c/0x60 Oct 28 01:19:59 mbpc-pc kernel: [] ? maybe_create_worker+0x8e/0x110 Oct 28 01:19:59 mbpc-pc kernel: [] ? schedule+0x40/0xb0 Oct 28 01:19:59 mbpc-pc kernel: [] worker_thread+0x16d/0x520 Oct 28 01:19:59 mbpc-pc kernel: [] ? default_wake_function+0x12/0x20 Oct 28 01:19:59 mbpc-pc kernel: [] ? __wake_up_common+0x56/0x90 Oct 28 01:19:59 mbpc-pc kernel: [] ? maybe_create_worker+0x110/0x110 Oct 28 01:19:59 mbpc-pc kernel: [] ? schedule+0x40/0xb0 Oct 28 01:19:59 mbpc-pc kernel: [] ? maybe_create_worker+0x110/0x110 Oct 28 01:19:59 mbpc-pc kernel: [] kthread+0xcc/0xf0 Oct 28 01:19:59 mbpc-pc kernel: [] ? schedule_tail+0x1e/0xc0 Oct 28 01:19:59 mbpc-pc kernel: [] ret_from_fork+0x1f/0x40 Oct 28 01:19:59 mbpc-pc kernel: [] ? kthread_freezable_should_stop+0x70/0x70 Oct 28 01:19:59 mbpc-pc kernel: Code: 0d 00 00 48 c7 c7 00 2a 16 a0 e8 ac 32 f2 e0 48 83 c4 18 5b 41 5c 41 5d c9 c3 48 8b bb 90 02 00 00 e8 85 da 07 e1 e9 30 ff ff ff <0f> 0b eb fe 0f 0b 66 2e 0f 1f 84 00 00 00 00 00 eb f4 66 66 66 Oct 28 01:19:59 mbpc-pc kernel: RIP [] qlt_free_cmd+0x160/0x180 [qla2xxx] Oct 28 01:19:59 mbpc-pc kernel: RSP Oct 28 01:19:59 mbpc-pc kernel: ---[ end trace 2551bf47a19dbe2e ]--- 2) This works with a new disk that's just been inserted. No issues. The kernel had the patch in both scenarios. So appears we can't function on a degraded array that looses 1 (RAID 5 / 6 ) or 2 ( RAID 6 ) disks, at the moment, even though the array itself is fine. Perhaps it's the nature of the failed disk. -- Cheers, Tom K. ------------------------------------------------------------------------------------- Living on earth is expensive, but it includes a free trip around the sun.