simultaneous connections in PASV mode

Question

I am using the FileTransferClient API of edtFTPj/free in a Java app that allows users to transfer data to my server. In order to increase the transfer speed I have implemented a connection pool in my Java app with multiple simultaneous connections. The problem I'm encountering is that having multiple simultaneous connections only helps speed up the data transfers when using active mode (as opposed to passive mode). However, active mode does not seem to be supported by certain public wifi hotspots so I'd prefer to use passive mode instead. My guess is that I need to explicitly open separate ports on the ftp client side (beyond the default port 21) in order to allow simultaneous connections in passive mode, while in active mode this task is performed by the server.

Is my hunch correct? If so, how do I open multiple ftp ports using edtFTPj/free?

Any pointers in the right direction would be greatly appreciated. Thx

Answer 1

Since I'm using rather large files to transfer (about 20 MB), I've increased the value 10000 to 300000 for the ftp buffer size and the progress monitor. In order to flush out the problem, the only change I needed to do to your sample code was to have the second thread start slightly delayed. After all, with a connection pool, it becomes highly unlikely for all threads to start at the same time. So, I've inserted the following code between the two calls to "new Thread() {..."
try {
Thread.sleep(200);
}
catch (Exception e) {}

There seems to be some type of race condition going on, since I can find delays at which the problem disappears (e.g. for delay = 0). In my example, both files have about the same size of 22 MB and take about 45 seconds each to transfer to the server. However, with just the "right" delay between the 2 concurrent threads, they take a total of 83 seconds to upload instead of the expected 45 seconds.

run:
INFO [TestConcurrent] 9 May 2012 16:06:40.966 : Starting upload: /public_html/Curious/ftp/IMGP2704.DNG
DEBUG [FTPClient] 9 May 2012 16:06:40.983 : Class: com.enterprisedt.net.ftp.FTPClient
Location: file:/C:/Users/Curious/Documents/NetBeansProjects/DebugFTP/src/edtftpj.jar
Version: 2.3.0
Build timestamp: 26-Aug-2011 13:52:07 EST
Java version: 1.6.0_26
CLASSPATH:

C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src\edtftpj.jar;C:\Users\Curious\Documents\NetBeansProjects\Debu

gFTP\build\classes;C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src
OS name: Windows Vista
OS arch: x86
OS version: 6.0

DEBUG [FTPClient] 9 May 2012 16:06:41.089 : Connecting to ftp.somename.com/67.20.76.108:21
INFO [TestConcurrent] 9 May 2012 16:06:41.167 : Starting upload: /public_html/Curious/ftp/IMGP2705.DNG
DEBUG [FTPClient] 9 May 2012 16:06:41.167 : Class: com.enterprisedt.net.ftp.FTPClient
Location: file:/C:/Users/Curious/Documents/NetBeansProjects/DebugFTP/src/edtftpj.jar
Version: 2.3.0
Build timestamp: 26-Aug-2011 13:52:07 EST
Java version: 1.6.0_26
CLASSPATH:

C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src\edtftpj.jar;C:\Users\Curious\Documents\NetBeansProjects\Debu

gFTP\build\classes;C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src
OS name: Windows Vista
OS arch: x86
OS version: 6.0

DEBUG [FTPClient] 9 May 2012 16:06:41.167 : Connecting to ftp.somename.com/67.20.76.108:21
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.340 : 220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.341 : 220-You are user number 1 of 1000 allowed.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.341 : 220-Local time is now 14:07. Server port: 21.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.341 : 220-This is a private system - No anonymous login
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.341 : 220-IPv6 connections are also welcome on this server.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.341 : 220 You will be disconnected after 15 minutes of inactivity.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.342 : ---> USER somename
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.391 : 220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.391 : 220-You are user number 2 of 1000 allowed.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.391 : 220-Local time is now 14:07. Server port: 21.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.392 : 220-This is a private system - No anonymous login
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.392 : 220-IPv6 connections are also welcome on this server.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.392 : 220 You will be disconnected after 15 minutes of inactivity.
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.392 : ---> USER somename
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.452 : 331 User somename OK. Password required
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.452 : ---> PASS ********
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.502 : 331 User somename OK. Password required
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.502 : ---> PASS ********
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.653 : 230 OK. Current restricted directory is /
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.653 : ---> PWD
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.723 : 230 OK. Current restricted directory is /
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.723 : ---> PWD
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.764 : 257 "/" is your current location
DEBUG [FTPClient] 9 May 2012 16:06:41.764 : Attempt #1
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.764 : ---> PASV
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.833 : 257 "/" is your current location
DEBUG [FTPClient] 9 May 2012 16:06:41.834 : Attempt #1
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.834 : ---> PASV
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.874 : 227 Entering Passive Mode (67,20,76,108,199,1)
INFO [FTPControlSocket] 9 May 2012 16:06:41.874 : Substituting server supplied IP (67.20.76.108) with remote host IP

(67.20.76.108)
DEBUG [FTPControlSocket] 9 May 2012 16:06:41.948 : 227 Entering Passive Mode (67,20,76,108,148,97)
INFO [FTPControlSocket] 9 May 2012 16:06:41.948 : Substituting server supplied IP (67.20.76.108) with remote host IP

(67.20.76.108)
DEBUG [FTPControlSocket] 9 May 2012 16:06:42.053 : ---> STOR /public_html/Curious/ftp/IMGP2704.DNG
DEBUG [FTPControlSocket] 9 May 2012 16:06:42.130 : ---> STOR /public_html/Curious/ftp/IMGP2705.DNG
DEBUG [FTPControlSocket] 9 May 2012 16:06:42.171 : 150 Accepted data connection
DEBUG [FTPControlSocket] 9 May 2012 16:06:42.249 : 150 Accepted data connection
INFO [ProgressMonitor] 9 May 2012 16:06:48.281 : /public_html/Curious/ftp/IMGP2705.DNG 3009643 bytes
INFO [ProgressMonitor] 9 May 2012 16:06:53.650 : /public_html/Curious/ftp/IMGP2704.DNG 3008390 bytes
INFO [ProgressMonitor] 9 May 2012 16:06:53.959 : /public_html/Curious/ftp/IMGP2705.DNG 6019788 bytes
INFO [ProgressMonitor] 9 May 2012 16:06:59.662 : /public_html/Curious/ftp/IMGP2705.DNG 9029854 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:04.019 : /public_html/Curious/ftp/IMGP2704.DNG 6017329 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:05.349 : /public_html/Curious/ftp/IMGP2705.DNG 12040227 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:11.042 : /public_html/Curious/ftp/IMGP2705.DNG 15050171 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:14.727 : /public_html/Curious/ftp/IMGP2704.DNG 9027052 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:16.730 : /public_html/Curious/ftp/IMGP2705.DNG 18059689 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:22.413 : /public_html/Curious/ftp/IMGP2705.DNG 21067692 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:25.785 : /public_html/Curious/ftp/IMGP2704.DNG 12036521 bytes
INFO [ProgressMonitor] 9 May 2012 16:07:26.161 : /public_html/Curious/ftp/IMGP2705.DNG 22935622 bytes
DEBUG [FTPClient] 9 May 2012 16:07:26.161 : Transferred 22935622 bytes to remote host
DEBUG [FTPControlSocket] 9 May 2012 16:07:26.279 : 226-File successfully transferred
DEBUG [FTPControlSocket] 9 May 2012 16:07:26.279 : 226 44.034 seconds (measured here), 506.89 Kbytes per second
DEBUG [FTPControlSocket] 9 May 2012 16:07:26.279 : ---> QUIT
DEBUG [FTPControlSocket] 9 May 2012 16:07:26.389 : 221-Goodbye. You uploaded 22321 and downloaded 0 kbytes.
DEBUG [FTPControlSocket] 9 May 2012 16:07:26.389 : 221 Logout.
INFO [T

Answer 2

Have you been able to replicate my symptoms?

Answer 3

I just tried adding the 200ms sleep between the two uploads and it made no difference for me.

Try adding a Thread.yield() in your bytesTransferred method:

public void bytesTransferred(long count) {
   log.info(fileName + " " + count + " bytes");
   Thread.yield();
}

- Hans (EnterpriseDT)

Answer 4

Adding Thread.yield() does not help. In fact, I don't even need to call the ProgressMonitor for the problem to occur.

As I had stated before, there appears to be a race condition which means that you might need a different delay than 200ms for your particular setup.

A more reliable way to trigger the symptoms is to use just a single thread and transfer an entire sequence of files instead. Then, at the same time launch another instance of the app with a different sequence of files. This will ensure that the delay between the beginning of file transfers will vary.

Please let me know if launching 2 instances will allow you to replicate my problem. Thanks.

Answer 5

OK, if yield doesn't help then try to add a sleep as follows:

public void bytesTransferred(long count) { 
   log.info(fileName + " " + count + " bytes");
   log.debug("Sleeping for 5s");
   Thread.sleep(5000); 
   log.debug("Woke up");
}

It'll be interesting to see if the JVM just sits idle for that period instead of switching to the other thread.

By the way, you're running in an app-server aren't you? It may be doing something funky with the threads. Have you tried the same test from the command-line?

- Hans (EnterpriseDT)

Answer 6

I'm posting the results of your suggested modification below in the hope it might help you diagnose the problem. However, note that bytesTransferred() is only called from the ProgressMonitor and the problem persists even without calling the ProgressMonitor.

I'm experiencing the problem with a variety of servers. The one I'm interfacing with here is a Linux web server.


run:
INFO [TestConcurrent] 15 May 2012 22:20:28.034 : Starting upload: /public_html/Curious/ftp/IMGP2704.DNG
DEBUG [FTPClient] 15 May 2012 22:20:28.050 : Class: com.enterprisedt.net.ftp.FTPClient
Location: file:/C:/Users/Curious/Documents/NetBeansProjects/DebugFTP/src/edtftpj.jar
Version: 2.3.0
Build timestamp: 26-Aug-2011 13:52:07 EST
Java version: 1.6.0_26
CLASSPATH: C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src\edtftpj.jar;C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\build\classes;C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src
OS name: Windows Vista
OS arch: x86
OS version: 6.0

DEBUG [FTPClient] 15 May 2012 22:20:28.075 : Connecting to ftp.somename.com/67.20.76.108:21
INFO [TestConcurrent] 15 May 2012 22:20:28.235 : Starting upload: /public_html/Curious/ftp/IMGP2705.DNG
DEBUG [FTPClient] 15 May 2012 22:20:28.235 : Class: com.enterprisedt.net.ftp.FTPClient
Location: file:/C:/Users/Curious/Documents/NetBeansProjects/DebugFTP/src/edtftpj.jar
Version: 2.3.0
Build timestamp: 26-Aug-2011 13:52:07 EST
Java version: 1.6.0_26
CLASSPATH: C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src\edtftpj.jar;C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\build\classes;C:\Users\Curious\Documents\NetBeansProjects\DebugFTP\src
OS name: Windows Vista
OS arch: x86
OS version: 6.0

DEBUG [FTPClient] 15 May 2012 22:20:28.235 : Connecting to ftp.somename.com/67.20.76.108:21
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.322 : 220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.322 : 220-You are user number 5 of 1000 allowed.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.322 : 220-Local time is now 20:20. Server port: 21.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.323 : 220-This is a private system - No anonymous login
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.323 : 220-IPv6 connections are also welcome on this server.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.323 : 220 You will be disconnected after 15 minutes of inactivity.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.324 : ---> USER somename
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.433 : 331 User somename OK. Password required
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.433 : ---> PASS ********
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.454 : 220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.454 : 220-You are user number 6 of 1000 allowed.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.454 : 220-Local time is now 20:20. Server port: 21.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.454 : 220-This is a private system - No anonymous login
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.455 : 220-IPv6 connections are also welcome on this server.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.455 : 220 You will be disconnected after 15 minutes of inactivity.
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.455 : ---> USER somename
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.563 : 331 User somename OK. Password required
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.563 : ---> PASS ********
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.624 : 230 OK. Current restricted directory is /
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.624 : ---> PWD
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.732 : 257 "/" is your current location
DEBUG [FTPClient] 15 May 2012 22:20:28.732 : Attempt #1
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.733 : ---> PASV
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.757 : 230 OK. Current restricted directory is /
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.757 : ---> PWD
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.842 : 227 Entering Passive Mode (67,20,76,108,40,11)
INFO [FTPControlSocket] 15 May 2012 22:20:28.842 : Substituting server supplied IP (67.20.76.108) with remote host IP (67.20.76.108)
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.867 : 257 "/" is your current location
DEBUG [FTPClient] 15 May 2012 22:20:28.867 : Attempt #1
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.867 : ---> PASV
DEBUG [FTPControlSocket] 15 May 2012 22:20:28.975 : 227 Entering Passive Mode (67,20,76,108,237,251)
INFO [FTPControlSocket] 15 May 2012 22:20:28.975 : Substituting server supplied IP (67.20.76.108) with remote host IP (67.20.76.108)
DEBUG [FTPControlSocket] 15 May 2012 22:20:29.046 : ---> STOR /public_html/Curious/ftp/IMGP2704.DNG
DEBUG [FTPControlSocket] 15 May 2012 22:20:29.163 : 150 Accepted data connection
DEBUG [FTPControlSocket] 15 May 2012 22:20:29.179 : ---> STOR /public_html/Curious/ftp/IMGP2705.DNG
DEBUG [FTPControlSocket] 15 May 2012 22:20:29.295 : 150 Accepted data connection
INFO [ProgressMonitor] 15 May 2012 22:20:33.153 : /public_html/Curious/ftp/IMGP2704.DNG 3008390 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:20:33.153 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:20:38.153 : Woke up
INFO [ProgressMonitor] 15 May 2012 22:20:41.708 : /public_html/Curious/ftp/IMGP2704.DNG 6017329 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:20:41.708 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:20:46.708 : Woke up
INFO [ProgressMonitor] 15 May 2012 22:20:46.845 : /public_html/Curious/ftp/IMGP2705.DNG 3009643 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:20:46.845 : Sleeping for 5s
INFO [ProgressMonitor] 15 May 2012 22:20:50.059 : /public_html/Curious/ftp/IMGP2704.DNG 9027052 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:20:50.060 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:20:51.845 : Woke up
DEBUG [ProgressMonitor] 15 May 2012 22:20:55.060 : Woke up
INFO [ProgressMonitor] 15 May 2012 22:20:58.409 : /public_html/Curious/ftp/IMGP2704.DNG 12036521 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:20:58.409 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:21:03.409 : Woke up
INFO [ProgressMonitor] 15 May 2012 22:21:05.996 : /public_html/Curious/ftp/IMGP2705.DNG 6019788 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:21:05.996 : Sleeping for 5s
INFO [ProgressMonitor] 15 May 2012 22:21:07.031 : /public_html/Curious/ftp/IMGP2704.DNG 15046136 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:21:07.031 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:21:10.997 : Woke up
DEBUG [ProgressMonitor] 15 May 2012 22:21:12.031 : Woke up
INFO [ProgressMonitor] 15 May 2012 22:21:15.890 : /public_html/Curious/ftp/IMGP2704.DNG 18055138 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:21:15.890 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:21:20.890 : Woke up
INFO [ProgressMonitor] 15 May 2012 22:21:22.671 : /public_html/Curious/ftp/IMGP2705.DNG 9029854 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:21:22.671 : Sleeping for 5s
INFO [ProgressMonitor] 15 May 2012 22:21:24.377 : /public_html/Curious/ftp/IMGP2704.DNG 21063149 bytes
DEBUG [ProgressMonitor] 15 May 2012 22:21:24.377 : Sleeping for 5s
DEBUG [ProgressMonitor] 15 May 2012 22:21:27.671 : Woke up
DEBUG [ProgressMonitor] 15 May 2012 22:21:29.377 : Woke up
INFO [ProgressMonitor] 15 May 201

Answer 7

I suggest that you search for statics in our code (it's open-source). I think you'll see that there aren't any that could cause synchronization problems between separate instances. Instead I suspect the JVM is excessively prioritizing one thread over the other, and allowing the first one to complete before giving the second one a chance to run.

The test you just did indicates that this is what's happening because your log shows the transfers happening concurrently:

INFO [ProgressMonitor] 15 May 2012 22:20:41.708 : /public_html/Curious/ftp/IMGP2704.DNG 6017329 bytes 
DEBUG [ProgressMonitor] 15 May 2012 22:20:41.708 : Sleeping for 5s 
DEBUG [ProgressMonitor] 15 May 2012 22:20:46.708 : Woke up 
INFO [ProgressMonitor] 15 May 2012 22:20:46.845 : /public_html/Curious/ftp/IMGP2705.DNG 3009643 bytes 
DEBUG [ProgressMonitor] 15 May 2012 22:20:46.845 : Sleeping for 5s 
INFO [ProgressMonitor] 15 May 2012 22:20:50.059 : /public_html/Curious/ftp/IMGP2704.DNG 9027052 bytes 

They wouldn't happen concurrently if there was a synchronization problem.

Why the JVM should behave like this I don't know.

- Hans (EnterpriseDT)

Answer 8

Any thread prioritization issues cannot be blamed when running two separate instances: When you're running two instances, each one is running in its own JVM so they are completely decoupled from one another.

Answer 9

The logs you've posted are all from a single process though right?

- Hans (EnterpriseDT)

Answer 10

By the way, all of the source-code is included in the distribution, so maybe it's easier if you diagnose and fix the problem yourself. We'd of course be very happy if you could send us the patch when you're done.

- Hans (EnterpriseDT)