[2016-05-01 22:27:20] TRACE Adhearsion::Initializer: OS: linux-gnu - RUBY: ruby 1.9.3
[2016-05-01 22:27:20] TRACE Adhearsion::Initializer: Environment: {"MAIL"=>"/var/mail/sjamaan", "USER"=>"sjamaan", "LANGUAGE"=>"en_GB:en", "SSH_AGENT_PID"=>"1710", "SHLVL"=>"1", "HOME"=>"/home/sjamaan", "DBUS_SESSION_BUS_ADDRESS"=>"unix:abstract=/tmp/dbus-Vp955Yk8gl,guid=4af9769f1049f99da2ca41385725d78a", "LOGNAME"=>"sjamaan", "rvm_bin_path"=>"/home/sjamaan/.rvm/bin", "IRBRC"=>"/home/sjamaan/.rvm/rubies/ruby-1.9.3-p551/.irbrc", "RUBY_VERSION"=>"ruby-1.9.3-p551", "PATH"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551/bin:/home/sjamaan/.rvm/gems/ruby-1.9.3-p551@global/bin:/home/sjamaan/.rvm/rubies/ruby-1.9.3-p551/bin:/home/sjamaan/.rvm/bin:/home/sjamaan/chickens/use-this/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games", "MY_RUBY_HOME"=>"/home/sjamaan/.rvm/rubies/ruby-1.9.3-p551", "DISPLAY"=>":0.0", "LANG"=>"en_GB.UTF-8", "XAUTHORITY"=>"/home/sjamaan/.Xauthority", "SSH_AUTH_SOCK"=>"/tmp/ssh-MFikAtWJb0Ay/agent.1611", "SHELL"=>"/bin/zsh", "rvm_prefix"=>"/home/sjamaan", "GEM_HOME"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551", "rvm_version"=>"1.27.0 (master)", "GPG_AGENT_INFO"=>"/tmp/gpg-rYfFMx/S.gpg-agent:1711:1", "PWD"=>"/tmp/ami_proxy", "GEM_PATH"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551:/home/sjamaan/.rvm/gems/ruby-1.9.3-p551@global", "rvm_path"=>"/home/sjamaan/.rvm", "TERM"=>"xterm", "WINDOWID"=>"25165839", "XTERM_VERSION"=>"XTerm(312)", "XTERM_LOCALE"=>"en_GB.UTF-8", "XTERM_SHELL"=>"/bin/zsh", "OLDPWD"=>"/tmp", "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: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:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=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:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=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:*.webm=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=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.axa=00;36:*.oga=00;36:*.spx=00;36:*.xspf=00;36:", "rvm_alias_expanded"=>"", "rvm_bin_flag"=>"", "rvm_docs_type"=>"", "rvm_gemstone_package_file"=>"", "rvm_gemstone_url"=>"", "rvm_niceness"=>"", "rvm_nightly_flag"=>"", "rvm_only_path_flag"=>"", "rvm_proxy"=>"", "rvm_quiet_flag"=>"", "rvm_ruby_bits"=>"", "rvm_ruby_file"=>"", "rvm_ruby_make"=>"", "rvm_ruby_make_install"=>"", "rvm_ruby_mode"=>"", "rvm_script_name"=>"", "rvm_sdk"=>"", "rvm_silent_flag"=>"", "rvm_use_flag"=>"", "rvm_wrapper_name"=>"", "install_flag"=>"1", "reinstall_flag"=>"1", "_system_type"=>"Linux", "_system_name"=>"Debian", "_system_version"=>"8", "_system_arch"=>"x86_64", "rvm_hook"=>"", "_"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551@global/bin/bundle", "_ORIGINAL_GEM_PATH"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551:/home/sjamaan/.rvm/gems/ruby-1.9.3-p551@global", "BUNDLE_BIN_PATH"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551@global/gems/bundler-1.7.6/bin/bundle", "BUNDLE_GEMFILE"=>"/tmp/ami_proxy/Gemfile", "RUBYOPT"=>"-rbundler/setup", "RUBYLIB"=>"/home/sjamaan/.rvm/gems/ruby-1.9.3-p551@global/gems/bundler-1.7.6/lib"}
[2016-05-01 22:27:20] TRACE Adhearsion::Initializer:   # ******* Configuration for punchblock **************

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

  # Directory containing certificates for securing the connection. [AHN_PUNCHBLOCK_CERTS_DIRECTORY]
  config.punchblock.certs_directory    = 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           = "secret"

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

  # ******* 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                  = "/tmp/ami_proxy"


[2016-05-01 22:27:20] TRACE Adhearsion::Initializer: Gem versions: ["rake 11.1.2", "i18n 0.7.0", "multi_json 1.11.3", "activesupport 3.2.22.2", "adhearsion-loquacious 1.9.3", "bundler 1.7.6", "timers 1.1.0", "celluloid 0.15.0", "countdownlatch 1.0.0", "deep_merge 1.0.1", "ffi 1.9.10", "connection_pool 1.2.0", "rubinius-core-api 0.0.1", "rubinius-actor 0.0.2", "girl_friday 0.11.2", "has-guarded-handlers 1.6.3", "little-plugger 1.1.4", "logging 1.8.2", "coderay 1.1.1", "method_source 0.8.2", "slop 3.6.0", "pry 0.10.3", "eventmachine 1.2.0.1", "mini_portile 0.5.3", "nokogiri 1.6.1", "niceogiri 1.1.2", "blather 1.2.0", "future-resource 1.1.0", "nio4r 1.2.1", "celluloid-io 0.15.0", "ruby_ami 2.4.0", "ruby_fs 1.1.1", "ruby_speech 1.1.0", "state_machine 1.2.0", "punchblock 1.9.4", "thor 0.18.1", "adhearsion 2.3.5", "adhearsion-asterisk 1.5.1"]
[2016-05-01 22:27:20] INFO  Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2016-05-01 22:27:20] DEBUG Punchblock::Connection::Asterisk: Starting up...
[2016-05-01 22:27:20] INFO  Adhearsion::Console: Launching Adhearsion Console
[2016-05-01 22:27:20] INFO  Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [SEND] Action: login
ActionID: 5f1cdc58-4e5d-4ee1-8a38-a3538c09e863
Username: username
Secret: secret
Events: On


[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] Asterisk Call Manager/2.8.0

[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success

[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] ActionID: 5f1cdc58-4e5d-4ee1-8a38-a3538c09e863

[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] Message: Authentication accepted

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


[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"5f1cdc58-4e5d-4ee1-8a38-a3538c09e863", "Message"=>"Authentication accepted"}, text_body=nil, events=[]>
[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="FullyBooted", headers={"Privilege"=>"system,all", "Status"=>"Fully Booted"}, text_body=nil, events=[]>
[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [SEND] Action: command
ActionID: 33cbadd0-042d-4353-ba67-3c888c29416a
Command: dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect


[2016-05-01 22:27:20] INFO  Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Follows
Privilege: Command
ActionID: 33cbadd0-042d-4353-ba67-3c888c29416a
Extension 1@adhearsion-redirect with priority 1 already exists
Command 'dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect' failed.
--END COMMAND--


[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"33cbadd0-042d-4353-ba67-3c888c29416a"}, text_body="Extension 1@adhearsion-redirect with priority 1 already exists\nCommand 'dialplan add extension 1,1,AGI,agi:async into adhearsion-redirect' failed.", events=[]>
[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [SEND] Action: command
ActionID: 208ddf15-994d-432f-96c2-90d8e3b07d11
Command: dialplan show adhearsion-redirect


[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Follows
Privilege: Command

[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] ActionID: 208ddf15-994d-432f-96c2-90d8e3b07d11

[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] [ Context 'adhearsion-redirect' created by 'pbx_config' ]
  '1' =>            1. AGI(agi:async)                             [pbx_config]

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

[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] --END COMMAND--


[2016-05-01 22:27:20] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"Privilege"=>"Command", "ActionID"=>"208ddf15-994d-432f-96c2-90d8e3b07d11"}, 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=[]>
[2016-05-01 22:27:20] 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
[2016-05-01 22:27:20] INFO  Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2016-05-01 22:27:20] INFO  Adhearsion::Initializer: Adhearsion v2.3.5 initialized in "development"!
[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [SEND] Action: queuestatus
ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd


[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success

[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd

[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] EventList: start

[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] Message: Queue status will follow


[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"8a69bc89-f422-4429-a584-8d68ec1977dd", "EventList"=>"start", "Message"=>"Queue status will follow"}, text_body=nil, events=[]>
[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] Event: QueueParams
Queue: 2003
Max: 0
Strategy: rrmemory
Calls: 0
Holdtime: 0
TalkTime: 0
Completed: 0
Abandoned: 0
ServiceLevel: 60
ServicelevelPerf: 0.0
Weight: 0
ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd

Event: QueueParams
Queue: 2002
Max: 0
Strategy: rrmemory
Calls: 0
Holdtime: 0
TalkTime: 0
Completed: 0
Abandoned: 0
ServiceLevel: 60
ServicelevelPerf: 0.0
Weight: 0
ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd


[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="QueueParams", headers={"Queue"=>"2003", "Max"=>"0", "Strategy"=>"rrmemory", "Calls"=>"0", "Holdtime"=>"0", "TalkTime"=>"0", "Completed"=>"0", "Abandoned"=>"0", "ServiceLevel"=>"60", "ServicelevelPerf"=>"0.0", "Weight"=>"0", "ActionID"=>"8a69bc89-f422-4429-a584-8d68ec1977dd"}, text_body=nil, events=[]>
[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="QueueParams", headers={"Queue"=>"2002", "Max"=>"0", "Strategy"=>"rrmemory", "Calls"=>"0", "Holdtime"=>"0", "TalkTime"=>"0", "Completed"=>"0", "Abandoned"=>"0", "ServiceLevel"=>"60", "ServicelevelPerf"=>"0.0", "Weight"=>"0", "ActionID"=>"8a69bc89-f422-4429-a584-8d68ec1977dd"}, text_body=nil, events=[]>
[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] Event: QueueParams
Queue: 2001
Max: 0
Strategy: rrmemory
Calls: 0
Holdtime: 0
TalkTime: 0
Completed: 0
Abandoned: 0
ServiceLevel: 60
ServicelevelPerf: 0.0
Weight: 0
ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd

Event: QueueMember
Queue: 2001
Name: SIP/1002
Location: SIP/1002
StateInterface: SIP/1002
Membership: static
Penalty: 0
CallsTaken: 0
LastCall: 0
InCall: 0
Status: 4
Paused: 0
PausedReason: 
ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd

Event: QueueStatusComplete
ActionID: 8a69bc89-f422-4429-a584-8d68ec1977dd
EventList: Complete
ListItems: 4


[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="QueueParams", headers={"Queue"=>"2001", "Max"=>"0", "Strategy"=>"rrmemory", "Calls"=>"0", "Holdtime"=>"0", "TalkTime"=>"0", "Completed"=>"0", "Abandoned"=>"0", "ServiceLevel"=>"60", "ServicelevelPerf"=>"0.0", "Weight"=>"0", "ActionID"=>"8a69bc89-f422-4429-a584-8d68ec1977dd"}, text_body=nil, events=[]>
[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="QueueMember", headers={"Queue"=>"2001", "Name"=>"SIP/1002", "Location"=>"SIP/1002", "StateInterface"=>"SIP/1002", "Membership"=>"static", "Penalty"=>"0", "CallsTaken"=>"0", "LastCall"=>"0", "InCall"=>"0", "Status"=>"4", "Paused"=>"0", "PausedReason"=>"", "ActionID"=>"8a69bc89-f422-4429-a584-8d68ec1977dd"}, text_body=nil, events=[]>
[2016-05-01 22:27:25] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="QueueStatusComplete", headers={"ActionID"=>"8a69bc89-f422-4429-a584-8d68ec1977dd", "EventList"=>"Complete", "ListItems"=>"4"}, text_body=nil, events=[]>
[2016-05-01 22:27:33] INFO  Adhearsion::Initializer: Received SIGINT. Shutting down.
[2016-05-01 22:27:33] INFO  Adhearsion::Process: Transitioning from running to stopping with 0 active calls due to shutdown event.
[2016-05-01 22:27:33] DEBUG Punchblock::Connection::Asterisk: Finalizing stream
[2016-05-01 22:27:33] WARN  Celluloid: Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
[2016-05-01 22:27:33] INFO  Adhearsion::PunchblockPlugin::Initializer: Shutting down while connecting. Breaking the connection block.
[2016-05-01 22:27:33] INFO  Adhearsion::Console: Adhearsion Console shutting down
[2016-05-01 22:27:33] INFO  Adhearsion::Process: Adhearsion shut down
[2016-05-01 22:27:33] DEBUG Celluloid: Terminating 4 actors...