From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Original-To: poffice@blade.nagaokaut.ac.jp Delivered-To: poffice@blade.nagaokaut.ac.jp Received: from kankan.nagaokaut.ac.jp (kankan.nagaokaut.ac.jp [133.44.2.24]) by blade.nagaokaut.ac.jp (Postfix) with ESMTP id 119F719C0421 for ; Sat, 28 Nov 2015 01:04:46 +0900 (JST) Received: from voscc.nagaokaut.ac.jp (voscc.nagaokaut.ac.jp [133.44.1.100]) by kankan.nagaokaut.ac.jp (Postfix) with ESMTP id 2127BB5D8BD for ; Sat, 28 Nov 2015 01:35:58 +0900 (JST) Received: from neon.ruby-lang.org (neon.ruby-lang.org [221.186.184.75]) by voscc.nagaokaut.ac.jp (Postfix) with ESMTP id 0E5B118CC7B5 for ; Sat, 28 Nov 2015 01:35:57 +0900 (JST) Received: from [221.186.184.76] (localhost [IPv6:::1]) by neon.ruby-lang.org (Postfix) with ESMTP id 8E337120577; Sat, 28 Nov 2015 01:35:54 +0900 (JST) X-Original-To: ruby-core@ruby-lang.org Delivered-To: ruby-core@ruby-lang.org Received: from o2.heroku.sendgrid.net (o2.heroku.sendgrid.net [67.228.50.55]) by neon.ruby-lang.org (Postfix) with ESMTPS id E687A120566 for ; Sat, 28 Nov 2015 01:35:49 +0900 (JST) DKIM-Signature: v=1; a=rsa-sha1; c=relaxed; d=sendgrid.me; h=from:to:references:subject:mime-version:content-type:content-transfer-encoding:list-id; s=smtpapi; bh=DK3GQs7IqhoRZINZgqyiWZ3oHU4=; b=DlPxpc5ubhj8TqiLP0 +dSqCFy4k5JOkSLkYruTyIYiqIYAX6R6gbLerzvnVTXXaySPiKV1Ptf6joE3ueDg YDkYuuKUXqNb5f24itQtmjoh7QpthAkqRaMfwFWro5N8AR7v42D16vlUuea2/MPN s2DkbuaNAwOdaEyKJeQd5PeDU= Received: by filter0886p1mdw1.sendgrid.net with SMTP id filter0886p1mdw1.20265.565886584E 2015-11-27 16:35:36.843802471 +0000 UTC Received: from herokuapp.com (ec2-54-161-250-253.compute-1.amazonaws.com [54.161.250.253]) by ismtpd0001p1iad1.sendgrid.net (SG) with ESMTP id aCsxQf2KRhitufQS4sVQOQ for ; Fri, 27 Nov 2015 16:35:36.716 +0000 (UTC) Date: Fri, 27 Nov 2015 16:35:36 +0000 From: godfreykfc@gmail.com To: ruby-core@ruby-lang.org Message-ID: References: Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit X-Redmine-MailingListIntegration-Message-Ids: 46388 X-Redmine-Project: ruby-trunk X-Redmine-Issue-Id: 11744 X-Redmine-Issue-Author: chancancode X-Redmine-Sender: chancancode X-Mailer: Redmine X-Redmine-Host: bugs.ruby-lang.org X-Redmine-Site: Ruby Issue Tracking System X-Auto-Response-Suppress: All Auto-Submitted: auto-generated X-SG-EID: ync6xU2WACa70kv/Ymy4QrNMhiuLXJG8OTL2vJD1yS4Rah+G97/4sQadXW9EpG8ajVk2qkwZ3yD23h JzU/AiocDoq4whSC02ALA7X+VpkgFXt1BCgIK3ZCaDIib4+6d7d3UMRMAOIBQoTZNOU7fMiNRX4WXD yg7UO/4OOfv4fljYOI2Ho4LWfcPo0cTDlIgm X-SendGrid-Contentd-ID: {"test_id":"1448642141"} X-ML-Name: ruby-core X-Mail-Count: 71707 Subject: [ruby-core:71707] [Ruby trunk - Bug #11744] Open files being GC'ed while still in use X-BeenThere: ruby-core@ruby-lang.org X-Mailman-Version: 2.1.15 Precedence: list Reply-To: Ruby developers List-Id: Ruby developers List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Errors-To: ruby-core-bounces@ruby-lang.org Sender: "ruby-core" Issue #11744 has been updated by Godfrey Chan. Actually, @nurse you are right! It turns out that rb-inotify uses `IO.fd_for` in its code. At some point, the system starts recycling FD numbers, so we got the same FD number on our file as the rb-inotify object waiting to be GC'ed. When the GC hit at that moment, the finalizer would have auto-closed the "wrong" file. So this can be closed. Thank you very much for helping us! We will send a patch to rb-inotify! ---------------------------------------- Bug #11744: Open files being GC'ed while still in use https://bugs.ruby-lang.org/issues/11744#change-55112 * Author: Godfrey Chan * Status: Open * Priority: Normal * Assignee: * ruby -v: 2.2.3 * Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN ---------------------------------------- Hello! We recently added a feature on Rails that uses the [`listen` gem](https://github.com/guard/listen) under-the-hood. Since we enabled those tests, we have been seeing random failures on Travis CI like [these](https://travis-ci.org/rails/rails/jobs/92563035#L976): ``` 1) Error: KeyGeneratorTest#test_Generating_a_key_of_an_alternative_length: Errno::EBADF: Bad file descriptor @ fptr_finalize - /home/travis/build/rails/rails/activesupport/lib/active_support/key_generator.rb /home/travis/build/rails/rails/activesupport/test/key_generator_test.rb:16:in `setup' ``` What's happening here is that the [setup code](https://github.com/rails/rails/blob/master/activesupport/test/key_generator_test.rb#L16) for this test is referencing an [constant previously marked for autoload](https://github.com/rails/rails/blob/master/activesupport/lib/active_support.rb#L52), and something went wrong *during* autoload (inside Ruby). (By the way, I was referring to [Ruby's `autoload` feature](http://ruby-doc.org/core-2.2.3/Module.html#method-i-autoload) which is not specific to Rails, although we did [enhance it to infer the filename](https://github.com/rails/rails/blob/e1e6499ede1dd196c03f650b95c3a0098c7c32ff/activesupport/lib/active_support/dependencies/autoload.rb).) Because there are so many things going on in the test suite, I tried to narrow down the problem further by removing most of the work we do. Eventually, I arrived at this [reproduction script](https://github.com/rails/rails/blob/9982d60b34b976a826358644d1157d2589b92e94/activesupport/test/file_evented_update_checker_test.rb#L4-L39). I disabled the rest of the test suite so that this file is the only test being ran, in three different configurations: ``` (1) LISTEN=1 LISTEN_GC_FIX=1 bundle exec rake test (2) LISTEN=1 bundle exec rake test (3) LISTEN=0 bundle exec rake test ``` In each of the tests, we tried to do a very simple `File.open(..., 'r') { |f| ... }` (reading in the first 10 bytes to make sure we are dealing with the correct file) up to 5000 times. In (1), we set up 20 listeners, do no work, and properly tear down each of them, and disabling the GC before opening the files. In (2), we also setup the listeners but do not disable the GC. In (3), we do not set up the listeners nor disable the GC. Scenario (2) reliably fails on Travis CI, and the rest reliably passes: https://travis-ci.org/rails/rails/builds/93402196 ``` /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:31:in `close': Bad file descriptor @ fptr_finalize - vendor/bundle/ruby/2.2.0/cache/bundler/git/mail-c03100656df0e86c13a2d6103ac408da7a4e728c/objects/34/fdd44ee4de34a2f05b0088562e38797db604a8 (Errno::EBADF) from /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:31:in `open' from /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:31:in `block (2 levels) in ' from /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:26:in `glob' from /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:26:in `block in ' from /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:23:in `chdir' from /home/travis/build/rails/rails/activesupport/test/file_evented_update_checker_test.rb:23:in `' from /home/travis/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/rake/rake_test_loader.rb:10:in `require' from /home/travis/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/rake/rake_test_loader.rb:10:in `block (2 levels) in
' from /home/travis/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/rake/rake_test_loader.rb:9:in `each' from /home/travis/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/rake/rake_test_loader.rb:9:in `block in
' from /home/travis/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/rake/rake_test_loader.rb:4:in `select' from /home/travis/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/rake/rake_test_loader.rb:4:in `
' ``` Note that we are using the "block form" `File.open` in the test here, and [the error](https://travis-ci.org/rails/rails/jobs/93402198#L4418) is happening during the implicit `close` call inside Ruby. Also note that we are *loading* the listen gem in all three cases, so merely having it loaded does not trigger the issue. I was not able to reproduce this locally on a Mac, so this is probably Linux specific. From what I can tell, listen gem uses [rb-inotify](https://github.com/nex3/rb-inotify) (which in turns uses ffi) on Linux so that might be related too. * * * My hypothesis is that, so interaction between listen/rb-inotify/ffi during the listener setup/teardown phase is putting the Ruby VM/process into a bad state. In this state, somehow the VM is confused about what is being used. When the GC runs, it somehow thinks that the file we are currently reading (the `f` inside the `File.open(...) { |f| ... }` call) is no longer being used, causing it to be GC-ed and auto-closed. When the block finishes running (it did indeed open the file correctly, as it was able to read the first 10 bytes correctly), the [finalizer](https://github.com/ruby/ruby/blob/v2_2_3/io.c#L6387) code tries to close FD again, causing the OS to return a `EBADF` error. While it is certainly possible that the listen/rb-inotify/ffi gems are doing something wrong, it seems quite strange that they could put the Ruby process in such a state, so I figured it is worth having Ruby core people look into this. I tried to [reproduce this outside of Rails](https://github.com/chancancode/listen-bug) but so far I cannot make it work, I'll keep trying. (Feel free to fork it.) -- https://bugs.ruby-lang.org/