search

adhearsion / adhearsion

A Ruby framework for building telephony applications
http://adhearsion.com
MIT License
609 stars 128 forks source link

Adhearsion hangs up inbound call after dial action with Asterisk (11) #287

Closed gersmann closed 11 years ago

gersmann commented 11 years ago

I have a new installation of asterisk 11 and adhearsion 2.3 with a very simple controller:

def run
    answer
    dial 'SIP/08925007641@placetel.de'
    dial 'SIP/08925007642@placetel.de'
    hangup
  end

The inbound call gets correctly forwarded to the first dial actions number. However, if that call is terminated by the receiver, I would expect the call to be forwarded to the second number. This is not happening, both calls are hanged up.

See the following log for reference:

[2013-04-22 02:32:27] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="498912509582", from="unknown <SIP/+498941150126>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/placetel.de-00000005", :x_agi_language=>"en", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1366590747.7", :x_agi_version=>"11.3.0", :x_agi_callerid=>"+498941150126", :x_agi_calleridname=>"unknown", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"498912509582", :x_agi_rdnis=>"unknown", :x_agi_context=>"adhearsion", :x_agi_extension=>"498912509582", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"4393988096"}, call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084"
[2013-04-22 02:32:27] INFO  Adhearsion::Router: Call 27b79b14-aaf8-4f63-af1a-78a6643e8084 selected route "default" (Test)
[2013-04-22 02:32:27] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-04-22 02:32:27] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/placetel.de-00000005", :commandid=>"431347133", :command=>"EXEC RINGING"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:27] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/placetel.de-00000005", :commandid=>"431347133", :command=>"EXEC RINGING", :resultcode=>"200", :result=>"Success"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:27] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/placetel.de-00000005", :commandid=>"3acb5042-69c6-4e1a-b6fa-cffaf6429c4b", :result=>"200%20result%3D0%0A"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:27] INFO  Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Executing controller #<Test call=27b79b14-aaf8-4f63-af1a-78a6643e8084, metadata={}>
[2013-04-22 02:32:27] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-04-22 02:32:28] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Offer to="498912509582", from="unknown <SIP/+498941150126>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/placetel.de-00000005", :x_agi_language=>"en", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1366590747.7", :x_agi_version=>"11.3.0", :x_agi_callerid=>"+498941150126", :x_agi_calleridname=>"unknown", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"498912509582", :x_agi_rdnis=>"unknown", :x_agi_context=>"adhearsion", :x_agi_extension=>"498912509582", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"4393988096"}, call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084"
[2013-04-22 02:32:28] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/placetel.de-00000005", :commandid=>"48914149", :command=>"ANSWER"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newstate", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000005", :channelstate=>"6", :channelstatedesc=>"Up", :calleridnum=>"+498941150126", :calleridname=>"", :connectedlinenum=>"", :connectedlinename=>"", :uniqueid=>"1366590747.7"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/placetel.de-00000005", :commandid=>"48914149", :command=>"ANSWER", :resultcode=>"200", :result=>"Success"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/placetel.de-00000005", :commandid=>"363726a7-df02-42d4-a5f1-6f2ee79eff5d", :result=>"200%20result%3D0%0A"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::OutboundCall: : Executing command #<Punchblock::Command::Dial to="SIP/08925007641@placetel.de", from="unknown <SIP/+498941150126>", join=nil, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-04-22 02:32:28] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"punchblock_call_id", :value=>"12132a5b-6454-43ab-9d1d-5b4049135e94", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :uniqueid=>"1366590748.8", :accountcode=>"", :oldaccountcode=>""}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewCallerid", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :calleridnum=>"SIP/+498941150126", :calleridname=>"unknown", :uniqueid=>"1366590748.8", :cid_callingpres=>"0 (Presentation Allowed, Not Screened)"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newstate", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :channelstate=>"5", :channelstatedesc=>"Ringing", :calleridnum=>"SIP/+498941150126", :calleridname=>"unknown", :connectedlinenum=>"SIP/+498941150126", :connectedlinename=>"unknown", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:28] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Ringing headers_hash={}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newstate", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :channelstate=>"6", :channelstatedesc=>"Up", :calleridnum=>"SIP/+498941150126", :calleridname=>"unknown", :connectedlinenum=>"SIP/+498941150126", :connectedlinename=>"unknown", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"punchblock_call_id", :value=>"12132a5b-6454-43ab-9d1d-5b4049135e94", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :uniqueid=>"1366590748.8", :accountcode=>"", :oldaccountcode=>""}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="OriginateResponse", attributes_hash={:privilege=>"call,all", :actionid=>"36b0dcd1-047f-457f-923c-d9c7986ba8cf", :response=>"Success", :channel=>"SIP/placetel.de-00000006", :context=>"", :exten=>"", :reason=>"4", :uniqueid=>"1366590748.8", :calleridnum=>"SIP/+498941150126", :calleridname=>"unknown"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/placetel.de-00000006", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fplacetel.de-00000006%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201366590748.8%0Aagi_version%3A%2011.3.0%0Aagi_callerid%3A%20SIP%2F%2B498941150126%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%204395028480%0A%0A"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::CallController::Dial::Dial: #dial joining call 12132a5b-6454-43ab-9d1d-5b4049135e94 to 27b79b14-aaf8-4f63-af1a-78a6643e8084
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/placetel.de-00000005", :commandid=>"1268156699", :command=>"ANSWER"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/placetel.de-00000005", :commandid=>"1268156699", :command=>"ANSWER", :resultcode=>"200", :result=>"Success"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/placetel.de-00000005", :commandid=>"99cf6d6d-1efd-41ac-bc27-ad9e4999c91f", :result=>"200%20result%3D0%0A"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Executing command #<Punchblock::Command::Join call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", mixer_name=nil, direction=nil, media=nil, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="MusicOnHold", attributes_hash={:privilege=>"call,all", :state=>"Stop", :channel=>"SIP/placetel.de-00000005", :uniqueid=>"1366590747.7"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Rename", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000005", :newname=>"SIP/placetel.de-00000005<MASQ>", :uniqueid=>"1366590747.7"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/placetel.de-00000006", :commandid=>"1605142416", :command=>"EXEC Bridge \"SIP/placetel.de-00000005\""}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewCallerid", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000005", :calleridnum=>"+498941150126", :calleridname=>"", :uniqueid=>"1366590752.9", :cid_callingpres=>"0 (Presentation Allowed, Not Screened)"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"Bridge/SIP/placetel.de-00000005<ZOMBIE>"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="BridgeExec", attributes_hash={:privilege=>"call,all", :response=>"Success", :channel1=>"SIP/placetel.de-00000006", :channel2=>"SIP/placetel.de-00000005"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="BridgeExec", attributes_hash={:privilege=>"call,all", :response=>"Success", :channel1=>"SIP/placetel.de-00000006", :channel2=>"SIP/placetel.de-00000005"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000005", :uniqueid=>"1366590752.9", :accountcode=>"", :oldaccountcode=>""}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"BRIDGEPEER", :value=>"SIP/placetel.de-00000005", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"BRIDGEPEER", :value=>"SIP/placetel.de-00000006", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"Bridge/SIP/placetel.de-00000005<ZOMBIE>", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20Bridge%2FSIP%2Fplacetel.de-00000005%3CZOMBIE%3E%0Aagi_language%3A%20en%0Aagi_type%3A%20NULL%0Aagi_uniqueid%3A%201366590747.7%0Aagi_version%3A%2011.3.0%0Aagi_callerid%3A%20unknown%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%2067%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%204393988096%0A%0A"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Bridge", attributes_hash={:privilege=>"call,all", :bridgestate=>"Link", :bridgetype=>"core", :channel1=>"SIP/placetel.de-00000006", :channel2=>"SIP/placetel.de-00000005", :uniqueid1=>"1366590748.8", :uniqueid2=>"1366590752.9", :callerid1=>"SIP/+498941150126", :callerid2=>"+498941150126"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"BRIDGEPEER", :value=>"SIP/placetel.de-00000005", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Bridge", attributes_hash={:privilege=>"call,all", :bridgestate=>"Link", :bridgetype=>"core", :channel1=>"SIP/placetel.de-00000006", :channel2=>"SIP/placetel.de-00000005", :uniqueid1=>"1366590748.8", :uniqueid2=>"1366590752.9", :callerid1=>"SIP/+498941150126", :callerid2=>"+498941150126"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"Bridge/SIP/placetel.de-00000005<ZOMBIE>"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"BRIDGEPVTCALLID", :value=>"46B8AB64-5174851B00045057-FC8E1700", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"BRIDGEPEER", :value=>"SIP/placetel.de-00000006", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"BRIDGEPVTCALLID", :value=>"072861f04fa1c2a3440310d20b8a2f0f@fpbx.de", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Joined call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", mixer_name=nil, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:32] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Joined call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", mixer_name=nil, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOS", :value=>"ssrc=1525457262;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSBRIDGED", :value=>"ssrc=1525457262;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSJITTER", :value=>"minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSJITTERBRIDGED", :value=>"minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSLOSS", :value=>"minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSLOSSBRIDGED", :value=>"minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSRTTBRIDGED", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSRTT", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOS", :value=>"ssrc=734316550;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSBRIDGED", :value=>"ssrc=734316550;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSJITTER", :value=>"minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSJITTERBRIDGED", :value=>"minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSLOSS", :value=>"minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSLOSSBRIDGED", :value=>"minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"RTPAUDIOQOSRTTBRIDGED", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSRTT", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Bridge", attributes_hash={:privilege=>"call,all", :bridgestate=>"Unlink", :bridgetype=>"core", :channel1=>"SIP/placetel.de-00000006", :channel2=>"SIP/placetel.de-00000005", :uniqueid1=>"1366590748.8", :uniqueid2=>"1366590752.9", :callerid1=>"SIP/+498941150126", :callerid2=>"+498941150126"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Bridge", attributes_hash={:privilege=>"call,all", :bridgestate=>"Unlink", :bridgetype=>"core", :channel1=>"SIP/placetel.de-00000006", :channel2=>"SIP/placetel.de-00000005", :uniqueid1=>"1366590748.8", :uniqueid2=>"1366590752.9", :callerid1=>"SIP/+498941150126", :callerid2=>"+498941150126"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="HangupRequest", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"BRIDGERESULT", :value=>"SUCCESS", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/placetel.de-00000006", :commandid=>"1605142416", :command=>"EXEC Bridge \"SIP/placetel.de-00000005\"", :resultcode=>"200", :result=>"Success"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/placetel.de-00000006", :commandid=>"d4ff1c4c-4336-4639-a8ab-3c9310d2c5ca", :result=>"200%20result%3D0%0A"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="SoftHangupRequest", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000005", :uniqueid=>"1366590752.9", :cause=>"16"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/placetel.de-00000006"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newexten", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :context=>"adhearsion", :extension=>"h", :priority=>"1", :application=>"AGI", :appdata=>"agi:async", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000006", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1366590748.8"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000006", :uniqueid=>"1366590748.8", :calleridnum=>"SIP/+498941150126", :calleridname=>"unknown", :connectedlinenum=>"SIP/+498941150126", :connectedlinename=>"unknown", :accountcode=>"", :cause=>"16", :cause_txt=>"Normal Clearing"}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/placetel.de-00000005", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fplacetel.de-00000005%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201366590752.9%0Aagi_version%3A%2011.3.0%0Aagi_callerid%3A%20%2B498941150126%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20498912509582%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%204393988096%0A%0A"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] INFO  Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Call ended
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/placetel.de-00000005"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::OutboundCall: 12132a5b-6454-43ab-9d1d-5b4049135e94: Receiving message: #<Punchblock::Event::Unjoined call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", mixer_name=nil, target_call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOS", :value=>"ssrc=734316550;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSJITTER", :value=>"minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSLOSS", :value=>"minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOSRTT", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/placetel.de-00000005", :variable=>"RTPAUDIOQOS", :value=>"ssrc=734316550;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1366590752.9"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/placetel.de-00000005", :uniqueid=>"1366590752.9", :calleridnum=>"+498941150126", :calleridname=>"<unknown>", :connectedlinenum=>"<unknown>", :connectedlinename=>"<unknown>", :accountcode=>"", :cause=>"0", :cause_txt=>"Unknown"}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::Unjoined call_id="12132a5b-6454-43ab-9d1d-5b4049135e94", mixer_name=nil, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="27b79b14-aaf8-4f63-af1a-78a6643e8084", component_id=nil, target_mixer_name=nil>
[2013-04-22 02:32:34] INFO  Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Call ended
[2013-04-22 02:32:34] DEBUG Adhearsion::CallController::Dial::Dial: #dial finished. Hanging up 1 outbound calls: 12132a5b-6454-43ab-9d1d-5b4049135e94.
[2013-04-22 02:32:34] INFO  Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Call was hung up
[2013-04-22 02:32:35] DEBUG Adhearsion::Call: 27b79b14-aaf8-4f63-af1a-78a6643e8084: Finished executing controller #<Test call=27b79b14-aaf8-4f63-af1a-78a6643e8084, metadata={}>
benlangfeld commented 11 years ago

Thanks for report. Please provide logs at trace level so that we may properly assist.

gersmann commented 11 years ago

Hi Ben,

thanks for the quick feedback. I have attached the trace log. Please note that changing the log level to trace changed the predictability of the results. I actually had one case now where the dial plan was executed as expected, another case where the second number was called, even though the inbound call was hung up after ending the first outbound call. The trace shows the behavior I originally reported.

https://gist.github.com/gersmann/f51a5f71d73e931d09c2

Best regards

benlangfeld commented 11 years ago

@polysics is apparently also seeing this. Can one (or both :+1:) of you please try bisecting Adhearsion/Punchblock to locate the commit that broke this? That'll help me get you a resolution much faster :)

JustinAiken commented 11 years ago

There's a guide to doing that here, http://mojolingo.com/blog/2013/using-git-bisect-to-troubleshoot-ruby-gems/ btw ;)

gersmann commented 11 years ago

Hi Ben,

re. your recommendation to bisect the gems: I have tested on a completely different configuration: freeswitch (1.4), ruby 1.9.3, adhearsion 2.2.1 and punchblock 1.8.0.

I still have the same problem, so I am not sure what is going on here. Maybe I have a misconception re. the adhearsion API.

If I define two dial statements in a CallController like: dial 'user/1000@192.168.2.112' dial 'user/1001@192.168.2.112' What is the expected behaviour? Should the inbound leg be hung up after the first outbound call is terminated?

Best regards

benlangfeld commented 11 years ago

No, it should not. I just remembered what you'll need, which is to set the following channel variables in your FreeSWITCH dialplan prior to parking:

http://wiki.freeswitch.org/wiki/Variable_hangup_after_bridge = false http://wiki.freeswitch.org/wiki/Variable_park_after_bridge = true

If you could confirm that these work and propose a documentation update ( https://github.com/adhearsion/adhearsion-website/blob/master/views/docs/getting-started/freeswitch.mdand https://github.com/adhearsion/adhearsion/blob/develop/lib/adhearsion/generators/app/templates/README.md) that would be awesome :)

gersmann commented 11 years ago

Hi Ben,

yes, the issue has been resolved for Freeswitch by updating the configuration as recommended. Strange, that I experienced exactly the same behavior with Asterisk. Is there a similar configuration setting for Asterisk?

Best regards

benlangfeld commented 11 years ago

@bklang or @polysics will be able to answer about Asterisk better than I.

benlangfeld commented 11 years ago

Thanks, I've merged those two PRs :)

benlangfeld commented 10 years ago

See https://github.com/adhearsion/punchblock/issues/193 for further details on the issue on Asterisk.