Ensure command lines are written synchronously with -O.

If output-sync is enabled, have make write the command line to the temp file
instead of printing it directly to the screen to ensure that the output is
ordered properly.  Also, remove extraneous enter/leave operations by having
them printed directly when dumping temp file output.

5 files changed, 96 insertions, 100 deletions

diff --git a/ChangeLog b/ChangeLog
index 9f30bf7..8632e1a 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,15 @@
+2013-05-05  Paul Smith  <psmith@gnu.org>
+
+	* job.c (child_out): Write newlines explicitly, and don't do
+	anything if the message is empty.
+	(sync_output): Put working dir messages around stdout AND stderr.
+	(start_job_command): Move the tmp file assignment earlier.  After
+	we do it, write the command line to the temp file to get the order
+	correct.
+
+	* misc.c (message): Remove special handling for output_sync.
+	(error): Ditto.
+
 2013-05-04  Paul Smith  <psmith@gnu.org>
 
 	* loadapi.c (gmk_alloc): New function.
diff --git a/job.c b/job.c
index 0389866..726cca8 100644
--- a/job.c
+++ b/job.c
@@ -478,14 +478,17 @@ child_out (const struct child *child, const char *msg, int out)
 {
   int fd = out ? child->outfd : child->errfd;
 
+  if (!msg || msg[0] == '\0')
+    return;
+
   if (fd >= 0)
     {
       int len = strlen (msg);
+      int b;
 
       lseek (fd, 0, SEEK_END);
       while (1)
         {
-          int b;
           EINTRLOOP (b, write (fd, msg, len));
           if (b == len)
             break;
@@ -494,12 +497,14 @@ child_out (const struct child *child, const char *msg, int out)
           len -= b;
           msg += b;
         }
+      EINTRLOOP (b, write (fd, "\n", 1));
     }
   else
     {
       FILE *f = out ? stdout : stderr;
       fputs (msg, f);
       fflush (f);
+      putc ('\n', f);
     }
 }
 
@@ -548,7 +553,7 @@ child_error (const struct child *child,
   l = strlen (pre) + strlen (f->name) + strlen (post);
 
 #ifdef VMS
-  if (exit_code & 1 != 0)
+  if ((exit_code & 1) != 0)
     return;
 
   msg = error_s (l + INTEGER_LENGTH, NILF,
@@ -651,28 +656,28 @@ sync_init ()
 static void
 assign_child_tempfiles (struct child *c)
 {
-  /* If we have a temp file, we're done.  */
-  if (c->outfd >= 0 || c->errfd >= 0)
-    return;
-
-  if (STREAM_OK (stdout))
-    {
-      c->outfd = open_tmpfd ();
-      if (c->outfd < 0)
-        goto error;
-      CLOSE_ON_EXEC (c->outfd);
-    }
-
-  if (STREAM_OK (stderr))
+  /* If we don't have a temp file, get one.  */
+  if (c->outfd < 0 && c->errfd < 0)
     {
-      if (c->outfd >= 0 && combined_output)
-        c->errfd = c->outfd;
-      else
+      if (STREAM_OK (stdout))
         {
-          c->errfd = open_tmpfd ();
-          if (c->errfd < 0)
+          c->outfd = open_tmpfd ();
+          if (c->outfd < 0)
             goto error;
-          CLOSE_ON_EXEC (c->errfd);
+          CLOSE_ON_EXEC (c->outfd);
+        }
+
+      if (STREAM_OK (stderr))
+        {
+          if (c->outfd >= 0 && combined_output)
+            c->errfd = c->outfd;
+          else
+            {
+              c->errfd = open_tmpfd ();
+              if (c->errfd < 0)
+                goto error;
+              CLOSE_ON_EXEC (c->errfd);
+            }
         }
     }
 
@@ -765,14 +770,12 @@ sync_output (struct child *c)
 
       /* We've entered the "critical section" during which a lock is held.
          We want to keep it as short as possible.  */
+      log_working_directory (1, 1);
       if (outfd_not_empty)
-        {
-          log_working_directory (1, 1);
           pump_from_tmp (c->outfd, stdout);
-          log_working_directory (0, 1);
-        }
       if (errfd_not_empty && c->errfd != c->outfd)
         pump_from_tmp (c->errfd, stderr);
+      log_working_directory (0, 1);
 
       /* Exit the critical section.  */
       if (sem)
@@ -1375,7 +1378,8 @@ start_job_command (struct child *child)
 #if !defined(_AMIGA) && !defined(WINDOWS32)
   static int bad_stdin = -1;
 #endif
-  int sync_cmd = 0;
+  int print_cmd;
+  int sync_cmd;
   char *p;
   /* Must be volatile to silence bogus GCC warning about longjmp/vfork.  */
   volatile int flags;
@@ -1503,13 +1507,40 @@ start_job_command (struct child *child)
       return;
     }
 
-  /* Print out the command.  If silent, we call 'message' with null so it
-     can log the working directory before the command's own error messages
-     appear.  */
+  print_cmd = (just_print_flag || trace_flag
+               || (!(flags & COMMANDS_SILENT) && !silent_flag));
 
-  message (0, (just_print_flag || trace_flag
-               || (!(flags & COMMANDS_SILENT) && !silent_flag))
-	   ? "%s" : (char *) 0, p);
+#ifdef OUTPUT_SYNC
+  if (output_sync && sync_handle == -1)
+    sync_init();
+#endif
+
+  /* Are we going to synchronize this command's output?  Do so if either we're
+     in SYNC_MAKE mode or this command is not recursive.  We'll also check
+     output_sync separately below in case it changes due to error.  */
+  sync_cmd = output_sync && (output_sync == OUTPUT_SYNC_MAKE
+                             || !(flags & COMMANDS_RECURSE));
+
+#ifdef OUTPUT_SYNC
+  if (sync_cmd)
+    {
+      /* If syncing, make sure we have temp files.
+         Write the command to the temp file so it's output in order.  */
+      assign_child_tempfiles (child);
+      if (print_cmd)
+        child_out (child, p, 1);
+    }
+  else
+    /* We don't want to sync this command: to avoid misordered
+       output ensure any already-synced content is written.  */
+    sync_output (child);
+#endif /* OUTPUT_SYNC */
+
+  /* If we're not syncing, print out the command.  If silent, we call
+     'message' with null so it can log the working directory before the
+     command's own error messages appear.  */
+  if (! sync_cmd)
+    message (0, print_cmd ? "%s" : NULL, p);
 
   /* Tell update_goal_chain that a command has been started on behalf of
      this target.  It is important that this happens here and not in
@@ -1563,11 +1594,6 @@ start_job_command (struct child *child)
   fflush (stdout);
   fflush (stderr);
 
-  /* Are we going to synchronize this command's output?  Do so if either we're
-     in SYNC_MAKE mode or this command is not recursive.  We'll also check
-     output_sync separately below in case it changes due to error.  */
-  sync_cmd = output_sync == OUTPUT_SYNC_MAKE || !(flags & COMMANDS_RECURSE);
-
 #ifndef VMS
 #if !defined(WINDOWS32) && !defined(_AMIGA) && !defined(__MSDOS__)
 
@@ -1692,19 +1718,6 @@ start_job_command (struct child *child)
 
 #else  /* !__EMX__ */
 
-#ifdef OUTPUT_SYNC
-      if (output_sync && sync_handle == -1)
-        sync_init();
-
-      if (output_sync && sync_cmd)
-        /* If we still want to sync, make sure we have temp files. */
-        assign_child_tempfiles (child);
-      else
-        /* We don't want to sync this command: to avoid misordered
-           output ensure any already-synched content is written.  */
-        sync_output (child);
-#endif /* OUTPUT_SYNC */
-
       child->pid = vfork ();
       environ = parent_environ;	/* Restore value child may have clobbered.  */
       if (child->pid == 0)
@@ -1831,19 +1844,6 @@ start_job_command (struct child *child)
       HANDLE hPID;
       char* arg0;
 
-#ifdef OUTPUT_SYNC
-      if (output_sync && sync_handle == -1)
-        sync_init();
-
-      if (output_sync && sync_cmd)
-        /* If we still want to sync, make sure we have temp files. */
-        assign_child_tempfiles (child);
-      else
-        /* We don't want to sync this command: to avoid misordered output
-           ensure any already-synched content is written.  */
-        sync_output (child);
-#endif /* OUTPUT_SYNC */
-
       /* make UNC paths safe for CreateProcess -- backslash format */
       arg0 = argv[0];
       if (arg0 && arg0[0] == '/' && arg0[1] == '/')
diff --git a/misc.c b/misc.c
index 766874f..2a6c6ea 100644
--- a/misc.c
+++ b/misc.c
@@ -179,11 +179,11 @@ concat (unsigned int num, ...)
   return result;
 }
 
-/* If we had a standard-compliant vsnprintf() this would be a lot simpler.
-   Maybe in the future we'll include gnulib's version.  */
 
 /* Return a formatted string buffer.
-   LENGTH must be the maximum length of all format arguments, stringified.  */
+   LENGTH must be the maximum length of all format arguments, stringified.
+   If we had a standard-compliant vsnprintf() this would be a lot simpler.
+   Maybe in the future we'll include gnulib's version.  */
 
 const char *
 message_s (unsigned int length, int prefix, const char *fmt, ...)
@@ -215,8 +215,6 @@ message_s (unsigned int length, int prefix, const char *fmt, ...)
   vsprintf (bp, fmt, args);
   va_end (args);
 
-  strcat (bp, "\n");
-
   return buffer;
 }
 
@@ -253,8 +251,6 @@ error_s (unsigned int length, const gmk_floc *flocp, const char *fmt, ...)
   vsprintf (bp, fmt, args);
   va_end (args);
 
-  strcat (bp, "\n");
-
   return buffer;
 }
 
@@ -270,9 +266,6 @@ message (int prefix, const char *fmt, ...)
 
   if (fmt != 0)
     {
-      if (output_sync)
-        log_working_directory (1, 1);
-
       if (prefix)
 	{
 	  if (makelevel == 0)
@@ -284,9 +277,6 @@ message (int prefix, const char *fmt, ...)
       vfprintf (stdout, fmt, args);
       va_end (args);
       putchar ('\n');
-
-      if (output_sync)
-        log_working_directory (0, 1);
     }
 
   fflush (stdout);
@@ -299,10 +289,7 @@ error (const gmk_floc *flocp, const char *fmt, ...)
 {
   va_list args;
 
-  if (output_sync)
-    log_working_directory (1, 1);
-  else
-    log_working_directory (1, 0);
+  log_working_directory (1, 0);
 
   if (flocp && flocp->filenm)
     fprintf (stderr, "%s:%lu: ", flocp->filenm, flocp->lineno);
@@ -317,9 +304,6 @@ error (const gmk_floc *flocp, const char *fmt, ...)
 
   putc ('\n', stderr);
   fflush (stderr);
-
-  if (output_sync)
-    log_working_directory (0, 1);
 }
 
 /* Print an error message and exit.  */
diff --git a/tests/ChangeLog b/tests/ChangeLog
index ade64f0..4d11706 100644
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,9 @@
+2013-05-05  Paul Smith  <psmith@gnu.org>
+
+	* scripts/features/output-sync (output_sync_set): Remove
+	extraneous enter/leave lines, which are no longer printed.
+	Add tests for syncing command line printing.
+
 2013-05-04  Paul Smith  <psmith@gnu.org>
 
 	* scripts/features/loadapi: Use the new alloc functions.
diff --git a/tests/scripts/features/output-sync b/tests/scripts/features/output-sync
index a1560ad..e7edfce 100644
--- a/tests/scripts/features/output-sync
+++ b/tests/scripts/features/output-sync
@@ -127,14 +127,11 @@ make-foo: ; \$(MAKE) -C foo
 make-bar: ; \$(MAKE) -C bar!,
               '-j -Omake',
 "#MAKEPATH# -C foo
-#MAKEPATH# -C bar
-#MAKE#[1]: Entering directory '#PWD#/foo'
 #MAKE#[1]: Entering directory '#PWD#/foo'
 foo: start
 foo: end
 #MAKE#[1]: Leaving directory '#PWD#/foo'
-#MAKE#[1]: Leaving directory '#PWD#/foo'
-#MAKE#[1]: Entering directory '#PWD#/bar'
+#MAKEPATH# -C bar
 #MAKE#[1]: Entering directory '#PWD#/bar'
 bar: start
 bar: end
@@ -142,7 +139,6 @@ bar: end
 #MAKE#[1]: Entering directory '#PWD#/bar'
 baz: start
 baz: end
-#MAKE#[1]: Leaving directory '#PWD#/bar'
 #MAKE#[1]: Leaving directory '#PWD#/bar'\n", 0, 6);
 
 # Test per-target synchronization.
@@ -160,8 +156,6 @@ make-bar: ; $sleep_command 1 ; \$(MAKE) -C bar!,
               '-j --output-sync=target',
 "#MAKEPATH# -C foo
 $sleep_command 1 ; #MAKEPATH# -C bar
-#MAKE#[1]: Entering directory '#PWD#/foo'
-#MAKE#[1]: Entering directory '#PWD#/bar'
 #MAKE#[1]: Entering directory '#PWD#/bar'
 bar: start
 bar: end
@@ -170,11 +164,9 @@ bar: end
 foo: start
 foo: end
 #MAKE#[1]: Leaving directory '#PWD#/foo'
-#MAKE#[1]: Leaving directory '#PWD#/foo'
 #MAKE#[1]: Entering directory '#PWD#/bar'
 baz: start
 baz: end
-#MAKE#[1]: Leaving directory '#PWD#/bar'
 #MAKE#[1]: Leaving directory '#PWD#/bar'\n", 0, 6);
 
 # Test that messages from make itself are enclosed with
@@ -189,20 +181,16 @@ make-bar-bar: ; $sleep_command 1 ; \$(MAKE) -C bar bar!,
               '-j -O',
 "#MAKEPATH# -C foo foo-fail
 $sleep_command 1 ; #MAKEPATH# -C bar bar
-#MAKE#[1]: Entering directory '#PWD#/foo'
-#MAKE#[1]: Entering directory '#PWD#/bar'
 #MAKE#[1]: Entering directory '#PWD#/bar'
 bar: start
 bar: end
 #MAKE#[1]: Leaving directory '#PWD#/bar'
-#MAKE#[1]: Leaving directory '#PWD#/bar'
 #MAKE#[1]: Entering directory '#PWD#/foo'
 foo-fail: start
 foo-fail: end
 Makefile:20: recipe for target 'foo-fail' failed
 #MAKE#[1]: *** [foo-fail] Error 1
 #MAKE#[1]: Leaving directory '#PWD#/foo'
-#MAKE#[1]: Leaving directory '#PWD#/foo'
 #MAKEFILE#:4: recipe for target 'make-foo-fail' failed
 #MAKE#: *** [make-foo-fail] Error 2\n",
 512);
@@ -224,20 +212,16 @@ make-bar: ; $sleep_command 1 ; \$(MAKE) -C bar bar-job!,
 "#MAKEPATH# -C foo foo-job
 $sleep_command 1 ; #MAKEPATH# -C bar bar-job
 #MAKE#[1]: Entering directory '#PWD#/foo'
-#MAKE#[1]: Entering directory '#PWD#/foo'
 foo: start
 #MAKE#[1]: Leaving directory '#PWD#/foo'
 #MAKE#[1]: Entering directory '#PWD#/bar'
-#MAKE#[1]: Entering directory '#PWD#/bar'
 bar: start
 #MAKE#[1]: Leaving directory '#PWD#/bar'
 #MAKE#[1]: Entering directory '#PWD#/bar'
 bar: end
 #MAKE#[1]: Leaving directory '#PWD#/bar'
-#MAKE#[1]: Leaving directory '#PWD#/bar'
 #MAKE#[1]: Entering directory '#PWD#/foo'
 foo: end
-#MAKE#[1]: Leaving directory '#PWD#/foo'
 #MAKE#[1]: Leaving directory '#PWD#/foo'\n", 0, 6);
 
 
@@ -254,5 +238,15 @@ all:
 
 run_make_test(undef, '-j -Otarget', "foo\nbar\n");
 
+# Ensure when make writes out command it's not misordered
+run_make_test(qq!
+all:
+\t\@echo foobar
+\ttrue
+!,
+              '-j -Ojob', "foobar\ntrue\n");
+
+run_make_test(undef, '-j -Otarget', "foobar\ntrue\n");
+
 # This tells the test driver that the perl test script executed properly.
 1;