Logging changed to SLF4J, instead of wrapping it in a non-standard way. SSH logging is now dependent on what the executor log is set to (only for logback implementations)

src/dorkbox/executor/DeferredProcessResult.kt

@@ -25,24 +25,16 @@ import dorkbox.executor.processResults.SyncProcessResult
 import dorkbox.executor.stop.ProcessStopper
 import dorkbox.executor.stream.IOStreamHandler
 import dorkbox.executor.stream.PumpStreamHandler
-import kotlinx.coroutines.CancellationException
-import kotlinx.coroutines.CoroutineExceptionHandler
-import kotlinx.coroutines.Dispatchers
-import kotlinx.coroutines.ExperimentalCoroutinesApi
-import kotlinx.coroutines.Job
-import kotlinx.coroutines.TimeoutCancellationException
+import kotlinx.coroutines.*
 import kotlinx.coroutines.channels.Channel
-import kotlinx.coroutines.launch
-import kotlinx.coroutines.runBlocking
-import kotlinx.coroutines.withContext
-import kotlinx.coroutines.withTimeout
-import kotlinx.coroutines.withTimeoutOrNull
-import kotlinx.coroutines.yield
 import mu.KotlinLogging
+import org.slf4j.Logger
 import org.slf4j.MDC
 import java.io.ByteArrayOutputStream
 import java.io.IOException
-import java.util.concurrent.*
+import java.util.concurrent.ExecutionException
+import java.util.concurrent.TimeUnit
+import java.util.concurrent.TimeoutException
 import kotlin.text.Charsets.UTF_8
 
 internal data class Params(
@@ -67,18 +59,18 @@ internal data class Params(
         val streams: IOStreamHandler,
 
         /**
-         * Helper for logging messages about starting and waiting for the processes.
+         * Logger for logging messages about starting and waiting for the processes.
          */
-        val messageLogger: MessageLogger,
+        val logger: Logger?,
 
         /**
          * ONLY called if there is an exception while waiting for the process to complete.
          */
         val errorMessageHandler: (StringBuilder) -> Unit,
 
-        val closeTimeout: Long, val closeTimeoutUnit: TimeUnit,
+    val closeTimeout: Long, val closeTimeoutUnit: TimeUnit,
 
-        val asyncProcessStart: Boolean)
+    val asyncProcessStart: Boolean)
 
 
 class DeferredProcessResult internal constructor(private val process: Process,
@@ -367,10 +359,11 @@ class DeferredProcessResult internal constructor(private val process: Process,
             exit = process.waitFor()
 
             finished = true
-            params.messageLogger.message(log, "{} stopped with exit code {}", this, exit)
+
+            LogHelper.logAtLowestLevel(params.logger, "{} stopped with exit code {}", this, exit)
         } finally {
             if (!finished) {
-                params.messageLogger.message(log, "Stopping {}...", this)
+                LogHelper.logAtLowestLevel(params.logger, "Stopping {}...", this)
                 params.stopper.stop(process)
             }
 

src/dorkbox/executor/Executor.kt

@@ -228,8 +228,11 @@ open class Executor {
 
     /**
      * Helper for logging messages about starting and waiting for the processes.
+     *
+     * see http://logback.qos.ch/manual/architecture.html for more info
+     *  logger order goes (from lowest to highest) TRACE->DEBUG->INFO->WARN->ERROR->OFF
      */
-    private var messageLogger = MessageLoggers.DEBUG
+    private var logger: Logger? = null
 
     /**
      * Capture a snapshot of this process executor's main state.
@@ -1042,16 +1045,17 @@ open class Executor {
 
     /**
      * Changes how most common messages about starting and waiting for processes are actually logged.
-     * By default [MessageLoggers.DEBUG] is used.
+     * By default **NO OUTPUT** is used.
      *
-     * However if someone is executing a process every second [MessageLoggers.TRACE] may be used e.g.
+     * see http://logback.qos.ch/manual/architecture.html for more info
+     *  logger order goes (from lowest to highest) TRACE->DEBUG->INFO->WARN->ERROR->OFF
      *
-     * @param messageLogger message logger for certain level.
+     * @param logger logger instance to use. Will log at whatever the highest level possible for that logger
      *
      * @return This process executor.
      */
-    fun setMessageLogger(messageLogger: MessageLogger): Executor {
-        this.messageLogger = messageLogger
+    fun setLogger(logger: Logger?): Executor {
+        this.logger = logger
         return this
     }
 
@@ -1270,7 +1274,7 @@ open class Executor {
             // should we execute the command as a "shell command", or should we fork the process and run it directly?
 
             if (IS_OS_WINDOWS) {
-                // add our commands to the internal command list
+                // add our commands to the internal command list BEFORE all other commands
                 builder.command().addAll(0, listOf("cmd", "/c"))
             } else {
                 if (DEFAULT_SHELL == null) {
@@ -1303,32 +1307,10 @@ open class Executor {
                 }
 
                 // *nix
-                ///  // when a shell AND on *nix, we have to place ALL the args into a single "arg" that is passed in
-                //            final StringBuilder stringBuilder = new StringBuilder(1024);
-                //
-                //            stringBuilder.append(this.executableName).append(" ");
-                //
-                //            for (String arg : this.arguments) {
-                //                stringBuilder.append(arg).append(" ");
-                //            }
-                //
-                //            if (!arguments.isEmpty()) {
-                //                if (pipeToNull) {
-                //                    stringBuilder.append(pipeToNullString);
-                //                }
-                //                else {
-                //                    // delete last " "
-                //                    stringBuilder.delete(stringBuilder.length() - 1, stringBuilder.length());
-                //                }
-                //            }
-                //
-                //            fullCommand.add(stringBuilder.toString());
-// add our commands to the internal command list
+                // add our commands to the internal command list BEFORE all other commands
                 builder.command().addAll(0, listOf(DEFAULT_SHELL!!, "-c"))
             }
 
-
-
             if (IS_OS_MAC && !environment.containsKey("SOFTWARE")) {
                 // Enable LANG overrides
                 environment["SOFTWARE"] = ""
@@ -1363,7 +1345,6 @@ open class Executor {
         // we can read the output IN ADDITION TO having our own output stream for the process.
         if (!readOutput && executeAsShell && streams.out is NopOutputStream) {
             // NOTE: this ONLY works if we are running as a shell!
-
             val command = builder.command()
 
             // should we redirect our output to null? we are not interested in the program output
@@ -1380,36 +1361,25 @@ open class Executor {
         }
 
 
-        messageLogger.message(log, "Executing $executingMessageParams")
 
         val nativeProcess = try {
             if (sshExecOptions != null) {
-                sshExecOptions!!.startProcess(timeout, timeoutUnit)
+                LogHelper.logAtLowestLevel(logger, "Executing on ${sshExecOptions!!.info()} $executingMessageParams")
+                sshExecOptions!!.startProcess(timeout, timeoutUnit, logger)
             } else {
+                LogHelper.logAtLowestLevel(logger, "Executing $executingMessageParams")
                 builder.start()
             }
-        } catch (e: IOException) {
-            if (e.javaClass === IOException::class.java) {
-                val errorMessage = "Could not execute $executingMessageParams"
-                throw ProcessInitException.newInstance(errorMessage, e) ?: IOException(errorMessage, e)
+        } catch (e: Exception) {
+            val errorMessage = if (sshExecOptions != null) {
+                "Could not execute on ${sshExecOptions!!.info()} $executingMessageParams"
+            } else {
+                "Could not execute $executingMessageParams"
             }
-            throw e
-        } catch (e: RuntimeException) {
-            if (e.javaClass === IllegalArgumentException::class.java) {
-                val errorMessage = "Could not execute $executingMessageParams"
-                throw IllegalArgumentException(errorMessage, e)
-            }
-            throw e
-        }
 
-        val processPid = PidHelper.get(nativeProcess)
-        if (processPid == PidHelper.INVALID) {
-            messageLogger.message(log, "Started process")
-        } else {
-            messageLogger.message(log, "Started process [pid={}]", processPid)
+            throw ProcessInitException.newInstance(errorMessage, e) ?: IOException(errorMessage, e)
         }
 
-
         // we might reassign the streams if they are to be read
         var streams: IOStreamHandler
 
@@ -1471,17 +1441,25 @@ open class Executor {
         // Invoke listeners - changing this executor does not affect the started process any more
         newListeners.afterStart(nativeProcess, this)
 
+        val logger = logger
         val params = Params(processAttributes = attributes,
                             stopper = stopper,
                             listener = newListeners,
                             streams = streams,
-                            messageLogger = messageLogger,
+                            logger = logger,
                             errorMessageHandler = errorMessageHandler,
                             closeTimeout = closeTimeout,
                             closeTimeoutUnit = closeTimeoutUnit,
                             asyncProcessStart = asyncProcessStart)
 
         val deferred = DeferredProcessResult(nativeProcess, params, createProcessResults)
+        val processPid = deferred.pid
+        if (processPid == PidHelper.INVALID) {
+            LogHelper.logAtLowestLevel(logger, "Started process")
+        } else {
+            LogHelper.logAtLowestLevel(logger, "Started process [pid={}]", processPid)
+        }
+
         deferred.start()
 
         return deferred

src/dorkbox/executor/LogHelper.kt

@@ -0,0 +1,336 @@
+/*
+ * Copyright 2021 dorkbox, llc
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * 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.
+ */
+
+@file:Suppress("DuplicatedCode")
+
+package dorkbox.executor
+
+import net.schmizz.sshj.SSHClient
+import net.schmizz.sshj.common.LoggerFactory
+import net.schmizz.sshj.transport.random.JCERandom
+import org.slf4j.Logger
+import org.slf4j.helpers.MarkerIgnoringBase
+
+object LogHelper {
+    fun fixSshLogger(log: Logger?) {
+        try {
+            // exception is thrown if logback is not available.
+            val logger = org.slf4j.LoggerFactory.getLogger(JCERandom::class.java) as ch.qos.logback.classic.Logger
+            if (log == null) {
+                logger.level = ch.qos.logback.classic.Level.ERROR
+                return
+            }
+
+            val orig = log as ch.qos.logback.classic.Logger
+            logger.level = orig.level
+        } catch (e: Exception) {
+        }
+    }
+
+    /**
+     * see http://logback.qos.ch/manual/architecture.html for more info
+     *  logger order goes (from lowest to highest) TRACE->DEBUG->INFO->WARN->ERROR->OFF
+     */
+    fun logAtLowestLevel(log: Logger?, message: String, vararg arguments: Any) {
+        if (log == null) {
+            return
+        }
+
+        when {
+            log.isTraceEnabled -> {
+                log.trace(message, arguments)
+            }
+            log.isDebugEnabled -> {
+                log.debug(message, arguments)
+            }
+            log.isInfoEnabled -> {
+                log.info(message, arguments)
+            }
+            log.isWarnEnabled -> {
+                log.warn(message, arguments)
+            }
+            log.isErrorEnabled -> {
+                log.error(message, arguments)
+            }
+        }
+    }
+
+    fun getLogFactory(logger: Logger?): LoggerFactory {
+        if (logger == null) {
+            return object : LoggerFactory {
+                override fun getLogger(name: String): Logger {
+                    return org.slf4j.helpers.NOPLogger.NOP_LOGGER
+                }
+
+                override fun getLogger(clazz: Class<*>): Logger {
+                    return org.slf4j.helpers.NOPLogger.NOP_LOGGER
+                }
+            }
+        }
+
+        return object : LoggerFactory {
+            override fun getLogger(name: String): Logger {
+                return LogHelperLogger(name)
+            }
+
+            override fun getLogger(clazz: Class<*>): Logger {
+                var name = clazz.name
+                if (name.startsWith(SshExecOptions::class.java.name)) {
+                    name = SSHClient::class.java.name
+                }
+                return LogHelperLogger(name)
+            }
+        }
+    }
+
+
+    /**
+     * A direct implementation of [Logger] that delegates to the lowest possible logger.
+     *
+     * This is NOT to be used for performant critical logs!
+     */
+    open class LogHelperLogger(name: String) : MarkerIgnoringBase() {
+        val logger = org.slf4j.LoggerFactory.getLogger(name)!!
+
+        /**
+         * Always returns the string value "NOP".
+         */
+        override fun getName(): String {
+            return name
+        }
+
+        override fun isTraceEnabled(): Boolean {
+            return true
+        }
+
+        fun log(msg: String) {
+            when {
+                logger.isTraceEnabled -> {
+                    logger.trace(msg)
+                }
+                logger.isDebugEnabled -> {
+                    logger.debug(msg)
+                }
+                logger.isInfoEnabled -> {
+                    logger.info(msg)
+                }
+                logger.isWarnEnabled -> {
+                    logger.warn(msg)
+                }
+                logger.isErrorEnabled -> {
+                    logger.error(msg)
+                }
+            }
+        }
+
+        fun log(format: String, arg: Any) {
+            when {
+                logger.isTraceEnabled -> {
+                    logger.trace(format, arg)
+                }
+                logger.isDebugEnabled -> {
+                    logger.debug(format, arg)
+                }
+                logger.isInfoEnabled -> {
+                    logger.info(format, arg)
+                }
+                logger.isWarnEnabled -> {
+                    logger.warn(format, arg)
+                }
+                logger.isErrorEnabled -> {
+                    logger.error(format, arg)
+                }
+            }
+        }
+
+        fun log(format: String, arg1: Any, arg2: Any) {
+            when {
+                logger.isTraceEnabled -> {
+                    logger.trace(format, arg1, arg2)
+                }
+                logger.isDebugEnabled -> {
+                    logger.debug(format, arg1, arg2)
+                }
+                logger.isInfoEnabled -> {
+                    logger.info(format, arg1, arg2)
+                }
+                logger.isWarnEnabled -> {
+                    logger.warn(format, arg1, arg2)
+                }
+                logger.isErrorEnabled -> {
+                    logger.error(format, arg1, arg2)
+                }
+            }
+        }
+
+        fun log(format: String, vararg argArray: Any) {
+            when {
+                logger.isTraceEnabled -> {
+                    logger.trace(format, argArray)
+                }
+                logger.isDebugEnabled -> {
+                    logger.debug(format, argArray)
+                }
+                logger.isInfoEnabled -> {
+                    logger.info(format, argArray)
+                }
+                logger.isWarnEnabled -> {
+                    logger.warn(format, argArray)
+                }
+                logger.isErrorEnabled -> {
+                    logger.error(format, argArray)
+                }
+            }
+        }
+
+        fun log(msg: String, t: Throwable) {
+            when {
+                logger.isTraceEnabled -> {
+                    logger.trace(msg, t)
+                }
+                logger.isDebugEnabled -> {
+                    logger.debug(msg, t)
+                }
+                logger.isInfoEnabled -> {
+                    logger.info(msg, t)
+                }
+                logger.isWarnEnabled -> {
+                    logger.warn(msg, t)
+                }
+                logger.isErrorEnabled -> {
+                    logger.error(msg, t)
+                }
+            }
+        }
+
+
+        override fun trace(msg: String) {
+            log(msg)
+        }
+
+        override fun trace(format: String, arg: Any) {
+            log(format, arg)
+        }
+
+        override fun trace(format: String, arg1: Any, arg2: Any) {
+            log(format, arg1, arg2)
+        }
+
+        override fun trace(format: String, vararg argArray: Any) {
+            log(format, argArray)
+        }
+
+        override fun trace(msg: String, t: Throwable) {
+            log(msg, t)
+        }
+
+        override fun isDebugEnabled(): Boolean {
+            return true
+        }
+
+        override fun debug(msg: String) {
+            log(msg)
+        }
+
+        override fun debug(format: String, arg: Any) {
+            log(format, arg)
+        }
+
+        override fun debug(format: String, arg1: Any, arg2: Any) {
+            log(format, arg1, arg2)
+        }
+
+        override fun debug(format: String, vararg argArray: Any) {
+            log(format, argArray)
+        }
+
+        override fun debug(msg: String, t: Throwable) {
+            log(msg, t)
+        }
+
+        override fun isInfoEnabled(): Boolean {
+            return true
+        }
+
+        override fun info(msg: String) {
+            log(msg)
+        }
+
+        override fun info(format: String, arg1: Any) {
+            log(format, arg1)
+        }
+
+        override fun info(format: String, arg1: Any, arg2: Any) {
+            log(format, arg1, arg2)
+        }
+
+        override fun info(format: String, vararg argArray: Any) {
+            log(format, argArray)
+        }
+
+        override fun info(msg: String, t: Throwable) {
+            log(msg, t)
+        }
+
+        override fun isWarnEnabled(): Boolean {
+            return true
+        }
+
+        override fun warn(msg: String) {
+            log(msg)
+        }
+
+        override fun warn(format: String, arg1: Any) {
+            log(format, arg1)
+        }
+
+        override fun warn(format: String, arg1: Any, arg2: Any) {
+            log(format, arg1, arg2)
+        }
+
+        override fun warn(format: String, vararg argArray: Any) {
+            log(format, argArray)
+        }
+
+        override fun warn(msg: String, t: Throwable) {
+            log(msg, t)
+        }
+
+        override fun isErrorEnabled(): Boolean {
+            return true
+        }
+
+        override fun error(msg: String) {
+            log(msg)
+        }
+
+        override fun error(format: String, arg1: Any) {
+            log(format, arg1)
+        }
+
+        override fun error(format: String, arg1: Any, arg2: Any) {
+            log(format, arg1, arg2)
+        }
+
+        override fun error(format: String, vararg argArray: Any) {
+            log(format, argArray)
+        }
+
+        override fun error(msg: String, t: Throwable) {
+            log(msg, t)
+        }
+    }
+}

src/dorkbox/executor/MessageLogger.kt

@@ -1,36 +0,0 @@
-/*
- * Copyright 2020 dorkbox, llc
- * Copyright (C) 2014 ZeroTurnaround <support@zeroturnaround.com>
- * Contains fragments of code from Apache Commons Exec, rights owned
- * by Apache Software Foundation (ASF).
- *
- * Licensed under the Apache License, Version 2.0 (the "License");
- * 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 dorkbox.executor
-
-import org.slf4j.Logger
-
-/**
- * Logs messages at certain level.
- */
-interface MessageLogger {
-    /**
-     * Log a message at certain level according to the specified format and arguments.
-     *
-     * @param log logger to be used.
-     * @param format the format string
-     * @param arguments a list of arguments
-     */
-    fun message(log: Logger, format: String, vararg arguments: Any)
-}

src/dorkbox/executor/MessageLoggers.kt

@@ -1,61 +0,0 @@
-/*
- * Copyright 2020 dorkbox, llc
- * Copyright (C) 2014 ZeroTurnaround <support@zeroturnaround.com>
- * Contains fragments of code from Apache Commons Exec, rights owned
- * by Apache Software Foundation (ASF).
- *
- * Licensed under the Apache License, Version 2.0 (the "License");
- * 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 dorkbox.executor
-
-import dorkbox.executor.stream.slf4j.Level
-import org.slf4j.Logger
-
-/**
- * Contains [MessageLogger] instances for various log levels. This is so we can set the logger level FROM
- */
-object MessageLoggers {
-    val NOP = object : MessageLogger {
-        override fun message(log: Logger, format: String, arguments: Array<out Any>) {
-            // do nothing
-        }
-    }
-
-    val TRACE = object : MessageLogger {
-        override fun message(log: Logger, format: String, arguments: Array<out Any>) {
-            log.trace(format, *arguments)
-        }
-    }
-
-    val DEBUG = object : MessageLogger {
-        override fun message(log: Logger, format: String, arguments: Array<out Any>) {
-            log.debug(format, *arguments)
-        }
-    }
-
-    val INFO = object : MessageLogger {
-        override fun message(log: Logger, format: String, arguments: Array<out Any>) {
-            log.info(format, *arguments)
-        }
-    }
-
-    operator fun get(level: Level): MessageLogger {
-        return when (level) {
-            Level.TRACE -> TRACE
-            Level.DEBUG -> DEBUG
-            Level.INFO -> INFO
-            else -> throw IllegalArgumentException("Invalid level $level")
-        }
-    }
-}

src/dorkbox/executor/SshExecOptions.kt

@@ -19,12 +19,16 @@ package dorkbox.executor
 import dorkbox.executor.exceptions.InvalidExitValueException
 import dorkbox.executor.processResults.SyncProcessResult
 import kotlinx.coroutines.runBlocking
+import net.schmizz.sshj.DefaultConfig
 import net.schmizz.sshj.SSHClient
+import net.schmizz.sshj.common.LoggerFactory
 import net.schmizz.sshj.transport.verification.HostKeyVerifier
 import net.schmizz.sshj.transport.verification.PromiscuousVerifier
+import org.slf4j.Logger
 import java.io.File
 import java.io.IOException
-import java.util.concurrent.*
+import java.util.concurrent.TimeUnit
+import java.util.concurrent.TimeoutException
 
 /**
  * see https://github.com/hierynomus/sshj
@@ -45,9 +49,27 @@ class SshExecOptions(val executor: Executor) {
     private var knownHostsFile: String? = null
 
 
-    private val ssh = SSHClient()
+    private lateinit var ssh: SSHClient
+
+    internal fun startProcess(timeout: Long, timeoutUnit: TimeUnit, logger: Logger?): SshProcess {
+        // have to fixup several loggers!
+        LogHelper.fixSshLogger(logger)
+
+        // have to setup the SSH client loggers BEFORE creating it!
+        val factory = LogHelper.getLogFactory(logger)
+        val config = object : DefaultConfig() {
+            override fun setLoggerFactory(loggerFactory: LoggerFactory) {
+                super.setLoggerFactory(factory)
+            }
+            override fun getLoggerFactory(): LoggerFactory {
+                return factory
+            }
+        }
+        config.loggerFactory = factory
+
+        ssh = SSHClient(config)
+
 
-    internal fun startProcess(timeout: Long, timeoutUnit: TimeUnit): SshProcess {
         if (strictHostCheck) {
             if (knownHostsFile != null) {
                 ssh.loadKnownHosts(File(knownHostsFile!!))
@@ -90,7 +112,6 @@ class SshExecOptions(val executor: Executor) {
         return ssh
     }
 
-
     fun userName(userName: String): SshExecOptions {
         this.userName = userName
         return this
@@ -199,6 +220,12 @@ class SshExecOptions(val executor: Executor) {
         return this
     }
 
+    /**
+     * @return information regarding the username + host + port this connect is with
+     */
+    fun info(): String {
+        return "$userName@$host:$port"
+    }
 
     /**
      * Executes the JAVA sub process.