SONAR-6732 fix ServerTest perf test confused by extra JVM

orchestrator is using the WS /api/server/index which does not wait for the Compute Engine in its own process to actually finish starting
startup time and shutdown time are therefor incorrectly calculated. We now rely on logs to compute them correctly, until the WS is updated

diff --git a/server/sonar-ce/src/main/java/org/sonar/ce/app/CeServer.java b/server/sonar-ce/src/main/java/org/sonar/ce/app/CeServer.java
index 279081366e907056d25deb8effdb5f0b69d61b4c..a09765d1d25241606168766a5e63b00283e04fa8 100644 (file)
--- a/server/sonar-ce/src/main/java/org/sonar/ce/app/CeServer.java
+++ b/server/sonar-ce/src/main/java/org/sonar/ce/app/CeServer.java
@@ -79,7 +79,7 @@ public class CeServer implements Monitored {
   /**
    * Can't be started as is. Needs to be bootstrapped by sonar-application
    */
-  public static void main(String[] args) throws Exception {
+  public static void main(String[] args) {
     ProcessEntryPoint entryPoint = ProcessEntryPoint.createForArguments(args);
     Props props = entryPoint.getProps();
     new ServerProcessLogging(PROCESS_NAME, LOG_LEVEL_PROPERTY).configure(props);
@@ -188,6 +188,7 @@ public class CeServer implements Monitored {
     private void startup() {
       LOG.info("Compute Engine Server starting up...");
       computeEngine.startup();
+      LOG.info("Compute Engine Server is up");
     }
 
     private void waitForStopSignal() {

diff --git a/tests/perf/src/main/java/org/sonarsource/sonarqube/perf/ServerLogs.java b/tests/perf/src/main/java/org/sonarsource/sonarqube/perf/ServerLogs.java
index 7bf905241536a6b7ffcb9c1f0dea204cabdf2d12..bc85ad04ae98c2c9cb4416702b23d4dcbdb216dd 100644 (file)
--- a/tests/perf/src/main/java/org/sonarsource/sonarqube/perf/ServerLogs.java
+++ b/tests/perf/src/main/java/org/sonarsource/sonarqube/perf/ServerLogs.java
@@ -29,7 +29,7 @@ import java.util.List;
 
 public class ServerLogs {
 
-  static Date extractDate(String line) {
+  public static Date extractDate(String line) {
     String pattern = "yyyy.MM.dd HH:mm:ss";
     SimpleDateFormat format = new SimpleDateFormat(pattern);
     if (line.length() > 19) {

diff --git a/tests/perf/src/test/java/org/sonarsource/sonarqube/perf/server/ServerTest.java b/tests/perf/src/test/java/org/sonarsource/sonarqube/perf/server/ServerTest.java
index 36687d52c2d7a33500e2fb2d848c8e1d11258168..2c89409013ef048c6f92072cbb3c8c0b5e38fd89 100644 (file)
--- a/tests/perf/src/test/java/org/sonarsource/sonarqube/perf/server/ServerTest.java
+++ b/tests/perf/src/test/java/org/sonarsource/sonarqube/perf/server/ServerTest.java
@@ -20,16 +20,22 @@
 package org.sonarsource.sonarqube.perf.server;
 
 import com.sonar.orchestrator.Orchestrator;
-import org.sonarsource.sonarqube.perf.PerfTestCase;
-import org.sonarsource.sonarqube.perf.ServerLogs;
 import java.io.IOException;
 import java.util.Collections;
 import java.util.Date;
 import java.util.List;
 import org.apache.commons.io.FileUtils;
+import org.junit.Rule;
 import org.junit.Test;
+import org.junit.rules.Timeout;
+import org.sonarsource.sonarqube.perf.PerfTestCase;
+import org.sonarsource.sonarqube.perf.ServerLogs;
 
 public class ServerTest extends PerfTestCase {
+  private static final int TIMEOUT_3_MINUTES = 1000 * 60 * 3;
+
+  @Rule
+  public Timeout timeout = new Timeout(TIMEOUT_3_MINUTES);
 
   // ES + TOMCAT
   @Test
@@ -46,39 +52,60 @@ public class ServerTest extends PerfTestCase {
       .setServerProperty("sonar.web.javaOpts", defaultWebJavaOptions + " -Djava.security.egd=file:/dev/./urandom")
       .build();
     try {
-      long startupDuration = start(orchestrator);
-      assertDurationAround(startupDuration, 41000);
+      ServerLogs.clear(orchestrator);
+      orchestrator.start();
+
+      // compare dates of first and last log
+      long firstLogDate = ServerLogs.extractFirstDate(readLogLines(orchestrator)).getTime();
+      long startedAtDate = extractStartedAtDate(orchestrator);
+      assertDurationAround(startedAtDate - firstLogDate, 45000);
+
+      ServerLogs.clear(orchestrator);
+      orchestrator.stop();
 
-      long shutdownDuration = stop(orchestrator);
-      // can't use percent margins because logs are second-grained but not milliseconds
-      assertDurationLessThan(shutdownDuration, 4000);
+      List<String> lines = readLogLines(orchestrator);
+      long firstStopLogDate = ServerLogs.extractFirstDate(lines).getTime();
+      long stopDate = extractStopDate(lines);
+      assertDurationLessThan(stopDate - firstStopLogDate, 10000);
 
     } finally {
       orchestrator.stop();
     }
   }
 
-  long start(Orchestrator orchestrator) throws IOException {
-    ServerLogs.clear(orchestrator);
-    orchestrator.start();
-    return logsPeriod(orchestrator);
+  private static long extractStartedAtDate(Orchestrator orchestrator) throws IOException {
+    Date startedAtDate = extractStartedDate(readLogLines(orchestrator));
+    // if SQ never starts, the test will fail with timeout
+    while (startedAtDate == null) {
+      try {
+        Thread.sleep(100);
+        startedAtDate = extractStartedDate(readLogLines(orchestrator));
+      } catch (InterruptedException e) {
+        // ignored
+      }
+    }
+    return startedAtDate.getTime();
   }
 
-  long stop(Orchestrator orchestrator) throws Exception {
-    ServerLogs.clear(orchestrator);
-    orchestrator.stop();
-    return logsPeriod(orchestrator);
+  private static Date extractStartedDate(List<String> lines) {
+    Collections.reverse(lines);
+    Date end = null;
+    for (String line : lines) {
+      if (line.contains("Compute Engine Server is up")) {
+        end = ServerLogs.extractDate(line);
+        break;
+      }
+    }
+    return end;
   }
 
-  private long logsPeriod(Orchestrator orchestrator) throws IOException {
-    // compare dates of first and last log
-    List<String> lines = FileUtils.readLines(orchestrator.getServer().getLogs());
-    if (lines.size() < 2) {
-      throw new IllegalStateException("Fail to estimate server shutdown or startup duration. Not enough logs.");
-    }
-    Date start = ServerLogs.extractFirstDate(lines);
+  private static long extractStopDate(List<String> lines) throws IOException {
     Collections.reverse(lines);
     Date end = ServerLogs.extractFirstDate(lines);
-    return end.getTime() - start.getTime();
+    return end.getTime();
+  }
+
+  private static List<String> readLogLines(Orchestrator orchestrator) throws IOException {
+    return FileUtils.readLines(orchestrator.getServer().getLogs());
   }
 }