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 4BF4819C0421 for ; Fri, 27 Nov 2015 17:51:36 +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 26EADB5D8BD for ; Fri, 27 Nov 2015 18:22:46 +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 B9EBA18CC7E9 for ; Fri, 27 Nov 2015 18:22:46 +0900 (JST) Received: from [221.186.184.76] (localhost [IPv6:::1]) by neon.ruby-lang.org (Postfix) with ESMTP id 84B8B12052A; Fri, 27 Nov 2015 18:22:44 +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 DB1F61204E2 for ; Fri, 27 Nov 2015 18:22:40 +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=T8kI3+nbSCKqxCfg+JEPhUAZeSU=; b=hi4nkGgG/UoAk79WS3 NEqmwMho/MOFq/syiShvSxXDwQ4y/7grs+Tlxj0GrOGc5uW9ITry3WD21p4xIY9f PrFqAlF9LTZlMiovwDAQJW3Ihs9wVczADketqD8wdE4+kvFBwQAT6ivbnNjo+cBS UWeklGktlnf0wssCc+kZ24RAU= Received: by filter0836p1mdw1.sendgrid.net with SMTP id filter0836p1mdw1.7321.565820DC52 2015-11-27 09:22:36.709602032 +0000 UTC Received: from herokuapp.com (ec2-54-145-145-72.compute-1.amazonaws.com [54.145.145.72]) by ismtpd0005p1iad1.sendgrid.net (SG) with ESMTP id OvsO9g5zTHm5DvmOdRPgIw for ; Fri, 27 Nov 2015 09:22:36.757 +0000 (UTC) Date: Fri, 27 Nov 2015 09:22: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: 46384 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/Ymy4QrNMhiuLXJG8OTL2vJD1yS4A0mLShzlZnDER8/fS64qAaSYbe4HB4HeVhr 88fQpa4cEkdhqy9QWfktUGGOp/9dGt7xWjSbb9zVFGvVlqVabECk7RJA33N+zKBR9w70DjnHpQ6oAl mYBEaH1I96ENK2jT9xcIopinNR7tIx7psIuU X-ML-Name: ruby-core X-Mail-Count: 71703 Subject: [ruby-core:71703] [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. > We have found the issue Looks like I spoke too soon! The issue is back with listen 3.0.5. > In my experience, such false closing is caused by IO.for_fd without specifying autoclose: false. I don't *think* that's the case here, but I could be completely wrong. In the [simplified reproduction script](https://github.com/rails/rails/blob/9982d60b34b976a826358644d1157d2589b92e94/activesupport/test/file_evented_update_checker_test.rb#L4-L39), all we are doing is this: ``` Dir.glob("**/*") do |entry| if File.file?(entry) && !File.zero?(entry) File.open(entry, 'r') { |f| puts f.read(10).inspect } end end ``` As you can see, the GC happened in between `puts f.read(10).inspect` finished executing and the implicit `f.close` internal to `File.open`, and we don't call `IO.for_fd` here. ---------------------------------------- Bug #11744: Open files being GC'ed while still in use https://bugs.ruby-lang.org/issues/11744#change-55109 * 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/