ioFTPD v7.4.3 Released (Experimental)

Yil · 04-20-2010, 03:33 PM

The OpenSSL port of ioFTPD is now available. It should function the same, but a lot has changed so let me know if you notice anything odd...

NOTE: experimental release... make sure to save old /system dir in case this doesn't work for you. Report all issues here.

Latest Version:
Link: ioFTPD-v7.4.3.zip

Source:
Link: ioFTPD-v7.4.0-src.zip

Yil · 04-20-2010, 03:33 PM

Code:

v7.4.0 Release Notes:

1) Files in \System:
   Changed : ioFTPD.[exe,pdb] - Version 7.4.0.0.
   Changed : dgbhelp.dll, symsrv.dll - Version 6.12.2.633
   Added   : libeay32.[dll,pdb], ssleay32.[dll,pdb] - Version 1.0.0.0
   Deleted : makecert.exe
   Changed : ioFTPD.ini - summary of changes by section...
     [FTP_Service] : BNC_HOST_# comment changed.


*** New features:

2) The server now uses the OpenSSL library to perform SSL/TLS encryption.

   New SSL/TLS certificates will be needed and can be created via the
   "site makecert" command, and removed via the "site removecert" command.
   The server can now do this without the help of an external program.
   The certificates are stored as <name>.key and <name>.pem files in the
   ioFTPD system directory.  If necessary change permissions on the .key
   file to make it readable only by the server/you if the machine is shared.

   For the moment the following ioFTPD.ini settings do not matter, however
   they may in a future build so until I decided one way or the other I'm
   not deleting references to them.
     [FTP_Service] : Min_Cipher_Strength, Max_Cipher_Strength
     [Threads]     : Encryption_Threads

3) Make sure you now have at least as many io_Threads under [Threads] as you
   do cores as the encryption and CRC computation for incoming files are
   performed in the I/O thread now instead of a separate thread.

4) You may now specify wildcards in BNC_HOST_# definitions for a service.
   Dynamic DNS hostnames are not supported at this time.

5) AUTH SSL and implicit SSL connections used to imply PROT P but AUTH TLS
   didn't... Now none do, as clients are supposed to enable this via PROT P.


*** Bug Fixes

6) Fixed a race condition when a service starts that would cause some or even
   all sockets listening for connections to not be created.  This should fix
   the server sometimes not accepting connections at startup problem.

7) Changed socket and file read/write routines to make sure they clear the
   overlapped fields that should be set to zero before using them.


*** Internal changes:

8) The Overlapped socket structures contain an identifier that is incremented
    before each call, and cleared in the callback.  This can detect bad usage.
    If everything looks good it will be removed in a later build.

9) Moved CRC field out of overlapped structure and into ioFile itself.

10) The following functions no longer exist or have changed enough that they
    should not be called by external modules: ioSend, ioRecv,
    TransmitPackages, ReceiveLine, ioCloseSocket, Secure_SendResult,
    Secure_ReceiveResult.

Yil · 04-20-2010, 03:38 PM

Grr, forgot to update the ioFTPD.ini file for distribution with this simple comment change:

Code:

# IDNT command restricted to use by these hosts.  You may list up to
# 10 (i.e. BNC_HOST_10) IP addresses or hostnames without skipping numbers.
# You may use wildcards.
;BNC_HOST_1 = 127.0.0.1

Yil · 04-20-2010, 05:11 PM

Hmm... the openSSL libs are built against the debug runtimes... I'm going to need to re-compile them against the regular... Update coming in a few mins.

Yil · 04-20-2010, 05:38 PM

Code:

v7.4.1 Release Notes:

1) Files in \System:
   Changed : libeay32.dll ssleay32.dll - Version 1.0.0.0
   Deleted : libeay32.pdb ssleay32.pdb

*** Bug Fixes

2) The OpenSSL libraries were compiled with debugging information and would
   fail to find the right libraries when ioFTPD.exe was run and generate the
     "The application failed to initialize properly (0xc0150002).  Click on
      OK to terminate the application."
   message.

Yil · 04-20-2010, 05:45 PM

I'll figure out how to get it compiled without using the debug library but to output a .pdb for better error reporting later...

I'll also probably add an option to have it auto-generate the cert if it's missing or invalid.

Yil · 04-20-2010, 06:51 PM

Looks like an early tester seeing some issues with incomplete files and a script having login issues. And it crashed...

Give me a day or two, I don't suggest upgrading yet.

Yil · 04-20-2010, 11:55 PM

Code:

v7.4.2 Release Notes:

1) Files in \System:
   Changed : ioFTPD.[exe,pdb] - Version 7.4.2.0


*** Bug Fixes

2) Fixed a bug introduced in the port where an internal job was ended too
   soon during login and could result in a race condition and the client
   being disconnected and/or crashing the server.

Yil · 04-20-2010, 11:59 PM

Ok, simple fix to eliminate the easy to reproduce crash problem. Funny enough, it wasn't in any of the OpenSSL code LOL...

See if this works. There have been some issues with received files being truncated. This version should show a "226-Transfered: <bytes>." message after the zipscript output if any. If you are finding things don't transfer correctly please confirm if the bytes written match the size of the file exactly.

Oh, and if you see it writing any lines to the logs/Debug.log file please let me know. There are a few cases I don't expect to happen that I can log there and if they do occur I'll need to handle them.

pion · 04-21-2010, 03:16 AM

I tried upgrading io733 to io742. I did not change anything in the ioftpd.ini.

without ssl:

ioftpd.ini:
Host = my.external.ip
Bind = 192.168.10.100

PASV
227 Entering Passive Mode (127,0,0,1,57,248)

and

PWD
257 "/" is current directory.
STAT -l
(hangs)

Both cases are without SSL

site makecert
200-NAME="abcd" [FTP_Service (Certificate_Name)]
500 makecert: The object or property already exists.

however, I could login with ssl after, AND stat -l worked with ssl. In addition, stat -l seems to work without ssl also after the 'site makecert' (?)

with ssl:

For AUTH SSL after the upgrade I got "Network subsystem is unusable(10091)", after the new cert was in place - but I suspect the client to be at fault there. However using AUTH TLS worked up until fxp transfer:

(09:57:00) [IO_703] 150 Opening BINARY mode data connection for file.rar (14648 bytes) using SSL/TLS.
(09:57:01) [IO_703] 426 Connection closed: The specified network name is no longer available.
(09:57:01) [IO_703] CPSV
(09:57:01) [IO_703] 227 Entering Passive Mode (1,1,1,1,65,3)
(09:57:01) [IO_742] 226-Transferred: 0.
(09:57:01) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:57:01) [IO_742] PORT 1,1,1,1,65,3
(09:57:01) [IO_742] 226 ABOR command successful.
(09:57:01) [IO_742] 200 PORT command successful.
(09:57:01) [IO_742] STOR file.rar
(09:57:01) [IO_742] 150 Opening BINARY mode data connection for file.rar using SSL/TLS.
(09:57:01) [IO_703] RETR file.rar
(09:57:02) [IO_703] 150 Opening BINARY mode data connection for file.rar (14648 bytes) using SSL/TLS.
(09:57:03) [IO_703] 426 Connection closed: The specified network name is no longer available.
(09:57:03) [IO_703] CPSV
(09:57:03) [IO_703] 227 Entering Passive Mode (1,1,1,1,68,235)
(09:57:03) [IO_742] 226-Transferred: 0.
(09:57:03) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:57:03) [IO_742] PORT 1,1,1,1,68,235
(09:57:03) [IO_742] 226 ABOR command successful.
(09:57:03) [IO_742] 200 PORT command successful.
(09:57:03) [IO_742] STOR file.rar
(09:57:04) [IO_742] 150 Opening BINARY mode data connection for file.rar using SSL/TLS.
(09:57:04) [IO_703] RETR file.rar
(09:57:04) [IO_703] 150 Opening BINARY mode data connection for file.rar (14648 bytes) using SSL/TLS.
(09:57:05) [IO_703] 426 Connection closed: The specified network name is no longer available.
(09:57:05) [IO_703] CPSV
(09:57:05) [IO_703] 227 Entering Passive Mode (1,1,1,1,60,109)
(09:57:05) [IO_742] 226-Transferred: 0.
(09:57:05) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:57:05) [IO_742] PORT 1,1,1,1,60,109
(09:57:05) [IO_742] 226 ABOR command successful.
(09:57:05) [IO_742] 200 PORT command successful.
(09:57:05) [IO_742] STOR file.rar
(09:57:05) [IO_742] 150 Opening BINARY mode data connection for file.rar using SSL/TLS.
(09:57:05) [IO_703] RETR file.rar
(09:57:06) [IO_703] 150 Opening BINARY mode data connection for file.rar (14648 bytes) using SSL/TLS.
(09:57:07) [IO_703] 426 Connection closed: The specified network name is no longer available.
(09:57:07) [IO_742] 226-Transferred: 0.
(09:57:07) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:57:07) [IO_703] CWD /
(09:57:07) [IO_742] CWD /
(09:57:07) [IO_742] 226 ABOR command successful.

(09:54:47) [IO_742] STOR myfile.r19
(09:54:47) [IO_742] 150 Opening BINARY mode data connection for myfile.r19 using SSL/TLS.
(09:54:47) [glftpd] RETR myfile.r19
(09:54:47) [glftpd] 150 Opening BINARY mode data connection for myfile.r19 (15000000 bytes) using SSL/TLS.
(09:54:47) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_connect()), disconnected: Connection reset by peer.
(09:54:47) [glftpd] CPSV
(09:54:47) [glftpd] 227 Entering Passive Mode (1,1,1,1,38,235)
(09:54:47) [IO_742] 226-Transferred: 0.
(09:54:47) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:54:47) [IO_742] PORT 1,1,1,1,38,235
(09:54:47) [IO_742] 226 ABOR command successful.
(09:54:47) [IO_742] 200 PORT command successful.
(09:54:47) [IO_742] STOR myfile.r19
(09:54:48) [IO_742] 150 Opening BINARY mode data connection for myfile.r19 using SSL/TLS.
(09:54:48) [glftpd] RETR myfile.r19
(09:54:48) [glftpd] 150 Opening BINARY mode data connection for myfile.r19 (15000000 bytes) using SSL/TLS.
(09:54:48) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_connect()), disconnected: Connection reset by peer.
(09:54:48) [glftpd] CPSV
(09:54:48) [glftpd] 227 Entering Passive Mode (1,1,1,1,37,82)
(09:54:48) [IO_742] 226-Transferred: 0.
(09:54:48) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:54:48) [IO_742] PORT 1,1,1,1,37,82
(09:54:48) [IO_742] 226 ABOR command successful.
(09:54:48) [IO_742] 200 PORT command successful.
(09:54:48) [IO_742] STOR myfile.r19
(09:54:49) [IO_742] 150 Opening BINARY mode data connection for myfile.r19 using SSL/TLS.
(09:54:49) [glftpd] RETR myfile.r19
(09:54:49) [glftpd] 150 Opening BINARY mode data connection for myfile.r19 (15000000 bytes) using SSL/TLS.
(09:54:49) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_connect()), disconnected: Connection reset by peer.
(09:54:49) [glftpd] CPSV
(09:54:49) [glftpd] 227 Entering Passive Mode (1,1,1,1,38,72)
(09:54:49) [IO_742] 226-Transferred: 0.
(09:54:49) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:54:49) [IO_742] PORT 1,1,1,1,38,72
(09:54:49) [IO_742] 226 ABOR command successful.
(09:54:49) [IO_742] 200 PORT command successful.
(09:54:49) [IO_742] STOR myfile.r19
(09:54:49) [IO_742] 150 Opening BINARY mode data connection for myfile.r19 using SSL/TLS.
(09:54:49) [glftpd] RETR myfile.r19
(09:54:49) [glftpd] 150 Opening BINARY mode data connection for myfile.r19 (15000000 bytes) using SSL/TLS.
(09:54:49) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_connect()), disconnected: Connection reset by peer.
(09:54:49) [glftpd] CPSV
(09:54:49) [glftpd] 227 Entering Passive Mode (1,1,1,1,42,129)
(09:54:49) [IO_742] 226-Transferred: 0.
(09:54:49) [IO_742] 426 Connection closed: SSL library returned a failure code.
(09:54:49) [IO_742] PORT 1,1,1,1,42,129
(09:54:50) [IO_742] 226 ABOR command successful.
(09:54:50) [IO_742] 200 PORT command successful.
(09:54:50) [IO_742] STOR myfile.r19
(09:54:50) [IO_742] 150 Opening BINARY mode data connection for myfile.r19 using SSL/TLS.
(09:54:50) [glftpd] RETR myfile.r19
(09:54:50) [glftpd] 150 Opening BINARY mode data connection for myfile.r19 (15000000 bytes) using SSL/TLS.
(09:54:50) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_connect()), disconnected: Connection reset by peer.

as pasv doesn't resolve proper, reverse transfer naturally don't work either:

(10:11:00) [io_703] TYPE I
(10:11:00) [io_703] 200 Type set to I.
(10:11:00) [io_742] TYPE I
(10:11:00) [io_742] 200 Type set to I.
(10:11:00) [io_703] Reversed FXP started
(10:11:00) [io_742] CPSV
(10:11:00) [io_742] 227 Entering Passive Mode (127,0,0,1,61,45)
(10:11:00) [io_703] PORT 127,0,0,1,21,45
(10:11:00) [io_703] 200 PORT command successful.
(10:11:00) [io_742] STOR thefile.rar
(10:11:01) [io_742] 150 Opening BINARY mode data connection for thefile.rar using SSL/TLS.
(10:11:01) [io_703] RETR thefile.rar
(10:11:01) [io_703] 150 Opening BINARY mode data connection for thefile.rar (14648 bytes) using SSL/TLS.
(10:11:02) [io_703] 426 Connection closed: No connection could be made because the target machine actively refused it.
(10:11:02) [i] Reversed FXP started
(10:11:02) [io_742] CPSV
(10:11:02) [io_742] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(10:11:02) [i] Reversed FXP started
(10:11:02) [io_742] CPSV
(10:11:03) [io_742] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(10:11:03) [i] Reversed FXP started
(10:11:03) [io_742] CPSV
(10:11:03) [io_742] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.

I tried to manually enter a directory, the ftpd disconnected me, causing my client to reconnect right away:

(10:02:17) [IO_742] CWD mydir
(10:02:17) [IO_742] 250 CWD command successful.
(10:02:17) [IO_742] PWD
(10:02:17) [IO_742] 257 "/mydir" is current directory.
(10:02:17) [IO_742] STAT -l
(10:02:18) [IO_742] Connecting to IO_742
(10:02:18) [IO_742] Resolving IO_742.mydns.com...
(10:02:18) [IO_742] IO_742.mydns.com => 1.1.1.1
(10:02:18) [IO_742] Connecting to 1.1.1.1:21

and after reconnect, the directory listed fine! (??) also for new sessions. (I might add that it's a fairly large directory). Other directories also listed fine in this and later sessions.

And finally, transferring files in AUTH TLS mode as regular download worked fine (except for PASV, which resolves wrong)

*Edit: I might add that I got some debug.log messages:

04-21-2010 09:42:52 AsyncSelectCancel flags: 0
04-21-2010 09:46:18 AsyncSelectCancel flags: 0
04-21-2010 09:46:58 AsyncSelectCancel flags: 0
..

Yil · 04-21-2010, 09:58 AM

Hmm. I'm willing to bet that the "large" directory is at fault for your listing issues. If you request a directory listing via "stat -l" that takes longer that 2 minutes to enumerate most FTP clients will time out the command. The most common case is a network mounted drive and I've seen this lots of times in that situation. Just re-connect and do it again and everything from that point works fine which is what you are seeing as well. I haven't found a good way to get around that problem, but it's the entire reason the preloading feature exists and allows for the DELAY option...

You mentioned PASV not resolving correctly. Is that something new or unexpected? I don't believe any of that should be different than before...

I guess I missed something in the SSL case though with the "SSL library returned a failure code" messages... I was hoping for more info from the Debug.log file, but knowing there is an issue means I'll test more and see what happens locally. My simple tests with glftpd/drftpd and back to itself worked, but I guess I got something wrong somewhere. I presume it has to do with the handshake code given no bytes were transferred.

pion · 04-21-2010, 10:42 AM

For large directories my client is listing bytes as it recieves them, when it hang it didn't get any bytes at all. As for my previous dirlisting problems, they are occuring at small directories also (<300 subdirs).

And on a sidenote of dirlisting: I put preload=false, but io742 still used a couple of minutes of loading ram before I was able to log in? (connection time out)

I'm not connecting to localhost ftpd... so yeah, the 127.0.0.1 is quite unexpected

Yil · 04-21-2010, 12:06 PM

ioFTPD won't display anything until all subdirs are evaluated so that is normal. And I mentioned before that no matter what preloading settings you have set it will load the mountpoints from the default VFS file (usually default.vfs) and any defined via VFS under [VFS_Preload]. However if delay=false it won't stop you from logging in while that is happening. Check the logfile to see the message order and what it means (see the v7.3 thread).

I just tested up/down over SSL and switched the connect/accept role via SSCN between ioFTPD and glFTPD with 2 different FTPs (one using an expired cert even) and all worked fine. I tested downloading from drFTPD as well in both roles and that worked as well.

It's still pretty likely I goofed something up by missing a case (as I said there are a few I was hoping don't happen), but I had no issues with the PASV feature. Double check your .ini file because until it reports that correctly you have other problems to worry about... Swap the .exe with the old without touching the .ini and see if it gets the PASV host correct. Are you using an IP address, a dynamic DNS name, a regular DNS name? Does it resolve correctly outside of ioFTPD?

I know, sometimes silly stuff, but have to check... Firewall? etc...

pion · 04-21-2010, 01:16 PM

The 127.0.0.1 problem was my windows hosts file with one dns record too much, so no wonder there was problems!

SSL transfers worked fine after I fixed that bit. I still get that network subsystem unusable in FTPRush, and in FlashFXP I get
[R] 220 -
[R] AUTH SSL
[R] 234 AUTH SSL successful.
[R] Connected. Negotiating SSL session..
[R] Connection failed (Connection lost)
[R] Delaying for 120 seconds before reconnect attempt #1

Where AUTH TLS works fine in both clients. AUTH SSL also work towards previous io versions in both clients.

Not so sure it's solely the clients fault anymore, I attempted to install latest openssl libraries, and tried flashfxp install today, in both win7, and win2k3 with the same result.. any way to look closer on what's happening when negotiating the ssl session?

I have DELAY = FALSE in ioftpd.ini, starting with empty logs

This is from clean logs:

nxmydb.log:
04-21-2010 20:04:16 ------------------------------------------------------------

<unable to log in at this point>

ioftpd.log:
04-21-2010 20:05:40 SSL: "Found certificate" "name=abcd" "Service=FTP_Service" "(Certificate_name)"
04-21-2010 20:05:40 START: "PID=1296" "CmdLine="
04-21-2010 20:05:40 PRELOAD: "begin" "../etc/default.vfs"
04-21-2010 20:06:12 LOGIN: "FTP_Service" "pion"

At that login, I'm stuck waiting for STAT -l (no disconnect, just delay) for a couple of minutes until
(20:09:01) [FTP] List Complete: 426 bytes in 84,33 seconds (0,01KB/s)

This is about 4000 folders, which each have 3 subfolders, so that leaves the total to 16000 folders. Why does it take 4 minutes, 45 seconds before login successful? I find it hard to believe that it takes that long to iterate through the subdirs on idle cpu/hdd IO..

Yil · 04-21-2010, 02:00 PM

pion: Just to double check are you using 7.4.2? The previous versions had a bug where it could drop the client right after/during negotiation which would look a lot like the first problem you listed in your latest post.

AUTH SSL and AUTH TLS are the same PROVIDED you haven't set the "Encryption_Protocol" option in the .ini file for the Service. If you have then you are limited to that protocol only... Can you double check that line is commented out? ioFTPD should be smart enough to not advertise/accept protocols it doesn't support, but right now it just ignore the argument to AUTH. The .ini option definitely controls what is allowed though. And AUTH TLS or SSL appeared to work for me locally, but I'll try some other clients!

It really does take a while to enter, enumerate all files/folders, read and parse the .ioFTPD file to get permissions and apply them to files and to figure out if the directory is an ioFTPD symbolic link or not. The only shortcut here is to disable sizing of directories in which case it goes straight to the .ioFTPD file to get only the perms and symbolic link target in each subdir. In the future perhaps I can provide a cache file and store it in directories with large fanouts or something, but for the moment on startup you're kinda stuck waiting for a while for the first listing in large dirs... I will double check that a directory lock isn't being held longer than necessary by the preloader though. I did do some profiling on this, and it's almost entirely disk limited. It just takes windows/NTFS a long time to open and enumerate all the dirs.

I know it sounds weird, but try DELAY=True. That enables a special multi-threaded directory scan that does a lot of things in parallel. It's actually MUCH MUCH faster if you have multiple drives. And as a bonus the server won't respond until it's actually ready which means it looks offline for 2 minutes but is immediately usable instead of answering right away but really won't do anything for 5 minutes using your numbers.