From: Steffen Maier <maier@linux.vnet.ibm.com>
Subject: scsi: zfcp: fix payload with full FCP_RSP IU in SCSI trace records
Patch-mainline: v4.14-rc1
Git-commit: 12c3e5754c8022a4f2fd1e9f00d19e99ee0d3cc1
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 payload with full FCP_RSP IU in SCSI trace records
If the FCP_RSP UI has optional parts (FCP_SNS_INFO or FCP_RSP_INFO) and
thus does not fit into the fsp_rsp field built into a SCSI trace record,
trace the full FCP_RSP UI with all optional parts as payload record
instead of just FCP_SNS_INFO as payload and
a 1 byte RSP_INFO_CODE part of FCP_RSP_INFO built into the SCSI record.
That way we would also get the full FCP_SNS_INFO in case a
target would ever send more than
min(SCSI_SENSE_BUFFERSIZE==96, ZFCP_DBF_PAY_MAX_REC==256)==96.
The mandatory part of FCP_RSP IU is only 24 bytes.
PAYload costs at least one full PAY record of 256 bytes anyway.
We cap to the hardware response size which is only FSF_FCP_RSP_SIZE==128.
So we can just put the whole FCP_RSP IU with any optional parts into
PAYload similarly as we do for SAN PAY since v4.9 commit aceeffbb59bb
("zfcp: trace full payload of all SAN records (req,resp,iels)").
This does not cause any additional trace records wasting memory.
Decoded trace records were confusing because they showed a hard-coded
sense data length of 96 even if the FCP_RSP_IU field FCP_SNS_LEN showed
actually less.
Since the same commit, we set pl_len for SAN traces to the full length of a
request/response even if we cap the corresponding trace.
In contrast, here for SCSI traces we set pl_len to the pre-computed
length of FCP_RSP IU considering SNS_LEN or RSP_LEN if valid.
Nonetheless we trace a hardcoded payload of length FSF_FCP_RSP_SIZE==128
if there were optional parts.
This makes it easier for the zfcpdbf tool to format only the relevant
part of the long FCP_RSP UI buffer. And any trailing information is still
available in the payload trace record just in case.
Rename the payload record tag from "fcp_sns" to "fcp_riu" to make the new
content explicit to zfcpdbf which can then pick a suitable field name such
as "FCP rsp IU all:" instead of "Sense info :"
Also, the same zfcpdbf can still be backwards compatible with "fcp_sns".
Old example trace record before this fix, formatted with the tool zfcpdbf
from s390-tools:
Timestamp : ...
Area : SCSI
Subarea : 00
Level : 3
Exception : -
CPU id : ..
Caller : 0x...
Record id : 1
Tag : rsl_err
Request id : 0x<request_id>
SCSI ID : 0x...
SCSI LUN : 0x...
SCSI result : 0x00000002
SCSI retries : 0x00
SCSI allowed : 0x05
SCSI scribble : 0x<request_id>
SCSI opcode : 00000000 00000000 00000000 00000000
FCP rsp inf cod: 0x00
FCP rsp IU : 00000000 00000000 00000202 00000000
^^==FCP_SNS_LEN_VALID
00000020 00000000
^^^^^^^^==FCP_SNS_LEN==32
Sense len : 96 <==min(SCSI_SENSE_BUFFERSIZE,ZFCP_DBF_PAY_MAX_REC)
Sense info : 70000600 00000018 00000000 29000000
00000400 00000000 00000000 00000000
00000000 00000000 00000000 00000000<==superfluous
00000000 00000000 00000000 00000000<==superfluous
00000000 00000000 00000000 00000000<==superfluous
00000000 00000000 00000000 00000000<==superfluous
New example trace records with this fix:
Timestamp : ...
Area : SCSI
Subarea : 00
Level : 3
Exception : -
CPU ID : ..
Caller : 0x...
Record ID : 1
Tag : rsl_err
Request ID : 0x<request_id>
SCSI ID : 0x...
SCSI LUN : 0x...
SCSI result : 0x00000002
SCSI retries : 0x00
SCSI allowed : 0x03
SCSI scribble : 0x<request_id>
SCSI opcode : a30c0112 00000000 02000000 00000000
FCP rsp inf cod: 0x00
FCP rsp IU : 00000000 00000000 00000a02 00000200
00000020 00000000
FCP rsp IU len : 56
FCP rsp IU all : 00000000 00000000 00000a02 00000200
^^=FCP_RESID_UNDER|FCP_SNS_LEN_VALID
00000020 00000000 70000500 00000018
^^^^^^^^==FCP_SNS_LEN
^^^^^^^^^^^^^^^^^
00000000 240000cb 00011100 00000000
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
00000000 00000000
^^^^^^^^^^^^^^^^^==FCP_SNS_INFO
Timestamp : ...
Area : SCSI
Subarea : 00
Level : 1
Exception : -
CPU ID : ..
Caller : 0x...
Record ID : 1
Tag : lr_okay
Request ID : 0x<request_id>
SCSI ID : 0x...
SCSI LUN : 0x...
SCSI result : 0x00000000
SCSI retries : 0x00
SCSI allowed : 0x05
SCSI scribble : 0x<request_id>
SCSI opcode : <CDB of unrelated SCSI command passed to eh handler>
FCP rsp inf cod: 0x00
FCP rsp IU : 00000000 00000000 00000100 00000000
00000000 00000008
FCP rsp IU len : 32
FCP rsp IU all : 00000000 00000000 00000100 00000000
^^==FCP_RSP_LEN_VALID
00000000 00000008 00000000 00000000
^^^^^^^^==FCP_RSP_LEN
^^^^^^^^^^^^^^^^^==FCP_RSP_INFO
Signed-off-by: Steffen Maier <maier@linux.vnet.ibm.com>
Fixes: 250a1352b95e ("[SCSI] zfcp: Redesign of the debug tracing for SCSI records.")
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.c | 21 +++++++++++++++++----
1 file changed, 17 insertions(+), 4 deletions(-)
--- a/drivers/s390/scsi/zfcp_dbf.c
+++ b/drivers/s390/scsi/zfcp_dbf.c
@@ -572,19 +572,32 @@ void zfcp_dbf_scsi(char *tag, int level,
if (fsf) {
rec->fsf_req_id = fsf->req_id;
+ rec->pl_len = FCP_RESP_WITH_EXT;
fcp_rsp = (struct fcp_resp_with_ext *)
&(fsf->qtcb->bottom.io.fcp_rsp);
+ /* mandatory parts of FCP_RSP IU in this SCSI record */
memcpy(&rec->fcp_rsp, fcp_rsp, FCP_RESP_WITH_EXT);
if (fcp_rsp->resp.fr_flags & FCP_RSP_LEN_VAL) {
fcp_rsp_info = (struct fcp_resp_rsp_info *) &fcp_rsp[1];
rec->fcp_rsp_info = fcp_rsp_info->rsp_code;
+ rec->pl_len += be32_to_cpu(fcp_rsp->ext.fr_rsp_len);
}
if (fcp_rsp->resp.fr_flags & FCP_SNS_LEN_VAL) {
- rec->pl_len = min((u16)SCSI_SENSE_BUFFERSIZE,
- (u16)ZFCP_DBF_PAY_MAX_REC);
- zfcp_dbf_pl_write(dbf, sc->sense_buffer, rec->pl_len,
- "fcp_sns", fsf->req_id);
+ rec->pl_len += be32_to_cpu(fcp_rsp->ext.fr_sns_len);
}
+ /* complete FCP_RSP IU in associated PAYload record
+ * but only if there are optional parts
+ */
+ if (fcp_rsp->resp.fr_flags != 0)
+ zfcp_dbf_pl_write(
+ dbf, fcp_rsp,
+ /* at least one full PAY record
+ * but not beyond hardware response field
+ */
+ min_t(u16, max_t(u16, rec->pl_len,
+ ZFCP_DBF_PAY_MAX_REC),
+ FSF_FCP_RSP_SIZE),
+ "fcp_riu", fsf->req_id);
}
debug_event(dbf->scsi, level, rec, sizeof(*rec));