Feb 22 15:14:28.516: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.227.4:5060 Feb 22 15:14:28.516: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Feb 22 15:14:28.516: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 Feb 22 15:14:28.516: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Feb 22 15:14:28.520: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.227.2:5060;branch=z9hG4bK27C7F From: "8003" ;tag=76D8CC-325 To: ;tag=415DD6EC-F482F731 CSeq: 101 INVITE Call-ID: AB56451E-E08F11DC-806AADE1-CDDF26C8@192.168.227.2 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_301-UA/1.6.7.0098 Content-Type: application/sdp Content-Length: 189 v=0 o=- 1203676924 1203676924 IN IP4 192.168.227.4 s=Polycom IP Phone c=IN IP4 192.168.227.4 t=0 0 m=audio 2228 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 Feb 22 15:14:28.520: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIhandle200OKInvite: Transaction active. Facilities will be queued. Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIhandle200OKInvite: *** This ccb is the parent Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPICompareRespMediaInfo: No Comparsion needed as 18x response SDP is either absent or ignored Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIDoPtimeNegotiation: No ptime present or multiple ptime attributes that can't be handled Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved. Feb 22 15:14:28.520: //67/000000000000/SIP/Info/sipSPIDoDTMFRelayNegotiation: Payload type (101) is reserved for requested dtmf relay mode. Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of full named event(NE) match in fmtp list of events. Feb 22 15:14:28.524: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=rtp-nte stream_type=voice+dtmf (1), dest_ip_address=192.168.227.4, dest_port=2228 Feb 22 15:14:28.524: //67/000000000000/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : rtp-nte Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Feb 22 15:14:28.524: //67/000000000000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.227.2 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_report_media_to_peer: callId 67 peer 66 flags 0x7 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: CallID 67, sdp 0x62F3544C channels 0x6322D74C SIP: Attribute ptime, level 1 instance 1 not found. Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Hndl ptype 0 mline 1 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecing codec g711ulaw SIP: Attribute ptime, level 1 instance 1 not found. Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation NOT done, get ptime from sdp: ptime=0, media_ndx=1 Feb 22 15:14:28.524: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :0, codecbytes: 0 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Codec bytes 0, use default packet rate 160 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Adding codec 5 ptype 0 time 0, bytes 160 as channel 0 mline 1 ss 0 192.168.227.4:2228 Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Hndl ptype 101 mline 1 Feb 22 15:14:28.524: //67/000000000000/SIP/Error/sipSPI_ipip_copy_sdp_to_channelInfo: Unable to find the proper instance for FMTP SIP: fmtp attribute, level 1 instance 0 not found. Feb 22 15:14:28.524: //67/000000000000/SIP/Error/sipSPI_ipip_copy_sdp_to_channelInfo: Unable to acquire event mask for rfc2833 dtmf relay Feb 22 15:14:28.524: //67/000000000000/SIP/Info/sipSPI_ipip_report_media_to_peer: Report initial call media Feb 22 15:14:28.524: //67/000000000000/SIP/Info/copy_channels: callId 67 size 80 ptr 0x62F3532C) Feb 22 15:14:28.524: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: Feb 22 15:14:28.524: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 136) Feb 22 15:14:28.524: //66/AB5163DE8068/SIP/Info/ccsip_event_handler: ccsip_event_handler: peer ID 67 chans 0x62F3532C event 136 flags 0x40001C 0x43 data 0x62F3532C Feb 22 15:14:28.524: //66/AB5163DE8068/SIP/Info/ccsip_event_handler: ccsip_event_handler: CC_EV_H245_OPEN_CHANNEL_IND: peer ID 67 chans 0x62F3532C event 136 flags 0x40001C 0x43 data 0x62F3532C Feb 22 15:14:28.524: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_NEW_MEDIA Feb 22 15:14:28.524: //66/AB5163DE8068/SIP/Info/ccsip_event_handler: ccsip_event_handler: set event->type = SIPSPI_EV_CC_NEW_MEDIA!: peer ID 67 chans 0x62F3532C event 136 flags 0x40001C 0x43 data 0x62F3532C Feb 22 15:14:28.528: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: CC_R_SUCCESS_WITH_CONFIRMED Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=-1, current_seq_num=0x19EB Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=-1, current_seq_num=0x0 Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/ccsip_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160 Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/ccsip_caps_ind: Set forking flag to 0x0 Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0 Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sip_set_modem_caps: Disabling Modem Relay... Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/sip_set_modem_caps: nse payload = 0, ptru mode = 0, ptru-codec=0, redundancy=0, xid=0, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Media/sipSPISetStreamInfo: 0 Active Streams Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Error/sipSPISetStreamInfo: Number of active streams is zero (0)! Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Media/sipSPISetStreamInfo: caps.stream_count=0,caps.stream[0].stream_type=0xFFFF, caps.stream_list.xmitFunc= Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Media/sipSPISetStreamInfo: ??unknown??, caps.stream_list.context= Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Media/sipSPISetStreamInfo: 0x0 (gccb) Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/ccsip_caps_ind: Load DSP with codec : g711ulaw, Bytes=160 Feb 22 15:14:28.528: //66/AB5163DE8068/SIP/Info/ccsip_caps_ind: ccsip_caps_ind: ccb->pld.flags_ipip = 0x43 Feb 22 15:14:28.528: //67/000000000000/SIP/Info/ccsip_caps_ack: Set forking flag to 0x0 Feb 22 15:14:28.528: //67/000000000000/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Callid : 67 Negotiated Codec : g711ulaw, bytes :160 Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 Negotiated CN payload : 0 Media Srce Addr/Port : 192.168.227.2:17008 Media Dest Addr/Port : 192.168.227.4:2228 Feb 22 15:14:28.528: //67/000000000000/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges Feb 22 15:14:28.528: //67/000000000000/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connect_media returned: SIP_SUCCESS Feb 22 15:14:28.528: //67/000000000000/SIP/State/sipSPIChangeState: 0x6322C744 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE) Feb 22 15:14:28.528: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed. Feb 22 15:14:28.528: //67/000000000000/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connected returned: SIP_SUCCESS Feb 22 15:14:28.532: //67/000000000000/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer Feb 22 15:14:28.532: //67/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Feb 22 15:14:28.532: //67/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x62448678, addr=192.168.227.4, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x60D667F4 Feb 22 15:14:28.532: //67/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Feb 22 15:14:28.532: //67/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Feb 22 15:14:28.532: //67/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x62448678 Feb 22 15:14:28.532: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x62448678, addr=192.168.227.4, port=5060, connId=1 for UDP Feb 22 15:14:28.532: //67/000000000000/SIP/State/sipSPIChangeState: 0x6322C744 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) Feb 22 15:14:28.532: //67/000000000000/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x6322C744 State of The Call : STATE_ACTIVE TCP Sockets Used : NO Calling Number : 8003 Called Number : 8004 Source IP Address (Sig ): 192.168.227.2 Destn SIP Req Addr:Port : 192.168.227.4:5060 Destn SIP Resp Addr:Port : 192.168.227.4:5060 Destination Name : 192.168.227.4 Feb 22 15:14:28.532: //67/000000000000/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 Source IP Address (Media): 192.168.227.2 Source IP Port (Media): 17008 Destn IP Address (Media): 192.168.227.4 Destn IP Port (Media): 2228 Orig Destn IP Address:Port (Media): 0.0.0.0:0 Feb 22 15:14:28.532: //67/000000000000/SIP/Info/sipSPICallActive: Transaction Complete. Lock on Facilities released. Feb 22 15:14:28.532: //67/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Feb 22 15:14:28.532: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 25 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPI_ipip_handle_channel_info: CCSIP:callID 66 ft: 1, inc 4, 192.168.227.4:2228, codec 5 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: callid 66, channels 0x62F3532C caps 0x624597D4 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: pref dtmf 101 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: nego mline 1 dtmf 101 ss 0 ret 0 Feb 22 15:14:28.532: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: retreive codec 5 ptype 0 time 20 bytes 160 Feb 22 15:14:28.532: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 16992 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Negotiated method of dtmf relayand pyld: 6 101 Feb 22 15:14:28.532: //66/AB5163DE8068/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges Feb 22 15:14:28.536: //66/AB5163DE8068/SIP/Info/ccsip_bridge: confID = 26, srcCallID = 66, dstCallID = 67 Feb 22 15:14:28.536: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Feb 22 15:14:28.536: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Feb 22 15:14:28.536: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: ACK sip:8004@192.168.227.4:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.227.2:5060;branch=z9hG4bK29177B From: "8003" ;tag=76D8CC-325 To: ;tag=415DD6EC-F482F731 Date: Fri, 22 Feb 2008 15:14:17 GMT Call-ID: AB56451E-E08F11DC-806AADE1-CDDF26C8@192.168.227.2 Max-Forwards: 70 CSeq: 101 ACK Content-Length: 0 Feb 22 15:14:28.540: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7 Feb 22 15:14:28.540: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIUcccause_to_sipcause: Unknown PSTN cause code from CCAPI:0 Feb 22 15:14:28.540: //67/000000000000/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Feb 22 15:14:28.540: //67/000000000000/SIP/Info/sipSPIPushOrigRequestContainerIntoHolder: Request Container Holder is above threshold...trimming Feb 22 15:14:28.540: //67/000000000000/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Feb 22 15:14:28.540: //67/000000000000/SIP/Info/sipSPISendBye: Associated container=0x63362DCC to Bye Feb 22 15:14:28.540: //67/000000000000/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer Feb 22 15:14:28.540: //67/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Feb 22 15:14:28.540: //67/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x62448678, addr=192.168.227.4, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x60D66184 Feb 22 15:14:28.540: //67/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Feb 22 15:14:28.540: //67/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Feb 22 15:14:28.540: //67/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x62448678 Feb 22 15:14:28.540: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x62448678, addr=192.168.227.4, port=5060, connId=1 for UDP Feb 22 15:14:28.540: //67/000000000000/SIP/Info/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer Feb 22 15:14:28.540: //67/000000000000/SIP/State/sipSPIChangeState: 0x6322C744 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Feb 22 15:14:28.540: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7 Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/Error/act_sentalert_disconnect: Disconnect cause from ccapi :16 and sip_disc_cause: 500 Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/Info/sipSPISendInviteResponse: Associated container=0x63362AFC to Invite Response 500 Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/Transport/sipSPITransportSendMessage: msg=0x623D9E50, addr=192.168.227.3, port=49173, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x60D65870 Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Feb 22 15:14:28.544: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x623D9E50, addr=192.168.227.3, port=5060, connId=0 for UDP Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response Feb 22 15:14:28.544: //66/AB5163DE8068/SIP/State/sipSPIChangeState: 0x6322AD78 : State change from (STATE_SENT_ALERTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Feb 22 15:14:28.544: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:8004@192.168.227.4:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.227.2:5060;branch=z9hG4bK2AE6B From: "8003" ;tag=76D8CC-325 To: ;tag=415DD6EC-F482F731 Date: Fri, 22 Feb 2008 15:14:17 GMT Call-ID: AB56451E-E08F11DC-806AADE1-CDDF26C8@192.168.227.2 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Timestamp: 1203693268 CSeq: 103 BYE Reason: Q.850;cause=0 Content-Length: 0 Feb 22 15:14:28.548: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 192.168.227.3:5060;branch=z9hG4bK37807dc1 From: "8003" ;tag=001e136c4599001c87418538-b9015f0b To: ;tag=76D8B0-214 Date: Fri, 22 Feb 2008 15:14:17 GMT Call-ID: 001e136c-45990016-4f446cea-b9128365@192.168.227.3 Server: Cisco-SIPGateway/IOS-12.x CSeq: 101 INVITE Allow-Events: telephone-event Reason: Q.850;cause=16 Content-Length: 0 Feb 22 15:14:29.008: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.227.3:49197 Feb 22 15:14:29.008: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Feb 22 15:14:29.008: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 Feb 22 15:14:29.012: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Feb 22 15:14:29.012: //66/AB5163DE8068/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x6322AD78 Feb 22 15:14:29.012: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:8004@192.168.227.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.227.3:5060;branch=z9hG4bK37807dc1 From: "8003" ;tag=001e136c4599001c87418538-b9015f0b To: ;tag=76D8B0-214 Call-ID: 001e136c-45990016-4f446cea-b9128365@192.168.227.3 Date: Fri, 02 Nov 2007 23:56:46 GMT CSeq: 101 ACK Content-Length: 0 Feb 22 15:14:29.012: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.227.3,Port 49197, Transport 1, SentBy Port 5060 Feb 22 15:14:29.012: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EEST to SIP default timezone = GMT Feb 22 15:14:29.012: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.227.3,Port 49197, Transport 1, SentBy Port 5060 Feb 22 15:14:29.012: //66/AB5163DE8068/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:780038 ConnTime 0 Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/State/sipSPIChangeState: 0x6322AD78 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x6322AD78 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 8003 Called Number : 8004 Source IP Address (Sig ): 192.168.227.2 Destn SIP Req Addr:Port : 192.168.227.3:5060 Destn SIP Resp Addr:Port : 192.168.227.3:49197 Destination Name : 192.168.227.3 Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 Source IP Address (Media): 192.168.227.2 Source IP Port (Media): 16992 Destn IP Address (Media): 192.168.227.3 Destn IP Port (Media): 26984 Orig Destn IP Address:Port (Media): 0.0.0.0:0 Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 500 Feb 22 15:14:29.016: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[38] removed. Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table. Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6322AD78 key=001e136c-45990016-4f446cea-b9128365@192.168.227.38004 Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table. Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6322AD78 key=001e136c-45990016-4f446cea-b9128365@192.168.227.376D8B0-214 Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 42 Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Feb 22 15:14:29.016: //66/AB5163DE8068/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 6322AD78 Feb 22 15:14:29.020: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[38] Feb 22 15:14:29.020: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.227.4:5060 Feb 22 15:14:29.020: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Feb 22 15:14:29.020: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 Feb 22 15:14:29.020: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Feb 22 15:14:29.024: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.227.2:5060;branch=z9hG4bK2AE6B From: "8003" ;tag=76D8CC-325 To: ;tag=415DD6EC-F482F731 CSeq: 103 BYE Call-ID: AB56451E-E08F11DC-806AADE1-CDDF26C8@192.168.227.2 Contact: User-Agent: PolycomSoundPointIP-SPIP_301-UA/1.6.7.0098 Content-Length: 0 Feb 22 15:14:29.024: //67/000000000000/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 0 DiscTime:780040 ConnTime 779990 Feb 22 15:14:29.024: //67/000000000000/SIP/State/sipSPIChangeState: 0x6322C744 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Feb 22 15:14:29.024: //67/000000000000/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x6322C744 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 8003 Called Number : 8004 Source IP Address (Sig ): 192.168.227.2 Destn SIP Req Addr:Port : 192.168.227.4:5060 Destn SIP Resp Addr:Port : 192.168.227.4:5060 Destination Name : 192.168.227.4 Feb 22 15:14:29.024: //67/000000000000/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 Source IP Address (Media): 192.168.227.2 Source IP Port (Media): 17008 Destn IP Address (Media): 192.168.227.4 Destn IP Port (Media): 2228 Orig Destn IP Address:Port (Media): 0.0.0.0:0 Feb 22 15:14:29.024: //67/000000000000/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 0 Disconnect Cause (SIP) : 200 Feb 22 15:14:29.024: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[39] removed. Feb 22 15:14:29.024: //67/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table. Feb 22 15:14:29.028: //67/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6322C744 key=AB56451E-E08F11DC-806AADE1-CDDF26C8@192.168.227.2 Feb 22 15:14:29.028: //67/000000000000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 43 Feb 22 15:14:29.028: //67/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Feb 22 15:14:29.028: //67/AB5163DE8068/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 6322C744 Feb 22 15:14:29.028: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[39]