search

adhearsion / adhearsion-asterisk

Asterisk specific features for Adhearsion
http://adhearsion.com
MIT License
17 stars 15 forks source link

undefined method `code' for #<Punchblock::Event::Complete::Hangup> #4

Closed chewi closed 12 years ago

chewi commented 12 years ago

Prematurely hanging up a call intermittently results in the error below. I'm not sure of the exact conditions required to reproduce.

[2012-05-16 14:21:19] DEBUG Adhearsion::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Executing command #<Punchblock::Component::Asterisk::AGI::Command name="EXEC SayDigits", params_array=["2600"], target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-16 14:21:19] DEBUG Punchblock::Translator::Asterisk::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Executing command: #<Punchblock::Component::Asterisk::AGI::Command name="EXEC SayDigits", params_array=["2600"], target_call_id="1b19d201-1db8-4f68-aad6-7c9c5224f39a", component_id=nil, target_mixer_name=nil, state_name=:requested>
[2012-05-16 14:21:19] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: 1b19d201-1db8-4f68-aad6-7c9c5224f39a, Component ID: e8c84fdb-1bee-495e-bb02-11bd148737ab: Starting up...
[2012-05-16 14:21:19] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: 1b19d201-1db8-4f68-aad6-7c9c5224f39a, Component ID: e8c84fdb-1bee-495e-bb02-11bd148737ab: Handling response: #<RubyAMI::Response:0x00000003fd0388 @headers={"ActionID"=>"ac57991e-f726-41bf-9499-dfd17c67c23c", "Message"=>"Added AGI command to queue"}, @action=Action: agi
ActionID: ac57991e-f726-41bf-9499-dfd17c67c23c
Channel: SIP/gigaset-00000014
Command: EXEC SayDigits "2600"
CommandID: e8c84fdb-1bee-495e-bb02-11bd148737ab

>
[2012-05-16 14:21:19] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: 1b19d201-1db8-4f68-aad6-7c9c5224f39a, Component ID: e8c84fdb-1bee-495e-bb02-11bd148737ab: Setting response on component node to #<Punchblock::Ref id="e8c84fdb-1bee-495e-bb02-11bd148737ab", target_call_id=nil, component_id=nil, target_mixer_name=nil>
[2012-05-16 14:21:21] WARN  Punchblock::Translator::Asterisk::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Could not find component for AMI event: #<RubyAMI::Event:0x007fb1742599c8 @headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-00000014"}, @name="AsyncAGI">
[2012-05-16 14:21:21] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: 1b19d201-1db8-4f68-aad6-7c9c5224f39a, Component ID: e8c84fdb-1bee-495e-bb02-11bd148737ab: Handling AMI event: #<RubyAMI::Event:0x007fb1741ad290 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000014", "CommandID"=>"e8c84fdb-1bee-495e-bb02-11bd148737ab", "Result"=>"200%20result%3D-1%0A"}, @name="AsyncAGI">
[2012-05-16 14:21:21] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: 1b19d201-1db8-4f68-aad6-7c9c5224f39a, Component ID: e8c84fdb-1bee-495e-bb02-11bd148737ab: Received AsyncAGI:Exec event, sending complete event.
[2012-05-16 14:21:21] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: 1b19d201-1db8-4f68-aad6-7c9c5224f39a, Component ID: e8c84fdb-1bee-495e-bb02-11bd148737ab: Sending event #<Punchblock::Event::Complete reason=#<Punchblock::Event::Complete::Hangup name=:hangup, target_call_id="1b19d201-1db8-4f68-aad6-7c9c5224f39a", component_id="e8c84fdb-1bee-495e-bb02-11bd148737ab", target_mixer_name=nil>, recording=nil, target_call_id="1b19d201-1db8-4f68-aad6-7c9c5224f39a", component_id="e8c84fdb-1bee-495e-bb02-11bd148737ab", target_mixer_name=nil>
[2012-05-16 14:21:21] DEBUG Adhearsion::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Receiving message: #<Punchblock::Event::Complete reason=#<Punchblock::Event::Complete::Hangup name=:hangup, target_call_id="1b19d201-1db8-4f68-aad6-7c9c5224f39a", component_id="e8c84fdb-1bee-495e-bb02-11bd148737ab", target_mixer_name=nil>, recording=nil, target_call_id="1b19d201-1db8-4f68-aad6-7c9c5224f39a", component_id="e8c84fdb-1bee-495e-bb02-11bd148737ab", target_mixer_name=nil>
[2012-05-16 14:21:21] ERROR Adhearsion::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: <NoMethodError> undefined method `code' for #<Punchblock::Event::Complete::Hangup:0x007fb138164450>
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/foundation/object.rb:22:in `method_missing'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bundler/gems/adhearsion-asterisk-20b8cd7cff63/lib/adhearsion/asterisk/call_controller_methods.rb:21:in `block in agi'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bundler/gems/adhearsion-asterisk-20b8cd7cff63/lib/adhearsion/asterisk/call_controller_methods.rb:21:in `map'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bundler/gems/adhearsion-asterisk-20b8cd7cff63/lib/adhearsion/asterisk/call_controller_methods.rb:21:in `agi'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bundler/gems/adhearsion-asterisk-20b8cd7cff63/lib/adhearsion/asterisk/call_controller_methods.rb:37:in `execute'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bundler/gems/adhearsion-asterisk-20b8cd7cff63/lib/adhearsion/asterisk/call_controller_methods.rb:376:in `play_digits'
    /home/jlecuirot/ctnv/app/call_controllers/inbound_requests_call_controller.rb:24:in `run'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:83:in `execute!'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:45:in `block in exec'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:44:in `catch'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:44:in `exec'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call.rb:296:in `block (2 levels) in execute_controller'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/foundation/exception_handler.rb:6:in `catching_standard_errors'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call.rb:294:in `block in execute_controller'
[2012-05-16 14:21:21] DEBUG Adhearsion::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="1b19d201-1db8-4f68-aad6-7c9c5224f39a", component_id=nil, target_mixer_name=nil>
[2012-05-16 14:21:21] INFO  Adhearsion::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Call ended
[2012-05-16 14:21:21] DEBUG Adhearsion::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Finished executing controller #<InboundRequestsCallController call=1b19d201-1db8-4f68-aad6-7c9c5224f39a, metadata={}>
[2012-05-16 14:21:26] DEBUG Punchblock::Translator::Asterisk::Call: 1b19d201-1db8-4f68-aad6-7c9c5224f39a: Shutting down
bklang commented 12 years ago

9:43 Ben Klang Just trying to figure out the problem reported by Chewi on IRC 9:44 Ben Langfeld connected

9:44 Ben Klang He's getting a Punchblock::Event::Complete::Hangup (which is a Complete event) but it doesn't respond to :code 9:48 Ben Langfeld connected

9:48 Ben Langfeld So, something about a hangup complete event why should it respond to #code?

9:49 Ben Klang shouldn't it?

9:49 Ben Langfeld I didn't get anything about the context, can you repeat that?

9:49 Ben Klang or maybe we need to pass a Complete event for the original action instead of the Hangup event the exception occurs if he hangs up in the middle of play_digits, but not if he lets it complete normally

9:49 Ben Langfeld what exception?

9:50 Ben Klang http://pastebin.com/QqQe9bRY

9:50 Ben Langfeld sorry, the only message I got was " He's getting a Punchblock::Event::Complete::Hangup (which is a Complete event) but it doesn't respond to :code "

9:50 Ben Klang https://github.com/chewi/adhearsion-asterisk/tree/feature/play_digits

9:50 Ben Langfeld Ok, from the top

9:51 Ben Klang you want me to start over with describing the question?

9:51 Ben Langfeld I havn't seen the question Only that message

9:51 Ben Klang ok sorry The question is, why is this exception occurring? The line of code that throws the exception is clearly expecting a Complete event. It is receiving a (subclass of a) Complete event, which makes me think that it should not be failing like this

9:53 Ben Langfeld aha, so the failure is here: https://github.com/adhearsion/adhearsion-asterisk/blob/develop/lib/adhearsion/asterisk/call_controller_methods.rb#L21 Can I see an example of the complete event in the success case?

9:54 Ben Klang sure, one sec

9:55 Ben Langfeld Ok, I've found it: https://github.com/adhearsion/punchblock/blob/develop/lib/punchblock/translator/asterisk/component/asterisk/agi_command.rb#L70

9:56 Ben Klang Success vs. Hangup?

9:57 Ben Langfeld the bug was introduced here: https://github.com/adhearsion/punchblock/commit/a6b2f5b3ce77f2d7805ec0b02f4cc247b43e86ec

benlangfeld commented 12 years ago

Ok, so I believe this is due to the AGI Exec event we use to send the success complete event not being received until after the hangup event is received, causing us to shut down the agi component with a hangup reason. To confirm this, I will need TRACE logs of this scenario, and steps to reproduce.

benlangfeld commented 12 years ago

@chewi: Can I get logs at TRACE level, and details of how you triggered this?

chewi commented 12 years ago

Don't worry, was already going to do that but will have to wait till tomorrow.

chewi commented 12 years ago

I reproduced it with Adhearsion-2.0.0 (from gem) and Asterisk 1.8.11.1 on Fedora 16. Hang up while the number is being spoken during the following call and you should see the output below.

class AhnTest < Adhearsion::CallController
  def run
    answer
    sleep 1
    play_numeric "7777"
  end
end
[2012-05-21 09:33:11] TRACE Adhearsion::Initializer: OS: linux-gnu - RUBY: ruby 1.9.3
[2012-05-21 09:33:11] TRACE Adhearsion::Initializer: Environment: {"XDG_VTNR"=>"1", "LDFLAGS"=>"-Wl,-O1 -Wl,--as-needed", "SSH_AGENT_PID"=>"1625", "XDG_SESSION_ID"=>"2", "rvm_bin_path"=>"/home/jlecuirot/.rvm/bin", "HOSTNAME"=>"red", "IMSETTINGS_INTEGRATE_DESKTOP"=>"yes", "GEM_HOME"=>"/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194", "GLADE_PIXMAP_PATH"=>":", "TERM"=>"xterm", "XDG_MENU_PREFIX"=>"xfce-", "SHELL"=>"/bin/bash", "XDG_SESSION_COOKIE"=>"80a91188fa75681d91ede2f80000001a-1337586126.290343-1752585030", "HISTSIZE"=>"1000", "IRBRC"=>"/home/jlecuirot/.rvm/rubies/ruby-1.9.3-p194/.irbrc", "PERL5LIB"=>"/home/jlecuirot/perl5/lib/perl5/x86_64-linux-thread-multi:/home/jlecuirot/perl5/lib/perl5", "WINDOWID"=>"62914564", "OLDPWD"=>"/home/jlecuirot/ahn-test/lib", "GNOME_KEYRING_CONTROL"=>"/tmp/keyring-lRtsnq", "PERL_MB_OPT"=>"--install_base /home/jlecuirot/perl5", "MY_RUBY_HOME"=>"/home/jlecuirot/.rvm/rubies/ruby-1.9.3-p194", "IMSETTINGS_MODULE"=>"none", "USER"=>"jlecuirot", "LS_COLORS"=>"rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41: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:*.tlz=01;31:*.txz=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lz=01;31:*.xz=01;31:*.bz2=01;31:*.tbz=01;31:*.tbz2=01;31:*.bz=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=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:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36:*.pdf=00;33:*.ps=00;33:*.ps.gz=00;33:*.txt=00;33:*.patch=00;33:*.diff=00;33:*.log=00;33:*.tex=00;33:*.xls=00;33:*.xlsx=00;33:*.ppt=00;33:*.pptx=00;33:*.rtf=00;33:*.doc=00;33:*.docx=00;33:*.odt=00;33:*.ods=00;33:*.odp=00;33:*.xml=00;33:*.epub=00;33:*.abw=00;33:*.html=00;33:*.wpd=00;33:", "__array_start"=>"0", "GLADE_MODULE_PATH"=>":", "rvm_path"=>"/home/jlecuirot/.rvm", "SSH_AUTH_SOCK"=>"/tmp/ssh-jaNWCKGg1493/agent.1493", "USERNAME"=>"jlecuirot", "SESSION_MANAGER"=>"local/unix:@/tmp/.ICE-unix/1771,unix/unix:/tmp/.ICE-unix/1771", "CXXFLAGS"=>"-march=core2 -O2 -pipe", "escape_flag"=>"1", "XDG_CONFIG_DIRS"=>"/etc/xdg", "rvm_prefix"=>"/home/jlecuirot", "DESKTOP_SESSION"=>"xfce", "MAIL"=>"/var/spool/mail/jlecuirot", "PATH"=>"/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bin:/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194@global/bin:/home/jlecuirot/.rvm/rubies/ruby-1.9.3-p194/bin:/home/jlecuirot/.rvm/bin:/home/jlecuirot/perl5/bin:/usr/lib64/ccache:/usr/local/bin:/usr/bin:/bin:/usr/local/sbin:/usr/sbin:/sbin:/home/jlecuirot/.local/bin:/home/jlecuirot/bin", "QT_IM_MODULE"=>"xim", "PWD"=>"/home/jlecuirot/ahn-test", "XMODIFIERS"=>"@im=none", "EDITOR"=>"emacs -nw", "GNOME_KEYRING_PID"=>"1489", "LANG"=>"en_GB.UTF-8", "_second"=>"1", "GDMSESSION"=>"xfce", "SSH_ASKPASS"=>"/usr/libexec/openssh/gnome-ssh-askpass", "HISTCONTROL"=>"ignoredups", "rvm_version"=>"1.13.4 (stable)", "SHLVL"=>"3", "HOME"=>"/home/jlecuirot", "XDG_SEAT"=>"seat0", "CFLAGS"=>"-march=core2 -O2 -pipe", "PERL_LOCAL_LIB_ROOT"=>"/home/jlecuirot/perl5", "_first"=>"0", "LESS"=>"-R -M --shift 5", "LOGNAME"=>"jlecuirot", "CVS_RSH"=>"ssh", "DBUS_SESSION_BUS_ADDRESS"=>"unix:abstract=/tmp/dbus-ub7v7ECxuC,guid=8a33e06ab12e304785bae4f40000005e", "XDG_DATA_DIRS"=>"/usr/local/share:/usr/share", "GEM_PATH"=>"/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194:/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194@global", "LESSOPEN"=>"||/usr/bin/lesspipe.sh %s", "WINDOWPATH"=>"1", "XDG_RUNTIME_DIR"=>"/run/user/jlecuirot", "DISPLAY"=>":0.0", "GLADE_CATALOG_PATH"=>":", "LIBGLADE_MODULE_PATH"=>":", "RUBY_VERSION"=>"ruby-1.9.3-p194", "PERL_MM_OPT"=>"INSTALL_BASE=/home/jlecuirot/perl5", "XAUTHORITY"=>"/var/run/gdm/auth-for-jlecuirot-27xOG9/database", "COLORTERM"=>"Terminal", "CCACHE_HASHDIR"=>"", "_"=>"/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/bin/ahn", "BUNDLE_BIN_PATH"=>"/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194@global/gems/bundler-1.1.3/bin/bundle", "BUNDLE_GEMFILE"=>"/home/jlecuirot/ahn-test/Gemfile", "RUBYOPT"=>"-I/home/jlecuirot/.rvm/gems/ruby-1.9.3-p194@global/gems/bundler-1.1.3/lib -rbundler/setup"}
[2012-05-21 09:33:11] TRACE Adhearsion::Initializer:   # ******* 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

  # Host punchblock needs to connect (where rayo or asterisk are 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       = 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 [AHN_PUNCHBLOCK_PLATFORM]
  config.punchblock.platform           = :asterisk

  # Port punchblock needs to connect (by default 5038 for Asterisk, 5222 for Rayo) [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           = "XXXXXXXX"

  # ******* 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/jlecuirot/ahn-test"

[2012-05-21 09:33:11] TRACE Adhearsion::Initializer: Gem versions: ["bundler 1.1.3", "rake 0.9.2.2", "i18n 0.6.0", "multi_json 1.3.5", "activesupport 3.2.3", "adhearsion-loquacious 1.9.2", "celluloid 0.10.0", "countdownlatch 1.0.0", "deep_merge 1.0.0", "ffi 1.0.11", "future-resource 1.0.0", "connection_pool 0.1.0", "girl_friday 0.9.7", "systemu 2.2.0", "macaddr 1.6.0", "uuid 2.3.5", "has-guarded-handlers 1.2.0", "little-plugger 1.1.3", "logging 1.7.2", "coderay 1.0.6", "method_source 0.7.1", "slop 2.4.4", "pry 0.9.9.6", "eventmachine 0.12.10", "nokogiri 1.5.2", "niceogiri 1.0.1", "blather 0.7.1", "uuidtools 2.1.2", "ruby_ami 1.0.1", "ruby_speech 1.0.0", "state_machine 1.1.2", "punchblock 1.2.0", "thor 0.15.0", "adhearsion 2.0.0", "adhearsion-asterisk 1.2.0"]
[2012-05-21 09:33:11] INFO  Adhearsion::Console: Launching Adhearsion Console
[2012-05-21 09:33:11] INFO  Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2012-05-21 09:33:11] DEBUG Punchblock::Translator::Asterisk: Starting up...
[2012-05-21 09:33:11] INFO  Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2012-05-21 09:33:11] DEBUG Punchblock::Connection::Asterisk: Starting the RubyAMI client
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Stream::Connected:0x000000031597f0>
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Stream::Connected:0x00000003158490>
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [SEND]: Action: login
ActionID: d2998319-488d-4ffe-9d1d-7d25d2dac4f0
Username: XXXXXXXX
Secret: XXXXXXXX
Events: On

[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Response:0x00000002806310 @headers={"ActionID"=>"19f32b66-e901-48c1-8f8a-aa9fc99a2002", "Message"=>"Authentication accepted"}>
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002f8d930 @headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, @name="FullyBooted">
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response:0x00000002e5b148 @headers={"ActionID"=>"d2998319-488d-4ffe-9d1d-7d25d2dac4f0", "Message"=>"Authentication accepted"}>
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [QUEUE]: Action: events
ActionID: 39dc078b-6f5f-408d-81f4-39935cae4121
EventMask: Off

[2012-05-21 09:33:11] TRACE Punchblock::Translator::Asterisk: Counting FullyBooted event
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Event:0x00000002d8ba10 @headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, @name="FullyBooted">
[2012-05-21 09:33:11] TRACE Punchblock::Translator::Asterisk: Counting FullyBooted event
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [SEND]: Action: events
ActionID: 39dc078b-6f5f-408d-81f4-39935cae4121
EventMask: Off

[2012-05-21 09:33:11] TRACE RubyAMI::Client: [QUEUE]: Action: command
ActionID: 00ef82f3-d275-4e2c-9d3c-c2b7a76fb193
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect

[2012-05-21 09:33:11] TRACE Punchblock::Translator::Asterisk: Added extension extension 1,1,AGI,agi:async into adhearsion-redirect
[2012-05-21 09:33:11] INFO  Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2012-05-21 09:33:11] INFO  Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2012-05-21 09:33:11] INFO  Adhearsion::Initializer: Adhearsion v2.0.0 initialized in "development"!
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response:0x00000002453538 @headers={"ActionID"=>"39dc078b-6f5f-408d-81f4-39935cae4121", "Events"=>"Off"}>
[2012-05-21 09:33:11] TRACE RubyAMI::Client: [SEND]: Action: command
ActionID: 00ef82f3-d275-4e2c-9d3c-c2b7a76fb193
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect

[2012-05-21 09:33:11] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response:0x000000024be590 @headers={"Privilege"=>"Command", "ActionID"=>"00ef82f3-d275-4e2c-9d3c-c2b7a76fb193", "Failed to add '1,1,AGI(agi"=>"async)' extension into 'adhearsion-redirect' context\nCommand 'dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect' failed.\n--END COMMAND--"}, @text_body="Failed to add '1,1,AGI(agi:async)' extension into 'adhearsion-redirect' context\nCommand 'dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect' failed.">
[2012-05-21 09:33:13] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002f97f70 @headers={"Privilege"=>"user,all", "Account"=>"asterisk", "Packet"=>""}, @name="JabberEvent">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002d1f450 @headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-00000007", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "AccountCode"=>"", "Exten"=>"1337", "Context"=>"adhearsion", "Uniqueid"=>"1337589195.7"}, @name="Newchannel">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002ca8f80 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Variable"=>"SIPURI", "Value"=>"sip:gigaset@192.168.1.30:5060", "Uniqueid"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002d6eb90 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.1.39", "Uniqueid"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x000000030fbba0 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Variable"=>"SIPCALLID", "Value"=>"4023834559@192_168_1_30", "Uniqueid"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002dbe898 @headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-00000007", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1337589195.7"}, @name="Newstate">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002ab2f28 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Context"=>"adhearsion", "Extension"=>"1337", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1337589195.7"}, @name="Newexten">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002f59f40 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/gigaset-00000007", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fgigaset-00000007%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201337589195.7%0Aagi_version%3A%201.8.11.1%0Aagi_callerid%3A%20gigaset%0Aagi_calleridname%3A%20Gigaset%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201337%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%201337%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140636335494912%0A%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk: Handling AsyncAGI Start event by creating a new call
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Starting up call with channel SIP/gigaset-00000007, id f86b833b-b5b1-492e-a969-8775a46f14d0
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending Punchblock event: #<Punchblock::Event::Offer to="1337", from="Gigaset <sip:gigaset>", call_id="f86b833b-b5b1-492e-a969-8775a46f14d0"
[2012-05-21 09:33:15] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="1337", from="Gigaset <sip:gigaset>", call_id="f86b833b-b5b1-492e-a969-8775a46f14d0"
[2012-05-21 09:33:15] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Executing command: #<Punchblock::Command::Accept headers_hash={}, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil, state_name=:requested>
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Attempting to accept an inbound call. Executing RINGING.
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending AGI action EXEC RINGING
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: daf4aa64-b727-450b-84ab-d52795662f8a: Starting up...
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending AMI action Action: agi
ActionID: f57a6365-87c8-424c-ad14-0a8f1d2039c0
Channel: SIP/gigaset-00000007
Command: EXEC RINGING
CommandID: daf4aa64-b727-450b-84ab-d52795662f8a

[2012-05-21 09:33:15] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: f57a6365-87c8-424c-ad14-0a8f1d2039c0
Channel: SIP/gigaset-00000007
Command: EXEC RINGING
CommandID: daf4aa64-b727-450b-84ab-d52795662f8a

[2012-05-21 09:33:15] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: f57a6365-87c8-424c-ad14-0a8f1d2039c0
Channel: SIP/gigaset-00000007
Command: EXEC RINGING
CommandID: daf4aa64-b727-450b-84ab-d52795662f8a

[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response:0x000000026e28d0 @headers={"ActionID"=>"f57a6365-87c8-424c-ad14-0a8f1d2039c0", "Message"=>"Added AGI command to queue"}>
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: daf4aa64-b727-450b-84ab-d52795662f8a: Handling response: #<RubyAMI::Response:0x000000026e28d0 @headers={"ActionID"=>"f57a6365-87c8-424c-ad14-0a8f1d2039c0", "Message"=>"Added AGI command to queue"}, @action=Action: agi
ActionID: f57a6365-87c8-424c-ad14-0a8f1d2039c0
Channel: SIP/gigaset-00000007
Command: EXEC RINGING
CommandID: daf4aa64-b727-450b-84ab-d52795662f8a

>
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: daf4aa64-b727-450b-84ab-d52795662f8a: Setting response on component node to #<Punchblock::Ref id="daf4aa64-b727-450b-84ab-d52795662f8a", target_call_id=nil, component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002d1a2c0 @headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-00000007", "CommandId"=>"1428367046", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, @name="AGIExec">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002df34d0 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/gigaset-00000007", "CommandId"=>"1428367046", "Command"=>"EXEC RINGING"}, @name="AGIExec">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002d952b8 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000007", "CommandID"=>"daf4aa64-b727-450b-84ab-d52795662f8a", "Result"=>"200%20result%3D0%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Received an AsyncAGI event. Looking for matching AGICommand component.
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: daf4aa64-b727-450b-84ab-d52795662f8a: Handling AMI event: #<RubyAMI::Event:0x00000002d952b8 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000007", "CommandID"=>"daf4aa64-b727-450b-84ab-d52795662f8a", "Result"=>"200%20result%3D0%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: daf4aa64-b727-450b-84ab-d52795662f8a: Received AsyncAGI:Exec event, sending complete event.
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: daf4aa64-b727-450b-84ab-d52795662f8a: Sending event #<Punchblock::Event::Complete reason=#<Punchblock::Component::Asterisk::AGI::Command::Complete::Success code=200, result=0, data="">, recording=nil, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="daf4aa64-b727-450b-84ab-d52795662f8a", target_mixer_name=nil>
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: AGI action received complete event #<Punchblock::Event::Complete reason=#<Punchblock::Component::Asterisk::AGI::Command::Complete::Success code=200, result=0, data="">, recording=nil, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="daf4aa64-b727-450b-84ab-d52795662f8a", target_mixer_name=nil>
[2012-05-21 09:33:15] INFO  Adhearsion::Router: Call f86b833b-b5b1-492e-a969-8775a46f14d0 selected route "default" (AhnTest)
[2012-05-21 09:33:15] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk: Executing command #<Punchblock::Command::Answer headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Executing command: #<Punchblock::Command::Answer headers_hash={}, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil, state_name=:requested>
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending AGI action EXEC ANSWER
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b: Starting up...
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending AMI action Action: agi
ActionID: f22d51ac-9da3-4b72-b3a2-3a9a5a25ba1a
Channel: SIP/gigaset-00000007
Command: EXEC ANSWER
CommandID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b

[2012-05-21 09:33:15] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: f22d51ac-9da3-4b72-b3a2-3a9a5a25ba1a
Channel: SIP/gigaset-00000007
Command: EXEC ANSWER
CommandID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b

[2012-05-21 09:33:15] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: f22d51ac-9da3-4b72-b3a2-3a9a5a25ba1a
Channel: SIP/gigaset-00000007
Command: EXEC ANSWER
CommandID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b

[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response:0x000000032a2a08 @headers={"ActionID"=>"f22d51ac-9da3-4b72-b3a2-3a9a5a25ba1a", "Message"=>"Added AGI command to queue"}>
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b: Handling response: #<RubyAMI::Response:0x000000032a2a08 @headers={"ActionID"=>"f22d51ac-9da3-4b72-b3a2-3a9a5a25ba1a", "Message"=>"Added AGI command to queue"}, @action=Action: agi
ActionID: f22d51ac-9da3-4b72-b3a2-3a9a5a25ba1a
Channel: SIP/gigaset-00000007
Command: EXEC ANSWER
CommandID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b

>
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b: Setting response on component node to #<Punchblock::Ref id="7d980773-1f3c-4ff8-8e2e-675b2bd16f2b", target_call_id=nil, component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002ec44e0 @headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-00000007", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1337589195.7"}, @name="Newstate">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002ebbcf0 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/gigaset-00000007", "CommandId"=>"1897602130", "Command"=>"EXEC ANSWER"}, @name="AGIExec">
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Received a Newstate AMI event with state 6: Up
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending Punchblock event: #<Punchblock::Event::Answered headers_hash={}, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002fa98d8 @headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-00000007", "CommandId"=>"1897602130", "Command"=>"EXEC ANSWER", "ResultCode"=>"200", "Result"=>"Success"}, @name="AGIExec">
[2012-05-21 09:33:15] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002fb7d98 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000007", "CommandID"=>"7d980773-1f3c-4ff8-8e2e-675b2bd16f2b", "Result"=>"200%20result%3D0%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Received an AsyncAGI event. Looking for matching AGICommand component.
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b: Handling AMI event: #<RubyAMI::Event:0x00000002fb7d98 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000007", "CommandID"=>"7d980773-1f3c-4ff8-8e2e-675b2bd16f2b", "Result"=>"200%20result%3D0%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b: Received AsyncAGI:Exec event, sending complete event.
[2012-05-21 09:33:15] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: 7d980773-1f3c-4ff8-8e2e-675b2bd16f2b: Sending event #<Punchblock::Event::Complete reason=#<Punchblock::Component::Asterisk::AGI::Command::Complete::Success code=200, result=0, data="">, recording=nil, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="7d980773-1f3c-4ff8-8e2e-675b2bd16f2b", target_mixer_name=nil>
[2012-05-21 09:33:15] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: AGI action received complete event #<Punchblock::Event::Complete reason=#<Punchblock::Component::Asterisk::AGI::Command::Complete::Success code=200, result=0, data="">, recording=nil, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="7d980773-1f3c-4ff8-8e2e-675b2bd16f2b", target_mixer_name=nil>
[2012-05-21 09:33:15] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Receiving message: #<Punchblock::Event::Offer to="1337", from="Gigaset <sip:gigaset>", call_id="f86b833b-b5b1-492e-a969-8775a46f14d0"
[2012-05-21 09:33:15] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Receiving message: #<Punchblock::Event::Answered headers_hash={}, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:16] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Executing command #<Punchblock::Component::Asterisk::AGI::Command name="EXEC SayNumber", params_array=["7777"], target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-21 09:33:16] TRACE Punchblock::Translator::Asterisk: Executing command #<Punchblock::Component::Asterisk::AGI::Command name="EXEC SayNumber", params_array=["7777"], target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2012-05-21 09:33:16] DEBUG Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Executing command: #<Punchblock::Component::Asterisk::AGI::Command name="EXEC SayNumber", params_array=["7777"], target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil, state_name=:requested>
[2012-05-21 09:33:16] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: ad46ab92-10c3-4f35-ab98-1b25fd28df80: Starting up...
[2012-05-21 09:33:16] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending AMI action Action: agi
ActionID: bafc85b9-ca58-4d76-9914-0dde329a09cb
Channel: SIP/gigaset-00000007
Command: EXEC SayNumber "7777"
CommandID: ad46ab92-10c3-4f35-ab98-1b25fd28df80

[2012-05-21 09:33:16] TRACE RubyAMI::Client: [QUEUE]: Action: agi
ActionID: bafc85b9-ca58-4d76-9914-0dde329a09cb
Channel: SIP/gigaset-00000007
Command: EXEC SayNumber "7777"
CommandID: ad46ab92-10c3-4f35-ab98-1b25fd28df80

[2012-05-21 09:33:16] TRACE RubyAMI::Client: [SEND]: Action: agi
ActionID: bafc85b9-ca58-4d76-9914-0dde329a09cb
Channel: SIP/gigaset-00000007
Command: EXEC SayNumber "7777"
CommandID: ad46ab92-10c3-4f35-ab98-1b25fd28df80

[2012-05-21 09:33:16] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Response:0x00000002abfcf0 @headers={"ActionID"=>"bafc85b9-ca58-4d76-9914-0dde329a09cb", "Message"=>"Added AGI command to queue"}>
[2012-05-21 09:33:16] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: ad46ab92-10c3-4f35-ab98-1b25fd28df80: Handling response: #<RubyAMI::Response:0x00000002abfcf0 @headers={"ActionID"=>"bafc85b9-ca58-4d76-9914-0dde329a09cb", "Message"=>"Added AGI command to queue"}, @action=Action: agi
ActionID: bafc85b9-ca58-4d76-9914-0dde329a09cb
Channel: SIP/gigaset-00000007
Command: EXEC SayNumber "7777"
CommandID: ad46ab92-10c3-4f35-ab98-1b25fd28df80

>
[2012-05-21 09:33:16] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: ad46ab92-10c3-4f35-ab98-1b25fd28df80: Setting response on component node to #<Punchblock::Ref id="ad46ab92-10c3-4f35-ab98-1b25fd28df80", target_call_id=nil, component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:16] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002f627f8 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/gigaset-00000007", "CommandId"=>"1099508072", "Command"=>"EXEC SayNumber \"7777\""}, @name="AGIExec">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x000000026c5f00 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Variable"=>"RTPAUDIOQOS", "Value"=>"ssrc=1710625583;themssrc=2042526718;lp=0;rxjitter=0.000223;rxcount=221;txjitter=0.000000;txcount=167;rlp=0;rtt=0.000000", "Uniqueid"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x0000000329c338 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "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"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002ebe6a8 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "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"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002ec7d20 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Variable"=>"RTPAUDIOQOSRTT", "Value"=>"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;", "Uniqueid"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000003157978 @headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-00000007", "CommandId"=>"1099508072", "Command"=>"EXEC SayNumber \"7777\"", "ResultCode"=>"200", "Result"=>"Success"}, @name="AGIExec">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002fa1d90 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000007", "CommandID"=>"ad46ab92-10c3-4f35-ab98-1b25fd28df80", "Result"=>"200%20result%3D0%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002fafdf0 @headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-00000007"}, @name="AsyncAGI">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002fb30e0 @headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-00000007", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1337589195.7"}, @name="VarSet">
[2012-05-21 09:33:20] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Received an AsyncAGI event. Looking for matching AGICommand component.
[2012-05-21 09:33:20] WARN  Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Could not find component for AMI event: #<RubyAMI::Event:0x00000002fafdf0 @headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-00000007"}, @name="AsyncAGI">
[2012-05-21 09:33:20] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Event:0x00000002fbbd08 @headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-00000007", "Uniqueid"=>"1337589195.7", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "Cause"=>"0", "Cause-txt"=>"Unknown"}, @name="Hangup">
[2012-05-21 09:33:20] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Received an AsyncAGI event. Looking for matching AGICommand component.
[2012-05-21 09:33:20] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Received a Hangup AMI event. Sending End event.
[2012-05-21 09:33:20] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: ad46ab92-10c3-4f35-ab98-1b25fd28df80: Handling AMI event: #<RubyAMI::Event:0x00000002fa1d90 @headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-00000007", "CommandID"=>"ad46ab92-10c3-4f35-ab98-1b25fd28df80", "Result"=>"200%20result%3D0%0A"}, @name="AsyncAGI">
[2012-05-21 09:33:20] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: ad46ab92-10c3-4f35-ab98-1b25fd28df80: Received AsyncAGI:Exec event, sending complete event.
[2012-05-21 09:33:20] DEBUG Punchblock::Translator::Asterisk::Component::Asterisk::AGICommand: Call ID: f86b833b-b5b1-492e-a969-8775a46f14d0, Component ID: ad46ab92-10c3-4f35-ab98-1b25fd28df80: Sending event #<Punchblock::Event::Complete reason=#<Punchblock::Event::Complete::Hangup name=:hangup, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="ad46ab92-10c3-4f35-ab98-1b25fd28df80", target_mixer_name=nil>, recording=nil, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="ad46ab92-10c3-4f35-ab98-1b25fd28df80", target_mixer_name=nil>
[2012-05-21 09:33:20] TRACE Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Sending Punchblock event: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:20] ERROR Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: <NoMethodError> undefined method `code' for #<Punchblock::Event::Complete::Hangup:0x000000030c6dd8>
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/foundation/object.rb:22:in `method_missing'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-asterisk-1.2.0/lib/adhearsion/asterisk/call_controller_methods.rb:21:in `block in agi'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-asterisk-1.2.0/lib/adhearsion/asterisk/call_controller_methods.rb:21:in `map'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-asterisk-1.2.0/lib/adhearsion/asterisk/call_controller_methods.rb:21:in `agi'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-asterisk-1.2.0/lib/adhearsion/asterisk/call_controller_methods.rb:37:in `execute'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-asterisk-1.2.0/lib/adhearsion/asterisk/call_controller_methods.rb:366:in `play_numeric'
    /home/jlecuirot/ahn-test/lib/ahn_test.rb:5:in `run'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:83:in `execute!'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:45:in `block in exec'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:44:in `catch'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call_controller.rb:44:in `exec'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call.rb:296:in `block (2 levels) in execute_controller'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/foundation/exception_handler.rb:6:in `catching_standard_errors'
    /home/jlecuirot/.rvm/gems/ruby-1.9.3-p194/gems/adhearsion-2.0.0/lib/adhearsion/call.rb:294:in `block in execute_controller'
[2012-05-21 09:33:20] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Receiving message: #<Punchblock::Event::Complete reason=#<Punchblock::Event::Complete::Hangup name=:hangup, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="ad46ab92-10c3-4f35-ab98-1b25fd28df80", target_mixer_name=nil>, recording=nil, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id="ad46ab92-10c3-4f35-ab98-1b25fd28df80", target_mixer_name=nil>
[2012-05-21 09:33:20] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="f86b833b-b5b1-492e-a969-8775a46f14d0", component_id=nil, target_mixer_name=nil>
[2012-05-21 09:33:20] INFO  Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Call ended
[2012-05-21 09:33:20] DEBUG Adhearsion::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Finished executing controller #<AhnTest call=f86b833b-b5b1-492e-a969-8775a46f14d0, metadata={}>
[2012-05-21 09:33:24] INFO  Adhearsion::Initializer: Received SIGINT. Shutting down.
[2012-05-21 09:33:24] INFO  Adhearsion::Process: Transitioning from running to stopping with 0 active calls due to shutdown event.
[2012-05-21 09:33:24] INFO  Adhearsion::PunchblockPlugin::Initializer: Shutting down while connecting. Breaking the connection block.
[2012-05-21 09:33:24] INFO  Adhearsion::Console: Adhearsion Console shutting down
[2012-05-21 09:33:24] DEBUG Punchblock::Translator::Asterisk: Shutting down
[2012-05-21 09:33:24] INFO  Adhearsion::Process: Adhearsion shut down
[2012-05-21 09:33:24] DEBUG Punchblock::Translator::Asterisk::Call: f86b833b-b5b1-492e-a969-8775a46f14d0: Shutting down
[2012-05-21 09:33:24] TRACE RubyAMI::Client: [RECV-ACTIONS]: #<RubyAMI::Stream::Disconnected:0x000000030d9dc0>
[2012-05-21 09:33:24] TRACE RubyAMI::Client: [RECV-EVENTS]: #<RubyAMI::Stream::Disconnected:0x000000030d9e88>
[2012-05-21 09:33:25] INFO  Celluloid: Terminating 2 actors...
[2012-05-21 09:33:25] INFO  Celluloid: Shutdown completed cleanly
benlangfeld commented 12 years ago

Ok, I have a reproduction of this and will get it fixed ASAP.

benlangfeld commented 12 years ago

So, it looks like events are being received in the correct order, but there are race conditions in the Asterisk code in Punchblock processing said events. I need to ensure events are processed in order more carefully. I will hopefully get this fixed tomorrow or Wendesday.

benlangfeld commented 12 years ago

I decided that Hangup was probably the correct reason to send here, and so I've modified adhearsion-asterisk to raise a Hangup exception. Can you use adhearsion-asterisk from the develop branch and let me know if this is ok for you? I will release a new version on confirmation.

chewi commented 12 years ago

Seems fine now. Thanks very much.