REALLY hard to debug errors in web-console

[schneems]

Hit a bug in web_console when trying to upgrade to Rails 5. It took me hours to figure out where it was coming from. This was the only thing in my logs:

Started GET "/" for ::1 at 2016-01-11 16:39:26 -0600

This was what I was rendering in development mode:

Why was this happening? Web-console inserts itself right before debug_exceptions middleware which makes sense, normally this is the middleware that would render the error to the logs, however web-console relies on getting the request before this point. Unfortunately this means it comes right after show_exceptions middleware which contrary to the name, does not show what exception is occurring, instead it swallows it and returns a default 500 response.

Bug: Web-console doesn't have any kind of fail safe response or debugging when internals fail. Either let's find a way to play nice with debug-exceptions middleware and put it afterwards, or essentially duplicate logic in debug-exceptions so we at least log errors to the logger.

[gsamokovarov]

I do feel your frustration. It gets tricky, especially when you don't suspect WebConsole::Middleware or ActionPack::DebugExceptions were the ones failing, because as you saw, there is no backtrace and you are in the dark.

---

I'll try to describe how Web Console works, so I can elaborate on the positioning:

When a request comes in, WebConsole::Middleware checks if it has to evaluate code in an already saved bindings. We call this a session. Those requests are initiated by the console UI itself. In this case, the middleware evaluates the input code and halts the middleware chain with a JSON for the console UI.

If this is not the case the, the middleware will let the other middlewares do their job and after they're done, will listen to whether someone in there wanted to initiate a new Web Console session. If they did, we insert the console UI alongside the already rendered content.

A session can be initiated by the console helper, which you can use in controller or view context. It saves a binding in env['web_console.binding'], which we can pick up and create a new session for it.

A session can be initiated from an exception as well. For this case, we have monkey patched ActionPack::DebugExceptions to leave the exception it's handing in env['web_console.exception'].

This is why we position WebConsole::Middleware before ActionPack::DebugExceptions in the middleware stack. We let Debug Exceptions handle the error, display the page and return the flow back to us. Then we insert the console UI in the response and create a session with the exception bindings, so the UI can evaluate code in them. That's probably where things fail for you. That's my guess.

---

So how I debug it? It's kinda primitive, but I attach a debugger at the beginning of WebConsole::Middleware#call and walk through every expression, testing where the middleware is blowing up. The monkey patch of ActionPack::DebugExceptions can be the one failing as well... ActionPack::ShowExceptions is there in development as a last resort. If everything else fails (even if it is ActionPack::DebugExceptions or WebConsole::Middleware) display something for the users.

To help with that, we can log exceptions in WebConsole::Middleware#call and continue without the console in the request when they occur. While those errors won't be actionable, the exempt from the logs can be useful for bug reports. I don't think we need to duplicate any code from Debug Exceptions here and I'll try to work on that. I'm quite curious what caused this for you...

[schneems]

I'm quite curious what caused this for you...

The error I was seeing was fixed in master. The method signature of ActionDispatch::RemoteIp::GetIP changed along with the internal instance variable names, it was fixed

web-console/lib/web_console/request.rb

Lines 32 to 41 in 0991238

	def initialize(req, proxies)
	# After rails/rails@07b2ff0 ActionDispatch::RemoteIp::GetIp initializes
	# with a ActionDispatch::Request object instead of plain Rack
	# environment hash. Keep both @req and @env here, so we don't if/else
	# on Rails versions.
	@req = req
	@env = req.env
	@check_ip = true
	@proxies = proxies
	end

.

FWIW I don't think we should over-write initialize without calling super. The names of instance variables aren't expected to be stable unless they're generated via attr_accessor and @req isn't. Even though this was fixed this one time, it may happen again in the future. If/else would be better than to couple to the internals of another request imho.

we can log exceptions in WebConsole::Middleware#call and continue without the console in the request when they occur.

Debugging was pretty easy when I figured out where the error was coming from. I just want to make sure errors that occur in web-console are logged. When an error happens in the app we don't need to log it because it's presumably been logged via debug_exceptions, we also don't want to swallow any errors, we should always re-raise. I think we could achieve that with something like this

def call_app(env)
  begin
    @app.call(env)
  rescue => e
    @app_exception = e
    throw(:app_exception)
  end
end

def call(env)
  catch(:app_exception) do
    # web-console stuff
    call_app(env)
    # more web-console stuff
  end
rescue => e
  Rails.logger.error("Zomg error in web-console#{e}")
  raise e
ensure
  raise app_exception if @app_exception
end

That way all exceptions will be re-raised, internal web-console errors will be logged, and app errors won't be double logged.

[olivierlacan]

Repro was easy for me. Update Gemfile from 4.2 to Rails 5 beta1, then try to boot the app.

Even after bundle update it was still crashing the way @schneems showed. I noticed the only version specification I had left was gem "web-console", "~> 2.0". Removed the "~> 2.0" and ran bundle update web-console, and everything worked after that.

So thanks for this issue and discussion. I would strongly recommend back-porting the master fix to the 2.0 branch and releasing a patch release just for the sake of saving yourself (maybe) from the hordes of people who will likely run into this bug when upgrading from Rails 4.x to 5.x since the lose ~> 2.0 dependency was a Rails 4.x default.

[gsamokovarov]

That's reasonable. Will try to put a 2.x patch release as well before the next Rails beta.

[sgrif]

Just as a note, I've had about half a dozen cases of people asking me "why don't exceptions work in Rails 5" that were caused by this. We should definitely make sure old gemfiles will work before releasing

[gsamokovarov]

I have released a new version (3.1.0) and a ~> 2.0 compatibility release (2.3.0).

Sadly, people will still have to do bundle update web-console to get their exceptions up and running 😞 Hopefully, it's a bit easier with the compat release.

[schneems]

Thanks for the release!

[thiensubs]

After I upgrade Rails from 5.0.2 to 5.1.1, it not working and always appear errors:
No such middleware to insert after: "ActionDispatch::DebugExceptions"
I was upgrade web-console to 3.5.1 but it still not working.
Here my track:

No such middleware to insert after: "ActionDispatch::DebugExceptions"
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/actionpack-5.1.1/lib/action_dispatch/middleware/stack.rb:106:in `assert_index'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/actionpack-5.1.1/lib/action_dispatch/middleware/stack.rb:80:in `insert_after'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/configuration.rb:69:in `block in merge_into'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/configuration.rb:68:in `each'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/configuration.rb:68:in `merge_into'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/engine.rb:507:in `block in app'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/engine.rb:504:in `synchronize'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/engine.rb:504:in `app'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/application/finisher.rb:45:in `block in <module:Finisher>'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/initializable.rb:30:in `instance_exec'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/initializable.rb:30:in `run'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/initializable.rb:59:in `block in run_initializers'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/initializable.rb:58:in `run_initializers'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/application.rb:353:in `initialize!'
/Users/thiensubs/Documents/super-control/config/environment.rb:5:in `<top (required)>'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:292:in `require'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:292:in `block in require'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:258:in `load_dependency'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:292:in `require'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/application.rb:329:in `require_environment!'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/railties-5.1.1/lib/rails/application.rb:445:in `block in run_tasks_blocks'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/gems/rake-11.3.0/exe/rake:27:in `<top (required)>'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/bin/ruby_executable_hooks:15:in `eval'
/Users/thiensubs/.rvm/gems/ruby-2.4.1/bin/ruby_executable_hooks:15:in `<main>'
Tasks: TOP => middleware => environment
(See full trace by running task with --trace)

Can you help me?

[gsamokovarov]

@thiensubs can you give me a bit more context when this error is happening? Is it during the application boot? Do you have any specific configurations about handling errors?

[thiensubs]

Here is my Gemfile

source 'https://rubygems.org'


# Bundle edge Rails instead: gem 'rails', github: 'rails/rails'
gem 'rails', '~> 5.1'
# Use SCSS for stylesheets
gem 'sass-rails', '~> 5.0'
# Use Uglifier as compressor for JavaScript assets
gem 'uglifier', '>= 1.3.0'
# Use CoffeeScript for .coffee assets and views
gem 'coffee-rails'
# See https://github.com/rails/execjs#readme for more supported runtimes
# gem 'therubyracer', platforms: :ruby
gem 'execjs'

# Use jquery as the JavaScript library
gem 'jquery-rails'
# Turbolinks makes following links in your web application faster. Read more: https://github.com/rails/turbolinks
gem 'turbolinks'

# Use ActiveModel has_secure_password
# gem 'bcrypt', '~> 3.1.7'

# Use Unicorn as the app server
# gem 'unicorn'

group :development, :test do
  # Call 'byebug' anywhere in the code to stop execution and get a debugger console
  # gem 'byebug'
  # gem 'bullet'
  gem 'rails-erd'
  gem 'erb_to_slim'
  gem 'mysql2'
end

group :development do
  # Access an IRB console on exception pages or by using <%= console %> in views
  gem 'web-console'
  gem 'listen'
  # Spring speeds up development by keeping your application running in the background. Read more: https://github.com/rails/spring
  gem 'spring'
end
group :test, :development do
  gem 'rspec-rails'
  # gem 'mongoid-rspec'
  gem 'shoulda-matchers', require: false
end
gem 'pry-rails'
gem 'devise', git: 'https://github.com/plataformatec/devise.git', branch: 'master'
gem 'whenever'
gem 'oj'
gem 'oj_mimic_json'
gem 'escape_utils'
gem 'sidekiq'
gem 'simple_form'
gem 'font-awesome-sass'
gem 'mongoid', git: 'https://github.com/mongodb/mongoid'
# gem 'bson_ext'
# gem 'rpush-mongoid', '~> 0.2.0'
gem 'airbrake', '~> 4.3.0'
# gem 'rpush'
gem "slim-rails"
gem 'simple_enum' , require: 'simple_enum/mongoid'
# gem 'countries'
# gem 'money'
# gem 'currencies'
# gem 'google_currency'
gem 'mina', '0.3.8'
gem 'mina-sidekiq'
gem 'will_paginate'
gem "will_paginate_mongoid"
gem "bower-rails", "~> 0.10.0"
gem 'react-rails'
gem 'mechanize'
# gem 'draper', '~> 1.3'
# gem 'tesseract'
gem 'apipie-rails'
gem 'telegram-bot-ruby'

gem 'parallel'
# gem 'browserlog', '~> 0.0.2'
# gem 'apriori-ruby'
# gem 'fpgrowth'
# gem 'mina-whenever'
#Upload File
gem "paperclip"
gem 'annotate'
gem 'item'
gem 'jquery-datatables-rails', git: 'git://github.com/rweng/jquery-datatables-rails.git'
gem "jquery-fileupload-rails"
gem "mongoid-paperclip"
# gem 'mobvious'
# gem 'mobvious-rails'
gem "chartkick"
gem 'awesome_print'
gem 'mongoid-geospatial', require: 'mongoid/geospatial'
gem 'remotipart', '~> 1.3'

This issue appear when I starting app or using any command rake like: rake routes, rake middleware...
I only upgrade Rails app from Rails 5.0.2 to Rails 5.1.1 .

[gsamokovarov]

Do you have any specific middleware configuration?