Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Blocker
    • Resolution: Fixed
    • Component/s: unity3d-plugin
    • Labels:
      None
    • Environment:
      * Mac OS X
      * Slave node running on same machine as Jenkins (connected via SSH to localhost, same 'jenkins' user running everything)
      * Unity Cache server (running on same machine as Jenkins and Unity slave node)
    • Similar Issues:

      Description

      We get a pipe broken exception in the Jenkins Unity plugin about 50% of the time. The workspace is cleaned before every build, and compiled assets are fetched from a Unity Cache server running on the same machine.

      The error happens ALWAYS at the exact same step:
      [...]
      Refresh: trashing asset 2197dcffa7f1e4295a0f8e83fed9f5bf
      Refresh: trashing asset bca6eeff7c4924a429da9a1b3450b036
      Refresh: trashing asset 6b4a9fff255e844c999a4bcd6105d894
      Refresh: trashing asset d63cefffccda34624843a84caddbb852
      Failure on remote
      java.io.IOException: Pipe broken
      at java.io.PipedInputStream.read(PipedInputStream.java:322)
      at java.io.PipedInputStream.read(PipedInputStream.java:378)
      at java.io.InputStream.read(InputStream.java:101)
      at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64)

      When it succeeds, the next line is ALWAYS
      Updating Assets - GUID: 00000000000000001000000000000000...
      done. [Time: 18.743246 ms]

      So IF the build fails, then it is ALWAYS right after the last asset being trashed. If it makes it to the next line (updating asset with GUID 00001000), then the build will ALWAYS succeed.

      I think that the frequency of the error is dependent on how large the project is, as we didn't get the error nearly as much in the beginning phases of the project. Now that the project is large we get the pipe broken error about 50% of the time. This is of course conjecture and the frequency of the error could be caused by something else entirely.

      Also, errors tend to happen multiple times in a row. Conversely, once it succeeds it tends to succeed for several consecutive builds.

      This is of course very much a showstopper for us, so I'd be extremely grateful if someone could have a look at this issue.

      Thanks!

      • Tommi Kiviniemi
        VP Technology, Co-founder
        Seriously Digital Entertainment Ltd.

        Attachments

          Issue Links

            Activity

            tommigun Tommi Kiviniemi created issue -
            Hide
            tommigun Tommi Kiviniemi added a comment -

            Please note that this is not a duplicate of https://issues.jenkins-ci.org/browse/JENKINS-22492 as the cause is very different in #22492.

            Show
            tommigun Tommi Kiviniemi added a comment - Please note that this is not a duplicate of https://issues.jenkins-ci.org/browse/JENKINS-22492 as the cause is very different in #22492.
            Hide
            tommigun Tommi Kiviniemi added a comment - - edited

            Please also note that the log file itself does contain the portions after the point where Jenkins bails out, so it is not a matter of log truncation or similar. I'm suspecting this might be a timeout in the log stream reader, as that step takes quite a long time and Unity doesn't output anything in the log there during that time.

            Show
            tommigun Tommi Kiviniemi added a comment - - edited Please also note that the log file itself does contain the portions after the point where Jenkins bails out, so it is not a matter of log truncation or similar. I'm suspecting this might be a timeout in the log stream reader, as that step takes quite a long time and Unity doesn't output anything in the log there during that time.
            tommigun Tommi Kiviniemi made changes -
            Field Original Value New Value
            Environment Mac OS X Mac OS X,
            Slave node running on same machine as Jenkins (connected via SSH to localhost, same 'jenkins' user running everything)
            tommigun Tommi Kiviniemi made changes -
            Environment Mac OS X,
            Slave node running on same machine as Jenkins (connected via SSH to localhost, same 'jenkins' user running everything)
            * Mac OS X
            * Slave node running on same machine as Jenkins (connected via SSH to localhost, same 'jenkins' user running everything)
            * Unity Cache server (running on same machine as Jenkins and Unity slave node)
            tommigun Tommi Kiviniemi made changes -
            Description We get a pipe broken exception in the Jenkins Unity plugin about 50% of the time.

            It ALWAYS happens at the exact same step:
            [...]
            Refresh: trashing asset 2197dcffa7f1e4295a0f8e83fed9f5bf
            Refresh: trashing asset bca6eeff7c4924a429da9a1b3450b036
            Refresh: trashing asset 6b4a9fff255e844c999a4bcd6105d894
            Refresh: trashing asset d63cefffccda34624843a84caddbb852
            Failure on remote
            java.io.IOException: Pipe broken
            at java.io.PipedInputStream.read(PipedInputStream.java:322)
            at java.io.PipedInputStream.read(PipedInputStream.java:378)
            at java.io.InputStream.read(InputStream.java:101)
            at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64)

            When it succeeds, the next line is ALWAYS
            Updating Assets - GUID: 00000000000000001000000000000000...
             done. [Time: 18.743246 ms]

            So IF the build fails, then it is ALWAYS right after the last asset being trashed. If it makes it to the next line (updating asset with GUID 00001000), then the build will ALWAYS succeed.

            I think that the frequency of the error is dependent on how large the project is, as we didn't get the error nearly as much in the beginning phases of the project. Now that the project is large we get the pipe broken error about 50% of the time. This is of course conjecture and the frequency of the error could be caused by something else entirely.

            Also, errors tend to happen multiple times in a row. Conversely, once it succeeds it tends to succeed for several consecutive builds.

            This is of course very much a showstopper for us, so I'd be extremely grateful if someone could have a look at this issue.

            Thanks!
            - Tommi Kiviniemi
            VP Technology, Co-founder
            Seriously Digital Entertainment Ltd.
            We get a pipe broken exception in the Jenkins Unity plugin about 50% of the time. The workspace is cleaned before every build, and compiled assets are fetched from a Unity Cache server running on the same machine.

            The error happens ALWAYS at the exact same step:
            [...]
            Refresh: trashing asset 2197dcffa7f1e4295a0f8e83fed9f5bf
            Refresh: trashing asset bca6eeff7c4924a429da9a1b3450b036
            Refresh: trashing asset 6b4a9fff255e844c999a4bcd6105d894
            Refresh: trashing asset d63cefffccda34624843a84caddbb852
            Failure on remote
            java.io.IOException: Pipe broken
            at java.io.PipedInputStream.read(PipedInputStream.java:322)
            at java.io.PipedInputStream.read(PipedInputStream.java:378)
            at java.io.InputStream.read(InputStream.java:101)
            at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64)

            When it succeeds, the next line is ALWAYS
            Updating Assets - GUID: 00000000000000001000000000000000...
             done. [Time: 18.743246 ms]

            So IF the build fails, then it is ALWAYS right after the last asset being trashed. If it makes it to the next line (updating asset with GUID 00001000), then the build will ALWAYS succeed.

            I think that the frequency of the error is dependent on how large the project is, as we didn't get the error nearly as much in the beginning phases of the project. Now that the project is large we get the pipe broken error about 50% of the time. This is of course conjecture and the frequency of the error could be caused by something else entirely.

            Also, errors tend to happen multiple times in a row. Conversely, once it succeeds it tends to succeed for several consecutive builds.

            This is of course very much a showstopper for us, so I'd be extremely grateful if someone could have a look at this issue.

            Thanks!
            - Tommi Kiviniemi
            VP Technology, Co-founder
            Seriously Digital Entertainment Ltd.
            Hide
            lacostej lacostej added a comment -

            Which version of jenkins are you using ?
            Are you using the -logFile option of unity3d command line ?

            Show
            lacostej lacostej added a comment - Which version of jenkins are you using ? Are you using the -logFile option of unity3d command line ?
            Hide
            tommigun Tommi Kiviniemi added a comment - - edited

            Hi lacostej!

            We are currently using Jenkins 1.574 (newest stable), and this has happened with pretty much every Jenkins version for the last couple of months.

            Yes, we are using -logFile (to prevent multiple concurrent builds from overwriting the same log). Here's the argument to the Unity plugin:
            -noGraphics -batchmode -quit -projectPath “/XXX/workspace/YYY/ZZZ" -logFile "/XXX/workspace/YYY/Editor.log" -executeMethod Builder.BuildFromCommandLine -CustomArgs:Mode=Debug;Target=iPhone;OutputPath=/XXX/workspace/YYY/Build/iOS_XCode

            If I open the log file at /XXX/workspace/YYY/Editor.log I can see the lines following the pipe broken error (Updating Assets - GUID: 00000000000000001000000000000000... etc.), so Unity is definitely outputting that to the log. For whatever reason the Unity plugin's stream reader seems to think that the log stream gets broken there and bails out. I don't know if the stream times out or what the heck is going on there? Please let me know if you need any more info.

            PS. The same error happens without -logFile as well, albeit it seems to happen more often (could be because concurrent builds could overwrite the same log in that scenario). But even when building ONE build at a time, using -logFile or not using it can still invoke the same pipe broken error.

            • Tommi
            Show
            tommigun Tommi Kiviniemi added a comment - - edited Hi lacostej! We are currently using Jenkins 1.574 (newest stable), and this has happened with pretty much every Jenkins version for the last couple of months. Yes, we are using -logFile (to prevent multiple concurrent builds from overwriting the same log). Here's the argument to the Unity plugin: -noGraphics -batchmode -quit -projectPath “/XXX/workspace/YYY/ZZZ" -logFile "/XXX/workspace/YYY/Editor.log" -executeMethod Builder.BuildFromCommandLine -CustomArgs:Mode=Debug;Target=iPhone;OutputPath=/XXX/workspace/YYY/Build/iOS_XCode If I open the log file at /XXX/workspace/YYY/Editor.log I can see the lines following the pipe broken error (Updating Assets - GUID: 00000000000000001000000000000000... etc.), so Unity is definitely outputting that to the log. For whatever reason the Unity plugin's stream reader seems to think that the log stream gets broken there and bails out. I don't know if the stream times out or what the heck is going on there? Please let me know if you need any more info. PS. The same error happens without -logFile as well, albeit it seems to happen more often (could be because concurrent builds could overwrite the same log in that scenario). But even when building ONE build at a time, using -logFile or not using it can still invoke the same pipe broken error. Tommi
            Hide
            lacostej lacostej added a comment -

            I will set up a full testbed for master/slave scenarios. I will also set up a long running build (maybe one that builds multiple architecture in a row, for let's say 1h).

            Just to make sure I got you:

            • you have a distributed environment with master&slave on the same server
            • the pipe failure happens in the middle of the build (i.e. not just a few seconds before the completion).

            I am also working on new features (like auto-install of unity). Feel free to take contact to discuss this further.

            Show
            lacostej lacostej added a comment - I will set up a full testbed for master/slave scenarios. I will also set up a long running build (maybe one that builds multiple architecture in a row, for let's say 1h). Just to make sure I got you: you have a distributed environment with master&slave on the same server the pipe failure happens in the middle of the build (i.e. not just a few seconds before the completion). I am also working on new features (like auto-install of unity). Feel free to take contact to discuss this further.
            Hide
            lacostej lacostej added a comment -

            FYI, I've setup a local master/slave setup, using 1.565.1 (latest stable).

            I have 0 executors on master, 1 on slave. The slave connects using ssh, as in your setup.

            I configured the install of Unity 4.5.1f2 in jenkins.

            I added the EnvInject plugin to tune the config a bit.

            I created a Unity project to try to reproduce your workload. The git repo is on: https://bitbucket.org/WeWantToKnow/unity3d-sample-project

            Basically I run the 2D platform sample from Unity3d, and have a jennkins job that builds 8 platforms in a row, multiple times (4 in my case). I.e. 32 builds.

            I was unable to get the project to fail so far. This takes 10 min on my machine. I run java 1.7.0_21 Mac OS X 10.9.4

            I would be great to know if this project fails to run on your machine.

            You can reproduce the same config by using the following configuration:

            • Prepare an environment for the run
            • - Properties Content
              BUILD_MANY_TIMES=4
            • Git
            • - Repository URL
              git@bitbucket.org:WeWantToKnow/unity3d-sample-project.git
            • Unity3d Builder:
            • - Unity3d installation name:
              Unity 4.5.1f2
            • - Editor command line arguments
              -quit -batchmode -executeMethod MyEditorScript.PerformAllManyBuild -logFile $WORKSPACE/unity3d_editor.log
            Show
            lacostej lacostej added a comment - FYI, I've setup a local master/slave setup, using 1.565.1 (latest stable). I have 0 executors on master, 1 on slave. The slave connects using ssh, as in your setup. I configured the install of Unity 4.5.1f2 in jenkins. I added the EnvInject plugin to tune the config a bit. I created a Unity project to try to reproduce your workload. The git repo is on: https://bitbucket.org/WeWantToKnow/unity3d-sample-project Basically I run the 2D platform sample from Unity3d, and have a jennkins job that builds 8 platforms in a row, multiple times (4 in my case). I.e. 32 builds. I was unable to get the project to fail so far. This takes 10 min on my machine. I run java 1.7.0_21 Mac OS X 10.9.4 I would be great to know if this project fails to run on your machine. You can reproduce the same config by using the following configuration: Prepare an environment for the run - Properties Content BUILD_MANY_TIMES=4 Git - Repository URL git@bitbucket.org:WeWantToKnow/unity3d-sample-project.git Unity3d Builder: - Unity3d installation name: Unity 4.5.1f2 - Editor command line arguments -quit -batchmode -executeMethod MyEditorScript.PerformAllManyBuild -logFile $WORKSPACE/unity3d_editor.log
            Hide
            lacostej lacostej added a comment -

            Note I've posted on the dev list for a bit of help:

            https://groups.google.com/d/msg/jenkinsci-dev/LjHaBd6yUW8/LstWtVCaOHwJ

            "Troubleshooting remoting related input/output stream piping issues"

            Show
            lacostej lacostej added a comment - Note I've posted on the dev list for a bit of help: https://groups.google.com/d/msg/jenkinsci-dev/LjHaBd6yUW8/LstWtVCaOHwJ "Troubleshooting remoting related input/output stream piping issues"
            Hide
            tommigun Tommi Kiviniemi added a comment -

            Thank you so much for looking into this issue.

            I will try to build the sample project with our setup to see whether it fails and report any findings. I don't know if this affects anything but the slave executors are running on the same machine as the master in our current setup, so the SSH connections never go over the network. I will try to set up a repository with the sample project as quickly as possible to help you get more data.

            Thanks,

            • Tommi
            Show
            tommigun Tommi Kiviniemi added a comment - Thank you so much for looking into this issue. I will try to build the sample project with our setup to see whether it fails and report any findings. I don't know if this affects anything but the slave executors are running on the same machine as the master in our current setup, so the SSH connections never go over the network. I will try to set up a repository with the sample project as quickly as possible to help you get more data. Thanks, Tommi
            Hide
            tommigun Tommi Kiviniemi added a comment -

            I am sorry that I haven't gotten back to you regarding the sample project yet, but we are just about to release our game and have been too swamped to find time for it. Just wanted to let you know that I will do it as soon as time permits.

            PS. We are using Unity Cache server, running on the same machine as everything else. If you have it could you try enabling it to see if you get the sample project build to fail?

            Show
            tommigun Tommi Kiviniemi added a comment - I am sorry that I haven't gotten back to you regarding the sample project yet, but we are just about to release our game and have been too swamped to find time for it. Just wanted to let you know that I will do it as soon as time permits. PS. We are using Unity Cache server, running on the same machine as everything else. If you have it could you try enabling it to see if you get the sample project build to fail?
            Hide
            lacostej lacostej added a comment -

            No cache server here

            Settings up the test project should take 5 min if you have the envinject plugin already installed.

            Good luck with your launch. Feel free to mail me to announce it (or if you need test users, I have testflight/hockeyapp accounts if needed)

            Show
            lacostej lacostej added a comment - No cache server here Settings up the test project should take 5 min if you have the envinject plugin already installed. Good luck with your launch. Feel free to mail me to announce it (or if you need test users, I have testflight/hockeyapp accounts if needed)
            Hide
            lacostej lacostej added a comment -

            Tommi, let me know if you still have problem with this issue. I am available on skype @lacostej

            Show
            lacostej lacostej added a comment - Tommi, let me know if you still have problem with this issue. I am available on skype @lacostej
            Hide
            bsawyer ben s added a comment - - edited

            It's not clear to me how this is different from JENKINS-22492 since they both appear to be identical according to the descriptions. I'm not sure which one I should watch, so I'm watching both

            Anyway, we are having the broken pipe issue as well. Details:

            • Linux master (Ubuntu)
            • Unity builds occur on remote Mac OSX slaves
            • Jenkins v1.607
            • Unity3d plugin v0.7
            • Various Unity versions: 3.5.7, 4.5.4, 4.6.4. Doesn't seem to make a difference.

            I'm here today because I feel like after our recent Jenkins update to 1.607 this error has started occurring more frequently, however I can't say for certain.

            Show
            bsawyer ben s added a comment - - edited It's not clear to me how this is different from JENKINS-22492 since they both appear to be identical according to the descriptions. I'm not sure which one I should watch, so I'm watching both Anyway, we are having the broken pipe issue as well. Details: Linux master (Ubuntu) Unity builds occur on remote Mac OSX slaves Jenkins v1.607 Unity3d plugin v0.7 Various Unity versions: 3.5.7, 4.5.4, 4.6.4. Doesn't seem to make a difference. I'm here today because I feel like after our recent Jenkins update to 1.607 this error has started occurring more frequently, however I can't say for certain.
            Hide
            lacostej lacostej added a comment -

            Ben,

            > It's not clear to me how this is different from JENKINS-22492 since
            > they both appear to be identical according to the descriptions. I'm not sure which one I should watch, so I'm watching both

            Let's fix both then

            Do you happen to have a reliable way to reproduce this ? If not, have you tried to create one ?

            Is your job long running ?

            Do you use the -logFile option ?

            Show
            lacostej lacostej added a comment - Ben, > It's not clear to me how this is different from JENKINS-22492 since > they both appear to be identical according to the descriptions. I'm not sure which one I should watch, so I'm watching both Let's fix both then Do you happen to have a reliable way to reproduce this ? If not, have you tried to create one ? Is your job long running ? Do you use the -logFile option ?
            Hide
            bsawyer ben s added a comment -

            Unfortunately I don't have any specific way to reproduce it. Most of our jobs are rather long, however. In fact when a job undergoes a fresh import into a new workspace, the likelihood of this error occurring seems to increase. The larger the project (the more assets) the more frequent.

            It often happens after Unity lists "Used Assets, sorted by uncompressed size:"

             0.0 kb	 0.0% Assets/Resources/path/to/some/file1
             0.0 kb	 0.0% Assets/Resources/path/to/some/file2
            Failure on remote 
            java.io.IOException: Pipe broken
            	at java.io.PipedInputStream.read(PipedInputStream.java:322)
            	at java.io.PipedInputStream.read(PipedInputStream.java:378)
            	at java.io.InputStream.read(InputStream.java:101)
            	at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64)

            But it also occurs in other points in time:

            Unloading 0 unused Assets to reduce memory usage. Loaded Objects now: 488.
            Total: 1.677543 ms (FindLiveObjects: 0.061794 ms CreateObjectMapping: 0.023056 ms MarkObjects: 1.508662 ms  DeleteObjects: 0.005961 ms)
            
            Failure on remote 
            java.io.IOException: Pipe broken
            	at java.io.PipedInputStream.read(PipedInputStream.java:322)
            	at java.io.PipedInputStream.read(PipedInputStream.java:378)
            	at java.io.InputStream.read(InputStream.java:101)
            	at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64)

            And:

            DisplayProgressbar: Android build
            DisplayProgressbar: Fetching assembly references
            DisplayProgressbar: Creating staging area
            DisplayProgressbar: Rebuilding resources
            DisplayProgressbar: Compiling resources
            DisplayProgressbar: Creating streaming package
            DisplayProgressbar: Creating asset package
            DisplayProgressbar: Creating APK package
            Failure on remote 
            java.io.IOException: Pipe broken
            	at java.io.PipedInputStream.read(PipedInputStream.java:322)
            	at java.io.PipedInputStream.read(PipedInputStream.java:378)
            	at java.io.InputStream.read(InputStream.java:101)
            	at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64)

            All of the above are taken from completely separate projects.

            And yes, all of our jobs use the -logFile option

            -batchmode -quit -logFile "$WORKSPACE/unity.log" -projectPath $WORKSPACE -executeMethod Foo.bar

            I've never seen the error occur more than once per build, and it never seems to cause the build to fail, but if something else causes the build to fail it can be a serious red herring. After the "pipe broken" error, the Jenkins log picks up with the next immediate build step.

            Show
            bsawyer ben s added a comment - Unfortunately I don't have any specific way to reproduce it. Most of our jobs are rather long, however. In fact when a job undergoes a fresh import into a new workspace, the likelihood of this error occurring seems to increase. The larger the project (the more assets) the more frequent. It often happens after Unity lists " Used Assets, sorted by uncompressed size: " 0.0 kb 0.0% Assets/Resources/path/to/some/file1 0.0 kb 0.0% Assets/Resources/path/to/some/file2 Failure on remote java.io.IOException: Pipe broken at java.io.PipedInputStream.read(PipedInputStream.java:322) at java.io.PipedInputStream.read(PipedInputStream.java:378) at java.io.InputStream.read(InputStream.java:101) at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64) But it also occurs in other points in time: Unloading 0 unused Assets to reduce memory usage. Loaded Objects now: 488. Total: 1.677543 ms (FindLiveObjects: 0.061794 ms CreateObjectMapping: 0.023056 ms MarkObjects: 1.508662 ms DeleteObjects: 0.005961 ms) Failure on remote java.io.IOException: Pipe broken at java.io.PipedInputStream.read(PipedInputStream.java:322) at java.io.PipedInputStream.read(PipedInputStream.java:378) at java.io.InputStream.read(InputStream.java:101) at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64) And: DisplayProgressbar: Android build DisplayProgressbar: Fetching assembly references DisplayProgressbar: Creating staging area DisplayProgressbar: Rebuilding resources DisplayProgressbar: Compiling resources DisplayProgressbar: Creating streaming package DisplayProgressbar: Creating asset package DisplayProgressbar: Creating APK package Failure on remote java.io.IOException: Pipe broken at java.io.PipedInputStream.read(PipedInputStream.java:322) at java.io.PipedInputStream.read(PipedInputStream.java:378) at java.io.InputStream.read(InputStream.java:101) at org.jenkinsci.plugins.unity3d.io.StreamCopyThread.run(StreamCopyThread.java:64) All of the above are taken from completely separate projects. And yes, all of our jobs use the -logFile option -batchmode -quit -logFile "$WORKSPACE/unity.log" -projectPath $WORKSPACE -executeMethod Foo.bar I've never seen the error occur more than once per build, and it never seems to cause the build to fail, but if something else causes the build to fail it can be a serious red herring. After the "pipe broken" error, the Jenkins log picks up with the next immediate build step.
            Hide
            lacostej lacostej added a comment -

            As indicated earlier, I posted a message on the dev list: https://groups.google.com/d/msg/jenkinsci-dev/LjHaBd6yUW8/LstWtVCaOHwJ
            But I didn't get feedback.

            I am considering to start patching the remoting lib to get more debugging. I don't understand why the pipe gets broken.

            Show
            lacostej lacostej added a comment - As indicated earlier, I posted a message on the dev list: https://groups.google.com/d/msg/jenkinsci-dev/LjHaBd6yUW8/LstWtVCaOHwJ But I didn't get feedback. I am considering to start patching the remoting lib to get more debugging. I don't understand why the pipe gets broken.
            Hide
            lacostej lacostej added a comment - - edited

            As anyone tried to add some standard Jenkins debugging for the remoting element ?

            For example, following https://wiki.jenkins-ci.org/display/JENKINS/Logging

            1. Go to Jenkins / Manage Jenkins / System Log
            2. add a new log recorder, e.g. named "Remoting"
            3. add a logger, with name hudson.remoting, level FINEST
            4. optional add another Logger for anything unity3d related (org.jenkinsci.plugins.unity3d / FINEST)
            5. save it

            Check that it works (you should start seeing logs appear as soon as some slaves are involved).

            When the bug triggers, look at the logs and add them here or send them privately to me.

            Show
            lacostej lacostej added a comment - - edited As anyone tried to add some standard Jenkins debugging for the remoting element ? For example, following https://wiki.jenkins-ci.org/display/JENKINS/Logging 1. Go to Jenkins / Manage Jenkins / System Log 2. add a new log recorder, e.g. named "Remoting" 3. add a logger, with name hudson.remoting, level FINEST 4. optional add another Logger for anything unity3d related (org.jenkinsci.plugins.unity3d / FINEST) 5. save it Check that it works (you should start seeing logs appear as soon as some slaves are involved). When the bug triggers, look at the logs and add them here or send them privately to me.
            lacostej lacostej made changes -
            Link This issue is duplicated by JENKINS-22492 [ JENKINS-22492 ]
            Hide
            cblegare Charles Bouchard-Légaré added a comment -

            Here are some logs extracted using the loggers as you suggested.

            May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,227)
            May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow
            decrease(7806,227)->1048349
            May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,227)
            May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow
            increase(7806,227)->1048576
            May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,111)
            May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow
            decrease(7806,111)->1048465
            May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,111)
            May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow
            increase(7806,111)->1048576
            May 21, 2015 9:25:44 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,1395)
            May 21, 2015 9:25:44 AM FINER hudson.remoting.PipeWindow
            decrease(7806,1395)->1047181
            May 21, 2015 9:25:44 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,1395)
            May 21, 2015 9:25:44 AM FINER hudson.remoting.PipeWindow
            increase(7806,1395)->1048576
            May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,39)
            May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow
            decrease(7806,39)->1048537
            May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,39)
            May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow
            increase(7806,39)->1048576
            May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,358)
            May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow
            decrease(7806,358)->1048218
            May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,358)
            May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow
            increase(7806,358)->1048576
            May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,776)
            May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow
            decrease(7806,776)->1047800
            May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,776)
            May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow
            increase(7806,776)->1048576
            May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,39)
            May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow
            decrease(7806,39)->1048537
            May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,39)
            May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow
            increase(7806,39)->1048576
            May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,352)
            May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow
            decrease(7806,352)->1048224
            May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,352)
            May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow
            increase(7806,352)->1048576
            May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,390)
            May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow
            decrease(7806,390)->1048186
            May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,390)
            May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow
            increase(7806,390)->1048576
            May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,388)
            May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow
            decrease(7806,388)->1048188
            May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,388)
            May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow
            increase(7806,388)->1048576
            May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,388)
            May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow
            decrease(7806,388)->1048188
            May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,388)
            May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow
            increase(7806,388)->1048576
            May 21, 2015 9:25:53 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,1395)
            May 21, 2015 9:25:53 AM FINER hudson.remoting.PipeWindow
            decrease(7806,1395)->1047181
            May 21, 2015 9:25:53 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,1395)
            May 21, 2015 9:25:53 AM FINER hudson.remoting.PipeWindow
            increase(7806,1395)->1048576
            May 21, 2015 9:26:02 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,4417)
            May 21, 2015 9:26:02 AM FINER hudson.remoting.PipeWindow
            decrease(7806,4417)->1044159
            May 21, 2015 9:26:02 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,4417)
            May 21, 2015 9:26:02 AM FINER hudson.remoting.PipeWindow
            increase(7806,4417)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1040384
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1032192
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1024000
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1015808
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1007616
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->999424
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->991232
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,5341)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,5341)->985891
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->994083
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1002275
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1010467
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1018659
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1026851
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1035043
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1043235
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,5341)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,5341)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1040384
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1032192
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1024000
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,8192)->1015808
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,6708)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,6708)->1009100
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1017292
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1025484
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1033676
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,8192)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,8192)->1041868
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,6708)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,6708)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,784)->1047792
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,784)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,784)->1047792
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,784)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,1568)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,1568)->1047008
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,1568)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,1568)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,784)->1047792
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,784)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,784)->1047792
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,784)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,784)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,38)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,38)->1048538
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,38)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,38)->1048576
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,51)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            decrease(7806,51)->1048525
            May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,51)
            May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow
            increase(7806,51)->1048576
            May 21, 2015 9:26:12 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,4749)
            May 21, 2015 9:26:12 AM FINER hudson.remoting.PipeWindow
            decrease(7806,4749)->1043827
            May 21, 2015 9:26:12 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,4749)
            May 21, 2015 9:26:12 AM FINER hudson.remoting.PipeWindow
            increase(7806,4749)->1048576
            May 21, 2015 9:26:15 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,4419)
            May 21, 2015 9:26:15 AM FINER hudson.remoting.PipeWindow
            decrease(7806,4419)->1044157
            May 21, 2015 9:26:15 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,4419)
            May 21, 2015 9:26:15 AM FINER hudson.remoting.PipeWindow
            increase(7806,4419)->1048576
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@6418c30a
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@381e8444
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@3f59462
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send ProxyOutputStream.Unexport(7798)
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1f8e9d7e
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@23c3231e
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@2ee90846
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@36394798
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@b0a88f6
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@773747fe
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@525ccc87
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send ProxyOutputStream.Unexport(7801)
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send ProxyOutputStream.Unexport(7802)
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@bf67fea
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@4f3bfef6
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@78a46620
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@f805e5e
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@6a24e609
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1a54bf85
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@659a2ec1
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@29d9bf25
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@4b974f33
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@5e9bbeb8
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1a78f425
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@9590290
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@ec92d24
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@52d9cb2f
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1d190fc6
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@a668644
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@45542848
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send ProxyOutputStream.Unexport(7804)
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send ProxyOutputStream.Unexport(7805)
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@4624c159
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1b643614
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@26dbeec5
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1fa040e9
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@4a41f04f
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1b6f87f7
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@23df9b8a
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@4b3eb044
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@3e0ecd9
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@1e86be7a
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@379d7899
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@113bc052
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@9a8a927
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@5825d1af
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@30f10cad
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@631f2e3
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@86cab9d
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@7b003acb
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@f1d83ca
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@4b831383
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@c97e05f
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@35b5cfda
            May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel
            Send hudson.remoting.UnexportCommand@45b7033b
            May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$FileCallableWrapper@2fc406e3
            May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@4fe8ee13,exception=null]
            May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$FileCallableWrapper@51a532cd
            May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@7d4b2672,exception=null]
            May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$IsUnix@3613ea95
            May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@53d313f1,exception=null]
            May 21, 2015 9:27:40 AM FINE hudson.remoting.Channel
            Send UserRequest:hudson.remoting.PingThread$Ping@52fcc248
            May 21, 2015 9:27:40 AM FINE hudson.remoting.Channel
            Received Response[retVal=hudson.remoting.UserResponse@2e9541b5,exception=null]
            May 21, 2015 9:27:45 AM FINE hudson.remoting.Channel
            Send UserRequest:hudson.remoting.PingThread$Ping@490ce9f7
            May 21, 2015 9:27:45 AM FINE hudson.remoting.Channel
            Received Response[retVal=hudson.remoting.UserResponse@39161514,exception=null]
            May 21, 2015 9:28:11 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.remoting.PingThread$Ping@6cab37b7
            May 21, 2015 9:28:11 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@6fef257b,exception=null]
            May 21, 2015 9:30:14 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7806,156)
            May 21, 2015 9:30:14 AM FINER hudson.remoting.PipeWindow
            decrease(7806,156)->1048420
            May 21, 2015 9:30:14 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Dead(7806)
            May 21, 2015 9:30:14 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7806,156)
            May 21, 2015 9:30:14 AM FINER hudson.remoting.PipeWindow
            increase(7806,156)->1048576
            May 21, 2015 9:31:33 AM FINE hudson.remoting.Channel
            Send ProxyOutputStream.EOF(7806)
            May 21, 2015 9:31:33 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@43cdd87,exception=null]
            May 21, 2015 9:31:46 AM FINE hudson.remoting.Channel
            Send UserRequest:hudson.remoting.Channel$IOSyncer@149db10e
            May 21, 2015 9:31:46 AM FINE hudson.remoting.Channel
            Received Response[retVal=hudson.remoting.UserResponse@1a5c7213,exception=null]
            May 21, 2015 9:31:46 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@52395ed7,exception=null]
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.Launcher$RemoteLauncher$KillTask@3be05f2
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Send UserRequest:hudson.util.ProcessTree$1@550d8b63
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received Response[retVal=hudson.remoting.UserResponse@50353a39,exception=null]
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@56819d52,exception=null]
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@6366d92b
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@753bc908
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@280b6859
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@4efbf99
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@180bd857
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@31a84416
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@1e0e19d2
            May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel
            Received hudson.remoting.UnexportCommand@2fc13968
            May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$FileCallableWrapper@31d58a4
            May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@369ff356,exception=null]
            May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$FileCallableWrapper@7cf54207
            May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@b7ff7fa,exception=null]
            May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.plugins.disk_usage.DiskUsageUtil$DiskUsageCallable@753692b0
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@4afdc934,exception=null]
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received UserRequest:org.jenkinsci.plugins.envinject.service.EnvironmentVariablesNodeLoader$1@b5bd77d
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@c0e3cb8,exception=null]
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received UserRequest:org.jenkinsci.plugins.envinject.service.EnvInjectActionSetter$1@247ba307
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@34b926d2,exception=null]
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$FileCallableWrapper@4c5e6823
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Response[retVal=hudson.remoting.UserResponse@3acba143,exception=null]
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received UserRequest:hudson.FilePath$FileCallableWrapper@3973f8ad
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send UserRequest:hudson.scm.SubversionWorkspaceSelector$1@2a614c69
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received Response[retVal=hudson.remoting.UserResponse@114f12d5,exception=null]
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7811,26)
            May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow
            decrease(7811,26)->1048550
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Pipe.Flush(7811)
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Pipe.Chunk(7811,1)
            May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow
            decrease(7811,1)->1048549
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Pipe.Flush(7811)
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Send Pipe.Flush(7811)
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7811,26)
            May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow
            increase(7811,26)->1048575
            May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel
            Received ProxyOutputStream.Ack(7811,1)
            May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow
            increase(7811,1)->1048576
            May 21, 2015 9:32:07 AM FINE hudson.remoting.Channel
            
            Show
            cblegare Charles Bouchard-Légaré added a comment - Here are some logs extracted using the loggers as you suggested. May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,227) May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow decrease(7806,227)->1048349 May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,227) May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow increase(7806,227)->1048576 May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,111) May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow decrease(7806,111)->1048465 May 21, 2015 9:25:40 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,111) May 21, 2015 9:25:40 AM FINER hudson.remoting.PipeWindow increase(7806,111)->1048576 May 21, 2015 9:25:44 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,1395) May 21, 2015 9:25:44 AM FINER hudson.remoting.PipeWindow decrease(7806,1395)->1047181 May 21, 2015 9:25:44 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,1395) May 21, 2015 9:25:44 AM FINER hudson.remoting.PipeWindow increase(7806,1395)->1048576 May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,39) May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow decrease(7806,39)->1048537 May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,39) May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow increase(7806,39)->1048576 May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,358) May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow decrease(7806,358)->1048218 May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,358) May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow increase(7806,358)->1048576 May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,776) May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow decrease(7806,776)->1047800 May 21, 2015 9:25:46 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,776) May 21, 2015 9:25:46 AM FINER hudson.remoting.PipeWindow increase(7806,776)->1048576 May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,39) May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow decrease(7806,39)->1048537 May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,39) May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow increase(7806,39)->1048576 May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,352) May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow decrease(7806,352)->1048224 May 21, 2015 9:25:48 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,352) May 21, 2015 9:25:48 AM FINER hudson.remoting.PipeWindow increase(7806,352)->1048576 May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,390) May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow decrease(7806,390)->1048186 May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,390) May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow increase(7806,390)->1048576 May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,388) May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow decrease(7806,388)->1048188 May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,388) May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow increase(7806,388)->1048576 May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,388) May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow decrease(7806,388)->1048188 May 21, 2015 9:25:50 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,388) May 21, 2015 9:25:50 AM FINER hudson.remoting.PipeWindow increase(7806,388)->1048576 May 21, 2015 9:25:53 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,1395) May 21, 2015 9:25:53 AM FINER hudson.remoting.PipeWindow decrease(7806,1395)->1047181 May 21, 2015 9:25:53 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,1395) May 21, 2015 9:25:53 AM FINER hudson.remoting.PipeWindow increase(7806,1395)->1048576 May 21, 2015 9:26:02 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,4417) May 21, 2015 9:26:02 AM FINER hudson.remoting.PipeWindow decrease(7806,4417)->1044159 May 21, 2015 9:26:02 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,4417) May 21, 2015 9:26:02 AM FINER hudson.remoting.PipeWindow increase(7806,4417)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1040384 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1032192 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1024000 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1015808 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1007616 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->999424 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->991232 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,5341) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,5341)->985891 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->994083 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1002275 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1010467 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1018659 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1026851 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1035043 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1043235 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,5341) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,5341)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1040384 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1032192 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1024000 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,8192)->1015808 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,6708) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,6708)->1009100 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1017292 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1025484 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1033676 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,8192) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,8192)->1041868 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,6708) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,6708)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,784)->1047792 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,784)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,784)->1047792 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,784)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,1568) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,1568)->1047008 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,1568) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,1568)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,784)->1047792 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,784)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,784)->1047792 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,784) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,784)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,38) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,38)->1048538 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,38) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,38)->1048576 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,51) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow decrease(7806,51)->1048525 May 21, 2015 9:26:05 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,51) May 21, 2015 9:26:05 AM FINER hudson.remoting.PipeWindow increase(7806,51)->1048576 May 21, 2015 9:26:12 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,4749) May 21, 2015 9:26:12 AM FINER hudson.remoting.PipeWindow decrease(7806,4749)->1043827 May 21, 2015 9:26:12 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,4749) May 21, 2015 9:26:12 AM FINER hudson.remoting.PipeWindow increase(7806,4749)->1048576 May 21, 2015 9:26:15 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,4419) May 21, 2015 9:26:15 AM FINER hudson.remoting.PipeWindow decrease(7806,4419)->1044157 May 21, 2015 9:26:15 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,4419) May 21, 2015 9:26:15 AM FINER hudson.remoting.PipeWindow increase(7806,4419)->1048576 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@6418c30a May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@381e8444 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@3f59462 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send ProxyOutputStream.Unexport(7798) May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1f8e9d7e May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@23c3231e May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@2ee90846 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@36394798 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@b0a88f6 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@773747fe May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@525ccc87 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send ProxyOutputStream.Unexport(7801) May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send ProxyOutputStream.Unexport(7802) May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@bf67fea May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@4f3bfef6 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@78a46620 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@f805e5e May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@6a24e609 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1a54bf85 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@659a2ec1 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@29d9bf25 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@4b974f33 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@5e9bbeb8 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1a78f425 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@9590290 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@ec92d24 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@52d9cb2f May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1d190fc6 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@a668644 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@45542848 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send ProxyOutputStream.Unexport(7804) May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send ProxyOutputStream.Unexport(7805) May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@4624c159 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1b643614 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@26dbeec5 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1fa040e9 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@4a41f04f May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1b6f87f7 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@23df9b8a May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@4b3eb044 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@3e0ecd9 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@1e86be7a May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@379d7899 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@113bc052 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@9a8a927 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@5825d1af May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@30f10cad May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@631f2e3 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@86cab9d May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@7b003acb May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@f1d83ca May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@4b831383 May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@c97e05f May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@35b5cfda May 21, 2015 9:26:39 AM FINE hudson.remoting.Channel Send hudson.remoting.UnexportCommand@45b7033b May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$FileCallableWrapper@2fc406e3 May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@4fe8ee13,exception= null ] May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$FileCallableWrapper@51a532cd May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@7d4b2672,exception= null ] May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$IsUnix@3613ea95 May 21, 2015 9:26:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@53d313f1,exception= null ] May 21, 2015 9:27:40 AM FINE hudson.remoting.Channel Send UserRequest:hudson.remoting.PingThread$Ping@52fcc248 May 21, 2015 9:27:40 AM FINE hudson.remoting.Channel Received Response[retVal=hudson.remoting.UserResponse@2e9541b5,exception= null ] May 21, 2015 9:27:45 AM FINE hudson.remoting.Channel Send UserRequest:hudson.remoting.PingThread$Ping@490ce9f7 May 21, 2015 9:27:45 AM FINE hudson.remoting.Channel Received Response[retVal=hudson.remoting.UserResponse@39161514,exception= null ] May 21, 2015 9:28:11 AM FINE hudson.remoting.Channel Received UserRequest:hudson.remoting.PingThread$Ping@6cab37b7 May 21, 2015 9:28:11 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@6fef257b,exception= null ] May 21, 2015 9:30:14 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7806,156) May 21, 2015 9:30:14 AM FINER hudson.remoting.PipeWindow decrease(7806,156)->1048420 May 21, 2015 9:30:14 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Dead(7806) May 21, 2015 9:30:14 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7806,156) May 21, 2015 9:30:14 AM FINER hudson.remoting.PipeWindow increase(7806,156)->1048576 May 21, 2015 9:31:33 AM FINE hudson.remoting.Channel Send ProxyOutputStream.EOF(7806) May 21, 2015 9:31:33 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@43cdd87,exception= null ] May 21, 2015 9:31:46 AM FINE hudson.remoting.Channel Send UserRequest:hudson.remoting.Channel$IOSyncer@149db10e May 21, 2015 9:31:46 AM FINE hudson.remoting.Channel Received Response[retVal=hudson.remoting.UserResponse@1a5c7213,exception= null ] May 21, 2015 9:31:46 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@52395ed7,exception= null ] May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received UserRequest:hudson.Launcher$RemoteLauncher$KillTask@3be05f2 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Send UserRequest:hudson.util.ProcessTree$1@550d8b63 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received Response[retVal=hudson.remoting.UserResponse@50353a39,exception= null ] May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@56819d52,exception= null ] May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@6366d92b May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@753bc908 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@280b6859 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@4efbf99 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@180bd857 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@31a84416 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@1e0e19d2 May 21, 2015 9:31:47 AM FINE hudson.remoting.Channel Received hudson.remoting.UnexportCommand@2fc13968 May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$FileCallableWrapper@31d58a4 May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@369ff356,exception= null ] May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$FileCallableWrapper@7cf54207 May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@b7ff7fa,exception= null ] May 21, 2015 9:31:48 AM FINE hudson.remoting.Channel Received UserRequest:hudson.plugins.disk_usage.DiskUsageUtil$DiskUsageCallable@753692b0 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@4afdc934,exception= null ] May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received UserRequest:org.jenkinsci.plugins.envinject.service.EnvironmentVariablesNodeLoader$1@b5bd77d May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@c0e3cb8,exception= null ] May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received UserRequest:org.jenkinsci.plugins.envinject.service.EnvInjectActionSetter$1@247ba307 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@34b926d2,exception= null ] May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$FileCallableWrapper@4c5e6823 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Response[retVal=hudson.remoting.UserResponse@3acba143,exception= null ] May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received UserRequest:hudson.FilePath$FileCallableWrapper@3973f8ad May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send UserRequest:hudson.scm.SubversionWorkspaceSelector$1@2a614c69 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received Response[retVal=hudson.remoting.UserResponse@114f12d5,exception= null ] May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7811,26) May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow decrease(7811,26)->1048550 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Pipe.Flush(7811) May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Pipe.Chunk(7811,1) May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow decrease(7811,1)->1048549 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Pipe.Flush(7811) May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Send Pipe.Flush(7811) May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7811,26) May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow increase(7811,26)->1048575 May 21, 2015 9:31:54 AM FINE hudson.remoting.Channel Received ProxyOutputStream.Ack(7811,1) May 21, 2015 9:31:54 AM FINER hudson.remoting.PipeWindow increase(7811,1)->1048576 May 21, 2015 9:32:07 AM FINE hudson.remoting.Channel
            Hide
            lacostej lacostej added a comment -

            Thanks Charles for the logs.

            I don't know what's happening yet but this should help us a bit. I am surprised to not see more communication.

            What can I see:

            • Pipe.Chunks are seen up to May 21, 2015 9:26:15
            • followed by lots of hudson.remoting.UnexportCommand
            • a PingThread kicks in at May 21, 2015 9:27:40 AM
            • a PingThread kicks in at May 21, 2015 9:28:11 AM
            • nothing during 2 min
            • a Pipe.Chunk is sent
            • a Dead is received instead of an Ack

            Here's a patch to apply to your remoting.jar https://github.com/lacostej/remoting/commit/02969e1271443afc933dcb8e0d472c1dfc9e8856 that could help knowing why the Death. Maybe worth a shot ?

            This also should help a bit: https://wiki.jenkins-ci.org/display/JENKINS/Remoting+issue although Charles said he couldn't find any specific info in his slaves logs.

            Show
            lacostej lacostej added a comment - Thanks Charles for the logs. I don't know what's happening yet but this should help us a bit. I am surprised to not see more communication. What can I see: Pipe.Chunks are seen up to May 21, 2015 9:26:15 followed by lots of hudson.remoting.UnexportCommand a PingThread kicks in at May 21, 2015 9:27:40 AM a PingThread kicks in at May 21, 2015 9:28:11 AM nothing during 2 min a Pipe.Chunk is sent a Dead is received instead of an Ack Here's a patch to apply to your remoting.jar https://github.com/lacostej/remoting/commit/02969e1271443afc933dcb8e0d472c1dfc9e8856 that could help knowing why the Death. Maybe worth a shot ? This also should help a bit: https://wiki.jenkins-ci.org/display/JENKINS/Remoting+issue although Charles said he couldn't find any specific info in his slaves logs.
            Hide
            lacostej lacostej added a comment - - edited

            Good news, I managed to find at least one reproducible scenario in which this error happens. It required a distributed built setup. More info later!

            Show
            lacostej lacostej added a comment - - edited Good news, I managed to find at least one reproducible scenario in which this error happens. It required a distributed built setup. More info later!
            Hide
            lacostej lacostej added a comment -

            I know the root cause and I have a fix that seems to pass my tests.

            The root cause is when I wrote the plugin, I created my own piping mechanism because I was having issues with the Jenkins remoting one. When doing so, I went with using the remoting and java.io.Piped*Stream.

            See https://github.com/jenkinsci/unity3d-plugin/blob/b4d78b6fee8752c02eacb35c1b0416c55d9d76f5/src/main/java/org/jenkinsci/plugins/unity3d/io/Pipe.java#L35

            While the java.io.Piped*Stream classes work fine most of the time, they have some issues, including thread unfriendliness. See http://www.live-graph.org/javadoc/complete/org/LiveGraph/dataFile/read/PipedInputStream.html for some description.

            As stated in the Javadoc for the java.io.PipedInputStream: A pipe is said to be broken if a thread that was providing data bytes to the connected piped output stream is no longer alive.

            In the case of jenkins used in a distributed scenario, those threads are pooled (search threadPoolForRemoting in jenkins core). In particular, if the remote output isn't producing output for a while, this pooling seems to have more chance of happening. In this case, the writeSide thread is recycled/replaced. The next call to read detects the "pipe is broken".

            So we cannot use the java.io.Piped*Stream in conjunction with Jenkins.

            Now it seems that I can use the jenkins remoting FastPiped*Stream classes and everything work fine. So easy...

            Show
            lacostej lacostej added a comment - I know the root cause and I have a fix that seems to pass my tests. The root cause is when I wrote the plugin, I created my own piping mechanism because I was having issues with the Jenkins remoting one. When doing so, I went with using the remoting and java.io.Piped*Stream. See https://github.com/jenkinsci/unity3d-plugin/blob/b4d78b6fee8752c02eacb35c1b0416c55d9d76f5/src/main/java/org/jenkinsci/plugins/unity3d/io/Pipe.java#L35 While the java.io.Piped*Stream classes work fine most of the time, they have some issues, including thread unfriendliness. See http://www.live-graph.org/javadoc/complete/org/LiveGraph/dataFile/read/PipedInputStream.html for some description. As stated in the Javadoc for the java.io.PipedInputStream: A pipe is said to be broken if a thread that was providing data bytes to the connected piped output stream is no longer alive. In the case of jenkins used in a distributed scenario, those threads are pooled (search threadPoolForRemoting in jenkins core). In particular, if the remote output isn't producing output for a while, this pooling seems to have more chance of happening. In this case, the writeSide thread is recycled/replaced. The next call to read detects the "pipe is broken". So we cannot use the java.io.Piped*Stream in conjunction with Jenkins. Now it seems that I can use the jenkins remoting FastPiped*Stream classes and everything work fine. So easy...
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Jerome Lacoste
            Path:
            src/main/java/org/jenkinsci/plugins/unity3d/io/Pipe.java
            http://jenkins-ci.org/commit/unity3d-plugin/dff4212ee1f3c9ec1ed54dda0f2788d0126d2fc1
            Log:
            [FIXED JENKINS-23958] use jenkins remoting piping streams for piping. java.io.Piped*Stream are not threads friendly and cause 'Pipe is broken' issue when jenkins pool the writing threads

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Jerome Lacoste Path: src/main/java/org/jenkinsci/plugins/unity3d/io/Pipe.java http://jenkins-ci.org/commit/unity3d-plugin/dff4212ee1f3c9ec1ed54dda0f2788d0126d2fc1 Log: [FIXED JENKINS-23958] use jenkins remoting piping streams for piping. java.io.Piped*Stream are not threads friendly and cause 'Pipe is broken' issue when jenkins pool the writing threads
            scm_issue_link SCM/JIRA link daemon made changes -
            Status Open [ 1 ] Resolved [ 5 ]
            Resolution Fixed [ 1 ]
            Hide
            lacostej lacostej added a comment -

            Fixed in v0.8

            Show
            lacostej lacostej added a comment - Fixed in v0.8
            lacostej lacostej made changes -
            Status Resolved [ 5 ] Closed [ 6 ]
            rtyler R. Tyler Croy made changes -
            Workflow JNJira [ 156828 ] JNJira + In-Review [ 207892 ]

              People

              • Assignee:
                lacostej lacostej
                Reporter:
                tommigun Tommi Kiviniemi
              • Votes:
                1 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: