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.
Thanks
Cjb
***********************************************************
Dialplan: sofia/internal/100@192.168.30.100:5060 parsing [default->local_extension] continue=false
Dialplan: sofia/internal/100@192.168.30.100:5060 Regex (PASS) [local_extension] destination_number(104) =~ /(^\d{2,7}$)/ break=on-false
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(dialed_extension=104)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action export(dialed_extension=104)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action limit(hash ${domain_name} 104 ${limit_max} ${limit_destination})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(1 b s execute_extension::dx XML features)
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)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(ringback=${us-ring})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(call_timeout=30)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(continue_on_fail=true)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action bridge(user/${user_data(${destination_number}@${domain_name} attr id)}@${domain_name})
Dialplan: sofia/internal/100@192.168.30.100:5060 Action answer()
Dialplan: sofia/internal/100@192.168.30.100:5060 Action sleep(1000)
Dialplan: sofia/internal/100@192.168.30.100:5060 Action voicemail(default ${domain_name} ${dialed_extension})
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
2013-09-18 16:50:26.133173 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
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
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
2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/100@192.168.30.100:5060) State EXECUTE
2013-09-18 16:50:26.133173 [DEBUG] mod_sofia.c:230 sofia/internal/100@192.168.30.100:5060 SOFIA EXECUTE
2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:209 sofia/internal/100@192.168.30.100:5060 Standard EXECUTE
EXECUTE sofia/internal/100@192.168.30.100:5060 set(call_direction=local)
2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [call_direction]=[local]
EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-spymap/100/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf)
EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/100/104)
EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/global/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf)
EXECUTE sofia/internal/100@192.168.30.100:5060 set(RFC2822_DATE=Wed, 18 Sep 2013 16:50:26 -0300)
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]
EXECUTE sofia/internal/100@192.168.30.100:5060 set(dialed_extension=104)
2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [dialed_extension]=[104]
EXECUTE sofia/internal/100@192.168.30.100:5060 export(dialed_extension=104)
2013-09-18 16:50:26.133173 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) [dialed_extension]=[104]
EXECUTE sofia/internal/100@192.168.30.100:5060 limit(hash 192.168.30.100 104 5 )
2013-09-18 16:50:26.133173 [INFO] switch_limit.c:126 incr called: 192.168.30.100_104 max:5, interval:0
2013-09-18 16:50:26.133173 [INFO] mod_hash.c:202 Usage for 192.168.30.100_104 is now 1/5
EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(1 b s execute_extension::dx XML features)
2013-09-18 16:50:26.133173 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *1 execute_extension::dx XML features
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)
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
EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(3 b s execute_extension::cf XML features)
2013-09-18 16:50:26.153076 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/100@192.168.30.100:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2013-09-18 16:50:26.153076 [INFO] switch_ivr_async.c:3628 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/100@192.168.30.100:5060 set(ringback=%(2000, 4000, 440.0, 480.0))
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)]
EXECUTE sofia/internal/100@192.168.30.100:5060 set(transfer_ringback=local_stream://moh)
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]
EXECUTE sofia/internal/100@192.168.30.100:5060 set(call_timeout=30)
2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100@192.168.30.100:5060 SET [call_timeout]=[30]
EXECUTE sofia/internal/100@192.168.30.100:5060 set(hangup_after_bridge=true)
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]
EXECUTE sofia/internal/100@192.168.30.100:5060 set(continue_on_fail=true)
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]
EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-call_return/104/100)
EXECUTE sofia/internal/100@192.168.30.100:5060 hash(insert/192.168.30.100-last_dial_ext/104/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf)
EXECUTE sofia/internal/100@192.168.30.100:5060 set(called_party_call_group=sales, support, billing)
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]
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)
EXECUTE sofia/internal/100@192.168.30.100:5060 bridge(user/104@192.168.30.100)
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
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
2013-09-18 16:50:26.153076 [DEBUG] switch_ivr_originate.c:2050 Parsing global variables
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
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
2013-09-18 16:50:26.153076 [DEBUG] switch_ivr_originate.c:2050 Parsing global variables
2013-09-18 16:50:26.153076 [DEBUG] switch_event.c:1615 Parsing variable [sip_invite_domain]=[192.168.30.100]
2013-09-18 16:50:26.153076 [DEBUG] switch_event.c:1615 Parsing variable [presence_id]=[104@192.168.30.100]
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]
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
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]
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
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
2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:87 sofia/internal/sip:104@192.168.2.56:5060 SOFIA INIT
2013-09-18 16:50:26.153076 [DEBUG] sofia_glue.c:1220 Local SDP:
v=0
o=FreeSWITCH 1379503966 1379503967 IN IP4 192.168.30.100
s=FreeSWITCH
c=IN IP4 192.168.30.100
t=0 0
m=audio 29860 RTP/AVP 0 9 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
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
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]
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
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]
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
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
2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:137 sofia/internal/sip:104@192.168.2.56:5060 SOFIA ROUTING
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
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]
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
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
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
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
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]
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
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]
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]
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]
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]
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]
2013-09-18 16:50:29.153119 [DEBUG] switch_channel.c:3135 Send signal sofia/internal/sip:104@192.168.2.56:5060 [KILL]
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]
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
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
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
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
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
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
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
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]
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
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
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
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
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
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]
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
2013-09-18 16:50:29.173113 [DEBUG] switch_ivr_originate.c:3622 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
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
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]
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
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
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
2013-09-18 16:50:29.173113 [DEBUG] mod_sofia.c:373 sofia/internal/sip:104@192.168.2.56:5060 SOFIA DESTROY
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
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
2013-09-18 16:50:29.173113 [NOTICE] switch_ivr_originate.c:2651 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]
2013-09-18 16:50:29.173113 [DEBUG] switch_ivr_originate.c:3622 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2013-09-18 16:50:29.173113 [INFO] mod_dptools.c:3173 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
EXECUTE sofia/internal/100@192.168.30.100:5060 answer()
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
2013-09-18 16:50:29.173113 [DEBUG] switch_rtp.c:2885 Starting timer [soft] 160 bytes per 20ms
2013-09-18 16:50:29.193168 [DEBUG] switch_core_media.c:4320 Set 2833 dtmf send payload to 101
2013-09-18 16:50:29.193168 [DEBUG] switch_core_media.c:4326 Set 2833 dtmf receive payload to 101
2013-09-18 16:50:29.193168 [DEBUG] mod_sofia.c:822 Local SDP sofia/internal/100@192.168.30.100:5060:
v=0
o=FreeSWITCH 1379508387 1379508388 IN IP4 192.168.30.100
s=FreeSWITCH
c=IN IP4 192.168.30.100
t=0 0
m=audio 25442 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
2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:861 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
2013-09-18 16:50:29.193168 [NOTICE] mod_dptools.c:1206 Channel [sofia/internal/100@192.168.30.100:5060] has been answered
2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
2013-09-18 16:50:29.193168 [DEBUG] switch_channel.c:3595 (sofia/internal/100@192.168.30.100:5060) Callstate Change RINGING -> ACTIVE
2013-09-18 16:50:29.193168 [DEBUG] sofia.c:5793 Channel sofia/internal/100@192.168.30.100:5060 entering state [completed][200]
EXECUTE sofia/internal/100@192.168.30.100:5060 sleep(1000)
2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
2013-09-18 16:50:29.213115 [DEBUG] sofia.c:5793 Channel sofia/internal/100@192.168.30.100:5060 entering state [ready][200]
2013-09-18 16:50:29.233215 [DEBUG] switch_rtp.c:4926 Correct ip/port confirmed.
EXECUTE sofia/internal/100@192.168.30.100:5060 voicemail(default 192.168.30.100 104)
2013-09-18 16:50:30.313134 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2013-09-18 16:50:30.313134 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en)
2013-09-18 16:50:30.313134 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
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
2013-09-18 16:50:31.773134 [DEBUG] switch_ivr_play_say.c:251 Handle say:[104] (en:en)
2013-09-18 16:50:31.773134 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
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
2013-09-18 16:50:33.553123 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en)
2013-09-18 16:50:33.553123 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
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
2013-09-18 16:50:34.633211 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2013-09-18 16:50:34.633211 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en)
2013-09-18 16:50:34.633211 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
2013-09-18 16:50:35.893133 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
2013-09-18 16:50:35.913133 [NOTICE] sofia.c:715 Hangup sofia/internal/100@192.168.30.100:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2013-09-18 16:50:35.913133 [DEBUG] switch_channel.c:3135 Send signal sofia/internal/100@192.168.30.100:5060 [KILL]
2013-09-18 16:50:35.913133 [INFO] mod_hash.c:304 Usage for 192.168.30.100_104 is now 0
2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
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
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)
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
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
2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/100@192.168.30.100:5060) State HANGUP
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
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
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
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
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
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
2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
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
2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/100@192.168.30.100:5060) State REPORTING
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
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
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
2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/100@192.168.30.100:5060 [BREAK]
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
2013-09-18 16:50:35.913133 [NOTICE] switch_core_session.c:1567 Session 304 (sofia/internal/100@192.168.30.100:5060) Ended
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]
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
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
2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/100@192.168.30.100:5060) State DESTROY
2013-09-18 16:50:35.913133 [DEBUG] mod_sofia.c:373 sofia/internal/100@192.168.30.100:5060 SOFIA DESTROY
2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:99 sofia/internal/100@192.168.30.100:5060 Standard DESTROY
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