2021-12-03 14:48:56

by Paul Menzel

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

2021-12-07 04:13:41

by Bart Van Assche

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

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.