Control connection timeout causes 100% CPU usage

[johnstruse]

We have been scanning our FTP servers with Nessus and frequently after a batch of scans have been run, the FTP server will be using 100% on Linux. An strace reveals that it is very rapidly attempting to poll one or more sockets (depending on how many are stuck).

epoll_wait(6, [{EPOLLOUT, {u32=25, u64=3426317835490557977}}], 1023, 100) = 1
read(25, 0x2802ba3, 5)                  = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(6, [{EPOLLOUT, {u32=25, u64=3426317835490557977}}], 1023, 100) = 1
read(25, 0x2802ba3, 5)                  = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(6, [{EPOLLOUT, {u32=25, u64=3426317835490557977}}], 1023, 100) = 1
read(25, 0x2802ba3, 5)   

# netstat -apn | grep 16458
tcp        0      0 127.0.0.1:21            0.0.0.0:*               LISTEN      16458/ftpd_linux.
tcp        0      0 xxx.xxx.xxx.xxx:21        0.0.0.0:*               LISTEN      16458/ftpd_linux.
tcp        0      0 xxx.xxx.xxx.xxx:21        yyy.yyy.yyy.yyy:38968   ESTABLISHED 16458/ftpd_linux.

In the FTPD logs, all other connections by yyy.yyy.yyy.yyy show that they were opened and closed successfully, however port 38968 shows an opened connection and then a timeout, but the socket never closed.

2017-07-15 17:26:02,840 pyftpdlib    INFO     yyy.yyy.yyy.yyy:38968-[] FTP session opened (connect)
2017-07-15 17:31:03,051 pyftpdlib    INFO     yyy.yyy.yyy.yyy:38968-[] Control connection timed out.

On yyy.yyy.yyy.yyy, a quick netstat shows that the socket is not open on that end any longer.

[giampaolo]

Sorry for the big delay in responding. Was there any progress about this? You can try running the server with DEBUG logging enabled:

    from pyftpdlib.log import config_logging
    config_logging(level=logging.DEBUG)

Hopefully that may give some hints about what syscall the busy loop keeps calling. It should be either send() or recv() failing with a certain error code.

[thiagolinhares]

Hi there, I've got a similar (maybe the same) issue here. DEBUG logging led me to TLS implementation error. So far I've disabled TLS_FTPHandler and I'm using only FTPHandler. This fixed this loop Also noticed that the bug/error is reproducible when editing a file between a ~60 sec interval.

This is the log when the issue occurs: (fake user and IP for privacy)

DEBUG:pyftpdlib:refreshing tasks (2 join() potentials) DEBUG:pyftpdlib:[debug] call: recv(), err: SysCallError(-1, 'Unexpected EOF') (<LWFTPHandler(id=139969512712568, addr='1.2.3.4:57286', ssl=True, user='user123')>) DEBUG:pyftpdlib:[debug] call: _do_ssl_shutdown() -> shutdown(), err: Error([('SSL routines', '', 'shutdown while in init')],) (<LWFTPHandler(id=139969512712568, addr='1.2.3.4:57286', ssl=True, user='user123')>)

[hakai]

I had the same issue and it's apparently related to multiple inheritance of TLS_FTPHandler from both SSLConnection and FTPHandler. During calls to the close() method, only SSLConnection.close() is executed, the missing call to FTPHandler.close() then causes the issue.

See pull request #613