Cannot dial long distance numbers? FreePBX 2.4.0.1

Very bizarre situation… We have a client whose PBX is having some hardware problems so we’re replacing the hardware. We are replacing their PIII-1Ghz, 512MB RAM, IDE, Digium TE110P system with a refurbished Dell 2650 w/SCSI RAID-1, 2Gb RAM, and a Sangoma A101 . Because the system is refurbished we decided to test it as our PBX before replacing their existing system. We installed Trixbox 2.4.2 and upgraded everything a week ago. We used it all week and had no problems. The only difference in their setup and ours is that we use IAX2 to connect to another Asterisk system that acts as a SIP/IAX gateway, where they use a PRI.

So on Friday afternoon we deleted all of our settings and manually entered all of their extensions, groups, queues and tftp files for the Snom phones. We took the new server out to their office and installed it, everything appeared to be working perfectly until someone tried to make a long distance call.

They heard an error message that they needed to dial a 1 or 0 to make the long distance call, this came from their PRI provider not the PBX. We double checked the outbound routes to make sure we weren’t truncating the dial string and we weren’t. The Dial pattern is:

1411
311
411
911
011.
1800NXXXXXX
1866NXXXXXX
1877NXXXXXX
1888NXXXXXX
1NXXNXXXXXX
NXXNXXXXXX
NXXXXXX

We tried changing it to X. to see if it made a difference and it didn’t. We checked the Asterisk CLI (see below) to verify the full dial string (e.g. 17135551212) was being passed to the ZAP/go and it appeared it was. We checked the ZAP/go trunk to see if we had something in the dial pattern and we didn’t, nothing other than the outbound callerid, maximum channels and Zap identifier was configured in the trunk since nothing else is necessary.

We checked with the PRI provider to see if they were seeing the full dial string and were told they weren’t seeing the 1 in the dial string. We checked the Sangoma config to see if there was something that might be truncating the dial string and we couldn’t find a setting that could remove the 1. We called Sangoma and were told our Sangoma setup was correct.

Anyone have any idea what could be causing this?

Trixbox 2.4.2
Core 2.4.0.1
Feature Code Admin 2.4.0.1
FreePBX Framework 2.4.0.0
Snom 360 firmware 6.5.127

Asterisk CLI output for long distance call:

[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [19728311600@from-internal:1] Macro(“SIP/500-09113360”, “user-callerid|SKIPTTL|”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:1] NoOp(“SIP/500-09113360”, “user-callerid: device 500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:2] Set(“SIP/500-09113360”, “AMPUSER=500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/500-09113360”, “0?report”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/500-09113360”, “1|Set|REALCALLERIDNUM=500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: ExecIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:5] NoOp(“SIP/500-09113360”, “REALCALLERIDNUM is 500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:6] Set(“SIP/500-09113360”, “AMPUSER=500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/500-09113360”, “AMPUSERCIDNAME=LIZ PAINTER”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:8] GotoIf(“SIP/500-09113360”, “0?report”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/500-09113360”, “AMPUSERCID=500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:10] Set(“SIP/500-09113360”, “CALLERID(all)=“LIZ PAINTER” <500>”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:11] Set(“SIP/500-09113360”, “REALCALLERIDNUM=500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: AMPUSER/500/language not found in database.
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: AMPUSER/500/language not found in database.
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:12] ExecIf(“SIP/500-09113360”, “0|Set|CHANNEL(language)=”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: ExecIf
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: AMPUSER/500/language not found in database.
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: AMPUSER/500/language not found in database.
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:13] NoOp(“SIP/500-09113360”, “TTL: ARG1: SKIPTTL”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:14] GotoIf(“SIP/500-09113360”, “1?continue”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-user-callerid,s,23)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-user-callerid:23] NoOp(“SIP/500-09113360”, “Using CallerID “LIZ PAINTER” <500>”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [19728311600@from-internal:2] Set(“SIP/500-09113360”, “_NODEST=”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [19728311600@from-internal:3] Macro(“SIP/500-09113360”, “record-enable|500|OUT|”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/500-09113360”, “0?2:4”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-record-enable,s,4)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/500-09113360”, “recordingcheck|20080222-182943|1203726583.32”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Feb 22 18:29:43] VERBOSE[5560] logger.c: recordingcheck|20080222-182943|1203726583.32: Outbound recording not enabled
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – AGI Script recordingcheck completed, returning 0
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: AGI
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-record-enable:5] NoOp(“SIP/500-09113360”, “No recording needed”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [19728311600@from-internal:4] Macro(“SIP/500-09113360”, “dialout-trunk|1|19728311600||”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/500-09113360”, “DIAL_TRUNK=1”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: AMPUSER/500/pinless not found in database.
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:2] ExecIf(“SIP/500-09113360”, “0|Authenticate|”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: ExecIf
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: AMPUSER/500/pinless not found in database.
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/500-09113360”, “0?disabletrunk|1”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/500-09113360”, “DIAL_NUMBER=19728311600”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/500-09113360”, “DIAL_TRUNK_OPTIONS=trwW”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/500-09113360”, “GROUP()=OUT_1”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/500-09113360”, “0?nomax”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:8] GotoIf(“SIP/500-09113360”, “0?chanfull”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/500-09113360”, “0?skipoutcid”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/500-09113360”, “DIAL_TRUNK_OPTIONS=”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/500-09113360”, “outbound-callerid|1”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:1] GotoIf(“SIP/500-09113360”, “1?start”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-outbound-callerid,s,3)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:3] NoOp(“SIP/500-09113360”, “REALCALLERIDNUM is 500”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:4] GotoIf(“SIP/500-09113360”, “1?normcid”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-outbound-callerid,s,9)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:9] Set(“SIP/500-09113360”, “USEROUTCID=”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] DEBUG[5560] func_db.c: DB: DEVICE/500/emergency_cid not found in database.
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:10] Set(“SIP/500-09113360”, “EMERGENCYCID=”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:11] Set(“SIP/500-09113360”, “TRUNKOUTCID=“CENSORED” <2815551212>”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:12] GotoIf(“SIP/500-09113360”, “1?trunkcid”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-outbound-callerid,s,16)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:16] GotoIf(“SIP/500-09113360”, “0?usercid”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:17] Set(“SIP/500-09113360”, “CALLERID(all)=CENSORED <2815551212>”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:18] GotoIf(“SIP/500-09113360”, “1?report”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-outbound-callerid,s,22)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-outbound-callerid:22] NoOp(“SIP/500-09113360”, “CallerID set to “CENSORED” <2815551212>”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Noop
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Macro
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:12] AGI(“SIP/500-09113360”, “fixlocalprefix”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – AGI Script fixlocalprefix completed, returning 0
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: AGI
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/500-09113360”, “OUTNUM=19728311600”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/500-09113360”, “custom=ZAP/g0”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Set
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:15] GotoIf(“SIP/500-09113360”, “1?gocall”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Goto (macro-dialout-trunk,s,17)
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:17] Macro(“SIP/500-09113360”, “dialout-trunk-predial-hook|”) in new stack
[Feb 22 18:29:43] WARNING[5560] app_macro.c: Context ‘macro-dialout-trunk-predial-hook’ for macro ‘dialout-trunk-predial-hook’ lacks ‘s’ extension, priority 1
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: Macro
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/500-09113360”, “0?bypass|1”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:19] GotoIf(“SIP/500-09113360”, “0?customtrunk”) in new stack
[Feb 22 18:29:43] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Executing [s@macro-dialout-trunk:20] Dial(“SIP/500-09113360”, “ZAP/g0/19728311600|300|”) in new stack
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Requested transfer capability: 0x00 - SPEECH
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Called g0/19728311600
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Zap/7-1 is proceeding passing it to SIP/500-09113360
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Zap/7-1 is making progress passing it to SIP/500-09113360
[Feb 22 18:29:43] VERBOSE[5560] logger.c: – Zap/7-1 is making progress passing it to SIP/500-09113360
[Feb 22 18:29:56] DEBUG[5560] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/7-1
[Feb 22 18:29:56] DEBUG[5560] chan_zap.c: Not yet hungup… Calling hangup once with icause, and clearing call
[Feb 22 18:29:56] DEBUG[5560] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/7-1
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Hungup ‘Zap/7-1’
[Feb 22 18:29:56] VERBOSE[5560] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on ‘SIP/500-09113360’ in macro ‘dialout-trunk’
[Feb 22 18:29:56] VERBOSE[5560] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on ‘SIP/500-09113360’
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/500-09113360”, “hangupcall|”) in new stack
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/500-09113360”, “w”) in new stack
[Feb 22 18:29:56] DEBUG[5560] app_macro.c: Executed application: ResetCDR
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“SIP/500-09113360”, “”) in new stack
[Feb 22 18:29:56] DEBUG[5560] app_macro.c: Executed application: NoCDR
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“SIP/500-09113360”, “1?skiprg”) in new stack
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Goto (macro-hangupcall,s,6)
[Feb 22 18:29:56] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“SIP/500-09113360”, “1?skipblkvm”) in new stack
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Goto (macro-hangupcall,s,9)
[Feb 22 18:29:56] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“SIP/500-09113360”, “1?theend”) in new stack
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Goto (macro-hangupcall,s,11)
[Feb 22 18:29:56] DEBUG[5560] app_macro.c: Executed application: GotoIf
[Feb 22 18:29:56] VERBOSE[5560] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“SIP/500-09113360”, “”) in new stack
[Feb 22 18:29:56] VERBOSE[5560] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/500-09113360’ in macro ‘hangupcall’
[Feb 22 18:29:56] VERBOSE[5560] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/500-09113360’