[reSIProcate] Record-Route issues with Repro and Cisco

Sun May 8 23:51:21 CDT 2005

Repro Dev,

I know I should start simple but that never seems to happen.  I have
found an issue, at least in my setup, with the Record-Route path
specified when it is sent back to the originator because it doesn't
contain the port number.  I don't know if this is a Cisco-related issue
or Repro so I'm throwing it out here.

The setup:
Originator:  Cisco 7940, 172.31.1.154:5060
Proxy:       Gentoo Linux, aka Linux2, 172.31.1.31:12010   ** Note Port
Target:      Cisco 2651, 172.31.1.62:5060

Source Revision: SVN 4553

The originator and the target both register with Proxy:12010 and use
that as their proxy.

Debug logs for Repro and the 7940 below - they ARE NOT from the same
exact call but show the problem. Key lines are in bold.

Repro is receiving all requests on :12010 correctly throughout the
invite state. It is populating the Record-Route with <sip:linux2;lr> and
DNS resolves correctly on the Gentoo system and both devices.  I BELIEVE
this should be <sip:linux2:12010;lr>. If you look at the Via statements
they are correct with the port number.

The 7940 handles everything fine until it gets to the ACK and BYE - it
tries to use the Record-Route from the 183 response message and sends
the ACK to <sip:linux2:5060> but the proxy isn't listening on 5060 - it
expects 12010. Same issue if I hang up the 7940 - the BYE messages goes
to :5060.

I did have issues on the 2651 because name resolution was explicitly
disabled - this is the first time in almost a year of working with
Resiprocate that it has required me to use DNS and not just IP's.

There is also a "fishy" message because 172.31.1.31:5060 doesn't exist...

DEBUG | 20050508-221646.945 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:662 | Transmitting to [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] *via [ V4 172.31.1.31:5060* UDP
received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]

Of course, if I change the proxy to run on :5060 (or add another
transport for :5060 and :12010) everything is fine.

Thoughts?

Jay

*Debug output from Cisco 7940:*

sip_sm_cc_channel_send_buf_fcn: Sent SIP message: handle=<1>:
message=
<INVITE sip:2414 at 172.31.1.31;user=phone SIP/2.0
Via: SIP/2.0/UDP 172.31.1.154:5060
From: "User ID"
<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a002574b55b98-7fb5bd41
To: <sip:2414 at 172.31.1.31;user=phone>
Call-ID: 000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154
CSeq: 101 INVITE
User-Agent: CSCO/4
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 180
Content-Type: application/sdp
Content-Length: 247
Accept: application/sdp
Remote-Party-ID: "User ID"
<sip:1234567 at 172.31.1.154>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 26274 17257 IN IP4 172.31.1.154
s=SIP Call
c=IN IP4 172.31.1.154
t=0 0
m=audio 20416 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
>, length=<793>

----
SIPProcessUDPMessage: recv UDP message from <172.31.1.31>:<59950>:
<SIP/2.0 183 Session Progress
To: <sip:2414 at 172.31.1.31;user=phone>;tag=16D6DF18-1848
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a002574b55b98-7fb5bd41
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154
CSeq: 101 INVITE
*Record-Route: <sip:linux2;lr>*
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: UPDATE
Content-Disposition: session;handling=required
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 10:26:20 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 198

v=0
o=CiscoSystemsSIP-GW-UserAgent 5889 217 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 16692 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
>, length=767
sipSPICheckResponse: Response match:
callid=000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154, cseq=101,
cseq_method=INVITE
-----
SIPProcessUDPMessage: recv UDP message from <172.31.1.31>:<59950>:
<SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=16D6DF18-1848
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a002574b55b98-7fb5bd41
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154
CSeq: 101 INVITE
*Record-Route: <sip:linux2;lr>*
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 10:26:20 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 198

v=0
o=CiscoSystemsSIP-GW-UserAgent 5889 217 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 16692 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
>, length=796
sipSPICheckResponse: Response match:
callid=000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154, cseq=101,
cseq_method=INVITE
SIPSPIAddRouteHeaders: Adding route = <sip:2414 at 172.31.1.62:5060>
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE,
to_tag=<16D6DF18-1848>)

---
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to
server <172.31.1.31>:<5060>, handle = 8
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <172.31.1.31>:<5060>,
handle=<8>:
message=
*<ACK sip:linux2:5060;lr SIP/2.0*
Via: SIP/2.0/UDP 172.31.1.154:5060
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a002574b55b98-7fb5bd41
To: <sip:2414 at 172.31.1.31;user=phone>;tag=16D6DF18-1848
Call-ID: 000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154
CSeq: 101 ACK
User-Agent: CSCO/4
Route: <sip:2414 at 172.31.1.62:5060>
Content-Length: 0

>, length=<356>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel
handle = 8
SIPSPIAddRouteHeaders: Adding route = <sip:2414 at 172.31.1.62:5060>
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to
server <172.31.1.31>:<5060>, handle = 7
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <172.31.1.31>:<5060>,
handle=<7>:
message=
*<BYE sip:linux2:5060;lr SIP/2.0*
Via: SIP/2.0/UDP 172.31.1.154:5060
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a002574b55b98-7fb5bd41
To: <sip:2414 at 172.31.1.31;user=phone>;tag=16D6DF18-1848
Call-ID: 000a8a5c-be3a02e7-0b1e9afe-05555d0d at 172.31.1.154
CSeq: 102 BYE
User-Agent: CSCO/4
Content-Length: 0
Route: <sip:2414 at 172.31.1.62:5060>

>, length=<356>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel
handle = 7
sip_sm_cc_channel_send_buf_fcn: Sent SIP message: handle=<2>:

*Debug Output from Repro:*

DEBUG | 20050508-221646.860 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.154:50814
UDP *received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]*
connectionId=0 ]
DEBUG | 20050508-221646.861 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:56 | Checking if SipReq:  INVITE
2414 at 172.31.1.31 tid=a7715a8a286277faf86a38e7a1e56b4c cseq=INVITE
contact=1234567 at 172.31.1.154:5060 / 101 from(wire) is for me
DEBUG | 20050508-221646.861 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:61 | Checking rule...
DEBUG | 20050508-221646.861 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | MessageFilterRule.cxx:42 | Matching rule for INVITE
sip:2414 at 172.31.1.31;user=phone SIP/2.0
To: <sip:2414 at 172.31.1.31;user=phone>
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 180
Accept: application/sdp
Content-Type: application/sdp
User-Agent: CSCO/4
Content-Length: 246
Remote-Party-ID: "User ID"
<sip:1234567 at 172.31.1.154>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 5073 13678 IN IP4 172.31.1.154
s=SIP Call
c=IN IP4 172.31.1.154
t=0 0
m=audio 20414 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

DEBUG | 20050508-221646.862 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | MessageFilterRule.cxx:64 | Method is not in list. Rule
does not match.
DEBUG | 20050508-221646.862 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:68 | No matching rule found
DEBUG | 20050508-221646.862 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:56 | Checking if SipReq:  INVITE
2414 at 172.31.1.31 tid=a7715a8a286277faf86a38e7a1e56b4c cseq=INVITE
contact=1234567 at 172.31.1.154:5060 / 101 from(wire) is for me
DEBUG | 20050508-221646.863 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:61 | Checking rule...
DEBUG | 20050508-221646.863 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | MessageFilterRule.cxx:42 | Matching rule for INVITE
sip:2414 at 172.31.1.31;user=phone SIP/2.0
To: <sip:2414 at 172.31.1.31;user=phone>
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 180
Accept: application/sdp
Content-Type: application/sdp
User-Agent: CSCO/4
Content-Length: 246
Remote-Party-ID: "User ID"
<sip:1234567 at 172.31.1.154>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 5073 13678 IN IP4 172.31.1.154
s=SIP Call
c=IN IP4 172.31.1.154
t=0 0
m=audio 20414 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

DEBUG | 20050508-221646.864 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:64 | Match!
DEBUG | 20050508-221646.864 | linux2 | repro | RESIP | 10248 |
1087687600 | Helper.cxx:294 | Helper::makeResponse(SipReq:  INVITE
2414 at 172.31.1.31 tid=a7715a8a286277faf86a38e7a1e56b4c cseq=INVITE
contact=1234567 at 172.31.1.154:5060 / 101 from(wire) code=100 reason=
DEBUG | 20050508-221646.864 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TimerQueue.cxx:85 | Adding timer: Timer Trying
tid=a7715a8a286277faf86a38e7a1e56b4c ms=80
DEBUG | 20050508-221646.864 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0
INVITE sip:2414 at 172.31.1.31;user=phone SIP/2.0
To: <sip:2414 at 172.31.1.31;user=phone>
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 180
Accept: application/sdp
Content-Type: application/sdp
User-Agent: CSCO/4
Content-Length: 246
Remote-Party-ID: "User ID"
<sip:1234567 at 172.31.1.154>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 5073 13678 IN IP4 172.31.1.154
s=SIP Call
c=IN IP4 172.31.1.154
t=0 0
m=audio 20414 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

DEBUG | 20050508-221646.865 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got: INVITE sip:2414 at 172.31.1.31;user=phone
SIP/2.0
To: <sip:2414 at 172.31.1.31;user=phone>
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 180
Accept: application/sdp
Content-Type: application/sdp
User-Agent: CSCO/4
Content-Length: 246
Remote-Party-ID: "User ID"
<sip:1234567 at 172.31.1.154>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 5073 13678 IN IP4 172.31.1.154
s=SIP Call
c=IN IP4 172.31.1.154
t=0 0
m=audio 20414 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

INFO | 20050508-221646.866 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:128 | New RequestContext
tid=a7715a8a286277faf86a38e7a1e56b4c : SipReq:  INVITE 2414 at 172.31.1.31
tid=a7715a8a286277faf86a38e7a1e56b4c cseq=INVITE
contact=1234567 at 172.31.1.154:5060 / 101 from(wire)
INFO | 20050508-221646.866 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:132 | Inserting new RequestContext
tid=a7715a8a286277faf86a38e7a1e56b4c -> RequestContext:  identity=
candidates=[] count=1 final=0
DEBUG | 20050508-221646.867 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:134 | RequestContexts:
[a7715a8a286277faf86a38e7a1e56b4c -> 0x8389a48]
DEBUG | 20050508-221646.867 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:64 | RequestContext::process(Message)
RequestContext:  identity= candidates=[] count=1 final=0
DEBUG | 20050508-221646.867 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestProcessorChain.cxx:58 | Chain invoking monkey:
Monkey Chain!

DEBUG | 20050508-221646.867 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestProcessorChain.cxx:58 | Chain invoking monkey:
RouteProcessor monkey

DEBUG | 20050508-221646.867 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | monkeys/RouteProcessor.cxx:35 | Monkey handling request:
RouteProcessor monkey
; reqcontext = RequestContext:  identity= candidates=[] count=1 final=0
DEBUG | 20050508-221646.868 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestProcessorChain.cxx:58 | Chain invoking monkey:
AmIResponsible monkey

DEBUG | 20050508-221646.868 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | monkeys/AmIResponsible.cxx:28 | Monkey handling request:
AmIResponsible monkey
; reqcontext = RequestContext:  identity= candidates=[] count=1 final=0
DEBUG | 20050508-221646.868 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestProcessorChain.cxx:58 | Chain invoking monkey: Route
Monkey

DEBUG | 20050508-221646.868 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | monkeys/RouteMonkey.cxx:34 | Monkey handling request: Route
Monkey
; reqcontext = RequestContext:  identity= candidates=[] count=1 final=0
DEBUG | 20050508-221646.868 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestProcessorChain.cxx:58 | Chain invoking monkey:
LocationServer monkey

DEBUG | 20050508-221646.869 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | monkeys/LocationServer.cxx:21 | Monkey handling request:
LocationServer monkey
; reqcontext = RequestContext:  identity= candidates=[] count=1 final=0
INFO | 20050508-221646.869 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | monkeys/LocationServer.cxx:41 | LocationServer monkey
 adding target sip:2414 at 172.31.1.62:5060
INFO | 20050508-221646.869 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:158 | Adding candidate
<sip:2414 at 172.31.1.62:5060>
INFO | 20050508-221646.869 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | monkeys/LocationServer.cxx:57 | LocationServer monkey
 there are 1 candidates -> continue
INFO | 20050508-221646.869 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:108 | process candidates for
RequestContext:  identity= candidates=[<sip:2414 at 172.31.1.62:5060>]
count=1 final=0
INFO | 20050508-221646.870 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:53 | Considering
<sip:2414 at 172.31.1.62:5060>
INFO | 20050508-221646.870 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:65 | Added <sip:2414 at 172.31.1.62:5060>;q=0
INFO | 20050508-221646.870 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:151 | Creating new client transaction
48531449e6cfd553 -> sip:2414 at 172.31.1.62:5060
DEBUG | 20050508-221646.870 | linux2 | repro | RESIP | 10248 |
1096080304 | SipStack.cxx:269 | SEND: SipReq:  INVITE
2414 at 172.31.1.62:5060 tid=48531449e6cfd553 cseq=INVITE
contact=1234567 at 172.31.1.154:5060 / 101 from(wire)
INFO | 20050508-221646.871 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:215 | add client transaction tid=48531449e6cfd553
0x8389a48
DEBUG | 20050508-221646.891 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TimerQueue.cxx:85 | Adding timer: Timer B
tid=48531449e6cfd553 ms=32000
DEBUG | 20050508-221646.891 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:247 | Looking up dns entries for
sip:2414 at 172.31.1.62:5060
DEBUG | 20050508-221646.891 | linux2 | repro | RESIP:DNS | 10248 |
1087687600 | DnsResult.cxx:136 | DnsResult::lookup sip:2414 at 172.31.1.62:5060
DEBUG | 20050508-221646.891 | linux2 | repro | RESIP:DNS | 10248 |
1087687600 | DnsResult.cxx:255 | Numeric result so return immediately: [
V4 172.31.1.62:5060 UDP connectionId=0 ]
DEBUG | 20050508-221646.892 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TimerQueue.cxx:85 | Adding timer: Timer A
tid=48531449e6cfd553 ms=500
DEBUG | 20050508-221646.892 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:518 | Looked up source for
destination: [ V4 172.31.1.62:5060 UDP connectionId=0 ] -> [ V4
172.31.1.31:0 UDP connectionId=0 ] sent-by= sent-port=0
DEBUG | 20050508-221646.892 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:744 | findTransport([ V4
172.31.1.31:0 UDP connectionId=0 ])
DEBUG | 20050508-221646.892 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:786 | findTransport (any port, any
interface) => Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
DEBUG | 20050508-221646.893 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:662 | Transmitting to [ V4
172.31.1.62:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] via [ V4 172.31.1.31:0 UDP
connectionId=0 ]

INVITE sip:2414 at 172.31.1.62:5060 SIP/2.0
To: <sip:2414 at 172.31.1.31;user=phone>
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
*Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport*
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE  
*Record-Route: <sip:linux2;lr>*
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 180
Max-Forwards: 20
Accept: application/sdp
Content-Type: application/sdp
User-Agent: CSCO/4
Content-Length: 246
Remote-Party-ID: "User ID"
<sip:1234567 at 172.31.1.154>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 5073 13678 IN IP4 172.31.1.154
s=SIP Call
c=IN IP4 172.31.1.154
t=0 0
m=audio 20414 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

DEBUG | 20050508-221646.894 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:160 | Adding message to tx buffer to: [ V4
172.31.1.62:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ]
DEBUG | 20050508-221646.924 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.62:5060
UDP received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]
DEBUG | 20050508-221646.924 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0

SIP/2.0 100 Trying
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 0

DEBUG | 20050508-221646.925 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got:

SIP/2.0 100 Trying
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 0

INFO | 20050508-221646.925 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:140 | Looking up RequestContext tid=48531449e6cfd553
DEBUG | 20050508-221646.925 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:64 | RequestContext::process(Message)
RequestContext:  identity= candidates=[] count=2 final=0
INFO | 20050508-221646.926 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:174 | processResponse:

SIP/2.0 100 Trying
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 0

**** Why didn't the 100 Trying get forwarded?*

INFO | 20050508-221646.926 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:208 | Search for 48531449e6cfd553 in
[48531449e6cfd553 -> Branch: sip:2414 at 172.31.1.62:5060  status=0]
INFO | 20050508-221646.927 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:108 | process candidates for
RequestContext:  identity= candidates=[] count=2 final=0

DEBUG | 20050508-221646.936 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.62:5060
UDP received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]
DEBUG | 20050508-221646.936 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0

SIP/2.0 183 Session Progress
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: UPDATE
Content-Disposition: session;handling=required
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221646.937 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got:

SIP/2.0 183 Session Progress
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: UPDATE
Content-Disposition: session;handling=required
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

INFO | 20050508-221646.938 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:140 | Looking up RequestContext tid=48531449e6cfd553
DEBUG | 20050508-221646.938 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:64 | RequestContext::process(Message)
RequestContext:  identity= candidates=[] count=2 final=0
INFO | 20050508-221646.938 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:174 | processResponse:

SIP/2.0 183 Session Progress
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: UPDATE
Content-Disposition: session;handling=required
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221646.939 | linux2 | repro | RESIP | 10248 |
1096080304 | SipStack.cxx:269 | SEND: SipResp: 183
tid=a7715a8a286277faf86a38e7a1e56b4c cseq=INVITE
contact=2414 at 172.31.1.62:5060 / 101 from(wire)
INFO | 20050508-221646.940 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:208 | Search for 48531449e6cfd553 in
[48531449e6cfd553 -> Branch: sip:2414 at 172.31.1.62:5060  status=1]
DEBUG | 20050508-221646.945 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:518 | Looked up source for
destination: [ V4 172.31.1.154:5060 UDP received on: Transport: [ V4
0.0.0.0:12010 UDP connectionId=0 ] connectionId=0 ] -> [ V4
172.31.1.31:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] sent-by=172.31.1.154 sent-port=5060
DEBUG | 20050508-221646.945 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:662 | Transmitting to [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] *via [ V4 172.31.1.31:5060* UDP
received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]

SIP/2.0 183 Session Progress
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: UPDATE
Content-Disposition: session;handling=required
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221646.946 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:160 | Adding message to tx buffer to: [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ]
DEBUG | 20050508-221650.524 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.62:5060
UDP received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]
DEBUG | 20050508-221650.524 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0
SIP/2.0

200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221650.525 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=1
ClientTransactionTerminated 48531449e6cfd553
DEBUG | 20050508-221650.526 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TimerQueue.cxx:85 | Adding timer: Timer StaleClient
tid=48531449e6cfd553 ms=32000
DEBUG | 20050508-221650.526 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got:

SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

INFO | 20050508-221650.527 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:140 | Looking up RequestContext tid=48531449e6cfd553
DEBUG | 20050508-221650.527 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:64 | RequestContext::process(Message)
RequestContext:  identity= candidates=[] count=2 final=1
INFO | 20050508-221650.527 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:174 | processResponse:

SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

INFO | 20050508-221650.528 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:376 | Terminating client transaction:
48531449e6cfd553 all = 1
INFO | 20050508-221650.528 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:377 | client transactions:
[48531449e6cfd553 -> Branch: sip:2414 at 172.31.1.62:5060  status=3]
INFO | 20050508-221650.529 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | ResponseContext.cxx:348 | Cancel all proceeding client
transactions: 1
DEBUG | 20050508-221650.529 | linux2 | repro | RESIP | 10248 |
1096080304 | SipStack.cxx:269 | SEND: SipResp: 200
tid=a7715a8a286277faf86a38e7a1e56b4c cseq=INVITE
contact=2414 at 172.31.1.62:5060 / 101 from(wire)
DEBUG | 20050508-221650.529 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got: ClientTransactionTerminated
48531449e6cfd553
INFO | 20050508-221650.529 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:49 |
RequestContext::process(TransactionTerminated) 48531449e6cfd553 :
RequestContext:  identity= candidates=[] count=2 final=1
DEBUG | 20050508-221650.551 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:518 | Looked up source for
destination: [ V4 172.31.1.154:5060 UDP received on: Transport: [ V4
0.0.0.0:12010 UDP connectionId=0 ] connectionId=0 ] -> [ V4
172.31.1.31:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] sent-by=172.31.1.154 sent-port=5060
DEBUG | 20050508-221650.551 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:662 | Transmitting to [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] via [ *V4 172.31.1.31:5060* UDP
received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]

SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221650.552 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:160 | Adding message to tx buffer to: [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ]
DEBUG | 20050508-221650.552 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0
ServerTransactionTerminated a7715a8a286277faf86a38e7a1e56b4c
DEBUG | 20050508-221650.553 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TimerQueue.cxx:85 | Adding timer: Timer StaleServer
tid=a7715a8a286277faf86a38e7a1e56b4c ms=32000
DEBUG | 20050508-221650.553 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got: ServerTransactionTerminated
a7715a8a286277faf86a38e7a1e56b4c
INFO | 20050508-221650.553 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | RequestContext.cxx:49 |
RequestContext::process(TransactionTerminated)
a7715a8a286277faf86a38e7a1e56b4c : RequestContext:  identity=
candidates=[] count=1 final=1
DEBUG | 20050508-221651.026 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.62:5060
UDP received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]
DEBUG | 20050508-221651.026 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0

SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221651.027 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got: SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

INFO | 20050508-221651.028 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:140 | Looking up RequestContext tid=48531449e6cfd553
INFO | 20050508-221651.028 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:150 | Unmatched response (stray?) :
SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221652.027 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.62:5060
UDP received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]
DEBUG | 20050508-221652.028 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU: Proxy size=0
SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221652.029 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:68 | Got: SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

INFO | 20050508-221652.030 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:140 | Looking up RequestContext tid=48531449e6cfd553
INFO | 20050508-221652.030 | linux2 | repro | REPRO:APP | 10248 |
1096080304 | Proxy.cxx:150 | Unmatched response (stray?) :
SIP/2.0 200 OK
To: <sip:2414 at 172.31.1.31;user=phone>;tag=169926A5-1C79
From: "User
ID"<sip:1234567 at 172.31.1.31>;tag=000a8a5cbe3a0024265e70cc-50e77551
Via: SIP/2.0/UDP
172.31.1.31:12010;branch=z9hG4bK-d87543-48531449e6cfd553-1--d87543-;rport
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025c-33da6934-0117c7ad at 172.31.1.154
CSeq: 101 INVITE
Record-Route: <sip:linux2;lr>
Contact: <sip:2414 at 172.31.1.62:5060>
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER,
SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
Content-Type: application/sdp
Date: Tue, 05 Mar 2002 09:18:55 gmt
Server: Cisco-SIPGateway/IOS-12.x
Allow-Events: telephone-event
Content-Length: 199

v=0
o=CiscoSystemsSIP-GW-UserAgent 1564 5021 IN IP4 172.31.1.62
s=SIP Call
c=IN IP4 172.31.1.62
t=0 0
m=audio 18534 RTP/AVP 18
c=IN IP4 172.31.1.62
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

DEBUG | 20050508-221653.320 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:209 | incoming from: [ V4 172.31.1.154:50814
UDP received on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ]
connectionId=0 ]
DEBUG | 20050508-221653.320 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:56 | Checking if SipReq:  REGISTER
172.31.1.31 tid=ff37b1b7af8915c878d19b9093d5b3f2 cseq=REGISTER
contact=1234567 at 172.31.1.154:5060 / 101 from(wire) is for me
DEBUG | 20050508-221653.320 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:61 | Checking rule...
DEBUG | 20050508-221653.320 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | MessageFilterRule.cxx:42 | Matching rule for REGISTER
sip:172.31.1.31 SIP/2.0
To: <sip:1234567 at 172.31.1.31>
From: <sip:1234567 at 172.31.1.31>
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154
CSeq: 101 REGISTER
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 120
User-Agent: CSCO/4
Content-Length: 0

DEBUG | 20050508-221653.321 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionUser.cxx:64 | Match!
DEBUG | 20050508-221653.321 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TransactionState.cxx:1535 | Send to TU: TU:
DialogUsageManager size=0 REGISTER sip:172.31.1.31 SIP/2.0
To: <sip:1234567 at 172.31.1.31>
From: <sip:1234567 at 172.31.1.31>
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154
CSeq: 101 REGISTER
Contact: <sip:1234567 at 172.31.1.154:5060>
Expires: 120
User-Agent: CSCO/4
Content-Length: 0

INFO | 20050508-221653.322 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:828 | Got: SipReq:  REGISTER
172.31.1.31 tid=ff37b1b7af8915c878d19b9093d5b3f2 cseq=REGISTER
contact=1234567 at 172.31.1.154:5060 / 101 from(wire)
DEBUG | 20050508-221653.322 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1214 |
DialogUsageManager::processRequest: SipReq:  REGISTER 172.31.1.31
tid=ff37b1b7af8915c878d19b9093d5b3f2 cseq=REGISTER
contact=1234567 at 172.31.1.154:5060 / 101 from(wire)
DEBUG | 20050508-221653.322 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSetId.cxx:31 | ********** Generated Local Tag ***********
DEBUG | 20050508-221653.322 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1495 | Looking for dialogSet:
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-7362167e in map:
DEBUG | 20050508-221653.322 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1496 | []
DEBUG | 20050508-221653.323 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSetId.cxx:31 | ********** Generated Local Tag ***********
DEBUG | 20050508-221653.323 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSetId.cxx:31 | ********** Generated Local Tag ***********
DEBUG | 20050508-221653.323 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSet.cxx:86 |  ************* Created DialogSet(UAS) 
-- 000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f*************
DEBUG | 20050508-221653.323 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1344 | *********** Calling
AppDialogSetFactory *************
DEBUG | 20050508-221653.323 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1350 | ************* Adding
DialogSet ***************
DEBUG | 20050508-221653.323 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1351 | Before: []
DEBUG | 20050508-221653.324 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1353 | After:
Req[000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f -> 0x83983c8]
DEBUG | 20050508-221653.324 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSetId.cxx:31 | ********** Generated Local Tag ***********
DEBUG | 20050508-221653.324 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogId.cxx:50 | DialogId::DialogId:
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-8aabdc7f-
DEBUG | 20050508-221653.324 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSet.cxx:669 | findDialog:
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-8aabdc7f- in []
DEBUG | 20050508-221653.324 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | ServerRegistration.cxx:97 | got a registration
DEBUG | 20050508-221653.325 | linux2 | repro | REPRO:APP | 10248 |
1112865712 | Registrar.cxx:27 | Registrar::onRefresh SipReq:  REGISTER
172.31.1.31 tid=ff37b1b7af8915c878d19b9093d5b3f2 cseq=REGISTER
contact=1234567 at 172.31.1.154:5060 / 101 from(wire)
DEBUG | 20050508-221653.325 | linux2 | repro | RESIP | 10248 |
1112865712 | Helper.cxx:294 | Helper::makeResponse(SipReq:  REGISTER
172.31.1.31 tid=ff37b1b7af8915c878d19b9093d5b3f2 cseq=REGISTER
contact=1234567 at 172.31.1.154:5060 / 101 from(wire) code=200 reason=
INFO | 20050508-221653.325 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | ServerRegistration.cxx:39 | accepted a registration
sip:1234567 at 172.31.1.31
DEBUG | 20050508-221653.325 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1495 | Looking for dialogSet:
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-6894c327 in map:
DEBUG | 20050508-221653.326 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1496 |
[000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f -> 0x83983c8]
DEBUG | 20050508-221653.326 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:605 | SEND: SIP/2.0 200 OK
To: <sip:1234567 at 172.31.1.31>;tag=6894c327
From: <sip:1234567 at 172.31.1.31>
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154
CSeq: 101 REGISTER
Contact: <sip:1234567 at 172.31.1.154:5060>;expires=120
Content-Length: 0

DEBUG | 20050508-221653.326 | linux2 | repro | RESIP | 10248 |
1112865712 | SipStack.cxx:269 | SEND: SipResp: 200
tid=ff37b1b7af8915c878d19b9093d5b3f2 cseq=REGISTER
contact=1234567 at 172.31.1.154:5060 / 101 from(tu)
INFO | 20050508-221653.327 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:828 | Got: DestroyDialogSet
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f
DEBUG | 20050508-221653.327 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:928 | Destroying
usageDestroyDialogSet
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f
DEBUG | 20050508-221653.327 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogSet.cxx:124 |  ********** DialogSet::~DialogSet:
000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f*************
DEBUG | 20050508-221653.327 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1526 | ************* Removing
DialogSet ***************
DEBUG | 20050508-221653.328 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1527 | Before:
[000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154-88f7476f -> 0x83983c8]
DEBUG | 20050508-221653.328 | linux2 | repro | RESIP:DUM | 10248 |
1112865712 | DialogUsageManager.cxx:1529 | After: []
DEBUG | 20050508-221653.346 | linux2 | repro | RESIP:TRANSACTION | 10248
| 1087687600 | TimerQueue.cxx:85 | Adding timer: Timer J
tid=ff37b1b7af8915c878d19b9093d5b3f2 ms=32000
DEBUG | 20050508-221653.346 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:518 | Looked up source for
destination: [ V4 172.31.1.154:5060 UDP received on: Transport: [ V4
0.0.0.0:12010 UDP connectionId=0 ] connectionId=0 ] -> [ V4
172.31.1.31:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] sent-by=172.31.1.154 sent-port=5060
DEBUG | 20050508-221653.347 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | TransportSelector.cxx:662 | Transmitting to [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ] via [ V4 172.31.1.31:5060 UDP received
on: Transport: [ V4 0.0.0.0:12010 UDP connectionId=0 ] connectionId=0
]SIP/2.0 200 OK
To: <sip:1234567 at 172.31.1.31>;tag=6894c327
From: <sip:1234567 at 172.31.1.31>
Via: SIP/2.0/UDP 172.31.1.154:5060
Call-ID: 000a8a5c-be3a025d-32e63273-60ece6a8 at 172.31.1.154
CSeq: 101 REGISTER
Contact: <sip:1234567 at 172.31.1.154:5060>;expires=120
Content-Length: 0

DEBUG | 20050508-221653.348 | linux2 | repro | RESIP:TRANSPORT | 10248 |
1087687600 | Transport.cxx:160 | Adding message to tx buffer to: [ V4
172.31.1.154:5060 UDP received on: Transport: [ V4 0.0.0.0:12010 UDP
connectionId=0 ] connectionId=0 ]

** END **

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://list.resiprocate.org/pipermail/resiprocate-devel/attachments/20050508/29b542b2/attachment.htm>