sr-dev December 2021

sr-dev@lists.kamailio.org

11 participants
269 discussions

[kamailio/kamailio] Kamailio 5.4.x dialog profiles functionality dead-lock on certain high-load scenarios (Issue #2923)

by Henning Westerholt

### Description The Kamailio 5.4.x dialog profiles functionality can lead to dead-lock on certain high-load scenarios. The Kamailio dialog profiles are used to track parallel channels for about 200 outgoing PSTN carrier interconnections. During high traffic times (like several thousands parallel calls) the Kamailio server will frequently (e.g. hourly) goes into an end-less loop while executing get_profile_size in the configuration script. This causes the locking for the dialog profiles never be released and Kamailio will stop serving traffic. Internal monitoring tools and RPC commands stay working, as long as they do not touch the dialog functionality. A similar (dedicated) Kamailio setup is used for tracking parallel channels for customers. Here the dead-lock is not observed that frequently, but aparentely also some crashes happens in a much longer time interval. ### Troubleshooting After analysis of the back-traces with GDB the get_profile_size() function was removed from the configuration script. After this change the crash did not happened anymore for several days. #### Reproduction Issue could not be reproduced so far. #### Debugging Data ##### bt 1 (some data removed) (gdb) bt \# 0 0x00007f57cf3b00da in get_profile_size (profile=0x7f50ccbc7e80, value=0x7ffd9928f300) at dlg_profile.c:859 n = 364 i = 12 ph = 0x7f50d3e4b7d0 \# 1 0x00007f57cf419c67 in w_get_profile_size_helper (msg=0x7f57d699d418, profile=0x7f50ccbc7e80, value=0x7ffd9928f300, spd=0x7f57d6916960) at dialog.c:941 \# 2 0x00007f57cf41a459 in w_get_profile_size3 (msg=0x7f57d699d418, profile=0x7f50ccbc7e80, value=0x7f57d6935118, result=0x7f57d6916960) at dialog.c:982 \# 3 0x0000000000463fea in do_action (h=0x7ffd99293610, a=0x7f57d6936488, msg=0x7f57d699d418) at core/action.c:1094 \# 4 0x00000000004711ee in run_actions (h=0x7ffd99293610, a=0x7f57d6936488, msg=0x7f57d699d418) at core/action.c:1581 \# 5 0x000000000046058b in do_action (h=0x7ffd99293610, a=0x7f57d690fda8, msg=0x7f57d699d418) at core/action.c:700 The first back-trace was taking from a running process with gdb. The counter in f0 does not increased that much during this time, probably due the overflow of the loop counter. ##### bt2 (analysis with data structure with gdb scripts) Here the loop counter in f0 showed a really high value. Expected size of dialog profiles hash table: (gdb) p profile->entries[3] $4 = {first = 0x7f9bfd4aad98, content = 2068} (gdb) p profile->entries[7] $3 = {first = 0x7f9c12079f70, content = 784} (gdb) p profile->entries[12] $6 = {first = 0x7f9c02be5d50, content = 7600} (gdb) p profile->entries[14] $2 = {first = 0x7f9bff636de8, content = 6764} hash table bucket 14 shows a lot of corruption and the loop never ends (carrier names and IPs replaced). The list for hash bucket 7 got linked to the list for hash bucket 14: counter 6755: prev 0x7f9c0b9dcde0 - current 0x7f9c02e5b378 - next 0x7f9c0a5f9ba0 - value carrier1-XX.XX - hash 14 counter 6756: prev 0x7f9c02e5b378 - current 0x7f9c0a5f9ba0 - next 0x7f9c0860b968 - value carrier1-XX.XX▒▒▒▒ - hash 14 counter 6757: prev 0x7f9c0a5f9ba0 - current 0x7f9c0860b968 - next 0x7f9bfe3f3a78 - value carrier1-XX.XX▒▒▒▒ - hash 14 counter 6758: prev 0x7f9c0860b968 - current 0x7f9bfe3f3a78 - next 0x7f9c10d977f0 - value carrier1-XX.XX - hash 14 counter 6759: prev 0x7f9bfe3f3a78 - current 0x7f9c10d977f0 - next 0x7f9c0ae198b0 - value carrier2-XX.XX▒▒▒▒ - hash 7 counter 6760: prev 0x7f9c10d977f0 - current 0x7f9c0ae198b0 - next 0x7f9c12079f70 - value carrier3-XX.XX - hash 7 counter 6761: prev 0x7f9c0ae198b0 - current 0x7f9c12079f70 - next 0x7f9c011f2540 - value-carrier2-XX.XX▒▒▒▒ - hash 7 counter 6762: prev 0x7f9c12079f70 - current 0x7f9c011f2540 - next 0x7f9bfff886f0 - value carrier2-XX.XX▒▒▒▒ - hash 7 counter 6763: prev 0x7f9c011f2540 - current 0x7f9bfff886f0 - next 0x7f9c05db00a8 - value carrier3-XX.XX= - hash 7 [...] counter 28270: prev 0x7f9c019d06e8 - current 0x7f9bfaf18290 - next 0x7f9c12c90680 - value carrier2-XX.XX▒▒▒▒ - hash 7 counter 28271: prev 0x7f9bfaf18290 - current 0x7f9c12c90680 - next 0x7f9c086a2b58 - value-carrier2-XX.XX▒▒▒▒ - hash 7 counter 28272: prev 0x7f9c12c90680 - current 0x7f9c086a2b58 - next 0x7f9c0b4f09e8 - value carrier2-XX.XX▒▒▒▒ - hash 7 [...] hash table bucket 7 is still consistent regarding the loop, but already shows initial sign of corruption. There is one item of the list for hash bucket 14 visible: counter 780: prev 0x7f9c0db57ac8 - current 0x7f9c02225700 - next 0x7f9bfbf7db08 - value carrier2-XX.XX▒▒▒▒ - hash 7 counter 781: prev 0x7f9c02225700 - current 0x7f9bfbf7db08 - next 0x7f9c10d977f0 - value carrier1-XX.XX- hash 14 counter 782: prev 0x7f9bfe3f3a78 - current 0x7f9c10d977f0 - next 0x7f9c0ae198b0 - value carrier2-XX.XX▒▒▒▒ - hash 7 counter 783: prev 0x7f9c10d977f0 - current 0x7f9c0ae198b0 - next 0x7f9c12079f70 - value carrier3-XX.XX - hash 7 total size of hash table is 784 #### Log Messages No special log messages observed. #### SIP Traffic SIP traffic looked ok during analysis of the core dumps. ### Possible Solutions * adding additional safe-guards for the get_profile_size function to not access data from other hash buckets * stopping the loop counter after some threshold * finding and fixing the source of the internal data corruption (obviously) * refactoring the dialog modules to use another approach for storing the dialog profile information ### Additional Information * **Kamailio version**: Kamailio 5.4.7, compiled from git repository * **Operating System**: CentOS 7.9 -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2923

2 years, 1 month

[kamailio/kamailio] There is no jwt.so (#2883)

by hance2010

2 years, 2 months

[kamailio/kamailio] db_redis: cluster support (Issue #2977)

by Riccardo-78

### Description At the moment db_redis driver does not support interfacing with a redis cluster. This is a proposal to add support to it. The db_redis module will get a new module parameter to enable cluster support (with default 0 - disabled): ``` modparam("db_redis", "cluster", 1) ``` The redis url used by other modules needs to specify all nodes in the cluster, and must NOT include redis database number (since it's not supported in cluster mode): ``` #!define DBURL_USRLOC "redis://10.0.1.1:6379,10.0.1.2:6379,10.0.1.3:6379" ``` The implementation is going to use the [hiredis-cluster](https://github.com/Nordix/hiredis-cluster) library (BSD license). If cluster mode is not enabled the module will behave like before, i.e. all calls to redis will use hiredis library directly. If you find this proposal sensible, I'll start coding it. Feedback is welcome, of course! -- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2977 You are receiving this because you are subscribed to this thread. Message ID: <kamailio/kamailio/issues/2977(a)github.com>

2 years, 3 months

[kamailio/kamailio] Enable CentOS 7 to build with OpenSSL 1.1.1 package from EPEL (#2779)

by space88man

#### Pre-Submission Checklist - [X] Commit message has the format required by CONTRIBUTING guide - [X] Commits are split per component (core, individual modules, libs, utils, ...) - [X] Each component has a single commit (if not, squash them into one commit) - [X] No commits to README files for modules (changes must be done to docbook files in `doc/` subfolder, the README file is autogenerated) #### Type Of Change - [ ] Small bug fix (non-breaking change which fixes an issue) - [X] New feature (non-breaking change which adds new functionality) - [ ] Breaking change (fix or feature that would change existing functionality) #### Checklist:  - [ ] PR should be backported to stable branches - [X] Tested changes locally - [ ] Related to issue #XXXX (replace XXXX with an open issue number) #### Description EPEL now includes a openssl11 package for CentOS 7. This feature is for users who want to build kamailio-tls with OpenSSL 1.1.1 instead of OpenSSL 1.0.2. It is implemented as a `--with=openssl11` conditional (the default os off), so should not affect/change the regular CentOS 7 builds as distributed by kamailio.org. This is for adventurous users on CentOS 7 willing to maintain their own OpenSSL 1.1.1-enabled TLS package. EPEL dependencies( openssl11-libs, openssl11-devel) are required at runtime and for build. You can view, comment on, or merge this pull request online at: https://github.com/kamailio/kamailio/pull/2779 -- Commit Summary -- * pkg: enable CentOS 7 to build with OpenSSL 1.1.1 -- File Changes -- M pkg/kamailio/obs/kamailio.spec (32) -- Patch Links -- https://github.com/kamailio/kamailio/pull/2779.patch https://github.com/kamailio/kamailio/pull/2779.diff -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/pull/2779

2 years, 3 months

[kamailio/kamailio] Localy generated transaction with dns failover and socket forcing (Issue #2987)

by Dennis

### Description DNS failover do not wok for localy generated transaction when script forcing socket or sets Via parameters with corex via_add_srvid/via_add_xavp_params, in log appear the errors: ``` Dec 24 13:30:17 sbc kamailio[9772]: 10(9800) DEBUG: <core> [core/parser/parse_uri.c:1306]: parse_uri(): bad uri, state 0 parsed: <<F3>gbf> (4) / <<F3>gbf#017^?> (38) Dec 24 13:30:17 sbc kamailio[9772]: 10(9800) ERROR: tm [ut.h:245]: uri2dst2(): bad_uri: [<F3>gbf#017^?] ``` #### Reproduction Config stripped for localize problem: ``` #!define IPADDR_THISNODE "192.168.122.130" #!subst "/IPADDR_THISNODE/192.168.122.130/" #!define MULTIDOMAIN 0 ####### Global Parameters ######### #!define WITH_DEBUG ### LOG Levels: 3=DBG, 2=INFO, 1=NOTICE, 0=WARN, -1=ERR #!ifdef WITH_DEBUG debug=4 log_stderror=yes #!else debug=2 log_stderror=no #!endif memdbg=5 memlog=5 log_facility=LOG_LOCAL0 log_prefix="{$mt $hdr(CSeq) $ci} " /* number of SIP routing processes */ children=8 server_id = 10 xavp_via_params = "via" /* uncomment the next line to disable TCP (default on) */ disable_tcp=yes /* uncomment the next line to disable the auto discovery of local aliases * based on reverse DNS on IPs (default on) */ # auto_aliases=no /* listen on local and anycast addresses */ listen=udp:IPADDR_THISNODE:5060 #### DNS settings use_dns_cache = on # Use KAMAILIO internal DNS cache use_dns_failover = on # Depends on KAMAILIO internal DNS cache #dns_srv_loadbalancing = on # #dns_try_naptr = on # dns_try_naptr = off # dns_retr_time=1 # Time in seconds before retrying a DNS request dns_retr_no=1 # Number of DNS retransmissions before giving up dns_try_ipv6=yes dns_use_search_list=no ####### Modules Section ######## /* set paths to location of modules */ loadmodule "jsonrpcs.so" loadmodule "kex.so" loadmodule "corex.so" loadmodule "tm.so" loadmodule "tmx.so" loadmodule "sl.so" loadmodule "rr.so" loadmodule "pv.so" loadmodule "maxfwd.so" loadmodule "siputils.so" loadmodule "xlog.so" loadmodule "ctl.so" loadmodule "cfg_rpc.so" loadmodule "counters.so" loadmodule "dispatcher.so" # ----------------- setting module-specific parameters --------------- # ----- jsonrpcs params ----- modparam("jsonrpcs", "pretty_format", 1) /* set the path to RPC fifo control file */ # modparam("jsonrpcs", "fifo_name", "/run/kamailio/kamailio_rpc.fifo") /* set the path to RPC unix socket control file */ # modparam("jsonrpcs", "dgram_socket", "/run/kamailio/kamailio_rpc.sock") # ----- tm params ----- # auto-discard branches from previous serial forking leg modparam("tm", "failure_reply_mode", 3) # ----- tm params ----- modparam("tm", "fr_timer", 2000) #modparam("tm", "reparse_on_dns_failover", 0) # ----- dispatcher params ----- modparam("dispatcher", "list_file", "/etc/kamailio/dispatcher.list") modparam("dispatcher", "ds_ping_interval", 10) modparam("dispatcher", "ds_probing_mode", 1) modparam("dispatcher", "ds_probing_threshold", 2) modparam("dispatcher", "ds_ping_method", "OPTIONS") modparam("dispatcher", "outbound_proxy", "sip:proxy") # ----- corex params ----- modparam("corex", "dns_cache", "type=A;name=proxy;addr=192.168.122.129;ttl=3600000;flags=2") modparam("corex", "dns_cache", "type=A;name=proxy;addr=192.168.122.131;ttl=3600000;flags=2") # ----- rr params ----- # set next param to 1 to add value to ;lr param (helps with some UAs) modparam("rr", "enable_full_lr", 0) # do not append from tag to the RR (no need for this script) modparam("rr", "append_fromtag", 0) onsend_route { xinfo(">> onsend_route snd_to=$sndto(ip)\n"); } event_route [tm:local-request] { xlog("L_INFO", ">> Routing locally generated $rm to $ru\n"); xinfo(">> mbu: $mbu"); $fs = "udp:IPADDR_THISNODE:5060"; // This have the same effect as forcing socket // via_add_srvid(1); t_set_fr(1000,250); } ``` disparcher list have only one target: `110 sip:192.168.122.131:5060;transport=udp 0 1` The scenario is simple - dispatcher try to ping target via proxy, config have two "A" records in cache, all work as expected until tm:local-request route modify Via header by setting $fs or one of the corex module functions which set flags FL_ADD_SRVID|FL_ADD_XAVP_VIA_PARAMS|FL_USE_XAVP_VIA_FIELDS, tm in this case (after error as above) decline failover. #### Debugging Data transaction fail log: ``` Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: dispatcher [dispatch.c:3546]: ds_ping_result_helper(): probe all, mode DS_PROBE_ALL Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: dispatcher [dispatch.c:3589]: ds_ping_set(): probing set #110, URI sip:192.168.122.131:5060;transport=udp Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: dispatcher [dispatch.c:3620]: ds_ping_set(): Default ping_from: sip:dispatcher@localhost Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: dispatcher [dispatch.c:3630]: ds_ping_set(): Default outbound proxy: sip:proxy Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: tm [uac.c:457]: t_uac_prepare(): next_hop=<sip:proxy> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/dns_cache.c:527]: _dns_hash_find(): (_sip._udp.proxy(15), 33), h=170 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/dns_cache.c:3050]: dns_srv_resolve_ip(): ("_sip._udp.proxy", 0, 0), ret=-5, ip= Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/dns_cache.c:527]: _dns_hash_find(): (proxy(5), 1), h=878 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/dns_cache.c:2807]: dns_a_resolve(): (proxy, 0) returning 0 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/dns_cache.c:3176]: dns_srv_sip_resolve(): (proxy, 0, 0), ip, ret=0 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: tm [uac.c:158]: dlg2hash(): hashid 55725 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: tm [uac.c:246]: t_run_local_req(): executing event_route[tm:local-request] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request: Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg(): method: <OPTIONS> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg(): uri: <sip:192.168.122.131:5060;transport=udp> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKda9d.ac749307000000000000000000000000.0>; state=16 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) INFO: <script>: >> Routing locally generated OPTIONS to sip:192.168.122.131:5060;transport=udp Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/msg_translator.c:1799]: check_boundaries(): no multi-part body Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) INFO: <script>: >> mbu: OPTIONS sip:192.168.122.131:5060;transport=udp SIP/2.0 Dec 24 13:15:37 sbc kamailio[9772]: Via: SIP/2.0/UDP 192.168.122.130;branch=z9hG4bKda9d.ac749307000000000000000000000000.0 Dec 24 13:15:37 sbc kamailio[9772]: To: <sip:192.168.122.131:5060;transport=udp> Dec 24 13:15:37 sbc kamailio[9772]: From: <sip:dispatcher@localhost>;tag=e92e326f0a937cb326014225217c2c12-5929046b Dec 24 13:15:37 sbc kamailio[9772]: CSeq: 10 OPTIONS Dec 24 13:15:37 sbc kamailio[9772]: Call-ID: 62100fd077a3a243-9799(a)192.168.122.130 Dec 24 13:15:37 sbc kamailio[9772]: Max-Forwards: 70 Dec 24 13:15:37 sbc kamailio[9772]: Content-Length: 0 Dec 24 13:15:37 sbc kamailio[9772]: User-Agent: kamailio (5.5.3 (x86_64/linux)) Dec 24 13:15:37 sbc kamailio[9772]: #015 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: pv [pv_core.c:2703]: pv_set_force_sock(): trying to set send-socket to [udp:192.168.122.130:5060] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 15==15 && [192.168.122.130] == [192.168.122.130] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/socket_info.c:648]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: tm [uac.c:314]: t_run_local_req(): local Via update - new socket: [192.168.122.130] - msg-flags: 0 9(9799) DEBUG: tm [uac.c:340]: t_run_local_req(): apply new updates with Via to sip msg Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/msg_translator.c:1799]: check_boundaries(): no multi-part body Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request: Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg(): method: <OPTIONS> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg(): uri: <sip:192.168.122.131:5060;transport=udp> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKda9d.ac749307000000000000000000000000.0>; state=16 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=10 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [42]; uri=[sip:192.168.122.131:5060;transport=udp] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (42)[<sip:192.168.122.131:5060;transport=udp> Dec 24 13:15:37 sbc kamailio[9772]: ], to tag (0)[] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type 4 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type 5 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <10> <OPTIONS> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID] type 6 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Content-Length] type 12 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [User-Agent] type 28 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request: Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg(): method: <OPTIONS> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg(): uri: <sip:192.168.122.131:5060;transport=udp> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKda9d.ac749307000000000000000000000000.0>; state=16 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=10 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [42]; uri=[sip:192.168.122.131:5060;transport=udp] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (42)[<sip:192.168.122.131:5060;transport=udp> Dec 24 13:15:37 sbc kamailio[9772]: ], to tag (0)[] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type 4 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type 5 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <10> <OPTIONS> Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID] type 6 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: tm [uac.c:189]: uac_refresh_hdr_shortcuts(): cseq: [CSeq: 10] Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) DEBUG: tm [uac.c:685]: send_prepared_request_impl(): uac: 0x7f0f6262b9c8 branch: 0 to 192.168.122.131:5060 Dec 24 13:15:37 sbc kamailio[9772]: 9(9799) INFO: <script>: >> onsend_route snd_to=192.168.122.131 Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: <core> [core/parser/parse_uri.c:1306]: parse_uri(): bad uri, state 0 parsed: <<F3>gbf> (4) / <<F3>gbf#017^?> (38) Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) ERROR: tm [ut.h:245]: uri2dst2(): bad_uri: [<F3>gbf#017^?] Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:1363]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=408 Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:1592]: t_should_relay_response(): rps completed - uas status: 0 branch: 0 Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:2236]: local_reply(): branch=0, save=0, winner=0 Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_reply.c:2275]: local_reply(): local transaction completed 408/0 (totag retr: 0/1024) Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: tm [t_hooks.c:256]: run_trans_callbacks_internal(): DBG: trans=0x7f0f6262b738, callback type 1024, id 0 entered Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: dispatcher [dispatch.c:3491]: ds_options_callback(): OPTIONS-Request was finished with code 408 (to sip:192.168.122.131:5060;transport=udp, group 110) Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: dispatcher [dispatch.c:2973]: ds_update_state(): update state for sip:192.168.122.131:5060;transport=udp in group 110 to 10 Dec 24 13:15:37 sbc kamailio[9772]: 10(9800) DEBUG: dispatcher [dispatch.c:3049]: ds_update_state(): old state was 9, set new state to 9 ``` I think that error somewhere in memory management when allocating/free structures for Via header modification which is hard to debug, i have insert several debug output in uac.c in my case the problem fire after a call of function insert_tmcb: ``` /* Register the callbacks after everything is successful and nothing can fail. Otherwise the callback parameter would be freed twise, once from TMCB_DESTROY, and again because of the negative return code. */ {// extra debug struct ua_client *uac=&request->my_T->uac[0]; LM_DBG(">>>>> Before insert_tmcb\n"); LM_DBG(">>>>> request uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri)); uac=&new_cell->uac[0]; LM_DBG(">>>>> new_cell uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri)); } if(uac_r->cb && insert_tmcb(&(new_cell->tmcb_hl), uac_r->cb_flags, *(uac_r->cb), uac_r->cbp, NULL)!=1){ ret=E_OUT_OF_MEM; LM_ERR("short of tmcb shmem\n"); goto error1; } {// extra debug struct ua_client *uac=&request->my_T->uac[0]; LM_DBG(">>>>> After insert_tmcb\n"); LM_DBG(">>>>> request uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri)); uac=&new_cell->uac[0]; LM_DBG(">>>>> new_cell uac: %p urip: %p uri: %.*s\n", uac, &uac->uri, STR_FMT(&uac->uri)); } ``` In log i see: ``` Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:189]: uac_refresh_hdr_shortcuts(): cseq: [CSeq: 10] Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:591]: t_uac_prepare(): >>>>> Before insert_tmcb Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:592]: t_uac_prepare(): >>>>> request uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: sip:192.168.122.131:5060;transport=udp Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:594]: t_uac_prepare(): >>>>> new_cell uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: sip:192.168.122.131:5060;transport=udp Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:604]: t_uac_prepare(): >>>>> After insert_tmcb Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:605]: t_uac_prepare(): >>>>> request uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: <F3>#007yDr^? Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:607]: t_uac_prepare(): >>>>> new_cell uac: 0x7f72407959c8 urip: 0x7f7240795bd8 uri: <F3>#007yDr^? Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) DEBUG: tm [uac.c:699]: send_prepared_request_impl(): uac: 0x7f72407959c8 branch: 0 to 192.168.122.131:5060 Dec 24 14:36:39 sbc kamailio[12709]: 9(12732) INFO: <script>: >> onsend_route snd_to=192.168.122.131 Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: <core> [core/parser/parse_uri.c:1306]: parse_uri(): bad uri, state 0 parsed: <<F3>#007yD> (4) / <<F3>#007yDr^?> (38) Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) ERROR: tm [ut.h:245]: uri2dst2(): bad_uri: [<F3>#007yDr^?] Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:1363]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=408 Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:1592]: t_should_relay_response(): rps completed - uas status: 0 branch: 0 Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:2236]: local_reply(): branch=0, save=0, winner=0 Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_reply.c:2275]: local_reply(): local transaction completed 408/0 (totag retr: 0/1024) Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: tm [t_hooks.c:256]: run_trans_callbacks_internal(): DBG: trans=0x7f7240795738, callback type 1024, id 0 entered Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:3491]: ds_options_callback(): OPTIONS-Request was finished with code 408 (to sip:192.168.122.131:5060;transport=udp, group 110) Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:2973]: ds_update_state(): update state for sip:192.168.122.131:5060;transport=udp in group 110 to 10 Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:3004]: ds_update_state(): destination did not replied 1 times, threshold 2 Dec 24 14:36:40 sbc kamailio[12709]: 10(12733) DEBUG: dispatcher [dispatch.c:3049]: ds_update_state(): old state was 0, set new state to 10 ``` insert_tmcb have shm_malloc fincion call in the beninig, after this call the content of uri structure is broken. ### Additional Information * **Kamailio Version** - output of `kamailio -v` ``` version: kamailio 5.5.3 (x86_64/linux) 473cef flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. ``` * **Operating System**: ``` Ubuntu 18.04.6 LTS ``` -- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2987 You are receiving this because you are subscribed to this thread. Message ID: <kamailio/kamailio/issues/2987(a)github.com>

2 years, 3 months

[kamailio/kamailio] register using uac module is getting send even if send_socket is not in this listening list of kamailio (#2624)

by Surendra Tiwari

### Description I am uac module with database. uacreg table have the send_socket column. i do have 2 kamailio server running. i want only kamailio-1 should send register to uacreg entries. for this i have used send_socket column with socket of kamailio-1. After this we can see both kamailio server sending registration and that's the problem.  ### Troubleshooting #### Reproduction loadmodule "uac.so" modparam("uac","auth_username_avp","$avp(auser)") modparam("uac","auth_password_avp","$avp(apass)") modparam("uac","auth_realm_avp","$avp(arealm)") modparam("uac", "reg_contact_addr", "EXTERNAL_IP:5060") modparam("uac", "reg_db_url", DBURL) and use send_socket into uacreg with kamailio-1 socket.  #### Debugging Data  ``` (paste your debugging data here) ``` #### Log Messages  ``` (paste your log messages here) ``` #### SIP Traffic  ``` (paste your sip traffic here) ``` ### Possible Solutions  ### Additional Information * **Kamailio Version** - output of `kamailio -v` ``` version: kamailio 5.3.8 (x86_64/linux) flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled with gcc 8.3.0 ``` * **Operating System**:  ``` root@ip-10-0-12-135:/etc/kamailio# uname -a Linux ip-10-0-12-135 5.3.0-1019-aws #21~18.04.1-Ubuntu SMP Mon May 11 12:33:03 UTC 2020 x86_64 GNU/Linux ``` -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2624

2 years, 3 months

[kamailio/kamailio] app_lua: build warning (#2728)

by sergey-safarov

``` which: no lua-config in (/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin) which: no lua-config in (/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin) CC (gcc) [M app_lua.so] app_lua_api.o app_lua_api.c: In function 'lua_sr_kemi_register_libs': app_lua_api.c:1942:2: warning: implicit declaration of function 'luaL_openlib'; did you mean 'luaL_openlibs'? [-Wimplicit-f unction-declaration] 1942 | luaL_openlib(L, "KSR", _sr_crt_KSRMethods, 0); | ^~~~~~~~~~~~ | luaL_openlibs CC (gcc) [M app_lua.so] app_lua_kemi_export.o CC (gcc) [M app_lua.so] app_lua_mod.o LD (gcc) [M app_lua.so] app_lua.so which: no lua-config in (/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin) which: no lua-config in (/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin) CC (gcc) [M app_lua_sr.so] app_lua_sr_api.o app_lua_sr_api.c: In function 'lua_sr_core_openlibs': app_lua_sr_api.c:1614:2: warning: implicit declaration of function 'luaL_openlib'; did you mean 'luaL_openlibs'? [-Wimplici t-function-declaration] 1614 | luaL_openlib(L, "sr", _sr_core_Map, 0); | ^~~~~~~~~~~~ | luaL_openlibs CC (gcc) [M app_lua_sr.so] app_lua_sr_exp.o app_lua_sr_exp.c: In function 'lua_sr_exp_openlibs': app_lua_sr_exp.c:3686:3: warning: implicit declaration of function 'luaL_openlib'; did you mean 'luaL_openlibs'? [-Wimplici t-function-declaration] 3686 | luaL_openlib(L, "sr.sl", _sr_sl_Map, 0); | ^~~~~~~~~~~~ | luaL_openlibs CC (gcc) [M app_lua_sr.so] app_lua_sr_mod.o LD (gcc) [M app_lua_sr.so] app_lua_sr.so ``` -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2728

2 years, 3 months

[kamailio/kamailio] DB_UNIXODBC always reports errors for sql queries with no result set (#2810)

by kdanderso

### Description SQL queries that do not return a result set (such as INSERT, DELETE, UPDATE) always report errors when using db_unixodbc. The query succeeds, but the log indicates a failure. #### Reproduction Use db_unixodbc.so for sql queries. Issue a valid query such as INSERT that is not expected to return a result set. #### Log Messages ERROR: db_unixodbc [res.c:52]: db_unixodbc_get_columns(): no columns returned from the query ERROR: db_unixodbc [res.c:253]: db_unixodbc_convert_result(): getting column names failed ERROR: db_unixodbc [dbase.c:271]: db_unixodbc_store_result(): failed to convert result ERROR: <core> [db_query.c:197]: db_do_raw_query(): error while storing result ERROR: sqlops [sql_api.c:297]: sql_do_query(): cannot do the query [DELETE FROM mytable WHERE id = 1] ### Additional Information Kamailio Version 5.5.0 This issue was also reported to SR-users, but that user did not open an issue. (See https://lists.kamailio.org/pipermail/sr-users/2018-March/100581.html) -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2810

2 years, 4 months

[kamailio/kamailio] server crashes every 10 hours (#2101)

by ekke56

### Description  ### Troubleshooting coredump data below. #### Reproduction  #### Debugging Data  ``` (gdb) bt full #0 0x000000000046ccdd in get_hash1_raw (s=0x5da51296 <Address 0x5da51296 out of bounds>, len=9) at core/hashes.h:109 p = 0x5da51296 <Address 0x5da51296 out of bounds> v = 4100353960 h = 0 #1 0x000000000046cfb6 in str_hash_get (ht=0xa6d6c0 <cnts_hash_table>, key=0x5da51296 <Address 0x5da51296 out of bounds>, len=9) at core/str_hash.h:94 h = 0 e = 0x19 #2 0x000000000046debe in cnt_hash_lookup (group=0x7ffc2db9d7c0, name=0x7eff79693b80) at core/counters.c:420 e = 0x7eff80c48c88 first = 0xbd8191bc2e950d55 cnt_rec = 0x7eff80c48cb0 #3 0x000000000046e752 in counter_lookup_str (handle=0x7ffc2db9d7d0, group=0x7ffc2db9d7c0, name=0x7eff79693b80) at core/counters.c:541 cnt_rec = 0x19 #4 0x00007eff7d65b447 in get_stat (name=0x7eff79693b80) at ../../core/counters.h:197 h = {id = 13} grp = {s = 0x0, len = 0} #5 0x00007eff7d65c113 in statsc_svalue (name=0x7eff79693b80, res=0x7eff79693f4b) at statsc_mod.c:149 stat = 0xd __FUNCTION__ = "statsc_svalue" #6 0x00007eff7d65db79 in statsc_timer (ticks=113205942, param=0x0) at statsc_mod.c:274 sm = 0x7eff79693b70 tn = 1571099286 n = 115 __FUNCTION__ = "statsc_timer" #7 0x00000000005db7f9 in sr_wtimer_exec (ticks=113205942, param=0x0) at core/timer_proc.c:390 wt = 0x7eff80c56f48 wn = 0x0 wp = 0x0 cs = 0 __FUNCTION__ = "sr_wtimer_exec" #8 0x00000000005daa29 in fork_sync_timer (child_id=-1, desc=0x7c8a71 "secondary timer", make_sock=1, f=0x5db4f2 <sr_wtimer_exec>, param=0x0, interval=1000) at core/timer_proc.c:224 pid = 0 ts1 = 1811295077 ts2 = 1000 #9 0x00000000005dbb26 in sr_wtimer_start () at core/timer_proc.c:416 __FUNCTION__ = "sr_wtimer_start" #10 0x0000000000425a33 in main_loop () at main.c:1729 i = 8 pid = 3615 si = 0x0 si_desc = "udp receiver child=7 sock=91.216.86.57:5060\000\377~\000\000@۹-\374\177\000\000\020\207A\000\000\000\000\000\020\336\271-\374\177\000\000\323c{\000\000\000\000\000\031\000\000\000\000\000\000\000\000\000\000\004\000\000\000\000\000\000\200\000\000\000\000\000__:\201\377~\000\000\250\346\260v\377~\000\000\270\314À\377~\000" nrprocs = 8 woneinit = 1 __FUNCTION__ = "main_loop" #11 0x000000000042c72a in main (argc=7, argv=0x7ffc2db9def8) at main.c:2696 cfg_stream = 0x1ee3010 c = -1 r = 0 tmp = 0x7ffc2db9ef2c "" tmp_len = 0 port = 0 proto = 0 options = 0x76a9a0 ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:" ret = -1 ---Type <return> to continue, or q <return> to quit--- info locals seed = 2620966285 rfd = 4 debug_save = 0 debug_flag = 0 dont_fork_cnt = 0 n_lst = 0x2 p = 0x0 st = {st_dev = 20, st_ino = 22346, st_nlink = 2, st_mode = 16832, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1568107728, tv_nsec = 458000000}, st_mtim = { tv_sec = 1571064422, tv_nsec = 57000000}, st_ctim = {tv_sec = 1571064422, tv_nsec = 57000000}, __unused = {0, 0, 0}} __FUNCTION__ = "main" (gdb) list 104 register unsigned v; 105 register unsigned h; 106 107 h=0; 108 109 hash_update_str(s, s+len, p, v, h); 110 return hash_finish(h); 111 } 112 113 ``` #### Log Messages  ``` no relevant messages ``` #### SIP Traffic  ``` seems to be triggered by internal timer ``` ### Possible Solutions  ### Additional Information * **Kamailio Version** - output of `kamailio -v` ``` version: kamailio 5.2.4 (x86_64/linux) 759867 flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, 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_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: 759867 compiled on 12:20:22 Sep 11 2019 with gcc 4.8.5 ``` * **Operating System**:  ``` CentOS Linux release 7.4.1708 (Core) Linux xxx 3.10.0-957.12.2.el7.x86_64 #1 SMP Tue May 14 21:24:32 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux ``` -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2101

2 years, 4 months

[kamailio/kamailio] Infinity read from closed socket (#2658)

by sergey-safarov

### Description I observing a case when Kamailio stop processing calls. What is found: *Lot of connections with CLOSE_WAIT state* ``` [root@sbc-13 ~]# netstat -anp | grep 5060 tcp 129 0 100.85.118.66:5060 0.0.0.0:* LISTEN 56907/kamailio tcp 153 0 100.85.118.66:5060 3.101.84.132:21929 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:32738 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:39084 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:28843 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:57939 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:27823 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:15820 CLOSE_WAIT - tcp 0 0 100.85.118.66:5060 207.244.110.239:11587 ESTABLISHED 56907/kamailio tcp 153 0 100.85.118.66:5060 3.101.84.132:11972 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:57245 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:54344 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:41416 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:3644 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:61657 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:49325 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:65334 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:48657 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:1612 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:7879 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:56626 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:57247 CLOSE_WAIT - tcp 153 0 100.85.118.66:5060 3.101.84.132:30494 CLOSE_WAIT - ``` At this time on two core server, one core loaded 100% and another core is free. And top show ``` %Cpu(s): 29.4 us, 26.5 sy ``` As about 26% CPU cycles proceed kernel call, using `strace` utility I found Kamailio process (with top CSP usage) continusly make thus kernel calls. ``` recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) recvfrom(58, 0x7ffdb46a5ab0, 232, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) ``` *Then I check 58 process file descriptor* ``` [root@sbc-13 ~]# ls -la /proc/56907/fd/58 lrwx------. 1 kamailio kamailio 64 Mar 3 10:49 /proc/56907/fd/58 -> 'socket:[3931924]' ``` *Info about open socket* ``` [root@sbc-13 ~]# lsof -a -p 56907| grep 3931924 kamailio 56907 kamailio 58u IPv4 3931924 0t0 TCP ip-100-85-118-66.us-west-1.compute.internal:sip->207.244.110.239:11495 (ESTABLISHED) ``` *Info about Kamailio 56907 process* ``` [root@sbc-13 ~]# kamcmd core.ps | tail 56903 tcp receiver (generic) child=4 56904 tcp receiver (generic) child=5 56905 tcp receiver (generic) child=6 56906 tcp receiver (generic) child=7 56907 tcp main process ``` Then using gdb I have created core file and back trace here ``` (gdb) bt full #0 0x00007f07d3639b1e in recv () from /lib64/libpthread.so.0 No symbol table info available. #1 0x0000000000528817 in tcpconn_read_haproxy (c=0x7f07ce98d930) at core/tcp_main.c:953 bytes = -1 retval = 0 size = 3454406656 port = 32519 p = 0x7ef068 "" end = 0x7f07d335c4c0 <syslog> "\363\017\036\372H\201\354", <incomplete sequence \330> src_ip = 0x6e9646 <qm_shm_malloc+103> dst_ip = 0x7ffdb46a5c20 v2sig = "\r\n\r\n\000\r\nQUIT\n" hdr = {v1 = {line = "\300\304\065\323\004", '\000' <repeats 11 times>, "\370ؘ\316\004\000\000\000t\251\205\000\000\000\000\000\320[j\264\375\177\000\000\004\331m\000\000\000\000\000\320[j\264\375\177\000\000\306\331m\000\000\000\000\000\b\342u\316\a\177\000\000\000\020\346\315\a\177\000\000\367b\201\000\000\000\000\000y\251\205\000n\004\000\000\260\235\201\000\000\000\000\000\247\227\201"}, v2 = {sig = "\300\304\065\323\004\000\000\000\000\000\000", ver_cmd = 0 '\000', fam = 0 '\000', len = 0, addr = {ip4 = {src_addr = 3466123512, dst_addr = 4, src_port = 43380, dst_port = 133}, ip6 = {src_addr = "\370ؘ\316\004\000\000\000t\251\205\000\000\000\000", dst_addr = "\320[j\264\375\177\000\000\004\331m\000\000\000\000", src_port = 23504, dst_port = 46186}, unx = {src_addr = "\370ؘ\316\004\000\000\000t\251\205\000\000\000\000\000\320[j\264\375\177\000\000\004\331m\000\000\000\000\000\320[j\264\375\177\000\000\306\331m\000\000\000\000\000\b\342u\316\a\177\000\000\000\020\346\315\a\177\000\000\367b\201\000\000\000\000\000y\251\205\000n\004\000\000\260\235\201\000\000\000\000\000\247\227\201\000\000\000\000\000\240C\000\000\000\000\000\000\000\020\346", <incomplete sequence \315>, dst_addr = "\a\177\000\000PB\226\316\a\177\000\000\000\020\346\315\a\177\000\000\274\332\366\312\a\177\000\000Ȧ\351͗\002\000\000\240\370\366\312\a\177\000\000S\342\366\312\a\177\000\000@\342u\316\a\177\000\000\000\000\000\000\000\000P\225\001\000\000\000\000\000\000\000\003\000\000\000\001\b\000\000\300[j\264\375\177\000\000R\031Q\000\000\000\000\000hV\313\322\a\177\000"}}}} __func__ = "tcpconn_read_haproxy" #2 0x0000000000529cc8 in tcpconn_new (sock=58, su=0x7ffdb46a5e00, local_addr=0x7f07d2cb5668, ba=0x7f07d2cb5610, type=2, state=3) at core/tcp_main.c:1164 c = 0x7f07ce98d930 rd_b_size = 16384 ret = 32519 __func__ = "tcpconn_new" #3 0x000000000055194e in handle_new_connect (si=0x7f07d2cb5610) at core/tcp_main.c:4259 su = {s = {sa_family = 2, sa_data = ",\347\317\364n\357\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 59180, sin_addr = {s_addr = 4017026255}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 59180, sin6_flowinfo = 4017026255, sin6_addr = {__in6_u = {__u6_addr8 = "\000\000\000\000\000\000\000\000h\360~\000\000\000\000", __u6_addr16 = {0, 0, 0, 0, 61544, 126, 0, 0}, __u6_addr32 = {0, 0, 8319080, 0}}}, sin6_scope_id = 67108864}, sas = {ss_family = 2, __ss_padding = ",\347\317\364n\357\000\000\000\000\000\000\000\000h\360~\000\000\000\000\000\000\000\000\004\000\000\000\000\360^j\264\375\177\000\000\023FU\000\000\000\000\000\230_\226\316\a\177\000\000\300\225\264\000\000\000\000\000\377\377\377\377\001\000\000\000\060٘\316\a\177\000\000\060٘\316\a\177\000\000\377\377\377\377\377\377\377\377\220^j\264\375\177\000\000\000\000\000\000\000\000\000\000\300\304\065\323\a\177\000", __ss_align = 8235966803625406752}} sock_name = {s = {sa_family = 23984, sa_data = "j\264\375\177\000\000\376\023Q\000\000\000\000"}, sin = {sin_family = 23984, sin_port = 46186, sin_addr = {s_addr = 32765}, sin_zero = "\376\023Q\000\000\000\000"}, sin6 = {sin6_family = 23984, sin6_port = 46186, sin6_flowinfo = 32765, sin6_addr = {__in6_u = {__u6_addr8 = "\376\023Q\000\000\000\000\000\310ژ\316\a\177\000", __u6_addr16 = {5118, 81, 0, 0, 56008, 52888, 32519, 0}, __u6_addr32 = {5313534, 0, 3466123976, 32519}}}, sin6_scope_id = 3454980136}, sas = {ss_family = 23984, __ss_padding = "j\264\375\177\000\000\376\023Q\000\000\000\000\000\310ژ\316\a\177\000\000(\320\356\315\a\177\000\000\030\"\202\000_\376\377\377\000\000\000\000\000\000\000\000\300\304\065\323\a\177\000\000\363:\204\000\000\000\000\000h\360~\000\000\000\000\000\000\000\000\004\000\000\000\000\360^j\264\375\177\000\000\245\222T\000\000\000\000\000\250\376\314\322\002\000\000\000\000\000\000\000\002\000\000\000Dc\201\000\241\001\000", __ss_align = 0}} sock_name_len = 32519 dst_su = 0x7f07d2cb5668 tcpconn = 0xffffffffce98d930 su_len = 16 new_sock = 58 __func__ = "handle_new_connect" #4 0x0000000000554aac in handle_io (fm=0x7f07d2ccfa40, ev=1, idx=-1) at core/tcp_main.c:4517 ret = 16 __func__ = "handle_io" #5 0x000000000051c992 in io_wait_loop_epoll (h=0xaf4760 <io_h>, t=5, repeat=0) at core/io_wait.h:1070 n = 1 r = 0 fm = 0x7f07d2ccfa40 revents = 1 __func__ = "io_wait_loop_epoll" #6 0x000000000055800f in tcp_main_loop () at core/tcp_main.c:4808 si = 0x0 r = 8 __func__ = "tcp_main_loop" #7 0x000000000042ca0b in main_loop () at main.c:1788 i = 8 pid = 0 si = 0x0 si_desc = "udp receiver child=7 sock=[2600:1f1c:6d5:aa03::7]:5060\000\061\063\062:5060)\000\000\000\000\060\000\000\000\370bj\264\375\177\000\000\020bj\264\375\177\000\000\000\334ѯ\344lFߨE\201\000\000\000\000\000\250\203\306\322k\000\000\000\363:\204\000\000\000\000\000\270o\305\322\a\177\000" nrprocs = 8 woneinit = 1 __func__ = "main_loop" #8 0x0000000000435d95 in main (argc=11, argv=0x7ffdb46a6828) at main.c:2895 cfg_stream = 0x156b2a0 c = -1 r = 0 tmp = 0x7ffdb46a6ee3 "" tmp_len = 0 port = 0 proto = 0 ahost = 0x0 aport = 0 options = 0x7f1e48 ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:" ret = -1 seed = 2702569434 rfd = 4 debug_save = 0 debug_flag = 0 dont_fork_cnt = 2 n_lst = 0x7ffdb46d4268 p = 0x7f07d3309db5 <handle_intel.constprop+197> "H\205\300uf\213t$\004M\215\216\244" st = {st_dev = 24, st_ino = 19244, st_nlink = 2, st_mode = 16832, st_uid = 985, st_gid = 979, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1613817804, tv_nsec = 114998890}, st_mtim = {tv_sec = 1614768566, tv_nsec = 7667804}, st_ctim = {tv_sec = 1614768566, tv_nsec = 7667804}, __glibc_reserved = {0, 0, 0}} tbuf = '\000' <repeats 16 times>, "\214\344'\323\a\177\000\000\330Am\264\375\177\000\000\000\000\000\000 ", '\000' <repeats 19 times>, "X_\376\323\a\177\000\000\000ej\264\375\177\000\000\a\000\000\000\000\000\000\000\020U\376\323\a\177\000\000\a\000\000\000\t\000\000\000\210\351 \324\a\177\000\000\034\021\377\323\a\177\000\000\000\000\000\000\000\000\000\000H\037\377\323\a\177\000\000Pdj\264\375\177\000\000\260\344'\323\a\177\000\000\300\363\037\324\a\177\000\000\000\000\000\000\000\000\000\000\320dj\264\375\177", '\000' <repeats 26 times>, "\200W\376\323\a\177\000\000"... option_index = 12 long_options = {{name = 0x7f4056 "help", has_arg = 0, flag = 0x0, val = 104}, {name = 0x7ef4e1 "version", has_arg = 0, flag = 0x0, val = 118}, {name = 0x7f405b "alias", has_arg = 1, flag = 0x0, val = 1024}, {name = 0x7f4061 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name = 0x7f4067 "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x7f4070 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x7f407a "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x7f4084 "loadmodule", has_arg = 1, flag = 0x0, val = 1029}, {name = 0x7f408f "modparam", has_arg = 1, flag = 0x0, val = 1030}, {name = 0x7f4098 "log-engine", has_arg = 1, flag = 0x0, val = 1031}, {name = 0x7f40a3 "debug", has_arg = 1, flag = 0x0, val = 1032}, {name = 0x7f40a9 "cfg-print", has_arg = 0, flag = 0x0, val = 1033}, {name = 0x7f40b3 "atexit", has_arg = 1, flag = 0x0, val = 1034}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}} __func__ = "main" ``` We use enabled haproxy protocol. Loos as Kamailio does not properly close the socket when the socket closed on the client-side. ### Additional Information * **Kamailio Version** - output of `kamailio -v` ``` [root@sbc-13 ~]# kamailio -v version: kamailio 5.5.0-dev4 (x86_64/linux) 06656a flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: 06656a compiled on 04:01:58 Mar 1 2021 with gcc 8.3.1 ``` * **Operating System**: ``` [root@sbc-13 ~]# cat /etc/os-release NAME="CentOS Linux" VERSION="8" ID="centos" ID_LIKE="rhel fedora" VERSION_ID="8" PLATFORM_ID="platform:el8" PRETTY_NAME="CentOS Linux 8" ANSI_COLOR="0;31" CPE_NAME="cpe:/o:centos:centos:8" HOME_URL="https://centos.org/" BUG_REPORT_URL="https://bugs.centos.org/" CENTOS_MANTISBT_PROJECT="CentOS-8" CENTOS_MANTISBT_PROJECT_VERSION="8" ``` -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2658

2 years, 4 months

← Newer
1
...
6
7
8
9
10
11
12
...
27
Older →

Jump to page:

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

sr-dev December 2021