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
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
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
Evan,
I would not invest the time to look into the SER side of your problem. Because this is a general problem. Instead of SER any other network element (router, switch, etc.) could change the order of the packets. BTW I guess this problem occurs on your SER because the ACK and the INVITE are handled by different SER processes. And as SER is not call-statefull there is no parameter to solve this situation.
I fear you are right that this problem is not covered by any RFC, but the solutions seems logical to me: if this a generic problem, then either the UAC is not allowed to send a re-INVITE until the first INVITE is completed, or the UAS has to accept a re-INVITE after sending the 200 OK. But how does the the UAC know that the ACK reached the UAS so that it can send the re-INVITE now? It cant know that, so it would have to wait for a timer before it could send the re-INVITE. On the other side the INVITE transaction is completed for the UAS by sending the 200 OK (the ACK is a new transaction, according to the branch). Thus I think the UAS (the Cisco gateway) should accept the re-INVITE without complaining.
Just for curiosity: is the call established or does the Cisco gateway drop the call after sending the 500?
Regards Nils
On Wednesday 16 November 2005 07:51, 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
Serdev mailing list serdev@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serdev
Hey Nils,
You are correct that each message is handled by a different process, as it to be expected, and I know that SER is not call statefull so my concern lies around the fact that SER is delivering an INVITE which requires FAR more processing and at least 2 database hits before a loosely routed ACK which requires little to none for processing.
I'm going to differ with you, and my self from last night, on the views about the RFC as it does indeed cover the problem (I was just looking at it the wrong way before). A re-INVITE cannot modify a dialog that does not exist, and without the ACK being delivered in response to the 200 OK the dialog is not yet created which is why the Cisco is returning a CheckRequest failure since there's no dialog to map the re-INVITE to. So, the device is correct in returning an error.
When the Cisco returns the 500 error it's only for the re-INVITE so the initial call stays established and a BYE is still required to tear it down. The problem is that Asterisk is expecting that to work and has already re-INVITED to the client so there's no audio and to the caller the call failed.
-Evan
Nils Ohlmeier wrote:
Evan,
I would not invest the time to look into the SER side of your problem. Because this is a general problem. Instead of SER any other network element (router, switch, etc.) could change the order of the packets. BTW I guess this problem occurs on your SER because the ACK and the INVITE are handled by different SER processes. And as SER is not call-statefull there is no parameter to solve this situation.
I fear you are right that this problem is not covered by any RFC, but the solutions seems logical to me: if this a generic problem, then either the UAC is not allowed to send a re-INVITE until the first INVITE is completed, or the UAS has to accept a re-INVITE after sending the 200 OK. But how does the the UAC know that the ACK reached the UAS so that it can send the re-INVITE now? It cant know that, so it would have to wait for a timer before it could send the re-INVITE. On the other side the INVITE transaction is completed for the UAS by sending the 200 OK (the ACK is a new transaction, according to the branch). Thus I think the UAS (the Cisco gateway) should accept the re-INVITE without complaining.
Just for curiosity: is the call established or does the Cisco gateway drop the call after sending the 500?
Regards Nils
On Wednesday 16 November 2005 07:51, 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
Serdev mailing list serdev@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serdev
-
Evan Borgstrom -
Greger V. Teigre -
Nils Ohlmeier