buildSrc/src/main/java/cc/squirreljme/plugin/multivm/VMTestWorkAction.java

   1 // -*- Mode: Java; indent-tabs-mode: t; tab-width: 4 -*-
   2 // ---------------------------------------------------------------------------
   3 // SquirrelJME
   4 //     Copyright (C) Stephanie Gawroriski <xer@multiphasicapps.net>
   5 // ---------------------------------------------------------------------------
   6 // SquirrelJME is under the Mozilla Public License Version 2.0.
   7 // See license.mkd for licensing and copyright information.
   8 // ---------------------------------------------------------------------------
   9
  10 package cc.squirreljme.plugin.multivm;
  11
  12 import cc.squirreljme.plugin.util.GradleLoggerOutputStream;
  13 import java.io.IOException;
  14 import java.io.PrintStream;
  15 import java.nio.file.Files;
  16 import java.nio.file.StandardOpenOption;
  17 import java.time.Instant;
  18 import java.time.LocalDateTime;
  19 import java.time.ZoneId;
  20 import java.time.format.DateTimeFormatter;
  21 import java.util.Map;
  22 import java.util.concurrent.ConcurrentHashMap;
  23 import java.util.concurrent.TimeUnit;
  24 import org.gradle.api.logging.LogLevel;
  25 import org.gradle.api.logging.Logger;
  26 import org.gradle.workers.WorkAction;
  27
  28 /**
  29  * This performs the actual work of running the VM tests.
  30  *
  31  * @since 2020/09/07
  32  */
  33 @SuppressWarnings("UnstableApiUsage")
  34 public abstract class VMTestWorkAction
  35         implements WorkAction<VMTestParameters>
  36 {
  37         /** Logger storage. */
  38         static final Map<String, __LogHolder__> _LOGGERS =
  39                 new ConcurrentHashMap<>();
  40
  41         /** The timeout for tests, in nanoseconds. */
  42         public static final long TEST_TIMEOUT =
  43                 360_000_000_000L;
  44
  45         /** Skip sequence special. */
  46         private static final byte[] _SKIP_SPECIAL =
  47                 new byte[]{'%', '!', 'S', 'k', 'O', 'n', 'T', 'i', '!', '%'};
  48
  49         /**
  50          * {@inheritDoc}
  51          * @since 2020/09/07
  52          */
  53         @SuppressWarnings("UseOfProcessBuilder")
  54         @Override
  55         public void execute()
  56         {
  57                 // Determine the name of the test
  58                 VMTestParameters parameters = this.getParameters();
  59                 String testName = parameters.getTestName().get();
  60
  61                 // Get the log holder
  62                 __LogHolder__ logHolder = VMTestWorkAction._LOGGERS.get(
  63                         parameters.getUniqueId().get());
  64                 Logger logger = logHolder.logger;
  65
  66                 // Threads for processing stream data
  67                 Thread stdOutThread = null;
  68                 Thread stdErrThread = null;
  69
  70                 // The current and total test IDs, used to measure progress
  71                 int count = parameters.getCount().get();
  72                 int total = parameters.getTotal().get();
  73
  74                 // If we are debugging, we do not want to kill the test by a timeout
  75                 // if it takes forever because we might be very slow at debugging
  76                 boolean isDebugging = VMTestTaskAction.isDebugging();
  77
  78                 // The process might not be able to execute
  79                 Process process = null;
  80                 try
  81                 {
  82                         // Note this is running
  83                         logger.lifecycle(String.format("???? %s [%d/%d]",
  84                                 testName, count, total));
  85
  86                         // Clock the starting time
  87                         long clockStart = System.currentTimeMillis();
  88                         long nsStart = System.nanoTime();
  89
  90                         // Setup output handler
  91                         ProcessBuilder processBuilder = new ProcessBuilder(
  92                                 parameters.getCommandLine().get().toArray(new String[0]));
  93                         processBuilder.redirectOutput(ProcessBuilder.Redirect.PIPE);
  94                         processBuilder.redirectError(ProcessBuilder.Redirect.PIPE);
  95
  96                         // Start the process with the command line that was pre-determined
  97                         process = processBuilder.start();
  98
  99                         // Setup listening buffer threads
 100                         VMTestOutputBuffer stdOut = new VMTestOutputBuffer(
 101                                 process.getInputStream(), new GradleLoggerOutputStream(logger
 102                                 , LogLevel.LIFECYCLE, count, total),
 103                                 false);
 104                         VMTestOutputBuffer stdErr = new VMTestOutputBuffer(
 105                                 process.getErrorStream(), new GradleLoggerOutputStream(logger
 106                                 , LogLevel.ERROR, count, total),
 107                                 true);
 108
 109                         // Setup threads for reading standard output and standard error
 110                         stdOutThread = new Thread(stdOut, "stdOutReader");
 111                         stdErrThread = new Thread(stdErr, "stdErrReader");
 112
 113                         // Start both threads so console lines can be read as they appear
 114                         stdOutThread.start();
 115                         stdErrThread.start();
 116
 117                         // Wait for the process to terminate, the exit code will contain
 118                         // the result of the test (pass, skip, fail)
 119                         int exitCode = -1;
 120                         boolean timeOutHit = false;
 121                         for (;;)
 122                                 try
 123                                 {
 124                                         // Has the test run expired? Only when not debugging
 125                                         if (!isDebugging)
 126                                         {
 127                                                 long nsDur = System.nanoTime() - nsStart;
 128                                                 if (nsDur >= VMTestWorkAction.TEST_TIMEOUT)
 129                                                 {
 130                                                         // Note it
 131                                                         logger.error(String.format("TIME %s [%d/%d]",
 132                                                                 testName, count, total));
 133
 134                                                         // Set timeout as being hit, used for special
 135                                                         // check
 136                                                         timeOutHit = true;
 137
 138                                                         // The logic for interrupts is the same
 139                                                         throw new InterruptedException("Test Timeout");
 140                                                 }
 141                                         }
 142
 143                                         // Wait for completion
 144                                         if (process.waitFor(3, TimeUnit.SECONDS))
 145                                         {
 146                                                 exitCode = process.waitFor();
 147                                                 break;
 148                                         }
 149                                 }
 150                                 catch (InterruptedException e)
 151                                 {
 152                                         // Add note that this happened
 153                                         logger.error(String.format("INTR %s", testName));
 154
 155                                         // Stop the processes that are running
 156                                         process.destroy();
 157                                         stdOutThread.interrupt();
 158                                         stdErrThread.interrupt();
 159
 160                                         // Stop running the loop
 161                                         break;
 162                                 }
 163
 164                         // Clock the ending time
 165                         long nsDur = System.nanoTime() - nsStart;
 166
 167                         byte[] stdErrBytes = stdErr.getBytes(stdErrThread);
 168                         if (timeOutHit && VMTestWorkAction.__findTimeoutSkip(stdErrBytes))
 169                                 exitCode = VMTestResult.SKIP.exitCode;
 170
 171                         // Note this has finished
 172                         VMTestResult testResult = VMTestResult.valueOf(exitCode);
 173                         logger.lifecycle(String.format("%4s %s [%d/%d]",
 174                                 testResult, testName, count, total));
 175
 176                         // Write the XML file
 177                         try (PrintStream out = new PrintStream(Files.newOutputStream(
 178                                 parameters.getResultFile().get().getAsFile().toPath(),
 179                                 StandardOpenOption.CREATE,
 180                                 StandardOpenOption.TRUNCATE_EXISTING,
 181                                 StandardOpenOption.WRITE)))
 182                         {
 183                                 // Write the resultant XML, this will be read later for
 184                                 // detection purposes
 185                                 VMTestWorkAction.__writeXml(out, testName, testResult,
 186                                         parameters.getVmName().get(), clockStart, nsDur,
 187                                         stdOut.getBytes(stdOutThread),
 188                                         stdErrBytes);
 189
 190                                 // Make sure everything is written
 191                                 out.flush();
 192                         }
 193                 }
 194
 195                 // Process failed to execute
 196                 catch (IOException e)
 197                 {
 198                         throw new RuntimeException("I/O Exception in " + testName, e);
 199                 }
 200
 201                 // Interrupt read/write threads
 202                 finally
 203                 {
 204                         // If our test process is still alive, stop it
 205                         if (process != null)
 206                                 if (process.isAlive())
 207                                         process.destroyForcibly();
 208
 209                         // Stop the standard output thread from running
 210                         if (stdOutThread != null)
 211                                 stdOutThread.interrupt();
 212
 213                         // Stop the standard error thread from running
 214                         if (stdErrThread != null)
 215                                 stdErrThread.interrupt();
 216                 }
 217         }
 218
 219         /**
 220          * Finds the special timeout sequence if this has had a timeout, this is
 221          * used to detect if a test should just skip rather than causing a fail.
 222          *
 223          * @param __stdErrBytes The standard error bytes.
 224          * @return If the sequence was found.
 225          * @throws NullPointerException On null arguments.
 226          * @since 2021/07/18
 227          */
 228         private static boolean __findTimeoutSkip(byte[] __stdErrBytes)
 229                 throws NullPointerException
 230         {
 231                 if (__stdErrBytes == null)
 232                         throw new NullPointerException("NARG");
 233
 234                 // Skip special sequence
 235                 byte[] skipSpecial = VMTestWorkAction._SKIP_SPECIAL;
 236                 byte firstByte = skipSpecial[0];
 237                 int skipLen = skipSpecial.length;
 238
 239                 // Find the sequence
 240                 for (int i = 0, n = Math.max(0, __stdErrBytes.length - skipLen);
 241                         i < n; i++)
 242                 {
 243                         // If the first byte is a match, then
 244                         byte quick = __stdErrBytes[i];
 245                         if (quick != firstByte)
 246                                 continue;
 247
 248                         // Check if the entire sequence matched
 249                         for (int j = 0, q = i; j <= skipLen; j++, q++)
 250                                 if (j == skipLen)
 251                                         return true;
 252                                 else if (__stdErrBytes[q] != skipSpecial[j])
 253                                         break;
 254                 }
 255
 256                 // Not found
 257                 return false;
 258         }
 259
 260         /**
 261          * Writes the XML test result to the given output.
 262          *
 263          * @param __out The stream to write the XML to.
 264          * @param __testName The name of the test.
 265          * @param __result The result of the test.
 266          * @param __vmName The virtual machine name.
 267          * @param __clockStart The starting time of the test.
 268          * @param __nsDur The duration of the test in nanoseconds.
 269          * @param __stdOut Standard output.
 270          * @param __stdErr Standard error.
 271          * @throws NullPointerException On null arguments.
 272          * @since 2020/09/07
 273          */
 274         @SuppressWarnings("resource")
 275         private static void __writeXml(PrintStream __out, String __testName,
 276                 VMTestResult __result, String __vmName, long __clockStart,
 277                 long __nsDur, byte[] __stdOut, byte[] __stdErr)
 278                 throws NullPointerException
 279         {
 280                 if (__out == null || __testName == null || __result == null ||
 281                         __stdOut == null || __stdErr == null || __vmName == null)
 282                         throw new NullPointerException("NARG");
 283
 284                 // Write the XML header
 285                 __out.println("<?xml version=\"1.0\" encoding=\"UTF-8\"?>");
 286
 287                 // Determine the counts for the test
 288                 int numTests = 1;
 289                 int numSkipped = (__result == VMTestResult.SKIP ? 1 : 0);
 290                 int numFailed = (__result == VMTestResult.FAIL ? 1 : 0);
 291
 292                 // The current timestamp
 293                 String nowTimestamp = DateTimeFormatter.ISO_LOCAL_DATE_TIME.format(
 294                         LocalDateTime.ofInstant(Instant.ofEpochMilli(__clockStart),
 295                                 ZoneId.systemDefault()));
 296
 297                 // Duration in seconds
 298                 double durationSeconds = __nsDur / 1_000_000_000D;
 299
 300                 // Open test suite
 301                 __out.printf("<testsuite name=\"%s\" tests=\"%d\" " +
 302                         "skipped=\"%d\" failures=\"%d\" errors=\"%d\" " +
 303                         "timestamp=\"%s\" hostname=\"%s\" time=\"%.3f\" " +
 304                         ">",
 305                         __testName, numTests, numSkipped, numFailed, numFailed,
 306                         nowTimestamp, __vmName, durationSeconds);
 307                 __out.println();
 308
 309                 // Begin properties
 310                 __out.println("<properties>");
 311
 312                 // A special property is used for a quick search to determine if there
 313                 // is a pass, skip, or fail as the test result needs to be read to
 314                 // determine if the task is okay
 315                 __out.printf("<property name=\"squirreljme.test.result\" " +
 316                         "value=\"%s:result:%s:\" />", VMTestTaskAction._SPECIAL_KEY,
 317                         __result.name());
 318                 __out.println();
 319
 320                 // Also
 321                 __out.printf("<property name=\"squirreljme.test.nanoseconds\" " +
 322                         "value=\"%s:nanoseconds:%s:\" />", VMTestTaskAction._SPECIAL_KEY,
 323                         __nsDur);
 324                 __out.println();
 325
 326                 // End properties
 327                 __out.println("</properties>");
 328
 329                 // Begin test case
 330                 __out.printf("<testcase name=\"%s\" classname=\"%s\" " +
 331                         "time=\"%.3f\">",
 332                         __testName, __testName, durationSeconds);
 333                 __out.println();
 334
 335                 // Failed tests use this tag accordingly, despite there being a
 336                 // failures indicator
 337                 if (__result == VMTestResult.FAIL)
 338                 {
 339                         __out.printf("<failure type=\"%s\">", __testName);
 340                         VMTestWorkAction.__writeText(__out, __stdErr);
 341                         __out.println("</failure>");
 342                 }
 343
 344                 // Write both buffers
 345                 VMTestWorkAction.__writeTextTag(__out, "system-out", __stdOut);
 346                 VMTestWorkAction.__writeTextTag(__out, "system-err", __stdErr);
 347
 348                 // End test case
 349                 __out.println("</testcase>");
 350
 351                 // Close test suite
 352                 __out.println("</testsuite>");
 353         }
 354
 355         /**
 356          * Writes the given XML Text.
 357          *
 358          * @param __out The target stream.
 359          * @param __text The text to write.
 360          * @throws NullPointerException On null arguments.
 361          * @since 2020/10/12
 362          */
 363         private static void __writeText(PrintStream __out, byte[] __text)
 364                 throws NullPointerException
 365         {
 366                 if (__out == null || __text == null)
 367                         throw new NullPointerException("NARG");
 368
 369                 __out.print("<![CDATA[");
 370                 __out.print(new String(__text));
 371                 __out.print("]]>");
 372         }
 373
 374         /**
 375          * Writes raw buffer text to the output.
 376          *
 377          * @param __out The stream to write to.
 378          * @param __key The tag key.
 379          * @param __text The bytes for the key.
 380          * @throws NullPointerException On null arguments.
 381          * @since 2020/09/07
 382          */
 383         @SuppressWarnings("resource")
 384         private static void __writeTextTag(PrintStream __out, String __key,
 385                 byte[] __text)
 386                 throws NullPointerException
 387         {
 388                 if (__out == null || __key == null || __text == null)
 389                         throw new NullPointerException("NARG");
 390
 391                 // Write tag into here
 392                 __out.printf("<%s>", __key);
 393                 VMTestWorkAction.__writeText(__out, __text);
 394                 __out.printf("</%s>", __key);
 395                 __out.println();
 396         }
 397 }