I am FS beginner and I have a basic PBX setup using FS with the Siemens A580 IP Phones.  I thought everything was working fine since I could make and receive basic calls without any obvious issues.  However, recently I wanted to use more advanced functions in FS and discovered that I could not use any of DTMF based functions (e.g. call transfer/record) during calls with the Siemens IP phones.  The same functions work fine when I use a softphone.  So, I started looking at the log file and I think there is some problem between the Siemens IP phones and FS (log file attached below).  It seems that when a call comes in, FS calls the extensions and then the extensions send back confirmation and SIP status codes.  With softphone extensions, I see 180 (Ringing) and 200 (OK) as normal status.  However, with Siemens IP phone extensions, I see 480 (Temporarily Unavailable) which seems to cause FS to terminate the session.  So, FS log shows there is actually no active session which explains why it does not performs DTMF detection for the call session.  However, the call to Siemens IP phones actually continues with ringing when an extension handset answers the call is established with the caller with full voice communication.  I don't know how FS works but this seems very strange.  I would like to know how to get FS to work properly with Siemens IP phones including the DTMF functions during calls.  Any help would be appreciated.


----------------------------------------------
2009-11-14 09:35:43.942450 [NOTICE] switch_channel.c:602 New Channel sofia/internal/4155559999@192.168.1.254 [22f8ee00-d144-11de-a41f-e5a6b5425f55]
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/4155559999@192.168.1.254) Running State Change CS_NEW
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:404 (sofia/internal/4155559999@192.168.1.254) State NEW
2009-11-14 09:35:43.951943 [DEBUG] sofia.c:3289 Channel sofia/internal/4155559999@192.168.1.254 entering state [received][100]
2009-11-14 09:35:43.951943 [DEBUG] sofia.c:3296 Remote SDP:
v=0
o=- 119640485 119640485 IN IP4 192.168.1.97
s=-
c=IN IP4 192.168.1.97
t=0 0
m=audio 16430 RTP/AVP 0 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2009-11-14 09:35:43.951943 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[G7221:115:32000:20]
2009-11-14 09:35:43.951943 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[G7221:107:16000:20]
2009-11-14 09:35:43.951943 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[G722:9:8000:20]
2009-11-14 09:35:43.951943 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:20]/[PCMU:0:8000:20]
2009-11-14 09:35:43.951943 [DEBUG] sofia_glue.c:2029 Set Codec sofia/internal/4155559999@192.168.1.254 PCMU/8000 20 ms 160 samples
2009-11-14 09:35:43.951943 [DEBUG] sofia_glue.c:3031 Set 2833 dtmf payload to 101
2009-11-14 09:35:43.951943 [DEBUG] sofia.c:3455 (sofia/internal/4155559999@192.168.1.254) State Change CS_NEW -> CS_INIT
2009-11-14 09:35:43.951943 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/4155559999@192.168.1.254) Running State Change CS_INIT
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/4155559999@192.168.1.254) State INIT
2009-11-14 09:35:43.951943 [DEBUG] mod_sofia.c:83 sofia/internal/4155559999@192.168.1.254 SOFIA INIT
2009-11-14 09:35:43.951943 [DEBUG] mod_sofia.c:111 (sofia/internal/4155559999@192.168.1.254) State Change CS_INIT -> CS_ROUTING
2009-11-14 09:35:43.951943 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/4155559999@192.168.1.254) State INIT going to sleep
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/4155559999@192.168.1.254) Running State Change CS_ROUTING
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/4155559999@192.168.1.254) State ROUTING
2009-11-14 09:35:43.951943 [DEBUG] mod_sofia.c:130 sofia/internal/4155559999@192.168.1.254 SOFIA ROUTING
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:78 sofia/internal/4155559999@192.168.1.254 Standard ROUTING
2009-11-14 09:35:43.951943 [INFO] mod_dialplan_xml.c:315 Processing WIRELESS CALLER->4155553333 in context default
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->unloop] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [global-intercept] destination_number(4155553333) =~ /^886$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [group-intercept] destination_number(4155553333) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [intercept-ext] destination_number(4155553333) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->redial] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [redial] destination_number(4155553333) =~ /^870$|^\*66$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->global] continue=true
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/4155559999@192.168.1.254 Absolute Condition [global]
Dialplan: sofia/internal/4155559999@192.168.1.254 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/4155559999@192.168.1.254 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/4155559999@192.168.1.254 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [snom-demo-2] destination_number(4155553333) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [snom-demo-1] destination_number(4155553333) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [eavesdrop] destination_number(4155553333) =~ /^88(.*)$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [eavesdrop] destination_number(4155553333) =~ /^779$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->call_return] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [call_return] destination_number(4155553333) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->del-group] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [del-group] destination_number(4155553333) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->add-group] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [add-group] destination_number(4155553333) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [call-group-simo] destination_number(4155553333) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [call-group-order] destination_number(4155553333) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [extension-intercom] destination_number(4155553333) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [Local_Extension] destination_number(4155553333) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->group_dial_ringables] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [group_dial_ringables] destination_number(4155553333) =~ /^1999$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->mobile_extensions] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [mobile_extensions] destination_number(4155553333) =~ /^(20[01][0-9])$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->vmain] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [vmain] destination_number(4155553333) =~ /^vmain$|^4000$$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->vm1000] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [vm1000] destination_number(4155553333) =~ /^vm1000$|^4100$|^\*98$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->sip_uri] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [sip_uri] destination_number(4155553333) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->nb_conferences] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [nb_conferences] destination_number(4155553333) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->wb_conferences] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [wb_conferences] destination_number(4155553333) =~ /^(31\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->uwb_conferences] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [uwb_conferences] destination_number(4155553333) =~ /^(32\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->cdquality_conferences] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [cdquality_conferences] destination_number(4155553333) =~ /^(33\d{2})$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(4155553333) =~ /^9(888|1616|3232)$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [mad_boss_intercom] destination_number(4155553333) =~ /^0911$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [mad_boss_intercom] destination_number(4155553333) =~ /^0912$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->mad_boss] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [mad_boss] destination_number(4155553333) =~ /^0913$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ivr_demo] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ivr_demo] destination_number(4155553333) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->dynamic_conference] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [dynamic_conference] destination_number(4155553333) =~ /^5001$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->rtp_multicast_page] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [rtp_multicast_page] destination_number(4155553333) =~ /^pagegroup$|^7243$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->park] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [park] destination_number(4155553333) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->unpark] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [unpark] destination_number(4155553333) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->park] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [park] destination_number(4155553333) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->unpark] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [unpark] destination_number(4155553333) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->park] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [park] destination_number(4155553333) =~ /callpark/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->unpark] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [unpark] destination_number(4155553333) =~ /pickup/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->wait] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [wait] destination_number(4155553333) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->fax_receive] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [fax_receive] destination_number(4155553333) =~ /^9978$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->fax_transmit] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [fax_transmit] destination_number(4155553333) =~ /^9979$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ringback_180] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ringback_180] destination_number(4155553333) =~ /^9980$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ringback_183_uk_ring] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ringback_183_uk_ring] destination_number(4155553333) =~ /^9981$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ringback_183_music_ring] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ringback_183_music_ring] destination_number(4155553333) =~ /^9982$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ringback_post_answer_uk_ring] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(4155553333) =~ /^9983$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ringback_post_answer_music] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ringback_post_answer_music] destination_number(4155553333) =~ /^9984$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->ClueCon] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [ClueCon] destination_number(4155553333) =~ /^9991$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->show_info] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [show_info] destination_number(4155553333) =~ /^9992$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->video_record] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [video_record] destination_number(4155553333) =~ /^9993$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->video_playback] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [video_playback] destination_number(4155553333) =~ /^9994$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->delay_echo] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [delay_echo] destination_number(4155553333) =~ /^9995$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->echo] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [echo] destination_number(4155553333) =~ /^9996$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->milliwatt] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [milliwatt] destination_number(4155553333) =~ /^9997$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->tone_stream] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [tone_stream] destination_number(4155553333) =~ /^9998$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->zrtp_enrollement] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [zrtp_enrollement] destination_number(4155553333) =~ /^9787$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->hold_music] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [hold_music] destination_number(4155553333) =~ /^9999$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->fax] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [fax] destination_number(4155553333) =~ /^fax|9777$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->test-9555] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [test-9555] destination_number(4155553333) =~ /^9555$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->test-9666] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [test-9666] destination_number(4155553333) =~ /^9666$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->pizza_demo] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (FAIL) [pizza_demo] destination_number(4155553333) =~ /^(pizza|74992)$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 parsing [default->Inbound-4155553333] continue=false
Dialplan: sofia/internal/4155559999@192.168.1.254 Regex (PASS) [Inbound-4155553333] destination_number(4155553333) =~ /^4155553333$/ break=on-false
Dialplan: sofia/internal/4155559999@192.168.1.254 Action ring_ready()
Dialplan: sofia/internal/4155559999@192.168.1.254 Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action set(ringback=${us-ring})
Dialplan: sofia/internal/4155559999@192.168.1.254 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action set(call_timeout=28)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action set(continue_on_fail=true)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action bridge(${group_call(ringables@${domain_name})})
Dialplan: sofia/internal/4155559999@192.168.1.254 Action answer()
Dialplan: sofia/internal/4155559999@192.168.1.254 Action sleep(1000)
Dialplan: sofia/internal/4155559999@192.168.1.254 Action voicemail(default ${domain_name} 1000)
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/4155559999@192.168.1.254) State Change CS_ROUTING -> CS_EXECUTE
2009-11-14 09:35:43.951943 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/4155559999@192.168.1.254) State ROUTING going to sleep
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/4155559999@192.168.1.254) Running State Change CS_EXECUTE
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/4155559999@192.168.1.254) State EXECUTE
2009-11-14 09:35:43.951943 [DEBUG] mod_sofia.c:173 sofia/internal/4155559999@192.168.1.254 SOFIA EXECUTE
2009-11-14 09:35:43.951943 [DEBUG] switch_core_state_machine.c:151 sofia/internal/4155559999@192.168.1.254 Standard EXECUTE
EXECUTE sofia/internal/4155559999@192.168.1.254 hash(insert/192.168.1.254-spymap/4155559999/22f8ee00-d144-11de-a41f-e5a6b5425f55)
EXECUTE sofia/internal/4155559999@192.168.1.254 hash(insert/192.168.1.254-last_dial/4155559999/4155553333)
EXECUTE sofia/internal/4155559999@192.168.1.254 hash(insert/192.168.1.254-last_dial/global/22f8ee00-d144-11de-a41f-e5a6b5425f55)
EXECUTE sofia/internal/4155559999@192.168.1.254 ring_ready()
2009-11-14 09:35:43.951943 [DEBUG] mod_dptools.c:415 sofia/internal/4155559999@192.168.1.254 receive message [RINGING]
2009-11-14 09:35:43.951943 [NOTICE] mod_sofia.c:1449 Ring-Ready sofia/internal/4155559999@192.168.1.254!
2009-11-14 09:35:43.951943 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:43.951943 [NOTICE] mod_dptools.c:415 Ring Ready sofia/internal/4155559999@192.168.1.254!
EXECUTE sofia/internal/4155559999@192.168.1.254 bind_meta_app(1 b s execute_extension::dx XML features)
2009-11-14 09:35:43.951943 [INFO] switch_ivr_async.c:1795 Bound B-Leg: 1 execute_extension::dx XML features
EXECUTE sofia/internal/4155559999@192.168.1.254 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/4155559999.2009-11-14-09-35-43.wav)
2009-11-14 09:35:43.951943 [INFO] switch_ivr_async.c:1795 Bound B-Leg: 2 record_session::/usr/local/freeswitch/recordings/4155559999.2009-11-14-09-35-43.wav
EXECUTE sofia/internal/4155559999@192.168.1.254 bind_meta_app(3 b s execute_extension::cf XML features)
2009-11-14 09:35:43.951943 [INFO] switch_ivr_async.c:1795 Bound B-Leg: 3 execute_extension::cf XML features
EXECUTE sofia/internal/4155559999@192.168.1.254 set(ringback=%(2000,4000,440.0,480.0))
2009-11-14 09:35:43.951943 [DEBUG] mod_dptools.c:748 sofia/internal/4155559999@192.168.1.254 SET [ringback]=[%(2000,4000,440.0,480.0)]
EXECUTE sofia/internal/4155559999@192.168.1.254 set(transfer_ringback=local_stream://moh)
2009-11-14 09:35:43.951943 [DEBUG] mod_dptools.c:748 sofia/internal/4155559999@192.168.1.254 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/4155559999@192.168.1.254 set(call_timeout=28)
2009-11-14 09:35:43.951943 [DEBUG] mod_dptools.c:748 sofia/internal/4155559999@192.168.1.254 SET [call_timeout]=[28]
EXECUTE sofia/internal/4155559999@192.168.1.254 set(hangup_after_bridge=true)
2009-11-14 09:35:43.951943 [DEBUG] mod_dptools.c:748 sofia/internal/4155559999@192.168.1.254 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/4155559999@192.168.1.254 set(continue_on_fail=true)
2009-11-14 09:35:43.951943 [DEBUG] mod_dptools.c:748 sofia/internal/4155559999@192.168.1.254 SET [continue_on_fail]=[true]
2009-11-14 09:35:43.966601 [DEBUG] sofia.c:3289 Channel sofia/internal/4155559999@192.168.1.254 entering state [early][180]
EXECUTE sofia/internal/4155559999@192.168.1.254 bridge([presence_id=1011@192.168.1.254]sofia/internal/sip:1011@192.168.1.98:5872,[presence_id=1012@192.168.1.254]sofia/internal/sip:1012@192.168.1.98:5872,[presence_id=1014@192.168.1.254]sofia/internal/sip:1014@192.168.1.97:5060)
2009-11-14 09:35:43.986485 [NOTICE] switch_channel.c:602 New Channel sofia/internal/sip:1011@192.168.1.98:5872 [22ff385a-d144-11de-a41f-e5a6b5425f55]
2009-11-14 09:35:43.986485 [DEBUG] mod_sofia.c:2811 (sofia/internal/sip:1011@192.168.1.98:5872) State Change CS_NEW -> CS_INIT
2009-11-14 09:35:43.990495 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1011@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:43.990495 [NOTICE] switch_channel.c:602 New Channel sofia/internal/sip:1012@192.168.1.98:5872 [22ff6230-d144-11de-a41f-e5a6b5425f55]
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1011@192.168.1.98:5872) Running State Change CS_INIT
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1011@192.168.1.98:5872) State INIT
2009-11-14 09:35:43.990495 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1011@192.168.1.98:5872 SOFIA INIT
2009-11-14 09:35:43.990495 [DEBUG] mod_sofia.c:111 (sofia/internal/sip:1011@192.168.1.98:5872) State Change CS_INIT -> CS_ROUTING
2009-11-14 09:35:43.990495 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1011@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1011@192.168.1.98:5872) State INIT going to sleep
2009-11-14 09:35:43.990495 [DEBUG] sofia.c:3289 Channel sofia/internal/sip:1011@192.168.1.98:5872 entering state [calling][0]
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1011@192.168.1.98:5872) Running State Change CS_ROUTING
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:1011@192.168.1.98:5872) State ROUTING
2009-11-14 09:35:43.990495 [DEBUG] mod_sofia.c:130 sofia/internal/sip:1011@192.168.1.98:5872 SOFIA ROUTING
2009-11-14 09:35:43.990495 [DEBUG] switch_ivr_originate.c:63 (sofia/internal/sip:1011@192.168.1.98:5872) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2009-11-14 09:35:43.990495 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1011@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:1011@192.168.1.98:5872) State ROUTING going to sleep
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1011@192.168.1.98:5872) Running State Change CS_CONSUME_MEDIA
2009-11-14 09:35:43.990495 [DEBUG] switch_core_state_machine.c:503 (sofia/internal/sip:1011@192.168.1.98:5872) State CONSUME_MEDIA
2009-11-14 09:35:43.990495 [DEBUG] mod_sofia.c:2811 (sofia/internal/sip:1012@192.168.1.98:5872) State Change CS_NEW -> CS_INIT
2009-11-14 09:35:43.990495 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1012@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:43.994449 [NOTICE] switch_channel.c:602 New Channel sofia/internal/sip:1014@192.168.1.97:5060 [22fffdb2-d144-11de-a41f-e5a6b5425f55]
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1012@192.168.1.98:5872) Running State Change CS_INIT
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1012@192.168.1.98:5872) State INIT
2009-11-14 09:35:43.994449 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1012@192.168.1.98:5872 SOFIA INIT
2009-11-14 09:35:43.994449 [DEBUG] mod_sofia.c:111 (sofia/internal/sip:1012@192.168.1.98:5872) State Change CS_INIT -> CS_ROUTING
2009-11-14 09:35:43.994449 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1012@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:43.994449 [DEBUG] sofia.c:3289 Channel sofia/internal/sip:1012@192.168.1.98:5872 entering state [calling][0]
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1012@192.168.1.98:5872) State INIT going to sleep
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1012@192.168.1.98:5872) Running State Change CS_ROUTING
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:1012@192.168.1.98:5872) State ROUTING
2009-11-14 09:35:43.994449 [DEBUG] mod_sofia.c:130 sofia/internal/sip:1012@192.168.1.98:5872 SOFIA ROUTING
2009-11-14 09:35:43.994449 [DEBUG] switch_ivr_originate.c:63 (sofia/internal/sip:1012@192.168.1.98:5872) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2009-11-14 09:35:43.994449 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1012@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:1012@192.168.1.98:5872) State ROUTING going to sleep
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1012@192.168.1.98:5872) Running State Change CS_CONSUME_MEDIA
2009-11-14 09:35:43.994449 [DEBUG] switch_core_state_machine.c:503 (sofia/internal/sip:1012@192.168.1.98:5872) State CONSUME_MEDIA
2009-11-14 09:35:43.994449 [DEBUG] mod_sofia.c:2811 (sofia/internal/sip:1014@192.168.1.97:5060) State Change CS_NEW -> CS_INIT
2009-11-14 09:35:43.994449 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1014@192.168.1.97:5060 [BREAK]
2009-11-14 09:35:43.998457 [DEBUG] switch_ivr_originate.c:1701 sofia/internal/4155559999@192.168.1.254 receive message [PROGRESS]
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1014@192.168.1.97:5060) Running State Change CS_INIT
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1014@192.168.1.97:5060) State INIT
2009-11-14 09:35:43.998457 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1014@192.168.1.97:5060 SOFIA INIT
2009-11-14 09:35:43.998457 [DEBUG] mod_sofia.c:111 (sofia/internal/sip:1014@192.168.1.97:5060) State Change CS_INIT -> CS_ROUTING
2009-11-14 09:35:43.998457 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1014@192.168.1.97:5060 [BREAK]
2009-11-14 09:35:43.998457 [DEBUG] sofia.c:3289 Channel sofia/internal/sip:1014@192.168.1.97:5060 entering state [calling][0]
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1014@192.168.1.97:5060) State INIT going to sleep
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1014@192.168.1.97:5060) Running State Change CS_ROUTING
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:1014@192.168.1.97:5060) State ROUTING
2009-11-14 09:35:43.998457 [DEBUG] mod_sofia.c:130 sofia/internal/sip:1014@192.168.1.97:5060 SOFIA ROUTING
2009-11-14 09:35:43.998457 [DEBUG] switch_ivr_originate.c:63 (sofia/internal/sip:1014@192.168.1.97:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2009-11-14 09:35:43.998457 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1014@192.168.1.97:5060 [BREAK]
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:1014@192.168.1.97:5060) State ROUTING going to sleep
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1014@192.168.1.97:5060) Running State Change CS_CONSUME_MEDIA
2009-11-14 09:35:43.998457 [DEBUG] switch_core_state_machine.c:503 (sofia/internal/sip:1014@192.168.1.97:5060) State CONSUME_MEDIA
2009-11-14 09:35:43.998457 [INFO] switch_ivr_originate.c:1701 Sending early media
2009-11-14 09:35:44.2435 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/internal/4155559999@192.168.1.254] 192.168.1.254 port 31052 -> 192.168.1.97 port 16430 codec: 0 ms: 20
2009-11-14 09:35:44.2435 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 160 bytes per 20ms
2009-11-14 09:35:44.6432 [INFO] mod_sofia.c:1506 Ring SDP:
v=0
o=FreeSWITCH 1258189091 1258189092 IN IP4 192.168.1.254
s=FreeSWITCH
c=IN IP4 192.168.1.254
t=0 0
m=audio 31052 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2009-11-14 09:35:44.6432 [NOTICE] mod_sofia.c:1509 Pre-Answer sofia/internal/4155559999@192.168.1.254!
2009-11-14 09:35:44.6432 [DEBUG] sofia.c:3289 Channel sofia/internal/4155559999@192.168.1.254 entering state [early][183]
2009-11-14 09:35:44.6432 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:44.6432 [DEBUG] switch_ivr_originate.c:1718 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2009-11-14 09:35:44.6432 [DEBUG] switch_ivr_originate.c:1777 Play Ringback Tone [%(2000,4000,440.0,480.0)]
2009-11-14 09:35:44.18430 [DEBUG] switch_core_io.c:649 sofia/internal/4155559999@192.168.1.254 receive message [TRANSCODING_NECESSARY]
2009-11-14 09:35:44.22473 [DEBUG] sofia.c:3289 Channel sofia/internal/sip:1014@192.168.1.97:5060 entering state [proceeding][180]
2009-11-14 09:35:44.22473 [NOTICE] sofia.c:3353 Ring-Ready sofia/internal/sip:1014@192.168.1.97:5060!
2009-11-14 09:35:52.326423 [DEBUG] sofia.c:3289 Channel sofia/internal/sip:1011@192.168.1.98:5872 entering state [terminated][480]
2009-11-14 09:35:52.326423 [NOTICE] sofia.c:3849 Hangup sofia/internal/sip:1011@192.168.1.98:5872 [CS_CONSUME_MEDIA] [NO_USER_RESPONSE]
2009-11-14 09:35:52.326423 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/sip:1011@192.168.1.98:5872 [KILL]
2009-11-14 09:35:52.326423 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1011@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:503 (sofia/internal/sip:1011@192.168.1.98:5872) State CONSUME_MEDIA going to sleep
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1011@192.168.1.98:5872) Running State Change CS_HANGUP
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/sip:1011@192.168.1.98:5872) State HANGUP
2009-11-14 09:35:52.330490 [DEBUG] mod_sofia.c:306 sofia/internal/sip:1011@192.168.1.98:5872 Overriding SIP cause 408 with 480 from the other leg
2009-11-14 09:35:52.330490 [DEBUG] mod_sofia.c:338 Channel sofia/internal/sip:1011@192.168.1.98:5872 hanging up, cause: NO_USER_RESPONSE
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1011@192.168.1.98:5872 Standard HANGUP, cause: NO_USER_RESPONSE
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/sip:1011@192.168.1.98:5872) State HANGUP going to sleep
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/sip:1011@192.168.1.98:5872) State Change CS_HANGUP -> CS_REPORTING
2009-11-14 09:35:52.330490 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1011@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1011@192.168.1.98:5872) Running State Change CS_REPORTING
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/sip:1011@192.168.1.98:5872) State REPORTING
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1011@192.168.1.98:5872 Standard REPORTING, cause: NO_USER_RESPONSE
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/sip:1011@192.168.1.98:5872) State REPORTING going to sleep
2009-11-14 09:35:52.330490 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/sip:1011@192.168.1.98:5872) State Change CS_REPORTING -> CS_DESTROY
2009-11-14 09:35:52.330490 [DEBUG] switch_core_session.c:1068 Session 542 (sofia/internal/sip:1011@192.168.1.98:5872) Locked, Waiting on external entities
2009-11-14 09:35:52.618414 [DEBUG] sofia.c:3289 Channel sofia/internal/sip:1012@192.168.1.98:5872 entering state [terminated][480]
2009-11-14 09:35:52.618414 [NOTICE] sofia.c:3849 Hangup sofia/internal/sip:1012@192.168.1.98:5872 [CS_CONSUME_MEDIA] [NO_USER_RESPONSE]
2009-11-14 09:35:52.618414 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/sip:1012@192.168.1.98:5872 [KILL]
2009-11-14 09:35:52.618414 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1012@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:503 (sofia/internal/sip:1012@192.168.1.98:5872) State CONSUME_MEDIA going to sleep
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1012@192.168.1.98:5872) Running State Change CS_HANGUP
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/sip:1012@192.168.1.98:5872) State HANGUP
2009-11-14 09:35:52.626426 [DEBUG] mod_sofia.c:306 sofia/internal/sip:1012@192.168.1.98:5872 Overriding SIP cause 408 with 480 from the other leg
2009-11-14 09:35:52.626426 [DEBUG] mod_sofia.c:338 Channel sofia/internal/sip:1012@192.168.1.98:5872 hanging up, cause: NO_USER_RESPONSE
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1012@192.168.1.98:5872 Standard HANGUP, cause: NO_USER_RESPONSE
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/sip:1012@192.168.1.98:5872) State HANGUP going to sleep
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/sip:1012@192.168.1.98:5872) State Change CS_HANGUP -> CS_REPORTING
2009-11-14 09:35:52.626426 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1012@192.168.1.98:5872 [BREAK]
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1012@192.168.1.98:5872) Running State Change CS_REPORTING
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/sip:1012@192.168.1.98:5872) State REPORTING
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1012@192.168.1.98:5872 Standard REPORTING, cause: NO_USER_RESPONSE
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/sip:1012@192.168.1.98:5872) State REPORTING going to sleep
2009-11-14 09:35:52.626426 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/sip:1012@192.168.1.98:5872) State Change CS_REPORTING -> CS_DESTROY
2009-11-14 09:35:52.626426 [DEBUG] switch_core_session.c:1068 Session 543 (sofia/internal/sip:1012@192.168.1.98:5872) Locked, Waiting on external entities
2009-11-14 09:35:59.778421 [DEBUG] sofia.c:3289 Channel sofia/internal/4155559999@192.168.1.254 entering state [terminated][487]
2009-11-14 09:35:59.778421 [NOTICE] sofia.c:3849 Hangup sofia/internal/4155559999@192.168.1.254 [CS_EXECUTE] [ORIGINATOR_CANCEL]
2009-11-14 09:35:59.778421 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/4155559999@192.168.1.254 [KILL]
2009-11-14 09:35:59.778421 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:59.798426 [NOTICE] switch_ivr_originate.c:1994 Hangup sofia/internal/sip:1014@192.168.1.97:5060 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
2009-11-14 09:35:59.798426 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/sip:1014@192.168.1.97:5060 [KILL]
2009-11-14 09:35:59.798426 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1014@192.168.1.97:5060 [BREAK]
2009-11-14 09:35:59.798426 [DEBUG] switch_ivr_originate.c:2134 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
2009-11-14 09:35:59.798426 [NOTICE] switch_core_session.c:1086 Session 542 (sofia/internal/sip:1011@192.168.1.98:5872) Ended
2009-11-14 09:35:59.798426 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/sip:1011@192.168.1.98:5872 [CS_DESTROY]
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/sip:1011@192.168.1.98:5872) State DESTROY
2009-11-14 09:35:59.798426 [DEBUG] mod_sofia.c:255 sofia/internal/sip:1011@192.168.1.98:5872 SOFIA DESTROY
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1011@192.168.1.98:5872 Standard DESTROY
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/sip:1011@192.168.1.98:5872) State DESTROY going to sleep
2009-11-14 09:35:59.798426 [NOTICE] switch_core_session.c:1086 Session 543 (sofia/internal/sip:1012@192.168.1.98:5872) Ended
2009-11-14 09:35:59.798426 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/sip:1012@192.168.1.98:5872 [CS_DESTROY]
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/sip:1012@192.168.1.98:5872) State DESTROY
2009-11-14 09:35:59.798426 [DEBUG] mod_sofia.c:255 sofia/internal/sip:1012@192.168.1.98:5872 SOFIA DESTROY
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1012@192.168.1.98:5872 Standard DESTROY
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/sip:1012@192.168.1.98:5872) State DESTROY going to sleep
2009-11-14 09:35:59.798426 [INFO] mod_dptools.c:2093 Originate Failed.  Cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/4155559999@192.168.1.254) State EXECUTE going to sleep
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/4155559999@192.168.1.254) Running State Change CS_HANGUP
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/4155559999@192.168.1.254) State HANGUP
2009-11-14 09:35:59.798426 [DEBUG] mod_sofia.c:306 sofia/internal/4155559999@192.168.1.254 Overriding SIP cause 487 with 487 from the other leg
2009-11-14 09:35:59.798426 [DEBUG] mod_sofia.c:338 Channel sofia/internal/4155559999@192.168.1.254 hanging up, cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:46 sofia/internal/4155559999@192.168.1.254 Standard HANGUP, cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.798426 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/4155559999@192.168.1.254) State HANGUP going to sleep
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:503 (sofia/internal/sip:1014@192.168.1.97:5060) State CONSUME_MEDIA going to sleep
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1014@192.168.1.97:5060) Running State Change CS_HANGUP
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/sip:1014@192.168.1.97:5060) State HANGUP
2009-11-14 09:35:59.810601 [DEBUG] mod_sofia.c:306 sofia/internal/sip:1014@192.168.1.97:5060 Overriding SIP cause 487 with 487 from the other leg
2009-11-14 09:35:59.810601 [DEBUG] mod_sofia.c:338 Channel sofia/internal/sip:1014@192.168.1.97:5060 hanging up, cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.810601 [DEBUG] mod_sofia.c:406 Sending CANCEL to sofia/internal/sip:1014@192.168.1.97:5060
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1014@192.168.1.97:5060 Standard HANGUP, cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/sip:1014@192.168.1.97:5060) State HANGUP going to sleep
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/sip:1014@192.168.1.97:5060) State Change CS_HANGUP -> CS_REPORTING
2009-11-14 09:35:59.810601 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/sip:1014@192.168.1.97:5060 [BREAK]
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/sip:1014@192.168.1.97:5060) Running State Change CS_REPORTING
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/sip:1014@192.168.1.97:5060) State REPORTING
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1014@192.168.1.97:5060 Standard REPORTING, cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/sip:1014@192.168.1.97:5060) State REPORTING going to sleep
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/sip:1014@192.168.1.97:5060) State Change CS_REPORTING -> CS_DESTROY
2009-11-14 09:35:59.810601 [DEBUG] switch_core_session.c:1068 Session 544 (sofia/internal/sip:1014@192.168.1.97:5060) Locked, Waiting on external entities
2009-11-14 09:35:59.810601 [NOTICE] switch_core_session.c:1086 Session 544 (sofia/internal/sip:1014@192.168.1.97:5060) Ended
2009-11-14 09:35:59.810601 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/sip:1014@192.168.1.97:5060 [CS_DESTROY]
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/sip:1014@192.168.1.97:5060) State DESTROY
2009-11-14 09:35:59.810601 [DEBUG] mod_sofia.c:255 sofia/internal/sip:1014@192.168.1.97:5060 SOFIA DESTROY
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1014@192.168.1.97:5060 Standard DESTROY
2009-11-14 09:35:59.810601 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/sip:1014@192.168.1.97:5060) State DESTROY going to sleep
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/4155559999@192.168.1.254) State Change CS_HANGUP -> CS_REPORTING
2009-11-14 09:35:59.814986 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/4155559999@192.168.1.254 [BREAK]
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/4155559999@192.168.1.254) Running State Change CS_REPORTING
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/4155559999@192.168.1.254) State REPORTING
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:53 sofia/internal/4155559999@192.168.1.254 Standard REPORTING, cause: ORIGINATOR_CANCEL
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/4155559999@192.168.1.254) State REPORTING going to sleep
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/4155559999@192.168.1.254) State Change CS_REPORTING -> CS_DESTROY
2009-11-14 09:35:59.814986 [DEBUG] switch_core_session.c:1068 Session 541 (sofia/internal/4155559999@192.168.1.254) Locked, Waiting on external entities
2009-11-14 09:35:59.814986 [NOTICE] switch_core_session.c:1086 Session 541 (sofia/internal/4155559999@192.168.1.254) Ended
2009-11-14 09:35:59.814986 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/4155559999@192.168.1.254 [CS_DESTROY]
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/4155559999@192.168.1.254) State DESTROY
2009-11-14 09:35:59.814986 [DEBUG] mod_sofia.c:255 sofia/internal/4155559999@192.168.1.254 SOFIA DESTROY
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:60 sofia/internal/4155559999@192.168.1.254 Standard DESTROY
2009-11-14 09:35:59.814986 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/4155559999@192.168.1.254) State DESTROY going to sleep