Bug 50507 - Exec task may mix the stderr and stdout output while logging it
Exec task may mix the stderr and stdout output while logging it
Status: RESOLVED FIXED
Product: Ant
Classification: Unclassified
Component: Core tasks
1.8.2
PC Windows XP
: P2 critical with 1 vote (vote)
: 1.8.3
Assigned To: Ant Notifications List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2010-12-21 13:57 UTC by William Bernardet
Modified: 2012-03-05 16:10 UTC (History)
1 user (show)



Attachments
Merging the streams on a line basis (3.22 KB, application/octet-stream)
2010-12-22 05:31 UTC, William Bernardet
Details

Note You need to log in before you can comment on or make changes to this bug.
Description William Bernardet 2010-12-21 13:57:02 UTC
It looks like Ant 1.8.1 (also verified with future 1.8.2 from CI https://hudson.apache.org/hudson/view/A-F/view/Ant/job/Ant_Nightly/187/artifact/) can mix stderr and stdout stream output while logging it. The following example can easily help to reproduce the issue:
<?xml version="1.0">
<project>
    <target name="demo">
        <exec executable="${ant.home}/bin/ant.bat">
            <arg value="-f" />
            <arg file="${ant.file}" />
            <arg value="generate-output" />
        </exec>
    </target>

    <target name="generate-output">
        <echo>${ant.version}</echo>
        <echo message="some blablablablablablablablablablablabla error message" level="error" />
        <echo message="some blablablablablablablablablablablabla info message" level="info" />
        <echo message="some blablablablablablablablablablablabla error message" level="error" />
        <echo message="some blablablablablablablablablablablabla info message" level="info" />
        <echo message="some blablablablablablablablablablablabla error message" level="error" />
        <echo message="some blablablablablablablablablablablabla info message" level="info" />
        <echo message="some blablablablablablablablablablablabla error message" level="error" />
        <echo message="some blablablablablablablablablablablabla info message" level="info" />
        <echo message="some blablablablablablablablablablablabla error message" level="error" />
        <echo message="some blablablablablablablablablablablabla info message" level="info" />
    </target>
</project>

Executed with Ant 1.8.1, a message on stderr can be printed in the middle of an another message coming from stdout:

C:\...>ant demo
Buildfile: C:\apps\test\build.xml

demo:
     [exec] Buildfile: C:\apps\test\build.xml
     [exec]
     [exec] generate-output:
     [exec]      [echo] Apache Ant version 1.8.1 compiled on April 30 2010
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla in     [echo]
some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec] fo message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]
     [exec] BUILD SUCCESSFUL
     [exec] Total time: 0 seconds

BUILD SUCCESSFUL
Total time: 1 second

Same script executed with Ant 1.7.0 will log the output of each stream correctly (line by line):

C:\apps\test>ant demo
Buildfile: build.xml

demo:
     [exec] Buildfile: C:\apps\test\build.xml
     [exec]
     [exec] generate-output:
     [exec]      [echo] Apache Ant version 1.7.0 compiled on December 13 2006
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla info message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]      [echo] some blablablablablablablablablablablabla error message
     [exec]
     [exec] BUILD SUCCESSFUL
     [exec] Total time: 0 seconds
Comment 1 Antoine Levy-Lambert 2010-12-21 15:21:59 UTC
I can reproduce this on Windows. It is not a systematic bug.
It is similar or the same bug like 48746
Comment 2 William Bernardet 2010-12-22 02:33:40 UTC
Do you think this issue will be addressed in 1.8.2?
Comment 3 William Bernardet 2010-12-22 05:31:55 UTC
Created attachment 26439 [details]
Merging the streams on a line basis
Comment 4 William Bernardet 2010-12-22 05:34:44 UTC
(In reply to comment #3)
> Created an attachment (id=26439) [details]
> Merging the streams on a line basis

Actually the issue is coming from the merging of stdout and stderr by the OutputStreamFunneler class without having any consideration about line ending.
Comment 5 Antoine Levy-Lambert 2010-12-22 10:47:22 UTC
William thanks very much for the patch. A release candidate for 1.8.2 is already built and should be released officially on 12/27. Your patch can make it into 1.8.3 if it passes the tests and no one sees architectural or performance problems with it. Do not worry, we can build 1.8.3 relatively fast after 1.8.2.
Comment 6 Antoine Levy-Lambert 2011-04-21 10:58:58 UTC
Patch committed. Thanks.

Additionally, I have made flush a no op in LineOrientedOutputStream.
Comment 8 Stefan Bodewig 2011-12-04 10:46:27 UTC
and svn revision 1210088 - see bug 52283
Comment 9 Jesse Glick 2012-02-23 19:41:21 UTC
This test fails in trunk using JDK 5u22 or 6u31 or 7u3 on Ubuntu:

src/etc/testcases/taskdefs/exec/exec.xml:60: output indicates a mixup of out and err
	at org.apache.tools.ant.taskdefs.Exit.execute(Exit.java:164)
...
	at org.apache.tools.ant.taskdefs.ExecTaskTest.testOutAndErr(ExecTaskTest.java:108)

Sometimes it passes, but usually it fails. I made the test better report the failure, showing the following output:

doit:
blabla:
blabla:
     [exec] some blablablablablablablablablablablabla info message outsome blablablablablablablablablablablabla error message err
     [exec] 
     [exec] some blablablablablablablablablablablabla info message outsome blablablablablablablablablablablabla error message err
     [exec] 
blabla:
     [exec] some blablablablablablablablablablablabla error message errsome blablablablablablablablablablablabla info message out
     [exec] 
blabla:
blabla:
blabla:
blabla:
     [exec] some blablablablablablablablablablablabla error message errsome blablablablablablablablablablablabla info message out
     [exec] 
blabla:
blabla:
blabla:
Comment 10 Jesse Glick 2012-03-05 16:10:44 UTC
Committed revision 1297113 to disable the test since it consistently fails for me on Ubuntu, and according to [1] on the CI builder as well.

[1] https://builds.apache.org/job/Ant_JDK_1.5_Test/452/testReport/org.apache.tools.ant.taskdefs/ExecTaskTest/testOutAndErr/