Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8025883

PrintStream "autoFlush" parameter violates its API contract

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: P4 P4
    • tbd
    • 7u25
    • core-libs
    • windows_7

      FULL PRODUCT VERSION :
      java version "1.7.0_25"
      Java(TM) SE Runtime Environment (build 1.7.0_25-b16)
      Java HotSpot(TM) 64-Bit Server VM (build 23.25-b01, mixed mode)


      ADDITIONAL OS VERSION INFORMATION :
      Microsoft Windows [Version 6.1.7601]

      Also observed on Linux:
      Linux 2.6.32.12-0.7.1.xs1.4.90.530.170661xen #1 SMP Mon Feb 6 17:55:01 EST 2012 i686 i686 i386 GNU/Linux


      A DESCRIPTION OF THE PROBLEM :
      The JavaDoc for PrintStream provides the following description of the "autoFlush" parameter:

      "A boolean; if true, the output buffer will be flushed whenever a byte array is written, one of the println methods is invoked, or a newline character or byte ('
      ') is written"

      One would reasonably infer then that the stream does *not* flush absent one of these conditions being satisfied (as is the case if autoFlush is false). However, every one of the "print" and "append" methods in the PrintStream implementation results in the PrintStream.write(byte[],int,int) method being invoked internally, which satisfies the first condition in the description of this parameter. The effect of course is that the stream flushes after every invocation of any of those methods, regardless of the content of what is being printed to the stream. This clearly violates the common-sense expectation of how this parameter should behave, given its documentation.

      Such behavior renders the parameter largely useless in practice, as output cannot be controlled using "print" methods as one might expect. It is also potentially a source of serious and unexpected performance degradation, if a caller is expecting the flushing of a stream to happen in a line-buffered manner, rather than a character-buffered manner.

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      1. javac AutoFlushBugStream.java
      2. java AutoFlushBugStream

      (optional, to see origin of erroneous calls to flush())
      3. java AutoFlushBugStream -p


      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      (Output on console:)

      Helloshould run together with 'Hello'Hello world

      (Note that the behavior when calling PrintStream.print("Hello") is in direct contradiction to the assertion made in the comment on bug 4988954.)
      ACTUAL -
      (Output on console:)

      Hello
      should run together with 'Hello'
      H
      e
      l
      l
      o

      w
      o
      r
      l
      d


      REPRODUCIBILITY :
      This bug can be reproduced always.

      ---------- BEGIN SOURCE ----------

      import java.io.ByteArrayOutputStream;
      import java.io.IOException;
      import java.io.PrintStream;

      /**
       * Expose bug in PrintStream autoFlush behavior.
       */
      public class AutoFlushBugStream extends ByteArrayOutputStream {
          /** Maximum number of bytes that can be written before we force the data to be flushed to the log,
              even in the absence of any newlines, to prevent unbounded memory consumption. */
          private static final int MAX_BUFFER_SIZE = 16 * 1024;
          private static final String NL = System.getProperty("line.separator");

          private final String linePrefix;
          
          private boolean printTraces = false;
          private boolean disableFlush = false;
          
          /**
           * There is a significant bug in the JDK (as of 1.7) that causes a PrintStream to flush the
           * underlying stream much more often than it is contractually specified to do so in the
           * standard library JavaDocs. The nature of the bug is such that the default PrintStream
           * behavior causes each individual character written to it to be flushed to the stream, which
           * would result in our logger stream writing each character as an individual log message,
           * instead of only writing a complete line to the log when the newline character(s) sequence
           * is encountered. This class is a workaround that provides a hook in the logger stream to
           * disable the erroneous flushing behavior in the PrintStream. It is somewhat better this way
           * anyway since we have our own mechanism in place to periodically force a flush in the (unlikely)
           * event of a long sequence of bytes not containing any newlines, so as to prevent unbounded
           * memory consumption.
           */
          static final class FlushInterceptorPrintStream extends PrintStream {
              private final AutoFlushBugStream loggerOut;
              private volatile boolean disableFlush = false;
              
              FlushInterceptorPrintStream(AutoFlushBugStream out) {
                  super(out, true);
                  this.loggerOut = out;
              }
              
              public void write(byte buf[], int off, int len) {
                  synchronized (this) {
                      //loggerOut.disableFlush = true;
                      try {
                          super.write(buf, off, len);
                      }
                      finally {
                          //loggerOut.disableFlush = false;
                      }
                  }
              }
          }
          
          
          public AutoFlushBugStream(boolean printTraces) {
              this(printTraces, "");
          }
          
          public AutoFlushBugStream(boolean printTraces, String linePrefix) {
              super(1024);
              this.printTraces = printTraces;
              this.linePrefix = linePrefix;
          }
          
          public void flush() {
              if (disableFlush) {
                  return;
              }
              
              if (printTraces) {
                  // Generates a stack trace that reveals why flush() is being called when it really shouldn't be
                  new Exception("flush()").printStackTrace();
              }
              
              String logText = this.toString();
              int end = logText.length() - (logText.endsWith(NL) ? NL.length() : 0);
              System.out.println(linePrefix + logText.substring(0, end));
              
              this.reset();
          }
          
          public void write(int b) {
              if (this.size() == MAX_BUFFER_SIZE) {
                  this.flush();
              }
              super.write(b);
          }
          
          public void write(byte[] b) throws IOException {
              if (this.size() + b.length >= MAX_BUFFER_SIZE) {
                  this.flush();
              }
              super.write(b);
          }
          
          public void write(byte[] b, int off, int len) {
              if (this.size() + len >= MAX_BUFFER_SIZE) {
                  this.flush();
              }
              super.write(b, off, len);
          }
          
          // The stream returned by this method probably is thread safe due to internal synchronization
          // provided by java.io.PrintStream.
          public static PrintStream createPrintStream(boolean printTraces) {
              return createPrintStream(printTraces, "");
          }
          
          public static PrintStream createPrintStream(boolean printTraces, String linePrefix) {
              return new FlushInterceptorPrintStream(new AutoFlushBugStream(printTraces, linePrefix));
          }
          
          
          public static void main(String[] args) throws Exception {
              boolean printTraces = (args.length >= 1 && args[0].equals("-p"));
              PrintStream bugStream = AutoFlushBugStream.createPrintStream(printTraces);
              bugStream.print("Hello");
              bugStream.print("should run together with 'Hello'");
              // Should further extend what should (so far) be a single line...
              bugStream.print('H');
              bugStream.print('e');
              bugStream.print('l');
              bugStream.print('l');
              bugStream.print('o');
              bugStream.print(' ');
              bugStream.print('w');
              bugStream.print('o');
              bugStream.print('r');
              bugStream.print('l');
              bugStream.print('d');
          }
      }

      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      Uncomment lines 44 and 49:

      44: loggerOut.disableFlush = true
      49: loggerOut.disableFlush = false

      (This completely disables the part of the PrintStream contract that it should flush whenever a byte array is written, so the WAR is imperfect.)

            Unassigned Unassigned
            aefimov Aleksej Efimov
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated: