Solved: ucxsi not receiving ringing notification

tj1 · ‎04-22-2015

Hi,

I'm having problem where the application is not receiving ringing notification event. It is receiving OUT_OF_SERVICE and BACK_IN_SERVICE.

ID DN Num Tag Mac MRef CreateTime #Msg

==== ========== === ============ ==== ==================== ====

32625 66363 0 001AA1E55F70 0 Apr 22 2015 06:09:11 7

#MSG corresponds with the OUT_OF_SERVICE and BACK_IN_SERVICE message being received.

Raghavendra G V · ‎04-28-2015

Looks like you are passing empty call, please try to get CMECall from CMECallConnectionRingingEvent and pass to answer method.

Thanks,

Raghavendra

View solution in original post

Raghavendra G V · ‎04-22-2015

Hi,

Please share the SDK debugs, hope you have implemented the CMECSTAListener.

Thanks,

Raghavendra

tj1 · ‎04-22-2015

Hi Raghavendra,

debug below. Yes, I have implemented the CMECSTAListener.

Thanks

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 1 to index 119

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1727E524 with refCount = 1

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13BF0BC8 with refCount = 1

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1727E524

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, connid=119, transport=TCP

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 59575 connId 119

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

REGISTER sip:172.28.218.1:5060;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~5

Max-Forwards: 70

To: <sip:davecallconnector@172.28.218.1>

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

Call-ID: 14296485727041@172.28.218.1

CSeq: 4 REGISTER

Content-Length: 0

Contact: <sip:null@172.28.250.93:5070;transport=tcp>;expires=120

X-cisco-session-server: davecallconnector

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x15D6F0F0) with key=[5652] to table

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 172.28.250.93:59575,natted src: 172.28.218.1:5060, natted transport: 2

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 172.28.250.93

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0

Apr 21 20:37:40.764: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 172.28.254.130 for SIP

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.28.254.130

Apr 21 20:37:40.764: //-1/16E06104AA98/SIP/State/sipSPIChangeState: 0x15D6F0F0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5060vrfid 0

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone AEST to SIP default timezone = GMT

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:37:40.764: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x13BF0BC8) counter, current msg->refCount = 2

Apr 21 20:37:40.764: //-1/16E06104AA98/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x15D6F0F0)->last_request = 0x13BF0BC8, refCount = 2

Apr 21 20:37:40.764: //-1/16E06104AA98/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x15D6F0F0 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f balance 0

Apr 21 20:37:40.764: //32697/16E06104AA98/SIP/Event/sact_idle_new_message_register:

ccsip_api_register_ind return value : SIP_SUCCESS

Apr 21 20:37:40.764: //32697/16E06104AA98/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 7FB9 to table

Apr 21 20:37:40.764: //32697/16E06104AA98/SIP/State/sipSPIChangeState: 0x15D6F0F0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)

Apr 21 20:37:40.764: //32697/16E06104AA98/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x174F4B58]

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Re-Register not for passthrough, Try CME

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: CCSIP_REGISTER:: re-REGISTER request

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 32690

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Error/sipSPILineGetVersionStr:

Failed to get supported header value

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/ccsipRegisterStartRCBTimer: Starting timer for pattern davecallconnector for 120 seconds

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Error/ccsipCheckVoiceRegSupportedFeatures:

Unable to access supported header values

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1727E524 with refCount = 1

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x102EF370 to REGISTER Response 200

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Transport/sipSPITransportSendMessage: msg=0x1727E524, addr=172.28.250.93, port=59575, sentBy_port=5070, local_addr=, is_req=0, transport=2, switch=0, callBack=0x97DA6F8

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x1727E524, addr=172.28.250.93, port=59575, local_addr=, connId=119 vrfid=0 for TCP

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x15D6F0F0 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 7FB9

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[5652] removed.

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x13BF0BC8) counter, current msg->refCount = 1

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, unregistering context=0x15D6F0F0

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x15D6F0F0 from the connection; gcb might be locked

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13BF0BC8

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer

Apr 21 20:37:40.768: //32697/16E06104AA98/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x15D6F0F0

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5652]

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPITransportSendMessage: gcb has cleanedup, Done with send operations for this context

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5652]

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 119, fd: 1

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 200 OK

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~5

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

To: <sip:davecallconnector@172.28.218.1>;tag=83E69AEC-1BDA

Date: Tue, 21 Apr 2015 20:37:40 GMT

Call-ID: 14296485727041@172.28.218.1

Server: Cisco-SIPGateway/IOS-15.4.3.M1

CSeq: 4 REGISTER

X-cisco-referenceID: FB47A3FE

Contact: <sip:davecallconnector@172.28.250.93:5070;transport=tcp>;expires=60

Expires: 60

Content-Length: 0

Apr 21 20:37:40.768: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1727E524

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_reg_number_table:

No entry found in reg Number Table for davecallconnector

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_delete_from_cc_call_id_table:

Entry not found for search key

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_reg_delete_from_call_id_table: ****Delete from sipCallID Table

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/ccsipGetCCBFromRCB: Retrived CCB pointer [0x0]

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_spi_register_free_rcb:

Error in unregistering davecallconnector@172.28.250.93

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIFreePthruDataFromRPCBorRCB: RCB =[0x102BD7B4].. RPCB =[0x0]

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Info/verbose/9216/sipSPIPassThruHdrContainerFreeHelper: Data -->[0x0]

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_PassthruContentContainerFreeHelper:

Null ContentQ - Exit

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_rpcb_search_cc_call_id_table:

No entry found in ccCallID Table

Apr 21 20:37:44.844: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_free_rcb: Freeing rcb [0x102BD7B4]

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[5650] removed.

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: free ccb->call_info.origRedirectNumber

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x15D4F188 key=CEF395E-E79D11E4-AA97AB81-28935809@172.28.218.1

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x4006816C

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x25C4564, addr=172.28.218.2, port=5060, local_addr=, unregistering context=0x15D4F188

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x15D4F188 from the connection=0x25C4E38 context list

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_api_initiate_subscription_termination: Queued event from SIP SPI : SIPSPI_EV_SUBSCRIPTION_TERMINATED

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer

Apr 21 20:38:00.068: //32696/0CED64E6AA93/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x15D4F188

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE]

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/act_subscription_terminated: Resetting server EDB flag

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/info/4096/sipSPITerminateEvent: 1 Events still active on this Subscription Dialog

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE]

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/act_subscription_terminated: Resetting Client EDB flag

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneEDB: There are 1 EDBs on edbQ

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneEDB: DeQ'd EDB(0x2A63E64)

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFreeOneEDB: EnQing EDB(0x2A63E64) for reuse

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/sipSPITerminateEvent: Freeing SCB(0x42A3111C), 0 active events present

Apr 21 20:38:00.068: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[5651] removed.

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/sipSPIRemoveSCBFromClientTable: Removing SCB(0x42A3111C) with Key(CEF395E-E79D11E4-AA97AB81-28935809@172.28.218.183E659C4-1A8D) from Client Table

Apr 21 20:38:00.068: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneSCB: EnQing SCB(0x42A3111C) for reuse

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 1 to index 119

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, connid=119, transport=TCP

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 59575 connId 119

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

REGISTER sip:172.28.218.1:5060;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~6

Max-Forwards: 70

To: <sip:davecallconnector@172.28.218.1>

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

Call-ID: 14296485727041@172.28.218.1

CSeq: 5 REGISTER

Content-Length: 0

Contact: <sip:null@172.28.250.93:5070;transport=tcp>;expires=120

X-cisco-session-server: davecallconnector

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x15D4F188) with key=[5653] to table

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 172.28.250.93:59575,natted src: 172.28.218.1:5060, natted transport: 2

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 172.28.250.93

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0

Apr 21 20:38:10.832: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 172.28.254.130 for SIP

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.28.254.130

Apr 21 20:38:10.832: //-1/28CC62ACAA99/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5060vrfid 0

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone AEST to SIP default timezone = GMT

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x47020AE0) counter, current msg->refCount = 2

Apr 21 20:38:10.832: //-1/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x15D4F188)->last_request = 0x47020AE0, refCount = 2

Apr 21 20:38:10.832: //-1/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x15D4F188 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f balance 0

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Event/sact_idle_new_message_register:

ccsip_api_register_ind return value : SIP_SUCCESS

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 7FBA to table

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x174F4B58]

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Re-Register not for passthrough, Try CME

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: CCSIP_REGISTER:: re-REGISTER request

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 32690

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Error/sipSPILineGetVersionStr:

Failed to get supported header value

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/ccsipRegisterStartRCBTimer: Starting timer for pattern davecallconnector for 120 seconds

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Error/ccsipCheckVoiceRegSupportedFeatures:

Unable to access supported header values

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x102F0B80 to REGISTER Response 200

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Transport/sipSPITransportSendMessage: msg=0x13F54F14, addr=172.28.250.93, port=59575, sentBy_port=5070, local_addr=, is_req=0, transport=2, switch=0, callBack=0x97DA6F8

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x13F54F14, addr=172.28.250.93, port=59575, local_addr=, connId=119 vrfid=0 for TCP

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x15D4F188 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 7FBA

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[5653] removed.

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x47020AE0) counter, current msg->refCount = 1

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, unregistering context=0x15D4F188

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x15D4F188 from the connection; gcb might be locked

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer

Apr 21 20:38:10.832: //32698/28CC62ACAA99/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x15D4F188

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5653]

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPITransportSendMessage: gcb has cleanedup, Done with send operations for this context

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5653]

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 119, fd: 1

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 200 OK

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~6

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

To: <sip:davecallconnector@172.28.218.1>;tag=83E71060-D80

Date: Tue, 21 Apr 2015 20:38:10 GMT

Call-ID: 14296485727041@172.28.218.1

Server: Cisco-SIPGateway/IOS-15.4.3.M1

CSeq: 5 REGISTER

X-cisco-referenceID: FB47A3FE

Contact: <sip:davecallconnector@172.28.250.93:5070;transport=tcp>;expires=60

Expires: 60

Content-Length: 0

Apr 21 20:38:10.832: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

dcmhrc02#show cti session

ID DN Num Tag Mac MRef CreateTime #Msg

==== ========== === ============ ==== ==================== ====

32691 66363 0 001AA1E55F70 0 Apr 22 2015 06:36:15 1

dcmhrc02#conf t

Enter configuration commands, one per line. End with CNTL/Z.

dcmhrc02(config)#ephone

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 1 to index 119

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, connid=119, transport=TCP

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 59575 connId 119

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

REGISTER sip:172.28.218.1:5060;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~7

Max-Forwards: 70

To: <sip:davecallconnector@172.28.218.1>

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

Call-ID: 14296485727041@172.28.218.1

CSeq: 6 REGISTER

Content-Length: 0

Contact: <sip:null@172.28.250.93:5070;transport=tcp>;expires=120

X-cisco-session-server: davecallconnector

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x15D4F188) with key=[5654] to table

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 172.28.250.93:59575,natted src: 172.28.218.1:5060, natted transport: 2

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 172.28.250.93

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0

Apr 21 20:38:40.896: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 172.28.254.130 for SIP

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.28.254.130

Apr 21 20:38:40.896: //-1/3AB7C792AA9A/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5060vrfid 0

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone AEST to SIP default timezone = GMT

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x47020AE0) counter, current msg->refCount = 2

Apr 21 20:38:40.896: //-1/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x15D4F188)->last_request = 0x47020AE0, refCount = 2

Apr 21 20:38:40.896: //-1/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x15D4F188 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f balance 0

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Event/sact_idle_new_message_register:

ccsip_api_register_ind return value : SIP_SUCCESS

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 7FBB to table

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x174F4B58]

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Re-Register not for passthrough, Try CME

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: CCSIP_REGISTER:: re-REGISTER request

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 32690

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Error/sipSPILineGetVersionStr:

Failed to get supported header value

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/ccsipRegisterStartRCBTimer: Starting timer for pattern davecallconnector for 120 seconds

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Error/ccsipCheckVoiceRegSupportedFeatures:

Unable to access supported header values

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x102F0B80 to REGISTER Response 200

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Transport/sipSPITransportSendMessage: msg=0x13F54F14, addr=172.28.250.93, port=59575, sentBy_port=5070, local_addr=, is_req=0, transport=2, switch=0, callBack=0x97DA6F8

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x13F54F14, addr=172.28.250.93, port=59575, local_addr=, connId=119 vrfid=0 for TCP

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x15D4F188 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 7FBB

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[5654] removed.

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x47020AE0) counter, current msg->refCount = 1

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, unregistering context=0x15D4F188

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x15D4F188 from the connection; gcb might be locked

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer

Apr 21 20:38:40.896: //32699/3AB7C792AA9A/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x15D4F188

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5654]

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPITransportSendMessage: gcb has cleanedup, Done with send operations for this context

Apr 21 20:38:40.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5654]

Apr 21 20:38:40.900: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event ty 1

dcmhrc02(config-ephone)#pe: send msg, connid: 119, fd: 1

Apr 21 20:38:40.900: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 200 OK

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~7

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

To: <sip:davecallconnector@172.28.218.1>;tag=83E785D0-BC0

Date: Tue, 21 Apr 2015 20:38:40 GMT

Call-ID: 14296485727041@172.28.218.1

Server: Cisco-SIPGateway/IOS-15.4.3.M1

CSeq: 6 REGISTER

X-cisco-referenceID: FB47A3FE

Contact: <sip:davecallconnector@172.28.250.93:5070;transport=tcp>;expires=60

Expires: 60

Content-Length: 0

Apr 21 20:38:40.900: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14reset

resetting 001A.A1E5.5F70

dcmhrc02(config-ephone)#

Apr 21 20:38:44.536: //CTI/LM:cti_update_cme_line_status mac addr 001AA1E55F70 number 66363 line status 0 normal 1 line removed 0 line shared 0 cti notify 1

Apr 21 20:38:44.536: //CTI/SM:sm_find_context_ids_by_line num 66363, tag 0, mac 001AA1E55F70, prev 0, expanded 0

Apr 21 20:38:44.536: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:38:44.536: //CTI/CM: target_node 16FD7830

Apr 21 20:38:44.536: //CTI/CM: - dn 66363

Apr 21 20:38:44.536: %IPPHONE-6-UNREGISTER_NORMAL: ephone-1:SEP001AA1E55F70 IP:172.28.218.138 Socket:63 DeviceType:Phone has unregistered normally.

Apr 21 20:38:44.536: //CTI/LM:lmm_process_cti_event event 15

Apr 21 20:38:44.536: //CTI/LM:lmm_process_cti_event event 14

Apr 21 20:38:44.536: //CTI/SM:sm_process_lmm_event event 15

Apr 21 20:38:44.536: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:38:44.536: //CTI/SM: to return 1544C8B0

Apr 21 20:38:44.536: //CTI/PI:pi_send_log_event event 15 context_id 32691

Apr 21 20:38:44.536: //CTI/PI:pi_build_event event 15

Apr 21 20:38:44.536: //CTI/XI:cti2csta:1076 cti_ev_type_t(15)

Apr 21 20:38:44.536: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=(001AA1E55F70)

Apr 21 20:38:44.536: //CTI/XI:cti2csta_cause: cti_cause = 1

Apr 21 20:38:44.536: //CTI/XI:cti2csta:2169 csta_EventType_t(45)

Apr 21 20:38:44.536: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(295), message(295)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier>

</device>

<cause>normal</cause>

</OutOfServiceEvent>

Apr 21 20:38:44.536: //CTI/SM:sm_process_lmm_event event 14

Apr 21 20:38:44.536: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:38:44.536: //CTI/SM: to return 1544C8B0

Apr 21 20:38:44.536: //CTI/PI:pi_send_log_event event 14 context_id 32691

Apr 21 20:38:44.536: //CTI/PI:pi_build_event event 14

Apr 21 20:38:44.536: //CTI/XI:cti2csta:1076 cti_ev_type_t(14)

Apr 21 20:38:44.536: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=()

Apr 21 20:38:44.536: //CTI/XI:cti2csta:2169 csta_EventType_t(44)

Apr 21 20:38:44.536: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(255), message(255)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

</device>

</BackInServiceEvent>

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 34

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/verbose/4096/act_active_info_request: Transaction active. Facilities/INFO requests will be queued.

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 5 event

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/4096/sipSPISendInfo: Associated container=0x102F1260 to Info

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 295

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPISendInfo: Sending INFO to the transport layer

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: msg=0x13F54F14, addr=172.28.250.93, port=5070, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=0, callBack=0x97D4514

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, unregistering context=0x15D62460

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Could not purge context gcb=0x15D62460 from the connection; gcb might be locked

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.250.93, rport:5070 with laddr:

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x15D62460 with connection=0x426367C4 context list

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x13F54F14

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x13F54F14, addr=172.28.250.93, port=5070, local_addr=, connId=120 vrfid=0 for TCP

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/512/sentInfo: Sent Info Request, starting InfoTimer

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 34

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/8192/Session-Timer/sipSTSLMain:

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/verbose/4096/act_active_info_request: Transaction active. Facilities/INFO requests will be queued.

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 5 event

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/4096/sipSPISendInfo: Associated container=0x102E4790 to Info

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 255

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPISendInfo: Sending INFO to the transport layer

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: msg=0x47020AE0, addr=172.28.250.93, port=5070, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=0, callBack=0x97D4514

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.250.93, rport:5070 with laddr:

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x15D62460 is already on connection=0x426367C4 context_list

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x47020AE0

Apr 21 20:38:44.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x47020AE0, addr=172.28.250.93, port=5070, local_addr=, connId=120 vrfid=0 for TCP

Apr 21 20:38:44.536: //32691/E3856E28AA86/SIP/Info/info/512/sentInfo: Sent Info Request, starting InfoTimer

Apr 21 20:38:44.540: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 120, fd: 2

Apr 21 20:38:44.540: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Sent:

INFO sip:66363_001AA1E55F70@172.28.250.93:5070;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B01385

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

Date: Tue, 21 Apr 2015 20:36:14 GMT

Call-ID: 14296485768312@192.168.1.10

User-Agent: Cisco-SIPGateway/IOS-15.4.3.M1

Max-Forwards: 70

Timestamp: 1429648724

CSeq: 101 INFO

Contact: <sip:66363@172.28.254.130:5060;transport=tcp>

Content-Type: application/csta+xml

Content-Disposition: signal;handling=required

Content-Length: 295

<?xml version="1.0" encoding="UTF-8"?>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier></device>

<cause>normal</cause></OutOfServiceEvent>

Apr 21 20:38:44.540: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:38:44.540: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 120, fd: 2

Apr 21 20:38:44.540: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sip_tcp_sendmsg: Socket blocked data queued

Apr 21 20:38:44.540: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipTcpQueueSendData: Data queued length: 835

Apr 21 20:38:44.540: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:38:44.548: //-1/xxxxxxxxxxxx/SIP/Info/sip_tcp_resend: Socket blocked requeue data

Apr 21 20:38:44.556: //-1/xxxxxxxxxxxx/SIP/Info/sip_tcp_resend: Socket blocked requeue data

Apr 21 20:38:44.564: //-1/xxxxxxxxxxxx/SIP/Info/sip_tcp_resend: Socket blocked requeue data

Apr 21 20:38:44.576: //-1/xxxxxxxxxxxx/SIP/Info/sip_tcp_resend: Socket blocked requeue data

Apr 21 20:38:44.584: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:38:44.584: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

INFO sip:66363_001AA1E55F70@172.28.250.93:5070;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B1E8B

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

Date: Tue, 21 Apr 2015 20:36:14 GMT

Call-ID: 14296485768312@192.168.1.10

User-Agent: Cisco-SIPGateway/IOS-15.4.3.M1

Max-Forwards: 70

Timestamp: 1429648724

CSeq: 102 INFO

Contact: <sip:66363@172.28.254.130:5060;transport=tcp>

Content-Type: application/csta+xml

Content-Disposition: signal;handling=required

Content-Length: 255

<?xml version="1.0" encoding="UTF-8"?>

Apr 21 20:38:44.584: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 120

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x42635D70

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=5070, local_addr=, connid=120, transport=TCP

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5070 connId 120

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:38:44.592: //32691/E3856E28AA86/SIP/Info/info/1024/sipSPIMatchRespToReqTran: match z9hG4bK24B01385 to via_branch_list - remove and continue

Apr 21 20:38:44.592: //32691/E3856E28AA86/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x15D62460

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x13F54F14) counter, current msg->refCount = 2

Apr 21 20:38:44.592: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 Ok

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B01385

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

Call-ID: 14296485768312@192.168.1.10

CSeq: 101 INFO

Content-Length: 0

Content-Type: application/csta+xml

Apr 21 20:38:44.592: //32691/E3856E28AA86/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX

Apr 21 20:38:44.592: //32691/E3856E28AA86/SIP/Info/verbose/4096/sact_active_new_message_response: Transaction Complete. Lock on Facilities/INFO released.

Apr 21 20:38:44.592: //32691/E3856E28AA86/SIP/Info/verbose/32768/ccsip_api_info_done: RTP_LPBK == FALSE, checkpoint HA data

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x13F54F14) counter, current msg->refCount = 1

Apr 21 20:38:44.592: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:38:44.592: //CTI/PI:cti_frontend_proc [7FB3]: received CC Event [21]: CC_EV_CALL_INFO_ACK

Apr 21 20:38:44.592: //CTI/PI:pi_process_service_event event 21

Apr 21 20:38:44.592: //CTI/PI: got CC_EV_CALL_INFO_ACK callID 32691

Apr 21 20:38:44.592: //CTI/SM:sm_handle_cc_service event 85

Apr 21 20:38:44.592: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:38:44.596: //CTI/SM: to return 1544C8B0

Apr 21 20:38:44.596: //CTI/SM: got CTI_EV_ACK, callID 32691

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 120

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x42635D70

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=5070, local_addr=, connid=120, transport=TCP

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5070 connId 120

Apr 21 20:38:44.632: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:38:44.636: //32691/E3856E28AA86/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK24B1E8B from via branch list

Apr 21 20:38:44.636: //32691/E3856E28AA86/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x15D62460

Apr 21 20:38:44.636: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x47020AE0) counter, current msg->refCount = 2

Apr 21 20:38:44.636: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 Ok

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B1E8B

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

Call-ID: 14296485768312@192.168.1.10

CSeq: 102 INFO

Content-Length: 0

Content-Type: application/csta+xml

Apr 21 20:38:44.636: //32691/E3856E28AA86/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX

Apr 21 20:38:44.636: //32691/E3856E28AA86/SIP/Info/verbose/4096/sact_active_new_message_response: Transaction Complete. Lock on Facilities/INFO released.

Apr 21 20:38:44.636: //32691/E3856E28AA86/SIP/Info/verbose/32768/ccsip_api_info_done: RTP_LPBK == FALSE, checkpoint HA data

Apr 21 20:38:44.636: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x47020AE0) counter, current msg->refCount = 1

Apr 21 20:38:44.636: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:38:44.636: //CTI/PI:cti_frontend_proc [7FB3]: received CC Event [21]: CC_EV_CALL_INFO_ACK

Apr 21 20:38:44.636: //CTI/PI:pi_process_service_event event 21

Apr 21 20:38:44.636: //CTI/PI: got CC_EV_CALL_INFO_ACK callID 32691

Apr 21 20:38:44.636: //CTI/SM:sm_handle_cc_service event 85

Apr 21 20:38:44.636: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:38:44.636: //CTI/SM: to return 1544C8B0

Apr 21 20:38:44.636: //CTI/SM: got CTI_EV_ACK, callID 32691

dcmhrc02(config-ephone)#^Z

dcmhrc02#sh

Apr 21 20:38:47.544: %SYS-5-CONFIG_I: Configured from console by network on vty8 (172.28.250.93)ow cti sess

dcmhrc02#show cti session

ID DN Num Tag Mac MRef CreateTime #Msg

==== ========== === ============ ==== ==================== ====

32691 66363 0 001AA1E55F70 0 Apr 22 2015 06:36:15 3

dcmhrc02#show cti session

ID DN Num Tag Mac MRef CreateTime #Msg

==== ========== === ============ ==== ==================== ====

32691 66363 0 001AA1E55F70 0 Apr 22 2015 06:36:15 3

dcmhrc02#

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 1 to index 119

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1060BAF8 with refCount = 1

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, connid=119, transport=TCP

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 59575 connId 119

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

REGISTER sip:172.28.218.1:5060;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~8

Max-Forwards: 70

To: <sip:davecallconnector@172.28.218.1>

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

Call-ID: 14296485727041@172.28.218.1

CSeq: 7 REGISTER

Content-Length: 0

Contact: <sip:null@172.28.250.93:5070;transport=tcp>;expires=120

X-cisco-session-server: davecallconnector

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x15D4F188) with key=[5655] to table

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 172.28.250.93:59575,natted src: 172.28.218.1:5060, natted transport: 2

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 172.28.250.93

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0

Apr 21 20:39:10.964: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 172.28.254.130 for SIP

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.28.254.130

Apr 21 20:39:10.964: //-1/4CA3C8A1AA9B/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5060vrfid 0

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone AEST to SIP default timezone = GMT

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x1060BAF8) counter, current msg->refCount = 2

Apr 21 20:39:10.964: //-1/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x15D4F188)->last_request = 0x1060BAF8, refCount = 2

Apr 21 20:39:10.964: //-1/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x15D4F188 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f balance 0

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Event/sact_idle_new_message_register:

ccsip_api_register_ind return value : SIP_SUCCESS

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 7FBC to table

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x174F4B58]

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Re-Register not for passthrough, Try CME

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: CCSIP_REGISTER:: re-REGISTER request

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 32690

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Error/sipSPILineGetVersionStr:

Failed to get supported header value

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/ccsipRegisterStartRCBTimer: Starting timer for pattern davecallconnector for 120 seconds

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Error/ccsipCheckVoiceRegSupportedFeatures:

Unable to access supported header values

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13F54F14 with refCount = 1

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x102F24F0 to REGISTER Response 200

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Transport/sipSPITransportSendMessage: msg=0x13F54F14, addr=172.28.250.93, port=59575, sentBy_port=5070, local_addr=, is_req=0, transport=2, switch=0, callBack=0x97DA6F8

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x13F54F14, addr=172.28.250.93, port=59575, local_addr=, connId=119 vrfid=0 for TCP

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x15D4F188 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 7FBC

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[5655] removed.

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x1060BAF8) counter, current msg->refCount = 1

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, unregistering context=0x15D4F188

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x15D4F188 from the connection; gcb might be locked

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1060BAF8

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer

Apr 21 20:39:10.964: //32700/4CA3C8A1AA9B/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x15D4F188

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5655]

Apr 21 20:39:10.964: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPITransportSendMessage: gcb has cleanedup, Done with send operations for this context

Apr 21 20:39:10.968: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[5655]

Apr 21 20:39:10.968: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 119, fd: 1

Apr 21 20:39:10.968: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 200 OK

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~8

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

To: <sip:davecallconnector@172.28.218.1>;tag=83E7FB44-1220

Date: Tue, 21 Apr 2015 20:39:10 GMT

Call-ID: 14296485727041@172.28.218.1

Server: Cisco-SIPGateway/IOS-15.4.3.M1

CSeq: 7 REGISTER

X-cisco-referenceID: FB47A3FE

Contact: <sip:davecallconnector@172.28.250.93:5070;transport=tcp>;expires=60

Expires: 60

Content-Length: 0

Apr 21 20:39:10.968: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:21.732: //CTI/CM:

Apr 21 20:39:21.732: //CTI/CM:-- trigger 1, callID 32701, dn 200990, reason 157701124, result 0

Apr 21 20:39:21.732: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:21.732: //CTI/CM: target_node 25FD778

Apr 21 20:39:21.732: //CTI/CM: - dn 200990

Apr 21 20:39:21.732: //CTI/CM: CallEntry 1012890

Apr 21 20:39:21.732: //CTI/CM: dstCallID -1

Apr 21 20:39:21.732: //CTI/CM: line_info 25FD784, dn 200990

Apr 21 20:39:21.732: //CTI/CM: * cmm_crs_proc_tr_call_orig

Apr 21 20:39:21.732: //CTI/CM: callID = 32701, CG 200990, GCID =

Apr 21 20:39:21.732: //CTI/CM:cmm_is_hairpin_leg number 200990 callID 32701

Apr 21 20:39:21.732: //CTI/CM: -- cid 32701 interface type 26

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_is_ephone_leg cid 32701 interface type 26 return TRUE530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:21.732: //CTI/CM:increase_gcid_ref_count 32701 0

Apr 21 20:39:21.732: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:21.732: //CTI/CM: target_node 0

Apr 21 20:39:21.732: //CTI/CM: Gcidinfo node Search FAILED

Apr 21 20:39:21.732: //CTI/CM:create_gcidinfo_node 32701

Apr 21 20:39:21.732: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:21.732: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:21.732: //CTI/CM: count = 1

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 404C11C8 callID 32701 dn_tag -1 dn_chan -1

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_call_inst_set_DN_tag call_inst 404C11C8 dn_tag 90 dn_chan 1

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_call_inst_set_DN_phone ccGetCallInfo ret succ. phone tag 99

Apr 21 20:39:21.732: //CTI/CM: orig --> callID 32701, line_info 25FD784, call_inst 404C11C8, gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:21.732: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:21.732: //CTI/CM: target_node 25FD778

Apr 21 20:39:21.732: //CTI/CM: - dn 200990

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:21.732: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:21.732: //CTI/CM: target_node 25FD778

Apr 21 20:39:21.732: //CTI/CM: - dn 200990

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_ORIGINATED

Apr 21 20:39:22.736: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:22.736: //CTI/CM:

Apr 21 20:39:22.736: //CTI/CM:-- trigger 14, callID 32702, dn 66363, reason 1079265368, result 317342152

Apr 21 20:39:22.736: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:22.736: //CTI/CM: target_node 16FD7830

Apr 21 20:39:22.736: //CTI/CM: - dn 66363

Apr 21 20:39:22.736: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:22.736: //CTI/CM: dstCallID 32701

Apr 21 20:39:22.736: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:22.736: //CTI/CM: * cti_cmm_crs_proc_tr_call_active

Apr 21 20:39:22.736: //CTI/CM: callID = 32702,src_callid = 32701, CG 200990, CD = 66363, GCID =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.736: //CTI/CM:increase_gcid_ref_count 32702 0

Apr 21 20:39:22.736: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:22.736: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:22.740: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.740: //CTI/CM: count = 2

Apr 21 20:39:22.740: //CTI/CM: set originalCalled = 66363

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:22.740: //CTI/CM:

Apr 21 20:39:22.740: //CTI/CM:-- trigger 2, callID 32702, dn 66363, reason -1433490559, result 680744969

Apr 21 20:39:22.740: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:22.740: //CTI/CM: target_node 16FD7830

Apr 21 20:39:22.740: //CTI/CM: - dn 66363

Apr 21 20:39:22.740: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:22.740: //CTI/CM: dstCallID 32701

Apr 21 20:39:22.740: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:22.740: //CTI/CM: * cmm_crs_proc_tr_call_offr

Apr 21 20:39:22.740: //CTI/CM: offr --> line_info 16FD783C

Apr 21 20:39:22.740: //CTI/CM: CallEntry_src 1012890, id = 32701

Apr 21 20:39:22.740: //CTI/CM: call_inst_src 404C11C8 gcid_parent 00000000-00000000-00000000-00000000

Apr 21 20:39:22.740: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:22.740: //CTI/CM: target_node 25FD778

Apr 21 20:39:22.740: //CTI/CM: - dn 200990

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 200990 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.740: //CTI/CM:cmm_find_callid_from_gcid dn 200990

Apr 21 20:39:22.740: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:22.740: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:22.740: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.740: //CTI/CM: to return callID 32701

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:22.740: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:22.740: //CTI/CM: target_node 25FD778

Apr 21 20:39:22.740: //CTI/CM: - dn 200990

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_OFFERED

Apr 21 20:39:22.740: //CTI/CM: CID = 32702, CallEntry_dst = 100A6A0, call_inst_dst = 404C2794

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 404C2794 callID 32702 dn_tag -1 dn_chan -1

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:22.748: //CTI/CM:

Apr 21 20:39:22.748: //CTI/CM:-- trigger 3, callID 32702, dn 66363, reason 1079271936, result 170250468

Apr 21 20:39:22.748: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:22.748: //CTI/CM: target_node 16FD7830

Apr 21 20:39:22.748: //CTI/CM: - dn 66363

Apr 21 20:39:22.748: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:22.748: //CTI/CM: dstCallID 32701

Apr 21 20:39:22.748: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:22.748: //CTI/CM: * cmm_crs_proc_tr_call_ring

Apr 21 20:39:22.748: //CTI/CM: call_inst_src 404C11C8 gcid_parent 00000000-00000000-00000000-00000000

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_call_inst_set_DN_tag call_inst 404C2794 dn_tag 64 dn_chan 1

Apr 21 20:39:22.748: //CTI/CM: ring --> callID 32702, line_info 16FD783C, call_inst 404C2794, gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 21 20:39:22.748: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:22.752: //CTI/CM: target_node 25FD778

Apr 21 20:39:22.752: //CTI/CM: - dn 200990

Apr 21 20:39:22.752: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 21 20:39:22.752: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 21 20:39:35.592: %IPPHONE-6-REG_ALARM: 22: Name=SEP001AA1E55F70 Load= SCCP41.8-4-4S Last=Reset-Reset

Apr 21 20:39:35.696: //CTI/LM:cti_update_cme_line_status mac addr 001AA1E55F70 number 66363 line status 0 normal 0 line removed 0 line shared 0 cti notify 1

Apr 21 20:39:35.696: //CTI/SM:sm_find_context_ids_by_line num 66363, tag 0, mac 001AA1E55F70, prev 0, expanded 0

Apr 21 20:39:35.696: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:35.696: //CTI/CM: target_node 16FD7830

Apr 21 20:39:35.696: //CTI/CM: - dn 66363

Apr 21 20:39:35.696: //CTI/LM:lmm_process_cti_event event 15

Apr 21 20:39:35.696: //CTI/LM:lmm_process_cti_event event 14

Apr 21 20:39:35.696: //CTI/SM:sm_process_lmm_event event 15

Apr 21 20:39:35.696: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:35.696: //CTI/SM: to return 1544C8B0

Apr 21 20:39:35.696: //CTI/PI:pi_send_log_event event 15 context_id 32691

Apr 21 20:39:35.696: //CTI/PI:pi_build_event event 15

Apr 21 20:39:35.696: //CTI/XI:cti2csta:1076 cti_ev_type_t(15)

Apr 21 20:39:35.696: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=(001AA1E55F70)

Apr 21 20:39:35.696: //CTI/XI:cti2csta_cause: cti_cause = 21

Apr 21 20:39:35.696: //CTI/XI:cti2csta:2169 csta_EventType_t(45)

Apr 21 20:39:35.696: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(300), message(300)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier>

</device>

<cause>maintenance</cause>

</OutOfServiceEvent>

Apr 21 20:39:35.696: //CTI/SM:sm_process_lmm_event event 14

Apr 21 20:39:35.696: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:35.696: //CTI/SM: to return 1544C8B0

Apr 21 20:39:35.696: //CTI/PI:pi_send_log_event event 14 context_id 32691

Apr 21 20:39:35.696: //CTI/PI:pi_build_event event 14

Apr 21 20:39:35.696: //CTI/XI:cti2csta:1076 cti_ev_type_t(14)

Apr 21 20:39:35.696: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=()

Apr 21 20:39:35.696: //CTI/XI:cti2csta:2169 csta_EventType_t(44)

Apr 21 20:39:35.696: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(255), message(255)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

</device>

</BackInServiceEvent>

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 34

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/verbose/4096/act_active_info_request: Transaction active. Facilities/INFO requests will be queued.

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1060BAF8 with refCount = 1

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 5 event

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/info/4096/sipSPISendInfo: Associated container=0x102F3258 to Info

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 300

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Transport/sipSPISendInfo: Sending INFO to the transport layer

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: msg=0x1060BAF8, addr=172.28.250.93, port=5070, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=0, callBack=0x97D4514

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.250.93, rport:5070 with laddr:

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x15D62460 is already on connection=0x426367C4 context_list

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x1060BAF8

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x1060BAF8, addr=172.28.250.93, port=5070, local_addr=, connId=120 vrfid=0 for TCP

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/info/512/sentInfo: Sent Info Request, starting InfoTimer

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 34

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/info/8192/Session-Timer/sipSTSLMain:

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/verbose/4096/act_active_info_request: Transaction active. Facilities/INFO requests will be queued.

Apr 21 20:39:35.696: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 5 event

Apr 21 20:39:35.696: //32691/E3856E28AA86/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Info/info/4096/sipSPISendInfo: Associated container=0x102F20D0 to Info

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 255

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Transport/sipSPISendInfo: Sending INFO to the transport layer

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: msg=0x47020AE0, addr=172.28.250.93, port=5070, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=0, callBack=0x97D4514

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.250.93, rport:5070 with laddr:

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x15D62460 is already on connection=0x426367C4 context_list

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x47020AE0

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x47020AE0, addr=172.28.250.93, port=5070, local_addr=, connId=120 vrfid=0 for TCP

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Info/info/512/sentInfo: Sent Info Request, starting InfoTimer

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 120, fd: 2

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Sent:

INFO sip:66363_001AA1E55F70@172.28.250.93:5070;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B27A4

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

Date: Tue, 21 Apr 2015 20:36:14 GMT

Call-ID: 14296485768312@192.168.1.10

User-Agent: Cisco-SIPGateway/IOS-15.4.3.M1

Max-Forwards: 70

Timestamp: 1429648775

CSeq: 103 INFO

Contact: <sip:66363@172.28.254.130:5060;transport=tcp>

Content-Type: application/csta+xml

Content-Disposition: signal;handling=required

Content-Length: 300

<?xml version="1.0" encoding="UTF-8"?>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier></device>

<cause>maintenance</cause></OutOfServiceEvent>

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1060BAF8

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 120, fd: 2

Apr 21 20:39:35.700: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Sent:

INFO sip:66363_001AA1E55F70@172.28.250.93:5070;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B317A5

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

Date: Tue, 21 Apr 2015 20:36:14 GMT

Call-ID: 14296485768312@192.168.1.10

User-Agent: Cisco-SIPGateway/IOS-15.4.3.M1

Max-Forwards: 70

Timestamp: 1429648775

CSeq: 104 INFO

Contact: <sip:66363@172.28.254.130:5060;transport=tcp>

Content-Type: application/csta+xml

Content-Disposition: signal;handling=required

Content-Length: 255

<?xml version="1.0" encoding="UTF-8"?>

Apr 21 20:39:35.700: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:39:35.748: %IPPHONE-6-REGISTER: ephone-1:SEP001AA1E55F70 IP:172.28.218.138 Socket:69 DeviceType:Phone has registered.

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 120

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1060BAF8 with refCount = 1

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x42635D70

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=5070, local_addr=, connid=120, transport=TCP

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5070 connId 120

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:39:35.752: //32691/E3856E28AA86/SIP/Info/info/1024/sipSPIMatchRespToReqTran: match z9hG4bK24B27A4 to via_branch_list - remove and continue

Apr 21 20:39:35.752: //32691/E3856E28AA86/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x15D62460

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x1060BAF8) counter, current msg->refCount = 2

Apr 21 20:39:35.752: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 Ok

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B27A4

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

Call-ID: 14296485768312@192.168.1.10

CSeq: 103 INFO

Content-Length: 0

Content-Type: application/csta+xml

Apr 21 20:39:35.752: //32691/E3856E28AA86/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX

Apr 21 20:39:35.752: //32691/E3856E28AA86/SIP/Info/verbose/4096/sact_active_new_message_response: Transaction Complete. Lock on Facilities/INFO released.

Apr 21 20:39:35.752: //32691/E3856E28AA86/SIP/Info/verbose/32768/ccsip_api_info_done: RTP_LPBK == FALSE, checkpoint HA data

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x1060BAF8) counter, current msg->refCount = 1

Apr 21 20:39:35.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1060BAF8

Apr 21 20:39:35.756: //CTI/PI:cti_frontend_proc [7FB3]: received CC Event [21]: CC_EV_CALL_INFO_ACK

Apr 21 20:39:35.756: //CTI/PI:pi_process_service_event event 21

Apr 21 20:39:35.756: //CTI/PI: got CC_EV_CALL_INFO_ACK callID 32691

Apr 21 20:39:35.756: //CTI/SM:sm_handle_cc_service event 85

Apr 21 20:39:35.756: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:35.756: //CTI/SM: to return 1544C8B0

Apr 21 20:39:35.756: //CTI/SM: got CTI_EV_ACK, callID 32691

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 120

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1060BAF8 with refCount = 1

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1060BAF8

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x42635D70

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=5070, local_addr=, connid=120, transport=TCP

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5070 connId 120

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:39:35.760: //32691/E3856E28AA86/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK24B317A5 from via branch list

Apr 21 20:39:35.760: //32691/E3856E28AA86/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x15D62460

Apr 21 20:39:35.760: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x47020AE0) counter, current msg->refCount = 2

Apr 21 20:39:35.760: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 Ok

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B317A5

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

Call-ID: 14296485768312@192.168.1.10

CSeq: 104 INFO

Content-Length: 0

Content-Type: application/csta+xml

Apr 21 20:39:35.760: //32691/E3856E28AA86/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX

Apr 21 20:39:35.760: //32691/E3856E28AA86/SIP/Info/verbose/4096/sact_active_new_message_response: Transaction Complete. Lock on Facilities/INFO released.

Apr 21 20:39:35.760: //32691/E3856E28AA86/SIP/Info/verbose/32768/ccsip_api_info_done: RTP_LPBK == FALSE, checkpoint HA data

Apr 21 20:39:35.764: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x47020AE0) counter, current msg->refCount = 1

Apr 21 20:39:35.764: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:39:35.764: //CTI/PI:cti_frontend_proc [7FB3]: received CC Event [21]: CC_EV_CALL_INFO_ACK

Apr 21 20:39:35.764: //CTI/PI:pi_process_service_event event 21

Apr 21 20:39:35.764: //CTI/PI: got CC_EV_CALL_INFO_ACK callID 32691

Apr 21 20:39:35.764: //CTI/SM:sm_handle_cc_service event 85

Apr 21 20:39:35.764: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:35.764: //CTI/SM: to return 1544C8B0

Apr 21 20:39:35.764: //CTI/SM: got CTI_EV_ACK, callID 32691

Apr 21 20:39:36.252: //CTI/LM:cti_update_cme_line_status mac addr 001AA1E55F70 number 66363 line status 1 normal 1 line removed 0 line shared 0 cti notify 1

Apr 21 20:39:36.252: //CTI/SM:sm_find_context_ids_by_line num 66363, tag 0, mac 001AA1E55F70, prev 0, expanded 0

Apr 21 20:39:36.252: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.252: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.252: //CTI/CM: - dn 66363

Apr 21 20:39:36.252: //CTI/LM:lmm_process_cti_event event 14

Apr 21 20:39:36.252: //CTI/SM:sm_process_lmm_event event 14

Apr 21 20:39:36.252: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:36.252: //CTI/SM: to return 1544C8B0

Apr 21 20:39:36.252: //CTI/PI:pi_send_log_event event 14 context_id 32691

Apr 21 20:39:36.252: //CTI/PI:pi_build_event event 14

Apr 21 20:39:36.252: //CTI/XI:cti2csta:1076 cti_ev_type_t(14)

Apr 21 20:39:36.252: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=(001AA1E55F70)

Apr 21 20:39:36.252: //CTI/XI:cti2csta:2169 csta_EventType_t(44)

Apr 21 20:39:36.252: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(275), message(275)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier>

</device>

</BackInServiceEvent>

Apr 21 20:39:36.252: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 34

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Info/verbose/4096/act_active_info_request: Transaction active. Facilities/INFO requests will be queued.

Apr 21 20:39:36.252: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 5 event

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Info/info/4096/sipSPISendInfo: Associated container=0x102F13C0 to Info

Apr 21 20:39:36.252: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 275

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Transport/sipSPISendInfo: Sending INFO to the transport layer

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: msg=0x47020AE0, addr=172.28.250.93, port=5070, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=0, callBack=0x97D4514

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:39:36.252: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.250.93, rport:5070 with laddr:

Apr 21 20:39:36.252: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x15D62460 is already on connection=0x426367C4 context_list

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x47020AE0

Apr 21 20:39:36.252: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x47020AE0, addr=172.28.250.93, port=5070, local_addr=, connId=120 vrfid=0 for TCP

Apr 21 20:39:36.252: //32691/E3856E28AA86/SIP/Info/info/512/sentInfo: Sent Info Request, starting InfoTimer

Apr 21 20:39:36.256: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 120, fd: 2

Apr 21 20:39:36.256: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Sent:

INFO sip:66363_001AA1E55F70@172.28.250.93:5070;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B41C3B

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

Date: Tue, 21 Apr 2015 20:36:14 GMT

Call-ID: 14296485768312@192.168.1.10

User-Agent: Cisco-SIPGateway/IOS-15.4.3.M1

Max-Forwards: 70

Timestamp: 1429648776

CSeq: 105 INFO

Contact: <sip:66363@172.28.254.130:5060;transport=tcp>

Content-Type: application/csta+xml

Content-Disposition: signal;handling=required

Content-Length: 275

<?xml version="1.0" encoding="UTF-8"?>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier></device></BackInServiceEvent>

Apr 21 20:39:36.256: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 120

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1060BAF8 with refCount = 1

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x42635D70

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=5070, local_addr=, connid=120, transport=TCP

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5070 connId 120

Apr 21 20:39:36.308: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:39:36.312: //32691/E3856E28AA86/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK24B41C3B from via branch list

Apr 21 20:39:36.312: //32691/E3856E28AA86/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x15D62460

Apr 21 20:39:36.312: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x1060BAF8) counter, current msg->refCount = 2

Apr 21 20:39:36.312: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 Ok

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B41C3B

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

Call-ID: 14296485768312@192.168.1.10

CSeq: 105 INFO

Content-Length: 0

Content-Type: application/csta+xml

Apr 21 20:39:36.312: //32691/E3856E28AA86/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX

Apr 21 20:39:36.312: //32691/E3856E28AA86/SIP/Info/verbose/4096/sact_active_new_message_response: Transaction Complete. Lock on Facilities/INFO released.

Apr 21 20:39:36.312: //32691/E3856E28AA86/SIP/Info/verbose/32768/ccsip_api_info_done: RTP_LPBK == FALSE, checkpoint HA data

Apr 21 20:39:36.312: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x1060BAF8) counter, current msg->refCount = 1

Apr 21 20:39:36.312: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1060BAF8

Apr 21 20:39:36.312: //CTI/PI:cti_frontend_proc [7FB3]: received CC Event [21]: CC_EV_CALL_INFO_ACK

Apr 21 20:39:36.312: //CTI/PI:pi_process_service_event event 21

Apr 21 20:39:36.312: //CTI/PI: got CC_EV_CALL_INFO_ACK callID 32691

Apr 21 20:39:36.312: //CTI/SM:sm_handle_cc_service event 85

Apr 21 20:39:36.312: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:36.312: //CTI/SM: to return 1544C8B0

Apr 21 20:39:36.312: //CTI/SM: got CTI_EV_ACK, callID 32691

Apr 21 20:39:36.468: //CTI/LM:cti_update_mwi_info_to_app mac addr 001AA1E55F70 number 66363 mwi OFF

Apr 21 20:39:36.468: //CTI/SM:sm_find_context_ids_by_line num 66363, tag 0, mac 001AA1E55F70, prev 0, expanded 0

Apr 21 20:39:36.468: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.472: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.472: //CTI/CM: - dn 66363

Apr 21 20:39:36.472: //CTI/LM:lmm_process_cti_event event 84

Apr 21 20:39:36.472: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:36.472: //CTI/CM:

Apr 21 20:39:36.472: //CTI/CM:-- trigger 13, callID 32702, dn 66363, reason 808858425, result 16777215

Apr 21 20:39:36.472: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.472: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.472: //CTI/CM: - dn 66363

Apr 21 20:39:36.472: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:36.472: //CTI/CM: dstCallID 32701

Apr 21 20:39:36.472: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:36.472: //CTI/CM: * cmm_crs_proc_tr_call_redir

Apr 21 20:39:36.472: //CTI/CM: inst 404C2794 state 4

Apr 21 20:39:36.472: //CTI/CM: set inst 404C11C8, dn 200990 redir cause = 4

Apr 21 20:39:36.472: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:36.472: //CTI/CM: target_node 0

Apr 21 20:39:36.472: //CTI/CM:Lineinfo node Search 66666 FAILED

Apr 21 20:39:36.472: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.472: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.472: //CTI/CM: - dn 66363

Apr 21 20:39:36.472: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.472: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.472: //CTI/CM: - dn 66363

Apr 21 20:39:36.472: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DIVERTED

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:36.476: //CTI/CM:

Apr 21 20:39:36.476: //CTI/CM:-- trigger 16, callID 32702, dn 66363, reason 19, result 0

Apr 21 20:39:36.476: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.476: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.476: //CTI/CM: - dn 66363

Apr 21 20:39:36.476: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:36.476: //CTI/CM: dstCallID 32701

Apr 21 20:39:36.476: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:36.476: //CTI/CM: * cti_cmm_crs_proc_tr_rpt_disconn

Apr 21 20:39:36.476: //CTI/CM: callID = 32702, CD ,CG =200990 CD = 66363, GCID =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM: * is_only_one_callinst_with_dn_and_gcid

Apr 21 20:39:36.476: //CTI/CM: callid 32702, dn = 66363, gcid =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:36.476: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:36.476: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM: Cause = C(13), inst cause = A

Apr 21 20:39:36.476: //CTI/CM: Cause changed from alertTimeExpired to CFNA

Apr 21 20:39:36.476: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:36.476: //CTI/CM: target_node 25FD778

Apr 21 20:39:36.476: //CTI/CM: - dn 200990

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 200990 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM:cmm_find_callid_from_gcid dn 200990

Apr 21 20:39:36.476: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:36.476: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:36.476: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM: to return callID 32701

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:36.476: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:36.476: //CTI/CM: target_node 25FD778

Apr 21 20:39:36.476: //CTI/CM: - dn 200990

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:36.476: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.476: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.476: //CTI/CM: - dn 66363

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 66363 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM:cmm_find_callid_from_gcid dn 66363

Apr 21 20:39:36.476: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:36.476: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:36.476: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM: to return callID 32702

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 66363 callID 32702

Apr 21 20:39:36.476: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.476: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.476: //CTI/CM: - dn 66363

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 64 mac no mac

Apr 21 20:39:36.476: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 66363 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.476: //CTI/CM:cmm_find_callid_from_gcid dn 66363

Apr 21 20:39:36.476: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:36.476: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:36.476: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.480: //CTI/CM: to return callID 32702

Apr 21 20:39:36.480: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 66363 callID 32702

Apr 21 20:39:36.480: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:36.480: //CTI/CM: target_node 16FD7830

Apr 21 20:39:36.480: //CTI/CM: - dn 66363

Apr 21 20:39:36.480: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 64 mac no mac

Apr 21 20:39:36.480: //CTI/CM:decrease_gcid_ref_count 32702

Apr 21 20:39:36.480: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:36.480: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:36.480: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.480: //CTI/CM: count = 1

Apr 21 20:39:36.480: //CTI/CM: delete_callinst 404C2794, callID = 32702

Apr 21 20:39:36.480: //CTI/CM: freeing instance from CllEntry 100A6A0

Apr 21 20:39:36.480: //CTI/CM:cti_is_sccp_endpoint DN 66363

Apr 21 20:39:36.480: //CTI/CM:

Apr 21 20:39:36.480: sccp endpoint TRUE

Apr 21 20:39:36.480: //CTI/SM:sm_process_lmm_event event 84

Apr 21 20:39:36.480: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:36.480: //CTI/SM: to return 1544C8B0

Apr 21 20:39:36.480: //CTI/PI:pi_send_log_event event 84 context_id 32691

Apr 21 20:39:36.480: //CTI/PI:pi_build_event event 84

Apr 21 20:39:36.480: //CTI/XI:cti2csta:1076 cti_ev_type_t(84)

Apr 21 20:39:36.480: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=(001AA1E55F70)

Apr 21 20:39:36.480: //CTI/XI:cti2csta:2169 csta_EventType_t(48)

Apr 21 20:39:36.480: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(332), message(332)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier>

</targetDevice>

<messageWaitingOn>false</messageWaitingOn>

</MessageWaitingEvent>

Apr 21 20:39:36.480: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 34

Apr 21 20:39:36.480: //32691/E3856E28AA86/SIP/Info/verbose/4096/act_active_info_request: Transaction active. Facilities/INFO requests will be queued.

Apr 21 20:39:36.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x47020AE0 with refCount = 1

Apr 21 20:39:36.480: //32691/E3856E28AA86/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 5 event

Apr 21 20:39:36.480: //32691/E3856E28AA86/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:39:36.480: //32691/E3856E28AA86/SIP/Info/verbose/4096/sipSPIPushOrigRequestContainerIntoHolder: Request Container Holder is above threshold...trimming

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Info/info/4096/sipSPISendInfo: Associated container=0x102F22E0 to Info

Apr 21 20:39:36.484: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 332

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Transport/sipSPISendInfo: Sending INFO to the transport layer

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: msg=0x47020AE0, addr=172.28.250.93, port=5070, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=0, callBack=0x97D4514

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:39:36.484: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.250.93, rport:5070 with laddr:

Apr 21 20:39:36.484: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x15D62460 is already on connection=0x426367C4 context_list

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x47020AE0

Apr 21 20:39:36.484: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x47020AE0, addr=172.28.250.93, port=5070, local_addr=, connId=120 vrfid=0 for TCP

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Info/info/512/sentInfo: Sent Info Request, starting InfoTimer

Apr 21 20:39:36.484: %VOIPAAA-5-VOIP_CALL_HISTORY: CallLegType 1, ConnectionId 530E3CF6E79D11E4AA9CAB8128935809, SetupTime 06:39:22.744 AEST Wed Apr 22 2015, PeerAddress 66363, PeerSubAddress , DisconnectCause 13 , DisconnectText no user answer (19), ConnectTime 06:39:36.484 AEST Wed Apr 22 2015, DisconnectTime 06:39:36.484 AEST Wed Apr 22 2015, CallOrigin 1, ChargedUnits 0, InfoType 2, TransmitPackets 0, TransmitBytes 0, ReceivePackets 0, ReceiveBytes 0

Apr 21 20:39:36.484: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:CFNA,ft:04/22/2015 06:39:36.476,frs:0,fid:73500,fcid:530E3CF6E79D11E4AA9CAB8128935809,legID:7FBD,frson:3,fdcnt:1,fwder:66363,fwdee:200990,fwdto:66666,frm:66363,bguid:530E3CF6E79D11E4AA9CAB8128935809

Apr 21 20:39:36.484: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:TWC,ft:04/22/2015 06:39:22.736,cgn:200990,cdn:66363,frs:0,fid:73499,fcid:530E3CF6E79D11E4AA9CAB8128935809,legID:7FBE,bguid:530E3CF6E79D11E4AA9CAB8128935809

Apr 21 20:39:36.484: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 120, fd: 2

Apr 21 20:39:36.484: //32691/E3856E28AA86/SIP/Msg/ccsipDisplayMsg:

Sent:

INFO sip:66363_001AA1E55F70@172.28.250.93:5070;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.254.130:5060;branch=z9hG4bK24B5952

From: <sip:66363@172.28.218.1>;tag=83E54A64-2523

To: CME_SDK <sip:66363_001AA1E55F70@csta-sdk>;tag=dsd548f03c

Date: Tue, 21 Apr 2015 20:36:14 GMT

Call-ID: 14296485768312@192.168.1.10

User-Agent: Cisco-SIPGateway/IOS-15.4.3.M1

Max-Forwards: 70

Timestamp: 1429648776

CSeq: 106 INFO

Contact: <sip:66363@172.28.254.130:5060;transport=tcp>

Content-Type: application/csta+xml

Content-Disposition: signal;handling=required

Content-Length: 332

<?xml version="1.0" encoding="UTF-8"?>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier></targetDevice>

<messageWaitingOn>false</messageWaitingOn></MessageWaitingEvent>

Apr 21 20:39:36.484: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x47020AE0

Apr 21 20:39:36.488: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x15D4F188) with key=[5656] to table

Apr 21 20:39:36.488: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:

Apr 21 20:39:36.488: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:

Apr 21 20:39:36.488: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..

Apr 21 20:39:36.488: //32703/000000000000/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/critical/32768/ccsip_ipip_media_forking_read_from_TDContainer: MF: Unable to read data from TD Container..

Apr 21 20:39:36.488: //32703/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..

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: EV_UNDEFINED

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_MODE

Apr 21 20:39:36.488: //32703/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

Apr 21 20:39:36.488: //32703/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md_snr:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed_snr:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_h32x_in_set_mode:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_h323_in_set_mode:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_sccp_in_set_mode:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/4096/is_mode_sip_sccp_in_set_mode:

Apr 21 20:39:36.488: //32703/000000000000/SIP/Info/info/8192/sip_iwf_def_set_mode_hdlr: Setting SPI mode to SIP-TDM

Apr 21 20:39:36.488: //32703/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_sccp_early_dialog_container

Apr 21 20:39:36.488: //32703/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGEfind_gcidinfo_node

Apr 21 20:39:36.656: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:36.656: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:36.656: //CTI/CM: to return callID 32701

Apr 21 20:39:36.656: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:36.656: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:36.656: //CTI/CM: target_node 25FD778

Apr 21 20:39:36.656: //CTI/CM: - dn 200990

Apr 21 20:39:36.656: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:36.656: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_MEDIAATTACHED

Apr 21 20:39:38.816: //32703/5BDA6F22AAA1/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=32703, proc_id=9

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1017CA80 with refCount = 1

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x16962628 with refCount = 1

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [172.28.218.2]:32770, local_address:[ - ]

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1017CA80

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

BYE sip:200990@172.28.218.1:5060 SIP/2.0

Via: SIP/2.0/UDP 172.28.218.2:5060;branch=z9hG4bK5nZMMMf7hWvi8wv.DyW0Bw~~622

Max-Forwards: 70

To: <sip:200990@172.28.218.1>;tag=83E85F04-1A46

From: <sip:66666@172.28.218.2>;tag=ds104fc43

Call-ID: 5BDBA80B-E79D11E4-AAA5AB81-28935809@172.28.218.1

CSeq: 2 BYE

Content-Length: 0

Allow: INVITE, BYE, CANCEL, ACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO

Cisco-Gcid: 530E3CF6-E79D-11E4-AA9C-AB8128935809

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/info/4096/sipSPICheckFromToRequest: Found matching CB 15D4F188

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/info/4096/sipSPILocateInviteDialogCCB: ****Found CCB in UAC table

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x16962628) counter, current msg->refCount = 2

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.218.2,Port 32770, Transport 1, SentBy Port 5060vrfid 0

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone AEST to SIP default timezone = GMT

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.218.2,Port 32770, Transport 1, SentBy Port 5060vrfid 0

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/ccsip_set_release_source_for_peer: ownCallId[32703], src[4]

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/critical/4096/sipSPIInitiateDisconnect: Initiate call disconnect(16) for outgoing call

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13CC17F8

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQSIG: No QSIG Body found in inbound container

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQ931: No RawMsg Body found in inbound container

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 29

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg..

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:

Freeing NULL pointer!

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x16962628) counter, current msg->refCount = 3

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x15D4F188)->last_request = 0x16962628, refCount = 3

Apr 21 20:39:40.488: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x16962628) counter, current msg->refCount = 2

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 18

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/State/ccsip_cnfsm_debugs: IPIPMS:cur_container:ccsip_ipip_media_service_main_container, cur_state:S_IPIP_MEDIA_SERV_STATE_IDLE, event:E_IPIP_MEDIA_SERV_EV_XCODER_RESET_STREAM

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES*****

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Info/verbose/256/sipSPIResetXcoder: Xcoder resource already cleaned up

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/State/ccsip_cnfsm_debugs: IPIPMS:next_state:S_IPIP_MEDIA_SERV_STATE_IDLE

Apr 21 20:39:40.488: //32703/5BDA6F22AAA1/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:17283244

Apr 21 20:39:40.488: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:40.488: //CTI/CM:

Apr 21 20:39:40.488: //CTI/CM:-- trigger 16, callID 32701, dn 200990, reason 16, result 1079272200

Apr 21 20:39:40.488: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.488: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.488: //CTI/CM: - dn 200990

Apr 21 20:39:40.488: //CTI/CM: CallEntry 1012890

Apr 21 20:39:40.488: //CTI/CM: dstCallID -1

Apr 21 20:39:40.488: //CTI/CM: line_info 25FD784, dn 200990

Apr 21 20:39:40.488: //CTI/CM: * cti_cmm_crs_proc_tr_rpt_disconn

Apr 21 20:39:40.488: //CTI/CM: callID = 32701, CG ,CG =200990 CD = 66666, GCID =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.488: //CTI/CM: * is_only_one_callinst_with_dn_and_gcid

Apr 21 20:39:40.492: //CTI/CM: callid 32701, dn = 200990, gcid =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.492: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.492: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM: Cause = A(10), inst cause = A

Apr 21 20:39:40.492: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.492: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.492: //CTI/CM: - dn 200990

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 200990 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM:cmm_find_callid_from_gcid dn 200990

Apr 21 20:39:40.492: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.492: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.492: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM: to return callID 32701

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:40.492: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.492: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.492: //CTI/CM: - dn 200990

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:40.492: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.492: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.492: //CTI/CM: - dn 66666

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 66666 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM:cmm_find_callid_from_gcid dn 66666

Apr 21 20:39:40.492: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.492: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.492: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM: to return callID 32703

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 66666 callID 32703

Apr 21 20:39:40.492: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.492: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.492: //CTI/CM: - dn 66666

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag -1 mac no mac

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 200990 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM:cmm_find_callid_from_gcid dn 200990

Apr 21 20:39:40.492: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.492: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.492: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM: to return callID 32701

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:40.492: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.492: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.492: //CTI/CM: - dn 200990

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:40.492: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_CONN_CLEARED

Apr 21 20:39:40.492: //CTI/CM:decrease_gcid_ref_count 32701

Apr 21 20:39:40.492: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.492: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.492: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.492: //CTI/CM: count = 1

Apr 21 20:39:40.492: //CTI/CM: delete_callinst 404C11C8, callID = 32701

Apr 21 20:39:40.492: //CTI/CM: freeing instance from CllEntry 1012890

Apr 21 20:39:40.492: //CTI/CM:cti_is_sccp_endpoint DN 200990

Apr 21 20:39:40.492: //CTI/CM:

Apr 21 20:39:40.492: sccp endpoint TRUE

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:40.496: //CTI/CM:

Apr 21 20:39:40.496: //CTI/CM:-- trigger 16, callID 32703, dn 66666, reason 16, result 1079272200

Apr 21 20:39:40.496: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.496: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.496: //CTI/CM: - dn 66666

Apr 21 20:39:40.496: //CTI/CM: CallEntry 100D1F0

Apr 21 20:39:40.496: //CTI/CM: dstCallID -1

Apr 21 20:39:40.496: //CTI/CM: line_info 1000A690, dn 66666

Apr 21 20:39:40.496: //CTI/CM: * cti_cmm_crs_proc_tr_rpt_disconn

Apr 21 20:39:40.496: //CTI/CM: callID = 32703, CD ,CG =200990 CD = 66666, GCID =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM: * is_only_one_callinst_with_dn_and_gcid

Apr 21 20:39:40.496: //CTI/CM: callid 32703, dn = 66666, gcid =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.496: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.496: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM: Cause = A(10), inst cause = A

Apr 21 20:39:40.496: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.496: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.496: //CTI/CM: - dn 200990

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 200990 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM:cmm_find_callid_from_gcid dn 200990

Apr 21 20:39:40.496: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.496: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.496: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM: to return callID -1

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID fail in getting CallID

Apr 21 20:39:40.496: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.496: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.496: //CTI/CM: - dn 66666

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 66666 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM:cmm_find_callid_from_gcid dn 66666

Apr 21 20:39:40.496: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.496: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.496: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM: to return callID 32703

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 66666 callID 32703

Apr 21 20:39:40.496: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.496: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.496: //CTI/CM: - dn 66666

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag -1 mac no mac

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 66666 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM:cmm_find_callid_from_gcid dn 66666

Apr 21 20:39:40.496: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.496: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.496: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.496: //CTI/CM: to return callID 32703

Apr 21 20:39:40.496: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 66666 callID 32703

Apr 21 20:39:40.496: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.500: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.500: //CTI/CM: - dn 66666

Apr 21 20:39:40.500: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag -1 mac no mac

Apr 21 20:39:40.500: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_CONN_CLEARED

Apr 21 20:39:40.500: //CTI/CM:decrease_gcid_ref_count 32703

Apr 21 20:39:40.500: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:40.500: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:40.500: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:40.500: //CTI/CM:delete_gcid_node

Apr 21 20:39:40.500: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.500: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.500: //CTI/CM: - dn 200990

Apr 21 20:39:40.500: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.500: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.500: //CTI/CM: - dn 66666

Apr 21 20:39:40.500: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_CONN_DROPPED

Apr 21 20:39:40.500: //CTI/CM: delete_callinst 404C2794, callID = 32703

Apr 21 20:39:40.500: //CTI/CM: freeing instance from CllEntry 100D1F0

Apr 21 20:39:40.500: //CTI/CM:cti_is_sccp_endpoint DN 66666

Apr 21 20:39:40.500: //CTI/CM:cti_is_SIP_line_side_endpoint DN 66666

Apr 21 20:39:40.500: //CTI/CM:find_lineinfo_node finding number 66666

Apr 21 20:39:40.500: //CTI/CM: target_node 1000A684

Apr 21 20:39:40.500: //CTI/CM: - dn 66666

Apr 21 20:39:40.500: //CTI/CM:free 66666 line_info 1000A690

Apr 21 20:39:40.500: //32703/5BDA6F22AAA1/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=32703

Apr 21 20:39:40.500: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 29

Apr 21 20:39:40.500: //32703/5BDA6F22AAA1/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg..

Apr 21 20:39:40.500: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT

Apr 21 20:39:40.500: //32703/5BDA6F22AAA1/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=32703, proc_id=1

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 1 active bw 0 Kbps

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface GigabitEthernet0/0 bw 80 Kbps

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/4096/act_disconnecting_disconnect: Disconnect now.. no defer BYE..

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1017CA80 with refCount = 1

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/4096/sipSPISendByeResponse: Associated container=0x102E68E8 to Bye Response

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Transport/sipSPISendByeResponse: Sending BYE Response to the transport layer

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Transport/sipSPITransportSendMessage: msg=0x1017CA80, addr=172.28.218.2, port=32770, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x97D6768

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x25C4564, addr=172.28.218.2, port=5060, local_addr=, unregistering context=0x15D4F188

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x15D4F188 from the connection=0x25C4E38 context list

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x1017CA80 to default port=5060

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.28.218.2, rport:5060 with laddr:

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x15D4F188 with connection=0x25C4E38 context list

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x1017CA80

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x1017CA80, addr=172.28.218.2, port=5060, local_addr=, connId=2 vrfid=0 for UDP

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/512/sentByeResponse: Sent 200ok to the BYE, tearing down the call

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/verbose/8192/sipSPIDeferCallClose: Not split dataplane, bail

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/verbose/8192/sipSPIWaitForStatsBforeCallClose: Not split dataplane, bail

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat:

sipSPICallCloseAfterFinalStat:

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 4 Playout: 3800 DiscTime:221304797 ConnTime 221304398

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Media/sipSPIHandleDestroyRtpSession: stream:17283244

Apr 21 20:39:40.504: %VOIPAAA-5-VOIP_CALL_HISTORY: CallLegType 2, ConnectionId 5BDA6F22E79D11E4AAA1AB8128935809, SetupTime 06:39:36.504 AEST Wed Apr 22 2015, PeerAddress 66666, PeerSubAddress , DisconnectCause 10 , DisconnectText normal call clearing (16), ConnectTime 06:39:36.514 AEST Wed Apr 22 2015, DisconnectTime 06:39:40.504 AEST Wed Apr 22 2015, CallOrigin 1, ChargedUnits 0, InfoType 2, TransmitPackets 192, TransmitBytes 30720, ReceivePackets 198, ReceiveBytes 31680

Apr 21 20:39:40.504: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:CFNA,ft:04/22/2015 06:39:36.488,frs:0,fid:73503,fcid:530E3CF6E79D11E4AA9CAB8128935809,legID:7FBF,frson:3,fdcnt:1,fwder:66363,fwdee:200990,fwdto:66666,frm:66363,bguid:530E3CF6E79D11E4AA9CAB8128935809

Apr 21 20:39:40.504: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:TWC,ft:04/22/2015 06:39:36.488,cgn:200990,cdn:66666,frs:0,fid:73504,fcid:530E3CF6E79D11E4AA9CAB8128935809,legID:7FBF,bguid:530E3CF6E79D11E4AA9CAB8128935809

Apr 21 20:39:40.504: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x16962628) counter, current msg->refCount = 1

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/State/sipSPIChangeState: 0x15D4F188 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Call/sipSPICallInfo:

The Call Setup Information is:

Call Control Block (CCB) : 0x0x15D4F188

State of The Call : STATE_DEAD

TCP Sockets Used : NO

Calling Number : 200990

Called Number : 66666

Source IP Address (Sig ): 172.28.218.1

Destn SIP Req Addr:Port : 172.28.218.2:5060

Destn SIP Resp Addr:Port : 172.28.218.2:32770

Destination Name : 172.28.218.2

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Call/sipSPIMediaCallInfo:

Number of Media Streams: 1

Media Stream : 1

Negotiated Codec : g711ulaw

Negotiated Codec Bytes : 160

Nego. Codec payload : 0 (tx), 0 (rx)

Negotiated Dtmf-relay : 8

Dtmf-relay Payload : 0 (tx), 0 (rx)

Source IP Address (Media): 172.28.218.1

Source IP Port (Media): 20164

Destn IP Address (Media): 172.28.218.2

Destn IP Port (Media): 21016

Orig Destn IP Address:Port (Media): [ - ]:0

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Call/sipSPICallInfo:

Disconnect Cause (CC) : 16

Disconnect Cause (SIP) : 200

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 7FBF

Apr 21 20:39:40.504: //32703/5BDA6F22AAA1/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Return and SIP_TIMER_REMOVE_TRANSACTION timer will free this ccb=0x15D4F188

Apr 21 20:39:40.504: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:40.504: //CTI/CM:

Apr 21 20:39:40.504: //CTI/MD:-- trigger 23, callID 32701, dn 200990, reason 15, result 10

Apr 21 20:39:40.504: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.504: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.504: //CTI/CM: - dn 200990

Apr 21 20:39:40.504: //CTI/CM: CallEntry 1012890

Apr 21 20:39:40.504: //CTI/CM: dstCallID -1

Apr 21 20:39:40.504: //CTI/MD: line_info 25FD784, dn 200990

Apr 21 20:39:40.504: //CTI/MD: * cti_cmm_crs_proc_tr_call_mediadetached

Apr 21 20:39:40.504: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:40.504: //CTI/CM:

Apr 21 20:39:40.504: //CTI/MD:-- trigger 23, callID 32701, dn 200990, reason 1112845024, result 292859168

Apr 21 20:39:40.504: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:40.504: //CTI/CM: target_node 25FD778

Apr 21 20:39:40.504: //CTI/CM: - dn 200990

Apr 21 20:39:40.504: //CTI/CM: CallEntry 1012890

Apr 21 20:39:40.504: //CTI/CM: dstCallID -1

Apr 21 20:39:40.504: //CTI/MD: line_info 25FD784, dn 200990

Apr 21 20:39:40.504: //CTI/MD: * cti_cmm_crs_proc_tr_call_mediadetached

Apr 21 20:39:40.508: %VOIPAAA-5-VOIP_CALL_HISTORY: CallLegType 1, ConnectionId 530E3CF6E79D11E4AA9CAB8128935809, SetupTime 06:39:21.728 AEST Wed Apr 22 2015, PeerAddress 200990, PeerSubAddress , DisconnectCause 10 , DisconnectText normal call clearing (16), ConnectTime 06:39:36.528 AEST Wed Apr 22 2015, DisconnectTime 06:39:40.508 AEST Wed Apr 22 2015, CallOrigin 2, ChargedUnits 0, InfoType 2, TransmitPackets 0, TransmitBytes 0, ReceivePackets 192, ReceiveBytes 30720

Apr 21 20:39:40.508: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:CFNA,ft:04/22/2015 06:39:36.488,frs:0,fid:73503,fcid:530E3CF6E79D11E4AA9CAB8128935809,legID:7FBF,frson:3,fdcnt:1,fwder:66363,fwdee:200990,fwdto:66666,frm:66363,bguid:530E3CF6E79D11E4AA9CAB8128935809

Apr 21 20:39:40.508: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:TWC,ft:04/22/2015 06:39:21.732,cgn:200990,cdn:,frs:0,fid:73498,fcid:530E3CF6E79D11E4AA9CAB8128935809,legID:7FBD,bguid:530E3CF6E79D11E4AA9CAB8128935809

Apr 21 20:39:40.512: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.28.218.2:5060;branch=z9hG4bK5nZMMMf7hWvi8wv.DyW0Bw~~622

From: <sip:66666@172.28.218.2>;tag=ds104fc43

To: <sip:200990@172.28.218.1>;tag=83E85F04-1A46

Date: Tue, 21 Apr 2015 20:39:40 GMT

Call-ID: 5BDBA80B-E79D11E4-AAA5AB81-28935809@172.28.218.1

Server: Cisco-SIPGateway/IOS-15.4.3.M1

CSeq: 2 BYE

Reason: Q.850;cause=16

P-RTP-Stat: PS=192,OS=30720,PR=198,OR=31680,PL=0,JI=0,LA=0,DU=3

Content-Length: 0

Apr 21 20:39:40.512: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1017CA80

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 1 to index 119

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x1017CA80 with refCount = 1

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x13BAD038 with refCount = 1

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1017CA80

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x42635D70, addr=172.28.250.93, port=59575, local_addr=, connid=119, transport=TCP

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 59575 connId 119

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

REGISTER sip:172.28.218.1:5060;transport=tcp SIP/2.0

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~9

Max-Forwards: 70

To: <sip:davecallconnector@172.28.218.1>

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

Call-ID: 14296485727041@172.28.218.1

CSeq: 8 REGISTER

Content-Length: 0

Contact: <sip:null@172.28.250.93:5070;transport=tcp>;expires=120

X-cisco-session-server: davecallconnector

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x15D6F0F0) with key=[5658] to table

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 172.28.250.93:59575,natted src: 172.28.218.1:5060, natted transport: 2

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 172.28.250.93

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0

Apr 21 20:39:41.028: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0

Apr 21 20:39:41.028: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 172.28.254.130 for SIP

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.28.254.130

Apr 21 20:39:41.032: //-1/5E8FCC4EAAA6/SIP/State/sipSPIChangeState: 0x15D6F0F0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5060vrfid 0

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone AEST to SIP default timezone = GMT

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.28.250.93,Port 59575, Transport 2, SentBy Port 5070vrfid 0

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x13BAD038) counter, current msg->refCount = 2

Apr 21 20:39:41.032: //-1/5E8FCC4EAAA6/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x15D6F0F0)->last_request = 0x13BAD038, refCount = 2

Apr 21 20:39:41.032: //-1/5E8FCC4EAAA6/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x15D6F0F0 key=14296485727041@172.28.218.1davecallconnectordsd1b2e01f balance 0

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/Event/sact_idle_new_message_register:

ccsip_api_register_ind return value : SIP_SUCCESS

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 7FC0 to table

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/State/sipSPIChangeState: 0x15D6F0F0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x174F4B58]

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Re-Register not for passthrough, Try CME

Apr 21 20:39:41.032: //32704/5E8FCC4EAAA6/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME caseSIP/2.0 200 OK

Via: SIP/2.0/TCP 172.28.250.93:5070;branch=z9hG4bK9bkDTjwKc7Ez15sTfoNEXQ~~9

From: <sip:davecallconnector@172.28.218.1>;tag=dsd1b2e01f

To: <sip:davecallconnector@172.28.218.1>;tag=83E870B8-E44

Date: Tue, 21 Apr 2015 20:39:41 GMT

Call-ID: 14296485727041@172.28.218.1

Server: Cisco-SIPGateway/IOS-15.4.3.M1

CSeq: 8 REGISTER

X-cisco-referenceID: FB47A3FE

Contact: <sip:davecallconnector@172.28.250.93:5070;transport=tcp>;expires=60

Expires: 60

Content-Length: 0

Apr 21 20:39:41.032: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1017CA80

dcmhrc02#

dcmhrc02#show cti session

ID DN Num Tag Mac MRef CreateTime #Msg

==== ========== === ============ ==== ==================== ====

32691 66363 0 001AA1E55F70 0 Apr 22 2015 06:36:15 7

Raghavendra G V · ‎04-22-2015

Hi,

From logs I don't see if any call placed, you can try with our sample codes in below location.

Cisco UCXAPI https://developer.cisco.com/site/uc-express-services/documentation/

You can raise a Dev Net support case, for more information you can refer below link.

Cisco DevNet Support https://developer.cisco.com/site/devnet/support/

Thanks,

Raghavendra

tj1 · ‎04-23-2015

Hi Raghavendra,

Sorry I should have provided more information about the log

I initiated a phone call from 200990 to 66363 as listed below but it did not generate CSTA event

Apr 21 20:39:10.968: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x13F54F14

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:21.732: //CTI/CM:

Apr 21 20:39:21.732: //CTI/CM:-- trigger 1, callID 32701, dn 200990, reason 157701124, result 0

Apr 21 20:39:21.732: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:21.732: //CTI/CM: target_node 25FD778

Apr 21 20:39:21.732: //CTI/CM: - dn 200990

Apr 21 20:39:21.732: //CTI/CM: CallEntry 1012890

Apr 21 20:39:21.732: //CTI/CM: dstCallID -1

Apr 21 20:39:21.732: //CTI/CM: line_info 25FD784, dn 200990

Apr 21 20:39:21.732: //CTI/CM: * cmm_crs_proc_tr_call_orig

Apr 21 20:39:21.732: //CTI/CM: callID = 32701, CG 200990, GCID =

Apr 21 20:39:21.732: //CTI/CM:cmm_is_hairpin_leg number 200990 callID 32701

Apr 21 20:39:21.732: //CTI/CM: -- cid 32701 interface type 26

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_is_ephone_leg cid 32701 interface type 26 return TRUE530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:21.732: //CTI/CM:increase_gcid_ref_count 32701 0

Apr 21 20:39:21.732: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:21.732: //CTI/CM: target_node 0

Apr 21 20:39:21.732: //CTI/CM: Gcidinfo node Search FAILED

Apr 21 20:39:21.732: //CTI/CM:create_gcidinfo_node 32701

Apr 21 20:39:21.732: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:21.732: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:21.732: //CTI/CM: count = 1

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 404C11C8 callID 32701 dn_tag -1 dn_chan -1

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_call_inst_set_DN_tag call_inst 404C11C8 dn_tag 90 dn_chan 1

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_call_inst_set_DN_phone ccGetCallInfo ret succ. phone tag 99

Apr 21 20:39:21.732: //CTI/CM: orig --> callID 32701, line_info 25FD784, call_inst 404C11C8, gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:21.732: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:21.732: //CTI/CM: target_node 25FD778

Apr 21 20:39:21.732: //CTI/CM: - dn 200990

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:21.732: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:21.732: //CTI/CM: target_node 25FD778

Apr 21 20:39:21.732: //CTI/CM: - dn 200990

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:21.732: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_ORIGINATED

Apr 21 20:39:22.736: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:22.736: //CTI/CM:

Apr 21 20:39:22.736: //CTI/CM:-- trigger 14, callID 32702, dn 66363, reason 1079265368, result 317342152

Apr 21 20:39:22.736: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:22.736: //CTI/CM: target_node 16FD7830

Apr 21 20:39:22.736: //CTI/CM: - dn 66363

Apr 21 20:39:22.736: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:22.736: //CTI/CM: dstCallID 32701

Apr 21 20:39:22.736: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:22.736: //CTI/CM: * cti_cmm_crs_proc_tr_call_active

Apr 21 20:39:22.736: //CTI/CM: callID = 32702,src_callid = 32701, CG 200990, CD = 66363, GCID =530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.736: //CTI/CM:increase_gcid_ref_count 32702 0

Apr 21 20:39:22.736: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:22.736: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:22.740: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.740: //CTI/CM: count = 2

Apr 21 20:39:22.740: //CTI/CM: set originalCalled = 66363

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:22.740: //CTI/CM:

Apr 21 20:39:22.740: //CTI/CM:-- trigger 2, callID 32702, dn 66363, reason -1433490559, result 680744969

Apr 21 20:39:22.740: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:22.740: //CTI/CM: target_node 16FD7830

Apr 21 20:39:22.740: //CTI/CM: - dn 66363

Apr 21 20:39:22.740: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:22.740: //CTI/CM: dstCallID 32701

Apr 21 20:39:22.740: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:22.740: //CTI/CM: * cmm_crs_proc_tr_call_offr

Apr 21 20:39:22.740: //CTI/CM: offr --> line_info 16FD783C

Apr 21 20:39:22.740: //CTI/CM: CallEntry_src 1012890, id = 32701

Apr 21 20:39:22.740: //CTI/CM: call_inst_src 404C11C8 gcid_parent 00000000-00000000-00000000-00000000

Apr 21 20:39:22.740: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:22.740: //CTI/CM: target_node 25FD778

Apr 21 20:39:22.740: //CTI/CM: - dn 200990

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 200990 gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.740: //CTI/CM:cmm_find_callid_from_gcid dn 200990

Apr 21 20:39:22.740: //CTI/CM:find_gcidinfo_node

Apr 21 20:39:22.740: //CTI/CM: target_node 1772B7C0

Apr 21 20:39:22.740: //CTI/CM: - gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.740: //CTI/CM: to return callID 32701

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 200990 callID 32701

Apr 21 20:39:22.740: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:22.740: //CTI/CM: target_node 25FD778

Apr 21 20:39:22.740: //CTI/CM: - dn 200990

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 90 mac 1CE85DC9D715

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_OFFERED

Apr 21 20:39:22.740: //CTI/CM: CID = 32702, CallEntry_dst = 100A6A0, call_inst_dst = 404C2794

Apr 21 20:39:22.740: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 404C2794 callID 32702 dn_tag -1 dn_chan -1

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_notify_trigger

Apr 21 20:39:22.748: //CTI/CM:

Apr 21 20:39:22.748: //CTI/CM:-- trigger 3, callID 32702, dn 66363, reason 1079271936, result 170250468

Apr 21 20:39:22.748: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:22.748: //CTI/CM: target_node 16FD7830

Apr 21 20:39:22.748: //CTI/CM: - dn 66363

Apr 21 20:39:22.748: //CTI/CM: CallEntry 100A6A0

Apr 21 20:39:22.748: //CTI/CM: dstCallID 32701

Apr 21 20:39:22.748: //CTI/CM: line_info 16FD783C, dn 66363

Apr 21 20:39:22.748: //CTI/CM: * cmm_crs_proc_tr_call_ring

Apr 21 20:39:22.748: //CTI/CM: call_inst_src 404C11C8 gcid_parent 00000000-00000000-00000000-00000000

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_call_inst_set_DN_tag call_inst 404C2794 dn_tag 64 dn_chan 1

Apr 21 20:39:22.748: //CTI/CM: ring --> callID 32702, line_info 16FD783C, call_inst 404C2794, gcid 530E3CF6-E79D11E4-AA9CAB81-28935809

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 21 20:39:22.748: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 21 20:39:22.748: //CTI/CM:find_lineinfo_node finding number 200990

Apr 21 20:39:22.752: //CTI/CM: target_node 25FD778

Apr 21 20:39:22.752: //CTI/CM: - dn 200990

Apr 21 20:39:22.752: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 21 20:39:22.752: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

I reset the phone here and it generated CSTA event

Apr 21 20:39:35.592: %IPPHONE-6-REG_ALARM: 22: Name=SEP001AA1E55F70 Load= SCCP41.8-4-4S Last=Reset-Reset

Apr 21 20:39:35.696: //CTI/LM:cti_update_cme_line_status mac addr 001AA1E55F70 number 66363 line status 0 normal 0 line removed 0 line shared 0 cti notify 1

Apr 21 20:39:35.696: //CTI/SM:sm_find_context_ids_by_line num 66363, tag 0, mac 001AA1E55F70, prev 0, expanded 0

Apr 21 20:39:35.696: //CTI/CM:find_lineinfo_node finding number 66363

Apr 21 20:39:35.696: //CTI/CM: target_node 16FD7830

Apr 21 20:39:35.696: //CTI/CM: - dn 66363

Apr 21 20:39:35.696: //CTI/LM:lmm_process_cti_event event 15

Apr 21 20:39:35.696: //CTI/LM:lmm_process_cti_event event 14

Apr 21 20:39:35.696: //CTI/SM:sm_process_lmm_event event 15

Apr 21 20:39:35.696: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:35.696: //CTI/SM: to return 1544C8B0

Apr 21 20:39:35.696: //CTI/PI:pi_send_log_event event 15 context_id 32691

Apr 21 20:39:35.696: //CTI/PI:pi_build_event event 15

Apr 21 20:39:35.696: //CTI/XI:cti2csta:1076 cti_ev_type_t(15)

Apr 21 20:39:35.696: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=(001AA1E55F70)

Apr 21 20:39:35.696: //CTI/XI:cti2csta_cause: cti_cause = 21

Apr 21 20:39:35.696: //CTI/XI:cti2csta:2169 csta_EventType_t(45)

Apr 21 20:39:35.696: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(300), message(300)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

<deviceIdentifier>tel:66363;device=001AA1E55F70</deviceIdentifier>

</device>

<cause>maintenance</cause>

</OutOfServiceEvent>

Apr 21 20:39:35.696: //CTI/SM:sm_process_lmm_event event 14

Apr 21 20:39:35.696: //CTI/SM:sm_find_scb_node_by_context context_id 32691

Apr 21 20:39:35.696: //CTI/SM: to return 1544C8B0

Apr 21 20:39:35.696: //CTI/PI:pi_send_log_event event 14 context_id 32691

Apr 21 20:39:35.696: //CTI/PI:pi_build_event event 14

Apr 21 20:39:35.696: //CTI/XI:cti2csta:1076 cti_ev_type_t(14)

Apr 21 20:39:35.696: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(66363) phone-context=(0,) device=()

Apr 21 20:39:35.696: //CTI/XI:cti2csta:2169 csta_EventType_t(44)

Apr 21 20:39:35.696: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(255), message(255)

<?xml version="1.0" encoding="UTF-8"?>

</monitorCrossRefID>

</device>

</BackInSer

The router is running CME 10.5.

Thanks

Raghavendra G V · ‎04-23-2015

Thanks for sharing the info, are you monitoring 200990 and 66363 phones ?

Thanks,

Raghavendra

tj1 · ‎04-25-2015

Hi Raghavendra,

I'm now able to remote answer internal calls but not external from ISDN/E1. CME responds with invalid callid below are the logs.

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>

</callToBeAnswered>

</AnswerCall>

Apr 25 05:47:54.585: //CTI/XI:csta_AnswerCall_cb: Function Called

Apr 25 05:47:54.585: //CTI/XI:csta_callToBeAnswered_cb: Function Called

Apr 25 05:47:54.585: //CTI/XI:csta_callID_cb: Function Called

Apr 25 05:47:54.585: //CTI/XI:csta_deviceID_cb: Function Called

Apr 25 05:47:54.585: //CTI/XI:csta2cti:811 csta_service_type_t(1)

Apr 25 05:47:54.585: //CTI/XI:csta2cti_CallID: Input = 61F84BF6-EA4311E4-8DD6AA78-418DAEF4

Apr 25 05:47:54.585: //CTI/XI:csta2cti_CallID: match 4, 61F84BF6-EA4311E4-8DD6AA78-418DAEF4

Apr 25 05:47:54.585: //CTI/XI:csta2cti_DeviceID: csta(73465) attr(0,) number(73465) phone-context=(0,) device=()

Apr 25 05:47:54.585: //CTI/XI:csta2cti:1062 cti_ev_type_t(39)

Apr 25 05:47:54.585: //CTI/SM:sm_find_scb_node_by_context context_id 363741

Apr 25 05:47:54.585: //CTI/SM: to return 41975234

Apr 25 05:47:54.585: //CTI/PI:pi_process_service_event Feature Server Type = 2, Monitor_only = 0

Apr 25 05:47:54.585: //CTI/SM:sm_handle_cc_service event 39

Apr 25 05:47:54.585: //CTI/SM:sm_find_scb_node_by_context context_id 363741

Apr 25 05:47:54.585: //CTI/SM: to return 41975234

Apr 25 05:47:54.585: //CTI/CC:ccm_process_sm_event event 39

Apr 25 05:47:54.585: //CTI/CM:find_lineinfo_node finding number 73465

Apr 25 05:47:54.585: //CTI/CM: target_node 4435465C

Apr 25 05:47:54.585: //CTI/CM: - dn 73465

Apr 25 05:47:54.585: //CTI/CC:ccm_find_ccb_by_gcid parent 0

Apr 25 05:47:54.585: //CTI/CC:ccm_append_ccb ccb 44415C38

Apr 25 05:47:54.589: //CTI/CC: final ccb count 1

Apr 25 05:47:54.589: //CTI/CC:ccm_drive_fsm state_curr 1 event 39

Apr 25 05:47:54.589: //CTI/CC: Eventual selection 15

Apr 25 05:47:54.589: //CTI/CC:Fsm_Idle_AnswerCall answering 73465

Apr 25 05:47:54.589: //CTI/CM:cmm_find_callid_from_gcid dn 73465

Apr 25 05:47:54.589: //CTI/CM:find_gcidinfo_node

Apr 25 05:47:54.589: //CTI/CM: target_node 0

Apr 25 05:47:54.589: //CTI/CM: Gcidinfo node Search FAILED

Apr 25 05:47:54.589: //CTI/CM: to return callID -1

Apr 25 05:47:54.589: //CTI/CC:ccm_delete_ccb

Apr 25 05:47:54.589: //CTI/CC: ccb 44415C38 released

Apr 25 05:47:54.589: //CTI/CC: final ccb count 0

Apr 25 05:47:54.589: //CTI/SM:sm_process_ccm_event event 53

Apr 25 05:47:54.589: //CTI/SM:sm_find_scb_node_by_context context_id 363741

Apr 25 05:47:54.589: //CTI/SM: to return 41975234

Apr 25 05:47:54.589: //CTI/PI:pi_send_cc_event event 53 context_id 363741

Apr 25 05:47:54.589: //CTI/PI:pi_build_event event 53

Apr 25 05:47:54.589: //CTI/XI:cti2csta:1076 cti_ev_type_t(53)

Apr 25 05:47:54.589: //CTI/XI:cti2csta_error: cti_error = 5

Apr 25 05:47:54.589: //CTI/XI:cti2csta:2169 csta_EventType_t(1)

Apr 25 05:47:54.589: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(177), message(177)

<?xml version="1.0" encoding="UTF-8"?>

<operation>invalidCallID</operation>

</CSTAErrorCode>

DN CallID GCID Calling Called State

========= ====== =================================== ========== ========== =====

73465

363859 6A9128C2-EA4511E4-A52B3C08-F686F2D0 73465 DELVR

Thanks

Raghavendra G V · ‎04-27-2015

Currently UCXSI supports to monitor and control only SCCP device registered in Cisco Unified CME.

Thanks,

Raghavendra

tj1 · ‎04-27-2015

Hi Raghavendra,

But I am able to answer calls originating from H323 trunk to the SCCP phone that's registered to CME.

Thanks

Raghavendra G V · ‎04-27-2015

can you explain the call flow which is not working, please attach full logs with below debug command.

debug cti all

Thanks,

Raghavendra

tj1 · ‎04-27-2015

Hi Raghavendra,

The call flow that I'm having issues with is answering a call that originates from my mobile to a CME registered SCCP phone. The call comes to the CME via E1 trunk.

Apr 28 01:19:21.173: //CTI/CM: target_node 4098E858

Apr 28 01:19:21.173: //CTI/CM: - gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.177: //CTI/CM: to return callID 370675

Apr 28 01:19:21.177: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 73460 callID 370675

Apr 28 01:19:21.177: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:21.177: //CTI/CM: target_node 40088218

Apr 28 01:19:21.177: //CTI/CM: - dn 73460

Apr 28 01:19:21.177: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 3 mac 0C272454DE75

Apr 28 01:19:21.177: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_OFFERED

Apr 28 01:19:21.177: //CTI/CM: CID = 370677, CallEntry_dst = 18587240, call_inst_dst = 1337907C

Apr 28 01:19:21.177: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 1337907C callID 370677 dn_tag -1 dn_chan -1

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:21.829: //CTI/CM:

Apr 28 01:19:21.829: //CTI/CM:-- trigger 1, callID 370678, dn , reason 905969664, result 344017696

Apr 28 01:19:21.829: //CTI/CM:find_lineinfo_node finding number

Apr 28 01:19:21.829: //CTI/CM: target_node 0

Apr 28 01:19:21.829: //CTI/CM:Lineinfo node Search FAILED

Apr 28 01:19:21.829: //CTI/CM:create_lineinfo_node

Apr 28 01:19:21.829: //CTI/CM: target_node 18D912D8

Apr 28 01:19:21.829: //CTI/CM: - dn

Apr 28 01:19:21.829: //CTI/CM: CallEntry 41919BE0

Apr 28 01:19:21.829: //CTI/CM: dstCallID -1

Apr 28 01:19:21.829: //CTI/CM: line_info 18D912E4, dn

Apr 28 01:19:21.829: //CTI/CM: * cmm_crs_proc_tr_call_orig

Apr 28 01:19:21.829: //CTI/CM: callID = 370678, CG , GCID =

Apr 28 01:19:21.829: //CTI/CM:cmm_is_hairpin_leg number callID 370678

Apr 28 01:19:21.829: //CTI/CM: -- cid 370678 interface type 13

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_is_ephone_leg cid 370678 interface type 13 return FALSE

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_has_2nd_ephone_leg_in_gcid compared number cid 370678

Apr 28 01:19:21.829: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.829: //CTI/CM: target_node 0

Apr 28 01:19:21.829: //CTI/CM: Gcidinfo node Search FAILED

Apr 28 01:19:21.829: //CTI/CM: cti_cmm_has_2nd_ephone_leg_in_gcid callID -1 leg NOT FOUND

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_has_2nd_ephone_leg_in_gcid compared number cid 370678

Apr 28 01:19:21.829: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.829: //CTI/CM: target_node 4098EC08

Apr 28 01:19:21.829: //CTI/CM: - gcid 06DFBD6E-EC7A11E4-8859AA78-418DAEF4

Apr 28 01:19:21.829: //CTI/CM: cti_cmm_has_2nd_ephone_leg_in_gcid callID -1 leg NOT FOUND

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_has_2nd_ephone_leg_in_gcid compared number cid 370678

Apr 28 01:19:21.829: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.829: //CTI/CM: target_node 4098E4A8

Apr 28 01:19:21.829: //CTI/CM: - gcid 42C9FB15-EC7B11E4-88F7AA78-418DAEF4

Apr 28 01:19:21.829: //CTI/CM: cti_cmm_has_2nd_ephone_leg_in_gcid callID -1 leg NOT FOUND

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_has_2nd_ephone_leg_in_gcid compared number cid 370678

Apr 28 01:19:21.829: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.829: //CTI/CM: target_node 4098E858

Apr 28 01:19:21.829: //CTI/CM: - gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.829: //CTI/CM: cti_cmm_has_2nd_ephone_leg_in_gcid callID -1 leg NOT FOUND6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.829: //CTI/CM:increase_gcid_ref_count 370678 0

Apr 28 01:19:21.829: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.829: //CTI/CM: target_node 0

Apr 28 01:19:21.829: //CTI/CM: Gcidinfo node Search FAILED

Apr 28 01:19:21.829: //CTI/CM:create_gcidinfo_node 370678

Apr 28 01:19:21.829: //CTI/CM: target_node 4098EA30

Apr 28 01:19:21.829: //CTI/CM: - gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.829: //CTI/CM: count = 1

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 13377AB0 callID 370678 dn_tag -1 dn_chan -1

Apr 28 01:19:21.829: //CTI/CM: orig --> callID 370678, line_info 18D912E4, call_inst 13377AB0, gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num callID 370678

Apr 28 01:19:21.829: //CTI/CM:find_lineinfo_node finding number

Apr 28 01:19:21.829: //CTI/CM: target_node 18D912D8

Apr 28 01:19:21.829: //CTI/CM: - dn

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag -1 mac no mac

Apr 28 01:19:21.829: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_ORIGINATED

Apr 28 01:19:21.833: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:21.833: //CTI/CM:

Apr 28 01:19:21.833: //CTI/CM:-- trigger 14, callID 370679, dn 73566, reason 0, result 0

Apr 28 01:19:21.833: //CTI/CM:find_lineinfo_node finding number 73566

Apr 28 01:19:21.833: //CTI/CM: target_node 419665B4

Apr 28 01:19:21.833: //CTI/CM: - dn 73566

Apr 28 01:19:21.833: //CTI/CM: CallEntry 18584C60

Apr 28 01:19:21.833: //CTI/CM: dstCallID 370678

Apr 28 01:19:21.833: //CTI/CM: line_info 419665C0, dn 73566

Apr 28 01:19:21.833: //CTI/CM: * cti_cmm_crs_proc_tr_call_active

Apr 28 01:19:21.833: //CTI/CM: callID = 370679,src_callid = 370678, CG , CD = 73566, GCID =6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.833: //CTI/CM:increase_gcid_ref_count 370679 0

Apr 28 01:19:21.833: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.833: //CTI/CM: target_node 4098EA30

Apr 28 01:19:21.833: //CTI/CM: - gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.833: //CTI/CM: count = 2

Apr 28 01:19:21.833: //CTI/CM: set originalCalled = 73566

Apr 28 01:19:21.833: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:21.833: //CTI/CM:

Apr 28 01:19:21.833: //CTI/CM:-- trigger 2, callID 370679, dn 73566, reason 1, result 292880384

Apr 28 01:19:21.833: //CTI/CM:find_lineinfo_node finding number 73566

Apr 28 01:19:21.837: //CTI/CM: target_node 419665B4

Apr 28 01:19:21.837: //CTI/CM: - dn 73566

Apr 28 01:19:21.837: //CTI/CM: CallEntry 18584C60

Apr 28 01:19:21.837: //CTI/CM: dstCallID 370678

Apr 28 01:19:21.837: //CTI/CM: line_info 419665C0, dn 73566

Apr 28 01:19:21.837: //CTI/CM: * cmm_crs_proc_tr_call_offr

Apr 28 01:19:21.837: //CTI/CM: offr --> line_info 419665C0

Apr 28 01:19:21.837: //CTI/CM: CallEntry_src 41919BE0, id = 370678

Apr 28 01:19:21.837: //CTI/CM: call_inst_src 13377AB0 gcid_parent 00000000-00000000-00000000-00000000

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.837: //CTI/CM:cmm_find_callid_from_gcid dn

Apr 28 01:19:21.837: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.837: //CTI/CM: target_node 4098EA30

Apr 28 01:19:21.837: //CTI/CM: - gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.837: //CTI/CM: to return callID 370678

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num callID 370678

Apr 28 01:19:21.837: //CTI/CM:find_lineinfo_node finding number

Apr 28 01:19:21.837: //CTI/CM: target_node 18D912D8

Apr 28 01:19:21.837: //CTI/CM: - dn

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag -1 mac no mac

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_OFFERED

Apr 28 01:19:21.837: <== CMM show CTI event ==>

Apr 28 01:19:21.837: - Calling

Apr 28 01:19:21.837: - Calling attr 0

Apr 28 01:19:21.837: - Calling tag -1

Apr 28 01:19:21.837: - Calling MAC

Apr 28 01:19:21.837: - Called 73566

Apr 28 01:19:21.837: - Called attr 1

Apr 28 01:19:21.837: - Called tag 0

Apr 28 01:19:21.837: - Called MAC

Apr 28 01:19:21.837: - ConnAddr 73566

Apr 28 01:19:21.837: - ConnAddr attr 1

Apr 28 01:19:21.837: - ConnAddr tag -1

Apr 28 01:19:21.837: - ConnAddr MAC

Apr 28 01:19:21.837: - type 69

Apr 28 01:19:21.837: - Cause 1 normal

Apr 28 01:19:21.837: - Gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.837: - EV_OFFERED

Apr 28 01:19:21.837: - LastRedirectAddr

Apr 28 01:19:21.837: - LastRedirectAddr attr 0

Apr 28 01:19:21.837: - type 0

Apr 28 01:19:21.837: - direction 0

Apr 28 01:19:21.837: - originalCalled

Apr 28 01:19:21.837: - originalCalled attr 0

Apr 28 01:19:21.837: - parentGcid00000000-00000000-00000000-00000000

Apr 28 01:19:21.837: - localConnectionState Alerting

Apr 28 01:19:21.837:

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo subscription id 370631 dn_tag 0

Apr 28 01:19:21.837: send EV_OFFERED on number 73566 to ccm. sub id 370631

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_OFFERED

Apr 28 01:19:21.837: //CTI/CM: CID = 370679, CallEntry_dst = 18584C60, call_inst_dst = 1336E21C

Apr 28 01:19:21.837: //CTI/CM:cti_cmm_call_inst_set_DN_phone call_inst 1336E21C callID 370679 dn_tag -1 dn_chan -1

Apr 28 01:19:21.837: //CTI/CC:ccm_handle_call_event type 69 ConnAddr 73566

Apr 28 01:19:21.837: //CTI/CM:find_lineinfo_node finding number 73566

Apr 28 01:19:21.837: //CTI/CM: target_node 419665B4

Apr 28 01:19:21.837: //CTI/CM: - dn 73566

Apr 28 01:19:21.837: //CTI/CC:ccm_find_ccb_by_gcid parent 0

Apr 28 01:19:21.837: //CTI/CC:ccm_append_ccb ccb 44415D40

Apr 28 01:19:21.837: //CTI/CC: final ccb count 1

Apr 28 01:19:21.837: //CTI/CC:ccm_drive_fsm state_curr 1 event 69

Apr 28 01:19:21.837: //CTI/CC: Eventual selection 12

Apr 28 01:19:21.837: //CTI/CC:Fsm_AnyState_AnyEvent state_curr 1 event 69

Apr 28 01:19:21.837: //CTI/CC:ccm_delete_ccb

Apr 28 01:19:21.837: //CTI/CC: ccb 44415D40 released

Apr 28 01:19:21.837: //CTI/CC: final ccb count 0

Apr 28 01:19:21.841: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:21.841: //CTI/CM:

Apr 28 01:19:21.841: //CTI/CM:-- trigger 3, callID 370679, dn 73566, reason 0, result 0

Apr 28 01:19:21.841: //CTI/CM:find_lineinfo_node finding number 73566

Apr 28 01:19:21.841: //CTI/CM: target_node 419665B4

Apr 28 01:19:21.841: //CTI/CM: - dn 73566

Apr 28 01:19:21.841: //CTI/CM: CallEntry 18584C60

Apr 28 01:19:21.841: //CTI/CM: dstCallID 370678

Apr 28 01:19:21.841: //CTI/CM: line_info 419665C0, dn 73566

Apr 28 01:19:21.841: //CTI/CM: * cmm_crs_proc_tr_call_ring

Apr 28 01:19:21.841: //CTI/CM: call_inst_src 13377AB0 gcid_parent 00000000-00000000-00000000-00000000

Apr 28 01:19:21.841: //CTI/CM:cti_cmm_call_inst_set_DN_tag call_inst 1336E21C dn_tag 130 dn_chan 1

Apr 28 01:19:21.841: //CTI/CM: ring --> callID 370679, line_info 419665C0, call_inst 1336E21C, gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.841: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 28 01:19:21.841: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 28 01:19:21.841: <== CMM show CTI event ==>

Apr 28 01:19:21.841: - Calling

Apr 28 01:19:21.841: - Calling attr 0

Apr 28 01:19:21.841: - Calling tag -1

Apr 28 01:19:21.841: - Calling MAC

Apr 28 01:19:21.841: - Called 73566

Apr 28 01:19:21.841: - Called attr 1

Apr 28 01:19:21.841: - Called tag 130

Apr 28 01:19:21.841: - Called MAC 405539ACDA93

Apr 28 01:19:21.841: - ConnAddr 73566

Apr 28 01:19:21.841: - ConnAddr attr 1

Apr 28 01:19:21.841: - ConnAddr tag 130

Apr 28 01:19:21.841: - ConnAddr MAC 405539ACDA93

Apr 28 01:19:21.841: - type 70

Apr 28 01:19:21.841: - Cause 1 normal

Apr 28 01:19:21.841: - Gcid 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.845: - EV_DELIVERED

Apr 28 01:19:21.845: - type 0

Apr 28 01:19:21.845: - LastRedirectAddr

Apr 28 01:19:21.845: - LastRedirectAddr attr 0

Apr 28 01:19:21.845: - direction 0

Apr 28 01:19:21.845: - originalCalled

Apr 28 01:19:21.845: - originalCalled attr 0

Apr 28 01:19:21.845: - parentGcid00000000-00000000-00000000-00000000

Apr 28 01:19:21.845: - localConnectionState Alerting

Apr 28 01:19:21.845:

Apr 28 01:19:21.845: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo subscription id 370631 dn_tag 0

Apr 28 01:19:21.845: //CTI/CM:cmm_is_hairpin_leg number 73566 callID 370679

Apr 28 01:19:21.845: send EV_DELIVERED on number 73566 to ccm. sub id 370631

Apr 28 01:19:21.845: //CTI/CM:find_lineinfo_node finding number

Apr 28 01:19:21.845: //CTI/CM: target_node 18D912D8

Apr 28 01:19:21.845: //CTI/CM: - dn

Apr 28 01:19:21.845: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 28 01:19:21.845: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 28 01:19:21.845: //CTI/CC:ccm_handle_call_event type 70 ConnAddr 73566

Apr 28 01:19:21.845: //CTI/CM:find_lineinfo_node finding number 73566

Apr 28 01:19:21.845: //CTI/CM: target_node 419665B4

Apr 28 01:19:21.845: //CTI/CM: - dn 73566

Apr 28 01:19:21.845: //CTI/CC:ccm_find_ccb_by_gcid parent 0

Apr 28 01:19:21.845: //CTI/CC:ccm_append_ccb ccb 44415D40

Apr 28 01:19:21.845: //CTI/CC: final ccb count 1

Apr 28 01:19:21.845: //CTI/CC:ccm_drive_fsm state_curr 1 event 70

Apr 28 01:19:21.845: //CTI/CC: Eventual selection 1

Apr 28 01:19:21.845: //CTI/CC:Fsm_AnyState_AnyCallEvent state_curr 1 event 70

Apr 28 01:19:21.845: //CTI/CC:ccm_delete_ccb

Apr 28 01:19:21.845: //CTI/CC: ccb 44415D40 released

Apr 28 01:19:21.845: //CTI/CC: final ccb count 0

Apr 28 01:19:21.849: //CTI/SM:sm_process_ccm_event event 70

Apr 28 01:19:21.849: //CTI/SM:sm_find_scb_node_by_context context_id 370631

Apr 28 01:19:21.849: //CTI/SM: to return 40979B14

Apr 28 01:19:21.849: //CTI/PI:pi_send_cc_event event 70 context_id 370631

Apr 28 01:19:21.849: //CTI/PI:pi_build_event event 70

Apr 28 01:19:21.849: //CTI/XI:cti2csta:1076 cti_ev_type_t(70)

Apr 28 01:19:21.849: //CTI/XI:cti2csta_cause: cti_cause = 1

Apr 28 01:19:21.849: //CTI/XI:cti2csta_xrefID: xrefID (1D0)

Apr 28 01:19:21.849: //CTI/XI:cti2csta_CallID: CallID = 6F2C1F32-EC7B11E4-A6A33C08-F686F2D0

Apr 28 01:19:21.849: //CTI/XI:cti2csta_DeviceID: attr(1,tel:) number(73566) phone-context=(0,) device=(405539ACDA93)

Apr 28 01:19:21.849: //CTI/XI:cti2csta:2169 csta_EventType_t(29)

Apr 28 01:19:21.849: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(699), message(699)

<?xml version="1.0" encoding="UTF-8"?>

<deviceID>tel:73566;device=405539ACDA93</deviceID>

</connection>

<deviceIdentifier>tel:73566;device=405539ACDA93</deviceIdentifier>

</alertingDevice>

</callingDevice>

<deviceIdentifier>tel:73566;device=405539ACDA93</deviceIdentifier>

</calledDevice>

</lastRedirectionDevice>

<localConnectionInfo>alerting</localConnectionInfo>

<cause>normal</cause>

</DeliveredEvent>

Apr 28 01:19:21.873: //CTI/PI:cti_frontend_proc [5A7C7]: received CC Event [20]: CC_EV_CALL_INFO_ACK

Apr 28 01:19:21.873: //CTI/PI:pi_process_service_event event 20

Apr 28 01:19:21.873: //CTI/PI: got CC_EV_CALL_INFO_ACK callID 370631

Apr 28 01:19:21.873: //CTI/SM:sm_handle_cc_service event 85

Apr 28 01:19:21.873: //CTI/SM:sm_find_scb_node_by_context context_id 370631

Apr 28 01:19:21.873: //CTI/SM: to return 40979B14

Apr 28 01:19:21.873: //CTI/SM: got CTI_EV_ACK, callID 370631

Apr 28 01:19:21.925: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:21.925: //CTI/CM:

Apr 28 01:19:21.929: //CTI/CM: ring --> callID 370677, line_info 213DA08, call_inst 1337907C, gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.929: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 28 01:19:21.929: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 28 01:19:21.929: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:21.929: //CTI/CM: target_node 40088218

Apr 28 01:19:21.929: //CTI/CM: - dn 73460

Apr 28 01:19:21.929: //CTI/CM:cti_cmm_ringing_notify_ccm trigger EV_DELIVERED

Apr 28 01:19:21.929: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_DELIVERED

Apr 28 01:19:21.973: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:21.973: //CTI/CM:

Apr 28 01:19:21.973: //CTI/MD:-- trigger 22, callID 370675, dn 73460, reason 0, result 401651488

Apr 28 01:19:21.973: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:21.973: //CTI/CM: target_node 40088218

Apr 28 01:19:21.973: //CTI/CM: - dn 73460

Apr 28 01:19:21.973: //CTI/CM: CallEntry 4191C1C0

Apr 28 01:19:21.973: //CTI/CM: dstCallID 370677

Apr 28 01:19:21.973: //CTI/MD: line_info 40088224, dn 73460

Apr 28 01:19:21.977: //CTI/MD: * cti_cmm_crs_proc_tr_call_mediaattached

Apr 28 01:19:21.977: //CTI/MD: parm --> callID 370675, line_info 40088224, call_inst 13374F18

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 73460 gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.977: //CTI/CM:cmm_find_callid_from_gcid dn 73460

Apr 28 01:19:21.977: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.977: //CTI/CM: target_node 4098E858

Apr 28 01:19:21.977: //CTI/CM: - gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.977: //CTI/CM: to return callID 370675

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 73460 callID 370675

Apr 28 01:19:21.977: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:21.977: //CTI/CM: target_node 40088218

Apr 28 01:19:21.977: //CTI/CM: - dn 73460

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 3 mac 0C272454DE75

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 73460 gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.977: //CTI/CM:cmm_find_callid_from_gcid dn 73460

Apr 28 01:19:21.977: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:21.977: //CTI/CM: target_node 4098E858

Apr 28 01:19:21.977: //CTI/CM: - gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:21.977: //CTI/CM: to return callID 370675

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 73460 callID 370675

Apr 28 01:19:21.977: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:21.977: //CTI/CM: target_node 40088218

Apr 28 01:19:21.977: //CTI/CM: - dn 73460

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 3 mac 0C272454DE75

Apr 28 01:19:21.977: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_MEDIAATTACHED

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_notify_trigger

Apr 28 01:19:22.009: //CTI/CM:

Apr 28 01:19:22.009: //CTI/MD:-- trigger 22, callID 370675, dn 73460, reason 926102583, result 905969664

Apr 28 01:19:22.009: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:22.009: //CTI/CM: target_node 40088218

Apr 28 01:19:22.009: //CTI/CM: - dn 73460

Apr 28 01:19:22.009: //CTI/CM: CallEntry 4191C1C0

Apr 28 01:19:22.009: //CTI/CM: dstCallID 370677

Apr 28 01:19:22.009: //CTI/MD: line_info 40088224, dn 73460

Apr 28 01:19:22.009: //CTI/MD: * cti_cmm_crs_proc_tr_call_mediaattached

Apr 28 01:19:22.009: //CTI/MD: parm --> callID 370675, line_info 40088224, call_inst 13374F18

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 73460 gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:22.009: //CTI/CM:cmm_find_callid_from_gcid dn 73460

Apr 28 01:19:22.009: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:22.009: //CTI/CM: target_node 4098E858

Apr 28 01:19:22.009: //CTI/CM: - gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:22.009: //CTI/CM: to return callID 370675

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 73460 callID 370675

Apr 28 01:19:22.009: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:22.009: //CTI/CM: target_node 40088218

Apr 28 01:19:22.009: //CTI/CM: - dn 73460

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 3 mac 0C272454DE75

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_GCID num 73460 gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:22.009: //CTI/CM:cmm_find_callid_from_gcid dn 73460

Apr 28 01:19:22.009: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:22.009: //CTI/CM: target_node 4098E858

Apr 28 01:19:22.009: //CTI/CM: - gcid 6AA6E9F7-EC7B11E4-891AAA78-418DAEF4

Apr 28 01:19:22.009: //CTI/CM: to return callID 370675

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID num 73460 callID 370675

Apr 28 01:19:22.009: //CTI/CM:find_lineinfo_node finding number 73460

Apr 28 01:19:22.009: //CTI/CM: target_node 40088218

Apr 28 01:19:22.009: //CTI/CM: - dn 73460

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_set_dev_id_DN_Phone_by_callID getting dn_tag 3 mac 0C272454DE75

Apr 28 01:19:22.009: //CTI/CM:cti_cmm_notify_ccm_from_lineinfo trigger EV_MEDIAATTACHED

Apr 28 01:19:25.709: //CTI/PI:cti_frontend_proc [5A7C7]: received CC Event [19]: CC_EV_CALL_INFO

Apr 28 01:19:25.709: //CTI/PI:pi_process_service_event event 19

Apr 28 01:19:25.709: //CTI/PI: got CC_EV_CALL_INFO callID 370631

Apr 28 01:19:25.709: //CTI/PI:pi_parse_service event 0

Apr 28 01:19:25.709: CTI_PARSER:Processing XML message

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>

</callToBeAnswered>

</AnswerCall>

Apr 28 01:19:25.709: //CTI/XI:csta_AnswerCall_cb: Function Called

Apr 28 01:19:25.709: //CTI/XI:csta_callToBeAnswered_cb: Function Called

Apr 28 01:19:25.709: //CTI/XI:csta_deviceID_cb: Function Called

Apr 28 01:19:25.709: //CTI/XI:csta2cti:811 csta_service_type_t(1)

Apr 28 01:19:25.709: //CTI/XI:csta2cti_DeviceID: csta(73566) attr(0,) number(73566) phone-context=(0,) device=()

Apr 28 01:19:25.709: //CTI/XI:csta2cti:1062 cti_ev_type_t(39)

Apr 28 01:19:25.709: //CTI/SM:sm_find_scb_node_by_context context_id 370631

Apr 28 01:19:25.709: //CTI/SM: to return 40979B14

Apr 28 01:19:25.709: //CTI/PI:pi_process_service_event Feature Server Type = 2, Monitor_only = 0

Apr 28 01:19:25.709: //CTI/SM:sm_handle_cc_service event 39

Apr 28 01:19:25.709: //CTI/SM:sm_find_scb_node_by_context context_id 370631

Apr 28 01:19:25.709: //CTI/SM: to return 40979B14

Apr 28 01:19:25.709: //CTI/CC:ccm_process_sm_event event 39

Apr 28 01:19:25.709: //CTI/CM:find_lineinfo_node finding number 73566

Apr 28 01:19:25.709: //CTI/CM: target_node 419665B4

Apr 28 01:19:25.709: //CTI/CM: - dn 73566

Apr 28 01:19:25.709: //CTI/CC:ccm_find_ccb_by_gcid parent 0

Apr 28 01:19:25.709: //CTI/CC:ccm_append_ccb ccb 44415D40

Apr 28 01:19:25.709: //CTI/CC: final ccb count 1

Apr 28 01:19:25.709: //CTI/CC:ccm_drive_fsm state_curr 1 event 39

Apr 28 01:19:25.709: //CTI/CC: Eventual selection 15

Apr 28 01:19:25.709: //CTI/CC:Fsm_Idle_AnswerCall answering 73566

Apr 28 01:19:25.709: //CTI/CM:cmm_find_callid_from_gcid dn 73566

Apr 28 01:19:25.709: //CTI/CM:find_gcidinfo_node

Apr 28 01:19:25.709: //CTI/CM: target_node 0

Apr 28 01:19:25.709: //CTI/CM: Gcidinfo node Search FAILED

Apr 28 01:19:25.709: //CTI/CM: to return callID -1

Apr 28 01:19:25.709: //CTI/CC:ccm_delete_ccb

Apr 28 01:19:25.709: //CTI/CC: ccb 44415D40 released

Apr 28 01:19:25.709: //CTI/CC: final ccb count 0

Apr 28 01:19:25.709: //CTI/SM:sm_process_ccm_event event 53

Apr 28 01:19:25.709: //CTI/SM:sm_find_scb_node_by_context context_id 370631

Apr 28 01:19:25.709: //CTI/SM: to return 40979B14

Apr 28 01:19:25.709: //CTI/PI:pi_send_cc_event event 53 context_id 370631

Apr 28 01:19:25.709: //CTI/PI:pi_build_event event 53

Apr 28 01:19:25.709: //CTI/XI:cti2csta:1076 cti_ev_type_t(53)

Apr 28 01:19:25.709: //CTI/XI:cti2csta_error: cti_error = 5

Apr 28 01:19:25.709: //CTI/XI:cti2csta:2169 csta_EventType_t(1)

Apr 28 01:19:25.709: //CTI/XML:csta_xml_builder: XML message evt->protocol(1) buffer size(5000), return length(177), message(177)

<?xml version="1.0" encoding="UTF-8"?>

<operation>invalidCallID</operation>

</CSTAErrorCode>

Thanks

Raghavendra G V · ‎04-27-2015

I don't see callID in AnswerCall, could you please share your code how you are answering the call. Which call did you pass to answer method.

</callToBeAnswered>

</AnswerCall>

Thanks,

Raghavendra

tj1 · ‎04-28-2015

Hi Raghavendra,

Below are the code to answer a call.

CMECall myCall1 = provider.createCall(CMECall.Type.DIRECT);

tc = ephone1.getTerminalConnection(dn1);

tc.answer(myCall, cmeResponse );

Thanks

Raghavendra G V · ‎04-28-2015

Looks like you are passing empty call, please try to get CMECall from CMECallConnectionRingingEvent and pass to answer method.

Thanks,

Raghavendra

tj1 · ‎04-28-2015

yup that's it.

I wonder why it works on internal call ? Thanks