* [PATCH v2 1/2] scsi: core: Add KUnit tests for scsi_logging.c
2026-08-31 17:58 [PATCH v2 0/2] scsi: core: Optimize the SCSI printk() variants Bart Van Assche
@ 2026-08-31 17:58 ` Bart Van Assche
2026-08-31 20:05 ` sashiko-bot
2026-08-31 17:58 ` [PATCH v2 2/2] scsi: core: Eliminate scsi_log_{reserve,release}_buffer() Bart Van Assche
1 sibling, 1 reply; 4+ messages in thread
From: Bart Van Assche @ 2026-08-31 17:58 UTC (permalink / raw)
To: Martin K . Petersen
Cc: linux-scsi, John Garry, Bart Van Assche, James E.J. Bottomley,
Martin K. Petersen
Add regression unit tests for the functions in drivers/scsi/scsi_logging.c
that call dev_printk().
Implement a macro redefinition approach where dev_printk() is intercepted
when CONFIG_SCSI_LOGGING_KUNIT_TEST is enabled, allowing the test suite to
capture the emitted log levels, target device references, and formatted
log strings into a test buffer without side effects.
Add test cases covering:
- sdev_prefix_printk() with and without device name prefix.
- scmd_printk() with tag only, disk name and tag, and untagged commands.
- scsi_print_command() with 6, 10, 16, and multi-line 32-byte CDBs,
as well as vendor-specific and reserved opcodes.
- scsi_print_sense_hdr() with standard, descriptor, and deferred formats.
- __scsi_print_sense() with normalized sense data and raw hex dumps.
- scsi_print_sense() with command-attached sense buffers.
- scsi_print_result() with custom messages, default messages, unknown
dispositions, and unknown hostbyte statuses.
Signed-off-by: Bart Van Assche <bvanassche@acm.org>
---
drivers/scsi/Kconfig | 9 +
drivers/scsi/scsi_logging.c | 30 +++
drivers/scsi/scsi_logging_test.c | 422 +++++++++++++++++++++++++++++++
3 files changed, 461 insertions(+)
create mode 100644 drivers/scsi/scsi_logging_test.c
diff --git a/drivers/scsi/Kconfig b/drivers/scsi/Kconfig
index 4a2af0f702e1..8c2a44b55900 100644
--- a/drivers/scsi/Kconfig
+++ b/drivers/scsi/Kconfig
@@ -76,6 +76,15 @@ config SCSI_LIB_KUNIT_TEST
If unsure say N.
+config SCSI_LOGGING_KUNIT_TEST
+ bool "KUnit tests for SCSI logging functions" if !KUNIT_ALL_TESTS
+ depends on SCSI && KUNIT=y && SCSI_CONSTANTS
+ default KUNIT_ALL_TESTS
+ help
+ Run SCSI Mid Layer's KUnit tests for scsi_logging.
+
+ If unsure say N.
+
comment "SCSI support type (disk, tape, CD-ROM)"
depends on SCSI
diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
index 3cd0d3074085..3bff4dea4c6a 100644
--- a/drivers/scsi/scsi_logging.c
+++ b/drivers/scsi/scsi_logging.c
@@ -15,6 +15,32 @@
#include <scsi/scsi_eh.h>
#include <scsi/scsi_dbg.h>
+#if IS_ENABLED(CONFIG_SCSI_LOGGING_KUNIT_TEST)
+static void (*scsi_logging_test_dev_printk)(const char *level,
+ const struct device *dev,
+ const char *fmt, va_list args);
+
+static void scsi_logging_dev_printk(const char *level, const struct device *dev,
+ const char *fmt, ...)
+{
+ va_list args;
+
+ va_start(args, fmt);
+ if (unlikely(scsi_logging_test_dev_printk)) {
+ scsi_logging_test_dev_printk(level, dev, fmt, args);
+ } else {
+ struct va_format vaf = { .fmt = fmt, .va = &args };
+
+ _dev_printk(level, dev, "%pV", &vaf);
+ }
+ va_end(args);
+}
+
+#undef dev_printk
+#define dev_printk(level, dev, fmt, ...) \
+ scsi_logging_dev_printk(level, dev, fmt, ##__VA_ARGS__)
+#endif
+
static char *scsi_log_reserve_buffer(size_t *len)
{
*len = 128;
@@ -436,3 +462,7 @@ void scsi_print_result(struct scsi_cmnd *cmd, const char *msg, int disposition)
scsi_log_release_buffer(logbuf);
}
EXPORT_SYMBOL(scsi_print_result);
+
+#if IS_ENABLED(CONFIG_SCSI_LOGGING_KUNIT_TEST)
+#include "scsi_logging_test.c"
+#endif
diff --git a/drivers/scsi/scsi_logging_test.c b/drivers/scsi/scsi_logging_test.c
new file mode 100644
index 000000000000..1dcebc383052
--- /dev/null
+++ b/drivers/scsi/scsi_logging_test.c
@@ -0,0 +1,422 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * KUnit tests for scsi_logging.c.
+ *
+ * Copyright 2026 Google LLC
+ */
+#include <kunit/test.h>
+#include <linux/blkdev.h>
+#include <scsi/scsi.h>
+#include <scsi/scsi_cmnd.h>
+#include <scsi/scsi_dbg.h>
+#include <scsi/scsi_device.h>
+#include <scsi/scsi_eh.h>
+#include <scsi/scsi_proto.h>
+
+#define MAX_CAPTURED_LINES 16
+#define MAX_LINE_LEN 256
+
+struct captured_dev_printk {
+ const char *level;
+ const struct device *dev;
+ char msg[MAX_LINE_LEN];
+};
+
+static struct captured_dev_printk captured_logs[MAX_CAPTURED_LINES];
+static int captured_count;
+
+static void test_capture_dev_printk(const char *level, const struct device *dev,
+ const char *fmt, va_list args)
+{
+ if (captured_count < MAX_CAPTURED_LINES) {
+ captured_logs[captured_count].level = level;
+ captured_logs[captured_count].dev = dev;
+ vscnprintf(captured_logs[captured_count].msg,
+ sizeof(captured_logs[captured_count].msg), fmt,
+ args);
+ captured_count++;
+ }
+}
+
+static void scsi_logging_test_reset(void)
+{
+ captured_count = 0;
+ memset(captured_logs, 0, sizeof(captured_logs));
+}
+
+static int scsi_logging_test_init(struct kunit *test)
+{
+ scsi_logging_test_reset();
+ scsi_logging_test_dev_printk = test_capture_dev_printk;
+ return 0;
+}
+
+static void scsi_logging_test_exit(struct kunit *test)
+{
+ scsi_logging_test_dev_printk = NULL;
+}
+
+struct test_scsi_cmd {
+ struct request rq;
+ struct scsi_cmnd cmd;
+};
+
+struct test_fixture {
+ struct scsi_device *sdev;
+ struct gendisk *disk;
+ struct request_queue *q;
+ struct test_scsi_cmd *tscmd;
+};
+
+static struct test_fixture *scsi_logging_create_fixture(struct kunit *test)
+{
+ struct test_fixture *tf = kunit_kzalloc(test, sizeof(*tf), GFP_KERNEL);
+
+ KUNIT_ASSERT_NOT_NULL(test, tf);
+
+ tf->sdev = kunit_kzalloc(test, sizeof(*tf->sdev), GFP_KERNEL);
+ KUNIT_ASSERT_NOT_NULL(test, tf->sdev);
+
+ tf->disk = kunit_kzalloc(test, sizeof(*tf->disk), GFP_KERNEL);
+ KUNIT_ASSERT_NOT_NULL(test, tf->disk);
+
+ tf->q = kunit_kzalloc(test, sizeof(*tf->q), GFP_KERNEL);
+ KUNIT_ASSERT_NOT_NULL(test, tf->q);
+
+ tf->tscmd = kunit_kzalloc(test, sizeof(*tf->tscmd), GFP_KERNEL);
+ KUNIT_ASSERT_NOT_NULL(test, tf->tscmd);
+
+ tf->q->disk = tf->disk;
+ tf->tscmd->cmd.device = tf->sdev;
+ strscpy(tf->disk->disk_name, "sda", sizeof(tf->disk->disk_name));
+
+ return tf;
+}
+
+static void test_sdev_prefix_printk(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+
+ /* NULL sdev should produce no output */
+ sdev_prefix_printk(KERN_INFO, NULL, "test", "should not print");
+ KUNIT_EXPECT_EQ(test, captured_count, 0);
+
+ /* Without name prefix */
+ sdev_prefix_printk(KERN_WARNING, tf->sdev, NULL, "warning %d", 42);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].level, KERN_WARNING);
+ KUNIT_EXPECT_PTR_EQ(test, captured_logs[0].dev, &tf->sdev->sdev_gendev);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg, "warning 42");
+
+ /* With name prefix */
+ scsi_logging_test_reset();
+ sdev_prefix_printk(KERN_ERR, tf->sdev, "adapter0", "error code %d", -5);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].level, KERN_ERR);
+ KUNIT_EXPECT_PTR_EQ(test, captured_logs[0].dev, &tf->sdev->sdev_gendev);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[adapter0] error code -5");
+}
+
+static void test_scmd_printk(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+
+ /* NULL scmd should produce no output */
+ scmd_printk(KERN_INFO, NULL, "should not print");
+ KUNIT_EXPECT_EQ(test, captured_count, 0);
+
+ /* scmd with tag but no disk name */
+ tf->tscmd->rq.q = NULL;
+ tf->tscmd->rq.tag = 5;
+ scmd_printk(KERN_INFO, &tf->tscmd->cmd, "test msg %d", 10);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].level, KERN_INFO);
+ KUNIT_EXPECT_PTR_EQ(test, captured_logs[0].dev, &tf->sdev->sdev_gendev);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg, "tag#5 test msg 10");
+
+ /* scmd with disk name and tag */
+ scsi_logging_test_reset();
+ tf->tscmd->rq.q = tf->q;
+ tf->tscmd->rq.tag = 12;
+ scmd_printk(KERN_ERR, &tf->tscmd->cmd, "failed status");
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].level, KERN_ERR);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[sda] tag#12 failed status");
+
+ /* scmd with disk name but no tag (tag < 0) */
+ scsi_logging_test_reset();
+ tf->tscmd->rq.tag = -1;
+ scmd_printk(KERN_NOTICE, &tf->tscmd->cmd, "no tag notification");
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[sda] no tag notification");
+}
+
+static void test_scsi_print_command(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+ static const unsigned char cdb6[6] = { 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x00 };
+ static const unsigned char cdb10[10] = { 0x28, 0x00, 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x00, 0x08, 0x00 };
+ static const unsigned char cdb16[16] = { 0x88, 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x08, 0x00 };
+ static const unsigned char cdb32[32] = {
+ 0x7f, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x18,
+ 0x00, 0x09, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
+ 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x08, 0x00
+ };
+ static const unsigned char cdb_vendor[6] = { 0xc0, 0x00, 0x00,
+ 0x00, 0x00, 0x00 };
+ static const unsigned char cdb_reserved[6] = { 0x60, 0x00, 0x00,
+ 0x00, 0x00, 0x00 };
+
+ tf->tscmd->rq.q = tf->q;
+ tf->tscmd->rq.tag = 1;
+
+ /* 6-byte TEST UNIT READY */
+ memcpy(tf->tscmd->cmd.cmnd, cdb6, sizeof(cdb6));
+ tf->tscmd->cmd.cmd_len = sizeof(cdb6);
+ scsi_print_command(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#1 CDB: Test Unit Ready 00 00 00 00 00 00");
+
+ /* 10-byte READ(10) */
+ scsi_logging_test_reset();
+ memcpy(tf->tscmd->cmd.cmnd, cdb10, sizeof(cdb10));
+ tf->tscmd->cmd.cmd_len = sizeof(cdb10);
+ scsi_print_command(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00");
+
+ /* 16-byte READ(16) */
+ scsi_logging_test_reset();
+ memcpy(tf->tscmd->cmd.cmnd, cdb16, sizeof(cdb16));
+ tf->tscmd->cmd.cmd_len = sizeof(cdb16);
+ scsi_print_command(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#1 CDB: Read(16) 88 00 00 00 00 00 00 00 00 00 00 00 00 00 08 00");
+
+ /* 32-byte CDB (CDB len > 16 generates multiple printk lines) */
+ scsi_logging_test_reset();
+ memcpy(tf->tscmd->cmd.cmnd, cdb32, sizeof(cdb32));
+ tf->tscmd->cmd.cmd_len = sizeof(cdb32);
+ scsi_print_command(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 3);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[sda] tag#1 CDB: Read(32)\n");
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[1].msg,
+ "[sda] tag#1 CDB[00]: 7f 00 00 00 00 00 00 18 00 09 00 00 00 00 00 00");
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[2].msg,
+ "[sda] tag#1 CDB[10]: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 08 00");
+
+ /* Vendor-specific opcode */
+ scsi_logging_test_reset();
+ memcpy(tf->tscmd->cmd.cmnd, cdb_vendor, sizeof(cdb_vendor));
+ tf->tscmd->cmd.cmd_len = sizeof(cdb_vendor);
+ scsi_print_command(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#1 CDB: opcode=0xc0 (vendor) c0 00 00 00 00 00");
+
+ /* Reserved opcode */
+ scsi_logging_test_reset();
+ memcpy(tf->tscmd->cmd.cmnd, cdb_reserved, sizeof(cdb_reserved));
+ tf->tscmd->cmd.cmd_len = sizeof(cdb_reserved);
+ scsi_print_command(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#1 CDB: opcode=0x60 (reserved) 60 00 00 00 00 00");
+}
+
+static void test_scsi_print_sense_hdr(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+ struct scsi_sense_hdr sshdr = {
+ .response_code = 0x70,
+ .sense_key = ILLEGAL_REQUEST,
+ .asc = 0x20,
+ .ascq = 0x00,
+ };
+
+ scsi_print_sense_hdr(tf->sdev, "sda", &sshdr);
+ KUNIT_EXPECT_EQ(test, captured_count, 2);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[sda] Sense Key : Illegal Request [current] ");
+ KUNIT_EXPECT_STREQ(test, captured_logs[1].msg,
+ "[sda] Add. Sense: Invalid command operation code");
+
+ /* Deferred and descriptor format */
+ scsi_logging_test_reset();
+ sshdr.response_code = 0x73;
+ sshdr.sense_key = UNIT_ATTENTION;
+ sshdr.asc = 0x29;
+ sshdr.ascq = 0x00;
+ scsi_print_sense_hdr(tf->sdev, "sdb", &sshdr);
+ KUNIT_EXPECT_EQ(test, captured_count, 2);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sdb] Sense Key : Unit Attention [deferred] [descriptor] ");
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[1].msg,
+ "[sdb] Add. Sense: Power on, reset, or bus device reset occurred");
+
+ /* Additional sense: Invalid token operation, remote rod token creation not supported */
+ scsi_logging_test_reset();
+ sshdr.response_code = 0x70;
+ sshdr.sense_key = ILLEGAL_REQUEST;
+ sshdr.asc = 0x23;
+ sshdr.ascq = 0x03;
+ scsi_print_sense_hdr(tf->sdev, "sdc", &sshdr);
+ KUNIT_EXPECT_EQ(test, captured_count, 2);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sdc] Sense Key : Illegal Request [current] ");
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[1].msg,
+ "[sdc] Add. Sense: Invalid token operation, remote rod token creation not supported");
+}
+
+static void test_scsi_print_sense_buffer(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+ unsigned char normalized_sense[18] = {
+ [0] = 0x70, [2] = NOT_READY, [7] = 10, [12] = 0x04, [13] = 0x01,
+ };
+ unsigned char raw_sense[16] = { 0 };
+
+ /* Normalized sense buffer */
+ __scsi_print_sense(tf->sdev, "sda", normalized_sense,
+ sizeof(normalized_sense));
+ KUNIT_EXPECT_EQ(test, captured_count, 2);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[sda] Sense Key : Not Ready [current] ");
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[1].msg,
+ "[sda] Add. Sense: Logical unit is in process of becoming ready");
+
+ /* Unnormalized / raw sense buffer dumped in hex */
+ scsi_logging_test_reset();
+ __scsi_print_sense(tf->sdev, "sda", raw_sense, sizeof(raw_sense));
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00");
+}
+
+static void test_scsi_print_sense_cmd(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+ unsigned char *sense_buffer =
+ kunit_kzalloc(test, SCSI_SENSE_BUFFERSIZE, GFP_KERNEL);
+
+ KUNIT_ASSERT_NOT_NULL(test, sense_buffer);
+ sense_buffer[0] = 0x70;
+ sense_buffer[2] = UNIT_ATTENTION;
+ sense_buffer[7] = 10;
+ sense_buffer[12] = 0x28;
+ sense_buffer[13] = 0x00;
+
+ tf->tscmd->cmd.sense_buffer = sense_buffer;
+ tf->tscmd->rq.q = tf->q;
+ tf->tscmd->rq.tag = 3;
+
+ scsi_print_sense(&tf->tscmd->cmd);
+ KUNIT_EXPECT_EQ(test, captured_count, 2);
+ KUNIT_EXPECT_STREQ(test, captured_logs[0].msg,
+ "[sda] tag#3 Sense Key : Unit Attention [current] ");
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[1].msg,
+ "[sda] tag#3 Add. Sense: Not ready to ready change, medium may have changed");
+}
+
+static void test_scsi_print_result(struct kunit *test)
+{
+ struct test_fixture *tf = scsi_logging_create_fixture(test);
+
+ tf->tscmd->rq.q = tf->q;
+ tf->tscmd->rq.tag = 4;
+ tf->tscmd->cmd.result = (DID_OK << 16) | SAM_STAT_CHECK_CONDITION;
+ tf->tscmd->cmd.jiffies_at_alloc = jiffies - 5 * HZ;
+
+ /* Result with message */
+ scsi_print_result(&tf->tscmd->cmd, "Failed command", FAILED);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#4 Failed command: FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=5s");
+
+ /* Result without message */
+ scsi_logging_test_reset();
+ scsi_print_result(&tf->tscmd->cmd, NULL, SUCCESS);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#4 SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=5s");
+
+ /* Result with DID_TRANSPORT_DISRUPTED hostbyte */
+ scsi_logging_test_reset();
+ tf->tscmd->cmd.result = (DID_TRANSPORT_DISRUPTED << 16) | SAM_STAT_CHECK_CONDITION;
+ scsi_print_result(&tf->tscmd->cmd, "Transport disrupted", NEEDS_RETRY);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#4 Transport disrupted: NEEDS_RETRY Result: hostbyte=DID_TRANSPORT_DISRUPTED driverbyte=DRIVER_OK cmd_age=5s");
+
+ /* Result with hostbyte without known string */
+ scsi_logging_test_reset();
+ tf->tscmd->cmd.result = (0x1f << 16);
+ scsi_print_result(&tf->tscmd->cmd, "Unknown hostbyte", FAILED);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#4 Unknown hostbyte: FAILED Result: hostbyte=0x1f driverbyte=DRIVER_OK cmd_age=5s");
+
+ /* Result with unknown disposition */
+ scsi_logging_test_reset();
+ tf->tscmd->cmd.result = (DID_OK << 16);
+ scsi_print_result(&tf->tscmd->cmd, "Unknown disp", 0x7f);
+ KUNIT_EXPECT_EQ(test, captured_count, 1);
+ KUNIT_EXPECT_STREQ(
+ test, captured_logs[0].msg,
+ "[sda] tag#4 Unknown disp: UNKNOWN(0x7f) Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=5s");
+}
+
+static struct kunit_case scsi_logging_test_cases[] = {
+ KUNIT_CASE(test_sdev_prefix_printk),
+ KUNIT_CASE(test_scmd_printk),
+ KUNIT_CASE(test_scsi_print_command),
+ KUNIT_CASE(test_scsi_print_sense_hdr),
+ KUNIT_CASE(test_scsi_print_sense_buffer),
+ KUNIT_CASE(test_scsi_print_sense_cmd),
+ KUNIT_CASE(test_scsi_print_result),
+ {}
+};
+
+static struct kunit_suite scsi_logging_test_suite = {
+ .name = "scsi_logging",
+ .init = scsi_logging_test_init,
+ .exit = scsi_logging_test_exit,
+ .test_cases = scsi_logging_test_cases,
+};
+
+kunit_test_suite(scsi_logging_test_suite);
+
+MODULE_DESCRIPTION("SCSI logging unit tests");
+MODULE_AUTHOR("Bart Van Assche");
+MODULE_LICENSE("GPL");
^ permalink raw reply related [flat|nested] 4+ messages in thread* [PATCH v2 2/2] scsi: core: Eliminate scsi_log_{reserve,release}_buffer()
2026-08-31 17:58 [PATCH v2 0/2] scsi: core: Optimize the SCSI printk() variants Bart Van Assche
2026-08-31 17:58 ` [PATCH v2 1/2] scsi: core: Add KUnit tests for scsi_logging.c Bart Van Assche
@ 2026-08-31 17:58 ` Bart Van Assche
1 sibling, 0 replies; 4+ messages in thread
From: Bart Van Assche @ 2026-08-31 17:58 UTC (permalink / raw)
To: Martin K . Petersen
Cc: linux-scsi, John Garry, Bart Van Assche, Hannes Reinecke,
James E.J. Bottomley, Martin K. Petersen
The SCSI logging functions allocate a temporary buffer. This approach has
multiple disadvantages:
- Runtime overhead.
- Truncation of log messages to 127 characters.
- Messages are discarded if buffer allocation fails.
Hence this patch that eliminates temporary buffer allocations. Instead,
use struct va_format (%pV) and format directly with dev_printk().
Introduce sdev_tag_prefix_vprintk() and sdev_tag_prefix_printk() helper
functions that emit dev_printk() messages with optional device name
([<name>]) and request tag (tag#<tag>) prefixes.
Convert sdev_prefix_printk(), scmd_printk(), scsi_print_command(),
scsi_log_dump_sense(), scsi_log_print_sense_hdr(), and scsi_print_result()
to use these helpers. Use the %*ph format specifier to format CDB and
sense hex buffers directly.
Remove scsi_log_reserve_buffer(), scsi_log_release_buffer(), and
sdev_format_header().
This patch has been generated by asking Gemini 3.7 to eliminate the
scsi_log_*_buffer() functions from the scsi_logging.c file, followed by
some minor manual improvements.
Cc: Hannes Reinecke <hare@suse.de>
Cc: John Garry <john.g.garry@oracle.com>
Signed-off-by: Bart Van Assche <bvanassche@acm.org>
---
drivers/scsi/scsi_logging.c | 263 ++++++++++++------------------------
1 file changed, 90 insertions(+), 173 deletions(-)
diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
index 3bff4dea4c6a..0991e5cb305a 100644
--- a/drivers/scsi/scsi_logging.c
+++ b/drivers/scsi/scsi_logging.c
@@ -41,17 +41,6 @@ static void scsi_logging_dev_printk(const char *level, const struct device *dev,
scsi_logging_dev_printk(level, dev, fmt, ##__VA_ARGS__)
#endif
-static char *scsi_log_reserve_buffer(size_t *len)
-{
- *len = 128;
- return kmalloc(*len, GFP_ATOMIC);
-}
-
-static void scsi_log_release_buffer(char *bufptr)
-{
- kfree(bufptr);
-}
-
static inline const char *scmd_name(struct scsi_cmnd *scmd)
{
const struct request *rq = scsi_cmd_to_rq(scmd);
@@ -61,48 +50,57 @@ static inline const char *scmd_name(struct scsi_cmnd *scmd)
return rq->q->disk->disk_name;
}
-static size_t sdev_format_header(char *logbuf, size_t logbuf_len,
- const char *name, int tag)
+static void __printf(5, 0)
+sdev_tag_prefix_vprintk(const char *level, const struct scsi_device *sdev,
+ const char *name, int tag, const char *fmt,
+ va_list *args)
{
- size_t off = 0;
+ const struct device *dev;
+ struct va_format vaf = {
+ .fmt = fmt,
+ .va = args,
+ };
- if (name)
- off += scnprintf(logbuf + off, logbuf_len - off,
- "[%s] ", name);
+ if (!sdev)
+ return;
- if (WARN_ON(off >= logbuf_len))
- return off;
+ dev = &sdev->sdev_gendev;
+ if (name) {
+ if (tag >= 0)
+ dev_printk(level, dev, "[%s] tag#%d %pV", name, tag,
+ &vaf);
+ else
+ dev_printk(level, dev, "[%s] %pV", name, &vaf);
+ } else {
+ if (tag >= 0)
+ dev_printk(level, dev, "tag#%d %pV", tag, &vaf);
+ else
+ dev_printk(level, dev, "%pV", &vaf);
+ }
+}
- if (tag >= 0)
- off += scnprintf(logbuf + off, logbuf_len - off,
- "tag#%d ", tag);
- return off;
+static void __printf(5, 6)
+sdev_tag_prefix_printk(const char *level, const struct scsi_device *sdev,
+ const char *name, int tag, const char *fmt, ...)
+{
+ va_list args;
+
+ va_start(args, fmt);
+ sdev_tag_prefix_vprintk(level, sdev, name, tag, fmt, &args);
+ va_end(args);
}
void sdev_prefix_printk(const char *level, const struct scsi_device *sdev,
const char *name, const char *fmt, ...)
{
va_list args;
- char *logbuf;
- size_t off = 0, logbuf_len;
if (!sdev)
return;
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
- return;
-
- if (name)
- off += scnprintf(logbuf + off, logbuf_len - off,
- "[%s] ", name);
- if (!WARN_ON(off >= logbuf_len)) {
- va_start(args, fmt);
- off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
- va_end(args);
- }
- dev_printk(level, &sdev->sdev_gendev, "%s", logbuf);
- scsi_log_release_buffer(logbuf);
+ va_start(args, fmt);
+ sdev_tag_prefix_vprintk(level, sdev, name, -1, fmt, &args);
+ va_end(args);
}
EXPORT_SYMBOL(sdev_prefix_printk);
@@ -110,24 +108,14 @@ void scmd_printk(const char *level, struct scsi_cmnd *scmd, const char *fmt,
...)
{
va_list args;
- char *logbuf;
- size_t off = 0, logbuf_len;
if (!scmd)
return;
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
- return;
- off = sdev_format_header(logbuf, logbuf_len, scmd_name(scmd),
- scsi_cmd_to_rq(scmd)->tag);
- if (off < logbuf_len) {
- va_start(args, fmt);
- off += vscnprintf(logbuf + off, logbuf_len - off, fmt, args);
- va_end(args);
- }
- dev_printk(level, &scmd->device->sdev_gendev, "%s", logbuf);
- scsi_log_release_buffer(logbuf);
+ va_start(args, fmt);
+ sdev_tag_prefix_vprintk(level, scmd->device, scmd_name(scmd),
+ scsi_cmd_to_rq(scmd)->tag, fmt, &args);
+ va_end(args);
}
EXPORT_SYMBOL(scmd_printk);
@@ -205,60 +193,34 @@ EXPORT_SYMBOL(__scsi_format_command);
void scsi_print_command(struct scsi_cmnd *cmd)
{
+ char opcode_name[64];
int k;
- char *logbuf;
- size_t off, logbuf_len;
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
+ if (!cmd)
return;
- off = sdev_format_header(logbuf, logbuf_len,
- scmd_name(cmd), scsi_cmd_to_rq(cmd)->tag);
- if (off >= logbuf_len)
- goto out_printk;
- off += scnprintf(logbuf + off, logbuf_len - off, "CDB: ");
- if (WARN_ON(off >= logbuf_len))
- goto out_printk;
-
- off += scsi_format_opcode_name(logbuf + off, logbuf_len - off,
- cmd->cmnd);
- if (off >= logbuf_len)
- goto out_printk;
+ scsi_format_opcode_name(opcode_name, sizeof(opcode_name), cmd->cmnd);
- /* print out all bytes in cdb */
if (cmd->cmd_len > 16) {
/* Print opcode in one line and use separate lines for CDB */
- off += scnprintf(logbuf + off, logbuf_len - off, "\n");
- dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
+ sdev_tag_prefix_printk(KERN_INFO, cmd->device, scmd_name(cmd),
+ scsi_cmd_to_rq(cmd)->tag, "CDB: %s\n",
+ opcode_name);
for (k = 0; k < cmd->cmd_len; k += 16) {
- size_t linelen = min(cmd->cmd_len - k, 16);
-
- off = sdev_format_header(logbuf, logbuf_len,
- scmd_name(cmd),
- scsi_cmd_to_rq(cmd)->tag);
- if (!WARN_ON(off > logbuf_len - 58)) {
- off += scnprintf(logbuf + off, logbuf_len - off,
- "CDB[%02x]: ", k);
- hex_dump_to_buffer(&cmd->cmnd[k], linelen,
- 16, 1, logbuf + off,
- logbuf_len - off, false);
- }
- dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s",
- logbuf);
+ size_t linelen = min_t(size_t, cmd->cmd_len - k, 16);
+
+ sdev_tag_prefix_printk(KERN_INFO, cmd->device,
+ scmd_name(cmd),
+ scsi_cmd_to_rq(cmd)->tag,
+ "CDB[%02x]: %*ph", k,
+ (int)linelen, &cmd->cmnd[k]);
}
- goto out;
- }
- if (!WARN_ON(off > logbuf_len - 49)) {
- off += scnprintf(logbuf + off, logbuf_len - off, " ");
- hex_dump_to_buffer(cmd->cmnd, cmd->cmd_len, 16, 1,
- logbuf + off, logbuf_len - off,
- false);
+ } else {
+ sdev_tag_prefix_printk(KERN_INFO, cmd->device, scmd_name(cmd),
+ scsi_cmd_to_rq(cmd)->tag, "CDB: %s %*ph",
+ opcode_name, (int)cmd->cmd_len,
+ cmd->cmnd);
}
-out_printk:
- dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
-out:
- scsi_log_release_buffer(logbuf);
}
EXPORT_SYMBOL(scsi_print_command);
@@ -318,51 +280,29 @@ static void
scsi_log_dump_sense(const struct scsi_device *sdev, const char *name, int tag,
const unsigned char *sense_buffer, int sense_len)
{
- char *logbuf;
- size_t logbuf_len;
int i;
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
- return;
-
for (i = 0; i < sense_len; i += 16) {
int len = min(sense_len - i, 16);
- size_t off;
-
- off = sdev_format_header(logbuf, logbuf_len,
- name, tag);
- hex_dump_to_buffer(&sense_buffer[i], len, 16, 1,
- logbuf + off, logbuf_len - off,
- false);
- dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf);
+
+ sdev_tag_prefix_printk(KERN_INFO, sdev, name, tag, "%*ph", len,
+ &sense_buffer[i]);
}
- scsi_log_release_buffer(logbuf);
}
static void
scsi_log_print_sense_hdr(const struct scsi_device *sdev, const char *name,
int tag, const struct scsi_sense_hdr *sshdr)
{
- char *logbuf;
- size_t off, logbuf_len;
+ char sense_hdr[64];
+ char extd_sense[96];
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
- return;
- off = sdev_format_header(logbuf, logbuf_len, name, tag);
- off += scsi_format_sense_hdr(logbuf + off, logbuf_len - off, sshdr);
- dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf);
- scsi_log_release_buffer(logbuf);
+ scsi_format_sense_hdr(sense_hdr, sizeof(sense_hdr), sshdr);
+ sdev_tag_prefix_printk(KERN_INFO, sdev, name, tag, "%s", sense_hdr);
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
- return;
- off = sdev_format_header(logbuf, logbuf_len, name, tag);
- off += scsi_format_extd_sense(logbuf + off, logbuf_len - off,
- sshdr->asc, sshdr->ascq);
- dev_printk(KERN_INFO, &sdev->sdev_gendev, "%s", logbuf);
- scsi_log_release_buffer(logbuf);
+ scsi_format_extd_sense(extd_sense, sizeof(extd_sense), sshdr->asc,
+ sshdr->ascq);
+ sdev_tag_prefix_printk(KERN_INFO, sdev, name, tag, "%s", extd_sense);
}
static void
@@ -407,59 +347,36 @@ EXPORT_SYMBOL(scsi_print_sense);
void scsi_print_result(struct scsi_cmnd *cmd, const char *msg, int disposition)
{
- char *logbuf;
- size_t off, logbuf_len;
const char *mlret_string = scsi_mlreturn_string(disposition);
const char *hb_string = scsi_hostbyte_string(cmd->result);
unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) / HZ;
+ char mlret_buf[32];
+ char hb_buf[40];
- logbuf = scsi_log_reserve_buffer(&logbuf_len);
- if (!logbuf)
- return;
-
- off = sdev_format_header(logbuf, logbuf_len, scmd_name(cmd),
- scsi_cmd_to_rq(cmd)->tag);
-
- if (off >= logbuf_len)
- goto out_printk;
-
- if (msg) {
- off += scnprintf(logbuf + off, logbuf_len - off,
- "%s: ", msg);
- if (WARN_ON(off >= logbuf_len))
- goto out_printk;
- }
if (mlret_string)
- off += scnprintf(logbuf + off, logbuf_len - off,
- "%s ", mlret_string);
+ snprintf(mlret_buf, sizeof(mlret_buf), "%s", mlret_string);
else
- off += scnprintf(logbuf + off, logbuf_len - off,
- "UNKNOWN(0x%02x) ", disposition);
- if (WARN_ON(off >= logbuf_len))
- goto out_printk;
-
- off += scnprintf(logbuf + off, logbuf_len - off, "Result: ");
- if (WARN_ON(off >= logbuf_len))
- goto out_printk;
+ snprintf(mlret_buf, sizeof(mlret_buf), "UNKNOWN(0x%02x)",
+ disposition);
if (hb_string)
- off += scnprintf(logbuf + off, logbuf_len - off,
- "hostbyte=%s ", hb_string);
+ snprintf(hb_buf, sizeof(hb_buf), "hostbyte=%s", hb_string);
else
- off += scnprintf(logbuf + off, logbuf_len - off,
- "hostbyte=0x%02x ", host_byte(cmd->result));
- if (WARN_ON(off >= logbuf_len))
- goto out_printk;
-
- off += scnprintf(logbuf + off, logbuf_len - off,
- "driverbyte=DRIVER_OK ");
-
- off += scnprintf(logbuf + off, logbuf_len - off,
- "cmd_age=%lus", cmd_age);
-
-out_printk:
- dev_printk(KERN_INFO, &cmd->device->sdev_gendev, "%s", logbuf);
- scsi_log_release_buffer(logbuf);
+ snprintf(hb_buf, sizeof(hb_buf), "hostbyte=0x%02x",
+ host_byte(cmd->result));
+
+ if (msg)
+ sdev_tag_prefix_printk(
+ KERN_INFO, cmd->device, scmd_name(cmd),
+ scsi_cmd_to_rq(cmd)->tag,
+ "%s: %s Result: %s driverbyte=DRIVER_OK cmd_age=%lus",
+ msg, mlret_buf, hb_buf, cmd_age);
+ else
+ sdev_tag_prefix_printk(
+ KERN_INFO, cmd->device, scmd_name(cmd),
+ scsi_cmd_to_rq(cmd)->tag,
+ "%s Result: %s driverbyte=DRIVER_OK cmd_age=%lus",
+ mlret_buf, hb_buf, cmd_age);
}
EXPORT_SYMBOL(scsi_print_result);
^ permalink raw reply related [flat|nested] 4+ messages in thread