From b2c6ad1673e37353dd1f5d0e67972a5b1b4151fd Mon Sep 17 00:00:00 2001
From: Oleg Nenashev <o.v.nenashev@gmail.com>
Date: Mon, 3 Jul 2017 10:48:50 +0200
Subject: [PATCH] [JENKINS-45233] - Log errors when Response message cannot be
 delivered due to the closed channel (#177)

* [FIXED JENKINS-45223] - Print warnings about failed responses when cannot deliver them due to the closed channel

* Improve logging of the command execution

* [JENKINS-45233] - Address comments from @jglick

* [JENKINS-45233] - get rid of gratituos synchronization
---
 src/main/java/hudson/remoting/Channel.java | 11 +++++++++--
 src/main/java/hudson/remoting/Request.java |  8 +++-----
 2 files changed, 12 insertions(+), 7 deletions(-)

diff --git a/src/main/java/hudson/remoting/Channel.java b/src/main/java/hudson/remoting/Channel.java
index 3cfa3106e..31bceab4e 100644
--- a/src/main/java/hudson/remoting/Channel.java
+++ b/src/main/java/hudson/remoting/Channel.java
@@ -528,11 +528,18 @@ protected Channel(@Nonnull ChannelBuilder settings, @Nonnull CommandTransport tr
         transport.setup(this, new CommandReceiver() {
             public void handle(Command cmd) {
                 commandsReceived++;
-                lastCommandReceivedAt = System.currentTimeMillis();
-                if (logger.isLoggable(Level.FINE))
+                long receivedAt = System.currentTimeMillis();
+                lastCommandReceivedAt = receivedAt;
+                if (logger.isLoggable(Level.FINE)) {
                     logger.fine("Received " + cmd);
+                } else if (logger.isLoggable(Level.FINER)) {
+                    logger.log(Level.FINER, "Received command " + cmd, cmd.createdAt);
+                }
                 try {
                     cmd.execute(Channel.this);
+                    if (logger.isLoggable(Level.FINE)) {
+                        logger.log(Level.FINE, "Completed command {0}. It took {1}ms", new Object[] {cmd, System.currentTimeMillis() - receivedAt});
+                    }
                 } catch (Throwable t) {
                     logger.log(Level.SEVERE, "Failed to execute command " + cmd + " (channel " + Channel.this.name + ")", t);
                     logger.log(Level.SEVERE, "This command is created here", cmd.createdAt);
diff --git a/src/main/java/hudson/remoting/Request.java b/src/main/java/hudson/remoting/Request.java
index ab6f62958..1887cf430 100644
--- a/src/main/java/hudson/remoting/Request.java
+++ b/src/main/java/hudson/remoting/Request.java
@@ -25,6 +25,7 @@
 
 import java.io.IOException;
 import java.io.Serializable;
+import java.nio.channels.ClosedChannelException;
 import java.util.concurrent.CancellationException;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Future;
@@ -345,14 +346,11 @@ public void run() {
                     if(chainCause)
                         rsp.createdAt.initCause(createdAt);
 
-                    synchronized (channel) {// expand the synchronization block of the send() method to a check
-                        if(!channel.isOutClosed())
-                            channel.send(rsp);
-                    }
+                    channel.send(rsp);
                 } catch (IOException e) {
                     // communication error.
                     // this means the caller will block forever
-                    logger.log(Level.SEVERE, "Failed to send back a reply",e);
+                    logger.log(Level.WARNING, "Failed to send back a reply to the request " + this, e);
                 } finally {
                     channel.executingCalls.remove(id);
                     Thread.currentThread().setName(oldThreadName);