[PATCH] net, bridge: print log message after state changed

[PATCH] net, bridge: print log message after state changed

[Holger Brunck]

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(-)

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)
-- 
1.7.1

Re: [PATCH] net, bridge: print log message after state changed

[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"

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

I'm not applying this patch.

Re: [PATCH] net, bridge: print log message after state changed

[Fritz, Wolfgang]

[-- Attachment #1.1: Type: text/plain, Size: 1675 bytes --]


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.

Regards,
Wolfgang 


> I'm not applying this patch.
> 
-- 
"I love deadlines. I like the whooshing sound they make as they fly by"
(Douglas Adams)
=======================================================================
KEYMILE GmbH       mailto:wolfgang.fritz@keymile.com
Wolfgang Fritz     Phone: +49 (0)511 6747-692
Wohlenbergstr. 3   Fax:   +49 (0)511 6747-777
D-30179 Hannover   http://www.keymile.com

Managing Directors: Björn Claaßen, Dipl.-Kfm. Andreas Gebauer
Legal structure: GmbH, Registered office: Hanover, HRB 61069 
Local court Hanover, VAT-Reg.-No.: DE 812282795, 
WEEE-Reg.-No.: DE 59336750

[-- Attachment #1.2: Type: text/html, Size: 2591 bytes --]

[-- Attachment #2: Type: text/plain, Size: 159 bytes --]

_______________________________________________
Bridge mailing list
Bridge@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/bridge

Re: [PATCH] net, bridge: print log message after state changed

[David Miller]

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.

Re: [PATCH] net, bridge: print log message after state changed

[Fritz, Wolfgang]

[-- Attachment #1.1: Type: text/plain, Size: 3241 bytes --]


Am Montag, den 14.11.2011, 02:07 -0500 schrieb David Miller:
> 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.
> 

OK. I see what you mean.

Proposal 1 (simple): 
- Modify log message to "Entered xxx state"
- Apply patch
- Do not touch other br_log_message calls.

Proposal 2 (more complicated):
Add parameter "newstate" to br_log_message and put br_log_message before
the state change. Print log message only if new state != current state.

Advantage: Reduces log spam when STP is disabled. After the last
modifications to the bridge code which force "forwarding" state if STP
is disabled, you get lots of bogus messages "entering forwarding state":

Event                    old message      new message
link up                  learning         forwarding
forwarding delay expired forwarding       forwarding
interface down           disabled         forwarding
link down                disabled         forwarding  

If you accept one of the proposals, I'll prepare a patch. Otherwise, we
keep my original patch in our local tree.

> I'm still not applying this.  If the other log messages behave
> differently, they are broken, so go fix those instead.

Regards,
Wolfgang

-- 
"I love deadlines. I like the whooshing sound they make as they fly by"
(Douglas Adams)
=======================================================================
KEYMILE GmbH       mailto:wolfgang.fritz@keymile.com
Wolfgang Fritz     Phone: +49 (0)511 6747-692
Wohlenbergstr. 3   Fax:   +49 (0)511 6747-777
D-30179 Hannover   http://www.keymile.com

Managing Directors: Björn Claaßen, Dipl.-Kfm. Andreas Gebauer
Legal structure: GmbH, Registered office: Hanover, HRB 61069 
Local court Hanover, VAT-Reg.-No.: DE 812282795, 
WEEE-Reg.-No.: DE 59336750

[-- Attachment #1.2: Type: text/html, Size: 5051 bytes --]

[-- Attachment #2: Type: text/plain, Size: 159 bytes --]

_______________________________________________
Bridge mailing list
Bridge@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/bridge

Re: [PATCH] net, bridge: print log message after state changed

[Joe Perches]

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.

Re: [PATCH] net, bridge: print log message after state changed

[David Lamparter]

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

Re: [PATCH] net, bridge: print log message after state changed

[Stephen Hemminger]

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?

Re: [PATCH] net, bridge: print log message after state changed

[Holger Brunck]

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