CC的IVR每次放音中间都要停顿3.6秒钟

发布时间:  2015-02-12 浏览次数:  195 下载次数:  0
问题描述

1、IVR业务调测时候,现场进行拨测时发现:
播放提示音过程中有停顿现象,提示音由多个录音拼接而成,播放完第一个语音后会停顿5秒左右再继续播放下一个语音。用户感知就是不连贯的感觉。

2、ASR进程语音识别,CTI上报识给IVR别收号结果:识别结束的原因为1:ASR_RESULT_TTS_ERROR ,并且在通话过程中偶尔会出现异常挂机情况。

 

处理过程

一、首先告知一线进行抓包分析。需要抓取的包包括:

   1、ICDDEBUG包,网关的端到端内部消息包,网关的sip交互包,网关侧的MRCP协议包(针对科大讯飞的ASR服务,确认ASR是否发送了MRCP包),ASR侧的wirshark包(确认网关的MRCP消息是否到达ASR,因为MRCP协议走的是TCPIP网络,因此可以通过wireshark抓mrcp包)。

   2、反馈抓包的时间点,主被叫。

二、通过分析抓包过程:

   1、icddebug过程

60616| |0|2085-02-10 14:13:04.361|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> Setup||
60617| |0|2085-02-10 14:13:04.362|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> Setup-Ack||
60657| |0|2085-02-10 14:13:04.431|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> Alerting||
60665| |0|2085-02-10 14:13:04.465|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> Alerting-Ack||
60666| |0|2085-02-10 14:13:04.465|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> Notify||
60694| |0|2085-02-10 14:13:04.467|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> Answer||
60696| |0|2085-02-10 14:13:04.561|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> Answer-Ack||
60914| |0|2085-02-10 14:13:05.226|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音1和DTMF收一位号
60967| |0|2085-02-10 14:13:05.665|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
61254| |0|2085-02-10 14:13:08.858|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||放音1成功
61266| |0|2085-02-10 14:13:08.859|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音3
61285| |0|2085-02-10 14:13:09.049|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
61399| |0|2085-02-10 14:13:10.337|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||放音3成功
61409| |0|2085-02-10 14:13:10.339|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音4
61418| |0|2085-02-10 14:13:10.537|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
61530| |0|2085-02-10 14:13:11.618|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||放音4成功
61540| |0|2085-02-10 14:13:11.620|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音5
61577| |0|2085-02-10 14:13:11.978|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
61578| |0|2085-02-10 14:13:11.978|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||收号2成功
61592| |0|2085-02-10 14:13:11.979|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> StopPauseContinueOperator||停止放音
61609| |0|2085-02-10 14:13:12.098|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> StopPauseContinueOperatorRes||
61629| |0|2085-02-10 14:13:12.217|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音7和ASR8识别
61676| |0|2085-02-10 14:13:12.782|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
61813| |0|2085-02-10 14:13:14.058|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||
62235| |0|2085-02-10 14:13:18.498|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorEvent||
62420| |0|2085-02-10 14:13:20.211|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||ASR识别8成功
62465| |0|2085-02-10 14:13:20.544|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音9和ASR10识别
62544| |0|2085-02-10 14:13:20.914|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
62935| |0|2085-02-10 14:13:25.143|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||
62944| |0|2085-02-10 14:13:25.144|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> StopPauseContinueOperator||停止ASR10
63222| |0|2085-02-10 14:13:28.792|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> StopPauseContinueOperatorRes||
63232| |0|2085-02-10 14:13:28.793|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音12和ASR13识别
63307| |0|2085-02-10 14:13:29.120|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
63395| |0|2085-02-10 14:13:29.904|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||
63404| |0|2085-02-10 14:13:29.905|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> StopPauseContinueOperator||停止ASR13识别 ,时间点 14:13:29.905
63746| |0|2085-02-10 14:13:33.585|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> StopPauseContinueOperatorRes|| 网关给CTI发送的停止语音识别时间点: 14:13:33.585
63756| |0|2085-02-10 14:13:33.586|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> ResourceOperator||放音15和ASR识别
63769| |0|2085-02-10 14:13:33.896|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorAck||
63869| |0|2085-02-10 14:13:34.728|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||
64163| |0|2085-02-10 14:13:37.825|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> ResourceOperatorRes||ASR16识别失败:识别结束的原因为1:ASR_RESULT_TTS_ERROR
64201| |0|2085-02-10 14:13:37.845|9:ctiserver|SCP(1)|ACD_SIP(9)|210|SP_ASN1_INTERFACE -> Release||CTI发送拆除呼叫
64207| |0|2085-02-10 14:13:37.881|9:ctiserver|ACD_SIP(9)|SCP(1)|210|SP_ASN1_INTERFACE -> Release-Complete|| 

 从icddebug看出ASR13识别之后,IVR立即下发业务的停止ASR识别命令。此时发送停止到接收到CTI的停止成功消息时间间隔3.6秒。因此此时在客户角度就是无任何声音的3.6秒。

2、IVR的trace的跟踪消息

-------------------------------------------------------首先IVR先组装wav语音信息-----------------------------------------------------------------------------------------------------------
2015-02-10 14:13:20.357  179 Enter CheckUserHookMsg() function, Param: ssp=-1
2015-02-10 14:13:20.368  179 Resource has been expire, but it is not changed!
2015-02-10 14:13:20.368  179 http://99.12.115.65/CMB_ASR/Voice/PuTongHua/请问您需要查询活期账户余额还是定期账户余额呢.vox resource is in cache,And it can be use!
2015-02-10 14:13:20.368  179 IVR(0,179)->IVRAGENT(255,65535): IVR_LIBAGENT_STATE(50008):seqno=20 flag=0 remote=z:\audio\2\201412041724_111.wav
2015-02-10 14:13:20.419  179 排队机(9,255)->IVR(0,179): IVR_LIBAGENT_STATE_ACK(50009):seqno=20 res=0 exist=1 size=17452
2015-02-10 14:13:20.419  179 get remote file(z:\audio\2\201412041724_111.wav) result=0:FileExist:1,DelayTime:6000
2015-02-10 14:13:20.419  179 Get audio file:http://99.12.115.65/CMB_ASR/Voice/PuTongHua/请问您需要查询活期账户余额还是定期账户余额呢.vox success,save as z:\audio\2\201412041724_111.wav
2015-02-10 14:13:20.419  179 Enter CheckUserHookMsg() function, Param: ssp=-1
2015-02-10 14:13:20.429  179 Resource has been expire, but it is not changed!
2015-02-10 14:13:20.429  179 http://99.12.115.65/CMB_ASR/Voice/PuTongHua/如有疑问.vox resource is in cache,And it can be use!
2015-02-10 14:13:20.429  179 IVR(0,179)->IVRAGENT(255,65535): IVR_LIBAGENT_STATE(50008):seqno=21 flag=0 remote=z:\audio\2\201412041724_112.wav
2015-02-10 14:13:20.463  179 排队机(9,256)->IVR(0,179): IVR_LIBAGENT_STATE_ACK(50009):seqno=21 res=0 exist=1 size=3431
2015-02-10 14:13:20.464  179 get remote file(z:\audio\2\201412041724_112.wav) result=0:FileExist:1,DelayTime:6000
2015-02-10 14:13:20.464  179 Get audio file:http://99.12.115.65/CMB_ASR/Voice/PuTongHua/如有疑问.vox success,save as z:\audio\2\201412041724_112.wav
2015-02-10 14:13:20.464  179 Enter CheckUserHookMsg() function, Param: ssp=-1
2015-02-10 14:13:20.471  179 Resource has been expire, but it is not changed!
2015-02-10 14:13:20.471  179 http://99.12.115.65/CMB_ASR/Voice/PuTongHua/请说“帮助”.vox resource is in cache,And it can be use!
2015-02-10 14:13:20.471  179 IVR(0,179)->IVRAGENT(255,65535): IVR_LIBAGENT_STATE(50008):seqno=22 flag=0 remote=z:\audio\2\201412041724_113.wav
2015-02-10 14:13:20.543  179 排队机(9,257)->IVR(0,179): IVR_LIBAGENT_STATE_ACK(50009):seqno=22 res=0 exist=1 size=3525
2015-02-10 14:13:20.543  179 get remote file(z:\audio\2\201412041724_113.wav) result=0:FileExist:1,DelayTime:6000
2015-02-10 14:13:20.543  179 Get audio file:http://99.12.115.65/CMB_ASR/Voice/PuTongHua/请说“帮助”.vox success,save as z:\audio\2\201412041724_113.wav
2015-02-10 14:13:20.543  179 Interpreter gather active DGid, active grammar id: 16908288, grammar file name: dg1020000
2015-02-10 14:13:20.543  179 ===>MsgCount=1 MaxDigit=23 InterTime=5 EndDelineater=12 FirstTime=5 CancelDigit=255 InputModes=3
2015-02-10 14:13:20.543  179 Enter VXML_SpeakInput_E() function, Param: MaxDigit=23,InterTime=5,EndDelineater=12,FirstTime=5,CancelDigit=255,InputModes=3
2015-02-10 14:13:20.543  179 CI Speak&Input   max_digit = 23 , inter_time = 5 , end_delineater = 12 , first_time = 0  <prompt> Count = 1
2015-02-10 14:13:20.543  179 <prompt bargein='1'> strTtsAudio =  <audio$= z:\audio\2\201412041724_111.wav/> <audio$= z:\audio\2\201412041724_112.wav/> <audio$= z:\audio\2\201412041724_113.wav/>
2015-02-10 14:13:20.543  179 IVR(0,179)->CCS(255,212): 放音收号消息:放音识别收号的命令类型为14; VP  放音  语音识别, FileName=z:\audio\2\201412041724_111.wav; --放音叫ASR识别命令下发
2015-02-10 14:13:20.915  179 CCS(255,212)->IVR(0,179):  SP_START_DTMF_ASR_ACK result: 成功, vp dsn: 65535 --CTI反馈命令成功开始执行
2015-02-10 14:13:20.915  179 Enter IVR_ProcessEvent() function, Param: UserDialing=1, UserHookOff=1,TimeOut=1, ResAvailable=0, DeviceInfo=1,Notify=0, UserAsr=1
2015-02-10 14:13:20.915  179 [事件处理]

2015-02-10 14:13:25.144  179 CCS(255,212)->IVR(0,179): 录放音结束:MSG NOT SPECIFIED(21) --放音结果上报
2015-02-10 14:13:25.144  179 ProcessEvent receive msg type=21, mask=1048827
2015-02-10 14:13:25.144  179 设备消息出口
2015-02-10 14:13:25.144  179 Get Message form Queue! Event=设备消息出口(6)
2015-02-10 14:13:25.144  179 Send stopAsrDrv message! StopType=0, SSP=-1
2015-02-10 14:13:25.144  179 IVR(0,179)->CCS(255,212): 停止放音识别收号的消息:停止的类型为0--------------------->IVR下发停止ASR收号,但是此时CTI还没有上报收号成功的结果
2015-02-10 14:13:28.792  179 CCS(255,212)->IVR(0,179): 停止识别应答消息:结果为1 --停止ASR识别成功上报
2015-02-10 14:13:28.792  179 IVR(0,179)->CCS(255,212): 放音收号消息:放音识别收号的命令类型为14; VP  放音  语音识别, FileName=z:\audio\2\201412041724_112.wav; --第二次放音内容是:如有疑问
2015-02-10 14:13:29.120  179 CCS(255,212)->IVR(0,179):  SP_START_DTMF_ASR_ACK result: 成功, vp dsn: 65535
2015-02-10 14:13:29.120  179 Enter IVR_ProcessEvent() function, Param: UserDialing=1, UserHookOff=1,TimeOut=1, ResAvailable=0, DeviceInfo=1,Notify=0, UserAsr=1
2015-02-10 14:13:29.120  179 [事件处理]
2015-02-10 14:13:29.905  179 CCS(255,212)->IVR(0,179): 录放音结束:MSG NOT SPECIFIED(21)
2015-02-10 14:13:29.905  179 ProcessEvent receive msg type=21, mask=1048827
2015-02-10 14:13:29.905  179 设备消息出口
2015-02-10 14:13:29.905  179 Get Message form Queue! Event=设备消息出口(6)
2015-02-10 14:13:29.905  179 Send stopAsrDrv message! StopType=0, SSP=-1
2015-02-10 14:13:29.905  179 IVR(0,179)->CCS(255,212): 停止放音识别收号的消息:停止的类型为0
2015-02-10 14:13:33.585  179 CCS(255,212)->IVR(0,179): 停止识别应答消息:结果为1 ,第二次停止
2015-02-10 14:13:33.586  179 IVR(0,179)->CCS(255,212): 放音收号消息:放音识别收号的命令类型为14; VP  放音  语音识别, FileName=z:\audio\2\201412041724_113.wav;
2015-02-10 14:13:33.897  179 CCS(255,212)->IVR(0,179):  SP_START_DTMF_ASR_ACK result: 成功, vp dsn: 65535
2015-02-10 14:13:33.897  179 Enter IVR_ProcessEvent() function, Param: UserDialing=1, UserHookOff=1,TimeOut=1, ResAvailable=0, DeviceInfo=1,Notify=0, UserAsr=1
2015-02-10 14:13:33.897  179 [事件处理]
2015-02-10 14:13:34.729  179 CCS(255,212)->IVR(0,179): 录放音结束:MSG NOT SPECIFIED(21)
2015-02-10 14:13:34.729  179 ProcessEvent receive msg type=21, mask=1048827
2015-02-10 14:13:34.729  179 设备消息出口
2015-02-10 14:13:34.729  179 Get Message form Queue! Event=设备消息出口(6)
2015-02-10 14:13:34.729  179 Play_Drv_Asr return value = 6,Left <prompt> count= 0
2015-02-10 14:13:34.729  179 CI Speak&Input QuitVoiceEnd and allow bargein, next step is process event
2015-02-10 14:13:34.729  179 Enter IVR_ProcessEvent() function, Param: UserDialing=1, UserHookOff=1,TimeOut=1, ResAvailable=0, DeviceInfo=1,Notify=0, UserAsr=1
2015-02-10 14:13:34.729  179 [事件处理]
2015-02-10 14:13:37.825  179 CCS(255,212)->IVR(0,179): 上报识别收号结果消息:识别结束的原因为1:ASR_RESULT_TTS_ERROR --ASR识别语音失败上报
2015-02-10 14:13:37.825  179 ProcessEvent receive msg type=142, mask=1048827
2015-02-10 14:13:37.825  179 Get asrResult.ucResult=1
2015-02-10 14:13:37.825  179 设备消息出口
2015-02-10 14:13:37.825  179 Get Message form Queue! Event=设备消息出口(9)
2015-02-10 14:13:37.825  179 <===SpeakInputResult=9 input: ***0  InputType=0
2015-02-10 14:13:37.825  179 Platform speak Input result wrong, throw event: ERROR: Error occurs on VP when prompting, error.platform.vperror!
2015-02-10 14:13:37.826  179 Vxmlevent process, event type: error.platform.vperror , event message: ERROR: Error occurs on VP when prompting, error.platform.vperror!
2015-02-10 14:13:37.826  179 Interpreter throw  _exit event: unhandled event: event=error.platform.vperror msg=ERROR: Error occurs on VP when prompting, error.platform.vperror!
2015-02-10 14:13:37.826  179 Interpreter run, catch event : unhandled event: event=error.platform.vperror msg=ERROR: Error occurs on VP when prompting, error.platform.vperror!
2015-02-10 14:13:37.826  179 Enter VXML_Disconnect() function, Param: cause=0
2015-02-10 14:13:37.826  179 Enter CheckUserHookMsg() function, Param: ssp=54527
2015-02-10 14:13:37.826  179 Send disconnect/release msgtype=8 ssp=54527 cause=0
2015-02-10 14:13:37.826  179 IVR(0,179)->CCS(255,212): 拆线: 原因: 正常拆线 --IVR由于ASR失败失败,因此下发拆除呼叫的命令
2015-02-10 14:13:37.827  179 CCS(255,212)->IVR(0,179): 释放呼叫: 原因: 正常拆线

3、MRCP协议的分析

  对于停止收号响应慢的问题,是ASR侧过了3秒多才回的200消息。  UAP发起RECOGNIZE,但是ASR侧一直不响应。

4、从IP报文看,UAP发送bye消息给ASR侧,但是ASR侧一直没有响应。

 

根因

从IVR日志看,业务侧要连续播放三段语音,然后让客户进行ASR识别收号,但是每当一段语音播放结束的时候,业务就下发了停止ASR识别操作(由于ASR侧回复消息慢或不响应,导致两端语音之间出现停顿),IVR没有必要每次都要下发停止ASR,完全可以三段语音合在一起播放,然后一次性的stop停止ASR语音识别,IVR业务逻辑存在一些问题。

解决方案
因此基于当前的情况,给客户做出的解释和建议:
1、 让客户推动ASR厂商解决ASR服务端侧问题。
2、 业务侧IVR能否做一下调整,比如将这里出现的三条分段语音合并成一条语音进行播放:

201412041724_111.wav :  请问您需要查询活期账户余额还是定期账户余额呢
201412041724_112.wav:  如有疑问
201412041724_113.wav : 请说“帮助”

这样一定程度上能降低每段语音之间的间隔(将一个语音分成三段来播放,来回消息交互量会增加、每次资源操作也会有一定耗时,比如一两百个毫秒)。并且改变也可以改变一下放音三次合在一起,从业务侧考虑是否必要分开,如果分开必须保证ASR恢复识别消息的及时性,否则一定出现停顿的现象。

END