Add more RemoteBuilder tests. Fix related to remote builder bugs (#977)

Author: ekharkunov

server/src/main/java/com/defold/extender/remote/RemoteEngineBuilder.java

@@ -58,6 +58,7 @@
 import java.nio.file.StandardCopyOption;
 import java.util.Optional;
 import java.util.concurrent.TimeUnit;
+import java.util.stream.Stream;
 import java.util.zip.ZipEntry;
 import java.util.zip.ZipOutputStream;
 import java.nio.charset.Charset;
@@ -67,6 +68,7 @@ public class RemoteEngineBuilder {
 
     private static final Logger LOGGER = LoggerFactory.getLogger(RemoteEngineBuilder.class);
     private static final String RECONNECT_METRIC_ID = "extender.service.remoteBuilder.reconnect";
+    private static final int MAX_ERROR_BODY_LENGTH = 200;
 
     private GCPInstanceService instanceService;
     private final MeterRegistry meterRegistry;
@@ -141,6 +143,12 @@ private void countReconnect(HttpHost builderHost, String operation) {
             "operation", operation);
     }
 
+    // Remote builders can return a large HTML error page as a job_status body; cap what we echo
+    // into error.txt so a runaway body never bloats the file the client downloads.
+    private static String truncate(String body) {
+        return body.length() <= MAX_ERROR_BODY_LENGTH ? body : body.substring(0, MAX_ERROR_BODY_LENGTH) + "...";
+    }
+
     private static String requestOperation(HttpRequest request) {
         try {
             // request paths are /build_async/<platform>/<sdk>, /job_status, /job_result
@@ -207,7 +215,26 @@ public void buildAsync(final RemoteInstanceConfig remoteInstanceConfig,
                     touchInstance(remoteInstanceConfig.getInstanceId());
                     HttpGet statusRequest = new HttpGet(String.format("%s/job_status?jobId=%s", remoteInstanceConfig.getUrl(), jobId));
                     try (CloseableHttpResponse statusResponse = httpClient.execute(statusRequest)) {
-                        jobStatus = Integer.valueOf(EntityUtils.toString(statusResponse.getEntity()));
+                        int statusCode = statusResponse.getStatusLine().getStatusCode();
+                        if (statusCode != HttpStatus.SC_OK) {
+                            LOGGER.error(Markers.SERVER_ERROR, "Remote builder returned HTTP {} for job_status of job {}", statusCode, jobId);
+                            File errorFile = new File(resultDir, BuilderConstants.BUILD_ERROR_FILENAME);
+                            try (PrintWriter writer = new PrintWriter(errorFile)) {
+                                writer.write(String.format("Remote builder returned HTTP %d for job_status of job %s", statusCode, jobId));
+                            }
+                            return;
+                        }
+                        String jobStatusBody = EntityUtils.toString(statusResponse.getEntity());
+                        try {
+                            jobStatus = Integer.valueOf(jobStatusBody.trim());
+                        } catch (NumberFormatException exc) {
+                            LOGGER.error(Markers.SERVER_ERROR, "Remote builder returned malformed job_status '{}' for job {}", truncate(jobStatusBody), jobId);
+                            File errorFile = new File(resultDir, BuilderConstants.BUILD_ERROR_FILENAME);
+                            try (PrintWriter writer = new PrintWriter(errorFile)) {
+                                writer.write(String.format("Remote builder returned malformed job_status '%s' for job %s", truncate(jobStatusBody), jobId));
+                            }
+                            return;
+                        }
                     }
                     if (jobStatus != 0) {
                         LOGGER.info(String.format("Job %s status is %d", jobId, jobStatus));
@@ -255,6 +282,17 @@ private void downloadResult(final RemoteInstanceConfig remoteInstanceConfig, Str
         for (int attempt = 0; ; ++attempt) {
             touchInstance(remoteInstanceConfig.getInstanceId());
             try (CloseableHttpResponse resultResponse = httpClient.execute(new HttpGet(resultUrl))) {
+                int resultStatusCode = resultResponse.getStatusLine().getStatusCode();
+                if (resultStatusCode != HttpStatus.SC_OK) {
+                    // A completed HTTP error (not a mid-download IOException) is a definitive builder
+                    // fault, so don't retry it and never copy its body into build.zip.
+                    LOGGER.error(Markers.SERVER_ERROR, "Remote builder returned HTTP {} for job_result of job {}", resultStatusCode, jobId);
+                    File errorFile = new File(resultDir, BuilderConstants.BUILD_ERROR_FILENAME);
+                    try (PrintWriter writer = new PrintWriter(errorFile)) {
+                        writer.write(String.format("Remote builder returned HTTP %d for job_result of job %s", resultStatusCode, jobId));
+                    }
+                    return;
+                }
                 if (jobStatus == BuilderConstants.JobStatus.SUCCESS.ordinal()) {
                     // Write zip file to result directory
                     File tmpResult = new File(resultDir, BuilderConstants.BUILD_RESULT_FILENAME + ".tmp");
@@ -287,9 +325,11 @@ HttpEntity buildHttpEntity(final File projectDirectory, File tmpUploadArchive) t
         MultipartEntityBuilder entityBuilder = MultipartEntityBuilder.create();
         entityBuilder.setStrictMode();
 
-        try (OutputStream fileOut = Files.newOutputStream(tmpUploadArchive.toPath()); ZipOutputStream zipStream = new ZipOutputStream(fileOut)) {
-            Path projectDirectoryPath = projectDirectory.toPath();
-            Files.walk(projectDirectoryPath)
+        Path projectDirectoryPath = projectDirectory.toPath();
+        try (OutputStream fileOut = Files.newOutputStream(tmpUploadArchive.toPath());
+             ZipOutputStream zipStream = new ZipOutputStream(fileOut);
+             Stream<Path> projectFiles = Files.walk(projectDirectoryPath)) {
+            projectFiles
                 .filter(Files::isRegularFile)
                 .filter(path -> !path.getFileName().toString().equals(ExtenderConst.SOURCE_CODE_ARCHIVE_MAGIC_NAME))
                 .filter(path -> !path.getFileName().toString().equals(DataCacheService.FILE_CACHE_INFO_FILE))

server/src/test/java/com/defold/extender/TimerTest.java

@@ -0,0 +1,50 @@
+package com.defold.extender;
+
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import org.junit.jupiter.api.Test;
+
+public class TimerTest {
+
+    @Test
+    public void startReturnsTheElapsedTimeSinceTheLastCall() throws InterruptedException {
+        Timer timer = new Timer();
+        timer.start();
+
+        Thread.sleep(100);
+        long lap = timer.start();
+
+        // Deliberately loose: Thread.sleep only guarantees a lower bound, and clock granularity
+        // on Windows is ~15ms.
+        assertTrue(lap >= 90, String.format("Expected a lap of at least 90ms, got %d", lap));
+    }
+
+    @Test
+    public void startResetsTheBaselineSoLapsDoNotAccumulate() throws InterruptedException {
+        Timer timer = new Timer();
+        timer.start();
+
+        Thread.sleep(100);
+        long firstLap = timer.start();
+        long secondLap = timer.start();
+
+        assertTrue(firstLap >= 90, String.format("Expected a first lap of at least 90ms, got %d", firstLap));
+        // Without the reset inside start(), the second lap would still measure from the original
+        // baseline and come back >= 100ms. This is the mechanism that made calling
+        // measureRemoteEngineBuild(buildTimer.start(), ...) twice halve the reported build time.
+        assertTrue(secondLap < 90, String.format("Expected the baseline to reset, but the second lap was %d", secondLap));
+    }
+
+    @Test
+    public void theFirstCallOnAnUnprimedTimerReturnsMillisSinceEpoch() {
+        long before = System.currentTimeMillis();
+        long firstLap = new Timer().start();
+        long after = System.currentTimeMillis();
+
+        // The baseline starts at 0, so an unprimed Timer reports wall-clock epoch millis rather than
+        // a duration. That is why MetricsWriter's constructor and buildAsync both prime the timer
+        // before measuring anything.
+        assertTrue(firstLap >= before && firstLap <= after,
+                String.format("Expected epoch millis in [%d, %d], got %d", before, after, firstLap));
+    }
+}

server/src/test/java/com/defold/extender/metrics/MetricsWriterTest.java

@@ -0,0 +1,98 @@
+package com.defold.extender.metrics;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import java.util.concurrent.TimeUnit;
+
+import org.junit.jupiter.api.Test;
+
+import io.micrometer.core.instrument.Timer;
+import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
+
+public class MetricsWriterTest {
+
+    private static final String REMOTE_BUILD = "extender.job.remoteBuild";
+    private static final String PLATFORM = "x86_64-osx";
+
+    private static Timer remoteBuildTimer(SimpleMeterRegistry registry, String platform) {
+        return registry.timer(REMOTE_BUILD, "platform", platform);
+    }
+
+    @Test
+    public void measureRemoteEngineBuildRecordsTheGivenDurationUnderThePlatformTag() {
+        SimpleMeterRegistry registry = new SimpleMeterRegistry();
+
+        new MetricsWriter(registry).measureRemoteEngineBuild(1234L, PLATFORM);
+
+        Timer timer = remoteBuildTimer(registry, PLATFORM);
+        assertEquals(1, timer.count());
+        assertEquals(1234.0, timer.totalTime(TimeUnit.MILLISECONDS), 0.001);
+    }
+
+    @Test
+    public void everyCallToMeasureRemoteEngineBuildRecordsOneMoreSample() {
+        SimpleMeterRegistry registry = new SimpleMeterRegistry();
+        MetricsWriter writer = new MetricsWriter(registry);
+
+        writer.measureRemoteEngineBuild(300L, PLATFORM);
+        writer.measureRemoteEngineBuild(100L, PLATFORM);
+
+        // buildAsync used to call this once at the end of the try block and again in the finally
+        // block. Because Timer.start() resets, the second sample was ~0ms: the count doubled and the
+        // reported mean halved. This pins the contract that RemoteEngineBuilderTest's
+        // verify(metrics, times(1)) relies on.
+        Timer timer = remoteBuildTimer(registry, PLATFORM);
+        assertEquals(2, timer.count());
+        assertEquals(400.0, timer.totalTime(TimeUnit.MILLISECONDS), 0.001);
+        assertEquals(200.0, timer.mean(TimeUnit.MILLISECONDS), 0.001);
+    }
+
+    @Test
+    public void samplesForDifferentPlatformsAreRecordedSeparately() {
+        SimpleMeterRegistry registry = new SimpleMeterRegistry();
+        MetricsWriter writer = new MetricsWriter(registry);
+
+        writer.measureRemoteEngineBuild(1000L, PLATFORM);
+        writer.measureRemoteEngineBuild(2000L, "arm64-ios");
+
+        assertEquals(1, remoteBuildTimer(registry, PLATFORM).count());
+        assertEquals(1000.0, remoteBuildTimer(registry, PLATFORM).totalTime(TimeUnit.MILLISECONDS), 0.001);
+        assertEquals(1, remoteBuildTimer(registry, "arm64-ios").count());
+        assertEquals(2000.0, remoteBuildTimer(registry, "arm64-ios").totalTime(TimeUnit.MILLISECONDS), 0.001);
+    }
+
+    @Test
+    public void theNoDurationOverloadRecordsExactlyOneSampleFromTheInternalTimer() {
+        SimpleMeterRegistry registry = new SimpleMeterRegistry();
+
+        new MetricsWriter(registry).measureRemoteEngineBuild(PLATFORM);
+
+        assertEquals(1, remoteBuildTimer(registry, PLATFORM).count());
+    }
+
+    @Test
+    public void theConstructorPrimesTheInternalTimerSoTheFirstSampleIsNotEpochMillis() {
+        SimpleMeterRegistry registry = new SimpleMeterRegistry();
+        MetricsWriter writer = new MetricsWriter(registry);
+
+        writer.measureRemoteEngineBuild(PLATFORM);
+
+        // An unprimed com.defold.extender.Timer returns System.currentTimeMillis() on its first
+        // start(). Were the constructor not to prime it, this would record ~1.7e12 milliseconds.
+        double totalMillis = remoteBuildTimer(registry, PLATFORM).totalTime(TimeUnit.MILLISECONDS);
+        assertTrue(totalMillis < 60_000,
+                String.format("Expected a sane duration, got %f ms", totalMillis));
+    }
+
+    @Test
+    public void measureEngineBuildAndMeasureRemoteEngineBuildUseDistinctMeters() {
+        SimpleMeterRegistry registry = new SimpleMeterRegistry();
+        MetricsWriter writer = new MetricsWriter(registry);
+
+        writer.measureRemoteEngineBuild(500L, PLATFORM);
+
+        assertEquals(1, remoteBuildTimer(registry, PLATFORM).count());
+        assertEquals(0, registry.timer("extender.job.build", "platform", PLATFORM).count());
+    }
+}

server/src/test/java/com/defold/extender/remote/RemoteBuildExceptionTest.java

@@ -0,0 +1,46 @@
+package com.defold.extender.remote;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertNull;
+import static org.junit.jupiter.api.Assertions.assertSame;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import java.io.IOException;
+
+import org.junit.jupiter.api.Test;
+
+import com.defold.extender.ExtenderException;
+
+public class RemoteBuildExceptionTest {
+
+    @Test
+    public void theMessageOnlyConstructorLeavesTheCauseUnset() {
+        RemoteBuildException exception = new RemoteBuildException("Failed to add files to multipart request");
+
+        assertEquals("Failed to add files to multipart request", exception.getMessage());
+        assertNull(exception.getCause());
+    }
+
+    @Test
+    public void theCauseIsPreservedSoTheUnderlyingIoFailureStaysDiagnosable() {
+        ExtenderException cause = new ExtenderException("Failed to create source code archive");
+        RemoteBuildException exception = new RemoteBuildException("Failed to add files to multipart request", cause);
+
+        assertEquals("Failed to add files to multipart request", exception.getMessage());
+        assertSame(cause, exception.getCause());
+    }
+
+    @Test
+    public void itIsUncheckedSoBuildAsyncCanThrowItWithoutDeclaringIt() {
+        // buildAsync only declares FileNotFoundException and IOException. If RemoteBuildException
+        // ever became checked, the multipart failure path would stop compiling.
+        assertTrue(RuntimeException.class.isAssignableFrom(RemoteBuildException.class));
+    }
+
+    @Test
+    public void aCheckedCauseIsAcceptedByTheTwoArgumentConstructor() {
+        IOException cause = new IOException("disk full");
+
+        assertSame(cause, new RemoteBuildException("Failed to add files to multipart request", cause).getCause());
+    }
+}