[Freeswitch-dev] tone_detect

Mon Sep 8 16:15:38 EDT 2008

Hi Brian,

> Have you looked at these examples:
> http://wiki.freeswitch.org/wiki/Misc._Dialplan_Tools_tone_detect

Actually I based my dialplan on that specific example.

> Can you provide a console log with debug output would help see what is
> going on.

Here is an example, it happens the same no matter if I record or not the
session.  I know that the audio is interrupted because I'm tapping the
analog channel of the fax machine and hearing what happens.

The interruption of the audio comes almost as the same time as the line:
2008-09-08 14:27:35 [DEBUG] switch_core_io.c:365
switch_core_session_read_frame() Engaging Read Buffer at 320 bytes vs 1

-------------------------

2008-09-08 14:27:24 [DEBUG] switch_ivr_originate.c:664
switch_ivr_originate() variable string 0 = [ignore_early_media=true]
2008-09-08 14:27:24 [NOTICE] switch_channel.c:538 switch_channel_set_name()
New Channel sofia/auronix/116 at 192.168.1.16
[e19ba58a-95ba-fd49-972a-30824b45daf6]
2008-09-08 14:27:24 [DEBUG] mod_sofia.c:2020 sofia_outgoing_channel()
sofia/auronix/116 at 192.168.1.16 State Change CS_NEW -> CS_INIT
2008-09-08 14:27:24 [DEBUG] switch_core_session.c:727
switch_core_session_signal_state_change() Kill
sofia/auronix/116 at 192.168.1.16 [BREAK]
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:365
switch_core_session_run() sofia/auronix/116 at 192.168.1.16 Running State
Change CS_INIT
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:415
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State INIT
2008-09-08 14:27:24 [DEBUG] mod_sofia.c:80 sofia_on_init()
sofia/auronix/116 at 192.168.1.16 SOFIA INIT
2008-09-08 14:27:24 [DEBUG] mod_sofia.c:107 sofia_on_init()
sofia/auronix/116 at 192.168.1.16 State Change CS_INIT -> CS_ROUTING
2008-09-08 14:27:24 [DEBUG] switch_core_session.c:727
switch_core_session_signal_state_change() Kill
sofia/auronix/116 at 192.168.1.16 [BREAK]
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:415
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State INIT going
to sleep
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:365
switch_core_session_run() sofia/auronix/116 at 192.168.1.16 Running State
Change CS_ROUTING
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:420
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State ROUTING
2008-09-08 14:27:24 [DEBUG] mod_sofia.c:119 sofia_on_routing()
sofia/auronix/116 at 192.168.1.16 SOFIA ROUTING
2008-09-08 14:27:24 [DEBUG] switch_ivr_originate.c:57 originate_on_routing()
sofia/auronix/116 at 192.168.1.16 State Change CS_ROUTING -> CS_CONSUME_MEDIA
2008-09-08 14:27:24 [DEBUG] switch_core_session.c:727
switch_core_session_signal_state_change() Kill
sofia/auronix/116 at 192.168.1.16 [BREAK]
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:420
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State ROUTING
going to sleep
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:365
switch_core_session_run() sofia/auronix/116 at 192.168.1.16 Running State
Change CS_CONSUME_MEDIA
2008-09-08 14:27:24 [DEBUG] switch_core_state_machine.c:442
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State
CONSUME_MEDIA
2008-09-08 14:27:24 [DEBUG] sofia.c:200 sofia_event_callback() event
[nua_i_state] status [0][INVITE sent] session:
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:27:24 [DEBUG] sofia.c:2159 sofia_handle_sip_i_state() Channel
sofia/auronix/116 at 192.168.1.16 entering state [calling]
2008-09-08 14:27:24 [DEBUG] sofia.c:200 sofia_event_callback() event
[nua_r_invite] status [183][Session Progress] session:
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:27:24 [DEBUG] sofia.c:200 sofia_event_callback() event
[nua_i_state] status [183][Session Progress] session:
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:27:24 [DEBUG] sofia.c:2159 sofia_handle_sip_i_state() Channel
sofia/auronix/116 at 192.168.1.16 entering state [proceeding]
2008-09-08 14:27:24 [DEBUG] sofia.c:2163 sofia_handle_sip_i_state() Remote
SDP:
v=0
o=AudiocodesGW 679202607 679202491 IN IP4 192.168.1.16
s=Phone-Call
c=IN IP4 192.168.1.16
t=0 0
m=audio 6000 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2008-09-08 14:27:24 [DEBUG] sofia_glue.c:2303 sofia_glue_negotiate_sdp()
Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000]
2008-09-08 14:27:24 [DEBUG] sofia_glue.c:1548 sofia_glue_tech_set_codec()
Set Codec sofia/auronix/116 at 192.168.1.16 PCMU/8000 20 ms 160 samples
2008-09-08 14:27:24 [DEBUG] sofia_glue.c:2266 sofia_glue_negotiate_sdp() Set
2833 dtmf payload to 101
2008-09-08 14:27:24 [DEBUG] sofia_glue.c:1757 sofia_glue_activate_rtp()
AUDIO RTP [sofia/auronix/116 at 192.168.1.16] 192.168.1.1 port 25268 ->
192.168.1.16 port 6000 codec: 0 ms: 20
2008-09-08 14:27:24 [DEBUG] switch_rtp.c:818 switch_rtp_create() Starting
timer [soft] 160 bytes per 20000ms
2008-09-08 14:27:24 [NOTICE] switch_channel.c:1413
switch_channel_perform_mark_pre_answered() Ring-Ready
sofia/auronix/116 at 192.168.1.16!
2008-09-08 14:27:24 [NOTICE] sofia_glue.c:2032 sofia_glue_tech_media()
Pre-Answer sofia/auronix/116 at 192.168.1.16!
2008-09-08 14:27:24 [DEBUG] sofia.c:332 sofia_event_callback() nua_r_prack:
unknown event 39: 200 OK
2008-09-08 14:27:27 [DEBUG] sofia.c:2159 sofia_handle_sip_i_state() Channel
sofia/auronix/116 at 192.168.1.16 entering state [ready]
2008-09-08 14:27:27 [DEBUG] switch_ivr_originate.c:1380
switch_ivr_originate() Originate Resulted in Success:
[sofia/auronix/116 at 192.168.1.16]
2008-09-08 14:27:27 [NOTICE] sofia.c:2474 sofia_handle_sip_i_state() Channel
[sofia/auronix/116 at 192.168.1.16] has been answered
2008-09-08 14:27:27 [DEBUG] switch_ivr.c:1092 switch_ivr_session_transfer()
sofia/auronix/116 at 192.168.1.16 State Change CS_CONSUME_MEDIA -> CS_ROUTING
2008-09-08 14:27:27 [DEBUG] switch_core_session.c:727
switch_core_session_signal_state_change() Kill
sofia/auronix/116 at 192.168.1.16 [BREAK]
2008-09-08 14:27:27 [DEBUG] switch_core_session.c:435
switch_core_session_receive_message() Kill sofia/auronix/116 at 192.168.1.16
[BREAK]
2008-09-08 14:27:27 [NOTICE] switch_ivr.c:1098 switch_ivr_session_transfer()
Transfer sofia/auronix/116 at 192.168.1.16 to XML[detecta_fax at default]
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:442
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State
CONSUME_MEDIA going to sleep
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:365
switch_core_session_run() sofia/auronix/116 at 192.168.1.16 Running State
Change CS_ROUTING
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:420
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State ROUTING
2008-09-08 14:27:27 [DEBUG] mod_sofia.c:119 sofia_on_routing()
sofia/auronix/116 at 192.168.1.16 SOFIA ROUTING
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:64
switch_core_standard_on_routing() Standard ROUTING
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:27:27 [INFO] mod_dialplan_xml.c:228 dialplan_hunt() Processing
FreeSWITCH->detecta_fax in context default
2008-09-08 14:27:27 [DEBUG] mod_dialplan_xml.c:113 parse_exten() test
conditions destination_number(detecta_fax) =~ /detecta_fax/
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:97
switch_core_standard_on_routing() sofia/auronix/116 at 192.168.1.16 State
Change CS_ROUTING -> CS_EXECUTE
2008-09-08 14:27:27 [DEBUG] switch_core_session.c:727
switch_core_session_signal_state_change() Kill
sofia/auronix/116 at 192.168.1.16 [BREAK]
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:420
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State ROUTING
going to sleep
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:365
switch_core_session_run() sofia/auronix/116 at 192.168.1.16 Running State
Change CS_EXECUTE
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:430
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State EXECUTE
2008-09-08 14:27:27 [DEBUG] mod_sofia.c:156 sofia_on_execute()
sofia/auronix/116 at 192.168.1.16 SOFIA EXECUTE
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:129
switch_core_standard_on_execute() Standard EXECUTE
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:140
switch_core_standard_on_execute() sofia/auronix/116 at 192.168.1.16 Execute
record_session(C:\\borrame\\sesion.wav)
2008-09-08 14:27:27 [DEBUG] switch_core_media_bug.c:227
switch_core_media_bug_add() Attaching BUG to sofia/auronix/116 at 192.168.1.16
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:140
switch_core_standard_on_execute() sofia/auronix/116 at 192.168.1.16 Execute
tone_detect(fax 1100 r +5000 transfer fax_detectado XML default)
2008-09-08 14:27:27 [NOTICE] mod_dptools.c:1228
tone_detect_session_function() Enabling tone detection 'fax' '1100'
2008-09-08 14:27:27 [DEBUG] switch_ivr_async.c:1271
switch_ivr_tone_detect_session() Adding tone spec 1100 index 0
2008-09-08 14:27:27 [DEBUG] switch_core_media_bug.c:227
switch_core_media_bug_add() Attaching BUG to sofia/auronix/116 at 192.168.1.16
2008-09-08 14:27:27 [DEBUG] switch_core_state_machine.c:140
switch_core_standard_on_execute() sofia/auronix/116 at 192.168.1.16 Execute
playback(C:\\Auronix\\OpenSource\\Freeswitch\\audios\\_retencionAgente.WAV)
2008-09-08 14:27:27 [DEBUG] switch_ivr_play_say.c:917 switch_ivr_play_file()
Codec Activated L16 at 8000hz 1 channels 20ms
2008-09-08 14:27:27 [DEBUG] switch_core_session.c:435
switch_core_session_receive_message() Kill sofia/auronix/116 at 192.168.1.16
[BREAK]
2008-09-08 14:27:35 [DEBUG] switch_core_io.c:365
switch_core_session_read_frame() Engaging Read Buffer at 320 bytes vs 1
2008-09-08 14:28:12 [DEBUG] sofia.c:2159 sofia_handle_sip_i_state() Channel
sofia/auronix/116 at 192.168.1.16 entering state [received]
2008-09-08 14:28:12 [DEBUG] sofia.c:2163 sofia_handle_sip_i_state() Remote
SDP:
v=0
o=AudiocodesGW 679202607 679202491 IN IP4 192.168.1.16
s=Phone-Call
c=IN IP4 192.168.1.16
t=0 0
m=audio 6000 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2008-09-08 14:28:12 [DEBUG] sofia_glue.c:2240 sofia_glue_negotiate_sdp() Our
existing sdp is still good [PCMU 192.168.1.16:6000], let's keep it.
2008-09-08 14:28:12 [DEBUG] sofia_glue.c:2266 sofia_glue_negotiate_sdp() Set
2833 dtmf payload to 101
2008-09-08 14:28:12 [DEBUG] sofia_glue.c:1751 sofia_glue_activate_rtp()
Audio params are unchanged.
2008-09-08 14:28:12 [DEBUG] sofia.c:2433 sofia_handle_sip_i_state()
Processing Reinvite
2008-09-08 14:28:12 [DEBUG] sofia.c:2159 sofia_handle_sip_i_state() Channel
sofia/auronix/116 at 192.168.1.16 entering state [completed]
2008-09-08 14:28:13 [DEBUG] sofia.c:2159 sofia_handle_sip_i_state() Channel
sofia/auronix/116 at 192.168.1.16 entering state [ready]
2008-09-08 14:28:56 [DEBUG] switch_ivr_play_say.c:1207
switch_ivr_play_file() done playing file
2008-09-08 14:28:56 [DEBUG] switch_core_state_machine.c:140
switch_core_standard_on_execute() sofia/auronix/116 at 192.168.1.16 Execute
hangup(NORMAL_CLEARING)
2008-09-08 14:28:56 [NOTICE] mod_dptools.c:593 hangup_function() Hangup
sofia/auronix/116 at 192.168.1.16 [CS_EXECUTE] [NORMAL_CLEARING]
2008-09-08 14:28:56 [DEBUG] switch_channel.c:1368
switch_channel_perform_hangup() Kill sofia/auronix/116 at 192.168.1.16 [KILL]
2008-09-08 14:28:56 [DEBUG] switch_core_session.c:727
switch_core_session_signal_state_change() Kill
sofia/auronix/116 at 192.168.1.16 [BREAK]
2008-09-08 14:28:56 [DEBUG] switch_core_state_machine.c:430
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State EXECUTE
going to sleep
2008-09-08 14:28:56 [DEBUG] switch_core_state_machine.c:365
switch_core_session_run() sofia/auronix/116 at 192.168.1.16 Running State
Change CS_HANGUP
2008-09-08 14:28:56 [DEBUG] switch_core_state_machine.c:393
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State HANGUP
2008-09-08 14:28:56 [DEBUG] mod_sofia.c:264 sofia_on_hangup() Channel
sofia/auronix/116 at 192.168.1.16 hanging up, cause: NORMAL_CLEARING
2008-09-08 14:28:56 [DEBUG] mod_sofia.c:321 sofia_on_hangup() Sending BYE to
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:28:56 [DEBUG] switch_core_state_machine.c:46
switch_core_standard_on_hangup() Standard HANGUP
sofia/auronix/116 at 192.168.1.16, cause: NORMAL_CLEARING
2008-09-08 14:28:56 [DEBUG] switch_core_state_machine.c:393
switch_core_session_run() (sofia/auronix/116 at 192.168.1.16) State HANGUP
going to sleep
2008-09-08 14:28:56 [DEBUG] switch_core_media_bug.c:284
switch_core_media_bug_remove_all() Removing BUG from
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:28:56 [DEBUG] switch_core_media_bug.c:284
switch_core_media_bug_remove_all() Removing BUG from
sofia/auronix/116 at 192.168.1.16
2008-09-08 14:28:56 [DEBUG] switch_core_session.c:794
switch_core_session_thread() Session 9 (sofia/auronix/116 at 192.168.1.16)
Locked, Waiting on external entities
2008-09-08 14:28:56 [NOTICE] switch_core_session.c:812
switch_core_session_thread() Session 9 (sofia/auronix/116 at 192.168.1.16)
Ended
2008-09-08 14:28:56 [NOTICE] switch_core_session.c:814
switch_core_session_thread() Close Channel sofia/auronix/116 at 192.168.1.16
[CS_HANGUP]

> Please do not hijack threads.  Click new message and input the list
> address yourself or from your address book.

Sorry about that, I thought that just by setting a new subject would be OK.
Won't happen again.

Cesar Cepeda.