30 May
2007
30 May
'07
4:49 p.m.
We are currently experiencing problems with our production OpenSER
(1.1.0) environment where the load on the server is steadily increasing
and the OpenSER response time increases drastically (e.g., 30+ seconds
for an internal call to ring).
Capturing the network traffic when this happens we have noticed that our
Asterisk (1.2.10) voicemail server is sending malformed CANCEL requests
to our OpenSER proxy. We are not certain whether this is a cause or an
effect of the load problems on the OpenSER server. Here is the SIP data
from the bad CANCEL request:
Session Initiation Protocol
Request-Line: CANCEL :u43974@128.59.59.215:5069 SIP/2.0
Method: CANCEL
[Resent Packet: False]
Message Header
Via: SIP/2.0/UDP 128.59.59.215:5069;branch=z9hG4bK6734835b;rport
Transport: UDP
Sent-by Address: 128.59.59.215
Sent-by port: 5069
Branch: z9hG4bK6734835b
RPort: rport
Route: <sip:128.59.59.199;lr=on;ftag=4FC702F4-7F812557>
From: <sip:43974@sip.columbia.edu;user=phone>
SIP from address: sip:43974@sip.columbia.edu
To: "Jim Rios" <sip:47891@sip.columbia.edu>;tag=4FC702F4-7F812557
SIP Display info: "Jim Rios"
SIP to address: sip:47891@sip.columbia.edu
SIP tag: 4FC702F4-7F812557
Contact: <sip:u43974@128.59.59.215:5069>
Contact Binding: <sip:u43974@128.59.59.215:5069>
URI: <sip:u43974@128.59.59.215:5069>
SIP contact address: sip:u43974@128.59.59.215:5069
Call-ID: c9a0135b-41273fb6-f7b6cea9(a)160.39.14.100
CSeq: 101 CANCEL
Sequence Number: 101
Method: CANCEL
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0
Accompanying this bad CANCEL request are the following error messages
recorded by OpenSER to syslog when it attempts to process it:
May 29 15:34:07 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:07 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:07 cocoa openser[892]: xl_get_ruri: ERROR while parsing the R-URI
May 29 15:34:08 cocoa openser[892]: c9a0135b-41273fb6-f7b6cea9(a)160.39.14.100: route[0]
CANCEL r-uri <<null>> from <sip:43974@sip.columbia.edu;user=phone> to
<sip:47891@sip.columbia.edu>
May 29 15:34:08 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:08 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:08 cocoa openser[892]: loose_route: Error while parsing Request URI
May 29 15:34:08 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:09 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:09 cocoa openser[892]: WARNING: do_action:error in expression
May 29 15:34:09 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:09 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:09 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:10 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:10 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:10 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:10 cocoa openser[892]: alias_db_lookup: Error while parsing Request-URI
While the malformed packet is likely the fault of the Asterisk server
(we see no packets from OpenSER to Asterisk with the sip protocol
missing from the URI), we are wondering if OpenSER errors out in a bad
way when it tries to process this packet, possibly entering into some
sort of loop that is causing the load to go through the roof.
It is also unclear to us why the Asterisk voicemail server would be
responding with a cancel. In our packet capture we see no record of a
request initiated by the Asterisk server that it would be sending a
CANCEL for.
Any insight that could be offered into this problem would be greatly
appreciated.
Thx,
David Coulthart
30 May
30 May
5:12 p.m.
Hello,
On 05/30/07 17:49, David Coulthart wrote:
We are currently experiencing problems with our
production OpenSER
(1.1.0) environment where the load on the server is steadily increasing
and the OpenSER response time increases drastically (e.g., 30+ seconds
for an internal call to ring).
this might be because of some slow DNS or database response. The best is
to run in higher debug mode to see where it gets stuck. Another
possiblity is the syslog, make sure it is configured to be asynchronous.
If you have lot of messages written to syslog synchronous, then you will
get lot of delays.
To troubleshoot, see which application eats most of the CPU, if that
happens.
On the other hand, with 1.2.x you get better performances and parsing
error handling via error_route. You should consider upgrading.
Cheers,
Daniel
Capturing the network traffic when this happens we
have noticed that our
Asterisk (1.2.10) voicemail server is sending malformed CANCEL requests
to our OpenSER proxy. We are not certain whether this is a cause or an
effect of the load problems on the OpenSER server. Here is the SIP data
from the bad CANCEL request:
Session Initiation Protocol
Request-Line: CANCEL :u43974@128.59.59.215:5069 SIP/2.0
Method: CANCEL
[Resent Packet: False]
Message Header
Via: SIP/2.0/UDP 128.59.59.215:5069;branch=z9hG4bK6734835b;rport
Transport: UDP
Sent-by Address: 128.59.59.215
Sent-by port: 5069
Branch: z9hG4bK6734835b
RPort: rport
Route: <sip:128.59.59.199;lr=on;ftag=4FC702F4-7F812557>
From: <sip:43974@sip.columbia.edu;user=phone>
SIP from address: sip:43974@sip.columbia.edu
To: "Jim Rios"
<sip:47891@sip.columbia.edu>;tag=4FC702F4-7F812557
SIP Display info: "Jim Rios"
SIP to address: sip:47891@sip.columbia.edu
SIP tag: 4FC702F4-7F812557
Contact: <sip:u43974@128.59.59.215:5069>
Contact Binding: <sip:u43974@128.59.59.215:5069>
URI: <sip:u43974@128.59.59.215:5069>
SIP contact address: sip:u43974@128.59.59.215:5069
Call-ID: c9a0135b-41273fb6-f7b6cea9(a)160.39.14.100
CSeq: 101 CANCEL
Sequence Number: 101
Method: CANCEL
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0
Accompanying this bad CANCEL request are the following error messages
recorded by OpenSER to syslog when it attempts to process it:
May 29 15:34:07 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:07 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:07 cocoa openser[892]: xl_get_ruri: ERROR while parsing the R-URI
May 29 15:34:08 cocoa openser[892]: c9a0135b-41273fb6-f7b6cea9(a)160.39.14.100: route[0]
CANCEL r-uri <<null>> from <sip:43974@sip.columbia.edu;user=phone> to
<sip:47891@sip.columbia.edu>
May 29 15:34:08 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:08 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:08 cocoa openser[892]: loose_route: Error while parsing Request URI
May 29 15:34:08 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:09 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:09 cocoa openser[892]: WARNING: do_action:error in expression
May 29 15:34:09 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:09 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:09 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:10 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:10 cocoa openser[892]: ERROR: parse_uri: bad uri, state 0 parsed:
<:u43> (4) / <:u43974@128.59.59.215:5069> (26)
May 29 15:34:10 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri
<:u43974@128.59.59.215:5069>
May 29 15:34:10 cocoa openser[892]: alias_db_lookup: Error while parsing Request-URI
While the malformed packet is likely the fault of the Asterisk server
(we see no packets from OpenSER to Asterisk with the sip protocol
missing from the URI), we are wondering if OpenSER errors out in a bad
way when it tries to process this packet, possibly entering into some
sort of loop that is causing the load to go through the roof.
It is also unclear to us why the Asterisk voicemail server would be
responding with a cancel. In our packet capture we see no record of a
request initiated by the Asterisk server that it would be sending a
CANCEL for.
Any insight that could be offered into this problem would be greatly
appreciated.
Thx,
David Coulthart
_______________________________________________
Users mailing list
Users(a)openser.org
http://openser.org/cgi-bin/mailman/listinfo/users
1 Jun
1 Jun
5:39 p.m.
New subject: [Users] Malformed CANCEL request from Asterisk possibly impacting OpenSER?
On Wed, 2007-05-30 at 18:12 +0300, Daniel-Constantin Mierla wrote:
Hello,
On 05/30/07 17:49, David Coulthart wrote:
Daniel,
Thank you for this info. It appears switching to asynchronous
syslog'ing was a huge win for us.
We are currently experiencing problems with our
production OpenSER
(1.1.0) environment where the load on the server is steadily increasing
and the OpenSER response time increases drastically (e.g., 30+ seconds
for an internal call to ring).
this might be because of some slow DNS or database response. The best is
to run in higher debug mode to see where it gets stuck. Another
possiblity is the syslog, make sure it is configured to be asynchronous.
If you have lot of messages written to syslog synchronous, then you will
get lot of delays. To troubleshoot, see which application eats most of
the CPU, if that
happens.
On the other hand, with 1.2.x you get better performances and parsing
error handling via error_route. You should consider upgrading.
We are investigating 1.2.1. Better performance always sounds good.
Thx,
David Coulthart
30 May
30 May
5:33 p.m.
New subject: [Users] Malformed CANCEL request from Asterisk possibly impactingOpenSER?
Take a look at
http://bugs.digium.com/view.php?id=7351
Might be related. I've seen this too.
There's a (very simple) patch attached which you can try.
-----Original Message-----
From: users-bounces(a)openser.org [mailto:users-bounces@openser.org] On
Behalf Of David Coulthart
Sent: Wednesday, May 30, 2007 10:49 AM
To: users(a)openser.org
Subject: [Users] Malformed CANCEL request from Asterisk possibly
impactingOpenSER?
We are currently experiencing problems with our production OpenSER
(1.1.0) environment where the load on the server is steadily increasing
and the OpenSER response time increases drastically (e.g., 30+ seconds
for an internal call to ring).
1 Jun
1 Jun
5:41 p.m.
New subject: [Users] Malformed CANCEL request from Asterisk possibly impactingOpenSER?
On Wed, 2007-05-30 at 11:33 -0400, Vadim Berezniker wrote:
Take a look at
http://bugs.digium.com/view.php?id=7351
Might be related. I've seen this too.
There's a (very simple) patch attached which you can try.
Vadim,
Thanks for this info. We are currently testing the patch to see if it
will fix the bad behavior from Asterisk.
Thx,
David Coulthart
27 Jun
27 Jun
3 p.m.
New subject: [OpenSER-Users] Re: [Users] Malformed CANCEL request from Asterisk possibly impacting OpenSER?
On Wed, 2007-05-30 at 10:49 -0400, David Coulthart wrote:
We are currently experiencing problems with our
production OpenSER
(1.1.0) environment where the load on the server is steadily increasing
and the OpenSER response time increases drastically (e.g., 30+ seconds
for an internal call to ring).
Capturing the network traffic when this happens we have noticed that our
Asterisk (1.2.10) voicemail server is sending malformed CANCEL requests
to our OpenSER proxy. We are not certain whether this is a cause or an
effect of the load problems on the OpenSER server. Here is the SIP data
from the bad CANCEL request:
I just want to close the loop on this issue in case anyone else runs
into this problem. Thanks to the advice from Vadim Berezniker we are
using the attached patch applied against Asterisk 1.2.18, which
eliminates the bad CANCEL requests (no longer missing the sip prefix).
David Coulthart
6142
days inactive
6170
days old
5 comments
3 participants
participants (3)
-
Daniel-Constantin Mierla -
David Coulthart -
Vadim Berezniker