Why does program output redirection make the output of its sub-processes to be out of order?

Question

In my program in C, running on Linux, which creates sub-processes using system() I noticed that when I redirected stdout to a pipe or to a file then the output of the sub-processes was sent before the output of buffered I/O functions like printf(). When stdout was left to go to the terminal then the output was in the expected order. I simplified the program to the following example:

#include <stdio.h>
#include <stdlib.h>

int main(void)
{
    printf("1. output from printf()\n");
    system("echo '2. output from a command called using system()'");

    return EXIT_SUCCESS;
}

The expected output when stdout goes to the terminal:

$ ./iobuffer
1. output from printf()
2. output from a command called using system()

The output out of order when stdout is redirected to a pipe or a file:

$ ./iobuffer | cat
2. output from a command called using system()
1. output from printf()

Answer 1

A terminal generally uses line-buffering, while a pipe would use block buffering.

This means that your printf call, which includes a newline, will fill the line buffer, triggering a flush. When redirecting, no flush takes place until the program completes.

echo on the other hand, always flushes the buffer it is writing to when it completes.

With line buffering (terminal output), the order is:

• printf() prints a line with newline, buffer is flushed, you see 1. output from printf() being printed.
• echo writes output, exits, flushes the buffer, you see 2. output from a command called using system() printed.

With block buffering, the order is:

• printf() prints a line with newline, not fully filling the buffer.
• echo writes output, exits, flushes the buffer, you see 2. output from a command called using system() printed.
• Your program exits, flushes its block buffer, you see 1. output from printf() being printed.

Your options are to use to flush explicitly using fflush() or to set the buffering on stdout explicitly with setvbuf().

Answer 2

This reply is complementing the reply of Martijn Pieters. Citations of sources describing the default buffering modes of streams are at the end.

Solutions

Here are three basic solutions with explanation:

a) Flush the buffers before calling a sub-process. This option could be significantly more effective when you do a lot of output from the main program and just few sub-process calls.

printf("1. output from printf()\n");
fflush(stdout);
system("echo '2. output from a command called using system()'");

b) Change the buffering of stdout to line-buffering (or unbuffered) for the whole program. This option is a small change to the program as you call sevbuf() only at the beginning and the rest of the program stays the same.

if(setvbuf(stdin, NULL, _IOLBF, BUFSIZ))
    err(EXIT_FAILURE, NULL);
printf("1. output from printf()\n");
system("echo '2. output from a command called using system()'");

Edit:
c) Change the buffering of stdout to line-buffering (or unbuffered) for the whole program by an external utility. This option does not change the program at all so you do not need to recompile or even have sources of the program. You just call the program using the stdbuf utility.

$ stdbuf -oL ./iobuffer | cat
1. output from printf()
2. output from a command called using system()

References - describing why the buffering mode changes

The initial buffering setting is described for example in the documents below. Streams to interactive devices like terminal are by default line-buffered so that newline-ended messages appear immediately on the terminal. Pipes, files etc. use block-buffering (or full-buffering) for better performance.

The GNU C Library Reference Manual
http://www.gnu.org/software/libc/manual/html_node/Buffering-Concepts.html#Buffering-Concepts

Newly opened streams are normally fully buffered, with one exception: a stream connected to an interactive device such as a terminal is initially line buffered.

Linux man-pages: stdin (3)
http://linux.die.net/man/3/stdin

The stream stderr is unbuffered. The stream stdout is line-buffered when it points to a terminal. Partial lines will not appear until fflush(3) or exit(3) is called, or a newline is printed. This can produce unexpected results, especially with debugging output. The buffering mode of the standard streams (or any other stream) can be changed using the setbuf(3) or setvbuf(3) call.

There are also a mention of the buffering of a terminal driver.

ISO/IEC 9899:201x C11 Committee Draft — April 12, 2011; 7.21.3 Files, page 301
http://www.open-std.org/jtc1/sc22/wg14/www/docs/n1570.pdf

As initially opened, the standard error stream is not fully buffered; the standard input and standard output streams are fully buffered if and only if the stream can be determined not to refer to an interactive device.

The Open Group: System Interfaces and Headers Issue 4, Version 2; 2.4 Standard I/O Streams, page 32
https://www2.opengroup.org/ogsys/catalog/C435 (free registration needed for download)

When opened, the standard error stream is not fully buffered; the standard input and standard output streams are fully buffered if and only if the stream can be determined not to refer to an interactive device.

There is also a very interesting chapter 2.4.1 "Interaction of File Descriptors and Standard I/O Streams" about combining of buffered and unbuffered I/O which somewhat relates to sub-process calls.