From fe1dbd4c3420aba8585a3c58a33f3668dfa3aaeb Mon Sep 17 00:00:00 2001 From: Rory Hunter Date: Fri, 15 Nov 2019 13:58:28 +0000 Subject: [PATCH] Don't close stderr under `--quiet` (#47208) Closes #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. --- .../java/org/elasticsearch/cli/Terminal.java | 5 + .../packaging/test/PackageTests.java | 114 +++++++++++------- .../elasticsearch/packaging/util/Docker.java | 7 +- .../packaging/util/Packages.java | 34 +++++- .../elasticsearch/bootstrap/Bootstrap.java | 7 +- .../bootstrap/Elasticsearch.java | 11 ++ ...ElasticsearchUncaughtExceptionHandler.java | 34 ++++-- .../bootstrap/StartupException.java | 12 +- 8 files changed, 156 insertions(+), 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 index 718b4796c0209..74af7e2e3102f 100644 --- 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 index 283c3df59290f..4aa9e0d0e0ae3 100644 --- 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 index 686cccbdc6c79..62146c0d5db57 100644 --- 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 void withLogging(CheckedRunnable 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 index 11034b95d56fe..1e6540e778874 100644 --- 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 journalctl 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 index 5e719164a1c89..ff6be43e66474 100644 --- 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 index 26a1aa30ada17..3513a967763f5 100644 --- 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 index 1c3c0ccf6b61f..d2d5ea1ef6ea8 100644 --- 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 index 59629eb5b3b19..f9349361a4444 100644 --- 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 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); + } } }