"bad uri" response header collisions bug in OpenSIPS 2.4.3

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

"bad uri" response header collisions bug in OpenSIPS 2.4.3

Jock McKechnie
Afternoon folks;

I recently upgraded one of our production boxes to 2.4.3-1.el7 out of
the OpenSIPS yum repo and within a few minutes I started seeing errors
like this in the OpenSIPS logging:
ERROR:core:parse_uri: bad uri, state 0 parsed: < 183> (4) / < 183
Session Progress#015#012Via: SIP/2.0/UDP 20> (42)
ERROR:core:parse_sip_msg_uri: bad uri < 183 Session
Progress#015#012Via: SIP/2.0/UDP 20>
ERROR:perl:perl_exec2: failed to parse Request-URI
ERROR:core:parse_uri: bad uri, state 0 parsed: < 183> (4) / < 183
Session Progress#015#012Via: SIP/2.0/UDP 20> (42)
ERROR:core:parse_sip_msg_uri: bad uri < 183 Session
Progress#015#012Via: SIP/2.0/UDP 20>
ERROR:perl:perl_exec2: failed to parse Request-URI
ERROR:tm:_reply_light: failed to generate 400 reply when a final 400
was sent out
ERROR:signaling:sig_send_reply_mod: failed to send reply with tm module
ERROR:perl:perl_exec2: failed to send reply
ERROR:tm:_reply_light: failed to generate 500 reply when a final 400
was sent out

I trapped SIP for a while and OpenSIPS appears to be periodically
responding to messages with impressively malformed response
type/headers:
ACK  183 Session Progress
Via: SIP/2.0/UDP 20 SIP/2.0

This belongs to the end of the call flow below (from 192.168.80.13
through our 2.4.3 proxy 192.168.93.214, to the destination server
192.168.80.56). You'll see the .56 returns a 403 Forbidden which the
OpenSIPS is supposed to be ACKing, but instead it does something Very
Odd with the header - and then proceeds to throw the logged errors
above and returns a 400 to the requesting server.

U 2018/11/28 10:18:22.758859 192.168.80.56:5060 -> 192.168.93.214:5060
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP
192.168.93.214:5060;received=192.168.93.214;branch=z9hG4bKcb74.9a10e3a3.0
Via: SIP/2.0/UDP
192.168.80.13:5060;rport=5060;received=192.168.80.13;branch=z9hG4bKPjdb6efcd9-373b-4122-8bde-9d92a608d6ee
Record-Route: <sip:192.168.93.214;lr;ftag=c0d1ec70-fbaa-429c-acc9-17dec131459e;did=453.a5b161a2>
Call-ID: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
From: <sip:+16465551212@192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
To: <sip:XFER_3235551212@192.168.80.56>;tag=f9e1dd31-b586-4f47-9fb8-3d541b658a67
CSeq: 5413 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

U 2018/11/28 10:18:22.759216 192.168.93.214:5060 -> 192.168.80.56:5060
ACK  183 Session Progress
Via: SIP/2.0/UDP 20 SIP/2.0
Via: SIP/2.0/UDP 192.168.93.214:5060;branch=z9hG4bKcb74.9a10e3a3.0
From: <sip:+16465551212@192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
To: <sip:XFER_3235551212@192.168.80.56>;tag=f9e1dd31-b586-4f47-9fb8-3d541b658a67
CSeq: 5413 ACK
Max-Forwards: 70
User-Agent: OpenSIPS (2.4.3 (x86_64/linux))
Content-Length: 0

U 2018/11/28 10:18:22.759666 192.168.93.214:5060 -> 192.168.80.13:5060
SIP/2.0 400 Bad Request-URI
v: SIP/2.0/UDP 192.168.80.13:5060;received=192.168.80.13;rport=5060;branch=z9hG4bKPjdb6efcd9-373b-4122-8bde-9d92a608d6ee
f: sip:+16465551212@192.168.80.13;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
t: sip:+13235551212@192.168.93.214;tag=155c340f586c28d0300cf5a6ccf90d99-03d7
i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
CSeq: 5413 INVITE
Server: OpenSIPS (2.4.3 (x86_64/linux))
Content-Length: 0

I'm going to try and get more detailed debug dumps from OpenSIPS but
it's only happening on a subset of calls and, of course, this was a
production box (I didn't notice this in my limited testing) so I'm not
able to safely live debug this box.

I wanted to pitch it over the fence as soon as I could to get things
rolling in case you guys might have an idea what's going on.

Thanks much,

 - Jock

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

Re: "bad uri" response header collisions bug in OpenSIPS 2.4.3

Răzvan Crainea-2
Hi, Jock!

The errors you dumped below are found in the proxy's logs (192.168.93.214)?
I don't actually understand how OpenSIPS triggers the ACK parsing error
if he's the one generating it. Is OpenSIPS somehow looping the ACK to
itself to re-parse it? Are you also tracking the internal interface?

Best regards,
Răzvan

On 11/28/18 10:59 PM, Jock McKechnie wrote:

> Afternoon folks;
>
> I recently upgraded one of our production boxes to 2.4.3-1.el7 out of
> the OpenSIPS yum repo and within a few minutes I started seeing errors
> like this in the OpenSIPS logging:
> ERROR:core:parse_uri: bad uri, state 0 parsed: < 183> (4) / < 183
> Session Progress#015#012Via: SIP/2.0/UDP 20> (42)
> ERROR:core:parse_sip_msg_uri: bad uri < 183 Session
> Progress#015#012Via: SIP/2.0/UDP 20>
> ERROR:perl:perl_exec2: failed to parse Request-URI
> ERROR:core:parse_uri: bad uri, state 0 parsed: < 183> (4) / < 183
> Session Progress#015#012Via: SIP/2.0/UDP 20> (42)
> ERROR:core:parse_sip_msg_uri: bad uri < 183 Session
> Progress#015#012Via: SIP/2.0/UDP 20>
> ERROR:perl:perl_exec2: failed to parse Request-URI
> ERROR:tm:_reply_light: failed to generate 400 reply when a final 400
> was sent out
> ERROR:signaling:sig_send_reply_mod: failed to send reply with tm module
> ERROR:perl:perl_exec2: failed to send reply
> ERROR:tm:_reply_light: failed to generate 500 reply when a final 400
> was sent out
>
> I trapped SIP for a while and OpenSIPS appears to be periodically
> responding to messages with impressively malformed response
> type/headers:
> ACK  183 Session Progress
> Via: SIP/2.0/UDP 20 SIP/2.0
>
> This belongs to the end of the call flow below (from 192.168.80.13
> through our 2.4.3 proxy 192.168.93.214, to the destination server
> 192.168.80.56). You'll see the .56 returns a 403 Forbidden which the
> OpenSIPS is supposed to be ACKing, but instead it does something Very
> Odd with the header - and then proceeds to throw the logged errors
> above and returns a 400 to the requesting server.
>
> U 2018/11/28 10:18:22.758859 192.168.80.56:5060 -> 192.168.93.214:5060
> SIP/2.0 403 Forbidden
> Via: SIP/2.0/UDP
> 192.168.93.214:5060;received=192.168.93.214;branch=z9hG4bKcb74.9a10e3a3.0
> Via: SIP/2.0/UDP
> 192.168.80.13:5060;rport=5060;received=192.168.80.13;branch=z9hG4bKPjdb6efcd9-373b-4122-8bde-9d92a608d6ee
> Record-Route: <sip:192.168.93.214;lr;ftag=c0d1ec70-fbaa-429c-acc9-17dec131459e;did=453.a5b161a2>
> Call-ID: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
> From: <sip:+16465551212@192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
> To: <sip:XFER_3235551212@192.168.80.56>;tag=f9e1dd31-b586-4f47-9fb8-3d541b658a67
> CSeq: 5413 INVITE
> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
> NOTIFY, REFER, MESSAGE, OPTIONS
> Content-Length:  0
>
> U 2018/11/28 10:18:22.759216 192.168.93.214:5060 -> 192.168.80.56:5060
> ACK  183 Session Progress
> Via: SIP/2.0/UDP 20 SIP/2.0
> Via: SIP/2.0/UDP 192.168.93.214:5060;branch=z9hG4bKcb74.9a10e3a3.0
> From: <sip:+16465551212@192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
> i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
> To: <sip:XFER_3235551212@192.168.80.56>;tag=f9e1dd31-b586-4f47-9fb8-3d541b658a67
> CSeq: 5413 ACK
> Max-Forwards: 70
> User-Agent: OpenSIPS (2.4.3 (x86_64/linux))
> Content-Length: 0
>
> U 2018/11/28 10:18:22.759666 192.168.93.214:5060 -> 192.168.80.13:5060
> SIP/2.0 400 Bad Request-URI
> v: SIP/2.0/UDP 192.168.80.13:5060;received=192.168.80.13;rport=5060;branch=z9hG4bKPjdb6efcd9-373b-4122-8bde-9d92a608d6ee
> f: sip:+16465551212@192.168.80.13;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
> t: sip:+13235551212@192.168.93.214;tag=155c340f586c28d0300cf5a6ccf90d99-03d7
> i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
> CSeq: 5413 INVITE
> Server: OpenSIPS (2.4.3 (x86_64/linux))
> Content-Length: 0
>
> I'm going to try and get more detailed debug dumps from OpenSIPS but
> it's only happening on a subset of calls and, of course, this was a
> production box (I didn't notice this in my limited testing) so I'm not
> able to safely live debug this box.
>
> I wanted to pitch it over the fence as soon as I could to get things
> rolling in case you guys might have an idea what's going on.
>
> Thanks much,
>
>   - Jock
>
> _______________________________________________
> Users mailing list
> [hidden email]
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>

--
Răzvan Crainea
OpenSIPS Core Developer
   http://www.opensips-solutions.com
Meet the OpenSIPS team at the next OpenSIPS Summit:
   https://www.opensips.org/events

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

Re: "bad uri" response header collisions bug in OpenSIPS 2.4.3

Jock McKechnie
Hey Răzvan;

My apologies for the delay - that disaster last Monday when we were
talking ended up taking up a large portion of my previous and current
week, annoyingly.

I have yet to be able to reliably replicate this issue - when I saw it
(on just shy of 10% of calls) it was on a production service that I
had upgraded to 2.4.3 that morning. Because it was adversely affecting
production calls I had no choice but to (after getting a quick SIP
trap) restart the service on 2.4.2. This issue presented itself _the
instant_ 2.4.3 was brought up, and disappeared _the instant_ I
reverted to 2.4.2 - so there is no question that it is specific to
2.4.3. Unfortunately I can't tell you what or where!

I spent some time yesterday and the day before running calls through
my load testing mechanism. I was able to catch two (of our ~100,000
calls) but OpenSIPS debug was off at the time (d'oh). With debug on I
was unable to catch a single one. Whatever this is, it appears to only
show up when it has the chance to break my customer's traffic :) As
soon as I find time, I'll try and bring some other, less active, boxes
up to 2.4.3 and work outwards until I find something that appears to
make it happen and get you some debug dumps.

I mostly just wanted to let you know that there's definitely something
in 2.4.3 going on, and it's important to us, but I haven't had the
time to re-test sufficiently and I appreciate that there's probably
not a heap you can do without it.

To be continued;

 - JP

On Thu, Nov 29, 2018 at 2:41 AM Răzvan Crainea <[hidden email]> wrote:

>
> Hi, Jock!
>
> The errors you dumped below are found in the proxy's logs (192.168.93.214)?
> I don't actually understand how OpenSIPS triggers the ACK parsing error
> if he's the one generating it. Is OpenSIPS somehow looping the ACK to
> itself to re-parse it? Are you also tracking the internal interface?
>
> Best regards,
> Răzvan
>
> On 11/28/18 10:59 PM, Jock McKechnie wrote:
> > Afternoon folks;
> >
> > I recently upgraded one of our production boxes to 2.4.3-1.el7 out of
> > the OpenSIPS yum repo and within a few minutes I started seeing errors
> > like this in the OpenSIPS logging:
> > ERROR:core:parse_uri: bad uri, state 0 parsed: < 183> (4) / < 183
> > Session Progress#015#012Via: SIP/2.0/UDP 20> (42)
> > ERROR:core:parse_sip_msg_uri: bad uri < 183 Session
> > Progress#015#012Via: SIP/2.0/UDP 20>
> > ERROR:perl:perl_exec2: failed to parse Request-URI
> > ERROR:core:parse_uri: bad uri, state 0 parsed: < 183> (4) / < 183
> > Session Progress#015#012Via: SIP/2.0/UDP 20> (42)
> > ERROR:core:parse_sip_msg_uri: bad uri < 183 Session
> > Progress#015#012Via: SIP/2.0/UDP 20>
> > ERROR:perl:perl_exec2: failed to parse Request-URI
> > ERROR:tm:_reply_light: failed to generate 400 reply when a final 400
> > was sent out
> > ERROR:signaling:sig_send_reply_mod: failed to send reply with tm module
> > ERROR:perl:perl_exec2: failed to send reply
> > ERROR:tm:_reply_light: failed to generate 500 reply when a final 400
> > was sent out
> >
> > I trapped SIP for a while and OpenSIPS appears to be periodically
> > responding to messages with impressively malformed response
> > type/headers:
> > ACK  183 Session Progress
> > Via: SIP/2.0/UDP 20 SIP/2.0
> >
> > This belongs to the end of the call flow below (from 192.168.80.13
> > through our 2.4.3 proxy 192.168.93.214, to the destination server
> > 192.168.80.56). You'll see the .56 returns a 403 Forbidden which the
> > OpenSIPS is supposed to be ACKing, but instead it does something Very
> > Odd with the header - and then proceeds to throw the logged errors
> > above and returns a 400 to the requesting server.
> >
> > U 2018/11/28 10:18:22.758859 192.168.80.56:5060 -> 192.168.93.214:5060
> > SIP/2.0 403 Forbidden
> > Via: SIP/2.0/UDP
> > 192.168.93.214:5060;received=192.168.93.214;branch=z9hG4bKcb74.9a10e3a3.0
> > Via: SIP/2.0/UDP
> > 192.168.80.13:5060;rport=5060;received=192.168.80.13;branch=z9hG4bKPjdb6efcd9-373b-4122-8bde-9d92a608d6ee
> > Record-Route: <sip:192.168.93.214;lr;ftag=c0d1ec70-fbaa-429c-acc9-17dec131459e;did=453.a5b161a2>
> > Call-ID: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
> > From: <sip:+16465551212@192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
> > To: <sip:XFER_3235551212@192.168.80.56>;tag=f9e1dd31-b586-4f47-9fb8-3d541b658a67
> > CSeq: 5413 INVITE
> > Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
> > NOTIFY, REFER, MESSAGE, OPTIONS
> > Content-Length:  0
> >
> > U 2018/11/28 10:18:22.759216 192.168.93.214:5060 -> 192.168.80.56:5060
> > ACK  183 Session Progress
> > Via: SIP/2.0/UDP 20 SIP/2.0
> > Via: SIP/2.0/UDP 192.168.93.214:5060;branch=z9hG4bKcb74.9a10e3a3.0
> > From: <sip:+16465551212@192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
> > i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
> > To: <sip:XFER_3235551212@192.168.80.56>;tag=f9e1dd31-b586-4f47-9fb8-3d541b658a67
> > CSeq: 5413 ACK
> > Max-Forwards: 70
> > User-Agent: OpenSIPS (2.4.3 (x86_64/linux))
> > Content-Length: 0
> >
> > U 2018/11/28 10:18:22.759666 192.168.93.214:5060 -> 192.168.80.13:5060
> > SIP/2.0 400 Bad Request-URI
> > v: SIP/2.0/UDP 192.168.80.13:5060;received=192.168.80.13;rport=5060;branch=z9hG4bKPjdb6efcd9-373b-4122-8bde-9d92a608d6ee
> > f: sip:+16465551212@192.168.80.13;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
> > t: sip:+13235551212@192.168.93.214;tag=155c340f586c28d0300cf5a6ccf90d99-03d7
> > i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
> > CSeq: 5413 INVITE
> > Server: OpenSIPS (2.4.3 (x86_64/linux))
> > Content-Length: 0
> >
> > I'm going to try and get more detailed debug dumps from OpenSIPS but
> > it's only happening on a subset of calls and, of course, this was a
> > production box (I didn't notice this in my limited testing) so I'm not
> > able to safely live debug this box.
> >
> > I wanted to pitch it over the fence as soon as I could to get things
> > rolling in case you guys might have an idea what's going on.
> >
> > Thanks much,
> >
> >   - Jock
> >
> > _______________________________________________
> > Users mailing list
> > [hidden email]
> > http://lists.opensips.org/cgi-bin/mailman/listinfo/users
> >
>
> --
> Răzvan Crainea
> OpenSIPS Core Developer
>    http://www.opensips-solutions.com
> Meet the OpenSIPS team at the next OpenSIPS Summit:
>    https://www.opensips.org/events
>
> _______________________________________________
> 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