FTP: sporadic test failures - toPath does not write all bytes to file

[tgambet]

Versions used

Akka version: 2.5.22
Alpakka version: master branch with PR #1668 only

Note: The follow bug only arises when testing against an FTP server in docker. While I could not reproduce it on the master branch (which uses an embedded server with an in-memory filesystem) I believe it is still affected and the issue will arise in real-world usage of alpakka.

Expected Behavior

FTP.toPath should write a file consistently.

Actual Behavior

Testing FTP.toPath with a big file (~2M) fails sporadically with some bytes missing in the target file.

Reproducible Test Case

While running tests against docker I noticed that the toPath test with a big file failed maybe once out of ten times. To check the frequency of that failure I added the following trait:

// https://gist.github.com/dwickern/6ba9c5c505d2325d3737ace059302922
trait Repeated extends TestSuiteMixin { this: TestSuite =>
  protected abstract override def runTest(testName: String, args: Args): Status = {
    def run0(times: Int): Status = {
      val status = super.runTest(testName, args)
      if (times <= 1) status else status.thenRun(run0(times - 1))
    }
    run0(args.configMap.getWithDefault("times", "1").toInt)
  }
}

Extended it:

final class FtpStageSpec extends BaseFtpSpec with CommonFtpStageSpec with Repeated

And ran:
sbt ftp/testOnly *.FtpStageSpec -- -Dtimes=20 (runs each test 20 times in a row)

Here is a snip of relevant logs, testing only file length:

[info] FTPIOSink
[info] - should write a bigger file (~2 MB) to a path from a stream of bytes (753 milliseconds)
[info] - should write a bigger file (~2 MB) to a path from a stream of bytes *** FAILED *** (30 seconds, 973 milliseconds)
[info]   The code passed to eventually never returned normally. Attempted 60 times over 30 seconds. Last failure message: 1990656 was not equal to 2000020.
[info] - should write a bigger file (~2 MB) to a path from a stream of bytes (723 milliseconds)
[info] - should write a bigger file (~2 MB) to a path from a stream of bytes *** FAILED *** (30 seconds, 929 milliseconds)
[info]   The code passed to eventually never returned normally. Attempted 60 times over 30 seconds. Last failure message: 1998848 was not equal to 2000020.
[info] - should write a bigger file (~2 MB) to a path from a stream of bytes *** FAILED *** (30 seconds, 798 milliseconds)
[info]   The code passed to eventually never returned normally. Attempted 60 times over 30 seconds. Last failure message: 1990656 was not equal to 2000020.
...

(failures goes on)

It happens much more than expected so I investigated the issue and found that completePendingCommand(), a method of the underlying FTPClient, is never called. It is mandatory to call that method to finalize the transfer and check its completion as per FTPClient's documentation:
"To finalize the file transfer you must call completePendingCommand and check its return value to verify success. If this is not done, subsequent commands may behave unexpectedly."

I wrote a fix where the command is called after closing the output stream in FtpIOGraphStage.scala, reran the tests, and got the all green.

Question: Should the fix be part of #1668 or should I a open a new pull request?

[ennru]

Wow, thank you for investigating.
Please go ahead and add the fix to #1668.

[tgambet]

I implemented it like this: 5dcafe2

The casting of handler feels weird since it is necessarily an instance of ftpLike.Handler. Let me know what you think.

[tgambet]

Fixed per #1668