Pastebin this info and select "FreeSWITCH Log" as the syntax highlighting. I need the colorized output to read logs. (I'm getting older and it's hard for me to ready black and white in an email.)
-MCOn Fri, May 13, 2011 at 7:32 AM, Leonardo P. Bidinoto <leonardo.bidinoto@voicetechnology.com.br> wrote:
Hi Michael,
Just succeeded to reproduce the problem.
The condition is: when a channel inside a conference is using a ESL connection(lets call it "A") through socket application and another ESL connection(lets call it "B") executes a command with this channel, the "B" ESL connection will wait the "A" ESL connection close to execute its command.
If the channel hangs up before the "A" ESL connection is closed, then "B" ESL command will never be executed and the stucked channel will still be there, into sofia and the conference too.
To verify that, just do "show channels" and "conference list". with "uuid_exists" command, return "false".
Here are the actions done by the channel before get stucked:
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.187321 [NOTICE] switch_channel.c:816 New Channel sofia/external/1000123402@192.168.0.154 [16e09413-9cb0-4011-a635-f91933a35c0f]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia.c:4761 Channel sofia/external/1000123402@192.168.0.154 entering state [received][100]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia.c:4772 Remote SDP:
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia_glue.c:4656 Audio Codec Compare [BV32:107:16000:20:0]/[PCMU:0:8000:20:64000]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia_glue.c:4656 Audio Codec Compare [BV32:107:16000:20:0]/[PCMA:8:8000:20:64000]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia_glue.c:4656 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia_glue.c:2788 Set Codec sofia/external/1000123402@192.168.0.154 PCMU/8000 20 ms 160 samples 64000 bits
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia_glue.c:4770 Set 2833 dtmf send/recv payload to 101
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] sofia.c:4943 (sofia/external/1000123402@192.168.0.154) State Change CS_NEW -> CS_INIT
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_session.c:1114 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_state_machine.c:325 (sofia/external/1000123402@192.168.0.154) Running State Change CS_INIT
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_state_machine.c:361 (sofia/external/1000123402@192.168.0.154) State INIT
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] mod_sofia.c:84 sofia/external/1000123402@192.168.0.154 SOFIA INIT
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] mod_sofia.c:124 (sofia/external/1000123402@192.168.0.154) State Change CS_INIT -> CS_ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_session.c:1114 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_state_machine.c:361 (sofia/external/1000123402@192.168.0.154) State INIT going to sleep
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_state_machine.c:325 (sofia/external/1000123402@192.168.0.154) Running State Change CS_ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_channel.c:1665 (sofia/external/1000123402@192.168.0.154) Callstate Change DOWN -> RINGING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_state_machine.c:364 (sofia/external/1000123402@192.168.0.154) State ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] mod_sofia.c:147 sofia/external/1000123402@192.168.0.154 SOFIA ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [DEBUG] switch_core_state_machine.c:77 sofia/external/1000123402@192.168.0.154 Standard ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.188323 [INFO] mod_dialplan_xml.c:331 Processing Phone1 <1000123402>->1234567890 in context public
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 parsing [public->unloop] continue=false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 parsing [public->public_extensions] continue=false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Regex (PASS) [public_extensions] destination_number(1234567890) =~ /^(\d*)$/ break=on-false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Action transfer(1234567890 XML default)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.190328 [DEBUG] switch_core_state_machine.c:119 (sofia/external/1000123402@192.168.0.154) State Change CS_ROUTING -> CS_EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.190328 [DEBUG] switch_core_session.c:1114 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.190328 [DEBUG] switch_core_state_machine.c:364 (sofia/external/1000123402@192.168.0.154) State ROUTING going to sleep
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.190328 [DEBUG] switch_core_state_machine.c:325 (sofia/external/1000123402@192.168.0.154) Running State Change CS_EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.190328 [DEBUG] switch_core_state_machine.c:371 (sofia/external/1000123402@192.168.0.154) State EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.190328 [DEBUG] mod_sofia.c:240 sofia/external/1000123402@192.168.0.154 SOFIA EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_state_machine.c:157 sofia/external/1000123402@192.168.0.154 Standard EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 transfer(1234567890 XML default)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_ivr.c:1597 (sofia/external/1000123402@192.168.0.154) State Change CS_EXECUTE -> CS_ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_session.c:1114 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_session.c:707 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [NOTICE] switch_ivr.c:1603 Transfer sofia/external/1000123402@192.168.0.154 to XML[1234567890@default]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_state_machine.c:371 (sofia/external/1000123402@192.168.0.154) State EXECUTE going to sleep
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_state_machine.c:325 (sofia/external/1000123402@192.168.0.154) Running State Change CS_ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_state_machine.c:364 (sofia/external/1000123402@192.168.0.154) State ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] mod_sofia.c:147 sofia/external/1000123402@192.168.0.154 SOFIA ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [DEBUG] switch_core_state_machine.c:77 sofia/external/1000123402@192.168.0.154 Standard ROUTING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.191327 [INFO] mod_dialplan_xml.c:331 Processing Phone1 <1000123402>->1234567890 in context default
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 parsing [default->flex] continue=false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Regex (PASS) [flex] destination_number(1234567890) =~ /^(\d+)$/ break=on-false
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Action log(INFO VOICE received dest=1234567890)
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Action set(playback_terminators=#)
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Action log(INFO Let's do some ivrd, shall we?)
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Action set(ivr_path=/usr/local/ipconf/fs/daemon/ivr.rb)
16e09413-9cb0-4011-a635-f91933a35c0f Dialplan: sofia/external/1000123402@192.168.0.154 Action socket(localhost:8084 full)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] switch_core_state_machine.c:119 (sofia/external/1000123402@192.168.0.154) State Change CS_ROUTING -> CS_EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] switch_core_session.c:1114 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] switch_core_state_machine.c:364 (sofia/external/1000123402@192.168.0.154) State ROUTING going to sleep
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] switch_core_state_machine.c:325 (sofia/external/1000123402@192.168.0.154) Running State Change CS_EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] switch_core_state_machine.c:371 (sofia/external/1000123402@192.168.0.154) State EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] mod_sofia.c:240 sofia/external/1000123402@192.168.0.154 SOFIA EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [DEBUG] switch_core_state_machine.c:157 sofia/external/1000123402@192.168.0.154 Standard EXECUTE
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 log(INFO VOICE received dest=1234567890)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.193325 [INFO] mod_dptools.c:1184 VOICE received dest=1234567890
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(playback_terminators=#)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.194331 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [playback_terminators]=[#]
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 log(INFO Let's do some ivrd, shall we?)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.194331 [INFO] mod_dptools.c:1184 Let's do some ivrd, shall we?
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(ivr_path=/usr/local/ipconf/fs/daemon/ivr.rb)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.194331 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [ivr_path]=[/usr/local/ipconf/fs/daemon/ivr.rb]
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 socket(localhost:8084 full)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.930309 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute answer()
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 answer()
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.930309 [DEBUG] sofia_glue.c:3022 AUDIO RTP [sofia/external/1000123402@192.168.0.154] 192.168.0.154 port 24232 -> 192.168.0.111 port 4046 codec: 0 ms: 20
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.930309 [DEBUG] switch_rtp.c:1623 Starting timer [soft] 160 bytes per 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.932313 [DEBUG] sofia_glue.c:3284 Set 2833 dtmf send payload to 101
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.932313 [DEBUG] sofia_glue.c:3289 Set 2833 dtmf receive payload to 101
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.932313 [DEBUG] mod_sofia.c:681 Local SDP sofia/external/1000123402@192.168.0.154:
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.932313 [DEBUG] switch_core_session.c:707 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.932313 [DEBUG] switch_channel.c:2827 (sofia/external/1000123402@192.168.0.154) Callstate Change RINGING -> ACTIVE
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.932313 [NOTICE] mod_dptools.c:930 Channel [sofia/external/1000123402@192.168.0.154] has been answered
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:47.933312 [DEBUG] sofia.c:4761 Channel sofia/external/1000123402@192.168.0.154 entering state [completed][200]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:48.040285 [DEBUG] sofia.c:4761 Channel sofia/external/1000123402@192.168.0.154 entering state [ready][200]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:48.082294 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute playback(/usr/local/freeswitch/sounds/flex/app32/teste/WelcomeToTheConferenceSystem.wav)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 playback(/usr/local/freeswitch/sounds/flex/app32/teste/WelcomeToTheConferenceSystem.wav)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:48.082294 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:48.114277 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:48.155281 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/Mainmenu.wav flex_digits 5000 )
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/Mainmenu.wav flex_digits 5000 )
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:51:48.155281 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:00.893670 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 1:1120
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:00.893670 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:00.897674 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:00.897674 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [flex_digits]=[UNDEF]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:00.940673 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/PleaseEnterYourPassCodeNow.wav flex_digits 5000 )
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/PleaseEnterYourPassCodeNow.wav flex_digits 5000 )
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:00.940673 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.113662 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 8:640
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.113662 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.116663 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.116663 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [flex_digits]=[UNDEF]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.117663 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute read(1 11 /usr/local/freeswitch/sounds/flex/app32/teste/Silence.wav flex_digits 5000 #,*)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 read(1 11 /usr/local/freeswitch/sounds/flex/app32/teste/Silence.wav flex_digits 5000 #,*)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.117663 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:01.153658 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.053615 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF #:960
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.055618 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.055618 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [flex_digits]=[UNDEF]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.146613 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute playback(/usr/local/freeswitch/sounds/flex/app32/teste/InternalHelp.wav)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 playback(/usr/local/freeswitch/sounds/flex/app32/teste/InternalHelp.wav)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.146613 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.333603 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF #:800
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.333603 [DEBUG] mod_dptools.c:1664 Digit #
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.333603 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.350617 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute playback(/usr/local/freeswitch/sounds/flex/app32/teste/YouAreTheOnlyPersonOnThisConference.wav)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 playback(/usr/local/freeswitch/sounds/flex/app32/teste/YouAreTheOnlyPersonOnThisConference.wav)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:02.350617 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:04.253520 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:04.322510 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute conference(15646@teste+flags{waste})
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 conference(15646@teste+flags{waste})
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:04.813492 [DEBUG] mod_conference.c:5582 Raw Codec Activation Success L16@8000hz 1 channel 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:04.813492 [DEBUG] mod_conference.c:5627 Raw Codec Activation Success L16@8000hz 1 channel 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:04.813492 [DEBUG] switch_core_codec.c:116 sofia/external/1000123402@192.168.0.154 Push codec L16:70
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:05.280469 [DEBUG] switch_core_session.c:707 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:05.280469 [DEBUG] mod_conference.c:2557 Setup timer soft success interval: 20 samples: 160
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:16.573928 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF *:960
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:16.593929 [DEBUG] mod_conference.c:2021 Execute app: socket, localhost:8085 sync full
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:16.593929 [DEBUG] switch_core_codec.c:141 sofia/external/1000123402@192.168.0.154 Restore previous codec PCMU:0.
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 socket(localhost:8085 sync full)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.097927 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/Silence.wav flex_digits 2000 )
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/Silence.wav flex_digits 2000 )
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.097927 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.133923 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.373913 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 1:1120
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.375912 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.375912 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [flex_digits]=[UNDEF]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.490911 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute playback(/usr/local/freeswitch/sounds/flex/app32/teste/SelfMuteOn.wav)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 playback(/usr/local/freeswitch/sounds/flex/app32/teste/SelfMuteOn.wav)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:17.490911 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:19.233824 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:19.235828 [DEBUG] switch_cpp.cpp:988 sofia/external/1000123402@192.168.0.154 destroy/unlink session from object
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:19.235828 [DEBUG] switch_core_codec.c:116 sofia/external/1000123402@192.168.0.154 Push codec L16:70
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:43.433668 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF *:800
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:43.453667 [DEBUG] mod_conference.c:2021 Execute app: socket, localhost:8085 sync full
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:43.453667 [DEBUG] switch_core_codec.c:141 sofia/external/1000123402@192.168.0.154 Restore previous codec PCMU:0.
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 socket(localhost:8085 sync full)
====================================================================================================================================================
While Inside this connection, a "conference 15646 kick [member_id of this channels]" command is executed by a fs_cli console and get stuck while waiting response.
====================================================================================================================================================
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:44.000850 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/Silence.wav flex_digits 2000 )
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 read(1 1 /usr/local/freeswitch/sounds/flex/app32/teste/Silence.wav flex_digits 2000 )
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:44.000850 [DEBUG] switch_ivr_play_say.c:1279 Codec Activated L16@8000hz 1 channels 20ms
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:44.033846 [DEBUG] switch_ivr_play_say.c:1649 done playing file
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:44.553821 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 1:960
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:44.555825 [DEBUG] switch_ivr.c:561 sofia/external/1000123402@192.168.0.154 Command Execute set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f EXECUTE sofia/external/1000123402@192.168.0.154 set(flex_digits)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:44.555825 [DEBUG] mod_dptools.c:1060 sofia/external/1000123402@192.168.0.154 SET [flex_digits]=[UNDEF]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.674244 [DEBUG] switch_channel.c:2560 (sofia/external/1000123402@192.168.0.154) Callstate Change ACTIVE -> HANGUP
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.674244 [NOTICE] sofia.c:538 Hangup sofia/external/1000123402@192.168.0.154 [CS_EXECUTE] [NORMAL_CLEARING]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.674244 [DEBUG] switch_channel.c:2576 Send signal sofia/external/1000123402@192.168.0.154 [KILL]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.674244 [DEBUG] switch_core_session.c:1114 Send signal sofia/external/1000123402@192.168.0.154 [BREAK]
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.675246 [DEBUG] switch_core_session.c:2057 sofia/external/1000123402@192.168.0.154 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.675246 [DEBUG] switch_cpp.cpp:988 sofia/external/1000123402@192.168.0.154 destroy/unlink session from object
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.675246 [DEBUG] switch_core_session.c:2057 sofia/external/1000123402@192.168.0.154 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.675246 [DEBUG] switch_core_codec.c:116 sofia/external/1000123402@192.168.0.154 Push codec L16:70
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.675246 [DEBUG] mod_conference.c:2815 Channel leaving conference, cause: NORMAL_CLEARING
16e09413-9cb0-4011-a635-f91933a35c0f 2011-05-13 10:52:56.757239 [DEBUG] mod_conference.c:6104 sofia/external/1000123402@192.168.0.154 skip receive message [UNBRIDGE] (channel is hungup already)
I hope this info helps.2011/5/12 Michael Collins <msc@freeswitch.org>
_______________________________________________On Thu, May 12, 2011 at 12:27 PM, Leonardo P. Bidinoto <leonardo.bidinoto@voicetechnology.com.br> wrote:
Hi Michael,
Im not using to any cdr module.I would recommend that you do several things:#1 - update to latest git#2 - rotate logs#3 - enable uuid logging (see logfile.conf.xml - param name "uuid")#4 - reproduce the symptom with a single call (if possible)#5 - pastebin the log for the uuid in question and link to it in this thread
From there hopefully we'll get a clue as to what is happening.-MC
FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
--
Leonardo Pires Bidinoto
Voice Technology
www.voicetechnology.com.br
_______________________________________________
FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
_______________________________________________
FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org