Another "/!\ FAILSAFE /!\...Status: 500 Internal Server Error"

[Rick]

This is a problem I've been chasing for a week now. It is triggered
by swapping ruby 1.9 for ruby 1.8. The "FAILSAFE" error comes from
rack 1.0.0, rack 0.9.1 gave a different message but failed
nonetheless.

I've been working with the ruby folks, see ruby-lang issue 1414 (my
naive assumption on where the problem originates). My own
investigation has been hampered by the lack of ruby-debug support for
ruby 1.9 combined with the absence of the problem when using ruby 1.8.

However, I just received this message - it may shed some light for
someone familiar with the rack code:
-------------------------
Although I don't know what ActionController::UploadedStringIO
is, I suspect it may be relevant that StringIO#path is no
longer defined.

--
Nobu Nakada
-------------------------

This email came in response to the rack 0.9.1 log messages which read:

-------------------------
NameError (undefined method `path' for class
`ActionController::UploadedStringIO'):
<internal:prelude>:8:in `synchronize'
thin (1.0.0) lib/thin/connection.rb:63:in `pre_process'
thin (1.0.0) lib/thin/connection.rb:54:in `process'
thin (1.0.0) lib/thin/connection.rb:39:in `receive_data'
eventmachine (0.12.6) lib/eventmachine.rb:240:in `run_machine'
eventmachine (0.12.6) lib/eventmachine.rb:240:in `run'
thin (1.0.0) lib/thin/backends/base.rb:57:in `start'
thin (1.0.0) lib/thin/server.rb:150:in `start'
-------------------------

The rack 1.0.0 log messages for the same attempted upload read:

-------------------------
/!\ FAILSAFE /!\ 2009-05-01 10:05:18 -1000
Status: 500 Internal Server Error
invalid byte sequence in US-ASCII
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/utils.rb:
324:in `=~'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/utils.rb:
324:in `block in parse_multipart'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/utils.rb:
319:in `loop'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/utils.rb:
319:in `parse_multipart'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/request.rb:
141:in `POST'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/
methodoverride.rb:15:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/actionpack-2.3.2/lib/
action_controller/params_parser.rb:15:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/actionpack-2.3.2/lib/
action_controller/rewindable_input.rb:25:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/actionpack-2.3.2/lib/
action_controller/session/cookie_store.rb:93:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/actionpack-2.3.2/lib/
action_controller/reloader.rb:9:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/actionpack-2.3.2/lib/
action_controller/failsafe.rb:11:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/lock.rb:
11:in `block in call'
<internal:prelude>:8:in `synchronize'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/lock.rb:
11:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/actionpack-2.3.2/lib/
action_controller/dispatcher.rb:106:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rails-2.3.2/lib/rails/rack/
static.rb:31:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/urlmap.rb:
46:in `block in call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/urlmap.rb:
40:in `each'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/urlmap.rb:
40:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rails-2.3.2/lib/rails/rack/
log_tailer.rb:17:in `call'
/opt/RoR/lib/ruby/gems/1.9.1/gems/thin-1.0.0/lib/thin/
connection.rb:63:in `pre_process'
/opt/RoR/lib/ruby/gems/1.9.1/gems/thin-1.0.0/lib/thin/
connection.rb:54:in `process'
/opt/RoR/lib/ruby/gems/1.9.1/gems/thin-1.0.0/lib/thin/
connection.rb:39:in `receive_data'
/opt/RoR/lib/ruby/gems/1.9.1/gems/eventmachine-0.12.6/lib/
eventmachine.rb:240:in `run_machine'
/opt/RoR/lib/ruby/gems/1.9.1/gems/eventmachine-0.12.6/lib/
eventmachine.rb:240:in `run'
/opt/RoR/lib/ruby/gems/1.9.1/gems/thin-1.0.0/lib/thin/backends/
base.rb:57:in `start'
/opt/RoR/lib/ruby/gems/1.9.1/gems/thin-1.0.0/lib/thin/server.rb:
150:in `start'
/opt/RoR/lib/ruby/gems/1.9.1/gems/thin-1.0.0/lib/rack/handler/
thin.rb:14:in `run'
/opt/RoR/lib/ruby/gems/1.9.1/gems/rails-2.3.2/lib/commands/
server.rb:111:in `<top (required)>'
script/server:3:in `require'
script/server:3:in `<main>'
-------------------------

Here is the page that triggers the error (on clicking create):

-------------------------
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">

<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
<head>
<meta http-equiv="content-type" content="text/html;charset=UTF-8" />
<title>Users: new</title>
<link href="/stylesheets/scaffold.css?1240786686" media="screen"
rel="stylesheet" type="text/css" />
</head>
<body>
<form action="/mugshots" enctype="multipart/form-data"
method="post"><div style="margin:0;padding:0"><input
name="authenticity_token" type="hidden"
value="EL9no9L6TBkwWbc70x3ytHgv3zlzffVU3+oMm/nW3CI=" /></div><p>
<label for="mugshot_uploaded_datal">Upload A Mugshot:</label>
<input id="mugshot_uploaded_data" name="mugshot[uploaded_data]"
size="30" type="file" />
</p>
<p>
<input name="commit" type="submit" value="Create" />
</p>
</form>

</body>
</html>
-------------------------

Needless to say, this page passes W3 Markup Validation with full
green, not even a warning.

One thing I notice here that I don't understand is that the html
source (and w3) clearly identify the page as being of:
<meta http-equiv="content-type" content="text/
html;charset=UTF-8" />

However, the error message in the log tells me:
/!\ FAILSAFE /!\ 2009-05-01 10:05:18 -1000
Status: 500 Internal Server Error
invalid byte sequence in US-ASCII

[Rick]

<label for="mugshot_uploaded_datal">Upload A Mugshot:</label>

is actually:

<label for="mugshot_uploaded_data">Upload A Mugshot:</label>

error is unchanged

[Si]

I'm also getting this with my file upload forms. Ruby 1.9.2-dev, Rails
2.3.2, Rack 1.0, Webrick, using UTF-8 char set.

[Si]

Thought I'd have a dig into this, and it appears that adding:

read_buffer.force_encoding("ascii-8bit") if RUBY_VERSION >= "1.9"

to force the read buffer to binary at
Rack::Utils::Multipart#self.parse_multipart:313 allows the Rack
portion to work. The problem being that the buffer is created with the
default encoding (no initial data in it, so Ruby won't guess
otherwise), and this will cause problems when the data hits buf for
scanning with the regex.

After that you will get back to the previous Rack 0.9.1 error you
mention.

As Nobu Nakada points out, StringIO no longer has path. By commenting
out the alias from ActionController::UploadedFile#self.included:6, the
upload works. I'm not sure if path was being used or not in Rails -
there must have been good reason to pull it from Ruby after all - but
I only find mention of the new alias, local_path, in a test:

actionpack-2.3.2/test/controller/test_test.rb

[Rick]

The "ascii-8bit" change to utils.rb makes sense to me. I can
understand it as one bit of internationalization cruft that didn't get
scrubbed.

I must admit, however, the change in uploaded_file.rb has me
confused. I can follow the code thread from the (0.9.1) error report
back to the file but, other than the fact "it works in my situation",
I'm having problems taking it in. One immediate question is why apply
it to self.included and not self.extended 7 lines later?

By the way, what sort of success have you had running rake tests on
actionpack-2.3.2?

rick

[Si]

I see UploadedFile#self.extended is used in normalize_parameters of
action_controller's request.rb. I assume it's dealing with a heavier
weight representation of an IO object, with real path info. StringIO,
according to it's source, is only a psuedo IO object, for if the core
lib version is not available, so path is not available.

Do you mean tests of actionpack itself? I'm running RSpec and
Autospec, and having no problems generally, but I'm not running Rails
tests. My aim for this problem (and other 1.9 related issues) is just
to get everything working for me in development. Most of my issues
have been with string encoding perhaps unsurprisingly, but most are
easily fixed with magic comments.

Aha! Even as I write, a fix has been checked in for ActiveMerchant
UTF-8 encoding issues. Cool.

https://jadedpixel.lighthouseapp.com/projects/11599/tickets/77-please-add-ruby-19-magic-comments-for-utf-encoded-source

Probably the biggest trouble areas left for me are mixed encodings in
templates (Haml in my case), and that the DB adapter (PostgreSQL) will
only give back ASCII encoded strings, ignoring that it's actually
UTF-8. That looks to be a very common problem with the adapters. With
my dev test data though, everything is working very well.

Considering the changes going into Rails and Rack, this problem with
uploads might already be fixed in head versions, but I'm only looking
to use the released versions that I'll have in production, so quick
hackery for dev is ideal for now.

[Si]

OK, that sucks:

2309 tests, 10826 assertions, 29 failures, 8 errors

App in development has no known problems right now though. I do have
an old test-unit (1.2.3) in place for RSpec on Ruby 1.9 compatibility
etc, and am getting lots of stuff like this:

<MiniTest::Assertion> exception expected but was Class:
<Test::Unit::AssertionFailedError>

So, perhaps I have a setup that's clashing with the Rails tests.

[Si]

Looks like the problem with those ActionPack tests was Mocha for me,
but I don't use it ordinarily:

https://rails.lighthouseapp.com/projects/8994/tickets/2060-installation-of-miniunit-causes-test-to-fail

[Si]

I didn't have to make any changes to get this working on a Linux
deployment. Things that spring to mind:

Dev is OSX, Production is Linux
Phusion Passenger and Ruby 1.9.1 / Rails 2.3.2 for both
Apache was NOT configured correctly for UTF-8 external encoding at the
time I tried this, on OSX, but I had this configured correctly early
on with Linux Apache (HTTPD_LANG=en_US.UTF-8 in /etc/sysconfig/httpd
(Linux), but EnvironmentVariables needed in /System/Library/
LaunchDaemons/org.apache.httpd.plist (OSX))