Created attachment 1544114 [details]
Fix SRPM

Thanks for the report.

Do you have some evidence that the pututxline() calls in fact fail? And if they do fail, what is the errno?

I was able to reproduce the 'gone - no logout' lines, however they disappear after some event (perhaps after the corresponding vsftpd processes terminate). And even though I got the 'gone - no logout' lines, none of the pututxline() calls in fact failed.

Hello,

Yes, I was also in the situation where 'gone - no logout' disappear. But the issue is that sometimes, the entry stays in the utmp file, because the call does not success.

I made a ugly version where I print a message when the return is null:

  while (pututxline(&s_utent) == NULL) {
        str_alloc_text(&utmp_str, "pututxline return NULL, retrying \n");
        str_syslog(&utmp_str,0);
        setutxent();
}

And a previous version where I don't retry, and I can see the message when the utmp is broken.

This bug turned out to be much more tricky than I thought. It turns
out that the source of the signals that make pututxline() fail with
EINTR is pututxline() itself - pututxline() does locking of the utmp
file and uses alarm() to set a timeout on the locking operation. So
what we observe as pututxline() failing with EINTR is in fact
pututxline() timing out while attempting to lock a file.

Now if I use the fix that repeats both setutxent() and pututxline()
when pututxline() fails with EINTR, things can get ugly. This fix
causes a situation to arise where many vsftpd processes keep re-trying
setutxent() and pututxline() and none of them succeed.

You could think that this cannot happen - if one process times out on
a lock operation, it must mean that some other process is currently
holding the lock and that process is moving forward. Unfortunatelly,
this may not always be the case - the process that holds the lock may
not be moving forward at all.

The problem is that pututxline() locks the utmp file twice in a row
and each of the two lock operations can time out. So it can happen
that while the first locking succeeds, the second locking times out
and consequently the whole pututxline() call fails. And if this
happens for every process that is attempting to call setutxent() and
pututxline(), none of the processes will move forward.  They will keep
looping, potentially forever, or at least for a very long time. In my
testing, this situation arises fairly often.

The solution to this problem is to make pututxline() remember that a
previous call to pututxline has already done the first locking,
remember that it has already done the work that needs to be done while
that lock is held, and to reuse the result of that work.

This could, in theory be achieved by repeating only pututxline() - not
both setutxent() and pututxline(). However there is currently a glibc
bug that prevents us from doing that - I'll file the bug shortly.

Once the glibc bug is fixed, we should be able to safely keep
repeating pututxline() until it succeeds and we can properly fix this
vsftpd bug.

But until the glibc bug is fixed, there's not much I can do in
vsftpd. I can implement a partial fix, where the
setutxline()-pututxline() combo is repeated only a couple of times and
give up after the retries are exhausted. This may help a bit, but it's
not a complete fix.

(In reply to Welterlen Benoit from comment #0)
> Actual results:
> Entries in utmp broken, then the file size increases and performances fall

I'd say it's in fact normal that the file keeps growing and
subsequently the utmp file processing takes longer. I think the
performance could be improved however by changing pututxline() to lock
only the relevant portion of the file for writing - currently it locks
the whole file, which increases contention. I think locking the whole
file is unnecessary. I'll file a bug for this.

(In reply to Ondřej Lysoněk from comment #13)
> This could, in theory be achieved by repeating only pututxline() - not
> both setutxent() and pututxline(). However there is currently a glibc
> bug that prevents us from doing that - I'll file the bug shortly.

I've filed bug#1734791 for this.

(In reply to Ondřej Lysoněk from comment #13)
> But until the glibc bug is fixed, there's not much I can do in
> vsftpd. I can implement a partial fix, where the
> setutxline()-pututxline() combo is repeated only a couple of times and
> give up after the retries are exhausted. This may help a bit, but it's
> not a complete fix.

TL;DR:
I ran some experiments to determine if repeating
setutxline()-pututxline() is worth it. From the results of the
experiment it seems that repeating it once improves the situation
significantly, however anything more than that does not seem to be
worth it.

Long version:
The experiment was to run the following 'for' loop twice in sequence:
for i in {1..10000}; do echo -en "user user$((i%51))\\npass user$((i%51))\\nquit\\n" | nc localhost 21 & done > log; wait;

I measured the time the second iteration has taken and counted the
number of bad utmp entries when the test finished.

I ran the experiment with unpatched vsftpd and several versions of
patched vsftpd - the patches differed in the number of
setutxent()-pututxline() attempts.

The results follow.

Test with unpatched vsftpd (number of utmp insert/remove attempts: 1)
- Time taken: 4m6.468s
- Number of bad utmp entries: 7192

Test with patched vsftpd, number of utmp insert/remove attempts: 2
- Time taken: 4m39.467s
- Number of bad utmp entries: 1321

Test with patched vsftpd, number of utmp insert/remove attempts: 3
- Time taken: 5m0.778s
- Number of bad utmp entries: 1300

Test with patched vsftpd, number of utmp insert/remove attempts: 8
Time taken: 6m22s
Number of bad utmp entries: 1003

From these results we can see that raising the number of insert/remove
attempts to 2 reduces the number of bad utmp entries
significantly. Incresing the number of attempts further does
not significantly affect the number of bad utmp entries, whereas the
execution time grows approximately linearly.

Clearing the dependency on glibc bug#1734791. We'll use this bug to do the partial fix. I've cloned this bug to bug#1737433 - we'll use that to fully resolve the problem after the glibc bug is fixed.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:1010