Re: [asterisk-users] FreePBX/Debian Aborts Call While Connecting
You're looking at only the logfiles, which don't reflect the problem at the other side, the switch which sees the incoming request abort before it can complete the connection, and before the 45s timeout. What you're missing is my reports of that difference on either side of the network, which I have mentioned in every message to this list, including the one you counted. In any event, the problem is some kind of protocol handling bug, either in the SIP server or the (SVN) version of Asterisk I'm using. I pointed at a different (newer) SIP server at my same carrier, and have no problem connecting. Though I was connecting OK to the old SIP server with my old Asterisk version (1.2.12) before the upgrade. I expect that both the old SIP server and the SVN Asterisk version have bugs which finally combine to abort improperly, and without proper failure reporting by Asterisk. Thanks anyway for trying to help. On Thu, 2007-02-01 at 22:59 -0500, Asterisk wrote: On Thu, 2007-02-01 at 08:47 -0500, Matthew Rubenstein wrote: The point is that the SIP carrier side gets the abort *before the SIP carrier can complete the connection*. That doesn't take 45s. It takes something like a few seconds. What is causing my (Asterisk) side to abort right after completing registration? On Thu, 2007-02-01 at 02:28 -0500, Asterisk wrote: Yeah, your waittime parameter in your call file is set to 45 seconds. db On Wed, 2007-01-31 at 21:52 -0500, Matthew Rubenstein wrote: I used the FreePBX on Debian HowTo at http://powerontech.com/freepbx-on-debian.htm to install. I use callfiles to initiate calls to my SIP carrier. They get my registration, but they see that my call is interrupted before they can complete the connection. My Asterisk log shows that the call times out after the time (45s) specified in my dialplan Dial() command. What is wrong? [from /var/log/asterisk/full]: [...] Alright, take a look the **Lines: **Line 1: Your dial sequence clearly shows the 45sec timeout value being applied as the second value in the dial plan SIP/[EMAIL PROTECTED]|45| -- Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Executing Dial(Local/[EMAIL PROTECTED],2, SIP/[EMAIL PROTECTED]|45| M(say-call-2-digits^17182335097)g) in new stack **Line 2: The timer has expired 45000ms is the same 45 second timer that was set for timeout Jan 30 23:42:15 VERBOSE[17269] logger.c: -- Nobody picked up in 45000 ms Line 3: The call is dropped towards the carrier. Maybe I am missing something here but it seems you are using a macro with some global variable set for a 45 second wait time for outbound calls. Thanks, Dave -- (C) Matthew Rubenstein ___ --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
Re: [asterisk-users] FreePBX/Debian Aborts Call While Connecting
The point is that the SIP carrier side gets the abort *before the SIP carrier can complete the connection*. That doesn't take 45s. It takes something like a few seconds. What is causing my (Asterisk) side to abort right after completing registration? On Thu, 2007-02-01 at 02:28 -0500, Asterisk wrote: Yeah, your waittime parameter in your call file is set to 45 seconds. db On Wed, 2007-01-31 at 21:52 -0500, Matthew Rubenstein wrote: I used the FreePBX on Debian HowTo at http://powerontech.com/freepbx-on-debian.htm to install. I use callfiles to initiate calls to my SIP carrier. They get my registration, but they see that my call is interrupted before they can complete the connection. My Asterisk log shows that the call times out after the time (45s) specified in my dialplan Dial() command. What is wrong? [from /var/log/asterisk/full]: [...] -- (C) Matthew Rubenstein ___ --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
Re: [asterisk-users] FreePBX/Debian Aborts Call While Connecting
On Thu, 2007-02-01 at 08:47 -0500, Matthew Rubenstein wrote: The point is that the SIP carrier side gets the abort *before the SIP carrier can complete the connection*. That doesn't take 45s. It takes something like a few seconds. What is causing my (Asterisk) side to abort right after completing registration? On Thu, 2007-02-01 at 02:28 -0500, Asterisk wrote: Yeah, your waittime parameter in your call file is set to 45 seconds. db On Wed, 2007-01-31 at 21:52 -0500, Matthew Rubenstein wrote: I used the FreePBX on Debian HowTo at http://powerontech.com/freepbx-on-debian.htm to install. I use callfiles to initiate calls to my SIP carrier. They get my registration, but they see that my call is interrupted before they can complete the connection. My Asterisk log shows that the call times out after the time (45s) specified in my dialplan Dial() command. What is wrong? [from /var/log/asterisk/full]: [...] Alright, take a look the **Lines: **Line 1: Your dial sequence clearly shows the 45sec timeout value being applied as the second value in the dial plan SIP/[EMAIL PROTECTED]|45| -- Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Executing Dial(Local/[EMAIL PROTECTED],2, SIP/[EMAIL PROTECTED]|45| M(say-call-2-digits^17182335097)g) in new stack **Line 2: The timer has expired 45000ms is the same 45 second timer that was set for timeout Jan 30 23:42:15 VERBOSE[17269] logger.c: -- Nobody picked up in 45000 ms Line 3: The call is dropped towards the carrier. Maybe I am missing something here but it seems you are using a macro with some global variable set for a 45 second wait time for outbound calls. Thanks, Dave ___ --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
[asterisk-users] FreePBX/Debian Aborts Call While Connecting
I used the FreePBX on Debian HowTo at
http://powerontech.com/freepbx-on-debian.htm to install. I use callfiles
to initiate calls to my SIP carrier. They get my registration, but they
see that my call is interrupted before they can complete the connection.
My Asterisk log shows that the call times out after the time (45s)
specified in my dialplan Dial() command. What is wrong?
[from /var/log/asterisk/full]:
Jan 30 23:40:35 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 102: Match
Found
Jan 30 23:40:44 DEBUG[6268] manager.c: Manager received command
'Command'
Jan 30 23:40:44 DEBUG[6268] manager.c: Manager received command
'Command'
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Scheduled a registration timeout
for 66.153.22.16 id #17818
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'[EMAIL PROTECTED]' Request 606: Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 606: Match
Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'[EMAIL PROTECTED]' Request 607: Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 607: Match
Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Registration successful
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Cancelling timeout 17818
Jan 30 23:41:16 DEBUG[6245] chan_sip.c: Auto destroying call
'[EMAIL PROTECTED]'
Jan 30 23:41:30 VERBOSE[17267] logger.c: -- Attempting call on
Local/[EMAIL PROTECTED]/n for [EMAIL PROTECTED]:1 (Retry 1)
Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Executing
NoOp(Local/[EMAIL PROTECTED],2, Calling
SIP/[EMAIL PROTECTED]) in new stack
Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Executing
Dial(Local/[EMAIL PROTECTED],2, SIP/[EMAIL PROTECTED]|45|
M(say-call-2-digits^17182335097)g) in new stack
Jan 30 23:41:30 DEBUG[17269] chan_sip.c: Setting NAT on RTP to 0
Jan 30 23:41:30 DEBUG[17269] chan_sip.c: Outgoing Call for 16467508273
Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Called
[EMAIL PROTECTED]
Jan 30 23:41:30 DEBUG[6245] chan_sip.c: Acked pending invite 102
Jan 30 23:41:30 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 102: Match
Found
Jan 30 23:41:30 DEBUG[6245] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'[EMAIL PROTECTED]' Request 103: Found
Jan 30 23:41:35 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 102: Match
Found
Jan 30 23:42:15 VERBOSE[17269] logger.c: -- Nobody picked up in
45000 ms
Jan 30 23:42:15 DEBUG[17269] chan_sip.c:
update_call_counter(16467508273) - decrement call limit counter
Jan 30 23:42:15 DEBUG[17269] chan_sip.c: Acked pending invite 103
Jan 30 23:42:15 DEBUG[17269] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 103: Match
Found
Jan 30 23:42:15 DEBUG[17269] app_dial.c: Exiting with
DIALSTATUS=NOANSWER.
Jan 30 23:42:15 VERBOSE[17269] logger.c: -- Executing
NoOp(Local/[EMAIL PROTECTED],2, Done dialing from) in new
stack
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-01-30
23:42:15','16467508273','16467508273','callTo','ext-jjp-out', 'Local/[EMAIL
PROTECTED],1','','Dial','Local/[EMAIL
PROTECTED]/n',0,0,'FAILED',3,'','1170196890.32')
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-01-30 23:42:15','','','s','default',
'**Unknown**','','','',0,0,'FAILED',3,'','1170196935.35')
Jan 30 23:42:15 NOTICE[17267] pbx_spool.c: Call failed to go through,
reason 0
Jan 30 23:42:15 DEBUG[17269] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Jan 30 23:42:15 DEBUG[17269] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-01-30
23:41:30','16467508273','16467508273','callFrom','ext-jjp-out', 'Local/[EMAIL
PROTECTED],2','SIP/tu3961-08196340','NoOp','Done dialing from',45,0,'NO
ANSWER',3,'','1170196890.33')
Jan 30 23:42:15 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 103: Match
Not Found
Jan 30 23:42:15 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 103: Match
Found
Jan 30 23:42:29 DEBUG[6245] chan_sip.c: Scheduled a registration timeout
for 66.153.22.16 id #17831
Jan 30
Re: [asterisk-users] FreePBX/Debian Aborts Call While Connecting
Yeah, your waittime parameter in your call file is set to 45 seconds.
db
On Wed, 2007-01-31 at 21:52 -0500, Matthew Rubenstein wrote:
I used the FreePBX on Debian HowTo at
http://powerontech.com/freepbx-on-debian.htm to install. I use callfiles
to initiate calls to my SIP carrier. They get my registration, but they
see that my call is interrupted before they can complete the connection.
My Asterisk log shows that the call times out after the time (45s)
specified in my dialplan Dial() command. What is wrong?
[from /var/log/asterisk/full]:
Jan 30 23:40:35 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 102: Match
Found
Jan 30 23:40:44 DEBUG[6268] manager.c: Manager received command
'Command'
Jan 30 23:40:44 DEBUG[6268] manager.c: Manager received command
'Command'
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Scheduled a registration timeout
for 66.153.22.16 id #17818
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'[EMAIL PROTECTED]' Request 606: Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 606: Match
Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'[EMAIL PROTECTED]' Request 607: Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 607: Match
Found
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Registration successful
Jan 30 23:40:44 DEBUG[6245] chan_sip.c: Cancelling timeout 17818
Jan 30 23:41:16 DEBUG[6245] chan_sip.c: Auto destroying call
'[EMAIL PROTECTED]'
Jan 30 23:41:30 VERBOSE[17267] logger.c: -- Attempting call on
Local/[EMAIL PROTECTED]/n for [EMAIL PROTECTED]:1 (Retry 1)
Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Executing
NoOp(Local/[EMAIL PROTECTED],2, Calling
SIP/[EMAIL PROTECTED]) in new stack
Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Executing
Dial(Local/[EMAIL PROTECTED],2, SIP/[EMAIL PROTECTED]|45|
M(say-call-2-digits^17182335097)g) in new stack
Jan 30 23:41:30 DEBUG[17269] chan_sip.c: Setting NAT on RTP to 0
Jan 30 23:41:30 DEBUG[17269] chan_sip.c: Outgoing Call for 16467508273
Jan 30 23:41:30 VERBOSE[17269] logger.c: -- Called
[EMAIL PROTECTED]
Jan 30 23:41:30 DEBUG[6245] chan_sip.c: Acked pending invite 102
Jan 30 23:41:30 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 102: Match
Found
Jan 30 23:41:30 DEBUG[6245] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'[EMAIL PROTECTED]' Request 103: Found
Jan 30 23:41:35 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 102: Match
Found
Jan 30 23:42:15 VERBOSE[17269] logger.c: -- Nobody picked up in
45000 ms
Jan 30 23:42:15 DEBUG[17269] chan_sip.c:
update_call_counter(16467508273) - decrement call limit counter
Jan 30 23:42:15 DEBUG[17269] chan_sip.c: Acked pending invite 103
Jan 30 23:42:15 DEBUG[17269] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 103: Match
Found
Jan 30 23:42:15 DEBUG[17269] app_dial.c: Exiting with
DIALSTATUS=NOANSWER.
Jan 30 23:42:15 VERBOSE[17269] logger.c: -- Executing
NoOp(Local/[EMAIL PROTECTED],2, Done dialing from) in new
stack
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-01-30
23:42:15','16467508273','16467508273','callTo','ext-jjp-out', 'Local/[EMAIL
PROTECTED],1','','Dial','Local/[EMAIL
PROTECTED]/n',0,0,'FAILED',3,'','1170196890.32')
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Jan 30 23:42:15 DEBUG[17267] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-01-30 23:42:15','','','s','default',
'**Unknown**','','','',0,0,'FAILED',3,'','1170196935.35')
Jan 30 23:42:15 NOTICE[17267] pbx_spool.c: Call failed to go through,
reason 0
Jan 30 23:42:15 DEBUG[17269] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Jan 30 23:42:15 DEBUG[17269] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-01-30
23:41:30','16467508273','16467508273','callFrom','ext-jjp-out', 'Local/[EMAIL
PROTECTED],2','SIP/tu3961-08196340','NoOp','Done dialing from',45,0,'NO
ANSWER',3,'','1170196890.33')
Jan 30 23:42:15 DEBUG[6245] chan_sip.c: Stopping retransmission on
'[EMAIL PROTECTED]' of Request 103: Match
Not
