/ Bug 3131 – Session process uses 100% CPU after aborted transfer
Bug 3131 - Session process uses 100% CPU after aborted transfer
: Session process uses 100% CPU after aborted transfer
Status: CLOSED FIXED
Product: ProFTPD
core
: 1.3.2rc1
: All All
: P2 normal
Assigned To: proftpd development group
:
:
:
:
  Show dependency treegraph
 
Reported: 2008-11-11 15:06 UTC by Konstantin Falkov
Modified: 2008-11-21 00:58 UTC (History)
0 users (show)

See Also:


Attachments
Adds handling of Telnet IP, DM codes (4.13 KB, patch)
2008-11-13 00:49 UTC, TJ Saunders
Details
Updates previous patch to explicitly check for aborted downloads in pr_data_xfer() (5.33 KB, patch)
2008-11-13 17:04 UTC, TJ Saunders
Details
Updates previous patch (5.42 KB, patch)
2008-11-13 19:43 UTC, TJ Saunders
Details
Updates previous patch (5.83 KB, patch)
2008-11-14 13:50 UTC, TJ Saunders
Details
Updates previous patch (6.11 KB, patch)
2008-11-14 17:32 UTC, TJ Saunders
Details
Updates previous patch (9.57 KB, patch)
2008-11-14 20:20 UTC, TJ Saunders
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Falkov 2008-11-11 15:06:00 UTC
proftpd session process rises to 100% cpu after ABOR command while downloading.

ftpsrv# proftpd -v
ProFTPD Version 1.3.2rc3
ftpsrv# uname -a
FreeBSD ftpsrv 7.1-PRERELEASE FreeBSD 7.1-PRERELEASE #1: Tue Nov 11 10:29:42
MSK
 2008     root@ftpsrv:/usr/src/sys/amd64/compile/INFY_FTP  amd64

Nov 11 19:30:00 ftpsrv proftpd[1899] ftpsrv (192.168.159.82[192.168.159.82]):
FT
P session opened.
Nov 11 19:30:00 ftpsrv proftpd[1899] ftpsrv (192.168.159.82[192.168.159.82]):
Pr
eparing to chroot to directory '/pub/ftproot'
Nov 11 19:30:00 ftpsrv proftpd[1899] ftpsrv (192.168.159.82[192.168.159.82]):
AN
ON ftp: Login successful.
Nov 11 19:30:49 ftpsrv proftpd[1899] ftpsrv (192.168.159.82[192.168.159.82]):
no
tice: user ftp: aborting transfer: No such file or directory

pid 1899 (proftpd), uid 1001, was killed: exceeded maximum CPU limit
Comment 1 TJ Saunders 2008-11-11 16:10:05 UTC
Could you provide your full proftpd.conf, and the output from running `proftpd
-V' and `proftpd -l', please?
Comment 2 Konstantin Falkov 2008-11-11 17:15:40 UTC
ftpsrv# proftpd -V
Compile-time Settings:
  Version: 1.3.2rc3
  Platform: FREEBSD7 (FREEBSD7_1)
  Built With:
    configure  '--localstatedir=/var/run' '--sysconfdir=/usr/local/etc'
'--disab
le-sendfile' '--disable-ipv6' '--enable-nls'
'--with-includes=:/usr/local/includ
e' '--with-libraries=:/usr/local/lib' '--prefix=/usr/local'
'--mandir=/usr/local
/man' '--infodir=/usr/local/info/' '--build=amd64-portbld-freebsd7.1'
'build_ali
as=amd64-portbld-freebsd7.1' 'CC=cc' 'CFLAGS=-O2 -fno-strict-aliasing -pipe'
'LI
BS=-lintl -L/usr/local/lib' 'CXX=c++' 'CXXFLAGS=-O2 -fno-strict-aliasing -pipe'

  CFLAGS: -O2 -fno-strict-aliasing -pipe -Wall
  LDFLAGS: -L$(top_srcdir)/lib
  LIBS: -lintl  -lpam -lsupp -lcrypt -lintl -L/usr/local/lib -lutil

  Files:
    Configuration File:
      /usr/local/etc/proftpd.conf
    Pid File:
      /var/run/proftpd.pid
    Scoreboard File:
      /var/run/proftpd/proftpd.scoreboard

  Features:
    - Autoshadow support
    - Controls support
    + curses support
    - Developer support
    - DSO support
    - IPv6 support
    + Largefile support
    - Lastlog support
    + ncurses support
    + NLS support
    - OpenSSL support
    - POSIX ACL support
    - Shadow file suppport
    - Sendfile support
    + Trace support

  Tunable Options:
    PR_TUNABLE_BUFFER_SIZE = 1024
    PR_TUNABLE_GLOBBING_MAX = 8
    PR_TUNABLE_HASH_TABLE_SIZE = 40
    PR_TUNABLE_NEW_POOL_SIZE = 512
    PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
    PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
    PR_TUNABLE_SELECT_TIMEOUT = 30
    PR_TUNABLE_TIMEOUTIDENT = 10
    PR_TUNABLE_TIMEOUTIDLE = 600
    PR_TUNABLE_TIMEOUTLINGER = 180
    PR_TUNABLE_TIMEOUTLOGIN = 300
    PR_TUNABLE_TIMEOUTNOXFER = 300
    PR_TUNABLE_TIMEOUTSTALLED = 3600
    PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10

ftpsrv# proftpd -l
Compiled-in modules:
  mod_core.c
  mod_xfer.c
  mod_auth_unix.c
  mod_auth_file.c
  mod_auth.c
  mod_ls.c
  mod_log.c
  mod_site.c
  mod_delay.c
  mod_facts.c
  mod_ident.c
  mod_auth_pam.c
  mod_lang.c
Comment 3 Konstantin Falkov 2008-11-11 17:20:11 UTC
# Infinity.Net ProFTPd config

ServerName                      "Infinity.Net FTP server"
ServerType                      standalone
DefaultServer                   on
Port                            21
#UseIPv6                                off
Umask                           022
SystemLog                       /var/log/proftpd/proftpd.log
#SyslogLevel                    debug
TransferLog                     /var/log/proftpd/transfer.log
WtmpLog                         off
MaxInstances                    30
#MaxClientsPerHost              1
MaxTransfersPerHost             RETR,APPE,STOR 1
RLimitCPU                       session 10 10
IdentLookups                    off
ServerIdent                     on "Infinity FTP server ready."
PassivePorts                    59152 65534
UseEncoding                     koi8-r cp1251
UseReverseDNS                   no
TimeoutLinger                   30
User                            nobody
Group                           nogroup
DefaultRoot                     ~
AllowOverwrite                  on
AllowStoreRestart               on
AllowRetrieveRestart            on

<Limit SITE_CHMOD>
  DenyAll
</Limit>

<Class glnet>
 From 172.28.65.0/24
</Class>
<Class baza>
    From 172.16.100.0/22
</Class>
<Class visp>
    From 10.0.0.0/8
</Class>
<Class infy>
    From 192.168.128.0/19
</Class>
<Class tnet>
    From 192.168.224.0/19
</Class>
<Class voce>
    From 192.168.192.0/19
</Class>
<Class comtel>
    From 172.16.128.0/21
</Class>
<Class default>
    From 0.0.0.0/0
</Class>

TransferRate STOR,APPE,RETR 400 class glnet
TransferRate STOR,APPE,RETR 2048 class visp
TransferRate STOR,APPE,RETR 5120 class voce
TransferRate STOR,APPE,RETR 5120 class infy
TransferRate STOR,APPE,RETR 1024 class baza
TransferRate STOR,APPE,RETR 2048 class tnet
TransferRate STOR,APPE,RETR 5120 class comtel
TransferRate STOR,APPE,RETR 512 class default

<Anonymous /pub/ftproot>
  User                          ftp
  Group                         ftp
  RequireValidShell             off
  UserAlias                     anonymous ftp
  MaxClients                    30
  #DisplayLogin                 welcome.msg
  #DisplayChdir                 .message
  <Limit WRITE>
    DenyAll
  </Limit>

  <Directory games/!New>
    <Limit STOR APPE MKD XMKD>
        AllowClass infy voce
    </Limit>
  </Directory>

  <Directory soft/!New>
    <Limit STOR APPE MKD XMKD>
        AllowClass infy voce
    </Limit>
  </Directory>

  <Directory video/!New>
    <Limit STOR APPE MKD XMKD>
        AllowClass infy voce
    </Limit>
  </Directory>

  <Directory music/!New>
    <Limit STOR APPE MKD XMKD>
        AllowClass infy voce
    </Limit>
  </Directory>

</Anonymous>
Comment 4 TJ Saunders 2008-11-12 13:03:38 UTC
Hmm.  While I try to reproduce this issue locally, could you add the following
to your proftpd.conf, and send me the generated file from such an abort?

  TraceLog /path/to/trace.log
  Trace DEFAULT:10
Comment 5 Konstantin Falkov 2008-11-12 13:53:53 UTC
done.
Comment 6 TJ Saunders 2008-11-12 19:26:42 UTC
What happens if you comment out the UseEncoding directive from your
proftpd.conf?
Comment 7 TJ Saunders 2008-11-13 00:49:25 UTC
Created attachment 2899 [details]
Adds handling of Telnet IP, DM codes

One thing I noticed in the provided trace logs was that some of the Telnet
codes used for aborts (as per RFC) were showing up in the buffer of control
connection command data.  This shouldn't happen.

Specifically, the IAC ("Interpret As Command", value 255/FF), IP ("Interrupt
Process, value 244/F4) and DM ("Data Mark", value 242/F2) were showing up.  The
other Telnet codes that proftpd implements are properly filtered out of that
command buffer.  This patch, then, adds handling of the IP and DM codes,
filtering them out as well.

The reason I asked about the UseEncoding directive is that, depending on the
charsets requested with that directive, proftpd will NOT handle Telnet codes --
this is especially the case for several common Cyrillic charsets which use a
value of 255 to mean something else (other than the Telnet IAC code).

Anyway, please try this patch and see what happens, both with and without the
UseEncoding directive.
Comment 8 Konstantin Falkov 2008-11-13 02:15:15 UTC
Tryed this patch with several settings:
#UseEncoding
#TimeoutLinger 
-> binary mode download abort: session process hangs but does not use 100% cpu,
client waits about 30 sec and then says timeout and control connection breaks.
-> ASCII mode download abort: session process hangs and uses 100$ cpu, clients
waits about 5 sec and says that remote closed control connection.

#UseEncoding
TimeoutLinger 1
-> binary mode download abort: client wait 1 sec after abort and then work
fine, control connection doesnt breaks.
-> ASCII mode download abort: session process hangs and uses 100$ cpu, clients
waits about 5 sec and says that remote closed control connection.

UseEncoding koi8-r cp1251
TimeoutLinger 1
-> binary mode download abort: session process hangs and uses 100$ cpu, clients
waits about 15 sec(unix console ftp client) and says that remote closed control
connection.
-> ASCII mode download abort: session process hangs and uses 100$ cpu, clients
waits about 5 sec(vista console ftp client) and says that remote closed control
connection.
->Upload abort works fine.
Comment 9 TJ Saunders 2008-11-13 17:04:18 UTC
Created attachment 2900 [details]
Updates previous patch to explicitly check for aborted downloads in
pr_data_xfer()

This patch updates the previous one, and adds an explicit check in the
pr_data_xfer() function for an aborted transfer.  From a process trace I saw,
there looked to be an edge case where proftpd could get caught in a tight loop
calling select(2), over and over, not writing any data but not knowing to stop
polling.

This should help in all of the aborted download cases, whether or not it's an
ASCII or binary download.

It sounds like aborted uploads, ASCII or binary, don't cause the CPU usage
spike?
Comment 10 Konstantin Falkov 2008-11-13 17:38:38 UTC
I've applyed new patch and problem looks like not solved for me =( Uploads
still ok.
Comment 11 TJ Saunders 2008-11-13 19:43:18 UTC
Created attachment 2901 [details]
Updates previous patch

This patch adds one more check for the 'aborted' flag, in a place where it
looks like the CPU spinning *might* be happening.  I can't reproduce the CPU
usage spike, though, so I'll have to keep supplying patches for trials, for
now.
Comment 12 Konstantin Falkov 2008-11-14 01:00:48 UTC
with last patch there are no such cpu spike on abort! but control connection
still didnt reply after abort =(

ftpsrv# ftp
ftp> open localhost
Trying ::1...
Trying 127.0.0.1...
Connected to localhost.
220 Infinity FTP server ready.
Name (localhost:root): ftp
331 Anonymous login ok, send your complete email address as your password
Password:
230 Anonymous access granted, restrictions apply
Remote system type is UNIX.
Using binary mode to transfer files.
ftp> get 100M
local: 100M remote: 100M
229 Entering Extended Passive Mode (|||62768|)
150 Opening BINARY mode data connection for 100M (104857600 bytes)
  1% |                                     |  1568 KB  519.99 KB/s    03:13
ETA^
C
receive aborted. Waiting for remote to finish abort.
426 Transfer aborted. Data connection closed.
^C
421 Service not available, user interrupt. Connection closed.
1966080 bytes received in 00:41 (45.71 KB/s)
Comment 13 Konstantin Falkov 2008-11-14 01:29:47 UTC
And what with SIGABRT message spam? This issue linked with aborting of transfer
too but I can reproduce it only using FTP Drive program...

Nov 14 09:23:04 ftpsrv proftpd[67737]: ftpsrv (192.168.222.84[192.168.222.84])
- ProFTPD received SIGABRT signal, no core dump 
Nov 14 09:23:04 ftpsrv last message repeated 5541 times
Nov 14 09:23:04 ftpsrv proftpd[67753]: ftpsrv (192.168.222.84[192.168.222.84])
- notice: user ftp: aborting transfer: No such file or directory 
Nov 14 09:23:04 ftpsrv proftpd[67737]: ftpsrv (192.168.222.84[192.168.222.84])
- ProFTPD received SIGABRT signal, no core dump 
Nov 14 09:23:31 ftpsrv last message repeated 1052090 times
Comment 14 Konstantin Falkov 2008-11-14 01:48:17 UTC
Without UseEncoding download abort works perfect with last patch... Even
without TimeoutLinger 1
Comment 15 Konstantin Falkov 2008-11-14 02:47:02 UTC
SIGABRT occurs after several ABORTS in FTP Drive session i dont know how but
its control session doesnt breaks on abort with UseEncoding, all other clients
that i tryed(vista/freebsd console clients and Far Manager) cant do that.

Nov 14 10:26:39 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
ANON ftp: Login successful. 
Nov 14 10:26:39 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:26:39 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:26:40 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:26:41 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:26:48 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:26:49 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:26:51 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:35 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:35 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:35 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:36 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:39 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:42 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:42 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:43 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:44 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:45 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:45 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:27:48 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:48 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:27:49 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:29:49 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:29:50 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:29:50 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:29:56 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:29:56 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:29:57 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:01 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:02 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:33 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:34 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:34 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:34 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:36 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:36 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:37 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:38 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:40 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:40 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:43 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:43 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:44 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:45 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:45 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:46 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:48 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:48 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:48 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:49 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:50 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:52 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:54 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:54 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:54 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:56 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:56 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:56 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:58 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:58 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:30:59 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:30:59 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:31:00 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:31:01 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:31:02 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:31:02 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:31:03 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:31:04 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:31:05 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:31:08 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: No such file or directory 
Nov 14 10:31:08 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
notice: user ftp: aborting transfer: Data connection closed 
Nov 14 10:31:08 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
ProFTPD received SIGABRT signal, no core dump 
Nov 14 10:31:14 ftpsrv last message repeated 248180 times
Nov 14 10:31:14 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
ProFTPD received SIGABRT signal, no core dump 
Nov 14 10:31:16 ftpsrv last message repeated 70279 times
Nov 14 10:31:16 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
ProFTPD received SIGABRT signal, no core dump 
Nov 14 10:31:46 ftpsrv last message repeated 1194453 times
Nov 14 10:31:16 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
ProFTPD received SIGABRT signal, no core dump 
Nov 14 10:32:00 ftpsrv last message repeated 499978 times
Nov 14 10:32:00 ftpsrv proftpd[744]: ftpsrv (192.168.222.84[192.168.222.84]) -
ProFTPD received SIGABRT signal, no core dump 
Nov 14 10:32:14 ftpsrv last message repeated 539484 times

(dmesg)
pid 744 (proftpd), uid 1001: exited on signal 11
Comment 16 TJ Saunders 2008-11-14 10:19:58 UTC
There are several different bugs/issues involved in this case.

The patch supplied addresses two that have been found so far:

  1. The handling of certain Telnet codes (IP, DM) was missing
  2. A tightly spinning select() loop could happen in pr_netio_write() if a
     transfer was aborted -- this is now detected properly.

The remaining issues to track down are:

  3. Determine why the control connection might be closed/dropped for some
     aborted transfers.
  4. Determine why writing to the ScoreboardFile, for some sessions, leads to
     SIGABRT.
Comment 17 TJ Saunders 2008-11-14 13:50:53 UTC
Created attachment 2902 [details]
Updates previous patch

This version of the patch updates the previous one, and changes the check for
aborted transfers slightly.

Before, the CPU usage spike happened in pr_netio_write() because an aborted
transfer check resulted in an endless while loop.  The previous patch fixed
this by adding another aborted transfer check in pr_netio_write().  However,
this resulted in the case where the ABOR response was NOT being sent to the
client.  Clients would then wait and wait for this response, which would never
happen.  To fix this, the aborted transfer checks were moved, in
pr_netio_write(), to only be in the case where we're writing to the data stream
(used to be happening for writes to both control and data streams).
Comment 18 TJ Saunders 2008-11-14 14:33:43 UTC
I opened Bug#3132 to track the SIGABRT issue.
Comment 19 TJ Saunders 2008-11-14 17:32:40 UTC
Created attachment 2905 [details]
Updates previous patch

This patch fixes one additional complication which arises with aborted
transfers, when UseEncoding is in effect for Cyrillic charsets.  The
UseEncoding means that the Telnet abort bytes aren't filtered out of the
control connection; these bytes are usually followed by the string "ABOR" for
aborting a transfer.  This means that proftpd doesn't see an "ABOR" command, it
sees something like "????ABOR" (where each '?' is a Telnet control byte).

The ABOR command handler usually cleans up the data transfer state, including
clearing any 'aborted' flags.  But in this case, the ABOR handler is never
called.  Which means any data transfer which happens after the initlal abort
fails -- the 'aborted' flag is still set.  The fix, then, is to clear that flag
before any new data transfer.
Comment 20 Konstantin Falkov 2008-11-14 17:47:41 UTC
Now Midnight Commander/Far Manager aborts download perfecty. But vista/freebsd
console ftp clients still have controll connection timeout when you have
UseEncoding in proftpd config. Without this option they work as they should do.
Comment 21 TJ Saunders 2008-11-14 20:20:14 UTC
Created attachment 2906 [details]
Updates previous patch

Another update to the patch.  In this, I've added some checks to the response
code, so that any Telnet code sequences are stripped from response messages. 
(Hopefully this helps those clients which don't appear to handle Telnet codes
appearing in FTP response strings after an aborted transfer.)
Comment 22 Konstantin Falkov 2008-11-14 20:51:31 UTC
I just tested last and previous patches. vista/freebsd console clients still
cant abort download in proper way if we dont have TimeoutLinger 1 or so in
config, so responses fix dont matter for them. So with that option they abort
as intended even with previuos patch.
btw can 1 sec linger timeout drop transfer coz of some network/client lag?
meybe    its too low for usual setting =)
Thank you very much for fixing that annoying for me problem.
Comment 23 TJ Saunders 2008-11-14 20:57:54 UTC
Using a low TimeoutLinger value in your proftpd.conf is completely fine; you
could argue that the default timeout of 3 minutes, in the proftpd source code,
is too long.  So if using "TimeoutLinger 1" works for your Vista/FreeBSD
clients for aborting transfers, go with that.

I'll commit the previous patch (not the last one which filters the response
strings) to CVS, then mark this bug fixed.
Comment 24 TJ Saunders 2008-11-14 21:02:50 UTC
Patch (http://bugs.proftpd.org/attachment.cgi?id=2906&action=view) committed to
CVS.

Thanks for all of the help in tracking this down!
Comment 25 TJ Saunders 2008-11-21 00:58:28 UTC
Resolved in 1.3.2rc3.