Problems creating *.obj.log files

[Erik Joelsson]

Hello Ralf,

Very interesting analysis! I have spent a lot of time trying to get the 
piping to log files, while keeping out/err separation working with as 
little performance impact as possible. I was aware of problem 3, which 
causes some annoying output ordering sometimes, but I had not 
encountered 1 and 2 before. Checking my latest local Windows build, I do 
indeed have some truncated files, not as many as you, but still 79 (less 
virus scanning). That would certainly make incremental builds unreliable.

I tried your suggestion for problem 1 and it works for me too. We should 
definitely get that fix in. I have filed JDK-8207001. Do you mind if I 
use your patch for it?

I agree on the only solution for the 3rd problem, but I would not want 
to go there. Delaying output can have lots of weird consequences, if you 
for example interrupt a build with ctrl-c.

Another option would be to revert to our previous solution, where we 
used this script: 
http://hg.openjdk.java.net/jdk8u/jdk8u/file/090b27d25e19/common/bin/logger.sh 
The problem with that was performance as it created more extra shell 
instances for each compile command.

The only solution to fix problem 2 would be to stop separating out/err. 
I wonder how big of a problem that actually is though?

/Erik


On 2018-07-10 05:34, Schmelter, Ralf wrote:
> Hi,
>
> while building openjdk on Windows, I've stumbled over a problem which leads to truncated *.obj.log files, which in turn leads to empty dependency files (which are generated from the contents of the *.obj.log files on Windows). In the end, the incremental build will not be reliable.
>
> The reason seems to be this code from the ExecuteWithLog macro in common/MakeBase.gmk:
> ( $(strip $2) > >($(TEE) $(strip $1).log) 2> >($(TEE) $(strip $1).log >&2) || \
>      ...
>
> This executes the command given in $2 and tries to write stdout/stderr to the file given by $1 and to 'normal' stdout/stderr via process substitution. But it has a few problems.
>
> The first problem occurs when the stdout-tee truncates the file, then it writes some of the input it got into the file and only after this the stderr-tee has run far enough to truncate the same file, which leads to the loss of at least a part of stdout.
>
> Another problem appears when the command writes to stdout and stderr. Since each tee has its own file position, they would overwrite one another.
>
> The third problem arises because when the command $2 has ended, the bash shell will not wait for the process substitutions (the two tee commands) to end and instead will process the next command. Here we try to copy the log file in case of an error. But the tee commands might not have written the whole input they have got, so not the whole content of the file might get copied.
>
>
> In my case it seems to be the first problem which I see most. When doing a fresh build on my Windows machine (which has quite an aggressive virus scanner active), I get something like the following:
>> find . -name "*.obj.log" -size 0 | wc -l
> 424
>
>> find . -name "*.obj.log" -not -size 0 | wc -l
> 1603
>
> Which means about 20% of the *.obj.log files are truncated.
>
> When I replace the code above with:
>    ( $(strip $2) > >($(TEE) $(strip $1).log) 2>&1 || \
>      ...
>
> I see no more truncated *.obj.log files. The cost is that stderr is redirected to stdout (since the >&2 of the second tee is missing). The last problem can be avoided by using something like:
>    ($(RM) -f $(strip $1).log && $(strip $2) > >($(TEE) -a $(strip $1).log) 2> >($(TEE) -a $(strip $1).log >&2) || \
>      ...
>
> This also leads to no truncated files, but the relative order of stdout/stderr might be wrong.
>
> If the third problem should be solved too, the only solution I've found was to redierect via >  $(strip $1).log  2>&1 to the file and then later use 'cat' to write the output to stdout (losing the distinction between stdout and stderr).
>
> Best regards,
> Ralf