Re: Re: [RFC PATCH v2 5/7] ata_dev_printk: Use dev_printk

[Bartlomiej Zolnierkiewicz <b.zolnierkie@samsung.com>]

On 5/14/20 8:03 PM, Tony Asleson wrote:
> On 5/14/20 12:53 AM, Hannes Reinecke wrote:
>> On 5/13/20 11:36 PM, Tony Asleson wrote:
>>> Utilize the dev_printk function which will add structured data
>>> to the log message.
>>>
>>> Signed-off-by: Tony Asleson <tasleson@redhat.com>
>>> ---
>>>   drivers/ata/libata-core.c | 10 +++++++---
>>>   1 file changed, 7 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
>>> index 42c8728f6117..16978d615a17 100644
>>> --- a/drivers/ata/libata-core.c
>>> +++ b/drivers/ata/libata-core.c
>>> @@ -7301,6 +7301,7 @@ EXPORT_SYMBOL(ata_link_printk);
>>>   void ata_dev_printk(const struct ata_device *dev, const char *level,
>>>               const char *fmt, ...)
>>>   {
>>> +    const struct device *gendev;
>>>       struct va_format vaf;
>>>       va_list args;
>>>   @@ -7309,9 +7310,12 @@ void ata_dev_printk(const struct ata_device
>>> *dev, const char *level,
>>>       vaf.fmt = fmt;
>>>       vaf.va = &args;
>>>   -    printk("%sata%u.%02u: %pV",
>>> -           level, dev->link->ap->print_id, dev->link->pmp + dev->devno,
>>> -           &vaf);
>>> +    gendev = (dev->sdev) ? &dev->sdev->sdev_gendev : &dev->tdev;
>>> +
>>> +    dev_printk(level, gendev, "ata%u.%02u: %pV",
>>> +            dev->link->ap->print_id,
>>> +            dev->link->pmp + dev->devno,
>>> +            &vaf);
>>>         va_end(args);
>>>   }
>>>
>> That is wrong.
>> dev_printk() will already prefix the logging message with the device
>> name, so we'll end up having the name printed twice.
> 
> It certainly could be. Early in boot when &dev->sdev->sdev_gendev ==
> NULL and &dev->tdev is used we get
> 
> dev1.0: ata1.00: configured for UDMA/100
> 
> later when &dev->sdev->sdev_gendev != NULL we get
> 
> sd 1:0:0:0: [sdb] 209715200 512-byte logical blocks: (107 GB/100 GiB)

This one comes from the SCSI layer.

From libata we get i.e.:

sd 1:0:0:0: ata2.00: exception Emask 0x0 SAct 0x800000 SErr 0x800000
action 0x6 frozen

instead of

ata2.00: exception Emask 0x0 SAct 0x800000 SErr 0x800000 action 0x6 frozen

> to clarify, your point is dev1.0 is redundant as ata1.00 exists in the
> message?
> 
> 
> In the block layer print_req_error we get:
> 
> block sdb: blk_update_request: I/O error, dev sdb, sector 10000 op
> 0x0:(READ) flags 0x80700 phys_seg 4 prio class 0

I think it should be modified to not include dev any longer: 

block sdb: blk_update_request: I/O error, sector 10000 op
0x0:(READ) flags 0x80700 phys_seg 4 prio class 0

but it is up to Jens to make a final decision on that.

> Which seems a bit more redundant.

Yes but it is a debug message visible only on error while for libata
_all_ messages are now changed.

Best regards,
--
Bartlomiej Zolnierkiewicz
Samsung R&D Institute Poland
Samsung Electronics

> I've been trying to be careful to not change the human readable portion
> of the message, so not to disturb all the log scraping tools that exist
> mining errors.  Maybe this is the wrong approach?  In my original patch
> series I brought back printk_emit so that I could add the structured
> data without introducing changes in the message text output.  James
> Bottomley suggested using dev_printk which certainly made things
> cleaner, but it does add the prefix.
> 
> 
> Thanks,
> Tony
>