I'm seeing a system get stuck unable to bring a downed interface back up
when it's got an updelay value set, behavior which ceased when logging
spew was removed from bond_miimon_inspect(). I'm monitoring logs on this
system over another network connection, and it seems that the act of
spewing logs at all there increases rtnl lock contention, because
instrumented code showed bond_mii_monitor() never able to succeed in it's
attempts to call rtnl_trylock() to actually commit link state changes,
leaving the downed link stuck in BOND_LINK_DOWN. The system in question
appears to be fine with the log spew being moved to
bond_commit_link_state(), which is called after the successful
rtnl_trylock(). I'm actually wondering if perhaps we ultimately need/want
some bond-specific lock here to prevent racing with bond_close() instead
of using rtnl, but this shift of the output appears to work. I believe
this started happening when de77ecd4ef02 ("bonding: improve link-status
update in mii-monitoring") went in, but I'm not 100% on that.
The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat
separate from the fix for the actual hang, but it eliminates a constant
"invalid new link 3 on slave" message seen related to this issue, and it's
not actually an invalid state here, so we shouldn't be reporting it as an
error.
CC: Mahesh Bandewar <[email protected]>
CC: Jay Vosburgh <[email protected]>
CC: Veaceslav Falico <[email protected]>
CC: Andy Gospodarek <[email protected]>
CC: "David S. Miller" <[email protected]>
CC: Jakub Kicinski <[email protected]>
CC: Thomas Davis <[email protected]>
CC: [email protected]
Signed-off-by: Jarod Wilson <[email protected]>
---
drivers/net/bonding/bond_main.c | 26 ++++++----------------
include/net/bonding.h | 38 +++++++++++++++++++++++++++++++++
2 files changed, 44 insertions(+), 20 deletions(-)
diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
index 47afc5938c26..cdb6c64f16b6 100644
--- a/drivers/net/bonding/bond_main.c
+++ b/drivers/net/bonding/bond_main.c
@@ -2292,23 +2292,13 @@ static int bond_miimon_inspect(struct bonding *bond)
bond_propose_link_state(slave, BOND_LINK_FAIL);
commit++;
slave->delay = bond->params.downdelay;
- if (slave->delay) {
- slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n",
- (BOND_MODE(bond) ==
- BOND_MODE_ACTIVEBACKUP) ?
- (bond_is_active_slave(slave) ?
- "active " : "backup ") : "",
- bond->params.downdelay * bond->params.miimon);
- }
+
fallthrough;
case BOND_LINK_FAIL:
if (link_state) {
/* recovered before downdelay expired */
bond_propose_link_state(slave, BOND_LINK_UP);
slave->last_link_up = jiffies;
- slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
- (bond->params.downdelay - slave->delay) *
- bond->params.miimon);
commit++;
continue;
}
@@ -2330,19 +2320,10 @@ static int bond_miimon_inspect(struct bonding *bond)
commit++;
slave->delay = bond->params.updelay;
- if (slave->delay) {
- slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n",
- ignore_updelay ? 0 :
- bond->params.updelay *
- bond->params.miimon);
- }
fallthrough;
case BOND_LINK_BACK:
if (!link_state) {
bond_propose_link_state(slave, BOND_LINK_DOWN);
- slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
- (bond->params.updelay - slave->delay) *
- bond->params.miimon);
commit++;
continue;
}
@@ -2456,6 +2437,11 @@ static void bond_miimon_commit(struct bonding *bond)
continue;
+ case BOND_LINK_BACK:
+ bond_propose_link_state(slave, BOND_LINK_NOCHANGE);
+
+ continue;
+
default:
slave_err(bond->dev, slave->dev, "invalid new link %d on slave\n",
slave->link_new_state);
diff --git a/include/net/bonding.h b/include/net/bonding.h
index adc3da776970..6a09de9a3f03 100644
--- a/include/net/bonding.h
+++ b/include/net/bonding.h
@@ -558,10 +558,48 @@ static inline void bond_propose_link_state(struct slave *slave, int state)
static inline void bond_commit_link_state(struct slave *slave, bool notify)
{
+ struct bonding *bond = slave->bond;
+
if (slave->link_new_state == BOND_LINK_NOCHANGE)
return;
+ if (slave->link == slave->link_new_state)
+ return;
+
slave->link = slave->link_new_state;
+
+ switch(slave->link) {
+ case BOND_LINK_UP:
+ slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
+ (bond->params.downdelay - slave->delay) *
+ bond->params.miimon);
+ break;
+
+ case BOND_LINK_FAIL:
+ if (slave->delay) {
+ slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n",
+ (BOND_MODE(bond) ==
+ BOND_MODE_ACTIVEBACKUP) ?
+ (bond_is_active_slave(slave) ?
+ "active " : "backup ") : "",
+ bond->params.downdelay * bond->params.miimon);
+ }
+ break;
+
+ case BOND_LINK_DOWN:
+ slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
+ (bond->params.updelay - slave->delay) *
+ bond->params.miimon);
+ break;
+
+ case BOND_LINK_BACK:
+ if (slave->delay) {
+ slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n",
+ bond->params.updelay * bond->params.miimon);
+ }
+ break;
+ }
+
if (notify) {
bond_queue_slave_event(slave);
bond_lower_state_changed(slave);
--
2.28.0
On Sat, 5 Dec 2020 18:43:54 -0500 Jarod Wilson wrote:
> I'm seeing a system get stuck unable to bring a downed interface back up
> when it's got an updelay value set, behavior which ceased when logging
> spew was removed from bond_miimon_inspect(). I'm monitoring logs on this
> system over another network connection, and it seems that the act of
> spewing logs at all there increases rtnl lock contention, because
> instrumented code showed bond_mii_monitor() never able to succeed in it's
> attempts to call rtnl_trylock() to actually commit link state changes,
> leaving the downed link stuck in BOND_LINK_DOWN. The system in question
> appears to be fine with the log spew being moved to
> bond_commit_link_state(), which is called after the successful
> rtnl_trylock().
But it's not called under rtnl_lock AFAICT. So something else is also
spewing messages?
While bond_commit_link_state() _is_ called under the lock. So you're
increasing the retry rate, by putting the slow operation under the
lock, is that right?
Also isn't bond_commit_link_state() called from many more places?
So we're adding new prints, effectively?
> I'm actually wondering if perhaps we ultimately need/want
> some bond-specific lock here to prevent racing with bond_close() instead
> of using rtnl, but this shift of the output appears to work. I believe
> this started happening when de77ecd4ef02 ("bonding: improve link-status
> update in mii-monitoring") went in, but I'm not 100% on that.
>
> The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat
> separate from the fix for the actual hang, but it eliminates a constant
> "invalid new link 3 on slave" message seen related to this issue, and it's
> not actually an invalid state here, so we shouldn't be reporting it as an
> error.
Let's make it a separate patch, then.
Jarod Wilson <[email protected]> wrote:
>I'm seeing a system get stuck unable to bring a downed interface back up
>when it's got an updelay value set, behavior which ceased when logging
>spew was removed from bond_miimon_inspect(). I'm monitoring logs on this
>system over another network connection, and it seems that the act of
>spewing logs at all there increases rtnl lock contention, because
>instrumented code showed bond_mii_monitor() never able to succeed in it's
>attempts to call rtnl_trylock() to actually commit link state changes,
>leaving the downed link stuck in BOND_LINK_DOWN. The system in question
>appears to be fine with the log spew being moved to
>bond_commit_link_state(), which is called after the successful
>rtnl_trylock(). I'm actually wondering if perhaps we ultimately need/want
>some bond-specific lock here to prevent racing with bond_close() instead
>of using rtnl, but this shift of the output appears to work. I believe
>this started happening when de77ecd4ef02 ("bonding: improve link-status
>update in mii-monitoring") went in, but I'm not 100% on that.
We use RTNL not to avoid deadlock with bonding itself, but
because the "commit" side undertakes actions which require RTNL, e.g.,
various events will eventually call netdev_lower_state_changed.
However, the RTNL acquisition is a trylock to avoid the deadlock
with bond_close. Moving that out of line here (e.g., putting the commit
into another work queue event or the like) has the same problem, in that
bond_close needs to wait for all of the work queue events to finish, and
it holds RTNL.
Also, a dim memory says that the various notification messages
were mostly placed in the "inspect" phase and not the "commit" phase to
avoid doing printk-like activities with RTNL held. As a general
principle, I don't think we want to add more verbiage under RTNL.
>The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat
>separate from the fix for the actual hang, but it eliminates a constant
>"invalid new link 3 on slave" message seen related to this issue, and it's
>not actually an invalid state here, so we shouldn't be reporting it as an
>error.
Do you mean bond_miimon_commit here and not bond_miimon_inspect
(which already has a case for BOND_LINK_BACK)?
In principle, bond_miimon_commit should not see _BACK or _FAIL
state as a new link state, because those states should be managed at the
bond_miimon_inspect level (as they are the result of updelay and
downdelay). These states should not be "committed" in the sense of
causing notifications or doing actions that require RTNL.
My recollection is that the "invalid new link" messages were the
result of a bug in de77ecd4ef02, which was fixed in 1899bb325149
("bonding: fix state transition issue in link monitoring"), but maybe
the RTNL problem here induces that in some other fashion.
Either way, I believe this message is correct as-is.
-J
>CC: Mahesh Bandewar <[email protected]>
>CC: Jay Vosburgh <[email protected]>
>CC: Veaceslav Falico <[email protected]>
>CC: Andy Gospodarek <[email protected]>
>CC: "David S. Miller" <[email protected]>
>CC: Jakub Kicinski <[email protected]>
>CC: Thomas Davis <[email protected]>
>CC: [email protected]
>Signed-off-by: Jarod Wilson <[email protected]>
>---
> drivers/net/bonding/bond_main.c | 26 ++++++----------------
> include/net/bonding.h | 38 +++++++++++++++++++++++++++++++++
> 2 files changed, 44 insertions(+), 20 deletions(-)
>
>diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
>index 47afc5938c26..cdb6c64f16b6 100644
>--- a/drivers/net/bonding/bond_main.c
>+++ b/drivers/net/bonding/bond_main.c
>@@ -2292,23 +2292,13 @@ static int bond_miimon_inspect(struct bonding *bond)
> bond_propose_link_state(slave, BOND_LINK_FAIL);
> commit++;
> slave->delay = bond->params.downdelay;
>- if (slave->delay) {
>- slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n",
>- (BOND_MODE(bond) ==
>- BOND_MODE_ACTIVEBACKUP) ?
>- (bond_is_active_slave(slave) ?
>- "active " : "backup ") : "",
>- bond->params.downdelay * bond->params.miimon);
>- }
>+
> fallthrough;
> case BOND_LINK_FAIL:
> if (link_state) {
> /* recovered before downdelay expired */
> bond_propose_link_state(slave, BOND_LINK_UP);
> slave->last_link_up = jiffies;
>- slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
>- (bond->params.downdelay - slave->delay) *
>- bond->params.miimon);
> commit++;
> continue;
> }
>@@ -2330,19 +2320,10 @@ static int bond_miimon_inspect(struct bonding *bond)
> commit++;
> slave->delay = bond->params.updelay;
>
>- if (slave->delay) {
>- slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n",
>- ignore_updelay ? 0 :
>- bond->params.updelay *
>- bond->params.miimon);
>- }
> fallthrough;
> case BOND_LINK_BACK:
> if (!link_state) {
> bond_propose_link_state(slave, BOND_LINK_DOWN);
>- slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
>- (bond->params.updelay - slave->delay) *
>- bond->params.miimon);
> commit++;
> continue;
> }
>@@ -2456,6 +2437,11 @@ static void bond_miimon_commit(struct bonding *bond)
>
> continue;
>
>+ case BOND_LINK_BACK:
>+ bond_propose_link_state(slave, BOND_LINK_NOCHANGE);
>+
>+ continue;
>+
> default:
> slave_err(bond->dev, slave->dev, "invalid new link %d on slave\n",
> slave->link_new_state);
>diff --git a/include/net/bonding.h b/include/net/bonding.h
>index adc3da776970..6a09de9a3f03 100644
>--- a/include/net/bonding.h
>+++ b/include/net/bonding.h
>@@ -558,10 +558,48 @@ static inline void bond_propose_link_state(struct slave *slave, int state)
>
> static inline void bond_commit_link_state(struct slave *slave, bool notify)
> {
>+ struct bonding *bond = slave->bond;
>+
> if (slave->link_new_state == BOND_LINK_NOCHANGE)
> return;
>
>+ if (slave->link == slave->link_new_state)
>+ return;
>+
> slave->link = slave->link_new_state;
>+
>+ switch(slave->link) {
>+ case BOND_LINK_UP:
>+ slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
>+ (bond->params.downdelay - slave->delay) *
>+ bond->params.miimon);
>+ break;
>+
>+ case BOND_LINK_FAIL:
>+ if (slave->delay) {
>+ slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n",
>+ (BOND_MODE(bond) ==
>+ BOND_MODE_ACTIVEBACKUP) ?
>+ (bond_is_active_slave(slave) ?
>+ "active " : "backup ") : "",
>+ bond->params.downdelay * bond->params.miimon);
>+ }
>+ break;
>+
>+ case BOND_LINK_DOWN:
>+ slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
>+ (bond->params.updelay - slave->delay) *
>+ bond->params.miimon);
>+ break;
>+
>+ case BOND_LINK_BACK:
>+ if (slave->delay) {
>+ slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n",
>+ bond->params.updelay * bond->params.miimon);
>+ }
>+ break;
>+ }
>+
> if (notify) {
> bond_queue_slave_event(slave);
> bond_lower_state_changed(slave);
>--
>2.28.0
>
---
-Jay Vosburgh, [email protected]
On Tue, Dec 8, 2020 at 3:35 PM Jay Vosburgh <[email protected]> wrote:
>
> Jarod Wilson <[email protected]> wrote:
>
> >I'm seeing a system get stuck unable to bring a downed interface back up
> >when it's got an updelay value set, behavior which ceased when logging
> >spew was removed from bond_miimon_inspect(). I'm monitoring logs on this
> >system over another network connection, and it seems that the act of
> >spewing logs at all there increases rtnl lock contention, because
> >instrumented code showed bond_mii_monitor() never able to succeed in it's
> >attempts to call rtnl_trylock() to actually commit link state changes,
> >leaving the downed link stuck in BOND_LINK_DOWN. The system in question
> >appears to be fine with the log spew being moved to
> >bond_commit_link_state(), which is called after the successful
> >rtnl_trylock(). I'm actually wondering if perhaps we ultimately need/want
> >some bond-specific lock here to prevent racing with bond_close() instead
> >of using rtnl, but this shift of the output appears to work. I believe
> >this started happening when de77ecd4ef02 ("bonding: improve link-status
> >update in mii-monitoring") went in, but I'm not 100% on that.
>
> We use RTNL not to avoid deadlock with bonding itself, but
> because the "commit" side undertakes actions which require RTNL, e.g.,
> various events will eventually call netdev_lower_state_changed.
>
> However, the RTNL acquisition is a trylock to avoid the deadlock
> with bond_close. Moving that out of line here (e.g., putting the commit
> into another work queue event or the like) has the same problem, in that
> bond_close needs to wait for all of the work queue events to finish, and
> it holds RTNL.
Ah, okay, it wasn't clear to me that we actually do need RTNL here,
I'd thought it was just for the deadlock avoidance with bond_close,
based on the comments in the source.
> Also, a dim memory says that the various notification messages
> were mostly placed in the "inspect" phase and not the "commit" phase to
> avoid doing printk-like activities with RTNL held. As a general
> principle, I don't think we want to add more verbiage under RTNL.
Yeah, that's fair.
> >The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat
> >separate from the fix for the actual hang, but it eliminates a constant
> >"invalid new link 3 on slave" message seen related to this issue, and it's
> >not actually an invalid state here, so we shouldn't be reporting it as an
> >error.
>
> Do you mean bond_miimon_commit here and not bond_miimon_inspect
> (which already has a case for BOND_LINK_BACK)?
Whoops, yes.
> In principle, bond_miimon_commit should not see _BACK or _FAIL
> state as a new link state, because those states should be managed at the
> bond_miimon_inspect level (as they are the result of updelay and
> downdelay). These states should not be "committed" in the sense of
> causing notifications or doing actions that require RTNL.
>
> My recollection is that the "invalid new link" messages were the
> result of a bug in de77ecd4ef02, which was fixed in 1899bb325149
> ("bonding: fix state transition issue in link monitoring"), but maybe
> the RTNL problem here induces that in some other fashion.
>
> Either way, I believe this message is correct as-is.
Hm, okay, definitely seeing this message pop up regularly when a link
recovers, using a fairly simple reproducer:
slave1=p6p1
slave2=p6p2
modprobe -rv bonding
modprobe -v bonding mode=2 miimon=100 updelay=200
ip link set bond0 up
ifenslave bond0 $slave1 $slave2
sleep 10
while :
do
ip link set $slave1 down
sleep 1
ip link set $slave1 up
sleep 1
done
I wasn't actually seeing the problem until I was running a 'watch -n 1
"dmesg | tail -n 50"' or similar in a remote ssh session on the host.
I should add the caveat that this was also initially seen on an older
kernel, but with a fairly up-to-date bonding driver, which does
include both de77ecd4ef02 and 1899bb325149. I'm going to keep prodding
w/a more recent upstreamier kernel, and see if I can get a better idea
of what's actually going on.
--
Jarod Wilson
[email protected]
On Tue, Dec 8, 2020 at 2:38 PM Jakub Kicinski <[email protected]> wrote:
>
> On Sat, 5 Dec 2020 18:43:54 -0500 Jarod Wilson wrote:
> > I'm seeing a system get stuck unable to bring a downed interface back up
> > when it's got an updelay value set, behavior which ceased when logging
> > spew was removed from bond_miimon_inspect(). I'm monitoring logs on this
> > system over another network connection, and it seems that the act of
> > spewing logs at all there increases rtnl lock contention, because
> > instrumented code showed bond_mii_monitor() never able to succeed in it's
> > attempts to call rtnl_trylock() to actually commit link state changes,
> > leaving the downed link stuck in BOND_LINK_DOWN. The system in question
> > appears to be fine with the log spew being moved to
> > bond_commit_link_state(), which is called after the successful
> > rtnl_trylock().
>
> But it's not called under rtnl_lock AFAICT. So something else is also
> spewing messages?
>
> While bond_commit_link_state() _is_ called under the lock. So you're
> increasing the retry rate, by putting the slow operation under the
> lock, is that right?
Partially, yes. I probably should have tagged this with RFC instead of
PATCH, tbh. My theory was that the log spew, being sent out *other*
network interfaces when monitoring the system or remote syslog or ssh
was potentially causing some rtnl_lock() calls, so not spewing until
after actually being able to grab the lock would lessen the problem
w/actually acquiring the lock, but I ... don't know offhand how to
verify that theory.
> Also isn't bond_commit_link_state() called from many more places?
> So we're adding new prints, effectively?
Ah. Crap. Yes. bond_set_slave_link_state() is called quite a few
places, and that in turn calls bond_commit_link_state().
> > I'm actually wondering if perhaps we ultimately need/want
> > some bond-specific lock here to prevent racing with bond_close() instead
> > of using rtnl, but this shift of the output appears to work. I believe
> > this started happening when de77ecd4ef02 ("bonding: improve link-status
> > update in mii-monitoring") went in, but I'm not 100% on that.
> >
> > The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat
> > separate from the fix for the actual hang, but it eliminates a constant
> > "invalid new link 3 on slave" message seen related to this issue, and it's
> > not actually an invalid state here, so we shouldn't be reporting it as an
> > error.
>
> Let's make it a separate patch, then.
Sounds like Jay is confident that bit is valid, and I shouldn't be
ending up in that state, unless something else is going wrong.
--
Jarod Wilson
[email protected]
On Tue, Dec 8, 2020 at 3:35 PM Jay Vosburgh <[email protected]> wrote:
>
> Jarod Wilson <[email protected]> wrote:
...
> >The addition of a case BOND_LINK_BACK in bond_miimon_commit() is somewhat
> >separate from the fix for the actual hang, but it eliminates a constant
> >"invalid new link 3 on slave" message seen related to this issue, and it's
> >not actually an invalid state here, so we shouldn't be reporting it as an
> >error.
...
> In principle, bond_miimon_commit should not see _BACK or _FAIL
> state as a new link state, because those states should be managed at the
> bond_miimon_inspect level (as they are the result of updelay and
> downdelay). These states should not be "committed" in the sense of
> causing notifications or doing actions that require RTNL.
>
> My recollection is that the "invalid new link" messages were the
> result of a bug in de77ecd4ef02, which was fixed in 1899bb325149
> ("bonding: fix state transition issue in link monitoring"), but maybe
> the RTNL problem here induces that in some other fashion.
>
> Either way, I believe this message is correct as-is.
For reference, with 5.10.1 and this script:
#!/bin/sh
slave1=ens4f0
slave2=ens4f1
modprobe -rv bonding
modprobe -v bonding mode=2 miimon=100 updelay=200
ip link set bond0 up
ifenslave bond0 $slave1 $slave2
sleep 5
while :
do
ip link set $slave1 down
sleep 1
ip link set $slave1 up
sleep 1
done
I get this repeating log output:
[ 9488.262291] sfc 0000:05:00.0 ens4f0: link up at 10000Mbps
full-duplex (MTU 1500)
[ 9488.339508] bond0: (slave ens4f0): link status up, enabling it in 200 ms
[ 9488.339511] bond0: (slave ens4f0): invalid new link 3 on slave
[ 9488.547643] bond0: (slave ens4f0): link status definitely up, 10000
Mbps full duplex
[ 9489.276614] bond0: (slave ens4f0): link status definitely down,
disabling slave
[ 9490.273830] sfc 0000:05:00.0 ens4f0: link up at 10000Mbps
full-duplex (MTU 1500)
[ 9490.315540] bond0: (slave ens4f0): link status up, enabling it in 200 ms
[ 9490.315543] bond0: (slave ens4f0): invalid new link 3 on slave
[ 9490.523641] bond0: (slave ens4f0): link status definitely up, 10000
Mbps full duplex
[ 9491.356526] bond0: (slave ens4f0): link status definitely down,
disabling slave
[ 9492.285249] sfc 0000:05:00.0 ens4f0: link up at 10000Mbps
full-duplex (MTU 1500)
[ 9492.291522] bond0: (slave ens4f0): link status up, enabling it in 200 ms
[ 9492.291523] bond0: (slave ens4f0): invalid new link 3 on slave
[ 9492.499604] bond0: (slave ens4f0): link status definitely up, 10000
Mbps full duplex
[ 9493.331594] bond0: (slave ens4f0): link status definitely down,
disabling slave
"invalid new link 3 on slave" is there every single time.
Side note: I'm not actually able to reproduce the repeating "link
status up, enabling it in 200 ms" and never recovering from a downed
link on this host, no clue why it's so reproducible w/another system.
--
Jarod Wilson
[email protected]