SIPP 压测 IVR，FreeSWITCH收到了DTMF按键，但无法识别的问题

        昨天咱们团队的测试小姐姐跑过来找我，说通过SIPP压测IVR时，发现业务日志中没看到采集的按键，让我帮忙看看是哪里出了问题。

        明明以前可以运行的脚本，为啥放在现在的环境玩不转了呢？！一番拔丝抽茧后，问题被解决了……

 

        今早运动后，看了一眼窗外，风未止，雨已停。既然周末时光如此美好，思虑三秒后，决定写个随笔总结一下，毕竟年纪大了，好记性不如烂笔头嘛！

        说干咱就干，兄dei，让我们一起来解开呼叫中心IVR业务压测“事故现场”之谜吧

        

一、问题现象：

　　SIP和FS可以成功建立通话，并且SIPP脚本中明确采用读取pcap文件的方式发送了DTMF按键，但FS日志上看却没有收到按键信息（即没有打印 RTP RECV DTMF的字样）

二、运行环境

　　SIPP 版本 : v3.4.1-TLS-PCAP-RTPSTREAM built Jan 23 2017, 18:38:09

　　FS 版本    ：v1.6.20

　　OS 版本   : CentOs 7.9

二、问题分析

　　首先，咱检查下自己的SIPP脚本是否正确

       仔细确认过眼神，SIPP脚本中虽然给FS回ACK部分有些问题，但并不是影响按键的原因。发送按键的代码并没写错，确实发了按键，日志也能佐证。

压测脚本目录：
../sipp_script/
├── caller_ivr.xml
├── ivrsipp.cvs
├── pcap
│   └── dtmf_2833_4.pcap
└── sipp


caller_ivr.xml  文件中发送按键的内容


  <pause milliseconds="3000"/>
  <nop>
        <action>
                <exec play_pcap_audio="pcap/dtmf_2833_4.pcap"/>
                <log message="Call_num: [$caller_num1] send dtmf 4===================="/>
        </action>
  </nop>

vi caller_ivr_5648_logs.log SIPP日志，可以看到已经执行了发按键

===========From is Custom header is 491998 10.21.39.117
===========From is Custom header is 491998
Call_num: 491998 send dtmf 4====================

　　其次，咱看看FS日志，找找事故现场的蛛丝马迹

　　过滤后发现两点：

• FS日志里确实没有打印按键信息，因为没有打印 RTP RECV DTMF
• 通话的SDP里没检测到rfc2833, 被改用INFO 模式传输了

[powerop@FATD00194498 logs]$ grep e3bdf4d6-8ef5-48e4-9ed3-e48aa6b35a3c freeswitch.log* | grep "dtmf\|DTMF"
e3bdf4d6-8ef5-48e4-9ed3-e48aa6b35a3c tid:[139758169360128] 2022-02-18 13:23:34.924687 [DEBUG] switch_core_media.c:4784 No 2833 in SDP.  Disable 2833 dtmf and switch to INFO
e3bdf4d6-8ef5-48e4-9ed3-e48aa6b35a3c tid:[139758169360128] 2022-02-18 13:23:34.924687 [DEBUG] switch_core_media.c:7220 sofia/external/491998@10.2.85.25 Set rtp dtmf delay to 40

　　我们用软电话注册呼叫的方式测试一通，软电话按键模式采用rfc2833，FS可以收到按键，日志是下面这样的：

85ea46bd-ec8e-434e-9f55-a869738ef2ad tid:[139758169360128] 2022-02-18 13:25:53.664688 [DEBUG] switch_core_media.c:4777 sofia/external/1022@10.2.32.142 Set 2833 dtmf send payload to 101 recv payload to 101
85ea46bd-ec8e-434e-9f55-a869738ef2ad tid:[139758169360128] 2022-02-18 13:25:53.664688 [DEBUG] switch_core_media.c:7190 sofia/external/1022@10.2.32.142 Set 2833 dtmf send payload to 101
85ea46bd-ec8e-434e-9f55-a869738ef2ad tid:[139758169360128] 2022-02-18 13:25:53.664688 [DEBUG] switch_core_media.c:7197 sofia/external/1022@10.2.32.142 Set 2833 dtmf receive payload to 101
85ea46bd-ec8e-434e-9f55-a869738ef2ad tid:[139758169360128] 2022-02-18 13:25:53.664688 [DEBUG] switch_core_media.c:7220 sofia/external/1022@10.2.32.142 Set rtp dtmf delay to 40
85ea46bd-ec8e-434e-9f55-a869738ef2ad tid:[139758169360128] 2022-02-18 13:25:56.004688 [DEBUG] switch_rtp.c:7738 RTP RECV DTMF 4:1440
85ea46bd-ec8e-434e-9f55-a869738ef2ad tid:[139758169360128] 2022-02-18 13:25:56.004688 [INFO] switch_channel.c:515 RECV DTMF 4:1440

        然后，既然客户端发送了按键，但FS日志没有打印出来，咱就看看是不是因为网络原因，导致服务端FS没有收到RTP吧

        咱在服务端FS上抓包，从文件看，FS其实是收到了SIPP确实发了DTMF的，但最终没有解析出来

        

        

　　到这里，咱其实已经能得出下面一个结论：网络没有问题，问题出在FS上，应该是FS无法解析SIPP传输的inbound带内按键模式 ，只能处理RFC2833按键。

 

        BTW，关于DTMF在呼叫中心业务中的传输方式通常包含 outbound带外传输（SIP INFO）、inbound带内传输（DTMF放在RTP流中）、RFC2833(严格的讲也算inbound模式，只是这个有特殊的Payload Type值 101），这里不进行发散介绍了，有兴趣的同学就自行度娘吧。

        不过，我们可以顺道来看看SIP报文，发现SIPP测试时，FS回复的 200 OK 的 SDP里没有 DTMF 2833 信息，进一步佐证了咱前面的结论。

FS回复的异常200 OK	FS回复的正常200 OK
SIP/2.0 200 OK Via:  SIP/2.0/UDP 10.2.85.25:5070;branch=z9hG4bK14d6.216056d2.0 Via:  SIP/2.0/UDP 10.2.32.116:20001;branch=z9hG4bK-22926-1-0 Record-Route:  <sip:10.2.85.25:5070;lr;did=a0d.0f8a73e6> From:  491998 <sip:491998@10.2.85.25>;tag=1 To:  331054 <sip:331054@10.2.85.25>;tag=Z0ZXmD2ev4yBp Call-ID: 1-22926@10.2.32.116 CSeq:  1 INVITE Contact:  <sip:331054@10.21.39.117:5080;transport=udp> User-Agent:  FreeSWITCH-mod_sofia/1.6.20~64bit Accept:  application/sdp Allow:  INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported:  timer, path, replaces Allow-Events:  talk, hold, conference, refer Content-Type:  application/sdp Content-Disposition:  session Content-Length:  198 Remote-Party-ID:  "331054" <sip:331054@10.2.85.25>;party=calling;privacy=off;screen=no   v=0 o=FreeSWITCH 1645141666 1645141667 IN IP4 10.21.39.117 s=FreeSWITCH c=IN IP4 10.21.39.117 t=0 0 m=audio 20148 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtcp:20149 IN IP4 10.21.39.117	SIP/2.0 200 OK Via:  SIP/2.0/UDP 10.2.85.25:5070;branch=z9hG4bK57df.e5d8b5c2.0 Via:  SIP/2.0/UDP 10.2.32.142:5080;received=10.2.32.142;rport=5080;branch=z9hG4bKp449tF2aKt50r Record-Route:  <sip:10.2.85.25:5070;lr;did=9cf.c6140023> From:  "Extension 1022" <sip:1022@10.2.32.142>;tag=1Htg00NZF7j2j To:  <sip:331054@10.2.85.25:5070>;tag=m04rB9St6S40e Call-ID: 1555d89c-0b1e-123b-a58b-fa163e1b47d2 CSeq:  48027184 INVITE Contact:  <sip:331054@10.21.39.117:5080;transport=udp> User-Agent:  FreeSWITCH-mod_sofia/1.6.20~64bit Accept:  application/sdp Allow:  INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported:  timer, path, replaces Allow-Events:  talk, hold, conference, refer Content-Type:  application/sdp Content-Disposition:  session Content-Length:  254 X-FS-Display-Name:  331054 X-FS-Display-Number:  sip:331054@10.2.85.25 X-FS-Support:  update_display,send_info Remote-Party-ID:  "331054" <sip:331054@10.2.85.25>;party=calling;privacy=off;screen=no   v=0 o=FreeSWITCH 1645135459 1645135460 IN IP4 10.21.39.117 s=FreeSWITCH c=IN IP4 10.21.39.117 t=0 0 m=audio 26494 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=rtcp:26495 IN IP4 10.21.39.117
SIPP 发送的INVITE 【以下给的是OpenSIPs上转发给FS的报文】	软电话测试发起的INVITE 【以下给的是OpenSIPs上转发给FS的报文】
INVITE sip:331054@10.21.39.117:5080 SIP/2.0 Record-Route:  <sip:10.2.85.25:5070;lr;did=a0d.0f8a73e6> Via:  SIP/2.0/UDP 10.2.85.25:5070;branch=z9hG4bK14d6.216056d2.0 Via:  SIP/2.0/UDP 10.2.32.116:20001;branch=z9hG4bK-22926-1-0 From:  491998 <sip:491998@10.2.85.25>;tag=1 To:  331054 <sip:331054@10.2.85.25> Call-ID: 1-22926@10.2.32.116 CSeq:  1 INVITE Contact:  <sip:491998@10.2.32.116:20001> Max-Forwards:  69 Subject:  Call Performance Test user-agent:  SIPp client mode version unknown Content-Type:  application/sdp Content-Length:    200 X-UUI:  &XCID=09469f19016451618148EXCIDEND X-CID:  09469f19016451618148EXCIDEND   v=0 o=user1 53655765 2353687637 IN IP4 10.2.32.116 s=- c=IN IP4 10.2.32.116 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16   【这里是脚本故意为之，咱用不到12-15】 a=sendrecv	INVITE sip:331054@10.21.39.117:5080 SIP/2.0 Record-Route:  <sip:10.2.85.25:5070;lr;did=9cf.c6140023> Via:  SIP/2.0/UDP 10.2.85.25:5070;branch=z9hG4bK57df.e5d8b5c2.0 Via:  SIP/2.0/UDP 10.2.32.142:5080;received=10.2.32.142;rport=5080;branch=z9hG4bKp449tF2aKt50r Max-Forwards:  68 From:  "Extension 1022" <sip:1022@10.2.32.142>;tag=1Htg00NZF7j2j To:  <sip:331054@10.2.85.25:5070> Call-ID: 1555d89c-0b1e-123b-a58b-fa163e1b47d2 CSeq:  48027184 INVITE Contact:  <sip:mod_sofia@10.2.32.142:5080> User-Agent:  FreeSWITCH-mod_sofia/1.6.20+git~20201225T055006Z~c731e3fe87~64bit Allow:  INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported:  timer, path, replaces Allow-Events:  talk, hold, conference, refer Content-Type:  application/sdp Content-Disposition:  session Content-Length:  242 X-FS-Support:  update_display,send_info Remote-Party-ID:  "Extension 1022" <sip:1022@10.2.32.142>;party=calling;screen=yes;privacy=off X-UUI:  &XCID=0aab741d616451619532EXCIDEND X-CID:  0aab741d616451619532EXCIDEND   v=0 o=FreeSWITCH 1645138423 1645138424 IN IP4 10.2.32.142 s=FreeSWITCH c=IN IP4 10.2.32.142 t=0 0 m=audio 23530 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20

 

        接下来检查FS配置文件 vars.xml ,  发现文件中没有配置 rtp_liberal_dtmf ，导致无法兼容非常规的按键模式。

 

三、解决问题

        调整FS vars.xml 文件，增加下面蓝色加粗部分的配置项， 重启FS，问题解决

  <!--close rtp cng 2021-04-29-->
  <X-PRE-PROCESS cmd="set" data="suppress_cng=true"/>

  <!--open rtcp cng 2021-11-11-->
  <X-PRE-PROCESS cmd="set" data="rtcp_mux=false"/>
  <X-PRE-PROCESS cmd="set" data="rtcp_audio_interval_msec=3000"/>

8   <!-- Enable liberal DTMF for those that can't get it right  -->
9   <X-PRE-PROCESS cmd="set" data="rtp_liberal_dtmf=true"/>

        重新运行SIPP压测脚本，成功获取到按键，得到FS日志如下：

SDP中没有2833，所以FS自动进行兼容，增加 101 telephone-event SDP 头
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:35.942635 [DEBUG] switch_core_media.c:4738 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:35.942635 [DEBUG] switch_core_media.c:4767 sofia/external/491998@10.2.32.142 Set 2833 dtmf send payload to 101 recv payload to 101
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:35.942635 [DEBUG] switch_core_media.c:7180 sofia/external/491998@10.2.32.142 Set 2833 dtmf send payload to 101
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:35.942635 [DEBUG] switch_core_media.c:7187 sofia/external/491998@10.2.32.142 Set 2833 dtmf receive payload to 101
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:35.942635 [DEBUG] switch_core_media.c:7210 sofia/external/491998@10.2.32.142 Set rtp dtmf delay to 40
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:39.082643 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 4:2240
acd3b564-90be-11ec-9fca-9785bd7be268 tid:[139932390749952] 2022-02-18 21:28:39.082643 [INFO] switch_channel.c:515 RECV DTMF 4:2240

 

附录：

SDP 信息中 【 a=fmtp:101 0-11,16】 的含义

101 ： 代表是采用rfc2833 telephone-event模式传输按键

0-11,16 ：代表支持的DTMF按键 

DTMF-related named Event	Event encoding (decimal)
0–9	0–9
*	10
#	11
A–D	12–15
Flash	16

　　Tips，对于编写SIPP脚本不是很熟练的同学，可以通过用软电话注册拨打测试，并进行抓包，然后分析抓包文件中SIP 信令，按照信令内容编写SIPP脚步即可。

　　这里给出本次测试的SIPP脚步和抓包文件，供大家参看。

• SIPP测试脚本+抓包文件

• SIPP使用手册