[RFC,0/3] Detect superfluous newline in logs

  Getting readable and consistent logs is important when running a DPDK
application, especially when troubleshooting.
A common issue with logs is when a DPDK change do not add (or on the
contrary add too many \n) in the format string.

This issue would only get noticed when actually hitting this log (which
may be something difficult to do).

This series proposes to introduce a new RTE_LOG helper that is
responsible for logging a one line message and spews a build error (with
gcc) if any \n is part of the format string.


Note:
- the first patch is intentionnally sent as a single block: splitting it
  into per library commits with correct Fixes: tags is a tedious work.
  I would split it for a non RFC series. For now, it is enough to show
  case the idea.
- the last patch shows how an existing log macro is converted,
  

On Fri, Nov 17, 2023 at 02:18:21PM +0100, David Marchand wrote:
> Getting readable and consistent logs is important when running a DPDK
> application, especially when troubleshooting.
> A common issue with logs is when a DPDK change do not add (or on the
> contrary add too many \n) in the format string.
> 
> This issue would only get noticed when actually hitting this log (which
> may be something difficult to do).
> 
> This series proposes to introduce a new RTE_LOG helper that is
> responsible for logging a one line message and spews a build error (with
> gcc) if any \n is part of the format string.
> 
> 
> Note:
> - the first patch is intentionnally sent as a single block: splitting it
>   into per library commits with correct Fixes: tags is a tedious work.
>   I would split it for a non RFC series. For now, it is enough to show
>   case the idea.
> - the last patch shows how an existing log macro is converted,
> 
> 
very nice. I definitely think this should be implemented for 24.03

Thanks,
/Bruce

PS: I'm not even sure that the first patch needs to be split. I think it's
    fairly clear as-is.
  

> From: David Marchand [mailto:david.marchand@redhat.com]
> Sent: Friday, 17 November 2023 14.18
> 
> Getting readable and consistent logs is important when running a DPDK
> application, especially when troubleshooting.
> A common issue with logs is when a DPDK change do not add (or on the
> contrary add too many \n) in the format string.
> 
> This issue would only get noticed when actually hitting this log (which
> may be something difficult to do).
> 
> This series proposes to introduce a new RTE_LOG helper that is
> responsible for logging a one line message and spews a build error
> (with gcc) if any \n is part of the format string.
> 

The new helper's name is RTE_LOG_LINE, not RTE_LOG.

As far as I can see, RTE_LOG continues working as before - allowing one line of log message to span multiple lines of RTE_LOG() calls with \n in the last of them. Which is good.

Anyway, I like the concept. And it solves a real problem.

If you want other names, e.g. RTE_LOG for a complete line (appending \n in the macro itself), and RTE_LOG_PART (or similar) for an incomplete line, I wouldn't object. But that would probably break the API.

> 
> Note:
> - the first patch is intentionnally sent as a single block: splitting
> it
>   into per library commits with correct Fixes: tags is a tedious work.
>   I would split it for a non RFC series. For now, it is enough to show
>   case the idea.
> - the last patch shows how an existing log macro is converted,
  

On Fri, Nov 17, 2023 at 2:27 PM Bruce Richardson
<bruce.richardson@intel.com> wrote:
>
> On Fri, Nov 17, 2023 at 02:18:21PM +0100, David Marchand wrote:
> > Getting readable and consistent logs is important when running a DPDK
> > application, especially when troubleshooting.
> > A common issue with logs is when a DPDK change do not add (or on the
> > contrary add too many \n) in the format string.
> >
> > This issue would only get noticed when actually hitting this log (which
> > may be something difficult to do).
> >
> > This series proposes to introduce a new RTE_LOG helper that is
> > responsible for logging a one line message and spews a build error (with
> > gcc) if any \n is part of the format string.
> >
> >
> > Note:
> > - the first patch is intentionnally sent as a single block: splitting it
> >   into per library commits with correct Fixes: tags is a tedious work.
> >   I would split it for a non RFC series. For now, it is enough to show
> >   case the idea.
> > - the last patch shows how an existing log macro is converted,
> >
> >
> very nice. I definitely think this should be implemented for 24.03

I am still wondering how this idea should evolve...

Some points I have in mind but for which I am not sure what is the best.

Some log helpers were exposed to applications and had no explicit
requirement wrt \n.
Applications may have used those helpers with multiline messages.
So maybe existing *exposed* helpers should be left untouched... and a
new helper would need to be introduced.
IOW with an example, cryptodev (missing a RTE_ prefix) CDEV_LOG_ERR
macro is publicly exposed.
A CDEV_LOG_LINE_ERR may be needed to avoid breaking external users.


There are a lot of other log macros that let it to the callers to add
a trailing \n.
Should we convert them?
Converting the *whole* DPDK code to the new helper (with some
exceptions for people who like multiline logs..) would be nice to
close this topic once and for all.
But it would likely be a nightmare for later fixes that contain logs
and which could introduce regressions in such logs if the backport
does not take care of re-adding a \n.
  

On Fri, Nov 17, 2023 at 2:47 PM Morten Brørup <mb@smartsharesystems.com> wrote:
>
> > From: David Marchand [mailto:david.marchand@redhat.com]
> > Sent: Friday, 17 November 2023 14.18
> >
> > Getting readable and consistent logs is important when running a DPDK
> > application, especially when troubleshooting.
> > A common issue with logs is when a DPDK change do not add (or on the
> > contrary add too many \n) in the format string.
> >
> > This issue would only get noticed when actually hitting this log (which
> > may be something difficult to do).
> >
> > This series proposes to introduce a new RTE_LOG helper that is
> > responsible for logging a one line message and spews a build error
> > (with gcc) if any \n is part of the format string.
> >
>
> The new helper's name is RTE_LOG_LINE, not RTE_LOG.

Sorry, wrong completion.

>
> As far as I can see, RTE_LOG continues working as before - allowing one line of log message to span multiple lines of RTE_LOG() calls with \n in the last of them. Which is good.

Indeed, we can't break / change RTE_LOG api.
This API is too old, that would be a nightmare.

>
> Anyway, I like the concept. And it solves a real problem.
>
> If you want other names, e.g. RTE_LOG for a complete line (appending \n in the macro itself), and RTE_LOG_PART (or similar) for an incomplete line, I wouldn't object. But that would probably break the API.

No API breaking allowed :-).
  

On Fri, Nov 17, 2023 at 02:48:25PM +0100, David Marchand wrote:
> On Fri, Nov 17, 2023 at 2:27 PM Bruce Richardson
> <bruce.richardson@intel.com> wrote:
> >
> > On Fri, Nov 17, 2023 at 02:18:21PM +0100, David Marchand wrote:
> > > Getting readable and consistent logs is important when running a DPDK
> > > application, especially when troubleshooting.
> > > A common issue with logs is when a DPDK change do not add (or on the
> > > contrary add too many \n) in the format string.
> > >
> > > This issue would only get noticed when actually hitting this log (which
> > > may be something difficult to do).
> > >
> > > This series proposes to introduce a new RTE_LOG helper that is
> > > responsible for logging a one line message and spews a build error (with
> > > gcc) if any \n is part of the format string.
> > >
> > >
> > > Note:
> > > - the first patch is intentionnally sent as a single block: splitting it
> > >   into per library commits with correct Fixes: tags is a tedious work.
> > >   I would split it for a non RFC series. For now, it is enough to show
> > >   case the idea.
> > > - the last patch shows how an existing log macro is converted,
> > >
> > >
> > very nice. I definitely think this should be implemented for 24.03
> 
> I am still wondering how this idea should evolve...
> 
> Some points I have in mind but for which I am not sure what is the best.
> 
> Some log helpers were exposed to applications and had no explicit
> requirement wrt \n.
> Applications may have used those helpers with multiline messages.
> So maybe existing *exposed* helpers should be left untouched... and a
> new helper would need to be introduced.

And the existing helpers deprecated. Internal log helpers should not be
exposed to apps.

> IOW with an example, cryptodev (missing a RTE_ prefix) CDEV_LOG_ERR
> macro is publicly exposed.
> A CDEV_LOG_LINE_ERR may be needed to avoid breaking external users.
> 

RTE_CDEV_LOG_ERR should be available, though, right? :-)

> 
> There are a lot of other log macros that let it to the callers to add
> a trailing \n.
> Should we convert them?

I would think that, ideally, yes we should.

> Converting the *whole* DPDK code to the new helper (with some
> exceptions for people who like multiline logs..) would be nice to
> close this topic once and for all.
> But it would likely be a nightmare for later fixes that contain logs
> and which could introduce regressions in such logs if the backport
> does not take care of re-adding a \n.

Good point. I wonder how many backports add new logs, or modify existing
ones? Are there any automated checks, or a checklist for backports to
enable us to catch these sort of things?
Naming could be a problem, but we could look to move over existing logs by
using new log macro names, which should help us to catch these. Even if the
log names are a bit awkward, if they are kept internal-only, it shouldn't
matter much. [Plus we would always be free to do a mass-rename back to the
original name in future, once the backport issues are reduced].

/Bruce
  

> From: David Marchand [mailto:david.marchand@redhat.com]
> Sent: Friday, 17 November 2023 15.10
> 
> On Fri, Nov 17, 2023 at 2:47 PM Morten Brørup
> <mb@smartsharesystems.com> wrote:
> >
> > > From: David Marchand [mailto:david.marchand@redhat.com]
> > > Sent: Friday, 17 November 2023 14.18
> > >
> > > Getting readable and consistent logs is important when running a
> DPDK
> > > application, especially when troubleshooting.
> > > A common issue with logs is when a DPDK change do not add (or on
> the
> > > contrary add too many \n) in the format string.
> > >
> > > This issue would only get noticed when actually hitting this log
> (which
> > > may be something difficult to do).
> > >
> > > This series proposes to introduce a new RTE_LOG helper that is
> > > responsible for logging a one line message and spews a build error
> > > (with gcc) if any \n is part of the format string.
> > >
> >
> > The new helper's name is RTE_LOG_LINE, not RTE_LOG.
> 
> Sorry, wrong completion.
> 
> >
> > As far as I can see, RTE_LOG continues working as before - allowing
> one line of log message to span multiple lines of RTE_LOG() calls with
> \n in the last of them. Which is good.
> 
> Indeed, we can't break / change RTE_LOG api.
> This API is too old, that would be a nightmare.
> 
> >
> > Anyway, I like the concept. And it solves a real problem.
> >
> > If you want other names, e.g. RTE_LOG for a complete line (appending
> \n in the macro itself), and RTE_LOG_PART (or similar) for an
> incomplete line, I wouldn't object. But that would probably break the
> API.
> 
> No API breaking allowed :-).

OK, then:

Series-acked-by: Morten Brørup <mb@smartsharesystems.com>
  

On Fri, Nov 17, 2023 at 3:11 PM Bruce Richardson
<bruce.richardson@intel.com> wrote:
>
> On Fri, Nov 17, 2023 at 02:48:25PM +0100, David Marchand wrote:
> > On Fri, Nov 17, 2023 at 2:27 PM Bruce Richardson
> > <bruce.richardson@intel.com> wrote:
> > >
> > > On Fri, Nov 17, 2023 at 02:18:21PM +0100, David Marchand wrote:
> > > > Getting readable and consistent logs is important when running a DPDK
> > > > application, especially when troubleshooting.
> > > > A common issue with logs is when a DPDK change do not add (or on the
> > > > contrary add too many \n) in the format string.
> > > >
> > > > This issue would only get noticed when actually hitting this log (which
> > > > may be something difficult to do).
> > > >
> > > > This series proposes to introduce a new RTE_LOG helper that is
> > > > responsible for logging a one line message and spews a build error (with
> > > > gcc) if any \n is part of the format string.
> > > >
> > > >
> > > > Note:
> > > > - the first patch is intentionnally sent as a single block: splitting it
> > > >   into per library commits with correct Fixes: tags is a tedious work.
> > > >   I would split it for a non RFC series. For now, it is enough to show
> > > >   case the idea.
> > > > - the last patch shows how an existing log macro is converted,
> > > >
> > > >
> > > very nice. I definitely think this should be implemented for 24.03
> >
> > I am still wondering how this idea should evolve...
> >
> > Some points I have in mind but for which I am not sure what is the best.
> >
> > Some log helpers were exposed to applications and had no explicit
> > requirement wrt \n.
> > Applications may have used those helpers with multiline messages.
> > So maybe existing *exposed* helpers should be left untouched... and a
> > new helper would need to be introduced.
>
> And the existing helpers deprecated. Internal log helpers should not be
> exposed to apps.

I agree.


>
> > IOW with an example, cryptodev (missing a RTE_ prefix) CDEV_LOG_ERR
> > macro is publicly exposed.
> > A CDEV_LOG_LINE_ERR may be needed to avoid breaking external users.
> >
>
> RTE_CDEV_LOG_ERR should be available, though, right? :-)

Err, yes, but if we make it private, we don't need the RTE_ prefix ? :-)

>
> >
> > There are a lot of other log macros that let it to the callers to add
> > a trailing \n.
> > Should we convert them?
>
> I would think that, ideally, yes we should.
>
> > Converting the *whole* DPDK code to the new helper (with some
> > exceptions for people who like multiline logs..) would be nice to
> > close this topic once and for all.
> > But it would likely be a nightmare for later fixes that contain logs
> > and which could introduce regressions in such logs if the backport
> > does not take care of re-adding a \n.
>
> Good point. I wonder how many backports add new logs, or modify existing
> ones? Are there any automated checks, or a checklist for backports to

Touching logs in backport happens often afaics.

(to simplify I added a vXX.11.0 tag pointing at vXX.11)

$ for i in $(seq 0 4); do echo v21.11.${i}..v21.11.$((i + 1)) $(git
diff v21.11.${i}..v21.11.$((i + 1)) | grep -c ^\+.*LOG); done
v21.11.0..v21.11.1 122
v21.11.1..v21.11.2 40
v21.11.2..v21.11.3 43
v21.11.3..v21.11.4 30
v21.11.4..v21.11.5 24

$ for i in $(seq 0 2); do echo v22.11.${i}..v22.11.$((i + 1)) $(git
diff v22.11.${i}..v22.11.$((i + 1)) | grep -c ^\+.*LOG); done
v22.11.0..v22.11.1 0
v22.11.1..v22.11.2 37
v22.11.2..v22.11.3 106

I don't think there are checks on this topic (and to be fair, I don't
see which check could be done).


> enable us to catch these sort of things?
> Naming could be a problem, but we could look to move over existing logs by
> using new log macro names, which should help us to catch these. Even if the
> log names are a bit awkward, if they are kept internal-only, it shouldn't
> matter much. [Plus we would always be free to do a mass-rename back to the
> original name in future, once the backport issues are reduced].

This is the way I had in mind.