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@TESCOGroup.com> wrote in
message
news:03C20CC487B2EF488E22EC586871ABBE02EBD0A3@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@172.16.200.5>;tag=2425948795
To: <sip:5155@172.16.200.5>;tag=as279eb184
Call-ID: 2425954456-c4756-5065@172.16.8.200
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:5155@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@172.16.200.5 SIP/2.0
Via: SIP/2.0/UDP 172.16.8.200:5065;branch=z9hG4bKline0-2425957956
To: <sip:5155@172.16.200.5>
From: "From Desk"<sip:5100@172.16.200.5>;tag=2425948795
Call-Id: 2425954456-c4756-5065@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@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@172.16.200.5> (27)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 3: From: "From
Desk"<sip:5100@172.16.200.5>;tag=2425948795 (55)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 4: Call-Id:
2425954456-c4756-5065@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@172.16.200.5>;tag=2425948795
To: <sip:5155@172.16.200.5>;tag=as279eb184
Call-ID: 2425954456-c4756-5065@172.16.8.200
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:5155@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@172.16.200.5>;tag=2425948795
To: <sip:5155@172.16.200.5>;tag=as279eb184
Call-ID: 2425954456-c4756-5065@172.16.8.200
CSeq: 2 CANCEL
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:5155@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@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@172.16.200.5 SIP/2.0
Via: SIP/2.0/UDP 172.16.8.200:5065;branch=z9hG4bKline0-2425957956
To: <sip:5155@172.16.200.5>;tag=as279eb184
From: "From Desk"<sip:5100@172.16.200.5>;tag=2425948795
Call-Id: 2425954456-c4756-5065@172.16.8.200
Max-Forwards: 70
CSeq: 2 ACK
Contact: sip:5100@172.16.8.200:5065
Content-Length: 0
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 0: ACK
sip:5155@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@172.16.200.5>;tag=as279eb184 (42)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 3: From: "From
Desk"<sip:5100@172.16.200.5>;tag=2425948795 (55)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 4: Call-Id:
2425954456-c4756-5065@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@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@172.16.8.200' of Response 2: Match Found
Oct 20 13:19:46 VERBOSE[8171] logger.c: Destroying call
'2425954456-c4756-5065@172.16.8.200'
Oct 20 13:19:46 VERBOSE[8171] logger.c:
<-- SIP read from 172.16.8.200:5065:
REFER sip:Unknown@172.16.200.5 SIP/2.0
Via: SIP/2.0/UDP 172.16.8.200:5065;branch=z9hG4bKline0-2425953069
To: "Unknown" <sip:Unknown@172.16.200.5>;tag=as25d7f97e
From: <sip:5100@172.16.8.200:5065>;tag=2425967614
Call-Id: 761da63b5eedcc6b125ad03042960be0@172.16.200.5
Max-Forwards: 70
CSeq: 2 REFER
Contact: sip:5100@172.16.8.200:5065
Refer-To:
Referred-By: sip:5100@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@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@172.16.200.5>;tag=as25d7f97e (55)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 3: From:
<sip:5100@172.16.8.200:5065>;tag=2425967614 (49)
Oct 20 13:19:46 DEBUG[8171] chan_sip.c: Header 4: Call-Id:
761da63b5eedcc6b125ad03042960be0@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@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@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@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@172.16.8.200:5065>;tag=2425967614
To: "Unknown" <sip:Unknown@172.16.200.5>;tag=as25d7f97e
Call-ID: 761da63b5eedcc6b125ad03042960be0@172.16.200.5
CSeq: 2 REFER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:Unknown@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