AP3915i will not become active but communicate with controller

[ar1]

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

[ar1]

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.

[Craig_Guilmette]

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.

[Martineau__John]

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

[ar1]

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