Improve Taskomatic by removing invalid triggers before start and enha…

…ncing logs

java/code/src/com/redhat/rhn/taskomatic/TaskoJob.java

@@ -177,6 +177,7 @@ private TaskoRun runTask(TaskoSchedule schedule, TaskoTask task, TaskoTemplate t
                         TaskoFactory.save(taskRun);
                         HibernateFactory.commitTransaction();
                         HibernateFactory.closeSession();
+                        log.debug("Tasko run for {} created. Running job...", schedule.getJobLabel());
 
                         doExecute(job, context, taskRun);
 

java/code/src/com/redhat/rhn/taskomatic/TaskoQuartzHelper.java

@@ -20,6 +20,9 @@
 import static org.quartz.TriggerBuilder.newTrigger;
 import static org.quartz.TriggerKey.triggerKey;
 
+import com.redhat.rhn.common.conf.Config;
+import com.redhat.rhn.common.hibernate.HibernateFactory;
+import com.redhat.rhn.frontend.events.TransactionHelper;
 import com.redhat.rhn.taskomatic.core.SchedulerKernel;
 import com.redhat.rhn.taskomatic.domain.TaskoSchedule;
 
@@ -30,6 +33,7 @@
 import org.quartz.SchedulerException;
 import org.quartz.Trigger;
 import org.quartz.TriggerKey;
+import org.quartz.impl.jdbcjobstore.StdJDBCConstants;
 
 import java.time.Instant;
 import java.time.ZoneId;
@@ -42,6 +46,14 @@
  */
 public class TaskoQuartzHelper {
 
+    private static final String QRTZ_PREFIX = Config.get()
+            .getString("org.quartz.jobStore.tablePrefix", StdJDBCConstants.DEFAULT_TABLE_PREFIX);
+    private static final String QRTZ_TRIGGERS = QRTZ_PREFIX.concat("TRIGGERS");
+    private static final String QRTZ_SIMPLE_TRIGGERS = QRTZ_PREFIX.concat("SIMPLE_TRIGGERS");
+    private static final String QRTZ_CRON_TRIGGERS = QRTZ_PREFIX.concat("CRON_TRIGGERS");
+    private static final String QRTZ_SIMPROP_TRIGGERS = QRTZ_PREFIX.concat("SIMPROP_TRIGGERS");
+    private static final String QRTZ_BLOB_TRIGGERS = QRTZ_PREFIX.concat("BLOB_TRIGGERS");
+
     private static Logger log = LogManager.getLogger(TaskoQuartzHelper.class);
 
     private static final DateTimeFormatter TIMESTAMP_FORMAT = DateTimeFormatter.ofPattern("yyyyMMddHHmmss")
@@ -210,4 +222,35 @@ public static boolean isValidCronExpression(String cronExpression) {
         }
         return true;
     }
+
+    /**
+     * This method is responsible for detecting and removing invalid triggers from the Quartz database.
+     * In some cases, the Quartz database can become inconsistent, with records in the main QRTZ_TRIGGERS table lacking
+     * corresponding entries in any of the possible detail property tables (QRTZ_CRON_TRIGGERS, QRTZ_SIMPLE_TRIGGERS,
+     * QRTZ_BLOB_TRIGGERS or QRTZ_SIMPROP_TRIGGERS). See: bsc#1202519, bsc#1208635 and
+     * https://github.com/uyuni-project/uyuni/issues/5556
+     *
+     * While the exact scenarios leading to this inconsistency may not be clear, this method provides a solution to
+     * prevent Taskomatic from failing to start, performing a cleanup of invalid triggers before starting the scheduler
+     */
+    public static void cleanInvalidTriggers() {
+        log.info("Checking quartz database consistency...");
+        TransactionHelper.handlingTransaction(
+            () -> {
+                int del = HibernateFactory.getSession().createNativeQuery(cleanInvalidTriggersQuery()).executeUpdate();
+                log.info("Removed {} invalid triggers", del);
+            },
+            e -> log.warn("Error removing invalid triggers.", e)
+        );
+    }
+
+    private static String cleanInvalidTriggersQuery() {
+        return "DELETE FROM " + QRTZ_TRIGGERS + " T " +
+            "WHERE T.SCHED_NAME || T.TRIGGER_NAME || T.TRIGGER_GROUP NOT IN (" +
+                "SELECT c.SCHED_NAME || c.TRIGGER_NAME || c.TRIGGER_GROUP FROM " + QRTZ_CRON_TRIGGERS + " c UNION " +
+                "SELECT s.SCHED_NAME || s.TRIGGER_NAME || s.TRIGGER_GROUP FROM " + QRTZ_SIMPLE_TRIGGERS + " s UNION " +
+                "SELECT b.SCHED_NAME || b.TRIGGER_NAME || b.TRIGGER_GROUP FROM " + QRTZ_BLOB_TRIGGERS + " b UNION " +
+                "SELECT sp.SCHED_NAME || sp.TRIGGER_NAME || sp.TRIGGER_GROUP FROM " + QRTZ_SIMPROP_TRIGGERS + " sp" +
+            ")";
+   }
 }

java/code/src/com/redhat/rhn/taskomatic/TaskoXmlRpcHandler.java

@@ -317,6 +317,8 @@ public Date scheduleSingleBunchRun(Integer orgId, String bunchName, String jobLa
         TaskoSchedule schedule = new TaskoSchedule(orgId, bunch, jobLabel, params, start, null, null);
         TaskoFactory.save(schedule);
         HibernateFactory.commitTransaction();
+        log.info("Schedule created for {}. Creating quartz Job...", jobLabel);
+
         // create job
         try {
             return TaskoQuartzHelper.createJob(schedule);
@@ -325,6 +327,7 @@ public Date scheduleSingleBunchRun(Integer orgId, String bunchName, String jobLa
             log.error("Unable to create job {}", schedule.getJobLabel(), e);
             TaskoFactory.delete(schedule);
             HibernateFactory.commitTransaction();
+            log.debug("Schedule removed.");
             throw e;
         }
     }

java/code/src/com/redhat/rhn/taskomatic/TaskomaticApi.java

@@ -609,14 +609,19 @@ public void scheduleActionExecution(Action action, boolean forcePackageListRefre
     public void scheduleMinionActionExecutions(List<Action> actions, boolean forcePackageListRefresh)
             throws TaskomaticApiException {
         List<Map<String, String>> paramsList = new ArrayList<>();
+        List<String> ids = new ArrayList<>();
         for (Action action: actions) {
             Map<String, String> params = new HashMap<>();
-            params.put("action_id", Long.toString(action.getId()));
+            String id = Long.toString(action.getId());
+            params.put("action_id", id);
             params.put("force_pkg_list_refresh", Boolean.toString(forcePackageListRefresh));
             params.put("earliest_action", action.getEarliestAction().toInstant().toString());
             paramsList.add(params);
+            ids.add(id);
         }
+        LOG.debug("Scheduling actions: {}.", ids);
         invoke("tasko.scheduleRuns", MINION_ACTION_BUNCH_LABEL, MINION_ACTION_JOB_PREFIX, paramsList);
+        LOG.debug("Actions scheduled: {}.", ids);
     }
 
     /**

java/code/src/com/redhat/rhn/taskomatic/core/SchedulerKernel.java

@@ -135,6 +135,7 @@ public void startup() throws TaskomaticException {
         MessageQueue.startMessaging();
         MessageQueue.configureDefaultActions(GlobalInstanceHolder.SALT_API);
         try {
+            TaskoQuartzHelper.cleanInvalidTriggers();
             SchedulerKernel.scheduler.start();
             initializeAllSatSchedules();
             synchronized (this.shutdownLock) {

java/code/src/com/redhat/rhn/taskomatic/task/MinionActionExecutor.java

@@ -85,15 +85,15 @@ public String getConfigNamespace() {
      */
     @Override
     public void execute(JobExecutionContext context) {
+        long actionId = context.getJobDetail().getJobDataMap().getLongValueFromString("action_id");
+
         if (log.isDebugEnabled()) {
-            log.debug("Start minion action executor");
+            log.debug("Start minion action executor for action {}", actionId);
         }
 
         // Measure time to calculate the total duration
         long start = System.currentTimeMillis();
         boolean forcePackageListRefresh = false;
-        long actionId = context.getJobDetail()
-                .getJobDataMap().getLongValueFromString("action_id");
         User user = Optional.ofNullable(context.getJobDetail().getJobDataMap().get("user_id"))
                 .map(id -> Long.parseLong(id.toString()))
                 .map(UserFactory::lookupById)
@@ -113,6 +113,10 @@ public void execute(JobExecutionContext context) {
 
         Action action = ActionFactory.lookupById(actionId);
 
+        if (log.isDebugEnabled()) {
+            log.debug("Number of Queued Server Actions for {}: {}", actionId, countQueuedServerActions(action));
+        }
+
         // HACK: it is possible that this Taskomatic task triggered before the corresponding Action was really
         // COMMITted in the database. Wait for some minutes checking if it appears
         int waitedTime = 0;

java/code/src/com/suse/manager/utils/SaltUtils.java

@@ -550,6 +550,7 @@ public void updateServerAction(ServerAction serverAction, long retcode,
 
         // Determine the final status of the action
         if (actionFailed(function, jsonResult, success, retcode)) {
+            LOG.debug("Status of action {} being set to Failed.", serverAction.getParentAction().getId());
             serverAction.setStatus(ActionFactory.STATUS_FAILED);
             // check if the minion is locked (blackout mode)
             String output = getJsonResultWithPrettyPrint(jsonResult);
@@ -708,6 +709,7 @@ else if (action instanceof BaseVirtualizationPoolAction || action instanceof Bas
         else {
            serverAction.setResultMsg(getJsonResultWithPrettyPrint(jsonResult));
         }
+        LOG.debug("Finished update server action for action {}", action.getId());
     }
 
     private void handleStateApplyData(ServerAction serverAction, JsonElement jsonResult, long retcode,

java/code/src/com/suse/manager/webui/services/SaltServerActionService.java

@@ -542,7 +542,14 @@ private void executeForRegularMinions(Action actionIn, boolean forcePackageListR
                 targetMinions = entry.getValue();
             }
 
+            LOG.debug("Executing action {} for {} minions.", actionIn.getId(), targetMinions.size());
             results = execute(actionIn, call, targetMinions, forcePackageListRefresh, isStagingJob);
+            LOG.debug(
+                "Finished action {}. Picked up for {} minions and failed for {} minions.",
+                actionIn.getId(),
+                results.get(true).size(),
+                results.get(false).size()
+            );
 
             if (!isStagingJob) {
                 List<Long> succeededServerIds = results.get(true).stream()

java/spacewalk-java.changes.welder.improve-taskomatic

@@ -0,0 +1 @@
+- Improve Taskomatic by removing invalid triggers before starting and enhancing logs

schema/spacewalk/postgres/quartz/tables/qrtz.sql

@@ -68,6 +68,27 @@ CREATE TABLE qrtz_cron_triggers
 	REFERENCES QRTZ_TRIGGERS(SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP)
 );
 
+CREATE TABLE qrtz_simprop_triggers
+ (
+    SCHED_NAME VARCHAR(120) NOT NULL,
+    TRIGGER_NAME VARCHAR(200) NOT NULL,
+    TRIGGER_GROUP VARCHAR(200) NOT NULL,
+    STR_PROP_1 VARCHAR(512) NULL,
+    STR_PROP_2 VARCHAR(512) NULL,
+    STR_PROP_3 VARCHAR(512) NULL,
+    INT_PROP_1 INT NULL,
+    INT_PROP_2 INT NULL,
+    LONG_PROP_1 BIGINT NULL,
+    LONG_PROP_2 BIGINT NULL,
+    DEC_PROP_1 NUMERIC(13,4) NULL,
+    DEC_PROP_2 NUMERIC(13,4) NULL,
+    BOOL_PROP_1 BOOL NULL,
+    BOOL_PROP_2 BOOL NULL,
+    PRIMARY KEY (SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP),
+    FOREIGN KEY (SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP)
+    REFERENCES QRTZ_TRIGGERS(SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP)
+);
+
 CREATE TABLE qrtz_blob_triggers
   (
     TRIGGER_NAME VARCHAR(200) NOT NULL,

schema/spacewalk/upgrade/susemanager-schema-4.4.7-to-susemanager-schema-4.4.8/001-add-qrtz-missing-table.sql

@@ -0,0 +1,24 @@
+--
+-- add missing simprop_triggers table
+-- it was part of 00_0100-quartz-schema-upgrade.sql but was missing in qrtz.sql
+--
+CREATE TABLE IF NOT EXISTS qrtz_simprop_triggers
+ (
+    SCHED_NAME VARCHAR(120) NOT NULL,
+    TRIGGER_NAME VARCHAR(200) NOT NULL,
+    TRIGGER_GROUP VARCHAR(200) NOT NULL,
+    STR_PROP_1 VARCHAR(512) NULL,
+    STR_PROP_2 VARCHAR(512) NULL,
+    STR_PROP_3 VARCHAR(512) NULL,
+    INT_PROP_1 INT NULL,
+    INT_PROP_2 INT NULL,
+    LONG_PROP_1 BIGINT NULL,
+    LONG_PROP_2 BIGINT NULL,
+    DEC_PROP_1 NUMERIC(13,4) NULL,
+    DEC_PROP_2 NUMERIC(13,4) NULL,
+    BOOL_PROP_1 BOOL NULL,
+    BOOL_PROP_2 BOOL NULL,
+    PRIMARY KEY (SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP),
+    FOREIGN KEY (SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP)
+    REFERENCES QRTZ_TRIGGERS(SCHED_NAME,TRIGGER_NAME,TRIGGER_GROUP)
+);