On Thu, 2008-04-03 at 13:45, Charles P Wright wrote:
> Scott if you can run say 10 calls that exhibit this behavior with
> -trace_msg and -trace_error that could go a long way to diagnosing the
> problem.
Well, since its related to load (if not congestion or both), I can't do
that for 10 calls, at least not with the stable build. However, I've
gone through the trace_msg for some large sets where the 200 OK is
received and the ACK is never sent, and there's nothing in there that's
different from the calls there the ACK is sent. There's also nothing in
the error log, except at the end it aborts the calls in progress when I
quit. I extracted the messages from one call in that log and attached it
(stable.missing.ack) in case I've missed anything.
For the trunk build, I'm not sure if it is the same sort of error after
all -- in the trunk code, the error where there are too many OKs sent
comes much more easily, and now that I look at the trace messages
(trunk.bad), I see that it's a different thing: in this case, the 180 OK
is coming after the BYE is sent, and then sipp is sending a new ack,
apparently thinking the call is not connected (instead of realizing it
is completed).
-Scott
> The matching code did change between the 3.0 and the latest release, but I
> didn't think that the default logic had been changed. The new logic is to
> support the start_txn and response_txn attributes of send and receive,
> respectively. Previously, the CSeq was used and the matching was
> imprecise (and the default is). But now you can explicitly mark them
> like:
> <send start_txn="invite" />
> ...
> </send>
> <recv resposne_txn="invite" reply="100" />
> <recv resposne_txn="invite" reply="180" />
> <recv resposne_txn="invite" reply="200" />
>
> The string "invite" in here is just a name, it can be anything. When the
> message is sent, its branch ID is stored in a table, and replies are
> validated against that branch.
>
> You can actually prevent an optional="global" message from taking over the
> control flow by doing advance_state="false", but I would prefer to fix the
> matching for your scenario.
>
> Charles
>
>
>
>
> Scott Oaks <[EMAIL PROTECTED]>
> Sent by: [EMAIL PROTECTED]
> 04/03/2008 12:54 PM
> Please respond to
> [EMAIL PROTECTED]
>
>
> To
> Charles P Wright/Watson/[EMAIL PROTECTED]
> cc
> [email protected]
> Subject
> Re: [Sipp-users] sipp corrupting messages
>
>
>
>
>
>
>
> On Wed, 2008-04-02 at 23:05, Charles P Wright wrote:
> > My best guess is that if you look at the default messages in the source,
>
> > that ACK will match up relatively nicely to one of them in there rather
> > than it coming from some sort of corruption.
>
> Yes, it turns out to be the case, but why we get to that code is still a
> mystery -- it's coming from abortCall() and likely process_unexpected()
> but I can't quite catch that. Still, this happens quite rarely, and
> there's a more general issue with the ACKs that I'll show below
> (originally, I thought it was all the same, but it turns out not to be).
>
> > I would also be interested if you can provide any more information about
>
> > regressions you've seen.
>
> I'm beginning to think that what I'm seeing is a different manifestation
> of the same symptom I see in the stable build. In general, I see more
> errors and a longer reported avg call length (maybe 20-30% more) at the
> end of a run -- but the call length is, I suspect, at least partly
> because of the extra error processing time. It could also be a compile
> issue -- I can't compile the latest code with the SunStudio compiler I
> used for the stable code, though I don't really think that there is a
> signficant difference between that at gcc these days.
>
> About those errors -- I'm increasingly convinced that something is wrong
> in the combination of optional messages received out of order and
> congestion. If I run 100 calls in the latest code (well, the latest I
> checked out, which is SVN version 424), the uac reports this:
>
> Call limit reached (-m 100), 0.494 s period 1 ms scheduler resolution
> 0 calls (limit 1536) Peak was 62 calls, after 0 s
> 0 Running, 100 Paused, 0 Woken up
> 17 dead call msg (discarded) 0 out-of-call msg (discarded)
> 2 open sockets
>
> Messages Retrans Timeout
> Unexpected-Msg
> INVITE ----------> 100 0 0
> 100 <---------- 100 0 0 0
> 180 <---------- 85 0 0 0
> 200 <---------- E-RTD1 122 0 0 0
> ACK ----------> 122 0
> Pause [ 0ms] 122 0
> BYE ----------> 122 0 0
> 200 <---------- 78 0 0 22
>
> There's just some bad call-matching going on there; there shouldn't 22
> extra 200OK received to from the INVITE; clearly they belong to the BYE
> (and then the 22 extra BYEs cause 22 481s to be received).
>
> For comparison, here's what I see in the stable build:
> Call limit reached (-m 1000), 0.660 s period 9 ms scheduler
> resolution
> 172 calls (limit 1536) Peak was 858 calls, after 1 s
> 0 Running, 172 Paused, 0 Woken up
> 0 out-of-call msg (discarded)
> 2 open sockets 0/0/12 TCP errors
> (send/recv/cong)
>
> Messages Retrans Timeout
> Unexpected-Msg
> INVITE ----------> 1000 0 0
> 100 <---------- 1000 0 0 0
> 180 <---------- 933 0 0 0
> 200 <---------- E-RTD1 1000 0 0 0
> ACK ----------> 829 0
> Pause [ 0ms] 829 0
> BYE ----------> 829 0 0
> 200 <---------- 828 0 0 0
>
> At this point, the uac never sends anything else; for some reason it has
> dropped 171 200 responses and not sent out an ACK. [But I don't see 171
> of the abort-call generated ACKs either -- possibly there are two
> different things going on.]
>
> If a GLOBAL optional message is received out of order, perhaps it should
> just be ignored (that is, after incrementing the recv counter,
> call::process_incoming() could return without processing the rest)? That
> certainly fixes the issue for me (on both the stable and trunk builds).
> Or perhaps there could be an optional="ingore" tag for that case?
>
> -Scott
>
>
>
>
> -------------------------------------------------------------------------
> Check out the new SourceForge.net Marketplace.
> It's the best place to buy or sell services for
> just about anything Open Source.
> http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
> _______________________________________________
> Sipp-users mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/sipp-users
----------------------------------------------- 2008-04-03 10:21:39:409.084
TCP message sent (572 bytes):
INVITE sip:[EMAIL PROTECTED]:5045;transport=TCP SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-0
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
To: sut <sip:[EMAIL PROTECTED]:5045>
Call-ID: [EMAIL PROTECTED]
CSeq: 1 INVITE
Contact: <sip:[EMAIL PROTECTED]:5035;transport=TCP>
Max-Forwards: 70
Subject: InviteProxy Performance Test
Test-Type: uas
Content-Type: application/sdp
Content-Length: 129
v=0
o=user1 53655765 2353687637 IN IP4 10.5.8.146
s=-
c=IN IP4 10.5.8.146
t=0 0
m=audio 6001 RTP/AVP 0
a=rtpmap:0 PCMU/8000
----------------------------------------------- 2008-04-03 10:21:39:418.017
TCP message received [276] bytes :
SIP/2.0 100 Trying
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>
Cseq: 1 INVITE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-0
Server: Glassfish_SIP_1.0.0
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
----------------------------------------------- 2008-04-03 10:21:39:428.894
TCP message received [634] bytes :
SIP/2.0 200 OK
Record-Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
Content-Length: 129
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Contact: <sip:10.5.8.146:5045>;transport=TCP;fid=server_1
Cseq: 1 INVITE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-0;received=10.5.8.175
Content-Type: application/sdp
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
v=0
o=user1 53655765 2353687637 IN IP4 10.5.8.146
s=-
c=IN IP4 10.5.8.146
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000
----------------------------------------------- 2008-04-03 10:21:39:429.137
TCP message sent (465 bytes):
ACK sip:[EMAIL PROTECTED]:5045;transport=TCP;fid=server_1 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-4
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
To: sut <sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Call-ID: [EMAIL PROTECTED]
CSeq: 1 ACK
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
Contact: sip:[EMAIL PROTECTED]:5035
Max-Forwards: 70
Subject: InviteProxy Performance Test
Content-Length: 0
----------------------------------------------- 2008-04-03 10:21:39:429.230
TCP message sent (465 bytes):
BYE sip:[EMAIL PROTECTED]:5045;transport=TCP;fid=server_1 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-6
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
To: sut <sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Call-ID: [EMAIL PROTECTED]
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
CSeq: 2 BYE
Contact: sip:[EMAIL PROTECTED]:5035
Max-Forwards: 70
Subject: InviteProxy Performance Test
Content-Length: 0
----------------------------------------------- 2008-04-03 10:21:39:429.443
TCP message received [464] bytes :
SIP/2.0 180 Ringing
Record-Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Contact: <sip:10.5.8.146:5045;transport=TCP>
Cseq: 1 INVITE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-0;received=10.5.8.175
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
----------------------------------------------- 2008-04-03 10:21:39:451.195
TCP message received [389] bytes :
SIP/2.0 200 OK
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Contact: <sip:10.5.8.146:5045;transport=TCP>
Cseq: 2 BYE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-6;received=10.5.8.175
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
----------------------------------------------- 2008-04-03 10:21:39:451.349
TCP message sent (465 bytes):
ACK sip:[EMAIL PROTECTED]:5045;transport=TCP;fid=server_1 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-4
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
To: sut <sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Call-ID: [EMAIL PROTECTED]
CSeq: 2 ACK
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
Contact: sip:[EMAIL PROTECTED]:5035
Max-Forwards: 70
Subject: InviteProxy Performance Test
Content-Length: 0
----------------------------------------------- 2008-04-03 10:21:39:451.437
TCP message sent (465 bytes):
BYE sip:[EMAIL PROTECTED]:5045;transport=TCP;fid=server_1 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-6
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
To: sut <sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Call-ID: [EMAIL PROTECTED]
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
CSeq: 2 BYE
Contact: sip:[EMAIL PROTECTED]:5035
Max-Forwards: 70
Subject: InviteProxy Performance Test
Content-Length: 0
----------------------------------------------- 2008-04-03 10:21:39:538.850
TCP message received [341] bytes :
SIP/2.0 481 Call/Transaction Does Not Exist
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Cseq: 2 BYE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-6;received=10.5.8.175
Server: Glassfish_SIP_1.0.0
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
-----------------------------------------------
Unexpected TCP message received:
SIP/2.0 481 Call/Transaction Does Not Exist
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Cseq: 2 BYE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14-6;received=10.5.8.175
Server: Glassfish_SIP_1.0.0
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
----------------------------------------------- 2008-04-03 10:21:39:539.555
TCP message sent (358 bytes):
BYE sip:[EMAIL PROTECTED]:5045 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14--1
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Call-ID: [EMAIL PROTECTED]
CSeq: 3 BYE
Max-Forwards: 70
Contact: <sip:[EMAIL PROTECTED]:5035;transport=TCP>
Content-Length: 0
----------------------------------------------- 2008-04-03 10:21:39:586.993
TCP message received [342] bytes :
SIP/2.0 481 Call/Transaction Does Not Exist
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Cseq: 3 BYE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14--1;received=10.5.8.175
Server: Glassfish_SIP_1.0.0
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
-----------------------------------------------
Dead call [EMAIL PROTECTED] recieved a TCP message:
SIP/2.0 481 Call/Transaction Does Not Exist
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=14198SIPpTag01158
Cseq: 3 BYE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-14510-14--1;received=10.5.8.175
Server: Glassfish_SIP_1.0.0
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=14510SIPpTag0014
Call-Id: [EMAIL PROTECTED]
----------------------------------------------- 2008-04-03 11:34:42:546.428
TCP message sent (577 bytes):
INVITE sip:[EMAIL PROTECTED]:5045;transport=TCP SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-23099-248-0
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=23099SIPpTag00248
To: sut <sip:[EMAIL PROTECTED]:5045>
Call-ID: [EMAIL PROTECTED]
CSeq: 1 INVITE
Contact: <sip:[EMAIL PROTECTED]:5035;transport=TCP>
Max-Forwards: 70
Subject: InviteProxy Performance Test
Test-Type: uas
Content-Type: application/sdp
Content-Length: 131
v=0
o=user1 53655765 2353687637 IN IP4 10.5.8.146
s=-
c=IN IP4 10.5.8.146
t=0 0
m=audio 6001 RTP/AVP 0
a=rtpmap:0 PCMU/8000
----------------------------------------------- 2008-04-03 11:34:42:972.738
TCP message received [279] bytes :
SIP/2.0 100 Trying
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>
Cseq: 1 INVITE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-23099-248-0
Server: Glassfish_SIP_1.0.0
From: sipp <sip:[EMAIL PROTECTED]:5035>;tag=23099SIPpTag00248
Call-Id: [EMAIL PROTECTED]
----------------------------------------------- 2008-04-03 11:34:43:98.759
TCP message received [637] bytes :
SIP/2.0 200 OK
Record-Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
Content-Length: 129
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=23098SIPpTag01248
Contact: <sip:10.5.8.146:5045>;transport=TCP;fid=server_1
Cseq: 1 INVITE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-23099-248-0;received=10.5.8.175
Content-Type: application/sdp
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=23099SIPpTag00248
Call-Id: [EMAIL PROTECTED]
v=0
o=user1 53655765 2353687637 IN IP4 10.5.8.146
s=-
c=IN IP4 10.5.8.146
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000
----------------------------------------------- 2008-04-03 11:34:43:99.321
TCP message received [467] bytes :
SIP/2.0 180 Ringing
Record-Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
Content-Length: 0
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=23098SIPpTag01248
Contact: <sip:10.5.8.146:5045;transport=TCP>
Cseq: 1 INVITE
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-23099-248-0;received=10.5.8.175
Route: <sip:10.5.8.173:5060;fid=server_1;transport=tcp;lr>
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=23099SIPpTag00248
Call-Id: [EMAIL PROTECTED]
...This is from the abort when I quit manually after 15 seconds...
----------------------------------------------- 2008-04-03 11:34:58:900.683
TCP message sent (356 bytes):
ACK sip:[EMAIL PROTECTED]:5045 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-23099-248--1
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=23099SIPpTag00248
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=23098SIPpTag01248
Call-ID: [EMAIL PROTECTED]
CSeq: 1 ACK
Max-Forwards: 70
Contact: <sip:10.5.8.146:5035;transport=TCP>
Content-Length: 0
----------------------------------------------- 2008-04-03 11:34:58:900.965
TCP message sent (356 bytes):
BYE sip:[EMAIL PROTECTED]:5045 SIP/2.0
Via: SIP/2.0/TCP 10.5.8.146:5035;branch=z9hG4bK-23099-248--1
From: "sipp"<sip:[EMAIL PROTECTED]:5035>;tag=23099SIPpTag00248
To: "sut"<sip:[EMAIL PROTECTED]:5045>;tag=23098SIPpTag01248
Call-ID: [EMAIL PROTECTED]
CSeq: 2 BYE
Max-Forwards: 70
Contact: <sip:10.5.8.146:5035;transport=TCP>
Content-Length: 0
-------------------------------------------------------------------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
_______________________________________________
Sipp-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/sipp-users
