SIP phone call forward noan not working over trunk

[nmdc.kzstan]

Hi,

"Call forward noan" to non-local numbers is not working on 7821 SIP phones registered to CME. "Call forward all" configured on the same phone is working.  If not answered call is forwarded to Cisco Unity Express :

dial-peer voice 199 voip
destination-pattern 199
session protocol sipv2
session target ipv4:10.46.0.1
dtmf-relay sip-notify
codec g711ulaw
no vad

7821 DN config:

voice register dn 117
number 117
call-forward b2bua noan 199 timeout 15
allow watch
name P17
no-reg
label P17

telephony-service

 call-park system application
 call-forward pattern .T

"Call forward noan" configured on SCCP phone is working. 

ephone-dn 195 dual-line
number 195 no-reg both
call-forward noan 199 timeout 15

"debug ccsip messages" shows that no INVITE message is sent to CUE after 15 sec timeout.

[nmdc.kzstan]

voice service voip

allow-connections h323 to h323
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
no supplementary-service sip moved-temporarily
no supplementary-service sip refer
supplementary-service media-renegotiate
redirect ip2ip
fax protocol pass-through g711alaw
sip
registrar server
early-offer forced

[nmdc.kzstan]

With TCL and VXML IVR scripts call forward noan was not working for both  local and non-local

SIP forwards. Worked after handoff to default application:

handoff appl leg_incoming default "DESTINATION=$dest"

[nmdc.kzstan]

debug ccsip all output. 10.46.1.1 is CME, 10.46.1.10 - 7821 SIP Phone

Nov 8 15:19:28.895: //20926/8BD06BC282D6/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=20926
Nov 8 15:19:28.895: //20926/8BD06BC282D6/SIP/Info/critical/8192/ccsip_call_statistics: Stats request failed for callid=20926, dstCallID=-1, rc=-7
Nov 8 15:19:28.895: //20926/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 33
Nov 8 15:19:28.895: //20926/8BD06BC282D6/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg..
Nov 8 15:19:28.895: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
Nov 8 15:19:28.895: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISASSOCIATE
Nov 8 15:19:28.895: //20923/8BD06BC282D6/SIP/Info/notify/1/ccsip_query_codec_info: Negotiated codec = 6
Nov 8 15:19:28.895: //20923/8BD06BC282D6/SIP/Info/notify/1/sipSPI_ipip_codec_byte_transrating: codec class not supported in xrating scenario, return FALSE
Nov 8 15:19:28.895: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x3FEBCA58) with key=[24483] to table
Nov 8 15:19:28.895: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:
Nov 8 15:19:28.895: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:
Nov 8 15:19:28.895: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/sipSPIChangeState: 0x3FEBCA58 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/critical/32768/ccsip_ipip_media_forking_read_from_TDContainer: MF: Unable to read data from TD Container..
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/critical/32768/ccsip_ipip_media_forking_forked_leg_config: MF: TD container cannot be read/container is NULL. Setting of forked call leg failed..
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: EV_UNDEFINED
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_MODE
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_MODE
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md_snr:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed_snr:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/verbose/8192/sip_iwf_sip_ed_set_mode_hdlr: Setting SPI mode to SIP-SIP
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_sip_early_dialog_container
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: CC_EV_IF_DIAG_DONE
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_FLOW_MODE
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sip_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_FLOW_MODE
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_fa2fa_flow_mode_transition:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_ft2fa_flow_mode_transition:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_fa2ft_md_flow_mode_transition:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_fa2ft_flow_mode_transition:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/is_fa2ft_flow_mode_transition:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2
Nov 8 15:19:28.895: //20927/000000000000/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS
Nov 8 15:19:28.899: //20927/000000000000/SIP/Info/info/4096/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 400000
Nov 8 15:19:28.899: //20927/000000000000/SIP/Info/info/4096/ccsip_call_setup_request:
This a IPIP call: Chan 0, codec 6 channel 8248, ip 10.0.0.12:8248 params 0x24040440 caps 0x24E2BC9C
Nov 8 15:19:28.899: //20927/000000000000/SIP/Info/info/4096/ccsip_call_setup_request:
This a IPIP call: Chan 1, codec -1 channel 8248, ip 10.0.0.12:8248 params 0x24040440 caps 0x24E2BC9C
Nov 8 15:19:28.899: //20927/000000000000/SIP/Info/info/4096/ccsip_call_setup_request:
This a IPIP call: Chan 2, codec -1 channel 8248, ip 10.0.0.12:8248 params 0x24040440 caps 0x24E2BC9C
Nov 8 15:19:28.899: //20927/000000000000/SIP/Info/info/4096/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 400000
Nov 8 15:19:28.899: //20927/000000000000/SIP/Info/verbose/4096/ccsip_call_setup_request: Copy over rediectNumber from call info
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/ccsip_call_setup_request: Copy over rediectNumber from ssInfo
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/ccsip_call_setup_request: ccb->call_info.origRedirectNumber = 2111111
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/ccsip_call_setup_request: Number Translation Set For Called-Number
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Error/sipSPIGetCallServerGroupTargets:
No server group configured
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/5120/ccsip_call_setup_request: No dest server group configured
Nov 8 15:19:28.899: //-1/xxxxxxxxxxxx/SIP/Info/verbose/5120/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 10.46.0.1 target_port : 5060

Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 51BF to table
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/notify/131072/ccsip_call_setup_request: Incrementing call counter to [1] in dial-peer [199]
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/ccsip_call_setup_request: Posting PRE_SETUP event to IWF.
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 0, Event Id: CC_EV_SIP_PRE_SETUP
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_PRE_SETUP
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sip_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_PRE_SETUP
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/1/sip_iwf_sip_ed_pre_setup_hdlr: Deferring SETUP till peer channel event.
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/2049/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/sipSPI_set_mid_call_sig_not_supported: ReSetting mid call sig not supported
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/16384/sipSPI_reset_block_chan_ind: Resetting the block channel id flags
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/2048/sipSPI_ipip_store_config_info: Setting mid_call_config_info = 0x0 for callid = 20927
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/32768/sipSPIGetCallConfig: Media Antitrombone disabled
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/notify/131072/sipSPICanSetFallbackFlag: Local Fallback is not active
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/8192/sipSPIGetCallConfig: VRF id = 0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/6144/sipSPI_ipip_read_peer_config_info: Mid-call Config info for peer leg is 0x0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/6144/sipSPI_ipip_read_peer_config_info: Config info for peer leg is 0x0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/4/update_video_params_from_config: Checking Video Type Rate=-1 video_codec_allowed=1F
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: STUN Usage is not enabled
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=20923
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg..
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/8704/sipSPIGetCallConfig: Incoming: No defer BYE for last
call stats
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp configure for this leg.
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: en_p->encap_s.voIP.voipPeerCfgMediaClass = 0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer has no media class recorder.
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done...
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/32768/ccsip_ipip_media_forking_intra_frame_request_config: MF: FIR en_p->encap_s.voIP.voipPeerCfgMediaClass = 0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/32768/ccsip_ipip_media_forking_get_forked_leg_config: MF: This leg is not forked call leg.
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/critical/11264/ccsipInitDSCPPolicyInfo: No DSCP Profile configured, No RPH 2 DSCP Mapping and DSCP policing
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/8192/sipSPIGetCallConfig: Initilise the DSCP policy
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE
Nov 8 15:19:28.899: //20927/937494A982DD/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_event_handler: Received event : 196)
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: EV_UNDEFINED
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_MODE
Nov 8 15:19:28.899: [0x3B2BEE88]CNFSM: cur_container:sip_iwf_sip_mid_dialog_container, cur_state:S_SIP_IWF_SDP_DONE, event:E_SIP_IWF_EV_SET_MODE
Nov 8 15:19:28.899: [0x3B2BEE88]CNFSM: new_container:sip_iwf_main_container
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_mode_sip_sip_md_snr:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_mode_sip_sip_ed_snr:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_mode_sip_sip_md:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/sip_iwf_sip_md_set_mode_hdlr: Setting SPI mode to SIP-SIP
Nov 8 15:19:28.899: [0x3B2BEE88]CNFSM: new_container:sip_iwf_sip_mid_dialog_container
Nov 8 15:19:28.899: [0x3B2BEE88]CNFSM: next_state:CNFSM_NO_STATE_CHANGE
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_iwf_map_cc_return_code: Mapping SIP_IWF_SUCCESS
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: CC_EV_IF_DIAG_DONE
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_FLOW_MODE
Nov 8 15:19:28.899: [0x3B2BEE88]CNFSM: cur_container:sip_iwf_sip_mid_dialog_container, cur_state:S_SIP_IWF_SDP_DONE, event:E_SIP_IWF_EV_SET_FLOW_MODE
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_fa2fa_flow_mode_transition:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_ft2fa_flow_mode_transition:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.899: [0x3B2BEE88]CNFSM: new_container:sip_iwf_main_container
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_fa2ft_md_flow_mode_transition:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_fa2ft_flow_mode_transition:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/is_fa2ft_flow_mode_transition:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev:
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2
Nov 8 15:19:28.899: //20923/8BD06BC282D6/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS
Nov 8 15:19:28.899: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8
Nov 8 15:19:28.899: //20926/8BD06BC282D6/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 40009 active bw 0 Kbps
Nov 8 15:19:28.899: //20926/8BD06BC282D6/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface GigabitEthernet0/2 bw 80 Kbps
Nov 8 15:19:28.899: //20926/8BD06BC282D6/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps
Nov 8 15:19:28.899: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIUcccause_to_sipcause:
Unknown PSTN cause code from CCAPI:0
Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3B36F930 with refCount = 1
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/info/4096/sipSPISendCancel: Associated container=0x3B2C4840 to Cancel
Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Transport/sipSPISendCancel: Sending CANCEL to the transport layer
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Transport/sipSPITransportSendMessage: msg=0x3B36F930, addr=10.46.1.10, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x35F25CA0
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.46.1.10, rport:5060 with laddr:

Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x3FEC3150 is already on connection=0x3F47E1BC context_list
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x3B36F930
Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3B36F930, addr=10.46.1.10, port=5060, local_addr=, connId=4 vrfid=0 for UDP
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Info/info/512/sentCancelDisconnecting: Sent Cancel Request, starting CancelWaitResponseTimer
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/State/sipSPIChangeState: 0x3FEC3150 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE)
Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 15
Nov 8 15:19:28.903: //20926/8BD06BC282D6/SIP/Msg/ccsipDisplayMsg:
Sent:
CANCEL sip:117@10.46.1.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.46.1.1:5060;branch=z9hG4bK7027F84
From: <sip:933333333@sip.telecom.dd>;tag=425FCC58-1CF8
To: <sip:117@10.46.1.10>
Date: Tue, 08 Nov 2016 15:19:20 GMT
Call-ID: 8EA92B8A-A4FD11E6-82DCB6B6-5AB7FB3C@10.46.1.1
CSeq: 101 CANCEL
Max-Forwards: 10
Timestamp: 1478618368
Reason: Q.850;cause=0
Content-Length: 0

Nov 8 15:19:28.903: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3B36F930
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x24D29558 with refCount = 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x23FFFF0C with refCount = 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.46.1.10]:5060, local_address:[ - ]
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x24D29558
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK7027F84 from via branch list
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIRemoveBranchName:
invalid ccb, bName or branch list for sipSPIRemoveBranchName
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x23FFFF0C) counter, current msg->refCount = 2
Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.46.1.1:5060;branch=z9hG4bK7027F84
From: <sip:933333333@sip.telecom.dd>;tag=425FCC58-1CF8
To: <sip:117@10.46.1.10>;tag=c47295a9706601af04acce72-47921555
Call-ID: 8EA92B8A-A4FD11E6-82DCB6B6-5AB7FB3C@10.46.1.1
Date: Tue, 08 Nov 2016 15:19:19 GMT
CSeq: 101 CANCEL
Server: Cisco-CP7821/10.3.1
Content-Length: 0

Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX
Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [2] Method Code [104]

Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:111358254 ConnTime 0
Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Media/sipSPIHandleDestroyRtpSession: stream:24DECCF4
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3F63781C
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x23FFFF0C) counter, current msg->refCount = 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x24D29558 with refCount = 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3B2F0AC4 with refCount = 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.46.1.10]:5060, local_address:[ - ]
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x24D29558
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
Nov 8 15:19:28.907: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3B2F0AC4) counter, current msg->refCount = 2
Nov 8 15:19:28.907: //20926/8BD06BC282D6/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/UDP 10.46.1.1:5060;branch=z9hG4bK7027F84
From: <sip:933333333@sip.telecom.dd>;tag=425FCC58-1CF8
To: <sip:117@10.46.1.10>;tag=c47295a9706601af04acce72-47921555
Call-ID: 8EA92B8A-A4FD11E6-82DCB6B6-5AB7FB3C@10.46.1.1
Date: Tue, 08 Nov 2016 15:19:19 GMT
CSeq: 101 INVITE
Server: Cisco-CP7821/10.3.1
Contact: <sip:A5CC-17AE@10.46.1.10:5060;transport=udp>
Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO
Remote-Party-ID: "P17" <sip:117@10.46.1.1>;party=called;id-type=subscriber;privacy=off;screen=yes
Allow-Events: kpml,dialog
Content-Length: 0

Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/1024/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/32768/ccsip_ipip_media_forking_copy_prev_best_rpid: MF: Delete the previous remote party id..
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/32768/ccsip_ipip_media_forking_copy_prev_best_rpid: MF: This is best rpid..
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/4096/sipSPISetInfoFromRpid: calling host comes from rpid 10.46.1.1
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/4096/sipSPISetInfoFromRpid: Received current remote name: P17, current remote number: 117
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/4096/sipSPISetInfoFromRpid: Received ;screen=yes ;privacy=off -> Setting Octet3A 0x81, extended_privacy 0x00
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [4] Method Code [102]

Nov 8 15:19:28.911: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x24D29558 with refCount = 1
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/4096/sipSPIChangeDeferAckState: Change state from 0 to new state 0, called from :sipSPIPresendProcessing
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 1 event
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/4096/ccsip_offer_ans_handle_call_active:
Nov 8 15:19:28.911: [0x3B2C3D40]CNFSM: cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_SENT, event:E_SIP_DIALOG_ESTD
Nov 8 15:19:28.911: [0x3B2C3D40]CNFSM: next_state:CNFSM_NO_STATE_CHANGE
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/critical/1/ccsip_offer_ans_process_event: O/A - an event is deferred
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/critical/4096/ccsip_offer_ans_event_defer: an event is deferred
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/4096/sipSPISendAck: Associated container=0x3B2BEC78 to Ack
Nov 8 15:19:28.911: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Transport/sipSPITransportSendMessage: msg=0x24D29558, addr=10.46.1.10, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x35F26120
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
Nov 8 15:19:28.911: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.46.1.10, rport:5060 with laddr:

Nov 8 15:19:28.911: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x3FEC3150 is already on connection=0x3F47E1BC context_list
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x24D29558
Nov 8 15:19:28.911: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x24D29558, addr=10.46.1.10, port=5060, local_addr=, connId=4 vrfid=0 for UDP
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/critical/512/sentErrorResponseCallClose: Sent Error Response since the Gw is Shutdown
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/8192/sipSPIDeferCallClose: Not split dataplane, bail
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/8192/sipSPIWaitForStatsBforeCallClose: Not split dataplane, bail
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat:
sipSPICallCloseAfterFinalStat:
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/State/sipSPIChangeState: 0x3FEC3150 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x0x3FEC3150
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number : 933333333
Called Number : 117
Source IP Address (Sig ): 10.46.1.1
Destn SIP Req Addr:Port : 10.46.1.10:5060
Destn SIP Resp Addr:Port : 10.46.1.10:5060
Destination Name : 10.46.1.10

Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Nego. Codec payload : 255 (tx), 255 (rx)
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0 (tx), 0 (rx)
Source IP Address (Media): 10.46.1.1
Source IP Port (Media): 22500
Destn IP Address (Media): -
Destn IP Port (Media): 0
Orig Destn IP Address:Port (Media): [ - ]:0

Nov 8 15:19:28.911: //20926/8BD06BC282D6/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 0
Disconnect Cause (SIP) : 487
ACK sip:117@10.46.1.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.46.1.1:5060;branch=z9hG4bK7027F84
From: <sip:933333333@sip.telecom.dd>;tag=425FCC58-1CF8
To: <sip:117@10.46.1.10>;tag=c47295a9706601af04acce72-47921555
Date: Tue, 08 Nov 2016 15:19:20 GMT
Call-ID: 8EA92B8A-A4FD11E6-82DCB6B6-5AB7FB3C@10.46.1.1
Max-Forwards: 10
CSeq: 101 ACK
Allow-Events: kpml, telephone-event
Content-Length: 0

Nov 8 15:19:28.911: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x24D29558
undebug
% Incomplete command.

[emily.stemmerich]

Did you ever get this sorted out?  I'm having the same issue.

[Nikolay Pestov]

Try to set:

voice service voip

      supplementary-service sip moved-temporarily