Skip to content

Instantly share code, notes, and snippets.

@krakatoa
Created March 7, 2013 14:23
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save krakatoa/9fed421c8516a1eac395 to your computer and use it in GitHub Desktop.
Save krakatoa/9fed421c8516a1eac395 to your computer and use it in GitHub Desktop.
Dial issue with park_after_bridge=true and hangup_after_bridge=false
[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={}>
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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment