High CPU usage with a user that stay logged for a long time

[Gabriele]

Hi,

I'm using Filezilla Server 0.9.41beta on Windows Server 2003 up-to-date

I'm having the following issue with a client that daily send me some text files.
The transfer ends up correctly (I see the line "Transfer OK" in the log") but the user does not log out (or does not log out properly).
I can sometimes see the line "disconnected" but the user seems to remain logged in (I cannot see any other login attempt so I presume that disconnection has not happened correctly).

Coming back after some time one core of the CPU is completely occupied by Filezilla process (with only the problematic user logged in), until I manually kicked off the user.

The following day it may happen again, having the user logged in twice, with two cores completely occupied by Filezilla.

Since this is a 2 core machine, CPU is completely stuck.
What is worse is that other file tranfer by other client are sometimes paused (or proceed very slowly) until kicking off the users.

To be noted that I have about 30 clients that send me daily text files and all works fine (and have always worked fine from a lot of months) with all of them.
There is exactly one problematic user and he/she was always problematic

Server timeouts are quite standard:

Connection timeout: 9999
No Transfer timeout: 600
Login timeout: 60

Is anyone seeing this strange behaviour?

These are the lines of the problematic sessions (with anonymized IP, username and password).
Nothing very strange here but some info on FTP client and connection options

(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> Connected, sending welcome message...
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> FEAT
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> 211-Features:
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  MDTM
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  REST STREAM
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  SIZE
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  MLST type*;size*;modify*;
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  MLSD
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  UTF8
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  CLNT
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)>  MFMT
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> 211 End
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> CLNT lftp/3.7.11
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> 200 Don't care
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> OPTS UTF8 ON
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> 530 Please log in with USER and PASS first.
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> USER problematic_user
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> 331 Password required for problematic_user
(004878) 19/07/2013 13.50.04 - (not logged in) (xx.yy.zz.tt)> PASS xxxx
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> 230 Logged on
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> CLNT lftp/3.7.11
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> 200 Don't care
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> OPTS UTF8 ON
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> 200 UTF8 mode enabled
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> PWD
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> 257 "/" is current directory.
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> PASV
(004878) 19/07/2013 13.50.04 - problematic_user (xx.yy.zz.tt)> 227 Entering Passive Mode (aa,bb,cc,dd,15,27)
(004878) 19/07/2013 13.50.05 - problematic_user (xx.yy.zz.tt)> ALLO 662581
(004878) 19/07/2013 13.50.05 - problematic_user (xx.yy.zz.tt)> 202 No storage allocation neccessary.
(004878) 19/07/2013 13.50.05 - problematic_user (xx.yy.zz.tt)> STOR file1.txt
(004878) 19/07/2013 13.50.05 - problematic_user (xx.yy.zz.tt)> 150 Connection accepted
(004878) 19/07/2013 13.50.06 - problematic_user (xx.yy.zz.tt)> 226 Transfer OK
(004878) 19/07/2013 13.50.07 - problematic_user (xx.yy.zz.tt)> PASV
(004878) 19/07/2013 13.50.07 - problematic_user (xx.yy.zz.tt)> 227 Entering Passive Mode (aa,bb,cc,dd,15,28)
(004878) 19/07/2013 13.50.07 - problematic_user (xx.yy.zz.tt)> STOR file2.txt
(004878) 19/07/2013 13.50.07 - problematic_user (xx.yy.zz.tt)> 150 Connection accepted
(004878) 19/07/2013 13.50.08 - problematic_user (xx.yy.zz.tt)> 226 Transfer OK
(004878) 19/07/2013 13.50.08 - problematic_user (xx.yy.zz.tt)> PASV
(004878) 19/07/2013 13.50.08 - problematic_user (xx.yy.zz.tt)> 227 Entering Passive Mode (aa,bb,cc,dd,15,29)
(004878) 19/07/2013 13.50.08 - problematic_user (xx.yy.zz.tt)> STOR file3.txt
(004878) 19/07/2013 13.50.08 - problematic_user (xx.yy.zz.tt)> 150 Connection accepted
(004878) 19/07/2013 13.50.10 - problematic_user (xx.yy.zz.tt)> 226 Transfer OK
(004878) 19/07/2013 13.50.10 - problematic_user (xx.yy.zz.tt)> PASV
(004878) 19/07/2013 13.50.10 - problematic_user (xx.yy.zz.tt)> 227 Entering Passive Mode (aa,bb,cc,dd,15,30)
(004878) 19/07/2013 13.50.10 - problematic_user (xx.yy.zz.tt)> STOR file4.txt
(004878) 19/07/2013 13.50.10 - problematic_user (xx.yy.zz.tt)> 150 Connection accepted
(004878) 19/07/2013 13.50.11 - problematic_user (xx.yy.zz.tt)> 226 Transfer OK
(004878) 19/07/2013 13.50.11 - problematic_user (xx.yy.zz.tt)> PASV
(004878) 19/07/2013 13.50.11 - problematic_user (xx.yy.zz.tt)> 227 Entering Passive Mode (aa,bb,cc,dd,15,31)
(004878) 19/07/2013 13.50.11 - problematic_user (xx.yy.zz.tt)> STOR file5.txt
(004878) 19/07/2013 13.50.11 - problematic_user (xx.yy.zz.tt)> 150 Connection accepted
(004878) 19/07/2013 13.50.13 - problematic_user (xx.yy.zz.tt)> 226 Transfer OK
(004878) 19/07/2013 13.50.13 - problematic_user (xx.yy.zz.tt)> PASV
(004878) 19/07/2013 13.50.13 - problematic_user (xx.yy.zz.tt)> 227 Entering Passive Mode (aa,bb,cc,dd,15,35)
(004878) 19/07/2013 13.50.13 - problematic_user (xx.yy.zz.tt)> STOR file6.txt
(004878) 19/07/2013 13.50.13 - problematic_user (xx.yy.zz.tt)> 150 Connection accepted
(004878) 19/07/2013 13.50.14 - problematic_user (xx.yy.zz.tt)> 226 Transfer OK
(004878) 19/07/2013 13.50.14 - problematic_user (xx.yy.zz.tt)> QUIT
(004878) 19/07/2013 13.50.14 - problematic_user (xx.yy.zz.tt)> 221 Goodbye
(004878) 19/07/2013 13.50.14 - problematic_user (xx.yy.zz.tt)> disconnected.

I would happily provide more info if needed since this problem requires me manual intervention so it's quite annoying.

[Gabriele]

The following is a problematic debug session.
Even if there is quit command, it doesn't really quit.

Client is lftp in a quite old versione, 3.7.11.

I've made some tests from LAN and I was not able to reproduce the problem, nor with lftp 4.3.8 nor compiling 3.7.11.

# lftp -e "debug 20; mput -a *.txt;bye" -u USER,PASSWORD host
FileCopy(0x8184238) enters state INITIAL    
FileCopy(0x8184238) enters state DO_COPY
---- dns cache hit                           
---- Connecting to host (XX.XX.XX.XX) port 21
<--- 227 Entering Passive Mode (XX.XX.XX.XX,8,201)                     
---- Connessione del socket dei dati a (XX.XX.XX.XX) porta 2249 (in english, connecting data socket to (XX.XX.XX.XX) port 2249)
---- Data connection established                                          
---> ALLO 662581

<--- 202 No storage allocation neccessary.                                
---> STOR file1.txt
<--- 150 Connection accepted                                              
copy: get hit eof                                                       
copy: waiting for put confirmation
FileCopy(0x8184238) enters state CONFIRM_WAIT

---- Chiusura del socket dati (in english, closing data socket)                                       
<--- 226 Transfer OK                                                                     
copy: put confirmed store
FileCopy(0x8184238) enters state GET_DONE_WAIT

copy: get is finished - all done
FileCopy(0x8184238) enters state ALL_DONE
FileCopy(0x81b35b0) enters state INITIAL
FileCopy(0x81b35b0) enters state DO_COPY
---> PASV                                      
<--- 227 Entering Passive Mode (XX.XX.XX.XX,8,202)                       
---- Connessione del socket dei dati a (XX.XX.XX.XX) porta 2250
---- Data connection established                                            
---> STOR file2.txt
<--- 150 Connection accepted                                                
copy: get hit eof                                                       
copy: waiting for put confirmation
FileCopy(0x81b35b0) enters state CONFIRM_WAIT

---- Chiusura del socket dati (in english, closing data socket)                                 
<--- 226 Transfer OK                                                              
copy: put confirmed store
FileCopy(0x81b35b0) enters state GET_DONE_WAIT

copy: get is finished - all done
FileCopy(0x81b35b0) enters state ALL_DONE
FileCopy(0x81b0f78) enters state INITIAL
FileCopy(0x81b0f78) enters state DO_COPY
---> PASV                                    
<--- 227 Entering Passive Mode (XX.XX.XX.XX,8,203)                     
---- Connessione del socket dei dati a (XX.XX.XX.XX) porta 2251
---- Data connection established                                          
---> STOR 20130619.persone.txt
<--- 150 Connection accepted                                              
copy: get hit eof                                                       
copy: waiting for put confirmation
FileCopy(0x81b0f78) enters state CONFIRM_WAIT

---- Chiusura del socket dati (in english, closing data socket)                                              
<--- 226 Transfer OK                                                                     
copy: put confirmed store
FileCopy(0x81b0f78) enters state GET_DONE_WAIT

copy: get is finished - all done
FileCopy(0x81b0f78) enters state ALL_DONE
FileCopy(0x8181f28) enters state INITIAL
FileCopy(0x8181f28) enters state DO_COPY
---> PASV                                      
<--- 227 Entering Passive Mode (XX.XX.XX.XX,8,208)                       
---- Connessione del socket dei dati a (XX.XX.XX.XX) porta 2256
---- Data connection established                                            
---> STOR file3.txt
<--- 150 Connection accepted                                                
copy: get hit eof                                                       
copy: waiting for put confirmation
FileCopy(0x8181f28) enters state CONFIRM_WAIT

---- Chiusura del socket dati (in english, closing data socket)                                    
<--- 226 Transfer OK                                                                      
copy: put confirmed store
FileCopy(0x8181f28) enters state GET_DONE_WAIT

copy: get is finished - all done
FileCopy(0x8181f28) enters state ALL_DONE
1967134 bytes transferred in 11 seconds (169.6K/s)

Trasferiti 4 file in totale (in english, 4 files transferred)
---> QUIT
---- Chiusura del socket di controllo (in english, closing control socket)

[Tim Kosse]

Do you have a speed limit set?

[Tim Kosse]

Please try FileZilla Server 0.9.42

[Gabriele]

Unfortunately the problem still happened with 0.9.42.

The server has speed limits, while there is no per-user o per-group speed limit for the problematic user (that is the only user of its group).

I'll attach one session with 0.9.42 and an anonymized version of Filezilla Server.xml.
The user apparently did not issue the QUIT command or did not issue it correctly.
My client assured me that his script does indeed issue QUIT and the client seems to detach correctly.

Now in the console, the user seems to be yet logged on the server and one core of the CPU is stuck at 100%.

I have also quite default timeouts settings.

The problematic user in Filezilla Server.xml is named PROBLEMATIC_USER, its group is named PROBLEMATIC_GROUP. Settings for them are quite standard

[Gabriele]

Session of the problematic user in version 0.9.42

[Gabriele]

Anonymized Filezilla Server configuration xml

[Tim Kosse]

This should be fixed in the most recent version. Please test the most recent version.

[Gabriele]

I'm the original reporter.
Just to confirm that the problem with my problematic user seems fixed in version 0.9.43 (last version I can use since I'm on Windows Server 2003).
Thanks for your work.