<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"><head><meta http-equiv=Content-Type content="text/html; charset=us-ascii"><meta name=Generator content="Microsoft Word 15 (filtered medium)"><style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";
mso-fareast-language:EN-US;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri","sans-serif";
mso-fareast-language:EN-US;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]--></head><body lang=EN-CA link="#0563C1" vlink="#954F72"><div class=WordSection1><p class=MsoNormal>We have an Extension that if we call we cannot speak to the person it goes directly to voicemail. We cannot seem to determine why it is doing this. Any suggestion would be welcomed. I have a copy of the log for the call and highlighted the sections which may indicate an issue. <o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>Thanks <o:p></o:p></p><p class=MsoNormal>Cjb<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>***********************************************************<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 parsing [default->local_extension] continue=false <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Regex (PASS) [local_extension] destination_number(104) =~ /(^\d{2,7}$)/ break=on-false <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(dialed_extension=104) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action export(dialed_extension=104) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action limit(hash ${domain_name} 104 ${limit_max} ${limit_destination}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(1 b s execute_extension::dx XML features) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.wav) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(3 b s execute_extension::cf XML features) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(ringback=${us-ring}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(transfer_ringback=local_stream://moh) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(call_timeout=30) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(hangup_after_bridge=true) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(continue_on_fail=true) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action bridge(user/${user_data(${destination_number}@${domain_name} attr id)}@${domain_name}) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action answer() <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action sleep(1000) <o:p></o:p></p><p class=MsoNormal>Dialplan: sofia/internal/100@192.168.30.100:5060 Action voicemail(default ${domain_name} ${dialed_extension}) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/100@192.168.30.100:5060) State Change CS_ROUTING -> CS_EXECUTE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/100@192.168.30.100:5060) State ROUTING going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/100@192.168.30.100:5060) Running State Change CS_EXECUTE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/100@192.168.30.100:5060) State EXECUTE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] mod_sofia.c:230 sofia/internal/100@192.168.30.100:5060 SOFIA EXECUTE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:209 sofia/internal/100@192.168.30.100:5060 Standard EXECUTE <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(call_direction=local) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [call_direction]=[local] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-spymap/100/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf) <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/100/104) <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/global/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf) <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(RFC2822_DATE=Wed, 18 Sep 2013 16:50:26 -0300) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [RFC2822_DATE]=[Wed, 18 Sep 2013 16:50:26 -0300] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(dialed_extension=104) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [dialed_extension]=[104] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 export(dialed_extension=104) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) [dialed_extension]=[104] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 limit(hash 192.168.30.100 104 5 ) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [INFO] switch_limit.c:126 incr called: 192.168.30.100_104 max:5, interval:0 <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [INFO] mod_hash.c:202 Usage for 192.168.30.100_104 is now 1/5 <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(1 b s execute_extension::dx XML features) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.133173 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *1 execute_extension::dx XML features <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/archive/2013/Sep/18/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf.wav) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/archive/2013/Sep/18/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf.wav <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(3 b s execute_extension::cf XML features) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *3 execute_extension::cf XML features <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *4 execute_extension::att_xfer XML features <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(ringback=%(2000, 4000, 440.0, 480.0)) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [ringback]=[%(2000, 4000, 440.0, 480.0)] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(transfer_ringback=local_stream://moh) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [transfer_ringback]=[local_stream://moh] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(call_timeout=30) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [call_timeout]=[30] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(hangup_after_bridge=true) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [hangup_after_bridge]=[true] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(continue_on_fail=true) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [continue_on_fail]=[true] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-call_return/104/100) <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial_ext/104/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf) <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 set(called_party_call_group=sales, support, billing) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [called_party_call_group]=[sales, support, billing] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/sales, support, billing/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf) <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 bridge(user/104@192.168.30.100) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_channel.c:1176 sofia/internal/100@192.168.30.100:5060 EXPORTING[export_vars] [domain_name]=[192.168.30.100] to event <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_channel.c:1176 sofia/internal/100@192.168.30.100:5060 EXPORTING[export_vars] [dialed_extension]=[104] to event <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_ivr_originate.c:2050 Parsing global variables <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_channel.c:1176 sofia/internal/100@192.168.30.100:5060 EXPORTING[export_vars] [domain_name]=[192.168.30.100] to event <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_channel.c:1176 sofia/internal/100@192.168.30.100:5060 EXPORTING[export_vars] [dialed_extension]=[104] to event <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_ivr_originate.c:2050 Parsing global variables <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_event.c:1615 Parsing variable [sip_invite_domain]=[192.168.30.100] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_event.c:1615 Parsing variable [presence_id]=[104@192.168.30.100] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [NOTICE] switch_channel.c:1030 New Channel sofia/internal/sip:104@192.168.2.56:5060 [ab4e9db4-127b-4683-9844-6d631f9f8d35] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:4438 (sofia/internal/sip:104@192.168.2.56:5060) State Change CS_NEW -> CS_INIT <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104@192.168.2.56:5060) Running State Change CS_INIT <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:104@192.168.2.56:5060) State INIT <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:87 sofia/internal/sip:104@192.168.2.56:5060 SOFIA INIT <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] sofia_glue.c:1220 Local SDP: <o:p></o:p></p><p class=MsoNormal>v=0 <o:p></o:p></p><p class=MsoNormal>o=FreeSWITCH 1379503966 1379503967 IN IP4 192.168.30.100 <o:p></o:p></p><p class=MsoNormal>s=FreeSWITCH <o:p></o:p></p><p class=MsoNormal>c=IN IP4 192.168.30.100 <o:p></o:p></p><p class=MsoNormal><span lang=FR-CA>t=0 0 <o:p></o:p></span></p><p class=MsoNormal><span lang=FR-CA>m=audio 29860 RTP/AVP 0 9 8 3 101 13 <o:p></o:p></span></p><p class=MsoNormal>a=rtpmap:101 telephone-event/8000 <o:p></o:p></p><p class=MsoNormal>a=fmtp:101 0-16 <o:p></o:p></p><p class=MsoNormal>a=ptime:20 <o:p></o:p></p><p class=MsoNormal>a=sendrecv <o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:114 (sofia/internal/sip:104@192.168.2.56:5060) State Change CS_INIT -> CS_ROUTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:104@192.168.2.56:5060) State INIT going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104@192.168.2.56:5060) Running State Change CS_ROUTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:104@192.168.2.56:5060) State ROUTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:137 sofia/internal/sip:104@192.168.2.56:5060 SOFIA ROUTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:104@192.168.2.56:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:104@192.168.2.56:5060) State ROUTING going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104@192.168.2.56:5060) Running State Change CS_CONSUME_MEDIA <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:104@192.168.2.56:5060) State CONSUME_MEDIA <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:104@192.168.2.56:5060) State CONSUME_MEDIA going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:26.153076 [DEBUG] sofia.c:5793 Channel sofia/internal/sip:104@192.168.2.56:5060 entering state [calling][0] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:27.193099 [DEBUG] sofia_reg.c:2224 Changing expire time to 600 by request of proxy sip:sip-slb.voicemeup.com <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] sofia.c:5793 Channel sofia/internal/sip:104@192.168.2.56:5060 entering state [terminated][503] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [NOTICE] sofia.c:6601 Hangup sofia/internal/sip:104@192.168.2.56:5060 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_channel.c:3135 Send signal sofia/internal/sip:104@192.168.2.56:5060 [KILL] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104@192.168.2.56:5060) Running State Change CS_HANGUP <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:104@192.168.2.56:5060) State HANGUP <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] mod_sofia.c:463 Channel sofia/internal/sip:104@192.168.2.56:5060 hanging up, cause: NORMAL_TEMPORARY_FAILURE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:104@192.168.2.56:5060 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:104@192.168.2.56:5060) State HANGUP going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:692 (sofia/internal/sip:104@192.168.2.56:5060) Callstate Change DOWN -> HANGUP <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/sip:104@192.168.2.56:5060) State Change CS_HANGUP -> CS_REPORTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104@192.168.2.56:5060) Running State Change CS_REPORTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:104@192.168.2.56:5060) State REPORTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:104@192.168.2.56:5060 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/sip:104@192.168.2.56:5060) State REPORTING going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/sip:104@192.168.2.56:5060) State Change CS_REPORTING -> CS_DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/sip:104@192.168.2.56:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>2013-09-18 16:50:29.153119 [DEBUG] switch_core_session.c:1549 Session 305 (sofia/internal/sip:104@192.168.2.56:5060) Locked, Waiting on external entities</span> <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_ivr_originate.c:3622 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [NOTICE] switch_core_session.c:1567 Session 305 (sofia/internal/sip:104@192.168.2.56:5060) Ended <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [NOTICE] switch_core_session.c:1571 Close Channel sofia/internal/sip:104@192.168.2.56:5060 [CS_DESTROY] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/sip:104@192.168.2.56:5060) Callstate Change HANGUP -> DOWN <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:104@192.168.2.56:5060) Running State Change CS_DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:104@192.168.2.56:5060) State DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] mod_sofia.c:373 sofia/internal/sip:104@192.168.2.56:5060 SOFIA DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:104@192.168.2.56:5060 Standard DESTROY <o:p></o:p></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>2013-09-18 16:50:29.173113 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:104@192.168.2.56:5060) State DESTROY going to sleep <o:p></o:p></span></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>2013-09-18 16:50:29.173113 [NOTICE] switch_ivr_originate.c:2651 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]</span> <o:p></o:p></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>2013-09-18 16:50:29.173113 [DEBUG] switch_ivr_originate.c:3622 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] <o:p></o:p></span></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>2013-09-18 16:50:29.173113 [INFO] mod_dptools.c:3173 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE</span> <o:p></o:p></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>EXECUTE sofia/internal/100@192.168.30.100:5060 answer()</span> <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_core_media.c:3986 AUDIO RTP [sofia/internal/100@192.168.30.100:5060] 192.168.30.100 port 25442 -> 192.168.30.50 port 16430 codec: 0 ms: 20 <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.173113 [DEBUG] switch_rtp.c:2885 Starting timer [soft] 160 bytes per 20ms <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_media.c:4320 Set 2833 dtmf send payload to 101 <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_media.c:4326 Set 2833 dtmf receive payload to 101 <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] mod_sofia.c:822 Local SDP sofia/internal/100@192.168.30.100:5060: <o:p></o:p></p><p class=MsoNormal>v=0 <o:p></o:p></p><p class=MsoNormal>o=FreeSWITCH 1379508387 1379508388 IN IP4 192.168.30.100 <o:p></o:p></p><p class=MsoNormal>s=FreeSWITCH <o:p></o:p></p><p class=MsoNormal>c=IN IP4 192.168.30.100 <o:p></o:p></p><p class=MsoNormal><span lang=FR-CA>t=0 0 <o:p></o:p></span></p><p class=MsoNormal><span lang=FR-CA>m=audio 25442 RTP/AVP 0 101 <o:p></o:p></span></p><p class=MsoNormal>a=rtpmap:0 PCMU/8000 <o:p></o:p></p><p class=MsoNormal>a=rtpmap:101 telephone-event/8000 <o:p></o:p></p><p class=MsoNormal>a=fmtp:101 0-16 <o:p></o:p></p><p class=MsoNormal>a=silenceSupp:off - - - - <o:p></o:p></p><p class=MsoNormal>a=ptime:20 <o:p></o:p></p><p class=MsoNormal>a=sendrecv <o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:861 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [NOTICE] mod_dptools.c:1206 Channel [sofia/internal/100@192.168.30.100:5060] has been answered <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_channel.c:3595 (sofia/internal/100@192.168.30.100:5060) Callstate Change RINGING -> ACTIVE <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] sofia.c:5793 Channel sofia/internal/100@192.168.30.100:5060 entering state [completed][200] <o:p></o:p></p><p class=MsoNormal>EXECUTE sofia/internal/100@192.168.30.100:5060 sleep(1000) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.213115 [DEBUG] sofia.c:5793 Channel sofia/internal/100@192.168.30.100:5060 entering state [ready][200] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:29.233215 [DEBUG] switch_rtp.c:4926 Correct ip/port confirmed. <o:p></o:p></p><p class=MsoNormal><span style='background:yellow;mso-highlight:yellow'>EXECUTE sofia/internal/100@192.168.30.100:5060 voicemail(default 192.168.30.100 104)</span> <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:30.313134 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:30.313134 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:30.313134 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:31.673132 [DEBUG] switch_ivr_play_say.c:1704 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:31.773134 [DEBUG] switch_ivr_play_say.c:251 Handle say:[104] (en:en) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:31.773134 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:33.453122 [DEBUG] switch_ivr_play_say.c:1704 done playing file file_string://digits/1.wav!digits/0.wav!digits/4.wav <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:33.553123 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:33.553123 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:34.533112 [DEBUG] switch_ivr_play_say.c:1704 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:34.633211 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:34.633211 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:34.633211 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.893133 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [NOTICE] sofia.c:715 Hangup sofia/internal/100@192.168.30.100:5060 [CS_EXECUTE] [NORMAL_CLEARING] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_channel.c:3135 Send signal sofia/internal/100@192.168.30.100:5060 [KILL] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [INFO] mod_hash.c:304 Usage for 192.168.30.100_104 is now 0 <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_ivr_play_say.c:1704 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:2743 sofia/internal/100@192.168.30.100:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/100@192.168.30.100:5060) State EXECUTE going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/100@192.168.30.100:5060) Running State Change CS_HANGUP <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/100@192.168.30.100:5060) State HANGUP <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] mod_sofia.c:457 sofia/internal/100@192.168.30.100:5060 Overriding SIP cause 480 with 503 from the other leg <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] mod_sofia.c:463 Channel sofia/internal/100@192.168.30.100:5060 hanging up, cause: NORMAL_CLEARING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:48 sofia/internal/100@192.168.30.100:5060 Standard HANGUP, cause: NORMAL_CLEARING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/100@192.168.30.100:5060) State HANGUP going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:692 (sofia/internal/100@192.168.30.100:5060) Callstate Change ACTIVE -> HANGUP <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/100@192.168.30.100:5060) State Change CS_HANGUP -> CS_REPORTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/100@192.168.30.100:5060) Running State Change CS_REPORTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/100@192.168.30.100:5060) State REPORTING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:92 sofia/internal/100@192.168.30.100:5060 Standard REPORTING, cause: NORMAL_CLEARING <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/100@192.168.30.100:5060) State REPORTING going to sleep <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/100@192.168.30.100:5060) State Change CS_REPORTING -> CS_DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1549 Session 304 (sofia/internal/100@192.168.30.100:5060) Locked, Waiting on external entities <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [NOTICE] switch_core_session.c:1567 Session 304 (sofia/internal/100@192.168.30.100:5060) Ended <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [NOTICE] switch_core_session.c:1571 Close Channel sofia/internal/100@192.168.30.100:5060 [CS_DESTROY] <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/100@192.168.30.100:5060) Callstate Change HANGUP -> DOWN <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/100@192.168.30.100:5060) Running State Change CS_DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/100@192.168.30.100:5060) State DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] mod_sofia.c:373 sofia/internal/100@192.168.30.100:5060 SOFIA DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:99 sofia/internal/100@192.168.30.100:5060 Standard DESTROY <o:p></o:p></p><p class=MsoNormal>2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/100@192.168.30.100:5060) State DESTROY going to sleep<o:p></o:p></p></div></body></html>