Refactor logging in Script class to simplify handling of sensitive arguments

This commit is contained in:
chenyoulong20g@ict.ac.cn 2025-11-11 18:09:20 +08:00
parent 5bae18270e
commit d15379b729
1 changed files with 52 additions and 164 deletions

View File

@ -247,16 +247,12 @@ public class Script implements Callable<String> {
public String execute(OutputInterpreter interpreter) {
String[] command = _command.toArray(new String[_command.size()]);
String commandLine = buildCommandLine(command);
if (_logger.isDebugEnabled() && !avoidLoggingCommand && sensitiveArgIndices.isEmpty()) {
if (_logger.isDebugEnabled() && !avoidLoggingCommand) {
_logger.debug(String.format("Executing command [%s].", commandLine.split(KeyStoreUtils.KS_FILENAME)[0]));
}
try {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format("Creating process for command [%s].", commandLine));
} else {
_logger.trace("Creating process for command with sensitive arguments.");
}
_logger.trace(String.format("Creating process for command [%s].", commandLine));
ProcessBuilder pb = new ProcessBuilder(command);
pb.redirectErrorStream(true);
if (_workDir != null)
@ -274,126 +270,62 @@ public class Script implements Callable<String> {
_thread = Thread.currentThread();
ScheduledFuture<String> future = null;
if (_timeout > 0) {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format(
"Scheduling the execution of command [%s] with a timeout of [%s] milliseconds.",
commandLine, _timeout));
} else {
_logger.trace(String.format(
"Scheduling the execution of command with sensitive arguments with a timeout of [%s] milliseconds.",
_timeout));
}
_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);
}
long processPid = _process.pid();
Task task = null;
if (interpreter != null && interpreter.drain()) {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format("Executing interpreting task of process [%s] for command [%s].",
processPid, commandLine));
} else {
_logger.trace(String.format(
"Executing interpreting task of process [%s] for command with sensitive arguments.",
processPid));
}
_logger.trace(String.format("Executing interpreting task of process [%s] for command [%s].",
processPid, commandLine));
task = new Task(interpreter, ir);
s_executors.execute(task);
}
while (true) {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format("Attempting process [%s] execution for command [%s] with timeout [%s].",
processPid, commandLine, _timeout));
} else {
_logger.trace(String.format(
"Attempting process [%s] execution for command with sensitive arguments with timeout [%s].",
processPid, _timeout));
}
_logger.trace(String.format("Attempting process [%s] execution for command [%s] with timeout [%s].",
processPid, commandLine, _timeout));
try {
if (_process.waitFor(_timeout, TimeUnit.MILLISECONDS)) {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format(
"Process [%s] execution for command [%s] completed within timeout period [%s].",
processPid, commandLine,
_timeout));
} else {
_logger.trace(String.format(
"Process [%s] execution for command with sensitive arguments completed within timeout period [%s].",
processPid,
_timeout));
}
_logger.trace(String.format(
"Process [%s] execution for command [%s] completed within timeout period [%s].",
processPid, commandLine,
_timeout));
if (_process.exitValue() == 0) {
if (sensitiveArgIndices.isEmpty()) {
_logger.debug(String.format("Successfully executed process [%s] for command [%s].",
processPid, commandLine));
} else {
_logger.debug(String.format(
"Successfully executed process [%s] for command with sensitive arguments.",
processPid));
}
_logger.debug(String.format("Successfully executed process [%s] for command [%s].",
processPid, commandLine));
if (interpreter != null) {
if (interpreter.drain()) {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(
String.format("Returning task result of process [%s] for command [%s].",
processPid, commandLine));
} else {
_logger.trace(String.format(
"Returning task result of process [%s] for command with sensitive arguments.",
processPid));
}
_logger.trace(
String.format("Returning task result of process [%s] for command [%s].",
processPid, commandLine));
return task.getResult();
}
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(
String.format("Returning interpretation of process [%s] for command [%s].",
processPid, commandLine));
} else {
_logger.trace(String.format(
"Returning interpretation of process [%s] for command with sensitive arguments.",
processPid));
}
_logger.trace(
String.format("Returning interpretation of process [%s] for command [%s].",
processPid, commandLine));
return interpreter.interpret(ir);
} else {
// null return exitValue apparently
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format("Process [%s] for command [%s] exited with value [%s].",
processPid, commandLine,
_process.exitValue()));
} else {
_logger.trace(String.format(
"Process [%s] for command with sensitive arguments exited with value [%s].",
processPid,
_process.exitValue()));
}
_logger.trace(String.format("Process [%s] for command [%s] exited with value [%s].",
processPid, commandLine,
_process.exitValue()));
return String.valueOf(_process.exitValue());
}
} else {
if (sensitiveArgIndices.isEmpty()) {
_logger.warn(String.format("Execution of process [%s] for command [%s] failed.",
processPid, commandLine));
} else {
_logger.warn(String.format(
"Execution of process [%s] for command with sensitive arguments failed.",
processPid));
}
_logger.warn(String.format("Execution of process [%s] for command [%s] failed.",
processPid, commandLine));
break;
}
}
} catch (InterruptedException e) {
if (!_isTimeOut) {
if (sensitiveArgIndices.isEmpty()) {
_logger.debug(String.format(
"Exception [%s] occurred; however, it was not a timeout. Therefore, proceeding with the execution of process [%s] for command "
+ "[%s].",
e.getMessage(), processPid, commandLine), e);
} else {
_logger.debug(String.format(
"Exception [%s] occurred; however, it was not a timeout. Therefore, proceeding with the execution of process [%s] for command "
+ "with sensitive arguments.",
e.getMessage(), processPid), e);
}
_logger.debug(String.format(
"Exception [%s] occurred; however, it was not a timeout. Therefore, proceeding with the execution of process [%s] for command [%s].",
e.getMessage(), processPid, commandLine), e);
continue;
}
} finally {
@ -406,33 +338,21 @@ public class Script implements Callable<String> {
TimedOutLogger log = new TimedOutLogger(_process);
Task timedoutTask = new Task(log, ir);
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(String.format("Running timed out task of process [%s] for command [%s].", processPid,
commandLine));
} else {
_logger.trace(String.format(
"Running timed out task of process [%s] for command with sensitive arguments.",
processPid));
}
_logger.trace(String.format("Running timed out task of process [%s] for command [%s].", processPid,
commandLine));
timedoutTask.run();
if (!_passwordCommand && sensitiveArgIndices.isEmpty()) {
if (_passwordCommand) {
_logger.warn(String.format("Process [%s] for command [%s] timed out.", processPid, commandLine));
} else {
_logger.warn(String.format("Process [%s] for command [%s] timed out. Output is [%s].", processPid,
commandLine, timedoutTask.getResult()));
} else {
_logger.warn(
String.format("Process [%s] for command with sensitive arguments timed out.", processPid));
}
return ERR_TIMEOUT;
}
if (sensitiveArgIndices.isEmpty()) {
_logger.debug(String.format("Exit value of process [%s] for command [%s] is [%s].", processPid,
commandLine, _process.exitValue()));
} else {
_logger.debug(String.format("Exit value of process [%s] for command with sensitive arguments is [%s].",
processPid, _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);
@ -443,49 +363,24 @@ public class Script implements Callable<String> {
error = String.valueOf(_process.exitValue());
}
if (sensitiveArgIndices.isEmpty()) {
_logger.warn(String.format("Process [%s] for command [%s] encountered the error: [%s].", processPid,
commandLine, error));
} else {
_logger.warn(
String.format("Process [%s] for command with sensitive arguments encountered the error: [%s].",
processPid, error));
}
_logger.warn(String.format("Process [%s] for command [%s] encountered the error: [%s].", processPid,
commandLine, error));
return error;
} catch (SecurityException ex) {
if (sensitiveArgIndices.isEmpty()) {
_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);
} else {
_logger.warn(String.format(
"Exception [%s] occurred. This may be due to an attempt of executing command with sensitive data as non root.",
ex.getMessage()),
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);
} catch (Exception ex) {
if (sensitiveArgIndices.isEmpty()) {
_logger.warn(String.format("Exception [%s] occurred when attempting to run command [%s].",
ex.getMessage(), commandLine), ex);
} else {
_logger.warn(
String.format("Exception [%s] occurred when attempting to run a command with sensitive data.",
ex.getMessage()),
ex);
}
_logger.warn(String.format("Exception [%s] occurred when attempting to run command [%s].",
ex.getMessage(), commandLine), ex);
return stackTraceAsString(ex);
} finally {
if (_process != null) {
if (sensitiveArgIndices.isEmpty()) {
_logger.trace(
String.format("Destroying process [%s] for command [%s].", _process.pid(), commandLine));
} else {
_logger.trace(String.format("Destroying process [%s] for a command with sensitive data.",
_process.pid()));
}
_logger.trace(
String.format("Destroying process [%s] for command [%s].", _process.pid(), commandLine));
IOUtils.closeQuietly(_process.getErrorStream());
IOUtils.closeQuietly(_process.getOutputStream());
IOUtils.closeQuietly(_process.getInputStream());
@ -496,10 +391,11 @@ public class Script implements Callable<String> {
public String executeIgnoreExitValue(OutputInterpreter interpreter, int exitValue) {
String[] command = _command.toArray(new String[_command.size()]);
String commandLine = buildCommandLine(command);
if (_logger.isDebugEnabled() && sensitiveArgIndices.isEmpty()) {
if (_logger.isDebugEnabled() && !avoidLoggingCommand) {
_logger.debug(
String.format("Executing: %s", buildCommandLine(command).split(KeyStoreUtils.KS_FILENAME)[0]));
String.format("Executing: %s", commandLine.split(KeyStoreUtils.KS_FILENAME)[0]));
}
try {
@ -510,7 +406,7 @@ public class Script implements Callable<String> {
_process = pb.start();
if (_process == null) {
_logger.warn(String.format("Unable to execute: %s", buildCommandLine(command)));
_logger.warn(String.format("Unable to execute: %s", commandLine));
return String.format("Unable to execute the command: %s", command[0]);
}
@ -574,12 +470,8 @@ public class Script implements Callable<String> {
Task timedoutTask = new Task(log, ir);
timedoutTask.run();
if (!_passwordCommand && sensitiveArgIndices.isEmpty()) {
_logger.warn(String.format("Timed out: %s. Output is: %s", buildCommandLine(command),
_logger.warn(String.format("Timed out: %s. Output is: %s", commandLine,
timedoutTask.getResult()));
} else {
_logger.warn(String.format("Timed out: %s", "command with sensitive data"));
}
return ERR_TIMEOUT;
}
@ -603,11 +495,7 @@ public class Script implements Callable<String> {
_logger.warn("Security Exception....not running as root?", ex);
return stackTraceAsString(ex);
} catch (Exception ex) {
if (sensitiveArgIndices.isEmpty()) {
_logger.warn(String.format("Exception: %s", buildCommandLine(command)), ex);
} else {
_logger.warn("Exception on command with sensitive data.", ex);
}
_logger.warn(String.format("Exception: %s", commandLine), ex);
return stackTraceAsString(ex);
} finally {
if (_process != null) {