[Freeswitch-users] SBC bridged call: DTMF delay

Alex Zarubin ZAlex at webley.com
Mon Sep 17 22:58:38 MSD 2012 

Hi all,

 

FS in SBC mode, 'external' and 'internal' sip calls are bridged. DTMF
sequence '11234567890' gets passed with a delay, - 2 sec between the
last digit '0' is received and sent (see log below). There is a
consistent 500ms+ between 'Queue digit delay of 40ms' and 'Send start
packet' for the next digit.

Haven't found a way to fix it so far (wiki, user list, parameters such
as auto-rtp-bugs), help will be appreciated. CentOS 6.1, Xen, rfc2833.

 

Thank you.

 

Alex

 

 

2012-09-17 12:52:20.714917 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF
1:1120

2012-09-17 12:52:20.714917 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:20.774914 [DEBUG] switch_rtp.c:2420 Send start packet
for [1] ts=325320 dur=160/160/1120 seq=6880 lw=325320

2012-09-17 12:52:20.794915 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=325320 dur=320/320/1120 seq=6881 lw=325480

2012-09-17 12:52:20.814914 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=325320 dur=480/480/1120 seq=6882 lw=325640

2012-09-17 12:52:20.834915 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=325320 dur=640/640/1120 seq=6883 lw=325800

2012-09-17 12:52:20.874917 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=325320 dur=800/800/1120 seq=6884 lw=161

2012-09-17 12:52:20.894918 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=325320 dur=960/960/1120 seq=6885 lw=321

2012-09-17 12:52:20.914916 [DEBUG] switch_rtp.c:2323 Send end packet for
[1] ts=325320 dur=1120/1120/1120 seq=6886 lw=321

2012-09-17 12:52:20.914916 [DEBUG] switch_rtp.c:2323 Send end packet for
[1] ts=325320 dur=1120/1120/1120 seq=6887 lw=321

2012-09-17 12:52:20.914916 [DEBUG] switch_rtp.c:2323 Send end packet for
[1] ts=325320 dur=1120/1120/1120 seq=6888 lw=321

2012-09-17 12:52:20.914916 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:21.054920 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 1:960

2012-09-17 12:52:21.054920 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:21.454915 [DEBUG] switch_rtp.c:2420 Send start packet
for [1] ts=331880 dur=160/160/960 seq=6907 lw=331880

2012-09-17 12:52:21.474918 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=331880 dur=320/320/960 seq=6908 lw=332040

2012-09-17 12:52:21.494916 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 2:800

2012-09-17 12:52:21.494916 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=331880 dur=480/480/960 seq=6909 lw=332200

2012-09-17 12:52:21.494916 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:21.514915 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=331880 dur=640/640/960 seq=6910 lw=332360

2012-09-17 12:52:21.534920 [DEBUG] switch_rtp.c:2323 Send middle packet
for [1] ts=331880 dur=800/800/960 seq=6911 lw=332520

2012-09-17 12:52:21.554917 [DEBUG] switch_rtp.c:2323 Send end packet for
[1] ts=331880 dur=960/960/960 seq=6912 lw=332520

2012-09-17 12:52:21.554917 [DEBUG] switch_rtp.c:2323 Send end packet for
[1] ts=331880 dur=960/960/960 seq=6913 lw=332520

2012-09-17 12:52:21.554917 [DEBUG] switch_rtp.c:2323 Send end packet for
[1] ts=331880 dur=960/960/960 seq=6914 lw=332520

2012-09-17 12:52:21.554917 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:21.934916 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 3:800

2012-09-17 12:52:21.934916 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:22.094915 [DEBUG] switch_rtp.c:2420 Send start packet
for [2] ts=337000 dur=160/160/800 seq=6934 lw=337000

2012-09-17 12:52:22.114914 [DEBUG] switch_rtp.c:2323 Send middle packet
for [2] ts=337000 dur=320/320/800 seq=6935 lw=337160

2012-09-17 12:52:22.134920 [DEBUG] switch_rtp.c:2323 Send middle packet
for [2] ts=337000 dur=480/480/800 seq=6936 lw=337320

2012-09-17 12:52:22.154919 [DEBUG] switch_rtp.c:2323 Send middle packet
for [2] ts=337000 dur=640/640/800 seq=6937 lw=337480

2012-09-17 12:52:22.174917 [DEBUG] switch_rtp.c:2323 Send end packet for
[2] ts=337000 dur=800/800/800 seq=6938 lw=337480

2012-09-17 12:52:22.174917 [DEBUG] switch_rtp.c:2323 Send end packet for
[2] ts=337000 dur=800/800/800 seq=6939 lw=337480

2012-09-17 12:52:22.174917 [DEBUG] switch_rtp.c:2323 Send end packet for
[2] ts=337000 dur=800/800/800 seq=6940 lw=337480

2012-09-17 12:52:22.174917 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:22.554917 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 4:960

2012-09-17 12:52:22.554917 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:22.714915 [DEBUG] switch_rtp.c:2420 Send start packet
for [3] ts=341960 dur=160/160/800 seq=6959 lw=341960

2012-09-17 12:52:22.734917 [DEBUG] switch_rtp.c:2323 Send middle packet
for [3] ts=341960 dur=320/320/800 seq=6960 lw=342120

2012-09-17 12:52:22.754918 [DEBUG] switch_rtp.c:2323 Send middle packet
for [3] ts=341960 dur=480/480/800 seq=6961 lw=342280

2012-09-17 12:52:22.774919 [DEBUG] switch_rtp.c:2323 Send middle packet
for [3] ts=341960 dur=640/640/800 seq=6962 lw=342440

2012-09-17 12:52:22.794916 [DEBUG] switch_rtp.c:2323 Send end packet for
[3] ts=341960 dur=800/800/800 seq=6963 lw=342440

2012-09-17 12:52:22.794916 [DEBUG] switch_rtp.c:2323 Send end packet for
[3] ts=341960 dur=800/800/800 seq=6964 lw=342440

2012-09-17 12:52:22.794916 [DEBUG] switch_rtp.c:2323 Send end packet for
[3] ts=341960 dur=800/800/800 seq=6965 lw=342440

2012-09-17 12:52:22.794916 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:22.994918 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 5:800

2012-09-17 12:52:22.994918 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:23.334917 [DEBUG] switch_rtp.c:2420 Send start packet
for [4] ts=346920 dur=160/160/960 seq=6985 lw=346920

2012-09-17 12:52:23.354917 [DEBUG] switch_rtp.c:2323 Send middle packet
for [4] ts=346920 dur=320/320/960 seq=6986 lw=347080

2012-09-17 12:52:23.374915 [DEBUG] switch_rtp.c:2323 Send middle packet
for [4] ts=346920 dur=480/480/960 seq=6987 lw=347240

2012-09-17 12:52:23.394913 [DEBUG] switch_rtp.c:2323 Send middle packet
for [4] ts=346920 dur=640/640/960 seq=6988 lw=347400

2012-09-17 12:52:23.414914 [DEBUG] switch_rtp.c:2323 Send middle packet
for [4] ts=346920 dur=800/800/960 seq=6989 lw=347560

2012-09-17 12:52:23.434914 [DEBUG] switch_rtp.c:2323 Send end packet for
[4] ts=346920 dur=960/960/960 seq=6990 lw=347560

2012-09-17 12:52:23.434914 [DEBUG] switch_rtp.c:2323 Send end packet for
[4] ts=346920 dur=960/960/960 seq=6991 lw=347560

2012-09-17 12:52:23.434914 [DEBUG] switch_rtp.c:2323 Send end packet for
[4] ts=346920 dur=960/960/960 seq=6992 lw=347560

2012-09-17 12:52:23.434914 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:23.474915 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 6:800

2012-09-17 12:52:23.474915 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

nta: timer J fired, terminate 200 response

nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free

2012-09-17 12:52:23.974919 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 7:960

2012-09-17 12:52:23.974919 [DEBUG] switch_rtp.c:2420 Send start packet
for [5] ts=351560 dur=160/160/800 seq=7012 lw=351560

2012-09-17 12:52:23.974919 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:23.994918 [DEBUG] switch_rtp.c:2323 Send middle packet
for [5] ts=351560 dur=320/320/800 seq=7013 lw=351720

2012-09-17 12:52:24.014914 [DEBUG] switch_rtp.c:2323 Send middle packet
for [5] ts=351560 dur=480/480/800 seq=7014 lw=351880

2012-09-17 12:52:24.034914 [DEBUG] switch_rtp.c:2323 Send middle packet
for [5] ts=351560 dur=640/640/800 seq=7015 lw=352040

2012-09-17 12:52:24.054913 [DEBUG] switch_rtp.c:2323 Send end packet for
[5] ts=351560 dur=800/800/800 seq=7016 lw=352040

2012-09-17 12:52:24.054913 [DEBUG] switch_rtp.c:2323 Send end packet for
[5] ts=351560 dur=800/800/800 seq=7017 lw=352040

2012-09-17 12:52:24.054913 [DEBUG] switch_rtp.c:2323 Send end packet for
[5] ts=351560 dur=800/800/800 seq=7018 lw=352040

2012-09-17 12:52:24.054913 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:24.394917 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 8:960

2012-09-17 12:52:24.394917 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:24.594915 [DEBUG] switch_rtp.c:2420 Send start packet
for [6] ts=357000 dur=160/160/800 seq=7037 lw=357000

2012-09-17 12:52:24.614924 [DEBUG] switch_rtp.c:2323 Send middle packet
for [6] ts=357000 dur=320/320/800 seq=7038 lw=357160

2012-09-17 12:52:24.634922 [DEBUG] switch_rtp.c:2323 Send middle packet
for [6] ts=357000 dur=480/480/800 seq=7039 lw=357320

2012-09-17 12:52:24.654919 [DEBUG] switch_rtp.c:2323 Send middle packet
for [6] ts=357000 dur=640/640/800 seq=7040 lw=357480

2012-09-17 12:52:24.674918 [DEBUG] switch_rtp.c:2323 Send end packet for
[6] ts=357000 dur=800/800/800 seq=7041 lw=357480

2012-09-17 12:52:24.674918 [DEBUG] switch_rtp.c:2323 Send end packet for
[6] ts=357000 dur=800/800/800 seq=7042 lw=357480

2012-09-17 12:52:24.674918 [DEBUG] switch_rtp.c:2323 Send end packet for
[6] ts=357000 dur=800/800/800 seq=7043 lw=357480

2012-09-17 12:52:24.674918 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:24.814915 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 9:800

2012-09-17 12:52:24.814915 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:25.214926 [DEBUG] switch_rtp.c:2420 Send start packet
for [7] ts=361960 dur=160/160/960 seq=7063 lw=361960

2012-09-17 12:52:25.234921 [DEBUG] switch_rtp.c:2323 Send middle packet
for [7] ts=361960 dur=320/320/960 seq=7064 lw=362120

2012-09-17 12:52:25.254920 [DEBUG] switch_rtp.c:2323 Send middle packet
for [7] ts=361960 dur=480/480/960 seq=7065 lw=362280

2012-09-17 12:52:25.274919 [DEBUG] switch_rtp.c:2323 Send middle packet
for [7] ts=361960 dur=640/640/960 seq=7066 lw=362440

2012-09-17 12:52:25.294926 [DEBUG] switch_rtp.c:3410 RTP RECV DTMF 0:800

2012-09-17 12:52:25.294926 [DEBUG] switch_rtp.c:2323 Send middle packet
for [7] ts=361960 dur=800/800/960 seq=7067 lw=362600

2012-09-17 12:52:25.294926 [DEBUG] switch_ivr_bridge.c:391 Send signal
sofia/internal/9910 at Kate-conf02-dev.webley.com:5080 [BREAK]

2012-09-17 12:52:25.314920 [DEBUG] switch_rtp.c:2323 Send end packet for
[7] ts=361960 dur=960/960/960 seq=7068 lw=362600

2012-09-17 12:52:25.314920 [DEBUG] switch_rtp.c:2323 Send end packet for
[7] ts=361960 dur=960/960/960 seq=7069 lw=362600

2012-09-17 12:52:25.314920 [DEBUG] switch_rtp.c:2323 Send end packet for
[7] ts=361960 dur=960/960/960 seq=7070 lw=362600

2012-09-17 12:52:25.314920 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:25.874915 [DEBUG] switch_rtp.c:2420 Send start packet
for [8] ts=161 dur=160/160/960 seq=7096 lw=161

2012-09-17 12:52:25.894918 [DEBUG] switch_rtp.c:2323 Send middle packet
for [8] ts=161 dur=320/320/960 seq=7097 lw=321

2012-09-17 12:52:25.914916 [DEBUG] switch_rtp.c:2323 Send middle packet
for [8] ts=161 dur=480/480/960 seq=7098 lw=481

2012-09-17 12:52:25.934917 [DEBUG] switch_rtp.c:2323 Send middle packet
for [8] ts=161 dur=640/640/960 seq=7099 lw=641

2012-09-17 12:52:25.954921 [DEBUG] switch_rtp.c:2323 Send middle packet
for [8] ts=161 dur=800/800/960 seq=7100 lw=801

2012-09-17 12:52:25.974930 [DEBUG] switch_rtp.c:2323 Send end packet for
[8] ts=161 dur=960/960/960 seq=7101 lw=801

2012-09-17 12:52:25.974930 [DEBUG] switch_rtp.c:2323 Send end packet for
[8] ts=161 dur=960/960/960 seq=7102 lw=801

2012-09-17 12:52:25.974930 [DEBUG] switch_rtp.c:2323 Send end packet for
[8] ts=161 dur=960/960/960 seq=7103 lw=801

2012-09-17 12:52:25.974930 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:26.514917 [DEBUG] switch_rtp.c:2420 Send start packet
for [9] ts=372360 dur=160/160/800 seq=7128 lw=372360

2012-09-17 12:52:26.534917 [DEBUG] switch_rtp.c:2323 Send middle packet
for [9] ts=372360 dur=320/320/800 seq=7129 lw=372520

2012-09-17 12:52:26.554924 [DEBUG] switch_rtp.c:2323 Send middle packet
for [9] ts=372360 dur=480/480/800 seq=7130 lw=372680

2012-09-17 12:52:26.574918 [DEBUG] switch_rtp.c:2323 Send middle packet
for [9] ts=372360 dur=640/640/800 seq=7131 lw=372840

2012-09-17 12:52:26.594915 [DEBUG] switch_rtp.c:2323 Send end packet for
[9] ts=372360 dur=800/800/800 seq=7132 lw=372840

2012-09-17 12:52:26.594915 [DEBUG] switch_rtp.c:2323 Send end packet for
[9] ts=372360 dur=800/800/800 seq=7133 lw=372840

2012-09-17 12:52:26.594915 [DEBUG] switch_rtp.c:2323 Send end packet for
[9] ts=372360 dur=800/800/800 seq=7134 lw=372840

2012-09-17 12:52:26.594915 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms

2012-09-17 12:52:27.134920 [DEBUG] switch_rtp.c:2420 Send start packet
for [0] ts=377480 dur=160/160/800 seq=7160 lw=377480

2012-09-17 12:52:27.154916 [DEBUG] switch_rtp.c:2323 Send middle packet
for [0] ts=377480 dur=320/320/800 seq=7161 lw=377640

2012-09-17 12:52:27.174916 [DEBUG] switch_rtp.c:2323 Send middle packet
for [0] ts=377480 dur=480/480/800 seq=7162 lw=377800

2012-09-17 12:52:27.194919 [DEBUG] switch_rtp.c:2323 Send middle packet
for [0] ts=377480 dur=640/640/800 seq=7163 lw=377960

2012-09-17 12:52:27.214916 [DEBUG] switch_rtp.c:2323 Send end packet for
[0] ts=377480 dur=800/800/800 seq=7164 lw=377960

2012-09-17 12:52:27.214916 [DEBUG] switch_rtp.c:2323 Send end packet for
[0] ts=377480 dur=800/800/800 seq=7165 lw=377960

2012-09-17 12:52:27.214916 [DEBUG] switch_rtp.c:2323 Send end packet for
[0] ts=377480 dur=800/800/800 seq=7166 lw=377960

2012-09-17 12:52:27.214916 [DEBUG] switch_rtp.c:2271 Queue digit delay
of 40ms


 
This message and any attachments to it are intended only for the addressee(s) identified above and may contain CONFIDENTIAL information. It is not intended for transmission to, or receipt by, any unauthorized persons.  If you are not an intended recipient or an agent responsible for delivering it to an intended recipient, you have received this e-mail in error and any dissemination, distribution, or copying of this message or any attachment to it is strictly prohibited. If you have received this email in error, please (i) do not read it, (ii) reply to the sender that you received the message in error, and (iii) erase or destroy the message from your system.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120917/9ff43c03/attachment-0001.html

Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users mailing list