[PATCH] telemetry: lower log level on socket error

[PATCH] telemetry: lower log level on socket error

[David Marchand]

When starting two DPDK programs using the same DPDK prefix (like for
example OVS and testpmd, both running as primary processes in
--in-memory mode), the first DPDK process of the two spews some error
log when the second starts:

TELEMETRY: Socket write base info to client failed

This is because telemetry init involves trying to connect on existing
sockets to check if it can take over an existing socket file.

On the other hand, this error log provides no helpful information.
Lower this log to debug level.

Fixes: e14bb5f10509 ("telemetry: fix connected clients count")
Cc: stable@dpdk.org

Signed-off-by: David Marchand <david.marchand@redhat.com>
---
 lib/telemetry/telemetry.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/telemetry/telemetry.c b/lib/telemetry/telemetry.c
index 1663bd8c68..509fae76ec 100644
--- a/lib/telemetry/telemetry.c
+++ b/lib/telemetry/telemetry.c
@@ -382,7 +382,7 @@ client_handler(void *sock_id)
 			"{\"version\":\"%s\",\"pid\":%d,\"max_output_len\":%d}",
 			telemetry_version, getpid(), MAX_OUTPUT_LEN);
 	if (write(s, info_str, strlen(info_str)) < 0) {
-		TMTY_LOG_LINE(ERR, "Socket write base info to client failed");
+		TMTY_LOG_LINE(DEBUG, "Socket write base info to client failed");
 		goto exit;
 	}
 
-- 
2.44.0

Re: [PATCH] telemetry: lower log level on socket error

[Christian Ehrhardt]

On Thu, Jun 6, 2024 at 2:27 PM David Marchand <david.marchand@redhat.com> wrote:
>
> When starting two DPDK programs using the same DPDK prefix (like for
> example OVS and testpmd, both running as primary processes in
> --in-memory mode), the first DPDK process of the two spews some error
> log when the second starts:
>
> TELEMETRY: Socket write base info to client failed
>
> This is because telemetry init involves trying to connect on existing
> sockets to check if it can take over an existing socket file.
>
> On the other hand, this error log provides no helpful information.
> Lower this log to debug level.

I agree, it is useful info in rare occasions, but not a "please
consider having a panic" error level.
Thank you for polishing all edges of this one issue that I raised originally!

Signed-off-by: Christian Ehrhardt <christian.ehrhardt@canonical.com>

> Fixes: e14bb5f10509 ("telemetry: fix connected clients count")
> Cc: stable@dpdk.org
>
> Signed-off-by: David Marchand <david.marchand@redhat.com>
> ---
>  lib/telemetry/telemetry.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/lib/telemetry/telemetry.c b/lib/telemetry/telemetry.c
> index 1663bd8c68..509fae76ec 100644
> --- a/lib/telemetry/telemetry.c
> +++ b/lib/telemetry/telemetry.c
> @@ -382,7 +382,7 @@ client_handler(void *sock_id)
>                         "{\"version\":\"%s\",\"pid\":%d,\"max_output_len\":%d}",
>                         telemetry_version, getpid(), MAX_OUTPUT_LEN);
>         if (write(s, info_str, strlen(info_str)) < 0) {
> -               TMTY_LOG_LINE(ERR, "Socket write base info to client failed");
> +               TMTY_LOG_LINE(DEBUG, "Socket write base info to client failed");
>                 goto exit;
>         }
>
> --
> 2.44.0
>


-- 
Christian Ehrhardt
Director of Engineering, Ubuntu Server
Canonical Ltd

Re: [PATCH] telemetry: lower log level on socket error

[Bruce Richardson]

On Thu, Jun 06, 2024 at 02:26:54PM +0200, David Marchand wrote:
> When starting two DPDK programs using the same DPDK prefix (like for
> example OVS and testpmd, both running as primary processes in
> --in-memory mode), the first DPDK process of the two spews some error
> log when the second starts:
> 
> TELEMETRY: Socket write base info to client failed
> 
> This is because telemetry init involves trying to connect on existing
> sockets to check if it can take over an existing socket file.
> 
> On the other hand, this error log provides no helpful information.
> Lower this log to debug level.
> 
> Fixes: e14bb5f10509 ("telemetry: fix connected clients count")
> Cc: stable@dpdk.org
> 
> Signed-off-by: David Marchand <david.marchand@redhat.com>

Acked-by: Bruce Richardson <bruce.richardson@intel.com>

Would it be also worthwhile having the probing process wait a small amount
of time or check for an input string before closing the socket? That should
avoid the error message being necessary at all for the case described.

> ---
>  lib/telemetry/telemetry.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/lib/telemetry/telemetry.c b/lib/telemetry/telemetry.c
> index 1663bd8c68..509fae76ec 100644
> --- a/lib/telemetry/telemetry.c
> +++ b/lib/telemetry/telemetry.c
> @@ -382,7 +382,7 @@ client_handler(void *sock_id)
>  			"{\"version\":\"%s\",\"pid\":%d,\"max_output_len\":%d}",
>  			telemetry_version, getpid(), MAX_OUTPUT_LEN);
>  	if (write(s, info_str, strlen(info_str)) < 0) {
> -		TMTY_LOG_LINE(ERR, "Socket write base info to client failed");
> +		TMTY_LOG_LINE(DEBUG, "Socket write base info to client failed");
>  		goto exit;
>  	}
>  
> -- 
> 2.44.0
> 

Re: [PATCH] telemetry: lower log level on socket error

[Stephen Hemminger]

On Mon, 17 Jun 2024 15:28:17 +0100
Bruce Richardson <bruce.richardson@intel.com> wrote:

> On Thu, Jun 06, 2024 at 02:26:54PM +0200, David Marchand wrote:
> > When starting two DPDK programs using the same DPDK prefix (like for
> > example OVS and testpmd, both running as primary processes in
> > --in-memory mode), the first DPDK process of the two spews some error
> > log when the second starts:
> > 
> > TELEMETRY: Socket write base info to client failed
> > 
> > This is because telemetry init involves trying to connect on existing
> > sockets to check if it can take over an existing socket file.
> > 
> > On the other hand, this error log provides no helpful information.
> > Lower this log to debug level.
> > 
> > Fixes: e14bb5f10509 ("telemetry: fix connected clients count")
> > Cc: stable@dpdk.org
> > 
> > Signed-off-by: David Marchand <david.marchand@redhat.com>  
> 
> Acked-by: Bruce Richardson <bruce.richardson@intel.com>
> 
> Would it be also worthwhile having the probing process wait a small amount
> of time or check for an input string before closing the socket? That should
> avoid the error message being necessary at all for the case described.

If telemetry used abstract socket path instead this would not be a problem.
Using regular paths leads to races and problems with restart.
And all the stat and runtime check logic could go away.

Re: [PATCH] telemetry: lower log level on socket error

[Bruce Richardson]

On Mon, Jun 17, 2024 at 07:39:43AM -0700, Stephen Hemminger wrote:
> On Mon, 17 Jun 2024 15:28:17 +0100
> Bruce Richardson <bruce.richardson@intel.com> wrote:
> 
> > On Thu, Jun 06, 2024 at 02:26:54PM +0200, David Marchand wrote:
> > > When starting two DPDK programs using the same DPDK prefix (like for
> > > example OVS and testpmd, both running as primary processes in
> > > --in-memory mode), the first DPDK process of the two spews some error
> > > log when the second starts:
> > > 
> > > TELEMETRY: Socket write base info to client failed
> > > 
> > > This is because telemetry init involves trying to connect on existing
> > > sockets to check if it can take over an existing socket file.
> > > 
> > > On the other hand, this error log provides no helpful information.
> > > Lower this log to debug level.
> > > 
> > > Fixes: e14bb5f10509 ("telemetry: fix connected clients count")
> > > Cc: stable@dpdk.org
> > > 
> > > Signed-off-by: David Marchand <david.marchand@redhat.com>  
> > 
> > Acked-by: Bruce Richardson <bruce.richardson@intel.com>
> > 
> > Would it be also worthwhile having the probing process wait a small amount
> > of time or check for an input string before closing the socket? That should
> > avoid the error message being necessary at all for the case described.
> 
> If telemetry used abstract socket path instead this would not be a problem.
> Using regular paths leads to races and problems with restart.
> And all the stat and runtime check logic could go away.

Are abstract paths not linux-specific? Also, would using abstract paths not
mean that we need to implement some form of authentication on the
connections? Right now, using real paths in the DPDK runtime directory, a
regular user cannot connect to the telemetry of a process running as
another user or as root.

/Bruce

Re: [PATCH] telemetry: lower log level on socket error

[Stephen Hemminger]

On Mon, 17 Jun 2024 15:52:09 +0100
Bruce Richardson <bruce.richardson@intel.com> wrote:

> > > 
> > > Would it be also worthwhile having the probing process wait a small amount
> > > of time or check for an input string before closing the socket? That should
> > > avoid the error message being necessary at all for the case described.  
> > 
> > If telemetry used abstract socket path instead this would not be a problem.
> > Using regular paths leads to races and problems with restart.
> > And all the stat and runtime check logic could go away.  
> 
> Are abstract paths not linux-specific? Also, would using abstract paths not
> mean that we need to implement some form of authentication on the
> connections? Right now, using real paths in the DPDK runtime directory, a
> regular user cannot connect to the telemetry of a process running as
> another user or as root.

Yes. But existing restart logic is brittle.

Re: [PATCH] telemetry: lower log level on socket error

[Thomas Monjalon]

06/06/2024 15:26, Christian Ehrhardt:
> On Thu, Jun 6, 2024 at 2:27 PM David Marchand <david.marchand@redhat.com> wrote:
> >
> > When starting two DPDK programs using the same DPDK prefix (like for
> > example OVS and testpmd, both running as primary processes in
> > --in-memory mode), the first DPDK process of the two spews some error
> > log when the second starts:
> >
> > TELEMETRY: Socket write base info to client failed
> >
> > This is because telemetry init involves trying to connect on existing
> > sockets to check if it can take over an existing socket file.
> >
> > On the other hand, this error log provides no helpful information.
> > Lower this log to debug level.
> 
> I agree, it is useful info in rare occasions, but not a "please
> consider having a panic" error level.
> Thank you for polishing all edges of this one issue that I raised originally!
> 
> Signed-off-by: Christian Ehrhardt <christian.ehrhardt@canonical.com>

Where did you raise it? I don't find it in emails.

Re: [PATCH] telemetry: lower log level on socket error

[Thomas Monjalon]

17/06/2024 16:28, Bruce Richardson:
> On Thu, Jun 06, 2024 at 02:26:54PM +0200, David Marchand wrote:
> > When starting two DPDK programs using the same DPDK prefix (like for
> > example OVS and testpmd, both running as primary processes in
> > --in-memory mode), the first DPDK process of the two spews some error
> > log when the second starts:
> > 
> > TELEMETRY: Socket write base info to client failed
> > 
> > This is because telemetry init involves trying to connect on existing
> > sockets to check if it can take over an existing socket file.
> > 
> > On the other hand, this error log provides no helpful information.
> > Lower this log to debug level.
> > 
> > Fixes: e14bb5f10509 ("telemetry: fix connected clients count")
> > Cc: stable@dpdk.org
> > 
> > Signed-off-by: David Marchand <david.marchand@redhat.com>
> 
> Acked-by: Bruce Richardson <bruce.richardson@intel.com>

Applied, thanks.