Logging using the SCSI logging feature

The SCSI logging feature is of interest primarily for software developers who are debugging software problems. It can also be useful for administrators who track down hardware or configuration problems.

The SCSI logging feature can log information such as:

Initiation of commands
Completion of commands
Error conditions
Sense data for SCSI commands

The information is written into the Linux log buffer and usually appears in /var/log/messages.

The SCSI logging feature is controlled by a 32-bit value - the SCSI logging level. This value is divided into 3-bit fields that describe the log level of a specific log area. Due to the 3-bit subdivision, setting levels or interpreting the meaning of current levels of the SCSI logging feature is not trivial.

The following logging areas are provided with the SCSI logging feature:

SCSI LOG ERROR RECOVERY: Messages regarding error recovery.
SCSI LOG TIMEOUT: Messages regarding timeout handling of SCSI commands.
SCSI LOG SCAN BUS: Messages regarding bus scanning.
SCSI LOG MLQUEUE: Messages regarding command handling in SCSI mid-level handling of SCSI commands.
SCSI LOG MLCOMPLETE: Messages regarding command completion in SCSI mid layer.
SCSI LOG LLQUEUE: Messages regarding command handling in low-level drivers (for example, sd, sg, or sr). (Not used in current vanilla kernel).
SCSI LOG LLCOMPLETE: Messages regarding command completion in low-level drivers. (Not used in current vanilla kernel).
SCSI LOG HLQUEUE: Messages regarding command handling in high-level drivers (for example, sd, sg, or sr).
SCSI LOG HLCOMPLETE: Messages regarding command completion in high-level drivers.
SCSI LOG IOCTL: Messages regarding handling of IOCTLs.

Each area has its own logging level. The logging levels can be changed by using a logging word, which can be passed from and to the kernel with a sysctl. The logging levels can easily be read and set with the scsi_logging_level command (part of s390-tools). For a detailed description of the scsi_logging_level tool, see Device Drivers, Features, and Commands, SC33-8411 available on the developerWorks® website at:

www.ibm.com/developerworks/linux/linux390/documentation_dev.html

The following logging levels might be of interest for administrators:

SCSI LOG MLQUEUE=2 traces opcodes of all initiated SCSI commands
SCSI LOG MLCOMPLETE=1 traces completion (opcode, result, sense data) of SCSI commands that did not complete successfully in terms of the SCSI stack. Such commands either timed out, or need to be retried.
SCSI LOG MLCOMPLETE=2 traces completion (opcode, result, sense data) of all SCSI commands
SCSI LOG IOCTL=2 traces initiation of IOCTLs for SCSI disks (device, ioctl-command)

Examples

These examples show how to set the logging level for various problems.

Example 1 shows how to set the log level for SCSI_LOG_MLCOMPLETE to 1 to log all non-successful completions and completions with sense data.

#>scsi_logging_level -s --mlcomplete 1
New scsi logging level:
dev.scsi.logging_level = 4096
SCSI_LOG_ERROR=0
SCSI_LOG_TIMEOUT=0
SCSI_LOG_SCAN=0
SCSI_LOG_MLQUEUE=0
SCSI_LOG_MLCOMPLETE=1
SCSI_LOG_LLQUEUE=0
SCSI_LOG_LLCOMPLETE=0
SCSI_LOG_HLQUEUE=0
SCSI_LOG_HLCOMPLETE=0
SCSI_LOG_IOCTL=0

When you configure a new LUN for zfcp, additional messages appear (in bold):

May 17 12:03:58 t2945012 kernel:   Vendor: IBM       Model: 2107900           Rev: .203
May 17 12:03:58 t2945012 kernel:   Type:   Direct-Access                      ANSI SCSI revision: 05
May 17 12:03:58 t2945012 kernel: sd 0:0:0:0: done SUCCESS        2 sd 0:0:0:0:
May 17 12:03:58 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:03:58 t2945012 kernel: : Current: sense key: Unit Attention
May 17 12:03:58 t2945012 kernel:     Additional sense: Power on, reset, or bus device reset occurred
May 17 12:03:58 t2945012 kernel: SCSI device sda: 10485760 512-byte hdwr sectors (5369 MB)
May 17 12:03:58 t2945012 kernel: sda: Write Protect is off
May 17 12:03:58 t2945012 kernel: SCSI device sda: drive cache: write back
May 17 12:03:58 t2945012 kernel: SCSI device sda: 10485760 512-byte hdwr sectors (5369 MB)
May 17 12:03:58 t2945012 kernel: sda: Write Protect is off
May 17 12:03:58 t2945012 kernel: SCSI device sda: drive cache: write back
May 17 12:03:58 t2945012 kernel:  sda: sda1 sda2
May 17 12:03:58 t2945012 kernel: sd 0:0:0:0: Attached scsi disk sda

Example 2 shows how to set the log level for SCSI_LOG_MLCOMPLETE to 2 to log all command completions:

#>scsi_logging_level -s --mlcomplete 2
New scsi logging level:
dev.scsi.logging_level = 8192
SCSI_LOG_ERROR=0
SCSI_LOG_TIMEOUT=0
SCSI_LOG_SCAN=0
SCSI_LOG_MLQUEUE=0
SCSI_LOG_MLCOMPLETE=2
SCSI_LOG_LLQUEUE=0
SCSI_LOG_LLCOMPLETE=0
SCSI_LOG_HLQUEUE=0
SCSI_LOG_HLCOMPLETE=0
SCSI_LOG_IOCTL=0

When you configure a new LUN for zfcp, additional log messages appear (in bold):

May 17 12:06:01 t2945012 kernel:  1:0:0:0: done SUCCESS        0  1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Inquiry: 12 00 00 00 24 00
May 17 12:06:01 t2945012 kernel:  1:0:0:0: done SUCCESS        0  1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Inquiry: 12 00 00 00 a4 00
May 17 12:06:01 t2945012 kernel:   Vendor: IBM       Model: 2107900           Rev: .203
May 17 12:06:01 t2945012 kernel:   Type:   Direct-Access                      ANSI SCSI revision: 05
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        2 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:06:01 t2945012 kernel: : Current: sense key: Unit Attention
May 17 12:06:01 t2945012 kernel:     Additional sense: Power on, reset, or bus device reset occurred
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Read Capacity (10): 25 00 00 00 00 00 00 00 00 00
May 17 12:06:01 t2945012 kernel: SCSI device sdb: 10485760 512-byte hdwr sectors (5369 MB)
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Mode Sense (6): 1a 00 3f 00 04 00
May 17 12:06:01 t2945012 kernel: sdb: Write Protect is off
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Mode Sense (6): 1a 00 08 00 04 00
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Mode Sense (6): 1a 00 08 00 20 00
May 17 12:06:01 t2945012 kernel: SCSI device sdb: drive cache: write back
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Read Capacity (10): 25 00 00 00 00 00 00 00 00 00
May 17 12:06:01 t2945012 kernel: SCSI device sdb: 10485760 512-byte hdwr sectors (5369 MB)
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Mode Sense (6): 1a 00 3f 00 04 00
May 17 12:06:01 t2945012 kernel: sdb: Write Protect is off
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Mode Sense (6): 1a 00 08 00 04 00
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Mode Sense (6): 1a 00 08 00 20 00
May 17 12:06:01 t2945012 kernel: SCSI device sdb: drive cache: write back
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:06:01 t2945012 kernel:         command: Read (10): 28 00 00 00 00 00 00 00 08 00
May 17 12:06:01 t2945012 kernel:  sdb:sdb1 sdb2
May 17 12:06:01 t2945012 kernel: sd 1:0:0:0: Attached scsi disk sdb
...

Example 3 shows how to set the log level for SCSI_LOG_MLQUEUE to 2 to log command queuing in the SCSI mid-layer.

#>scsi_logging_level -s --mlqueue 2
New scsi logging level:
dev.scsi.logging_level = 1024
SCSI_LOG_ERROR=0
SCSI_LOG_TIMEOUT=0
SCSI_LOG_SCAN=0
SCSI_LOG_MLQUEUE=2
SCSI_LOG_MLCOMPLETE=0
SCSI_LOG_LLQUEUE=0
SCSI_LOG_LLCOMPLETE=0
SCSI_LOG_HLQUEUE=0
SCSI_LOG_HLCOMPLETE=0
SCSI_LOG_IOCTL=0

The output shows Test Unit Ready commands that are issued by the path checker of multipathd (from multipath-tools):

May 17 12:07:36 t2945012 kernel: sd 0:0:0:0: send                  sd 0:0:0:0:
May 17 12:07:36 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:07:37 t2945012 kernel: sd 1:0:0:0: send                  sd 1:0:0:0:
May 17 12:07:37 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00

Example 4 shows how to set the log level for SCSI_LOG_MLQUEUE and SCSI_LOG_MLCOMPLETE to 2 to log command queuing and command completion in the SCSI mid-layer.

#>scsi_logging_level -s --mlqueue 2 --mlcomplete 2
New scsi logging level:
dev.scsi.logging_level = 9216
SCSI_LOG_ERROR=0
SCSI_LOG_TIMEOUT=0
SCSI_LOG_SCAN=0
SCSI_LOG_MLQUEUE=2
SCSI_LOG_MLCOMPLETE=2
SCSI_LOG_LLQUEUE=0
SCSI_LOG_LLCOMPLETE=0
SCSI_LOG_HLQUEUE=0
SCSI_LOG_HLCOMPLETE=0
SCSI_LOG_IOCTL=0

The output shows Test Unit Ready commands that are issued by the path checker of multipathd (from multipath-tools). In contrast to the previous example with additional messages (in bold):

May 17 12:07:56 t2945012 kernel: sd 0:0:0:0: send                  sd 0:0:0:0:
May 17 12:07:56 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:07:56 t2945012 kernel: sd 0:0:0:0: done SUCCESS        0 sd 0:0:0:0:
May 17 12:07:56 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:07:57 t2945012 kernel: sd 1:0:0:0: send                  sd 1:0:0:0:
May 17 12:07:57 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:07:57 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:07:57 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00

Example 5 shows how to set the log level for SCSI_LOG_MLQUEUE, SCSI_LOG_MLCOMPLETE and SCSI_LOG_IOCTL to 2 to log command queuing and command completion in the SCSI mid-layer and IOCTL information.

#>scsi_logging_level -s --mlqueue 2 --mlcomplete 2 --ioctl 2
New scsi logging level:
dev.scsi.logging_level = 268444672
SCSI_LOG_ERROR=0
SCSI_LOG_TIMEOUT=0
SCSI_LOG_SCAN=0
SCSI_LOG_MLQUEUE=2
SCSI_LOG_MLCOMPLETE=2
SCSI_LOG_LLQUEUE=0
SCSI_LOG_LLCOMPLETE=0
SCSI_LOG_HLQUEUE=0
SCSI_LOG_HLCOMPLETE=0
SCSI_LOG_IOCTL=2

The output shows Test Unit Ready commands that are issued by the path checker of multipathd (from multipath-tools). In contrast to the previous example, this one has additional messages (in bold):

May 17 12:08:17 t2945012 kernel: sd_ioctl: disk=sda, cmd=0x2285
May 17 12:08:17 t2945012 kernel: sd 0:0:0:0: send                  sd 0:0:0:0:
May 17 12:08:17 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:08:17 t2945012 kernel: sd 0:0:0:0: done SUCCESS        0 sd 0:0:0:0:
May 17 12:08:17 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:08:18 t2945012 kernel: sd_ioctl: disk=sdb, cmd=0x2285
May 17 12:08:18 t2945012 kernel: sd 1:0:0:0: send                  sd 1:0:0:0:
May 17 12:08:18 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00
May 17 12:08:18 t2945012 kernel: sd 1:0:0:0: done SUCCESS        0 sd 1:0:0:0:
May 17 12:08:18 t2945012 kernel:         command: Test Unit Ready: 00 00 00 00 00 00

Example 6 shows how to switch off all SCSI logging levels:

#>scsi_logging_level -s -a 0
New scsi logging level:
dev.scsi.logging_level = 0
SCSI_LOG_ERROR=0
SCSI_LOG_TIMEOUT=0
SCSI_LOG_SCAN=0
SCSI_LOG_MLQUEUE=0
SCSI_LOG_MLCOMPLETE=0
SCSI_LOG_LLQUEUE=0
SCSI_LOG_LLCOMPLETE=0
SCSI_LOG_HLQUEUE=0
SCSI_LOG_HLCOMPLETE=0
SCSI_LOG_IOCTL=0