secret
Created

Dial issue with park_after_bridge=true and hangup_after_bridge=false

  • Download Gist
ahn_dial-2.log
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85
[2013-03-07 11:27:34] INFO Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2013-03-07 11:27:35] INFO Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2013-03-07 11:27:35] DEBUG Punchblock::Connection::Freeswitch: Starting the RubyFS stream
[2013-03-07 11:27:35] DEBUG RubyFS::Stream: Starting up...
[2013-03-07 11:27:35] INFO Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2013-03-07 11:27:35] INFO Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2013-03-07 11:27:35] INFO Adhearsion::Initializer: Adhearsion v2.2.1 initialized in "development"!
[2013-03-07 11:28:15] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="3@10.0.0.12", from=" <1000@10.0.0.10>", headers={:x_variable_direction=>"inbound", :x_variable_uuid=>"3f7d4ece-8733-11e2-aeee-8d859806bb64", :x_variable_session_id=>"1", :x_variable_sip_from_user=>"1000", :x_variable_sip_from_uri=>"1000@10.0.0.10", :x_variable_sip_from_host=>"10.0.0.10", :x_variable_channel_name=>"sofia/internal/1000@10.0.0.10", :x_variable_sip_call_id=>"f0f8f013-01d4-1231-1099-08002715f81e", :x_variable_sip_local_network_addr=>"10.0.0.12", :x_variable_sip_network_ip=>"10.0.0.10", :x_variable_sip_network_port=>"5080", :x_variable_sip_received_ip=>"10.0.0.10", :x_variable_sip_received_port=>"5080", :x_variable_sip_via_protocol=>"udp", :x_variable_sip_authorized=>"true", :x_variable_sip_acl_authed_by=>"domains", :x_variable_sip_from_user_stripped=>"1000", :x_variable_sip_from_tag=>"0H0362SN61jma", :x_variable_sofia_profile_name=>"internal", :x_variable_recovery_profile_name=>"internal", :x_variable_sip_remote_party_id=>"\"Extension 1000\" <sip:1000@10.0.0.10>;party=calling;screen=yes;privacy=off", :x_variable_sip_cid_type=>"rpid", :x_variable_sip_full_via=>"SIP/2.0/UDP 10.0.0.10:5080;rport=5080;branch=z9hG4bKSa4QtFSD3pDrS", :x_variable_sip_from_display=>"Extension 1000", :x_variable_sip_full_from=>"\"Extension 1000\" <sip:1000@10.0.0.10>;tag=0H0362SN61jma", :x_variable_sip_full_to=>"<sip:3@10.0.0.12>", :x_variable_sip_req_user=>"3", :x_variable_sip_req_uri=>"3@10.0.0.12", :x_variable_sip_req_host=>"10.0.0.12", :x_variable_sip_to_user=>"3", :x_variable_sip_to_uri=>"3@10.0.0.12", :x_variable_sip_to_host=>"10.0.0.12", :x_variable_sip_contact_params=>"transport=udp;gw=ivr_engine_out", :x_variable_sip_contact_user=>"gw+ivr_engine_out", :x_variable_sip_contact_port=>"5080", :x_variable_sip_contact_uri=>"gw+ivr_engine_out@10.0.0.10:5080", :x_variable_sip_contact_host=>"10.0.0.10", :x_variable_sip_user_agent=>"FreeSWITCH-mod_sofia/1.3.10b+git~20121210T195225Z~7ba3dadcd8", :x_variable_sip_via_host=>"10.0.0.10", :x_variable_sip_via_port=>"5080", :x_variable_sip_via_rport=>"5080", :x_variable_max_forwards=>"69", :x_variable_presence_id=>"1000@10.0.0.10", :x_variable_switch_r_sdp=>"v=0\r\no=- 3571654774 3571654774 IN IP4 10.0.0.3\r\ns=pjmedia\r\nc=IN IP4 10.0.0.3\r\nt=0 0\r\nm=audio 4072 RTP/AVP 18 102 105 8 101\r\nc=IN IP4 10.0.0.3\r\na=rtpmap:18 G729/8000\r\na=fmtp:18 annexb=no\r\na=rtpmap:102 ILBC/8000\r\na=fmtp:102 mode=30\r\na=rtpmap:105 speex/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=rtcp:4073 IN IP4 10.0.0.3\r\n", :x_variable_ep_codec_string=>"PCMA@8000h@20i@64000b", :x_variable_endpoint_disposition=>"DELAYED NEGOTIATION", :x_variable_dp_match=>"DELAYED NEGOTIATIONDELAYED NEGOTIATION", :x_variable_call_uuid=>"3f7d4ece-8733-11e2-aeee-8d859806bb64", :x_variable_open=>"true", :x_variable_rfc2822_date=>"Thu, 07 Mar 2013 11:28:15 -0300", :x_variable_export_vars=>"RFC2822_DATE", :x_variable_hangup_after_bridge=>"false", :x_variable_park_after_bridge=>"true", :x_variable_current_application=>"park"}, call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64"
[2013-03-07 11:28:15] INFO Adhearsion::Router: Call 3f7d4ece-8733-11e2-aeee-8d859806bb64 selected route "Inbound Call" (IvrController)
[2013-03-07 11:28:15] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:15] INFO Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing controller #<IvrController call=3f7d4ece-8733-11e2-aeee-8d859806bb64, metadata={}>
[2013-03-07 11:28:15] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::Offer to="3@10.0.0.12", from=" <1000@10.0.0.10>", headers={:x_variable_direction=>"inbound", :x_variable_uuid=>"3f7d4ece-8733-11e2-aeee-8d859806bb64", :x_variable_session_id=>"1", :x_variable_sip_from_user=>"1000", :x_variable_sip_from_uri=>"1000@10.0.0.10", :x_variable_sip_from_host=>"10.0.0.10", :x_variable_channel_name=>"sofia/internal/1000@10.0.0.10", :x_variable_sip_call_id=>"f0f8f013-01d4-1231-1099-08002715f81e", :x_variable_sip_local_network_addr=>"10.0.0.12", :x_variable_sip_network_ip=>"10.0.0.10", :x_variable_sip_network_port=>"5080", :x_variable_sip_received_ip=>"10.0.0.10", :x_variable_sip_received_port=>"5080", :x_variable_sip_via_protocol=>"udp", :x_variable_sip_authorized=>"true", :x_variable_sip_acl_authed_by=>"domains", :x_variable_sip_from_user_stripped=>"1000", :x_variable_sip_from_tag=>"0H0362SN61jma", :x_variable_sofia_profile_name=>"internal", :x_variable_recovery_profile_name=>"internal", :x_variable_sip_remote_party_id=>"\"Extension 1000\" <sip:1000@10.0.0.10>;party=calling;screen=yes;privacy=off", :x_variable_sip_cid_type=>"rpid", :x_variable_sip_full_via=>"SIP/2.0/UDP 10.0.0.10:5080;rport=5080;branch=z9hG4bKSa4QtFSD3pDrS", :x_variable_sip_from_display=>"Extension 1000", :x_variable_sip_full_from=>"\"Extension 1000\" <sip:1000@10.0.0.10>;tag=0H0362SN61jma", :x_variable_sip_full_to=>"<sip:3@10.0.0.12>", :x_variable_sip_req_user=>"3", :x_variable_sip_req_uri=>"3@10.0.0.12", :x_variable_sip_req_host=>"10.0.0.12", :x_variable_sip_to_user=>"3", :x_variable_sip_to_uri=>"3@10.0.0.12", :x_variable_sip_to_host=>"10.0.0.12", :x_variable_sip_contact_params=>"transport=udp;gw=ivr_engine_out", :x_variable_sip_contact_user=>"gw+ivr_engine_out", :x_variable_sip_contact_port=>"5080", :x_variable_sip_contact_uri=>"gw+ivr_engine_out@10.0.0.10:5080", :x_variable_sip_contact_host=>"10.0.0.10", :x_variable_sip_user_agent=>"FreeSWITCH-mod_sofia/1.3.10b+git~20121210T195225Z~7ba3dadcd8", :x_variable_sip_via_host=>"10.0.0.10", :x_variable_sip_via_port=>"5080", :x_variable_sip_via_rport=>"5080", :x_variable_max_forwards=>"69", :x_variable_presence_id=>"1000@10.0.0.10", :x_variable_switch_r_sdp=>"v=0\r\no=- 3571654774 3571654774 IN IP4 10.0.0.3\r\ns=pjmedia\r\nc=IN IP4 10.0.0.3\r\nt=0 0\r\nm=audio 4072 RTP/AVP 18 102 105 8 101\r\nc=IN IP4 10.0.0.3\r\na=rtpmap:18 G729/8000\r\na=fmtp:18 annexb=no\r\na=rtpmap:102 ILBC/8000\r\na=fmtp:102 mode=30\r\na=rtpmap:105 speex/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=rtcp:4073 IN IP4 10.0.0.3\r\n", :x_variable_ep_codec_string=>"PCMA@8000h@20i@64000b", :x_variable_endpoint_disposition=>"DELAYED NEGOTIATION", :x_variable_dp_match=>"DELAYED NEGOTIATIONDELAYED NEGOTIATION", :x_variable_call_uuid=>"3f7d4ece-8733-11e2-aeee-8d859806bb64", :x_variable_open=>"true", :x_variable_rfc2822_date=>"Thu, 07 Mar 2013 11:28:15 -0300", :x_variable_export_vars=>"RFC2822_DATE", :x_variable_hangup_after_bridge=>"false", :x_variable_park_after_bridge=>"true", :x_variable_current_application=>"park"}, call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64"
[2013-03-07 11:28:15] DEBUG Adhearsion::ActiveRecord::Plugin::Service: Ivr Load (4.5ms) SELECT `ivrs`.* FROM `ivrs` WHERE `ivrs`.`id` = ? LIMIT 1 [["id", "3"]]
[2013-03-07 11:28:16] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:16] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:16] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing command #<Punchblock::Component::Input mode=:dtmf, terminator=nil, recognizer=nil, initial_timeout=30000, inter_digit_timeout=30000, sensitivity=nil, min_confidence=nil, grammar=#<Punchblock::Component::Input::Grammar content_type="application/srgs+xml", value=<grammar xmlns="http://www.w3.org/2001/06/grammar" version="1.0" xml:lang="en-US" mode="dtmf" root="inputdigits">
<rule id="inputdigits" scope="public">
<one-of>
<item>0</item>
<item>1</item>
<item>2</item>
<item>3</item>
<item>4</item>
<item>5</item>
<item>6</item>
<item>7</item>
<item>8</item>
<item>9</item>
<item>#</item>
<item>*</item>
</one-of>
</rule>
</grammar>, url=nil, target_call_id=nil, component_id=nil, target_mixer_name=nil>, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:18] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::Complete reason=#<Punchblock::Component::Input::Complete::Success mode=:dtmf, confidence=1.0, interpretation="dtmf-1", utterance="1", name=:success, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id="aa8577d9-7351-4cbe-9891-b09b673d3c05", target_mixer_name=nil>, recording=nil, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id="aa8577d9-7351-4cbe-9891-b09b673d3c05", target_mixer_name=nil>
[2013-03-07 11:28:18] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Menu received valid input (1). Calling the matching hook.
[2013-03-07 11:28:18] WARN Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: ["sofia/gateway/re_engine_out/1001"]
[2013-03-07 11:28:18] WARN Adhearsion::CallController::Dial::Dial: #dial call: 3f7d4ece-8733-11e2-aeee-8d859806bb64
[2013-03-07 11:28:18] WARN Adhearsion::CallController::Dial::Dial: #dial targets: ["sofia/gateway/re_engine_out/1001"]
[2013-03-07 11:28:18] WARN Adhearsion::CallController::Dial::Dial: #dial calls: [[#<Adhearsion::OutboundCall: offer=nil, end_reason=nil, commands=[], variables={}, controllers=[], to=nil, from=nil>, "sofia/gateway/re_engine_out/1001", nil]]
[2013-03-07 11:28:18] WARN Adhearsion::CallController::Dial::Dial: #dial calling: "sofia/gateway/re_engine_out/1001"
[2013-03-07 11:28:18] DEBUG Adhearsion::OutboundCall: : Executing command #<Punchblock::Command::Dial to="sofia/gateway/re_engine_out/1001", from="1000", join=nil, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:18] WARN Adhearsion::CallController::Dial::Dial: #dial awaiting_completion
[2013-03-07 11:28:18] WARN Adhearsion::CallController::Dial::Dial: #dial awaiting_completion: no_answer
[2013-03-07 11:28:22] DEBUG Adhearsion::OutboundCall: 2860d510-8454-4861-8c43-e4fffaeb159f: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="2860d510-8454-4861-8c43-e4fffaeb159f", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:22] WARN Adhearsion::CallController::Dial::Dial: #dial joining call 2860d510-8454-4861-8c43-e4fffaeb159f to 3f7d4ece-8733-11e2-aeee-8d859806bb64
[2013-03-07 11:28:22] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:22] DEBUG Adhearsion::OutboundCall: 2860d510-8454-4861-8c43-e4fffaeb159f: Executing command #<Punchblock::Command::Join call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", mixer_name=nil, direction=nil, media=nil, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:22] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::Joined call_id="2860d510-8454-4861-8c43-e4fffaeb159f", mixer_name=nil, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:22] DEBUG Adhearsion::OutboundCall: 2860d510-8454-4861-8c43-e4fffaeb159f: Receiving message: #<Punchblock::Event::Joined call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", mixer_name=nil, target_call_id="2860d510-8454-4861-8c43-e4fffaeb159f", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:24] DEBUG Adhearsion::OutboundCall: 2860d510-8454-4861-8c43-e4fffaeb159f: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="2860d510-8454-4861-8c43-e4fffaeb159f", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:24] INFO Adhearsion::OutboundCall: 2860d510-8454-4861-8c43-e4fffaeb159f: Call ended
[2013-03-07 11:28:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:24] INFO Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Call ended
[2013-03-07 11:28:24] WARN Adhearsion::CallController::Dial::Dial: #dial finished. Hanging up 1 outbound calls: 2860d510-8454-4861-8c43-e4fffaeb159f.
[2013-03-07 11:28:24] WARN Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: ANSWER: success: IvrPlan::Play
[2013-03-07 11:28:24] ERROR Adhearsion::PunchblockPlugin::Initializer: Event received for inactive call 3f7d4ece-8733-11e2-aeee-8d859806bb64: #<Punchblock::Event::Unjoined call_id="2860d510-8454-4861-8c43-e4fffaeb159f", mixer_name=nil, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:28:24] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="3@10.0.0.12", from=" <1000@10.0.0.10>", headers={:x_variable_direction=>"inbound", :x_variable_uuid=>"3f7d4ece-8733-11e2-aeee-8d859806bb64", :x_variable_session_id=>"1", :x_variable_sip_from_user=>"1000", :x_variable_sip_from_uri=>"1000@10.0.0.10", :x_variable_sip_from_host=>"10.0.0.10", :x_variable_channel_name=>"sofia/internal/1000@10.0.0.10", :x_variable_sip_local_network_addr=>"10.0.0.12", :x_variable_sip_network_ip=>"10.0.0.10", :x_variable_sip_network_port=>"5080", :x_variable_sip_received_ip=>"10.0.0.10", :x_variable_sip_received_port=>"5080", :x_variable_sip_via_protocol=>"udp", :x_variable_sip_authorized=>"true", :x_variable_sip_acl_authed_by=>"domains", :x_variable_sip_from_user_stripped=>"1000", :x_variable_sofia_profile_name=>"internal", :x_variable_recovery_profile_name=>"internal", :x_variable_sip_remote_party_id=>"\"Extension 1000\" <sip:1000@10.0.0.10>;party=calling;screen=yes;privacy=off", :x_variable_sip_cid_type=>"rpid", :x_variable_sip_req_user=>"3", :x_variable_sip_req_uri=>"3@10.0.0.12", :x_variable_sip_req_host=>"10.0.0.12", :x_variable_sip_to_user=>"3", :x_variable_sip_to_uri=>"3@10.0.0.12", :x_variable_sip_to_host=>"10.0.0.12", :x_variable_sip_contact_params=>"transport=udp;gw=ivr_engine_out", :x_variable_sip_contact_user=>"gw+ivr_engine_out", :x_variable_sip_contact_port=>"5080", :x_variable_sip_contact_uri=>"gw+ivr_engine_out@10.0.0.10:5080", :x_variable_sip_contact_host=>"10.0.0.10", :x_variable_sip_user_agent=>"FreeSWITCH-mod_sofia/1.3.10b+git~20121210T195225Z~7ba3dadcd8", :x_variable_sip_via_host=>"10.0.0.10", :x_variable_sip_via_port=>"5080", :x_variable_sip_via_rport=>"5080", :x_variable_max_forwards=>"69", :x_variable_presence_id=>"1000@10.0.0.10", :x_variable_switch_r_sdp=>"v=0\r\no=- 3571654774 3571654774 IN IP4 10.0.0.3\r\ns=pjmedia\r\nc=IN IP4 10.0.0.3\r\nt=0 0\r\nm=audio 4072 RTP/AVP 18 102 105 8 101\r\nc=IN IP4 10.0.0.3\r\na=rtpmap:18 G729/8000\r\na=fmtp:18 annexb=no\r\na=rtpmap:102 ILBC/8000\r\na=fmtp:102 mode=30\r\na=rtpmap:105 speex/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=rtcp:4073 IN IP4 10.0.0.3\r\n", :x_variable_ep_codec_string=>"PCMA@8000h@20i@64000b", :x_variable_dp_match=>"DELAYED NEGOTIATIONDELAYED NEGOTIATION", :x_variable_open=>"true", :x_variable_rfc2822_date=>"Thu, 07 Mar 2013 11:28:15 -0300", :x_variable_export_vars=>"RFC2822_DATE", :x_variable_hangup_after_bridge=>"false", :x_variable_park_after_bridge=>"true", :x_variable_current_application=>"answer", :x_variable_sip_remote_audio_rtcp_port=>"4073 IN IP4 10.0.0.3", :x_variable_sip_audio_recv_pt=>"8", :x_variable_sip_use_codec_name=>"PCMA", :x_variable_sip_use_codec_rate=>"8000", :x_variable_sip_use_codec_ptime=>"20", :x_variable_read_codec=>"PCMA", :x_variable_read_rate=>"8000", :x_variable_write_codec=>"PCMA", :x_variable_write_rate=>"8000", :x_variable_local_media_ip=>"10.0.0.12", :x_variable_local_media_port=>"30926", :x_variable_advertised_media_ip=>"10.0.0.12", :x_variable_sip_use_pt=>"8", :x_variable_rtp_use_ssrc=>"1396007656", :x_variable_sip_2833_send_payload=>"101", :x_variable_sip_2833_recv_payload=>"101", :x_variable_remote_media_ip=>"10.0.0.3", :x_variable_remote_media_port=>"4072", :x_variable_sip_local_sdp_str=>"v=0\no=FreeSWITCH 1362635570 1362635571 IN IP4 10.0.0.12\ns=FreeSWITCH\nc=IN IP4 10.0.0.12\nt=0 0\nm=audio 30926 RTP/AVP 8 101\na=rtpmap:8 PCMA/8000\na=rtpmap:101 telephone-event/8000\na=fmtp:101 0-16\na=silenceSupp:off - - - -\na=ptime:20\na=sendrecv\n", :x_variable_endpoint_disposition=>"ANSWER", :x_variable_sip_to_tag=>"ZtHNQ3XtK670S", :x_variable_sip_from_tag=>"0H0362SN61jma", :x_variable_sip_cseq=>"40996937", :x_variable_sip_call_id=>"f0f8f013-01d4-1231-1099-08002715f81e", :x_variable_sip_full_via=>"SIP/2.0/UDP 10.0.0.10:5080;rport=5080;branch=z9hG4bKtKXgvaaH0Z3aN", :x_variable_sip_from_display=>"Extension 1000", :x_variable_sip_full_from=>"\"Extension 1000\" <sip:1000@10.0.0.10>;tag=0H0362SN61jma", :x_variable_sip_full_to=>"<sip:3@10.0.0.12>;tag=ZtHNQ3XtK670S", :x_variable_original_destination_number=>"3", :x_variable_original_caller_id_name=>"Extension 1000", :x_variable_original_caller_id_number=>"1000", :x_variable_transfer_history=>"1362666502:3f80b582-8733-11e2-aeef-8d859806bb64:uuid_br:2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_transfer_source=>"1362666502:3f80b582-8733-11e2-aeef-8d859806bb64:uuid_br:2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_call_uuid=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_last_bridge_to=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_bridge_channel=>"sofia/external/1001", :x_variable_bridge_uuid=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_signal_bond=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_last_sent_callee_id_name=>"1001", :x_variable_last_sent_callee_id_number=>"1001", :x_variable_sip_reason=>"Q.850;cause=16;text=\"NORMAL_CLEARING\"", :x_variable_sip_hangup_phrase=>"OK", :x_variable_last_bridge_hangup_cause=>"NORMAL_CLEARING", :x_variable_last_bridge_proto_specific_hangup_cause=>"sip:200"}, call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64"
[2013-03-07 11:28:24] INFO Adhearsion::Router: Call 3f7d4ece-8733-11e2-aeee-8d859806bb64 selected route "Inbound Call" (IvrController)
[2013-03-07 11:28:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:28:24] INFO Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing controller #<IvrController call=3f7d4ece-8733-11e2-aeee-8d859806bb64, metadata={}>
[2013-03-07 11:28:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::Offer to="3@10.0.0.12", from=" <1000@10.0.0.10>", headers={:x_variable_direction=>"inbound", :x_variable_uuid=>"3f7d4ece-8733-11e2-aeee-8d859806bb64", :x_variable_session_id=>"1", :x_variable_sip_from_user=>"1000", :x_variable_sip_from_uri=>"1000@10.0.0.10", :x_variable_sip_from_host=>"10.0.0.10", :x_variable_channel_name=>"sofia/internal/1000@10.0.0.10", :x_variable_sip_local_network_addr=>"10.0.0.12", :x_variable_sip_network_ip=>"10.0.0.10", :x_variable_sip_network_port=>"5080", :x_variable_sip_received_ip=>"10.0.0.10", :x_variable_sip_received_port=>"5080", :x_variable_sip_via_protocol=>"udp", :x_variable_sip_authorized=>"true", :x_variable_sip_acl_authed_by=>"domains", :x_variable_sip_from_user_stripped=>"1000", :x_variable_sofia_profile_name=>"internal", :x_variable_recovery_profile_name=>"internal", :x_variable_sip_remote_party_id=>"\"Extension 1000\" <sip:1000@10.0.0.10>;party=calling;screen=yes;privacy=off", :x_variable_sip_cid_type=>"rpid", :x_variable_sip_req_user=>"3", :x_variable_sip_req_uri=>"3@10.0.0.12", :x_variable_sip_req_host=>"10.0.0.12", :x_variable_sip_to_user=>"3", :x_variable_sip_to_uri=>"3@10.0.0.12", :x_variable_sip_to_host=>"10.0.0.12", :x_variable_sip_contact_params=>"transport=udp;gw=ivr_engine_out", :x_variable_sip_contact_user=>"gw+ivr_engine_out", :x_variable_sip_contact_port=>"5080", :x_variable_sip_contact_uri=>"gw+ivr_engine_out@10.0.0.10:5080", :x_variable_sip_contact_host=>"10.0.0.10", :x_variable_sip_user_agent=>"FreeSWITCH-mod_sofia/1.3.10b+git~20121210T195225Z~7ba3dadcd8", :x_variable_sip_via_host=>"10.0.0.10", :x_variable_sip_via_port=>"5080", :x_variable_sip_via_rport=>"5080", :x_variable_max_forwards=>"69", :x_variable_presence_id=>"1000@10.0.0.10", :x_variable_switch_r_sdp=>"v=0\r\no=- 3571654774 3571654774 IN IP4 10.0.0.3\r\ns=pjmedia\r\nc=IN IP4 10.0.0.3\r\nt=0 0\r\nm=audio 4072 RTP/AVP 18 102 105 8 101\r\nc=IN IP4 10.0.0.3\r\na=rtpmap:18 G729/8000\r\na=fmtp:18 annexb=no\r\na=rtpmap:102 ILBC/8000\r\na=fmtp:102 mode=30\r\na=rtpmap:105 speex/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=rtcp:4073 IN IP4 10.0.0.3\r\n", :x_variable_ep_codec_string=>"PCMA@8000h@20i@64000b", :x_variable_dp_match=>"DELAYED NEGOTIATIONDELAYED NEGOTIATION", :x_variable_open=>"true", :x_variable_rfc2822_date=>"Thu, 07 Mar 2013 11:28:15 -0300", :x_variable_export_vars=>"RFC2822_DATE", :x_variable_hangup_after_bridge=>"false", :x_variable_park_after_bridge=>"true", :x_variable_current_application=>"answer", :x_variable_sip_remote_audio_rtcp_port=>"4073 IN IP4 10.0.0.3", :x_variable_sip_audio_recv_pt=>"8", :x_variable_sip_use_codec_name=>"PCMA", :x_variable_sip_use_codec_rate=>"8000", :x_variable_sip_use_codec_ptime=>"20", :x_variable_read_codec=>"PCMA", :x_variable_read_rate=>"8000", :x_variable_write_codec=>"PCMA", :x_variable_write_rate=>"8000", :x_variable_local_media_ip=>"10.0.0.12", :x_variable_local_media_port=>"30926", :x_variable_advertised_media_ip=>"10.0.0.12", :x_variable_sip_use_pt=>"8", :x_variable_rtp_use_ssrc=>"1396007656", :x_variable_sip_2833_send_payload=>"101", :x_variable_sip_2833_recv_payload=>"101", :x_variable_remote_media_ip=>"10.0.0.3", :x_variable_remote_media_port=>"4072", :x_variable_sip_local_sdp_str=>"v=0\no=FreeSWITCH 1362635570 1362635571 IN IP4 10.0.0.12\ns=FreeSWITCH\nc=IN IP4 10.0.0.12\nt=0 0\nm=audio 30926 RTP/AVP 8 101\na=rtpmap:8 PCMA/8000\na=rtpmap:101 telephone-event/8000\na=fmtp:101 0-16\na=silenceSupp:off - - - -\na=ptime:20\na=sendrecv\n", :x_variable_endpoint_disposition=>"ANSWER", :x_variable_sip_to_tag=>"ZtHNQ3XtK670S", :x_variable_sip_from_tag=>"0H0362SN61jma", :x_variable_sip_cseq=>"40996937", :x_variable_sip_call_id=>"f0f8f013-01d4-1231-1099-08002715f81e", :x_variable_sip_full_via=>"SIP/2.0/UDP 10.0.0.10:5080;rport=5080;branch=z9hG4bKtKXgvaaH0Z3aN", :x_variable_sip_from_display=>"Extension 1000", :x_variable_sip_full_from=>"\"Extension 1000\" <sip:1000@10.0.0.10>;tag=0H0362SN61jma", :x_variable_sip_full_to=>"<sip:3@10.0.0.12>;tag=ZtHNQ3XtK670S", :x_variable_original_destination_number=>"3", :x_variable_original_caller_id_name=>"Extension 1000", :x_variable_original_caller_id_number=>"1000", :x_variable_transfer_history=>"1362666502:3f80b582-8733-11e2-aeef-8d859806bb64:uuid_br:2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_transfer_source=>"1362666502:3f80b582-8733-11e2-aeef-8d859806bb64:uuid_br:2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_call_uuid=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_last_bridge_to=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_bridge_channel=>"sofia/external/1001", :x_variable_bridge_uuid=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_signal_bond=>"2860d510-8454-4861-8c43-e4fffaeb159f", :x_variable_last_sent_callee_id_name=>"1001", :x_variable_last_sent_callee_id_number=>"1001", :x_variable_sip_reason=>"Q.850;cause=16;text=\"NORMAL_CLEARING\"", :x_variable_sip_hangup_phrase=>"OK", :x_variable_last_bridge_hangup_cause=>"NORMAL_CLEARING", :x_variable_last_bridge_proto_specific_hangup_cause=>"sip:200"}, call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64"
[2013-03-07 11:28:24] DEBUG Adhearsion::ActiveRecord::Plugin::Service: Ivr Load (1.1ms) SELECT `ivrs`.* FROM `ivrs` WHERE `ivrs`.`id` = ? LIMIT 1 [["id", "3"]]
[2013-03-07 11:28:24] INFO Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Call was hung up
[2013-03-07 11:28:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Finished executing controller #<IvrController call=3f7d4ece-8733-11e2-aeee-8d859806bb64, metadata={}>
[2013-03-07 11:28:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-03-07 11:29:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id=nil, target_mixer_name=nil>
[2013-03-07 11:29:24] INFO Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Call ended
[2013-03-07 11:29:24] ERROR Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: <Adhearsion::Call::CommandTimeout> #<Punchblock::Command::Answer headers_hash={}, target_call_id="3f7d4ece-8733-11e2-aeee-8d859806bb64", component_id=nil, target_mixer_name=nil, state_name=:requested>
/home/vagrant/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/celluloid-0.12.4/lib/celluloid/responses.rb:24:in `value'
/home/vagrant/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/celluloid-0.12.4/lib/celluloid/actor.rb:80:in `call'
/home/vagrant/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/celluloid-0.12.4/lib/celluloid/proxies/actor_proxy.rb:102:in `method_missing'
/vagrant/adhearsion/lib/adhearsion/call.rb:22:in `method_missing'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:195:in `answer'
/vagrant/ivr-engine/lib/ivr_controller.rb:13:in `run'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:106:in `execute!'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:81:in `block in exec'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:80:in `catch'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:80:in `exec'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:97:in `exec_with_callback'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:91:in `block (2 levels) in bg_exec'
/vagrant/adhearsion/lib/adhearsion/foundation/exception_handler.rb:5:in `catching_standard_errors'
/vagrant/adhearsion/lib/adhearsion/call_controller.rb:90:in `block in bg_exec'
/home/vagrant/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
/home/vagrant/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
[2013-03-07 11:29:24] DEBUG Adhearsion::Call: 3f7d4ece-8733-11e2-aeee-8d859806bb64: Finished executing controller #<IvrController call=3f7d4ece-8733-11e2-aeee-8d859806bb64, metadata={}>
fs_dial-2.log
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556
2013-03-07 11:26:55.941526 [DEBUG] mod_event_socket.c:2805 Socket up listening on 0.0.0.0:8021
2013-03-07 11:26:55.941858 [NOTICE] switch_core.c:1209 Created ip list rfc1918.auto default (deny)
2013-03-07 11:26:55.941875 [NOTICE] switch_utils.c:295 Adding 10.0.0.0/8 (allow) [] to list rfc1918.auto
2013-03-07 11:26:55.941883 [NOTICE] switch_utils.c:295 Adding 172.16.0.0/12 (allow) [] to list rfc1918.auto
2013-03-07 11:26:55.941888 [NOTICE] switch_utils.c:295 Adding 192.168.0.0/16 (allow) [] to list rfc1918.auto
2013-03-07 11:26:55.941895 [NOTICE] switch_core.c:1217 Created ip list wan.auto default (allow)
2013-03-07 11:26:55.941899 [NOTICE] switch_utils.c:295 Adding 0.0.0.0/8 (deny) [] to list wan.auto
2013-03-07 11:26:55.941908 [NOTICE] switch_utils.c:295 Adding 10.0.0.0/8 (deny) [] to list wan.auto
2013-03-07 11:26:55.941913 [NOTICE] switch_utils.c:295 Adding 172.16.0.0/12 (deny) [] to list wan.auto
2013-03-07 11:26:55.941916 [NOTICE] switch_utils.c:295 Adding 192.168.0.0/16 (deny) [] to list wan.auto
2013-03-07 11:26:55.941916 [NOTICE] switch_core.c:1226 Created ip list nat.auto default (deny)
2013-03-07 11:26:55.941916 [NOTICE] switch_core.c:1228 Adding 10.0.2.15/255.255.255.0 (deny) to list nat.auto
2013-03-07 11:26:55.941916 [NOTICE] switch_utils.c:295 Adding 10.0.0.0/8 (allow) [] to list nat.auto
2013-03-07 11:26:55.941916 [NOTICE] switch_utils.c:295 Adding 172.16.0.0/12 (allow) [] to list nat.auto
2013-03-07 11:26:55.941921 [NOTICE] switch_utils.c:295 Adding 192.168.0.0/16 (allow) [] to list nat.auto
2013-03-07 11:26:55.941927 [NOTICE] switch_core.c:1237 Created ip list loopback.auto default (deny)
2013-03-07 11:26:55.941932 [NOTICE] switch_utils.c:295 Adding 127.0.0.0/8 (allow) [] to list loopback.auto
2013-03-07 11:26:55.941938 [NOTICE] switch_core.c:1243 Created ip list localnet.auto default (deny)
2013-03-07 11:26:55.941946 [NOTICE] switch_core.c:1246 Adding 10.0.2.15/255.255.255.0 (allow) to list localnet.auto
2013-03-07 11:26:55.941965 [NOTICE] switch_utils.c:295 Adding 192.168.42.0/24 (deny) [] to list lan
2013-03-07 11:26:55.941980 [NOTICE] switch_core.c:1342 Adding 192.168.42.0/24 (deny) to list lan
2013-03-07 11:26:55.941989 [NOTICE] switch_utils.c:295 Adding 192.168.42.42/32 (allow) [] to list lan
2013-03-07 11:26:55.941994 [NOTICE] switch_core.c:1342 Adding 192.168.42.42/32 (allow) to list lan
2013-03-07 11:26:55.942059 [NOTICE] switch_utils.c:295 Adding 192.0.2.0/24 (allow) [brian@10.0.0.12] to list domains
2013-03-07 11:26:55.942078 [NOTICE] switch_utils.c:295 Adding 10.0.0.10/24 (allow) [] to list domains
2013-03-07 11:26:55.942084 [NOTICE] switch_core.c:1342 Adding 10.0.0.10/24 (allow) to list domains
2013-03-07 11:26:55.943689 [DEBUG] switch_loadable_module.c:642 Chat Thread Started
2013-03-07 11:26:55.943737 [DEBUG] switch_loadable_module.c:642 Chat Thread Started
2013-03-07 11:28:15.263235 [NOTICE] switch_channel.c:976 New Channel sofia/internal/1000@10.0.0.10 [3f7d4ece-8733-11e2-aeee-8d859806bb64]
2013-03-07 11:28:15.263235 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:15.263235 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:15.263235 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_NEW
2013-03-07 11:28:15.263235 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/1000@10.0.0.10) State NEW
2013-03-07 11:28:15.283139 [DEBUG] sofia.c:7697 IP 10.0.0.10 Approved by acl "domains[]". Access Granted.
2013-03-07 11:28:15.283139 [DEBUG] sofia.c:5597 Channel sofia/internal/1000@10.0.0.10 entering state [received][100]
2013-03-07 11:28:15.283139 [DEBUG] sofia.c:5608 Remote SDP:
v=0
o=- 3571654774 3571654774 IN IP4 10.0.0.3
s=pjmedia
c=IN IP4 10.0.0.3
t=0 0
m=audio 4072 RTP/AVP 18 102 105 8 101
c=IN IP4 10.0.0.3
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:102 ILBC/8000
a=fmtp:102 mode=30
a=rtpmap:105 speex/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4073 IN IP4 10.0.0.3
 
2013-03-07 11:28:15.283139 [DEBUG] sofia.c:5821 (sofia/internal/1000@10.0.0.10) State Change CS_NEW -> CS_INIT
2013-03-07 11:28:15.283139 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_INIT
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1000@10.0.0.10) State INIT
2013-03-07 11:28:15.283139 [DEBUG] mod_sofia.c:86 sofia/internal/1000@10.0.0.10 SOFIA INIT
2013-03-07 11:28:15.283139 [DEBUG] mod_sofia.c:126 (sofia/internal/1000@10.0.0.10) State Change CS_INIT -> CS_ROUTING
2013-03-07 11:28:15.283139 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1000@10.0.0.10) State INIT going to sleep
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_ROUTING
2013-03-07 11:28:15.283139 [DEBUG] switch_channel.c:2012 (sofia/internal/1000@10.0.0.10) Callstate Change DOWN -> RINGING
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/1000@10.0.0.10) State ROUTING
2013-03-07 11:28:15.283139 [DEBUG] mod_sofia.c:149 sofia/internal/1000@10.0.0.10 SOFIA ROUTING
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:117 sofia/internal/1000@10.0.0.10 Standard ROUTING
2013-03-07 11:28:15.283139 [INFO] mod_dialplan_xml.c:557 Processing Extension 1000 <1000>->3 in context default
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1000@10.0.0.10 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Action set(open=true)
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1000@10.0.0.10 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [global-intercept] destination_number(3) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [group-intercept] destination_number(3) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [intercept-ext] destination_number(3) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->redial] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [redial] destination_number(3) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->global] continue=true
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/1000@10.0.0.10 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=- 3571654774 3571654774 IN IP4 10.0.0.3
s=pjmedia
c=IN IP4 10.0.0.3
t=0 0
m=audio 4072 RTP/AVP 18 102 105 8 101
c=IN IP4 10.0.0.3
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:102 ILBC/8000
a=fmtp:102 mode=30
a=rtpmap:105 speex/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4073 IN IP4 10.0.0.3
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1000@10.0.0.10 Absolute Condition [global]
Dialplan: sofia/internal/1000@10.0.0.10 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1000@10.0.0.10 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1000@10.0.0.10 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1000@10.0.0.10 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [snom-demo-2] destination_number(3) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [snom-demo-1] destination_number(3) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [eavesdrop] destination_number(3) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [eavesdrop] destination_number(3) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [call_return] destination_number(3) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [del-group] destination_number(3) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [add-group] destination_number(3) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [call-group-simo] destination_number(3) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [call-group-order] destination_number(3) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [extension-intercom] destination_number(3) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [Local_Extension] destination_number(3) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [Local_Extension_Skinny] destination_number(3) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->group_dial_sales] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [group_dial_sales] destination_number(3) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->group_dial_support] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [group_dial_support] destination_number(3) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->group_dial_billing] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [group_dial_billing] destination_number(3) =~ /^2002$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->operator] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [operator] destination_number(3) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->vmain] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [vmain] destination_number(3) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->sip_uri] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [sip_uri] destination_number(3) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->nb_conferences] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [nb_conferences] destination_number(3) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->wb_conferences] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [wb_conferences] destination_number(3) =~ /^(31\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->uwb_conferences] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [uwb_conferences] destination_number(3) =~ /^(32\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->cdquality_conferences] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [cdquality_conferences] destination_number(3) =~ /^(33\d{2})$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(3) =~ /^9(888|8888|1616|3232)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [mad_boss_intercom] destination_number(3) =~ /^0911$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [mad_boss_intercom] destination_number(3) =~ /^0912$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->mad_boss] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [mad_boss] destination_number(3) =~ /^0913$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ivr_demo] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ivr_demo] destination_number(3) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->dynamic_conference] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [dynamic_conference] destination_number(3) =~ /^5001$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->rtp_multicast_page] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [rtp_multicast_page] destination_number(3) =~ /^pagegroup$|^7243$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->park] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [park] destination_number(3) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->unpark] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [unpark] destination_number(3) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->valet_park] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [valet_park] destination_number(3) =~ /^(6000)$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->valet_park] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [valet_park] destination_number(3) =~ /^(60\d[1-9])$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->park] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [park] destination_number(3) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->unpark] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [unpark] destination_number(3) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->park] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [park] destination_number(3) =~ /callpark/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->unpark] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [unpark] destination_number(3) =~ /pickup/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->wait] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [wait] destination_number(3) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->fax_receive] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [fax_receive] destination_number(3) =~ /^9178$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->fax_transmit] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [fax_transmit] destination_number(3) =~ /^9179$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ringback_180] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ringback_180] destination_number(3) =~ /^9180$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ringback_183_uk_ring] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ringback_183_uk_ring] destination_number(3) =~ /^9181$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ringback_183_music_ring] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ringback_183_music_ring] destination_number(3) =~ /^9182$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ringback_post_answer_uk_ring] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(3) =~ /^9183$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ringback_post_answer_music] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ringback_post_answer_music] destination_number(3) =~ /^9184$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->ClueCon] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [ClueCon] destination_number(3) =~ /^9191$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->show_info] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [show_info] destination_number(3) =~ /^9192$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->video_record] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [video_record] destination_number(3) =~ /^9193$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->video_playback] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [video_playback] destination_number(3) =~ /^9194$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->delay_echo] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [delay_echo] destination_number(3) =~ /^9195$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->echo] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [echo] destination_number(3) =~ /^9196$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->milliwatt] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [milliwatt] destination_number(3) =~ /^9197$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->tone_stream] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [tone_stream] destination_number(3) =~ /^9198$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->zrtp_enrollement] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [zrtp_enrollement] destination_number(3) =~ /^9787$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->hold_music] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [hold_music] destination_number(3) =~ /^9664$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->laugh break] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Regex (FAIL) [laugh break] destination_number(3) =~ /^9386$/ break=on-false
Dialplan: sofia/internal/1000@10.0.0.10 parsing [default->adhearsion] continue=false
Dialplan: sofia/internal/1000@10.0.0.10 Absolute Condition [adhearsion]
Dialplan: sofia/internal/1000@10.0.0.10 Action log(INFO por aca pase yo)
Dialplan: sofia/internal/1000@10.0.0.10 Action set(hangup_after_bridge=false)
Dialplan: sofia/internal/1000@10.0.0.10 Action set(park_after_bridge=true)
Dialplan: sofia/internal/1000@10.0.0.10 Action park()
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/1000@10.0.0.10) State Change CS_ROUTING -> CS_EXECUTE
2013-03-07 11:28:15.283139 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/1000@10.0.0.10) State ROUTING going to sleep
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_EXECUTE
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/1000@10.0.0.10) State EXECUTE
2013-03-07 11:28:15.283139 [DEBUG] mod_sofia.c:242 sofia/internal/1000@10.0.0.10 SOFIA EXECUTE
2013-03-07 11:28:15.283139 [DEBUG] switch_core_state_machine.c:209 sofia/internal/1000@10.0.0.10 Standard EXECUTE
EXECUTE sofia/internal/1000@10.0.0.10 set(open=true)
2013-03-07 11:28:15.283139 [DEBUG] mod_dptools.c:1367 sofia/internal/1000@10.0.0.10 SET [open]=[true]
EXECUTE sofia/internal/1000@10.0.0.10 hash(insert/10.0.0.12-spymap/1000/3f7d4ece-8733-11e2-aeee-8d859806bb64)
EXECUTE sofia/internal/1000@10.0.0.10 hash(insert/10.0.0.12-last_dial/1000/3)
EXECUTE sofia/internal/1000@10.0.0.10 hash(insert/10.0.0.12-last_dial/global/3f7d4ece-8733-11e2-aeee-8d859806bb64)
EXECUTE sofia/internal/1000@10.0.0.10 export(RFC2822_DATE=Thu, 07 Mar 2013 11:28:15 -0300)
2013-03-07 11:28:15.283139 [DEBUG] switch_channel.c:1143 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 07 Mar 2013 11:28:15 -0300]
EXECUTE sofia/internal/1000@10.0.0.10 log(INFO por aca pase yo)
2013-03-07 11:28:15.283139 [INFO] mod_dptools.c:1533 por aca pase yo
EXECUTE sofia/internal/1000@10.0.0.10 set(hangup_after_bridge=false)
2013-03-07 11:28:15.283139 [DEBUG] mod_dptools.c:1367 sofia/internal/1000@10.0.0.10 SET [hangup_after_bridge]=[false]
EXECUTE sofia/internal/1000@10.0.0.10 set(park_after_bridge=true)
2013-03-07 11:28:15.283139 [DEBUG] mod_dptools.c:1367 sofia/internal/1000@10.0.0.10 SET [park_after_bridge]=[true]
EXECUTE sofia/internal/1000@10.0.0.10 park()
2013-03-07 11:28:15.502237 [DEBUG] switch_core_session.c:1110 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:15.502237 [DEBUG] switch_ivr.c:612 sofia/internal/1000@10.0.0.10 Command Execute respond(180 Ringing)
EXECUTE sofia/internal/1000@10.0.0.10 respond(180 Ringing)
2013-03-07 11:28:15.502237 [DEBUG] mod_sofia.c:2631 Responding with 180 [Ringing]
2013-03-07 11:28:15.502237 [WARNING] mod_sofia.c:2692 Cannot respond.
2013-03-07 11:28:15.502237 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.203061 [DEBUG] switch_core_session.c:1110 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.222287 [DEBUG] switch_ivr.c:612 sofia/internal/1000@10.0.0.10 Command Execute answer(%[punchblock_command_id=67459614-f7be-4dd3-bfa6-134842d4e247])
2013-03-07 11:28:16.222287 [DEBUG] switch_event.c:1608 Parsing variable [punchblock_command_id]=[67459614-f7be-4dd3-bfa6-134842d4e247]
EXECUTE sofia/internal/1000@10.0.0.10 answer()
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [G729:18:8000:20:8000]/[G722:9:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [G729:18:8000:20:8000]/[PCMU:0:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [G729:18:8000:20:8000]/[PCMA:8:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [G729:18:8000:20:8000]/[GSM:3:8000:20:13200]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [ILBC:102:8000:30:0]/[G722:9:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [ILBC:102:8000:30:0]/[PCMU:0:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [ILBC:102:8000:30:0]/[PCMA:8:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [ILBC:102:8000:30:0]/[GSM:3:8000:20:13200]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [speex:105:8000:20:0]/[G722:9:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [speex:105:8000:20:0]/[PCMU:0:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [speex:105:8000:20:0]/[PCMA:8:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [speex:105:8000:20:0]/[GSM:3:8000:20:13200]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:3110 Set Codec sofia/internal/1000@10.0.0.10 PCMA/8000 20 ms 160 samples 64000 bits
2013-03-07 11:28:16.222287 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@10.0.0.10 Original read codec set to PCMA:8
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:5284 Set 2833 dtmf send/recv payload to 101
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:3369 AUDIO RTP [sofia/internal/1000@10.0.0.10] 10.0.0.12 port 30926 -> 10.0.0.3 port 4072 codec: 8 ms: 20
2013-03-07 11:28:16.222287 [DEBUG] switch_rtp.c:1982 Starting timer [soft] 160 bytes per 20ms
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:3633 Set 2833 dtmf send payload to 101
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:3639 Set 2833 dtmf receive payload to 101
2013-03-07 11:28:16.222287 [DEBUG] sofia_glue.c:3666 sofia/internal/1000@10.0.0.10 Set rtp dtmf delay to 40
2013-03-07 11:28:16.222287 [NOTICE] sofia_glue.c:4277 Pre-Answer sofia/internal/1000@10.0.0.10!
2013-03-07 11:28:16.222287 [DEBUG] switch_channel.c:3155 (sofia/internal/1000@10.0.0.10) Callstate Change RINGING -> EARLY
2013-03-07 11:28:16.222287 [DEBUG] mod_sofia.c:856 Local SDP sofia/internal/1000@10.0.0.10:
v=0
o=FreeSWITCH 1362635570 1362635571 IN IP4 10.0.0.12
s=FreeSWITCH
c=IN IP4 10.0.0.12
t=0 0
m=audio 30926 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
 
2013-03-07 11:28:16.222287 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.222287 [DEBUG] sofia.c:5597 Channel sofia/internal/1000@10.0.0.10 entering state [completed][200]
2013-03-07 11:28:16.222287 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.222287 [DEBUG] switch_channel.c:3414 (sofia/internal/1000@10.0.0.10) Callstate Change EARLY -> ACTIVE
2013-03-07 11:28:16.222287 [NOTICE] mod_dptools.c:1199 Channel [sofia/internal/1000@10.0.0.10] has been answered
2013-03-07 11:28:16.222287 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.222287 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.222287 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.222287 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:16.262029 [DEBUG] sofia.c:5597 Channel sofia/internal/1000@10.0.0.10 entering state [ready][200]
2013-03-07 11:28:16.262029 [INFO] sofia.c:931 sofia/internal/1000@10.0.0.10 Update Callee ID to "1000" <1000>
2013-03-07 11:28:16.262029 [DEBUG] sofia.c:7471 dispatched freeswitch event for INFO
2013-03-07 11:28:16.382240 [DEBUG] switch_rtp.c:3701 Correct ip/port confirmed.
2013-03-07 11:28:18.403661 [DEBUG] switch_rtp.c:3912 RTP RECV DTMF 1:1600
2013-03-07 11:28:18.403661 [DEBUG] switch_channel.c:417 RECV DTMF 1:1600
2013-03-07 11:28:18.502162 [DEBUG] switch_ivr_originate.c:2039 Parsing global variables
2013-03-07 11:28:18.502162 [DEBUG] switch_event.c:1608 Parsing variable [return_ring_ready]=[true]
2013-03-07 11:28:18.502162 [DEBUG] switch_event.c:1608 Parsing variable [origination_uuid]=[2860d510-8454-4861-8c43-e4fffaeb159f]
2013-03-07 11:28:18.502162 [DEBUG] switch_event.c:1608 Parsing variable [origination_caller_id_number]=[1000]
2013-03-07 11:28:18.502162 [DEBUG] switch_event.c:1608 Parsing variable [originate_timeout]=[30]
2013-03-07 11:28:18.502162 [NOTICE] switch_channel.c:976 New Channel sofia/external/1001 [2860d510-8454-4861-8c43-e4fffaeb159f]
2013-03-07 11:28:18.502162 [DEBUG] mod_sofia.c:4960 (sofia/external/1001) State Change CS_NEW -> CS_INIT
2013-03-07 11:28:18.502162 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.502162 [DEBUG] switch_core_session.c:560 sofia/external/1001 set UUID=2860d510-8454-4861-8c43-e4fffaeb159f
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_INIT
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:454 (sofia/external/1001) State INIT
2013-03-07 11:28:18.502162 [DEBUG] mod_sofia.c:86 sofia/external/1001 SOFIA INIT
2013-03-07 11:28:18.502162 [DEBUG] sofia_glue.c:2664 Local SDP:
v=0
o=FreeSWITCH 1362647238 1362647239 IN IP4 10.0.0.12
s=FreeSWITCH
c=IN IP4 10.0.0.12
t=0 0
m=audio 19260 RTP/AVP 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
 
2013-03-07 11:28:18.502162 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.502162 [DEBUG] mod_sofia.c:126 (sofia/external/1001) State Change CS_INIT -> CS_ROUTING
2013-03-07 11:28:18.502162 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:454 (sofia/external/1001) State INIT going to sleep
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_ROUTING
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:470 (sofia/external/1001) State ROUTING
2013-03-07 11:28:18.502162 [DEBUG] mod_sofia.c:149 sofia/external/1001 SOFIA ROUTING
2013-03-07 11:28:18.502162 [DEBUG] switch_ivr_originate.c:67 (sofia/external/1001) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-03-07 11:28:18.502162 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:470 (sofia/external/1001) State ROUTING going to sleep
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_CONSUME_MEDIA
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:489 (sofia/external/1001) State CONSUME_MEDIA
2013-03-07 11:28:18.502162 [DEBUG] switch_core_state_machine.c:489 (sofia/external/1001) State CONSUME_MEDIA going to sleep
2013-03-07 11:28:18.502162 [DEBUG] sofia.c:5597 Channel sofia/external/1001 entering state [calling][0]
2013-03-07 11:28:18.541861 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.541861 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.541861 [DEBUG] sofia.c:5597 Channel sofia/external/1001 entering state [calling][0]
2013-03-07 11:28:18.762141 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.762141 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.762141 [INFO] sofia.c:931 sofia/external/1001 Update Callee ID to "1001" <sip:1001@10.0.0.14>
2013-03-07 11:28:18.762141 [DEBUG] sofia.c:5597 Channel sofia/external/1001 entering state [proceeding][183]
2013-03-07 11:28:18.762141 [DEBUG] sofia.c:5608 Remote SDP:
v=0
o=FreeSWITCH 1362638677 1362638678 IN IP4 10.0.0.14
s=FreeSWITCH
c=IN IP4 10.0.0.14
t=0 0
m=audio 27328 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
 
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:5155 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:3110 Set Codec sofia/external/1001 PCMU/8000 20 ms 160 samples 64000 bits
2013-03-07 11:28:18.762141 [DEBUG] switch_core_codec.c:111 sofia/external/1001 Original read codec set to PCMU:0
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:5277 Set 2833 dtmf send payload to 101
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:3369 AUDIO RTP [sofia/external/1001] 10.0.0.12 port 19260 -> 10.0.0.14 port 27328 codec: 0 ms: 20
2013-03-07 11:28:18.762141 [DEBUG] switch_rtp.c:1982 Starting timer [soft] 160 bytes per 20ms
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:3633 Set 2833 dtmf send payload to 101
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:3639 Set 2833 dtmf receive payload to 101
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:3666 sofia/external/1001 Set rtp dtmf delay to 40
2013-03-07 11:28:18.762141 [DEBUG] sofia_glue.c:3672 Set comfort noise payload to 13
2013-03-07 11:28:18.762141 [NOTICE] sofia_glue.c:4277 Pre-Answer sofia/external/1001!
2013-03-07 11:28:18.762141 [DEBUG] switch_channel.c:3155 (sofia/external/1001) Callstate Change DOWN -> EARLY
2013-03-07 11:28:18.762141 [DEBUG] switch_ivr_originate.c:3463 Originate Resulted in Success: [sofia/external/1001]
2013-03-07 11:28:18.762141 [INFO] switch_channel.c:2872 sofia/external/1001 Flipping CID from "" <1000> to "1001" <1001>
2013-03-07 11:28:18.762141 [DEBUG] mod_commands.c:4049 (sofia/external/1001) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2013-03-07 11:28:18.762141 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:18.762141 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_EXECUTE
2013-03-07 11:28:18.762141 [DEBUG] switch_core_state_machine.c:477 (sofia/external/1001) State EXECUTE
2013-03-07 11:28:18.762141 [DEBUG] mod_sofia.c:242 sofia/external/1001 SOFIA EXECUTE
2013-03-07 11:28:18.762141 [DEBUG] switch_core_state_machine.c:209 sofia/external/1001 Standard EXECUTE
EXECUTE sofia/external/1001 park()
2013-03-07 11:28:18.841866 [DEBUG] switch_rtp.c:3701 Correct ip/port confirmed.
2013-03-07 11:28:22.442063 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.442063 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.481941 [INFO] sofia.c:931 sofia/external/1001 Update Callee ID to "Outbound Call" <sip:1001@10.0.0.14>
2013-03-07 11:28:22.481941 [DEBUG] sofia.c:5597 Channel sofia/external/1001 entering state [completing][200]
2013-03-07 11:28:22.481941 [DEBUG] sofia.c:5605 Duplicate SDP
v=0
o=FreeSWITCH 1362638677 1362638678 IN IP4 10.0.0.14
s=FreeSWITCH
c=IN IP4 10.0.0.14
t=0 0
m=audio 27328 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
 
2013-03-07 11:28:22.481941 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.481941 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.481941 [DEBUG] sofia.c:5597 Channel sofia/external/1001 entering state [ready][200]
2013-03-07 11:28:22.481941 [DEBUG] switch_channel.c:3414 (sofia/external/1001) Callstate Change EARLY -> ACTIVE
2013-03-07 11:28:22.481941 [NOTICE] sofia.c:6288 Channel [sofia/external/1001] has been answered
2013-03-07 11:28:22.522407 [DEBUG] switch_ivr_bridge.c:1700 (sofia/external/1001) State Change CS_EXECUTE -> CS_HIBERNATE
2013-03-07 11:28:22.522407 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.522407 [DEBUG] switch_ivr_bridge.c:1702 (sofia/internal/1000@10.0.0.10) State Change CS_EXECUTE -> CS_HIBERNATE
2013-03-07 11:28:22.522407 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.522407 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/1000@10.0.0.10) State EXECUTE going to sleep
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_HIBERNATE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:492 (sofia/internal/1000@10.0.0.10) State HIBERNATE
2013-03-07 11:28:22.561850 [DEBUG] mod_sofia.c:223 sofia/internal/1000@10.0.0.10 SOFIA HIBERNATE
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:766 (sofia/internal/1000@10.0.0.10) State Change CS_HIBERNATE -> CS_RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:492 (sofia/internal/1000@10.0.0.10) State HIBERNATE going to sleep
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@10.0.0.10) State RESET
2013-03-07 11:28:22.561850 [DEBUG] mod_sofia.c:167 sofia/internal/1000@10.0.0.10 SOFIA RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:751 sofia/internal/1000@10.0.0.10 CUSTOM RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:106 sofia/internal/1000@10.0.0.10 Standard RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@10.0.0.10) State RESET going to sleep
2013-03-07 11:28:22.561850 [DEBUG] sofia.c:7471 dispatched freeswitch event for INFO
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:477 (sofia/external/1001) State EXECUTE going to sleep
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_HIBERNATE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:492 (sofia/external/1001) State HIBERNATE
2013-03-07 11:28:22.561850 [DEBUG] mod_sofia.c:223 sofia/external/1001 SOFIA HIBERNATE
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:766 (sofia/external/1001) State Change CS_HIBERNATE -> CS_RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:492 (sofia/external/1001) State HIBERNATE going to sleep
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:473 (sofia/external/1001) State RESET
2013-03-07 11:28:22.561850 [DEBUG] mod_sofia.c:167 sofia/external/1001 SOFIA RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:751 sofia/external/1001 CUSTOM RESET
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:758 (sofia/external/1001) State Change CS_RESET -> CS_SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:473 (sofia/external/1001) State RESET going to sleep
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:483 (sofia/external/1001) State SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] mod_sofia.c:687 SOFIA SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:776 sofia/external/1001 CUSTOM SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:808 (sofia/internal/1000@10.0.0.10) State Change CS_RESET -> CS_SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:483 (sofia/internal/1000@10.0.0.10) State SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] mod_sofia.c:687 SOFIA SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_ivr_bridge.c:776 sofia/internal/1000@10.0.0.10 CUSTOM SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:277 sofia/internal/1000@10.0.0.10 Standard SOFT_EXECUTE
2013-03-07 11:28:22.561850 [DEBUG] switch_core_state_machine.c:483 (sofia/internal/1000@10.0.0.10) State SOFT_EXECUTE going to sleep
2013-03-07 11:28:22.582197 [DEBUG] switch_ivr_bridge.c:1268 (sofia/internal/1000@10.0.0.10) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
2013-03-07 11:28:22.582197 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.582197 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.582197 [DEBUG] switch_core_session.c:830 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.582197 [DEBUG] switch_ivr_bridge.c:1370 (sofia/internal/1000@10.0.0.10) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2013-03-07 11:28:22.582197 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.582197 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_EXCHANGE_MEDIA
2013-03-07 11:28:22.582197 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/1000@10.0.0.10) State EXCHANGE_MEDIA
2013-03-07 11:28:22.582197 [DEBUG] mod_sofia.c:681 SOFIA EXCHANGE_MEDIA
2013-03-07 11:28:22.582197 [DEBUG] switch_core_session.c:892 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.582197 [DEBUG] switch_core_session.c:892 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:22.642245 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:22.681844 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:24.541965 [DEBUG] switch_core_session.c:975 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_channel.c:3011 (sofia/external/1001) Callstate Change ACTIVE -> HANGUP
2013-03-07 11:28:24.563400 [NOTICE] sofia.c:711 Hangup sofia/external/1001 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2013-03-07 11:28:24.563400 [DEBUG] switch_channel.c:3034 Send signal sofia/external/1001 [KILL]
2013-03-07 11:28:24.563400 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr_bridge.c:597 BRIDGE THREAD DONE [sofia/external/1001]
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr_bridge.c:622 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr_bridge.c:510 sofia/external/1001 ending bridge by request from write function
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr_bridge.c:597 BRIDGE THREAD DONE [sofia/internal/1000@10.0.0.10]
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr_bridge.c:622 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr.c:2847 (sofia/internal/1000@10.0.0.10) State Change CS_EXCHANGE_MEDIA -> CS_PARK
2013-03-07 11:28:24.563400 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/1000@10.0.0.10) State EXCHANGE_MEDIA going to sleep
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_PARK
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:486 (sofia/internal/1000@10.0.0.10) State PARK
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:283 sofia/internal/1000@10.0.0.10 Standard PARK
2013-03-07 11:28:24.563400 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_ivr_bridge.c:1471 sofia/external/1001 skip receive message [UNBRIDGE] (channel is hungup already)
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:483 (sofia/external/1001) State SOFT_EXECUTE going to sleep
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_HANGUP
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:676 (sofia/external/1001) State HANGUP
2013-03-07 11:28:24.563400 [DEBUG] mod_sofia.c:503 Channel sofia/external/1001 hanging up, cause: NORMAL_CLEARING
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:48 sofia/external/1001 Standard HANGUP, cause: NORMAL_CLEARING
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:676 (sofia/external/1001) State HANGUP going to sleep
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:446 (sofia/external/1001) State Change CS_HANGUP -> CS_REPORTING
2013-03-07 11:28:24.563400 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:415 (sofia/external/1001) Running State Change CS_REPORTING
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:758 (sofia/external/1001) State REPORTING
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:92 sofia/external/1001 Standard REPORTING, cause: NORMAL_CLEARING
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:758 (sofia/external/1001) State REPORTING going to sleep
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:440 (sofia/external/1001) State Change CS_REPORTING -> CS_DESTROY
2013-03-07 11:28:24.563400 [DEBUG] switch_core_session.c:1310 Send signal sofia/external/1001 [BREAK]
2013-03-07 11:28:24.563400 [DEBUG] switch_core_session.c:1518 Session 2 (sofia/external/1001) Locked, Waiting on external entities
2013-03-07 11:28:24.563400 [NOTICE] switch_core_session.c:1536 Session 2 (sofia/external/1001) Ended
2013-03-07 11:28:24.563400 [NOTICE] switch_core_session.c:1540 Close Channel sofia/external/1001 [CS_DESTROY]
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:565 (sofia/external/1001) Callstate Change HANGUP -> DOWN
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:568 (sofia/external/1001) Running State Change CS_DESTROY
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:578 (sofia/external/1001) State DESTROY
2013-03-07 11:28:24.563400 [DEBUG] mod_sofia.c:396 sofia/external/1001 SOFIA DESTROY
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:99 sofia/external/1001 Standard DESTROY
2013-03-07 11:28:24.563400 [DEBUG] switch_core_state_machine.c:578 (sofia/external/1001) State DESTROY going to sleep
2013-03-07 11:28:24.762111 [DEBUG] switch_core_session.c:1110 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:24.802171 [DEBUG] switch_ivr.c:612 sofia/internal/1000@10.0.0.10 Command Execute respond(180 Ringing)
EXECUTE sofia/internal/1000@10.0.0.10 respond(180 Ringing)
2013-03-07 11:28:24.802171 [DEBUG] mod_sofia.c:2631 Responding with 180 [Ringing]
2013-03-07 11:28:24.802171 [WARNING] mod_sofia.c:2692 Cannot respond.
2013-03-07 11:28:24.802171 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:24.902032 [DEBUG] switch_core_session.c:1110 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:28:24.921865 [DEBUG] switch_ivr.c:612 sofia/internal/1000@10.0.0.10 Command Execute answer(%[punchblock_command_id=466cc2c0-4c8e-43e3-bfdf-7ad784b9b677])
2013-03-07 11:28:24.921865 [DEBUG] switch_event.c:1608 Parsing variable [punchblock_command_id]=[466cc2c0-4c8e-43e3-bfdf-7ad784b9b677]
EXECUTE sofia/internal/1000@10.0.0.10 answer()
2013-03-07 11:29:01.642482 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:29:01.662467 [DEBUG] switch_channel.c:3011 (sofia/internal/1000@10.0.0.10) Callstate Change ACTIVE -> HANGUP
2013-03-07 11:29:01.662467 [NOTICE] sofia.c:711 Hangup sofia/internal/1000@10.0.0.10 [CS_PARK] [NORMAL_CLEARING]
2013-03-07 11:29:01.662467 [DEBUG] switch_channel.c:3034 Send signal sofia/internal/1000@10.0.0.10 [KILL]
2013-03-07 11:29:01.662467 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:486 (sofia/internal/1000@10.0.0.10) State PARK going to sleep
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_HANGUP
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:676 (sofia/internal/1000@10.0.0.10) State HANGUP
2013-03-07 11:29:01.662467 [DEBUG] mod_sofia.c:497 sofia/internal/1000@10.0.0.10 Overriding SIP cause 480 with 200 from the other leg
2013-03-07 11:29:01.662467 [DEBUG] mod_sofia.c:503 Channel sofia/internal/1000@10.0.0.10 hanging up, cause: NORMAL_CLEARING
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:48 sofia/internal/1000@10.0.0.10 Standard HANGUP, cause: NORMAL_CLEARING
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:676 (sofia/internal/1000@10.0.0.10) State HANGUP going to sleep
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/1000@10.0.0.10) State Change CS_HANGUP -> CS_REPORTING
2013-03-07 11:29:01.662467 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@10.0.0.10) Running State Change CS_REPORTING
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:758 (sofia/internal/1000@10.0.0.10) State REPORTING
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:92 sofia/internal/1000@10.0.0.10 Standard REPORTING, cause: NORMAL_CLEARING
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:758 (sofia/internal/1000@10.0.0.10) State REPORTING going to sleep
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/1000@10.0.0.10) State Change CS_REPORTING -> CS_DESTROY
2013-03-07 11:29:01.662467 [DEBUG] switch_core_session.c:1310 Send signal sofia/internal/1000@10.0.0.10 [BREAK]
2013-03-07 11:29:01.662467 [DEBUG] switch_core_session.c:1518 Session 1 (sofia/internal/1000@10.0.0.10) Locked, Waiting on external entities
2013-03-07 11:29:01.662467 [NOTICE] switch_core_session.c:1536 Session 1 (sofia/internal/1000@10.0.0.10) Ended
2013-03-07 11:29:01.662467 [NOTICE] switch_core_session.c:1540 Close Channel sofia/internal/1000@10.0.0.10 [CS_DESTROY]
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1000@10.0.0.10) Callstate Change HANGUP -> DOWN
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:568 (sofia/internal/1000@10.0.0.10) Running State Change CS_DESTROY
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/1000@10.0.0.10) State DESTROY
2013-03-07 11:29:01.662467 [DEBUG] mod_sofia.c:396 sofia/internal/1000@10.0.0.10 SOFIA DESTROY
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:99 sofia/internal/1000@10.0.0.10 Standard DESTROY
2013-03-07 11:29:01.662467 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/1000@10.0.0.10) State DESTROY going to sleep

Please sign in to comment on this gist.

Something went wrong with that request. Please try again.