Bug 757311

Summary: logrotate.d can't restart proftpd
Product: [Fedora] Fedora Reporter: customercare
Component: proftpdAssignee: Matthias Saou <matthias>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: unspecified    
Version: 15CC: matthias, paul
Target Milestone: ---   
Target Release: ---   
Hardware: i386   
OS: Linux   
Whiteboard:
Fixed In Version: proftpd-1.3.4a-5.fc15 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-03-08 21:22:08 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description customercare 2011-11-26 11:23:46 UTC
Description of problem:

The logrotate script for proftpd uses :

test -f /var/lock/subsys/proftpd && /usr/bin/killall -HUP proftpd || :

to reload the daemon. This does not work ( see below ) . The Systemd is not able to restart/reload proftpd this way. This may be caused by a bug in the proftpd init script as mentioned: 

"/var/run/proftpd/proftpd.pid does not exist"

The adhoc solution was to switch to a full proftpd restart in the logrotate script : 

test -f /var/lock/subsys/proftpd && /etc/init.d/proftpd try-restart || :

This works flawless now since one week. 


Version-Release number of selected component (if applicable):

1.3.4

How reproducible:

run logrotate and proftpd together
  
Actual results:

Nov 16 03:06:02 c1 proftpd[1441]: 83.246.67.243 - received SIGHUP -- master server reparsing configuration file
Nov 16 03:06:03 c1 systemd[1]: PID 1441 read from file /var/run/proftpd/proftpd.pid does not exist. Your service or init script might be broken.
Nov 16 03:06:03 c1 systemd[1]: proftpd.service: main process exited, code=exited, status=127  

Expected results:

a clean restart of proftpd after logrotate is done.


Here is the ADHOC FIX : 

# cat /etc/logrotate.d/proftpd
/var/log/proftpd/*.log /var/log/xferlog {
    compress
    missingok
    notifempty
    sharedscripts
    postrotate
        test -f /var/lock/subsys/proftpd && /etc/init.d/proftpd try-restart || :
    endscript
}

Comment 1 Paul Howarth 2011-11-28 09:45:25 UTC
I'm struggling to reproduce this. I've tried running "/usr/bin/killall -HUP proftpd" on a Fedora 15 VM and I get the "reparsing configuration file" message in the logs but it otherwise carries on as normal.

Regarding the ad-hoc fix, that particular change isn't good going forward as from Fedora 16 we're using a native systemd unit file and the SysV initscript is no longer shipped. I have a proftpd server running on F-16 and its logs are being rotated properly too.

Comment 2 customercare 2011-11-28 10:09:03 UTC
"I'm struggling to reproduce this. I've tried running "/usr/bin/killall -HUP
proftpd" on a Fedora 15 VM and I get the "reparsing configuration file" message
in the logs but it otherwise carries on as normal."

It was persistent for weeks until i changed the -HUP to the full restart.

I will check that on fc16 too soon. Can you set a reminder for this bug in... lets say 3 weeks ?

In the meantime, maybe this is helpful: 

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
/etc/proftpd.conf
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

ServerName                      "ProFTPD server"
ServerIdent                     on "FTP Server ready."
ServerAdmin                     root@localhost
ServerType                      standalone
DefaultServer                   on
AccessGrantMsg                  "User %u logged in."
DeferWelcome                    off
DefaultRoot                     ~ !adm

AuthPAMConfig                   proftpd
AuthOrder                       mod_sql.c mod_auth_pam.c mod_auth_unix.c

AllowOverwrite on
AllowRetrieveRestart on
AllowStoreRestart on

IdentLookups                    off
UseReverseDNS                   off
tcpNoDelay                      off

Port                            21
Umask                           022
ListOptions                     "-a"
AllowRetrieveRestart            on
AllowStoreRestart               on
MaxInstances                    20
User                            nobody
Group                           nobody
UseSendfile                     no
ScoreboardFile                  /var/run/proftpd.score
<Global>
  RootLogin                off
  AllowOverwrite                yes
  AuthPAM                       on
  <Limit ALL SITE_CHMOD>
    AllowAll
  </Limit>
</Global>

LogFormat                       default "%h %l %u %t \"%r\" %s %b"
LogFormat                       auth    "%v [%P] %h %t \"%r\" %s"

#debugLevel 10
Serverlog /var/log/proftpd/proftpd.log

#ExtendedLog /var/log/proftpd/auth_log AUTH auth
TransferLog /var/log/xferlog

<IfModule mod_dso.c>
  LoadModule mod_ban.c
  LoadModule mod_ifsession.c
  LoadModule mod_quotatab.c
  LoadModule mod_quotatab_file.c
  LoadModule mod_sql.c
  LoadModule mod_sql_mysql.c
</IfModule>
<IfModule mod_ban.c>
  BanEngine on
  BanLog /var/log/proftpd/ban.log
  BanTable /var/run/proftpd/ban.tab
  # If the same client reaches the MaxLoginAttempts limit 2 times
  # within 10 minutes, automatically add a ban for that client that
  # will expire after one hour.
  BanOnEvent MaxLoginAttempts 2/00:10:00 01:00:00
  # Allow the FTP admin to manually add/remove bans
  BanControlsACLs all allow user ftpadm
</IfModule>

RequireValidShell on

SQLAuthTypes Crypt
#SQLAuthenticate users usersetfast
SQLAuthenticate users
SQLConnectInfo ************************
SQLDefaultGID 65534
SQLDefaultUID 65534
SQLMinUserGID 100
SQLMinUserUID 500
SQLUserInfo proftpd_users username password uid gid homedir shell
#SQLGroupInfo proftpd_groups groupname gid members
SQLLog PASS counter
SQLNamedQuery counter UPDATE "letzter_zugriff=now(), count=count+1 WHERE username='%u'" proftpd_users
#SQLLOGFILE /var/log/proftpd/sql.log 


+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
/etc/init.d/proftpd 
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
#!/bin/sh
#
# Startup script for ProFTPD
#
# chkconfig: 2345 85 15
# description: ProFTPD is an enhanced FTP server with a focus towards \
#              simplicity, security, and ease of configuration. \
#              It features a very Apache-like configuration syntax, \
#              and a highly customizable server infrastructure, \
#              including support for multiple 'virtual' FTP servers, \
#              anonymous FTP, and permission-based directory visibility.
# processname: proftpd
# config: /etc/proftpd.conf
# pidfile: /var/run/proftpd/proftpd.pid

...
untampered from here
...

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
/var/run
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

# ls -la /var/run/ | grep proftp
drwxr-xr-x   2 root    root     120 27. Nov 03:36 proftpd
-rw-r--r--   1 root    root      16 27. Nov 03:36 proftpd.score
-rw-r--r--   1 root    root       0 27. Nov 03:36 proftpd.score.lck

# ls -la /var/run/proftpd
insgesamt 12
drwxr-xr-x  2 root root  120 27. Nov 03:36 .
drwxr-xr-x 26 root root  940 28. Nov 10:01 ..
-rw-r--r--  1 root root    0 15. Nov 19:43 ban.tab
-rw-r--r--  1 root root 6440 27. Nov 03:36 proftpd.delay
-rw-r--r--  1 root root    6 27. Nov 03:36 proftpd.pid
srwxrwxrwx  1 root root    0 27. Nov 03:36 proftpd.sock

Comment 3 Paul Howarth 2011-11-28 13:53:29 UTC
If you do the killall -HUP manually (or /etc/init.d/proftpd reload), does that kill the server?

Comment 4 customercare 2011-11-29 09:41:00 UTC
no, neither does work. Which isn't suprising, as "reload" just executes : "killproc proftpd -HUP" .

# pstree -up | grep proftpd
           |-proftpd(10772,nobody)
# killall -HUP proftpd
# pstree -up | grep proftpd
# /etc/init.d/proftpd start
Starting proftpd (via systemctl):                          [  OK  ]
# pstree -up | grep proftpd
# /etc/init.d/proftpd try-restart
Restarting proftpd (via systemctl):                        [  OK  ]
# pstree -up | grep proftpd
           |-proftpd(12856,nobody)
# /etc/init.d/proftpd reload
Reloading proftpd configuration (via systemctl):           [  OK  ]
# pstree -up | grep proftpd
#  /etc/init.d/proftpd try-restart
Restarting proftpd (via systemctl):                        [  OK  ]
[root@c1 rdt]# pstree -up | grep proftpd
           |-proftpd(12949,nobody)


proftpd.log is emtpy
debug.log is empty
only ban.log shows something:

Nov 29 10:30:30 mod_ban/0.6[12855]: obtained shmid 229376 for BanTable '/var/run/proftpd/ban.tab'
Nov 29 10:31:03 mod_ban/0.6[12948]: obtained shmid 229376 for BanTable '/var/run/proftpd/ban.tab'

Heres the /v/l/messages : 

Nov 29 10:29:54 c1 proftpd[10772]: 83.246.67.243 - received SIGHUP -- master server reparsing configuration file
Nov 29 10:29:54 c1 systemd[1]: PID 10772 read from file /var/run/proftpd/proftpd.pid does not exist. Your service or init script might be broken.
Nov 29 10:29:54 c1 systemd[1]: proftpd.service: main process exited, code=exited, status=127
Nov 29 10:30:30 c1 systemd[1]: Unit proftpd.service entered failed state.
Nov 29 10:30:30 c1 proftpd[12856]: 83.246.67.243 - ProFTPD 1.3.4 (stable) (built Thu Nov 10 2011 20:03:07 UTC) standalone mode STARTUP
Nov 29 10:30:56 c1 proftpd[12856]: 83.246.67.243 - received SIGHUP -- master server reparsing configuration file
Nov 29 10:30:56 c1 systemd[1]: PID 12856 read from file /var/run/proftpd/proftpd.pid does not exist. Your service or init script might be broken.
Nov 29 10:30:56 c1 systemd[1]: proftpd.service: main process exited, code=exited, status=127
Nov 29 10:31:03 c1 systemd[1]: Unit proftpd.service entered failed state.
Nov 29 10:31:03 c1 proftpd[12949]: 83.246.67.243 - ProFTPD 1.3.4 (stable) (built Thu Nov 10 2011 20:03:07 UTC) standalone mode STARTUP

I have watched /v/run/proftpd:

insgesamt 12
drwxr-xr-x  2 root root  120 29. Nov 10:31 .
drwxr-xr-x 26 root root  940 29. Nov 10:31 ..
-rw-r--r--  1 root root    0 15. Nov 19:43 ban.tab
-rw-r--r--  1 root root 6440 27. Nov 03:36 proftpd.delay
-rw-r--r--  1 root root    6 29. Nov 10:31 proftpd.pid
srwxrwxrwx  1 root root    0 29. Nov 10:31 proftpd.sock  

The PID file did not change, nor did it got removed. Systemds default message about the broken initscript may be true ;)

with the option try-restart , i get a new pid file ( as expected )

The proftpd guys should look into it.

Comment 5 Paul Howarth 2011-11-29 09:50:37 UTC
Yes, the HUP shouldn't be killing the server; that's the problem, rather than the initscript. I'll raise it upstream.

Comment 6 Paul Howarth 2011-12-02 14:27:10 UTC
Reported upstream: http://bugs.proftpd.org/show_bug.cgi?id=3724

Comment 7 Paul Howarth 2011-12-02 18:28:02 UTC
Would it be possible to get the SQLLogFile data as well, to see if perhaps
something in mod_sql/mod_sql_mysql doesn't like the restart?

Comment 8 customercare 2011-12-05 11:30:55 UTC
With this option: 

SQLLOGFILE /var/log/proftpd/sql.log

The SQL log is not filled with data on the startup try after a -HUP :

# ls -la /var/log/proftpd/sql.log
-rw-r----- 1 root root 0 23. Okt 03:31 /var/log/proftpd/sql.log

Comment 9 Fedora Update System 2012-02-28 22:20:14 UTC
proftpd-1.3.4a-5.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/proftpd-1.3.4a-5.fc15

Comment 10 Fedora Update System 2012-03-01 09:27:08 UTC
Package proftpd-1.3.4a-5.fc15:
* should fix your issue,
* was pushed to the Fedora 15 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing proftpd-1.3.4a-5.fc15'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-2735/proftpd-1.3.4a-5.fc15
then log in and leave karma (feedback).

Comment 11 Fedora Update System 2012-03-08 21:22:08 UTC
proftpd-1.3.4a-5.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.