Intermittent Audio Drop-Outs (and maybe dropped calls)

dmcoopknx · October 25, 2010, 12:09am

Using the following version:

PBX in a Flash Version : 1.7.5.5
FreePBX Version : 2.6.0.2
Running Asterisk Version : Asterisk 1.4.33
Asterisk Source Version : 1.4.33
Dahdi Source Version : 2.3.0.1+2.3.0
Libpri Source Version : 1.4.11.3
Addons Source Version : 1.4.11

With the following physical configuration:

SIP Trunk Provided by Windstream <–> My EdgePBX <–> Three Internal PBXs trunked to the EdgePBX via IAX2 trunks.

All calls in/out from the three internal PBXs flow through the EdgePBX. No end-user devices are configured to the EdgePBX. Internal PBXs call each other through EdgePBX - no ext to ext dialing - must dial full 7 digit phone number.

We have about 30 phones/ATAs total. Two PBXs are loaded lightly with just a few devices each. The third PBX has 22 devices on it. The phones are Cisco SPA504G for deskphones and Snom M3 for wireless. There are three Linksys ATAs (one on each PBX).

As far as we can tell we have zero problems with faxing (surprise).

For the most part it works well. However at least once per day there are a couple of audio fades/drop-outs and/or a dropped call or two or three. I am still trying to figure out if the calls are really dropped or if the caller is giving up and hanging up the phone (because they assume it was dropped) during an audio drop-out.

Here are the current symptoms:

*The calls are to/from landline as well as mobile phones (so we can’t blame AT&T mobile).
*It does not seem to matter if it is an inbound or an outbound call.
*It does seem that the inside caller is the only one that notices it - outside folks have not reported having a problem.
*Sometimes the drop-out last a few seconds and as long as 20 seconds.
*Sometimes there is a small amount of audio static/crackle at the beginning of the event or at the end but not always.
*So far users of the virtual PBXs have not reported any issues - but I personally think this is a function of call volume.

Troubleshooting steps we have taken so far:

*Segregated VoIP completely from data network physically. It now has its own physical network. This helped a lot - problem went from dozen times a day to a couple.
*Replaced every network switch and fiber transceiver in the network.
*Moved all three internal PBXs and the EdgePBX (as well as all phones/ATAs) into the same subnet.
*Configured QoS on network.

This is a multi-tenant situation so having all the PBXs in the same subnet is less than ideal but I am willing to do it for the short time till we figure out what is causing it.

Right now none of the original switches or routers are in this network.

The EdgePBX is running on IBM server. Two internal PBXs (light duty ones) are virtualized on VMware ESX server. One internal PBX (one with 22 devices) is a physical Lenovo server. When I say server here I mean honest to goodness real servers - not a glorified PC or workstation. They are both rackmount and both have Intel Xeon processors. EdgePBX has 4GB of RAM. Internals all have 2GB. The VMware host is also on an IBM server with lots of RAM. VMware tools is installed on the ESX guest machines. The VMware ESX host is a high performance machine design for high IOPs

Any ideas of where/how to start troubleshooting this?

Just to be clear - I am a complete newb to all this VoIP stuff. I first started working with FreePBX about 6 months ago. So please don’t assume I will know what you are talking about - I’ll take no offense if you talk to me like a 3rd grader. I have been an IT tech for 15+ years but none of my experience has been with VoIP and very little with Linux. I estimate I know 3% of what you guys do about FreePBX and 5% of Linux – so please be gentle.

Thanks so much for help and advice.

dmcoopknx · November 18, 2010, 6:17pm

After wasting weeks working with Windstream support on the issues I swapped over to bandwidth.com as a test a couple of weeks ago. The problem went away immediately. Windstream is still working on it (cause we still have the circuit) but here we are 2 weeks later and they still can’t find the problem and bandwidth.com works nearly perfectly.

There have been a few small issues with bandwidth.com but for the most part it works well. I am expecting that this is now solved and will be canceling my Windstream service in a few days.

dmcoopknx · October 27, 2010, 6:12pm

Windstream installed a different router and a Packet Island on site yesterday and the problems are still happening. Tech said he sees no issues being caught by the Packet Island. Since we are down to the wire on this I just ordered a SIP trunk from SIPSTATION.com with one DID and five call paths. So far so good. We have been using it for almost 2 hours now and no issues … developing …

On another note a Windstream guy called me a little while ago and said that on my PBX I need to set “Voice Tailored = 101”. He said it is sometimes called “DTMF Tailored”. Does anyone know what he is talking about? I have looked through the FreePBX GUI and can’t find it and have no joy in using Google either to figure out what it might be.

Thanks all for you input and help.

dmcoopknx · October 25, 2010, 9:05pm

The Juniper is an SSG 140. We have a metro-e - 100mb loop.

I plan on replacing the Comcast portion with internet from our data center.

At this time no SIP/IAX2 goes through that side of the drawing anyway.

dmcoopknx · October 25, 2010, 9:18pm

… I just discovered the ‘reply’ link.

The line speed for Windstream SIP is a full T1 from them. They say it goes directly into their SIP cloud (QoS) the whole way.

Info about the SSG is below in another post.

dmcoopknx · October 25, 2010, 11:59pm

A friend hooked me up with a guy that manages all the Asterisk deployments for a large trucking company. Some of you Asterisk dev folks may know him (cause he says he knows some of you) but since I did not ask his permission to include his name here I won’t.

Tonight he found two config issues with my EdgePBX that he is hopeful will solve the problem. One was an issue with the routing table on the EdgePBX. The other was under Asterisk SIP settings in FreePBX GUI.

We are going to see how tomorrow goes and work from there.

I will post back final fixes when he figures it out.

dmcoopknx · October 25, 2010, 8:53pm

[2010-10-25 08:24:44] VERBOSE[3426] logger.c: – Accepting AUTHENTICATED call from 10.10.8.2:
> requested format = ulaw,
> requested prefs = (ulaw|alaw|gsm),
> actual format = ulaw,
> host prefs = (ulaw|alaw|gsm),
> priority = mine
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [4145676@from-internal:1] Macro(“IAX2/johnson-6325”, “user-callerid|SKIPTTL|”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:1] Set(“IAX2/johnson-6325”, “AMPUSER=8652432221”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“IAX2/johnson-6325”, “0?report”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“IAX2/johnson-6325”, “1|Set|REALCALLERIDNUM=8652432221”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[5919] func_db.c: DB: DEVICE/8652432221/user not found in database.
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:4] Set(“IAX2/johnson-6325”, “AMPUSER=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] DEBUG[5919] func_db.c: DB: AMPUSER//cidname not found in database.
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:5] Set(“IAX2/johnson-6325”, “AMPUSERCIDNAME=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“IAX2/johnson-6325”, “1?report”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Goto (macro-user-callerid,s,9)
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:9] GotoIf(“IAX2/johnson-6325”, “1?continue”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Goto (macro-user-callerid,s,18)
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-user-callerid:18] NoOp(“IAX2/johnson-6325”, “Using CallerID “” <8652432221>”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Noop
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [4145676@from-internal:2] Set(“IAX2/johnson-6325”, “_NODEST=”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [4145676@from-internal:3] Macro(“IAX2/johnson-6325”, “record-enable||OUT|”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“IAX2/johnson-6325”, “1?check”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Goto (macro-record-enable,s,4)
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-record-enable:4] AGI(“IAX2/johnson-6325”, “recordingcheck|20101025-082444|1288009484.636”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: recordingcheck|20101025-082444|1288009484.636: No AMPUSER db entry for . Not recording
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – AGI Script recordingcheck completed, returning 0
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: AGI
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“IAX2/johnson-6325”, “”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [4145676@from-internal:4] Macro(“IAX2/johnson-6325”, “dialout-trunk|1|4145676||”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“IAX2/johnson-6325”, “DIAL_TRUNK=1”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] DEBUG[5919] func_db.c: DB: AMPUSER//pinless not found in database.
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“IAX2/johnson-6325”, “0?sub-pincheck|s|1”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GosubIf
[2010-10-25 08:24:44] DEBUG[5919] func_db.c: DB: AMPUSER//pinless not found in database.
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“IAX2/johnson-6325”, “0?disabletrunk|1”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“IAX2/johnson-6325”, “DIAL_NUMBER=4145676”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“IAX2/johnson-6325”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“IAX2/johnson-6325”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“IAX2/johnson-6325”, “1?nomax”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Goto (macro-dialout-trunk,s,9)
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“IAX2/johnson-6325”, “0?skipoutcid”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“IAX2/johnson-6325”, “DIAL_TRUNK_OPTIONS=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“IAX2/johnson-6325”, “outbound-callerid|1”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“IAX2/johnson-6325”, “0|SetCallerPres|”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“IAX2/johnson-6325”, “0|Set|REALCALLERIDNUM=8652432221”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“IAX2/johnson-6325”, “1?normcid”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Goto (macro-outbound-callerid,s,6)
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] DEBUG[5919] func_db.c: DB: AMPUSER//outboundcid not found in database.
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:6] Set(“IAX2/johnson-6325”, “USEROUTCID=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] DEBUG[5919] func_db.c: DB: DEVICE/8652432221/emergency_cid not found in database.
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:7] Set(“IAX2/johnson-6325”, “EMERGENCYCID=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:8] Set(“IAX2/johnson-6325”, “TRUNKOUTCID=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“IAX2/johnson-6325”, “1?trunkcid”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Goto (macro-outbound-callerid,s,12)
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“IAX2/johnson-6325”, “0|Set|CALLERID(all)=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“IAX2/johnson-6325”, “0|Set|CALLERID(all)=”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“IAX2/johnson-6325”, “0|SetCallerPres|prohib_passed_screen”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Macro
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:12] ExecIf(“IAX2/johnson-6325”, “1|AGI|fixlocalprefix”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: == fixlocalprefix: Dialpattern 865+NXXXXXX matched. 4145676 -> 8654145676
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – AGI Script fixlocalprefix completed, returning 0
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Last app: AGI|fixlocalprefix
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“IAX2/johnson-6325”, “OUTNUM=8654145676”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“IAX2/johnson-6325”, “custom=SIP/Windstream”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“IAX2/johnson-6325”, “0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:16] Macro(“IAX2/johnson-6325”, “dialout-trunk-predial-hook|”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“IAX2/johnson-6325”, “”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: Macro
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:17] GotoIf(“IAX2/johnson-6325”, “0?bypass|1”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“IAX2/johnson-6325”, “0?customtrunk”) in new stack
[2010-10-25 08:24:44] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Executing [s@macro-dialout-trunk:19] Dial(“IAX2/johnson-6325”, “SIP/Windstream/8654145676|300|”) in new stack
[2010-10-25 08:24:44] VERBOSE[5919] logger.c: – Called Windstream/8654145676
[2010-10-25 08:24:45] VERBOSE[5919] logger.c: – SIP/Windstream-00000140 is making progress passing it to IAX2/johnson-6325
[2010-10-25 08:24:46] VERBOSE[5919] logger.c: – SIP/Windstream-00000140 is ringing
[2010-10-25 08:24:46] VERBOSE[5919] logger.c: – SIP/Windstream-00000140 is making progress passing it to IAX2/johnson-6325
[2010-10-25 08:25:06] VERBOSE[5919] logger.c: – SIP/Windstream-00000140 answered IAX2/johnson-6325
[2010-10-25 08:31:59] VERBOSE[3409] logger.c: – Remote UNIX connection
[2010-10-25 08:31:59] VERBOSE[6141] logger.c: – Remote UNIX connection disconnected
[2010-10-25 08:31:59] VERBOSE[3409] logger.c: – Remote UNIX connection
[2010-10-25 08:32:00] VERBOSE[3425] logger.c: – Accepting AUTHENTICATED call from 10.10.8.3:
> requested format = ulaw,
> requested prefs = (ulaw|alaw|gsm),
> actual format = ulaw,
> host prefs = (ulaw|alaw|gsm),
> priority = mine
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [19312478084@from-internal:1] Macro(“IAX2/case-3491”, “user-callerid|SKIPTTL|”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:1] Set(“IAX2/case-3491”, “AMPUSER=8655583033”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“IAX2/case-3491”, “0?report”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“IAX2/case-3491”, “1|Set|REALCALLERIDNUM=8655583033”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] DEBUG[6146] func_db.c: DB: DEVICE/8655583033/user not found in database.
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:4] Set(“IAX2/case-3491”, “AMPUSER=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] DEBUG[6146] func_db.c: DB: AMPUSER//cidname not found in database.
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:5] Set(“IAX2/case-3491”, “AMPUSERCIDNAME=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“IAX2/case-3491”, “1?report”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Goto (macro-user-callerid,s,9)
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:9] GotoIf(“IAX2/case-3491”, “1?continue”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Goto (macro-user-callerid,s,18)
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-user-callerid:18] NoOp(“IAX2/case-3491”, “Using CallerID “” <8655583033>”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Noop
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [19312478084@from-internal:2] Set(“IAX2/case-3491”, “_NODEST=”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [19312478084@from-internal:3] Macro(“IAX2/case-3491”, “record-enable||OUT|”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“IAX2/case-3491”, “1?check”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Goto (macro-record-enable,s,4)
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-record-enable:4] AGI(“IAX2/case-3491”, “recordingcheck|20101025-083200|1288009920.638”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: recordingcheck|20101025-083200|1288009920.638: No AMPUSER db entry for . Not recording
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – AGI Script recordingcheck completed, returning 0
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: AGI
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“IAX2/case-3491”, “”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [19312478084@from-internal:4] Macro(“IAX2/case-3491”, “dialout-trunk|1|19312478084||”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“IAX2/case-3491”, “DIAL_TRUNK=1”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] DEBUG[6146] func_db.c: DB: AMPUSER//pinless not found in database.
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“IAX2/case-3491”, “0?sub-pincheck|s|1”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GosubIf
[2010-10-25 08:32:00] DEBUG[6146] func_db.c: DB: AMPUSER//pinless not found in database.
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“IAX2/case-3491”, “0?disabletrunk|1”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“IAX2/case-3491”, “DIAL_NUMBER=19312478084”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“IAX2/case-3491”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“IAX2/case-3491”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“IAX2/case-3491”, “1?nomax”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Goto (macro-dialout-trunk,s,9)
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“IAX2/case-3491”, “0?skipoutcid”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“IAX2/case-3491”, “DIAL_TRUNK_OPTIONS=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“IAX2/case-3491”, “outbound-callerid|1”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“IAX2/case-3491”, “0|SetCallerPres|”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“IAX2/case-3491”, “0|Set|REALCALLERIDNUM=8655583033”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“IAX2/case-3491”, “1?normcid”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Goto (macro-outbound-callerid,s,6)
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] DEBUG[6146] func_db.c: DB: AMPUSER//outboundcid not found in database.
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:6] Set(“IAX2/case-3491”, “USEROUTCID=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] DEBUG[6146] func_db.c: DB: DEVICE/8655583033/emergency_cid not found in database.
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:7] Set(“IAX2/case-3491”, “EMERGENCYCID=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:8] Set(“IAX2/case-3491”, “TRUNKOUTCID=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“IAX2/case-3491”, “1?trunkcid”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Goto (macro-outbound-callerid,s,12)
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“IAX2/case-3491”, “0|Set|CALLERID(all)=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“IAX2/case-3491”, “0|Set|CALLERID(all)=”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“IAX2/case-3491”, “0|SetCallerPres|prohib_passed_screen”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Macro
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:12] ExecIf(“IAX2/case-3491”, “1|AGI|fixlocalprefix”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – AGI Script fixlocalprefix completed, returning 0
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Last app: AGI|fixlocalprefix
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“IAX2/case-3491”, “OUTNUM=19312478084”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“IAX2/case-3491”, “custom=SIP/Windstream”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Set
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“IAX2/case-3491”, “0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: ExecIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:16] Macro(“IAX2/case-3491”, “dialout-trunk-predial-hook|”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“IAX2/case-3491”, “”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: Macro
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:17] GotoIf(“IAX2/case-3491”, “0?bypass|1”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“IAX2/case-3491”, “0?customtrunk”) in new stack
[2010-10-25 08:32:00] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Executing [s@macro-dialout-trunk:19] Dial(“IAX2/case-3491”, “SIP/Windstream/19312478084|300|”) in new stack
[2010-10-25 08:32:00] VERBOSE[6146] logger.c: – Called Windstream/19312478084
[2010-10-25 08:32:00] VERBOSE[6145] logger.c: – Remote UNIX connection disconnected
[2010-10-25 08:32:01] VERBOSE[6146] logger.c: – SIP/Windstream-00000141 is making progress passing it to IAX2/case-3491
[2010-10-25 08:32:04] VERBOSE[3409] logger.c: – Remote UNIX connection
[2010-10-25 08:32:32] VERBOSE[6146] logger.c: – SIP/Windstream-00000141 answered IAX2/case-3491
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“IAX2/case-3491”, “hangupcall|”) in new stack
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“IAX2/case-3491”, “1?skiprg”) in new stack
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Goto (macro-hangupcall,s,4)
[2010-10-25 08:33:52] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“IAX2/case-3491”, “1?skipblkvm”) in new stack
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Goto (macro-hangupcall,s,7)
[2010-10-25 08:33:52] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“IAX2/case-3491”, “1?theend”) in new stack
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Goto (macro-hangupcall,s,9)
[2010-10-25 08:33:52] DEBUG[6146] app_macro.c: Executed application: GotoIf
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“IAX2/case-3491”, “”) in new stack
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘IAX2/case-3491’ in macro ‘hangupcall’
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: == Spawn h extension (macro-dialout-trunk, h, 1) exited non-zero on ‘IAX2/case-3491’
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘IAX2/case-3491’ in macro ‘dialout-trunk’
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: == Spawn extension (from-internal, 19312478084, 4) exited non-zero on ‘IAX2/case-3491’
[2010-10-25 08:33:52] VERBOSE[6146] logger.c: – Hungup ‘IAX2/case-3491’
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“IAX2/johnson-6325”, “hangupcall|”) in new stack
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“IAX2/johnson-6325”, “1?skiprg”) in new stack
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Goto (macro-hangupcall,s,4)
[2010-10-25 08:45:56] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“IAX2/johnson-6325”, “1?skipblkvm”) in new stack
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Goto (macro-hangupcall,s,7)
[2010-10-25 08:45:56] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“IAX2/johnson-6325”, “1?theend”) in new stack
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Goto (macro-hangupcall,s,9)
[2010-10-25 08:45:56] DEBUG[5919] app_macro.c: Executed application: GotoIf
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“IAX2/johnson-6325”, “”) in new stack
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘IAX2/johnson-6325’ in macro ‘hangupcall’
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: == Spawn h extension (macro-dialout-trunk, h, 1) exited non-zero on ‘IAX2/johnson-6325’
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘IAX2/johnson-6325’ in macro ‘dialout-trunk’
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: == Spawn extension (from-internal, 4145676, 4) exited non-zero on ‘IAX2/johnson-6325’
[2010-10-25 08:45:56] VERBOSE[5919] logger.c: – Hungup ‘IAX2/johnson-6325’

dmcoopknx · October 25, 2010, 8:39pm

[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [4145676@from-internal:1] Macro(“SIP/150-00000228”, “user-callerid|SKIPTTL|”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/150-00000228”, “AMPUSER=150”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/150-00000228”, “0?report”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/150-00000228”, “1|Set|REALCALLERIDNUM=150”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/150-00000228”, “AMPUSER=150”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/150-00000228”, “AMPUSERCIDNAME=TestExt”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/150-00000228”, “0?report”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/150-00000228”, “AMPUSERCID=150”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/150-00000228”, “CALLERID(all)=“TestExt” <150>”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: AMPUSER/150/language not found in database.
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: AMPUSER/150/language not found in database.
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:9] ExecIf(“SIP/150-00000228”, “0|Set|CHANNEL(language)=”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: AMPUSER/150/language not found in database.
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: AMPUSER/150/language not found in database.
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:10] GotoIf(“SIP/150-00000228”, “1?continue”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Goto (macro-user-callerid,s,19)
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-user-callerid:19] NoOp(“SIP/150-00000228”, “Using CallerID “TestExt” <150>”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Noop
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [4145676@from-internal:2] Set(“SIP/150-00000228”, “_NODEST=”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [4145676@from-internal:3] Macro(“SIP/150-00000228”, “record-enable|150|OUT|”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/150-00000228”, “1?check”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Goto (macro-record-enable,s,4)
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-record-enable:4] ExecIf(“SIP/150-00000228”, “0|MacroExit|”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-record-enable:5] GotoIf(“SIP/150-00000228”, “0?Group:OUT”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Goto (macro-record-enable,s,15)
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-record-enable:15] GotoIf(“SIP/150-00000228”, “0?IN”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-record-enable:16] ExecIf(“SIP/150-00000228”, “1|MacroExit|”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [4145676@from-internal:4] Macro(“SIP/150-00000228”, “dialout-trunk|1|4145676||”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/150-00000228”, “DIAL_TRUNK=1”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: AMPUSER/150/pinless not found in database.
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/150-00000228”, “0?sub-pincheck|s|1”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GosubIf
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: AMPUSER/150/pinless not found in database.
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/150-00000228”, “0?disabletrunk|1”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/150-00000228”, “DIAL_NUMBER=4145676”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/150-00000228”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/150-00000228”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/150-00000228”, “1?nomax”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Goto (macro-dialout-trunk,s,9)
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/150-00000228”, “0?skipoutcid”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/150-00000228”, “DIAL_TRUNK_OPTIONS=”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/150-00000228”, “outbound-callerid|1”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/150-00000228”, “0|SetCallerPres|”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/150-00000228”, “0|Set|REALCALLERIDNUM=150”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/150-00000228”, “1?normcid”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Goto (macro-outbound-callerid,s,6)
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/150-00000228”, “USEROUTCID=8652432221”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] DEBUG[6499] func_db.c: DB: DEVICE/150/emergency_cid not found in database.
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/150-00000228”, “EMERGENCYCID=”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/150-00000228”, “TRUNKOUTCID=8656719060”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/150-00000228”, “1?trunkcid”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Goto (macro-outbound-callerid,s,12)
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“SIP/150-00000228”, “1|Set|CALLERID(all)=8656719060”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Last app: Set|CALLERID(all)=8656719060
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“SIP/150-00000228”, “1|Set|CALLERID(all)=8652432221”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Last app: Set|CALLERID(all)=8652432221
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/150-00000228”, “0|Set|CALLERID(all)=”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/150-00000228”, “0|SetCallerPres|prohib_passed_screen”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Macro
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:12] ExecIf(“SIP/150-00000228”, “0|AGI|fixlocalprefix”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/150-00000228”, “OUTNUM=4145676”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/150-00000228”, “custom=IAX2/johnson”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Set
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/150-00000228”, “0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: ExecIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:16] Macro(“SIP/150-00000228”, “dialout-trunk-predial-hook|”) in new stack
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/150-00000228”, “”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: Macro
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:17] GotoIf(“SIP/150-00000228”, “0?bypass|1”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/150-00000228”, “0?customtrunk”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Executing [s@macro-dialout-trunk:19] Dial(“SIP/150-00000228”, “IAX2/johnson/4145676|300|”) in new stack
[2010-10-25 08:24:44] DEBUG[6499] chan_iax2.c: prepending 4 to prefs
[2010-10-25 08:24:44] VERBOSE[6499] logger.c: – Called johnson/4145676
[2010-10-25 08:24:44] VERBOSE[3925] logger.c: – Call accepted by 10.10.8.1 (format ulaw)
[2010-10-25 08:24:44] VERBOSE[3925] logger.c: – Format for call is ulaw
[2010-10-25 08:24:45] VERBOSE[6499] logger.c: – IAX2/johnson-9860 is making progress passing it to SIP/150-00000228
[2010-10-25 08:24:46] VERBOSE[6499] logger.c: – IAX2/johnson-9860 is ringing
[2010-10-25 08:24:46] VERBOSE[6499] logger.c: – IAX2/johnson-9860 is making progress passing it to SIP/150-00000228
[2010-10-25 08:25:06] VERBOSE[6499] logger.c: – IAX2/johnson-9860 stopped sounds
[2010-10-25 08:25:06] VERBOSE[6499] logger.c: – IAX2/johnson-9860 answered SIP/150-00000228
[2010-10-25 08:27:17] VERBOSE[3898] logger.c: Extension Changed 230[ext-local] new state InUse for Notify User 221
[2010-10-25 08:27:17] VERBOSE[6504] logger.c: – Executing [*97@from-internal:1] Answer(“SIP/230-00000229”, “”) in new stack
[2010-10-25 08:27:17] VERBOSE[6504] logger.c: – Executing [*97@from-internal:2] Wait(“SIP/230-00000229”, “1”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [*97@from-internal:3] Macro(“SIP/230-00000229”, “user-callerid|”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/230-00000229”, “AMPUSER=230”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/230-00000229”, “0?report”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/230-00000229”, “1|Set|REALCALLERIDNUM=230”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: ExecIf
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/230-00000229”, “AMPUSER=230”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/230-00000229”, “AMPUSERCIDNAME=Dale East”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/230-00000229”, “0?report”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/230-00000229”, “AMPUSERCID=230”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/230-00000229”, “CALLERID(all)=“Dale East” <230>”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] DEBUG[6504] func_db.c: DB: AMPUSER/230/language not found in database.
[2010-10-25 08:27:18] DEBUG[6504] func_db.c: DB: AMPUSER/230/language not found in database.
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:9] ExecIf(“SIP/230-00000229”, “0|Set|CHANNEL(language)=”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: ExecIf
[2010-10-25 08:27:18] DEBUG[6504] func_db.c: DB: AMPUSER/230/language not found in database.
[2010-10-25 08:27:18] DEBUG[6504] func_db.c: DB: AMPUSER/230/language not found in database.
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:10] GotoIf(“SIP/230-00000229”, “0?continue”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:11] Set(“SIP/230-00000229”, “__TTL=64”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:12] GotoIf(“SIP/230-00000229”, “1?continue”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Goto (macro-user-callerid,s,19)
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-user-callerid:19] NoOp(“SIP/230-00000229”, “Using CallerID “Dale East” <230>”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Noop
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [*97@from-internal:4] Macro(“SIP/230-00000229”, “get-vmcontext|230”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-get-vmcontext:1] Set(“SIP/230-00000229”, “VMCONTEXT=default”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: Set
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/230-00000229”, “0?200:300”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Goto (macro-get-vmcontext,s,300)
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [s@macro-get-vmcontext:300] NoOp(“SIP/230-00000229”, “”) in new stack
[2010-10-25 08:27:18] DEBUG[6504] app_macro.c: Executed application: NoOp
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [*97@from-internal:5] MailboxExists(“SIP/230-00000229”, “230@default”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [*97@from-internal:6] GotoIf(“SIP/230-00000229”, “1?mbexist”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Goto (from-internal,*97,106)
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – Executing [*97@from-internal:106] VoiceMailMain(“SIP/230-00000229”, “230@default”) in new stack
[2010-10-25 08:27:18] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-password’ (language ‘en’)
[2010-10-25 08:27:23] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-youhave’ (language ‘en’)
[2010-10-25 08:27:24] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘digits/1’ (language ‘en’)
[2010-10-25 08:27:24] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-INBOX’ (language ‘en’)
[2010-10-25 08:27:25] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-and’ (language ‘en’)
[2010-10-25 08:27:26] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘digits/1’ (language ‘en’)
[2010-10-25 08:27:26] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-Old’ (language ‘en’)
[2010-10-25 08:27:27] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-message’ (language ‘en’)
[2010-10-25 08:27:28] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-onefor’ (language ‘en’)
[2010-10-25 08:27:29] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-INBOX’ (language ‘en’)
[2010-10-25 08:27:30] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-messages’ (language ‘en’)
[2010-10-25 08:27:30] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-first’ (language ‘en’)
[2010-10-25 08:27:30] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-message’ (language ‘en’)
[2010-10-25 08:27:31] VERBOSE[6504] logger.c: == Parsing ‘/var/spool/asterisk/voicemail/default/230/INBOX/msg0000.txt’: [2010-10-25 08:27:31] VERBOSE[6504] logger.c: Found
[2010-10-25 08:27:31] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘/var/spool/asterisk/voicemail/default/230/INBOX/msg0000’ (language ‘en’)
[2010-10-25 08:28:23] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-advopts’ (language ‘en’)
[2010-10-25 08:28:24] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-deleted’ (language ‘en’)
[2010-10-25 08:28:25] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-nomore’ (language ‘en’)
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – <SIP/230-00000229> Playing ‘vm-advopts’ (language ‘en’)
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: == Spawn extension (from-internal, *97, 106) exited non-zero on ‘SIP/230-00000229’
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Executing [h@from-internal:1] Macro(“SIP/230-00000229”, “hangupcall”) in new stack
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/230-00000229”, “1?skiprg”) in new stack
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Goto (macro-hangupcall,s,4)
[2010-10-25 08:28:27] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“SIP/230-00000229”, “1?skipblkvm”) in new stack
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Goto (macro-hangupcall,s,7)
[2010-10-25 08:28:27] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“SIP/230-00000229”, “1?theend”) in new stack
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Goto (macro-hangupcall,s,9)
[2010-10-25 08:28:27] DEBUG[6504] app_macro.c: Executed application: GotoIf
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“SIP/230-00000229”, “”) in new stack
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/230-00000229’ in macro ‘hangupcall’
[2010-10-25 08:28:27] VERBOSE[6504] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/230-00000229’
[2010-10-25 08:28:27] VERBOSE[3898] logger.c: Extension Changed 230[ext-local] new state Idle for Notify User 221
[2010-10-25 08:35:34] VERBOSE[3896] logger.c: – Remote UNIX connection
[2010-10-25 08:35:35] VERBOSE[6729] logger.c: – Remote UNIX connection disconnected
[2010-10-25 08:35:35] VERBOSE[3896] logger.c: – Remote UNIX connection
[2010-10-25 08:35:35] VERBOSE[6732] logger.c: – Remote UNIX connection disconnected
[2010-10-25 08:36:44] VERBOSE[3896] logger.c: – Remote UNIX connection
[2010-10-25 08:40:49] VERBOSE[3898] logger.c: Extension Changed 242[ext-local] new state InUse for Notify User 221
[2010-10-25 08:40:49] VERBOSE[6768] logger.c: – Executing [*97@from-internal:1] Answer(“SIP/242-0000022a”, “”) in new stack
[2010-10-25 08:40:49] VERBOSE[6768] logger.c: – Executing [*97@from-internal:2] Wait(“SIP/242-0000022a”, “1”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [*97@from-internal:3] Macro(“SIP/242-0000022a”, “user-callerid|”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/242-0000022a”, “AMPUSER=242”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/242-0000022a”, “0?report”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/242-0000022a”, “1|Set|REALCALLERIDNUM=242”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: ExecIf
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/242-0000022a”, “AMPUSER=242”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/242-0000022a”, “AMPUSERCIDNAME=Shawn Boles”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/242-0000022a”, “0?report”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/242-0000022a”, “AMPUSERCID=242”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/242-0000022a”, “CALLERID(all)=“Shawn Boles” <242>”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] DEBUG[6768] func_db.c: DB: AMPUSER/242/language not found in database.
[2010-10-25 08:40:50] DEBUG[6768] func_db.c: DB: AMPUSER/242/language not found in database.
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:9] ExecIf(“SIP/242-0000022a”, “0|Set|CHANNEL(language)=”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: ExecIf
[2010-10-25 08:40:50] DEBUG[6768] func_db.c: DB: AMPUSER/242/language not found in database.
[2010-10-25 08:40:50] DEBUG[6768] func_db.c: DB: AMPUSER/242/language not found in database.
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:10] GotoIf(“SIP/242-0000022a”, “0?continue”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:11] Set(“SIP/242-0000022a”, “__TTL=64”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:12] GotoIf(“SIP/242-0000022a”, “1?continue”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Goto (macro-user-callerid,s,19)
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-user-callerid:19] NoOp(“SIP/242-0000022a”, “Using CallerID “Shawn Boles” <242>”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Noop
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [*97@from-internal:4] Macro(“SIP/242-0000022a”, “get-vmcontext|242”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-get-vmcontext:1] Set(“SIP/242-0000022a”, “VMCONTEXT=default”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: Set
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/242-0000022a”, “0?200:300”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Goto (macro-get-vmcontext,s,300)
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [s@macro-get-vmcontext:300] NoOp(“SIP/242-0000022a”, “”) in new stack
[2010-10-25 08:40:50] DEBUG[6768] app_macro.c: Executed application: NoOp
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [*97@from-internal:5] MailboxExists(“SIP/242-0000022a”, “242@default”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [*97@from-internal:6] GotoIf(“SIP/242-0000022a”, “1?mbexist”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Goto (from-internal,*97,106)
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – Executing [*97@from-internal:106] VoiceMailMain(“SIP/242-0000022a”, “242@default”) in new stack
[2010-10-25 08:40:50] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-password’ (language ‘en’)
[2010-10-25 08:40:58] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-youhave’ (language ‘en’)
[2010-10-25 08:40:59] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘digits/3’ (language ‘en’)
[2010-10-25 08:41:00] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-INBOX’ (language ‘en’)
[2010-10-25 08:41:00] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-and’ (language ‘en’)
[2010-10-25 08:41:01] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘digits/3’ (language ‘en’)
[2010-10-25 08:41:01] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-Old’ (language ‘en’)
[2010-10-25 08:41:02] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-messages’ (language ‘en’)
[2010-10-25 08:41:03] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-onefor’ (language ‘en’)
[2010-10-25 08:41:04] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-INBOX’ (language ‘en’)
[2010-10-25 08:41:05] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-messages’ (language ‘en’)
[2010-10-25 08:41:05] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-first’ (language ‘en’)
[2010-10-25 08:41:06] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-message’ (language ‘en’)
[2010-10-25 08:41:07] VERBOSE[6768] logger.c: == Parsing ‘/var/spool/asterisk/voicemail/default/242/INBOX/msg0000.txt’: [2010-10-25 08:41:07] VERBOSE[6768] logger.c: Found
[2010-10-25 08:41:07] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘/var/spool/asterisk/voicemail/default/242/INBOX/msg0000’ (language ‘en’)
[2010-10-25 08:41:41] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-advopts’ (language ‘en’)
[2010-10-25 08:41:43] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-repeat’ (language ‘en’)
[2010-10-25 08:41:45] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-next’ (language ‘en’)
[2010-10-25 08:41:48] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-delete’ (language ‘en’)
[2010-10-25 08:41:48] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-message’ (language ‘en’)
[2010-10-25 08:41:49] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘digits/2’ (language ‘en’)
[2010-10-25 08:41:50] VERBOSE[6768] logger.c: == Parsing ‘/var/spool/asterisk/voicemail/default/242/INBOX/msg0001.txt’: [2010-10-25 08:41:50] VERBOSE[6768] logger.c: Found
[2010-10-25 08:41:50] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘/var/spool/asterisk/voicemail/default/242/INBOX/msg0001’ (language ‘en’)
[2010-10-25 08:42:06] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-prev’ (language ‘en’)
[2010-10-25 08:42:09] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-advopts’ (language ‘en’)
[2010-10-25 08:42:10] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-last’ (language ‘en’)
[2010-10-25 08:42:10] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-message’ (language ‘en’)
[2010-10-25 08:42:11] VERBOSE[6768] logger.c: == Parsing ‘/var/spool/asterisk/voicemail/default/242/INBOX/msg0002.txt’: [2010-10-25 08:42:11] VERBOSE[6768] logger.c: Found
[2010-10-25 08:42:11] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘/var/spool/asterisk/voicemail/default/242/INBOX/msg0002’ (language ‘en’)
[2010-10-25 08:42:37] VERBOSE[6768] logger.c: – <SIP/242-0000022a> Playing ‘vm-prev’ (language ‘en’)
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: == Spawn extension (from-internal, *97, 106) exited non-zero on ‘SIP/242-0000022a’
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Executing [h@from-internal:1] Macro(“SIP/242-0000022a”, “hangupcall”) in new stack
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/242-0000022a”, “1?skiprg”) in new stack
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Goto (macro-hangupcall,s,4)
[2010-10-25 08:42:39] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“SIP/242-0000022a”, “1?skipblkvm”) in new stack
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Goto (macro-hangupcall,s,7)
[2010-10-25 08:42:39] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“SIP/242-0000022a”, “1?theend”) in new stack
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Goto (macro-hangupcall,s,9)
[2010-10-25 08:42:39] DEBUG[6768] app_macro.c: Executed application: GotoIf
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“SIP/242-0000022a”, “”) in new stack
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/242-0000022a’ in macro ‘hangupcall’
[2010-10-25 08:42:39] VERBOSE[6768] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/242-0000022a’
[2010-10-25 08:42:39] VERBOSE[3898] logger.c: Extension Changed 242[ext-local] new state Idle for Notify User 221
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/150-00000228”, “hangupcall|”) in new stack
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/150-00000228”, “1?skiprg”) in new stack
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Goto (macro-hangupcall,s,4)
[2010-10-25 08:45:56] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“SIP/150-00000228”, “1?skipblkvm”) in new stack
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Goto (macro-hangupcall,s,7)
[2010-10-25 08:45:56] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“SIP/150-00000228”, “1?theend”) in new stack
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Goto (macro-hangupcall,s,9)
[2010-10-25 08:45:56] DEBUG[6499] app_macro.c: Executed application: GotoIf
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“SIP/150-00000228”, “”) in new stack
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/150-00000228’ in macro ‘hangupcall’
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: == Spawn h extension (macro-dialout-trunk, h, 1) exited non-zero on ‘SIP/150-00000228’
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: – Hungup ‘IAX2/johnson-9860’
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘SIP/150-00000228’ in macro ‘dialout-trunk’
[2010-10-25 08:45:56] VERBOSE[6499] logger.c: == Spawn extension (from-internal, 4145676, 4) exited non-zero on ‘SIP/150-00000228’

mickecarlsson · October 25, 2010, 8:15pm

Hmmm, the Juniper SSG, is that a SSG5? I would swap that Linksys to the Juniper without any doubt. We use the SSG5 at work, I have had 42 concurrent calls without any drop-outs or anything.
What is the line speed for Windstream SIP?

dmcoopknx · October 25, 2010, 8:36pm

I am about to post the call trace information for a period of time from 8:24 this AM to 8:44 AM. During this time I know that an event occured to a number dialed 4145676. The first post will be the internal (JAPBX) and the second will be the EdgePBX.

I have looked over both traces and don’t see anything that jumps out to me as a problem - however - I really don’t know what I am looking for either.

The audio drop out lasted about 10 seconds. Sorry I don’t have the exact time but I would say it was in the first half of the call someplace.

dmcoopknx · October 25, 2010, 8:00pm

Here is a link to the drawing of how we are configured at this time. It is worth noting that we originally had the Internet side being fed by a Juniper SSG when it was all nested within the data side of our network. When we seperated it out I did it this way to keep it as far isolated from everything we had been doing as possible.

http://bit.ly/cn6gRQ

A few more explanations:

All phones are DHCP.
Everything on the inside of the Linksys DD-WRT is in the same subnet 10.10.8.1/24.
The problem we are having is only (so far) being reported to happen on the phones connected to the JAPBX.
The reason for so many switches is these are in different parts of the building. I moved the JAPBX into the suite with the phones to see if it would help. It did not.

I am about to start working on the call trace stuff now.

mudslide567 · October 25, 2010, 5:24pm

I agree this is probably a network issue but it may have nothing to do with asterisk or the phones. I have seen this type of problem occur when someone backs up a server or downloads huge video files. Have you profiled your LAN traffic?

Wireshark will generate massive amounts of data that will not necessarily be helpful unless you can analyse it at a macro level. You will need a traffic analysis tool to go along with it. [You can get a fully functional 10 day free trial of CACE Pilot which will analyse your Wireshark data – you should be able to easily get to the root of this in 10 days!]

Once you have a good understanding of network traffic you will be able to better figure out what needs to be done which may be as simple as implementing ToS/QoS but may require better segregation of traffic.

dmcoopknx · October 25, 2010, 3:31pm

mickecarlsson - The physical PBX is the one that end-users are reporting drop-outs occuring from. It was virtual to start out with but I converted it to physical a couple of weeks ago as a trouble shooting step. Users on the other two networks have never complained - but this could be a function of call volume. The folks on the physical server make more calls in one day than the other two combined for two weeks. I am glad to look at the call traces - I’ll post back if I see anything.

SkykingOH - That is the direction we have spen a lot of time working in. At this point nothing (network equipment wise) is still in that LAN. The router and all switches have been replaced with different equipment. Things did get somewhat better on Thursday and Friday last week after we seperated the VoIP from the data physically but it seems today to be back to it’s usual tricks. We have had a total of 9 incidents today. I have opened a ticket with Windstream to see if they will take a closer look at their network for me. Switches are managed. No interface errors, discards, etc. Duplex is all ok - everything is set to auto and is matching up ok. There are no VLANs at this time - on the old system we had a Juniper SSG doing routing. Now we have a single VLAN and I downgraded to a Linksys E3000 flashed with DD-WRT.

I am working on a drawing now of exactly what we have going on and will post a link to that this afternoon. Also I am working on setting up a machine so I can try to use Wireshark to capture packets from the EdgePBX going to Windstream. That may be a problem since the PBX is plugged directly into their router.

mickecarlsson · October 25, 2010, 4:40am

Which PBX are getting call-drops and/or audio fades?
Start looking at that first (I suspect the VMware PBX’s).
Second, start doing Asterisk call traces. I think that PIAF has verbose set to 3 so you can actually look at the call logs on each PBX (/var/log/astrisk/full, full.0, full,1 etc) to see if there is anything there.

SkykingOH · October 25, 2010, 6:10am

My vote would be network problem. Find the packet loss and you have found your problem.

Are your switches managed? Look for interfaces with errors, duplex mismatches etc.

The subnets are not the issue, what were you using to route between the VLAN’s?