Bug #13141: Spurious Net::FTPReplyError

• Status: Third Party's Issue
• Assignee: shugo (Shugo Maeda)
• Target version: -
• ruby -v: ruby 2.2.6p396 (2016-11-15 revision 56800) [x64-mingw32]
• Backport: 2.2: UNKNOWN, 2.3: UNKNOWN, 2.4: UNKNOWN

[Phrogz (Gavin Kistner)]

I have a script that downloads many files via FTP. ftp.getbinaryfile occasionally fails (about 7 times while downloading ~2000 files).

Here's the code:

Net::FTP.open(SITE) do |ftp|
  ftp.login USER, PASS
  ftp.passive = true
  dates_by_year.each do |year,dates|
    ftp.chdir(File.join(DIR,'_archive',year.to_s))
    regex = /\.#{Regexp.union *dates.map(&mashed_date)}/
    ftp.list.map(&FILENAMEFROMLIST).compact.grep(regex).sort.map do |file|
      unzipped = calculate_uncompressed(file)
      unless File.exists?(unzipped)
        $log.debug "...downloading archived #{file}"
        ftp.getbinaryfile(file)
        $log.debug "...unzipping local #{file}"
        `gzip.exe -d #{file}`
        $log.debug "...unzipped #{file}"
      end
    end
  end
end

Here's an excerpt from the logs when it fails (where line 166 is the getbinaryfile call above):

D, [2017-01-19T16:08:48.307731 #1828] DEBUG -- : ...downloading archived developerdownloads_26549.esw3cdc_S.201611041500-1800-98.gz
D, [2017-01-19T16:08:49.350458 #1828] DEBUG -- : ...unzipping local developerdownloads_26549.esw3cdc_S.201611041500-1800-98.gz
D, [2017-01-19T16:08:49.412917 #1828] DEBUG -- : ...unzipped developerdownloads_26549.esw3cdc_S.201611041500-1800-98.gz
D, [2017-01-19T16:08:49.412917 #1828] DEBUG -- : ...downloading archived developerdownloads_26549.esw3cdc_S.201611041500-1800-99.gz
C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:979:in `parse227': 226 Transfer complete. 0 bytes transferred. 0 bps. (Net::FTPReplyError)
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:392:in `makepasv'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:404:in `transfercmd'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:489:in `block (2 levels) in retrbinary'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:199:in `with_binary'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:487:in `block in retrbinary'
	from C:/Ruby/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:486:in `retrbinary'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:619:in `getbinaryfile'
	from E:/dashstats_importer/import_from_ftp.rb:166:in `block (3 levels) in download_archives'

Every time it fails is the exact same error message: ftp.rb:977:in 'parse227': 226 Transfer complete. 0 bytes transferred. 0 bps. (Net::FTPReplyError).

When I run the script again the download succeeds, and eventually fails on a different file. It is not a problem with the specific files.

This is on ruby 2.2.6p396 (2016-11-15 revision 56800) [x64-mingw32] running under Windows Server R2012 R2, 64-bit

[shugo (Shugo Maeda)]

• Status changed from Open to Assigned
• Assignee set to shugo (Shugo Maeda)

Could you send us the debug output setting Net::FTP#debug_mode to true?

Net::FTP.open(SITE) do |ftp|
  ftp.debug_mode = true
  ...

[Phrogz (Gavin Kistner)]

With debug_mode on, I see this in my logs:

D, [2017-04-05T12:55:33.047600 #5076] DEBUG -- : ...downloading archived developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz
D, [2017-04-05T12:55:34.066636 #5076] DEBUG -- : ...unzipping local developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz
D, [2017-04-05T12:55:34.144761 #5076] DEBUG -- : ...unzipped developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz
D, [2017-04-05T12:55:34.160387 #5076] DEBUG -- : ...downloading archived developerdownloads_26549.esw3cdc_S.201703190000-0300-34.gz
C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:979:in `parse227': 226 Transfer complete. 0 bytes transferred. 0 bps. (Net::FTPReplyError)
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:392:in `makepasv'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:404:in `transfercmd'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:489:in `block (2 levels) in retrbinary'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:199:in `with_binary'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:487:in `block in retrbinary'
	from C:/Ruby/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:486:in `retrbinary'
	from C:/Ruby/lib/ruby/2.2.0/net/ftp.rb:619:in `getbinaryfile'
	from E:/dashstats_importer/import_from_ftp.rb:169:in `block (3 levels) in download_archives'

…and I see this on stdout/stderr:

get: 227 Entering Passive Mode (216,228,121,98,47,119).
put: RETR developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz
get: 150 Opening BINARY mode data connection for developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz.
get: 226 Transfer complete. 324995 bytes transferred. 324995 bps.
put: PASV
get: 226 Transfer complete. 0 bytes transferred. 0 bps.

[shugo (Shugo Maeda)]

Phrogz (Gavin Kistner) wrote:

get: 227 Entering Passive Mode (216,228,121,98,47,119).
put: RETR developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz
get: 150 Opening BINARY mode data connection for developerdownloads_26549.esw3cdc_S.201703190000-0300-33.gz.
get: 226 Transfer complete. 324995 bytes transferred. 324995 bps.
put: PASV
get: 226 Transfer complete. 0 bytes transferred. 0 bps.

226 is returned as a reply of PASV, but it's not RFC compilant and
seems a server issue.
Retrying on Net::FTPReplyError may work, but I'm not sure.

[Phrogz (Gavin Kistner)]

shugo (Shugo Maeda) wrote:

226 is returned as a reply of PASV, but it's not RFC compilant and
seems a server issue.

I agree that this appears to be a bad server. Thanks for the suggestion to catch the error and retry. (Not sure why I didn't think of that!)

FWIW this server is "EFT v6.3.2.3", I think provided by https://www.globalscape.com/managed-file-transfer

I suggest that this bug should be closed, as it is probably unreasonable (and perhaps even undesirable) for Net::FTP to try to handle and hide invalid responses like this.

[shugo (Shugo Maeda)]

• Status changed from Assigned to Third Party's Issue

Phrogz (Gavin Kistner) wrote:

shugo (Shugo Maeda) wrote:

226 is returned as a reply of PASV, but it's not RFC compilant and
seems a server issue.

I agree that this appears to be a bad server. Thanks for the suggestion to catch the error and retry. (Not sure why I didn't think of that!)

FWIW this server is "EFT v6.3.2.3", I think provided by https://www.globalscape.com/managed-file-transfer

I suggest that this bug should be closed, as it is probably unreasonable (and perhaps even undesirable) for Net::FTP to try to handle and hide invalid responses like this.

Thanks for your suggestion.

Please retry on FTPReplyError as a workaround.

[Phrogz (Gavin Kistner)]

shugo (Shugo Maeda) wrote:

Please retry on FTPReplyError as a workaround.

I have implemented this workaround and it has successfully recovered several times now. FWIW the code is:

retries = 3
begin
   ftp.getbinaryfile(file)
rescue Net::FTPReplyError => err
   if (retries -= 1) >= 0
      $log.warn "...got an error downloading #{file} (#{err}); trying again"
      retry
   else
      $log.error "Too many retries. Giving up."
      exit!
   end
end

Curiously, Globalscape has not yet been able to reproduce or witness the bug from server logs.