AP do not join WLC

[stefan.wagner]

Hi , i have the problem that one AP in one location doesnt join the WLC.

i checked DHCP scope options , time on WLC and AP etc.

I also check all this issues:

http://www.cisco.com/en/US/products/ps6366/products_tech_note09186a00808f8599.shtml

I only see an DTLS error

debug AP

*Oct 24 08:23:02.307: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to up

*Oct 24 08:23:02.332: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio1, changed state to up

*Oct 24 08:23:10.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10.X.X:X peer_port: 5246

*Oct 24 08:23:10.000: %CAPWAP-5-CHANGED: CAPWAP changed state to

*Oct 24 08:23:40.198: DTLS_CLIENT_ERROR: ../dtls/dtls_connection_db.c:2017 Max retransmission count reached!

*Oct 24 08:23:40.198: %DTLS-3-HANDSHAKE_RETRANSMIT: Max retransmit count for 10.X.X:X is reached.

*Oct 24 08:24:10.051: %DTLS-5-SEND_ALERT: Send FATAL : Close notify Alert to 10.X.X.X:5246

debug:

*spamReceiveTask: Oct 24 08:54:53.308: 0c:85:25:30:14:20 DTLS connection closed event receivedserver (10.X:X:X/5246) client (10.X:X:X/4270)
*spamReceiveTask: Oct 24 08:54:53.308: 0c:85:25:30:14:20 No entry exists for AP (10.X:X:X/4270)
*spamReceiveTask: Oct 24 08:54:53.308: 0c:85:25:30:14:20 No AP entry exist in temporary database for 10.X:X:X:4270
*spamReceiveTask: Oct 24 08:54:53.443: 0c:85:25:30:14:20 Discovery Request from 10.X:X:X:4271

*spamReceiveTask: Oct 24 08:54:53.443: 0c:85:25:30:14:20 Join Priority Processing status = 0, Incoming Ap's Priority 1, MaxLrads = 25, joined Aps =1
*spamReceiveTask: Oct 24 08:54:53.443: 0c:85:25:30:14:20 Discovery Response sent to 10.X:X:X:4271

*spamReceiveTask: Oct 24 08:55:03.378: 0c:85:25:30:14:20 DTLS connection not found, creating new connection for 10.X:X:X (4271) 10.X:X:X (5246)

*spamReceiveTask: Oct 24 08:55:03.378: sshpmGetCID: called to evaluate <cscoDefaultIdCert>

I wanne find out if, for this location it is an provider problem (WAN)

Have someone else such a problem ?

best regards

[stefan.wagner]

Hi ... the AP had worked before on another location ... same provider ans same lan setup .....
i believe it`s an provider problem .

best regards

[asawasth]

this is a packet reassembly issue as highlighted by sarvanan. You could be hitting teh following defect:

CSCuo35247.

[Leo Laohoo]

Try these commands on the WAP:

1.  clear capwap private

2.  clear capwap ap controller ip address

3.  REBOOT

4.  Post the entire bootup process again.

[stefan.wagner]

Here the output during reboot:

WRDTR,CLKTR: 0x88000800 0x00000000
RQDC ,RFDC : 0x80000033 0x00000259

ddr init done

Running Normal Memtest...
Passed.
IOS Bootloader - Starting system.
FLASH CHIP:  Numonyx P33
Checking for Over Erased blocks
......................................................................................................................................................................................................................................................
Xmodem file system is available.

DDR values used from system serial eeprom.
WRDTR,CLKTR: 0x88000800, 0x00000000
RQDC, RFDC : 0x80000033, 0x00000259

PCIE0: link is up.
PCIE0: VC0 is active
PCIE1: link is up.
PCIE1: VC0 is active
64bit PCIE devices
PCIEx: initialization done
flashfs[0]: 35 files, 8 directories
flashfs[0]: 0 orphaned files, 0 orphaned directories
flashfs[0]: Total bytes: 31739904
flashfs[0]: Bytes used: 8308736
flashfs[0]: Bytes available: 23431168
flashfs[0]: flashfs fsck took 14 seconds.
Reading cookie from system serial eeprom...Done
Base Ethernet MAC address: 28:94:0f:01:0a:d8
Ethernet speed is 100 Mb - FULL duplex
Loading "flash:/ap3g1-k9w8-mx.124-23c.JA5/ap3g1-k9w8-mx.124-23c.JA5"...##############################################################################################################################################################################################################################################################################################################################################################################################################################################################################

File "flash:/ap3g1-k9w8-mx.124-23c.JA5/ap3g1-k9w8-mx.124-23c.JA5" uncompressed and installed, entry point: 0x4000
executing...
enet halted

              Restricted Rights Legend

Use, duplication, or disclosure by the Government is
subject to restrictions as set forth in subparagraph
(c) of the Commercial Computer Software - Restricted
Rights clause at FAR sec. 52.227-19 and subparagraph
(c) (1) (ii) of the Rights in Technical Data and Computer
Software clause at DFARS sec. 252.227-7013.

           cisco Systems, Inc.
           170 West Tasman Drive
           San Jose, California 95134-1706

Cisco IOS Software, C3500 Software (AP3G1-K9W8-M), Version 12.4(23c)JA5, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2012 by Cisco Systems, Inc.
Compiled Mon 30-Apr-12 13:30 by prod_rel_team

Proceeding with system init

Proceeding to unmask interrupts
Initializing flashfs...
FLASH CHIP:  Numonyx P33
Checking for Over Erased blocks
......................................................................................................................................................................................................................................................

flashfs[1]: 35 files, 8 directories
flashfs[1]: 0 orphaned files, 0 orphaned directories
flashfs[1]: Total bytes: 31481856
flashfs[1]: Bytes used: 8308736
flashfs[1]: Bytes available: 23173120
flashfs[1]: flashfs fsck took 7 seconds.
flashfs[1]: Initialization complete.
flashfs[2]: 0 files, 1 directories
flashfs[2]: 0 orphaned files, 0 orphaned directories
flashfs[2]: Total bytes: 11999232
flashfs[2]: Bytes used: 1024
flashfs[2]: Bytes available: 11998208
flashfs[2]: flashfs fsck took 1 seconds.
flashfs[2]: Initialization complete....done Initializing flashfs.

Ethernet speed is 100 Mb - FULL duplex

Radio0  present 8364B 8000 B8020000 0 B8030000 10
Radio1  present 8364B 8000 B0020000 0 B0030000 C
This product contains cryptographic features and is subject to United
States and local country laws governing import, export, transfer and
use. Delivery of Cisco cryptographic products does not imply
third-party authority to import, export, distribute or use encryption.
Importers, exporters, distributors and users are responsible for
compliance with U.S. and local country laws. By using this product you
agree to comply with applicable laws and regulations. If you are unable
to comply with U.S. and local laws, return this product immediately.

A summary of U.S. laws governing Cisco cryptographic products may be found at:
http://www.cisco.com/wwl/export/crypto/tool/stqrg.html

If you require further assistance please contact us by sending email to
export@cisco.com.

cisco AIR-CAP3502I-E-K9    (PowerPC460exr) processor (revision A0) with 81910K/49152K bytes of memory.
Processor board ID FCZ1603W4NP
PowerPC460exr CPU at 666Mhz, revision number 0x18A8
Last reset from reload
LWAPP image version 7.0.235.0
1 Gigabit Ethernet interface
2 802.11 Radio(s)

32K bytes of flash-simulated non-volatile configuration memory.
Base ethernet MAC Address: 28:94:0F:01:0A:D8
Part Number                          : 73-12175-05
PCA Assembly Number                  : 800-32268-05
PCA Revision Number                  : A0
PCB Serial Number                    : FOC1544345G
Top Assembly Part Number             : 800-32891-01
Top Assembly Serial Number           : FCZ1603W4NP
Top Revision Number                  : A0
Product/Model Number                 : AIR-CAP3502I-E-K9
% Please define a domain-name first.

Press RETURN to get started!

*Mar  1 00:00:09.531: %SOAP_FIPS-2-SELF_TEST_IOS_SUCCESS: IOS crypto FIPS self test passed
*Mar  1 00:00:09.537: *** CRASH_LOG = YES

*Mar  1 00:00:09.537: 64bit PCIE devicesSecurity Core found.
Base Ethernet MAC address: 28:94:0F:01:0A:D8

*Mar  1 00:00:12.378: %LINK-3-UPDOWN: Interface GigabitEthernet0, changed state to up
*Mar  1 00:00:13.177: %SOAP_FIPS-2-SELF_TEST_RAD_SUCCESS: RADIO crypto FIPS self test passed on interface Dot11Radio 0
*Mar  1 00:00:13.410: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0, changed state to up
*Mar  1 00:00:15.867: %SOAP_FIPS-2-SELF_TEST_RAD_SUCCESS: RADIO crypto FIPS self test passed on interface Dot11Radio 1
*Mar  1 00:00:15.917: %LWAPP-3-CLIENTEVENTLOG: Read and initialized AP event log (contains, 1037 messages)

*Mar  1 00:00:15.929:  status of voice_diag_test from WLC is false
*Mar  1 00:00:18.028: %SYS-5-RESTART: System restarted --
Cisco IOS Software, C3500 Software (AP3G1-K9W8-M), Version 12.4(23c)JA5, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2012 by Cisco Systems, Inc.
Compiled Mon 30-Apr-12 13:30 by prod_rel_team
*Mar  1 00:00:18.028: %SNMP-5-COLDSTART: SNMP agent on host ap is undergoing a cold start
*Mar  1 00:13:19.034: %CAPWAP-5-CHANGED: CAPWAP changed state to DISCOVERY
*Mar  1 00:13:19.050: %LINK-5-CHANGED: Interface Dot11Radio1, changed state to reset
*Mar  1 00:13:19.050: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to reset
*Mar  1 00:13:19.223: %SSH-5-ENABLED: SSH 2.0 has been enabled
*Mar  1 00:13:19.972: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0, changed state to up
*Mar  1 00:13:20.050: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio1, changed state to down
*Mar  1 00:13:20.050: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to down
*Mar  1 00:13:27.194: %DHCP-6-ADDRESS_ASSIGN: Interface GigabitEthernet0 assigned DHCP address 10.127.76.5, mask 255.255.255.0, hostname AP2894.0f01.0ad8

*Mar  1 00:13:37.940:  status of voice_diag_test from WLC is false
*Mar  1 00:13:38.003: Logging LWAPP message to 255.255.255.255.

Translating "CISCO-CAPWAP-CONTROLLER.test.net"...domain server (10.X.X.X)
*Mar  1 00:13:49.022: %CAPWAP-5-DHCP_OPTION_43: Controller address 10..X.X.X obtained through DHCP (10..X.X.X) [OK]

*Oct 26 07:03:15.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10..X.X.X peer_port: 5246
*Oct 26 07:03:15.000: %CAPWAP-5-CHANGED: CAPWAP changed state to
*Oct 26 07:03:27.570: %CDP_PD-4-POWER_OK: Full power - NON_CISCO-NO_CDP_RECEIVED inline power source
*Oct 26 07:03:27.661: %LINK-3-UPDOWN: Interface Dot11Radio1, changed state to up
*Oct 26 07:03:27.755: %LINK-3-UPDOWN: Interface Dot11Radio0, changed state to up
*Oct 26 07:03:28.580: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio1, changed state to up
*Oct 26 07:03:28.580: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 255.255.255.255 started - CLI initiated
*Oct 26 07:03:28.674: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to up
*Oct 26 07:03:45.180: DTLS_CLIENT_ERROR: ../dtls/dtls_connection_db.c:2017 Max retransmission count reached!
*Oct 26 07:03:45.180: %DTLS-3-HANDSHAKE_RETRANSMIT: Max retransmit count for 10..X.X.X is reached.
*Oct 26 07:04:15.051: %DTLS-5-SEND_ALERT: Send FATAL : Close notify Alert to 10.X.X.X:5246
*Oct 26 07:04:15.105: %CAPWAP-5-CHANGED: CAPWAP changed state to DISCOVERY
*Oct 26 07:04:15.105: %CAPWAP-5-CHANGED: CAPWAP changed state to DISCOVERY
*Oct 26 07:04:15.168: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to administratively down
*Oct 26 07:04:15.168: %LINK-5-CHANGED: Interface Dot11Radio1, changed state to administratively down
*Oct 26 07:04:15.177: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to reset
*Oct 26 07:04:15.187:  status of voice_diag_test from WLC is false
*Oct 26 07:04:15.187: %LINK-3-UPDOWN: Interface Dot11Radio1, changed state to up
*Oct 26 07:04:15.196: %LINK-3-UPDOWN: Interface Dot11Radio0, changed state to up
*Oct 26 07:04:15.206: %LINK-5-CHANGED: Interface Dot11Radio1, changed state to reset
*Oct 26 07:04:25.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10.X.X.X peer_port: 5246
*Oct 26 07:04:25.000: %CAPWAP-5-CHANGED: CAPWAP changed state to
*Oct 26 07:04:55.176: DTLS_CLIENT_ERROR: ../dtls/dtls_connection_db.c:2017 Max retransmission count reached!
*Oct 26 07:04:55.176: %DTLS-3-HANDSHAKE_RETRANSMIT: Max retransmit count for 10.X.X.X is reached.
*Oct 26 07:05:25.051: %DTLS-5-SEND_ALERT: Send FATAL : Close notify Alert to 10.X.X.X:5246
*Oct 26 07:05:25.105: %CAPWAP-5-CHANGED: CAPWAP changed state to DISCOVERY
*Oct 26 07:05:25.105: %CAPWAP-5-CHANGED: CAPWAP changed state to DISCOVERY
*Oct 26 07:05:25.165: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to administratively down
*Oct 26 07:05:25.165: %LINK-5-CHANGED: Interface Dot11Radio1, changed state to administratively down
*Oct 26 07:05:25.174: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to reset
*Oct 26 07:05:25.184:  status of voice_diag_test from WLC is false
*Oct 26 07:05:25.184: %LINK-3-UPDOWN: Interface Dot11Radio1, changed state to up
*Oct 26 07:05:25.193: %LINK-3-UPDOWN: Interface Dot11Radio0, changed state to up
*Oct 26 07:05:25.202: %LINK-5-CHANGED: Interface Dot11Radio1, changed state to reset
*Oct 26 07:05:25.218: %LINK-3-UPDOWN: Interface Dot11Radio1, changed s

[Bruno Gri]

Hello,

I'm having the exact same issue described at the top of this thread. Unfortunately, I was not able to fix it by issuing the command: "capwap ap controller ip address ". Any ideas of what can be affecting the DTLS handshake betwen the AP and the controller?

I have attached the debug dtls client detail where shows exaclty when is breaking.

[Leo Laohoo]

Hi Bruno,

Please provide the following output:

1.  WLC:  sh sysinfo;

2.  AP:  sh version;

3.  AP:  sh inventory; and

4.  Console into the AP and reboot.  Post the entire bootup process.

[Bruno Gri]

Hello,

Here is the info:

1) WLC, sh sysinfo:

Manufacturer's Name.............................. Cisco Systems Inc.

Product Name..................................... Cisco Controller

Product Version.................................. 7.0.230.0

Bootloader Version............................... 1.0.1

Field Recovery Image Version..................... 6.0.182.0

Firmware Version................................. FPGA 1.3, Env 1.6, USB console 1.27

Build Type....................................... DATA + WPS

System Name...................................... WLC5508_1

System Location..................................

System Contact...................................

System ObjectID.................................. 1.3.6.1.4.1.9.1.1069

IP Address....................................... 10.143.254.253

Last Reset....................................... Software reset

System Up Time................................... 57 days 18 hrs 27 mins 8 secs

System Timezone Location......................... (GMT -6:00) Central Time (US and Canada)

Current Boot License Level....................... base

Current Boot License Type........................ Permanent

Next Boot License Level.......................... base

Next Boot License Type........................... Permanent

Configured Country............................... US  - United States

--More-- or (q)uit

Operating Environment............................ Commercial (0 to 40 C)

Internal Temp Alarm Limits....................... 0 to 65 C

Internal Temperature............................. +39 C

External Temperature............................. +26 C

Fan Status....................................... OK

State of 802.11b Network......................... Enabled

State of 802.11a Network......................... Enabled

Number of WLANs.................................. 6

Number of Active Clients......................... 510

Burned-in MAC Address............................ 68:EF:BD:93:87:40

Power Supply 1................................... Present, OK

Power Supply 2................................... Present, OK

Maximum number of APs supported.................. 350

2) AP, sh version

CC233-3#show version

Cisco IOS Software, C1140 Software (C1140-RCVK9W8-M), Version 12.4(21a)JX, RELEASE SOFTWARE (fc1)

Technical Support: http://www.cisco.com/techsupport

Copyright (c) 1986-2009 by Cisco Systems, Inc.

Compiled Mon 27-Apr-09 15:34 by prod_rel_team

ROM: Bootstrap program is C1140 boot loader

BOOTLDR: C1140 Boot Loader (C1140-BOOT-M) Version 12.4(23c)JA, RELEASE SOFTWARE (fc3)

CC233-3 uptime is 0 minutes

System returned to ROM by power-on

System image file is "flash:/c1140-rcvk9w8-mx/c1140-rcvk9w8-mx"

This product contains cryptographic features and is subject to United

States and local country laws governing import, export, transfer and

use. Delivery of Cisco cryptographic products does not imply

third-party authority to import, export, distribute or use encryption.

Importers, exporters, distributors and users are responsible for

compliance with U.S. and local country laws. By using this product you

agree to comply with applicable laws and regulations. If you are unable

to comply with U.S. and local laws, return this product immediately.

A summary of U.S. laws governing Cisco cryptographic products may be found at:

http://www.cisco.com/wwl/export/crypto/tool/stqrg.html

If you require further assistance please contact us by sending email to

export@cisco.com.

cisco AIR-LAP1142N-A-K9    (PowerPC405ex) processor (revision A0) with 98294K/32768K bytes of memory.

Processor board ID FTX1453E17H

PowerPC405ex CPU at 586Mhz, revision number 0x147E

Last reset from power-on

LWAPP image version 3.0.51.0

1 Gigabit Ethernet interface

32K bytes of flash-simulated non-volatile configuration memory.

Base ethernet MAC Address: 1C:DF:0F:95:AA:34

Part Number                          : 73-12836-01

PCA Assembly Number                  : 800-33767-01

PCA Revision Number                  : A0

PCB Serial Number                    : FOC14513NHY

Top Assembly Part Number             : 800-33775-01

Top Assembly Serial Number           : FTX1453E17H

Top Revision Number                  : A0

Product/Model Number                 : AIR-LAP1142N-A-K9

Configuration register is 0xF

3) AP, sh inventory: doesn't show anything

4) AP boot process:

using  eeprom values

WRDTR,CLKTR: 0x84000800 0x40000000

RQDC ,RFDC : 0x80000038 0x0000020e

ddr init done

Running Normal Memtest...

Passed.

IOS Bootloader - Starting system.

FLASH CHIP:  Numonyx P33

Checking for Over Erased blocks

......................................................................................................................................................................................................................................................

Xmodem file system is available.

DDR values used from system serial eeprom.

WRDTR,CLKTR: 0x84000800, 0x40000000

RQDC, RFDC : 0x80000038, 0x0000020e

PCIE0: link is up.

PCIE0: VC0 is active

PCIE1: link is up.

PCIE1: VC0 is active

PCIEx: initialization done

flashfs[0]: 8 files, 4 directories

flashfs[0]: 0 orphaned files, 0 orphaned directories

flashfs[0]: Total bytes: 32385024

flashfs[0]: Bytes used: 2381824

flashfs[0]: Bytes available: 30003200

flashfs[0]: flashfs fsck took 18 seconds.

Reading cookie from system serial eeprom...Done

Base Ethernet MAC address: 1c:df:0f:95:aa:34

Ethernet speed is 100 Mb - FULL duplex

Loading "flash:/c1140-rcvk9w8-mx/c1140-rcvk9w8-mx"...#########################################################################################################################################################################################################################

File "flash:/c1140-rcvk9w8-mx/c1140-rcvk9w8-mx" uncompressed and installed, entry point: 0x4000

executing...

enet halted

              Restricted Rights Legend

Use, duplication, or disclosure by the Government is

subject to restrictions as set forth in subparagraph

(c) of the Commercial Computer Software - Restricted

Rights clause at FAR sec. 52.227-19 and subparagraph

(c) (1) (ii) of the Rights in Technical Data and Computer

Software clause at DFARS sec. 252.227-7013.

           cisco Systems, Inc.

           170 West Tasman Drive

           San Jose, California 95134-1706

Cisco IOS Software, C1140 Software (C1140-RCVK9W8-M), Version 12.4(21a)JX, RELEASE SOFTWARE (fc1)

Technical Support: http://www.cisco.com/techsupport

Copyright (c) 1986-2009 by Cisco Systems, Inc.

Compiled Mon 27-Apr-09 15:34 by prod_rel_team

Proceeding with system init

Proceeding to unmask interrupts

Initializing flashfs...

flashfs[1]: 8 files, 4 directories

flashfs[1]: 0 orphaned files, 0 orphaned directories

flashfs[1]: Total bytes: 32385024

flashfs[1]: Bytes used: 2381824

flashfs[1]: Bytes available: 30003200

flashfs[1]: flashfs fsck took 4 seconds.

flashfs[1]: Initialization complete....done Initializing flashfs.

Ethernet speed is 100 Mb - FULL duplex

This product contains cryptographic features and is subject to United

States and local country laws governing import, export, transfer and

use. Delivery of Cisco cryptographic products does not imply

third-party authority to import, export, distribute or use encryption.

Importers, exporters, distributors and users are responsible for

compliance with U.S. and local country laws. By using this product you

agree to comply with applicable laws and regulations. If you are unable

to comply with U.S. and local laws, return this product immediately.

A summary of U.S. laws governing Cisco cryptographic products may be found at:

http://www.cisco.com/wwl/export/crypto/tool/stqrg.html

If you require further assistance please contact us by sending email to

export@cisco.com.

cisco AIR-LAP1142N-A-K9    (PowerPC405ex) processor (revision A0) with 98294K/32768K bytes of memory.

Processor board ID FTX1453E17H

PowerPC405ex CPU at 586Mhz, revision number 0x147E

Last reset from power-on

LWAPP image version 3.0.51.0

1 Gigabit Ethernet interface

32K bytes of flash-simulated non-volatile configuration memory.

Base ethernet MAC Address: 1C:DF:0F:95:AA:34

Part Number                          : 73-12836-01

PCA Assembly Number                  : 800-33767-01

PCA Revision Number                  : A0

PCB Serial Number                    : FOC14513NHY

Top Assembly Part Number             : 800-33775-01

Top Assembly Serial Number           : FTX1453E17H

Top Revision Number                  : A0

Product/Model Number                 : AIR-LAP1142N-A-K9  

% Please define a domain-name first.

Press RETURN to get started!

*Mar  1 00:00:05.916: *** CRASH_LOG = YES

Base Ethernet MAC address: 1C:DF:0F:95:AA:34

*Mar  1 00:00:06.120: %LWAPP-3-CLIENTEVENTLOG: Read and initialized AP event log (contains, 1024 messages)

*Mar  1 00:00:08.182: %LINK-3-UPDOWN: Interface GigabitEthernet0, changed state to up

*Mar  1 00:00:08.213: %SYS-5-RESTART: System restarted --

Cisco IOS Software, C1140 Software (C1140-RCVK9W8-M), Version 12.4(21a)JX, RELEASE SOFTWARE (fc1)

Technical Support: http://www.cisco.com/techsupport

Copyright (c) 1986-2009 by Cisco Systems, Inc.

Compiled Mon 27-Apr-09 15:34 by prod_rel_team

*Mar  1 00:27:33.010: %CAPWAP-5-CHANGED: CAPWAP changed state to DISCOVERY

*Mar  1 00:27:33.968: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0, changed state to up

*Mar  1 00:27:41.580: %DHCP-6-ADDRESS_ASSIGN: Interface GigabitEthernet0 assigned DHCP address 10.0.233.204, mask 255.255.255.192, hostname CC233-3

*Mar  1 00:27:56.404: %CDP_PD-2-POWER_LOW: All radios disabled - NEGOTIATED WS-C2960-24PC-L (2c3f.3863.2e14)

Translating "CISCO-CAPWAP-CONTROLLER.cc.int"...domain server (10.143.254.250) [OK]

Translating "CISCO-LWAPP-CONTROLLER.cc.int"...domain server (10.143.254.250)

*Mar  1 00:28:02.937: %CAPWAP-3-ERRORLOG: Did not get log server settings from DHCP.

*Mar  1 00:28:03.257: %CAPWAP-3-ERRORLOG: Could Not resolve CISCO-LWAPP-CONTROLLER.cc.int

*Mar  1 00:28:13.258: %CAPWAP-3-ERRORLOG: Go join a capwap controller

*Jan 30 22:19:14.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10.143.254.253 peer_port: 5246

*Jan 30 22:19:14.000: %CAPWAP-5-CHANGED: CAPWAP changed state to 

[Leo Laohoo]

IP Address....................................... 10.143.254.253

Management IP Address of your WLC.

Translating "CISCO-CAPWAP-CONTROLLER.cc.int"...domain server (10.143.254.250) [OK]
Translating "CISCO-LWAPP-CONTROLLER.cc.int"...domain server (10.143.254.250)

Your DNS is configured incorrectly.

Console into the AP and enter the command:  capwap ap controller ip address 10.143.254.253

[Bruno Gri]

I see what you are saying but 10.143.254.250 is our internal DNS which is resolving CISCO-CAPWAP-CONTROLLER to both of my WLC's, 10.143.254.253 and 10.143.254.254.

The AP's are able to find both WLC's with no problem, the issue is that once they find it, they can't complete the DTLS handshake properly as it is shown in the following debug dtls client event detail:

Jan 30 16:10:27.043: DTLS_CLIENT_EVENT: dtls_disconnect: Disconnecting DTLS connection 0x0106B2D8

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_free_connection: Called... for connection 0x0106B2D8

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_send_Alert: Called...

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT: dtls_send_Alert: Sending FATAL : Close notify Alert

*Jan 30 16:10:27.043: %DTLS-5-SEND_ALERT: Send FATAL : Close notify Alert to 10.143.254.253:5246

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 30 16:10:27.044: DTLS_CLIENT_EVENT: wtpDtlsCallback: DTLS-Ctrl Connection 0x0106B2D8 closed

*Jan 30 16:10:27.044: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 30 16:10:27.044: DTLS_CLIENT_EVENT: dtls_free_connection: Done... for connection 0x0106B2D8

*Jan 30 16:09:27.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10.143.254.253 peer_port: 5246

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_inc_ref_count: Secret reference count= 2

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_delete: Secret not deleted, reference count = 1

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_send_ClientHello: Called...

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_send_handshake_msg: Called...

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 30 16:09:27.000: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 30 16:09:27.249: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0276BB38

066D46C0:                   16FEFF00 00000000          .~......

066D46D0: 00000000 2F030000 23000000 00000000  ..../...#.......

066D46E0: 23FEFF20 0A00E9CD 5AC11234 56789ABC  #~. ..iMZA.4Vx.<

066D46F0: 49623895 65565B89 4FC53D11 2340A364  Ib8.eV[.OE=.#@#d

066D4700: B6970C60                             6..`           

*Jan 30 16:09:27.249: DTLS_CLIENT_EVENT: dtls_process_HelloVerifyRequest: Processing...

*Jan 30 16:09:27.249: DTLS_CLIENT_EVENT_DETAIL: dtls_send_ClientHello: Called...

*Jan 30 16:09:27.250: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 30 16:09:27.250: DTLS_CLIENT_EVENT_DETAIL: dtls_send_handshake_msg: Called...

*Jan 30 16:09:27.250: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 30 16:09:27.250: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 30 16:09:27.250: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 30 16:09:27.380: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0276BB38

0672A5F0: 16FEFF00 00000000 00000100 52020000  .~..........R...

0672A600: 46000100 00000000 46FEFF51 0945FD41  F.......F~.Q.E}A

0672A610: 72A60F69 8FF7981D EB2D4368 C0EBEE5A  r&.i.w..k-Ch@knZ

0672A620: BF93298E AE1F3C69 0AC69F20 3B0CF765  ?.)...

0672A630: 82AABEEE 5E969BF8 AC5F040F 80E72744  .*>n^..x,_...g'D

0672A640: E458FD9A 172435AF ECFE8D58 002F00    dX}..$5/l~.X./.

*Jan 30 16:09:27.381: DTLS_CLIENT_EVENT: dtls_process_ServerHello: Processing...

*Jan 30 16:09:27.381: DTLS_CLIENT_EVENT: dtls_connection_set_cipher: Setting cipher to TLS_RSA_WITH_AES_128_CBC_SHA

*Jan 30 16:09:27.381: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_pki_init: Called...

*Jan 30 16:09:27.381: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Attempting to extract next record....

*Jan 30 16:09:27.381: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0276BB38

0672A640:                                  16                 .

0672A650: FEFF0000 00000000 000201B4 0B00047F  ~..........4....

0672A660: 00020000 000001A8 00047C00 04793082  .......(..|..y0.

0672A670: 04753082 035DA003 02010202 0A526B23  .u0..] ......Rk#

0672A680: FA000000 2EBDB130 0D06092A 864886F7  z....=10...*.H.w

0672A690: 0D010105 05003039 31163014 06035504  ......091.0...U.

0672A6A0: 0A130D43 6973636F 20537973 74656D73  ...Cisco Systems

0672A6B0: 311F301D 06035504 03131643 6973636F  1.0...U....Cisco

0672A6C0: 204D616E 75666163 74757269 6E672043   Manufacturing C

0672A6D0: 41301E17 0D313030 36313230 36303632  A0...10061206062

0672A6E0: 315A170D 32303036 31323036 31363231  1Z..200612061621

0672A6F0: 5A308194 310B3009 06035504 06130255  Z0..1.0...U....U

0672A700: 53311330 11060355 0408130A 43616C69  S1.0...U....Cali

0672A710: 666F726E 69613111 300F0603 55040713  fornia1.0...U...

0672A720: 0853616E 204A6F73 65311630 14060355  .San Jose1.0...U

0672A730: 040A130D 43697363 6F205379 7374656D  ....Cisco System

0672A740: 73312330 21060355 0403131A 4149522D  s1#0!..U....AIR-

0672A750: 43543535 30382D4B 392D3638 65666264  CT5508-K9-68efbd

0672A760: 39333837 34303120 301E0609 2A864886  9387401 0...*.H.

0672A770: F70D0109 01161173 7570706F 72744063  w......support@c

0672A780: 6973636F 2E636F6D 30820122 300D0609  isco.com0.."0...

0672A790: 2A864886 F70D0101 01050003 82010F00  *.H.w...........

0672A7A0: 3082010A 02820101 00C15461 F2C243FB  0........ATarBC{

0672A7B0: 8BC194A0 DB36E174 F5A8EFE4 3035DB03  .A. [6atu(od05[.

0672A7C0: 6DD4BB71 BC8965F1 C3FB114D 2D5A99E7  mT;q<.eqC{.M-Z.g

0672A7D0: CD126C97 C1028F42 84E0CE58 2CF85EAD  M.l.A..B.`NX,x^-

0672A7E0: 5FAC9136 44EE0385 FFD0C911 8AFD8962  _,.6Dn...PI..}.b

0672A7F0: B8ED5463 C8AF2A37 5791121A 7E7E59B3  8mTcH/*7W...~~Y3

0672A800: ADA789A0 E0E079ED C77D7567 289F942D  -'. ``ymG}ug(..-

0672A810:                                                     

*Jan 30 16:09:27.384: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (424) <  length (1151)

*Jan 30 16:09:27.384: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 30 16:09:27.384: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 30 16:09:27.384: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 30 16:09:27.384: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 30 16:09:27.384: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0276BB38

06786EE0: 16FEFF00 00000000 00000302 130B0004  .~..............

06786EF0: 7F000200 01A80002 07A5BE2F FCD3AC38  .....(...%>/|S,8

06786F00: 095005D3 57A4B85B D0E70723 A95CD14F  .P.SW$8[Pg.#)\QO

06786F10: 5F694471 A6DBC8B1 E9A89861 C1651866  _iDq&[H1i(.aAe.f

06786F20: E005D581 417EF3A3 6C39DF0F 06A2F6B2  `.U.A~s#l9_.."v2

06786F30: 50E7E2EC 091A8392 BA879322 13BECA0E  Pgbl....:..".>J.

06786F40: 1A87E9E8 942F64B6 2FCD378E 766067B9  ..ih./d6/M7.v`g9

06786F50: C4112F23 016E5EEE 09FA51EB 71FBABE0  D./#.n^n.zQkq{+`

06786F60: CC5948B3 0747DF64 4917FF6D 77978CFC  LYH3.G_dI..mw..|

06786F70: 8A19B5DC 3935601E F7B8FACD 64154950  ..5\95`.w8zMd.IP

06786F80: 931B06A0 917E31D6 57976393 04C23BE5  ... .~1VW.c..B;e

06786F90: 881D0203 010001A3 82012130 82011D30  .......#..!0...0

06786FA0: 0B060355 1D0F0404 030205A0 301D0603  ...U....... 0...

06786FB0: 551D0E04 16041448 714FC453 8D5BE14D  U......HqODS.[aM

06786FC0: 4B28A5C1 F86C4D01 1CF9D530 1F060355  K(%AxlM..yU0...U

06786FD0: 1D230418 30168014 D0C52226 AB4F4660  .#..0...PE"&+OF`

06786FE0: ECAE0591 C7DC5AD1 B047F76C 303F0603  l...G\ZQ0Gwl0?..

06786FF0: 551D1F04 38303630 34A032A0 30862E68  U...80604 2 0..h

06787000: 7474703A 2F2F7777 772E6369 73636F2E  ttp://www.cisco.

06787010: 636F6D2F 73656375 72697479 2F706B69  com/security/pki

06787020: 2F63726C 2F636D63 612E6372 6C304C06  /crl/cmca.crl0L.

06787030: 082B0601 05050701 01044030 3E303C06  .+........@0>0<.

06787040: 082B0601 05050730 02863068 7474703A  .+.....0..0http:

06787050: 2F2F7777 772E6369 73636F2E 636F6D2F  //www.cisco.com/

06787060: 73656375 72697479 2F706B69 2F636572  security/pki/cer

06787070: 74732F63 6D63612E 63657230 3F06092B  ts/cmca.cer0?..+

06787080: 06010401 82371402 04321E30 00490050  .....7...2.0.I.P

06787090: 00530045 00430049 006E0074 00650072  .S.E.C.I.n.t.e.r

067870A0: 006D0065 00640069 00610074 0065004F  .m.e.d.i.a.t.e.O

067870B0: 00660066 006C0069 006E0065 300D0609  .f.f.l.i.n.e0...

067870C0: 2A864886 F70D0101 05050003 82010100  *.H.w...........

067870D0: 41672784 69A984AD B072098B 30359E2A  Ag'.i).-0r..05.*

067870E0: 101175F8 080FE002 0FB3F622 FB1A5F5E  ..ux..`..3v"{._^

067870F0: DDC30F16 0CC6B4DC FE582CB1 DC4654EB  ]C...F4\~X,1\FTk

06787100:                                                     

*Jan 30 16:09:27.387: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (519) <  length (1151)

*Jan 30 16:09:27.387: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 30 16:09:27.387: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 30 16:09:27.387: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 30 16:09:27.387: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

CC233-2#

CC233-2#

CC233-2#

*Jan 30 16:10:27.042: DTLS_CLIENT_EVENT: dtls_disconnect: Disconnecting DTLS connection 0x0276BB38

*Jan 30 16:10:27.042: DTLS_CLIENT_EVENT_DETAIL: dtls_free_connection: Called... for connection 0x0276BB38

*Jan 30 16:10:27.042: DTLS_CLIENT_EVENT_DETAIL: dtls_send_Alert: Called...

*Jan 30 16:10:27.042: DTLS_CLIENT_EVENT: dtls_send_Alert: Sending FATAL : Close notify Alert

*Jan 30 16:10:27.043: %DTLS-5-SEND_ALERT: Send FATAL : Close notify Alert to 10.143.254.253:5246

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT: wtpDtlsCallback: DTLS-Ctrl Connection 0x0276BB38 closed

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 30 16:10:27.043: DTLS_CLIENT_EVENT: dtls_free_connection: Done... for connection 0x0276BB38

It is worth mention that this is happening in only one of more than 200 locations which are all configured the same way.

I have tried with 4 different AP's and they all show the same behaviour. Same AP's in a different location work just fine, that's why I'm pretty convince this is related to the carrier itself, now it is strange that nothing else is affected on that location, just the AP / WLC control traffic.

PS: I did try the command capwap ap controller ip address 10.143.254.253 but I obtained the same result

[Stephen Rodriguez]

can you post the ouput from

debug mac addr < ap mac >

debug capwap events enable

debug capwap errrors enable

HTH,
Steve

------------------------------------------------------------------------------------------------
Please remember to rate useful posts, and mark questions as answered

[Bruno Gri]

Hi Steve,

Here is the output:

(Cisco Controller) >debug mac addr 1c:df:0f:95:ac:09

(Cisco Controller) >debug capwap events enable

(Cisco Controller) >debug capwap errors enable

(Cisco Controller) >

(Cisco Controller) >

(Cisco Controller) >show debug

MAC address ................................ 1c:df:0f:95:ac:09

Debug Flags Enabled:

  capwap error enabled.

  capwap critical enabled.

  capwap events enabled.

  capwap state enabled.

  dtls event enabled.

  lwapp events enabled.

  lwapp errors enabled.

  pm pki enabled.

(Cisco Controller) >

(Cisco Controller) >

(Cisco Controller) >*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: called to evaluate

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 0, CA cert >bsnOldDefaultCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 1, CA cert >bsnDefaultRootCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 2, CA cert >bsnDefaultCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 3, CA cert >bsnDefaultBuildCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 4, CA cert >cscoDefaultNewRootCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 5, CA cert >cscoDefaultMfgCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 0, ID cert >bsnOldDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 1, ID cert >bsnDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 2, ID cert >cscoDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: called to get cert for CID 1f05728d

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 0, certname >bsnOldDefaultCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 1, certname >bsnDefaultRootCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 2, certname >bsnDefaultCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 3, certname >bsnDefaultBuildCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 4, certname >cscoDefaultNewRootCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 5, certname >cscoDefaultMfgCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 0, certname >bsnOldDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 1, certname >bsnDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCertFromCID: comparing to row 2, certname >cscoDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: called to evaluate

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 0, CA cert >bsnOldDefaultCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 1, CA cert >bsnDefaultRootCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 2, CA cert >bsnDefaultCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 3, CA cert >bsnDefaultBuildCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 4, CA cert >cscoDefaultNewRootCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 5, CA cert >cscoDefaultMfgCaCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 0, ID cert >bsnOldDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 1, ID cert >bsnDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.459: sshpmGetCID: comparing to row 2, ID cert >cscoDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.460: sshpmGetSshPrivateKeyFromCID: called to get key for CID 1f05728d

*spamApTask7: Jan 31 09:20:20.460: sshpmGetSshPrivateKeyFromCID: comparing to row 0, certname >bsnOldDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.460: sshpmGetSshPrivateKeyFromCID: comparing to row 1, certname >bsnDefaultIdCert<

*spamApTask7: Jan 31 09:20:20.460: sshpmGetSshPrivateKeyFromCID: comparing to row 2, certname >cscoDefaultIdCert<

(Cisco Controller) >

(Cisco Controller) >*spamApTask7: Jan 31 09:20:20.460: sshpmGetSshPrivateKeyFromCID: match in row 2

*sshpmLscTask: Jan 31 09:21:21.071: sshpmLscTask: LSC Task received a message 4

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: called to evaluate

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 0, CA cert >bsnOldDefaultCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 1, CA cert >bsnDefaultRootCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 2, CA cert >bsnDefaultCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 3, CA cert >bsnDefaultBuildCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 4, CA cert >cscoDefaultNewRootCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 5, CA cert >cscoDefaultMfgCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 0, ID cert >bsnOldDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 1, ID cert >bsnDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 2, ID cert >cscoDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: called to get cert for CID 1f05728d

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 0, certname >bsnOldDefaultCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 1, certname >bsnDefaultRootCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 2, certname >bsnDefaultCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 3, certname >bsnDefaultBuildCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 4, certname >cscoDefaultNewRootCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 5, certname >cscoDefaultMfgCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 0, certname >bsnOldDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 1, certname >bsnDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCertFromCID: comparing to row 2, certname >cscoDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: called to evaluate

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 0, CA cert >bsnOldDefaultCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 1, CA cert >bsnDefaultRootCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 2, CA cert >bsnDefaultCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 3, CA cert >bsnDefaultBuildCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 4, CA cert >cscoDefaultNewRootCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 5, CA cert >cscoDefaultMfgCaCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 0, ID cert >bsnOldDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 1, ID cert >bsnDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.123: sshpmGetCID: comparing to row 2, ID cert >cscoDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.124: sshpmGetSshPrivateKeyFromCID: called to get key for CID 1f05728d

*spamApTask6: Jan 31 09:21:23.124: sshpmGetSshPrivateKeyFromCID: comparing to row 0, certname >bsnOldDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.124: sshpmGetSshPrivateKeyFromCID: comparing to row 1, certname >bsnDefaultIdCert<

*spamApTask6: Jan 31 09:21:23.124: sshpmGetSshPrivateKeyFromCID: comparing to row 2, certname >cscoDefaultIdCert<

[Stephen Rodriguez]

looks like cert validation might be failing.  Are you doing any AP security, like authorize MIC etc?

HTH,
Steve

------------------------------------------------------------------------------------------------
Please remember to rate useful posts, and mark questions as answered

[Bruno Gri]

The option "Accept Manufactured Installed Certificate (MIC)" it is checked on both WLC's. I think the key of this issue is in the following lines:

*Jan 31 16:21:21.357: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (424) <  length (1151)

*Jan 31 16:21:21.357: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:21:21.357: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 31 16:21:21.357: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 31 16:21:21.357: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:21:21.357: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0277EEC0

We run a packet capture and we found that the following:

1) AP sends client hello

2) WLC receives it

3) WLC replies with Server Hello

4) WLC sends certificate (packet size 590 Bytes)

5) AP receives it

6) WLC sends certificate (packet size 360 Bytes)

7) AP doesn't receives it

8) AP timeout

It is always the same behaviour.

[Stephen Rodriguez]

almost looks like PMTUD isn't working.

may want to try

config ap tcp-adjust-mss all < value >

HTH,
Steve

------------------------------------------------------------------------------------------------
Please remember to rate useful posts, and mark questions as answered

[Bruno Gri]

But it is only with this location though, that's why I think is related to something in the carrier side, althgouth I can't understand what could it be. Here is what it comes down to:

Debug of a working AP:

*Jan 31 16:36:09.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10.143.254.254 peer_port: 5246

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_inc_ref_count: Secret reference count= 2

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_delete: Secret not deleted, reference count = 1

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_send_ClientHello: Called...

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_send_handshake_msg: Called...

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 31 16:36:09.000: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 31 16:36:09.187: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x026C9F00

06738EA0:                   16FEFF00 00000000          .~......

06738EB0: 00000000 2F030000 23000000 00000000  ..../...#.......

06738EC0: 23FEFF20 0A00DECB 7EAA1234 56789ABC  #~. ..^K~*.4Vx.<

06738ED0: 930E45B2 C60AB26E 9F96C225 0F0726E9  ..E2F.2n..B%..&i

06738EE0: AD8A6517                             -.e.           

*Jan 31 16:36:09.188: DTLS_CLIENT_EVENT: dtls_process_HelloVerifyRequest: Processing...

*Jan 31 16:36:09.188: DTLS_CLIENT_EVENT_DETAIL: dtls_send_ClientHello: Called...

*Jan 31 16:36:09.189: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 31 16:36:09.189: DTLS_CLIENT_EVENT_DETAIL: dtls_send_handshake_msg: Called...

*Jan 31 16:36:09.189: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 31 16:36:09.189: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 31 16:36:09.189: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:36:09.261: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x026C9F00

06704AF0:                            16FEFF00              .~..

06704B00: 00000000 00000100 52020000 46000100  ........R...F...

06704B10: 00000000 46FEFF51 0A9DBF76 DA0F0B66  ....F~.Q..?vZ..f

06704B20: 72B28A8A A5B29EF1 B66E8A24 FB5539C3  r2..%2.q6n.${U9C

06704B30: 2F267366 2D02AC20 7B40A093 2488AC76  /&sf-., {@ .$.,v

06704B40: D0D694A9 2661230B CBA7A413 E010474D  PV.)&a#.K'$.`.GM

06704B50: 0A494E66 EE0BE4EE 002F00             .INfn.dn./.    

*Jan 31 16:36:09.262: DTLS_CLIENT_EVENT: dtls_process_ServerHello: Processing...

*Jan 31 16:36:09.262: DTLS_CLIENT_EVENT: dtls_connection_set_cipher: Setting cipher to TLS_RSA_WITH_AES_128_CBC_SHA

*Jan 31 16:36:09.262: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_pki_init: Called...

*Jan 31 16:36:09.262: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Attempting to extract next record....

*Jan 31 16:36:09.262: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x026C9F00

06704B50:                         16 FEFF0000             .~...

06704B60: 00000000 000201B4 0B00047F 00020000  .......4........

06704B70: 000001A8 00047C00 04793082 04753082  ...(..|..y0..u0.

06704B80: 035DA003 02010202 0A5021F6 ED000000  .] ......P!vm...

06704B90: 2EB59930 0D06092A 864886F7 0D010105  .5.0...*.H.w....

06704BA0: 05003039 31163014 06035504 0A130D43  ..091.0...U....C

06704BB0: 6973636F 20537973 74656D73 311F301D  isco Systems1.0.

06704BC0: 06035504 03131643 6973636F 204D616E  ..U....Cisco Man

06704BD0: 75666163 74757269 6E672043 41301E17  ufacturing CA0..

06704BE0: 0D313030 36313131 39323731 315A170D  .100611192711Z..

06704BF0: 32303036 31313139 33373131 5A308194  200611193711Z0..

06704C00: 310B3009 06035504 06130255 53311330  1.0...U....US1.0

06704C10: 11060355 0408130A 43616C69 666F726E  ...U....Californ

06704C20: 69613111 300F0603 55040713 0853616E  ia1.0...U....San

06704C30: 204A6F73 65311630 14060355 040A130D   Jose1.0...U....

06704C40: 43697363 6F205379 7374656D 73312330  Cisco Systems1#0

06704C50: 21060355 0403131A 4149522D 43543535  !..U....AIR-CT55

06704C60: 30382D4B 392D3638 65666264 39333833  08-K9-68efbd9383

06704C70: 32303120 301E0609 2A864886 F70D0109  201 0...*.H.w...

06704C80: 01161173 7570706F 72744063 6973636F  ...support@cisco

06704C90: 2E636F6D 30820122 300D0609 2A864886  .com0.."0...*.H.

06704CA0: F70D0101 01050003 82010F00 3082010A  w...........0...

06704CB0: 02820101 00DE519C EBD5DE04 BBE84810  .....^Q.kU^.;hH.

06704CC0: B796C26A 19B3C0C4 039F5946 8C5BA9D5  7.Bj.3@D..YF.[)U

06704CD0: 6C3FFD50 E95163DA A4ADB7DB 280198D7  l?}PiQcZ$-7[(..W

06704CE0: E5606E5A FA165D1C FD97E8A7 3259FED7  e`nZz.].}.h'2Y~W

06704CF0: C043DEBC 6653727D D2B514E3 C6ABDCB8  @C^

06704D00: 848C65F2 4A96A5A7 11881F0C 90A3CB03  ..erJ.%'.....#K.

06704D10: 3FA69851 1112E7EF FF173971           ?&.Q..go..9q   

*Jan 31 16:36:09.264: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (424) <  length (1151)

*Jan 31 16:36:09.264: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:36:09.264: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 31 16:36:09.264: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 31 16:36:09.265: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:36:09.266: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x026C9F00

067000F0: 16FEFF00 00000000 00000302 130B0004  .~..............

06700100: 7F000200 01A80002 07198FBE E5CB79E6  .....(.....>eKyf

06700110: 2ED9EF2F 0F66C568 73D72351 54BB111F  .Yo/.fEhsW#QT;..

06700120: 40A7B3BD 2294943F 61ADAD6C 54C95FFC  @'3="..?a--lTI_|

06700130: 6E0DA143 004C0C1D 200A17DC 0E61D224  n.!C.L.. ..\.aR$

06700140: EF6DDBB9 72DAF726 001AC973 1E228D8D  om[9rZw&..Is."..

06700150: A745158B F13D646E 1CCDF808 AEA47A7D  'E..q=dn.Mx..$z}

06700160: 10DBF88A 2FB02F5F 15A71982 BF458124  .[x./0/_.'..?E.$

06700170: 3159A9CD 6EC72B43 D5541C04 291B83F4  1Y)MnG+CUT..)..t

06700180: F6A667D9 6125AB38 74C55671 9CC46CC4  v&gYa%+8tEVq.DlD

06700190: C78146FA B4FB10B5 620E9C03 3FDE0261  G.Fz4{.5b...?^.a

067001A0: 17530203 010001A3 82012130 82011D30  .S.....#..!0...0

067001B0: 0B060355 1D0F0404 030205A0 301D0603  ...U....... 0...

067001C0: 551D0E04 1604148F 93BB23DE B485C5F2  U........;#^4.Er

067001D0: 3553F941 3ED2A81F CD53AA30 1F060355  5SyA>R(.MS*0...U

067001E0: 1D230418 30168014 D0C52226 AB4F4660  .#..0...PE"&+OF`

067001F0: ECAE0591 C7DC5AD1 B047F76C 303F0603  l...G\ZQ0Gwl0?..

06700200: 551D1F04 38303630 34A032A0 30862E68  U...80604 2 0..h

06700210: 7474703A 2F2F7777 772E6369 73636F2E  ttp://www.cisco.

06700220: 636F6D2F 73656375 72697479 2F706B69  com/security/pki

06700230: 2F63726C 2F636D63 612E6372 6C304C06  /crl/cmca.crl0L.

06700240: 082B0601 05050701 01044030 3E303C06  .+........@0>0<.

06700250: 082B0601 05050730 02863068 7474703A  .+.....0..0http:

06700260: 2F2F7777 772E6369 73636F2E 636F6D2F  //www.cisco.com/

06700270: 73656375 72697479 2F706B69 2F636572  security/pki/cer

06700280: 74732F63 6D63612E 63657230 3F06092B  ts/cmca.cer0?..+

06700290: 06010401 82371402 04321E30 00490050  .....7...2.0.I.P

067002A0: 00530045 00430049 006E0074 00650072  .S.E.C.I.n.t.e.r

067002B0: 006D0065 00640069 00610074 0065004F  .m.e.d.i.a.t.e.O

067002C0: 00660066 006C0069 006E0065 300D0609  .f.f.l.i.n.e0...

067002D0: 2A864886 F70D0101 05050003 82010100  *.H.w...........

067002E0: 2134BFC4 607F0AC1 4E74DE75 ABC95334  !4?D`..ANt^u+IS4

067002F0: 68B4CA08 E6774486 03367B24 4DFAE43E  h4J.fwD..6{$Mzd>

06700300: 8D74380C 581C4242 949D7E4B 235E3B5E  .t8.X.BB..~K#^;^

06700310:                                                     

*Jan 31 16:36:09.269: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (519) <  length (1151)

*Jan 31 16:36:09.269: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:36:09.269: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 31 16:36:09.269: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 31 16:36:09.269: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:36:09.269: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x026C9F00

06775BD0:                   16FEFF00 00000000          .~......

06775BE0: 00000400 D00B0004 7F000200 03AF0000  ....P......../..

06775BF0: C47FE7D0 6D49F7D3 955B2084 6C8E2701  D.gPmIwS.[ .l.'.

06775C00: 024858B8 B23679B2 D4DFE94B E3524454  .HX826y2T_iKcRDT

06775C10: 3F1C7F89 8916D838 CCECEA24 34C3E68A  ?.....X8Llj$4Cf.

06775C20: 427B83DE 6F02FB0D 8FDE45A1 04274B95  B{.^o.{..^E!.'K.

06775C30: 9FDBD8A5 7DC5C94B 030613C6 047F0937  .[X%}EIK...F...7

06775C40: 6F24F619 9C7B93B2 4BA2E768 5A4ABA58  o$v..{.2K"ghZJ:X

06775C50: 2EEECD3D B1BFAD3B D6184F9A 6034BDF0  .nM=1?-;V.O.`4=p

06775C60: 981D6FEE E044918C 81ED9BD8 4D01B350  ..on`D...m.XM.3P

06775C70: FBCDF285 8007C7BE 90C885FD 821ED93E  {Mr...G>.H.}..Y>

06775C80: B07FFF2C 67FDA948 78B816A2 029498DE  0..,g})Hx8."...^

06775C90: FB4C21B2 E8095673 C9A590E0 E16F5499  {L!2h.VsI%.`aoT.

06775CA0: E4639F34 E48479C7 D3E7EFE7 61DFAF48  dc.4d.yGSgoga_/H

06775CB0: 19E5563B 2D                          .eV;-          

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (196) <  length (1151)

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Attempting to extract next record....

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x026C9F00

06775CB0:            16FEFF 00000000 00000005       .~.........

06775CC0: 00180B00 047F0002 00047300 000C3D27  ..........s...='

06775CD0: 3B623688 29C8CA64 2167               ;b6.)HJd!g     

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (12) <  length (1151)

*Jan 31 16:36:09.271: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:36:09.272: DTLS_CLIENT_EVENT_DETAIL: local_reassembly_check: Handshake sequence 2 is ready for assembly

*Jan 31 16:36:09.272: DTLS_CLIENT_EVENT_DETAIL: local_reassemble: Message assembled

*********************************************************************

Debug of failed AP:

*Jan 31 16:52:51.000: %CAPWAP-5-DTLSREQSEND: DTLS connection request sent peer_ip: 10.143.254.254 peer_port: 5246

*Jan 31 16:52:51.000: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_inc_ref_count: Secret reference count= 2

*Jan 31 16:52:51.000: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 31 16:52:51.000: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_delete: Secret not deleted, reference count = 1

*Jan 31 16:52:51.000: DTLS_CLIENT_EVENT_DETAIL: dtls_send_ClientHello: Called...

*Jan 31 16:52:51.000: DTLS_CLIENT_EVENT_DETAIL: dtls_send_handshake_msg: Called...

*Jan 31 16:52:51.000: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 31 16:52:51.001: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 31 16:52:51.235: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0278009C

067E02E0:                            16FEFF00              .~..

067E02F0: 00000000 00000000 2F030000 23000000  ......../...#...

067E0300: 00000000 23FEFF20 0A00E9CD 5AC11234  ....#~. ..iMZA.4

067E0310: 56789ABC 49623895 65565B89 4FC53D11  Vx.

067E0320: 2340A364 B6970C60                    #@#d6..`       

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT: dtls_process_HelloVerifyRequest: Processing...

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT_DETAIL: dtls_send_ClientHello: Called...

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_flush_handshake_msgs: Called...

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT_DETAIL: dtls_send_handshake_msg: Called...

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT_DETAIL: dtls_record_send: Called...

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT_DETAIL: dtls_connection_send: Called...

*Jan 31 16:52:51.236: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:52:51.360: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0278009C

06803E20:          16FEFF00 00000000 00000100      .~..........

06803E30: 52020000 46000100 00000000 46FEFF51  R...F.......F~.Q

06803E40: 0AA1E669 386F805D F3907CEB C6212A7C  .!fi8o.]s.|kF!*|

06803E50: 7D0DAB83 0B8079F3 380B43C0 2DCDCD20  }.+...ys8.C@-MM

06803E60: 729501D9 456FE544 3CADEE74 690F27C7  r..YEoeD<-nti.'G

06803E70: 47AE362C 3E274CB2 6C5DDE4E CDC5FC10  G.6,>'L2l]^NME|.

06803E80: 002F00                               ./.            

*Jan 31 16:52:51.360: DTLS_CLIENT_EVENT: dtls_process_ServerHello: Processing...

*Jan 31 16:52:51.360: DTLS_CLIENT_EVENT: dtls_connection_set_cipher: Setting cipher to TLS_RSA_WITH_AES_128_CBC_SHA

*Jan 31 16:52:51.360: DTLS_CLIENT_EVENT_DETAIL: dtls_secret_pki_init: Called...

*Jan 31 16:52:51.360: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Attempting to extract next record....

*Jan 31 16:52:51.360: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0278009C

06803E80:       16 FEFF0000 00000000 000201B4     .~..........4

06803E90: 0B00047F 00020000 000001A8 00047C00  ...........(..|.

06803EA0: 04793082 04753082 035DA003 02010202  .y0..u0..] .....

06803EB0: 0A5021F6 ED000000 2EB59930 0D06092A  .P!vm....5.0...*

06803EC0: 864886F7 0D010105 05003039 31163014  .H.w......091.0.

06803ED0: 06035504 0A130D43 6973636F 20537973  ..U....Cisco Sys

06803EE0: 74656D73 311F301D 06035504 03131643  tems1.0...U....C

06803EF0: 6973636F 204D616E 75666163 74757269  isco Manufacturi

06803F00: 6E672043 41301E17 0D313030 36313131  ng CA0...1006111

06803F10: 39323731 315A170D 32303036 31313139  92711Z..20061119

06803F20: 33373131 5A308194 310B3009 06035504  3711Z0..1.0...U.

06803F30: 06130255 53311330 11060355 0408130A  ...US1.0...U....

06803F40: 43616C69 666F726E 69613111 300F0603  California1.0...

06803F50: 55040713 0853616E 204A6F73 65311630  U....San Jose1.0

06803F60: 14060355 040A130D 43697363 6F205379  ...U....Cisco Sy

06803F70: 7374656D 73312330 21060355 0403131A  stems1#0!..U....

06803F80: 4149522D 43543535 30382D4B 392D3638  AIR-CT5508-K9-68

06803F90: 65666264 39333833 32303120 301E0609  efbd9383201 0...

06803FA0: 2A864886 F70D0109 01161173 7570706F  *.H.w......suppo

06803FB0: 72744063 6973636F 2E636F6D 30820122  rt@cisco.com0.."

06803FC0: 300D0609 2A864886 F70D0101 01050003  0...*.H.w.......

06803FD0: 82010F00 3082010A 02820101 00DE519C  ....0........^Q.

06803FE0: EBD5DE04 BBE84810 B796C26A 19B3C0C4  kU^.;hH.7.Bj.3@D

06803FF0: 039F5946 8C5BA9D5 6C3FFD50 E95163DA  ..YF.[)Ul?}PiQcZ

06804000: A4ADB7DB 280198D7 E5606E5A FA165D1C  $-7[(..We`nZz.].

06804010: FD97E8A7 3259FED7 C043DEBC 6653727D  }.h'2Y~W@C^

06804020: D2B514E3 C6ABDCB8 848C65F2 4A96A5A7  R5.cF+\8..erJ.%'

06804030: 11881F0C 90A3CB03 3FA69851 1112E7EF  .....#K.?&.Q..go

06804040: FF173971                             ..9q           

*Jan 31 16:52:51.363: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (424) <  length (1151)

*Jan 31 16:52:51.363: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:52:51.363: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 31 16:52:51.363: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 31 16:52:51.364: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:52:51.364: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: Called... for connection 0x0278009C

06846A80:                   16FEFF00 00000000          .~......

06846A90: 00000302 130B0004 7F000200 01A80002  .............(..

06846AA0: 07198FBE E5CB79E6 2ED9EF2F 0F66C568  ...>eKyf.Yo/.fEh

06846AB0: 73D72351 54BB111F 40A7B3BD 2294943F  sW#QT;..@'3="..?

06846AC0: 61ADAD6C 54C95FFC 6E0DA143 004C0C1D  a--lTI_|n.!C.L..

06846AD0: 200A17DC 0E61D224 EF6DDBB9 72DAF726   ..\.aR$om[9rZw&

06846AE0: 001AC973 1E228D8D A745158B F13D646E  ..Is."..'E..q=dn

06846AF0: 1CCDF808 AEA47A7D 10DBF88A 2FB02F5F  .Mx..$z}.[x./0/_

06846B00: 15A71982 BF458124 3159A9CD 6EC72B43  .'..?E.$1Y)MnG+C

06846B10: D5541C04 291B83F4 F6A667D9 6125AB38  UT..)..tv&gYa%+8

06846B20: 74C55671 9CC46CC4 C78146FA B4FB10B5  tEVq.DlDG.Fz4{.5

06846B30: 620E9C03 3FDE0261 17530203 010001A3  b...?^.a.S.....#

06846B40: 82012130 82011D30 0B060355 1D0F0404  ..!0...0...U....

06846B50: 030205A0 301D0603 551D0E04 1604148F  ... 0...U.......

06846B60: 93BB23DE B485C5F2 3553F941 3ED2A81F  .;#^4.Er5SyA>R(.

06846B70: CD53AA30 1F060355 1D230418 30168014  MS*0...U.#..0...

06846B80: D0C52226 AB4F4660 ECAE0591 C7DC5AD1  PE"&+OF`l...G\ZQ

06846B90: B047F76C 303F0603 551D1F04 38303630  0Gwl0?..U...8060

06846BA0: 34A032A0 30862E68 7474703A 2F2F7777  4 2 0..http://ww

06846BB0: 772E6369 73636F2E 636F6D2F 73656375  w.cisco.com/secu

06846BC0: 72697479 2F706B69 2F63726C 2F636D63  rity/pki/crl/cmc

06846BD0: 612E6372 6C304C06 082B0601 05050701  a.crl0L..+......

06846BE0: 01044030 3E303C06 082B0601 05050730  ..@0>0<..+.....0

06846BF0: 02863068 7474703A 2F2F7777 772E6369  ..0http://www.ci

06846C00: 73636F2E 636F6D2F 73656375 72697479  sco.com/security

06846C10: 2F706B69 2F636572 74732F63 6D63612E  /pki/certs/cmca.

06846C20: 63657230 3F06092B 06010401 82371402  cer0?..+.....7..

06846C30: 04321E30 00490050 00530045 00430049  .2.0.I.P.S.E.C.I

06846C40: 006E0074 00650072 006D0065 00640069  .n.t.e.r.m.e.d.i

06846C50: 00610074 0065004F 00660066 006C0069  .a.t.e.O.f.f.l.i

06846C60: 006E0065 300D0609 2A864886 F70D0101  .n.e0...*.H.w...

06846C70: 05050003 82010100 2134BFC4 607F0AC1  ........!4?D`..A

06846C80: 4E74DE75 ABC95334 68B4CA08 E6774486  Nt^u+IS4h4J.fwD.

06846C90: 03367B24 4DFAE43E 8D74380C 581C4242  .6{$Mzd>.t8.X.BB

06846CA0: 949D7E4B 235E3B5E                    ..~K#^;^       

*Jan 31 16:52:51.367: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Reassembly required for handshake seq 2. frag_len (519) <  length (1151)

*Jan 31 16:52:51.367: DTLS_CLIENT_EVENT_DETAIL: dtls_handshake_fragment_new: Called...

*Jan 31 16:52:51.367: DTLS_CLIENT_EVENT_DETAIL: dtls_reassemble_handshake: Not ready to assemble yet.

*Jan 31 16:52:51.367: DTLS_CLIENT_EVENT_DETAIL: dtls_client_process_record: DTLS handshake buffered for reassembly later

*Jan 31 16:52:51.367: DTLS_CLIENT_EVENT_DETAIL: dtls_process_packet: End of datagram reached.

*Jan 31 16:53:51.044: DTLS_CLIENT_EVENT: dtls_disconnect: Disconnecting DTLS connection 0x0278009C

*Jan 31 16:53:51.044: DTLS_CLIENT_EVENT_DETAIL: dtls_free_connection: Called... for connection 0x0278009C

*Jan 31 16:53:51.044: DTLS_CLIENT_EVENT_DETAIL: dtls_send_Alert: Called...

*Jan 31 16:53:51.044: DTLS_CLIENT_EVENT: dtls_send_Alert: Sending FATAL : Close notify Alert

*Jan 31 16:53:51.045: %DTLS-5-SEND_ALERT: Send FATAL : Close notify Alert to 10.143.254.254:5246

As you can see there are identical up to handshake seq 2. frag_len (519) <  length (1151). The working AP receives the last fragment and succesfully reassembles it. The failed AP never receives that last fragment.

I can't think of any reason why this could be happening.