[PATCH v2 0/2] scsi: core: Optimize the SCSI printk() variants

[PATCH v2 0/2] scsi: core: Optimize the SCSI printk() variants

[Bart Van Assche]

Hi Martin,

The SCSI logging functions currently allocate a temporary 128-byte
buffer via kmalloc(..., GFP_ATOMIC). This design has several drawbacks:
 - Runtime memory allocation and freeing overhead on logging paths.
 - Truncation of log messages to 127 characters.
 - Discarded log messages if the buffer allocation fails under memory
   pressure.

This patch series eliminates temporary buffer allocations from
scsi_logging.c by formatting messages directly using struct va_format
(%pV) and dev_printk(), as well as formatting hex buffers directly
with %*ph.

To ensure formatting and logging behavior remain free of regressions,
the first patch introduces a comprehensive KUnit test suite for the
SCSI logging functions. The second patch refactors scsi_logging.c to use
the direct formatting helpers.

Please consider applying this series.

Thanks,

Bart.

Changes compared to v1:
 - Expanded a single patch into a series of two patches by adding a
   patch with unit tests.
 - Restored a newline in a format string that was missing from v1.

Bart Van Assche (2):
  scsi: core: Add KUnit tests for scsi_logging.c
  scsi: core: Eliminate scsi_log_{reserve,release}_buffer()

 drivers/scsi/Kconfig             |   9 +
 drivers/scsi/scsi_logging.c      | 285 +++++++++------------
 drivers/scsi/scsi_logging_test.c | 422 +++++++++++++++++++++++++++++++
 3 files changed, 547 insertions(+), 169 deletions(-)
 create mode 100644 drivers/scsi/scsi_logging_test.c

[PATCH v2 1/2] scsi: core: Add KUnit tests for scsi_logging.c

[Bart Van Assche]

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");

[PATCH v2 2/2] scsi: core: Eliminate scsi_log_{reserve,release}_buffer()

[Bart Van Assche]

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);
 

Re: [PATCH v2 1/2] scsi: core: Add KUnit tests for scsi_logging.c

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 3 potential issue(s) to consider:
- [Medium] Data race and out-of-bounds memory write in SCSI logging test capture.
- [Medium] NULL pointer dereference due to a TOCTOU data race on the global `scsi_logging_test_dev_printk` pointer.
- [Low] Global suppression of actual SCSI system logs during KUnit test execution.
--

commit 33967e88f5091c2f971d2edac33840afe7e6e925
Author: Bart Van Assche <bvanassche@acm.org>
    
scsi: core: Add KUnit tests for scsi_logging.c
    
This commit introduces KUnit tests for SCSI logging functions by
intercepting dev_printk() when CONFIG_SCSI_LOGGING_KUNIT_TEST is enabled.
It captures log outputs into a buffer to verify standard and formatted
SCSI command outputs.

> diff --git a/drivers/scsi/scsi_logging.c b/drivers/scsi/scsi_logging.c
> index 3cd0d30740855..3bff4dea4c6ac 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);

[Severity: Medium]
Could this result in a NULL pointer dereference? The global pointer
scsi_logging_test_dev_printk is checked for truthiness and then invoked
without synchronization or READ_ONCE(). If a background SCSI event triggers
a log concurrently with the test teardown in scsi_logging_test_exit()
(which clears the pointer), a race window exists where the pointer might be
evaluated as non-NULL but cleared before invocation.

> +	} else {
> +		struct va_format vaf = { .fmt = fmt, .va = &args };
> +
> +		_dev_printk(level, dev, "%pV", &vaf);
> +	}

[Severity: Low]
Does this branch inadvertently suppress all actual SCSI system logs during
the test execution? Because the hook intercepts all dev_printk() calls in
scsi_logging.c and doesn't filter for the test-specific dev structure,
background hardware logs might be swallowed while the test is running.

> +	va_end(args);
> +}

[ ... ]

> diff --git a/drivers/scsi/scsi_logging_test.c b/drivers/scsi/scsi_logging_test.c
> new file mode 100644
> index 0000000000000..1dcebc383052a
> --- /dev/null
> +++ b/drivers/scsi/scsi_logging_test.c
> @@ -0,0 +1,422 @@
[ ... ]
> +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;

[Severity: Medium]
Is there a risk of an out-of-bounds memory write here if background SCSI
events occur concurrently? The bounds check on the shared captured_count
variable is made locklessly, creating a TOCTOU race window. Multiple
threads or an interrupt on the same CPU could evaluate the bounds check
simultaneously and then proceed to write into the array.

> +		vscnprintf(captured_logs[captured_count].msg,
> +			   sizeof(captured_logs[captured_count].msg), fmt,
> +			   args);
> +		captured_count++;

[Severity: Medium]
This increment further contributes to the race, as concurrent executions
would increment captured_count beyond MAX_CAPTURED_LINES after writing out
of bounds.

> +	}
> +}
> +
> +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;
> +}

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/cover.1788198780.git.bvanassche@acm.org?part=1