Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-54496

Node monitoring should not log exceptions for disconnected nodes

    Details

    • Type: Improvement
    • Status: Open (View Workflow)
    • Priority: Minor
    • Resolution: Unresolved
    • Component/s: core, remoting
    • Labels:
      None
    • Similar Issues:

      Description

      In an environment in which Jenkins nodes are being created and removed a lot, e.g. when using the docker-plugin to create single-use containers as slave nodes, the node monitoring functionality can fill the logs full of spurious exceptions, e.g.

      Oct 13, 2018 10:18:14 PM io.jenkins.docker.DockerTransientNode$1 println
      INFO: Disconnected computer for node 'docker-hst02-00030qwaqtu3g'.
      Oct 13, 2018 10:18:14 PM io.jenkins.docker.DockerTransientNode$1 println
      INFO: Removed Node for node 'docker-hst02-00030qwaqtu3g'.
      Oct 13, 2018 10:18:14 PM hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor monitorDetailed
      WARNING: Failed to monitor docker-hst02-00030qwaqtu3g for Clock Difference
      java.util.concurrent.ExecutionException: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.Channel$2.adapt(Channel.java:992)
      	at hudson.remoting.Channel$2.adapt(Channel.java:986)
      	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitorDetailed(AbstractAsyncNodeMonitorDescriptor.java:114)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitor(AbstractAsyncNodeMonitorDescriptor.java:76)
      	at hudson.node_monitors.AbstractNodeMonitorDescriptor$Record.run(AbstractNodeMonitorDescriptor.java:305)
      Caused by: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:107)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.resolveClass(MultiClassLoaderSerializer.java:128)
      	at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1826)
      	at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
      	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
      	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
      	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
      	at hudson.remoting.UserRequest.deserialize(UserRequest.java:291)
      	at hudson.remoting.UserRequest$NormalResponse.retrieve(UserRequest.java:326)
      	at hudson.remoting.Channel$2.adapt(Channel.java:990)
      	... 5 more
      Caused by: java.util.concurrent.ExecutionException: Invalid object ID 2 iota=7
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
      	at hudson.remoting.ExportTable.get(ExportTable.java:397)
      	at hudson.remoting.Channel.getExportedObject(Channel.java:780)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:105)
      	... 14 more
      
      Oct 13, 2018 10:18:14 PM hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor monitorDetailed
      WARNING: Failed to monitor docker-hst02-00030qwaqtu3g for Free Temp Space
      java.util.concurrent.ExecutionException: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.Channel$2.adapt(Channel.java:992)
      	at hudson.remoting.Channel$2.adapt(Channel.java:986)
      	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitorDetailed(AbstractAsyncNodeMonitorDescriptor.java:114)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitor(AbstractAsyncNodeMonitorDescriptor.java:76)
      	at hudson.node_monitors.AbstractNodeMonitorDescriptor$Record.run(AbstractNodeMonitorDescriptor.java:305)
      Caused by: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:107)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.resolveClass(MultiClassLoaderSerializer.java:128)
      	at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1826)
      	at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
      	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
      	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
      	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
      	at hudson.remoting.UserRequest.deserialize(UserRequest.java:291)
      	at hudson.remoting.UserRequest$NormalResponse.retrieve(UserRequest.java:326)
      	at hudson.remoting.Channel$2.adapt(Channel.java:990)
      	... 5 more
      Caused by: java.util.concurrent.ExecutionException: Invalid object ID 2 iota=7
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
      	at hudson.remoting.ExportTable.get(ExportTable.java:397)
      	at hudson.remoting.Channel.getExportedObject(Channel.java:780)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:105)
      	... 14 more
      
      Oct 13, 2018 10:18:15 PM io.jenkins.docker.DockerTransientNode$1 println
      INFO: Stopped container 'f42781f352e6b9a08e66654e9d385999a4a210bb0956f3dc9f8125e169e245fe' for node 'docker-hst02-00030qwaqtu3g'.
      
      Oct 13, 2018 10:18:15 PM hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor monitorDetailed
      WARNING: Failed to monitor docker-hst02-00030qwaqtu3g for Free Disk Space
      java.util.concurrent.ExecutionException: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.Channel$2.adapt(Channel.java:992)
      	at hudson.remoting.Channel$2.adapt(Channel.java:986)
      	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitorDetailed(AbstractAsyncNodeMonitorDescriptor.java:114)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitor(AbstractAsyncNodeMonitorDescriptor.java:76)
      	at hudson.node_monitors.AbstractNodeMonitorDescriptor$Record.run(AbstractNodeMonitorDescriptor.java:305)
      Caused by: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:107)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.resolveClass(MultiClassLoaderSerializer.java:128)
      	at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1826)
      	at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
      	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
      	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
      	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
      	at hudson.remoting.UserRequest.deserialize(UserRequest.java:291)
      	at hudson.remoting.UserRequest$NormalResponse.retrieve(UserRequest.java:326)
      	at hudson.remoting.Channel$2.adapt(Channel.java:990)
      	... 5 more
      Caused by: java.util.concurrent.ExecutionException: Invalid object ID 2 iota=7
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
      	at hudson.remoting.ExportTable.get(ExportTable.java:397)
      	at hudson.remoting.Channel.getExportedObject(Channel.java:780)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:105)
      	... 14 more
      
      Oct 13, 2018 10:18:15 PM hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor monitorDetailed
      WARNING: Failed to monitor docker-hst02-00030qwaqtu3g for Free Swap Space
      java.util.concurrent.ExecutionException: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.Channel$2.adapt(Channel.java:992)
      	at hudson.remoting.Channel$2.adapt(Channel.java:986)
      	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitorDetailed(AbstractAsyncNodeMonitorDescriptor.java:114)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitor(AbstractAsyncNodeMonitorDescriptor.java:76)
      	at hudson.node_monitors.AbstractNodeMonitorDescriptor$Record.run(AbstractNodeMonitorDescriptor.java:305)
      Caused by: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:107)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.resolveClass(MultiClassLoaderSerializer.java:128)
      	at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1826)
      	at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
      	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
      	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
      	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
      	at hudson.remoting.UserRequest.deserialize(UserRequest.java:291)
      	at hudson.remoting.UserRequest$NormalResponse.retrieve(UserRequest.java:326)
      	at hudson.remoting.Channel$2.adapt(Channel.java:990)
      	... 5 more
      Caused by: java.util.concurrent.ExecutionException: Invalid object ID 2 iota=7
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
      	at hudson.remoting.ExportTable.get(ExportTable.java:397)
      	at hudson.remoting.Channel.getExportedObject(Channel.java:780)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:105)
      	... 14 more
      
      Oct 13, 2018 10:18:15 PM hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor monitorDetailed
      WARNING: Failed to monitor docker-hst02-00030qwaqtu3g for Response Time
      java.util.concurrent.ExecutionException: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.Channel$2.adapt(Channel.java:992)
      	at hudson.remoting.Channel$2.adapt(Channel.java:986)
      	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)
      	at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitorDetailed(AbstractAsyncNodeMonitorDescriptor.java:114)
      	at hudson.node_monitors.ResponseTimeMonitor$1.monitor(ResponseTimeMonitor.java:57)
      	at hudson.node_monitors.AbstractNodeMonitorDescriptor$Record.run(AbstractNodeMonitorDescriptor.java:305)
      Caused by: java.io.IOException: Cannot locate RemoteClassLoader.ClassLoaderProxy(2) in the channel exported table
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:107)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.resolveClass(MultiClassLoaderSerializer.java:128)
      	at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1826)
      	at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
      	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
      	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
      	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
      	at hudson.remoting.UserRequest.deserialize(UserRequest.java:291)
      	at hudson.remoting.UserRequest$NormalResponse.retrieve(UserRequest.java:326)
      	at hudson.remoting.Channel$2.adapt(Channel.java:990)
      	... 5 more
      Caused by: java.util.concurrent.ExecutionException: Invalid object ID 2 iota=7
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
      	at hudson.remoting.ExportTable.get(ExportTable.java:397)
      	at hudson.remoting.Channel.getExportedObject(Channel.java:780)
      	at hudson.remoting.MultiClassLoaderSerializer$Input.readClassLoader(MultiClassLoaderSerializer.java:105)
      	... 14 more
      

      This is ugly and obscures "real errors" within the log. This causes real-world problems when trying to debug actual slave disconnection issues, as the log is full of "normal" exceptions that obscure any abnormal exceptions.

      Recommendation:
      Node monitoring code should only report exceptions to the main `jenkins.err.log` file if the slave node still exists by the time the exception is caught ; there's no point logging huge exception traces for a slave node which has already been removed.
      If the node doesn't exist then either suppress the logging completely or log it at a lower severity so it doesn't fill the main logfile.

        Attachments

          Activity

          Hide
          jthompson Jeff Thompson added a comment -

          I'm not really sure what the desired behavior here is. It seems like the ask is that Jenkins would be better able to distinguish between an ephemeral and a permanent agent and then react or log differently in the two situations. It seems like these log messages might be important for permanent agents but excessive for ephemeral ones. Maybe this type of monitoring should not be enabled for ephemeral agents.

          Alternatively, the ask might be to improve the detection of when an agent no longer exists. Looking at the stack trace and the code, this operation is only called if Jenkins thinks the node exists.

          Show
          jthompson Jeff Thompson added a comment - I'm not really sure what the desired behavior here is. It seems like the ask is that Jenkins would be better able to distinguish between an ephemeral and a permanent agent and then react or log differently in the two situations. It seems like these log messages might be important for permanent agents but excessive for ephemeral ones. Maybe this type of monitoring should not be enabled for ephemeral agents. Alternatively, the ask might be to improve the detection of when an agent no longer exists. Looking at the stack trace and the code, this operation is only called if Jenkins thinks the node exists.
          Hide
          pjdarton pjdarton added a comment - - edited

          The node existed when the method started its work, but the node is removed during execution (causing the exception). It's a race condition, but one that's very common with high-throughout dynamic slaves.
          I strongly suspect that, if the code checked again "does this node exist" before logging the exception, it would discover that the node does not exist anymore (and, in my opinion, should either log at a lower level, or not log at all)

          Show
          pjdarton pjdarton added a comment - - edited The node existed when the method started its work, but the node is removed during execution (causing the exception). It's a race condition, but one that's very common with high-throughout dynamic slaves. I strongly suspect that, if the code checked again "does this node exist" before logging the exception, it would discover that the node does not exist anymore (and, in my opinion, should either log at a lower level, or not log at all)

            People

            • Assignee:
              jthompson Jeff Thompson
              Reporter:
              pjdarton pjdarton
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: