[Serusers] Re: [Serdev] ACK before INVITE on re-INVITE causes Cisco AS's to return a 500 error

[Evan Borgstrom]

Hey Greger,

	Sorry, I made a typo, the message at 16:51:51.559657 should be listed
as going to the Cisco device at Z.Z.Z.Z and not Asterisk at X.X.X.X.

	The interesting this is this usually only happens about once an hour
and all the other times the ACK leaves SER before the INVITE. We log
everything on our boxes pretty extensively (we log a bunch of human
readable data along with the entire message buffer via xlog) for most
messages and if I look through our logs I see the ACK being processed as
loose before the INVITE.

	The loose route section of the config is pretty simple, it xlogs some
stuff and then sends it off to route(1) which sets up a reply handler,
adds an RPID and t_relay()'s so I'm not sure the config has anything to
do with this, especially because the ACK is delivered before the INVITE
approx 98 out of 100 times.

-Evan

Greger V. Teigre wrote:
> Evan,
> I'm not able to match your text with the messages you show. The message
> timestamped 16:51:51.559657, does it go to Cisco? It is shown to go to
> Asterisk and it doesn't make sense.
> However, until the Cisco gw receives the ACK from Asterisk, no call has
> been established and the reINVITE cannot be matched. IMO, this is not a
> Cisco bug. It seems very strange indeed that ser should send a reINVITE
> before the ACK in the same call. Even without FIFO, an INVITE is likely
> to take more time to process than a loose routed ACK. I would try to log
> more thoroughly in SER to see what happens in processing the ACK and the
> reINVITE.  It could be a problem in your ser.cfg, but it seems strange
> indeed.
> g-)
> 
> ----- Original Message ----- From: "Evan Borgstrom"
> <evan.borgstrom at ca.mci.com>
> To: <serusers at lists.iptel.org>; <serdev at lists.iptel.org>
> Sent: Wednesday, November 16, 2005 12:05 AM
> Subject: [Serdev] ACK before INVITE on re-INVITE causes Cisco AS's to
> return a 500 error
> 
> 
>> Hey all,
>>
>> This has more to do with Asterisk & Cisco AS's IMO but I thought it
>> would be interesting to get some responses from this group before I
>> begin the battle with Cisco to get a bug report underway.
>>
>> We have an Asterisk box acting as a PBX sending calls to our SER
>> instances. The asterisk box has "reinvite=yes" in the sip.conf file
>> which causes Asterisk to send a re-INVITE for the call once it receives
>> the 200 OK. This re-INVITE has it's SDP changed to that of the IP Phone
>> behind the Asterisk box so that all media doesn't need to traverse it.
>> This works fine except in certain instances where messages get out of
>> order and it causes our Cisco GW's to error the call with a generic 500
>> message. When the messages are in the correct order the 500 error does
>> not appear.
>>
>> So here's the situation, user behind the asterisk box picks up the
>> phone and dials a PSTN destination. Asterisk fires off the initial
>> invite and everything proceeds as normal and we eventually receive the
>> 200 OK message to which the Asterisk box replies with ACK and a new
>> INVITE that come in this order (X = Asterisk, Y = SER, Z = Cisco):
>>
>> U 2005/11/15 16:51:51.557322 X.X.X.X:5060 -> Y.Y.Y.Y:5060
>> ACK
>>
>> #
>> U 2005/11/15 16:51:51.557948 X.X.X.X:5060 -> Y.Y.Y.Y:5060
>> INVITE
>>
>> SER accordingly processes the two messages and replies 100 Trying to
>> the new INVITE message. Here's where the problem occurs, SER then sends
>> these messages out to the PSTN gateway but the order has been reversed:
>>
>> #
>> U 2005/11/15 16:51:51.558937 Y.Y.Y.Y:5060 -> X.X.X.X:5060
>> SIP/2.0 100 trying
>>
>> #
>> U 2005/11/15 16:51:51.559000 Y.Y.Y.Y:5060 -> Z.Z.Z.Z:5060
>> INVITE
>>
>> #
>> U 2005/11/15 16:51:51.559657 Y.Y.Y.Y:5060 -> X.X.X.X:5060
>> ACK
>>
>> When this happens the Cisco GW replies with a 500 error message and the
>> following is sent to the Cisco's logs:
>>
>> #
>> U 2005/11/15 16:51:51.711355 Z.Z.Z.Z:5060 -> Y.Y.Y.Y:5060
>> SIP/2.0 500 Server Internal Error.
>>
>>
>> Nov 15 21:51:51.613: HandleUdpSocketReads :Msg enqueued for SPI with
>> IPaddr: Y.Y.Y.Y:5060
>> Nov 15 21:51:51.613: *****CCB found in UAS Request table. ccb=0x653BCD0C
>> Nov 15 21:51:51.613: CCSIP-SPI-CONTROL:  act_sentsucc_new_message
>> Nov 15 21:51:51.617: CCSIP-SPI-CONTROL: act_sentsucc_new_message_request
>> Nov 15 21:51:51.617:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
>> Nov 15 21:51:51.617: sip_stats_status_code
>> Nov 15 21:51:51.617: sipSPICheckRequest: CheckRequest fail on method 102
>> error code: 2 and status: 500
>>
>>
>> Is there any parameter that I can set to ensure that message leave SER
>> in the order they enter? Should the Cisco be able to handle this
>> condition (I check a number of different sections of the RFC but
>> couldn't find anything specific for either side)?
>>
>> Thanks,
>> Evan
>>
>> _______________________________________________
>> Serdev mailing list
>> serdev at lists.iptel.org
>> http://lists.iptel.org/mailman/listinfo/serdev
>>
>>
>