839275 - mach output is scrambled, confusing mach's warning parser

Status: REOPENED

(Firefox Build System :: Mach Core, enhancement)

Description

[Chris Peterson [:cpeterson]]

This problem looks like a race condition logging to stderr:

 1:46.94 In file inclutded frroma il  /Users/cpe/ob    jtedrson/Coidre /m        oz  on: '--bI2g/diill /Users/cpetersosta/centra     /       l/js/sirc/jnnscal/Copi-tests/u testChdrodeme/mozilla/eB/ufferce nsp   r. n'cpp:5:
 1:46.94 In file included from /Users/cpeterson/Code/mozilla/central/js/src/jsapi-tests/tests.h:8:
 1:46.94 ../../../dist/include/mozilla/Util.tral/o
 1:46.94    bh:2cl a2jd5:nir g-b2g/dist/inc       lude/   33 nc lspr'
 1:46.94 clangang:: : :wa      w a r n irwn ngwarni:n g i ng: a de:a argumer  l e t e d   f u n rncn it unngug:utmesnet di oun d n deu         finis tea r dui g uodmns are a  ri Cn+ eur+gi ng  c11 ex  nt untensic  o          on [ u-msWpc+iol ed m   atdp uion+ :riing comp1 l  1a'-ext -inc ilutlaensions]

The problem seems to happen when I'm using clang to compile files that log many warnings. My legacy mozconfig (for B2G) includes `mk_add_options MOZ_MAKE_FLAGS="-j9 -s"` which may be cause problems.


This also confuses mach's warning parser:

1       -Wc++11+1-ext1-extensions
1       -ons
1       -Wc++11e -extensionsa C++
1       ns
1       -Wc++ ^
1       -Wc: deleted function def++io11-exte fnnnsionss
1	-I /UsWc++e/js11-eapi-testsxtensionrs/cpeterson/Code/mozilla/central/js/src'

Comment 1

[Gregory Szorc [:gps]]

Wow. I haven't seen output this bad before. What's your -j when building?

Anyway, there is nothing mach can do, sadly. Both make and pymake have child processes inherit the stderr and stdout file descriptors from the parent. So, the stderr and stdout file descriptors mach (or the terminal) gets may contain output like this since there is no locking involved. We are at the whim of the buffering of the operating system. Sad panda.

Comment 2

[Chris Peterson [:cpeterson]]

(In reply to Gregory Szorc [:gps] from comment #1)
> Wow. I haven't seen output this bad before. What's your -j when building?

In the example above, my mozconfig contained `mk_add_options MOZ_MAKE_FLAGS="-j9 -s"` but usually I don't specify any -j so mach can do the Right Thing.

Comment 3

[Jeff Hammel]

Strange.  I thought OSX was line buffered for both stdout/stderr.  I was wondering if this was bug 798300 though that is for windows.  Horrible threading issues? (Or, really, issues that system IO libraries were not written thread-compatible?) To be fair I know little of mach or OSX

Comment 4

[Chris Peterson [:cpeterson]]

btw, this stdout/stderr problem only seems to happen when building with clang (for Firefox OSX). Building the same source tree on the same machine with gcc (for Firefox Android) seems to work fine.

Comment 5

[Gregory Szorc [:gps]]

(In reply to Chris Peterson (:cpeterson) from comment #4)
> btw, this stdout/stderr problem only seems to happen when building with
> clang (for Firefox OSX). Building the same source tree on the same machine
> with gcc (for Firefox Android) seems to work fine.

I build with Clang on OS X (although my own compiled version from SVN) and don't experience this.

Just to clear up a loose end, you get "bad" output with |make -f client.mk| as well, right?

Comment 6

[Chris Peterson [:cpeterson]]

(In reply to Gregory Szorc [:gps] from comment #5)
> Just to clear up a loose end, you get "bad" output with |make -f client.mk|
> as well, right?

Curiously, |make -f client.mk| (with an aggressive -j16 in my mozconfig) does NOT repro this problem when building mozilla-inbound. |mach build| seems to be buffering less than |make -f client.mk| because mach's output streams rapidly, but make's output is bursty.

Also, neither |mach build| nor |make -f client.mk| seem to repro the problem when building mozilla-aurora.

Comment 7

[Gregory Szorc [:gps]]

(In reply to Chris Peterson (:cpeterson) from comment #6)
> (In reply to Gregory Szorc [:gps] from comment #5)
> > Just to clear up a loose end, you get "bad" output with |make -f client.mk|
> > as well, right?
> 
> Curiously, |make -f client.mk| (with an aggressive -j16 in my mozconfig)
> does NOT repro this problem when building mozilla-inbound. |mach build|
> seems to be buffering less than |make -f client.mk| because mach's output
> streams rapidly, but make's output is bursty.
> 
> Also, neither |mach build| nor |make -f client.mk| seem to repro the problem
> when building mozilla-aurora.

wat? This defies reason. |mach build| calls out to |make -f client.mk| currently. The only thing I can think of is that gmake buffers differently depending on isatty({stderr, stdout}). However, I don't see isatty() used in the gmake source. Perhaps the OS is taking things into account?

What happens if you |make -f client.mk > logfile|? If that doesn't create bad output, WTF.

Comment 8

[Chris Peterson [:cpeterson]]

|make -f client.mk > logfile| does not create bad output, either in the terminal's stderr or logfile's stdout.

I also tested redirecting |mach build > logfile| and noticed that both stderr and stdout were directed to the log file. The log file's text was scrambled. So perhaps mach's redirecting of stderr to stdout is "crossing the streams", whereas make buffers and flushes stderr and stdout independently.

Comment 9

[Jeff Hammel]

Guessing this could be https://bugzilla.mozilla.org/show_bug.cgi?id=794984 ?

Comment 10

[Gregory Szorc [:gps]]

Reopening since the problem occurs with mach but not client.mk.

I'm guessing this is a mozprocess issue and tools team will handle appropriately.

Comment 11

[Mike Hommey [:glandium]]

Another thing to take into account is that pipes and files can have a different buffering behavior, too. When running in mach, make output is actually redirected to a pipe.

Comment 12

[Jeff Hammel]

(In reply to Gregory Szorc [:gps] from comment #10)
> Reopening since the problem occurs with mach but not client.mk.
> 
> I'm guessing this is a mozprocess issue and tools team will handle
> appropriately.

I'll try to up the priority of bug 794984 a bit.