RFR: JDK-8207001: *.obj.log files get truncated causing unreliable incremental builds on Windows

[Erik Joelsson]

Please review this fix for problem 1 described below. The patch is 
basically what Ralf suggested.

Bug: https://bugs.openjdk.java.net/browse/JDK-8207001
Webrev: http://cr.openjdk.java.net/~erikj/8207001/webrev.01/

/Erik


On 2018-07-10 10:34, Erik Joelsson wrote:
> 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
>