Grandstream HT503 doesn't HangUP

mogan · September 5, 2015, 4:43pm

Hello, my configuration is:
Asterisk (Ver. 11.18.0)
FreePBX 12.0.76

I’m using Grandstream HT503 (HT-503 V2.0A Software Version: Program – 1.0.14.1; Bootloader – 1.0.0.18; Core – 1.0.14.1; Base – 1.0.14.1; Extra – 1.0.14.1; CPE – 1.0.1.48) to connect to a PSTN line and it’s working, i can place call using an outbound route and incoming calls ring on ring group correctly.
The problem is that it doesn’t hang up correctly, but only after (exactly) 60 seconds that I terminate the call on the pbx’s phones.

Here are some config files i use, If you need more details just ask.

TRUNKS

Trunk name 503
Outbound CallerID 20002000
Maximum Channels: 	1
*Outgoing Settings*
Trunk Name: landline
PEER Details:
type=peer
authname=20002000
secret=mysecret
host=192.168.100.128
port=5062
disallow=all
allow=ulaw&alaw&gsm
canreinvite=no
dtmfmode=rfc2833
context=internal-phones
qualify=yes
hanguponpolarityswitch=yes
*Incoming Settings*
USER Context: empty
USER Details: empty
*Registration* 
Register String: empty

EXTENSION

Display Name = 20002000
Secret = mysecret
DTMF Signaling = RFC2833	
Can Reinvite = no
Context = from-internal
Host = dynamic
Trust RPID = yes
Media Encryption = none
Send RPID = send P-Asserted-Identity Header
Connection Type = friend 	
NAT Mode = no
Port = 5060
Qualify = yes
Qualify Frequency = 60 	
Transport  = All-UDP primary
Enable AVPF = no
Force AVP = no
Enable ICE Support = no
Enable Encryption = no

Here you can find grandstream config settings (add http cause I can’t put images in topic).
://www.marcogiannini.it/temp/basic.png
://www.marcogiannini.it/temp/advanced.png
://www.marcogiannini.it/temp/fxs.png
://www.marcogiannini.it/temp/fxo.png

Thanks for helping.
Marco

dicko · September 5, 2015, 5:25pm

Your ATA is responsible for “hang-up supervision”, the settings on your fxo page need to agree with what your telco sends to signal a hangup condition (if indeed they are providing that in the first place) I would check with them .

mogan · September 5, 2015, 6:11pm

Thanks for your reply. I will go through that line.

mogan · September 5, 2015, 7:06pm

BTW I’m not sure is exactly like you say cause I think the problem is in the way the PBX send the hang up tone to the ata cause the incoming call goes this way

PSTN ----> Ata-FXO -----> via sip to the PBX -----> Extension

When the extension hang up the PBX have to pass this event to the ATA that is the fisical device connected to the line and the only one appointed to hang up the call.

When the hang up comes from the PSTN line (e.g. the person outside hang up), the PBX/ATA has no problem to register the event.

I think the problem is in the way the pbx send the hang up signal to the ata.
Am I wrong?

EDIT:

Here is a log from a call made with my mobile to the pstn line.

[2015-09-05 21:19:19] VERBOSE[1806][C-00000058] netsock2.c: == Using SIP RTP TOS bits 184
[2015-09-05 21:19:19] VERBOSE[1806][C-00000058] netsock2.c: == Using SIP RTP CoS mark 5
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:1] Macro("SIP/20002000-000000d3", "user-callerid,") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/20002000-000000d3", "TOUCH_MONITOR=1441480759.211") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/20002000-000000d3", "AMPUSER=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/20002000-000000d3", "0?report") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/20002000-000000d3", "1?Set(REALCALLERIDNUM=20002000)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/20002000-000000d3", "AMPUSER=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/20002000-000000d3", "0?limit") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/20002000-000000d3", "AMPUSERCIDNAME=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/20002000-000000d3", "0?report") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/20002000-000000d3", "AMPUSERCID=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/20002000-000000d3", "__DIAL_OPTIONS=Ttr") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/20002000-000000d3", "CALLERID(all)="20002000" <20002000>") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/20002000-000000d3", "0?limit") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/20002000-000000d3", "0?Set(GROUP(concurrency_limit)=20002000)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:14] GosubIf("SIP/20002000-000000d3", "7?sub-ccss,s,1(from-internal,600)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/20002000-000000d3", "0?Return()") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/20002000-000000d3", "CCSS_SETUP=TRUE") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/20002000-000000d3", "0?monitor_config,1(from-internal,600):monitor_default,1(from-internal,600)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/20002000-000000d3", "0?is_exten") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/20002000-000000d3", "") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/20002000-000000d3", "FALSE") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:15] ExecIf("SIP/20002000-000000d3", "0?Set(CHANNEL(language)=)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/20002000-000000d3", "0?continue") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:17] ExecIf("SIP/20002000-000000d3", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:18] Set("SIP/20002000-000000d3", "__TTL=64") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:19] GotoIf("SIP/20002000-000000d3", "1?continue") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Goto (macro-user-callerid,s,30)
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/20002000-000000d3", "CALLERID(number)=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/20002000-000000d3", "CALLERID(name)=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/20002000-000000d3", "CDR(cnum)=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/20002000-000000d3", "CDR(cnam)=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-user-callerid:34] Set("SIP/20002000-000000d3", "CHANNEL(language)=en") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:2] Macro("SIP/20002000-000000d3", "blkvm-setifempty,") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/20002000-000000d3", "1?init") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Goto (macro-blkvm-setifempty,s,4)
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/20002000-000000d3", "__BLKVM_CHANNEL=SIP/20002000-000000d3") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/20002000-000000d3", "SHARED(BLKVM,SIP/20002000-000000d3)=TRUE") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/20002000-000000d3", "GOSUB_RETVAL=TRUE") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/20002000-000000d3", "") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:3] GotoIf("SIP/20002000-000000d3", "1?skipov") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Goto (from-internal,600,6)
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:6] Set("SIP/20002000-000000d3", "RRNODEST=") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:7] Set("SIP/20002000-000000d3", "__NODEST=600") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:8] GosubIf("SIP/20002000-000000d3", "0?sub-rgsetcid,s,1()") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:9] Gosub("SIP/20002000-000000d3", "sub-record-check,s,1(rg,600,dontcare)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/20002000-000000d3", "0?initialized") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:2] Set("SIP/20002000-000000d3", "__REC_STATUS=INITIALIZED") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:3] Set("SIP/20002000-000000d3", "NOW=1441480759") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:4] Set("SIP/20002000-000000d3", "__DAY=05") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:5] Set("SIP/20002000-000000d3", "__MONTH=09") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/20002000-000000d3", "__YEAR=2015") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/20002000-000000d3", "__TIMESTR=20150905-211919") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:8] Set("SIP/20002000-000000d3", "__FROMEXTEN=20002000") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:9] Set("SIP/20002000-000000d3", "__MON_FMT=wav") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/20002000-000000d3", "Recordings initialized") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/20002000-000000d3", "0?Set(ARG3=dontcare)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/20002000-000000d3", "REC_POLICY_MODE_SAVE=") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/20002000-000000d3", "0?Set(REC_STATUS=NO)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/20002000-000000d3", "2?checkaction") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Goto (sub-record-check,s,17)
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/20002000-000000d3", "0?sub-record-check,rg,1") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:18] NoOp("SIP/20002000-000000d3", "Generic rg Recording Check - 20002000 600") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:19] Gosub("SIP/20002000-000000d3", "recordcheck,1(dontcare,rg,600)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/20002000-000000d3", "Starting recording check against dontcare") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/20002000-000000d3", "dontcare") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Goto (sub-record-check,recordcheck,3)
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [recordcheck@sub-record-check:3] Return("SIP/20002000-000000d3", "") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@sub-record-check:20] Return("SIP/20002000-000000d3", "") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:10] Set("SIP/20002000-000000d3", "RingGroupMethod=ringall") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [600@from-internal:11] Macro("SIP/20002000-000000d3", "dial,20,Ttr,2001-2000-2010") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-dial:1] GotoIf("SIP/20002000-000000d3", "1?dial") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Goto (macro-dial,s,3)
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-dial:3] AGI("SIP/20002000-000000d3", "dialparties.agi") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: dialparties.agi: Caller ID name is '20002000' number is '20002000'
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Added extension 2001 to extension map
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Added extension 2000 to extension map
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Added extension 2010 to extension map
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Extension 2001 cf is disabled
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Extension 2000 cf is disabled
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Extension 2010 cf is disabled
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Extension 2001 do not disturb is disabled
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Extension 2000 do not disturb is disabled
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Extension 2010 do not disturb is disabled
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: dbset CALLTRACE/2001 to 20002000
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: dbset CALLTRACE/2000 to 20002000
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: dbset CALLTRACE/2010 to 20002000
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- dialparties.agi: Filtered ARG3: 2001-2000-2010
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] res_agi.c: -- <SIP/20002000-000000d3>AGI Script dialparties.agi completed, returning 0
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-dial:7] Dial("SIP/20002000-000000d3", "SIP/2001&SIP/2000&SIP/2010,20,TtrM(auto-blkvm)") in new stack
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] netsock2.c: == Using SIP RTP TOS bits 184
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] netsock2.c: == Using SIP RTP CoS mark 5
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] netsock2.c: == Using SIP RTP TOS bits 184
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] netsock2.c: == Using SIP RTP CoS mark 5
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] netsock2.c: == Using SIP RTP TOS bits 184
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] netsock2.c: == Using SIP RTP CoS mark 5
[2015-09-05 21:19:19] VERBOSE[1750] chan_sip.c: == Extension Changed 2001[ext-local] new state Ringing for Notify User 2000
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- Called SIP/2001
[2015-09-05 21:19:19] VERBOSE[1750] chan_sip.c: == Extension Changed 2000[ext-local] new state Ringing for Notify User 2001
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- Called SIP/2000
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- Called SIP/2010
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2010-000000d6 connected line has changed. Saving it until answer for SIP/20002000-000000d3
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2000-000000d5 connected line has changed. Saving it until answer for SIP/20002000-000000d3
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2001-000000d4 connected line has changed. Saving it until answer for SIP/20002000-000000d3
[2015-09-05 21:19:19] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2001-000000d4 is ringing
[2015-09-05 21:19:19] VERBOSE[1750] chan_sip.c: == Extension Changed 2001[ext-local] new state Ringing for Notify User 2000
[2015-09-05 21:19:20] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2000-000000d5 is ringing
[2015-09-05 21:19:20] VERBOSE[1750] chan_sip.c: == Extension Changed 2000[ext-local] new state Ringing for Notify User 2001 (queued)
[2015-09-05 21:19:20] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2010-000000d6 is ringing
[2015-09-05 21:19:20] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2001-000000d4 is ringing
[2015-09-05 21:19:20] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2000-000000d5 is ringing
[2015-09-05 21:19:21] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2001-000000d4 is ringing
[2015-09-05 21:19:21] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2000-000000d5 is ringing
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2010-000000d6 connected line has changed. Saving it until answer for SIP/20002000-000000d3
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] app_dial.c: -- SIP/2010-000000d6 answered SIP/20002000-000000d3
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:1] Set("SIP/2010-000000d6", "__MACRO_RESULT=") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:2] Set("SIP/2010-000000d6", "CFIGNORE=") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:3] Set("SIP/2010-000000d6", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:4] Set("SIP/2010-000000d6", "FORWARD_CONTEXT=from-internal") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:5] Set("SIP/2010-000000d6", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:6] Macro("SIP/2010-000000d6", "blkvm-clr,") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("SIP/2010-000000d6", "SHARED(BLKVM,SIP/20002000-000000d3)=") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("SIP/2010-000000d6", "GOSUB_RETVAL=") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/2010-000000d6", "") in new stack
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/2010-000000d6", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=2010)") in new stack
[2015-09-05 21:19:22] VERBOSE[1750] chan_sip.c: == Extension Changed 2001[ext-local] new state Idle for Notify User 2000
[2015-09-05 21:19:22] VERBOSE[1750] chan_sip.c: == Extension Changed 2000[ext-local] new state Idle for Notify User 2001
[2015-09-05 21:19:22] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/2010-000000d6", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=2010)") in new stack
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: -- Executing [h@macro-dial:1] Macro("SIP/20002000-000000d3", "hangupcall") in new stack
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-hangupcall:1] ExecIf("SIP/20002000-000000d3", "0?Set(CDR(recordingfile)=.wav)") in new stack
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-hangupcall:2] GotoIf("SIP/20002000-000000d3", "1?theend") in new stack
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: -- Goto (macro-hangupcall,s,4)
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/20002000-000000d3", "") in new stack
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/20002000-000000d3' in macro 'hangupcall'
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/20002000-000000d3'
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/20002000-000000d3' in macro 'dial'
[2015-09-05 21:19:25] VERBOSE[9401][C-00000058] pbx.c: == Spawn extension (from-internal, 600, 11) exited non-zero on 'SIP/20002000-000000d3'

dicko · September 5, 2015, 8:02pm

hard to say, you have:-

hanguponpolarityswitch=yes

in your SIP connection to the ATA, this is not appropriate for a SIP connection. SIP has it’s own protocol for signalling hangup, your ATA must do that for you.

As an aside FXO’s will in your case only use alaw so the ulaw and especially the gsm are spurious and can cause unnecessary transcoding , the context “internal-phones” is not part of FreePBX I guess you did that, and you should not need to “qualify” with a device on your own network.

mogan · September 5, 2015, 10:56pm

I noticed that the problem is coming up only when the call start from outside. If the call start from an extension in the pbx range, the hang-up issue doesn’t appear.

I made two logs from the HT503 Syslog function But I can’t post here (no txt extensions allowed!) and they are too big to include in the text. So i posted the files on the Grandstream forum.

dicko · September 5, 2015, 11:01pm

Yep, that’s a mismatch between the ATA and the provider, You need to find out what disconnect supervision your provider supplies, (if any) and so match it. . .

james · September 6, 2015, 3:59am

you have to check the hangup detection such as busydetect from your ATA GUI.

mogan · September 6, 2015, 8:10am

Thanks a lot for your help.

I think to be near to focus the real problem.
Analyzing the Grandstream logs I found that when I hang up from internal phone (and the call started from outside) the log contain these lines:

IFX_TAPI_EVENT_FXO_APOH event received on port 1 ch 0, status=CALL_COMMUNICATION
Dispatching event: 34 (LINE_APOH) on port 1:0
ATACtrl::processFxoLineAPOH on port 1:0, status = CALL_COMMUNICATION/CALL_IDLE
SIPStack(0)::run: Active transactions: 1
SIPStack(0)::receiveMessage:(600)BYE [.........]

I think the real problem is that the ATA receive some kind of tone that make it start listening for something: that’s what the CALL_COMMUNICATION status is for.
So, when the sip “Bye” command is issued the line is not released cause the ata is waiting for “COMMUNICATION”.
That’s why after 60 secs of nothing (no communication) the ata finally release the line.

Anyone knows something more?
thanks
Marco

mogan · September 6, 2015, 8:23am

Found that APOH stands for Another Phone Off Hook.
Maybe could help.