diff mbox series

[1/5] USB: typec: tcpm: Prevent log overflow by removing old entries

Message ID 20201210160521.3417426-2-gregkh@linuxfoundation.org (mailing list archive)
State New, archived
Headers show
Series USB: typec: various patches | expand

Commit Message

Greg KH Dec. 10, 2020, 4:05 p.m. UTC 
From: Badhri Jagan Sridharan <badhri@google.com>

TCPM logs overflow once the logbuffer is full. Clear old entries and
allow logging the newer ones as the newer would be more relevant to the
issue being debugged.

Also, do not reset the logbuffer tail as end users might take back to
back bugreports which would result in an empty buffer.

Cc: Guenter Roeck <linux@roeck-us.net>
Cc: Heikki Krogerus <heikki.krogerus@linux.intel.com>
Cc: Kyle Tso <kyletso@google.com>
Signed-off-by: Badhri Jagan Sridharan <badhri@google.com>
Signed-off-by: Will McVicker <willmcvicker@google.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
---
 drivers/usb/typec/tcpm/tcpm.c | 16 +++-------------
 1 file changed, 3 insertions(+), 13 deletions(-)

Comments

Guenter Roeck Dec. 10, 2020, 5:42 p.m. UTC | #1 
On Thu, Dec 10, 2020 at 05:05:17PM +0100, Greg Kroah-Hartman wrote:
> From: Badhri Jagan Sridharan <badhri@google.com>
> 
> TCPM logs overflow once the logbuffer is full. Clear old entries and
> allow logging the newer ones as the newer would be more relevant to the
> issue being debugged.
> 
> Also, do not reset the logbuffer tail as end users might take back to
> back bugreports which would result in an empty buffer.
> 

Historically, the reason for not doing this was that, once a problem occurs,
the log would fill up quickly (typically with reconnect attempts), and the
actual reason for the problem would be overwritten. Maybe that reasoning
no longer applies; I just wanted to point out that there _was_ a reason for
not clearing old log entries.

Guenter

> Cc: Guenter Roeck <linux@roeck-us.net>
> Cc: Heikki Krogerus <heikki.krogerus@linux.intel.com>
> Cc: Kyle Tso <kyletso@google.com>
> Signed-off-by: Badhri Jagan Sridharan <badhri@google.com>
> Signed-off-by: Will McVicker <willmcvicker@google.com>
> Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> ---
>  drivers/usb/typec/tcpm/tcpm.c | 16 +++-------------
>  1 file changed, 3 insertions(+), 13 deletions(-)
> 
> diff --git a/drivers/usb/typec/tcpm/tcpm.c b/drivers/usb/typec/tcpm/tcpm.c
> index cedc6cf82d61..0ceeab50ed64 100644
> --- a/drivers/usb/typec/tcpm/tcpm.c
> +++ b/drivers/usb/typec/tcpm/tcpm.c
> @@ -470,12 +470,6 @@ static bool tcpm_port_is_disconnected(struct tcpm_port *port)
>  
>  #ifdef CONFIG_DEBUG_FS
>  
> -static bool tcpm_log_full(struct tcpm_port *port)
> -{
> -	return port->logbuffer_tail ==
> -		(port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
> -}
> -
>  __printf(2, 0)
>  static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
>  {
> @@ -495,11 +489,6 @@ static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
>  
>  	vsnprintf(tmpbuffer, sizeof(tmpbuffer), fmt, args);
>  
> -	if (tcpm_log_full(port)) {
> -		port->logbuffer_head = max(port->logbuffer_head - 1, 0);
> -		strcpy(tmpbuffer, "overflow");
> -	}
> -
>  	if (port->logbuffer_head < 0 ||
>  	    port->logbuffer_head >= LOG_BUFFER_ENTRIES) {
>  		dev_warn(port->dev,
> @@ -519,6 +508,9 @@ static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
>  		  (unsigned long)ts_nsec, rem_nsec / 1000,
>  		  tmpbuffer);
>  	port->logbuffer_head = (port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
> +	if (port->logbuffer_head == port->logbuffer_tail)
> +		port->logbuffer_tail =
> +			(port->logbuffer_tail + 1) % LOG_BUFFER_ENTRIES;
>  
>  abort:
>  	mutex_unlock(&port->logbuffer_lock);
> @@ -622,8 +614,6 @@ static int tcpm_debug_show(struct seq_file *s, void *v)
>  		seq_printf(s, "%s\n", port->logbuffer[tail]);
>  		tail = (tail + 1) % LOG_BUFFER_ENTRIES;
>  	}
> -	if (!seq_has_overflowed(s))
> -		port->logbuffer_tail = tail;
>  	mutex_unlock(&port->logbuffer_lock);
>  
>  	return 0;
> -- 
> 2.29.2
>
Badhri Jagan Sridharan Dec. 10, 2020, 7:10 p.m. UTC | #2 
Hi Guenter,

While I agree with what you are saying, since the logbuffer does not
have the intelligence to drop older entries where no issues were seen,
logbuffer gets full pretty quickly with good instances and there is no
space left to log the bad instance. Should wrapping this in a config
option be a better way to go about this  ? When the config optioin is
set, old entries will be dropped.
Please let me know, I can update the patch and resend.

Thanks,
Badhri



On Thu, Dec 10, 2020 at 9:53 AM Guenter Roeck <linux@roeck-us.net> wrote:
>
> On Thu, Dec 10, 2020 at 05:05:17PM +0100, Greg Kroah-Hartman wrote:
> > From: Badhri Jagan Sridharan <badhri@google.com>
> >
> > TCPM logs overflow once the logbuffer is full. Clear old entries and
> > allow logging the newer ones as the newer would be more relevant to the
> > issue being debugged.
> >
> > Also, do not reset the logbuffer tail as end users might take back to
> > back bugreports which would result in an empty buffer.
> >
>
> Historically, the reason for not doing this was that, once a problem occurs,
> the log would fill up quickly (typically with reconnect attempts), and the
> actual reason for the problem would be overwritten. Maybe that reasoning
> no longer applies; I just wanted to point out that there _was_ a reason for
> not clearing old log entries.
>
> Guenter
>
> > Cc: Guenter Roeck <linux@roeck-us.net>
> > Cc: Heikki Krogerus <heikki.krogerus@linux.intel.com>
> > Cc: Kyle Tso <kyletso@google.com>
> > Signed-off-by: Badhri Jagan Sridharan <badhri@google.com>
> > Signed-off-by: Will McVicker <willmcvicker@google.com>
> > Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> > ---
> >  drivers/usb/typec/tcpm/tcpm.c | 16 +++-------------
> >  1 file changed, 3 insertions(+), 13 deletions(-)
> >
> > diff --git a/drivers/usb/typec/tcpm/tcpm.c b/drivers/usb/typec/tcpm/tcpm.c
> > index cedc6cf82d61..0ceeab50ed64 100644
> > --- a/drivers/usb/typec/tcpm/tcpm.c
> > +++ b/drivers/usb/typec/tcpm/tcpm.c
> > @@ -470,12 +470,6 @@ static bool tcpm_port_is_disconnected(struct tcpm_port *port)
> >
> >  #ifdef CONFIG_DEBUG_FS
> >
> > -static bool tcpm_log_full(struct tcpm_port *port)
> > -{
> > -     return port->logbuffer_tail ==
> > -             (port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
> > -}
> > -
> >  __printf(2, 0)
> >  static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
> >  {
> > @@ -495,11 +489,6 @@ static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
> >
> >       vsnprintf(tmpbuffer, sizeof(tmpbuffer), fmt, args);
> >
> > -     if (tcpm_log_full(port)) {
> > -             port->logbuffer_head = max(port->logbuffer_head - 1, 0);
> > -             strcpy(tmpbuffer, "overflow");
> > -     }
> > -
> >       if (port->logbuffer_head < 0 ||
> >           port->logbuffer_head >= LOG_BUFFER_ENTRIES) {
> >               dev_warn(port->dev,
> > @@ -519,6 +508,9 @@ static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
> >                 (unsigned long)ts_nsec, rem_nsec / 1000,
> >                 tmpbuffer);
> >       port->logbuffer_head = (port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
> > +     if (port->logbuffer_head == port->logbuffer_tail)
> > +             port->logbuffer_tail =
> > +                     (port->logbuffer_tail + 1) % LOG_BUFFER_ENTRIES;
> >
> >  abort:
> >       mutex_unlock(&port->logbuffer_lock);
> > @@ -622,8 +614,6 @@ static int tcpm_debug_show(struct seq_file *s, void *v)
> >               seq_printf(s, "%s\n", port->logbuffer[tail]);
> >               tail = (tail + 1) % LOG_BUFFER_ENTRIES;
> >       }
> > -     if (!seq_has_overflowed(s))
> > -             port->logbuffer_tail = tail;
> >       mutex_unlock(&port->logbuffer_lock);
> >
> >       return 0;
> > --
> > 2.29.2
> >
Guenter Roeck Dec. 11, 2020, 12:01 a.m. UTC | #3 
On Thu, Dec 10, 2020 at 11:10:27AM -0800, Badhri Jagan Sridharan wrote:
> Hi Guenter,
> 
> While I agree with what you are saying, since the logbuffer does not
> have the intelligence to drop older entries where no issues were seen,
> logbuffer gets full pretty quickly with good instances and there is no
> space left to log the bad instance. Should wrapping this in a config

For my use case, it was typically sufficient to clear the log buffer
by reading it if needed. However, as I said, my original reason may no
longer apply. After all, the code is much more stable than it used to be,
and maybe the endless conection attempts after an initial error are no
longer seen. At this point I don't really have a strong opinion either way.

> option be a better way to go about this  ? When the config optioin is
> set, old entries will be dropped.

A config option (assuming you mean Kconfig) seems bad. Maybe we could
have a writeable debugfs file which defines the approach to use (not
sure if that would be acceptable, though).

Note that I also considered changing logging to tracing, but that has
the disadvantage that it needs to be explicitly activated and doesn't
provide any kind of history in the "normal" case. On a higher level,
it would be nice to have a logging option like the one implemented here
in the infrastucture. But that is really a completely different issue.

Thanks,
Guenter

> Please let me know, I can update the patch and resend.
> 
> Thanks,
> Badhri
> 
> 
> 
> On Thu, Dec 10, 2020 at 9:53 AM Guenter Roeck <linux@roeck-us.net> wrote:
> >
> > On Thu, Dec 10, 2020 at 05:05:17PM +0100, Greg Kroah-Hartman wrote:
> > > From: Badhri Jagan Sridharan <badhri@google.com>
> > >
> > > TCPM logs overflow once the logbuffer is full. Clear old entries and
> > > allow logging the newer ones as the newer would be more relevant to the
> > > issue being debugged.
> > >
> > > Also, do not reset the logbuffer tail as end users might take back to
> > > back bugreports which would result in an empty buffer.
> > >
> >
> > Historically, the reason for not doing this was that, once a problem occurs,
> > the log would fill up quickly (typically with reconnect attempts), and the
> > actual reason for the problem would be overwritten. Maybe that reasoning
> > no longer applies; I just wanted to point out that there _was_ a reason for
> > not clearing old log entries.
> >
> > Guenter
> >
> > > Cc: Guenter Roeck <linux@roeck-us.net>
> > > Cc: Heikki Krogerus <heikki.krogerus@linux.intel.com>
> > > Cc: Kyle Tso <kyletso@google.com>
> > > Signed-off-by: Badhri Jagan Sridharan <badhri@google.com>
> > > Signed-off-by: Will McVicker <willmcvicker@google.com>
> > > Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> > > ---
> > >  drivers/usb/typec/tcpm/tcpm.c | 16 +++-------------
> > >  1 file changed, 3 insertions(+), 13 deletions(-)
> > >
> > > diff --git a/drivers/usb/typec/tcpm/tcpm.c b/drivers/usb/typec/tcpm/tcpm.c
> > > index cedc6cf82d61..0ceeab50ed64 100644
> > > --- a/drivers/usb/typec/tcpm/tcpm.c
> > > +++ b/drivers/usb/typec/tcpm/tcpm.c
> > > @@ -470,12 +470,6 @@ static bool tcpm_port_is_disconnected(struct tcpm_port *port)
> > >
> > >  #ifdef CONFIG_DEBUG_FS
> > >
> > > -static bool tcpm_log_full(struct tcpm_port *port)
> > > -{
> > > -     return port->logbuffer_tail ==
> > > -             (port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
> > > -}
> > > -
> > >  __printf(2, 0)
> > >  static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
> > >  {
> > > @@ -495,11 +489,6 @@ static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
> > >
> > >       vsnprintf(tmpbuffer, sizeof(tmpbuffer), fmt, args);
> > >
> > > -     if (tcpm_log_full(port)) {
> > > -             port->logbuffer_head = max(port->logbuffer_head - 1, 0);
> > > -             strcpy(tmpbuffer, "overflow");
> > > -     }
> > > -
> > >       if (port->logbuffer_head < 0 ||
> > >           port->logbuffer_head >= LOG_BUFFER_ENTRIES) {
> > >               dev_warn(port->dev,
> > > @@ -519,6 +508,9 @@ static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
> > >                 (unsigned long)ts_nsec, rem_nsec / 1000,
> > >                 tmpbuffer);
> > >       port->logbuffer_head = (port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
> > > +     if (port->logbuffer_head == port->logbuffer_tail)
> > > +             port->logbuffer_tail =
> > > +                     (port->logbuffer_tail + 1) % LOG_BUFFER_ENTRIES;
> > >
> > >  abort:
> > >       mutex_unlock(&port->logbuffer_lock);
> > > @@ -622,8 +614,6 @@ static int tcpm_debug_show(struct seq_file *s, void *v)
> > >               seq_printf(s, "%s\n", port->logbuffer[tail]);
> > >               tail = (tail + 1) % LOG_BUFFER_ENTRIES;
> > >       }
> > > -     if (!seq_has_overflowed(s))
> > > -             port->logbuffer_tail = tail;
> > >       mutex_unlock(&port->logbuffer_lock);
> > >
> > >       return 0;
> > > --
> > > 2.29.2
> > >
diff mbox series

Patch

diff --git a/drivers/usb/typec/tcpm/tcpm.c b/drivers/usb/typec/tcpm/tcpm.c
index cedc6cf82d61..0ceeab50ed64 100644
--- a/drivers/usb/typec/tcpm/tcpm.c
+++ b/drivers/usb/typec/tcpm/tcpm.c
@@ -470,12 +470,6 @@  static bool tcpm_port_is_disconnected(struct tcpm_port *port)
 
 #ifdef CONFIG_DEBUG_FS
 
-static bool tcpm_log_full(struct tcpm_port *port)
-{
-	return port->logbuffer_tail ==
-		(port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
-}
-
 __printf(2, 0)
 static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
 {
@@ -495,11 +489,6 @@  static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
 
 	vsnprintf(tmpbuffer, sizeof(tmpbuffer), fmt, args);
 
-	if (tcpm_log_full(port)) {
-		port->logbuffer_head = max(port->logbuffer_head - 1, 0);
-		strcpy(tmpbuffer, "overflow");
-	}
-
 	if (port->logbuffer_head < 0 ||
 	    port->logbuffer_head >= LOG_BUFFER_ENTRIES) {
 		dev_warn(port->dev,
@@ -519,6 +508,9 @@  static void _tcpm_log(struct tcpm_port *port, const char *fmt, va_list args)
 		  (unsigned long)ts_nsec, rem_nsec / 1000,
 		  tmpbuffer);
 	port->logbuffer_head = (port->logbuffer_head + 1) % LOG_BUFFER_ENTRIES;
+	if (port->logbuffer_head == port->logbuffer_tail)
+		port->logbuffer_tail =
+			(port->logbuffer_tail + 1) % LOG_BUFFER_ENTRIES;
 
 abort:
 	mutex_unlock(&port->logbuffer_lock);
@@ -622,8 +614,6 @@  static int tcpm_debug_show(struct seq_file *s, void *v)
 		seq_printf(s, "%s\n", port->logbuffer[tail]);
 		tail = (tail + 1) % LOG_BUFFER_ENTRIES;
 	}
-	if (!seq_has_overflowed(s))
-		port->logbuffer_tail = tail;
 	mutex_unlock(&port->logbuffer_lock);
 
 	return 0;