Don't close stderr under --quiet (elastic#47208)

Closes elastic#46900. When running ES with `--quiet`, if ES then exits abnormally, a user has to go hunting in the logs for the error. Instead, never close System.err, and print more information to it if ES encounters a fatal error e.g. config validation, or some fatal runtime exception. This is useful when running under e.g. systemd, since the error will go into the journal. Note that stderr is still closed in daemon (`-d`) mode.
pugnascotia · Nov 21, 2019 · fe1dbd4 · fe1dbd4
1 parent 010c3de
commit fe1dbd4
Show file tree

Hide file tree

Showing 8 changed files with 156 additions and 68 deletions.
diff --git a/libs/cli/src/main/java/org/elasticsearch/cli/Terminal.java b/libs/cli/src/main/java/org/elasticsearch/cli/Terminal.java
@@ -151,6 +151,11 @@ public final boolean promptYesNo(String prompt, boolean defaultYes) {
         }
     }
 
+    public void flush() {
+        this.getWriter().flush();
+        this.getErrorWriter().flush();
+    }
+
     private static class ConsoleTerminal extends Terminal {
 
         private static final Console CONSOLE = System.console();

diff --git a/qa/os/src/test/java/org/elasticsearch/packaging/test/PackageTests.java b/qa/os/src/test/java/org/elasticsearch/packaging/test/PackageTests.java
@@ -23,7 +23,6 @@
 import org.apache.http.client.fluent.Request;
 import org.elasticsearch.packaging.util.FileUtils;
 import org.elasticsearch.packaging.util.Shell.Result;
-import org.hamcrest.CoreMatchers;
 import org.junit.BeforeClass;
 
 import java.nio.charset.StandardCharsets;
@@ -47,10 +46,12 @@
 import static org.elasticsearch.packaging.util.Packages.SYSTEMD_SERVICE;
 import static org.elasticsearch.packaging.util.Packages.assertInstalled;
 import static org.elasticsearch.packaging.util.Packages.assertRemoved;
+import static org.elasticsearch.packaging.util.Packages.clearJournal;
 import static org.elasticsearch.packaging.util.Packages.installPackage;
 import static org.elasticsearch.packaging.util.Packages.remove;
 import static org.elasticsearch.packaging.util.Packages.restartElasticsearch;
 import static org.elasticsearch.packaging.util.Packages.startElasticsearch;
+import static org.elasticsearch.packaging.util.Packages.startElasticsearchIgnoringFailure;
 import static org.elasticsearch.packaging.util.Packages.stopElasticsearch;
 import static org.elasticsearch.packaging.util.Packages.verifyPackageInstallation;
 import static org.elasticsearch.packaging.util.Platforms.getOsRelease;
@@ -60,7 +61,7 @@
 import static org.hamcrest.CoreMatchers.equalTo;
 import static org.hamcrest.CoreMatchers.not;
 import static org.hamcrest.Matchers.containsString;
-import static org.hamcrest.Matchers.isEmptyString;
+import static org.hamcrest.Matchers.emptyString;
 import static org.hamcrest.core.Is.is;
 import static org.junit.Assume.assumeThat;
 import static org.junit.Assume.assumeTrue;
@@ -79,8 +80,8 @@ public void test10InstallPackage() throws Exception {
         verifyPackageInstallation(installation, distribution(), sh);
     }
 
-    public void test20PluginsCommandWhenNoPlugins() throws Exception {
-        assertThat(sh.run(installation.bin("elasticsearch-plugin") + " list").stdout, isEmptyString());
+    public void test20PluginsCommandWhenNoPlugins() {
+        assertThat(sh.run(installation.bin("elasticsearch-plugin") + " list").stdout, is(emptyString()));
     }
 
     public void test30DaemonIsNotEnabledOnRestart() {
@@ -95,7 +96,7 @@ public void test31InstallDoesNotStartServer() {
         assertThat(sh.run("ps aux").stdout, not(containsString("org.elasticsearch.bootstrap.Elasticsearch")));
     }
 
-    public void assertRunsWithJavaHome() throws Exception {
+    private void assertRunsWithJavaHome() throws Exception {
         byte[] originalEnvFile = Files.readAllBytes(installation.envFile);
         try {
             Files.write(installation.envFile, ("JAVA_HOME=" + systemJavaHome + "\n").getBytes(StandardCharsets.UTF_8),
@@ -287,53 +288,17 @@ public void test80DeletePID_DIRandRestart() throws Exception {
     }
 
     public void test81CustomPathConfAndJvmOptions() throws Exception {
-        assumeTrue(isSystemd());
-
-        assertPathsExist(installation.envFile);
-
-        stopElasticsearch(sh);
-
-        // The custom config directory is not under /tmp or /var/tmp because
-        // systemd's private temp directory functionally means different
-        // processes can have different views of what's in these directories
-        String randomName = RandomStrings.randomAsciiAlphanumOfLength(getRandom(), 10);
-        sh.run("mkdir /etc/"+randomName);
-        final Path tempConf = Paths.get("/etc/"+randomName);
-
-        try {
-            mkdir(tempConf);
-            cp(installation.config("elasticsearch.yml"), tempConf.resolve("elasticsearch.yml"));
-            cp(installation.config("log4j2.properties"), tempConf.resolve("log4j2.properties"));
-
-            // we have to disable Log4j from using JMX lest it will hit a security
-            // manager exception before we have configured logging; this will fail
-            // startup since we detect usages of logging before it is configured
-            final String jvmOptions =
-                "-Xms512m\n" +
-                    "-Xmx512m\n" +
-                    "-Dlog4j2.disable.jmx=true\n";
-            append(tempConf.resolve("jvm.options"), jvmOptions);
-
-            sh.runIgnoreExitCode("chown -R elasticsearch:elasticsearch " + tempConf);
-
-            cp(installation.envFile, tempConf.resolve("elasticsearch.bk"));//backup
-            append(installation.envFile, "ES_PATH_CONF=" + tempConf + "\n");
+        withCustomConfig(tempConf -> {
             append(installation.envFile, "ES_JAVA_OPTS=-XX:-UseCompressedOops");
 
             startElasticsearch(sh, installation);
 
             final String nodesResponse = makeRequest(Request.Get("http://localhost:9200/_nodes"));
-            assertThat(nodesResponse, CoreMatchers.containsString("\"heap_init_in_bytes\":536870912"));
-            assertThat(nodesResponse, CoreMatchers.containsString("\"using_compressed_ordinary_object_pointers\":\"false\""));
+            assertThat(nodesResponse, containsString("\"heap_init_in_bytes\":536870912"));
+            assertThat(nodesResponse, containsString("\"using_compressed_ordinary_object_pointers\":\"false\""));
 
             stopElasticsearch(sh);
-
-        } finally {
-            rm(installation.envFile);
-            cp(tempConf.resolve("elasticsearch.bk"), installation.envFile);
-            rm(tempConf);
-            cleanup();
-        }
+        });
     }
 
     public void test82SystemdMask() throws Exception {
@@ -375,4 +340,63 @@ public void test83serviceFileSetsLimits() throws Exception {
 
         stopElasticsearch(sh);
     }
+
+    public void test90DoNotCloseStderrWhenQuiet() throws Exception {
+        withCustomConfig(tempConf -> {
+            // Create a startup problem by adding an invalid YAML line to the config
+            append(tempConf.resolve("elasticsearch.yml"), "discovery.zen.ping.unicast.hosts:15172.30.5.3416172.30.5.35, 172.30.5.17]\n");
+
+            // Make sure we don't pick up the journal entries for previous ES instances.
+            clearJournal(sh);
+            startElasticsearchIgnoringFailure(sh);
+
+            final Result logs = sh.run("journalctl -u elasticsearch.service");
+
+            assertThat(logs.stdout, containsString("Failed to load settings from [elasticsearch.yml]"));
+        });
+    }
+
+    @FunctionalInterface
+    private interface CustomConfigConsumer {
+        void accept(Path path) throws Exception;
+    }
+
+    private void withCustomConfig(CustomConfigConsumer pathConsumer) throws Exception {
+        assumeTrue(isSystemd());
+
+        assertPathsExist(installation.envFile);
+
+        stopElasticsearch(sh);
+
+        // The custom config directory is not under /tmp or /var/tmp because
+        // systemd's private temp directory functionally means different
+        // processes can have different views of what's in these directories
+        String randomName = RandomStrings.randomAsciiAlphanumOfLength(getRandom(), 10);
+        sh.run("mkdir /etc/" + randomName);
+        final Path tempConf = Paths.get("/etc/" + randomName);
+
+        try {
+            mkdir(tempConf);
+            cp(installation.config("elasticsearch.yml"), tempConf.resolve("elasticsearch.yml"));
+            cp(installation.config("log4j2.properties"), tempConf.resolve("log4j2.properties"));
+
+            // we have to disable Log4j from using JMX lest it will hit a security
+            // manager exception before we have configured logging; this will fail
+            // startup since we detect usages of logging before it is configured
+            final String jvmOptions = "-Xms512m\n-Xmx512m\n-Dlog4j2.disable.jmx=true\n";
+            append(tempConf.resolve("jvm.options"), jvmOptions);
+
+            sh.runIgnoreExitCode("chown -R elasticsearch:elasticsearch " + tempConf);
+
+            cp(installation.envFile, tempConf.resolve("elasticsearch.bk"));// backup
+            append(installation.envFile, "ES_PATH_CONF=" + tempConf + "\n");
+
+            pathConsumer.accept(tempConf);
+        } finally {
+            rm(installation.envFile);
+            cp(tempConf.resolve("elasticsearch.bk"), installation.envFile);
+            rm(tempConf);
+            cleanup();
+        }
+    }
 }
diff --git a/qa/os/src/test/java/org/elasticsearch/packaging/util/Docker.java b/qa/os/src/test/java/org/elasticsearch/packaging/util/Docker.java
@@ -21,6 +21,7 @@
 
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
+import org.elasticsearch.common.CheckedRunnable;
 
 import java.nio.file.Path;
 import java.nio.file.attribute.PosixFilePermission;
@@ -409,7 +410,7 @@ public static void waitForElasticsearch(String status, String index, Installatio
         withLogging(() -> ServerUtils.waitForElasticsearch(status, index, installation, username, password));
     }
 
-    private static void withLogging(ThrowingRunnable r) throws Exception {
+    private static <E extends Exception> void withLogging(CheckedRunnable<E> r) throws Exception {
         try {
             r.run();
         } catch (Exception e) {
@@ -418,8 +419,4 @@ private static void withLogging(ThrowingRunnable r) throws Exception {
             throw e;
         }
     }
-
-    private interface ThrowingRunnable {
-        void run() throws Exception;
-    }
 }
diff --git a/qa/os/src/test/java/org/elasticsearch/packaging/util/Packages.java b/qa/os/src/test/java/org/elasticsearch/packaging/util/Packages.java
@@ -52,7 +52,7 @@
 
 public class Packages {
 
-    protected static final Logger logger =  LogManager.getLogger(Packages.class);
+    private static final Logger logger =  LogManager.getLogger(Packages.class);
 
     public static final Path SYSVINIT_SCRIPT = Paths.get("/etc/init.d/elasticsearch");
     public static final Path SYSTEMD_SERVICE = Paths.get("/usr/lib/systemd/system/elasticsearch.service");
@@ -114,7 +114,7 @@ public static Installation installPackage(Distribution distribution) throws IOEx
         return installation;
     }
 
-    public static Result runInstallCommand(Distribution distribution, Shell sh) {
+    private static Result runInstallCommand(Distribution distribution, Shell sh) {
         final Path distributionFile = distribution.path;
 
         if (Platforms.isRPM()) {
@@ -281,7 +281,33 @@ public static void startElasticsearch(Shell sh, Installation installation) throw
         assertElasticsearchStarted(sh, installation);
     }
 
-    public static void assertElasticsearchStarted(Shell sh, Installation installation) throws IOException {
+    /**
+     * Starts Elasticsearch, without checking that startup is successful. To also check
+     * that Elasticsearch has started, call {@link #startElasticsearch(Shell, Installation)}.
+     */
+    public static void startElasticsearchIgnoringFailure(Shell sh) {
+        if (isSystemd()) {
+            sh.runIgnoreExitCode("systemctl daemon-reload");
+            sh.runIgnoreExitCode("systemctl enable elasticsearch.service");
+            sh.runIgnoreExitCode("systemctl is-enabled elasticsearch.service");
+            sh.runIgnoreExitCode("systemctl start elasticsearch.service");
+        } else {
+            sh.runIgnoreExitCode("service elasticsearch start");
+        }
+    }
+
+    /**
+     * Clears the systemd journal. This is intended to clear the <code>journalctl</code> output
+     * before a test that checks the journal output.
+     */
+    public static void clearJournal(Shell sh) {
+        if (isSystemd()) {
+            sh.run("rm -rf /run/log/journal/");
+            sh.run("systemctl restart systemd-journald");
+        }
+    }
+
+    private static void assertElasticsearchStarted(Shell sh, Installation installation) throws IOException {
         waitForElasticsearch(installation);
 
         if (isSystemd()) {
@@ -292,7 +318,7 @@ public static void assertElasticsearchStarted(Shell sh, Installation installatio
         }
     }
 
-    public static void stopElasticsearch(Shell sh) throws IOException {
+    public static void stopElasticsearch(Shell sh) {
         if (isSystemd()) {
             sh.run("systemctl stop elasticsearch.service");
         } else {

diff --git a/server/src/main/java/org/elasticsearch/bootstrap/Bootstrap.java b/server/src/main/java/org/elasticsearch/bootstrap/Bootstrap.java
@@ -357,7 +357,12 @@ static void init(
 
             INSTANCE.start();
 
-            if (closeStandardStreams) {
+            // We don't close stderr if `--quiet` is passed, because that
+            // hides fatal startup errors. For example, if Elasticsearch is
+            // running via systemd, the init script only specifies
+            // `--quiet`, not `-d`, so we want users to be able to see
+            // startup errors via journalctl.
+            if (foreground == false) {
                 closeSysError();
             }
         } catch (NodeValidationException | RuntimeException e) {

diff --git a/server/src/main/java/org/elasticsearch/bootstrap/Elasticsearch.java b/server/src/main/java/org/elasticsearch/bootstrap/Elasticsearch.java
@@ -91,6 +91,17 @@ public void checkPermission(Permission perm) {
         final Elasticsearch elasticsearch = new Elasticsearch();
         int status = main(args, elasticsearch, Terminal.DEFAULT);
         if (status != ExitCodes.OK) {
+            final String basePath = System.getProperty("es.logs.base_path");
+            // It's possible to fail before logging has been configured, in which case there's no point
+            // suggesting that the user look in the log file.
+            if (basePath != null) {
+                Terminal.DEFAULT.errorPrintln(
+                    "ERROR: Elasticsearch did not exit normally - check the logs at "
+                        + basePath
+                        + System.getProperty("file.separator")
+                        + System.getProperty("es.logs.cluster_name") + ".log"
+                );
+            }
             exit(status);
         }
     }

diff --git a/server/src/main/java/org/elasticsearch/bootstrap/ElasticsearchUncaughtExceptionHandler.java b/server/src/main/java/org/elasticsearch/bootstrap/ElasticsearchUncaughtExceptionHandler.java
@@ -21,7 +21,7 @@
 
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.message.ParameterizedMessage;
+import org.elasticsearch.cli.Terminal;
 import org.elasticsearch.common.SuppressForbidden;
 
 import java.io.IOError;
@@ -32,29 +32,29 @@ class ElasticsearchUncaughtExceptionHandler implements Thread.UncaughtExceptionH
     private static final Logger logger = LogManager.getLogger(ElasticsearchUncaughtExceptionHandler.class);
 
     @Override
-    public void uncaughtException(Thread t, Throwable e) {
-        if (isFatalUncaught(e)) {
+    public void uncaughtException(Thread thread, Throwable t) {
+        if (isFatalUncaught(t)) {
             try {
-                onFatalUncaught(t.getName(), e);
+                onFatalUncaught(thread.getName(), t);
             } finally {
                 // we use specific error codes in case the above notification failed, at least we
                 // will have some indication of the error bringing us down
-                if (e instanceof InternalError) {
+                if (t instanceof InternalError) {
                     halt(128);
-                } else if (e instanceof OutOfMemoryError) {
+                } else if (t instanceof OutOfMemoryError) {
                     halt(127);
-                } else if (e instanceof StackOverflowError) {
+                } else if (t instanceof StackOverflowError) {
                     halt(126);
-                } else if (e instanceof UnknownError) {
+                } else if (t instanceof UnknownError) {
                     halt(125);
-                } else if (e instanceof IOError) {
+                } else if (t instanceof IOError) {
                     halt(124);
                 } else {
                     halt(1);
                 }
             }
         } else {
-            onNonFatalUncaught(t.getName(), e);
+            onNonFatalUncaught(thread.getName(), t);
         }
     }
 
@@ -63,11 +63,21 @@ static boolean isFatalUncaught(Throwable e) {
     }
 
     void onFatalUncaught(final String threadName, final Throwable t) {
-        logger.error(() -> new ParameterizedMessage("fatal error in thread [{}], exiting", threadName), t);
+        final String message = "fatal error in thread [" + threadName + "], exiting";
+        logger.error(message, t);
+        Terminal.DEFAULT.errorPrintln(message);
+        t.printStackTrace(Terminal.DEFAULT.getErrorWriter());
+        // Without a final flush, the stacktrace may not be shown before ES exits
+        Terminal.DEFAULT.flush();
     }
 
     void onNonFatalUncaught(final String threadName, final Throwable t) {
-        logger.warn(() -> new ParameterizedMessage("uncaught exception in thread [{}]", threadName), t);
+        final String message = "uncaught exception in thread [" + threadName + "]";
+        logger.error(message, t);
+        Terminal.DEFAULT.errorPrintln(message);
+        t.printStackTrace(Terminal.DEFAULT.getErrorWriter());
+        // Without a final flush, the stacktrace may not be shown if ES goes on to exit
+        Terminal.DEFAULT.flush();
     }
 
     void halt(int status) {

diff --git a/server/src/main/java/org/elasticsearch/bootstrap/StartupException.java b/server/src/main/java/org/elasticsearch/bootstrap/StartupException.java
@@ -111,7 +111,17 @@ private void printStackTrace(Consumer<String> consumer) {
         // if its a guice exception, the whole thing really will not be in the log, its megabytes.
         // refer to the hack in bootstrap, where we don't log it
         if (originalCause instanceof CreationException == false) {
-            consumer.accept("Refer to the log for complete error details.");
+            final String basePath = System.getProperty("es.logs.base_path");
+            // It's possible to fail before logging has been configured, in which case there's no point
+            // suggested that the user look in the log file.
+            if (basePath != null) {
+                final String logPath = System.getProperty("es.logs.base_path")
+                    + System.getProperty("file.separator")
+                    + System.getProperty("es.logs.cluster_name")
+                    + ".log";
+
+                consumer.accept("For complete error details, refer to the log at " + logPath);
+            }
         }
     }