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

@@ -7,14 +7,20 @@ 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
 
 ## [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
 

build.gradle

@@ -19,7 +19,7 @@ compileTestJava { options.encoding = "UTF-8" }
 //    }
 //}
 
-version = "3.15.1"
+version = "3.16.0"
 
 
 repositories {

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:
+# argon2_hashing_pool_size:
+
+# (OPTIONAL | Default: "INFO"). Logging level for the core. Values are "DEBUG" | "INFO" | "WARN" | "ERROR" | "NONE"
+# log_level:

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:

pluginInterfaceSupported.json

@@ -1,6 +1,6 @@
 {
   "_comment": "contains a list of plugin interfaces branch names that this core supports",
   "versions": [
-    "2.17"
+    "2.18"
   ]
 }

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) {
 
         }
     }

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);

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<LOG_LEVEL> allowedLogLevels = null;
+
+    public Set<LOG_LEVEL> 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()) {

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;

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<LOG_LEVEL> logLevel) {
         Config.loadConfig(this);
     }
 

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) {