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

Wed Aug 29 14:41:34 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 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