"ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

"ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Krzysztof Olędzki]

Hi,

I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged.

For example, on my Dell PowerEdge 840 which has only one PATA port I used to get:

scsi host1: ata_piix
ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14
ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15
ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
ata2: port disabled--ignoring
ata1.01: NODEV after polling detection
ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33

After that commit, the following two log entries are missing:
ata2: port disabled--ignoring
ata1.01: NODEV after polling detection

Note that these are just examples, there are many more messages impacted by that.

Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg:
ata_link_dbg(link, "port disabled--ignoring\n");	[in drivers/ata/libata-eh.c]
ata_dev_dbg(dev, "NODEV after polling detection\n");	[in drivers/ata/libata-core.c]

The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro:

+#define ata_dev_printk(level, dev, fmt, ...)			\
+        pr_ ## level("ata%u.%02u: " fmt,			\
+               (dev)->link->ap->print_id,			\
+	       (dev)->link->pmp + (dev)->devno,			\
+	       ##__VA_ARGS__)
(...)
 #define ata_link_dbg(link, fmt, ...)				\
-	ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__)
+	ata_link_printk(debug, link, fmt, ##__VA_ARGS__)
(...)
 #define ata_dev_dbg(dev, fmt, ...)				\
-	ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__)
+	ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__

So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg).

pr_debug is defined as:
/* If you are writing a driver, please use dev_dbg instead */
#if defined(CONFIG_DYNAMIC_DEBUG) || \
	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
#include <linux/dynamic_debug.h>

/**
 * pr_debug - Print a debug-level message conditionally
 * @fmt: format string
 * @...: arguments for the format string
 *
 * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
 * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
 * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
 *
 * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
 * pr_fmt() internally).
 */
#define pr_debug(fmt, ...)			\
	dynamic_pr_debug(fmt, ##__VA_ARGS__)
#elif defined(DEBUG)
#define pr_debug(fmt, ...) \
	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
#define pr_debug(fmt, ...) \
	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#endif

Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged.

Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more.

Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging.
One of the cases like this was covered in the patch:
-#ifdef ATA_DEBUG
        if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ)))
-               ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n",
-                               status);
-#endif
+               ata_port_dbg(ap, "abnormal Status 0x%X\n", status);

Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info?

Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days...

Best regards,
 Krzysztof Olędzki

Re: "ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Niklas Cassel]

Hello Krzysztof,

On Sun, May 05, 2024 at 01:06:28PM -0700, Krzysztof Olędzki wrote:
> Hi,
> 
> I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged.
> 
> For example, on my Dell PowerEdge 840 which has only one PATA port I used to get:
> 
> scsi host1: ata_piix
> ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14
> ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15
> ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
> ata2: port disabled--ignoring
> ata1.01: NODEV after polling detection
> ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33
> 
> After that commit, the following two log entries are missing:
> ata2: port disabled--ignoring
> ata1.01: NODEV after polling detection
> 
> Note that these are just examples, there are many more messages impacted by that.
> 
> Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg:
> ata_link_dbg(link, "port disabled--ignoring\n");	[in drivers/ata/libata-eh.c]
> ata_dev_dbg(dev, "NODEV after polling detection\n");	[in drivers/ata/libata-core.c]
> 
> The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro:
> 
> +#define ata_dev_printk(level, dev, fmt, ...)			\
> +        pr_ ## level("ata%u.%02u: " fmt,			\
> +               (dev)->link->ap->print_id,			\
> +	       (dev)->link->pmp + (dev)->devno,			\
> +	       ##__VA_ARGS__)
> (...)
>  #define ata_link_dbg(link, fmt, ...)				\
> -	ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__)
> +	ata_link_printk(debug, link, fmt, ##__VA_ARGS__)
> (...)
>  #define ata_dev_dbg(dev, fmt, ...)				\
> -	ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__)
> +	ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__
> 
> So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg).
> 
> pr_debug is defined as:
> /* If you are writing a driver, please use dev_dbg instead */
> #if defined(CONFIG_DYNAMIC_DEBUG) || \
> 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
> #include <linux/dynamic_debug.h>
> 
> /**
>  * pr_debug - Print a debug-level message conditionally
>  * @fmt: format string
>  * @...: arguments for the format string
>  *
>  * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
>  * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
>  * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
>  *
>  * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
>  * pr_fmt() internally).
>  */
> #define pr_debug(fmt, ...)			\
> 	dynamic_pr_debug(fmt, ##__VA_ARGS__)
> #elif defined(DEBUG)
> #define pr_debug(fmt, ...) \
> 	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #else
> #define pr_debug(fmt, ...) \
> 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #endif
> 
> Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged.
> 
> Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more.
> 
> Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging.
> One of the cases like this was covered in the patch:
> -#ifdef ATA_DEBUG
>         if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ)))
> -               ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n",
> -                               status);
> -#endif
> +               ata_port_dbg(ap, "abnormal Status 0x%X\n", status);
> 
> Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info?
> 
> Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days...

The change to the dynamic debug model was very much intentional.

CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG (and ata_msg_info/ata_msg_probe)
was replaced with dynamic debug.

So the reason why you saw the messages before was most likely because you
built your kernel with CONFIG_ATA_DEBUG / CONFIG_ATA_VERBOSE_DEBUG.
If you want to see the same error messages, you are now expected to use
dynamic debug for the file which you want debug messages enabled.


I do agree that the debug prints that were NOT guarded by CONFIG_ATA_DEBUG
do now work differently, as they are no longer printed to dmesg at all.
I'm not sure if this part was intentional. I'm guessing that it wasn't.

Looking at these three prints specifically:
ata_link_dbg(link, "port disabled--ignoring\n");
ata_dev_dbg(dev, "NODEV after polling detection\n");
ata_dev_dbg(dev, "disabling queued TRIM support\n");

None of them were protected with CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG
before the series converting to dynamic debug was merged.


The best way forward is probably to look at all debug prints before the
series converting to dynamic debug was merged, and see if any print NOT
guarded by CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG should be considered
to promoted to an info print instead.
(The prints that were guarded are not relevant, for those you really are
expected to need to use dynamic debug in order to actually get them
printed to dmesg.)


Kind regards,
Niklas

Re: "ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Damien Le Moal]

On 5/7/24 06:49, Niklas Cassel wrote:
> Hello Krzysztof,
> 
> On Sun, May 05, 2024 at 01:06:28PM -0700, Krzysztof Olędzki wrote:
>> Hi,
>>
>> I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged.
>>
>> For example, on my Dell PowerEdge 840 which has only one PATA port I used to get:
>>
>> scsi host1: ata_piix
>> ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14
>> ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15
>> ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
>> ata2: port disabled--ignoring
>> ata1.01: NODEV after polling detection
>> ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33
>>
>> After that commit, the following two log entries are missing:
>> ata2: port disabled--ignoring
>> ata1.01: NODEV after polling detection
>>
>> Note that these are just examples, there are many more messages impacted by that.
>>
>> Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg:
>> ata_link_dbg(link, "port disabled--ignoring\n");	[in drivers/ata/libata-eh.c]
>> ata_dev_dbg(dev, "NODEV after polling detection\n");	[in drivers/ata/libata-core.c]
>>
>> The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro:
>>
>> +#define ata_dev_printk(level, dev, fmt, ...)			\
>> +        pr_ ## level("ata%u.%02u: " fmt,			\
>> +               (dev)->link->ap->print_id,			\
>> +	       (dev)->link->pmp + (dev)->devno,			\
>> +	       ##__VA_ARGS__)
>> (...)
>>  #define ata_link_dbg(link, fmt, ...)				\
>> -	ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__)
>> +	ata_link_printk(debug, link, fmt, ##__VA_ARGS__)
>> (...)
>>  #define ata_dev_dbg(dev, fmt, ...)				\
>> -	ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__)
>> +	ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__
>>
>> So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg).
>>
>> pr_debug is defined as:
>> /* If you are writing a driver, please use dev_dbg instead */
>> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>> 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
>> #include <linux/dynamic_debug.h>
>>
>> /**
>>  * pr_debug - Print a debug-level message conditionally
>>  * @fmt: format string
>>  * @...: arguments for the format string
>>  *
>>  * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
>>  * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
>>  * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
>>  *
>>  * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
>>  * pr_fmt() internally).
>>  */
>> #define pr_debug(fmt, ...)			\
>> 	dynamic_pr_debug(fmt, ##__VA_ARGS__)
>> #elif defined(DEBUG)
>> #define pr_debug(fmt, ...) \
>> 	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>> #else
>> #define pr_debug(fmt, ...) \
>> 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>> #endif
>>
>> Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged.
>>
>> Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more.
>>
>> Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging.
>> One of the cases like this was covered in the patch:
>> -#ifdef ATA_DEBUG
>>         if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ)))
>> -               ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n",
>> -                               status);
>> -#endif
>> +               ata_port_dbg(ap, "abnormal Status 0x%X\n", status);
>>
>> Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info?
>>
>> Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days...
> 
> The change to the dynamic debug model was very much intentional.
> 
> CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG (and ata_msg_info/ata_msg_probe)
> was replaced with dynamic debug.
> 
> So the reason why you saw the messages before was most likely because you
> built your kernel with CONFIG_ATA_DEBUG / CONFIG_ATA_VERBOSE_DEBUG.
> If you want to see the same error messages, you are now expected to use
> dynamic debug for the file which you want debug messages enabled.
> 
> 
> I do agree that the debug prints that were NOT guarded by CONFIG_ATA_DEBUG
> do now work differently, as they are no longer printed to dmesg at all.
> I'm not sure if this part was intentional. I'm guessing that it wasn't.
> 
> Looking at these three prints specifically:
> ata_link_dbg(link, "port disabled--ignoring\n");

Given the recent addition of the port map mask, we could restore this print as
an info level.

> ata_dev_dbg(dev, "NODEV after polling detection\n");

This one is weird. It should be an error print.

> ata_dev_dbg(dev, "disabling queued TRIM support\n");

This is also OK to restore as an info print. But given that, there are a lot
more horkage disabling features that we probably should print.

> 
> None of them were protected with CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG
> before the series converting to dynamic debug was merged.
> 
> 
> The best way forward is probably to look at all debug prints before the
> series converting to dynamic debug was merged, and see if any print NOT
> guarded by CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG should be considered
> to promoted to an info print instead.
> (The prints that were guarded are not relevant, for those you really are
> expected to need to use dynamic debug in order to actually get them
> printed to dmesg.)
> 
> 
> Kind regards,
> Niklas
> 

-- 
Damien Le Moal
Western Digital Research

Re: "ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Krzysztof Olędzki]

On 06.05.2024 at 15:08, Damien Le Moal wrote:
> On 5/7/24 06:49, Niklas Cassel wrote:
>> Hello Krzysztof,

Hello and thank you for your quick and detailed response from both of you!

>> On Sun, May 05, 2024 at 01:06:28PM -0700, Krzysztof Olędzki wrote:
>>> Hi,
>>>
>>> I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged.
>>>
>>> For example, on my Dell PowerEdge 840 which has only one PATA port I used to get:
>>>
>>> scsi host1: ata_piix
>>> ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14
>>> ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15
>>> ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
>>> ata2: port disabled--ignoring
>>> ata1.01: NODEV after polling detection
>>> ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33
>>>
>>> After that commit, the following two log entries are missing:
>>> ata2: port disabled--ignoring
>>> ata1.01: NODEV after polling detection
>>>
>>> Note that these are just examples, there are many more messages impacted by that.
>>>
>>> Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg:
>>> ata_link_dbg(link, "port disabled--ignoring\n");	[in drivers/ata/libata-eh.c]
>>> ata_dev_dbg(dev, "NODEV after polling detection\n");	[in drivers/ata/libata-core.c]
>>>
>>> The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro:
>>>
>>> +#define ata_dev_printk(level, dev, fmt, ...)			\
>>> +        pr_ ## level("ata%u.%02u: " fmt,			\
>>> +               (dev)->link->ap->print_id,			\
>>> +	       (dev)->link->pmp + (dev)->devno,			\
>>> +	       ##__VA_ARGS__)
>>> (...)
>>>  #define ata_link_dbg(link, fmt, ...)				\
>>> -	ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__)
>>> +	ata_link_printk(debug, link, fmt, ##__VA_ARGS__)
>>> (...)
>>>  #define ata_dev_dbg(dev, fmt, ...)				\
>>> -	ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__)
>>> +	ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__
>>>
>>> So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg).
>>>
>>> pr_debug is defined as:
>>> /* If you are writing a driver, please use dev_dbg instead */
>>> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>>> 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
>>> #include <linux/dynamic_debug.h>
>>>
>>> /**
>>>  * pr_debug - Print a debug-level message conditionally
>>>  * @fmt: format string
>>>  * @...: arguments for the format string
>>>  *
>>>  * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
>>>  * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
>>>  * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
>>>  *
>>>  * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
>>>  * pr_fmt() internally).
>>>  */
>>> #define pr_debug(fmt, ...)			\
>>> 	dynamic_pr_debug(fmt, ##__VA_ARGS__)
>>> #elif defined(DEBUG)
>>> #define pr_debug(fmt, ...) \
>>> 	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>> #else
>>> #define pr_debug(fmt, ...) \
>>> 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>> #endif
>>>
>>> Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged.
>>>
>>> Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more.
>>>
>>> Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging.
>>> One of the cases like this was covered in the patch:
>>> -#ifdef ATA_DEBUG
>>>         if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ)))
>>> -               ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n",
>>> -                               status);
>>> -#endif
>>> +               ata_port_dbg(ap, "abnormal Status 0x%X\n", status);
>>>
>>> Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info?
>>>
>>> Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days...
>>
>> The change to the dynamic debug model was very much intentional.
>>
>> CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG (and ata_msg_info/ata_msg_probe)
>> was replaced with dynamic debug.

Understood.

>> So the reason why you saw the messages before was most likely because you
>> built your kernel with CONFIG_ATA_DEBUG / CONFIG_ATA_VERBOSE_DEBUG.

I don't believe this is the case - please note these were ATA_VERBOSE_DEBUG / ATA_DEBUG (i.e. not CONFIG_...) and these logging entries were not covered by ifdefs, for example:

if (rc == -ENOENT) {
        ata_link_dbg(link, "port disabled--ignoring\n");
        ehc->i.action &= ~ATA_EH_RESET;

        ata_for_each_dev(dev, link, ALL)
                classes[dev->devno] = ATA_DEV_NONE;

        rc = 0;
} else
        ata_link_err(link,
                     "prereset failed (errno=%d)\n",
                     rc);

>> If you want to see the same error messages, you are now expected to use
>> dynamic debug for the file which you want debug messages enabled.

Totally agree on the "debug" type of messages but I'm not sure if asking users to use dynamic debug to see error messages is what we want...

>> I do agree that the debug prints that were NOT guarded by CONFIG_ATA_DEBUG
>> do now work differently, as they are no longer printed to dmesg at all.
>> I'm not sure if this part was intentional. I'm guessing that it wasn't.

That's precisely the point I have been trying to make here. The dynamic debugging change seems like a very welcome one, the messages disappearing - perhaps not so much. Especially in a middle of a -stable kernel.

>> Looking at these three prints specifically:
>> ata_link_dbg(link, "port disabled--ignoring\n");
> 
> Given the recent addition of the port map mask, we could restore this print as
> an info level.
> 
>> ata_dev_dbg(dev, "NODEV after polling detection\n");
> 
> This one is weird. It should be an error print.
> 
>> ata_dev_dbg(dev, "disabling queued TRIM support\n");
> 
> This is also OK to restore as an info print. But given that, there are a lot
> more horkage disabling features that we probably should print.

Thanks. Just a note that these were just some examples. Also, can I help somehow or should I just wait for patches to test?

>> None of them were protected with CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG
>> before the series converting to dynamic debug was merged.
>>
>>
>> The best way forward is probably to look at all debug prints before the
>> series converting to dynamic debug was merged, and see if any print NOT
>> guarded by CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG should be considered
>> to promoted to an info print instead.

Same question as the above: can I help somehow or should I just wait for patches to test?

>> (The prints that were guarded are not relevant, for those you really are
>> expected to need to use dynamic debug in order to actually get them
>> printed to dmesg.)

Fair and I fully agree with this one.

Thanks,
 Krzysztof

Re: "ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Damien Le Moal]

On 2024/05/13 15:50, Krzysztof Olędzki wrote:
> On 06.05.2024 at 15:08, Damien Le Moal wrote:
>> On 5/7/24 06:49, Niklas Cassel wrote:
>>> Hello Krzysztof,
> 
> Hello and thank you for your quick and detailed response from both of you!
> 
>>> On Sun, May 05, 2024 at 01:06:28PM -0700, Krzysztof Olędzki wrote:
>>>> Hi,
>>>>
>>>> I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged.
>>>>
>>>> For example, on my Dell PowerEdge 840 which has only one PATA port I used to get:
>>>>
>>>> scsi host1: ata_piix
>>>> ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14
>>>> ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15
>>>> ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
>>>> ata2: port disabled--ignoring
>>>> ata1.01: NODEV after polling detection
>>>> ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33
>>>>
>>>> After that commit, the following two log entries are missing:
>>>> ata2: port disabled--ignoring
>>>> ata1.01: NODEV after polling detection
>>>>
>>>> Note that these are just examples, there are many more messages impacted by that.
>>>>
>>>> Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg:
>>>> ata_link_dbg(link, "port disabled--ignoring\n");	[in drivers/ata/libata-eh.c]
>>>> ata_dev_dbg(dev, "NODEV after polling detection\n");	[in drivers/ata/libata-core.c]
>>>>
>>>> The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro:
>>>>
>>>> +#define ata_dev_printk(level, dev, fmt, ...)			\
>>>> +        pr_ ## level("ata%u.%02u: " fmt,			\
>>>> +               (dev)->link->ap->print_id,			\
>>>> +	       (dev)->link->pmp + (dev)->devno,			\
>>>> +	       ##__VA_ARGS__)
>>>> (...)
>>>>  #define ata_link_dbg(link, fmt, ...)				\
>>>> -	ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__)
>>>> +	ata_link_printk(debug, link, fmt, ##__VA_ARGS__)
>>>> (...)
>>>>  #define ata_dev_dbg(dev, fmt, ...)				\
>>>> -	ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__)
>>>> +	ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__
>>>>
>>>> So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg).
>>>>
>>>> pr_debug is defined as:
>>>> /* If you are writing a driver, please use dev_dbg instead */
>>>> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>>>> 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
>>>> #include <linux/dynamic_debug.h>
>>>>
>>>> /**
>>>>  * pr_debug - Print a debug-level message conditionally
>>>>  * @fmt: format string
>>>>  * @...: arguments for the format string
>>>>  *
>>>>  * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
>>>>  * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
>>>>  * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
>>>>  *
>>>>  * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
>>>>  * pr_fmt() internally).
>>>>  */
>>>> #define pr_debug(fmt, ...)			\
>>>> 	dynamic_pr_debug(fmt, ##__VA_ARGS__)
>>>> #elif defined(DEBUG)
>>>> #define pr_debug(fmt, ...) \
>>>> 	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>> #else
>>>> #define pr_debug(fmt, ...) \
>>>> 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>> #endif
>>>>
>>>> Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged.
>>>>
>>>> Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more.
>>>>
>>>> Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging.
>>>> One of the cases like this was covered in the patch:
>>>> -#ifdef ATA_DEBUG
>>>>         if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ)))
>>>> -               ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n",
>>>> -                               status);
>>>> -#endif
>>>> +               ata_port_dbg(ap, "abnormal Status 0x%X\n", status);
>>>>
>>>> Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info?
>>>>
>>>> Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days...
>>>
>>> The change to the dynamic debug model was very much intentional.
>>>
>>> CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG (and ata_msg_info/ata_msg_probe)
>>> was replaced with dynamic debug.
> 
> Understood.
> 
>>> So the reason why you saw the messages before was most likely because you
>>> built your kernel with CONFIG_ATA_DEBUG / CONFIG_ATA_VERBOSE_DEBUG.
> 
> I don't believe this is the case - please note these were ATA_VERBOSE_DEBUG / ATA_DEBUG (i.e. not CONFIG_...) and these logging entries were not covered by ifdefs, for example:
> 
> if (rc == -ENOENT) {
>         ata_link_dbg(link, "port disabled--ignoring\n");
>         ehc->i.action &= ~ATA_EH_RESET;
> 
>         ata_for_each_dev(dev, link, ALL)
>                 classes[dev->devno] = ATA_DEV_NONE;
> 
>         rc = 0;
> } else
>         ata_link_err(link,
>                      "prereset failed (errno=%d)\n",
>                      rc);
> 
>>> If you want to see the same error messages, you are now expected to use
>>> dynamic debug for the file which you want debug messages enabled.
> 
> Totally agree on the "debug" type of messages but I'm not sure if asking users to use dynamic debug to see error messages is what we want...
> 
>>> I do agree that the debug prints that were NOT guarded by CONFIG_ATA_DEBUG
>>> do now work differently, as they are no longer printed to dmesg at all.
>>> I'm not sure if this part was intentional. I'm guessing that it wasn't.
> 
> That's precisely the point I have been trying to make here. The dynamic debugging change seems like a very welcome one, the messages disappearing - perhaps not so much. Especially in a middle of a -stable kernel.
> 
>>> Looking at these three prints specifically:
>>> ata_link_dbg(link, "port disabled--ignoring\n");
>>
>> Given the recent addition of the port map mask, we could restore this print as
>> an info level.
>>
>>> ata_dev_dbg(dev, "NODEV after polling detection\n");
>>
>> This one is weird. It should be an error print.
>>
>>> ata_dev_dbg(dev, "disabling queued TRIM support\n");
>>
>> This is also OK to restore as an info print. But given that, there are a lot
>> more horkage disabling features that we probably should print.
> 
> Thanks. Just a note that these were just some examples. Also, can I help somehow or should I just wait for patches to test?
> 
>>> None of them were protected with CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG
>>> before the series converting to dynamic debug was merged.
>>>
>>>
>>> The best way forward is probably to look at all debug prints before the
>>> series converting to dynamic debug was merged, and see if any print NOT
>>> guarded by CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG should be considered
>>> to promoted to an info print instead.
> 
> Same question as the above: can I help somehow or should I just wait for patches to test?

If you have something in mind, please, by all means, send patches and we'll go
from there. What I think we need is:

1) Review the code to make sure that we print an error message for everything
that fails but should really succeeds. Beware here that some things may "fail"
during port scan if a device is not attached. That is normal and should not
result in printing errors.

2) Add prints whenever a horkage flag is applied to a device, port or link.

That should not be a lot.


-- 
Damien Le Moal
Western Digital Research

Re: "ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Krzysztof Olędzki]

On 13.05.2024 at 06:14, Damien Le Moal wrote:
> On 2024/05/13 15:50, Krzysztof Olędzki wrote:
>> On 06.05.2024 at 15:08, Damien Le Moal wrote:
>>> On 5/7/24 06:49, Niklas Cassel wrote:
>>>> Hello Krzysztof,
>>
>> Hello and thank you for your quick and detailed response from both of you!
>>
>>>> On Sun, May 05, 2024 at 01:06:28PM -0700, Krzysztof Olędzki wrote:
>>>>> Hi,
>>>>>
>>>>> I noticed that since https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=742bef476ca5352b16063161fb73a56629a6d995 (which also got backported to -stable kernels) several of messages from dmesg regarding the ATA subsystem are no longer logged.
>>>>>
>>>>> For example, on my Dell PowerEdge 840 which has only one PATA port I used to get:
>>>>>
>>>>> scsi host1: ata_piix
>>>>> ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xfc00 irq 14
>>>>> ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xfc08 irq 15
>>>>> ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
>>>>> ata2: port disabled--ignoring
>>>>> ata1.01: NODEV after polling detection
>>>>> ata1.00: ATAPI: SAMSUNG CD-R/RW SW-248F, R602, max UDMA/33
>>>>>
>>>>> After that commit, the following two log entries are missing:
>>>>> ata2: port disabled--ignoring
>>>>> ata1.01: NODEV after polling detection
>>>>>
>>>>> Note that these are just examples, there are many more messages impacted by that.
>>>>>
>>>>> Looking at the code, these messages are logged via ata_link_dbg / ata_dev_dbg:
>>>>> ata_link_dbg(link, "port disabled--ignoring\n");	[in drivers/ata/libata-eh.c]
>>>>> ata_dev_dbg(dev, "NODEV after polling detection\n");	[in drivers/ata/libata-core.c]
>>>>>
>>>>> The commit change how the logging is called - ata_dev_printk function which was calling printk() directly got replaced with the following macro:
>>>>>
>>>>> +#define ata_dev_printk(level, dev, fmt, ...)			\
>>>>> +        pr_ ## level("ata%u.%02u: " fmt,			\
>>>>> +               (dev)->link->ap->print_id,			\
>>>>> +	       (dev)->link->pmp + (dev)->devno,			\
>>>>> +	       ##__VA_ARGS__)
>>>>> (...)
>>>>>  #define ata_link_dbg(link, fmt, ...)				\
>>>>> -	ata_link_printk(link, KERN_DEBUG, fmt, ##__VA_ARGS__)
>>>>> +	ata_link_printk(debug, link, fmt, ##__VA_ARGS__)
>>>>> (...)
>>>>>  #define ata_dev_dbg(dev, fmt, ...)				\
>>>>> -	ata_dev_printk(dev, KERN_DEBUG, fmt, ##__VA_ARGS__)
>>>>> +	ata_dev_printk(debug, dev, fmt, ##__VA_ARGS__
>>>>>
>>>>> So, instead of printk(..., level == KERN_DEBUG, ) we now call pr_debug(...). This is a problem as printk(msg, KERN_DEBUG) != pr_debug(msg).
>>>>>
>>>>> pr_debug is defined as:
>>>>> /* If you are writing a driver, please use dev_dbg instead */
>>>>> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>>>>> 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
>>>>> #include <linux/dynamic_debug.h>
>>>>>
>>>>> /**
>>>>>  * pr_debug - Print a debug-level message conditionally
>>>>>  * @fmt: format string
>>>>>  * @...: arguments for the format string
>>>>>  *
>>>>>  * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
>>>>>  * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
>>>>>  * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
>>>>>  *
>>>>>  * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
>>>>>  * pr_fmt() internally).
>>>>>  */
>>>>> #define pr_debug(fmt, ...)			\
>>>>> 	dynamic_pr_debug(fmt, ##__VA_ARGS__)
>>>>> #elif defined(DEBUG)
>>>>> #define pr_debug(fmt, ...) \
>>>>> 	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>>> #else
>>>>> #define pr_debug(fmt, ...) \
>>>>> 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>>> #endif
>>>>>
>>>>> Without CONFIG_DYNAMIC_DEBUG and if no CONFIG_DEBUG is enabled, the end result is calling no_printk which means nothing gets logged.
>>>>>
>>>>> Looking at the code, there are more impacted calls, like for example ata_dev_dbg(dev, "disabling queued TRIM support\n") for ATA_HORKAGE_NO_NCQ_TRIM, which also seems like an important information to log, and there are more.
>>>>>
>>>>> Was this change done intentionally? Note that most of the "debug" printks in libata code seem to be guarded by ata_msg_info / ata_msg_probe / ATA_DEBUG which was sufficient to prevent excess debug information logging.
>>>>> One of the cases like this was covered in the patch:
>>>>> -#ifdef ATA_DEBUG
>>>>>         if (status != 0xff && (status & (ATA_BUSY | ATA_DRQ)))
>>>>> -               ata_port_printk(ap, KERN_DEBUG, "abnormal Status 0x%X\n",
>>>>> -                               status);
>>>>> -#endif
>>>>> +               ata_port_dbg(ap, "abnormal Status 0x%X\n", status);
>>>>>
>>>>> Assuming this is the intended direction, would it make sense for now to at promote "unconditionally" logged messages from ata_link_dbg/ata_dev_dbg to ata_link_info/ata_dev_info?
>>>>>
>>>>> Longer term, perhaps we want to revisit ata_msg_info/ata_msg_probe/ATA_DEBUG/ATA_VERBOSE_DEBUG vs ata_dev_printk/ata_link_printk/pr_debug (and maybe also pr_devel), especially that DYNAMIC_DEBUG is available these days...
>>>>
>>>> The change to the dynamic debug model was very much intentional.
>>>>
>>>> CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG (and ata_msg_info/ata_msg_probe)
>>>> was replaced with dynamic debug.
>>
>> Understood.
>>
>>>> So the reason why you saw the messages before was most likely because you
>>>> built your kernel with CONFIG_ATA_DEBUG / CONFIG_ATA_VERBOSE_DEBUG.
>>
>> I don't believe this is the case - please note these were ATA_VERBOSE_DEBUG / ATA_DEBUG (i.e. not CONFIG_...) and these logging entries were not covered by ifdefs, for example:
>>
>> if (rc == -ENOENT) {
>>         ata_link_dbg(link, "port disabled--ignoring\n");
>>         ehc->i.action &= ~ATA_EH_RESET;
>>
>>         ata_for_each_dev(dev, link, ALL)
>>                 classes[dev->devno] = ATA_DEV_NONE;
>>
>>         rc = 0;
>> } else
>>         ata_link_err(link,
>>                      "prereset failed (errno=%d)\n",
>>                      rc);
>>
>>>> If you want to see the same error messages, you are now expected to use
>>>> dynamic debug for the file which you want debug messages enabled.
>>
>> Totally agree on the "debug" type of messages but I'm not sure if asking users to use dynamic debug to see error messages is what we want...
>>
>>>> I do agree that the debug prints that were NOT guarded by CONFIG_ATA_DEBUG
>>>> do now work differently, as they are no longer printed to dmesg at all.
>>>> I'm not sure if this part was intentional. I'm guessing that it wasn't.
>>
>> That's precisely the point I have been trying to make here. The dynamic debugging change seems like a very welcome one, the messages disappearing - perhaps not so much. Especially in a middle of a -stable kernel.
>>
>>>> Looking at these three prints specifically:
>>>> ata_link_dbg(link, "port disabled--ignoring\n");
>>>
>>> Given the recent addition of the port map mask, we could restore this print as
>>> an info level.
>>>
>>>> ata_dev_dbg(dev, "NODEV after polling detection\n");
>>>
>>> This one is weird. It should be an error print.
>>>
>>>> ata_dev_dbg(dev, "disabling queued TRIM support\n");
>>>
>>> This is also OK to restore as an info print. But given that, there are a lot
>>> more horkage disabling features that we probably should print.
>>
>> Thanks. Just a note that these were just some examples. Also, can I help somehow or should I just wait for patches to test?
>>
>>>> None of them were protected with CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG
>>>> before the series converting to dynamic debug was merged.
>>>>
>>>>
>>>> The best way forward is probably to look at all debug prints before the
>>>> series converting to dynamic debug was merged, and see if any print NOT
>>>> guarded by CONFIG_ATA_DEBUG/CONFIG_ATA_VERBOSE_DEBUG should be considered
>>>> to promoted to an info print instead.
>>
>> Same question as the above: can I help somehow or should I just wait for patches to test?
> 
> If you have something in mind, please, by all means, send patches and we'll go
> from there. What I think we need is:
> 
> 1) Review the code to make sure that we print an error message for everything
> that fails but should really succeeds. Beware here that some things may "fail"
> during port scan if a device is not attached. That is normal and should not
> result in printing errors.
> 
> 2) Add prints whenever a horkage flag is applied to a device, port or link.
> 
> That should not be a lot.

Thank you. How about the following patch? I'm sure I missed something
but it should bring us close to where we were before the logging cleanup.

If something like this is acceptable, perpahs it would be also possible
to include it in the -stable kernels, I think up to and including 5.15?

From b1f93347828a3d8c52ae4a73f9fb48341d0c2afb Mon Sep 17 00:00:00 2001
From: Krzysztof Piotr Oledzki <ole@ans.pl>
Date: Sat, 25 May 2024 22:35:58 -0700
Subject: [PATCH] ata: libata: restore visibility of important messages

With the recent cleanup and migration to standard
pr_{debug,info,notice,warn,err} macros instead of the
hand-crafted printk helpers some important messages
disappeared from dmesg unless dynamic debug is enabled.

Restore their visibility by promoting them to info or err (when
appropriate).

Also, improve or add information about features disabled due to
ATA_HORKAGE workarounds like NONCQ, NO_NCQ_ON_ATI and NO_FUA.

For ATA_HORKAGE_DIAGNOSTIC and ATA_HORKAGE_FIRMWARE_WARN convert the
message to a single line and update the ata.wiki.kernel.org link.

Signed-off-by: Krzysztof Piotr Oledzki <ole@ans.pl>
---
 drivers/ata/libata-core.c | 49 +++++++++++++++++++++------------------
 drivers/ata/libata-eh.c   |  2 +-
 2 files changed, 28 insertions(+), 23 deletions(-)

diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 4f35aab81a0a..0603849692ae 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -1793,7 +1793,7 @@ int ata_dev_read_id(struct ata_device *dev, unsigned int *p_class,
 
 	if (err_mask) {
 		if (err_mask & AC_ERR_NODEV_HINT) {
-			ata_dev_dbg(dev, "NODEV after polling detection\n");
+			ata_dev_err(dev, "NODEV after polling detection\n");
 			return -ENOENT;
 		}
 
@@ -1825,8 +1825,8 @@ int ata_dev_read_id(struct ata_device *dev, unsigned int *p_class,
 			 * both flavors of IDENTIFYs which happens
 			 * sometimes with phantom devices.
 			 */
-			ata_dev_dbg(dev,
-				    "both IDENTIFYs aborted, assuming NODEV\n");
+			ata_dev_info(dev,
+				     "both IDENTIFYs aborted, assuming NODEV\n");
 			return -ENOENT;
 		}
 
@@ -1857,9 +1857,9 @@ int ata_dev_read_id(struct ata_device *dev, unsigned int *p_class,
 	if (class == ATA_DEV_ATA || class == ATA_DEV_ZAC) {
 		if (!ata_id_is_ata(id) && !ata_id_is_cfa(id))
 			goto err_out;
-		if (ap->host->flags & ATA_HOST_IGNORE_ATA &&
-							ata_id_is_ata(id)) {
-			ata_dev_dbg(dev,
+		if ((ap->host->flags & ATA_HOST_IGNORE_ATA) &&
+		    ata_id_is_ata(id)) {
+			ata_dev_info(dev,
 				"host indicates ignore ATA devices, ignored\n");
 			return -ENOENT;
 		}
@@ -2247,7 +2247,8 @@ static void ata_dev_config_ncq_send_recv(struct ata_device *dev)
 		memcpy(cmds, ap->sector_buf, ATA_LOG_NCQ_SEND_RECV_SIZE);
 
 		if (dev->horkage & ATA_HORKAGE_NO_NCQ_TRIM) {
-			ata_dev_dbg(dev, "disabling queued TRIM support\n");
+			ata_dev_info(dev, "disabling queued TRIM - "
+					  "known buggy device\n");
 			cmds[ATA_LOG_NCQ_SEND_RECV_DSM_OFFSET] &=
 				~ATA_LOG_NCQ_SEND_RECV_DSM_TRIM;
 		}
@@ -2335,13 +2336,13 @@ static int ata_dev_config_ncq(struct ata_device *dev,
 	if (!IS_ENABLED(CONFIG_SATA_HOST))
 		return 0;
 	if (dev->horkage & ATA_HORKAGE_NONCQ) {
-		snprintf(desc, desc_sz, "NCQ (not used)");
+		snprintf(desc, desc_sz, "NCQ (not used - known buggy device)");
 		return 0;
 	}
 
 	if (dev->horkage & ATA_HORKAGE_NO_NCQ_ON_ATI &&
 	    ata_dev_check_adapter(dev, PCI_VENDOR_ID_ATI)) {
-		snprintf(desc, desc_sz, "NCQ (not used)");
+		snprintf(desc, desc_sz, "NCQ (not used - known buggy device/host adapter)");
 		return 0;
 	}
 
@@ -2397,7 +2398,7 @@ static void ata_dev_config_sense_reporting(struct ata_device *dev)
 
 	err_mask = ata_dev_set_feature(dev, SETFEATURE_SENSE_DATA, 0x1);
 	if (err_mask) {
-		ata_dev_dbg(dev,
+		ata_dev_err(dev,
 			    "failed to enable Sense Data Reporting, Emask 0x%x\n",
 			    err_mask);
 	}
@@ -2479,7 +2480,7 @@ static void ata_dev_config_trusted(struct ata_device *dev)
 
 	trusted_cap = get_unaligned_le64(&ap->sector_buf[40]);
 	if (!(trusted_cap & (1ULL << 63))) {
-		ata_dev_dbg(dev,
+		ata_dev_err(dev,
 			    "Trusted Computing capability qword not valid!\n");
 		return;
 	}
@@ -2688,9 +2689,15 @@ static void ata_dev_config_fua(struct ata_device *dev)
 	if (!(dev->flags & ATA_DFLAG_LBA48) || !ata_id_has_fua(dev->id))
 		goto nofua;
 
-	/* Ignore known bad devices and devices that lack NCQ support */
-	if (!ata_ncq_supported(dev) || (dev->horkage & ATA_HORKAGE_NO_FUA))
+	/* Ignore devices that lack NCQ support */
+	if (!ata_ncq_supported(dev))
+		goto nofua;
+
+	/* Finally, ignore buggy devices */
+	if (dev->horkage & ATA_HORKAGE_NO_FUA) {
+		ata_dev_info(dev, "disabling FUA - known buggy device");
 		goto nofua;
+	}
 
 	dev->flags |= ATA_DFLAG_FUA;
 
@@ -3060,24 +3067,22 @@ int ata_dev_configure(struct ata_device *dev)
 	if (ap->ops->dev_config)
 		ap->ops->dev_config(dev);
 
-	if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
+	if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
 		/* Let the user know. We don't want to disallow opens for
 		   rescue purposes, or in case the vendor is just a blithering
 		   idiot. Do this after the dev_config call as some controllers
 		   with buggy firmware may want to avoid reporting false device
 		   bugs */
 
-		if (print_info) {
-			ata_dev_warn(dev,
-"Drive reports diagnostics failure. This may indicate a drive\n");
-			ata_dev_warn(dev,
-"fault or invalid emulation. Contact drive vendor for information.\n");
-		}
+		ata_dev_warn(dev, "Drive reports diagnostics failure."
+				  " This may indicate a drive fault or invalid emulation."
+				  " Contact drive vendor for information.\n");
 	}
 
 	if ((dev->horkage & ATA_HORKAGE_FIRMWARE_WARN) && print_info) {
-		ata_dev_warn(dev, "WARNING: device requires firmware update to be fully functional\n");
-		ata_dev_warn(dev, "         contact the vendor or visit http://ata.wiki.kernel.org\n");
+		ata_dev_warn(dev, "WARNING: device requires firmware update to be"
+				  " fully functional contact the vendor or visit"
+				  " http://ata.wiki.kernel.org/index.php/Known_issues\n");
 	}
 
 	return 0;
diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 214b935c2ced..5b9382ef261c 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2667,7 +2667,7 @@ int ata_eh_reset(struct ata_link *link, int classify,
 
 		if (rc) {
 			if (rc == -ENOENT) {
-				ata_link_dbg(link, "port disabled--ignoring\n");
+				ata_link_info(link, "port disabled--ignoring\n");
 				ehc->i.action &= ~ATA_EH_RESET;
 
 				ata_for_each_dev(dev, link, ALL)
-- 
2.45.1

Thanks,
 Krzysztof

Re: [PATCH] ata: libata: restore visibility of important messages

[kernel test robot]

Hi Krzysztof,

kernel test robot noticed the following build warnings:

[auto build test WARNING on linus/master]
[also build test WARNING on v6.9 next-20240523]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Krzysztof-Ol-dzki/ata-libata-restore-visibility-of-important-messages/20240526-144120
base:   linus/master
patch link:    https://lore.kernel.org/r/a116c331-530e-4d45-a32c-37c57542724a%40ans.pl
patch subject: [PATCH] ata: libata: restore visibility of important messages
config: alpha-defconfig (https://download.01.org/0day-ci/archive/20240526/202405261642.ya8nqExt-lkp@intel.com/config)
compiler: alpha-linux-gcc (GCC) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240526/202405261642.ya8nqExt-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202405261642.ya8nqExt-lkp@intel.com/

All warnings (new ones prefixed by >>):

   drivers/ata/libata-core.c: In function 'ata_dev_config_ncq.constprop':
>> drivers/ata/libata-core.c:2345:74: warning: 'NCQ (not used - known buggy ...' directive output truncated writing 48 bytes into a region of size 32 [-Wformat-truncation=]
    2345 |                 snprintf(desc, desc_sz, "NCQ (not used - known buggy device/host adapter)");
         |                                          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~~~~~~~~~~~~~~
   drivers/ata/libata-core.c:2345:17: note: 'snprintf' output 49 bytes into a destination of size 32
    2345 |                 snprintf(desc, desc_sz, "NCQ (not used - known buggy device/host adapter)");
         |                 ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
   drivers/ata/libata-core.c:2339:74: warning: 'NCQ (not used - known buggy ...' directive output truncated writing 35 bytes into a region of size 32 [-Wformat-truncation=]
    2339 |                 snprintf(desc, desc_sz, "NCQ (not used - known buggy device)");
         |                                          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~
   drivers/ata/libata-core.c:2339:17: note: 'snprintf' output 36 bytes into a destination of size 32
    2339 |                 snprintf(desc, desc_sz, "NCQ (not used - known buggy device)");
         |                 ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~


vim +2345 drivers/ata/libata-core.c

  2323	
  2324	static int ata_dev_config_ncq(struct ata_device *dev,
  2325				       char *desc, size_t desc_sz)
  2326	{
  2327		struct ata_port *ap = dev->link->ap;
  2328		int hdepth = 0, ddepth = ata_id_queue_depth(dev->id);
  2329		unsigned int err_mask;
  2330		char *aa_desc = "";
  2331	
  2332		if (!ata_id_has_ncq(dev->id)) {
  2333			desc[0] = '\0';
  2334			return 0;
  2335		}
  2336		if (!IS_ENABLED(CONFIG_SATA_HOST))
  2337			return 0;
  2338		if (dev->horkage & ATA_HORKAGE_NONCQ) {
  2339			snprintf(desc, desc_sz, "NCQ (not used - known buggy device)");
  2340			return 0;
  2341		}
  2342	
  2343		if (dev->horkage & ATA_HORKAGE_NO_NCQ_ON_ATI &&
  2344		    ata_dev_check_adapter(dev, PCI_VENDOR_ID_ATI)) {
> 2345			snprintf(desc, desc_sz, "NCQ (not used - known buggy device/host adapter)");
  2346			return 0;
  2347		}
  2348	
  2349		if (ap->flags & ATA_FLAG_NCQ) {
  2350			hdepth = min(ap->scsi_host->can_queue, ATA_MAX_QUEUE);
  2351			dev->flags |= ATA_DFLAG_NCQ;
  2352		}
  2353	
  2354		if (!(dev->horkage & ATA_HORKAGE_BROKEN_FPDMA_AA) &&
  2355			(ap->flags & ATA_FLAG_FPDMA_AA) &&
  2356			ata_id_has_fpdma_aa(dev->id)) {
  2357			err_mask = ata_dev_set_feature(dev, SETFEATURES_SATA_ENABLE,
  2358				SATA_FPDMA_AA);
  2359			if (err_mask) {
  2360				ata_dev_err(dev,
  2361					    "failed to enable AA (error_mask=0x%x)\n",
  2362					    err_mask);
  2363				if (err_mask != AC_ERR_DEV) {
  2364					dev->horkage |= ATA_HORKAGE_BROKEN_FPDMA_AA;
  2365					return -EIO;
  2366				}
  2367			} else
  2368				aa_desc = ", AA";
  2369		}
  2370	
  2371		if (hdepth >= ddepth)
  2372			snprintf(desc, desc_sz, "NCQ (depth %d)%s", ddepth, aa_desc);
  2373		else
  2374			snprintf(desc, desc_sz, "NCQ (depth %d/%d)%s", hdepth,
  2375				ddepth, aa_desc);
  2376	
  2377		if ((ap->flags & ATA_FLAG_FPDMA_AUX)) {
  2378			if (ata_id_has_ncq_send_and_recv(dev->id))
  2379				ata_dev_config_ncq_send_recv(dev);
  2380			if (ata_id_has_ncq_non_data(dev->id))
  2381				ata_dev_config_ncq_non_data(dev);
  2382			if (ata_id_has_ncq_prio(dev->id))
  2383				ata_dev_config_ncq_prio(dev);
  2384		}
  2385	
  2386		return 0;
  2387	}
  2388	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: "ata: libata: move ata_{port,link,dev}_dbg to standard pr_XXX() macros" - 742bef476ca5352b16063161fb73a56629a6d995 changed logging behavior and disabled a number of messages

[Damien Le Moal]

On 5/26/24 3:39 PM, Krzysztof Olędzki wrote:
> Thank you. How about the following patch? I'm sure I missed something
> but it should bring us close to where we were before the logging cleanup.
> 
> If something like this is acceptable, perpahs it would be also possible
> to include it in the -stable kernels, I think up to and including 5.15?

Please send a proper patch with afixes tag and cc-stable tag instead of
something as a reply to this thread. We will do the review of that.

> 
> From b1f93347828a3d8c52ae4a73f9fb48341d0c2afb Mon Sep 17 00:00:00 2001
> From: Krzysztof Piotr Oledzki <ole@ans.pl>
> Date: Sat, 25 May 2024 22:35:58 -0700
> Subject: [PATCH] ata: libata: restore visibility of important messages
> 
> With the recent cleanup and migration to standard
> pr_{debug,info,notice,warn,err} macros instead of the
> hand-crafted printk helpers some important messages
> disappeared from dmesg unless dynamic debug is enabled.

Very short lines. Please format this up to 72 chars per line.
And instead of using the very subjective "recent" term for the message changes,
please reference the commit that did it.

> 
> Restore their visibility by promoting them to info or err (when
> appropriate).
> 
> Also, improve or add information about features disabled due to
> ATA_HORKAGE workarounds like NONCQ, NO_NCQ_ON_ATI and NO_FUA.

This part should be a different patch as it is not "fixing" the previous
changes but adds new messages.

> 
> For ATA_HORKAGE_DIAGNOSTIC and ATA_HORKAGE_FIRMWARE_WARN convert the
> message to a single line and update the ata.wiki.kernel.org link.

Hmmm... I have no idea who created that wiki nor if it is maintained at all...
We (the libata maintainers) are for sure not maintaining it. So I would prefer
to entirely remove that link as I am not sure the information there is correct
at all. If anything needs to be documented, then add a note in
Documentation/./driver-api/libata.rst". (note that I have actually never looked
at this doc file either since taking on libata maintainership. Its content may
not be up-to-date. Will need to review it.).

> Signed-off-by: Krzysztof Piotr Oledzki <ole@ans.pl>
> ---
>  drivers/ata/libata-core.c | 49 +++++++++++++++++++++------------------
>  drivers/ata/libata-eh.c   |  2 +-
>  2 files changed, 28 insertions(+), 23 deletions(-)
> 
> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
> index 4f35aab81a0a..0603849692ae 100644
> --- a/drivers/ata/libata-core.c
> +++ b/drivers/ata/libata-core.c
> @@ -1793,7 +1793,7 @@ int ata_dev_read_id(struct ata_device *dev, unsigned int *p_class,
>  
>  	if (err_mask) {
>  		if (err_mask & AC_ERR_NODEV_HINT) {
> -			ata_dev_dbg(dev, "NODEV after polling detection\n");
> +			ata_dev_err(dev, "NODEV after polling detection\n");

The "NODEV" mention here makes no sense given that we return -ENOENT. Let's
instead print the error mask with the usual format.

>  			return -ENOENT;
>  		}
>  
> @@ -1825,8 +1825,8 @@ int ata_dev_read_id(struct ata_device *dev, unsigned int *p_class,
>  			 * both flavors of IDENTIFYs which happens
>  			 * sometimes with phantom devices.
>  			 */
> -			ata_dev_dbg(dev,
> -				    "both IDENTIFYs aborted, assuming NODEV\n");
> +			ata_dev_info(dev,
> +				     "both IDENTIFYs aborted, assuming NODEV\n");

This is not really normal, so let's make this a "warn". And replace "NODEV"
with "no device present.".

>  			return -ENOENT;
>  		}
>  
> @@ -1857,9 +1857,9 @@ int ata_dev_read_id(struct ata_device *dev, unsigned int *p_class,
>  	if (class == ATA_DEV_ATA || class == ATA_DEV_ZAC) {
>  		if (!ata_id_is_ata(id) && !ata_id_is_cfa(id))
>  			goto err_out;
> -		if (ap->host->flags & ATA_HOST_IGNORE_ATA &&
> -							ata_id_is_ata(id)) {
> -			ata_dev_dbg(dev,
> +		if ((ap->host->flags & ATA_HOST_IGNORE_ATA) &&
> +		    ata_id_is_ata(id)) {
> +			ata_dev_info(dev,
>  				"host indicates ignore ATA devices, ignored\n");

Let's improve the wording here as "host" has a meaning (e.g. scsi host). Let's
make this something like:

		 ata_dev_info(dev,
			"ATA_HOST_IGNORE_ATA set: ignoring device.\n");

>  			return -ENOENT;
>  		}
> @@ -2247,7 +2247,8 @@ static void ata_dev_config_ncq_send_recv(struct ata_device *dev)
>  		memcpy(cmds, ap->sector_buf, ATA_LOG_NCQ_SEND_RECV_SIZE);
>  
>  		if (dev->horkage & ATA_HORKAGE_NO_NCQ_TRIM) {
> -			ata_dev_dbg(dev, "disabling queued TRIM support\n");
> +			ata_dev_info(dev, "disabling queued TRIM - "
> +					  "known buggy device\n");

There is no need to change the message text here: it is clear. And because this
is a horkage, let's use ata_dev_warn() and capitalize the first letter of the
message:

			ata_dev_warn(dev, "Disabling NCQ TRIM support\n");

Note that we could define a common format for all horkage related messages. E.g.:
		
ata_dev_warn(dev,
	"ATA_HORKAGE_NO_NCQ_TRIM set: Disabling queued TRIM support\n");

But I am not sure that is really useful as long as the same message text is not
repeated for a different reason. That will avoid the long lines :)

>  			cmds[ATA_LOG_NCQ_SEND_RECV_DSM_OFFSET] &=
>  				~ATA_LOG_NCQ_SEND_RECV_DSM_TRIM;
>  		}
> @@ -2335,13 +2336,13 @@ static int ata_dev_config_ncq(struct ata_device *dev,
>  	if (!IS_ENABLED(CONFIG_SATA_HOST))
>  		return 0;
>  	if (dev->horkage & ATA_HORKAGE_NONCQ) {
> -		snprintf(desc, desc_sz, "NCQ (not used)");
> +		snprintf(desc, desc_sz, "NCQ (not used - known buggy device)");

I think we should replace this snprintf() with a ata_dev_warn() message similar
to the above NCQ TRIM. E.g.:

		ata_dev_warn(dev, "Disabling NCQ support\n");

>  		return 0;
>  	}
>  
>  	if (dev->horkage & ATA_HORKAGE_NO_NCQ_ON_ATI &&
>  	    ata_dev_check_adapter(dev, PCI_VENDOR_ID_ATI)) {
> -		snprintf(desc, desc_sz, "NCQ (not used)");
> +		snprintf(desc, desc_sz, "NCQ (not used - known buggy device/host adapter)");

Same as above.

>  		return 0;
>  	}
>  
> @@ -2397,7 +2398,7 @@ static void ata_dev_config_sense_reporting(struct ata_device *dev)
>  
>  	err_mask = ata_dev_set_feature(dev, SETFEATURE_SENSE_DATA, 0x1);
>  	if (err_mask) {
> -		ata_dev_dbg(dev,
> +		ata_dev_err(dev,
>  			    "failed to enable Sense Data Reporting, Emask 0x%x\n",
>  			    err_mask);
>  	}
> @@ -2479,7 +2480,7 @@ static void ata_dev_config_trusted(struct ata_device *dev)
>  
>  	trusted_cap = get_unaligned_le64(&ap->sector_buf[40]);
>  	if (!(trusted_cap & (1ULL << 63))) {
> -		ata_dev_dbg(dev,
> +		ata_dev_err(dev,
>  			    "Trusted Computing capability qword not valid!\n");

I think this fits in one line. So let's drop the line break.

>  		return;
>  	}
> @@ -2688,9 +2689,15 @@ static void ata_dev_config_fua(struct ata_device *dev)
>  	if (!(dev->flags & ATA_DFLAG_LBA48) || !ata_id_has_fua(dev->id))
>  		goto nofua;
>  
> -	/* Ignore known bad devices and devices that lack NCQ support */
> -	if (!ata_ncq_supported(dev) || (dev->horkage & ATA_HORKAGE_NO_FUA))
> +	/* Ignore devices that lack NCQ support */
> +	if (!ata_ncq_supported(dev))
> +		goto nofua;
> +
> +	/* Finally, ignore buggy devices */
> +	if (dev->horkage & ATA_HORKAGE_NO_FUA) {
> +		ata_dev_info(dev, "disabling FUA - known buggy device");

Use ata_dev_warn():

		ata_dev_warn(dev, "Disabling FUA support.\n");

>  		goto nofua;
> +	}
>  
>  	dev->flags |= ATA_DFLAG_FUA;
>  
> @@ -3060,24 +3067,22 @@ int ata_dev_configure(struct ata_device *dev)
>  	if (ap->ops->dev_config)
>  		ap->ops->dev_config(dev);
>  
> -	if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
> +	if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
>  		/* Let the user know. We don't want to disallow opens for
>  		   rescue purposes, or in case the vendor is just a blithering
>  		   idiot. Do this after the dev_config call as some controllers
>  		   with buggy firmware may want to avoid reporting false device
>  		   bugs */

While at it, please fix this comment block format.

>  
> -		if (print_info) {
> -			ata_dev_warn(dev,
> -"Drive reports diagnostics failure. This may indicate a drive\n");
> -			ata_dev_warn(dev,
> -"fault or invalid emulation. Contact drive vendor for information.\n");
> -		}
> +		ata_dev_warn(dev, "Drive reports diagnostics failure."
> +				  " This may indicate a drive fault or invalid emulation."
> +				  " Contact drive vendor for information.\n");
>  	}
>  
>  	if ((dev->horkage & ATA_HORKAGE_FIRMWARE_WARN) && print_info) {
> -		ata_dev_warn(dev, "WARNING: device requires firmware update to be fully functional\n");
> -		ata_dev_warn(dev, "         contact the vendor or visit http://ata.wiki.kernel.org\n");
> +		ata_dev_warn(dev, "WARNING: device requires firmware update to be"
> +				  " fully functional contact the vendor or visit"
> +				  " http://ata.wiki.kernel.org/index.php/Known_issues\n");

As mentioned, I think we shoud drop the wiki link. It is not maintained.

>  	}
>  
>  	return 0;
> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
> index 214b935c2ced..5b9382ef261c 100644
> --- a/drivers/ata/libata-eh.c
> +++ b/drivers/ata/libata-eh.c
> @@ -2667,7 +2667,7 @@ int ata_eh_reset(struct ata_link *link, int classify,
>  
>  		if (rc) {
>  			if (rc == -ENOENT) {
> -				ata_link_dbg(link, "port disabled--ignoring\n");
> +				ata_link_info(link, "port disabled--ignoring\n");

I think ata_link_warn() is better here. And let's reformat the message:

				ata_link_warn(link,
					      "Ignoring disabled port\n");

>  				ehc->i.action &= ~ATA_EH_RESET;
>  
>  				ata_for_each_dev(dev, link, ALL)

-- 
Damien Le Moal
Western Digital Research