[Freeswitch-users] Newbie- problem with 1 Ext going directly to Voicemail

Thu Sep 19 00:20:37 MSD 2013

turn on sip trace to find out more.. but the first indication of failure is this line:

2013-09-18 16:50:29.153119 [DEBUG] sofia.c:5793 Channel sofia/internal/sip:104 at 192.168.2.56:5060 entering state [terminated][503]

On Sep 18, 2013, at 4:08 PM, Charles Bujold <cjbujold at accra.ca> wrote:

> 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 at 192.168.30.100:5060 parsing [default->local_extension] continue=false
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Regex (PASS) [local_extension] destination_number(104) =~ /(^\d{2,7}$)/ break=on-false
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(dialed_extension=104)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action export(dialed_extension=104)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action limit(hash ${domain_name} 104 ${limit_max} ${limit_destination})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action bind_meta_app(1 b s execute_extension::dx XML features)
> Dialplan: sofia/internal/100 at 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 at 192.168.30.100:5060 Action bind_meta_app(3 b s execute_extension::cf XML features)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(ringback=${us-ring})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(transfer_ringback=local_stream://moh)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(call_timeout=30)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(hangup_after_bridge=true)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(continue_on_fail=true)
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action bridge(user/${user_data(${destination_number}@${domain_name} attr id)}@${domain_name})
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action answer()
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action sleep(1000)
> Dialplan: sofia/internal/100 at 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 at 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 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/100 at 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 at 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 at 192.168.30.100:5060) State EXECUTE
> 2013-09-18 16:50:26.133173 [DEBUG] mod_sofia.c:230 sofia/internal/100 at 192.168.30.100:5060 SOFIA EXECUTE
> 2013-09-18 16:50:26.133173 [DEBUG] switch_core_state_machine.c:209 sofia/internal/100 at 192.168.30.100:5060 Standard EXECUTE
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 set(call_direction=local)
> 2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100 at 192.168.30.100:5060 SET [call_direction]=[local]
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 hash(insert/192.168.30.100-spymap/100/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf)
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/100/104)
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 hash(insert/192.168.30.100-last_dial/global/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf)
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 SET [RFC2822_DATE]=[Wed, 18 Sep 2013 16:50:26 -0300]
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 set(dialed_extension=104)
> 2013-09-18 16:50:26.133173 [DEBUG] mod_dptools.c:1374 sofia/internal/100 at 192.168.30.100:5060 SET [dialed_extension]=[104]
> EXECUTE sofia/internal/100 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.30.100:5060 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 SET [transfer_ringback]=[local_stream://moh]
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 set(call_timeout=30)
> 2013-09-18 16:50:26.153076 [DEBUG] mod_dptools.c:1374 sofia/internal/100 at 192.168.30.100:5060 SET [call_timeout]=[30]
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 SET [hangup_after_bridge]=[true]
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 SET [continue_on_fail]=[true]
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 hash(insert/192.168.30.100-call_return/104/100)
> EXECUTE sofia/internal/100 at 192.168.30.100:5060 hash(insert/192.168.30.100-last_dial_ext/104/1481c571-0ba5-4ef0-8649-3ab9f7aecdbf)
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 SET [called_party_call_group]=[sales, support, billing]
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 bridge(user/104 at 192.168.30.100)
> 2013-09-18 16:50:26.153076 [DEBUG] switch_channel.c:1176 sofia/internal/100 at 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 at 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 at 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 at 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 at 192.168.30.100]
> 2013-09-18 16:50:26.153076 [NOTICE] switch_channel.c:1030 New Channel sofia/internal/sip:104 at 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 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104 at 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 at 192.168.2.56:5060) State INIT
> 2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:87 sofia/internal/sip:104 at 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 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:104 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104 at 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 at 192.168.2.56:5060) State ROUTING
> 2013-09-18 16:50:26.153076 [DEBUG] mod_sofia.c:137 sofia/internal/sip:104 at 192.168.2.56:5060 SOFIA ROUTING
> 2013-09-18 16:50:26.153076 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:104 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:26.153076 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:104 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:29.153119 [DEBUG] sofia.c:5793 Channel sofia/internal/sip:104 at 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 at 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 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104 at 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 at 192.168.2.56:5060) State HANGUP
> 2013-09-18 16:50:29.153119 [DEBUG] mod_sofia.c:463 Channel sofia/internal/sip:104 at 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 at 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 at 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 at 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 at 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 at 192.168.2.56:5060 [BREAK]
> 2013-09-18 16:50:29.153119 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:104 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.2.56:5060) State DESTROY
> 2013-09-18 16:50:29.173113 [DEBUG] mod_sofia.c:373 sofia/internal/sip:104 at 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 at 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 at 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 at 192.168.30.100:5060 answer()
> 2013-09-18 16:50:29.173113 [DEBUG] switch_core_media.c:3986 AUDIO RTP [sofia/internal/100 at 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 at 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 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:29.193168 [NOTICE] mod_dptools.c:1206 Channel [sofia/internal/100 at 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 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:29.193168 [DEBUG] switch_channel.c:3595 (sofia/internal/100 at 192.168.30.100:5060) Callstate Change RINGING -> ACTIVE
> 2013-09-18 16:50:29.193168 [DEBUG] sofia.c:5793 Channel sofia/internal/100 at 192.168.30.100:5060 entering state [completed][200]
> EXECUTE sofia/internal/100 at 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 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:29.193168 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:29.213115 [DEBUG] sofia.c:5793 Channel sofia/internal/100 at 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 at 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 at 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 at 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 at 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 at 8000hz 1 channels 20ms
> 2013-09-18 16:50:35.893133 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/100 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:35.913133 [NOTICE] sofia.c:715 Hangup sofia/internal/100 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.30.100:5060) State HANGUP
> 2013-09-18 16:50:35.913133 [DEBUG] mod_sofia.c:457 sofia/internal/100 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/100 at 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 at 192.168.30.100:5060) State REPORTING
> 2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:92 sofia/internal/100 at 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 at 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 at 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 at 192.168.30.100:5060 [BREAK]
> 2013-09-18 16:50:35.913133 [DEBUG] switch_core_session.c:1549 Session 304 (sofia/internal/100 at 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 at 192.168.30.100:5060) Ended
> 2013-09-18 16:50:35.913133 [NOTICE] switch_core_session.c:1571 Close Channel sofia/internal/100 at 192.168.30.100:5060 [CS_DESTROY]
> 2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/100 at 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 at 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 at 192.168.30.100:5060) State DESTROY
> 2013-09-18 16:50:35.913133 [DEBUG] mod_sofia.c:373 sofia/internal/100 at 192.168.30.100:5060 SOFIA DESTROY
> 2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:99 sofia/internal/100 at 192.168.30.100:5060 Standard DESTROY
> 2013-09-18 16:50:35.913133 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/100 at 192.168.30.100:5060) State DESTROY going to sleep

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20130918/1ce4cee4/attachment-0001.html 