Bug #132684 for Term-ReadLine-Event: "illegal file descriptor or filehandle" and other failures

Sat May 23 04:39:41 2020 SREZIC [...] cpan.org - Ticket created

CC:	ANDK [...] cpan.org
Subject:	"illegal file descriptor or filehandle" and other failures

On some of my smoker systems the test suite fails: ... # Testing Term::ReadLine::Event: AnyEvent version 7.17 illegal file descriptor or filehandle (either no attached file descriptor or illegal value): GLOB(0x420e8810) at /home/cpansand/.cpan/build/2020021122/Term-ReadLine-Event-0.05-11/blib/lib/Term/ReadLine/Event.pm line 42. # Looks like your test exited with 9 just after 1. t/10-AnyEvent.t ......... Dubious, test returned 9 (wstat 2304, 0x900) Failed 1/2 subtests # Testing Term::ReadLine::Event: AnyEvent version 7.17 # Testing Term::ReadLine::Event: Coro version 6.54 fcntl() on closed filehandle FIN at /home/cpansand/.cpan/build/2020021122/AnyEvent-7.17-11/blib/lib/AnyEvent.pm line 1384. # Looks like your test exited with 255 before it could output anything. t/10-Coro.t ............. Dubious, test returned 255 (wstat 65280, 0xff00) Failed 1/1 subtests # Testing Term::ReadLine::Event: IO::Async version 0.74 Expected that read_handle can ->fileno at /home/cpansand/.cpan/build/2020021122/Term-ReadLine-Event-0.05-11/blib/lib/Term/ReadLine/Event.pm line 103. # Looks like your test exited with 255 just after 1. t/10-IO-Async.t ......... Dubious, test returned 255 (wstat 65280, 0xff00) Failed 1/2 subtests # Testing Term::ReadLine::Event: POE version 1.368 t/10-POE.t .............. ok t/10-Reflex.t ........... skipped: Reflex is not installed t/10-Tk.t ............... skipped: Tk can't initialise: couldn't connect to display ":0" at /usr/perl5.26.0p/lib/site_perl/5.26.0/amd64-freebsd/Tk/MainWindow.pm line 53. # Testing Term::ReadLine::Event: POE version 1.368 # Testing Term::ReadLine::Event: AnyEvent version 7.17 AnyEvent->io: cannot dup() filehandle in mode 'r': Bad file descriptor, at /home/cpansand/.cpan/build/2020021122/AnyEvent-7.17-11/blib/lib/AnyEvent.pm line 1585. # Looks like your test exited with 9 just after 1. t/20-POE_and_AE.t ....... Dubious, test returned 9 (wstat 2304, 0x900) Failed 1/2 subtests ... I have the impression that this happens only if the test suite runs under a newer CPAN.pm version. For example, with perl 5.30.2 and the original CPAN.pm there (version 2.22) this error does not happen, but with bleadperl (CPAN.pm version 2.27) it fails. Also, it fails with perl 5.30.2 and CPAN.pm 2.28-TRIAL (2.27 is not installable anymore because of other problems).

Sun May 24 05:26:34 2020 ANDK [...] cpan.org - Correspondence added

A few more datapoints. The oldest perl with such a diagnostics ('illegal file descriptor') seems to be 5.26.0 on http://www.cpantesters.org/cpan/report/ad71ae46-cb46-11e7-90b2-ce4f375ad520, this was made with CPAN 2.18. And counterexamples: PASS reports where 2.27 was used and not everything was a skip: http://www.cpantesters.org/cpan/report/113155450 http://www.cpantesters.org/cpan/report/106459965 http://www.cpantesters.org/cpan/report/110923410

Sun May 24 05:26:35 2020 The RT System itself - Status changed from 'new' to 'open'

Sun May 24 07:46:40 2020 SREZIC [...] cpan.org - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

strace shows that in the problematic case /dev/tty cannot be opened, erroring with ENXIO (No such device or address). Here are three strace.logs from this section: the first two are successful, the third one fails: 5.30.2, with CPAN.pm 2.22: 13523 11:38:30.984185 write(6, "# Testing Term::ReadLine::Event: AnyEvent version 7.17\n", 55) = 55 <0.000024> 13523 11:38:30.984282 stat("/dev/tty", {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000024> 13523 11:38:30.984371 openat(AT_FDCWD, "/dev/tty", O_RDONLY|O_CLOEXEC <unfinished ...> 13523 11:38:30.984425 <... openat resumed> ) = 3 <0.000034> 13523 11:38:30.984466 ioctl(3, TCGETS <unfinished ...> 13523 11:38:30.984515 <... ioctl resumed> , {B9600 opost isig icanon echo ...}) = 0 <0.000034> 13523 11:38:30.984565 lseek(3, 0, SEEK_CUR <unfinished ...> 13523 11:38:30.984616 <... lseek resumed> ) = -1 ESPIPE (Illegal seek) <0.000034> 13523 11:38:30.984663 fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000025> 13523 11:38:30.984743 close(3) = 0 <0.000056> 13523 11:38:30.984861 openat(AT_FDCWD, "/dev/tty", O_RDONLY|O_CLOEXEC) = 3 <0.000025> 13523 11:38:30.984932 ioctl(3, TCGETS, {B9600 opost isig icanon echo ...}) = 0 <0.000021> 13523 11:38:30.985001 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000021> 13523 11:38:30.985080 fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000053> 13523 11:38:30.985196 openat(AT_FDCWD, "/dev/tty", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 4 <0.000024> 13523 11:38:30.985268 ioctl(4, TCGETS, {B9600 opost isig icanon echo ...}) = 0 <0.000021> 13523 11:38:30.985335 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000016> 13523 11:38:30.985394 fstat(4, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000021> 13523 11:38:30.985462 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000033> 13523 11:38:30.985552 ioctl(4, TCGETS, {B9600 opost isig icanon echo ...}) = 0 <0.000021> 13523 11:38:30.985620 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000016> 13523 11:38:30.985692 stat("/home/cpansand/.cpan/build/2020052410/Term-ReadLine-Event-0.05-1/blib/lib/Term/Cap.pmc", 0x7ffe906cb110) = -1 ENOENT (No such file or directory) <0.000023> 13523 11:38:30.985763 stat("/home/cpansand/.cpan/build/2020052410/Term-ReadLine-Event-0.05-1/blib/lib/Term/Cap.pm", 0x7ffe906cb110) = -1 ENOENT (No such file or directory) <0.000021> 5.31.11, without CPAN.pm: 11258 11:23:15.244113 write(6, "# Testing Term::ReadLine::Event: AnyEvent version 7.17\n", 55) = 55 <0.000022> 11258 11:23:15.244197 stat("/dev/tty", <unfinished ...> 11258 11:23:15.244263 <... stat resumed> {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000045> 11258 11:23:15.244315 openat(AT_FDCWD, "/dev/tty", O_RDONLY|O_CLOEXEC <unfinished ...> 11258 11:23:15.244367 <... openat resumed> ) = 3 <0.000032> 11258 11:23:15.244413 ioctl(3, TCGETS <unfinished ...> 11258 11:23:15.244462 <... ioctl resumed> , {B9600 opost isig icanon echo ...}) = 0 <0.000034> 11258 11:23:15.244509 lseek(3, 0, SEEK_CUR <unfinished ...> 11258 11:23:15.244558 <... lseek resumed> ) = -1 ESPIPE (Illegal seek) <0.000034> 11258 11:23:15.244598 fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000020> 11258 11:23:15.244673 close(3) = 0 <0.000022> 11258 11:23:15.244742 openat(AT_FDCWD, "/dev/tty", O_RDONLY|O_CLOEXEC) = 3 <0.000024> 11258 11:23:15.244813 ioctl(3, TCGETS, {B9600 opost isig icanon echo ...}) = 0 <0.000020> 11258 11:23:15.244880 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000020> 11258 11:23:15.244943 fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000020> 11258 11:23:15.245012 openat(AT_FDCWD, "/dev/tty", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 4 <0.000023> 11258 11:23:15.245082 ioctl(4, TCGETS, {B9600 opost isig icanon echo ...}) = 0 <0.000020> 11258 11:23:15.245149 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000019> 11258 11:23:15.245211 fstat(4, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000019> 11258 11:23:15.245277 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000019> 11258 11:23:15.245340 ioctl(4, TCGETS, {B9600 opost isig icanon echo ...}) = 0 <0.000020> 11258 11:23:15.245405 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000019> 11258 11:23:15.245484 stat("/home/cpansand/.cpan/build/2020052410/Term-ReadLine-Event-0.05-1/blib/lib/Term/Cap.pmc", 0x7ffdf0dcf0f0) = -1 ENOENT (No such file or directory) <0.000022> 11258 11:23:15.245554 stat("/home/cpansand/.cpan/build/2020052410/Term-ReadLine-Event-0.05-1/blib/lib/Term/Cap.pm", 0x7ffdf0dcf0f0) = -1 ENOENT (No such file or directory) <0.000021> 5.31.11, with CPAN.pm 2.77: 27442 11:08:16.192988 write(6, "# Testing Term::ReadLine::Event: AnyEvent version 7.17\n", 55) = 55 <0.000025> 27442 11:08:16.193088 stat("/dev/tty", <unfinished ...> 27442 11:08:16.193145 <... stat resumed> {st_mode=S_IFCHR|0666, st_rdev=makedev(0x5, 0), ...}) = 0 <0.000037> 27442 11:08:16.193198 openat(AT_FDCWD, "/dev/tty", O_RDONLY|O_CLOEXEC <unfinished ...> 27442 11:08:16.193251 <... openat resumed> ) = -1 ENXIO (No such device or address) <0.000031> 27442 11:08:16.193299 openat(AT_FDCWD, "&STDIN", O_RDONLY|O_CLOEXEC <unfinished ...> 27442 11:08:16.193353 <... openat resumed> ) = -1 ENOENT (No such file or directory) <0.000034> 27442 11:08:16.193400 fcntl(2, F_DUPFD_CLOEXEC, 0 <unfinished ...> 27442 11:08:16.193452 <... fcntl resumed> ) = 3 <0.000034> 27442 11:08:16.193492 ioctl(3, TCGETS, 0x7ffcea216f20) = -1 ENOTTY (Inappropriate ioctl for device) <0.000019> 27442 11:08:16.193553 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000019> 27442 11:08:16.193620 fstat(3, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 <0.000019> 27442 11:08:16.193705 stat("/home/cpansand/.cpan/build/2020052410/Term-ReadLine-Event-0.05-1/blib/lib/Term/Cap.pmc", 0x7ffcea216f30) = -1 ENOENT (No such file or directory) <0.000028> 27442 11:08:16.193784 stat("/home/cpansand/.cpan/build/2020052410/Term-ReadLine-Event-0.05-1/blib/lib/Term/Cap.pm", 0x7ffcea216f30) = -1 ENOENT (No such file or directory) <0.000025> I tried the third case also without Test::Reporter, but the problem persists.

Sun May 24 08:32:27 2020 SREZIC [...] cpan.org - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On 2020-05-24 07:46:40, SREZIC wrote: Show quoted text

> strace shows that in the problematic case /dev/tty cannot be opened, > erroring with ENXIO (No such device or address). Here are three > strace.logs from this section: the first two are successful, the third > one fails:

[...] An open on /dev/tty may fail if setsid() was called before. Here's a oneliner demonstrating this: $ perl -MPOSIX -e 'if (fork == 0) { POSIX::setsid(); open my $fh, "/dev/tty" or die $!; exit 0 } wait' No such device or address at -e line 1. The open() is successful when the POSIX::setsid() call is removed. And it seems that CPAN.pm calls setsid() starting with this commit: commit eae114870872c16ce8123c3a1fc543d5a506946d Author: Andreas Koenig <andk@cpan.org> Date: Sat Mar 9 19:32:54 2019 +0100 Add a fork level to let setsid protect us from tests killing their process group

Sun May 24 08:48:10 2020 ANDK [...] cpan.org - Correspondence added

Thanks Slaven, an excellent analysis! As always:)