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

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

[Paul Menzel]

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

Re: Part of Spinning up disk... ....ready logged on separate line and as warning (default level)

[Bart Van Assche]

On 12/3/21 06:48, Paul Menzel wrote:
> 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?

Not sure what is going on. All I know is that KERN_CONT is considered
deprecated and that it should be avoided. From commit 45c55e92fcee 
("checkpatch: warn on logging continuations"):

     pr_cont(...) and printk(KERN_CONT ...) uses should be discouraged
     as their output can be interleaved by multiple logging processes.

Thanks,

Bart.