Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 18 replies
  • Subscribers 1 subscriber
  • Views 11352 views
  • Users 0 members are here
Options
Suggested
This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

AP 10 disconnecting

wingman
Hi All

I am getting quite few disconnects over the past month and this is relevant log

2012:09:03-18:47:52 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: sending 1/2 msg of Group Key Handshake
2012:09:03-18:47:52 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: sending 1/2 msg of Group Key Handshake
2012:09:03-18:47:52 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: received EAPOL-Key frame (2/2 Group)
2012:09:03-18:47:52 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: group key handshake completed (RSN)
2012:09:03-18:47:52 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: received EAPOL-Key frame (2/2 Group)
2012:09:03-18:47:52 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: group key handshake completed (RSN)
2012:09:03-18:49:35 ap-10 sysinit: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1alrm_handler(): timeout, reason 1
2012:09:03-18:49:35 ap-10 init: starting pid 20657, tty '': '/etc/init.d/rcS K shutdown'
2012:09:03-18:49:35 ap-10 sysinit: interface not found.
2012:09:03-18:50:02 * awed[6916]: [AP10 A40000D709AC807] disconnected. Close socket and kill process.
2012:09:03-18:50:04 * awed[4157]: [MASTER] new connection from 192.168.2.1:45989
2012:09:03-18:50:06 * awed[6568]: [AP10 A40000D709AC807] (Re-)loaded identity and/or configuration
2012:09:03-18:50:08 ap-10 sysinit: Channel 2 busy time 17/230ms, 7%


and 

2012:08:29-06:32:42 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 IEEE 802.1X: authenticated - EAP type: 21 ((null))
2012:08:29-06:32:42 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: Added PMKSA cache entry (IEEE 802.1X)
2012:08:29-06:41:32 ap-10 hostapd: wlan1: WPA rekeying GTK
2012:08:29-06:41:32 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: sending 1/2 msg of Group Key Handshake
2012:08:29-06:41:32 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: received EAPOL-Key frame (2/2 Group)
2012:08:29-06:41:32 ap-10 hostapd: wlan1: STA 68:a8:6d:cd:2e:07 WPA: group key handshake completed (RSN)
2012:08:29-06:47:38 ap-10 sysinit: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1alrm_handler(): timeout, reason 1
2012:08:29-06:47:38 ap-10 sysinit: interface not found.
2012:08:29-06:48:06 * awed[15443]: [AP10 A40000D709AC807] disconnected. Close socket and kill process.
2012:08:29-06:48:09 * awed[4146]: [MASTER] new connection from 192.168.2.1:45989
2012:08:29-06:48:10 * awed[26308]: [AP10 A40000D709AC807] (Re-)loaded identity and/or configuration
2012:08:29-06:48:11 ap-10 sysinit: Channel 2 busy time 33/242ms, 13%



MAC 68:a8:6d:cd:2e:07 is : iphone 4S IOS 5.1.1

Same issue as here: https://community.sophos.com/products/unified-threat-management/astaroorg/f/76/t/64639 Is there a solution on this one?

Thanks


This thread was automatically locked due to age.
  • 0
    Have you tried the AP re-flashing utility in Support Tools?

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • 0 in reply to BAlfson
    Hi Wingman,

    I don't have a solution ready for this problem [:(] but thanks for the log snippets.

    Helmut
  • 0 in reply to BAlfson
    Have you tried the AP re-flashing utility in Support Tools?

    Cheers - Bob

    haven't tried this yet Bob as I know this is a known issue that the dev/qa are working on and I would like to provide further logs if required.

    Helmut let me know if you want me to provide any more logs/debugs etc

    latest one today

    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 IEEE 802.1X: Sending EAP Packet (identifier 237)
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: sending 1/4 msg of 4-Way Handshake
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: received EAPOL-Key frame (2/4 Pairwise)
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: sending 3/4 msg of 4-Way Handshake
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: received EAPOL-Key frame (4/4 Pairwise)
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: pairwise key handshake completed (RSN)
    2012:09:04-18:53:55 ap-10 awelogger[1946]: id="4101" severity="info" sys="System" sub="WiFi" name="STA connected" ssid="Stoufospito" ssid_id="WLAN2.0" bssid="00:1a:8c:06:13:51" sta="70:56:81:c2:3a:19"
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 IEEE 802.1X: authorizing port
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 RADIUS: starting accounting session 5045A524-00000002
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 IEEE 802.1X: authenticated - EAP type: 21 ((null))
    2012:09:04-18:53:55 ap-10 hostapd: wlan1: STA 70:56:81:c2:3a:19 WPA: Added PMKSA cache entry (IEEE 802.1X)
    2012:09:04-18:54:55 ap-10 sysinit: alrm_handler(): timeout, reason 1
    2012:09:04-18:54:55 ap-10 init: starting pid 21431, tty '': '/etc/init.d/rcS K shutdown'
    2012:09:04-18:54:55 ap-10 sysinit: interface not found.
    2012:09:04-18:55:29 * awed[20088]: [AP10 A40000D709AC807] error while writing to socket, dropping.
    2012:09:04-18:55:38 * awed[4157]: [MASTER] new connection from 192.168.2.1:45989
    2011:12:31-00:00:38 ap-10 sysinit: Channel 2 busy time 17/230ms, 7%
    2011:12:31-00:00:38 ap-10 sysinit: Channel 3 busy time 15/230ms, 6%
    2011:12:31-00:00:39 ap-10 sysinit: Channel 4 busy time 11/230ms, 4%


    70:56:81:c2:3a:19: is my MBA 2012 (another apple product [:P])

    Thanks
  • 0 in reply to wingman
    The "alrm_handler" message in the log indicates that the TCP control connection between ASG and AP died even though the AP can still send loglines to the ASG. So it is not a generic network failure.

    Maybe you could run a tcpdump on the ASG ("tcpdump -i ethX -s0 -w wifi.pcap") and send it to me when the next "alrm_handler" connection failure happens?

    Thanks,
    Helmut
  • 0
    Hi Helmut

    not sure if 9.002 had any wireless fixes but after upgrading to 9.002 I only had one alrm_handler which I didn't get via tcpdump. I will send you an email as soon as I get the next one with the output of my tcpdump

    Thanks
  • 0
    Hey Helmut

    I just got another one

    /var/log/wireless.log:2012:09:10-06:54:37 ap-10 sysinit: AP-STA-DISCONNECTED 00:1c:b3:52:b7:58alrm_handler(): timeout, reason 1

    password for the file sent you your email address at sophos.
    *send link via pm*

    Thanks
  • 0 in reply to wingman
    Do any of these timeouts coincide with IPS updates (check in the up2date log) ?  Just thinking maybe it's updating and interrupting the traffic to the AP, just a thought.

    CTO, Convergent Information Security Solutions, LLC

    https://www.convergesecurity.com

    Sophos Platinum Partner

    --------------------------------------

    Advice given as posted on this forum does not construe a support relationship or other relationship with Convergent Information Security Solutions, LLC or its subsidiaries.  Use the advice given at your own risk.

  • 0 in reply to BrucekConvergent
    Do any of these timeouts coincide with IPS updates (check in the up2date log) ?  Just thinking maybe it's updating and interrupting the traffic to the AP, just a thought.


    up2 date 

    2012:09:10-18:10:34 **** auisys[4259]: id="371D" severity="info" sys="system" sub="up2date" name="No up2date packages available for installation" status="failed" action="preinst_check" package="savi"

    2012:09:10-18:10:39 **** auisys[4259]: id="3716" severity="info" sys="system" sub="up2date" name="Up2date Package Installer finished, exiting"

    2012:09:10-18:44:05 **** audld[11645]: Starting Up2Date Package Downloader

    2012:09:10-18:44:09 **** audld[11645]: patch up2date possible

    2012:09:10-18:44:16 **** audld[11645]: id="3701" severity="info" sys="system" sub="up2date" name="Authentication successful"

    2012:09:10-19:13:02 **** audld[16338]: Starting Up2Date Package Downloader

    2012:09:10-19:13:02 **** audld[16338]: patch up2date possible

    

    /var/log/wireless/2012/09/wireless-2012-09-10.log.gz:2012:09:10-18:44:02 ap-10 sysinit: AP-STA-CONNECTED 18:3d:a2:90:3a:b8alrm_handler(): timeout, reason 1


    2012:09:10-06:54:19 **** auisys[27051]: Searching for available up2date packages for type 'savi'

    2012:09:10-06:54:19 **** auisys[27051]: Installing up2date package file '/var/up2date//savi/u2d-savi-9.1208-1209.patch.tgz.gpg'

    2012:09:10-06:54:19 **** auisys[27051]: Verifying up2date package signature

    2012:09:10-06:54:56 **** auisys[27051]: Still waiting for process 'sh' (pid=27290, timeout 300 seconds, 270 remaining)

    2012:09:10-06:55:26 **** auisys[27051]: Still waiting for process 'sh' (pid=27290, timeout 300 seconds, 240 remaining)

    2012:09:10-06:55:32 **** auisys[27051]: Unpacking installation instructions

    2012:09:10-06:55:41 **** auisys[27051]: Unpacking up2date package container

    2012:09:10-06:55:42 **** auisys[27051]: Running pre-installation checks

    

    /var/log/wireless/2012/09/wireless-2012-09-10.log.gz:2012:09:10-06:54:37 ap-10 sysinit: AP-STA-DISCONNECTED 00:1c:b3:52:b7:58alrm_handler(): timeout, reason 1


    However, not all "alrm_handler" issues happen the same time as the updates as per below
    Thanks
  • 0
    Helumt did you receive the wireshark log? Do you need more captures from me?
  • 0 in reply to wingman
    Yep, got it. Thanks. I did only a quick analysis but this is what I've found out:

    Frame no 115964 + 115965 + 115978 + 115979 is the last successful handshake with the AP before a disconnect.

    15 seconds later (frame 116041 + 116042) the AP again sends a status update to the ASG. However, the ASG doesn't answer immediately but with a delay of nearly 40 seconds (frame 116110 and later). In the meantime the AP already timed out (frame 116090) because it assumes the ASG is gone.

    Hence, my assumption is that your ASG is under quite heavy load and thus awed (the wireless control daemon) doesn't receive enough CPU time to finish its work in a timely manner [:(]

    Could you please check the CPU usage graph in the reporting section to see whether your ASG is under high load from time to time? Of course you can also just run a script that writes the current CPU (and maybe IO) load to a file such that we can identify if CPU or IO spikes are the culprit for the AP disconnects.

    Thanks,
    Helmut
Unfiltered HTML