render_template fails when streaming is active (Rails 3.2)

[kylev]

Given rspec-rails 2.12.1 and a simple template controller:

class HelpController < ApplicationController
  def faq
    render stream: true
  end
end

And a related spec:

require 'spec_helper'

describe HelpController do
  describe "faq" do
    it "should be successful" do
      get :faq
      expect(should).do render_template 'faq'
    end
  end
end

The test should succeed. Instead, it fails:

  1) HelpController faq should be successful
     Failure/Error: response.should render_template 'faq'
       expecting <"faq"> but rendering with <"">
     # ./spec/controllers/help_controller_spec.rb:10:in `block (3 levels) in <top (required)>'

It should succeed. Removing the stream: true makes the test succeed.

[kylev]

This may be related to a actionpack bug, fixed not yet backported into the 3.2 series.

rails/rails#5288

[alindeman]

This may be related to a actionpack bug, fixed not yet backported into the 3.2 series.

Do you have time to apply the fix and see if it fixes your tests? Thanks!

[kylev]

It doesn't seem to work. I hand-patched my locally installed ActionController::TemplateAssertions with a reference to response.body (which should start the rendering sequence enough to resolve template lookups) and the test still fails.

  1) HelpController faq should be successful
     Failure/Error: response.should render_template 'faq'
       expecting <"faq"> but rendering with <"layouts/slimstrap">
     # ./spec/controllers/help_controller_spec.rb:10:in `block (3 levels) in <top (required)>'

I'm not terribly surprised by this as it sort of makes sense that streaming output would be primed with the layout template first, and render my designated template later on in the process. But it seems like a pretty bad bug (or possibly a misunderstanding on my part) in the public contract of assert_template.

Interestingly, with (1) the response.body hack in place as well as (2) turning on render_views the test will pass.

I'm going to dig a bit more this evening (if I have time) and post findings here. Perhaps the rails side of things should be treating streamed results a bit differently.

[kylev]

Still working on narrowing this down. It seems like this should pass with render_views still turned off.

If you want to see a completely minimal demonstration of the problem, I created a branch to demonstrate it off my "fresh" rails 3.2.x playground.

[fables-tales]

yo @alindeman I can probably take a look at this on tuesday if that's ok with you

[alindeman]

yo @alindeman I can probably take a look at this on tuesday if that's ok with you

That'd be awesome! Thanks for jumping in.

[kylev]

Note, I've updated my repro branch to demonstrate that the same effect seems present with .erb as well as .slim templates (both of which support streaming).

I also added a .haml verision that passes (HAML doesn't support streaming).

The failing tests happen regardless of whether you have the response.body reference back-port in place for ActionController::TemplateAssertions#assert_template, although slightly differently.

[fables-tales]

I'm getting an epic CNR with my current dev version of rspec.

shell output:

2 (rspec_slim)$ pwd
/Users/sam/dev/fresh32
3 (rspec_slim)$ bundle exec rspec
Rack::File headers parameter replaces cache_control after Rack 1.5.
#<ActionController::TestResponse:0x007fcdc43e2620 @body=#<Rack::Chunked::Body:0x007fcdc42e5510 @body=[""]>, @header={"Cache-Control"=>"no-cache", "Transfer-Encoding"=>"chunked", "Content-Type"=>"text/html; charset=utf-8"}, @status=200, @sending_file=false, @blank=false, @cache_control={}, @etag=nil, @writer=#<Proc:0x007fcdc43ec1e8@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/actionpack-3.2.11/lib/action_controller/test_case.rb:212 (lambda)>, @block=nil, @length=0, @content_type="text/html", @charset="utf-8", @template=nil, @request=#<ActionController::TestRequest:0x007fcdc470c0a8 @env={"rack.version"=>[1, 1], "rack.input"=>#<StringIO:0x007fcdc30ec430>, "rack.errors"=>#<StringIO:0x007fcdc42bb328>, "rack.multithread"=>true, "rack.multiprocess"=>true, "rack.run_once"=>false, "REQUEST_METHOD"=>"GET", "SERVER_NAME"=>"example.org", "SERVER_PORT"=>"80", "QUERY_STRING"=>"", "rack.url_scheme"=>"http", "HTTPS"=>"off", "SCRIPT_NAME"=>nil, "CONTENT_LENGTH"=>"0", "action_dispatch.routes"=>#<ActionDispatch::Routing::RouteSet:0x007fcdc46b8930>, "action_dispatch.parameter_filter"=>[:password], "action_dispatch.secret_token"=>"81d251c8d06b01e4c726bd7285c4f3d2308ff920827bab5e8a53907eac7afe86d87bc051d1e57a8abf59a7e231eb1a43d9fa5128a8107ca39f952706b98c09b5", "action_dispatch.show_exceptions"=>false, "action_dispatch.show_detailed_exceptions"=>true, "action_dispatch.logger"=>#<ActiveSupport::TaggedLogging:0x007fcdc3097c00 @logger=#<ActiveSupport::BufferedLogger:0x007fcdc30907e8 @log_dest=#<File:/Users/sam/dev/fresh32/log/test.log>, @log=#<Logger:0x007fcdc3090720 @progname=nil, @level=0, @default_formatter=#<Logger::Formatter:0x007fcdc3090630 @datetime_format=nil>, @formatter=#<Logger::SimpleFormatter:0x007fcdc30901d0 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x007fcdc3090518 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<File:/Users/sam/dev/fresh32/log/test.log>, @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fcdc30904a0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fcdc3090220>>>>>>, "action_dispatch.backtrace_cleaner"=>#<Rails::BacktraceCleaner:0x007fcdc43db320 @filters=[#<Proc:0x007fcdc43db258@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:10>, #<Proc:0x007fcdc43db230@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:11>, #<Proc:0x007fcdc43db208@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:12>, #<Proc:0x007fcdc43e2b20@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:26>], @silencers=[#<Proc:0x007fcdc43e2af8@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:15>]>, "HTTP_HOST"=>"test.host", "REMOTE_ADDR"=>"0.0.0.0", "HTTP_USER_AGENT"=>"Rails Testing", "rack.session"=>{}, "rack.session.options"=>{:key=>"rack.session", :path=>"/", :domain=>nil, :expire_after=>nil, :secure=>false, :httponly=>true, :defer=>false, :renew=>false, :sidbits=>128, :cookie_only=>true, :secure_random=>SecureRandom, :id=>"18df12ec1bbf8d975202f71cb20cd8e2"}, "action_dispatch.request.query_parameters"=>{}, "action_dispatch.cookies"=>#<ActionDispatch::Cookies::CookieJar:0x007fcdc43ec670 @secret="81d251c8d06b01e4c726bd7285c4f3d2308ff920827bab5e8a53907eac7afe86d87bc051d1e57a8abf59a7e231eb1a43d9fa5128a8107ca39f952706b98c09b5", @set_cookies={}, @delete_cookies={}, @host="test.host", @secure=false, @closed=false, @cookies={}>, "rack.request.cookie_hash"=>{}, "action_dispatch.request.path_parameters"=>{"controller"=>"pages", "action"=>"with_slim"}, "action_dispatch.request.content_type"=>nil, "action_dispatch.request.request_parameters"=>{}, "action_dispatch.request.flash_hash"=>#<ActionDispatch::Flash::FlashHash:0x007fcdc30ec1d8 @used=#<Set: {}>, @closed=false, @flashes={}, @now=nil>, "PATH_INFO"=>"/pages/with_slim", "action_dispatch.request.parameters"=>{"controller"=>"pages", "action"=>"with_slim"}, "action_dispatch.request.formats"=>[text/html]}, @formats=nil, @symbolized_path_params={:controller=>"pages", :action=>"with_slim"}, @request_method="GET", @method="GET", @protocol="http://", @remote_ip=nil, @ip=nil, @fullpath="/pages/with_slim", @set_cookies={}, @cookies={}, @port=80, @filtered_parameters={"controller"=>"pages", "action"=>"with_slim"}>>
...

Finished in 0.04999 seconds
3 examples, 0 failures

Randomized with seed 13585

4 (rspec_slim)$ git diff
diff --git a/Gemfile b/Gemfile
index 00d2156..beb380d 100644
--- a/Gemfile
+++ b/Gemfile
@@ -24,7 +24,7 @@ end
 gem 'jquery-rails'

 group :test, :development do
-  gem 'rspec-rails'
+  gem 'rspec-rails', path:"/Users/sam/dev/rspec/rspec-rails"
 end

 # To use ActiveModel has_secure_password
diff --git a/Gemfile.lock b/Gemfile.lock
index b2f5239..bfce0e4 100644
--- a/Gemfile.lock
+++ b/Gemfile.lock
@@ -1,3 +1,14 @@
+PATH
+  remote: /Users/sam/dev/rspec/rspec-rails
+  specs:
+    rspec-rails (2.12.0)
+      actionpack (>= 3.0)
+      activesupport (>= 3.0)
+      railties (>= 3.0)
+      rspec-core (~> 2.12.0)
+      rspec-expectations (~> 2.12.0)
+      rspec-mocks (~> 2.12.0)
+
 GEM
   remote: https://rubygems.org/
   specs:
@@ -85,13 +96,6 @@ GEM
     rspec-expectations (2.12.1)
       diff-lcs (~> 1.1.3)
     rspec-mocks (2.12.1)
-    rspec-rails (2.12.2)
-      actionpack (>= 3.0)
-      activesupport (>= 3.0)
-      railties (>= 3.0)
-      rspec-core (~> 2.12.0)
-      rspec-expectations (~> 2.12.0)
-      rspec-mocks (~> 2.12.0)
     sass (3.2.5)
     sass-rails (3.2.6)
       railties (~> 3.2.0)
@@ -125,7 +129,7 @@ DEPENDENCIES
   haml
   jquery-rails

ruby version: ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-darwin11.4.0]

rspec-rails version: 1d15db0

[fables-tales]

I've got this revision of @kylev's repo: a03589ce500269bbc661a8304eafbf906ed447d5

[kylev]

Can you repro it with the version my app specifies?

[fables-tales]

I can, the failure trace looks like this:

0 (rspec_slim)$ bundle exec rspec
Rack::File headers parameter replaces cache_control after Rack 1.5.
#<ActionController::TestResponse:0x007ff71e801c28 @body=#<Rack::Chunked::Body:0x007ff71db17490 @body=#<ActionView::StreamingTemplateRenderer::Body:0x007ff71db19560 @start=#<Proc:0x007ff71db17f30@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/actionpack-3.2.11/lib/action_view/renderer/streaming_template_renderer.rb:55>>>, @header={"Cache-Control"=>"no-cache", "Transfer-Encoding"=>"chunked", "Content-Type"=>"text/html; charset=utf-8"}, @status=200, @sending_file=false, @blank=false, @cache_control={}, @etag=nil, @writer=#<Proc:0x007ff71eee0b20@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/actionpack-3.2.11/lib/action_controller/test_case.rb:212 (lambda)>, @block=nil, @length=0, @content_type="text/html", @charset="utf-8", @template=nil, @request=#<ActionController::TestRequest:0x007ff71ee67590 @env={"rack.version"=>[1, 1], "rack.input"=>#<StringIO:0x007ff71e95b060>, "rack.errors"=>#<StringIO:0x007ff71c03b9f0>, "rack.multithread"=>true, "rack.multiprocess"=>true, "rack.run_once"=>false, "REQUEST_METHOD"=>"GET", "SERVER_NAME"=>"example.org", "SERVER_PORT"=>"80", "QUERY_STRING"=>"", "rack.url_scheme"=>"http", "HTTPS"=>"off", "SCRIPT_NAME"=>nil, "CONTENT_LENGTH"=>"0", "action_dispatch.routes"=>#<ActionDispatch::Routing::RouteSet:0x007ff71df286b0>, "action_dispatch.parameter_filter"=>[:password], "action_dispatch.secret_token"=>"81d251c8d06b01e4c726bd7285c4f3d2308ff920827bab5e8a53907eac7afe86d87bc051d1e57a8abf59a7e231eb1a43d9fa5128a8107ca39f952706b98c09b5", "action_dispatch.show_exceptions"=>false, "action_dispatch.show_detailed_exceptions"=>true, "action_dispatch.logger"=>#<ActiveSupport::TaggedLogging:0x007ff71de40130 @logger=#<ActiveSupport::BufferedLogger:0x007ff71de386d8 @log_dest=#<File:/Users/sam/dev/fresh32/log/test.log>, @log=#<Logger:0x007ff71de38610 @progname=nil, @level=0, @default_formatter=#<Logger::Formatter:0x007ff71de40568 @datetime_format=nil>, @formatter=#<Logger::SimpleFormatter:0x007ff71de401d0 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x007ff71de40310 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<File:/Users/sam/dev/fresh32/log/test.log>, @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007ff71de40298 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007ff71de401f8>>>>>>, "action_dispatch.backtrace_cleaner"=>#<Rails::BacktraceCleaner:0x007ff71e802bc8 @filters=[#<Proc:0x007ff71e802ab0@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:10>, #<Proc:0x007ff71e802a88@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:11>, #<Proc:0x007ff71e802a60@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:12>, #<Proc:0x007ff71e802218@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:26>], @silencers=[#<Proc:0x007ff71e8021f0@/Users/sam/.rvm/gems/ruby-1.9.3-p194/gems/railties-3.2.11/lib/rails/backtrace_cleaner.rb:15>]>, "HTTP_HOST"=>"test.host", "REMOTE_ADDR"=>"0.0.0.0", "HTTP_USER_AGENT"=>"Rails Testing", "rack.session"=>{}, "rack.session.options"=>{:key=>"rack.session", :path=>"/", :domain=>nil, :expire_after=>nil, :secure=>false, :httponly=>true, :defer=>false, :renew=>false, :sidbits=>128, :cookie_only=>true, :secure_random=>SecureRandom, :id=>"6df5b0b0c51be99510f4f4d08b893dce"}, "action_dispatch.request.query_parameters"=>{}, "action_dispatch.cookies"=>#<ActionDispatch::Cookies::CookieJar:0x007ff71eee1728 @secret="81d251c8d06b01e4c726bd7285c4f3d2308ff920827bab5e8a53907eac7afe86d87bc051d1e57a8abf59a7e231eb1a43d9fa5128a8107ca39f952706b98c09b5", @set_cookies={}, @delete_cookies={}, @host="test.host", @secure=false, @closed=false, @cookies={}>, "rack.request.cookie_hash"=>{}, "action_dispatch.request.path_parameters"=>{"controller"=>"pages", "action"=>"with_slim"}, "action_dispatch.request.content_type"=>nil, "action_dispatch.request.request_parameters"=>{}, "action_dispatch.request.flash_hash"=>#<ActionDispatch::Flash::FlashHash:0x007ff71e95af98 @used=#<Set: {}>, @closed=false, @flashes={}, @now=nil>, "PATH_INFO"=>"/pages/with_slim", "action_dispatch.request.parameters"=>{"controller"=>"pages", "action"=>"with_slim"}, "action_dispatch.request.formats"=>[text/html]}, @formats=nil, @symbolized_path_params={:controller=>"pages", :action=>"with_slim"}, @request_method="GET", @method="GET", @protocol="http://", @remote_ip=nil, @ip=nil, @fullpath="/pages/with_slim", @set_cookies={}, @cookies={}, @port=80, @filtered_parameters={"controller"=>"pages", "action"=>"with_slim"}>>
FF.

Failures:

  1) PagesController GET 'with_slim' returns http success and the with_slim template
     Failure/Error: response.should render_template 'with_slim'
       expecting <"with_slim"> but rendering with <"">
     # ./spec/controllers/pages_controller_spec.rb:10:in `block (3 levels) in <top (required)>'

  2) PagesController GET 'with_erb' returns http success and the with_erb template
     Failure/Error: response.should render_template 'with_erb'
       expecting <"with_erb"> but rendering with <"">
     # ./spec/controllers/pages_controller_spec.rb:18:in `block (3 levels) in <top (required)>'

Finished in 0.0536 seconds
3 examples, 2 failures

Failed examples:

rspec ./spec/controllers/pages_controller_spec.rb:6 # PagesController GET 'with_slim' returns http success and the with_slim template
rspec ./spec/controllers/pages_controller_spec.rb:15 # PagesController GET 'with_erb' returns http success and the with_erb template

Randomized with seed 23043

This means the issue has been fixed between the current release and dev versions of rspec-rails.

[kylev]

Perhaps this has to do with the new EmptyTemplateHandler...

[fables-tales]

@kylev so it's been fixed in the dev version of rspec, I'd expect the next release to cause this issue to be fixed. @alindeman do you agree?

[alindeman]

Very nice. I honestly don't know exactly why EmptyTemplateHandler would have fixed this issue, but the view pipeline is complicated :) The enhancement will be in a future rspec-rails 2.13, yep! Thanks for tracking this down as always @samphippen.