Newbie- problem with 1 Ext going directly to Voicemail
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)}/${s trftime(%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_numbe r}) 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-3ab9f7ae cdbf) 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/1481c57 1-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/1481c57 1-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-3ab9f7a ecdbf) 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
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@192.168.2.56:5060 entering state [terminated][503] On Sep 18, 2013, at 4:08 PM, Charles Bujold <cjbujold@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@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
participants (2)
-
Charles Bujold
-
Michael Jerris