proftpd will not start with kernel 2.6.32-22-generic

[Graham T]

Binary package hint: proftpd-basic

Description: Ubuntu 10.04 LTS
Release: 10.04
2.6.32-22-generic
proftpd-basic (v 1.3.2c-1) from the repositories

On the current kernel 2.6.32-22-generic proftpd does not startup on system startup - in fact there is no mention of it in any logs, including the proftpd log files.

From Terminal I try a sudo proftpd and get this:

[CODE]
graham@gt-desktop:~$ sudo proftpd
 - notice: unable to bind to Unix domain socket at '/var/run/proftpd/test.sock': No such file or directory
 - notice: unable to listen to local socket: Operation not permitted
gt-desktop - 127.0.1.1:22122 masquerading as nn.nn.nn.nnn
gt-desktop - mod_delay/0.6: error opening DelayTable '/var/run/proftpd/proftpd.delay': No such file or directory
gt-desktop - notice: unable to listen to local socket: Operation not permitted
[/CODE]

If I boot into the previous kernel: 2.6.32-21-generic proftpd starts up fine on system startup and if I kill it then restart it I get:

[CODE]
graham@gt-desktop:~$ sudo proftpd
 - notice: unable to bind to Unix domain socket at '/var/run/proftpd/test.sock': No such file or directory
 - notice: unable to listen to local socket: Operation not permitted
gt-desktop - 127.0.1.1:21 masquerading as nn.nn.nn.nnn
[/CODE]... and it starts up fine.

The weird thing is, is that this did not break right after the kernel upgrade. It was working fine after that for a couple of days and several reboots on the new kernel.

The only thing that has changed between it working and not working is some updates I applied last night as recommended by the Update Manager:

[CODE]
Commit Log for Tue Jun 8 20:30:34 2010

Upgraded the following packages:
brasero (2.30.0-0ubuntu1) to 2.30.1-0ubuntu2
brasero-common (2.30.0-0ubuntu1) to 2.30.1-0ubuntu2
gnome-keyring (2.92.92.is.2.30.1-0ubuntu1) to 2.92.92.is.2.30.1-0ubuntu2
gnome-panel (1:2.30.0-0ubuntu1) to 1:2.30.0-0ubuntu2
gnome-panel-data (1:2.30.0-0ubuntu1) to 1:2.30.0-0ubuntu2
libbrasero-media0 (2.30.0-0ubuntu1) to 2.30.1-0ubuntu2
libcairomm-1.0-1 (1.8.0-1build2) to 1.8.4-0ubuntu1
libgcr0 (2.92.92.is.2.30.1-0ubuntu1) to 2.92.92.is.2.30.1-0ubuntu2
libgp11-0 (2.92.92.is.2.30.1-0ubuntu1) to 2.92.92.is.2.30.1-0ubuntu2
libpam-gnome-keyring (2.92.92.is.2.30.1-0ubuntu1) to 2.92.92.is.2.30.1-0ubuntu2
libpanel-applet2-0 (1:2.30.0-0ubuntu1) to 1:2.30.0-0ubuntu2
openoffice.org-base-core (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-calc (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-common (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-core (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-draw (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-emailmerge (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-gnome (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-gtk (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-impress (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-math (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-style-human (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
openoffice.org-writer (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
python-papyon (0.4.6-0ubuntu2) to 0.4.8-0ubuntu1
python-uno (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
rhythmbox (0.12.8-0ubuntu5) to 0.12.8-0ubuntu6
rhythmbox-plugin-cdrecorder (0.12.8-0ubuntu5) to 0.12.8-0ubuntu6
rhythmbox-plugins (0.12.8-0ubuntu5) to 0.12.8-0ubuntu6
telepathy-butterfly (0.5.8-1ubuntu1) to 0.5.9-0ubuntu1
ttf-opensymbol (1:3.2.0-7ubuntu4) to 1:3.2.0-7ubuntu4.1
tzdata (2010i-1) to 2010j-0ubuntu0.10.04
tzdata-java (2010i-1) to 2010j-0ubuntu0.10.04
uno-libs3 (1.6.0+OOo3.2.0-7ubuntu4) to 1.6.0+OOo3.2.0-7ubuntu4.1
ure (1.6.0+OOo3.2.0-7ubuntu4) to 1.6.0+OOo3.2.0-7ubuntu4.1
[/CODE]

Since rebooting after that set of updates, proftpd will not start up - seemingly with some kind of permissions problem... but I can't work out what. I have reinstalled the proftpd-basic package via Synaptic to no effect.

[Graham T (grahamt-manichostingservices)]

Attached my proftpd.conf file in case it is of any use.

Only thing I have changed is to mask out my public IP on the MasqueradeAddress line.

[Graham T (grahamt-manichostingservices)]

OK - things get even stranger.

proftpd stopped working on 2.6.32-21-generic as well after a reboot.

I checked again and the /var/run/proftpd directory had gone! I manually recreated it and proftpd started up cleanly.

However, following a reboot the /var/run/proftpd directory had gone missing again and proftpd failed to start up.

So actually this seems to be a problem with the /var/run/proftpd directory vanishing. proftpd will run fine on 2.6.32-22-generic as long as that directory is manually created after each reboot.

[Graham T (grahamt-manichostingservices)]

OK some thoughts... /var/run/proftpd contains:
proftpd.delay
proftpd.sock

all the time, even after the proftpd service is stopped.

On starting the proftpd service another file is created:
proftpd.scoreboard

On stopping the service:
proftpd.scoreboard is removed
proftpd.delay is altered in some way (the timestamp on the file changes)

Could it be that during shutdown, the proftpd service stops and tries to write its change to proftpd.delay but the system actually shuts down before the changes are fully committed to disk? i.e. a side-effect of the ext4 journalling??

[Graham T (grahamt-manichostingservices)]

After some more digging it looks like /etc/init.d/proftpd actually checks for the existence of /var/run/proftpd and creates it is it doesn't exist.

Near the top it has:

[code]
# /var/run could be on a tmpfs
[ ! -d /var/run/proftpd ] && mkdir /var/run/proftpd
[/code]

I am absolutely cack at shell scripting but that looked wrong to me so I tried these variants:

[code]
[ ! test -d /var/run/proftpd ] && mkdir /var/run/proftpd
[/code]

and

[code]
if ! test -d /var/run/proftpd; then
  mkdir /var/run/proftpd
fi
[/code]

And still the directory is not there following a reboot!

Any ideas welcome!

Thanks :D

[Graham T (grahamt-manichostingservices)]

OK... after startup and from a Terminal window, just calling the /etc/init.d/proftpd script creates the missing directory and starts the proftpd daemon fine!

[CODE]
graham@gt-desktop:~$ ls -l /var/run
total 44
-rw-r--r-- 1 root root 4 2010-06-12 00:54 acpid.pid
srw-rw-rw- 1 root root 0 2010-06-12 00:54 acpid.socket
-rw-r--r-- 1 root root 4 2010-06-12 00:54 atd.pid
drwxr-xr-x 2 avahi avahi 80 2010-06-12 00:54 avahi-daemon
drwxr-xr-x 2 root root 60 2010-06-12 00:54 console
drwxr-xr-x 2 root root 60 2010-06-12 00:54 ConsoleKit
-rw-r--r-- 1 root root 4 2010-06-12 00:54 console-kit-daemon.pid
-rw-r--r-- 1 root root 4 2010-06-12 00:54 crond.pid
---------- 1 root root 0 2010-06-12 00:54 crond.reboot
drwxr-xr-x 2 messagebus messagebus 80 2010-06-12 00:54 dbus
-rw-r--r-- 1 root root 4 2010-06-12 00:54 dhclient-eth0.pid
drwx--x--x 4 root gdm 100 2010-06-12 00:54 gdm
-rw-r--r-- 1 root root 4 2010-06-12 00:54 gdm.pid
drwxr-xr-x 2 root root 60 2010-06-12 00:54 network
-rw-r--r-- 1 root root 3 2010-06-12 00:54 NetworkManager.pid
-rw-r--r-- 1 root root 1777 2010-06-12 00:54 nm-dhclient-eth0.conf
drwxr-xr-x 4 root root 80 2010-06-12 00:54 pm-utils
-rw-r--r-- 1 root root 4 2010-06-12 00:54 rsyslogd.pid
drwxrwxr-x 2 root utmp 40 2010-06-12 00:54 screen
drwxr-xr-x 2 root root 40 2010-06-12 00:54 sendsigs.omit.d
drwx------ 3 root graham 60 2010-06-12 00:56 sudo
drwxr-xr-x 2 root root 60 2010-06-12 00:54 udev-configure-printer
-rw-r--r-- 1 root root 4 2010-06-12 00:54 upstart-udev-bridge.pid
-rw-rw-r-- 1 root utmp 3840 2010-06-12 01:03 utmp

graham@gt-desktop:~$ sudo sh /etc/init.d/proftpd
[sudo] password for graham:

graham@gt-desktop:~$ sudo sh /etc/init.d/proftpd start
 * Starting ftp server proftpd gt-desktop - 127.0.1.1:22122 masquerading as 80.46.64.185
                                                                         [ OK ]
graham@gt-desktop:~$ ls -l /var/run
total 48
-rw-r--r-- 1 root root 4 2010-06-12 00:54 acpid.pid
srw-rw-rw- 1 root root 0 2010-06-12 00:54 acpid.socket
-rw-r--r-- 1 root root 4 2010-06-12 00:54 atd.pid
drwxr-xr-x 2 avahi avahi 80 2010-06-12 00:54 avahi-daemon
drwxr-xr-x 2 root root 60 2010-06-12 00:54 console
drwxr-xr-x 2 root root 60 2010-06-12 00:54 ConsoleKit
-rw-r--r-- 1 root root 4 2010-06-12 00:54 console-kit-daemon.pid
-rw-r--r-- 1 root root 4 2010-06-12 00:54 crond.pid
---------- 1 root root 0 2010-06-12 00:54 crond.reboot
drwxr-xr-x 2 messagebus messagebus 80 2010-06-12 00:54 dbus
-rw-r--r-- 1 root root 4 2010-06-12 00:54 dhclient-eth0.pid
drwx--x--x 4 root gdm 100 2010-06-12 00:54 gdm
-rw-r--r-- 1 root root 4 2010-06-12 00:54 gdm.pid
drwxr-xr-x 2 root root 60 2010...

[Arnd (arnd-arndnet)]

Hi,
so I presume the bug is invalid then, because this is no longer relevant for you?

BTW: using the init scripts is always the preferred way to start and stop daemons...

Best regards,
Arnd

[Graham T (grahamt-manichostingservices)]

Hi Arnd,

It is still relevant to me.

On most system restarts (reboot) proftpd will not start up
automatically. Very occasionally it does. It is this inconsistent
behaviour that is making it hard to identify what the problem is.

When it fails to start during bootup, simply using "sudo service proftpd
start" will start it perfectly well.

I've run out of ideas of where to look to diagnose it.

Thanks
Graham

On 16/06/10 18:41, Arnd wrote:
> Hi,
> so I presume the bug is invalid then, because this is no longer relevant for you?
>
> BTW: using the init scripts is always the preferred way to start and
> stop daemons...
>
> Best regards,
> Arnd
>
>

[Arnd (arnd-arndnet)]

Hi Graham,

just a guess.
Could you try to add the line
mkdir -p /var/run/proftpd

after the line:
mkdir -p /var/run/sendsigs.omit.d

in /etc/init/mounted-varrun

Best regards,
Arnd

[Graham T (grahamt-manichostingservices)]

Hi Arnd,

Sure - I will give that a try.

But how will that be any different to the section in /etc/init.d/proftpd
that checks for the existence of /var/run/proftpd and creates it if it
is not present?

It looks like this:

# /var/run could be on a tmpfs
[ ! -d /var/run/proftpd ] && mkdir /var/run/proftpd

And if I stop the proftpd service, manually delete /var/run/proftpd then
start the proftpd service again the /var/run/proftpd directory is
correctly created and the service starts.

I am just asking out of curiosity as I have no idea what
/etc/init/mounted-varrun is used for!

I will add that line in now and let you know how it goes.

Many thanks
Graham

On 18/06/10 08:32, Arnd wrote:
> Hi Graham,
>
> just a guess.
> Could you try to add the line
> mkdir -p /var/run/proftpd
>
> after the line:
> mkdir -p /var/run/sendsigs.omit.d
>
> in /etc/init/mounted-varrun
>
> Best regards,
> Arnd
>
>

[Arnd (arnd-arndnet)]

Hi Graham,

Am 18.06.2010 23:34, schrieb Graham T:
> Sure - I will give that a try.
>
> But how will that be any different to the section in /etc/init.d/proftpd
> that checks for the existence of /var/run/proftpd and creates it if it
> is not present?
>

I suspect a race between the upstart jobs and the traditional init scripts.
Unfortunately proftpd is a traditional init script. I'm not 100% sure, but
I believe upstart scripts are executed partly in parallel with
traditional init
scripts, so I suspect that sometimes /var/run is not yet mounted as tmpfs
when the check you mentioned:

> # /var/run could be on a tmpfs
> [ ! -d /var/run/proftpd ] && mkdir /var/run/proftpd
>
is performed. Probably /var/run/proftpd exists at this point (on the root
filesystem.) Then, before proftpd is executed later in this script
/var/run is
mounted by the upstart script and suddenly /var/run/proftpd does not exists
anymore (because this is a new filesystem now). However, this is
all just speculation. There would be only a short timeframe were this
failure
can occur, but on the other hand this is in line with your report that
the behaviour seems somewhat random.

>
> And if I stop the proftpd service, manually delete /var/run/proftpd then
> start the proftpd service again the /var/run/proftpd directory is
> correctly created and the service starts.
>
> I am just asking out of curiosity as I have no idea what
> /etc/init/mounted-varrun is used for!
>
Its executed immediately after /var/run is mounted as tmpfs.
> I will add that line in now and let you know how it goes.
>

Of course this is not the real bug fix, but would point in the right
direction...

Best regards,
Arnd

[Graham T (grahamt-manichostingservices)]

Hi Arnd,

Thanks for the explanation.

Unfortunately it has not solved the problem. After a reboot, although
the directory /var/run/proftpd does now exist, it is empty and the
proftpd service is not running.

It still starts up fine if I do so manually.

I have just discovered how to enable trace logging for proftpd to give
extremely verbose logs which I have setup to log to a directory on the
root filesystem. Hopefully that may give some more clues.

Will let you know.

Thanks,
Graham

On 19/06/10 11:48, Arnd wrote:
> Hi Graham,
>
> Am 18.06.2010 23:34, schrieb Graham T:
>
>> Sure - I will give that a try.
>>
>> But how will that be any different to the section in /etc/init.d/proftpd
>> that checks for the existence of /var/run/proftpd and creates it if it
>> is not present?
>>
>>
> I suspect a race between the upstart jobs and the traditional init scripts.
> Unfortunately proftpd is a traditional init script. I'm not 100% sure, but
> I believe upstart scripts are executed partly in parallel with
> traditional init
> scripts, so I suspect that sometimes /var/run is not yet mounted as tmpfs
> when the check you mentioned:
>
>
>> # /var/run could be on a tmpfs
>> [ ! -d /var/run/proftpd ]&& mkdir /var/run/proftpd
>>
>>
> is performed. Probably /var/run/proftpd exists at this point (on the root
> filesystem.) Then, before proftpd is executed later in this script
> /var/run is
> mounted by the upstart script and suddenly /var/run/proftpd does not exists
> anymore (because this is a new filesystem now). However, this is
> all just speculation. There would be only a short timeframe were this
> failure
> can occur, but on the other hand this is in line with your report that
> the behaviour seems somewhat random.
>
>
>> And if I stop the proftpd service, manually delete /var/run/proftpd then
>> start the proftpd service again the /var/run/proftpd directory is
>> correctly created and the service starts.
>>
>> I am just asking out of curiosity as I have no idea what
>> /etc/init/mounted-varrun is used for!
>>
>>
> Its executed immediately after /var/run is mounted as tmpfs.
>
>> I will add that line in now and let you know how it goes.
>>
>>
> Of course this is not the real bug fix, but would point in the right
> direction...
>
> Best regards,
> Arnd
>
>

[Graham T (grahamt-manichostingservices)]

Hi Arnd,

The trace logging did not help - on the restarts when the proftpd
service does not start absolutely nothing is logged to the trace log
file. Which would seem to indicate to me that the service does not even
attempt to initialise.

However, I have made some other progress. Having read lots of proftpd
forum threads I came across one that was discussing profptd not starting
on Karmic that mentioned a problem with an unknown runlevel. There was
no resolution on the thread but it did prompt me to investigate.

I have found that:

a. On the restarts when proftpd starts up successfully the output of the
runlevel command looks normal i.e.

graham@gt-desktop:~$ runlevel
N 2

b. On the restarts when proftpd does not start up the output of the
runlevel command is not normal, it gives this:

graham@gt-desktop:~$ runlevel
unknown

I have also noticed that in scenario b. when proftpd does not start,
neither does the printing daemon cupsd.

The above two scenarios are absolutely consistent over about 50 restarts
I have now done.

So this in fact is looking to be not a proftpd bug at all, but something
going wrong with the init process - with proftpd and cupsd failing to
start being a symptom of that, along with the failure to export the
runlevel env.

For clarity, although the thread I came across the runlevel discussion
on was relating to Karmic, I am running Lucid.

Now I need to try and understand how to debug the init process to
continue investigating - something that I have never looked at, so I'm
learning all the way from here, which is a good thing :)

Should this bug be marked as Invalid now because it actually appears not
to be a proftpd bug?

Thanks for all your help.

Regards,
Graham

[Graham T (grahamt-manichostingservices)]

Hi Arnd,

My problem seems to be caused by this already opened bug which appears
to be something to do with upstart:
https://bugs.launchpad.net/ubuntu/+source/upstart/+bug/543506

I have added myself to that one.

So I guess this bug report can be closed now.

Many thanks,
Graham

[Mahyuddin Susanto (udienz)]

HI, i'm using proftpd in lucid too, but i'm not getting any errors like above