From: Steffen Maier <maier@linux.vnet.ibm.com>
Subject: scsi: zfcp: fix capping of unsuccessful GPN_FT SAN response trace records
Patch-mainline: v4.14-rc1
Git-commit: 975171b4461be296a35e83ebd748946b81cf0635
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 capping of unsuccessful GPN_FT SAN response trace records

              v4.9 commit aceeffbb59bb ("zfcp: trace full payload of all SAN records
              (req,resp,iels)") fixed trace data loss of 2.6.38 commit 2c55b750a884
              ("[SCSI] zfcp: Redesign of the debug tracing for SAN records.")
              necessary for problem determination, e.g. to see the
              currently active zone set during automatic port scan.

              While it already saves space by not dumping any empty residual entries
              of the large successful GPN_FT response (4 pages), there are seldom cases
              where the GPN_FT response is unsuccessful and likely does not have
              FC_NS_FID_LAST set in fp_flags so we did not cap the trace record.
              We typically see such case for an initiator WWPN, which is not in any zone.

              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).

              Example trace record pair formatted with zfcpdbf:

              Timestamp      : ...
              Area           : SAN
              Subarea        : 00
              Level          : 1
              Exception      : -
              CPU ID         : ..
              Caller         : 0x...
              Record ID      : 1
              Tag            : fssct_1
              Request ID     : 0x<request_id>
              Destination ID : 0x00fffffc
              SAN req short  : 01000000 fc020000 01720ffc 00000000
                               00000008
              SAN req length : 20
              |
              Timestamp      : ...
              Area           : SAN
              Subarea        : 00
              Level          : 1
              Exception      : -
              CPU ID         : ..
              Caller         : 0x...
              Record ID      : 2
              Tag            : fsscth2
              Request ID     : 0x<request_id>
              Destination ID : 0x00fffffc
              SAN resp short : 01000000 fc020000 80010000 00090700
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
              SAN resp length: 16384
              San resp info  : 01000000 fc020000 80010000 00090700
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]
                               00000000 00000000 00000000 00000000 [trailing info]

              The fix saves all but one of the previously associated 64 PAYload trace
              record chunks of size 256 bytes each.

              Signed-off-by: Steffen Maier <maier@linux.vnet.ibm.com>
              Fixes: aceeffbb59bb ("zfcp: trace full payload of all SAN records (req,resp,iels)")
              Fixes: 2c55b750a884 ("[SCSI] zfcp: Redesign of the debug tracing for SAN 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 |   10 +++++++++-
 drivers/s390/scsi/zfcp_fsf.c |    4 ++--
 2 files changed, 11 insertions(+), 3 deletions(-)

--- a/drivers/s390/scsi/zfcp_dbf.c
+++ b/drivers/s390/scsi/zfcp_dbf.c
@@ -3,7 +3,7 @@
  *
  * Debug traces for zfcp.
  *
- * Copyright IBM Corp. 2002, 2016
+ * Copyright IBM Corp. 2002, 2017
  */
 
 #define KMSG_COMPONENT "zfcp"
@@ -447,6 +447,7 @@ static u16 zfcp_dbf_san_res_cap_len_if_g
 	struct fc_ct_hdr *reqh = sg_virt(ct_els->req);
 	struct fc_ns_gid_ft *reqn = (struct fc_ns_gid_ft *)(reqh + 1);
 	struct scatterlist *resp_entry = ct_els->resp;
+	struct fc_ct_hdr *resph;
 	struct fc_gpn_ft_resp *acc;
 	int max_entries, x, last = 0;
 
@@ -473,6 +474,13 @@ static u16 zfcp_dbf_san_res_cap_len_if_g
 		return len; /* not GPN_FT response so do not cap */
 
 	acc = sg_virt(resp_entry);
+
+	/* cap all but accept CT responses to at least the CT header */
+	resph = (struct fc_ct_hdr *)acc;
+	if ((ct_els->status) ||
+	    (resph->ct_cmd != cpu_to_be16(FC_FS_ACC)))
+		return max(FC_CT_HDR_LEN, ZFCP_DBF_SAN_MAX_PAYLOAD);
+
 	max_entries = (reqh->ct_mr_size * 4 / sizeof(struct fc_gpn_ft_resp))
 		+ 1 /* zfcp_fc_scan_ports: bytes correct, entries off-by-one
 		     * to account for header as 1st pseudo "entry" */;
--- a/drivers/s390/scsi/zfcp_fsf.c
+++ b/drivers/s390/scsi/zfcp_fsf.c
@@ -928,8 +928,8 @@ static void zfcp_fsf_send_ct_handler(str
 
 	switch (header->fsf_status) {
         case FSF_GOOD:
-		zfcp_dbf_san_res("fsscth2", req);
 		ct->status = 0;
+		zfcp_dbf_san_res("fsscth2", req);
 		break;
         case FSF_SERVICE_CLASS_NOT_SUPPORTED:
 		zfcp_fsf_class_not_supp(req);
@@ -1109,8 +1109,8 @@ static void zfcp_fsf_send_els_handler(st
 
 	switch (header->fsf_status) {
 	case FSF_GOOD:
-		zfcp_dbf_san_res("fsselh1", req);
 		send_els->status = 0;
+		zfcp_dbf_san_res("fsselh1", req);
 		break;
 	case FSF_SERVICE_CLASS_NOT_SUPPORTED:
 		zfcp_fsf_class_not_supp(req);
