事象

ensure 節を使って Net::FTP#close しても、コネクションが残ってしまう事象に遭遇。

$ ruby -v
ruby 2.6.5p114 (2019-10-01 revision 67812) [x86_64-darwin18]

原因

Net::FTP#put で確立するデータコネクションが #write などで例外が発生した時に切断されていない模様。

# https://github.com/ruby/ruby/blob/00f4c13e22967de1d7e42085b2fc32bf6718f580/lib/net/ftp.rb#L683-L707
    def storbinary(cmd, file, blocksize, rest_offset = nil) # :yield: data
      if rest_offset
        file.seek(rest_offset, IO::SEEK_SET)
      end
      synchronize do
        with_binary(true) do
          conn = transfercmd(cmd)
          loop do
            buf = file.read(blocksize)
            break if buf == nil
            conn.write(buf)
            yield(buf) if block_given?
          end
          conn.close
          voidresp
        end
      end
    rescue Errno::EPIPE
      # EPIPE, in this case, means that the data connection was unexpectedly
      # terminated.  Rather than just raising EPIPE to the caller, check the
      # response on the control connection.  If getresp doesn't raise a more
      # appropriate exception, re-raise the original exception.
      getresp
      raise
    end

再現

適当な FTP サーバーを動かして確認。

$ docker run --rm \
  -p 20-21:20-21 \
  -p 21100-21110:21100-21110 \
  -e FTP_USER=user \
  -e FTP_PASS=pass \
  -e PASV_ADDRESS=localhost \
  -e PASV_MIN_PORT=21100 \
  -e PASV_MAX_PORT=21110 \
  fauria/vsftpd

再現スクリプト

require 'net/ftp'

def upload
  ftp = Net::FTP.new
  ftp.read_timeout = 0.1
  ftp.passive = true
  ftp.connect('localhost')
  ftp.login('user', 'pass')

  i = 0
  ftp.put(__FILE__, '/uploaded', 1) do |data|
    i += 1
    raise 'Bomb' if i > 3
  end
rescue => e
  puts e.message
ensure
  unless ftp.closed?
    ftp.close
    puts 'closed.'
  end
end

11.times { upload }

puts 'wait'
loop {}

$ ruby test.rb
Bomb
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
Net::ReadTimeout with #<Socket:fd 11>
closed.
wait

コネクション

$ lsof -i:21100-21110

Before

COMMAND    PID     USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
com.docke 1354 koshigoe   17u  IPv6 0x370c9672434eb1d5      0t0  TCP *:21110 (LISTEN)
com.docke 1354 koshigoe   19u  IPv6 0x370c9672434eac15      0t0  TCP *:21109 (LISTEN)
com.docke 1354 koshigoe   21u  IPv6 0x370c9672434e9ad5      0t0  TCP *:21108 (LISTEN)
com.docke 1354 koshigoe   23u  IPv6 0x370c967241a28e15      0t0  TCP *:21107 (LISTEN)
com.docke 1354 koshigoe   25u  IPv6 0x370c967241a2aad5      0t0  TCP *:21106 (LISTEN)
com.docke 1354 koshigoe   29u  IPv6 0x370c967241a29f55      0t0  TCP *:21105 (LISTEN)
com.docke 1354 koshigoe   31u  IPv6 0x370c9672557d9c15      0t0  TCP *:21104 (LISTEN)
com.docke 1354 koshigoe   33u  IPv6 0x370c9672557d9655      0t0  TCP *:21103 (LISTEN)
com.docke 1354 koshigoe   35u  IPv6 0x370c9672557d7f55      0t0  TCP *:21102 (LISTEN)
com.docke 1354 koshigoe   37u  IPv6 0x370c9672385aae15      0t0  TCP *:21101 (LISTEN)
com.docke 1354 koshigoe   39u  IPv6 0x370c9672385ae1d5      0t0  TCP *:21100 (LISTEN)

After

COMMAND     PID     USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
com.docke  1354 koshigoe   17u  IPv6 0x370c9672434eb1d5      0t0  TCP *:21110 (LISTEN)
com.docke  1354 koshigoe   19u  IPv6 0x370c9672434eac15      0t0  TCP *:21109 (LISTEN)
com.docke  1354 koshigoe   21u  IPv6 0x370c9672434e9ad5      0t0  TCP *:21108 (LISTEN)
com.docke  1354 koshigoe   23u  IPv6 0x370c967241a28e15      0t0  TCP *:21107 (LISTEN)
com.docke  1354 koshigoe   25u  IPv6 0x370c967241a2aad5      0t0  TCP *:21106 (LISTEN)
com.docke  1354 koshigoe   29u  IPv6 0x370c967241a29f55      0t0  TCP *:21105 (LISTEN)
com.docke  1354 koshigoe   31u  IPv6 0x370c9672557d9c15      0t0  TCP *:21104 (LISTEN)
com.docke  1354 koshigoe   33u  IPv6 0x370c9672557d9655      0t0  TCP *:21103 (LISTEN)
com.docke  1354 koshigoe   35u  IPv6 0x370c9672557d7f55      0t0  TCP *:21102 (LISTEN)
com.docke  1354 koshigoe   37u  IPv6 0x370c9672385aae15      0t0  TCP *:21101 (LISTEN)
com.docke  1354 koshigoe   39u  IPv6 0x370c9672385ae1d5      0t0  TCP *:21100 (LISTEN)
com.docke  1354 koshigoe   45u  IPv6 0x370c9672557d6e15      0t0  TCP localhost:21104->localhost:64487 (ESTABLISHED)
com.docke  1354 koshigoe   47u  IPv6 0x370c9672385adc15      0t0  TCP localhost:21106->localhost:64489 (ESTABLISHED)
com.docke  1354 koshigoe   49u  IPv6 0x370c9672434ea095      0t0  TCP localhost:21103->localhost:64491 (ESTABLISHED)
com.docke  1354 koshigoe   51u  IPv6 0x370c967253fc5095      0t0  TCP localhost:21100->localhost:64493 (ESTABLISHED)
com.docke  1354 koshigoe   53u  IPv6 0x370c9672589ebc15      0t0  TCP localhost:21105->localhost:64495 (ESTABLISHED)
com.docke  1354 koshigoe   55u  IPv6 0x370c9672589eb655      0t0  TCP localhost:21110->localhost:64497 (ESTABLISHED)
com.docke  1354 koshigoe   57u  IPv6 0x370c967257775c15      0t0  TCP localhost:21107->localhost:64499 (ESTABLISHED)
com.docke  1354 koshigoe   59u  IPv6 0x370c9672557d73d5      0t0  TCP localhost:21108->localhost:64501 (ESTABLISHED)
com.docke  1354 koshigoe   61u  IPv6 0x370c9672591fd515      0t0  TCP localhost:21101->localhost:64503 (ESTABLISHED)
com.docke  1354 koshigoe   63u  IPv6 0x370c9672591ff1d5      0t0  TCP localhost:21109->localhost:64505 (ESTABLISHED)
com.docke  1354 koshigoe   65u  IPv6 0x370c9672592dd515      0t0  TCP localhost:21102->localhost:64507 (ESTABLISHED)
ruby      59669 koshigoe   14u  IPv6 0x370c9672557d9095      0t0  TCP localhost:64487->localhost:21104 (ESTABLISHED)
ruby      59669 koshigoe   15u  IPv6 0x370c9672557d6855      0t0  TCP localhost:64489->localhost:21106 (ESTABLISHED)
ruby      59669 koshigoe   16u  IPv6 0x370c9672434ea655      0t0  TCP localhost:64491->localhost:21103 (ESTABLISHED)
ruby      59669 koshigoe   17u  IPv6 0x370c967253fc4515      0t0  TCP localhost:64493->localhost:21100 (ESTABLISHED)
ruby      59669 koshigoe   18u  IPv6 0x370c9672589eaad5      0t0  TCP localhost:64495->localhost:21105 (ESTABLISHED)
ruby      59669 koshigoe   19u  IPv6 0x370c9672589e9995      0t0  TCP localhost:64497->localhost:21110 (ESTABLISHED)
ruby      59669 koshigoe   20u  IPv6 0x370c9672589ec1d5      0t0  TCP localhost:64499->localhost:21107 (ESTABLISHED)
ruby      59669 koshigoe   21u  IPv6 0x370c967241a2a515      0t0  TCP localhost:64501->localhost:21108 (ESTABLISHED)
ruby      59669 koshigoe   22u  IPv6 0x370c9672591fdad5      0t0  TCP localhost:64503->localhost:21101 (ESTABLISHED)
ruby      59669 koshigoe   23u  IPv6 0x370c9672591fec15      0t0  TCP localhost:64505->localhost:21109 (ESTABLISHED)
ruby      59669 koshigoe   24u  IPv6 0x370c9672591fb855      0t0  TCP localhost:64507->localhost:21102 (ESTABLISHED)

FTP サーバー(vsftpd)のプロセス

$ ps aux | grep '[v]sftpd'

Before

root         1  0.0  0.0  11700  2660 ?        Ss   11:40   0:00 /bin/bash /usr/sbin/run-vsftpd.sh
root        13  0.0  0.1  53292  3860 ?        S    11:40   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf

After

root         1  0.0  0.0  11700  2660 ?        Ss   11:40   0:00 /bin/bash /usr/sbin/run-vsftpd.sh
root        13  0.0  0.1  53292  3996 ?        S    11:40   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      58  0.0  0.1  75748  4628 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         60  0.0  0.1  75848  3860 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      61  0.0  0.1  75748  4628 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         63  0.0  0.1  75772  3860 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      64  0.0  0.1  75748  4628 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         66  0.0  0.1  75772  3860 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      69  0.0  0.1  75748  4628 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         71  0.0  0.1  75772  3860 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      72  0.0  0.1  75748  4628 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         74  0.0  0.1  75772  3860 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      75  0.0  0.1  75748  4628 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         77  0.0  0.1  75772  3860 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      78  0.0  0.1  75748  4632 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         80  0.0  0.1  75772  3864 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      81  0.0  0.1  75748  4632 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         83  0.0  0.1  75772  3864 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      84  0.0  0.1  75748  4632 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         86  0.0  0.1  75772  3864 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      87  0.0  0.1  75748  4632 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         89  0.0  0.1  75772  3864 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
nobody      90  0.0  0.1  75748  4632 ?        Ss   11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf
ftp         92  0.0  0.1  75772  3864 ?        S    11:43   0:00 /usr/sbin/vsftpd /etc/vsftpd/vsftpd.conf

対策

報告(相談)場所に迷った結果、Ruby Issue Tracking System に駆け込んでしまった。