1 /* 2 * Copyright (C) 2010 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package com.android.tradefed.util; 18 19 20 import com.android.annotations.Nullable; 21 import com.android.tradefed.command.CommandInterrupter; 22 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationMetricKey; 23 import com.android.tradefed.invoker.tracing.CloseableTraceScope; 24 import com.android.tradefed.log.LogUtil.CLog; 25 import com.android.tradefed.result.error.ErrorIdentifier; 26 27 import com.google.common.annotations.VisibleForTesting; 28 import com.google.common.base.Strings; 29 30 import java.io.BufferedOutputStream; 31 import java.io.File; 32 import java.io.IOException; 33 import java.io.InputStream; 34 import java.io.OutputStream; 35 import java.lang.ProcessBuilder.Redirect; 36 import java.util.ArrayList; 37 import java.util.Arrays; 38 import java.util.HashMap; 39 import java.util.HashSet; 40 import java.util.List; 41 import java.util.Map; 42 import java.util.Set; 43 import java.util.concurrent.CountDownLatch; 44 import java.util.concurrent.TimeUnit; 45 import java.util.stream.Collectors; 46 47 import javax.annotation.Nonnull; 48 49 /** 50 * A collection of helper methods for executing operations. 51 */ 52 public class RunUtil implements IRunUtil { 53 54 public static final String RUNNABLE_NOTIFIER_NAME = "RunnableNotifier"; 55 public static final String INHERITIO_PREFIX = "inheritio-"; 56 57 private static final int POLL_TIME_INCREASE_FACTOR = 4; 58 private static final long THREAD_JOIN_POLL_INTERVAL = 30 * 1000; 59 private static final long PROCESS_DESTROY_TIMEOUT_SEC = 2; 60 private long mPollingInterval = THREAD_JOIN_POLL_INTERVAL; 61 private static IRunUtil sDefaultInstance = null; 62 private File mWorkingDir = null; 63 private Map<String, String> mEnvVariables = new HashMap<String, String>(); 64 private Set<String> mUnsetEnvVariables = new HashSet<String>(); 65 private EnvPriority mEnvVariablePriority = EnvPriority.UNSET; 66 private boolean mRedirectStderr = false; 67 private boolean mLinuxInterruptProcess = false; 68 69 private final CommandInterrupter mInterrupter; 70 private final boolean mInheritEnvVars; 71 72 /** 73 * Create a new {@link RunUtil} object to use. 74 */ RunUtil()75 public RunUtil() { 76 this(CommandInterrupter.INSTANCE); 77 } 78 RunUtil(boolean inheritEnvVars)79 public RunUtil(boolean inheritEnvVars) { 80 this(CommandInterrupter.INSTANCE, inheritEnvVars); 81 } 82 83 @VisibleForTesting RunUtil(@onnull CommandInterrupter interrupter)84 RunUtil(@Nonnull CommandInterrupter interrupter) { 85 this(interrupter, true); 86 } 87 RunUtil(@onnull CommandInterrupter interrupter, boolean inheritEnvVars)88 private RunUtil(@Nonnull CommandInterrupter interrupter, boolean inheritEnvVars) { 89 mInterrupter = interrupter; 90 mInheritEnvVars = inheritEnvVars; 91 } 92 93 /** 94 * Get a reference to the default {@link RunUtil} object. 95 * <p/> 96 * This is useful for callers who want to use IRunUtil without customization. 97 * Its recommended that callers who do need a custom IRunUtil instance 98 * (ie need to call either {@link #setEnvVariable(String, String)} or 99 * {@link #setWorkingDir(File)} create their own copy. 100 */ getDefault()101 public static IRunUtil getDefault() { 102 if (sDefaultInstance == null) { 103 sDefaultInstance = new RunUtil(); 104 } 105 return sDefaultInstance; 106 } 107 108 /** 109 * Sets a new value for the internal polling interval. In most cases, you should never have a 110 * need to change the polling interval except for specific cases such as unit tests. 111 * 112 * @param pollInterval in ms for polling interval. Must be larger than 100ms. 113 */ 114 @VisibleForTesting setPollingInterval(long pollInterval)115 void setPollingInterval(long pollInterval) { 116 if (pollInterval >= 100) { 117 mPollingInterval = pollInterval; 118 return; 119 } 120 throw new IllegalArgumentException("Polling interval set too low. Try 100ms."); 121 } 122 123 /** 124 * {@inheritDoc} 125 */ 126 @Override setWorkingDir(File dir)127 public synchronized void setWorkingDir(File dir) { 128 if (this.equals(sDefaultInstance)) { 129 throw new UnsupportedOperationException("Cannot setWorkingDir on default RunUtil"); 130 } 131 mWorkingDir = dir; 132 } 133 134 /** 135 * {@inheritDoc} 136 */ 137 @Override setEnvVariable(String name, String value)138 public synchronized void setEnvVariable(String name, String value) { 139 if (this.equals(sDefaultInstance)) { 140 throw new UnsupportedOperationException("Cannot setEnvVariable on default RunUtil"); 141 } 142 mEnvVariables.put(name, value); 143 } 144 145 /** 146 * {@inheritDoc} 147 * Environment variables may inherit from the parent process, so we need to delete 148 * the environment variable from {@link ProcessBuilder#environment()} 149 * 150 * @param key the variable name 151 * @see ProcessBuilder#environment() 152 */ 153 @Override unsetEnvVariable(String key)154 public synchronized void unsetEnvVariable(String key) { 155 if (this.equals(sDefaultInstance)) { 156 throw new UnsupportedOperationException("Cannot unsetEnvVariable on default RunUtil"); 157 } 158 mUnsetEnvVariables.add(key); 159 } 160 161 /** {@inheritDoc} */ 162 @Override setRedirectStderrToStdout(boolean redirect)163 public void setRedirectStderrToStdout(boolean redirect) { 164 if (this.equals(sDefaultInstance)) { 165 throw new UnsupportedOperationException( 166 "Cannot setRedirectStderrToStdout on default RunUtil"); 167 } 168 mRedirectStderr = redirect; 169 } 170 171 /** 172 * {@inheritDoc} 173 */ 174 @Override runTimedCmd(final long timeout, final String... command)175 public CommandResult runTimedCmd(final long timeout, final String... command) { 176 return runTimedCmd(timeout, (OutputStream) null, (OutputStream) null, command); 177 } 178 179 /** {@inheritDoc} */ 180 @Override runTimedCmdWithOutputMonitor( final long timeout, final long idleOutputTimeout, final String... command)181 public CommandResult runTimedCmdWithOutputMonitor( 182 final long timeout, final long idleOutputTimeout, final String... command) { 183 return runTimedCmdWithOutputMonitor( 184 timeout, idleOutputTimeout, (OutputStream) null, (OutputStream) null, command); 185 } 186 187 /** {@inheritDoc} */ 188 @Override runTimedCmd( final long timeout, final OutputStream stdout, OutputStream stderr, final String... command)189 public CommandResult runTimedCmd( 190 final long timeout, 191 final OutputStream stdout, 192 OutputStream stderr, 193 final String... command) { 194 return runTimedCmdWithOutputMonitor(timeout, 0, stdout, stderr, command); 195 } 196 197 /** {@inheritDoc} */ 198 @Override runTimedCmdWithOutputMonitor( final long timeout, final long idleOutputTimeout, final OutputStream stdout, OutputStream stderr, final String... command)199 public CommandResult runTimedCmdWithOutputMonitor( 200 final long timeout, 201 final long idleOutputTimeout, 202 final OutputStream stdout, 203 OutputStream stderr, 204 final String... command) { 205 ProcessBuilder processBuilder = createProcessBuilder(command); 206 RunnableResult osRunnable = createRunnableResult(stdout, stderr, processBuilder); 207 CommandStatus status = 208 runTimedWithOutputMonitor(timeout, idleOutputTimeout, osRunnable, true); 209 CommandResult result = osRunnable.getResult(); 210 result.setStatus(status); 211 return result; 212 } 213 214 /** 215 * Create a {@link com.android.tradefed.util.IRunUtil.IRunnableResult} that will run the 216 * command. 217 */ 218 @VisibleForTesting createRunnableResult( OutputStream stdout, OutputStream stderr, ProcessBuilder processBuilder)219 RunnableResult createRunnableResult( 220 OutputStream stdout, OutputStream stderr, ProcessBuilder processBuilder) { 221 return new RunnableResult( 222 /* input= */ null, 223 processBuilder, 224 stdout, 225 stderr, 226 /* inputRedirect= */ null, 227 false); 228 } 229 230 /** {@inheritDoc} */ 231 @Override runTimedCmdRetry( long timeout, long retryInterval, int attempts, String... command)232 public CommandResult runTimedCmdRetry( 233 long timeout, long retryInterval, int attempts, String... command) { 234 return runTimedCmdRetryWithOutputMonitor(timeout, 0, retryInterval, attempts, command); 235 } 236 237 /** {@inheritDoc} */ 238 @Override runTimedCmdRetryWithOutputMonitor( long timeout, long idleOutputTimeout, long retryInterval, int attempts, String... command)239 public CommandResult runTimedCmdRetryWithOutputMonitor( 240 long timeout, 241 long idleOutputTimeout, 242 long retryInterval, 243 int attempts, 244 String... command) { 245 CommandResult result = null; 246 int counter = 0; 247 while (counter < attempts) { 248 result = runTimedCmdWithOutputMonitor(timeout, idleOutputTimeout, command); 249 if (CommandStatus.SUCCESS.equals(result.getStatus())) { 250 return result; 251 } 252 sleep(retryInterval); 253 counter++; 254 } 255 return result; 256 } 257 createProcessBuilder(String... command)258 private synchronized ProcessBuilder createProcessBuilder(String... command) { 259 return createProcessBuilder(Arrays.asList(command)); 260 } 261 createProcessBuilder(Redirect redirect, String... command)262 private synchronized ProcessBuilder createProcessBuilder(Redirect redirect, String... command) { 263 return createProcessBuilder(redirect, Arrays.asList(command), false); 264 } 265 createProcessBuilder(List<String> commandList)266 private synchronized ProcessBuilder createProcessBuilder(List<String> commandList) { 267 return createProcessBuilder(null, commandList, false); 268 } 269 createProcessBuilder( Redirect redirect, List<String> commandList, boolean enableCache)270 public synchronized ProcessBuilder createProcessBuilder( 271 Redirect redirect, List<String> commandList, boolean enableCache) { 272 ProcessBuilder processBuilder = new ProcessBuilder(); 273 if (!mInheritEnvVars) { 274 processBuilder.environment().clear(); 275 } 276 277 if (mWorkingDir != null) { 278 processBuilder.directory(mWorkingDir); 279 } 280 Map<String, String> env = mEnvVariables; 281 if (enableCache) { 282 File workingDir = 283 processBuilder.directory() != null 284 ? processBuilder.directory() 285 : new File(System.getProperty("user.dir")); 286 for (int i = 0; i < commandList.size(); i++) { 287 String prefix = i < 1 ? "./" : ""; 288 commandList.set(i, prefix + toRelative(workingDir, commandList.get(i))); 289 } 290 for (Map.Entry<String, String> entry : env.entrySet()) { 291 String key = entry.getKey(); 292 if (key.equals("LD_LIBRARY_PATH")) { 293 env.put( 294 key, 295 Arrays.asList(entry.getValue().split(pathSeparator())).stream() 296 .map(p -> toRelative(workingDir, p)) 297 .sorted() 298 .collect(Collectors.joining(pathSeparator()))); 299 } 300 } 301 } 302 // By default unset an env. for process has higher priority, but in some case we might want 303 // the 'set' to have priority. 304 if (EnvPriority.UNSET.equals(mEnvVariablePriority)) { 305 if (!env.isEmpty()) { 306 processBuilder.environment().putAll(env); 307 } 308 if (!mUnsetEnvVariables.isEmpty()) { 309 // in this implementation, the unsetEnv's priority is higher than set. 310 processBuilder.environment().keySet().removeAll(mUnsetEnvVariables); 311 } 312 } else { 313 if (!mUnsetEnvVariables.isEmpty()) { 314 processBuilder.environment().keySet().removeAll(mUnsetEnvVariables); 315 } 316 if (!env.isEmpty()) { 317 // in this implementation, the setEnv's priority is higher than set. 318 processBuilder.environment().putAll(env); 319 } 320 } 321 processBuilder.redirectErrorStream(mRedirectStderr); 322 if (redirect != null) { 323 processBuilder.redirectOutput(redirect); 324 processBuilder.redirectError(redirect); 325 } 326 return processBuilder.command(commandList); 327 } 328 329 /** 330 * {@inheritDoc} 331 */ 332 @Override runTimedCmdWithInput(final long timeout, String input, final String... command)333 public CommandResult runTimedCmdWithInput(final long timeout, String input, 334 final String... command) { 335 return runTimedCmdWithInput(timeout, input, ArrayUtil.list(command)); 336 } 337 338 /** 339 * {@inheritDoc} 340 */ 341 @Override runTimedCmdWithInput(final long timeout, String input, final List<String> command)342 public CommandResult runTimedCmdWithInput(final long timeout, String input, 343 final List<String> command) { 344 RunnableResult osRunnable = new RunnableResult(input, createProcessBuilder(command)); 345 CommandStatus status = runTimed(timeout, osRunnable, true); 346 CommandResult result = osRunnable.getResult(); 347 result.setStatus(status); 348 return result; 349 } 350 351 /** {@inheritDoc} */ 352 @Override runTimedCmdWithInput( long timeout, String input, File stdoutFile, File stderrFile, String... command)353 public CommandResult runTimedCmdWithInput( 354 long timeout, String input, File stdoutFile, File stderrFile, String... command) { 355 ProcessBuilder pb = createProcessBuilder(command); 356 pb.redirectOutput(ProcessBuilder.Redirect.to(stdoutFile)); 357 pb.redirectError(ProcessBuilder.Redirect.to(stderrFile)); 358 RunnableResult osRunnable = new RunnableResult(input, pb); 359 CommandStatus status = runTimed(timeout, osRunnable, true); 360 CommandResult result = osRunnable.getResult(); 361 result.setStatus(status); 362 // In case of error backfill, copy stderr to its file 363 if (result.getExitCode() == 88) { 364 try { 365 FileUtil.writeToFile(result.getStderr(), stderrFile, true); 366 } catch (IOException e) { 367 // Ignore 368 } 369 } 370 return result; 371 } 372 373 /** {@inheritDoc} */ 374 @Override runTimedCmdWithInputRedirect( final long timeout, @Nullable File inputRedirect, final String... command)375 public CommandResult runTimedCmdWithInputRedirect( 376 final long timeout, @Nullable File inputRedirect, final String... command) { 377 RunnableResult osRunnable = 378 new RunnableResult( 379 /* input= */ null, 380 createProcessBuilder(command), 381 /* stdoutStream= */ null, 382 /* stderrStream= */ null, 383 inputRedirect, 384 true); 385 CommandStatus status = runTimed(timeout, osRunnable, true); 386 CommandResult result = osRunnable.getResult(); 387 result.setStatus(status); 388 return result; 389 } 390 391 /** {@inheritDoc} */ 392 @Override runTimedCmdSilently(final long timeout, final String... command)393 public CommandResult runTimedCmdSilently(final long timeout, final String... command) { 394 RunnableResult osRunnable = new RunnableResult(null, createProcessBuilder(command), false); 395 CommandStatus status = runTimed(timeout, osRunnable, false); 396 CommandResult result = osRunnable.getResult(); 397 result.setStatus(status); 398 return result; 399 } 400 401 /** 402 * {@inheritDoc} 403 */ 404 @Override runTimedCmdSilentlyRetry(long timeout, long retryInterval, int attempts, String... command)405 public CommandResult runTimedCmdSilentlyRetry(long timeout, long retryInterval, int attempts, 406 String... command) { 407 CommandResult result = null; 408 int counter = 0; 409 while (counter < attempts) { 410 result = runTimedCmdSilently(timeout, command); 411 if (CommandStatus.SUCCESS.equals(result.getStatus())) { 412 return result; 413 } 414 sleep(retryInterval); 415 counter++; 416 } 417 return result; 418 } 419 420 /** 421 * {@inheritDoc} 422 */ 423 @Override runCmdInBackground(final String... command)424 public Process runCmdInBackground(final String... command) throws IOException { 425 return runCmdInBackground(null, command); 426 } 427 428 /** {@inheritDoc} */ 429 @Override runCmdInBackground(Redirect redirect, final String... command)430 public Process runCmdInBackground(Redirect redirect, final String... command) 431 throws IOException { 432 final String fullCmd = Arrays.toString(command); 433 CLog.v("Running in background: %s", fullCmd); 434 return createProcessBuilder(redirect, command).start(); 435 } 436 437 /** 438 * {@inheritDoc} 439 */ 440 @Override runCmdInBackground(final List<String> command)441 public Process runCmdInBackground(final List<String> command) throws IOException { 442 return runCmdInBackground(null, command); 443 } 444 445 /** {@inheritDoc} */ 446 @Override runCmdInBackground(Redirect redirect, final List<String> command)447 public Process runCmdInBackground(Redirect redirect, final List<String> command) 448 throws IOException { 449 CLog.v("Running in background: %s", command); 450 return createProcessBuilder(redirect, command, false).start(); 451 } 452 453 /** 454 * {@inheritDoc} 455 */ 456 @Override runCmdInBackground(List<String> command, OutputStream output)457 public Process runCmdInBackground(List<String> command, OutputStream output) 458 throws IOException { 459 CLog.v("Running in background: %s", command); 460 Process process = createProcessBuilder(command).start(); 461 inheritIO( 462 process.getInputStream(), 463 output, 464 String.format(INHERITIO_PREFIX + "stdout-%s", command)); 465 inheritIO( 466 process.getErrorStream(), 467 output, 468 String.format(INHERITIO_PREFIX + "stderr-%s", command)); 469 return process; 470 } 471 472 /** 473 * {@inheritDoc} 474 */ 475 @Override runTimed(long timeout, IRunUtil.IRunnableResult runnable, boolean logErrors)476 public CommandStatus runTimed(long timeout, IRunUtil.IRunnableResult runnable, 477 boolean logErrors) { 478 return runTimedWithOutputMonitor(timeout, 0, runnable, logErrors); 479 } 480 481 /** {@inheritDoc} */ 482 @Override runTimedWithOutputMonitor( long timeout, long idleOutputTimeout, IRunUtil.IRunnableResult runnable, boolean logErrors)483 public CommandStatus runTimedWithOutputMonitor( 484 long timeout, 485 long idleOutputTimeout, 486 IRunUtil.IRunnableResult runnable, 487 boolean logErrors) { 488 mInterrupter.checkInterrupted(); 489 RunnableNotifier runThread = new RunnableNotifier(runnable, logErrors); 490 if (logErrors) { 491 if (timeout > 0L) { 492 CLog.d( 493 "Running command %s with timeout: %s", 494 runnable.getCommand(), TimeUtil.formatElapsedTime(timeout)); 495 } else { 496 CLog.d("Running command %s without timeout.", runnable.getCommand()); 497 } 498 } 499 CommandStatus status = CommandStatus.TIMED_OUT; 500 try { 501 runThread.start(); 502 long startTime = System.currentTimeMillis(); 503 long pollInterval = 0; 504 if (timeout > 0L && timeout < mPollingInterval) { 505 // only set the pollInterval if we have a timeout 506 pollInterval = timeout; 507 } else { 508 pollInterval = mPollingInterval; 509 } 510 do { 511 try { 512 // Check if the command is still making progress. 513 if (idleOutputTimeout != 0 514 && runThread.isAlive() 515 && !runnable.checkOutputMonitor(idleOutputTimeout)) { 516 // Set to Failed. 517 runThread.cancel(); 518 } else { 519 runThread.join(pollInterval); 520 } 521 } catch (InterruptedException e) { 522 if (isInterruptAllowed()) { 523 CLog.i("runTimed: interrupted while joining the runnable"); 524 break; 525 } else { 526 CLog.i("runTimed: currently uninterruptible, ignoring interrupt"); 527 } 528 } 529 mInterrupter.checkInterrupted(); 530 } while ((timeout == 0L || (System.currentTimeMillis() - startTime) < timeout) 531 && runThread.isAlive()); 532 } catch (RunInterruptedException e) { 533 runThread.cancel(); 534 throw e; 535 } finally { 536 // Snapshot the status when out of the run loop because thread may terminate and return 537 // a false FAILED instead of TIMED_OUT. 538 status = runThread.getStatus(); 539 if (CommandStatus.TIMED_OUT.equals(status) || CommandStatus.EXCEPTION.equals(status)) { 540 CLog.i("runTimed: Calling interrupt, status is %s", status); 541 runThread.cancel(); 542 } 543 } 544 mInterrupter.checkInterrupted(); 545 return status; 546 } 547 548 /** 549 * {@inheritDoc} 550 */ 551 @Override runTimedRetry(long opTimeout, long pollInterval, int attempts, IRunUtil.IRunnableResult runnable)552 public boolean runTimedRetry(long opTimeout, long pollInterval, int attempts, 553 IRunUtil.IRunnableResult runnable) { 554 return runTimedRetryWithOutputMonitor(opTimeout, 0, pollInterval, attempts, runnable); 555 } 556 557 /** {@inheritDoc} */ 558 @Override runTimedRetryWithOutputMonitor( long opTimeout, long idleOutputTimeout, long pollInterval, int attempts, IRunUtil.IRunnableResult runnable)559 public boolean runTimedRetryWithOutputMonitor( 560 long opTimeout, 561 long idleOutputTimeout, 562 long pollInterval, 563 int attempts, 564 IRunUtil.IRunnableResult runnable) { 565 for (int i = 0; i < attempts; i++) { 566 if (runTimedWithOutputMonitor(opTimeout, idleOutputTimeout, runnable, true) 567 == CommandStatus.SUCCESS) { 568 return true; 569 } 570 CLog.d("operation failed, waiting for %d ms", pollInterval); 571 sleep(pollInterval); 572 } 573 return false; 574 } 575 576 /** 577 * {@inheritDoc} 578 */ 579 @Override runFixedTimedRetry(final long opTimeout, final long pollInterval, final long maxTime, final IRunUtil.IRunnableResult runnable)580 public boolean runFixedTimedRetry(final long opTimeout, final long pollInterval, 581 final long maxTime, final IRunUtil.IRunnableResult runnable) { 582 return runFixedTimedRetryWithOutputMonitor(opTimeout, 0, pollInterval, maxTime, runnable); 583 } 584 585 /** {@inheritDoc} */ 586 @Override runFixedTimedRetryWithOutputMonitor( final long opTimeout, long idleOutputTimeout, final long pollInterval, final long maxTime, final IRunUtil.IRunnableResult runnable)587 public boolean runFixedTimedRetryWithOutputMonitor( 588 final long opTimeout, 589 long idleOutputTimeout, 590 final long pollInterval, 591 final long maxTime, 592 final IRunUtil.IRunnableResult runnable) { 593 final long initialTime = getCurrentTime(); 594 while (getCurrentTime() < (initialTime + maxTime)) { 595 if (runTimedWithOutputMonitor(opTimeout, idleOutputTimeout, runnable, true) 596 == CommandStatus.SUCCESS) { 597 return true; 598 } 599 CLog.d("operation failed, waiting for %d ms", pollInterval); 600 sleep(pollInterval); 601 } 602 return false; 603 } 604 605 /** {@inheritDoc} */ 606 @Override runEscalatingTimedRetry( final long opTimeout, final long initialPollInterval, final long maxPollInterval, final long maxTime, final IRunUtil.IRunnableResult runnable)607 public boolean runEscalatingTimedRetry( 608 final long opTimeout, 609 final long initialPollInterval, 610 final long maxPollInterval, 611 final long maxTime, 612 final IRunUtil.IRunnableResult runnable) { 613 // wait an initial time provided 614 long pollInterval = initialPollInterval; 615 final long initialTime = getCurrentTime(); 616 while (true) { 617 if (runTimedWithOutputMonitor(opTimeout, 0, runnable, true) == CommandStatus.SUCCESS) { 618 return true; 619 } 620 long remainingTime = maxTime - (getCurrentTime() - initialTime); 621 if (remainingTime <= 0) { 622 CLog.d("operation is still failing after retrying for %d ms", maxTime); 623 return false; 624 } else if (remainingTime < pollInterval) { 625 // cap pollInterval to a max of remainingTime 626 pollInterval = remainingTime; 627 } 628 CLog.d("operation failed, waiting for %d ms", pollInterval); 629 sleep(pollInterval); 630 // somewhat arbitrarily, increase the poll time by a factor of 4 for each attempt, 631 // up to the previously decided maximum 632 pollInterval *= POLL_TIME_INCREASE_FACTOR; 633 if (pollInterval > maxPollInterval) { 634 pollInterval = maxPollInterval; 635 } 636 } 637 } 638 639 /** 640 * Retrieves the current system clock time. 641 * <p/> 642 * Exposed so it can be mocked for unit testing 643 */ getCurrentTime()644 long getCurrentTime() { 645 return System.currentTimeMillis(); 646 } 647 648 /** 649 * {@inheritDoc} 650 */ 651 @Override sleep(long time)652 public void sleep(long time) { 653 mInterrupter.checkInterrupted(); 654 if (time <= 0) { 655 return; 656 } 657 try (CloseableTraceScope sleep = 658 new CloseableTraceScope(InvocationMetricKey.host_sleep.toString())) { 659 Thread.sleep(time); 660 } catch (InterruptedException e) { 661 // ignore 662 CLog.d("sleep interrupted"); 663 } 664 mInterrupter.checkInterrupted(); 665 } 666 667 /** {@inheritDoc} */ 668 @Override allowInterrupt(boolean allow)669 public void allowInterrupt(boolean allow) { 670 if (allow) { 671 mInterrupter.allowInterrupt(); 672 } else { 673 mInterrupter.blockInterrupt(); 674 } 675 } 676 677 /** {@inheritDoc} */ 678 @Override isInterruptAllowed()679 public boolean isInterruptAllowed() { 680 return mInterrupter.isInterruptible(); 681 } 682 683 /** {@inheritDoc} */ 684 @Override setInterruptibleInFuture(Thread thread, final long timeMs)685 public void setInterruptibleInFuture(Thread thread, final long timeMs) { 686 mInterrupter.allowInterruptAsync(thread, timeMs, TimeUnit.MILLISECONDS); 687 } 688 689 /** {@inheritDoc} */ 690 @Override interrupt(Thread thread, String message)691 public synchronized void interrupt(Thread thread, String message) { 692 interrupt(thread, message, null); 693 } 694 695 /** {@inheritDoc} */ 696 @Override interrupt(Thread thread, String message, ErrorIdentifier errorId)697 public synchronized void interrupt(Thread thread, String message, ErrorIdentifier errorId) { 698 mInterrupter.interrupt(thread, message, errorId); 699 mInterrupter.checkInterrupted(); 700 } 701 702 /** 703 * Helper thread that wraps a runnable, and notifies when done. 704 */ 705 private static class RunnableNotifier extends Thread { 706 707 private final IRunUtil.IRunnableResult mRunnable; 708 private CommandStatus mStatus = CommandStatus.TIMED_OUT; 709 private boolean mLogErrors = true; 710 RunnableNotifier(IRunUtil.IRunnableResult runnable, boolean logErrors)711 RunnableNotifier(IRunUtil.IRunnableResult runnable, boolean logErrors) { 712 // Set this thread to be a daemon so that it does not prevent 713 // TF from shutting down. 714 setName(RUNNABLE_NOTIFIER_NAME); 715 setDaemon(true); 716 mRunnable = runnable; 717 mLogErrors = logErrors; 718 } 719 720 @Override run()721 public void run() { 722 CommandStatus status; 723 try { 724 status = mRunnable.run() ? CommandStatus.SUCCESS : CommandStatus.FAILED; 725 } catch (InterruptedException e) { 726 CLog.i("runutil interrupted"); 727 status = CommandStatus.EXCEPTION; 728 backFillException(mRunnable.getResult(), e); 729 } catch (Exception e) { 730 if (mLogErrors) { 731 CLog.e("Exception occurred when executing runnable"); 732 CLog.e(e); 733 } 734 status = CommandStatus.EXCEPTION; 735 backFillException(mRunnable.getResult(), e); 736 } 737 synchronized (this) { 738 mStatus = status; 739 } 740 } 741 cancel()742 public void cancel() { 743 mRunnable.cancel(); 744 } 745 getStatus()746 synchronized CommandStatus getStatus() { 747 return mStatus; 748 } 749 backFillException(CommandResult result, Exception e)750 private void backFillException(CommandResult result, Exception e) { 751 if (result == null) { 752 return; 753 } 754 if (Strings.isNullOrEmpty(result.getStderr())) { 755 result.setStderr(StreamUtil.getStackTrace(e)); 756 } 757 if (result.getExitCode() == null) { 758 // Set non-zero exit code 759 result.setExitCode(88); 760 } 761 } 762 } 763 764 class RunnableResult implements IRunUtil.IRunnableResult { 765 private final ProcessBuilder mProcessBuilder; 766 private final CommandResult mCommandResult; 767 private final String mInput; 768 private Process mProcess = null; 769 private CountDownLatch mCountDown = null; 770 private Thread mExecutionThread; 771 private OutputStream mStdOut = null; 772 private OutputStream mStdErr = null; 773 private final File mInputRedirect; 774 private final Object mLock = new Object(); 775 private boolean mCancelled = false; 776 private boolean mLogErrors = true; 777 private File mOutputMonitorStdoutFile; 778 private File mOutputMonitorStderrFile; 779 private long mOutputMonitorFileLastSize; 780 private long mOutputMonitorLastChangeTime; 781 RunnableResult(final String input, final ProcessBuilder processBuilder)782 RunnableResult(final String input, final ProcessBuilder processBuilder) { 783 this(input, processBuilder, null, null, null, true); 784 } 785 RunnableResult(final String input, final ProcessBuilder processBuilder, boolean logErrors)786 RunnableResult(final String input, final ProcessBuilder processBuilder, boolean logErrors) { 787 this(input, processBuilder, null, null, null, logErrors); 788 } 789 790 /** 791 * Alternative constructor that allows redirecting the output to any Outputstream. Stdout 792 * and stderr can be independently redirected to different Outputstream implementations. If 793 * streams are null, default behavior of using a buffer will be used. 794 * 795 * <p>Additionally, Stdin can be redirected from a File. 796 */ RunnableResult( final String input, final ProcessBuilder processBuilder, final OutputStream stdoutStream, final OutputStream stderrStream, final File inputRedirect, final boolean logErrors)797 RunnableResult( 798 final String input, 799 final ProcessBuilder processBuilder, 800 final OutputStream stdoutStream, 801 final OutputStream stderrStream, 802 final File inputRedirect, 803 final boolean logErrors) { 804 mProcessBuilder = processBuilder; 805 mInput = input; 806 mLogErrors = logErrors; 807 808 mInputRedirect = inputRedirect; 809 if (mInputRedirect != null) { 810 // Set Stdin to mInputRedirect file. 811 mProcessBuilder.redirectInput(mInputRedirect); 812 } 813 814 mCommandResult = newCommandResult(); 815 mCountDown = new CountDownLatch(1); 816 817 // Redirect IO, so that the outputstream for the spawn process does not fill up 818 // and cause deadlock. 819 mStdOut = stdoutStream; 820 mStdErr = stderrStream; 821 } 822 823 @Override getCommand()824 public List<String> getCommand() { 825 return new ArrayList<>(mProcessBuilder.command()); 826 } 827 828 @Override getResult()829 public CommandResult getResult() { 830 return mCommandResult; 831 } 832 833 /** Start a {@link Process} based on the {@link ProcessBuilder}. */ 834 @VisibleForTesting startProcess()835 Process startProcess() throws IOException { 836 return mProcessBuilder.start(); 837 } 838 839 @Override run()840 public boolean run() throws Exception { 841 File stdoutFile = mProcessBuilder.redirectOutput().file(); 842 File stderrFile = mProcessBuilder.redirectError().file(); 843 boolean temporaryStdout = false; 844 boolean temporaryErrOut = false; 845 Thread stdoutThread = null; 846 Thread stderrThread = null; 847 synchronized (mLock) { 848 if (mCancelled) { 849 // if cancel() was called before run() took the lock, we do not even attempt 850 // to run. 851 return false; 852 } 853 mExecutionThread = Thread.currentThread(); 854 if (stdoutFile == null && mStdOut == null) { 855 temporaryStdout = true; 856 stdoutFile = 857 FileUtil.createTempFile( 858 String.format( 859 "temporary-stdout-%s", 860 mProcessBuilder.command().get(0)), 861 ".txt"); 862 stdoutFile.deleteOnExit(); 863 mProcessBuilder.redirectOutput(Redirect.appendTo(stdoutFile)); 864 } 865 if (stderrFile == null && mStdErr == null) { 866 temporaryErrOut = true; 867 stderrFile = 868 FileUtil.createTempFile( 869 String.format( 870 "temporary-errout-%s", 871 mProcessBuilder.command().get(0)), 872 ".txt"); 873 stderrFile.deleteOnExit(); 874 mProcessBuilder.redirectError(Redirect.appendTo(stderrFile)); 875 } 876 // Obtain a reference to the output stream redirect file for progress monitoring. 877 mOutputMonitorStdoutFile = stdoutFile; 878 mOutputMonitorStderrFile = stderrFile; 879 mOutputMonitorFileLastSize = 0; 880 mOutputMonitorLastChangeTime = 0; 881 try { 882 mProcess = startProcess(); 883 } catch (IOException | RuntimeException e) { 884 if (temporaryStdout) { 885 FileUtil.deleteFile(stdoutFile); 886 } 887 if (temporaryErrOut) { 888 FileUtil.deleteFile(stderrFile); 889 } 890 throw e; 891 } 892 if (mInput != null) { 893 BufferedOutputStream processStdin = 894 new BufferedOutputStream(mProcess.getOutputStream()); 895 processStdin.write(mInput.getBytes("UTF-8")); 896 processStdin.flush(); 897 processStdin.close(); 898 } 899 if (mStdOut != null) { 900 stdoutThread = 901 inheritIO( 902 mProcess.getInputStream(), 903 mStdOut, 904 String.format( 905 "inheritio-stdout-%s", mProcessBuilder.command())); 906 } 907 if (mStdErr != null) { 908 stderrThread = 909 inheritIO( 910 mProcess.getErrorStream(), 911 mStdErr, 912 String.format( 913 "inheritio-stderr-%s", mProcessBuilder.command())); 914 } 915 } 916 // Wait for process to complete. 917 Integer rc = null; 918 try { 919 try { 920 rc = mProcess.waitFor(); 921 // wait for stdout and stderr to be read 922 if (stdoutThread != null) { 923 stdoutThread.join(); 924 } 925 if (stderrThread != null) { 926 stderrThread.join(); 927 } 928 } finally { 929 rc = (rc != null) ? rc : 1; // In case of interruption ReturnCode is null 930 mCommandResult.setExitCode(rc); 931 932 // Write out the streams to the result. 933 if (temporaryStdout) { 934 mCommandResult.setStdout(FileUtil.readStringFromFile(stdoutFile)); 935 } else { 936 final String stdoutDest = 937 stdoutFile != null 938 ? stdoutFile.getAbsolutePath() 939 : mStdOut.getClass().getSimpleName(); 940 mCommandResult.setStdout("redirected to " + stdoutDest); 941 } 942 if (temporaryErrOut) { 943 mCommandResult.setStderr(FileUtil.readStringFromFile(stderrFile)); 944 } else { 945 final String stderrDest = 946 stderrFile != null 947 ? stderrFile.getAbsolutePath() 948 : mStdErr.getClass().getSimpleName(); 949 mCommandResult.setStderr("redirected to " + stderrDest); 950 } 951 } 952 } finally { 953 if (temporaryStdout) { 954 FileUtil.deleteFile(stdoutFile); 955 } 956 if (temporaryErrOut) { 957 FileUtil.deleteFile(stderrFile); 958 } 959 mCountDown.countDown(); 960 } 961 962 if (rc != null && rc == 0) { 963 return true; 964 } else if (mLogErrors) { 965 CLog.d("%s command failed. return code %d", mProcessBuilder.command(), rc); 966 } 967 return false; 968 } 969 970 @Override cancel()971 public void cancel() { 972 if (mCancelled) { 973 return; 974 } 975 mCancelled = true; 976 synchronized (mLock) { 977 if (mProcess == null || !mProcess.isAlive()) { 978 return; 979 } 980 CLog.d("Cancelling the process execution."); 981 if (mLinuxInterruptProcess) { 982 long pid = mProcess.pid(); 983 CommandResult killRes = RunUtil.getDefault().runTimedCmd( 984 60000L, "kill", "-2", "" + pid); 985 CLog.d("status=%s. stdout=%s . stderr=%s", 986 killRes.getStatus(), killRes.getStdout(), killRes.getStderr()); 987 // Just give a little bit of time to terminate. 988 if (mProcess.isAlive()) { 989 RunUtil.getDefault().sleep(1000L); 990 } 991 } 992 // Always destroy to ensure it terminates. 993 mProcess.destroy(); 994 try { 995 // Only allow to continue if the Stdout has been read 996 // RunnableNotifier#Interrupt is the next call and will terminate the thread 997 if (!mCountDown.await(PROCESS_DESTROY_TIMEOUT_SEC, TimeUnit.SECONDS)) { 998 CLog.i("Process still not terminated, interrupting the execution thread"); 999 mExecutionThread.interrupt(); 1000 mCountDown.await(); 1001 } 1002 } catch (InterruptedException e) { 1003 CLog.i("interrupted while waiting for process output to be saved"); 1004 } 1005 } 1006 } 1007 1008 @Override toString()1009 public String toString() { 1010 return "RunnableResult [command=" 1011 + ((mProcessBuilder != null) ? mProcessBuilder.command() : null) 1012 + "]"; 1013 } 1014 1015 /** 1016 * Checks if the currently running operation has made progress since the last check. 1017 * 1018 * @param idleOutputTimeout ms idle with no observed progress before beginning to assume no 1019 * progress is being made. 1020 * @return true if progress has been detected otherwise false. 1021 */ 1022 @Override checkOutputMonitor(Long idleOutputTimeout)1023 public boolean checkOutputMonitor(Long idleOutputTimeout) { 1024 synchronized (mLock) { 1025 // If we don't have what we need to check for progress, abort the check. 1026 if ((mOutputMonitorStdoutFile == null || !mOutputMonitorStdoutFile.exists()) 1027 && (mOutputMonitorStderrFile == null 1028 || !mOutputMonitorStderrFile.exists())) { 1029 // Let the operation timeout on its own. 1030 return true; 1031 } 1032 1033 if (mOutputMonitorLastChangeTime == 0) { 1034 mOutputMonitorLastChangeTime = System.currentTimeMillis(); 1035 // If this is the start of a new command invocation, log only once. 1036 CLog.d( 1037 "checkOutputMonitor activated with idle timeout set for %.2f seconds", 1038 idleOutputTimeout / 1000f); 1039 } 1040 1041 // Observing progress by monitoring the size of the output changing. 1042 long currentFileSize = getMonitoredStdoutSize() + getMonitoredStderrSize(); 1043 long idleTime = System.currentTimeMillis() - mOutputMonitorLastChangeTime; 1044 if (currentFileSize == mOutputMonitorFileLastSize && idleTime > idleOutputTimeout) { 1045 CLog.d( 1046 "checkOutputMonitor: No new progress detected for over %.2f seconds", 1047 idleTime / 1000f); 1048 return false; 1049 } 1050 1051 // Update change time only when new data appears on the streams. 1052 if (currentFileSize != mOutputMonitorFileLastSize) { 1053 mOutputMonitorLastChangeTime = System.currentTimeMillis(); 1054 idleTime = 0; 1055 } 1056 mOutputMonitorFileLastSize = currentFileSize; 1057 } 1058 // Always default to progress being made. 1059 return true; 1060 } 1061 getMonitoredStdoutSize()1062 private long getMonitoredStdoutSize() { 1063 if (mOutputMonitorStdoutFile != null && mOutputMonitorStdoutFile.exists()) { 1064 return mOutputMonitorStdoutFile.length(); 1065 } 1066 return 0; 1067 } 1068 getMonitoredStderrSize()1069 private long getMonitoredStderrSize() { 1070 if (mOutputMonitorStderrFile != null && mOutputMonitorStderrFile.exists()) { 1071 return mOutputMonitorStderrFile.length(); 1072 } 1073 return 0; 1074 } 1075 } 1076 1077 /** 1078 * Helper method to redirect input stream. 1079 * 1080 * @param src {@link InputStream} to inherit/redirect from 1081 * @param dest {@link BufferedOutputStream} to inherit/redirect to 1082 * @param name the name of the thread returned. 1083 * @return a {@link Thread} started that receives the IO. 1084 */ inheritIO(final InputStream src, final OutputStream dest, String name)1085 private static Thread inheritIO(final InputStream src, final OutputStream dest, String name) { 1086 // In case of some Process redirect, source stream can be null. 1087 if (src == null) { 1088 return null; 1089 } 1090 Thread t = 1091 new Thread( 1092 new Runnable() { 1093 @Override 1094 public void run() { 1095 try { 1096 StreamUtil.copyStreams(src, dest); 1097 } catch (IOException e) { 1098 CLog.e("Failed to read input stream %s.", name); 1099 } 1100 } 1101 }); 1102 t.setName(name); 1103 t.start(); 1104 return t; 1105 } 1106 1107 /** {@inheritDoc} */ 1108 @Override setEnvVariablePriority(EnvPriority priority)1109 public void setEnvVariablePriority(EnvPriority priority) { 1110 if (this.equals(sDefaultInstance)) { 1111 throw new UnsupportedOperationException( 1112 "Cannot setEnvVariablePriority on default RunUtil"); 1113 } 1114 mEnvVariablePriority = priority; 1115 } 1116 1117 /** {@inheritDoc} */ 1118 @Override setLinuxInterruptProcess(boolean interrupt)1119 public void setLinuxInterruptProcess(boolean interrupt) { 1120 if (this.equals(sDefaultInstance)) { 1121 throw new UnsupportedOperationException( 1122 "Cannot setLinuxInterruptProcess on default RunUtil"); 1123 } 1124 mLinuxInterruptProcess = interrupt; 1125 } 1126 newCommandResult()1127 private static CommandResult newCommandResult() { 1128 CommandResult commandResult = new CommandResult(); 1129 // Ensure the outputs are never null 1130 commandResult.setStdout(""); 1131 commandResult.setStderr(""); 1132 return commandResult; 1133 } 1134 toRelative(File start, String target)1135 private static String toRelative(File start, String target) { 1136 File targetFile = new File(target); 1137 return targetFile.exists() ? toRelative(start, targetFile) : target; 1138 } 1139 toRelative(File start, File target)1140 private static String toRelative(File start, File target) { 1141 String relPath = start.toPath().relativize(target.toPath()).toString(); 1142 return relPath.length() != 0 ? relPath : "."; 1143 } 1144 pathSeparator()1145 private static String pathSeparator() { 1146 return System.getProperty("path.separator"); 1147 } 1148 } 1149