Start a new topic

Random disconnects and crashes

Mhaynes @ Wed Jul 16 14:49:09 EEST 2014
Some quick background info: I just started managing the network at the company I work for and I'm not sure if these issues have been going on for a long time or not. All I know is they have been happening for at least 3 days. We are running version 7.1.0_14 and we had the same problem with the previous version we used; I think that was something like 7.0.2 maybe? I don't have that in front of me but I'm pretty sure it was one release prior to what we have now.

Ok, so here is what's going on. Every day at a random time the ftp server restarts with no warning. When I look at the log file I see normal traffic and then all of the sudden there is a gap of anywhere from a few seconds to 30 minutes or more and then a message that the started has restarted: CrushFTP Run message followed shortly by Server Started message. This seems to happen at least once a day and sometimes more than once.

The second issue is that our clients are getting disconnected at random times for no apparent reason. Sometimes they are able to log right back in and other times they cannot. One of the clients reported getting this message: "Server unexpectedly Closed connection".

Neither of these problems affect all clients and neither occurs all the time or at obvious times. It really seems like they are just random events with no indication of why. The log file has been set to log level 2 and I'm waiting to see if anything shows the next time a client indicates an issue. In the log file the only things that appear to be errors or are things I'm not sure about are the following messages:

java.lang.ClassNotFoundException: crushftp.server.ServerSession
java.io.IOException: Unable to establish loopback connection
UserBackupPurge:Folder has 100 user items, max is 100.

Those messages are not shown a lot and do not appear to be around the time of the failures.



Here is a small clipping of the log file around an apparently disconnect. I've taken out private info but just know that session 269 and 271 are the same client. I'm not sure what the 127.0.0.1 message are about. Any thoughts on those as well?

[code]
07/16/2014 11:21:58 AM|[SFTP:269:------] READ: *CWD ------*
07/16/2014 11:21:58 AM|[SFTP:269:------] READ: *LIST ------*
07/16/2014 11:22:03 AM|There are now 5 active connections
07/16/2014 11:22:57 AM|There are now 4 active connections
07/16/2014 11:22:58 AM|There are now 3 active connections
07/16/2014 11:27:53 AM|:127.0.0.1
07/16/2014 11:27:53 AM|:127.0.0.1
07/16/2014 11:27:53 AM|There are now 4 active connections
07/16/2014 11:27:53 AM|:127.0.0.1
07/16/2014 11:27:53 AM|There are now 5 active connections
07/16/2014 11:27:53 AM|:127.0.0.1
07/16/2014 11:27:53 AM|Client is attempting none authentication
07/16/2014 11:27:53 AM|Client is attempting keyboard-interactive authentication
07/16/2014 11:27:53 AM|[SFTP:lookup:22][271] Accepting connection from: ------
07/16/2014 11:27:53 AM|[SFTP:271:------] READ: *Verifying password for ------*
07/16/2014 11:27:53 AM|[SFTP:271:------] READ: *USER ------*
07/16/2014 11:27:53 AM|UserBackupPurge:Looking for old user folders to delete from here:./backup/
07/16/2014 11:27:53 AM|UserBackupPurge:Folder has 301 items.
07/16/2014 11:27:54 AM|UserBackupPurge:Folder has 100 user items, max is 100.
07/16/2014 11:27:54 AM|UserBackupPurge:Purging old backup users from:------
07/16/2014 11:27:54 AM|[SFTP:271:------] READ: *CONNECT ------*
[/code]

spinkb @ Wed Jul 16 15:29:00 EEST 2014
The 127.0.0.1 messages happen for all SFTP connections. They are normal.

These messages I want to see more details when why occur...

java.lang.ClassNotFoundException: crushftp.server.ServerSession
java.io.IOException: Unable to establish loopback connection

What OS is this?

If you look at the admin in CrushFTP, what is the memory usage like, number of threads like?

Thanks,
Ben
Mhaynes @ Wed Jul 16 15:33:02 EEST 2014
I'll get details on those messages in just a bit but can give you this info real quick:

OS: Windows server 2008 R2 standard
Memory usage: 340.4mb free, 111.6mb used
Threads: 12 free, 4 busy


spinkb @ Wed Jul 16 15:35:01 EEST 2014
I suggestion the service/wrapper.conf file, adjust the memory line to be 1024 or 2048.

Possibly there is something causing the server to run out of memory and stop working...then the wrapper restarts CrushFTP when it detects the server is down.

This would explain customers having strange issues too...

Thanks,
Ben
Mhaynes @ Wed Jul 16 15:37:07 EEST 2014
Details from around the errors:

[code]07/15/2014 05:30:00 PM|Initializing Secure Random Number Generator
07/15/2014 05:30:00 PM|Configuration complete.
07/15/2014 05:30:00 PM|ServerStatus:http_cleaner:
07/15/2014 05:30:00 PM|java.lang.ClassNotFoundException: crushftp.server.ServerSession
07/15/2014 05:30:00 PM|java.net.URLClassLoader$1.run:-1
07/15/2014 05:30:00 PM|java.security.AccessController.doPrivileged:-2
07/15/2014 05:30:00 PM|java.net.URLClassLoader.findClass:-1
07/15/2014 05:30:00 PM|java.lang.ClassLoader.loadClass:-1
07/15/2014 05:30:00 PM|java.net.FactoryURLClassLoader.loadClass:-1
07/15/2014 05:30:00 PM|java.lang.ClassLoader.loadClass:-1
07/15/2014 05:30:00 PM|java.lang.Class.forName0:-2
07/15/2014 05:30:00 PM|java.lang.Class.forName:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.resolveClass:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readNonProxyDesc:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readClassDesc:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readOrdinaryObject:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject0:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.defaultReadFields:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readSerialData:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readOrdinaryObject:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject0:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject:-1
07/15/2014 05:30:00 PM|java.util.Hashtable.readObject:-1
07/15/2014 05:30:00 PM|sun.reflect.GeneratedMethodAccessor3.invoke:-1
07/15/2014 05:30:00 PM|sun.reflect.DelegatingMethodAccessorImpl.invoke:-1
07/15/2014 05:30:00 PM|java.lang.reflect.Method.invoke:-1
07/15/2014 05:30:00 PM|java.io.ObjectStreamClass.invokeReadObject:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readSerialData:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readOrdinaryObject:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject0:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject:-1
07/15/2014 05:30:00 PM|java.util.Hashtable.readObject:-1
07/15/2014 05:30:00 PM|sun.reflect.GeneratedMethodAccessor3.invoke:-1
07/15/2014 05:30:00 PM|sun.reflect.DelegatingMethodAccessorImpl.invoke:-1
07/15/2014 05:30:00 PM|java.lang.reflect.Method.invoke:-1
07/15/2014 05:30:00 PM|java.io.ObjectStreamClass.invokeReadObject:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readSerialData:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readOrdinaryObject:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject0:-1
07/15/2014 05:30:00 PM|java.io.ObjectInputStream.readObject:-1
07/15/2014 05:30:00 PM|crushftp.handlers.SharedSession.init:42
07/15/2014 05:30:00 PM|crushftp.handlers.SharedSession.find:205
07/15/2014 05:30:00 PM|crushftp.server.ServerStatus.update_now:2399
07/15/2014 05:30:00 PM|crushftp.handlers.UpdateTimer.run:43
07/15/2014 05:30:00 PM|java.lang.Thread.run:-1
07/15/2014 05:30:00 PM|[HTTPS:1:lookup:4433] Accepting connection from:-------
07/15/2014 05:30:02 PM|[HTTPS:2:lookup:4433] Accepting connection from: -------
07/15/2014 05:30:08 PM|Server Memory Stats: Max=455.12 MB, Free=410.54 MB
07/15/2014 05:30:21 PM|main_server_thread:lookup:22
07/15/2014 05:30:21 PM|java.io.IOException: Unable to establish loopback connection
07/15/2014 05:30:21 PM|sun.nio.ch.PipeImpl$Initializer.run:-1
07/15/2014 05:30:21 PM|java.security.AccessController.doPrivileged:-2
07/15/2014 05:30:21 PM|sun.nio.ch.PipeImpl.:-1
07/15/2014 05:30:21 PM|sun.nio.ch.SelectorProviderImpl.openPipe:-1
07/15/2014 05:30:21 PM|java.nio.channels.Pipe.open:-1
07/15/2014 05:30:21 PM|sun.nio.ch.WindowsSelectorImpl.:-1
07/15/2014 05:30:21 PM|sun.nio.ch.WindowsSelectorProvider.openSelector:-1
07/15/2014 05:30:21 PM|com.maverick.nio.SelectorThread.A:-1
07/15/2014 05:30:21 PM|com.maverick.nio.SelectorThread.:-1
07/15/2014 05:30:21 PM|com.maverick.nio.SelectorThreadPool.A:-1
07/15/2014 05:30:21 PM|com.maverick.nio.SelectorThreadPool.:-1
07/15/2014 05:30:21 PM|com.maverick.nio.Daemon.startup:-1
07/15/2014 05:30:21 PM|crushftp.server.daemon.TCPServer.run:57
07/15/2014 05:30:21 PM|java.lang.Thread.run:-1
07/15/2014 05:30:21 PM|The server failed to start
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT performing final select to cancel all keys
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
07/15/2014 05:30:21 PM|SSHD-CONNECT completed final select
[/code]
spinkb @ Wed Jul 16 15:39:31 EEST 2014
This suggest some and data in your sessions.obj file.

When adjusting the server memory, stop the service, delete sessions.obj, and start the service.

Thanks,
Ben
Mhaynes @ Wed Jul 16 15:42:51 EEST 2014
Thanks for the suggestions Ben. I have set the memory to 2048 and removed the sessions.obj file and restarted. We will monitor for a couple of days and I'll post again whether we have additional issues or not.


Thanks again.
Login to post a comment