From a86d60b26bb37ad81290ddb60ca071dd34208009 Mon Sep 17 00:00:00 2001 From: Rishabh Poddar Date: Thu, 18 Aug 2022 12:07:33 +0530 Subject: [PATCH] feat: Implementing log levels (#495) * initial implementation without tests * fixes a few tests * fixes more tests * adds several tests for log level * adds more tests * optimisation * changes info log to optionally log to the console * small change * fixes tests * changes as per plugin interface * changes version --- CHANGELOG.md | 8 +- build.gradle | 2 +- config.yaml | 5 +- devConfig.yaml | 3 + pluginInterfaceSupported.json | 2 +- src/main/java/io/supertokens/Main.java | 43 +- .../java/io/supertokens/config/Config.java | 2 +- .../io/supertokens/config/CoreConfig.java | 40 ++ .../io/supertokens/cronjobs/CronTask.java | 8 +- .../java/io/supertokens/inmemorydb/Start.java | 8 +- .../java/io/supertokens/output/Logging.java | 36 +- .../storageLayer/StorageLayer.java | 8 +- .../java/io/supertokens/version/Version.java | 2 +- .../io/supertokens/webserver/Webserver.java | 6 +- .../supertokens/webserver/WebserverAPI.java | 9 +- .../io/supertokens/test/LogLevelTest.java | 561 ++++++++++++++++++ .../java/io/supertokens/test/LoggingTest.java | 12 +- 17 files changed, 702 insertions(+), 53 deletions(-) create mode 100644 src/test/java/io/supertokens/test/LogLevelTest.java diff --git a/CHANGELOG.md b/CHANGELOG.md index 80e3368f0..279c699f6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,12 @@ to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [unreleased] +## [3.16.0] - 2022-08-18 + +- Changes logging level of API start / finished & Cronjob start / finished to be `INFO` level instead of `DEBUG` level. +- Added new config `log_level` to set logging level. Possible values are `DEBUG` | `INFO` | `WARN` | `ERROR` | + `NONE`. As an example, setting the log level to `WARN` would make the core print out `WARN` and `ERROR` level logs. + ## [3.15.1] - 2022-08-10 - Updates UserIdMapping recipe to resolve UserId Mappings for Auth recipes in the core itself @@ -14,7 +20,7 @@ to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [3.15.0] - 2022-07-25 - Adds UserIdMapping recipe -- Support for collecting and displaying failing tests +- Support for collecting and displaying failing tests ### Database changes diff --git a/build.gradle b/build.gradle index 287c49ac1..039213be2 100644 --- a/build.gradle +++ b/build.gradle @@ -19,7 +19,7 @@ compileTestJava { options.encoding = "UTF-8" } // } //} -version = "3.15.1" +version = "3.16.0" repositories { diff --git a/config.yaml b/config.yaml index dabe294ce..cb016774a 100644 --- a/config.yaml +++ b/config.yaml @@ -102,4 +102,7 @@ core_config_version: 0 # (OPTIONAL | Default: 1). Number of concurrent argon2 hashes that can happen at the same time for sign up or sign # in requests. -# argon2_hashing_pool_size: \ No newline at end of file +# argon2_hashing_pool_size: + +# (OPTIONAL | Default: "INFO"). Logging level for the core. Values are "DEBUG" | "INFO" | "WARN" | "ERROR" | "NONE" +# log_level: \ No newline at end of file diff --git a/devConfig.yaml b/devConfig.yaml index 2aaf2fe37..af8e9e57a 100644 --- a/devConfig.yaml +++ b/devConfig.yaml @@ -103,3 +103,6 @@ disable_telemetry: true # (OPTIONAL | Default: 1). Number of concurrent argon2 hashes that can happen at the same time for sign up or sign # in requests. # argon2_hashing_pool_size: + +# (OPTIONAL | Default: "INFO"). Logging level for the core. Values are "DEBUG" | "INFO" | "WARN" | "ERROR" | "NONE" +# log_level: \ No newline at end of file diff --git a/pluginInterfaceSupported.json b/pluginInterfaceSupported.json index f53ad46bf..103fee1cd 100644 --- a/pluginInterfaceSupported.json +++ b/pluginInterfaceSupported.json @@ -1,6 +1,6 @@ { "_comment": "contains a list of plugin interfaces branch names that this core supports", "versions": [ - "2.17" + "2.18" ] } \ No newline at end of file diff --git a/src/main/java/io/supertokens/Main.java b/src/main/java/io/supertokens/Main.java index 1a37ae574..11b153ec6 100644 --- a/src/main/java/io/supertokens/Main.java +++ b/src/main/java/io/supertokens/Main.java @@ -118,7 +118,7 @@ public void start(String[] args) { ProcessState.getInstance(this).addState(ProcessState.PROCESS_STATE.SHUTTING_DOWN, null); stopApp(); - Logging.info(this, "Goodbye"); + Logging.info(this, "Goodbye", true); } catch (Exception e) { ProcessState.getInstance(this).addState(ProcessState.PROCESS_STATE.SHUTTING_DOWN, null); @@ -143,14 +143,16 @@ private void init() throws IOException { // Handle kill signal gracefully handleKillSignalForWhenItHappens(); - // loading storage layer - StorageLayer.init(this, CLIOptions.get(this).getInstallationPath() + "plugin/", + // loading configs for core. + Config.loadConfig(this, CLIOptions.get(this).getConfigFilePath() == null ? CLIOptions.get(this).getInstallationPath() + "config.yaml" : CLIOptions.get(this).getConfigFilePath()); - // loading configs for core. - Config.loadConfig(this, + Logging.info(this, "Completed config.yaml loading.", true); + + // loading storage layer + StorageLayer.init(this, CLIOptions.get(this).getInstallationPath() + "plugin/", CLIOptions.get(this).getConfigFilePath() == null ? CLIOptions.get(this).getInstallationPath() + "config.yaml" : CLIOptions.get(this).getConfigFilePath()); @@ -161,8 +163,6 @@ private void init() throws IOException { // init file logging Logging.initFileLogging(this); - Logging.info(this, "Completed config.yaml loading."); - // initialise cron job handler Cronjobs.init(this); @@ -217,7 +217,7 @@ private void init() throws IOException { // NOTE: If the message below is changed, make sure to also change the corresponding check in the CLI program // for start command Logging.info(this, "Started SuperTokens on " + Config.getConfig(this).getHost(this) + ":" - + Config.getConfig(this).getPort(this) + " with PID: " + ProcessHandle.current().pid()); + + Config.getConfig(this).getPort(this) + " with PID: " + ProcessHandle.current().pid(), true); } @TestOnly @@ -314,8 +314,24 @@ public void killForTestingAndWaitForShutdown() throws InterruptedException { // must not throw any error // must wait for everything to finish and only then exit private void stopApp() { - Logging.info(this, "Stopping SuperTokens..."); try { + // We do this first because it was initialized first. + // so if something else fails below due to config not initialized, + // then at least this will be cleared. + if (this.shutdownHook != null) { + try { + Runtime.getRuntime().removeShutdownHook(this.shutdownHook); + } catch (IllegalStateException e) { + // we are shutting down already.. so doesn't matter + } + } + + // Note that logging may throw an error if the config + // was not loaded due to an error in config. But this is OK + // since we load config before loading anything else + // below this, and this whole block is surrounded in a + // try / catch. + Logging.info(this, "Stopping SuperTokens...", true); Webserver.getInstance(this).stop(); Cronjobs.shutdownAndAwaitTermination(this); if (!Main.isTesting) { @@ -340,19 +356,12 @@ private void stopApp() { */ } } - if (this.shutdownHook != null) { - try { - Runtime.getRuntime().removeShutdownHook(this.shutdownHook); - } catch (IllegalStateException e) { - // we are shutting down already.. so doesn't matter - } - } removeDotStartedFileForThisProcess(); Logging.stopLogging(this); // uncomment this when you want to confirm that processes are actually shut. // printRunningThreadNames(); - } catch (Exception ignored) { + } catch (Throwable ignored) { } } diff --git a/src/main/java/io/supertokens/config/Config.java b/src/main/java/io/supertokens/config/Config.java index 33fa93aef..a367bc54c 100644 --- a/src/main/java/io/supertokens/config/Config.java +++ b/src/main/java/io/supertokens/config/Config.java @@ -50,6 +50,7 @@ public static void loadConfig(Main main, String configFilePath) { return; } main.getResourceDistributor().setResource(RESOURCE_KEY, new Config(main, configFilePath)); + Logging.info(main, "Loading supertokens config.", true); } public static CoreConfig getConfig(Main main) { @@ -60,7 +61,6 @@ public static CoreConfig getConfig(Main main) { } private CoreConfig loadCoreConfig(String configFilePath) throws IOException { - Logging.info(main, "Loading supertokens config."); final ObjectMapper mapper = new ObjectMapper(new YAMLFactory()); CoreConfig config = mapper.readValue(new File(configFilePath), CoreConfig.class); config.validateAndInitialise(main); diff --git a/src/main/java/io/supertokens/config/CoreConfig.java b/src/main/java/io/supertokens/config/CoreConfig.java index 5c5ae1b45..4faf2b4a5 100644 --- a/src/main/java/io/supertokens/config/CoreConfig.java +++ b/src/main/java/io/supertokens/config/CoreConfig.java @@ -21,10 +21,13 @@ import io.supertokens.Main; import io.supertokens.cliOptions.CLIOptions; import io.supertokens.exceptions.QuitProgramException; +import io.supertokens.pluginInterface.LOG_LEVEL; import org.jetbrains.annotations.TestOnly; import java.io.File; import java.io.IOException; +import java.util.HashSet; +import java.util.Set; @JsonIgnoreProperties(ignoreUnknown = true) public class CoreConfig { @@ -110,6 +113,36 @@ public class CoreConfig { @JsonProperty private String base_path = ""; + @JsonProperty + private String log_level = "INFO"; + + private Set allowedLogLevels = null; + + public Set getLogLevels(Main main) { + if (allowedLogLevels != null) { + return allowedLogLevels; + } + LOG_LEVEL logLevel = LOG_LEVEL.valueOf(this.log_level.toUpperCase()); + allowedLogLevels = new HashSet<>(); + if (logLevel == LOG_LEVEL.NONE) { + return allowedLogLevels; + } + allowedLogLevels.add(LOG_LEVEL.ERROR); + if (logLevel == LOG_LEVEL.ERROR) { + return allowedLogLevels; + } + allowedLogLevels.add(LOG_LEVEL.WARN); + if (logLevel == LOG_LEVEL.WARN) { + return allowedLogLevels; + } + allowedLogLevels.add(LOG_LEVEL.INFO); + if (logLevel == LOG_LEVEL.INFO) { + return allowedLogLevels; + } + allowedLogLevels.add(LOG_LEVEL.DEBUG); + return allowedLogLevels; + } + public String getBasePath() { String base_path = this.base_path; // Don't modify the original value from the config if (base_path == null || base_path.equals("/") || base_path.isEmpty()) { @@ -375,6 +408,13 @@ void validateAndInitialise(Main main) throws IOException { } } + if (!log_level.equalsIgnoreCase("info") && !log_level.equalsIgnoreCase("none") + && !log_level.equalsIgnoreCase("error") && !log_level.equalsIgnoreCase("warn") + && !log_level.equalsIgnoreCase("debug")) { + throw new QuitProgramException( + "'log_level' config must be one of \"NONE\",\"DEBUG\", \"INFO\", \"WARN\" or \"ERROR\"."); + } + if (!getInfoLogPath(main).equals("null")) { File infoLog = new File(getInfoLogPath(main)); if (!infoLog.exists()) { diff --git a/src/main/java/io/supertokens/cronjobs/CronTask.java b/src/main/java/io/supertokens/cronjobs/CronTask.java index c117102d9..af3b6cb54 100644 --- a/src/main/java/io/supertokens/cronjobs/CronTask.java +++ b/src/main/java/io/supertokens/cronjobs/CronTask.java @@ -30,17 +30,17 @@ public abstract class CronTask extends ResourceDistributor.SingletonResource imp protected CronTask(String jobName, Main main) { this.jobName = jobName; this.main = main; - Logging.info(main, "Starting task: " + jobName); + Logging.info(main, "Starting task: " + jobName, false); } void shutdownIsGoingToBeCalled() { - Logging.info(main, "Stopping task: " + jobName); + Logging.info(main, "Stopping task: " + jobName, false); } @Override public void run() { try { - Logging.debug(main, "Cronjob started: " + jobName); + Logging.info(main, "Cronjob started: " + jobName, false); doTask(); } catch (Exception e) { ProcessState.getInstance(main).addState(ProcessState.PROCESS_STATE.CRON_TASK_ERROR_LOGGING, e); @@ -49,7 +49,7 @@ public void run() { main.wakeUpMainThreadToShutdown(); } } - Logging.debug(main, "Cronjob finished: " + jobName); + Logging.info(main, "Cronjob finished: " + jobName, false); } protected abstract void doTask() throws Exception; diff --git a/src/main/java/io/supertokens/inmemorydb/Start.java b/src/main/java/io/supertokens/inmemorydb/Start.java index 5bdebb4c8..65c69ff34 100644 --- a/src/main/java/io/supertokens/inmemorydb/Start.java +++ b/src/main/java/io/supertokens/inmemorydb/Start.java @@ -20,15 +20,14 @@ import io.supertokens.Main; import io.supertokens.ProcessState; import io.supertokens.ResourceDistributor; -import io.supertokens.emailpassword.EmailPassword; import io.supertokens.emailverification.EmailVerification; import io.supertokens.emailverification.exception.EmailAlreadyVerifiedException; import io.supertokens.inmemorydb.config.Config; import io.supertokens.inmemorydb.queries.*; import io.supertokens.pluginInterface.KeyValueInfo; +import io.supertokens.pluginInterface.LOG_LEVEL; import io.supertokens.pluginInterface.RECIPE_ID; import io.supertokens.pluginInterface.STORAGE_TYPE; -import io.supertokens.pluginInterface.authRecipe.AuthRecipeStorage; import io.supertokens.pluginInterface.authRecipe.AuthRecipeUserInfo; import io.supertokens.pluginInterface.emailpassword.PasswordResetTokenInfo; import io.supertokens.pluginInterface.emailpassword.UserInfo; @@ -48,7 +47,6 @@ import io.supertokens.pluginInterface.jwt.JWTSigningKeyInfo; import io.supertokens.pluginInterface.jwt.exceptions.DuplicateKeyIdException; import io.supertokens.pluginInterface.jwt.sqlstorage.JWTRecipeSQLStorage; -import io.supertokens.pluginInterface.nonAuthRecipe.NonAuthRecipeStorage; import io.supertokens.pluginInterface.passwordless.PasswordlessCode; import io.supertokens.pluginInterface.passwordless.PasswordlessDevice; import io.supertokens.pluginInterface.passwordless.exception.*; @@ -83,9 +81,9 @@ import java.sql.SQLException; import java.sql.SQLTransactionRollbackException; import java.util.ArrayList; -import java.util.Arrays; import java.util.HashMap; import java.util.List; +import java.util.Set; public class Start implements SessionSQLStorage, EmailPasswordSQLStorage, EmailVerificationSQLStorage, ThirdPartySQLStorage, @@ -126,7 +124,7 @@ public STORAGE_TYPE getType() { } @Override - public void loadConfig(String ignored) { + public void loadConfig(String ignored, Set logLevel) { Config.loadConfig(this); } diff --git a/src/main/java/io/supertokens/output/Logging.java b/src/main/java/io/supertokens/output/Logging.java index 833c4746c..17ccf8a3a 100644 --- a/src/main/java/io/supertokens/output/Logging.java +++ b/src/main/java/io/supertokens/output/Logging.java @@ -24,6 +24,7 @@ import io.supertokens.Main; import io.supertokens.ResourceDistributor; import io.supertokens.config.Config; +import io.supertokens.pluginInterface.LOG_LEVEL; import io.supertokens.pluginInterface.Storage; import io.supertokens.storageLayer.StorageLayer; import io.supertokens.utils.Utils; @@ -74,12 +75,13 @@ private static Logging getInstance(Main main) { public static void initFileLogging(Main main) { if (getInstance(main) == null) { main.getResourceDistributor().setResource(RESOURCE_ID, new Logging(main)); - StorageLayer.getStorage(main).initFileLogging(Config.getConfig(main).getInfoLogPath(main), - Config.getConfig(main).getErrorLogPath(main)); } } public static void debug(Main main, String msg) { + if (!Config.getConfig(main).getLogLevels(main).contains(LOG_LEVEL.DEBUG)) { + return; + } try { msg = msg.trim(); if (getInstance(main) != null) { @@ -90,18 +92,26 @@ public static void debug(Main main, String msg) { } } - public static void info(Main main, String msg) { + public static void info(Main main, String msg, boolean toConsoleAsWell) { + if (!Config.getConfig(main).getLogLevels(main).contains(LOG_LEVEL.INFO)) { + return; + } try { msg = msg.trim(); - systemOut(msg); if (getInstance(main) != null) { getInstance(main).infoLogger.info(msg); } + if (toConsoleAsWell) { + systemOut(msg); + } } catch (NullPointerException ignored) { } } public static void warn(Main main, String msg) { + if (!Config.getConfig(main).getLogLevels(main).contains(LOG_LEVEL.WARN)) { + return; + } try { msg = msg.trim(); if (getInstance(main) != null) { @@ -112,6 +122,15 @@ public static void warn(Main main, String msg) { } public static void error(Main main, String err, boolean toConsoleAsWell) { + try { + if (!Config.getConfig(main).getLogLevels(main).contains(LOG_LEVEL.ERROR)) { + return; + } + } catch (Throwable ignored) { + // if it comes here, it means that the config was not loaded and that we are trying + // to log some other error. In this case, we want to log it anyway, so we catch any + // error and continue below. + } try { err = err.trim(); if (getInstance(main) != null) { @@ -125,6 +144,15 @@ public static void error(Main main, String err, boolean toConsoleAsWell) { } public static void error(Main main, String message, boolean toConsoleAsWell, Exception e) { + try { + if (!Config.getConfig(main).getLogLevels(main).contains(LOG_LEVEL.ERROR)) { + return; + } + } catch (Throwable ignored) { + // if it comes here, it means that the config was not loaded and that we are trying + // to log some other error. In this case, we want to log it anyway, so we catch any + // error and continue below. + } try { String err = Utils.throwableStacktraceToString(e).trim(); if (getInstance(main) != null) { diff --git a/src/main/java/io/supertokens/storageLayer/StorageLayer.java b/src/main/java/io/supertokens/storageLayer/StorageLayer.java index a20780c34..d8509819e 100644 --- a/src/main/java/io/supertokens/storageLayer/StorageLayer.java +++ b/src/main/java/io/supertokens/storageLayer/StorageLayer.java @@ -19,6 +19,7 @@ import io.supertokens.Main; import io.supertokens.ResourceDistributor; import io.supertokens.cliOptions.CLIOptions; +import io.supertokens.config.Config; import io.supertokens.exceptions.QuitProgramException; import io.supertokens.inmemorydb.Start; import io.supertokens.output.Logging; @@ -33,7 +34,6 @@ import io.supertokens.pluginInterface.thirdparty.sqlStorage.ThirdPartySQLStorage; import io.supertokens.pluginInterface.useridmapping.UserIdMappingStorage; import io.supertokens.pluginInterface.usermetadata.sqlStorage.UserMetadataSQLStorage; -import io.supertokens.pluginInterface.userroles.UserRolesStorage; import io.supertokens.pluginInterface.userroles.sqlStorage.UserRolesSQLStorage; import org.jetbrains.annotations.TestOnly; @@ -53,7 +53,7 @@ public class StorageLayer extends ResourceDistributor.SingletonResource { private static URLClassLoader ucl = null; private StorageLayer(Main main, String pluginFolderPath, String configFilePath) throws MalformedURLException { - Logging.info(main, "Loading storage layer."); + Logging.info(main, "Loading storage layer.", true); if (static_ref_to_storage != null && Main.isTesting) { // we reuse the storage layer during testing so that we do not waste // time reconnecting to the db. @@ -97,12 +97,12 @@ private StorageLayer(Main main, String pluginFolderPath, String configFilePath) && (storageLayerTemp.canBeUsed(configFilePath) || CLIOptions.get(main).isForceNoInMemoryDB())) { this.storage = storageLayerTemp; } else { - Logging.info(main, "Using in memory storage."); + Logging.info(main, "Using in memory storage.", true); this.storage = new Start(main); } } this.storage.constructor(main.getProcessId(), Main.makeConsolePrintSilent); - this.storage.loadConfig(configFilePath); + this.storage.loadConfig(configFilePath, Config.getConfig(main).getLogLevels(main)); if (Main.isTesting && !(this.storage instanceof Start)) { // we save the storage layer for testing (if it's not an in mem db) purposes so that // next time, we can just reuse this. diff --git a/src/main/java/io/supertokens/version/Version.java b/src/main/java/io/supertokens/version/Version.java index 8f199b138..1495dbaf0 100644 --- a/src/main/java/io/supertokens/version/Version.java +++ b/src/main/java/io/supertokens/version/Version.java @@ -60,7 +60,7 @@ public static VersionFile getVersion(Main main) { } private VersionFile loadVersionFile(String versionFilePath) throws IOException { - Logging.info(main, "Loading supertokens version.yaml file."); + Logging.info(main, "Loading supertokens version.yaml file.", true); final ObjectMapper mapper = new ObjectMapper(new YAMLFactory()); VersionFile version = mapper.readValue(new File(versionFilePath), VersionFile.class); version.validate(); diff --git a/src/main/java/io/supertokens/webserver/Webserver.java b/src/main/java/io/supertokens/webserver/Webserver.java index fea008ae9..d3bef1dfd 100644 --- a/src/main/java/io/supertokens/webserver/Webserver.java +++ b/src/main/java/io/supertokens/webserver/Webserver.java @@ -41,11 +41,9 @@ import io.supertokens.webserver.api.useridmapping.RemoveUserIdMappingAPI; import io.supertokens.webserver.api.useridmapping.UpdateExternalUserIdInfoAPI; import io.supertokens.webserver.api.useridmapping.UserIdMappingAPI; -import io.supertokens.webserver.api.usermetadata.UserMetadataAPI; import io.supertokens.webserver.api.usermetadata.RemoveUserMetadataAPI; - +import io.supertokens.webserver.api.usermetadata.UserMetadataAPI; import io.supertokens.webserver.api.userroles.*; -import io.supertokens.webserver.api.userroles.RemoveUserRoleAPI; import org.apache.catalina.LifecycleException; import org.apache.catalina.LifecycleState; import org.apache.catalina.connector.Connector; @@ -228,7 +226,7 @@ public void stop() { if (tomcat.getServer() == null) { return; } - Logging.info(main, "Stopping webserver..."); + Logging.info(main, "Stopping webserver...", true); if (tomcat.getServer().getState() != LifecycleState.DESTROYED) { if (tomcat.getServer().getState() != LifecycleState.STOPPED) { try { diff --git a/src/main/java/io/supertokens/webserver/WebserverAPI.java b/src/main/java/io/supertokens/webserver/WebserverAPI.java index fa7ecf029..2f1b5ce5c 100644 --- a/src/main/java/io/supertokens/webserver/WebserverAPI.java +++ b/src/main/java/io/supertokens/webserver/WebserverAPI.java @@ -155,10 +155,11 @@ protected void service(HttpServletRequest req, HttpServletResponse resp) throws if (this.versionNeeded(req)) { String version = getVersionFromRequest(req); assertThatVersionIsCompatible(version); - Logging.debug(main, - "API called: " + this.getPath() + ". Method: " + req.getMethod() + ". Version: " + version); + Logging.info(main, + "API called: " + this.getPath() + ". Method: " + req.getMethod() + ". Version: " + version, + false); } else { - Logging.debug(main, "API called: " + this.getPath() + ". Method: " + req.getMethod()); + Logging.info(main, "API called: " + this.getPath() + ". Method: " + req.getMethod(), false); } super.service(req, resp); } catch (Exception e) { @@ -180,7 +181,7 @@ protected void service(HttpServletRequest req, HttpServletResponse resp) throws sendTextResponse(500, "Internal Error", resp); } } - Logging.debug(main, "API ended: " + this.getPath() + ". Method: " + req.getMethod()); + Logging.info(main, "API ended: " + this.getPath() + ". Method: " + req.getMethod(), false); } protected String getRIDFromRequest(HttpServletRequest req) { diff --git a/src/test/java/io/supertokens/test/LogLevelTest.java b/src/test/java/io/supertokens/test/LogLevelTest.java new file mode 100644 index 000000000..a54db7c10 --- /dev/null +++ b/src/test/java/io/supertokens/test/LogLevelTest.java @@ -0,0 +1,561 @@ +/* + * Copyright (c) 2020, VRAI Labs and/or its affiliates. All rights reserved. + * + * This software is licensed under the Apache License, Version 2.0 (the + * "License") as published by the Apache Software Foundation. + * + * You may not use this file except in compliance with the License. You may + * obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT + * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the + * License for the specific language governing permissions and limitations + * under the License. + */ + +package io.supertokens.test; + +import io.supertokens.ProcessState; +import io.supertokens.ProcessState.PROCESS_STATE; +import io.supertokens.config.Config; +import io.supertokens.output.Logging; +import io.supertokens.pluginInterface.LOG_LEVEL; +import io.supertokens.test.TestingProcessManager.TestingProcess; +import org.junit.AfterClass; +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; +import org.junit.rules.TestRule; + +import java.io.*; +import java.nio.charset.StandardCharsets; +import java.util.Scanner; +import java.util.Set; + +import static junit.framework.TestCase.assertEquals; +import static org.junit.Assert.*; + +public class LogLevelTest { + @Rule + public TestRule watchman = Utils.getOnFailure(); + + @AfterClass + public static void afterTesting() { + Utils.afterTesting(); + } + + @Before + public void beforeEach() { + Utils.reset(); + } + + @Test + public void testLogLevels() throws Exception { + { + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(3, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.INFO)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + Utils.reset(); + + { + Utils.setValueInConfig("log_level", "NONE"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(0, logLevels.size()); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "ERROR"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(1, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "WARN"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(2, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "INFO"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(3, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + assertTrue(logLevels.contains(LOG_LEVEL.INFO)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "DEBUG"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(4, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + assertTrue(logLevels.contains(LOG_LEVEL.INFO)); + assertTrue(logLevels.contains(LOG_LEVEL.DEBUG)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelNoneOutput() throws Exception { + { + Utils.setValueInConfig("log_level", "NONE"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + File infoLog = new File(Config.getConfig(process.getProcess()).getInfoLogPath(process.getProcess())); + File errorLog = new File(Config.getConfig(process.getProcess()).getErrorLogPath(process.getProcess())); + boolean didOutput = false; + Logging.error(process.getProcess(), "some message", false); + Logging.warn(process.getProcess(), "some message"); + Logging.info(process.getProcess(), "some message", true); + Logging.debug(process.getProcess(), "some message"); + + try (Scanner scanner = new Scanner(infoLog, StandardCharsets.UTF_8)) { + while (scanner.hasNextLine()) { + String line = scanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + didOutput = true; + break; + } + } + } + + try (Scanner errorScanner = new Scanner(errorLog, StandardCharsets.UTF_8)) { + while (errorScanner.hasNextLine()) { + String line = errorScanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + didOutput = true; + break; + } + } + } + + assertFalse(didOutput); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelErrorOutput() throws Exception { + { + Utils.setValueInConfig("log_level", "ERROR"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + File infoLog = new File(Config.getConfig(process.getProcess()).getInfoLogPath(process.getProcess())); + File errorLog = new File(Config.getConfig(process.getProcess()).getErrorLogPath(process.getProcess())); + boolean errorOutput = false; + boolean warnOutput = false; + boolean infoOutput = false; + boolean debugOutput = false; + + Logging.error(process.getProcess(), "some error", false); + Logging.warn(process.getProcess(), "some warn"); + Logging.info(process.getProcess(), "some info", true); + Logging.debug(process.getProcess(), "some debug"); + + try (Scanner scanner = new Scanner(infoLog, StandardCharsets.UTF_8)) { + while (scanner.hasNextLine()) { + String line = scanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some info")) { + infoOutput = true; + } else if (line.contains("some debug")) { + debugOutput = true; + } + } + } + } + + try (Scanner errorScanner = new Scanner(errorLog, StandardCharsets.UTF_8)) { + while (errorScanner.hasNextLine()) { + String line = errorScanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some error")) { + errorOutput = true; + } else if (line.contains("some warn")) { + warnOutput = true; + } + } + } + } + + assertTrue(errorOutput && !warnOutput && !infoOutput && !debugOutput); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelWarnOutput() throws Exception { + { + Utils.setValueInConfig("log_level", "WARN"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + File infoLog = new File(Config.getConfig(process.getProcess()).getInfoLogPath(process.getProcess())); + File errorLog = new File(Config.getConfig(process.getProcess()).getErrorLogPath(process.getProcess())); + boolean errorOutput = false; + boolean warnOutput = false; + boolean infoOutput = false; + boolean debugOutput = false; + + Logging.error(process.getProcess(), "some error", false); + Logging.warn(process.getProcess(), "some warn"); + Logging.info(process.getProcess(), "some info", true); + Logging.debug(process.getProcess(), "some debug"); + + try (Scanner scanner = new Scanner(infoLog, StandardCharsets.UTF_8)) { + while (scanner.hasNextLine()) { + String line = scanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some info")) { + infoOutput = true; + } else if (line.contains("some debug")) { + debugOutput = true; + } + } + } + } + + try (Scanner errorScanner = new Scanner(errorLog, StandardCharsets.UTF_8)) { + while (errorScanner.hasNextLine()) { + String line = errorScanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some error")) { + errorOutput = true; + } else if (line.contains("some warn")) { + warnOutput = true; + } + } + } + } + + assertTrue(errorOutput && warnOutput && !infoOutput && !debugOutput); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelInfoOutput() throws Exception { + { + Utils.setValueInConfig("log_level", "INFO"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + File infoLog = new File(Config.getConfig(process.getProcess()).getInfoLogPath(process.getProcess())); + File errorLog = new File(Config.getConfig(process.getProcess()).getErrorLogPath(process.getProcess())); + boolean errorOutput = false; + boolean warnOutput = false; + boolean infoOutput = false; + boolean debugOutput = false; + + Logging.error(process.getProcess(), "some error", false); + Logging.warn(process.getProcess(), "some warn"); + Logging.info(process.getProcess(), "some info", true); + Logging.debug(process.getProcess(), "some debug"); + + try (Scanner scanner = new Scanner(infoLog, StandardCharsets.UTF_8)) { + while (scanner.hasNextLine()) { + String line = scanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some info")) { + infoOutput = true; + } else if (line.contains("some debug")) { + debugOutput = true; + } + } + } + } + + try (Scanner errorScanner = new Scanner(errorLog, StandardCharsets.UTF_8)) { + while (errorScanner.hasNextLine()) { + String line = errorScanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some error")) { + errorOutput = true; + } else if (line.contains("some warn")) { + warnOutput = true; + } + } + } + } + + assertTrue(errorOutput && warnOutput && infoOutput && !debugOutput); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelDebugOutput() throws Exception { + { + Utils.setValueInConfig("log_level", "DEBUG"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + File infoLog = new File(Config.getConfig(process.getProcess()).getInfoLogPath(process.getProcess())); + File errorLog = new File(Config.getConfig(process.getProcess()).getErrorLogPath(process.getProcess())); + boolean errorOutput = false; + boolean warnOutput = false; + boolean infoOutput = false; + boolean debugOutput = false; + + Logging.error(process.getProcess(), "some error", false); + Logging.warn(process.getProcess(), "some warn"); + Logging.info(process.getProcess(), "some info", true); + Logging.debug(process.getProcess(), "some debug"); + + try (Scanner scanner = new Scanner(infoLog, StandardCharsets.UTF_8)) { + while (scanner.hasNextLine()) { + String line = scanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some info")) { + infoOutput = true; + } else if (line.contains("some debug")) { + debugOutput = true; + } + } + } + } + + try (Scanner errorScanner = new Scanner(errorLog, StandardCharsets.UTF_8)) { + while (errorScanner.hasNextLine()) { + String line = errorScanner.nextLine(); + if (line.contains(process.getProcess().getProcessId())) { + if (line.contains("some error")) { + errorOutput = true; + } else if (line.contains("some warn")) { + warnOutput = true; + } + } + } + } + + assertTrue(errorOutput && warnOutput && infoOutput && debugOutput); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelNoneOutputWithConfigErrorShouldLog() throws Exception { + { + ByteArrayOutputStream stdOutput = new ByteArrayOutputStream(); + ByteArrayOutputStream errorOutput = new ByteArrayOutputStream(); + System.setOut(new PrintStream(stdOutput)); + System.setErr(new PrintStream(errorOutput)); + + Utils.setValueInConfig("log_level", "NONE"); + Utils.setValueInConfig("access_token_validity", "-1"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.INIT_FAILURE)); + + assertFalse(fileContainsString(stdOutput, "access_token_validity")); + assertTrue(fileContainsString(errorOutput, "access_token_validity")); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testLogLevelsUpperLowerCase() throws Exception { + { + Utils.setValueInConfig("log_level", "NonE"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(0, logLevels.size()); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "error"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(1, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "wArN"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(2, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "info"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(3, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + assertTrue(logLevels.contains(LOG_LEVEL.INFO)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + { + Utils.setValueInConfig("log_level", "debug"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); + + Set logLevels = Config.getConfig(process.getProcess()).getLogLevels(process.getProcess()); + // default log level should be info + assertEquals(4, logLevels.size()); + assertTrue(logLevels.contains(LOG_LEVEL.ERROR)); + assertTrue(logLevels.contains(LOG_LEVEL.WARN)); + assertTrue(logLevels.contains(LOG_LEVEL.INFO)); + assertTrue(logLevels.contains(LOG_LEVEL.DEBUG)); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + } + + @Test + public void testIncorrectLogLevel() throws Exception { + Utils.setValueInConfig("log_level", "random"); + String[] args = { "../" }; + TestingProcess process = TestingProcessManager.start(args); + + ProcessState.EventAndException e = process.checkOrWaitForEvent(ProcessState.PROCESS_STATE.INIT_FAILURE); + assertNotNull(e); + assertEquals(e.exception.getMessage(), + "'log_level' config must be one of \"NONE\",\"DEBUG\", \"INFO\", \"WARN\" or \"ERROR\"."); + + process.kill(); + assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STOPPED)); + } + + private static boolean fileContainsString(ByteArrayOutputStream log, String value) throws IOException { + boolean containsString = false; + try (BufferedReader reader = new BufferedReader(new StringReader(log.toString()))) { + String currentReadingLine = reader.readLine(); + while (currentReadingLine != null) { + if (currentReadingLine.contains(value)) { + containsString = true; + break; + } + currentReadingLine = reader.readLine(); + } + } + return containsString; + } + +} diff --git a/src/test/java/io/supertokens/test/LoggingTest.java b/src/test/java/io/supertokens/test/LoggingTest.java index 63fccf5cc..f43743814 100644 --- a/src/test/java/io/supertokens/test/LoggingTest.java +++ b/src/test/java/io/supertokens/test/LoggingTest.java @@ -105,7 +105,7 @@ public void customLogging() throws Exception { assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); Logging.error(process.getProcess(), "From Test", false); - Logging.info(process.getProcess(), "From Test"); + Logging.info(process.getProcess(), "From Test", true); boolean infoFlag = false; boolean errorFlag = false; @@ -174,6 +174,7 @@ public void testStandardOutLoggingWithNullStr() throws Exception { ByteArrayOutputStream stdOutput = new ByteArrayOutputStream(); ByteArrayOutputStream errorOutput = new ByteArrayOutputStream(); + Utils.setValueInConfig("log_level", "DEBUG"); Utils.setValueInConfig("info_log_path", "\"null\""); Utils.setValueInConfig("error_log_path", "\"null\""); @@ -187,10 +188,10 @@ public void testStandardOutLoggingWithNullStr() throws Exception { assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); Logging.debug(process.getProcess(), "outTest-dfkn3knsakn"); - Logging.error(process.getProcess(), "errTest-sdvjovnoasid", false); + Logging.error(process.getProcess(), "errTest-sdvjovnoasid", true); assertTrue(fileContainsString(stdOutput, "outTest-dfkn3knsakn")); - assertTrue(fileContainsString(stdOutput, "errTest-sdvjovnoasid")); + assertTrue(fileContainsString(errorOutput, "errTest-sdvjovnoasid")); } finally { process.kill(); @@ -207,6 +208,7 @@ public void testStandardOutLoggingWithNull() throws Exception { ByteArrayOutputStream stdOutput = new ByteArrayOutputStream(); ByteArrayOutputStream errorOutput = new ByteArrayOutputStream(); + Utils.setValueInConfig("log_level", "DEBUG"); Utils.setValueInConfig("info_log_path", "null"); Utils.setValueInConfig("error_log_path", "null"); @@ -220,10 +222,10 @@ public void testStandardOutLoggingWithNull() throws Exception { assertNotNull(process.checkOrWaitForEvent(PROCESS_STATE.STARTED)); Logging.debug(process.getProcess(), "outTest-dfkn3knsakn"); - Logging.error(process.getProcess(), "errTest-sdvjovnoasid", false); + Logging.error(process.getProcess(), "errTest-sdvjovnoasid", true); assertTrue(fileContainsString(stdOutput, "outTest-dfkn3knsakn")); - assertTrue(fileContainsString(stdOutput, "errTest-sdvjovnoasid")); + assertTrue(fileContainsString(errorOutput, "errTest-sdvjovnoasid")); } finally { process.kill();