Hello everyone,
I have a problem in production environment where I have two SIP Proxies and both had the same problem but I don't have a ideia about root cause that triggered it.
Unfortunately I don't have a core dump file because it was truncated for don't have space enough in file system. So I only have loggings filesin DEBUG level.
The proxy_1 apparently was processing a SUBSCRIBE request and the proxy_2 was processing a DMQ messages. Both of proxies crashed after appear this line in logging file " CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10"
What could trigger this error?
The loggin of proxy_1 is following:
2020-01-28 05:17:37.058 INFO: <script>: New request - M=SUBSCRIBE R=sip: 172.29.213.10:5070 F=sip:9147323151@businesshostedvoice.com:5061 T=sip:9147323156@busine sshostedvoice.com:5061 IP=udp:10.159.0.25:5060 ID= 0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 CSeq=20830 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 74) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 80) returns address 0x7f3fb4365df8 frag. 0x7f3fb4365dc0 (size=80) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 52) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 56) returns address 0x7f3fb7c8ef08 frag. 0x7f3fb7c8eed0 (size=56) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 67) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fd2bc8928 frag. 0x7f3fd2bc88f0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Applying rewrite rules on '9147323156' using dialplan 'DB_MANIPS' - R=sip:172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmT UrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:208]: dp_get_ivalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:216]: dp_get_ivalue(): dpid is 1 from pv argument 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:225]: dp_get_svalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:313]: dp_translate_f(): input is 9147323156 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:676]: translate(): no matching rule 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:318]: dp_translate_f(): could not translate 9147323156 with dpid 1 2020-01-28 05:17:37.059 INFO: <script>: No matching rewrite rules for '9147323156' found - R=sip:172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnz dKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 70) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fa7f6f028 frag. 0x7f3fa7f6eff0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Clean AVPs that contains rewrite rule from method ROUTE_APPLY_REWRITE_RULE ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzd KbnqZHYs2tiFs+Okphqx4p@10.159.0.25 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb4365df8), called from core: core/usr_avp.c: destroy_a vp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb4365dc0 alloc'ed from core: core/usr_avp.c: create_avp (175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb7c8ef08), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb7c8eed0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fd2bc8928), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fd2bc88f0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f40d8531010, 247) called from db_postgres: km_dbase.c: db_postgres_submit_query(171) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f40d8531010, 248) returns address 0x7f40d8aac7d8 frag. 0x7f40d8aac7a0 (size=376) on 1 -th hit 2020-01-28 05:17:37.059 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:17:37.059 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 28150 (shutting down?) 2020-01-28 05:17:37.059 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:17:37.059 ALERT: <core> [main.c:744]: handle_sigs(): child process 28150 exited by a signal 11 2020-01-28 05:17:37.059 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:17:37.059 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.059 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5111688, used+overhead=6932632, free=11941736 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: 1. N address=0x7f40d856ab40 frag=0x7f40d856ab08 size=256 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: qm_status: 2. N address=0x7f40d856aca8 frag=0x7f40d856ac70 size=176 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/counters.c: cnt_hash_add(332) 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments:
The loggin of proxy_2 is following:
2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:usrloc@172.29.217.7:5060] 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [sip:usrloc@172.29.217.7:5060] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499f980 frag. 0x7f5ae499f948 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499bcf8 frag. 0x7f5ae499bcc0 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) called from core: core/parser/msg_parser.c: get_hdr_ field(135) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) returns address 0x7f5ae4916f90 frag. 0x7f5ae4916f58 (size=48) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <KDMQ> 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499e520 frag. 0x7f5ae499e4e8 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [ 3d48b3aa4ec7e11f-8255@172.29.213.8] - cseq: [10 KDMQ] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) called from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) returns address 0x7f5ae48e1340 frag. 0x7f5ae48e1308 (size=1736) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48e1340), called from core: core/rvalue.c: rval_destroy(129) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48e1308 alloc'ed from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190276 T start=0xffffffffffffffff 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:879]: t_reply_matching(): t_reply_matching: hash 26335 label 0 branch 0 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:933]: t_reply_matching(): reply matched (T=0x7f59eef5b310)! 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg id=190277 global id=190277 T end=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190277 T start=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T already found! 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2147]: reply_received(): org. status uas=0, uac[0]=0 local=2 is_invite=0) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1220]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2021]: local_reply(): branch=0, save=0, winner=0 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2060]: local_reply(): local transaction completed 200/0 (totag retr: 0/1024) 2020-01-28 05:57:21.077 DEBUG: tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f59eef5b310, callback type 1024, id 0 entered 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:61]: dmq_tm_callback(): dmq_tm_callback start 2020-01-28 05:57:21.077 DEBUG: dmq_usrloc [usrloc_sync.c:583]: usrloc_dmq_resp_callback_f(): dmq response callback triggered [0x7f5ae4a373c8 200 (nil)] 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:67]: dmq_tm_callback(): dmq_tm_callback done 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59f9b93080), called from dmq: dmqnode.c: shm_free_node(306) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59f9b93048 alloc'ed from dmq: ../../core/ut.h: shm_str_dup(723) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c6055a40), called from dmq: dmqnode.c: shm_free_node(307) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c6055a08 alloc'ed from dmq: dmqnode.c: shm_dup_node(279) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c4a46a48), called from dmq: dmq_funcs.c: dmq_tm_callback(69) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c4a46a10 alloc'ed from dmq: dmq_funcs.c: dmq_send_message(212) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1578]: cleanup_uac_timers(): RETR/FR timers reset 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 143 usec 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2020-01-28 05:57:21.078 DEBUG: <core> [core/receive.c:368]: receive_msg(): cleaning up 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e670), called from core: core/parser/parse_via.c: free_via_param_list(2725) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e638 alloc'ed from core: core/parser/parse_via.c: parse_via(2511) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f830), called from core: core/parser/parse_via.c: free_via_list(2738) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f7f8 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(116) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4921478), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4921440 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4924f60), called from core: core/parser/parse_addr_spec.c: free_to_params(895) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4924f28 alloc'ed from core: core/parser/parse_addr_spec.c: parse_to_param(285) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4998e48), called from core: core/parser/parse_addr_spec.c: free_to(905) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4998e10 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(155) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48ecd18), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48ecce0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f980), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f948 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4916f90), called from core: core/parser/parse_cseq.c: free_cseq(99) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4916f58 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(135) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499bcf8), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499bcc0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e520), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e4e8 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4a373c8), called from core: core/receive.c: receive_msg(370) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4a37390 alloc'ed from core: core/receive.c: receive_msg(150) 2020-01-28 05:57:21.117 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:57:21.117 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 8253 (shutting down?) 2020-01-28 05:57:21.117 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:57:21.118 ALERT: <core> [main.c:744]: handle_sigs(): child process 8253 exited by a signal 11 2020-01-28 05:57:21.118 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:57:21.118 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg):
Best regards Virgílio Cunha
The CRITICAL log message is a side effect of the crash, not the reason of the crash.
First I suggest you upgrade to at least to latest 5.0.x, because there were many fixes after 5.0.1, and what you get may be fixed already. Such upgrade requires to deploy new binaries and restart.
Even better will be to upgrade to a maintained release, such as 5.3 or 5.2. This may require to change config file and database structure, but you have more fixes include.
After upgrade, if you still get the crash, grab the backtrace with gdb from the core file -- logs suggest it was generate:
ALERT: <core> [main.c:747]: handle_sigs(): core was generated
Cheers, Daniel
On 29.01.20 11:45, Virgílio Cunha wrote:
Hello everyone,
I have a problem in production environment where I have two SIP Proxies and both had the same problem but I don't have a ideia about root cause that triggered it.
Unfortunately I don't have a core dump file because it was truncated for don't have space enough in file system. So I only have loggings filesin DEBUG level.
The proxy_1 apparently was processing a SUBSCRIBE request and the proxy_2 was processing a DMQ messages. Both of proxies crashed after appear this line in logging file " CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10"
What could trigger this error?
The loggin of proxy_1 is following:
2020-01-28 05:17:37.058 INFO: <script>: New request - M=SUBSCRIBE R=sip:172.29.213.10:5070 http://172.29.213.10:5070 F=sip:9147323151@businesshostedvoice.com:5061 http://sip:9147323151@businesshostedvoice.com:5061 T=sip:9147323156@busine sshostedvoice.com:5061 http://sshostedvoice.com:5061 IP=udp:10.159.0.25:5060 http://10.159.0.25:5060 ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 mailto:0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzdKbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 CSeq=20830 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 74) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 80) returns address 0x7f3fb4365df8 frag. 0x7f3fb4365dc0 (size=80) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 52) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 56) returns address 0x7f3fb7c8ef08 frag. 0x7f3fb7c8eed0 (size=56) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 67) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fd2bc8928 frag. 0x7f3fd2bc88f0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Applying rewrite rules on '9147323156' using dialplan 'DB_MANIPS' - R=sip:172.29.213.10:5070 http://172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmT UrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 mailto:UrVeFdEMSouFoeDnzdKbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:208]: dp_get_ivalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:216]: dp_get_ivalue(): dpid is 1 from pv argument 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:225]: dp_get_svalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:313]: dp_translate_f(): input is 9147323156 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:676]: translate(): no matching rule 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:318]: dp_translate_f(): could not translate 9147323156 with dpid 1 2020-01-28 05:17:37.059 INFO: <script>: No matching rewrite rules for '9147323156' found - R=sip:172.29.213.10:5070 http://172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnz dKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 mailto:dKbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 70) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fa7f6f028 frag. 0x7f3fa7f6eff0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Clean AVPs that contains rewrite rule from method ROUTE_APPLY_REWRITE_RULE ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzd KbnqZHYs2tiFs+Okphqx4p@10.159.0.25 mailto:KbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb4365df8), called from core: core/usr_avp.c: destroy_a vp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb4365dc0 alloc'ed from core: core/usr_avp.c: create_avp (175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb7c8ef08), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb7c8eed0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fd2bc8928), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fd2bc88f0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f40d8531010, 247) called from db_postgres: km_dbase.c: db_postgres_submit_query(171) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f40d8531010, 248) returns address 0x7f40d8aac7d8 frag. 0x7f40d8aac7a0 (size=376) on 1 -th hit 2020-01-28 05:17:37.059 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:17:37.059 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 28150 (shutting down?) 2020-01-28 05:17:37.059 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:17:37.059 ALERT: <core> [main.c:744]: handle_sigs(): child process 28150 exited by a signal 11 2020-01-28 05:17:37.059 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:17:37.059 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.059 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5111688, used+overhead=6932632, free=11941736 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: 1. N address=0x7f40d856ab40 frag=0x7f40d856ab08 size=256 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: qm_status: 2. N address=0x7f40d856aca8 frag=0x7f40d856ac70 size=176 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/counters.c: cnt_hash_add(332) 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments:
The loggin of proxy_2 is following:
2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:usrloc@172.29.217.7:5060 http://sip:usrloc@172.29.217.7:5060] 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:usrloc@172.29.217.7:5060 http://sip:usrloc@172.29.217.7:5060>] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499f980 frag. 0x7f5ae499f948 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499bcf8 frag. 0x7f5ae499bcc0 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) called from core: core/parser/msg_parser.c: get_hdr_ field(135) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) returns address 0x7f5ae4916f90 frag. 0x7f5ae4916f58 (size=48) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <KDMQ> 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499e520 frag. 0x7f5ae499e4e8 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [3d48b3aa4ec7e11f-8255@172.29.213.8 mailto:3d48b3aa4ec7e11f-8255@172.29.213.8] - cseq: [10 KDMQ] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) called from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) returns address 0x7f5ae48e1340 frag. 0x7f5ae48e1308 (size=1736) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48e1340), called from core: core/rvalue.c: rval_destroy(129) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48e1308 alloc'ed from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190276 T start=0xffffffffffffffff 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:879]: t_reply_matching(): t_reply_matching: hash 26335 label 0 branch 0 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:933]: t_reply_matching(): reply matched (T=0x7f59eef5b310)! 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg id=190277 global id=190277 T end=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190277 T start=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T already found! 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2147]: reply_received(): org. status uas=0, uac[0]=0 local=2 is_invite=0) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1220]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2021]: local_reply(): branch=0, save=0, winner=0 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2060]: local_reply(): local transaction completed 200/0 (totag retr: 0/1024) 2020-01-28 05:57:21.077 DEBUG: tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f59eef5b310, callback type 1024, id 0 entered 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:61]: dmq_tm_callback(): dmq_tm_callback start 2020-01-28 05:57:21.077 DEBUG: dmq_usrloc [usrloc_sync.c:583]: usrloc_dmq_resp_callback_f(): dmq response callback triggered [0x7f5ae4a373c8 200 (nil)] 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:67]: dmq_tm_callback(): dmq_tm_callback done 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59f9b93080), called from dmq: dmqnode.c: shm_free_node(306) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59f9b93048 alloc'ed from dmq: ../../core/ut.h: shm_str_dup(723) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c6055a40), called from dmq: dmqnode.c: shm_free_node(307) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c6055a08 alloc'ed from dmq: dmqnode.c: shm_dup_node(279) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c4a46a48), called from dmq: dmq_funcs.c: dmq_tm_callback(69) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c4a46a10 alloc'ed from dmq: dmq_funcs.c: dmq_send_message(212) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1578]: cleanup_uac_timers(): RETR/FR timers reset 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 143 usec 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2020-01-28 05:57:21.078 DEBUG: <core> [core/receive.c:368]: receive_msg(): cleaning up 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e670), called from core: core/parser/parse_via.c: free_via_param_list(2725) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e638 alloc'ed from core: core/parser/parse_via.c: parse_via(2511) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f830), called from core: core/parser/parse_via.c: free_via_list(2738) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f7f8 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(116) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4921478), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4921440 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4924f60), called from core: core/parser/parse_addr_spec.c: free_to_params(895) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4924f28 alloc'ed from core: core/parser/parse_addr_spec.c: parse_to_param(285) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4998e48), called from core: core/parser/parse_addr_spec.c: free_to(905) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4998e10 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(155) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48ecd18), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48ecce0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f980), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f948 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4916f90), called from core: core/parser/parse_cseq.c: free_cseq(99) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4916f58 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(135) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499bcf8), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499bcc0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e520), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e4e8 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4a373c8), called from core: core/receive.c: receive_msg(370) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4a37390 alloc'ed from core: core/receive.c: receive_msg(150) 2020-01-28 05:57:21.117 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:57:21.117 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 8253 (shutting down?) 2020-01-28 05:57:21.117 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:57:21.118 ALERT: <core> [main.c:744]: handle_sigs(): child process 8253 exited by a signal 11 2020-01-28 05:57:21.118 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:57:21.118 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg):
Best regards Virgílio Cunha
Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
Thanks Daniel for your answer,
Before upgrade kamailio to latest 5.0.x, I collected more information in 5.0.1 version about reported problem. In production environment I have 4 sip proxies that are synchronized via DMQ. The configuration of DMQ is follow:
loadmodule "dmq.so" modparam("dmq", "server_address", "sip:MY_IP_ADDRESS:MY_PORT_ADDRESS") modparam("dmq", "notification_address", "DMQ_HOSTS") modparam("dmq", "multi_notify", 1) modparam("dmq", "num_workers", 4)
Where "DMQ_HOSTS" that is used in the notification_address parameter is the FQDN of the proxies. The FQDN is resolved with the IP of the 4 proxies..
Let me know if I did something wrong in my configuration.
In scenario that kamailio crashes I had around 7700 user registers and when I restart the proxy it crashes in dmq module, the backtrace of coredump is the following:.
Program terminated with signal 11, Segmentation fault. #0 0x00007f8773f0b198 in ?? () from /usr/lib64/kamailio/modules/dmq.so Missing separate debuginfos, use: debuginfo-install kamailio-5.0.1-1.el6.x86_64 (gdb) bt full #0 0x00007f8773f0b198 in ?? () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #1 0x00007f8773f0ec1a in job_queue_size () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #2 0x00007f8773f0e2f4 in add_dmq_job () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #3 0x00007f8773f00ec1 in dmq_handle_message () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #4 0x00000000004336e1 in do_action () No symbol table info available. #5 0x000000000044046c in run_actions () No symbol table info available. #6 0x000000000043364a in do_action () No symbol table info available. #7 0x000000000044046c in run_actions () No symbol table info available. #8 0x0000000000440bfe in run_top_route () No symbol table info available. #9 0x0000000000529ae1 in receive_msg () No symbol table info available. #10 0x000000000063da5f in udp_rcv_loop () No symbol table info available. #11 0x000000000042372c in main_loop () No symbol table info available. #12 0x000000000042aaf9 in main () No symbol table info available. (gdb)
Was this problem in dmq identified/fixed?
Best regards, Virgílio Cunha
Em qua., 29 de jan. de 2020 às 13:49, Daniel-Constantin Mierla < miconda@gmail.com> escreveu:
The CRITICAL log message is a side effect of the crash, not the reason of the crash.
First I suggest you upgrade to at least to latest 5.0.x, because there were many fixes after 5.0.1, and what you get may be fixed already. Such upgrade requires to deploy new binaries and restart.
Even better will be to upgrade to a maintained release, such as 5.3 or 5.2. This may require to change config file and database structure, but you have more fixes include.
After upgrade, if you still get the crash, grab the backtrace with gdb from the core file -- logs suggest it was generate:
ALERT: <core> [main.c:747]: handle_sigs(): core was generated
Cheers, Daniel On 29.01.20 11:45, Virgílio Cunha wrote:
Hello everyone,
I have a problem in production environment where I have two SIP Proxies and both had the same problem but I don't have a ideia about root cause that triggered it.
Unfortunately I don't have a core dump file because it was truncated for don't have space enough in file system. So I only have loggings filesin DEBUG level.
The proxy_1 apparently was processing a SUBSCRIBE request and the proxy_2 was processing a DMQ messages. Both of proxies crashed after appear this line in logging file " CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10"
What could trigger this error?
The loggin of proxy_1 is following:
2020-01-28 05:17:37.058 INFO: <script>: New request - M=SUBSCRIBE R=sip: 172.29.213.10:5070 F=sip:9147323151@businesshostedvoice.com:5061 T= sip:9147323156@busine sshostedvoice.com:5061 IP=udp:10.159.0.25:5060 ID= 0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 CSeq=20830 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 74) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 80) returns address 0x7f3fb4365df8 frag. 0x7f3fb4365dc0 (size=80) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 52) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 56) returns address 0x7f3fb7c8ef08 frag. 0x7f3fb7c8eed0 (size=56) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 67) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fd2bc8928 frag. 0x7f3fd2bc88f0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Applying rewrite rules on '9147323156' using dialplan 'DB_MANIPS' - R=sip:172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmT UrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:208]: dp_get_ivalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:216]: dp_get_ivalue(): dpid is 1 from pv argument 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:225]: dp_get_svalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:313]: dp_translate_f(): input is 9147323156 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:676]: translate(): no matching rule 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:318]: dp_translate_f(): could not translate 9147323156 with dpid 1 2020-01-28 05:17:37.059 INFO: <script>: No matching rewrite rules for '9147323156' found - R=sip:172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnz dKbnqZHYs2tiFs+Okphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 70) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fa7f6f028 frag. 0x7f3fa7f6eff0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Clean AVPs that contains rewrite rule from method ROUTE_APPLY_REWRITE_RULE ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzd KbnqZHYs2tiFs+Okphqx4p@10.159.0.25 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb4365df8), called from core: core/usr_avp.c: destroy_a vp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb4365dc0 alloc'ed from core: core/usr_avp.c: create_avp (175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb7c8ef08), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb7c8eed0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fd2bc8928), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fd2bc88f0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f40d8531010, 247) called from db_postgres: km_dbase.c: db_postgres_submit_query(171) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f40d8531010, 248) returns address 0x7f40d8aac7d8 frag. 0x7f40d8aac7a0 (size=376) on 1 -th hit 2020-01-28 05:17:37.059 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:17:37.059 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 28150 (shutting down?) 2020-01-28 05:17:37.059 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:17:37.059 ALERT: <core> [main.c:744]: handle_sigs(): child process 28150 exited by a signal 11 2020-01-28 05:17:37.059 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:17:37.059 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.059 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5111688, used+overhead=6932632, free=11941736 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: 1. N address=0x7f40d856ab40 frag=0x7f40d856ab08 size=256 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: qm_status: 2. N address=0x7f40d856aca8 frag=0x7f40d856ac70 size=176 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/counters.c: cnt_hash_add(332) 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments:
The loggin of proxy_2 is following:
2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:usrloc@172.29.217.7:5060] 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [sip:usrloc@172.29.217.7:5060] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499f980 frag. 0x7f5ae499f948 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499bcf8 frag. 0x7f5ae499bcc0 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) called from core: core/parser/msg_parser.c: get_hdr_ field(135) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) returns address 0x7f5ae4916f90 frag. 0x7f5ae4916f58 (size=48) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <KDMQ> 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499e520 frag. 0x7f5ae499e4e8 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [ 3d48b3aa4ec7e11f-8255@172.29.213.8] - cseq: [10 KDMQ] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) called from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) returns address 0x7f5ae48e1340 frag. 0x7f5ae48e1308 (size=1736) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48e1340), called from core: core/rvalue.c: rval_destroy(129) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48e1308 alloc'ed from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190276 T start=0xffffffffffffffff 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:879]: t_reply_matching(): t_reply_matching: hash 26335 label 0 branch 0 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:933]: t_reply_matching(): reply matched (T=0x7f59eef5b310)! 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg id=190277 global id=190277 T end=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190277 T start=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T already found! 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2147]: reply_received(): org. status uas=0, uac[0]=0 local=2 is_invite=0) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1220]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2021]: local_reply(): branch=0, save=0, winner=0 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2060]: local_reply(): local transaction completed 200/0 (totag retr: 0/1024) 2020-01-28 05:57:21.077 DEBUG: tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f59eef5b310, callback type 1024, id 0 entered 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:61]: dmq_tm_callback(): dmq_tm_callback start 2020-01-28 05:57:21.077 DEBUG: dmq_usrloc [usrloc_sync.c:583]: usrloc_dmq_resp_callback_f(): dmq response callback triggered [0x7f5ae4a373c8 200 (nil)] 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:67]: dmq_tm_callback(): dmq_tm_callback done 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59f9b93080), called from dmq: dmqnode.c: shm_free_node(306) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59f9b93048 alloc'ed from dmq: ../../core/ut.h: shm_str_dup(723) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c6055a40), called from dmq: dmqnode.c: shm_free_node(307) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c6055a08 alloc'ed from dmq: dmqnode.c: shm_dup_node(279) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c4a46a48), called from dmq: dmq_funcs.c: dmq_tm_callback(69) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c4a46a10 alloc'ed from dmq: dmq_funcs.c: dmq_send_message(212) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1578]: cleanup_uac_timers(): RETR/FR timers reset 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 143 usec 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2020-01-28 05:57:21.078 DEBUG: <core> [core/receive.c:368]: receive_msg(): cleaning up 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e670), called from core: core/parser/parse_via.c: free_via_param_list(2725) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e638 alloc'ed from core: core/parser/parse_via.c: parse_via(2511) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f830), called from core: core/parser/parse_via.c: free_via_list(2738) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f7f8 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(116) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4921478), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4921440 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4924f60), called from core: core/parser/parse_addr_spec.c: free_to_params(895) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4924f28 alloc'ed from core: core/parser/parse_addr_spec.c: parse_to_param(285) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4998e48), called from core: core/parser/parse_addr_spec.c: free_to(905) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4998e10 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(155) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48ecd18), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48ecce0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f980), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f948 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4916f90), called from core: core/parser/parse_cseq.c: free_cseq(99) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4916f58 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(135) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499bcf8), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499bcc0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e520), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e4e8 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4a373c8), called from core: core/receive.c: receive_msg(370) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4a37390 alloc'ed from core: core/receive.c: receive_msg(150) 2020-01-28 05:57:21.117 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:57:21.117 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 8253 (shutting down?) 2020-01-28 05:57:21.117 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:57:21.118 ALERT: <core> [main.c:744]: handle_sigs(): child process 8253 exited by a signal 11 2020-01-28 05:57:21.118 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:57:21.118 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg):
Best regards Virgílio Cunha
Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
Hello,
the backtrace is unfortunately not useful, as you are missing the necessary debug information. There should a be Kamailio package available to install the debug information.
But as mentioned before, you really should upgrade at least to the lastest 5.0.x version, as many bugs are fixed in this version comparing to 5.0.1.
If you want to get better help from the community, you should also update to a maintained version (5.2.x or 5.3.x).
Cheers,
Henning
-- Henning Westerholt – https://skalatan.de/blog/ Kamailio services – https://gilawa.comhttps://gilawa.com/
From: sr-users sr-users-bounces@lists.kamailio.org On Behalf Of Virgílio Cunha Sent: Wednesday, March 4, 2020 12:39 PM To: miconda@gmail.com; Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org Subject: Re: [SR-Users] Kamailio 5.0.1 Crashes
Thanks Daniel for your answer,
Before upgrade kamailio to latest 5.0.x, I collected more information in 5.0.1 version about reported problem. In production environment I have 4 sip proxies that are synchronized via DMQ. The configuration of DMQ is follow: loadmodule "dmq.so" modparam("dmq", "server_address", "sip:MY_IP_ADDRESS:MY_PORT_ADDRESS") modparam("dmq", "notification_address", "DMQ_HOSTS") modparam("dmq", "multi_notify", 1) modparam("dmq", "num_workers", 4)
Where "DMQ_HOSTS" that is used in the notification_address parameter is the FQDN of the proxies. The FQDN is resolved with the IP of the 4 proxies..
Let me know if I did something wrong in my configuration.
In scenario that kamailio crashes I had around 7700 user registers and when I restart the proxy it crashes in dmq module, the backtrace of coredump is the following:.
Program terminated with signal 11, Segmentation fault. #0 0x00007f8773f0b198 in ?? () from /usr/lib64/kamailio/modules/dmq.so Missing separate debuginfos, use: debuginfo-install kamailio-5.0.1-1.el6.x86_64 (gdb) bt full #0 0x00007f8773f0b198 in ?? () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #1 0x00007f8773f0ec1a in job_queue_size () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #2 0x00007f8773f0e2f4 in add_dmq_job () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #3 0x00007f8773f00ec1 in dmq_handle_message () from /usr/lib64/kamailio/modules/dmq.so No symbol table info available. #4 0x00000000004336e1 in do_action () No symbol table info available. #5 0x000000000044046c in run_actions () No symbol table info available. #6 0x000000000043364a in do_action () No symbol table info available. #7 0x000000000044046c in run_actions () No symbol table info available. #8 0x0000000000440bfe in run_top_route () No symbol table info available. #9 0x0000000000529ae1 in receive_msg () No symbol table info available. #10 0x000000000063da5f in udp_rcv_loop () No symbol table info available. #11 0x000000000042372c in main_loop () No symbol table info available. #12 0x000000000042aaf9 in main () No symbol table info available. (gdb)
Was this problem in dmq identified/fixed?
Best regards, Virgílio Cunha
Em qua., 29 de jan. de 2020 às 13:49, Daniel-Constantin Mierla <miconda@gmail.commailto:miconda@gmail.com> escreveu:
The CRITICAL log message is a side effect of the crash, not the reason of the crash.
First I suggest you upgrade to at least to latest 5.0.x, because there were many fixes after 5.0.1, and what you get may be fixed already. Such upgrade requires to deploy new binaries and restart.
Even better will be to upgrade to a maintained release, such as 5.3 or 5.2. This may require to change config file and database structure, but you have more fixes include.
After upgrade, if you still get the crash, grab the backtrace with gdb from the core file -- logs suggest it was generate:
ALERT: <core> [main.c:747]: handle_sigs(): core was generated
Cheers, Daniel On 29.01.20 11:45, Virgílio Cunha wrote: Hello everyone,
I have a problem in production environment where I have two SIP Proxies and both had the same problem but I don't have a ideia about root cause that triggered it.
Unfortunately I don't have a core dump file because it was truncated for don't have space enough in file system. So I only have loggings filesin DEBUG level.
The proxy_1 apparently was processing a SUBSCRIBE request and the proxy_2 was processing a DMQ messages. Both of proxies crashed after appear this line in logging file " CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10"
What could trigger this error?
The loggin of proxy_1 is following:
2020-01-28 05:17:37.058 INFO: <script>: New request - M=SUBSCRIBE R=sip:172.29.213.10:5070http://172.29.213.10:5070 F=sip:9147323151@businesshostedvoice.com:5061http://sip:9147323151@businesshostedvoice.com:5061 T=sip:9147323156@busine sshostedvoice.com:5061http://sshostedvoice.com:5061 IP=udp:10.159.0.25:5060http://10.159.0.25:5060 ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25mailto:0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzdKbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 CSeq=20830 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 74) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 80) returns address 0x7f3fb4365df8 frag. 0x7f3fb4365dc0 (size=80) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 52) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 56) returns address 0x7f3fb7c8ef08 frag. 0x7f3fb7c8eed0 (size=56) on 1 -th hit 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 67) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.058 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fd2bc8928 frag. 0x7f3fd2bc88f0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Applying rewrite rules on '9147323156' using dialplan 'DB_MANIPS' - R=sip:172.29.213.10:5070http://172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmT UrVeFdEMSouFoeDnzdKbnqZHYs2tiFs+Okphqx4p@10.159.0.25mailto:UrVeFdEMSouFoeDnzdKbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:208]: dp_get_ivalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:216]: dp_get_ivalue(): dpid is 1 from pv argument 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:225]: dp_get_svalue(): searching 4 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:313]: dp_translate_f(): input is 9147323156 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:606]: translate(): regex operator testing over [9147323156] 2020-01-28 05:17:37.059 DEBUG: dialplan [dp_repl.c:676]: translate(): no matching rule 2020-01-28 05:17:37.059 DEBUG: dialplan [dialplan.c:318]: dp_translate_f(): could not translate 9147323156 with dpid 1 2020-01-28 05:17:37.059 INFO: <script>: No matching rewrite rules for '9147323156' found - R=sip:172.29.213.10:5070http://172.29.213.10:5070 ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnz dKbnqZHYs2tiFs+Okphqx4p@10.159.0.25mailto:dKbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 UA='Grandstream GXP2140 1.0.9.135' 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f3f97a41000, 70) called from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f3f97a41000, 72) returns address 0x7f3fa7f6f028 frag. 0x7f3fa7f6eff0 (size=72) on 1 -th hit 2020-01-28 05:17:37.059 INFO: <script>: Clean AVPs that contains rewrite rule from method ROUTE_APPLY_REWRITE_RULE ID=0gQAAC8WAAACBAAALxYAAJmTUrVeFdEMSouFoeDnzd KbnqZHYs2tiFs+Okphqx4p@10.159.0.25mailto:KbnqZHYs2tiFs%2BOkphqx4p@10.159.0.25 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb4365df8), called from core: core/usr_avp.c: destroy_a vp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb4365dc0 alloc'ed from core: core/usr_avp.c: create_avp (175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fb7c8ef08), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fb7c8eed0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f3f97a41000, 0x7f3fd2bc8928), called from core: core/usr_avp.c: destroy_avp(592) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f3fd2bc88f0 alloc'ed from core: core/usr_avp.c: create_avp(175) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f40d8531010, 247) called from db_postgres: km_dbase.c: db_postgres_submit_query(171) 2020-01-28 05:17:37.059 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f40d8531010, 248) returns address 0x7f40d8aac7d8 frag. 0x7f40d8aac7a0 (size=376) on 1 -th hit 2020-01-28 05:17:37.059 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:17:37.059 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 28150 (shutting down?) 2020-01-28 05:17:37.059 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:17:37.059 ALERT: <core> [main.c:744]: handle_sigs(): child process 28150 exited by a signal 11 2020-01-28 05:17:37.059 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:17:37.059 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.059 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5111688, used+overhead=6932632, free=11941736 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5260600, used+overhead=7067400, free=11806968 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments: 2020-01-28 05:17:37.060 DEBUG: qm_status: 0. N address=0x7f40d856a6d8 frag=0x7f40d856a6a0 size=1024 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: 1. N address=0x7f40d856ab40 frag=0x7f40d856ab08 size=256 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/str_hash.h: str_hash_alloc(59) 2020-01-28 05:17:37.060 DEBUG: qm_status: start check=f0f0f0f0, end check= c0c0c0c0, abcdefed 2020-01-28 05:17:37.060 DEBUG: qm_status: 2. N address=0x7f40d856aca8 frag=0x7f40d856ac70 size=176 used=1 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: alloc'd from core: core/counters.c: cnt_hash_add(332) 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: (0x7f40d8531010): 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: heap size= 18874368 2020-01-28 05:17:37.060 DEBUG: qm_status: used= 5103784, used+overhead=6908920, free=11965448 2020-01-28 05:17:37.060 DEBUG: qm_status: max used (+overhead)= 7144424 2020-01-28 05:17:37.060 DEBUG: qm_status: dumping all alloc'ed. fragments:
The loggin of proxy_2 is following:
2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:usrloc@172.29.217.7:5060http://sip:usrloc@172.29.217.7:5060] 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:usrloc@172.29.217.7:5060http://sip:usrloc@172.29.217.7:5060>] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499f980 frag. 0x7f5ae499f948 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_he aders(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499bcf8 frag. 0x7f5ae499bcc0 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) called from core: core/parser/msg_parser.c: get_hdr_ field(135) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 48) returns address 0x7f5ae4916f90 frag. 0x7f5ae4916f58 (size=48) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <KDMQ> 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) called from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 64) returns address 0x7f5ae499e520 frag. 0x7f5ae499e4e8 (size=64) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [3d48b3aa4ec7e11f-8255@172.29.213.8mailto:3d48b3aa4ec7e11f-8255@172.29.213.8] - cseq: [10 KDMQ] 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:368]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) called from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f5ae4367010, 936) returns address 0x7f5ae48e1340 frag. 0x7f5ae48e1308 (size=1736) on 1 -th hit 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48e1340), called from core: core/rvalue.c: rval_destroy(129) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48e1308 alloc'ed from core: core/rvalue.c: rval_new_empty(224) 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190276 T start=0xffffffffffffffff 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:879]: t_reply_matching(): t_reply_matching: hash 26335 label 0 branch 0 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:933]: t_reply_matching(): reply matched (T=0x7f59eef5b310)! 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg id=190277 global id=190277 T end=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg id=190277 global id=190277 T start=0x7f59eef5b310 2020-01-28 05:57:21.077 DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T already found! 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2147]: reply_received(): org. status uas=0, uac[0]=0 local=2 is_invite=0) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1220]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2021]: local_reply(): branch=0, save=0, winner=0 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:2060]: local_reply(): local transaction completed 200/0 (totag retr: 0/1024) 2020-01-28 05:57:21.077 DEBUG: tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f59eef5b310, callback type 1024, id 0 entered 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:61]: dmq_tm_callback(): dmq_tm_callback start 2020-01-28 05:57:21.077 DEBUG: dmq_usrloc [usrloc_sync.c:583]: usrloc_dmq_resp_callback_f(): dmq response callback triggered [0x7f5ae4a373c8 200 (nil)] 2020-01-28 05:57:21.077 DEBUG: dmq [dmq_funcs.c:67]: dmq_tm_callback(): dmq_tm_callback done 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59f9b93080), called from dmq: dmqnode.c: shm_free_node(306) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59f9b93048 alloc'ed from dmq: ../../core/ut.h: shm_str_dup(723) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c6055a40), called from dmq: dmqnode.c: shm_free_node(307) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c6055a08 alloc'ed from dmq: dmqnode.c: shm_dup_node(279) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f59a3877000, 0x7f59c4a46a48), called from dmq: dmq_funcs.c: dmq_tm_callback(69) 2020-01-28 05:57:21.077 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f59c4a46a10 alloc'ed from dmq: dmq_funcs.c: dmq_send_message(212) 2020-01-28 05:57:21.077 DEBUG: tm [t_reply.c:1578]: cleanup_uac_timers(): RETR/FR timers reset 2020-01-28 05:57:21.077 DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 143 usec 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2020-01-28 05:57:21.077 DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2020-01-28 05:57:21.078 DEBUG: <core> [core/receive.c:368]: receive_msg(): cleaning up 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e670), called from core: core/parser/parse_via.c: free_via_param_list(2725) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e638 alloc'ed from core: core/parser/parse_via.c: parse_via(2511) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f830), called from core: core/parser/parse_via.c: free_via_list(2738) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f7f8 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(116) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4921478), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4921440 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4924f60), called from core: core/parser/parse_addr_spec.c: free_to_params(895) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4924f28 alloc'ed from core: core/parser/parse_addr_spec.c: parse_to_param(285) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4998e48), called from core: core/parser/parse_addr_spec.c: free_to(905) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4998e10 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(155) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae48ecd18), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae48ecce0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499f980), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499f948 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4916f90), called from core: core/parser/parse_cseq.c: free_cseq(99) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4916f58 alloc'ed from core: core/parser/msg_parser.c: get_hdr_field(135) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499bcf8), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499bcc0 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae499e520), called from core: core/parser/hf.c: free_hdr_field_lst(217) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae499e4e8 alloc'ed from core: core/parser/msg_parser.c: parse_headers(319) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:454]: qm_free(): qm_free(0x7f5ae4367010, 0x7f5ae4a373c8), called from core: core/receive.c: receive_msg(370) 2020-01-28 05:57:21.078 DEBUG: <core> [core/mem/q_malloc.c:489]: qm_free(): qm_free: freeing frag. 0x7f5ae4a37390 alloc'ed from core: core/receive.c: receive_msg(150) 2020-01-28 05:57:21.117 CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 10 2020-01-28 05:57:21.117 DEBUG: <core> [core/tcp_main.c:3456]: handle_ser_child(): dead child 2, pid 8253 (shutting down?) 2020-01-28 05:57:21.117 DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa52ba0, 10, -1, 0x0) fd_no=61 called 2020-01-28 05:57:21.118 ALERT: <core> [main.c:744]: handle_sigs(): child process 8253 exited by a signal 11 2020-01-28 05:57:21.118 ALERT: <core> [main.c:747]: handle_sigs(): core was generated 2020-01-28 05:57:21.118 INFO: <core> [main.c:759]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:761]: handle_sigs(): terminating due to SIGCHLD 2020-01-28 05:57:21.118 INFO: <core> [main.c:814]: sig_usr(): signal 15 received 2020-01-28 05:57:21.118 DEBUG: <core> [main.c:825]: sig_usr(): Memory status (pkg):
Best regards Virgílio Cunha
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users@lists.kamailio.orgmailto:sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.comhttp://www.asipto.com
www.twitter.com/micondahttp://www.twitter.com/miconda -- www.linkedin.com/in/micondahttp://www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.comhttp://www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.comhttp://www.kamailioworld.com
-
Daniel-Constantin Mierla -
Henning Westerholt -
Virgílio Cunha