Outgoing Calls Not Rolling Over To Multiple Trunk Sequence

My company is setting up an Asterisk system, and we have configured 4 SIP trunks (from Broadvoice) in the system. Using AMP interface, we configured an outgoing route to have a trunk sequence containing all 4 trunks, one after the other.

Nonetheless, outgoing calls on this route will not roll over to a second trunk, they only attempt calling out on the first trunk and stop there, with the message being that “all circuits are busy”. Any re-ordering of the sequence has made no difference.

Has anyone had this problem? Could it be a problem with Broadvoice? Is it that a configuration step is missing? is there something besides identifying the trunk sequence in an outgoing route that must be done for this to take effect?

Thanks - any help is appreciated.

–Nathan

this sounds wrong! i’ve had occasional problems with one of my 3 providers and rollover just works. can you post from your /var/log/asterisk/full the relevant entries when this happens?

This is the section of the log file (193 lines) from when 2 calls were taking place simultaneously, and only 1 went out while the other got a busy signal.

Thanks again for helping!

Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Setting NAT on RTP to 0
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘001319e0-ed7d000a-2b3b4458-7c3f3743@192.168.10.88’ of Response 101: Match Found
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Setting NAT on RTP to 0
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Checking SIP call limits for device 204
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: build_route: Contact hop: sip:204@192.168.10.88:5060
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing Macro(“SIP/204-ab05”, “dialout-trunk|1|15029925505|”) in new stack
Jan 31 14:57:32 DEBUG[8398] pbx.c: Expression result is '1’
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing GotoIf(“SIP/204-ab05”, “1?3:2)”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Goto (macro-dialout-trunk,s,3)
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing Macro(“SIP/204-ab05”, “user-callerid”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing DBget(“SIP/204-ab05”, “AMPUSER=DEVICE/204/user”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – DBget: varname=AMPUSER, family=DEVICE, key=204/user
Jan 31 14:57:32 VERBOSE[8398] logger.c: – DBget: set variable AMPUSER to 204
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing DBget(“SIP/204-ab05”, “AMPUSERCIDNAME=AMPUSER/204/cidname”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – DBget: varname=AMPUSERCIDNAME, family=AMPUSER, key=204/cidname
Jan 31 14:57:32 VERBOSE[8398] logger.c: – DBget: set variable AMPUSERCIDNAME to Jim Murphy
Jan 31 14:57:32 DEBUG[8398] pbx.c: Expression result is '0’
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing GotoIf(“SIP/204-ab05”, “0?5”) in new stack
Jan 31 14:57:32 DEBUG[8398] pbx.c: Not taking any branch
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing SetCallerID(“SIP/204-ab05”, ““Jim Murphy” <204>”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing NoOp(“SIP/204-ab05”, “Using CallerID “Jim Murphy” <204>”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing Macro(“SIP/204-ab05”, “record-enable|204|OUT”) in new stack
Jan 31 14:57:32 DEBUG[8398] pbx.c: Function result is ‘0’
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing GotoIf(“SIP/204-ab05”, “0 > 0?2:4”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Goto (macro-record-enable,s,4)
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing AGI(“SIP/204-ab05”, “recordingcheck|20060131-145732|1138737452.32”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jan 31 14:57:32 VERBOSE[8398] logger.c: recordingcheck|20060131-145732|1138737452.32: Outbound recording not enabled
Jan 31 14:57:32 VERBOSE[8398] logger.c: – AGI Script recordingcheck completed, returning 0
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing NoOp(“SIP/204-ab05”, “No recording needed”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing Macro(“SIP/204-ab05”, “outbound-callerid|1”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing DBget(“SIP/204-ab05”, “USEROUTCID=AMPUSER/204/outboundcid”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – DBget: varname=USEROUTCID, family=AMPUSER, key=204/outboundcid
Jan 31 14:57:32 VERBOSE[8398] logger.c: – DBget: set variable USEROUTCID to
Jan 31 14:57:32 DEBUG[8398] pbx.c: Expression result is ‘0’
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing GotoIf(“SIP/204-ab05”, “0?4”) in new stack
Jan 31 14:57:32 DEBUG[8398] pbx.c: Not taking any branch
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing SetCallerID(“SIP/204-ab05”, ““Pilgrim IT” <4138251999>”) in new stack
Jan 31 14:57:32 DEBUG[8398] pbx.c: Expression result is ‘1’
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing GotoIf(“SIP/204-ab05”, “1?6”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Goto (macro-outbound-callerid,s,6)
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing NoOp(“SIP/204-ab05”, “CallerID set to “Pilgrim IT” <4138251999>”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing SetGroup(“SIP/204-ab05”, “OUT_1”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing CheckGroup(“SIP/204-ab05”, “1”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing SetVar(“SIP/204-ab05”, “DIAL_NUMBER=15029925505”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing SetVar(“SIP/204-ab05”, “DIAL_TRUNK=1”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing AGI(“SIP/204-ab05”, “fixlocalprefix”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46573
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46575
Jan 31 14:57:32 VERBOSE[8398] logger.c: fixlocalprefix: Could not parse /etc/asterisk/localprefixes.conf
Jan 31 14:57:32 VERBOSE[8398] logger.c: – AGI Script fixlocalprefix completed, returning 0
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing SetVar(“SIP/204-ab05”, “OUTNUM=15029925505”) in new stack
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing Cut(“SIP/204-ab05”, “custom=OUT_1|:|1”) in new stack
Jan 31 14:57:32 WARNING[8398] ast_expr2.y: non-numeric argument
Jan 31 14:57:32 DEBUG[8398] pbx.c: Expression result is ‘0’
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing GotoIf(“SIP/204-ab05”, “0?16”) in new stack
Jan 31 14:57:32 DEBUG[8398] pbx.c: Not taking any branch
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Executing Dial(“SIP/204-ab05”, “SIP/4138251999/15029925505”) in new stack
Jan 31 14:57:32 DEBUG[8398] chan_sip.c: Setting NAT on RTP to 524288
Jan 31 14:57:32 DEBUG[8398] chan_sip.c: Outgoing Call for 15029925505
Jan 31 14:57:32 VERBOSE[8398] logger.c: – Called 4138251999/15029925505
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘760c02fd036846c50747bc98617e22e3@127.0.0.1’ of Request 1886: Match Found
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Cancelling timeout 46573
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘5eb3908f4e91d6cb02647e366b721fe6@127.0.0.1’ of Request 1886: Match Found
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Cancelling timeout 46575
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '36ebdaa05609c5e523f5724c757f02e7@sip.broadvoice.com’ Request 102: Found
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Acked pending invite 102
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: Stopping retransmission on '36ebdaa05609c5e523f5724c757f02e7@sip.broadvoice.com’ of Request 102: Match Found
Jan 31 14:57:32 DEBUG[2718] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '36ebdaa05609c5e523f5724c757f02e7@sip.broadvoice.com’ Request 103: Found
Jan 31 14:57:36 DEBUG[2718] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '36ebdaa05609c5e523f5724c757f02e7@sip.broadvoice.com’ Request 103: Found
Jan 31 14:57:36 VERBOSE[8398] logger.c: – SIP/4138251999-aa2d is making progress passing it to SIP/204-ab05
Jan 31 14:57:36 DEBUG[2718] chan_sip.c: Setting NAT on RTP to 0
Jan 31 14:57:36 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘001319d1-fc5a0075-3764f681-4fc08579@192.168.10.87’ of Response 101: Match Found
Jan 31 14:57:36 DEBUG[2718] chan_sip.c: Setting NAT on RTP to 0
Jan 31 14:57:36 DEBUG[2718] chan_sip.c: Checking SIP call limits for device 201
Jan 31 14:57:36 DEBUG[2718] chan_sip.c: build_route: Contact hop: sip:201@192.168.10.87:5060
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing Macro(“SIP/201-c840”, “dialout-trunk|1|14132107984|”) in new stack
Jan 31 14:57:36 DEBUG[8402] pbx.c: Expression result is '1’
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing GotoIf(“SIP/201-c840”, “1?3:2)”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Goto (macro-dialout-trunk,s,3)
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing Macro(“SIP/201-c840”, “user-callerid”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing DBget(“SIP/201-c840”, “AMPUSER=DEVICE/201/user”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – DBget: varname=AMPUSER, family=DEVICE, key=201/user
Jan 31 14:57:36 VERBOSE[8402] logger.c: – DBget: set variable AMPUSER to 201
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing DBget(“SIP/201-c840”, “AMPUSERCIDNAME=AMPUSER/201/cidname”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – DBget: varname=AMPUSERCIDNAME, family=AMPUSER, key=201/cidname
Jan 31 14:57:36 VERBOSE[8402] logger.c: – DBget: set variable AMPUSERCIDNAME to Nathan Mealey
Jan 31 14:57:36 DEBUG[8402] pbx.c: Expression result is ‘0’
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing GotoIf(“SIP/201-c840”, “0?5”) in new stack
Jan 31 14:57:36 DEBUG[8402] pbx.c: Not taking any branch
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing SetCallerID(“SIP/201-c840”, ““Nathan Mealey” <201>”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing NoOp(“SIP/201-c840”, “Using CallerID “Nathan Mealey” <201>”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing Macro(“SIP/201-c840”, “record-enable|201|OUT”) in new stack
Jan 31 14:57:36 DEBUG[8402] pbx.c: Function result is ‘0’
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing GotoIf(“SIP/201-c840”, “0 > 0?2:4”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Goto (macro-record-enable,s,4)
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing AGI(“SIP/201-c840”, “recordingcheck|20060131-145736|1138737456.34”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jan 31 14:57:36 VERBOSE[8402] logger.c: recordingcheck|20060131-145736|1138737456.34: Outbound recording not enabled
Jan 31 14:57:36 VERBOSE[8402] logger.c: – AGI Script recordingcheck completed, returning 0
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing NoOp(“SIP/201-c840”, “No recording needed”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing Macro(“SIP/201-c840”, “outbound-callerid|1”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing DBget(“SIP/201-c840”, “USEROUTCID=AMPUSER/201/outboundcid”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – DBget: varname=USEROUTCID, family=AMPUSER, key=201/outboundcid
Jan 31 14:57:36 VERBOSE[8402] logger.c: – DBget: set variable USEROUTCID to
Jan 31 14:57:36 DEBUG[8402] pbx.c: Expression result is ‘0’
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing GotoIf(“SIP/201-c840”, “0?4”) in new stack
Jan 31 14:57:36 DEBUG[8402] pbx.c: Not taking any branch
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing SetCallerID(“SIP/201-c840”, ““Pilgrim IT” <4138251999>”) in new stack
Jan 31 14:57:36 DEBUG[8402] pbx.c: Expression result is ‘1’
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing GotoIf(“SIP/201-c840”, “1?6”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Goto (macro-outbound-callerid,s,6)
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing NoOp(“SIP/201-c840”, “CallerID set to “Pilgrim IT” <4138251999>”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing SetGroup(“SIP/201-c840”, “OUT_1”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing CheckGroup(“SIP/201-c840”, “1”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: == Spawn extension (macro-dialout-trunk, s, 107) exited non-zero on ‘SIP/201-c840’ in macro ‘dialout-trunk’
Jan 31 14:57:36 VERBOSE[8402] logger.c: == Spawn extension (from-internal, 914132107984, 1) exited non-zero on ‘SIP/201-c840’
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing Macro(“SIP/201-c840”, “hangupcall”) in new stack
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing ResetCDR(“SIP/201-c840”, “w”) in new stack
Jan 31 14:57:36 DEBUG[8402] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jan 31 14:57:36 DEBUG[8402] 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 (‘2006-01-31 14:57:36’,’“Pilgrim IT” <4138251999>’,‘4138251999’,‘914132107984’,‘from-internal’, ‘SIP/201-c840’,’’,‘ResetCDR’,‘w’,0,0,‘NO ANSWER’,3,’’,‘1138737456.34’)
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing NoCDR(“SIP/201-c840”, “”) in new stack
Jan 31 14:57:36 WARNING[8402] cdr.c: CDR on channel ‘SIP/201-c840’ not posted
Jan 31 14:57:36 WARNING[8402] cdr.c: CDR on channel ‘SIP/201-c840’ lacks end
Jan 31 14:57:36 VERBOSE[8402] logger.c: – Executing Wait(“SIP/201-c840”, “5”) in new stack
Jan 31 14:57:38 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46586
Jan 31 14:57:38 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘451b85e632bef5a2165588486e18c064@127.0.0.1’ of Request 1886: Match Found
Jan 31 14:57:38 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:57:38 DEBUG[2718] chan_sip.c: Cancelling timeout 46586
Jan 31 14:57:40 DEBUG[2718] chan_sip.c: Auto destroying call '760c02fd036846c50747bc98617e22e3@127.0.0.1’
Jan 31 14:57:40 DEBUG[2718] chan_sip.c: Auto destroying call '5eb3908f4e91d6cb02647e366b721fe6@127.0.0.1’
Jan 31 14:57:42 VERBOSE[8402] logger.c: – Executing Hangup(“SIP/201-c840”, “”) in new stack
Jan 31 14:57:42 VERBOSE[8402] logger.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/201-c840’ in macro ‘hangupcall’
Jan 31 14:57:42 VERBOSE[8402] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/201-c840’
Jan 31 14:57:42 DEBUG[8402] chan_sip.c: update_call_counter(201) - decrement call limit counter
Jan 31 14:57:42 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘001319d1-fc5a0075-3764f681-4fc08579@192.168.10.87’ of Response 102: Match Found
Jan 31 14:57:46 DEBUG[2718] chan_sip.c: Auto destroying call ‘451b85e632bef5a2165588486e18c064@127.0.0.1’
Jan 31 14:57:47 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46591
Jan 31 14:57:48 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘60c36d9f39486f404284f93a0358dbf2@127.0.0.1’ of Request 1886: Match Found
Jan 31 14:57:48 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:57:48 DEBUG[2718] chan_sip.c: Cancelling timeout 46591
Jan 31 14:57:48 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘6e55e0b05531197b75cf9b3a075ad209@192.168.10.100’ of Request 102: Match Found
Jan 31 14:57:51 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘5da268de7ef2326c303c084c06bcb351@192.168.10.100’ of Request 102: Match Found
Jan 31 14:57:51 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘52b5e7844ed65f954db5b34c41e8e015@192.168.10.100’ of Request 102: Match Found
Jan 31 14:57:54 DEBUG[2718] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '36ebdaa05609c5e523f5724c757f02e7@sip.broadvoice.com’ Request 103: Found
Jan 31 14:57:54 VERBOSE[8398] logger.c: – SIP/4138251999-aa2d is ringing
Jan 31 14:57:54 VERBOSE[8398] logger.c: – SIP/4138251999-aa2d is making progress passing it to SIP/204-ab05
Jan 31 14:57:55 DEBUG[2718] chan_sip.c: Auto destroying call ‘60c36d9f39486f404284f93a0358dbf2@127.0.0.1’
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46604
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46606
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘760c02fd036846c50747bc98617e22e3@127.0.0.1’ of Request 1887: Match Found
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Cancelling timeout 46604
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘5eb3908f4e91d6cb02647e366b721fe6@127.0.0.1’ of Request 1887: Match Found
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:57:56 DEBUG[2718] chan_sip.c: Cancelling timeout 46606
Jan 31 14:57:57 DEBUG[2718] chan_sip.c: Acked pending invite 103
Jan 31 14:57:57 DEBUG[2718] chan_sip.c: Stopping retransmission on '36ebdaa05609c5e523f5724c757f02e7@sip.broadvoice.com’ of Request 103: Match Found
Jan 31 14:57:57 DEBUG[2718] chan_sip.c: build_route: Contact hop: sip:15029925505@147.135.2.128
Jan 31 14:57:57 VERBOSE[8398] logger.c: – SIP/4138251999-aa2d answered SIP/204-ab05
Jan 31 14:57:57 VERBOSE[8398] logger.c: – Attempting native bridge of SIP/204-ab05 and SIP/4138251999-aa2d
Jan 31 14:57:57 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘001319e0-ed7d000a-2b3b4458-7c3f3743@192.168.10.88’ of Response 102: Match Found
Jan 31 14:57:59 DEBUG[8398] channel.c: Didn’t get a frame from channel: SIP/4138251999-aa2d
Jan 31 14:57:59 DEBUG[8398] channel.c: Bridge stops bridging channels SIP/204-ab05 and SIP/4138251999-aa2d
Jan 31 14:57:59 DEBUG[8398] chan_sip.c: update_call_counter(15029925505) - decrement call limit counter
Jan 31 14:57:59 DEBUG[8398] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jan 31 14:57:59 VERBOSE[8398] logger.c: == Spawn extension (macro-dialout-trunk, s, 14) exited non-zero on ‘SIP/204-ab05’ in macro ‘dialout-trunk’
Jan 31 14:57:59 VERBOSE[8398] logger.c: == Spawn extension (from-internal, 915029925505, 1) exited non-zero on ‘SIP/204-ab05’
Jan 31 14:57:59 VERBOSE[8398] logger.c: – Executing Macro(“SIP/204-ab05”, “hangupcall”) in new stack
Jan 31 14:57:59 VERBOSE[8398] logger.c: – Executing ResetCDR(“SIP/204-ab05”, “w”) in new stack
Jan 31 14:57:59 DEBUG[8398] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jan 31 14:57:59 DEBUG[8398] 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 (‘2006-01-31 14:57:32’,’“Pilgrim IT” <4138251999>’,‘4138251999’,‘915029925505’,‘from-internal’, ‘SIP/204-ab05’,‘SIP/4138251999-aa2d’,‘ResetCDR’,‘w’,27,2,‘ANSWERED’,3,’’,‘1138737452.32’)
Jan 31 14:57:59 VERBOSE[8398] logger.c: – Executing NoCDR(“SIP/204-ab05”, “”) in new stack
Jan 31 14:57:59 WARNING[8398] cdr.c: CDR on channel ‘SIP/204-ab05’ not posted
Jan 31 14:57:59 WARNING[8398] cdr.c: CDR on channel ‘SIP/204-ab05’ lacks end
Jan 31 14:57:59 VERBOSE[8398] logger.c: – Executing Wait(“SIP/204-ab05”, “5”) in new stack
Jan 31 14:58:00 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘1240df697c73a47f382ee0d5779f0edf@192.168.10.100’ of Request 102: Match Found
Jan 31 14:58:02 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘1704103d2478acc2763271e3690f07f4@192.168.10.100’ of Request 102: Match Found
Jan 31 14:58:02 DEBUG[2718] chan_sip.c: Scheduled a registration timeout for sip.broadvoice.com id #46621
Jan 31 14:58:03 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘451b85e632bef5a2165588486e18c064@127.0.0.1’ of Request 1887: Match Found
Jan 31 14:58:03 DEBUG[2718] chan_sip.c: Registration successful
Jan 31 14:58:03 DEBUG[2718] chan_sip.c: Cancelling timeout 46621
Jan 31 14:58:04 VERBOSE[8398] logger.c: – Executing Hangup(“SIP/204-ab05”, “”) in new stack
Jan 31 14:58:04 VERBOSE[8398] logger.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/204-ab05’ in macro 'hangupcall’
Jan 31 14:58:04 VERBOSE[8398] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/204-ab05’
Jan 31 14:58:04 DEBUG[8398] chan_sip.c: update_call_counter(204) - decrement call limit counter
Jan 31 14:58:04 DEBUG[2718] chan_sip.c: Stopping retransmission on ‘001319e0-ed7d000a-2b3b4458-7c3f3743@192.168.10.88’ of Request 102: Match Found
Jan 31 14:58:04 DEBUG[2718] chan_sip.c: Auto destroying call '760c02fd036846c50747bc98617e22e3@127.0.0.1’
Jan 31 14:58:04 DEBUG[2718] chan_sip.c: Auto destroying call '5eb3908f4e91d6cb02647e366b721fe6@127.0.0.1’
Jan 31 14:58:10 DEBUG[2718] chan_sip.c: Auto destroying call ‘451b85e632bef5a2165588486e18c064@127.0.0.1’

Hmmm, well, to be honest, I thought the rollover code was for if you couldn’t connect to make the call at all (e.g. i’ve gotten a provider messed up, so the dialout code would go to the next one.) Dunno if that works that way for a call limit error. It seems BV only allows one call at a time (not unusual for an “all you can eat” provider.) Have to set the call limit to 1 in the BV trunk?