[reSIProcate] Invite request to our special test number yields some interesting results... see logs below.

Wed Mar 22 01:10:27 CST 2006

Hi,

I included some excerps of the logs I'm getting and have questions about 
them.  I'm getting
these interesting results when I call a special call test number.  This 
test number just
answers the phone,  sends me a voice recording,  lets me record 
something and plays it
back to me,  but resip is not acknowledging the answer signal from the 
remote client when
I initially call.

DEBUG | 1143008997 | SipPhone | RESIP:DUM | 
/Volumes/TFKCrunch/Crunch/Development/newSipTestApp/resiprocate/dum/DialogId.cxx:50 
| DialogId::DialogId: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..-15694b49-
DEBUG | 1143008997 | SipPhone | RESIP | 
/Volumes/TFKCrunch/Crunch/Development/newSipTestApp/resiprocate/SipStack.cxx:269 
| SEND: SipReq:  INVITE u415521 at whitephone.com tid=697341515c3ed23a 
cseq=INVITE contact=u354 / 1 from(tu)
DEBUG | 1143008997 | SipPhone | RESIP:TRANSACTION | TimerQueue.cxx:85 | 
Adding timer: Timer B tid=697341515c3ed23a ms=32000
DEBUG | 1143008997 | SipPhone | RESIP:TRANSPORT | 
TransportSelector.cxx:243 | Looking up dns entries for 
sip:u415521 at whitephone.com
DEBUG | 1143008997 | SipPhone | RESIP:DNS | DnsResult.cxx:136 | 
DnsResult::lookup sip:u415521 at whitephone.com
DEBUG | 1143008997 | SipPhone | RESIP:DNS | DnsResult.cxx:337 | Doing 
NAPTR lookup: whitephone.com
DEBUG | 1143009002 | SipPhone | RESIP:DNS | DnsResult.cxx:351 | Doing 
SRV lookup: _sip._udp.whitephone.com
DEBUG | 1143009007 | SipPhone | RESIP:DNS | DnsResult.cxx:330 | Doing 
Host (A) lookup: on-instant.com

Why is it doing all these DNS lookups. Is there a setting that can 
minimize this?

We have a special test number we can call that goes to a recording which 
we use to test things.
When we call this "Call test" number,  I get the following log outputs, 
and I confirmed the
server is sending the 200 OK after the invite, but resip is not sensing 
it.   Below you will
see the logs I'm getting.  Can someone tell me what's going on?  As you 
see,  it gets the
100 trying,  180 ringing - see below,  then it gets the 100 trying 
again,  before going to
the 180 ringing,  until eventually,  I get the 408 stale timeout.  Is 
this because I didn't
give it enough time to get the 200 OK?   If this is the case,  how would 
I extend the wait
time before the timeout.

See below for logs of what I'm getting.

UAC(INVITE): myDialog: created.
Dialog.cxx:289 | Dialog::dispatch: SipResp: 180 tid=697341515c3ed23a 
cseq=INVITE contact=213.167.79.25:5060 / 1 from(wire)
DEBUG | 1143009014 | SipPhone | RESIP:DUM | Dialog.cxx:526 | 
Dialog::dispatch  --  Created new client invite sessionSipResp: 180 
tid=697341515c3ed23a cseq=INVITE contact=213.167.79.25:5060 / 1 from(wire)
DEBUG | 1143009014 | SipPhone | RESIP:DUM | InviteSession.cxx:45 | ^^^ 
InviteSession::InviteSession 0x70ab600
INFO | 1143009014 | SipPhone | RESIP:DUM | InviteSession.cxx:1438 | 
Transition UAC_Start -> UAC_Early
: ClientInviteSession-onNewSession - SipResp: 180 tid=697341515c3ed23a 
cseq=INVITE contact=213.167.79.25:5060 / 1 from(wire)
INFO | 1143009014 | SipPhone | RESIP:DUM | ClientInviteSession.cxx:286 | 
UAC_Early: startStaleCallTimer
DEBUG | 1143009014 | SipPhone | RESIP:TRANSACTION | TimerQueue.cxx:105 | 
Adding application timer: DumTimeout::StaleCall INVITE: 5 UAC_Early 
ADDR="TestUser5"<sip:u354 at whitephone.com:5060>;tag=15694b49 
PEER=<sip:u415521 at whitephone.com>: duration=180 seq=2
: InviteSession-onProvisional - SipResp: 180 tid=697341515c3ed23a 
cseq=INVITE contact=213.167.79.25:5060 / 1 from(wire)
INFO | 1143009024 | SipPhone | RESIP:TRANSACTION | TuSelector.cxx:69 | 
Stats message
WARNING | 1143009024 | SipPhone | RESIP:STATS | 
StatisticsMessage.cxx:152 | RESIP:TRANSACTION
TU summary: 0 TRANSPORT 0 TRANSACTION 0 CLIENTTX 1 SERVERTX 0 TIMERS 1
Transaction summary: reqi 0 reqo 3 rspi 7 rspo 0
Details: INVi 0/S0/F0 INVo 1/S1/F0 ACKi 0 ACKo 0 BYEi 0/S0/F0 BYEo 
0/S0/F0 CANi 0/S0/F0 CANo 0/S0/F0 MSGi 0/S0/F0 MSGo 0/S0/F0 OPTi 0/S0/F0 
OPTo 0/S0/F0 REGi 0/S0/F0 REGo 2/S1/F1 PUBi 0/S0/F0 PUBo 0/S0/F0 SUBi 
0/S0/F0 SUBo 0/S0/F0 NOTi 0/S0/F0 NOTo 0/S0/F0
Retransmissions: INVx 0 BYEx 0 CANx 0 MSGx 0 OPTx 0 REGx 0 finx 0 nonx 0 
PUBx 0 SUBx 0 NOTx 0
DEBUG | 1143009025 | SipPhone | RESIP:TRANSPORT | Transport.cxx:209 | 
incoming from: [ V4 213.167.79.25:5060 UDP received on: Transport: [ V4 
0.0.0.0:5060 UDP connectionId=0 ] connectionId=0 ]
DEBUG | 1143009025 | SipPhone | RESIP:TRANSACTION | TimerQueue.cxx:85 | 
Adding timer: Timer D tid=697341515c3ed23a ms=32000
DEBUG | 1143009025 | SipPhone | RESIP:TRANSPORT | 
TransportSelector.cxx:658 | Transmitting to [ V4 213.167.79.25:5060 UDP 
received on: Transport: [ V4 0.0.0.0:5060 UDP connectionId=0 ] 
connectionId=0 ] via [ V4 192.168.2.102:5060 UDP connectionId=0 ]ACK 
sip:u415521 at whitephone.com SIP/2.0
To: <sip:u415521 at whitephone.com>
From: "TestUser5"<sip:u354 at whitephone.com:5060>;tag=15694b49
Via: SIP/2.0/UDP 
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..
CSeq: 1 ACK
Content-Length: 0

DEBUG | 1143009025 | SipPhone | RESIP:TRANSPORT | Transport.cxx:160 | 
Adding message to tx buffer to: [ V4 213.167.79.25:5060 UDP received on: 
Transport: [ V4 0.0.0.0:5060 UDP connectionId=0 ] connectionId=0 ]
DEBUG | 1143009025 | SipPhone | RESIP:TRANSACTION | 
TransactionState.cxx:1535 | Send to TU: TU: DialogUsageManager size=0 
SIP/2.0 408 Request Timeout 
R004152990215832601451776M000A213.167.79.20P10332
To: <sip:u415521 at whitephone.com>
From: "TestUser5"<sip:u354 at whitephone.com:5060>;tag=15694b49
Via: SIP/2.0/UDP 
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..
CSeq: 1 INVITE
Contact: <sip:213.167.79.25:5060;transport=udp>
Content-Length: 0

INFO | 1143009025 | SipPhone | RESIP:DUM | DialogUsageManager.cxx:830 | 
Got: SipResp: 408 tid=697341515c3ed23a cseq=INVITE 
contact=213.167.79.25:5060 / 1 from(wire)
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogUsageManager.cxx:1380 
| DialogUsageManager::processResponse: SIP/2.0 408 Request Timeout 
R004152990215832601451776M000A213.167.79.20P10332
To: <sip:u415521 at whitephone.com>
From: "TestUser5"<sip:u354 at whitephone.com:5060>;tag=15694b49
Via: SIP/2.0/UDP 
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..
CSeq: 1 INVITE
Contact: <sip:213.167.79.25:5060;transport=udp>
Content-Length: 0

DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogUsageManager.cxx:1493 
| Looking for dialogSet: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..-15694b49 
in map:
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogUsageManager.cxx:1494 
| [4612a0934c62acc5 at dGZrZWRpdC5sb2NhbA..-3bfb676b -> 0x698b890, 
565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..-15694b49 -> 0x69d6830]
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogUsageManager.cxx:1395 
| DialogUsageManager::processResponse: SipResp: 408 tid=697341515c3ed23a 
cseq=INVITE contact=213.167.79.25:5060 / 1 from(wire)
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogId.cxx:50 | 
DialogId::DialogId: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..-15694b49-
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogSet.cxx:665 | 
findDialog: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..-15694b49- in 
[565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..-15694b49- -> 0x70aac00]
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogSet.cxx:361 | Found 
matching dialog mClientSubscriptions(0), mServerSubscriptions(0) for
SIP/2.0 408 Request Timeout 
R004152990215832601451776M000A213.167.79.20P10332
To: <sip:u415521 at whitephone.com>
From: "TestUser5"<sip:u354 at whitephone.com:5060>;tag=15694b49
Via: SIP/2.0/UDP 
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62 at dGZrZWRpdC5sb2NhbA..
CSeq: 1 INVITE
Contact: <sip:213.167.79.25:5060;transport=udp>
Content-Length: 0

-------- end --------

John