diff --git a/changelog.d/4483-job-lifecycle-hooks.added.md b/changelog.d/4483-job-lifecycle-hooks.added.md new file mode 100644 index 0000000000..ea6d1899a3 --- /dev/null +++ b/changelog.d/4483-job-lifecycle-hooks.added.md @@ -0,0 +1 @@ +- Background jobs gained lifecycle hooks. `beforePerform(data)` and `afterPerform(data, result)` run with `perform()`, under its timeout, and a throw from either fails the attempt. `onSuccess(result)` runs once the job is recorded as completed, and `onFailure(error, attempt, isFinal)` after each failed attempt, with `isFinal = true` when the job won't be tried again (including when a crashed worker's last attempt is reaped). Both are best-effort: a throw is logged and never changes the job's outcome. `set(jobsOnFailure = "component.path.method")` adds an app-wide failure hook, called with one struct (`jobId`, `jobClass`, `queue`, `attempt`, `maxRetries`, `isFinal`, `error`) as its `event` argument; job data is never passed to it. `perform()`'s return value is now stored in a new `wheels_jobs.result` column (added automatically): simple values as-is, anything else as JSON, cut short at 4000 bytes with a `...[truncated]` marker. ([#4483](https://github.com/wheels-dev/wheels/issues/4483)) diff --git a/vendor/wheels/Job.cfc b/vendor/wheels/Job.cfc index b2a5344b24..aa3e6db254 100644 --- a/vendor/wheels/Job.cfc +++ b/vendor/wheels/Job.cfc @@ -796,6 +796,8 @@ component { // The retry/fail UPDATEs run inside a catch, where a local. write doesn't survive on // BoxLang, so a fenced outcome there is carried out through this struct. var fence = {lost = false}; + // The failure the hooks report, filled in by the same catch (so not through local.). + var failure = {recorded = false, isFinal = false, attempt = 0, type = "", message = "", detail = ""}; // Each claim writes a fresh token; this attempt may only complete, retry or fail the // job while the row still carries it (a reaped-and-re-claimed row carries another). @@ -845,23 +847,13 @@ component { // Backoff settings for retry scheduling. Defaults come from this processing // instance; overridden from the failing job's own class once it instantiates, // mirroring JobWorker.$scheduleRetry so both paths share one retry schedule. - local.backoffBaseDelay = this.baseDelay; - local.backoffMaxDelay = this.maxDelay; - local.backoffRetryBackoff = this.retryBackoff; + local.backoff = $backoffSettings(this); try { // Instantiate and execute the job local.jobInstance = $instantiateJobClass(jobClass = arguments.jobRow.jobClass, jobId = arguments.jobRow.id); local.jobInstance.$setClaimContext(jobId = arguments.jobRow.id, claimToken = local.claimToken); - if (StructKeyExists(local.jobInstance, "baseDelay")) { - local.backoffBaseDelay = local.jobInstance.baseDelay; - } - if (StructKeyExists(local.jobInstance, "maxDelay")) { - local.backoffMaxDelay = local.jobInstance.maxDelay; - } - if (StructKeyExists(local.jobInstance, "retryBackoff")) { - local.backoffRetryBackoff = local.jobInstance.retryBackoff; - } + local.backoff = $backoffSettings(local.jobInstance); local.jobData = DeserializeJSON(arguments.jobRow.data); // Restore tenant context if the job was enqueued within a tenant scope and @@ -879,17 +871,8 @@ component { ); if (local.performOutcome.busy) { // Another run holds the job's lease: wait for it without using up an attempt. - $deferJobForLease( - jobId = arguments.jobRow.id, - jobClass = arguments.jobRow.jobClass, - claimToken = local.claimToken, - delaySeconds = local.performOutcome.retryInSeconds, - leaseName = local.performOutcome.leaseName - ); + $deferBusyRun(jobRow = arguments.jobRow, claimToken = local.claimToken, performOutcome = local.performOutcome, clearTenant = local.hasTenantContext); local.result.skipped = true; - if (local.hasTenantContext) { - $clearTenantContext(); - } return local.result; } local.result.leaseLost = local.performOutcome.leaseLost; @@ -897,6 +880,8 @@ component { throw(type = "Wheels.JobTimeout", message = local.performOutcome.error); } if (!local.performOutcome.success) { + failure.type = local.performOutcome.errorType; + failure.detail = local.performOutcome.errorDetail; throw(type = "Wheels.JobFailed", message = local.performOutcome.error); } @@ -907,9 +892,10 @@ component { id = {value = arguments.jobRow.id, cfsqltype = "cf_sql_varchar"} }; local.doneGuard = $claimTokenGuard(claimToken = local.claimToken, params = local.doneParams); + local.resultSet = $resultAssignment(performOutcome = local.performOutcome, params = local.doneParams); queryExecute( "UPDATE wheels_jobs - SET status = 'completed', completedAt = :completedAt, updatedAt = :updatedAt + SET status = 'completed', completedAt = :completedAt, updatedAt = :updatedAt" & local.resultSet & " WHERE id = :id AND status = 'processing'" & local.doneGuard, local.doneParams, {datasource = variables.$datasource, result = "local.doneResult"} @@ -926,12 +912,23 @@ component { file = "wheels_jobs" ); local.result.success = true; + $fireJobSuccess( + jobInstance = local.jobInstance, + performOutcome = local.performOutcome, + jobId = arguments.jobRow.id, + jobClass = arguments.jobRow.jobClass + ); } } catch (any e) { // Determine retry eligibility local.currentAttempts = Val(arguments.jobRow.attempts) + 1; local.maxRetries = Val(arguments.jobRow.maxRetries); + failure.attempt = local.currentAttempts; + failure.message = e.message; + if (!Len(failure.type)) { + failure.type = e.type; + } if (local.currentAttempts <= local.maxRetries) { // Schedule retry with configurable exponential backoff, capped at maxDelay. @@ -939,9 +936,9 @@ component { // overrides apply (the base instance defaults are only the fallback). local.backoffSeconds = $backoffDelay( attempts = local.currentAttempts, - baseDelay = local.backoffBaseDelay, - maxDelay = local.backoffMaxDelay, - retryBackoff = local.backoffRetryBackoff + baseDelay = local.backoff.baseDelay, + maxDelay = local.backoff.maxDelay, + retryBackoff = local.backoff.retryBackoff ); local.nextRunAt = DateAdd("s", local.backoffSeconds, $now()); @@ -967,6 +964,8 @@ component { if (Len(local.claimToken) && Val(local.retryResult.recordCount ?: 0) == 0) { fence.lost = true; $logFencedAttempt(jobId = arguments.jobRow.id, jobClass = arguments.jobRow.jobClass, outcome = "failed, retry"); + } else { + failure.recorded = true; } writeLog( @@ -996,6 +995,9 @@ component { if (Len(local.claimToken) && Val(local.failResult.recordCount ?: 0) == 0) { fence.lost = true; $logFencedAttempt(jobId = arguments.jobRow.id, jobClass = arguments.jobRow.jobClass, outcome = "failed"); + } else { + failure.recorded = true; + failure.isFinal = true; } writeLog( @@ -1011,6 +1013,18 @@ component { if (fence.lost) { local.result.fenced = true; } + if (failure.recorded) { + $fireJobFailure( + jobInstance = StructKeyExists(local, "jobInstance") ? local.jobInstance : "", + jobId = arguments.jobRow.id, + jobClass = arguments.jobRow.jobClass, + queue = StructKeyExists(arguments.jobRow, "queue") ? arguments.jobRow.queue : "", + error = $jobError(type = failure.type, message = failure.message, detail = failure.detail), + attempt = failure.attempt, + maxRetries = Val(arguments.jobRow.maxRetries), + isFinal = failure.isFinal + ); + } // Clean up tenant context after job execution if (local.hasTenantContext) { @@ -1020,6 +1034,35 @@ component { return local.result; } + /** + * Internal: a job's retry backoff settings (baseDelay, maxDelay, retryBackoff), so a failing + * job's own class overrides apply to its retry schedule. + */ + public struct function $backoffSettings(required any jobInstance) { + return { + baseDelay = StructKeyExists(arguments.jobInstance, "baseDelay") ? arguments.jobInstance.baseDelay : this.baseDelay, + maxDelay = StructKeyExists(arguments.jobInstance, "maxDelay") ? arguments.jobInstance.maxDelay : this.maxDelay, + retryBackoff = StructKeyExists(arguments.jobInstance, "retryBackoff") ? arguments.jobInstance.retryBackoff : this.retryBackoff + }; + } + + /** + * Internal: puts back a run whose lease another run holds ($deferJobForLease), and clears the + * tenant context it restored, since perform() never ran. + */ + public void function $deferBusyRun(required struct jobRow, required string claimToken, required struct performOutcome, required boolean clearTenant) { + $deferJobForLease( + jobId = arguments.jobRow.id, + jobClass = arguments.jobRow.jobClass, + claimToken = arguments.claimToken, + delaySeconds = arguments.performOutcome.retryInSeconds, + leaseName = arguments.performOutcome.leaseName + ); + if (arguments.clearTenant) { + $clearTenantContext(); + } + } + /** * Restore tenant context from job data when the job was enqueued within a tenant * scope, and strip the internal $wheelsTenantContext key from the passed data @@ -1173,6 +1216,7 @@ component { $ensureClaimTokenColumns(); $ensureUniqueKeyColumn(); $ensureHeartbeatColumn(); + $ensureResultColumn(); return true; } catch (any e) { // Table doesn't exist — create it @@ -1218,6 +1262,7 @@ component { claimedBy #local.varcharType#(128), uniqueKey #local.varcharType#(255), heartbeatAt #local.datetimeType#, + result #$resultColumnType(local.dbType)#, lastError #local.textType#, runAt #local.datetimeType#, completedAt #local.datetimeType#, @@ -1479,6 +1524,225 @@ component { return variables.$claimTokenColumnsPresent; } + /** + * Add the result column (perform()'s return value) to an existing wheels_jobs table. Never + * inside a Wheels transaction (DDL there commits the caller's work on MySQL and Oracle); + * a failed ALTER backs off and logs once, and jobs then run without storing their result. + */ + public void function $ensureResultColumn() { + if (Len($outermostWheelsTransaction())) { + return; + } + if ($jobTableHasColumn("result")) { + $clearClaimTimeoutAlterMemo(memoKey = "$resultAlterFailedAt"); + return; + } + if ($claimTimeoutAlterInBackoff(memoKey = "$resultAlterFailedAt")) { + return; + } + try { + queryExecute($resultAlterSql(), {}, {datasource = variables.$datasource}); + $clearClaimTimeoutAlterMemo(memoKey = "$resultAlterFailedAt"); + } catch (any e) { + $recordClaimTimeoutAlterFailure(memoKey = "$resultAlterFailedAt"); + if (StructKeyExists(application, "wheels") && !StructKeyExists(application.wheels, "$resultAlterWarned")) { + application.wheels.$resultAlterWarned = true; + writeLog( + text = "Could not add the wheels_jobs.result column (#e.message#). Jobs run as before but " + & "their return values aren't stored. Add it manually (result VARCHAR(4000)) to store them.", + type = "warning", + file = "wheels_jobs" + ); + } + } + } + + /** + * Whether this instance can store results. Memoised per instance; the first call also runs + * the column ensure, like $claimTokenColumnsAvailable(). + */ + public boolean function $resultColumnAvailable() { + if (!StructKeyExists(variables, "$resultColumnPresent")) { + try { + $ensureResultColumn(); + variables.$resultColumnPresent = $jobTableHasColumn("result"); + } catch (any e) { + variables.$resultColumnPresent = false; + } + } + return variables.$resultColumnPresent; + } + + /** + * The result column's type: NVARCHAR(4000) on SQL Server, whose VARCHAR silently mangles + * non-ASCII text, and VARCHAR(4000) (VARCHAR2 on Oracle) elsewhere. + */ + public string function $resultColumnType(required string dbType) { + if (arguments.dbType == "sqlserver") { + return "NVARCHAR(4000)"; + } + return (arguments.dbType == "oracle" ? "VARCHAR2" : "VARCHAR") & "(4000)"; + } + + /** + * The per-database "ADD result" DDL. + */ + public string function $resultAlterSql() { + local.dbType = $detectDatabaseType(); + local.definition = "result #$resultColumnType(local.dbType)#"; + if (local.dbType == "oracle") { + return "ALTER TABLE wheels_jobs ADD (#local.definition#)"; + } + if (local.dbType == "sqlserver") { + return "ALTER TABLE wheels_jobs ADD #local.definition#"; + } + return "ALTER TABLE wheels_jobs ADD COLUMN #local.definition#"; + } + + /** + * The completion UPDATE's result assignment and parameter: perform()'s return value, or NULL + * when it returned nothing (or the column isn't there, when the fragment is empty). An empty + * string is stored as NULL too: Oracle can't tell the two apart. + */ + public string function $resultAssignment(required struct performOutcome, required struct params) { + if (!$resultColumnAvailable()) { + return ""; + } + // Detected once per instance: this runs on every completion. + if (!StructKeyExists(variables, "$resultDbType")) { + variables.$resultDbType = $detectDatabaseType(); + } + local.dbType = variables.$resultDbType; + local.text = arguments.performOutcome.hasResult ? $serializeJobResult(value = arguments.performOutcome.result, dbType = local.dbType) : ""; + arguments.params.result = { + value = local.text, + cfsqltype = local.dbType == "sqlserver" ? "cf_sql_nvarchar" : "cf_sql_varchar", + null = !Len(local.text) + }; + return ", result = :result"; + } + + /** + * perform()'s return value as stored text: a simple value as-is, anything else as JSON. A value + * over the column's limit is cut short and ends with a visible marker. The limit is what the + * column counts: 4000 characters (UTF-16 code units) for SQL Server's NVARCHAR, and 4000 UTF-8 + * bytes elsewhere (Oracle's VARCHAR2 counts bytes; for the databases that count characters, + * bytes is the safe bound). The trim loop only runs for a value over the limit. + */ + public string function $serializeJobResult(any value, string dbType = "") { + if (IsNull(arguments.value)) { + return ""; + } + local.text = IsSimpleValue(arguments.value) ? ToString(arguments.value) : SerializeJSON(arguments.value); + local.limit = 4000; + local.countChars = arguments.dbType == "sqlserver"; + if ($resultSize(local.text, local.countChars) <= local.limit) { + return local.text; + } + local.marker = "...[truncated]"; + local.keep = local.limit - Len(local.marker); + local.text = Left(local.text, local.keep); + while (Len(local.text) > 0 && $resultSize(local.text, local.countChars) > local.keep) { + local.text = Left(local.text, Len(local.text) - 1); + } + return local.text & local.marker; + } + + /** + * Internal: a text's size as a result column counts it, in characters or UTF-8 bytes. + */ + public numeric function $resultSize(required string text, required boolean countChars) { + return arguments.countChars ? Len(arguments.text) : Len(CharsetDecode(arguments.text, "utf-8")); + } + + /** + * Calls the job's onSuccess(result) after its completion was recorded. Best-effort: a throw + * is logged and never changes the job's outcome. + */ + public void function $fireJobSuccess(required any jobInstance, required struct performOutcome, required string jobId, required string jobClass) { + if (!IsObject(arguments.jobInstance) || !StructKeyExists(arguments.jobInstance, "onSuccess")) { + return; + } + try { + if (arguments.performOutcome.hasResult) { + arguments.jobInstance.onSuccess(arguments.performOutcome.result); + } else { + arguments.jobInstance.onSuccess(); + } + } catch (any e) { + writeLog(text = "Job '#arguments.jobClass#' [#arguments.jobId#] onSuccess() failed: #e.message#", type = "error", file = "wheels_jobs"); + } + } + + /** + * Calls the job's onFailure(error, attempt, isFinal), then the app's jobsOnFailure hook, after a + * failed attempt was recorded. `isFinal` is true when the job won't be tried again. Both are + * best-effort: a throw is logged and never changes the job's outcome. `jobInstance` may be "" + * when the job class couldn't be loaded; the global hook still runs. + */ + public void function $fireJobFailure( + required any jobInstance, + required string jobId, + required string jobClass, + required string queue, + required struct error, + required numeric attempt, + required numeric maxRetries, + required boolean isFinal + ) { + if (IsObject(arguments.jobInstance) && StructKeyExists(arguments.jobInstance, "onFailure")) { + try { + // Positional, so the hook may name its parameters freely (`final` itself isn't a + // valid parameter name on Adobe CF). + arguments.jobInstance.onFailure(arguments.error, arguments.attempt, arguments.isFinal); + } catch (any e) { + writeLog(text = "Job '#arguments.jobClass#' [#arguments.jobId#] onFailure() failed: #e.message#", type = "error", file = "wheels_jobs"); + } + } + local.event = {}; + local.event["jobId"] = arguments.jobId; + local.event["jobClass"] = arguments.jobClass; + local.event["queue"] = arguments.queue; + local.event["attempt"] = arguments.attempt; + local.event["maxRetries"] = arguments.maxRetries; + local.event["isFinal"] = arguments.isFinal; + local.event["error"] = arguments.error; + $callJobsOnFailure(local.event); + } + + /** + * Calls the app's global failure hook, set(jobsOnFailure = "component.path.method"), with one + * struct describing the failure ({jobId, jobClass, queue, attempt, maxRetries, isFinal, error}) (no job data: it can hold secrets). The method receives it as + * its `event` argument. Best-effort; a hook that can't be called is logged once per app. + */ + public void function $callJobsOnFailure(required struct event) { + if (!StructKeyExists(application, "wheels") || !StructKeyExists(application.wheels, "jobsOnFailure")) { + return; + } + local.target = Trim(application.wheels.jobsOnFailure); + if (ListLen(local.target, ".") < 2) { + return; + } + local.method = ListLast(local.target, "."); + local.path = Left(local.target, Len(local.target) - Len(local.method) - 1); + try { + local.hook = CreateObject("component", local.path); + Invoke(local.hook, local.method, {event = arguments.event}); + } catch (any e) { + if (!StructKeyExists(application.wheels, "$jobsOnFailureWarned")) { + application.wheels.$jobsOnFailureWarned = true; + writeLog(text = "The jobsOnFailure hook '#local.target#' failed: #e.message#", type = "error", file = "wheels_jobs"); + } + } + } + + /** + * The error struct the failure hooks receive. + */ + public struct function $jobError(string type = "", string message = "", string detail = "") { + return {type = Len(arguments.type) ? arguments.type : "Wheels.JobFailed", message = arguments.message, detail = arguments.detail}; + } + /** * A fresh, unique token for one claim of one job. */ @@ -2207,7 +2471,7 @@ component { required struct jobData, required numeric timeoutSeconds ) { - local.rv = {success = false, error = "", timedOut = false}; + local.rv = {success = false, error = "", timedOut = false, hasResult = false, result = "", errorType = "", errorDetail = ""}; local.timeoutMs = Max(1, Int(arguments.timeoutSeconds)) * 1000; local.threadName = "wheelsJob" & Replace(CreateUUID(), "-", "", "all"); local.box = {instance = arguments.jobInstance, data = arguments.jobData, ok = false, err = ""}; @@ -2215,12 +2479,30 @@ component { try { thread name="#local.threadName#" action="run" box="#local.box#" { try { - attributes.box.instance.perform(data = attributes.box.data); + // beforePerform/afterPerform are part of the work: they run under the same + // timeout, and a throw from either fails the attempt. + if (StructKeyExists(attributes.box.instance, "beforePerform")) { + attributes.box.instance.beforePerform(data = attributes.box.data); + } + performResult = attributes.box.instance.perform(data = attributes.box.data); + thread.hasResult = !IsNull(performResult); + if (thread.hasResult) { + thread.result = performResult; + } + if (StructKeyExists(attributes.box.instance, "afterPerform")) { + if (thread.hasResult) { + attributes.box.instance.afterPerform(data = attributes.box.data, result = performResult); + } else { + attributes.box.instance.afterPerform(data = attributes.box.data); + } + } thread.ok = true; thread.err = ""; } catch (any e) { thread.ok = false; thread.err = e.message; + thread.errType = e.type; + thread.errDetail = e.detail; } } thread action="join" name="#local.threadName#" timeout="#local.timeoutMs#"; @@ -2237,9 +2519,15 @@ component { } if (StructKeyExists(local.meta, "ok") && local.meta.ok) { local.rv.success = true; + if (StructKeyExists(local.meta, "hasResult") && local.meta.hasResult && StructKeyExists(local.meta, "result")) { + local.rv.hasResult = true; + local.rv.result = local.meta.result; + } return local.rv; } local.rv.error = (StructKeyExists(local.meta, "err") && Len(local.meta.err)) ? local.meta.err : "Job failed"; + local.rv.errorType = StructKeyExists(local.meta, "errType") ? local.meta.errType : ""; + local.rv.errorDetail = StructKeyExists(local.meta, "errDetail") ? local.meta.errDetail : ""; return local.rv; } catch (any threadErr) { // Fail closed. Inline perform() would hang until the job finished. diff --git a/vendor/wheels/JobWorker.cfc b/vendor/wheels/JobWorker.cfc index 60ab92e5a0..eb9a7a223e 100644 --- a/vendor/wheels/JobWorker.cfc +++ b/vendor/wheels/JobWorker.cfc @@ -247,32 +247,7 @@ component { } this.jobsFailed++; arguments.result.error = local.processResult.error; - - // Determine retry eligibility - local.currentAttempts = Val(arguments.row.attempts) + 1; - local.maxRetries = Val(arguments.row.maxRetries); - if (local.currentAttempts <= local.maxRetries) { - local.recorded = $scheduleRetry( - jobId = arguments.row.id, - currentAttempts = local.currentAttempts, - jobClass = arguments.row.jobClass, - maxRetries = local.maxRetries, - errorMessage = local.processResult.error, - claimToken = local.jobRow.claimToken - ); - } else { - local.recorded = $markFailed( - jobId = arguments.row.id, - jobClass = arguments.row.jobClass, - maxRetries = local.maxRetries, - errorMessage = local.processResult.error, - claimToken = local.jobRow.claimToken - ); - } - if (Len(local.jobRow.claimToken) && local.recorded == 0) { - $jobBridge().$logFencedAttempt(jobId = arguments.row.id, jobClass = arguments.row.jobClass, outcome = "failed"); - arguments.result.fenced = true; - } + arguments.result.fenced = $recordFailedAttempt(jobRow = local.jobRow, processResult = local.processResult); return arguments.result; } @@ -369,12 +344,22 @@ component { expectedAttempts = local.currentAttempts, staleCutoff = local.rowCutoff ); + // Interrupted is final: it is never run again. + if (local.won > 0) { + $fireReapedFailure( + row = local.row, + message = "Job timed out after #local.rowTimeout# seconds and is not idempotent, so it was not retried" + ); + } } else if (local.currentAttempts <= local.maxRetries) { // Reschedule for retry local.won = $scheduleRetry(local.row.id, local.currentAttempts, local.row.jobClass, local.maxRetries, "Job timed out after #local.rowTimeout# seconds", local.currentAttempts, local.rowCutoff); } else { // Exhausted retries local.won = $markFailed(local.row.id, local.row.jobClass, local.maxRetries, "Job timed out after #local.rowTimeout# seconds (max retries exhausted)", local.currentAttempts, local.rowCutoff); + if (local.won > 0) { + $fireReapedFailure(row = local.row, message = "Job timed out after #local.rowTimeout# seconds (max retries exhausted)"); + } } if (local.won > 0) { local.recovered++; @@ -395,7 +380,7 @@ component { if ($claimTimeoutColumnAvailable()) { try { return queryExecute( - "SELECT id, jobClass, attempts, maxRetries, updatedAt, claimTimeout + "SELECT id, jobClass, queue, attempts, maxRetries, updatedAt, claimTimeout FROM wheels_jobs " & arguments.whereClause, arguments.params, {datasource = variables.$datasource} @@ -405,7 +390,7 @@ component { } } return queryExecute( - "SELECT id, jobClass, attempts, maxRetries, updatedAt + "SELECT id, jobClass, queue, attempts, maxRetries, updatedAt FROM wheels_jobs " & arguments.whereClause, arguments.params, {datasource = variables.$datasource} @@ -821,7 +806,9 @@ component { * Execute a job's perform() method. */ private struct function $executeJob(required struct jobRow, numeric timeout = 300) { - local.result = {success = false, fenced = false, busy = false, retryInSeconds = 0, leaseName = "", leaseLost = false, error = ""}; + local.result = {success = false, fenced = false, busy = false, retryInSeconds = 0, leaseName = "", leaseLost = false, error = "", errorType = "", errorDetail = "", jobInstance = "", tenantPending = false}; + // The failure's type/detail for the hooks, filled in by the catch (so not through local.). + var failure = {type = "", detail = ""}; local.claimToken = StructKeyExists(arguments.jobRow, "claimToken") ? arguments.jobRow.claimToken : ""; // Initialized before the try so the cleanup below never reads an undefined @@ -862,6 +849,7 @@ component { claimTimeout = local.workerCap ); local.result.leaseLost = local.performOutcome.leaseLost; + local.result.jobInstance = local.jobInstance; if (local.performOutcome.busy) { local.result.busy = true; local.result.retryInSeconds = local.performOutcome.retryInSeconds; @@ -875,6 +863,8 @@ component { throw(type = "Wheels.JobTimeout", message = local.performOutcome.error); } if (!local.performOutcome.success) { + failure.type = local.performOutcome.errorType; + failure.detail = local.performOutcome.errorDetail; throw(type = "Wheels.JobFailed", message = local.performOutcome.error); } @@ -887,9 +877,10 @@ component { id = {value = arguments.jobRow.id, cfsqltype = "cf_sql_varchar"} }; local.doneGuard = $jobBridge().$claimTokenGuard(claimToken = local.claimToken, params = local.doneParams); + local.resultSet = $jobBridge().$resultAssignment(performOutcome = local.performOutcome, params = local.doneParams); queryExecute( "UPDATE wheels_jobs - SET status = 'completed', completedAt = :completedAt, updatedAt = :updatedAt + SET status = 'completed', completedAt = :completedAt, updatedAt = :updatedAt" & local.resultSet & " WHERE id = :id AND status = 'processing'" & local.doneGuard, local.doneParams, {datasource = variables.$datasource, result = "local.doneResult"} @@ -906,19 +897,120 @@ component { file = "wheels_jobs" ); local.result.success = true; + $jobBridge().$fireJobSuccess( + jobInstance = local.jobInstance, + performOutcome = local.performOutcome, + jobId = arguments.jobRow.id, + jobClass = arguments.jobRow.jobClass + ); } } catch (any e) { local.result.error = Left(e.message, 1000); + if (!Len(failure.type)) { + failure.type = e.type; + } } + local.result.errorType = failure.type; + local.result.errorDetail = failure.detail; - // Clean up tenant context after job execution + // Clean up tenant context after job execution. A failed attempt keeps it until + // $recordFailedAttempt() has run the failure hooks, which then clears it. if (local.hasTenantContext) { - $jobBridge().$clearTenantContext(); + if (local.result.success || local.result.fenced) { + $jobBridge().$clearTenantContext(); + } else { + local.result.tenantPending = true; + } } return local.result; } + /** + * Records a failed attempt (a retry, or failed when retries are exhausted), then runs the + * failure hooks unless the attempt was fenced, and clears the tenant context the attempt + * kept for them. Returns true when the attempt was fenced. + */ + private boolean function $recordFailedAttempt(required struct jobRow, required struct processResult) { + var outcome = {fenced = false}; + try { + local.currentAttempts = Val(arguments.jobRow.attempts) + 1; + local.maxRetries = Val(arguments.jobRow.maxRetries); + local.isFinal = local.currentAttempts > local.maxRetries; + if (!local.isFinal) { + local.recorded = $scheduleRetry( + jobId = arguments.jobRow.id, + currentAttempts = local.currentAttempts, + jobClass = arguments.jobRow.jobClass, + maxRetries = local.maxRetries, + errorMessage = arguments.processResult.error, + claimToken = arguments.jobRow.claimToken + ); + } else { + local.recorded = $markFailed( + jobId = arguments.jobRow.id, + jobClass = arguments.jobRow.jobClass, + maxRetries = local.maxRetries, + errorMessage = arguments.processResult.error, + claimToken = arguments.jobRow.claimToken + ); + } + if (Len(arguments.jobRow.claimToken) && local.recorded == 0) { + $jobBridge().$logFencedAttempt(jobId = arguments.jobRow.id, jobClass = arguments.jobRow.jobClass, outcome = "failed"); + outcome.fenced = true; + } else { + $jobBridge().$fireJobFailure( + jobInstance = arguments.processResult.jobInstance, + jobId = arguments.jobRow.id, + jobClass = arguments.jobRow.jobClass, + queue = arguments.jobRow.queue, + error = $jobBridge().$jobError( + type = arguments.processResult.errorType, + message = arguments.processResult.error, + detail = arguments.processResult.errorDetail + ), + attempt = local.currentAttempts, + maxRetries = local.maxRetries, + isFinal = local.isFinal + ); + } + } finally { + if (arguments.processResult.tenantPending) { + $jobBridge().$clearTenantContext(); + } + } + return outcome.fenced; + } + + /** + * Runs the failure hooks for a job the reaper just ended for good: marked failed (its worker + * died or ran past its timeout on its last attempt), or interrupted (not idempotent, so never + * re-run). Best-effort and never blocks the reap loop; the job class + * is loaded on this server, and no tenant context is restored (the row's data isn't read). + */ + private void function $fireReapedFailure(required struct row, required string message) { + try { + var instance = ""; + try { + instance = $jobBridge().$instantiateJobClass(jobClass = arguments.row.jobClass); + } catch (any loadError) { + instance = ""; + } + $jobBridge().$fireJobFailure( + jobInstance = instance, + jobId = arguments.row.id, + jobClass = arguments.row.jobClass, + queue = StructKeyExists(arguments.row, "queue") ? arguments.row.queue : "", + error = $jobBridge().$jobError(type = "Wheels.JobTimeout", message = arguments.message), + attempt = Val(arguments.row.attempts), + maxRetries = Val(arguments.row.maxRetries), + isFinal = true + ); + } catch (any e) { + writeLog(text = "Job '#arguments.row.jobClass#' [#arguments.row.id#] failure hooks after the reap failed: #e.message#", type = "error", file = "wheels_jobs"); + } + } + /** * Schedule a failed job for retry with configurable exponential backoff. */ diff --git a/vendor/wheels/tests/_assets/jobs/FailureHookTarget.cfc b/vendor/wheels/tests/_assets/jobs/FailureHookTarget.cfc new file mode 100644 index 0000000000..b192e1de5d --- /dev/null +++ b/vendor/wheels/tests/_assets/jobs/FailureHookTarget.cfc @@ -0,0 +1,15 @@ +/** + * The app-wide failure hook the hook specs point jobsOnFailure at (core-suite fixture). It keeps + * the last event it was called with in the application scope. + */ +component { + + public void function record(required struct event) { + application["$hookSpecGlobal"] = Duplicate(arguments.event); + if (!StructKeyExists(application, "$hookSpecGlobalCount")) { + application["$hookSpecGlobalCount"] = 0; + } + application["$hookSpecGlobalCount"] = application["$hookSpecGlobalCount"] + 1; + } + +} diff --git a/vendor/wheels/tests/_assets/jobs/HookProbeJob.cfc b/vendor/wheels/tests/_assets/jobs/HookProbeJob.cfc new file mode 100644 index 0000000000..e9f45b07e3 --- /dev/null +++ b/vendor/wheels/tests/_assets/jobs/HookProbeJob.cfc @@ -0,0 +1,73 @@ +/** + * A job with every lifecycle hook (core-suite fixture). Each hook appends to a list in the + * application scope so the hook specs can check what ran, in what order, with what. + * data.mode picks what perform() does: "text" (default), "struct", "void", "long" or "fail". + */ +component extends="wheels.Job" { + + function config() { + super.config(); + this.maxRetries = 1; + } + + public void function beforePerform(struct data = {}) { + $note("before"); + if (StructKeyExists(arguments.data, "failBefore") && arguments.data.failBefore) { + throw(type = "Spec.BeforeFailure", message = "before failed"); + } + } + + public any function perform(struct data = {}) { + $note("perform"); + local.mode = StructKeyExists(arguments.data, "mode") ? arguments.data.mode : "text"; + if (local.mode == "fail") { + throw(type = "Spec.HookFailure", message = "perform failed", detail = "spec detail"); + } + if (local.mode == "struct") { + return {count = 2, ok = true}; + } + if (local.mode == "long") { + return RepeatString("x", 5000); + } + if (local.mode == "unicode") { + return "caf" & Chr(233) & " " & Chr(8211) & " " & Chr(26085) & Chr(26412) & " " & Chr(10003); + } + if (local.mode == "unicodeLong") { + return RepeatString(Chr(26085) & Chr(26412), 1500); + } + if (local.mode == "void") { + return; + } + return "done"; + } + + public void function afterPerform(struct data = {}, any result) { + $note("after"); + } + + public void function onSuccess(any result) { + if (IsNull(arguments.result)) { + $note("success:none"); + } else if (IsSimpleValue(arguments.result)) { + $note("success:" & Left(arguments.result, 10)); + } else { + $note("success:complex"); + } + if (StructKeyExists(application, "$hookSpecSuccessThrows") && application["$hookSpecSuccessThrows"]) { + throw(type = "Spec.SuccessHookFailure", message = "onSuccess failed"); + } + } + + public void function onFailure(struct error, numeric attempt, boolean isFinal) { + local.finalText = arguments.isFinal ? "true" : "false"; + $note("failure:#arguments.attempt#:#local.finalText#:#arguments.error.type#"); + } + + private void function $note(required string entry) { + if (!StructKeyExists(application, "$hookSpecLog")) { + application["$hookSpecLog"] = ""; + } + application["$hookSpecLog"] = ListAppend(application["$hookSpecLog"], arguments.entry, "|"); + } + +} diff --git a/vendor/wheels/tests/_assets/jobs/NonIdempotentHookJob.cfc b/vendor/wheels/tests/_assets/jobs/NonIdempotentHookJob.cfc new file mode 100644 index 0000000000..f4eddd2ec5 --- /dev/null +++ b/vendor/wheels/tests/_assets/jobs/NonIdempotentHookJob.cfc @@ -0,0 +1,12 @@ +/** + * HookProbeJob that must never run twice (core-suite fixture): a reaped attempt ends + * 'interrupted', which the hook specs check fires onFailure as final. + */ +component extends="wheels.tests._assets.jobs.HookProbeJob" { + + function config() { + super.config(); + this.idempotent = false; + } + +} diff --git a/vendor/wheels/tests/specs/jobs/JobLifecycleHooksSpec.cfc b/vendor/wheels/tests/specs/jobs/JobLifecycleHooksSpec.cfc new file mode 100644 index 0000000000..efa8e2bced --- /dev/null +++ b/vendor/wheels/tests/specs/jobs/JobLifecycleHooksSpec.cfc @@ -0,0 +1,229 @@ +/** + * Job lifecycle hooks and the stored result. beforePerform/afterPerform run with perform() as part + * of the work; onSuccess/onFailure run after the outcome is recorded and can't change it; the + * app-wide jobsOnFailure hook hears about every failure; perform()'s return value is stored in + * wheels_jobs.result. Both processing paths (the worker and processQueue()) are covered. + */ +component extends="wheels.WheelsTest" { + + function run() { + + describe("job lifecycle hooks", function() { + + beforeEach(function() { + new wheels.Job().$ensureJobTable(); + $cleanup(); + application["$hookSpecLog"] = ""; + application["$hookSpecSuccessThrows"] = false; + application["$hookSpecGlobalCount"] = 0; + StructDelete(application, "$hookSpecGlobal"); + application.wheels.jobsOnFailure = "wheels.tests._assets.jobs.FailureHookTarget.record"; + StructDelete(application.wheels, "$jobsOnFailureWarned"); + }); + + afterEach(function() { + $cleanup(); + StructDelete(application.wheels, "jobsOnFailure"); + StructDelete(application.wheels, "$jobsOnFailureWarned"); + application["$hookSpecSuccessThrows"] = false; + }); + + it("runs beforePerform, perform, afterPerform, then onSuccess, and stores the result", function() { + var id = $insertJob(queue = "test_hooks_ok", data = {mode = "text"}); + var result = new wheels.JobWorker().processNext(queues = "test_hooks_ok", timeout = 300); + expect(result.success).toBeTrue(result.error); + expect(application["$hookSpecLog"]).toBe("before|perform|after|success:done"); + expect($row(id).result).toBe("done"); + }); + + it("stores a complex result as JSON", function() { + var id = $insertJob(queue = "test_hooks_struct", data = {mode = "struct"}); + new wheels.JobWorker().processNext(queues = "test_hooks_struct", timeout = 300); + var stored = DeserializeJSON($row(id).result); + expect(stored.count).toBe(2); + expect(ListLast(application["$hookSpecLog"], "|")).toBe("success:complex"); + }); + + it("stores NULL when perform() returns nothing", function() { + var id = $insertJob(queue = "test_hooks_void", data = {mode = "void"}); + new wheels.JobWorker().processNext(queues = "test_hooks_void", timeout = 300); + var row = $row(id); + expect(row.status).toBe("completed"); + expect(row.resultIsNull).toBeTrue(); + expect(ListLast(application["$hookSpecLog"], "|")).toBe("success:none"); + }); + + it("cuts a long result short with a visible marker", function() { + var id = $insertJob(queue = "test_hooks_long", data = {mode = "long"}); + new wheels.JobWorker().processNext(queues = "test_hooks_long", timeout = 300); + var stored = $row(id).result; + expect(Len(stored)).toBeLTE(4000); + expect(Right(stored, 14)).toBe("...[truncated]"); + }); + + it("stores a non-ASCII result intact", function() { + var id = $insertJob(queue = "test_hooks_unicode", data = {mode = "unicode"}); + new wheels.JobWorker().processNext(queues = "test_hooks_unicode", timeout = 300); + expect($row(id).result).toBe("caf" & Chr(233) & " " & Chr(8211) & " " & Chr(26085) & Chr(26412) & " " & Chr(10003)); + }); + + it("cuts a long non-ASCII result at what the column counts, never mid-character", function() { + var id = $insertJob(queue = "test_hooks_unicodelong", data = {mode = "unicodeLong"}); + new wheels.JobWorker().processNext(queues = "test_hooks_unicodelong", timeout = 300); + var stored = $row(id).result; + var original = RepeatString(Chr(26085) & Chr(26412), 1500); + if (new wheels.Job().$detectDatabaseType() == "sqlserver") { + // NVARCHAR(4000) counts characters: 3000 fit whole. + expect(stored).toBe(original); + } else { + // 9000 UTF-8 bytes: cut to 4000 bytes, on a character boundary. + expect(Right(stored, 14)).toBe("...[truncated]"); + expect(Len(CharsetDecode(stored, "utf-8"))).toBeLTE(4000); + var kept = Left(stored, Len(stored) - 14); + expect(Left(original, Len(kept))).toBe(kept); + } + }); + + it("calls onFailure and the app's hook with isFinal = false when the job will be retried", function() { + var id = $insertJob(queue = "test_hooks_retry", data = {mode = "fail"}); + var result = new wheels.JobWorker().processNext(queues = "test_hooks_retry", timeout = 300); + expect(result.success).toBeFalse(); + expect($row(id).status).toBe("pending"); + expect(ListLast(application["$hookSpecLog"], "|")).toBe("failure:1:false:Spec.HookFailure"); + var event = application["$hookSpecGlobal"]; + expect(event.jobId).toBe(id); + expect(event.jobClass).toBe("wheels.tests._assets.jobs.HookProbeJob"); + expect(event.queue).toBe("test_hooks_retry"); + expect(event.attempt).toBe(1); + expect(event.isFinal).toBeFalse(); + expect(event.error.type).toBe("Spec.HookFailure"); + expect(event.error.message).toInclude("perform failed"); + expect(event.error.detail).toBe("spec detail"); + expect(StructKeyExists(event, "data")).toBeFalse("job data never reaches the app-wide hook"); + }); + + it("calls the hooks with isFinal = true when the job is marked failed", function() { + var id = $insertJob(queue = "test_hooks_final", data = {mode = "fail"}, attempts = 1); + new wheels.JobWorker().processNext(queues = "test_hooks_final", timeout = 300); + expect($row(id).status).toBe("failed"); + expect(ListLast(application["$hookSpecLog"], "|")).toBe("failure:2:true:Spec.HookFailure"); + expect(application["$hookSpecGlobal"].isFinal).toBeTrue(); + expect(application["$hookSpecGlobalCount"]).toBe(1); + }); + + it("fails the attempt when beforePerform throws, without running perform()", function() { + var id = $insertJob(queue = "test_hooks_before", data = {failBefore = true}); + var result = new wheels.JobWorker().processNext(queues = "test_hooks_before", timeout = 300); + expect(result.success).toBeFalse(); + expect(application["$hookSpecLog"]).toBe("before|failure:1:false:Spec.BeforeFailure"); + expect($row(id).status).toBe("pending"); + }); + + it("keeps the job completed when onSuccess throws", function() { + application["$hookSpecSuccessThrows"] = true; + var id = $insertJob(queue = "test_hooks_throws", data = {mode = "text"}); + var result = new wheels.JobWorker().processNext(queues = "test_hooks_throws", timeout = 300); + expect(result.success).toBeTrue(result.error); + expect($row(id).status).toBe("completed"); + }); + + it("still records the failure when the app's hook can't be called", function() { + application.wheels.jobsOnFailure = "wheels.tests._assets.jobs.NoSuchHookTarget.record"; + var id = $insertJob(queue = "test_hooks_badglobal", data = {mode = "fail"}); + new wheels.JobWorker().processNext(queues = "test_hooks_badglobal", timeout = 300); + expect($row(id).status).toBe("pending"); + expect(ListLast(application["$hookSpecLog"], "|")).toBe("failure:1:false:Spec.HookFailure"); + }); + + it("runs the hooks and stores the result in processQueue() too", function() { + var okId = $insertJob(queue = "test_hooks_pq", data = {mode = "text"}); + var failId = $insertJob(queue = "test_hooks_pq", data = {mode = "fail"}, attempts = 1); + new wheels.Job().processQueue(queue = "test_hooks_pq", limit = 0); + expect($row(okId).result).toBe("done"); + expect(application["$hookSpecLog"]).toInclude("success:done"); + expect(application["$hookSpecLog"]).toInclude("failure:2:true:Spec.HookFailure"); + expect($row(failId).status).toBe("failed"); + expect(application["$hookSpecGlobal"].jobId).toBe(failId); + }); + + it("calls the hooks with isFinal = true when the reaper marks a dead worker's last attempt failed", function() { + var id = $insertJob(queue = "test_hooks_reap", data = {mode = "text"}, attempts = 2, status = "processing", stale = true); + new wheels.JobWorker().checkTimeouts(timeout = 300, queues = "test_hooks_reap"); + expect($row(id).status).toBe("failed"); + expect(application["$hookSpecLog"]).toBe("failure:2:true:Wheels.JobTimeout"); + expect(application["$hookSpecGlobal"].isFinal).toBeTrue(); + }); + + it("calls the hooks with isFinal = true when the reaper interrupts a job that isn't idempotent", function() { + var id = $insertJob(queue = "test_hooks_interrupt", data = {mode = "text"}, attempts = 1, status = "processing", stale = true, jobClass = "wheels.tests._assets.jobs.NonIdempotentHookJob"); + new wheels.JobWorker().checkTimeouts(timeout = 300, queues = "test_hooks_interrupt"); + expect($row(id).status).toBe("interrupted"); + expect(application["$hookSpecLog"]).toBe("failure:1:true:Wheels.JobTimeout"); + expect(application["$hookSpecGlobal"].isFinal).toBeTrue(); + }); + + it("doesn't call the hooks when the reaper schedules a retry", function() { + $insertJob(queue = "test_hooks_reapretry", data = {mode = "text"}, attempts = 1, status = "processing", stale = true); + new wheels.JobWorker().checkTimeouts(timeout = 300, queues = "test_hooks_reapretry"); + expect(application["$hookSpecLog"]).toBe(""); + expect(application["$hookSpecGlobalCount"]).toBe(0); + }); + + }); + } + + private void function $cleanup() { + try { + queryExecute("DELETE FROM wheels_jobs WHERE queue LIKE 'test_hooks_%'", {}, {datasource = application.wheels.dataSourceName}); + } catch (any e) { + } + } + + private string function $insertJob( + required string queue, + struct data = {}, + numeric attempts = 0, + string status = "pending", + boolean stale = false, + string jobClass = "wheels.tests._assets.jobs.HookProbeJob" + ) { + var id = CreateUUID(); + var stamp = arguments.stale ? DateAdd("h", -2, Now()) : DateAdd("s", -5, Now()); + queryExecute( + "INSERT INTO wheels_jobs (id, jobClass, queue, data, priority, status, attempts, maxRetries, runAt, createdAt, updatedAt) + VALUES (:id, :jobClass, :queue, :data, 0, :status, :attempts, 1, :runAt, :createdAt, :updatedAt)", + { + id = {value = id, cfsqltype = "cf_sql_varchar"}, + jobClass = {value = arguments.jobClass, cfsqltype = "cf_sql_varchar"}, + queue = {value = arguments.queue, cfsqltype = "cf_sql_varchar"}, + data = {value = SerializeJSON(arguments.data), cfsqltype = "cf_sql_longvarchar"}, + status = {value = arguments.status, cfsqltype = "cf_sql_varchar"}, + attempts = {value = arguments.attempts, cfsqltype = "cf_sql_integer"}, + runAt = {value = stamp, cfsqltype = "cf_sql_timestamp"}, + createdAt = {value = stamp, cfsqltype = "cf_sql_timestamp"}, + updatedAt = {value = stamp, cfsqltype = "cf_sql_timestamp"} + }, + {datasource = application.wheels.dataSourceName} + ); + return id; + } + + private struct function $row(required string id) { + var q = queryExecute( + "SELECT status, result FROM wheels_jobs WHERE id = :id", + {id = {value = arguments.id, cfsqltype = "cf_sql_varchar"}}, + {datasource = application.wheels.dataSourceName} + ); + var nulls = queryExecute( + "SELECT id FROM wheels_jobs WHERE id = :id AND result IS NULL", + {id = {value = arguments.id, cfsqltype = "cf_sql_varchar"}}, + {datasource = application.wheels.dataSourceName} + ); + return { + status = q.recordCount ? q.status : "", + result = q.recordCount && !IsNull(q.result[1]) ? q.result[1] : "", + resultIsNull = nulls.recordCount > 0 + }; + } + +}