Bugs item #1783705, was opened at 2007-08-29 00:22
Message generated for change (Comment added) made by henningw
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: Henning Westerholt (henningw)
Date: 2007-08-30 11:21
Message:
Logged In: YES
user_id=337916
Originator: NO
VAL_TIME returns its value as time_t, this is on most machines simply an
int. And time_t espected from the db_time2str, too. The error is probably
in siptrace.c, the time is here stored in an int, and not in an time_t.
This could break on machines where time_t is not an int. I've fixed this.
Could you please do another test? I'll review further usage of the time
datatypes in the modules.
Henning
----------------------------------------------------------------------
Comment By: Norm Brandinger (norm_brandinger)
Date: 2007-08-29 22:20
Message:
Logged In: YES
user_id=1786021
Originator: NO
In modules/mysql/val.c I casted the VAL_TIME() macro to an (unsigned int).
This appears to have corrected both the core and the failed insert into
sip_trace.
I changed line 205 to:
if (db_time2str((unsigned int)VAL_TIME(_v), _s, _len) < 0) {
The machine I'm running is using a 64-bit processor and perhaps this is
related to the problem.
A review of the codebase shows that the flatstore and perlvdb modules both
used the same (unsigned int) casting for VAL_TIME().
The following modules ( acc unixodbc usrloc postgres ) use VAL_TIME()
without casting. It is probably a good idea to review these modules to
determine if there is a potential failure waiting to happen on 64-bit
machines. Obviously, it would be better to modify VAL_TIME() than to worry
about castings in every module that may make use of it.
----------------------------------------------------------------------
Comment By: Norm Brandinger (norm_brandinger)
Date: 2007-08-29 17:18
Message:
Logged In: YES
user_id=1786021
Originator: NO
A little more info from this bt.
Program terminated with signal 11, Segmentation fault.
#0 0x00002aca1e51b1bb in strftime_l () from /lib/libc.so.6
(gdb) bt
#0 0x00002aca1e51b1bb in strftime_l () from /lib/libc.so.6
#1 0x00000000004a193f in db_time2str (_v=7955998463975860683,
_s=0x2aca1e9eb105 "71544\\\"\\r\\nContact: \\\"8101\\\"
<sip:[EMAIL PROTECTED]:5061>;expires=3600\\r\\nUser-Agent:
Sipura/SPA841-3.1.4(a)\\r\\nContent-Length: 0\\r\\nAllow: ACK, BYE, CANCEL,
INFO, INVITE, NOTIFY, OPTIONS, REFER\\r\\n\\"..., _l=0x7fff8ced43a4) at
db/db_ut.c:171
#2 0x00002aca1e7e8c64 in val2str (_c=<value optimized out>,
_v=0x2aca1e7db580,
_s=0x2aca1e9eb104 "e71544\\\"\\r\\nContact: \\\"8101\\\"
<sip:[EMAIL PROTECTED]:5061>;expires=3600\\r\\nUser-Agent:
Sipura/SPA841-3.1.4(a)\\r\\nContent-Length: 0\\r\\nAllow: ACK, BYE, CANCEL,
INFO, INVITE, NOTIFY, OPTIONS, REFER\\r\\n"..., _len=0x7fff8ced43a4) at
val.c:205
#3 0x00000000004a14b1 in db_print_values (_c=0x8a70e8,
_b=0x2aca1e9eaf09 "'SIP/2.0 100 Trying\\r\\nVia: SIP/2.0/UDP
192.168.1.200:5061;branch=z9hG4bK-e9878a28;rport=5061;received=209.102.227.253\\r\\nFrom:
\\\"8101\\\" <sip:[EMAIL PROTECTED]>;tag=47c3583e16688c12o1\\r\\nTo:
\\\"81"..., _l=65431, _v=0x1fa, _n=10, val2str=0x2aca1e7e8af0 <val2str>)
at db/db_ut.c:234
#4 0x00002aca1e7e5bd9 in db_mysql_insert (_h=0x8a70e8, _k=<value
optimized out>, _v=0x7fff8ced4430, _n=10) at dbase.c:483
#5 0x00002aca27180309 in trace_sl_onreply_out (req=<value optimized out>,
sl_param=<value optimized out>) at siptrace.c:1367
#6 0x00002aca20f7987b in run_sl_callbacks (req=0x8a72f8, buffer=<value
optimized out>, code=<value optimized out>, reason=<value optimized out>,
to=0x2aca1e7db580) at sl_cb.c:88
#7 0x00002aca20f7a390 in sl_send_reply_helper (msg=0x8a72f8, code=100,
text=0x7fff8ced4730, tag=0x0) at sl_funcs.c:185
#8 0x00002aca20f78e94 in w_sl_send_reply (msg=0x8a72f8, str1=<value
optimized out>, str2=0x8773c0 "8óz") at sl.c:240
#9 0x000000000040d9da in do_action (a=0x7af3c8, msg=0x8a72f8) at
action.c:886
#10 0x000000000040c7e3 in run_action_list (a=<value optimized out>,
msg=0x8a72f8) at action.c:131
#11 0x000000000040e5dc in do_action (a=0x740d48, msg=0x8a72f8) at
action.c:111
#12 0x000000000040c7e3 in run_action_list (a=<value optimized out>,
msg=0x8a72f8) at action.c:131
#13 0x000000000040f5a7 in do_action (a=0x740de8, msg=0x8a72f8) at
action.c:804
#14 0x000000000040c7e3 in run_action_list (a=<value optimized out>,
msg=0x8a72f8) at action.c:131
#15 0x0000000000410600 in run_top_route (a=0x73c2f0, msg=0x8a72f8) at
action.c:111
#16 0x0000000000444aef in receive_msg (buf=0x2aca27dbfc88 "\002", len=710,
rcv_info=0x7fff8ced52c0) at receive.c:156
#17 0x000000000047764f in udp_rcv_loop () at udp_server.c:451
#18 0x0000000000431221 in main (argc=4, argv=0x7fff8ced54b8) at main.c:806
----------------------------------------------------------------------
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:[EMAIL PROTECTED]>;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
_______________________________________________
Devel mailing list
Devel@openser.org
http://openser.org/cgi-bin/mailman/listinfo/devel
