On 22 March 2010 13:39, Carlos Talbot <carlos.talbot@gmail.com> wrote:
I've experienced the same problem. I have several SIP clients registered to one extension on my FreeSWITCH server at home (multiple-registrations). If one of the clients happens to be siproid it will immediately answer while the other clients stop ringing. It also sends a European ringback tone to the caller for some reason. I'm still trying to debug the sipdroid code to figure out where this is happening.
Looks like sipdroid might be in the clear. 107.338991 202.173.153.98 -> 192.168.200.42 SIP/SDP Request: INVITE sip:1002@192.168.200.42:43658;transport=udp, with session description 107.554359 192.168.200.42 -> 202.173.153.98 SIP Status: 100 Trying 108.387799 192.168.200.42 -> 202.173.153.98 SIP/SDP Status: 180 Ringing, with session description <hang up> 121.372867 202.173.153.98 -> 192.168.200.42 SIP Request: CANCEL sip:1002@192.168.200.42:43658;transport=udp 121.496434 192.168.200.42 -> 202.173.153.98 SIP Status: 200 OK 121.559057 192.168.200.42 -> 202.173.153.98 SIP Status: 487 Request Terminated 121.560015 202.173.153.98 -> 192.168.200.42 SIP Request: ACK sip:1002@192.168.200.42:43658;transport=udp 123.679219 192.168.200.42 -> 202.173.153.98 UDP Source port: 43658 Destination port: sip This gets me back to the other thread - "How long did the phone ring?" which discusses 180 vs 183 styles of answering calls. In this case it is using 180 which was described as "your phone rings (Ringing message)", not 183 as I expected it might be which is "early media or inband ringing (Session Progress message)". All of the above looks perfect to me. However something is really screwy. First question, what generates that non-standard ring tone I can hear? At this time freeswitch shows: freeswitch@internal> show channels uuid,direction,created,created_epoch,name,state,cid_name,cid_num,ip_addr,dest,application,application_data,dialplan,context,read_codec,read_rate,write_codec,write_rate,secure,hostname,presence_id,presence_data 994c5126-d961-4838-b642-d41060242283,inbound,2010-03-22 18:52:22,1269244342,sofia/internal/1000@202.173.153.98,CS_EXECUTE,Lounge,1000,192.168.87.13,1002,bridge,user/1002@microcomaustralia.com.au,XML,default,PCMA,8000,PCMA,8000,,huey,1000@202.173.153.98, bef34f96-bb3c-44b2-b8d8-41f5a1e7913e,outbound,2010-03-22 18:52:22,1269244342,sofia/internal/sip:1002@192.168.200.42:43658,CS_EXCHANGE_MEDIA,Lounge,1001,192.168.87.13,1002,,,XML,default,PCMA,8000,PCMA,8000,,huey,1002@microcomaustralia.com.au, which seems to imply that it is passing audio data to/from siphoid. However nothing shows up on the sip port for negotiating this. How is this possible? It seems like I am getting inband ringing with 180. Am I confused? I also note RTP packets whizzing past, which confirms this. I have added full debugging from freeswitch to the end. I haven't yet analysed it in detail.
My impression is that the primary developer of sipdroid is in an Asterisk world and so does not really care on how the mjsip based SIP stack behaves in other environments.
:-(
Incidentally, Brian West had replied to your email regarding a copy of sipdroid I recently built with the SILK codec. I've recently checked in the code along with BV support. I recommend SILK over BV with sipdroid though as BV is a CPU hog. Well, this is partly to do with how sipdroid behaves too. See here: http://code.google.com/p/sipdroid/issues/detail?id=358 The patch includes SILK's wide band codecs so it's worth testing against a FreeSWITCH server. I'd like others feedback on the perceived sound quality (especially those with Droids as I hear they have a pretty decent speaker). On my HTC magic you can tell the difference between SILK8 and 16 but I'm not that impressed on the fidelity of the handset speaker. Most cell phone manufactures nowadays (including Apple) don't seem to care about the primary purpose of the device; a decent sounding phone call.
Ok, will look at codecs once I work out what is going on with ringing... 2010-03-22 18:52:22.120480 [DEBUG] sofia.c:5797 IP 192.168.87.13 Approved by acl "domains[1001@microcomaustralia.com.au]". Access Granted. 2010-03-22 18:52:22.120480 [DEBUG] sofia.c:5919 Authenticating user 1001@microcomaustralia.com.au 2010-03-22 18:52:22.120480 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1000@202.173.153.98 [994c5126-d961-4838-b642-d41060242283] 2010-03-22 18:52:22.151167 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@202.173.153.98) Running State Change CS_NEW 2010-03-22 18:52:22.151167 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1000@202.173.153.98) State NEW 2010-03-22 18:52:22.171563 [DEBUG] sofia.c:4152 Channel sofia/internal/1000@202.173.153.98 entering state [received][100] 2010-03-22 18:52:22.171563 [DEBUG] sofia.c:4163 Remote SDP: v=0 o=- 3092896 3092896 IN IP4 192.168.87.13 s=- c=IN IP4 192.168.87.13 t=0 0 m=audio 16468 RTP/AVP 8 0 2 4 18 96 97 98 100 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 2010-03-22 18:52:22.171563 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:30]/[G7221:115:32000:20] 2010-03-22 18:52:22.171563 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:30]/[G7221:107:16000:20] 2010-03-22 18:52:22.178570 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:30]/[PCMU:0:8000:20] 2010-03-22 18:52:22.178570 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:30]/[PCMA:8:8000:20] 2010-03-22 18:52:22.178570 [DEBUG] sofia_glue.c:3626 Substituting codec PCMA@30i@8000h 2010-03-22 18:52:22.181212 [DEBUG] sofia_glue.c:2354 Set Codec sofia/internal/1000@202.173.153.98 PCMA/8000 30 ms 240 samples 2010-03-22 18:52:22.187060 [DEBUG] sofia_glue.c:3518 Set 2833 dtmf send payload to 101 2010-03-22 18:52:22.187060 [DEBUG] sofia.c:4309 (sofia/internal/1000@202.173.153.98) State Change CS_NEW -> CS_INIT 2010-03-22 18:52:22.187060 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:22.187060 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@202.173.153.98) Running State Change CS_INIT 2010-03-22 18:52:22.187060 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/1000@202.173.153.98) State INIT 2010-03-22 18:52:22.187060 [DEBUG] mod_sofia.c:83 sofia/internal/1000@202.173.153.98 SOFIA INIT 2010-03-22 18:52:22.187060 [DEBUG] mod_sofia.c:117 (sofia/internal/1000@202.173.153.98) State Change CS_INIT -> CS_ROUTING 2010-03-22 18:52:22.187060 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:22.187060 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/1000@202.173.153.98) State INIT going to sleep 2010-03-22 18:52:22.187060 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@202.173.153.98) Running State Change CS_ROUTING 2010-03-22 18:52:22.198995 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/1000@202.173.153.98) State ROUTING 2010-03-22 18:52:22.198995 [DEBUG] mod_sofia.c:140 sofia/internal/1000@202.173.153.98 SOFIA ROUTING 2010-03-22 18:52:22.198995 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1000@202.173.153.98 Standard ROUTING 2010-03-22 18:52:22.198995 [INFO] mod_dialplan_xml.c:418 Processing Lounge->1002 in context default Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->unloop] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [global-intercept] destination_number(1002) =~ /^886$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->redial] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [redial] destination_number(1002) =~ /^870$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->global] continue=true Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/1000@202.173.153.98 Absolute Condition [global] Dialplan: sofia/internal/1000@202.173.153.98 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1000@202.173.153.98 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1000@202.173.153.98 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [snom-demo-2] destination_number(1002) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [snom-demo-1] destination_number(1002) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^88(.*)$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^779$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->call_return] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [call_return] destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->del-group] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [del-group] destination_number(1002) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->add-group] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [add-group] destination_number(1002) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (FAIL) [extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1000@202.173.153.98 Regex (PASS) [Local_Extension] destination_number(1002) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@202.173.153.98 Action set(dialed_extension=1002) Dialplan: sofia/internal/1000@202.173.153.98 Action export(dialed_extension=1002) Dialplan: sofia/internal/1000@202.173.153.98 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1000@202.173.153.98 Action bind_meta_app(2 b s record_session::/opt/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1000@202.173.153.98 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1000@202.173.153.98 Action set(ringback=${au-ring}) Dialplan: sofia/internal/1000@202.173.153.98 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1000@202.173.153.98 Action set(call_timeout=30) Dialplan: sofia/internal/1000@202.173.153.98 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@202.173.153.98 Action set(continue_on_fail=true) Dialplan: sofia/internal/1000@202.173.153.98 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1000@202.173.153.98 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1000@202.173.153.98 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1000@202.173.153.98 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@202.173.153.98 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1000@202.173.153.98 Action answer() Dialplan: sofia/internal/1000@202.173.153.98 Action sleep(1000) Dialplan: sofia/internal/1000@202.173.153.98 Action voicemail(default ${domain_name} ${dialed_extension}) 2010-03-22 18:52:22.248545 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1000@202.173.153.98) State Change CS_ROUTING -> CS_EXECUTE 2010-03-22 18:52:22.248545 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:22.248545 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/1000@202.173.153.98) State ROUTING going to sleep 2010-03-22 18:52:22.250461 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@202.173.153.98) Running State Change CS_EXECUTE 2010-03-22 18:52:22.254446 [DEBUG] switch_core_state_machine.c:348 (sofia/internal/1000@202.173.153.98) State EXECUTE 2010-03-22 18:52:22.254446 [DEBUG] mod_sofia.c:226 sofia/internal/1000@202.173.153.98 SOFIA EXECUTE 2010-03-22 18:52:22.254446 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1000@202.173.153.98 Standard EXECUTE EXECUTE sofia/internal/1000@202.173.153.98 hash(insert/microcomaustralia.com.au-spymap/1000/994c5126-d961-4838-b642-d41060242283) EXECUTE sofia/internal/1000@202.173.153.98 hash(insert/microcomaustralia.com.au-last_dial/1000/1002) EXECUTE sofia/internal/1000@202.173.153.98 hash(insert/microcomaustralia.com.au-last_dial/global/994c5126-d961-4838-b642-d41060242283) EXECUTE sofia/internal/1000@202.173.153.98 set(dialed_extension=1002) 2010-03-22 18:52:22.277534 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [dialed_extension]=[1002] EXECUTE sofia/internal/1000@202.173.153.98 export(dialed_extension=1002) 2010-03-22 18:52:22.311503 [DEBUG] mod_dptools.c:898 EXPORT [dialed_extension]=[1002] EXECUTE sofia/internal/1000@202.173.153.98 bind_meta_app(1 b s execute_extension::dx XML features) 2010-03-22 18:52:22.323369 [INFO] switch_ivr_async.c:2339 Bound B-Leg: 1 execute_extension::dx XML features EXECUTE sofia/internal/1000@202.173.153.98 bind_meta_app(2 b s record_session::/opt/freeswitch/recordings/1000.2010-03-22-18-52-22.wav) 2010-03-22 18:52:22.337501 [INFO] switch_ivr_async.c:2339 Bound B-Leg: 2 record_session::/opt/freeswitch/recordings/1000.2010-03-22-18-52-22.wav EXECUTE sofia/internal/1000@202.173.153.98 bind_meta_app(3 b s execute_extension::cf XML features) 2010-03-22 18:52:22.354499 [INFO] switch_ivr_async.c:2339 Bound B-Leg: 3 execute_extension::cf XML features EXECUTE sofia/internal/1000@202.173.153.98 set(ringback=) 2010-03-22 18:52:22.359488 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [ringback]=[UNDEF] EXECUTE sofia/internal/1000@202.173.153.98 set(transfer_ringback=local_stream://moh) 2010-03-22 18:52:22.372662 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1000@202.173.153.98 set(call_timeout=30) 2010-03-22 18:52:22.384505 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [call_timeout]=[30] EXECUTE sofia/internal/1000@202.173.153.98 set(hangup_after_bridge=true) 2010-03-22 18:52:22.398395 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1000@202.173.153.98 set(continue_on_fail=true) 2010-03-22 18:52:22.403370 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1000@202.173.153.98 hash(insert/microcomaustralia.com.au-call_return/1002/1000) EXECUTE sofia/internal/1000@202.173.153.98 hash(insert/microcomaustralia.com.au-last_dial_ext/1002/994c5126-d961-4838-b642-d41060242283) EXECUTE sofia/internal/1000@202.173.153.98 set(called_party_callgroup=) 2010-03-22 18:52:22.437699 [DEBUG] mod_dptools.c:814 sofia/internal/1000@202.173.153.98 SET [called_party_callgroup]=[UNDEF] EXECUTE sofia/internal/1000@202.173.153.98 hash(insert/microcomaustralia.com.au-last_dial//994c5126-d961-4838-b642-d41060242283) EXECUTE sofia/internal/1000@202.173.153.98 bridge(user/1002@microcomaustralia.com.au) 2010-03-22 18:52:22.505426 [DEBUG] switch_ivr_originate.c:1885 variable string 0 = [presence_id=1002@microcomaustralia.com.au] 2010-03-22 18:52:22.505426 [NOTICE] switch_channel.c:669 New Channel sofia/internal/sip:1002@192.168.200.42:43658 [bef34f96-bb3c-44b2-b8d8-41f5a1e7913e] 2010-03-22 18:52:22.509487 [DEBUG] mod_sofia.c:3375 (sofia/internal/sip:1002@192.168.200.42:43658) State Change CS_NEW -> CS_INIT 2010-03-22 18:52:22.509487 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:22.521870 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_INIT 2010-03-22 18:52:22.521870 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/sip:1002@192.168.200.42:43658) State INIT 2010-03-22 18:52:22.521870 [DEBUG] mod_sofia.c:83 sofia/internal/sip:1002@192.168.200.42:43658 SOFIA INIT 2010-03-22 18:52:22.532449 [DEBUG] mod_sofia.c:117 (sofia/internal/sip:1002@192.168.200.42:43658) State Change CS_INIT -> CS_ROUTING 2010-03-22 18:52:22.532449 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:22.532449 [DEBUG] sofia.c:4152 Channel sofia/internal/sip:1002@192.168.200.42:43658 entering state [calling][0] 2010-03-22 18:52:22.532449 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/sip:1002@192.168.200.42:43658) State INIT going to sleep 2010-03-22 18:52:22.536471 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_ROUTING 2010-03-22 18:52:22.542405 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/sip:1002@192.168.200.42:43658) State ROUTING 2010-03-22 18:52:22.542405 [DEBUG] mod_sofia.c:140 sofia/internal/sip:1002@192.168.200.42:43658 SOFIA ROUTING 2010-03-22 18:52:22.542405 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1002@192.168.200.42:43658) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2010-03-22 18:52:22.542405 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:22.545489 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/sip:1002@192.168.200.42:43658) State ROUTING going to sleep 2010-03-22 18:52:22.545489 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_CONSUME_MEDIA 2010-03-22 18:52:22.549537 [DEBUG] switch_core_state_machine.c:360 (sofia/internal/sip:1002@192.168.200.42:43658) State CONSUME_MEDIA 2010-03-22 18:52:22.549537 [DEBUG] switch_core_state_machine.c:360 (sofia/internal/sip:1002@192.168.200.42:43658) State CONSUME_MEDIA going to sleep 2010-03-22 18:52:22.549537 [INFO] ozmod_zt.c:638 Setting echo cancel to 64 taps for 1:1 2010-03-22 18:52:22.553504 [WARNING] ozmod_zt.c:644 Echo cancel not available for 1:1 2010-03-22 18:52:22.553504 [DEBUG] mod_openzap.c:403 Set codec PCMU 20ms 2010-03-22 18:52:22.559427 [DEBUG] mod_openzap.c:1312 Connect outbound channel OpenZAP/1:1/ 2010-03-22 18:52:22.562442 [NOTICE] switch_channel.c:669 New Channel OpenZAP/1:1/ [63bd7875-06a6-4779-9c21-f69d08a1e6f7] 2010-03-22 18:52:22.562442 [DEBUG] mod_openzap.c:1326 (OpenZAP/1:1/) State Change CS_NEW -> CS_INIT 2010-03-22 18:52:22.562442 [DEBUG] switch_core_session.c:1018 Send signal OpenZAP/1:1/ [BREAK] 2010-03-22 18:52:22.562442 [DEBUG] ozmod_analog.c:80 Changing state on 1:1 from DOWN to GENRING 2010-03-22 18:52:22.562442 [DEBUG] ozmod_analog.c:279 ANALOG CHANNEL thread starting. 2010-03-22 18:52:22.566556 [INFO] ozmod_zt.c:638 Setting echo cancel to 64 taps for 1:1 2010-03-22 18:52:22.566556 [WARNING] ozmod_zt.c:644 Echo cancel not available for 1:1 2010-03-22 18:52:22.566556 [DEBUG] ozmod_analog.c:450 Executing state handler on 1:1 for GENRING 2010-03-22 18:52:22.571354 [DEBUG] mod_openzap.c:1593 got FXS sig [PROGRESS] 2010-03-22 18:52:22.571354 [NOTICE] mod_openzap.c:1609 Ring-Ready OpenZAP/1:1/! 2010-03-22 18:52:22.583992 [DEBUG] switch_core_state_machine.c:314 (OpenZAP/1:1/) Running State Change CS_INIT 2010-03-22 18:52:22.583992 [DEBUG] switch_core_state_machine.c:338 (OpenZAP/1:1/) State INIT 2010-03-22 18:52:22.587618 [DEBUG] mod_openzap.c:431 (OpenZAP/1:1/) State Change CS_INIT -> CS_ROUTING 2010-03-22 18:52:22.587618 [DEBUG] switch_core_session.c:1018 Send signal OpenZAP/1:1/ [BREAK] 2010-03-22 18:52:22.587618 [DEBUG] switch_core_state_machine.c:338 (OpenZAP/1:1/) State INIT going to sleep 2010-03-22 18:52:22.589860 [DEBUG] switch_core_state_machine.c:314 (OpenZAP/1:1/) Running State Change CS_ROUTING 2010-03-22 18:52:22.599032 [DEBUG] switch_core_state_machine.c:341 (OpenZAP/1:1/) State ROUTING 2010-03-22 18:52:22.599032 [DEBUG] mod_openzap.c:454 OpenZAP/1:1/ CHANNEL ROUTING 2010-03-22 18:52:22.599032 [DEBUG] switch_ivr_originate.c:66 (OpenZAP/1:1/) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2010-03-22 18:52:22.599032 [DEBUG] switch_core_session.c:1018 Send signal OpenZAP/1:1/ [BREAK] 2010-03-22 18:52:22.602467 [DEBUG] switch_core_state_machine.c:341 (OpenZAP/1:1/) State ROUTING going to sleep 2010-03-22 18:52:22.602467 [DEBUG] switch_core_state_machine.c:314 (OpenZAP/1:1/) Running State Change CS_CONSUME_MEDIA 2010-03-22 18:52:22.606517 [DEBUG] switch_core_state_machine.c:360 (OpenZAP/1:1/) State CONSUME_MEDIA 2010-03-22 18:52:22.606517 [DEBUG] switch_core_state_machine.c:360 (OpenZAP/1:1/) State CONSUME_MEDIA going to sleep 2010-03-22 18:52:22.611986 [NOTICE] mod_sofia.c:1832 Ring-Ready sofia/internal/1000@202.173.153.98! 2010-03-22 18:52:22.618469 [DEBUG] sofia.c:4152 Channel sofia/internal/1000@202.173.153.98 entering state [early][180] 2010-03-22 18:52:22.618469 [DEBUG] switch_core_session.c:638 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:22.618469 [NOTICE] switch_ivr_originate.c:437 Ring Ready sofia/internal/1000@202.173.153.98! 2010-03-22 18:52:23.599391 [INFO] sofia.c:662 Update Callee ID to "1002" <1002> 2010-03-22 18:52:23.616441 [DEBUG] sofia.c:4152 Channel sofia/internal/sip:1002@192.168.200.42:43658 entering state [proceeding][180] 2010-03-22 18:52:23.616441 [DEBUG] sofia.c:4163 Remote SDP: v=0 o=1002@microcomaustralia.com.au 0 0 IN IP4 192.168.200.42 s=Session SIP/SDP c=IN IP4 192.168.200.42 t=0 0 m=audio 21000 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:30] 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:20]/[PCMU:0:8000:30] 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:3579 Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:30] 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:3626 Substituting codec PCMA@20i@8000h 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:2354 Set Codec sofia/internal/sip:1002@192.168.200.42:43658 PCMA/8000 20 ms 160 samples 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:3512 Set 2833 dtmf recv payload to 0 2010-03-22 18:52:23.616441 [DEBUG] sofia_glue.c:2594 AUDIO RTP [sofia/internal/sip:1002@192.168.200.42:43658] 202.173.153.98 port 26012 -> 192.168.200.42 port 21000 codec: 8 ms: 20 2010-03-22 18:52:23.616441 [DEBUG] switch_rtp.c:1182 Starting timer [soft] 160 bytes per 20ms 2010-03-22 18:52:23.625834 [NOTICE] sofia_glue.c:3150 Pre-Answer sofia/internal/sip:1002@192.168.200.42:43658! 2010-03-22 18:52:23.625834 [DEBUG] switch_channel.c:2180 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:23.625834 [NOTICE] switch_ivr_originate.c:3079 Hangup OpenZAP/1:1/ [CS_CONSUME_MEDIA] [LOSE_RACE] 2010-03-22 18:52:23.630894 [DEBUG] switch_channel.c:2071 Send signal OpenZAP/1:1/ [KILL] 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:314 (OpenZAP/1:1/) Running State Change CS_HANGUP 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:499 (OpenZAP/1:1/) State HANGUP 2010-03-22 18:52:23.630894 [DEBUG] mod_openzap.c:526 Changing state on 1:1 from GENRING to HANGUP 2010-03-22 18:52:23.630894 [DEBUG] mod_openzap.c:556 OpenZAP/1:1/ CHANNEL HANGUP 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:46 OpenZAP/1:1/ Standard HANGUP, cause: LOSE_RACE 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:499 (OpenZAP/1:1/) State HANGUP going to sleep 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:333 (OpenZAP/1:1/) State Change CS_HANGUP -> CS_REPORTING 2010-03-22 18:52:23.630894 [DEBUG] switch_core_session.c:1018 Send signal OpenZAP/1:1/ [BREAK] 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:314 (OpenZAP/1:1/) Running State Change CS_REPORTING 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:590 (OpenZAP/1:1/) State REPORTING 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:53 OpenZAP/1:1/ Standard REPORTING, cause: LOSE_RACE 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:590 (OpenZAP/1:1/) State REPORTING going to sleep 2010-03-22 18:52:23.630894 [DEBUG] switch_core_state_machine.c:327 (OpenZAP/1:1/) State Change CS_REPORTING -> CS_DESTROY 2010-03-22 18:52:23.630894 [DEBUG] switch_core_session.c:1018 Send signal OpenZAP/1:1/ [BREAK] 2010-03-22 18:52:23.630894 [DEBUG] switch_core_session.c:1161 Session 84 (OpenZAP/1:1/) Locked, Waiting on external entities 2010-03-22 18:52:23.640155 [DEBUG] switch_core_session.c:1018 Send signal OpenZAP/1:1/ [BREAK] 2010-03-22 18:52:23.646445 [DEBUG] ozmod_analog.c:450 Executing state handler on 1:1 for HANGUP 2010-03-22 18:52:23.651492 [INFO] switch_ivr_originate.c:3105 Sending early media 2010-03-22 18:52:23.653336 [DEBUG] sofia_glue.c:2594 AUDIO RTP [sofia/internal/1000@202.173.153.98] 202.173.153.98 port 23450 -> 192.168.87.13 port 16468 codec: 8 ms: 30 2010-03-22 18:52:23.654347 [DEBUG] switch_rtp.c:1182 Starting timer [soft] 240 bytes per 30ms 2010-03-22 18:52:23.657559 [DEBUG] mod_sofia.c:1901 Ring SDP: v=0 o=FreeSWITCH 1269220893 1269220894 IN IP4 202.173.153.98 s=FreeSWITCH c=IN IP4 202.173.153.98 t=0 0 m=audio 23450 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:30 a=sendrecv 2010-03-22 18:52:23.659401 [NOTICE] mod_sofia.c:1904 Pre-Answer sofia/internal/1000@202.173.153.98! 2010-03-22 18:52:23.668549 [DEBUG] sofia.c:4147 Channel sofia/internal/1000@202.173.153.98 skipping state [early][183] 2010-03-22 18:52:23.684459 [DEBUG] switch_core_session.c:638 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:23.684459 [DEBUG] switch_ivr_originate.c:3148 Originate Resulted in Success: [sofia/internal/sip:1002@192.168.200.42:43658] 2010-03-22 18:52:23.684459 [NOTICE] switch_core_session.c:1179 Session 84 (OpenZAP/1:1/) Ended 2010-03-22 18:52:23.684459 [NOTICE] switch_core_session.c:1181 Close Channel OpenZAP/1:1/ [CS_DESTROY] 2010-03-22 18:52:23.684459 [DEBUG] switch_core_state_machine.c:428 (OpenZAP/1:1/) Running State Change CS_DESTROY 2010-03-22 18:52:23.684459 [DEBUG] switch_core_state_machine.c:439 (OpenZAP/1:1/) State DESTROY 2010-03-22 18:52:23.684459 [DEBUG] switch_core_state_machine.c:60 OpenZAP/1:1/ Standard DESTROY 2010-03-22 18:52:23.684459 [DEBUG] switch_core_state_machine.c:439 (OpenZAP/1:1/) State DESTROY going to sleep 2010-03-22 18:52:23.699411 [DEBUG] switch_ivr_originate.c:3148 Originate Resulted in Success: [sofia/internal/sip:1002@192.168.200.42:43658] 2010-03-22 18:52:23.705505 [DEBUG] switch_core_session.c:638 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:23.705505 [DEBUG] switch_core_session.c:638 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:23.705505 [DEBUG] switch_ivr_bridge.c:1182 (sofia/internal/sip:1002@192.168.200.42:43658) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2010-03-22 18:52:23.709595 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:23.709595 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_EXCHANGE_MEDIA 2010-03-22 18:52:23.709595 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/sip:1002@192.168.200.42:43658) State EXCHANGE_MEDIA 2010-03-22 18:52:23.709595 [DEBUG] mod_sofia.c:504 SOFIA EXCHANGE_MEDIA 2010-03-22 18:52:23.776426 [DEBUG] switch_rtp.c:2064 Correct ip/port confirmed. 2010-03-22 18:52:23.776426 [DEBUG] switch_core_io.c:896 Engaging Write Buffer at 320 bytes to accommodate 480->320 2010-03-22 18:52:24.165340 [DEBUG] ozmod_analog.c:391 Changing state on 1:1 from HANGUP to DOWN 2010-03-22 18:52:24.185341 [DEBUG] ozmod_analog.c:450 Executing state handler on 1:1 for DOWN 2010-03-22 18:52:24.185341 [DEBUG] mod_openzap.c:1593 got FXS sig [STOP] 2010-03-22 18:52:24.185341 [DEBUG] zap_io.c:1383 channel done 1:1 2010-03-22 18:52:24.185341 [DEBUG] ozmod_analog.c:764 ANALOG CHANNEL 1:1 thread ended. 2010-03-22 18:52:24.295343 [DEBUG] switch_rtp.c:2064 Correct ip/port confirmed. 2010-03-22 18:52:24.295343 [DEBUG] switch_core_io.c:896 Engaging Write Buffer at 480 bytes to accommodate 320->480 freeswitch@internal> freeswitch@internal> show cha [ channels] [ chat] freeswitch@internal> show channels uuid,direction,created,created_epoch,name,state,cid_name,cid_num,ip_addr,dest,application,application_data,dialplan,context,read_codec,read_rate,write_codec,write_rate,secure,hostname,presence_id,presence_data 994c5126-d961-4838-b642-d41060242283,inbound,2010-03-22 18:52:22,1269244342,sofia/internal/1000@202.173.153.98,CS_EXECUTE,Lounge,1000,192.168.87.13,1002,bridge,user/1002@microcomaustralia.com.au,XML,default,PCMA,8000,PCMA,8000,,huey,1000@202.173.153.98, bef34f96-bb3c-44b2-b8d8-41f5a1e7913e,outbound,2010-03-22 18:52:22,1269244342,sofia/internal/sip:1002@192.168.200.42:43658,CS_EXCHANGE_MEDIA,Lounge,1001,192.168.87.13,1002,,,XML,default,PCMA,8000,PCMA,8000,,huey,1002@microcomaustralia.com.au, 2 total. freeswitch@internal> 2010-03-22 18:52:39.786251 [DEBUG] sofia.c:4152 Channel sofia/internal/1000@202.173.153.98 entering state [terminated][487] 2010-03-22 18:52:39.786251 [NOTICE] sofia.c:4788 Hangup sofia/internal/1000@202.173.153.98 [CS_EXECUTE] [ORIGINATOR_CANCEL] 2010-03-22 18:52:39.786251 [DEBUG] switch_channel.c:2071 Send signal sofia/internal/1000@202.173.153.98 [KILL] 2010-03-22 18:52:39.786251 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:39.795756 [DEBUG] switch_ivr_bridge.c:472 sofia/internal/1000@202.173.153.98 ending bridge by request from write function 2010-03-22 18:52:39.795756 [DEBUG] switch_core_session.c:638 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:39.795756 [DEBUG] switch_ivr_bridge.c:565 BRIDGE THREAD DONE [sofia/internal/sip:1002@192.168.200.42:43658] 2010-03-22 18:52:39.795756 [DEBUG] switch_ivr_bridge.c:585 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:39.795756 [NOTICE] switch_ivr_bridge.c:637 Hangup sofia/internal/sip:1002@192.168.200.42:43658 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2010-03-22 18:52:39.795756 [DEBUG] switch_channel.c:2071 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [KILL] 2010-03-22 18:52:39.795756 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:39.795756 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/sip:1002@192.168.200.42:43658) State EXCHANGE_MEDIA going to sleep 2010-03-22 18:52:39.795756 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_HANGUP 2010-03-22 18:52:39.795756 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/sip:1002@192.168.200.42:43658) State HANGUP 2010-03-22 18:52:39.795756 [DEBUG] mod_sofia.c:405 sofia/internal/sip:1002@192.168.200.42:43658 Overriding SIP cause 480 with 487 from the other leg 2010-03-22 18:52:39.795756 [DEBUG] mod_sofia.c:411 Channel sofia/internal/sip:1002@192.168.200.42:43658 hanging up, cause: NORMAL_CLEARING 2010-03-22 18:52:39.795756 [DEBUG] switch_ivr_bridge.c:478 sofia/internal/1000@202.173.153.98 ending bridge by request from read function 2010-03-22 18:52:39.852735 [DEBUG] switch_ivr_bridge.c:565 BRIDGE THREAD DONE [sofia/internal/1000@202.173.153.98] 2010-03-22 18:52:39.852735 [DEBUG] switch_ivr_bridge.c:585 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:39.852735 [DEBUG] switch_core_state_machine.c:348 (sofia/internal/1000@202.173.153.98) State EXECUTE going to sleep 2010-03-22 18:52:39.852735 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@202.173.153.98) Running State Change CS_HANGUP 2010-03-22 18:52:39.852735 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1000@202.173.153.98) State HANGUP 2010-03-22 18:52:39.852735 [DEBUG] mod_sofia.c:405 sofia/internal/1000@202.173.153.98 Overriding SIP cause 487 with 487 from the other leg 2010-03-22 18:52:39.852735 [DEBUG] mod_sofia.c:411 Channel sofia/internal/1000@202.173.153.98 hanging up, cause: ORIGINATOR_CANCEL 2010-03-22 18:52:39.902442 [DEBUG] mod_sofia.c:464 Sending CANCEL to sofia/internal/sip:1002@192.168.200.42:43658 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1000@202.173.153.98 Standard HANGUP, cause: ORIGINATOR_CANCEL 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1000@202.173.153.98) State HANGUP going to sleep 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1000@202.173.153.98) State Change CS_HANGUP -> CS_REPORTING 2010-03-22 18:52:39.910280 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@202.173.153.98) Running State Change CS_REPORTING 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1000@202.173.153.98) State REPORTING 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1000@202.173.153.98 Standard REPORTING, cause: ORIGINATOR_CANCEL 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1000@202.173.153.98) State REPORTING going to sleep 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1000@202.173.153.98) State Change CS_REPORTING -> CS_DESTROY 2010-03-22 18:52:39.910280 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/1000@202.173.153.98 [BREAK] 2010-03-22 18:52:39.910280 [DEBUG] switch_core_session.c:1161 Session 82 (sofia/internal/1000@202.173.153.98) Locked, Waiting on external entities 2010-03-22 18:52:39.910280 [NOTICE] switch_core_session.c:1179 Session 82 (sofia/internal/1000@202.173.153.98) Ended 2010-03-22 18:52:39.910280 [NOTICE] switch_core_session.c:1181 Close Channel sofia/internal/1000@202.173.153.98 [CS_DESTROY] 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1000@202.173.153.98) Running State Change CS_DESTROY 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1000@202.173.153.98) State DESTROY 2010-03-22 18:52:39.910280 [DEBUG] mod_sofia.c:338 sofia/internal/1000@202.173.153.98 SOFIA DESTROY 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@202.173.153.98 Standard DESTROY 2010-03-22 18:52:39.910280 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1000@202.173.153.98) State DESTROY going to sleep 2010-03-22 18:52:39.925570 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1002@192.168.200.42:43658 Standard HANGUP, cause: NORMAL_CLEARING 2010-03-22 18:52:39.925570 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/sip:1002@192.168.200.42:43658) State HANGUP going to sleep 2010-03-22 18:52:39.931493 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/sip:1002@192.168.200.42:43658) State Change CS_HANGUP -> CS_REPORTING 2010-03-22 18:52:39.931493 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:39.931493 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_REPORTING 2010-03-22 18:52:39.931493 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/sip:1002@192.168.200.42:43658) State REPORTING 2010-03-22 18:52:39.931493 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1002@192.168.200.42:43658 Standard REPORTING, cause: NORMAL_CLEARING 2010-03-22 18:52:39.935435 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/sip:1002@192.168.200.42:43658) State REPORTING going to sleep 2010-03-22 18:52:39.935435 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/sip:1002@192.168.200.42:43658) State Change CS_REPORTING -> CS_DESTROY 2010-03-22 18:52:39.935435 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/sip:1002@192.168.200.42:43658 [BREAK] 2010-03-22 18:52:39.937446 [DEBUG] switch_core_session.c:1161 Session 83 (sofia/internal/sip:1002@192.168.200.42:43658) Locked, Waiting on external entities 2010-03-22 18:52:39.937446 [NOTICE] switch_core_session.c:1179 Session 83 (sofia/internal/sip:1002@192.168.200.42:43658) Ended 2010-03-22 18:52:39.937446 [NOTICE] switch_core_session.c:1181 Close Channel sofia/internal/sip:1002@192.168.200.42:43658 [CS_DESTROY] 2010-03-22 18:52:39.941335 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/sip:1002@192.168.200.42:43658) Running State Change CS_DESTROY 2010-03-22 18:52:39.941335 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/sip:1002@192.168.200.42:43658) State DESTROY 2010-03-22 18:52:39.941335 [DEBUG] mod_sofia.c:338 sofia/internal/sip:1002@192.168.200.42:43658 SOFIA DESTROY 2010-03-22 18:52:39.941335 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1002@192.168.200.42:43658 Standard DESTROY 2010-03-22 18:52:39.941335 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/sip:1002@192.168.200.42:43658) State DESTROY going to sleep -- Brian May <brian@microcomaustralia.com.au>