System crashes with increased drive count

Discussion:

(too old to reply)

Jun Wu

2014-05-09 02:17:35 UTC

We are running in system crashes as number of drive under test
increases. The test configuration is one initiator as server running
fio sessions to remote drives on a target server via fcoe vn2vn. Both
servers running fedora 20 (kernel 3.14.2-200). Running fio sessions up
to 7 remote drives works but target machines hangs when drive count
increased to 8. The system crashes are very repeatable and duplicated
on RHEL 6.5. Following are error messages on target server:

[ 1503.737314] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000048
[ 1503.737442] IP: [<ffffffffa0610885>] ft_sess_put+0x5/0x30 [tcm_fc]
[ 1503.737540] PGD 0
[ 1503.737575] Oops: 0000 [#1] SMP
[ 1503.737631] Modules linked in: tcm_fc target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
fcoe libfcoe libfc scsi_transport_fc scsi_tgt 8021q garp mrp fuse
ip6t_rpfilter ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute
bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6
nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security
ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4
nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle
iptable_security iptable_raw coretemp iTCO_wdt kvm_intel kvm gpio_ich
iTCO_vendor_support ses crc32c_intel tpm_tis enclosure i7core_edac
ioatdma edac_core shpchp serio_raw tpm lpc_ich mfd_core i2c_i801
microcode acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd sunrpc radeon
drm_kms_helper ttm
[ 1503.738933] igb ixgbe drm ata_generic mdio ptp pata_acpi pps_core
pata_jmicron i2c_algo_bit aacraid dca i2c_core
[ 1503.739118] CPU: 5 PID: 6537 Comm: kworker/5:4 Not tainted
3.14.2-200.fc20.x86_64 #1
[ 1503.739225] Hardware name: Supermicro X8DTN/X8DTN, BIOS 2.1c 10/28/2011
[ 1503.739338] Workqueue: target_completion target_complete_ok_work
[target_core_mod]
[ 1503.739449] task: ffff88062071d580 ti: ffff88061a322000 task.ti:
ffff88061a322000
[ 1503.739553] RIP: 0010:[<ffffffffa0610885>] [<ffffffffa0610885>]
ft_sess_put+0x5/0x30 [tcm_fc]
[ 1503.739681] RSP: 0018:ffff88061a323ce8 EFLAGS: 00010016
[ 1503.739755] RAX: 0000000000000000 RBX: ffff880304a23498 RCX: 0000000000009010
[ 1503.739853] RDX: 0000000000009010 RSI: 00000000000000cb RDI: 0000000000000000
[ 1503.739953] RBP: ffff88061a323d08 R08: ffff88031c4c6500 R09: 000000018020000f
[ 1503.740051] R10: ffffffff815cfe87 R11: ffffea000c713180 R12: ffff88031c4c6500
[ 1503.740150] R13: ffff88031f7c1f80 R14: ffff88031f7c1fe8 R15: 0000000000000000
[ 1503.740250] FS: 0000000000000000(0000) GS:ffff88063fc20000(0000)
knlGS:0000000000000000
[ 1503.740363] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1503.740443] CR2: 0000000000000048 CR3: 0000000001c0c000 CR4: 00000000000007e0
[ 1503.740541] Stack:
[ 1503.740572] ffffffffa060e058 ffff880304a23568 ffff88031f7c1f80
ffff880304a234a8
[ 1503.740692] ffff88061a323d18 ffffffffa060e5e2 ffff88061a323d40
ffffffffa05cff42
[ 1503.740812] ffff880304a234a8 ffff880304a23568 0000000000000246
ffff88061a323d70
[ 1503.740931] Call Trace:
[ 1503.740969] [<ffffffffa060e058>] ? ft_free_cmd+0x58/0x60 [tcm_fc]
[ 1503.741057] [<ffffffffa060e5e2>] ft_release_cmd+0x12/0x20 [tcm_fc]
[ 1503.741150] [<ffffffffa05cff42>] target_release_cmd_kref+0x52/0x80
[target_core_mod]
[ 1503.741264] [<ffffffffa05d1bd3>] transport_release_cmd+0xd3/0xf0
[target_core_mod]
[ 1503.741377] [<ffffffffa05d1c28>]
transport_generic_free_cmd+0x38/0x250 [target_core_mod]
[ 1503.741491] [<ffffffffa060e600>] ft_check_stop_free+0x10/0x20 [tcm_fc]
[ 1503.741590] [<ffffffffa05cfe32>]
transport_cmd_check_stop+0xc2/0x140 [target_core_mod]
[ 1503.741708] [<ffffffffa05d3a97>]
target_complete_ok_work+0xe7/0x2d0 [target_core_mod]
[ 1503.741824] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 1503.741907] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 1503.741985] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 1503.742069] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 1503.742138] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 1503.742227] [<ffffffff816fef7c>] ret_from_fork+0x7c/0xb0
[ 1503.746668] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 1503.751104] Code: 48 89 f0 48 89 c7 89 d6 48 89 e5 48 8b 49 10 48
89 ca e8 4f ed ff ff 5d c3 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 66
66 66 66 90 <8b> 47 48 85 c0 74 22 48 8d 47 48 f0 83 6f 48 01 74 09 c3
0f 1f
[ 1503.760558] RIP [<ffffffffa0610885>] ft_sess_put+0x5/0x30 [tcm_fc]
[ 1503.765145] RSP <ffff88061a323ce8>
[ 1503.769687] CR2: 0000000000000048
[ 1503.789003] ---[ end trace c7457ccb45bf0bc9 ]---

Before target hangs, a lot of messages as follows are printed out on
the initiator:

fio: io_u error on file /dev/sdl: Input/output error
read offset=1030152192, buflen=4096

[ 3787.971900] sd 8:0:0:0: [sdl] Unhandled error code
[ 3787.971907] sd 8:0:0:0: [sdl]
[ 3787.971910] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 3787.971913] sd 8:0:0:0: [sdl] CDB:
[ 3787.971915] Read(10): 28 00 00 1e b3 70 00 00 08 00
[ 3787.971924] end_request: I/O error, dev sdl, sector 2012016

Installation steps used:
yum install lldpad
yum install fcoe-utils
modprobe fcoe
yum install targetcli

Before these tests, we also installed Redhat 6.5 and followed
instructions on https://www.open-fcoe.org/. On Redhat, I were only
able to run fio to 3 target drives. Using 4 target drives crashed the
target machine.

Any suggestions?

Thanks,

Jun

Nicholas A. Bellinger

2014-05-12 19:34:28 UTC

Permalink

Post by Jun Wu
We are running in system crashes as number of drive under test
increases. The test configuration is one initiator as server running
fio sessions to remote drives on a target server via fcoe vn2vn. Both
servers running fedora 20 (kernel 3.14.2-200). Running fio sessions up
to 7 remote drives works but target machines hangs when drive count
increased to 8. The system crashes are very repeatable and duplicated
[ 1503.737314] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000048
[ 1503.737442] IP: [<ffffffffa0610885>] ft_sess_put+0x5/0x30 [tcm_fc]
[ 1503.737540] PGD 0
[ 1503.737575] Oops: 0000 [#1] SMP
[ 1503.737631] Modules linked in: tcm_fc target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
fcoe libfcoe libfc scsi_transport_fc scsi_tgt 8021q garp mrp fuse
ip6t_rpfilter ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute
bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6
nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security
ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4
nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle
iptable_security iptable_raw coretemp iTCO_wdt kvm_intel kvm gpio_ich
iTCO_vendor_support ses crc32c_intel tpm_tis enclosure i7core_edac
ioatdma edac_core shpchp serio_raw tpm lpc_ich mfd_core i2c_i801
microcode acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd sunrpc radeon
drm_kms_helper ttm
[ 1503.738933] igb ixgbe drm ata_generic mdio ptp pata_acpi pps_core
pata_jmicron i2c_algo_bit aacraid dca i2c_core
[ 1503.739118] CPU: 5 PID: 6537 Comm: kworker/5:4 Not tainted
3.14.2-200.fc20.x86_64 #1
[ 1503.739225] Hardware name: Supermicro X8DTN/X8DTN, BIOS 2.1c 10/28/2011
[ 1503.739338] Workqueue: target_completion target_complete_ok_work
[target_core_mod]
ffff88061a322000
[ 1503.739553] RIP: 0010:[<ffffffffa0610885>] [<ffffffffa0610885>]
ft_sess_put+0x5/0x30 [tcm_fc]
[ 1503.739681] RSP: 0018:ffff88061a323ce8 EFLAGS: 00010016
[ 1503.739755] RAX: 0000000000000000 RBX: ffff880304a23498 RCX: 0000000000009010
[ 1503.739853] RDX: 0000000000009010 RSI: 00000000000000cb RDI: 0000000000000000
[ 1503.739953] RBP: ffff88061a323d08 R08: ffff88031c4c6500 R09: 000000018020000f
[ 1503.740051] R10: ffffffff815cfe87 R11: ffffea000c713180 R12: ffff88031c4c6500
[ 1503.740150] R13: ffff88031f7c1f80 R14: ffff88031f7c1fe8 R15: 0000000000000000
[ 1503.740250] FS: 0000000000000000(0000) GS:ffff88063fc20000(0000)
knlGS:0000000000000000
[ 1503.740363] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1503.740443] CR2: 0000000000000048 CR3: 0000000001c0c000 CR4: 00000000000007e0
[ 1503.740572] ffffffffa060e058 ffff880304a23568 ffff88031f7c1f80
ffff880304a234a8
[ 1503.740692] ffff88061a323d18 ffffffffa060e5e2 ffff88061a323d40
ffffffffa05cff42
[ 1503.740812] ffff880304a234a8 ffff880304a23568 0000000000000246
ffff88061a323d70
[ 1503.740969] [<ffffffffa060e058>] ? ft_free_cmd+0x58/0x60 [tcm_fc]
[ 1503.741057] [<ffffffffa060e5e2>] ft_release_cmd+0x12/0x20 [tcm_fc]
[ 1503.741150] [<ffffffffa05cff42>] target_release_cmd_kref+0x52/0x80
[target_core_mod]
[ 1503.741264] [<ffffffffa05d1bd3>] transport_release_cmd+0xd3/0xf0
[target_core_mod]
[ 1503.741377] [<ffffffffa05d1c28>]
transport_generic_free_cmd+0x38/0x250 [target_core_mod]
[ 1503.741491] [<ffffffffa060e600>] ft_check_stop_free+0x10/0x20 [tcm_fc]
[ 1503.741590] [<ffffffffa05cfe32>]
transport_cmd_check_stop+0xc2/0x140 [target_core_mod]
[ 1503.741708] [<ffffffffa05d3a97>]
target_complete_ok_work+0xe7/0x2d0 [target_core_mod]
[ 1503.741824] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 1503.741907] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 1503.741985] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 1503.742069] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 1503.742138] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 1503.742227] [<ffffffff816fef7c>] ret_from_fork+0x7c/0xb0
[ 1503.746668] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 1503.751104] Code: 48 89 f0 48 89 c7 89 d6 48 89 e5 48 8b 49 10 48
89 ca e8 4f ed ff ff 5d c3 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 66
66 66 66 90 <8b> 47 48 85 c0 74 22 48 8d 47 48 f0 83 6f 48 01 74 09 c3
0f 1f
[ 1503.760558] RIP [<ffffffffa0610885>] ft_sess_put+0x5/0x30 [tcm_fc]
[ 1503.765145] RSP <ffff88061a323ce8>
[ 1503.769687] CR2: 0000000000000048
[ 1503.789003] ---[ end trace c7457ccb45bf0bc9 ]---

Post by Jun Wu
From 1d8dc8a29cfa6d66e5068ab6dad3216fe218cc53 Mon Sep 17 00:00:00 2001

From: Nicholas Bellinger <***@linux-iscsi.org>
Date: Mon, 12 May 2014 12:18:32 -0700
Subject: [PATCH] tcm_fc: Fix free-after-use regression in ft_free_cmd

This patch fixes a free-after-use regression in ft_free_cmd(), where
percpu_ida_free() was incorrectly called to release the tag before
ft_sess_put() is called to drop the session reference.

Fix this bug by moving the percpu_ida_free() call after ft_free_cmd().

The regression was originally introduced in v3.13-rc1 commit:

commit 5f544cfac956971099e906f94568bc3fd1a7108a
Author: Nicholas Bellinger <***@daterainc.com>
Date: Mon Sep 23 12:12:42 2013 -0700

tcm_fc: Convert to per-cpu command map pre-allocation of ft_cmd

Reported-by: Jun Wu <***@stormojo.com>
Cc: Mark Rustad <***@intel.com>
Cc: Robert Love <***@intel.com>
Cc: <***@vger.kernel.org> #3.13+
Signed-off-by: Nicholas Bellinger <***@linux-iscsi.org>
---
drivers/target/tcm_fc/tfc_cmd.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/target/tcm_fc/tfc_cmd.c b/drivers/target/tcm_fc/tfc_cmd.c
index 01cf37f..28fce39 100644
--- a/drivers/target/tcm_fc/tfc_cmd.c
+++ b/drivers/target/tcm_fc/tfc_cmd.c
@@ -100,8 +100,8 @@ static void ft_free_cmd(struct ft_cmd *cmd)
if (fr_seq(fp))
lport->tt.seq_release(fr_seq(fp));
fc_frame_free(fp);
- percpu_ida_free(&se_sess->sess_tag_pool, cmd->se_cmd.map_tag);
ft_sess_put(cmd->sess); /* undo get from lookup at recv */
+ percpu_ida_free(&se_sess->sess_tag_pool, cmd->se_cmd.map_tag);
}

void ft_release_cmd(struct se_cmd *se_cmd)
--
1.7.10.4

Post by Jun Wu
Before target hangs, a lot of messages as follows are printed out on
fio: io_u error on file /dev/sdl: Input/output error
read offset=1030152192, buflen=4096
[ 3787.971900] sd 8:0:0:0: [sdl] Unhandled error code
[ 3787.971907] sd 8:0:0:0: [sdl]
[ 3787.971910] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 3787.971915] Read(10): 28 00 00 1e b3 70 00 00 08 00
[ 3787.971924] end_request: I/O error, dev sdl, sector 2012016

Not sure what's going on here without more information.

Post by Jun Wu
yum install lldpad
yum install fcoe-utils
modprobe fcoe
yum install targetcli
Before these tests, we also installed Redhat 6.5 and followed
instructions on https://www.open-fcoe.org/. On Redhat, I were only
able to run fio to 3 target drives. Using 4 target drives crashed the
target machine.

No idea without more info wrt RHEL 6.5, but it certainly doesn't have
the v3.13+ specific percpu-ida regression from above.

--nab

Jun Wu

2014-05-13 21:52:36 UTC

Permalink

Hi Nicholas,

We had to roll back system from 3.14 to 3.11 due to compile issues of
our software. So I am not able to verify your fix at this point.
I ran the same tests on 3.11 instead.

In one case the target crashed with following message:

May 13 13:06:25 poc2 kernel: BUG: unable to handle kernel paging
request at ffffffffffffffa4
May 13 13:06:25 poc2 kernel: IP: [<ffffffff8164ac07>]
_raw_spin_lock_bh+0x17/0x40
May 13 13:06:25 poc2 kernel: PGD 1c0f067 PUD 1c11067 PMD 0
May 13 13:06:25 poc2 kernel: Oops: 0002 [#1] SMP
May 13 13:06:25 poc2 kernel: Modules linked in: fcoe libfcoe 8021q
garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
ip6t_rpfilter ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute
bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6
nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security
ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4
nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle
iptable_security iptable_raw nfsd auth_rpcgss nfs_acl lockd sunrpc
ixgbe mdio igb ptp pps_core serio_raw ses enclosure iTCO_wdt
iTCO_vendor_support lpc_ich mfd_core shpchp i2c_i801 coretemp
kvm_intel kvm crc32c_intel microcode i7core_edac ioatdma acpi_cpufreq
edac_core dca mperf radeon i2c_algo_bit
May 13 13:06:25 poc2 kernel: drm_kms_helper ttm drm ata_generic
i2c_core pata_acpi pata_jmicron aacraid
May 13 13:06:25 poc2 kernel: CPU: 0 PID: 1810 Comm: kworker/0:0 Not
tainted 3.11.10-301.fc20.x86_64 #1
May 13 13:06:25 poc2 kernel: Hardware name: Supermicro X8DTN/X8DTN,
BIOS 2.1c 10/28/2011
May 13 13:06:25 poc2 kernel: Workqueue: target_completion
target_complete_ok_work [target_core_mod]
May 13 13:06:25 poc2 kernel: task: ffff88032c5096e0 ti:
ffff88031bb78000 task.ti: ffff88031bb78000
May 13 13:06:25 poc2 kernel: RIP: 0010:[<ffffffff8164ac07>]
[<ffffffff8164ac07>] _raw_spin_lock_bh+0x17/0x40
May 13 13:06:25 poc2 kernel: RSP: 0018:ffff88031bb79cf0 EFLAGS: 00010206
May 13 13:06:25 poc2 kernel: RAX: 0000000000000100 RBX:
ffffffffffffffa4 RCX: 0000000000000000
May 13 13:06:25 poc2 kernel: RDX: 0000000000000000 RSI:
0000000000000000 RDI: ffffffffffffffa4
May 13 13:06:25 poc2 kernel: RBP: ffff88031bb79cf8 R08:
00000000ffffffff R09: ffff88031a37f678
May 13 13:06:25 poc2 kernel: R10: 0000000000000001 R11:
0000000000000044 R12: 0000000000000000
May 13 13:06:25 poc2 kernel: R13: ffff88031a37f678 R14:
ffff88062d9fd6c8 R15: ffff88032c6da05c
May 13 13:06:25 poc2 kernel: FS: 0000000000000000(0000)
GS:ffff880333c00000(0000) knlGS:0000000000000000
May 13 13:06:25 poc2 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
May 13 13:06:25 poc2 kernel: CR2: ffffffffffffffa4 CR3:
0000000001c0c000 CR4: 00000000000007f0
May 13 13:06:25 poc2 kernel: Stack:
May 13 13:06:25 poc2 kernel: ffffffffffffffa4 ffff88031bb79d18
ffffffffa0594d2b ffff880328d13410
May 13 13:06:25 poc2 kernel: ffff88031a37c200 ffff88031bb79d58
ffffffffa05356f2 0000000000000018
May 13 13:06:25 poc2 kernel: ffff88062cea8800 0000000000000000
ffffea000c8eb640 0000000000000000
May 13 13:06:25 poc2 kernel: Call Trace:
May 13 13:06:25 poc2 kernel: [<ffffffffa0594d2b>]
fc_seq_start_next+0x1b/0x40 [libfc]
May 13 13:06:25 poc2 kernel: [<ffffffffa05356f2>]
ft_queue_status+0xf2/0x220 [tcm_fc]
May 13 13:06:25 poc2 kernel: [<ffffffffa0536972>]
ft_queue_data_in+0x72/0x5a0 [tcm_fc]
May 13 13:06:25 poc2 kernel: [<ffffffffa04f57ba>]
target_complete_ok_work+0x14a/0x2b0 [target_core_mod]
May 13 13:06:25 poc2 kernel: [<ffffffff810810f5>] process_one_work+0x175/0x430
May 13 13:06:25 poc2 kernel: [<ffffffff81081d1b>] worker_thread+0x11b/0x3a0
May 13 13:06:25 poc2 kernel: [<ffffffff81081c00>] ? rescuer_thread+0x340/0x340
May 13 13:06:25 poc2 kernel: [<ffffffff81088660>] kthread+0xc0/0xd0
May 13 13:06:25 poc2 kernel: [<ffffffff810885a0>] ?
insert_kthread_work+0x40/0x40
May 13 13:06:25 poc2 kernel: [<ffffffff8165332c>] ret_from_fork+0x7c/0xb0
May 13 13:06:25 poc2 kernel: [<ffffffff810885a0>] ?
insert_kthread_work+0x40/0x40
May 13 13:06:25 poc2 kernel: Code: 1f 44 00 00 f3 90 0f b6 07 38 d0 75
f7 5d c3 0f 1f 44 00 00 66 66 66 66 90 55 48 89 e5 53 48 89 fb e8 7e
05 a2 ff b8 00 01 00 00 <f0> 66 0f c1 03 0f b6 d4 38 c2 74 0e 0f 1f 44
00 00 f3 90 0f b6
May 13 13:06:25 poc2 kernel: RIP [<ffffffff8164ac07>]
_raw_spin_lock_bh+0x17/0x40

In another case, the initiator crashed with:

May 13 12:00:47 poc1 kernel: [ 4086.708455] WARNING: CPU: 1 PID: 1869
at lib/list_debug.c:62 __list_del_entry+0x82/0xd0()
May 13 12:00:47 poc1 kernel: [ 4086.708459] list_del corruption.
next->prev should be ffff88061dab0318, but was ffff88061d257318
May 13 12:00:47 poc1 kernel: [ 4086.708461] Modules linked in: fcoe
libfcoe 8021q garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt
target_core_pscsi target_core_file target_core_iblock iscsi_target_mod
target_core_mod nf_conntrack_netbios_ns nf_conntrack_broadcast
ipt_MASQUERADE ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute
bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6
nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security
ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4
nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle
iptable_security iptable_raw coretemp kvm_intel kvm crc32c_intel
iTCO_wdt iTCO_vendor_support microcode serio_raw i2c_i801 ses igb
enclosure lpc_ich mfd_core ixgbe ptp pps_core mdio i7core_edac ioatdma
edac_core dca shpchp acpi_cpufreq mperf nfsd auth_rpcgss nfs_acl lockd
sunrpc radeon i2c_algo_bit drm_kms_helper ttm drm ata_generic i2c_core
pata_acpi pata_jmicron aacraid
May 13 12:00:47 poc1 kernel: [ 4086.708556] CPU: 1 PID: 1869 Comm:
fcoethread/1 Not tainted 3.11.10-301.fc20.x86_64 #1
May 13 12:00:47 poc1 kernel: [ 4086.708558] Hardware name: Supermicro
X8DTN/X8DTN, BIOS 2.1c 10/28/2011
May 13 12:00:47 poc1 kernel: [ 4086.708561] 0000000000000009
ffff8806129dfb40 ffffffff816441db ffff8806129dfb88
May 13 12:00:47 poc1 kernel: [ 4086.708569] ffff8806129dfb78
ffffffff8106715d ffff88061dab0318 ffff88061dab0a00
May 13 12:00:47 poc1 kernel: [ 4086.708576] 0000000000000286
ffff880c1b5e4388 0000000000000030 ffff8806129dfbd8
May 13 12:00:47 poc1 kernel: [ 4086.708582] Call Trace:
May 13 12:00:47 poc1 kernel: [ 4086.708592] [<ffffffff816441db>]
dump_stack+0x45/0x56
May 13 12:00:47 poc1 kernel: [ 4086.708598] [<ffffffff8106715d>]
warn_slowpath_common+0x7d/0xa0
May 13 12:00:47 poc1 kernel: [ 4086.708602] [<ffffffff810671cc>]
warn_slowpath_fmt+0x4c/0x50
May 13 12:00:47 poc1 kernel: [ 4086.708608] [<ffffffff81311dc2>]
__list_del_entry+0x82/0xd0
May 13 12:00:47 poc1 kernel: [ 4086.708613] [<ffffffff81311e1d>]
list_del+0xd/0x30
May 13 12:00:47 poc1 kernel: [ 4086.708624] [<ffffffffa05de23c>]
fc_io_compl+0x1cc/0x710 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708633] [<ffffffffa05de7df>]
fc_fcp_complete_locked+0x5f/0x1a0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708642] [<ffffffffa05dfac9>]
fc_fcp_resp.isra.22+0x79/0x2f0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708651] [<ffffffff810a2a33>] ?
load_balance+0xe3/0x740
May 13 12:00:47 poc1 kernel: [ 4086.708660] [<ffffffffa05e0424>]
fc_fcp_recv+0x6e4/0xef0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708666] [<ffffffff810115ce>] ?
__switch_to+0x13e/0x4b0
May 13 12:00:47 poc1 kernel: [ 4086.708673] [<ffffffff8164aab5>] ?
_raw_spin_unlock_bh+0x15/0x20
May 13 12:00:47 poc1 kernel: [ 4086.708682] [<ffffffffa05dfd40>] ?
fc_fcp_resp.isra.22+0x2f0/0x2f0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708690] [<ffffffffa05d421b>]
fc_exch_recv+0x8eb/0xd70 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708695] [<ffffffffa0613299>]
fcoe_percpu_receive_thread+0x299/0x540 [fcoe]
May 13 12:00:47 poc1 kernel: [ 4086.708699] [<ffffffffa0613000>] ?
fcoe_set_port_id+0x50/0x50 [fcoe]
May 13 12:00:47 poc1 kernel: [ 4086.708705] [<ffffffff81088660>]
kthread+0xc0/0xd0
May 13 12:00:47 poc1 kernel: [ 4086.708710] [<ffffffff810885a0>] ?
insert_kthread_work+0x40/0x40
May 13 12:00:47 poc1 kernel: [ 4086.708717] [<ffffffff8165332c>]
ret_from_fork+0x7c/0xb0
May 13 12:00:47 poc1 kernel: [ 4086.708723] [<ffffffff810885a0>] ?
insert_kthread_work+0x40/0x40
May 13 12:00:47 poc1 kernel: [ 4086.708728] ---[ end trace 61dc774d1f379191 ]---

[***@poc1 log]# lspci | grep 82599
08:00.0 Ethernet controller: Intel Corporation 82599ES 10-Gigabit
SFI/SFP+ Network Connection (rev 01)

[***@poc1 log]# uname -a
Linux poc1 3.11.10-301.fc20.x86_64 #1 SMP Thu Dec 5 14:01:17 UTC 2013
x86_64 x86_64 x86_64 GNU/Linux

Thanks,

Jun

On Mon, May 12, 2014 at 12:34 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

The v3.14 OOPs above looks like a free-after-use regression from the
v3.13 conversion to use percpu-ida for pre-allocation of ft_cmd
descriptors.
Here's the patch that I'm applying to address this specific bug in
tcm_fc. Please apply it and verify the fix on your end.
From 1d8dc8a29cfa6d66e5068ab6dad3216fe218cc53 Mon Sep 17 00:00:00 2001
Date: Mon, 12 May 2014 12:18:32 -0700
Subject: [PATCH] tcm_fc: Fix free-after-use regression in ft_free_cmd
This patch fixes a free-after-use regression in ft_free_cmd(), where
percpu_ida_free() was incorrectly called to release the tag before
ft_sess_put() is called to drop the session reference.
Fix this bug by moving the percpu_ida_free() call after ft_free_cmd().
commit 5f544cfac956971099e906f94568bc3fd1a7108a
Date: Mon Sep 23 12:12:42 2013 -0700
tcm_fc: Convert to per-cpu command map pre-allocation of ft_cmd
---
drivers/target/tcm_fc/tfc_cmd.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/drivers/target/tcm_fc/tfc_cmd.c b/drivers/target/tcm_fc/tfc_cmd.c
index 01cf37f..28fce39 100644
--- a/drivers/target/tcm_fc/tfc_cmd.c
+++ b/drivers/target/tcm_fc/tfc_cmd.c
@@ -100,8 +100,8 @@ static void ft_free_cmd(struct ft_cmd *cmd)
if (fr_seq(fp))
lport->tt.seq_release(fr_seq(fp));
fc_frame_free(fp);
- percpu_ida_free(&se_sess->sess_tag_pool, cmd->se_cmd.map_tag);
ft_sess_put(cmd->sess); /* undo get from lookup at recv */
+ percpu_ida_free(&se_sess->sess_tag_pool, cmd->se_cmd.map_tag);
}
void ft_release_cmd(struct se_cmd *se_cmd)
--
1.7.10.4

Not sure what's going on here without more information.

No idea without more info wrt RHEL 6.5, but it certainly doesn't have
the v3.13+ specific percpu-ida regression from above.
--nab

Nicholas A. Bellinger

2014-05-14 21:39:22 UTC

Permalink

Post by Jun Wu
Hi Nicholas,
We had to roll back system from 3.14 to 3.11 due to compile issues of
our software. So I am not able to verify your fix at this point.

That is unfortunate your stuck on a now unsupported stable kernel.
There are some other libfc related fixes that have gone in during the
v3.13 timeframe, so I'd strongly recommend upgrading to at least that
stable version.

In any event, I'll be pushing that particular >= v3.13.y patch anyways,
as it's a obvious regression bugfix for percpu-ida pre-allocation.

Post by Jun Wu
I ran the same tests on 3.11 instead.
May 13 13:06:25 poc2 kernel: BUG: unable to handle kernel paging
request at ffffffffffffffa4
May 13 13:06:25 poc2 kernel: IP: [<ffffffff8164ac07>]
_raw_spin_lock_bh+0x17/0x40
May 13 13:06:25 poc2 kernel: PGD 1c0f067 PUD 1c11067 PMD 0
May 13 13:06:25 poc2 kernel: Oops: 0002 [#1] SMP
May 13 13:06:25 poc2 kernel: Modules linked in: fcoe libfcoe 8021q

garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi

Post by Jun Wu
target_core_file target_core_iblock iscsi_target_mod target_core_mod
ip6t_rpfilter ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute
bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6
nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security
ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4
nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle
iptable_security iptable_raw nfsd auth_rpcgss nfs_acl lockd sunrpc
ixgbe mdio igb ptp pps_core serio_raw ses enclosure iTCO_wdt
iTCO_vendor_support lpc_ich mfd_core shpchp i2c_i801 coretemp
kvm_intel kvm crc32c_intel microcode i7core_edac ioatdma acpi_cpufreq
edac_core dca mperf radeon i2c_algo_bit
May 13 13:06:25 poc2 kernel: drm_kms_helper ttm drm ata_generic
i2c_core pata_acpi pata_jmicron aacraid
May 13 13:06:25 poc2 kernel: CPU: 0 PID: 1810 Comm: kworker/0:0 Not
tainted 3.11.10-301.fc20.x86_64 #1
May 13 13:06:25 poc2 kernel: Hardware name: Supermicro X8DTN/X8DTN,
BIOS 2.1c 10/28/2011
May 13 13:06:25 poc2 kernel: Workqueue: target_completion target_complete_ok_work [target_core_mod]
May 13 13:06:25 poc2 kernel: task: ffff88032c5096e0 ti: ffff88031bb78000 task.ti: ffff88031bb78000
May 13 13:06:25 poc2 kernel: RIP: 0010:[<ffffffff8164ac07>] [<ffffffff8164ac07>] _raw_spin_lock_bh+0x17/0x40
May 13 13:06:25 poc2 kernel: RSP: 0018:ffff88031bb79cf0 EFLAGS: 00010206
May 13 13:06:25 poc2 kernel: RAX: 0000000000000100 RBX: ffffffffffffffa4 RCX: 0000000000000000
May 13 13:06:25 poc2 kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffffffffffa4
May 13 13:06:25 poc2 kernel: RBP: ffff88031bb79cf8 R08: 00000000ffffffff R09: ffff88031a37f678
May 13 13:06:25 poc2 kernel: R10: 0000000000000001 R11: 0000000000000044 R12: 0000000000000000
May 13 13:06:25 poc2 kernel: R13: ffff88031a37f678 R14: ffff88062d9fd6c8 R15: ffff88032c6da05c
May 13 13:06:25 poc2 kernel: FS: 0000000000000000(0000) GS:ffff880333c00000(0000) knlGS:0000000000000000
May 13 13:06:25 poc2 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
May 13 13:06:25 poc2 kernel: CR2: ffffffffffffffa4 CR3: 0000000001c0c000 CR4: 00000000000007f0
May 13 13:06:25 poc2 kernel: ffffffffffffffa4 ffff88031bb79d18 ffffffffa0594d2b ffff880328d13410
May 13 13:06:25 poc2 kernel: ffff88031a37c200 ffff88031bb79d58 ffffffffa05356f2 0000000000000018
May 13 13:06:25 poc2 kernel: ffff88062cea8800 0000000000000000 ffffea000c8eb640 0000000000000000
May 13 13:06:25 poc2 kernel: [<ffffffffa0594d2b>] fc_seq_start_next+0x1b/0x40 [libfc]
May 13 13:06:25 poc2 kernel: [<ffffffffa05356f2>] ft_queue_status+0xf2/0x220 [tcm_fc]
May 13 13:06:25 poc2 kernel: [<ffffffffa0536972>] ft_queue_data_in+0x72/0x5a0 [tcm_fc]
May 13 13:06:25 poc2 kernel: [<ffffffffa04f57ba>] target_complete_ok_work+0x14a/0x2b0 [target_core_mod]
May 13 13:06:25 poc2 kernel: [<ffffffff810810f5>] process_one_work+0x175/0x430
May 13 13:06:25 poc2 kernel: [<ffffffff81081d1b>] worker_thread+0x11b/0x3a0
May 13 13:06:25 poc2 kernel: [<ffffffff81081c00>] ? rescuer_thread+0x340/0x340
May 13 13:06:25 poc2 kernel: [<ffffffff81088660>] kthread+0xc0/0xd0
May 13 13:06:25 poc2 kernel: [<ffffffff810885a0>] ? insert_kthread_work+0x40/0x40
May 13 13:06:25 poc2 kernel: [<ffffffff8165332c>] ret_from_fork+0x7c/0xb0
May 13 13:06:25 poc2 kernel: [<ffffffff810885a0>] ? insert_kthread_work+0x40/0x40
May 13 13:06:25 poc2 kernel: Code: 1f 44 00 00 f3 90 0f b6 07 38 d0 75
f7 5d c3 0f 1f 44 00 00 66 66 66 66 90 55 48 89 e5 53 48 89 fb e8 7e
05 a2 ff b8 00 01 00 00 <f0> 66 0f c1 03 0f b6 d4 38 c2 74 0e 0f 1f 44
00 00 f3 90 0f b6
May 13 13:06:25 poc2 kernel: RIP [<ffffffff8164ac07>] _raw_spin_lock_bh+0x17/0x40

So before we start debugging again, please confirm that this is a
*completely* stock v3.11.10 build, and that your not building
out-of-tree target modules again.

Post by Jun Wu
May 13 12:00:47 poc1 kernel: [ 4086.708455] WARNING: CPU: 1 PID: 1869
at lib/list_debug.c:62 __list_del_entry+0x82/0xd0()
May 13 12:00:47 poc1 kernel: [ 4086.708459] list_del corruption.
next->prev should be ffff88061dab0318, but was ffff88061d257318
May 13 12:00:47 poc1 kernel: [ 4086.708461] Modules linked in: fcoe
libfcoe 8021q garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt
target_core_pscsi target_core_file target_core_iblock iscsi_target_mod
target_core_mod nf_conntrack_netbios_ns nf_conntrack_broadcast
ipt_MASQUERADE ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute
bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6
nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security
ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4
nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle
iptable_security iptable_raw coretemp kvm_intel kvm crc32c_intel
iTCO_wdt iTCO_vendor_support microcode serio_raw i2c_i801 ses igb
enclosure lpc_ich mfd_core ixgbe ptp pps_core mdio i7core_edac ioatdma
edac_core dca shpchp acpi_cpufreq mperf nfsd auth_rpcgss nfs_acl lockd
sunrpc radeon i2c_algo_bit drm_kms_helper ttm drm ata_generic i2c_core
pata_acpi pata_jmicron aacraid
fcoethread/1 Not tainted 3.11.10-301.fc20.x86_64 #1
May 13 12:00:47 poc1 kernel: [ 4086.708558] Hardware name: Supermicro
X8DTN/X8DTN, BIOS 2.1c 10/28/2011
May 13 12:00:47 poc1 kernel: [ 4086.708561] 0000000000000009 ffff8806129dfb40 ffffffff816441db ffff8806129dfb88
May 13 12:00:47 poc1 kernel: [ 4086.708569] ffff8806129dfb78 ffffffff8106715d ffff88061dab0318 ffff88061dab0a00
May 13 12:00:47 poc1 kernel: [ 4086.708576] 0000000000000286 ffff880c1b5e4388 0000000000000030 ffff8806129dfbd8
May 13 12:00:47 poc1 kernel: [ 4086.708592] [<ffffffff816441db>] dump_stack+0x45/0x56
May 13 12:00:47 poc1 kernel: [ 4086.708598] [<ffffffff8106715d>] warn_slowpath_common+0x7d/0xa0
May 13 12:00:47 poc1 kernel: [ 4086.708602] [<ffffffff810671cc>] warn_slowpath_fmt+0x4c/0x50
May 13 12:00:47 poc1 kernel: [ 4086.708608] [<ffffffff81311dc2>] __list_del_entry+0x82/0xd0
May 13 12:00:47 poc1 kernel: [ 4086.708613] [<ffffffff81311e1d>] list_del+0xd/0x30
May 13 12:00:47 poc1 kernel: [ 4086.708624] [<ffffffffa05de23c>] fc_io_compl+0x1cc/0x710 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708633] [<ffffffffa05de7df>] fc_fcp_complete_locked+0x5f/0x1a0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708642] [<ffffffffa05dfac9>] fc_fcp_resp.isra.22+0x79/0x2f0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708651] [<ffffffff810a2a33>] ? load_balance+0xe3/0x740
May 13 12:00:47 poc1 kernel: [ 4086.708660] [<ffffffffa05e0424>] fc_fcp_recv+0x6e4/0xef0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708666] [<ffffffff810115ce>] ? __switch_to+0x13e/0x4b0
May 13 12:00:47 poc1 kernel: [ 4086.708673] [<ffffffff8164aab5>] ? _raw_spin_unlock_bh+0x15/0x20
May 13 12:00:47 poc1 kernel: [ 4086.708682] [<ffffffffa05dfd40>] ? fc_fcp_resp.isra.22+0x2f0/0x2f0 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708690] [<ffffffffa05d421b>] fc_exch_recv+0x8eb/0xd70 [libfc]
May 13 12:00:47 poc1 kernel: [ 4086.708695] [<ffffffffa0613299>] fcoe_percpu_receive_thread+0x299/0x540 [fcoe]
May 13 12:00:47 poc1 kernel: [ 4086.708699] [<ffffffffa0613000>] ? fcoe_set_port_id+0x50/0x50 [fcoe]
May 13 12:00:47 poc1 kernel: [ 4086.708705] [<ffffffff81088660>] kthread+0xc0/0xd0
May 13 12:00:47 poc1 kernel: [ 4086.708710] [<ffffffff810885a0>] ? insert_kthread_work+0x40/0x40
May 13 12:00:47 poc1 kernel: [ 4086.708717] [<ffffffff8165332c>] ret_from_fork+0x7c/0xb0
May 13 12:00:47 poc1 kernel: [ 4086.708723] [<ffffffff810885a0>] ? insert_kthread_work+0x40/0x40
May 13 12:00:47 poc1 kernel: [ 4086.708728] ---[ end trace 61dc774d1f379191 ]---

No idea on the initiator side issue. Intel folks..? (Adding
openfcoe-dev CC')

--nab

Post by Jun Wu
08:00.0 Ethernet controller: Intel Corporation 82599ES 10-Gigabit
SFI/SFP+ Network Connection (rev 01)
Linux poc1 3.11.10-301.fc20.x86_64 #1 SMP Thu Dec 5 14:01:17 UTC 2013
x86_64 x86_64 x86_64 GNU/Linux
Thanks,

Jun Wu

2014-05-15 00:23:24 UTC

Permalink

On Wed, May 14, 2014 at 2:39 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

Post by Jun Wu
Hi Nicholas,
We had to roll back system from 3.14 to 3.11 due to compile issues of
our software. So I am not able to verify your fix at this point.

That is unfortunate your stuck on a now unsupported stable kernel.
There are some other libfc related fixes that have gone in during the
v3.13 timeframe, so I'd strongly recommend upgrading to at least that
stable version.
In any event, I'll be pushing that particular >= v3.13.y patch anyways,
as it's a obvious regression bugfix for percpu-ida pre-allocation.

garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi

So before we start debugging again, please confirm that this is a
*completely* stock v3.11.10 build, and that your not building
out-of-tree target modules again.

Yes we installed official Fedora 20 iso image and then
yum install targetcli
modprobe fcoe

Kernel version is 3.11.10-301.fc20.x86_64 which is a stock kernel distribution.

Post by Nicholas A. Bellinger

No idea on the initiator side issue. Intel folks..? (Adding
openfcoe-dev CC')
--nab

Nicholas A. Bellinger

2014-05-15 01:57:25 UTC

Permalink

Post by Jun Wu
On Wed, May 14, 2014 at 2:39 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

Post by Jun Wu
Hi Nicholas,
We had to roll back system from 3.14 to 3.11 due to compile issues of
our software. So I am not able to verify your fix at this point.

That is unfortunate your stuck on a now unsupported stable kernel.
There are some other libfc related fixes that have gone in during the
v3.13 timeframe, so I'd strongly recommend upgrading to at least that
stable version.
In any event, I'll be pushing that particular >= v3.13.y patch anyways,
as it's a obvious regression bugfix for percpu-ida pre-allocation.

garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi

So before we start debugging again, please confirm that this is a
*completely* stock v3.11.10 build, and that your not building
out-of-tree target modules again.

Yes we installed official Fedora 20 iso image and then
yum install targetcli
modprobe fcoe
Kernel version is 3.11.10-301.fc20.x86_64 which is a stock kernel distribution.

So I'd still recommend >= v3.13.y in order to pick-up the other libfc
related bugfixes that have gone in since v3.11.y ran out of stable
support some months ago. I can't tell if that is related to the bug(s)
that your hitting on both initiator + target sides here, but it
definitely would not hurt.

Also, here is the updated >= v3.13.y percpu-ida pre-allocation
regression fix that will be going into v3.15-rc6 shortly. Note this is
different from the original version, so please make sure you use this
one instead.

https://git.kernel.org/cgit/linux/kernel/git/nab/target-pending.git/commit/?id=e7c36ac16b91bf09e94f82d1838f0f9f114bed08

--nab

Jun Wu

2014-05-15 02:20:29 UTC

Permalink

On Wed, May 14, 2014 at 6:57 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

Post by Jun Wu
On Wed, May 14, 2014 at 2:39 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

Post by Jun Wu
Hi Nicholas,
We had to roll back system from 3.14 to 3.11 due to compile issues of
our software. So I am not able to verify your fix at this point.

That is unfortunate your stuck on a now unsupported stable kernel.
There are some other libfc related fixes that have gone in during the
v3.13 timeframe, so I'd strongly recommend upgrading to at least that
stable version.
In any event, I'll be pushing that particular >= v3.13.y patch anyways,
as it's a obvious regression bugfix for percpu-ida pre-allocation.

garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi

So before we start debugging again, please confirm that this is a
*completely* stock v3.11.10 build, and that your not building
out-of-tree target modules again.

Yes we installed official Fedora 20 iso image and then
yum install targetcli
modprobe fcoe
Kernel version is 3.11.10-301.fc20.x86_64 which is a stock kernel distribution.

So I'd still recommend >= v3.13.y in order to pick-up the other libfc
related bugfixes that have gone in since v3.11.y ran out of stable
support some months ago. I can't tell if that is related to the bug(s)
that your hitting on both initiator + target sides here, but it
definitely would not hurt.
Also, here is the updated >= v3.13.y percpu-ida pre-allocation
regression fix that will be going into v3.15-rc6 shortly. Note this is
different from the original version, so please make sure you use this
one instead.

That's what we are going to do. Our software compiles on 3.13 kernel.
I will run some test once the systems are ready.

Thanks a lot.

Post by Nicholas A. Bellinger
https://git.kernel.org/cgit/linux/kernel/git/nab/target-pending.git/commit/?id=e7c36ac16b91bf09e94f82d1838f0f9f114bed08
--nab

Jun Wu

2014-05-20 00:29:35 UTC

Permalink

Hi Nicholas,

We downloaded the source of our running kernel (3.13.10-200) and
applied your percpu-ida pre-allocation regression fix, then compiled
and installed the kernel. I repeated the same test three times,
running 10 fio sessions to 10 drives on the target through fcoe vn2vn.
In the first two tests, the target machine hung with the following
messages:

15231 May 19 11:49:27 poc1 kernel: [ 1073.783229] ft_queue_data_in:
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 196608,
lso_max <0x10000>
15232 May 19 11:49:27 poc1 kernel: [ 1073.783238] ft_queue_data_in:
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 131072,
lso_max <0x10000>
15233 May 19 11:49:27 poc1 kernel: [ 1073.783242] ft_queue_data_in:
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 65536,
lso_max <0x10000>
15234 May 19 11:49:27 poc1 kernel: [ 1073.783245] ft_queue_data_in:
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 0,
lso_max <0x10000>
15235 May 19 11:49:30 poc1 kernel: [ 1076.907061] ft_queue_data_in:
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 196608,
lso_max <0x10000>
15236 May 19 11:49:30 poc1 kernel: [ 1076.907068] ft_queue_data_in:
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 131072,
lso_max <0x10000>
15237 May 19 11:49:30 poc1 kernel: [ 1076.907073] ft_queue_data_in:
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 65536,
lso_max <0x10000>
15238 May 19 11:49:30 poc1 kernel: [ 1076.907077] ft_queue_data_in:
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 0,
lso_max <0x10000>
15239 May 19 11:50:01 poc1 kernel: [ 1107.918910] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 458752,
lso_max <0x10000>
15240 May 19 11:50:01 poc1 kernel: [ 1107.918918] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 393216,
lso_max <0x10000>
15241 May 19 11:50:01 poc1 kernel: [ 1107.918922] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 327680,
lso_max <0x10000>
15242 May 19 11:50:01 poc1 kernel: [ 1107.918925] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 262144,
lso_max <0x10000>
15243 May 19 11:50:01 poc1 kernel: [ 1107.918929] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 196608,
lso_max <0x10000>
15244 May 19 11:50:01 poc1 kernel: [ 1107.918932] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 131072,
lso_max <0x10000>
15245 May 19 11:50:01 poc1 kernel: [ 1107.918936] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 65536,
lso_max <0x10000>
15246 May 19 11:50:01 poc1 kernel: [ 1107.918939] ft_queue_data_in:
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 0,
lso_max <0x10000>
15247 May 19 11:50:05 poc1 kernel: [ 1111.450900] ft_queue_data_in:
Failed to send frame ffff880c0b24ca00, xid <0xea6>, remaining 196608,
lso_max <0x10000>
15248 May 19 11:50:05 poc1 kernel: [ 1111.450908] ft_queue_data_in:
Failed to send frame ffff880c0b24ca00, xid <0xea6>, remaining 131072,
lso_max <0x10000>
15249 May 19 11:51:12 poc1 kernel: [ 1178.698434] ft_queue_data_in: 6
callbacks suppressed
15250 May 19 11:51:12 poc1 kernel: [ 1178.698440] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 458752,
lso_max <0x10000>
15251 May 19 11:51:12 poc1 kernel: [ 1178.698446] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 393216,
lso_max <0x10000>
15252 May 19 11:51:12 poc1 kernel: [ 1178.698449] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 327680,
lso_max <0x10000>
15253 May 19 11:51:12 poc1 kernel: [ 1178.698453] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 262144,
lso_max <0x10000>
15254 May 19 11:51:12 poc1 kernel: [ 1178.698456] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 196608,
lso_max <0x10000>
15255 May 19 11:51:12 poc1 kernel: [ 1178.698460] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 131072,
lso_max <0x10000>
15256 May 19 11:51:12 poc1 kernel: [ 1178.698463] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 65536,
lso_max <0x10000>
15257 May 19 11:51:12 poc1 kernel: [ 1178.698467] ft_queue_data_in:
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 0,
lso_max <0x10000>

In the third test, after above lines, some additional messages were printed:

15258 May 19 11:52:46 poc1 kernel: [ 1272.969464] BUG: soft lockup -
CPU#0 stuck for 22s! [fcoethread/0:3372]
15259 May 19 11:52:46 poc1 kernel: [ 1272.969468] Modules linked in:
fcoe libfcoe ipt_MASQUERADE xt_CHECKSUM tcm_fc libfc scsi_transport_fc
scsi_tgt target_core_pscsi target_core_file target_core_iblock
iscsi_target_mod target_core_mod 8 021q garp mrp ip6t_rpfilter
ip6t_REJECT xt_conntrack ebtable_nat ebtable_broute bridge stp llc
ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6
nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw ip6tabl
e_filter ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4
nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security
iptable_raw coretemp kvm_intel kvm crc32c_intel iTCO_wdt
iTCO_vendor_support gpio_ich microcode serio_ raw lpc_ich
i2c_i801 mfd_core ioatdma ses enclosure i7core_edac edac_core shpchp
acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd sunrpc radeon
drm_kms_helper ttm ixgbe drm igb ata_generic mdio pata_acpi ptp
pps_core i2c_algo_bit pata_j micron aacraid dca i2c_core
15260 May 19 11:52:46 poc1 kernel: [ 1272.969537] CPU: 0 PID: 3372
Comm: fcoethread/0 Not tainted 3.13.10-200.zbfcoepatch.fc20.x86_64 #1
15261 May 19 11:52:46 poc1 kernel: [ 1272.969539] Hardware name:
Supermicro X8DTN/X8DTN, BIOS 2.1c 10/28/2011
15262 May 19 11:52:46 poc1 kernel: [ 1272.969541] task:
ffff88061cb29140 ti: ffff88061e14c000 task.ti: ffff88061e14c000
15263 May 19 11:52:46 poc1 kernel: [ 1272.969543] RIP:
0010:[<ffffffff8168e834>] [<ffffffff8168e834>]
_raw_spin_lock_bh+0x34/0x40
15264 May 19 11:52:46 poc1 kernel: [ 1272.969552] RSP:
0018:ffff88061e14de10 EFLAGS: 00000282
15265 May 19 11:52:46 poc1 kernel: [ 1272.969554] RAX:
000000000000aa8f RBX: ffff880627c14580 RCX: 000000000000136f
15266 May 19 11:52:46 poc1 kernel: [ 1272.969556] RDX:
000000000000136f RSI: ffff88061cb29140 RDI: ffff880627c153fc
15267 May 19 11:52:46 poc1 kernel: [ 1272.969558] RBP:
ffff88061e14de18 R08: ffff88061e14c000 R09: 0000000000000004
15268 May 19 11:52:46 poc1 kernel: [ 1272.969560] R10:
0000000000000004 R11: 0000000000000005 R12: ffff880c09bfd800
15269 May 19 11:52:46 poc1 kernel: [ 1272.969561] R13:
ffff880627c14580 R14: 0000000000000000 R15: 0000000000000000
15270 May 19 11:52:46 poc1 kernel: [ 1272.969564] FS:
0000000000000000(0000) GS:ffff880627c00000(0000)
knlGS:0000000000000000
15271 May 19 11:52:46 poc1 kernel: [ 1272.969566] CS: 0010 DS: 0000
ES: 0000 CR0: 000000008005003b
15272 May 19 11:52:46 poc1 kernel: [ 1272.969568] CR2:
00007f3c2c851000 CR3: 0000000001c0c000 CR4: 00000000000007f0
15273 May 19 11:52:46 poc1 kernel: [ 1272.969570] Stack:
15274 May 19 11:52:46 poc1 kernel: [ 1272.969572] ffff880627c153e0
ffff88061e14dec8 ffffffffa06590ed ffff880627c14580
15275 May 19 11:52:46 poc1 kernel: [ 1272.969577] ffff880c1d00d400
0000000000000000 ffff880627c14580 ffff88061cb29140
15276 May 19 11:52:46 poc1 kernel: [ 1272.969581] ffff88061cb29140
ffff880627c153fc ffff880627c153e0 ffff88060c314dce
15277 May 19 11:52:46 poc1 kernel: [ 1272.969585] Call Trace:
15278 May 19 11:52:46 poc1 kernel: [ 1272.969592]
[<ffffffffa06590ed>] fcoe_percpu_receive_thread+0xdd/0x53c [fcoe]
15279 May 19 11:52:46 poc1 kernel: [ 1272.969597]
[<ffffffffa0659010>] ? fcoe_set_port_id+0x50/0x50 [fcoe]
15280 May 19 11:52:46 poc1 kernel: [ 1272.969603]
[<ffffffff8108f2f2>] kthread+0xd2/0xf0
15281 May 19 11:52:46 poc1 kernel: [ 1272.969607]
[<ffffffff8108f220>] ? insert_kthread_work+0x40/0x40
15282 May 19 11:52:46 poc1 kernel: [ 1272.969613]
[<ffffffff81696dbc>] ret_from_fork+0x7c/0xb0
15283 May 19 11:52:46 poc1 kernel: [ 1272.969617]
[<ffffffff8108f220>] ? insert_kthread_work+0x40/0x40
15284 May 19 11:52:46 poc1 kernel: [ 1272.969618] Code: 53 48 89 fb e8
4e 34 9e ff b8 00 00 01 00 f0 0f c1 03 89 c2 c1 ea 10 66 39 c2 75 03
5b 5d c3 0f b7 03 89 d1 66 39 d0 74 f3 f3 90 <0f> b7 03 66 39 c8 75 f6
eb e7 66 90 66 66 66 66 90 55 48 89 e5

I didn't see the previous message "unable to handle kernel NULL
pointer dereference at 0000000000000048". So it must have been fixed
by your change.

Thanks,

Jun

On Wed, May 14, 2014 at 6:57 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

Post by Jun Wu
On Wed, May 14, 2014 at 2:39 PM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

Post by Jun Wu
Hi Nicholas,
We had to roll back system from 3.14 to 3.11 due to compile issues of
our software. So I am not able to verify your fix at this point.

That is unfortunate your stuck on a now unsupported stable kernel.
There are some other libfc related fixes that have gone in during the
v3.13 timeframe, so I'd strongly recommend upgrading to at least that
stable version.
In any event, I'll be pushing that particular >= v3.13.y patch anyways,
as it's a obvious regression bugfix for percpu-ida pre-allocation.

garp mrp tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi

So before we start debugging again, please confirm that this is a
*completely* stock v3.11.10 build, and that your not building
out-of-tree target modules again.

Yes we installed official Fedora 20 iso image and then
yum install targetcli
modprobe fcoe
Kernel version is 3.11.10-301.fc20.x86_64 which is a stock kernel distribution.

So I'd still recommend >= v3.13.y in order to pick-up the other libfc
related bugfixes that have gone in since v3.11.y ran out of stable
support some months ago. I can't tell if that is related to the bug(s)
that your hitting on both initiator + target sides here, but it
definitely would not hurt.
Also, here is the updated >= v3.13.y percpu-ida pre-allocation
regression fix that will be going into v3.15-rc6 shortly. Note this is
different from the original version, so please make sure you use this
one instead.
https://git.kernel.org/cgit/linux/kernel/git/nab/target-pending.git/commit/?id=e7c36ac16b91bf09e94f82d1838f0f9f114bed08
--nab

Nicholas A. Bellinger

2014-05-20 18:03:27 UTC

Permalink

Post by Jun Wu
Hi Nicholas,
We downloaded the source of our running kernel (3.13.10-200) and
applied your percpu-ida pre-allocation regression fix, then compiled
and installed the kernel. I repeated the same test three times,
running 10 fio sessions to 10 drives on the target through fcoe vn2vn.
In the first two tests, the target machine hung with the following
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff880c0b188200, xid <0x2a5>, remaining 0,
lso_max <0x10000>
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff880c1d1df000, xid <0x305>, remaining 0,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 458752,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 393216,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 327680,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 262144,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff88060cd40800, xid <0x3cb>, remaining 0,
lso_max <0x10000>
Failed to send frame ffff880c0b24ca00, xid <0xea6>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff880c0b24ca00, xid <0xea6>, remaining 131072,
lso_max <0x10000>
15249 May 19 11:51:12 poc1 kernel: [ 1178.698434] ft_queue_data_in: 6
callbacks suppressed
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 458752,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 393216,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 327680,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 262144,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff88060ba97400, xid <0xb8a>, remaining 0,
lso_max <0x10000>

The call into lport->tt.seq_send() libfc code is failing to send
outgoing solicited data-in. From the output, note the LSO (large
segment offload aka TCP segment offload) feature has been enabled by the
underlying NIC hardware.

So in order to isolate possible issues, I'd recommend:

- Disabling hardware offloads on both initiator and target sides (LRO +
LSO) using ethtool -K
- Disabling any jumbo frames settings on either side

Is there any other non standard network and/or switch settings that are
in place..? Also, please confirm what your NIC + switch setup looks
like.

Rob & Open-FCoE folks, is there anything else to take into consideration
here..?

Post by Jun Wu
I didn't see the previous message "unable to handle kernel NULL
pointer dereference at 0000000000000048". So it must have been fixed
by your change.

Thanks for confirming that bit.

--nab

Jun Wu

2014-05-21 05:29:44 UTC

Permalink

MTU were 1500 for both initiator and target.
I used "ethtool -K p4p1 tso off" to turn off tcp segmentation offload
on all machines. Register setting after the command is shown below.

[***@poc3 jkong]# ethtool -k p4p1
Features for p4p1:
rx-checksumming: on
tx-checksumming: on
tx-checksum-ipv4: on
tx-checksum-ip-generic: off [fixed]
tx-checksum-ipv6: on
tx-checksum-fcoe-crc: on [fixed]
tx-checksum-sctp: on
scatter-gather: on
tx-scatter-gather: on
tx-scatter-gather-fraglist: off [fixed]
tcp-segmentation-offload: off
tx-tcp-segmentation: off
tx-tcp-ecn-segmentation: off [fixed]
tx-tcp6-segmentation: off
udp-fragmentation-offload: off [fixed]
generic-segmentation-offload: on
generic-receive-offload: on
large-receive-offload: off
rx-vlan-offload: on
tx-vlan-offload: on
ntuple-filters: off
receive-hashing: on
highdma: on [fixed]
rx-vlan-filter: on
vlan-challenged: off [fixed]
tx-lockless: off [fixed]
netns-local: off [fixed]
tx-gso-robust: off [fixed]
tx-fcoe-segmentation: on [fixed]
tx-gre-segmentation: off [fixed]
tx-ipip-segmentation: off [fixed]
tx-sit-segmentation: off [fixed]
tx-udp_tnl-segmentation: off [fixed]
tx-mpls-segmentation: off [fixed]
fcoe-mtu: on [fixed]
tx-nocache-copy: on
loopback: off [fixed]
rx-fcs: off [fixed]
rx-all: off
tx-vlan-stag-hw-insert: off [fixed]
rx-vlan-stag-hw-parse: off [fixed]
rx-vlan-stag-filter: off [fixed]
l2-fwd-offload: off

Info on NIC drivers

[***@poc3 jkong]# ethtool -i p4p1
driver: ixgbe
version: 3.15.1-k
firmware-version: 0x80000208
bus-info: 0000:08:00.0
supports-statistics: yes
supports-test: yes
supports-eeprom-access: yes
supports-register-dump: yes
supports-priv-flags: no

After the change, I repeated the same test and got similar failure on
target side:

[12253.032595] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 458752, lso_max <0x10000>
[12253.032605] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 393216, lso_max <0x10000>
[12253.032609] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 327680, lso_max <0x10000>
[12253.032613] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 262144, lso_max <0x10000>
[12284.299877] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 196608, lso_max <0x10000>
[12284.299885] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 131072, lso_max <0x10000>
[12284.299889] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 65536, lso_max <0x10000>
[12284.299892] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 0, lso_max <0x10000>
[12284.451810] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 458752, lso_max <0x10000>
[12284.451818] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 393216, lso_max <0x10000>
[12284.451824] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 327680, lso_max <0x10000>
[12284.451827] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 262144, lso_max <0x10000>
[12284.451831] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 196608, lso_max <0x10000>
[12284.451834] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 131072, lso_max <0x10000>
[12347.503478] ft_queue_data_in: 2 callbacks suppressed
[12347.503486] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 458752, lso_max <0x10000>
[12347.503492] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 393216, lso_max <0x10000>
[12347.503496] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 327680, lso_max <0x10000>
[12347.503517] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 262144, lso_max <0x10000>
[12378.402412] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 458752, lso_max <0x10000>
[12378.402420] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 393216, lso_max <0x10000>
[12378.402425] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 327680, lso_max <0x10000>
[12378.402428] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 262144, lso_max <0x10000>
[12378.402432] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 196608, lso_max <0x10000>
[12378.402436] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 131072, lso_max <0x10000>
[12378.402440] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 65536, lso_max <0x10000>
[12378.402444] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 0, lso_max <0x10000>
[13049.224513] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 196608, lso_max <0x10000>
[13049.224524] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 131072, lso_max <0x10000>
[13049.224528] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 65536, lso_max <0x10000>
[13049.224532] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 0, lso_max <0x10000>
[13052.511306] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 196608, lso_max <0x10000>
[13052.511313] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 131072, lso_max <0x10000>
[13052.511317] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 65536, lso_max <0x10000>
[13052.511321] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 0, lso_max <0x10000>
[13087.976748] ft_queue_data_in: Failed to send frame
ffff88031afc9c00, xid <0x96b>, remaining 458752, lso_max <0x10000>
[13087.998453] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 458752, lso_max <0x10000>
[13087.998459] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 393216, lso_max <0x10000>
[13087.998463] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 327680, lso_max <0x10000>
[13087.998467] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 262144, lso_max <0x10000>
[13087.998470] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 196608, lso_max <0x10000>
[13087.998474] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 131072, lso_max <0x10000>
[13087.998478] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 65536, lso_max <0x10000>
[13087.998482] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 0, lso_max <0x10000>
[13119.177286] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 458752, lso_max <0x10000>
[13119.177297] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 393216, lso_max <0x10000>
[13119.177302] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 327680, lso_max <0x10000>
[13119.177307] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 262144, lso_max <0x10000>
[13119.177311] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 196608, lso_max <0x10000>
[13119.177316] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 131072, lso_max <0x10000>
[13119.177321] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 65536, lso_max <0x10000>
[13119.177325] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 0, lso_max <0x10000>
[13122.335322] ------------[ cut here ]------------
[13122.335336] WARNING: CPU: 6 PID: 2165 at
include/scsi/fc_frame.h:173 fcoe_percpu_receive_thread+0x507/0x53c
[fcoe]()
[13122.335338] Modules linked in: async_memcpy async_xor xor async_tx
fcoe libfcoe tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
8021q garp mrp bridge stp llc iTCO_wdt gpio_ich iTCO_vendor_support
coretemp kvm_intel kvm crc32c_intel microcode serio_raw i2c_i801
lpc_ich mfd_core ses enclosure i7core_edac ioatdma edac_core shpchp
acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd sunrpc radeon
drm_kms_helper ttm drm ixgbe igb ata_generic mdio pata_acpi ptp
pata_jmicron pps_core i2c_algo_bit aacraid dca i2c_core [last
unloaded: vd]
[13122.335390] CPU: 6 PID: 2165 Comm: fcoethread/6 Tainted: GF
O 3.13.10-200.zbfcoepatch.fc20.x86_64 #1
[13122.335392] Hardware name: Supermicro X8DTN/X8DTN, BIOS 2.1c 10/28/2011
[13122.335394] 0000000000000009 ffff88062b04bdd0 ffffffff81687eac
0000000000000000
[13122.335400] ffff88062b04be08 ffffffff8106d4dd ffffe8ffffc41748
ffff88062a444700
[13122.335404] ffff8800b7e926e8 0000000000000002 ffff88062b04be88
ffff88062b04be18
[13122.335408] Call Trace:
[13122.335419] [<ffffffff81687eac>] dump_stack+0x45/0x56
[13122.335426] [<ffffffff8106d4dd>] warn_slowpath_common+0x7d/0xa0
[13122.335430] [<ffffffff8106d5ba>] warn_slowpath_null+0x1a/0x20
[13122.335435] [<ffffffffa0651517>]
fcoe_percpu_receive_thread+0x507/0x53c [fcoe]
[13122.335440] [<ffffffffa0651010>] ? fcoe_set_port_id+0x50/0x50 [fcoe]
[13122.335446] [<ffffffff8108f2f2>] kthread+0xd2/0xf0
[13122.335450] [<ffffffff8108f220>] ? insert_kthread_work+0x40/0x40
[13122.335458] [<ffffffff81696dbc>] ret_from_fork+0x7c/0xb0
[13122.335461] [<ffffffff8108f220>] ? insert_kthread_work+0x40/0x40
[13122.335464] ---[ end trace e4509e1053f499ac ]---

Thanks,

Jun

On Tue, May 20, 2014 at 11:03 AM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

The call into lport->tt.seq_send() libfc code is failing to send
outgoing solicited data-in. From the output, note the LSO (large
segment offload aka TCP segment offload) feature has been enabled by the
underlying NIC hardware.
- Disabling hardware offloads on both initiator and target sides (LRO +
LSO) using ethtool -K
- Disabling any jumbo frames settings on either side
Is there any other non standard network and/or switch settings that are
in place..? Also, please confirm what your NIC + switch setup looks
like.
Rob & Open-FCoE folks, is there anything else to take into consideration
here..?

Post by Jun Wu
I didn't see the previous message "unable to handle kernel NULL
pointer dereference at 0000000000000048". So it must have been fixed
by your change.

Thanks for confirming that bit.
--nab

Vasu Dev

2014-05-21 16:21:06 UTC

Permalink

Post by Jun Wu
MTU were 1500 for both initiator and target.
I used "ethtool -K p4p1 tso off" to turn off tcp segmentation offload
on all machines. Register setting after the command is shown below.
rx-checksumming: on
tx-checksumming: on
tx-checksum-ipv4: on
tx-checksum-ip-generic: off [fixed]
tx-checksum-ipv6: on
tx-checksum-fcoe-crc: on [fixed]
tx-checksum-sctp: on
scatter-gather: on
tx-scatter-gather: on
tx-scatter-gather-fraglist: off [fixed]
tcp-segmentation-offload: off
tx-tcp-segmentation: off
tx-tcp-ecn-segmentation: off [fixed]
tx-tcp6-segmentation: off
udp-fragmentation-offload: off [fixed]
generic-segmentation-offload: on
generic-receive-offload: on
large-receive-offload: off
rx-vlan-offload: on
tx-vlan-offload: on
ntuple-filters: off
receive-hashing: on
highdma: on [fixed]
rx-vlan-filter: on
vlan-challenged: off [fixed]
tx-lockless: off [fixed]
netns-local: off [fixed]
tx-gso-robust: off [fixed]
tx-fcoe-segmentation: on [fixed]
tx-gre-segmentation: off [fixed]
tx-ipip-segmentation: off [fixed]
tx-sit-segmentation: off [fixed]
tx-udp_tnl-segmentation: off [fixed]
tx-mpls-segmentation: off [fixed]
fcoe-mtu: on [fixed]
tx-nocache-copy: on
loopback: off [fixed]
rx-fcs: off [fixed]
rx-all: off
tx-vlan-stag-hw-insert: off [fixed]
rx-vlan-stag-hw-parse: off [fixed]
rx-vlan-stag-filter: off [fixed]
l2-fwd-offload: off
Info on NIC drivers
driver: ixgbe
version: 3.15.1-k
firmware-version: 0x80000208
bus-info: 0000:08:00.0
supports-statistics: yes
supports-test: yes
supports-eeprom-access: yes
supports-register-dump: yes
supports-priv-flags: no
After the change, I repeated the same test and got similar failure on
[12253.032595] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 458752, lso_max <0x10000>

It is send frame failure and to find out what caused send failure more
debug info in low level fcoe Tx path functions will be helpful, it can
be done by:-

# echo 0xFF > /sys/module/libfc/parameters/debug_logging
# echo 0x1 > /sys/module/fcoe/parameters/debug_logging

Disabling Tx offload may not help here and instead would slow down Tx,
so have them restored.

Also, are you using switch between hosts and target ? In any case you
would need DCB PFC or PAUSE enabled to avoid excessive Tx retries though
that should not cause send failure.

//Vasu

Post by Jun Wu
[12253.032605] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 393216, lso_max <0x10000>
[12253.032609] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 327680, lso_max <0x10000>
[12253.032613] ft_queue_data_in: Failed to send frame
ffff88062a638600, xid <0xa0c>, remaining 262144, lso_max <0x10000>
[12284.299877] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 196608, lso_max <0x10000>
[12284.299885] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 131072, lso_max <0x10000>
[12284.299889] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 65536, lso_max <0x10000>
[12284.299892] ft_queue_data_in: Failed to send frame
ffff8803202ec600, xid <0x3a2>, remaining 0, lso_max <0x10000>
[12284.451810] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 458752, lso_max <0x10000>
[12284.451818] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 393216, lso_max <0x10000>
[12284.451824] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 327680, lso_max <0x10000>
[12284.451827] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 262144, lso_max <0x10000>
[12284.451831] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 196608, lso_max <0x10000>
[12284.451834] ft_queue_data_in: Failed to send frame
ffff88061deb1400, xid <0xecf>, remaining 131072, lso_max <0x10000>
[12347.503478] ft_queue_data_in: 2 callbacks suppressed
[12347.503486] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 458752, lso_max <0x10000>
[12347.503492] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 393216, lso_max <0x10000>
[12347.503496] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 327680, lso_max <0x10000>
[12347.503517] ft_queue_data_in: Failed to send frame
ffff8806142bc800, xid <0xb4f>, remaining 262144, lso_max <0x10000>
[12378.402412] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 458752, lso_max <0x10000>
[12378.402420] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 393216, lso_max <0x10000>
[12378.402425] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 327680, lso_max <0x10000>
[12378.402428] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 262144, lso_max <0x10000>
[12378.402432] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 196608, lso_max <0x10000>
[12378.402436] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 131072, lso_max <0x10000>
[12378.402440] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 65536, lso_max <0x10000>
[12378.402444] ft_queue_data_in: Failed to send frame
ffff88062ddeac00, xid <0x6a5>, remaining 0, lso_max <0x10000>
[13049.224513] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 196608, lso_max <0x10000>
[13049.224524] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 131072, lso_max <0x10000>
[13049.224528] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 65536, lso_max <0x10000>
[13049.224532] ft_queue_data_in: Failed to send frame
ffff880614588c00, xid <0xd2f>, remaining 0, lso_max <0x10000>
[13052.511306] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 196608, lso_max <0x10000>
[13052.511313] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 131072, lso_max <0x10000>
[13052.511317] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 65536, lso_max <0x10000>
[13052.511321] ft_queue_data_in: Failed to send frame
ffff88062d49f000, xid <0x8ae>, remaining 0, lso_max <0x10000>
[13087.976748] ft_queue_data_in: Failed to send frame
ffff88031afc9c00, xid <0x96b>, remaining 458752, lso_max <0x10000>
[13087.998453] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 458752, lso_max <0x10000>
[13087.998459] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 393216, lso_max <0x10000>
[13087.998463] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 327680, lso_max <0x10000>
[13087.998467] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 262144, lso_max <0x10000>
[13087.998470] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 196608, lso_max <0x10000>
[13087.998474] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 131072, lso_max <0x10000>
[13087.998478] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 65536, lso_max <0x10000>
[13087.998482] ft_queue_data_in: Failed to send frame
ffff88032c881200, xid <0xb23>, remaining 0, lso_max <0x10000>
[13119.177286] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 458752, lso_max <0x10000>
[13119.177297] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 393216, lso_max <0x10000>
[13119.177302] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 327680, lso_max <0x10000>
[13119.177307] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 262144, lso_max <0x10000>
[13119.177311] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 196608, lso_max <0x10000>
[13119.177316] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 131072, lso_max <0x10000>
[13119.177321] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 65536, lso_max <0x10000>
[13119.177325] ft_queue_data_in: Failed to send frame
ffff88062dff7400, xid <0xfcf>, remaining 0, lso_max <0x10000>
[13122.335322] ------------[ cut here ]------------
[13122.335336] WARNING: CPU: 6 PID: 2165 at
include/scsi/fc_frame.h:173 fcoe_percpu_receive_thread+0x507/0x53c
[fcoe]()
[13122.335338] Modules linked in: async_memcpy async_xor xor async_tx
fcoe libfcoe tcm_fc libfc scsi_transport_fc scsi_tgt target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
8021q garp mrp bridge stp llc iTCO_wdt gpio_ich iTCO_vendor_support
coretemp kvm_intel kvm crc32c_intel microcode serio_raw i2c_i801
lpc_ich mfd_core ses enclosure i7core_edac ioatdma edac_core shpchp
acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd sunrpc radeon
drm_kms_helper ttm drm ixgbe igb ata_generic mdio pata_acpi ptp
pata_jmicron pps_core i2c_algo_bit aacraid dca i2c_core [last
unloaded: vd]
[13122.335390] CPU: 6 PID: 2165 Comm: fcoethread/6 Tainted: GF
O 3.13.10-200.zbfcoepatch.fc20.x86_64 #1
[13122.335392] Hardware name: Supermicro X8DTN/X8DTN, BIOS 2.1c 10/28/2011
[13122.335394] 0000000000000009 ffff88062b04bdd0 ffffffff81687eac
0000000000000000
[13122.335400] ffff88062b04be08 ffffffff8106d4dd ffffe8ffffc41748
ffff88062a444700
[13122.335404] ffff8800b7e926e8 0000000000000002 ffff88062b04be88
ffff88062b04be18
[13122.335419] [<ffffffff81687eac>] dump_stack+0x45/0x56
[13122.335426] [<ffffffff8106d4dd>] warn_slowpath_common+0x7d/0xa0
[13122.335430] [<ffffffff8106d5ba>] warn_slowpath_null+0x1a/0x20
[13122.335435] [<ffffffffa0651517>]
fcoe_percpu_receive_thread+0x507/0x53c [fcoe]
[13122.335440] [<ffffffffa0651010>] ? fcoe_set_port_id+0x50/0x50 [fcoe]
[13122.335446] [<ffffffff8108f2f2>] kthread+0xd2/0xf0
[13122.335450] [<ffffffff8108f220>] ? insert_kthread_work+0x40/0x40
[13122.335458] [<ffffffff81696dbc>] ret_from_fork+0x7c/0xb0
[13122.335461] [<ffffffff8108f220>] ? insert_kthread_work+0x40/0x40
[13122.335464] ---[ end trace e4509e1053f499ac ]---
Thanks,
Jun
On Tue, May 20, 2014 at 11:03 AM, Nicholas A. Bellinger

Post by Nicholas A. Bellinger

The call into lport->tt.seq_send() libfc code is failing to send
outgoing solicited data-in. From the output, note the LSO (large
segment offload aka TCP segment offload) feature has been enabled by the
underlying NIC hardware.
- Disabling hardware offloads on both initiator and target sides (LRO +
LSO) using ethtool -K
- Disabling any jumbo frames settings on either side
Is there any other non standard network and/or switch settings that are
in place..? Also, please confirm what your NIC + switch setup looks
like.
Rob & Open-FCoE folks, is there anything else to take into consideration
here..?

Post by Jun Wu
I didn't see the previous message "unable to handle kernel NULL
pointer dereference at 0000000000000048". So it must have been fixed
by your change.

Thanks for confirming that bit.
--nab

_______________________________________________
fcoe-devel mailing list
http://lists.open-fcoe.org/mailman/listinfo/fcoe-devel

Jun Wu

2014-05-21 21:03:40 UTC

Permalink

I enabled the Tx offload and set the debug_loggings as suggested. A
few minutes run generated a 1.5GB messages file.

The file has repeated patterns of the following:

18630713 May 21 11:01:53 poc2 kernel: [ 1528.182334] host7: xid b48:
f_ctl 800000 seq 1
18630714 May 21 11:01:53 poc2 kernel: [ 1528.182345] host7: xid b48:
f_ctl 880008 seq 2
18630715 May 21 11:01:53 poc2 kernel: [ 1528.182601] host7: xid 38e:
f_ctl 800000 seq 1
18630716 May 21 11:01:53 poc2 kernel: [ 1528.182621] host7: xid 38e:
f_ctl 880008 seq 2
18630717 May 21 11:01:53 poc2 kernel: [ 1528.182771] host7: xid 74a:
f_ctl 800000 seq 1
18630718 May 21 11:01:53 poc2 kernel: [ 1528.182785] host7: xid 74a:
f_ctl 880008 seq 2
18630719 May 21 11:01:53 poc2 kernel: [ 1528.183161] host7: xid e4f:
f_ctl 800000 seq 1
18630720 May 21 11:01:53 poc2 kernel: [ 1528.183181] host7: xid e4f:
f_ctl 880008 seq 2
18630721 May 21 11:01:53 poc2 kernel: [ 1528.184285] host7: xid 666:
f_ctl 800000 seq 1
18630722 May 21 11:01:53 poc2 kernel: [ 1528.184301] host7: xid 666:
f_ctl 880008 seq 2
18630723 May 21 11:01:53 poc2 kernel: [ 1528.184550] host7: xid c20:
f_ctl 800000 seq 1
18630724 May 21 11:01:53 poc2 kernel: [ 1528.184589] host7: xid c20:
f_ctl 880008 seq 2
18630725 May 21 11:01:53 poc2 kernel: [ 1528.185198] host7: xid 607:
f_ctl 800000 seq 1
18630726 May 21 11:01:53 poc2 kernel: [ 1528.185213] host7: xid 607:
f_ctl 880008 seq 2
18630727 May 21 11:01:53 poc2 kernel: [ 1528.185659] host7: xid 925:
f_ctl 800000 seq 1
18630728 May 21 11:01:53 poc2 kernel: [ 1528.185662] host7: xid b48:
f_ctl 800000 seq 1
18630729 May 21 11:01:53 poc2 kernel: [ 1528.185672] host7: xid b48:
f_ctl 880008 seq 2
18630730 May 21 11:01:53 poc2 kernel: [ 1528.185680] host7: xid 925:
f_ctl 880008 seq 2
18630731 May 21 11:01:53 poc2 kernel: [ 1528.185751] host7: xid b61:
f_ctl 800000 seq 1
18630732 May 21 11:01:53 poc2 kernel: [ 1528.185765] host7: xid b61:
f_ctl 880008 seq 2
18630733 May 21 11:01:53 poc2 kernel: [ 1528.186413] host7: xid 829:
f_ctl 800000 seq 1
18630734 May 21 11:01:53 poc2 kernel: [ 1528.186425] host7: xid 829:
f_ctl 880008 seq 2
18630735 May 21 11:01:53 poc2 kernel: [ 1528.186785] host7: xid 6e4:
f_ctl 800000 seq 1
18630736 May 21 11:01:53 poc2 kernel: [ 1528.186817] host7: xid 6e4:
f_ctl 880008 seq 2
18630737 May 21 11:01:53 poc2 kernel: [ 1528.186932] host7: xid dab:
f_ctl 800000 seq 1
18630738 May 21 11:01:53 poc2 kernel: [ 1528.186946] host7: xid dab:
f_ctl 880008 seq 2
18630739 May 21 11:01:53 poc2 kernel: [ 1528.187907] host7: xid 8ac:
f_ctl 800000 seq 1
18630740 May 21 11:01:53 poc2 kernel: [ 1528.187920] host7: xid 8ac:
f_ctl 880008 seq 2
18630741 May 21 11:01:53 poc2 kernel: [ 1528.188656] host7: xid 38e:
f_ctl 800000 seq 1
18630742 May 21 11:01:53 poc2 kernel: [ 1528.188675] host7: xid 38e:
f_ctl 880008 seq 2
18630743 May 21 11:01:53 poc2 kernel: [ 1528.188889] host7: xid b61:
f_ctl 800000 seq 1
18630744 May 21 11:01:53 poc2 kernel: [ 1528.188899] host7: xid b61:
f_ctl 880008 seq 2
18630745 May 21 11:01:53 poc2 kernel: [ 1528.189281] host7: xid 88d:
f_ctl 800000 seq 1
18630746 May 21 11:01:53 poc2 kernel: [ 1528.189301] host7: xid 88d:
f_ctl 880008 seq 2
18630747 May 21 11:01:53 poc2 kernel: [ 1528.189378] host7: xid c20:
f_ctl 800000 seq 1
18630748 May 21 11:01:53 poc2 kernel: [ 1528.189392] host7: xid c20:
f_ctl 880008 seq 2
18630749 May 21 11:01:53 poc2 kernel: [ 1528.189836] host7: xid 862:
f_ctl 800000 seq 1
18630750 May 21 11:01:53 poc2 kernel: [ 1528.189850] host7: xid 862:
f_ctl 880008 seq 2
18630751 May 21 11:01:53 poc2 kernel: [ 1528.191740] host7: xid 6e4:
Exchange timer armed : 0 msecs
18630752 May 21 11:01:53 poc2 kernel: [ 1528.191747] host7: xid 6e4:
f_ctl 800000 seq 1
18630753 May 21 11:01:53 poc2 kernel: [ 1528.191756] host7: xid 6e4:
f_ctl 800000 seq 2
18630754 May 21 11:01:53 poc2 kernel: [ 1528.191763] host7: xid 6e4:
Exchange timed out
18630755 May 21 11:01:53 poc2 kernel: [ 1528.191777] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 458752,
lso_max <0x10000>
18630756 May 21 11:01:53 poc2 kernel: [ 1528.191782] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 393216,
lso_max <0x10000>
18630757 May 21 11:01:53 poc2 kernel: [ 1528.191786] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 327680,
lso_max <0x10000>
18630758 May 21 11:01:53 poc2 kernel: [ 1528.191790] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 262144,
lso_max <0x10000>
18630759 May 21 11:01:53 poc2 kernel: [ 1528.191794] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 196608,
lso_max <0x10000>
18630760 May 21 11:01:53 poc2 kernel: [ 1528.191798] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 131072,
lso_max <0x10000>
18630761 May 21 11:01:53 poc2 kernel: [ 1528.191801] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 65536,
lso_max <0x10000>
18630762 May 21 11:01:53 poc2 kernel: [ 1528.191805] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 0,
lso_max <0x10000>
18630763 May 21 11:01:53 poc2 kernel: [ 1528.192163] host7: xid b48:
f_ctl 800000 seq 1
18630764 May 21 11:01:53 poc2 kernel: [ 1528.192166] host7: xid 607:
f_ctl 800000 seq 1
18630765 May 21 11:01:53 poc2 kernel: [ 1528.192176] host7: xid 607:
f_ctl 880008 seq 2
18630766 May 21 11:01:53 poc2 kernel: [ 1528.192180] host7: xid b48:
f_ctl 880008 seq 2
18630767 May 21 11:01:53 poc2 kernel: [ 1528.192266] host7: xid 666:
f_ctl 800000 seq 1

Above is the first time ft_queue_data_in message shows up in the file.
Here is another instance:

18631537 May 21 11:01:53 poc2 kernel: [ 1528.333876] host7: xid 74a:
f_ctl 800000 seq 1
18631538 May 21 11:01:53 poc2 kernel: [ 1528.333893] host7: xid 74a:
f_ctl 880008 seq 2
18631539 May 21 11:01:53 poc2 kernel: [ 1528.334816] host7: xid c20:
f_ctl 800000 seq 1
18631540 May 21 11:01:53 poc2 kernel: [ 1528.334834] host7: xid c20:
f_ctl 880008 seq 2
18631541 May 21 11:01:53 poc2 kernel: [ 1528.334847] host7: xid b81:
f_ctl 800000 seq 1
18631542 May 21 11:01:53 poc2 kernel: [ 1528.334858] host7: xid 983:
f_ctl 800000 seq 1
18631543 May 21 11:01:53 poc2 kernel: [ 1528.334864] host7: xid b81:
f_ctl 880008 seq 2
18631544 May 21 11:01:53 poc2 kernel: [ 1528.334881] host7: xid 983:
f_ctl 880008 seq 2
18631545 May 21 11:01:53 poc2 kernel: [ 1528.334972] host7: xid 686:
f_ctl 800000 seq 1
18631546 May 21 11:01:53 poc2 kernel: [ 1528.334985] host7: xid 686:
f_ctl 880008 seq 2
18631547 May 21 11:01:53 poc2 kernel: [ 1528.335036] host7: xid 704:
f_ctl 800000 seq 1
18631548 May 21 11:01:53 poc2 kernel: [ 1528.335052] host7: xid 704:
f_ctl 880008 seq 2
18631549 May 21 11:01:53 poc2 kernel: [ 1528.335078] host7: xid 627:
f_ctl 800000 seq 1
18631550 May 21 11:01:53 poc2 kernel: [ 1528.335088] host7: xid 627:
f_ctl 880008 seq 2
18631551 May 21 11:01:53 poc2 kernel: [ 1528.335202] host7: xid b48:
f_ctl 800000 seq 1
18631552 May 21 11:01:53 poc2 kernel: [ 1528.335214] host7: xid b48:
f_ctl 880008 seq 2
18631553 May 21 11:01:53 poc2 kernel: [ 1528.335381] host7: xid 74a:
Exchange timer armed : 0 msecs
18631554 May 21 11:01:53 poc2 kernel: [ 1528.335386] host7: xid 74a:
f_ctl 800000 seq 1
18631555 May 21 11:01:53 poc2 kernel: [ 1528.335388] host7: xid 74a:
Exchange timed out
18631556 May 21 11:01:53 poc2 kernel: [ 1528.335672] host7: xid 869:
f_ctl 800000 seq 1
18631557 May 21 11:01:53 poc2 kernel: [ 1528.335688] host7: xid 869:
f_ctl 880008 seq 2
18631558 May 21 11:01:53 poc2 kernel: [ 1528.336213] host7: xid 965:
f_ctl 800000 seq 1
18631559 May 21 11:01:53 poc2 kernel: [ 1528.336232] host7: xid 965:
f_ctl 880008 seq 2
18631560 May 21 11:01:53 poc2 kernel: [ 1528.336477] host7: xid 74a:
f_ctl 800000 seq 2
18631561 May 21 11:01:53 poc2 kernel: [ 1528.336482] ft_queue_data_in:
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 196608,
lso_max <0x10000>
18631562 May 21 11:01:53 poc2 kernel: [ 1528.336486] ft_queue_data_in:
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 131072,
lso_max <0x10000>
18631563 May 21 11:01:53 poc2 kernel: [ 1528.336489] host7: xid 74a:
f_ctl 800000 seq 3
18631564 May 21 11:01:53 poc2 kernel: [ 1528.337645] host7: xid 86d:
f_ctl 800000 seq 1
18631565 May 21 11:01:53 poc2 kernel: [ 1528.337759] host7: xid 86d:
f_ctl 880008 seq 2
18631566 May 21 11:01:53 poc2 kernel: [ 1528.337827] host7: xid 44e:
f_ctl 800000 seq 1
18631567 May 21 11:01:53 poc2 kernel: [ 1528.337846] host7: xid 44e:
f_ctl 880008 seq 2
18631568 May 21 11:01:53 poc2 kernel: [ 1528.340521] host7: xid 8c2:
Exchange timer armed : 0 msecs
18631569 May 21 11:01:53 poc2 kernel: [ 1528.340526] host7: xid 8c2:
f_ctl 800000 seq 1
18631570 May 21 11:01:53 poc2 kernel: [ 1528.340667] host7: xid 8c2:
Exchange timed out
18631571 May 21 11:01:53 poc2 kernel: [ 1528.341064] host7: xid 983:
f_ctl 800000 seq 1
18631572 May 21 11:01:53 poc2 kernel: [ 1528.341087] host7: xid 983:
f_ctl 880008 seq 2
18631573 May 21 11:01:53 poc2 kernel: [ 1528.341286] host7: xid b48:
f_ctl 800000 seq 1
18631574 May 21 11:01:53 poc2 kernel: [ 1528.341306] host7: xid b48:
f_ctl 880008 seq 2
18631575 May 21 11:01:53 poc2 kernel: [ 1528.341522] host7: xid 869:
Exchange timer armed : 0 msecs
18631576 May 21 11:01:53 poc2 kernel: [ 1528.341528] host7: xid 869:
f_ctl 800000 seq 1
18631577 May 21 11:01:53 poc2 kernel: [ 1528.341539] host7: xid 869:
Exchange timed out
18631578 May 21 11:01:53 poc2 kernel: [ 1528.341966] host7: xid 965:
f_ctl 800000 seq 1
18631579 May 21 11:01:53 poc2 kernel: [ 1528.341979] host7: xid 965:
f_ctl 880008 seq 2
18631580 May 21 11:01:53 poc2 kernel: [ 1528.342450] host7: xid 627:
f_ctl 800000 seq 1
18631581 May 21 11:01:53 poc2 kernel: [ 1528.342467] host7: xid 627:
f_ctl 880008 seq 2
18631582 May 21 11:01:53 poc2 kernel: [ 1528.342945] host7: xid 70a:
f_ctl 800000 seq 1
18631583 May 21 11:01:53 poc2 kernel: [ 1528.342959] host7: xid 70a:
f_ctl 880008 seq 2

After stripping out the repeated "host7: xid xxx: f_ctl 800000 seq
x" messages, we have:

18630507:May 21 11:01:53 poc2 kernel: [ 1528.148314] host7: xid d6b:
Exchange timer armed : 0 msecs
18630509:May 21 11:01:53 poc2 kernel: [ 1528.148357] host7: xid d6b:
Exchange timed out
18630642:May 21 11:01:53 poc2 kernel: [ 1528.169143] host7: xid 88c:
Exchange timer armed : 0 msecs
18630644:May 21 11:01:53 poc2 kernel: [ 1528.169197] host7: xid 88c:
Exchange timed out
18630751:May 21 11:01:53 poc2 kernel: [ 1528.191740] host7: xid 6e4:
Exchange timer armed : 0 msecs
18630754:May 21 11:01:53 poc2 kernel: [ 1528.191763] host7: xid 6e4:
Exchange timed out
18630755:May 21 11:01:53 poc2 kernel: [ 1528.191777] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 458752,
lso_max <0x10000>
18630756:May 21 11:01:53 poc2 kernel: [ 1528.191782] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 393216,
lso_max <0x10000>
18630757:May 21 11:01:53 poc2 kernel: [ 1528.191786] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 327680,
lso_max <0x10000>
18630758:May 21 11:01:53 poc2 kernel: [ 1528.191790] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 262144,
lso_max <0x10000>
18630759:May 21 11:01:53 poc2 kernel: [ 1528.191794] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 196608,
lso_max <0x10000>
18630760:May 21 11:01:53 poc2 kernel: [ 1528.191798] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 131072,
lso_max <0x10000>
18630761:May 21 11:01:53 poc2 kernel: [ 1528.191801] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 65536,
lso_max <0x10000>
18630762:May 21 11:01:53 poc2 kernel: [ 1528.191805] ft_queue_data_in:
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 0,
lso_max <0x10000>
18630777:May 21 11:01:53 poc2 kernel: [ 1528.195937] host7: xid 666:
Exchange timer armed : 0 msecs
18630779:May 21 11:01:53 poc2 kernel: [ 1528.195983] host7: xid 666:
Exchange timed out
18630780:May 21 11:01:53 poc2 kernel: [ 1528.196336] host7: xid 862:
Exchange timer armed : 0 msecs
18630782:May 21 11:01:53 poc2 kernel: [ 1528.196348] host7: xid 862:
Exchange timed out
18630879:May 21 11:01:53 poc2 kernel: [ 1528.211080] host7: xid b61:
Exchange timer armed : 0 msecs
18630881:May 21 11:01:53 poc2 kernel: [ 1528.211137] host7: xid b61:
Exchange timed out
18630898:May 21 11:01:53 poc2 kernel: [ 1528.214253] host7: xid 38e:
Exchange timer armed : 0 msecs
18630900:May 21 11:01:53 poc2 kernel: [ 1528.214284] host7: xid 38e:
Exchange timed out
18631007:May 21 11:01:53 poc2 kernel: [ 1528.236137] host7: xid 88d:
Exchange timer armed : 0 msecs
18631009:May 21 11:01:53 poc2 kernel: [ 1528.236172] host7: xid 88d:
Exchange timed out
18631176:May 21 11:01:53 poc2 kernel: [ 1528.264223] host7: xid 607:
Exchange timer armed : 0 msecs
18631178:May 21 11:01:53 poc2 kernel: [ 1528.264239] host7: xid 607:
Exchange timed out
18631185:May 21 11:01:53 poc2 kernel: [ 1528.266310] host7: xid 82d:
Exchange timer armed : 0 msecs
18631187:May 21 11:01:53 poc2 kernel: [ 1528.266351] host7: xid 82d:
Exchange timed out
18631226:May 21 11:01:53 poc2 kernel: [ 1528.275452] host7: xid 8a2:
Exchange timer armed : 0 msecs
18631228:May 21 11:01:53 poc2 kernel: [ 1528.275463] host7: xid 8a2:
Exchange timed out
18631553:May 21 11:01:53 poc2 kernel: [ 1528.335381] host7: xid 74a:
Exchange timer armed : 0 msecs
18631555:May 21 11:01:53 poc2 kernel: [ 1528.335388] host7: xid 74a:
Exchange timed out
18631561:May 21 11:01:53 poc2 kernel: [ 1528.336482] ft_queue_data_in:
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 196608,
lso_max <0x10000>
18631562:May 21 11:01:53 poc2 kernel: [ 1528.336486] ft_queue_data_in:
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 131072,
lso_max <0x10000>
18631568:May 21 11:01:53 poc2 kernel: [ 1528.340521] host7: xid 8c2:
Exchange timer armed : 0 msecs
18631570:May 21 11:01:53 poc2 kernel: [ 1528.340667] host7: xid 8c2:
Exchange timed out
18631575:May 21 11:01:53 poc2 kernel: [ 1528.341522] host7: xid 869:
Exchange timer armed : 0 msecs
18631577:May 21 11:01:53 poc2 kernel: [ 1528.341539] host7: xid 869:
Exchange timed out
18631660:May 21 11:01:53 poc2 kernel: [ 1528.356897] host7: xid e4f:
Exchange timer armed : 0 msecs
18631662:May 21 11:01:53 poc2 kernel: [ 1528.356975] host7: xid e4f:
Exchange timed out
18631825:May 21 11:01:53 poc2 kernel: [ 1528.398431] host7: xid 965:
Exchange timer armed : 0 msecs
18631827:May 21 11:01:53 poc2 kernel: [ 1528.398509] host7: xid 965:
Exchange timed out
18631844:May 21 11:01:53 poc2 kernel: [ 1528.401772] host7: xid 44e:
Exchange timer armed : 0 msecs
18631846:May 21 11:01:53 poc2 kernel: [ 1528.401850] host7: xid 44e:
Exchange timed out
18631859:May 21 11:01:53 poc2 kernel: [ 1528.404996] host7: xid 704:
Exchange timer armed : 0 msecs
18631861:May 21 11:01:53 poc2 kernel: [ 1528.405043] host7: xid 704:
Exchange timed out
18631876:May 21 11:01:53 poc2 kernel: [ 1528.412608] host7: xid 86d:
Exchange timer armed : 0 msecs
18631878:May 21 11:01:53 poc2 kernel: [ 1528.412619] host7: xid 86d:
Exchange timed out
18631919:May 21 11:01:53 poc2 kernel: [ 1528.431939] host7: xid 686:
Exchange timer armed : 0 msecs
18631921:May 21 11:01:53 poc2 kernel: [ 1528.432000] host7: xid 686:
Exchange timed out
18631950:May 21 11:01:53 poc2 kernel: [ 1528.441542] host7: xid def:
Exchange timer armed : 0 msecs
18631952:May 21 11:01:53 poc2 kernel: [ 1528.441573] host7: xid def:
Exchange timed out
18631967:May 21 11:01:53 poc2 kernel: [ 1528.447848] host7: xid 3ce:
Exchange timer armed : 0 msecs
18631969:May 21 11:01:53 poc2 kernel: [ 1528.447863] host7: xid 3ce:
Exchange timed out
18632008:May 21 11:01:53 poc2 kernel: [ 1528.453868] host7: xid 627:
Exchange timer armed : 0 msecs
18632010:May 21 11:01:53 poc2 kernel: [ 1528.453879] host7: xid 627:
Exchange timed out
18655343:May 21 11:01:56 poc2 kernel: [ 1531.747863] host7: xid 48e:
Exchange timer armed : 0 msecs
18655345:May 21 11:01:56 poc2 kernel: [ 1531.747879] host7: xid 48e:
Exchange timed out
18655414:May 21 11:01:56 poc2 kernel: [ 1531.758175] host7: xid 667:
Exchange timer armed : 0 msecs
18655416:May 21 11:01:56 poc2 kernel: [ 1531.758204] host7: xid 667:
Exchange timed out
18655533:May 21 11:01:56 poc2 kernel: [ 1531.776753] host7: xid 6c6:
Exchange timer armed : 0 msecs
18655535:May 21 11:01:56 poc2 kernel: [ 1531.776765] host7: xid 6c6:
Exchange timed out
18655832:May 21 11:01:56 poc2 kernel: [ 1531.818184] host7: xid 647:
Exchange timer armed : 0 msecs
18655834:May 21 11:01:56 poc2 kernel: [ 1531.818227] host7: xid 647:
Exchange timed out
18655893:May 21 11:01:56 poc2 kernel: [ 1531.825287] host7: xid 46e:
Exchange timer armed : 0 msecs
18655895:May 21 11:01:56 poc2 kernel: [ 1531.825344] host7: xid 46e:
Exchange timed out
18656116:May 21 11:01:56 poc2 kernel: [ 1531.863739] host7: xid dab:
Exchange timer armed : 0 msecs
18656118:May 21 11:01:56 poc2 kernel: [ 1531.863765] host7: xid dab:
Exchange timed out
18656124:May 21 11:01:56 poc2 kernel: [ 1531.865740] host7: xid 8ac:
Exchange timer armed : 0 msecs
18656129:May 21 11:01:56 poc2 kernel: [ 1531.865800] host7: xid 8ac:
Exchange timed out
18656130:May 21 11:01:56 poc2 kernel: [ 1531.865813] host7: xid 5e7:
Exchange timer armed : 2000 msecs
18656267:May 21 11:01:56 poc2 kernel: [ 1531.891151] host7: xid e6f:
Exchange timer armed : 0 msecs
18656269:May 21 11:01:56 poc2 kernel: [ 1531.891177] host7: xid e6f:
Exchange timed out
18656320:May 21 11:01:56 poc2 kernel: [ 1531.899587] host7: xid 82c:
Exchange timer armed : 0 msecs
18656322:May 21 11:01:56 poc2 kernel: [ 1531.899606] host7: xid 82c:
Exchange timed out
18656355:May 21 11:01:56 poc2 kernel: [ 1531.906904] host7: xid 646:
Exchange timer armed : 0 msecs
18656357:May 21 11:01:56 poc2 kernel: [ 1531.906952] host7: xid 646:
Exchange timed out
18656608:May 21 11:01:56 poc2 kernel: [ 1531.960276] host7: xid 945:
Exchange timer armed : 0 msecs
18656610:May 21 11:01:56 poc2 kernel: [ 1531.960293] host7: xid 945:
Exchange timed out
18656613:May 21 11:01:56 poc2 kernel: [ 1531.960985] host7: xid 724:
Exchange timer armed : 0 msecs
18656615:May 21 11:01:56 poc2 kernel: [ 1531.961002] host7: xid 724:
Exchange timed out
18656634:May 21 11:01:56 poc2 kernel: [ 1531.968643] host7: xid 8ad:
Exchange timer armed : 0 msecs
18656636:May 21 11:01:56 poc2 kernel: [ 1531.968660] host7: xid 8ad:
Exchange timed out
18656641:May 21 11:01:56 poc2 kernel: [ 1531.974843] host7: xid 5e7:
Exchange timer armed : 10000 msecs
18656642:May 21 11:01:56 poc2 kernel: [ 1531.974848] host7: xid 5e7:
f_ctl 90000 seq 1
18656655:May 21 11:01:56 poc2 kernel: [ 1531.983896] host7: xid 687:
Exchange timer armed : 0 msecs
18656657:May 21 11:01:56 poc2 kernel: [ 1531.983912] host7: xid 687:
Exchange timed out
18656746:May 21 11:01:56 poc2 kernel: [ 1532.011935] host7: xid 5e7:
Exchange timer armed : 10000 msecs
18656747:May 21 11:01:56 poc2 kernel: [ 1532.011940] host7: xid 5e7:
f_ctl 90000 seq 2
18669030:May 21 11:01:58 poc2 kernel: [ 1533.870105] host7: xid 5e7:
Exchange timed out
18841592:May 21 11:02:27 poc2 kernel: [ 1562.646991] host7: xid 90d:
Exchange timer armed : 0 msecs
18841595:May 21 11:02:27 poc2 kernel: [ 1562.647066] host7: xid 90d:
Exchange timed out
18842498:May 21 11:02:27 poc2 kernel: [ 1562.795804] host7: xid 8ac:
Exchange timer armed : 0 msecs
18842500:May 21 11:02:27 poc2 kernel: [ 1562.795820] host7: xid 8ac:
Exchange timed out
18842547:May 21 11:02:27 poc2 kernel: [ 1562.805335] host7: xid 94c:
Exchange timer armed : 0 msecs
18842549:May 21 11:02:27 poc2 kernel: [ 1562.805351] host7: xid 94c:
Exchange timed out
18842584:May 21 11:02:27 poc2 kernel: [ 1562.810550] host7: xid f2f:
Exchange timer armed : 0 msecs
18842586:May 21 11:02:27 poc2 kernel: [ 1562.810605] host7: xid f2f:
Exchange timed out
18842593:May 21 11:02:27 poc2 kernel: [ 1562.811735] host7: xid 7e6:
Exchange timer armed : 0 msecs
18842595:May 21 11:02:27 poc2 kernel: [ 1562.811795] host7: xid 7e6:
Exchange timed out
18842740:May 21 11:02:27 poc2 kernel: [ 1562.837943] host7: xid e8b:
Exchange timer armed : 0 msecs
18842742:May 21 11:02:27 poc2 kernel: [ 1562.837966] host7: xid 8cd:
Exchange timer armed : 0 msecs
18842743:May 21 11:02:27 poc2 kernel: [ 1562.837968] host7: xid e8b:
Exchange timed out
18842745:May 21 11:02:27 poc2 kernel: [ 1562.838038] host7: xid 8cd:
Exchange timed out
18842872:May 21 11:02:27 poc2 kernel: [ 1562.863661] host7: xid 824:
Exchange timer armed : 0 msecs
18842874:May 21 11:02:27 poc2 kernel: [ 1562.863674] host7: xid 824:
Exchange timed out
18842951:May 21 11:02:27 poc2 kernel: [ 1562.876390] host7: xid 766:
Exchange timer armed : 0 msecs
18842953:May 21 11:02:27 poc2 kernel: [ 1562.876405] host7: xid 766:
Exchange timed out
18842960:May 21 11:02:27 poc2 kernel: [ 1562.878444] host7: xid ca8:
Exchange timer armed : 0 msecs
18842962:May 21 11:02:27 poc2 kernel: [ 1562.878470] host7: xid ca8:
Exchange timed out
18843025:May 21 11:02:27 poc2 kernel: [ 1562.892335] host7: xid a25:
Exchange timer armed : 0 msecs
18843027:May 21 11:02:27 poc2 kernel: [ 1562.892400] host7: xid a25:
Exchange timed out
18843092:May 21 11:02:27 poc2 kernel: [ 1562.905946] host7: xid be1:
Exchange timer armed : 0 msecs
18843094:May 21 11:02:27 poc2 kernel: [ 1562.905971] host7: xid be1:
Exchange timed out
18843239:May 21 11:02:27 poc2 kernel: [ 1562.934586] host7: xid 52e:
Exchange timer armed : 0 msecs
18843241:May 21 11:02:27 poc2 kernel: [ 1562.934601] host7: xid 52e:
Exchange timed out
18843264:May 21 11:02:27 poc2 kernel: [ 1562.938141] host7: xid bc8:
Exchange timer armed : 0 msecs
18843266:May 21 11:02:27 poc2 kernel: [ 1562.938164] host7: xid bc8:
Exchange timed out
18843353:May 21 11:02:27 poc2 kernel: [ 1562.959150] host7: xid c21:
Exchange timer armed : 0 msecs
18843356:May 21 11:02:27 poc2 kernel: [ 1562.959194] ft_queue_data_in:
10 callbacks suppressed
18843357:May 21 11:02:27 poc2 kernel: [ 1562.959196] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 458752,
lso_max <0x10000>
18843358:May 21 11:02:27 poc2 kernel: [ 1562.959199] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 393216,
lso_max <0x10000>
18843359:May 21 11:02:27 poc2 kernel: [ 1562.959202] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 327680,
lso_max <0x10000>
18843360:May 21 11:02:27 poc2 kernel: [ 1562.959204] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 262144,
lso_max <0x10000>
18843361:May 21 11:02:27 poc2 kernel: [ 1562.959208] host7: xid c21:
Exchange timed out
18843362:May 21 11:02:27 poc2 kernel: [ 1562.959209] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 196608,
lso_max <0x10000>
18843363:May 21 11:02:27 poc2 kernel: [ 1562.959212] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 131072,
lso_max <0x10000>
18843364:May 21 11:02:27 poc2 kernel: [ 1562.959214] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 65536,
lso_max <0x10000>
18843365:May 21 11:02:27 poc2 kernel: [ 1562.959217] ft_queue_data_in:
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 0,
lso_max <0x10000>
18843416:May 21 11:02:27 poc2 kernel: [ 1562.968554] host7: xid f4f:
Exchange timer armed : 0 msecs
18843426:May 21 11:02:27 poc2 kernel: [ 1562.968656] host7: xid f4f:
Exchange timed out
18843581:May 21 11:02:27 poc2 kernel: [ 1562.991761] host7: xid 7e4:
Exchange timer armed : 0 msecs
18843583:May 21 11:02:27 poc2 kernel: [ 1562.991853] host7: xid 7e4:
Exchange timed out
18843690:May 21 11:02:27 poc2 kernel: [ 1563.011282] host7: xid a05:
Exchange timer armed : 0 msecs

Thanks

Post by Vasu Dev

It is send frame failure and to find out what caused send failure more
debug info in low level fcoe Tx path functions will be helpful, it can
be done by:-
# echo 0xFF > /sys/module/libfc/parameters/debug_logging
# echo 0x1 > /sys/module/fcoe/parameters/debug_logging
Disabling Tx offload may not help here and instead would slow down Tx,
so have them restored.
Also, are you using switch between hosts and target ? In any case you
would need DCB PFC or PAUSE enabled to avoid excessive Tx retries though
that should not cause send failure.
//Vasu

Post by Nicholas A. Bellinger

The call into lport->tt.seq_send() libfc code is failing to send
outgoing solicited data-in. From the output, note the LSO (large
segment offload aka TCP segment offload) feature has been enabled by the
underlying NIC hardware.
- Disabling hardware offloads on both initiator and target sides (LRO +
LSO) using ethtool -K
- Disabling any jumbo frames settings on either side
Is there any other non standard network and/or switch settings that are
in place..? Also, please confirm what your NIC + switch setup looks
like.
Rob & Open-FCoE folks, is there anything else to take into consideration
here..?

Post by Jun Wu
I didn't see the previous message "unable to handle kernel NULL
pointer dereference at 0000000000000048". So it must have been fixed
by your change.

Thanks for confirming that bit.
--nab

_______________________________________________
fcoe-devel mailing list
http://lists.open-fcoe.org/mailman/listinfo/fcoe-devel

Jun Wu

2014-05-21 22:23:41 UTC

Permalink

On initiator side, there were also a lot of messages:

May 21 11:01:52 poc1 kernel: [ 3374.393864] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.396149] host7: xid fc1: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.396155] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.397069] host7: xid 602: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.397075] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.397482] host7: xid a46: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.398443] host7: xid 602: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.398498] host7: xid 6ce: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.398863] host7: xid 6ce: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.398869] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.399449] host7: xid 6a2: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.399476] host7: xid 3e1: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.399486] host7: xid dcd: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.399866] host7: xid dcd: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.399872] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.400472] host7: xid d6c: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.401442] host7: xid 585: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.401453] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.402457] host7: xid 585: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.402480] host7: xid 742: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.403602] host7: xid 4a7: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.403607] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.403674] host7: xid 907: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.403678] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:52 poc1 kernel: [ 3374.404276] host7: fcp: 00061e: xid
0084-08c2: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:52 poc1 kernel: [ 3374.404281] host7: xid 84: f_ctl 90000 seq 1
May 21 11:01:52 poc1 kernel: [ 3374.404492] host7: xid dac: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.404506] host7: xid 70a: Exchange
timer armed : 8000 msecs
May 21 11:01:52 poc1 kernel: [ 3374.405384] host7: xid 585: Exchange
timer canceled
May 21 11:01:52 poc1 kernel: [ 3374.405390] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)

More and more "fc_fcp_recv_data set ERROR" messages show up in the file later:

May 21 11:01:53 poc1 kernel: [ 3374.614142] host7: fcp: 00061e: xid
01ed-0925: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.614147] host7: xid 1ed: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.616658] host7: xid 4e7: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.617657] host7: xid 54a: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.617958] host7: xid 54a: Exchange
timer canceled
May 21 11:01:53 poc1 kernel: [ 3374.617965] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:53 poc1 kernel: [ 3374.619656] host7: xid ded: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.620627] host7: xid 489: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.620744] host7: fcp: 00061e: xid
01cd-038e: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.620747] host7: xid 1cd: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.621078] host7: xid 1cd: BLS rctl
85 - BLS reject received
May 21 11:01:53 poc1 kernel: [ 3374.621389] host7: xid 3c1: Exchange
timer canceled
May 21 11:01:53 poc1 kernel: [ 3374.621395] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:53 poc1 kernel: [ 3374.621622] host7: xid a64: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.622056] host7: fcp: 00061e: xid
0107-06e4: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.622060] host7: xid 107: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.622370] host7: xid cc: exch: BLS
rctl 84 - BLS accept
May 21 11:01:53 poc1 kernel: [ 3374.622381] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_CMD_ABORTED
May 21 11:01:53 poc1 kernel: [ 3374.622491] host7: fcp: 00061e: xid
00a5-0862: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.622496] host7: xid a5: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.622866] host7: xid b86: Exchange
timer canceled
May 21 11:01:53 poc1 kernel: [ 3374.622870] host7: xid 1e6: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.622889] host7: xid dcd: Exchange
timer canceled
May 21 11:01:53 poc1 kernel: [ 3374.622897] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:53 poc1 kernel: [ 3374.623491] host7: xid 1e6: BLS rctl
85 - BLS reject received
May 21 11:01:53 poc1 kernel: [ 3374.623637] host7: xid 4a0: Exchange
timer canceled
May 21 11:01:53 poc1 kernel: [ 3374.623719] host7: fcp: 00061e: xid
012d-0869: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.623724] host7: xid 12d: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.624626] host7: xid fa4: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.624824] host7: xid fa4: Exchange
timer canceled
May 21 11:01:53 poc1 kernel: [ 3374.624829] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_DATA_UNDRUN (scsi)
May 21 11:01:53 poc1 kernel: [ 3374.625133] host7: fcp: 00061e: xid
00a4-0e4f: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.625137] host7: xid a4: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.625404] host7: xid a4: BLS rctl
85 - BLS reject received
May 21 11:01:53 poc1 kernel: [ 3374.625536] host7: fcp: 00061e: xid
01e7-05e7: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.625540] host7: xid 1e7: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.625637] host7: xid fa4: Exchange
timer armed : 8000 msecs
May 21 11:01:53 poc1 kernel: [ 3374.625842] host7: xid 1e7: BLS rctl
85 - BLS reject received
May 21 11:01:53 poc1 kernel: [ 3374.626210] host7: fcp: 00061e: xid
01a7-0666: DDP I/O in fc_fcp_recv_data set ERROR
May 21 11:01:53 poc1 kernel: [ 3374.626213] host7: xid 1a7: f_ctl 90000 seq 1
May 21 11:01:53 poc1 kernel: [ 3374.626581] host7: xid 102: exch: BLS
rctl 84 - BLS accept
May 21 11:01:53 poc1 kernel: [ 3374.626590] host7: fcp: 00061e:
Returning DID_ERROR to scsi-ml due to FC_CMD_ABORTED
May 21 11:01:53 poc1 kernel: [ 3374.626602] host7: fcp: 00061e: xid
01c7-0862: DDP I/O in fc_fcp_recv_data set ERROR

Post by Jun Wu
I enabled the Tx offload and set the debug_loggings as suggested. A
few minutes run generated a 1.5GB messages file.
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
Exchange timer armed : 0 msecs
f_ctl 800000 seq 1
f_ctl 800000 seq 2
Exchange timed out
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 458752,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 393216,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 327680,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 262144,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 0,
lso_max <0x10000>
f_ctl 800000 seq 1
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 880008 seq 2
f_ctl 800000 seq 1
Above is the first time ft_queue_data_in message shows up in the file.
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
Exchange timer armed : 0 msecs
f_ctl 800000 seq 1
Exchange timed out
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 2
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 131072,
lso_max <0x10000>
f_ctl 800000 seq 3
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
Exchange timer armed : 0 msecs
f_ctl 800000 seq 1
Exchange timed out
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
Exchange timer armed : 0 msecs
f_ctl 800000 seq 1
Exchange timed out
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
f_ctl 800000 seq 1
f_ctl 880008 seq 2
After stripping out the repeated "host7: xid xxx: f_ctl 800000 seq
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 458752,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 393216,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 327680,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 262144,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff8805bf245e00, xid <0x6e4>, remaining 0,
lso_max <0x10000>
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff8802e25c1e00, xid <0x74a>, remaining 131072,
lso_max <0x10000>
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 2000 msecs
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 10000 msecs
f_ctl 90000 seq 1
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 10000 msecs
f_ctl 90000 seq 2
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
10 callbacks suppressed
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 458752,
lso_max <0x10000>
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 393216,
lso_max <0x10000>
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 327680,
lso_max <0x10000>
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 262144,
lso_max <0x10000>
Exchange timed out
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 196608,
lso_max <0x10000>
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 131072,
lso_max <0x10000>
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 65536,
lso_max <0x10000>
Failed to send frame ffff8800ba6e6400, xid <0xc21>, remaining 0,
lso_max <0x10000>
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Exchange timed out
Exchange timer armed : 0 msecs
Thanks

Post by Vasu Dev

It is send frame failure and to find out what caused send failure more
debug info in low level fcoe Tx path functions will be helpful, it can
be done by:-
# echo 0xFF > /sys/module/libfc/parameters/debug_logging
# echo 0x1 > /sys/module/fcoe/parameters/debug_logging
Disabling Tx offload may not help here and instead would slow down Tx,
so have them restored.
Also, are you using switch between hosts and target ? In any case you
would need DCB PFC or PAUSE enabled to avoid excessive Tx retries though
that should not cause send failure.
//Vasu

Post by Nicholas A. Bellinger

The call into lport->tt.seq_send() libfc code is failing to send
outgoing solicited data-in. From the output, note the LSO (large
segment offload aka TCP segment offload) feature has been enabled by the
underlying NIC hardware.
- Disabling hardware offloads on both initiator and target sides (LRO +
LSO) using ethtool -K
- Disabling any jumbo frames settings on either side
Is there any other non standard network and/or switch settings that are
in place..? Also, please confirm what your NIC + switch setup looks
like.
Rob & Open-FCoE folks, is there anything else to take into consideration
here..?

Post by Jun Wu
I didn't see the previous message "unable to handle kernel NULL
pointer dereference at 0000000000000048". So it must have been fixed
by your change.

Thanks for confirming that bit.
--nab

_______________________________________________
fcoe-devel mailing list
http://lists.open-fcoe.org/mailman/listinfo/fcoe-devel

Vasu Dev

2014-05-23 16:23:58 UTC