3 Rings Before IVR

Hello All,

I hope you are doing great.

I have installed 8 Ports FXO Analog POTS card Original Asterisk Card (Wildcard A8A).
Everything is working perfect except,
when a caller calls to the analog line, he gets 3 rings and then call is received by the IVR. This happens on 1 port. On the other port, only 1 ring and the call is received by IVR.

I have set Answer Immediately = Yes in the global settings - but that doesnt help.
Is it possible that the call get received immediately by the IVR?

Many Thanks,

Regards,

Check again, please. I think it’s 2 rings.
Caller ID is transmitted between the 1st and 2nd ring so asterisk should ring after the 1st ring.

It varies, sometimes its 2 rings, sometimes its 3.
But on one line, IVR is heard after 1 ring.

Do you mean that its not the issue of the server ?
Am i thinking correct that, because the caller ID is not transmitted to asterisk that is why Asterisk waits for it and as soon as it receives, it will start IVR ?

Regards

I had something like this a while ago, and another member suggested checking if fax detection was turned on and it was on one of the channels.

I have disabled Fax Detection = no in global settings.

Any other place to turn it off ?

Open the asterisk CLI and call your box. If you see that the call gets in asterisk and waits for some reason then it is a diaplan issue and easy to fix. If you see nothing then it is the dadhi driver that you have to configure. Maybe this specific line needs polarity reversal enabled. As sali mentioned cid data is passed between the first two rings. I don’t thing it is such a big issue.

Thank you for your reply. I will check this tonight.

Yes you are right, if it remains 2 rings and then IVR, than its not an issue at all.

Good find, astbox. Thanks for the info.

I have checked through the Asterisk CLI.

Everything else is the same, except there are 2 differences.

  1. The line which get 3 rings before ivr, it doesnt get the caller ID, while the other one gets the caller ID.
    Executing [[email protected]:4] ExecIf(“DAHDI/8-1”, “1 ?Set(CALLERID(name)=XXXXXXXXXX)”) in new stack

  2. This following line also appears.

[2017-06-11 18:16:59] WARNING[15832][C-00000366]: sig_analog.c:3100 __analog_handle_event: Ring/Off-hook in strange state 6 on channel 7

Connect to asterisk cli with the following command

asterisk -rvvvd

make a new call and post here what you get.

Hi,
many thanks for your reply.
Please check the following log

localhost*CLI>
[2017-06-12 23:31:16] DEBUG[20340]: chan_dahdi.c:12625 do_monitor: Monitor doohicky got event Ring Begin on channel 7
[2017-06-12 23:31:16] DEBUG[20340]: sig_analog.c:3694 analog_handle_init_event: channel (7) - signaling (5) - event (ANALOG_EVENT_RINGBEGIN)
[2017-06-12 23:31:17] DEBUG[2402]: chan_sip.c:8679 sip_alloc: Allocating new SIP dialog for [email protected][::1]:5060 - OPTIONS (No RTP)
[2017-06-12 23:31:17] DEBUG[2402]: chan_sip.c:8465 change_callid_pvt: SIP call-id changed from ‘[email protected][::1]:5060’ to ‘[email protected]:5060’
[2017-06-12 23:31:17] DEBUG[2402]: chan_sip.c:3374 initialize_initreq: Initializing initreq for method OPTIONS - callid [email protected]:5060
[2017-06-12 23:31:17] DEBUG[2402]: chan_sip.c:4429 __sip_ack: Stopping retransmission on ‘[email protected]:5060’ of Request 102: Match Found
[2017-06-12 23:31:17] DEBUG[20340]: chan_dahdi.c:12625 do_monitor: Monitor doohicky got event Ring/Answered on channel 7
[2017-06-12 23:31:17] DEBUG[20340]: sig_analog.c:3694 analog_handle_init_event: channel (7) - signaling (5) - event (ANALOG_EVENT_RINGOFFHOOK)
[2017-06-12 23:31:17] DEBUG[20340][C-000003c9]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2017-06-12 23:31:17] DEBUG[20340][C-000003c9]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2017-06-12 23:31:17] DEBUG[2471]: sig_analog.c:1766 __analog_ss_thread: __analog_ss_thread 7
– Starting simple switch on ‘DAHDI/7-1’
[2017-06-12 23:31:21] DEBUG[2402]: chan_sip.c:8679 sip_alloc: Allocating new SIP dialog for [email protected][::1]:5060 - OPTIONS (No RTP)
[2017-06-12 23:31:21] DEBUG[2402]: chan_sip.c:8465 change_callid_pvt: SIP call-id changed from ‘[email protected][::1]:5060’ to ‘[email protected]:5060’
[2017-06-12 23:31:21] DEBUG[2402]: chan_sip.c:3374 initialize_initreq: Initializing initreq for method OPTIONS - callid [email protected]:5060
[2017-06-12 23:31:21] DEBUG[2402]: chan_sip.c:4429 __sip_ack: Stopping retransmission on ‘[email protected]:5060’ of Request 102: Match Found
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘NoOp’
– Executing [[email protected]:1] NoOp(“DAHDI/7-1”, "Entering from-dahdi with DID == ") in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Ringing’
– Executing [[email protected]:2] Ringing(“DAHDI/7-1”, “”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: chan_dahdi.c:10047 dahdi_indicate: Requested indication 3 on channel DAHDI/7-1
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:3] Set(“DAHDI/7-1”, “DID=s”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘NoOp’
– Executing [[email protected]:4] NoOp(“DAHDI/7-1”, “DID is now s”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘GotoIf’
– Executing [[email protected]:5] GotoIf(“DAHDI/7-1”, “1?dahdiok:checkzap”) in new stack
– Goto (from-analog,s,9)
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘NoOp’
– Executing [[email protected]:9] NoOp(“DAHDI/7-1”, “Is a DAHDi Channel”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:10] Set(“DAHDI/7-1”, “CHAN=7-1”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:11] Set(“DAHDI/7-1”, “CHAN=7”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Macro’
– Executing [[email protected]:12] Macro(“DAHDI/7-1”, “from-dahdi-7,s,1”) in new stack
[2017-06-12 23:31:27] WARNING[2471][C-000003c9]: app_macro.c:309 _macro_exec: No such context ‘macro-from-dahdi-7’ for macro ‘from-dahdi-7’. Was called by [email protected]
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘NoOp’
– Executing [[email protected]:13] NoOp(“DAHDI/7-1”, “Returned from Macro from-dahdi-7”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Goto’
– Executing [[email protected]:14] Goto(“DAHDI/7-1”, “from-pstn,s,1”) in new stack
– Goto (from-pstn,s,1)
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘ExecIf’
– Executing [[email protected]:1] ExecIf(“DAHDI/7-1”, “1?Set(__FROM_DID=s)”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Gosub’
– Executing [[email protected]:2] Gosub(“DAHDI/7-1”, “app-blacklist-check,s,1()”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: app_stack.c:579 gosub_exec: Channel DAHDI/7-1 has no datastore, so we’re allocating one.
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: db.c:376 db_get_common: Unable to find key ‘’ in family ‘blacklist’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: db.c:376 db_get_common: Unable to find key ‘’ in family ‘blacklist’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘GotoIf’
– Executing [[email protected]:1] GotoIf(“DAHDI/7-1”, “0?blacklisted”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:12181 pbx_builtin_gotoif: Not taking any branch
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:2] Set(“DAHDI/7-1”, “CALLED_BLACKLIST=1”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Return’
– Executing [[email protected]:3] Return(“DAHDI/7-1”, “”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:3] Set(“DAHDI/7-1”, “CDR(did)=s”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘ExecIf’
– Executing [[email protected]:4] ExecIf(“DAHDI/7-1”, “1 ?Set(CALLERID(name)=)”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:5] Set(“DAHDI/7-1”, “CHANNEL(musicclass)=default”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:6] Set(“DAHDI/7-1”, “__MOHCLASS=default”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:7] Set(“DAHDI/7-1”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:8] Set(“DAHDI/7-1”, “CALLERPRES()=allowed_not_screened”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Goto’
– Executing [[email protected]:9] Goto(“DAHDI/7-1”, “ivr-4,s,1”) in new stack
– Goto (ivr-4,s,1)
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:1] Set(“DAHDI/7-1”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:2] Set(“DAHDI/7-1”, “INVALID_LOOPCOUNT=0”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:3] Set(“DAHDI/7-1”, “_IVR_CONTEXT_ivr-4=”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:4] Set(“DAHDI/7-1”, “_IVR_CONTEXT=ivr-4”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:5] Set(“DAHDI/7-1”, “__IVR_RETVM=”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘GotoIf’
– Executing [[email protected]:6] GotoIf(“DAHDI/7-1”, “0?skip”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:12181 pbx_builtin_gotoif: Not taking any branch
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Answer’
– Executing [[email protected]:7] Answer(“DAHDI/7-1”, “”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: sig_analog.c:1497 analog_answer: analog_answer 7
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: sig_analog.c:1528 analog_answer: Took DAHDI/7-1 off hook
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: chan_dahdi.c:5379 dahdi_enable_ec: Enabled echo cancellation on channel 7
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: chan_dahdi.c:5398 dahdi_train_ec: No echo training requested
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: chan_dahdi.c:10047 dahdi_indicate: Requested indication -1 on channel DAHDI/7-1
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Wait’
– Executing [[email protected]:8] Wait(“DAHDI/7-1”, “1”) in new stack
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: channel.c:5416 set_format: Set channel DAHDI/7-1 to write format slin
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: channel.c:3597 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2017-06-12 23:31:27] DEBUG[2471][C-000003c9]: channel.c:8846 ast_channel_start_silence_generator: Started silence generator on ‘DAHDI/7-1’
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: channel.c:3597 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: channel.c:8881 ast_channel_stop_silence_generator: Stopped silence generator on ‘DAHDI/7-1’
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: channel.c:5416 set_format: Set channel DAHDI/7-1 to write format ulaw
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:9] Set(“DAHDI/7-1”, “IVR_MSG=custom/Main_Welcome2”) in new stack
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Set’
– Executing [[email protected]:10] Set(“DAHDI/7-1”, “TIMEOUT(digit)=3”) in new stack
– Digit timeout set to 3.000
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: pbx.c:4905 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘ExecIf’
– Executing [[email protected]:11] ExecIf(“DAHDI/7-1”, “1?Background(custom/Main_Welcome2)”) in new stack
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: channel.c:5416 set_format: Set channel DAHDI/7-1 to write format slin
[2017-06-12 23:31:28] DEBUG[2471][C-000003c9]: channel.c:3597 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
– <DAHDI/7-1> Playing ‘custom/Main_Welcome2.slin’ (language ‘en’)
[2017-06-12 23:31:33] DEBUG[2402]: chan_sip.c:8679 sip_alloc: Allocating new SIP dialog for [email protected][::1]:5060 - OPTIONS (No RTP)
[2017-06-12 23:31:33] DEBUG[2402]: chan_sip.c:8465 change_callid_pvt: SIP call-id changed from ‘[email protected][::1]:5060’ to ‘[email protected]:5060’
[2017-06-12 23:31:33] DEBUG[2402]: chan_sip.c:3374 initialize_initreq: Initializing initreq for method OPTIONS - callid [email protected]:5060
[2017-06-12 23:31:33] DEBUG[2402]: chan_sip.c:4429 __sip_ack: Stopping retransmission on ‘[email protected]:5060’ of Request 102: Match Found
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: dsp.c:1525 ast_dsp_process: Requesting Hangup because the busy tone was detected on channel DAHDI/7-1
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:3597 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:3597 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:5416 set_format: Set channel DAHDI/7-1 to write format ulaw
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: pbx.c:6789 __ast_pbx_run: Spawn extension (ivr-4,s,11) exited non-zero on ‘DAHDI/7-1’
== Spawn extension (ivr-4, s, 11) exited non-zero on ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:2664 ast_softhangup_nolock: Soft-Hanging up channel ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:2664 ast_softhangup_nolock: Soft-Hanging up channel ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: pbx.c:5005 pbx_extension_helper: Launching ‘Hangup’
– Executing [[email protected]:1] Hangup(“DAHDI/7-1”, “”) in new stack
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:2664 ast_softhangup_nolock: Soft-Hanging up channel ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: pbx.c:6305 ast_pbx_h_exten_run: Spawn extension (ivr-4,h,1) exited non-zero on ‘DAHDI/7-1’
== Spawn extension (ivr-4, h, 1) exited non-zero on ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: channel.c:2843 ast_hangup: Hanging up channel ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: chan_dahdi.c:6659 dahdi_hangup: dahdi_hangup(DAHDI/7-1)
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: sig_analog.c:1280 analog_hangup: analog_hangup 7
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: sig_analog.c:1303 analog_hangup: Hangup: channel: 7 index = 0, normal = 1, callwait = 0, thirdcall = 0
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: chan_dahdi.c:5414 dahdi_disable_ec: Disabled echo cancellation on channel 7
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: chan_dahdi.c:7299 dahdi_setoption: Set option TONE VERIFY, mode: OFF(0) on DAHDI/7-1
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: chan_dahdi.c:7309 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/7-1
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: sig_analog.c:785 analog_update_conf: Updated conferencing on 7, with 0 conference users
– Hanging up on ‘DAHDI/7-1’
– Hungup ‘DAHDI/7-1’
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: cdr_mysql.c:343 mysql_log: Inserting a CDR record.
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: cdr_mysql.c:346 mysql_log: SQL command as follows: INSERT INTO cdr (calldate,dst,dcontext,channel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,did) VALUES (‘2017-06-12 23:31:17’,‘s’,‘ivr-4’,‘DAHDI/7-1’,‘BackGround’,‘custom/Main_Welcome2’,‘20’,‘10’,‘ANSWERED’,‘3’,‘1497292277.1768’,‘s’)
[2017-06-12 23:31:37] DEBUG[2471][C-000003c9]: cdr_sqlite3_custom.c:261 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test,src,dst) VALUES (‘2017-06-12 23:31:17’,’’,‘ivr-4’,‘DAHDI/7-1’,’’,‘BackGround’,‘custom/Main_Welcome2’,‘20’,‘10’,‘ANSWERED’,‘DOCUMENTATION’,’’,‘1497292277.1768’,’’,’’,’’,‘s’)

Awaiting reply
Regards

Any Help I can get ?

try adding

sendcalleridafter=0

to /etc/asterisk/chan_dahdi.conf