search

choonkeat / runtimeerror_notifier

runtimeerror_notifier gem for those without email sending resources
Other
2 stars 1 forks source link

Does not catch exceptions while rendering templates when HTTP streaming is enabled #4

Open vojtad opened 10 years ago

vojtad commented 10 years ago

Hey, I have noticed, that runtimeerror_notifier does not catch exceptions that occur while rendering page templates when HTTP streaming is enabled for that specific page. When I try to disable HTTP streaming it starts to work. Do you have any idea what could be wrong or how to make it work? I am using Rails 4.0.5 and runtimeerror_notifier 0.0.19.

Here is snippet with exception from heroku logs.

2014-06-08T10:55:07.157539+00:00 app[web.2]: Started GET "/38890599/flow-cytometric-analysis-of-cellmembrane-derived-microvesicles-in-tissue-culture-and-human-plasma" for 66.249.67.186 at 2014-06-08 10:55:07 +0000
2014-06-08T10:55:07.162541+00:00 app[web.2]:   Parameters: {"presentation"=>"38890599", "presentation_title"=>"flow-cytometric-analysis-of-cellmembrane-derived-microvesicles-in-tissue-culture-and-human-plasma"}
2014-06-08T10:55:07.162392+00:00 app[web.2]: Processing by PresentationController#show as */*
2014-06-08T10:55:07.226434+00:00 app[web.2]: Completed 200 OK in 64ms (Views: 2.0ms | ActiveRecord: 25.4ms)
2014-06-08T10:55:07.497447+00:00 app[web.2]: [AWS S3 200 0.264312 0 retries] head_object(:bucket_name=>"slideslive",:key=>"data/users/1844/background_image.jpg")
2014-06-08T10:55:07.497454+00:00 app[web.2]:
2014-06-08T10:55:07.774984+00:00 heroku[router]: at=info method=GET path=/38890599/flow-cytometric-analysis-of-cellmembrane-derived-microvesicles-in-tissue-culture-and-human-plasma host=slideslive.com request_id=10961dc4-774b-47f5-9483-3d3d4b276d5f fwd="66.249.67.186" dyno=web.2 connect=1ms service=618ms status=200 bytes=7405
2014-06-08T10:55:07.750168+00:00 app[web.2]: [AWS S3 200 0.141605 0 retries] head_object(:bucket_name=>"slideslive",:key=>"data/presentations/38890599/38890599.jpg")
2014-06-08T10:55:07.761283+00:00 app[web.2]:   Rendered app/views_mobile/layouts/_site_header.html.erb (5.9ms)
2014-06-08T10:55:07.750171+00:00 app[web.2]:
2014-06-08T10:55:07.771533+00:00 app[web.2]:
2014-06-08T10:55:07.758559+00:00 app[web.2]: Cache digest for layouts/_site_header.html: 4346dddc42756ab98786e21ec3297b19
2014-06-08T10:55:07.765952+00:00 app[web.2]: Read fragment views/presentations/38890599-20140608105507204473773/true/false/false/false/true/c118c123728bbd93a3d36d95bd5f7093 (1.1ms)
2014-06-08T10:55:07.771536+00:00 app[web.2]: ActionView::Template::Error (undefined method `has_role?' for nil:NilClass):
2014-06-08T10:55:07.771538+00:00 app[web.2]:     158:             <% end %>
2014-06-08T10:55:07.771540+00:00 app[web.2]:     159:           </div>
2014-06-08T10:55:07.771562+00:00 app[web.2]:     163:
2014-06-08T10:55:07.771559+00:00 app[web.2]:     161:           <% if current_user.has_role? :admin %>
2014-06-08T10:55:07.771572+00:00 app[web.2]:   /app/app/views/presentation/show.html.erb:161:in `block in _app_views_presentation_show_html_erb__3841342601483987573_70324593029300'
2014-06-08T10:55:07.771557+00:00 app[web.2]:     160:
2014-06-08T10:55:07.771561+00:00 app[web.2]:     162:               <div id="sl-player-error" class="removed">
2014-06-08T10:55:07.771583+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
2014-06-08T10:55:07.771571+00:00 app[web.2]:     164:               </div>
2014-06-08T10:55:07.771574+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/helpers/cache_helper.rb:185:in `fragment_for'
2014-06-08T10:55:07.771581+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/notifications.rb:159:in `block in instrument'
2014-06-08T10:55:07.771585+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/notifications.rb:159:in `instrument'
2014-06-08T10:55:07.771592+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
2014-06-08T10:55:07.771576+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/helpers/cache_helper.rb:115:in `cache'
2014-06-08T10:55:07.771586+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/template.rb:141:in `render'
2014-06-08T10:55:07.771590+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/notifications.rb:159:in `block in instrument'
2014-06-08T10:55:07.771602+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/chunked.rb:23:in `each'
2014-06-08T10:55:07.771589+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/abstract_renderer.rb:38:in `block in instrument'
2014-06-08T10:55:07.771596+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/streaming_template_renderer.rb:67:in `delayed_render'
2014-06-08T10:55:07.771598+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/streaming_template_renderer.rb:53:in `block in render_template'
2014-06-08T10:55:07.771580+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/template.rb:143:in `block in render'
2014-06-08T10:55:07.771600+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/streaming_template_renderer.rb:20:in `each'
2014-06-08T10:55:07.771577+00:00 app[web.2]:   /app/app/views/presentation/show.html.erb:87:in `_app_views_presentation_show_html_erb__3841342601483987573_70324593029300'
2014-06-08T10:55:07.771618+00:00 app[web.2]:
2014-06-08T10:55:07.771614+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/puma-2.8.2/lib/puma/server.rb:254:in `block in run'
2014-06-08T10:55:07.771594+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/abstract_renderer.rb:38:in `instrument'
2014-06-08T10:55:07.771593+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/notifications.rb:159:in `instrument'
2014-06-08T10:55:07.760952+00:00 app[web.2]: Read fragment views/header/true/4346dddc42756ab98786e21ec3297b19 (2.0ms)
2014-06-08T10:55:07.762739+00:00 app[web.2]:   Rendered application/_presentation_embed_code.html.erb (0.3ms)
2014-06-08T10:55:07.771015+00:00 app[web.2]:   Rendered presentation/show.html.erb within layouts/application (541.7ms)
2014-06-08T10:55:07.771608+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/body_proxy.rb:31:in `each'
2014-06-08T10:55:07.771605+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_dispatch/http/response.rb:42:in `each'
2014-06-08T10:55:07.771587+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/streaming_template_renderer.rb:91:in `block in delayed_render'
2014-06-08T10:55:07.771604+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_dispatch/http/response.rb:83:in `each'
2014-06-08T10:55:07.771612+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/puma-2.8.2/lib/puma/server.rb:361:in `process_client'
2014-06-08T10:55:07.771606+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/body_proxy.rb:31:in `each'
2014-06-08T10:55:07.771617+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/puma-2.8.2/lib/puma/thread_pool.rb:92:in `block in spawn_thread'
2014-06-08T10:55:07.771611+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/puma-2.8.2/lib/puma/server.rb:615:in `handle_request'
2014-06-08T10:55:07.771619+00:00 app[web.2]:
2014-06-08T10:55:07.771599+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_view/renderer/streaming_template_renderer.rb:20:in `call'
2014-06-08T10:55:07.771609+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/body_proxy.rb:31:in `each'
2014-06-08T10:55:07.771615+00:00 app[web.2]:   /app/vendor/bundle/ruby/2.0.0/gems/puma-2.8.2/lib/puma/thread_pool.rb:92:in `call'
choonkeat commented 10 years ago

Sorry I can't replicate it.

I created a bare bones controller app/controllers/users_controller.rb

class UsersController < ApplicationController
  def send_message
    render stream: true
  end
end

added to routes.rb

get '/users/send_message' => 'users#send_message'

with a broken template app/views/users/send_message.html.haml

%h3 Hello

= @user.bad

and received the notification.

Could you try the same and let me know? Perhaps I'm misunderstanding the issue or setup to replicate the bug

vojtad commented 10 years ago

Hi, I am sorry for my answering so late, but I was too busy. It still does not work for me. The only difference I see from your setup is that I use erb templates.

However, I believe I have found the source of my problem. Look at

lib/action_view/renderer/streaming_template_renderer.rb

in actionpack gem. It looks like every exception that occures while rendering the response body is rescued in ActionView::StreamingTemplateRenderer.each and then just logged using ActionView::StreamingTemplateRenderer.log_error.

I think this is the source of not logging exception by runtimeerror_notifier. No exception make its way to it up the stack.

However, I think the rendering of response body happens out of the middleware stack, so it is not possible to catch the exception even if it would not be rescued. I currently have no idea how to fix this, do you have any?