OpenSIPS 1.4.2 memory corruption issue under extreme load?

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

OpenSIPS 1.4.2 memory corruption issue under extreme load?

Serge JF
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@4.xx.xx.227:5060 SIP/2.0
 From: <sip:+18668496441@63.xxx.xx.108:5060>;tag=telstage-67aa-49a935d9
 To: sip:+18566654221@8.xx.xx.19;tag=gK02b2b6e2
 Contact: <sip:63.xxx.xx.108:5060;transport=udp>
 Call-ID: 49a935d9-029f-0065abfa-8162901a-4330cddf@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
Reply | Threaded
Open this post in threaded view
|

Re: OpenSIPS 1.4.2 memory corruption issue under extreme load?

Bogdan-Andrei Iancu
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:+[hidden email].227:5060 SIP/2.0
>  From: <sip:+[hidden email].108:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email].19;tag=gK02b2b6e2
>  Contact: <sip:63.xxx.xx.108:5060;transport=udp>
>  Call-ID: [hidden email].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
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Reply | Threaded
Open this post in threaded view
|

Re: OpenSIPS 1.4.2 memory corruption issue under extreme load?

joel garcia
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:+[hidden email]:5060 SIP/2.0
 From: <sip:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
 To: sip:+[hidden email];tag=gK02b2b6e2
 Contact: <sip:63.xx.xx.xx:5060;transport=udp>
 Call-ID: [hidden email]
 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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
 To: sip:+[hidden email];tag=gK02b2b6e2
 Call-ID: [hidden email]
 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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
 To: sip:+[hidden email];tag=gK02b2b6e2
 Call-ID: [hidden email]
 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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-31e5-49a935fc
 To: sip:+[hidden email];tag=gK0ad718b1
 Call-ID: [hidden email]
 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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
 To: sip:+[hidden email];tag=gK02b2b6e2
 Call-ID: [hidden email]
 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:+[hidden email]: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 <[hidden email]>
To: Serge JF <[hidden email]>
Cc: [hidden email]
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:+[hidden email].227:5060 SIP/2.0
>  From: <sip:+[hidden email].108:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email].19;tag=gK02b2b6e2
>  Contact: <sip:63.xxx.xx.108:5060;transport=udp>
>  Call-ID: [hidden email].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
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users

_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Reply | Threaded
Open this post in threaded view
|

Re: OpenSIPS 1.4.2 memory corruption issue under extreme load?

Bogdan-Andrei Iancu
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:+[hidden email]:5060 SIP/2.0
>  From: <sip:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Contact: <sip:63.xx.xx.xx:5060;transport=udp>
>  Call-ID: [hidden email]
>  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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Call-ID: [hidden email]
>  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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Call-ID: [hidden email]
>  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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-31e5-49a935fc
>  To: sip:+[hidden email];tag=gK0ad718b1
>  Call-ID: [hidden email]
>  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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Call-ID: [hidden email]
>  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:+[hidden email]: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 <[hidden email]>
> *To:* Serge JF <[hidden email]>
> *Cc:* [hidden email]
> *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:+[hidden email] <mailto:[hidden email]>.227:5060 SIP/2.0
> >  From: <sip:+[hidden email]
> <mailto:[hidden email]>.108:5060>;tag=telstage-67aa-49a935d9
> >  To: sip:+[hidden email]
> <mailto:[hidden email]>.19;tag=gK02b2b6e2
> >  Contact: <sip:63.xxx.xx.108:5060;transport=udp>
> >  Call-ID: [hidden email]
> <mailto:[hidden email]>.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
> [hidden email] <mailto:[hidden email]>
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users


_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Reply | Threaded
Open this post in threaded view
|

Re: OpenSIPS 1.4.2 memory corruption issue under extreme load?

joel garcia
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 <[hidden email]>
To: joel garcia <[hidden email]>
Cc: Serge JF <[hidden email]>; [hidden email]
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:+[hidden email]:5060 SIP/2.0
>  From: <sip:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Contact: <sip:63.xx.xx.xx:5060;transport=udp>
>  Call-ID: [hidden email]
>  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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Call-ID: [hidden email]
>  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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Call-ID: [hidden email]
>  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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-31e5-49a935fc
>  To: sip:+[hidden email];tag=gK0ad718b1
>  Call-ID: [hidden email]
>  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:+[hidden email]: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:+[hidden email]:5060>;tag=telstage-67aa-49a935d9
>  To: sip:+[hidden email];tag=gK02b2b6e2
>  Call-ID: [hidden email]
>  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:+[hidden email]: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 <[hidden email]>
> *To:* Serge JF <[hidden email]>
> *Cc:* [hidden email]
> *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:+[hidden email] <mailto:[hidden email]>.227:5060 SIP/2.0
> >  From: <sip:+[hidden email] <mailto:[hidden email]>.108:5060>;tag=telstage-67aa-49a935d9
> >  To: sip:+[hidden email] <mailto:[hidden email]>.19;tag=gK02b2b6e2
> >  Contact: <sip:63.xxx.xx.108:5060;transport=udp>
> >  Call-ID: [hidden email] <mailto:[hidden email]>.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
> [hidden email] <mailto:[hidden email]>
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users


_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Reply | Threaded
Open this post in threaded view
|

Re: OpenSIPS 1.4.2 memory corruption issue under extreme load?

Bogdan-Andrei Iancu
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 <[hidden email]>
> *To:* joel garcia <[hidden email]>
> *Cc:* Serge JF <[hidden email]>; [hidden email]
> *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:+[hidden email] <mailto:[hidden email]>:5060 SIP/2.0
> >  From: <sip:+[hidden email]
> <mailto:[hidden email]>:5060>;tag=telstage-67aa-49a935d9
> >  To: sip:+[hidden email]
> <mailto:[hidden email]>;tag=gK02b2b6e2
> >  Contact: <sip:63.xx.xx.xx:5060;transport=udp>
> >  Call-ID: [hidden email]
> <mailto:[hidden email]>
> >  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:+[hidden email]
> <mailto:[hidden email]>:5060>;tag=telstage-67aa-49a935d9
> >  To: sip:+[hidden email]
> <mailto:[hidden email]>;tag=gK02b2b6e2
> >  Call-ID: [hidden email]
> <mailto:[hidden email]>
> >  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:+[hidden email]
> <mailto:[hidden email]>: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:+[hidden email]
> <mailto:[hidden email]>:5060>;tag=telstage-67aa-49a935d9
> >  To: sip:+[hidden email]
> <mailto:[hidden email]>;tag=gK02b2b6e2
> >  Call-ID: [hidden email]
> <mailto:[hidden email]>
> >  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:+[hidden email]
> <mailto:[hidden email]>: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:+[hidden email]
> <mailto:[hidden email]>:5060>;tag=telstage-31e5-49a935fc
> >  To: sip:+[hidden email]
> <mailto:[hidden email]>;tag=gK0ad718b1
> >  Call-ID: [hidden email]
> <mailto:[hidden email]>
> >  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:+[hidden email]
> <mailto:[hidden email]>: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:+[hidden email]
> <mailto:[hidden email]>:5060>;tag=telstage-67aa-49a935d9
> >  To: sip:+[hidden email]
> <mailto:[hidden email]>;tag=gK02b2b6e2
> >  Call-ID: [hidden email]
> <mailto:[hidden email]>
> >  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:+[hidden email]
> <mailto:[hidden email]>: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 <[hidden email]
> <mailto:[hidden email]>>
> > *To:* Serge JF <[hidden email] <mailto:[hidden email]>>
> > *Cc:* [hidden email] <mailto:[hidden email]>
> > *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:+[hidden email] <mailto:[hidden email]>
> <mailto:[hidden email] <mailto:[hidden email]>>.227:5060 SIP/2.0
> > >  From: <sip:+[hidden email] <mailto:[hidden email]>
> <mailto:[hidden email]
> <mailto:[hidden email]>>.108:5060>;tag=telstage-67aa-49a935d9
> > >  To: sip:+[hidden email] <mailto:[hidden email]>
> <mailto:[hidden email]
> <mailto:[hidden email]>>.19;tag=gK02b2b6e2
> > >  Contact: <sip:63.xxx.xx.108:5060;transport=udp>
> > >  Call-ID: [hidden email]
> <mailto:[hidden email]>
> <mailto:[hidden email]
> <mailto:[hidden email]>>.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
> > [hidden email] <mailto:[hidden email]>
> <mailto:[hidden email] <mailto:[hidden email]>>
> > http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>


_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users