Search code examples
freeswitchdtmf

freeswitch can't receive b-leg dtmf during calling to an agent of callcenter for at least 60 seconds


As the title says, I have a problem of getting dtmf digits from b-leg. When I call a queue in callcenter, the two legs can be bridged. But It doesn't have any reaction when I press '*7' on my b-leg telephone.

Here is the dialplan:

    <extension name="Queue90">
        <condition field="destination_number" expression="^90$">
            <action application="bind_meta_app" data="7 ab s execute_extension::att_xfer XML features"/>
            <action application="callcenter" data="90"/>
        </condition>
    </extension>

And, here is the console log:

2021-10-28 10:44:19.553594 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/[email protected] [f3285184-3798-11ec-a026-fd0671809b3f]
2021-10-28 10:44:19.553594 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_NEW (Cur 1 Tot 3)
2021-10-28 10:44:19.553594 [DEBUG] sofia.c:10279 sofia/internal/[email protected] receiving invite from 10.30.4.11:5060 version: 1.10.3 -release 64bit
2021-10-28 10:44:19.553594 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 10.30.4.11:0.
2021-10-28 10:44:19.553594 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/[email protected]) State NEW
2021-10-28 10:44:19.573586 [DEBUG] sofia.c:2434 detaching session f3285184-3798-11ec-a026-fd0671809b3f
freeswitch@pbx>
2021-10-28 10:44:19.593597 [DEBUG] sofia.c:2544 Re-attaching to session f3285184-3798-11ec-a026-fd0671809b3f
2021-10-28 10:44:19.613595 [DEBUG] sofia.c:10279 sofia/internal/[email protected] receiving invite from 10.30.4.11:5060 version: 1.10.3 -release 64bit
2021-10-28 10:44:19.613595 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 10.30.4.11:0.
2021-10-28 10:44:19.613595 [NOTICE] mod_python.c:213 Invoking py module: user_manage
2021-10-28 10:44:19.613595 [DEBUG] mod_python.c:305 Call python script
2021-10-28 10:44:19.633586 [DEBUG] mod_python.c:308 Finished calling python script
2021-10-28 10:44:19.633586 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected] entering state [received][100]
2021-10-28 10:44:19.633586 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=8001 8000 8000 IN IP4 10.30.4.11
s=SIP Call
c=IN IP4 10.30.4.11
t=0 0
m=audio 5004 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2021-10-28 10:44:19.633586 [DEBUG] sofia.c:7738 (sofia/internal/[email protected]) State Change CS_NEW -> CS_INIT
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_INIT (Cur 1 Tot 3)
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/[email protected]) State INIT
2021-10-28 10:44:19.633586 [DEBUG] mod_sofia.c:93 sofia/internal/[email protected] SOFIA INIT
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:40 sofia/internal/[email protected] Standard INIT
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/[email protected]) State Change CS_INIT -> CS_ROUTING
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/[email protected]) State INIT going to sleep
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_ROUTING (Cur 1 Tot 3)
2021-10-28 10:44:19.633586 [DEBUG] switch_channel.c:2332 (sofia/internal/[email protected]) Callstate Change DOWN -> RINGING
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/[email protected]) State ROUTING
2021-10-28 10:44:19.633586 [DEBUG] mod_sofia.c:154 sofia/internal/[email protected] SOFIA ROUTING
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:236 sofia/internal/[email protected] Standard ROUTING
2021-10-28 10:44:19.633586 [INFO] mod_dialplan_xml.c:637 Processing xxx <8001>->90 in context default
Dialplan: sofia/internal/[email protected] parsing [default->Queue90] continue=false
Dialplan: sofia/internal/[email protected] Regex (PASS) [Queue90] destination_number(90) =~ /^90$/ break=on-false
Dialplan: sofia/internal/[email protected] Action bind_meta_app(7 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/[email protected] Action callcenter(90)
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/[email protected]) State Change CS_ROUTING -> CS_EXECUTE
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/[email protected]) State ROUTING going to sleep
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_EXECUTE (Cur 1 Tot 3)
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/[email protected]) State EXECUTE
2021-10-28 10:44:19.633586 [DEBUG] mod_sofia.c:209 sofia/internal/[email protected] SOFIA EXECUTE
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:329 sofia/internal/[email protected] Standard EXECUTE
EXECUTE [depth=0] sofia/internal/[email protected] bind_meta_app(7 b s execute_extension::att_xfer XML features)
2021-10-28 10:44:19.633586 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *7 execute_extension::att_xfer XML features
2021-10-28 10:44:19.633586 [DEBUG] switch_core_session.c:2722 Application callcenter Requires media! pre_answering channel sofia/internal/[email protected]
2021-10-28 10:44:19.633586 [INFO] switch_core_session.c:2724 Sending early media
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 101@8000
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:3837 Set Codec sofia/internal/[email protected] PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2021-10-28 10:44:19.633586 [DEBUG] switch_core_codec.c:111 sofia/internal/[email protected] Original read codec set to PCMU:0
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5851 Set telephone-event payload to 101@8000
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:5909 sofia/internal/[email protected] Set 2833 dtmf send payload to 101 recv payload to 101
2021-10-28 10:44:19.633586 [DEBUG] switch_core_media.c:8661 AUDIO RTP [sofia/internal/[email protected]] 10.75.6.77 port 30308 -> 10.30.4.11 port 5004 codec: 0 ms: 20
2021-10-28 10:44:19.633586 [DEBUG] switch_rtp.c:4413 Starting timer [soft] 160 bytes per 20ms
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8975 sofia/internal/[email protected] Set 2833 dtmf send payload to 101
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8982 sofia/internal/[email protected] Set 2833 dtmf receive payload to 101
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:9005 sofia/internal/[email protected] Set rtp dtmf delay to 40
2021-10-28 10:44:19.653601 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/[email protected]!
2021-10-28 10:44:19.653601 [DEBUG] switch_channel.c:3565 (sofia/internal/[email protected]) Callstate Change RINGING -> EARLY
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8643 Audio params are unchanged for sofia/internal/[email protected].
2021-10-28 10:44:19.653601 [DEBUG] mod_sofia.c:2593 Ring SDP:
v=0
o=FreeSWITCH 1635358751 1635358752 IN IP4 10.75.6.77
s=FreeSWITCH
c=IN IP4 10.75.6.77
t=0 0
m=audio 30308 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

EXECUTE [depth=0] sofia/internal/[email protected] callcenter(90)
2021-10-28 10:44:19.653601 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected] entering state [early][183]
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8643 Audio params are unchanged for sofia/internal/[email protected].
2021-10-28 10:44:19.653601 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/[email protected]:
v=0
o=FreeSWITCH 1635358751 1635358753 IN IP4 10.75.6.77
s=FreeSWITCH
c=IN IP4 10.75.6.77
t=0 0
m=audio 30308 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2021-10-28 10:44:19.653601 [NOTICE] mod_callcenter.c:3020 Channel [sofia/internal/[email protected]] has been answered
2021-10-28 10:44:19.653601 [DEBUG] switch_channel.c:3865 (sofia/internal/[email protected]) Callstate Change EARLY -> ACTIVE
2021-10-28 10:44:19.653601 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected] entering state [completed][200]
2021-10-28 10:44:19.653601 [DEBUG] mod_callcenter.c:3111 Member xxx <8001> joining queue 90
2021-10-28 10:44:19.653601 [DEBUG] mod_callcenter.c:3375 Queue has 1 waiting calls.
2021-10-28 10:44:19.653601 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@8000hz 1 channels 20ms
freeswitch@pbx>
2021-10-28 10:44:19.673591 [DEBUG] mod_callcenter.c:1180 Updated Agent 5001 set state = Receiving
2021-10-28 10:44:19.673591 [DEBUG] mod_callcenter.c:1753 Setting outbound caller_id_name to: xxx
2021-10-28 10:44:19.673591 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2021-10-28 10:44:19.673591 [DEBUG] switch_ivr_originate.c:2804 Parsing session specific variables
2021-10-28 10:44:19.673591 [NOTICE] mod_python.c:213 Invoking py module: user_manage
2021-10-28 10:44:19.673591 [DEBUG] mod_python.c:305 Call python script
2021-10-28 10:44:19.693596 [DEBUG] mod_python.c:308 Finished calling python script
2021-10-28 10:44:19.693596 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2021-10-28 10:44:19.693596 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/[email protected]:5068 [f33da75a-3798-11ec-a02f-fd0671809b3f]
2021-10-28 10:44:19.693596 [DEBUG] mod_sofia.c:5089 (sofia/internal/[email protected]:5068) State Change CS_NEW -> CS_INIT
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_INIT (Cur 2 Tot 4)
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/[email protected]:5068) State INIT
2021-10-28 10:44:19.693596 [DEBUG] mod_sofia.c:93 sofia/internal/[email protected]:5068 SOFIA INIT
2021-10-28 10:44:19.693596 [DEBUG] sofia_glue.c:1587 sip:[email protected]:5068 Setting proxy route to sofia/internal/[email protected]:5068
2021-10-28 10:44:19.693596 [DEBUG] sofia_glue.c:1618 sofia/internal/[email protected]:5068 sending invite version: 1.10.3 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1635364719 1635364720 IN IP4 10.75.6.77
s=FreeSWITCH
c=IN IP4 10.75.6.77
t=0 0
m=audio 24340 RTP/AVP 102 9 0 8 105 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:105 telephone-event/48000
a=fmtp:105 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=video 25832 RTP/AVP 103 104
b=AS:3072
a=rtpmap:103 H264/90000
a=rtpmap:104 VP8/90000
a=sendrecv
a=rtcp-fb:103 ccm fir
a=rtcp-fb:103 ccm tmmbr
a=rtcp-fb:103 nack
a=rtcp-fb:103 nack pli
a=rtcp-fb:104 ccm fir
a=rtcp-fb:104 ccm tmmbr
a=rtcp-fb:104 nack
a=rtcp-fb:104 nack pli

2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:40 sofia/internal/[email protected]:5068 Standard INIT
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/[email protected]:5068) State Change CS_INIT -> CS_ROUTING
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/[email protected]:5068) State INIT going to sleep
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_ROUTING (Cur 2 Tot 4)
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/[email protected]:5068) State ROUTING
2021-10-28 10:44:19.693596 [DEBUG] mod_sofia.c:154 sofia/internal/[email protected]:5068 SOFIA ROUTING
2021-10-28 10:44:19.693596 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/[email protected]:5068) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/[email protected]:5068) State ROUTING going to sleep
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 4)
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/[email protected]:5068) State CONSUME_MEDIA
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/[email protected]:5068) State CONSUME_MEDIA going to sleep
2021-10-28 10:44:19.693596 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [calling][0]
freeswitch@pbx>
freeswitch@pbx>
2021-10-28 10:44:19.833592 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [proceeding][180]
2021-10-28 10:44:19.833592 [NOTICE] sofia.c:7436 Ring-Ready sofia/internal/[email protected]:5068!
2021-10-28 10:44:19.833592 [DEBUG] switch_channel.c:3437 (sofia/internal/[email protected]:5068) Callstate Change DOWN -> RINGING
freeswitch@pbx>
freeswitch@pbx>
2021-10-28 10:44:19.973606 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected] entering state [ready][200]
2021-10-28 10:44:20.253590 [DEBUG] switch_rtp.c:7722 Correct audio ip/port confirmed.
freeswitch@pbx>
2021-10-28 10:44:22.173587 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/local/freeswitch/sounds/zhuanjiezhong.wav
2021-10-28 10:44:22.193590 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@8000hz 1 channels 20ms
2021-10-28 10:44:23.053590 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [completing][200]
2021-10-28 10:44:23.053590 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=5001 8004 8000 IN IP4 10.30.0.15
s=SIP Call
c=IN IP4 10.30.0.15
t=0 0
m=audio 5028 RTP/AVP 0 8 9 105
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:105 telephone-event/8000
a=fmtp:105 0-15
a=ptime:20
m=video 0 RTP/AVP 103 104

2021-10-28 10:44:23.073610 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [ready][200]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 105@8000
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:3837 Set Codec sofia/internal/[email protected]:5068 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2021-10-28 10:44:23.073610 [DEBUG] switch_core_codec.c:111 sofia/internal/[email protected]:5068 Original read codec set to PCMU:0
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5851 Set telephone-event payload to 105@8000
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:5909 sofia/internal/[email protected]:5068 Set 2833 dtmf send payload to 105 recv payload to 101
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:8661 AUDIO RTP [sofia/internal/[email protected]:5068] 10.75.6.77 port 24340 -> 10.30.0.15 port 5028 codec: 0 ms: 20
2021-10-28 10:44:23.073610 [DEBUG] switch_rtp.c:4413 Starting timer [soft] 160 bytes per 20ms
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:8975 sofia/internal/[email protected]:5068 Set 2833 dtmf send payload to 105
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:8982 sofia/internal/[email protected]:5068 Set 2833 dtmf receive payload to 101
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:9005 sofia/internal/[email protected]:5068 Set rtp dtmf delay to 40
2021-10-28 10:44:23.073610 [NOTICE] sofia.c:8503 Channel [sofia/internal/[email protected]:5068] has been answered
2021-10-28 10:44:23.073610 [DEBUG] switch_channel.c:3865 (sofia/internal/[email protected]:5068) Callstate Change RINGING -> ACTIVE
2021-10-28 10:44:23.073610 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/[email protected]:5068]
2021-10-28 10:44:23.073610 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/[email protected]:5068]
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_async.c:1351 Record session sample rate: 8000 -> 8000
2021-10-28 10:44:23.093582 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/internal/[email protected]
2021-10-28 10:44:23.093582 [DEBUG] mod_callcenter.c:1965 Agent 5001 answered "xxx" <8001> from queue 90 (Recorded)
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:2213 (sofia/internal/[email protected]) State Change CS_EXECUTE -> CS_HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:2215 (sofia/internal/[email protected]:5068) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_HIBERNATE (Cur 2 Tot 4)
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:666 (sofia/internal/[email protected]:5068) State HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] mod_sofia.c:191 sofia/internal/[email protected]:5068 SOFIA HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:1144 (sofia/internal/[email protected]:5068) State Change CS_HIBERNATE -> CS_RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:666 (sofia/internal/[email protected]:5068) State HIBERNATE going to sleep
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_RESET (Cur 2 Tot 4)
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:647 (sofia/internal/[email protected]:5068) State RESET
2021-10-28 10:44:23.093582 [DEBUG] mod_sofia.c:172 sofia/internal/[email protected]:5068 SOFIA RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:1129 sofia/internal/[email protected]:5068 CUSTOM RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:188 sofia/internal/[email protected]:5068 Standard RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:647 (sofia/internal/[email protected]:5068) State RESET going to sleep
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/local/freeswitch/sounds/zhuanjiezhong.wav
2021-10-28 10:44:23.093582 [DEBUG] mod_callcenter.c:3283 Member xxx <8001> is answered by an agent in queue 90
2021-10-28 10:44:23.113588 [DEBUG] mod_callcenter.c:3375 Queue has 0 waiting calls.
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/[email protected]) State EXECUTE going to sleep
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_HIBERNATE (Cur 2 Tot 4)
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:666 (sofia/internal/[email protected]) State HIBERNATE
2021-10-28 10:44:23.113588 [DEBUG] mod_sofia.c:191 sofia/internal/[email protected] SOFIA HIBERNATE
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1144 (sofia/internal/[email protected]) State Change CS_HIBERNATE -> CS_RESET
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:666 (sofia/internal/[email protected]) State HIBERNATE going to sleep
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_RESET (Cur 2 Tot 4)
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:647 (sofia/internal/[email protected]) State RESET
2021-10-28 10:44:23.113588 [DEBUG] mod_sofia.c:172 sofia/internal/[email protected] SOFIA RESET
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1129 sofia/internal/[email protected] CUSTOM RESET
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1136 (sofia/internal/[email protected]) State Change CS_RESET -> CS_SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:647 (sofia/internal/[email protected]) State RESET going to sleep
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 4)
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:657 (sofia/internal/[email protected]) State SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] mod_sofia.c:662 SOFIA SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1154 sofia/internal/[email protected] CUSTOM SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1186 (sofia/internal/[email protected]:5068) State Change CS_RESET -> CS_SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 4)
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:657 (sofia/internal/[email protected]:5068) State SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] mod_sofia.c:662 SOFIA SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1154 sofia/internal/[email protected]:5068 CUSTOM SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:401 sofia/internal/[email protected]:5068 Standard SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:657 (sofia/internal/[email protected]:5068) State SOFT_EXECUTE going to sleep
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_bridge.c:1683 (sofia/internal/[email protected]:5068) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
2021-10-28 10:44:23.133586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 4)
2021-10-28 10:44:23.133586 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/[email protected]:5068) State CONSUME_MEDIA
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_bridge.c:1058 sofia/internal/[email protected]:5068 CUSTOM HOLD
2021-10-28 10:44:23.133586 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/[email protected]:5068) State CONSUME_MEDIA going to sleep
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_bridge.c:1793 (sofia/internal/[email protected]:5068) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2021-10-28 10:44:23.133586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/[email protected]:5068) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 4)
2021-10-28 10:44:23.133586 [DEBUG] switch_core_state_machine.c:654 (sofia/internal/[email protected]:5068) State EXCHANGE_MEDIA
2021-10-28 10:44:23.133586 [DEBUG] mod_sofia.c:656 SOFIA EXCHANGE_MEDIA
2021-10-28 10:44:23.133586 [DEBUG] mod_callcenter.c:2009 Member "xxx" 8001 is bridged to agent 5001
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_async.c:1640 No silence detection configured; assuming start of speech
2021-10-28 10:44:23.153585 [DEBUG] mod_callcenter.c:1301 Updated tier: Agent 5001 in Queue 90 set state = Active Inbound
2021-10-28 10:44:23.153585 [DEBUG] mod_callcenter.c:1180 Updated Agent 5001 set state = In a queue call
2021-10-28 10:44:23.153585 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2021-10-28 10:44:23.293594 [DEBUG] switch_rtp.c:7722 Correct audio ip/port confirmed.
freeswitch@pbx>
freeswitch@pbx>
freeswitch@pbx>
freeswitch@pbx>
freeswitch@pbx>
2021-10-28 10:45:20.773590 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [calling][0]
2021-10-28 10:45:20.813595 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [completing][200]
2021-10-28 10:45:20.813595 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=5001 8004 8001 IN IP4 10.30.0.15
s=SIP Call
c=IN IP4 10.30.0.15
t=0 0
m=audio 5028 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
m=video 0 RTP/AVP 103

2021-10-28 10:45:20.833591 [DEBUG] sofia.c:7325 Channel sofia/internal/[email protected]:5068 entering state [ready][200]
2021-10-28 10:45:26.813594 [DEBUG] switch_rtp.c:7967 RTP RECV DTMF *:1280
2021-10-28 10:45:26.813594 [INFO] switch_channel.c:522 RECV DTMF *:1280
2021-10-28 10:45:27.233594 [DEBUG] switch_rtp.c:7967 RTP RECV DTMF 7:1280
2021-10-28 10:45:27.233594 [INFO] switch_channel.c:522 RECV DTMF 7:1280
2021-10-28 10:45:27.233594 [DEBUG] switch_ivr_async.c:4311 sofia/internal/[email protected] Processing meta digit '7' [execute_extension::att_xfer XML features]
2021-10-28 10:45:27.533627 [DEBUG] switch_ivr.c:632 sofia/internal/[email protected] Command Execute [depth=0] playback(local_stream://moh)
EXECUTE [depth=0] sofia/internal/[email protected] playback(local_stream://moh)
2021-10-28 10:45:27.533627 [DEBUG] switch_ivr.c:632 sofia/internal/[email protected]:5068 Command Execute [depth=0] execute_extension(att_xfer XML features)
EXECUTE [depth=0] sofia/internal/[email protected]:5068 execute_extension(att_xfer XML features)

But I can capture the dtmf packet from my telephone. It's so weird to me. Can somebody tell me why?


Solution

  • I know how to fix it now. It's cause by freeswitch set 2833 dtmf send payload to 105 recv payload to 101, but the telephone still send 105 dtmf payload type to freeswitch. I modified 'rfc2833-pt' in sip_profiles/internal.xml to '105' and it worked for me.