[OpenSER-Devel] memory leak in canceled call with diversion header

Fri Feb 1 03:57:43 UTC 2008

Hi,
Looking for advice on a memory problem in openser v1.2.3.
A simple call is canceled, but the memory associated with the 
'msg->diversion->parsed' is leaking (Invite contains a 'Diversion' header).
Processing the 487 appears to be running tm callbacks that parse the 
message (while allocating memory), which do not later get freed.

In general terms, what is happening during these steps?
1.
msg_translator.c: build_res_buf_from_sip_res

2.
build_res_from_sip_res: copied size: orig:97, new: 36, rest: 642
msg= SIP/2.0 487 Request terminated

3.
What is the callback id? As in this example:
  DBG: trans=0x4849523c, callback type 128, id 1 entered

Here is a part of a memlog trace that I hope is readable.
The memory at 0x81ab378 is the leak.

Regards,
will

Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 800) called 
from receive.c: receive_msg(81)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 800) returns 
address 0x81a8620 frag. 0x81a8608 (size=800) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: SIP Reply  (status):
Jan 31 16:12:05 www /openser[64400]:  version: <SIP/2.0>
Jan 31 16:12:05 www /openser[64400]:  status:  <487>
Jan 31 16:12:05 www /openser[64400]:  reason:  <Request terminated>
Jan 31 16:12:05 www /openser[64400]: parse_headers: flags=2
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) called 
from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) returns 
address 0x81a8bfc frag. 0x81a8be4 (size=36) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 116) called 
from parser/msg_parser.c: get_hdr_field(109)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 116) returns 
address 0x81a91cc frag. 0x81a91b4 (size=116) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) called 
from parser/parse_via.c: parse_via(1817)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) returns 
address 0x81ab238 frag. 0x81ab220 (size=32) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: Found param type 232, <branch> = 
<z9hG4bKe6d4.62185f65.0>; state=9
Jan 31 16:12:05 www /openser[64400]: parse_via: next_via
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 116) called 
from parser/parse_via.c: parse_via(1981)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 116) returns 
address 0x81a89c4 frag. 0x81a89ac (size=116) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) called 
from parser/parse_via.c: parse_via(1817)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) returns 
address 0x81a8ab8 frag. 0x81a8aa0 (size=32) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: Found param type 232, <branch> = 
<z9hG4bK221.43267-64.1.43268>; state=9
Jan 31 16:12:05 www /openser[64400]: parse_via: next_via
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 116) called 
from parser/parse_via.c: parse_via(1981)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 116) returns 
address 0x81a93c8 frag. 0x81a93b0 (size=212) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) called 
from parser/parse_via.c: parse_via(1817)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) returns 
address 0x81a9ebc frag. 0x81a9ea4 (size=32) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: Found param type 232, <branch> = 
<z9hG4bK90.8559-64.21.8560>; state=16
Jan 31 16:12:05 www /openser[64400]: end of header reached, state=5
Jan 31 16:12:05 www /openser[64400]: end of header reached, state=5
Jan 31 16:12:05 www /openser[64400]: parse_headers: Via found, flags=2
Jan 31 16:12:05 www /openser[64400]: parse_headers: this is the first via
Jan 31 16:12:05 www /openser[64400]: After parse_msg...
Jan 31 16:12:05 www /openser[64400]: DEBUG:forward_reply: found module 
tm, passing reply to it
Jan 31 16:12:05 www /openser[64400]: DEBUG: t_check: start=0xffffffff
Jan 31 16:12:05 www /openser[64400]: parse_headers: flags=22
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) called 
from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) returns 
address 0x81a907c frag. 0x81a9064 (size=36) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) called 
from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) returns 
address 0x81a8f80 frag. 0x81a8f68 (size=36) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 212) called 
from parser/msg_parser.c: get_hdr_field(156)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 212) returns 
address 0x81ab0fc frag. 0x81ab0e4 (size=268) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 24) called 
from parser/parse_to.c: parse_to_param(278)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 24) returns 
address 0x81a8e4c frag. 0x81a8e34 (size=24) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: DEBUG: add_param: tag=933.31127-63.1
Jan 31 16:12:05 www /openser[64400]: DEBUG:parse_to:end of header 
reached, state=29
Jan 31 16:12:05 www /openser[64400]: DBUG:parse_to: display={}, 
ruri={sip:+12902000006 at b0.qa2.l1.test.com}
Jan 31 16:12:05 www /openser[64400]: DEBUG: get_hdr_field: <To> [59]; 
uri=[sip:+12902000006 at b0.qa2.l1.test.com]
Jan 31 16:12:05 www /openser[64400]: DEBUG: to body 
[<sip:+12902000006 at b0.qa2.l1.test.com>]
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) called 
from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 36) returns 
address 0x81a8fd4 frag. 0x81a8fbc (size=36) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 24) called 
from parser/msg_parser.c: get_hdr_field(132)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 24) returns 
address 0x81a8ee8 frag. 0x81a8ed0 (size=24) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: get_hdr_field: cseq <CSeq>: <101> 
<INVITE>
Jan 31 16:12:05 www /openser[64400]: parse_headers: flags=8
Jan 31 16:12:05 www /openser[64400]: DEBUG: t_reply_matching: hash 19822 
label 1458929958 branch 0
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:REF_UNSAFE: after is 1
Jan 31 16:12:05 www /openser[64400]: DEBUG: t_reply_matching: reply 
matched (T=0x4849523c)!
Jan 31 16:12:05 www /openser[64400]: DBG: trans=0x4849523c, callback 
type 2, id 1 entered
Jan 31 16:12:05 www /openser[64400]: parse_headers: flags=8
Jan 31 16:12:05 www /openser[64400]: DEBUG: t_check: end=0x4849523c
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:reply_received: org. 
status uas=180, uac[0]=180 local=0 is_invite=1)
Jan 31 16:12:05 www /openser[64400]: parse_headers: flags=8
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:build_local: using 
FROM=<From:"user555555555 TrailBlazer (7007)" 
<sip:12901300001 at 2356.b0.qa2.l1.test.c
om>;tag=221.43267-64.1^M >, 
TO=<To:<sip:+12902000006 at b0.qa2.l1.test.com>;tag=933.31127-63.1^M >, 
CSEQ_N=<CSeq:101>
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 70) called 
from msg_translator.c: via_builder(2019)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 72) returns 
address 0x81aafc0 frag. 0x81aafa8 (size=72) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x482c7000, 370) called 
from t_msgbuilder.c: build_local(290)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x482c7000, 372) returns 
address 0x4849ef24 frag. 0x4849ef0c (size=372) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81aafc0), 
called from t_msgbuilder.c: build_local(333)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81aafa8 
alloc'ed from msg_translator.c: via_builder(2019)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x482c7000, 0x4849ef24), 
called from t_reply.c: send_ack(294)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x4849ef0c 
alloc'ed from t_msgbuilder.c: build_local(290)
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:t_should_relay_response: 
T_code=180, new_code=487
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:t_pick_branch: picked 
branch 0, code 487
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:t_should_relay_response: 
dns-failover test: branch=0, last_recv=487, flags=2
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:relay_reply: branch=0, 
save=0, relay=0
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) called 
from data_lump.c: del_lump(295)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 32) returns 
address 0x81a9a9c frag. 0x81a9a84 (size=32) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]:  old size: 739, new size: 678
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 679) called 
from msg_translator.c: build_res_buf_from_sip_res(1625)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 680) returns 
address 0x81ab860 frag. 0x81ab848 (size=1172) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: build_res_from_sip_res: copied 
size: orig:97, new: 36, rest: 642 msg= SIP/2.0 487 Request terminated^M 
Via:SIP/2.
0/UDP 10.88.228.163:49152;branch=z9hG4bK221.43267-64.1.43268,SIP/2.0/UDP 
192.168.64.21:5060;branch=z9hG4bK90.8559-64.21.8560^M 
From:"user555555555 TrailBlazer (7007)" <sip:12901
300001 at 2356.b0.qa2.l1.test.com>;tag=221.43267-64.1^M 
To:<sip:+12902000006 at b0.qa2.l1.test.com>;tag=933.31127-63.1^M CSeq:101 
INVITE^M Call-ID:2237-106271537193 at 2356.b0.qa2.l1.test.com^M 
Max-Forwards:70^M Content-Length:0^M 
Record-Route:<sip:10.88.228.140:49152;lr>,<sip:10.88.128.125;ftag=221.43267-64.1;did=51e.96e13d47;lr>,<sip:10.88.228.163:49152;lr
 >^M Contact:<sip:12902000001 at 10.88.228.140:49155>^M 
Remote-Party-ID:<sip:12902000001 at 2354.b0.qa2.l1.test.com>^M ^M
Jan 31 16:12:05 www /openser[64400]: qm_free(0x482c7000, 0x4849f0c8), 
called from mem/shm_mem.c: sh_realloc(85)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x4849f0b0 
alloc'ed from mem/shm_mem.c: sh_realloc(86)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x482c7000, 678) called 
from mem/shm_mem.c: sh_realloc(86)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x482c7000, 680) returns 
address 0x4849f0c8 frag. 0x4849f0b0 (size=852) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:set_timer: relative 
timeout is 500000
Jan 31 16:12:05 www /openser[64400]: DEBUG: add_to_tail_of_timer[4]: 
0x48495304 (797700000)
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:set_timer: relative 
timeout is 30
Jan 31 16:12:05 www /openser[64400]: DEBUG: add_to_tail_of_timer[0]: 
0x48495320 (827)
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:relay_reply: sent 
buf=0x81ab860: SIP/2.0 4..., shmem=0x4849f0c8: SIP/2.0 4
Jan 31 16:12:05 www /openser[64400]: DBG: trans=0x4849523c, callback 
type 128, id 1 entered

Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 212) called 
from parser/parse_diversion.c: parse_diversion_header(54)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 212) returns 
address 0x81ab378 frag. 0x81ab360 (size=388) on 1 -th hit
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 24) called 
from parser/parse_to.c: parse_to_param(278)
Jan 31 16:12:05 www /openser[64400]: qm_malloc(0x8151120, 24) returns 
address 0x81a9788 frag. 0x81a9770 (size=32) on 1 -th hit

Jan 31 16:12:05 www /openser[64400]: DEBUG: add_param: reason=follow-me
Jan 31 16:12:05 www /openser[64400]: DEBUG:parse_to:end of header 
reached, state=29
Jan 31 16:12:05 www /openser[64400]: DBUG:parse_to: 
display={"TrailBlazer Counting Sheep"}, 
ruri={sip:+12901300009 at 2356.b0.qa2.l1.test.com}

Jan 31 16:12:05 www /openser[64400]: DBG: trans=0x4849523c, callback 
type 128, id 0 entered
Jan 31 16:12:05 www /openser[64400]: DEBUG:dialog:next_state_dlg: dialog 
0x48499250 changed from state 2 to state 5, due event 4
Jan 31 16:12:05 www /openser[64400]: DEBUG:dialog:dlg_onreply: dialog 
0x48499250 failed (negative reply)
Jan 31 16:12:05 www /openser[64400]: DBUG:dialog:unref_dlg: unref dlg 
0x48499250 with 1 -> 1
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81ab860), 
called from t_reply.c: relay_reply(1158)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81ab848 
alloc'ed from msg_translator.c: build_res_buf_from_sip_res(1625)
Jan 31 16:12:05 www /openser[64400]: DEBUG: cleanup_uac_timers: RETR/FR 
timers reset
Jan 31 16:12:05 www /openser[64400]: DEBUG:tm:UNREF_UNSAFE: after is 0
Jan 31 16:12:05 www /openser[64400]: DEBUG:destroy_avp_list: destroying 
list 0x0
Jan 31 16:12:05 www /openser[64400]: receive_msg: cleaning up
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81ab238), 
called from parser/parse_via.c: free_via_param_list(2014)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81ab220 
alloc'ed from parser/parse_via.c: parse_via(1817)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a91cc), 
called from parser/parse_via.c: free_via_list(2026)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a91b4 
alloc'ed from parser/msg_parser.c: get_hdr_field(109)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8ab8), 
called from parser/parse_via.c: free_via_param_list(2014)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8aa0 
alloc'ed from parser/parse_via.c: parse_via(1817)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a89c4), 
called from parser/parse_via.c: free_via_list(2026)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a89ac 
alloc'ed from parser/parse_via.c: parse_via(1981)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a9ebc), 
called from parser/parse_via.c: free_via_param_list(2014)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a9ea4 
alloc'ed from parser/parse_via.c: parse_via(1817)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a93c8), 
called from parser/parse_via.c: free_via_list(2026)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a93b0 
alloc'ed from parser/parse_via.c: parse_via(1981)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8bfc), 
called from parser/hf.c: free_hdr_field_lst(208)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8be4 
alloc'ed from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a907c), 
called from parser/hf.c: free_hdr_field_lst(208)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a9064 
alloc'ed from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8e4c), 
called from parser/parse_to.c: free_to_params(62)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8e34 
alloc'ed from parser/parse_to.c: parse_to_param(278)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81ab0fc), 
called from parser/parse_to.c: free_to(71)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81ab0e4 
alloc'ed from parser/msg_parser.c: get_hdr_field(156)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8f80), 
called from parser/hf.c: free_hdr_field_lst(208)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8f68 
alloc'ed from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8ee8), 
called from parser/parse_cseq.c: free_cseq(104)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8ed0 
alloc'ed from parser/msg_parser.c: get_hdr_field(132)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8fd4), 
called from parser/hf.c: free_hdr_field_lst(208)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8fbc 
alloc'ed from parser/msg_parser.c: parse_headers(312)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a9a9c), 
called from data_lump.c: free_lump_list(426)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a9a84 
alloc'ed from data_lump.c: del_lump(295)
Jan 31 16:12:05 www /openser[64400]: qm_free(0x8151120, 0x81a8620), 
called from receive.c: receive_msg(208)
Jan 31 16:12:05 www /openser[64400]: qm_free: freeing frag. 0x81a8608 
alloc'ed from receive.c: receive_msg(81)