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