Add logs to script execution (#6874)

Co-authored-by: Stephan Krug <stephan.krug@scclouds.com.br>
This commit is contained in:
Stephan Krug 2023-10-31 11:06:00 -03:00 committed by GitHub
parent 235e4fe190
commit 288f066d9f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -205,19 +205,20 @@ public class Script implements Callable<String> {
public String execute(OutputInterpreter interpreter) { public String execute(OutputInterpreter interpreter) {
String[] command = _command.toArray(new String[_command.size()]); String[] command = _command.toArray(new String[_command.size()]);
if (_logger.isDebugEnabled()) { String commandLine = buildCommandLine(command);
_logger.debug("Executing: " + buildCommandLine(command).split(KeyStoreUtils.KS_FILENAME)[0]); _logger.debug(String.format("Executing command [%s].", commandLine.split(KeyStoreUtils.KS_FILENAME)[0]));
}
try { try {
_logger.trace(String.format("Creating process for command [%s].", commandLine));
ProcessBuilder pb = new ProcessBuilder(command); ProcessBuilder pb = new ProcessBuilder(command);
pb.redirectErrorStream(true); pb.redirectErrorStream(true);
if (_workDir != null) if (_workDir != null)
pb.directory(new File(_workDir)); pb.directory(new File(_workDir));
_logger.trace(String.format("Starting process for command [%s].", commandLine));
_process = pb.start(); _process = pb.start();
if (_process == null) { if (_process == null) {
_logger.warn("Unable to execute: " + buildCommandLine(command)); _logger.warn(String.format("Unable to execute command [%s] because no process was created.", commandLine));
return "Unable to execute the command: " + command[0]; return "Unable to execute the command: " + command[0];
} }
@ -226,40 +227,48 @@ public class Script implements Callable<String> {
_thread = Thread.currentThread(); _thread = Thread.currentThread();
ScheduledFuture<String> future = null; ScheduledFuture<String> future = null;
if (_timeout > 0) { if (_timeout > 0) {
_logger.trace(String.format("Scheduling the execution of command [%s] with a timeout of [%s] milliseconds.", commandLine, _timeout));
future = s_executors.schedule(this, _timeout, TimeUnit.MILLISECONDS); future = s_executors.schedule(this, _timeout, TimeUnit.MILLISECONDS);
} }
long processPid = _process.pid();
Task task = null; Task task = null;
if (interpreter != null && interpreter.drain()) { if (interpreter != null && interpreter.drain()) {
_logger.trace(String.format("Executing interpreting task of process [%s] for command [%s].", processPid, commandLine));
task = new Task(interpreter, ir); task = new Task(interpreter, ir);
s_executors.execute(task); s_executors.execute(task);
} }
while (true) { while (true) {
_logger.debug("Executing while with timeout : " + _timeout); _logger.trace(String.format("Attempting process [%s] execution for command [%s] with timeout [%s].", processPid, commandLine, _timeout));
try { try {
//process execution completed within timeout period
if (_process.waitFor(_timeout, TimeUnit.MILLISECONDS)) { if (_process.waitFor(_timeout, TimeUnit.MILLISECONDS)) {
//process completed successfully _logger.trace(String.format("Process [%s] execution for command [%s] completed within timeout period [%s].", processPid, commandLine,
_timeout));
if (_process.exitValue() == 0) { if (_process.exitValue() == 0) {
_logger.debug("Execution is successful."); _logger.debug(String.format("Successfully executed process [%s] for command [%s].", processPid, commandLine));
if (interpreter != null) { if (interpreter != null) {
return interpreter.drain() ? task.getResult() : interpreter.interpret(ir); if (interpreter.drain()) {
_logger.trace(String.format("Returning task result of process [%s] for command [%s].", processPid, commandLine));
return task.getResult();
}
_logger.trace(String.format("Returning interpretation of process [%s] for command [%s].", processPid, commandLine));
return interpreter.interpret(ir);
} else { } else {
// null return exitValue apparently // null return exitValue apparently
_logger.trace(String.format("Process [%s] for command [%s] exited with value [%s].", processPid, commandLine,
_process.exitValue()));
return String.valueOf(_process.exitValue()); return String.valueOf(_process.exitValue());
} }
} else { //process failed } else {
_logger.warn(String.format("Execution of process [%s] for command [%s] failed.", processPid, commandLine));
break; break;
} }
} //timeout }
} catch (InterruptedException e) { } catch (InterruptedException e) {
if (!_isTimeOut) { if (!_isTimeOut) {
/* _logger.debug(String.format("Exception [%s] occurred; however, it was not a timeout. Therefore, proceeding with the execution of process [%s] for command "
* This is not timeout, we are interrupted by others, + "[%s].", e.getMessage(), processPid, commandLine), e);
* continue
*/
_logger.debug("We are interrupted but it's not a timeout, just continue");
continue; continue;
} }
} finally { } finally {
@ -269,21 +278,21 @@ public class Script implements Callable<String> {
Thread.interrupted(); Thread.interrupted();
} }
//timeout without completing the process
TimedOutLogger log = new TimedOutLogger(_process); TimedOutLogger log = new TimedOutLogger(_process);
Task timedoutTask = new Task(log, ir); Task timedoutTask = new Task(log, ir);
_logger.trace(String.format("Running timed out task of process [%s] for command [%s].", processPid, commandLine));
timedoutTask.run(); timedoutTask.run();
if (!_passwordCommand) { if (!_passwordCommand) {
_logger.warn("Timed out: " + buildCommandLine(command) + ". Output is: " + timedoutTask.getResult()); _logger.warn(String.format("Process [%s] for command [%s] timed out. Output is [%s].", processPid, commandLine, timedoutTask.getResult()));
} else { } else {
_logger.warn("Timed out: " + buildCommandLine(command)); _logger.warn(String.format("Process [%s] for command [%s] timed out.", processPid, commandLine));
} }
return ERR_TIMEOUT; return ERR_TIMEOUT;
} }
_logger.debug("Exit value is " + _process.exitValue()); _logger.debug(String.format("Exit value of process [%s] for command [%s] is [%s].", processPid, commandLine, _process.exitValue()));
BufferedReader reader = new BufferedReader(new InputStreamReader(_process.getInputStream()), 128); BufferedReader reader = new BufferedReader(new InputStreamReader(_process.getInputStream()), 128);
@ -294,18 +303,19 @@ public class Script implements Callable<String> {
error = String.valueOf(_process.exitValue()); error = String.valueOf(_process.exitValue());
} }
if (_logger.isDebugEnabled()) { _logger.warn(String.format("Process [%s] for command [%s] encountered the error: [%s].", processPid, commandLine, error));
_logger.debug(error);
}
return error; return error;
} catch (SecurityException ex) { } catch (SecurityException ex) {
_logger.warn("Security Exception....not running as root?", ex); _logger.warn(String.format("Exception [%s] occurred. This may be due to an attempt of executing command [%s] as non root.", ex.getMessage(), commandLine),
ex);
return stackTraceAsString(ex); return stackTraceAsString(ex);
} catch (Exception ex) { } catch (Exception ex) {
_logger.warn("Exception: " + buildCommandLine(command), ex); _logger.warn(String.format("Exception [%s] occurred when attempting to run command [%s].", ex.getMessage(), commandLine), ex);
return stackTraceAsString(ex); return stackTraceAsString(ex);
} finally { } finally {
if (_process != null) { if (_process != null) {
_logger.trace(String.format("Destroying process [%s] for command [%s].", _process.pid(), commandLine));
IOUtils.closeQuietly(_process.getErrorStream()); IOUtils.closeQuietly(_process.getErrorStream());
IOUtils.closeQuietly(_process.getOutputStream()); IOUtils.closeQuietly(_process.getOutputStream());
IOUtils.closeQuietly(_process.getInputStream()); IOUtils.closeQuietly(_process.getInputStream());