Inbound calls randomly get fax tones

JayArr · September 20, 2019, 8:58pm

Hi All

I have a simple installation, it’s a dedicated HP Proliant DL360 server FreePBX 13.0.197 installed and all up to date. Asterisk version 13.12.1. I have one extension for my phone (ext 10) and one trunk line in (POTS5826). Both are routed through a genuine Digium 4 port modular analog PCI-Express x1 card. with one FXO and one FXS.

The overall reason for the system is to be able to screen out the robocalls and the telemarketers.

The big problem is that sometimes callers simply get a set of fax tones, I can reproduce it by calling in from my cell, hanging up and immediately calling again, the second call-in gets fax tones. I suspect that somehow the scripts from the first call aren’t all done but why that results in fax tones I don’t understand.

Pragmatically… I don’t care why I just need to get rid of the situation.

I own and have read Asterisk The Definitive Guide by Bryant, Madsen and Van Meggelen. I learned all the basics and then decided my installation was so simple it would be more appropriate to use FreePBX after all there is nothing so uncommon in my installation that it requires custom code.

The book indicates I should be able to build a simple dial plan in about 100 lines, but when I printed out the extensions_additional.conf I got 80 PAGES of code. Holy crap that has got to be the very definition of bloatware don’t you think?

When I look through the code there’s a ton I don’t use and a lot of sections I do use have lines that start:
exten => fax,1,

I don’t have any fax functions selected in the freepbx interface!

Can I delete these fax lines?

Will FreePBX just put them back? The header says it is auto generated.

How do I get rid of the bloatware and still retain usage of the FreePBX interface?

Jeff

JayArr · September 20, 2019, 9:02pm

Further info:
Here is the CDR list of the last three calls, note that the first two never got through, they just got fax tones. The third made it through.

Call Date	System	CallerID	DID	App	Destination	Disposition	Duration
2019-09-20 13:13:12	1569010392.11	“Brit. Columbia” <12506167017>	s	Dial	10	ANSWERED	02:10
2019-09-20 13:11:16	1569010276.9	7789823626	s	BackGround	s [ivr-1]	ANSWERED	00:20
2019-09-20 13:10:22	1569010222.7	7789823626	s	BackGround	s [ivr-1]	ANSWERED	00:20

Notice the app is “Background” why is it involved? I wonder if it’s still running from previous call?

JayArr · September 20, 2019, 9:06pm

Here’s the log entries for the middle call (it got fax tones)

[2019-09-20 13:11:16] VERBOSE[20775][C-00000008] sig_analog.c: Starting simple switch on 'DAHDI/1-1'
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:1] NoOp("DAHDI/1-1", "Entering from-dahdi with DID == ") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:2] Ringing("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:3] Set("DAHDI/1-1", "DID=s") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:4] NoOp("DAHDI/1-1", "DID is now s") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:5] GotoIf("DAHDI/1-1", "1?dahdiok:checkzap") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (from-analog,s,9)
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:9] NoOp("DAHDI/1-1", "Is a DAHDi Channel") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:10] Set("DAHDI/1-1", "CHAN=1-1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:11] Set("DAHDI/1-1", "CHAN=1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:12] Macro("DAHDI/1-1", "from-dahdi-1,s,1") in new stack
[2019-09-20 13:11:17] WARNING[20775][C-00000008] app_macro.c: No such context 'macro-from-dahdi-1' for macro 'from-dahdi-1'. Was called by s@from-analog
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:13] NoOp("DAHDI/1-1", "Returned from Macro from-dahdi-1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-analog:14] Goto("DAHDI/1-1", "from-pstn,s,1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (from-pstn,s,1)
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:1] Set("DAHDI/1-1", "__DIRECTION=INBOUND") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:2] Gosub("DAHDI/1-1", "sub-record-check,s,1(in,s,dontcare)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:1] GotoIf("DAHDI/1-1", "0?initialized") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:2] Set("DAHDI/1-1", "__REC_STATUS=INITIALIZED") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:3] Set("DAHDI/1-1", "NOW=1569010277") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:4] Set("DAHDI/1-1", "__DAY=20") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:5] Set("DAHDI/1-1", "__MONTH=09") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:6] Set("DAHDI/1-1", "__YEAR=2019") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:7] Set("DAHDI/1-1", "__TIMESTR=20190920-131117") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:8] Set("DAHDI/1-1", "__FROMEXTEN=unknown") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:9] Set("DAHDI/1-1", "__MON_FMT=wav") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:10] NoOp("DAHDI/1-1", "Recordings initialized") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:11] ExecIf("DAHDI/1-1", "0?Set(ARG3=dontcare)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:12] Set("DAHDI/1-1", "REC_POLICY_MODE_SAVE=") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:13] ExecIf("DAHDI/1-1", "0?Set(REC_STATUS=NO)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:14] GotoIf("DAHDI/1-1", "2?checkaction") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@sub-record-check:17] GotoIf("DAHDI/1-1", "1?sub-record-check,in,1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [in@sub-record-check:1] NoOp("DAHDI/1-1", "Inbound Recording Check to s") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [in@sub-record-check:2] Set("DAHDI/1-1", "FROMEXTEN=unknown") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [in@sub-record-check:3] ExecIf("DAHDI/1-1", "10?Set(FROMEXTEN=7789823626)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [in@sub-record-check:4] Gosub("DAHDI/1-1", "recordcheck,1(dontcare,in,s)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("DAHDI/1-1", "Starting recording check against dontcare") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("DAHDI/1-1", "dontcare") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [recordcheck@sub-record-check:3] Return("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [in@sub-record-check:5] Return("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:3] ExecIf("DAHDI/1-1", "1?Set(__FROM_DID=s)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:4] Set("DAHDI/1-1", "returnhere=1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:5] Gosub("DAHDI/1-1", "app-blacklist-check,s,1()") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@app-blacklist-check:2] Set("DAHDI/1-1", "CALLED_BLACKLIST=1") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@app-blacklist-check:3] Return("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:6] Set("DAHDI/1-1", "CDR(did)=s") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:7] GotoIf("DAHDI/1-1", "0?") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:8] ExecIf("DAHDI/1-1", "0 ?Set(CALLERID(name)=7789823626)") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:9] Set("DAHDI/1-1", "CHANNEL(musicclass)=none") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:10] Set("DAHDI/1-1", "__MOHCLASS=none") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:11] Ringing("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:12] Set("DAHDI/1-1", "__RINGINGSENT=TRUE") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:13] Set("DAHDI/1-1", "__REVERSAL_REJECT=TRUE") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:14] GotoIf("DAHDI/1-1", "0?post-reverse-charge") in new stack
[2019-09-20 13:11:17] WARNING[20775][C-00000008] func_channel.c: Unknown or unavailable item requested: 'reversecharge'
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:15] GotoIf("DAHDI/1-1", "0?macro-hangupcall") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:16] NoOp("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:17] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:17] Wait("DAHDI/1-1", "3") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:18] Set("DAHDI/1-1", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:19] Set("DAHDI/1-1", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:20] Set("DAHDI/1-1", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:21] Set("DAHDI/1-1", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:22] NoOp("DAHDI/1-1", "CallerID Entry Point") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@from-pstn:23] Goto("DAHDI/1-1", "ivr-1,s,1") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (ivr-1,s,1)
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:1] Set("DAHDI/1-1", "TIMEOUT_LOOPCOUNT=0") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:2] Set("DAHDI/1-1", "INVALID_LOOPCOUNT=0") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:3] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-1=") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:4] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-1") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:5] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:6] GotoIf("DAHDI/1-1", "0?skip") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:7] Answer("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:20] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:8] Wait("DAHDI/1-1", "1") in new stack
[2019-09-20 13:11:21] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:9] Set("DAHDI/1-1", "IVR_MSG=custom/welcome-to-jre") in new stack
[2019-09-20 13:11:21] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:10] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[2019-09-20 13:11:21] VERBOSE[20775][C-00000008] func_timeout.c: Digit timeout set to 3.000
[2019-09-20 13:11:21] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:11] ExecIf("DAHDI/1-1", "1?Background(custom/welcome-to-jre)") in new stack
[2019-09-20 13:11:21] VERBOSE[20775][C-00000008] file.c: &lt;DAHDI/1-1&gt; Playing 'custom/welcome-to-jre.slin' (language 'en')
[2019-09-20 13:11:29] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:12] WaitExten("DAHDI/1-1", "3,") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx_builtins.c: Timeout on DAHDI/1-1, going to 't'
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx.c: Executing [t@ivr-1:1] Set("DAHDI/1-1", "TIMEOUT_LOOPCOUNT=1") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx.c: Executing [t@ivr-1:2] GotoIf("DAHDI/1-1", "0?final") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx.c: Executing [t@ivr-1:3] Set("DAHDI/1-1", "IVR_MSG=custom/timeout&amp;custom/welcome-to-jre") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx.c: Executing [t@ivr-1:4] Goto("DAHDI/1-1", "s,start") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx_builtins.c: Goto (ivr-1,s,10)
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:10] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] func_timeout.c: Digit timeout set to 3.000
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] pbx.c: Executing [s@ivr-1:11] ExecIf("DAHDI/1-1", "1?Background(custom/timeout&amp;custom/welcome-to-jre)") in new stack
[2019-09-20 13:11:32] VERBOSE[20775][C-00000008] file.c: &lt;DAHDI/1-1&gt; Playing 'custom/timeout.slin' (language 'en')
[2019-09-20 13:11:36] VERBOSE[20775][C-00000008] pbx.c: Spawn extension (ivr-1, s, 11) exited non-zero on 'DAHDI/1-1'
[2019-09-20 13:11:36] VERBOSE[20775][C-00000008] pbx.c: Executing [h@ivr-1:1] Hangup("DAHDI/1-1", "") in new stack
[2019-09-20 13:11:36] VERBOSE[20775][C-00000008] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on 'DAHDI/1-1'
[2019-09-20 13:11:36] VERBOSE[20775][C-00000008] sig_analog.c: Hanging up on 'DAHDI/1-1'
[2019-09-20 13:11:36] VERBOSE[20775][C-00000008] chan_dahdi.c: Hungup 'DAHDI/1-1'

Stewart1 · September 20, 2019, 9:47pm

This is most puzzling, as the log shows it playing the IVR prompt normally (and eventually timing out).

Please confirm:

You don’t have a fax machine or other non-voice equipment, e.g. alarm system or medical alert device on this line.
The FXO port is connected to a real copper POTS line, rather than e.g. a cable MTA or fiber ONT.
The Fax tab for your Inbound Route (if it exists at all) has Detect Faxes set to No.
Your /etc/asterisk/chan_dahdi.conf has faxdetect=no.

Do you have a way to monitor the POTS line, such as a butt set?

On a successful call, hang up the calling mobile but keep the called analog phone off hook. See whether Asterisk recognizes the disconnect almost immediately (one second or less), or there is a long delay.

JayArr · September 20, 2019, 11:25pm

Hi Stewart1

I don’t own a fax machine, at all.

The POTs line is copper and a real POTs line. It does branch into the alarm system but it’s a relay contact circuit such that the alarm system can break onto the line and cause the line to go off hook before it dials a pre programmed number to the alarm company. The alarm does not monitor or answer the line, all it can do is activate the relay to break into the line and dial out.

The fax tab on my inbound route has detect Faxes set to NO.

My /etc/asterisk/chan_dahdi.conf file has faxdetect=no

There is a long delay after I hang up the calling phone, almost 10 seconds, before asterisk puts a dial tone onto my extension set.

JayArr · September 20, 2019, 11:30pm

I just simulated it again, the middle call resulted in fax tones, notice the CDR reported it’s app as “Background”

Call Date	System	CallerID	DID	App	Destination	Disposition	Duration
2019-09-20 16:24:11	1569021851.26	“MICHELLE GAUTHI” <7789823626>	s	Dial	10	ANSWERED	00:28
2019-09-20 16:22:58	1569021778.25	UNKNOWN	s	BackGround	s [ivr-1]	ANSWERED	00:21
2019-09-20 16:22:14	1569021734.23	“MICHELLE GAUTHI” <7789823626>	s	Dial	10	ANSWERED	00:37

Here is the log of the middle call:

[2019-09-20 16:22:58] VERBOSE[346][C-00000015] sig_analog.c: Starting simple switch on ‘DAHDI/1-1’
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:1] NoOp(“DAHDI/1-1”, "Entering from-dahdi with DID == ") in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:2] Ringing(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:3] Set(“DAHDI/1-1”, “DID=s”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:4] NoOp(“DAHDI/1-1”, “DID is now s”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:5] GotoIf(“DAHDI/1-1”, “1?dahdiok:checkzap”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx_builtins.c: Goto (from-analog,s,9)
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:9] NoOp(“DAHDI/1-1”, “Is a DAHDi Channel”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:10] Set(“DAHDI/1-1”, “CHAN=1-1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:11] Set(“DAHDI/1-1”, “CHAN=1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:12] Macro(“DAHDI/1-1”, “from-dahdi-1,s,1”) in new stack
[2019-09-20 16:23:08] WARNING[346][C-00000015] app_macro.c: No such context ‘macro-from-dahdi-1’ for macro ‘from-dahdi-1’. Was called by s@from-analog
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:13] NoOp(“DAHDI/1-1”, “Returned from Macro from-dahdi-1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-analog:14] Goto(“DAHDI/1-1”, “from-pstn,s,1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx_builtins.c: Goto (from-pstn,s,1)
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:1] Set(“DAHDI/1-1”, “__DIRECTION=INBOUND”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:2] Gosub(“DAHDI/1-1”, “sub-record-check,s,1(in,s,dontcare)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:1] GotoIf(“DAHDI/1-1”, “0?initialized”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:2] Set(“DAHDI/1-1”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:3] Set(“DAHDI/1-1”, “NOW=1569021788”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:4] Set(“DAHDI/1-1”, “__DAY=20”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:5] Set(“DAHDI/1-1”, “__MONTH=09”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:6] Set(“DAHDI/1-1”, “__YEAR=2019”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:7] Set(“DAHDI/1-1”, “__TIMESTR=20190920-162308”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:8] Set(“DAHDI/1-1”, “__FROMEXTEN=unknown”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:9] Set(“DAHDI/1-1”, “__MON_FMT=wav”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:10] NoOp(“DAHDI/1-1”, “Recordings initialized”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:11] ExecIf(“DAHDI/1-1”, “0?Set(ARG3=dontcare)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:12] Set(“DAHDI/1-1”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:13] ExecIf(“DAHDI/1-1”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:14] GotoIf(“DAHDI/1-1”, “2?checkaction”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@sub-record-check:17] GotoIf(“DAHDI/1-1”, “1?sub-record-check,in,1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [in@sub-record-check:1] NoOp(“DAHDI/1-1”, “Inbound Recording Check to s”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [in@sub-record-check:2] Set(“DAHDI/1-1”, “FROMEXTEN=unknown”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [in@sub-record-check:3] ExecIf(“DAHDI/1-1”, “0?Set(FROMEXTEN=)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [in@sub-record-check:4] Gosub(“DAHDI/1-1”, “recordcheck,1(dontcare,in,s)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“DAHDI/1-1”, “Starting recording check against dontcare”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“DAHDI/1-1”, “dontcare”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [in@sub-record-check:5] Return(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:3] ExecIf(“DAHDI/1-1”, “1?Set(__FROM_DID=s)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:4] Set(“DAHDI/1-1”, “returnhere=1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:5] Gosub(“DAHDI/1-1”, “app-blacklist-check,s,1()”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“DAHDI/1-1”, “0?blacklisted”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@app-blacklist-check:2] Set(“DAHDI/1-1”, “CALLED_BLACKLIST=1”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@app-blacklist-check:3] Return(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:6] Set(“DAHDI/1-1”, “CDR(did)=s”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:7] GotoIf(“DAHDI/1-1”, “0?”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:8] ExecIf(“DAHDI/1-1”, “1 ?Set(CALLERID(name)=)”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:9] Set(“DAHDI/1-1”, “CHANNEL(musicclass)=none”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:10] Set(“DAHDI/1-1”, “__MOHCLASS=none”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:11] Ringing(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:12] Set(“DAHDI/1-1”, “__RINGINGSENT=TRUE”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:13] Set(“DAHDI/1-1”, “__REVERSAL_REJECT=TRUE”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:14] GotoIf(“DAHDI/1-1”, “0?post-reverse-charge”) in new stack
[2019-09-20 16:23:08] WARNING[346][C-00000015] func_channel.c: Unknown or unavailable item requested: ‘reversecharge’
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:15] GotoIf(“DAHDI/1-1”, “0?macro-hangupcall”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:16] NoOp(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:08] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:17] Wait(“DAHDI/1-1”, “3”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:18] Set(“DAHDI/1-1”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:19] Set(“DAHDI/1-1”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:20] Set(“DAHDI/1-1”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:21] Set(“DAHDI/1-1”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:22] NoOp(“DAHDI/1-1”, “CallerID Entry Point”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@from-pstn:23] Goto(“DAHDI/1-1”, “ivr-1,s,1”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx_builtins.c: Goto (ivr-1,s,1)
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:1] Set(“DAHDI/1-1”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:2] Set(“DAHDI/1-1”, “INVALID_LOOPCOUNT=0”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:3] Set(“DAHDI/1-1”, “_IVR_CONTEXT_ivr-1=”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:4] Set(“DAHDI/1-1”, “_IVR_CONTEXT=ivr-1”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:5] Set(“DAHDI/1-1”, “__IVR_RETVM=”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:6] GotoIf(“DAHDI/1-1”, “0?skip”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:7] Answer(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:11] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:8] Wait(“DAHDI/1-1”, “1”) in new stack
[2019-09-20 16:23:12] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:9] Set(“DAHDI/1-1”, “IVR_MSG=custom/welcome-to-jre”) in new stack
[2019-09-20 16:23:12] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:10] Set(“DAHDI/1-1”, “TIMEOUT(digit)=3”) in new stack
[2019-09-20 16:23:12] VERBOSE[346][C-00000015] func_timeout.c: Digit timeout set to 3.000
[2019-09-20 16:23:12] VERBOSE[346][C-00000015] pbx.c: Executing [s@ivr-1:11] ExecIf(“DAHDI/1-1”, “1?Background(custom/welcome-to-jre)”) in new stack
[2019-09-20 16:23:12] VERBOSE[346][C-00000015] file.c: <DAHDI/1-1> Playing ‘custom/welcome-to-jre.slin’ (language ‘en’)
[2019-09-20 16:23:13] WARNING[346][C-00000015] sig_analog.c: Ring/Off-hook in strange state 6 on channel 1
[2019-09-20 16:23:15] NOTICE[346][C-00000015] sig_analog.c: Alarm cleared on channel 1
[2019-09-20 16:23:20] VERBOSE[346][C-00000015] pbx.c: Spawn extension (ivr-1, s, 11) exited non-zero on ‘DAHDI/1-1’
[2019-09-20 16:23:20] VERBOSE[346][C-00000015] pbx.c: Executing [h@ivr-1:1] Hangup(“DAHDI/1-1”, “”) in new stack
[2019-09-20 16:23:20] VERBOSE[346][C-00000015] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘DAHDI/1-1’
[2019-09-20 16:23:20] VERBOSE[346][C-00000015] sig_analog.c: Hanging up on ‘DAHDI/1-1’
[2019-09-20 16:23:20] VERBOSE[346][C-00000015] chan_dahdi.c: Hungup ‘DAHDI/1-1’

JayArr · September 20, 2019, 11:40pm

What does this mean?

[2019-09-20 16:23:13] WARNING[346][C-00000015] sig_analog.c: Ring/Off-hook in strange state 6 on channel 1

it’s near the very end of the log just after where background is playing the welcome message.

arielgrin · September 21, 2019, 12:02am

It means that the fxo port detected an abnormal state of the line, either related to unexpected voltage or current values for the actual real status of the line, be it onhook, ringing or offhook.

JayArr · September 21, 2019, 12:48am

Thanks Arielfrin, that gives me something to work with.

I’ve changed the FXO module - no change in symptoms so that’s not it.

arielgrin · September 21, 2019, 2:16am

It is usually a problem on the line, not on the fxo port.
Regarding fax tones, by any chance have you enabled tone detection when you configured your card? I don’t know if Digium has that option, but Sangoma cards do.

Stewart1 · September 21, 2019, 4:31am

Many alarm systems are set up so the installer can remotely bypass zones or even program the system. The usual protocol for this is the installer calls in, lets it ring once, hangs up, then calls back 10 to 30 seconds later. When the alarm system sees this sequence, its modem answers the line and after authenticating, the installer can make changes.

I’m fairly sure that your testing is inadvertently causing the alarm to answer. Your calls are always ‘answered’ after one ring, because once DAHDI has collected the caller ID, the IVR picks up the line. I’m guessing that the alarm panel is not smart enough to detect the off hook in this case, so it just sees the single ring and ‘arms’ itself to answer the next call if it comes within the appropriate window.

You can confirm all this by connecting an analog phone in parallel with the FXO card. When an inbound call fails and the caller hears modem tones, pick up the analog phone and listen. My bet is that you’ll hear nothing, because the panel has seized the line.

If this is indeed your issue and you don’t need this remote access to the panel, just disable it (if you don’t know the installer code, ask the alarm company to do so). Some panels can be set up to answer after e.g. 15 rings, so by temporarily disabling the PBX from answering, remote access to the panel is still possible.

If you still have trouble, please post: Alarm panel make/model? Do you have the installer code?

JayArr · September 21, 2019, 4:42am

You sir are a GENIUS!

OK, Solved! the sounds were from the alarm not asterisk.

The function is called Ans. Mach. Overide/Double Call Enabled.
Section 401 - option 1 (DSC 832 model PC5010)
(I have the installer code and all the manuals, I put this alarm in myself)

I think what was happening was that the line would ring and both would try to answer but when the alarm grabs the line everything after it (asterisk) goes dead so then asterisk threw a warning because the POTS line had no voltage on it. In the meantime the caller is listening to the modem from the alarm trying to communicate with what it thinks is the base station.

Thanks to everyone who helped, especially Stewart1 !

system · September 28, 2019, 4:52am

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.