29 Jan
2020
29 Jan
'20
1:45 p.m.
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(a)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(a)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(a)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(a)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(a)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
29 Jan
29 Jan
4:49 p.m.
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(a)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(a)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(a)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(a)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(a)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(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.com
www.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
4 Mar
4 Mar
2:38 p.m.
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(a)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(a)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(a)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(a)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(a)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(a)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
9 Mar
9 Mar
1:42 p.m.
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.com<https://gilawa.com/>
From: sr-users <sr-users-bounces(a)lists.kamailio.org> On Behalf Of Virgílio Cunha
Sent: Wednesday, March 4, 2020 12:39 PM
To: miconda(a)gmail.com; Kamailio (SER) - Users Mailing List
<sr-users(a)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.com<mailto: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<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<mailto:sr-users@lists.kamailio.org>
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.com<http://www.asipto.com>
www.twitter.com/miconda<http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda<http://www.linkedin.com/in/miconda>
Kamailio Advanced Training - March 9-11, 2020, Berlin -
www.asipto.com<http://www.asipto.com>
Kamailio World Conference - April 27-29, 2020, in Berlin --
www.kamailioworld.com<http://www.kamailioworld.com>
1719
days inactive
1759
days old
3 comments
3 participants
participants (3)
-
Daniel-Constantin Mierla -
Henning Westerholt -
Virgílio Cunha