Merge pull request #2841 from jglick/FullDuplexHttpService-diag

Added logging to FullDuplexHttpService

core/src/main/java/jenkins/util/FullDuplexHttpService.java

@@ -32,6 +32,8 @@ import java.io.OutputStream;
 import java.util.Map;
 import java.util.UUID;
 import java.util.concurrent.TimeUnit;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import javax.servlet.ServletException;
 import javax.servlet.http.HttpServletResponse;
 import org.kohsuke.accmod.Restricted;
@@ -46,6 +48,8 @@ import org.kohsuke.stapler.StaplerResponse;
  */
 public abstract class FullDuplexHttpService {
 
+    private static final Logger LOGGER = Logger.getLogger(FullDuplexHttpService.class.getName());
+
     /**
      * Set to true if the servlet container doesn't support chunked encoding.
      */
@@ -92,12 +96,15 @@ public abstract class FullDuplexHttpService {
         {// wait until we have the other channel
             long end = System.currentTimeMillis() + CONNECTION_TIMEOUT;
             while (upload == null && System.currentTimeMillis() < end) {
+                LOGGER.log(Level.FINE, "Waiting for upload stream for {0}: {1}", new Object[] {uuid, this});
                 wait(1000);
             }
 
             if (upload == null) {
                 throw new IOException("HTTP full-duplex channel timeout: " + uuid);
             }
+
+            LOGGER.log(Level.FINE, "Received upload stream {0} for {1}: {2}", new Object[] {upload, uuid, this});
         }
 
         try {
@@ -123,6 +130,7 @@ public abstract class FullDuplexHttpService {
 
         // publish the upload channel
         upload = in;
+        LOGGER.log(Level.FINE, "Recording upload stream {0} for {1}: {2}", new Object[] {upload, uuid, this});
         notify();
 
         // wait until we are done
@@ -157,14 +165,25 @@ public abstract class FullDuplexHttpService {
 
                 if (req.getHeader("Side").equals("download")) {
                     FullDuplexHttpService service = createService(req, uuid);
+                    LOGGER.log(Level.FINE, "Processing download side for {0}: {1}", new Object[] {uuid, service});
                     services.put(uuid, service);
                     try {
                         service.download(req, rsp);
                     } finally {
+                        LOGGER.log(Level.FINE, "Finished download side for {0}: {1}", new Object[] {uuid, service});
                         services.remove(uuid);
                     }
                 } else {
-                    services.get(uuid).upload(req, rsp);
+                    FullDuplexHttpService service = services.get(uuid);
+                    if (service == null) {
+                        throw new IOException("No download side found for " + uuid);
+                    }
+                    LOGGER.log(Level.FINE, "Processing upload side for {0}: {1}", new Object[] {uuid, service});
+                    try {
+                        service.upload(req, rsp);
+                    } finally {
+                        LOGGER.log(Level.FINE, "Finished upload side for {0}: {1}", new Object[] {uuid, service});
+                    }
                 }
             } catch (InterruptedException e) {
                 throw new IOException(e);

test/src/test/java/hudson/cli/CLIActionTest.java

@@ -33,6 +33,7 @@ import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import jenkins.model.Jenkins;
 import jenkins.security.ApiTokenProperty;
+import jenkins.util.FullDuplexHttpService;
 import jenkins.util.Timer;
 import org.apache.commons.io.FileUtils;
 import org.apache.commons.io.output.TeeOutputStream;
@@ -257,7 +258,7 @@ public class CLIActionTest {
     @Issue("JENKINS-41745")
     @Test
     public void interleavedStdio() throws Exception {
-        logging.record(PlainCLIProtocol.class, Level.FINE);
+        logging.record(PlainCLIProtocol.class, Level.FINE).record(FullDuplexHttpService.class, Level.FINE);
         File jar = tmp.newFile("jenkins-cli.jar");
         FileUtils.copyURLToFile(j.jenkins.getJnlpJars("jenkins-cli.jar").getURL(), jar);
         ByteArrayOutputStream baos = new ByteArrayOutputStream();