blob: bd70339c1242eb1f2515a7a947b007472823a3c8 [file] [log] [blame]
Hannes Reineckeded85c12015-01-08 07:43:42 +01001/*
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>
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +010016#include <scsi/scsi_eh.h>
Hannes Reineckeded85c12015-01-08 07:43:42 +010017#include <scsi/scsi_dbg.h>
18
19#define SCSI_LOG_SPOOLSIZE 4096
Hannes Reineckeded85c12015-01-08 07:43:42 +010020
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
Hannes Reinecke21045512015-01-08 07:43:46 +010072static 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)
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +010080{
81 size_t off = 0;
82
Hannes Reinecke21045512015-01-08 07:43:46 +010083 if (name)
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +010084 off += scnprintf(logbuf + off, logbuf_len - off,
Hannes Reinecke21045512015-01-08 07:43:46 +010085 "[%s] ", name);
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +010086
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
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +010096void sdev_prefix_printk(const char *level, const struct scsi_device *sdev,
97 const char *name, const char *fmt, ...)
Hannes Reineckeded85c12015-01-08 07:43:42 +010098{
99 va_list args;
100 char *logbuf;
101 size_t off = 0, logbuf_len;
Hannes Reineckeded85c12015-01-08 07:43:42 +0100102
103 if (!sdev)
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100104 return;
Hannes Reineckeded85c12015-01-08 07:43:42 +0100105
106 logbuf = scsi_log_reserve_buffer(&logbuf_len);
107 if (!logbuf)
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100108 return;
Hannes Reineckeded85c12015-01-08 07:43:42 +0100109
110 if (name)
111 off += scnprintf(logbuf + off, logbuf_len - off,
112 "[%s] ", name);
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100113 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 }
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100118 dev_printk(level, &sdev->sdev_gendev, "%s", logbuf);
Hannes Reineckeded85c12015-01-08 07:43:42 +0100119 scsi_log_release_buffer(logbuf);
Hannes Reineckeded85c12015-01-08 07:43:42 +0100120}
121EXPORT_SYMBOL(sdev_prefix_printk);
122
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100123void scmd_printk(const char *level, const struct scsi_cmnd *scmd,
Hannes Reineckeded85c12015-01-08 07:43:42 +0100124 const char *fmt, ...)
125{
Hannes Reineckeded85c12015-01-08 07:43:42 +0100126 va_list args;
127 char *logbuf;
128 size_t off = 0, logbuf_len;
Hannes Reineckeded85c12015-01-08 07:43:42 +0100129
130 if (!scmd || !scmd->cmnd)
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100131 return;
Hannes Reineckeded85c12015-01-08 07:43:42 +0100132
133 logbuf = scsi_log_reserve_buffer(&logbuf_len);
134 if (!logbuf)
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100135 return;
Hannes Reinecke21045512015-01-08 07:43:46 +0100136 off = sdev_format_header(logbuf, logbuf_len, scmd_name(scmd),
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100137 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 }
Hannes Reinecke9c4a6b12015-02-04 08:11:34 +0100143 dev_printk(level, &scmd->device->sdev_gendev, "%s", logbuf);
Hannes Reineckeded85c12015-01-08 07:43:42 +0100144 scsi_log_release_buffer(logbuf);
Hannes Reineckeded85c12015-01-08 07:43:42 +0100145}
146EXPORT_SYMBOL(scmd_printk);
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100147
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{
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100222 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
Hannes Reinecke21045512015-01-08 07:43:46 +0100233 off = sdev_format_header(logbuf, logbuf_len,
234 scmd_name(cmd), cmd->request->tag);
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100235 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");
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100250 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100251 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;
Hannes Reinecke21045512015-01-08 07:43:46 +0100258 off = sdev_format_header(logbuf, logbuf_len,
259 scmd_name(cmd),
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100260 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 }
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100268 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s",
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100269 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:
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100281 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
Hannes Reinecke9e5ed2a2015-01-08 07:43:44 +0100282 scsi_log_release_buffer(logbuf);
283}
284EXPORT_SYMBOL(scsi_print_command);
Hannes Reinecke21045512015-01-08 07:43:46 +0100285
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);
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100359 dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf);
Hannes Reinecke21045512015-01-08 07:43:46 +0100360 }
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);
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100376 dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf);
Hannes Reinecke21045512015-01-08 07:43:46 +0100377 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);
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100385 dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf);
Hannes Reinecke21045512015-01-08 07:43:46 +0100386 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);
Hannes Reinecke026f8da2015-01-08 07:43:47 +0100427
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:
Christoph Hellwig2fc583c2015-01-18 16:11:28 +0100482 dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
Hannes Reinecke026f8da2015-01-08 07:43:47 +0100483 scsi_log_release_buffer(logbuf);
484}
485EXPORT_SYMBOL(scsi_print_result);