Skip to content

Instantly share code, notes, and snippets.

@gemasergey

gemasergey/gist:3926706

Created October 21, 2012 11:15
Show Gist options
  • Save gemasergey/3926706 to your computer and use it in GitHub Desktop.
Save gemasergey/3926706 to your computer and use it in GitHub Desktop.
Download ZIP
Adhearsion::OutboundCall Event handler error
Raw
gistfile1.txt
Starting Adhearsion server at /root/rbox
[2012-10-21 14:13:45] TRACE Adhearsion::Initializer: OS: linux-gnu - RUBY: ruby 1.9.3
[2012-10-21 14:13:45] TRACE Adhearsion::Initializer: Environment: {"rvm_bin_path"=>"/usr/local/rvm/bin", "GEM_HOME"=>"/usr/local/rvm/gems/ruby-1.9.3-p286", "SHELL"=>"/bin/bash", "TERM"=>"xterm", "XDG_SESSION_COOKIE"=>"16e8c0ad735d1c8d9cb733834d57e3f8-1350809586.9319-1670370443", "IRBRC"=>"/usr/local/rvm/rubies/ruby-1.9.3-p286/.irbrc", "OLDPWD"=>"/root", "MY_RUBY_HOME"=>"/usr/local/rvm/rubies/ruby-1.9.3-p286", "USER"=>"root", "LS_COLORS"=>"rs=0:di=01;34:ln=01;36:hl=44;37:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arj=01;31:*.taz=01;31:*.lzh=01;31:*.lzma=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.rar=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.axa=00;36:*.oga=00;36:*.spx=00;36:*.xspf=00;36:", "SUDO_USER"=>"gemas", "__array_start"=>"0", "SUDO_UID"=>"1000", "rvm_path"=>"/usr/local/rvm", "USERNAME"=>"root", "escape_flag"=>"1", "rvm_prefix"=>"/usr/local", "PATH"=>"/usr/local/rvm/gems/ruby-1.9.3-p286/bin:/usr/local/rvm/gems/ruby-1.9.3-p286@global/bin:/usr/local/rvm/rubies/ruby-1.9.3-p286/bin:/usr/local/rvm/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games", "MAIL"=>"/var/mail/root", "PWD"=>"/root/rbox", "LANG"=>"C", "_second"=>"1", "rvm_version"=>"1.16.15 (stable)", "SHLVL"=>"1", "SUDO_COMMAND"=>"/bin/su", "HOME"=>"/root", "_first"=>"0", "LOGNAME"=>"root", "GEM_PATH"=>"/usr/local/rvm/gems/ruby-1.9.3-p286:/usr/local/rvm/gems/ruby-1.9.3-p286@global", "LESSOPEN"=>"| /usr/bin/lesspipe %s", "install_flag"=>"1", "SUDO_GID"=>"1000", "RUBY_VERSION"=>"ruby-1.9.3-p286", "LESSCLOSE"=>"/usr/bin/lesspipe %s %s", "_"=>"/usr/local/rvm/gems/ruby-1.9.3-p286/bin/ahn", "_ORIGINAL_GEM_PATH"=>"/usr/local/rvm/gems/ruby-1.9.3-p286:/usr/local/rvm/gems/ruby-1.9.3-p286@global", "BUNDLE_GEMFILE"=>"/root/rbox/Gemfile", "BUNDLE_BIN_PATH"=>"/usr/local/rvm/gems/ruby-1.9.3-p286@global/gems/bundler-1.2.1/bin/bundle", "RUBYOPT"=>"-I/usr/local/rvm/gems/ruby-1.9.3-p286@global/gems/bundler-1.2.1/lib -rbundler/setup"}
[2012-10-21 14:13:45] 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 = "callcenter"
# host where the database is installed [AHN_ADHEARSION_ACTIVERECORD_HOST]
config.adhearsion_activerecord.host = "192.168.2.55"
# 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 = "1221"
# 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 = "192.168.2.55"
# The media engine to use. Defaults to platform default. [AHN_PUNCHBLOCK_MEDIA_ENGINE]
config.punchblock.media_engine = nil
# The domain at which to address mixers [AHN_PUNCHBLOCK_MIXERS_DOMAIN]
config.punchblock.mixers_domain = nil
# Authentication credentials [AHN_PUNCHBLOCK_PASSWORD]
config.punchblock.password = "xxxxxxxx"
# 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 = "ahn"
# ******* 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 = "/root/rbox"
[2012-10-21 14:13:45] TRACE Adhearsion::Initializer: Gem versions: ["rake 0.9.2.2", "i18n 0.6.1", "multi_json 1.3.6", "activesupport 3.2.8", "builder 3.0.4", "activemodel 3.2.8", "arel 3.0.2", "tzinfo 0.3.33", "activerecord 3.2.8", "adhearsion-loquacious 1.9.3", "bundler 1.2.1", "facter 1.6.13", "timers 1.0.1", "celluloid 0.12.2", "countdownlatch 1.0.0", "deep_merge 1.0.0", "ffi 1.1.5", "future-resource 1.0.0", "connection_pool 0.9.2", "girl_friday 0.10.0", "has-guarded-handlers 1.3.1", "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.0.2", "blather 0.8.1", "nio4r 0.4.0", "celluloid-io 0.12.0", "ruby_ami 1.2.4", "json 1.7.5", "ruby_fs 1.0.1", "ruby_speech 1.0.0", "state_machine 1.1.2", "punchblock 1.5.1", "thor 0.16.0", "adhearsion 2.1.3", "adhearsion-activerecord 0.2.0", "adhearsion-asterisk 1.3.0", "mysql2 0.3.11"]
[2012-10-21 14:13:45] INFO Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2012-10-21 14:13:45] INFO Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: Starting up...
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: Starting up...
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Asterisk Call Manager/1.1
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Asterisk Call Manager/1.1
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Stream::Connected:0xaaaa320>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [SEND]: Action: login
ActionID: 90597e97-7b60-4120-a9da-e228f8a1bcb2
Username: ahn
Secret: dtxyjcnm
Events: On
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Stream::Connected:0xaaaa3c0>
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [SEND] Action: login
ActionID: e2832776-43f9-40a5-a77f-748002a90207
Username: ahn
Secret: dtxyjcnm
Events: On
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [SEND] Action: login
ActionID: 90597e97-7b60-4120-a9da-e228f8a1bcb2
Username: ahn
Secret: dtxyjcnm
Events: On
[2012-10-21 14:13:45] INFO Adhearsion::Console: Launching Adhearsion Console
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Response: Success
ActionID: 90597e97-7b60-4120-a9da-e228f8a1bcb2
Message: Authentication accepted
Event: FullyBooted
Privilege: system,all
Status: Fully Booted
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"90597e97-7b60-4120-a9da-e228f8a1bcb2", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Response: Success
ActionID: e2832776-43f9-40a5-a77f-748002a90207
Message: Authentication accepted
Event: FullyBooted
Privilege: system,all
Status: Fully Booted
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
AHN> [2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"e2832776-43f9-40a5-a77f-748002a90207", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"90597e97-7b60-4120-a9da-e228f8a1bcb2", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [QUEUE]: Action: events
ActionID: bb62ae7c-ff6a-4a48-ba3f-d83addd2f7b0
EventMask: Off
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Response headers={"ActionID"=>"e2832776-43f9-40a5-a77f-748002a90207", "Message"=>"Authentication accepted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [SEND]: Action: events
ActionID: bb62ae7c-ff6a-4a48-ba3f-d83addd2f7b0
EventMask: Off
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [SEND] Action: events
ActionID: bb62ae7c-ff6a-4a48-ba3f-d83addd2f7b0
EventMask: Off
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [QUEUE]: Action: command
ActionID: 3aff8196-72b9-44eb-8327-c7d537ead929
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Response: Success
ActionID: bb62ae7c-ff6a-4a48-ba3f-d83addd2f7b0
Events: Off
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"bb62ae7c-ff6a-4a48-ba3f-d83addd2f7b0", "Events"=>"Off"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [QUEUE]: Action: command
ActionID: 79975695-60fd-427c-8f8b-adb0a974b02e
Command: dialplan show adhearsion-redirect
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"bb62ae7c-ff6a-4a48-ba3f-d83addd2f7b0", "Events"=>"Off"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:45] INFO Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2012-10-21 14:13:45] INFO Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2012-10-21 14:13:45] TRACE RubyAMI::Client: [SEND]: Action: command
ActionID: 3aff8196-72b9-44eb-8327-c7d537ead929
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect
[2012-10-21 14:13:45] INFO Adhearsion::Initializer: Adhearsion v2.1.3 initialized in "development"!
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [SEND] Action: command
ActionID: 3aff8196-72b9-44eb-8327-c7d537ead929
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Response: Follows
Privilege: Command
ActionID: 3aff8196-72b9-44eb-8327-c7d537ead929
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Extension '1,1,AGI(agi:async)' added into 'adhearsion-redirect' context
--END COMMAND--
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"3aff8196-72b9-44eb-8327-c7d537ead929", "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-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"3aff8196-72b9-44eb-8327-c7d537ead929", "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-10-21 14:13:45] TRACE RubyAMI::Client: [SEND]: Action: command
ActionID: 79975695-60fd-427c-8f8b-adb0a974b02e
Command: dialplan show adhearsion-redirect
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [SEND] Action: command
ActionID: 79975695-60fd-427c-8f8b-adb0a974b02e
Command: dialplan show adhearsion-redirect
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] Response: Follows
Privilege: Command
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] ActionID: 79975695-60fd-427c-8f8b-adb0a974b02e
[ Context 'adhearsion-redirect' created by 'pbx_config' ]
'1' => 1. AGI(agi:async) [pbx_config]
-= 1 extension (1 priority) in 1 context. =-
--END COMMAND--
[2012-10-21 14:13:45] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"79975695-60fd-427c-8f8b-adb0a974b02e"}, 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-10-21 14:13:45] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"79975695-60fd-427c-8f8b-adb0a974b02e"}, 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-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/rivas-00000047
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 0577602602
CallerIDName: 0577602602
AccountCode:
Exten: 7867399
Context: from-ahn
Uniqueid: 1350817926.71
Event: VarSet
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Variable: SIPURI
Value: sip:0577602602@192.168.2.112:5060
Uniqueid: 1350817926.71
Event: VarSet
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Variable: SIPDOMAIN
Value: 192.168.2.55
Uniqueid: 1350817926.71
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "AccountCode"=>"", "Exten"=>"7867399", "Context"=>"from-ahn", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"SIPURI", "Value"=>"sip:0577602602@192.168.2.112:5060", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.2.55", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "AccountCode"=>"", "Exten"=>"7867399", "Context"=>"from-ahn", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"SIPURI", "Value"=>"sip:0577602602@192.168.2.112:5060", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] Event: VarSet
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Variable: SIPCALLID
Value: 54e36e932f75ca8b0d85958a30522916@192.168.2.112:5060
Uniqueid: 1350817926.71
Event: Newstate
Privilege: call,all
Channel: SIP/rivas-00000047
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 0577602602
CallerIDName: 0577602602
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1350817926.71
Event: Newexten
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Context: from-ahn
Extension: 7867399
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1350817926.71
Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: SIP/rivas-00000047
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%207867399%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.2.55", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"SIPCALLID", "Value"=>"54e36e932f75ca8b0d85958a30522916@192.168.2.112:5060", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Context"=>"from-ahn", "Extension"=>"7867399", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"SIPCALLID", "Value"=>"54e36e932f75ca8b0d85958a30522916@192.168.2.112:5060", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%207867399%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Context"=>"from-ahn", "Extension"=>"7867399", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%207867399%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="7867399", from="0577602602 <SIP/0577602602>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/rivas-00000047", :x_agi_language=>"ru", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1350817926.71", :x_agi_version=>"1.8.13.1~dfsg-1", :x_agi_callerid=>"0577602602", :x_agi_calleridname=>"0577602602", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"7867399", :x_agi_rdnis=>"unknown", :x_agi_context=>"from-ahn", :x_agi_extension=>"7867399", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"-1279874192"}, call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0"
[2012-10-21 14:13:48] INFO Adhearsion::Router: Call 81dc7008-57c3-404c-80d2-5e2d309dadb0 selected route "default" (TestOutCall)
[2012-10-21 14:13:48] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: 4309f878-3aeb-46b3-81be-57991b0704b9
Channel: SIP/rivas-00000047
Command: EXEC RINGING
CommandID: 6b8296a0-42aa-45fe-850c-d6e7285b5a99
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: 4309f878-3aeb-46b3-81be-57991b0704b9
Channel: SIP/rivas-00000047
Command: EXEC RINGING
CommandID: 6b8296a0-42aa-45fe-850c-d6e7285b5a99
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [SEND] Action: agi
ActionID: 4309f878-3aeb-46b3-81be-57991b0704b9
Channel: SIP/rivas-00000047
Command: EXEC RINGING
CommandID: 6b8296a0-42aa-45fe-850c-d6e7285b5a99
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] Response: Success
ActionID: 4309f878-3aeb-46b3-81be-57991b0704b9
Message: Added AGI command to queue
[2012-10-21 14:13:48] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"4309f878-3aeb-46b3-81be-57991b0704b9", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:48] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"4309f878-3aeb-46b3-81be-57991b0704b9", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/rivas-00000047
CommandId: 179731926
Command: EXEC RINGING
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"179731926", "Command"=>"EXEC RINGING"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"179731926", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/rivas-00000047", "CommandID"=>"6b8296a0-42aa-45fe-850c-d6e7285b5a99", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/rivas-00000047
CommandId: 179731926
Command: EXEC RINGING
ResultCode: 200
Result: Success
Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/rivas-00000047
CommandID: 6b8296a0-42aa-45fe-850c-d6e7285b5a99
Result: 200%20result%3D0%0A
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"179731926", "Command"=>"EXEC RINGING"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"179731926", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/rivas-00000047", "CommandID"=>"6b8296a0-42aa-45fe-850c-d6e7285b5a99", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/rivas-00000047", :commandid=>"179731926", :command=>"EXEC RINGING", :resultcode=>"200", :result=>"Success"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/rivas-00000047", :commandid=>"179731926", :command=>"EXEC RINGING"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/rivas-00000047", :commandid=>"6b8296a0-42aa-45fe-850c-d6e7285b5a99", :result=>"200%20result%3D0%0A"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] INFO Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Executing controller #<TestOutCall call=81dc7008-57c3-404c-80d2-5e2d309dadb0, metadata={}>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Executing command #<Punchblock::Command::Reject reason=:busy, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: 95ef2ae1-a84f-42f5-aee0-ecf8d950b8cc
Channel: SIP/rivas-00000047
Command: EXEC Busy
CommandID: fd002c28-f4dc-4caa-94e0-ef29cd94eaad
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: 95ef2ae1-a84f-42f5-aee0-ecf8d950b8cc
Channel: SIP/rivas-00000047
Command: EXEC Busy
CommandID: fd002c28-f4dc-4caa-94e0-ef29cd94eaad
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [SEND] Action: agi
ActionID: 95ef2ae1-a84f-42f5-aee0-ecf8d950b8cc
Channel: SIP/rivas-00000047
Command: EXEC Busy
CommandID: fd002c28-f4dc-4caa-94e0-ef29cd94eaad
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Response: Success
ActionID: 95ef2ae1-a84f-42f5-aee0-ecf8d950b8cc
Message: Added AGI command to queue
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"95ef2ae1-a84f-42f5-aee0-ecf8d950b8cc", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"95ef2ae1-a84f-42f5-aee0-ecf8d950b8cc", "Message"=>"Added AGI command to queue"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/rivas-00000047
CommandId: 1360109905
Command: EXEC Busy
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"1360109905", "Command"=>"EXEC Busy"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"1360109905", "Command"=>"EXEC Busy"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Event: Newstate
Privilege: call,all
Channel: SIP/rivas-00000047
ChannelState: 7
ChannelStateDesc: Busy
CallerIDNum: 0577602602
CallerIDName: 0577602602
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1350817926.71
Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/rivas-00000047
CommandId: 1360109905
Command: EXEC Busy
ResultCode: 200
Result: Unknown Result
Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/rivas-00000047
CommandID: fd002c28-f4dc-4caa-94e0-ef29cd94eaad
Result: 200%20result%3D-1%0A
Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: SIP/rivas-00000047
Event: VarSet
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1350817926.71
Event: Newexten
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Context: from-ahn
Extension: h
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1350817926.71
Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: SIP/rivas-00000047
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A
Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: SIP/rivas-00000047
Event: VarSet
Privilege: dialplan,all
Channel: SIP/rivas-00000047
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1350817926.71
Event: Hangup
Privilege: call,all
Channel: SIP/rivas-00000047
Uniqueid: 1350817926.71
CallerIDNum: 0577602602
CallerIDName: 0577602602
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Cause: 0
Cause-txt: Unknown
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "ChannelState"=>"7", "ChannelStateDesc"=>"Busy", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"1360109905", "Command"=>"EXEC Busy", "ResultCode"=>"200", "Result"=>"Unknown Result"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/rivas-00000047", "CommandID"=>"fd002c28-f4dc-4caa-94e0-ef29cd94eaad", "Result"=>"200%20result%3D-1%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "ChannelState"=>"7", "ChannelStateDesc"=>"Busy", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047", "CommandId"=>"1360109905", "Command"=>"EXEC Busy", "ResultCode"=>"200", "Result"=>"Unknown Result"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/rivas-00000047", "CommandID"=>"fd002c28-f4dc-4caa-94e0-ef29cd94eaad", "Result"=>"200%20result%3D-1%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Context"=>"from-ahn", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Context"=>"from-ahn", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/rivas-00000047", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/rivas-00000047"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "Uniqueid"=>"1350817926.71", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/rivas-00000047", "Uniqueid"=>"1350817926.71", "CallerIDNum"=>"0577602602", "CallerIDName"=>"0577602602", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/rivas-00000047", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1350817926.71"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Offer to="7867399", from="0577602602 <SIP/0577602602>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/rivas-00000047", :x_agi_language=>"ru", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1350817926.71", :x_agi_version=>"1.8.13.1~dfsg-1", :x_agi_callerid=>"0577602602", :x_agi_calleridname=>"0577602602", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"7867399", :x_agi_rdnis=>"unknown", :x_agi_context=>"from-ahn", :x_agi_extension=>"7867399", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"-1279874192"}, call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0"
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/rivas-00000047", :commandid=>"1360109905", :command=>"EXEC Busy"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newstate", attributes_hash={:privilege=>"call,all", :channel=>"SIP/rivas-00000047", :channelstate=>"7", :channelstatedesc=>"Busy", :calleridnum=>"0577602602", :calleridname=>"0577602602", :connectedlinenum=>"", :connectedlinename=>"", :uniqueid=>"1350817926.71"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/rivas-00000047", :commandid=>"1360109905", :command=>"EXEC Busy", :resultcode=>"200", :result=>"Unknown Result"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::OutboundCall: : Executing command #<Punchblock::Command::Dial to="SIP/301", from="Sergei Gema <9090>", join=nil, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/rivas-00000047", :commandid=>"fd002c28-f4dc-4caa-94e0-ef29cd94eaad", :result=>"200%20result%3D-1%0A"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/rivas-00000047", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1350817926.71"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/rivas-00000047"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Newexten", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/rivas-00000047", :context=>"from-ahn", :extension=>"h", :priority=>"1", :application=>"AGI", :appdata=>"agi:async", :uniqueid=>"1350817926.71"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/rivas-00000047", :env=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Frivas-00000047%0Aagi_language%3A%20ru%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201350817926.71%0Aagi_version%3A%201.8.13.1~dfsg-1%0Aagi_callerid%3A%200577602602%0Aagi_calleridname%3A%200577602602%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207867399%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20from-ahn%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20-1279874192%0A%0A"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/rivas-00000047"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/rivas-00000047", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1350817926.71"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/rivas-00000047", :uniqueid=>"1350817926.71", :calleridnum=>"0577602602", :calleridname=>"0577602602", :connectedlinenum=>"<unknown>", :connectedlinename=>"<unknown>", :cause=>"0", :cause_txt=>"Unknown"}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="81dc7008-57c3-404c-80d2-5e2d309dadb0", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:13:49] INFO Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Call ended
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [QUEUE]: Action: originate
ActionID: 9c0621aa-28f4-4861-9e5f-29709a3b9916
Async: true
Application: AGI
Data: agi:async
Channel: SIP/301
Callerid: Sergei Gema <9090>
Variable: punchblock_call_id=4c642d1f-fb5f-44c2-91de-1d61799658c1
Timeout: 30000
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [SEND]: Action: originate
ActionID: 9c0621aa-28f4-4861-9e5f-29709a3b9916
Async: true
Application: AGI
Data: agi:async
Channel: SIP/301
Callerid: Sergei Gema <9090>
Variable: punchblock_call_id=4c642d1f-fb5f-44c2-91de-1d61799658c1
Timeout: 30000
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [SEND] Action: originate
ActionID: 9c0621aa-28f4-4861-9e5f-29709a3b9916
Async: true
Application: AGI
Data: agi:async
Channel: SIP/301
Callerid: Sergei Gema <9090>
Variable: punchblock_call_id=4c642d1f-fb5f-44c2-91de-1d61799658c1
Timeout: 30000
[2012-10-21 14:13:49] DEBUG Adhearsion::Call: 81dc7008-57c3-404c-80d2-5e2d309dadb0: Finished executing controller #<TestOutCall call=81dc7008-57c3-404c-80d2-5e2d309dadb0, metadata={}>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Response: Success
ActionID: 9c0621aa-28f4-4861-9e5f-29709a3b9916
Message: Originate successfully queued
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Response headers={"ActionID"=>"9c0621aa-28f4-4861-9e5f-29709a3b9916", "Message"=>"Originate successfully queued"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response headers={"ActionID"=>"9c0621aa-28f4-4861-9e5f-29709a3b9916", "Message"=>"Originate successfully queued"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/301-00000048
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context: phones
Uniqueid: 1350817926.72
Event: VarSet
Privilege: dialplan,all
Channel: SIP/301-00000048
Variable: SIPCALLID
Value: 0785870b15325c041d10e38a36ce9935@192.168.2.55:5060
Uniqueid: 1350817926.72
Event: VarSet
Privilege: dialplan,all
Channel: SIP/301-00000048
Variable: punchblock_call_id
Value: 4c642d1f-fb5f-44c2-91de-1d61799658c1
Uniqueid: 1350817926.72
Event: NewAccountCode
Privilege: call,all
Channel: SIP/301-00000048
Uniqueid: 1350817926.72
AccountCode:
OldAccountCode:
Event: NewCallerid
Privilege: call,all
Channel: SIP/301-00000048
CallerIDNum: 9090
CallerIDName: Sergei Gema
Uniqueid: 1350817926.72
CID-CallingPres: 0 (Presentation Allowed, Not Screened)
Event: ExtensionStatus
Privilege: call,all
Exten: 301
Context: hint
Hint: SIP/301
Status: 8
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"phones", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/301-00000048", "Variable"=>"SIPCALLID", "Value"=>"0785870b15325c041d10e38a36ce9935@192.168.2.55:5060", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"phones", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/301-00000048", "Variable"=>"punchblock_call_id", "Value"=>"4c642d1f-fb5f-44c2-91de-1d61799658c1", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/301-00000048", "Variable"=>"SIPCALLID", "Value"=>"0785870b15325c041d10e38a36ce9935@192.168.2.55:5060", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "Uniqueid"=>"1350817926.72", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/301-00000048", "Variable"=>"punchblock_call_id", "Value"=>"4c642d1f-fb5f-44c2-91de-1d61799658c1", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema", "Uniqueid"=>"1350817926.72", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "Uniqueid"=>"1350817926.72", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="ExtensionStatus", headers={"Privilege"=>"call,all", "Exten"=>"301", "Context"=>"hint", "Hint"=>"SIP/301", "Status"=>"8"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema", "Uniqueid"=>"1350817926.72", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="ExtensionStatus", headers={"Privilege"=>"call,all", "Exten"=>"301", "Context"=>"hint", "Hint"=>"SIP/301", "Status"=>"8"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] Event: Newstate
Privilege: call,all
Channel: SIP/301-00000048
ChannelState: 5
ChannelStateDesc: Ringing
CallerIDNum: 9090
CallerIDName: Sergei Gema
ConnectedLineNum: 9090
ConnectedLineName: Sergei Gema
Uniqueid: 1350817926.72
[2012-10-21 14:13:49] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "ChannelState"=>"5", "ChannelStateDesc"=>"Ringing", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema", "ConnectedLineNum"=>"9090", "ConnectedLineName"=>"Sergei Gema", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "ChannelState"=>"5", "ChannelStateDesc"=>"Ringing", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema", "ConnectedLineNum"=>"9090", "ConnectedLineName"=>"Sergei Gema", "Uniqueid"=>"1350817926.72"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:13:49] DEBUG Adhearsion::OutboundCall: 4c642d1f-fb5f-44c2-91de-1d61799658c1: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/301-00000048", :variable=>"punchblock_call_id", :value=>"4c642d1f-fb5f-44c2-91de-1d61799658c1", :uniqueid=>"1350817926.72"}, target_call_id="4c642d1f-fb5f-44c2-91de-1d61799658c1", component_id=nil, target_mixer_name=nil>
exit[2012-10-21 14:14:19] DEBUG RubyAMI::Client: [RECV] Event: PeerStatus
Privilege: system,all
ChannelType: SIP
Peer: SIP/rivas
PeerStatus: Registered
Address: 192.168.2.112:5060
[2012-10-21 14:14:19] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="PeerStatus", headers={"Privilege"=>"system,all", "ChannelType"=>"SIP", "Peer"=>"SIP/rivas", "PeerStatus"=>"Registered", "Address"=>"192.168.2.112:5060"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="PeerStatus", headers={"Privilege"=>"system,all", "ChannelType"=>"SIP", "Peer"=>"SIP/rivas", "PeerStatus"=>"Registered", "Address"=>"192.168.2.112:5060"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] DEBUG RubyAMI::Client: [RECV] Event: ExtensionStatus
Privilege: call,all
Exten: 301
Context: hint
Hint: SIP/301
Status: 0
Event: Hangup
Privilege: call,all
Channel: SIP/301-00000048
Uniqueid: 1350817926.72
CallerIDNum: 9090
CallerIDName: Sergei Gema
ConnectedLineNum: 9090
ConnectedLineName: Sergei Gema
Cause: 19
Cause-txt: User alerting, no answer
Event: OriginateResponse
Privilege: call,all
ActionID: 9c0621aa-28f4-4861-9e5f-29709a3b9916
Response: Failure
Channel: SIP/301
Context:
Exten:
Reason: 3
Uniqueid: <null>
CallerIDNum: 9090
CallerIDName: Sergei Gema
[2012-10-21 14:14:19] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="ExtensionStatus", headers={"Privilege"=>"call,all", "Exten"=>"301", "Context"=>"hint", "Hint"=>"SIP/301", "Status"=>"0"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "Uniqueid"=>"1350817926.72", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema", "ConnectedLineNum"=>"9090", "ConnectedLineName"=>"Sergei Gema", "Cause"=>"19", "Cause-txt"=>"User alerting, no answer"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="ExtensionStatus", headers={"Privilege"=>"call,all", "Exten"=>"301", "Context"=>"hint", "Hint"=>"SIP/301", "Status"=>"0"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] DEBUG RubyAMI::Client: [RECV] #<RubyAMI::Event name="OriginateResponse", headers={"Privilege"=>"call,all", "ActionID"=>"9c0621aa-28f4-4861-9e5f-29709a3b9916", "Response"=>"Failure", "Channel"=>"SIP/301", "Context"=>"", "Exten"=>"", "Reason"=>"3", "Uniqueid"=>"<null>", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/301-00000048", "Uniqueid"=>"1350817926.72", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema", "ConnectedLineNum"=>"9090", "ConnectedLineName"=>"Sergei Gema", "Cause"=>"19", "Cause-txt"=>"User alerting, no answer"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event name="OriginateResponse", headers={"Privilege"=>"call,all", "ActionID"=>"9c0621aa-28f4-4861-9e5f-29709a3b9916", "Response"=>"Failure", "Channel"=>"SIP/301", "Context"=>"", "Exten"=>"", "Reason"=>"3", "Uniqueid"=>"<null>", "CallerIDNum"=>"9090", "CallerIDName"=>"Sergei Gema"}, text_body=nil, events=nil, action=nil>
[2012-10-21 14:14:19] DEBUG Adhearsion::OutboundCall: 4c642d1f-fb5f-44c2-91de-1d61799658c1: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/301-00000048", :uniqueid=>"1350817926.72", :calleridnum=>"9090", :calleridname=>"Sergei Gema", :connectedlinenum=>"9090", :connectedlinename=>"Sergei Gema", :cause=>"19", :cause_txt=>"User alerting, no answer"}, target_call_id="4c642d1f-fb5f-44c2-91de-1d61799658c1", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:14:19] ERROR Adhearsion::OutboundCall: 4c642d1f-fb5f-44c2-91de-1d61799658c1: <Celluloid::DeadActorError> attempted to call a dead actor
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/celluloid-0.12.2/lib/celluloid/actor.rb:65:in `rescue in call'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/celluloid-0.12.2/lib/celluloid/actor.rb:62:in `call'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/adhearsion-2.1.3/lib/adhearsion/foundation/object.rb:17:in `logger'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/adhearsion-2.1.3/lib/adhearsion/call_controller.rb:61:in `logger'
/root/rbox/lib/main.rb:42:in `block in run'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:113:in `call'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:113:in `call_handler'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:85:in `block (3 levels) in trigger_handler'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:85:in `catch'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:85:in `block (2 levels) in trigger_handler'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:84:in `each'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:84:in `find'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:84:in `block in trigger_handler'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:83:in `catch'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/has-guarded-handlers-1.3.1/lib/has_guarded_handlers.rb:83:in `trigger_handler'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/adhearsion-2.1.3/lib/adhearsion/call.rb:101:in `block in deliver_message'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/adhearsion-2.1.3/lib/adhearsion/foundation/exception_handler.rb:5:in `catching_standard_errors'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/adhearsion-2.1.3/lib/adhearsion/call.rb:101:in `deliver_message'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/celluloid-0.12.2/lib/celluloid/calls.rb:99:in `dispatch'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/celluloid-0.12.2/lib/celluloid/actor.rb:323:in `block in handle_message'
/usr/local/rvm/gems/ruby-1.9.3-p286/gems/celluloid-0.12.2/lib/celluloid/tasks/task_fiber.rb:22:in `block in initialize'
[2012-10-21 14:14:19] DEBUG Adhearsion::OutboundCall: 4c642d1f-fb5f-44c2-91de-1d61799658c1: Receiving message: #<Punchblock::Event::End reason=:reject, headers_hash={}, target_call_id="4c642d1f-fb5f-44c2-91de-1d61799658c1", component_id=nil, target_mixer_name=nil>
[2012-10-21 14:14:19] INFO Adhearsion::OutboundCall: 4c642d1f-fb5f-44c2-91de-1d61799658c1: Call ended
AHN> exit
[2012-10-21 14:14:24] INFO Celluloid: Terminating 10 actors...
[2012-10-21 14:14:24] DEBUG RubyAMI::Client: Finalizing stream
[2012-10-21 14:14:24] DEBUG RubyAMI::Client: Finalizing stream
[2012-10-21 14:14:24] INFO Celluloid: Shutdown completed cleanly
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment