[Home]

Summary:ASTERISK-12102: reINVITE --> Ignoring this INVITE request --> Hanging up call - no reply to our critical packet.
Reporter:Johan Wilfer (johan)Labels:
Date Opened:2008-05-28 17:44:29Date Closed:2008-12-09 11:14:55.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 12746.txt
( 1) bug0012746sipdialog
( 2) Maximum_retries_exceeded_on_transmission_MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc
( 3) Sip_registration_SIP_TIMER:_Initializing_retransmit_timer_on_packet:_Id_#-1
Description:Under light load this does not occur. However, when Asterisk serves more than a few calls my provider resends the initial INVITE. Then you see the following in the log:
[May 22 18:46:05] VERBOSE[26472] logger.c: Ignoring this INVITE request

Then follows retries and about 20 seconds after the call is initiated it is terminated by Asterisk:
[May 22 18:46:25] WARNING[26472] chan_sip.c: Maximum retries exceeded on transmission N2EzNDEyOGFmNGNmZmY0NGM4NmJlMmZmZWIzMDg3Mzk. for seqno 1 (Critical Response)
[May 22 18:46:25] WARNING[26472] chan_sip.c: Hanging up call N2EzNDEyOGFmNGNmZmY0NGM4NmJlMmZmZWIzMDg3Mzk. - no reply to our critical packet.

Below the SIP HISTORY for the dialogue is attached. I've tried to sort this out with no success. There seem to be some miscommunication between Asterisk and my providers sip server. This can and have also occurred during calls, exactly the same outcome.

****** ADDITIONAL INFORMATION ******

---------- SIP HISTORY for 'N2EzNDEyOGFmNGNmZmY0NGM4NmJlMmZmZWIzMDg3Mzk.'
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   * SIP Call
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   001. Rx              INVITE / 1 INVITE / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   002. NewChan         Channel SIP/XXXXXXXXXX-082ba218 - from N2EzNDEyOGFmNGNmZmY0NGM4
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   003. TxResp          SIP/2.0 / 1 INVITE - 100 Trying
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   004. TxRespRel       SIP/2.0 / 1 INVITE - 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   005. Rx              INVITE / 1 INVITE / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   006. TxResp          SIP/2.0 / 1 INVITE - 100 Trying
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   007. TxRespRel       SIP/2.0 / 1 INVITE - 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   008. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   009. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   010. ReTx            1000 SIP/2.0 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   011. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   012. ReTx            2000 SIP/2.0 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   013. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   014. ReTx            4000 SIP/2.0 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   015. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   016. ReTx            4000 SIP/2.0 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   017. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   018. ReTx            4000 SIP/2.0 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   019. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   020. ReTx            4000 SIP/2.0 200 OK
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   021. Rx              ACK / 1 ACK / sip:0303350XXX@217.25.XXX.XXX
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   022. MaxRetries      (Critical)
[May 22 18:46:26] DEBUG[26472] chan_sip.c:   023. Hangup          Cause No user responding
[May 22 18:46:26] DEBUG[26472] chan_sip.c:
---------- END SIP HISTORY for 'N2EzNDEyOGFmNGNmZmY0NGM4NmJlMmZmZWIzMDg3Mzk.'
Comments:By: Raj Jain (rjain) 2008-06-01 06:00:31

We are ignoring UAC's ACK somehow, and thus we keep re-transmitting the 200 OK. I'm not sure why, because the messaging looks ok. Pls. enable core logging to level 10 and repost the log.
By: Johan Wilfer (johan) 2008-06-01 08:13:14

I've the following in logger.conf to be able to catch the debug:
full => notice,warning,error,debug,verbose ;logs to /var/asterisk/full
This log was intended for my voip supplier so I removed the dialplan execution entries.

I've added to asterisk.conf under [options]
verbose = 10

Is this what you asked me to do? Or is it more? (I still have the original logs  if that's enough).
By: Raj Jain (rjain) 2008-06-01 10:04:44

I don't see debug entries in the log. Pls. post unstripped log.
By: Johan Wilfer (johan) 2008-06-01 11:41:15

I haven't stripped any debug messages from the log. I do have stripped away the dialplan execution entries however. ("VERBOSE[19271] logger.c: -- Executing ... in new stack").

I've configured my Asterisk as above to get the missing debug entries.

Is it sufficient or do I need to configure my Asterisk further to get these logs?
By: David Woolley (davidw) 2008-06-01 12:19:41

With the default configuration, debug messages aren't output.  You need to enable output in logger.conf.
By: Johan Wilfer (johan) 2008-06-01 17:06:35

Ok, now I have very chatty logs so I guess it works. Thanks! My conf:

--- asterisk.conf ---
[options]
verbose = 10
debug = 10

--- logger.conf ---
[logfiles]
console => notice,warning,error
messages => warning,error
full => notice,warning,error,debug,verbose

I get approximately two of these per week. Most for them occur at the beginning of the call, but I've seen cases where this happens mid call as well (reinvite).
I'll post the output here when I catch another.

Isn't these messages strange (from the dialog attached):
[May 22 18:46:05] VERBOSE[26472] logger.c: --- (21 headers 16 lines) ---
[May 22 18:46:05] VERBOSE[26472] logger.c: Ignoring this INVITE request
[May 22 18:46:05] VERBOSE[26472] logger.c:

After this you have all these retransmits and then the channel are terminated..


By: Raj Jain (rjain) 2008-06-01 17:13:40

The message "Ignoring this INVITE request" is printed when Asterisk receives an INVITE retransmission. That part is correct. I'm not sure why we're ignoring the ACK. A naked eye look at the messaging doesn't seem to reveal much, that's why I've requested the debug log.
By: Johan Wilfer (johan) 2008-06-01 17:19:38

I have enabled this now with the settings verbose = 10, debug = 10. I will upload a full dialog as soon I catch one. That will probably take a few days.

Thank you rjain!
By: Himal R Rana (ranahimal) 2008-06-30 06:36:59

Hello!
I have been tracing this same bug from quit few time!
It happens where there is re-transmitted invite and u r auto answering call to playback something.
There is one bug posted related to this and also one nice discussion between OLE.
and RAJ regarding this.
I think its related to the  SDP session Id which may get the things this way.
I m providing some link for the more details.

http://bugs.digium.com/view.php?id=10332
And
http://www.mail-archive.com/asterisk-users@lists.digium.com/msg177079.html

Thanks.
Himal R Rana
By: Olle Johansson (oej) 2008-07-01 02:36:12

We do need a full debug output in order to see what's going on. Make sure you enable debug to console and catch everything on the console for this. THanks.
By: Johan Wilfer (johan) 2008-07-01 04:32:13

Yes I am auto answering to playback a sound file. But science my voip supplier fixed the problem in their end I don't get these problems any more... Maybe we could keep this one open for a while and I report if I can catch one more of these.

Catching on the console is next to impossible because it's like <1% of the calls that ends up this way. But it's enough to make my customers complain.. So I log everything instead.
By: Himal R Rana (ranahimal) 2008-07-03 03:16:38

Yes i resolved the issue by very differently!
But it is not the resolution for the problem.
I m not auto answering the calls but rather waiting for the upstream ACK to come and fulfill the transaction then everything seems to work perfectly.
The scenario is like this way we are dealing with the vpn gateway which is giving us sip traffic so there will be delay in the transactions.
In this case there will be re-transmits going on.

-------------Problem is like this way--------------------
Problem arises when the i m auto answering the call so asterisk sends OK to ongoing call then there comes the ACK from the upstream call and we are sending that OK to downstream user(VPN one- with retransmits) too.
So there is two OK transaction going on at same time from asterisk which is very unusual and leads to destruction of call when retransmit of any two transaction exceeds.
And u will be disconnected on connected call..
By: Johan Wilfer (johan) 2008-07-03 05:26:38

Does that mean that Asterisk can be modified to not terminate these calls?

Edit: How did you implement your workaround?


By: Olle Johansson (oej) 2008-07-03 05:30:10

Closing this since original reporter solved the issue without a change in Asterisk.
Feel free to reopen if the issue comes back.

Thanks!
By: Johan Wilfer (johan) 2008-07-03 05:36:52

Sorry, I just got one more of these.

[Jun 29 11:02:33] WARNING[10286] chan_sip.c: Maximum retries exceeded on transmission YWQxMjFiNWRlNjMyNDlkY2JmMzA1NjE2MmE0NDg1OWU. for seqno 1 (Critical Response)
[Jun 29 11:02:33] WARNING[10286] chan_sip.c: Hanging up call YWQxMjFiNWRlNjMyNDlkY2JmMzA1NjE2MmE0NDg1OWU. - no reply to our critical packet.

I will start digging into my logs now...
By: Johan Wilfer (johan) 2008-07-03 09:46:16

Ok, I've uploaded a more verbose log of this error. I've caught three calls that are terminated this way, so if you need more data I'll upload them as well.
By: Olle Johansson (oej) 2008-07-03 10:34:56

Can you please test with latest 1.4 from svn?

I see
[Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Stopping retransmission on 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.' of Response 1: Match Found

THen a retransmission of that 200 OK soon after. Just to be sure we're not chasing shadows, please try with a later version than 1.4.19. Thank you.
By: Olle Johansson (oej) 2008-07-03 10:35:54

[Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #-1

A bit strange that one too.
By: Olle Johansson (oej) 2008-07-03 10:38:15

---------- SIP HISTORY for 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.'
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   * SIP Call
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   001. Rx              INVITE / 1 INVITE / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   002. NewChan         Channel SIP/voipprovider-0821c288 - from MWQxOGM5YmZkOTJmMDgyYTA1
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   003. TxResp          SIP/2.0 / 1 INVITE - 100 Trying
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   004. TxRespRel       SIP/2.0 / 1 INVITE - 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   005. Rx              INVITE / 1 INVITE / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   006. TxResp          SIP/2.0 / 1 INVITE - 100 Trying
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   007. TxRespRel       SIP/2.0 / 1 INVITE - 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   008. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   009. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   010. ReTx            1000 SIP/2.0 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   011. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   012. ReTx            2000 SIP/2.0 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   013. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   014. ReTx            4000 SIP/2.0 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   015. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   016. ReTx            4000 SIP/2.0 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   017. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   018. ReTx            4000 SIP/2.0 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   019. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   020. ReTx            4000 SIP/2.0 200 OK
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   021. Rx              ACK / 1 ACK / sip:0303123456@123.456.789.123
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   022. MaxRetries      (Critical)
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:   023. Hangup          Cause No user responding
[Jun 25 00:45:58] DEBUG[10286] chan_sip.c:
---------- END SIP HISTORY for 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.'
By: Olle Johansson (oej) 2008-07-03 10:44:54

"Ahh. Vi har en retransmit."

There's a retransmit that generates a reply that we retransmit endlessly. That's bad. Let's fix.
By: Olle Johansson (oej) 2008-07-03 10:58:08

Johan, please test this patch to your current asterisk or the latest one. I think this will fix your problem. Thanks for reporting back quickly, so I can fix this in svn.

Hälsningar
/Olle
By: Johan Wilfer (johan) 2008-07-03 11:29:02

Tack! :-)
I'll apply this path to my system tonight, thanks Olle!

Edit: I've applied the patch now, I'm still use version 1.4.19 because I have to apply a bunch of manual patches (integrated in svn but not in 1.4) to add functionality to my 1.4...

I've at least one of these per week so I report back in two weeks...


By: Olle Johansson (oej) 2008-07-04 02:34:04

Ok, looking forward to your reply. Please report after a few days too, even if you don't see this so I know that the patch doesn't break anything. If so, I can commit this and we'll hope that it fixed your issue.
By: Johan Wilfer (johan) 2008-07-04 07:59:11

Ok, I'll. It havn't crached yet :-)

One change I noticed is that previously my messages-log was clutterd with lines like:
[Jun 25 00:45:38] WARNING[10286] chan_sip.c: Unsupported SDP media type in offer: image 4922 udptl t38
one for each call... They are now all gone.
By: Johan Wilfer (johan) 2008-07-04 08:51:06

Olle, about:
[Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1

I see these in SIP REGISTRY as well, I've uploaded a log if you want to take a look.
By: Johan Wilfer (johan) 2008-07-07 19:20:30

The patch does not break my system. Until now this works perfectly, no calls are terminated because of this any more... I will report back after some weeks also.
By: Digium Subversion (svnbot) 2008-07-08 03:58:41

Repository: asterisk
Revision: 128912

U   branches/1.4/channels/chan_sip.c

------------------------------------------------------------------------
r128912 | oej | 2008-07-08 03:58:36 -0500 (Tue, 08 Jul 2008) | 7 lines

Fix issues where repeated messages where ignored, but retransmitted reliably instead of unreliably.
Reported by: johan
Patches:
     12746.txt uploaded by oej (license 306)
Tested by: johan
(issue ASTERISK-12102)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=128912
By: Olle Johansson (oej) 2008-07-08 04:12:30

Ok, I've committed the fix to 1.4, trunk and 1.6.0 branches. Thanks for your responses. If the problem re-appears, then don't hesitate to re-open this bug.

/Olle