23 Dec
2013
23 Dec
'13
2:25 p.m.
file http://box.tutpro.com/tmp/gdb_kamailio_20131223_145323 contains gdb bt
of all presence server processes when presence server is not responding to
any new requests. looks like several processes are in futexlock.h if that
tells something.
this is with kamailio 4.0.
-- juha
23 Dec
23 Dec
4:35 p.m.
Juha Heinanen writes:
file
http://box.tutpro.com/tmp/gdb_kamailio_20131223_145323 contains gdb bt
of all presence server processes when presence server is not responding to
any new requests. looks like several processes are in futexlock.h if that
tells something.
this is with kamailio 4.0.
actually, looks like it was with an older version of kamailio. will
upgrade and see if hangup happens again.
-- juha
24 Dec
24 Dec
12:36 a.m.
On 23/12/13 14:25, Juha Heinanen wrote:
file
http://box.tutpro.com/tmp/gdb_kamailio_20131223_145323 contains gdb bt
of all presence server processes when presence server is not responding to
any new requests. looks like several processes are in futexlock.h if that
tells something.
It is a sign of deadlock.
I looked quickly over the code and it seems that in 4.0 there are some
error cases when an acquired lock is not released.
Didn't have the time to make a fix, but if someone has time before I can
get back to it, look in pua module, in send_subscribe.c,
send_subscribe(...) function.
If the module is not in PUA_DB_ONLY, there is a lock acquired:
lock_get(&HashT->p_records[hash_code].lock);
And in the following lines of code I could spot some 'goto error'
without a lock_release(). To get a patch, I would need more time to spot
all the cases, which I don't have for the moment. Maybe someone else can
jump in, otherwise I will look over it when I get the first chance.
Cheers,
Daniel
this is with kamailio 4.0.
-- juha
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
26 Dec
26 Dec
4:55 p.m.
Daniel-Constantin Mierla writes:
I looked quickly over the code and it seems that in
4.0 there are some
error cases when an acquired lock is not released.
yes, there was a few error and done goto cases where lock was not
released. hopefully i caught them all.
if i don't see any objections, i'll cherry pick them in a few days to
stable releases.
-- juha
5:15 p.m.
i very thanks you to answer my question so quickly. so there are no problem in my add
codes ?
27 Dec
27 Dec
4:21 a.m.
dear : now i just register and unregister ,the kamailio stop ,why?
below is bebug:
DEBUG: <core> [parser/msg_parser.c:629]: parse_msg(): method: <REGISTER>
8(3563) DEBUG: <core> [parser/msg_parser.c:631]: parse_msg(): uri:
<sip:192.168.1.113>
8(3563) DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): version:
<SIP/2.0>
8(3563) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param
type 235, <rport> = <n/a>; state=6
8(3563) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param
type 232, <branch> = <z9hG4bKPjUpioznTxJADwiMJzDCFfcZD707rrtXpc>; state=16
8(3563) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header
reached, state=5
8(3563) DEBUG: <core> [parser/msg_parser.c:517]: parse_headers(): parse_headers:
Via found, flags=2
8(3563) DEBUG: <core> [parser/msg_parser.c:519]: parse_headers(): parse_headers:
this is the first via
8(3563) DEBUG: <core> [receive.c:152]: receive_msg(): After parse_msg...
8(3563) DEBUG: <core> [receive.c:193]: receive_msg(): preparing to run routing
scripts...
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=464 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=574 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=569 a=25
n=mf_process_maxfwd_header
8(3563) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 70
8(3563) DEBUG: maxfwd [maxfwd.c:161]: process_maxfwd_header(): value 70 decreased to 16
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=579 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=574 a=26
n=sanity_check
8(3563) DEBUG: <core> [parser/parse_to.c:799]: parse_to(): end of header reached,
state=10
8(3563) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG:
get_hdr_field: <To> [27]; uri=[sip:elwin@192.168.1.113]
8(3563) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body
[<sip:elwin@192.168.1.113>
]
8(3563) DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field:
cseq <CSeq>: <45784> <REGISTER>
8(3563) DEBUG: <core> [parser/msg_parser.c:208]: get_hdr_field(): DEBUG:
get_hdr_body : content_length=0
8(3563) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of
header
8(3563) DEBUG: <core> [parser/parse_to.c:176]: parse_to_param(): DEBUG: add_param:
tag=GHR.sqyfD0bmoQpfMxGFAVYJZaz2A67M
8(3563) DEBUG: <core> [parser/parse_to.c:799]: parse_to(): end of header reached,
state=29
8(3563) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=467 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=767 a=2
n=return
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=479 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=470 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=479 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=623 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=583 a=24
n=has_totag
8(3563) DEBUG: siputils [checks.c:103]: has_totag(): no totag
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=483 a=24
n=t_check_trans
8(3563) DEBUG: tm [t_lookup.c:1100]: t_check_msg(): DEBUG: t_check_msg: msg id=13 global
id=12 T start=0xffffffffffffffff
8(3563) DEBUG: tm [t_lookup.c:534]: t_lookup_request(): t_lookup_request: start
searching: hash=161, isACK=0
8(3563) DEBUG: tm [t_lookup.c:492]: matching_3261(): DEBUG: RFC3261 transaction matching
failed
8(3563) DEBUG: tm [t_lookup.c:716]: t_lookup_request(): DEBUG: t_lookup_request: no
transaction found
8(3563) DEBUG: tm [t_lookup.c:1169]: t_check_msg(): DEBUG: t_check_msg: msg id=13 global
id=13 T end=(nil)
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=486 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=744 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=731 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=739 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=734 a=27
n=auth_check
8(3563) DEBUG: auth_db [authorize.c:476]: auth_check(): realm [192.168.1.113] table
[subscriber] flags [1]
8(3563) DEBUG: auth [api.c:96]: pre_auth(): auth: digest-algo: parsed value: 0
8(3563) DEBUG: <core> [db_res.c:118]: db_new_result(): allocate 56 bytes for result
set at 0x7f5a38e0ddf0
8(3563) DEBUG: db_mysql [km_res.c:68]: db_mysql_get_columns(): 1 columns returned from
the query
8(3563) DEBUG: <core> [db_res.c:155]: db_allocate_columns(): allocate 8 bytes for
result names at 0x7f5a38e0d710
8(3563) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 4 bytes for
result types at 0x7f5a38e0d630
8(3563) DEBUG: db_mysql [km_res.c:85]: db_mysql_get_columns(): allocate 16 bytes for
RES_NAMES[0] at 0x7f5a38e0de50
8(3563) DEBUG: db_mysql [km_res.c:92]: db_mysql_get_columns():
RES_NAMES(0x7f5a38e0de50)[0]=[password]
8(3563) DEBUG: db_mysql [km_res.c:136]: db_mysql_get_columns(): use DB1_STRING result
type
8(3563) DEBUG: <core> [db_res.c:184]: db_allocate_rows(): allocate 16 bytes for
rows at 0x7f5a38e0d600
8(3563) DEBUG: <core> [db_row.c:119]: db_allocate_row(): allocate 32 bytes for row
values at 0x7f5a38e0d780
8(3563) DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [elwin]
8(3563) DEBUG: auth_db [authorize.c:196]: get_ha1(): HA1 string calculated:
34049bf85f5010d95bb0f9729b71f370
8(3563) DEBUG: auth [api.c:211]: auth_check_response(): check_response: Our result =
'5143b47433f1518159f7341d660de56a'
8(3563) DEBUG: auth [api.c:218]: auth_check_response(): check_response: Authorization is
OK
8(3563) DEBUG: <core> [db_res.c:81]: db_free_columns(): freeing 1 columns
8(3563) DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[0] at
0x7f5a38e0de50
8(3563) DEBUG: <core> [db_res.c:94]: db_free_columns(): freeing result names at
0x7f5a38e0d710
8(3563) DEBUG: <core> [db_res.c:99]: db_free_columns(): freeing result types at
0x7f5a38e0d630
8(3563) DEBUG: <core> [db_res.c:54]: db_free_rows(): freeing 1 rows
8(3563) DEBUG: <core> [db_row.c:97]: db_free_row(): freeing row values at
0x7f5a38e0d780
8(3563) DEBUG: <core> [db_res.c:62]: db_free_rows(): freeing rows at
0x7f5a38e0d600
8(3563) DEBUG: <core> [db_res.c:136]: db_free_result(): freeing result set at
0x7f5a38e0ddf0
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=741 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=739 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=751 a=16 n=if
8(3563) DEBUG: <core> [socket_info.c:589]: grep_sock_info(): grep_sock_info -
checking if host==us: 13==9 && [192.168.1.113] == [127.0.0.1]
8(3563) DEBUG: <core> [socket_info.c:593]: grep_sock_info(): grep_sock_info -
checking if port 5060 (advertise 0) matches port 5060
8(3563) DEBUG: <core> [socket_info.c:589]: grep_sock_info(): grep_sock_info -
checking if host==us: 13==13 && [192.168.1.113] == [192.168.1.113]
8(3563) DEBUG: <core> [socket_info.c:593]: grep_sock_info(): grep_sock_info -
checking if port 5060 (advertise 0) matches port 5060
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=751 a=2
n=return
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=490 a=25
n=remove_hf
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=495 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=491 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=501 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=495 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=501 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=818 a=16 n=if
8(3563) DEBUG: <core> [socket_info.c:589]: grep_sock_info(): grep_sock_info -
checking if host==us: 13==9 && [192.168.1.113] == [127.0.0.1]
8(3563) DEBUG: <core> [socket_info.c:593]: grep_sock_info(): grep_sock_info -
checking if port 5060 (advertise 0) matches port 5060
8(3563) DEBUG: <core> [socket_info.c:589]: grep_sock_info(): grep_sock_info -
checking if host==us: 13==13 && [192.168.1.113] == [192.168.1.113]
8(3563) DEBUG: <core> [socket_info.c:593]: grep_sock_info(): grep_sock_info -
checking if port 5060 (advertise 0) matches port 5060
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=506 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=711 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=686 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=687 a=2
n=return
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=509 a=5 n=route
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=640 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=627 a=25
n=is_method
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=635 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=629 a=41
n=isflagset
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=638 a=16 n=if
8(3563) ERROR: *** cfgtrace: c=[/usr/local/etc/kamailio/kamailio.cfg] l=635 a=25 n=save
8(3563) DEBUG: registrar [reg_mod.c:444]: w_save2(): registrar/reg_mod.c w_save2
function
8(3563) DEBUG: registrar [save.c:839]: save(): registrar/save.c save function
8(3563) DEBUG: registrar [common.c:58]: extract_aor(): registrar/common.c extract_aor
function
8(3563) DEBUG: registrar [save.c:789]: add_contacts(): registrar/save.c add_contacts
function
17(3577) DEBUG: <core> [tcp_main.c:3597]: handle_ser_child(): enter
handle_ser_child
17(3577) : <core> [pass_fd.c:294]: receive_fd(): ERROR: receive_fd: EOF on 15
17(3577) DEBUG: <core> [tcp_main.c:3607]: handle_ser_child(): DBG: handle_ser_child:
dead child 6, pid 3561 (shutting down?)
17(3577) DEBUG: <core> [io_wait.h:617]: io_watch_del(): DBG: io_watch_del (0x89bd40,
15, -1, 0x0) fd_no=22 called
0(3554) ALERT: <core> [main.c:788]: handle_sigs(): child process 3561 exited by a
signal 11
0(3554) ALERT: <core> [main.c:791]: handle_sigs(): core was generated
0(3554) INFO: <core> [main.c:803]: handle_sigs(): INFO: terminating due to
SIGCHLD
15(3575) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
14(3574) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
1(3556) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
2(3557) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
3(3558) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
13(3572) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
5(3560) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
12(3570) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
16(3576) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
7(3562) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
4(3559) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
11(3566) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
17(3577) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
9(3564) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
8(3563) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
10(3565) INFO: <core> [main.c:854]: sig_usr(): INFO: signal 15 received
0(3554) DEBUG: registrar [reg_mod.c:622]: mod_destroy(): enter mod_destroy
0(3554) DEBUG: usrloc [urecord.c:327]: wb_timer(): Binding
'elwin','sip:elwin@192.168.1.112:5060' has expired
0(3554) DEBUG: usrloc [ucontact.c:1286]: uldb_delete_attrs(): trying to delete location
attributes
0(3554) DEBUG: <core> [db_pool.c:102]: pool_remove(): removing connection from the
pool
0(3554) DEBUG: tm [t_funcs.c:118]: tm_shutdown(): DEBUG: tm_shutdown : start
0(3554) DEBUG: tm [t_funcs.c:121]: tm_shutdown(): DEBUG: tm_shutdown : emptying hash
table
0(3554) DEBUG: tm [t_funcs.c:123]: tm_shutdown(): DEBUG: tm_shutdown : removing
semaphores
0(3554) DEBUG: tm [t_funcs.c:125]: tm_shutdown(): DEBUG: tm_shutdown : destroying tmcb
lists
0(3554) DEBUG: tm [t_funcs.c:128]: tm_shutdown(): DEBUG: tm_shutdown : done
0(3554) DEBUG: <core> [mem/shm_mem.c:242]: shm_mem_destroy(): shm_mem_destroy
0(3554) DEBUG: <core> [mem/shm_mem.c:245]: shm_mem_destroy(): destroying the shared
memory lock
0(3554) DEBUG: <core> [main.c:807]: handle_sigs(): terminating due to SIGCHLD
10:41 a.m.
On 26/12/13 16:55, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
OK, thanks for taking care, backporting is fine.
Cheers,
Daniel
--
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
I looked quickly over the code and it seems that
in 4.0 there are some
error cases when an acquired lock is not released.
yes, there was a few error and
done goto cases where lock was not
released. hopefully i caught them all.
if i don't see any objections, i'll cherry pick them in a few days to
stable releases.
28 Dec
28 Dec
4:21 a.m.
hello
can you help me ? i really cannt find other ways to solve this. i just add socket
,then occur so big problem, how i can do this ?
3772
days inactive
3777
days old
7 comments
3 participants
participants (3)
-
Daniel-Constantin Mierla -
Juha Heinanen -
文/kl