Incoming calls hangup/not routed -- from extension with 7777

FreePBX Installation / Upgrade
1

I work in a small company (5 staff, 6 extensions, 3 PSTN lines and 2 VoIP SIP accounts) in Australia.

Last week I did a fresh clean install of PBX in a Flash 1.3 (with Asterisk 1.4, FreePBX 2.4.1.2). All FreePBX modules which are installed are up-to-date. All was working excellently last week :smiley:

Our 3 PSTN lines are connected to an external VoIP gateway box, which registers the lines as SIP extensions (3001, 3002, 3003) and sends the “hotline” code of 7777 to asterisk to simulate an incoming call. This was working correctly last week, but this week incoming calls are hung up. I have dialled 7777 from other SIP extensions and got the same immediate hangup, so I do not believe it is a problem with the VoIP gateway.

===========
Extension: 3001

Display Name _FXO1
Extension Options (default values)

Device Options
This device uses sip technology.
secret 3001
dtmfmode info
canreinvite no
context from-internal
host dynamic
type friend
nat yes
port 5060
qualify yes
callgroup
pickupgroup
disallow all
allow ulaw
dial SIP/3001
accountcode
mailbox 3001@device

Fax Handling
Fax Extension disabled

Privacy
Privacy Manager No

Recording Options
Record Incoming On Demand
Record Outgoing On Demand

Voicemail & Directory
Status Disabled

============
Inbound Routes: All calls - any DID / any CID

Fax Handling Disabled
Privacy Manager No

Set Destination
Extension 39

=============

IVR: not used (yet)

I was having a little fun Friday afternoon, listening to the System Recordings > Built-in recordings and selecting some for possible use in an IVR. I don’t see how that would hangup incoming calls.

2

From the logfile… I dialled from extension 39 to 3002, at PSTN dial tone I dialled our PSTN line 1, which was answered as extension 3001 (_FXO1) which immediately hungup.

[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [3002@from-internal:1] Macro(“SIP/39-08ade1a8”, “exten-vm|novm|3002”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:1] Macro(“SIP/39-08ade1a8”, “user-callerid”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:1] NoOp(“SIP/39-08ade1a8”, “user-callerid: device 39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Noop
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:2] Set(“SIP/39-08ade1a8”, “AMPUSER=39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/39-08ade1a8”, “0?report”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/39-08ade1a8”, “1|Set|REALCALLERIDNUM=39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: ExecIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:5] NoOp(“SIP/39-08ade1a8”, “REALCALLERIDNUM is 39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Noop
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:6] Set(“SIP/39-08ade1a8”, “AMPUSER=39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/39-08ade1a8”, “AMPUSERCIDNAME=Don Burch”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:8] GotoIf(“SIP/39-08ade1a8”, “0?report”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/39-08ade1a8”, “AMPUSERCID=39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:10] Set(“SIP/39-08ade1a8”, “CALLERID(all)=“Don Burch” <39>”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:11] Set(“SIP/39-08ade1a8”, “REALCALLERIDNUM=39”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] DEBUG[3032] func_db.c: DB: AMPUSER/39/language not found in database.
[Oct 13 15:20:12] DEBUG[3032] func_db.c: DB: AMPUSER/39/language not found in database.
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:12] ExecIf(“SIP/39-08ade1a8”, “0|Set|CHANNEL(language)=”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: ExecIf
[Oct 13 15:20:12] DEBUG[3032] func_db.c: DB: AMPUSER/39/language not found in database.
[Oct 13 15:20:12] DEBUG[3032] func_db.c: DB: AMPUSER/39/language not found in database.
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:13] NoOp(“SIP/39-08ade1a8”, “TTL: ARG1: novm”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Noop
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:14] GotoIf(“SIP/39-08ade1a8”, “0?continue”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:15] Set(“SIP/39-08ade1a8”, “__TTL=64”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:16] GotoIf(“SIP/39-08ade1a8”, “1?continue”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Goto (macro-user-callerid,s,23)
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-user-callerid:23] NoOp(“SIP/39-08ade1a8”, “Using CallerID “Don Burch” <39>”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Noop
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Macro
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:2] Set(“SIP/39-08ade1a8”, “RingGroupMethod=none”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:3] Set(“SIP/39-08ade1a8”, “VMBOX=novm”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:4] Set(“SIP/39-08ade1a8”, “EXTTOCALL=3002”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] DEBUG[3032] func_db.c: DB: CFU/3002 not found in database.
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:5] Set(“SIP/39-08ade1a8”, “CFUEXT=”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] DEBUG[3032] func_db.c: DB: CFB/3002 not found in database.
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:6] Set(“SIP/39-08ade1a8”, “CFBEXT=”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:7] Set(“SIP/39-08ade1a8”, “RT=”"") in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Set
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:8] Macro(“SIP/39-08ade1a8”, “record-enable|3002|IN”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/39-08ade1a8”, “0?2:4”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Goto (macro-record-enable,s,4)
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/39-08ade1a8”, “recordingcheck|20081013-152012|1223871612.9”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Oct 13 15:20:12] VERBOSE[3032] logger.c: recordingcheck|20081013-152012|1223871612.9: Inbound recording not enabled
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – AGI Script recordingcheck completed, returning 0
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: AGI
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-record-enable:5] NoOp(“SIP/39-08ade1a8”, “No recording needed”) in new stack
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Noop
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: Macro
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-exten-vm:9] Macro(“SIP/39-08ade1a8”, “dial||tr|3002”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-dial:1] GotoIf(“SIP/39-08ade1a8”, “1?dial”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Goto (macro-dial,s,3)
[Oct 13 15:20:12] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Executing [s@macro-dial:3] AGI(“SIP/39-08ade1a8”, “dialparties.agi”) in new stack
[Oct 13 15:20:12] VERBOSE[3032] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Oct 13 15:20:13] VERBOSE[3032] logger.c: dialparties.agi: Starting New Dialparties.agi
[Oct 13 15:20:13] VERBOSE[3035] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Oct 13 15:20:13] VERBOSE[3035] logger.c: Found
[Oct 13 15:20:13] VERBOSE[3035] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Oct 13 15:20:13] VERBOSE[3035] logger.c: Found
[Oct 13 15:20:13] VERBOSE[3035] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Oct 13 15:20:13] VERBOSE[3035] logger.c: Found
[Oct 13 15:20:13] VERBOSE[3035] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Oct 13 15:20:13] VERBOSE[3032] logger.c: dialparties.agi: Caller ID name is ‘Don Burch’ number is ‘39’
[Oct 13 15:20:13] VERBOSE[3032] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – dialparties.agi: Added extension 3002 to extension map
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – dialparties.agi: Extension 3002 cf is disabled
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – dialparties.agi: Extension 3002 do not disturb is disabled
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – dialparties.agi: dbset CALLTRACE/3002 to 39
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – dialparties.agi: Filtered ARG3: 3002
[Oct 13 15:20:13] VERBOSE[3035] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – AGI Script dialparties.agi completed, returning 0
[Oct 13 15:20:13] DEBUG[3032] app_macro.c: Executed application: AGI
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – Executing [s@macro-dial:7] Dial(“SIP/39-08ade1a8”, “SIP/3002||tr”) in new stack
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – Called 3002
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – SIP/3002-08b02ae0 is ringing
[Oct 13 15:20:13] VERBOSE[3032] logger.c: – SIP/3002-08b02ae0 answered SIP/39-08ade1a8
[Oct 13 15:20:25] NOTICE[2688] chan_sip.c: – Registration for ‘09[email protected]’ timed out, trying again (Attempt #133)
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [7777@from-internal:1] Goto(“SIP/3001-08af9798”, “from-pstn|s|1”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Goto (from-pstn,s,1)
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:1] Set(“SIP/3001-08af9798”, “__FROM_DID=s”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:2] GotoIf(“SIP/3001-08af9798”, “1 ?cidok”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Goto (from-pstn,s,4)
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:4] NoOp(“SIP/3001-08af9798”, “CallerID is “device” <3001>”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:5] Set(“SIP/3001-08af9798”, “FAX_RX=system”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:6] Set(“SIP/3001-08af9798”, "[email protected]") in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:7] Answer(“SIP/3001-08af9798”, “”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@from-pstn:8] PlayTones(“SIP/3001-08af9798”, “ring”) in new stack
[Oct 13 15:20:26] WARNING[3037] pbx.c: No application ‘NVFaxDetect’ for extension (from-pstn, s, 9)
[Oct 13 15:20:26] VERBOSE[3037] logger.c: == Spawn extension (from-pstn, s, 9) exited non-zero on ‘SIP/3001-08af9798’
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [h@from-pstn:1] NoOp(“SIP/3001-08af9798”, “Catch-All DID Match - Found h - You probably want a DID for this.”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [h@from-pstn:2] Goto(“SIP/3001-08af9798”, “ext-did|s|1”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Goto (ext-did,s,1)
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@ext-did:1] Set(“SIP/3001-08af9798”, “__FROM_DID=s”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@ext-did:2] GotoIf(“SIP/3001-08af9798”, “1 ?cidok”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Goto (ext-did,s,4)
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@ext-did:4] NoOp(“SIP/3001-08af9798”, “CallerID is “device” <3001>”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@ext-did:5] Set(“SIP/3001-08af9798”, “FAX_RX=system”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@ext-did:6] Set(“SIP/3001-08af9798”, "[email protected]") in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: – Executing [s@ext-did:7] Answer(“SIP/3001-08af9798”, “”) in new stack
[Oct 13 15:20:26] VERBOSE[3037] logger.c: == Spawn extension (ext-did, s, 7) exited non-zero on ‘SIP/3001-08af9798’
[Oct 13 15:20:32] VERBOSE[3032] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/39-08ade1a8’ in macro ‘dial’
[Oct 13 15:20:32] VERBOSE[3032] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/39-08ade1a8’ in macro ‘exten-vm’
[Oct 13 15:20:32] VERBOSE[3032] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/39-08ade1a8’
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [h@macro-dial:1] Macro(“SIP/39-08ade1a8”, “hangupcall”) in new stack
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/39-08ade1a8”, “w”) in new stack
[Oct 13 15:20:32] DEBUG[3032] app_macro.c: Executed application: ResetCDR
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“SIP/39-08ade1a8”, “”) in new stack
[Oct 13 15:20:32] DEBUG[3032] app_macro.c: Executed application: NoCDR
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“SIP/39-08ade1a8”, “1?skiprg”) in new stack
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Goto (macro-hangupcall,s,6)
[Oct 13 15:20:32] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“SIP/39-08ade1a8”, “1?skipblkvm”) in new stack
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Goto (macro-hangupcall,s,9)
[Oct 13 15:20:32] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“SIP/39-08ade1a8”, “1?theend”) in new stack
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Goto (macro-hangupcall,s,11)
[Oct 13 15:20:32] DEBUG[3032] app_macro.c: Executed application: GotoIf
[Oct 13 15:20:32] VERBOSE[3032] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“SIP/39-08ade1a8”, “”) in new stack
[Oct 13 15:20:32] VERBOSE[3032] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/39-08ade1a8’ in macro ‘hangupcall’
[Oct 13 15:20:32] VERBOSE[3032] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/39-08ade1a8’
[Oct 13 15:20:34] VERBOSE[3039] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Oct 13 15:20:34] VERBOSE[3039] logger.c: Found
[Oct 13 15:20:34] VERBOSE[3039] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Oct 13 15:20:34] VERBOSE[3039] logger.c: Found
[Oct 13 15:20:34] VERBOSE[3039] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Oct 13 15:20:34] VERBOSE[3039] logger.c: Found
[Oct 13 15:20:34] VERBOSE[3039] logger.c: == Manager ‘admin’ logged on from 127.0.0.1

3

The problem is definitely with the 7777 processing in asterisk/freepbx. maybe because I started to investigate IVR on friday evening then decided to plan the IVR menus befor starting to make changes. I couldn’t see any change in freepbx, but maybe something was changed and not changed back :frowning:

Today I changed the Feature Code > Simulate Incoming Call to 777 (three digits) and incoming calls get a call cannot be completed as dialled message.

Then i setup a Ring Group called 7777 (four digits) which ring all extensions. Since I had recorded a welcome message on Friday I also added this as an announcement in the Ring Group 7777 … and got our system working again.

Thanks to all for your help. This really shows off the main feature of open source … in order to use the software you must first become an expert in it.

4