I got this working but would like some feedback why.
Things I tried:
- I upgraded FreeNAS to FreeNAS 11 and retested with no success.
- I setup FreeNAS ISCSI targets to be disk devices and not ZVOLs basically eliminating ZFS from the equation on the FreeNAS side. With 2 ISCSI targets creating a mirrored ZFS pool on the M3000 side, I would get errors when the pool was scrubbed but these were recoverable from the other device in the mirror.
- I tried a Solaris VM running on an ESXi server to the same FreeNAS server. the ESXi server has an Intel 10G card. This worked which lead me to believe that it could work and maybe something to do with the Chelsio S320 10G in the M3000
- I tried disabling the LSO on the Chelsio S320E 10G card on the M3000 as well as configuring the MTU to 1500 instead of 9000. Still errors.
At one point on the FreeNAS server, I saw this in the message log:
Code:
Jun 20 22:59:02 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): received PDU with CmdSN 8535941, while expected 8537982
Jun 20 22:59:02 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): received PDU with CmdSN 8537983, while expected 8537982; dropping connection
Jun 20 22:59:02 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): received PDU with CmdSN 8537984, while expected 8537982; dropping connection
So it looked like a protocol error occurred.
On a whim, on the M3000 initiator, I enabled data and header digests for the ISCSI target. I was able to transfer with no corruption reported from the pool when scrubbed.
I backed of and just enabled header digests and still was able to transfer with no corrupt from the pool reported when scrubbed.
As a test to confirm that the header digests were making the difference, I disabled the header digests and tried again with MTU = 8000, and LSO disabled on the Chelsio S320E card.
Code:
bash-3.2# ndd -get /dev/cxge0 \?
? (read only)
accept-jumbo (read and write)
hw-csum (read and write)
lso (read and write)
rx_pause (read and write)
tx_pause (read and write)
coalesce (read and write)
bash-3.2# ndd -get /dev/cxge0 accept-jumbo
1
bash-3.2# ndd -get /dev/cxge0 hw-csum
1
bash-3.2# ndd -get /dev/cxge0 lso
0
bash-3.2# ndd -get /dev/cxge0 rx_pause
1
bash-3.2# ndd -get /dev/cxge0 tx_pause
1
bash-3.2# ndd -get /dev/cxge0 coalesce
5
bash-3.2#
Immediately the M3000 side reported:
Code:
Jun 22 08:13:09 ct-m3000-global scsi: [ID 243001 kern.info] /scsi_vhci (scsi_vhci0):
Jun 22 08:13:09 ct-m3000-global /scsi_vhci/ssd@g6589cfc00000029aadcfeeaa310ae53b (ssd12): Command failed to complete (3) on path iscsi0/ssd@0000iqn.2005-10.org.freenas.ctl:m30000001,0
Jun 22 08:13:09 ct-m3000-global scsi: [ID 107833 kern.warning] WARNING: /scsi_vhci/ssd@g6589cfc00000029aadcfeeaa310ae53b (ssd12):
Jun 22 08:13:09 ct-m3000-global SCSI transport failed: reason 'tran_err': retrying command
Jun 22 08:13:22 ct-m3000-global scsi: [ID 243001 kern.info] /scsi_vhci (scsi_vhci0):
Jun 22 08:13:22 ct-m3000-global /scsi_vhci/ssd@g6589cfc00000029aadcfeeaa310ae53b (ssd12): Command failed to complete (3) on path iscsi0/ssd@0000iqn.2005-10.org.freenas.ctl:m30000001,0
...
and the FreeNAS side reported:
Code:
Jun 22 08:13:09 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): no ping reply (NOP-Out) after 5 seconds; dropping connection
Jun 22 08:13:09 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): waiting for CTL to terminate 6 tasks
Jun 22 08:13:09 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): tasks terminated
Jun 22 08:13:22 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): no ping reply (NOP-Out) after 5 seconds; dropping connection
Jun 22 08:13:22 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): waiting for CTL to terminate 9 tasks
Jun 22 08:13:22 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): tasks terminated
Jun 22 08:13:36 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240:
...
I actually had to reboot both the FreeNAS server and the M3000 to get this to come back up.
So to recap, the M3000 are directly connected to each other through a Chelsio S320E card with quality cable.
Here is the statistics from from the M3000 side using "netstat" . This is before I copied 585G of data to the ZFS pool backed by the ISCSI target
M3000 Before IP statistics
Code:
IPv4 ipForwarding = 2 ipDefaultTTL = 255
ipInReceives =72469839 ipInHdrErrors = 0
ipInAddrErrors = 0 ipInCksumErrs = 0
ipForwDatagrams = 0 ipForwProhibits = 180
ipInUnknownProtos = 1 ipInDiscards = 0
ipInDelivers =72469026 ipOutRequests =40016277
ipOutDiscards = 0 ipOutNoRoutes = 0
ipReasmTimeout = 15 ipReasmReqds = 0
ipReasmOKs = 0 ipReasmFails = 0
ipReasmDuplicates = 0 ipReasmPartDups = 0
ipFragOKs = 0 ipFragFails = 0
ipFragCreates = 0 ipRoutingDiscards = 0
tcpInErrs = 0 udpNoPorts = 752
udpInCksumErrs = 0 udpInOverflows = 0
rawipInOverflows = 0 ipsecInSucceeded = 446
ipsecInFailed = 0 ipInIPv6 = 0
ipOutIPv6 = 0 ipOutSwitchIPv6 = 0
M3000 After IP statistics
Code:
IPv4 ipForwarding = 2 ipDefaultTTL = 255
ipInReceives =106913420 ipInHdrErrors = 0
ipInAddrErrors = 0 ipInCksumErrs = 0
ipForwDatagrams = 0 ipForwProhibits = 180
ipInUnknownProtos = 1 ipInDiscards = 0
ipInDelivers =106911636 ipOutRequests =70481324
ipOutDiscards = 0 ipOutNoRoutes = 0
ipReasmTimeout = 15 ipReasmReqds = 0
ipReasmOKs = 0 ipReasmFails = 0
ipReasmDuplicates = 0 ipReasmPartDups = 0
ipFragOKs = 0 ipFragFails = 0
ipFragCreates = 0 ipRoutingDiscards = 0
tcpInErrs = 0 udpNoPorts = 1723
udpInCksumErrs = 0 udpInOverflows = 0
rawipInOverflows = 0 ipsecInSucceeded = 446
ipsecInFailed = 0 ipInIPv6 = 0
ipOutIPv6 = 0 ipOutSwitchIPv6 = 0
M3000 Before TCP statistics
Code:
TCP tcpRtoAlgorithm = 4 tcpRtoMin = 400
tcpRtoMax = 60000 tcpMaxConn = -1
tcpActiveOpens = 17 tcpPassiveOpens = 8
tcpAttemptFails = 7 tcpEstabResets = 2
tcpCurrEstab = 5 tcpOutSegs =40023845
tcpOutDataSegs =4896582 tcpOutDataBytes =335910143
tcpRetransSegs = 1 tcpRetransBytes = 0
tcpOutAck =35119484 tcpOutAckDelayed = 6520
tcpOutUrg = 0 tcpOutWinUpdate = 428
tcpOutWinProbe = 0 tcpOutControl = 46
tcpOutRsts = 9 tcpOutFastRetrans = 0
tcpInSegs =72468715
tcpInAckSegs =4864542 tcpInAckBytes =335910151
tcpInDupAck = 8 tcpInAckUnsent = 0
tcpInInorderSegs =72443741 tcpInInorderBytes =1086680933
tcpInUnorderSegs = 0 tcpInUnorderBytes = 0
tcpInDupSegs = 0 tcpInDupBytes = 0
tcpInPartDupSegs = 0 tcpInPartDupBytes = 0
tcpInPastWinSegs = 0 tcpInPastWinBytes = 0
tcpInWinProbe = 0 tcpInWinUpdate = 0
tcpInClosed = 2 tcpRttNoUpdate = 4584
tcpRttUpdate =4859947 tcpTimRetrans = 0
tcpTimRetransDrop = 0 tcpTimKeepalive = 0
tcpTimKeepaliveProbe= 0 tcpTimKeepaliveDrop = 0
tcpListenDrop = 0 tcpListenDropQ0 = 0
tcpHalfOpenDrop = 0 tcpOutSackRetrans = 0
M3000 After TCP Statistics
Code:
TCP tcpRtoAlgorithm = 4 tcpRtoMin = 400
tcpRtoMax = 60000 tcpMaxConn = -1
tcpActiveOpens = 19 tcpPassiveOpens = 9
tcpAttemptFails = 7 tcpEstabResets = 2
tcpCurrEstab = 6 tcpOutSegs =137559419
tcpOutDataSegs =33682786 tcpOutDataBytes =2021111811
tcpRetransSegs = 38 tcpRetransBytes =331520
tcpOutAck =36798482 tcpOutAckDelayed = 12351
tcpOutUrg = 0 tcpOutWinUpdate = 428
tcpOutWinProbe = 0 tcpOutControl = 51
tcpOutRsts = 11 tcpOutFastRetrans = 0
tcpInSegs =106911534
tcpInAckSegs =31017044 tcpInAckBytes =2020521269
tcpInDupAck = 32 tcpInAckUnsent = 0
tcpInInorderSegs =81605515 tcpInInorderBytes =1563304710
tcpInUnorderSegs = 0 tcpInUnorderBytes = 0
tcpInDupSegs = 86 tcpInDupBytes = 4466
tcpInPartDupSegs = 0 tcpInPartDupBytes = 0
tcpInPastWinSegs = 0 tcpInPastWinBytes = 0
tcpInWinProbe = 0 tcpInWinUpdate = 0
tcpInClosed = 2 tcpRttNoUpdate =20855360
tcpRttUpdate =10161671 tcpTimRetrans = 14
tcpTimRetransDrop = 0 tcpTimKeepalive = 4
tcpTimKeepaliveProbe= 0 tcpTimKeepaliveDrop = 0
tcpListenDrop = 0 tcpListenDropQ0 = 0
tcpHalfOpenDrop = 0 tcpOutSackRetrans = 0
On the FreeNAS side
FreeNAS Before IP Statistics
Code:
ip:
34733271 total packets received
0 bad header checksums
0 with size smaller than minimum
0 with data size < data length
0 with ip length > max ip packet size
0 with header length < data size
0 with data length < header length
0 with bad options
0 with incorrect version number
0 fragments received
0 fragments dropped (dup or out of space)
0 fragments dropped after timeout
0 packets reassembled ok
34733269 packets for this host
0 packets for unknown/unsupported protocol
0 packets forwarded (0 packets fast forwarded)
0 packets not forwardable
11 packets received for unknown multicast group
0 redirects sent
34938942 packets sent from this host
0 packets sent with fabricated ip header
0 output packets dropped due to no bufs, etc.
4 output packets discarded due to no route
0 output datagrams fragmented
0 fragments created
0 datagrams that can't be fragmented
0 tunneling packets that can't find gif
0 datagrams with bad address in header
FreeNAS After IP Statistics
Code:
ip:
63654535 total packets received
0 bad header checksums
0 with size smaller than minimum
0 with data size < data length
0 with ip length > max ip packet size
0 with header length < data size
0 with data length < header length
0 with bad options
0 with incorrect version number
0 fragments received
0 fragments dropped (dup or out of space)
0 fragments dropped after timeout
0 packets reassembled ok
63654533 packets for this host
0 packets for unknown/unsupported protocol
0 packets forwarded (0 packets fast forwarded)
0 packets not forwardable
35 packets received for unknown multicast group
0 redirects sent
69443030 packets sent from this host
0 packets sent with fabricated ip header
0 output packets dropped due to no bufs, etc.
4 output packets discarded due to no route
0 output datagrams fragmented
0 fragments created
0 datagrams that can't be fragmented
0 tunneling packets that can't find gif
0 datagrams with bad address in header
FreeNAS Before TCP Statistics
Code:
tcp:
34938758 packets sent
34881862 data packets (632491612554 bytes)
14 data packets (1545 bytes) retransmitted
0 data packets unnecessarily retransmitted
0 resends initiated by MTU discovery
46304 ack-only packets (6036 delayed)
0 URG only packets
0 window probe packets
2 window update packets
10580 control packets
34730712 packets received
32472358 acks (for 632491627850 bytes)
2716 duplicate acks
0 acks for unsent data
4900795 packets (350268867 bytes) received in-sequence
77 completely duplicate packets (130 bytes)
0 old duplicate packets
0 packets with some dup. data (0 bytes duped)
0 out-of-order packets (0 bytes)
0 packets (0 bytes) of data after window
0 window probes
7766 window update packets
61 packets received after close
0 discarded for bad checksums
0 discarded for bad header offset fields
0 discarded because packet too short
0 discarded due to memory problems
5166 connection requests
5351 connection accepts
0 bad connection attempts
0 listen queue overflows
0 ignored RSTs in the windows
10475 connections established (including accepts)
10460 times used RTT from hostcache
10460 times used RTT variance from hostcache
1 time used slow-start threshold from hostcache
10193 connections closed (including 77 drops)
478 connections updated cached RTT on close
479 connections updated cached RTT variance on close
1 connection updated cached ssthresh on close
42 embryonic connections dropped
12596423 segments updated rtt (of 12584412 attempts)
13 retransmit timeouts
1 connection dropped by rexmit timeout
0 persist timeouts
0 connections dropped by persist timeout
0 Connections (fin_wait_2) dropped because of timeout
0 keepalive timeouts
0 keepalive probes sent
0 connections dropped by keepalive
29784245 correct ACK header predictions
2234820 correct data packet header predictions
5351 syncache entries added
0 retransmitted
0 dupsyn
0 dropped
5351 completed
0 bucket overflow
0 cache overflow
0 reset
0 stale
0 aborted
0 badack
0 unreach
0 zone failures
5351 cookies sent
0 cookies received
4 hostcache entries added
0 bucket overflow
0 SACK recovery episodes
0 segment rexmits in SACK recovery episodes
0 byte rexmits in SACK recovery episodes
0 SACK options (SACK blocks) received
0 SACK options (SACK blocks) sent
0 SACK scoreboard overflow
0 packets with ECN CE bit set
9189 packets with ECN ECT(0) bit set
0 packets with ECN ECT(1) bit set
97 successful ECN handshakes
0 times ECN reduced the congestion window
0 packets with matching signature received
0 packets with bad signature received
0 times failed to make signature due to no SA
0 times unexpected signature received
0 times no signature provided by segment
TCP connection count by state:
0 connections in CLOSED state
10 connections in LISTEN state
0 connections in SYN_SENT state
0 connections in SYN_RCVD state
16 connections in ESTABLISHED state
0 connections in CLOSE_WAIT state
0 connections in FIN_WAIT_1 state
0 connections in CLOSING state
0 connections in LAST_ACK state
0 connections in FIN_WAIT_2 state
470 connections in TIME_WAIT state
FreeNAS After TCP Statistics
Code:
tcp:
69442123 packets sent
44071864 data packets (633013769758 bytes)
28 data packets (5913 bytes) retransmitted
0 data packets unnecessarily retransmitted
0 resends initiated by MTU discovery
25330373 ack-only packets (13378 delayed)
0 URG only packets
0 window probe packets
18432 window update packets
21430 control packets
63648080 packets received
39431734 acks (for 633013799646 bytes)
5093 duplicate acks
0 acks for unsent data
33664515 packets (629115436043 bytes) received in-sequence
78 completely duplicate packets (130 bytes)
0 old duplicate packets
0 packets with some dup. data (0 bytes duped)
0 out-of-order packets (0 bytes)
0 packets (0 bytes) of data after window
0 window probes
15555 window update packets
125 packets received after close
0 discarded for bad checksums
0 discarded for bad header offset fields
0 discarded because packet too short
0 discarded due to memory problems
10466 connection requests
10891 connection accepts
0 bad connection attempts
0 listen queue overflows
0 ignored RSTs in the windows
21315 connections established (including accepts)
21298 times used RTT from hostcache
21298 times used RTT variance from hostcache
2 times used slow-start threshold from hostcache
21561 connections closed (including 139 drops)
848 connections updated cached RTT on close
851 connections updated cached RTT variance on close
3 connections updated cached ssthresh on close
42 embryonic connections dropped
15931180 segments updated rtt (of 15906685 attempts)
27 retransmit timeouts
1 connection dropped by rexmit timeout
0 persist timeouts
0 connections dropped by persist timeout
0 Connections (fin_wait_2) dropped because of timeout
1 keepalive timeout
1 keepalive probe sent
0 connections dropped by keepalive
29893218 correct ACK header predictions
24169053 correct data packet header predictions
10891 syncache entries added
0 retransmitted
0 dupsyn
0 dropped
10891 completed
0 bucket overflow
0 cache overflow
0 reset
0 stale
0 aborted
0 badack
0 unreach
0 zone failures
10891 cookies sent
0 cookies received
5 hostcache entries added
0 bucket overflow
0 SACK recovery episodes
0 segment rexmits in SACK recovery episodes
0 byte rexmits in SACK recovery episodes
0 SACK options (SACK blocks) received
0 SACK options (SACK blocks) sent
0 SACK scoreboard overflow
0 packets with ECN CE bit set
22847 packets with ECN ECT(0) bit set
0 packets with ECN ECT(1) bit set
233 successful ECN handshakes
0 times ECN reduced the congestion window
0 packets with matching signature received
0 packets with bad signature received
0 times failed to make signature due to no SA
0 times unexpected signature received
0 times no signature provided by segment
TCP connection count by state:
0 connections in CLOSED state
10 connections in LISTEN state
0 connections in SYN_SENT state
0 connections in SYN_RCVD state
4 connections in ESTABLISHED state
0 connections in CLOSE_WAIT state
0 connections in FIN_WAIT_1 state
0 connections in CLOSING state
0 connections in LAST_ACK state
0 connections in FIN_WAIT_2 state
2 connections in TIME_WAIT state
On the FreeNAS side, I saw this in the log after the transfer:
Code:
Jun 22 10:31:19 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): no ping reply (NOP-Out) after 5 seconds; dropping connection
Jun 22 10:31:19 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): waiting for CTL to terminate 5 tasks
Jun 22 10:31:19 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): tasks terminated
Jun 22 10:31:29 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): no ping reply (NOP-Out) after 5 seconds; dropping connection
Jun 22 10:31:29 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): waiting for CTL to terminate 3 tasks
Jun 22 10:31:29 freenas WARNING: 192.168.11.2 (iqn.1986-03.com.sun:01:000b5de240e4.4dadca1c): tasks terminated
On the M3000 side, I saw this in the log after the transfer:
Code:
Jun 22 10:31:19 ct-m3000-global scsi: [ID 243001 kern.info] /scsi_vhci (scsi_vhci0):
Jun 22 10:31:19 ct-m3000-global /scsi_vhci/ssd@g6589cfc00000029aadcfeeaa310ae53b (ssd12): Command failed to complete (3) on path iscsi0/ssd@0000iqn.2005-10.org.freenas.ctl:m30000001,0
Jun 22 10:31:19 ct-m3000-global scsi: [ID 107833 kern.warning] WARNING: /scsi_vhci/ssd@g6589cfc00000029aadcfeeaa310ae53b (ssd12):
Jun 22 10:31:19 ct-m3000-global SCSI transport failed: reason 'tran_err': retrying command
Jun 22 10:31:29 ct-m3000-global scsi: [ID 243001 kern.info] /scsi_vhci (scsi_vhci0):
Jun 22 10:31:29 ct-m3000-global /scsi_vhci/ssd@g6589cfc00000029aadcfeeaa310ae53b (ssd12): Command failed to complete (3) on path iscsi0/ssd@0000iqn.2005-10.org.freenas.ctl:m30000001,0
Running "zpool scrub" on the pool on the M3000, I see
Code:
bash-3.2# zpool status -v sanspace
pool: sanspace
state: ONLINE
status: One or more devices has experienced an error resulting in data
corruption. Applications may be affected.
action: Restore the file in question if possible. Otherwise restore the
entire pool from backup.
see: http://www.sun.com/msg/ZFS-8000-8A
scan: scrub repaired 0 in 0h31m with 11 errors on Thu Jun 22 11:20:15 2017
config:
NAME STATE READ WRITE CKSUM
sanspace ONLINE 0 0 11
c1t6589CFC00000029AADCFEEAA310AE53Bd0 ONLINE 0 0 22
errors: Permanent errors have been detected in the following files:
/sanspace/data/csemdb/seg0/c44b181.dat
/sanspace/data/csemdb/seg0/c44ec71.dat
/sanspace/data/csemdb/seg0/c7790.dat
/sanspace/data/csemdb/seg0/c82e0.dat
/sanspace/data/csemdb/seg0/c84c0.dat
/sanspace/data/csemdb/seg0/c44b131.dat
/sanspace/data/csemdb/seg0/c4475b0.dat
/sanspace/data/csemdb/seg0/c337c40.dat
/sanspace/data/csemdb/seg0/c44ecb1.dat
/sanspace/data/csemdb/seg0/ce8c0.dat
/sanspace/data/csemdb/seg0/c5f30.dat
bash-3.2#
I am wondering how this is not being detected and corrected at the TCP level?
TCP is a reliable data stream and its TCP checksum probably should be catching data corruption errors and retransmitting.
Looking at the FreeNAS TCP statistics, there are very few duplicate packets, duplicate acks, and no out of order packets received. On the transmit side, there are very few retransmitted packets as well.
Looking at the M3000 TCP statistics, again there are very few duplicate packets, duplicate acks, and no out of order packets. On the transmit side again, there are very few retransmitted packets as well.
I think pretty much proves that a ISCSI protocol level corruption error is happening.
Any thoughts?
