CME to CME over internet behind NAT/PAT on both sides scenario

Hi,

I have a couple CME running routers with FXS cards/analog phones, and I would like to understand how the following scenario would work if possible.

Imagine you plugging in a CME router to your soho internet router , and then I would do the same on my side. So, essentially both sides would be behind edge/NAT routers.

What am I missing here for this to work? I am thinking I would need to add ip/port forwarding on each Edge router for port 2000 to inside local lan IP address running CME on each side?

Is this doable w/o first establishing ipsec vpn tunnel over the internet or using a SIP trunk provider?

Take a look at the simulation in packet tracer (minus telephony-server config), how would you establish connectivity between two Call Managers when each side is behind a NAT?

Thanks

Find more posts tagged with

Comments

Example . I also tried setting up a static route on each edge side as well, didn't make a difference. I understand this wouldn't be a good idea or design anyway....but tried it for kicks anyway.

Sh access-list , does show that the access list is getting hits when you ping from one side to another.

cme_to_cme_over_isp_cloud.jpg

Haven't figured this out yet, found some good threads though-

Setting up CME behind a NAT/PAT router possible? | CertForums

https://supportforums.cisco.com/discussion/10134906/cme-behind-nat

Ciscoshizzle: SIP firewall traversal and why does SIP Not Handle NAT so good?

I run a UC520 at home behind my ADSL router (in bridged mode), CME via a SIP trunk...working fine (now

).

Been a while since I tried your scenario, but maybe try forwarding port 2000 on the WAN side to the CME source address? Or it could be a quirk of PacketTracer...

Hmm, maybe it is a PT glitch? Did you have to enable port forwarding on your ADSL router for UC520?

Been a while since I've tested it that way, as I forward port 5060 for SIP, so it should be the same for SCCP.

azaghul wrote: »

Been a while since I've tested it that way, as I forward port 5060 for SIP, so it should be the same for SCCP.

I think in this case example above with CME with FXS/Analog phones (not CUCM) it's just H323, not SCCP/SIP?

I think we are getting into the limitations of PT...

I'm digging deep here, so could be way off the mark

...shodown & pitviper are the go-to guys on all things Cisco voip.

the analogue phone appears as an eFXS to the router and then talks SCCP internally,
the Cisco native (default) signalling/media protocol over the WAN is H323, so should be no need to worry about port 2000 (SCCP internal only),
the voip dial-peer session target points to the WAN router loopback address(?) to which you bind H323 (h323-gateway voip bind srcaddr <ip-address>)
on the CME router you point the telephony-service source-address to the WAN loopback(?)

As I said I'm probably way off, I don't do VoIP at work so the skills are rusty.

I guess alot also depends if you are using a service provider VPN, a point-to-point tunnel, or just the internet as the WAN.

azaghul wrote: »

I think we are getting into the limitations of PT...

I'm digging deep here, so could be way off the mark ...shodown & pitviper are the go-to guys on all things Cisco voip.
the analogue phone appears as an eFXS to the router and then talks SCCP internally,

the Cisco native (default) signalling/media protocol over the WAN is H323, so should be no need to worry about port 2000 (SCCP internal only),

the voip dial-peer session target points to the WAN router loopback address(?) to which you bind H323 (h323-gateway voip bind srcaddr <ip-address>)

on the CME router you point the telephony-service source-address to the WAN loopback(?)

As I said I'm probably way off, I don't do VoIP at work so the skills are rusty.

I guess alot also depends if you are using a service provider VPN, a point-to-point tunnel, or just the internet as the WAN.

For this specific example, just internet as the WAN, not utilizing VPN.

I am going to spin this up on my physical lab tomorrow and see if I get the same results as in PT.

Ok, so I spun this topology in my lab. When dialing the phone number from CME A router to the CME B router, it's matching a dial peer and sends the call to the 20.20.20.2 ip address, ip address of the outside nat interface on the EDGE B router facing the wan.

dial-peer voice 1 voip
description TO call other CME over WAN
destination-pattern 2...
session target ipv4:20.20.20.2
dtmf-relay h245-alphanumeric

I see that the voip dial peer is hitting the first NAT for the CME A router and also the second NAT router for the remote CME B is also incrementing.

EDGE_NAT_A#sh ip nat translations
Pro Inside global Inside local Outside local Outside global
tcp 10.10.10.2:2 10.10.10.2:23 20.20.20.2:1026 20.20.20.2:1026
tcp 10.10.10.2:6 10.10.10.2:23 20.20.20.2:1032 20.20.20.2:1032
tcp 10.10.10.2:1024 10.10.10.2:43286 1.1.1.12:23 1.1.1.12:23
tcp 10.10.10.2:1025 10.10.10.2:1024 1.1.1.12:23 1.1.1.12:23
tcp 10.10.10.2:18636 192.168.1.200:18636 20.20.20.2:1720 20.20.20.2:1720

before call

EDGE_NAT_B#sh ip nat translations
Pro Inside global Inside local Outside local Outside global
udp 20.20.20.2:123 65.65.65.200:123 192.168.1.7:123 192.168.1.7:123
tcp 20.20.20.2:1 20.20.20.2:23 10.10.10.2:29220 10.10.10.2:29220
tcp 20.20.20.2:2 20.20.20.2:1 10.10.10.2:29220 10.10.10.2:29220
EDGE_NAT_B#

during making the call from CME A to CME B

EDGE_NAT_B#
EDGE_NAT_B#sh ip nat translations
Pro Inside global Inside local Outside local Outside global
tcp 20.20.20.2:1044 20.20.20.2:1720 10.10.10.2:16660 10.10.10.2:16660
udp 20.20.20.2:123 65.65.65.200:123 192.168.1.7:123 192.168.1.7:123
tcp 20.20.20.2:1 20.20.20.2:23 10.10.10.2:29220 10.10.10.2:29220
tcp 20.20.20.2:2 20.20.20.2:1 10.10.10.2:29220 10.10.10.2:29220

After a few seconds I get a fast busy.

So, what else do I need to set up on the EDGE NAT routers to be able to translate the packets from CME_A to CME_B and the other way around?

I am currently pointing the voip dial peer to the remote OUTSIDE NAT address, since I think pointing to the INSIDE NAT interface wouldn't be correct in this case? Since it can be a local LAN address anyway?

Do I need to set up a static translation rule to go from 20.20.20.2 (edge/nat_B outside ip) to 65.65.65.200 (cme_b ip address) ? And the same 10.10.10.2 (edge/nat_A outside ip to 192.168.1.200 (cme_a ip) ?

Something like this on each EDGE/NAT router https://supportforums.cisco.com/discussion/11786016/ios-port-forwarding-commands-port-forwarding ?

Ok so made some progress, it's still not working 100% but here is the latest. I've changed the edge nat config to static to re-direct anything hitting 10.10.10.2 to 192.168.1.200(cme) and anything hitting 20.20.20.2 to 65.65.65.200 (cme). See below .

Call signaling appears to be working, I can call from one side to the other over the wan cloud and through two edge/nat routers, but there is no audio either way.

CME A dial peer

dial-peer voice 1 voip
description TO call other CME over WAN
destination-pattern 7...
session target ipv4:20.20.20.2
dtmf-relay h245-alphanumeric

telephony-service
max-ephones 30
max-dn 30
ip source-address 192.168.1.200 port 2000
auto assign 1 to 1
create cnf-files version-stamp 7960 Jan 03 2015 18:33:06
max-conferences 4 gain -6
transfer-system full-consult
!

CME A ip config

interface FastEthernet0/0
description TO EDGE
ip address 192.168.1.200 255.255.255.0
duplex auto
speed auto
!
!
ip forward-protocol nd
ip route 0.0.0.0 0.0.0.0 192.168.1.100
!

CME_A_#sh voip rtp connections
VoIP RTP active connections :
No. CallId dstCallId LocalRTP RmtRTP LocalIP RemoteIP
1 17 16 19014 16964 192.168.1.200 65.65.65.200
Found 1 active RTP connections
CME_A_#

CME B dial peer

dial-peer voice 1 voip
description to call OTHER CME over WAN
destination-pattern 66..
session target ipv4:10.10.10.2
!
!
!
telephony-service
max-ephones 30
max-dn 30
ip source-address 65.65.65.200 port 2000
auto assign 1 to 1
max-conferences 4 gain -6
transfer-system full-consult

interface FastEthernet0/0
description TO SP CLOUD
ip address 65.65.65.200 255.255.255.0
duplex auto
speed auto
!
!
ip forward-protocol nd
ip route 0.0.0.0 0.0.0.0 65.65.65.100
!

CME_B#sh voip rtp connections
VoIP RTP active connections :
No. CallId dstCallId LocalRTP RmtRTP LocalIP RemoteIP
1 2 3 16964 19014 65.65.65.200 192.168.1.200
Found 1 active RTP connections
CME_B#

EDGE A NAT router

interface FastEthernet0/0
description INSIDE TO CME
ip address 192.168.1.100 255.255.255.0
ip nat inside
duplex auto
speed auto
!
!
interface FastEthernet0/1
description TO WAN CLOUD
ip address 10.10.10.2 255.255.255.0
ip nat outside
duplex auto
speed auto
!
!
ip nat inside source static 192.168.1.200 10.10.10.2
ip http server
ip classless
ip route 0.0.0.0 0.0.0.0 10.10.10.1

EDGE_NAT_A#sh ip nat translations
Pro Inside global Inside local Outside local Outside global
--- 10.10.10.2 192.168.1.200 --- ---
EDGE_NAT_A#

EDGE B NAT router

interface FastEthernet0/0
description TO CME SIDE
ip address 65.65.65.100 255.255.255.0
ip nat inside
duplex auto
speed auto
!
!
interface FastEthernet0/1
description TO WAN SIDE
ip address 20.20.20.2 255.255.255.0
ip nat outside
duplex auto
speed auto
!

!
ip nat inside source static 65.65.65.200 20.20.20.2
ip http server
ip classless
ip route 0.0.0.0 0.0.0.0 20.20.20.1

EDGE_NAT_B#sh ip nat translations
Pro Inside global Inside local Outside local Outside global
--- 20.20.20.2 65.65.65.200 --- ---
EDGE_NAT_B#

JeanM wrote: »

Ok so made some progress, it's still not working 100% but here is the latest. I've changed the edge nat config to static to re-direct anything hitting 10.10.10.2 to 192.168.1.200(cme) and anything hitting 20.20.20.2 to 65.65.65.200 (cme). See below .

Call signaling appears to be working, I can call from one side to the other over the wan cloud and through two edge/nat routers, but there is no audio either way.

!
ip nat inside source static 65.65.65.200 20.20.20.2
ip http server
ip classless
ip route 0.0.0.0 0.0.0.0 20.20.20.1

EDGE_NAT_B#sh ip nat translations
Pro Inside global Inside local Outside local Outside global
--- 20.20.20.2 65.65.65.200 --- ---
EDGE_NAT_B#

Just taking a stab..... going off what Azaghul mentioned...

voice service voip
allow-connections H323 to H323
{then}

H323

I dunno I'm still in the novice stage of Voice....

Tried that as well on both routers, didn't make a difference.

And there is no ip address trusted authenticate in 12.4 ios
Cisco Unified Communications Manager Express Command Reference - Cisco Unified CME Commands: I [Cisco Unified Communications Manager Express] - Cisco

CME_B(config)#voice service voip
CME_B(conf-voi-serv)#?
VOICE SERVICE configuration commands:
allow-connections Allow call connection types
cause-code Sets the internal cause code for SIP and H323
default Set a command to its defaults
exit Exit from voice service configuration mode
fax Global fax commands
h323 Global H.323 configuration commands
media Global media setting for voip calls
modem Global modem commands
no Negate a command or set its defaults
redirect voip call redirect
shutdown Stop VoIP services gracefully without dropping active
calls
signaling Global setting for signaling payload handling
sip SIP configuration commands
supplementary-service Config supplementary service features
CME_B(conf-voi-serv)#
CME_B(conf-voi-serv)#allow-connections ?
h323 from-type h323
sip from-type sip

CME_B(conf-voi-serv)#allow-connections h3
CME_B(conf-voi-serv)#allow-connections h323 to ?
h323 to-type h323
sip to-type sip

CME_B(conf-voi-serv)#allow-connections h323 to h323
CME_B(conf-voi-serv)#
CME_B(conf-voi-serv)#
CME_B(conf-voi-serv)#signaling ?
forward Global setting for signaling forwarding
update Global setting for updating signaling data

CME_B(conf-voi-serv)#h
CME_B(conf-voi-serv)#h323 ?
<cr>

CME_B(conf-voi-serv)#h323
CME_B(conf-serv-h323)#?
VOICE SERVICE VOIP H323 configuration commands:
bearercap-ie Specify bearercap_ie coding
billing B-channel info present
call Global setting for H.323 Calls
ccm-compatible For Cisco Call Manager connections, allow CCM-specific
behavior
default Set a command to its defaults
emptycapability Empty Capability (TCS=0)
encoding Global setting for H.323 ASN.1 encoding options
exit Exit from voice service voip h323 configuration mode
h225 TCP H225 call signalling channel
h245 H245 Signalling
h450 H450 parameter configuration
ip Global H.323 IP related configurations
no Negate a command or set its defaults
ras Gateway RAS configuration
session H323 Voice Protocol session config
telephony-service For CCME H323 connections

CME_B(conf-serv-h323)#

Since call signaling is working both ways, next step would be to debug RTP or what is blocking it right?

dunno I'm still in the novice stage of Voice....

If you are making connections but no actual sound could be codec mismatch.... both Dial-Peers using G711?

Yep, same here, just trying to learn this stuff via the means of labbing what comes into my mind lol. Same codec on both, if I by-pass the edge routers, everything works fine.

I am thinking it's either additional config is needed on the edge/nat routers or maybe additional config is needed on the CME routers for the rtp to work over nat?

another stab

router A

dial-peer voice 1 voip
description TO call other CME over WAN
destination-pattern 7...
session target ipv4:20.20.20.2
dtmf-relay h245-alphanumeric

router B

dial-peer voice 1 voip
description to call OTHER CME over WAN
destination-pattern 66..
session target ipv4:10.10.10.2

my dial-peers on both ends have : [except for the one that uses MGCP... I've got 3 branch over frame with dial peers and then 1 that uses MGCP]

dtmf-relay H245-alphanumeric
codec g711.ulaw
no vad

and all 3 on frame use H323 over frame relay with:
voice service voip
allow-connections h323 to h323
supplementary-service h450.12
[&]
H323

again I'm a really really, really novice on all this..... best to as Pitviper because he's the man on all this..maybe a PM to him?

No difference. Do you have NAT on both sides as well?

I am not using SIP, but I though these posts were interesting:

https://supportforums.cisco.com/discussion/10134906/cme-behind-nat
https://supportforums.cisco.com/discussion/11826301/outgoing-calls-cme-sip-trunk-not-working

http://www.h323.net/config/
http://hive2.hive.packetizer.com/users/h323forum/specifications/h323_nat_fw_solution.pdf

4 How are NAT different and why is that important?

While NAT issues are not unique to H.323 and, in fact, are issues shared by every communication protocol on the Internet, H.323 presents special challenges, since it is often the case that both communicating devices are behind two different NAT devices. Further, it is ideal to allow those devices to communicate directly, or to at least allow media to flow point-to-point between the devices in order to allow the H.323 multimedia systems to scale.

The basic premise of point-to-point media is to have the devices send media packets to each other directly, even if one or both communicating devices are behind a NAT. If only one device is behind a NAT and one knows which one that is, then one could instruct the device on the public Internet to wait for the media to be established from the device behind the NAT first. In so doing, the device behind the NAT creates pinholes in the NAT so the external device can send media to the internal device.

The problem becomes more challenging when both devices are behind a NAT and is complicated even further by the fact that there are a variety of different “NAT types”. The key to solving the double NAT issue is to understand how different NAT devices work and to understand that the behaviour of some NAT devices is more accommodating to achieve direct media. By understanding NAT behaviour, it is then possible to exploit that behaviour in order to enable direct point-to-point media flows.

https://supportforums.cisco.com/discussion/9956976/how-h323-video-between-overlapping-private-networks
According to the above,

"NAT with ALG can translate the embedded addresses in H225/H245."

Maybe use NAT overload?

instead of NAT static mapping?

I messed with NAT and CME for about 2 days and gave up and went with Frame Relay just to get the stuff working.....

Magic Jack works...so does IP phone service from ISP providers such as cable and DSL. those routers do NAT so for all appearances, it does work...but.....
.

Yeah, there is no issue if I am not adding the edge routers into the mix. But, that's not really a realistic scenario then

These are not SIP phones either, there are just analog phones connected to FXS modules in the CME A and B routers, I wanted to keep this as simple as possible before making it more complex. The more I am reading on this, it seems to be related to NAT/H.323 side and NAT packet inspection?

I am going to try switching the VoIP dial-peer to sipv2 next and see if it makes any difference for kicks.

I just remember something about SCCP phones and an issue with NAT somewhere a while ago.....

As far as analog on FXS/FXO ports I did that on my system, it worked with a gateway router and MGCP across WAN.. can call the analog phone on CME from SCCP phones in CME.

Pitviper had that on his system. His red phone!!

so he may have some info on his sticky notes for CCNP voice

Yes, 2 CME routers have a voip dial peer (h.323 or sip) and pots dial peers for the analog phones on the fxs ports.
Each CME router is behind Edge routers doing the nat/pat, form there each edge router connects to a couple routers simulating the wan / eigrp cloud.

Calling remote phone extension over this scenario is currently working, but there is no audio. That's why I am thinking it's an RTP issue over the edge routers. If the edge routers are removed, then this works fine.

So, I switched the voip dial-peer protocol to SIP and made some test calls, same as with h.323, signaling works but no audio.

I ran a debug on CME B router. This is what happens when a call comes in from CME A router and I answer it, and then hang it up.

CME_B#debug ccsip all
This may severely impact system performance. Continue? [confirm]
All SIP Call tracing is enabled
CME_B#
CME_B#
CME_B#
*Mar 1 11:18:19.267: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.10.10.2:63056
*Mar 1 11:18:19.267: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Mar 1 11:18:19.267: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:7701@65.65.65.200:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK72509
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>
Date: Sun, 04 Jan 2015 03:41:55 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Supported: 100rel,timer,replaces
Min-SE: 1800
Cisco-Guid: 1912525453-2465862116-2150164069-1803217998
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: "Lenzman" <sip:6601@10.10.10.2>;party=calling;screen=no;privacy=off
Timestamp: 1420342915
Contact: <sip:6601@10.10.10.2:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 191

v=0
o=CiscoSystemsSIP-GW-UserAgent 8276 1095 IN IP4 192.168.1.200
s=SIP Call
c=IN IP4 192.168.1.200
t=0 0
m=audio 16702 RTP/AVP 8
c=IN IP4 10.10.10.2
a=rtpmap:8 PCMA/8000
a=ptime:20

*Mar 1 11:18:19.271: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.10.2,Port 5060, Transport 1, SentBy Port 5060
*Mar 1 11:18:19.275: //-1/71FED28D8028/SIP/State/sipSPIChangeState: 0x88606548 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Mar 1 11:18:19.275: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.10.2,Port 63056, Transport 1, SentBy Port 5060
*Mar 1 11:18:19.275: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Mar 1 11:18:19.275: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.10.2,Port 63056, Transport 1, SentBy Port 5060
*Mar 1 11:18:19.283: //-1/71FED28D8028/SIP/Info/sipSPISetInfoFromRpid: Received current remote name: Lenzman, current remote number: 6601
*Mar 1 11:18:19.283: //-1/71FED28D8028/SIP/Info/sipSPISetInfoFromRpid: Received ;screen=no ;privacy=off -> Setting Octet3A 0x80, extended_privacy 0x00
*Mar 1 11:18:19.283: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetGtdBody: No valid GTD body found.
*Mar 1 11:18:19.283: //-1/71FED28D8028/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
*Mar 1 11:18:19.287: //-1/71FED28D8028/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x88606548 key=7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.2007701
*Mar 1 11:18:19.287: //-1/71FED28D8028/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id
*Mar 1 11:18:19.287: //-1/71FED28D8028/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 7701
*Mar 1 11:18:19.287: //-1/71FED28D8028/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 6601
*Mar 1 11:18:19.287: //-1/71FED28D8028/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name Lenzman, number 6601, Calling oct3 0x00, oct_3a 0x80, Called number 7701
*Mar 1 11:18:19.291: //-1/71FED28D8028/SIP/Info/sipSPIGetCallConfig: Peer tag 1 matched for incoming call
*Mar 1 11:18:19.291: //-1/71FED28D8028/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Mar 1 11:18:19.291: //-1/71FED28D8028/SIP/Info/sipSPIContinueNewMsgInvite: Calling name Lenzman, number 6601, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 7701, oct3 0x00
*Mar 1 11:18:19.295: //-1/71FED28D8028/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE
*Mar 1 11:18:19.295: //-1/71FED28D8028/SIP/Info/sipSPIContinueNewMsgInvite: Requires reliable-provisional support
*Mar 1 11:18:19.295: //-1/71FED28D8028/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Mar 1 11:18:19.295: //6/71FED28D8028/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1
*Mar 1 11:18:19.295: //6/71FED28D8028/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711alaw) Negotiation Successful on Static Payload for m-line 1
*Mar 1 11:18:19.299: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711alaw ptime :20, codecbytes: 160
*Mar 1 11:18:19.299: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20
*Mar 1 11:18:19.299: //6/71FED28D8028/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711alaw
*Mar 1 11:18:19.299: //6/71FED28D8028/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1
*Mar 1 11:18:19.299: //6/71FED28D8028/SIP/Info/sipSPIDoDTMFRelayNegotiation: Requested DTMF-RELAY option(s) not found in Preferred DTMF-RELAY option list!
*Mar 1 11:18:19.299: //6/71FED28D8028/SIP/Info/sipSPIStreamTypeAndDtmfRelay: DTMF Relay mode: Inband Voice
*Mar 1 11:18:19.299: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0
*Mar 1 11:18:19.299: //6/71FED28D8028/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
*Mar 1 11:18:19.303: //6/71FED28D8028/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
*Mar 1 11:18:19.303: //6/71FED28D8028/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1
payload_type=8, codec_bytes=160, codec=g711alaw, dtmf_relay=inband-voice
stream_type=voice-only (0), dest_ip_address=10.10.10.2, dest_port=16702
*Mar 1 11:18:19.303: //6/71FED28D8028/SIP/Media/sipSPIUpdCallWithSdpInfo:
Preferred Codec : g711alaw, bytes :160
Preferred DTMF relay : inband-voice
Preferred NTE payload : 101
Early Media : No
Delayed Media : No
Bridge Done : No
New Media : No
DSP DNLD Reqd : No

*Mar 1 11:18:19.303: //6/71FED28D8028/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 65.65.65.200
*Mar 1 11:18:19.303: //6/71FED28D8028/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 6 peer 0 flags 0x201
*Mar 1 11:18:19.303: //6/71FED28D8028/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 6, sdp 0x88195174 channels 0x886080F8
*Mar 1 11:18:19.307: //6/71FED28D8028/SIP/Info/copy_channels:
callId 6 size 0 ptr 0x88186D8

*Mar 1 11:18:19.307: //6/71FED28D8028/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 8 mline 1
*Mar 1 11:18:19.307: //6/71FED28D8028/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711alaw
*Mar 1 11:18:19.307: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20
*Mar 1 11:18:19.307: //6/71FED28D8028/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
*Mar 1 11:18:19.307: //6/71FED28D8028/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Adding codec 6 ptype 8 time 20, bytes 160 as channel 0 mline 1 ss 0 10.10.10.2:16702
*Mar 1 11:18:19.307: //6/71FED28D8028/SIP/Info/sipSPI_ipip_report_media_to_peer:
Report initial call media
*Mar 1 11:18:19.311: //6/71FED28D8028/SIP/Info/copy_channels:
callId 6 size 80 ptr 0x84561EF0)
*Mar 1 11:18:19.311: //6/71FED28D8028/SIP/Info/sipSPI_ipip_report_media_to_peer:
CCSIP: Unable to report channel ind
*Mar 1 11:18:19.311: //6/71FED28D8028/SIP/Media/sipSPIUpdCallWithSdpInfo:
Stream type : voice-only
Media line : 1
State : STREAM_ADDING (2)
Callid : -1
Negotiated Codec : g711alaw, bytes :160
Negotiated DTMF relay : inband-voice
Negotiated NTE payload : 0
Negotiated CN payload : 0
Media Srce Addr/Port : 65.65.65.200:0
Media Dest Addr/Port : 10.10.10.2:16702

*Mar 1 11:18:19.311: //6/71FED28D8028/SIP/Info/sipSPIHandleInviteMedia:
Negotiated Codec : g711alaw, bytes :160
Preferred Codec : g711alaw, bytes :160
Preferred DTMF relay 1 : 0
Preferred DTMF relay 2 : 0
Negotiated DTMF relay : 0
Preferred and Negotiated NTE payloads: 101 0
Preferred and Negotiated NSE payloads: 100 0
Preferred and Negotiated Modem Relay: 0 0
Preferred and Negotiated Modem Relay GwXid: 1 0

*Mar 1 11:18:19.311: //6/71FED28D8028/SIP/Info/sipSPIDoQoSNegotiation: SDP body with media description
*Mar 1 11:18:19.315: //6/71FED28D8028/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Mar 1 11:18:19.315: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 16610 for stream 1
*Mar 1 11:18:19.315: //6/71FED28D8028/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=16610
*Mar 1 11:18:19.315: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1
*Mar 1 11:18:19.315: //6/71FED28D8028/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 16610
*Mar 1 11:18:19.319: //6/71FED28D8028/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
*Mar 1 11:18:19.319: //6/71FED28D8028/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo
*Mar 1 11:18:19.319: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed.
*Mar 1 11:18:19.319: //6/71FED28D8028/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS
*Mar 1 11:18:19.319: //6/71FED28D8028/SIP/Info/sipSPIUaddCcbToUASRespTable: ****Adding to UAS Response table.
*Mar 1 11:18:19.319: //6/71FED28D8028/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x88606548 key=7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200105B94-2315
*Mar 1 11:18:19.323: //6/71FED28D8028/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 6 to table
*Mar 1 11:18:19.327: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: msg=0x855545A8, addr=10.10.10.2, port=63056, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Mar 1 11:18:19.327: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Mar 1 11:18:19.327: //6/71FED28D8028/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Mar 1 11:18:19.327: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x855545A8, addr=10.10.10.2, port=5060, connId=0 for UDP
*Mar 1 11:18:19.327: //6/71FED28D8028/SIP/State/sipSPIChangeState: 0x88606548 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE)
*Mar 1 11:18:19.327: //6/71FED28D8028/SIP/Info/sipSPIProcessContactInfo: Previous Hop 10.10.10.2:5060
*Mar 1 11:18:19.343: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK72509
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>;tag=105B94-2315
Date: Fri, 01 Mar 2002 11:18:19 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Timestamp: 1420342915
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 101 INVITE
Allow-Events: telephone-event
Content-Length: 0

*Mar 1 11:18:19.343: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING
*Mar 1 11:18:19.351: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler:
*Mar 1 11:18:19.351: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 13

*Mar 1 11:18:19.351: //6/71FED28D8028/SIP/Info/ccsip_event_handler:
ccsip_event_handler: peer ID 7 chans 0x855C0160 event 138 flags 0x12020038 0x601 data 0x855C0160
*Mar 1 11:18:19.351: //6/71FED28D8028/SIP/Info/ccsip_event_handler:
ccsip_event_handler: CC_EV_H245_SET_MODE: peer ID 7 chans 0x855C0160 event 138 flags 0x12020038 0x601 data 0x855C0160
*Mar 1 11:18:19.351: //6/71FED28D8028/SIP/Info/ccsip_event_handler:
ccsip_event_handler: CC_EV_H245_SET_MODE: peer ID 7 chans 0x855C0160 event 138 flags 0x12020038 0x601 data 0x855C0160, type = 6
*Mar 1 11:18:19.355: //6/71FED28D8028/SIP/Info/ccsip_event_handler:
ccsip_event_handler: !!!!!CC_EV_H245_SET_MODE: not clearing VTSP flag
*Mar 1 11:18:19.355: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: CC_R_SUCCESS_WITH_CONFIRMED
*Mar 1 11:18:19.367: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROGRESS
*Mar 1 11:18:19.367: //6/71FED28D8028/SIP/Info/ccsip_bridge: confID = 3, srcCallID = 6, dstCallID = 7
*Mar 1 11:18:19.367: //6/71FED28D8028/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 6/7
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=-1, new streamcallid=6
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice-only (callid 6) to the VOIP RTP library
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 65.65.65.200
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 65.65.65.200, lport = 16610, raddr = 10.10.10.2, rport=16702, do_rtcp=TRUE
src_callid = 6, dest_callid = 7, stream type = voice-only, stream direction = SENDRECV
media_ip_addr = 10.10.10.2
*Mar 1 11:18:19.371: //6/71FED28D8028/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
*Mar 1 11:18:19.375: //6/71FED28D8028/SIP/Media/sipSPIGetNewLocalMediaDirection:
New Remote Media Direction = SENDRECV
Present Local Media Direction = SENDRECV
New Local Media Direction = SENDRECV
retVal = 0

*Mar 1 11:18:19.379: //6/71FED28D8028/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=6, current_seq_num=0x1750
*Mar 1 11:18:19.379: //6/71FED28D8028/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=6, current_seq_num=0x5AF
*Mar 1 11:18:19.379: //6/71FED28D8028/SIP/Info/ccsip_caps_ind: Load DSP with negotiated codec: g711alaw, Bytes=160
*Mar 1 11:18:19.379: //6/71FED28D8028/SIP/Info/ccsip_caps_ind: Set forking flag to 0x0
*Mar 1 11:18:19.383: //6/71FED28D8028/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB
*Mar 1 11:18:19.383: //6/71FED28D8028/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0
*Mar 1 11:18:19.383: //6/71FED28D8028/SIP/Info/sip_set_modem_caps: Disabling Modem Relay...
*Mar 1 11:18:19.383: //6/71FED28D8028/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
*Mar 1 11:18:19.383: //6/71FED28D8028/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list
*Mar 1 11:18:19.383: //6/71FED28D8028/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled
*Mar 1 11:18:19.383: //6/71FED28D8028/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
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Media/sipSPISetStreamInfo: 1 Active Streams
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice-only) from media line 1
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Media/sipSPISetStreamInfo:
caps.stream_count=1,caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc=
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context=
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Media/sipSPISetStreamInfo: 0x855B1BA0 (gccb)
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Info/ccsip_caps_ind: Load DSP with codec : g711alaw, Bytes=160
*Mar 1 11:18:19.387: //6/71FED28D8028/SIP/Info/ccsip_caps_ind: ccsip_caps_ind: ccb->flags_ipip = 0x603
*Mar 1 11:18:19.391: //6/71FED28D8028/SIP/Info/ccsip_caps_ack: Set forking flag to 0x0
*Mar 1 11:18:19.391: //6/71FED28D8028/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI
*Mar 1 11:18:19.391: //6/71FED28D8028/SIP/Info/sipSPISendInviteResponse183: Session Type is Media/Qos/Security/RTR SDP body is attached
*Mar 1 11:18:19.395: //6/71FED28D8028/SIP/Transport/sipSPISendInviteResponse: Sending 183 Response to the Transport Layer
*Mar 1 11:18:19.395: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: msg=0x85554518, addr=10.10.10.2, port=63056, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x8105FF1C
*Mar 1 11:18:19.399: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Mar 1 11:18:19.399: //6/71FED28D8028/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Mar 1 11:18:19.399: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x85554518, addr=10.10.10.2, port=5060, connId=0 for UDP
*Mar 1 11:18:19.399: //6/71FED28D8028/SIP/Info/sentInviteResponse18x: Sent a 18x Response
*Mar 1 11:18:19.399: //6/71FED28D8028/SIP/Info/setPrackLockIfNeeded: Transaction active. Facilities will be queued.
*Mar 1 11:18:19.407: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK72509
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>;tag=105B94-2315
Date: Fri, 01 Mar 2002 11:18:19 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Timestamp: 1420342915
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 101 INVITE
Require: 100rel
RSeq: 9938
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Allow-Events: telephone-event
Contact: <sip:7701@65.65.65.200:5060>
Content-Disposition: session;handling=required
Content-Type: application/sdp
Content-Length: 191

v=0
o=CiscoSystemsSIP-GW-UserAgent 1365 6528 IN IP4 65.65.65.200
s=SIP Call
c=IN IP4 65.65.65.200
t=0 0
m=audio 16610 RTP/AVP 8
c=IN IP4 65.65.65.200
a=rtpmap:8 PCMA/8000
a=ptime:20

*Mar 1 11:18:19.455: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.10.10.2:63056
*Mar 1 11:18:19.459: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Mar 1 11:18:19.459: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
PRACK sip:7701@65.65.65.200:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK8183E
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>;tag=105B94-2315
Date: Sun, 04 Jan 2015 03:41:55 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
CSeq: 102 PRACK
RAck: 9938 101 INVITE
Max-Forwards: 70
Content-Length: 0

*Mar 1 11:18:19.459: //6/71FED28D8028/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x88606548
*Mar 1 11:18:19.463: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.10.10.2,Port 63056, Transport 1, SentBy Port 5060
*Mar 1 11:18:19.463: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Mar 1 11:18:19.467: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.10.10.2,Port 63056, Transport 1, SentBy Port 5060
*Mar 1 11:18:19.467: //6/71FED28D8028/SIP/Info/act_recdinvite_new_message_request: Transaction Complete. Lock on Facilities released.
*Mar 1 11:18:19.471: //6/71FED28D8028/SIP/Transport/sipSPISendPrackResponse: Sending PRACK Response to the transport layer
*Mar 1 11:18:19.471: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: msg=0x85554998, addr=10.10.10.2, port=63056, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Mar 1 11:18:19.471: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Mar 1 11:18:19.471: //6/71FED28D8028/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Mar 1 11:18:19.471: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x85554998, addr=10.10.10.2, port=5060, connId=0 for UDP
*Mar 1 11:18:19.475: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK8183E
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>;tag=105B94-2315
Date: Fri, 01 Mar 2002 11:18:19 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 PRACK
Content-Length: 0

*Mar 1 11:18:22.491: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_CONNECT
*Mar 1 11:18:22.495: //6/71FED28D8028/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI
*Mar 1 11:18:22.503: //6/71FED28D8028/SIP/Transport/sipSPISendInviteResponse: Sending 200OK Response to the Transport Layer
*Mar 1 11:18:22.503: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: msg=0x85554998, addr=10.10.10.2, port=63056, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x81060204
*Mar 1 11:18:22.503: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Mar 1 11:18:22.503: //6/71FED28D8028/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Mar 1 11:18:22.503: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x85554998, addr=10.10.10.2, port=5060, connId=0 for UDP
*Mar 1 11:18:22.507: //6/71FED28D8028/SIP/Info/sentInviteResponse200: Sent 200Ok for Invite in state STATE_RECD_INVITE
*Mar 1 11:18:22.507: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteResponse200: Transaction active. Facilities will be queued.
*Mar 1 11:18:22.507: //6/71FED28D8028/SIP/State/sipSPIChangeState: 0x88606548 : State change from (STATE_RECD_INVITE, SUBSTATE_NONE) to (STATE_SENT_SUCCESS, SUBSTATE_NONE)
*Mar 1 11:18:22.507: //6/71FED28D8028/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Mar 1 11:18:22.511: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK72509
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>;tag=105B94-2315
Date: Fri, 01 Mar 2002 11:18:19 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Timestamp: 1420342915
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Supported: replaces
Allow-Events: telephone-event
Contact: <sip:7701@65.65.65.200:5060>
Content-Type: application/sdp
Content-Length: 191

v=0
o=CiscoSystemsSIP-GW-UserAgent 1365 6528 IN IP4 65.65.65.200
s=SIP Call
c=IN IP4 65.65.65.200
t=0 0
m=audio 16610 RTP/AVP 8
c=IN IP4 65.65.65.200
a=rtpmap:8 PCMA/8000
a=ptime:20

*Mar 1 11:18:22.551: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.10.10.2:63056
*Mar 1 11:18:22.555: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Mar 1 11:18:22.555: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:7701@65.65.65.200:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.10.2:5060;branch=z9hG4bK922B3
From: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
To: <sip:7701@65.65.65.200>;tag=105B94-2315
Date: Sun, 04 Jan 2015 03:41:55 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0

*Mar 1 11:18:22.555: //6/71FED28D8028/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x88606548
*Mar 1 11:18:22.559: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.10.10.2,Port 63056, Transport 1, SentBy Port 5060
*Mar 1 11:18:22.559: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Mar 1 11:18:22.563: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.10.10.2,Port 63056, Transport 1, SentBy Port 5060
*Mar 1 11:18:22.563: //6/71FED28D8028/SIP/Info/act_sentsucc_new_message_request: Transaction Complete. Lock on Facilities released.
*Mar 1 11:18:22.563: //6/71FED28D8028/SIP/State/sipSPIChangeState: 0x88606548 : State change from (STATE_SENT_SUCCESS, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE)
*Mar 1 11:18:22.563: //6/71FED28D8028/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x88606548
State of The Call : STATE_ACTIVE
TCP Sockets Used : NO
Calling Number : 6601
Called Number : 7701
Source IP Address (Sig ): 65.65.65.200
Destn SIP Req Addr:Port : 10.10.10.2:5060
Destn SIP Resp Addr:Port : 10.10.10.2:63056
Destination Name : 10.10.10.2

*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : g711alaw
Negotiated Codec Bytes : 160
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 65.65.65.200
Source IP Port (Media): 16610
Destn IP Address (Media): 10.10.10.2
Destn IP Port (Media): 16702
Orig Destn IP Address:Port (Media): 0.0.0.0:0

*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPICreateAndStartRtpTimer:
*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled.
*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPIProcessHoldTimerForCall: Media IP Addr 10.10.10.2, RTCP Type 3
*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Connection=0x883160C4, addr=10.10.10.2, port=5060, connid=1 has been aged out
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostCloseConnection: Posting UDP conn close for addr=10.10.10.2, port=5060, connid=1
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipDeleteConnInstance: Deleted conn=0x883160C4, connid=1, addr=10.10.10.2, port=5060, transport=udp
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x85554488,addr=10.10.10.2
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportStopAgeingTimer: Aging timer stopped for holder=0x85554488,addr=10.10.10.2
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipDeleteConnHolder: Deleted holder=0x85554488, addr=10.10.10.2, count=0
*Mar 1 11:18:22.595: //-1/xxxxxxxxxxxx/SIP/Info/udpsock_close_connect: Socket fd: 1 closed for connid 1 with remote port: 5060
*Mar 1 11:19:10.199: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Mar 1 11:19:10.203: //6/71FED28D8028/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI
*Mar 1 11:19:10.203: //6/71FED28D8028/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
*Mar 1 11:19:10.203: //6/71FED28D8028/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
*Mar 1 11:19:10.207: //6/71FED28D8028/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer
*Mar 1 11:19:10.207: //6/71FED28D8028/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Mar 1 11:19:10.207: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: msg=0x85554488, addr=10.10.10.2, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x81060440
*Mar 1 11:19:10.207: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Mar 1 11:19:10.207: //6/71FED28D8028/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Mar 1 11:19:10.211: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x85554878,addr=10.10.10.2
*Mar 1 11:19:10.211: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnHolder: Created new holder=0x85554878, addr=10.10.10.2
*Mar 1 11:19:10.211: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting UDP conn create request for addr=10.10.10.2, port=5060, context=0x8831555C
*Mar 1 11:19:10.211: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x88316168,addr=10.10.10.2, port=5060
*Mar 1 11:19:10.211: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new initiated conn=0x88316168, connid=-1, addr=10.10.10.2, port=5060, transport=udp
*Mar 1 11:19:10.211: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering ccb=0x88606548 with connection=0x88316168
*Mar 1 11:19:10.215: //6/71FED28D8028/SIP/Transport/sipSPITransportSendMessage: Deferred sending msg=0x85554488
*Mar 1 11:19:10.223: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWConnectionCreated: context=0x8831555C
*Mar 1 11:19:10.223: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: gConnTab=0x8831555C, addr=10.10.10.2, port=5060, connid=1, transport=udp
*Mar 1 11:19:10.223: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportStopConnWaitTimer: Wait timer stopped for connection=0x88316168,addr=10.10.10.2, port=5060
*Mar 1 11:19:10.223: //6/71FED28D8028/SIP/Transport/sipTransportPostInternalMsg: Posting Internal Msg type=0
*Mar 1 11:19:10.223: //6/71FED28D8028/SIP/Info/ccsip_lock_ccb: CCB locked; reference count=1
*Mar 1 11:19:10.227: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessInternalMsg: context=0x88606548
*Mar 1 11:19:10.231: //6/71FED28D8028/SIP/Info/ccsip_unlock_ccb: CCB unlocked; reference count=0
*Mar 1 11:19:10.231: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x85554488, addr=10.10.10.2, port=5060, connId=1 for UDP
*Mar 1 11:19:10.231: //6/71FED28D8028/SIP/Info/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer
*Mar 1 11:19:10.231: //6/71FED28D8028/SIP/State/sipSPIChangeState: 0x88606548 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Mar 1 11:19:10.235: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
BYE sip:6601@10.10.10.2:5060 SIP/2.0
Via: SIP/2.0/UDP 65.65.65.200:5060;branch=z9hG4bK2F04
From: <sip:7701@65.65.65.200>;tag=105B94-2315
To: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
Date: Fri, 01 Mar 2002 11:18:22 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1014981550
CSeq: 101 BYE
Reason: Q.850;cause=16
Content-Length: 0

*Mar 1 11:19:10.275: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.10.10.2:5060
*Mar 1 11:19:10.279: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Mar 1 11:19:10.279: //6/71FED28D8028/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x88606548
*Mar 1 11:19:10.279: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 65.65.65.200:5060;branch=z9hG4bK2F04
From: <sip:7701@65.65.65.200>;tag=105B94-2315
To: "Lenzman" <sip:6601@10.10.10.2>;tag=6948E0-F2
Date: Sun, 04 Jan 2015 03:42:46 GMT
Call-ID: 7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200
Server: Cisco-SIPGateway/IOS-12.x
Timestamp: 1014981550
Content-Length: 0
CSeq: 101 BYE

*Mar 1 11:19:10.283: //6/71FED28D8028/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 43630 DiscTime:112302 ConnTime 107524
*Mar 1 11:19:10.287: //6/71FED28D8028/SIP/State/sipSPIChangeState: 0x88606548 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Mar 1 11:19:10.287: //6/71FED28D8028/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x88606548
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number : 6601
Called Number : 7701
Source IP Address (Sig ): 65.65.65.200
Destn SIP Req Addr:Port : 10.10.10.2:5060
Destn SIP Resp Addr:Port : 10.10.10.2:63056
Destination Name : 10.10.10.2

*Mar 1 11:19:10.287: //6/71FED28D8028/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : g711alaw
Negotiated Codec Bytes : 160
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 65.65.65.200
Source IP Port (Media): 16610
Destn IP Address (Media): 10.10.10.2
Destn IP Port (Media): 16702
Orig Destn IP Address:Port (Media): 0.0.0.0:0

*Mar 1 11:19:10.287: //6/71FED28D8028/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 16
Disconnect Cause (SIP) : 200

*Mar 1 11:19:10.287: //6/71FED28D8028/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 6
*Mar 1 11:19:10.291: //6/71FED28D8028/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
*Mar 1 11:19:10.291: //6/71FED28D8028/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x88606548 key=7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.2007701
*Mar 1 11:19:10.291: //6/71FED28D8028/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
*Mar 1 11:19:10.291: //6/71FED28D8028/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x88606548 key=7637C454-92FA11E4-802BE665-6B7AEC4E@192.168.1.200105B94-2315
*Mar 1 11:19:10.295: //6/71FED28D8028/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Mar 1 11:19:10.295: //6/71FED28D8028/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 88606548
CME_B#
CME_B#
CME_B#un all
All possible debugging has been turned off
CME_B#

*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled.
*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPIProcessHoldTimerForCall: Media IP Addr 10.10.10.2, RTCP Type 3
*Mar 1 11:18:22.567: //6/71FED28D8028/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Connection=0x883160C4, addr=10.10.10.2, port=5060, connid=1 has been aged out
*Mar 1 11:18:22.591: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostCloseConnection: Posting UDP conn close for addr=10.10.10.2, port=5060, connid=1

So here you can see RTP timer timing out and then ending the session.... on UDP port 5060.....

the connection is made as you said but then zippo nadda and the RTP session times out....\

that's probably you hanging up the phone and the session is closed

if your using NAT or NAT overload or even PAT and you haven't told your router that UDP ports are ok. geez I'm thinking firewalls.... see novice here....

So on the EDGE_A I have a static entry like , 192.168.1.200 is CME_A and 10.10.10.2 is the outside interface of the edge router facing the WAN.
ip nat inside source static 192.168.1.200 10.10.10.2

And on the EDGE_B I have a similar entry to point traffic coming to 20.20.20.2 to the CME_B at 65.65.65.200
ip nat inside source static 65.65.65.200 20.20.20.2

I tried adding back an entry below and also sppecifically added permit udp any any , no difference, still just signaling works but no audio.

ip nat inside source list TEST interface FastEthernet0/1 overload
ip nat inside source static 192.168.1.200 10.10.10.2
!
ip access-list extended TEST
permit ip any any
permit udp any any

Alright, looks to be working now, going to make some more calls and verify it.

It seems adding a static ip nat inside source static udp CME_IP 5060 Edge_Outside_IP 5060 extendable on both edge routers fixed it.

Glad I wasn't crazy when I thought I had my dial-peer configured right, and was thinking it's an RTP issue all along , woot!

Confirmed, signaling and now rtp is working both ways.

Here is a good debug

CME_A_#debug ccsip all
This may severely impact system performance. Continue? [confirm]
All SIP Call tracing is enabled
CME_A_#
CME_A_#
CME_A_#
CME_A_#
CME_A_#
*Jan 4 05:22:11.180: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 20.20.20.2:59570
*Jan 4 05:22:11.180: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jan 4 05:22:11.180: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:6601@192.168.1.200:5060 SIP/2.0
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bK919B5
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>
Date: Fri, 01 Mar 2002 12:58:35 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Supported: 100rel,timer,replaces
Min-SE: 1800
Cisco-Guid: 3688424679-743051734-2148715475-4247906904
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: "Goldie" <sip:7701@20.20.20.2>;party=calling;screen=no;privacy=off
Timestamp: 1014987515
Contact: <sip:7701@20.20.20.2:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 189

v=0
o=CiscoSystemsSIP-GW-UserAgent 4151 6864 IN IP4 65.65.65.200
s=SIP Call
c=IN IP4 65.65.65.200
t=0 0
m=audio 19012 RTP/AVP 8
c=IN IP4 20.20.20.2
a=rtpmap:8 PCMA/8000
a=ptime:20

*Jan 4 05:22:11.188: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 20.20.20.2,Port 5060, Transport 1, SentBy Port 5060
*Jan 4 05:22:11.188: //-1/DBD8E4E78012/SIP/State/sipSPIChangeState: 0x8561974C : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Jan 4 05:22:11.188: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:11.188: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Jan 4 05:22:11.192: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:11.196: //-1/DBD8E4E78012/SIP/Info/sipSPISetInfoFromRpid: Received current remote name: Goldie, current remote number: 7701
*Jan 4 05:22:11.196: //-1/DBD8E4E78012/SIP/Info/sipSPISetInfoFromRpid: Received ;screen=no ;privacy=off -> Setting Octet3A 0x80, extended_privacy 0x00
*Jan 4 05:22:11.200: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetGtdBody: No valid GTD body found.
*Jan 4 05:22:11.200: //-1/DBD8E4E78012/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
*Jan 4 05:22:11.200: //-1/DBD8E4E78012/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x8561974C key=E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.2006601
*Jan 4 05:22:11.200: //-1/DBD8E4E78012/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id
*Jan 4 05:22:11.200: //-1/DBD8E4E78012/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 6601
*Jan 4 05:22:11.200: //-1/DBD8E4E78012/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 7701
*Jan 4 05:22:11.204: //-1/DBD8E4E78012/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name Goldie, number 7701, Calling oct3 0x00, oct_3a 0x80, Called number 6601
*Jan 4 05:22:11.204: //-1/DBD8E4E78012/SIP/Info/sipSPIGetCallConfig: Peer tag 1 matched for incoming call
*Jan 4 05:22:11.208: //-1/DBD8E4E78012/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Jan 4 05:22:11.208: //-1/DBD8E4E78012/SIP/Info/sipSPIContinueNewMsgInvite: Calling name Goldie, number 7701, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 6601, oct3 0x00
*Jan 4 05:22:11.208: //-1/DBD8E4E78012/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE
*Jan 4 05:22:11.208: //-1/DBD8E4E78012/SIP/Info/sipSPIContinueNewMsgInvite: Requires reliable-provisional support
*Jan 4 05:22:11.208: //-1/DBD8E4E78012/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Jan 4 05:22:11.208: //39/DBD8E4E78012/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1
*Jan 4 05:22:11.212: //39/DBD8E4E78012/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711alaw) Negotiation Successful on Static Payload for m-line 1
*Jan 4 05:22:11.212: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711alaw ptime :20, codecbytes: 160
*Jan 4 05:22:11.212: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20
*Jan 4 05:22:11.212: //39/DBD8E4E78012/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711alaw
*Jan 4 05:22:11.212: //39/DBD8E4E78012/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1
*Jan 4 05:22:11.212: //39/DBD8E4E78012/SIP/Info/sipSPIDoDTMFRelayNegotiation: Requested DTMF-RELAY option(s) not found in Preferred DTMF-RELAY option list!
*Jan 4 05:22:11.212: //39/DBD8E4E78012/SIP/Info/sipSPIStreamTypeAndDtmfRelay: DTMF Relay mode: Inband Voice
*Jan 4 05:22:11.216: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0
*Jan 4 05:22:11.216: //39/DBD8E4E78012/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
*Jan 4 05:22:11.216: //39/DBD8E4E78012/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
*Jan 4 05:22:11.216: //39/DBD8E4E78012/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1
payload_type=8, codec_bytes=160, codec=g711alaw, dtmf_relay=inband-voice
stream_type=voice-only (0), dest_ip_address=20.20.20.2, dest_port=19012
*Jan 4 05:22:11.216: //39/DBD8E4E78012/SIP/Media/sipSPIUpdCallWithSdpInfo:
Preferred Codec : g711alaw, bytes :160
Preferred DTMF relay : h245-alphanumeric
Preferred NTE payload : 101
Early Media : No
Delayed Media : No
Bridge Done : No
New Media : No
DSP DNLD Reqd : No

*Jan 4 05:22:11.216: //39/DBD8E4E78012/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.200
*Jan 4 05:22:11.220: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 39 peer 0 flags 0x201
*Jan 4 05:22:11.220: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 39, sdp 0x884BECCC channels 0x8561B2FC
*Jan 4 05:22:11.220: //39/DBD8E4E78012/SIP/Info/copy_channels:
callId 39 size 0 ptr 0x8816A250)
*Jan 4 05:22:11.220: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 8 mline 1
*Jan 4 05:22:11.220: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711alaw
*Jan 4 05:22:11.220: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20
*Jan 4 05:22:11.220: //39/DBD8E4E78012/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
*Jan 4 05:22:11.220: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Adding codec 6 ptype 8 time 20, bytes 160 as channel 0 mline 1 ss 0 20.20.20.2:19012
*Jan 4 05:22:11.224: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_report_media_to_peer:
Report initial call media
*Jan 4 05:22:11.224: //39/DBD8E4E78012/SIP/Info/copy_channels:
callId 39 size 80 ptr 0x84AB59F0)
*Jan 4 05:22:11.224: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_report_media_to_peer:
CCSIP: Unable to report channel ind
*Jan 4 05:22:11.224: //39/DBD8E4E78012/SIP/Media/sipSPIUpdCallWithSdpInfo:
Stream type : voice-only
Media line : 1
State : STREAM_ADDING (2)
Callid : -1
Negotiated Codec : g711alaw, bytes :160
Negotiated DTMF relay : inband-voice
Negotiated NTE payload : 0
Negotiated CN payload : 0
Media Srce Addr/Port : 192.168.1.200:0
Media Dest Addr/Port : 20.20.20.2:19012

*Jan 4 05:22:11.224: //39/DBD8E4E78012/SIP/Info/sipSPIHandleInviteMedia:
Negotiated Codec : g711alaw, bytes :160
Preferred Codec : g711alaw, bytes :160
Preferred DTMF relay 1 : 3
Preferred DTMF relay 2 : 0
Negotiated DTMF relay : 0
Preferred and Negotiated NTE payloads: 101 0
Preferred and Negotiated NSE payloads: 100 0
Preferred and Negotiated Modem Relay: 0 0
Preferred and Negotiated Modem Relay GwXid: 1 0

*Jan 4 05:22:11.228: //39/DBD8E4E78012/SIP/Info/sipSPIDoQoSNegotiation: SDP body with media description
*Jan 4 05:22:11.228: //39/DBD8E4E78012/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Jan 4 05:22:11.228: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 17184 for stream 1
*Jan 4 05:22:11.228: //39/DBD8E4E78012/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=17184
*Jan 4 05:22:11.232: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1
*Jan 4 05:22:11.232: //39/DBD8E4E78012/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 17184
*Jan 4 05:22:11.232: //39/DBD8E4E78012/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
*Jan 4 05:22:11.232: //39/DBD8E4E78012/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo
*Jan 4 05:22:11.232: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed.
*Jan 4 05:22:11.236: //39/DBD8E4E78012/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS
*Jan 4 05:22:11.236: //39/DBD8E4E78012/SIP/Info/sipSPIUaddCcbToUASRespTable: ****Adding to UAS Response table.
*Jan 4 05:22:11.236: //39/DBD8E4E78012/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x8561974C key=E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200C51530-236B
*Jan 4 05:22:11.236: //39/DBD8E4E78012/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 27 to table
*Jan 4 05:22:11.240: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: msg=0x887481D0, addr=20.20.20.2, port=59570, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Jan 4 05:22:11.240: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jan 4 05:22:11.240: //39/DBD8E4E78012/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jan 4 05:22:11.240: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x887481D0, addr=20.20.20.2, port=5060, connId=0 for UDP
*Jan 4 05:22:11.244: //39/DBD8E4E78012/SIP/State/sipSPIChangeState: 0x8561974C : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE)
*Jan 4 05:22:11.244: //39/DBD8E4E78012/SIP/Info/sipSPIProcessContactInfo: Previous Hop 20.20.20.2:5060
*Jan 4 05:22:11.248: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING
*Jan 4 05:22:11.252: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler:
*Jan 4 05:22:11.256: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 13

*Jan 4 05:22:11.256: //39/DBD8E4E78012/SIP/Info/ccsip_event_handler:
ccsip_event_handler: peer ID 40 chans 0x8578F670 event 138 flags 0x12020038 0x601 data 0x8578F670
*Jan 4 05:22:11.256: //39/DBD8E4E78012/SIP/Info/ccsip_event_handler:
ccsip_event_handler: CC_EV_H245_SET_MODE: peer ID 40 chans 0x8578F670 event 138 flags 0x12020038 0x601 data 0x8578F670
*Jan 4 05:22:11.256: //39/DBD8E4E78012/SIP/Info/ccsip_event_handler:
ccsip_event_handler: CC_EV_H245_SET_MODE: peer ID 40 chans 0x8578F670 event 138 flags 0x12020038 0x601 data 0x8578F670, type = 6
*Jan 4 05:22:11.256: //39/DBD8E4E78012/SIP/Info/ccsip_event_handler:
ccsip_event_handler: !!!!!CC_EV_H245_SET_MODE: not clearing VTSP flag
*Jan 4 05:22:11.256: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: CC_R_SUCCESS_WITH_CONFIRMED
*Jan 4 05:22:11.268: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bK919B5
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Sun, 04 Jan 2015 05:22:11 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Timestamp: 1014987515
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 101 INVITE
Allow-Events: telephone-event
Content-Length: 0

*Jan 4 05:22:11.276: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROGRESS
*Jan 4 05:22:11.276: //39/DBD8E4E78012/SIP/Info/ccsip_bridge: confID = 9, srcCallID = 39, dstCallID = 40
*Jan 4 05:22:11.276: //39/DBD8E4E78012/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 39/40
*Jan 4 05:22:11.276: //39/DBD8E4E78012/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=-1, new streamcallid=39
*Jan 4 05:22:11.276: //39/DBD8E4E78012/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions
*Jan 4 05:22:11.276: //39/DBD8E4E78012/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice-only (callid 39) to the VOIP RTP library
*Jan 4 05:22:11.280: //39/DBD8E4E78012/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.200
*Jan 4 05:22:11.280: //39/DBD8E4E78012/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
*Jan 4 05:22:11.280: //39/DBD8E4E78012/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 192.168.1.200, lport = 17184, raddr = 20.20.20.2, rport=19012, do_rtcp=TRUE
src_callid = 39, dest_callid = 40, stream type = voice-only, stream direction = SENDRECV
media_ip_addr = 20.20.20.2
*Jan 4 05:22:11.280: //39/DBD8E4E78012/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
*Jan 4 05:22:11.280: //39/DBD8E4E78012/SIP/Media/sipSPIGetNewLocalMediaDirection:
New Remote Media Direction = SENDRECV
Present Local Media Direction = SENDRECV
New Local Media Direction = SENDRECV
retVal = 0

*Jan 4 05:22:11.288: //39/DBD8E4E78012/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=39, current_seq_num=0x1049
*Jan 4 05:22:11.288: //39/DBD8E4E78012/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=39, current_seq_num=0x14E4
*Jan 4 05:22:11.288: //39/DBD8E4E78012/SIP/Info/ccsip_caps_ind: Load DSP with negotiated codec: g711alaw, Bytes=160
*Jan 4 05:22:11.288: //39/DBD8E4E78012/SIP/Info/ccsip_caps_ind: Set forking flag to 0x0
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Info/sip_set_modem_caps: Disabling Modem Relay...
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled
*Jan 4 05:22:11.292: //39/DBD8E4E78012/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
*Jan 4 05:22:11.292: //39/DBD8E4E78012/SIP/Media/sipSPISetStreamInfo: 1 Active Streams
*Jan 4 05:22:11.296: //39/DBD8E4E78012/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice-only) from media line 1
*Jan 4 05:22:11.296: //39/DBD8E4E78012/SIP/Media/sipSPISetStreamInfo:
caps.stream_count=1,caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc=
*Jan 4 05:22:11.296: //39/DBD8E4E78012/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context=
*Jan 4 05:22:11.296: //39/DBD8E4E78012/SIP/Media/sipSPISetStreamInfo: 0x887A6CA0 (gccb)
*Jan 4 05:22:11.296: //39/DBD8E4E78012/SIP/Info/ccsip_caps_ind: Load DSP with codec : g711alaw, Bytes=160
*Jan 4 05:22:11.296: //39/DBD8E4E78012/SIP/Info/ccsip_caps_ind: ccsip_caps_ind: ccb->flags_ipip = 0x603
*Jan 4 05:22:11.300: //39/DBD8E4E78012/SIP/Info/ccsip_caps_ack: Set forking flag to 0x0
*Jan 4 05:22:11.300: //39/DBD8E4E78012/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI
*Jan 4 05:22:11.300: //39/DBD8E4E78012/SIP/Info/sipSPISendInviteResponse183: Session Type is Media/Qos/Security/RTR SDP body is attached
*Jan 4 05:22:11.308: //39/DBD8E4E78012/SIP/Transport/sipSPISendInviteResponse: Sending 183 Response to the Transport Layer
*Jan 4 05:22:11.308: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: msg=0x887482F0, addr=20.20.20.2, port=59570, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x8105FF1C
*Jan 4 05:22:11.308: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jan 4 05:22:11.308: //39/DBD8E4E78012/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jan 4 05:22:11.308: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x887482F0, addr=20.20.20.2, port=5060, connId=0 for UDP
*Jan 4 05:22:11.308: //39/DBD8E4E78012/SIP/Info/sentInviteResponse18x: Sent a 18x Response
*Jan 4 05:22:11.308: //39/DBD8E4E78012/SIP/Info/setPrackLockIfNeeded: Transaction active. Facilities will be queued.
*Jan 4 05:22:11.316: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bK919B5
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Sun, 04 Jan 2015 05:22:11 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Timestamp: 1014987515
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 101 INVITE
Require: 100rel
RSeq: 7694
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Allow-Events: telephone-event
Contact: <sip:6601@192.168.1.200:5060>
Content-Disposition: session;handling=required
Content-Type: application/sdp
Content-Length: 194

v=0
o=CiscoSystemsSIP-GW-UserAgent 3190 4529 IN IP4 192.168.1.200
s=SIP Call
c=IN IP4 192.168.1.200
t=0 0
m=audio 17184 RTP/AVP 8
c=IN IP4 192.168.1.200
a=rtpmap:8 PCMA/8000
a=ptime:20

*Jan 4 05:22:11.368: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 20.20.20.2:59570
*Jan 4 05:22:11.368: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jan 4 05:22:11.368: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
PRACK sip:6601@192.168.1.200:5060 SIP/2.0
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bKA2409
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Fri, 01 Mar 2002 12:58:35 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
CSeq: 102 PRACK
RAck: 7694 101 INVITE
Max-Forwards: 70
Content-Length: 0

*Jan 4 05:22:11.372: //39/DBD8E4E78012/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x8561974C
*Jan 4 05:22:11.376: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:11.376: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Jan 4 05:22:11.380: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:11.380: //39/DBD8E4E78012/SIP/Info/act_recdinvite_new_message_request: Transaction Complete. Lock on Facilities released.
*Jan 4 05:22:11.384: //39/DBD8E4E78012/SIP/Transport/sipSPISendPrackResponse: Sending PRACK Response to the transport layer
*Jan 4 05:22:11.384: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: msg=0x887486E0, addr=20.20.20.2, port=59570, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Jan 4 05:22:11.384: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jan 4 05:22:11.384: //39/DBD8E4E78012/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jan 4 05:22:11.384: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x887486E0, addr=20.20.20.2, port=5060, connId=0 for UDP
*Jan 4 05:22:11.388: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bKA2409
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Sun, 04 Jan 2015 05:22:11 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 102 PRACK
Content-Length: 0

*Jan 4 05:22:17.096: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_CONNECT
*Jan 4 05:22:17.100: //39/DBD8E4E78012/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI
*Jan 4 05:22:17.108: //39/DBD8E4E78012/SIP/Transport/sipSPISendInviteResponse: Sending 200OK Response to the Transport Layer
*Jan 4 05:22:17.108: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: msg=0x887486E0, addr=20.20.20.2, port=59570, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x81060204
*Jan 4 05:22:17.108: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jan 4 05:22:17.108: //39/DBD8E4E78012/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jan 4 05:22:17.108: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x887486E0, addr=20.20.20.2, port=5060, connId=0 for UDP
*Jan 4 05:22:17.112: //39/DBD8E4E78012/SIP/Info/sentInviteResponse200: Sent 200Ok for Invite in state STATE_RECD_INVITE
*Jan 4 05:22:17.112: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteResponse200: Transaction active. Facilities will be queued.
*Jan 4 05:22:17.112: //39/DBD8E4E78012/SIP/State/sipSPIChangeState: 0x8561974C : State change from (STATE_RECD_INVITE, SUBSTATE_NONE) to (STATE_SENT_SUCCESS, SUBSTATE_NONE)
*Jan 4 05:22:17.112: //39/DBD8E4E78012/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Jan 4 05:22:17.116: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bK919B5
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Sun, 04 Jan 2015 05:22:11 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Timestamp: 1014987515
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Supported: replaces
Allow-Events: telephone-event
Contact: <sip:6601@192.168.1.200:5060>
Content-Type: application/sdp
Content-Length: 194

v=0
o=CiscoSystemsSIP-GW-UserAgent 3190 4529 IN IP4 192.168.1.200
s=SIP Call
c=IN IP4 192.168.1.200
t=0 0
m=audio 17184 RTP/AVP 8
c=IN IP4 192.168.1.200
a=rtpmap:8 PCMA/8000
a=ptime:20

*Jan 4 05:22:17.160: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 20.20.20.2:59570
*Jan 4 05:22:17.160: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jan 4 05:22:17.160: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:6601@192.168.1.200:5060 SIP/2.0
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bKB2144
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Fri, 01 Mar 2002 12:58:35 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0

*Jan 4 05:22:17.164: //39/DBD8E4E78012/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x8561974C
*Jan 4 05:22:17.164: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:17.168: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Jan 4 05:22:17.168: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:17.168: //39/DBD8E4E78012/SIP/Info/act_sentsucc_new_message_request: Transaction Complete. Lock on Facilities released.
*Jan 4 05:22:17.168: //39/DBD8E4E78012/SIP/State/sipSPIChangeState: 0x8561974C : State change from (STATE_SENT_SUCCESS, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE)
*Jan 4 05:22:17.168: //39/DBD8E4E78012/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x8561974C
State of The Call : STATE_ACTIVE
TCP Sockets Used : NO
Calling Number : 7701
Called Number : 6601
Source IP Address (Sig ): 192.168.1.200
Destn SIP Req Addr:Port : 20.20.20.2:5060
Destn SIP Resp Addr:Port : 20.20.20.2:59570
Destination Name : 20.20.20.2

*Jan 4 05:22:17.172: //39/DBD8E4E78012/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : g711alaw
Negotiated Codec Bytes : 160
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 192.168.1.200
Source IP Port (Media): 17184
Destn IP Address (Media): 20.20.20.2
Destn IP Port (Media): 19012
Orig Destn IP Address:Port (Media): 0.0.0.0:0

*Jan 4 05:22:17.172: //39/DBD8E4E78012/SIP/Info/sipSPICreateAndStartRtpTimer:
*Jan 4 05:22:17.172: //39/DBD8E4E78012/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled.
*Jan 4 05:22:17.172: //39/DBD8E4E78012/SIP/Info/sipSPIProcessHoldTimerForCall: Media IP Addr 20.20.20.2, RTCP Type 3
*Jan 4 05:22:17.172: //39/DBD8E4E78012/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
CME_A_#
CME_A_#
CME_A_#
*Jan 4 05:22:57.592: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 20.20.20.2:59570
*Jan 4 05:22:57.596: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jan 4 05:22:57.596: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
BYE sip:6601@192.168.1.200:5060 SIP/2.0
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bKC6DD
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Fri, 01 Mar 2002 12:58:35 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1014987561
CSeq: 103 BYE
Reason: Q.850;cause=16
Content-Length: 0

*Jan 4 05:22:57.600: //39/DBD8E4E78012/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x8561974C
*Jan 4 05:22:57.600: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:57.600: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
*Jan 4 05:22:57.604: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 20.20.20.2,Port 59570, Transport 1, SentBy Port 5060
*Jan 4 05:22:57.604: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[39], src[2]
*Jan 4 05:22:57.604: //39/DBD8E4E78012/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer
*Jan 4 05:22:57.604: //39/DBD8E4E78012/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(16) for incoming call
*Jan 4 05:22:57.604: //39/DBD8E4E78012/SIP/State/sipSPIChangeState: 0x8561974C : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jan 4 05:22:57.612: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Jan 4 05:22:57.620: //39/DBD8E4E78012/SIP/Transport/sipSPISendByeResponse: Sending BYE Response to the transport layer
*Jan 4 05:22:57.620: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: msg=0x88748410, addr=20.20.20.2, port=59570, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x8106070C
*Jan 4 05:22:57.620: //39/DBD8E4E78012/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jan 4 05:22:57.620: //39/DBD8E4E78012/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jan 4 05:22:57.620: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x88748410, addr=20.20.20.2, port=5060, connId=0 for UDP
*Jan 4 05:22:57.620: //39/DBD8E4E78012/SIP/Info/sentByeResponse: Sent 200ok to the BYE, tearing down the call
*Jan 4 05:22:57.624: //39/DBD8E4E78012/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 39210 DiscTime:1296244 ConnTime 1292193
*Jan 4 05:22:57.624: //39/DBD8E4E78012/SIP/State/sipSPIChangeState: 0x8561974C : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Jan 4 05:22:57.628: //39/DBD8E4E78012/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x8561974C
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number : 7701
Called Number : 6601
Source IP Address (Sig ): 192.168.1.200
Destn SIP Req Addr:Port : 20.20.20.2:5060
Destn SIP Resp Addr:Port : 20.20.20.2:59570
Destination Name : 20.20.20.2

*Jan 4 05:22:57.628: //39/DBD8E4E78012/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : g711alaw
Negotiated Codec Bytes : 160
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 192.168.1.200
Source IP Port (Media): 17184
Destn IP Address (Media): 20.20.20.2
Destn IP Port (Media): 19012
Orig Destn IP Address:Port (Media): 0.0.0.0:0

*Jan 4 05:22:57.628: //39/DBD8E4E78012/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 16
Disconnect Cause (SIP) : 200

*Jan 4 05:22:57.628: //39/DBD8E4E78012/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 27
*Jan 4 05:22:57.636: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 20.20.20.2:5060;branch=z9hG4bKC6DD
From: "Goldie" <sip:7701@20.20.20.2>;tag=6C27D4-751
To: <sip:6601@192.168.1.200>;tag=C51530-236B
Date: Sun, 04 Jan 2015 05:22:57 GMT
Call-ID: E01FDCD9-2C4A11D6-8015CBD3-FD31EA58@65.65.65.200
Server: Cisco-SIPGateway/IOS-12.x
Timestamp: 1014987561
Content-Length: 0
CSeq: 103 BYE

CME_A_#
CME_A_#
CME_A_#
CME_A_#

So opening UDP port 5060 on a ACL allows the voice stream to go through on the FXS analog SIP RTP connection ?

And that is both ways?

Ways cool!!!

So any warbling or delay on the audio over the WAN? Just curious......

VoIP quality is fine, no issues that I can report. Now, my WAN is basically a LAB "wan" made of a couple routers. I'll play with different codecs once I have more time to compare as well. Yeah, so the 2600xm routers have the Voice modules and DSP with the FXS cards for the analog phones, from there it's VoIP on the other side of the router

My next plan of action is to extend this lab over the internet, by finding another person who is willing to configure a CME router and dial-peer. That way it will really be over internet WAN .

Let me know if you are interested to give it a shot.

So this is strictly FXS/FXO analog phone on CME where CME runs on the 2620xm & your using the single FA 0/0 as your WAN link out on the 2620xm? over SIP?

just curious again.... I remember you labbing SIP voip a while back

This lab scenario is just as shown in the diagram in the 2nd post . Basically it's analog phone on fxs port / voice module in 2600xm running cme connected to 1st 2621 running as edge to 1st 3640 running as "service provider" wan link to 2nd 3640 as another SP, connected to 2nd 2621 running as remote edge, and connected to another 2600xm/fxs/analog phone. I basically wanted to "simulate" two branch locations , each one behind it's own internet connection with NAT on each side...

SIP trunk I do have configured on one of the 2811, that was another lab exercise

Quick Links