On-hook phone hangup immediatel after answering inbound call

[laplace]

Vicibox 8.0.0-beta from .iso | Vicidial v.2.14-628a build 170913-0908 | Asterisk 11.25.1-vici | Single server setup | No Digium/Sangoma Hardware | No Extra Software After Installation
My setup for inbound center works fine, I have grandstream gateway with 8 POTS configured as a trunk, 3 agents and Zoiper Biz softphones. I double checked all possible codecs issues and excluded it.
When I receive an inbound call with DID routed to in-group and call gets assigned to on-hook agent, the soft phone rings but once I answer it hangs up. The same happens if I set the DID to an agent directly (I noticed that there is a "forbidden" reply from in the log). This applies to other tested softphoes (GS Wave).
Otherwise if on-hook is set to NO the phone rings into conference when the agent logs in and can normally get calls from customers, also if configured she can grab a call from the queue, and if DID is routed to phone it rings and answers normally.
Any suggestion is highly appreciated.

Sample log for on-hook agent issue

Code: Select all

Oct  4 22:42:02]     -- <SIP/001-00000006> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:02] <SIP/001-00000006>AGI Tx >> 200 result=0 endpos=160
[Oct  4 22:42:02]     -- <SIP/001-00000006>AGI Script agi-VDAD_inbound_calltime_check.agi completed, returning 0
[Oct  4 22:42:02]     -- Executing [s@Main_Menu:3] Set("SIP/001-00000006", "INVCOUNT=0") in new stack
[Oct  4 22:42:02]     -- Executing [s@Main_Menu:4] BackGround("SIP/001-00000006", "1-Greetings_converted") in new stack
[Oct  4 22:42:02]     -- <SIP/001-00000006> Playing '1-Greetings_converted.slin' (language 'en')
[Oct  4 22:42:04] DTMF[5755][C-00000005]: channel.c:4215 __ast_read: DTMF begin '1' received on SIP/001-00000006
[Oct  4 22:42:04] DTMF[5755][C-00000005]: channel.c:4219 __ast_read: DTMF begin ignored '1' on SIP/001-00000006
[Oct  4 22:42:04] DTMF[5755][C-00000005]: channel.c:4129 __ast_read: DTMF end '1' received on SIP/001-00000006, duration 100 ms
[Oct  4 22:42:04] DTMF[5755][C-00000005]: channel.c:4199 __ast_read: DTMF end passthrough '1' on SIP/001-00000006
[Oct  4 22:42:04]     -- Executing [1@Main_Menu:1] AGI("SIP/001-00000006", "agi-VDAD_ALL_inbound.agi,CID-----SO-----001-----Main_Menu--------------------998-----1-----IN01------------------------------") in new stack
[Oct  4 22:42:04]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_request: agi-VDAD_ALL_inbound.agi
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_channel: SIP/001-00000006
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_language: en
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_type: SIP
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_uniqueid: 1507146122.12
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_version: 11.25.1-vici
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_callerid: 5692
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_calleridname: unknown
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_callingpres: 0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_callingani2: 0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_callington: 0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_callingtns: 0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_dnid: 001
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_rdnis: unknown
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_context: Main_Menu
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_extension: 1
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_priority: 1
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_enhanced: 0.0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_accountcode:
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_threadid: 140669880637184
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> agi_arg_1: CID-----SO-----001-----Main_Menu--------------------998-----1-----IN01------------------------------
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >>
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << GET VARIABLE state
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << GET VARIABLE postal_code
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=0
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << STREAM FILE sip-silence ""
[Oct  4 22:42:04]     -- <SIP/001-00000006> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=0 endpos=160
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << STREAM FILE sip-silence ""
[Oct  4 22:42:04]     -- <SIP/001-00000006> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=0 endpos=160
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << SET CALLERID "Y0042242040000000150 <5692>"
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=1
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:04]   == Manager 'sendcron' logged on from 127.0.0.1
[Oct  4 22:42:04]     -- Executing [192*168*050*011*8050@default:1] Goto("Local/192*168*050*011*8050@default-00000003;2", "default,8050,1") in new stack
[Oct  4 22:42:04]     -- Goto (default,8050,1)
[Oct  4 22:42:04]     -- Executing [8050@default:1] Dial("Local/192*168*050*011*8050@default-00000003;2", "SIP/8050,60,") in new stack
[Oct  4 22:42:04]   == Using SIP RTP CoS mark 5
[Oct  4 22:42:04]     -- Called SIP/8050
[Oct  4 22:42:04]     -- SIP/8050-00000007 is ringing
[Oct  4 22:42:04] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:04] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:05] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:05] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:05] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:05] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:05] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:05] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:05] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:05] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:06] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:06] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:06] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:06] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:06] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:06] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:06] <SIP/001-00000006>AGI Rx << SET MUSIC ON default
[Oct  4 22:42:06]     -- Started music on hold, class 'default', on SIP/001-00000006
[Oct  4 22:42:06] <SIP/001-00000006>AGI Tx >> 200 result=0
[Oct  4 22:42:06]   == Manager 'sendcron' logged on from 127.0.0.1
[Oct  4 22:42:06]   == Manager 'sendcron' logged off from 127.0.0.1
[Oct  4 22:42:07] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:07] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:08]        > 0x7ff0b0014430 -- Probation passed - setting RTP source address to 192.168.50.64:8000
[Oct  4 22:42:08] NOTICE[5765][C-00000006]: res_rtp_asterisk.c:4519 ast_rtp_read: Unknown RTP codec 95 received from '192.168.50.64:8000'
[Oct  4 22:42:08]     -- SIP/8050-00000007 answered Local/192*168*050*011*8050@default-00000003;2
[Oct  4 22:42:08]        > Channel Local/192*168*050*011*8050@default-00000003;1 was answered
[Oct  4 22:42:08]     -- Executing [138331*3*Y0042242040000000150*8050*8050@default:1] AGI("SIP/8050-00000007", "agi://127.0.0.1:4577/call_log") in new stack
[Oct  4 22:42:08]     -- Executing [h@default:1] AGI("Local/192*168*050*011*8050@default-00000003;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----0") in new stack
[Oct  4 22:42:08] AGI Tx >> agi_network: yes
[Oct  4 22:42:08] AGI Tx >> agi_network: yes
[Oct  4 22:42:08] AGI Tx >> agi_network_script: call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----0
[Oct  4 22:42:08] AGI Tx >> agi_network_script: call_log
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----0
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_channel: Local/192*168*050*011*8050@default-00000003;2
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_language: en
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_channel: SIP/8050-00000007
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_type: Local
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_language: en
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_uniqueid: 1507146124.14
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_type: SIP
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_version: 11.25.1-vici
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_uniqueid: 1507146124.13
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_version: 11.25.1-vici
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_callerid: 5692
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callerid: 8050
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_calleridname: unknown
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_calleridname: 8050
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_callingpres: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callingpres: 0
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_callingani2: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callingani2: 0
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_callington: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callington: 0
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_callingtns: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callingtns: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_dnid: unknown
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_dnid: unknown
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_rdnis: unknown
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_rdnis: unknown
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_context: default
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_extension: 138331*3*Y0042242040000000150*8050*8050
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_context: default
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_extension: h
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_priority: 1
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_priority: 1
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_enhanced: 0.0
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_enhanced: 0.0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_accountcode:
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_accountcode:
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_threadid: 140669876922112
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> agi_threadid: 140669879621376
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >>
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >>
[Oct  4 22:42:08]     -- <SIP/8050-00000007>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> HANGUP
[Oct  4 22:42:08]     -- Executing [138331*3*Y0042242040000000150*8050*8050@default:2] Dial("SIP/8050-00000007", "SIP/001/138331*3*Y0042242040000000150*8050*8050,,tTo") in new stack
[Oct  4 22:42:08]     -- <Local/192*168*050*011*8050@default-00000003;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----0 completed, returning 0
[Oct  4 22:42:08] <Local/192*168*050*011*8050@default-00000003;2>AGI Tx >> HANGUP
[Oct  4 22:42:08]   == Using SIP RTP CoS mark 5
[Oct  4 22:42:08] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:08] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:08]     -- Called SIP/001/138331*3*Y0042242040000000150*8050*8050
[Oct  4 22:42:08] WARNING[2803][C-00000006]: chan_sip.c:23322 handle_response_invite: Received response: "Forbidden" from '"8050" <sip:8050@192.168.50.11>;tag=as5dd7e93f'
[Oct  4 22:42:08]   == Everyone is busy/congested at this time (1:0/0/1)
[Oct  4 22:42:08]     -- Executing [138331*3*Y0042242040000000150*8050*8050@default:3] Hangup("SIP/8050-00000007", "") in new stack
[Oct  4 22:42:08]   == Spawn extension (default, 138331*3*Y0042242040000000150*8050*8050, 3) exited non-zero on 'SIP/8050-00000007'
[Oct  4 22:42:08]     -- Executing [h@default:1] AGI("SIP/8050-00000007", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CHANUNAVAIL----------") in new stack
[Oct  4 22:42:08] AGI Tx >> agi_network: yes
[Oct  4 22:42:08] AGI Tx >> agi_network_script: call_log--HVcauses--PRI-----NODEBUG-----21-----CHANUNAVAIL----------
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CHANUNAVAIL----------
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_channel: SIP/8050-00000007
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_language: en
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_type: SIP
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_uniqueid: 1507146124.13
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_version: 11.25.1-vici
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callerid: 8050
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_calleridname: 8050
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callingpres: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callingani2: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callington: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_callingtns: 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_dnid: unknown
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_rdnis: unknown
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_context: default
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_extension: h
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_priority: 1
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_enhanced: 0.0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_accountcode:
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> agi_threadid: 140669876922112
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >>
[Oct  4 22:42:08]     -- <SIP/8050-00000007>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CHANUNAVAIL---------- completed, returning 0
[Oct  4 22:42:08] <SIP/8050-00000007>AGI Tx >> HANGUP
[Oct  4 22:42:08]   == Spawn extension (default, 8050, 1) exited non-zero on 'Local/192*168*050*011*8050@default-00000003;2'
[Oct  4 22:42:09] <SIP/001-00000006>AGI Rx << CHANNEL STATUS SIP/001-00000006
[Oct  4 22:42:09] <SIP/001-00000006>AGI Tx >> 200 result=6
[Oct  4 22:42:09]   == Manager 'sendcron' logged off from 127.0.0.1
[Oct  4 22:42:09] <SIP/001-00000006>AGI Rx << STREAM FILE sip-silence ""
[Oct  4 22:42:09]     -- Stopped music on hold on SIP/001-00000006
[Oct  4 22:42:09]     -- <SIP/001-00000006> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:09] <SIP/001-00000006>AGI Tx >> 200 result=0 endpos=160
[Oct  4 22:42:09] <SIP/001-00000006>AGI Rx << STREAM FILE sip-silence ""
[Oct  4 22:42:09]     -- <SIP/001-00000006> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:09] <SIP/001-00000006>AGI Tx >> 200 result=0 endpos=160
[Oct  4 22:42:09] <SIP/001-00000006>AGI Rx << STREAM FILE sip-silence ""
[Oct  4 22:42:09]     -- <SIP/001-00000006> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:09] <SIP/001-00000006>AGI Tx >> 200 result=0 endpos=160
[Oct  4 22:42:09] <SIP/001-00000006>AGI Rx << STREAM FILE generic_hold ""
[Oct  4 22:42:09]     -- <SIP/001-00000006> Playing 'generic_hold.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> 200 result=-1 endpos=28960
[Oct  4 22:42:13]     -- <SIP/001-00000006>AGI Script agi-VDAD_ALL_inbound.agi completed, returning 4
[Oct  4 22:42:13]   == Spawn extension (Main_Menu, 1, 1) exited non-zero on 'SIP/001-00000006'
[Oct  4 22:42:13]     -- Executing [h@Main_Menu:1] AGI("SIP/001-00000006", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Oct  4 22:42:13] AGI Tx >> agi_network: yes
[Oct  4 22:42:13] AGI Tx >> agi_network_script: call_log--HVcauses--PRI-----NODEBUG-----0---------------
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_channel: SIP/001-00000006
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_language: en
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_type: SIP
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_uniqueid: 1507146122.12
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_version: 11.25.1-vici
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_callerid: 5692
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_calleridname: Y0042242040000000150
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_callingpres: 0
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_callingani2: 0
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_callington: 0
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_callingtns: 0
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_dnid: 001
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_rdnis: unknown
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_context: Main_Menu
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_extension: h
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_priority: 1
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_enhanced: 0.0
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_accountcode:
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> agi_threadid: 140669880637184
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >>
[Oct  4 22:42:13]     -- <SIP/001-00000006>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Oct  4 22:42:13] <SIP/001-00000006>AGI Tx >> HANGUP


Sample with direct call menu to phone with no issue

Code: Select all

[Oct  4 22:48:26] DTMF[6570][C-00000007]: channel.c:4215 __ast_read: DTMF begin '2' received on SIP/001-00000009
[Oct  4 22:48:26] DTMF[6570][C-00000007]: channel.c:4219 __ast_read: DTMF begin ignored '2' on SIP/001-00000009
[Oct  4 22:48:26] DTMF[6570][C-00000007]: channel.c:4129 __ast_read: DTMF end '2' received on SIP/001-00000009, duration 100 ms
[Oct  4 22:48:26] DTMF[6570][C-00000007]: channel.c:4199 __ast_read: DTMF end passthrough '2' on SIP/001-00000009
[Oct  4 22:48:26]     -- Executing [2@Main_Menu:1] Goto("SIP/001-00000009", "default,192*168*050*011*8050,1") in new stack
[Oct  4 22:48:26]     -- Goto (default,192*168*050*011*8050,1)
[Oct  4 22:48:26]     -- Executing [192*168*050*011*8050@default:1] Goto("SIP/001-00000009", "default,8050,1") in new stack
[Oct  4 22:48:26]     -- Goto (default,8050,1)
[Oct  4 22:48:26]     -- Executing [8050@default:1] Dial("SIP/001-00000009", "SIP/8050,60,") in new stack
[Oct  4 22:48:26]   == Using SIP RTP CoS mark 5
[Oct  4 22:48:26]     -- Called SIP/8050
[Oct  4 22:48:26]        > 0x7ff05c0255c0 -- Probation passed - setting RTP source address to 192.168.50.220:5020
[Oct  4 22:48:26]     -- SIP/8050-0000000a is ringing
[Oct  4 22:48:29]        > 0x7feff003b3e0 -- Probation passed - setting RTP source address to 192.168.50.64:8000
[Oct  4 22:48:29] NOTICE[6570][C-00000007]: res_rtp_asterisk.c:4519 ast_rtp_read: Unknown RTP codec 95 received from '192.168.50.64:8000'
[Oct  4 22:48:29]        > 0x7feff003b3e0 -- Probation passed - setting RTP source address to 192.168.50.64:8000
[Oct  4 22:48:30]     -- SIP/8050-0000000a answered SIP/001-00000009
[Oct  4 22:48:30]        > 0x7feff003b3e0 -- Probation passed - setting RTP source address to 192.168.50.64:8000
[Oct  4 22:48:30]        > 0x7ff05c0255c0 -- Probation passed - setting RTP source address to 192.168.50.220:5020
[Oct  4 22:48:39]     -- Executing [h@default:1] AGI("SIP/001-00000009", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----18-----9") in new stack
[Oct  4 22:48:39] AGI Tx >> agi_network: yes
[Oct  4 22:48:39] AGI Tx >> agi_network_script: call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----18-----9
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----18-----9
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_channel: SIP/001-00000009
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_language: en
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_type: SIP
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_uniqueid: 1507146501.17
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_version: 11.25.1-vici
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_callerid: 569
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_calleridname: unknown
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_callingpres: 0
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_callingani2: 0
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_callington: 0
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_callingtns: 0
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_dnid: 001
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_rdnis: unknown
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_context: default
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_extension: h
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_priority: 1
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_enhanced: 0.0
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_accountcode:
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >> agi_threadid: 140669880637184
[Oct  4 22:48:39] <SIP/001-00000009>AGI Tx >>
[Oct  4 22:48:40]     -- <SIP/001-00000009>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----18-----9 completed, returning 0
[Oct  4 22:48:40] <SIP/001-00000009>AGI Tx >> HANGUP
[Oct  4 22:48:40]   == Spawn extension (default, 8050, 1) exited non-zero on 'SIP/001-00000009'


[laplace]

I tried the same scenario with fresh installation (vicibox 8.0.1 without any update) simplest configuration, same issue.

-- Called SIP/001/138331*1*Y0050330300000000008*8050*8050
[Oct 5 03:30:33] == Spawn extension (default, 8050, 1) exited non-zero on 'Local/192*168*050*012*8050@default-00000001;2'
[Oct 5 03:30:33] WARNING[2687][C-00000006]: chan_sip.c:23322 handle_response_invite: Received response: "Forbidden" from '"8050" <sip:8050@192.168.50.12>;tag=as4829a1dd'

[ftartari]

Vicibox 8.0.0-beta from .iso | Vicidial v.2.14-628a build 170913-0908 | Asterisk 11.25.1-vici | Single server setup | No Digium/Sangoma Hardware | No Extra Software After Installation
My setup for inbound center works fine, I have grandstream gateway with 8 POTS configured as a trunk, 3 agents and Zoiper Biz softphones. I double checked all possible codecs issues and excluded it.
When I receive an inbound call with DID routed to in-group and call gets assigned to on-hook agent, the soft phone rings but once I answer it hangs up. The same happens if I set the DID to an agent directly (I noticed that there is a "forbidden" reply from in the log). This applies to other tested softphoes (GS Wave).
Otherwise if on-hook is set to NO the phone rings into conference when the agent logs in and can normally get calls from customers, also if configured she can grab a call from the queue, and if DID is routed to phone it rings and answers normally.
Any suggestion is highly appreciated.

I have exactly the same problem as you.

I upgraded to 8.1.0 in the hope of solving but I was not lucky.

current:
VERSION: 2.14b0.5
SVN Version: 3053
DB Schema Version: 1561
DB Schema Update Date: 2018-10-30 20:04:22

Have you discovered anything that might be causing this?

Thanks

[ftartari]

i found solution!!!!!!!!!!!

on inbound groups option On-Hook CID

only GENERIC or CUSTOMER_PHONE_RING_AGENT will work. Any other option call hangup on answer by agent.

on this option hint has an alert "If you are using Asterisk 13 or higher, only the RINGAGENT options will work properly."

I use asterisk 13 and not observe this.

[williamconley]

i found solution!!!!!!!!!!!

on inbound groups option On-Hook CID

only GENERIC or CUSTOMER_PHONE_RING_AGENT will work. Any other option call hangup on answer by agent.

on this option hint has an alert "If you are using Asterisk 13 or higher, only the RINGAGENT options will work properly."

I use asterisk 13 and not observe this.

Excellent postback! Well done.

[dominikPL]

Hi, Wiliam can you give me information if you plan to solve this problem?

[williamconley]

Hi, Wiliam can you give me information if you plan to solve this problem?

you haven't stated a problem. others did, and they posted their asterisk CLI output so we could actually see what the problem was. AFAIK your system is working as it should until you provide some inkling of why we should think otherwise.

[dominikPL]

I mean this problem

only GENERIC or CUSTOMER_PHONE_RING_AGENT will work. Any other option call hangup on answer by agent.

I set ingroup On-Hook CID CUSTOMER_PHONE_INGROUP
Here my CLI output, beginning when agent log in, end when phone ring second time. Agent on hook phone 2222.

Code: Select all

[Aug  2 07:18:53]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug  2 07:18:53]     -- Called 8300@default
[Aug  2 07:18:53]     -- Executing [8300@default:1] Hangup("Local/8300@default-00000060;2", "") in new stack
[Aug  2 07:18:53]   == Spawn extension (default, 8300, 1) exited non-zero on 'Local/8300@default-00000060;2'
[Aug  2 07:18:53] WARNING[14341][C-000000e3]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[Aug  2 07:18:53]     -- Executing [h@default:1] AGI("Local/8300@default-00000060;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------)") in new stack
[Aug  2 07:18:53]     -- <Local/8300@default-00000060;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------) completed, returning 0
[Aug  2 07:18:54]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug  2 07:19:01]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug  2 07:19:01]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug  2 07:19:03]   == Using SIP RTP CoS mark 5
[Aug  2 07:19:03]        > 0x136c520 -- Strict RTP learning after remote address set to: 192.168.32.21:16178
[Aug  2 07:19:03]     -- Executing [scc_test@trunkinbound:1] AGI("SIP/TELCOtest-00000067", "agi-DID_route.agi") in new stack
[Aug  2 07:19:03]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-DID_route.agi
[Aug  2 07:19:04]     -- <SIP/TELCOtest-00000067>AGI Script agi-DID_route.agi completed, returning 0
[Aug  2 07:19:04]     -- Executing [s@IVR:1] Answer("SIP/TELCOtest-00000067", "") in new stack
[Aug  2 07:19:04]     -- Executing [s@IVR:2] AGI("SIP/TELCOtest-00000067", "agi-VDAD_inbound_calltime_check.agi,kolejka-----YES-----IVR-------------------------NO") in new stack
[Aug  2 07:19:04]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_inbound_calltime_check.agi
[Aug  2 07:19:04]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:04]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:04]     -- <SIP/TELCOtest-00000067>AGI Script agi-VDAD_inbound_calltime_check.agi completed, returning 0
[Aug  2 07:19:04]     -- Executing [s@IVR:3] Set("SIP/TELCOtest-00000067", "INVCOUNT=0") in new stack
[Aug  2 07:19:04]     -- Executing [s@IVR:4] BackGround("SIP/TELCOtest-00000067", "prompt") in new stack
[Aug  2 07:19:04]     -- <SIP/TELCOtest-00000067> Playing 'prompt.slin' (language 'en')
[Aug  2 07:19:04]        > 0x136c520 -- Strict RTP switching to RTP target address 192.168.32.21:16178 as source
[Aug  2 07:19:06] DTMF[14395][C-000000e4]: channel.c:4124 __ast_read: DTMF begin '3' received on SIP/TELCOtest-00000067
[Aug  2 07:19:06] DTMF[14395][C-000000e4]: channel.c:4128 __ast_read: DTMF begin ignored '3' on SIP/TELCOtest-00000067
[Aug  2 07:19:06] DTMF[14395][C-000000e4]: channel.c:4038 __ast_read: DTMF end '3' received on SIP/TELCOtest-00000067, duration 260 ms
[Aug  2 07:19:06] DTMF[14395][C-000000e4]: channel.c:4108 __ast_read: DTMF end passthrough '3' on SIP/TELCOtest-00000067
[Aug  2 07:19:06]     -- Executing [3@IVR:1] AGI("SIP/TELCOtest-00000067", "cm.agi,kolejka-----3-----NONE-----0-----0") in new stack
[Aug  2 07:19:06]     -- Launched AGI Script /usr/share/asterisk/agi-bin/cm.agi
[Aug  2 07:19:06]     -- <SIP/TELCOtest-00000067>AGI Script cm.agi completed, returning 0
[Aug  2 07:19:06]     -- Executing [3@IVR:2] AGI("SIP/TELCOtest-00000067", "agi-VDAD_ALL_inbound.agi,CID-----LB-----kolejka-----IVR--------------------998----------TESTCAMP------------------------------") in new stack
[Aug  2 07:19:06]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
[Aug  2 07:19:07]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:07]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:07]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug  2 07:19:07]     -- Called 010*022*021*121*2222@default
[Aug  2 07:19:07]     -- Executing [010*022*021*121*2222@default:1] Goto("Local/010*022*021*121*2222@default-00000061;2", "default,2222,1") in new stack
[Aug  2 07:19:07]     -- Goto (default,2222,1)
[Aug  2 07:19:07]     -- Executing [2222@default:1] Dial("Local/010*022*021*121*2222@default-00000061;2", "SIP/2222,60,") in new stack
[Aug  2 07:19:07]   == Using SIP RTP CoS mark 5
[Aug  2 07:19:07]     -- Called SIP/2222
[Aug  2 07:19:07]     -- SIP/2222-00000068 is ringing
[Aug  2 07:19:07]     -- Local/010*022*021*121*2222@default-00000061;1 is ringing
[Aug  2 07:19:08]        > 0x136c520 -- Strict RTP learning complete - Locking on source address 192.168.32.21:16178
[Aug  2 07:19:09]     -- Started music on hold, class 'default', on channel 'SIP/TELCOtest-00000067'
[Aug  2 07:19:10]        > 0x7f1690012020 -- Strict RTP learning after remote address set to: 10.22.21.104:4006
[Aug  2 07:19:10]     -- SIP/2222-00000068 answered Local/010*022*021*121*2222@default-00000061;2
[Aug  2 07:19:10]     -- Local/010*022*021*121*2222@default-00000061;1 answered
[Aug  2 07:19:10]     -- Executing [138331*69*Y8020719070000000095*1234*2222@default:1] AGI("Local/010*022*021*121*2222@default-00000061;1", "agi-VDAD_local_optimize.agi,kolejka0224634081") in new stack
[Aug  2 07:19:10]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_local_optimize.agi
[Aug  2 07:19:10]     -- Channel SIP/2222-00000068 joined 'simple_bridge' basic-bridge <ec979d3e-99e5-4cae-948d-e0f37d438b85>
[Aug  2 07:19:10]     -- Channel Local/010*022*021*121*2222@default-00000061;2 joined 'simple_bridge' basic-bridge <ec979d3e-99e5-4cae-948d-e0f37d438b85>
[Aug  2 07:19:10]        > 0x7f1690012020 -- Strict RTP switching to RTP target address 10.22.21.104:4006 as source
[Aug  2 07:19:10]     -- <Local/010*022*021*121*2222@default-00000061;1>AGI Script agi-VDAD_local_optimize.agi completed, returning 0
[Aug  2 07:19:10]     -- Executing [138331*69*Y8020719070000000095*1234*2222@default:2] Wait("Local/010*022*021*121*2222@default-00000061;1", "2") in new stack
[Aug  2 07:19:11]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug  2 07:19:12]     -- Stopped music on hold on SIP/TELCOtest-00000067
[Aug  2 07:19:12]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:12]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:12]     -- <SIP/TELCOtest-00000067> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:12]     -- <SIP/TELCOtest-00000067> Playing 'generic_hold.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  2 07:19:12]     -- Executing [138331*69*Y8020719070000000095*1234*2222@default:3] Hangup("Local/010*022*021*121*2222@default-00000061;1", "") in new stack
[Aug  2 07:19:12]   == Spawn extension (default, 138331*69*Y8020719070000000095*1234*2222, 3) exited non-zero on 'Local/010*022*021*121*2222@default-00000061;1'
[Aug  2 07:19:12] WARNING[14408][C-000000e6]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[Aug  2 07:19:12]     -- Executing [h@default:1] AGI("Local/010*022*021*121*2222@default-00000061;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------)") in new stack
[Aug  2 07:19:12]     -- <Local/010*022*021*121*2222@default-00000061;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------) completed, returning 0
[Aug  2 07:19:12]     -- Channel Local/010*022*021*121*2222@default-00000061;2 left 'simple_bridge' basic-bridge <ec979d3e-99e5-4cae-948d-e0f37d438b85>
[Aug  2 07:19:12]   == Spawn extension (default, 2222, 1) exited non-zero on 'Local/010*022*021*121*2222@default-00000061;2'
[Aug  2 07:19:12]     -- Executing [h@default:1] AGI("Local/010*022*021*121*2222@default-00000061;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----2-----SIP 200 OK)") in new stack
[Aug  2 07:19:12]     -- Channel SIP/2222-00000068 left 'simple_bridge' basic-bridge <ec979d3e-99e5-4cae-948d-e0f37d438b85>
[Aug  2 07:19:12]     -- <Local/010*022*021*121*2222@default-00000061;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----2-----SIP 200 OK) completed, returning 0
[Aug  2 07:19:18]     -- Started music on hold, class 'default', on channel 'SIP/TELCOtest-00000067'
[Aug  2 07:19:28]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug  2 07:19:28]     -- Called 010*022*021*121*2222@default
[Aug  2 07:19:28]     -- Executing [010*022*021*121*2222@default:1] Goto("Local/010*022*021*121*2222@default-00000062;2", "default,2222,1") in new stack
[Aug  2 07:19:28]     -- Goto (default,2222,1)
[Aug  2 07:19:28]     -- Executing [2222@default:1] Dial("Local/010*022*021*121*2222@default-00000062;2", "SIP/2222,60,") in new stack
[Aug  2 07:19:28]   == Using SIP RTP CoS mark 5
[Aug  2 07:19:28]     -- Called SIP/2222
[Aug  2 07:19:28]     -- SIP/2222-00000069 is ringing



[williamconley]

I mean this problem

only GENERIC or CUSTOMER_PHONE_RING_AGENT will work. Any other option call hangup on answer by agent.

I set ingroup On-Hook CID CUSTOMER_PHONE_INGROUP

In this example, do you include a single test call from beginning to end? Including the hangup? And not including any other traffic?

Have you included your full system information while attempting to get free help on this cool free forum supplied by The Vicidial Group? (hint, hint, lol )

[dominikPL]

I paste log again from beginning to end. In this example call flow is: "Client" call to did, is routed to ivr, then pressed 3, and goes to ingroup, agent phone starts ringing then agent take call but is imminently hangup, client still waiting in IVR.

Code: Select all

[Aug  9 15:11:14]     -- Executing [scc_test@trunkinbound:1] AGI("SIP/TELCOtest-00000018", "agi-DID_route.agi") in new stack
[Aug  9 15:11:14]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-DID_route.agi
[Aug  9 15:11:14]     -- <SIP/TELCOtest-00000018>AGI Script agi-DID_route.agi completed, returning 0
[Aug  9 15:11:14]     -- Executing [s@IVR:1] Answer("SIP/TELCOtest-00000018", "") in new stack
[Aug  9 15:11:15]     -- Executing [s@IVR:2] AGI("SIP/TELCOtest-00000018", "agi-VDAD_inbound_calltime_check.agi,kolejka-----YES-----IVR-------------------------NO") in new stack
[Aug  9 15:11:15]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_inbound_calltime_check.agi
[Aug  9 15:11:15]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:15]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:15]        > 0x7f59a8013660 -- Strict RTP switching to RTP target address 192.168.32.21:18546 as source
[Aug  9 15:11:15]     -- <SIP/TELCOtest-00000018>AGI Script agi-VDAD_inbound_calltime_check.agi completed, returning 0
[Aug  9 15:11:15]     -- Executing [s@IVR:3] Set("SIP/TELCOtest-00000018", "INVCOUNT=0") in new stack
[Aug  9 15:11:15]     -- Executing [s@IVR:4] BackGround("SIP/TELCOtest-00000018", "prompt") in new stack
[Aug  9 15:11:15]     -- <SIP/TELCOtest-00000018> Playing 'prompt.slin' (language 'en')
[Aug  9 15:11:17] DTMF[32429][C-00000088]: channel.c:4124 __ast_read: DTMF begin '3' received on SIP/TELCOtest-00000018
[Aug  9 15:11:17] DTMF[32429][C-00000088]: channel.c:4128 __ast_read: DTMF begin ignored '3' on SIP/TELCOtest-00000018
[Aug  9 15:11:18] DTMF[32429][C-00000088]: channel.c:4038 __ast_read: DTMF end '3' received on SIP/TELCOtest-00000018, duration 200 ms
[Aug  9 15:11:18] DTMF[32429][C-00000088]: channel.c:4108 __ast_read: DTMF end passthrough '3' on SIP/TELCOtest-00000018
[Aug  9 15:11:18]     -- Executing [3@IVR:1] AGI("SIP/TELCOtest-00000018", "cm.agi,kolejka-----3-----NONE-----0-----0") in new stack
[Aug  9 15:11:18]     -- Launched AGI Script /usr/share/asterisk/agi-bin/cm.agi
[Aug  9 15:11:18]     -- <SIP/TELCOtest-00000018>AGI Script cm.agi completed, returning 0
[Aug  9 15:11:18]     -- Executing [3@IVR:2] AGI("SIP/TELCOtest-00000018", "agi-VDAD_ALL_inbound.agi,CID-----LB-----kolejka-----IVR--------------------998----------TESTCAMP------------------------------") in new stack
[Aug  9 15:11:18]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
[Aug  9 15:11:18]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:18]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:18]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug  9 15:11:18]     -- Called 010*022*021*121*2222@default
[Aug  9 15:11:18]     -- Executing [010*022*021*121*2222@default:1] Goto("Local/010*022*021*121*2222@default-0000006f;2", "default,2222,1") in new stack
[Aug  9 15:11:18]     -- Goto (default,2222,1)
[Aug  9 15:11:18]     -- Executing [2222@default:1] Dial("Local/010*022*021*121*2222@default-0000006f;2", "SIP/2222,60,") in new stack
[Aug  9 15:11:18]   == Using SIP RTP CoS mark 5
[Aug  9 15:11:18]     -- Called SIP/2222
[Aug  9 15:11:18]     -- SIP/2222-00000019 is ringing
[Aug  9 15:11:18]     -- Local/010*022*021*121*2222@default-0000006f;1 is ringing
[Aug  9 15:11:19]        > 0x7f59a8013660 -- Strict RTP learning complete - Locking on source address 192.168.32.21:18546
[Aug  9 15:11:20]     -- Started music on hold, class 'default', on channel 'SIP/TELCOtest-00000018'
[Aug  9 15:11:21]        > 0x7f59b800c2c0 -- Strict RTP learning after remote address set to: 10.22.21.104:4006
[Aug  9 15:11:21]     -- SIP/2222-00000019 answered Local/010*022*021*121*2222@default-0000006f;2
[Aug  9 15:11:21]     -- Local/010*022*021*121*2222@default-0000006f;1 answered
[Aug  9 15:11:21]     -- Executing [138331*20*Y8091511180000000121*1234*2222@default:1] AGI("Local/010*022*021*121*2222@default-0000006f;1", "agi-VDAD_local_optimize.agi,kolejka0224634081") in new stack
[Aug  9 15:11:21]     -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_local_optimize.agi
[Aug  9 15:11:21]     -- Channel SIP/2222-00000019 joined 'simple_bridge' basic-bridge <1515447c-2a6b-4c1e-8aef-0a9f91edbaf2>
[Aug  9 15:11:21]     -- Channel Local/010*022*021*121*2222@default-0000006f;2 joined 'simple_bridge' basic-bridge <1515447c-2a6b-4c1e-8aef-0a9f91edbaf2>
[Aug  9 15:11:21]        > 0x7f59b800c2c0 -- Strict RTP switching to RTP target address 10.22.21.104:4006 as source
[Aug  9 15:11:21]     -- <Local/010*022*021*121*2222@default-0000006f;1>AGI Script agi-VDAD_local_optimize.agi completed, returning 0
[Aug  9 15:11:21]     -- Executing [138331*20*Y8091511180000000121*1234*2222@default:2] Wait("Local/010*022*021*121*2222@default-0000006f;1", "2") in new stack
[Aug  9 15:11:22]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug  9 15:11:23]     -- Stopped music on hold on SIP/TELCOtest-00000018
[Aug  9 15:11:23]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:23]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:23]     -- Executing [138331*20*Y8091511180000000121*1234*2222@default:3] Hangup("Local/010*022*021*121*2222@default-0000006f;1", "") in new stack
[Aug  9 15:11:23]   == Spawn extension (default, 138331*20*Y8091511180000000121*1234*2222, 3) exited non-zero on 'Local/010*022*021*121*2222@default-0000006f;1'
[Aug  9 15:11:23] WARNING[32445][C-0000008a]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[Aug  9 15:11:23]     -- Executing [h@default:1] AGI("Local/010*022*021*121*2222@default-0000006f;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------)") in new stack
[Aug  9 15:11:23]     -- <Local/010*022*021*121*2222@default-0000006f;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------) completed, returning 0
[Aug  9 15:11:23]     -- Channel Local/010*022*021*121*2222@default-0000006f;2 left 'simple_bridge' basic-bridge <1515447c-2a6b-4c1e-8aef-0a9f91edbaf2>
[Aug  9 15:11:23]   == Spawn extension (default, 2222, 1) exited non-zero on 'Local/010*022*021*121*2222@default-0000006f;2'
[Aug  9 15:11:23]     -- Executing [h@default:1] AGI("Local/010*022*021*121*2222@default-0000006f;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----2-----SIP 200 OK)") in new stack
[Aug  9 15:11:23]     -- Channel SIP/2222-00000019 left 'simple_bridge' basic-bridge <1515447c-2a6b-4c1e-8aef-0a9f91edbaf2>
[Aug  9 15:11:23]     -- <SIP/TELCOtest-00000018> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Aug  9 15:11:23]     -- <Local/010*022*021*121*2222@default-0000006f;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----2-----SIP 200 OK) completed, returning 0
[Aug  9 15:11:23]     -- <SIP/TELCOtest-00000018> Playing 'generic_hold.gsm' (escape_digits=) (sample_offset 0) (language 'en')


[dominikPL]

May I have some information, please?
Do you confirm this problem?
If yes, Do you have on roadmap plan to solve the problem?

[williamconley]

Have you included your full system information while attempting to get free help on this cool free forum supplied by The Vicidial Group? (hint, hint, lol )

Code: Select all

Executing [138331*69*Y8020719070000000095*1234*2222@default:1]
Executing [138331*69*Y8020719070000000095*1234*2222@default:2]
Executing [138331*69*Y8020719070000000095*1234*2222@default:3]

In both examples, these three lines appear to indicate that audio never initializes for the client call. If audio never starts flowing, Vicidial will kill the call. Note that the default:2 includes a two second "wait" during which audio (sip-silence) is sent once per second. If that still results in a "local" channel, then audio has not begun and the call will be killed.

This can happen if the wrong Asterisk version was included in the configuration during installation and a re-installation was not done. Reinstallation with a new Asterisk version and "include sample configs" will update the asterisk config files and alter the way asterisk works slightly for the different version. It can also happen if there's an actual firewall issue blocking audio on this type of calls. Inbound calls and outbound calls can be handled differently based on system configuration options, thus "outbound" audio working is not a true indicator of whether inbound audio is working. A good test is to route an inbound call directly to a SIP extension and see if you get two way audio. You can also turn on SIP debugging to see if there is a codec handshake failing since inbound/outbound configurations can also have different options enabled and something as simple as g729 being required but not present for inbound (either by your server or the inbound provider) can kill the call at the moment sound *should* begin.