drivers/scsi/scsi_logging.c

   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
  25 struct scsi_log_buf {
  26         char buffer[SCSI_LOG_SPOOLSIZE];
  27         unsigned long map;
  28 };
  29
  30 static DEFINE_PER_CPU(struct scsi_log_buf, scsi_format_log);
  31
  32 static 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
  56 static 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
  72 static 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
  78 static 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
  96 void 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 }
 121 EXPORT_SYMBOL(sdev_prefix_printk);
 122
 123 void 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 }
 146 EXPORT_SYMBOL(scmd_printk);
 147
 148 static 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
 197 size_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 }
 218 EXPORT_SYMBOL(__scsi_format_command);
 219
 220 void 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         }
 280 out_printk:
 281         dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
 282         scsi_log_release_buffer(logbuf);
 283 }
 284 EXPORT_SYMBOL(scsi_print_command);
 285
 286 static size_t
 287 scsi_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
 315 static size_t
 316 scsi_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
 338 static void
 339 scsi_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
 364 static void
 365 scsi_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
 389 static void
 390 scsi_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  */
 404 void
 405 scsi_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 }
 410 EXPORT_SYMBOL(scsi_print_sense_hdr);
 411
 412 /* Normalize and print sense buffer with name prefix */
 413 void __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 }
 418 EXPORT_SYMBOL(__scsi_print_sense);
 419
 420 /* Normalize and print sense buffer in SCSI command */
 421 void 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 }
 426 EXPORT_SYMBOL(scsi_print_sense);
 427
 428 void 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));
 481 out_printk:
 482         dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
 483         scsi_log_release_buffer(logbuf);
 484 }
 485 EXPORT_SYMBOL(scsi_print_result);