[SOLVED] 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/8001@10.75.6.77 [f3285184-3798-11ec-a026-fd0671809b3f]
2021-10-28 10:44:19.553594 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) Running State Change CS_NEW (Cur 1 Tot 3)
2021-10-28 10:44:19.553594 [DEBUG] sofia.c:10279 sofia/internal/8001@10.75.6.77 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/8001@10.75.6.77) 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/8001@10.75.6.77 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/8001@10.75.6.77 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/8001@10.75.6.77) State Change CS_NEW -> CS_INIT
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) 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/8001@10.75.6.77) State INIT
2021-10-28 10:44:19.633586 [DEBUG] mod_sofia.c:93 sofia/internal/8001@10.75.6.77 SOFIA INIT
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:40 sofia/internal/8001@10.75.6.77 Standard INIT
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/8001@10.75.6.77) State Change CS_INIT -> CS_ROUTING
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/8001@10.75.6.77) State INIT going to sleep
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) Running State Change CS_ROUTING (Cur 1 Tot 3)
2021-10-28 10:44:19.633586 [DEBUG] switch_channel.c:2332 (sofia/internal/8001@10.75.6.77) Callstate Change DOWN -> RINGING
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/8001@10.75.6.77) State ROUTING
2021-10-28 10:44:19.633586 [DEBUG] mod_sofia.c:154 sofia/internal/8001@10.75.6.77 SOFIA ROUTING
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8001@10.75.6.77 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/8001@10.75.6.77 parsing [default->Queue90] continue=false
Dialplan: sofia/internal/8001@10.75.6.77 Regex (PASS) [Queue90] destination_number(90) =~ /^90$/ break=on-false
Dialplan: sofia/internal/8001@10.75.6.77 Action bind_meta_app(7 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/8001@10.75.6.77 Action callcenter(90)
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/8001@10.75.6.77) State Change CS_ROUTING -> CS_EXECUTE
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/8001@10.75.6.77) State ROUTING going to sleep
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) 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/8001@10.75.6.77) State EXECUTE
2021-10-28 10:44:19.633586 [DEBUG] mod_sofia.c:209 sofia/internal/8001@10.75.6.77 SOFIA EXECUTE
2021-10-28 10:44:19.633586 [DEBUG] switch_core_state_machine.c:329 sofia/internal/8001@10.75.6.77 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/8001@10.75.6.77 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/8001@10.75.6.77
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/8001@10.75.6.77 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/8001@10.75.6.77 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/8001@10.75.6.77 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/8001@10.75.6.77] 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/8001@10.75.6.77 Set 2833 dtmf send payload to 101
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8982 sofia/internal/8001@10.75.6.77 Set 2833 dtmf receive payload to 101
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:9005 sofia/internal/8001@10.75.6.77 Set rtp dtmf delay to 40
2021-10-28 10:44:19.653601 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/8001@10.75.6.77!
2021-10-28 10:44:19.653601 [DEBUG] switch_channel.c:3565 (sofia/internal/8001@10.75.6.77) Callstate Change RINGING -> EARLY
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8643 Audio params are unchanged for sofia/internal/8001@10.75.6.77.
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/8001@10.75.6.77 callcenter(90)
2021-10-28 10:44:19.653601 [DEBUG] sofia.c:7325 Channel sofia/internal/8001@10.75.6.77 entering state [early][183]
2021-10-28 10:44:19.653601 [DEBUG] switch_core_media.c:8643 Audio params are unchanged for sofia/internal/8001@10.75.6.77.
2021-10-28 10:44:19.653601 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/8001@10.75.6.77:
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/8001@10.75.6.77] has been answered
2021-10-28 10:44:19.653601 [DEBUG] switch_channel.c:3865 (sofia/internal/8001@10.75.6.77) Callstate Change EARLY -> ACTIVE
2021-10-28 10:44:19.653601 [DEBUG] sofia.c:7325 Channel sofia/internal/8001@10.75.6.77 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/5001@10.30.0.15:5068 [f33da75a-3798-11ec-a02f-fd0671809b3f]
2021-10-28 10:44:19.693596 [DEBUG] mod_sofia.c:5089 (sofia/internal/5001@10.30.0.15:5068) State Change CS_NEW -> CS_INIT
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15:5068) State INIT
2021-10-28 10:44:19.693596 [DEBUG] mod_sofia.c:93 sofia/internal/5001@10.30.0.15:5068 SOFIA INIT
2021-10-28 10:44:19.693596 [DEBUG] sofia_glue.c:1587 sip:5001@10.30.0.15:5068 Setting proxy route to sofia/internal/5001@10.30.0.15:5068
2021-10-28 10:44:19.693596 [DEBUG] sofia_glue.c:1618 sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15:5068 Standard INIT
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/5001@10.30.0.15:5068) State Change CS_INIT -> CS_ROUTING
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/5001@10.30.0.15:5068) State INIT going to sleep
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15:5068) State ROUTING
2021-10-28 10:44:19.693596 [DEBUG] mod_sofia.c:154 sofia/internal/5001@10.30.0.15:5068 SOFIA ROUTING
2021-10-28 10:44:19.693596 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/5001@10.30.0.15:5068) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/5001@10.30.0.15:5068) State ROUTING going to sleep
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15:5068) State CONSUME_MEDIA
2021-10-28 10:44:19.693596 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/5001@10.30.0.15:5068) State CONSUME_MEDIA going to sleep
2021-10-28 10:44:19.693596 [DEBUG] sofia.c:7325 Channel sofia/internal/5001@10.30.0.15:5068 entering state [calling][0]
freeswitch@pbx>
freeswitch@pbx>
2021-10-28 10:44:19.833592 [DEBUG] sofia.c:7325 Channel sofia/internal/5001@10.30.0.15:5068 entering state [proceeding][180]
2021-10-28 10:44:19.833592 [NOTICE] sofia.c:7436 Ring-Ready sofia/internal/5001@10.30.0.15:5068!
2021-10-28 10:44:19.833592 [DEBUG] switch_channel.c:3437 (sofia/internal/5001@10.30.0.15:5068) Callstate Change DOWN -> RINGING
freeswitch@pbx>
freeswitch@pbx>
2021-10-28 10:44:19.973606 [DEBUG] sofia.c:7325 Channel sofia/internal/8001@10.75.6.77 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/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15:5068 Set 2833 dtmf send payload to 105
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:8982 sofia/internal/5001@10.30.0.15:5068 Set 2833 dtmf receive payload to 101
2021-10-28 10:44:23.073610 [DEBUG] switch_core_media.c:9005 sofia/internal/5001@10.30.0.15:5068 Set rtp dtmf delay to 40
2021-10-28 10:44:23.073610 [NOTICE] sofia.c:8503 Channel [sofia/internal/5001@10.30.0.15:5068] has been answered
2021-10-28 10:44:23.073610 [DEBUG] switch_channel.c:3865 (sofia/internal/5001@10.30.0.15:5068) Callstate Change RINGING -> ACTIVE
2021-10-28 10:44:23.073610 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/5001@10.30.0.15:5068]
2021-10-28 10:44:23.073610 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/5001@10.30.0.15: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/8001@10.75.6.77
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/8001@10.75.6.77) State Change CS_EXECUTE -> CS_HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:2215 (sofia/internal/5001@10.30.0.15:5068) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15:5068) State HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] mod_sofia.c:191 sofia/internal/5001@10.30.0.15:5068 SOFIA HIBERNATE
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:1144 (sofia/internal/5001@10.30.0.15:5068) State Change CS_HIBERNATE -> CS_RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:666 (sofia/internal/5001@10.30.0.15:5068) State HIBERNATE going to sleep
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15:5068) State RESET
2021-10-28 10:44:23.093582 [DEBUG] mod_sofia.c:172 sofia/internal/5001@10.30.0.15:5068 SOFIA RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_ivr_bridge.c:1129 sofia/internal/5001@10.30.0.15:5068 CUSTOM RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:188 sofia/internal/5001@10.30.0.15:5068 Standard RESET
2021-10-28 10:44:23.093582 [DEBUG] switch_core_state_machine.c:647 (sofia/internal/5001@10.30.0.15: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/8001@10.75.6.77) State EXECUTE going to sleep
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) 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/8001@10.75.6.77) State HIBERNATE
2021-10-28 10:44:23.113588 [DEBUG] mod_sofia.c:191 sofia/internal/8001@10.75.6.77 SOFIA HIBERNATE
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1144 (sofia/internal/8001@10.75.6.77) State Change CS_HIBERNATE -> CS_RESET
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:666 (sofia/internal/8001@10.75.6.77) State HIBERNATE going to sleep
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) 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/8001@10.75.6.77) State RESET
2021-10-28 10:44:23.113588 [DEBUG] mod_sofia.c:172 sofia/internal/8001@10.75.6.77 SOFIA RESET
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1129 sofia/internal/8001@10.75.6.77 CUSTOM RESET
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1136 (sofia/internal/8001@10.75.6.77) State Change CS_RESET -> CS_SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:647 (sofia/internal/8001@10.75.6.77) State RESET going to sleep
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8001@10.75.6.77) 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/8001@10.75.6.77) 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/8001@10.75.6.77 CUSTOM SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_ivr_bridge.c:1186 (sofia/internal/5001@10.30.0.15:5068) State Change CS_RESET -> CS_SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15:5068 CUSTOM SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:401 sofia/internal/5001@10.30.0.15:5068 Standard SOFT_EXECUTE
2021-10-28 10:44:23.113588 [DEBUG] switch_core_state_machine.c:657 (sofia/internal/5001@10.30.0.15:5068) State SOFT_EXECUTE going to sleep
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_bridge.c:1683 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15:5068) State CONSUME_MEDIA
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_bridge.c:1058 sofia/internal/5001@10.30.0.15:5068 CUSTOM HOLD
2021-10-28 10:44:23.133586 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/5001@10.30.0.15:5068) State CONSUME_MEDIA going to sleep
2021-10-28 10:44:23.133586 [DEBUG] switch_ivr_bridge.c:1793 (sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15: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/5001@10.30.0.15:5068 entering state [calling][0]
2021-10-28 10:45:20.813595 [DEBUG] sofia.c:7325 Channel sofia/internal/5001@10.30.0.15: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/5001@10.30.0.15: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/8001@10.75.6.77 Processing meta digit '7' [execute_extension::att_xfer XML features]
2021-10-28 10:45:27.533627 [DEBUG] switch_ivr.c:632 sofia/internal/8001@10.75.6.77 Command Execute [depth=0] playback(local_stream://moh)
EXECUTE [depth=0] sofia/internal/8001@10.75.6.77 playback(local_stream://moh)
2021-10-28 10:45:27.533627 [DEBUG] switch_ivr.c:632 sofia/internal/5001@10.30.0.15:5068 Command Execute [depth=0] execute_extension(att_xfer XML features)
EXECUTE [depth=0] sofia/internal/5001@10.30.0.15: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?