History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: QB-3108
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Critical Critical
Assignee: Robin Shen
Reporter: AlSt
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
QuickBuild

Build timeout does not work on build running a command line in combination with force kill

Created: 28/Dec/17 11:48 AM   Updated: 13/Jan/18 01:24 AM
Component/s: None
Affects Version/s: 7.0.30
Fix Version/s: None

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: Unknown


 Description  « Hide
Following situation:
Build with
* Checkout step
* Gradle build step

Build timeout: 25 minutes
Force kill timeout: 60 seconds

Build times out and the "Terminating launched command gracefully..." log line appears.
Graceful termination takes longer than 60 seconds -> Force kill is not triggered.
After approx 50 minutes (after the graceful kill log line was shown) the cancel button is pressed because the build should have been stopped already for 49 minutes or so (after the force kill timeout expired).
Now the "Unable to terminate launched command gracefully, terminating forcibly instead..." log line appears.

I took a look at the source code and I think I know what's the problem there:

com/pmease/quickbuild/execution/Commandline.java: Lines 350-378:

InterruptedException interruptedException = null;
try {
result.setReturnCode(process.waitFor());
} catch (InterruptedException e) {
interruptedException = e;
Context.getLogger().info("Terminating launched command gracefully...");
terminateProcessTree(process, session, false);
}
long lastTime = System.currentTimeMillis();

Configuration configuration = Context.getConfiguration();
int forceKillTimeout;
if (configuration != null)
forceKillTimeout = configuration.findForceKillTimeout();
else
forceKillTimeout = 5;

while (!streamPumper.closed()) {
try {
Thread.sleep(100);
} catch (InterruptedException e) {
if (System.currentTimeMillis() - lastTime > forceKillTimeout*1000L) {
             Context.getLogger().info("Unable to terminate launched command gracefully, terminating forcibly instead...");
             terminateProcessTree(process, session, true);
lastTime = System.currentTimeMillis();
}
}
}

The problem is that the interruption state is not preserved...
Thread.sleep() resets the interruption state of the current thread and also the second InterruptedException is never thrown automatically. That's why the manual click of the cancel button solves that as the interruptedexception is thrown again.

The fix should be putting
if (System.currentTimeMillis() - lastTime > forceKillTimeout*1000L) {
             Context.getLogger().info("Unable to terminate launched command gracefully, terminating forcibly instead...");
             terminateProcessTree(process, session, true);
lastTime = System.currentTimeMillis();
}
outside the catch block to check it always.

I think the whole code example should be changed to something like:
InterruptedException interruptedException = null;
try {
result.setReturnCode(process.waitFor());
} catch (InterruptedException e) {
interruptedException = e;
Context.getLogger().info("Terminating launched command gracefully...");
terminateProcessTree(process, session, false);

long lastTime = System.currentTimeMillis();

Configuration configuration = Context.getConfiguration();
int forceKillTimeout;
if (configuration != null)
forceKillTimeout = configuration.findForceKillTimeout();
else
forceKillTimeout = 5;

while (!streamPumper.closed()) {
try {
Thread.sleep(100);
} catch (InterruptedException e) {

}
if (System.currentTimeMillis() - lastTime > forceKillTimeout*1000L) {
Context.getLogger().info("Unable to terminate launched command gracefully, terminating forcibly instead...");
terminateProcessTree(process, session, true);
lastTime = System.currentTimeMillis();
}
}

}

Then the first interruptedexception is caught... the graceful terminate is triggered... the streamPumper state is checked periodically and if the forceKillTimeout is reached -> the force kill is triggered.

Please share your thoughts on this, but I think this is the solution for this problem.


 All   Comments   Work Log   Change History      Sort Order:
Robin Shen [28/Dec/17 10:15 PM]
Thanks for the investigation. That is really the problem. Changed your suggestion slightly to make QB always trying to terminate gracefully before force kill:

InterruptedException interruptedException = null;
  try {
    result.setReturnCode(process.waitFor());
  } catch (InterruptedException e) {
    interruptedException = e;
    Context.getLogger().info("Terminating launched command gracefully...");
    terminateProcessTree(process, session, false);
  }
  long lastTime = System.currentTimeMillis();
            
  Configuration configuration = Context.getConfiguration();
  int forceKillTimeout;
  if (configuration != null)
    forceKillTimeout = configuration.findForceKillTimeout();
  else
    forceKillTimeout = 5;

  while (!streamPumper.closed()) {
    try {
      Thread.sleep(100);
      } catch (InterruptedException e) {
        if (interruptedException == null) { // if not interrupted before, try a graceful kill
interruptedException = e;
Context.getLogger().info("Terminating launched command gracefully...");
terminateProcessTree(process, session, false);
lastTime = System.currentTimeMillis();
}
    }
        
    if (interruptedException != null && System.currentTimeMillis() - lastTime > forceKillTimeout*1000L) {
      Context.getLogger().info("Unable to terminate launched command gracefully, terminating forcibly instead...");
      terminateProcessTree(process, session, true);
      lastTime = System.currentTimeMillis();
    }
 }

AlSt [29/Dec/17 06:58 AM]
Looks like the way to go :-)