Re: [PATCH v5 00/13] Detect superfluous newline in logs

[Stephen Hemminger <stephen@networkplumber.org>]

On Wed, 20 Dec 2023 16:35:53 +0100
David Marchand <david.marchand@redhat.com> 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 a situation hard to reach).
> 
> This series proposes to introduce a new RTE_LOG_LINE 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.
> 
> 
> Since the v1 discussion on the cover letter, I changed my mind, and made the
> choice to break existing logging helpers exported in the public API.
> The reasoning is that those should not be used in the first place:
> logs should be produced only by the library that registers the logtype.
> 
> Some multiline logging for debugging and the test assert macros are
> still present, but in this case an explicit call to RTE_LOG() is done.
> This can be checked with a simple:
> $ git grep -E 'RTE_LOG(_DP)?\(' -- lib/ :^lib/log/
> lib/acl/acl_bld.c:      RTE_LOG(DEBUG, ACL, "Build phase for ACL \"%s\":\n"
> lib/acl/acl_gen.c:      RTE_LOG(DEBUG, ACL, "Gen phase for ACL \"%s\":\n"
> lib/bpf/bpf_validate.c: RTE_LOG(DEBUG, BPF, "%s(%p) stats:\n"
> lib/bpf/bpf_validate.c: RTE_LOG(DEBUG, BPF,
> lib/eal/common/eal_common_debug.c:              RTE_LOG(CRIT, EAL, "Error - exiting with code: %d\n"
> lib/eal/include/rte_test.h:             RTE_LOG(ERR, EAL, "Test assert %s line %d failed: "           \
> lib/ip_frag/ip_frag_common.h:#define    IP_FRAG_LOG(lvl, fmt, args...)  RTE_LOG(lvl, IPFRAG, fmt, ##args)
> lib/sched/rte_sched.c:  RTE_LOG(DEBUG, SCHED, "Low level config for pipe profile %u:\n"
> lib/sched/rte_sched.c:  RTE_LOG(DEBUG, SCHED, "Low level config for subport profile %u:\n"
> lib/vhost/vhost.h:      RTE_LOG_DP(DEBUG, VHOST_DATA, "VHOST_DATA: (%s) %s", dev->ifname, packet); \

Tabs are also problematic for syslog.

With simple mod to testpmd:
diff --git a/app/test-pmd/testpmd.c b/app/test-pmd/testpmd.c
index 9e4e99e53b9a..811fe0c4aeb8 100644
--- a/app/test-pmd/testpmd.c
+++ b/app/test-pmd/testpmd.c
@@ -4555,6 +4555,9 @@ main(int argc, char** argv)
                rte_exit(EXIT_FAILURE, "Cannot init EAL: %s\n",
                         rte_strerror(rte_errno));
 
+       RTE_LOG(INFO, USER1, "Sample log message with extra\nnewline\n");
+       RTE_LOG(INFO, USER1, "Sample log message with tab\tinserted\n");

And the result in syslog is:

2023-12-21T08:27:47.172156-08:00 sut dpdk-testpmd[69471]: USER1: Sample log message with extra#012newline
2023-12-21T08:27:47.173418-08:00 sut dpdk-testpmd[69471]: USER1: Sample log message with tab#011inserted