Superfecta - new errors and timeouts

Hello,

I’m using Freepbx 14 with Superfecta 14.0.6 (also tried 14.0.18 with similar results).

Long story short, everything was working fine. Did an update and some time after I noticed calls were not coming in. Checking the logs it appears the call comes in but gets stuck in the superfecta. Not sure if the issue is being caused by the update or not.

So tried manually running superfecta and I see the following errors with Google and Can411 modules.

Executing GoogleContacts
Searching Google Contacts for number: 9051234567
{“error”:{“type”:“Whoops\Exception\ErrorException”,“message”:“DOMDocument::loadXML(): Empty string supplied as input”,“file”:"/var/www/html/admin/modules/superfecta/includes/oauth-google/Google_Service_ReadContacts.php",“line”:71}

Executing Can411
Searching www.411.ca - (905) 123-4567…
Resolving timed out after 3519 milliseconds
result took 5.0411 seconds.

Is anyone else having any issues with Can411 or GoogleContacts in Superfecta?

A call trace would be generally helpful here. Based on the exception I would say google contacts is not configured correctly.

The strange thing is it was working perfectly before.

Attached is what I have in the log for the incoming call. If there is a better way to log please let me know.

Since this log was taken, i’ve disabled Google portion and cleared credentials. Reactivated…Run the “debug” followed the link to get the activation code, put it back in. And again the same issue.

> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12896344334@from-trunk:1] Set("SIP/FPLOuT-00000049", "__DIRECTION=INBOUND") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12896344334@from-trunk:2] Gosub("SIP/FPLOuT-00000049", "sub-record-check,s,1(in,12896344334,force)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/FPLOuT-00000049", "0?initialized") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:2] Set("SIP/FPLOuT-00000049", "__REC_STATUS=INITIALIZED") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:3] Set("SIP/FPLOuT-00000049", "NOW=1553186590") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:4] Set("SIP/FPLOuT-00000049", "__DAY=21") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:5] Set("SIP/FPLOuT-00000049", "__MONTH=03") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:6] Set("SIP/FPLOuT-00000049", "__YEAR=2019") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:7] Set("SIP/FPLOuT-00000049", "__TIMESTR=20190321-124310") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:8] Set("SIP/FPLOuT-00000049", "__FROMEXTEN=unknown") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:9] Set("SIP/FPLOuT-00000049", "__MON_FMT=wav") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/FPLOuT-00000049", "Recordings initialized") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/FPLOuT-00000049", "0?Set(ARG3=dontcare)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:12] Set("SIP/FPLOuT-00000049", "REC_POLICY_MODE_SAVE=") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/FPLOuT-00000049", "0?Set(REC_STATUS=NO)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/FPLOuT-00000049", "2?checkaction") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (sub-record-check,s,17)
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/FPLOuT-00000049", "1?sub-record-check,in,1") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (sub-record-check,in,1)
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/FPLOuT-00000049", "Inbound Recording Check to 12891234567") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [in@sub-record-check:2] Set("SIP/FPLOuT-00000049", "FROMEXTEN=unknown") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/FPLOuT-00000049", "10?Set(FROMEXTEN=9051237918)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/FPLOuT-00000049", "recordcheck,1(force,in,12891234567)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/FPLOuT-00000049", "Starting recording check against force") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/FPLOuT-00000049", "force") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:5] Set("SIP/FPLOuT-00000049", "__REC_POLICY_MODE=FORCE") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf("SIP/FPLOuT-00000049", "1?startrec") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("SIP/FPLOuT-00000049", "Starting recording: in, 12891234567") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:17] Set("SIP/FPLOuT-00000049", "__CALLFILENAME=in-12891234567-9051237918-20190321-124310-1553186590.89") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:18] MixMonitor("SIP/FPLOuT-00000049", "2019/03/21/in-12891234567-9051237918-20190321-124310-1553186590.89.wav,abi(LOCAL_MIXMON_ID),") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:19] Set("SIP/FPLOuT-00000049", "__MIXMON_ID=0x7fe3e0049e60") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:20] Set("SIP/FPLOuT-00000049", "__RECORD_ID=SIP/FPLOuT-00000049") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:21] Set("SIP/FPLOuT-00000049", "__REC_STATUS=RECORDING") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:22] Set("SIP/FPLOuT-00000049", "CDR(recordingfile)=in-12891234567-9051237918-20190321-124310-1553186590.89.wav") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [recordcheck@sub-record-check:23] Return("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [in@sub-record-check:5] Return("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:3] Set("SIP/FPLOuT-00000049", "CHANNEL(tonezone)=us") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:4] Set("SIP/FPLOuT-00000049", "__FROM_DID=12891234567") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:5] Set("SIP/FPLOuT-00000049", "returnhere=1") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:6] Gosub("SIP/FPLOuT-00000049", "app-blacklist-check,s,1()") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/FPLOuT-00000049", "0?blacklisted") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/FPLOuT-00000049", "CALLED_BLACKLIST=1") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:7] Set("SIP/FPLOuT-00000049", "CDR(did)=12891234567") in new stack
> [2019-03-21 12:43:10] VERBOSE[18681][C-0000002a] app_mixmonitor.c: Begin MixMonitor Recording SIP/FPLOuT-00000049
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:8] GotoIf("SIP/FPLOuT-00000049", "0?") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:9] ExecIf("SIP/FPLOuT-00000049", "0 ?Set(CALLERID(name)=9051237918)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:10] Set("SIP/FPLOuT-00000049", "__MOHCLASS=") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:11] Set("SIP/FPLOuT-00000049", "__REVERSAL_REJECT=FALSE") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:12] GotoIf("SIP/FPLOuT-00000049", "1?post-reverse-charge") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (from-trunk,12891234567,14)
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:14] NoOp("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:15] Macro("SIP/FPLOuT-00000049", "privacy-mgr,3,10") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:1] Set("SIP/FPLOuT-00000049", "KEEPCID=9051237918") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:2] Set("SIP/FPLOuT-00000049", "TESTCID=9056979188.000000") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:3] ExecIf("SIP/FPLOuT-00000049", "0?Set(CALLERID(num)=)") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:4] PrivacyManager("SIP/FPLOuT-00000049", "3,10") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] app_privacy.c: CallerID number present: Skipping
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:5] GotoIf("SIP/FPLOuT-00000049", "0?fail") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:6] GosubIf("SIP/FPLOuT-00000049", "1?app-blacklist-check,s,1()") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/FPLOuT-00000049", "0?blacklisted") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/FPLOuT-00000049", "CALLED_BLACKLIST=1") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:7] Set("SIP/FPLOuT-00000049", "CALLERID(num-pres)=allowed_passed_screen") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-privacy-mgr:8] MacroExit("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:16] Set("SIP/FPLOuT-00000049", "CIDSFSCHEME=YmFzZV9EZWZhdWx0") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:17] AGI("SIP/FPLOuT-00000049", "/var/www/html/admin/modules/superfecta/agi/superfecta.agi") in new stack
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: Launched AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: Executing Scheme..
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: Scheme Asked is: Default
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: The DID is: 12891234567
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: The CNUM is: 9051237918
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: The CNAME is: Smith D .
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi:
> [2019-03-21 12:43:10] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: Starting scheme Default
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: No callerid found
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Determined to be: 'Smith D .'
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: Attempting to set lookupcid
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] res_agi.c: <SIP/FPLOuT-00000049>AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi completed, returning 0
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:18] Set("SIP/FPLOuT-00000049", "CALLERID(name)=Smith D .") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:19] NoOp("SIP/FPLOuT-00000049", "CallerID Entry Point") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [12891234567@from-trunk:20] Goto("SIP/FPLOuT-00000049", "timeconditions,1,1") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (timeconditions,1,1)
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:1] Set("SIP/FPLOuT-00000049", "DB(TC/1/INUSESTATE)=INUSE") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:2] Set("SIP/FPLOuT-00000049", "DB(TC/1/NOT_INUSESTATE)=NOT_INUSE") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:3] NoOp("SIP/FPLOuT-00000049", "TIMENOW: 12:43,Thu,21,Mar,America/Toronto") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:4] NoOp("SIP/FPLOuT-00000049", "TIMEMATCHED: FALSE") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:5] GotoIfTime("SIP/FPLOuT-00000049", "22:10-07:15,mon-fri,*,*,America/Toronto?truestate") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:6] NoOp("SIP/FPLOuT-00000049", "TIMENOW: 12:43,Thu,21,Mar,America/Toronto") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:7] NoOp("SIP/FPLOuT-00000049", "TIMEMATCHED: FALSE") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:8] GotoIfTime("SIP/FPLOuT-00000049", "22:30-09:00,sat-sun,*,*,America/Toronto?truestate") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:9] GotoIf("SIP/FPLOuT-00000049", "0?truegoto") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:10] ExecIf("SIP/FPLOuT-00000049", "0?Set(DB(TC/1)=)") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:11] Set("SIP/FPLOuT-00000049", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:12] ExecIf("SIP/FPLOuT-00000049", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [1@timeconditions:13] GotoIf("SIP/FPLOuT-00000049", "1?ext-group,600,1") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (ext-group,600,1)
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [600@ext-group:1] GotoIf("SIP/FPLOuT-00000049", "0?cid") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [600@ext-group:2] PlayTones("SIP/FPLOuT-00000049", "ring") in new stack
> [2019-03-21 12:43:38] WARNING[18678][C-0000002a] translate.c: no samples for ulawtolin
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [600@ext-group:3] Progress("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [600@ext-group:4] Macro("SIP/FPLOuT-00000049", "user-callerid,") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/FPLOuT-00000049", "TOUCH_MONITOR=1553186590.89") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/FPLOuT-00000049", "AMPUSER=9051237918") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/FPLOuT-00000049", "0?report") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/FPLOuT-00000049", "1?Set(REALCALLERIDNUM=9051237918)") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/FPLOuT-00000049", "AMPUSER=") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/FPLOuT-00000049", "0?limit") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/FPLOuT-00000049", "AMPUSERCIDNAME=") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/FPLOuT-00000049", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/FPLOuT-00000049", "1?report") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (macro-user-callerid,s,16)
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/FPLOuT-00000049", "Macro Depth is 1") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/FPLOuT-00000049", "1?report2:macroerror") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (macro-user-callerid,s,18)
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/FPLOuT-00000049", "0?continue") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("SIP/FPLOuT-00000049", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:20] Set("SIP/FPLOuT-00000049", "__TTL=64") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("SIP/FPLOuT-00000049", "1?continue") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (macro-user-callerid,s,37)
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/FPLOuT-00000049", "CALLERID(number)=9051237918") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/FPLOuT-00000049", "CALLERID(name)=Smith D .") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("SIP/FPLOuT-00000049", "0?cnum") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/FPLOuT-00000049", "CDR(cnam)=Smith D .") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [h@ext-group:1] Macro("SIP/FPLOuT-00000049", "hangupcall,") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/FPLOuT-00000049", "1?theend") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx_builtins.c: Goto (macro-hangupcall,s,3)
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/FPLOuT-00000049", "0?Set(CDR(recordingfile)=)") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-hangupcall:4] NoOp("SIP/FPLOuT-00000049", " monior file= /var/spool/asterisk/monitor/2019/03/21/in-12891231234-9051237918-20190321-124310-1553186590.89.wav") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-hangupcall:5] AGI("SIP/FPLOuT-00000049", "attendedtransfer-rec-restart.php,,/var/spool/asterisk/monitor/2019/03/21/in-12891231234-9051237918-20190321-124310-1553186590.89.wav") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] res_agi.c: <SIP/FPLOuT-00000049>AGI Script attendedtransfer-rec-restart.php completed, returning 0
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Executing [s@macro-hangupcall:6] Hangup("SIP/FPLOuT-00000049", "") in new stack
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'SIP/FPLOuT-00000049' in macro 'hangupcall'
> [2019-03-21 12:43:38] VERBOSE[18678][C-0000002a] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/FPLOuT-00000049'
> [2019-03-21 12:43:38] VERBOSE[18681][C-0000002a] app_mixmonitor.c: MixMonitor close filestream (mixed)
> [2019-03-21 12:43:38] VERBOSE[18681][C-0000002a] app_mixmonitor.c: End MixMonitor Recording SIP/FPLOuT-00000049
> [2019-03-21 12:44:03] VERBOSE[2270][C-0000002b] netsock2.c: Using SIP RTP TOS bits 184
> [2019-03-21 12:44:03] VERBOSE[2270][C-0000002b] netsock2.c: Using SIP RTP CoS mark 5

First step is to update to current:

[root@freepbx asterisk]# fwconsole ma list | grep super
| superfecta           | 14.0.18    |

fwconsole ma upgrade superfecta --edge

Upgraded: | superfecta | 14.0.18 | Enabled | GPLv2+

Turned on google and tried the debug/test/

Debug is on and set at level: 1
The Original Number: 9051234567
The Scheme: Default
Scheme Type: SINGLEFECTA
Debugging Enabled, will not stop after first result

Scheme Asked is: Default
The DID is: 5555555555
The CNUM is: 9051234567
The CNAME is: CID Superfecta!

Starting scheme Default
Executing Superfecta Cache
Searching Superfecta Cache …
‘unknown’
result took 0.0021 seconds.

Executing GoogleContacts
Searching Google Contacts for number: 9051234567
{“error”:{“type”:“Whoops\Exception\ErrorException”,“message”:“DOMDocument::loadXML(): Empty string supplied as input”,“file”:"/var/www/html/admin/modules/superfecta/includes/oauth-google/Google_Service_ReadContacts.php",“line”:71}}

Since it didn’t ask me to re-authorize, just out of curiousity would it help if I uninstalled and re-installed superfecta?

Just as an updated, just to be safe, uninstalled and removed module.
Installed module added google and ran. Got:

Executing GoogleContacts
Searching Google Contacts for number: 9051234567
Access Token missing: authorisation is needed.

To set or reset authorisation

Click the link in the next line, then copy the code google give into the second box on the settings area for Google Contacts. Then click submit in the settings, and then use another test number to check all is working.

To start that process, click here

So far so good. Did the authorization. Run Test again. getting:

Executing GoogleContacts
Searching Google Contacts for number: 9051234567
{“error”:{“type”:“Whoops\Exception\ErrorException”,“message”:“DOMDocument::loadXML(): Empty string supplied as input”,“file”:“/var/www/html/admin/modules/superfecta/includes/oauth-google/Google_Service_ReadContacts.php”,“line”:71}}

This might be a bug. See if anyone here can reproduce this, and then report it: issues.freepbx.org

You know in another post IVR only accepting 1 digit - #23 by sentinelace @tm1000 asked “Why are you running edge on production machines?” pointing out the new release that caused the complaint it the post was in edge for a reason.

However, this is probably how people end up with Edge stuff on their system. Being told almost all the time the answer is to upgrade and that it is in Edge. If Edge is there for testing/finalizing the update/release before pushing it to the Stable repo for people to update with then suggesting it for almost everything when telling people to upgrade makes it kind of pointless because you just end up with rando’s that see posts like this and jump on Edge.

Edge is either there for testing modules before they go Stable or it’s there for Stable updates to be pulled from. It can’t be both and you can’t have it both ways.

1 Like

Google contacts is working for me, and I am running edge. I know there were recent changes to the Google Contacts module, so I was half expecting the upgrade to fix things. Even if it doesn’t fix, it is necessary to confirm that the issue is present in the edge version before opening a ticket.

@lesismore

Further testing on my part, and I was able to reproduce your issue exactly once, and it appears to have happened when I did a Google Contacts lookup on a number that partially matches an entry. Issue is in the file /var/www/html/admin/modules/superfecta/includes/oauth-google/Google_Service_ReadContacts.php near this section:

$result = $this->curl_file_get_contents($this->constructFinalUrl());

//        echo $result;

$doc = new DOMDocument;
$doc->recover = true;
$doc->loadXML($result);

In some cases $result is not getting set, or getting set to something unexpected. If you uncomment the echo line and do more debug lookups you might be able to figure out what’s going on and open a bug ticket.

Thanks for the assistance Lorne! I’ve uncommented and changed to debug level 3 but still don’t get any additional information. I’ve also tested with contacts saved as +1905… 1905… and 905… all produce the same result. So I have logged Bug #19692

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