From 80ebee8d1bf09b113ff3a4226ae6c8bf607c62ff Mon Sep 17 00:00:00 2001 From: Kevin Mc Tiernan Date: Fri, 14 Feb 2025 12:28:00 +0100 Subject: [PATCH 1/2] ScheduledTask should set a basic "traceId" by default * Wrapped logic in a try-finally block for scheduledTask execution. Setting the following MDC values before and clearing in the finally block: * traceId * scheduledTaskRunId * scheduledTaskName * scheduledTaskNameClean --- .../scheduledtask/ScheduledTaskRunner.java | 100 ++++++++++++------ 1 file changed, 70 insertions(+), 30 deletions(-) diff --git a/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java b/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java index bec7c26..ec26c8d 100644 --- a/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java +++ b/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java @@ -29,6 +29,7 @@ import java.util.List; import java.util.Map; import java.util.Optional; +import java.util.concurrent.ThreadLocalRandom; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -57,6 +58,11 @@ class ScheduledTaskRunner implements ScheduledTask { private static final int ELIDED_LOG_LINES_ON_MASTER_SLEEP = 8; private static String DEFAULT_LOGGER_NAME = ScheduledTask.class.getName(); + private static final String MDC_TRACE_ID_KEY = "traceId"; + private static final String MDC_TASK_RUN_ID_KEY = "scheduledTaskRunId"; + private static final String MDC_TASK_NAME_KEY = "scheduledTaskName"; + private static final String MDC_TASK_NAME_CLEAN_KEY = "scheduledTaskNameClean"; + private final ScheduledTaskConfig _config; private final ScheduledTaskRegistry _scheduledTaskRegistry; private final ScheduledTaskRepository _scheduledTaskRepository; @@ -328,47 +334,62 @@ private void runTask() { // Update the next run time in the database _scheduledTaskRepository.updateNextRun(getName()); Instant nextRun = nextScheduledRun(getActiveCronExpressionInternal(), Instant.now(_clock)); - log.info("Thread for Task '" + getName() - + "' is beginning to do the run according " - + "to the set schedule '" + getActiveCronExpressionInternal().toString() - + "'. Setting next run to '" + nextRun + "'."); _currentRunStarted = Instant.now(_clock); long id = _scheduledTaskRepository.addScheduleRun(getName(), Host.getLocalHostName(), _currentRunStarted, "Schedule run starting."); ScheduleRunContext ctx = new ScheduledTaskRunnerContext(id, ScheduledTaskRunner.this, Host.getLocalHostName(), _scheduledTaskRepository, _clock, _currentRunStarted); + // :: Set MDC values for log lines. + MDC.put(MDC_TRACE_ID_KEY, "ScheduledTask[" + getNameCleanedAndStripped() + "]rid[" + id + "]" + + generateRandomString()); + MDC.put(MDC_TASK_RUN_ID_KEY, String.valueOf(id)); + MDC.put(MDC_TASK_NAME_KEY, getName()); + MDC.put(MDC_TASK_NAME_CLEAN_KEY, getNameCleanedAndStripped()); - // ?: Is this schedule manually triggered? Ie set to run once. - if (ScheduledTaskRunner.this._runOnce) { - // -> Yes, this where set to run once and is manually triggered. so add a log line. - // note, this is named runNow in the gui but runOnce in the db so we use the term used - // in gui for the logging. - ctx.log("Manually started"); - } - - // :: Try to run the code that the user wants, log if it fails. try { - ScheduleStatus status = _runnable.run(ctx); - if (!(status instanceof ScheduleStatusValidResponse)) { - throw new IllegalArgumentException("The ScheduleRunContext returned a invalid ScheduleStatus," - + " make sure you are using done(), failed() or dispatched()"); + log.info("Thread for Task '" + getName() + + "' is beginning to do the run according " + + "to the set schedule '" + getActiveCronExpressionInternal().toString() + + "'. Setting next run to '" + nextRun + "'."); + // ?: Is this schedule manually triggered? Ie set to run once. + if (ScheduledTaskRunner.this._runOnce) { + // -> Yes, this where set to run once and is manually triggered. so add a log line. + // note, this is named runNow in the gui but runOnce in the db so we use the term used + // in gui for the logging. + ctx.log("Manually started"); + } + + // :: Try to run the code that the user wants, log if it fails. + try { + ScheduleStatus status = _runnable.run(ctx); + if (!(status instanceof ScheduleStatusValidResponse)) { + throw new IllegalArgumentException("The ScheduleRunContext returned a invalid ScheduleStatus," + + " make sure you are using done(), failed() or dispatched()"); + } + } + catch (Throwable t) { + // Oh no, the schedule we set to run failed, we should log this and continue + // on the normal schedule loop + String message = "Schedule '" + getName() + " run failed due to an error.' "; + log.info(message); + ctx.failed(message, t); } + _lastRunCompleted = Instant.now(_clock); + + _isRunning = false; + log.info("Thread for Task '" + getName() + "' " + + " runId '" + ctx.getRunId() + "' " + + "used '" + Duration.between(_currentRunStarted, _lastRunCompleted).toMillis() + "' " + + "ms to run."); } - catch (Throwable t) { - // Oh no, the schedule we set to run failed, we should log this and continue - // on the normal schedule loop - String message = "Schedule '" + getName() + " run failed due to an error.' "; - log.info(message); - ctx.failed(message, t); + finally { + // :: Clear MDC values + MDC.remove(MDC_TRACE_ID_KEY); + MDC.remove(MDC_TASK_RUN_ID_KEY); + MDC.remove(MDC_TASK_NAME_KEY); + MDC.remove(MDC_TASK_NAME_CLEAN_KEY); } - _lastRunCompleted = Instant.now(_clock); - - _isRunning = false; - log.info("Thread for Task '" + getName() + "' " - + " runId '" + ctx.getRunId() + "' " - + "used '" + Duration.between(_currentRunStarted, _lastRunCompleted).toMillis() + "' " - + "ms to run."); } /** @@ -456,6 +477,11 @@ public String getName() { return _config.getName(); } + public String getNameCleanedAndStripped() { + return _config.getName().replace(" ", "_") + .replace(":", "_").strip(); + } + @Override public Criticality getCriticality() { return _config.getCriticality(); @@ -905,4 +931,18 @@ static String throwableToStackTraceString(Throwable throwable) { throwable.printStackTrace(pw); return sw.toString(); } + + private static final String ALPHANUMERIC_CHARACTERS = + "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789"; + /** + * Generate a random string, so our traceId will be unique (enough) for each run of the health check. + */ + private String generateRandomString() { + char[] randomChars = new char[7]; + for (int i = 0; i < randomChars.length; i++) { + randomChars[i] = ALPHANUMERIC_CHARACTERS + .charAt(ThreadLocalRandom.current().nextInt(ALPHANUMERIC_CHARACTERS.length())); + } + return new String(randomChars); + } } From 7a59267da4b303648795e146be5e91a157de0cd4 Mon Sep 17 00:00:00 2001 From: Kevin Mc Tiernan Date: Mon, 17 Feb 2025 09:45:35 +0100 Subject: [PATCH 2/2] Move MDC calls inside the try * MDC calls were outside the try, makes more sense to stick em inside the try should any of these calls fail it now guarantees clean up. --- .../scheduledtask/ScheduledTaskRunner.java | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java b/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java index ec26c8d..41d3cf0 100644 --- a/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java +++ b/scheduledtask-core/src/main/java/com/storebrand/scheduledtask/ScheduledTaskRunner.java @@ -340,14 +340,15 @@ private void runTask() { ScheduleRunContext ctx = new ScheduledTaskRunnerContext(id, ScheduledTaskRunner.this, Host.getLocalHostName(), _scheduledTaskRepository, _clock, _currentRunStarted); - // :: Set MDC values for log lines. - MDC.put(MDC_TRACE_ID_KEY, "ScheduledTask[" + getNameCleanedAndStripped() + "]rid[" + id + "]" - + generateRandomString()); - MDC.put(MDC_TASK_RUN_ID_KEY, String.valueOf(id)); - MDC.put(MDC_TASK_NAME_KEY, getName()); - MDC.put(MDC_TASK_NAME_CLEAN_KEY, getNameCleanedAndStripped()); - try { + // :: Set MDC values for log lines. + MDC.put(MDC_TRACE_ID_KEY, "ScheduledTask[" + getNameCleanedAndStripped() + "]rid[" + id + "]" + + generateRandomString()); + MDC.put(MDC_TASK_RUN_ID_KEY, String.valueOf(id)); + MDC.put(MDC_TASK_NAME_KEY, getName()); + MDC.put(MDC_TASK_NAME_CLEAN_KEY, getNameCleanedAndStripped()); + + // Proceed with the run log.info("Thread for Task '" + getName() + "' is beginning to do the run according " + "to the set schedule '" + getActiveCronExpressionInternal().toString()