CAPs not coming back up with Control Plane Security enabled after upgrading to 6.3.1.1

[eosuorah]

Opened up this thread for tracking the fix to this issue as Aruba TAC is currently looking into this. However, if anyone has experienced this issue, please share your fix.

Regards.

[cjoseph]

Eosuorah,

If you type "show log security 50" and show ap database, it might give you a clue what state the access points are in when they do not come up.  In addition, CPSEC requires new ports for access points to connect to the controller, and if your remote or local site is blocking this traffic, your access points will not come up:  

https://arubanetworkskb.secure.force.com/pkb/articles/FAQ/What-is-control-plane-security-How-does-one-configure-verify-it

https://arubanetworkskb.secure.force.com/pkb/articles/Troubleshooting/APs-are-continuously-rebooting

 Also make sure the ap-role has the correct ACLs:  https://arubanetworkskb.secure.force.com/pkb/articles/Troubleshooting/R-1205

[eosuorah]

---

cjoseph wrote:

Eosuorah,

If you type "show log security 50" and show ap database, it might give you a clue what state the access points are in when they do not come up.  In addition, CPSEC requires new ports for access points to connect to the controller, and if your remote or local site is blocking this traffic, your access points will not come up:  

https://arubanetworkskb.secure.force.com/pkb/articles/FAQ/What-is-control-plane-security-How-does-one-configure-verify-it

https://arubanetworkskb.secure.force.com/pkb/articles/Troubleshooting/APs-are-continuously-rebooting

 Also make sure the ap-role has the correct ACLs:  https://arubanetworkskb.secure.force.com/pkb/articles/Troubleshooting/R-1205

---

Regarding the ACLs, this applies to upgrades to AOS5.X and higher. My 620 Controller was already running AOS6.1. 

And regarding the CAPs and their states, I made sure they were already in an "approved-ready-for-cert" state and I tweaked between "switch cert" and "factory cert" and still doesn't work.

This is just so weird. This was all working before upgrading from 6.1 to 6.3.

[cjoseph]

But what is the output of "show ap database" when they refuse to come up?

What is the output of "show log system 50"?

The controller has to report why access points are not coming up and both of these commands give you a clue what is happening.

We cannot exactly replicate your environment, so we rely on you for clues as to why it is not coming up.  "It does not work, but it worked before" is a start, but we require additional information about the controller while this is happening.  If you cannot attempt it and give us the output of those commands, please wait until you can try to turn cpsec on, collect the output of those commands, and feed that back to us.  For now, we don't have any information to go on.

[eosuorah]

Been looking at the Logs and I don't see anything that helps me determine what the root cause is. See below:

(Aruba620BurlingtonMaster) #show log system 50

Nov 9 17:50:16 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:50:16 :304003:  <DBUG> |stm|  setup_hbt_tunnel: done S 192.168.100.61 D 192.168.221.133 A 0 Tun 0

Nov 9 17:50:16 :305025:  <DBUG> |stm|  sapm_clear_rejected_vap_list: AP MarkhamCAP radio -1: clearing

Nov 9 17:50:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:50:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:50:54 :305025:  <DBUG> |stm|  sapm_gap_get_changed_plan_info(1585): Running query SELECT UNIX_TIMESTAMP(MAX(modified_time)) FROM wms.sap_xg

Nov 9 17:50:54 :305025:  <DBUG> |stm|  sapm_gap_get_plan_delete_time(1412): Running query SELECT UNIX_TIMESTAMP(MAX(modified_time)) FROM wms.plan_info_updated

Nov 9 17:50:56 :303022:  <WARN> |AP BurlingtonCAP@192.168.100.200 nanny|  Reboot Reason: AP rebooted Sat Nov 9 17:49:54 EST 2013; SAPD: Rebooting after setting cert_cap=1. Need to open a secure channel(IPSEC) 

Nov 9 17:51:05 :305025:  <DBUG> |stm|  sapm_papi_rcv_cb: from 127.0.0.1:8235 to 8222 code 14001 length 359

Nov 9 17:51:05 :305025:  <DBUG> |stm|  sapm_ap_list_generate: Generating new AP list

Nov 9 17:51:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:51:19 :305025:  <DBUG> |stm|  sapm_papi_rcv_cb: from 127.0.0.1:8235 to 8222 code 14001 length 359

Nov 9 17:51:19 :305025:  <DBUG> |stm|  sapm_ap_list_generate: Using previously generated AP list

Nov 9 17:51:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:51:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:51:48 :305025:  <DBUG> |stm|  sapm_papi_rcv_cb: from 127.0.0.1:8226 to 8222 code 14001 length 105

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = discovery

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = igmp-join

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = igmp-vlan

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = rtcp-inactivity

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = alg-based-cac

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = sip-midcall-req-timeout

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = ap-blacklist-time

Nov 9 17:51:48 :304003:  <DBUG> |stm|  get_global_configuration called for key = flush-r1-on-new-r0

Nov 9 17:52:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:52:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:52:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:52:39 :399838:  <WARN> |nanny|  Resource 'Controlpath CPU' has exceeded  30%  threshold (actual:50%).

Nov 9 17:53:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:53:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:53:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:53:40 :399838:  <WARN> |nanny|  Resource 'Controlpath CPU' has dropped below  30%  threshold (actual:0%).

Nov 9 17:54:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:54:18 :305025:  <DBUG> |stm|  sapm_papi_rcv_cb: from 127.0.0.1:8235 to 8222 code 14001 length 211

Nov 9 17:54:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:54:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:55:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:55:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:55:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:55:54 :305025:  <DBUG> |stm|  sapm_gap_get_changed_plan_info(1585): Running query SELECT UNIX_TIMESTAMP(MAX(modified_time)) FROM wms.sap_xg

Nov 9 17:55:54 :305025:  <DBUG> |stm|  sapm_gap_get_plan_delete_time(1412): Running query SELECT UNIX_TIMESTAMP(MAX(modified_time)) FROM wms.plan_info_updated

Nov 9 17:56:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:56:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:56:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:57:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:57:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:57:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:58:05 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

Nov 9 17:58:19 :306502:  <DBUG> |stm|  Publish service 'stm-remote-node-license', object len 28

Nov 9 17:58:25 :337000:  <DBUG> |stm|  mon_mgr_update_thread_main: updateq empty. into conditional wait...

(Aruba620BurlingtonMaster) # show ap database

AP Database

-----------

Name           Group             AP Type  IP Address       Status  Flags  Switch IP       Standby IP

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

BurlingtonCAP  BurlingtonCampus  105      192.168.100.200  Down           192.168.100.61  0.0.0.0

MarkhamCAP     RAPOffice         105      192.168.221.133  Down           192.168.100.61  0.0.0.0

Flags: U = Unprovisioned; N = Duplicate name; G = No such group; L = Unlicensed

       I = Inactive; D = Dirty or no config; E = Regulatory Domain Mismatch

       X = Maintenance Mode; P = PPPoE AP; B = Built-in AP

       R = Remote AP; R- = Remote AP requires Auth; C = Cellular RAP;

       c = CERT-based RAP; 1 = 802.1x authenticated AP; 2 = Using IKE version 2

       u = Custom-Cert RAP; S = Standby-mode AP; J = USB cert at AP

       M = Mesh node; Y = Mesh Recovery

Total APs:2

(Aruba620BurlingtonMaster) #

[cjoseph]

I only see two access points, is that correct?

Do you have a firewall between the controller and those two sites?  If that is the case, you need to allow UDP 4500 as well as UDP 8209.  For the access points that will not come up do a "show datapath session table 192.168.100.200" and "show datapath session table 192.168.221.133" to see what traffic is being allowed to the controller.   From the message, the access point got the message that it needs to connect via IPSEC and that is the last message I see

"Nov 9 17:50:56 :303022:  <WARN> |AP BurlingtonCAP@192.168.100.200 nanny|  Reboot Reason: AP rebooted Sat Nov 9 17:49:54 EST 2013; SAPD: Rebooting after setting cert_cap=1. Need to open a secure channel(IPSEC) "

You might have to turn of some debugging because important messages are getting pushed because debugging is turned on.

[eosuorah]

---

cjoseph wrote:

I only see two access points, is that correct?

Do you have a firewall between the controller and those two sites?  If that is the case, you need to allow UDP 4500 as well as UDP 8209.  For the access points that will not come up do a "show datapath session table 192.168.100.200" and "show datapath session table 192.168.221.133" to see what traffic is being allowed to the controller.  

You might have to turn of some debugging because important messages are getting pushed because debugging is turned on.

---

Yes you are correct. And there isn't any Firewall from these Sites to the Controller. Besides the 192.168.100.200 is in the same Location as the Controller. And I see both APs attempting a session to the Controller. That's why I find this issue so weird. However see below:

(Aruba620BurlingtonMaster) #show datapath session 

Datapath Session Table Entries

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

Flags: F - fast age, S - src NAT, N - dest NAT

       D - deny, R - redirect, Y - no syn

       H - high prio, P - set prio, T - set ToS

       C - client, M - mirror, V - VOIP

       Q - Real-Time Quality analysis

       I - Deep inspect, U - Locally destined

       E - Media Deep Inspect, G - media signal

  Source IP     Destination IP  Prot SPort DPort  Cntr Prio ToS Age Destination TAge Packets   Bytes      Flags 

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

192.168.2.1     224.0.0.9       17   520   520    0/0     7 48  1   1/8         17   0         0          FC 

192.168.100.103 224.0.0.5       89   0     0      0/0     0 48  0   1/8         47   0         0          FC 

192.168.100.61  192.168.102.130 6    22    60437  0/0     0 4   0   1/8         84f  0         0           

192.168.100.3   224.0.0.5       89   0     0      0/0     0 48  0   1/8         4e   0         0          FC 

192.168.100.4   224.0.0.5       89   0     0      0/0     0 48  0   1/8         4a   0         0          FC 

192.168.101.1   224.0.0.5       89   0     0      0/0     7 48  0   1/8         46   0         0          FC 

192.168.101.1   224.0.0.9       17   520   520    0/0     7 48  1   1/8         17   0         0          FC 

192.168.100.103 224.0.0.9       17   520   520    0/0     0 48  1   1/8         17   0         0          FC 

192.168.100.61  192.168.221.133 17   4500  4500   0/0     0 0   27  1/8         1c2  0         0          FY 

192.168.101.255 192.168.101.75  17   37    1030   0/0     0 0   5   1/8         4b   0         0          FY 

192.168.100.92  192.168.100.255 17   138   138    0/0     0 0   0   1/8         4    0         0          FC 

192.168.100.255 192.168.100.92  17   138   138    0/0     0 0   0   1/8         4    0         0          FY 

192.168.101.75  192.168.101.255 17   1030  37     0/0     0 0   1   1/8         4b   0         0          FC 

192.168.221.133 192.168.100.61  17   4500  4500   0/0     0 0   0   1/8         1c2  0         0          FC 

192.168.100.61  99.227.188.4    17   4500  49623  0/0     0 0   1   1/8         c    0         0          FY 

192.168.100.200 192.168.100.61  17   4500  4500   0/0     0 0   1   1/8         10   0         0          FC 

99.227.188.4    192.168.100.61  17   49623 4500   0/0     0 0   1   1/8         c    0         0          FC 

192.168.100.61  192.168.100.200 17   4500  4500   0/0     0 0   1   1/8         10   0         0          FY 

192.168.102.130 192.168.100.61  6    60437 22     0/0     0 4   0   1/8         84f  0         0          C 

(Aruba620BurlingtonMaster) #

[cjoseph]

We also need to output of "show log system 100" and "show log security 100" as well as "show crypto ipsec sa"

[eosuorah]

---

cjoseph wrote:

We also need to output of "show log system 100" and "show log security 100" as well as "show crypto ipsec sa"

---

Attached herein.

[cjoseph]

What ip address is 192.168.100.61?  If that is the controller, what VLAN is that?  Is that the controller's switchip (type "show switchinfo")?