[reSIProcate] Performance of a P2P-over-SIP program using resiprocate
victor morales
victor.morales at tkk.fi
Mon May 14 16:06:15 CDT 2007
Hi!
Sorry for the delay...
I compiled the stack with the uncommented line you gave me.
Here is the log that I got and I only show the summary of the
retransmission as a sequence.
I can see the retransmission in the log now.
I cannot see the ACK getting to the stack or any error or clue as to
why the retransmission is happening.
Could my code be causing this somehow?
Thank you.
Victor M.
==================================
Here is the summary from Wireshark
==================================
No. Time Source Destination Protocol Info
65 9.193841 192.168.61.132 192.168.61.130
SIP/XML Request: INVITE sip:spzero at 192.168.61.130:12005
89 10.073606 192.168.61.130 192.168.61.132
SIP/XML Status: 606 Not Acceptable
90 10.073795 192.168.61.132 192.168.61.130 SIP
Request: ACK sip:spzero at 192.168.61.130:12005
120 11.064069 192.168.61.130 192.168.61.132
SIP/XML Status: 606 Not Acceptable
==========================================
And here is the debug level log from resip
==========================================
DEBUG | 20070514-223643.844 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | Transport.cxx:287 | incoming from: [ V4
192.168.61.132:5060 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ]
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TransactionUser.cxx:66 | Checking if SipReq: INVITE
spzero at 192.168.61.130:12005 tid=-7258-26-0 cseq=INVITE
contact=candid at 192.168.61.132:5060 / 26 from(wire) is for me
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TransactionUser.cxx:71 | Checking rule...
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | MessageFilterRule.cxx:42 | Matching rule for:
INVITE sip:spzero at 192.168.61.130:12005 SIP/2.0
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
Max-Forwards: 70
Contact: <sip:candid at 192.168.61.132:5060>
To: spzero <sip:spzero at 192.168.61.130:12005>
From: candid <sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Allow: INVITE, ACK, MESSAGE
Content-Type: text/xml
Content-Length: 180
<?xml version="1.0" encoding="ISO-8859-1" ?>
<request>
<name>Trac</name>
<extended type="size">0</extended>
<extended type="date">01.01.1900-01.01.2100</extended>
</request>
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TransactionUser.cxx:74 | Match!
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP | 5165 | 3079915904
| Helper.cxx:372 | Helper::makeResponse(SipReq: INVITE
spzero at 192.168.61.130:12005 tid=-7258-26-0 cseq=INVITE
contact=candid at 192.168.61.132:5060 / 26 from(wire) code=100 reason=
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:85 | Adding timer: Timer Trying
tid=-7258-26-0 ms=80
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TransactionState.cxx:1852 | Send to TU: TU:
DialogUsageManager size=0
INVITE sip:spzero at 192.168.61.130:12005 SIP/2.0
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
Max-Forwards: 70
Contact: <sip:candid at 192.168.61.132:5060>
To: spzero <sip:spzero at 192.168.61.130:12005>
From: candid <sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Allow: INVITE, ACK, MESSAGE
Content-Type: text/xml
Content-Length: 180
<?xml version="1.0" encoding="ISO-8859-1" ?>
<request>
<name>Trac</name>
<extended type="size">0</extended>
<extended type="date">01.01.1900-01.01.2100</extended>
</request>
INFO | 20070514-223643.845 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogUsageManager.cxx:1227 | Got: SipReq: INVITE
spzero at 192.168.61.130:12005 tid=-7258-26-0 cseq=INVITE
contact=candid at 192.168.61.132:5060 / 26 from(wire)
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogUsageManager.cxx:1494 |
DialogUsageManager::processRequest: SipReq: INVITE
spzero at 192.168.61.130:12005 tid=-7258-26-0 cseq=INVITE
contact=candid at 192.168.61.132:5060 / 26 from(wire)
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSetId.cxx:31 | ********** Generated Local Tag
***********
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSetId.cxx:31 | ********** Generated Local Tag
***********
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSetId.cxx:31 | ********** Generated Local Tag
***********
DEBUG | 20070514-223643.845 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSet.cxx:84 | ************* Created DialogSet(UAS)
-- 26-7258 at 192.168.61.132-ec956632*************
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSetId.cxx:31 | ********** Generated Local Tag
***********
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogId.cxx:50 | DialogId::DialogId:
26-7258 at 192.168.61.132-48d72e4d-26
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSet.cxx:736 | mState == 3 Creating a new Dialog
from msg:
INVITE sip:spzero at 192.168.61.130:12005 SIP/2.0
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
Max-Forwards: 70
Contact: <sip:candid at 192.168.61.132:5060>
To: "spzero"<sip:spzero at 192.168.61.130:12005>
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Allow: INVITE, ACK, MESSAGE
Content-Type: text/xml
Content-Length: 180
<?xml version="1.0" encoding="ISO-8859-1" ?>
<request>
<name>Trac</name>
<extended type="size">0</extended>
<extended type="date">01.01.1900-01.01.2100</extended>
</request>
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:87 | UAS dialog ID creation, DS:
26-7258 at 192.168.61.132-ec956632
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogId.cxx:63 | DialogId::DialogId:
26-7258 at 192.168.61.132-ec956632-26
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:129 | ************** Created Dialog as UAS
**************
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:130 | mRemoteNameAddr:
"candid"<sip:candid at 192.168.61.132:5060>;tag=26
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:131 | mLocalNameAddr:
"spzero"<sip:spzero at 192.168.61.130:12005>;tag=ec956632
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:132 | mLocalContact:
<sip:spzero at 192.168.61.130:12005>
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:133 | mRemoteTarget:
<sip:candid at 192.168.61.132:5060>
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:227 | Dialog::Dialog
26-7258 at 192.168.61.132-ec956632-26
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSet.cxx:774 | ### Calling CreateAppDialog ###:
INVITE sip:spzero at 192.168.61.130:12005 SIP/2.0
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
Max-Forwards: 70
Contact: <sip:candid at 192.168.61.132:5060>
To: "spzero"<sip:spzero at 192.168.61.130:12005>
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Allow: INVITE, ACK, MESSAGE
Content-Type: text/xml
Content-Length: 180
<?xml version="1.0" encoding="ISO-8859-1" ?>
<request>
<name>Trac</name>
<extended type="size">0</extended>
<extended type="date">01.01.1900-01.01.2100</extended>
</request>
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:313 | Dialog::dispatch: SipReq: INVITE
spzero at 192.168.61.130:12005 tid=-7258-26-0 cseq=INVITE
contact=candid at 192.168.61.132:5060 / 26 from(wire)
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:345 | Dialog::dispatch -- Created new server
invite sessionSipReq: INVITE spzero at 192.168.61.130:12005
tid=-7258-26-0 cseq=INVITE contact=candid at 192.168.61.132:5060 / 26
from(wire)
DEBUG | 20070514-223643.847 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | InviteSession.cxx:73 | ^^^ InviteSession::InviteSession
0x8398c70
DEBUG | 20070514-223643.848 | kenobi | nsp | RESIP | 5165 | 3079915904
| SipMessage.cxx:963 | SipMessage::getContents: text/xml
INFO | 20070514-223643.848 | kenobi | nsp | RESIP | 5165 | 3079915904
| SipMessage.cxx:972 | SipMessage::getContents: got content type
(text/xml) that is not known, returning as opaque
application/octet-stream
INFO | 20070514-223643.848 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | InviteSession.cxx:2067 | Transition UAS_Start ->
UAS_NoOffer
INFO | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | ServerInviteSession.cxx:384 | UAS_NoOffer: reject(606)
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP | 5165 | 3079915904
| Helper.cxx:372 | Helper::makeResponse(SipReq: INVITE
spzero at 192.168.61.130:12005 tid=-7258-26-0 cseq=INVITE
contact=candid at 192.168.61.132:5060 / 26 from(wire) code=606 reason=
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:982 | Dialog::makeResponse:
SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=ec956632
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Content-Length: 0
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogUsageManager.cxx:800 | SEND:
SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=ec956632
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Content-Type: text/xml
Content-Length: 50
<?xml version="1.0" ?><reply status="Not found" />
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP | 5165 | 3079915904
| SipStack.cxx:290 | SEND: SipResp: 606 tid=-7258-26-0 cseq=INVITE /
26 from(tu)
INFO | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | InviteSession.cxx:2067 | Transition UAS_NoOffer ->
InviteSession::Terminated
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | InviteSession.cxx:79 | ^^^ InviteSession::~InviteSession
0x8398c70
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | Dialog.cxx:232 | Dialog::~Dialog()
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogUsageManager.cxx:1986 | Got merged request removal
request
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:105 | Adding application timer:
DEBUG | 20070514-223643.852 | kenobi | nsp | RESIP:DUM | 5165 |
3079915904 | DialogSet.cxx:122 | ********** DialogSet::~DialogSet:
26-7258 at 192.168.61.132-ec956632*************
DEBUG | 20070514-223643.910 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | Transport.cxx:287 | incoming from: [ V4
192.168.61.132:5060 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ]
DEBUG | 20070514-223643.911 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:85 | Adding timer: Timer H
tid=-7258-26-0 ms=64000
DEBUG | 20070514-223643.911 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:85 | Adding timer: Timer G
tid=-7258-26-0 ms=1000
DEBUG | 20070514-223643.911 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | TransportSelector.cxx:521 | Looked up source for
destination: [ V4 192.168.61.132:5060 UDP target domain=unspecified
received on: Transport: [ V4 0.0.0.0:12005 UDP target
domain=unspecified connectionId=0 ] connectionId=0 ] -> [ V4
192.168.61.130:0 UDP target domain=unspecified received on: Transport:
[ V4 0.0.0.0:12005 UDP target domain=unspecified connectionId=0 ]
connectionId=0 ] sent-by=192.168.61.132 sent-port=5060
DEBUG | 20070514-223643.911 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | TransportSelector.cxx:879 | Transmitting to [ V4
192.168.61.132:5060 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4
192.168.61.130:12005 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ]
SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=ec956632
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Content-Type: text/xml
Content-Length: 50
<?xml version="1.0" ?><reply status="Not found" />
==================================================
DEBUG | 20070514-223644.055 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | UdpTransport.cxx:81 | Sent: SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=ec956632
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Content-Type: text/xml
Content-Length: 50
<?xml version="1.0" ?><reply status="Not found" />
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | Transport.cxx:287 | incoming from: [ V4
192.168.61.132:5060 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ]
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:85 | Adding timer: Timer H
tid=-7258-27-0 ms=64000
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:85 | Adding timer: Timer G
tid=-7258-27-0 ms=1000
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | TransportSelector.cxx:521 | Looked up source for
destination: [ V4 192.168.61.132:5060 UDP target domain=unspecified
received on: Transport: [ V4 0.0.0.0:12005 UDP target
domain=unspecified connectionId=0 ] connectionId=0 ] -> [ V4
192.168.61.130:0 UDP target domain=unspecified received on: Transport:
[ V4 0.0.0.0:12005 UDP target domain=unspecified connectionId=0 ]
connectionId=0 ] sent-by=192.168.61.132 sent-port=5060
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | TransportSelector.cxx:879 | Transmitting to [ V4
192.168.61.132:5060 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4
192.168.61.130:12005 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ]
SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-27-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=e10c9500
From: "aceline"<sip:aceline at 192.168.61.132:5060>;tag=27
Call-ID: 27-7258 at 192.168.61.132
CSeq: 27 INVITE
Content-Type: text/xml
Content-Length: 50
<?xml version="1.0" ?><reply status="Not found" />
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | Transport.cxx:213 | Adding message to tx buffer to: [ V4
192.168.61.132:5060 UDP target domain=unspecified received on:
Transport: [ V4 0.0.0.0:12005 UDP target domain=unspecified
connectionId=0 ] connectionId=0 ]
DEBUG | 20070514-223644.057 | kenobi | nsp | RESIP:TRANSACTION | 5165
| 3079915904 | TimerQueue.cxx:85 | Adding timer: Timer I
tid=-7258-19-0 ms=10000
DEBUG | 20070514-223644.109 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | UdpTransport.cxx:81 | Sent: SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-27-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=e10c9500
From: "aceline"<sip:aceline at 192.168.61.132:5060>;tag=27
Call-ID: 27-7258 at 192.168.61.132
CSeq: 27 INVITE
Content-Type: text/xml
Content-Length: 50
<?xml version="1.0" ?><reply status="Not found" />
==================================================
DEBUG | 20070514-223645.047 | kenobi | nsp | RESIP:TRANSPORT | 5165 |
3079915904 | UdpTransport.cxx:81 | Sent: SIP/2.0 606 Not Acceptable
Via: SIP/2.0/UDP 192.168.61.132:5060;branch=z9hG4bK-7258-26-0
To: "spzero"<sip:spzero at 192.168.61.130:12005>;tag=ec956632
From: "candid"<sip:candid at 192.168.61.132:5060>;tag=26
Call-ID: 26-7258 at 192.168.61.132
CSeq: 26 INVITE
Content-Type: text/xml
Content-Length: 50
<?xml version="1.0" ?><reply status="Not found" />
==================================================
More information about the resiprocate-devel
mailing list