[CLOUDBEES-2018] fixing the root cause.

kohsuke · kohsuke · commit dcbdbcc50702 · 2011-12-16T18:29:31.000-08:00
At some point after this code was originally written, I/O in remoting
became asynchronous. So we need to sync with that before we swap out
the new log output stream, or else you cut off stuff at the wrong
moment.

Normally the command transfer in remoting is slow enough that
you get more or less synchronized output anyway, which is why
this poblem remained unnoticed.

But if the uncliamed buffer gets large, write operation will take a long
time, which makes this issue more likely to show up.

This fix address this problem by doing a proper sync.
The recycling of ByteArrayOutputStream is also disabled because it makes
synchronization tricky.
diff --git a/changelog.html b/changelog.html
@@ -57,6 +57,8 @@
 <ul class=image>
   <li class=rfe>
     Update center UI improvement. "Install" button is now always visisble.
+  <li class=bug>
+    Fixed a bug where a large output from Maven can cause module log output to go out of sync with module build log files.
   <li class=bug>
     Fixed prematurely re-drawn matrix test result graph.
 </ul>
diff --git a/maven-plugin/src/main/java/hudson/maven/MavenBuild.java b/maven-plugin/src/main/java/hudson/maven/MavenBuild.java
@@ -50,7 +50,6 @@
 import hudson.util.DescribableList;
 import hudson.util.IOUtils;
 import org.apache.maven.BuildFailureException;
-import org.apache.maven.artifact.versioning.ComparableVersion;
 import org.apache.maven.execution.MavenSession;
 import org.apache.maven.execution.ReactorManager;
 import org.apache.maven.lifecycle.LifecycleExecutionException;
@@ -478,6 +477,7 @@ public void start() {
             onStartBuilding();
             startTime = System.currentTimeMillis();
             try {
+                sync();
                 listener.setSideOutputStream(log);
             } catch (IOException e) {
                 e.printStackTrace();
@@ -491,6 +491,7 @@ public void end() {
             duration += System.currentTimeMillis()- startTime;
             parentBuild.notifyModuleBuild(MavenBuild.this);
             try {
+                sync();
                 listener.setSideOutputStream(null);
                 save();
             } catch (IOException e) {
@@ -503,18 +504,33 @@ public void end() {
          */
         public void appendLastLog() {
             try {
+                sync();
                 listener.setSideOutputStream(log);
                 listener.setSideOutputStream(null);
             } catch (IOException e) {
                 e.printStackTrace();
             }
         }
 
+        /**
+         * Before we touch I/O streams, we need to make sure all the remote I/O operations are locally completed,
+         * or else we end up switching the log traffic at unaligned moments.
+         */
+        private void sync() {
+            try {
+                Channel.current().syncLocalIO();
+            } catch (InterruptedException e) {
+                // our signature doesn't allow us to throw InterruptedException, so we process it later
+                Thread.currentThread().interrupt();
+            }
+        }
+
         /**
          * Performs final clean up. Invoked after the entire aggregator build is completed.
          */
         protected void close() {
             try {
+                sync();
                 log.close();
             } catch (IOException e) {
                 e.printStackTrace();
diff --git a/maven-plugin/src/main/java/hudson/maven/SplittableBuildListener.java b/maven-plugin/src/main/java/hudson/maven/SplittableBuildListener.java
@@ -55,9 +55,9 @@ final class SplittableBuildListener extends AbstractTaskListener implements Buil
      * Used to accumulate data when no one is claiming the {@link #side},
      * so that the next one who set the {@link #side} can claim all the data.
      */
-    private ByteArrayOutputStream unclaimed = new ByteArrayOutputStream();
+    private final ByteArrayOutputStream unclaimed = new ByteArrayOutputStream();
 
-    private OutputStream side = unclaimed;
+    private volatile OutputStream side = unclaimed;
 
     /**
      * Constant {@link PrintStream} connected to both {@link #core} and {@link #side}.
@@ -95,8 +95,10 @@ public void setSideOutputStream(OutputStream os) throws IOException {
         if(os==null) {
             os = unclaimed;
         } else {
-            unclaimed.writeTo(os);
-            unclaimed = new ByteArrayOutputStream();
+            synchronized (unclaimed) {
+                unclaimed.writeTo(os);
+                unclaimed.reset();
+            }
         }
         this.side = os;
     }
