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@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@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
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@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@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@openser.org http://openser.org/cgi-bin/mailman/listinfo/users
On Wed, 2007-05-30 at 18:12 +0300, Daniel-Constantin Mierla wrote:
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.
Daniel,
Thank you for this info. It appears switching to asynchronous syslog'ing was a huge win for us.
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
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@openser.org [mailto:users-bounces@openser.org] On Behalf Of David Coulthart Sent: Wednesday, May 30, 2007 10:49 AM To: users@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).
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
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
-
Daniel-Constantin Mierla -
David Coulthart -
Vadim Berezniker