ioFTPD v7.3.3 Released (Beta) - Page 4

Silly · 04-08-2010, 06:46 AM

just upgraded....let's see...how's it going..

Yil · 04-08-2010, 10:02 AM

o_dog: I took a look around and didn't see anything obvious. It looked like all possible paths ended up resetting the flag no matter how the connection ended. The only suspicious thing I saw was the race condition on the bit field that could only occur if your client timed it out and tried to abort it which I presume you would see in the logs. I fixed that possibility in the 7.3.2 release just in case. If you're using that or newer and it's still happening I can always gin up a special debug version to record some info to the debug log or you can generate minidumps.

Can you double check that your client didn't try to abort the transfer on it's own before it got stuck? And upgrade to 7.3.3 to rule out the race condition I fixed.

pion · 04-08-2010, 10:12 AM

Yil; I tried your extra service configuration, but I had some problems with it. I copied the existing ftp service, renamed it, and change port, then added that Active_Services. At some point it appeared that only the latest service got loaded, essentially only opening one port. I also had problems getting the service to allow connections alltogether, also after reverting config, as if some bindings where still active. Reverting, manually killing the ioftpd.exe process, wait for a few, then starting it again appears to get things back to normal.

It's likely that the above problems is entirely my fault, however I find it curious that nothing (at all) showed up in logs when attempting to start ioftpd.exe. I could clearly see the process running, and spawning ioftpd-watch.exe - but not able to log in, and nothing is written in logs, not even startup events.

Yil · 04-08-2010, 01:09 PM

pion: I've seen once or twice locally and had people tell me they would start the server and not be able to connect to it, but restarting it fixed it so it wasn't a .ini file issue. I scratched my head since everything looked OK at first glance when I got it into the debugger but then I got the idea it might have something to do with the scheduler race condition on startup so I fixed that. If you see that problem again and you aren't playing with the config file let me know as it means the problem is still in there...

"Added" Active_Services? You mean replaced/modified the line under [Network] that was already there? If you can login you can use "site services" to see a list of configured services and their status. Use "site devices" to see configured devices although you won't need multiple of those since services can share them.

monk- · 04-09-2010, 08:22 AM

i also have problems with io just hanging at the startup
i figured out its hangs on directory caching
im used to putting all paths in the default.vfs
but with these hangs, it seams nessesary to disable cache on some paths

edit: i think it hangs on paths that are already cached
like:
"W:\FTP\MP3-ARCHIVE\OLDIES" /MP3-ARCHIVE/OLDIES
"w:" /STAFF/PROGRAMME/_HDD/W-drive
etc

and another question: is it possible to surpress log errors/warnings like: VFS WARNING: file '..\etc\default.vfs', line #59 has a real path that is invalid (error = No such file or directory): "y:" /STAFF/PROGRAMME/_HDD/Y-drive

edit2: hmm, i thought it would be anough to only put the sections in a seperate vfs file, and remove them from default.vfs
but then the sections dont show up on ftp
so now i wonder what the function is of this extra vfs file, when paths dont get loaded to the ftp anyway

pion · 04-09-2010, 08:56 AM

Startup bug appears to be more severe that I thought. I now have it on configs that has been static. ioftpd.exe is running and spawn ioftpd-watch.exe after a few seconds. I can also see io steadily growing in memory size for a few minutes, I'm guessing this is directory cache? After it reaches some final memory consumption it just sits there doing nothing. Not writing logs, not accepting connections.

Error.log are created showing: 04-09-2010 16:19:31 Unable to open/parse pre-load VFS file: ../etc/sections.vfs
04-09-2010 16:19:31 VFS WARNING: file '..\etc\default.vfs', line #45 has a real path that is invalid (error = No such file or directory): "mylocation" /mylocation

ioFTPD.log:
04-09-2010 16:19:31 PRELOAD: "begin" "..\etc\default.vfs"
04-09-2010 16:19:31 PRELOAD: "points=29" "..\etc\default.vfs"
04-09-2010 16:19:47 SSL: "Found certificate" "name=aaaa" "Service=FTP_Service" "(Certificate_name)"
04-09-2010 16:19:47 START: "PID=2836" "CmdLine="

nxMyDb.log:
04-09-2010 16:19:32 ------------------------------------------------------------

and that's it. No more logs to debug what's going on

Using io 7.3.3

I tried creating an empty file called sections.vfs - but same error came in log, however the ftpd started :S Looks somewhat random

Yil · 04-09-2010, 09:50 AM

Thanks for the observation. I'll take a quick look at the directory caching during preloading stuff which during startup is handled a little differently because the server isn't actually entirely configured at that point. It's possible I missed something being initialized and that's where the randomness is coming from.

I'll also add an option to completely disable it in the next build to see if that makes a difference as well.

pion · 04-09-2010, 12:07 PM

04-09-2010 17:02:23 Color #2 bad in .ini theme: '+ 2 Light-Full -1 2 2 2 -1 -1 -1 -1 -1 -1 2 2 2 2 2 2 2 2 2 -1 -1 -1 -1 -1 -1 -1 -1 5000 -1 5000 -1 5000 -1 5047 1 5 6 3 -1 -1 -1 -1 -1 -1 -1 -1 2 2 -1 -1 2'
04-09-2010 17:06:42 VFS WARNING: file '..\etc\default.vfs', line #28 has a real path that is invalid (error = No such file or direct..

I'm assuming it's directory caching taking so much time?
Is it possible to speed up that directory caching by specifying max folder depth or set some max execution time or similar? That time is on a core2 system with plenty free ram, and idle disk IO..

Basicly the problem is that the server is refusing any connection until that VFS WARNING log entry is written

pion · 04-09-2010, 01:59 PM

Not sure if this is nxMyDb or ioftpd problem, but I've seen groups disappear for no aparent reason, and the user is left in NoGroup. Anyone else seen this problem?

pion · 04-09-2010, 02:39 PM

Server stopping to accept files: Site 1 = drftpd, site2 = io 7.0.3

(21:17:05) [Site2] MKD /Mydir
(21:17:06) [Site2] 257 "/Mydir" created.
(21:17:06) [Site2] CWD /Mydir
(21:17:06) [Site2] 250 CWD command successful.
(21:17:06) [Site2] PWD
(21:17:06) [Site2] 257 "/Mydir" is current directory.
(21:17:06) [Site2] STAT -l
(21:17:06) [Site2] List Complete: 33 bytes in 0,11 seconds (0,30KB/s)
(21:17:06) [Site1] PRET RETR my.sfv
(21:17:06) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:06) [Site1] CPSV
(21:17:06) [Site1] 227 Entering Passive Mode (1,1,1,1,165,166).
(21:17:06) [Site2] PORT 1,1,1,1,165,166
(21:17:06) [Site2] 200 PORT command successful.
(21:17:06) [Site2] STOR my.sfv
(21:17:06) [Site2] 150 Opening ASCII mode data connection for my.sfv using SSL/TLS.
(21:17:06) [Site1] RETR my.sfv
(21:17:07) [Site1] 150 File status okay; about to open data connection from SLAVE1.
(21:17:17) [Site1] 426- Read timed out
(21:17:17) [Site1] 426 Read timed out
(21:17:17) [Site1] PRET RETR my.sfv
(21:17:17) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:17) [Site1] CPSV
(21:17:17) [Site1] 227 Entering Passive Mode (1,1,1,1,165,108).
(21:17:17) [Site2] PORT 1,1,1,1,165,108
(21:17:17) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:17) [Site1] PRET RETR my.sfv
(21:17:17) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:17) [Site1] CPSV
(21:17:18) [Site1] 227 Entering Passive Mode (1,1,1,1,164,93).
(21:17:18) [Site2] PORT 1,1,1,1,164,93
(21:17:18) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:18) [Site1] PRET RETR my.sfv
(21:17:18) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:18) [Site1] CPSV
(21:17:18) [Site1] 227 Entering Passive Mode (1,1,1,1,166,82).
(21:17:18) [Site2] PORT 1,1,1,1,166,82
(21:17:18) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:18) [Site1] PRET RETR my.sfv
(21:17:18) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:18) [Site1] CPSV
(21:17:18) [Site1] 227 Entering Passive Mode (1,1,1,1,167,198).
(21:17:18) [Site2] PORT 1,1,1,1,167,198
(21:17:18) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:18) [Site1] PRET RETR my.sfv
(21:17:19) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:19) [Site1] CPSV
(21:17:19) [Site1] 227 Entering Passive Mode (1,1,1,1,165,180).
(21:17:19) [Site2] PORT 1,1,1,1,165,180
(21:17:19) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:19) [Site1] PRET RETR my.sfv
(21:17:19) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:19) [Site1] CPSV
(21:17:19) [Site1] 227 Entering Passive Mode (1,1,1,1,165,218).
(21:17:19) [Site2] PORT 1,1,1,1,165,218
(21:17:19) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:19) [Site1] PRET RETR my.sfv
(21:17:19) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:19) [Site1] CPSV
(21:17:19) [Site1] 227 Entering Passive Mode (1,1,1,1,165,123).
(21:17:19) [Site2] PORT 1,1,1,1,165,123
(21:17:19) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:20) [Site1] PRET RETR my.sfv
(21:17:20) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:20) [Site1] CPSV
(21:17:20) [Site1] 227 Entering Passive Mode (1,1,1,1,165,42).
(21:17:20) [Site2] PORT 1,1,1,1,165,42
(21:17:20) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:20) [Site1] PRET RETR my.sfv
(21:17:20) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:20) [Site1] CPSV
(21:17:20) [Site1] 227 Entering Passive Mode (1,1,1,1,167,125).
(21:17:20) [Site2] PORT 1,1,1,1,167,125
(21:17:20) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:21) [Site1] PRET RETR my.sfv
(21:17:21) [Site1] 200 OK, will use SLAVE1 for upcoming transfer
(21:17:21) [Site1] CPSV
(21:17:21) [Site1] 227 Entering Passive Mode (1,1,1,1,166,158).
(21:17:21) [Site2] PORT 1,1,1,1,166,158
(21:17:21) [Site2] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(21:17:21) [Site1] PRET RETR my.sfv
(21:17:21) [Site1] 200 OK, will use SLAVE1 for upcoming transfer

In addition to this, the server site2 is no longer working with PASV (timeout). So no transfers possible at all.. the ABOR message, sticks around for about 5s before it aparently timeout.

I can log in and out, resulting in the same behaviour.

Now if I restart the ioftpd.exe service all transfers behave proper again (both PORT and PASV).

(as a note, waiting 3-5 minutes for io to start (dir caching?) is a real pain for debugging)

I didn't think about issuing 'site crashnow' - but if it happends again I'll do that also

pion · 04-09-2010, 02:49 PM

SystemError.log: 04-09-2010 21:46:59 Error converting string: /dir/subdir <-- Where is this error from? How to avoid it?

pion · 04-09-2010, 05:02 PM

I finally managed to catch some events leading up to hangup now:

THREAD 1:
(21:51:29) [site] 200 Type set to A.
(21:51:29) [site] PASV
(21:51:29) [site] 227 Entering Passive Mode (1,1,1,1,55,97)
(21:51:29) [site] Opening data connection IP: 1.1.1.1 PORT: 14177
(21:51:29) [site] LIST
(21:51:29) [site] 150 Opening ASCII mode data connection for directory listing using SSL/TLS.

THREAD 2:
(22:43:52) [site] TYPE A
(22:43:52) [site] 200 Type set to A.
(22:43:52) [site] PASV
(22:43:52) [site] 227 Entering Passive Mode (1,1,1,1,67,196)
(22:43:52) [site] Opening data connection IP: 1.1.1.1 PORT: 17348
(22:43:52) [site] LIST
(22:43:52) [site] 150 Opening ASCII mode data connection for directory listing using SSL/TLS.

Thread 1 had a successful transfer just before the hanging dir list.
Thread 2 had one successful transfer at 22:54 which is AFTER thread 1 got stuck. After that, I don't have any successful transfers. In addition, thread had some

(22:43:30) [site] Can't open data connection
(22:43:30) [site] 426 Connection closed: Connection timed out.

entries on list BEFORE it hanged completely

After that command it hanged for 2 and 1 hours consequently, until I now aborted them both manually in client. No new connections are accepted to the site, and I am unable to send any additional commands. ioftpd.exe is running, without any hints it's crashed/hanged/locked up. This is io 7.0.3

o_dog · 04-09-2010, 06:23 PM

pion: same error that i got. the 550 one

pion · 04-10-2010, 12:24 PM

Another crash/hangup/lockup where IO was dropping all connections more or less at once:

I had the following three threads connected:

IO -> IO

(19:06:05) [i] [IO_703 -> IO_703] myfile1.r02 4,3 Mbytes/8,41(s)/814,95Kbps
(19:06:05) [IO_703] CPSV
(19:06:05) [IO_703] 227 Entering Passive Mode (1,1,1,1,59,178)
(19:06:05) [IO_703] PORT 1,1,1,1,59,178
(19:06:05) [IO_703] 200 PORT command successful.
(19:06:05) [IO_703] STOR myfile1.r01
(19:06:05) [IO_703] 150 Opening BINARY mode data connection for myfile1.r01 using SSL/TLS.
(19:06:05) [IO_703] RETR myfile1.r01
(19:06:06) [IO_703] 150 Opening BINARY mode data connection for myfile1.r01 (14648 bytes) using SSL/TLS.
(19:06:22) [IO_703] 426 Connection closed: The specified network name is no longer available.
(19:06:22) [IO_703] CPSV
(19:06:22) [IO_703] 227 Entering Passive Mode (1,1,1,1,63,77)
(19:06:22) [IO_703] CPSV
(19:06:22) [IO_703] 227 Entering Passive Mode (1,1,1,1,64,179)
(19:06:22) [IO_703] CPSV
(19:06:22) [IO_703] 227 Entering Passive Mode (1,1,1,1,67,161)
(19:06:22) [IO_703] Connecting to IO_703
(19:06:22) [IO_703] Resolving IO_703.dns.com...
(19:06:22) [IO_703] IO_703.dns.com => 2.2.2.2
(19:06:22) [IO_703] Connecting to 2.2.2.2:21
(19:06:22) [IO_703] Connection Reset by Peer(10054)

DR -> IO

(19:05:25) [i] [DRFTPD -> IO_703] myfile2.r45 4,3 Mbytes/3,91(s)/442,39Kbps
(19:05:25) [DRFTPD] PRET RETR myfile2.r44
(19:05:25) [DRFTPD] 200 OK, will use master for upcoming transfer
(19:05:25) [DRFTPD] CPSV
(19:05:25) [DRFTPD] 227 Entering Passive Mode (1,1,1,1,119,108).
(19:05:25) [IO_703] PORT 1,1,1,1,119,108
(19:05:26) [IO_703] 200 PORT command successful.
(19:05:26) [IO_703] STOR myfile2.r44
(19:05:26) [IO_703] 150 Opening BINARY mode data connection for myfile2.r44 using SSL/TLS.
(19:05:26) [DRFTPD] RETR myfile2.r44
(19:05:26) [DRFTPD] 150 File status okay; about to open data connection from master.
(19:06:21) [DRFTPD] 426- Connection reset by peer: socket write error
(19:06:21) [DRFTPD] 426 Connection reset by peer: socket write error
(19:06:21) [DRFTPD] PRET RETR myfile2.r44
(19:06:21) [DRFTPD] 200 OK, will use master for upcoming transfer
(19:06:21) [DRFTPD] CPSV
(19:06:21) [DRFTPD] 227 Entering Passive Mode (1,1,1,1,125,249).
(19:06:21) [IO_703] Connecting to IO_703
(19:06:21) [IO_703] Resolving IO_703.dns.com...
(19:06:21) [IO_703] IO_703.dns.com => 2.2.2.2
(19:06:21) [IO_703] Connecting to 2.2.2.2:21
(19:06:21) [IO_703] Connection Reset by Peer(10054)

Moving directory

(19:04:56) [IO_703] RNFR Subdir
(19:04:56) [IO_703] 350 Directory exists, ready for destination name.
(19:04:56) [IO_703] RNTO /ROOT/Mydir/Subdir
(19:04:56) [IO_703] 250 RNTO command successful.
(19:04:56) [IO_703] PASV
(19:04:57) [IO_703] 227 Entering Passive Mode (2,2,2,2,60,17)
(19:04:57) [IO_703] Opening data connection IP: 2.2.2.2 PORT: 15377
(19:04:57) [IO_703] LIST
(19:04:57) [IO_703] 150 Opening ASCII mode data connection for directory listing using SSL/TLS.
(19:04:57) [IO_703] Encryption algorithm: TLSv1 DES-CBC3-SHA-168
(19:04:59) [IO_703] 226-[UL: 1GB] [DL: 1GB] [Speed: 1.3KB/s] [Free: 1MB]
(19:04:59) [IO_703] 226 [Section: DEFAULT] [Credits: 150.0MB] [Ratio: Leech]
(19:04:59) [IO_703] List Complete: 3*129 bytes in 0,47 seconds (10,67KB/s)
(19:05:05) [IO_703] CWD .
(19:05:06) [IO_703] 250 CWD command successful.
(19:05:06) [IO_703] PWD
(19:05:06) [IO_703] 257 "/ROOT" is current directory.
(19:05:11) [IO_703] RNFR Subdir3
(19:05:11) [IO_703] 350 Directory exists, ready for destination name.
(19:05:11) [IO_703] RNTO /ROOT/Mydir3/Subdir3
(19:05:12) [IO_703] 250 RNTO command successful.
(19:05:12) [IO_703] PASV
(19:05:12) [IO_703] 227 Entering Passive Mode (2,2,2,2,56,136)
(19:05:12) [IO_703] Opening data connection IP: 2.2.2.2 PORT: 14472
(19:05:12) [IO_703] LIST
(19:05:12) [IO_703] 150 Opening ASCII mode data connection for directory listing using SSL/TLS.
(19:05:15) [IO_703] Encryption algorithm: TLSv1 DES-CBC3-SHA-168
(19:05:16) [IO_703] 226-[UL: 1GB] [DL: 1GB] [Speed: 1KB/s] [Free: 1MB]
(19:05:16) [IO_703] 226 [Section: DEFAULT] [Credits: 1MB] [Ratio: 1]
(19:05:16) [IO_703] List Complete: 72*984 bytes in 0,56 seconds (74,77KB/s)
(19:05:36) [IO_703] CWD .
(19:05:36) [IO_703] 250 CWD command successful.
(19:05:36) [IO_703] PWD
(19:05:36) [IO_703] 257 "/ROOT" is current directory.
(19:05:51) [IO_703] CWD .
(19:05:51) [IO_703] 250 CWD command successful.
(19:05:51) [IO_703] PWD
(19:05:51) [IO_703] 257 "/ROOT" is current directory.
(19:06:06) [IO_703] CWD .
(19:06:06) [IO_703] 250 CWD command successful.
(19:06:06) [IO_703] PWD
(19:06:06) [IO_703] 257 "/ROOT" is current directory.
(19:06:17) [IO_703] RNFR Subdir2
(19:06:18) [IO_703] 350 Directory exists, ready for destination name.
(19:06:18) [IO_703] RNTO /ROOT/Mydir2/Subdir2
(19:06:21) [IO_703] Connecting to IO_703
(19:06:21) [IO_703] Resolving IO_703.dns.com...
(19:06:21) [IO_703] IO_703.dns.com => 2.2.2.2
(19:06:21) [IO_703] Connecting to 2.2.2.2:21
(19:06:21) [IO_703] Connection Reset by Peer(10054)

Notice the timestamps, where io decided to just drop all connections, and not allow any new ones to be made..

*Edit: After some minutes, io was back on again - and it had created a crashlog - so now there's something to debug!

Zer0Racer · 04-10-2010, 01:24 PM

What is the point in spamming logs from v7.0.3 when there a newer versions? Have you tried upgrading?