Memory leak after SIP message fails to be sent due to no socket found

[pwakano]

Description

When SIP message fails to be sent due to no socket found, apparently the TM module is not deleting the transaction and so it is causing a memory leak.

Troubleshooting

Reproduction

The easiest way to reproduce the problem is to setup a dispatcher destination with SIP ping enabled. Kamailio should not be listening to the interface which is used to reach that destination. So this will cause Kamailio to complain about not finding a socket to send the OPTIONS.
After this happens, it is possible to see from the kamcmd tm.stats command that the "created" has increased by 1, freed has not changed and "delayed_free" also increased by 1.
Problem is that the delayed_free never gets freed and after checking the kamcmd core.shmmem, for every failed OPTIONS request under this condition, 5808 bits are leaked...
This goes on until there is no shared memory left.....

Debugging Data

Log Messages

 /usr/sbin/kamailio[20755]: DEBUG: dispatcher [dispatch.c:2664]: ds_ping_set(): probing set #2, URI sip:10.11.12.13:6060
 /usr/sbin/kamailio[20755]: DEBUG: tm [uac.c:427]: t_uac_prepare(): next_hop=<sip:10.11.12.13:6060>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/resolve.c:1225]: srv_sip_resolvehost(): 10.11.12.13:6060 proto=0
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/resolve.c:1346]: srv_sip_resolvehost(): returning 0xada520 (10.11.12.13:6060 proto=1)
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/forward.c:174]: get_out_socket(): socket determined: 0x7f33189ee298
 /usr/sbin/kamailio[20755]: DEBUG: tm [uac.c:152]: dlg2hash(): hashid 8554
 /usr/sbin/kamailio[20755]: DEBUG: tm [uac.c:238]: t_run_local_req(): executing event_route[tm:local-request]
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <OPTIONS>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:10.11.12.13:6060>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKa612.f9317e75000000000000000000000000.0>; state=16
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [25]; uri=[sip:10.11.12.13:6060]
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:10.11.12.13:6060>#015#012]
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <OPTIONS>
 /usr/sbin/kamailio[20755]: DEBUG: pv [pv_trans.c:564]: tr_eval_string(): i=0 j=10
 /usr/sbin/kamailio[20755]: NOTICE: <script>: [479309551f] OPTIONS: Local Request to sip:10.11.12.13:6060 - sip:10.11.12.13:6060
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_cseq.c:115]: dlg_cseq_prepare_new_msg(): prepare new msg for cseq update operations
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <OPTIONS>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:10.11.12.13:6060>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKa612.f9317e75000000000000000000000000.0>; state=16
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_cseq.c:59]: dlg_cseq_prepare_msg(): prepare msg for cseq update operations
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [25]; uri=[sip:10.11.12.13:6060]
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:10.11.12.13:6060>#015#012]
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <OPTIONS>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=744e9d847dad9acc2d5178ac65520eba-8cc2
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_cseq.c:382]: dlg_cseq_msg_sent(): traking cseq updates
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_hash.c:766]: internal_get_dlg(): no dialog callid='479309551fdf88bf-20755@55.66.77.88' found
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_hash.c:797]: get_dlg(): no dialog callid='479309551fdf88bf-20755@55.66.77.88' found
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_handlers.c:1202]: dlg_lookup_msg_dialog(): dlg with callid '479309551fdf88bf-20755@55.66.77.88' not found
 /usr/sbin/kamailio[20755]: DEBUG: dialog [dlg_cseq.c:394]: dlg_cseq_msg_sent(): no dialog for this request
 /usr/sbin/kamailio[20755]: DEBUG: tm [uac.c:638]: send_prepared_request_impl(): uac: 0x7f331184c5f8  branch: 0  to 10.11.12.13:6060
 /usr/sbin/kamailio[20755]: DEBUG: tm [../../core/onsend.h:69]: run_onsend(): required parameters are not available - ignoring
 /usr/sbin/kamailio[20755]: DEBUG: dispatcher [dispatch.c:2664]: ds_ping_set(): probing set #1, URI sip:12.34.56.78:6060
 /usr/sbin/kamailio[20755]: DEBUG: tm [uac.c:427]: t_uac_prepare(): next_hop=<sip:12.34.56.78:6060>
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/resolve.c:1225]: srv_sip_resolvehost(): 12.34.56.78:6060 proto=0
 /usr/sbin/kamailio[20755]: DEBUG: <core> [core/resolve.c:1346]: srv_sip_resolvehost(): returning 0xada520 (12.34.56.78:6060 proto=1)
 /usr/sbin/kamailio[20755]: ERROR: <core> [core/forward.c:181]: get_out_socket(): no socket found
 /usr/sbin/kamailio[20755]: ERROR: <core> [core/forward.c:183]: get_out_socket(): no corresponding socket found for(udp:12.34.56.78:6060)
 /usr/sbin/kamailio[20755]: ERROR: tm [ut.h:317]: uri2dst2(): no corresponding socket found for "12.34.56.78" af 2 (udp:12.34.56.78:6060)
 /usr/sbin/kamailio[20755]: ERROR: tm [uac.c:449]: t_uac_prepare(): no socket found
 /usr/sbin/kamailio[20755]: ERROR: dispatcher [dispatch.c:2683]: ds_ping_set(): unable to ping [sip:12.34.56.78:6060]

Real IPs were replaced, this is their usage:
10.11.12.13 = Kamailio listening IP in local network interface
12.34.56.78 = destination SIP trunk which does not have a matching listened socket by Kamailio
55.66.77.88 = Kamailio listening IP in public network interface

SIP Traffic

Possible Solutions

Additional Information

• Kamailio Version - output of kamailio -v

# kamailio -v
version: kamailio 5.0.6 (x86_64/linux) 
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, 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_LISTEN 16, 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 on 04:19:46 Mar 30 2018 with gcc 4.8.5

• Operating System:

# cat /etc/redhat-release 
CentOS Linux release 7.4.1708 (Core) 
# uname -a
Linux dev1-sbcaio-01 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

[miconda]

Thanks for the report and guidelines to reproduce it.

I pushed a patch for it in master branch. Can you try it? If all ok, then I will backport.

Was this case how you discovered it? Or was another scenario? I want to see if we should look at other parts of code.

[pwakano]

Hi Daniel,
Thanks for the prompt reply! I will try to test your patch by today!
This is the case I detected the problem. During investigation, I also saw same problem with the SIP ping from the LCR module, but I guessed they had the same root cause in the TM module.

[pwakano]

Hi Daniel,
I am using the RPM packages for CentOS so I was not able to make my environment work with head from Master so easily..... nonetheless I applied the change to the head of 5.0 branch and it did work fine!
No more increase in the "delayed_free", instead it counted on the "freed" stat. Also no memory leak was observed as well!
Thank you very much!

[miconda]

OK, thanks for testing, it was backported to 5.1 and it will be to 5.0.