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 B7EFB19C0421 for ; Fri, 27 Nov 2015 14:15:14 +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 70249B5D91A for ; Fri, 27 Nov 2015 14:46:24 +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 E791E18CC7E6 for ; Fri, 27 Nov 2015 14:46:24 +0900 (JST) Received: from [221.186.184.76] (localhost [IPv6:::1]) by neon.ruby-lang.org (Postfix) with ESMTP id 229CD120529; Fri, 27 Nov 2015 14:46:22 +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 5A9ED12049E for ; Fri, 27 Nov 2015 14:46:18 +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=7y0LkqC8UdHJ6LuQ/HSahkT+oow=; b=mgUe25moJvzYf73bA1 Hwht9p2J+CLIoV1SrwYdKSvu2ZmLL6uijqjHjJXEExUBAz7dPOJt6W3gViOHAgyW ksfFZ0Erf7c6JoLWu7ed9kTmwuvTfvLHI+AX3PYKgXec3qPTQWmlxeBqy1f+3TjV AdjR0O28uQdzGVFOUdTq718w8= Received: by filter0910p1mdw1.sendgrid.net with SMTP id filter0910p1mdw1.7950.5657EE267 2015-11-27 05:46:14.302164605 +0000 UTC Received: from herokuapp.com (ec2-54-157-216-50.compute-1.amazonaws.com [54.157.216.50]) by ismtpd0003p1iad1.sendgrid.net (SG) with ESMTP id sht7Pkv9QiKb8JN4TDZMUg for ; Fri, 27 Nov 2015 05:46:14.248 +0000 (UTC) Date: Fri, 27 Nov 2015 05:46:14 +0000 From: naruse@airemix.jp 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: 46382 X-Redmine-Project: ruby-trunk X-Redmine-Issue-Id: 11744 X-Redmine-Issue-Author: chancancode X-Redmine-Sender: naruse 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/Ymy4QrNMhiuLXJG8OTL2vJD1yS5pU5b81a0NNCfmD+iUFEr7HuUeQkfCMT6rp1 vVoOXTVQ7DvdaTtbCE1b1hL+V4CkE/LuEdO/9aM5xqpNB3euqCnf5bSok2x1fXKenk/8Xbw1RCjQnB ZZVcEJihDMVdem8= X-ML-Name: ruby-core X-Mail-Count: 71701 Subject: [ruby-core:71701] [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 Yui NARUSE. In my experience, such false closing is caused by IO.for_fd without specifying autoclose: false. You know Ruby's IO object automatically closes their fd on finalize. It happens even when the object is created by IO.for_fd(fd) (or IO.new(fd) or other aliases), of course the original user of the fd hit EBADF. You can avoid this by specifying autoclose: false for IO.for_fd. ---------------------------------------- Bug #11744: Open files being GC'ed while still in use https://bugs.ruby-lang.org/issues/11744#change-55107 * 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/