1/* 2 * scsi_logging.c 3 * 4 * Copyright (C) 2014 SUSE Linux Products GmbH 5 * Copyright (C) 2014 Hannes Reinecke <hare@suse.de> 6 * 7 * This file is released under the GPLv2 8 */ 9 10#include <linux/kernel.h> 11#include <linux/atomic.h> 12 13#include <scsi/scsi.h> 14#include <scsi/scsi_cmnd.h> 15#include <scsi/scsi_device.h> 16#include <scsi/scsi_eh.h> 17#include <scsi/scsi_dbg.h> 18 19#define SCSI_LOG_SPOOLSIZE 4096 20 21#if (SCSI_LOG_SPOOLSIZE / SCSI_LOG_BUFSIZE) > BITS_PER_LONG 22#warning SCSI logging bitmask too large 23#endif 24 25struct scsi_log_buf { 26 char buffer[SCSI_LOG_SPOOLSIZE]; 27 unsigned long map; 28}; 29 30static DEFINE_PER_CPU(struct scsi_log_buf, scsi_format_log); 31 32static char *scsi_log_reserve_buffer(size_t *len) 33{ 34 struct scsi_log_buf *buf; 35 unsigned long map_bits = sizeof(buf->buffer) / SCSI_LOG_BUFSIZE; 36 unsigned long idx = 0; 37 38 preempt_disable(); 39 buf = this_cpu_ptr(&scsi_format_log); 40 idx = find_first_zero_bit(&buf->map, map_bits); 41 if (likely(idx < map_bits)) { 42 while (test_and_set_bit(idx, &buf->map)) { 43 idx = find_next_zero_bit(&buf->map, map_bits, idx); 44 if (idx >= map_bits) 45 break; 46 } 47 } 48 if (WARN_ON(idx >= map_bits)) { 49 preempt_enable(); 50 return NULL; 51 } 52 *len = SCSI_LOG_BUFSIZE; 53 return buf->buffer + idx * SCSI_LOG_BUFSIZE; 54} 55 56static void scsi_log_release_buffer(char *bufptr) 57{ 58 struct scsi_log_buf *buf; 59 unsigned long idx; 60 int ret; 61 62 buf = this_cpu_ptr(&scsi_format_log); 63 if (bufptr >= buf->buffer && 64 bufptr < buf->buffer + SCSI_LOG_SPOOLSIZE) { 65 idx = (bufptr - buf->buffer) / SCSI_LOG_BUFSIZE; 66 ret = test_and_clear_bit(idx, &buf->map); 67 WARN_ON(!ret); 68 } 69 preempt_enable(); 70} 71 72static inline const char *scmd_name(const struct scsi_cmnd *scmd) 73{ 74 return scmd->request->rq_disk ? 75 scmd->request->rq_disk->disk_name : NULL; 76} 77 78static size_t sdev_format_header(char *logbuf, size_t logbuf_len, 79 const char *name, int tag) 80{ 81 size_t off = 0; 82 83 if (name) 84 off += scnprintf(logbuf + off, logbuf_len - off, 85 "[%s] ", name); 86 87 if (WARN_ON(off >= logbuf_len)) 88 return off; 89 90 if (tag >= 0) 91 off += scnprintf(logbuf + off, logbuf_len - off, 92 "tag#%d ", tag); 93 return off; 94} 95 96void sdev_prefix_printk(const char *level, const struct scsi_device *sdev, 97 const char *name, const char *fmt, ...) 98{ 99 va_list args; 100 char *logbuf; 101 size_t off = 0, logbuf_len; 102 103 if (!sdev) 104 return; 105 106 logbuf = scsi_log_reserve_buffer(&logbuf_len); 107 if (!logbuf) 108 return; 109 110 if (name) 111 off += scnprintf(logbuf + off, logbuf_len - off, 112 "[%s] ", name); 113 if (!WARN_ON(off >= logbuf_len)) { 114 va_start(args, fmt); 115 off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args); 116 va_end(args); 117 } 118 dev_printk(level, &sdev->sdev_gendev, "%s", logbuf); 119 scsi_log_release_buffer(logbuf); 120} 121EXPORT_SYMBOL(sdev_prefix_printk); 122 123void scmd_printk(const char *level, const struct scsi_cmnd *scmd, 124 const char *fmt, ...) 125{ 126 va_list args; 127 char *logbuf; 128 size_t off = 0, logbuf_len; 129 130 if (!scmd || !scmd->cmnd) 131 return; 132 133 logbuf = scsi_log_reserve_buffer(&logbuf_len); 134 if (!logbuf) 135 return; 136 off = sdev_format_header(logbuf, logbuf_len, scmd_name(scmd), 137 scmd->request->tag); 138 if (off < logbuf_len) { 139 va_start(args, fmt); 140 off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args); 141 va_end(args); 142 } 143 dev_printk(level, &scmd->device->sdev_gendev, "%s", logbuf); 144 scsi_log_release_buffer(logbuf); 145} 146EXPORT_SYMBOL(scmd_printk); 147 148static size_t scsi_format_opcode_name(char *buffer, size_t buf_len, 149 const unsigned char *cdbp) 150{ 151 int sa, cdb0; 152 const char *cdb_name = NULL, *sa_name = NULL; 153 size_t off; 154 155 cdb0 = cdbp[0]; 156 if (cdb0 == VARIABLE_LENGTH_CMD) { 157 int len = scsi_varlen_cdb_length(cdbp); 158 159 if (len < 10) { 160 off = scnprintf(buffer, buf_len, 161 "short variable length command, len=%d", 162 len); 163 return off; 164 } 165 sa = (cdbp[8] << 8) + cdbp[9]; 166 } else 167 sa = cdbp[1] & 0x1f; 168 169 if (!scsi_opcode_sa_name(cdb0, sa, &cdb_name, &sa_name)) { 170 if (cdb_name) 171 off = scnprintf(buffer, buf_len, "%s", cdb_name); 172 else { 173 off = scnprintf(buffer, buf_len, "opcode=0x%x", cdb0); 174 if (WARN_ON(off >= buf_len)) 175 return off; 176 if (cdb0 >= VENDOR_SPECIFIC_CDB) 177 off += scnprintf(buffer + off, buf_len - off, 178 " (vendor)"); 179 else if (cdb0 >= 0x60 && cdb0 < 0x7e) 180 off += scnprintf(buffer + off, buf_len - off, 181 " (reserved)"); 182 } 183 } else { 184 if (sa_name) 185 off = scnprintf(buffer, buf_len, "%s", sa_name); 186 else if (cdb_name) 187 off = scnprintf(buffer, buf_len, "%s, sa=0x%x", 188 cdb_name, sa); 189 else 190 off = scnprintf(buffer, buf_len, 191 "opcode=0x%x, sa=0x%x", cdb0, sa); 192 } 193 WARN_ON(off >= buf_len); 194 return off; 195} 196 197size_t __scsi_format_command(char *logbuf, size_t logbuf_len, 198 const unsigned char *cdb, size_t cdb_len) 199{ 200 int len, k; 201 size_t off; 202 203 off = scsi_format_opcode_name(logbuf, logbuf_len, cdb); 204 if (off >= logbuf_len) 205 return off; 206 len = scsi_command_size(cdb); 207 if (cdb_len < len) 208 len = cdb_len; 209 /* print out all bytes in cdb */ 210 for (k = 0; k < len; ++k) { 211 if (off > logbuf_len - 3) 212 break; 213 off += scnprintf(logbuf + off, logbuf_len - off, 214 " %02x", cdb[k]); 215 } 216 return off; 217} 218EXPORT_SYMBOL(__scsi_format_command); 219 220void scsi_print_command(struct scsi_cmnd *cmd) 221{ 222 int k; 223 char *logbuf; 224 size_t off, logbuf_len; 225 226 if (!cmd->cmnd) 227 return; 228 229 logbuf = scsi_log_reserve_buffer(&logbuf_len); 230 if (!logbuf) 231 return; 232 233 off = sdev_format_header(logbuf, logbuf_len, 234 scmd_name(cmd), cmd->request->tag); 235 if (off >= logbuf_len) 236 goto out_printk; 237 off += scnprintf(logbuf + off, logbuf_len - off, "CDB: "); 238 if (WARN_ON(off >= logbuf_len)) 239 goto out_printk; 240 241 off += scsi_format_opcode_name(logbuf + off, logbuf_len - off, 242 cmd->cmnd); 243 if (off >= logbuf_len) 244 goto out_printk; 245 246 /* print out all bytes in cdb */ 247 if (cmd->cmd_len > 16) { 248 /* Print opcode in one line and use separate lines for CDB */ 249 off += scnprintf(logbuf + off, logbuf_len - off, "\n"); 250 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf); 251 scsi_log_release_buffer(logbuf); 252 for (k = 0; k < cmd->cmd_len; k += 16) { 253 size_t linelen = min(cmd->cmd_len - k, 16); 254 255 logbuf = scsi_log_reserve_buffer(&logbuf_len); 256 if (!logbuf) 257 break; 258 off = sdev_format_header(logbuf, logbuf_len, 259 scmd_name(cmd), 260 cmd->request->tag); 261 if (!WARN_ON(off > logbuf_len - 58)) { 262 off += scnprintf(logbuf + off, logbuf_len - off, 263 "CDB[%02x]: ", k); 264 hex_dump_to_buffer(&cmd->cmnd[k], linelen, 265 16, 1, logbuf + off, 266 logbuf_len - off, false); 267 } 268 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", 269 logbuf); 270 scsi_log_release_buffer(logbuf); 271 } 272 return; 273 } 274 if (!WARN_ON(off > logbuf_len - 49)) { 275 off += scnprintf(logbuf + off, logbuf_len - off, " "); 276 hex_dump_to_buffer(cmd->cmnd, cmd->cmd_len, 16, 1, 277 logbuf + off, logbuf_len - off, 278 false); 279 } 280out_printk: 281 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf); 282 scsi_log_release_buffer(logbuf); 283} 284EXPORT_SYMBOL(scsi_print_command); 285 286static size_t 287scsi_format_extd_sense(char *buffer, size_t buf_len, 288 unsigned char asc, unsigned char ascq) 289{ 290 size_t off = 0; 291 const char *extd_sense_fmt = NULL; 292 const char *extd_sense_str = scsi_extd_sense_format(asc, ascq, 293 &extd_sense_fmt); 294 295 if (extd_sense_str) { 296 off = scnprintf(buffer, buf_len, "Add. Sense: %s", 297 extd_sense_str); 298 if (extd_sense_fmt) 299 off += scnprintf(buffer + off, buf_len - off, 300 "(%s%x)", extd_sense_fmt, ascq); 301 } else { 302 if (asc >= 0x80) 303 off = scnprintf(buffer, buf_len, "<<vendor>>"); 304 off += scnprintf(buffer + off, buf_len - off, 305 "ASC=0x%x ", asc); 306 if (ascq >= 0x80) 307 off += scnprintf(buffer + off, buf_len - off, 308 "<<vendor>>"); 309 off += scnprintf(buffer + off, buf_len - off, 310 "ASCQ=0x%x ", ascq); 311 } 312 return off; 313} 314 315static size_t 316scsi_format_sense_hdr(char *buffer, size_t buf_len, 317 const struct scsi_sense_hdr *sshdr) 318{ 319 const char *sense_txt; 320 size_t off; 321 322 off = scnprintf(buffer, buf_len, "Sense Key : "); 323 sense_txt = scsi_sense_key_string(sshdr->sense_key); 324 if (sense_txt) 325 off += scnprintf(buffer + off, buf_len - off, 326 "%s ", sense_txt); 327 else 328 off += scnprintf(buffer + off, buf_len - off, 329 "0x%x ", sshdr->sense_key); 330 off += scnprintf(buffer + off, buf_len - off, 331 scsi_sense_is_deferred(sshdr) ? "[deferred] " : "[current] "); 332 333 if (sshdr->response_code >= 0x72) 334 off += scnprintf(buffer + off, buf_len - off, "[descriptor] "); 335 return off; 336} 337 338static void 339scsi_log_dump_sense(const struct scsi_device *sdev, const char *name, int tag, 340 const unsigned char *sense_buffer, int sense_len) 341{ 342 char *logbuf; 343 size_t logbuf_len; 344 int i; 345 346 logbuf = scsi_log_reserve_buffer(&logbuf_len); 347 if (!logbuf) 348 return; 349 350 for (i = 0; i < sense_len; i += 16) { 351 int len = min(sense_len - i, 16); 352 size_t off; 353 354 off = sdev_format_header(logbuf, logbuf_len, 355 name, tag); 356 hex_dump_to_buffer(&sense_buffer[i], len, 16, 1, 357 logbuf + off, logbuf_len - off, 358 false); 359 dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf); 360 } 361 scsi_log_release_buffer(logbuf); 362} 363 364static void 365scsi_log_print_sense_hdr(const struct scsi_device *sdev, const char *name, 366 int tag, const struct scsi_sense_hdr *sshdr) 367{ 368 char *logbuf; 369 size_t off, logbuf_len; 370 371 logbuf = scsi_log_reserve_buffer(&logbuf_len); 372 if (!logbuf) 373 return; 374 off = sdev_format_header(logbuf, logbuf_len, name, tag); 375 off += scsi_format_sense_hdr(logbuf + off, logbuf_len - off, sshdr); 376 dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf); 377 scsi_log_release_buffer(logbuf); 378 379 logbuf = scsi_log_reserve_buffer(&logbuf_len); 380 if (!logbuf) 381 return; 382 off = sdev_format_header(logbuf, logbuf_len, name, tag); 383 off += scsi_format_extd_sense(logbuf + off, logbuf_len - off, 384 sshdr->asc, sshdr->ascq); 385 dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf); 386 scsi_log_release_buffer(logbuf); 387} 388 389static void 390scsi_log_print_sense(const struct scsi_device *sdev, const char *name, int tag, 391 const unsigned char *sense_buffer, int sense_len) 392{ 393 struct scsi_sense_hdr sshdr; 394 395 if (scsi_normalize_sense(sense_buffer, sense_len, &sshdr)) 396 scsi_log_print_sense_hdr(sdev, name, tag, &sshdr); 397 else 398 scsi_log_dump_sense(sdev, name, tag, sense_buffer, sense_len); 399} 400 401/* 402 * Print normalized SCSI sense header with a prefix. 403 */ 404void 405scsi_print_sense_hdr(const struct scsi_device *sdev, const char *name, 406 const struct scsi_sense_hdr *sshdr) 407{ 408 scsi_log_print_sense_hdr(sdev, name, -1, sshdr); 409} 410EXPORT_SYMBOL(scsi_print_sense_hdr); 411 412/* Normalize and print sense buffer with name prefix */ 413void __scsi_print_sense(const struct scsi_device *sdev, const char *name, 414 const unsigned char *sense_buffer, int sense_len) 415{ 416 scsi_log_print_sense(sdev, name, -1, sense_buffer, sense_len); 417} 418EXPORT_SYMBOL(__scsi_print_sense); 419 420/* Normalize and print sense buffer in SCSI command */ 421void scsi_print_sense(const struct scsi_cmnd *cmd) 422{ 423 scsi_log_print_sense(cmd->device, scmd_name(cmd), cmd->request->tag, 424 cmd->sense_buffer, SCSI_SENSE_BUFFERSIZE); 425} 426EXPORT_SYMBOL(scsi_print_sense); 427 428void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, 429 int disposition) 430{ 431 char *logbuf; 432 size_t off, logbuf_len; 433 const char *mlret_string = scsi_mlreturn_string(disposition); 434 const char *hb_string = scsi_hostbyte_string(cmd->result); 435 const char *db_string = scsi_driverbyte_string(cmd->result); 436 437 logbuf = scsi_log_reserve_buffer(&logbuf_len); 438 if (!logbuf) 439 return; 440 441 off = sdev_format_header(logbuf, logbuf_len, 442 scmd_name(cmd), cmd->request->tag); 443 444 if (off >= logbuf_len) 445 goto out_printk; 446 447 if (msg) { 448 off += scnprintf(logbuf + off, logbuf_len - off, 449 "%s: ", msg); 450 if (WARN_ON(off >= logbuf_len)) 451 goto out_printk; 452 } 453 if (mlret_string) 454 off += scnprintf(logbuf + off, logbuf_len - off, 455 "%s ", mlret_string); 456 else 457 off += scnprintf(logbuf + off, logbuf_len - off, 458 "UNKNOWN(0x%02x) ", disposition); 459 if (WARN_ON(off >= logbuf_len)) 460 goto out_printk; 461 462 off += scnprintf(logbuf + off, logbuf_len - off, "Result: "); 463 if (WARN_ON(off >= logbuf_len)) 464 goto out_printk; 465 466 if (hb_string) 467 off += scnprintf(logbuf + off, logbuf_len - off, 468 "hostbyte=%s ", hb_string); 469 else 470 off += scnprintf(logbuf + off, logbuf_len - off, 471 "hostbyte=0x%02x ", host_byte(cmd->result)); 472 if (WARN_ON(off >= logbuf_len)) 473 goto out_printk; 474 475 if (db_string) 476 off += scnprintf(logbuf + off, logbuf_len - off, 477 "driverbyte=%s", db_string); 478 else 479 off += scnprintf(logbuf + off, logbuf_len - off, 480 "driverbyte=0x%02x", driver_byte(cmd->result)); 481out_printk: 482 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf); 483 scsi_log_release_buffer(logbuf); 484} 485EXPORT_SYMBOL(scsi_print_result); 486