Perl / perl5

🐪 The Perl programming language
https://dev.perl.org/perl5/
Other
1.9k stars 540 forks source link

perlio forget about buffering settings on EAGAIN #8701

Open p5pRT opened 17 years ago

p5pRT commented 17 years ago

Migrated from rt.perl.org#41043 (status was 'open')

Searchable as RT41043$

p5pRT commented 17 years ago

From perlbug@plan9.de

Created by perlbug@plan9.de

It seems that $| and autoflush ability is lost on the first EAGAIN.

Here is a test program that might or might not work (it should be run under a terminal emulator\, and it likely works best under linux because I tested it with that kernel) that illustrates the problem​:

  !/usr/bin/perl

  use Fcntl;

  open my $fh\, ">&1" or die;   fcntl $fh\, F_SETFL\, O_NONBLOCK or die;

  $|=1;

  print "-";   syswrite $fh\, "\x00" x 8192;   print "+";   sleep 1;   print "*";   sleep 60;

Here is an explanation of what the program does​:

1. get another filehandle for stdout 2. make it nonblocking (this also makes fd 1 nonblocking) 3. print a "-"\, which gets printed immediately. 4. write 8192 bytes\, which is hopefully more than the tty supports 5. print a single "+"\, causing a write()\, but results in EAGAIN 6. wait a while\, print "*"\, which should cause a write()\, but doesn't 7. give us time to look at the output.

Here is what I expect​:

  -* \<---cursor here

  (-+* is another expected possibility)

here is what I usually get​:

  - \<---cursor here

If I strace the program (carefully)\, I get (among others)\, this​:

  write(1\, "-"\, 1) = 1   write(3\, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...\, 8192) = 4095   write(1\, "+"\, 1) = -1 EAGAIN (Resource temporarily unavailable)   nanosleep({1\, 0}\, {1\, 0}) = 0   nanosleep({60\, 0}\, ...

As you can see\, "-" gets printed\, then our 8k dump fills the tty buffer\, then "+" gets written\, but gets EAGAIN.

After a second\, we write another "*"\, but perl will not even attempt the write.

This is IMHO a bug\, as $| should cause a flush\, and thus a write().

Doing $|=0;$|=1 flushes the buffer\, and the "*" appears\, but subsequent writes will still be buffered\, and I found no way of resurrecting STDOUT with autoflush\, short of closing and reopening it.

Please note that I didn't investigate this further (it could quite likely be stdio that would change buffering modes on EAGAIN\, for example\, and it took me some days to locate the code that causes this behaviour and to write a testcase).

I still think perl most be involved somehow\, as an explicit flush (setting $|=1) actually prints the buffer out fully - if perl would do a flush after every print\, as documented\, I would expect it to still just work\, regardless of what stdio thinks about buffering.

Please also note that the "+" usually gets lost\, which is somehow expected or not\, but the "*" and all subsequent prints get buffered internally and will be written on excplit flush (setting $|) but will not be autoflushed.

Perl Info ``` Flags: category=core severity=low Site configuration information for perl v5.8.8: Configured by Marc Lehmann at Sat May 13 14:13:02 CEST 2006. Summary of my perl5 (revision 5 version 8 subversion 8) configuration: Platform: osname=linux, osvers=2.6.16.11, archname=amd64-linux uname='linux fuji 2.6.16.11 #2 preempt thu may 4 14:20:31 cest 2006 i686 gnulinux ' config_args='-Duselargefiles -Uuse64bitint -Uuse64bitall -Dusemymalloc=y -Dcc=gcc-4.0 -Dccflags=-ggdb -Dcppflags=-D_GNU_SOURCE -I/opt/include -Doptimize=-O4 -march=pentium3 -mtune=pentium3 -funroll-loops -fno-strict-aliasing -Dcccdlflags=-fPIC -Dldflags=-L/opt/perl/lib -L/opt/lib -Dlibs=-ldl -lm -lcrypt -Darchname=amd64-linux -Dprefix=/opt/perl -Dprivlib=/opt/perl/lib/perl5 -Darchlib=/opt/perl/lib/perl5 -Dvendorprefix=/opt/perl -Dvendorlib=/opt/perl/lib/perl5 -Dvendorarch=/opt/perl/lib/perl5 -Dsiteprefix=/opt/perl -Dsitelib=/opt/perl/lib/perl5 -Dsitearch=/opt/perl/lib/perl5 -Dsitebin=/opt/perl/bin -Dman1dir=/opt/perl/man/man1 -Dman3dir=/opt/perl/man/man3 -Dsiteman1dir=/opt/perl/man/man1 -Dsiteman3dir=/opt/perl/man/man3 -Dman1ext=1 -Dman3ext=3 -Dpager=/usr/bin/less -Uafs -Uusesfio -Uusenm -Uuseshrplib -Dd_dosuid -Dusethreads=undef -Duse5005threads=undef -Duseithreads=undef -Dusemultiplicity=undef -Demail=perl-binary@plan9.de -Dcf_email=perl-binary@plan9.de -Dcf_by=Marc Lehmann -Dlocincpth=/opt/perl/include /opt/include -Dmyhostname=localhost -Dmultiarch=undef -Dbin=/opt/perl/bin -des' hint=recommended, useposix=true, d_sigaction=define usethreads=undef use5005threads=undef useithreads=undef usemultiplicity=undef useperlio=define d_sfio=undef uselargefiles=define usesocks=undef use64bitint=undef use64bitall=undef uselongdouble=undef usemymalloc=y, bincompat5005=undef Compiler: cc='gcc-4.0', ccflags ='-ggdb -fno-strict-aliasing -pipe -Wdeclaration-after-statement -I/opt/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64', optimize='-O4 -march=pentium3 -mtune=pentium3 -funroll-loops -fno-strict-aliasing', cppflags='-D_GNU_SOURCE -I/opt/include -ggdb -fno-strict-aliasing -pipe -Wdeclaration-after-statement -I/opt/include' ccversion='', gccversion='4.0.3 (Debian 4.0.3-1)', gccosandvers='' intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12 ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=4, prototype=define Linker and Libraries: ld='gcc-4.0', ldflags ='-L/opt/perl/lib -L/opt/lib -L/usr/local/lib' libpth=/usr/local/lib /lib /usr/lib /usr/ucblib libs=-ldl -lm -lcrypt perllibs=-ldl -lm -lcrypt libc=/lib/libc-2.3.6.so, so=so, useshrplib=false, libperl=libperl.a gnulibc_version='2.3.6' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E' cccdlflags='-fPIC', lddlflags='-shared -L/opt/perl/lib -L/opt/lib -L/usr/local/lib' Locally applied patches: MAINT27284 @INC for perl v5.8.8: /root/src/sex /opt/perl/lib/perl5 /opt/perl/lib/perl5 /opt/perl/lib/perl5 /opt/perl/lib/perl5 /opt/perl/lib/perl5 /opt/perl/lib/perl5 /opt/perl/lib/perl5 . Environment for perl v5.8.8: HOME=/root LANG (unset) LANGUAGE (unset) LC_CTYPE=de_DE.UTF-8 LD_LIBRARY_PATH (unset) LOGDIR (unset) PATH=/root/s2:/root/s:/opt/bin:/opt/sbin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/X11/bin:/usr/games:/root/src/uunet:. PERL5LIB=/root/src/sex PERL5_CPANPLUS_CONFIG=/root/.cpanplus/config PERLDB_OPTS=ornaments=0 PERL_BADLANG (unset) PERL_UNICODE=EAL SHELL=/bin/bash ```
p5pRT commented 8 years ago

From @dcollinsn

I get some very inconsistent results from this​:

dcollins@​nightshade64​:\~/toolchain$ perl5.25.0 41043.pl -^C dcollins@​nightshade64​:\~/toolchain$ exit Script done\, file is /dev/null dcollins@​nightshade64​:\~/toolchain$ script /dev/null Script started\, file is /dev/null dcollins@​nightshade64​:\~/toolchain$ perl5.25.0 41043.pl -+*^C dcollins@​nightshade64​:\~/toolchain$ perl5.25.0 41043.pl -^C

Which is also what 5.8.8 does​:

dcollins@​nightshade64​:\~/toolchain$ perl5.8.8 41043.pl -+*^C dcollins@​nightshade64​:\~/toolchain$ perl5.8.8 41043.pl -^C

Even a `reset` doesn't get back to the original behavior\, but Ctrl-D\, script /dev/null does. What is going on here?

-- Respectfully\, Dan Collins

p5pRT commented 8 years ago

From [Unknown Contact. See original ticket]

I get some very inconsistent results from this​:

dcollins@​nightshade64​:\~/toolchain$ perl5.25.0 41043.pl -^C dcollins@​nightshade64​:\~/toolchain$ exit Script done\, file is /dev/null dcollins@​nightshade64​:\~/toolchain$ script /dev/null Script started\, file is /dev/null dcollins@​nightshade64​:\~/toolchain$ perl5.25.0 41043.pl -+*^C dcollins@​nightshade64​:\~/toolchain$ perl5.25.0 41043.pl -^C

Which is also what 5.8.8 does​:

dcollins@​nightshade64​:\~/toolchain$ perl5.8.8 41043.pl -+*^C dcollins@​nightshade64​:\~/toolchain$ perl5.8.8 41043.pl -^C

Even a `reset` doesn't get back to the original behavior\, but Ctrl-D\, script /dev/null does. What is going on here?

-- Respectfully\, Dan Collins

p5pRT commented 7 years ago

From zefram@fysh.org

This can be tested more cleanly by creating a pipe and never reading from it\, rather than writing to a tty and hoping that it can't keep up.

The behaviour seen arises from the sticky error status of an I/O handle. In itself\, the sticky error status is an intentional feature\, which can avoid the need to put high-level error-handling code on every I/O operation. The failed output of the "+" sets the sticky error flag. The effect of the error flag is then that\, even though outputting "*" succeeds as far as adding it to the buffer\, that output operation is considered failed. Consequently the print op aborts​: it doesn't attempt the flush operation that would normally result from the autoflush flag (which remains set)\, and it returns false. (If it were ignoring the autoflush flag and thought it had succeeded in outputting "*" just by adding it to the buffer then it would return true.)

Further enlightenment can be gained by changing the print operations to each print two things\, from separate operands\, as in 'print "*"\, "*"'. The operands are written to PerlIO sequentially\, and the autoflush happens after all of them. That sequence initially manifests by "--" being passed to the write syscall in one go. The effect of the sticky error then becomes clearer at the "*" line. Writing the first "*" to the buffer succeeds\, but the operation is considered failed because of the sticky error flag. The print op therefore aborts before outputting the second operand\, and so when a flush eventually happens (e.g.\, on program end) only the one "*" will be passed to the syscall.

You can clear the sticky error flag by using the ->clearerr method of IO​::Handle. This is the appropriate thing to do with errors that you expect to be transitory\, such as EAGAIN. This will restore the autoflushing behaviour that you're expecting​: the next print op after ->clearerr will automatically flush. If you've already buffered some output with the error flag set then ->clearerr won't flush it\, but you can do an explicit ->flush at the same time. However\, when you're expecting to handle an error from a specific operation\, it's best to complete the error handling and clear the error flag *before* you try to output anything that you want to succeed independently of the error you've handled.

This behaviour isn't a bug in perl. However\, it might be less strange (though still a bit confusing) if the sticky error flag made subsequent I/O operations fail *before* they were attempted. In this ticket's test case\, that would cause the "*" to be lost entirely\, not even reappearing at the end-of-program implicit flush. ->clearerr would still be needed to handle EAGAIN\, but we wouldn't get half-done print ops when the error is not cleared.

We could also probably document this better.

-zefram

p5pRT commented 7 years ago

The RT System itself - Status changed from 'new' to 'open'

p5pRT commented 7 years ago

From @cpansprout

On Sun\, 26 Mar 2017 17​:01​:37 -0700\, zefram@​fysh.org wrote​:

This behaviour isn't a bug in perl.

I still consider it unacceptable. (I reported a similar bug some years ago with the same underlying cause. I don’t know the number or remember the subject line.)

However\, it might be less strange (though still a bit confusing) if the sticky error flag made subsequent I/O operations fail *before* they were attempted. In this ticket's test case\, that would cause the "*" to be lost entirely\, not even reappearing at the end-of-program implicit flush. ->clearerr would still be needed to handle EAGAIN\, but we wouldn't get half-done print ops when the error is not cleared.

If print is going to do two separate print operations behind the scenes when given two arguments\, then both operations should happen the same way.

I.e.\, what you suggested above (which is unhelpful)\, or print("a"\,"b") should be equivalent to print("a")\,print("b"). If it can print the "a" without checking the error status\, it should be able to print the "b" the same way.

--

Father Chrysostomos

p5pRT commented 7 years ago

From zefram@fysh.org

Father Chrysostomos via RT wrote​:

or print("a"\,"b") should be equivalent to print("a")\,print("b").

With autoflush processing after the "a"? Someone's bound to be annoyed by thus splitting output that's currently merged. And would that mean that print() (with no operands to print) doesn't autoflush at all?

If it can print the "a" without checking the error status\, it should be able to print the "b" the same way.

If we go that way\, presumably we'd also do the autoflush (whether once or twice) even when errored. Effectively we'd be kicking the sticky-error behaviour up to a higher level. But this doesn't compose nicely.

We could expect that user code would contain higher-level I/O sequences that check for error returns and will abort early. So the same problem that arose with print("a"\, "b") only printing "a" would just arise again\, with (print("a") && print("b")). Would we encourage rewriting that to ignore errors from each operation\, only checking the handle's error status at the end? What about when a new error actually occurs during output​: do we want to try to output subsequent things anyway and save the error up to the end? What if there's an error in the middle of outputting the string resulting from a single operand​: should we skip a byte and try again to output the subsequent bytes? Usually we don't want any such continuance​: aborting the whole sequence as soon as an error happens is the right thing.

So I'd favour what I proposed​: that the sticky error state should prevent further operations being attempted. This does compose nicely\, in that all levels of code naturally get the consistent behaviour of aborting as soon as an error occurs and not doing any further I/O until the error is cleared. The unusual case of wanting to handle and clear an error should bear the burden of determining the granularity at which operations are to be resumed or retried.

-zefram