Patchwork net, bridge: print log message after state changed

login
register
mail settings
Submitter Holger Brunck
Date Nov. 10, 2011, 4:18 p.m.
Message ID <1320941934-3534-1-git-send-email-holger.brunck@keymile.com>
Download mbox | patch
Permalink /patch/124960/
State Rejected
Delegated to: David Miller
Headers show

Comments

Holger Brunck - Nov. 10, 2011, 4:18 p.m.
From: Wolfgang Fritz <wolfgang.fritz@keymile.com>

Function br_log_state writes log message "... entering XXXX state" so it
should be called after the state has changed and not before.

Signed-off-by: Wolfgang Fritz <wolfgang.fritz@keymile.com>
Signed-off-by: Holger Brunck <holger.brunck@keymile.com>
cc: Stephen Hemminger <shemminger@linux-foundation.org>
cc: "David S. Miller" <davem@davemloft.net>
cc: bridge@lists.linux-foundation.org
---
 net/bridge/br_stp_if.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)
David Miller - Nov. 14, 2011, 5:37 a.m.
From: Holger Brunck <holger.brunck@keymile.com>
Date: Thu, 10 Nov 2011 17:18:54 +0100

> From: Wolfgang Fritz <wolfgang.fritz@keymile.com>
> 
> Function br_log_state writes log message "... entering XXXX state" so it
> should be called after the state has changed and not before.
> 
> Signed-off-by: Wolfgang Fritz <wolfgang.fritz@keymile.com>
> Signed-off-by: Holger Brunck <holger.brunck@keymile.com>

"entering" can roughly mean "about to enter"

The message is therefore appropriately timed as far as I'm concerned.

I'm not applying this patch.

--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
David Miller - Nov. 14, 2011, 7:07 a.m.
From: "Fritz, Wolfgang" <Wolfgang.Fritz@keymile.com>
Date: Mon, 14 Nov 2011 08:03:31 +0100

> 
> Am Montag, den 14.11.2011, 00:37 -0500 schrieb David Miller:
>> From: Holger Brunck <holger.brunck@keymile.com>
>> Date: Thu, 10 Nov 2011 17:18:54 +0100
>> 
>> > From: Wolfgang Fritz <wolfgang.fritz@keymile.com>
>> > 
>> > Function br_log_state writes log message "... entering XXXX state" so it
>> > should be called after the state has changed and not before.
>> > 
>> > Signed-off-by: Wolfgang Fritz <wolfgang.fritz@keymile.com>
>> > Signed-off-by: Holger Brunck <holger.brunck@keymile.com>
>> 
>> "entering" can roughly mean "about to enter"
>> 
> 
> Exactly.
> 
>> The message is therefore appropriately timed as far as I'm concerned.
>> 
> 
> It's not.
> 
> Please test: create a bridge with STP disabled, add an interface to the
> bridge and set that interface down. You get the message "... entering
> forwarding state". That's wrong because it's "about to enter" disabled
> state some lines later.
> 
> All other (4) calls to br_log_state are located after the state change,
> see for example br_stp_enable_port() just some lines above the patch.

I would never expect an "entering" message to print out after the event
happens, and in fact I'd _always_ want to see it beforehand so that if
the state change caused a crash or similar it'd be that much easier
to pinpoint the proper location.

I'm still not applying this.  If the other log messages behave
differently, they are broken, so go fix those instead.
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Joe Perches - Nov. 14, 2011, 2:27 p.m.
On Mon, 2011-11-14 at 02:07 -0500, David Miller wrote:
> I would never expect an "entering" message to print out after the event
> happens, and in fact I'd _always_ want to see it beforehand so that if
> the state change caused a crash or similar it'd be that much easier
> to pinpoint the proper location.
> 
> I'm still not applying this.  If the other log messages behave
> differently, they are broken, so go fix those instead.

Perhaps use "entered" after the transition or "entering" before.


--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
David Lamparter - Nov. 17, 2011, 7:23 p.m.
On Mon, Nov 14, 2011 at 02:07:49AM -0500, David Miller wrote:
> >> The message is therefore appropriately timed as far as I'm concerned.
> >> 
> > 
> > It's not.
> > 
> > Please test: create a bridge with STP disabled, add an interface to the
> > bridge and set that interface down. You get the message "... entering
> > forwarding state". That's wrong because it's "about to enter" disabled
> > state some lines later.
> > 
> > All other (4) calls to br_log_state are located after the state change,
> > see for example br_stp_enable_port() just some lines above the patch.
> 
> I would never expect an "entering" message to print out after the event
> happens, and in fact I'd _always_ want to see it beforehand so that if
> the state change caused a crash or similar it'd be that much easier
> to pinpoint the proper location.

There seems to be a misunderstanding here. The patch effectively does:
-       br_log_state(p);
        p->state = BR_STATE_DISABLED;
+       br_log_state(p);

and the issue it is trying to fix is not the timing but rather the code
printing the wrong (old, now-left) state.

I do agree that the log message should be printed before anything
happens, so, Holger, can you brew a patch that does that?


-David
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
stephen hemminger - Nov. 17, 2011, 10:40 p.m.
On Thu, 17 Nov 2011 20:23:53 +0100
David Lamparter <equinox@diac24.net> wrote:

> There seems to be a misunderstanding here. The patch effectively does:
> -       br_log_state(p);
>         p->state = BR_STATE_DISABLED;
> +       br_log_state(p);
> 
> and the issue it is trying to fix is not the timing but rather the code
> printing the wrong (old, now-left) state.
> 
> I do agree that the log message should be printed before anything
> happens, so, Holger, can you brew a patch that does that?

Other than being horribly strict, why bother? I hope you aren't building
some application that depends on the ordering of the log message.
The state change doesn't get undone, why does the order of the message
matter at all?
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Holger Brunck - Nov. 18, 2011, 9:20 a.m.
On 11/17/2011 08:23 PM, David Lamparter wrote:
> On Mon, Nov 14, 2011 at 02:07:49AM -0500, David Miller wrote:
>>>> The message is therefore appropriately timed as far as I'm concerned.
>>>>
>>>
>>> It's not.
>>>
>>> Please test: create a bridge with STP disabled, add an interface to the
>>> bridge and set that interface down. You get the message "... entering
>>> forwarding state". That's wrong because it's "about to enter" disabled
>>> state some lines later.
>>>
>>> All other (4) calls to br_log_state are located after the state change,
>>> see for example br_stp_enable_port() just some lines above the patch.
>>
>> I would never expect an "entering" message to print out after the event
>> happens, and in fact I'd _always_ want to see it beforehand so that if
>> the state change caused a crash or similar it'd be that much easier
>> to pinpoint the proper location.
> 
> There seems to be a misunderstanding here. The patch effectively does:
> -       br_log_state(p);
>         p->state = BR_STATE_DISABLED;
> +       br_log_state(p);
> 
> and the issue it is trying to fix is not the timing but rather the code
> printing the wrong (old, now-left) state.
> 

Yes exactly this is the problem. We got confusing state messages in the current
implementation.

> I do agree that the log message should be printed before anything
> happens, so, Holger, can you brew a patch that does that?
> 

This can't be changed easily. Because in some situations we don't know which
state we will enter at the entry point of the function.

For example  br_make_forwarding does something like
if ..
  p->state = STATE_A
else if ...
  p->state = STATE_B
....

So my approach would be to change the log message from "port entering state" to
"port entered state" and print it out after the state changed.

Regards
Holger


--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Patch

diff --git a/net/bridge/br_stp_if.c b/net/bridge/br_stp_if.c
index 19308e3..e91be40 100644
--- a/net/bridge/br_stp_if.c
+++ b/net/bridge/br_stp_if.c
@@ -98,8 +98,6 @@  void br_stp_disable_port(struct net_bridge_port *p)
 	struct net_bridge *br = p->br;
 	int wasroot;
 
-	br_log_state(p);
-
 	wasroot = br_is_root_bridge(br);
 	br_become_designated_port(p);
 	p->state = BR_STATE_DISABLED;
@@ -121,6 +119,8 @@  void br_stp_disable_port(struct net_bridge_port *p)
 
 	if (br_is_root_bridge(br) && !wasroot)
 		br_become_root_bridge(br);
+
+	br_log_state(p);
 }
 
 static void br_stp_start(struct net_bridge *br)