Re: [Ipw2100-devel] ipw2100: race between isr_indicate_associated and rx path

Re: [Ipw2100-devel] ipw2100: race between isr_indicate_associated and rx path

[Zhu Yi]

[ remove ipw2100-devel and cc linux-wireless ]

On Mon, 2009-02-23 at 18:38 +0800, Helmut Schaa wrote:
> Am Donnerstag, 5. Februar 2009 schrieb Helmut Schaa:
> > Am Dienstag, 27. Januar 2009 schrieb Helmut Schaa:
> > > Am Freitag, 23. Januar 2009 schrieb Helmut Schaa:
> > > > Am Freitag, 23. Januar 2009 schrieb Zhu, Yi:
> [...]
> > > > > I see. This should be a firmware bug. I think your idea to queue packets
> > > > > between ASSOCIATING and ASSOCIATED and replay them later (state becomes
> > > > > ASSOCIATED) should work. 
> > > > 
> > > > Agreed, I'll try that (maybe today, maybe next week).
> > > 
> > > Ok, I've done a first try and the frame buffering/replaying works quite well
> > > but I've ran into another issue now:
> > > 
> > > The supplicant successfully receives the EAP frame which was buffered by the
> > > driver and sends the appropriate resone. However the response is not send over
> > > the air. If I just add a sleep(1) before sending the frame in the supplicant
> > > all works well. I have no clue yet why the frame is not send.
> > 
> > JFYI, got a bit further now. The driver never got the frame from the
> > supplicant. It's the netdev which does not accept the frame that short
> > after the queues are woken up.
> 
> Found some time again to investigate this issue again. The current state
> is as follows:
> 
> After the firmware notifies the driver about the association it starts
> buffering all frames. Once the delayed work is executed and moves the
> driver state to ASSOCIATED the following happens:
> 
> 1) netif_carrier_on
> 2) netif_wake_queue
> 3) wireless_send_event
> 4) replay buffered frames
> 
> Hereupon wpa_supplicant receives the buffered EAP-frame and builds the
> according reply and tries to send it. The sendto call does _not_ indicate
> an error. Nevertheless, the frame is not passed to the ipw2100 driver. I
> was able to track that down to the following situation:
> 
> 
> This happens when the driver moves to the associated state:
> ----------------------------
> netif_carrier_on
>   linkwatch_fire_event
>     linkwatch_schedule_work
> netif_wake_queue
> ----------------------------
> At that point in time the device's tx queue has a noop_qdisc assigned.
> 
> Now wpa_supplicant sends the EAP reply:
> ---------------------------
> packet_sendmsg
>   dev_queue_xmit
>     qdisc_enqueue_root
>       qdisc_enqueue
>         return NET_XMIT_CN
>   return 0
> ---------------------------
> Since the qdisc is still noop_qdisc, qdisc_enqueue returns NET_XMIT_CN for
> every frame while packet_sendmsg translates that to 0, see netdevice.h:
> 
> #define net_xmit_errno(e) ((e) != NET_XMIT_CN ? -ENOBUFS : 0)
> 
> Hence, wpa_supplicant thinks the frame was sent out successfully.
> 
> Somewhat later when the queued linkwatch work is executed the qdisc gets
> swapped to the default_qdisc which would allow frames to be send.
> 
> ---------------------------
> linkwatch_event
>   __linkwatch_run_queue
>     activate_dev
>       attach_default_qdisc
> ---------------------------

Thanks for the analysis. Are you sure noop_qdisc is still used when we
are about to netif_carrier_on() after receiving the association success
response? From dev_open(), dev_activate() is called after netdev->open.
So the txq->qdisc_sleeping should be already replaced with pfifo_fast.
But the state is still DEACTIVATED. Should the packet from
wpa_supplicant be dropped by dev_queue_xmit()?

> So, how should I proceed here?
> 
> Some possibilities that come to mind:
> 
> 1) let the noop_qdisc return NET_XMIT_DROP instead of NET_XMIT_CN and extend
>    wpa_supplicant to retry after a short timeout. Already tried this approach
>    and it works fine for me. wpa_supplicant typically needs one retry (200ms
>    delay) until the frame is successfully send out.
> 
> 2) Run activate_dev somehow without a delay. I guess this could be achieved by
>    changing linkwatch_urgent_event. I haven't tested this yet. But I guess we
>    would still have a small race here.
> 
> 3) Wait until activate_dev was called in ipw2100 before replaying the cached
>    frames.

I think making a sync version of netif_carrier_on/activate_dev should be
the way to go. This could be a requirement from wireless. In wired
network, netif_carrier_on() is called after a network cable plug event
is detected. Some delay should be OK. But in wireless,
netif_carrier_on() is usually called after an association is succeeded.
The driver has already some management frames transfered with AP. Now
it's the time to open the data frame transmission. The driver requires
to get the activate_dev() result (synchronously or via callback) because
otherwise the driver has no idea when the Qdisc is ready and then it can
start to deliver data frames to network stack and user space. The real
failure example here is the one Helmut found about the wpa_supplicant
EAPOL frames lost case above.

> Maybe, someone from the netdev people can give me a hand here?

Yeah, please comment.

Thanks,
-yi

Re: [Ipw2100-devel] ipw2100: race between isr_indicate_associated and rx path

[Helmut Schaa]

Am Dienstag, 24. Februar 2009 schrieb Zhu Yi:

[...]

> Thanks for the analysis. Are you sure noop_qdisc is still used when we
> are about to netif_carrier_on() after receiving the association success
> response? 

Yes, had a printk in noop_enqueue.

> From dev_open(), dev_activate() is called after netdev->open.
> So the txq->qdisc_sleeping should be already replaced with pfifo_fast.
> But the state is still DEACTIVATED.

Right. But for example when a connection cannot be established by ipw2100
it will call netif_carrier_off on disassociation which in turn leads to a
call to dev_deavtivate. Hence, it is possible that a noop_qdisc is
assigned while the device is up and carrier is off.

> Should the packet from 
> wpa_supplicant be dropped by dev_queue_xmit()?
>
> > So, how should I proceed here?
> > 
> > Some possibilities that come to mind:
> > 
> > 1) let the noop_qdisc return NET_XMIT_DROP instead of NET_XMIT_CN and extend
> >    wpa_supplicant to retry after a short timeout. Already tried this approach
> >    and it works fine for me. wpa_supplicant typically needs one retry (200ms
> >    delay) until the frame is successfully send out.
> > 
> > 2) Run activate_dev somehow without a delay. I guess this could be achieved by
> >    changing linkwatch_urgent_event. I haven't tested this yet. But I guess we
> >    would still have a small race here.
> > 
> > 3) Wait until activate_dev was called in ipw2100 before replaying the cached
> >    frames.
> 
> I think making a sync version of netif_carrier_on/activate_dev should be
> the way to go. This could be a requirement from wireless. In wired
> network, netif_carrier_on() is called after a network cable plug event
> is detected. Some delay should be OK.

Maybe, but I can imagine a similar race when using a wired 802.1x secured
network. The switch might send an EAP-request very quickly after the carrier
was detected.

> But in wireless, 
> netif_carrier_on() is usually called after an association is succeeded.
> The driver has already some management frames transfered with AP. Now
> it's the time to open the data frame transmission. The driver requires
> to get the activate_dev() result (synchronously or via callback) because
> otherwise the driver has no idea when the Qdisc is ready and then it can
> start to deliver data frames to network stack and user space.

Exactly.

[...]

Helmut

Re: [Ipw2100-devel] ipw2100: race between isr_indicate_associated and rx path

[Zhu Yi]

On Tue, 2009-02-24 at 20:15 +0800, Helmut Schaa wrote:
> Am Dienstag, 24. Februar 2009 schrieb Zhu Yi:
> 
> [...]
> 
> > Thanks for the analysis. Are you sure noop_qdisc is still used when we
> > are about to netif_carrier_on() after receiving the association success
> > response? 
> 
> Yes, had a printk in noop_enqueue.
> 
> > From dev_open(), dev_activate() is called after netdev->open.
> > So the txq->qdisc_sleeping should be already replaced with pfifo_fast.
> > But the state is still DEACTIVATED.
> 
> Right. But for example when a connection cannot be established by ipw2100
> it will call netif_carrier_off on disassociation which in turn leads to a
> call to dev_deavtivate. Hence, it is possible that a noop_qdisc is
> assigned while the device is up and carrier is off.

Make sense. Whatever there is race here but either the driver or the
user space is able to control and avoid it.

BTW, does wpa_supplicant start to receive EAPOL frames after it gets the
association event?

[...]

> > But in wireless, 
> > netif_carrier_on() is usually called after an association is succeeded.
> > The driver has already some management frames transfered with AP. Now
> > it's the time to open the data frame transmission. The driver requires
> > to get the activate_dev() result (synchronously or via callback) because
> > otherwise the driver has no idea when the Qdisc is ready and then it can
> > start to deliver data frames to network stack and user space.
> 
> Exactly.

Looks like we didn't bring enough attention for netdev people on this.
Should you change the title to remove ipw2100? It should be a generic
issue for the current netif_carrier_on/dev_activate() implementation.

Thanks,
-yi

Re: [Ipw2100-devel] ipw2100: race between isr_indicate_associated and rx path

[Helmut Schaa]

Am Mittwoch, 25. Februar 2009 schrieb Zhu Yi:
> Make sense. Whatever there is race here but either the driver or the
> user space is able to control and avoid it.
> 
> BTW, does wpa_supplicant start to receive EAPOL frames after it gets the
> association event?

Yep.

> [...]
> 
> > > But in wireless, 
> > > netif_carrier_on() is usually called after an association is succeeded.
> > > The driver has already some management frames transfered with AP. Now
> > > it's the time to open the data frame transmission. The driver requires
> > > to get the activate_dev() result (synchronously or via callback) because
> > > otherwise the driver has no idea when the Qdisc is ready and then it can
> > > start to deliver data frames to network stack and user space.
> > 
> > Exactly.
> 
> Looks like we didn't bring enough attention for netdev people on this.
> Should you change the title to remove ipw2100? It should be a generic
> issue for the current netif_carrier_on/dev_activate() implementation.

Argh! Just found out why dev_activate is called such late after
netif_carrier_on:

ipw2100 calls netif_carrier_on followed by netif_wake_queue when the driver
moves from associating to associated state. netif_carrier_on will then
call linkwatch_fire_event. However the carrier_on event is not treated as
urgent and as such the event is delayed (and thus dev_activate too).

An event is considered urgent if the netdev is running, has a carrier
_and_ any of the TX qdiscs changed. Since ipw2100 first calls carrier_on,
the last condition is not met and thus the event is not considered urgent
and gets delayed.

Just changing the order to first wake up the queues followed by the
carrier_on results in an urgent event. I ran a few tests with that change
(+ frame buffering patch) and wasn't able to trigger the race again.

I'll fold that into the frame buffer patch and send it to ipw2100-devel
once I finished the tests.

Helmut

Re: [Ipw2100-devel] ipw2100: race between isr_indicate_associated and rx path

[Zhu Yi]

On Wed, 2009-02-25 at 20:39 +0800, Helmut Schaa wrote:
> Argh! Just found out why dev_activate is called such late after
> netif_carrier_on:
> 
> ipw2100 calls netif_carrier_on followed by netif_wake_queue when the
> driver
> moves from associating to associated state. netif_carrier_on will then
> call linkwatch_fire_event. However the carrier_on event is not treated
> as
> urgent and as such the event is delayed (and thus dev_activate too).
> 
> An event is considered urgent if the netdev is running, has a carrier
> _and_ any of the TX qdiscs changed. Since ipw2100 first calls
> carrier_on,
> the last condition is not met and thus the event is not considered
> urgent and gets delayed.

Calling netif_wake_queue() before netif_carrier_on() is not correct in
semantics. Even it works, it looks like a workaround hack. I still think
making a sync version of netif_carrier_on is the way to go.

> Just changing the order to first wake up the queues followed by the
> carrier_on results in an urgent event. I ran a few tests with that
> change
> (+ frame buffering patch) and wasn't able to trigger the race again.
> 
> I'll fold that into the frame buffer patch and send it to
> ipw2100-devel
> once I finished the tests.

Sounds good.

Thanks,
-yi

Re: ipw2100: race between isr_indicate_associated and rx path

[Helmut Schaa]

Am Freitag, 27. Februar 2009 schrieb Zhu Yi:
> On Wed, 2009-02-25 at 20:39 +0800, Helmut Schaa wrote:
> > Argh! Just found out why dev_activate is called such late after
> > netif_carrier_on:
> > 
> > ipw2100 calls netif_carrier_on followed by netif_wake_queue when the
> > driver
> > moves from associating to associated state. netif_carrier_on will then
> > call linkwatch_fire_event. However the carrier_on event is not treated
> > as
> > urgent and as such the event is delayed (and thus dev_activate too).
> > 
> > An event is considered urgent if the netdev is running, has a carrier
> > _and_ any of the TX qdiscs changed. Since ipw2100 first calls
> > carrier_on,
> > the last condition is not met and thus the event is not considered
> > urgent and gets delayed.
> 
> Calling netif_wake_queue() before netif_carrier_on() is not correct in
> semantics. Even it works, it looks like a workaround hack. I still think
> making a sync version of netif_carrier_on is the way to go.

Hmm, we could use register_netdevice_notifier to get notified when the
carrier event is sent out and thus the tx queues are available.

The flow in ipw2100 would then be:

1) isr_indicate_associated:
- move to ASSOCIATING state
- start buffering incoming frames

2) ipw2100_ex_event_work:
- call carrier_on and wake_queues

3) netdevice_notification:
- move to ASSOCIATED state and replay buffered frames

I hope I'll find some time to try that soon.

Helmut