From: Steffen Maier <maier@linux.vnet.ibm.com>
Subject: scsi: zfcp: fix passing fsf_req to SCSI trace on TMF to correlate with HBA
Patch-mainline: v4.14-rc1
Git-commit: 9fe5d2b2fd30aa8c7827ec62cbbe6d30df4fe3e3
References: bnc#1066983, LTC#158494
Description: zfcp: fix tracing regressions, part 2
Symptom: On unsuccessful fabric nameserver responses during zfcp
automatic port scan, zfcp wastes 63 trace records of size 256
bytes each in the PAY trace area.
SCSI trace records on task management functions cannot be
correlated to HBA trace records because all fields related to
the FSF request are empty (zero).
On the following two rather seldom error cases during task
management function (TMF) handling as part of the scsi_eh
callbacks for LUN reset or Target reset, zfcp misses to write
trace records making such situations difficult to debug:
fc_block_scsi_eh() returning != 0 which is FAST_IO_FAIL, and
not having gotten an FSF request after the maximum number of
retry attempts and thus could not issue a TMF and has to
return FAILED.
SCSI trace records do not show FCP_RSP_INFO in case of TMFs,
or would only show the first 96 bytes of FCP_SNS_INFO if a
target would send more sense data.
Cannot always determine root cause for FSF requests that:
Failed by running into an ERP timeout or if they got
dismissed because a higher level recovery was triggered
[trace tags "erscf_1" or "erscf_2"], or
failed by running into an FSF request timeout [trace tag
"fsrth_1"], or
failed with a deferred error when using FCP hardware data
router.
Problem: Since v4.9 commit aceeffbb59bb ("zfcp: trace full payload of
all SAN records (req,resp,iels)"), zfcp only checked for
FC_NS_FID_LAST being set in fp_flags to cap an automatic port
scan SAN response. This flag likely does not occur in an
unsuccessful response.
V2.6.14 commit 8a36e4532ea1 ("[SCSI] zfcp: enhancement of
zfcp debug features") introdued trace records for TMFs but
hard coded NULL for a possibly existing TMF FSF request. The
scsi_cmnd scribble is also zero or unrelated for the TMF
request so it also could not lookup a suitable FSF request
from there.
The following two upstream commits introduced new early
returns without adding a trace record:
v2.6.35 commit a1dbfddd02d2 ("[SCSI] zfcp: Pass return code
from fc_block_scsi_eh to scsi eh"),
v2.6.30 commit 63caf367e1c9 ("[SCSI] zfcp: Improve
reliability of SCSI eh handlers in zfcp").
Zfcp only traced capped sense data.
Zfcp only used protocol status and FSF status to decide on an
unsuccessful response. However, this is only one of multiple
possible sources determining a failed FSF request.
Solution: Cap unsuccessful responses to at least the actual basic CT_IU
response plus whatever fits the SAN trace record built-in
"payload" buffer just in case there's trailing information of
which we would at least see the existence and its beginning.
In order not to erroneously cap successful responses, we need
to swap calling the trace function and setting the CT / ELS
status to success (0).
Pass fsf_req to SCSI trace on TMF.
There are some true cases where we really do not have an FSF
request:
"rsl_fai" from zfcp_dbf_scsi_fail_send() called for
early returns / completions in zfcp_scsi_queuecommand();
"abrt_or", "abrt_bl", "abrt_ru", "abrt_ar" from
zfcp_scsi_eh_abort_handler() where we did not get as far;
"lr_nres", "tr_nres" from zfcp_task_mgmt_function() where
we're successful and do not need to do anything because
adapter stopped. For these cases it's correct to pass NULL
for fsf_req to _zfcp_dbf_scsi().
Add missing trace record statements.
Instead of just capped sense data, trace the full FCP_RSP IU
which includes any sense data if available.
Check zfcp_fsf_req.status for ZFCP_STATUS_FSFREQ_DISMISSED or
ZFCP_STATUS_FSFREQ_ERROR and trace with a new tag "fs_rerr"
at the default trace level.
Reproduction: We typically see such case for an initiator WWPN, which is
not in any zone.
Tigger two timeouts in a row for the same single SCSI command
(READ or WRITE).
To manually create a similar situation: Stop multipathd so we
don't get additional path checker TURs. Enable RSCN suppression
on the SAN switch port beyond the first link, i.e. towards the
storage target. Disable that switch port. Send one SCSI command
in the background (because it will block for a while) e.g. via
"dd if=/dev/mapper/... of=/dev/null count=1 &". After
<SCSI command timeout> seconds, the command runs into the timeout
for the first time, gets aborted, and then a retry is submitted.
The retry is also lost because the switch port is still disabled.
After 1.5 * <SCSI command timeout> seconds, enable that switch
port again. After 2 * <SCSI command timeout> seconds, the command
runs into the timeout for the second time and triggers scsi_eh.
As first step, scsi_eh sends a LUN reset which should get a
successful response from the storage target. This response
causes a SCSI trace record for the TMF.
Similar to above paragraph to trigger a LUN reset but
triggering specific case is hardly possible.
Similar to two paragraphs above for TMF trace records.
During LUN attachment (automatic or manual) or after
re-plugging fibres, we typically get some expected sense data.
No known reproduction for ERP timeout, FSF request timeout,
or erroneous FSF request using FCP hardware data router.
Upstream-Description:
scsi: zfcp: fix passing fsf_req to SCSI trace on TMF to correlate with HBA
Without this fix we get SCSI trace records on task management functions
which cannot be correlated to HBA trace records because all fields
related to the FSF request are empty (zero).
Also, the FCP_RSP_IU is missing as well as any sense data if available.
This was caused by v2.6.14 commit 8a36e4532ea1 ("[SCSI] zfcp: enhancement
of zfcp debug features") introducing trace records for TMFs but
hard coding NULL for a possibly existing TMF FSF request.
The scsi_cmnd scribble is also zero or unrelated for the TMF request
so it also could not lookup a suitable FSF request from there.
A broken example trace record formatted with zfcpdbf from the s390-tools
package:
Timestamp : ...
Area : SCSI
Subarea : 00
Level : 1
Exception : -
CPU ID : ..
Caller : 0x...
Record ID : 1
Tag : lr_fail
Request ID : 0x0000000000000000
^^^^^^^^^^^^^^^^ no correlation to HBA record
SCSI ID : 0x<scsitarget>
SCSI LUN : 0x<scsilun>
SCSI result : 0x000e0000
SCSI retries : 0x00
SCSI allowed : 0x05
SCSI scribble : 0x0000000000000000
SCSI opcode : 2a000017 3bb80000 08000000 00000000
FCP rsp inf cod: 0x00
^^ no TMF response
FCP rsp IU : 00000000 00000000 00000000 00000000
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
00000000 00000000
^^^^^^^^^^^^^^^^^ no interesting FCP_RSP_IU
Sense len : ...
^^^^^^^^^^^^^^^^^^^^ no sense data length
Sense info : ...
^^^^^^^^^^^^^^^^^^^^ no sense data content, even if present
There are some true cases where we really do not have an FSF request:
"rsl_fai" from zfcp_dbf_scsi_fail_send() called for early
returns / completions in zfcp_scsi_queuecommand(),
"abrt_or", "abrt_bl", "abrt_ru", "abrt_ar" from
zfcp_scsi_eh_abort_handler() where we did not get as far,
"lr_nres", "tr_nres" from zfcp_task_mgmt_function() where we're
successful and do not need to do anything because adapter stopped.
For these cases it's correct to pass NULL for fsf_req to _zfcp_dbf_scsi().
Signed-off-by: Steffen Maier <maier@linux.vnet.ibm.com>
Fixes: 8a36e4532ea1 ("[SCSI] zfcp: enhancement of zfcp debug features")
Cc: <stable@vger.kernel.org> #2.6.38+
Reviewed-by: Benjamin Block <bblock@linux.vnet.ibm.com>
Signed-off-by: Benjamin Block <bblock@linux.vnet.ibm.com>
Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>
Signed-off-by: Steffen Maier <maier@linux.vnet.ibm.com>
Acked-by: Hannes Reinecke <hare@suse.com>
---
drivers/s390/scsi/zfcp_dbf.h | 7 ++++---
drivers/s390/scsi/zfcp_scsi.c | 8 ++++----
2 files changed, 8 insertions(+), 7 deletions(-)
--- a/drivers/s390/scsi/zfcp_dbf.h
+++ b/drivers/s390/scsi/zfcp_dbf.h
@@ -2,7 +2,7 @@
* zfcp device driver
* debug feature declarations
*
- * Copyright IBM Corp. 2008, 2016
+ * Copyright IBM Corp. 2008, 2017
*/
#ifndef ZFCP_DBF_H
@@ -401,7 +401,8 @@ void zfcp_dbf_scsi_abort(char *tag, stru
* @flag: indicates type of reset (Target Reset, Logical Unit Reset)
*/
static inline
-void zfcp_dbf_scsi_devreset(char *tag, struct scsi_cmnd *scmnd, u8 flag)
+void zfcp_dbf_scsi_devreset(char *tag, struct scsi_cmnd *scmnd, u8 flag,
+ struct zfcp_fsf_req *fsf_req)
{
char tmp_tag[ZFCP_DBF_TAG_LEN];
@@ -411,7 +412,7 @@ void zfcp_dbf_scsi_devreset(char *tag, s
memcpy(tmp_tag, "lr_", 3);
memcpy(&tmp_tag[3], tag, 4);
- _zfcp_dbf_scsi(tmp_tag, 1, scmnd, NULL);
+ _zfcp_dbf_scsi(tmp_tag, 1, scmnd, fsf_req);
}
/**
--- a/drivers/s390/scsi/zfcp_scsi.c
+++ b/drivers/s390/scsi/zfcp_scsi.c
@@ -3,7 +3,7 @@
*
* Interface to Linux SCSI midlayer.
*
- * Copyright IBM Corp. 2002, 2016
+ * Copyright IBM Corp. 2002, 2017
*/
#define KMSG_COMPONENT "zfcp"
@@ -278,7 +278,7 @@ static int zfcp_task_mgmt_function(struc
if (!(atomic_read(&adapter->status) &
ZFCP_STATUS_COMMON_RUNNING)) {
- zfcp_dbf_scsi_devreset("nres", scpnt, tm_flags);
+ zfcp_dbf_scsi_devreset("nres", scpnt, tm_flags, NULL);
return SUCCESS;
}
}
@@ -288,10 +288,10 @@ static int zfcp_task_mgmt_function(struc
wait_for_completion(&fsf_req->completion);
if (fsf_req->status & ZFCP_STATUS_FSFREQ_TMFUNCFAILED) {
- zfcp_dbf_scsi_devreset("fail", scpnt, tm_flags);
+ zfcp_dbf_scsi_devreset("fail", scpnt, tm_flags, fsf_req);
retval = FAILED;
} else {
- zfcp_dbf_scsi_devreset("okay", scpnt, tm_flags);
+ zfcp_dbf_scsi_devreset("okay", scpnt, tm_flags, fsf_req);
zfcp_scsi_forget_cmnds(zfcp_sdev, tm_flags);
}