Call forwarding to external number SIP SRST no sound - Page 2

Jakub Stroinski · ‎12-01-2015

Below is the current config

Call comes in, goes to 2000 (auto-attendant UCCX trigger in CUCM)

When CUCM is down, 2000 doesnt exti, calls go to 2339 and if no answer to 2340 under SRST mode

All of this works

Now, if I replace 2340 with a mobile number i.e. 95145551234, the mobile phone rings, but when answered, there is no sound (either direction) and the call is disconnected after 60 seconds.

Ideas gentlemen?

boot system flash:c2800nm-adventerprisek9-mz.151-4.M10.bin

ip dhcp excluded-address 172.16.16.1 172.16.16.20

ip dhcp pool voice
import all
network 172.16.16.0 255.255.255.0
default-router 172.16.16.1
option 150 ip 172.16.16.4
dns-server 10.10.0.5
lease 0 2

voice service voip
ip address trusted list
ipv4 72.55.168.18
ipv4 172.10.10.0 255.255.255.0
ipv4 172.16.16.0 255.255.255.0
ip address trusted call-block cause not-in-cug
gcid
clid substitute name
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
no supplementary-service sip moved-temporarily
no supplementary-service sip refer
sip
e911
registrar server expires max 600 min 60
transport switch udp tcp
asserted-id ppi
midcall-signaling passthru
no call service stop
!
voice class sip-profiles 1
request INVITE sip-header From modify "From: (.*<)(.*>)" "From: \"Cisco Lab\" <\2"
!
!
voice register global
timeouts interdigit 5
system message SRST active
max-dn 20
max-pool 20
!
voice register pool 1
translation-profile outgoing SRST
id network 172.16.16.0 mask 255.255.255.0
alias 1 2000 to 2339
dtmf-relay rtp-nte cisco-rtp
call-forward b2bua noan 2340 timeout 15
codec g711ulaw
!
!
!
voice translation-rule 1
rule 1 /.*/ /2000/
!
voice translation-rule 2
rule 1 /.*/ /5143605555/
!
voice translation-rule 3
rule 1 /^9\(.*\)/ /\1/
!
voice translation-rule 4
rule 1 /2000/ /2339/
!
!
voice translation-profile INCOMING
translate called 1
!
voice translation-profile OUTGOING
translate calling 2
translate called 3
!
voice translation-profile SRST
translate called 4

!
license udi pid CISCO2811 sn FTX1126AXXX

!
interface FastEthernet0/0
description DHCPVoIP
ip address 172.16.16.2 255.255.255.0
duplex auto
speed auto
!
interface FastEthernet0/1
no ip address
shutdown
duplex auto
speed auto
!
ip forward-protocol nd
no ip http server
no ip http secure-server
!
!
ip route 0.0.0.0 0.0.0.0 172.16.16.1
!
access-list 23 permit 172.16.16.0 0.0.0.255
access-list 23 permit 172.10.10.0 0.0.0.255
access-list 23 permit 10.10.0.0 0.0.0.255

dial-peer voice 1 voip
translation-profile incoming INCOMING
session protocol sipv2
session target ipv4:172.16.16.4
incoming called-number 12345678
dtmf-relay cisco-rtp rtp-nte
codec g711ulaw
no vad
!
dial-peer voice 3 voip
translation-profile outgoing OUTGOING
destination-pattern 9[2-9]..[2-9]......
session protocol sipv2
session target ipv4:72.55.168.18
no voice-class sip early-offer forced
voice-class sip profiles 1
dtmf-relay rtp-nte cisco-rtp sip-kpml sip-notify
codec g711ulaw
no vad
!
dial-peer voice 4 voip
destination-pattern 2...
session protocol sipv2
session target ipv4:172.16.16.4
dtmf-relay cisco-rtp rtp-nte
codec g711ulaw
no vad
!
!
sip-ua
credentials username 12345678 password 7 XXXXX realm montreal3.voip.ms
authentication username 12345678 password 7 XXXXX realm montreal3.voip.ms
registrar 1 dns:montreal3.voip.ms expires 300
registrar 2 ipv4:172.16.16.2 expires 3600
!
!
!
call-manager-fallback
max-conferences 8 gain -6
transfer-system full-consult
ip source-address 172.16.16.2 port 2000
max-ephones 1
max-dn 1 octo-line
alias 1 2000 to 2339

Ayodeji Okanlawon · ‎12-05-2015

The IOS on the gateway is a little old. I would suggest to upgrade it, before we do any other thing. Can you do that?

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

Im running (which seems to be the newest available for this router on Cisco's download portal)...:

Cisco IOS Software, 2800 Software (C2800NM-ADVENTERPRISEK9-M), Version 15.1(4)M10, RELEASE SOFTWARE (fc2)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2015 by Cisco Systems, Inc.
Compiled Tue 24-Mar-15 09:00 by prod_rel_team

ROM: System Bootstrap, Version 12.4(13r)T, RELEASE SOFTWARE (fc1)

LabDOMAIN1 uptime is 4 weeks, 2 days, 5 hours, 29 minutes
System returned to ROM by reload at 09:51:13 EST Thu Nov 5 2015
System restarted at 09:53:19 EST Thu Nov 5 2015
System image file is "flash:c2800nm-adventerprisek9-mz.151-4.M10.bin"
Last reload type: Normal Reload

Ayodeji Okanlawon · ‎12-05-2015

Thanks for the info. Does normal call work?

Can you try this IOS?

c2800nm-adventerprisek9-mz.151-3.T4.bin

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

Normal calling inbound/outbound works just fine

For the other IOS I will see what I can do remotely since I'm out of the country at present. I'll keep you posted

Ayodeji Okanlawon · ‎12-05-2015

Okay in the mean time we can enable packet capture on cube..

First..

1.   Configure the logging buffer

                                Router#configuration terminal
                                Router(config)#no logging console
                                Router(config)#service timestamps debug datetime msec
                                Router(config)#logging buffered 30000000 debugging
                                Router(config)#service sequence
                                Router(config)#no logging rate-limit
                                Router(config)#exit
                                Router#

Configure capture profile

               !
               ip traffic-export profile TAC mode capture
               bidirectional
               !
               interface fa0/0 ----> Interface which routes the traffic
               ip traffic-export apply TAC 99999999

NB: you will need to do this twice to capture tarffic on both interface that routes traffic to both itsp and cucm. If you only have one interface, then once will be fine.

2. Capture traffic with these exec (enable) level commands

Note: The exec cmds don’t appear until a profile has been configured

router#traffic-export interface fa0/0 clear
router#traffic-export interface fa0/0 start

3.        Do “clear log”.
4.        Make a test call.
5.        After 2 minutes, stop the debugs by entering “undebug all”
6.        Collect the output by entering “show log”

7. Stop the capture

router#traffic-export interface fa0/0 stop

8. Export the pcap file to a server

router#traffic-export interface fa0/0 copy ftp://x.x.x.x/capture.pcap

Send both captures and logs..Attach the logs

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

Just the one interface

LabDOMAIN1#show log
Syslog logging: enabled (5 messages dropped, 3 messages rate-limited, 2119 flushes, 0 overruns, xml disabled, filtering disabled)

No Active Message Discriminator.

No Inactive Message Discriminator.

    Console logging: disabled
    Monitor logging: disabled
    Buffer logging: level debugging, 6703 messages logged, xml disabled,
                    filtering disabled
    Exception Logging: size (4096 bytes)
    Count and timestamp logging messages: disabled
    Persistent logging: disabled

No active filter modules.

    Trap logging: level informational, 109 message lines logged
        Logging Source-Interface:       VRF Name:

Log Buffer (30000000 bytes):

039475: Dec 5 21:12:51.268: %RITE-5-CAPTURE_CLEAR: Cleared IP traffic capture buffer for interface FastEthernet0/0
039476: Dec 5 21:13:00.200: %RITE-5-CAPTURE_START: Started IP traffic capture for interface FastEthernet0/0
LabDOMAIN1#traffic-export interface fa0/0 stop

Ayodeji Okanlawon · ‎12-05-2015

There is nothing in the captures. it should be a pcap file

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

I think I just named the extension incorrectly (typo). Just rename the file.

Ayodeji Okanlawon · ‎12-05-2015

I did but there is nothing in it. It means that you didnt capture it correctly. Please check the steps again

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

I changed version on the router at the same time to the one you recommended. Same behaviour.

LabDOMAIN1#traffic-export interface fa0/0 clear
LabDOMAIN1#traffic-export interface fa0/0 start
LabDOMAIN1#clear log
Clear logging buffer [confirm]
LabDOMAIN1#traffic-export interface fa0/0 stop
LabDOMAIN1#un all
All possible debugging has been turned off
LabDOMAIN1#show logging
Syslog logging: enabled (0 messages dropped, 3 messages rate-limited, 0 flushes, 0 overruns, xml disabled, filtering disabled)

No Active Message Discriminator.

No Inactive Message Discriminator.

    Console logging: disabled
    Monitor logging: disabled
    Buffer logging: level debugging, 35 messages logged, xml disabled,
                    filtering disabled
    Exception Logging: size (4096 bytes)
    Count and timestamp logging messages: disabled
    Persistent logging: disabled

No active filter modules.

    Trap logging: level informational, 36 message lines logged

Log Buffer (30000000 bytes):

000035: Dec 5 22:10:32.004: %RITE-5-CAPTURE_STOP: Stopped IP traffic capture for interface FastEthernet0/0
LabDOMAIN1#traffic-export interface fa0/0 copy tftp:
Address or name of remote host []? 10.10.0.207
Capture buffer filename []? Load/capture.pcap
Copying capture buffer to tftp://10.10.0.207/Load/capture.pcap !!
47057 bytes copied.
LabDOMAIN1#

Ayodeji Okanlawon · ‎12-05-2015

Jakub,

There is no single RTP stream in the capture ( I do see the sip signalling). This is really strange. Just so we dont run into a wrong conclusion. Can you do a packet capture for a working call so atleast we establish that we get media in the captures

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

Here it is

Ayodeji Okanlawon · ‎12-05-2015

Excellent. That was good. I see rtp streams. So capture config is fine and cube does send the correct captures.

Now back to this baffling issue..l promise not to rest till its resolved.

1. Does call forwarding work from internal call to external ( the test we have done so far is from external and then forwarded to external..

2. Please do another test call, send me only this debug

"debug ccsip all"

3. also send your sh run

Please rate all useful posts

Jakub Stroinski · ‎12-05-2015

Yup, works just fine. The sh run hasn't changed since last time it was posted above; just the boot firmware has.

Called from 2810 to 2340 which is forwarded to 95148121234

Content-Disposition: session;handling=required
Content-Length: 301

v=0

o=CiscoSystemsSIP-GW-UserAgent 8249 9802 IN IP4 172.16.16.2
s=SIP Call
c=IN IP4 172.16.16.2
t=0 0
m=audio 16996 RTP/AVP 0 121 101
c=IN IP4 172.16.16.2
a=rtpmap:0 PCMU/8000
a=rtpmap:121 frf-dialed-digit/8000
a=fmtp:121 0-15
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

002372: Dec 5 22:55:38.213: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [72.55.168.18]:5060, local_address:[ - ]
002373: Dec 5 22:55:38.213: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
002374: Dec 5 22:55:38.213: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x4AACC054
002375: Dec 5 22:55:38.213: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x4AACC054, addr=72.55.168.18, port=5060, local_addr=, connid=4, transport=UDP
002376: Dec 5 22:55:38.213: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
002377: Dec 5 22:55:38.213: //189/471A62800000/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.16.2:5060;branch=z9hG4bK658BC;received=66.11.41.90;rport=50744
From: "Cisco Lab" <sip:5143601234@172.16.16.2>;tag=38AA6C-27C
To: <sip:5148121234@72.55.168.18>;tag=as1b17a8ef
Call-ID: 1E5B84C1-9ADA11E5-80B2DB8C-E7BAB034@172.16.16.2
CSeq: 102 INVITE
Server: voip.ms
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:5148121234@72.55.168.18:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 268

v=0
o=root 438937205 438937206 IN IP4 72.55.168.18
s=voip.ms
c=IN IP4 72.55.168.18
t=0 0
m=audio 12888 RTP/AVP 0 18 101

a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

002378: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX
002379: Dec 5 22:55:38.217: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container
002380: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/sipSPIhandle200OKInvite: Transaction active. Facilities will be queued.
002381: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/sipSPIhandle200OKInvite: *** This ccb is the parent
002382: Dec 5 22:55:38.217: //188/471A62800000/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: 188/189, new src/dest ccCallids: 188/189
002383: Dec 5 22:55:38.217: //188/471A62800000/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=188, new streamcallid=188
002384: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/sipSPIProcessNotifyCallInfoHeader: Call-Info header with for Unsolicited Notify Absent,Disabling Unsolicited Notifies
002385: Dec 5 22:55:38.217: //189/471A62800000/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP
002386: Dec 5 22:55:38.217: //189/471A62800000/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:200, container:4E597574
002387: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLExtractSessionExpiresHdr:
Session-Expires value: 1800 refresher: uas
002388: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_RESP
002389: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLInitialSRRespWithSEPeerEventGen: Session refresh and expiry has to be started by the endpoints
002390: Dec 5 22:55:38.217: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLProcessPassPeerEvent: session timer negotiated end to end
002391: Dec 5 22:55:38.217: //189/471A62800000/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_PASS_ST_PARAMS, SE Value:1800, SE Refresher:uas, Min-SE Value:1800, flags:121
002392: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLMain:
SE: 1800;refresher:uas peer refresher:uas, flags:121, posted event:E_STSL_INVALID_PEER_EVENT, reason:4
Configured SE:1800, Configured Min-SE:1800
002393: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container
002394: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
002395: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue
002396: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0
002397: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled
002398: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/ccsip_api_call_connect_media: Unable to add headers into container
002399: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1
002400: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPIValidateConnectionAddress: Dest port = 12888
SIP: Attribute mid, level 1 instance 1 not found.
002401: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
002402: Dec 5 22:55:38.221: //189/471A62800000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 172.16.16.2
002403: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved
as its in use by other codec No Codec
002404: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application
002405: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96
002406: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101
002407: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 96 for Codec:
002408: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved
as its in use by other codec No Codec
002409: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application
002410: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98
002411: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101
002412: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec:
002413: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1
002414: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20
002415: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :20, codecbytes: 160
002416: Dec 5 22:55:38.221: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
002417: Dec 5 22:55:38.221: //189/471A62800000/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw
002418: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0
002419: Dec 5 22:55:38.221: //189/471A62800000/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1
002420: Dec 5 22:55:38.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec
002421: Dec 5 22:55:38.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96
002422: Dec 5 22:55:38.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec
002423: Dec 5 22:55:38.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98
002424: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/sipSPIReserveRtpNtePayload: Reserved the payload type 101 for RTP-NTE
002425: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option
002426: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of full named event(NE) match in fmtp list of events.
002427: Dec 5 22:55:38.225: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0
002428: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
002429: Dec 5 22:55:38.225: //189/471A62800000/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
002430: Dec 5 22:55:38.225: //189/471A62800000/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=72.55.168.18, dest_port=12888
002431: Dec 5 22:55:38.225: //189/471A62800000/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING)
002432: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPICompareStreams: stream 1 dest_port: old=12888 new=12888
002433: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPIGetNewLocalMediaDirection:
New Remote Media Direction = SENDRECV
Present Local Media Direction = SENDRECV
New Local Media Direction = SENDRECV
retVal = 0

002434: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPICompareStreams: Flags set for stream 1: RTP_CHANGE=No CAPS_CHANGE=No RSVP_ADDR_CHANGE=No RSVP_MEDIA_CHANGE=No
002435: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPICompareSDP: Flags set for call: NEW_MEDIA=No DSPDNLD_REQD=No IPIP_MEDIA=No
002436: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPIReplaceSDP: Main stream got changed & it's Flow Around
002437: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPIUpdCallWithSdpInfo:
Preferred Codec : g711ulaw, bytes :160
Preferred DTMF relay : rtp-nte
Preferred NTE payload : 101
Early Media : No
Delayed Media : Yes
Bridge Done : Yes
New Media : No
DSP DNLD Reqd : No

002438: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
002439: Dec 5 22:55:38.225: //189/471A62800000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 172.16.16.2
002440: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 189 peer 188 flags 0x400401 state STATE_RECD_PROCEEDING
002441: Dec 5 22:55:38.225: //189/471A62800000/SIP/Info/sipSPI_ipip_vcc_ProcessXcoderNeeded: Delayed media call & 183 is received.. Do not process VCC..
002442: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: Xcoder not yet used for the call
002443: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service
002444: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured
002445: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 189, Peer CallID 188, sdp 0x4E77ED80 channels 0x4D1A7344
002446: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/copy_channels:
callId 189 size 240 ptr 0x499F3D1C)
002447: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: stream_callid = 189
002448: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: reset the switch..
002449: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 0 mline 1
002450: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711ulaw
002451: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/codec_found:
Codec to be matched: 5
002452: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/codec_found: codecs[i] = 5 & codec = 5 are same..
002453: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 5

002454: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPISrtpTranscoder:
Checking if transcoder is needed for SRTP-RTP
002455: Dec 5 22:55:38.229: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
002456: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation done: stream->negotiated_ptime=20,stream->negotiated_codec_bytes=160, coverted ptime=20 stream->mline_index=1, media_ndx=1
002457: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Adding codec 5 ptype 0 time 20, bytes 160 as channel 0 mline 1 ss 1 72.55.168.18:12888
002458: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 18 mline 1
002459: Dec 5 22:55:38.229: //189/471A62800000/SIP/Media/sipSPISelectCodecVersion: Codec (g729r8) is not in preferred list
002460: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: An exact codec match not configured, using interoperable codec g729r8 pre-ietf
002461: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g729r8 pre-ietf
002462: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/codec_found:
Codec to be matched: 0
002463: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/codec_found: No match for the codecs found..
002464: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 101 mline 1
002465: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: setting ipip_caps DTMF to RFC2833: callid = 189, dtmf = 6
002466: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[channel_ndx].codec = 5

002467: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[channel_ndx].codec = -1

002468: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: tagdata already updated. Do no-op
002469: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 189 flags 0x10000100 state STATE_RECD_PROCEEDING
002470: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: Reporting media in Substate SUBSTATE_PROCEEDING_PROCEEDING
002471: Dec 5 22:55:38.229: //189/471A62800000/SIP/Info/ccsip_update_srtp_caps: 7396: Not Sending NULL SRTP CAPS to SIP LEG
002472: Dec 5 22:55:38.229: //189/471A62800000/SIP/Media/sipSPIUpdCallWithSdpInfo:
Stream type : voice+dtmf
Media line : 1
State : STREAM_ADDING (2)
Stream address type : 1
Callid : 189
Negotiated Codec : g711ulaw, bytes :160
Nego. Codec payload : 0 (tx), 0 (rx)
Negotiated DTMF relay : rtp-nte
Negotiated NTE payload : 101 (tx), 101 (rx)
Negotiated CN payload : 0
Media Srce Addr/Port : [172.16.16.2]:0
Media Dest Addr/Port : [72.55.168.18]:12888

002473: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Error/sipSPICheckAndClearSrcSRTPSdp: CCB SDP source pointer NULL
002474: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges
002475: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connect_media returned: SIP_SUCCESS
002476: Dec 5 22:55:38.233: //189/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE)
002477: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIQoSRevertBW: Entry
002478: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container
002479: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container
002480: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message

002481: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIShrlCall: Check peer: 3 for Shared-Line call, callid: 189
002482: Dec 5 22:55:38.233: //188/471A62800000/SIP/Info/sipSPIShrlCall: Check peer: 4 for Shared-Line call, callid: 188
002483: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIOptionsPing: Session Timer negotiated, not doing Options Ping
002484: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/ccsip_api_call_connected: SDP_INFO PTR 0x0

002485: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/ccsip_api_call_connected: NO SDP YET.

002486: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connected returned: SIP_SUCCESS_DELAYED_MEDIA
002487: Dec 5 22:55:38.233: //189/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (SIP_STATE_RECD_SUCCESS, SUBSTATE_NONE)
002488: Dec 5 22:55:38.233: //189/471A62800000/SIP/Info/sipSPIhandle200OKInvite: starting MediaAck timer(2)
002489: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT: ccb ptr 4D1A05E0

002490: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT: app_diaplay_name[] app_display_num[5148121234]
002491: Dec 5 22:55:38.233: //188/471A62800000/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT : KPML_CONFIGURED[FALSE] collect_digits[95148121234] calledNumber[95148121234] display_name[] display_num[5148121234]
002492: Dec 5 22:55:38.233: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_CONNECT
002493: Dec 5 22:55:38.241: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7
002494: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/sipSPI_ipip_set_history_info_header: No HI header recvd from container
002495: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/preprocessConnect: Negotiation Not Yet done ! Delay Revert BW
002496: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/preprocessConnect: Write sdp_info into msg_body
002497: Dec 5 22:55:38.241: //188/471A62800000/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP
002498: Dec 5 22:55:38.241: //188/471A62800000/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:200, container:4E599514
002499: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_RESP
002500: Dec 5 22:55:38.241: //188/471A62800000/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_PASS_ST_PARAMS, SE Value:1800, SE Refresher:uas, Min-SE Value:1800, flags:121
002501: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/Session-Timer/sipSTSLSRRespPassPeerEventHndlr: Adding session expires header with values received from peer leg
002502: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/Session-Timer/sipSTSLSRRespPassPeerEventHndlr: session timer negotiated end to end
002503: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/Session-Timer/sipSTSLMain:
SE: 1800;refresher:uas peer refresher:uas, flags:121, posted event:E_STSL_INVALID_PEER_EVENT, reason:4
Configured SE:1800, Configured Min-SE:1800
002504: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 8 event
002505: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002506: Dec 5 22:55:38.241: //188/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002507: Dec 5 22:55:38.245: //188/471A62800000/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off
002508: Dec 5 22:55:38.245: //188/471A62800000/SIP/Info/sipSPIAppAddCallInfoUI: callinfo UI update request for callid: 188

002509: Dec 5 22:55:38.245: //188/471A62800000/SIP/Info/sipSPISendInviteResponse: Transaction active. Facilities will be queued.
SIP: (188) Group (a= group line) attribute, level 65535 instance 1 not found.
002510: Dec 5 22:55:38.245: //188/471A62800000/SIP/Info/sipSPIGetCallExtensionSupported: anat enabled, src_sdp dont have anat
002511: Dec 5 22:55:38.245: //188/471A62800000/SIP/Info/sipSPISendInviteResponse: Associated container=0x4E599514 to Invite Response 200
002512: Dec 5 22:55:38.245: //188/471A62800000/SIP/Transport/sipSPISendInviteResponse: Sending 200OK Response to the Transport Layer
002513: Dec 5 22:55:38.245: //188/471A62800000/SIP/Transport/sipSPITransportSendMessage: msg=0x4E6F8FE8, addr=172.16.16.4, port=56947, sentBy_port=5060, local_addr=, is_req=0, transport=2, switch=0, callBack=0x41BD70B0
002514: Dec 5 22:55:38.245: //188/471A62800000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002515: Dec 5 22:55:38.245: //188/471A62800000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
002516: Dec 5 22:55:38.245: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4E6F8FE8, addr=172.16.16.4, port=56947, local_addr=, connId=2 for TCP
002517: Dec 5 22:55:38.245: //188/471A62800000/SIP/Info/sentInviteResponse200: Sent 200Ok for Invite in state STATE_RECD_INVITE
002518: Dec 5 22:55:38.245: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteResponse200: Transaction active. Facilities will be queued.
002519: Dec 5 22:55:38.245: //188/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A05E0 : State change from (STATE_RECD_INVITE, SUBSTATE_NONE) to (STATE_SENT_SUCCESS, SUBSTATE_NONE)
002520: Dec 5 22:55:38.249: //188/471A62800000/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/TCP 172.16.16.4:5060;branch=z9hG4bK22c12871299
From: <sip:2810@172.16.16.4>;tag=39907~3fc70ea7-97d8-43ff-88ef-629b7d5bc97e-32091593
To: <sip:95148121234@172.16.16.2>;tag=38AE38-1063

Date: Sat, 05 Dec 2015 22:55:30 GMT
Call-ID: 471a6280-66316b62-db-41010ac@172.16.16.4
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:5148121234@172.16.16.2>;party=called;screen=no;privacy=off
Contact: <sip:5148121234@172.16.16.2:5060;transport=tcp>
Supported: replaces
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-12.x
Cisco-Gcid: 1E573F11-9ADA-11E5-80AF-DB8CE7BAB034
Session-Expires: 1800;refresher=uas
Require: timer
Supported: timer
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 301

v=0
o=CiscoSystemsSIP-GW-UserAgent 8249 9802 IN IP4 172.16.16.2
s=SIP Call

c=IN IP4 172.16.16.2
t=0 0
m=audio 16996 RTP/AVP 0 121 101
c=IN IP4 172.16.16.2
a=rtpmap:0 PCMU/8000
a=rtpmap:121 frf-dialed-digit/8000
a=fmtp:121 0-15
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

002521: Dec 5 22:55:38.257: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
002522: Dec 5 22:55:38.257: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
002523: Dec 5 22:55:38.257: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x4AACBFE8, addr=172.16.16.4, port=56947, local_addr=, connid=2, transport=TCP
002524: Dec 5 22:55:38.257: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:5148121234@172.16.16.2:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 172.16.16.4:5060;branch=z9hG4bK22d25ff9685
From: <sip:2810@172.16.16.4>;tag=39907~3fc70ea7-97d8-43ff-88ef-629b7d5bc97e-32091593

To: <sip:95148121234@172.16.16.2>;tag=38AE38-1063
Date: Sat, 05 Dec 2015 22:55:30 GMT
Call-ID: 471a6280-66316b62-db-41010ac@172.16.16.4
User-Agent: Cisco-CUCM11.0
Max-Forwards: 70
CSeq: 101 ACK
Allow-Events: presence
Session-ID: 5ff02685d8f11a9918f838ec4aa39906;remote=6da8a2c0a1b7d0a16d7ae83b1ab39907
Content-Type: application/sdp
Content-Length: 223

v=0
o=CiscoSystemsCCM-SIP 39907 1 IN IP4 172.16.16.4
s=SIP Call
c=IN IP4 172.16.16.23
b=TIAS:64000
b=AS:64
t=0 0
m=audio 21022 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

002525: Dec 5 22:55:38.257: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
002526: Dec 5 22:55:38.261: //188/471A62800000/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x4D1A05E0
002527: Dec 5 22:55:38.261: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.4,Port 56947, Transport 2, SentBy Port 5060
002528: Dec 5 22:55:38.261: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EST to SIP default timezone = GMT
002529: Dec 5 22:55:38.261: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.4,Port 56947, Transport 2, SentBy Port 5060
002530: Dec 5 22:55:38.261: //188/471A62800000/SIP/Info/act_sentsucc_new_message_request: Transaction Complete. Lock on Facilities released.
002531: Dec 5 22:55:38.261: //188/471A62800000/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1
002532: Dec 5 22:55:38.261: //188/471A62800000/SIP/Info/sipSPIValidateConnectionAddress: Dest port = 21022
SIP: Attribute mid, level 1 instance 1 not found.
002533: Dec 5 22:55:38.261: //188/471A62800000/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
002534: Dec 5 22:55:38.261: //188/471A62800000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 172.16.16.2
002535: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec
002536: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96
002537: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved
as its in use by other codec No Codec
002538: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application
002539: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98
002540: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101
002541: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec:
002542: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1
002543: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoPtimeNegotiation: No ptime present or multiple ptime attributes that can't be handled
002544: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0
002545: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1
002546: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec
002547: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec
002548: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98
002549: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIReserveRtpNtePayload: Reserved the payload type 101 for RTP-NTE
002550: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option
002551: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of partial named event(NE) match in fmtp list of events.
002552: Dec 5 22:55:38.265: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0
002553: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
002554: Dec 5 22:55:38.265: //188/471A62800000/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
002555: Dec 5 22:55:38.265: //188/471A62800000/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=172.16.16.23, dest_port=21022
002556: Dec 5 22:55:38.265: //188/471A62800000/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING)
002557: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIProcessAckMedia: Media negotiation was not done earlier
002558: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1
002559: Dec 5 22:55:38.265: //188/471A62800000/SIP/Info/sipSPIDoStreamQoSNegotiation: Best effort
002560: Dec 5 22:55:38.265: //188/471A62800000/SIP/Media/sipSPIReplaceSDP: Remote SDP after bridge completed
002561: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIReplaceSDP: Main stream got changed & it's a Flow thru
002562: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 188) to the VOIP RTP library
002563: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
002564: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 172.16.16.2
002565: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
002566: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 172.16.16.2, lport = 16996, raddr = 172.16.16.23, rport=21022, do_rtcp=TRUE
src_callid = 188, dest_callid = 189, stream type = voice+dtmf, stream direction = SENDRECV
media_ip_addr = 172.16.16.23, vrf tableid = 0 media_addr_type = 1
002567: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update
002568: Dec 5 22:55:38.269: //189/471A62800000/SIP/Info/ccsip_update_peer_caps: gccb/stream is NULL, not updating now !!
002569: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPIUpdateGccb: Failure from the peer leg so no updations now!!
002570: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:4E6C0FB8
002571: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPIUpdateRtcpSession: Process Media changes is still pending.
002572: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIGetNewLocalMediaDirection:
New Remote Media Direction = SENDRECV
Present Local Media Direction = SENDRECV
New Local Media Direction = SENDRECV
retVal = 0

002573: Dec 5 22:55:38.269: //188/471A62800000/SIP/State/sipSPIChangeStreamState: Stream (callid = 188) State changed from (STREAM_ADDING) to (STREAM_ACTIVE)
002574: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPIUpdCallWithSdpInfo:
Preferred Codec : g711ulaw, bytes :160
Preferred DTMF relay : cisco-rtp
Preferred NTE payload : 101
Early Media : Yes
Delayed Media : Yes
Bridge Done : Yes
New Media : Yes
DSP DNLD Reqd : Yes

002575: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
002576: Dec 5 22:55:38.269: //188/471A62800000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 172.16.16.2
002577: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 188 peer 189 flags 0x400007 state STATE_SENT_SUCCESS
002578: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPI_ipip_vcc_ProcessXcoderNeeded: xcoder_attached not yet initialised for this call.
002579: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: Xcoder not yet used for the call
002580: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service
002581: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured
002582: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 188, Peer CallID 189, sdp 0x4E6C15C0 channels 0x4D1A1B7C
002583: Dec 5 22:55:38.269: //188/471A62800000/SIP/Info/copy_channels:
callId 188 size 240 ptr 0x48E116B8)
002584: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: stream_callid = 188
002585: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: reset the switch..
002586: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 0 mline 1
002587: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711ulaw
002588: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/codec_found:
Codec to be matched: 5
002589: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/codec_found: codecs[i] = 5 & codec = 5 are same..
002590: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 5

002591: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPISrtpTranscoder:
Checking if transcoder is needed for SRTP-RTP
002592: Dec 5 22:55:38.273: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
002593: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation done: stream->negotiated_ptime=0,stream->negotiated_codec_bytes=160, coverted ptime=20 stream->mline_index=1, media_ndx=1
002594: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Adding codec 5 ptype 0 time 20, bytes 160 as channel 0 mline 1 ss 1 172.16.16.23:21022
002595: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 101 mline 1
002596: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: setting ipip_caps DTMF to RFC2833: callid = 188, dtmf = 6
002597: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[channel_ndx].codec = 5

002598: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[channel_ndx].codec = -1

002599: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: Updating tagdata..
002600: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 188 flags 0x18000100 state STATE_SENT_SUCCESS
002601: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer:
Report initial call media
002602: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: ccb->flags 0xC0601E, ccb->pld.flags_ipip 0x400007

002603: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: Updating the negotiated codec bytes
002604: Dec 5 22:55:38.273: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: Post CAPS to peer.

002605: Dec 5 22:55:38.273: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_caps_ind_internal:
destCallID=189, srcCallID=188,
peer_ccb->call_info.currentLocalName=,
peer_ccb->call_info.currentRemoteName=,
ccb->call_info.currentLocalName=5143601234,
ccb->call_info.currentRemoteName=
002606: Dec 5 22:55:38.273: //189/471A62800000/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=189, current_seq_num=0x0
002607: Dec 5 22:55:38.273: //189/471A62800000/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=189, current_seq_num=0x0
002608: Dec 5 22:55:38.273: //189/471A62800000/SIP/Info/ccsip_update_stream_negotiated_codec: Codec that peer call leg has indicated is same what this call leg is already using.. Do nothing..
002609: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Load DSP with negotiated codec: g711ulaw, Bytes=160
002610: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Set forking flag to 0x0
002611: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB with rx payload = 101, tx payload = 101
002612: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0
002613: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=188
002614: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sip_set_modem_caps: Disabling Modem Relay...
002615: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list
002616: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled
002617: Dec 5 22:55:38.277: //189/471A62800000/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
002618: Dec 5 22:55:38.277: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: 0 Active Streams
002619: Dec 5 22:55:38.277: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: Number of active streams is zero (0)!
002620: Dec 5 22:55:38.277: //189/471A62800000/SIP/Media/sipSPISetStreamInfo:
caps.stream_count=0,caps.stream[0].stream_type=0xFFFF, caps.stream_list.xmitFunc=
002621: Dec 5 22:55:38.277: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: ??unknown??, caps.stream_list.context=
002622: Dec 5 22:55:38.277: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: 0x0 (gccb)
002623: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Load DSP with codec : g711ulaw, Bytes=160, payload = 0
002624: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: ccsip_caps_ind: ccb->pld.flags_ipip = 0x400401
002625: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/sipSPISrtpTranscoder:
Checking if transcoder is needed for SRTP-RTP
002626: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: No video caps detected in the caps posted by peer leg
002627: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Calling cc_api_caps_ack()
002628: Dec 5 22:55:38.277: //188/471A62800000/SIP/Info/ccsip_caps_ack_internal: Set forking flag to 0x0
002629: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: local_codec_dnld needed for initial DO-DO call
002630: Dec 5 22:55:38.277: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: ccb->flags 0xC0601E, ccb->pld.flags_ipip 0x400007

002631: Dec 5 22:55:38.277: //188/471A62800000/SIP/Info/copy_channels:
callId 188 size 240 ptr 0x48E116B8)
002632: Dec 5 22:55:38.277: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 168)
002633: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_event_handler:
ccsip_event_handler: peer ID 188 chans 0x48E116B8 event 168 flags 0xC06018 0x10000100 0x400401 data 0x48E116B8
002634: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_event_handler:
ccsip_event_handler: CC_EV_H245_OPEN_CHANNEL_IND: peer ID 188 chans 0x48E116B8 event 168 flags 0xC06018 0x10000100 0x400401 data 0x48E116B8
002635: Dec 5 22:55:38.277: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_NEW_MEDIA
002636: Dec 5 22:55:38.277: //189/471A62800000/SIP/Info/ccsip_event_handler:
ccsip_event_handler: set event->type = SIPSPI_EV_CC_NEW_MEDIA!: peer ID 188 chans 0x48E116B8 event 168 flags 0xC06018 0x10000100 0x400401 data 0x48E116B8 Media Trigger 0
002637: Dec 5 22:55:38.277: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: CC_R_SUCCESS_WITH_CONFIRMED
002638: Dec 5 22:55:38.277: //188/471A62800000/SIP/Info/sipSPI_ipip_report_media_to_peer: SIP2SIP, posting channel_ind to peer.

002639: Dec 5 22:55:38.277: //188/471A62800000/SIP/Info/ccsip_update_srtp_caps: 7396: Not Sending NULL SRTP CAPS to SIP LEG
002640: Dec 5 22:55:38.277: //188/471A62800000/SIP/Media/sipSPIUpdCallWithSdpInfo:
Stream type : voice+dtmf
Media line : 1
State : STREAM_ACTIVE (5)
Stream address type : 1
Callid : 188
Negotiated Codec : g711ulaw, bytes :160
Nego. Codec payload : 0 (tx), 0 (rx)
Negotiated DTMF relay : rtp-nte
Negotiated NTE payload : 101 (tx), 101 (rx)
Negotiated CN payload : 0
Media Srce Addr/Port : [172.16.16.2]:16996
Media Dest Addr/Port : [172.16.16.23]:21022

002641: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges
002642: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
002643: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 172.16.16.2, lport = 16996, raddr = 172.16.16.23, rport=21022, do_rtcp=TRUE
src_callid = 188, dest_callid = 189, stream type = voice+dtmf, stream direction = SENDRECV
media_ip_addr = 172.16.16.23, vrf tableid = 0 media_addr_type = 1
002644: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update
002645: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/ccsip_update_peer_caps: gccb/stream is NULL, not updating now !!
002646: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sipSPIUpdateGccb: Failure from the peer leg so no updations now!!
002647: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:4E6C0FB8
002648: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled.
002649: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sipSPIProcessMediaChanges: DSPDNLD Reqd is true. Call DoCapsInd
002650: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/ccsip_get_channel_info_count: : 1
002651: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=188, current_seq_num=0x7D8
002652: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=188, current_seq_num=0xA5F
002653: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/ccsip_do_caps_ind_internal: Load DSP with codec: g711ulaw, Bytes=160
002654: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPISetStreamInfo: 1 Active Streams
002655: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice+dtmf) from media
line 1 codec g711ulaw
002656: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPISetStreamInfo:
caps.stream_count=1,caps.stream[0].stream_type=0x3, caps.stream_list.xmitFunc=
002657: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context=
002658: Dec 5 22:55:38.281: //188/471A62800000/SIP/Media/sipSPISetStreamInfo: 0x4E6ECB80 (gccb)
002659: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB with rx payload = 101, tx payload = 101
002660: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0
002661: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=189
002662: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sip_set_modem_caps: Disabling Modem Relay...
002663: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
002664: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list
002665: Dec 5 22:55:38.281: //188/471A62800000/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled
002666: Dec 5 22:55:38.281: //188/471A62800000/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
002667: Dec 5 22:55:38.281: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_caps_ind_internal:
destCallID=189, srcCallID=188,
peer_ccb->call_info.currentLocalName=,
peer_ccb->call_info.currentRemoteName=,
ccb->call_info.currentLocalName=5143601234,
ccb->call_info.currentRemoteName=
002668: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=189, current_seq_num=0x0
002669: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=189, current_seq_num=0x0
002670: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/ccsip_update_stream_negotiated_codec: Codec that peer call leg has indicated is same what this call leg is already using.. Do nothing..
002671: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Load DSP with negotiated codec: g711ulaw, Bytes=160
002672: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Set forking flag to 0x0
002673: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB with rx payload = 101, tx payload = 101
002674: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0
002675: Dec 5 22:55:38.281: //189/471A62800000/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=188
002676: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/sip_set_modem_caps: Disabling Modem Relay...
002677: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list
002678: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled
002679: Dec 5 22:55:38.285: //189/471A62800000/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
002680: Dec 5 22:55:38.285: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: 0 Active Streams
002681: Dec 5 22:55:38.285: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: Number of active streams is zero (0)!
002682: Dec 5 22:55:38.285: //189/471A62800000/SIP/Media/sipSPISetStreamInfo:
caps.stream_count=0,caps.stream[0].stream_type=0xFFFF, caps.stream_list.xmitFunc=
002683: Dec 5 22:55:38.285: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: ??unknown??, caps.stream_list.context=
002684: Dec 5 22:55:38.285: //189/471A62800000/SIP/Media/sipSPISetStreamInfo: 0x0 (gccb)
002685: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Load DSP with codec : g711ulaw, Bytes=160, payload = 0
002686: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: ccsip_caps_ind: ccb->pld.flags_ipip = 0x400401
002687: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/sipSPISrtpTranscoder:
Checking if transcoder is needed for SRTP-RTP
002688: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: No video caps detected in the caps posted by peer leg
002689: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: Calling cc_api_caps_ack()
002690: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/ccsip_caps_ack_internal: Set forking flag to 0x0
002691: Dec 5 22:55:38.285: //189/471A62800000/SIP/Info/ccsip_caps_ind_internal: local_codec_dnld needed for initial DO-DO call
002692: Dec 5 22:55:38.285: //188/471A62800000/SIP/Error/sipSPIProcessAckMedia: Could not modify QoS params for midcall INVITE
002693: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPIQoSRevertBW: Entry
002694: Dec 5 22:55:38.285: //188/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A05E0 : State change from (STATE_SENT_SUCCESS, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE)
002695: Dec 5 22:55:38.285: //188/471A62800000/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x4D1A05E0
State of The Call : STATE_ACTIVE
TCP Sockets Used : YES
Calling Number : 2810
Called Number : 95148121234
Source IP Address (Sig ): 172.16.16.2
Destn SIP Req Addr:Port : 172.16.16.4:5060
Destn SIP Resp Addr:Port : 172.16.16.4:56947
Destination Name : 172.16.16.4

002696: Dec 5 22:55:38.285: //188/471A62800000/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 : 6
Dtmf-relay Payload : 101 (tx), 101 (rx)
Source IP Address (Media): 172.16.16.2
Source IP Port (Media): 16996
Destn IP Address (Media): 172.16.16.23
Destn IP Port (Media): 21022
Orig Destn IP Address:Port (Media): [ - ]:0

002697: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled.
002698: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
002699: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue
002700: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0
002701: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled
002702: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/ccsip_api_request_answer: Could not add hdrs for ev:1
002703: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/ccsip_api_request_answer: ACK handling retval: SIP_SUCCESS
002704: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/act_sentsucc_new_message_request: ccsip_api_request_answer return val:SIP_SUCCESS
002705: Dec 5 22:55:38.285: //188/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A05E0 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE)
002706: Dec 5 22:55:38.285: //188/471A62800000/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x4D1A05E0
State of The Call : STATE_ACTIVE
TCP Sockets Used : YES
Calling Number : 2810
Called Number : 95148121234
Source IP Address (Sig ): 172.16.16.2
Destn SIP Req Addr:Port : 172.16.16.4:5060
Destn SIP Resp Addr:Port : 172.16.16.4:56947
Destination Name : 172.16.16.4

002707: Dec 5 22:55:38.285: //188/471A62800000/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 : 6
Dtmf-relay Payload : 101 (tx), 101 (rx)
Source IP Address (Media): 172.16.16.2
Source IP Port (Media): 16996
Destn IP Address (Media): 172.16.16.23
Destn IP Port (Media): 21022
Orig Destn IP Address:Port (Media): [ - ]:0

002708: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPIProcessHoldTimerForCall: Media IP Addr 172.16.16.23, RTCP Type 3
002709: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
002710: Dec 5 22:55:38.285: //188/471A62800000/SIP/Info/sipSPIOptionsPing: Session Timer negotiated, not doing Options Ping
002711: Dec 5 22:55:38.289: //188/471A62800000/SIP/Info/ccsip_api_update_allowed: UPDATE(2) allowed
002712: Dec 5 22:55:38.289: //188/471A62800000/SIP/Info/ccsip_offer_ans_handle_update_allowed:
002713: Dec 5 22:55:38.289: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 27
002714: Dec 5 22:55:38.289: //189/471A62800000/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT
002715: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLMain:
SE: 1800;refresher:uas peer refresher:uas, flags:121, posted event:E_STSL_INVALID_PEER_EVENT, reason:4
Configured SE:1800, Configured Min-SE:1800
002716: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_handle_channel_info:
CCSIP:callID 189 ft: 1, inc 0, 172.16.16.23:21022, codec 5

002717: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_handle_channel_info:
CCSIP:callid 189 state SIP_STATE_RECD_SUCCESS
002718: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_handle_channel_info: Reset FAX_PASSTHROUGH
002719: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_handle_channel_info: Reset IS_FAX_TO_VOICE_SWITCH..
002720: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
callid 189, channels 0x48E116B8 caps 0x4D08A980
002721: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: Peer cap provided: callid = 189, peer dtmf = 6peer t38 version = 0 peer t38 maxBitRate = 0
002722: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_vcc_ResponseFilterCodecs: codec copied to reference_codec_list = 5
002723: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/codec_found:
Codec to be matched: 5
002724: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/codec_found: codecs[i] = 5 & codec = 5 are same..
002725: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPIUpdatePreferredCodec: num_chans = 1
002726: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_vcc_ResponseFilterCodecs: Static-codec/Equalset/ Subset(with common codec) case..
002727: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
nego mline 1 dtmf 101 ss 1 ret 12
002728: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: Reset IS_FAX_TO_VOICE_SWITCH
002729: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: CCB->pld.flags_ipip 0x400401

002730: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: channel_ind/ack payload type 0

002731: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
retreive codec 5 ptype 0 time 20 bytes 160
002732: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
stream negotiated codec retreive codec 5
002733: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPI_ipip_handle_channel_info: audio channel_ind
002734: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges
002735: Dec 5 22:55:38.289: //189/471A62800000/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 189) to the VOIP RTP library
002736: Dec 5 22:55:38.289: //189/471A62800000/SIP/Media/sipSPIAddStream: Reserved port 17432 for rtp/rtcp
002737: Dec 5 22:55:38.289: //189/471A62800000/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
002738: Dec 5 22:55:38.289: //189/471A62800000/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 172.16.16.2
002739: Dec 5 22:55:38.289: //189/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
002740: Dec 5 22:55:38.289: //189/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 172.16.16.2, lport = 17432, raddr = 72.55.168.18, rport=12888, do_rtcp=TRUE
src_callid = 189, dest_callid = 188, stream type = voice+dtmf, stream direction = SENDRECV
media_ip_addr = 72.55.168.18, vrf tableid = 0 media_addr_type = 1
002741: Dec 5 22:55:38.289: //189/471A62800000/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
002742: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPICreateRtpSession: sess: 4E7841C4 do_rtcp:1
002743: Dec 5 22:55:38.293: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for stream type 1
002744: Dec 5 22:55:38.293: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nte
002745: Dec 5 22:55:38.293: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nse
002746: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for stream type 0
002747: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nte
002748: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nse
002749: Dec 5 22:55:38.293: //189/471A62800000/SIP/Media/sipSPICreateRtpSession: stun is disabled
002750: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled.
002751: Dec 5 22:55:38.293: //189/471A62800000/SIP/Media/sipSPIGetNewLocalMediaDirection:
New Remote Media Direction = SENDRECV
Present Local Media Direction = SENDRECV
New Local Media Direction = SENDRECV
retVal = 0

002752: Dec 5 22:55:38.293: //189/471A62800000/SIP/State/sipSPIChangeStreamState: Stream (callid = 189) State changed from (STREAM_ADDING) to (STREAM_ACTIVE)
002753: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPI_ipip_handle_channel_info: CCSIP: outgoing send PRACK/ACK with SDP
002754: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPIUpdateSrcSdpFixedPart: RTP port already reserved for stream 1, src_port=17432
002755: Dec 5 22:55:38.293: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1
002756: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 17432
002757: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPIUpdateSrcSdpVariablePart:
SIP update src sdp, negoitated codec 5, payload type 0

002758: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Negotiated method of dtmf relayand pyld: 6 101

002759: Dec 5 22:55:38.293: //189/471A62800000/SIP/Info/sipSPIUpdateSrcSdpVariablePart: max_event 15
002760: Dec 5 22:55:38.297: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_MEDIA_EVENT
002761: Dec 5 22:55:38.297: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 30
002762: Dec 5 22:55:38.297: //189/471A62800000/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT
002763: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/Session-Timer/sipSTSLMain:
SE: 1800;refresher:uas peer refresher:uas, flags:121, posted event:E_STSL_INVALID_PEER_EVENT, reason:4
Configured SE:1800, Configured Min-SE:1800
002764: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/act_handle_app_media_event: method = 107 state = 24
002765: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/act_handle_app_media_event: Received media sip event SIP_REQUEST_ANSWER
002766: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 1 event
002767: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002768: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002769: Dec 5 22:55:38.297: //189/471A62800000/SIP/Info/sipSPISendAck: Associated container=0x4E596914 to Ack
002770: Dec 5 22:55:38.297: //189/471A62800000/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer
002771: Dec 5 22:55:38.297: //189/471A62800000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
002772: Dec 5 22:55:38.297: //189/471A62800000/SIP/Transport/sipSPITransportSendMessage: msg=0x48DEE12C, addr=72.55.168.18, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x41BD7EB0
002773: Dec 5 22:55:38.301: //189/471A62800000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002774: Dec 5 22:55:38.301: //189/471A62800000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
002775: Dec 5 22:55:38.301: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:72.55.168.18, rport:5060 with laddr:

002776: Dec 5 22:55:38.301: //189/471A62800000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x48DEE12C
002777: Dec 5 22:55:38.301: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x48DEE12C, addr=72.55.168.18, port=5060, local_addr=, connId=4 for UDP
002778: Dec 5 22:55:38.301: //189/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (SIP_STATE_RECD_SUCCESS, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE)
002779: Dec 5 22:55:38.301: //189/471A62800000/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x4D1A5DA8
State of The Call : STATE_ACTIVE
TCP Sockets Used : NO
Calling Number : 5143601234
Called Number : 5148121234
Source IP Address (Sig ): 172.16.16.2
Destn SIP Req Addr:Port : 72.55.168.18:5060
Destn SIP Resp Addr:Port : 72.55.168.18:5060
Destination Name : 72.55.168.18

002780: Dec 5 22:55:38.301: //189/471A62800000/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 : 6
Dtmf-relay Payload : 101 (tx), 101 (rx)
Source IP Address (Media): 172.16.16.2
Source IP Port (Media): 17432
Destn IP Address (Media): 72.55.168.18
Destn IP Port (Media): 12888
Orig Destn IP Address:Port (Media): [ - ]:0

002781: Dec 5 22:55:38.301: //189/471A62800000/SIP/Info/sipSPICallActive: Transaction Complete. Lock on Facilities released.
002782: Dec 5 22:55:38.301: //189/471A62800000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
002783: Dec 5 22:55:38.301: //189/471A62800000/SIP/Msg/ccsipDisplayMsg:
Sent:
ACK sip:5148121234@72.55.168.18:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.16.2:5060;branch=z9hG4bK661BD4
From: "5143601234" <sip:5143601234@172.16.16.2>;tag=38AA6C-27C
To: <sip:5148121234@72.55.168.18>;tag=as1b17a8ef
Date: Sat, 05 Dec 2015 22:55:30 GMT
Call-ID: 1E5B84C1-9ADA11E5-80B2DB8C-E7BAB034@172.16.16.2
Max-Forwards: 70
CSeq: 102 ACK
Authorization: Digest username="12345678",realm="montreal3.voip.ms",uri="sip:5148121234@72.55.168.18:5060",response="a65975c0ecbc6de4ed8c09df6b0c3ff3",nonce="231d2543",algorithm=MD5
Allow-Events: kpml, telephone-event
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 243

v=0
o=CiscoSystemsSIP-GW-UserAgent 819 9042 IN IP4 172.16.16.2
s=SIP Call
c=IN IP4 172.16.16.2
t=0 0
m=audio 17432 RTP/AVP 0 101
c=IN IP4 172.16.16.2
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

002784: Dec 5 22:55:40.893: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [172.16.16.27]:5060, local_address:[ - ]
002785: Dec 5 22:55:40.893: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
002786: Dec 5 22:55:40.893: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
002787: Dec 5 22:55:40.893: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
REGISTER sip:172.16.16.2 SIP/2.0
Via: SIP/2.0/UDP 172.16.16.27:5060;branch=z9hG4bK7c92821f

From: <sip:2113@172.16.16.2>;tag=6899cd84535b032c58f5674e-3de93615
To: <sip:2113@172.16.16.2>
Call-ID: 6899cd84-535b0166-11e1616d-3d44465f@172.16.16.27
Max-Forwards: 70
Date: Sat, 05 Dec 2015 22:55:39 GMT
CSeq: 677 REGISTER
User-Agent: Cisco-CP7821/10.3.1
Contact: <sip:1e928337-8180-d7c4-b8a2-6e99bb146914@172.16.16.27:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-6899cd84535b>";+u.sip!devicename.ccm.cisco.com="SEP6899CD84535B";+u.sip!model.ccm.cisco.com="621"
Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-escapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-7.0.0,X-cisco-xsi-8.5.1
Content-Length: 0
Expires: 0

002788: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
002789: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0
002790: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x4D195650) with key=[167] to table
002791: Dec 5 22:55:40.897: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
002792: Dec 5 22:55:40.897: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
002793: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.16.16.27,Port 5060, Transport 1, SentBy Port 5060
002794: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()
002795: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()
002796: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 172.16.16.2
002797: Dec 5 22:55:40.897: //-1/246761EE80B3/SIP/State/sipSPIChangeState: 0x4D195650 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
002798: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.27,Port 5060, Transport 1, SentBy Port 5060
002799: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EST to SIP default timezone = GMT
002800: Dec 5 22:55:40.897: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.27,Port 5060, Transport 1, SentBy Port 5060
002801: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
002802: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Transport/sipSPITransportSendMessage: msg=0x4E72CF70, addr=172.16.16.27, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x0
002803: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002804: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
002805: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x4E72CF70 to default port=5060
002806: Dec 5 22:55:40.901: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.27, rport:5060 with laddr:

002807: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x4E72CF70
002808: Dec 5 22:55:40.901: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4E72CF70, addr=172.16.16.27, port=5060, local_addr=, connId=6 for UDP
002809: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
002810: Dec 5 22:55:40.901: //-1/246761EE80B3/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x4D195650 key=6899cd84-535b0166-11e1616d-3d44465f@172.16.16.2721136899cd84535b032c58f5674e-3de93615
002811: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Event/sact_idle_new_message_register:
ccsip_api_register_ind return value : SIP_SUCCESS

002812: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id BE to table
002813: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/State/sipSPIChangeState: 0x4D195650 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)
002814: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/ccsip_register_process_incoming_register: CCSIP_REGISTER:: un-REGISTER request
002815: Dec 5 22:55:40.905: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table: No entry found in sipCallID Table
002816: Dec 5 22:55:40.905: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_registration_passthrough: RCB Pointer : [0x0]
002817: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:172.16.16.27:5060, Host:172.16.16.27
002818: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/sipSPIGetRegisterConfig: Using Global Config
002819: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/sipSPIGetRegisterConfig: Peer-Tag = 4, Reg-Pthru = Disable
002820: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/ccsip_process_registration_passthrough: Register not for passthrough, Try CME
002821: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/ccsip_spi_register_incoming_unregistration: Un-Register for CME case
002822: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Error/ccsip_spi_register_incoming_unregistration: CCSIP_REGISTER:: no registration found
002823: Dec 5 22:55:40.905: //190/246761EE80B3/SIP/Info/ccsip_spi_registration_failed: Sending Register Response 404

002824: Dec 5 22:55:40.909: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP
002825: Dec 5 22:55:40.909: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 43
002826: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Info/sipSPISendResponse: Associated container=0x4E59675C to REGISTER Response 404
002827: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
002828: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Transport/sipSPITransportSendMessage: msg=0x4E6E77D8, addr=172.16.16.27, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x41BDA6B0
002829: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002830: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
002831: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x4E6E77D8 to default port=5060
002832: Dec 5 22:55:40.909: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.27, rport:5060 with laddr:

002833: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x4E6E77D8
002834: Dec 5 22:55:40.909: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4E6E77D8, addr=172.16.16.27, port=5060, local_addr=, connId=6 for UDP
002835: Dec 5 22:55:40.909: //190/246761EE80B3/SIP/State/sipSPIChangeState: 0x4D195650 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
002836: Dec 5 22:55:40.913: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.16.27:5060;branch=z9hG4bK7c92821f
From: <sip:2113@172.16.16.2>;tag=6899cd84535b032c58f5674e-3de93615
To: <sip:2113@172.16.16.2>
Date: Sat, 05 Dec 2015 22:55:40 GMT
Call-ID: 6899cd84-535b0166-11e1616d-3d44465f@172.16.16.27
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 677 REGISTER
Content-Length: 0

002837: Dec 5 22:55:40.913: //190/246761EE80B3/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 172.16.16.27:5060;branch=z9hG4bK7c92821f
From: <sip:2113@172.16.16.2>;tag=6899cd84535b032c58f5674e-3de93615
To: <sip:2113@172.16.16.2>;tag=38D210-843
Date: Sat, 05 Dec 2015 22:55:40 GMT
Call-ID: 6899cd84-535b0166-11e1616d-3d44465f@172.16.16.27

Server: Cisco-SIPGateway/IOS-12.x
CSeq: 677 REGISTER
Content-Length: 0

002838: Dec 5 22:55:46.841: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [72.55.168.18]:5060, local_address:[ - ]
002839: Dec 5 22:55:46.841: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
002840: Dec 5 22:55:46.841: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x4AACC054
002841: Dec 5 22:55:46.841: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x4AACC054, addr=72.55.168.18, port=5060, local_addr=, connid=4, transport=UDP
002842: Dec 5 22:55:46.841: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
BYE sip:5143601234@172.16.16.2:5060 SIP/2.0
Via: SIP/2.0/UDP 72.55.168.18:5060;branch=z9hG4bK426ee949;rport
Max-Forwards: 70
From: <sip:5148121234@72.55.168.18>;tag=as1b17a8ef
To: "Cisco Lab" <sip:5143601234@172.16.16.2>;tag=38AA6C-27C
Call-ID: 1E5B84C1-9ADA11E5-80B2DB8C-E7BAB034@172.16.16.2
CSeq: 102 BYE

User-Agent: voip.ms
Proxy-Authorization: Digest username="12345678", realm="montreal3.voip.ms", algorithm=MD5, uri="sip:72.55.168.18", nonce="231d2543", response="8675cdc4fce943ea6231f4919f9c515a"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

002843: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
002844: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPICheckFromToRequest: Found matching CB 4D1A5DA8
002845: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPILocateInviteDialogCCB: ****Found CCB in UAC table

002846: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 72.55.168.18,Port 5060, Transport 1, SentBy Port 5060
002847: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EST to SIP default timezone = GMT
002848: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 72.55.168.18,Port 5060, Transport 1, SentBy Port 5060
002849: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[189], src[4]
002850: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
002851: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container
002852: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(16) for outgoing call
002853: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container
002854: Dec 5 22:55:46.845: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container
002855: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service
002856: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured
002857: Dec 5 22:55:46.845: //189/471A62800000/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
002858: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue
002859: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0
002860: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled
002861: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/sipAddSipContainerToCallEntry: Unable to add passthru hdrs to container
002862: Dec 5 22:55:46.849: //189/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
002863: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for stream type 0
002864: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nte
002865: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nse
002866: Dec 5 22:55:46.849: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for stream type 1
002867: Dec 5 22:55:46.849: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nte
002868: Dec 5 22:55:46.849: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nse
002869: Dec 5 22:55:46.849: //188/471A62800000/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:4E6C0FB8
002870: Dec 5 22:55:46.849: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for stream type 1
002871: Dec 5 22:55:46.849: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nte
002872: Dec 5 22:55:46.849: //188/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nse
002873: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for stream type 0
002874: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nte
002875: Dec 5 22:55:46.849: //189/471A62800000/SIP/Info/updateGccbTxRxValues: No interworking required for nse
002876: Dec 5 22:55:46.849: //189/471A62800000/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:4E6FABE8
002877: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/ccsip_call_statistics: Stats are not supported for IPIP call.
002878: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service
002879: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured
002880: Dec 5 22:55:46.853: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
002881: Dec 5 22:55:46.853: //189/471A62800000/SIP/Info/ccsip_call_statistics: Stats are not supported for IPIP call.
002882: Dec 5 22:55:46.853: //189/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service
002883: Dec 5 22:55:46.853: //189/471A62800000/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured
002884: Dec 5 22:55:46.853: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
002885: Dec 5 22:55:46.853: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8
002886: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
002887: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 3 event
002888: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002889: Dec 5 22:55:46.853: //188/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002890: Dec 5 22:55:46.857: //188/471A62800000/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
002891: Dec 5 22:55:46.857: //188/471A62800000/SIP/Info/sipSPISendBye: Associated container=0x4E597574 to Bye
002892: Dec 5 22:55:46.857: //188/471A62800000/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer
002893: Dec 5 22:55:46.857: //188/471A62800000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is TRUE
002894: Dec 5 22:55:46.857: //188/471A62800000/SIP/Transport/sipSPITransportSendMessage: msg=0x4E6FC72C, addr=172.16.16.4, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=2, switch=1, callBack=0x41BD7434
002895: Dec 5 22:55:46.857: //188/471A62800000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002896: Dec 5 22:55:46.857: //188/471A62800000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 1
002897: Dec 5 22:55:46.857: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.4, rport:5060 with laddr:

002898: Dec 5 22:55:46.857: //188/471A62800000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x4E6FC72C
002899: Dec 5 22:55:46.857: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4E6FC72C, addr=172.16.16.4, port=5060, local_addr=, connId=3 for TCP
002900: Dec 5 22:55:46.857: //188/471A62800000/SIP/Info/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer
002901: Dec 5 22:55:46.857: //188/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A05E0 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
002902: Dec 5 22:55:46.857: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8
002903: Dec 5 22:55:46.857: //189/471A62800000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 3 event
002904: Dec 5 22:55:46.857: //189/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002905: Dec 5 22:55:46.857: //189/471A62800000/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container
002906: Dec 5 22:55:46.861: //189/471A62800000/SIP/Info/sipSPISendByeResponse: Associated container=0x4E596C84 to Bye Response
002907: Dec 5 22:55:46.861: //189/471A62800000/SIP/Transport/sipSPISendByeResponse: Sending BYE Response to the transport layer
002908: Dec 5 22:55:46.861: //189/471A62800000/SIP/Transport/sipSPITransportSendMessage: msg=0x48DEE12C, addr=72.55.168.18, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x41BD7894
002909: Dec 5 22:55:46.861: //189/471A62800000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002910: Dec 5 22:55:46.861: //189/471A62800000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
002911: Dec 5 22:55:46.861: //189/471A62800000/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x48DEE12C to default port=5060
002912: Dec 5 22:55:46.861: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:72.55.168.18, rport:5060 with laddr:

002913: Dec 5 22:55:46.861: //189/471A62800000/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x48DEE12C
002914: Dec 5 22:55:46.861: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x48DEE12C, addr=72.55.168.18, port=5060, local_addr=, connId=4 for UDP
002915: Dec 5 22:55:46.861: //189/471A62800000/SIP/Info/sentByeResponse: Sent 200ok to the BYE, tearing down the call
002916: Dec 5 22:55:46.861: //189/471A62800000/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 0 DiscTime:372975 ConnTime 372112
002917: Dec 5 22:55:46.861: //189/471A62800000/SIP/Media/sipSPIDestroyRtpSession: stream:4E6FABE8
002918: Dec 5 22:55:46.865: //189/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
002919: Dec 5 22:55:46.865: //189/471A62800000/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x4D1A5DA8
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number : 5143601234
Called Number : 5148121234
Source IP Address (Sig ): 172.16.16.2
Destn SIP Req Addr:Port : 72.55.168.18:5060
Destn SIP Resp Addr:Port : 72.55.168.18:5060
Destination Name : 72.55.168.18

002920: Dec 5 22:55:46.865: //189/471A62800000/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 : 6
Dtmf-relay Payload : 101 (tx), 101 (rx)
Source IP Address (Media): 172.16.16.2
Source IP Port (Media): 17432
Destn IP Address (Media): 72.55.168.18
Destn IP Port (Media): 12888
Orig Destn IP Address:Port (Media): [ - ]:0

002921: Dec 5 22:55:46.865: //189/471A62800000/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 16
Disconnect Cause (SIP) : 200

002922: Dec 5 22:55:46.865: //189/471A62800000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id BD
002923: Dec 5 22:55:46.865: //188/471A62800000/SIP/Msg/ccsipDisplayMsg:
Sent:
BYE sip:2810@172.16.16.4:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 172.16.16.2:5060;branch=z9hG4bK67C56
From: <sip:95148121234@172.16.16.2>;tag=38AE38-1063
To: <sip:2810@172.16.16.4>;tag=39907~3fc70ea7-97d8-43ff-88ef-629b7d5bc97e-32091593
Date: Sat, 05 Dec 2015 22:55:38 GMT
Call-ID: 471a6280-66316b62-db-41010ac@172.16.16.4
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1449356146
CSeq: 101 BYE

Reason: Q.850;cause=16
P-RTP-Stat: PS=421,OS=67360,PR=427,OR=68320,PL=0,JI=0,LA=0,DU=8
Content-Length: 0

002924: Dec 5 22:55:46.865: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 72.55.168.18:5060;branch=z9hG4bK426ee949;rport
From: <sip:5148121234@72.55.168.18>;tag=as1b17a8ef
To: "5143601234" <sip:5143601234@172.16.16.2>;tag=38AA6C-27C
Date: Sat, 05 Dec 2015 22:55:46 GMT
Call-ID: 1E5B84C1-9ADA11E5-80B2DB8C-E7BAB034@172.16.16.2
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 BYE
Reason: Q.850;cause=16
P-RTP-Stat: PS=426,OS=68160,PR=421,OR=67360,PL=0,JI=0,LA=0,DU=8
Content-Length: 0

002925: Dec 5 22:55:46.869: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
002926: Dec 5 22:55:46.869: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x4AACBFE8
002927: Dec 5 22:55:46.869: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x4AACBFE8, addr=172.16.16.4, port=5060, local_addr=, connid=3, transport=TCP
002928: Dec 5 22:55:46.873: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
002929: Dec 5 22:55:46.873: //188/471A62800000/SIP/Info/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK67C56 from via branch list
002930: Dec 5 22:55:46.873: //188/471A62800000/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x4D1A05E0
002931: Dec 5 22:55:46.873: //188/471A62800000/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/TCP 172.16.16.2:5060;branch=z9hG4bK67C56
From: <sip:95148121234@172.16.16.2>;tag=38AE38-1063
To: <sip:2810@172.16.16.4>;tag=39907~3fc70ea7-97d8-43ff-88ef-629b7d5bc97e-32091593
Date: Sat, 05 Dec 2015 22:55:46 GMT
Call-ID: 471a6280-66316b62-db-41010ac@172.16.16.4
Server: Cisco-CUCM11.0
CSeq: 101 BYE
Content-Length: 0

002932: Dec 5 22:55:46.873: //188/471A62800000/SIP/Info/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX
002933: Dec 5 22:55:46.873: //188/471A62800000/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 0 DiscTime:372976 ConnTime 372113
002934: Dec 5 22:55:46.873: //188/471A62800000/SIP/Media/sipSPIDestroyRtpSession: stream:4E6C0FB8
002935: Dec 5 22:55:46.877: //188/471A62800000/SIP/State/sipSPIChangeState: 0x4D1A05E0 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
002936: Dec 5 22:55:46.877: //188/471A62800000/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x4D1A05E0
State of The Call : STATE_DEAD
TCP Sockets Used : YES
Calling Number : 2810
Called Number : 95148121234
Source IP Address (Sig ): 172.16.16.2
Destn SIP Req Addr:Port : 172.16.16.4:5060
Destn SIP Resp Addr:Port : 172.16.16.4:56947
Destination Name : 172.16.16.4

002937: Dec 5 22:55:46.877: //188/471A62800000/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 : 6
Dtmf-relay Payload : 101 (tx), 101 (rx)
Source IP Address (Media): 172.16.16.2
Source IP Port (Media): 16996
Destn IP Address (Media): 172.16.16.23
Destn IP Port (Media): 21022
Orig Destn IP Address:Port (Media): [ - ]:0

002938: Dec 5 22:55:46.877: //188/471A62800000/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 16
Disconnect Cause (SIP) : 200

002939: Dec 5 22:55:46.877: //188/471A62800000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id BC
002940: Dec 5 22:55:46.877: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[165] removed.
002941: Dec 5 22:55:46.877: //188/471A62800000/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
002942: Dec 5 22:55:46.877: //188/471A62800000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x4D1A05E0 key=471a6280-66316b62-db-41010ac@172.16.16.495148121234
002943: Dec 5 22:55:46.877: //188/471A62800000/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
002944: Dec 5 22:55:46.877: //188/471A62800000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x4D1A05E0 key=471a6280-66316b62-db-41010ac@172.16.16.438AE38-1063
002945: Dec 5 22:55:46.877: //188/471A62800000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
002946: Dec 5 22:55:46.881: //188/471A62800000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
002947: Dec 5 22:55:46.881: //188/471A62800000/SIP/Info/ccsip_offer_ans_delete:
002948: Dec 5 22:55:46.881: //188/471A62800000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 4D1A05E0
002949: Dec 5 22:55:46.881: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[165]
002950: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id BE
002951: Dec 5 22:56:12.909: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[167] removed.
002952: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
002953: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x4D195650 key=6899cd84-535b0166-11e1616d-3d44465f@172.16.16.2721136899cd84535b032c58f5674e-3de93615
002954: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
002955: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
002956: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
002957: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/ccsip_offer_ans_delete:
002958: Dec 5 22:56:12.909: //190/246761EE80B3/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 4D195650
002959: Dec 5 22:56:18.865: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[166] removed.
002960: Dec 5 22:56:18.865: //189/471A62800000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
002961: Dec 5 22:56:18.865: //189/471A62800000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x4D1A5DA8 key=1E5B84C1-9ADA11E5-80B2DB8C-E7BAB034@172.16.16.2
002962: Dec 5 22:56:18.865: //189/471A62800000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
002963: Dec 5 22:56:18.865: //189/471A62800000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
002964: Dec 5 22:56:18.865: //189/471A62800000/SIP/Info/ccsip_offer_ans_delete:
002965: Dec 5 22:56:18.865: //189/471A62800000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 4D1A5DA8
002966: Dec 5 22:56:22.089: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x48E11BF4 Connection=0x4AACDDD8, addr=172.16.16.4, port=56947, connid=2 has been REFRESHED
002967: Dec 5 22:56:22.089: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x48E11BF4 Connection=0x4AACDEBC, addr=172.16.16.4, port=5060, connid=3 has been REFRESHED
002968: Dec 5 22:56:22.089: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x48E11BF4,addr=172.16.16.4
002969: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [172.16.16.22]:51276, local_address:[ - ]
002970: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
002971: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
002972: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
REGISTER sip:172.16.16.2 SIP/2.0
Via: SIP/2.0/UDP 172.16.16.22:5060;branch=z9hG4bK1ecedff5
From: <sip:2340@172.16.16.2>;tag=001e4aa8c4dd345c7c00ea70-2fc1fa27
To: <sip:2340@172.16.16.2>
Call-ID: 001e4aa8-c4dd0052-01346d5b-78774e1e@172.16.16.22
Max-Forwards: 70
Date: Sat, 05 Dec 2015 22:56:28 GMT
CSeq: 12454 REGISTER
User-Agent: Cisco-CP7941G/9.4.2
Contact: <sip:ca3399d6-0c96-6086-9681-7980cb27390f@172.16.16.22:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-001e4aa8c4dd>";+u.sip!devicename.ccm.cisco.com="SEP001E4AA8C4DD";+u.sip!model.ccm.cisco.com="115"
Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-escapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-6.0.0,X-cisco-xsi-8.5.1

Content-Length: 0
Expires: 0

002973: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
002974: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0
002975: Dec 5 22:56:28.181: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x4D1A5DA8) with key=[168] to table
002976: Dec 5 22:56:28.181: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
002977: Dec 5 22:56:28.181: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
002978: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.16.16.22,Port 5060, Transport 1, SentBy Port 5060
002979: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()
002980: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()
002981: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 172.16.16.2
002982: Dec 5 22:56:28.185: //-1/4097088780B4/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
002983: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.22,Port 51276, Transport 1, SentBy Port 5060
002984: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EST to SIP default timezone = GMT
002985: Dec 5 22:56:28.185: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.22,Port 51276, Transport 1, SentBy Port 5060
002986: Dec 5 22:56:28.185: //-1/4097088780B4/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
002987: Dec 5 22:56:28.185: //-1/4097088780B4/SIP/Transport/sipSPITransportSendMessage: msg=0x494599FC, addr=172.16.16.22, port=51276, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x0
002988: Dec 5 22:56:28.185: //-1/4097088780B4/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
002989: Dec 5 22:56:28.185: //-1/4097088780B4/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
002990: Dec 5 22:56:28.185: //-1/4097088780B4/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x494599FC to default port=5060
002991: Dec 5 22:56:28.189: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.22, rport:5060 with laddr:

002992: Dec 5 22:56:28.189: //-1/4097088780B4/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x494599FC
002993: Dec 5 22:56:28.189: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x494599FC, addr=172.16.16.22, port=5060, local_addr=, connId=3 for UDP
002994: Dec 5 22:56:28.189: //-1/4097088780B4/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
002995: Dec 5 22:56:28.189: //-1/4097088780B4/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x4D1A5DA8 key=001e4aa8-c4dd0052-01346d5b-78774e1e@172.16.16.222340001e4aa8c4dd345c7c00ea70-2fc1fa27
002996: Dec 5 22:56:28.189: //191/4097088780B4/SIP/Event/sact_idle_new_message_register:
ccsip_api_register_ind return value : SIP_SUCCESS

002997: Dec 5 22:56:28.189: //191/4097088780B4/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id BF to table
002998: Dec 5 22:56:28.189: //191/4097088780B4/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)
002999: Dec 5 22:56:28.189: //191/4097088780B4/SIP/Info/ccsip_register_process_incoming_register: CCSIP_REGISTER:: un-REGISTER request
003000: Dec 5 22:56:28.189: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table: No entry found in sipCallID Table
003001: Dec 5 22:56:28.189: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_registration_passthrough: RCB Pointer : [0x0]
003002: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:172.16.16.22:5060, Host:172.16.16.22
003003: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Info/sipSPIGetRegisterConfig: Using Global Config
003004: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Info/sipSPIGetRegisterConfig: Peer-Tag = 4, Reg-Pthru = Disable
003005: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Info/ccsip_process_registration_passthrough: Register not for passthrough, Try CME
003006: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Info/ccsip_spi_register_incoming_unregistration: Un-Register for CME case
003007: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Error/ccsip_spi_register_incoming_unregistration: CCSIP_REGISTER:: no registration found
003008: Dec 5 22:56:28.193: //191/4097088780B4/SIP/Info/ccsip_spi_registration_failed: Sending Register Response 404

003009: Dec 5 22:56:28.193: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP
003010: Dec 5 22:56:28.193: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 43
003011: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Info/sipSPISendResponse: Associated container=0x4E597AF4 to REGISTER Response 404
003012: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
003013: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Transport/sipSPITransportSendMessage: msg=0x4E6C22A0, addr=172.16.16.22, port=51276, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x41BDA6B0
003014: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
003015: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
003016: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x4E6C22A0 to default port=5060
003017: Dec 5 22:56:28.197: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.22, rport:5060 with laddr:

003018: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x4E6C22A0
003019: Dec 5 22:56:28.197: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4E6C22A0, addr=172.16.16.22, port=5060, local_addr=, connId=3 for UDP
003020: Dec 5 22:56:28.197: //191/4097088780B4/SIP/State/sipSPIChangeState: 0x4D1A5DA8 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
003021: Dec 5 22:56:28.197: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.16.22:5060;branch=z9hG4bK1ecedff5
From: <sip:2340@172.16.16.2>;tag=001e4aa8c4dd345c7c00ea70-2fc1fa27
To: <sip:2340@172.16.16.2>
Date: Sat, 05 Dec 2015 22:56:28 GMT
Call-ID: 001e4aa8-c4dd0052-01346d5b-78774e1e@172.16.16.22
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 12454 REGISTER
Content-Length: 0

003022: Dec 5 22:56:28.197: //191/4097088780B4/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 172.16.16.22:5060;branch=z9hG4bK1ecedff5
From: <sip:2340@172.16.16.2>;tag=001e4aa8c4dd345c7c00ea70-2fc1fa27
To: <sip:2340@172.16.16.2>;tag=398AC8-E7
Date: Sat, 05 Dec 2015 22:56:28 GMT
Call-ID: 001e4aa8-c4dd0052-01346d5b-78774e1e@172.16.16.22
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 12454 REGISTER
Content-Length: 0

003023: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [172.16.16.23]:49711, local_address:[ - ]
003024: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
003025: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
003026: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
REGISTER sip:172.16.16.2 SIP/2.0
Via: SIP/2.0/UDP 172.16.16.23:5060;branch=z9hG4bK5621f649
From: <sip:2339@172.16.16.2>;tag=44e4d945122b02f899e29aab-3949278e
To: <sip:2339@172.16.16.2>
Call-ID: 44e4d945-122b0026-e2b3ad2a-862ae3a9@172.16.16.23
Max-Forwards: 70
Date: Sat, 05 Dec 2015 22:56:52 GMT
CSeq: 669 REGISTER
User-Agent: Cisco-CP7975G/9.4.2
Contact: <sip:60037a2b-e0b4-7c3f-dd9f-4eca6b99ccd4@172.16.16.23:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-44e4d945122b>";+u.sip!devicename.ccm.cisco.com="SEP44E4D945122B";+u.sip!model.ccm.cisco.com="437"
Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-escapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-6.0.0,X-cisco-xsi-8.5.1
Content-Length: 0
Expires: 0

003027: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
003028: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0
003029: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x4D195650) with key=[169] to table
003030: Dec 5 22:56:52.705: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
003031: Dec 5 22:56:52.705: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
003032: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.16.16.23,Port 5060, Transport 1, SentBy Port 5060
003033: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()
003034: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()
003035: Dec 5 22:56:52.705: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 172.16.16.2
003036: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/State/sipSPIChangeState: 0x4D195650 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
003037: Dec 5 22:56:52.709: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.23,Port 49711, Transport 1, SentBy Port 5060
003038: Dec 5 22:56:52.709: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EST to SIP default timezone = GMT
003039: Dec 5 22:56:52.709: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.16.16.23,Port 49711, Transport 1, SentBy Port 5060
003040: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
003041: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/Transport/sipSPITransportSendMessage: msg=0x494599FC, addr=172.16.16.23, port=49711, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x0
003042: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
003043: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
003044: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x494599FC to default port=5060
003045: Dec 5 22:56:52.709: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.23, rport:5060 with laddr:

003046: Dec 5 22:56:52.709: //-1/4F3485AE80B5/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x494599FC
003047: Dec 5 22:56:52.709: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x494599FC, addr=172.16.16.23, port=5060, local_addr=, connId=5 for UDP
003048: Dec 5 22:56:52.713: //-1/4F3485AE80B5/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
003049: Dec 5 22:56:52.713: //-1/4F3485AE80B5/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x4D195650 key=44e4d945-122b0026-e2b3ad2a-862ae3a9@172.16.16.23233944e4d945122b02f899e29aab-3949278e
003050: Dec 5 22:56:52.713: //192/4F3485AE80B5/SIP/Event/sact_idle_new_message_register:
ccsip_api_register_ind return value : SIP_SUCCESS

003051: Dec 5 22:56:52.713: //192/4F3485AE80B5/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id C0 to table
003052: Dec 5 22:56:52.713: //192/4F3485AE80B5/SIP/State/sipSPIChangeState: 0x4D195650 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)
003053: Dec 5 22:56:52.713: //192/4F3485AE80B5/SIP/Info/ccsip_register_process_incoming_register: CCSIP_REGISTER:: un-REGISTER request
003054: Dec 5 22:56:52.713: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table: No entry found in sipCallID Table
003055: Dec 5 22:56:52.713: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_registration_passthrough: RCB Pointer : [0x0]
003056: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:172.16.16.23:5060, Host:172.16.16.23
003057: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/sipSPIGetRegisterConfig: Using Global Config
003058: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/sipSPIGetRegisterConfig: Peer-Tag = 4, Reg-Pthru = Disable
003059: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/ccsip_process_registration_passthrough: Register not for passthrough, Try CME
003060: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/ccsip_spi_register_incoming_unregistration: Un-Register for CME case
003061: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Error/ccsip_spi_register_incoming_unregistration: CCSIP_REGISTER:: no registration found
003062: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/ccsip_spi_registration_failed: Sending Register Response 404

003063: Dec 5 22:56:52.717: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP
003064: Dec 5 22:56:52.717: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 43
003065: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Info/sipSPISendResponse: Associated container=0x4E5981D4 to REGISTER Response 404
003066: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
003067: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Transport/sipSPITransportSendMessage: msg=0x546EB4F8, addr=172.16.16.23, port=49711, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x41BDA6B0
003068: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
003069: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
003070: Dec 5 22:56:52.717: //192/4F3485AE80B5/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x546EB4F8 to default port=5060
003071: Dec 5 22:56:52.721: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.16.23, rport:5060 with laddr:

003072: Dec 5 22:56:52.721: //192/4F3485AE80B5/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x546EB4F8
003073: Dec 5 22:56:52.721: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x546EB4F8, addr=172.16.16.23, port=5060, local_addr=, connId=5 for UDP
003074: Dec 5 22:56:52.721: //192/4F3485AE80B5/SIP/State/sipSPIChangeState: 0x4D195650 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
003075: Dec 5 22:56:52.721: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.16.23:5060;branch=z9hG4bK5621f649
From: <sip:2339@172.16.16.2>;tag=44e4d945122b02f899e29aab-3949278e
To: <sip:2339@172.16.16.2>
Date: Sat, 05 Dec 2015 22:56:52 GMT
Call-ID: 44e4d945-122b0026-e2b3ad2a-862ae3a9@172.16.16.23
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 669 REGISTER
Content-Length: 0

003076: Dec 5 22:56:52.721: //192/4F3485AE80B5/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 172.16.16.23:5060;branch=z9hG4bK5621f649

From: <sip:2339@172.16.16.2>;tag=44e4d945122b02f899e29aab-3949278e
To: <sip:2339@172.16.16.2>;tag=39EA90-E2F
Date: Sat, 05 Dec 2015 22:56:52 GMT
Call-ID: 44e4d945-122b0026-e2b3ad2a-862ae3a9@172.16.16.23
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 669 REGISTER
Content-Length: 0

003077: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id BF
003078: Dec 5 22:57:00.197: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[168] removed.
003079: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
003080: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x4D1A5DA8 key=001e4aa8-c4dd0052-01346d5b-78774e1e@172.16.16.222340001e4aa8c4dd345c7c00ea70-2fc1fa27
003081: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
003082: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
003083: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
003084: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/ccsip_offer_ans_delete:
003085: Dec 5 22:57:00.197: //191/4097088780B4/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 4D1A5DA8
LabDOMAIN1#

Ayodeji Okanlawon · ‎12-05-2015

Jakub,

Is this a log for a working call? What I need is one for a non working..so external to external call. Apologies if I didnt make that clear earlier

Please rate all useful posts