[sr-dev] [kamailio/kamailio] kamailio crashes on CANCEL due to empty reply_lumps (#872)

Wed Nov 30 16:42:30 CET 2016

log related to the process that crashes 
```
2016-11-30T16:28:41.159163+01:00 spce proxy[21490]: NOTICE: <script>: New request on proxy - M=CANCEL R=sip:4311003 at spce.test:5060 F=sip:004321001 at 127.0.2.1 T=sip:4311003 at spce.test IP=127.0.2.1:51602 (127.0.0.1:5060) ID=NGCP%incoming_peer_user_404%///1-22573 at 127.0.2.1 UA='<null>'
2016-11-30T16:28:41.159296+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 41721
2016-11-30T16:28:41.159333+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=9f2a.7af5bb99ad99ededed23ef8c4fa645f2.0
2016-11-30T16:28:41.159337+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f185dfbc060)! 
2016-11-30T16:28:41.159340+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed
2016-11-30T16:28:41.159344+01:00 spce proxy[21490]: DEBUG: tm [tm.c:992]: w_t_lookup_cancel(): lookup_original: t_lookupOriginalT returned: 0x7f185dfbc060
2016-11-30T16:28:41.159349+01:00 spce proxy[21490]: NOTICE: <script>: Request leaving server via local route - R=sip:4311003 at spce.test:5060 ID=NGCP%incoming_peer_user_404%///1-22573 at 127.0.2.1 UA='<null>'
2016-11-30T16:28:41.159456+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=3 , T on entrance=0xffffffffffffffff
2016-11-30T16:28:41.159465+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request: start searching: hash=41721, isACK=0
2016-11-30T16:28:41.159469+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261 transaction matching failed
2016-11-30T16:28:41.159472+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
2016-11-30T16:28:41.159479+01:00 spce proxy[21490]: DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f185dfb7950, callback type 1, id 0 entered
2016-11-30T16:28:41.159483+01:00 spce proxy[21490]: DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f185dfb7950, callback type 1, id 0 entered
2016-11-30T16:28:41.159507+01:00 spce proxy[21490]: DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated: 5784ab728e62bcded75a225f515946f2
2016-11-30T16:28:41.159532+01:00 spce proxy[21490]: DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup
2016-11-30T16:28:41.159538+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 41721
2016-11-30T16:28:41.159542+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=9f2a.7af5bb99ad99ededed23ef8c4fa645f2.0
2016-11-30T16:28:41.159545+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f185dfbc060)! 
2016-11-30T16:28:41.159610+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed
2016-11-30T16:28:41.159630+01:00 spce proxy[21490]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0)
```
the other related log:
```
2016-11-30T16:28:41.166920+01:00 spce proxy[21489]: NOTICE: <script>: Forcing request via B2BUA 'sip:127.0.0.1:5080' - R=sip:4311003 at 127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-22573 at 127.0.2.1 UA='<null>'
2016-11-30T16:28:41.166943+01:00 spce proxy[21489]: NOTICE: <script>: Request leaving server, D-URI='sip:127.0.0.1:5080' - R=sip:4311003 at 127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-22573 at 127.0.2.1 UA='<null>'
2016-11-30T16:28:41.166959+01:00 spce proxy[21489]: DEBUG: <core> [msg_translator.c:423]: clen_builder(): content-length: 168 (168)
2016-11-30T16:28:41.166966+01:00 spce proxy[21489]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0)
2016-11-30T16:28:41.166996+01:00 spce proxy[21489]: DEBUG: tm [t_fwd.c:1766]: t_forward_nonack(): t_forward_non_ack: no forwarding on a canceled transaction
2016-11-30T16:28:41.167001+01:00 spce proxy[21489]: ERROR: tm [tm.c:1415]: _w_t_relay_to(): ERROR: w_t_relay_to: t_relay_to failed
2016-11-30T16:28:41.167190+01:00 spce proxy[21489]: DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup
2016-11-30T16:28:41.167203+01:00 spce proxy[21489]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0)
2016-11-30T16:28:41.168010+01:00 spce proxy[21489]: ERROR: sl [sl_funcs.c:363]: sl_reply_error(): ERROR: sl_reply_error used: transaction canceled (487/SL)
2016-11-30T16:28:41.168024+01:00 spce proxy[21489]: INFO: <script>: No mediaproxy engaged for this branch, no need for stopping  - R=sip:testuser1003 at 127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-22573 at 127.0.2.1 UA='<null>'
2016-11-30T16:28:41.168037+01:00 spce proxy[21489]: DEBUG: <core> [parser/sdp/sdp.c:794]: free_sdp(): _sdp = 0x7f186f7612a0
2016-11-30T16:28:41.168037+01:00 spce proxy[21489]: DEBUG: <core> [parser/sdp/sdp.c:796]: free_sdp(): sdp = 0x7f1872477de0
2016-11-30T16:28:41.168061+01:00 spce proxy[21489]: DEBUG: <core> [parser/sdp/sdp.c:798]: free_sdp(): session = 0x7f1872477ae0
2016-11-30T16:28:41.168072+01:00 spce proxy[21489]: DEBUG: tm [t_reply.c:1752]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0
2016-11-30T16:28:41.168078+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-11-30T16:28:41.168081+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-11-30T16:28:41.168084+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-11-30T16:28:41.168087+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-11-30T16:28:41.168090+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-11-30T16:28:41.168155+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-11-30T16:28:41.168163+01:00 spce proxy[21489]: DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
2016-11-30T16:28:41.168167+01:00 spce proxy[21489]: DEBUG: <core> [receive.c:322]: receive_msg(): cleaning up
2016-11-30T16:28:41.362881+01:00 spce proxy[21499]: CRITICAL: <core> [pass_fd.c:277]: receive_fd(): EOF on 11
2016-11-30T16:28:41.362888+01:00 spce proxy[21499]: DEBUG: <core> [tcp_main.c:3456]: handle_ser_child(): dead child 4, pid 21490 (shutting down?)
2016-11-30T16:28:41.362898+01:00 spce proxy[21499]: DEBUG: <core> [io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x9fec80, 11, -1, 0x0) fd_no=14 called
2016-11-30T16:28:41.389837+01:00 spce proxy[21485]: ALERT: <core> [main.c:740]: handle_sigs(): child process 21490 exited by a signal 11
2016-11-30T16:28:41.389851+01:00 spce proxy[21485]: ALERT: <core> [main.c:743]: handle_sigs(): core was generated
2016-11-30T16:28:41.389864+01:00 spce proxy[21485]: INFO: <core> [main.c:755]: handle_sigs(): terminating due to SIGCHLD
2016-11-30T16:28:41.389870+01:00 spce proxy[21485]: DEBUG: <core> [main.c:757]: handle_sigs(): terminating due to SIGCHLD
```

sip flow:

[872.txt](https://github.com/kamailio/kamailio/files/622184/872.txt)


-- 
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/872#issuecomment-263906377
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-dev/attachments/20161130/59ecc4d7/attachment-0001.html>