From owner-svn-src-stable@FreeBSD.ORG Thu Oct 23 07:36:36 2014 Return-Path: Delivered-To: svn-src-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 339B980; Thu, 23 Oct 2014 07:36:36 +0000 (UTC) Received: from svn.freebsd.org (svn.freebsd.org [IPv6:2001:1900:2254:2068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 153778B5; Thu, 23 Oct 2014 07:36:36 +0000 (UTC) Received: from svn.freebsd.org ([127.0.1.70]) by svn.freebsd.org (8.14.9/8.14.9) with ESMTP id s9N7aZY5072948; Thu, 23 Oct 2014 07:36:35 GMT (envelope-from mav@FreeBSD.org) Received: (from mav@localhost) by svn.freebsd.org (8.14.9/8.14.9/Submit) id s9N7aYe4072941; Thu, 23 Oct 2014 07:36:34 GMT (envelope-from mav@FreeBSD.org) Message-Id: <201410230736.s9N7aYe4072941@svn.freebsd.org> X-Authentication-Warning: svn.freebsd.org: mav set sender to mav@FreeBSD.org using -f From: Alexander Motin Date: Thu, 23 Oct 2014 07:36:34 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-stable@freebsd.org, svn-src-stable-10@freebsd.org Subject: svn commit: r273531 - stable/10/sys/cam/ctl X-SVN-Group: stable-10 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-stable@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: SVN commit messages for all the -stable branches of the src tree List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 23 Oct 2014 07:36:36 -0000 Author: mav Date: Thu Oct 23 07:36:33 2014 New Revision: 273531 URL: https://svnweb.freebsd.org/changeset/base/273531 Log: MFC r273163: Implement more functional CTL debug logging. Setting bits in kern.cam.ctl.debug allows to log errors, commands and some commands data respectively. Modified: stable/10/sys/cam/ctl/ctl.c stable/10/sys/cam/ctl/ctl_debug.h stable/10/sys/cam/ctl/ctl_private.h stable/10/sys/cam/ctl/ctl_scsi_all.c stable/10/sys/cam/ctl/ctl_util.c stable/10/sys/cam/ctl/ctl_util.h Directory Properties: stable/10/ (props changed) Modified: stable/10/sys/cam/ctl/ctl.c ============================================================================== --- stable/10/sys/cam/ctl/ctl.c Thu Oct 23 07:22:18 2014 (r273530) +++ stable/10/sys/cam/ctl/ctl.c Thu Oct 23 07:36:33 2014 (r273531) @@ -315,10 +315,10 @@ static int worker_threads = -1; TUNABLE_INT("kern.cam.ctl.worker_threads", &worker_threads); SYSCTL_INT(_kern_cam_ctl, OID_AUTO, worker_threads, CTLFLAG_RDTUN, &worker_threads, 1, "Number of worker threads"); -static int verbose = 0; -TUNABLE_INT("kern.cam.ctl.verbose", &verbose); -SYSCTL_INT(_kern_cam_ctl, OID_AUTO, verbose, CTLFLAG_RWTUN, - &verbose, 0, "Show SCSI errors returned to initiator"); +static int ctl_debug = CTL_DEBUG_NONE; +TUNABLE_INT("kern.cam.ctl.debug", &ctl_debug); +SYSCTL_INT(_kern_cam_ctl, OID_AUTO, debug, CTLFLAG_RWTUN, + &ctl_debug, 0, "Enabled debug flags"); /* * Supported pages (0x00), Serial number (0x80), Device ID (0x83), @@ -5294,6 +5294,8 @@ ctl_config_move_done(union ctl_io *io) * * - Call some other function once the data is in? */ + if (ctl_debug & CTL_DEBUG_CDB_DATA) + ctl_data_print(io); /* * XXX KDM call ctl_scsiio() again for now, and check flag @@ -13766,17 +13768,14 @@ ctl_process_done(union ctl_io *io) case CTL_IO_SCSI: break; case CTL_IO_TASK: - if (bootverbose || verbose > 0) + if (bootverbose || (ctl_debug & CTL_DEBUG_INFO)) ctl_io_error_print(io, NULL); if (io->io_hdr.flags & CTL_FLAG_FROM_OTHER_SC) ctl_free_io(io); else fe_done(io); return (CTL_RETVAL_COMPLETE); - break; default: - printf("ctl_process_done: invalid io type %d\n", - io->io_hdr.io_type); panic("ctl_process_done: invalid io type %d\n", io->io_hdr.io_type); break; /* NOTREACHED */ @@ -13870,74 +13869,28 @@ ctl_process_done(union ctl_io *io) ctl_set_task_aborted(&io->scsiio); /* - * We print out status for every task management command. For SCSI - * commands, we filter out any unit attention errors; they happen - * on every boot, and would clutter up the log. Note: task - * management commands aren't printed here, they are printed above, - * since they should never even make it down here. + * If enabled, print command error status. + * We don't print UAs unless debugging was enabled explicitly. */ - switch (io->io_hdr.io_type) { - case CTL_IO_SCSI: { - int error_code, sense_key, asc, ascq; - - sense_key = 0; + do { + if ((io->io_hdr.status & CTL_STATUS_MASK) == CTL_SUCCESS) + break; + if (!bootverbose && (ctl_debug & CTL_DEBUG_INFO) == 0) + break; + if ((ctl_debug & CTL_DEBUG_INFO) == 0 && + ((io->io_hdr.status & CTL_STATUS_MASK) == CTL_SCSI_ERROR) && + (io->scsiio.scsi_status == SCSI_STATUS_CHECK_COND)) { + int error_code, sense_key, asc, ascq; - if (((io->io_hdr.status & CTL_STATUS_MASK) == CTL_SCSI_ERROR) - && (io->scsiio.scsi_status == SCSI_STATUS_CHECK_COND)) { - /* - * Since this is just for printing, no need to - * show errors here. - */ scsi_extract_sense_len(&io->scsiio.sense_data, - io->scsiio.sense_len, - &error_code, - &sense_key, - &asc, - &ascq, - /*show_errors*/ 0); + io->scsiio.sense_len, &error_code, &sense_key, + &asc, &ascq, /*show_errors*/ 0); + if (sense_key == SSD_KEY_UNIT_ATTENTION) + break; } - if (((io->io_hdr.status & CTL_STATUS_MASK) != CTL_SUCCESS) - && (((io->io_hdr.status & CTL_STATUS_MASK) != CTL_SCSI_ERROR) - || (io->scsiio.scsi_status != SCSI_STATUS_CHECK_COND) - || (sense_key != SSD_KEY_UNIT_ATTENTION))) { - - if ((time_uptime - ctl_softc->last_print_jiffies) <= 0){ - ctl_softc->skipped_prints++; - } else { - uint32_t skipped_prints; - - skipped_prints = ctl_softc->skipped_prints; - - ctl_softc->skipped_prints = 0; - ctl_softc->last_print_jiffies = time_uptime; - - if (skipped_prints > 0) { -#ifdef NEEDTOPORT - csevent_log(CSC_CTL | CSC_SHELF_SW | - CTL_ERROR_REPORT, - csevent_LogType_Trace, - csevent_Severity_Information, - csevent_AlertLevel_Green, - csevent_FRU_Firmware, - csevent_FRU_Unknown, - "High CTL error volume, %d prints " - "skipped", skipped_prints); -#endif - } - if (bootverbose || verbose > 0) - ctl_io_error_print(io, NULL); - } - } - break; - } - case CTL_IO_TASK: - if (bootverbose || verbose > 0) - ctl_io_error_print(io, NULL); - break; - default: - break; - } + ctl_io_error_print(io, NULL); + } while (0); /* * Tell the FETD or the other shelf controller we're done with this @@ -14082,6 +14035,8 @@ ctl_queue(union ctl_io *io) switch (io->io_hdr.io_type) { case CTL_IO_SCSI: case CTL_IO_TASK: + if (ctl_debug & CTL_DEBUG_CDB) + ctl_io_print(io); ctl_enqueue_incoming(io); break; default: Modified: stable/10/sys/cam/ctl/ctl_debug.h ============================================================================== --- stable/10/sys/cam/ctl/ctl_debug.h Thu Oct 23 07:22:18 2014 (r273530) +++ stable/10/sys/cam/ctl/ctl_debug.h Thu Oct 23 07:36:33 2014 (r273531) @@ -39,6 +39,16 @@ #ifndef _CTL_DEBUG_H_ #define _CTL_DEBUG_H_ +/* + * Debugging flags. + */ +typedef enum { + CTL_DEBUG_NONE = 0x00, /* no debugging */ + CTL_DEBUG_INFO = 0x01, /* SCSI errors */ + CTL_DEBUG_CDB = 0x02, /* SCSI CDBs and tasks */ + CTL_DEBUG_CDB_DATA = 0x04 /* SCSI CDB DATA */ +} ctl_debug_flags; + #ifdef CAM_CTL_DEBUG #define CTL_DEBUG_PRINT(X) \ do { \ Modified: stable/10/sys/cam/ctl/ctl_private.h ============================================================================== --- stable/10/sys/cam/ctl/ctl_private.h Thu Oct 23 07:22:18 2014 (r273530) +++ stable/10/sys/cam/ctl/ctl_private.h Thu Oct 23 07:36:33 2014 (r273531) @@ -456,8 +456,6 @@ struct ctl_softc { uint32_t num_pools; uint32_t cur_pool_id; STAILQ_HEAD(, ctl_io_pool) io_pools; - time_t last_print_jiffies; - uint32_t skipped_prints; struct ctl_thread threads[CTL_MAX_THREADS]; TAILQ_HEAD(tpc_tokens, tpc_token) tpc_tokens; struct callout tpc_timeout; Modified: stable/10/sys/cam/ctl/ctl_scsi_all.c ============================================================================== --- stable/10/sys/cam/ctl/ctl_scsi_all.c Thu Oct 23 07:22:18 2014 (r273530) +++ stable/10/sys/cam/ctl/ctl_scsi_all.c Thu Oct 23 07:36:33 2014 (r273531) @@ -112,32 +112,10 @@ ctl_scsi_command_string(struct ctl_scsii void ctl_scsi_path_string(union ctl_io *io, char *path_str, int len) { - if (io->io_hdr.nexus.targ_target.wwid[0] == 0) { - snprintf(path_str, len, "(%ju:%d:%ju:%d): ", - (uintmax_t)io->io_hdr.nexus.initid.id, - io->io_hdr.nexus.targ_port, - (uintmax_t)io->io_hdr.nexus.targ_target.id, - io->io_hdr.nexus.targ_lun); - } else { - /* - * XXX KDM find a better way to display FC WWIDs. - */ -#ifdef _KERNEL - snprintf(path_str, len, "(%ju:%d:%#jx,%#jx:%d): ", - (uintmax_t)io->io_hdr.nexus.initid.id, - io->io_hdr.nexus.targ_port, - (intmax_t)io->io_hdr.nexus.targ_target.wwid[0], - (intmax_t)io->io_hdr.nexus.targ_target.wwid[1], - io->io_hdr.nexus.targ_lun); -#else /* _KERNEL */ - snprintf(path_str, len, "(%ju:%d:%#jx,%#jx:%d): ", - (uintmax_t)io->io_hdr.nexus.initid.id, - io->io_hdr.nexus.targ_port, - (intmax_t)io->io_hdr.nexus.targ_target.wwid[0], - (intmax_t)io->io_hdr.nexus.targ_target.wwid[1], - io->io_hdr.nexus.targ_lun); -#endif /* _KERNEL */ - } + + snprintf(path_str, len, "(%u:%u:%u/%u): ", + io->io_hdr.nexus.initid.id, io->io_hdr.nexus.targ_port, + io->io_hdr.nexus.targ_lun, io->io_hdr.nexus.targ_mapped_lun); } /* Modified: stable/10/sys/cam/ctl/ctl_util.c ============================================================================== --- stable/10/sys/cam/ctl/ctl_util.c Thu Oct 23 07:22:18 2014 (r273530) +++ stable/10/sys/cam/ctl/ctl_util.c Thu Oct 23 07:36:33 2014 (r273531) @@ -731,69 +731,64 @@ ctl_scsi_task_string(struct ctl_taskio * } void -ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data, - struct sbuf *sb) +ctl_io_sbuf(union ctl_io *io, struct sbuf *sb) { - struct ctl_status_desc *status_desc; + const char *task_desc; char path_str[64]; - unsigned int i; - - status_desc = NULL; - - for (i = 0; i < (sizeof(ctl_status_table)/sizeof(ctl_status_table[0])); - i++) { - if ((io->io_hdr.status & CTL_STATUS_MASK) == - ctl_status_table[i].status) { - status_desc = &ctl_status_table[i]; - break; - } - } ctl_scsi_path_string(io, path_str, sizeof(path_str)); switch (io->io_hdr.io_type) { case CTL_IO_SCSI: sbuf_cat(sb, path_str); - ctl_scsi_command_string(&io->scsiio, NULL, sb); - - sbuf_printf(sb, "\n"); - - sbuf_printf(sb, "%sTag: 0x%04x, Type: %d\n", path_str, + sbuf_printf(sb, " Tag: %#x/%d\n", io->scsiio.tag_num, io->scsiio.tag_type); break; - case CTL_IO_TASK: { - const char *task_desc; - + case CTL_IO_TASK: sbuf_cat(sb, path_str); - task_desc = ctl_scsi_task_string(&io->taskio); - if (task_desc == NULL) sbuf_printf(sb, "Unknown Task Action %d (%#x)", - io->taskio.task_action, - io->taskio.task_action); + io->taskio.task_action, io->taskio.task_action); else sbuf_printf(sb, "Task Action: %s", task_desc); - - sbuf_printf(sb, "\n"); - switch (io->taskio.task_action) { case CTL_TASK_ABORT_TASK: - case CTL_TASK_ABORT_TASK_SET: - case CTL_TASK_CLEAR_TASK_SET: - sbuf_printf(sb, "%sTag: 0x%04x, Type: %d\n", path_str, - io->taskio.tag_num, - io->taskio.tag_type); + sbuf_printf(sb, " Tag: %#x/%d\n", + io->taskio.tag_num, io->taskio.tag_type); break; default: + sbuf_printf(sb, "\n"); break; } break; - } default: break; } +} + +void +ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data, + struct sbuf *sb) +{ + struct ctl_status_desc *status_desc; + char path_str[64]; + unsigned int i; + + ctl_io_sbuf(io, sb); + + status_desc = NULL; + for (i = 0; i < (sizeof(ctl_status_table)/sizeof(ctl_status_table[0])); + i++) { + if ((io->io_hdr.status & CTL_STATUS_MASK) == + ctl_status_table[i].status) { + status_desc = &ctl_status_table[i]; + break; + } + } + + ctl_scsi_path_string(io, path_str, sizeof(path_str)); sbuf_cat(sb, path_str); if (status_desc == NULL) @@ -815,23 +810,39 @@ ctl_io_error_sbuf(union ctl_io *io, stru } char * +ctl_io_string(union ctl_io *io, char *str, int str_len) +{ + struct sbuf sb; + + sbuf_new(&sb, str, str_len, SBUF_FIXEDLEN); + ctl_io_sbuf(io, &sb); + sbuf_finish(&sb); + return (sbuf_data(&sb)); +} + +char * ctl_io_error_string(union ctl_io *io, struct scsi_inquiry_data *inq_data, char *str, int str_len) { struct sbuf sb; sbuf_new(&sb, str, str_len, SBUF_FIXEDLEN); - ctl_io_error_sbuf(io, inq_data, &sb); - sbuf_finish(&sb); - return (sbuf_data(&sb)); } #ifdef _KERNEL void +ctl_io_print(union ctl_io *io) +{ + char str[512]; + + printf("%s", ctl_io_string(io, str, sizeof(str))); +} + +void ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data) { char str[512]; @@ -856,6 +867,37 @@ ctl_io_error_print(union ctl_io *io, str } +void +ctl_data_print(union ctl_io *io) +{ + char str[128]; + char path_str[64]; + struct sbuf sb; + int i, j, len; + + if (io->io_hdr.io_type != CTL_IO_SCSI) + return; + if (io->io_hdr.flags & CTL_FLAG_BUS_ADDR) + return; + if (io->io_hdr.flags & CTL_FLAG_EDPTR_SGLIST) /* XXX: Implement */ + return; + ctl_scsi_path_string(io, path_str, sizeof(path_str)); + len = min(io->scsiio.kern_data_len, 4096); + for (i = 0; i < len; ) { + sbuf_new(&sb, str, sizeof(str), SBUF_FIXEDLEN); + sbuf_cat(&sb, path_str); + sbuf_printf(&sb, " %#6x:%04x:", io->scsiio.tag_num, i); + for (j = 0; j < 16 && i < len; i++, j++) { + if (j == 8) + sbuf_cat(&sb, " "); + sbuf_printf(&sb, " %02x", io->scsiio.kern_data_ptr[i]); + } + sbuf_cat(&sb, "\n"); + sbuf_finish(&sb); + printf("%s", sbuf_data(&sb)); + } +} + #else /* _KERNEL */ void Modified: stable/10/sys/cam/ctl/ctl_util.h ============================================================================== --- stable/10/sys/cam/ctl/ctl_util.h Thu Oct 23 07:22:18 2014 (r273530) +++ stable/10/sys/cam/ctl/ctl_util.h Thu Oct 23 07:36:33 2014 (r273531) @@ -99,19 +99,20 @@ void ctl_scsi_free_io(union ctl_io *io); #endif /* !_KERNEL */ void ctl_scsi_zero_io(union ctl_io *io); const char *ctl_scsi_task_string(struct ctl_taskio *taskio); +void ctl_io_sbuf(union ctl_io *io, struct sbuf *sb); void ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data, struct sbuf *sb); +char *ctl_io_string(union ctl_io *io, char *str, int str_len); char *ctl_io_error_string(union ctl_io *io, struct scsi_inquiry_data *inq_data, char *str, int str_len); #ifdef _KERNEL - +void ctl_io_print(union ctl_io *io); void ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data); +void ctl_data_print(union ctl_io *io); #else /* _KERNEL */ -void -ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data, +void ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data, FILE *ofile); - #endif /* _KERNEL */ __END_DECLS