asterisk users - May 2005 - FAST BUSY on Back to back ZAP outgoing calls

Hello, I have a TDM400P with 2x2 configuration of FXOs and FXSs.  I set
a test extension of '444' to dial out a specific zap trunk and call a
local #.  First time I call out to '444' everything works fine.  If I
hang up the call, and within 10 seconds dial the same number again, I
get a fast busy.  Seems it isn't letting go of the trunk or something,
and I don't have a butt-set to listen in on it while its doing what it
does.  I'm dialing from a standard US pots line with no call waiting,
call forwarding, or caller ID.  Bare-bones.   Here is the
extensions.conf and Zapata.conf section, as well as the relevant error
lines:

 

Extensions.conf

exten => 444,1,Dial(Zap/4/6718688)

exten => 444,2,Hangup

 

Zapata.conf

context=pstn7469

echocancel=no

signalling=fxs_ks

channel => 4

 

Error Log

2005-05-25 17:37:00 DEBUG[2691]: Call from user '102' is 2 out of 0

2005-05-25 17:37:00 DEBUG[2691]: build_route: Contact hop:
<sip:102@192.168.0.233>

2005-05-25 17:37:00 DEBUG[2691]: Dialing '6718688'

2005-05-25 17:37:00 DEBUG[2691]: Deferring dialing...

2005-05-25 17:37:00 DEBUG[2691]: cdr_mysql: inserting a CDR record.

2005-05-25 17:37:00 DEBUG[2691]: cdr_mysql: SQL command as follows:
INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,dura
tion,billsec,disposition,amaflags,accountcode,userfield) VALUES
('2005-05-25 17:36:45','Living Room
<102>','102','777','default',
'SIP/102-bbbc','','MP3Player','http://64.236.34.196:80/stream/2004',15,1
5,'ANSWERED',3,'3607330988','')

2005-05-25 17:37:00 DEBUG[2691]: update_user_counter(102) - decrement
inUse counter

2005-05-25 17:37:01 DEBUG[2691]: Exception on 22, channel 4

2005-05-25 17:37:01 DEBUG[2691]: Got event Hook Transition Complete(12)
on channel 4 (index 0)

2005-05-25 17:37:02 DEBUG[2691]: Exception on 22, channel 4

2005-05-25 17:37:02 DEBUG[2691]: Got event Dial Complete(9) on channel 4
(index 0)

2005-05-25 17:37:02 DEBUG[2691]: Enabled echo cancellation on channel 4

2005-05-25 17:37:02 DEBUG[2691]: Engaged echo training on channel 4

2005-05-25 17:37:04 DEBUG[2691]: Exception on 22, channel 4

2005-05-25 17:37:04 DEBUG[2691]: Got event Dial Complete(9) on channel 4
(index 0)

2005-05-25 17:37:04 DEBUG[2691]: Echo cancellation already on

2005-05-25 17:37:04 DEBUG[2691]: Done dialing, but waiting for progress
detection before doing more...

2005-05-25 17:37:04 DEBUG[2691]: Ooh, format changed from unknown to
ulaw

2005-05-25 17:37:04 DEBUG[2691]: Driver for channel 'SIP/102-996b' does
not support indication 3, emulating it

2005-05-25 17:37:04 DEBUG[2691]: Prodding channel 'SIP/102-996b'

2005-05-25 17:37:04 DEBUG[2691]: Scheduling timer at 160 sample
intervals

2005-05-25 17:37:04 DEBUG[2691]: Scheduling timer at 0 sample intervals

2005-05-25 17:37:31 DEBUG[2691]: Hangup: channel: 4 index = 0, normal 22,
callwait = -1, thirdcall = -1

2005-05-25 17:37:31 DEBUG[2691]: disabled echo cancellation on channel 4

2005-05-25 17:37:31 DEBUG[2691]: Set option TDD MODE, value: OFF(0) on
Zap/4-1

2005-05-25 17:37:31 DEBUG[2691]: Updated conferencing on 4, with 0
conference users

2005-05-25 17:37:31 DEBUG[2691]: Exiting with DIALSTATUS=CANCEL.

2005-05-25 17:37:31 DEBUG[2691]: cdr_mysql: inserting a CDR record.

2005-05-25 17:37:31 DEBUG[2691]: cdr_mysql: SQL command as follows:
INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,dura
tion,billsec,disposition,amaflags,accountcode,userfield) VALUES
('2005-05-25 17:37:00','Living Room
<102>','102','444','default',
'SIP/102-996b','Zap/4-1','Dial','Zap/4/6718688',31,0,'NO
ANSWER',3,'360XXXXXXX','')

2005-05-25 17:37:31 DEBUG[2691]: update_user_counter(102) - decrement
inUse counter

2005-05-25 17:37:31 DEBUG[2691]: Stopping retransmission on
'a8b3ba01-a2c44413-b247e918@192.168.0.233' of Response 2: Found

2005-05-25 17:37:35 DEBUG[2691]: Sending VNAK

 

2005-05-25 17:38:51 DEBUG[2691]: Setting NAT on RTP to 0

2005-05-25 17:38:52 DEBUG[2691]: Stopping retransmission on
'e1975a9f-33d44ea1-5dab1bbe@192.168.0.233' of Response 1: Found

2005-05-25 17:38:52 DEBUG[2691]: Setting NAT on RTP to 0

2005-05-25 17:38:52 DEBUG[2691]: Check for res for 102

2005-05-25 17:38:52 DEBUG[2691]: Call from user '102' is 1 out of 0

2005-05-25 17:38:52 DEBUG[2691]: build_route: Contact hop:
<sip:102@192.168.0.233>

2005-05-25 17:38:52 DEBUG[2691]: Dialing '6718688'

2005-05-25 17:38:52 DEBUG[2691]: Deferring dialing...

2005-05-25 17:38:52 DEBUG[2691]: Exception on 22, channel 4

2005-05-25 17:38:52 DEBUG[2691]: Got event Hook Transition Complete(12)
on channel 4 (index 0)

2005-05-25 17:38:54 DEBUG[2691]: Exception on 22, channel 4

2005-05-25 17:38:54 DEBUG[2691]: Got event Dial Complete(9) on channel 4
(index 0)

2005-05-25 17:38:54 DEBUG[2691]: Enabled echo cancellation on channel 4

2005-05-25 17:38:54 DEBUG[2691]: Engaged echo training on channel 4

2005-05-25 17:38:55 DEBUG[2691]: Exception on 22, channel 4

2005-05-25 17:38:55 DEBUG[2691]: Got event Dial Complete(9) on channel 4
(index 0)

2005-05-25 17:38:55 DEBUG[2691]: Echo cancellation already on

2005-05-25 17:38:55 DEBUG[2691]: Done dialing, but waiting for progress
detection before doing more...

2005-05-25 17:38:55 DEBUG[2691]: Ooh, format changed from unknown to
ulaw

2005-05-25 17:38:55 DEBUG[2691]: Hangup: channel: 4 index = 0, normal 22,
callwait = -1, thirdcall = -1

2005-05-25 17:38:55 DEBUG[2691]: disabled echo cancellation on channel 4

2005-05-25 17:38:55 DEBUG[2691]: Set option TDD MODE, value: OFF(0) on
Zap/4-1

2005-05-25 17:38:55 DEBUG[2691]: Updated conferencing on 4, with 0
conference users

2005-05-25 17:38:55 DEBUG[2691]: Exiting with DIALSTATUS=BUSY.

2005-05-25 17:38:55 DEBUG[2691]: cdr_mysql: inserting a CDR record.

2005-05-25 17:38:55 DEBUG[2691]: cdr_mysql: SQL command as follows:
INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,dura
tion,billsec,disposition,amaflags,accountcode,userfield) VALUES
('2005-05-25 17:38:52','Living Room
<102>','102','444','default',
'SIP/102-5b2c','Zap/4-1','Hangup','',3,0,'BUSY',3,'360XXXXXXX','')

2005-05-25 17:38:55 DEBUG[2691]: update_user_counter(102) - decrement
inUse counter

2005-05-25 17:38:55 DEBUG[2691]: Stopping retransmission on
'e1975a9f-33d44ea1-5dab1bbe@192.168.0.233' of Response 2: Found

Chris Coulthurst

chris@shuksan.com

 



Chris Coulthurst
chris@shuksan.com