[reSIProcate] Invite request to our special test number yields some interesting results... see logs below.
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@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
DEBUG | 1143008997 | SipPhone | RESIP |
/Volumes/TFKCrunch/Crunch/Development/newSipTestApp/resiprocate/SipStack.cxx:269
| SEND: SipReq: INVITE u415521@xxxxxxxxxxxxxx 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@xxxxxxxxxxxxxx
DEBUG | 1143008997 | SipPhone | RESIP:DNS | DnsResult.cxx:136 |
DnsResult::lookup sip:u415521@xxxxxxxxxxxxxx
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@xxxxxxxxxxxxxx:5060>;tag=15694b49
PEER=<sip:u415521@xxxxxxxxxxxxxx>: 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@xxxxxxxxxxxxxx SIP/2.0
To: <sip:u415521@xxxxxxxxxxxxxx>
From: "TestUser5"<sip:u354@xxxxxxxxxxxxxx:5060>;tag=15694b49
Via: SIP/2.0/UDP
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxx
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@xxxxxxxxxxxxxx>
From: "TestUser5"<sip:u354@xxxxxxxxxxxxxx:5060>;tag=15694b49
Via: SIP/2.0/UDP
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxx
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@xxxxxxxxxxxxxx>
From: "TestUser5"<sip:u354@xxxxxxxxxxxxxx:5060>;tag=15694b49
Via: SIP/2.0/UDP
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxx
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@xxxxxxxxxxxxxxxxxxxxxxxxxxxxx
in map:
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogUsageManager.cxx:1494
| [4612a0934c62acc5@xxxxxxxxxxxxxxxxxxxxxxxxxxxxx -> 0x698b890,
565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxxxxxxxxxxx -> 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@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
DEBUG | 1143009025 | SipPhone | RESIP:DUM | DialogSet.cxx:665 |
findDialog: 565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx in
[565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx -> 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@xxxxxxxxxxxxxx>
From: "TestUser5"<sip:u354@xxxxxxxxxxxxxx:5060>;tag=15694b49
Via: SIP/2.0/UDP
192.168.2.102:5060;branch=z9hG4bK-d87543-697341515c3ed23a-1--d87543-;rport
Call-ID: 565ce9035dbdbe62@xxxxxxxxxxxxxxxxxxxx
CSeq: 1 INVITE
Contact: <sip:213.167.79.25:5060;transport=udp>
Content-Length: 0
-------- end --------
John