MSM720 (APs:MSM410) : After firmware upgrade to 6.6.0 APs does not sync with the controller

[Maltyx]

MSM720 : After firmware upgrade to 6.6.0 (from 6.5.1)  APs do firmware upgrade but  does not sync with the controller and staying in infinitive loop in status - Resetting Configuration, Uploading configuration and so on ...

Controller Syslog is like follow:

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

Aug 26 08:11:33.002 debug statspoller [3C:D9:2B:7B:D1:1B]: Transfer of AP statistics information failed: (7/0)
Aug 26 08:11:32.534 debug maestro_sc [3C:D9:2B:7B:D1:5F] report: ready indication timeout
Aug 26 08:11:31.986 debug statspoller [3C:D9:2B:7B:D1:2D]: Transfer of AP statistics information failed: (7/0)
Aug 26 08:11:31.774 debug rccd Called soap_call_PROCURVE_MOBILITY_MSM__ExecuteConfigurationReset()
Aug 26 08:11:31.759 debug mapconf [3C:D9:2B:7B:D1:64] CFG_SYNC_FAILURE.
Aug 26 08:11:31.758 debug mapconf process <7733> terminated.
Aug 26 08:11:31.758 debug maestro_sc [3C:D9:2B:7B:D1:64] report: error doing full configuration (event)
Aug 26 08:11:31.531 err mapconf [3C:D9:2B:7B:D1:64] CONFIGURE_VSCS() failed, endpoint <http://169.254.0.4:7668/SOAP>
Aug 26 08:11:31.530 err mapconf [3C:D9:2B:7B:D1:64] CONFIGURE_VSC() failed for <http://169.254.0.4:7668/SOAP>, VSC <Ariel/1/1>.
Aug 26 08:11:31.530 err mapconf [3C:D9:2B:7B:D1:64] CONFIG_full_vsc_security() failed, VSC <Ariel/1/1>.
Aug 26 08:11:31.514 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateVirtualSCPSK()
Aug 26 08:11:31.490 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateVirtualSCWEP()
Aug 26 08:11:31.245 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateVirtualSCSSID()
Aug 26 08:11:31.049 info eventmgr EVENT[28557] Capabilities of AP (name='3C:D9:2B:7B:D1:5F') have been identified by the controller
Aug 26 08:11:31.044 info eventmgr EVENT[28556] AP (name='3C:D9:2B:7B:D1:2D') has restored its previous configuration settings
Aug 26 08:11:31.038 info eventmgr EVENT[28555] Controller is waiting for AP (name='3C:D9:2B:7B:D1:64') to send its configuration
Aug 26 08:11:31.033 info eventmgr EVENT[28554] Controller is waiting for AP (name='3C:D9:2B:7B:D1:2F') to send its software version number
Aug 26 08:11:31.027 info eventmgr EVENT[28553] Capabilities of AP (name='3C:D9:2B:7B:D1:2D') have been identified by the controller
Aug 26 08:11:31.020 info eventmgr EVENT[28552] Capabilities of AP (name='3C:D9:2B:7B:D1:55') have been identified by the controller
Aug 26 08:11:31.014 info eventmgr EVENT[28551] AP (name='3C:D9:2B:7B:D1:2F') requested to be managed by controller (name='2C:41:38:42:DF:F8')
Aug 26 08:11:31.006 info eventmgr EVENT[28550] AP (name='3C:D9:2B:7B:D1:2F') requested to be managed by controller (name='2C:41:38:42:DF:F8')
Aug 26 08:11:31.004 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateVirtualSCIngressType()
Aug 26 08:11:31.000 info eventmgr EVENT[28549] AP (name='3C:D9:2B:7B:D1:2F') requested to be managed by controller (name='2C:41:38:42:DF:F8')
Aug 26 08:11:30.982 debug statspoller [3C:D9:2B:7B:D1:5F] Starting polling AP at 169.254.0.10
Aug 26 08:11:30.982 debug statspoller [3C:D9:2B:7B:D1:1B]: Transfer of AP statistics information failed: (28/0)
Aug 26 08:11:30.777 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateVirtualSCLocationAware()
Aug 26 08:11:30.666 debug store-devic Client 'TW1BDLF017 (3C:D9:2B:7B:D1:2D)' skipped sending entries '46' to '-1'
Aug 26 08:11:30.654 debug store-devic Sending client 'TW1BDLF017 (3C:D9:2B:7B:D1:2D)' init '45'
Aug 26 08:11:30.653 info store-devic Forward server connected to client 'TW1BDLF017 (3C:D9:2B:7B:D1:2D)' at '169.254.0.7:35885'
Aug 26 08:11:30.525 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateVirtualSCEgressMapping()
Aug 26 08:11:30.307 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddVirtualSC()
Aug 26 08:11:30.257 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateRADIUSProfileServer()
Aug 26 08:11:30.246 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateRADIUSProfileServer()
Aug 26 08:11:30.140 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddRADIUSProfile()
Aug 26 08:11:29.991 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateDefaultNetwork()
Aug 26 08:11:29.982 info maestro_sc [3C:D9:2B:7B:D1:5F] MAP is now connected securely.
Aug 26 08:11:29.979 debug statspoller [3C:D9:2B:7B:D1:2D]: Transfer of AP statistics information failed: (7/0)
Aug 26 08:11:29.969 debug maestro_sc [3C:D9:2B:7B:D1:5F] (TW1BDLF02V) has IP address 169.254.0.10
Aug 26 08:11:29.945 debug openvpn 10.16.16.60:1194 [3C_D9_2B_7B_D1_5F] Peer Connection Initiated with 10.16.16.60:1194
Aug 26 08:11:29.933 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddNetworkProfile()
Aug 26 08:11:29.863 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateDefaultNetwork()
Aug 26 08:11:29.812 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddNetworkProfile()
Aug 26 08:11:29.774 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateDefaultNetwork()
Aug 26 08:11:29.733 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddNetworkProfile()
Aug 26 08:11:29.688 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateDefaultNetwork()
Aug 26 08:11:29.650 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddNetworkProfile()
Aug 26 08:11:29.456 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__AddMACList()
Aug 26 08:11:29.244 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__ExecuteCloseGlobalTransaction()
Aug 26 08:11:29.226 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateTimezoneRule()
Aug 26 08:11:29.208 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateTimezoneRule()
Aug 26 08:11:29.165 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__ExecuteOpenGlobalTransaction()
Aug 26 08:11:28.949 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateTimeServerMode()
Aug 26 08:11:28.934 debug store-devic Client 'TW1BDLF00N (3C:D9:2B:7B:D1:1B)' skipped sending entries '46' to '-1'
Aug 26 08:11:28.911 debug store-devic Sending client 'TW1BDLF00N (3C:D9:2B:7B:D1:1B)' init '45'
Aug 26 08:11:28.910 info store-devic Forward server connected to client 'TW1BDLF00N (3C:D9:2B:7B:D1:1B)' at '169.254.0.8:34774'
Aug 26 08:11:28.891 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateLocalLog()
Aug 26 08:11:28.740 debug mapconf Called soap_call_PROCURVE_MOBILITY_MSM__UpdateCoordinatedModeConfigRevision()
Aug 26 08:11:28.739 debug mapconf [3C:D9:2B:7B:D1:64] processing SYNCCONF_FULLCONFIG_LIST.
Aug 26 08:11:28.723 debug statspoller [3C:D9:2B:7B:D1:2D]: Transfer of AP statistics information failed: (7/0)
Aug 26 08:11:28.706 debug mapconf retrieved functional configuration identifier <0x0000003d>.
Aug 26 08:11:28.549 debug statspoller [3C:D9:2B:7B:D1:55] Starting polling AP at 169.254.0.9
Aug 26 08:11:28.547 debug statspoller [3C:D9:2B:7B:D1:2D] Starting polling AP at 169.254.0.7
Aug 26 08:11:27.971 debug openvpn 10.16.16.67:1194 Expected Remote Options hash (VER=V4): '7caec09b'
Aug 26 08:11:27.971 debug openvpn 10.16.16.67:1194 Local Options hash (VER=V4): '129af7cc'
Aug 26 08:11:27.970 debug openvpn 10.16.16.67:1194 Data Channel MTU parms [ L:1472 D:1450 EF:41 EB:4 ET:0 EL:0 ]
Aug 26 08:11:27.970 debug openvpn 10.16.16.67:1194 Control Channel MTU parms [ L:1472 D:166 EF:66 EB:0 ET:0 EL:0 ]
Aug 26 08:11:27.970 debug openvpn 10.16.16.67:1194 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1431)
Aug 26 08:11:27.969 debug openvpn 10.16.16.67:1194 Re-using SSL/TLS context
Aug 26 08:11:27.550 info maestro_sc [3C:D9:2B:7B:D1:2D] MAP is now connected securely.
Aug 26 08:11:27.545 debug maestro_sc [3C:D9:2B:7B:D1:2D] (TW1BDLF017) has IP address 169.254.0.7
Aug 26 08:11:27.515 debug openvpn 10.16.16.25:1194 [3C_D9_2B_7B_D1_2D] Peer Connection Initiated with 10.16.16.25:1194
Aug 26 08:11:27.499 info maestro_sc [3C:D9:2B:7B:D1:55] MAP is now connected securely.
Aug 26 08:11:27.485 debug maestro_sc [3C:D9:2B:7B:D1:55] (TW1BDLF02J) has IP address 169.254.0.9
Aug 26 08:11:27.463 debug openvpn 10.16.16.38:1194 [3C_D9_2B_7B_D1_55] Peer Connection Initiated with 10.16.16.38:1194
Aug 26 08:11:26.699 debug openvpn 10.16.16.38:1194 Expected Remote Options hash (VER=V4): '7caec09b'
Aug 26 08:11:26.699 debug openvpn 10.16.16.38:1194 Local Options hash (VER=V4): '129af7cc'
Aug 26 08:11:26.699 debug openvpn 10.16.16.38:1194 Data Channel MTU parms [ L:1472 D:1450 EF:41 EB:4 ET:0 EL:0 ]
Aug 26 08:11:26.698 debug openvpn 10.16.16.38:1194 Control Channel MTU parms [ L:1472 D:166 EF:66 EB:0 ET:0 EL:0 ]
Aug 26 08:11:26.698 debug openvpn 10.16.16.38:1194 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1431)
Aug 26 08:11:26.698 debug openvpn 10.16.16.38:1194 Re-using SSL/TLS context
Aug 26 08:11:26.597 info iappd_sc New AP added: uniqueid: 3c:d9:2b:7b:d1:64 ip: 169.254.0.4
Aug 26 08:11:26.571 info iappd_sc New AP added: uniqueid: 3c:d9:2b:7b:d1:1b ip: 169.254.0.8
Aug 26 08:11:26.450 debug mapconf [3C:D9:2B:7B:D1:2F] removing MAP upon maestro request.
Aug 26 08:11:26.438 debug mapconf [3C:D9:2B:7B:D1:2F] removing MAP upon maestro request.
Aug 26 08:11:26.424 debug mapconf [3C:D9:2B:7B:D1:2F] removing MAP upon maestro request.
Aug 26 08:11:26.418 debug statspoller [3C:D9:2B:7B:D1:64]: Transfer of AP statistics information failed: (7/0)
Aug 26 08:11:26.406 info eventmgr EVENT[28548] Controller is waiting for AP (name='3C:D9:2B:7B:D1:55') to send its software version number
Aug 26 08:11:26.400 info eventmgr EVENT[28547] AP (name='3C:D9:2B:7B:D1:55') requested to be managed by controller (name='2C:41:38:42:DF:F8')
Aug 26 08:11:26.394 info eventmgr EVENT[28546] AP (name='3C:D9:2B:7B:D1:55') requested to be managed by controller (name='2C:41:38:42:DF:F8')
Aug 26 08:11:26.389 info eventmgr EVENT[28545] AP (name='3C:D9:2B:7B:D1:55') requested to be managed by controller (name='2C:41:38:42:DF:F8')

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

the most weird part is like that:

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

Aug 26 08:11:28.723 debug statspoller [3C:D9:2B:7B:D1:2D]: Transfer of AP statistics information failed: (7/0)
Aug 26 08:11:28.706 debug mapconf retrieved functional configuration identifier <0x0000003d>.
Aug 26 08:11:28.549 debug statspoller [3C:D9:2B:7B:D1:55] Starting polling AP at 169.254.0.9
Aug 26 08:11:28.547 debug statspoller [3C:D9:2B:7B:D1:2D] Starting polling AP at 169.254.0.7
Aug 26 08:11:27.971 debug openvpn 10.16.16.67:1194 Expected Remote Options hash (VER=V4): '7caec09b'
Aug 26 08:11:27.971 debug openvpn 10.16.16.67:1194 Local Options hash (VER=V4): '129af7cc'
Aug 26 08:11:27.970 debug openvpn 10.16.16.67:1194 Data Channel MTU parms [ L:1472 D:1450 EF:41 EB:4 ET:0 EL:0 ]
Aug 26 08:11:27.970 debug openvpn 10.16.16.67:1194 Control Channel MTU parms [ L:1472 D:166 EF:66 EB:0 ET:0 EL:0 ]
Aug 26 08:11:27.970 debug openvpn 10.16.16.67:1194 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1431)
Aug 26 08:11:27.969 debug openvpn 10.16.16.67:1194 Re-using SSL/TLS context
Aug 26 08:11:27.550 info maestro_sc [3C:D9:2B:7B:D1:2D] MAP is now connected securely.
Aug 26 08:11:27.545 debug maestro_sc [3C:D9:2B:7B:D1:2D] (TW1BDLF017) has IP address 169.254.0.7
Aug 26 08:11:27.515 debug openvpn 10.16.16.25:1194 [3C_D9_2B_7B_D1_2D] Peer Connection Initiated with 10.16.16.25:1194

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

So the question is - why the controller is trying to connect an AP by IP like 169.254.0.x instead of the real AP's IP 10.16.16.25 ... and it fails at the end with errors like those:

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

ug 26 08:11:31.531 err mapconf [3C:D9:2B:7B:D1:64] CONFIGURE_VSCS() failed, endpoint <http://169.254.0.4:7668/SOAP>
Aug 26 08:11:31.530 err mapconf [3C:D9:2B:7B:D1:64] CONFIGURE_VSC() failed for <http://169.254.0.4:7668/SOAP>, VSC <Ariel/1/1>.

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

Any help is welcome.

Thanks.

[Arimo]

There's really nothing weird about this. There's a VPN tunnel between the controller and the APs, and 169.254 -addresses are used within the tunnel.

It looks to me like there's a somehow illegal VSC configuration which causes the APs to fail sync. The failure message is about security, which would refer to encryption. With this it's not possible to go further.

You didn't mention why you upgraded, but if you're trying to resolve a problem you could upgrade to another version. 6.5.3 contains a few fixes which aren't available on 6.6-branch yet, including one related to AP adoption.

So I'd suggest going to 6.5.3 instead. If you get the same problem with that, try first restoring one or two APs to factory defaults - if that works you have a way to fix this. If they still don't get adopted I'd suggest calling support.

[Maltyx]

Hi Arimo,

Thank You for your reply.

Well, the reason I upgraded the controller is just to get the new GUI (dashboard styled, very useless IMHO..), so prior to upgrade everything worked fine, and after applying the new FW 6.6.0 all APs did not succeed to sync after making AP's firmware ... Downgrade to my previous FW 5.5.1 and restoring the config (taken prior to upgrade) did not succeeded to restore my setup, also resetting MSM410 AP to factory default did not helped to sync it...

Finally, what I did, is reseting the controller to factory default (all APs then synced) and then setting up a new configuration for the system ... Dumb way, but I had no time to find out what was the reason for the post upgrading fault of APs.