[OpenSIPS-Users] "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 at 192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
To: <sip:XFER_3235551212 at 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 at 192.168.80.13>;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
i: e33b7043-ef96-4102-9f6a-bcb9c97ac4da
To: <sip:XFER_3235551212 at 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 at 192.168.80.13;tag=c0d1ec70-fbaa-429c-acc9-17dec131459e
t: sip:+13235551212 at 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