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
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
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@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
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
i very thanks you to answer my question so quickly. so there are no problem in my add codes ?
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
On 26/12/13 16:55, Juha Heinanen wrote:
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.
OK, thanks for taking care, backporting is fine.
Cheers, Daniel
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 ?
-
Daniel-Constantin Mierla -
Juha Heinanen -
文/kl