search

adhearsion / adhearsion

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

dial race condition: timeout result vs Punchblock::ProtocolError #303

Closed chewi closed 11 years ago

chewi commented 11 years ago

Time for another episode of Chewi vs the Race Conditions! This one occurs when a dial command times out. Sometimes a :timeout result is returned (correct) and sometimes a Punchblock::ProtocolError exception is raised (bad!). It seems about 50/50. Feel free to use the SIP destination in this example. My server actually listens on a non-standard port.

class TestController < Adhearsion::CallController
  def run
    loop do
      logger.fatal "RESULT IS " + dial("SIP/foo@aura-online.co.uk", :for => 10.seconds).result.inspect
      sleep 3
    end
  end
end

This log shows the first attempt timing out correctly and the second attempt raising an exception, thus ending the call.

[2013-05-06 10:31:52] TRACE Adhearsion::Initializer: OS: linux-gnu - RUBY: ruby 2.0.0
[2013-05-06 10:31:52] TRACE Adhearsion::Initializer: Environment: {"XDG_VTNR"=>"1", "LDFLAGS"=>"-Wl,-O1 -Wl,--as-needed", "SSH_AGENT_PID"=>"24340", "XDG_SESSION_ID"=>"153", "rvm_bin_path"=>"/home/jlecuirot/.rvm/bin", "HOSTNAME"=>"red", "IMSETTINGS_INTEGRATE_DESKTOP"=>"yes", "GEM_HOME"=>"/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0", "GPG_AGENT_INFO"=>"/run/user/1000/keyring-BugWtf/gpg:0:1", "GLADE_PIXMAP_PATH"=>":", "rvm_error_clr"=>"\e[31m", "TERM"=>"xterm-256color", "XDG_MENU_PREFIX"=>"xfce-", "SHELL"=>"/bin/bash", "rvm_notify_clr"=>"\e[32m", "XDG_SESSION_COOKIE"=>"80a91188fa75681d91ede2f80000001a-1367827612.928374-1220905984", "HISTSIZE"=>"1000", "IRBRC"=>"/home/jlecuirot/.rvm/rubies/ruby-2.0.0-p0/.irbrc", "PERL5LIB"=>"/home/jlecuirot/perl5/lib/perl5/x86_64-linux-thread-multi:/home/jlecuirot/perl5/lib/perl5", "WINDOWID"=>"60817412", "OLDPWD"=>"/home/jlecuirot/Open", "GNOME_KEYRING_CONTROL"=>"/run/user/1000/keyring-BugWtf", "PERL_MB_OPT"=>"--install_base /home/jlecuirot/perl5", "MY_RUBY_HOME"=>"/home/jlecuirot/.rvm/rubies/ruby-2.0.0-p0", "IMSETTINGS_MODULE"=>"none", "QT_GRAPHICSSYSTEM_CHECKED"=>"1", "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:", "__array_start"=>"0", "GLADE_MODULE_PATH"=>":", "rvm_reset_clr"=>"\e(B\e[m", "rvm_path"=>"/home/jlecuirot/.rvm", "SSH_AUTH_SOCK"=>"/run/user/1000/keyring-BugWtf/ssh", "USERNAME"=>"jlecuirot", "SESSION_MANAGER"=>"local/unix:@/tmp/.ICE-unix/24375,unix/unix:/tmp/.ICE-unix/24375", "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-2.0.0-p0/bin:/home/jlecuirot/perl5/bin:/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0@global/bin:/home/jlecuirot/.rvm/rubies/ruby-2.0.0-p0/bin:/home/jlecuirot/.rvm/bin:/usr/lib64/ccache:/usr/local/bin:/usr/bin:/bin:/usr/local/sbin:/usr/sbin:/home/jlecuirot/.local/bin:/home/jlecuirot/bin", "QT_IM_MODULE"=>"xim", "PWD"=>"/home/jlecuirot/Open/ahn-test", "XMODIFIERS"=>"@im=none", "EDITOR"=>"emacs -nw", "GNOME_KEYRING_PID"=>"24200", "LANG"=>"en_GB.UTF-8", "_second"=>"1", "GDMSESSION"=>"xfce", "KRB5CCNAME"=>"DIR:/run/user/1000/krb5cc_acde4279130bf3560cbfc7165183e628", "SSH_ASKPASS"=>"/usr/libexec/openssh/gnome-ssh-askpass", "HISTCONTROL"=>"ignoredups", "rvm_version"=>"1.19.0 (stable)", "rvm_debug_clr"=>"\e[35m", "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-kvc4FkN6YW,guid=fa212f711f53a8e268e1f3d45187649d", "XDG_DATA_DIRS"=>"/usr/local/share:/usr/share", "GEM_PATH"=>"/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0:/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0@global", "LESSOPEN"=>"||/usr/bin/lesspipe.sh %s", "WINDOWPATH"=>"1", "XDG_RUNTIME_DIR"=>"/run/user/1000", "DISPLAY"=>":3.0", "GLADE_CATALOG_PATH"=>":", "rvm_warn_clr"=>"\e[33m", "RUBY_VERSION"=>"ruby-2.0.0-p0", "PERL_MM_OPT"=>"INSTALL_BASE=/home/jlecuirot/perl5", "XAUTHORITY"=>"/var/run/gdm/auth-for-jlecuirot-pp8Xbd/database", "COLORTERM"=>"Terminal", "CCACHE_HASHDIR"=>"", "_"=>"/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/bin/ahn", "_ORIGINAL_GEM_PATH"=>"/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0:/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0@global", "BUNDLE_GEMFILE"=>"/home/jlecuirot/Open/ahn-test/Gemfile", "BUNDLE_BIN_PATH"=>"/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/bundler-1.3.5/bin/bundle", "RUBYOPT"=>"-I/home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/bundler-1.3.5/lib -rbundler/setup"}
[2013-05-06 10:31:52] 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

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

  # Enable or disable Punchblock connectivity to a Voice server [AHN_PUNCHBLOCK_ENABLED]
  config.punchblock.enabled            = true

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

  # The media engine to use. Defaults to platform default. [AHN_PUNCHBLOCK_MEDIA_ENGINE]
  config.punchblock.media_engine       = 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           = "noisraehda"

  # 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           = "adhearsion"

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

  # Lifetime of a call after it has hung up [AHN_PLATFORM_AFTER_HANGUP_LIFETIME]
  config.platform.after_hangup_lifetime = 30

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

[2013-05-06 10:31:52] TRACE Adhearsion::Initializer: Gem versions: ["rake 10.0.4", "i18n 0.6.1", "multi_json 1.7.3", "activesupport 3.2.13", "adhearsion-loquacious 1.9.3", "bundler 1.3.5", "timers 1.1.0", "celluloid 0.13.0", "countdownlatch 1.0.0", "deep_merge 1.0.0", "ffi 1.8.1", "future-resource 1.0.0", "connection_pool 1.0.0", "rubinius-core-api 0.0.1", "rubinius-actor 0.0.2", "girl_friday 0.11.2", "has-guarded-handlers 1.5.0", "little-plugger 1.1.3", "logging 1.8.1", "coderay 1.0.9", "method_source 0.8.1", "slop 3.4.4", "pry 0.9.12.1", "eventmachine 1.0.3", "nokogiri 1.5.9", "niceogiri 1.1.2", "blather 0.8.4", "nio4r 0.4.5", "celluloid-io 0.13.1", "ruby_ami 2.0.0", "json 1.7.7", "ruby_fs 1.1.0", "ruby_speech 1.1.0", "state_machine 1.2.0", "punchblock 1.9.0", "thor 0.18.1", "adhearsion 2.3.2", "adhearsion-asterisk 1.3.1"]
[2013-05-06 10:31:52] INFO  Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2013-05-06 10:31:53] DEBUG Punchblock::Connection::Asterisk: Starting up...
[2013-05-06 10:31:53] INFO  Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [SEND] Action: login
ActionID: 18439587-7205-443a-93fd-23b159244da5
Username: adhearsion
Secret: noisraehda
Events: On

[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] Asterisk Call Manager/1.3
Response: Success
ActionID: 18439587-7205-443a-93fd-23b159244da5
Message: Authentication accepted

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

[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"18439587-7205-443a-93fd-23b159244da5", "Message"=>"Authentication accepted"}, text_body=nil, events=[]>
[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=[]>
[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [SEND] Action: command
ActionID: 8b2a8f64-00e5-4698-8b9d-a41e90383698
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect

[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Follows
Privilege: Command
ActionID: 8b2a8f64-00e5-4698-8b9d-a41e90383698
Extension '1,1,AGI(agi:async)' added into 'adhearsion-redirect' context
--END COMMAND--

[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"8b2a8f64-00e5-4698-8b9d-a41e90383698", "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=[]>
[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [SEND] Action: command
ActionID: 7df4090c-6d55-4218-b3bd-0f179b4d500b
Command: dialplan show adhearsion-redirect

[2013-05-06 10:31:53] INFO  Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Follows
Privilege: Command
ActionID: 7df4090c-6d55-4218-b3bd-0f179b4d500b
[ Context 'adhearsion-redirect' created by 'pbx_config' ]
  '1' =>            1. AGI(agi:async)                             [pbx_config]

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

[2013-05-06 10:31:53] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"7df4090c-6d55-4218-b3bd-0f179b4d500b"}, 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=[]>
[2013-05-06 10:31:53] WARN  Punchblock::Translator::Asterisk: Recordings directory /var/punchblock/record does not exist. Recording might not work. This warning can be ignored if Adhearsion is running on a separate machine than Asterisk. See http://adhearsion.com/docs/call-controllers#recording
[2013-05-06 10:31:53] INFO  Adhearsion::Console: Launching Adhearsion Console
[2013-05-06 10:31:53] INFO  Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2013-05-06 10:31:53] INFO  Adhearsion::Initializer: Adhearsion v2.3.2 initialized in "development"!
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/gigaset-0000000b
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: gigaset
CallerIDName: Gigaset
AccountCode: 
Exten: 1337
Context: default
Uniqueid: 1367832715.11

Event: VarSet
Privilege: dialplan,all
Channel: SIP/gigaset-0000000b
Variable: SIPURI
Value: sip:gigaset@192.168.1.30:5060
Uniqueid: 1367832715.11

Event: VarSet
Privilege: dialplan,all
Channel: SIP/gigaset-0000000b
Variable: SIPDOMAIN
Value: 192.168.1.39
Uniqueid: 1367832715.11

Event: VarSet
Privilege: dialplan,all
Channel: SIP/gigaset-0000000b
Variable: SIPCALLID
Value: 1928328933@192_168_1_30
Uniqueid: 1367832715.11

Event: Newstate
Privilege: call,all
Channel: SIP/gigaset-0000000b
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: gigaset
CallerIDName: Gigaset
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 1367832715.11

[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-0000000b", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "AccountCode"=>"", "Exten"=>"1337", "Context"=>"default", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-0000000b", "Variable"=>"SIPURI", "Value"=>"sip:gigaset@192.168.1.30:5060", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-0000000b", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.1.39", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-0000000b", "Variable"=>"SIPCALLID", "Value"=>"1928328933@192_168_1_30", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-0000000b", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newexten
Privilege: dialplan,all
Channel: SIP/gigaset-0000000b
Context: default
Extension: 1337
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1367832715.11

Event: AsyncAGI
Privilege: agi,all
SubEvent: Start
Channel: SIP/gigaset-0000000b
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fgigaset-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201367832715.11%0Aagi_version%3A%2011.2.2%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%20default%0Aagi_extension%3A%201337%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140353279575808%0A%0A

[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-0000000b", "Context"=>"default", "Extension"=>"1337", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/gigaset-0000000b", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Fgigaset-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201367832715.11%0Aagi_version%3A%2011.2.2%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%20default%0Aagi_extension%3A%201337%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140353279575808%0A%0A"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="1337", from="Gigaset <SIP/gigaset>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/gigaset-0000000b", :x_agi_language=>"en", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1367832715.11", :x_agi_version=>"11.2.2", :x_agi_callerid=>"gigaset", :x_agi_calleridname=>"Gigaset", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"1337", :x_agi_rdnis=>"unknown", :x_agi_context=>"default", :x_agi_extension=>"1337", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"140353279575808"}, call_id="38598941-717b-4726-9838-fbf5492003b0"
[2013-05-06 10:31:55] INFO  Adhearsion::Router: Call 38598941-717b-4726-9838-fbf5492003b0 selected route "default" (TestController)
[2013-05-06 10:31:55] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Executing command #<Punchblock::Command::Accept headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [SEND] Action: agi
ActionID: c0e06b2b-df0d-4de4-ac65-155e28c6b153
Channel: SIP/gigaset-0000000b
Command: EXEC RINGING
CommandID: 3f9d1c60-6a15-4f04-a4b7-614854b0d96b

[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: c0e06b2b-df0d-4de4-ac65-155e28c6b153
Message: Added AGI command to queue

[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"c0e06b2b-df0d-4de4-ac65-155e28c6b153", "Message"=>"Added AGI command to queue"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
SubEvent: Start
Channel: SIP/gigaset-0000000b
CommandId: 1879407050
Command: EXEC RINGING

Event: AGIExec
Privilege: agi,all
SubEvent: End
Channel: SIP/gigaset-0000000b
CommandId: 1879407050
Command: EXEC RINGING
ResultCode: 200
Result: Success

Event: AsyncAGI
Privilege: agi,all
SubEvent: Exec
Channel: SIP/gigaset-0000000b
CommandID: 3f9d1c60-6a15-4f04-a4b7-614854b0d96b
Result: 200%20result%3D0%0A

[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"Start", "Channel"=>"SIP/gigaset-0000000b", "CommandId"=>"1879407050", "Command"=>"EXEC RINGING"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-0000000b", "CommandId"=>"1879407050", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=[]>
[2013-05-06 10:31:55] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"Exec", "Channel"=>"SIP/gigaset-0000000b", "CommandID"=>"3f9d1c60-6a15-4f04-a4b7-614854b0d96b", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=[]>
[2013-05-06 10:31:56] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"Start", :channel=>"SIP/gigaset-0000000b", :commandid=>"1879407050", :command=>"EXEC RINGING"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:31:56] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AGIExec", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/gigaset-0000000b", :commandid=>"1879407050", :command=>"EXEC RINGING", :resultcode=>"200", :result=>"Success"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:31:56] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"Exec", :channel=>"SIP/gigaset-0000000b", :commandid=>"3f9d1c60-6a15-4f04-a4b7-614854b0d96b", :result=>"200%20result%3D0%0A"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:31:56] INFO  Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Executing controller #<TestController call=38598941-717b-4726-9838-fbf5492003b0, metadata={}>
[2013-05-06 10:31:56] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Offer to="1337", from="Gigaset <SIP/gigaset>", headers={:x_agi_request=>"async", :x_agi_channel=>"SIP/gigaset-0000000b", :x_agi_language=>"en", :x_agi_type=>"SIP", :x_agi_uniqueid=>"1367832715.11", :x_agi_version=>"11.2.2", :x_agi_callerid=>"gigaset", :x_agi_calleridname=>"Gigaset", :x_agi_callingpres=>"0", :x_agi_callingani2=>"0", :x_agi_callington=>"0", :x_agi_callingtns=>"0", :x_agi_dnid=>"1337", :x_agi_rdnis=>"unknown", :x_agi_context=>"default", :x_agi_extension=>"1337", :x_agi_priority=>"1", :x_agi_enhanced=>"0.0", :x_agi_accountcode=>"", :x_agi_threadid=>"140353279575808"}, call_id="38598941-717b-4726-9838-fbf5492003b0"
[2013-05-06 10:31:56] DEBUG Adhearsion::OutboundCall: : Executing command #<Punchblock::Command::Dial to="SIP/foo@aura-online.co.uk", from="Gigaset <SIP/gigaset>", join=nil, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [SEND] Action: originate
ActionID: 0b863fe8-4dcc-4c0e-8dde-fe5db054b417
Async: true
Application: AGI
Data: agi:async
Channel: SIP/foo@aura-online.co.uk
Callerid: Gigaset <SIP/gigaset>
Variable: punchblock_call_id=8eb7be66-c1c8-46b8-a8c1-2966cc3a281b
Timeout: 10000

[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: 0b863fe8-4dcc-4c0e-8dde-fe5db054b417
Message: Originate successfully queued

[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"0b863fe8-4dcc-4c0e-8dde-fe5db054b417", "Message"=>"Originate successfully queued"}, text_body=nil, events=[]>
[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000c
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 
CallerIDName: 
AccountCode: 
Exten: 
Context: default
Uniqueid: 1367832716.12

Event: VarSet
Privilege: dialplan,all
Channel: SIP/aura-online.co.uk-0000000c
Variable: SIPCALLID
Value: 165077883e4f7d750e2a8b3b378b2c10@213.123.185.55:5060
Uniqueid: 1367832716.12

Event: VarSet
Privilege: dialplan,all
Channel: SIP/aura-online.co.uk-0000000c
Variable: punchblock_call_id
Value: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b
Uniqueid: 1367832716.12

Event: NewAccountCode
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000c
Uniqueid: 1367832716.12
AccountCode: 
OldAccountCode: 

[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000c", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"default", "Uniqueid"=>"1367832716.12"}, text_body=nil, events=[]>
[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/aura-online.co.uk-0000000c", "Variable"=>"SIPCALLID", "Value"=>"165077883e4f7d750e2a8b3b378b2c10@213.123.185.55:5060", "Uniqueid"=>"1367832716.12"}, text_body=nil, events=[]>
[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/aura-online.co.uk-0000000c", "Variable"=>"punchblock_call_id", "Value"=>"8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", "Uniqueid"=>"1367832716.12"}, text_body=nil, events=[]>
[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000c", "Uniqueid"=>"1367832716.12", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=[]>
[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] Event: NewCallerid
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000c
CallerIDNum: SIP/gigaset
CallerIDName: Gigaset
Uniqueid: 1367832716.12
CID-CallingPres: 0 (Presentation Allowed, Not Screened)

[2013-05-06 10:31:56] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000c", "CallerIDNum"=>"SIP/gigaset", "CallerIDName"=>"Gigaset", "Uniqueid"=>"1367832716.12", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=[]>
[2013-05-06 10:31:56] DEBUG Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/aura-online.co.uk-0000000c", :variable=>"punchblock_call_id", :value=>"8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", :uniqueid=>"1367832716.12"}, target_call_id="8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:31:56] DEBUG Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/aura-online.co.uk-0000000c", :uniqueid=>"1367832716.12", :accountcode=>"", :oldaccountcode=>""}, target_call_id="8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:31:56] DEBUG Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewCallerid", attributes_hash={:privilege=>"call,all", :channel=>"SIP/aura-online.co.uk-0000000c", :calleridnum=>"SIP/gigaset", :calleridname=>"Gigaset", :uniqueid=>"1367832716.12", :cid_callingpres=>"0 (Presentation Allowed, Not Screened)"}, target_call_id="8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:06] DEBUG Adhearsion::CallController::Dial::Dial: #dial finished. Hanging up 1 outbound calls: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b.
[2013-05-06 10:32:06] INFO  Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Hanging up
[2013-05-06 10:32:06] DEBUG Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Executing command #<Punchblock::Command::Hangup headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-05-06 10:32:06] TRACE Punchblock::Connection::Asterisk: [SEND] Action: hangup
ActionID: 5534d0c4-a6ec-4095-915c-14b1b0e6b5bd
Channel: SIP/aura-online.co.uk-0000000c
Cause: 16

[2013-05-06 10:32:06] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: 5534d0c4-a6ec-4095-915c-14b1b0e6b5bd
Message: Channel Hungup

Event: Hangup
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000c
Uniqueid: 1367832716.12
CallerIDNum: SIP/gigaset
CallerIDName: Gigaset
ConnectedLineNum: SIP/gigaset
ConnectedLineName: Gigaset
AccountCode: 
Cause: 16
Cause-txt: Normal Clearing

[2013-05-06 10:32:06] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"5534d0c4-a6ec-4095-915c-14b1b0e6b5bd", "Message"=>"Channel Hungup"}, text_body=nil, events=[]>
[2013-05-06 10:32:06] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000c", "Uniqueid"=>"1367832716.12", "CallerIDNum"=>"SIP/gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"SIP/gigaset", "ConnectedLineName"=>"Gigaset", "AccountCode"=>"", "Cause"=>"16", "Cause-txt"=>"Normal Clearing"}, text_body=nil, events=[]>
[2013-05-06 10:32:06] TRACE Punchblock::Connection::Asterisk: [RECV] Event: OriginateResponse
Privilege: call,all
ActionID: 0b863fe8-4dcc-4c0e-8dde-fe5db054b417
Response: Failure
Channel: SIP/foo@aura-online.co.uk
Context: 
Exten: 
Reason: 1
Uniqueid: <null>
CallerIDNum: SIP/gigaset
CallerIDName: Gigaset

[2013-05-06 10:32:06] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="OriginateResponse", headers={"Privilege"=>"call,all", "ActionID"=>"0b863fe8-4dcc-4c0e-8dde-fe5db054b417", "Response"=>"Failure", "Channel"=>"SIP/foo@aura-online.co.uk", "Context"=>"", "Exten"=>"", "Reason"=>"1", "Uniqueid"=>"<null>", "CallerIDNum"=>"SIP/gigaset", "CallerIDName"=>"Gigaset"}, text_body=nil, events=[]>
[2013-05-06 10:32:06] DEBUG Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/aura-online.co.uk-0000000c", :uniqueid=>"1367832716.12", :calleridnum=>"SIP/gigaset", :calleridname=>"Gigaset", :connectedlinenum=>"SIP/gigaset", :connectedlinename=>"Gigaset", :accountcode=>"", :cause=>"16", :cause_txt=>"Normal Clearing"}, target_call_id="8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:06] FATAL Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: RESULT IS :timeout
[2013-05-06 10:32:06] DEBUG Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="8eb7be66-c1c8-46b8-a8c1-2966cc3a281b", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:06] INFO  Adhearsion::OutboundCall: 8eb7be66-c1c8-46b8-a8c1-2966cc3a281b: Call ended
[2013-05-06 10:32:09] DEBUG Adhearsion::OutboundCall: : Executing command #<Punchblock::Command::Dial to="SIP/foo@aura-online.co.uk", from="Gigaset <SIP/gigaset>", join=nil, headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [SEND] Action: originate
ActionID: 26221c59-2070-4e27-a2a2-3b1be3550ab6
Async: true
Application: AGI
Data: agi:async
Channel: SIP/foo@aura-online.co.uk
Callerid: Gigaset <SIP/gigaset>
Variable: punchblock_call_id=41a2a1a5-20b5-43c3-8954-ea51f3e7afea
Timeout: 10000

[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: 26221c59-2070-4e27-a2a2-3b1be3550ab6

[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] Message: Originate successfully queued

[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"26221c59-2070-4e27-a2a2-3b1be3550ab6", "Message"=>"Originate successfully queued"}, text_body=nil, events=[]>
[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newchannel
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000d
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 
CallerIDName: 
AccountCode: 
Exten: 
Context: default
Uniqueid: 1367832729.13

Event: VarSet
Privilege: dialplan,all
Channel: SIP/aura-online.co.uk-0000000d
Variable: SIPCALLID
Value: 5e90ef267febe3d33c9550290d1ad817@213.123.185.55:5060
Uniqueid: 1367832729.13

[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000d", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"", "CallerIDName"=>"", "AccountCode"=>"", "Exten"=>"", "Context"=>"default", "Uniqueid"=>"1367832729.13"}, text_body=nil, events=[]>
[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/aura-online.co.uk-0000000d", "Variable"=>"SIPCALLID", "Value"=>"5e90ef267febe3d33c9550290d1ad817@213.123.185.55:5060", "Uniqueid"=>"1367832729.13"}, text_body=nil, events=[]>
[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] Event: VarSet
Privilege: dialplan,all
Channel: SIP/aura-online.co.uk-0000000d
Variable: punchblock_call_id
Value: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea
Uniqueid: 1367832729.13

Event: NewAccountCode
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000d
Uniqueid: 1367832729.13
AccountCode: 
OldAccountCode: 

Event: NewCallerid
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000d
CallerIDNum: SIP/gigaset
CallerIDName: Gigaset
Uniqueid: 1367832729.13
CID-CallingPres: 0 (Presentation Allowed, Not Screened)

[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/aura-online.co.uk-0000000d", "Variable"=>"punchblock_call_id", "Value"=>"41a2a1a5-20b5-43c3-8954-ea51f3e7afea", "Uniqueid"=>"1367832729.13"}, text_body=nil, events=[]>
[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="NewAccountCode", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000d", "Uniqueid"=>"1367832729.13", "AccountCode"=>"", "OldAccountCode"=>""}, text_body=nil, events=[]>
[2013-05-06 10:32:09] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="NewCallerid", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000d", "CallerIDNum"=>"SIP/gigaset", "CallerIDName"=>"Gigaset", "Uniqueid"=>"1367832729.13", "CID-CallingPres"=>"0 (Presentation Allowed, Not Screened)"}, text_body=nil, events=[]>
[2013-05-06 10:32:09] DEBUG Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/aura-online.co.uk-0000000d", :variable=>"punchblock_call_id", :value=>"41a2a1a5-20b5-43c3-8954-ea51f3e7afea", :uniqueid=>"1367832729.13"}, target_call_id="41a2a1a5-20b5-43c3-8954-ea51f3e7afea", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:09] DEBUG Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewAccountCode", attributes_hash={:privilege=>"call,all", :channel=>"SIP/aura-online.co.uk-0000000d", :uniqueid=>"1367832729.13", :accountcode=>"", :oldaccountcode=>""}, target_call_id="41a2a1a5-20b5-43c3-8954-ea51f3e7afea", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:09] DEBUG Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="NewCallerid", attributes_hash={:privilege=>"call,all", :channel=>"SIP/aura-online.co.uk-0000000d", :calleridnum=>"SIP/gigaset", :calleridname=>"Gigaset", :uniqueid=>"1367832729.13", :cid_callingpres=>"0 (Presentation Allowed, Not Screened)"}, target_call_id="41a2a1a5-20b5-43c3-8954-ea51f3e7afea", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] DEBUG Adhearsion::CallController::Dial::Dial: #dial finished. Hanging up 1 outbound calls: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea.
[2013-05-06 10:32:19] INFO  Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Hanging up
[2013-05-06 10:32:19] DEBUG Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Executing command #<Punchblock::Command::Hangup headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [SEND] Action: hangup
ActionID: 5167a20d-46b2-461e-bd8a-ed1596784254
Channel: SIP/aura-online.co.uk-0000000d
Cause: 16

[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Hangup
Privilege: call,all
Channel: SIP/aura-online.co.uk-0000000d
Uniqueid: 1367832729.13
CallerIDNum: SIP/gigaset
CallerIDName: Gigaset
ConnectedLineNum: SIP/gigaset
ConnectedLineName: Gigaset
AccountCode: 
Cause: 0
Cause-txt: Unknown

Event: OriginateResponse
Privilege: call,all
ActionID: 26221c59-2070-4e27-a2a2-3b1be3550ab6
Response: Failure
Channel: SIP/foo@aura-online.co.uk
Context: 
Exten: 
Reason: 3
Uniqueid: <null>
CallerIDNum: SIP/gigaset
CallerIDName: Gigaset

[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/aura-online.co.uk-0000000d", "Uniqueid"=>"1367832729.13", "CallerIDNum"=>"SIP/gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"SIP/gigaset", "ConnectedLineName"=>"Gigaset", "AccountCode"=>"", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="OriginateResponse", headers={"Privilege"=>"call,all", "ActionID"=>"26221c59-2070-4e27-a2a2-3b1be3550ab6", "Response"=>"Failure", "Channel"=>"SIP/foo@aura-online.co.uk", "Context"=>"", "Exten"=>"", "Reason"=>"3", "Uniqueid"=>"<null>", "CallerIDNum"=>"SIP/gigaset", "CallerIDName"=>"Gigaset"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Error
ActionID: 5167a20d-46b2-461e-bd8a-ed1596784254
Message: No such channel

[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Error message="No such channel", headers=>
[2013-05-06 10:32:19] DEBUG Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/aura-online.co.uk-0000000d", :uniqueid=>"1367832729.13", :calleridnum=>"SIP/gigaset", :calleridname=>"Gigaset", :connectedlinenum=>"SIP/gigaset", :connectedlinename=>"Gigaset", :accountcode=>"", :cause=>"0", :cause_txt=>"Unknown"}, target_call_id="41a2a1a5-20b5-43c3-8954-ea51f3e7afea", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] DEBUG Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="41a2a1a5-20b5-43c3-8954-ea51f3e7afea", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] INFO  Adhearsion::OutboundCall: 41a2a1a5-20b5-43c3-8954-ea51f3e7afea: Call ended
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Finished executing controller #<TestController call=38598941-717b-4726-9838-fbf5492003b0, metadata={}>
[2013-05-06 10:32:19] ERROR Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: <Punchblock::ProtocolError> #<Punchblock::ProtocolError: name="error" text="No such channel" call_id=nil component_id=nil>
    /home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/celluloid-0.13.0/lib/celluloid/responses.rb:29:in `value'
    /home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/celluloid-0.13.0/lib/celluloid/actor.rb:69:in `call'
    /home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/celluloid-0.13.0/lib/celluloid/legacy.rb:14:in `method_missing'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call.rb:22:in `method_missing'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller/dial.rb:154:in `block in cleanup_calls'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller/dial.rb:152:in `each'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller/dial.rb:152:in `cleanup_calls'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller/dial.rb:54:in `dial'
    /home/jlecuirot/Open/ahn-test/lib/test_controller.rb:4:in `block in run'
    /home/jlecuirot/Open/ahn-test/lib/test_controller.rb:3:in `loop'
    /home/jlecuirot/Open/ahn-test/lib/test_controller.rb:3:in `run'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:106:in `execute!'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:81:in `block in exec'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:80:in `catch'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:80:in `exec'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:97:in `exec_with_callback'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:91:in `block (2 levels) in bg_exec'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/foundation/exception_handler.rb:5:in `catching_standard_errors'
    /home/jlecuirot/Open/adhearsion/lib/adhearsion/call_controller.rb:90:in `block in bg_exec'
    /home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
    /home/jlecuirot/.rvm/gems/ruby-2.0.0-p0/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
[2013-05-06 10:32:19] INFO  Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Hanging up
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Executing command #<Punchblock::Command::Hangup headers_hash={}, target_call_id=nil, component_id=nil, target_mixer_name=nil, state_name=:new>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [SEND] Action: hangup
ActionID: f0755e68-b376-40a9-8053-d8e27ffbd5ad
Channel: SIP/gigaset-0000000b
Cause: 16

[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: f0755e68-b376-40a9-8053-d8e27ffbd5ad
Message: Channel Hungup

[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"f0755e68-b376-40a9-8053-d8e27ffbd5ad", "Message"=>"Channel Hungup"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AsyncAGI
Privilege: agi,all
SubEvent: End
Channel: SIP/gigaset-0000000b

Event: VarSet
Privilege: dialplan,all
Channel: SIP/gigaset-0000000b
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1367832715.11

Event: SoftHangupRequest
Privilege: call,all
Channel: SIP/gigaset-0000000b
Uniqueid: 1367832715.11
Cause: 16

Event: Hangup
Privilege: call,all
Channel: SIP/gigaset-0000000b
Uniqueid: 1367832715.11
CallerIDNum: gigaset
CallerIDName: Gigaset
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
AccountCode: 
Cause: 16
Cause-txt: Normal Clearing

[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "SubEvent"=>"End", "Channel"=>"SIP/gigaset-0000000b"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Channel"=>"SIP/gigaset-0000000b", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1367832715.11"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="SoftHangupRequest", headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-0000000b", "Uniqueid"=>"1367832715.11", "Cause"=>"16"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Channel"=>"SIP/gigaset-0000000b", "Uniqueid"=>"1367832715.11", "CallerIDNum"=>"gigaset", "CallerIDName"=>"Gigaset", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "AccountCode"=>"", "Cause"=>"16", "Cause-txt"=>"Normal Clearing"}, text_body=nil, events=[]>
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="AsyncAGI", attributes_hash={:privilege=>"agi,all", :subevent=>"End", :channel=>"SIP/gigaset-0000000b"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="VarSet", attributes_hash={:privilege=>"dialplan,all", :channel=>"SIP/gigaset-0000000b", :variable=>"AGISTATUS", :value=>"HANGUP", :uniqueid=>"1367832715.11"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="SoftHangupRequest", attributes_hash={:privilege=>"call,all", :channel=>"SIP/gigaset-0000000b", :uniqueid=>"1367832715.11", :cause=>"16"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="Hangup", attributes_hash={:privilege=>"call,all", :channel=>"SIP/gigaset-0000000b", :uniqueid=>"1367832715.11", :calleridnum=>"gigaset", :calleridname=>"Gigaset", :connectedlinenum=>"<unknown>", :connectedlinename=>"<unknown>", :accountcode=>"", :cause=>"16", :cause_txt=>"Normal Clearing"}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] DEBUG Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, target_call_id="38598941-717b-4726-9838-fbf5492003b0", component_id=nil, target_mixer_name=nil>
[2013-05-06 10:32:19] INFO  Adhearsion::Call: 38598941-717b-4726-9838-fbf5492003b0: Call ended
benlangfeld commented 11 years ago

So, what is happening here is that #dial is attempting to hang up the call, and Punchblock is executing this request as an AMI Hangup action. In the time between sending the action and it being executed, Asterisk is firing a hangup event because the originate failed. The Hangup action is then failing, and we're passing on the error, instead of swallowing as we should. This is a regression, because we used to ignore AMI errors. We don't any more, but we don't necessarily handle cases like this correctly.

This is being triggered by the overlapping timeouts. We instruct Asterisk to timeout the originate after 10s, triggering the Hangup event, but we also keep our own timeout of 10s which is triggering the Hangup command. This is for safety, since we don't want to be at the mercy of Asterisk failing to hangup in time.

Fix coming shortly.