SIPp issues - seems FS doesn't understand ACK message
Hello, I've been with freeswittch for a while now.. and i can say it is worth developing it. anyhow i got into a strange issue... I'm tryng to see what load FS on my server can take. The Call flow is like this: SIPp FS INVITE --------> <------- 100 Trying <------- 302 Moved Temporary ACK ---------> I use a dummy dialplan for that. All custom functions i've build are disabled and i'm not using it here. Also custom modules are not loaded as well. <extension name="ServiceLookup"> <condition field="destination_number" expression="(^300030)(.*)"> <!--action application="lookup_service_destination" data="in ${caller_id_number:6:16}, in ${caller_id_number:0:6}, in $2, i n $1, in pgw01.ot.hr:5060, out red_contact, out authResult"/--> <action application="log" data="INFO ######################## ServiceLookup ########################\n"/> <action application="log" data="INFO ######################## contact = '${red_contact}' ##############\n"/> <action application="log" data="INFO ######################## CallerNum = '${caller_id_number:6:16}' ##########\n"/> <action application="log" data="INFO ######################## RADIUS auth = '${authResult}' ##########\n"/> <action application="execute_extension" data="doRedirect XML public"/> </condition> </extension> <extension name="doRedirect"> <condition field="destination_number" expression="^doRedirect$"/> <condition field="${authResult}" expression="^0$|^60$"> <action application="log" data="INFO ######################## RADIUS auth OK!!!' ##########\n"/> <!--action application="redirect" data="sip:${red_contact}"/--> <!--action application="answer"/--> <action application="redirect" data=" sip:12345616094191500@pgw01.ot.hr:5060"/> <!--anti-action application="answer"/--> <!--anti-action application="sleep" data="2000"/--> <action application="hangup" data="USER_BUSY"/> <anti-action application="redirect" data=" sip:12345616094191500@pgw01.ot.hr:5060"/> <anti-action application="log" data="INFO ######################## RADIUS auth NOK!! ##########\n"/> <!--anti-action application="respond" data="403 Forbidden"/--> <anti-action application="hangup" data="USER_BUSY"/> </condition> </extension> When i place a call from x-lite everything works fine ... x-lite sends an invite, gets SIP 302 and ACKs it correctly... FS is happy. When i place a call from SIPp i have the same scenario except FS seems not understand ACK message from SIPp and re-sends SIP 302 multiple times untill it gives up. I beleive this is due to 302 resend issue but; when i load FS with 100 CPS, i can see high CPU usage (just one thread taking most load... the rest does almost nothing) on FS. Also, starting from 40 CPS there is a big delay in receiving SIP 302 messages meaning i've sent 6000 calls and so far only for half of them got 302 response. Does anybody have a clue ? Here is a trace taken on FS for calls originated from SIPp (sipp -sn uac 10.4.4.251 -sf uac_redirect.xml -s 30003016094191500 -trace_err -r 1 -rp 100 -trace_msg -inf test.txt -m 1 -l 4000): freeswitch@l01sipindir1> recv 573 bytes from udp/[10.4.4.252]:5060 at 16:44:26.527236: ------------------------------------------------------------------------ INVITE sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>SIP/2.0 Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport Max-Forwards: 70 Contact: <sip:22222238515000403@10.4.4.252<sip%3A22222238515000403@10.4.4.252>
To: "30003016094191500"<sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>
From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 131
v=0 o=user1 53655765 2353687637 IN IP4 10.4.4.252 s=- c=IN IP4 10.4.4.252 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ send 328 bytes to udp/[10.4.4.252]:5060 at 16:44:26.527566: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500"<sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>
Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Content-Length: 0 ------------------------------------------------------------------------ send 722 bytes to udp/[10.4.4.252]:5060 at 16:44:26.535582: ------------------------------------------------------------------------ SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500" <sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251> ;tag=Hr4mHDUeBSNyH Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Contact: <sip:12345616094191500@pgw01.ot.hr:5060> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ recv 383 bytes from udp/[10.4.4.252]:5060 at 16:44:26.535809: ------------------------------------------------------------------------ ACK sip:30003016094191500@10.4.4.251:5060 SIP/2.0 Via: SIP/2.0/UDP 10.4.4.252:5060;branch=z9hG4bK-6962-1-3;rport To: "30003016094191500"<sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>
From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 Call-ID: 1-6962@10.4.4.252 CSeq: 1 ACK Contact: sip:sipp@10.4.4.252:5060 Max-Forwards: 70 Subject: Performance Test Content-Length: 0
------------------------------------------------------------------------ send 722 bytes to udp/[10.4.4.252]:5060 at 16:44:27.037070: ------------------------------------------------------------------------ SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500" <sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251> ;tag=Hr4mHDUeBSNyH Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Contact: <sip:12345616094191500@pgw01.ot.hr:5060> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ send 722 bytes to udp/[10.4.4.252]:5060 at 16:44:28.037063: ------------------------------------------------------------------------ SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500" <sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251> ;tag=Hr4mHDUeBSNyH Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Contact: <sip:12345616094191500@pgw01.ot.hr:5060> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
Tihomir.
Your ACK message must not be valid (dialog matching or something else) so every 1 call will generate 30 retries that are queued up in the sip stack. at 100cps you will be generating this problem 100 times per second and queue up countless unfinished dialogs thus eating up the cpu. On Mon, Aug 24, 2009 at 12:19 PM, Tihomir Culjaga <tculjaga@gmail.com>wrote:
Hello,
I've been with freeswittch for a while now.. and i can say it is worth developing it.
anyhow i got into a strange issue... I'm tryng to see what load FS on my server can take. The Call flow is like this:
SIPp FS
INVITE --------> <------- 100 Trying <------- 302 Moved Temporary ACK --------->
I use a dummy dialplan for that. All custom functions i've build are disabled and i'm not using it here. Also custom modules are not loaded as well.
<extension name="ServiceLookup"> <condition field="destination_number" expression="(^300030)(.*)"> <!--action application="lookup_service_destination" data="in ${caller_id_number:6:16}, in ${caller_id_number:0:6}, in $2, i n $1, in pgw01.ot.hr:5060, out red_contact, out authResult"/--> <action application="log" data="INFO ######################## ServiceLookup ########################\n"/> <action application="log" data="INFO ######################## contact = '${red_contact}' ##############\n"/> <action application="log" data="INFO ######################## CallerNum = '${caller_id_number:6:16}' ##########\n"/> <action application="log" data="INFO ######################## RADIUS auth = '${authResult}' ##########\n"/> <action application="execute_extension" data="doRedirect XML public"/> </condition> </extension>
<extension name="doRedirect"> <condition field="destination_number" expression="^doRedirect$"/> <condition field="${authResult}" expression="^0$|^60$"> <action application="log" data="INFO ######################## RADIUS auth OK!!!' ##########\n"/> <!--action application="redirect" data="sip:${red_contact}"/--> <!--action application="answer"/--> <action application="redirect" data=" sip:12345616094191500@pgw01.ot.hr:5060"/> <!--anti-action application="answer"/--> <!--anti-action application="sleep" data="2000"/--> <action application="hangup" data="USER_BUSY"/> <anti-action application="redirect" data=" sip:12345616094191500@pgw01.ot.hr:5060"/> <anti-action application="log" data="INFO ######################## RADIUS auth NOK!! ##########\n"/> <!--anti-action application="respond" data="403 Forbidden"/--> <anti-action application="hangup" data="USER_BUSY"/> </condition> </extension>
When i place a call from x-lite everything works fine ... x-lite sends an invite, gets SIP 302 and ACKs it correctly... FS is happy.
When i place a call from SIPp i have the same scenario except FS seems not understand ACK message from SIPp and re-sends SIP 302 multiple times untill it gives up.
I beleive this is due to 302 resend issue but; when i load FS with 100 CPS, i can see high CPU usage (just one thread taking most load... the rest does almost nothing) on FS. Also, starting from 40 CPS there is a big delay in receiving SIP 302 messages meaning i've sent 6000 calls and so far only for half of them got 302 response.
Does anybody have a clue ?
Here is a trace taken on FS for calls originated from SIPp (sipp -sn uac 10.4.4.251 -sf uac_redirect.xml -s 30003016094191500 -trace_err -r 1 -rp 100 -trace_msg -inf test.txt -m 1 -l 4000):
freeswitch@l01sipindir1> recv 573 bytes from udp/[10.4.4.252]:5060 at 16:44:26.527236: ------------------------------------------------------------------------ INVITE sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>SIP/2.0 Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport Max-Forwards: 70 Contact: <sip:22222238515000403@10.4.4.252<sip%3A22222238515000403@10.4.4.252>
To: "30003016094191500"<sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>
From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 131
v=0 o=user1 53655765 2353687637 IN IP4 10.4.4.252 s=- c=IN IP4 10.4.4.252 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ send 328 bytes to udp/[10.4.4.252]:5060 at 16:44:26.527566: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500"<sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>
Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Content-Length: 0
------------------------------------------------------------------------ send 722 bytes to udp/[10.4.4.252]:5060 at 16:44:26.535582: ------------------------------------------------------------------------ SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500" <sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251> ;tag=Hr4mHDUeBSNyH Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Contact: <sip:12345616094191500@pgw01.ot.hr:5060> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ recv 383 bytes from udp/[10.4.4.252]:5060 at 16:44:26.535809: ------------------------------------------------------------------------ ACK sip:30003016094191500@10.4.4.251:5060 SIP/2.0 Via: SIP/2.0/UDP 10.4.4.252:5060;branch=z9hG4bK-6962-1-3;rport To: "30003016094191500"<sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251>
From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 Call-ID: 1-6962@10.4.4.252 CSeq: 1 ACK Contact: sip:sipp@10.4.4.252:5060 Max-Forwards: 70 Subject: Performance Test Content-Length: 0
------------------------------------------------------------------------ send 722 bytes to udp/[10.4.4.252]:5060 at 16:44:27.037070: ------------------------------------------------------------------------ SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500" <sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251> ;tag=Hr4mHDUeBSNyH Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Contact: <sip:12345616094191500@pgw01.ot.hr:5060> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ send 722 bytes to udp/[10.4.4.252]:5060 at 16:44:28.037063: ------------------------------------------------------------------------ SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.4.4.252;branch=z9hG4bK-6962-1-0;rport=5060 From: "22222238515000403"<sip:22222238515000403@10.4.4.251<sip%3A22222238515000403@10.4.4.251>
;tag=1 To: "30003016094191500" <sip:30003016094191500@10.4.4.251<sip%3A30003016094191500@10.4.4.251> ;tag=Hr4mHDUeBSNyH Call-ID: 1-6962@10.4.4.252 CSeq: 1 INVITE Contact: <sip:12345616094191500@pgw01.ot.hr:5060> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
Tihomir.
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:213-799-1400
participants (2)
-
Anthony Minessale
-
Tihomir Culjaga