[Users] Malformed CANCEL request from Asterisk possibly impacting OpenSER?

Daniel-Constantin Mierla daniel at voice-system.ro
Wed May 30 17:12:36 CEST 2007


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 at 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 at sip.columbia.edu;user=phone>
>             SIP from address: sip:43974 at sip.columbia.edu
>         To: "Jim Rios" <sip:47891 at sip.columbia.edu>;tag=4FC702F4-7F812557
>             SIP Display info: "Jim Rios" 
>             SIP to address: sip:47891 at sip.columbia.edu
>             SIP tag: 4FC702F4-7F812557
>         Contact: <sip:u43974 at 128.59.59.215:5069>
>             Contact Binding: <sip:u43974 at 128.59.59.215:5069>
>                 URI: <sip:u43974 at 128.59.59.215:5069>
>                     SIP contact address: sip:u43974 at 128.59.59.215:5069
>         Call-ID: c9a0135b-41273fb6-f7b6cea9 at 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 at 128.59.59.215:5069> (26) 
> May 29 15:34:07 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri <:u43974 at 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 at 160.39.14.100: route[0] CANCEL r-uri <<null>> from <sip:43974 at sip.columbia.edu;user=phone> to <sip:47891 at sip.columbia.edu> 
> May 29 15:34:08 cocoa openser[892]: ERROR: parse_uri: bad uri,  state 0 parsed: <:u43> (4) / <:u43974 at 128.59.59.215:5069> (26) 
> May 29 15:34:08 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri <:u43974 at 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 at 128.59.59.215:5069> (26) 
> May 29 15:34:09 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri <:u43974 at 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 at 128.59.59.215:5069> (26) 
> May 29 15:34:09 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri <:u43974 at 128.59.59.215:5069> 
> May 29 15:34:09 cocoa openser[892]: ERROR: parse_uri: bad uri,  state 0 parsed: <:u43> (4) / <:u43974 at 128.59.59.215:5069> (26) 
> May 29 15:34:10 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri <:u43974 at 128.59.59.215:5069> 
> May 29 15:34:10 cocoa openser[892]: ERROR: parse_uri: bad uri,  state 0 parsed: <:u43> (4) / <:u43974 at 128.59.59.215:5069> (26) 
> May 29 15:34:10 cocoa openser[892]: ERROR: parse_sip_msg_uri: bad uri <:u43974 at 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 at openser.org
> http://openser.org/cgi-bin/mailman/listinfo/users
>
>   




More information about the sr-users mailing list