linux-kernel - Part of Spinning up disk... ....ready logged on separate line and as warning (default level)

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-ID: <8fdeecc3-bcce-1f5c-9aac-656fb3464c27@molgen.mpg.de>
Date:   Fri, 3 Dec 2021 15:48:51 +0100
From:   Paul Menzel <pmenzel@...gen.mpg.de>
To:     "James E. J. Bottomley" <jejb@...ux.ibm.com>,
        "Martin K. Petersen" <martin.petersen@...cle.com>,
        linux-scsi@...r.kernel.org, LKML <linux-kernel@...r.kernel.org>
Subject: Part of Spinning up disk... ....ready logged on separate line and as
 warning (default level)

Dear Linux folks,


Plugging in an external HDD over USB, Linux logs a warning:

     $ dmesg --level=warn
     [  244.677769] ....ready

With the messages around it:

     [  243.663382] sd 10:0:0:0: [sdb] Spinning up disk...
     [  244.677769] ....ready

The code in `drivers/scsi/sd.c` suggests that now line break should 
happen, as no `\n` is used and `printk(KERN_CONT ".")`. If that would 
work, the message would also be logged with level `KERN_NOTICE`.

Is the macro somehow getting in the way?

     sd_printk(KERN_NOTICE, sdkp, "Spinning up disk...");

 From `drivers/scsi/sd.h`:

```
#define sd_printk(prefix, sdsk, fmt, a...)                              \
         (sdsk)->disk ?                                                  \
               sdev_prefix_printk(prefix, (sdsk)->device,                \
                                  (sdsk)->disk->disk_name, fmt, ##a) :   \
               sdev_printk(prefix, (sdsk)->device, fmt, ##a)
```

 From `drivers/scsi/scsi_logging.c`:

```
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);
}
EXPORT_SYMBOL(sdev_prefix_printk);
```

Also, there are four dots in `....ready`, but the log timestamps only 
differ by one seconds.

     /* Wait 1 second for next try */
     msleep(1000);
     printk(KERN_CONT ".");

Any idea, how that can be?


Kind regards,

Paul