Trying to use the dialog module to implement calllimits I'm running into a problem when trying to use keep-alives to detect dead dialogs.
Limits work fine without keepalives. But as soon as either dlg_set_property("ka-dst"); or dlg_set_property("ka-src"); are used, after the ka_interval timeout kamailio will start to send OPTIONS as fast as possible. There is no difference in behavior for inbound of outbound calls.
Older threads on this seem to end without solution. Increasing shmem/pkgmem makes no difference. System is running on Debian/stable with deb http://deb.kamailio.org/kamailio wheezy main packages.
# kamailio -V version: kamailio 4.0.0 (x86_64/linux) flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 13:13:24 Mar 29 2013 with gcc 4.7.2
modparam("dialog","dlg_flag",4) modparam("dialog","hash_size",4096) modparam("dialog","enable_stats",1) modparam("dialog","db_url",DBURL) modparam("dialog","db_mode", 2) modparam("dialog","db_update_period", 15) modparam("dialog","profiles_with_value","maxchannels") modparam("dialog","profiles_no_value", "all") modparam("dialog","dlg_match_mode", 1) modparam("dialog","send_bye", 1) modparam("dialog","default_timeout", 43200) modparam("dialog","ka_timer", 15) modparam("dialog","ka_interval", 30)
dlm_manage() uses as:
route[DIALOG] { if (is_method("CANCEL|ACK") || (has_totag() && is_method("INVITE| BYE"))) { dlg_manage(); return; }
if (is_method("INVITE") && !has_totag()) { if($au==$null) { route(MAXCALLSINBOUND); } else { route(MAXCALLSOUTBOUND); }
dlg_manage(); } }
route[MAXCALLSOUTBOUND] { if(method=="INVITE") { if($au && $avp(src_maxchannels)>0) { $var(maxchannels) = 0; get_profile_size("maxchannels", "$au", "$var(maxchannels)");
if($var(maxchannels)>=$avp(src_maxchannels)) { send_reply("403","Call limit reached"); exit; }
set_dlg_profile("maxchannels","$au"); dlg_set_property("ka-src");
get_profile_size("maxchannels", "$au", "$var(maxchannels)"); } }
return; }
MAXCALLSINBOUND is nearly the same but uses $rU instead of $au (and routes to voicemail/redirects if applicable).
Resulting in network traffic:
U +6.719318 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.6baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
# U +0.000041 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.7baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
# U +0.000028 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.8baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
# U +0.000026 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.9baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
[6412 more OPTIONS before hanging up or phone reboots]
syslog output (another call since turning debug on will choke the machine in disk IO to syslog), it keeps repeating stuff like this:
14:19:56 DEBUG: topoh [topoh_mod.c:345]: the COOKIE is [xxx] 14:19:56 DEBUG: dialog [dlg_req_within.c:387]: keep-alive sent to caller 14:19:56 DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x7fb4bfe3d2e0 with 1 -> 2 14:19:56 DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x7fb4bfe3d2e0 with 1 -> 3 14:19:56 DEBUG: dialog [dlg_hash.c:590]: dialog id=7871 found on entry 2710 14:19:56 DEBUG: dialog [dlg_req_within.c:366]: sending BYE to caller 14:19:56 DEBUG: tm [uac.c:243]: DEBUG:tm:t_uac: next_hop=sip: +31880100781@10.0.34.226:27819 14:19:56 DEBUG: tm [uac.c:182]: DEBUG: dlg2hash: 6504 14:19:56 DEBUG: <core> [parser/msg_parser.c:623]: SIP Request: 14:19:56 DEBUG: <core> [parser/msg_parser.c:625]: method: <OPTIONS> 14:19:56 DEBUG: <core> [parser/msg_parser.c:627]: uri: sip: +31880100781@10.0.34.226:27819 14:19:56 DEBUG: <core> [parser/msg_parser.c:629]: version: <SIP/2.0> 14:19:56 DEBUG: <core> [parser/parse_via.c:1284]: Found param type 232, <branch> = <z9hG4bK8691.df660fd1.0>; state=16 14:19:56 DEBUG: <core> [parser/parse_via.c:2672]: end of header reached, state=5 14:19:56 DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=2 14:19:56 DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: this is the first via 14:19:56 DEBUG: <core> [parser/parse_to.c:176]: DEBUG: add_param: tag=a2b76e7ff411361o0 14:19:56 DEBUG: <core> [parser/parse_to.c:799]: end of header reached, state=29 14:19:56 DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:+31880100781@10.0.32.42] 14:19:56 DEBUG: <core> [parser/msg_parser.c:192]: DEBUG: to body [sip: +31880100781@109. 235.32.42] 14:19:56 DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field: cseq <CSeq>: <101> <OPTIONS> 14:19:56 DEBUG: <core> [parser/msg_parser.c:204]: DEBUG: get_hdr_body : content_length=0 14:19:56 DEBUG: <core> [parser/msg_parser.c:106]: found end of header 14:19:56 DEBUG: <core> [parser/parse_to.c:176]: DEBUG: add_param: tag=as23ba5e76 14:19:56 DEBUG: <core> [parser/parse_to.c:799]: end of header reached, state=29
Hello,
can you try the patch from the commit linked next? - http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=a17a32e5...
If all works fine, then I will backport.
Cheers, Daniel
On 6/3/13 2:37 PM, Daniel Tryba wrote:
Trying to use the dialog module to implement calllimits I'm running into a problem when trying to use keep-alives to detect dead dialogs.
Limits work fine without keepalives. But as soon as either dlg_set_property("ka-dst"); or dlg_set_property("ka-src"); are used, after the ka_interval timeout kamailio will start to send OPTIONS as fast as possible. There is no difference in behavior for inbound of outbound calls.
Older threads on this seem to end without solution. Increasing shmem/pkgmem makes no difference. System is running on Debian/stable with deb http://deb.kamailio.org/kamailio wheezy main packages.
# kamailio -V version: kamailio 4.0.0 (x86_64/linux) flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 13:13:24 Mar 29 2013 with gcc 4.7.2
modparam("dialog","dlg_flag",4) modparam("dialog","hash_size",4096) modparam("dialog","enable_stats",1) modparam("dialog","db_url",DBURL) modparam("dialog","db_mode", 2) modparam("dialog","db_update_period", 15) modparam("dialog","profiles_with_value","maxchannels") modparam("dialog","profiles_no_value", "all") modparam("dialog","dlg_match_mode", 1) modparam("dialog","send_bye", 1) modparam("dialog","default_timeout", 43200) modparam("dialog","ka_timer", 15) modparam("dialog","ka_interval", 30)
dlm_manage() uses as:
route[DIALOG] { if (is_method("CANCEL|ACK") || (has_totag() && is_method("INVITE| BYE"))) { dlg_manage(); return; }
if (is_method("INVITE") && !has_totag()) { if($au==$null) { route(MAXCALLSINBOUND); } else { route(MAXCALLSOUTBOUND); } dlg_manage(); }}
route[MAXCALLSOUTBOUND] { if(method=="INVITE") { if($au && $avp(src_maxchannels)>0) { $var(maxchannels) = 0; get_profile_size("maxchannels", "$au", "$var(maxchannels)");
if($var(maxchannels)>=$avp(src_maxchannels)) { send_reply("403","Call limit reached"); exit; } set_dlg_profile("maxchannels","$au"); dlg_set_property("ka-src"); get_profile_size("maxchannels", "$au","$var(maxchannels)"); } }
return;}
MAXCALLSINBOUND is nearly the same but uses $rU instead of $au (and routes to voicemail/redirects if applicable).
Resulting in network traffic:
U +6.719318 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.6baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
# U +0.000041 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.7baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
# U +0.000028 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.8baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
# U +0.000026 10.0.32.42:5060 -> 10.0.34.226:27819 OPTIONS sip:+31880100781@10.0.34.226:27819 SIP/2.0. Via: SIP/2.0/UDP 10.0.32.42;branch=z9hG4bK3548.9baca897.0. To: sip:+31880100781@10.0.32.42;tag=3c64a586e73b0dc9o0. From: sip:0880100705@10.0.32.42;tag=as2b14090d. CSeq: 101 OPTIONS. Call-ID: db688a0a-53e2d315@localhost. Max-Forwards: 70. Content-Length: 0. .
[6412 more OPTIONS before hanging up or phone reboots]
syslog output (another call since turning debug on will choke the machine in disk IO to syslog), it keeps repeating stuff like this:
14:19:56 DEBUG: topoh [topoh_mod.c:345]: the COOKIE is [xxx] 14:19:56 DEBUG: dialog [dlg_req_within.c:387]: keep-alive sent to caller 14:19:56 DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x7fb4bfe3d2e0 with 1 -> 2 14:19:56 DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x7fb4bfe3d2e0 with 1 -> 3 14:19:56 DEBUG: dialog [dlg_hash.c:590]: dialog id=7871 found on entry 2710 14:19:56 DEBUG: dialog [dlg_req_within.c:366]: sending BYE to caller 14:19:56 DEBUG: tm [uac.c:243]: DEBUG:tm:t_uac: next_hop=sip: +31880100781@10.0.34.226:27819 14:19:56 DEBUG: tm [uac.c:182]: DEBUG: dlg2hash: 6504 14:19:56 DEBUG: <core> [parser/msg_parser.c:623]: SIP Request: 14:19:56 DEBUG: <core> [parser/msg_parser.c:625]: method: <OPTIONS> 14:19:56 DEBUG: <core> [parser/msg_parser.c:627]: uri: sip: +31880100781@10.0.34.226:27819 14:19:56 DEBUG: <core> [parser/msg_parser.c:629]: version: <SIP/2.0> 14:19:56 DEBUG: <core> [parser/parse_via.c:1284]: Found param type 232, <branch> = <z9hG4bK8691.df660fd1.0>; state=16 14:19:56 DEBUG: <core> [parser/parse_via.c:2672]: end of header reached, state=5 14:19:56 DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=2 14:19:56 DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: this is the first via 14:19:56 DEBUG: <core> [parser/parse_to.c:176]: DEBUG: add_param: tag=a2b76e7ff411361o0 14:19:56 DEBUG: <core> [parser/parse_to.c:799]: end of header reached, state=29 14:19:56 DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:+31880100781@10.0.32.42] 14:19:56 DEBUG: <core> [parser/msg_parser.c:192]: DEBUG: to body [sip: +31880100781@109. 235.32.42] 14:19:56 DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field: cseq <CSeq>: <101> <OPTIONS> 14:19:56 DEBUG: <core> [parser/msg_parser.c:204]: DEBUG: get_hdr_body : content_length=0 14:19:56 DEBUG: <core> [parser/msg_parser.c:106]: found end of header 14:19:56 DEBUG: <core> [parser/parse_to.c:176]: DEBUG: add_param: tag=as23ba5e76 14:19:56 DEBUG: <core> [parser/parse_to.c:799]: end of header reached, state=29
On Monday 03 June 2013 20:54:41 Daniel-Constantin Mierla wrote:
can you try the patch from the commit linked next?
http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=a17a32e 5f7a3120c200d6e48fe91d7aa1dfd28b1
If all works fine, then I will backport.
Impressions from 45m of testing is that the patch appears to work. OPTIONS flooding went away, OPTIONS are send at specified interval ka_interval after the initial ka_timer timeout. Severed connections are detected and dialogs are removed.
But tomorrow I'll do some more tests.
Thanks for the quick patch.
On Tuesday 04 June 2013 18:20:19 Daniel Tryba wrote:
http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=a17a3 2e 5f7a3120c200d6e48fe91d7aa1dfd28b1
If all works fine, then I will backport.
But tomorrow I'll do some more tests.
It works to send OPTIONS and detect dead endpoints, but the results are not what you expect from the configuration:
modparam("dialog","ka_timer", 10) modparam("dialog","ka_interval", 15)
and dlg_set_property("ka-src");
Results in the first OPTIONS being send after ka_interval time since the OK on te INVITE. Next OPTIONS will be send after 2*ka_timer from then on:
xx:00:00 INVITE -> xx:00:01 200 OK <- xx:00:16 OPTIONS -> xx:00:36 OPTIONS -> xx:00:56 OPTIONS ->
modparam("dialog","ka_timer", 30) modparam("dialog","ka_interval", 60)
xx:00:00 INVITE -> xx:00:01 200 OK <- xx:01:21 OPTIONS -> xx:02:21 OPTIONS -> xx:03:21 OPTIONS ->
Regardless of this doubled ka_timer: ship it :)
-
Daniel Tryba -
Daniel-Constantin Mierla