ioFTPD v7.4.3 Released (Experimental) - Page 5

Yil · 04-29-2010, 11:37 AM

pion: That looked interesting for a minute, but it looks like nothing more than whatever problem you are having with socket communications. First, I'm curious about that "SITE XDUPE" line. Do you have an addon for that? I was surprised to see the command was accepted...

The interesting part is the ABOR line. The client issued the command and never received a response. I'm guessing the server hung up trying to force close the socket for some reason. That could turn out to be a really useful clue to me though, so keep them coming.

The part that caught my eye originally was the 550 debug line + Active Transfer in progress err, but it turns out that is correct behavior. The server has not returned acknowledgment of the ABOR command or returned success/failure of the transfer itself. The client is not allowed to start another transfer until one of those 3 things happen. Now obviously the server is stuck and not happy, but what made that log look really interesting to me just isn't...

o_dog: Any ABOR lines like the above showing up? Still having that issue that I was blaming on the client?

o_dog · 04-29-2010, 05:36 PM

Nah, i got problems with 10min timeouts it seems. thats my only problem at the moment. Dont really know why the transfer is stopping though.

Yil · 04-30-2010, 12:18 AM

pion: I examined a number of the dump files you sent me and most of them are hung in closesocket. This is familiar territory for me. I eventually figured out that what was happening is we passed a socket handle onto a child process (which is easy to do unfortunately) and then tried to force the socket closed. This can result in the server hanging until the child exits or perhaps blocks in an alertable state, but scripts don't expect to need to do this and so they often never do. I discovered this by accident back in late v6 and fixed the server to protect socket creation. It wasn't until v7.0 that I realized I also had to prevent the TCL library from creating sockets while ioFTPD was creating processes. So as I mentioned above I had a thought that libmysql probably has the same problem which is why your configuration is different than others and they aren't seeing any problems...

Anyway, I setup nxMyDB and performed some tests against the modified library that I thought should have fixed this. Evidently I didn't do something right because I can confirm that it looks like a socket handle is being passed onto child processes by nxMyDB but which really means libmysql. Debugging through several layers of dynamically loaded libraries really sucks, but I'll figure it out for you.

I can't prove this is the problem, but given past history I'm pretty sure this is it. So there is hope yet

Flow · 04-30-2010, 07:19 AM

hi Yil, can you check if IDENT port always open?. Can it be close if no one is using it?

Yil · 04-30-2010, 10:29 AM

ioFTPD doesn't respond to IDENT requests, it only sends them. You can disable the sending of them by using a timeout of 0 in the config file if you want. As far as ports go it just uses one of the defined out_ports and thus is the same range as active transfers from the server would use.

Yil · 04-30-2010, 03:11 PM

pion: I might have spoken too soon about the socket issue. I just noticed that the above test wasn't against the custom build I made for you. When using the new builds it does indeed look like I fixed the problem. So that means I no longer have a clue on how to fix this... Time to go bang the head against the wall some more and hope something else comes to mind.

pion · 05-01-2010, 05:41 AM

I attempted some more stresstesting, and fired up 15-20 transfers at once. Then I managed to hang the site after about 15 minutes. Could there be some unresolved race condition or similar?

But in any case, just have some logic that can detect when transfers start acting up, and restart it would be a huge help also.. manual restarts can be really painful...

SSL transfer also seem to be a problem still from some sources:

GL: 426 Data connection: Broken pipe.
DR: 426- Unexpected end of handshake data
(13:54:04) [DR] 426- Connection reset
(13:54:04) [DR] 426 Connection reset

No idea about the reason, but I noticed this in the event log:

An SSL connection request was received from a remote client application, but none of the cipher suites supported by the client application are supported by the server. The SSL connection request has failed.

Not sure if it's related or not, but the box doesn't have any other functions

Yil · 05-01-2010, 11:16 AM

I'm ahead of you on this

I spent last night making the server try to connect to itself every minute to detect when something goes wrong so it can restart itself. I also changed the watcher program to detect a locked up server better. I'll roll those and a few more changes out soon.

I've had another person report issues with drFTPD over SSL getting that "Unexpected end of handshake data" message as well. That log message info is new though and almost certainly related. If you can connect to the drFTPD site and download from it directly what does the client say the encryption mechanism chosen was? I.e. was is aes256, aes128, or something else. I am aware that some Java implementations have a crippled crypto suite installed by default to use short keys and I wonder if that could be part of the issue.

I'm also not convinced that OpenSSL v1.0 isn't slightly different than older beta releases based on comments elsewhere.

Do any transfers from that site work, or does it randomly not work?

pion · 05-01-2010, 11:37 AM

Transfers generally work fine from that site, but I randomly get "Network subsystem is unusable(10091)" in client after AUTH SSL command. But on reconnect, I get Encryption algorithm: TLSv1 DHE-RSA-AES256-SHA-256

Yil · 05-03-2010, 02:06 PM

Good news, I can confirm that 2 other people who had issues with ioFTPD running under win2k3 are now doing fine. The switch to OpenSSL seems to have made things FAR more stable than before for them as they are crashfree now. Pion's use of nxMyDB however is still unstable...

I did some more research into OpenSSL and found some useful info. I see how to order/limit which ciphers we want to use, so I think I'll see if I can't let users in the .ini file order them if people want that. More importantly though I can apply the key bit length min/max fields from before to weed out unwanted crappy ciphers automatically which is something far more likely for people to actually use.

I also see that I am using default/pure OpenSSL, and that there are a handful of "bugs" in other SSL libraries that it can be told to work around. I might try enabling all those workarounds to see if that increases interoperability.

We are also using the latest v1.0 release of OpenSSL which was released in March 2010. I found this tidbit in their list of changes:

Code:

  *) If no SSLv2 ciphers are used don't use an SSLv2 compatible client hello:
     this allows the use of compression and extensions. Change default cipher
     string to remove SSLv2 ciphersuites. This effectively avoids ancient SSLv2
     by default unless an application cipher string requests it.

Thus as of the 1.0 release SSLv2 is almost dead and the type of client hello is different than before. This may be a cause for slightly different behavior with some sites when FXPing.

pion · 05-04-2010, 03:24 AM

Bad news - io 745 is not working proper without nxmydb either.

(10:08:02) [glftpd] Reversed FXP started
(10:08:02) [io745] CPSV
(10:08:02) [io745] 226-Transferred: 0.
(10:08:02) [io745] 426 Connection closed: Connection timed out.
(10:08:02) [io745] 226 ABOR command successful.
(10:08:02) [io745] 227 Entering Passive Mode (1,1,1,1,65,54)
(10:08:02) [glftpd] PORT 1,1,1,1,65,54
(10:08:02) [glftpd] 200 PORT command successful.
(10:08:02) [io745] STOR file.r27
(10:08:03) [io745] 150 Opening BINARY mode data connection for file.r27 using SSL/TLS.
(10:08:03) [glftpd] RETR file.r27
(10:08:03) [glftpd] 150 Opening BINARY mode data connection for file.r27 (15000000 bytes) using SSL/TLS.
(10:08:22) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_accept()), disconnected: Connection reset by peer.
(10:08:22) [glftpd] Reversed FXP started
(10:08:22) [io745] CPSV
(10:08:22) [io745] 226-Transferred: 0.
(10:08:22) [io745] 426 Connection closed: Connection timed out.
(10:08:22) [io745] 226 ABOR command successful.
(10:08:22) [io745] 227 Entering Passive Mode (1,1,1,1,66,140)
(10:08:22) [glftpd] PORT 1,1,1,1,66,140
(10:08:22) [glftpd] 200 PORT command successful.
(10:08:22) [io745] STOR file.r27
(10:08:23) [io745] 150 Opening BINARY mode data connection for file.r27 using SSL/TLS.
(10:08:23) [glftpd] RETR file.r27
(10:08:23) [glftpd] 150 Opening BINARY mode data connection for file.r27 (15000000 bytes) using SSL/TLS.
(10:08:42) [glftpd] 435 Failed TLS negotiation on data channel (using SSL_accept()), disconnected: Connection reset by peer.

(10:03:22) [io703] Reversed FXP started
(10:03:22) [io745] 226-Transferred: 0.
(10:03:22) [io745] 426 Connection closed: Connection timed out.
(10:03:22) [io745] CPSV
(10:03:22) [io745] 226 ABOR command successful.
(10:03:22) [io745] 227 Entering Passive Mode (1,1,1,1,61,26)
(10:03:22) [io703] PORT 1,1,1,1,61,26
(10:03:22) [io703] 200 PORT command successful.
(10:03:22) [io745] STOR myfile.r09
(10:03:23) [io745] 150 Opening BINARY mode data connection for myfile.r09 using SSL/TLS.
(10:03:23) [io703] RETR myfile.r09
(10:03:23) [io703] 150 Opening BINARY mode data connection for myfile.r09 (14648 bytes) using SSL/TLS.
(10:03:43) [io703] 426 Connection closed: The specified network name is no longer available.
(10:03:43) [io703] Reversed FXP started
(10:03:43) [io745] 226-Transferred: 0.
(10:03:43) [io745] 426 Connection closed: Connection timed out.
(10:03:43) [io745] CPSV
(10:03:43) [io745] 226 ABOR command successful.
(10:03:43) [io745] 227 Entering Passive Mode (1,1,1,1,63,54)
(10:03:43) [io703] PORT 1,1,1,1,63,54
(10:03:43) [io703] 200 PORT command successful.
(10:03:43) [io745] STOR myfile.r09
(10:03:44) [io745] 150 Opening BINARY mode data connection for myfile.r09 using SSL/TLS.
(10:03:44) [io703] RETR myfile.r09
(10:03:44) [io703] 150 Opening BINARY mode data connection for myfile.r09 (14648 bytes) using SSL/TLS.
(10:04:04) [io703] 426 Connection closed: The specified network name is no longer available.

(10:18:38) [io745] STAT -l
(10:18:38) [io745] List Complete: 4*405 bytes in 0,11 seconds (40,05KB/s)
(10:18:42) [io745] PASV
(10:18:42) [io745] 227 Entering Passive Mode (1,1,1,1,63,227)
(10:18:43) [io745] RETR 6kbfile.nfo
(10:18:43) [io745] 150 Opening ASCII mode data connection for 6kbfile.nfo (5857 bytes) using SSL/TLS.
(10:18:57) [io745] ABOR
(10:18:57) [io745] Can't open data connection
(10:18:57) [io745] PASV
(10:18:58) [io745] 550-Init: 1, Aborted: 1, Socket: -1, LastError: 20500, Size: 5857, Pos: 240518168576
(10:18:58) [io745] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
(10:18:58) [io745] Connecting to io745

This behaviour repeats itself over and over and over and over for hours and hours - so it's clearly crashed. This is in fact, the excact same behaviour as the hangup bug, where it becomes impossible to connect to the ftpd after a while, except this time I can still connect, just not transfer anything. Upload, download, fxp to and from, from any type of daemon at the other side.

When issuing 'site crashnow' it does nothing other than write an entry in ioftpd.log (I could log in just fine in a new session)

When I attached windbg, io stopped accepting connections. However, once detached, io accepted connections again, but not a single transfer goes through.

Only upside to this is that I got a new dump for you..

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

I don't know what to say pion. I'm hoping someone like Silly will report whether 7.4.3 is stable or not for them as it clearly wasn't before, but the other reports I'm getting are all "stable" votes. The only downside so far is SSL traffic from some sites is having issues and I think I figured out how to fix that by enabling the bug workarounds and turning off SSL tickets. Bigstar and FlashFXP seems to have run into the ticket issue with the newer OpenSSL builds and older java SSL libraries as well so I'm pretty sure that will fix the issue.

Is there anything else in common on these systems that isn't standard? Common firewall? I'll take a look again at the loaded modules from the dumps you sent me, but I didn't notice anything weird the first time I looked. I.e. netlimiter, nvidia firewall, nod32's internet module (v3, I think v4 is ok), etc. All of those are known issues... It looked like nxmydb or the libmysql library it used were the likely suspect but if you've removed reference to them then you got me... I'll keep looking, but shy of the next round of changes coming which I don't expect to do much I'm running out of things to try.

Oh, and remember to make sure you have enough worker threads. I can't say for sure that rare cases don't crop up if worker threads exit. There aren't any I'm aware of, but the fact that I had to fix one in the past means there could be more.

monk- · 05-05-2010, 01:43 AM

Quote:

Originally Posted by Yil

First, I'm curious about that "SITE XDUPE" line. Do you have an addon for that? I was surprised to see the command was accepted...

ioPRECHECK, it supports XDUPE, an odog script, discontinued, though theres nothing to fix

plz dont give up on that lockup bug
(10:04:04) [io703] 426 Connection closed: The specified network name is no longer available.
(10:18:38) [io745] STAT -l
(10:18:38) [io745] List Complete: 4*405 bytes in 0,11 seconds (40,05KB/s)
u can see that stat -l is still transfering, so its prolly not a winsock or ssl problem

pion · 05-05-2010, 02:57 AM

I can also add, that while in this state, transfers without ssl is giving the exact same behaviour when I'm connecting to a new session. In fact, when transferring without ssl it crashed just the same!! And it doesn't last too long either, 1 hour or less in some cases. (like the case without ssl)

*Edit: The excact same behaviour also present with encryption disabled alltogether.

And as usual, just restarting the process fixes the problem.

Yil · 05-05-2010, 11:48 PM

I've been looking over the code and found a potential issue with aborting in-use connections which might explain why some people have a bigger issue than others. It also depends upon how graceful closesocket is which might vary upon the windows release so win2k3 vs XP might act differently...

Give me a few days to wrap up all the OpenSSL changes and a few other things and we'll see if 7.5 doesn't do the trick