[Home]

Summary:ASTERISK-29025: pbx_spool: Call remains up when it shouldn't be
Reporter:PARTHA PAUL (partho2999@live.com)Labels:
Date Opened:2020-08-10 20:44:50Date Closed:2020-08-22 08:57:29
Priority:MinorRegression?
Status:Closed/CompleteComponents:PBX/pbx_spool
Versions:16.12.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:Centos 7 OS 64 BIT 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000 link/ether 9a:61:a0:a5:c8:49 brd ff:ff:ff:ff:ff:ff inet XXX.XXX.XXX.X/18 brd 104.131.63.255 scope global eth0 valid_lft forever preferred_lft forever inet 10.17.0.5/16 brd 10.17.255.255 scope global eth0 valid_lft forever preferred_lft forever Attachments:
Description:I am using asterisk 16.12.0 version to originate calls, Following problem arises from time to time, a call will successfully
terminate
{noformat}
[root@99 outgoing]# asterisk -rx "core show channels verbose"
Channel Context Extension Prio State Application Data CallerID Duration Accountcode PeerAccount BridgeID
Local/6661@default-0 paul sw_7_"020" 12 Up SpeechBackgr "020",2 9123943000 03:54:02
{noformat}

FileName: 9123943000.call
Location: /var/spool/asterisk/outgoing
{noformat}
Channel: Local/6661
MaxRetries: 2
RetryTime: 60
WaitTime: 30
Callerid: 9123943000 <9123943000>
Context: AMD
Extension: 8881
Priority: 1

StartRetry: 31932 1 (1597095345)

DelayedRetry: 31932 0 (1597095345)

DelayedRetry: 31932 0 (1597095405)

DelayedRetry: 31932 0 (1597095465)

DelayedRetry: 31932 0 (1597095525)

DelayedRetry: 31932 0 (1597095585)

DelayedRetry: 31932 0 (1597095645)

DelayedRetry: 31932 0 (1597095705)

DelayedRetry: 31932 0 (1597095765)

DelayedRetry: 31932 0 (1597095825)

DelayedRetry: 31932 0 (1597095885)

DelayedRetry: 31932 0 (1597095945)

AbortRetry: 12581 1 (1597096005)

StartRetry: 12581 1 (1597096065)

EndRetry: 12581 1 (1597096036)

StartRetry: 12581 3 (1597096125)

DelayedRetry: 12581 2 (1597096096)

DelayedRetry: 12581 2 (1597096125)

DelayedRetry: 12581 2 (1597096156)

DelayedRetry: 12581 2 (1597096185)

DelayedRetry: 12581 2 (1597096216)

DelayedRetry: 12581 2 (1597096245)

DelayedRetry: 12581 2 (1597096276)

DelayedRetry: 12581 2 (1597096305)

DelayedRetry: 12581 2 (1597096336)

DelayedRetry: 12581 2 (1597096365)

DelayedRetry: 12581 2 (1597096396)

DelayedRetry: 12581 2 (1597096425)

DelayedRetry: 12581 2 (1597096456)

DelayedRetry: 12581 2 (1597096485)

DelayedRetry: 12581 2 (1597096516)

DelayedRetry: 12581 2 (1597096545)

DelayedRetry: 12581 2 (1597096576)

DelayedRetry: 12581 2 (1597096605)

DelayedRetry: 12581 2 (1597096636)

DelayedRetry: 12581 2 (1597096665)

DelayedRetry: 12581 2 (1597096696)

DelayedRetry: 12581 2 (1597096725)

DelayedRetry: 12581 2 (1597096756)

DelayedRetry: 12581 2 (1597096785)

DelayedRetry: 12581 2 (1597096816)

DelayedRetry: 12581 2 (1597096845)

DelayedRetry: 12581 2 (1597096876)

DelayedRetry: 12581 2 (1597096905)

DelayedRetry: 12581 2 (1597096936)

DelayedRetry: 12581 2 (1597096965)

DelayedRetry: 12581 2 (1597096996)

DelayedRetry: 12581 2 (1597097025)

DelayedRetry: 12581 2 (1597097056)

DelayedRetry: 12581 2 (1597097085)

DelayedRetry: 12581 2 (1597097116)

DelayedRetry: 12581 2 (1597097145)

DelayedRetry: 12581 2 (1597097176)

DelayedRetry: 12581 2 (1597097205)

DelayedRetry: 12581 2 (1597097237)

DelayedRetry: 12581 2 (1597097265)

DelayedRetry: 12581 2 (1597097297)

DelayedRetry: 12581 2 (1597097325)

DelayedRetry: 12581 2 (1597097357)

DelayedRetry: 12581 2 (1597097385)

DelayedRetry: 12581 2 (1597097417)

DelayedRetry: 12581 2 (1597097445)

DelayedRetry: 12581 2 (1597097477)
{noformat}

I think, it's a bug
Comments:By: Asterisk Team (asteriskteam) 2020-08-10 20:44:51.372-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Kevin Harwell (kharwell) 2020-08-12 14:16:13.932-0500

How often does the problem occur? For instance, 1 out of 3 times, half the time?

Could you please describe in more detail the basic scenario, and expectation of a successful vs a failed attempt.For instance, based on the call file I'm assuming it's expected attempt to call the specified extension 2 times and then fail, but it appears to not fail?

Also could you enable at least debugging level 1 (how to here [1]), and attach a "good", and if possible also a "bad" execution?

[1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Thanks!
By: PARTHA PAUL (partho2999@live.com) 2020-08-12 16:14:18.624-0500

Forgot to mention some important things

"core show channels" will show 0-20 channels when this happens (the true
count), but the "core show calls" and the call counter for active calls
after "core show channels" will show a very high amount of calls
(150-250+), this during times when we'd not expect to have close to that
amount.

Here is my bellow configuration

[general]
context=default                
match_auth_username=yes    
allowguest=no
allowoverlap=no                
allowtransfer=no              
realm=iNet                      
bindport=9060                
bindaddr=0.0.0.0            
nat=force_rport,comedia
externalip=XXX.XXX.XXX.XXX
localnet=10.17.0.5/255.255.0.0
localnet=172.17.0.1/255.255.0.0
localnet=172.16.0.0/255.255.255.0
transport=udp
tcpenable=no                  
dtmfmode=rfc2833
tlsenable=no
srvlookup=yes                  
tos_sip=cs3                    
tos_audio=ef                  
tos_video=af41              
tos_text=af41                
cos_sip=3                      
cos_audio=5                  
cos_video=4                  
cos_text=3                    
directrtpsetup=yes
directmedia=yes
maxexpiry=600              
minexpiry=120              
defaultexpiry=300          
qualifyfreq=120              
disallow=all                  
allow=g729
allow=g723
allow=alaw
allow=ulaw
autoframing=yes
mohinterpret=default
mohsuggest=default
language=en                
progressinband=no      
useragent=iNet
alwaysauthreject = no  
dynamic_exclude_static = yes
qualify=yes
t1min=300                      
timert1=4000                  
timerb=4000                  
rtptimeout=60                
rtpholdtimeout=30          
session-timers=refuse
;dumphistory=yes          
allowsubscribe=yes        
;------------------------------ JITTER BUFFER CONFIGURATION --------------------------
jbenable = yes              
jbforce = no                
jbmaxsize = 800        
jbresyncthreshold = 1000
jbimpl = fixed              
;-----------------------------------------------------------------------------------

[authentication]
[vitel-outbound]
type=friend
dtmfmode=rfc2833
host=XX.XX.XX.XX
port=5060
busy-level=3
call-limit=800
countext=outbound
qualify=yes
disallow=all
allow=g729
accountcode=outbound

cat /etc/asterisk/extensions.conf
[general]
static=yes
writeprotect=no
autofallthrough=yes
clearglobalvars=no
userscontext=default
autocreatepeer=yes

[globals]
CONSOLE=Console/dsp                        
TRUNK=Mobile/iPhone                                  
TRUNKMSD=1                                  

[default]
exten => s,1,NoOp()
exten => s,n,Hangup()
exten => i,1,Hangup()
exten => t,1,Hangup()

exten => h,1,NoOp()
exten => h,n,AGI(update.php)
exten => h,n,Hangup()


exten => _6661,1,Noop(Dialout number ${MNUM})
exten => _6661,n,Set(ASTOPER=${OPER})
exten => _6661,n,Dial(SIP/${MNUM}@vitel-outbound)
exten => _6661,n,Hangup()


[AMD]
exten => s,1,NoOp()
exten => s,n,Hangup()
exten => i,1,Hangup()
exten => t,1,Hangup()
exten => h,1,NoOp()
exten => h,n,AGI(update.php)
exten => h,n,Hangup()


exten => _8881,1,Answer()
exten => _8881,n,Set(CDR(userfield)=${OPER})
exten => _8881,n,Set(CALLERID(all)="${MNUM}" <${MNUM}>)
exten => _8881,n,Background(silence/1)
exten => _8881,n,AMD(${AMD_EXTRA})
exten => _8881,n,NoOp("AMD: ${AMDSTATUS} - ${AMDCAUSE}")
exten => _8881,n,GotoIf($["${AMDSTATUS}" = "MACHINE"]?machine)
exten => _8881,n,Set(TIMEOUT(response)=5)
exten => _8881,n,Goto(paul,7771,1)
exten => _8881,n,Hangup()
exten => _8881,n(machine),UserEvent(CALLSTATUS,Uniqueid:${UNIQUEID},V:AMD)
exten => _8881,n,Hangup()



/etc/asterisk/extensions.ael
globals {
       CONSOLE-AEL="Console/dsp";              
       IAXINFO-AEL=guest;                            
       OUTBOUND-TRUNK="Zap/g2";                
       OUTBOUND-TRUNKMSD=1;                                  
};


context paul {
  7771 => {
               Answer();
               Monitor(g729,${MONITOR_FILENAME},0);
              SpeechCreate();
              SpeechBackground(${AUDIOFILENAME},3);
              Set(WATSONTEXT=${SPEECH_TEXT(0)});
              SpeechDestroy();
              StopMonitor();
  };
};
------------------------------------------------------------------------------------------------------
Network Configuration

[root@paul6 outgoing]# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
   link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
   inet 127.0.0.1/8 scope host lo
      valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
   link/ether 9a:61:a0:a5:c8:49 brd ff:ff:ff:ff:ff:ff
   inet XX.XX.XX.6/18 brd XX.XX.XX.XX scope global eth0
      valid_lft forever preferred_lft forever
   inet 10.17.0.5/16 brd 10.17.255.255 scope global eth0
      valid_lft forever preferred_lft forever
4: docker0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default
   link/ether 02:42:dc:c9:44:bb brd ff:ff:ff:ff:ff:ff
   inet 172.17.0.1/16 brd 172.17.255.255 scope global docker0
      valid_lft forever preferred_lft forever
6: veth15e91aa@if5: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue master docker0 state UP group default
   link/ether 3e:4e:6c:42:6b:61 brd ff:ff:ff:ff:ff:ff link-netnsid 0
8: tun0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UNKNOWN group default qlen 100
   link/none
   inet 172.16.0.1 peer 172.16.0.2/32 scope global tun0
      valid_lft forever preferred_lft forever

-----------------------------------------------------------------------------------------------------
Speech To Text Engine is running ( 172.17.0.1/16 )

Also, in a day one or two whole asterisks got crash
By: Kevin Harwell (kharwell) 2020-08-12 18:01:34.069-0500

I'm still misunderstanding.
{quote}
... Following problem arises from time to time, a call will successfully terminate
{quote}
Are you expecting the call to not terminate? How is the call file problem manifesting itself? What's the expected scenario and outcome?
By: PARTHA PAUL (partho2999@live.com) 2020-08-13 07:16:28.948-0500

Sorry for the misunderstanding. I want asterisk should behave normally if both parties release the call why that call hold by an asterisk ( asterisk -rx "core show channels " )  and that time , i noticed asterisk doesn't delete that call file and continue appending "DelayedRetry: 12581 2 (1597097417) " . even asterisk cdr is not generated.  At the day end , asterisk got crashed.
By: Kevin Harwell (kharwell) 2020-08-13 13:34:20.974-0500

Since it seems to be happening regularly can you set the Asterisk debug level to 1, and enable SIP tracing in the log too [1]. For chan_sip that's "sip set debug" from the CLI. And then attach the log file to here to the issue.

[1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Thanks!
By: PARTHA PAUL (partho2999@live.com) 2020-08-14 19:46:36.535-0500

[Aug 14 20:42:43] VERBOSE[13096] pbx_spool.c: Attempting call on Local/6661 for 8881@AMD:1 (Retry 1)
[Aug 14 20:42:43] WARNING[13096] func_cdr.c: Using the CDR function to set 'accountcode' is deprecated. Please use the CHANNEL function instead.
[Aug 14 20:42:43] VERBOSE[13096] dial.c: Called 6661
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] pbx.c: Executing [6661@default:1] NoOp("Local/6661@default-00000000;2", "Dialout number 1065") in new stack
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] pbx.c: Executing [6661@default:2] Set("Local/6661@default-00000000;2", "ASTOPER=999999999") in new stack
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] pbx.c: Executing [6661@default:3] Dial("Local/6661@default-00000000;2", "SIP/1065") in new stack
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] netsock2.c: Using SIP RTP TOS bits 184
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] app_dial.c: Called SIP/1065
[Aug 14 20:42:43] VERBOSE[13097][C-00000002] app_dial.c: SIP/1065-00000000 is ringing
[Aug 14 20:42:43] VERBOSE[13096] dial.c: Local/6661@default-00000000;1 is ringing
[Aug 14 20:42:44] VERBOSE[13097][C-00000002] app_dial.c: SIP/1065-00000000 is ringing
[Aug 14 20:42:48] VERBOSE[13028][C-00000002] res_rtp_asterisk.c: 0x7f920c014a20 -- Strict RTP learning after remote address set to: 192.168.0.101:9170
[Aug 14 20:42:48] VERBOSE[13097][C-00000002] app_dial.c: SIP/1065-00000000 answered Local/6661@default-00000000;2
[Aug 14 20:42:48] VERBOSE[13096] dial.c: Local/6661@default-00000000;1 answered
[Aug 14 20:42:48] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:1] Answer("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:48] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:2] Set("Local/6661@default-00000000;1", "CDR(userfield)=3147485461") in new stack
[Aug 14 20:42:48] VERBOSE[13103][C-00000002] bridge_channel.c: Channel SIP/1065-00000000 joined 'simple_bridge' basic-bridge <32ef301b-2fa3-45a3-9fe1-723d428ba007>
[Aug 14 20:42:48] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:3] Set("Local/6661@default-00000000;1", "CALLERID(all)="1065" <1065>") in new stack
[Aug 14 20:42:48] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:4] BackGround("Local/6661@default-00000000;1", "silence/1") in new stack
[Aug 14 20:42:48] VERBOSE[13097][C-00000002] bridge_channel.c: Channel Local/6661@default-00000000;2 joined 'simple_bridge' basic-bridge <32ef301b-2fa3-45a3-9fe1-723d428ba007>
[Aug 14 20:42:48] VERBOSE[13096][C-00000003] file.c: <Local/6661@default-00000000;1> Playing 'silence/1.gsm' (language 'en')
[Aug 14 20:42:48] VERBOSE[13103][C-00000002] res_rtp_asterisk.c: 0x7f920c014a20 -- Strict RTP qualifying stream type: audio
[Aug 14 20:42:48] VERBOSE[13103][C-00000002] res_rtp_asterisk.c: 0x7f920c014a20 -- Strict RTP switching source address to 103.218.26.75:9170
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:5] AMD("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:49] VERBOSE[13096][C-00000003] app_amd.c: AMD: Local/6661@default-00000000;1 3147206952 (N/A) (Fmt: slin)
[Aug 14 20:42:49] VERBOSE[13096][C-00000003] app_amd.c: AMD: initialSilence [4000] greeting [1500] afterGreetingSilence [800] totalAnalysisTime [5000] minimumWordLength [50] betweenWordsSilence [50] maximumNumberOfWords [4] silenceThreshold [256] maximumWordLength [5000]
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13096][C-00000003] app_amd.c: AMD: Channel [Local/6661@default-00000000;1]. Changed state to STATE_IN_SILENCE
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:49] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:50] VERBOSE[13096][C-00000003] app_amd.c: AMD: Channel [Local/6661@default-00000000;1]. Word detected. iWordsCount:1
[Aug 14 20:42:50] VERBOSE[13096][C-00000003] app_amd.c: AMD: Channel [Local/6661@default-00000000;1]. Detected Talk, previous silence duration: 620
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] app_amd.c: AMD: Channel [Local/6661@default-00000000;1]. Changed state to STATE_IN_SILENCE
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] app_amd.c: AMD: Channel [Local/6661@default-00000000;1]. HUMAN: silenceDuration:800 afterGreetingSilence:800
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:6] NoOp("Local/6661@default-00000000;1", ""AMD: HUMAN - HUMAN-800-800"") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:7] GotoIf("Local/6661@default-00000000;1", "0?machine") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:8] Set("Local/6661@default-00000000;1", "TIMEOUT(response)=5") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] func_timeout.c: Response timeout set to 5.000
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [8881@AMD:9] Goto("Local/6661@default-00000000;1", "paul,7771,1") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,1)
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:1] MSet("Local/6661@default-00000000;1", "~~EXTEN~~=7771") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:2] Answer("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:3] Set("Local/6661@default-00000000;1", "VOLUME(TX)=2") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:4] Set("Local/6661@default-00000000;1", "VOLUME(RX)=2") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:5] Set("Local/6661@default-00000000;1", "DENOISE(rx)=on") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:6] MSet("Local/6661@default-00000000;1", "TIMEOUT(digit)=1") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] func_timeout.c: Digit timeout set to 1.000
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:7] MSet("Local/6661@default-00000000;1", "TIMEOUT(response)=5") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] func_timeout.c: Response timeout set to 5.000
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:8] Set("Local/6661@default-00000000;1", "TIMEOUT(absolute)=1800") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] func_timeout.c: Channel will hangup at 2020-08-14 21:12:51.850 EDT.
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:9] Set("Local/6661@default-00000000;1", "ASTOPER=3147485461") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:10] Set("Local/6661@default-00000000;1", "DMNUM=1065") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:11] Set("Local/6661@default-00000000;1", "CALLERID(all)="1065" <1065>") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:12] Set("Local/6661@default-00000000;1", "CDR(did)=1065") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:13] Set("Local/6661@default-00000000;1", "CDR(list_id)=2") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:14] Set("Local/6661@default-00000000;1", "CDR(list_rec)=66") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:15] Set("Local/6661@default-00000000;1", "CDR(accountcode)=15") in new stack
[Aug 14 20:42:51] WARNING[13096][C-00000003] func_cdr.c: Using the CDR function to set 'accountcode' is deprecated. Please use the CHANNEL function instead.
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:16] Set("Local/6661@default-00000000;1", "AUDIOFILENAME="020"") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:17] Set("Local/6661@default-00000000;1", "LoopCount=1") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:18] GotoIf("Local/6661@default-00000000;1", "0?19:22") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,22)
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:22] NoOp("Local/6661@default-00000000;1", "Finish if_paul_1") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:23] GotoIf("Local/6661@default-00000000;1", "0?24:25") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,25)
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:25] NoOp("Local/6661@default-00000000;1", "Finish if_paul_3") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:26] GotoIf("Local/6661@default-00000000;1", "0?27:28") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,28)
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:28] NoOp("Local/6661@default-00000000;1", "Finish if_paul_4") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:29] GotoIf("Local/6661@default-00000000;1", "0?30:35") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,35)
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:35] NoOp("Local/6661@default-00000000;1", "Finish if_paul_5") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:36] Set("Local/6661@default-00000000;1", "MONITOR_FILENAME=20200814-204251-1065") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:37] Goto("Local/6661@default-00000000;1", "sw_7_"020",10") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,sw_7_"020",10)
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:10] Monitor("Local/6661@default-00000000;1", "g729,20200814-204251-1065,0") in new stack
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:11] SpeechCreate("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:51] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Create speech resource ws://localhost:2700
[Aug 14 20:42:51] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Created speech resource result 0
[Aug 14 20:42:51] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:12] SpeechBackground("Local/6661@default-00000000;1", ""020",3") in new stack
[Aug 14 20:42:51] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Start recognition
[Aug 14 20:42:51] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:51] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:51] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:51] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:51] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:51] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : ""
}'
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:52] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : ""
}'
[Aug 14 20:42:52] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : ""
}'
[Aug 14 20:42:53] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "and those"
}'
[Aug 14 20:42:53] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "hello"
}'
[Aug 14 20:42:53] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "hello"
}'
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] res_rtp_asterisk.c: 0x7f920c014a20 -- Strict RTP learning complete - Locking on source address 103.218.26.75:9170
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "result" : [{
     "conf" : 1.000000,
     "end" : 0.750000,
     "start" : 0.390000,
     "word" : "hello"
   }],
 "text" : "hello"
}'
[Aug 14 20:42:53] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Recognition result: hello
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:13] Set("Local/6661@default-00000000;1", "WATSONTEXT=hello") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:14] SpeechDestroy("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:53] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Destroy speech resource
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] res_http_websocket.c: WebSocket connection to '127.0.0.1:2700' closed
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:15] StopMonitor("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_"020"@paul:16] Goto("Local/6661@default-00000000;1", "7771,38") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,38)
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:38] NoOp("Local/6661@default-00000000;1", "Finish switch_paul_7") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:39] GotoIf("Local/6661@default-00000000;1", "0?40:46") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,46)
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:46] NoOp("Local/6661@default-00000000;1", "Finish if_paul_8") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:47] GotoIf("Local/6661@default-00000000;1", "0?48:51") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,51)
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:51] NoOp("Local/6661@default-00000000;1", "Finish if_paul_9") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:52] AGI("Local/6661@default-00000000;1", "watsonquery.php,hello,1065,20200814-204251-1065,2,"020"") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/watsonquery.php
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] res_agi.c: <Local/6661@default-00000000;1>AGI Script watsonquery.php completed, returning 0
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:53] NoOp("Local/6661@default-00000000;1", ""We received id: 13 question: hello answer: 020 action:  actionvalue:  phone: 1065 Time: 2020-08-14 20:42:53"") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:54] Playback("Local/6661@default-00000000;1", "silence/1") in new stack
[Aug 14 20:42:53] VERBOSE[13096][C-00000003] file.c: <Local/6661@default-00000000;1> Playing 'silence/1.gsm' (language 'en')
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:53] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:55] GotoIf("Local/6661@default-00000000;1", "0?56:69") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,69)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:69] NoOp("Local/6661@default-00000000;1", "Finish if_paul_10") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:70] GotoIf("Local/6661@default-00000000;1", "0?71:75") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,75)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:75] Set("Local/6661@default-00000000;1", "LoopCount=1") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:76] Set("Local/6661@default-00000000;1", "AUDIOFILENAME=020") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:77] Goto("Local/6661@default-00000000;1", "start") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,18)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:18] GotoIf("Local/6661@default-00000000;1", "0?19:22") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,22)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:22] NoOp("Local/6661@default-00000000;1", "Finish if_paul_1") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:23] GotoIf("Local/6661@default-00000000;1", "0?24:25") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,25)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:25] NoOp("Local/6661@default-00000000;1", "Finish if_paul_3") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:26] GotoIf("Local/6661@default-00000000;1", "0?27:28") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,28)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:28] NoOp("Local/6661@default-00000000;1", "Finish if_paul_4") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:29] GotoIf("Local/6661@default-00000000;1", "0?30:35") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,7771,35)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:35] NoOp("Local/6661@default-00000000;1", "Finish if_paul_5") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:36] Set("Local/6661@default-00000000;1", "MONITOR_FILENAME=20200814-204254-1065") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [7771@paul:37] Goto("Local/6661@default-00000000;1", "sw_7_020,10") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx_builtins.c: Goto (paul,sw_7_020,10)
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_020@paul:10] Monitor("Local/6661@default-00000000;1", "g729,20200814-204254-1065,0") in new stack
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_020@paul:11] SpeechCreate("Local/6661@default-00000000;1", "") in new stack
[Aug 14 20:42:54] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Create speech resource ws://localhost:2700
[Aug 14 20:42:54] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Created speech resource result 0
[Aug 14 20:42:54] VERBOSE[13096][C-00000003] pbx.c: Executing [sw_7_020@paul:12] SpeechBackground("Local/6661@default-00000000;1", "020,3") in new stack
[Aug 14 20:42:54] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Start recognition
[Aug 14 20:42:55] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : ""
}'
[Aug 14 20:42:55] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : ""
}'
[Aug 14 20:42:55] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : ""
}'
[Aug 14 20:42:55] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "it"
}'
[Aug 14 20:42:55] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "let's see"
}'
[Aug 14 20:42:56] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "let's see"
}'
[Aug 14 20:42:56] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "let's see"
}'
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "let's see"
}'
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:56] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] NOTICE[13096][C-00000003] res_speech_vosk.c: (vosk) Got result: '{
 "partial" : "let's see"
}'
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
[Aug 14 20:42:57] VERBOSE[13103][C-00000002] codec_g72x.c:     -- G.729 PLC
/usr/sbin/safe_asterisk: line 171: 12977 Segmentation fault      (core dumped) nice -n $PRIORITY "${ASTSBINDIR}/asterisk" -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
[Aug 14 20:43:01] Asterisk 16.12.0 built by root @ localdataset on a x86_64 running Linux on 2020-08-06 18:53:26 UTC
[Aug 14 20:43:01] VERBOSE[13117] message.c: Message handler 'dialplan' registered.

By: Joshua C. Colp (jcolp) 2020-08-17 12:38:17.237-0500

Your Asterisk crashed, and you also appear to be using two modules which are not part of Asterisk and that we can't support (codec_g72x and res_speech_vosk). It is entirely possible that they are the cause of this issue. If you eliminate these for testing purposes, does that change things?
By: Derrick Hammer (pcfreak30) 2020-08-24 20:05:19.896-0500

I can confirm this issue does exist as a bug as well. it also seems to be a weird edge case. The following is the research I have found on it so far:

* On the cases where this happened, it seems the call had extra long periods of ringing before voicemail kicked in, 10+ rings.
* It appears the retries counter on the outgoing struct either does not increase or somehow gets decreased, so https://github.com/asterisk/asterisk/blob/fcd8e9d6ef6cad66ba3bfe58540aa1cdb372fc2c/pbx/pbx_spool.c#L524 is always getting hit, and causing the loop
* I am unsure if retries starts at 0 or 1, but on https://github.com/asterisk/asterisk/blob/fcd8e9d6ef6cad66ba3bfe58540aa1cdb372fc2c/pbx/pbx_spool.c#L524 it seems the "<=" might need to be a "<"?
* It seems that disabling the app_amd.so module prevents this bug from happening, so it may have an issue with interacting with it or just exposes an edge case bug.
* I have confirmed in my case, codec_g72x and res_speech_vosk aren't loaded and I do not get segfaults.
* With AMD off, it seems the call may not actually forward to the other end (to a queue or extension) despite the voicemail. This could imply some sort of connection signal shutting it down, but I cannot confirm this, only speculation.
* My Asterisk version is 13.32.0.

I hope this information helps :)