Trouble configuring Zulu

Commercial Products and Partners Sangoma
1

I am playing with Zulu to see if it can work well for our organization. I’ve “purchased” the 2 user license and set it up on my computer. I’m having an issue with Zulu connecting over WAN.

We have two internet lines in our office, a dedicated VOIP line and a line for all other use. If my computer is on the same LAN as the PBX (and I use the local IP in the Zulu Configuration) everything works as intended. However, if I move my computer off the PBX LAN and onto the other line, then change the Zulu configuration to my external IP for the PBX internet line, it won’t connect.

Am I missing a Zulu setting or firewall setting somewhere? I’m using the built in FreePBX firewall.

1.jpg1519×849 133 KB

2

Have you opened the ports for zulu as outlined in the zulu wiki

3

Thanks Tony, your response led me to the answer.

On the PBX firewall The Zulu service was not open. It said the service is automatically open to registered clients. I’m assuming since my desk phone is on the same LAN as the PBX but my computer was on a different LAN that is the reason it did not automatically open for me. I allowed it for Internet, Local, and Other.

I can now get the Zulu app to register from the other network, but now there is another issue. When I make a call from the Zulu app or when I call the extension from an outside line, the Zulu app goes to a grey screen that says “Connection dropped by remote peer”. This happens on the same network as my PBX and on the external network.

Thanks,

1 Like
4

You’d have to provide logs from the server showing us the crash.

5

Logs are below. Inbound call started at August 21st 2017, 9:05:08 am. I received the grey “Connection dropped by remote peer” at the beginning of this call. The logs show a “connectFailed - Error: connect ETIMEDOUT xxx.xxx.x.xxx:8002” about every 30 seconds. I’m only including the last few

If it matters, xxx.xxx.x.xxx is my PBX local address and yy.yyy.yy.yyy is the machine’s WAN address.

August 21st 2017, 9:03:01 am - debug: PBXCommunicator - increaseReconnectionTime - Increased reconnection time - 32000ms
August 21st 2017, 9:03:01 am - debug: PBXCommunicator - connect - xxx.xxx.x.xxx - 8002 - wss://
August 21st 2017, 9:03:01 am - debug: PBXCommunicator - Connecting to pbx server
August 21st 2017, 9:03:22 am - error: PBXCommunicator - connectFailed - Error: connect ETIMEDOUT xxx.xxx.x.xxx:8002
August 21st 2017, 9:03:54 am - debug: PBXCommunicator - increaseReconnectionTime - Increased reconnection time - 32000ms
August 21st 2017, 9:03:54 am - debug: PBXCommunicator - connect - xxx.xxx.x.xxx - 8002 - wss://
August 21st 2017, 9:03:54 am - debug: PBXCommunicator - Connecting to pbx server
August 21st 2017, 9:04:15 am - error: PBXCommunicator - connectFailed - Error: connect ETIMEDOUT xxx.xxx.x.xxx:8002
August 21st 2017, 9:04:47 am - debug: PBXCommunicator - increaseReconnectionTime - Increased reconnection time - 32000ms
August 21st 2017, 9:04:47 am - debug: PBXCommunicator - connect - xxx.xxx.x.xxx - 8002 - wss://
August 21st 2017, 9:04:47 am - debug: PBXCommunicator - Connecting to pbx server
August 21st 2017, 9:05:08 am - debug: ApplicationController - Current section - call
August 21st 2017, 9:05:08 am - error: PBXCommunicator - connectFailed - Error: connect ETIMEDOUT xxx.xxx.x.xxx:8002
August 21st 2017, 9:05:18 am - debug: ApplicationController - Current section - call
August 21st 2017, 9:05:22 am - debug: DOWNLOADING: C:\Users\Brad Phillips\AppData\Roaming\ZULU\zulu-1503324322.log
August 21st 2017, 9:05:28 am - debug: ApplicationController - Current section - about
August 21st 2017, 9:05:30 am - debug: ApplicationController - Changed section - call
August 21st 2017, 9:05:30 am - debug: Configuration - Getting configuration
August 21st 2017, 9:05:40 am - debug: PBXCommunicator - increaseReconnectionTime - Increased reconnection time - 32000ms
August 21st 2017, 9:05:40 am - debug: PBXCommunicator - connect - xxx.xxx.x.xxx - 8002 - wss://
August 21st 2017, 9:05:40 am - debug: PBXCommunicator - Connecting to pbx server
August 21st 2017, 9:05:49 am - debug: PBXCommunicator - Connection to PBX Server was closed: Connection dropped by remote peer.
August 21st 2017, 9:05:49 am - debug: PBXCommunicator - Connection to PBX Server was closed: Connection dropped by remote peer.
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - increaseReconnectionTime - Increased reconnection time - 2000ms
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - connect - yy.yyy.yy.yyy - 8002 - wss://
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - Connecting to pbx server
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - increaseReconnectionTime - Increased reconnection time - 2000ms
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - connect - yy.yyy.yy.yyy - 8002 - wss://
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - Connecting to pbx server
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - WebSocket Client Connected
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - clearReconnectionTimeouts
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - connect - waiting 2000ms to reset reconnection time
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - WebSocket Client Connected
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - clearReconnectionTimeouts
August 21st 2017, 9:05:50 am - debug: PBXCommunicator - connect - waiting 2000ms to reset reconnection time
August 21st 2017, 9:05:50 am - debug: Configuration - Getting configuration
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - Auth message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - Saving timestamp...
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - Auth message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - initial-presence-state message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - Initial state received - available
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - sms-dids message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - presence-states message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - incoming-presence-state message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - Subscribed to changes in presence state.
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - config message
August 21st 2017, 9:05:51 am - debug: UserImageManager - Image for bphillips expired
August 21st 2017, 9:05:51 am - debug: UserImageManager - Image for bphillips expired
August 21st 2017, 9:05:51 am - debug: UserImageManager - Local image is too old for bphillips
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - incoming-call message
August 21st 2017, 9:05:51 am - debug: PBXCommunicator - incoming-fax message
August 21st 2017, 9:05:52 am - debug: PBXCommunicator - Saving timestamp...
August 21st 2017, 9:05:52 am - debug: PBXCommunicator - Saving timestamp...
August 21st 2017, 9:05:52 am - debug: PBXCommunicator - resetReconnectionTime - Reset reconnection time - 1000ms
August 21st 2017, 9:05:52 am - debug: PBXCommunicator - resetReconnectionTime - Reset reconnection time - 1000ms
August 21st 2017, 9:05:53 am - debug: PBXCommunicator - contactlist message
August 21st 2017, 9:05:53 am - debug: PBXCommunicator - user-image message
August 21st 2017, 9:05:53 am - debug: UserImageManager - Saved image for bphillips
August 21st 2017, 9:06:01 am - error: PBXCommunicator - connectFailed - Error: connect ETIMEDOUT xxx.xxx.x.xxx:8002
August 21st 2017, 9:06:02 am - debug: ApplicationController - Current section - call

Thanks!

6

Those are not logs from the server unless you somehow figured out how to get freepbx to run on windows.

7

Sorry about that! Here are my PBX logs for a phone call. I had to cut it down due to 3200 character posting limit.

[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-user-callerid,s,15)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/Incoming9009-00000350", "0?continue") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:16] ExecIf("SIP/Incoming9009-00000350", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:17] Set("SIP/Incoming9009-00000350", "__TTL=6") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:18] GotoIf("SIP/Incoming9009-00000350", "1?continue") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-user-callerid,s,29)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/Incoming9009-00000350", "CALLERID(number)=5155551234") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/Incoming9009-00000350", "CALLERID(name)=WIRELESS CALLER") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:31] GotoIf("SIP/Incoming9009-00000350", "0?cnum") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/Incoming9009-00000350", "CDR(cnam)=WIRELESS CALLER") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/Incoming9009-00000350", "CDR(cnum)=5155551234") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-user-callerid:34] Set("SIP/Incoming9009-00000350", "CHANNEL(language)=en") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:2] Set("SIP/Incoming9009-00000350", "RingGroupMethod=none") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:3] Set("SIP/Incoming9009-00000350", "__EXTTOCALL=9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:4] Set("SIP/Incoming9009-00000350", "__PICKUPMARK=9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:5] Set("SIP/Incoming9009-00000350", "RT=20") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:6] ExecIf("SIP/Incoming9009-00000350", "0?Macro(vm,9008,DIRECTDIAL,)") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:7] ExecIf("SIP/Incoming9009-00000350", "0?MacroExit()") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:8] ExecIf("SIP/Incoming9009-00000350", "0?Gosub(ext-intercom,*809008,1())") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:9] ExecIf("SIP/Incoming9009-00000350", "0?MacroExit()") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] WARNING[30603][C-000001e8] pbx.c: Can't find trailing parenthesis for function 'DB(DEVICE/9008/dial'?
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:10] ExecIf("SIP/Incoming9009-00000350", "0?ChanSpy(SIP/9008,q)") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] WARNING[30603][C-000001e8] pbx.c: Can't find trailing parenthesis for function 'DB(DEVICE/9008/dial'?
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:11] ExecIf("SIP/Incoming9009-00000350", "0?MacroExit()") in new stack
[2017-08-22 12:32:26] ERROR[30603][C-000001e8] pbx.c: Function PJSIP_HEADER not registered
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:12] Gosub("SIP/Incoming9009-00000350", "sub-record-check,s,1(exten,9008,dontcare)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/Incoming9009-00000350", "10?initialized") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (sub-record-check,s,10)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/Incoming9009-00000350", "Recordings initialized") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/Incoming9009-00000350", "0?Set(ARG3=dontcare)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/Incoming9009-00000350", "REC_POLICY_MODE_SAVE=FORCE") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/Incoming9009-00000350", "0?Set(REC_STATUS=NO)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/Incoming9009-00000350", "5?checkaction") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (sub-record-check,s,17)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/Incoming9009-00000350", "1?sub-record-check,exten,1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (sub-record-check,exten,1)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:1] NoOp("SIP/Incoming9009-00000350", "Exten Recording Check between 5155551234 and 9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:2] Set("SIP/Incoming9009-00000350", "CALLTYPE=external") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:3] ExecIf("SIP/Incoming9009-00000350", "0?Set(CALLTYPE=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:4] Set("SIP/Incoming9009-00000350", "CALLEE=force") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:5] ExecIf("SIP/Incoming9009-00000350", "0?Set(CALLEE=dontcare)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:6] GotoIf("SIP/Incoming9009-00000350", "1?callee") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (sub-record-check,exten,11)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:11] Gosub("SIP/Incoming9009-00000350", "recordcheck,1(force,external,9008)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/Incoming9009-00000350", "Starting recording check against force") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/Incoming9009-00000350", "force") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (sub-record-check,recordcheck,5)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [recordcheck@sub-record-check:5] Set("SIP/Incoming9009-00000350", "__REC_POLICY_MODE=FORCE") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [recordcheck@sub-record-check:6] GotoIf("SIP/Incoming9009-00000350", "0?startrec") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [recordcheck@sub-record-check:7] Return("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [exten@sub-record-check:12] Return("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:13] GotoIf("SIP/Incoming9009-00000350", "1?macrodial") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-exten-vm,s,19)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:19] GosubIf("SIP/Incoming9009-00000350", "0?clrheader,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-exten-vm:20] Macro("SIP/Incoming9009-00000350", "dial-one,20,Ttr,9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:1] Set("SIP/Incoming9009-00000350", "DEXTEN=9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:2] Set("SIP/Incoming9009-00000350", "__CRM_SOURCE=5155551234") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:3] ExecIf("SIP/Incoming9009-00000350", "0?Set(EXTTOCALL=9008)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:4] Set("SIP/Incoming9009-00000350", "DIALSTATUS_CW=") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:5] GosubIf("SIP/Incoming9009-00000350", "0?screen,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:6] GosubIf("SIP/Incoming9009-00000350", "0?cf,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:7] GotoIf("SIP/Incoming9009-00000350", "1?skip1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,s,10)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:10] GotoIf("SIP/Incoming9009-00000350", "0?nodial") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("SIP/Incoming9009-00000350", "0?continue") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:12] Set("SIP/Incoming9009-00000350", "EXTHASCW=ENABLED") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:13] GotoIf("SIP/Incoming9009-00000350", "0?next1:cwinusebusy") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,s,25)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("SIP/Incoming9009-00000350", "0?next3:continue") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,s,27)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/Incoming9009-00000350", "0?nodial") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:28] GosubIf("SIP/Incoming9009-00000350", "1?dstring,1():dlocal,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("SIP/Incoming9009-00000350", "DSTRING=") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("SIP/Incoming9009-00000350", "DEVICES=9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/Incoming9009-00000350", "0?Return()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/Incoming9009-00000350", "0?Set(DEVICES=008)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("SIP/Incoming9009-00000350", "LOOPCNT=1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("SIP/Incoming9009-00000350", "ITER=1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("SIP/Incoming9009-00000350", "THISDIAL=SIP/9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/Incoming9009-00000350", "1?zap2dahdi,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/Incoming9009-00000350", "0?Return()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/Incoming9009-00000350", "NEWDIAL=") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/Incoming9009-00000350", "LOOPCNT2=1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/Incoming9009-00000350", "ITER2=1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/Incoming9009-00000350", "THISPART2=SIP/9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/Incoming9009-00000350", "0?Set(THISPART2=DAHDI/9008)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/Incoming9009-00000350", "NEWDIAL=SIP/9008&") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/Incoming9009-00000350", "ITER2=2") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/Incoming9009-00000350", "0?begin2") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/Incoming9009-00000350", "THISDIAL=SIP/9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:9] GotoIf("SIP/Incoming9009-00000350", "1?docheck") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,dstring,14)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:14] GotoIf("SIP/Incoming9009-00000350", "0?skipset") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:15] Set("SIP/Incoming9009-00000350", "DSTRING=SIP/9008&") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:16] Set("SIP/Incoming9009-00000350", "ITER=2") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:17] GotoIf("SIP/Incoming9009-00000350", "0?begin") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:18] ExecIf("SIP/Incoming9009-00000350", "0?Return()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:19] Set("SIP/Incoming9009-00000350", "DSTRING=SIP/9008") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [dstring@macro-dial-one:20] Return("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:29] GotoIf("SIP/Incoming9009-00000350", "0?nodial") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:30] GotoIf("SIP/Incoming9009-00000350", "0?skiptrace") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:31] GosubIf("SIP/Incoming9009-00000350", "1?ctset,1():ctclear,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("SIP/Incoming9009-00000350", "DB(CALLTRACE/9008)=5155551234") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:32] Set("SIP/Incoming9009-00000350", "D_OPTIONS=Ttr") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:33] NoOp("SIP/Incoming9009-00000350", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:34] ExecIf("SIP/Incoming9009-00000350", "0?Set(ALERT_INFO=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:35] ExecIf("SIP/Incoming9009-00000350", "0?Set(ALERT_INFO=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:36] ExecIf("SIP/Incoming9009-00000350", "0?Set(ALERT_INFO=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:37] ExecIf("SIP/Incoming9009-00000350", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:38] ExecIf("SIP/Incoming9009-00000350", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:39] GosubIf("SIP/Incoming9009-00000350", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:40] ExecIf("SIP/Incoming9009-00000350", "0?Set(CHANNEL(musicclass)=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:41] GosubIf("SIP/Incoming9009-00000350", "0?qwait,1()") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:42] Set("SIP/Incoming9009-00000350", "__CWIGNORE=") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:43] Set("SIP/Incoming9009-00000350", "__KEEPCID=TRUE") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:44] GotoIf("SIP/Incoming9009-00000350", "0?usegoto,1") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:45] GotoIf("SIP/Incoming9009-00000350", "1?godial") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,s,50)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:50] Macro("SIP/Incoming9009-00000350", "dialout-one-predial-hook,") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dialout-one-predial-hook:1] MacroExit("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:51] ExecIf("SIP/Incoming9009-00000350", "1?Set(D_OPTIONS=trI)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:52] GotoIf("SIP/Incoming9009-00000350", "1?zulunourl") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,s,54)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:54] ExecIf("SIP/Incoming9009-00000350", "0?Set(ZULU_TYPE=)") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:55] GotoIf("SIP/Incoming9009-00000350", "1?skippopup") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-dial-one,s,62)
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:62] UserEvent("SIP/Incoming9009-00000350", "zulu-call,eventtype:calling,extension:9008,type:,url:,cnam:WIRELESS CALLER,cnum:5155551234,lid:1503423141.1187") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:63] NoOp("SIP/Incoming9009-00000350", "Zulu Finished") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:64] NoOp("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:26] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-dial-one:65] Dial("SIP/Incoming9009-00000350", "SIP/9008,20,trIb(func-apply-sipheaders^s^1)") in new stack
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] netsock2.c: == Using SIP RTP TOS bits 184
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] netsock2.c: == Using SIP RTP CoS mark 5
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_stack.c: -- SIP/9008-00000351 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@func-apply-sipheaders:1] ExecIf("SIP/9008-00000351", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@func-apply-sipheaders:2] NoOp("SIP/9008-00000351", "Applying SIP Headers to channel") in new stack
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@func-apply-sipheaders:3] Set("SIP/9008-00000351", "SIPHEADERKEYS=") in new stack
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@func-apply-sipheaders:4] While("SIP/9008-00000351", "0") in new stack
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_while.c: -- Jumping to priority 7
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@func-apply-sipheaders:8] Return("SIP/9008-00000351", "") in new stack
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_stack.c: == Spawn extension (from-internal, 9008, 1) exited non-zero on 'SIP/9008-00000351'
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_stack.c: -- SIP/9008-00000351 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_dial.c: -- Called SIP/9008
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_dial.c: -- Connected line update to SIP/Incoming9009-00000350 prevented.
[2017-08-22 12:32:27] VERBOSE[30603][C-000001e8] app_dial.c: -- SIP/9008-00000351 is ringing
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_stack.c: -- SIP/9008-00000351 Internal Gosub(crm-hangup,s,1) start
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:1] NoOp("SIP/9008-00000351", "Sending Hangup to CRM") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:2] NoOp("SIP/9008-00000351", "HANGUP CAUSE: 16") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:3] ExecIf("SIP/9008-00000351", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:4] NoOp("SIP/9008-00000351", "MASTER CHANNEL: 1503423147.1188 = 1503423141.1187") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:5] GotoIf("SIP/9008-00000351", "1?return") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (crm-hangup,s,8)
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:8] Return("SIP/9008-00000351", "") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_stack.c: == Spawn extension (from-internal, 9008, 1) exited non-zero on 'SIP/9008-00000351'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_stack.c: -- SIP/9008-00000351 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_macro.c: == Spawn extension (macro-dial-one, s, 65) exited non-zero on 'SIP/Incoming9009-00000350' in macro 'dial-one'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_macro.c: == Spawn extension (macro-exten-vm, s, 20) exited non-zero on 'SIP/Incoming9009-00000350' in macro 'exten-vm'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: == Spawn extension (ext-local, 9008, 2) exited non-zero on 'SIP/Incoming9009-00000350'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [h@ext-local:1] Macro("SIP/Incoming9009-00000350", "hangupcall,") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-hangupcall:1] ExecIf("SIP/Incoming9009-00000350", "0?Set(CDR(recordingfile)=in-5159789008-5155551234-20170822-123221-1503423141.1187.wav)") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-hangupcall:2] GotoIf("SIP/Incoming9009-00000350", "1?theend") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Goto (macro-hangupcall,s,4)
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-hangupcall:4] ExecIf("SIP/Incoming9009-00000350", "0?Set(CDR(recordingfile)=)") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@macro-hangupcall:5] Hangup("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_macro.c: == Spawn extension (macro-hangupcall, s, 5) exited non-zero on 'SIP/Incoming9009-00000350' in macro 'hangupcall'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: == Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/Incoming9009-00000350'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_stack.c: -- SIP/Incoming9009-00000350 Internal Gosub(crm-hangup,s,1) start
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:1] NoOp("SIP/Incoming9009-00000350", "Sending Hangup to CRM") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:2] NoOp("SIP/Incoming9009-00000350", "HANGUP CAUSE: 16") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:3] ExecIf("SIP/Incoming9009-00000350", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:4] NoOp("SIP/Incoming9009-00000350", "MASTER CHANNEL: 1503423141.1187 = 1503423141.1187") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:5] GotoIf("SIP/Incoming9009-00000350", "0?return") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:6] Set("SIP/Incoming9009-00000350", "__CRM_HANGUP=1") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:7] AGI("SIP/Incoming9009-00000350", "sangomacrm.agi") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] res_agi.c: -- <SIP/Incoming9009-00000350>AGI Script sangomacrm.agi completed, returning 0
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] pbx.c: -- Executing [s@crm-hangup:8] Return("SIP/Incoming9009-00000350", "") in new stack
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_stack.c: == Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/Incoming9009-00000350'
[2017-08-22 12:32:30] VERBOSE[30603][C-000001e8] app_stack.c: -- SIP/Incoming9009-00000350 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2017-08-22 12:32:30] VERBOSE[30606][C-000001e8] app_mixmonitor.c: == MixMonitor close filestream (mixed)
[2017-08-22 12:32:30] VERBOSE[30606][C-000001e8] app_mixmonitor.c: == End MixMonitor Recording SIP/Incoming9009-00000350
8

Wrong log files. We need the zulu logs.

/var/log/asterisk/zulu_*

9

My bad (again). Here is the results of /var/log/asterisk/Zulu_out.log after a call

2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:12.391] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:12.391] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503431287}}'
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:12.398] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:12.398] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:12.602] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getfaxes', data: { timestamp: 1503431287 } } { status: false }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:12.604] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getsms', data: { id: 0 } } { status: false }
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:17.407] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:17.407] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503431292}}'
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:17.414] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:17.415] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:17.617] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getfaxes', data: { timestamp: 1503431292 } } { status: false }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:17.625] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getsms', data: { id: 0 } } { status: false }
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:19.263] [TRACE] [default] - ^[[39mReceived call from Zulu
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:19.264] [DEBUG] [default] - ^[[39m{ event: 'UserEvent',
  privilege: 'user,all',
  userevent: 'zulu-call',
  uniqueid: '1503431293.1233',
  'eventtype:calling': '',
  'extension:9008': '',
  'type:': '',
  'url:': '',
  'cnam:wireless caller': '',
  'cnum:5155551234': '',
  'lid:1503431293.1233': '' }
2017-08-22 14:48 -05:00: ^[[31m[2017-08-22 14:48:19.267] [ERROR] console - ^[[39mTypeError: must start with number, buffer, array or string
    at new Buffer (buffer.js:67:11)
    at EventEmitter.<anonymous> (/var/www/html/admin/modules/zulu/node/index.js:2:1371)
    at EventEmitter.emit (events.js:107:17)
    at process._tickDomainCallback (node.js:381:11)
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:19.628] [TRACE] [default] - ^[[39mEntering Startup
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:19.631] [INFO] [default] - ^[[39mStarting Zulu 13.0.53.2...
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:19.633] [TRACE] [default] - ^[[39mEntering Bootstrap
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:19.679] [TRACE] [default] - ^[[39mEntering Connect2Database
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:19.685] [DEBUG] [default] - ^[[39mConnected to Databse
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:19.706] [TRACE] [default] - ^[[39mEntering Connect2AstMan
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:19.709] [INFO] [default] - ^[[39mConnected to Asterisk
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:19.710] [INFO] [default] - ^[[39mFreePBX is Ready!
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:19.820] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:19.821] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getstartingids"}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:19.838] [DEBUG] [default] - ^[[39mTue Aug 22 2017 14:48:19 GMT-0500 (CDT) Client Server is listening on 0.0.0.0 on port 8002
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:19.839] [INFO] console - ^[[39mTue Aug 22 2017 14:48:19 GMT-0500 (CDT) Command Server is listening on localhost on port 7999
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.029] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getstartingids' } { status: true, data: { fax: '1503335845994', sms: 0 } }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.032] [DEBUG] [default] - ^[[39mStarting IDs:{"status":true,"data":{"fax":"1503335845994","sms":0}}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.325] [DEBUG] [default] - ^[[39m192.168.1.1 [raWcV3eKBjros8VPak79Jw==] connected
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.343] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"login","data":{"username":"bphillips","plaintext":"OBFUSCATED","lastconnected":1503423099,"c$
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:20.343] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.344] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{login-event-obfuscation}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.539] [DEBUG] [default] - ^[[39mResponse from processor: {login-event-obfuscation} { status: true,
  data:
   { id: '8',
     auth: '1',
     authid: null,
     username: 'bxxxxxxx',
     description: 'Autogenerated token on installation',
     password: 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx',
     default_extension: 'xxxx',
     primary_group: null,
     fname: 'xxx',
     lname: 'xxxxxxx',
     displayname: 'xxxx xxxxxxx',
     title: '',
     company: '',
     department: '',
     email: '',
     cell: '5155551234',
     work: '',
     home: '',
     fax: '',
     permissions: null,
     image: true,
     xmpp: '' } }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.547] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"type":"auth","message":"authenticated","version":"13.0.53.2","token":"93beeb36-7765-43ce$
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.553] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"pull","type":"config","id":75380}
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:20.553] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.553] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"config","data":{"uid":"8"}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.564] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"pull","type":"smsdids","id":86508}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.566] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"pull","type":"presence","id":86572}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.568] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"pull","type":"presencestates","id":37877}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.569] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":86572,"type":"available"}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.614] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":86508,"dids":[]}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.617] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":37877,"states":[{"id":"1","type":"available","message":""},{"id":"2","type":"c$
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.620] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"subscribe","type":"presence","id":43}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.621] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":43}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.799] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'config', data: { uid: '8' } } { status: true,
  uid: '8',
  data:
   { apps: [ 'fax', 'chat', 'contacts', 'call' ],
appdata: { fax: [Object] } } }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.801] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":75380,"brand":"FreePBX","user":{"id":"8","auth":"1","authid":null,"username":"$
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.806] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"subscribe","type":"call","id":80009}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.806] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":80009}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.806] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"subscribe","type":"fax","id":3510}
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:20.807] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.807] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503423099,"user":"8"}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.814] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"status":true,"actionid":3510}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.815] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"command":"pull","type":"contacts","userId":"8","id":92669}
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:20.816] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:20.816] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getcontacts","userId":"8"}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:21.025] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getfaxes',
  data: { timestamp: 1503423099, user: '8' } } { status: false }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:21.061] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getcontacts', userId: '8' } [ { uid: '12',

[LIST OF CONTACTS REDACTED]

    id: '115' } ]
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:21.104] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [raWcV3eKBjros8VPak79Jw==]:{"actionid":92669,"contacts":[{"uid":"12","groupid":"5","user":"1","displayname":"Operator","fname":"","$
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:25.033] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:25.033] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503431300}}'
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:25.041] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:25.042] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:25.246] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getfaxes', data: { timestamp: 1503431300 } } { status: false }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:25.251] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getsms', data: { id: 0 } } { status: false }
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:30.052] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:30.052] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503431305}}'
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:30.060] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:30.060] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:30.265] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getfaxes', data: { timestamp: 1503431305 } } { status: false }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:30.271] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getsms', data: { id: 0 } } { status: false }
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:32.568] [TRACE] [default] - ^[[39mReceived call from Zulu
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:32.568] [DEBUG] [default] - ^[[39m{ event: 'UserEvent',
  privilege: 'user,all',
  userevent: 'zulu-call',
  uniqueid: '1503431306.1235',
  'eventtype:calling': '',
  'extension:9008': '',
  'type:': '',
  'url:': '',
  'cnam:wireless caller': '',
  'cnum:5155551234': '',
  'lid:1503431306.1235': '' }
2017-08-22 14:48 -05:00: ^[[31m[2017-08-22 14:48:32.571] [ERROR] console - ^[[39mTypeError: must start with number, buffer, array or string
    at new Buffer (buffer.js:67:11)
    at EventEmitter.<anonymous> (/var/www/html/admin/modules/zulu/node/index.js:2:1371)
    at EventEmitter.emit (events.js:107:17)
    at process._tickDomainCallback (node.js:381:11)
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:32.857] [TRACE] [default] - ^[[39mEntering Startup
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:32.861] [INFO] [default] - ^[[39mStarting Zulu 13.0.53.2...
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:32.863] [TRACE] [default] - ^[[39mEntering Bootstrap
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:32.937] [TRACE] [default] - ^[[39mEntering Connect2Database
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:32.945] [DEBUG] [default] - ^[[39mConnected to Databse
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:32.970] [TRACE] [default] - ^[[39mEntering Connect2AstMan
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:32.973] [INFO] [default] - ^[[39mConnected to Asterisk
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:32.975] [INFO] [default] - ^[[39mFreePBX is Ready!
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:33.064] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.065] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"getstartingids"}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.083] [DEBUG] [default] - ^[[39mTue Aug 22 2017 14:48:33 GMT-0500 (CDT) Client Server is listening on 0.0.0.0 on port 8002
2017-08-22 14:48 -05:00: ^[[32m[2017-08-22 14:48:33.085] [INFO] console - ^[[39mTue Aug 22 2017 14:48:33 GMT-0500 (CDT) Command Server is listening on localhost on port 7999
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.263] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'getstartingids' } { status: true, data: { fax: '1503335845994', sms: 0 } }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.266] [DEBUG] [default] - ^[[39mStarting IDs:{"status":true,"data":{"fax":"1503335845994","sms":0}}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.644] [DEBUG] [default] - ^[[39m192.168.1.1 [su3bSJbAx1fDQUZfEeschw==] connected
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.673] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"command":"login","data":{"username":"bphillips","plaintext":"OBFUSCATED","lastconnected":1503423099,"c$
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:33.673] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.673] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{login-event-obfuscation}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.871] [DEBUG] [default] - ^[[39mResponse from processor: {login-event-obfuscation} { status: true,
  data:
   { id: '8',
     auth: '1',
     authid: null,
     username: 'xxxxxx',
     description: 'Autogenerated token on installation',
     password: 'xxxxxxxxxxxxxxxxxxxxxxxxxxxx',
     default_extension: 'xxx',
     primary_group: null,
     fname: '',
     lname: '',
     displayname: '',
     title: '',
     company: '',
     department: '',
     email: '',
     cell: '5155551234',
     work: '',
     home: '',
     fax: '',
     permissions: null,
     image: true,
     xmpp: '' } }
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.874] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"status":true,"type":"auth","message":"authenticated","version":"13.0.53.2","token":"56f5c042-4c92-4835$
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.880] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"command":"pull","type":"config","id":86234}
2017-08-22 14:48 -05:00: ^[[34m[2017-08-22 14:48:33.880] [TRACE] [default] - ^[[39mExecuting Processor
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.881] [DEBUG] [default] - ^[[39m/var/www/html/admin/modules/zulu/node/../processor '{"command":"config","data":{"uid":"8"}}'
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.902] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"command":"pull","type":"smsdids","id":83308}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.903] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"command":"pull","type":"presence","id":16361}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.905] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"command":"pull","type":"presencestates","id":23052}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.908] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"status":true,"actionid":16361,"type":"available"}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.950] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"status":true,"actionid":83308,"dids":[]}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.952] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"status":true,"actionid":23052,"states":[{"id":"1","type":"available","message":""},{"id":"2","type":"c$
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.956] [DEBUG] [default] - ^[[39m=> 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"command":"subscribe","type":"presence","id":94794}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:33.956] [DEBUG] [default] - ^[[39m<= 192.168.1.1 [su3bSJbAx1fDQUZfEeschw==]:{"status":true,"actionid":94794}
2017-08-22 14:48 -05:00: ^[[36m[2017-08-22 14:48:34.226] [DEBUG] [default] - ^[[39mResponse from processor: { command: 'config', data: { uid: '8' } } { status: true,
  uid: '8',
  data:
   { apps: [ 'fax', 'chat', 'contacts', 'call' ],
     appdata: { fax: [Object] } } }
10

Ok I would look in the zulu_err.log Im sorry I should have been way more clear about this from the beginning but it seems like your zulu server is crashing.

11

My Zulu_err.log file is empty. Not sure if this helps, this is the screen I’m seeing when a call comes in. My desk phone rings, Zulu flashes to this screen for about a second then back to normal. The Zulu app never “rings” and I can not pick up the call on it.

1.jpg799×710 24.6 KB

12

The zulu server is crashing

fwconsole pm2 --log zulu

and simulate the same thing. See what zulu says.

13

Here is my output

[root@localhost ~]# fwconsole pm2 --log zulu
OUT > ==> /var/log/asterisk/zulu_err.log <==

==> /var/log/asterisk/zulu_out.log <==
2017-08-22 18:01 -05:00: [2017-08-22 18:01:14.528] [TRACE] [default] - Executing Processor
2017-08-22 18:01 -05:00: [2017-08-22 18:01:14.529] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
2017-08-22 18:01 -05:00: [2017-08-22 18:01:14.732] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442869 } } { status: false }
2017-08-22 18:01 -05:00: [2017-08-22 18:01:14.736] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
2017-08-22 18:01 -05:00: [2017-08-22 18:01:19.540] [TRACE] [default] - Executing Processor
[2017-08-22 18:01:19.540] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442874}}'
2017-08-22 18:01 -05:00: [2017-08-22 18:01:19.551] [TRACE] [default] - Executing Processor
[2017-08-22 18:01:19.551] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
2017-08-22 18:01 -05:00: [2017-08-22 18:01:19.777] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442874 } } { status: false }
2017-08-22 18:01 -05:00: [2017-08-22 18:01:19.852] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:24.563] [TRACE] [default] - Executing Processor
2017-08-22 18:01 -05:00: [2017-08-22 18:01:24.563] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442879}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:24.572] [TRACE] [default] - Executing Processor
[2017-08-22 18:01:24.572] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:24.780] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442879 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:24.782] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:29.584] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:29.584] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442884}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:29.595] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:29.595] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:29.811] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:29.820] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442884 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:34.608] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:34.608] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442889}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:34.616] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:34.617] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:34.816] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442889 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:34.825] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:39.629] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:39.629] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442894}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:39.640] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:39.642] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:39.841] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442894 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:39.848] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:44.653] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:44.653] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442899}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:44.662] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:44.663] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:44.866] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442899 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:44.872] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:49.674] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:49.674] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442904}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:49.683] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:49.684] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:49.925] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:49.961] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442904 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:54.695] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:54.695] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503442909}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:54.704] [TRACE] [default] - Executing Processor
[2017-08-22 18:01:54.704] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getsms","data":{"id":0}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:54.911] [DEBUG] [default] - Response from processor: { command: 'getfaxes', data: { timestamp: 1503442909 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:54.922] [DEBUG] [default] - Response from processor: { command: 'getsms', data: { id: 0 } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:55.367] [TRACE] [default] - Received call from Zulu
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:55.367] [DEBUG] [default] - { event: 'UserEvent',
  privilege: 'user,all',
  userevent: 'zulu-call',
  uniqueid: '1503442909.1324',
  'eventtype:calling': '',
  'extension:9008': '',
  'type:': '',
  'url:': '',
  'cnam:wireless caller': '',
  'cnum:5155551234': '',
  'lid:1503442909.1324': '' }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:55.372] [ERROR] console - TypeError: must start with number, buffer, array or string
    at new Buffer (buffer.js:67:11)
    at EventEmitter.<anonymous> (/var/www/html/admin/modules/zulu/node/index.js:2:1371)
    at EventEmitter.emit (events.js:107:17)
    at process._tickDomainCallback (node.js:381:11)
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.077] [TRACE] [default] - Entering Startup
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.081] [INFO] [default] - Starting Zulu 13.0.53.2...
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.082] [TRACE] [default] - Entering Bootstrap
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.126] [TRACE] [default] - Entering Connect2Database
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.132] [DEBUG] [default] - Connected to Databse
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.164] [TRACE] [default] - Entering Connect2AstMan
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.167] [INFO] [default] - Connected to Asterisk
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.168] [INFO] [default] - FreePBX is Ready!
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.303] [TRACE] [default] - Executing Processor
2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.303] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getstartingids"}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.313] [DEBUG] [default] - Tue Aug 22 2017 18:01:56 GMT-0500 (CDT) Client Server is listening on 0.0.0.0 on port 8002
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.315] [INFO] console - Tue Aug 22 2017 18:01:56 GMT-0500 (CDT) Command Server is listening on localhost on port 7999
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.480] [DEBUG] [default] - 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==] connected
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.484] [DEBUG] [default] - Response from processor: { command: 'getstartingids' } { status: true, data: { fax: '1503335845994', sms: 0 } }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.486] [DEBUG] [default] - Starting IDs:{"status":true,"data":{"fax":"1503335845994","sms":0}}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.507] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"login","data":{"username":"bphillips","plaintext":"OBFUSCATED","lastconnected":1503423099,"clientversion":"2.0.27"}}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.507] [TRACE] [default] - Executing Processor
[2017-08-22 18:01:56.507] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{login-event-obfuscation}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.698] [DEBUG] [default] - Response from processor: {login-event-obfuscation} { status: true,
  data: 
   { id: '8',
     auth: '1',
     authid: null,
     username: 'xxxxxx',
     description: 'Autogenerated token on installation',
     password: 'xxxxxxxxxxxxxxxxxxxxxxxxx',
     default_extension: '9008',
     primary_group: null,
     fname: '',
     lname: '',
     displayname: '',
     title: '',
     company: '',
     department: '',
     email: '',
     cell: '5155551234',
     work: '',
     home: '',
     fax: '',
     permissions: null,
     image: true,
     xmpp: 'm' } }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.700] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"type":"auth","message":"authenticated","version":"13.0.53.2","token":"5a59db7e-f656-454a-af67-35689efb98e4"}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.706] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"pull","type":"config","id":39886}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.707] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.712] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"config","data":{"uid":"8"}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.717] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"pull","type":"smsdids","id":10706}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.719] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"pull","type":"presence","id":23724}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.722] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"pull","type":"presencestates","id":86088}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.726] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":23724,"type":"available"}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.755] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":10706,"dids":[]}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.757] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":86088,"states":[{"id":"1","type":"available","message":""},{"id":"2","type":"chat","message":""},{"id":"3","type":"away","message":""},{"id":"4","type":"dnd","message":""},{"id":"5","type":"xa","message":""},{"id":"6","type":"unavailable","message":""}]}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.761] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"subscribe","type":"presence","id":69726}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:56.763] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":69726}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.052] [DEBUG] [default] - Response from processor: { command: 'config', data: { uid: '8' } } { status: true,
  uid: '8',
  data: 
   { apps: [ 'fax', 'chat', 'contacts', 'call' ],
     appdata: { fax: [Object] } } }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.055] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":39886,"brand":"FreePBX","user":{"id":"8","auth":"1","authid":null,"username":"bphillips","description":"Autogenerated token on installation","password":"c895ddac622b50b74f7cf8a701ff8fa36b079420","default_extension":"9008","primary_group":null,"fname":"Brad","lname":"Phillips","displayname":"Brad Phillips","title":"Managing Partner","company":"Phillips Stafford Insurance Group","department":"","email":"[email protected]","cell":"5155551234","work":"5159789008","home":"","fax":"8886703251","permissions":null,"image":true,"xmpp":"[email protected]"},"apps":["fax","chat","contacts","call"],"appdata":{"fax":{"version":"13.0.36","stationid":"8886703251","header":"Phillips Stafford Insurance Group","covername":"Brad Phillips","covertel":"5159789008","coveremail":"[email protected]"}},"version":"13.0.53.2"}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.059] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"subscribe","type":"call","id":36866}
2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.059] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":36866}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.060] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"subscribe","type":"fax","id":81454}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.061] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.061] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getfaxes","data":{"timestamp":1503423099,"user":"8"}}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.065] [DEBUG] [default] - <= 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"status":true,"actionid":81454}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.067] [DEBUG] [default] - => 192.168.1.1 [PWjhSaPPF9SSi7TxIkMdyw==]:{"command":"pull","type":"contacts","userId":"8","id":99294}
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.067] [TRACE] [default] - Executing Processor
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.068] [DEBUG] [default] - /var/www/html/admin/modules/zulu/node/../processor '{"command":"getcontacts","userId":"8"}'
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.265] [DEBUG] [default] - Response from processor: { command: 'getfaxes',
  data: { timestamp: 1503423099, user: '8' } } { status: false }
OUT > 2017-08-22 18:01 -05:00: [2017-08-22 18:01:57.310] [DEBUG] [default] - Response from processor: { command: 'getcontacts', userId: '8' } [ { uid: '12',
14

What version of Asterisk is this as something is very very wrong with the events coming from Asterisk.

EG this event from Asterisk is 100% broken.

{ event: 'UserEvent',
  privilege: 'user,all',
  userevent: 'zulu-call',
  uniqueid: '1503442909.1324',
  'eventtype:calling': '',
  'extension:9008': '',
  'type:': '',
  'url:': '',
  'cnam:wireless caller': '',
  'cnum:5155551234': '',
  'lid:1503442909.1324': '' }
15

I’m running Asterisk 11.25.1 with FreePBX 13.0.192.16

16

Please use Asterisk 13. We will try to make this more clear but Sangoma no longer supports Asterisk 11 (though yes FreePBX 14 allows it)

17

Thanks, that solved the issue. I thought I was on 13 but obviously not.

1 Like