As a matter of fact, I already checked this. There is a reply route set before t_relay, and log outputs in it. The log line is well seen on 180 and on 200. This does not avoid retransmission.

Here is a log file with much trace for a call that was answered but retransmitted.

on an INVITE, a module of mine is collecting all contacts for a serial forking. an on_reply_route is set, with a trace of mine in it

My log format is : T000 [date] [time] bin#ser#<pid>#-1 = <log>

This was on a 1 call only. I cannot figure out what is happening.

Any comment is welcome.

Thanks ! Aurelien

Klaus Darilion a écrit :

Hi!

1. Not the ACK, but the 200 Ok will stop retransmission. I suspect

that the 200 ok is not identified as belonging to the INVITE transaction.

Try this:

1. before t_relay() activate a certain reply_route (t_on_reply("3"))
2. put some xlog in the the default reply route

onreply_route { xlog("==========================="); xlog("default reply route ...\n"); xlog("response: $$rm = $rm\n"); xlog("response: $mb\n"); xlog("==========================="); }

3. put some xlog in the reply route you activated with t_on_reply()

onreply_route[3] { xlog("==========================="); xlog("reply route 3 ...\n"); xlog("response: $$rm = $rm\n"); xlog("response: $mb\n"); xlog("==========================="); }

4. watch the log output

If both reply routes are exectued then kamailio successfully matched the reply to the response. If only the default reply route is executed then the transaction matching failed.

Try only with a single call (not 1000 calls/s) first.

regards klaus

Aurelien Grimaud schrieb:

...

Hi, I am using kamailio 1.4.2 and testing it with sipp. one sipp is client a uac (port 5066), the other is a uas (port 5063). kamailio is using 5060.

I am generating 100 calls per second for 1000 calls and message were retransmitted 4 times.

Here is a tcpdump of sip packets. Can anyone tell me why there is an INVITE retransmission at 16:16:38.627198 though the ACK for invite was received at 16:16:38.126096 ? Is there a known problem with retransmission timers ?

16:16:38.120384 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 579 E.._..@.@.f....!...!.....K..INVITE sip:otest@testg5 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.123426 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 325 E..a..@.@.g....!...!.....M..SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1;received=192.168.168.33 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Server: Kamailio (1.4.2-notls (i386/linux)) Content-Length: 0

16:16:38.123554 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.123830 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 451 E.....@.@.gz...!...!.......pSIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.124169 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 393 E.....@.@.g....!...!.......6SIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.124326 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 634 E.....@.@.f....!...!.......'SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Type: application/sdp Content-Length: 153

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000

16:16:38.124883 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 581 E..a..@.@.f....!...!.....M..SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:192.168.168.33:5063 Content-Type: application/sdp Content-Length: 153

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000

16:16:38.125532 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 427 E.....@.@.g....!...!.......XACK sip:192.168.168.33:5063 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Subject: Performance Test Content-Length: 0

16:16:38.126096 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 521 E..%..@.@.g,...!...!........ACK sip:192.168.168.33:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:38.627198 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.627677 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 474 E.....@.@.gc...!...!........SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.627970 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 416 E.....@.@.g....!...!.......MSIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.642356 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:39.642587 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 474 E.....@.@.gc...!...!........SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.643723 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 416 E.....@.@.g....!...!.......MSIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.797641 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 434 E.....@.@.g....!...!......._BYE sip:127.0.0.1:5063 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Subject: Performance Test Content-Length: 0

16:16:39.798436 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:39.798535 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.798814 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 336 E..l..@.@.g....!...!.....X..SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:40.257973 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:40.258080 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:41.285493 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:41.285593 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:41.695686 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:43.338592 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:43.338785 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 408 E.....@.@.g....!...!.......ESIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063;transport=UDP Content-Length: 0

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

Fair enough. If no one already experienced this strange behavior, it should be my module ... I'll try to make it again without my module.

However, in the log, after the 200 response, there is a cleanup_uac_timers: RETR/FR timers reset. So those timers are cleared. To investigate any further, could you point me where in the source the retransmission timers are cleared ?

Aurelien

Klaus Darilion a écrit :

Is it also happening WITHOUT your module?

klaus

Aurelien Grimaud schrieb:

...

As a matter of fact, I already checked this. There is a reply route set before t_relay, and log outputs in it. The log line is well seen on 180 and on 200. This does not avoid retransmission.

Here is a log file with much trace for a call that was answered but retransmitted.

on an INVITE, a module of mine is collecting all contacts for a serial forking. an on_reply_route is set, with a trace of mine in it

My log format is : T000 [date] [time] bin#ser#<pid>#-1 = <log>

This was on a 1 call only. I cannot figure out what is happening.

Any comment is welcome.

Thanks ! Aurelien

Klaus Darilion a écrit :

...

Hi!

1. Not the ACK, but the 200 Ok will stop retransmission. I suspect

that the 200 ok is not identified as belonging to the INVITE transaction.

Try this:

1. before t_relay() activate a certain reply_route (t_on_reply("3"))
2. put some xlog in the the default reply route

onreply_route { xlog("==========================="); xlog("default reply route ...\n"); xlog("response: $$rm = $rm\n"); xlog("response: $mb\n"); xlog("==========================="); }

3. put some xlog in the reply route you activated with t_on_reply()

onreply_route[3] { xlog("==========================="); xlog("reply route 3 ...\n"); xlog("response: $$rm = $rm\n"); xlog("response: $mb\n"); xlog("==========================="); }

4. watch the log output

If both reply routes are exectued then kamailio successfully matched the reply to the response. If only the default reply route is executed then the transaction matching failed.

Try only with a single call (not 1000 calls/s) first.

regards klaus

Aurelien Grimaud schrieb:

...

Hi, I am using kamailio 1.4.2 and testing it with sipp. one sipp is client a uac (port 5066), the other is a uas (port 5063). kamailio is using 5060.

I am generating 100 calls per second for 1000 calls and message were retransmitted 4 times.

Here is a tcpdump of sip packets. Can anyone tell me why there is an INVITE retransmission at 16:16:38.627198 though the ACK for invite was received at 16:16:38.126096 ? Is there a known problem with retransmission timers ?

16:16:38.120384 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 579 E.._..@.@.f....!...!.....K..INVITE sip:otest@testg5 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.123426 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 325 E..a..@.@.g....!...!.....M..SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1;received=192.168.168.33 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Server: Kamailio (1.4.2-notls (i386/linux)) Content-Length: 0

16:16:38.123554 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.123830 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 451 E.....@.@.gz...!...!.......pSIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.124169 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 393 E.....@.@.g....!...!.......6SIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.124326 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 634 E.....@.@.f....!...!.......'SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Type: application/sdp Content-Length: 153

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000

16:16:38.124883 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 581 E..a..@.@.f....!...!.....M..SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:192.168.168.33:5063 Content-Type: application/sdp Content-Length: 153

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000

16:16:38.125532 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 427 E.....@.@.g....!...!.......XACK sip:192.168.168.33:5063 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Subject: Performance Test Content-Length: 0

16:16:38.126096 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 521 E..%..@.@.g,...!...!........ACK sip:192.168.168.33:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:38.627198 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.627677 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 474 E.....@.@.gc...!...!........SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.627970 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 416 E.....@.@.g....!...!.......MSIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.642356 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:39.642587 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 474 E.....@.@.gc...!...!........SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.643723 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 416 E.....@.@.g....!...!.......MSIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.797641 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 434 E.....@.@.g....!...!......._BYE sip:127.0.0.1:5063 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Subject: Performance Test Content-Length: 0

16:16:39.798436 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:39.798535 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.798814 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 336 E..l..@.@.g....!...!.....X..SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:40.257973 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:40.258080 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:41.285493 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:41.285593 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:41.695686 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:43.338592 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:43.338785 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 408 E.....@.@.g....!...!.......ESIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063;transport=UDP Content-Length: 0

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

Hello,

On 12/09/08 17:31, Klaus Darilion wrote:

Aurelien Grimaud schrieb:

...

Fair enough. If no one already experienced this strange behavior, it should be my module ... I'll try to make it again without my module.

See my other email.

...

However, in the log, after the 200 response, there is a cleanup_uac_timers: RETR/FR timers reset. So those timers are cleared.

But the problem is, that the process which handles the INVITE has not finished yet and those (re)SETS the timer.

@Daniel - Have you investigated the problem?

so this is the half of the issue reported via: https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr...

This one got lost, but as I started to fix the other half (replying using proper mode to do retransmission), will investigate this as well ...

Cheers, Daniel

regards klaus

...

To investigate any further, could you point me where in the source the retransmission timers are cleared ?

Aurelien

Klaus Darilion a écrit :

...

Is it also happening WITHOUT your module?

klaus

Aurelien Grimaud schrieb:

...

As a matter of fact, I already checked this. There is a reply route set before t_relay, and log outputs in it. The log line is well seen on 180 and on 200. This does not avoid retransmission.

Here is a log file with much trace for a call that was answered but retransmitted.

on an INVITE, a module of mine is collecting all contacts for a serial forking. an on_reply_route is set, with a trace of mine in it

My log format is : T000 [date] [time] bin#ser#<pid>#-1 = <log>

This was on a 1 call only. I cannot figure out what is happening.

Any comment is welcome.

Thanks ! Aurelien

Klaus Darilion a écrit :

...

Hi!

1. Not the ACK, but the 200 Ok will stop retransmission. I suspect

that the 200 ok is not identified as belonging to the INVITE transaction.

Try this:

1. before t_relay() activate a certain reply_route (t_on_reply("3"))
2. put some xlog in the the default reply route

onreply_route { xlog("==========================="); xlog("default reply route ...\n"); xlog("response: $$rm = $rm\n"); xlog("response: $mb\n"); xlog("==========================="); }

3. put some xlog in the reply route you activated with t_on_reply()

onreply_route[3] { xlog("==========================="); xlog("reply route 3 ...\n"); xlog("response: $$rm = $rm\n"); xlog("response: $mb\n"); xlog("==========================="); }

4. watch the log output

If both reply routes are exectued then kamailio successfully matched the reply to the response. If only the default reply route is executed then the transaction matching failed.

Try only with a single call (not 1000 calls/s) first.

regards klaus

Aurelien Grimaud schrieb:

...

Hi, I am using kamailio 1.4.2 and testing it with sipp. one sipp is client a uac (port 5066), the other is a uas (port 5063). kamailio is using 5060.

I am generating 100 calls per second for 1000 calls and message were retransmitted 4 times.

Here is a tcpdump of sip packets. Can anyone tell me why there is an INVITE retransmission at 16:16:38.627198 though the ACK for invite was received at 16:16:38.126096 ? Is there a known problem with retransmission timers ?

16:16:38.120384 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 579 E.._..@.@.f....!...!.....K..INVITE sip:otest@testg5 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.123426 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 325 E..a..@.@.g....!...!.....M..SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1;received=192.168.168.33 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Server: Kamailio (1.4.2-notls (i386/linux)) Content-Length: 0

16:16:38.123554 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.123830 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 451 E.....@.@.gz...!...!.......pSIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.124169 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 393 E.....@.@.g....!...!.......6SIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.124326 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 634 E.....@.@.f....!...!.......'SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Type: application/sdp Content-Length: 153

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000

16:16:38.124883 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 581 E..a..@.@.f....!...!.....M..SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:192.168.168.33:5063 Content-Type: application/sdp Content-Length: 153

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 6004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000

16:16:38.125532 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 427 E.....@.@.g....!...!.......XACK sip:192.168.168.33:5063 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Subject: Performance Test Content-Length: 0

16:16:38.126096 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 521 E..%..@.@.g,...!...!........ACK sip:192.168.168.33:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:38.627198 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:38.627677 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 474 E.....@.@.gc...!...!........SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:38.627970 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 416 E.....@.@.g....!...!.......MSIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.642356 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:39.642587 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 474 E.....@.@.gc...!...!........SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.643723 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 416 E.....@.@.g....!...!.......MSIP/2.0 180 Ringing Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.797641 IP 192.168.168.33.5066 > 192.168.168.33.5060: SIP, length: 434 E.....@.@.g....!...!......._BYE sip:127.0.0.1:5063 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 70 Subject: Performance Test Content-Length: 0

16:16:39.798436 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:39.798535 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:39.798814 IP 192.168.168.33.5060 > 192.168.168.33.5066: SIP, length: 336 E..l..@.@.g....!...!.....X..SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:40.257973 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:40.258080 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:41.285493 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:41.285593 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 394 E.....@.@.g....!...!.......7SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063 Content-Length: 0

16:16:41.695686 IP 192.168.168.33.5060 > 192.168.168.33.5063: SIP, length: 731 E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:otest@testg5 Call-ID: 730-23096-127.0.0.1 CSeq: 1 INVITE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Expires: 180 Subject: Performance Test Content-Type: application/sdp Content-Length: 188

v=0 o=user1 53655765 2353687637 IN IP4 127.0.0.1 s=- c=IN IP4 127.0.0.1 t=0 0 m=audio 8925 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16

16:16:43.338592 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, length: 528 E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 Via: SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:sipp@127.0.0.1:5066 Max-Forwards: 69 Subject: Performance Test Content-Length: 0

16:16:43.338785 IP 192.168.168.33.5063 > 192.168.168.33.5060: SIP, length: 408 E.....@.@.g....!...!.......ESIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 From: sipp sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 Call-ID: 730-23096-127.0.0.1 CSeq: 2 BYE Contact: sip:127.0.0.1:5063;transport=UDP Content-Length: 0

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

On 12/09/08 17:56, Klaus Darilion wrote:

Daniel-Constantin Mierla schrieb:

...

Hello,

On 12/09/08 17:31, Klaus Darilion wrote:

...

Aurelien Grimaud schrieb:

...

Fair enough. If no one already experienced this strange behavior, it should be my module ... I'll try to make it again without my module.

See my other email.

...

However, in the log, after the 200 response, there is a cleanup_uac_timers: RETR/FR timers reset. So those timers are cleared.

But the problem is, that the process which handles the INVITE has not finished yet and those (re)SETS the timer.

@Daniel - Have you investigated the problem?

so this is the half of the issue reported via: https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr...

yes.

Can it be related to other modules which register callbacks (e.g. pua module or Aurelien's module?

what is the requests/second rate when the issue appears?

At first look, between sending and setting retransmission timer, there is no much processing for the request. The callback executed there is in use by siptrace, are you using this module?

Cheers, Daniel

...

This one got lost, but as I started to fix the other half (replying using proper mode to do retransmission), will investigate this as well ...

Cheers, Daniel

...

regards klaus

...

To investigate any further, could you point me where in the source the retransmission timers are cleared ?

Aurelien

Klaus Darilion a écrit :

...

Is it also happening WITHOUT your module?

klaus

Aurelien Grimaud schrieb:

...

As a matter of fact, I already checked this. There is a reply route set before t_relay, and log outputs in it. The log line is well seen on 180 and on 200. This does not avoid retransmission.

Here is a log file with much trace for a call that was answered but retransmitted.

on an INVITE, a module of mine is collecting all contacts for a serial forking. an on_reply_route is set, with a trace of mine in it

My log format is : T000 [date] [time] bin#ser#<pid>#-1 = <log>

This was on a 1 call only. I cannot figure out what is happening.

Any comment is welcome.

Thanks ! Aurelien

Klaus Darilion a écrit :

> Hi! > > 1. Not the ACK, but the 200 Ok will stop retransmission. I suspect > that the 200 ok is not identified as belonging to the INVITE > transaction. > > Try this: > > 1. before t_relay() activate a certain reply_route (t_on_reply("3")) > 2. put some xlog in the the default reply route > > onreply_route { > xlog("==========================="); > xlog("default reply route ...\n"); > xlog("response: $$rm = $rm\n"); > xlog("response: $mb\n"); > xlog("==========================="); > } > > 3. put some xlog in the reply route you activated with t_on_reply() > > onreply_route[3] { > xlog("==========================="); > xlog("reply route 3 ...\n"); > xlog("response: $$rm = $rm\n"); > xlog("response: $mb\n"); > xlog("==========================="); > } > > 4. watch the log output > > If both reply routes are exectued then kamailio successfully > matched the reply to the response. If only the default reply route > is executed then the transaction matching failed. > > Try only with a single call (not 1000 calls/s) first. > > regards > klaus > > Aurelien Grimaud schrieb: > > >> Hi, I am using kamailio 1.4.2 and testing it with sipp. >> one sipp is client a uac (port 5066), the other is a uas (port >> 5063). >> kamailio is using 5060. >> >> I am generating 100 calls per second for 1000 calls and message >> were retransmitted 4 times. >> >> Here is a tcpdump of sip packets. >> Can anyone tell me why there is an INVITE retransmission at >> 16:16:38.627198 though the ACK for invite was received at >> 16:16:38.126096 ? >> Is there a known problem with retransmission timers ? >> >> 16:16:38.120384 IP 192.168.168.33.5066 > 192.168.168.33.5060: >> SIP, length: 579 >> E.._..@.@.f....!...!.....K..INVITE sip:otest@testg5 SIP/2.0 >> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 70 >> Expires: 180 >> Subject: Performance Test >> Content-Type: application/sdp >> Content-Length: 188 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 8925 RTP/AVP 8 101 >> a=rtpmap:8 PCMA/8000 >> a=rtpmap:101 telephone-event/8000 >> a=fmtp:101 0-11,16 >> >> 16:16:38.123426 IP 192.168.168.33.5060 > 192.168.168.33.5066: >> SIP, length: 325 >> E..a..@.@.g....!...!.....M..SIP/2.0 100 Giving a try >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;branch=z9hG4bK-23096-730-1;received=192.168.168.33 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Server: Kamailio (1.4.2-notls (i386/linux)) >> Content-Length: 0 >> >> >> 16:16:38.123554 IP 192.168.168.33.5060 > 192.168.168.33.5063: >> SIP, length: 731 >> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Expires: 180 >> Subject: Performance Test >> Content-Type: application/sdp >> Content-Length: 188 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 8925 RTP/AVP 8 101 >> a=rtpmap:8 PCMA/8000 >> a=rtpmap:101 telephone-event/8000 >> a=fmtp:101 0-11,16 >> >> 16:16:38.123830 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 451 >> E.....@.@.gz...!...!.......pSIP/2.0 180 Ringing >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:38.124169 IP 192.168.168.33.5060 > 192.168.168.33.5066: >> SIP, length: 393 >> E.....@.@.g....!...!.......6SIP/2.0 180 Ringing >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:38.124326 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 634 >> E.....@.@.f....!...!.......'SIP/2.0 200 OK >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Type: application/sdp >> Content-Length: 153 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 6004 RTP/AVP 0 8 >> a=rtpmap:0 PCMU/8000 >> a=rtpmap:8 PCMA/8000 >> >> 16:16:38.124883 IP 192.168.168.33.5060 > 192.168.168.33.5066: >> SIP, length: 581 >> E..a..@.@.f....!...!.....M..SIP/2.0 200 OK >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:192.168.168.33:5063 >> Content-Type: application/sdp >> Content-Length: 153 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 6004 RTP/AVP 0 8 >> a=rtpmap:0 PCMU/8000 >> a=rtpmap:8 PCMA/8000 >> >> 16:16:38.125532 IP 192.168.168.33.5066 > 192.168.168.33.5060: >> SIP, length: 427 >> E.....@.@.g....!...!.......XACK sip:192.168.168.33:5063 SIP/2.0 >> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-11 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >> Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 70 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:38.126096 IP 192.168.168.33.5060 > 192.168.168.33.5063: >> SIP, length: 521 >> E..%..@.@.g,...!...!........ACK sip:192.168.168.33:5063 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:38.627198 IP 192.168.168.33.5060 > 192.168.168.33.5063: >> SIP, length: 731 >> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Expires: 180 >> Subject: Performance Test >> Content-Type: application/sdp >> Content-Length: 188 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 8925 RTP/AVP 8 101 >> a=rtpmap:8 PCMA/8000 >> a=rtpmap:101 telephone-event/8000 >> a=fmtp:101 0-11,16 >> >> 16:16:38.627677 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 474 >> E.....@.@.gc...!...!........SIP/2.0 180 Ringing >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut >> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:38.627970 IP 192.168.168.33.5060 > 192.168.168.33.5066: >> SIP, length: 416 >> E.....@.@.g....!...!.......MSIP/2.0 180 Ringing >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut >> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:39.642356 IP 192.168.168.33.5060 > 192.168.168.33.5063: >> SIP, length: 731 >> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Expires: 180 >> Subject: Performance Test >> Content-Type: application/sdp >> Content-Length: 188 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 8925 RTP/AVP 8 101 >> a=rtpmap:8 PCMA/8000 >> a=rtpmap:101 telephone-event/8000 >> a=fmtp:101 0-11,16 >> >> 16:16:39.642587 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 474 >> E.....@.@.gc...!...!........SIP/2.0 180 Ringing >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut >> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:39.643723 IP 192.168.168.33.5060 > 192.168.168.33.5066: >> SIP, length: 416 >> E.....@.@.g....!...!.......MSIP/2.0 180 Ringing >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut >> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:39.797641 IP 192.168.168.33.5066 > 192.168.168.33.5060: >> SIP, length: 434 >> E.....@.@.g....!...!......._BYE sip:127.0.0.1:5063 SIP/2.0 >> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 70 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:39.798436 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >> length: 528 >> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:39.798535 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 394 >> E.....@.@.g....!...!.......7SIP/2.0 200 OK >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:39.798814 IP 192.168.168.33.5060 > 192.168.168.33.5066: >> SIP, length: 336 >> E..l..@.@.g....!...!.....X..SIP/2.0 200 OK >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:40.257973 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >> length: 528 >> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:40.258080 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 394 >> E.....@.@.g....!...!.......7SIP/2.0 200 OK >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:41.285493 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >> length: 528 >> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:41.285593 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 394 >> E.....@.@.g....!...!.......7SIP/2.0 200 OK >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:127.0.0.1:5063 >> Content-Length: 0 >> >> >> 16:16:41.695686 IP 192.168.168.33.5060 > 192.168.168.33.5063: >> SIP, length: 731 >> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:otest@testg5 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 1 INVITE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Expires: 180 >> Subject: Performance Test >> Content-Type: application/sdp >> Content-Length: 188 >> >> v=0 >> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >> s=- >> c=IN IP4 127.0.0.1 >> t=0 0 >> m=audio 8925 RTP/AVP 8 101 >> a=rtpmap:8 PCMA/8000 >> a=rtpmap:101 telephone-event/8000 >> a=fmtp:101 0-11,16 >> >> 16:16:43.338592 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >> length: 528 >> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >> Via: SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:sipp@127.0.0.1:5066 >> Max-Forwards: 69 >> Subject: Performance Test >> Content-Length: 0 >> >> >> 16:16:43.338785 IP 192.168.168.33.5063 > 192.168.168.33.5060: >> SIP, length: 408 >> E.....@.@.g....!...!.......ESIP/2.0 200 OK >> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >> SIP/2.0/UDP >> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >> From: sipp >> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >> Call-ID: 730-23096-127.0.0.1 >> CSeq: 2 BYE >> Contact: sip:127.0.0.1:5063;transport=UDP >> Content-Length: 0 >> >> >> >> >> >> _______________________________________________ >> Users mailing list >> Users@lists.kamailio.org >> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >> >>

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

On 12/09/08 18:52, Aurelien Grimaud wrote:

I am able to reproduce it with 1 call / second without my module on BYE requests. here are traces.

there is a race (at least), indeed. It happens when there is fast reply. I am going to send you a patch soon for testing, you use svn branch 1.4 or the tarball?

Cheers, Daniel

ps: I added the ms on Logs.

Aurelien

Daniel-Constantin Mierla a écrit :

...

On 12/09/08 17:56, Klaus Darilion wrote:

...

Daniel-Constantin Mierla schrieb:

...

Hello,

On 12/09/08 17:31, Klaus Darilion wrote:

...

Aurelien Grimaud schrieb:

...

Fair enough. If no one already experienced this strange behavior, it should be my module ... I'll try to make it again without my module.

See my other email.

...

However, in the log, after the 200 response, there is a cleanup_uac_timers: RETR/FR timers reset. So those timers are cleared.

But the problem is, that the process which handles the INVITE has not finished yet and those (re)SETS the timer.

@Daniel - Have you investigated the problem?

so this is the half of the issue reported via: https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr...

yes.

Can it be related to other modules which register callbacks (e.g. pua module or Aurelien's module?

what is the requests/second rate when the issue appears?

At first look, between sending and setting retransmission timer, there is no much processing for the request. The callback executed there is in use by siptrace, are you using this module?

Cheers, Daniel

...

...

This one got lost, but as I started to fix the other half (replying using proper mode to do retransmission), will investigate this as well ...

Cheers, Daniel

Thanks for the patch.

With 1 call at a time, the bug does not trigger anymore. However, with 2 calls at a time it was triggered again on BYE. Attached log is result of my testing. 1 sipp as uac make 10 calls with 2 simultaneous calls allowed.

The call callid=7-22285-127.0.0.1 request resending of BYE message at 14:21:07.563004, though we have a 200 ok on BYE at 14:21:07.156865 (pid=21493) Bye request (pid=21495) was not finished to be treated at the time 200 ok was received.

This was done with my module active. I'll make new tests without it.

Regards, Aurelien

Daniel-Constantin Mierla a écrit :

... disregard the previous patch, please use this one. It was not the latest. Thanks,

Daniel

On 12/10/08 23:52, Daniel-Constantin Mierla wrote:

...

Hello,

On 12/09/08 20:41, Aurelien Grimaud wrote:

...

Daniel-Constantin Mierla a écrit :

...

On 12/09/08 18:52, Aurelien Grimaud wrote:

...

I am able to reproduce it with 1 call / second without my module on BYE requests. here are traces.

there is a race (at least), indeed. It happens when there is fast reply. I am going to send you a patch soon for testing, you use svn branch 1.4 or the tarball?

Great, I use the kamailio-1.4.2-notls tarball. But I can test any SVN branch / trunk if you wish.

can you test the attached patch with SVN trunk? Let me know the results. Pay attention to see if breaks something else, not just if fixes the reported issue. I let there some debug messages, to help troubleshooting, if the fix is ok, I'll remove them before committing.

Thanks, Daniel

...

Aurelien

...

Cheers, Daniel

...

ps: I added the ms on Logs.

Aurelien

Daniel-Constantin Mierla a écrit :

...

On 12/09/08 17:56, Klaus Darilion wrote:

> Daniel-Constantin Mierla schrieb: > >> Hello, >> >> On 12/09/08 17:31, Klaus Darilion wrote: >> >>> Aurelien Grimaud schrieb: >>> >>> >>>> Fair enough. >>>> If no one already experienced this strange behavior, it >>>> should be my module ... >>>> I'll try to make it again without my module. >>>> >>> See my other email. >>> >>> >>> >>>> However, in the log, after the 200 response, there is a >>>> cleanup_uac_timers: RETR/FR timers reset. >>>> So those timers are cleared. >>>> >>> But the problem is, that the process which handles the INVITE >>> has not finished yet and those (re)SETS the timer. >>> >>> @Daniel - Have you investigated the problem? >>> >> so this is the half of the issue reported via: >> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >> > yes. > > Can it be related to other modules which register callbacks > (e.g. pua module or Aurelien's module? > what is the requests/second rate when the issue appears?

At first look, between sending and setting retransmission timer, there is no much processing for the request. The callback executed there is in use by siptrace, are you using this module?

Cheers, Daniel

>> This one got lost, but as I started to fix the other half >> (replying using proper mode to do retransmission), will >> investigate this as well ... >> >> Cheers, >> Daniel >>

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote:

Answer waiting for approval : logs too big !

Here is a lighter one.

My answer was

...

Thanks for the patch.

With 1 call at a time, the bug does not trigger anymore. However, with 2 calls at a time it was triggered again on BYE. Attached log is result of my testing. 1 sipp as uac make 10 calls with 2 simultaneous calls allowed.

The call callid=7-22285-127.0.0.1 request resending of BYE message at 14:21:07.563004, though we have a 200 ok on BYE at 14:21:07.156865 (pid=21493) Bye request (pid=21495) was not finished to be treated at the time 200 ok was received.

This was done with my module active. I'll make new tests without it.

Regards, Aurelien

Daniel-Constantin Mierla a écrit :

...

... disregard the previous patch, please use this one. It was not the latest. Thanks,

Daniel

On 12/10/08 23:52, Daniel-Constantin Mierla wrote:

...

Hello,

On 12/09/08 20:41, Aurelien Grimaud wrote:

...

Daniel-Constantin Mierla a écrit :

...

On 12/09/08 18:52, Aurelien Grimaud wrote:

...

I am able to reproduce it with 1 call / second without my module on BYE requests. here are traces.

there is a race (at least), indeed. It happens when there is fast reply. I am going to send you a patch soon for testing, you use svn branch 1.4 or the tarball?

Great, I use the kamailio-1.4.2-notls tarball. But I can test any SVN branch / trunk if you wish.

can you test the attached patch with SVN trunk? Let me know the results. Pay attention to see if breaks something else, not just if fixes the reported issue. I let there some debug messages, to help troubleshooting, if the fix is ok, I'll remove them before committing.

Thanks, Daniel

...

Aurelien

...

Cheers, Daniel

...

ps: I added the ms on Logs.

Aurelien

Daniel-Constantin Mierla a écrit :

> On 12/09/08 17:56, Klaus Darilion wrote: > > >> Daniel-Constantin Mierla schrieb: >> >>> Hello, >>> >>> On 12/09/08 17:31, Klaus Darilion wrote: >>> >>>> Aurelien Grimaud schrieb: >>>> >>>> >>>>> Fair enough. >>>>> If no one already experienced this strange behavior, it >>>>> should be my module ... >>>>> I'll try to make it again without my module. >>>>> >>>> See my other email. >>>> >>>> >>>> >>>>> However, in the log, after the 200 response, there is a >>>>> cleanup_uac_timers: RETR/FR timers reset. >>>>> So those timers are cleared. >>>>> >>>> But the problem is, that the process which handles the INVITE >>>> has not finished yet and those (re)SETS the timer. >>>> >>>> @Daniel - Have you investigated the problem? >>>> >>> so this is the half of the issue reported via: >>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>> >> yes. >> >> Can it be related to other modules which register callbacks >> (e.g. pua module or Aurelien's module? >> > what is the requests/second rate when the issue appears? > > At first look, between sending and setting retransmission timer, > there is no much processing for the request. The callback > executed there is in use by siptrace, are you using this module? > > Cheers, > Daniel > >>> This one got lost, but as I started to fix the other half >>> (replying using proper mode to do retransmission), will >>> investigate this as well ... >>> >>> Cheers, >>> Daniel >>>

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

...

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote:

...

Answer waiting for approval : logs too big !

Here is a lighter one.

My answer was

...

Thanks for the patch.

With 1 call at a time, the bug does not trigger anymore. However, with 2 calls at a time it was triggered again on BYE. Attached log is result of my testing. 1 sipp as uac make 10 calls with 2 simultaneous calls allowed.

The call callid=7-22285-127.0.0.1 request resending of BYE message at 14:21:07.563004, though we have a 200 ok on BYE at 14:21:07.156865 (pid=21493) Bye request (pid=21495) was not finished to be treated at the time 200 ok was received.

This was done with my module active. I'll make new tests without it.

Regards, Aurelien

Daniel-Constantin Mierla a écrit :

...

... disregard the previous patch, please use this one. It was not the latest. Thanks,

Daniel

On 12/10/08 23:52, Daniel-Constantin Mierla wrote:

...

Hello,

On 12/09/08 20:41, Aurelien Grimaud wrote:

...

Daniel-Constantin Mierla a écrit :

> On 12/09/08 18:52, Aurelien Grimaud wrote: > >> I am able to reproduce it with 1 call / second without my >> module on BYE requests. >> here are traces. >> > there is a race (at least), indeed. It happens when there is > fast reply. I am going to send you a patch soon for testing, you > use svn branch 1.4 or the tarball? > Great, I use the kamailio-1.4.2-notls tarball. But I can test any SVN branch / trunk if you wish.

can you test the attached patch with SVN trunk? Let me know the results. Pay attention to see if breaks something else, not just if fixes the reported issue. I let there some debug messages, to help troubleshooting, if the fix is ok, I'll remove them before committing.

Thanks, Daniel

...

Aurelien

> Cheers, > Daniel > > > >> ps: I added the ms on Logs. >> >> Aurelien >> >> Daniel-Constantin Mierla a écrit : >> >>> On 12/09/08 17:56, Klaus Darilion wrote: >>> >>> >>>> Daniel-Constantin Mierla schrieb: >>>> >>>>> Hello, >>>>> >>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>> >>>>>> Aurelien Grimaud schrieb: >>>>>> >>>>>> >>>>>>> Fair enough. >>>>>>> If no one already experienced this strange behavior, it >>>>>>> should be my module ... >>>>>>> I'll try to make it again without my module. >>>>>>> >>>>>> See my other email. >>>>>> >>>>>> >>>>>> >>>>>>> However, in the log, after the 200 response, there is a >>>>>>> cleanup_uac_timers: RETR/FR timers reset. >>>>>>> So those timers are cleared. >>>>>>> >>>>>> But the problem is, that the process which handles the >>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>> >>>>>> @Daniel - Have you investigated the problem? >>>>>> >>>>> so this is the half of the issue reported via: >>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>>>> >>>> yes. >>>> >>>> Can it be related to other modules which register callbacks >>>> (e.g. pua module or Aurelien's module? >>>> >>> what is the requests/second rate when the issue appears? >>> >>> At first look, between sending and setting retransmission >>> timer, there is no much processing for the request. The >>> callback executed there is in use by siptrace, are you using >>> this module? >>> >>> Cheers, >>> Daniel >>> >>>>> This one got lost, but as I started to fix the other half >>>>> (replying using proper mode to do retransmission), will >>>>> investigate this as well ... >>>>> >>>>> Cheers, >>>>> Daniel >>>>>

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

Jerome Martin wrote:

Well, then your only onption might be to get a hub and connect an other machine to it running tcpdump/ngrep instead of running it locally. Also, look at your switches, maybe they have port mirriring ?

or try tcpdump -s 0 -w file.pcap port 5060

As this does not cause any console output maybe it does generate less load.

klaus

On Thu, 2008-12-11 at 17:22 +0100, Aurelien Grimaud wrote:

...

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

...

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

...

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote:

...

Answer waiting for approval : logs too big !

Here is a lighter one.

My answer was

...

Thanks for the patch.

With 1 call at a time, the bug does not trigger anymore. However, with 2 calls at a time it was triggered again on BYE. Attached log is result of my testing. 1 sipp as uac make 10 calls with 2 simultaneous calls allowed.

The call callid=7-22285-127.0.0.1 request resending of BYE message at 14:21:07.563004, though we have a 200 ok on BYE at 14:21:07.156865 (pid=21493) Bye request (pid=21495) was not finished to be treated at the time 200 ok was received.

This was done with my module active. I'll make new tests without it.

Regards, Aurelien

Daniel-Constantin Mierla a écrit :

...

... disregard the previous patch, please use this one. It was not the latest. Thanks,

Daniel

On 12/10/08 23:52, Daniel-Constantin Mierla wrote: > Hello, > > On 12/09/08 20:41, Aurelien Grimaud wrote: >> Daniel-Constantin Mierla a écrit : >> >>> On 12/09/08 18:52, Aurelien Grimaud wrote: >>> >>>> I am able to reproduce it with 1 call / second without my >>>> module on BYE requests. >>>> here are traces. >>>> >>> there is a race (at least), indeed. It happens when there is >>> fast reply. I am going to send you a patch soon for testing, you >>> use svn branch 1.4 or the tarball? >>> >> Great, I use the kamailio-1.4.2-notls tarball. >> But I can test any SVN branch / trunk if you wish. >> > can you test the attached patch with SVN trunk? Let me know the > results. Pay attention to see if breaks something else, not just > if fixes the reported issue. I let there some debug messages, to > help troubleshooting, if the fix is ok, I'll remove them before > committing. > > Thanks, > Daniel > >> Aurelien >> >> >>> Cheers, >>> Daniel >>> >>> >>> >>>> ps: I added the ms on Logs. >>>> >>>> Aurelien >>>> >>>> Daniel-Constantin Mierla a écrit : >>>> >>>>> On 12/09/08 17:56, Klaus Darilion wrote: >>>>> >>>>> >>>>>> Daniel-Constantin Mierla schrieb: >>>>>> >>>>>>> Hello, >>>>>>> >>>>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>>>> >>>>>>>> Aurelien Grimaud schrieb: >>>>>>>> >>>>>>>> >>>>>>>>> Fair enough. >>>>>>>>> If no one already experienced this strange behavior, it >>>>>>>>> should be my module ... >>>>>>>>> I'll try to make it again without my module. >>>>>>>>> >>>>>>>> See my other email. >>>>>>>> >>>>>>>> >>>>>>>> >>>>>>>>> However, in the log, after the 200 response, there is a >>>>>>>>> cleanup_uac_timers: RETR/FR timers reset. >>>>>>>>> So those timers are cleared. >>>>>>>>> >>>>>>>> But the problem is, that the process which handles the >>>>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>>>> >>>>>>>> @Daniel - Have you investigated the problem? >>>>>>>> >>>>>>> so this is the half of the issue reported via: >>>>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&group_id=139143&atid=743020 >>>>>>> >>>>>> yes. >>>>>> >>>>>> Can it be related to other modules which register callbacks >>>>>> (e.g. pua module or Aurelien's module? >>>>>> >>>>> what is the requests/second rate when the issue appears? >>>>> >>>>> At first look, between sending and setting retransmission >>>>> timer, there is no much processing for the request. The >>>>> callback executed there is in use by siptrace, are you using >>>>> this module? >>>>> >>>>> Cheers, >>>>> Daniel >>>>> >>>>>>> This one got lost, but as I started to fix the other half >>>>>>> (replying using proper mode to do retransmission), will >>>>>>> investigate this as well ... >>>>>>> >>>>>>> Cheers, >>>>>>> Daniel >>>>>>> >> >> >> >> _______________________________________________ >> Users mailing list >> Users@lists.kamailio.org mailto:Users@lists.kamailio.org >> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >> >> > > ------------------------------------------------------------------------ > > > _______________________________________________ > Users mailing list > Users@lists.kamailio.org mailto:Users@lists.kamailio.org > http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Devel mailing list Devel@lists.kamailio.org mailto:Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

---

Users mailing list Users@lists.kamailio.org mailto:Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

*Jérôme Martin **| **LongPhone* *Responsable Architecture Réseau* 122, rue la Boetie | 75008 Paris Tel : +33 (0)1 56 26 28 44 Fax : +33 (0)1 56 26 28 45 Mail : *jmartin*@longphone.fr Web : www.longphone.com http://www.longphone.com

---

---

Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

Aurelien Grimaud wrote:

Klaus Darilion a écrit :

...

Jerome Martin wrote:

...

Well, then your only onption might be to get a hub and connect an other machine to it running tcpdump/ngrep instead of running it locally. Also, look at your switches, maybe they have port mirriring ?

or try tcpdump -s 0 -w file.pcap port 5060

I tried it with the same result : no bug. All the traffic is local in my case. sipp uac, openser and sipp uas are running on the same host.

I tried with tcpdump -s0 -ilo port 5060, with no better result.

I'll try running sipp on other host, but latency caused by network interface will sure make the bug not show up.

That might be true - in my case the signaling was local too.

regards klaus

Daniel-Constantin Mierla a écrit :

can you try this new patch? It adds a new debug messages for troubleshooting -- you have to revert the previous patch as this one includes it. you can send it to me without ngrep, maybe i can catch it.

First try, without ngrep or tcpdump. BYE for CALL-ID=3-18225-127.0.0.1 is retransmitted.

I'll send the sipp messages but timestamps it provides seems wrong on messages sent.

Aurelien

Thanks, Daniel

On 12/11/08 18:22, Aurelien Grimaud wrote:

...

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

...

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

...

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote:

...

Answer waiting for approval : logs too big !

Here is a lighter one.

My answer was

...

Thanks for the patch.

With 1 call at a time, the bug does not trigger anymore. However, with 2 calls at a time it was triggered again on BYE. Attached log is result of my testing. 1 sipp as uac make 10 calls with 2 simultaneous calls allowed.

The call callid=7-22285-127.0.0.1 request resending of BYE message at 14:21:07.563004, though we have a 200 ok on BYE at 14:21:07.156865 (pid=21493) Bye request (pid=21495) was not finished to be treated at the time 200 ok was received.

This was done with my module active. I'll make new tests without it.

Regards, Aurelien

Daniel-Constantin Mierla a écrit :

...

... disregard the previous patch, please use this one. It was not the latest. Thanks,

Daniel

On 12/10/08 23:52, Daniel-Constantin Mierla wrote: > Hello, > > On 12/09/08 20:41, Aurelien Grimaud wrote: >> Daniel-Constantin Mierla a écrit : >> >>> On 12/09/08 18:52, Aurelien Grimaud wrote: >>> >>>> I am able to reproduce it with 1 call / second without my >>>> module on BYE requests. >>>> here are traces. >>>> >>> there is a race (at least), indeed. It happens when there is >>> fast reply. I am going to send you a patch soon for testing, >>> you use svn branch 1.4 or the tarball? >>> >> Great, I use the kamailio-1.4.2-notls tarball. >> But I can test any SVN branch / trunk if you wish. >> > can you test the attached patch with SVN trunk? Let me know the > results. Pay attention to see if breaks something else, not just > if fixes the reported issue. I let there some debug messages, to > help troubleshooting, if the fix is ok, I'll remove them before > committing. > > Thanks, > Daniel > >> Aurelien >> >> >>> Cheers, >>> Daniel >>> >>> >>> >>>> ps: I added the ms on Logs. >>>> >>>> Aurelien >>>> >>>> Daniel-Constantin Mierla a écrit : >>>> >>>>> On 12/09/08 17:56, Klaus Darilion wrote: >>>>> >>>>> >>>>>> Daniel-Constantin Mierla schrieb: >>>>>> >>>>>>> Hello, >>>>>>> >>>>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>>>> >>>>>>>> Aurelien Grimaud schrieb: >>>>>>>> >>>>>>>> >>>>>>>>> Fair enough. >>>>>>>>> If no one already experienced this strange behavior, it >>>>>>>>> should be my module ... >>>>>>>>> I'll try to make it again without my module. >>>>>>>>> >>>>>>>> See my other email. >>>>>>>> >>>>>>>> >>>>>>>> >>>>>>>>> However, in the log, after the 200 response, there is a >>>>>>>>> cleanup_uac_timers: RETR/FR timers reset. >>>>>>>>> So those timers are cleared. >>>>>>>>> >>>>>>>> But the problem is, that the process which handles the >>>>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>>>> >>>>>>>> @Daniel - Have you investigated the problem? >>>>>>>> >>>>>>> so this is the half of the issue reported via: >>>>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>>>>>> >>>>>> yes. >>>>>> >>>>>> Can it be related to other modules which register callbacks >>>>>> (e.g. pua module or Aurelien's module? >>>>>> >>>>> what is the requests/second rate when the issue appears? >>>>> >>>>> At first look, between sending and setting retransmission >>>>> timer, there is no much processing for the request. The >>>>> callback executed there is in use by siptrace, are you using >>>>> this module? >>>>> >>>>> Cheers, >>>>> Daniel >>>>> >>>>>>> This one got lost, but as I started to fix the other half >>>>>>> (replying using proper mode to do retransmission), will >>>>>>> investigate this as well ... >>>>>>> >>>>>>> Cheers, >>>>>>> Daniel >>>>>>> >> >> >> >> _______________________________________________ >> Users mailing list >> Users@lists.kamailio.org >> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >> >> > > ------------------------------------------------------------------------ > > > _______________________________________________ > Users mailing list > Users@lists.kamailio.org > http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

one question for you, is your system multi-processor?

Cheers, Daniel

On 12/12/08 10:30, Aurelien Grimaud wrote:

Daniel-Constantin Mierla a écrit :

...

can you try this new patch? It adds a new debug messages for troubleshooting -- you have to revert the previous patch as this one includes it. you can send it to me without ngrep, maybe i can catch it.

First try, without ngrep or tcpdump. BYE for CALL-ID=3-18225-127.0.0.1 is retransmitted.

I'll send the sipp messages but timestamps it provides seems wrong on messages sent.

Aurelien

...

Thanks, Daniel

On 12/11/08 18:22, Aurelien Grimaud wrote:

...

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

...

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

...

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote:

...

Answer waiting for approval : logs too big !

Here is a lighter one.

My answer was > Thanks for the patch. > > With 1 call at a time, the bug does not trigger anymore. > However, with 2 calls at a time it was triggered again on BYE. > Attached log is result of my testing. > 1 sipp as uac make 10 calls with 2 simultaneous calls allowed. > > The call callid=7-22285-127.0.0.1 request resending of BYE > message at 14:21:07.563004, though we have a 200 ok on BYE at > 14:21:07.156865 (pid=21493) > Bye request (pid=21495) was not finished to be treated at the > time 200 ok was received. > > This was done with my module active. > I'll make new tests without it. > > Regards, > Aurelien

Daniel-Constantin Mierla a écrit : > ... disregard the previous patch, please use this one. It was > not the latest. Thanks, > > Daniel > > > On 12/10/08 23:52, Daniel-Constantin Mierla wrote: >> Hello, >> >> On 12/09/08 20:41, Aurelien Grimaud wrote: >>> Daniel-Constantin Mierla a écrit : >>> >>>> On 12/09/08 18:52, Aurelien Grimaud wrote: >>>> >>>>> I am able to reproduce it with 1 call / second without my >>>>> module on BYE requests. >>>>> here are traces. >>>>> >>>> there is a race (at least), indeed. It happens when there is >>>> fast reply. I am going to send you a patch soon for testing, >>>> you use svn branch 1.4 or the tarball? >>>> >>> Great, I use the kamailio-1.4.2-notls tarball. >>> But I can test any SVN branch / trunk if you wish. >>> >> can you test the attached patch with SVN trunk? Let me know the >> results. Pay attention to see if breaks something else, not >> just if fixes the reported issue. I let there some debug >> messages, to help troubleshooting, if the fix is ok, I'll >> remove them before committing. >> >> Thanks, >> Daniel >> >>> Aurelien >>> >>> >>>> Cheers, >>>> Daniel >>>> >>>> >>>> >>>>> ps: I added the ms on Logs. >>>>> >>>>> Aurelien >>>>> >>>>> Daniel-Constantin Mierla a écrit : >>>>> >>>>>> On 12/09/08 17:56, Klaus Darilion wrote: >>>>>> >>>>>> >>>>>>> Daniel-Constantin Mierla schrieb: >>>>>>> >>>>>>>> Hello, >>>>>>>> >>>>>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>>>>> >>>>>>>>> Aurelien Grimaud schrieb: >>>>>>>>> >>>>>>>>> >>>>>>>>>> Fair enough. >>>>>>>>>> If no one already experienced this strange behavior, it >>>>>>>>>> should be my module ... >>>>>>>>>> I'll try to make it again without my module. >>>>>>>>>> >>>>>>>>> See my other email. >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>>> However, in the log, after the 200 response, there is a >>>>>>>>>> cleanup_uac_timers: RETR/FR timers reset. >>>>>>>>>> So those timers are cleared. >>>>>>>>>> >>>>>>>>> But the problem is, that the process which handles the >>>>>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>>>>> >>>>>>>>> @Daniel - Have you investigated the problem? >>>>>>>>> >>>>>>>> so this is the half of the issue reported via: >>>>>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>>>>>>> >>>>>>> yes. >>>>>>> >>>>>>> Can it be related to other modules which register >>>>>>> callbacks (e.g. pua module or Aurelien's module? >>>>>>> >>>>>> what is the requests/second rate when the issue appears? >>>>>> >>>>>> At first look, between sending and setting retransmission >>>>>> timer, there is no much processing for the request. The >>>>>> callback executed there is in use by siptrace, are you >>>>>> using this module? >>>>>> >>>>>> Cheers, >>>>>> Daniel >>>>>> >>>>>>>> This one got lost, but as I started to fix the other half >>>>>>>> (replying using proper mode to do retransmission), will >>>>>>>> investigate this as well ... >>>>>>>> >>>>>>>> Cheers, >>>>>>>> Daniel >>>>>>>> >>> >>> >>> >>> _______________________________________________ >>> Users mailing list >>> Users@lists.kamailio.org >>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>> >>> >> >> ------------------------------------------------------------------------ >> >> >> _______________________________________________ >> Users mailing list >> Users@lists.kamailio.org >> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >

---

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

uname -a Linux testg5 2.6.25.14-108.fc9.i686 #1 SMP Mon Aug 4 14:08:11 EDT 2008 i686 i686 i386 GNU/Linux

Daniel-Constantin Mierla a écrit :

On 12/12/08 11:36, Daniel-Constantin Mierla wrote:

...

one question for you, is your system multi-processor?

actually, please give the specs of your system: number of cpu and architecture, os, kernel, ...

Cheers, Daniel

...

Cheers, Daniel

On 12/12/08 10:30, Aurelien Grimaud wrote:

...

Daniel-Constantin Mierla a écrit :

...

can you try this new patch? It adds a new debug messages for troubleshooting -- you have to revert the previous patch as this one includes it. you can send it to me without ngrep, maybe i can catch it.

First try, without ngrep or tcpdump. BYE for CALL-ID=3-18225-127.0.0.1 is retransmitted.

I'll send the sipp messages but timestamps it provides seems wrong on messages sent.

Aurelien

...

Thanks, Daniel

On 12/11/08 18:22, Aurelien Grimaud wrote:

...

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

...

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

> Can you please make the test again and send along with the debug > messages the sip trace? > > ngrep -d any -qt -W byline port 5060 > > I want to check the sip messages as well. > > Thank you, > Daniel > > > On 12/11/08 16:19, Aurelien Grimaud wrote: > >> Answer waiting for approval : logs too big ! >> >> Here is a lighter one. >> >> My answer was >> >>> Thanks for the patch. >>> >>> With 1 call at a time, the bug does not trigger anymore. >>> However, with 2 calls at a time it was triggered again on BYE. >>> Attached log is result of my testing. >>> 1 sipp as uac make 10 calls with 2 simultaneous calls allowed. >>> >>> The call callid=7-22285-127.0.0.1 request resending of BYE >>> message at 14:21:07.563004, though we have a 200 ok on BYE at >>> 14:21:07.156865 (pid=21493) >>> Bye request (pid=21495) was not finished to be treated at the >>> time 200 ok was received. >>> >>> This was done with my module active. >>> I'll make new tests without it. >>> >>> Regards, >>> Aurelien >> Daniel-Constantin Mierla a écrit : >> >>> ... disregard the previous patch, please use this one. It was >>> not the latest. Thanks, >>> >>> Daniel >>> >>> >>> On 12/10/08 23:52, Daniel-Constantin Mierla wrote: >>> >>>> Hello, >>>> >>>> On 12/09/08 20:41, Aurelien Grimaud wrote: >>>> >>>>> Daniel-Constantin Mierla a écrit : >>>>> >>>>> >>>>>> On 12/09/08 18:52, Aurelien Grimaud wrote: >>>>>> >>>>>> >>>>>>> I am able to reproduce it with 1 call / second without my >>>>>>> module on BYE requests. >>>>>>> here are traces. >>>>>>> >>>>>> there is a race (at least), indeed. It happens when there >>>>>> is fast reply. I am going to send you a patch soon for >>>>>> testing, you use svn branch 1.4 or the tarball? >>>>>> >>>>> Great, I use the kamailio-1.4.2-notls tarball. >>>>> But I can test any SVN branch / trunk if you wish. >>>>> >>>> can you test the attached patch with SVN trunk? Let me know >>>> the results. Pay attention to see if breaks something else, >>>> not just if fixes the reported issue. I let there some debug >>>> messages, to help troubleshooting, if the fix is ok, I'll >>>> remove them before committing. >>>> >>>> Thanks, >>>> Daniel >>>> >>>> >>>>> Aurelien >>>>> >>>>> >>>>> >>>>>> Cheers, >>>>>> Daniel >>>>>> >>>>>> >>>>>> >>>>>> >>>>>>> ps: I added the ms on Logs. >>>>>>> >>>>>>> Aurelien >>>>>>> >>>>>>> Daniel-Constantin Mierla a écrit : >>>>>>> >>>>>>> >>>>>>>> On 12/09/08 17:56, Klaus Darilion wrote: >>>>>>>> >>>>>>>> >>>>>>>> >>>>>>>>> Daniel-Constantin Mierla schrieb: >>>>>>>>> >>>>>>>>>> Hello, >>>>>>>>>> >>>>>>>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>>>>>>> >>>>>>>>>>> Aurelien Grimaud schrieb: >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>>> Fair enough. >>>>>>>>>>>> If no one already experienced this strange behavior, >>>>>>>>>>>> it should be my module ... >>>>>>>>>>>> I'll try to make it again without my module. >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>> See my other email. >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>>> However, in the log, after the 200 response, there is >>>>>>>>>>>> a cleanup_uac_timers: RETR/FR timers reset. >>>>>>>>>>>> So those timers are cleared. >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>> But the problem is, that the process which handles the >>>>>>>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>>>>>>> >>>>>>>>>>> @Daniel - Have you investigated the problem? >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> so this is the half of the issue reported via: >>>>>>>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>>>>>>>>> >>>>>>>>> yes. >>>>>>>>> >>>>>>>>> Can it be related to other modules which register >>>>>>>>> callbacks (e.g. pua module or Aurelien's module? >>>>>>>>> >>>>>>>> what is the requests/second rate when the issue appears? >>>>>>>> >>>>>>>> At first look, between sending and setting retransmission >>>>>>>> timer, there is no much processing for the request. The >>>>>>>> callback executed there is in use by siptrace, are you >>>>>>>> using this module? >>>>>>>> >>>>>>>> Cheers, >>>>>>>> Daniel >>>>>>>> >>>>>>>>>> This one got lost, but as I started to fix the other >>>>>>>>>> half (replying using proper mode to do retransmission), >>>>>>>>>> will investigate this as well ... >>>>>>>>>> >>>>>>>>>> Cheers, >>>>>>>>>> Daniel >>>>>>>>>> >>>>> >>>>> _______________________________________________ >>>>> Users mailing list >>>>> Users@lists.kamailio.org >>>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>>>> >>>>> >>>> ------------------------------------------------------------------------ >>>> >>>> >>>> _______________________________________________ >>>> Users mailing list >>>> Users@lists.kamailio.org >>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

>>>>

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

Daniel-Constantin Mierla a écrit :

one question for you, is your system multi-processor?

Yes

cat /proc/cpuinfo

processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 15 model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz stepping : 6 cpu MHz : 2000.180 cache size : 4096 KB physical id : 0 siblings : 2 core id : 0 cpu cores : 2 fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc arch_perfmon pebs bts pni monitor ds_cpl vmx tm2 ssse3 cx16 xtpr dca lahf_lm bogomips : 4002.90 clflush size : 64

processor : 1 vendor_id : GenuineIntel cpu family : 6 model : 15 model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz stepping : 6 cpu MHz : 2000.180 cache size : 4096 KB physical id : 0 siblings : 2 core id : 1 cpu cores : 2 fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc arch_perfmon pebs bts pni monitor ds_cpl vmx tm2 ssse3 cx16 xtpr dca lahf_lm bogomips : 4000.14 clflush size : 64

processor : 2 vendor_id : GenuineIntel cpu family : 6 model : 15 model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz stepping : 6 cpu MHz : 2000.180 cache size : 4096 KB physical id : 3 siblings : 2 core id : 0 cpu cores : 2 fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc arch_perfmon pebs bts pni monitor ds_cpl vmx tm2 ssse3 cx16 xtpr dca lahf_lm bogomips : 4000.18 clflush size : 64

processor : 3 vendor_id : GenuineIntel cpu family : 6 model : 15 model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz stepping : 6 cpu MHz : 2000.180 cache size : 4096 KB physical id : 3 siblings : 2 core id : 1 cpu cores : 2 fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc arch_perfmon pebs bts pni monitor ds_cpl vmx tm2 ssse3 cx16 xtpr dca lahf_lm bogomips : 4000.18 clflush size : 64

Cheers, Daniel

On 12/12/08 10:30, Aurelien Grimaud wrote:

...

Daniel-Constantin Mierla a écrit :

...

can you try this new patch? It adds a new debug messages for troubleshooting -- you have to revert the previous patch as this one includes it. you can send it to me without ngrep, maybe i can catch it.

First try, without ngrep or tcpdump. BYE for CALL-ID=3-18225-127.0.0.1 is retransmitted.

I'll send the sipp messages but timestamps it provides seems wrong on messages sent.

Aurelien

...

Thanks, Daniel

On 12/11/08 18:22, Aurelien Grimaud wrote:

...

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

...

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

...

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote: > Answer waiting for approval : logs too big ! > > Here is a lighter one. > > My answer was >> Thanks for the patch. >> >> With 1 call at a time, the bug does not trigger anymore. >> However, with 2 calls at a time it was triggered again on BYE. >> Attached log is result of my testing. >> 1 sipp as uac make 10 calls with 2 simultaneous calls allowed. >> >> The call callid=7-22285-127.0.0.1 request resending of BYE >> message at 14:21:07.563004, though we have a 200 ok on BYE at >> 14:21:07.156865 (pid=21493) >> Bye request (pid=21495) was not finished to be treated at the >> time 200 ok was received. >> >> This was done with my module active. >> I'll make new tests without it. >> >> Regards, >> Aurelien > > > Daniel-Constantin Mierla a écrit : >> ... disregard the previous patch, please use this one. It was >> not the latest. Thanks, >> >> Daniel >> >> >> On 12/10/08 23:52, Daniel-Constantin Mierla wrote: >>> Hello, >>> >>> On 12/09/08 20:41, Aurelien Grimaud wrote: >>>> Daniel-Constantin Mierla a écrit : >>>> >>>>> On 12/09/08 18:52, Aurelien Grimaud wrote: >>>>> >>>>>> I am able to reproduce it with 1 call / second without my >>>>>> module on BYE requests. >>>>>> here are traces. >>>>>> >>>>> there is a race (at least), indeed. It happens when there is >>>>> fast reply. I am going to send you a patch soon for testing, >>>>> you use svn branch 1.4 or the tarball? >>>>> >>>> Great, I use the kamailio-1.4.2-notls tarball. >>>> But I can test any SVN branch / trunk if you wish. >>>> >>> can you test the attached patch with SVN trunk? Let me know >>> the results. Pay attention to see if breaks something else, >>> not just if fixes the reported issue. I let there some debug >>> messages, to help troubleshooting, if the fix is ok, I'll >>> remove them before committing. >>> >>> Thanks, >>> Daniel >>> >>>> Aurelien >>>> >>>> >>>>> Cheers, >>>>> Daniel >>>>> >>>>> >>>>> >>>>>> ps: I added the ms on Logs. >>>>>> >>>>>> Aurelien >>>>>> >>>>>> Daniel-Constantin Mierla a écrit : >>>>>> >>>>>>> On 12/09/08 17:56, Klaus Darilion wrote: >>>>>>> >>>>>>> >>>>>>>> Daniel-Constantin Mierla schrieb: >>>>>>>> >>>>>>>>> Hello, >>>>>>>>> >>>>>>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>>>>>> >>>>>>>>>> Aurelien Grimaud schrieb: >>>>>>>>>> >>>>>>>>>> >>>>>>>>>>> Fair enough. >>>>>>>>>>> If no one already experienced this strange behavior, >>>>>>>>>>> it should be my module ... >>>>>>>>>>> I'll try to make it again without my module. >>>>>>>>>>> >>>>>>>>>> See my other email. >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>>> However, in the log, after the 200 response, there is >>>>>>>>>>> a cleanup_uac_timers: RETR/FR timers reset. >>>>>>>>>>> So those timers are cleared. >>>>>>>>>>> >>>>>>>>>> But the problem is, that the process which handles the >>>>>>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>>>>>> >>>>>>>>>> @Daniel - Have you investigated the problem? >>>>>>>>>> >>>>>>>>> so this is the half of the issue reported via: >>>>>>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>>>>>>>> >>>>>>>> yes. >>>>>>>> >>>>>>>> Can it be related to other modules which register >>>>>>>> callbacks (e.g. pua module or Aurelien's module? >>>>>>>> >>>>>>> what is the requests/second rate when the issue appears? >>>>>>> >>>>>>> At first look, between sending and setting retransmission >>>>>>> timer, there is no much processing for the request. The >>>>>>> callback executed there is in use by siptrace, are you >>>>>>> using this module? >>>>>>> >>>>>>> Cheers, >>>>>>> Daniel >>>>>>> >>>>>>>>> This one got lost, but as I started to fix the other >>>>>>>>> half (replying using proper mode to do retransmission), >>>>>>>>> will investigate this as well ... >>>>>>>>> >>>>>>>>> Cheers, >>>>>>>>> Daniel >>>>>>>>> >>>> >>>> >>>> >>>> _______________________________________________ >>>> Users mailing list >>>> Users@lists.kamailio.org >>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>>> >>>> >>> >>> ------------------------------------------------------------------------ >>> >>> >>> _______________________________________________ >>> Users mailing list >>> Users@lists.kamailio.org >>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >> >

---

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

Sorry, same thing. CALLID: 1-15931-127.0.0.1

tm was retrieved from svn before applying patch. cd modules mv tm tm.patch2 svn up tm cd .. patch -p0 < ../tm-rb3.diff make all make install openser restart

Aurelien

Daniel-Constantin Mierla a écrit :

Hello,

let's see with this patch. I had no time to test it by myself, so your help is very much appreciated.

You have to revert the previous ones.

Thanks, Daniel

On 12/12/08 11:48, Aurelien Grimaud wrote:

...

...

...

First try, without ngrep or tcpdump. BYE for CALL-ID=3-18225-127.0.0.1 is retransmitted.

Daniel-Constantin Mierla a écrit :

On 12/12/08 13:02, Aurelien Grimaud wrote:

...

Sorry, same thing.

one more, please. see the attached patch (makes no sense to repeat from now on that you have to get the clean snv - no previous patches). thanks for your assistance.

Cheers, Daniel

nope, still retransmitting BYE ...

Aurelien

Daniel-Constantin Mierla a écrit :

On 12/12/08 17:14, Aurelien Grimaud wrote:

...

nope, still retransmitting BYE ...

I tried to narrow down the race time frame, I don't want to introduce new locking there. For the future, this is no longer there (if can be said so), sip-router core layer has some advanced locking system (barriers) and fixes for this issue.

Anyhow, here we are, so try this patch and let me know the result.

Cheers, Daniel

Thanks for the new patch. The race still exists, and I reproduced it (on an INVITE this time). Do not waste any more time on this issue. This race should not trigger on 'normal' use cases. I'll let you know.

Aurelien

Daniel-Constantin Mierla writes:

OK, anyhow, I have to create a testbed to reproduce in order to fix it properly. Thanks for your assistance so far.

daniel,

is this the same bug that i have reported and provided debug on pua PUBLISH retransmissions?

-- juha

Daniel-Constantin Mierla wrote:

one question for you, is your system multi-processor?

FYI: My system (which should similar bug) is a single-processor system.

regards klaus

Cheers, Daniel

On 12/12/08 10:30, Aurelien Grimaud wrote:

...

Daniel-Constantin Mierla a écrit :

...

can you try this new patch? It adds a new debug messages for troubleshooting -- you have to revert the previous patch as this one includes it. you can send it to me without ngrep, maybe i can catch it.

First try, without ngrep or tcpdump. BYE for CALL-ID=3-18225-127.0.0.1 is retransmitted.

I'll send the sipp messages but timestamps it provides seems wrong on messages sent.

Aurelien

...

Thanks, Daniel

On 12/11/08 18:22, Aurelien Grimaud wrote:

...

Well, it seems hard to reproduce with ngrep running .. It seems like the timing is not the same anymore and ngrep slow down the computer just enough for bug not to trigger. I tried many times and the result is that when ngrep is not running, the bug shows up, while wth ngrep it stay hidden. I hope last log from sipp were enough.

However, this retransmission should not disturb the remote user and while nasty race should be handled, this is minor for me. My real problem, concerns transaction module too and is more troubling. This is the one I related in http://lists.kamailio.org/pipermail/users/2008-December/020882.html

I use this timer triggering to fail over another end user and implement serial forking. If the timer triggers while it should not, I will initiate a second call to another destination, which is wrong.

Any idea on this one ?

This is while trying to reproduce it that I found those weird retransmission. I'll try and trigger this initial bug again.

Regards

Aurelien

Aurelien Grimaud a écrit :

...

Sure, meanwhile here are messages provided by sipp UAS side and UAC side. UAC contains only the 10 calls done UAS contains much more as I was trying to reproduce it with 1 call at a time.

Aurelien

Daniel-Constantin Mierla a écrit :

...

Can you please make the test again and send along with the debug messages the sip trace?

ngrep -d any -qt -W byline port 5060

I want to check the sip messages as well.

Thank you, Daniel

On 12/11/08 16:19, Aurelien Grimaud wrote: > Answer waiting for approval : logs too big ! > > Here is a lighter one. > > My answer was >> Thanks for the patch. >> >> With 1 call at a time, the bug does not trigger anymore. >> However, with 2 calls at a time it was triggered again on BYE. >> Attached log is result of my testing. >> 1 sipp as uac make 10 calls with 2 simultaneous calls allowed. >> >> The call callid=7-22285-127.0.0.1 request resending of BYE >> message at 14:21:07.563004, though we have a 200 ok on BYE at >> 14:21:07.156865 (pid=21493) >> Bye request (pid=21495) was not finished to be treated at the >> time 200 ok was received. >> >> This was done with my module active. >> I'll make new tests without it. >> >> Regards, >> Aurelien > > Daniel-Constantin Mierla a écrit : >> ... disregard the previous patch, please use this one. It was >> not the latest. Thanks, >> >> Daniel >> >> >> On 12/10/08 23:52, Daniel-Constantin Mierla wrote: >>> Hello, >>> >>> On 12/09/08 20:41, Aurelien Grimaud wrote: >>>> Daniel-Constantin Mierla a écrit : >>>> >>>>> On 12/09/08 18:52, Aurelien Grimaud wrote: >>>>> >>>>>> I am able to reproduce it with 1 call / second without my >>>>>> module on BYE requests. >>>>>> here are traces. >>>>>> >>>>> there is a race (at least), indeed. It happens when there is >>>>> fast reply. I am going to send you a patch soon for testing, >>>>> you use svn branch 1.4 or the tarball? >>>>> >>>> Great, I use the kamailio-1.4.2-notls tarball. >>>> But I can test any SVN branch / trunk if you wish. >>>> >>> can you test the attached patch with SVN trunk? Let me know the >>> results. Pay attention to see if breaks something else, not >>> just if fixes the reported issue. I let there some debug >>> messages, to help troubleshooting, if the fix is ok, I'll >>> remove them before committing. >>> >>> Thanks, >>> Daniel >>> >>>> Aurelien >>>> >>>> >>>>> Cheers, >>>>> Daniel >>>>> >>>>> >>>>> >>>>>> ps: I added the ms on Logs. >>>>>> >>>>>> Aurelien >>>>>> >>>>>> Daniel-Constantin Mierla a écrit : >>>>>> >>>>>>> On 12/09/08 17:56, Klaus Darilion wrote: >>>>>>> >>>>>>> >>>>>>>> Daniel-Constantin Mierla schrieb: >>>>>>>> >>>>>>>>> Hello, >>>>>>>>> >>>>>>>>> On 12/09/08 17:31, Klaus Darilion wrote: >>>>>>>>> >>>>>>>>>> Aurelien Grimaud schrieb: >>>>>>>>>> >>>>>>>>>> >>>>>>>>>>> Fair enough. >>>>>>>>>>> If no one already experienced this strange behavior, it >>>>>>>>>>> should be my module ... >>>>>>>>>>> I'll try to make it again without my module. >>>>>>>>>>> >>>>>>>>>> See my other email. >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>>> However, in the log, after the 200 response, there is a >>>>>>>>>>> cleanup_uac_timers: RETR/FR timers reset. >>>>>>>>>>> So those timers are cleared. >>>>>>>>>>> >>>>>>>>>> But the problem is, that the process which handles the >>>>>>>>>> INVITE has not finished yet and those (re)SETS the timer. >>>>>>>>>> >>>>>>>>>> @Daniel - Have you investigated the problem? >>>>>>>>>> >>>>>>>>> so this is the half of the issue reported via: >>>>>>>>> https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr... >>>>>>>>> >>>>>>>> yes. >>>>>>>> >>>>>>>> Can it be related to other modules which register >>>>>>>> callbacks (e.g. pua module or Aurelien's module? >>>>>>>> >>>>>>> what is the requests/second rate when the issue appears? >>>>>>> >>>>>>> At first look, between sending and setting retransmission >>>>>>> timer, there is no much processing for the request. The >>>>>>> callback executed there is in use by siptrace, are you >>>>>>> using this module? >>>>>>> >>>>>>> Cheers, >>>>>>> Daniel >>>>>>> >>>>>>>>> This one got lost, but as I started to fix the other half >>>>>>>>> (replying using proper mode to do retransmission), will >>>>>>>>> investigate this as well ... >>>>>>>>> >>>>>>>>> Cheers, >>>>>>>>> Daniel >>>>>>>>> >>>> >>>> >>>> _______________________________________________ >>>> Users mailing list >>>> Users@lists.kamailio.org >>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>>> >>>> >>> ------------------------------------------------------------------------ >>> >>> >>> _______________________________________________ >>> Users mailing list >>> Users@lists.kamailio.org >>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users

---

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

Aurelien Grimaud wrote:

I am able to reproduce it with 1 call / second without my module on BYE requests. here are traces.

ps: I added the ms on Logs.

How? Are you using syslog-ng?

klaus

Aurelien

Daniel-Constantin Mierla a écrit :

...

On 12/09/08 17:56, Klaus Darilion wrote:

...

Daniel-Constantin Mierla schrieb:

...

Hello,

On 12/09/08 17:31, Klaus Darilion wrote:

...

Aurelien Grimaud schrieb:

...

Fair enough. If no one already experienced this strange behavior, it should be my module ... I'll try to make it again without my module.

See my other email.

...

However, in the log, after the 200 response, there is a cleanup_uac_timers: RETR/FR timers reset. So those timers are cleared.

But the problem is, that the process which handles the INVITE has not finished yet and those (re)SETS the timer.

@Daniel - Have you investigated the problem?

so this is the half of the issue reported via: https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr...

yes.

Can it be related to other modules which register callbacks (e.g. pua module or Aurelien's module?

what is the requests/second rate when the issue appears?

At first look, between sending and setting retransmission timer, there is no much processing for the request. The callback executed there is in use by siptrace, are you using this module?

Cheers, Daniel

...

...

This one got lost, but as I started to fix the other half (replying using proper mode to do retransmission), will investigate this as well ...

Cheers, Daniel

...

regards klaus

...

To investigate any further, could you point me where in the source the retransmission timers are cleared ?

Aurelien

Klaus Darilion a écrit :

> Is it also happening WITHOUT your module? > > klaus > > Aurelien Grimaud schrieb: > >> As a matter of fact, I already checked this. >> There is a reply route set before t_relay, and log outputs in it. >> The log line is well seen on 180 and on 200. >> This does not avoid retransmission. >> >> Here is a log file with much trace for a call that was answered >> but retransmitted. >> >> on an INVITE, a module of mine is collecting all contacts for a >> serial forking. >> an on_reply_route is set, with a trace of mine in it >> >> My log format is : >> T000 [date] [time] bin#ser#<pid>#-1 = <log> >> >> This was on a 1 call only. >> I cannot figure out what is happening. >> >> Any comment is welcome. >> >> Thanks ! >> Aurelien >> >> Klaus Darilion a écrit : >> >>> Hi! >>> >>> 1. Not the ACK, but the 200 Ok will stop retransmission. I >>> suspect that the 200 ok is not identified as belonging to the >>> INVITE transaction. >>> >>> Try this: >>> >>> 1. before t_relay() activate a certain reply_route >>> (t_on_reply("3")) >>> 2. put some xlog in the the default reply route >>> >>> onreply_route { >>> xlog("==========================="); >>> xlog("default reply route ...\n"); >>> xlog("response: $$rm = $rm\n"); >>> xlog("response: $mb\n"); >>> xlog("==========================="); >>> } >>> >>> 3. put some xlog in the reply route you activated with >>> t_on_reply() >>> >>> onreply_route[3] { >>> xlog("==========================="); >>> xlog("reply route 3 ...\n"); >>> xlog("response: $$rm = $rm\n"); >>> xlog("response: $mb\n"); >>> xlog("==========================="); >>> } >>> >>> 4. watch the log output >>> >>> If both reply routes are exectued then kamailio successfully >>> matched the reply to the response. If only the default reply >>> route is executed then the transaction matching failed. >>> >>> Try only with a single call (not 1000 calls/s) first. >>> >>> regards >>> klaus >>> >>> Aurelien Grimaud schrieb: >>> >>>> Hi, I am using kamailio 1.4.2 and testing it with sipp. >>>> one sipp is client a uac (port 5066), the other is a uas (port >>>> 5063). >>>> kamailio is using 5060. >>>> >>>> I am generating 100 calls per second for 1000 calls and >>>> message were retransmitted 4 times. >>>> >>>> Here is a tcpdump of sip packets. >>>> Can anyone tell me why there is an INVITE retransmission at >>>> 16:16:38.627198 though the ACK for invite was received at >>>> 16:16:38.126096 ? >>>> Is there a known problem with retransmission timers ? >>>> >>>> 16:16:38.120384 IP 192.168.168.33.5066 > 192.168.168.33.5060: >>>> SIP, length: 579 >>>> E.._..@.@.f....!...!.....K..INVITE sip:otest@testg5 SIP/2.0 >>>> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 70 >>>> Expires: 180 >>>> Subject: Performance Test >>>> Content-Type: application/sdp >>>> Content-Length: 188 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 8925 RTP/AVP 8 101 >>>> a=rtpmap:8 PCMA/8000 >>>> a=rtpmap:101 telephone-event/8000 >>>> a=fmtp:101 0-11,16 >>>> >>>> 16:16:38.123426 IP 192.168.168.33.5060 > 192.168.168.33.5066: >>>> SIP, length: 325 >>>> E..a..@.@.g....!...!.....M..SIP/2.0 100 Giving a try >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;branch=z9hG4bK-23096-730-1;received=192.168.168.33 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Server: Kamailio (1.4.2-notls (i386/linux)) >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:38.123554 IP 192.168.168.33.5060 > 192.168.168.33.5063: >>>> SIP, length: 731 >>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Expires: 180 >>>> Subject: Performance Test >>>> Content-Type: application/sdp >>>> Content-Length: 188 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 8925 RTP/AVP 8 101 >>>> a=rtpmap:8 PCMA/8000 >>>> a=rtpmap:101 telephone-event/8000 >>>> a=fmtp:101 0-11,16 >>>> >>>> 16:16:38.123830 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 451 >>>> E.....@.@.gz...!...!.......pSIP/2.0 180 Ringing >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:38.124169 IP 192.168.168.33.5060 > 192.168.168.33.5066: >>>> SIP, length: 393 >>>> E.....@.@.g....!...!.......6SIP/2.0 180 Ringing >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:38.124326 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 634 >>>> E.....@.@.f....!...!.......'SIP/2.0 200 OK >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Type: application/sdp >>>> Content-Length: 153 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 6004 RTP/AVP 0 8 >>>> a=rtpmap:0 PCMU/8000 >>>> a=rtpmap:8 PCMA/8000 >>>> >>>> 16:16:38.124883 IP 192.168.168.33.5060 > 192.168.168.33.5066: >>>> SIP, length: 581 >>>> E..a..@.@.f....!...!.....M..SIP/2.0 200 OK >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:192.168.168.33:5063 >>>> Content-Type: application/sdp >>>> Content-Length: 153 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 6004 RTP/AVP 0 8 >>>> a=rtpmap:0 PCMU/8000 >>>> a=rtpmap:8 PCMA/8000 >>>> >>>> 16:16:38.125532 IP 192.168.168.33.5066 > 192.168.168.33.5060: >>>> SIP, length: 427 >>>> E.....@.@.g....!...!.......XACK sip:192.168.168.33:5063 SIP/2.0 >>>> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-11 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>> Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 70 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:38.126096 IP 192.168.168.33.5060 > 192.168.168.33.5063: >>>> SIP, length: 521 >>>> E..%..@.@.g,...!...!........ACK sip:192.168.168.33:5063 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:38.627198 IP 192.168.168.33.5060 > 192.168.168.33.5063: >>>> SIP, length: 731 >>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Expires: 180 >>>> Subject: Performance Test >>>> Content-Type: application/sdp >>>> Content-Length: 188 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 8925 RTP/AVP 8 101 >>>> a=rtpmap:8 PCMA/8000 >>>> a=rtpmap:101 telephone-event/8000 >>>> a=fmtp:101 0-11,16 >>>> >>>> 16:16:38.627677 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 474 >>>> E.....@.@.gc...!...!........SIP/2.0 180 Ringing >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut >>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:38.627970 IP 192.168.168.33.5060 > 192.168.168.33.5066: >>>> SIP, length: 416 >>>> E.....@.@.g....!...!.......MSIP/2.0 180 Ringing >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut >>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:39.642356 IP 192.168.168.33.5060 > 192.168.168.33.5063: >>>> SIP, length: 731 >>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Expires: 180 >>>> Subject: Performance Test >>>> Content-Type: application/sdp >>>> Content-Length: 188 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 8925 RTP/AVP 8 101 >>>> a=rtpmap:8 PCMA/8000 >>>> a=rtpmap:101 telephone-event/8000 >>>> a=fmtp:101 0-11,16 >>>> >>>> 16:16:39.642587 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 474 >>>> E.....@.@.gc...!...!........SIP/2.0 180 Ringing >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut >>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:39.643723 IP 192.168.168.33.5060 > 192.168.168.33.5066: >>>> SIP, length: 416 >>>> E.....@.@.g....!...!.......MSIP/2.0 180 Ringing >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut >>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:39.797641 IP 192.168.168.33.5066 > 192.168.168.33.5060: >>>> SIP, length: 434 >>>> E.....@.@.g....!...!......._BYE sip:127.0.0.1:5063 SIP/2.0 >>>> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-46 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 70 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:39.798436 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >>>> length: 528 >>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:39.798535 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 394 >>>> E.....@.@.g....!...!.......7SIP/2.0 200 OK >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:39.798814 IP 192.168.168.33.5060 > 192.168.168.33.5066: >>>> SIP, length: 336 >>>> E..l..@.@.g....!...!.....X..SIP/2.0 200 OK >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:40.257973 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >>>> length: 528 >>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:40.258080 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 394 >>>> E.....@.@.g....!...!.......7SIP/2.0 200 OK >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:41.285493 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >>>> length: 528 >>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:41.285593 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 394 >>>> E.....@.@.g....!...!.......7SIP/2.0 200 OK >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:127.0.0.1:5063 >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:41.695686 IP 192.168.168.33.5060 > 192.168.168.33.5063: >>>> SIP, length: 731 >>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:otest@testg5 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 1 INVITE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Expires: 180 >>>> Subject: Performance Test >>>> Content-Type: application/sdp >>>> Content-Length: 188 >>>> >>>> v=0 >>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>> s=- >>>> c=IN IP4 127.0.0.1 >>>> t=0 0 >>>> m=audio 8925 RTP/AVP 8 101 >>>> a=rtpmap:8 PCMA/8000 >>>> a=rtpmap:101 telephone-event/8000 >>>> a=fmtp:101 0-11,16 >>>> >>>> 16:16:43.338592 IP 192.168.168.33.5060 > 127.0.0.1.5063: SIP, >>>> length: 528 >>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>> Via: SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:sipp@127.0.0.1:5066 >>>> Max-Forwards: 69 >>>> Subject: Performance Test >>>> Content-Length: 0 >>>> >>>> >>>> 16:16:43.338785 IP 192.168.168.33.5063 > 192.168.168.33.5060: >>>> SIP, length: 408 >>>> E.....@.@.g....!...!.......ESIP/2.0 200 OK >>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, >>>> SIP/2.0/UDP >>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>> >>>> From: sipp >>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>> Call-ID: 730-23096-127.0.0.1 >>>> CSeq: 2 BYE >>>> Contact: sip:127.0.0.1:5063;transport=UDP >>>> Content-Length: 0 >>>> >>>> >>>> >>>> >>>> >>>> _______________________________________________ >>>> Users mailing list >>>> Users@lists.kamailio.org >>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>>>

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

Aurelien Grimaud wrote:

Klaus Darilion a écrit :

...

Aurelien Grimaud wrote:

...

I am able to reproduce it with 1 call / second without my module on BYE requests. here are traces.

ps: I added the ms on Logs.

How? Are you using syslog-ng?

slight modification of dprint.h

patches welcome :-)

...

klaus

...

Aurelien

Daniel-Constantin Mierla a écrit :

...

On 12/09/08 17:56, Klaus Darilion wrote:

...

Daniel-Constantin Mierla schrieb:

...

Hello,

On 12/09/08 17:31, Klaus Darilion wrote:

> Aurelien Grimaud schrieb: > > >> Fair enough. >> If no one already experienced this strange behavior, it should >> be my module ... >> I'll try to make it again without my module. >> > See my other email. > > > >> However, in the log, after the 200 response, there is a >> cleanup_uac_timers: RETR/FR timers reset. >> So those timers are cleared. >> > But the problem is, that the process which handles the INVITE has > not finished yet and those (re)SETS the timer. > > @Daniel - Have you investigated the problem? > so this is the half of the issue reported via: https://sourceforge.net/tracker/index.php?func=detail&aid=2105813&gr...

yes.

Can it be related to other modules which register callbacks (e.g. pua module or Aurelien's module?

what is the requests/second rate when the issue appears?

At first look, between sending and setting retransmission timer, there is no much processing for the request. The callback executed there is in use by siptrace, are you using this module?

Cheers, Daniel

...

...

This one got lost, but as I started to fix the other half (replying using proper mode to do retransmission), will investigate this as well ...

Cheers, Daniel

> regards > klaus > > > >> To investigate any further, could you point me where in the >> source the retransmission timers are cleared ? >> >> Aurelien >> >> Klaus Darilion a écrit : >> >>> Is it also happening WITHOUT your module? >>> >>> klaus >>> >>> Aurelien Grimaud schrieb: >>> >>>> As a matter of fact, I already checked this. >>>> There is a reply route set before t_relay, and log outputs in it. >>>> The log line is well seen on 180 and on 200. >>>> This does not avoid retransmission. >>>> >>>> Here is a log file with much trace for a call that was >>>> answered but retransmitted. >>>> >>>> on an INVITE, a module of mine is collecting all contacts for >>>> a serial forking. >>>> an on_reply_route is set, with a trace of mine in it >>>> >>>> My log format is : >>>> T000 [date] [time] bin#ser#<pid>#-1 = <log> >>>> >>>> This was on a 1 call only. >>>> I cannot figure out what is happening. >>>> >>>> Any comment is welcome. >>>> >>>> Thanks ! >>>> Aurelien >>>> >>>> Klaus Darilion a écrit : >>>> >>>>> Hi! >>>>> >>>>> 1. Not the ACK, but the 200 Ok will stop retransmission. I >>>>> suspect that the 200 ok is not identified as belonging to the >>>>> INVITE transaction. >>>>> >>>>> Try this: >>>>> >>>>> 1. before t_relay() activate a certain reply_route >>>>> (t_on_reply("3")) >>>>> 2. put some xlog in the the default reply route >>>>> >>>>> onreply_route { >>>>> xlog("==========================="); >>>>> xlog("default reply route ...\n"); >>>>> xlog("response: $$rm = $rm\n"); >>>>> xlog("response: $mb\n"); >>>>> xlog("==========================="); >>>>> } >>>>> >>>>> 3. put some xlog in the reply route you activated with >>>>> t_on_reply() >>>>> >>>>> onreply_route[3] { >>>>> xlog("==========================="); >>>>> xlog("reply route 3 ...\n"); >>>>> xlog("response: $$rm = $rm\n"); >>>>> xlog("response: $mb\n"); >>>>> xlog("==========================="); >>>>> } >>>>> >>>>> 4. watch the log output >>>>> >>>>> If both reply routes are exectued then kamailio successfully >>>>> matched the reply to the response. If only the default reply >>>>> route is executed then the transaction matching failed. >>>>> >>>>> Try only with a single call (not 1000 calls/s) first. >>>>> >>>>> regards >>>>> klaus >>>>> >>>>> Aurelien Grimaud schrieb: >>>>> >>>>>> Hi, I am using kamailio 1.4.2 and testing it with sipp. >>>>>> one sipp is client a uac (port 5066), the other is a uas >>>>>> (port 5063). >>>>>> kamailio is using 5060. >>>>>> >>>>>> I am generating 100 calls per second for 1000 calls and >>>>>> message were retransmitted 4 times. >>>>>> >>>>>> Here is a tcpdump of sip packets. >>>>>> Can anyone tell me why there is an INVITE retransmission at >>>>>> 16:16:38.627198 though the ACK for invite was received at >>>>>> 16:16:38.126096 ? >>>>>> Is there a known problem with retransmission timers ? >>>>>> >>>>>> 16:16:38.120384 IP 192.168.168.33.5066 > >>>>>> 192.168.168.33.5060: SIP, length: 579 >>>>>> E.._..@.@.f....!...!.....K..INVITE sip:otest@testg5 SIP/2.0 >>>>>> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-1 >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 70 >>>>>> Expires: 180 >>>>>> Subject: Performance Test >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 188 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 8925 RTP/AVP 8 101 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> a=rtpmap:101 telephone-event/8000 >>>>>> a=fmtp:101 0-11,16 >>>>>> >>>>>> 16:16:38.123426 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5066: SIP, length: 325 >>>>>> E..a..@.@.g....!...!.....M..SIP/2.0 100 Giving a try >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;branch=z9hG4bK-23096-730-1;received=192.168.168.33 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Server: Kamailio (1.4.2-notls (i386/linux)) >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:38.123554 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5063: SIP, length: 731 >>>>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Expires: 180 >>>>>> Subject: Performance Test >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 188 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 8925 RTP/AVP 8 101 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> a=rtpmap:101 telephone-event/8000 >>>>>> a=fmtp:101 0-11,16 >>>>>> >>>>>> 16:16:38.123830 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 451 >>>>>> E.....@.@.gz...!...!.......pSIP/2.0 180 Ringing >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:38.124169 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5066: SIP, length: 393 >>>>>> E.....@.@.g....!...!.......6SIP/2.0 180 Ringing >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:38.124326 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 634 >>>>>> E.....@.@.f....!...!.......'SIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 153 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 6004 RTP/AVP 0 8 >>>>>> a=rtpmap:0 PCMU/8000 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> >>>>>> 16:16:38.124883 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5066: SIP, length: 581 >>>>>> E..a..@.@.f....!...!.....M..SIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:192.168.168.33:5063 >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 153 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 6004 RTP/AVP 0 8 >>>>>> a=rtpmap:0 PCMU/8000 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> >>>>>> 16:16:38.125532 IP 192.168.168.33.5066 > >>>>>> 192.168.168.33.5060: SIP, length: 427 >>>>>> E.....@.@.g....!...!.......XACK sip:192.168.168.33:5063 SIP/2.0 >>>>>> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-11 >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>>>> Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 70 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:38.126096 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5063: SIP, length: 521 >>>>>> E..%..@.@.g,...!...!........ACK sip:192.168.168.33:5063 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:38.627198 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5063: SIP, length: 731 >>>>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Expires: 180 >>>>>> Subject: Performance Test >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 188 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 8925 RTP/AVP 8 101 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> a=rtpmap:101 telephone-event/8000 >>>>>> a=fmtp:101 0-11,16 >>>>>> >>>>>> 16:16:38.627677 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 474 >>>>>> E.....@.@.gc...!...!........SIP/2.0 180 Ringing >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut >>>>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:38.627970 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5066: SIP, length: 416 >>>>>> E.....@.@.g....!...!.......MSIP/2.0 180 Ringing >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut >>>>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:39.642356 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5063: SIP, length: 731 >>>>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Expires: 180 >>>>>> Subject: Performance Test >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 188 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 8925 RTP/AVP 8 101 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> a=rtpmap:101 telephone-event/8000 >>>>>> a=fmtp:101 0-11,16 >>>>>> >>>>>> 16:16:39.642587 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 474 >>>>>> E.....@.@.gc...!...!........SIP/2.0 180 Ringing >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.2, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut >>>>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:39.643723 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5066: SIP, length: 416 >>>>>> E.....@.@.g....!...!.......MSIP/2.0 180 Ringing >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-11 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut >>>>>> sip:otest@testg5;tag=17278SIPpTag01696;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:39.797641 IP 192.168.168.33.5066 > >>>>>> 192.168.168.33.5060: SIP, length: 434 >>>>>> E.....@.@.g....!...!......._BYE sip:127.0.0.1:5063 SIP/2.0 >>>>>> Via: SIP/2.0/UDP 127.0.0.1:5066;branch=z9hG4bK-23096-730-46 >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 70 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:39.798436 IP 192.168.168.33.5060 > 127.0.0.1.5063: >>>>>> SIP, length: 528 >>>>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:39.798535 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 394 >>>>>> E.....@.@.g....!...!.......7SIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:39.798814 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5066: SIP, length: 336 >>>>>> E..l..@.@.g....!...!.....X..SIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:40.257973 IP 192.168.168.33.5060 > 127.0.0.1.5063: >>>>>> SIP, length: 528 >>>>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:40.258080 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 394 >>>>>> E.....@.@.g....!...!.......7SIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:41.285493 IP 192.168.168.33.5060 > 127.0.0.1.5063: >>>>>> SIP, length: 528 >>>>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:41.285593 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 394 >>>>>> E.....@.@.g....!...!.......7SIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:127.0.0.1:5063 >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:41.695686 IP 192.168.168.33.5060 > >>>>>> 192.168.168.33.5063: SIP, length: 731 >>>>>> E.....@.@.fZ...!...!........INVITE sip:otest@testg5 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bKcb7d.7c08af34.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-1 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:otest@testg5 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 1 INVITE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Expires: 180 >>>>>> Subject: Performance Test >>>>>> Content-Type: application/sdp >>>>>> Content-Length: 188 >>>>>> >>>>>> v=0 >>>>>> o=user1 53655765 2353687637 IN IP4 127.0.0.1 >>>>>> s=- >>>>>> c=IN IP4 127.0.0.1 >>>>>> t=0 0 >>>>>> m=audio 8925 RTP/AVP 8 101 >>>>>> a=rtpmap:8 PCMA/8000 >>>>>> a=rtpmap:101 telephone-event/8000 >>>>>> a=fmtp:101 0-11,16 >>>>>> >>>>>> 16:16:43.338592 IP 192.168.168.33.5060 > 127.0.0.1.5063: >>>>>> SIP, length: 528 >>>>>> E..,..@.@.P....!............BYE sip:127.0.0.1:5063 SIP/2.0 >>>>>> Record-Route: sip:192.168.168.33;lr=on;ftag=23096SIPpTag09730 >>>>>> Via: SIP/2.0/UDP 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0 >>>>>> Via: SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:sipp@127.0.0.1:5066 >>>>>> Max-Forwards: 69 >>>>>> Subject: Performance Test >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> 16:16:43.338785 IP 192.168.168.33.5063 > >>>>>> 192.168.168.33.5060: SIP, length: 408 >>>>>> E.....@.@.g....!...!.......ESIP/2.0 200 OK >>>>>> Via: SIP/2.0/UDP >>>>>> 192.168.168.33;branch=z9hG4bK9b7d.0423bf25.0, SIP/2.0/UDP >>>>>> 127.0.0.1:5066;received=192.168.168.33;branch=z9hG4bK-23096-730-46 >>>>>> >>>>>> From: sipp >>>>>> sip:730-23096-127.0.0.1@127.0.0.1:5066;tag=23096SIPpTag09730 >>>>>> To: sut sip:service@192.168.168.33:5060;tag=17278SIPpTag01696 >>>>>> Call-ID: 730-23096-127.0.0.1 >>>>>> CSeq: 2 BYE >>>>>> Contact: sip:127.0.0.1:5063;transport=UDP >>>>>> Content-Length: 0 >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> _______________________________________________ >>>>>> Users mailing list >>>>>> Users@lists.kamailio.org >>>>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>>>>> >> > _______________________________________________ > Devel mailing list > Devel@lists.kamailio.org > http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel > >

---

Devel mailing list Devel@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/devel

Daniel-Constantin Mierla wrote:

On 12/09/08 17:56, Klaus Darilion wrote:

...

Can it be related to other modules which register callbacks (e.g. pua module or Aurelien's module?

what is the requests/second rate when the issue appears?

in my case just a single INVITE transaction which triggers sending of PUBLISH via dialog module callbacks.

At first look, between sending and setting retransmission timer, there is no much processing for the request. The callback executed there is in use by siptrace, are you using this module?

no. in my case the pua_dialoginfo module registers the callbacks from dialog module.

tm dialog pua_dialoginfo pua ---->| | | | INV | | | | | | | | <----| | | | 100 | | | | | | | | t_relay | | | | | | | <----| | | | INVI | | | | | | | | |--cb---->| | | | |-----cb----->| | | | |-pua api->| | | | | |<--use tm to send publish---------| | | | | <--- | | | | PUBL | | | | | | | | | | | | ---->| A) | | | PUBL | | | | 200 | | | | | | | | | | | | set B) | | | retransmit | | | timer for | | | PUBLISH | | | | | | |

The problem is similar to Aurelien's problem: The answer to the PUBLISH was received and processed faster (A) then the PUBLISH sending was finished and retransmission timer are set (B).

regards klaus