[OpenSER-Devel] [ openser-Bugs-1783705 ] SIPTRACE: date column contains invalid data

SourceForge.net noreply at sourceforge.net
Wed Aug 29 18:33:35 CEST 2007


Bugs item #1783705, was opened at 2007-08-29 00:22
Message generated for change (Comment added) made by norm_brandinger
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1783705&group_id=139143

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: ver devel
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Nobody/Anonymous (nobody)
Assigned to: Daniel-Constantin Mierla (miconda)
Summary: SIPTRACE: date column contains invalid data

Initial Comment:
This is an intermittent problem.

The resulting date column contains "0000-00-00 00:00:00" when the invalid data is attempted to be inserted.

Turning on the MySQL logging facility (/etc/mysql/my.cnf)
produced the following:

29 Query insert into sip_trace (...,date,...) values (...,'1493958-10-30 11:27:37',...)

The problem appears to be isolated to records with an 'in' direction.

Below is an 'out' direction record.

28 Query insert into sip_trace (...,date,...) values
 (...,'2007-08-28 20:08:25',...)

----------------------------------------------------------------------

Comment By: Norm Brandinger (norm_brandinger)
Date: 2007-08-29 16:33

Message:
Logged In: YES 
user_id=1786021
Originator: NO

Hi Henning,

The bt doesn't appear very useful.

Program terminated with signal 11, Segmentation fault.
#0  0x00002ad143f0f1bb in strftime_l () from /lib/libc.so.6
(gdb) bt
#0  0x00002ad143f0f1bb in strftime_l () from /lib/libc.so.6
#1  0x0000000000000000 in ?? ()
(gdb) 

log:

openser[5478]: siptrace:trace_sl_onreply_out: dest
[udp:209.102.227.253:5060]
openser[5478]: trace_sl_onreply_out: storing info...
openser[5472]: core:handle_sigs: child process 5479 exited by a signal 11
openser[5472]: core:handle_sigs: core was generated
openser[5472]: core:handle_sigs: terminating due to SIGCHLD
openser[5488]: core:sig_usr: signal 15 received
openser[5487]: core:sig_usr: signal 15 received

Norm


----------------------------------------------------------------------

Comment By: Henning Westerholt (henningw)
Date: 2007-08-29 16:05

Message:
Logged In: YES 
user_id=337916
Originator: NO

Hello Norman,

i've add a few more checks against time conversation failures. strftime
could sometimes return unspecified data, this could lead to an crash.
Perhaps you can do another short test? 
But i've no idea what source introduces the invalid data.

Thank you,

Henning

----------------------------------------------------------------------

Comment By: Norm Brandinger (norm_brandinger)
Date: 2007-08-29 12:41

Message:
Logged In: YES 
user_id=1786021
Originator: NO

Program terminated with signal 11, Segmentation fault.
#0  0x00002b0334efe1bb in strftime_l () from /lib/libc.so.6
(gdb) bt
#0  0x00002b0334efe1bb in strftime_l () from /lib/libc.so.6
#1  0x000000000049eead in db_time2str (_v=7955998463975842721, 
    _s=0x2b03353ce0f5 "NVITE, NOTIFY, OPTIONS, REFER\\r\\nContent-Type:
application/sdp\\r\\n\\r\\nv=0\\r\\no=- 5914140 5914140 IN IP4
192.168.1.200\\r\\ns=-\\r\\nc=IN IP4 192.168.1.200\\r\\nt=0 0\\r\\nm=audio
16468 RTP/AVP 0 2 4 8 18 96 9"..., _l=0x7fff7626fde4) at db/db_ut.c:168
#2  0x00002b03351cbc64 in val2str (_c=<value optimized out>,
_v=0x2b03351be580, 
    _s=0x2b03353ce0f4 "'NVITE, NOTIFY, OPTIONS, REFER\\r\\nContent-Type:
application/sdp\\r\\n\\r\\nv=0\\r\\no=- 5914140 5914140 IN IP4
192.168.1.200\\r\\ns=-\\r\\nc=IN IP4 192.168.1.200\\r\\nt=0 0\\r\\nm=audio
16468 RTP/AVP 0 2 4 8 18 96 "..., _len=0x7fff7626fde4) at val.c:205
#3  0x000000000049e2d5 in db_print_values (_c=0x8a2e88, 
    _b=0x2b03353cdf09 "'SIP/2.0 100 Trying\\r\\nVia: SIP/2.0/UDP
192.168.1.200:5060;branch=z9hG4bK-8e560106;rport=5060;received=209.102.227.253\\r\\nFrom:
\\\"9087472063\\\"
<sip:9087472063 at openser2.goes.com>;tag=479a9b41349f264eo0"..., _l=65431,
_v=0x1ea, _n=10, val2str=0x2b03351cbaf0 <val2str>)
    at db/db_ut.c:223
#4  0x00002b03351c8bd9 in db_mysql_insert (_h=0x8a2e88, _k=<value
optimized out>, _v=0x7fff7626fe70, _n=10) at dbase.c:483
#5  0x00002b033dde3309 in trace_sl_onreply_out (req=<value optimized out>,
sl_param=<value optimized out>) at siptrace.c:1367
#6  0x00002b0337bdd87b in run_sl_callbacks (req=0x8a3098, buffer=<value
optimized out>, code=<value optimized out>, reason=<value optimized out>, 
    to=0x2b03351be580) at sl_cb.c:88
#7  0x00002b0337bde3a0 in sl_send_reply_helper (msg=0x8a3098, code=100,
text=0x7fff76270170, tag=0x0) at sl_funcs.c:185
#8  0x00002b0337bdce94 in w_sl_send_reply (msg=0x8a3098, str1=<value
optimized out>, str2=0x874148 "X\205{") at sl.c:240
#9  0x000000000040d8ca in do_action (a=0x7b85e8, msg=0x8a3098) at
action.c:886
#10 0x000000000040c6d3 in run_action_list (a=<value optimized out>,
msg=0x8a3098) at action.c:131
#11 0x000000000040e4cc in do_action (a=0x73c9b8, msg=0x8a3098) at
action.c:111
#12 0x000000000040c6d3 in run_action_list (a=<value optimized out>,
msg=0x8a3098) at action.c:131
#13 0x000000000040f497 in do_action (a=0x73caf8, msg=0x8a3098) at
action.c:804
#14 0x000000000040c6d3 in run_action_list (a=<value optimized out>,
msg=0x8a3098) at action.c:131
#15 0x00000000004104f0 in run_top_route (a=0x737bd0, msg=0x8a3098) at
action.c:111
#16 0x0000000000442e0f in receive_msg (buf=0x2b033ea235e8 "§", len=926,
rcv_info=0x7fff76270d00) at receive.c:156
#17 0x0000000000474ccf in udp_rcv_loop () at udp_server.c:451
#18 0x000000000042e319 in main_loop () at main.c:815
#19 0x000000000042fd1b in main (argc=<value optimized out>, argv=<value
optimized out>) at main.c:1399
(gdb) 

----------------------------------------------------------------------

Comment By: Daniel-Constantin Mierla (miconda)
Date: 2007-08-29 12:24

Message:
Logged In: YES 
user_id=1246013
Originator: NO

Please paste the backtrace as well.

----------------------------------------------------------------------

Comment By: Norm Brandinger (norm_brandinger)
Date: 2007-08-29 12:12

Message:
Logged In: YES 
user_id=1786021
Originator: NO

Changing to debug=9 causes a core from siptrace very quickly (not the
first call to siptrace).

openser[18109]: sl:run_sl_callbacks: callback id 0 entered 
openser[18109]: parse_headers: flags=40 
openser[18109]: siptrace:trace_sl_onreply_out: dest
[udp:209.102.227.253:5060] 
openser[18109]: trace_sl_onreply_out: storing info... 
openser[18106]: core:handle_sigs: child process 18112 exited by a signal
11 
openser[18106]: core:handle_sigs: core was generated 
openser[18106]: core:handle_sigs: child process 18113 exited by a signal
11 
openser[18106]: core:handle_sigs: core was generated 
openser[18106]: core:handle_sigs: terminating due to SIGCHLD 
openser[18115]: core:sig_usr: signal 15 received 
openser[18128]: core:sig_usr: signal 15 received 
openser[18126]: core:sig_usr: signal 15 received

----------------------------------------------------------------------

Comment By: Norm Brandinger (norm_brandinger)
Date: 2007-08-29 11:58

Message:
Logged In: YES 
user_id=1786021
Originator: NO

Testing this morning shows the failure happening for both 'in' and 'out'
trace entries.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1783705&group_id=139143



More information about the Devel mailing list