Results of printf() and system() are in the wrong order when output is redirected to a file [duplicate]

Question

I have a C program that compiles to an executable called myprogram. This is its main function:

int main(int argc, char ** argv) {
  printf("this is a test message.\n");
  system("ls");

  return 0;
}

When I run myprogram > output.txt in a Linux shell and then examine output.txt, I see the output of ls listed above "this is a test message."

I feel like it should be the other way around. Why is this happening, and what can I do so that "this is a test message" appears at the top of output.txt?

If it matters, I'm new to both C and working in a command line.

Unlade

When you mix different output and input buffers but don't bother to flush your output, there's no guarantee what order they'll get written out. Your printf output could get written out before, after, or even in the middle of the ls output! Granted, having output written out in the middle of other output is rare, but I've seen it happen. Intuitively you think "There's no way one line of output could get written out in the middle of another one," but when you actually see it happen, your perception of reality is challenged. – Shockproof

You need to flush for printed stuff to be printed immediately. – Checklist

Answer 1

By default output to stdout is line-buffered when connected to a terminal. That is, the buffer is flushed when it's full or when you add a newline.

However, if stdout is not connected to a terminal, like what happens when you redirect the output from your program to a file, then stdout becomes fully buffered. That means the buffer will be flushed and actually written either when it's full or when explicitly flushed (which happens when the program exits).

This means that the output of a separate process started from your code (like what happens when you call system) will most likely be written first, since the buffer of that process will be flushed when that process ends, which is before your own process.

What happens when using redirection (or pipes for that matter):

1. Your printf call writes to the stdout buffer.
2. The system function starts a new process, which writes to its own buffer.
3. When the external process (started by your system call) exits, its buffer is flushed and written. Your own buffer in your own process, isn't touched.
4. Your own process ends, and your stdout buffer is flushed and written.

To get the output in the "correct" (or at least expected) order, call fflush before calling system, to explicitly flush stdout, or call setbuf before any output to disable buffering completely.

Wiese

Out of curiosity: Does the program output correctly even if fflush is called after system, or the system does everything ( including its own fflush ) in that call? – Dark

Another curious question - doesn't the output of system() also end up in the same stdout buffer that printf() used before? After all, it didn't bypass it and write directly to console. The stdouts of both programs were chained - as is evident by the fact that both ended up in output.txt. – Tableland

@Vilx-, no, stdio is a library, the buffers it uses exist in memory of the process. system() starts a new process with a separate memory space, and hence separate buffers. The child process does inherit the file descriptor from the parent, though, which is why the output goes to the same file. The difference between the OS-level file descriptors and the write() system call; and the C library FILE streams and printf() (etc.) is important here. – Garret

Your answer glosses over one detail that maybe the OP should be aware of: The stdout variable in the C program holds a pointer to a libc FILE object, but what is shared by the two processes is an open file descriptor. – Hysterogenic

Answer 2

It is related to output buffering. I managed to reproduce the same behaviour. Forcing the flush did it for me.

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

int main(int argc, char ** argv) {
  printf("this is a test message.\n");
  fflush(stdout);
  system("ls");

  return 0;
}

Before adding the fflush:

$ ./main > foo
$ cat foo
main
main.c
this is a test message.

and after:

$ ./main > foo
$ cat foo
this is a test message.
foo
main
main.c

Dennie

Answer 3

I suspect it's because of the order in which the stdout buffer gets flushed, which is not necessarily deterministic. It's possible that the parent spawns the ls process and doesn't flush its own stdout until after that returns. It may not actually flush stdout until the process exits.

Try adding fflush (stdout) after the printf statement and see if that forces the output to appear first.

Willin