Bugs item #2609050, was opened at 2009-02-17 14:26
Message generated for change (Comment added) made by bogdan_iancu
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=2609050&group_id=232389
Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: trunk
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Iñaki Baz (ibc_sf)
Assigned to: Nobody/Anonymous (nobody)
Summary: Segmentation fault in presence module related to MySQL
Initial Comment:
After upgrading to OpenSIPS rev 5320 a server acting as presence server crashes
very often.
There is no traffic at all, just 4 users so very log presence traffic.
syslog:
----------
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:presence:search_event: start event= [dialog]
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:presence:handle_publish: SIP-If-Match header found
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:presence:handle_publish: existing etag = a.1234829890.9781.1.1
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:presence:handle_publish: Expires header found, value= 8484
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_do_prepared_query: new query=|select body,sender from
presentity where domain=? AND username=? AND
event=? AND etag=?|
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_do_prepared_query: prepared statement successfully set...
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_val2bind: added val (0): len=9; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_val2bind: added val (1): len=3; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_val2bind: added val (3): len=21; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7205]:
DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_do_prepared_query: prepared statement successfully set...
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (0): len=21; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (1): len=4; type=3; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (2): len=4; type=3; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (4): len=9; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (5): len=3; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (6): len=6; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_val2bind: added val (7): len=21; type=254; is_null=0
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7204]:
DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 17 11:41:26 presence_server /usr/sbin/opensips_presence[7222]:
CRITICAL:core:receive_fd: EOF on 9
----------------
coredump:
----------------
#0 0x00002ae413496588 in mysql_stmt_prepare () from
/usr/lib/libmysqlclient.so.15
#1 0x00002ae4134989dc in cli_stmt_execute () from /usr/lib/libmysqlclient.so.15
#2 0x00002ae413498495 in mysql_stmt_execute () from
/usr/lib/libmysqlclient.so.15
#3 0x00002ae41332322c in db_mysql_free_result () from
/usr/lib/opensips/modules/db_mysql.so
#4 0x00002ae41332453f in db_mysql_update () from
/usr/lib/opensips/modules/db_mysql.so
#5 0x00002ae414a31185 in update_presentity () from
/usr/lib/opensips/modules/presence.so
#6 0x00002ae414a342d5 in handle_publish () from
/usr/lib/opensips/modules/presence.so
#7 0x000000000040f894 in do_action ()
#8 0x000000000040e0f3 in run_action_list ()
#9 0x0000000000411df5 in do_action ()
#10 0x000000000040e0f3 in run_action_list ()
#11 0x000000000041176f in do_action ()
#12 0x000000000040e0f3 in run_action_list ()
#13 0x0000000000411df5 in do_action ()
#14 0x000000000040e0f3 in run_action_list ()
#15 0x000000000041093a in do_action ()
#16 0x000000000040e0f3 in run_action_list ()
#17 0x000000000041176f in do_action ()
#18 0x000000000040e0f3 in run_action_list ()
#19 0x000000000040e480 in run_top_route ()
#20 0x0000000000441b4c in receive_msg ()
#21 0x0000000000472990 in udp_rcv_loop ()
#22 0x0000000000423917 in main ()
----------------
----------------------------------------------------------------------
>Comment By: Bogdan-Andrei Iancu (bogdan_iancu)
Date: 2009-02-17 16:11
Message:
Hi,
maybe this is related to bug #2608188 - it a report for prepared
statements crashing when reconnecting to mysql server....maybe it is the
same case here...
Regards,
Bogdan
----------------------------------------------------------------------
Comment By: Iñaki Baz (ibc_sf)
Date: 2009-02-17 16:03
Message:
Hi Anca, tested again with rev5323 and a similar error occurs with exactly
the same backtrace.
syslog:
------------
/usr/sbin/opensips_presence[19199]: DBG:core:parse_msg: SIP Request:
/usr/sbin/opensips_presence[19199]: DBG:core:parse_msg: method:
<SUBSCRIBE>
/usr/sbin/opensips_presence[19199]: DBG:core:parse_msg: uri:
<sip:ma...@d
/usr/sbin/opensips_presence[19199]: DBG:core:parse_msg: version:
<SIP/2.0>
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: flags=2
/usr/sbin/opensips_presence[19199]: DBG:core:parse_via_param: found param
type
/usr/sbin/opensips_presence[19199]: DBG:core:parse_via: end of header
reached,
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: via found,
flags=2
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: this is the
first
/usr/sbin/opensips_presence[19199]: DBG:core:receive_msg: After
parse_msg...
/usr/sbin/opensips_presence[19199]: DBG:core:receive_msg: preparing to run
rou
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: flags=100
/usr/sbin/opensips_presence[19199]: DBG:core:parse_via_param: found param
type
/usr/sbin/opensips_presence[19199]: DBG:core:parse_via_param: found param
type
/usr/sbin/opensips_presence[19199]: DBG:core:parse_via_param: found param
type
/usr/sbin/opensips_presence[19199]: DBG:core:parse_via: end of header
reached,
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: via found,
flags=1
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: parse_headers:
thi
/usr/sbin/opensips_presence[19199]: DBG:maxfwd:is_maxfwd_present: value =
69
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: flags=78
/usr/sbin/opensips_presence[19199]: DBG:core:parse_to: end of header
reached,
/usr/sbin/opensips_presence[19199]: DBG:core:parse_to: display={},
ruri={sip:m
/usr/sbin/opensips_presence[19199]: DBG:core:get_hdr_field: <To> [23];
uri=[si
/usr/sbin/opensips_presence[19199]: DBG:core:get_hdr_field: to body
[<sip:manw
/usr/sbin/opensips_presence[19199]: DBG:core:get_hdr_field: cseq <CSeq>:
<410>
/usr/sbin/opensips_presence[19199]: DBG:tm:t_lookup_request: start
searching:
/usr/sbin/opensips_presence[19199]: DBG:tm:matching_3261: RFC3261
transaction
/usr/sbin/opensips_presence[19199]: DBG:tm:t_lookup_request: no
transaction fo
/usr/sbin/opensips_presence[19199]:
/usr/sbin/opensips_presence[19199]: DBG:uri:has_totag: no totag
/usr/sbin/opensips_presence[19199]: DBG:core:tr_eval_string: i=11 j=8
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers: flags=8000000
/usr/sbin/opensips_presence[19199]: 14:56:12 - request from
92.122.79.216:3689
/usr/sbin/opensips_presence[19199]: SUBSCRIBE sip:[email protected]
/usr/sbin/opensips_presence[19199]: DBG:core:parse_to_param: tag=doohb
/usr/sbin/opensips_presence[19199]: DBG:core:parse_to: end of header
reached,
/usr/sbin/opensips_presence[19199]: DBG:core:parse_to: display={"Iñaki"},
ruri
/usr/sbin/opensips_presence[19199]: From: "Iñaki" <sip:[email protected]>
/usr/sbin/opensips_presence[19199]: DBG:core:pv_get_xto_attr: no Display
name
/usr/sbin/opensips_presence[19199]: To: <null> <sip:[email protected]>
/usr/sbin/opensips_presence[19199]: DBG:core:parse_headers:
flags=ffffffffffff
/usr/sbin/opensips_presence[19199]: DBG:core:get_hdr_field:
content_length=0
/usr/sbin/opensips_presence[19199]: DBG:core:get_hdr_field: found end of
heade
/usr/sbin/opensips_presence[19199]: DBG:presence:search_event: start
event= [p
/usr/sbin/opensips_presence[19199]: DBG:presence:extract_sdialog_info:
'Expire
/usr/sbin/opensips_presence[19199]: DBG:presence:extract_sdialog_info:
'To' he
/usr/sbin/opensips_presence[19199]: DBG:presence:extract_sdialog_info:
initial
/usr/sbin/opensips_presence[19199]: DBG:presence:extract_sdialog_info:
subs->c
/usr/sbin/opensips_presence[19199]: DBG:core:print_rr_body: current rr is
<sip
/usr/sbin/opensips_presence[19199]: DBG:core:print_rr_body: current rr is
<sip
/usr/sbin/opensips_presence[19199]: DBG:core:print_rr_body: out rr
[<sip:92.12
/usr/sbin/opensips_presence[19199]: DBG:core:print_rr_body: we have 2
records
/usr/sbin/opensips_presence[19199]:
DBG:db_mysql:db_mysql_do_prepared_query: s
/usr/sbin/opensips_presence[19199]: DBG:db_mysql:db_mysql_val2bind: added
val
/usr/sbin/opensips_presence[19199]: DBG:db_mysql:db_mysql_val2bind: added
val
/usr/sbin/opensips_presence[19199]: DBG:db_mysql:db_mysql_val2bind: added
val
/usr/sbin/opensips_presence[19199]: DBG:db_mysql:db_mysql_val2bind: added
val
/usr/sbin/opensips_presence[19199]:
DBG:db_mysql:db_mysql_do_prepared_query: d
/usr/sbin/opensips_presence[19207]: DBG:core:handle_tcp_child: dead tcp
child
/usr/sbin/opensips_presence[19207]: DBG:core:io_watch_del: io_watch_del
(0x5fe
/usr/sbin/opensips_presence[19207]: CRITICAL:core:receive_fd: EOF on 21
/usr/sbin/opensips_presence[19207]: DBG:core:handle_ser_child: dead child
11,
/usr/sbin/opensips_presence[19207]: DBG:core:io_watch_del: io_watch_del
(0x5fe
/usr/sbin/opensips_presence[19188]: INFO:core:handle_sigs: child process
19199
/usr/sbin/opensips_presence[19188]: INFO:core:handle_sigs: core was
generated
/usr/sbin/opensips_presence[19188]: INFO:core:handle_sigs: terminating due
to
/usr/sbin/opensips_presence[19207]: INFO:core:sig_usr: signal 15 received
------------
Note however that I'm testing presence_dialoginfo module. I will dissable
it now and try again.
PD: There is an ERROR in the logs:
---------
ERROR:db_mysql:db_mysql_do_prepared_query: mysql_stmt_execute() failed:
Lost connection to MySQL server during query
Feb 17 15:02:42 presence_server /usr/sbin/opensips_presence[20031]:
ERROR:presence:update_presentity: inserting new record in database
---------
----------------------------------------------------------------------
Comment By: Anca Vamanu (anca_vamanu)
Date: 2009-02-17 15:00
Message:
Hi Inaki,
I also noticed that there are problems with prepare statements and
operations in presentity table. But I thought that they occur only when
querying, because prepare statements put the result in a static buffer.
Just a couple of minutes ago I took out using prepare statements with
queries.
From your trace it seems that the crash occurs in an update. I don't know
the exact reason why there should be any overflow issues there. Can you
please update to the latest version of trunk and test again? If you will
see the error again, I will take out prepare statements for update also.
regards,
Anca
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=2609050&group_id=232389
_______________________________________________
Devel mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
