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@ca.mci.com To: serusers@lists.iptel.org; serdev@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@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serdev