FreeSWITCH收到重復的DTMF信號
阿新 • • 發佈：2018-05-13
安裝 現象 語音 nba 五個 現在 bubuko .cn -a
一、背景
用戶是運營商手機，撥打的是運營商的固話號碼進入的FreeSWITCH的IVR，進入IVR語音播報後，按指定的分機號呼相關人員。
二、現象
用戶反映撥打124870找不到指定人員，以前是正常的。
三、排查
跟蹤日誌。
1772094 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:57.950006 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [1][0] 1772095 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:57.950006 [INFO] switch_channel.c:515RECV DTMF 1:0 1772096 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:57.950006 [DEBUG] switch_channel.c:524 sofia/internal/15367900000@172.18.0.220 SHORT DTMF DIGIT LEN [0] 1772099 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:58.190012 [DEBUG] switch_rtp.c:7193 RTP RECV DTMF 1:800 1772100 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:58.190012 [INFO] switch_channel.c:515 RECV DTMF 1:800 1772101 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:58.790011 [DEBUG] switch_rtp.c:7193 RTP RECV DTMF 1:800 1772102 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:58.790011 [INFO] switch_channel.c:515 RECV DTMF 1:800 1772124 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.370014 [DEBUG] switch_rtp.c:7193 RTP RECV DTMF 2:800 1772125 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.370014 [INFO] switch_channel.c:515 RECV DTMF 2:800 1772128 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.690013 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [4][320] 1772129 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.690013 [INFO] switch_channel.c:515 RECV DTMF 4:320 1772130 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.690013 [DEBUG] switch_channel.c:524 sofia/internal/15367900000@172.18.0.220 SHORT DTMF DIGIT LEN [320] 1772131 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.930011 [DEBUG] switch_rtp.c:7193 RTP RECV DTMF 4:800 1772132 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.930011 [INFO] switch_channel.c:515 RECV DTMF 4:800 1772133 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.930011 [DEBUG] switch_ivr_menu.c:424 digits 111244 1772134 daadbfe3-1cbf-47b3-a2eb-f97d0ad38911 2018-05-03 17:16:59.930011 [DEBUG] switch_ivr_menu.c:559 action regex [111244] [/^(\d{6})$/] [2]
四、分析日誌
發現收到了DTMF信號是111244。一個一個看，
第一個DTMF信號1是inband信號，從音頻信號裏分析出來的（看日誌打印DTMF DETECTED表明了這種方式）。
第二個DTMF信號1是RFC2833信號，從RTP包裏分析出來的（看日誌打印RTP RECV DTMF表明了這種方式）。
第三個DTMF信號1是RFC2833信號，從RTP包裏分析出來的（看日誌打印RTP RECV DTMF表明了這種方式）。
第四個DTMF信號2是RFC2833信號，從RTP包裏分析出來的（看日誌打印RTP RECV DTMF表明了這種方式）。
第五個DTMF信號4是inband信號，從音頻信號裏分析出來的（看日誌打印DTMF DETECTED表明了這種方式）。
第六個DTMF信號4是RFC2833信號，從RTP包裏分析出來的（看日誌打印RTP RECV DTMF表明了這種方式）。
也就是說，運營商同時用兩種方式給我傳輸了DTMF信號，關鍵FreeSWITCH還同時解了兩種信號源，拼成一個DTMF字串，所以BUG就出現了。
以前是正常的，是以前運營商沒有傳rfc2833信號。
聯系運營商，說關閉兩種協議同時發的配置了。現在只使用inband方式。
五、繼續測試
還是能收到號碼重復的現象，這次再看日誌，變化了：
這次所有的信號都是使用inband方式傳遞過來的了，但是依然重復了。
2546518 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:18.530004 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [1][0] 2546519 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:18.530004 [INFO] switch_channel.c:515 RECV DTMF 1:0 2546520 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:18.530004 [DEBUG] switch_channel.c:524 sofia/internal/15367900000@172.18.0.220 SHORT DTMF DIGIT LEN [0] 2546523 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:18.830006 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [1][640] 2546524 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:18.830006 [INFO] switch_channel.c:515 RECV DTMF 1:640 2546525 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:19.350005 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [7][0] 2546526 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:19.350005 [INFO] switch_channel.c:515 RECV DTMF 7:0 2546527 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:19.350005 [DEBUG] switch_channel.c:524 sofia/internal/15367900000@172.18.0.220 SHORT DTMF DIGIT LEN [0] 2546531 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:19.650004 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [7][640] 2546532 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:19.650004 [INFO] switch_channel.c:515 RECV DTMF 7:640 2546533 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.610004 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [8][0] 2546534 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.610004 [INFO] switch_channel.c:515 RECV DTMF 8:0 2546535 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.610004 [DEBUG] switch_channel.c:524 sofia/internal/15367900000@172.18.0.220 SHORT DTMF DIGIT LEN [0] 2546536 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.890004 [DEBUG] switch_ivr_async.c:3200 DTMF DETECTED: [8][640] 2546537 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.890004 [INFO] switch_channel.c:515 RECV DTMF 8:640 2546538 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.890004 [DEBUG] switch_ivr_menu.c:424 digits 117788 2546539 e6e0ab6c-dec7-4713-a235-a5c9254011e3 2018-05-09 09:57:20.890004 [DEBUG] switch_ivr_menu.c:559 action regex [117788] [/^(\d{6})$/] [2]
六、繼續處理
聯系運營商，說需要抓包分析。想一想也是，這種日誌畢竟是我們的軟件打印的，不排除我們軟件的檢測問題。
七、奇妙的過程
讓我們自己從源頭定位一下吧，首先，抓包。因為業務電話很多。抓到的wireshark包很大。
1. 拆包和並包，參考http://www.cnblogs.com/yoyotl/p/8579217.html。從1個GB的包裏拆出一個1.5MB的小包。
2. 查看並導出RTP流。
2.1 電話->RTP->RTP流；
2.2 在彈出的RTP流中選中需要導出那一條記錄->分析；
2.3 在彈出的對話框中選擇->Save->同步的正向音頻；
2.4 得到一個*.au格式的音頻文件。
贊一下wireshark，可以很直觀的看出來聲音波形，如圖：
3. 問題來了，怎麽知道這些波形裏是否含有DTMF信號呢？是的話又是哪個信號呢？
這時候就需要借助另外一款神奇的產品了Cool Edit，真是夠酷的！
4. 下載安裝，打開au文件，得到這樣的一個圖。
5. 乍一看和wireshark看到的波形一樣，但是這款軟件提供了量化分析的功能。
6. 選中想要分析的波形區域->Analyze->Show Frequency Analysis，彈出如下一個圖：
讀出兩個峰值，分別代表了低頻和高頻頻率。
低頻695.3，高頻1210
7. 對照標準的DTMF頻率表，如圖：
8. 哈哈，得到了這段波形代表的DTMF信號了，就是1。
以此類推，讀出這段波形中的DTMF信息是117788661100。
確定是運營商多送了重復的DTMF信號，不抓蝦的感覺真好。
FreeSWITCH收到重復的DTMF信號