From d8c630e5f4784cb81f353bfc338ceeed1d91744e Mon Sep 17 00:00:00 2001 From: Steffen Maier Date: Tue, 11 Jul 2017 16:11:01 +0200 Subject: [PATCH] zfcpdbf: warn about ambiguous payload records with dup reqid & payarea MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Function get_payload_records() reading from disk, blindly adds payload record (junks) to a list in a 2-stage hierarchical hash keyed with request ID and PAY area. On adapter offline/online, zfcp resets the request ID to re-start with 1. Hence it's not a unique foreign key in the lifetime of the PAY area. The last payload record (junks) read for the same request ID and PAY area is the one printed as named PAY field in the tool output. This is not necessarily the chronologically last record due to PAY area wrapping. With this workaround, we: * warn on reading PAY records if ambiguous entries occurred, * print additional PAY timestamps which the user can compare with the actual trace record timestamps to determine if they are close enough to indicate a match. We only found this by accident because we kept "short" "payload" being a built-in part of some actual trace record types in areas HBA, SAN, SCSI. For above cases, the full PAYload did not match the built-in "short" "payload". While at it, also add a comment that PAY output can also be wrong in another case when junks of multi-part PAY records are missing due to PAY area wrapping. Below is an abbreviated example output with this workaround: Loading trace records ...(this might take a while) Warning: Ambiguous PAYload records. reqid:0000000000000037 area:san_res ... Timestamp : 2017-07-07-18:01:34:574827 Area : SAN ... Tag : fssct_1 Request ID : 0x0000000000000037 Destination ID : 0x00fffffc SAN req short : 01000000 fc020000 01720ffc 00000000 00000008 SAN req length : 20 Timestamp : 2017-07-07-18:01:34:619310 ------------------+ Area : SAN | ... | Tag : fsscth2 | Request ID : 0x0000000000000037 | Destination ID : 0x00fffffc | SAN resp short : 01000000 fc020000 80020000 00000000 | 00671a07 00000000 c05076ff d6801850 | 00671a7e 00000000 c05076ff d6801968 | SAN resp length: 16384 | Payload time : 2017-07-07-18:16:17:165708 <== does not match San resp info : 01000000 fc020000 80020000 00000000 <== wrong 4a49424d 20202020 20323936 34202020 <== wrong 20202020 20202020 20303230 30303030 <== wrong 30303745 43383720 20504348 49443a20 <== wrong 30313938 204e5049 5620556c 7049643a <== wrong 20303536 30303330 30202020 00000000 <== wrong 00000000 00000000 00000000 00000000 <== wrong ... <== wrong ... Timestamp : 2017-07-07-18:16:17:165713 Area : SAN ... Tag : fsscth2 Request ID : 0x0000000000000037 <== same reqid & pay "area" Destination ID : 0x00fffffc SAN resp short : 01000000 fc020000 80020000 00000000 4a49424d 20202020 20323936 34202020 20202020 20202020 20303230 30303030 SAN resp length: 273 Payload time : 2017-07-07-18:16:17:165708 <== 2nd & last, match close to Timestamp San resp info : 01000000 fc020000 80020000 00000000 4a49424d 20202020 20323936 34202020 20202020 20202020 20303230 30303030 30303745 43383720 20504348 49443a20 30313938 204e5049 5620556c 7049643a 20303536 30303330 30202020 00000000 00000000 00000000 00000000 00000000 ... Signed-off-by: Steffen Maier Reviewed-by: Jens Remus Signed-off-by: Jan Höppner --- CHANGELOG.md | 1 + scripts/zfcpdbf | 12 ++++++++++++ 2 files changed, 13 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index ea4391e9..49ff48c4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ Release history for s390-tools (MIT version) - lszfcp: Fix to show non-good target ports again - lszfcp: Fix missing block & sg device output without CONFIG_SYSFS_DEPRECATED - lszfcp: New command line option for extended output format + - zfcpdbf: Warn about ambiguous payload records with dup reqid & payarea * __v2.8.0 (2019-02-15)__ diff --git a/scripts/zfcpdbf b/scripts/zfcpdbf index 1fb2fe30..1bd56e09 100755 --- a/scripts/zfcpdbf +++ b/scripts/zfcpdbf @@ -291,6 +291,13 @@ sub get_payload_records my $area = str_from_hex(substr($record[2], 2, 14)); my $counter = hex(substr($record[2], 0, 2)); my $fsf_req_id = substr($record[2], 16, 16); + # ($counter == 0) is just a simple heuristic which can fail if + # there are missing payload record junks due to PAY area wrap! + if ($counter == 0 && + defined($PAYLOAD_RECORDS{$fsf_req_id}{$area})) { + print "Warning: Ambiguous PAYload records. reqid:" . + $fsf_req_id . " area:" . $area . "\n"; + } $PAYLOAD_RECORDS{$fsf_req_id}{$area}[$counter] = [@record]; if ($def_error && ($area =~ /def_err/)) { $def_error{$fsf_req_id}[$counter] = [@record]; @@ -515,11 +522,16 @@ sub print_payload my $field_name = shift(); my $tmp_str; + if ($payload) { + # workaround to let user determine ambiguous PAYload records + printf "%-14s : %s\n", "Payload time", $payload->[0]->[0]; + } printf "%-14s : ", $field_name; if (!$payload) { print "record not available anymore.\n"; return; } + # TODO: iterate with $counter loop and notify user about missing junks foreach my $cc (@$payload) { $tmp_str .= substr($cc->[2], 32); }