|Summary:||ASTERISK-12317: [patch] Spamming CLI / logs with 'Remote host can't match request BYE to call...'|
|Reporter:||Paul Belanger (pabelanger)||Labels:|
|Date Opened:||2008-07-04 11:33:07||Date Closed:||2008-11-20 13:25:20.000-0600|
|Environment:||Attachments:||( 0) 12994.patch|
( 1) full_v2.zip
( 2) full.txt
( 3) sip_history.txt
( 4) sip_trace.txt
|Description:||Every 6/7 seconds, our cli is getting spammed (see below).|
sip show channel email@example.com
* SIP Call
Curr. trans. direction: Outgoing
Owner channel ID: <none>
Our Codec Capability: 6
Non-Codec Capability (DTMF): 1
Their Codec Capability: 4
Joint Codec Capability: 4
Format: 0x0 (nothing)
T.38 support No
Video support No
MaxCallBR: 384 kbps
Theoretical Address: 192.168.20.3:5070
Received Address: 192.168.20.4:5070
SIP Transfer mode: open
NAT Support: RFC3581
Audio IP: 192.168.20.2 (local)
Our Tag: as643fb95e
Their Tag: as643fb95e
SIP User agent: RTCC/126.96.36.199
Original uri: sip:sv0071iv.internal.xxx.on.ca:5070
Need Destroy: No
Last Message: Tx: BYE
Promiscuous Redir: No
DTMF Mode: rfc2833
SIP Options: (none)
****** ADDITIONAL INFORMATION ******
[Jul 4 12:29:05] WARNING: chan_sip.c:15279 handle_response: Remote host can't match request BYE to call 'firstname.lastname@example.org'. Giving up.
[Jul 4 12:29:11] WARNING: chan_sip.c:15279 handle_response: Remote host can't match request BYE to call 'email@example.com'. Giving up.
[Jul 4 12:29:18] WARNING: chan_sip.c:15279 handle_response: Remote host can't match request BYE to call 'firstname.lastname@example.org'. Giving up.
|Comments:||By: Paul Belanger (pabelanger) 2008-07-04 11:35:52|
uploaded sip trace
By: Paul Belanger (pabelanger) 2008-07-04 13:29:08
Some additional information around this bug. It seems after I enabled sip debug for the trace, then disabled it. Some sip traces are still send to the cli.
> sip set debug off
SIP Debugging Disabled
BYE sip:sv0071iv.xxx.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0
Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK0ebfa37b;rport
CSeq: 26848 BYE
User-Agent: Asterisk PBX 1.6.0-beta9
We're now getting in the log files too:
WARNING chan_sip.c: sip_xmit of 0x48b7e5c (len 415) to 192.168.20.3:5070 returned -1 : Invalid argument
WARNING chan_sip.c: sip_xmit of 0x48b7e5c (len 415) to 192.168.20.3:5070 returned -2 : Bad file descriptor
By: Paul Belanger (pabelanger) 2008-07-04 13:36:25
It seems to be rotating... it now says:
chan_sip.c: sip_xmit of 0x48b7e5c (len 415) to 192.168.20.3:5070 returned 0 : Interrupted system call
By: Olle Johansson (oej) 2008-07-05 13:23:57
Well, the packets you've captured doesn't tell me anything. Capture all the console output, from the setup of the call to the BYE that fails and we can try to figure out what happens. Right now the only thing I can say based on your debug is "Yes, the remote host doesn't recognize the call". And that's no bug in Asterisk...
Set debug level to 5, verbose to 5, enable sip history and dumphistory in sip.conf and turn on sip debugging on the console. Capture all of consoles output to file. Upload that file after studying it.
By: Paul Belanger (pabelanger) 2008-07-11 13:56:54
oej: Sorry for the delay on this. I'll do as you ask and enable logging and history on SIP. We cannot reproduce this at will so it may take some time.
Question, what about have asterisk give up after x amount of failed times?
By: Paul Belanger (pabelanger) 2008-07-15 15:50:13
oej: We managed to capture the issue again today. This time we have verbose and debugs.
chan_sip.c:15282 handle_response: Remote host can't match request BYE to call 'email@example.com'. Giving up.
See attached for more information.
By: Vadim Sherbakov (vinsik) 2008-07-18 03:37:02
I have the same problem on 188.8.131.52.
After a call transfer asterisk seems to think that the call is still active.
[Jul 18 11:43:26] DEBUG chan_sip.c: Auto destroying SIP dialog 'firstname.lastname@example.org'
[Jul 18 11:43:26] DEBUG chan_sip.c: Finally hanging up channel after transfer: email@example.com
[Jul 18 11:43:26] DEBUG chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #385675))
[Jul 18 11:43:26] DEBUG chan_sip.c: = No match Their Call ID: 29A399523AED420EBDAEF4A5164D4CE40x5912ee9d Their Tag 1f971383e806 Our tag: as4d68b2fa
[Jul 18 11:43:26] DEBUG chan_sip.c: = No match Their Call ID: iSWmaDkuoIfcLz8rbhvtXONLxP17rM Their Tag 17v9cagtudhc71ej68di Our tag: as3f8d11e0
[Jul 18 11:43:26] DEBUG chan_sip.c: = No match Their Call ID: 3c26700fd6d8-di9tlee4j1qc@snom320-000413245816 Their Tag 77lkqcyrot Our tag: as01e608eb
[Jul 18 11:43:26] DEBUG chan_sip.c: = Found Their Call ID: firstname.lastname@example.org Their Tag as0196568f Our tag: as0196568f
[Jul 18 11:43:26] DEBUG chan_sip.c: Stopping retransmission on 'email@example.com' of Request 221: Match Found
[Jul 18 11:43:26] DEBUG chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 18 11:43:26] DEBUG chan_sip.c: = Found Their Call ID: firstname.lastname@example.org Their Tag Our tag: as42cc043d
[Jul 18 11:43:26] DEBUG chan_sip.c: Stopping retransmission on 'email@example.com' of Request 102: Match Found
This is what debug 9 is giving.
Reload of module chan_sip.so does not help.
Reload of asterisk does not help.
Restart of asterisk helps.
By: Olle Johansson (oej) 2008-07-18 04:06:55
[Jul 15 14:51:23] VERBOSE logger.c: Scheduling destruction of SIP dialog 'firstname.lastname@example.org' in 6400 ms (Method: REFER)
[Jul 15 14:51:24] VERBOSE logger.c: Really destroying SIP dialog 'email@example.com' Method: REFER
[Jul 15 14:51:26] VERBOSE logger.c:
<--- SIP read from TCP://192.168.20.3:5070 --->
BYE sip:firstname.lastname@example.org:5060;transport=TCP SIP/2.0
The SIp dialog is destroyed prematurely, before it's actually hanged up by the BYE. Seems like the 200 OK on the NOTIFY triggers the destruction of the pvt without a proper hangup. The initial call is not in the log however, which would be good to have.
By: Paul Belanger (pabelanger) 2008-07-18 12:30:19
Wow, that took a while for me to upload the .zip. Lots of Mantis errors.
Either way, I hope this will show the information your looking for oej.
By: Paul Belanger (pabelanger) 2008-09-18 15:53:06
Any this I could to do help this issue along?
By: Mark Michelson (mmichelson) 2008-10-30 15:43:45
I've started looking at this issue, and the problem comes from the fact that the logic in the function __sip_autodestruct() allows for infinite retransmissions of BYE requests.
I believe it is enough to set the NEEDDESTROY flag when receiving a 4XX response to a BYE. I'm uploading a patch to try.
By: Mark Michelson (mmichelson) 2008-10-30 15:46:04
12994.patch has been uploaded and is ready for testing. Let me know if this works. I have other ideas up my sleeve if this doesn't, but I'm pretty confident this is all that is needed.
By: Paul Belanger (pabelanger) 2008-11-04 12:07:57.000-0600
Thanks again putnopvut. We'll trying to roll the patch into production asap.
By: Mark Michelson (mmichelson) 2008-11-11 14:47:36.000-0600
pabelanger, have you used this patch in production yet? Does the problem appear to be solved?
By: Paul Belanger (pabelanger) 2008-11-11 15:26:27.000-0600
putnopvut: Sorry no. New management at our client site is now causing delays to implement this fix. Since it is not service affecting, they are reluctant to do any upgrades atm. I'll try to reproduce this error in our lab again.
By: Mark Michelson (mmichelson) 2008-11-11 15:28:39.000-0600
It's cool. We have a customer who was complaining about the same issue. We implemented this patch for them and they have since said that the problem is fixed. I was looking for confirmation here, too before I commit it to open source Asterisk, though.
By: Mark Michelson (mmichelson) 2008-11-20 11:44:18.000-0600
I have decided to go ahead and commit the patch since I have received confirmation from other sources that this patch fixes the problem.
By: Mark Michelson (mmichelson) 2008-11-20 13:25:19.000-0600
Interesting. The commit message template isn't working properly. This is fixed in the 1.4 branch with revision 158071 and in trunk with revision 158133.