[OpenSIPS-Users] OpenSIPS 1.4.2 memory corruption issue under extreme load?
Bogdan-Andrei Iancu
bogdan at voice-system.ro
Wed Mar 4 10:38:17 CET 2009
Hi Joel,
So, the the bogus VIA was received from the network level and not a
result of whatever processing (more or less buggy) in OpenSIPS....
Cool you traced it down.
Regards,
Bogdan
joel garcia wrote:
> Hey Bogdan,
>
> Thanks for responding.
>
> We have resolved our issue. It was a network\carrier issue.
>
> We noticed that all of the corrupt sip messages were coming from 2
> specific SBCs. It took a while, but we were finally able to narrow it
> down. When we dynamically removed those SBCs from the
> carrierroute.conf map, the parser via issue disappeared.
>
> Thanks,
> Joel
>
>
> ------------------------------------------------------------------------
> *From:* Bogdan-Andrei Iancu <bogdan at voice-system.ro>
> *To:* joel garcia <joelphilipgarcia at yahoo.com>
> *Cc:* Serge JF <serge at elasticall.com>; users at lists.opensips.org
> *Sent:* Tuesday, March 3, 2009 8:44:38 AM
> *Subject:* Re: [OpenSIPS-Users] OpenSIPS 1.4.2 memory corruption issue
> under extreme load?
>
> Hi Joel,
>
> whatever you do from the script, it is impossible to change the
> original buffer (which is parsed by the via_parser).
>
> Can you post (or privately sent) the log (debug=6) for such a request
> processing (if possible to capture).
>
> Thanks and regards,
> Bogdan
>
> joel garcia wrote:
> > Hey Bogdan,
> >
> > I'm working with Serge on this. Thank you for the helper facts.
> >
> > The TRACE log is before the error msg in the opensips.log. I've
> attached the log to the bottom.
> >
> > I'm hoping that our changes to the opensips.cfg are the cause of
> these errors. We're currently manipulating $avp(i:25) and $avp(i:35)
> variables to handle different carriers. Do you see anything wrong in
> this logic that could be corrupting the header or msg? Specifically,
> what I notice is that the Carrier-Name is not set in the header for
> this invite. We recently added some logic to default to a particular
> carrier if no carrier is specified.
> >
> > Under volume, we are seeing a large number of these type of parser
> errors in both the header and the msg. I have other examples.
> > I've also added a portion of our route() implementation.
> >
> > Thanks for your assistance,
> > Joel
> >
> >
> > route{
> >
> > xlog("TRACE:ROUTE: time($Ts) src($si:$sp) dst($Ri:$Rp) msg($mb)\n");
> > ...
> > if (is_method("INVITE")) {
> >
> > # set carrier name
> > if (is_present_hf("Carrier-Name")) {
> > $avp(i:25) = $(hdr(Carrier-Name){s.tolower});
> > # valid carrier name passed?
> > switch ($avp(i:25)) {
> > case "carrierA" :
> > $avp(i:25) = "doA";
> > break;
> > case "carrierB" :
> > if ($rU =~ "^\+?1?8[0|6|7|8]{2}[0-9]{5,8}") {
> > # doA needs to be used for 1-800, 1-866, 1-877 or
> 1-888 calls
> > $avp(i:25) = "doA";
> > } else {
> > # doB is required for non 1-800 calls
> > $avp(i:25) = "doB";
> > }
> > default :
> > ...
> > }
> > } else {
> > xlog("L_WARN", "WARN:ROUTE:CARRIER: no
> carrier name specified\n");
> > # dialing to the US or Canada?
> > # We didn't find the Carrier-Name in the
> header. DoweI need to
> > # add the Carrier-Name tag to the header or
> will just setting $avp(i:25) work?
> > if ($rU =~ "^1" || $rU =~ "^\+1") {
> > # doA is the default carrier for US
> and Canadian calls
> > $avp(i:25) = "doA";
> > }
> > ... handle international
> > }
> > }
> > }
> >
> > We also tweak $avp(i:35)
> >
> > route[1] {
> > if ($(hdr(Reason)) != null) {
> > $avp(i:35) = $(hdr(Reason));
> > };
> > if (!t_relay()) {
> > sl_reply_error();
> > };
> > exit;
> > }
> >
> > parse_via error msg logs
> >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]: TRACE:ROUTE:
> time(1235826197) src(63.xx.xx.xx:5060) dst(8.xx.xx.xx:5060) msg(INVITE
> sip:+18566654221 at 4.xx.xx.xx <mailto:18566654221 at 4.xx.xx.xx>:5060 SIP/2.0
> > From: <sip:+18668496441 at 63.xx.xx.xx
> <mailto:18668496441 at 63.xx.xx.xx>:5060>;tag=telstage-67aa-49a935d9
> > To: sip:+18566654221 at 8.xx.xx.xx
> <mailto:18566654221 at 8.xx.xx.xx>;tag=gK02b2b6e2
> > Contact: <sip:63.xx.xx.xx:5060;transport=udp>
> > Call-ID: 49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx>
> > CSeq: 32043 INVITE
> > Content-Length: 177
> > Content-Type: application/sdp
> > Content-Disposition: session; handling=required
> > Route: <sip:8.xx.xx.xx:5060;lr;ftag=telstage%2D67aa%2D49a935d9>
> > Session-Expires: 1800;refresher=uac
> > Supported: timer
> > Max-Forwards: 70
> > Via: SIP/2.0/UDP
> 63.xx.xx.xx:5060;branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > v=0
> > o=Sonus_UAC 8758 21805 IN IP4 4.xx.xx.xx
> > s=SIP Media Capabilities
> > c=IN IP4 4.xx.xx.xx
> > t=0 0
> > m=audio 11750 RTP/AVP 0
> > a=rtpmap:0 PCMU/8000
> > a=sendrecv
> > a=maxptime:20
> > )
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: invalid port number
> <5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf>
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: <SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > From: <sip:+18668496441 at 63.xx.xx.xx
> <mailto:18668496441 at 63.xx.xx.xx>:5060>;tag=telstage-67aa-49a935d9
> > To: sip:+18566654221 at 8.xx.xx.xx
> <mailto:18566654221 at 8.xx.xx.xx>;tag=gK02b2b6e2
> > Call-ID: 49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx>
> > CSeq: 32043 INVITE
> > Record-Route: <sip:8.xx.xx.xx:5060;lr;ftag=telstage-67aa-49a935d9>
> > Accept: application/sdp, application/isup, application/dtmf,
> application/dtmf-relay, multipart/mixed
> > Contact: <sip:+18566654221 at 4.xx.xx.xx
> <mailto:18566654221 at 4.xx.xx.xx>:5060>
> > Allow: INVITE,ACK,CANCEL,BYE,PRACK,UPDATE
> > Content-Length: 177
> > Content-Disposition: session; handling=required
> > Content-Type: application/sdp
> > v=0
> > o=Sonus_UAC 11722 5484 IN IP4 4.xx.xx.xx
> > s=SIP Media Capabilities
> > c=IN IP4 4.xx.xx.xx
> > t=0 0
> > m=audio 22942 RTP/AVP 0
> > a=rtpmap:0 PCMU/8000
> > a=sendrecv
> > a=maxptime:20
> > >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: parsed so far:<SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:get_hdr_field: bad via
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> INFO:core:parse_headers: bad header field
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:tm:t_check: reply cannot be parsed
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: invalid port number
> <5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf>
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: <SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > From: <sip:+18668496441 at 63.xx.xx.xx
> <mailto:18668496441 at 63.xx.xx.xx>:5060>;tag=telstage-67aa-49a935d9
> > To: sip:+18566654221 at 8.xx.xx.xx
> <mailto:18566654221 at 8.xx.xx.xx>;tag=gK02b2b6e2
> > Call-ID: 49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx>
> > CSeq: 32043 INVITE
> > Record-Route: <sip:8.xx.xx.xx:5060;lr;ftag=telstage-67aa-49a935d9>
> > Accept: application/sdp, application/isup, application/dtmf,
> application/dtmf-relay, multipart/mixed
> > Contact: <sip:+18566654221 at 4.xx.xx.xx
> <mailto:18566654221 at 4.xx.xx.xx>:5060>
> > Allow: INVITE,ACK,CANCEL,BYE,PRACK,UPDATE
> > Content-Length: 177
> > Content-Disposition: session; handling=required
> > Content-Type: application/sdp
> > v=0
> > o=Sonus_UAC 11722 5484 IN IP4 4.xx.xx.xx
> > s=SIP Media Capabilities
> > c=IN IP4 4.xx.xx.xx
> > t=0 0
> > m=audio 22942 RTP/AVP 0
> > a=rtpmap:0 PCMU/8000
> > a=sendrecv
> > a=maxptime:20
> > >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: parsed so far:<SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:get_hdr_field: bad via
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> INFO:core:parse_headers: bad header field
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:forward_reply: no 2nd via found in reply
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11609]:
> TRACE:ONREPLY_ROUTE: time(1235826197) src(4.xx.xx.xx:5060)
> dst(8.xx.xx.xx:5060) msg(SIP/2.0 200 OK
> > Via: SIP/2.0/UDP 8.xx.xx.xx;branch=z9hG4bKff9d.4d7cb833.0
> > Via: SIP/2.0/UDP
> 63.xx.xx.xx:5060;branch=z9hG4bK49a935fc-039b-00672428-07d84f2d-3f76ff5a
> > From: <sip:+18666287097 at 63.xx.xx.xx
> <mailto:18666287097 at 63.xx.xx.xx>:5060>;tag=telstage-31e5-49a935fc
> > To: sip:+19197639388 at 8.xx.xx.xx
> <mailto:19197639388 at 8.xx.xx.xx>;tag=gK0ad718b1
> > Call-ID: 49a935fc-039b-00672427-07d84f2d-3f76ff5a at 63.xx.xx.xx
> <mailto:49a935fc-039b-00672427-07d84f2d-3f76ff5a at 63.xx.xx.xx>
> > CSeq: 6600 INVITE
> > Record-Route: <sip:8.xx.xx.xx:5060;lr;ftag=telstage-31e5-49a935fc>
> > Accept: application/sdp, application/isup, application/dtmf,
> application/dtmf-relay, multipart/mixed
> > Contact: <sip:+19197639388 at 4.xx.xx.xx
> <mailto:19197639388 at 4.xx.xx.xx>:5060>
> > Allow: INVITE,ACK,CANCEL,BYE,PRACK,UPDATE
> > Content-Length: 175
> > Content-Disposition: session; handling=required
> > Content-Type: application/sdp
> > v=0
> > o=Sonus_UAC 27689 2463 IN IP4 4.xx.xx.xx
> > s=SIP Media Capabilities
> > c=IN IP4 4.55.20.66
> > t=0 0
> > m=audio 26588 RTP/AVP 0
> > a=rtpmap:0 PCMU/8000
> > a=
> >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: parsed so far:<SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:get_hdr_field: bad via
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> INFO:core:parse_headers: bad header field
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:tm:t_check: reply cannot be parsed
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: invalid port number
> <5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf>
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: <SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > From: <sip:+18668496441 at 63.xx.xx.xx
> <mailto:18668496441 at 63.xx.xx.xx>:5060>;tag=telstage-67aa-49a935d9
> > To: sip:+18566654221 at 8.xx.xx.xx
> <mailto:18566654221 at 8.xx.xx.xx>;tag=gK02b2b6e2
> > Call-ID: 49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xx.xx.xx>
> > CSeq: 32043 INVITE
> > Record-Route: <sip:8.xx.xx.xx:5060;lr;ftag=telstage-67aa-49a935d9>
> > Accept: application/sdp, application/isup, application/dtmf,
> application/dtmf-relay, multipart/mixed
> > Contact: <sip:+18566654221 at 4.xx.xx.xx
> <mailto:18566654221 at 4.xx.xx.xx>:5060>
> > Allow: INVITE,ACK,CANCEL,BYE,PRACK,UPDATE
> > Content-Length: 177
> > Content-Disposition: session; handling=required
> > Content-Type: application/sdp
> > v=0
> > o=Sonus_UAC 11722 5484 IN IP4 4.xx.xx.xx
> > s=SIP Media Capabilities
> > c=IN IP4 4.xx.xx.xx
> > t=0 0
> > m=audio 22942 RTP/AVP 0
> > a=rtpmap:0 PCMU/8000
> > a=sendrecv
> > a=maxptime:20
> > >
> > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> ERROR:core:parse_via: parsed so far:<SIP/2.0/UDP
> 63.xx.xx.xx:5060branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> >
> >
> > ------------------------------------------------------------------------
> > *From:* Bogdan-Andrei Iancu <bogdan at voice-system.ro
> <mailto:bogdan at voice-system.ro>>
> > *To:* Serge JF <serge at elasticall.com <mailto:serge at elasticall.com>>
> > *Cc:* users at lists.opensips.org <mailto:users at lists.opensips.org>
> > *Sent:* Monday, March 2, 2009 1:18:41 AM
> > *Subject:* Re: [OpenSIPS-Users] OpenSIPS 1.4.2 memory corruption
> issue under extreme load?
> >
> > Hi Sergio,
> >
> > First, some helper facts:
> >
> > 1) the message buffer is kept in private memory, so it cannot be written
> > by other processes
> >
> > 2) parsing of the first via is done before starting the script
> > execution, so, none of the modules can interfere with the buffer.
> >
> > So, how do you get the TRACE log ? do you use the SIP TRACE module?
> >
> > Is the TRACE log after the via error?
> >
> > Regards,
> > Bogdan
> >
> > Serge JF wrote:
> > > Hello,
> > >
> > > We run a very high volume OpenSIPS 1.4.2 deployment with over 6
> million
> > > calls processed daily on a single server running CentOS 5. After 3
> days at
> > > maximum load we started seeing errors such as:
> > >
> > > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]:
> > > ERROR:core:parse_via: invalid port number
> > > <5060?branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf>
> > >
> > > You'll notice the question mark ? after the port number. The
> OpenSIPS parser
> > > does not like this and fails in the parsing - which had to be
> expected. The
> > > issue is that the message according to the XLOG statement we got
> at the very
> > > beginning of our route[] was received with a semicolon as expected:
> > >
> > > Feb 28 08:03:17 sip101 /usr/local/sbin/opensips[11614]: TRACE:ROUTE:
> > > time(1235826197) src(63.xx.xx.108:5060) dst(8.xx.xx.14:5060)
> msg(INVITE
> > > sip:+18566654221 at 4.xx.xx <mailto:18566654221 at 4.xx.xx>
> <mailto:18566654221 at 4.xx.xx <mailto:18566654221 at 4.xx.xx>>.227:5060 SIP/2.0
> > > From: <sip:+18668496441 at 63.xxx.xx <mailto:18668496441 at 63.xxx.xx>
> <mailto:18668496441 at 63.xxx.xx
> <mailto:18668496441 at 63.xxx.xx>>.108:5060>;tag=telstage-67aa-49a935d9
> > > To: sip:+18566654221 at 8.xx.xx <mailto:18566654221 at 8.xx.xx>
> <mailto:18566654221 at 8.xx.xx
> <mailto:18566654221 at 8.xx.xx>>.19;tag=gK02b2b6e2
> > > Contact: <sip:63.xxx.xx.108:5060;transport=udp>
> > > Call-ID: 49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xxx.xx
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xxx.xx>
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xxx.xx
> <mailto:49a935d9-029f-0065abfa-8162901a-4330cddf at 63.xxx.xx>>.108
> > > CSeq: 32043 INVITE
> > > Content-Length: 177
> > > Content-Type: application/sdp
> > > Content-Disposition: session; handling=required
> > > Route: <sip:8.xx.xx.14:5060;lr;ftag=telstage%2D67aa%2D49a935d9>
> > > Session-Expires: 1800;refresher=uac
> > > Supported: timer
> > > Max-Forwards: 70
> > > Via: SIP/2.0/UDP
> > >
> 63.xxx.xx.108:5060;branch=z9hG4bK49a93615-0234-0065adf8-8162901a-4330cddf
> > >
> > > Could this be due to some overwriting of string buffers in the
> OpenSIPS CORE
> > > or TM module? How should we go about debugging this issue? It only
> seems to
> > > happen after a few days under load. For the time being we have
> introduced a
> > > nightly restart of the OpenSIPS to clear up the memory.
> > >
> > > Any pointer (sic) would be most welcome!
> > >
> > > Best Regards,
> > >
> > > Serge
> > >
> >
> > _______________________________________________
> > Users mailing list
> > Users at lists.opensips.org <mailto:Users at lists.opensips.org>
> <mailto:Users at lists.opensips.org <mailto:Users at lists.opensips.org>>
> > http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
More information about the Users
mailing list