d/freebsd-nq
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Implement more functional CTL debug logging.

Browse Source 
Setting bits in kern.cam.ctl.debug allows to log errors, commands and some
commands data respectively.

MFC after:	1 week
This commit is contained in:
Alexander Motin 2014-10-16 08:42:17 +00:00
parent 75afaef266
commit 218d5d4be2
6 changed files with 134 additions and 150 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

95
sys/cam/ctl/ctl.c
View File

@ -326,9 +326,9 @@ SYSCTL_NODE(_kern_cam, OID_AUTO, ctl, CTLFLAG_RD, 0, "CAM Target Layer");
static int worker_threads = -1;
SYSCTL_INT(_kern_cam_ctl, OID_AUTO, worker_threads, CTLFLAG_RDTUN,
&worker_threads, 1, "Number of worker threads");
static int verbose = 0;
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;
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),
@ -5066,6 +5066,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
@ -13508,17 +13510,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 */
@ -13612,74 +13611,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;
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;
sense_key = 0;
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
@ -13824,6 +13777,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:

10
sys/cam/ctl/ctl_debug.h
View File

@ -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 { \

2
sys/cam/ctl/ctl_private.h
View File

@ -474,8 +474,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;

30
sys/cam/ctl/ctl_scsi_all.c
View File

@ -112,32 +112,10 @@ ctl_scsi_command_string(struct ctl_scsiio *ctsio,
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);
}
/*

138
sys/cam/ctl/ctl_util.c
View File

@ -730,6 +730,44 @@ ctl_scsi_task_string(struct ctl_taskio *taskio)
return (NULL);
}
void
ctl_io_sbuf(union ctl_io *io, struct sbuf *sb)
{
const char *task_desc;
char path_str[64];
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, " Tag: %#x/%d\n",
io->scsiio.tag_num, io->scsiio.tag_type);
break;
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);
else
sbuf_printf(sb, "Task Action: %s", task_desc);
switch (io->taskio.task_action) {
case CTL_TASK_ABORT_TASK:
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)
@ -738,8 +776,9 @@ ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data,
char path_str[64];
unsigned int i;
status_desc = NULL;
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) ==
@ -751,50 +790,6 @@ ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data,
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,
io->scsiio.tag_num, io->scsiio.tag_type);
break;
case CTL_IO_TASK: {
const char *task_desc;
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);
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);
break;
default:
break;
}
break;
}
default:
break;
}
sbuf_cat(sb, path_str);
if (status_desc == NULL)
sbuf_printf(sb, "CTL Status: Unknown status %#x\n",
@ -814,6 +809,17 @@ ctl_io_error_sbuf(union ctl_io *io, struct scsi_inquiry_data *inq_data,
}
}
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)
@ -821,16 +827,21 @@ ctl_io_error_string(union ctl_io *io, struct scsi_inquiry_data *inq_data,
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)
{
@ -856,6 +867,37 @@ ctl_io_error_print(union ctl_io *io, struct scsi_inquiry_data *inq_data)
}
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

9
sys/cam/ctl/ctl_util.h
View File

@ -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