adhearsion.log

trace two-audio

[2012-12-09 19:37:52] TRACE Adhearsion::Initializer: OS: linux-gnu - RUBY: ruby 1.9.3
[2012-12-09 19:37:52] TRACE Adhearsion::Initializer: Environment: {"TERM"=>"screen", "SHELL"=>"/bin/bash", "SSH_CLIENT"=>"192.168.1.20 34758 22", "SSH_TTY"=>"/dev/pts/2", "USER"=>"bradleyd", "TMUX"=>"/tmp/shareds,6579,0", "PATH"=>"/var/lib/gems/1.9.1/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games", "MAIL"=>"/var/mail/bradleyd", "LC_MESSAGES"=>"en_US.UTF-8", "LC_COLLATE"=>"en_US.UTF-8", "PWD"=>"/home/bradleyd/vcs", "LANG"=>"C", "TMUX_PANE"=>"%5", "SHLVL"=>"2", "HOME"=>"/home/bradleyd", "LOGNAME"=>"bradleyd", "SSH_CONNECTION"=>"192.168.1.20 35357 192.168.1.21 22", "LC_CTYPE"=>"en_US.UTF-8", "OLDPWD"=>"/home/bradleyd/vcom", "_"=>"/usr/local/bin/ahn", "GEM_PATH"=>"/var/lib/gems/1.9.1:/home/bradleyd/.gem/ruby/1.9.1", "GEM_HOME"=>"/var/lib/gems/1.9.1", "BUNDLE_BIN_PATH"=>"/var/lib/gems/1.9.1/gems/bundler-1.2.1/bin/bundle", "BUNDLE_GEMFILE"=>"/home/bradleyd/vcs/Gemfile", "RUBYOPT"=>"-I/var/lib/gems/1.9.1/gems/bundler-1.2.1/lib -rbundler/setup"}
[2012-12-09 19:37:52] TRACE Adhearsion::Initializer:   # ******* Configuration for adhearsion_activerecord **************

  # Database adapter. It should be an adapter supported by ActiveRecord [AHN_ADHEARSION_ACTIVERECORD_ADAPTER]
  config.adhearsion_activerecord.adapter     = "mysql2"

  # Database to connect to. [AHN_ADHEARSION_ACTIVERECORD_DATABASE]
  config.adhearsion_activerecord.database    = "vcs"

  # host where the database is installed [AHN_ADHEARSION_ACTIVERECORD_HOST]
  config.adhearsion_activerecord.host        = "192.168.1.23"

  # paths to model files to load [AHN_ADHEARSION_ACTIVERECORD_MODEL_PATHS]
  config.adhearsion_activerecord.model_paths = []

  # valid password [AHN_ADHEARSION_ACTIVERECORD_PASSWORD]
  config.adhearsion_activerecord.password    = "zaqxsw2"

  # port where the database is listening [AHN_ADHEARSION_ACTIVERECORD_PORT]
  config.adhearsion_activerecord.port        = 3306

  # valid db username [AHN_ADHEARSION_ACTIVERECORD_USERNAME]
  config.adhearsion_activerecord.username    = "root"

  # ******* Configuration for punchblock **************

  # The domain at which to address calls [AHN_PUNCHBLOCK_CALLS_DOMAIN]
  config.punchblock.calls_domain       = nil

  # The amount of time to wait for a connection [AHN_PUNCHBLOCK_CONNECTION_TIMEOUT]
  config.punchblock.connection_timeout = 60

  # The default TTS voice to use. [AHN_PUNCHBLOCK_DEFAULT_VOICE]
  config.punchblock.default_voice      = nil

  # Host punchblock needs to connect (where rayo/asterisk/freeswitch is located) [AHN_PUNCHBLOCK_HOST]
  config.punchblock.host               = "127.0.0.1"

  # The media engine to use. Defaults to platform default. [AHN_PUNCHBLOCK_MEDIA_ENGINE]
  config.punchblock.media_engine       = :swift

  # The domain at which to address mixers [AHN_PUNCHBLOCK_MIXERS_DOMAIN]
  config.punchblock.mixers_domain      = nil

  # Authentication credentials [AHN_PUNCHBLOCK_PASSWORD]
  config.punchblock.password           = "dranoff"

  # Platform punchblock shall use to connect to the Telephony provider. Currently supported values:
  # - :xmpp
  # - :asterisk
  # - :freeswitch [AHN_PUNCHBLOCK_PLATFORM]
  config.punchblock.platform           = :asterisk

  # Port punchblock needs to connect [AHN_PUNCHBLOCK_PORT]
  config.punchblock.port               = 5038

  # The number of times to (re)attempt connection to the server [AHN_PUNCHBLOCK_RECONNECT_ATTEMPTS]
  config.punchblock.reconnect_attempts = Infinity

  # Delay between connection attempts [AHN_PUNCHBLOCK_RECONNECT_TIMER]
  config.punchblock.reconnect_timer    = 5

  # The root domain at which to address the server [AHN_PUNCHBLOCK_ROOT_DOMAIN]
  config.punchblock.root_domain        = nil

  # Authentication credentials [AHN_PUNCHBLOCK_USERNAME]
  config.punchblock.username           = "mark"

  # ******* Configuration for platform **************

  # Active environment. Supported values: development, production, staging, test [AHN_PLATFORM_ENVIRONMENT]
  config.platform.environment        = :development

  # Folder to include the own libraries to be used. Adhearsion loads any ruby file
  # located into this folder during the bootstrap process. Set to nil if you do not
  # want these files to be loaded. This folder is relative to the application root folder. [AHN_PLATFORM_LIB]
  config.platform.lib                = "lib"

  # Log configuration [AHN_PLATFORM_LOGGING]
  config.platform.logging

  # A log formatter to apply to all active outputters. If nil, the Adhearsion default formatter will be used. [AHN_PLATFORM_LOGGING_FORMATTER]
  config.platform.logging.formatter  = nil

  # Supported levels (in increasing severity) -- :trace < :debug < :info < :warn < :error < :fatal [AHN_PLATFORM_LOGGING_LEVEL]
  config.platform.logging.level      = :trace

  # An array of log outputters to use. The default is to log to stdout and log/adhearsion.log.
  # Each item must be either a string to use as a filename, or a valid Logging appender (see http://github.com/TwP/logging) [AHN_PLATFORM_LOGGING_OUTPUTTERS]
  config.platform.logging.outputters = ["log/adhearsion.log"]

  # Adhearsion process name, useful to make it easier to find in the process list
  # Pro tip: set this to your application's name and you can do "killall myapp"
  # Does not work under JRuby. [AHN_PLATFORM_PROCESS_NAME]
  config.platform.process_name       = "ahn"

  # Adhearsion application root folder [AHN_PLATFORM_ROOT]
  config.platform.root               = "/home/bradleyd/vcs"


[2012-12-09 19:37:52] TRACE Adhearsion::Initializer: Gem versions: ["bundler 1.2.1", "rake 10.0.2", "i18n 0.6.1", "multi_json 1.4.0", "activesupport 3.2.9", "builder 3.0.4", "activemodel 3.2.9", "arel 3.0.2", "tzinfo 0.3.35", "activerecord 3.2.9", "adhearsion-loquacious 1.9.3", "facter 1.6.16", "timers 1.0.1", "celluloid 0.12.3", "countdownlatch 1.0.0", "deep_merge 1.0.0", "ffi 1.2.0", "future-resource 1.0.0", "connection_pool 0.9.2", "rubinius-core-api 0.0.1", "rubinius-actor 0.0.2", "girl_friday 0.11.1", "has-guarded-handlers 1.5.0", "little-plugger 1.1.3", "logging 1.8.0", "coderay 1.0.8", "method_source 0.8.1", "slop 3.3.3", "pry 0.9.10", "eventmachine 1.0.0", "nokogiri 1.5.5", "niceogiri 1.1.1", "blather 0.8.1", "nio4r 0.4.3", "celluloid-io 0.12.0", "ruby_ami 1.2.5", "json 1.7.5", "ruby_fs 1.0.2", "ruby_speech 1.0.1", "state_machine 1.1.2", "punchblock 1.6.1", "thor 0.16.0", "adhearsion 2.1.3", "adhearsion-activerecord 0.2.0", "adhearsion-asterisk 1.3.0", "diff-lcs 1.1.3", "mysql2 0.3.11", "rspec-core 2.12.1", "rspec-expectations 2.12.0", "rspec-mocks 2.12.0", "rspec 2.12.0"]
[2012-12-09 19:37:52] INFO  Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2012-12-09 19:37:53] INFO  Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2012-12-09 19:37:53] INFO  Adhearsion::Console: Launching Adhearsion Console
[2012-12-09 19:37:53] DEBUG RubyAMI::Client: Starting up...
[2012-12-09 19:37:53] DEBUG RubyAMI::Client: Starting up...
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Asterisk Call Manager/1.1

[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Asterisk Call Manager/1.1

[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Stream::Connected:0x000000026812d8>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND]: Action: login
ActionID: 80324cd7-4197-4e2e-8c33-31e31952c149
Username: mark
Secret: dranoff
Events: On


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND] Action: login
ActionID: 80324cd7-4197-4e2e-8c33-31e31952c149
Username: mark
Secret: dranoff
Events: On


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Stream::Connected:0x0000000277b580>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND] Action: login
ActionID: 16e96800-62b0-436e-a285-f7d2ff75793a
Username: mark
Secret: dranoff
Events: On


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 80324cd7-4197-4e2e-8c33-31e31952c149
Message: Authentication accepted

Event: FullyBooted
Privilege: system,all
Status: Fully Booted


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"80324cd7-4197-4e2e-8c33-31e31952c149", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"80324cd7-4197-4e2e-8c33-31e31952c149", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 16e96800-62b0-436e-a285-f7d2ff75793a
Message: Authentication accepted

Event: FullyBooted
Privilege: system,all
Status: Fully Booted


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"16e96800-62b0-436e-a285-f7d2ff75793a", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [QUEUE]: Action: events
ActionID: 6afb8c76-1373-467b-8712-f3560911d41f
EventMask: Off


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Response headers={"ActionID"=>"16e96800-62b0-436e-a285-f7d2ff75793a", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND]: Action: events
ActionID: 6afb8c76-1373-467b-8712-f3560911d41f
EventMask: Off


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [QUEUE]: Action: command
ActionID: faa40b71-713a-4d0d-b6b4-99e72581f100
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [QUEUE]: Action: command
ActionID: 94c548e1-15a4-4f7a-9a06-1f2dd1c1097b
Command: dialplan show adhearsion-redirect


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND] Action: events
ActionID: 6afb8c76-1373-467b-8712-f3560911d41f
EventMask: Off


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 6afb8c76-1373-467b-8712-f3560911d41f
Events: Off


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"6afb8c76-1373-467b-8712-f3560911d41f", "Events"=>"Off"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"6afb8c76-1373-467b-8712-f3560911d41f", "Events"=>"Off"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:37:53] INFO  Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND]: Action: command
ActionID: faa40b71-713a-4d0d-b6b4-99e72581f100
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND] Action: command
ActionID: faa40b71-713a-4d0d-b6b4-99e72581f100
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Response: Follows
Privilege: Command
ActionID: faa40b71-713a-4d0d-b6b4-99e72581f100
Extension '1,1,AGI,agi:async' added into 'adhearsion-redirect' context
--END COMMAND--


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"faa40b71-713a-4d0d-b6b4-99e72581f100", "Extension '1,1,AGI,agi"=>"async' added into 'adhearsion-redirect' context\n--END COMMAND--"}, text_body="Extension '1,1,AGI,agi:async' added into 'adhearsion-redirect' context", events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"faa40b71-713a-4d0d-b6b4-99e72581f100", "Extension '1,1,AGI,agi"=>"async' added into 'adhearsion-redirect' context\n--END COMMAND--"}, text_body="Extension '1,1,AGI,agi:async' added into 'adhearsion-redirect' context", events=nil, action=nil>
[2012-12-09 19:37:53] INFO  Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND]: Action: command
ActionID: 94c548e1-15a4-4f7a-9a06-1f2dd1c1097b
Command: dialplan show adhearsion-redirect


[2012-12-09 19:37:53] INFO  Adhearsion::Initializer: Adhearsion v2.1.3 initialized in "development"!
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [SEND] Action: command
ActionID: 94c548e1-15a4-4f7a-9a06-1f2dd1c1097b
Command: dialplan show adhearsion-redirect


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] Response: Follows
Privilege: Command
ActionID: 94c548e1-15a4-4f7a-9a06-1f2dd1c1097b
[ Context 'adhearsion-redirect' created by 'pbx_config' ]
  '1' =>            1. AGI(agi:async)                             [pbx_config]

-= 1 extension (1 priority) in 1 context. =-
--END COMMAND--


[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"94c548e1-15a4-4f7a-9a06-1f2dd1c1097b"}, text_body="[ Context 'adhearsion-redirect' created by 'pbx_config' ]\n  '1' =>            1. AGI(agi:async)                             [pbx_config]\n\n-= 1 extension (1 priority) in 1 context. =-", events=nil, action=nil>
[2012-12-09 19:37:53] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"94c548e1-15a4-4f7a-9a06-1f2dd1c1097b"}, text_body="[ Context 'adhearsion-redirect' created by 'pbx_config' ]\n  '1' =>            1. AGI(agi:async)                             [pbx_config]\n\n-= 1 extension (1 priority) in 1 context. =-", events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/sip1-00000008
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 7278516359
CallerIDName: +17278516359
AccountCode: 
Exten: 8662338635
Context: adhearsion
Uniqueid: 1355099894.8

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: SIPURI
Value: sip:7278516359@64.2.142.28
Uniqueid: 1355099894.8

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: SIPDOMAIN
Value: 192.168.1.21
Uniqueid: 1355099894.8

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: SIPCALLID
Value: 4f405c493761d6fe028bada66be49523@64.2.142.28
Uniqueid: 1355099894.8

Event: Newstate
Privilege: call,all
Channel: SIP/sip1-00000008
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 7278516359
CallerIDName: +17278516359
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 1355099894.8

Event: Newexten
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Context: adhearsion
Extension: 8662338635
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1355099894.8


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "AccountCode"=>"", "Exten"=>"8662338635", "Context"=>"adhearsion", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"SIPURI", "Value"=>"sip:7278516359@64.2.142.28", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.1.21", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"SIPURI", "Value"=>"sip:7278516359@64.2.142.28", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "AccountCode"=>"", "Exten"=>"8662338635", "Context"=>"adhearsion", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"SIPCALLID", "Value"=>"4f405c493761d6fe028bada66be49523@64.2.142.28", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.1.21", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"SIPCALLID", "Value"=>"4f405c493761d6fe028bada66be49523@64.2.142.28", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Context"=>"adhearsion", "Extension"=>"8662338635", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000008
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000008%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%207278516359%0Aagi_calleridname%3A%20%2B17278516359%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%208662338635%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%208662338635%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933146687232%0A%0A


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Context"=>"adhearsion", "Extension"=>"8662338635", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000008%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%207278516359%0Aagi_calleridname%3A%20%2B17278516359%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%208662338635%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%208662338635%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933146687232%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000008%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%207278516359%0Aagi_calleridname%3A%20%2B17278516359%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%208662338635%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%208662338635%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933146687232%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="8662338635", from="+17278516359 <SIP/7278516359>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/sip1-00000008", :x_agi_language=>"en", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1355099894.8", :x_agi_version=>"1.8.10.1~dfsg-1ubuntu1", :x_agi_callerid=>"7278516359", :x_agi_calleridname=>"+17278516359", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"8662338635", :x_agi_rdnis=>"unknown", :x_agi_context=>"adhearsion", :x_agi_extension=>"8662338635", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"139933146687232"}, call_id="e644c75d-6e97-43ef-994b-785ba401e1cf"
[2012-12-09 19:38:14] INFO  Adhearsion::Router: Call e644c75d-6e97-43ef-994b-785ba401e1cf selected route "default" (InboundCallController)
[2012-12-09 19:38:14] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: 2e205af7-94a5-4c82-9e91-815e767516e3
Channel: SIP/sip1-00000008
Command: EXEC RINGING
CommandID: d38e3530-6baf-4447-a51a-d45fd58b89b1


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: 2e205af7-94a5-4c82-9e91-815e767516e3
Channel: SIP/sip1-00000008
Command: EXEC RINGING
CommandID: d38e3530-6baf-4447-a51a-d45fd58b89b1


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [SEND] Action: agi
ActionID: 2e205af7-94a5-4c82-9e91-815e767516e3
Channel: SIP/sip1-00000008
Command: EXEC RINGING
CommandID: d38e3530-6baf-4447-a51a-d45fd58b89b1


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 2e205af7-94a5-4c82-9e91-815e767516e3
Message: Added AGI command to queue


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"2e205af7-94a5-4c82-9e91-815e767516e3", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"2e205af7-94a5-4c82-9e91-815e767516e3", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000008
CommandId: 1910839833
Command: EXEC RINGING

Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/sip1-00000008
CommandId: 1910839833
Command: EXEC RINGING
ResultCode: 200
Result: Success

Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/sip1-00000008
CommandID: d38e3530-6baf-4447-a51a-d45fd58b89b1
Result: 200%20result%3D0%0A


[2012-12-09 19:38:14] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1910839833", "Command"=>"EXEC RINGING"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1910839833", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1910839833", "Command"=>"EXEC RINGING"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000008", "CommandID"=>"d38e3530-6baf-4447-a51a-d45fd58b89b1", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1910839833", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000008", "CommandID"=>"d38e3530-6baf-4447-a51a-d45fd58b89b1", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/sip1-00000008", :commandid=>"1910839833", :command=>"EXEC RINGING"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/sip1-00000008", :commandid=>"1910839833", :command=>"EXEC RINGING", :resultcode=>"200", :result=>"Success"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/sip1-00000008", :commandid=>"d38e3530-6baf-4447-a51a-d45fd58b89b1", :result=>"200%20result%3D0%0A"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Executing controller #<InboundCallController call=e644c75d-6e97-43ef-994b-785ba401e1cf, metadata={}>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Offer to="8662338635", from="+17278516359 <SIP/7278516359>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/sip1-00000008", :x_agi_language=>"en", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1355099894.8", :x_agi_version=>"1.8.10.1~dfsg-1ubuntu1", :x_agi_callerid=>"7278516359", :x_agi_calleridname=>"+17278516359", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"8662338635", :x_agi_rdnis=>"unknown", :x_agi_context=>"adhearsion", :x_agi_extension=>"8662338635", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"139933146687232"}, call_id="e644c75d-6e97-43ef-994b-785ba401e1cf"
[2012-12-09 19:38:15] DEBUG Adhearsion::ActiveRecord::Plugin::Service:   Did Load (0.8ms)  SELECT `pbx_DIDs`.* FROM `pbx_DIDs` WHERE `pbx_DIDs`.`Number` = '8662338635' LIMIT 1
[2012-12-09 19:38:15] DEBUG Adhearsion::ActiveRecord::Plugin::Service:   ForwardingNumber Load (0.7ms)  SELECT `pbx_ForwardingNumbers`.* FROM `pbx_ForwardingNumbers` WHERE `pbx_ForwardingNumbers`.`ID` = 6 LIMIT 1
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: 56c0c508-7f9d-46cd-a7ab-413dc0a28407
Channel: SIP/sip1-00000008
Command: ANSWER
CommandID: 8f1c6ed4-9dd8-473d-83e0-fbf269682543


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: 56c0c508-7f9d-46cd-a7ab-413dc0a28407
Channel: SIP/sip1-00000008
Command: ANSWER
CommandID: 8f1c6ed4-9dd8-473d-83e0-fbf269682543


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [SEND] Action: agi
ActionID: 56c0c508-7f9d-46cd-a7ab-413dc0a28407
Channel: SIP/sip1-00000008
Command: ANSWER
CommandID: 8f1c6ed4-9dd8-473d-83e0-fbf269682543


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 56c0c508-7f9d-46cd-a7ab-413dc0a28407
Message: Added AGI command to queue


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"56c0c508-7f9d-46cd-a7ab-413dc0a28407", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"56c0c508-7f9d-46cd-a7ab-413dc0a28407", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000008
CommandId: 620744626
Command: ANSWER

Event: Newstate
Privilege: call,all
Channel: SIP/sip1-00000008
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 7278516359
CallerIDName: +17278516359
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 1355099894.8


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"620744626", "Command"=>"ANSWER"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"620744626", "Command"=>"ANSWER"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/sip1-00000008
CommandId: 620744626
Command: ANSWER
ResultCode: 200
Result: Success

Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/sip1-00000008
CommandID: 8f1c6ed4-9dd8-473d-83e0-fbf269682543
Result: 200%20result%3D0%0A


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"620744626", "Command"=>"ANSWER", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000008", "CommandID"=>"8f1c6ed4-9dd8-473d-83e0-fbf269682543", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"620744626", "Command"=>"ANSWER", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000008", "CommandID"=>"8f1c6ed4-9dd8-473d-83e0-fbf269682543", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/sip1-00000008", :commandid=>"620744626", :command=>"ANSWER"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newstate", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000008", :channelstate=>"6", :channelstatedesc=>"Up", :calleridnum=>"7278516359", :calleridname=>"+17278516359", :connectedlinenum=>"", :connectedlinename=>"", :uniqueid=>"1355099894.8"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/sip1-00000008", :commandid=>"620744626", :command=>"ANSWER", :resultcode=>"200", :result=>"Success"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/sip1-00000008", :commandid=>"8f1c6ed4-9dd8-473d-83e0-fbf269682543", :result=>"200%20result%3D0%0A"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: FORWARD: 13334445555
[2012-12-09 19:38:15] DEBUG Adhearsion::ActiveRecord::Plugin::Service:   ForwardingNumber Load (1.1ms)  SELECT `pbx_ForwardingNumbers`.* FROM `pbx_ForwardingNumbers` WHERE `pbx_ForwardingNumbers`.`ID` = 1 LIMIT 1
[2012-12-09 19:38:15] DEBUG Adhearsion::OutboundCall: : Executing command #<Punchblock::Command::Dial to="SIP/17274600308@sip1", from="+17278516359 <SIP/7278516359>", join=nil, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [QUEUE]: Action: originate
ActionID: 53921281-01fd-48c3-9619-12871b5f4242
Async: true
Application: AGI
Data: agi:async
Channel: SIP/17274600308@sip1
Callerid: +17278516359 <SIP/7278516359>
Variable: punchblock_call_id=d33d285d-2559-4de1-84dc-9a281c431bbf


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [SEND]: Action: originate
ActionID: 53921281-01fd-48c3-9619-12871b5f4242
Async: true
Application: AGI
Data: agi:async
Channel: SIP/17274600308@sip1
Callerid: +17278516359 <SIP/7278516359>
Variable: punchblock_call_id=d33d285d-2559-4de1-84dc-9a281c431bbf


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [SEND] Action: originate
ActionID: 53921281-01fd-48c3-9619-12871b5f4242
Async: true
Application: AGI
Data: agi:async
Channel: SIP/17274600308@sip1
Callerid: +17278516359 <SIP/7278516359>
Variable: punchblock_call_id=d33d285d-2559-4de1-84dc-9a281c431bbf


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/sip1-00000009
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 
CallerIDName: 
AccountCode: 
Exten: 
Context: adhearsion
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: SIPCALLID
Value: 50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: punchblock_call_id
Value: d33d285d-2559-4de1-84dc-9a281c431bbf
Uniqueid: 1355099895.9

Event: NewAccountCode
Privilege: call,all
Channel: SIP/sip1-00000009
Uniqueid: 1355099895.9
AccountCode: 
OldAccountCode: 

Event: NewCallerid
Privilege: call,all
Channel: SIP/sip1-00000009
CallerIDNum: SIP/7278516359
CallerIDName: +17278516359
Uniqueid: 1355099895.9
CID-CallingPres: 0 (Presentation Allowed, Not Screened)


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"adhearsion", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"SIPCALLID", "Value"=>"50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 53921281-01fd-48c3-9619-12871b5f4242
Message: Originate successfully queued


[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"adhearsion", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"53921281-01fd-48c3-9619-12871b5f4242", "Message"=>"Originate successfully queued"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"punchblock_call_id", "Value"=>"d33d285d-2559-4de1-84dc-9a281c431bbf", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"SIPCALLID", "Value"=>"50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"53921281-01fd-48c3-9619-12871b5f4242", "Message"=>"Originate successfully queued"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099895.9", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359", "Uniqueid"=>"1355099895.9", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"punchblock_call_id", "Value"=>"d33d285d-2559-4de1-84dc-9a281c431bbf", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099895.9", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359", "Uniqueid"=>"1355099895.9", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"punchblock_call_id", :value=>"d33d285d-2559-4de1-84dc-9a281c431bbf", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:15] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewCallerid", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000009", :calleridnum=>"SIP/7278516359", :calleridname=>"+17278516359", :uniqueid=>"1355099895.9", :cid_callingpres=>"0 (Presentation Allowed, Not Screened)"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Event: Newstate
Privilege: call,all
Channel: SIP/sip1-00000009
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: SIP/7278516359
CallerIDName: +17278516359
ConnectedLineNum: SIP/7278516359
ConnectedLineName: +17278516359
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: punchblock_call_id
Value: d33d285d-2559-4de1-84dc-9a281c431bbf
Uniqueid: 1355099895.9

Event: NewAccountCode
Privilege: call,all
Channel: SIP/sip1-00000009
Uniqueid: 1355099895.9
AccountCode: 
OldAccountCode: 

Event: OriginateResponse
Privilege: call,all
ActionID: 53921281-01fd-48c3-9619-12871b5f4242
Response: Success
Channel: SIP/sip1-00000009
Context: 
Exten: 
Reason: 4
Uniqueid: 1355099895.9
CallerIDNum: SIP/7278516359
CallerIDName: +17278516359


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"SIP/7278516359", "ConnectedLineName"=>"+17278516359", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"punchblock_call_id", "Value"=>"d33d285d-2559-4de1-84dc-9a281c431bbf", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099895.9", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"punchblock_call_id", "Value"=>"d33d285d-2559-4de1-84dc-9a281c431bbf", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"SIP/7278516359", "ConnectedLineName"=>"+17278516359", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="OriginateResponse", headers={"Privilege"=>"call,all", "ActionID"=>"53921281-01fd-48c3-9619-12871b5f4242", "Response"=>"Success", "Channel"=>"SIP/sip1-00000009", "Context"=>"", "Exten"=>"", "Reason"=>"4", "Uniqueid"=>"1355099895.9", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000009
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20139933145163520%0A%0A


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099895.9", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="OriginateResponse", headers={"Privilege"=>"call,all", "ActionID"=>"53921281-01fd-48c3-9619-12871b5f4242", "Response"=>"Success", "Channel"=>"SIP/sip1-00000009", "Context"=>"", "Exten"=>"", "Reason"=>"4", "Uniqueid"=>"1355099895.9", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000009", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20139933145163520%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000009", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20139933145163520%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000009", :uniqueid=>"1355099895.9", :accountcode=>"", :oldaccountcode=>""}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"punchblock_call_id", :value=>"d33d285d-2559-4de1-84dc-9a281c431bbf", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newstate", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000009", :channelstate=>"6", :channelstatedesc=>"Up", :calleridnum=>"SIP/7278516359", :calleridname=>"+17278516359", :connectedlinenum=>"SIP/7278516359", :connectedlinename=>"+17278516359", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/sip1-00000009", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20139933145163520%0A%0A"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="OriginateResponse", attributes_hash={:privilege=>"call,all", :actionid=>"53921281-01fd-48c3-9619-12871b5f4242", :response=>"Success", :channel=>"SIP/sip1-00000009", :context=>"", :exten=>"", :reason=>"4", :uniqueid=>"1355099895.9", :calleridnum=>"SIP/7278516359", :calleridname=>"+17278516359"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::CallController::Dial::Dial: #dial joining call d33d285d-2559-4de1-84dc-9a281c431bbf to e644c75d-6e97-43ef-994b-785ba401e1cf
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: 1c600d73-ca65-4d12-a16c-78463aa05e40
Channel: SIP/sip1-00000008
Command: ANSWER
CommandID: 5d438157-d741-430b-8446-2179e91f95ba


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: 1c600d73-ca65-4d12-a16c-78463aa05e40
Channel: SIP/sip1-00000008
Command: ANSWER
CommandID: 5d438157-d741-430b-8446-2179e91f95ba


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [SEND] Action: agi
ActionID: 1c600d73-ca65-4d12-a16c-78463aa05e40
Channel: SIP/sip1-00000008
Command: ANSWER
CommandID: 5d438157-d741-430b-8446-2179e91f95ba


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: 1c600d73-ca65-4d12-a16c-78463aa05e40
Message: Added AGI command to queue


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"1c600d73-ca65-4d12-a16c-78463aa05e40", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"1c600d73-ca65-4d12-a16c-78463aa05e40", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000008
CommandId: 1100368610
Command: ANSWER


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1100368610", "Command"=>"ANSWER"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1100368610", "Command"=>"ANSWER"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/sip1-00000008
CommandId: 1100368610
Command: ANSWER
ResultCode: 200
Result: Success

Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/sip1-00000008
CommandID: 5d438157-d741-430b-8446-2179e91f95ba
Result: 200%20result%3D0%0A


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1100368610", "Command"=>"ANSWER", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000008", "CommandID"=>"5d438157-d741-430b-8446-2179e91f95ba", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000008", "CommandId"=>"1100368610", "Command"=>"ANSWER", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000008", "CommandID"=>"5d438157-d741-430b-8446-2179e91f95ba", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/sip1-00000008", :commandid=>"1100368610", :command=>"ANSWER"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/sip1-00000008", :commandid=>"1100368610", :command=>"ANSWER", :resultcode=>"200", :result=>"Success"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/sip1-00000008", :commandid=>"5d438157-d741-430b-8446-2179e91f95ba", :result=>"200%20result%3D0%0A"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Executing command #<Punchblock::Command::Join call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", mixer_name=nil, direction=nil, media=nil, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: de0a9c9a-c66a-4738-ad30-ce9dd0b51c1c
Channel: SIP/sip1-00000009
Command: EXEC Bridge "SIP/sip1-00000008"
CommandID: eb71d434-c3ed-424a-9975-04339d7ba140


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: de0a9c9a-c66a-4738-ad30-ce9dd0b51c1c
Channel: SIP/sip1-00000009
Command: EXEC Bridge "SIP/sip1-00000008"
CommandID: eb71d434-c3ed-424a-9975-04339d7ba140


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [SEND] Action: agi
ActionID: de0a9c9a-c66a-4738-ad30-ce9dd0b51c1c
Channel: SIP/sip1-00000009
Command: EXEC Bridge "SIP/sip1-00000008"
CommandID: eb71d434-c3ed-424a-9975-04339d7ba140


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Response: Success
ActionID: de0a9c9a-c66a-4738-ad30-ce9dd0b51c1c
Message: Added AGI command to queue


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"de0a9c9a-c66a-4738-ad30-ce9dd0b51c1c", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"de0a9c9a-c66a-4738-ad30-ce9dd0b51c1c", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000009
CommandId: 1142755243
Command: EXEC Bridge "SIP/sip1-00000008"

Event: Newchannel
Privilege: call,all
Channel: Bridge/SIP/sip1-00000008
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 
CallerIDName: 
AccountCode: 
Exten: 
Context: 
Uniqueid: 1355099902.10

Event: MusicOnHold
Privilege: call,all
State: Stop
Channel: SIP/sip1-00000008
UniqueID: 1355099894.8

Event: Newstate
Privilege: call,all
Channel: Bridge/SIP/sip1-00000008
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 
CallerIDName: 
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 1355099902.10

Event: Masquerade
Privilege: call,all
Clone: SIP/sip1-00000008
CloneState: Up
Original: Bridge/SIP/sip1-00000008
OriginalState: Up

Event: Rename
Privilege: call,all
Channel: SIP/sip1-00000008
Newname: SIP/sip1-00000008<MASQ>
Uniqueid: 1355099894.8

Event: Rename
Privilege: call,all
Channel: Bridge/SIP/sip1-00000008
Newname: SIP/sip1-00000008
Uniqueid: 1355099902.10

Event: Rename
Privilege: call,all
Channel: SIP/sip1-00000008<MASQ>
Newname: Bridge/SIP/sip1-00000008<ZOMBIE>
Uniqueid: 1355099894.8

Event: NewCallerid
Privilege: call,all
Channel: SIP/sip1-00000008
CallerIDNum: 7278516359
CallerIDName: +17278516359
Uniqueid: 1355099902.10
CID-CallingPres: 0 (Presentation Allowed, Not Screened)

Event: BridgeExec
Privilege: call,all
Response: Success
Channel1: SIP/sip1-00000009
Channel2: SIP/sip1-00000008

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: BRIDGEPEER
Value: SIP/sip1-00000008
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: BRIDGEPEER
Value: SIP/sip1-00000009
Uniqueid: 1355099902.10

Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>

Event: VarSet
Privilege: dialplan,all
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1355099894.8

Event: NewAccountCode
Privilege: call,all
Channel: SIP/sip1-00000008
Uniqueid: 1355099902.10
AccountCode: 
OldAccountCode: 

Event: Bridge
Privilege: call,all
Bridgestate: Link
Bridgetype: core
Channel1: SIP/sip1-00000009
Channel2: SIP/sip1-00000008
Uniqueid1: 1355099895.9
Uniqueid2: 1355099902.10
CallerID1: SIP/7278516359
CallerID2: 7278516359

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: BRIDGEPEER
Value: SIP/sip1-00000008
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: BRIDGEPVTCALLID
Value: 4f405c493761d6fe028bada66be49523@64.2.142.28
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: BRIDGEPEER
Value: SIP/sip1-00000009
Uniqueid: 1355099902.10

Event: Newexten
Privilege: dialplan,all
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>
Context: adhearsion
Extension: h
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1355099894.8

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: BRIDGEPVTCALLID
Value: 50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060
Uniqueid: 1355099902.10

Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>
Env: agi_request%3A%20async%0Aagi_channel%3A%20Bridge%2FSIP%2Fsip1-00000008%3CZOMBIE%3E%0Aagi_language%3A%20en%0Aagi_type%3A%20Kill%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20unknown%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%2064%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%20139933146687232%0A%0A

Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>


[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000009", "CommandId"=>"1142755243", "Command"=>"EXEC Bridge \"SIP/sip1-00000008\""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="MusicOnHold", headers={"Privilege"=>"call,all", "State"=>"Stop", "Channel"=>"SIP/sip1-00000008", "UniqueID"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000009", "CommandId"=>"1142755243", "Command"=>"EXEC Bridge \"SIP/sip1-00000008\""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"", "CallerIDName"=>"", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="MusicOnHold", headers={"Privilege"=>"call,all", "State"=>"Stop", "Channel"=>"SIP/sip1-00000008", "UniqueID"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"", "CallerIDName"=>"", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Masquerade", headers={"Privilege"=>"call,all", "Clone"=>"SIP/sip1-00000008", "CloneState"=>"Up", "Original"=>"Bridge/SIP/sip1-00000008", "OriginalState"=>"Up"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Rename", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "Newname"=>"SIP/sip1-00000008<MASQ>", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Rename", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008", "Newname"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Rename", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008<MASQ>", "Newname"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "Uniqueid"=>"1355099902.10", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Masquerade", headers={"Privilege"=>"call,all", "Clone"=>"SIP/sip1-00000008", "CloneState"=>"Up", "Original"=>"Bridge/SIP/sip1-00000008", "OriginalState"=>"Up"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Rename", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "Newname"=>"SIP/sip1-00000008<MASQ>", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="BridgeExec", headers={"Privilege"=>"call,all", "Response"=>"Success", "Channel1"=>"SIP/sip1-00000009", "Channel2"=>"SIP/sip1-00000008"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Rename", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008", "Newname"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Rename", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008<MASQ>", "Newname"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "Uniqueid"=>"1355099902.10", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="MusicOnHold", attributes_hash={:privilege=>"call,all", :state=>"Stop", :channel=>"SIP/sip1-00000008", :uniqueid=>"1355099894.8"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="BridgeExec", headers={"Privilege"=>"call,all", "Response"=>"Success", "Channel1"=>"SIP/sip1-00000009", "Channel2"=>"SIP/sip1-00000008"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099902.10", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Bridge", headers={"Privilege"=>"call,all", "Bridgestate"=>"Link", "Bridgetype"=>"core", "Channel1"=>"SIP/sip1-00000009", "Channel2"=>"SIP/sip1-00000008", "Uniqueid1"=>"1355099895.9", "Uniqueid2"=>"1355099902.10", "CallerID1"=>"SIP/7278516359", "CallerID2"=>"7278516359"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGEPVTCALLID", "Value"=>"4f405c493761d6fe028bada66be49523@64.2.142.28", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Rename", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000008", :newname=>"SIP/sip1-00000008<MASQ>", :uniqueid=>"1355099894.8"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Context"=>"adhearsion", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"BRIDGEPVTCALLID", "Value"=>"50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Bridge", headers={"Privilege"=>"call,all", "Bridgestate"=>"Link", "Bridgetype"=>"core", "Channel1"=>"SIP/sip1-00000009", "Channel2"=>"SIP/sip1-00000008", "Uniqueid1"=>"1355099895.9", "Uniqueid2"=>"1355099902.10", "CallerID1"=>"SIP/7278516359", "CallerID2"=>"7278516359"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20Bridge%2FSIP%2Fsip1-00000008%3CZOMBIE%3E%0Aagi_language%3A%20en%0Aagi_type%3A%20Kill%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20unknown%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%2064%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%20139933146687232%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099902.10", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] Event: VarSet
Privilege: dialplan,all
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1355099894.8

Event: Hangup
Privilege: call,all
Channel: Bridge/SIP/sip1-00000008<ZOMBIE>
Uniqueid: 1355099894.8
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Cause: 0
Cause-txt: Unknown


[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewCallerid", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000008", :calleridnum=>"7278516359", :calleridname=>"+17278516359", :uniqueid=>"1355099902.10", :cid_callingpres=>"0 (Presentation Allowed, Not Screened)"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGEPVTCALLID", "Value"=>"4f405c493761d6fe028bada66be49523@64.2.142.28", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"BRIDGEPEER", "Value"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Context"=>"adhearsion", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"BRIDGEPVTCALLID", "Value"=>"50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20Bridge%2FSIP%2Fsip1-00000008%3CZOMBIE%3E%0Aagi_language%3A%20en%0Aagi_type%3A%20Kill%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20unknown%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%2064%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%20139933146687232%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/sip1-00000009", :commandid=>"1142755243", :command=>"EXEC Bridge \"SIP/sip1-00000008\""}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"BRIDGEPEER", :value=>"SIP/sip1-00000008", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="BridgeExec", attributes_hash={:privilege=>"call,all", :response=>"Success", :channel1=>"SIP/sip1-00000009", :channel2=>"SIP/sip1-00000008"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"Bridge/SIP/sip1-00000008<ZOMBIE>"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Bridge", attributes_hash={:privilege=>"call,all", :bridgestate=>"Link", :bridgetype=>"core", :channel1=>"SIP/sip1-00000009", :channel2=>"SIP/sip1-00000008", :uniqueid1=>"1355099895.9", :uniqueid2=>"1355099902.10", :callerid1=>"SIP/7278516359", :callerid2=>"7278516359"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="BridgeExec", attributes_hash={:privilege=>"call,all", :response=>"Success", :channel1=>"SIP/sip1-00000009", :channel2=>"SIP/sip1-00000008"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"BRIDGEPEER", :value=>"SIP/sip1-00000008", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"BRIDGEPEER", :value=>"SIP/sip1-00000009", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"BRIDGEPVTCALLID", :value=>"4f405c493761d6fe028bada66be49523@64.2.142.28", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Bridge", attributes_hash={:privilege=>"call,all", :bridgestate=>"Link", :bridgetype=>"core", :channel1=>"SIP/sip1-00000009", :channel2=>"SIP/sip1-00000008", :uniqueid1=>"1355099895.9", :uniqueid2=>"1355099902.10", :callerid1=>"SIP/7278516359", :callerid2=>"7278516359"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Uniqueid"=>"1355099894.8", "CallerIDNum"=>"<unknown>", "CallerIDName"=>"<unknown>", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000008", :uniqueid=>"1355099902.10", :accountcode=>"", :oldaccountcode=>""}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099894.8"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"BRIDGEPEER", :value=>"SIP/sip1-00000009", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"Bridge/SIP/sip1-00000008<ZOMBIE>", "Uniqueid"=>"1355099894.8", "CallerIDNum"=>"<unknown>", "CallerIDName"=>"<unknown>", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"BRIDGEPVTCALLID", :value=>"50e35dc21eaa9f60676dfd75542389d6@192.168.1.21:5060", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"Bridge/SIP/sip1-00000008<ZOMBIE>"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"Bridge/SIP/sip1-00000008<ZOMBIE>", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20Bridge%2FSIP%2Fsip1-00000008%3CZOMBIE%3E%0Aagi_language%3A%20en%0Aagi_type%3A%20Kill%0Aagi_uniqueid%3A%201355099894.8%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20unknown%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%2064%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%20139933146687232%0A%0A"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Joined call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", mixer_name=nil, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:22] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Joined call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", mixer_name=nil, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: RTPAUDIOQOS
Value: ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000
Uniqueid: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOSBRIDGED
Value: ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
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: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
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: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
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: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
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: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: RTPAUDIOQOSRTT
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOSRTTBRIDGED
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOS
Value: ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: RTPAUDIOQOSBRIDGED
Value: ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000
Uniqueid: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
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: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
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: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
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: 1355099895.9


[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSBRIDGED", "Value"=>"ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"RTPAUDIOQOS", :value=>"ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSBRIDGED", "Value"=>"ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :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=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOSBRIDGED", :value=>"ssrc=565654478;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :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=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSRTTBRIDGED", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :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=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :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=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSRTTBRIDGED", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOSBRIDGED", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"RTPAUDIOQOSRTT", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOSBRIDGED", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
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: 1355099902.10

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOSRTT
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000008
Variable: RTPAUDIOQOSRTTBRIDGED
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1355099902.10

Event: Unlink
Privilege: call,all
Channel1: SIP/sip1-00000009
Channel2: SIP/sip1-00000008
Uniqueid1: 1355099895.9
Uniqueid2: 1355099902.10
CallerID1: SIP/7278516359
CallerID2: 7278516359

Event: Newexten
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Context: adhearsion
Extension: h
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1355099895.9

Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: SIP/sip1-00000009
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933145163520%0A%0A

Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: SIP/sip1-00000009

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: BRIDGERESULT
Value: SUCCESS
Uniqueid: 1355099895.9

Event: Hangup
Privilege: call,all
Channel: SIP/sip1-00000008
Uniqueid: 1355099902.10
CallerIDNum: 7278516359
CallerIDName: +17278516359
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Cause: 0
Cause-txt: Unknown

Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/sip1-00000009
CommandId: 1142755243
Command: EXEC Bridge "SIP/sip1-00000008"
ResultCode: 200
Result: Success

Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/sip1-00000009
CommandID: eb71d434-c3ed-424a-9975-04339d7ba140
Result: 200%20result%3D0%0A

Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: SIP/sip1-00000009

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOS
Value: ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
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: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
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: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOSRTT
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1355099895.9

Event: VarSet
Privilege: dialplan,all
Channel: SIP/sip1-00000009
Variable: RTPAUDIOQOS
Value: ssrc=1315579955;themssrc=0;lp=0;rxji
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOSRTTBRIDGED", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOS", :value=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOSRTTBRIDGED", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "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"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Unlink", headers={"Privilege"=>"call,all", "Channel1"=>"SIP/sip1-00000009", "Channel2"=>"SIP/sip1-00000008", "Uniqueid1"=>"1355099895.9", "Uniqueid2"=>"1355099902.10", "CallerID1"=>"SIP/7278516359", "CallerID2"=>"7278516359"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Context"=>"adhearsion", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Unlink", headers={"Privilege"=>"call,all", "Channel1"=>"SIP/sip1-00000009", "Channel2"=>"SIP/sip1-00000008", "Uniqueid1"=>"1355099895.9", "Uniqueid2"=>"1355099902.10", "CallerID1"=>"SIP/7278516359", "CallerID2"=>"7278516359"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000008", "Variable"=>"RTPAUDIOQOSRTTBRIDGED", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099902.10"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000009", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933145163520%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000009"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :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=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/sip1-00000009", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933145163520%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Context"=>"adhearsion", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :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=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"RTPAUDIOQOSBRIDGED", :value=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000009"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGERESULT", "Value"=>"SUCCESS", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099902.10", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"BRIDGERESULT", "Value"=>"SUCCESS", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000008", "Uniqueid"=>"1355099902.10", "CallerIDNum"=>"7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000009", "CommandId"=>"1142755243", "Command"=>"EXEC Bridge \"SIP/sip1-00000008\"", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000009", "CommandID"=>"eb71d434-c3ed-424a-9975-04339d7ba140", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :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=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000009", "CommandId"=>"1142755243", "Command"=>"EXEC Bridge \"SIP/sip1-00000008\"", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Unlink", attributes_hash={:privilege=>"call,all", :channel1=>"SIP/sip1-00000009", :channel2=>"SIP/sip1-00000008", :uniqueid1=>"1355099895.9", :uniqueid2=>"1355099902.10", :callerid1=>"SIP/7278516359", :callerid2=>"7278516359"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000008", :variable=>"RTPAUDIOQOSRTTBRIDGED", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1355099902.10"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOSRTT", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000009"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :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=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/sip1-00000009"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Unlink", attributes_hash={:privilege=>"call,all", :channel1=>"SIP/sip1-00000009", :channel2=>"SIP/sip1-00000008", :uniqueid1=>"1355099895.9", :uniqueid2=>"1355099902.10", :callerid1=>"SIP/7278516359", :callerid2=>"7278516359"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/sip1-00000009", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fsip1-00000009%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201355099895.9%0Aagi_version%3A%201.8.10.1~dfsg-1ubuntu1%0Aagi_callerid%3A%20SIP%2F7278516359%0Aagi_calleridname%3A%20%2B17278516359%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%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139933145163520%0A%0A"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/sip1-00000009"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newexten", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :context=>"adhearsion", :extension=>"h", :priority=>"1", :application=>"AGI", :appdata=>"agi:async", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/sip1-00000009", "CommandID"=>"eb71d434-c3ed-424a-9975-04339d7ba140", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"BRIDGERESULT", :value=>"SUCCESS", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000008", :uniqueid=>"1355099902.10", :calleridnum=>"7278516359", :calleridname=>"+17278516359", :connectedlinenum=>"<unknown>", :connectedlinename=>"<unknown>", :cause=>"0", :cause_txt=>"Unknown"}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Call ended
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/sip1-00000009", :commandid=>"1142755243", :command=>"EXEC Bridge \"SIP/sip1-00000008\"", :resultcode=>"200", :result=>"Success"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Receiving message: #<Punchblock::Event::Unjoined call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", mixer_name=nil, target_call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/sip1-00000009", :commandid=>"eb71d434-c3ed-424a-9975-04339d7ba140", :result=>"200%20result%3D0%0A"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/sip1-00000009"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Unjoined call_id="e644c75d-6e97-43ef-994b-785ba401e1cf", mixer_name=nil, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::CallController::Dial::Dial: #dial finished. Hanging up 1 outbound calls: d33d285d-2559-4de1-84dc-9a281c431bbf.
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Hanging up
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Executing command #<Punchblock::Command::Hangup headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "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"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] tter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000
Uniqueid: 1355099895.9

Event: Hangup
Privilege: call,all
Channel: SIP/sip1-00000009
Uniqueid: 1355099895.9
CallerIDNum: SIP/7278516359
CallerIDName: +17278516359
ConnectedLineNum: SIP/7278516359
ConnectedLineName: +17278516359
Cause: 16
Cause-txt: Normal Clearing


[2012-12-09 19:38:57] TRACE RubyAMI::Client: [QUEUE]: Action: hangup
ActionID: d7782d4c-58f0-4404-b6ba-6ab1abbde6a1
Channel: SIP/sip1-00000009
Cause: 16


[2012-12-09 19:38:57] TRACE RubyAMI::Client: [SEND]: Action: hangup
ActionID: d7782d4c-58f0-4404-b6ba-6ab1abbde6a1
Channel: SIP/sip1-00000009
Cause: 16


[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099895.9", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"SIP/7278516359", "ConnectedLineName"=>"+17278516359", "Cause"=>"16", "Cause-txt"=>"Normal Clearing"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/sip1-00000009", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", "Uniqueid"=>"1355099895.9"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [SEND] Action: hangup
ActionID: d7782d4c-58f0-4404-b6ba-6ab1abbde6a1
Channel: SIP/sip1-00000009
Cause: 16


[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] Response: Error
ActionID: d7782d4c-58f0-4404-b6ba-6ab1abbde6a1
Message: No such channel


[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV] #<RubyAMI::Error message="No such channel", headers=>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Error message="No such channel", headers=>
[2012-12-09 19:38:57] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/sip1-00000009", "Uniqueid"=>"1355099895.9", "CallerIDNum"=>"SIP/7278516359", "CallerIDName"=>"+17278516359", "ConnectedLineNum"=>"SIP/7278516359", "ConnectedLineName"=>"+17278516359", "Cause"=>"16", "Cause-txt"=>"Normal Clearing"}, text_body=nil, events=nil, action=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOS", :value=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: THIS IS A TEST LOG ENTRY
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: CALL TO -> 8662338635,  CALL FROM -> +17278516359 <SIP/7278516359>
[2012-12-09 19:38:57] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: FROM DATABASE -> 8662338635
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOSRTT", :value=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Status: #<Did:0x000000045c7c28>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :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=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :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=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Call was hung up
[2012-12-09 19:38:57] DEBUG Adhearsion::Call: e644c75d-6e97-43ef-994b-785ba401e1cf: Finished executing controller #<InboundCallController call=e644c75d-6e97-43ef-994b-785ba401e1cf, metadata={}>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/sip1-00000009", :variable=>"RTPAUDIOQOS", :value=>"ssrc=1315579955;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000", :uniqueid=>"1355099895.9"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/sip1-00000009", :uniqueid=>"1355099895.9", :calleridnum=>"SIP/7278516359", :calleridname=>"+17278516359", :connectedlinenum=>"SIP/7278516359", :connectedlinename=>"+17278516359", :cause=>"16", :cause_txt=>"Normal Clearing"}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] DEBUG Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="d33d285d-2559-4de1-84dc-9a281c431bbf", component_id=nil, target_mixer_name=nil>
[2012-12-09 19:38:57] INFO  Adhearsion::OutboundCall: d33d285d-2559-4de1-84dc-9a281c431bbf: Call ended