diff --git a/src/dorkbox/executor/DeferredProcessResult.kt b/src/dorkbox/executor/DeferredProcessResult.kt index 264c5e8..66806a0 100644 --- a/src/dorkbox/executor/DeferredProcessResult.kt +++ b/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) } diff --git a/src/dorkbox/executor/Executor.kt b/src/dorkbox/executor/Executor.kt index cca3ee6..d667713 100644 --- a/src/dorkbox/executor/Executor.kt +++ b/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 diff --git a/src/dorkbox/executor/LogHelper.kt b/src/dorkbox/executor/LogHelper.kt new file mode 100644 index 0000000..8ddb8f3 --- /dev/null +++ b/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) + } + } +} diff --git a/src/dorkbox/executor/MessageLogger.kt b/src/dorkbox/executor/MessageLogger.kt deleted file mode 100644 index e4ad1e4..0000000 --- a/src/dorkbox/executor/MessageLogger.kt +++ /dev/null @@ -1,36 +0,0 @@ -/* - * Copyright 2020 dorkbox, llc - * Copyright (C) 2014 ZeroTurnaround - * 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) -} diff --git a/src/dorkbox/executor/MessageLoggers.kt b/src/dorkbox/executor/MessageLoggers.kt deleted file mode 100644 index 138446d..0000000 --- a/src/dorkbox/executor/MessageLoggers.kt +++ /dev/null @@ -1,61 +0,0 @@ -/* - * Copyright 2020 dorkbox, llc - * Copyright (C) 2014 ZeroTurnaround - * 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) { - // do nothing - } - } - - val TRACE = object : MessageLogger { - override fun message(log: Logger, format: String, arguments: Array) { - log.trace(format, *arguments) - } - } - - val DEBUG = object : MessageLogger { - override fun message(log: Logger, format: String, arguments: Array) { - log.debug(format, *arguments) - } - } - - val INFO = object : MessageLogger { - override fun message(log: Logger, format: String, arguments: Array) { - 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") - } - } -} diff --git a/src/dorkbox/executor/SshExecOptions.kt b/src/dorkbox/executor/SshExecOptions.kt index 6c48f91..0c12646 100644 --- a/src/dorkbox/executor/SshExecOptions.kt +++ b/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.