[RFC net-next] net: don't dump stack on queue timeout

[RFC net-next] net: don't dump stack on queue timeout

[Jakub Kicinski]

The top syzbot report for networking (#14 for the entire kernel)
is the queue timeout splat. We kept it around for a long time,
because in real life it provides pretty strong signal that
something is wrong with the driver or the device.

Removing it is also likely to break monitoring for those who
track it as a kernel warning.

Nevertheless, WARN()ings are best suited for catching kernel
programming bugs. If a Tx queue gets starved due to a pause
storm, priority configuration, or other weirdness - that's
obviously a problem, but not a problem we can fix at
the kernel level.

Bite the bullet and convert the WARN() to a print.

Before:

  NETDEV WATCHDOG: eni1np1 (netdevsim): transmit queue 0 timed out 1975 ms
  WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:525 dev_watchdog+0x39e/0x3b0
  [... completely pointless stack trace of a timer follows ...]

Now:

  netdevsim netdevsim1 eni1np1: NETDEV WATCHDOG: CPU: 0: transmit queue 0 timed out 1769 ms

Alternatively we could mark the drivers which syzbot has
learned to abuse as "print-instead-of-WARN" selectively.

Reported-by: syzbot+d55372214aff0faa1f1f@syzkaller.appspotmail.com
Signed-off-by: Jakub Kicinski <kuba@kernel.org>
---
CC: jhs@mojatatu.com
CC: xiyou.wangcong@gmail.com
CC: jiri@resnulli.us
---
 net/sched/sch_generic.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/net/sched/sch_generic.c b/net/sched/sch_generic.c
index 4195a4bc26ca..8dd0e5925342 100644
--- a/net/sched/sch_generic.c
+++ b/net/sched/sch_generic.c
@@ -522,8 +522,9 @@ static void dev_watchdog(struct timer_list *t)
 
 			if (unlikely(timedout_ms)) {
 				trace_net_dev_xmit_timeout(dev, i);
-				WARN_ONCE(1, "NETDEV WATCHDOG: %s (%s): transmit queue %u timed out %u ms\n",
-					  dev->name, netdev_drivername(dev), i, timedout_ms);
+				netdev_crit(dev, "NETDEV WATCHDOG: CPU: %d: transmit queue %u timed out %u ms\n",
+					    raw_smp_processor_id(),
+					    i, timedout_ms);
 				netif_freeze_queues(dev);
 				dev->netdev_ops->ndo_tx_timeout(dev, i);
 				netif_unfreeze_queues(dev);
-- 
2.41.0

Re: [RFC net-next] net: don't dump stack on queue timeout

[Daniele Palmas]

Hello Jakub,

Il giorno gio 9 nov 2023 alle ore 01:09 Jakub Kicinski
<kuba@kernel.org> ha scritto:
>
> The top syzbot report for networking (#14 for the entire kernel)
> is the queue timeout splat. We kept it around for a long time,
> because in real life it provides pretty strong signal that
> something is wrong with the driver or the device.
>
> Removing it is also likely to break monitoring for those who
> track it as a kernel warning.
>
> Nevertheless, WARN()ings are best suited for catching kernel
> programming bugs. If a Tx queue gets starved due to a pause
> storm, priority configuration, or other weirdness - that's
> obviously a problem, but not a problem we can fix at
> the kernel level.
>
> Bite the bullet and convert the WARN() to a print.
>

I can't comment on other scenarios, but at least for mobile broadband
I think this could be a useful change.

For example, I can see the splat with MBIM modems when radio link
failure happens, something for which the host can't really do
anything. So, the main result of using WARN is to scare the users who
are not aware of the reasons behind it and create unneeded support
requests...

Thanks,
Daniele

Re: [RFC net-next] net: don't dump stack on queue timeout

[Jakub Kicinski]

On Thu, 9 Nov 2023 08:40:00 +0100 Daniele Palmas wrote:
> For example, I can see the splat with MBIM modems when radio link
> failure happens, something for which the host can't really do
> anything. So, the main result of using WARN is to scare the users who
> are not aware of the reasons behind it and create unneeded support
> requests...

Is it not possible to clear the carrier on downstream devices?
Radio link failure sounds like carrier loss.

Re: [RFC net-next] net: don't dump stack on queue timeout

[Daniele Palmas]

Il giorno gio 9 nov 2023 alle ore 16:18 Jakub Kicinski
<kuba@kernel.org> ha scritto:
>
> On Thu, 9 Nov 2023 08:40:00 +0100 Daniele Palmas wrote:
> > For example, I can see the splat with MBIM modems when radio link
> > failure happens, something for which the host can't really do
> > anything. So, the main result of using WARN is to scare the users who
> > are not aware of the reasons behind it and create unneeded support
> > requests...
>
> Is it not possible to clear the carrier on downstream devices?
> Radio link failure sounds like carrier loss.

The problem is that the MBIM standard does not define the
CDC_NOTIFY_NETWORK_CONNECTION, so carrier loss detection is managed
through the indications on the control channel.

But the kernel is not aware of what's passing through the control
channel, so it's the userspace tool that should detect carrier loss,
disconnect the bearers and set the network interface down.

For example, ModemManager is capable of doing that, but the problem is
that usually the standard modem notifications on the control channel
arrive later than the splat: increasing watchdog_timeo does not seem
to me a good option, since the notification could arrive much later.

One possible solution is to have some proprietary notifications on the
control channel that detect RLF early and trigger the above described
process before the warn happens: by coincidence, I wrote a custom
ModemManager patch for this a few days ago
https://gitlab.freedesktop.org/dnlplm/ModemManager/-/commit/89ba8ab65d4bfbd4cf1ff11ed58c08b112aca80f

Regards,
Daniele

Re: [RFC net-next] net: don't dump stack on queue timeout

[Jakub Kicinski]

On Fri, 10 Nov 2023 09:01:29 +0100 Daniele Palmas wrote:
> The problem is that the MBIM standard does not define the
> CDC_NOTIFY_NETWORK_CONNECTION, so carrier loss detection is managed
> through the indications on the control channel.
> 
> But the kernel is not aware of what's passing through the control
> channel, so it's the userspace tool that should detect carrier loss,
> disconnect the bearers and set the network interface down.
> 
> For example, ModemManager is capable of doing that, but the problem is
> that usually the standard modem notifications on the control channel
> arrive later than the splat: increasing watchdog_timeo does not seem
> to me a good option, since the notification could arrive much later.
> 
> One possible solution is to have some proprietary notifications on the
> control channel that detect RLF early and trigger the above described
> process before the warn happens: by coincidence, I wrote a custom
> ModemManager patch for this a few days ago
> https://gitlab.freedesktop.org/dnlplm/ModemManager/-/commit/89ba8ab65d4bfbd4cf1ff11ed58c08b112aca80f

I see, thanks for the extra info!

Re: [RFC net-next] net: don't dump stack on queue timeout

[Jiri Pirko]

Thu, Nov 09, 2023 at 01:09:01AM CET, kuba@kernel.org wrote:
>The top syzbot report for networking (#14 for the entire kernel)
>is the queue timeout splat. We kept it around for a long time,
>because in real life it provides pretty strong signal that
>something is wrong with the driver or the device.
>
>Removing it is also likely to break monitoring for those who
>track it as a kernel warning.
>
>Nevertheless, WARN()ings are best suited for catching kernel
>programming bugs. If a Tx queue gets starved due to a pause
>storm, priority configuration, or other weirdness - that's
>obviously a problem, but not a problem we can fix at
>the kernel level.
>
>Bite the bullet and convert the WARN() to a print.
>
>Before:
>
>  NETDEV WATCHDOG: eni1np1 (netdevsim): transmit queue 0 timed out 1975 ms
>  WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:525 dev_watchdog+0x39e/0x3b0
>  [... completely pointless stack trace of a timer follows ...]
>
>Now:
>
>  netdevsim netdevsim1 eni1np1: NETDEV WATCHDOG: CPU: 0: transmit queue 0 timed out 1769 ms
>
>Alternatively we could mark the drivers which syzbot has
>learned to abuse as "print-instead-of-WARN" selectively.
>
>Reported-by: syzbot+d55372214aff0faa1f1f@syzkaller.appspotmail.com
>Signed-off-by: Jakub Kicinski <kuba@kernel.org>

Makes sense.

Reviewed-by: Jiri Pirko <jiri@nvidia.com>

Re: [RFC net-next] net: don't dump stack on queue timeout

[Eric Dumazet]

On Thu, Nov 9, 2023 at 1:09 AM Jakub Kicinski <kuba@kernel.org> wrote:
>
> The top syzbot report for networking (#14 for the entire kernel)
> is the queue timeout splat. We kept it around for a long time,
> because in real life it provides pretty strong signal that
> something is wrong with the driver or the device.
>
> Removing it is also likely to break monitoring for those who
> track it as a kernel warning.
>
> Nevertheless, WARN()ings are best suited for catching kernel
> programming bugs. If a Tx queue gets starved due to a pause
> storm, priority configuration, or other weirdness - that's
> obviously a problem, but not a problem we can fix at
> the kernel level.
>
> Bite the bullet and convert the WARN() to a print.
>
> Before:
>
>   NETDEV WATCHDOG: eni1np1 (netdevsim): transmit queue 0 timed out 1975 ms
>   WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:525 dev_watchdog+0x39e/0x3b0
>   [... completely pointless stack trace of a timer follows ...]
>
> Now:
>
>   netdevsim netdevsim1 eni1np1: NETDEV WATCHDOG: CPU: 0: transmit queue 0 timed out 1769 ms
>
> Alternatively we could mark the drivers which syzbot has
> learned to abuse as "print-instead-of-WARN" selectively.
>
> Reported-by: syzbot+d55372214aff0faa1f1f@syzkaller.appspotmail.com
> Signed-off-by: Jakub Kicinski <kuba@kernel.org>

SGTM !
Reviewed-by: Eric Dumazet <edumazet@google.com>

Re: [RFC net-next] net: don't dump stack on queue timeout

[Jamal Hadi Salim]

On Wed, Nov 8, 2023 at 7:09 PM Jakub Kicinski <kuba@kernel.org> wrote:
>
> The top syzbot report for networking (#14 for the entire kernel)
> is the queue timeout splat. We kept it around for a long time,
> because in real life it provides pretty strong signal that
> something is wrong with the driver or the device.
>
> Removing it is also likely to break monitoring for those who
> track it as a kernel warning.
>
> Nevertheless, WARN()ings are best suited for catching kernel
> programming bugs. If a Tx queue gets starved due to a pause
> storm, priority configuration, or other weirdness - that's
> obviously a problem, but not a problem we can fix at
> the kernel level.
>
> Bite the bullet and convert the WARN() to a print.
>
> Before:
>
>   NETDEV WATCHDOG: eni1np1 (netdevsim): transmit queue 0 timed out 1975 ms
>   WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:525 dev_watchdog+0x39e/0x3b0
>   [... completely pointless stack trace of a timer follows ...]
>
> Now:
>
>   netdevsim netdevsim1 eni1np1: NETDEV WATCHDOG: CPU: 0: transmit queue 0 timed out 1769 ms
>
> Alternatively we could mark the drivers which syzbot has
> learned to abuse as "print-instead-of-WARN" selectively.
>
> Reported-by: syzbot+d55372214aff0faa1f1f@syzkaller.appspotmail.com
> Signed-off-by: Jakub Kicinski <kuba@kernel.org>

Reviewed-by: Jamal Hadi Salim <jhs@mojatatu.com>

cheers,
jamal

> ---
> CC: jhs@mojatatu.com
> CC: xiyou.wangcong@gmail.com
> CC: jiri@resnulli.us
> ---
>  net/sched/sch_generic.c | 5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
>
> diff --git a/net/sched/sch_generic.c b/net/sched/sch_generic.c
> index 4195a4bc26ca..8dd0e5925342 100644
> --- a/net/sched/sch_generic.c
> +++ b/net/sched/sch_generic.c
> @@ -522,8 +522,9 @@ static void dev_watchdog(struct timer_list *t)
>
>                         if (unlikely(timedout_ms)) {
>                                 trace_net_dev_xmit_timeout(dev, i);
> -                               WARN_ONCE(1, "NETDEV WATCHDOG: %s (%s): transmit queue %u timed out %u ms\n",
> -                                         dev->name, netdev_drivername(dev), i, timedout_ms);
> +                               netdev_crit(dev, "NETDEV WATCHDOG: CPU: %d: transmit queue %u timed out %u ms\n",
> +                                           raw_smp_processor_id(),
> +                                           i, timedout_ms);
>                                 netif_freeze_queues(dev);
>                                 dev->netdev_ops->ndo_tx_timeout(dev, i);
>                                 netif_unfreeze_queues(dev);
> --
> 2.41.0
>