ExtremeWireless (Identifi)

Expand all | Collapse all

AP3915i will not become active but communicate with controller

  • 1.  AP3915i will not become active but communicate with controller

    Posted 11-02-2018 07:19
    Hi all,
    I have a problem to become my AP3915i active on a V2110 Conroller in a different VLAN.
    I have configured DHCP Option 78 and I can ping the AP from the Controller MGMT_Plane_Interface and from the AP I can Ping the controller.
    After connecting the AP to a switch port in same vlan where the MGMT_Plane_Interface is, the AP becomes active.
    But if I configure the AP into a defferent vlan, set the AP to factory (cset factorydefault) and delete it in controller and then activate it in a different VLAN the AP will be shown and when I approve it, the AP will be inactive and the firmware of the AP is shown as unknown.

    I have checked the output from the console of the AP and done a tail -f /tmp/log/ap.log to see, what happend:
    It starts with:

    BusyBox v1.17.4 (2018-07-30 14:31:06 EDT) built-in shell (ash)
    Enter 'help' for a list of built-in commands.

    AP3915i-ROW 10.41.09.0008 interactive shell for service personnel only
    AP3915i-1824Y-137790000#
    AP3915i-1824Y-137790000# tail -f /tmp/log/ap.log
    Nov 2 06:33:43 cap: 00841:ru_misc.c:594-ru_ikedReqHandler()-ru_ikedReqHandler: IKED opCode 525 tid 1 totalNumIp 0 ru_id -1
    Nov 2 06:33:43 cap: 00841:ru_misc.c:551-ru_flushIkeIp()-ru_flushIkeIp: IKED removing all ike IP
    Nov 2 06:33:44 cap: 00841:ru_misc.c:356-ru_ikedRspRecv()-00000015000000010000020e0000000000000000
    Nov 2 06:33:44 cap: 00841:ru_misc.c:362-ru_ikedRspRecv()-0000000000000000000000000000000000000000
    Nov 2 06:33:44 cap: 00841:ru_misc.c:407-ru_ikedRspRecv()-ru_ikedRspRecv407: IKED tid 1 received response: 526 rc 0
    Nov 2 06:33:44 cap: 00841:ru_misc.c:296-ru_ikedRspHandler()-ru_ikedRspHandler: IKED All secure tunnel have been deleted
    Nov 2 06:33:44 krn: netflow_mtu_update ip:0 mtu:1450 src:0.
    Nov 2 06:33:44 krn: netflow_mtu_update set mtu:1450.
    Nov 2 06:33:44 krn: netflow_mtu_update: number_netflow_report_per_packet:12.
    Nov 2 06:33:44 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 287
    Nov 2 06:33:45 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 286
    Nov 2 06:33:46 iked: [info]: ike_sa.c:276: 1:172.17.227.11[4500] - 172.17.203.203[4500]:(nil):aborting ike_sa
    Nov 2 06:33:46 iked: [info]: ike_spmif.c:353: ipAddr cbcb11ac ctrl 0 ru_id 0 rc 13911
    Nov 2 06:33:46 iked: [info]: ike_spmif.c:384: 57360000ac11cbcb0000000001000000010000000301230a0014d8980002
    Nov 2 06:33:46 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 285
    Nov 2 06:33:47 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 284
    Nov 2 06:33:48 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 283
    Nov 2 06:33:49 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 282
    Nov 2 06:33:49 cap: SLPM: Finding RU managers for service='siemens'
    Nov 2 06:33:50 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 281
    Nov 2 06:33:51 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 280

    172.17.227.11 is the IP of the AP
    172.17.203.203 is the IP of the MGMT_Plane_Interface

    and later in the output I see:

    Nov 2 06:34:05 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 266
    Nov 2 06:34:06 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 265
    Nov 2 06:34:06 cap: RU_DISCOV: Decoding rcvd resp from 172.17.203.203, mode 3, plen 8
    Nov 2 06:34:06 cap: RU_DISCOV: Rcvd STANDBY resp from 172.17.203.203, standby time 1 secs
    Nov 2 06:34:06 cap: FAILED connection to AC_manager from 172.17.203.203
    Nov 2 06:34:07 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 264
    Nov 2 06:34:07 cap: 00841:ru_connect_to_ma.c:860-ru_discov_send_connect_req()- Attempting connection 2 to AC_manager 172.17.203.203 through IKE
    Nov 2 06:34:07 cap: 00841:ru_misc.c:594-ru_ikedReqHandler()-ru_ikedReqHandler: IKED opCode 525 tid 1 totalNumIp 0 ru_id -1
    Nov 2 06:34:07 iked: [info]: ike_spmif.c:296: Received message flush
    Nov 2 06:34:07 cap: 00841:ru_misc.c:356-ru_ikedRspRecv()-00000015000000010000020e0000000000000000
    Nov 2 06:34:07 cap: 00841:ru_misc.c:362-ru_ikedRspRecv()-0000000000000000000000000000000000000000
    Nov 2 06:34:07 cap: 00841:ru_misc.c:407-ru_ikedRspRecv()-ru_ikedRspRecv407: IKED tid 1 received response: 526 rc 0
    Nov 2 06:34:07 cap: 00841:ru_misc.c:296-ru_ikedRspHandler()-ru_ikedRspHandler: IKED All secure tunnel have been deleted
    Nov 2 06:34:07 cap: 00841:ru_misc.c:594-ru_ikedReqHandler()-ru_ikedReqHandler: IKED opCode 527 tid 1 totalNumIp 1 ru_id -1
    Nov 2 06:34:07 cap: 00841:ru_misc.c:596-ru_ikedReqHandler()- cbcb11ac
    Nov 2 06:34:07 cap: 00841:ru_misc.c:504-ru_addIkeIp()-IKED alloc 10 used 1 cbcb11ac(0)
    Nov 2 06:34:07 krn: updateMtuForFlowMgr: 3 callbacks suppressed
    Nov 2 06:34:07 krn: key_flush:2393 updateMtuForFlowMgr, wassp_sessionID:0.
    Nov 2 06:34:07 krn: netflow_mtu_update ip:0 mtu:1450 src:0.
    Nov 2 06:34:07 krn: netflow_mtu_update set mtu:1450.
    Nov 2 06:34:07 krn: netflow_mtu_update: number_netflow_report_per_packet:12.
    Nov 2 06:34:07 iked: [info]: ike_spmif.c:247: Received message init:1 -1 1 cbcb11ac
    Nov 2 06:34:07 iked: [info]: ikev2.c:1006: 2:172.17.227.11[500] - 172.17.203.203[500]:(nil):Adding pversion 1 information
    Nov 2 06:34:08 iked: [info]: ikev2.c:2086: 2:172.17.227.11[4500] - 172.17.203.203[4500]:(nil):Adding discovery information to AUTH
    Nov 2 06:34:08 iked: [PROTO_ERR]: ikev2_notify.c:647: received Notify payload protocol 0 type 13911
    Nov 2 06:34:08 iked: [info]: ikev2_notify.c:726: Received discovery information (48)
    Nov 2 06:34:08 iked: [PROTO_ERR]: ikev2.c:3183: 2:172.17.227.11[4500] - 172.17.203.203[4500]:0x1f6c020:message lacks IDr payload
    Nov 2 06:34:08 iked: [info]: ike_sa.c:276: 2:172.17.227.11[4500] - 172.17.203.203[4500]:(nil):aborting ike_sa
    Nov 2 06:34:08 iked: [info]: ike_pfkey.c:460: SADB_DELETE ul_proto=255 src=172.17.203.203[4500] dst=172.17.227.11[4500] satype=ESP spi=0x00000201
    Nov 2 06:34:08 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 263
    Nov 2 06:34:08 iked: [info]: ike_spmif.c:353: ipAddr cbcb11ac ctrl 0 ru_id 0 rc 13911
    Nov 2 06:34:08 iked: [info]: ike_spmif.c:384: 57360000ac11cbcb0000000001000000010000000301230a003059050002
    Nov 2 06:34:08 iked: [info]: ike_pfkey.c:700: received PFKEY_DELETE seq=0 satype=ESP spi=0x00000201
    Nov 2 06:34:08 cap: 00841:ru_misc.c:356-ru_ikedRspRecv()-0000001500000001000002100000000000000000
    Nov 2 06:34:08 cap: 00841:ru_misc.c:362-ru_ikedRspRecv()-0000000000000000000000000000000000000000
    Nov 2 06:34:08 cap: 00841:ru_misc.c:389-ru_ikedRspRecv()-ru_ikedRspRecv389: IKED tid 1 received response: 528 ip cbcb11ac rc 13911
    Nov 2 06:34:08 cap: 00841:ru_misc.c:518-ru_deleteIkeIp()-ru_deleteIkeIp: IKED delete cbcb11ac from ikedIpList
    Nov 2 06:34:08 cap: 00841:ru_misc.c:535-ru_deleteIkeIp()-ru_deleteIkeIp: IKED alloc 10 used 000841:ru_misc.c:539-ru_deleteIkeIp()-
    Nov 2 06:34:08 cap: 00841:ru_misc.c:794-ru_ike_discovery()-ru_ike_discovery: IKED request HWC cbcb11ac response HWC cbcb11ac
    Nov 2 06:34:08 cap: RU_DISCOV: Decoding rcvd resp from 172.17.203.203, mode 2, plen 36
    Nov 2 06:34:08 cap: RU_DISCOV: EID_SECURE_TUNNEL=0
    Nov 2 06:34:08 cap: SUCCESSFUL connection to AC_manager 172.17.203.203
    Nov 2 06:34:08 cap: 00841:ru_connect_to_ma.c:900-ru_discov_send_connect_req()-Accepted by AC 172.17.203.203 (ST=0)
    Nov 2 06:34:08 cap: 00841:ru_misc.c:594-ru_ikedReqHandler()-ru_ikedReqHandler: IKED opCode 525 tid 1 totalNumIp 0 ru_id -1
    Nov 2 06:34:08 iked: [info]: ike_spmif.c:296: Received message flush

    I interprete the "successful" message that controller and ap will be able to communicate.
    And if I try to login to the console port of the ap the default password will not work and I have to use the password configured in the controller for the admin account.

    And then:

    ov 2 06:34:08 cap: 00841:ru_misc.c:551-ru_flushIkeIp()-ru_flushIkeIp: IKED removing all ike IP
    Nov 2 06:34:08 cap: 00841:ru_misc.c:356-ru_ikedRspRecv()-00000015000000010000020e0000000000000000
    Nov 2 06:34:08 cap: 00841:ru_misc.c:362-ru_ikedRspRecv()-0000000000000000000000000000000000000000
    Nov 2 06:34:08 cap: 00841:ru_misc.c:407-ru_ikedRspRecv()-ru_ikedRspRecv407: IKED tid 1 received response: 526 rc 0
    Nov 2 06:34:08 cap: 00841:ru_misc.c:296-ru_ikedRspHandler()-ru_ikedRspHandler: IKED All secure tunnel have been deleted
    Nov 2 06:34:08 cap: get_next_step: stopping SLP thread...
    Nov 2 06:34:08 cap: m2MsgToDiscov: in_opcode 402, in_dstid 2, in_srcid 1
    Nov 2 06:34:08 cap: get_next_step: stopping DNS thread...
    Nov 2 06:34:08 cap: m2MsgToDiscov: in_opcode 402, in_dstid 3, in_srcid 1
    Nov 2 06:34:08 cap: STEP<6> (1/5) @ 0:36.000: Register & Authenticate with Access Controller,
    Nov 2 06:34:08 cap: ru_discov_main_dns: Got 402 msg
    Nov 2 06:34:08 cap: ru_discov_main_slp: Got 402 msg
    Nov 2 06:34:08 krn: netflow_mtu_update ip:0 mtu:1450 src:0.
    Nov 2 06:34:08 krn: netflow_mtu_update set mtu:1450.
    Nov 2 06:34:08 krn: netflow_mtu_update: number_netflow_report_per_packet:12.
    Nov 2 06:34:08 cap: 00841:ru_register.c:289-ru_register()-MaxRetryCnt 1 curIpIdx 0 curIpRetryCnt 0
    Nov 2 06:34:08 cap: 00841:ru_mgmt.c:3349-ru_disc_flush_m2pkts()-0 packets flushed
    Nov 2 06:34:08 cap: 00841:ru_register.c:111-ru_register_finish()-Attempting to Register with AC: 172.17.203.203 KEY: 1cafdf87964cbd4fdc041f56e48f020b
    Nov 2 06:34:09 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 262
    Nov 2 06:34:10 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 261
    Nov 2 06:34:11 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 260
    Nov 2 06:34:12 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 259
    Nov 2 06:34:13 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 258
    Nov 2 06:34:13 cap: 00841:ru_register.c:154-ru_register_finish()-sock=44, retval=0
    Nov 2 06:34:13 cap: 00841:ru_register.c:358-ru_register()-Failed to Register/Authenticate with AC at 172.17.203.203
    Nov 2 06:34:13 cap: Step<6>: Delay for 5000 mili seconds...
    Nov 2 06:34:14 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 257
    Nov 2 06:34:15 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 256
    Nov 2 06:34:16 cap: 00841:ru_mgmt.c:2883-whsl_trans()-S_EDISC 255

    The last few lines will be repeated until the AP reboots.

    I have searched here in the community and in the knowledge base and I found some helpfull informations how to configure the DHCP to use the option 78 (without this I saw that controller and AP will not communicate) but now I'm at the end of my knowledge.

    Any ideas or suggestions are welcome.

    Regards,
    Axel



  • 2.  RE: AP3915i will not become active but communicate with controller

    Posted 11-02-2018 10:01
    Hi,

    I have checked it this is happend with an AP3935i and this AP has no problem - so it looks like a general problem of the AP3515i, because I have tested it with two devices of the same type.

    Regards,
    Axel


  • 3.  RE: AP3915i will not become active but communicate with controller

    Posted 11-02-2018 10:26
    Axel,

    A quick way to get the AP up in running is to "force feed" the controller(s) IP.
    https://gtacknowledge.extremenetworks.com/articles/How_To/How-to-configure-controller-s-IP-in-the-AP

    John


  • 4.  RE: AP3915i will not become active but communicate with controller

    Posted 11-02-2018 11:14
    A common overlooked issue is the controller does not have its default route populated so the AP know the way to the controller but the controller doesn't know the way back. Controller, Network,routing protocols.


  • 5.  RE: AP3915i will not become active but communicate with controller

    Posted 11-02-2018 11:48
    Hi Craig,

    thanks a lot for the solution.

    I have add a static route for the network, where the AP resist and now it works.

    When I do sh traceroute from the controller I saw that it will use the wrong gateway.

    So adding a static route fix the problem.