[Home]

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:07Date Closed:2008-11-20 13:25:20.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
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 05b6e9a07669fa0c0a4d88a663b4a2bd@192.168.20.2
---
 * SIP Call
 Curr. trans. direction:  Outgoing
 Call-ID:                05b6e9a07669fa0c0a4d88a663b4a2bd@192.168.20.2
 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/3.0.0.0
 Peername:               sv0071iv
 Original uri:           sip:sv0071iv.internal.xxx.on.ca:5070
 Need Destroy:           No
 Last Message:           Tx: BYE
 Promiscuous Redir:      No
 Route:                  sip:sv0071iv.internal.xxx.on.ca:5070;transport=Tcp;maddr=192.168.20.3
 DTMF Mode:              rfc2833
 SIP Options:            (none)
 Session-Timer:          Inactive


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

[Jul  4 12:29:05] WARNING[5484]: chan_sip.c:15279 handle_response: Remote host can't match request BYE to call '05b6e9a07669fa0c0a4d88a663b4a2bd@192.168.20.2'. Giving up.
[Jul  4 12:29:11] WARNING[5484]: chan_sip.c:15279 handle_response: Remote host can't match request BYE to call '05b6e9a07669fa0c0a4d88a663b4a2bd@192.168.20.2'. Giving up.
[Jul  4 12:29:18] WARNING[5484]: chan_sip.c:15279 handle_response: Remote host can't match request BYE to call '05b6e9a07669fa0c0a4d88a663b4a2bd@192.168.20.2'. 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
Max-Forwards: 70
From: <sip:sv0071iv.voice:5070>;epid=72981C2AB9;tag=a85ee012d6
To: <sip:asterisk@192.168.20.2>;tag=as643fb95e
Call-ID: 05b6e9a07669fa0c0a4d88a663b4a2bd@192.168.20.2
CSeq: 26848 BYE
User-Agent: Asterisk PBX 1.6.0-beta9
Content-Length: 0
---

We're now getting in the log files too:
---
WARNING[5484] chan_sip.c: sip_xmit of 0x48b7e5c (len 415) to 192.168.20.3:5070 returned -1 : Invalid argument

and

WARNING[5484] 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?

Thanks,
PB
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 '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2'. Giving up.

See attached for more information.
By: Vadim Sherbakov (vinsik) 2008-07-18 03:37:02

I have the same problem on 1.4.20.1.
After a call transfer asterisk seems to think that the call is still active.

[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: Auto destroying SIP dialog '264f8c8f4e671fbc2c23c01406898da7@rt.cuuma.fi'
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: Finally hanging up channel after transfer: 264f8c8f4e671fbc2c23c01406898da7@rt.cuuma.fi
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #385675))
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: = No match Their Call ID: 29A399523AED420EBDAEF4A5164D4CE40x5912ee9d Their Tag 1f971383e806 Our tag: as4d68b2fa
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: = No match Their Call ID: iSWmaDkuoIfcLz8rbhvtXONLxP17rM Their Tag 17v9cagtudhc71ej68di Our tag: as3f8d11e0
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: = No match Their Call ID: 3c26700fd6d8-di9tlee4j1qc@snom320-000413245816 Their Tag 77lkqcyrot Our tag: as01e608eb
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: = Found Their Call ID: 264f8c8f4e671fbc2c23c01406898da7@rt.cuuma.fi Their Tag as0196568f Our tag: as0196568f
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: Stopping retransmission on '264f8c8f4e671fbc2c23c01406898da7@rt.cuuma.fi' of Request 221: Match Found
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: = Found Their Call ID: 1712eb8e11ff032a10a0ba6c731e5d99@rt.cuuma.fi Their Tag  Our tag: as42cc043d
[Jul 18 11:43:26] DEBUG[6568] chan_sip.c: Stopping retransmission on '1712eb8e11ff032a10a0ba6c731e5d99@rt.cuuma.fi' 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

From full.txt:
[Jul 15 14:51:23] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '5c4453990889bf207a765e427d5b5e89@192.168.20.2' in 6400 ms (Method: REFER)
[Jul 15 14:51:24] VERBOSE[22946] logger.c: Really destroying SIP dialog '5c4453990889bf207a765e427d5b5e89@192.168.20.2' Method: REFER
[Jul 15 14:51:26] VERBOSE[22946] logger.c:
<--- SIP read from TCP://192.168.20.3:5070 --->
BYE sip:asterisk@192.168.20.2: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.

Sorry 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.