Bug 65316

Summary: Parallel build sporadic error - UnknownElement.handleErrorOutput
Product: Ant Reporter: Stanislav Šimek <stanislav.simek>
Component: CoreAssignee: Ant Notifications List <notifications>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 1.10.9   
Target Milestone: 1.10.11   
Hardware: PC   
OS: All   

Description Stanislav Šimek 2021-05-19 12:29:36 UTC
Hi all,
may I ask you, I'm facing this sporadic error during execution of this parallel build.

How it possible that "realThing" is null?



    /**
     * Handles error output sent to System.err by this task or its real task.
     *
     * @param output The error output to log. Should not be <code>null</code>.
     */
    protected void handleErrorOutput(String output) {
        if (realThing instanceof Task) {
            ((Task) realThing).handleErrorOutput(output);      <<<<<<<<<<<<<<<<<<<<<<<<<<<<<< Point to this line. 
        } else {
            super.handleErrorOutput(output);
        }
    }


15:56:05 java.lang.NullPointerException
15:56:05 	at org.apache.tools.ant.UnknownElement.handleErrorOutput(UnknownElement.java:262)
15:56:05 	at org.apache.tools.ant.Project.demuxOutput(Project.java:1281)
15:56:05 	at org.apache.tools.ant.taskdefs.Ant.handleErrorOutput(Ant.java:309)
15:56:05 	at org.apache.tools.ant.taskdefs.SubAnt.handleErrorOutput(SubAnt.java:162)
15:56:05 	at org.apache.tools.ant.UnknownElement.handleErrorOutput(UnknownElement.java:262)
15:56:05 	at org.apache.tools.ant.Project.demuxOutput(Project.java:1281)
15:56:05 	at org.apache.tools.ant.DemuxOutputStream.processBuffer(DemuxOutputStream.java:169)
15:56:05 	at org.apache.tools.ant.DemuxOutputStream.write(DemuxOutputStream.java:144)
15:56:05 	at org.apache.tools.ant.DemuxOutputStream.write(DemuxOutputStream.java:241)
15:56:05 	at java.io.PrintStream.write(PrintStream.java:480)
15:56:05 	at net.sf.saxon.serialize.UTF8Writer._flushBuffer(UTF8Writer.java:358)
15:56:05 	at net.sf.saxon.serialize.UTF8Writer.flush(UTF8Writer.java:104)
15:56:05 	at net.sf.saxon.serialize.MessageEmitter.endDocument(MessageEmitter.java:81)
15:56:05 	at net.sf.saxon.event.TreeReceiver.endDocument(TreeReceiver.java:135)
15:56:05 	at net.sf.saxon.event.ProxyReceiver.endDocument(ProxyReceiver.java:118)
15:56:05 	at net.sf.saxon.expr.instruct.Message.processLeavingTail(Message.java:265)
15:56:05 	at net.sf.saxon.expr.instruct.Block.processLeavingTail(Block.java:735)
15:56:05 	at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:352)
15:56:05 	at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:533)
15:56:05 	at net.sf.saxon.trans.XsltController.applyTemplates(XsltController.java:746)
15:56:05 	at net.sf.saxon.s9api.AbstractXsltTransformer.applyTemplatesToSource(AbstractXsltTransformer.java:347)
15:56:05 	at net.sf.saxon.s9api.XsltTransformer.transform(XsltTransformer.java:349)
15:56:05 	at net.sf.saxon.jaxp.TransformerImpl.transform(TransformerImpl.java:71)
15:56:05 	at org.apache.tools.ant.taskdefs.optional.TraXLiaison.transform(TraXLiaison.java:201)
15:56:05 	at org.apache.tools.ant.taskdefs.XSLTProcess.process(XSLTProcess.java:870)
15:56:05 	at org.apache.tools.ant.taskdefs.XSLTProcess.execute(XSLTProcess.java:408)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at java.util.Vector.forEach(Vector.java:1277)
15:56:05 	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:67)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at org.apache.tools.ant.taskdefs.MacroInstance.execute(MacroInstance.java:391)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at java.util.Vector.forEach(Vector.java:1277)
15:56:05 	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:67)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at org.apache.tools.ant.taskdefs.MacroInstance.execute(MacroInstance.java:391)
15:56:05 	at net.sf.antcontrib.logic.ForTask.doSequentialIteration(ForTask.java:259)
15:56:05 	at net.sf.antcontrib.logic.ForTask.doToken(ForTask.java:268)
15:56:05 	at net.sf.antcontrib.logic.ForTask.doTheTasks(ForTask.java:324)
15:56:05 	at net.sf.antcontrib.logic.ForTask.execute(ForTask.java:244)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at java.util.Vector.forEach(Vector.java:1277)
15:56:05 	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:67)
15:56:05 	at net.sf.antcontrib.logic.IfTask.execute(IfTask.java:197)
15:56:05 	at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.TaskAdapter.execute(TaskAdapter.java:155)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at java.util.Vector.forEach(Vector.java:1277)
15:56:05 	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:67)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at org.apache.tools.ant.taskdefs.MacroInstance.execute(MacroInstance.java:391)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at com.siemens.ad.sync.CriticalSection.execute(CriticalSection.java:67)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at org.apache.tools.ant.Target.execute(Target.java:449)
15:56:05 	at org.apache.tools.ant.Target.performTasks(Target.java:470)
15:56:05 	at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1401)
15:56:05 	at org.apache.tools.ant.helper.SingleCheckExecutor.executeTargets(SingleCheckExecutor.java:36)
15:56:05 	at org.apache.tools.ant.Project.executeTargets(Project.java:1264)
15:56:05 	at org.apache.tools.ant.taskdefs.Ant.execute(Ant.java:437)
15:56:05 	at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:306)
15:56:05 	at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:225)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at java.util.Vector.forEach(Vector.java:1277)
15:56:05 	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:67)
15:56:05 	at net.sf.antcontrib.logic.IfTask.execute(IfTask.java:197)
15:56:05 	at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.TaskAdapter.execute(TaskAdapter.java:155)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at com.siemens.ad.sync.CriticalSection.execute(CriticalSection.java:67)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at java.util.Vector.forEach(Vector.java:1277)
15:56:05 	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:67)
15:56:05 	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:292)
15:56:05 	at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at org.apache.tools.ant.taskdefs.MacroInstance.execute(MacroInstance.java:391)
15:56:05 	at sun.reflect.GeneratedMethodAccessor147.invoke(Unknown Source)
15:56:05 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:56:05 	at java.lang.reflect.Method.invoke(Method.java:498)
15:56:05 	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:99)
15:56:05 	at org.apache.tools.ant.Task.perform(Task.java:350)
15:56:05 	at org.apache.tools.ant.taskdefs.Parallel$TaskRunnable.run(Parallel.java:454)
15:56:05 	at java.lang.Thread.run(Thread.java:748)
Comment 1 Jaikiran Pai 2021-05-19 12:33:03 UTC
Hello Stanislav,

Are you sure the version of Ant you are using is the one whose source you are checking? How do you invoke Ant? What's the output of:

ant -v
Comment 2 Jaikiran Pai 2021-05-19 12:34:55 UTC
I just re-read your message again. You say parallel builds and sporadic issue. I think this might be a sign that we have a race condition in that part of the code. Is it possible to share a sample build file which reproduces this (even if sporadically)?
Comment 3 Stanislav Šimek 2021-05-19 13:06:47 UTC
Hi
ant -v shows:
Apache Ant(TM) version 1.10.9 compiled on September 27 2020


Yes the files should be okay. I have checked callstack together with lines and it fits.

I'm really sorry, but I do not have any sample build file. Our build is quite complex.


I saw similar issue during exection of "own java ant task" that contains: 
(Same ant version and again parallel execution)
System.out.println("some text");

20:35:37 java.lang.NullPointerException
20:35:37 	at org.apache.tools.ant.UnknownElement.handleOutput(UnknownElement.java:216)
20:35:37 	at org.apache.tools.ant.Project.demuxOutput(Project.java:1283)
20:35:37 	at org.apache.tools.ant.taskdefs.Ant.handleOutput(Ant.java:251)
20:35:37 	at org.apache.tools.ant.taskdefs.SubAnt.handleOutput(SubAnt.java:105)
20:35:37 	at org.apache.tools.ant.UnknownElement.handleOutput(UnknownElement.java:216)
20:35:37 	at org.apache.tools.ant.Project.demuxOutput(Project.java:1283)
20:35:37 	at org.apache.tools.ant.DemuxOutputStream.processBuffer(DemuxOutputStream.java:169)
20:35:37 	at org.apache.tools.ant.DemuxOutputStream.write(DemuxOutputStream.java:144)
20:35:37 	at org.apache.tools.ant.DemuxOutputStream.write(DemuxOutputStream.java:241)
20:35:37 	at java.io.PrintStream.write(PrintStream.java:480)
20:35:37 	at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
20:35:37 	at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
20:35:37 	at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
20:35:37 	at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
20:35:37 	at java.io.PrintStream.newLine(PrintStream.java:546)
20:35:37 	at java.io.PrintStream.println(PrintStream.java:807)
Comment 4 Stefan Bodewig 2021-05-19 13:25:03 UTC
realThing is set to null in the finally block of execute. There could be a race condition where output is created on the thread that parallel has associated with the thread after the finally block has been run - or rather while the finally block is running in such a way that it has not been null when the instanceof check  happend but became null afterwards.

This is probably not fixable without synchronization.
Comment 5 Stanislav Šimek 2021-05-21 12:05:26 UTC
Okay, sounds good. Does it mean that it will be fixed in feature?
Or I can try to patch on my side. Are there any specific location where synchronization block must be added?
Comment 6 Stefan Bodewig 2021-05-22 11:15:29 UTC
When we started to support parallel execution of tasks Ant's Project instance started to associate executing tasks with threads - there is a ThreadLocal that knows the "current task". If something is sent to System.out/err Project redirects the output to the thread's task's handleOutput. In many cases the "current task" is an UnknownElement. There is a small window between the UnknownElement losing it's "realThing" and Project deregistering the task from the currrent thread (the later happens during the "taskFinished" event).

I think we need to synchronize all parts of the code that reads or writes from realThing. An alternative could be to use a local copy or an AtomicReference instead, though. I'll have a look.
Comment 7 Stefan Bodewig 2021-05-22 11:35:25 UTC
I think this is fixed with commit 96fa99ee6 in the master branch. Any chance you could give it a try?
Comment 8 Stanislav Šimek 2021-05-24 05:01:57 UTC
Hi,
Yes lets give a try. Please be patient, it takes ~ 10 days. To bring it to your build farm. Meanwhile really thank you.
Comment 9 Stanislav Šimek 2021-06-02 07:47:59 UTC
Hi Stefan,
It seems to be okay. Run ~ one week and no problem observed.
Thank you a lot!