APs 9120, 9130 Stuck in download

[Waltorres]

Good Morning

Large deployment running WLC9800-80 AP 9120 and AP9130. The WLC running 16.12.4a - APs from factory come with 8.10.105 and 8.10.112. APs are getting the correct IP for the controller through DHCP option 43 and join the WLC fine. The issue is that about 10% of the APs fail to download and get stuck in the process for several hours or until we clear the CAPWAP.

Controller shows the following:

2021/02/05 02:40:09.749 {wncmgrd_R0-0}{1}: [ewlc-infra-evq] [27155]: (note): Msg type :mesg->msgtype Priority:1
2021/02/05 02:40:09.749 {wncd_x_R0-7}{1}: [ifid-api] [31030]: (note): ifid alloc 0x0101ac4a56a0f720 recycled entry added to active record 0x91c00009
2021/02/05 02:40:09.749 {wncd_x_R0-7}{1}: [ifid-api] [31030]: (note): ifid alloc 0x0100ac4a56a0f720 recycled entry added to active record 0x91c0000c
2021/02/05 02:40:09.843 {wncmgrd_R0-0}{1}: [ewlc-infra-evq] [27155]: (note): EWLC_DWNLDS_PER_WNCD_INSTANCE. KEY MAC: ac4a.56a0.f720
2021/02/05 02:40:09.843 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-parse] [31030]: (ERR): Parse failed vendor payload, id 4232704 type 215, length 32
2021/02/05 02:40:09.843 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-parse] [31030]: (ERR): Parse failed vendor payload, id 4232704 type 215, length 176
2021/02/05 03:03:17.063 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Encrypted DTLS message send. Dest IP: 10.18.58.34[5253], length:1401
2021/02/05 03:03:17.063 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP Message buffer sent to DTLS for send. Buffer size: 1368, count of buffers: 1
2021/02/05 03:03:17.063 {wncd_x_R0-7}{1}: [capwapac-smgr-srvr] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 Retransmitting message: image_data_request retransmit attempt: 1
2021/02/05 03:03:17.063 {wncd_x_R0-7}{1}: [capwapac-smgr-srvr] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 TX SM Retransmit state enter, seq number:30, lowest ack pending seq num 29, rexmit timer ctxt seq num 0, rexmit interval sec 3, max retries count: 5,txq count :1, cur window size: 1, abort: No
2021/02/05 03:03:17.063 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_RETRANSMIT_TR", "data":{"transition":"RETRANSMIT_TR_TO_BUSY"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.063 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"RETRANSMIT_TR_TO_BUSY"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3a34", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Add message event handle:0x55568135df68
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP session request tx completed Msg tx index: 0
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_RESPONSE_PROCESS_TR", "data":{"transition":"RESPONSE_PROCESS_TR_TO_TXQ_SCHED_TR"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Encrypted DTLS message send. Dest IP: 10.18.58.34[5253], length:1401
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP Message buffer sent to DTLS for send. Buffer size: 1368, count of buffers: 1
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_TXQ_SCHED_TR", "data":{"transition":"TXQ_SCHED_TR_TO_BUSY"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"TXQ_SCHED_TR_TO_BUSY"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3464", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Source IP:10.18.58.34[5253], clear text message processed. length:24
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Evmgr message event cb handler invoked
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"EV_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"AsyncMessage", "dst":"0x5556815360a8"}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_RESP"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"E_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"SyncMessage", "src":{"id":"$n_$p_0x7ffc012d37b0", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"E_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"SyncMessage", "dst":{"id":"$n_$p_0x7ffc012d37b0", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"image_download_to_image_download_resp_processed"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3764", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD_RESP_PROCESSED", "data":{"transition":"image_download_resp_processed_to_image_download_tr"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Add message event handle:0x55568150eda8
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"image_download_resp_processed_to_image_download_tr"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3764", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_RESP"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Evmgr message event cb handler invoked
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"EV_IMG_SEND_REQ", "label_style":"italic", "type":"AsyncMessage", "dst":"0x555681319e58"}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_IMG_SEND_REQ"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"EV_REQUEST_MSG", "label_style":"italic", "type":"SyncMessage", "src":{"id":"$n_$p_0x7ffc012d3570", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"EV_REQUEST_MSG", "label_style":"italic", "type":"SyncMessage", "dst":{"id":"$n_$p_0x7ffc012d3570", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"BUSY_TO_BUSY_1"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3524", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [tdllib] [31030]: (debug): ewlc/ap/capwapac_session/src/capwapac_session.c:670:5: wtp_sess->tx_flow_control.e = TDL_TRUE: db=WNCD_DB, tid=0, obj_ptr=0x8080c4e26c, write_ptr=0x8080c4e26c, size=4
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"BUSY_TO_BUSY_1"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3524", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.069 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_IMG_SEND_REQ"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Add message event handle:0x555681464a38
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP session request tx completed Msg tx index: 0
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_RESPONSE_PROCESS_TR", "data":{"transition":"RESPONSE_PROCESS_TR_TO_TXQ_SCHED_TR"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Encrypted DTLS message send. Dest IP: 10.18.58.34[5253], length:1401
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP Message buffer sent to DTLS for send. Buffer size: 1368, count of buffers: 1
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_TXQ_SCHED_TR", "data":{"transition":"TXQ_SCHED_TR_TO_BUSY"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"TXQ_SCHED_TR_TO_BUSY"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3464", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Source IP:10.18.58.34[5253], clear text message processed. length:24
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Evmgr message event cb handler invoked
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"EV_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"AsyncMessage", "dst":"0x555681380f48"}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_RESP"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"E_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"SyncMessage", "src":{"id":"$n_$p_0x7ffc012d37b0", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"E_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"SyncMessage", "dst":{"id":"$n_$p_0x7ffc012d37b0", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"image_download_to_image_download_resp_processed"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3764", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD_RESP_PROCESSED", "data":{"transition":"image_download_resp_processed_to_image_download_tr"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Add message event handle:0x55568134f358
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"image_download_resp_processed_to_image_download_tr"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3764", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_RESP"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Evmgr message event cb handler invoked
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"EV_IMG_SEND_REQ", "label_style":"italic", "type":"AsyncMessage", "dst":"0x5556815360a8"}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_IMG_SEND_REQ"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"EV_REQUEST_MSG", "label_style":"italic", "type":"SyncMessage", "src":{"id":"$n_$p_0x7ffc012d3570", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"EV_REQUEST_MSG", "label_style":"italic", "type":"SyncMessage", "dst":{"id":"$n_$p_0x7ffc012d3570", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"BUSY_TO_BUSY_1"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3524", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [tdllib] [31030]: (debug): ewlc/ap/capwapac_session/src/capwapac_session.c:670:5: wtp_sess->tx_flow_control.e = TDL_TRUE: db=WNCD_DB, tid=0, obj_ptr=0x8080c4e26c, write_ptr=0x8080c4e26c, size=4
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"BUSY_TO_BUSY_1"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3524", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.075 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_IMG_SEND_REQ"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Add message event handle:0x55568135df68
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP session request tx completed Msg tx index: 0
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_RESPONSE_PROCESS_TR", "data":{"transition":"RESPONSE_PROCESS_TR_TO_TXQ_SCHED_TR"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Encrypted DTLS message send. Dest IP: 10.18.58.34[5253], length:1401
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [capwapac-smgr-sess] [31030]: (debug): Session-IP: 10.18.58.34[5253] Mac: ac4a.56a0.f720 CAPWAP Message buffer sent to DTLS for send. Buffer size: 1368, count of buffers: 1
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_TXQ_SCHED_TR", "data":{"transition":"TXQ_SCHED_TR_TO_BUSY"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_session_tx_sm:147", "label":"S_BUSY", "data":{"transition":"TXQ_SCHED_TR_TO_BUSY"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3464", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-sess] [31030]: (debug): Source IP:10.18.58.34[5253], clear text message processed. length:24
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Evmgr message event cb handler invoked
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"EV_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"AsyncMessage", "dst":"0x555681319e58"}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_RESP"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"E_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"SyncMessage", "src":{"id":"$n_$p_0x7ffc012d37b0", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"E_IMAGE_DATA_RESP_MSG", "label_style":"italic", "type":"SyncMessage", "dst":{"id":"$n_$p_0x7ffc012d37b0", "type":"DefaultInteraction"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"image_download_to_image_download_resp_processed"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "push_source":"true", "src":{"id":"$n_$p_0x7ffc012d3764", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD_RESP_PROCESSED", "data":{"transition":"image_download_resp_processed_to_image_download_tr"}, "type":"CircleEvent", "color":"00FF00", "radius":"0.5"}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Add message event handle:0x55568150eda8
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwap_imgdwnld_sm:18", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"image_download_resp_processed_to_image_download_tr"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3764", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [msc-fsm] [31030]: (debug): @msc_event {"entity":"/capwapac_wtp_sess_sm:146", "label":"S_IMAGE_DOWNLOAD", "data":{"transition":"IMAGE_DOWNLOAD_TO_IMAGE_DOWNLOAD_ON_RESP"}, "type":"CircleEvent", "color":"FFFF00", "radius":"0.7", "pop_source":"true", "dst":{"id":"$n_$p_0x7ffc012d3844", "type":"Transition", "straight":"true", "stroke_width":"2.0"}}
2021/02/05 03:03:17.080 {wncd_x_R0-7}{1}: [ewlc-infra-evmgr] [31030]: (debug): Evmgr message event cb handler invoked

Thank you for your help.

[Scott Fella]

Are you staging these ap's or are they mounted already?  What exactly do you mean that "you clear capwap"?  After you do this, you are saying they join or they don't?  I have had a few 9130's not really the 9120's that would not join, even if the ap's were on the same subnet as the controller.  I actually had to factory reset using the mode button and that fixed the issue for me.  I'm assuming you tried to bounce the port a few times to reload the ap?

[Waltorres]

We are staging the APs.

To try to initiate download again we console to the AP and do "Capwap ap erase all", 90 % of the time it reloads and downloads the image.

The other option for us is to do the factory reset (mode).

Do you know what this error means?

2021/02/05 02:40:09.843 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-parse] [31030]: (ERR): Parse failed vendor payload, id 4232704 type 215, length 32
2021/02/05 02:40:09.843 {wncd_x_R0-7}{1}: [ewlc-capwapmsg-parse] [31030]: (ERR): Parse failed vendor payload, id 4232704 type 215, length 176

Usually after this the AP gets Stuck.

[Scott Fella]

No idea... but some of these errors are normal, so look at a good ap, console into it and reboot it.  The mode button is what works the best from my experience vs the cli command which only clears the config.  You can search the bug toolkit and or open a case with TAC.  My workaround is easy for me because its fast.  This works also when my ap's disassociate and get stuck.  

[Waltorres]

This is from a Good AP:

2021/02/05 02:41:18.912 {wncd_x_R0-4}{1}: [ifid-api] [30085]: (note): ifid alloc 0x0101045fb9185ca0 recycled entry added to active record 0x9100001d
2021/02/05 02:41:18.912 {wncd_x_R0-4}{1}: [ifid-api] [30085]: (note): ifid alloc 0x0100045fb9185ca0 recycled entry added to active record 0x91000020
2021/02/05 02:41:18.913 {wncmgrd_R0-0}{1}: [ewlc-infra-evq] [27155]: (note): Msg type :mesg->msgtype Priority:1
2021/02/05 02:41:19.004 {wncmgrd_R0-0}{1}: [ewlc-infra-evq] [27155]: (note): EWLC_DWNLDS_PER_WNCD_INSTANCE. KEY MAC: 045f.b918.5ca0
2021/02/05 02:43:53.603 {wncd_x_R0-4}{1}: [image-dwnld-mgr] [30085]: (note): MAC: 045f.b918.5ca0 Image download Update End time : Time taken to download : 154 secs. Size : 64675840, Blocks sent : 48087, Response received : 48087, Aborted : No Image : /tmp/sw/rp/0/0/rp_wlc/mount/mnt/images/ap.pri/ap1g7
2021/02/05 02:43:53.604 {wncmgrd_R0-0}{1}: [ewlc-infra-evq] [27155]: (note): EWLC_DWNLDS_PER_WNCD_INSTANCE. KEY MAC: 045f.b918.5ca0
2021/02/05 02:43:53.604 {wncd_x_R0-4}{1}: [capwapac-smgr-sess-fsm] [30085]: (note): Session-IP: 10.18.58.47[5257] Mac: 045f.b918.5ca0 Last Control Packet received 12 seconds ago.
2021/02/05 02:43:53.604 {wncmgrd_R0-0}{1}: [loadbalance-notify] [27155]: (note): Deleted oid addr 1
2021/02/05 02:43:53.604 {wncd_x_R0-4}{1}: [capwapac-smgr-sess-fsm] [30085]: (note): Session-IP: 10.18.58.47[5257] Mac: 045f.b918.5ca0 Last Data Keep Alive Packet information not available. Data session was not established
2021/02/05 02:43:53.604 {wncmgrd_R0-0}{1}: [ewlc-infra-evq] [27155]: (note): Msg type :mesg->msgtype Priority:1
2021/02/05 02:43:53.604 {wncd_x_R0-4}{1}: [ewlc-dtls-sessmgr] [30085]: (note): Session id a0000000000000b marked delete pending
2021/02/05 02:43:53.604 {wncd_x_R0-4}{1}: [ewlc-dtls-sess] [30085]: (note): Remote Host: 10.18.58.47[5257] DTLS session destroy : Pending messages in read queue : 0, TX queue : 0
2021/02/05 02:43:53.604 {wncd_x_R0-4}{1}: [loadbalance-notify] [30085]: (ERR): IPv4: 10.18.58.47 Received message :Disconnect, no AP name
2021/02/05 02:43:53.604 {wncd_x_R0-4}{1}: [loadbalance-notify] [30085]: (note): MAC: 5ce1.7629.e3ec Loadbalance server sent message to instance: 4

[Scott Fella · Accepted solution]

You best bet if you want to understand the error or want to determine if it's a bug is to open a tac case.  The bug toolkit is available, but that error you highlighted is not showing up any data.  Your work around since the aps ship with IOS vs COS is just to use the mode button for the ap's that don't join properly.  See what TAC has to say to be honest, its a new deployment/purchase, so they should honor that even if your support has not yet started.

[Leo Laohoo]

Have you tried killing the power to the AP (not the "reload" command from the AP) and turning it back on?

[Waltorres]

Yes, that doesnt help. 

[Scott Fella]

That has only helped me a few times after the ap is joined and for some reason disconnects from the controller at a latter time. I would have to bounce the port and at time multiple times before the ap rejoined. If it doesn’t after around 4 port bounced, I use the mode button.