reassociation problem

[post_break]

I am also having this problem. I am running a Fon with the latest package as of now (bleeding edge). I am running AP + client using WPA on both the network I am connecting to and the one I am broadcasting. When I first boot up it works perfectly for about an hour or two. I'm basically trying to extend my network with my Fon in my garage.

I looked around the firmware for a gui way to get logs but didn't find anything. What is the easiest way to get logs of what's happening?

[Eric]

Run "logread" after sshing into the router.

Btw, I'm working on a last-ditch effort to figure this out before the 1.0 release tomorrow right now... but this bug is really really ugly, so I kind of doubt I'll make it...

[post_break]

Run "logread" after sshing into the router.

Btw, I'm working on a last-ditch effort to figure this out before the 1.0 release tomorrow right now... but this bug is really really ugly, so I kind of doubt I'll make it...

Will do. Thanks for the fast reply. And btw, your Mac firmware loader is excellent. Before I found this I was using VMware to run basically the same since I'm too lazy to do it by command line.

[post_break]

Sorry for the double post but I think I see the issue. The fon stays connected in client mode, the AP it creates shuts down and then reverts to WPA RADIUS. You can see that in the log here. This is a nasty bug. Plugging into the ethernet port lets me still ssh and even get DHCP can browse the net.

Code: Select all

Jul 13 19:53:21 OpenWrt user.info sysinit: (Did you specify correct configuration file path?)
Jul 13 19:53:22 OpenWrt user.info sysinit: sysctl: error: 'net.ipv4.ip_conntrack_max' is an unknown key
Jul 13 19:53:22 OpenWrt user.info sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_udp_timout_stream' is an unknown key
Jul 13 19:53:25 OpenWrt daemon.info dnsmasq[1415]: DHCPDISCOVER(br-lan) 00:17:f2:99:56:3e 
Jul 13 19:53:25 OpenWrt daemon.info dnsmasq[1415]: DHCPOFFER(br-lan) 192.168.1.147 00:17:f2:99:56:3e 
Jul 13 19:53:25 OpenWrt daemon.info dnsmasq[1415]: DHCPDISCOVER(br-lan) 00:17:f2:99:56:3e 
Jul 13 19:53:25 OpenWrt daemon.info dnsmasq[1415]: DHCPOFFER(br-lan) 192.168.1.147 00:17:f2:99:56:3e 
Jul 13 19:53:26 OpenWrt daemon.info dnsmasq[1415]: DHCPREQUEST(br-lan) 192.168.1.147 00:17:f2:99:56:3e 
Jul 13 19:53:26 OpenWrt daemon.info dnsmasq[1415]: DHCPACK(br-lan) 192.168.1.147 00:17:f2:99:56:3e mactop
Jul 13 19:53:35 OpenWrt authpriv.info dropbear[1434]: Child connection from 192.168.1.147:63400
Jul 13 19:53:39 OpenWrt authpriv.notice dropbear[1434]: password auth succeeded for 'root' from 192.168.1.147:63400
Jul 13 19:54:28 OpenWrt authpriv.info dropbear[1434]: exit after auth (root): Exited normally
Jul 13 20:00:01 OpenWrt cron.err crond[1319]: USER root pid 1441 cmd /usr/bin/set_kernel_timezone >/dev/null 2>&1
Jul 13 20:00:10 OpenWrt authpriv.info dropbear[1443]: Child connection from 192.168.1.147:63501
Jul 13 20:00:13 OpenWrt authpriv.notice dropbear[1443]: password auth succeeded for 'root' from 192.168.1.147:63501
Jul 13 20:01:01 OpenWrt cron.err crond[1319]: USER root pid 1453 cmd /usr/bin/set_kernel_timezone >/dev/null 2>&1
Jul 13 20:03:10 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e IEEE 802.11: deauthenticated due to local deauth request
Jul 13 20:03:10 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e IEEE 802.11: disassociated
Jul 13 20:03:11 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e IEEE 802.11: associated
Jul 13 20:03:11 OpenWrt daemon.info hostapd: ath1: STA 


00:17:f2:99:56:3e RADIUS: starting accounting session 0000003F-00000001


Jul 13 20:03:11 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e WPA: pairwise key handshake completed (WPA)
Jul 13 20:03:11 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e WPA: group key handshake completed (WPA)
Jul 13 20:11:01 OpenWrt cron.err crond[1319]: USER root pid 1461 cmd /usr/bin/set_kernel_timezone >/dev/null 2>&1
Jul 13 20:13:07 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e WPA: group key handshake completed (WPA)
Jul 13 20:21:01 OpenWrt cron.err crond[1319]: USER root pid 1470 cmd /usr/bin/set_kernel_timezone >/dev/null 2>&1
Jul 13 20:23:07 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e WPA: group key handshake completed (WPA)
Jul 13 20:31:01 OpenWrt cron.err crond[1319]: USER root pid 1479 cmd /usr/bin/set_kernel_timezone >/dev/null 2>&1
Jul 13 20:32:07 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e IEEE 802.11: associated
Jul 13 20:32:12 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e IEEE 802.11: deauthenticated due to local deauth request
Jul 13 20:32:12 OpenWrt daemon.info hostapd: ath1: STA 00:17:f2:99:56:3e IEEE 802.11: disassociated
Jul 13 20:33:40 OpenWrt daemon.info dnsmasq[1415]: DHCPDISCOVER(br-lan) 00:17:f2:2f:6b:0b 
Jul 13 20:33:40 OpenWrt daemon.info dnsmasq[1415]: DHCPOFFER(br-lan) 192.168.1.126 00:17:f2:2f:6b:0b 
Jul 13 20:33:40 OpenWrt daemon.info dnsmasq[1415]: DHCPDISCOVER(br-lan) 00:17:f2:2f:6b:0b 
Jul 13 20:33:40 OpenWrt daemon.info dnsmasq[1415]: DHCPOFFER(br-lan) 192.168.1.126 00:17:f2:2f:6b:0b 
Jul 13 20:33:41 OpenWrt daemon.info dnsmasq[1415]: DHCPREQUEST(br-lan) 192.168.1.126 00:17:f2:2f:6b:0b 
Jul 13 20:33:41 OpenWrt daemon.info dnsmasq[1415]: DHCPACK(br-lan) 192.168.1.126 00:17:f2:2f:6b:0b mactop
Jul 13 20:33:58 OpenWrt authpriv.info dropbear[1481]: Child connection from 192.168.1.126:63918
Jul 13 20:34:01 OpenWrt authpriv.notice dropbear[1481]: password auth succeeded for 'root' from 192.168.1.126:63918
Jul 13 20:34:45 OpenWrt daemon.info dnsmasq[1415]: DHCPREQUEST(br-lan) 192.168.1.126 00:17:f2:2f:6b:0b 
Jul 13 20:34:45 OpenWrt daemon.info dnsmasq[1415]: DHCPACK(br-lan) 192.168.1.126 00:17:f2:2f:6b:0b mactop
Jul 13 20:34:53 OpenWrt authpriv.info dropbear[1487]: Child connection from 192.168.1.126:63944
Jul 13 20:34:56 OpenWrt authpriv.notice dropbear[1487]: password auth succeeded for 'root' from 192.168.1.126:63944

I could be wrong but that's all I can come up with. The fon is still connected in client mode, the AP is the only thing that gets borked.

[Eric]

Yeah, I noticed the message about RADIUS (even commented on it above in this thread), but I think that's a symptom, not the cause of the problems. I'm also seeing errors like this with no encryption -- works for a while then dies, though I'm seeing slightly different error messages there. It seems AP+STA mode is problematic across the board right now. I'm pretty sure the root of whatever is going on is inside the madwifi driver kernel module... which makes debugging this really,really hard. As I suspected, I'm going to have to put off dealing with this until after the 1.0 release later today.

[post_break]

Yeah I noticed that it dies using encryption or not. With some help from a friend I checked to see disk usage, crons, and cpu usage and don't see anything. I don't have a serial cable but it looks like I'll have to get one. I've tried to bring down the AP while leaving the client connection running and that just crashes the damn thing. I guess a temporary fix would be to set up a cron to bring both the connections down then up every hour but that's hardly a fix.

[Eric]

Another reason the solution of bringing the network up/down every hour isn't particularly good: The time between failures is variable, and seems to decrease the more failures you've already experienced. So when you first boot the router you might wait an hour before failure. Then you restart the network and it fails after 15 minutes, and then 5 and sometimes it just dies altogether unless you reboot. And these times are not at all constant -- sometimes it fails 15 minutes after boot, sometimes 2 hours. Makes debugging SO much fun....

[crisman]

Yeah, I noticed the message about RADIUS (even commented on it above in this thread), but I think that's a symptom, not the cause of the problems. I'm also seeing errors like this with no encryption -- works for a while then dies, though I'm seeing slightly different error messages there. It seems AP+STA mode is problematic across the board right now. I'm pretty sure the root of whatever is going on is inside the madwifi driver kernel module... which makes debugging this really,really hard. As I suspected, I'm going to have to put off dealing with this until after the 1.0 release later today.

I don't think the problem is directly related to madwifi driver because this driver is the same from time to time ( openwrt use the r3314 of madwifi ). I think instead that problem could be in some patches applied to that driver. This problem is not new to me. The last working version I compiled is dated 7 november 2008. I tried compiling another release on december 2008 and that was affected by this bug. So I think problem maybe in a patch submitted between november and december 2008. That sounds good for you?

[Eric]

You're right, I'm sure it has something to do with the patches that are being applied... but there are a LOT of patches, and most of them are there for a very good reason. My understanding is that the newer madwifi releases are not compatible with the 2.6.26 kernel which is what is in OpenWrt 8.09, but many of these patches allow some of the newer features of the driver with the older kernel. Newer kernels cause all sorts of other compatibility and patch issues (that's why the trunk is less stable). Also I think OpenWrt is using a slightly different HAL. (Though if that's where the problem is, we're in real trouble, since that's binary...).

I've been trying to narrow down the version where there are problems and I'm finding that different versions cause different issues. For example it seems like the problems with unencrypted ap+client are more recent, while some of the problematic behavior I see when I use encryption exists in older versions too (as you say, it goes back to some time last fall).

[post_break]

Well at least we might be narrowing down the bug. What's odd for me is that the bug initiates like clockwork, unlike others. I have also thought of the possibility that because the AP and the client are running on the same channel there is a high degree of collisions or interference. The only problem with that theory is that it wouldn't kick me off like clock work.

I'm glad to see the bug noted on the front page though. That will definitely keep frustration down.