[OpenSIPS-Users] Running out memory when sending ack

Tito Cumpen tito at xsvoce.com
Wed Nov 20 19:15:54 CET 2013 

Liviu,


Thanks for your help. I have modified the debug to 4 here I am not seeing
the memory messages but the scenario fails on all occasions even at initial
launch l. Even after restarting the server to remove any possibility of a
memory leak in my previous instance. The fact that ack is not being sent it
causing the callee to drop the call. Here is the debug log:


Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4868]: DBG:core:tcp_send:
buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TCP
192.168.2.74:38602;received=108.xx.xx.184;rport=50456;branch=z9hG4bK1570207620#015#012From:
<sip:brain.gmail@ <http://sip:brain.gmail@192.237.178.40:34145>192.xxx.xx.xx
.40:34145 <http://sip:brain.gmail@192.237.178.40:34145>>;tag=1895987525#015#012To:
<sip:pinky.gmail at 192.xxx.xx.xx:34145>;tag=1763472269#015#012Call-ID:
321959835#015#012CSeq: 21 INVITE#015#012Record-Route:
<sip:192.xxx.xx.xx:5060;lr=on;transport=tcp>#015#012Contact:
<sip:pinky.gmail at 108.xx.xx.184:57277;transport=tcp>#015#012Content-Type:
application/sdp#015#012User-Agent: Linphone/3.6.1
(eXosip2/3.6.0)#015#012Content-Length:
760#015#012#015#012v=0#015#012o=pinky.gmail 3790 1167 IN IP4
192.168.2.122#015#012s=Talk#015#012c=IN IP4 192.168.2.122#015#012t=0
0#015#012a=nortpproxy:yes#015#012a=ice-pwd:6c1f278e2776535c3db87de5#015#012a=ice-ufrag:254135de#015#012m=audio
7078 RTP/AVP 8 0 120 111 110 101#015#012a=rtpmap:120
SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111
vbr=on#015#012a=rtpmap:110 speex/8000#015#012a=fmtp:110
vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101
0-11#015#012a=nortpproxy:yes#015#012a=candidate:1 1 UDP 2130706431
192.168.2.122 7078 typ host#015#012a=candidate:1 2 UDP 2130706430
192.168.2.122 7079 typ host#015#012m=video 9078 RTP/AVP 103
99#015#012a=rtpmap:103 VP8/90000#015#012a=rtpmap:99
MP4V-ES/90000#015#012a=fmtp:99
profile-level-id=3#015#012a=nortpproxy:yes#015#012a=candidate:1 1 UDP
2130706431 192.168.2.122 9078 typ host#015#012a=candidate:1 2 UDP
2130706430 192.168.2.122 9079 typ host#015#012

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4868]: DBG:tm:_reply_light:
reply sent out. buf=0x7d82c0: SIP/2.0 2..., shmem=0x7f635fae9668: SIP/2.0 2

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4868]: DBG:tm:_reply_light:
finished

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4868]: DBG:tm:t_unref_cell:
UNREF_UNSAFE: [0x7f635fa2bbb0] after is 0

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4868]: DBG:seas:process_input:
(Action dispatched,buffer.len=0)

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:tcp_read_req:
content-length= 0

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_msg: SIP
Request:

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_msg:
method:  <ACK>

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_msg:  uri:
    <sip:pinky.gmail at 108.xx.xx.184:57277;transport=tcp>

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_msg:
version: <SIP/2.0>

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=2

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_via_param:
found param type 235, <rport> = <n/a>; state=6

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK926930436>; state=16

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_via: end
of header reached, state=5

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
via found, flags=2

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
this is the first via

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:receive_msg:
After parse_msg...

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:receive_msg:
preparing to run routing scripts...

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=8

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_to_param:
tag=1763472269

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_to: end of
header reached, state=29

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_to:
display={}, ruri={sip:pinky.gmail at 192.xxx.xx.xx:34145}

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:get_hdr_field:
<To> [55]; uri=[sip:pinky.gmail at 192.xxx.xx.xx:34145]

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:get_hdr_field:
to body [<sip:pinky.gmail at 192.xxx.xx.xx:34145>]

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=ffffffffffffffff

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:get_hdr_field:
cseq <CSeq>: <21> <ACK>

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:get_hdr_field:
content_length=0

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:get_hdr_field:
found end of header

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=200

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:rr:is_preloaded:
is_preloaded: No

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:grep_sock_info:
checking if host==us: 14==14 &&  [108.xx.xx.184] == [192.xxx.xx.xx]

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:grep_sock_info:
checking if port 5060 matches port 57277

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:grep_sock_info:
checking if host==us: 14==14 &&  [108.xx.xx.184] == [192.xxx.xx.xx]

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:grep_sock_info:
checking if port 5060 matches port 57277

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:check_self: host
!= me

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:grep_sock_info:
checking if host==us: 14==14 &&  [192.xxx.xx.xx] == [192.xxx.xx.xx]

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:grep_sock_info:
checking if port 5060 matches port 5060

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:rr:after_loose:
Topmost route URI: 'sip:192.xxx.xx.xx:5060;lr=on;transport=tcp' is me

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=200

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:get_hdr_field:
found end of header

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:rr:find_next_route:
No next Route HF found

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:rr:after_loose: No
next URI found!

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:rr:run_rr_callbacks:
callback id 1 entered with <lr=on;transport=tcp>

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:dialog:dlg_onroute:
Route param 'did' not found

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: here is a lose route

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:uri:has_totag: totag
found

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: This has a totag

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: ack received by opensips
sending to app server!

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=ffffffffffffffff

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: received at route 1
sending to seas

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:tm:t_newtran:
transaction on entrance=0xffffffffffffffff

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=ffffffffffffffff

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=78

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:tm:t_lookup_request:
start searching: hash=12733, isACK=1

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_headers:
flags=38

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_to_param:
tag=1895987525

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_to: end of
header reached, state=29

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:parse_to:
display={}, ruri={sip:brain.gmail at 192.xxx.xx.xx:34145}

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:tm:t_lookup_request:
REF_UNSAFE:[0x7f635fa2bbb0] after is 1

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:tm:t_lookup_request:
e2e proxy ACK found

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]:
DBG:tm:cleanup_uac_timers: RETR/FR timers reset

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:seas:w_as_relay_t: as
found ! (app_server_one) processor id = 2

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]:
ERROR:seas:create_as_event_t: no transaction provided...

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: ERROR:seas:w_as_relay_t:
unable to create event code

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:tm:t_unref_cell:
UNREF_UNSAFE: [0x7f635fa2bbb0] after is 0

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]:
DBG:core:destroy_avp_list: destroying list (nil)

Nov 20 17:59:59 mediaproxy2 /sbin/opensips[4858]: DBG:core:receive_msg:
cleaning up







On Wed, Nov 20, 2013 at 3:22 AM, Liviu Chircu <liviu at opensips.org> wrote:

>  Hello Tito,
>
> Firstly, note that OpenSIPS will not use the entire available RAM on the
> box, but rather a predefined value ("-m" parameter, e.g. "-m 128" for a
> 128MB preallocated memory pool).
>
> Does your scenario not work at all or does OpenSIPS start misbehaving
> after some time? The log messages tell us that OpenSIPS has run out of
> memory and is unable to properly process incoming traffic.
>
> Best regards,
>
> Liviu Chircu
> OpenSIPS Developerhttp://www.opensips-solutions.com
>
> On 11/20/2013 07:14 AM, Tito Cumpen wrote:
>
>  Group,
>
>
>
>  I am relaying my invites and loose routes to a sipservlet using the seas
> module and wesip. I am noticing that when acks are sent to opensips it is
> directed to relay those acks to wesip and then back out to the recipient it
> fails to do so. Consequently I see this message being generated and
> eventually a memory problem. I am not seeing the message traverse through
> seas into the my servlet. Take note this is a single call on a server with
> more than sufficient ram. I am using version opensips-1.7.2-tls
>
>
> Thanks,
> Tito
>
>
>
>  Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2038]: here is a loose route
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2038]: This has a totag
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2038]: ack received by opensips
> sending to app server!
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2038]: received at route 1
> sending to seas
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2038]:
> ERROR:seas:create_as_event_t: no transaction provided...
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2038]: ERROR:seas:w_as_relay_t:
> unable to create event code
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2039]: here is a lose route
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2039]: This has a totag
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2039]: received at route 1
> sending to seas
>
> Nov 19 20:21:08 mediaproxy2 /sbin/opensips[2026]:
> INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App
> Servers] [0 Uncomplete AS]
>
> Nov 19 20:21:09 mediaproxy2 /sbin/opensips[2041]: WARNING:core:fm_malloc:
> Not enough free memory, will atempt defragmenation
>
> Nov 19 20:21:09 mediaproxy2 /sbin/opensips[2041]: ERROR:tm:sip_msg_cloner:
> no more share memory
>
> Nov 19 20:21:09 mediaproxy2 /sbin/opensips[2041]: ERROR:tm:new_t: out of
> mem
>
> Nov 19 20:21:09 mediaproxy2 /sbin/opensips[2041]: ERROR:tm:t_newtran:
> new_t failed
>
> Nov 19 20:21:09 mediaproxy2 /sbin/opensips[2026]:
> INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App
> Servers] [0 Uncomplete AS]
>
> Nov 19 20:21:11 mediaproxy2 /sbin/opensips[2026]:
> INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App
> Servers] [0 Uncomplete AS]
>
> Nov 19 20:21:17 mediaproxy2 /sbin/opensips[2038]: here is a lose route
>
> Nov 19 20:21:17 mediaproxy2 /sbin/opensips[2038]: This has a totag
>
> Nov 19 20:21:17 mediaproxy2 /sbin/opensips[2038]: received at route 1
> sending to seas
>
> Nov 19 20:21:17 mediaproxy2 /sbin/opensips[2026]:
> INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App
> Servers] [0 Uncomplete AS]
>
> Nov 19 20:21:17 mediaproxy2 /sbin/opensips[2026]:
> INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App
> Servers] [0 Uncomplete AS]
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2026]:
> INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App
> Servers] [0 Uncomplete AS]
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2031]: WARNING:core:fm_malloc:
> Not enough free memory, will atempt defragmenation
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2031]: ERROR:tm:relay_reply: no
> more share memory
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2031]: WARNING:core:fm_malloc:
> Not enough free memory, will atempt defragmenation
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2031]: ERROR:tm:_reply_light:
> failed to allocate shmem buffer
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2031]: WARNING:core:fm_malloc:
> Not enough free memory, will atempt defragmenation
>
> Nov 19 20:21:38 mediaproxy2 /sbin/opensips[2031]: ERROR:tm:relay_reply: no
> more share memory
>
>
> _______________________________________________
> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20131120/b83eb49b/attachment-0001.htm>

More information about the Users mailing list