tail'ing a file in a script session hangs

[Simon Déziel]

Steps to reproduce:

1) Start script session (same issue when script is saving to /dev/null)
script # or: script /dev/null
2) Tail a file
tailf /var/log/syslog
3) Press "Enter" 2 times
4) Notice the script process taking 100% CPU

This regression was introduced upstream by this commit: https://git.kernel.org/cgit/utils/util-linux/util-linux.git/commit/?id=54c6611d6f7b73609a5331f4d0bcf63c4af6429e

$ lsb_release -rd
Description: Ubuntu Xenial Xerus (development branch)
Release: 16.04

$ apt-cache policy util-linux bsdutils coreutils
util-linux:
  Installed: 2.27.1-4ubuntu1
  Candidate: 2.27.1-4ubuntu1
  Version table:
 *** 2.27.1-4ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu xenial-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     2.27.1-3ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu xenial/main amd64 Packages
bsdutils:
  Installed: 1:2.27.1-4ubuntu1
  Candidate: 1:2.27.1-4ubuntu1
  Version table:
 *** 1:2.27.1-4ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu xenial-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     1:2.27.1-3ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu xenial/main amd64 Packages
coreutils:
  Installed: 8.25-2ubuntu2
  Candidate: 8.25-2ubuntu2
  Version table:
 *** 8.25-2ubuntu2 500
        500 http://archive.ubuntu.com/ubuntu xenial/main amd64 Packages
        100 /var/lib/dpkg/status

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: util-linux 2.27.1-4ubuntu1
ProcVersionSignature: Ubuntu 4.4.0-10.25-generic 4.4.3
Uname: Linux 4.4.0-10-generic x86_64
NonfreeKernelModules: zfs zunicode zcommon znvpair zavl
ApportVersion: 2.20-0ubuntu3
Architecture: amd64
CurrentDesktop: Unity
Date: Fri Mar 4 15:14:15 2016
SourcePackage: util-linux
UpgradeStatus: No upgrade log present (probably fresh install)

[Ayan George (ayan)]

I couldn't reproduce it. Can you post strace output of script? There will be more than one script process -- chose the one that is consuming 100% CPU and run something like:

$ strace -tt -p <pid of scrip> >/tmp/strace.out

Let it run for about 15 seconds and exit. Then upload the output.

[Pádraig Brady (p-draigbrady)]

Reproduced with script 2.27.1 which spins in this case continually doing:

poll([{fd=4, events=POLLIN}], 1, 10) = 1 ([{fd=4, revents=POLLIN}])

[Simon Déziel (sdeziel)]

On 2016-03-05 12:10 AM, Pádraig Brady wrote:
> Reproduced with script 2.27.1 which spins in this case continually
> doing:
>
> poll([{fd=4, events=POLLIN}], 1, 10) = 1 ([{fd=4, revents=POLLIN}])

Yes, that's what strace'ing reveals in my case.

[Ayan George (ayan)]

Ah -- I've been able to reproduce it. I'll run it in a debugger and see if I can isolate the problem.

[Ayan George (ayan)]

Killing tail stops the runaway poll(). It might help to see what tail is doing as well.

[Ayan George (ayan)]

16.04 is using linux util tagged at v2.27.1. I can reproduce the problem using the git source at tag 2.27.1 forward. The bug doesn't occur in v2.26.2 so this looks like a regression.

[Simon Déziel (sdeziel)]

After bisecting util-linux, the problematic commit is:

54c6611d6f7b73609a5331f4d0bcf63c4af6429e is the first bad commit
commit 54c6611d6f7b73609a5331f4d0bcf63c4af6429e
Author: Karel Zak <email address hidden>
Date: Wed Jun 17 15:48:50 2015 +0200

    script: fix EOF problems

    * remove STDIN from poll() if:

      * STDIN already closed -- poll returns POLLHUP, for example:

      echo "date" | script

      * detect EOF as returned by read(), for example:

      script -c "echo Hello" < /dev/null

    * don't write to master when there is still something to read from
      slave (it means shell is not initialized yet or busy)

    Signed-off-by: Karel Zak <email address hidden>

:040000 040000 2cc2b7f5d69f16775151517912dce6ff3a586847 b1a8465b2c3f23c0f41bfb7308af49b92963e77b M term-utils

When using v2.27.1 and reverting just this commit, all is fine.

[Simon Déziel (sdeziel)]

FYI, the current master (d38bcd109e9) still has the problem.

[Simon Déziel (sdeziel)]

The above commit is from Debian's git. The problem still exists upstream in https://git.kernel.org/cgit/utils/util-linux/util-linux.git/commit/?id=44338f7fe6a529cef1f206dccd95e7282625c483

[Simon Déziel (sdeziel)]

The Debian maintainer forwarded the bug upstream and they fixed it right away. So here's a debdiff that fixes the problem for me. I uploaded it to my PPA and it successfully built on amd64 [1] but not i386 [2].

On i386 the libmount/lock test failed so it seems unrelated to this new commit. It's the only test that failed out of the 170 that were executed.

1: https://launchpad.net/~sdeziel/+archive/ubuntu/ppa/+build/9571252
2: https://launchpad.net/~sdeziel/+archive/ubuntu/ppa/+build/9571253

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "lp1553353.debdiff" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

[Martin Pitt (pitti)]

... and sponsored, thanks Simon!

[Launchpad Janitor (janitor)]

This bug was fixed in the package util-linux - 2.27.1-6ubuntu3

---------------
util-linux (2.27.1-6ubuntu3) xenial; urgency=medium

  * Add debian/patches/script-use-empty-slave.patch taken from
    upstream git (LP: #1553353, Closes: #820843)

 -- Simon Deziel <email address hidden> Wed, 13 Apr 2016 15:01:21 +0000