[asterisk-users] Re: some transfers dropped.
Steven
asterisk at tescogroup.com
Sun Oct 22 18:27:50 MST 2006
Could there be something going on in asterisk to make the first request fail, so that the SIP device cancels and retries the
transfer(refer)?
Could it be manager overuse?
--
--
Steven
http://www.glimasoutheast.org
"BerkHolz, Steven" <StevenBerkHolz at TESCOGroup.com> wrote in message
news:03C20CC487B2EF488E22EC586871ABBE02EBD0A3 at tg32.tescogroup.com...
We are having an issue with transferred calls being dropped.
Looking at the asterisk 1.2.10 logs, it appears that when it is dropped,
the SIP unit send a CANCEL message to the server.
On successful transfers this is not seen.
The errors logged in the SIP Unit error log, I believe are from the
second attempt to transfer the call, after it has actually been
disconnected.
Nothing is deferent in the logs above the CANCEL request for successful
or failed transfers.
So, I am not sure why the CANCEL is being sent.
I can not discern what may be different when it fails.
Thank You,
Steven BerkHolz
Board member of
www.glimasoutheast.org
ref: from SIP Phone (I think these are the second invite after it is
hung up)
2006-OCT-20 17:49:52 GMT +++ Current Timestamp +++
2006-OCT-20 17:19:47 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 15:56:37 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 15:50:00 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 15:45:38 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 15:11:28 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 15:10:58 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 14:59:26 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-20 12:45:30 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 19:53:25 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 18:40:52 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 18:03:45 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 17:55:55 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 15:09:13 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 15:04:33 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 14:52:12 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 14:34:35 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 14:20:17 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
2006-OCT-19 13:45:33 GMT NLPA ERROR: sipFailureResponseToRefer: received
603 response to REFER
ref. from asterisk 1.2.10 logs:
Oct 20 13:19:45 VERBOSE[10652] logger.c: -- Requested transfer
capability: 0x00 - SPEECH
Oct 20 13:19:45 DEBUG[8159] channel.c: Avoiding initial deadlock for
'Zap/25-1'
Oct 20 13:19:45 VERBOSE[10652] logger.c: -- Called g2/5155
Oct 20 13:19:45 VERBOSE[10652] logger.c: Transmitting (no NAT) to
172.16.8.200:5065:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425957956;received=172.16.8.200
From: "From Desk"<sip:5100 at 172.16.200.5>;tag=2425948795
To: <sip:5155 at 172.16.200.5>;tag=as279eb184
Call-ID: 2425954456-c4756-5065 at 172.16.8.200
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:5155 at 172.16.200.5>
Content-Length: 0
---
Oct 20 13:19:45 DEBUG[10658] app_queue.c: Device 'Zap/25' changed to
state '2' (In use) but we don't care because they're not a member of any
queue.
Oct 20 13:19:45 DEBUG[8159] devicestate.c: Changing state for Zap/25 -
state 2 (In use)
Oct 20 13:19:45 DEBUG[10659] app_queue.c: Device 'Zap/25' changed to
state '2' (In use) but we don't care because they're not a member of any
queue.
Oct 20 13:19:45 DEBUG[8167] chan_zap.c: Enabled echo cancellation on
channel 25
Oct 20 13:19:45 VERBOSE[10652] logger.c: -- Zap/25-1 is ringing
Oct 20 13:19:45 DEBUG[8159] devicestate.c: Changing state for Zap/25 -
state 6 (Ringing)
Oct 20 13:19:45 DEBUG[10660] app_queue.c: Device 'Zap/25' changed to
state '6' (Ringing) but we don't care because they're not a member of
any queue.
Oct 20 13:19:45 DEBUG[8171] chan_sip.c: Header 0: (0)
Oct 20 13:19:46 VERBOSE[8171] logger.c:
<-- SIP read from 172.16.8.200:5065:
CANCEL sip:5155 at 172.16.200.5 SIP/2.0
Via: SIP/2.0/UDP 172.16.8.200:5065;branch=z9hG4bKline0-2425957956
To: <sip:5155 at 172.16.200.5>
From: "From Desk"<sip:5100 at 172.16.200.5>;tag=2425948795
Call-Id: 2425954456-c4756-5065 at 172.16.8.200
Max-Forwards: 70
CSeq: 2 CANCEL
Content-Length: 0
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 0: CANCEL
sip:5155 at 172.16.200.5 SIP/2.0 (36)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 1: Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425957956 (65)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 2: To:
<sip:5155 at 172.16.200.5> (27)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 3: From: "From
Desk"<sip:5100 at 172.16.200.5>;tag=2425948795 (55)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 4: Call-Id:
2425954456-c4756-5065 at 172.16.8.200 (43)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 5: Max-Forwards: 70 (16)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 6: CSeq: 2 CANCEL (14)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 7: Content-Length: 0 (17)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 8: (0)
Oct 20 13:19:46 VERBOSE[8171] logger.c: --- (8 headers 0 lines)Oct 20
13:19:46 VERBOSE[8171] logger.c: --- (8 headers 0 lines)---
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: **** Received CANCEL (14) -
Command in SIP CANCEL
Oct 20 13:19:46 VERBOSE[8171] logger.c: Sending to 172.16.8.200 : 5065
(non-NAT)
Oct 20 13:19:46 VERBOSE[8171] logger.c: Reliably Transmitting (no NAT)
to 172.16.8.200:5065:
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425957956;received=172.16.8.200
From: "From Desk"<sip:5100 at 172.16.200.5>;tag=2425948795
To: <sip:5155 at 172.16.200.5>;tag=as279eb184
Call-ID: 2425954456-c4756-5065 at 172.16.8.200
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:5155 at 172.16.200.5>
Content-Length: 0
---
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: *** SIP TIMER: Initalizing
retransmit timer on packet: Id #51636
Oct 20 13:19:46 VERBOSE[8171] logger.c: Transmitting (no NAT) to
172.16.8.200:5065:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425957956;received=172.16.8.200
From: "From Desk"<sip:5100 at 172.16.200.5>;tag=2425948795
To: <sip:5155 at 172.16.200.5>;tag=as279eb184
Call-ID: 2425954456-c4756-5065 at 172.16.8.200
CSeq: 2 CANCEL
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:5155 at 172.16.200.5>
Content-Length: 0
---
Oct 20 13:19:46 DEBUG[10652] channel.c: Hanging up channel 'Zap/25-1'
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: zt_hangup(Zap/25-1)
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: Set option AUDIO MODE, value:
ON(1) on Zap/25-1
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: Hangup: channel: 25 index = 0,
normal = 38, callwait = -1, thirdcall = -1
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: Not yet hungup... Calling
hangup once with icause, and clearing call
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: disabled echo cancellation on
channel 25
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: Set option TDD MODE, value:
OFF(0) on Zap/25-1
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: Updated conferencing on 25,
with 0 conference users
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: Set option AUDIO MODE, value:
OFF(0) on Zap/25-1
Oct 20 13:19:46 DEBUG[10652] chan_zap.c: disabled echo cancellation on
channel 25
Oct 20 13:19:46 VERBOSE[10652] logger.c: -- Hungup 'Zap/25-1'
Oct 20 13:19:46 DEBUG[10652] app_dial.c: Exiting with DIALSTATUS=CANCEL.
Oct 20 13:19:46 DEBUG[10652] app_macro.c: Spawn extension
(macro-dial,s,12) exited non-zero on 'SIP/5100-9f70a9b0' in macro 'dial'
Oct 20 13:19:46 DEBUG[10652] app_macro.c: Spawn extension
(macro-dial,s,12) exited non-zero on 'SIP/5100-9f70a9b0' in macro
'exten-vm'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Spawn extension (macro-dial,s,12)
exited non-zero on 'SIP/5100-9f70a9b0'
Oct 20 13:19:46 DEBUG[8159] devicestate.c: Changing state for Zap/25 -
state 0 (Unknown)
Oct 20 13:19:46 DEBUG[10652] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Oct 20 13:19:46 DEBUG[10652] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,dura
tion,billsec,disposition,amaflags,accountcode,uniqueid) VALUES
('2006-10-20 13:19:44','5100','5100','5155','from-internal',
'SIP/5100-9f70a9b0','Zap/25-1','Dial','zap/g2/5155|15|r',2,0,'NO
ANSWER',3,'','1161364784.6637')
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '5100'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '5100'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '5155'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is 'from-internal'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is
'SIP/5100-9f70a9b0'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is 'Zap/25-1'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is 'Dial'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is
'zap/g2/5155|15|r'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '2006-10-20
13:19:44'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '(null)'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '2006-10-20
13:19:46'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '2'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '0'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is 'NO ANSWER'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is 'DOCUMENTATION'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '(null)'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '1161364784.6637'
Oct 20 13:19:46 DEBUG[10652] pbx.c: Function result is '(null)'
Oct 20 13:19:46 DEBUG[10652] channel.c: Hanging up channel
'SIP/5100-9f70a9b0'
Oct 20 13:19:46 DEBUG[10652] chan_sip.c: Hangup call SIP/5100-9f70a9b0,
SIP callid 2425954456-c4756-5065 at 172.16.8.200)
Oct 20 13:19:46 DEBUG[10652] chan_sip.c: update_call_counter(5100) -
decrement call limit counter
Oct 20 13:19:46 DEBUG[10652] chan_sip.c: Updating call counter for
incoming call
Oct 20 13:19:46 DEBUG[8159] chan_sip.c: Checking device state for peer
5100
Oct 20 13:19:46 DEBUG[8159] devicestate.c: Changing state for SIP/5100 -
state 2 (In use)
Oct 20 13:19:46 DEBUG[8159] chan_sip.c: Checking device state for peer
5100
Oct 20 13:19:46 DEBUG[10661] app_queue.c: Device 'Zap/25' changed to
state '0' (Unknown) but we don't care because they're not a member of
any queue.
Oct 20 13:19:46 DEBUG[10662] app_queue.c: Device 'SIP/5100' changed to
state '2' (In use) but we don't care because they're not a member of any
queue.
Oct 20 13:19:46 VERBOSE[8171] logger.c:
<-- SIP read from 172.16.8.200:5065:
ACK sip:5155 at 172.16.200.5 SIP/2.0
Via: SIP/2.0/UDP 172.16.8.200:5065;branch=z9hG4bKline0-2425957956
To: <sip:5155 at 172.16.200.5>;tag=as279eb184
From: "From Desk"<sip:5100 at 172.16.200.5>;tag=2425948795
Call-Id: 2425954456-c4756-5065 at 172.16.8.200
Max-Forwards: 70
CSeq: 2 ACK
Contact: sip:5100 at 172.16.8.200:5065
Content-Length: 0
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 0: ACK
sip:5155 at 172.16.200.5 SIP/2.0 (33)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 1: Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425957956 (65)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 2: To:
<sip:5155 at 172.16.200.5>;tag=as279eb184 (42)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 3: From: "From
Desk"<sip:5100 at 172.16.200.5>;tag=2425948795 (55)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 4: Call-Id:
2425954456-c4756-5065 at 172.16.8.200 (43)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 5: Max-Forwards: 70 (16)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 6: CSeq: 2 ACK (11)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 7: Contact:
sip:5100 at 172.16.8.200:5065 (35)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 8: Content-Length: 0 (17)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 9: (0)
Oct 20 13:19:46 VERBOSE[8171] logger.c: --- (9 headers 0 lines)Oct 20
13:19:46 VERBOSE[8171] logger.c: --- (9 headers 0 lines)---
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: **** Received ACK (6) - Command
in SIP ACK
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: ** SIP TIMER: Cancelling
retransmit of packet (reply received) Retransid #51636
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Stopping retransmission on
'2425954456-c4756-5065 at 172.16.8.200' of Response 2: Match Found
Oct 20 13:19:46 VERBOSE[8171] logger.c: Destroying call
'2425954456-c4756-5065 at 172.16.8.200'
Oct 20 13:19:46 VERBOSE[8171] logger.c:
<-- SIP read from 172.16.8.200:5065:
REFER sip:Unknown at 172.16.200.5 SIP/2.0
Via: SIP/2.0/UDP 172.16.8.200:5065;branch=z9hG4bKline0-2425953069
To: "Unknown" <sip:Unknown at 172.16.200.5>;tag=as25d7f97e
From: <sip:5100 at 172.16.8.200:5065>;tag=2425967614
Call-Id: 761da63b5eedcc6b125ad03042960be0 at 172.16.200.5
Max-Forwards: 70
CSeq: 2 REFER
Contact: sip:5100 at 172.16.8.200:5065
Refer-To:
Referred-By: sip:5100 at 172.16.8.200:5065
User-Agent: Citel-Handset-Gateway (DTS_E_DTP_32D)
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, NOTIFY, PRACK, REFER
Content-Length: 0
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 0: REFER
sip:Unknown at 172.16.200.5 SIP/2.0 (38)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 1: Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425953069 (65)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 2: To: "Unknown"
<sip:Unknown at 172.16.200.5>;tag=as25d7f97e (55)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 3: From:
<sip:5100 at 172.16.8.200:5065>;tag=2425967614 (49)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 4: Call-Id:
761da63b5eedcc6b125ad03042960be0 at 172.16.200.5 (54)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 5: Max-Forwards: 70 (16)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 6: CSeq: 2 REFER (13)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 7: Contact:
sip:5100 at 172.16.8.200:5065 (35)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 8: Refer-To: (10)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 9: Referred-By:
sip:5100 at 172.16.8.200:5065 (39)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 10: User-Agent:
Citel-Handset-Gateway (DTS_E_DTP_32D) (49)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 11: Allow: INVITE, ACK,
CANCEL, BYE, OPTIONS, NOTIFY, PRACK, REFER (62)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 12: Content-Length: 0
(17)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 13: (0)
Oct 20 13:19:46 VERBOSE[8171] logger.c: --- (13 headers 0 lines)Oct 20
13:19:46 VERBOSE[8171] logger.c: --- (13 headers 0 lines)---
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: **** Received REFER (9) -
Command in SIP REFER
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: SIP call transfer received for
call 761da63b5eedcc6b125ad03042960be0 at 172.16.200.5 (REFER)!
Oct 20 13:19:46 WARNING[8171] chan_sip.c: Refer-to: Huh? Not a SIP
header ()?
Oct 20 13:19:46 VERBOSE[8171] logger.c: Transmitting (no NAT) to
172.16.8.200:5065:
SIP/2.0 603 Declined
Via: SIP/2.0/UDP
172.16.8.200:5065;branch=z9hG4bKline0-2425953069;received=172.16.8.200
From: <sip:5100 at 172.16.8.200:5065>;tag=2425967614
To: "Unknown" <sip:Unknown at 172.16.200.5>;tag=as25d7f97e
Call-ID: 761da63b5eedcc6b125ad03042960be0 at 172.16.200.5
CSeq: 2 REFER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:Unknown at 172.16.200.5>
Content-Length: 0
X-Asterisk-HangupCause: Normal Clearing
_______________________________________________
--Bandwidth and Colocation provided by Easynews.com --
asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-users
More information about the asterisk-users
mailing list