Rails 6 - error page logs no information if a file misreports line counts

[liamwhite]

Certain features of slim, such as the include directive, can cause files to misreport line counts. This leads to the problem as follows, which has cost me a significant amount of time debugging.

Steps to reproduce

1. Make a new Rails 6 app with rails _6.0.0.rc1_ new myapp6 --skip-javascript
2. Apply this patch

diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb
index 09705d1..cb940c1 100644
--- a/app/controllers/application_controller.rb
+++ b/app/controllers/application_controller.rb
@@ -1,2 +1,4 @@
 class ApplicationController < ActionController::Base
+  def home
+  end
 end
diff --git a/app/controllers/roots_controller.rb b/app/controllers/roots_controller.rb
new file mode 100644
index 0000000..e69de29
diff --git a/app/views/application/home.html.erb b/app/views/application/home.html.erb
new file mode 100644
index 0000000..0935688
--- /dev/null
+++ b/app/views/application/home.html.erb
@@ -0,0 +1,5 @@
+<%
+  error = NameError.new
+  error.set_backtrace ["#{Rails.root.join("app", "views", "application", "home.html.erb")}:999:in `eval'"]
+  raise error
+%>
diff --git a/config/routes.rb b/config/routes.rb
index c06383a..c5974ab 100644
--- a/config/routes.rb
+++ b/config/routes.rb
@@ -1,3 +1,4 @@
 Rails.application.routes.draw do
   # For details on the DSL available within this file, see https://guides.rubyonrails.org/routing.html
+  root to: 'application#home'
 end

3. Start the webserver. rails s
4. Navigate to the root path. Notice that the verbose error log does not appear, and only the generic error page appears.
   
5. Also notice that there is no detail of this error logged in the console.

Started GET "/" for 127.0.0.1 at 2019-07-20 01:29:47 +0000
   (0.2ms)  SELECT sqlite_version(*)
Processing by ApplicationController#home as HTML
  Rendering application/home.html.erb within layouts/application
  Rendered application/home.html.erb within layouts/application (Duration: 0.7ms | Allocations: 2030)
Completed 500 Internal Server Error in 2ms (ActiveRecord: 0.0ms | Allocations: 3430)

6. Also notice that there is no detail of this error logged in development.log.

Started GET "/" for 127.0.0.1 at 2019-07-20 01:29:47 +0000
   (0.2ms)  SELECT sqlite_version(*)
Processing by ApplicationController#home as HTML
  Rendering application/home.html.erb within layouts/application
  Rendered application/home.html.erb within layouts/application (Duration: 0.7ms | Allocations: 2030)
Completed 500 Internal Server Error in 2ms (ActiveRecord: 0.0ms | Allocations: 3430)

Expected behavior

Rails should at the very least output the exception class and message. While far from ideal of actually displaying an error page with exception information, this is at least debuggable.

This error is correctly logged in a Rails 5.2.3 application initialized with rails _5.2.3_ new myapp5 --skip-javascript.

diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb
index 09705d1..cb940c1 100644
--- a/app/controllers/application_controller.rb
+++ b/app/controllers/application_controller.rb
@@ -1,2 +1,4 @@
 class ApplicationController < ActionController::Base
+  def home
+  end
 end
diff --git a/app/controllers/roots_controller.rb b/app/controllers/roots_controller.rb
new file mode 100644
index 0000000..e69de29
diff --git a/app/views/application/home.html.erb b/app/views/application/home.html.erb
new file mode 100644
index 0000000..0935688
--- /dev/null
+++ b/app/views/application/home.html.erb
@@ -0,0 +1,5 @@
+<%
+  error = NameError.new
+  error.set_backtrace ["#{Rails.root.join("app", "views", "application", "home.html.erb")}:999:in `eval'"]
+  raise error
+%>
diff --git a/config/routes.rb b/config/routes.rb
index c06383a..c5974ab 100644
--- a/config/routes.rb
+++ b/config/routes.rb
@@ -1,3 +1,4 @@
 Rails.application.routes.draw do
   # For details on the DSL available within this file, see http://guides.rubyonrails.org/routing.html
+  root to: 'application#home'
 end

Started GET "/" for 127.0.0.1 at 2019-07-20 01:31:50 +0000
Processing by ApplicationController#home as HTML
  Rendering application/home.html.erb within layouts/application
  Rendered application/home.html.erb within layouts/application (4.3ms)
Completed 500 Internal Server Error in 9ms (ActiveRecord: 0.0ms)


  
ActionView::Template::Error (NameError):

Potential fixes

Add rescue nil here.

rails/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb

Line 151 in 3d2bdc1

message.concat(exception.annotated_source_code) if exception.respond_to?(:annotated_source_code)

If the end index is lower than the start index, return an empty array instead.

rails/actionview/lib/action_view/template/error.rb

Line 94 in 3d2bdc1

return unless source_code = source_code[start_on_line..end_on_line]

System configuration

Rails version: 6.0.0.rc1
Ruby version: ruby 2.6.3p62 (2019-04-16 revision 67580) [x86_64-linux]

[rafaelfranca]

Fixed by #36532

[AnomalousBit]

I can confirm the more general issue of some exceptions not being logged in the console on development still exists. I've had a couple of issues crop up in the past weeks around sassc compilation errors and today with an ActionView::Template::Error (Multiple files with the same output path cannot be linked) error, with the exceptions never being displayed in the console, leaving me completely stumped as to why my Rails app was returning HTTP 500 / error pages.

In my situation, I was able to step down to https://github.com/rails/rails/blob/master/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb#L146 and determine that concat() is throwing a new exception, causing the logging to be completely silenced when exception.annotated_source_code returns nil.

I've provided a self-tested fix in a PR that I'm about to post that logs the exceptions as one would expect. Hopefully this saves people a lot of time that I've spent tracking down silent errors.

[bobwhitelock]

I've just run into the same issue as @AnomalousBit above with a new Rails 6 install, the fix suggested in #38820 (comment) worked for me.

[SeedyROM]

@bobwhitelock God this was hard to figure out. Thanks everybody in this thread and thanks for the link to the other issue