ioFTPD v7.5.9 Released (Beta)

[Yil]

o_dog: I can confirm that the server doesn't like NTFS junctions on network shares. While IGNORE mode really doesn't try to make the server realize it's a link it does attempt to validate the directory target because if it was invalid the server needs to know that so it can show a broken link fake entry. If it doesn't do that we get the old behavior of the server not showing broken links at all in listings.

The problem right now is the junction on the network share is returning a path that is valid only on the remote machine but it's being interpreted as if it was on the local machine and thus it's failing the existence test and you get the 0 byte broken link fake entry...

As soon as I figure out how to fix it I'll get a release out for you. I need to explore how the server resolves junctions across network shares and if you can link across different drives which are shared differently on the remote machine, and how to handle remote volume mountpoints, etc.

If you need something really quick, I can just test the link without interpreting it which should always work and probably makes the most sense for IGNORE mode anyway... That's a trivial change.

[pion]

10:39:50) [io752] RETR 1kbfile
(10:39:50) [io752] 550 1kbfile: Permission denied (config file).

ioftpd.ini:

Download = /* *

and no preRetr events.


What am I missing?

*Fix: Aparently the PERMISSIONS sections has to come before preload in ioftpd.ini

[pion]

I noticed something I haven't seen before. Who's at fault here? Or is it just a network error?

(15:20:28) [io743] PASV
(15:20:28) [io743] 227 Entering Passive Mode (1,1,1,1,68,159)
(15:20:28) [io752] PORT 1,1,1,1,68,159
(15:20:28) [io752] 200 PORT command successful.
(15:20:28) [io752] STOR file.r27
(15:20:30) [io752] 150 Opening BINARY mode data connection for file.r27.
(15:20:30) [io743] RETR file.r27
(15:20:30) [io743] 150 Opening BINARY mode data connection for file.r27 (100000000 bytes).
(15:21:17) [io743] 226-Transferred: 62128128.
(15:21:17) [io743] 426 Connection closed: The specified network name is no longer available.
(15:21:17) [io743] PASV
(15:21:17) [io743] 227 Entering Passive Mode (1,1,1,1,61,112)
(15:21:17) [io752] PORT 1,1,1,1,61,112
(15:21:19) [io752] 426-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:21:19) [io752] 426-250- | + CRC-Check: FaileD! |
(15:21:19) [io752] 426-250- `--------------------------------=====-------------'
(15:21:28) [io752] 426 Connection closed: A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.
(15:21:28) [io752] 226 ABOR command successful.
(15:21:28) [io752] 200 PORT command successful.
(15:21:28) [io752] STOR file.r27
(15:21:28) [io752] 150 Opening BINARY mode data connection for file.r27.
(15:21:28) [io743] RETR file.r27
(15:21:28) [io743] 150 Opening BINARY mode data connection for file.r27 (100000000 bytes).
(15:21:57) [io743] 226-Transferred: 100000000.
(15:21:57) [io743] 226-[UL: 3134.2GB] [DL: 2154.0GB] [Speed: 3458.8KB/s] [Free: 43533MB]
(15:21:57) [io743] 226 [Section: DEFAULT] [Credits: 150.0MB] [Ratio: Leech]
(15:21:57) [io752] 226-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:21:57) [io752] 226-250- | + CRC-Check: oK! |
(15:21:57) [io752] 226-250- +-=[UserTop]=-------------------===----------------+
(15:21:58) [i] [io743 -> io752] file.r27 95,4 Mbytes/29,09(s)/3*437,25Kbps
(15:21:58) [io743] PASV
(15:21:58) [io743] 227 Entering Passive Mode (1,1,1,1,62,107)
(15:21:58) [io752] PORT 1,1,1,1,62,107
(15:21:58) [io752] 200 PORT command successful.
(15:21:58) [io752] STOR file.r25
(15:22:01) [io752] 150 Opening BINARY mode data connection for file.r25.
(15:22:01) [io743] RETR file.r25
(15:22:03) [io743] 150 Opening BINARY mode data connection for file.r25 (100000000 bytes).
(15:22:21) [io743] 226-Transferred: 10223616.
(15:22:21) [io743] 426 Connection closed: The specified network name is no longer available.
(15:22:21) [io743] PASV
(15:22:21) [io743] 227 Entering Passive Mode (1,1,1,1,62,255)
(15:22:21) [io752] PORT 1,1,1,1,62,255
(15:22:21) [io752] 226 ABOR command successful.
(15:22:21) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:21) [io743] PASV
(15:22:21) [io743] 227 Entering Passive Mode (1,1,1,1,57,112)
(15:22:21) [io752] PORT 1,1,1,1,57,112
(15:22:21) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:21) [io743] PASV
(15:22:21) [io743] 227 Entering Passive Mode (1,1,1,1,54,192)
(15:22:21) [io752] PORT 1,1,1,1,54,192
(15:22:21) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:21) [io743] PASV
(15:22:21) [io743] 227 Entering Passive Mode (1,1,1,1,56,29)
(15:22:21) [io752] PORT 1,1,1,1,56,29
(15:22:21) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:22) [io743] PASV
(15:22:22) [io743] 227 Entering Passive Mode (1,1,1,1,57,210)
(15:22:22) [io752] PORT 1,1,1,1,57,210
(15:22:22) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:22) [io743] PASV
(15:22:22) [io743] 227 Entering Passive Mode (1,1,1,1,63,231)
(15:22:22) [io752] PORT 1,1,1,1,63,231
(15:22:22) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:22) [io743] PASV
(15:22:22) [io743] 227 Entering Passive Mode (1,1,1,1,57,73)
(15:22:22) [io752] PORT 1,1,1,1,57,73
(15:22:22) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:22) [io743] PASV
(15:22:23) [io743] 227 Entering Passive Mode (1,1,1,1,61,187)
(15:22:23) [io752] PORT 1,1,1,1,61,187
(15:22:23) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(15:22:23) [io743] PASV
(15:22:23) [io743] 227 Entering Passive Mode (1,1,1,1,70,80)
(15:22:23) [io752] 426-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:22:23) [io752] PORT 1,1,1,1,70,80
(15:22:23) [io752] 426-250- | + CRC-Check: FaileD! |
(15:22:23) [io752] 426-250- `--------------------------------=====-------------'
(15:22:23) [io752] 426 Connection closed: A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.
(15:22:23) [io743] Reversed FXP started
(15:22:23) [io752] PASV
(15:22:23) [io752] 200 PORT command successful.
(15:22:23) [io752] 227 Entering Passive Mode (2,2,2,2,60,145)
(15:22:23) [io743] PORT 2,2,2,2,60,145
(15:22:23) [io743] 200 PORT command successful.

[Yil]

pion: My money is on, uh, both?

Look at:
(15:21:17) [io743] 226-Transferred: 62128128.
(15:21:17) [io743] 426 Connection closed: The specified network name is no longer available.
(15:21:17) [io743] PASV
(15:21:17) [io743] 227 Entering Passive Mode (1,1,1,1,61,112)
(15:21:17) [io752] PORT 1,1,1,1,61,112
(15:21:19) [io752] 426-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:21:19) [io752] 426-250- | + CRC-Check: FaileD! |
(15:21:19) [io752] 426-250- `--------------------------------=====-------------'
(15:21:28) [io752] 426 Connection closed: A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.
(15:21:28) [io752] 226 ABOR command successful.
(15:21:28) [io752] 200 PORT command successful.

It appears that 743 transferred a bunch of bytes and then something happened to break/timeout the connection. The FTP client then started it over again. That isn't the interesting bit though, it's what the FTP program did with regards to the 752 server. It immediately tried to start another transfer! A little later (lagged connection, TCL script delay, etc ?) I can see the server responding with what I presume is the output of the previous failed transfer as well as an indication it was manually aborted, but no such command is recorded in the logfile. The fact that we see the 220 ABOR response is a good indication it might have tried to abort it but we can't know exactly when without a record of it. The most important point here is that the FTP client is not allowed to send another command until the response code for the ABOR is received, so the FTP client is at fault if it sent one and didn't wait for it. If it didn't send an abort, it's STILL at fault since the transfer was still going on and you can't start another one until it finishes/fails.

Everything worked out the first time and things went OK for the re-transfer, and then we get this:
(15:21:58) [io752] PORT 1,1,1,1,62,107
(15:21:58) [io752] 200 PORT command successful.
(15:21:58) [io752] STOR file.r25
(15:22:01) [io752] 150 Opening BINARY mode data connection for file.r25.
...
(15:22:21) [io752] PORT 1,1,1,1,62,255
(15:22:21) [io752] 226 ABOR command successful.
(15:22:21) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.

Assuming this represents the order things actually occurred then the FTP client once again tried to start another transfer without waiting for the previous to fail/complete (or it recorded the events wrong). A bunch of similar error messages to the last are returned as the client tried again and again to start a transfer.

The last bit is really interesting to me though:
(15:22:21) [io752] 226 ABOR command successful.
(15:22:23) [io752] 426-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:22:23) [io752] PORT 1,1,1,1,70,80
(15:22:23) [io752] 426-250- | + CRC-Check: FaileD! |
(15:22:23) [io752] 426-250- `--------------------------------=====-------------'
(15:22:23) [io752] 426 Connection closed: A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.
[Ignore the actual text of the 426 error message here. I return this error with the new closesocket locking I added as it seemed appropriate when using an already closed handle.]

It looks like you may have found an error in ioFTPD here though. When ioFTPD returned the first 226 abort reply it did so because it didn't have to force the socket closed so it assumed the transfer was already done/aborted and just returned success. However, the slightly later 426 replies means the server was still processing the results of the upload with the zipscript... This is clearly wrong, ioFTPD shouldn't respond with the 226 reply in this situation it should use some sort of lock/signal/etc to indicate that it aborted the connection but should not reply with the 226 answer until it returns the 426- replies like it does most of the time when ABOR actually forcefully closes the socket...

Given the potential that ioFTPD replied incorrectly to an aborted transfer before that part of the logfile the client may have been confused by the server. However, assuming events in the logfile are correct that still means it did the wrong thing... Really good catch here pion!


o_dog: It's also possible this could explain part of the ABOR problems you were seeing as well. The small parts of the logfiles you posted didn't show anything interesting, but it's possible ioFTPD screwed up and confused the client in your case as well with a bad reply order at some point previously but without that piece of the logfile it looked like the client was as fault (and it might just be both at fault) or it was inconclusive...

Either way, I should be able to fix this one...

[Yil]

pion: There's no order requirement for sections in the .ini file. However, the [VFS] section is kind of large because it starts with the default dir/file perms, then has a lot of commented text, and ends with Upload/Download/etc rules. I can tell you I've goofed and split the [VFS] section in half thinking the rules were their own section because of the way it's titled and set apart so I'm guessing you did the same... Glad you figured out how to undo whatever you did though.

[Yil]

It appears that dealing with NTFS junctions on a remote filesystem is hard... I can now detect when the directory is non-local but when I run into the junction I don't really have any way to determine the actual target since it's a remote path and that means nothing from looking at the directory mount point on the local machine since I don't know the base path for it. It's easy enough to just ignore the link similar to how IGNORE treats local junctions and that's what I'm probably going to do, but in that case you loose the nice features of SYMLINK mode...

I think I can add a requirement that the directory mounted in the .vfs file contain a special marker (chattr, or a file like .ioFTPD.base or something) that contains the base path on the server which I load in when loading new .vfs files.

However, there are 2 other options that I think work with network shares. I can teach ioFTPD how to parse .lnk files which is something I looked into when I did the NTFS junction stuff for v7 but didn't think worth doing, or on Vista+ the server could use symlinks which can refer to mountpoints and should function just like junctions... ioFTPD handles symlinks just like it does junctions so it's already supported, but the server just doesn't create them since you need to give the user account the ability to do so and I figured why bother when junctions work fine, but I obviously didn't count on network shares...

I've learned a lot though. I can detect remote NTFS junctions, and then figure out if the target path is on the same physical volume as the link which is useful. Now I just need to figure out how to put it all together.

I'm thinking I might need a new TCL function to make things easier for scripters though. Something along the lines of a create symlink function that would create a local NTFS junction if possible, else a symlink if supported, or maybe the .lnk style link, else a ioFTPD symlink. The trick is no matter which gets created it must be reverse resolvable to a VFS path for SYMLINK mode if that would have been possible locally. It turns out that might not be so hard for links TO network shares, but it's actually trickier for links on the network share that point BACK to local drives... Like suppose someone wanted to put the /Requests or /Incomplete dir on a remote filesystem. That wouldn't work if it tried to use junctions for everything.

It really is nice to see the links in explorer and be able to click on a dir and actually have it take you to the right place instead of having to do it in the FTP all the time, so I've got some incentive to get a workaround using filesystem links instead of ioFTPD symlinks.

Going to give it a day or two and see what ideas come to mind, but if someone has any ideas feel free to chime in.

[pion]

ioFTPD 7.5.2 is also crashing, refusing control connection. However it is less frequent that previous versions.

debug.log contains:

05-26-2010 14:51:49 WSAAsyncSelect error: 10022
05-26-2010 17:25:54 AsyncSelectProc: Socket 4964 not found.
05-26-2010 19:26:53 AsyncSelectProc: Socket 5020 not found.
05-26-2010 21:41:53 AsyncSelectProc: Socket 5108 not found.

watch.log did not get created until I attached windbg to process, then it wrote:

05-27-2010 11:09:12 Server timeout reached (70 > 60), killing it.

The last event in ioftpd.log was 23:38:37, then it was down for 12 hours until I noticed now.

Not sure if the dump I made from windbg is before or after the process got killed, but I'm sending it anyway.

*I might add that this server has a broken disk in it, so io could be crashing due to some hdd access? Expected behavior then is to time out the read, and report an error. This is probably related to my (insane) long preloading time from earlier. Which I also would expect io to give up on any broken disk within a reasonable time, instead of waiting 15 minutes.

[Yil]

pion: I doubt the lockup is directly related to disk problems. It is however likely that a disk that was causing errors by timing out, etc and forcing lots of aborted uploads/downloads might very well make problems in aborting much more likely to show up. I'm not referring to the previous message about how the server responds to the command, but to the actual act of forcing the socket closed. I'm going to have to change the way that is handled. I obviously made some good changes in these newer releases but not enough...

[pion]

Server crashed denying control connection.

Debug.log:

05-26-2010 14:51:49 WSAAsyncSelect error: 10022
05-26-2010 15:20:17 WSAAsyncSelect error: 10022
05-26-2010 19:30:19 AsyncSelectProc: Socket 4636 not found.
05-27-2010 01:10:18 AsyncSelectProc: Socket 4584 not found.
05-27-2010 01:55:18 AsyncSelectProc: Socket 4644 not found.
05-27-2010 02:10:18 AsyncSelectProc: Socket 4644 not found.
05-27-2010 04:55:23 AsyncSelectProc: Socket 4572 not found.
05-27-2010 08:45:22 AsyncSelectProc: Socket 4648 not found.
05-27-2010 09:00:17 AsyncSelectProc: Socket 4672 not found.
05-27-2010 09:50:20 AsyncSelectProc: Socket 4660 not found.
05-27-2010 13:25:24 AsyncSelectProc: Socket 4652 not found.
05-27-2010 18:47:17 AsyncSelectProc: Socket 4588 not found.

According to ioftpd.log it crashed 6 hours later, causing it to be crashed for 9 hours until my manual intervention now.

This server is without any hardware issues to my knowledge..


io 7.5.2 on win2k3 with ioFTPD-Watch.exe running, doing nothing.. this time it didn't kick in when I attached debugger either..


dump sent.

[Yil]

Just a quick note. I looked at the crashlog you sent earlier and noticed the stupid loader lock bug again. What really confused me is why it didn't detect it. Turns out I made a dumb mistake. For debugging purposes I obviously can't have it suicide after 60 seconds so I changed it to 60000 seconds at some point. I made a note to change it back, but when I looked I saw 60000 and thought that correct since most times are in milliseconds... DOH! So it looks like it did detect almost all of your lockups from the dumpfiles but it just didn't timeout properly...

I spent the last 12 hours working on a new bugfix release with a number of changes. I've got 1-2 more things to track down/fix so it should be out soon since there aren't any big new features.

[sCry]

great job! Soon long for me not update the file!

[Yil]

v7.5.3 Release Notes:

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

2) Files in \etc:
   Changed : Default.vfs - comments/documentation changed.


*** Incompatible changes/defaults:

3) The minimum supported operating system is now Windows XP.  A few new
   features are not available on Windows 2000 and it's so old there isn't any
   point in trying to keep support for it.

4) You may no longer use relative paths for directories you wish to mount in
   .vfs files.  These already generated a "VFS WARNING:" message about the
   entry but continued to work previously.  Now this is officially unsupported
   as it breaks some dir caching logic and the entries will be skipped and a
   "VFS ERROR:" messaged generated to the error logfile.

5) New files/directories will now go to the FIRST directory listed in the .vfs
   file for the mountpoint, the old behavior was to use the last dir.  This
   is a side effect of a bugfix below and duplicating the old behavior would
   add extra complexity and generate a performance hit.


*** Bug Fixes:

6) Fixed a bug with uploading to directories whose path doesn't exist on
   the last merged/raided directory listed in the .vfs file.  This is now
   fixed, but per #3 above the new behavior is to use the FIRST directory
   whose existing paths allow the new entry.  I.e. suppose you had these 2
   .vfs entries:
      "C:\Games"   /Games
      "D:\Games2"  /Games

   And these real directories:
      C:\Games\Favorites
      C:\Games\New
      D:\Games2\New
      D:\Games2\New\Test
      D:\Games2\Old

   New files or directories will be created thus:
      /Games/New/A       -> C:\Games\New\A
      /Games/New/Test/B  -> D:\Games2\New\Test\B
      /Games/Favorites/C -> C:\Games\Favorites\C
      /Games/Old/D       -> D:\Games2\Old\D

7) Fixed a bug with NTFS junctions on remotely mounted drives, or windows
   shares, not showing up.  For the moment these NTFS junctions will always
   act like NTFS_Reparse_Method = IGNORE because the logic to detect shared
   folders and to reverse paths doesn't know how to handle non-local paths.
   This may be fixed in a future release.

8) Fixed a bug where trying to create a directory that already exists would
   result in the OnNewDir script being called before failing.

9) Fixed a bug with detecting the loader lock and/or the winsock library
   getting stuck.  For debugging purposes I increased the 60 second
   timeout to 60000 and forgot to reset it before releasing the code for
   at least a few of the last releases.  I remember noting to undo the
   change but I guess I mistook 60000 for milliseconds which is what most
   time calculations use so I thought it looked correct...  This effectively
   disabled the deadlock detection mechanism!  The server now determines
   if a debugger is attached and if so it records an entry in the debug
   logfile but doesn't try to exit else it's new timeout is 60 seconds.

10) Fixed a bug where the server assumed external user/group modules wouldn't
   block.  This is obviously not always true and it was therefore possible
   that the server could end up with all worker threads being used up trying
   to access users or groups and get stuck for a while.

11) Fixed a bug where DELAY=TRUE preloading was done before the value for
    NTFS_Reparse_Method was set so preloaded directories that contained
    reparse points (NTFS junctions/symlinks) wouldn't show up as symlinks if
    NTFS_Reprase_Method was set to SYMLINK until the directory was updated
    in the cache.

12) Fixed a bug with the server's response to the ABOR command.  It was
    possible for it to return an immediate "226 ABOR command successful" reply
    if the server had finished the transfer and closed the connection, but
    before it had replied with the normal 226/426 reply.  The server will now
    wait to return the "226 ABOR command successful" message until after the
    normal reply which may not be instantly generated if the zipscript is
    processing an upload.

13) Fixed a number of potential bugs in the way async socket activity is
    reported by re-writing a number of pieces of logic.  Let's see if this
    fixes some things or if this entire method of doing things needs to be
    changed.  New Debug.log output for interesting cases added, not all
    messages indicate errors!

14) Fixed yet another bug where the built-in default Port_Deny_Host settings
    were improperly setup.

[Yil]

Version 7.5.3 contains some significant changes to the way async notification is done and thus it's possible I screwed up something. Local testing shows no problems, but let me know how it goes for you. I'd like positive replies as well just so I get a warm feeling that it's working correctly.

[usneek]

After two hours working with the new beta I received this error:

05-29-2010 14:39:24 System detected loader lock compromised! Terminating!
05-29-2010 14:40:25 2 clients failed to finish cleanly during shutdown grace period.
05-29-2010 14:41:25 2 clients must be zombies - terminating process.

Is the only error shown in the logs, is the first time I see it, just letting you know Yil, in case it help you in something.

[Yil]

NOTE: It looks like the 7.5.x releases somehow got a lot of a random test .ini from my development environment mixed in.... I must have done a bad merged or saved the wrong .ini file to the release dir at some point. If you had applied the changes to your .ini based upon the sections change stuff at the top of the file you'll be fine, but if you try to use winmerge or something you'd see a lot of changes as it had parts of a bunch of zipscripts setup and commented out, etc.

I'll put out a 7.5.4 release in a second with a clean update of the 7.4.x .ini file (there are so few changes to make) so it will be easier for people to upgrade.