So I spent about 3 hours today stuck on a problem that was so perplexing–and the answer so surprising–that I thought I should write about it. Several people reported different problems with the same symptoms, but no great matches for what I was seeing. So hopefully I can save a few people some trouble by writing this up.

Note: I’m working in Rails 3.0 on this project, and I haven’t experimented with this in 3.1 or 3.2. But that’s beside the point, really.

Symptoms

I was handing a POST action and then redirecting to an appropriate page with a success message in the Rails flash:

But instead of the redirect 302, the server was sending back a 406 Not Acceptable, which resulted in the browser displaying a blank screen, with no further information.

1
2
3
4
5
6

Started POST "/map/revert" for 127.0.0.1 at 2012-03-22 14:26:28 -0400
  Processing by MapsController#revert as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"XXX"}
...
Redirected to http://lightrules.dev/zones
Completed 406 Not Acceptable in 339ms

So the controller successfully redirected as I wanted, and then decided that the response was Not Acceptable? Well, that’s confusing.

Here’s a simplified version of the controller action:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

def revert

  @command = Command.new(:cmd => Command::RESET_MAP_TO_FILE)

  respond_to do |format|
    if @command.save
      EngineState.zero(:map_dirty)
      format.html {
        dest = session.delete(:map_return_to) || dashboard_url
        redirect_to dest, :notice => 'Map Changes Reverted.'
      }
      format.xml  { render :xml => @command, :status => :created, :location => @command }
      format.json { render :json => @command, :status => :created } # return for polling
    else
      # edited for brevity
    end
  end

end

Simple, right? Create and save a new Command object. No parameters, simple as can be. In fact I do the same thing quite often, so I’m repeating a pattern I kmow fairly well. But for some reason, we’re getting a 406, which means that the server can’t create a response like the client requested.

So digging into actionpack 3.0.12, I find the only place where Rails generates a 406 Not Acceptable:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

module ActionController #:nodoc:
  module MimeResponds #:nodoc:
    module ClassMethods
      # Collects mimes and return the response for the negotiated format. Returns
      # nil if :not_acceptable was sent to the client.
      #
      def retrieve_response_from_mimes(mimes=nil, &block)
        collector = Collector.new { default_render }
        mimes ||= collect_mimes_from_class_level
        mimes.each { |mime| collector.send(mime) }
        block.call(collector) if block_given?

        if format = request.negotiate_mime(collector.order)
          self.content_type ||= format.to_s
          lookup_context.freeze_formats([format.to_sym])
          collector.response_for(format)
        else
          head :not_acceptable
          nil
        end
      end
    end
  end
end

Ah, so it’s trying to negotiate the MIME type for the response, and it didn’t find one that’s acceptable.

So what did the client request?

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25

Request URL:http://lightrules.dev/map/revert
Request Method:POST
Status Code:406 Not Acceptable
Request Headers
  Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  Accept-Charset:ISO-8859-1,utf-8;q=0.7,*;q=0.3
  Accept-Encoding:gzip,deflate,sdch
  Accept-Language:en-US,en;q=0.8
  Cache-Control:max-age=0
  Connection:keep-alive
  Content-Length:82
  Content-Type:application/x-www-form-urlencoded
  Host:lightrules.dev
  Origin:http://lightrules.dev
  Referer:http://lightrules.dev/map/review
Form Data
  utf8:✓
  authenticity_token:rLJGT3VwSphAm/VtMTHz5bZMC0Npgoy8y6mMdz02GLk=
Response Headersview source
  Cache-Control:no-cache
  Connection:close
  Content-Type:text/html; charset=utf-8
  Location:http://lightrules.dev/zones
  X-Runtime:0.644635
  X-UA-Compatible:IE=Edge,chrome=1

Again, totally simple. It’s a form submit using HTTP method POST, and the Accept header specifies HTML and XML, which the controller recognized and routed properly to the format.html block in my action method. And then decided that it couldn’t generate an HTML response?

There’s obviously something broken with the MIME handling, so I tried removing the respond_to handling from the action, so it was a bare redirect_to call, but that didn’t help either.

Several hours into playing with this, I happened to trigger a double-render error with a strange backtrace:

1
2
3
4

AbstractController::DoubleRenderError (Render and/or redirect were called multiple times in this action. Please note that you may only call render OR redirect, and at most once per action. Also note that neither redirect nor render terminate execution of the action, so if you want to exit an action after redirecting, you need to do something like "redirect_to(...) and return".):
  app/controllers/maps_controller.rb:177:in `block (2 levels) in status'
  app/controllers/maps_controller.rb:176:in `status'
  app/controllers/maps_controller.rb:142:in `revert'

Wait, what? I have another custom action in the same controller called :status–part of a mechanism to refresh status on a completely different page dynamically via AJAX. But I was quite surprised to see that :status was being invoked from inside my :revert action method.

1
2
3
4
5

def status
  respond_to do |format|
    format.json { render :json => @fixture_status }
  end
end

It turns out that ActionController#status is already defined (actually delegated to the response object)–it’s one of those action names that you should know better than to override. But how exactly did calling that method break my :revert action?

Note that I only included one format, because I knew I’d only be using that action via AJAX and getting JSON back. It turns out that while processing the nested respond_to block, the controller code was comparing the requested HTML format with the :status action method’s ‘just json’ list, and coming up empty. Once that 406 is generated, no other response can be produced–not even a redirect!

Simply correcting the poorly-named :status action method cleaned up the problem.

Lessons Learned

If you’re going to wander off the REST reservation and make up arbitrary controller actions, be careful how you name them. Reusing a defined method name can result in some pretty inscrutible failure modes and cost you a lot of time.

The other lesson is to learn your way around the Rails stack (or whatever framework you’re building on). Stack Overflow may be handy, and I find clues on there from time to time, but often it’s blind men in a room describing an elephant. And it’s not even the same elephant you’re looking for. It turns out that there is authoritative information about how your framework behaves sitting right there on your disk, and you can learn a lot from it.