Lighthouse has a new layout. Prefer the old one? Return to the old layout, and switch back any time from the link at the top of each page.

This project is archived and is in readonly mode.

Rails 3.0 crashes Ruby 1.9.2p0 on repeated browser refresh

#5590

I'm not 100% certain whether this is a Ruby issue or a Rails issue (or a bit of both). It appears to be related to threading and the Rails log files, so it could be a Rails issue if Rails is missing a lock somewhere. If I understand it correctly, Ruby 1.9.x uses native threads and acquires a global lock when executing normal Ruby code, but then releases it inside IO calls. This would imply to me that two Ruby threads simultaneously accessing the same IO object could cause Ruby to crash.

It is easy to reproduce the problem. Install a clean 1.9.2p0 and Rails 3.0. Use the Rails 3.0 generator script to create an empty project, launch it using default options, point a browser to the home page for the new Rails app, and keep pressing F5 (or Refresh) until Ruby crashes. It crashes eventually no matter how I run it, but it seems to crash more often in production mode (which logs a bunch of routing errors, possibly due to a bug in the app generator script). Sometimes it will crash when I hold down the F5 key, but sometimes I have to hold and release it intermittently for a minute or two. It appears to be very dependent on timing, but I can usually make it crash in less than 60 seconds.

I'm currently using Windows 7 (x64) and Visual Studio 2008. The crash also occurs with the pre-packaged RubyInstaller for Windows. Given the debug information I've provided below, it does not appear to be OS-specific, but a different OS can have different timing and/or threading issues, so it may be specific to Windows.

I rebuilt Ruby with debugging options and got this call stack when it crashed:
rb_econv_convert() in transcode.c line 1449 (the ec parameter was set to NULL)
fill_cbuf() in io.c line 1691
read_all() in io.c line 1755
io_read() in io.c line 2163

I added some additional checks to the code to find out how fptr->readconv was getting cleared inside fill_cbuf(), and I traced it to io_fillbuf() and then rb_read_internal(). Now, rb_read_internal() does not have a pointer to fptr or any of its members. It could be a buffer overrun, but the buffer is much larger than the file, and the changes seem much too clean for that. In addition to readconv being cleared, other struct members are being reset to an earlier state (not necessarily back to 0), which seems to imply that another thread is accessing the same IO object while the current thread is inside rb_read_internal(). I can't "catch it in the act" because setting breakpoints affects the timing, and it typically requires hundreds of passes through this code to break. However, I can copy the struct fptr is pointing to and have it break as soon as it changes. The info being read right before the IO object gets reset is:

  • rbuf    0x05700408 "
    Started GET "/javascripts/dragdrop.js?1283353508" for 127.0.0.1 at 2010-09-08 16:22:14 -0400

ActionController::RoutingError (No route matches "/javascripts/dragdrop.js"):

Rendered d:/Projects/NetAuditor/v3.00/Code/Build/lib/ruby/gems/1.9.1/gems/actionpack-3.0.0/lib/action_dispatch/middleware/templates/rescues/routing_error.erb within rescues/layout (2.0ms)

"

I can stop this crash by changing the Ruby source to check for NULL before referencing the pointer. However, if there is still a threading issue, it may come back to bite me in production. Any ideas?

Reported by sponeil · September 9th, 2010 @ 02:44 PM

State: invalid
Milestone: none
Assigned to: Yehuda Katz (wycats) Yehuda Katz (wycats)
Importance: High

Activity

  1. Rohit Arondekar
    Rohit Arondekar
    • State changed from new to open
    • Assigned user set to Yehuda Katz (wycats)
    • Importance changed from to High

    I wasn't able to reproduce this yet but can you post the output of the crash?

    September 12th, 2010 @ 05:02 AM

  2. sponeil
    sponeil

    There was no output other than what I just posted. I was using the default web server (WEBrick) in Windows, and with serve_static_assets defaulted to false in production mode, it was generating routing errors trying to find the CSS and JS files under the public folder. When I hit refresh too fast, it also generated connection reset errors. After a time, Windows popped up its standard GPF message box with no other output. I couldn't get any other information out of it without running ruby.exe in the debugger so I could get a stack trace and try to figure out where it was crashing. The crash was much easier to reproduce in debug mode.

    When trying to reproduce it, I find I can get it to happen faster by holding F5 for a random period of time (1-5 seconds), releasing it for a second or two, and repeating the random hold. Try to vary how long you hold it down and release it to get different timing conditions. The speed and number of cores of the processor you're using may affect how hard it is to reproduce (mine is dual-core). If you're not, it may be much harder for you to reproduce it.

    If there's something specific you want me to look for, let me know. If not, I may be able to arrange a time to show you it happening on my system (via a WebEx meeting).

    September 12th, 2010 @ 01:32 PM

  3. habermann24
    habermann24

    +1 here!!

    I'm experiencing the same issue. So far only on Windows...i will try if i can reproduce it on a UNIX-based machine. It only happens for me if I have e.g. Javascript or CSS resources that can't be found.

    If it only happens on windows, i guess it might be a ruby problem concerning threading or something?

    September 13th, 2010 @ 07:05 PM

  4. gnufied
    gnufied
    • Tag set to windows 1.9.2

    Can't reproduce on *nix. Very likely windows specific. You may have to post this to ruby-core.

    September 22nd, 2010 @ 04:11 PM

  5. sponeil
    sponeil

    I have already posted it to ruby-core. Thanks.

    September 22nd, 2010 @ 05:48 PM

  6. David Trasbo
    David Trasbo
    • State changed from open to invalid

    Marking as invalid for now. Will re-open if it turns out to be a non-Ruby issue.

    September 23rd, 2010 @ 08:04 AM

  7. jtw
    jtw

    Just wanted to say that I installed ruby 1.9.2p0 and rails 3.0.3 via the rubyinstaller on my windows xp box. Ruby.exe started crashing on almost every page load. Then I came across this page and got the hint that something about having unloadable assets is causing this. I noticed in the webrick output that it couldn't find an image. As soon as I fixed that the crashing stopped.

    November 25th, 2010 @ 09:51 PM

  8. Jason Thomas
    Jason Thomas

    I'm having the same issue with Rails 3.0.3 on Windows using Ruby 1.9.2p0. My site will randomly crash when refreshing the main page. Debugging with Visual Studio shows the following:

    Unhandled exception at 0x62e1a822 in ruby.exe: 0xC0000005: Access violation writing location 0x0000000c.

    I then break into the disassembly which doesn't really help me. Here is the disassembly in case it is meaningful to anyone:

    62E1A809 jmp 62E1A692
    62E1A80E xchg ax,ax
    62E1A810 push ebp
    62E1A811 mov ebp,esp
    62E1A813 push edi
    62E1A814 push esi
    62E1A815 push ebx
    62E1A816 sub esp,4Ch
    62E1A819 mov ebx,dword ptr [ebp+8]
    62E1A81C lea eax,[ebp-19h]
    62E1A81F mov dword ptr [ebp-20h],eax
    -> 62E1A822 mov dword ptr [ebx+0Ch],1 This is the failure line 62E1A829 mov ecx,dword ptr [ebp+0Ch]
    62E1A82C test ecx,ecx
    62E1A82E je 62E1ACE8
    62E1A834 mov edx,dword ptr [ebp+14h]
    62E1A837 test edx,edx
    62E1A839 je 62E1ACD8

    December 15th, 2010 @ 06:19 PM

  9. Jason Thomas
    Jason Thomas

    When running my application in production mode: rails server -e production I have observed the following on rapid refreshes of the application but it does NOT crash:

    Started GET "/packets/list.xml" for 162.18.166.125 at 2010-12-15 11:17:57 -0700
    Processing by PacketsController#list as XML Rendered packets/list.xml.builder (0.0ms)
    Completed 200 OK in 0ms (Views: 0.0ms)
    [2010-12-15 11:17:57] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `write'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `<<'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `_write_data'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:295:in `send_body_string'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:186:in `send_body'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:103:in `send_response'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:86:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    [2010-12-15 11:17:57] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:56:in `eof?'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:56:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    [2010-12-15 11:17:57] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `write'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `<<'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `_write_data'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:295:in `send_body_string'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:186:in `send_body'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:103:in `send_response'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:86:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    [2010-12-15 11:17:57] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:56:in `eof?'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:56:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    [2010-12-15 11:17:57] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `write'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `<<'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `_write_data'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:295:in `send_body_string'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:186:in `send_body'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:103:in `send_response'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:86:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    [2010-12-15 11:17:57] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `write'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `<<'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:323:in `_write_data'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:295:in `send_body_string'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:186:in `send_body'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpresponse.rb:103:in `send_response'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:86:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    Started GET "/packets/list.xml" for 162.18.166.125 at 2010-12-15 11:19:09 -0700
    Processing by PacketsController#list as XML Rendered packets/list.xml.builder (15.6ms)
    Completed 200 OK in 16ms (Views: 15.6ms)
    [2010-12-15 11:19:09] ERROR Errno::ECONNABORTED: An established connection was aborted by the software in your host machine.

        C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:56:in `eof?'
    C:/Ruby192/lib/ruby/1.9.1/webrick/httpserver.rb:56:in `run'
    C:/Ruby192/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

    December 15th, 2010 @ 06:23 PM

  10. Peter Moberg
    Peter Moberg

    I can confirm this issue on Windows 7, Rails 3.0.3 and Ruby 1.9.2p136.

    In my application.html.erb i had a reference to a .css file that did not exist in the stylesheets directory

    <%= stylesheet_link_tag 'custom', :media => 'screen' %>

    When I browsed to http://localhost:3000/, WEBrick outputed:


    Started GET "/stylesheet/custom.css" for 127.0.0.1 at 2011-01-05 18:53:44 +0100

    ActionController::RoutingError (No route matches "/stylesheet/custom.css"):

    And after 2-3 requests Ruby crashed. If i remove the reference to the missing stylesheet, the application works fine.

    I also tried crashing the application by requesting http://localhost:3000/stylesheet/custom.css and http://localhost:3000/ in different browser windows a few times (with the reference to the stylesheet removed from application.html.erb), but this did not crash the site. So it seems like some timing issue.

    January 5th, 2011 @ 06:15 PM

  11. Zaknafein88
    Zaknafein88

    I found this on google, and wanted to share with others in the same circumstance.

    In the ruby-core thread for this problem, it was stated that this had something to do with the Rails log file. As a temporary workaround, I added to development.rb the following line:

    config.log_level = :fatal

    Experimentially I've found that log levels of :debug and :info allow the bug to be triggered, but all other log levels do not. For me the annoyance is serious enough that I'm willing to switch back and forth between log levels.

    March 9th, 2011 @ 02:29 AM

  12. iviney
    iviney

    I have been having this problem too, on Windows XP, Rails 3.0.5 and Ruby 1.9.2-p180: Ruby crashes and exits with error code -1073741819. The crash is 'An unhandled win32 exception occurred in ruby.exe [ 7952 ]'. The Visual Studio debugger then says, 'Unhandled exception at 0x62e1a00e in ruby.exe: 0xC0000005: Access violation writing location 0x0000000c.'

    In my case I didn't have a missing resource file, but the problem occurred after the log said:

    Started GET "/states.js" for 127.0.0.1 at 2011-04-18 20:14:40 +1200

    This was issued as a result of the following Rails code (this is in the Spree code base):

    <%= javascript_include_tag  'checkout', '/states' %>

    The javascript response is (usually) generated by the default action of the states controller. The crashes stopped when I changed the logging level in config/environments/development.rb:

    config.log_level = :warn

    (Thanks, Zaknafein88!) A proper fix would be nice. :-)

    April 18th, 2011 @ 09:34 AM