[OpenSER-Devel] [ openser-Bugs-1998765 ] Openser 1.3.2 Memory Corruption

Tue Jun 24 13:14:19 CEST 2008

Bugs item #1998765, was opened at 2008-06-20 13:37
Message generated for change (Comment added) made by henningw
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1998765&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: None
Group: None
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Scott Mullen (smullen27)
Assigned to: Nobody/Anonymous (nobody)
Summary: Openser 1.3.2 Memory Corruption

Initial Comment:
I currently have a bug opened against openser 1.3.0.  While debugging this issue I decided to uprade to the latest release (1.3.2).  This load too seems to have memory corruption; however it actually causes core dumps.

Below are 6 examples.

I'm fairly certain that one of the culprits for these core dumps is the new code added in openser1.3.1 at revision 3907.  http://openser.svn.sourceforge.net/viewvc/openser/tags/1.3.2/modules/tm/t_hooks.c?view=log#rev3907 

This code is freeing up some memory that was not free'd up in release 1.3.0.  I'll try to dig deeper into the code to understand why this change was made.  

Are there any documents regarding the TM module?  (design???)  
Is there any process to go about determining memory corruption?  It's almost impossible to use tools such as Valgrind because openser allocates all its memory at startup and manages the memory itself.  Are there any built in mechanisms to openser's memory management to help diagnose memory corruption?

Here are six stack traces that show the memory corruption.

#0  free_to (tb=0x81c3138) at parse_to.c:75
75                      foo = tp->next;
(gdb) where
#0  free_to (tb=0x81c3138) at parse_to.c:75
#1  0x080db200 in clean_hdr_field (hf=0xb45397c8) at hf.c:182
#2  0xb7dae267 in run_trans_callbacks (type=2, trans=0xb3f6e320, req=0xb4538c20, rpl=0x81c5cc8, code=300) at t_hooks.c:192
#3  0xb7db4d94 in t_reply_matching (p_msg=0x81c5cc8, p_branch=0xbf86da94) at t_lookup.c:836
#4  0xb7db525b in t_check (p_msg=0x81c5cc8, param_branch=0xbf86da94) at dprint.h:99
#5  0xb7dbffe6 in reply_received (p_msg=0x81c5cc8) at t_reply.c:1333
#6  0x08063ed8 in forward_reply (msg=0x81c5cc8) at forward.c:499
#7  0x080944a2 in receive_msg (
    buf=0x8165000 "SIP/2.0 300 Multiple choices\r\nVia: SIP/2.0/UDP x.x.x.x;branch=z9hG4bK186b.626d4ed1.0,SIP/2.0/UDP y.y.y.y;branch=z9hG4bK186b.4f19ea32.0,SIP/2.0/UDP z.z.z.z:5060;branch=z9hG4bK40ced30"..., len=930, rcv_info=0xbf86dbc4) at receive.c:194
#8  0x080d4485 in udp_rcv_loop () at udp_server.c:438
#9  0x0806c656 in main (argc=7, argv=0xbf86ddb4) at main.c:834

(gdb) where
#0  free_to (tb=0x81c4a78) at parse_to.c:75
#1  0x080db200 in clean_hdr_field (hf=0xb60e1354) at hf.c:182
#2  0xb7ddb267 in run_trans_callbacks (type=2, trans=0xb739bb88, req=0xb60e0788, rpl=0x81c5cc8, code=300) at t_hooks.c:192
#3  0xb7de1d94 in t_reply_matching (p_msg=0x81c5cc8, p_branch=0xbffe8214) at t_lookup.c:836
#4  0xb7de225b in t_check (p_msg=0x81c5cc8, param_branch=0xbffe8214) at dprint.h:99
#5  0xb7decfe6 in reply_received (p_msg=0x81c5cc8) at t_reply.c:1333
#6  0x08063ed8 in forward_reply (msg=0x81c5cc8) at forward.c:499
#7  0x080944a2 in receive_msg (
    buf=0x8165000 "SIP/2.0 300 Multiple choices\r\nVia: SIP/2.0/UDP x.x.x.x;branch=z9hG4bK06ad.c6505b65.0,SIP/2.0/UDP y.y.y.y;branch=z9hG4bK06ad.d99750b4.0,SIP/2.0/UDP z.z.z.z:5060;branch=z9hG4bK300ba7cc"..., len=930, rcv_info=0xbffe8344) at receive.c:194
#8  0x080d4485 in udp_rcv_loop () at udp_server.c:438
#9  0x0806c656 in main (argc=7, argv=0xbffe8534) at main.c:834
(gdb) 

#0  fm_free (qm=0xb3bc4000, p=0x322e3437) at f_malloc.c:333
333             size=f->size;
(gdb) where
#0  fm_free (qm=0xb3bc4000, p=0x322e3437) at f_malloc.c:333
#1  0xb7d61221 in free_cell (dead_cell=0xb5530a68) at h_table.c:175
#2  0xb7d89399 in delete_cell (p_cell=0xb5530a68, unlock=1) at timer.c:963
#3  0xb7d8b02a in timer_routine (ticks=44249, attr=0x0) at timer.c:347
#4  0x080c8845 in start_timer_processes () at timer.c:275
#5  0x0806c38b in main (argc=7, argv=0xbf9c0fd4) at main.c:873
(gdb) 

#0  0xb7e001d9 in t_lookup_request (p_msg=0x81c5cc8, leave_new_locked=1) at hash_func.h:63
63                              ch_h_inc;
(gdb) where
#0  0xb7e001d9 in t_lookup_request (p_msg=0x81c5cc8, leave_new_locked=1) at hash_func.h:63
#1  0xb7e01fed in t_newtran (p_msg=0x81c5cc8) at t_lookup.c:1081
#2  0xb7df7108 in tm_shutdown () at t_funcs.c:94
#3  0xb7e168f7 in w_t_relay (p_msg=0x81c5cc8, proxy=0x0, flags=0x0) at tm.c:926
#4  0x080525e0 in do_action (a=0x8191d90, msg=0x81c5cc8) at action.c:821
#5  0x080549e8 in run_action_list (a=0x8191d90, msg=0x81c5cc8) at action.c:132
#6  0x080a3bac in eval_expr (e=0x8191de8, msg=0x81c5cc8, val=0x0) at route.c:1069
#7  0x080a3629 in eval_expr (e=0x8191e10, msg=0x81c5cc8, val=0x0) at route.c:1376
#8  0x080a35bf in eval_expr (e=0x8191e38, msg=0x81c5cc8, val=0x0) at route.c:1381
#9  0x08051b24 in do_action (a=0x8191f40, msg=0x81c5cc8) at action.c:677
#10 0x080549e8 in run_action_list (a=0x8191f40, msg=0x81c5cc8) at action.c:132
#11 0x080531e2 in do_action (a=0x8184338, msg=0x81c5cc8) at action.c:112
#12 0x080549e8 in run_action_list (a=0x8184338, msg=0x81c5cc8) at action.c:132
#13 0x0805330f in do_action (a=0x81843e8, msg=0x81c5cc8) at action.c:694
#14 0x080549e8 in run_action_list (a=0x817fe78, msg=0x81c5cc8) at action.c:132
#15 0x08054d8a in run_top_route (a=0x817fe78, msg=0x81c5cc8) at action.c:112
#16 0x08094265 in receive_msg (
    buf=0x8165000 "BYE sip:+8885551212 at x.x.x.x:5060 SIP/2.0\r\nVia: SIP/2.0/UDP y.y.y.y:5060;branch=z9hG4bK25346802;rport\r\nRoute: <sip:z.z.z.z:5060;r2=on;lr;ftag=as32cbc1d0>,<sip:v.v.v.v:5060"..., len=490, rcv_info=0xbff3fa94) at receive.c:156
#17 0x080d4485 in udp_rcv_loop () at udp_server.c:438
#18 0x0806c656 in main (argc=7, argv=0xbff3fc84) at main.c:834
(gdb) 

#0  0xb7d891d9 in t_lookup_request (p_msg=0x81c5cc8, leave_new_locked=1) at hash_func.h:63
63                              ch_h_inc;
(gdb) where
#0  0xb7d891d9 in t_lookup_request (p_msg=0x81c5cc8, leave_new_locked=1) at hash_func.h:63
#1  0xb7d8afed in t_newtran (p_msg=0x81c5cc8) at t_lookup.c:1081
#2  0xb7d80108 in tm_shutdown () at t_funcs.c:94
#3  0xb7d9f8f7 in w_t_relay (p_msg=0x81c5cc8, proxy=0x0, flags=0x0) at tm.c:926
#4  0x080525e0 in do_action (a=0x8191d90, msg=0x81c5cc8) at action.c:821
#5  0x080549e8 in run_action_list (a=0x8191d90, msg=0x81c5cc8) at action.c:132
#6  0x080a3bac in eval_expr (e=0x8191de8, msg=0x81c5cc8, val=0x0) at route.c:1069
#7  0x080a3629 in eval_expr (e=0x8191e10, msg=0x81c5cc8, val=0x0) at route.c:1376
#8  0x080a35bf in eval_expr (e=0x8191e38, msg=0x81c5cc8, val=0x0) at route.c:1381
#9  0x08051b24 in do_action (a=0x8191f40, msg=0x81c5cc8) at action.c:677
#10 0x080549e8 in run_action_list (a=0x8191f40, msg=0x81c5cc8) at action.c:132
#11 0x080531e2 in do_action (a=0x8184338, msg=0x81c5cc8) at action.c:112
#12 0x080549e8 in run_action_list (a=0x8184338, msg=0x81c5cc8) at action.c:132
#13 0x0805330f in do_action (a=0x81843e8, msg=0x81c5cc8) at action.c:694
#14 0x080549e8 in run_action_list (a=0x817fe78, msg=0x81c5cc8) at action.c:132
#15 0x08054d8a in run_top_route (a=0x817fe78, msg=0x81c5cc8) at action.c:112
#16 0x08094265 in receive_msg (
    buf=0x8165000 "ACK sip:+18885551212 at x.x.x.x SIP/2.0\r\nCall-ID: 55f6ebc3-07db-4a25-abee-5b61a1d0a5b7 at y.y.y.y\r\nContent-Length: 0\r\nCSeq: 33591 ACK\r\nFrom: \"Bob\" <sip:+18885551212 at z.z.z.z>;tag=4"..., len=493, rcv_info=0xbff10a64) at receive.c:156
#17 0x080d4485 in udp_rcv_loop () at udp_server.c:438
#18 0x0806c656 in main (argc=7, argv=0xbff10c54) at main.c:834
(gdb) 

#0  0xb7d661d9 in t_lookup_request (p_msg=0x81c5cc8, leave_new_locked=1) at hash_func.h:63
63                              ch_h_inc;
(gdb) where
#0  0xb7d661d9 in t_lookup_request (p_msg=0x81c5cc8, leave_new_locked=1) at hash_func.h:63
#1  0xb7d67fed in t_newtran (p_msg=0x81c5cc8) at t_lookup.c:1081
#2  0xb7d5d108 in tm_shutdown () at t_funcs.c:94
#3  0xb7d7c8f7 in w_t_relay (p_msg=0x81c5cc8, proxy=0x0, flags=0x0) at tm.c:926
#4  0x080525e0 in do_action (a=0x8191d90, msg=0x81c5cc8) at action.c:821
#5  0x080549e8 in run_action_list (a=0x8191d90, msg=0x81c5cc8) at action.c:132
#6  0x080a3bac in eval_expr (e=0x8191de8, msg=0x81c5cc8, val=0x0) at route.c:1069
#7  0x080a3629 in eval_expr (e=0x8191e10, msg=0x81c5cc8, val=0x0) at route.c:1376
#8  0x080a35bf in eval_expr (e=0x8191e38, msg=0x81c5cc8, val=0x0) at route.c:1381
#9  0x08051b24 in do_action (a=0x8191f40, msg=0x81c5cc8) at action.c:677
#10 0x080549e8 in run_action_list (a=0x8191f40, msg=0x81c5cc8) at action.c:132
#11 0x080531e2 in do_action (a=0x8184338, msg=0x81c5cc8) at action.c:112
#12 0x080549e8 in run_action_list (a=0x8184338, msg=0x81c5cc8) at action.c:132
#13 0x0805330f in do_action (a=0x81843e8, msg=0x81c5cc8) at action.c:694
#14 0x080549e8 in run_action_list (a=0x817fe78, msg=0x81c5cc8) at action.c:132
#15 0x08054d8a in run_top_route (a=0x817fe78, msg=0x81c5cc8) at action.c:112
#16 0x08094265 in receive_msg (
    buf=0x8165000 "ACK sip:+17774441212 at x.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP y.y.y.y:5060;branch=z9hG4bK3a61eb1d;rport\r\nRoute: <sip:z.z.z.z;lr;ftag=as277e07ff>\r\nFrom: \"Joe\" "..., len=489, rcv_info=0xbfb3ae94) at receive.c:156
#17 0x080d4485 in udp_rcv_loop () at udp_server.c:438
#18 0x0806c656 in main (argc=7, argv=0xbfb3b084) at main.c:834
(gdb) 

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

>Comment By: Henning Westerholt (henningw)
Date: 2008-06-24 11:14

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

Hi Scott,

if you compile with "DDBG_QM_MALLOC" (see Makefile.defs) OpenSER will do
some additional checks agains double frees and such.

Cheers,

Henning

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

Comment By: Ovidiu Sas (osas)
Date: 2008-06-20 15:29

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

If you run with memlog=1, debug=9 and openser compiled with debug info
enabled you will see in the syslogs how memory is used.
In the case of core dump, you will need to search in the logs for the
address that was freed up (when was allocated and if it was already freed
up).

Regards,
Ovidiu Sas

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

Comment By: Scott Mullen (smullen27)
Date: 2008-06-20 15:08

Message:
Logged In: YES 
user_id=2082554
Originator: YES

This is more for detecting memory leaks.  I don't really see how this
would help me to determine memory corruption.  (ie.  Something getting
free'd twice, something getting free'd that is outside of the address space
of the program, etc)

Do you have any pointers as to how this could help me with memory
corruption issues, not memory leaks?

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

Comment By: Ovidiu Sas (osas)
Date: 2008-06-20 14:58

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

Here's a link on how to perform memory debug:
http://www.openser.org/dokuwiki/doku.php/troubleshooting:memory

Regards,
Ovidiu Sas

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

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