AP DTLS issues

[frederick.mercado]

Controller : C9800-L (HA config)

Version : 17.9.5 (upgraded due to the DTLS issue from 17.6.5)

AP: C9120AXI 

Software Version

17.9.5.47

Boot Version

1.1.2.4

Last Statistics Received

05/22/2024 10:02:26

Current CPU Usage (%)

4

Average CPU Usage (%)

4

Current Memory Usage (%)

43

Average Memory Usage (%)

43

Current Window Size

10

Switch: 9300L 48 port POE

I have apparently one AP that keeps losing connectivity to the WLC and a couple less concerning that are a few weeks out. The one AP seems to drop randomly (I see it often happens during the working day) the DTLS connection. I cannot figure out why. Up time is consistent and client connectivity is impacted, but I lose them briefly from the controller and they rejoin. 

Checked so far:

• Wireless configuration - using tool
• verified switch configuration (same as all other APs that work)
• Already have timers at 8/5
• All other APs are working fine
• Switchport shows no errors/swapped ports as well
• Did an ethernet line test with all pairs showing pass/good.
• Ran a pcap and packet trace with dump on WLC when DTLS session ends, and little to go on.
• Replaced the AP completely with a new unit.
• IOS was upgraded to 17.9.5
• Looked into CSCwa23659, but it should be resolved with this IOS.

Cisco C9800 AP disconnected due to max retransmission reached

[marce1000]

    >...I have apparently one AP that keeps losing connectivity to the WLC and a couple less concerning that are a few weeks out.
   - Check port connection parameters ; link speed , look at port (error) counters. Check if valid outputs and or AP model info is seen
      from show cdp neighbors detail  (e.g.)

  - Reboot the AP and check if that can help

  - Use https://www.cisco.com/c/en/us/support/docs/wireless/catalyst-9800-series-wireless-controllers/217738-monitor-catalyst-9800-kpis-key-performa.html#anc4  , check if you can correlate info's to this specific AP

  - Some more advanced DTLS debugging commands are included below (some of them are probably already mentioned in the previous link)
   show wireless stats ap join summary
  show wireless dtls connections
  show platform hardware chassis active qfp feature wireless capwap datapath statistics drop all
  show platform hardware chassis active qfp feature wireless capwap datapath mac-address <APradio-mac> details
  show platform hardware chassis active qfp feature wireless capwap datapath mac-address <APradio-mac> statistics
  show platform hardware chassis active qfp feature wireless dtls datapath statistics all
  show platform hardware chassis active qfp statistics drop all | inc Global | Wls 

 - Review the global controller configuration with the CLI command show tech wireless and feed the output from that
   into Wireless Config Analyzer

 M.

[frederick.mercado]

1) show cdp neighbor detail:

Device ID: LSLAP_Main_1
Entry address(es):
IP address: 10.74.*.*
IPv6 address: FE80::*:*:*:*(link-local)
Platform: cisco C9120AXI-B, Capabilities: Router Trans-Bridge
Interface: GigabitEthernet1/0/24, Port ID (outgoing port): GigabitEthernet0
Holdtime : 140 sec

Version :
Cisco AP Software, ap1g7-k9w8 Version: 17.9.5.47
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 2014-2015 by Cisco Systems, Inc.

advertisement version: 2
Peer Source MAC: *.*.3db0
Duplex: full
Power drawn: 23.200 Watts
Power request id: 34166, Power management id: 3
Power request levels are:23200 15400 0 0 0
Management address(es):
IP address: 10.74.*.*

2) Reboot

see my original post:

"Replaced the AP completely with a new unit." - this included a reboot of the prior unit.

3) Monitoring

#show wireless stats ap history | i Disjoined
LSLAP_Main_3 *.*.* Disjoined 05/01/24 23:04:23 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 15:55:00 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 15:34:34 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 15:07:37 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 14:49:36 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 14:04:33 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 13:37:31 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 13:28:30 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 08:31:18 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 07:55:22 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/15/24 06:52:37 NA DTLS close alert from peer 1
LGTAP_Main_5 *.*.* Disjoined 04/26/24 05:58:39 NA Max Retransmission to AP 1
LSLAP_Seattle_Main_1 *.*.* Disjoined 05/13/24 04:42:57 NA Heart beat timer expiry 1
LSLAP_Main_19 *.*.* Disjoined 04/26/24 12:56:57 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 13:08:55 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 12:50:46 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 12:24:02 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 11:56:42 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 10:18:00 NA DTLS close alert from peer 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 07:44:33 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 06:41:29 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 05:02:31 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/22/24 03:23:22 NA Max Retransmission to AP 1
LSLAP_Main_1 *.*.* Disjoined 05/21/24 19:44:17 NA Max Retransmission to AP 1

show wireless stats ap session termination
Event Previous State Occurance Count
------------------------------------------------------------------------------------
Image download status IMAGE_DOWNLOAD 1
Reset by API RUN 1
DTLS session closed RUN 70
Heartbeat timer expiry RUN 1
Message timer expiry RUN 287

4) DTLS debugging

Base MAC Ethernet MAC AP Name IP Address Status Last Failure Phase Last Disconnect Reason
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 LSLAP_Main_1 10.74.31.1 Joined Run Max Retransmission to AP

AP Name Local Port Peer IP Peer Port Version Ciphersuite
------------------------------------------------------------------------------------------------
LSLAP_Main_1 Capwap_Ctrl 10.74.*.* 5273 DTLSv1.2 TLS_NUM_ECDHE_RSA_WITH_AES_128_GCM_SHA256

show platform hardware chassis active qfp feature wireless capwap datapath statistics drop all

Drop Cause Packets Octets
================================================================================ ====================
Wls Capwap unsupported link type Error 0 0
Wls Capwap invalid tunnel Error 0 0
Wls Capwap input config missing Error 0 0
Wls Capwap invalid TPID Error 0 0
Wls Capwap ingress parsing Error 0 0
Wls Capwap invalid FC subtype Error 0 0
Wls Capwap SNAP Invalid HLEN Error 0 0
Wls Capwap Invalid SNAP Error 0 0
Wls Capwap ipv4 tunnel not found Error 33019 9980514
Wls Capwap ipv6 tunnel not found Error 0 0
Wls Capwap tunnel header add Error 0 0
Wls Capwap mobility tunnel header add Error 0 0
Wls Capwap MOU tunnel header add Error 0 0
Wls Capwap mobility MOU tunnel header add Error 0 0
Wls Capwap tunnel ipv4 header add Error 0 0
Wls Capwap tunnel ipv6 header add Error 0 0
Wls Capwap multicast tunnel header add Error 0 0
Wls Capwap multicast tunnel ipv4 header add Error 0 0
Wls Capwap multicast tunnel ipv6 header add Error 0 0
Wls Capwap v4 encap type disabled Error 168 80536
Wls Capwap v6 encap type disabled Error 0 0
Wls Capwap v4 input UIDB invalid 0 0
Wls Capwap v6 input UIDB invalid 0 0
Wls Capwap ingress dot3 ingress processing Error 0 0
Wls Capwap tunnel ingress unsufficient packet data 0 0
Wls Capwap tunnel ingress invalid capwap version Error 0 0
Wls Capwap tunnel ingress capwap hlen Error 0 0
Wls Capwap ingress fragment capwap payload length Error 0 0
Wls Capwap ingress non-frag capwap payload length Error 0 0
Wls Capwap ingress dot11_4 snap header len Error 0 0
Wls Capwap ingress dot11_4 Invalid SNAP header 0 0
Wls Capwap ingress dot11 ingress dot11_fc Error 0 0
Wls Capwap ingress dot11 ingress processing Error 0 0
Wls Capwap invalid DTLS header length Error 0 0
Wls Capwap invalid Capwap header type Error 0 0
Wls Capwap ingress PPE redistrib Error 0 0
Wls Capwap egress PPE redistrib invalid tunnel Error 0 0
Wls Capwap egress PPE redistrib Error 0 0
Wls Capwap blocks mcast ND from mobility to mobility tunnel 0 0

show platform hardware chassis active qfp feature wireless capwap datapath mac-address RADIO MAC details
Vrf : 0
Src IP : 10.74.*.*
Src Port : 5247
Dst IP : 10.74.*.*
Dst Port : 5273
Input Uidb : 0xff3d
Output Uidb : 0xff37
Instance Id : 3
Path MTU : 1485
Capwap MTU : 1424
DTLS Ctxt : 0x0000000000000000
Global LAG : enabled

show platform hardware chassis active qfp feature wireless capwap datapath mac-address RADIO MAC statistics
Pkts Bytes

Rx 0 0
Rx redistribute v4 0 0
Rx redistribute v6 0 0
Rx no redistribute non-ip 0 0
Rx no redistribute 0 0
Rx snap hlen Drop 0 0
Rx snap Drop 0 0
Rx wlclient not found Drop 12 868
Rx mob-wlclient not found Drop 0 0
Rx dot3 Drop 0 0
Rx dot11 parse Drop 0 0
Rx dot11 invld fc Drop 0 0
Rx dot11 Error Drop 0 0
Rx parse Drop 0 0
Rx no uidb Drop 0 0
Rx redistribute Drop 0 0
Punt dot11 dot1x 31 9482
Punt dot11 iapp 3426 732201
Punt dot11 rrm 0 0
Punt dot11 rfid 0 0
Punt sisf dhcp 4 1384
Punt sisf ipv6nd ns 1 90
Punt dot11 0 0
Punt dot11 mgmt 167 26495
Punt dot11 probe req 6034 1122022
Punt capwap data 0 0
Punt mobility keepalive 0 0
Punt capwap keepalive 207 20700
Punt capwap mdns 0 0
Tx 0 0
Tx hdr add Drop 0 0
Tx redistribute Drop 0 0
ETA IDP Records 0 0
ETA SALT Records 0 0
ETA SPLT Records 0 0
ETA BD Records 0 0
ETA TLS Records 0 0
Inject to Mobility Tunnel 0 0
Inject data keepalive 207 17802

show platform hardware chassis active qfp feature wireless dtls datapath statistics all
CPP Wireless DTLS Feature Stats

Description Packet Count Octet Count
----------- ------------ -----------
DTLS Packets To Encrypt 169018694 12244877055
DTLS Packets Encrypted 169018694 24013376777
DTLS Packets To Decrypt 169957479 17052484935
DTLS Packets Decrypted 169957479 15333338007
Skip Encryption - Handshake 0 0
Skip Encryption - Not AppData 0 0
Skip Encryption - No Hash Entry 0 0
Skip Encryption - No Crypto Handle 0 0
Skip Encryption - No DTLS header 3684045 641895475
Skip Encryption - Requested by RP 3235 1256045
Skip Decryption - Handshake 0 0
Skip Decryption - Not AppData 1518 702912
Skip Decryption - No Hash Entry 2542 1109028
Skip Decryption - No Crypto Handle 0 0
Skip Decryption - No DTLS header 164464 52349438
Skip Decryption - Multiple Records 0 0
Error - Encrypt Invalid Length 0 0
Error - Encrypt Header Restore 0 0
Error - DataEncrypt No Crypto Handle 0 0
Error - DataEncrypt Header Restore 0 0
Error - Decrypt Invalid Length 0 0
Error - Decrypt Header Restore 0 0
Error - DataDecrypt Zero Epoch 0 0
Error - DataDecrypt No Hash Entry 0 0
Error - DataDecrypt No Crypto Handle 0 0
Error - DataDecrypt Header Restore 0 0
Error - DataDecrypt non UDP Proto 0 0
Error - DataEncrypt non UDP Proto 0 0

show platform hardware chassis active qfp statistics drop all | inc Global | Wls
Global Drop Stats Packets Octets

5) Show tech wireless - already done! No discernable issue to affect this.

[marce1000]

 -  Try to change the AP to a different site tag and profile (they can have the same settings, just different names).  That should load-balance it onto a different WNCd process and then when it's stable change it back to the original site tag and profile.  You should do a capwap restart "ap name <apname> reset capwap" to make sure the tag and profile changes take effect each time.
                           Also  reboot the AP

 M.

[frederick.mercado]

Country code verified to US. 

Advanced

Country Code

USUS    

Multiple Countries

US

Statistics Timer

180

CAPWAP MTU

1485

AP Link Latency

Enabled

AP PMK Propagation Capability

Enabled

TCP Adjust MSS Option

AP TCP MSS Adjust

Enabled

AP TCP MSS Size

1250

AP IPv6 TCP MSS Adjust

Enabled

AP IPv6 TCP MSS Size

1250

AP Retransmit Config Parameters

AP Retransmit Count

8

AP Retransmit Interval

5

Changed site and tag. 

While looking at AP logs, I noticed NTP having issues. Unsure if this is related to the DTLS. But the times get jumbled as the log continues. The source is the WLC for time.

Stratum Version Last Received Delay Offset Jitter NTP server
5 4 3sec ago 0.812ms 0.406ms 0.004ms 10.74.*.*

May 23 10:14:14 ntp_update: NTP: Thu May 23 10:14:14 2024 :Can not create ntp process log file.
May 23 10:14:14 syslogd exiting
May 23 10:14:14 syslogd started: BusyBox v1.32.1
May 23 14:14:14 kernel: [*05/23/2024 10:14:14.3583] systemd[1]: Started Cisco syslog service.
May 23 14:14:14 kernel: [*05/23/2024 10:14:14.3723] systemd[1]: Started Cisco syslogd watcher.
May 23 14:14:14 kernel: [*05/23/2024 10:14:14.4313] Got WSA Server config TLVs
May 23 14:14:15 kernel: [05/23/2024 10:14:15.3043] audit_log_lost: 18 callbacks suppressed
May 23 14:14:15 kernel: [05/23/2024 10:14:15.3673] audit: audit_lost=41 audit_rate_limit=100 audit_backlog_limit=8192
May 23 14:14:15 kernel: [05/23/2024 10:14:15.4663] audit: rate limit exceeded
May 23 14:14:15 kernel: [*05/23/2024 10:14:15.6386] systemd[1]: Starting ntp watcher...
May 23 14:14:15 kernel: [*05/23/2024 10:14:15.6696] systemd[1]: Starting NTPD daemon...
May 23 10:14:15 ntpd[10064]: ntpd 4.2.8p15@1.3728-o Thu Jan 25 12:14:13 UTC 2024 (1): Starting
May 23 10:14:15 ntpd[10064]: Command line: /sbin/ntpd
May 23 10:14:15 ntpd[10064]: ----------------------------------------------------
May 23 10:14:15 ntpd[10064]: ntp-4 is maintained by Network Time Foundation,
May 23 10:14:15 ntpd[10064]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
May 23 10:14:15 ntpd[10064]: corporation. Support and training for ntp-4 are
May 23 10:14:15 ntpd[10064]: available at https://www.nwtime.org/support
May 23 10:14:15 ntpd[10064]: ----------------------------------------------------
May 23 10:14:15 ntpd[10066]: proto: precision = 0.220 usec (-22)
May 23 10:14:15 ntpd[10066]: basedate set to 2024-01-13
May 23 10:14:15 ntpd[10066]: gps base set to 2024-01-14 (week 2297)
May 23 10:14:15 ntpd[10066]: Listen and drop on 0 v6wildcard [::]:123
May 23 10:14:15 ntpd[10066]: Listen and drop on 1 v4wildcard 0.0.0.0:123
May 23 10:14:15 ntpd[10066]: Listen normally on 2 lo 127.0.0.1:123
May 23 10:14:15 ntpd[10066]: Listen normally on 3 srcr2 10.74.31.1:123
May 23 10:14:15 ntpd[10066]: Listen normally on 4 lo [::1]:123
May 23 10:14:15 ntpd[10066]: Listen normally on 5 srcr2 [fe80::db70:59c:bd78:93e9%61]:123
May 23 10:14:15 ntpd[10066]: Listening on routing socket on fd #22 for interface updates
May 23 10:14:15 ntpd[10066]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
May 23 10:14:15 ntpd[10066]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
May 23 14:14:15 kernel: [*05/23/2024 10:14:15.6896] systemd[1]: Started NTPD daemon.
May 23 14:14:15 kernel: [*05/23/2024 10:14:15.7146] systemd[1]: Started ntp watcher.
May 23 10:14:16 sshd[7319]: error: Could not get shadow information for admin
May 23 14:14:16 kernel: [*05/23/2024 10:14:16.6046]
May 23 14:14:16 kernel: [*05/23/2024 10:14:16.6046] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:16 kernel: [*05/23/2024 10:14:16.6046]
May 23 14:14:19 kernel: [*05/23/2024 10:14:19.2376]
May 23 14:14:19 kernel: [*05/23/2024 10:14:19.2376] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:19 kernel: [*05/23/2024 10:14:19.2376]
May 23 14:14:21 kernel: [*05/23/2024 10:14:21.0446]
May 23 14:14:21 kernel: [*05/23/2024 10:14:21.0446] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:21 kernel: [*05/23/2024 10:14:21.0446]
May 23 14:14:22 kernel: [*05/23/2024 10:14:22.8986]
May 23 14:14:22 kernel: [*05/23/2024 10:14:22.8986] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:22 kernel: [*05/23/2024 10:14:22.8986]
May 23 14:14:23 kernel: [*05/23/2024 10:14:23.1786] changed to DFS channel 116l, running CAC for 60 seconds.
May 23 14:14:23 kernel: [*05/23/2024 10:14:23.3276] CAC_STOP_EVT: CAC stopped on DFS channel 116l
May 23 14:14:23 kernel: [*05/23/2024 10:14:23.6966] changed to DFS channel 116l, running CAC for 60 seconds.
May 23 14:14:24 kernel: [*05/23/2024 10:14:24.7896]
May 23 14:14:24 kernel: [*05/23/2024 10:14:24.7896] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:24 kernel: [*05/23/2024 10:14:24.7896]
May 23 14:14:26 kernel: [*05/23/2024 10:14:26.6166]
May 23 14:14:26 kernel: [*05/23/2024 10:14:26.6166] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:26 kernel: [*05/23/2024 10:14:26.6166]
May 23 14:14:28 kernel: [*05/23/2024 10:14:28.4956]
May 23 14:14:28 kernel: [*05/23/2024 10:14:28.4956] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 14:14:28 kernel: [*05/23/2024 10:14:28.4956]
May 23 14:14:28 kernel: [*05/23/2024 10:14:28.6576] AP tag LSL_Main change to LSL_Conf
May 23 14:14:28 kernel: [*05/23/2024 10:14:28.6696] flags value is 0 process iot_radio
May 23 10:14:28 root: BLE reset lock acquired
May 23 10:14:31 root: released BLE reset lock
May 23 14:14:39 kernel: [*05/23/2024 10:14:39.4246] set cleanair [slot0][band0] enabled
May 23 14:14:39 kernel: [*05/23/2024 10:14:39.4266] set cleanair [slot0][band1] enabled
May 23 14:14:39 kernel: [*05/23/2024 10:14:39.4386] set cleanair [slot1][band1] enabled
May 23 10:14:39 NCI: I0: openSensor(slot=0)
May 23 10:14:39 eeprom_api[5185]: cfg loopback only mode 0
May 23 10:14:40 NCI: I : Entering spawned RxLoop
May 23 10:14:40 NCI: I0: SensorApp=5325626c
May 23 10:14:40 NCI: I0: SensorHdw=1.5.3
May 23 10:14:40 NCI: I0: Hardware Radio Band = [4890, 5935] MHz, BW=75313, band=1
May 23 10:14:40 NCI: I0: Hardware Radio Band = [2400, 2500] MHz, BW=75313, band=0
May 23 10:14:40 NCI: slot=0 mode=1 chanCnt=36 cw=255
May 23 10:14:40 NCI: Squashed Channel List:
May 23 10:14:40 NCI: chans: 1 2 3 4 5 6 7 8 9 10 11
May 23 10:14:40 NCI: 36 40 44 48 52 56 60 64 100 104 108
May 23 10:14:40 NCI: 112 116 120 124 128 132 136 140 144 149 153
May 23 10:14:40 NCI: 157 161 165
May 23 10:14:40 NCI: cf(MHz): 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462
May 23 10:14:40 NCI: 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540
May 23 10:14:40 NCI: 5560 5580 5600 5620 5640 5660 5680 5700 5720 5745 5765
May 23 10:14:40 NCI: 5785 5805 5825
May 23 10:14:40 NCI: I0: channel map channels: in=36 cloned=36
May 23 10:14:40 NCI: I0: Requesting MonBand [2400, 2482] bw=0MHz/0 ant=0xbc
May 23 10:14:40 NCI: I0: Monitoring (cf=2441, span=82), RadioUsage=5%
May 23 10:14:40 NCI: I0: dwell=25000us, update=3000ms, resBW=156251
May 23 10:14:40 NCI: I0: Requesting MonBand [5160, 5340] bw=0MHz/0 ant=0xbc
May 23 10:14:40 NCI: I0: Monitoring (cf=5250, span=180), RadioUsage=6%
May 23 10:14:40 NCI: I0: dwell=20000us, update=3000ms, resBW=156250
May 23 10:14:40 NCI: I0: Requesting MonBand [5480, 5845] bw=0MHz/0 ant=0xbc
May 23 10:14:40 NCI: I0: Monitoring (cf=5662, span=365), RadioUsage=12%
May 23 10:14:40 NCI: I0: dwell=20000us, update=3000ms, resBW=156250
May 23 10:14:40 NCI: CLEANAIR: Slot 0 enabled
May 23 10:14:42 eeprom_api[5185]: DART Antenna is not supported
May 23 10:14:44 NCI: CLEANAIR: Slot 1 channel change chk
May 23 14:15:27 kernel: [*05/23/2024 10:15:27.5760] CAC_EXPIRY_EVT: CAC finished on DFS channel 116l
May 23 14:16:38 kernel: [*05/23/2024 10:16:38.4440] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 14:16:38 kernel: [*05/23/2024 10:16:38.4440]
May 23 14:16:39 kernel: [*05/23/2024 10:16:39.2580] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 14:16:39 kernel: [*05/23/2024 10:16:39.2580]
May 23 14:16:40 kernel: [*05/23/2024 10:16:40.2080] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 14:16:40 kernel: [*05/23/2024 10:16:40.2080]

I have no firewalls, no port blocking. WLC is on same VLAN/subnet.

[Rich R]

By default the AP will sync to WLC time over CAPWAP (not NTP) when it joins.
You can also configure the AP to use NTP in the AP profile:
ap profile <your-ap-profile>
  ntp ip 1.2.3.4

[frederick.mercado]

Apparently the NTP change seems to not work...despite the synch on the server...but I see where Max retransmission happened at 11:13 EST. 

May 23 10:51:06 ntpd[25598]: ----------------------------------------------------
May 23 10:51:06 ntpd[25598]: ntp-4 is maintained by Network Time Foundation,
May 23 10:51:06 ntpd[25598]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
May 23 10:51:06 ntpd[25598]: corporation. Support and training for ntp-4 are
May 23 10:51:06 ntpd[25598]: available at https://www.nwtime.org/support
May 23 10:51:06 ntpd[25598]: ----------------------------------------------------
May 23 10:51:06 ntpd[25600]: proto: precision = 0.220 usec (-22)
May 23 10:51:06 ntpd[25600]: basedate set to 2024-01-13
May 23 10:51:06 ntpd[25600]: gps base set to 2024-01-14 (week 2297)
May 23 10:51:06 ntpd[25600]: Listen and drop on 0 v6wildcard [::]:123
May 23 10:51:06 ntpd[25600]: Listen and drop on 1 v4wildcard 0.0.0.0:123
May 23 10:51:06 ntpd[25600]: Listen normally on 2 lo 127.0.0.1:123
May 23 10:51:06 ntpd[25600]: Listen normally on 3 srcr2 10.74.31.1:123
May 23 10:51:06 ntpd[25600]: Listen normally on 4 lo [::1]:123
May 23 10:51:06 ntpd[25600]: Listen normally on 5 srcr2 [fe80::db70:59c:bd78:93e9%61]:123
May 23 10:51:06 ntpd[25600]: Listening on routing socket on fd #22 for interface updates
May 23 10:51:06 ntpd[25600]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized
May 23 10:51:06 ntpd[25600]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized
May 23 14:51:06 kernel: [*05/23/2024 10:51:06.1536] systemd[1]: Started NTPD daemon.
May 23 14:51:06 kernel: [*05/23/2024 10:51:06.1736] systemd[1]: Started ntp watcher.
May 23 14:54:39 kernel: [*05/23/2024 10:54:39.7350] Re-Tx Count=1, Max Re-Tx Value=8, SendSeqNum=211, NumofPendingMsgs=5
May 23 14:54:39 kernel: [*05/23/2024 10:54:39.7350]
May 23 14:54:44 kernel: [*05/23/2024 10:54:44.4860] Re-Tx Count=2, Max Re-Tx Value=8, SendSeqNum=212, NumofPendingMsgs=6
May 23 14:54:44 kernel: [*05/23/2024 10:54:44.4860]
May 23 14:54:49 kernel: [*05/23/2024 10:54:49.2380] Re-Tx Count=3, Max Re-Tx Value=8, SendSeqNum=216, NumofPendingMsgs=10
May 23 14:54:49 kernel: [*05/23/2024 10:54:49.2380]
May 23 10:56:59 ntpd[25600]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized
May 23 15:01:33 kernel: [*05/23/2024 11:01:33.9196] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:01:33 kernel: [*05/23/2024 11:01:33.9196]
May 23 15:01:34 kernel: [*05/23/2024 11:01:34.8466] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:01:34 kernel: [*05/23/2024 11:01:34.8466]
May 23 15:01:35 kernel: [*05/23/2024 11:01:35.7976] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:01:35 kernel: [*05/23/2024 11:01:35.7976]
May 23 15:03:35 kernel: [*05/23/2024 11:03:35.7243] Re-Tx Count=1, Max Re-Tx Value=8, SendSeqNum=56, NumofPendingMsgs=4
May 23 15:03:35 kernel: [*05/23/2024 11:03:35.7243]
May 23 15:03:41 kernel: [*05/23/2024 11:03:41.4274] Re-Tx Count=2, Max Re-Tx Value=8, SendSeqNum=56, NumofPendingMsgs=3
May 23 15:03:41 kernel: [*05/23/2024 11:03:41.4274]
May 23 15:03:46 kernel: [*05/23/2024 11:03:46.1785] Re-Tx Count=3, Max Re-Tx Value=8, SendSeqNum=58, NumofPendingMsgs=5
May 23 15:03:46 kernel: [*05/23/2024 11:03:46.1785]
May 23 15:05:21 kernel: [*05/23/2024 11:05:21.4120] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:05:21 kernel: [*05/23/2024 11:05:21.4120]
May 23 15:05:22 kernel: [*05/23/2024 11:05:22.3081] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:05:22 kernel: [*05/23/2024 11:05:22.3081]
May 23 15:05:23 kernel: [*05/23/2024 11:05:23.2591] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:05:23 kernel: [*05/23/2024 11:05:23.2591]
May 23 15:07:29 kernel: [*05/23/2024 11:07:29.2557] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:07:29 kernel: [*05/23/2024 11:07:29.2557]
May 23 15:07:30 kernel: [*05/23/2024 11:07:30.0357] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:07:30 kernel: [*05/23/2024 11:07:30.0357]
May 23 15:07:30 kernel: [*05/23/2024 11:07:30.9857] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:07:30 kernel: [*05/23/2024 11:07:30.9857]
May 23 15:11:18 kernel: [*05/23/2024 11:11:18.7782] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:11:18 kernel: [*05/23/2024 11:11:18.7782]
May 23 15:11:19 kernel: [*05/23/2024 11:11:19.6872] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:11:19 kernel: [*05/23/2024 11:11:19.6872]
May 23 15:11:20 kernel: [*05/23/2024 11:11:20.6372] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:11:20 kernel: [*05/23/2024 11:11:20.6372]
May 23 15:12:13 kernel: [*05/23/2024 11:12:13.6141] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:12:13 kernel: [*05/23/2024 11:12:13.6141]
May 23 15:12:14 kernel: [*05/23/2024 11:12:14.4261] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:12:14 kernel: [*05/23/2024 11:12:14.4261]
May 23 15:12:15 kernel: [*05/23/2024 11:12:15.3771] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:12:15 kernel: [*05/23/2024 11:12:15.3771]
May 23 15:12:25 kernel: [*05/23/2024 11:12:25.8230] Re-Tx Count=1, Max Re-Tx Value=8, SendSeqNum=153, NumofPendingMsgs=2
May 23 15:12:25 kernel: [*05/23/2024 11:12:25.8230]
May 23 15:12:30 kernel: [*05/23/2024 11:12:30.5750] Re-Tx Count=2, Max Re-Tx Value=8, SendSeqNum=154, NumofPendingMsgs=3
May 23 15:12:30 kernel: [*05/23/2024 11:12:30.5750]
May 23 15:12:35 kernel: [*05/23/2024 11:12:35.3260] Re-Tx Count=3, Max Re-Tx Value=8, SendSeqNum=156, NumofPendingMsgs=5
May 23 15:12:35 kernel: [*05/23/2024 11:12:35.3260]
May 23 11:12:40 sshd[1774]: error: Could not get shadow information for admin
May 23 11:12:40 sshd[1774]: Accepted password for admin from 10.74. port 60940 ssh2
May 23 15:12:43 kernel: [*05/23/2024 11:12:43.1189] Re-Tx Count=4, Max Re-Tx Value=8, SendSeqNum=158, NumofPendingMsgs=6
May 23 15:12:43 kernel: [*05/23/2024 11:12:43.1189]
May 23 15:12:47 kernel: [*05/23/2024 11:12:47.8699] Re-Tx Count=5, Max Re-Tx Value=8, SendSeqNum=158, NumofPendingMsgs=6
May 23 15:12:47 kernel: [*05/23/2024 11:12:47.8699]
May 23 15:12:52 kernel: [*05/23/2024 11:12:52.6218] Re-Tx Count=6, Max Re-Tx Value=8, SendSeqNum=158, NumofPendingMsgs=6
May 23 15:12:52 kernel: [*05/23/2024 11:12:52.6218]
May 23 15:12:57 kernel: [*05/23/2024 11:12:57.3737] Re-Tx Count=7, Max Re-Tx Value=8, SendSeqNum=158, NumofPendingMsgs=6
May 23 15:12:57 kernel: [*05/23/2024 11:12:57.3737]
May 23 15:13:02 kernel: [*05/23/2024 11:13:02.1247] Re-Tx Count=8, Max Re-Tx Value=8, SendSeqNum=159, NumofPendingMsgs=7
May 23 15:13:02 kernel: [*05/23/2024 11:13:02.1247]
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] Max retransmission count exceeded, going back to DISCOVER mode.
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] Dropping msg CAPWAP_WTP_EVENT_REQUEST, type = 34, len = 3083, eleLen = 3091, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] Dropping msg CAPWAP_WTP_EVENT_REQUEST, type = 34, len = 3083, eleLen = 3091, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] Dropping msg CAPWAP_WTP_EVENT_REQUEST, type = 34, len = 556, eleLen = 564, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] ...Vendor SubType: AP_CDP_CACHE_PAYLOAD(24) len: 552 vendId 409600
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] Dropping msg CAPWAP_WTP_EVENT_REQUEST, type = 34, len = 14, eleLen = 22, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] Dropping msg CAPWAP_WTP_EVENT_REQUEST, type = 34, len = 29, eleLen = 37, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6276] ...Vendor SubType: AP_LINK_AUDITING_PAYLOAD(55) len: 25 vendId 409600
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6286] Dropping msg CAPWAP_ECHO_REQUEST, type = 1, len = 0, eleLen = 8, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6286] Dropping msg CAPWAP_ECHO_REQUEST, type = 1, len = 0, eleLen = 8, sendSeqNum = 160
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6286] GOING BACK TO DISCOVER MODE
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6476] OOBImageDnld: OOBImageDownloadTimer expired for image download..
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6476] OOBImageDnld: Do common error handler for OOB image download..
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6746]
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.6746] CAPWAP State: DTLS Teardown
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.7796] DOT11_DRV[1]: DFS CAC timer enabled time 60
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.8096] DOT11_DRV[1]: DFS CAC timer enabled time 60
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.8496] DOT11_DRV[1]: DFS CAC timer enabled time 60
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.8706] DOT11_DRV[0]: Stop Radio0
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.8706] Stopped Radio 0
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.8936] DOT11_DRV[1]: Stop Radio1
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.8936] Stopped Radio 1
May 23 11:13:11 NCI: CLEANAIR: Slot 0 CAPWAP down
May 23 11:13:11 NCI: I0: shutdownNci
May 23 15:13:11 kernel: [*05/23/2024 11:13:11.9406] OOBImageDnld: Do common error handler for OOB image download..
May 23 11:13:12 upgrade: Script called with args:[CANCEL]
May 23 15:13:12 kernel: [*05/23/2024 11:13:12.0246] status 'upgrade.sh: Script called with args:[CANCEL]'
May 23 15:13:12 kernel: [*05/23/2024 11:13:12.0706] do CANCEL, part2 is active part
May 23 11:13:12 upgrade: Cleanup tmp files ...
May 23 15:13:12 kernel: [*05/23/2024 11:13:12.0916] status 'upgrade.sh: Cleanup tmp files ...'
May 23 15:13:12 kernel: [*05/23/2024 11:13:12.1186] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: DTLS Teardown(4).
May 23 15:13:12 kernel: [*05/23/2024 11:13:12.1186] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: DTLS Teardown(4).
May 23 15:13:16 kernel: [*05/23/2024 11:13:16.5875] OOBImageDnld: OOBImageDownloadTimer expired for image download..
May 23 15:13:16 kernel: [*05/23/2024 11:13:16.5875] OOBImageDnld: Do common error handler for OOB image download..
May 23 15:13:16 kernel: [*05/23/2024 11:13:16.6055] dtls_queue_first: Nothing to extract!
May 23 15:13:16 kernel: [*05/23/2024 11:13:16.6055]
May 23 15:13:17 kernel: [*05/23/2024 11:13:17.6065] ipv6 gw config loop in Ac discovery
May 23 15:13:19 kernel: [*05/23/2024 11:13:19.6065] ipv6 gw config loop in Ac discovery
May 23 15:13:21 kernel: [*05/23/2024 11:13:21.6064] ipv6 gw config loop in Ac discovery
May 23 15:13:23 kernel: [*05/23/2024 11:13:23.6064] ipv6 gw config loop in Ac discovery
May 23 15:13:25 kernel: [*05/23/2024 11:13:25.6064] ipv6 gw config loop in Ac discovery
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6124] systemd[1]: Starting dhcpv6 client watcher...
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6164]
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6164] CAPWAP State: Discovery
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6174] Got WLC address 10.74. from DHCP.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6174] IP DNS query for CISCO-CAPWAP-CONTROLLER.lam.liebherr.i
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6194] DNS resolved CISCO-CAPWAP-CONTROLLER.lam.liebherr.i
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6194] DNS discover IP addr: 10.74.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6214] Discovery Request sent to 10.74., discovery type STATIC_CONFIG(1)
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6404] Discovery Request sent to 10.74., discovery type DNS(3)
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6424] Discovery Request sent to 255.255.255.255, discovery type UNKNOWN(0)
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6424] Discovery Response from 10.74.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6434] Discovery Response from 10.74.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6434] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Discovery(2).
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6434] Discovery Response from 10.74.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6434] Discovery Response from 10.74.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6484] systemd[1]: Stopping DHCPv6 client...
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.6604] systemd[1]: Starting DHCPv6 client...
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.7124] systemd[1]: Started DHCPv6 client.
May 23 15:13:26 kernel: [*05/23/2024 11:13:26.7334] systemd[1]: Started dhcpv6 client watcher.
May 23 15:13:35 kernel: [*05/23/2024 11:13:35.9622] Started wait dtls timer (60 sec)
May 23 15:13:35 kernel: [*05/23/2024 11:13:35.9702]
May 23 15:13:35 kernel: [*05/23/2024 11:13:35.9702] CAPWAP State: DTLS Setup
May 23 15:13:36 kernel: [*05/23/2024 11:13:36.0282] dtls_verify_server_cert: Controller certificate verification successful
May 23 15:13:36 kernel: [*05/23/2024 11:13:36.3952]
May 23 15:13:36 kernel: [*05/23/2024 11:13:36.3952] CAPWAP State: Join
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.2902] OOBImageDnld: OOB Image Download in ap_cap_bitmask(2)
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.2902] Sending Join request to 10.74. through port 5260, packet size 1376
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.2932] Join Response from 10.74., packet size 1397
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.2932] AC accepted previous sent request with result code: 0
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.2932] Received wlcType 0, timer 30
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.3342]
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.3342] CAPWAP State: Image Data
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.3352] AP image version 17.9.5.47 backup 17.9.4.27, Controller 17.9.5.47
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.3352] Version is the same, do not need update.
May 23 11:13:37 upgrade: Script called with args:[NO_UPGRADE]
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.3762] status 'upgrade.sh: Script called with args:[NO_UPGRADE]'
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.4212] do NO_UPGRADE, part2 is active part
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.4332]
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.4332] CAPWAP State: Configure
May 23 11:13:37 capwapd[6009]: Check lagloadbalance setting flex_mode 0 cfg 0 linkstate 0 ap_type 86
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.6412] DOT11_CFG[1]: Starting radio 1
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.6562] DOT11_DRV[1]: DFS CAC timer enabled time 60
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.6572] DOT11_DRV[1]: Start Radio1
May 23 15:13:37 kernel: [*05/23/2024 11:13:37.6642] DOT11_DRV[1]: set_channel Channel set to 116/40
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.0762] Started Radio 1
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.0782] DOT11_CFG[0]: Starting radio 0
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.0782] DOT11_DRV[0]: Start Radio0
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.0862] DOT11_DRV[0]: set_channel Channel set to 11/20
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.5462] Started Radio 0
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.8642]
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.8642] CAPWAP State: Run
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.9312] AP has joined controller lslromi-wlc-01
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.9312] wtpHandleImageSwapEwlcmeTimer: time=0
May 23 15:13:38 kernel: [*05/23/2024 11:13:38.9342] IOT device ttyiot0 not found
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.1642] wl: Busy
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.1712] wl: Busy
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3042] Previous AP mode is 0, change to 0
May 23 11:13:39 capwapd[6009]: Check lagloadbalance setting flex_mode 0 cfg 0 linkstate 0 ap_type 86
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3092] Current session mode: ssh, Configured: Telnet-No, SSH-Yes, Console-Yes
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3092]
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3092] Current session mode: telnet, Configured: Telnet-No, SSH-Yes, Console-Yes
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3092]
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3092] Current session mode: console, Configured: Telnet-No, SSH-Yes, Console-Yes
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3092]
May 23 11:13:39 chpasswd: password for user changed
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3382] chpasswd: password for user changed
May 23 11:13:39 chpasswd: password for user changed
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.3552] chpasswd: password for user changed
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4102]
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4102] Same LSC mode, no action needed
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4112] CLSM[00:00:00:00:00:00]: U3 Client RSSI Stats feature is deprecated; can no longer be enabled
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4122] systemd[1]: Starting Cisco syslogd watcher...
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4152] systemd[1]: Starting ntp file watcher...
May 23 11:13:39 ntp_update: NTP: Thu May 23 11:13:39 2024 :Can not create ntp process log file.
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4302] Update NTP source to WLC
May 23 11:13:39 syslogd exiting
May 23 11:13:39 syslogd started: BusyBox v1.32.1
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4802] systemd[1]: Started Cisco syslog service.
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.4932] systemd[1]: Started Cisco syslogd watcher.
May 23 15:13:39 kernel: [*05/23/2024 11:13:39.5632] Got WSA Server config TLVs
May 23 15:13:41 kernel: [*05/23/2024 11:13:41.3341]
May 23 15:13:41 kernel: [*05/23/2024 11:13:41.3341] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:41 kernel: [*05/23/2024 11:13:41.3341]
May 23 15:13:43 kernel: [*05/23/2024 11:13:43.4001]
May 23 15:13:43 kernel: [*05/23/2024 11:13:43.4001] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:43 kernel: [*05/23/2024 11:13:43.4001]
May 23 15:13:45 kernel: [*05/23/2024 11:13:45.2111]
May 23 15:13:45 kernel: [*05/23/2024 11:13:45.2111] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:45 kernel: [*05/23/2024 11:13:45.2111]
May 23 15:13:47 kernel: [*05/23/2024 11:13:47.0540]
May 23 15:13:47 kernel: [*05/23/2024 11:13:47.0540] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:47 kernel: [*05/23/2024 11:13:47.0540]
May 23 15:13:47 kernel: [*05/23/2024 11:13:47.3170] changed to DFS channel 116l, running CAC for 60 seconds.
May 23 15:13:48 kernel: [*05/23/2024 11:13:48.8850]
May 23 15:13:48 kernel: [*05/23/2024 11:13:48.8850] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:48 kernel: [*05/23/2024 11:13:48.8850]
May 23 15:13:50 kernel: [*05/23/2024 11:13:50.6689]
May 23 15:13:50 kernel: [*05/23/2024 11:13:50.6689] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:50 kernel: [*05/23/2024 11:13:50.6689]
May 23 15:13:52 kernel: [*05/23/2024 11:13:52.4889]
May 23 15:13:52 kernel: [*05/23/2024 11:13:52.4889] *** Unable to connect to: 127.0.0.1:4040 - [Errno 111] Connection refused
May 23 15:13:52 kernel: [*05/23/2024 11:13:52.4889]
May 23 15:13:52 kernel: [*05/23/2024 11:13:52.6609] flags value is 0 process iot_radio
May 23 11:13:52 root: BLE reset lock acquired
May 23 11:13:55 root: released BLE reset lock
May 23 15:14:05 kernel: [*05/23/2024 11:14:05.6556] set cleanair [slot0][band0] enabled
May 23 15:14:05 kernel: [*05/23/2024 11:14:05.6576] set cleanair [slot0][band1] enabled
May 23 15:14:05 kernel: [*05/23/2024 11:14:05.6606] set cleanair [slot1][band1] enabled
May 23 11:14:05 NCI: I0: openSensor(slot=0)
May 23 11:14:05 eeprom_api[5185]: cfg loopback only mode 0
May 23 11:14:06 NCI: I0: SensorApp=5325626c
May 23 11:14:06 NCI: I0: SensorHdw=1.5.3
May 23 11:14:06 NCI: I0: Hardware Radio Band = [4890, 5935] MHz, BW=75313, band=1
May 23 11:14:06 NCI: I0: Hardware Radio Band = [2400, 2500] MHz, BW=75313, band=0
May 23 11:14:06 NCI: slot=0 mode=1 chanCnt=36 cw=255
May 23 11:14:06 NCI: Squashed Channel List:
May 23 11:14:06 NCI: chans: 1 2 3 4 5 6 7 8 9 10 11
May 23 11:14:06 NCI: 36 40 44 48 52 56 60 64 100 104 108
May 23 11:14:06 NCI: 112 116 120 124 128 132 136 140 144 149 153
May 23 11:14:06 NCI: 157 161 165
May 23 11:14:06 NCI: cf(MHz): 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462
May 23 11:14:06 NCI: 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540
May 23 11:14:06 NCI: 5560 5580 5600 5620 5640 5660 5680 5700 5720 5745 5765
May 23 11:14:06 NCI: 5785 5805 5825
May 23 11:14:06 NCI: I0: channel map channels: in=36 cloned=36
May 23 11:14:06 NCI: I0: Requesting MonBand [2400, 2482] bw=0MHz/0 ant=0xbc
May 23 11:14:06 NCI: I0: Monitoring (cf=2441, span=82), RadioUsage=5%
May 23 11:14:06 NCI: I0: dwell=25000us, update=3000ms, resBW=156251
May 23 11:14:06 NCI: I0: Requesting MonBand [5160, 5340] bw=0MHz/0 ant=0xbc
May 23 11:14:06 NCI: I0: Monitoring (cf=5250, span=180), RadioUsage=6%
May 23 11:14:06 NCI: I0: dwell=20000us, update=3000ms, resBW=156250
May 23 11:14:06 NCI: I0: Requesting MonBand [5480, 5845] bw=0MHz/0 ant=0xbc
May 23 11:14:06 NCI: I0: Monitoring (cf=5662, span=365), RadioUsage=12%
May 23 11:14:06 NCI: I0: dwell=20000us, update=3000ms, resBW=156250
May 23 11:14:06 NCI: CLEANAIR: Slot 0 enabled
May 23 11:14:10 NCI: CLEANAIR: Slot 1 channel change chk
May 23 15:14:51 kernel: [*05/23/2024 11:14:51.4915] CAC_EXPIRY_EVT: CAC finished on DFS channel 116l
May 23 15:15:17 kernel: [*05/23/2024 11:15:17.9827] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:15:17 kernel: [*05/23/2024 11:15:17.9827]
May 23 15:15:18 kernel: [*05/23/2024 11:15:18.7467] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:15:18 kernel: [*05/23/2024 11:15:18.7467]
May 23 15:15:19 kernel: [*05/23/2024 11:15:19.6967] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:15:19 kernel: [*05/23/2024 11:15:19.6967]
May 23 15:17:14 kernel: [*05/23/2024 11:17:14.4765] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:17:14 kernel: [*05/23/2024 11:17:14.4765]
May 23 15:17:15 kernel: [*05/23/2024 11:17:15.3104] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:17:15 kernel: [*05/23/2024 11:17:15.3104]
May 23 15:17:16 kernel: [*05/23/2024 11:17:16.2613] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:17:16 kernel: [*05/23/2024 11:17:16.2613]
May 23 15:21:36 kernel: [*05/23/2024 11:21:36.0239] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:21:36 kernel: [*05/23/2024 11:21:36.0239]
May 23 15:21:36 kernel: [*05/23/2024 11:21:36.7908] wtpProcessPacketFromApSvcSocket AP service socket returned 1
May 23 15:21:36 kernel: [*05/23/2024 11:21:36.7908]
May 23 15:21:37 kernel: [*05/23/2024 11:21:37.7408] wtpProcessPacketFromApSvcSocket AP service socket returned 1

[Rich R]

NTP works fine on my APs.

But I never suggested it would help with the DTLS problem.

Did you read my previous reply below?

[frederick.mercado]

Yes, contemplating the change. I mean 17.9.x train should be exiting in what 11 months? So we will be pushed to this anyhow. I just wonder what other issues we may get with it not being a MD or gold star.

[Rich R]

Yes 17.9 has 10 months of bug fixes left - it goes end of software maintenance 30 March 2025.  I already see things getting fixed in 17.12 but not 17.9 so we'll see more like that.  Only major issues will get fixed in the remaining 17.9 releases.
https://www.cisco.com/c/en/us/products/collateral/ios-nx-os-software/ios-xe-17/ios-xe-17-9-x-eol.html

So they will probably make 17.12.x the recommended release sometime in the next few months - most likely a month or two after 17.15.1 (currently in beta) gets released.

[frederick.mercado]

I changed it back now. Monitoring. Last DTLS success was on 05/23/2024 11:59:28

[Rich R]

See also https://bst.cloudapps.cisco.com/bugsearch/bug/CSCwi16509 fixed in 17.12.3 and
https://bst.cloudapps.cisco.com/bugsearch/bug/CSCwi42059 now marked Unreproducible, both related to corrupted AP state on the WLC.  The first one it can actually be another AP which is impacting the one you see the problem on.  Both bugs have a number of customer cases attached already.

Think about 17.12.3?

[frederick.mercado]

I had too much on my plate - given that this issue was low priority but I wanted to try to solve this. I did a capture with DTLS debug and this is what I see. I have over 1700+ DTLS session requests vs the <20 of other APs. Again, only this AP. I tried ordering a replacement AP and it does the same thing. SSL issues? Maybe cached info?

Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6524] OOBImageDnld: OOBImageDownloadTimer expired for image download..
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6524] OOBImageDnld: Do common error handler for OOB image download..
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] local_in_addr_comp: Client and server addresses/port/version of 2 nodes are 10.74.x.x:5272(65277)--10.74.x.x:5246(65277) 10.74.x.x:5272--10.74.x.x:5246
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_connection_find_using_link_info: Searching connection 10.74.x.x:5272--10.74.x.x:5246, result 0x55a356c400
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] wtpCloseAllDtlsConnections: Closing DTLS-CTRL connection 0x55a356c400.
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_cssl_msg_cb: Received >>> DTLS Header [Length 000d]
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_cssl_msg_cb: Received >>> DTLS 1.2 Alert [Length 0002] Warning Close notify
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_cssl_info_cb: SSL state = 0x1; where = 0x4008; ret = 0x100
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_cssl_info_cb: ret_type_string=warning
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_cssl_info_cb: ret_desc_string=close notify
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_cssl_info_cb: SSL_state_string=SSL negotiation finished successfully
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] local_in_addr_comp: Client and server addresses/port/version of 2 nodes are 10.74.x.x:5272(65277)--10.74.x.x:5246(65277) 10.74.x.x:5272--10.74.x.x:5246
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] wtpDtlsCallback: DTLS-Ctrl Connection 0x55a356c400 closed
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6714] dtls_free_connection: Free done... for connection 0x55a356c400
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6734] dtls_connectionDB_del_connection: Deleted Connection 0x55a356c400, Server 10.74.x.x:5246, Client 10.74.x.x:5272, Count 0, rc_return 2
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6734]
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6734] dtls_connection_find_using_link_info: Searching connection 10.74.x.x:5272--10.74.x.x:5247, result (nil)
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6824]
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.6824] CAPWAP State: DTLS Teardown
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.7174] CAPWAP data tunnel delete from forwarding succeeded
Aug 26 15:04:57 NCI: CLEANAIR: Slot 0 CAPWAP down
Aug 26 15:04:57 NCI: I0: shutdownNci
Aug 26 15:04:57 NCI: CLEANAIR: Slot 1 CAPWAP down
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.7304] OOBImageDnld: Do common error handler for OOB image download..
Aug 26 15:04:57 upgrade: Script called with args:[CANCEL]
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.8184] status 'upgrade.sh: Script called with args:[CANCEL]'
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.8644] do CANCEL, part2 is active part
Aug 26 15:04:57 upgrade: Cleanup tmp files ...
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.8844] status 'upgrade.sh: Cleanup tmp files ...'
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.9114] Setting gPreDownloadComplete=0
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.9124] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: DTLS Teardown(4).
Aug 26 19:04:57 kernel: [*08/26/2024 15:04:57.9124] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: DTLS Teardown(4).
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.3684] DTLS session cleanup completed. Restarting capwap state machine.
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.3854] OOBImageDnld: OOBImageDownloadTimer expired for image download..
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.3854] OOBImageDnld: Do common error handler for OOB image download..
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.4054] dtls_queue_first: Nothing to extract!
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.4054]
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.4054] Restarting WLC Discovery
Aug 26 19:05:02 kernel: [*08/26/2024 15:05:02.4054] Starting Discovery.
Aug 26 19:05:03 kernel: [*08/26/2024 15:05:03.4054] ipv6 gw config loop in Ac discovery
Aug 26 19:05:05 kernel: [*08/26/2024 15:05:05.4065] ipv6 gw config loop in Ac discovery
Aug 26 19:05:07 kernel: [*08/26/2024 15:05:07.4065] ipv6 gw config loop in Ac discovery
Aug 26 19:05:09 kernel: [*08/26/2024 15:05:09.4065] ipv6 gw config loop in Ac discovery
Aug 26 19:05:11 kernel: [*08/26/2024 15:05:11.4065] ipv6 gw config loop in Ac discovery
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4065] No uplink IPv6 address
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4075] IP DNS 10.74.x.x, 10.74.x.x; Domain lam.company.com
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4075] Parsed WLC ip is 10.74.x.x
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4075] DHCPv6 conf not found or empty, restart client process.
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4155] systemd[1]: Starting dhcpv6 client watcher...
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4215] TLV_AP_EWLC_TAGS_PAYLOAD tags = Policy:XXX_Main RF:XXX_Main Site:XXX_Main Source: 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4225] Discovery Request sent to 10.74.x.x, discovery type STATIC_CONFIG(1)
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4225] Got WLC address 10.74.x.x from DHCP.
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4225] Did not get log server settings from DHCP.
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4225] IP DNS query for CISCO-CAPWAP-CONTROLLER.lam.company.com
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4255] DNS resolved CISCO-CAPWAP-CONTROLLER.lam.company.com
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4405] systemd[1]: Stopping DHCPv6 client...
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4485] Discovery Request sent to 10.74.x.x, discovery type STATIC_CONFIG(1)
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4485] Sent Discovery to mobility group member 1. 10.74.x.x, type 1.
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4505] systemd[1]: Starting DHCPv6 client...
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4515] Discovery Request sent to 255.255.255.255, discovery type UNKNOWN(0)
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Discovery Response from 10.74.x.x
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] AC IPv4 10.74.x.x, load 20, count 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Not Found Configured MWAR (respIdx 0).
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Discovery Response from 10.74.x.x
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] AC IPv4 10.74.x.x, load 20, count 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Not Found Configured MWAR (respIdx 1).
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Discovery Response from 10.74.x.x
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] AC IPv4 10.74.x.x, load 20, count 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Duplicate Discovery response from XXXCO-WIFI-MI-MF-MDF-0FL-01
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Ignoring the duplicate discovery response
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Discovery Response from 10.74.x.x
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] AC IPv4 10.74.x.x, load 20, count 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Duplicate Discovery response from XXXCO-WIFI-MI-MF-MDF-0FL-01
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4525] Ignoring the duplicate discovery response
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] Discovery Response from 10.74.x.x
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] AC IPv4 10.74.x.x, load 20, count 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] Duplicate Discovery response from XXXCO-WIFI-MI-MF-MDF-0FL-01
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] Ignoring the duplicate discovery response
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] Discovery Response from 10.74.31.200
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] AC IPv4 10.74.x.x, load 20, count 1
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] Duplicate Discovery response from XXXCO-WIFI-MI-MF-MDF-0FL-01(10.74.31.200)
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4545] Ignoring the duplicate discovery response
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.4955] systemd[1]: Started DHCPv6 client.
Aug 26 19:05:12 kernel: [*08/26/2024 15:05:12.5165] systemd[1]: Started dhcpv6 client watcher.
Aug 26 19:05:15 kernel: [*08/26/2024 15:05:15.6466] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Discovery(2).
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9446] Calling wtpGetAcToJoin from timer expiry.
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9446] DiscRep[0]: addr 10.74.x.x, apMgrCount 1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9446] DiscRep[1]: addr 10.74.x.x, apMgrCount 1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] Selected MWAR 'XXXCO-WIFI-MI-MF-MDF-0FL-01' (mwarIdx 0).
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] Selected MWAR 'XXXCO-WIFI-MI-MF-MDF-0FL-01'  (index 0).
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] apMgrCount 1, index 0
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] Resetting FQDN DP config
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] Adding Ipv4 AP manager 10.74.x.x to least load
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] WLC: XXXCO-WIFI-MI-MF-MDF-0FL-01 ApMgr count 1, ipTransportTried 0, prefer-mode 1, isIpv4OrIpv6Static 0
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] IPv4 Pref mode. Choosing AP Mgr with index 0, IP 10.74.x.x, load 20
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456] capwapSetTransportAddr returning: index 0, apMgrCount 0
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9456]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9696] Started wait dtls timer (60 sec)
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9696] enet_hex A4004EF83DB0, app_tag A4004EF83DB0
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9696] app_tag: A4004EF83DB0 CN:Cisco Manufacturing CA III
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9786]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9786] CAPWAP State: DTLS Setup
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_new_connection: set replay log callback
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_new_connection: Successfully created SSL connection
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_client_initiate_connection: DTLS CLIENT INITIATE
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL state = 0x0; where = 0x10; ret = 0x1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL_state_string=before SSL initialization
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL state = 0x0; where = 0x1001; ret = 0x1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL_state_string=before SSL initialization
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_msg_cb: Received >>> DTLS Header [Length 000d]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_msg_cb: Received >>> DTLS 1.2 Handshake [Length 00d5] ClientHello
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL state = 0xc; where = 0x1001; ret = 0x1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL_state_string=SSLv3/TLS write client hello
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL state = 0xc; where = 0x1002; ret = 0xffffffff
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_cssl_info_cb: SSL_state_string=SSLv3/TLS write client hello
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] dtls_connectionDB_add_connection: Added Connection 0x55a3559400 Server 10.74.x.x:5246 Client 10.74.x.x:5272
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] create_dtls_connection: Creating DTLS Ctrl Connection 0x55a3559400
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9796] DTLS connection created sucessfully local_ip: 10.74.x.x local_port: 5272 peer_ip: 10.74.31.200 peer_port: 5246, app_tag: A4004EF83DB0 CN:Cisco Manufacturing CA III
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] local_in_addr_comp: Client and server addresses/port/version of 2 nodes are 10.74.x.x:5272(0)--10.74.x.x:5246(0) 10.74.x.x:5272--10.74.x.x:5246
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_connection_find_using_link_info: Searching connection 10.74.x.x:5272--10.74.x.x:5246, result 0x55a3559400
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_process_packet: in dtls_process_packet
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_msg_cb: Sent <<< DTLS Header [Length 000d]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_msg_cb: Sent <<< DTLS 1.2 Handshake [Length 0023] HelloVerifyRequest
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: SSL state = 0xc; where = 0x1001; ret = 0x1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: SSL_state_string=SSLv3/TLS write client hello
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: SSL state = 0x2; where = 0x1001; ret = 0x1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9816] dtls_cssl_info_cb: SSL_state_string=DTLS1 read hello verify request
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_msg_cb: Received >>> DTLS Header [Length 000d]
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_msg_cb: Received >>> DTLS 1.2 Handshake [Length 00e9] ClientHello
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_info_cb: SSL state = 0xc; where = 0x1001; ret = 0x1
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_info_cb: ret_type_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_info_cb: ret_desc_string=unknown
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_info_cb: SSL_state_string=SSLv3/TLS write client hello
Aug 26 19:05:21 kernel: [*08/26/2024 15:05:21.9826] dtls_cssl_info_cb: SSL state

[Rich R]

Did you read my previous reply @frederick.mercado ?

It can actually be another AP which is causing the problem for this AP.  The fact that you saw the same problem with a replacement AP suggests that is probably what's happening in your case.  So you need to troubleshoot as per the bug notes to work out which other AP is causing the problem.  If you're not sure then engage TAC.

And as I said you might want to consider upgrade to 17.12.3 or 17.12.4 (soon to be recommended by TAC) which have CSCwi16509 resolved.