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