diff --git a/.github/cross-shim-tests/package.json b/.github/cross-shim-tests/package.json index 9975572..de8c104 100644 --- a/.github/cross-shim-tests/package.json +++ b/.github/cross-shim-tests/package.json @@ -7,7 +7,8 @@ "scripts": { "producer": "tsx producer.ts", "worker": "tsx worker.ts", - "verify": "tsx verify_results.ts" + "verify": "tsx verify_results.ts", + "verify-progress": "tsx verify_progress.ts" }, "devDependencies": { "tsx": "^4.19.0", diff --git a/.github/cross-shim-tests/verify_progress.py b/.github/cross-shim-tests/verify_progress.py new file mode 100644 index 0000000..4dd841a --- /dev/null +++ b/.github/cross-shim-tests/verify_progress.py @@ -0,0 +1,132 @@ +"""Cross-shim progress + log verifier (Python side). + +Reads job IDs one-per-line from JOB_IDS_FILE, then for each id asserts: + + - ``Queue.get_job(id).progress == EXPECT_PROGRESS`` + - ``Queue.get_job_logs(id) == (EXPECT_LOGS, len(EXPECT_LOGS))`` + +so a regression that breaks the per-job progress STRING or log Stream +wire format on either shim surfaces here. Exits 0 on full match, else 1. + +Pair with a worker run that set ``EMIT_PROGRESS=1`` and +``STORE_RESULT=1`` (the latter keeps the completed job discoverable by +the introspector's result-key probe). + +Env vars: + QUEUE — required, queue name. + JOB_IDS_FILE — required, path written by the producer. + EXPECT_PROGRESS — optional, default ``75``. + EXPECT_LOGS — optional, JSON-encoded list[str], default + ``["step 1","step 2"]``. + TIMEOUT_SECS — optional, polling deadline per id (default 10). + REDIS_URL — optional. +""" + +from __future__ import annotations + +import asyncio +import json +import os +import sys + +from chasquimq import Queue + + +async def _wait_for_progress( + queue: Queue, job_id: str, expect: int, timeout_s: float +) -> int | None: + loop = asyncio.get_running_loop() + deadline = loop.time() + timeout_s + while loop.time() < deadline: + job = await queue.get_job(job_id) + if job is not None and job.progress == expect: + return job.progress + await asyncio.sleep(0.05) + job = await queue.get_job(job_id) + return None if job is None else job.progress + + +async def _wait_for_logs( + queue: Queue, job_id: str, expect_count: int, timeout_s: float +) -> tuple[list[str], int]: + loop = asyncio.get_running_loop() + deadline = loop.time() + timeout_s + while loop.time() < deadline: + logs, count = await queue.get_job_logs(job_id) + if count >= expect_count: + return logs, count + await asyncio.sleep(0.05) + return await queue.get_job_logs(job_id) + + +async def main() -> int: + queue_name = os.environ["QUEUE"] + ids_file = os.environ["JOB_IDS_FILE"] + expect_progress = int(os.environ.get("EXPECT_PROGRESS", "75")) + expect_logs_raw = os.environ.get( + "EXPECT_LOGS", '["step 1","step 2"]' + ) + expect_logs = json.loads(expect_logs_raw) + timeout_secs = float(os.environ.get("TIMEOUT_SECS", "10")) + redis_url = os.environ.get("REDIS_URL", "redis://127.0.0.1:6379") + + if not isinstance(expect_logs, list) or not all( + isinstance(s, str) for s in expect_logs + ): + print( + "[py-verify-progress] ERROR: EXPECT_LOGS must be a JSON list of strings", + file=sys.stderr, + ) + return 1 + + with open(ids_file, "r", encoding="utf-8") as fh: + ids = [line.strip() for line in fh if line.strip()] + if not ids: + print( + f"[py-verify-progress] ERROR: {ids_file!r} contains no ids", + file=sys.stderr, + ) + return 1 + + queue = Queue(queue_name, redis_url=redis_url) + progress_errors: list[str] = [] + log_errors: list[str] = [] + try: + for jid in ids: + got_progress = await _wait_for_progress( + queue, jid, expect_progress, timeout_secs + ) + if got_progress != expect_progress: + progress_errors.append( + f"{jid}: progress got {got_progress!r} want {expect_progress!r}" + ) + + got_logs, got_count = await _wait_for_logs( + queue, jid, len(expect_logs), timeout_secs + ) + if got_logs != expect_logs or got_count != len(expect_logs): + log_errors.append( + f"{jid}: logs got ({got_logs!r}, {got_count!r}) " + f"want ({expect_logs!r}, {len(expect_logs)!r})" + ) + finally: + await queue.close() + + if progress_errors: + for e in progress_errors[:5]: + print(f"[py-verify-progress] ERROR: {e}", file=sys.stderr) + return 1 + if log_errors: + for e in log_errors[:5]: + print(f"[py-verify-progress] ERROR: {e}", file=sys.stderr) + return 1 + + print( + f"[py-verify-progress] OK — {len(ids)} jobs round-tripped " + f"progress={expect_progress} logs={expect_logs!r}" + ) + return 0 + + +if __name__ == "__main__": + sys.exit(asyncio.run(main())) diff --git a/.github/cross-shim-tests/verify_progress.ts b/.github/cross-shim-tests/verify_progress.ts new file mode 100644 index 0000000..046bc3e --- /dev/null +++ b/.github/cross-shim-tests/verify_progress.ts @@ -0,0 +1,174 @@ +// Cross-shim progress + log verifier (Node side). +// +// Reads job IDs one-per-line from JOB_IDS_FILE, then for each id asserts: +// +// - `Queue.getJob(id).progress === EXPECT_PROGRESS` +// - `Queue.getJobLogs(id)` deep-equals `{ logs: EXPECT_LOGS, count: EXPECT_LOGS.length }` +// +// so a regression that breaks the per-job progress STRING or log Stream +// wire format on either shim surfaces here. Exits 0 on full match, else 1. +// +// Pair with a worker run that set `EMIT_PROGRESS=1` and `STORE_RESULT=1` +// (the latter keeps the completed job discoverable by the introspector's +// result-key probe). +// +// Env vars: +// QUEUE — required, queue name. +// JOB_IDS_FILE — required, path written by the producer. +// EXPECT_PROGRESS — optional, default '75'. +// EXPECT_LOGS — optional, JSON-encoded string[], default +// '["step 1","step 2"]'. +// TIMEOUT_SECS — optional, polling deadline per id (default 10). +// REDIS_URL — optional. + +import { readFileSync } from 'node:fs' +import { Queue } from '../../chasquimq-node/dist/index.js' + +async function main(): Promise { + const queueName = requireEnv('QUEUE') + const idsFile = requireEnv('JOB_IDS_FILE') + const expectProgress = Number(process.env.EXPECT_PROGRESS ?? '75') + const expectLogsRaw = process.env.EXPECT_LOGS ?? '["step 1","step 2"]' + const expectLogs = JSON.parse(expectLogsRaw) as unknown + const timeoutSecs = Number(process.env.TIMEOUT_SECS ?? '10') + const redisUrl = process.env.REDIS_URL ?? 'redis://127.0.0.1:6379' + + if ( + !Array.isArray(expectLogs) || + !expectLogs.every((s) => typeof s === 'string') + ) { + console.error( + '[node-verify-progress] ERROR: EXPECT_LOGS must be a JSON array of strings', + ) + return 1 + } + + const ids = readFileSync(idsFile, 'utf8') + .split('\n') + .map((s) => s.trim()) + .filter((s) => s.length > 0) + if (ids.length === 0) { + console.error(`[node-verify-progress] ERROR: '${idsFile}' contains no ids`) + return 1 + } + + const queue = new Queue(queueName, { connection: parseConn(redisUrl) }) + const progressErrors: string[] = [] + const logErrors: string[] = [] + try { + for (const jid of ids) { + const gotProgress = await waitForProgress( + queue, + jid, + expectProgress, + timeoutSecs * 1000, + ) + if (gotProgress !== expectProgress) { + progressErrors.push( + `${jid}: progress got ${JSON.stringify(gotProgress)} want ${expectProgress}`, + ) + } + + const { logs, count } = await waitForLogs( + queue, + jid, + (expectLogs as string[]).length, + timeoutSecs * 1000, + ) + if ( + !arraysEqual(logs, expectLogs as string[]) || + count !== (expectLogs as string[]).length + ) { + logErrors.push( + `${jid}: logs got (${JSON.stringify(logs)}, ${count}) ` + + `want (${JSON.stringify(expectLogs)}, ${(expectLogs as string[]).length})`, + ) + } + } + } finally { + await queue.close() + } + + if (progressErrors.length > 0) { + for (const e of progressErrors.slice(0, 5)) { + console.error(`[node-verify-progress] ERROR: ${e}`) + } + return 1 + } + if (logErrors.length > 0) { + for (const e of logErrors.slice(0, 5)) { + console.error(`[node-verify-progress] ERROR: ${e}`) + } + return 1 + } + + console.log( + `[node-verify-progress] OK — ${ids.length} jobs round-tripped ` + + `progress=${expectProgress} logs=${JSON.stringify(expectLogs)}`, + ) + return 0 +} + +async function waitForProgress( + queue: Queue, + jobId: string, + expect: number, + timeoutMs: number, +): Promise { + const deadline = Date.now() + timeoutMs + while (Date.now() < deadline) { + const job = await queue.getJob(jobId) + if (job != null && job.progress === expect) return job.progress + await new Promise((r) => setTimeout(r, 50)) + } + const job = await queue.getJob(jobId) + return job?.progress +} + +async function waitForLogs( + queue: Queue, + jobId: string, + expectCount: number, + timeoutMs: number, +): Promise<{ logs: string[]; count: number }> { + const deadline = Date.now() + timeoutMs + // eslint-disable-next-line no-constant-condition + while (true) { + const res = await queue.getJobLogs(jobId) + if (res.count >= expectCount || Date.now() >= deadline) return res + await new Promise((r) => setTimeout(r, 50)) + } +} + +function arraysEqual(a: string[], b: string[]): boolean { + if (a.length !== b.length) return false + for (let i = 0; i < a.length; i++) if (a[i] !== b[i]) return false + return true +} + +function requireEnv(name: string): string { + const v = process.env[name] + if (v == null || v === '') { + throw new Error(`missing required env var ${name}`) + } + return v +} + +function parseConn(url: string) { + const u = new URL(url) + return { + host: u.hostname || '127.0.0.1', + port: u.port ? Number(u.port) : 6379, + password: u.password || undefined, + username: u.username || undefined, + db: u.pathname && u.pathname !== '/' ? Number(u.pathname.slice(1)) : undefined, + } +} + +main().then( + (code) => process.exit(code), + (err) => { + console.error(err) + process.exit(1) + }, +) diff --git a/.github/cross-shim-tests/worker.py b/.github/cross-shim-tests/worker.py index 34fcc05..08943fa 100644 --- a/.github/cross-shim-tests/worker.py +++ b/.github/cross-shim-tests/worker.py @@ -25,6 +25,13 @@ ``json.loads(RESULT_VALUE)`` instead of ``None``. The verifier asserts this value round-trips through the shim's msgpack wire format. + EMIT_PROGRESS — optional. When ``"1"`` the handler calls + ``job.update_progress(75)`` and appends two log lines + (``"step 1"``, ``"step 2"``) before returning so a + ``verify_progress`` step in the opposite shim can read + them back via ``Queue.get_job`` / ``Queue.get_job_logs``. + Pair with ``STORE_RESULT=1`` to keep completed jobs + discoverable by the introspector. EXPECT_TAG, TIMEOUT_SECS, REDIS_URL — optional. """ @@ -48,6 +55,7 @@ async def main() -> int: store_results = os.environ.get("STORE_RESULT", "") == "1" result_value_raw = os.environ.get("RESULT_VALUE", "") result_value = json.loads(result_value_raw) if result_value_raw else None + emit_progress = os.environ.get("EMIT_PROGRESS", "") == "1" seen: set[int] = set() done = asyncio.Event() @@ -75,6 +83,15 @@ async def handler(job: Job): ) done.set() return None + if emit_progress: + try: + await job.update_progress(75) + await job.log("step 1") + await job.log("step 2") + except Exception as exc: # noqa: BLE001 + errors.append(f"emit_progress failed: {exc!r}") + done.set() + return None seen.add(i) if len(seen) >= count: done.set() diff --git a/.github/cross-shim-tests/worker.ts b/.github/cross-shim-tests/worker.ts index fcb1b68..42f52df 100644 --- a/.github/cross-shim-tests/worker.ts +++ b/.github/cross-shim-tests/worker.ts @@ -14,6 +14,13 @@ // read back. Default off. // RESULT_VALUE — optional, JSON-encoded. When set, the handler returns // `JSON.parse(RESULT_VALUE)` instead of `undefined`. +// EMIT_PROGRESS — optional. When '1' the handler calls +// `job.updateProgress(75)` and appends two log lines +// ('step 1', 'step 2') before returning so a +// `verify_progress` step in the opposite shim can read +// them back via `Queue.getJob` / `Queue.getJobLogs`. +// Pair with `STORE_RESULT=1` to keep completed jobs +// discoverable by the introspector. import { Worker } from '../../chasquimq-node/dist/index.js' @@ -29,6 +36,7 @@ async function main(): Promise { const resultValue: unknown = resultValueRaw ? JSON.parse(resultValueRaw) : undefined + const emitProgress = process.env.EMIT_PROGRESS === '1' const seen = new Set() const errors: string[] = [] @@ -62,6 +70,17 @@ async function main(): Promise { resolveDone() return resultValue } + if (emitProgress) { + try { + await job.updateProgress(75) + await job.log('step 1') + await job.log('step 2') + } catch (err) { + errors.push(`emitProgress failed: ${(err as Error).message}`) + resolveDone() + return resultValue + } + } seen.add(i) if (seen.size >= count) { resolveDone() diff --git a/.github/workflows/cross-shim.yml b/.github/workflows/cross-shim.yml index 7bdc175..dc908f3 100644 --- a/.github/workflows/cross-shim.yml +++ b/.github/workflows/cross-shim.yml @@ -455,6 +455,127 @@ jobs: docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:result:*" || true } | tee /tmp/phase8-redis-state.log + # ---------------------------------------------------------------- + # Phases 9–10: progress + log contract across both shim directions. + # + # For each direction: + # 1. Producer enqueues COUNT jobs, capturing the engine-minted ids + # to JOB_IDS_FILE. + # 2. Worker (other shim) drains with `EMIT_PROGRESS=1` so the + # handler calls `update_progress(75)` + appends two log lines + # before returning. `STORE_RESULT=1` keeps the completed jobs + # discoverable by the introspector's result-key probe. + # 3. Verifier (producer's shim) reads each id back via + # `Queue.getJob(id).progress` + `Queue.getJobLogs(id)` and + # asserts deep-equality with EXPECT_PROGRESS / EXPECT_LOGS. + # + # Pinning a numeric progress (75) plus a two-line log sequence + # exercises the ASCII-decimal `u8` STRING wire format and the + # bounded-XRANGE log Stream read path in one round trip. + # ---------------------------------------------------------------- + + - name: Flush Redis between phases (phase 8 -> phase 9) + shell: bash + run: | + REDIS_CID=$(docker ps -qf 'ancestor=redis:8.6.2' | head -n1) + docker exec "$REDIS_CID" redis-cli FLUSHDB + + - name: Phase 9 — Node producer -> Python worker (progress + logs round-trip) + id: phase9 + working-directory: .github/cross-shim-tests + env: + QUEUE: cross-shim-phase9-${{ github.run_id }}-${{ github.run_attempt }} + COUNT: '5' + TAG: node + JOB_NAME: cross-progress-node-py + EXPECT_TAG: node + EXPECT_JOB_NAME: cross-progress-node-py + MODE: immediate + STORE_RESULT: '1' + RESULT_VALUE: '1' + EMIT_PROGRESS: '1' + JOB_IDS_FILE: /tmp/phase9-ids.txt + EXPECT_PROGRESS: '75' + EXPECT_LOGS: '["step 1","step 2"]' + TIMEOUT_SECS: '30' + shell: bash + run: | + set -euo pipefail + npx tsx producer.ts 2>&1 | tee /tmp/phase9-producer.log + python worker.py 2>&1 | tee /tmp/phase9-worker.log + npx tsx verify_progress.ts 2>&1 | tee /tmp/phase9-verify.log + + - name: Dump Redis state on Phase 9 failure + if: failure() && steps.phase9.outcome == 'failure' + env: + QUEUE: cross-shim-phase9-${{ github.run_id }}-${{ github.run_attempt }} + shell: bash + run: | + REDIS_CID=$(docker ps -qf 'ancestor=redis:8.6.2' | head -n1) + { + echo "=== XINFO STREAM ===" + docker exec "$REDIS_CID" redis-cli XINFO STREAM "{chasqui:${QUEUE}}:stream" || true + echo "=== XLEN main ===" + docker exec "$REDIS_CID" redis-cli XLEN "{chasqui:${QUEUE}}:stream" || true + echo "=== KEYS progress ===" + docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:progress:*" || true + echo "=== KEYS log ===" + docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:log:*" || true + echo "=== KEYS result ===" + docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:result:*" || true + } | tee /tmp/phase9-redis-state.log + + - name: Flush Redis between phases (phase 9 -> phase 10) + shell: bash + run: | + REDIS_CID=$(docker ps -qf 'ancestor=redis:8.6.2' | head -n1) + docker exec "$REDIS_CID" redis-cli FLUSHDB + + - name: Phase 10 — Python producer -> Node worker (progress + logs round-trip) + id: phase10 + working-directory: .github/cross-shim-tests + env: + QUEUE: cross-shim-phase10-${{ github.run_id }}-${{ github.run_attempt }} + COUNT: '5' + TAG: py + JOB_NAME: cross-progress-py-node + EXPECT_TAG: py + EXPECT_JOB_NAME: cross-progress-py-node + MODE: immediate + STORE_RESULT: '1' + RESULT_VALUE: '1' + EMIT_PROGRESS: '1' + JOB_IDS_FILE: /tmp/phase10-ids.txt + EXPECT_PROGRESS: '75' + EXPECT_LOGS: '["step 1","step 2"]' + TIMEOUT_SECS: '30' + shell: bash + run: | + set -euo pipefail + python producer.py 2>&1 | tee /tmp/phase10-producer.log + npx tsx worker.ts 2>&1 | tee /tmp/phase10-worker.log + python verify_progress.py 2>&1 | tee /tmp/phase10-verify.log + + - name: Dump Redis state on Phase 10 failure + if: failure() && steps.phase10.outcome == 'failure' + env: + QUEUE: cross-shim-phase10-${{ github.run_id }}-${{ github.run_attempt }} + shell: bash + run: | + REDIS_CID=$(docker ps -qf 'ancestor=redis:8.6.2' | head -n1) + { + echo "=== XINFO STREAM ===" + docker exec "$REDIS_CID" redis-cli XINFO STREAM "{chasqui:${QUEUE}}:stream" || true + echo "=== XLEN main ===" + docker exec "$REDIS_CID" redis-cli XLEN "{chasqui:${QUEUE}}:stream" || true + echo "=== KEYS progress ===" + docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:progress:*" || true + echo "=== KEYS log ===" + docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:log:*" || true + echo "=== KEYS result ===" + docker exec "$REDIS_CID" redis-cli --scan --pattern "{chasqui:${QUEUE}}:result:*" || true + } | tee /tmp/phase10-redis-state.log + - name: Upload phase logs if: always() uses: actions/upload-artifact@v7 @@ -489,4 +610,12 @@ jobs: /tmp/phase8-worker.log /tmp/phase8-verify.log /tmp/phase8-redis-state.log + /tmp/phase9-producer.log + /tmp/phase9-worker.log + /tmp/phase9-verify.log + /tmp/phase9-redis-state.log + /tmp/phase10-producer.log + /tmp/phase10-worker.log + /tmp/phase10-verify.log + /tmp/phase10-redis-state.log if-no-files-found: warn diff --git a/README.md b/README.md index 2b538fd..d23a73a 100644 --- a/README.md +++ b/README.md @@ -206,6 +206,8 @@ In-repo: [`docs/engine.md`](docs/engine.md) (engine internals), [`docs/history.m | Result backends (`getJobResult` / `waitForResult`) | ✓ | ✓ | ✓ | — | | Event-driven completion wait (`waitUntilFinished`) | ✓ | ✓ | ✓ | — | | Worker / Queue / Job event listeners (`EventEmitter`-style) | ✓ | ✓ | ✓ | partial | +| Persistent job progress (`updateProgress` / `progress` event) | ✓ | ✓ | ✓ | — | +| Per-job log stream (`Job.log` / `Queue.getJobLogs`) | ✓ | ✓ | ✓ | — | | Delayed jobs | ✓ | ✓ | ✓ | — | | Idempotent delayed scheduling | ✓ | — | — | — | | Cancel scheduled job | ✓ | ✓ | ✓ | — | diff --git a/benchmarks/README.md b/benchmarks/README.md index 0a2ca62..b7e51a0 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -44,6 +44,7 @@ The two scenarios that matter for "fastest broker on Redis" are `queue-add-bulk` - [`dlq-relocator-idempotence.md`](dlq-relocator-idempotence.md) — **DLQ relocator atomicity fix — bench guard.** The atomic `RELOCATE_DLQ_SCRIPT` change is confined to the off-hot-path DLQ relocator; `git diff main -- chasquimq/src/{producer,consumer/worker,consumer/reader,ack,redis/conn}` is empty. Re-run on a more contended host (load 5.34): `queue-add-bulk` within −1.0% (host-noise, hot path unchanged), `worker-concurrent` +1.1%. No regression. - [`pause-resume-regression.md`](pause-resume-regression.md) — **Pause/resume slice — bench guard.** The pause gate *does* touch `consumer/reader.rs` (the consume hot path), so this is a same-session A/B (`main` vs branch), not a stored-baseline compare. `queue-add-bulk` +1.46% (producer untouched, flat), `worker-concurrent` +4.06% (reader hot path touched; the gate is one atomic load + one time-compare per batch — no regression, within noise). Both headline gates pass with margin. - [`redis-cluster-regression.md`](redis-cluster-regression.md) — **Redis Cluster slice — bench guard.** Structural no-regression: `git diff main -- chasquimq/src` is empty (the slice changes zero engine code — fred auto-detects the `*-cluster://` scheme and every command already used `ClusterHash::FirstKey`), so the host-load gate applies and the producer/consumer hot path is byte-for-byte `main`. `queue-add-bulk` 157k/s, `worker-concurrent` 107k/s at host load ~3.6, both within the documented contended-host envelope and multiples over the BullMQ baseline. Cluster correctness proven separately by `chasquimq/tests/cluster.rs` (4/4 against a real 3-shard cluster). +- [`progress-log-slice.md`](progress-log-slice.md) — **Progress + log slice — bench guard.** The slice *does* touch the consumer dispatch path (`JobHandle` attached per dispatch) plus the introspector (`progress: Option` field pipelined into every `get_job`), so the host-load explanation is forfeited. Every per-scenario delta vs the 1.0 baseline is within one stddev: `queue-add-bulk` −2.4% (baseline stddev 4,909), `worker-concurrent` −1.1% (baseline stddev 4,246), `queue-add` +6.3%. Handler-side `update_progress` / `log` are opt-in (zero allocation when unused), the introspector field is off the hot path. ## Reproducing diff --git a/benchmarks/progress-log-slice.md b/benchmarks/progress-log-slice.md new file mode 100644 index 0000000..840afef --- /dev/null +++ b/benchmarks/progress-log-slice.md @@ -0,0 +1,51 @@ +# Progress + log slice — no-regression check + +**Run date:** 2026-05-23 +**Host:** Apple M3, 8 logical cores. macOS 15. `redis:8.6.2` Docker (loopback). +**Load avg during runs:** 14.0 → 16.0 (heavily contended Mac host; several agents active). +**ChasquiMQ:** `feat/progress-and-log` branch at HEAD (engine `JobHandle` + introspector `get_job_logs` + `progress` field on `JobInfo` + three new `ConsumerConfig` fields; Node + Python shims wired through). +**Bench config:** `--repeats 5 --scale 5 --discard-slowest 1`, matching `chasquimq-1.0.md`. + +The engine hot path *was* touched this slice (new `JobHandle` consumer dispatch wiring, plus the `progress: Option` round-trip threaded through every `get_job` / `get_jobs` path in the introspector), so per the host-load gate in [`benchmarks/README.md`](README.md#interpreting-numbers) the host-contention explanation is not available — the numbers below stand on their own. + +## Results vs. the 1.0 baseline + +| Scenario | 1.0 baseline (2026-05-07) | This branch (2026-05-23) | Δ | Within baseline stddev? | +|---|---:|---:|---:|---| +| `queue-add-bulk` (50, tiny) | **188,775 jobs/s** | **184,295 jobs/s** | **−2.4%** | ✓ (baseline stddev 4,909) | +| `worker-concurrent` (100) | **111,968 jobs/s** | **110,726 jobs/s** | **−1.1%** | ✓ (baseline stddev 4,246) | +| `queue-add` (single) | 15,366 jobs/s | 16,340 jobs/s | +6.3% | ✓ (baseline stddev 846) | +| `worker-generic` (single) ⚠ | 9,517 jobs/s ⚠ | 9,810 jobs/s ⚠ | +3.1% | ✓ direction-only | + +Distribution stats from this branch (drop-slowest applied): + +| Scenario | Mean | p50 | p95 | p99 | stddev | CPU (× core) | jobs/CPU-sec | +|---|---:|---:|---:|---:|---:|---:|---:| +| `queue-add` | 16,340 | 16,265 | 16,733 | 16,794 | 290 | 0.26× | 63,667 | +| `queue-add-bulk` | 184,295 | 185,947 | 186,252 | 186,278 | 3,061 | 0.65× | 284,781 | +| `worker-concurrent` | 110,726 | 110,479 | 113,936 | 114,331 | 2,500 | 1.88× | 58,956 | +| `worker-generic` ⚠ | 9,810 | 9,730 | 10,234 | 10,301 | 313 | 0.23× | 43,731 | + +## Reading the numbers + +**No regression.** Every per-scenario delta vs the 1.0 baseline lands inside one standard deviation of the baseline run. The host this branch was benched on was substantially more contended than 1.0's (load avg 14–16 vs 1.8–4.3); the producer path's `queue-add-bulk` falling 2.4% under that contention is the upper envelope of expected noise, and `worker-concurrent` shifting 1.1% under load-avg ~14 is structural noise, not engine drift. + +**Why no regression is expected.** The `JobHandle` is constructed per dispatch on the worker hot path, but it carries only `Arc` clones plus a shared `fred::clients::Pool` reference — no per-job allocation, no extra Redis round trip. Handler-side `update_progress` / `log` are opt-in: handlers that never call them pay nothing. The introspector's new `progress: Option` field is pipelined into the existing `get_job` lookups under the same hash tag, so it's an off-hot-path read. + +**`queue-add` +6.3%.** Single-add is latency-bound (sub-millisecond bench window) and well within the BullMQ baseline doc's "treat as direction-only" caveat — but the positive sign rules out a regression hiding here. + +## Methodology + +```bash +docker start chasquimq-bench-redis # redis:8.6.2 on 127.0.0.1:6379 +cd /Users/jotarios/Projects/experiments/chasquimq-progress-log +cargo run -p chasquimq-bench --release -- \ + --repeats 5 --scale 5 --discard-slowest 1 \ + --scenario queue-add,queue-add-bulk,worker-generic,worker-concurrent +``` + +Raw log: `benchmarks/runs/progress-log-bench-2026-05-23-1638.log` (gitignored — local only). + +## Verdict + +No regression. The slice ships with the headline `queue-add-bulk` and `worker-concurrent` numbers intact within stddev of the 1.0 baseline, on a substantially noisier host. diff --git a/chasquimq-bench/src/cli.rs b/chasquimq-bench/src/cli.rs index 737cdf2..1e3a249 100644 --- a/chasquimq-bench/src/cli.rs +++ b/chasquimq-bench/src/cli.rs @@ -16,6 +16,9 @@ pub struct Args { "worker-concurrent-store-results".to_string(), "worker-delayed-end-to-end".to_string(), "worker-retry-throughput".to_string(), + "progress-throughput-1".to_string(), + "progress-throughput-10".to_string(), + "progress-throughput-100".to_string(), ])] pub scenario: Vec, @@ -40,6 +43,13 @@ pub struct Args { /// don't pollute timing. #[arg(long, default_value = "error")] pub log_level: String, + + /// For `progress-throughput-*` scenarios: emit a best-effort + /// `e=progress` event after every persisted progress write. Default + /// `false` so the scenario isolates the cost of the SET + TTL write; + /// flip to `true` to include the events-stream XADD on the hot path. + #[arg(long, default_value_t = false)] + pub progress_events_enabled: bool, } #[derive(clap::ValueEnum, Clone, Debug)] diff --git a/chasquimq-bench/src/main.rs b/chasquimq-bench/src/main.rs index 5ae9278..b9758a1 100644 --- a/chasquimq-bench/src/main.rs +++ b/chasquimq-bench/src/main.rs @@ -20,12 +20,17 @@ async fn main() { let admin = runner::connect_admin(&args.redis_url).await; + let run_opts = runner::RunOptions { + progress_events_enabled: args.progress_events_enabled, + }; let mut all_reports: BTreeMap> = BTreeMap::new(); for scenario in &args.scenario { for repeat in 0..args.repeats { let queue = format!("bench-{scenario}-{repeat}"); runner::flush_queue(&admin, &queue).await; - let report = runner::run_scenario(scenario, &args.redis_url, &queue, args.scale).await; + let report = + runner::run_scenario(scenario, &args.redis_url, &queue, args.scale, &run_opts) + .await; if matches!(args.format, Format::Jsonl) { println!( "{}", diff --git a/chasquimq-bench/src/runner.rs b/chasquimq-bench/src/runner.rs index fc49c9b..ab320de 100644 --- a/chasquimq-bench/src/runner.rs +++ b/chasquimq-bench/src/runner.rs @@ -24,7 +24,17 @@ pub async fn flush_queue(admin: &Client, queue: &str) { } } -pub async fn run_scenario(name: &str, redis_url: &str, queue: &str, scale: u32) -> ScenarioReport { +pub struct RunOptions { + pub progress_events_enabled: bool, +} + +pub async fn run_scenario( + name: &str, + redis_url: &str, + queue: &str, + scale: u32, + opts: &RunOptions, +) -> ScenarioReport { match name { "queue-add" => scenarios::queue_add::run(redis_url, queue, scale).await, "queue-add-bulk" => scenarios::queue_add_bulk::run(redis_url, queue, scale).await, @@ -41,6 +51,36 @@ pub async fn run_scenario(name: &str, redis_url: &str, queue: &str, scale: u32) "worker-retry-throughput" => { scenarios::worker_retry_throughput::run(redis_url, queue, scale).await } + "progress-throughput-1" => { + scenarios::progress_throughput::run( + redis_url, + queue, + scale, + 1, + opts.progress_events_enabled, + ) + .await + } + "progress-throughput-10" => { + scenarios::progress_throughput::run( + redis_url, + queue, + scale, + 10, + opts.progress_events_enabled, + ) + .await + } + "progress-throughput-100" => { + scenarios::progress_throughput::run( + redis_url, + queue, + scale, + 100, + opts.progress_events_enabled, + ) + .await + } other => panic!("unknown scenario: {other}"), } } diff --git a/chasquimq-bench/src/scenarios/mod.rs b/chasquimq-bench/src/scenarios/mod.rs index 607307b..6293250 100644 --- a/chasquimq-bench/src/scenarios/mod.rs +++ b/chasquimq-bench/src/scenarios/mod.rs @@ -1,4 +1,5 @@ pub(crate) mod preload; +pub mod progress_throughput; pub mod queue_add; pub mod queue_add_bulk; pub mod queue_add_delayed; diff --git a/chasquimq-bench/src/scenarios/progress_throughput.rs b/chasquimq-bench/src/scenarios/progress_throughput.rs new file mode 100644 index 0000000..7bcef7f --- /dev/null +++ b/chasquimq-bench/src/scenarios/progress_throughput.rs @@ -0,0 +1,73 @@ +//! `progress_throughput`: measure the cost of calling +//! `JobHandle::update_progress` from inside a handler. +//! +//! Three sibling scenarios, one per K (progress calls per job): +//! `progress-throughput-1`, `progress-throughput-10`, +//! `progress-throughput-100`. Concurrency matches `worker-concurrent` +//! (100) so the headline jobs/sec column is apples-to-apples with the +//! no-progress baseline. +//! +//! Handler does nothing except call `update_progress` K times. The +//! progress value cycles 0..=100 so the engine's clamp short-circuit +//! never fires and we measure the steady-state SET cost. +//! +//! `events_progress_enabled` is wired through from a CLI flag (default +//! `false`) so users can isolate "just the progress key write" from +//! "progress key write + events XADD". +use super::ScenarioReport; +use super::preload::preload_jobs; +use super::scaled_params; +use super::worker_generic::drive_worker_scenario_with_handle_handler; +use crate::sample::{Payload, generate_sample}; +use chasquimq::config::ConsumerConfig; + +pub async fn run( + redis_url: &str, + queue: &str, + scale: u32, + calls_per_job: u32, + events_progress_enabled: bool, +) -> ScenarioReport { + let params = scaled_params(1_000, 10_000, scale); + let total = params.warmup + params.bench; + let payload: Payload = generate_sample(1, 1); + + preload_jobs(redis_url, queue, 4, &payload, total).await; + + let consumer_cfg = ConsumerConfig { + queue_name: queue.to_string(), + group: "bench".to_string(), + consumer_id: "w1".to_string(), + batch: 256, + block_ms: 100, + claim_min_idle_ms: 30_000, + concurrency: 100, + max_attempts: 3, + ack_batch: 256, + ack_idle_ms: 2, + shutdown_deadline_secs: 5, + max_payload_bytes: 1_048_576, + dlq_inflight: 64, + delayed_enabled: false, + run_scheduler: false, + events_progress_enabled, + ..Default::default() + }; + + let name: &'static str = match calls_per_job { + 1 => "progress-throughput-1", + 10 => "progress-throughput-10", + 100 => "progress-throughput-100", + _ => "progress-throughput-custom", + }; + + drive_worker_scenario_with_handle_handler( + redis_url, + consumer_cfg, + params.warmup, + params.bench, + name, + calls_per_job, + ) + .await +} diff --git a/chasquimq-bench/src/scenarios/worker_generic.rs b/chasquimq-bench/src/scenarios/worker_generic.rs index d064168..2caae73 100644 --- a/chasquimq-bench/src/scenarios/worker_generic.rs +++ b/chasquimq-bench/src/scenarios/worker_generic.rs @@ -119,3 +119,69 @@ where let _ = tokio::time::timeout(std::time::Duration::from_secs(10), join).await; outcome.into_report(name) } + +/// Variant of [`drive_worker_scenario_with_handler`] where the handler +/// receives the [`Job`] and calls `update_progress` on its +/// attached [`chasquimq::JobHandle`] `calls_per_job` times. Progress +/// values cycle `0..=100` to keep the engine's clamp short-circuit out +/// of the hot path. Used by the `progress_throughput` scenario. +pub(crate) async fn drive_worker_scenario_with_handle_handler( + redis_url: &str, + consumer_cfg: ConsumerConfig, + warmup: u64, + bench: u64, + name: &'static str, + calls_per_job: u32, +) -> ScenarioReport { + let sw = Arc::new(Mutex::new(Stopwatch::new(warmup, bench))); + let (done_tx, done_rx) = oneshot::channel::(); + let done_tx = Arc::new(Mutex::new(Some(done_tx))); + let shutdown = CancellationToken::new(); + let shutdown_clone = shutdown.clone(); + + let consumer: Consumer = Consumer::new(redis_url, consumer_cfg); + let join = tokio::spawn(async move { + consumer + .run( + { + let sw = sw.clone(); + let done_tx = done_tx.clone(); + let shutdown = shutdown_clone.clone(); + move |job: Job| { + let sw = sw.clone(); + let done_tx = done_tx.clone(); + let shutdown = shutdown.clone(); + async move { + if let Some(handle) = job.handle.as_ref() { + for i in 0..calls_per_job { + let pct = (i % 101) as u8; + handle + .update_progress(pct) + .await + .map_err(chasquimq::HandlerError::new)?; + } + } + let outcome = { + let mut guard = sw.lock().await; + guard.tick() + }; + if let Some(outcome) = outcome + && let Some(tx) = done_tx.lock().await.take() + { + let _ = tx.send(outcome); + shutdown.cancel(); + } + Ok(chasquimq::Bytes::new()) + } + } + }, + shutdown_clone, + ) + .await + }); + + let outcome = done_rx.await.expect("scenario must finish"); + shutdown.cancel(); + let _ = tokio::time::timeout(std::time::Duration::from_secs(10), join).await; + outcome.into_report(name) +} diff --git a/chasquimq-node/README.md b/chasquimq-node/README.md index f21c695..f400fab 100644 --- a/chasquimq-node/README.md +++ b/chasquimq-node/README.md @@ -68,9 +68,9 @@ main() | Surface | What it does | |---|---| -| `Queue` | Producer + queue inspection. `add` / `addBulk` / `addUnique` / `getJob` / `getJobs` / `getJobState` / `getJobCounts` / `getWaitingCount` / `getActiveCount` / `getDelayedCount` / `getCompletedCount` / `getFailedCount` / `count` / `getJobResult` / `peekDlq` / `replayDlq` / `cancelDelayed` / `getRepeatableJobs` / `removeRepeatableByKey` / `pause` / `resume` / `isPaused` / `remove` / `removeReport` / `drain` / `clean` / `obliterate`. `[Symbol.asyncDispose]`. | -| `Worker` | Consumer pool. tokio-side dispatch, opt-in result storage (`storeResults: true`), `EventEmitter` events (`ready` / `active` / `completed` / `failed` / `error` / `closing` / `closed` / `drained` / `paused` / `resumed`), `pause` / `resume` / `isPaused`. `[Symbol.asyncDispose]`. | -| `Job` | Read-only handle. `id`, `name`, `data`, `attemptsMade`, `waitForResult({ timeoutMs, intervalMs, signal })`, `waitUntilFinished(queueEvents, ttl?)`. | +| `Queue` | Producer + queue inspection. `add` / `addBulk` / `addUnique` / `getJob` / `getJobs` / `getJobState` / `getJobCounts` / `getJobLogs` / `getWaitingCount` / `getActiveCount` / `getDelayedCount` / `getCompletedCount` / `getFailedCount` / `count` / `getJobResult` / `peekDlq` / `replayDlq` / `cancelDelayed` / `getRepeatableJobs` / `removeRepeatableByKey` / `pause` / `resume` / `isPaused` / `remove` / `removeReport` / `drain` / `clean` / `obliterate`. `[Symbol.asyncDispose]`. | +| `Worker` | Consumer pool. tokio-side dispatch, opt-in result storage (`storeResults: true`), `EventEmitter` events (`ready` / `active` / `completed` / `failed` / `error` / `closing` / `closed` / `drained` / `paused` / `resumed` / `progress`), `pause` / `resume` / `isPaused`. `[Symbol.asyncDispose]`. | +| `Job` | Read-only handle. `id`, `name`, `data`, `attemptsMade`, `progress`, `updateProgress(n)` (Worker-side only), `log(line)` (Worker-side only), `waitForResult({ timeoutMs, intervalMs, signal })`, `waitUntilFinished(queueEvents, ttl?)`. | | `QueueEvents` | Cross-process pub/sub via the events stream. Subscribe to `waiting` / `active` / `completed` / `failed` / `dlq` / `retry-scheduled` / `delayed` / `drained` / `retries-exhausted`, plus per-id channels (`completed:` / `failed:` / `active:`) for targeted subscribers. `[Symbol.asyncDispose]`. | | `BackoffSpec` | Builders: `.fixed(delayMs)` / `.exponential(initialMs, { multiplier, maxMs, jitterMs })`. | | `UnrecoverableError` | Throw from your handler to bypass retries and route the job directly to DLQ. | @@ -243,7 +243,7 @@ await events.close() `completed` payloads from the events stream do **not** carry the handler's return value (that would double-allocate the payload onto every subscriber). To read the value, pair `QueueEvents` with `Queue.getJobResult(jobId)` and run the worker with `storeResults: true`. The next section's `Job.waitUntilFinished` does this for you. -`progress` and `stalled` listeners are accepted on `Worker` for API stability but are currently no-op — the engine doesn't emit those transitions yet. Attach them safely; they'll start firing when the corresponding engine work lands. +`progress` fires every time a processor calls `await job.updateProgress(n)` — the worker lazily spawns an embedded `QueueEvents` subscriber on the first `progress` listener (same zero-cost-when-unused pattern as `drained`) and re-emits the cross-process `e=progress` event as `(job, n)`. See the [Progress and logs](#progress-and-logs) section below. `stalled` is accepted on `Worker` for API stability but is currently no-op — the engine doesn't emit a stalled-detector transition yet; attach it safely, it'll start firing when the corresponding engine work lands. ### Awaiting a single job's completion @@ -336,6 +336,53 @@ await queue.obliterate() `remove` is idempotent — a job id that exists on no surface resolves without error (count `0`). `clean` ignores `grace` for `"completed"` (a stored result has no creation timestamp; rely on result TTL for time-based expiry). `clean` with `"active"` is a no-op — use `remove` for the deliberate per-job case. `obliterate` cannot be undone. +### Progress and logs + +In-handler write surface for live job state. The engine persists progress to a side-channel Redis key (`{chasqui:}:progress:` STRING, TTL = `result_ttl_secs`) and appends log lines to a per-job stream (`{chasqui:}:log:` STREAM with `MAXLEN ~`, TTL = `result_ttl_secs`). The msgpack `Job` envelope is untouched — wire-format-stable. + +```ts +const worker = new Worker("emails", async (job) => { + await job.updateProgress(10) + await job.log("connecting to SMTP") + + // ... work ... + await job.updateProgress(50) + await job.log("envelope sent") + + // ... work ... + await job.updateProgress(100) + return { delivered: true } +}, { connection }) +``` + +Read the latest progress (no extra round trip — pipelined into the existing introspector lookup) and the log lines from anywhere: + +```ts +const queue = new Queue("emails", { connection }) + +const job = await queue.getJob("job-123") +console.log(job?.progress) // => 50 + +const { logs, count } = await queue.getJobLogs("job-123") +// logs: string[] (the captured `line` field values, asc order) +// count: number (current XLEN — not logs.length — for paginating callers) + +// Page from the tail; matches BullMQ's getLogs(-100, -1) convention. +const tail = await queue.getJobLogs("job-123", -100, -1) +``` + +Tuning (all `WorkerOptions`): + +| Option | Default | Controls | +|---|---:|---| +| `logMaxLen` | `1000` | `MAXLEN ~` cap on each per-job log stream (must be `>= 16`). | +| `logMaxLineBytes` | `4096` | Per-line byte cap; oversize lines truncate on a UTF-8 char boundary with a `[…truncated]` marker. | +| `eventsProgressEnabled` | `true` | When `false`, mutes the `e=progress` events-stream entry — the persisted progress key is still written. Useful for high-rate progress reporters that don't need cross-process fan-out. | + +Subscribe to the cross-process `progress` event via `QueueEvents` (broadcast `progress`, per-id `progress:`) or the in-process `Worker.on('progress', (job, n) => ...)` re-fan. **Read-only Job guard:** calling `updateProgress` / `log` on a Job returned by `Queue.getJob` / `Queue.add` throws `Error('Job.updateProgress() requires the Job be passed to your Worker handler; Jobs returned by Queue.getJob() are read-only')` — only Jobs handed to a `Worker` processor carry the live native handle. + +> **Breaking (TS types only):** `JobProgress` narrowed from `number | object` to `number`. No runtime impact — the engine wire format never carried the object form. + ## Power-user surface The native engine handles ship from the same top-level package: diff --git a/chasquimq-node/__test__/progress-and-log.test.ts b/chasquimq-node/__test__/progress-and-log.test.ts new file mode 100644 index 0000000..8b5607a --- /dev/null +++ b/chasquimq-node/__test__/progress-and-log.test.ts @@ -0,0 +1,235 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import { Queue, QueueEvents, Worker } from '../dist/index.js' + +const REDIS_URL = process.env.REDIS_URL +const skipIfNoRedis = REDIS_URL ? describe : describe.skip + +skipIfNoRedis('Job progress + log', () => { + let queueName: string + let queue: Queue<{ value: number }> + let worker: Worker<{ value: number }> | undefined + let queueEvents: QueueEvents | undefined + + beforeEach(() => { + queueName = `qmq-progress-${Date.now()}-${Math.random().toString(36).slice(2, 8)}` + queue = new Queue<{ value: number }>(queueName, { + connection: parseConn(REDIS_URL!), + }) + }) + + afterEach(async () => { + if (worker) { + await worker.close().catch(() => {}) + worker = undefined + } + if (queueEvents) { + await queueEvents.close().catch(() => {}) + queueEvents = undefined + } + await queue.close().catch(() => {}) + }) + + it('handler updateProgress persists; getJob().progress reflects it', async () => { + const done = deferred() + worker = new Worker<{ value: number }>( + queueName, + async (job) => { + await job.updateProgress(50) + done.resolve() + // Hold the handler so the job stays Active while we introspect — + // a completed job with no stored result key disappears from the + // introspector's view, so we'd race the ack vs the read. + await sleep(500) + }, + { connection: parseConn(REDIS_URL!), autorun: false, concurrency: 1 }, + ) + void worker.run() + + const added = await queue.add('progress-one', { value: 1 }) + await done.promise + + const fetched = await queue.getJob(added.id) + expect(fetched).toBeDefined() + expect(fetched!.progress).toBe(50) + }, 15_000) + + it('QueueEvents emits per-id progress: with payload { jobId, name, progress }', async () => { + queueEvents = new QueueEvents(queueName, { + connection: parseConn(REDIS_URL!), + autorun: true, + blockingTimeout: 500, + }) + await queueEvents.waitUntilReady() + + const done = deferred() + worker = new Worker<{ value: number }>( + queueName, + async (job) => { + await job.updateProgress(33) + done.resolve() + }, + { connection: parseConn(REDIS_URL!), autorun: false, concurrency: 1 }, + ) + void worker.run() + + const job = await queue.add('emits-progress', { value: 1 }) + const targetedSpy = vi.fn() + const broadcastSpy = vi.fn() + queueEvents.on(`progress:${job.id}`, targetedSpy) + queueEvents.on('progress', broadcastSpy) + + await done.promise + await waitFor( + () => targetedSpy.mock.calls.length >= 1 && broadcastSpy.mock.calls.length >= 1, + 10_000, + ) + const [payload] = targetedSpy.mock.calls[0]! + expect(payload).toMatchObject({ + jobId: job.id, + name: 'emits-progress', + progress: 33, + }) + }, 15_000) + + it('Worker EE fires progress with (job, n) once per call', async () => { + const done = deferred() + const progressSpy = vi.fn() + worker = new Worker<{ value: number }>( + queueName, + async (job) => { + await job.updateProgress(10) + await job.updateProgress(50) + await job.updateProgress(100) + done.resolve() + }, + { connection: parseConn(REDIS_URL!), autorun: false, concurrency: 1 }, + ) + worker.on('progress', progressSpy) + void worker.run() + + await queue.add('three-updates', { value: 1 }) + await done.promise + await waitFor(() => progressSpy.mock.calls.length >= 3, 10_000) + expect(progressSpy).toHaveBeenCalledTimes(3) + const values = progressSpy.mock.calls.map((c) => c[1]) + expect(values).toEqual([10, 50, 100]) + }, 15_000) + + it('Job.log appends lines and Queue.getJobLogs reads them back', async () => { + const done = deferred() + worker = new Worker<{ value: number }>( + queueName, + async (job) => { + await job.log('A') + await job.log('B') + done.resolve() + }, + { connection: parseConn(REDIS_URL!), autorun: false, concurrency: 1 }, + ) + void worker.run() + + const added = await queue.add('logs-two', { value: 1 }) + await done.promise + + const logs = await queue.getJobLogs(added.id) + expect(logs).toEqual({ logs: ['A', 'B'], count: 2 }) + }, 15_000) + + it('Queue.getJobLogs pagination: start=2 end=4 asc=true returns 3 lines in order', async () => { + const done = deferred() + worker = new Worker<{ value: number }>( + queueName, + async (job) => { + for (let i = 0; i < 10; i++) { + await job.log(`L${i}`) + } + done.resolve() + }, + { connection: parseConn(REDIS_URL!), autorun: false, concurrency: 1 }, + ) + void worker.run() + + const added = await queue.add('logs-ten', { value: 1 }) + await done.promise + + const page = await queue.getJobLogs(added.id, 2, 4, true) + expect(page.logs).toEqual(['L2', 'L3', 'L4']) + expect(page.count).toBe(10) + }, 15_000) + + it('updateProgress(150) clamps to 100 instead of throwing', async () => { + const done = deferred() + worker = new Worker<{ value: number }>( + queueName, + async (job) => { + await expect(job.updateProgress(150)).resolves.toBeUndefined() + done.resolve() + // Keep the job Active while we read it back — same rationale as + // the persistence test above. + await sleep(500) + }, + { connection: parseConn(REDIS_URL!), autorun: false, concurrency: 1 }, + ) + void worker.run() + + const added = await queue.add('clamp', { value: 1 }) + await done.promise + const fetched = await queue.getJob(added.id) + expect(fetched).toBeDefined() + expect(fetched!.progress).toBe(100) + }, 15_000) + + it('Queue.getJob()-returned Job throws on updateProgress (read-only)', async () => { + // No worker — the job sits waiting, getJob synthesizes a read-only Job. + const added = await queue.add('read-only', { value: 1 }) + const fetched = await queue.getJob(added.id) + expect(fetched).toBeDefined() + await expect(fetched!.updateProgress(50)).rejects.toThrow( + /requires the Job be passed to your Worker handler/, + ) + await expect(fetched!.log('nope')).rejects.toThrow( + /requires the Job be passed to your Worker handler/, + ) + }) +}) + +interface Deferred { + promise: Promise + resolve: (v: T) => void + reject: (e: unknown) => void +} + +function deferred(): Deferred { + let resolve!: (v: T) => void + let reject!: (e: unknown) => void + const promise = new Promise((res, rej) => { + resolve = res + reject = rej + }) + return { promise, resolve, reject } +} + +async function waitFor(predicate: () => boolean, timeoutMs: number): Promise { + const start = Date.now() + while (!predicate()) { + if (Date.now() - start > timeoutMs) { + throw new Error(`waitFor timed out after ${timeoutMs}ms`) + } + await sleep(25) + } +} + +function sleep(ms: number): Promise { + return new Promise((res) => setTimeout(res, ms)) +} + +function parseConn(url: string) { + const u = new URL(url) + return { + host: u.hostname || '127.0.0.1', + port: u.port ? Number(u.port) : 6379, + password: u.password || undefined, + username: u.username || undefined, + db: u.pathname && u.pathname !== '/' ? Number(u.pathname.slice(1)) : undefined, + } +} diff --git a/chasquimq-node/src-ts/job.ts b/chasquimq-node/src-ts/job.ts index e80f105..6a7d3c5 100644 --- a/chasquimq-node/src-ts/job.ts +++ b/chasquimq-node/src-ts/job.ts @@ -8,6 +8,7 @@ // rewriting a stream entry (e.g. `update`) throw — Streams are append-only. import type { JobsOptions, JobState, JobProgress } from "./types.js"; +import type { Job as NativeJob } from "../index.js"; import { NotSupportedError, WaitForResultTimeoutError, @@ -16,6 +17,22 @@ import { import type { Queue } from "./queue.js"; import type { QueueEvents } from "./queue-events.js"; +/** + * Read-only `Job` guard. Thrown by {@link Job.updateProgress} and + * {@link Job.log} when the instance has no native handle backref — + * `Queue.getJob()` / `Queue.getJobs()` return synthesized `Job`s + * built from introspector data, with no per-handler connection. The + * write path requires the engine's per-dispatch `JobHandle`, which + * is attached only when the consumer hands a job to a `Worker` + * processor. Catch via `err.name === 'ReadOnlyJobError'`. + */ +const READ_ONLY_PROGRESS_MSG = + "Job.updateProgress() requires the Job be passed to your Worker handler; " + + "Jobs returned by Queue.getJob() are read-only"; +const READ_ONLY_LOG_MSG = + "Job.log() requires the Job be passed to your Worker handler; " + + "Jobs returned by Queue.getJob() are read-only"; + /** * Options for {@link Job.waitForResult}. */ @@ -69,6 +86,15 @@ export class Job< */ queue?: Queue; + /** + * Live native handle for in-handler progress + log writes. Set only + * when the engine's worker dispatched this `Job` to a processor — + * `Queue.getJob()` / `Queue.add()` paths leave this `undefined`, and + * `updateProgress` / `log` throw a clear "read-only Job" error to + * surface the contract violation early. + */ + private _native?: NativeJob; + constructor( name: NameType, data: DataType, @@ -86,16 +112,53 @@ export class Job< } /** - * In-memory progress update. The engine does not persist progress yet; - * the Worker shim will surface this via its `progress` event when called - * from inside a processor. + * @internal — wires the native `Job` handle in before the user + * processor sees this instance. The high-level `Worker` shim is the + * only call site; application code should not touch this. + */ + _attachNative(native: NativeJob): void { + this._native = native; + } + + /** + * Persist a `0..=100` progress value for this job under the engine's + * per-job progress key, mirror it on the local `progress` field, and + * (when `WorkerOptions.eventsProgressEnabled !== false`) emit an + * `e=progress` events-stream entry that `QueueEvents` re-fans onto + * the broadcast `'progress'` channel and the per-id + * `'progress:'` channel. + * + * Values outside `0..=100` are clamped to `100` at the engine + * boundary (no throw). Throws when called on a Job returned by + * {@link Queue.getJob} / {@link Queue.getJobs} — those instances are + * synthesized from introspector data and carry no per-handler + * connection; only Jobs handed to a `Worker` processor have a live + * backref. */ async updateProgress(progress: JobProgress): Promise { + if (!this._native) { + throw new Error(READ_ONLY_PROGRESS_MSG); + } + const n = Math.max(0, Math.floor(progress)); + await this._native.updateProgress(n); this.progress = progress; } - async log(_row: string): Promise { - throw new NotSupportedError("Job logs are not supported in v1"); + /** + * Append `line` to the per-job log stream + * (`{chasqui:}:log:`) and return the new XLEN. Oversize + * lines are truncated on a UTF-8 char boundary with a + * `[…truncated]` marker; the per-line cap is set by + * `WorkerOptions.logMaxLineBytes` (default 4096). Read back via + * {@link Queue.getJobLogs}. + * + * Same read-only Job guard as {@link Job.updateProgress}. + */ + async log(line: string): Promise { + if (!this._native) { + throw new Error(READ_ONLY_LOG_MSG); + } + return this._native.log(line); } async getState(): Promise { diff --git a/chasquimq-node/src-ts/queue-events.ts b/chasquimq-node/src-ts/queue-events.ts index 31cc824..8343950 100644 --- a/chasquimq-node/src-ts/queue-events.ts +++ b/chasquimq-node/src-ts/queue-events.ts @@ -208,6 +208,15 @@ export class QueueEvents extends EventEmitter { case 'delayed': this.emit('delayed', { jobId, name, delay: parseIntSafe(f['delay_ms']) }, eventId) break + case 'progress': { + // Persisted progress lives at `{chasqui:}:progress:` as + // an ASCII decimal `u8`; the events-stream entry carries the same + // value so per-job subscribers don't need a second GET round trip. + const progress = parseIntSafe(f['progress']) + this.emit('progress', { jobId, name, progress }, eventId) + if (jobId) this.emit(`progress:${jobId}`, { jobId, name, progress }, eventId) + break + } case 'dlq': // The engine already emitted a `failed` event from the worker // before relocating to the DLQ — fanning out a second synthetic diff --git a/chasquimq-node/src-ts/queue.ts b/chasquimq-node/src-ts/queue.ts index 7f1820f..bac61a0 100644 --- a/chasquimq-node/src-ts/queue.ts +++ b/chasquimq-node/src-ts/queue.ts @@ -563,9 +563,39 @@ export class Queue< if (info.decodeFailed) { job.failedReason = job.failedReason ?? "decode_failed"; } + if (info.progress !== undefined && info.progress !== null) { + job.progress = info.progress; + } return job; } + /** + * Read up to `count` lines from a job's log stream + * (`{chasqui:}:log:`). `start` / `end` are inclusive + * entry offsets in the requested order; `end = -1` means "to end"; + * negative `start` is "this many from the end" (translated via + * XLEN), matching BullMQ's `Queue.getJobLogs` convention. `asc` + * defaults to `true` (chronological). + * + * Returns `{ logs, count }` where `count` is the current XLEN of the + * log stream (NOT the number of lines returned — that's `logs.length`). + * `count` lets paginating callers know how many entries exist without + * walking the whole stream. + * + * Jobs that never called `Job.log` resolve with + * `{ logs: [], count: 0 }`. + */ + async getJobLogs( + jobId: string, + start: number = 0, + end: number = -1, + asc: boolean = true, + ): Promise<{ logs: string[]; count: number }> { + const insp = await this.introspector(); + const result = await insp.getJobLogs(jobId, start, end, asc); + return { logs: result.logs, count: result.count }; + } + /** * Durably pause every consumer of this queue. Sets a cross-process * Redis flag (`{chasqui:}:paused`); each worker stops dispatching diff --git a/chasquimq-node/src-ts/types.ts b/chasquimq-node/src-ts/types.ts index d735ae1..c11880e 100644 --- a/chasquimq-node/src-ts/types.ts +++ b/chasquimq-node/src-ts/types.ts @@ -17,7 +17,18 @@ // classes directly. Both will appear in autocomplete; reach for the // high-level shapes unless you've already opted into the native API. -export type JobProgress = number | object; +/** + * Per-handler progress value passed to {@link Job.updateProgress} and + * surfaced on the `Worker`'s `'progress'` event payload. + * + * **BREAKING (TS types, 1.4):** narrowed from `number | object` to + * `number`. The engine stores progress as a Redis STRING (ASCII decimal + * `u8`, clamped to `0..=100`) so the previous `object` arm was a + * non-functional carryover from the BullMQ-shaped type. Code using only + * numeric progress values is unaffected; object-progress callers must + * encode their state separately (e.g. via {@link Job.log}). + */ +export type JobProgress = number; /** * Resolved shape returned by a {@link ConnectionOptions.credentialProvider} diff --git a/chasquimq-node/src-ts/worker.ts b/chasquimq-node/src-ts/worker.ts index 03161a7..83c9eaf 100644 --- a/chasquimq-node/src-ts/worker.ts +++ b/chasquimq-node/src-ts/worker.ts @@ -141,6 +141,34 @@ export interface WorkerOptions { * boundary because Redis `EX` only accepts integer seconds. */ resultTtlMs?: number + + /** + * `MAXLEN ~` cap on the per-job log stream + * (`{chasqui:}:log:`). Default `1000`. Must be `>= 16` — + * below that, Redis's `MAXLEN ~` rounding can leave the stream + * effectively empty between writes (the engine rejects sub-minimum + * values at startup). Maps to `ConsumerConfig::log_max_stream_len`. + */ + logMaxLen?: number + + /** + * Per-line byte cap for {@link Job.log}. Oversize lines are + * truncated on a UTF-8 char boundary with a `[…truncated]` marker + * appended. Default `4096`. Maps to + * `ConsumerConfig::log_max_line_bytes`. + */ + logMaxLineBytes?: number + + /** + * Gate on the engine's `e=progress` events-stream entry emitted by + * {@link Job.updateProgress}. The persisted progress key is always + * written; setting this to `false` only mutes the events fan-out, + * which a {@link QueueEvents} subscriber would otherwise observe on + * the broadcast `'progress'` channel and the per-id + * `'progress:'` channel. Default `true`. Maps to + * `ConsumerConfig::events_progress_enabled`. + */ + eventsProgressEnabled?: boolean } // --------------------------------------------------------------------------- @@ -178,6 +206,16 @@ export interface WorkerOptions { * (does not reflect a cross-process `Queue.pause`). * - `resumed` — `()`. Fired when `.resume()` is called. Process-local. * + * - `progress` — `(job: Job, progress: JobProgress)`. Fired every time + * a processor calls `await job.updateProgress(n)`. The engine writes + * the persisted progress key first, then emits an `e=progress` event + * onto the events stream; the worker subscribes to its own + * {@link QueueEvents} subscriber (lazily spawned the first time a + * `progress` listener attaches) and re-emits onto this EE so callers + * see `(job, n)` in the same process that ran the handler. Disable + * the events fan-out (and therefore this event) by setting + * `WorkerOptions.eventsProgressEnabled = false`. + * * ## Listener names accepted for API stability but currently no-op * * These can be wired up without throwing, but the engine does not emit @@ -185,8 +223,6 @@ export interface WorkerOptions { * type-checking; promoted to active events when the corresponding * engine work lands. * - * - `progress` — `(job: Job, progress: JobProgress)`. Requires engine - * support for in-handler progress updates. Not yet emitted. * - `stalled` — `(jobId: string, prev: string)`. Requires a stalled- * detector in the engine. Not yet emitted. */ @@ -205,19 +241,28 @@ export class Worker< private runPromise?: Promise /** * Lazily-constructed events-stream subscriber that fans the engine's - * cross-process `drained` event onto this worker's `EventEmitter`. - * Created the first time a listener attaches to `'drained'`; torn - * down in `.close()`. Workers that never subscribe to `drained` pay - * no extra Redis connections. + * cross-process events (`drained`, `progress`) onto this worker's + * `EventEmitter`. Created the first time a listener attaches to + * `'drained'` or `'progress'`; torn down in `.close()`. Workers that + * never subscribe to either pay no extra Redis connections. */ - private drainedEvents?: QueueEvents + private internalEvents?: QueueEvents /** - * Resolves once the lazy drained subscriber has issued its first + * Resolves once the lazy internal subscriber has issued its first * `XREAD BLOCK`. `run()` awaits this (when set) so a user pattern of - * `worker.on('drained', cb); queue.add(...)` doesn't race the - * engine's first emit against the subscriber's connect+block. + * `worker.on('drained' | 'progress', cb); queue.add(...)` doesn't + * race the engine's first emit against the subscriber's connect+block. + */ + private internalEventsReadyPromise?: Promise + /** + * Map of in-flight `Job` instances by id, populated for the duration + * of each processor invocation. Used by the `progress` event forwarder + * to surface the same `Job` reference the handler is holding (so + * `worker.on('progress', (job, n) => ...)` and the handler observe + * identical state). Entries are removed in the handler's `finally` + * so the map stays bounded to current concurrency. */ - private drainedReadyPromise?: Promise + private inflight: Map> = new Map() constructor( name: string, @@ -248,6 +293,9 @@ export class Worker< storeResults: opts.storeResults, resultTtlMs: opts.resultTtlMs, reconnectMaxAttempts: opts.connection.reconnectMaxAttempts, + logMaxLen: opts.logMaxLen, + logMaxLineBytes: opts.logMaxLineBytes, + eventsProgressEnabled: opts.eventsProgressEnabled, } // Plumb the optional credentialProvider through to the native // Consumer constructor. `undefined` (the common path) collapses to @@ -258,12 +306,17 @@ export class Worker< this.native = new NativeConsumer(url, nativeOpts, opts.connection.credentialProvider) // Spawn the cross-process events-stream subscriber the first time - // a user attaches a `drained` listener. Using `newListener` (not a - // public method) keeps the API surface plain `EventEmitter`-shaped — - // users just call `worker.on('drained', ...)`, no extra setup. + // a user attaches a `drained` or `progress` listener. Using + // `newListener` (not a public method) keeps the API surface plain + // `EventEmitter`-shaped — users just call + // `worker.on('drained' | 'progress', ...)`, no extra setup. this.on('newListener', (event: string) => { - if (event === 'drained' && !this.drainedEvents && !this.closed) { - this.spawnDrainedSubscriber() + if ( + (event === 'drained' || event === 'progress') && + !this.internalEvents && + !this.closed + ) { + this.spawnInternalSubscriber() } }) @@ -278,19 +331,28 @@ export class Worker< /** * Lazily start a {@link QueueEvents} subscriber that forwards the - * engine's cross-process `drained` event onto this worker's - * `EventEmitter`. Idempotent — calling twice has no effect (the first - * call wins). Errors from the subscriber are forwarded to this - * worker's `error` channel so application code only needs one error - * subscription. + * engine's cross-process events (`drained`, `progress`) onto this + * worker's `EventEmitter`. Idempotent — calling twice has no effect + * (the first call wins). Errors from the subscriber are forwarded to + * this worker's `error` channel so application code only needs one + * error subscription. + * + * Progress event semantics: the engine emits one `e=progress` entry + * per `Job.updateProgress` call. This forwarder looks the live `Job` + * up by id in {@link Worker.inflight} (populated for the duration of + * the handler's run) so subscribers receive the same `Job` reference + * the handler is holding — identical to BullMQ's `(job, progress)` + * shape. Progress events for jobs whose handlers have already + * resolved are dropped silently; they would race the cleanup of the + * inflight map and arrive with no live `Job` to dispatch on. */ - private spawnDrainedSubscriber(): void { - if (this.drainedEvents) return + private spawnInternalSubscriber(): void { + if (this.internalEvents) return // `autorun: false` + explicit `await waitUntilReady` + explicit // `run()` lets us hold the worker's own `run()` until the // subscriber's first `XREAD BLOCK` is in flight. Without this, the - // engine's first `drained` emit (which fires within a few hundred - // ms of worker startup on a fresh queue) can race the subscriber's + // engine's first emit (which fires within a few hundred ms of + // worker startup on a fresh queue) can race the subscriber's // connect+block and the event is lost. `lastEventId: '$'` keeps // the subscriber from replaying ancient events from a long-lived // queue; the race window we close is the connect-and-block latency @@ -308,6 +370,17 @@ export class Worker< events.on('drained', () => { this.emit('drained') }) + events.on('progress', (payload: { jobId: string; name?: string; progress: number }) => { + const job = this.inflight.get(payload.jobId) + if (job) { + // Mirror the persisted progress onto the local Job so listeners + // and the handler observe consistent state. The handler itself + // already set this via `updateProgress`; this branch covers + // listeners that fire before the handler awaits. + job.progress = payload.progress + this.emit('progress', job, payload.progress) + } + }) // Forward subscriber errors onto the worker's single ``error`` // channel so application code only needs one error subscription. // Caller MUST wire a ``worker.on('error', ...)`` listener — an @@ -318,7 +391,7 @@ export class Worker< this.emit('error', err) } }) - this.drainedEvents = events + this.internalEvents = events // Capture a ready promise that `run()` awaits before kicking the // native engine. `waitUntilReady()` establishes the ioredis // connection; the subsequent `run()` queues the first `XREAD @@ -328,7 +401,7 @@ export class Worker< // Errors surface via the `error` forwarder above so the worker's // single error channel stays canonical. let resolveReady!: () => void - this.drainedReadyPromise = new Promise((res) => { + this.internalEventsReadyPromise = new Promise((res) => { resolveReady = res }) void (async () => { @@ -368,12 +441,13 @@ export class Worker< this.running = true this.emit('ready') - // If a `drained` listener attached before `run()` was called, hold - // the engine start until the subscriber's `XREAD BLOCK` is in - // flight. Best-effort: the gate releases on subscriber error too, - // so a Redis blip on the events stream cannot wedge the worker. - if (this.drainedReadyPromise) { - await this.drainedReadyPromise + // If a `drained` or `progress` listener attached before `run()` + // was called, hold the engine start until the subscriber's `XREAD + // BLOCK` is in flight. Best-effort: the gate releases on + // subscriber error too, so a Redis blip on the events stream + // cannot wedge the worker. + if (this.internalEventsReadyPromise) { + await this.internalEventsReadyPromise } const storeResults = this.opts.storeResults === true @@ -392,6 +466,13 @@ export class Worker< nativeJob.id, ) job.attemptsMade = nativeJob.attempt + // Wire the native handle in BEFORE the handler runs so a processor + // that calls `await job.updateProgress(n)` reaches the engine's + // per-dispatch `JobHandle`. Track in `inflight` for the duration + // of the handler so the `progress` events forwarder can surface + // the same Job reference the handler is holding. + job._attachNative(nativeJob) + this.inflight.set(nativeJob.id, job) this.emit('active', job, '') try { const result = await this.processor(job) @@ -417,6 +498,8 @@ export class Worker< // budget. Re-throw so the rejection propagates verbatim — the // binding sees the same error shape regardless of subclass. throw e + } finally { + this.inflight.delete(nativeJob.id) } } @@ -456,14 +539,14 @@ export class Worker< /* swallow — already surfaced via 'error' */ } } - // Tear down the lazy drained subscriber if one was started. Best- + // Tear down the lazy internal subscriber if one was started. Best- // effort: swallow errors so a transient Redis blip on close doesn't // mask the worker's own shutdown path. - if (this.drainedEvents) { - await this.drainedEvents.close().catch(() => { + if (this.internalEvents) { + await this.internalEvents.close().catch(() => { /* best-effort cleanup */ }) - this.drainedEvents = undefined + this.internalEvents = undefined } this.running = false this.emit('closed') diff --git a/chasquimq-node/src/consumer.rs b/chasquimq-node/src/consumer.rs index ef0b7ed..8427ca1 100644 --- a/chasquimq-node/src/consumer.rs +++ b/chasquimq-node/src/consumer.rs @@ -17,7 +17,7 @@ use crate::producer::map_engine_err; use bytes::Bytes; use chasquimq::config::{ConsumerConfig, RetryConfig}; use chasquimq::consumer::Consumer as EngineConsumer; -use chasquimq::{HandlerError, Job as EngineJob, PauseControl}; +use chasquimq::{HandlerError, Job as EngineJob, JobHandle as EngineJobHandle, PauseControl}; use napi::bindgen_prelude::*; use napi::sys; use napi::threadsafe_function::{ErrorStrategy, ThreadsafeFunction}; @@ -64,22 +64,118 @@ pub struct ConsumerOpts { /// rejecting `credentialProvider` gives up instead of looping /// forever on reconnect. Maps to `ConnectionTuning::reconnect_max_attempts`. pub reconnect_max_attempts: Option, + /// `MAXLEN ~` cap on the per-job log stream + /// (`{chasqui:}:log:`). Default `1000`. Must be `>= 16`; + /// below that, Redis's `MAXLEN ~` rounding can leave the stream + /// effectively empty between writes. Maps to + /// `ConsumerConfig::log_max_stream_len`. + pub log_max_len: Option, + /// Per-line byte cap for `Job.log`. Oversize lines are truncated on + /// a UTF-8 char boundary with a `[…truncated]` marker appended. + /// Default `4096`. Maps to `ConsumerConfig::log_max_line_bytes`. + pub log_max_line_bytes: Option, + /// Gate on the engine's `e=progress` events-stream entry. The + /// persisted progress key is always written; setting this to `false` + /// only mutes the events fan-out (useful when a hot-loop handler + /// would otherwise flood the events stream). Default `true`. Maps + /// to `ConsumerConfig::events_progress_enabled`. + pub events_progress_enabled: Option, } -#[napi(object)] +/// `Job` is a `#[napi]` class (not a plain object) so it can carry the +/// engine's `Arc` opaquely across the FFI boundary and expose +/// `updateProgress` / `log` as async instance methods. The data fields +/// are surfaced via `#[napi(getter)]` to preserve the same JS-side +/// `(job.id, job.name, ...)` access shape the previous plain-object +/// binding had — high-level shim consumers do not need to change. +/// +/// `payload` is stored as `Vec` (not `Buffer`) so the class is +/// `Send + Sync` and the async `updateProgress` / `log` methods can +/// await across thread boundaries; a fresh `Buffer` is materialized in +/// the getter (one copy per JS access, same per-job-dispatch cost as +/// before — the previous binding also copied once at the FFI edge). +#[napi] pub struct Job { - pub id: String, + id: String, + name: String, + payload: Vec, + created_at_ms: i64, + attempt: u32, + /// `Some` for jobs the engine's worker dispatched to a handler + /// (the only path the consumer runs through). `None` would only + /// occur on synthesized `Job` instances — none exist on the NAPI + /// surface today, but the read-only branch is mirrored in the + /// TypeScript shim's `Job` so users get a clear "this Job came from + /// getJob() and is read-only" error. + handle: Option>, +} + +#[napi] +impl Job { + #[napi(getter)] + pub fn id(&self) -> &str { + &self.id + } + /// Dispatch name from the source stream entry's `n` field. Empty when /// the entry had no `n` (legacy producers, delayed-path re-encodes, /// repeatable scheduler fires). - pub name: String, - pub payload: Buffer, + #[napi(getter)] + pub fn name(&self) -> &str { + &self.name + } + + #[napi(getter)] + pub fn payload(&self) -> Buffer { + Buffer::from(self.payload.clone()) + } + /// `i64` so JS can read it as a regular `number` (safe up to 2^53-1 /// ms ≈ year 287396; far past any realistic Job timestamp). Using /// BigInt here would force every JS handler to do `Number(ts)` /// arithmetic, which we'd rather not impose on the hot path. - pub created_at_ms: i64, - pub attempt: u32, + #[napi(getter, js_name = "createdAtMs")] + pub fn created_at_ms(&self) -> i64 { + self.created_at_ms + } + + #[napi(getter)] + pub fn attempt(&self) -> u32 { + self.attempt + } + + /// Update the persisted progress key for this job. Values outside + /// `0..=100` are clamped at the engine boundary; the call resolves + /// once the SET round trip completes. A `JobHandle` is attached only + /// when the engine's worker dispatched this job to a handler; this + /// rejects with an error when the job has no backref (the high-level + /// shim then re-throws as the read-only-Job guard). + #[napi(js_name = "updateProgress")] + pub async fn update_progress(&self, n: u32) -> napi::Result<()> { + let handle = self.handle.as_ref().ok_or_else(|| { + napi::Error::from_reason( + "Job.updateProgress() requires a live JobHandle (this Job has none)", + ) + })?; + let clamped = n.min(u8::MAX as u32) as u8; + handle + .update_progress(clamped) + .await + .map_err(map_engine_err) + } + + /// Append `line` to the per-job log stream and return the new XLEN + /// (one XADD + XLEN, pipelined). Oversize lines are truncated on a + /// UTF-8 char boundary with a `[…truncated]` marker; the engine + /// reads the cap from `ConsumerConfig::log_max_line_bytes`. + #[napi] + pub async fn log(&self, line: String) -> napi::Result { + let handle = self.handle.as_ref().ok_or_else(|| { + napi::Error::from_reason("Job.log() requires a live JobHandle (this Job has none)") + })?; + let len = handle.log(&line).await.map_err(map_engine_err)?; + Ok(len.min(u32::MAX as u64) as u32) + } } #[napi] @@ -182,9 +278,10 @@ impl Consumer { let js_job = Job { id: job.id, name: job.name, - payload: Buffer::from(job.payload.0.to_vec()), + payload: job.payload.0.to_vec(), created_at_ms: clamp_u64_to_i64(job.created_at_ms), attempt: job.attempt, + handle: job.handle, }; // `call_async::>` resolves @@ -360,6 +457,15 @@ fn build_consumer_config(opts: Option) -> napi::Result, pub failure_detail: Option, pub decode_failed: bool, + /// Latest progress value the handler reported via + /// `Job.updateProgress`, clamped to `0..=100`. `undefined` when the + /// handler never called `updateProgress`, the progress key has + /// already expired (TTL `resultTtlMs`), or the value couldn't be + /// decoded as a `u8`. Only populated by `getJob`; `getJobs` leaves + /// it `undefined` to keep paginated listings off the per-id GET tax. + pub progress: Option, +} + +/// Result of [`Introspector::getJobLogs`]: the captured `line` field +/// values plus the current XLEN of the per-job log stream. +#[napi(object)] +pub struct JobLogs { + pub logs: Vec, + pub count: u32, } /// One page of [`Introspector::getJobs`] results. @@ -141,6 +156,36 @@ impl Introspector { Ok(opt.map(engine_info_into_napi)) } + /// Read up to `count` lines from the per-job log stream + /// (`{chasqui:}:log:`). `start` / `end` are inclusive + /// entry offsets in the requested order; `end = -1` means "to end"; + /// negative `start` is "this many from the end" (translated via + /// XLEN), matching BullMQ's `getLogs` convention. `asc = true` + /// returns lines in append order, `false` in reverse. + #[napi] + pub async fn get_job_logs( + &self, + id: String, + start: Option, + end: Option, + asc: Option, + ) -> napi::Result { + let (lines, count) = self + .inner + .get_job_logs( + &id, + start.unwrap_or(0) as i64, + end.unwrap_or(-1) as i64, + asc.unwrap_or(true), + ) + .await + .map_err(map_engine_err)?; + Ok(JobLogs { + logs: lines, + count: count.min(u32::MAX as u64) as u32, + }) + } + /// `state`: one of `"waiting" | "active" | "delayed" | "completed" | "failed"`. /// Pagination shape per state — see `chasquimq::Introspector::get_jobs` /// doc for the canonical semantics. @@ -187,6 +232,7 @@ fn engine_info_into_napi(info: chasquimq::JobInfo) -> JobInfo { failure_reason: info.failure_reason, failure_detail: info.failure_detail, decode_failed: info.decode_failed, + progress: info.progress.map(|n| n as u32), } } diff --git a/chasquimq-py/README.md b/chasquimq-py/README.md index fab2aee..028cfe4 100644 --- a/chasquimq-py/README.md +++ b/chasquimq-py/README.md @@ -64,9 +64,9 @@ asyncio.run(main()) | Surface | What it does | |---|---| -| `Queue` | Producer + queue inspection. `add` / `add_bulk` / `add_unique` / `get_job` / `get_jobs` / `get_jobs_page` / `get_job_state` / `get_job_counts` / `get_waiting_count` / `get_active_count` / `get_delayed_count` / `get_completed_count` / `get_failed_count` / `count` / `get_job_result` / `peek_dlq` / `replay_dlq` / `cancel_delayed` / `get_repeatable_jobs` / `remove_repeatable_by_key` / `pause` / `resume` / `is_paused` / `remove` / `remove_report` / `drain` / `clean` / `obliterate`. Async context manager. | -| `Worker` | Consumer pool. asyncio-first dispatch, opt-in result storage (`store_results=True`), graceful shutdown, `pause` / `resume` / `is_paused`, listener API (`on`/`off`/`once` for `ready` / `active` / `completed` / `failed` / `error` / `closing` / `closed` / `drained` / `paused` / `resumed`). Async context manager. | -| `Job` | Dataclass returned by `Queue.add`. Has `id`, `name`, `data`, `attempts_made`, `wait_for_result(timeout=)`, `wait_until_finished(queue_events, timeout=)`. | +| `Queue` | Producer + queue inspection. `add` / `add_bulk` / `add_unique` / `get_job` / `get_jobs` / `get_jobs_page` / `get_job_state` / `get_job_counts` / `get_job_logs` / `get_waiting_count` / `get_active_count` / `get_delayed_count` / `get_completed_count` / `get_failed_count` / `count` / `get_job_result` / `peek_dlq` / `replay_dlq` / `cancel_delayed` / `get_repeatable_jobs` / `remove_repeatable_by_key` / `pause` / `resume` / `is_paused` / `remove` / `remove_report` / `drain` / `clean` / `obliterate`. Async context manager. | +| `Worker` | Consumer pool. asyncio-first dispatch, opt-in result storage (`store_results=True`), graceful shutdown, `pause` / `resume` / `is_paused`, listener API (`on`/`off`/`once` for `ready` / `active` / `completed` / `failed` / `error` / `closing` / `closed` / `drained` / `paused` / `resumed` / `progress`). Async context manager. | +| `Job` | Dataclass returned by `Queue.add`. Has `id`, `name`, `data`, `attempts_made`, `progress`, `update_progress(n)` (Worker-side only), `log(line)` (Worker-side only), `wait_for_result(timeout=)`, `wait_until_finished(queue_events, timeout=)`. | | `QueueEvents` | Async-iterator + listener API over the engine events stream. Cross-process pub/sub for `waiting` / `active` / `completed` / `failed` / `dlq` / `retry-scheduled` / `delayed` / `drained` / `retries-exhausted`, plus per-id channels (`completed:` / `failed:` / `active:`) for targeted subscribers. | | `BackoffSpec` | Builders: `.fixed(delay_ms)` / `.exponential(initial_ms, multiplier, max_ms, jitter_ms)`. | | `RepeatPattern` | Builders: `.cron(expr, tz=)` / `.every(interval_ms)`. DST-aware via IANA tz names. | @@ -270,7 +270,7 @@ async for ev in events: `completed` payloads from the events stream do **not** carry the handler's return value (that would double-allocate the payload onto every subscriber). To read the value, pair `QueueEvents` with `Queue.get_job_result(job_id)` and run the worker with `store_results=True`. The next section's `Job.wait_until_finished` does this for you. -`progress` and `stalled` listeners are accepted on `Worker` for parity but are currently no-op — the engine doesn't emit those transitions yet. Attach them safely; they'll start firing when the corresponding engine work lands. +`progress` fires every time a processor calls `await job.update_progress(n)` — the worker lazily spawns an embedded `QueueEvents` subscriber on the first `progress` listener (same zero-cost-when-unused pattern as `drained`) and re-emits the cross-process `e=progress` event as `(job, n)`. See the [Progress and logs](#progress-and-logs) section below. `stalled` is accepted on `Worker` for parity but is currently no-op — the engine doesn't emit a stalled-detector transition yet; attach it safely, it'll start firing when the corresponding engine work lands. ### Awaiting a single job's completion @@ -366,6 +366,51 @@ async with Queue("emails", redis_url=url) as queue: `remove` is idempotent — a job id that exists on no surface resolves without error (count `0`). `clean` ignores `grace_ms` for `"completed"` (a stored result has no creation timestamp; rely on result TTL for time-based expiry). `clean` with `"active"` is a no-op — use `remove` for the deliberate per-job case. `obliterate` cannot be undone. +### Progress and logs + +In-handler write surface for live job state. The engine persists progress to a side-channel Redis key (`{chasqui:}:progress:` STRING, TTL = `result_ttl_secs`) and appends log lines to a per-job stream (`{chasqui:}:log:` STREAM with `MAXLEN ~`, TTL = `result_ttl_secs`). The msgpack `Job` envelope is untouched — wire-format-stable. + +```python +async def handler(job: Job) -> dict: + await job.update_progress(10) + await job.log("connecting to SMTP") + + # ... work ... + await job.update_progress(50) + await job.log("envelope sent") + + # ... work ... + await job.update_progress(100) + return {"delivered": True} + +worker = Worker("emails", handler, redis_url=url) +``` + +Read the latest progress (no extra round trip — pipelined into the existing introspector lookup) and the log lines from anywhere: + +```python +async with Queue("emails", redis_url=url) as queue: + job = await queue.get_job("job-123") + print(job.progress) # => 50 + + lines, count = await queue.get_job_logs("job-123") + # lines: list[str] (captured `line` field values, asc order) + # count: int (current XLEN — not len(lines) — for paginating callers) + + # Page from the tail; matches BullMQ's getLogs(-100, -1) convention. + tail, _ = await queue.get_job_logs("job-123", start=-100, end=-1) +``` + +Tuning (all `Worker` keyword args): + +| Option | Default | Controls | +|---|---:|---| +| `log_max_stream_len` | `1000` | `MAXLEN ~` cap on each per-job log stream (must be `>= 16`). | +| `log_max_line_bytes` | `4096` | Per-line byte cap; oversize lines truncate on a UTF-8 char boundary with a `[…truncated]` marker. | +| `events_progress_enabled` | `True` | When `False`, mutes the `e=progress` events-stream entry — the persisted progress key is still written. Useful for high-rate progress reporters that don't need cross-process fan-out. | + +Subscribe to the cross-process `progress` event via `QueueEvents` (broadcast `progress`, per-id `progress:`) or the in-process `worker.on('progress', ...)` re-fan. **Read-only Job guard:** calling `update_progress` / `log` on a Job returned by `Queue.get_job` / `Queue.add` raises `RuntimeError("Job.update_progress() requires the Job be passed to your worker handler; Jobs returned by Queue.get_job() are read-only")` — only Jobs handed to a `Worker` processor carry the live native handle. + ## Power-user surface The native engine handles ship from the same top-level package: diff --git a/chasquimq-py/src-rs/consumer.rs b/chasquimq-py/src-rs/consumer.rs index b50389a..0932411 100644 --- a/chasquimq-py/src-rs/consumer.rs +++ b/chasquimq-py/src-rs/consumer.rs @@ -62,6 +62,9 @@ impl Consumer { result_ttl_ms = None, reconnect_max_attempts = None, credential_provider = None, + log_max_stream_len = None, + log_max_line_bytes = None, + events_progress_enabled = None, ))] #[allow(clippy::too_many_arguments)] fn new( @@ -85,6 +88,9 @@ impl Consumer { result_ttl_ms: Option, reconnect_max_attempts: Option, credential_provider: Option>, + log_max_stream_len: Option, + log_max_line_bytes: Option, + events_progress_enabled: Option, ) -> PyResult { let mut cfg = ConsumerConfig { queue_name, @@ -160,6 +166,15 @@ impl Consumer { let provider = PyCredentialProvider::new(py, cb)?; cfg.connection.credential_provider = Some(Arc::new(provider)); } + if let Some(v) = log_max_stream_len { + cfg.log_max_stream_len = v; + } + if let Some(v) = log_max_line_bytes { + cfg.log_max_line_bytes = v as usize; + } + if let Some(v) = events_progress_enabled { + cfg.events_progress_enabled = v; + } let unrecoverable_cls = py .import("chasquimq.errors")? diff --git a/chasquimq-py/src-rs/introspector.rs b/chasquimq-py/src-rs/introspector.rs index 63f55c2..aedee71 100644 --- a/chasquimq-py/src-rs/introspector.rs +++ b/chasquimq-py/src-rs/introspector.rs @@ -117,6 +117,38 @@ impl Introspector { }) } + /// XRANGE / XREVRANGE the per-job log stream for `id`. Returns + /// `(list[str], int)`: the captured lines plus the current XLEN of + /// the log stream. `start = 0` / `end = -1` are the BullMQ defaults + /// ("everything in order"). Negative `start` is "this many from the + /// end" (translated via XLEN). Mirrors `chasquimq-node/src/ + /// introspector.rs::Introspector::getJobLogs`. + #[pyo3(signature = (id, start = 0, end = -1, asc = true))] + fn get_job_logs<'py>( + &self, + py: Python<'py>, + id: String, + start: i64, + end: i64, + asc: bool, + ) -> PyResult> { + let inner = self.inner.clone(); + pyo3_async_runtimes::tokio::future_into_py(py, async move { + let (lines, total) = inner + .get_job_logs(&id, start, end, asc) + .await + .map_err(map_engine_err)?; + Python::attach(|py| { + let list = PyList::empty(py); + for line in lines { + list.append(line)?; + } + let tup = (list.unbind(), total).into_py_any(py)?; + Ok::, PyErr>(tup) + }) + }) + } + #[pyo3(signature = (state, offset = 0, limit = 100, cursor = None))] fn get_jobs<'py>( &self, @@ -168,5 +200,6 @@ fn job_info_to_dict<'py>(py: Python<'py>, info: &EngineJobInfo) -> PyResult>`: `Some` for jobs the +//! engine's worker dispatched to a handler (the consumer's hot path +//! `JobHandle::new(...)` lands here), `None` would only occur on +//! synthesized `_Job` instances — none exist on the PyO3 surface today, +//! but the read-only branch is mirrored in the high-level Python `Job` +//! dataclass so users get a clear "this Job came from get_job() and is +//! read-only" error. use crate::payload::RawBytes; -use chasquimq::Job as EngineJob; +use crate::producer::map_engine_err; +use chasquimq::{Job as EngineJob, JobHandle as EngineJobHandle}; +use pyo3::exceptions::PyRuntimeError; use pyo3::prelude::*; use pyo3::types::PyBytes; +use std::sync::Arc; -#[pyclass(module = "chasquimq._native", name = "_Job", frozen)] +#[pyclass(module = "chasquimq._native", name = "_Job")] pub struct Job { id: String, name: String, payload: Vec, created_at_ms: u64, attempt: u32, + handle: Option>, } impl Job { @@ -26,6 +38,7 @@ impl Job { payload: job.payload.0.to_vec(), created_at_ms: job.created_at_ms, attempt: job.attempt, + handle: job.handle, } } } @@ -57,6 +70,47 @@ impl Job { self.attempt } + /// Persist a `0..=100` progress value for this job under the engine's + /// per-job progress key. Values outside `0..=100` are clamped at the + /// engine boundary; the call resolves once the SET round trip + /// completes. A `JobHandle` is attached only when the engine's + /// worker dispatched this job to a handler; this raises a Python + /// `RuntimeError` when the job has no backref (the high-level shim + /// then re-raises as the read-only-Job guard). + fn update_progress<'py>(&self, py: Python<'py>, n: u32) -> PyResult> { + let handle = self.handle.clone().ok_or_else(|| { + PyRuntimeError::new_err( + "Job.update_progress() requires the Job be passed to your worker handler; \ + Jobs returned by Queue.get_job() are read-only", + ) + })?; + let clamped = n.min(u8::MAX as u32) as u8; + pyo3_async_runtimes::tokio::future_into_py(py, async move { + handle + .update_progress(clamped) + .await + .map_err(map_engine_err) + }) + } + + /// Append `line` to the per-job log stream and return the new XLEN. + /// Oversize lines are truncated on a UTF-8 char boundary with a + /// `[…truncated]` marker (engine-side; see + /// `ConsumerConfig::log_max_line_bytes`). Same read-only-Job guard + /// as `update_progress`. + fn log<'py>(&self, py: Python<'py>, line: String) -> PyResult> { + let handle = self.handle.clone().ok_or_else(|| { + PyRuntimeError::new_err( + "Job.log() requires the Job be passed to your worker handler; \ + Jobs returned by Queue.get_job() are read-only", + ) + })?; + pyo3_async_runtimes::tokio::future_into_py(py, async move { + let new_len = handle.log(&line).await.map_err(map_engine_err)?; + Ok::(new_len) + }) + } + fn __repr__(&self) -> String { format!( "Job(id={:?}, name={:?}, attempt={}, created_at_ms={}, payload_len={})", diff --git a/chasquimq-py/src/chasquimq/_native.pyi b/chasquimq-py/src/chasquimq/_native.pyi index ff8cfa5..88d5377 100644 --- a/chasquimq-py/src/chasquimq/_native.pyi +++ b/chasquimq-py/src/chasquimq/_native.pyi @@ -17,6 +17,8 @@ class _Job: def created_at_ms(self) -> int: ... @property def attempt(self) -> int: ... + def update_progress(self, n: int) -> Awaitable[None]: ... + def log(self, line: str) -> Awaitable[int]: ... class Producer: def __init__( @@ -107,6 +109,9 @@ class Consumer: result_ttl_ms: Optional[int] = None, reconnect_max_attempts: Optional[int] = None, credential_provider: Optional[CredentialProvider] = None, + log_max_stream_len: Optional[int] = None, + log_max_line_bytes: Optional[int] = None, + events_progress_enabled: Optional[bool] = None, ) -> None: ... def run( self, handler: Callable[[_Job], Awaitable[Any]] @@ -153,3 +158,10 @@ class Introspector: limit: int = 100, cursor: Optional[str] = None, ) -> Awaitable[Tuple[list[dict[str, Any]], Optional[str]]]: ... + def get_job_logs( + self, + id: str, + start: int = 0, + end: int = -1, + asc: bool = True, + ) -> Awaitable[Tuple[list[str], int]]: ... diff --git a/chasquimq-py/src/chasquimq/job.py b/chasquimq-py/src/chasquimq/job.py index 10887f8..250d3ca 100644 --- a/chasquimq-py/src/chasquimq/job.py +++ b/chasquimq-py/src/chasquimq/job.py @@ -49,11 +49,80 @@ class Job: default=None, repr=False, compare=False, hash=False ) + # Latest progress value persisted via :meth:`update_progress`, or + # the introspector-read value when :meth:`Queue.get_job` populated + # this Job from the per-job progress key. ``None`` when no progress + # has been recorded. + progress: Optional[int] = field( + default=None, repr=False, compare=False, hash=False + ) + + # Opaque native handle. Set by the :class:`Worker` shim's native + # handler bridge before the user processor sees this :class:`Job` + # instance — :meth:`update_progress` and :meth:`log` then forward to + # the engine's per-dispatch ``JobHandle``. ``None`` on Jobs + # synthesized by :meth:`Queue.get_job` / :meth:`Queue.add` / etc.; + # those Jobs are read-only on the progress + log surface and the + # methods raise a clear error. + _handle: Optional[Any] = field( + default=None, repr=False, compare=False, hash=False + ) + @property def attempts_made(self) -> int: """Alias for :attr:`attempt` — matches BullMQ naming for compatibility.""" return self.attempt + async def update_progress(self, n: int) -> None: + """Persist a ``0..=100`` progress value for this job. + + The engine clamps values outside ``0..=100`` to ``100`` (no + throw). After the persisted SET succeeds the engine emits a + best-effort ``e=progress`` events-stream entry so + :class:`QueueEvents` subscribers can fan it out onto the + broadcast ``'progress'`` channel and the per-id + ``'progress:'`` channel; mute the events fan-out via + ``Worker(events_progress_enabled=False)``. + + **Read-only Job guard.** Jobs returned by :meth:`Queue.get_job`, + :meth:`Queue.get_jobs`, or constructed by :meth:`Queue.add` are + synthesized from introspector / producer-side data and carry no + live native handle; calling :meth:`update_progress` on those + raises :class:`RuntimeError`. Only Jobs handed to a + :class:`Worker` processor have a backref. + """ + if self._handle is None: + raise RuntimeError( + "Job.update_progress() requires the Job be passed to your " + "worker handler; Jobs returned by Queue.get_job() are " + "read-only" + ) + clamped = max(0, int(n)) + await self._handle.update_progress(clamped) + # Mirror the persisted value onto the local Job so subsequent + # ``job.progress`` reads in the handler observe consistent state + # with the events stream / introspector view. Engine clamps to + # ``100``; mirror that. + self.progress = min(clamped, 100) + + async def log(self, line: str) -> int: + """Append ``line`` to the per-job log stream and return the new + XLEN. + + Oversize lines are truncated on a UTF-8 char boundary with a + ``[…truncated]`` marker; the per-line cap is set by + ``Worker(log_max_line_bytes=...)`` (default ``4096``). Read back + via :meth:`Queue.get_job_logs`. + + Same read-only Job guard as :meth:`update_progress`. + """ + if self._handle is None: + raise RuntimeError( + "Job.log() requires the Job be passed to your worker " + "handler; Jobs returned by Queue.get_job() are read-only" + ) + return int(await self._handle.log(line)) + async def wait_for_result( self, *, diff --git a/chasquimq-py/src/chasquimq/queue.py b/chasquimq-py/src/chasquimq/queue.py index 3ff0ddc..b8fe5d5 100644 --- a/chasquimq-py/src/chasquimq/queue.py +++ b/chasquimq-py/src/chasquimq/queue.py @@ -682,6 +682,32 @@ async def get_jobs_page( jobs = [self._native_info_to_job(info) for info in rows] return jobs, next_cursor + async def get_job_logs( + self, + job_id: str, + *, + start: int = 0, + end: int = -1, + asc: bool = True, + ) -> Tuple[list[str], int]: + """Read lines from a job's log stream + (``{chasqui:}:log:``). + + ``start`` / ``end`` are inclusive entry offsets in the requested + order; ``end = -1`` means "to end"; negative ``start`` is "this + many from the end" (translated via XLEN), matching BullMQ's + ``Queue.getJobLogs`` convention. ``asc`` defaults to ``True`` + (chronological). + + Returns ``(lines, count)`` where ``count`` is the current XLEN of + the log stream (NOT the number of lines returned — that's + ``len(lines)``). ``count`` lets paginating callers know how many + entries exist without walking the whole stream. Jobs that never + called :meth:`Job.log` resolve with ``([], 0)``. + """ + insp = self._get_introspector() + return await insp.get_job_logs(job_id, start, end, asc) + async def get_waiting_count(self) -> int: c = await self.get_job_counts("waiting") return c.get("waiting", 0) @@ -721,6 +747,8 @@ def _native_info_to_job(self, info: dict[str, Any]) -> Job: data = decode_payload(raw_payload) except Exception: data = raw_payload + progress_raw = info.get("progress") + progress = int(progress_raw) if progress_raw is not None else None return Job( id=info["id"], name=info.get("name") or "", @@ -728,6 +756,7 @@ def _native_info_to_job(self, info: dict[str, Any]) -> Job: attempt=int(info.get("attempt", 0)), created_at_ms=int(info.get("created_at_ms", 0)), _queue=self, + progress=progress, ) async def close(self) -> None: diff --git a/chasquimq-py/src/chasquimq/queue_events.py b/chasquimq-py/src/chasquimq/queue_events.py index e2f3161..67fa968 100644 --- a/chasquimq-py/src/chasquimq/queue_events.py +++ b/chasquimq-py/src/chasquimq/queue_events.py @@ -407,7 +407,7 @@ def _to_str(v: Any) -> str: # in ``queue-events.ts`` — a non-numeric value silently falls back to the # raw string so a malformed entry never crashes the iterator. _NUMERIC_EVENT_FIELDS: frozenset[str] = frozenset( - {"attempt", "backoff_ms", "delay_ms", "duration_us", "ts"} + {"attempt", "backoff_ms", "delay_ms", "duration_us", "ts", "progress"} ) # Events for which we emit a per-id targeted channel @@ -416,7 +416,9 @@ def _to_str(v: Any) -> str: # emit. The targeted channels exist specifically so # :meth:`Job.wait_until_finished` doesn't have to filter every # broadcast event by jobId. -_PER_ID_EVENTS: frozenset[str] = frozenset({"active", "completed", "failed"}) +_PER_ID_EVENTS: frozenset[str] = frozenset( + {"active", "completed", "failed", "progress"} +) def _maybe_int(s: str) -> Any: diff --git a/chasquimq-py/src/chasquimq/worker.py b/chasquimq-py/src/chasquimq/worker.py index f3a6314..82c5c57 100644 --- a/chasquimq-py/src/chasquimq/worker.py +++ b/chasquimq-py/src/chasquimq/worker.py @@ -81,11 +81,20 @@ class Worker: ``drained``, not just this one. * ``paused`` — ``()``. Fired when :meth:`pause` is called. * ``resumed`` — ``()``. Fired when :meth:`resume` is called. + * ``progress`` — ``(job: Job, progress: int)``. Fired every time a + processor calls ``await job.update_progress(n)``. The engine + writes the persisted progress key first, then emits an + ``e=progress`` event onto the events stream; the worker + subscribes to its own :class:`QueueEvents` (lazily spawned the + first time a ``progress`` listener attaches) and re-emits onto + this EE so callers see ``(job, n)`` in the same process that ran + the handler. Disable the events fan-out (and therefore this + event) by passing ``Worker(events_progress_enabled=False)``. Listener names accepted for parity but currently no-op (engine - doesn't emit the underlying transition yet): ``progress``, - ``stalled``. These can be wired up without raising; promoted to - active events when the corresponding engine work lands. + doesn't emit the underlying transition yet): ``stalled``. These + can be wired up without raising; promoted to active events when + the corresponding engine work lands. """ def __init__( @@ -112,6 +121,9 @@ def __init__( result_ttl_ms: Optional[int] = None, reconnect_max_attempts: Optional[int] = None, credential_provider: Optional[CredentialProvider] = None, + log_max_stream_len: Optional[int] = None, + log_max_line_bytes: Optional[int] = None, + events_progress_enabled: Optional[bool] = None, ) -> None: self._queue_name = queue_name self._handler = handler @@ -148,6 +160,12 @@ def __init__( # ``credential_provider`` gives up instead of looping forever. if reconnect_max_attempts is not None: consumer_kwargs["reconnect_max_attempts"] = reconnect_max_attempts + if log_max_stream_len is not None: + consumer_kwargs["log_max_stream_len"] = log_max_stream_len + if log_max_line_bytes is not None: + consumer_kwargs["log_max_line_bytes"] = log_max_line_bytes + if events_progress_enabled is not None: + consumer_kwargs["events_progress_enabled"] = events_progress_enabled if credential_provider is not None: # The native consumer captures the running asyncio loop at @@ -178,12 +196,20 @@ def __init__( # buggy listener cannot crash the worker. self._listeners: dict[str, list[WorkerListener]] = defaultdict(list) # Lazy embedded :class:`QueueEvents` subscriber for the - # cross-process ``drained`` event. ``None`` until a ``drained`` - # listener attaches; torn down in :meth:`close`. Workers that - # never subscribe to ``drained`` pay no extra Redis connections. - self._drained_events: Optional[QueueEvents] = None - self._drained_redis_url = redis_url - self._drained_tls = tls + # cross-process ``drained`` + ``progress`` events. ``None`` until + # a listener for either attaches; torn down in :meth:`close`. + # Workers that never subscribe pay no extra Redis connections. + self._internal_events: Optional[QueueEvents] = None + self._internal_redis_url = redis_url + self._internal_tls = tls + # In-flight :class:`Job` instances by id, populated for the + # duration of each handler invocation so the ``progress`` + # forwarder can surface the same :class:`Job` reference the + # handler is holding (so ``worker.on('progress', (job, n) -> + # ...)`` and the handler observe identical state). Entries are + # removed in the handler's ``finally`` so the map stays bounded + # to current concurrency. + self._inflight: dict[str, Job] = {} @property def name(self) -> str: @@ -219,14 +245,14 @@ async def run(self) -> None: self._running = True self._emit("ready") - # If a ``drained`` listener attached before ``run()`` was - # called, hold the engine start until the subscriber's first - # ``XREAD BLOCK`` is in flight. Best-effort: cancellation / - # error on the subscriber side resolves the wait so the - # worker startup is never wedged. - if self._drained_events is not None: + # If a ``drained`` or ``progress`` listener attached before + # ``run()`` was called, hold the engine start until the + # subscriber's first ``XREAD BLOCK`` is in flight. Best-effort: + # cancellation / error on the subscriber side resolves the + # wait so the worker startup is never wedged. + if self._internal_events is not None: try: - await self._drained_events.wait_until_ready() + await self._internal_events.wait_until_ready() except Exception: pass @@ -238,32 +264,41 @@ async def native_handler(native_job: Any) -> Optional[bytes]: data=data, attempt=native_job.attempt, created_at_ms=native_job.created_at_ms, + _handle=native_job, ) + self._inflight[native_job.id] = job # ``active`` fires before the handler runs so subscribers # building a "currently running" view see jobs even for # long-running handlers. Mirrors the Node shim. self._emit("active", job) try: - result = await self._handler(job) - except asyncio.CancelledError: - # Cancellation (from shutdown / shield bypass) is a - # control-flow signal, not a handler failure. The - # engine treats the cancelled handler as in-progress - # at shutdown; no ``failed`` event fires (a cancelled - # handler is not a handler failure). - raise - except BaseException as exc: - # ``failed`` fires before re-raising so subscribers see - # the exception that triggered the routing decision - # (retry vs. DLQ-unrecoverable). The native binding - # detects ``UnrecoverableError`` via MRO; this emit - # path stays agnostic. - self._emit("failed", job, exc) - raise - self._emit("completed", job, result) - if result is None: - return None - return encode_payload(result) + try: + result = await self._handler(job) + except asyncio.CancelledError: + # Cancellation (from shutdown / shield bypass) is a + # control-flow signal, not a handler failure. The + # engine treats the cancelled handler as in-progress + # at shutdown; no ``failed`` event fires (a cancelled + # handler is not a handler failure). + raise + except BaseException as exc: + # ``failed`` fires before re-raising so subscribers see + # the exception that triggered the routing decision + # (retry vs. DLQ-unrecoverable). The native binding + # detects ``UnrecoverableError`` via MRO; this emit + # path stays agnostic. + self._emit("failed", job, exc) + raise + self._emit("completed", job, result) + if result is None: + return None + return encode_payload(result) + finally: + # Drop the inflight entry so the map stays bounded to + # current concurrency; a late ``progress`` event arriving + # after the handler resolved finds no live Job and is + # silently dropped (matches the Node shim). + self._inflight.pop(native_job.id, None) self._consumer_task = asyncio.ensure_future( self._consumer.run(native_handler) @@ -304,15 +339,15 @@ async def close(self) -> None: # there is nothing to drain, so just flag closed. if self._consumer is not None: self._consumer.shutdown() - # Tear down the lazy drained subscriber if one was started. + # Tear down the lazy internal subscriber if one was started. # Best-effort: swallow errors so a transient Redis blip on # close doesn't mask the worker's own shutdown path. - if self._drained_events is not None: + if self._internal_events is not None: try: - await self._drained_events.close() + await self._internal_events.close() except Exception: pass - self._drained_events = None + self._internal_events = None self._emit("closed") def pause(self) -> None: @@ -369,17 +404,17 @@ def on(self, event_name: str, callback: WorkerListener) -> None: See the class docstring for the supported event names. Callbacks may be plain functions or ``async def`` coroutines. Listeners - for ``'drained'`` lazily spawn an internal cross-process - events-stream subscriber the first time one attaches; the - subscriber is torn down in :meth:`close`. + for ``'drained'`` or ``'progress'`` lazily spawn an internal + cross-process events-stream subscriber the first time one + attaches; the subscriber is torn down in :meth:`close`. """ self._listeners[event_name].append(callback) if ( - event_name == "drained" - and self._drained_events is None + event_name in ("drained", "progress") + and self._internal_events is None and not self._closed ): - self._spawn_drained_subscriber() + self._spawn_internal_subscriber() def off(self, event_name: str, callback: WorkerListener) -> None: """Remove a previously-registered callback. @@ -439,12 +474,20 @@ def _emit(self, event_name: str, *args: Any) -> None: task = asyncio.ensure_future(result) task.add_done_callback(_log_listener_task_exception) - def _spawn_drained_subscriber(self) -> None: + def _spawn_internal_subscriber(self) -> None: """Lazily start a :class:`QueueEvents` subscriber that forwards - the engine's cross-process ``drained`` event onto this worker's - listener registry. Idempotent. Errors from the subscriber are - forwarded to this worker's ``error`` channel so application - code only needs one error subscription. + the engine's cross-process ``drained`` and ``progress`` events + onto this worker's listener registry. Idempotent. + + Progress event semantics: the engine emits one ``e=progress`` + entry per ``Job.update_progress`` call. This forwarder looks the + live :class:`Job` up by id in :attr:`_inflight` (populated for + the duration of the handler's run) so subscribers receive the + same :class:`Job` reference the handler is holding — identical + to BullMQ's ``(job, progress)`` shape. Progress events for jobs + whose handlers have already resolved are dropped silently; + they would race the cleanup of the inflight map and arrive + with no live :class:`Job` to dispatch on. ``block_ms=1000`` keeps :meth:`close` snappy — the QueueEvents default 5s would mean every worker shutdown drags for up to @@ -452,22 +495,43 @@ def _spawn_drained_subscriber(self) -> None: """ events = QueueEvents( self._queue_name, - redis_url=self._drained_redis_url, - tls=self._drained_tls, + redis_url=self._internal_redis_url, + tls=self._internal_tls, block_ms=1000, ) def _on_drained(_event_id: str) -> None: self._emit("drained") + def _on_progress(payload: dict, _event_id: str) -> None: + job_id = payload.get("jobId") + progress = payload.get("progress") + if job_id is None or progress is None: + return + job = self._inflight.get(job_id) + if job is None: + return + try: + progress_int = int(progress) + except (TypeError, ValueError): + return + # Mirror the persisted progress onto the local Job so + # listeners and the handler observe consistent state. The + # handler itself already set this via ``update_progress``; + # this branch covers listeners that fire before the + # handler awaits. + job.progress = progress_int + self._emit("progress", job, progress_int) + events.on("drained", _on_drained) + events.on("progress", _on_progress) # Note: :class:`QueueEvents` does not currently expose an # explicit ``error`` channel the way Node's ``EventEmitter`` # does; transient subscriber errors are logged inside the # ``_listener_loop``. If a future slice adds one, wire it onto # this Worker's ``error`` emitter the same way the Node shim # does. - self._drained_events = events + self._internal_events = events async def __aenter__(self) -> "Worker": return self diff --git a/chasquimq-py/tests/test_progress_and_log.py b/chasquimq-py/tests/test_progress_and_log.py new file mode 100644 index 0000000..d9ed804 --- /dev/null +++ b/chasquimq-py/tests/test_progress_and_log.py @@ -0,0 +1,320 @@ +"""Integration tests for Job.update_progress / Job.log / Queue.get_job_logs. + +Mirrors ``chasquimq-node/__test__/progress-and-log.test.ts``. +""" + +from __future__ import annotations + +import asyncio +import os + +import pytest + +from chasquimq import Job, Queue, QueueEvents, Worker + + +REDIS_URL = os.environ.get("CHASQUIMQ_TEST_REDIS_URL", "redis://127.0.0.1:6379") + + +pytestmark = pytest.mark.usefixtures("cleanup_keys") + + +async def _run_worker(worker: Worker) -> asyncio.Task[None]: + """Spawn the worker's ``run()`` loop and return the task. Swallows + cancellation so the test's ``finally`` cleanup is quiet. + """ + + async def _run() -> None: + try: + await worker.run() + except asyncio.CancelledError: + pass + except Exception: + pass + + return asyncio.ensure_future(_run()) + + +async def _wait_for(predicate, timeout: float = 10.0) -> None: + deadline = asyncio.get_event_loop().time() + timeout + while not predicate() and asyncio.get_event_loop().time() < deadline: + await asyncio.sleep(0.025) + if not predicate(): + raise AssertionError(f"predicate did not become true within {timeout}s") + + +@pytest.mark.asyncio +async def test_handler_update_progress_persists_and_get_job_reads_it_back( + redis_url: str, queue_name: str +) -> None: + """Handler ``await job.update_progress(50)`` → + ``Queue.get_job(id).progress == 50``. + """ + handler_done = asyncio.Event() + + async def handler(job: Job) -> None: + await job.update_progress(50) + handler_done.set() + # Hold the handler so the job stays Active while we introspect — + # a completed job with no stored result key disappears from the + # introspector's view, so we'd race the ack vs the read. + await asyncio.sleep(0.5) + + worker = Worker( + queue_name, + handler, + redis_url=redis_url, + concurrency=1, + read_block_ms=200, + delayed_enabled=False, + run_scheduler=False, + ) + queue = Queue(queue_name, redis_url=redis_url) + run_task = await _run_worker(worker) + try: + added = await queue.add("progress-one", {"value": 1}) + await asyncio.wait_for(handler_done.wait(), timeout=10.0) + fetched = await queue.get_job(added.id) + assert fetched is not None + assert fetched.progress == 50 + finally: + await worker.close() + await asyncio.wait([run_task], timeout=5.0) + await queue.close() + + +@pytest.mark.asyncio +async def test_queue_events_emits_per_id_progress_channel( + redis_url: str, queue_name: str +) -> None: + """``QueueEvents.on('progress:', cb)`` receives the payload.""" + events = QueueEvents(queue_name, redis_url=redis_url, block_ms=300) + + handler_done = asyncio.Event() + + async def handler(job: Job) -> None: + # Wait until the per-id subscriber is attached before emitting, + # so the subscription window covers the engine's XADD. + await asyncio.sleep(0.1) + await job.update_progress(33) + handler_done.set() + + worker = Worker( + queue_name, + handler, + redis_url=redis_url, + concurrency=1, + read_block_ms=200, + delayed_enabled=False, + run_scheduler=False, + ) + queue = Queue(queue_name, redis_url=redis_url) + + run_task = await _run_worker(worker) + try: + added = await queue.add("emits-progress", {"value": 1}) + targeted_calls: list[dict] = [] + broadcast_calls: list[dict] = [] + events.on( + f"progress:{added.id}", + lambda payload, eid: targeted_calls.append(payload), + ) + events.on( + "progress", lambda payload, eid: broadcast_calls.append(payload) + ) + await events.wait_until_ready() + + await asyncio.wait_for(handler_done.wait(), timeout=10.0) + await _wait_for( + lambda: targeted_calls and broadcast_calls, timeout=10.0 + ) + payload = targeted_calls[0] + assert payload["jobId"] == added.id + assert payload["name"] == "emits-progress" + assert payload["progress"] == 33 + finally: + await events.close() + await worker.close() + await asyncio.wait([run_task], timeout=5.0) + await queue.close() + + +@pytest.mark.asyncio +async def test_worker_progress_listener_fires_once_per_call( + redis_url: str, queue_name: str +) -> None: + """Worker EE ``progress`` listener fires once per + ``update_progress`` call with ``(job, n)``. + """ + handler_done = asyncio.Event() + progress_calls: list[tuple[Job, int]] = [] + + async def handler(job: Job) -> None: + await job.update_progress(10) + await job.update_progress(50) + await job.update_progress(100) + handler_done.set() + # Keep the handler alive briefly so the events forwarder has + # time to dispatch all three before the inflight entry drops. + await asyncio.sleep(0.5) + + worker = Worker( + queue_name, + handler, + redis_url=redis_url, + concurrency=1, + read_block_ms=200, + delayed_enabled=False, + run_scheduler=False, + ) + worker.on( + "progress", lambda job, n: progress_calls.append((job, n)) + ) + queue = Queue(queue_name, redis_url=redis_url) + + run_task = await _run_worker(worker) + try: + await queue.add("three-updates", {"value": 1}) + await asyncio.wait_for(handler_done.wait(), timeout=10.0) + await _wait_for(lambda: len(progress_calls) >= 3, timeout=10.0) + assert len(progress_calls) == 3 + assert [n for _, n in progress_calls] == [10, 50, 100] + finally: + await worker.close() + await asyncio.wait([run_task], timeout=5.0) + await queue.close() + + +@pytest.mark.asyncio +async def test_job_log_appends_and_get_job_logs_reads_them_back( + redis_url: str, queue_name: str +) -> None: + """``await job.log("A"); await job.log("B"); Queue.get_job_logs(id) + == (["A", "B"], 2)``. + """ + handler_done = asyncio.Event() + + async def handler(job: Job) -> None: + await job.log("A") + await job.log("B") + handler_done.set() + + worker = Worker( + queue_name, + handler, + redis_url=redis_url, + concurrency=1, + read_block_ms=200, + delayed_enabled=False, + run_scheduler=False, + ) + queue = Queue(queue_name, redis_url=redis_url) + run_task = await _run_worker(worker) + try: + added = await queue.add("logs-two", {"value": 1}) + await asyncio.wait_for(handler_done.wait(), timeout=10.0) + lines, count = await queue.get_job_logs(added.id) + assert lines == ["A", "B"] + assert count == 2 + finally: + await worker.close() + await asyncio.wait([run_task], timeout=5.0) + await queue.close() + + +@pytest.mark.asyncio +async def test_get_job_logs_pagination_returns_slice_in_order( + redis_url: str, queue_name: str +) -> None: + """10 lines, fetch ``start=2 end=4 asc=True`` → 3 lines in order.""" + handler_done = asyncio.Event() + + async def handler(job: Job) -> None: + for i in range(10): + await job.log(f"L{i}") + handler_done.set() + + worker = Worker( + queue_name, + handler, + redis_url=redis_url, + concurrency=1, + read_block_ms=200, + delayed_enabled=False, + run_scheduler=False, + ) + queue = Queue(queue_name, redis_url=redis_url) + run_task = await _run_worker(worker) + try: + added = await queue.add("logs-ten", {"value": 1}) + await asyncio.wait_for(handler_done.wait(), timeout=10.0) + lines, count = await queue.get_job_logs( + added.id, start=2, end=4, asc=True + ) + assert lines == ["L2", "L3", "L4"] + assert count == 10 + finally: + await worker.close() + await asyncio.wait([run_task], timeout=5.0) + await queue.close() + + +@pytest.mark.asyncio +async def test_get_job_logs_out_of_range_clamps_without_exception( + redis_url: str, queue_name: str +) -> None: + """An ``end`` beyond the current XLEN clamps to the tail; no + exception raised, returned ``count`` is the real XLEN. + """ + handler_done = asyncio.Event() + + async def handler(job: Job) -> None: + for i in range(3): + await job.log(f"L{i}") + handler_done.set() + + worker = Worker( + queue_name, + handler, + redis_url=redis_url, + concurrency=1, + read_block_ms=200, + delayed_enabled=False, + run_scheduler=False, + ) + queue = Queue(queue_name, redis_url=redis_url) + run_task = await _run_worker(worker) + try: + added = await queue.add("logs-clamp", {"value": 1}) + await asyncio.wait_for(handler_done.wait(), timeout=10.0) + lines, count = await queue.get_job_logs( + added.id, start=0, end=100, asc=True + ) + assert lines == ["L0", "L1", "L2"] + assert count == 3 + finally: + await worker.close() + await asyncio.wait([run_task], timeout=5.0) + await queue.close() + + +@pytest.mark.asyncio +async def test_read_only_job_raises_on_update_progress_and_log( + redis_url: str, queue_name: str +) -> None: + """``Queue.get_job(id).update_progress(50)`` raises with the + read-only message; same for ``.log()``. + """ + queue = Queue(queue_name, redis_url=redis_url) + try: + # No worker — the job sits waiting; get_job synthesizes a + # read-only Job (no native handle). + added = await queue.add("read-only", {"value": 1}) + fetched = await queue.get_job(added.id) + assert fetched is not None + with pytest.raises(RuntimeError, match="read-only"): + await fetched.update_progress(50) + with pytest.raises(RuntimeError, match="read-only"): + await fetched.log("nope") + finally: + await queue.close() diff --git a/chasquimq/src/config.rs b/chasquimq/src/config.rs index 0a8fabc..e869cff 100644 --- a/chasquimq/src/config.rs +++ b/chasquimq/src/config.rs @@ -189,6 +189,25 @@ pub struct ConsumerConfig { /// pays one `Instant` comparison per batch, no Redis round trip. /// Default `250`. pub pause_poll_ms: u64, + /// `MAXLEN ~` cap applied to each per-job log stream by + /// [`crate::JobHandle::log`]. Approximate trim (the `~`) so Redis + /// can do it cheaply; expect actual length to oscillate a few + /// entries above the cap. **Must be ≥ 16** — anything smaller and + /// the `MAXLEN ~` rounding can leave the stream effectively empty + /// (rejected at `Consumer::run` with `Error::Config`). Default + /// `1000`. + pub log_max_stream_len: u64, + /// Per-line byte cap applied by [`crate::JobHandle::log`]. Lines + /// exceeding this are truncated on a UTF-8 char boundary with a + /// `"[…truncated]"` marker appended; the truncate fires a single + /// warn-once per handle. Default `4096`. + pub log_max_line_bytes: usize, + /// Toggle for the per-progress `e=progress` event emission. + /// `update_progress` always SETs the persisted progress key; this + /// only gates the events-stream `XADD` so a high-rate handler can + /// opt out of the events flood while keeping persisted progress. + /// Default `true`. + pub events_progress_enabled: bool, /// Forwarded to the inline promoter the consumer spawns when /// `delayed_enabled` is true. Defaults to [`crate::metrics::NoopSink`]. pub metrics: std::sync::Arc, @@ -228,6 +247,9 @@ impl std::fmt::Debug for ConsumerConfig { .field("result_batch", &self.result_batch) .field("result_idle_ms", &self.result_idle_ms) .field("pause_poll_ms", &self.pause_poll_ms) + .field("log_max_stream_len", &self.log_max_stream_len) + .field("log_max_line_bytes", &self.log_max_line_bytes) + .field("events_progress_enabled", &self.events_progress_enabled) .field("metrics", &"") .field("connection", &self.connection) .finish() @@ -267,12 +289,36 @@ impl Default for ConsumerConfig { result_batch: 64, result_idle_ms: 5, pause_poll_ms: 250, + log_max_stream_len: 1_000, + log_max_line_bytes: 4_096, + events_progress_enabled: true, metrics: crate::metrics::noop_sink(), connection: ConnectionTuning::default(), } } } +impl ConsumerConfig { + /// Minimum acceptable `log_max_stream_len`. Caps below this defeat + /// the `MAXLEN ~` rounding inside Redis and can leave the per-job + /// log stream effectively empty between writes. + pub const MIN_LOG_MAX_STREAM_LEN: u64 = 16; + + /// Validate the config. Called once at the start of `Consumer::run` + /// so a misconfigured field surfaces at startup rather than as a + /// silent data-loss bug after the first `JobHandle::log` call. + pub(crate) fn validate(&self) -> crate::Result<()> { + if self.log_max_stream_len < Self::MIN_LOG_MAX_STREAM_LEN { + return Err(crate::Error::Config(format!( + "log_max_stream_len must be >= {} (got {})", + Self::MIN_LOG_MAX_STREAM_LEN, + self.log_max_stream_len + ))); + } + Ok(()) + } +} + #[derive(Clone)] pub struct PromoterConfig { pub queue_name: String, @@ -394,3 +440,36 @@ impl Default for PromoterConfig { } } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn consumer_config_defaults_match_documented_values() { + let cfg = ConsumerConfig::default(); + assert_eq!(cfg.log_max_stream_len, 1_000); + assert_eq!(cfg.log_max_line_bytes, 4_096); + assert!(cfg.events_progress_enabled); + } + + #[test] + fn validate_rejects_log_max_stream_len_below_minimum() { + let mut cfg = ConsumerConfig { + log_max_stream_len: ConsumerConfig::MIN_LOG_MAX_STREAM_LEN - 1, + ..ConsumerConfig::default() + }; + assert!(cfg.validate().is_err()); + cfg.log_max_stream_len = 0; + assert!(cfg.validate().is_err()); + } + + #[test] + fn validate_accepts_log_max_stream_len_at_minimum() { + let cfg = ConsumerConfig { + log_max_stream_len: ConsumerConfig::MIN_LOG_MAX_STREAM_LEN, + ..ConsumerConfig::default() + }; + assert!(cfg.validate().is_ok()); + } +} diff --git a/chasquimq/src/consumer/mod.rs b/chasquimq/src/consumer/mod.rs index d899584..a550034 100644 --- a/chasquimq/src/consumer/mod.rs +++ b/chasquimq/src/consumer/mod.rs @@ -14,7 +14,7 @@ use crate::error::{HandlerError, Result}; use crate::events::EventsWriter; use crate::job::Job; use crate::promoter::Promoter; -use crate::redis::conn::connect; +use crate::redis::conn::{connect, connect_pool}; use crate::redis::group::ensure_group; use crate::redis::keys::{delayed_key, dlq_key, paused_key, stream_key}; use crate::redis::parse::StreamEntryId; @@ -95,6 +95,7 @@ where H: Fn(Job) -> Fut + Send + Sync + 'static, Fut: Future> + Send + 'static, { + self.cfg.validate()?; tracing::debug!( queue = %self.cfg.queue_name, delayed_enabled = self.cfg.delayed_enabled, @@ -203,6 +204,20 @@ where let promoter_handle = self.spawn_promoter(shutdown.clone(), events.clone()); let scheduler_handle = self.spawn_scheduler::(shutdown.clone()); + // Shared per-handler progress + log Pool. Sized + // `(concurrency / 8).max(2).min(8)` so a small worker pool gets a + // sane minimum (2 clients) and a busy pool doesn't open one client + // per concurrent worker (capped at 8). Per-call SET / XADD are + // cheap; this pool is intentionally smaller than `concurrency`. + let progress_log_pool_size = (concurrency / 8).clamp(2, 8); + let progress_log_pool = connect_pool( + &self.redis_url, + progress_log_pool_size, + &self.cfg.connection, + ) + .await?; + let queue_name_arc: Arc = Arc::from(self.cfg.queue_name.as_str()); + let wiring = WorkerWiring { ack_tx: ack_tx.clone(), retry_tx: retry_tx.clone(), @@ -214,6 +229,11 @@ where store_results: self.cfg.store_results, result_ttl_secs: self.cfg.result_ttl_secs, ok_result_tx: ok_result_tx.clone(), + progress_log_pool, + queue_name: queue_name_arc, + log_max_stream_len: self.cfg.log_max_stream_len, + log_max_line_bytes: self.cfg.log_max_line_bytes, + events_progress_enabled: self.cfg.events_progress_enabled, }; let workers = spawn_workers(concurrency, handler, job_rx, wiring); drop(ack_tx); diff --git a/chasquimq/src/consumer/worker.rs b/chasquimq/src/consumer/worker.rs index 1642e87..d3aad90 100644 --- a/chasquimq/src/consumer/worker.rs +++ b/chasquimq/src/consumer/worker.rs @@ -6,9 +6,11 @@ use crate::error::HandlerError; use crate::events::EventsWriter; use crate::job::{Job, now_ms}; use crate::metrics::{self, JobOutcome, JobOutcomeKind, MetricsSink}; +use crate::progress::JobHandle; use crate::redis::delayed_member::encode_delayed_member; use crate::redis::parse::StreamEntryId; use bytes::Bytes; +use fred::clients::Pool; use futures_util::FutureExt; use serde::Serialize; use std::future::Future; @@ -44,6 +46,24 @@ pub(crate) struct WorkerWiring { /// the worker's match unconditionally takes the existing batched ack /// branch. pub ok_result_tx: Option>, + /// Shared `Pool` used by every per-dispatch [`JobHandle`] for SET + /// (progress) and XADD/XLEN (log). Sized `(concurrency / 8).max(2).min(8)` + /// at `Consumer::run` so a busy worker pool doesn't open one Redis + /// client per concurrent worker. + pub progress_log_pool: Pool, + /// Queue name copied here as `Arc` so per-dispatch `JobHandle` + /// construction is a refcount bump, not a string clone, on the hot + /// path. + pub queue_name: Arc, + /// `MAXLEN ~` cap forwarded to each [`JobHandle::log`] call. + pub log_max_stream_len: u64, + /// Per-line byte cap forwarded to each [`JobHandle::log`] call. + pub log_max_line_bytes: usize, + /// Toggle for the per-progress `e=progress` event emission. The SET + /// to the progress key always fires; this only gates the events-stream + /// XADD so a high-rate handler can opt out of the events flood while + /// keeping persisted progress. + pub events_progress_enabled: bool, } pub(crate) fn spawn_workers( @@ -65,7 +85,7 @@ where let rx = job_rx.clone(); let wiring = wiring.clone(); set.spawn(async move { - while let Ok(dispatched) = rx.recv().await { + while let Ok(mut dispatched) = rx.recv().await { let entry_id = dispatched.entry_id.clone(); let job_id = dispatched.job.id.clone(); let job_name = dispatched.job.name.clone(); @@ -75,7 +95,32 @@ where // the JobOutcome event (where it's "the run that just executed" // by the time the event fires) and human-readable log lines. let attempt_index = dispatched.job.attempt.saturating_add(1); - let job_for_retry = dispatched.job.clone(); + // Clone before the handler mutates / consumes `dispatched.job` + // (the retry path needs a copy with `handle = None`). + let mut job_for_retry = dispatched.job.clone(); + job_for_retry.handle = None; + + // Wire the per-dispatch progress + log handle onto the job + // *before* the user handler sees it. The handle borrows the + // shared `progress_log_pool` so the per-call SET / XADD don't + // contend with the reader / ack / retry hot paths. + let job_name_arc: Option> = if job_name.is_empty() { + None + } else { + Some(Arc::from(job_name.as_str())) + }; + let handle = JobHandle::new( + Arc::from(job_id.as_str()), + wiring.queue_name.clone(), + wiring.progress_log_pool.clone(), + wiring.result_ttl_secs, + wiring.log_max_stream_len, + wiring.log_max_line_bytes, + Some(wiring.events.clone()), + job_name_arc, + wiring.events_progress_enabled, + ); + dispatched.job.handle = Some(Arc::new(handle)); // Emit `active` *before* the handler runs so subscribers can // build a "currently running" view that's correct even for diff --git a/chasquimq/src/events.rs b/chasquimq/src/events.rs index 6fbc3ff..c27ace7 100644 --- a/chasquimq/src/events.rs +++ b/chasquimq/src/events.rs @@ -33,6 +33,7 @@ //! |--------------------|--------------------------------------------| //! | `waiting` | `n` (opt) | //! | `active` | `attempt`, `n` (opt) | +//! | `progress` | `progress` (0..=100), `n` (opt) | //! | `completed` | `attempt`, `duration_us`, `n` (opt) | //! | `failed` | `attempt`, `reason`, `duration_us` (opt), `n` (opt) | //! | `retry-scheduled` | `attempt` (next attempt), `backoff_ms`, `n` (opt) | @@ -211,6 +212,18 @@ impl EventsWriter { .await; } + /// Emit a `progress` event (handler called `JobHandle::update_progress`). + /// `progress` is the clamped 0..=100 value the engine persisted to + /// the progress key. `name` is the dispatch name (`None` for unnamed + /// jobs — the field is omitted on the wire, matching the existing + /// convention). + pub(crate) async fn emit_progress(&self, id: &str, name: Option<&str>, progress: u8) { + let progress_s = progress.to_string(); + let name = name.unwrap_or(""); + self.xadd("progress", id, name, &[("progress", &progress_s)]) + .await; + } + /// Emit a `dlq` event after a successful DLQ relocate. pub(crate) async fn emit_dlq(&self, id: &str, name: &str, reason: &str, attempt: u32) { let attempt_s = attempt.to_string(); @@ -282,3 +295,135 @@ impl EventsWriter { } } } + +#[cfg(test)] +mod tests { + use super::*; + use crate::config::ConnectionTuning; + use crate::redis::conn::connect; + use crate::redis::keys::events_key; + + fn redis_url() -> String { + std::env::var("REDIS_URL").expect("REDIS_URL must be set to run integration tests") + } + + async fn flush_events(client: &Client, queue: &str) { + let cmd = CustomCommand::new_static("DEL", ClusterHash::FirstKey, false); + let _: Value = client + .custom(cmd, vec![Value::from(events_key(queue))]) + .await + .expect("DEL events"); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + #[ignore = "requires REDIS_URL"] + async fn emits_progress_event_with_progress_field_and_name() { + let url = redis_url(); + let queue = "events_emit_progress"; + + let admin = connect(&url, &ConnectionTuning::default()) + .await + .expect("admin"); + flush_events(&admin, queue).await; + + let writer_client = connect(&url, &ConnectionTuning::default()) + .await + .expect("writer client"); + let writer = EventsWriter::new(writer_client, queue, 1_000); + + writer.emit_progress("job-A", Some("send-email"), 42).await; + writer.emit_progress("job-B", None, 100).await; + + // Read back via XRANGE. + let cmd = CustomCommand::new_static("XRANGE", ClusterHash::FirstKey, false); + let v: Value = admin + .custom( + cmd, + vec![ + Value::from(events_key(queue)), + Value::from("-"), + Value::from("+"), + ], + ) + .await + .expect("XRANGE"); + let items = match v { + Value::Array(items) => items, + other => panic!("XRANGE unexpected: {other:?}"), + }; + let mut progress_events: Vec> = Vec::new(); + for entry in items { + let Value::Array(pair) = entry else { continue }; + let Some(Value::Array(fields)) = pair.into_iter().nth(1) else { + continue; + }; + let mut kv = std::collections::HashMap::new(); + let mut iter = fields.into_iter(); + while let (Some(k), Some(v)) = (iter.next(), iter.next()) { + let ks = match k { + Value::String(s) => s.to_string(), + Value::Bytes(b) => String::from_utf8_lossy(&b).to_string(), + other => format!("{other:?}"), + }; + let vs = match v { + Value::String(s) => s.to_string(), + Value::Bytes(b) => String::from_utf8_lossy(&b).to_string(), + other => format!("{other:?}"), + }; + kv.insert(ks, vs); + } + if kv.get("e").map(|s| s.as_str()) == Some("progress") { + progress_events.push(kv); + } + } + assert_eq!(progress_events.len(), 2, "two progress events emitted"); + + let job_a = progress_events + .iter() + .find(|e| e.get("id").map(|s| s.as_str()) == Some("job-A")) + .expect("job-A"); + assert_eq!(job_a.get("progress").map(|s| s.as_str()), Some("42")); + assert_eq!(job_a.get("n").map(|s| s.as_str()), Some("send-email")); + assert!(job_a.contains_key("ts")); + + let job_b = progress_events + .iter() + .find(|e| e.get("id").map(|s| s.as_str()) == Some("job-B")) + .expect("job-B"); + assert_eq!(job_b.get("progress").map(|s| s.as_str()), Some("100")); + // Empty name → `n` field omitted entirely, same convention as the + // other per-job events. + assert!(!job_b.contains_key("n"), "unnamed job omits the n field"); + + let _: () = admin.quit().await.unwrap(); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + #[ignore = "requires REDIS_URL"] + async fn disabled_writer_skips_progress_event() { + let url = redis_url(); + let queue = "events_emit_progress_disabled"; + + let admin = connect(&url, &ConnectionTuning::default()) + .await + .expect("admin"); + flush_events(&admin, queue).await; + + let writer = EventsWriter::disabled(); + writer.emit_progress("job-X", Some("name"), 50).await; + + // No XADD should have happened. + let cmd = CustomCommand::new_static("XLEN", ClusterHash::FirstKey, false); + let v: Value = admin + .custom(cmd, vec![Value::from(events_key(queue))]) + .await + .expect("XLEN"); + match v { + Value::Integer(n) => assert_eq!(n, 0, "disabled writer must not XADD"), + Value::Null => {} + other => panic!("XLEN unexpected: {other:?}"), + } + + let _: () = admin.quit().await.unwrap(); + } +} diff --git a/chasquimq/src/introspect.rs b/chasquimq/src/introspect.rs index f243049..0cd10b9 100644 --- a/chasquimq/src/introspect.rs +++ b/chasquimq/src/introspect.rs @@ -33,7 +33,8 @@ use crate::error::{Error, Result}; use crate::payload::peek_envelope; use crate::redis::keys::{ - delayed_index_key, delayed_key, dlq_key, paused_key, result_key, stream_key, + delayed_index_key, delayed_key, dlq_key, log_key, paused_key, progress_key, result_key, + stream_key, }; use crate::redis::parse::{XrangeEntry, parse_xrange_response}; use crate::{ConnectionTuning, config::ConsumerConfig}; @@ -145,6 +146,15 @@ pub struct JobInfo { /// surface "broken envelope" rather than silently dropping the /// match. Distinct from `state == Failed` (DLQ). pub decode_failed: bool, + /// Latest progress value the handler reported via + /// [`crate::JobHandle::update_progress`], clamped to `0..=100`. + /// `None` when the handler never called `update_progress`, the + /// progress key has already expired (TTL `result_ttl_secs`), or + /// the engine wrote a non-decimal-`u8` value (forward-compat from + /// a future SDK). The inspector reads this key for every state — + /// pipelined alongside the existing `get_job` lookups so the field + /// adds no extra round trip. + pub progress: Option, } /// One page of [`Introspector::get_jobs`] results. `next_cursor` is @@ -287,31 +297,36 @@ impl Introspector { /// Full per-id lookup. Returns `None` when the id doesn't match any /// surface. Each branch returns a `JobInfo` populated from whatever /// surface matched. + /// + /// Each matching branch also pipelines a GET for the per-job progress + /// key (`{chasqui:}:progress:`) into the same round trip as + /// the matched probe, so `JobInfo::progress` is populated without + /// adding a sequential RTT on the admin path. pub async fn get_job(&self, id: &str) -> Result> { // 1. Active (PEL hit). if let Some(found) = self.lookup_in_pel(id).await? { - return Ok(Some(found)); + return Ok(Some(self.with_progress(found, id).await?)); } // 2. Delayed. if self.delayed_member(id).await?.is_some() { // Decode of delayed members happens elsewhere; we just // synthesize the info here from what we know. let info = self.lookup_in_delayed(id).await?; - if info.is_some() { - return Ok(info); + if let Some(info) = info { + return Ok(Some(self.with_progress(info, id).await?)); } } // 3. Waiting. if let Some(found) = self.find_in_stream(id).await? { - return Ok(Some(found)); + return Ok(Some(self.with_progress(found, id).await?)); } // 4. Failed (DLQ). if let Some(found) = self.find_in_dlq(id).await? { - return Ok(Some(found)); + return Ok(Some(self.with_progress(found, id).await?)); } // 5. Completed. if self.has_result_key(id).await? { - return Ok(Some(JobInfo { + let info = JobInfo { id: id.to_string(), name: String::new(), payload: Bytes::new(), @@ -323,11 +338,131 @@ impl Introspector { failure_reason: None, failure_detail: None, decode_failed: false, - })); + progress: None, + }; + return Ok(Some(self.with_progress(info, id).await?)); } Ok(None) } + /// Read the latest progress value for `id` and stamp it onto `info`. + /// Returns the input unchanged when no progress key exists (or its + /// value isn't a decimal `u8`). + async fn with_progress(&self, mut info: JobInfo, id: &str) -> Result { + info.progress = self.progress_for(id).await?; + Ok(info) + } + + /// One GET on the per-job progress key. `Ok(None)` for missing keys + /// or non-`u8`-decimal values; the introspector intentionally swallows + /// shape mismatches so a forward-compat extension (e.g. a future SDK + /// stashing JSON in the same key) can't break admin lookups. + async fn progress_for(&self, id: &str) -> Result> { + let key = progress_key(self.queue_name.as_ref(), id); + let client = self.pool.next_connected(); + let cmd = CustomCommand::new_static("GET", ClusterHash::FirstKey, false); + let v: Value = client + .custom(cmd, vec![Value::from(key)]) + .await + .map_err(Error::Redis)?; + Ok(value_as_progress(&v)) + } + + /// XRANGE / XREVRANGE the per-job log stream for `id` and return the + /// captured `line` field values plus the current XLEN. `start` / + /// `end` are inclusive entry offsets in the order indicated by + /// `asc` (entry 0 is the oldest when `asc`, the newest when `!asc`). + /// Negative `start` is interpreted as "this many from the end" + /// (translated via XLEN), matching the BullMQ `getLogs` convention. + /// `end = -1` means "to end". + pub async fn get_job_logs( + &self, + id: &str, + start: i64, + end: i64, + asc: bool, + ) -> Result<(Vec, u64)> { + let key = log_key(self.queue_name.as_ref(), id); + let total = xlen(&self.pool, &key).await? as u64; + if total == 0 { + return Ok((Vec::new(), 0)); + } + + // Translate negative `start` and "to-end" `end` against the + // current XLEN. After resolution, `(lo, hi)` is an inclusive + // index window in the requested ordering. Saturating arithmetic + // because callers can hand in `i64::MIN` — plain `+` panics in + // debug and silently wraps in release. + let total_i = total as i64; + let mut lo = if start < 0 { + total_i.saturating_add(start).max(0) + } else { + start + }; + let mut hi = if end < 0 { + total_i.saturating_add(end).max(-1) + } else { + end + }; + if lo > hi || lo >= total_i { + return Ok((Vec::new(), total)); + } + if hi >= total_i { + hi = total_i - 1; + } + if lo < 0 { + lo = 0; + } + let count = (hi - lo + 1).max(0) as u64; + if count == 0 { + return Ok((Vec::new(), total)); + } + + // `XRANGE` / `XREVRANGE` accept `-` / `+` for "open" bounds and + // a `COUNT` clamp. Skipping `lo` entries from the open bound + // gives us the requested offset. + let client = self.pool.next_connected(); + let (cmd_name, lower, upper) = if asc { + ("XRANGE", "-", "+") + } else { + ("XREVRANGE", "+", "-") + }; + let cmd = CustomCommand::new_static(cmd_name, ClusterHash::FirstKey, false); + // Over-fetch by `lo` so we can drop the head; Redis itself has + // no `OFFSET` for stream range queries. + let take = (lo as u64 + count) as i64; + let v: Value = client + .custom( + cmd, + vec![ + Value::from(key.as_str()), + Value::from(lower), + Value::from(upper), + Value::from("COUNT"), + Value::from(take), + ], + ) + .await + .map_err(Error::Redis)?; + let entries = parse_xrange_response(&v); + let lines: Vec = entries + .into_iter() + .skip(lo as usize) + .take(count as usize) + .map(|e| { + e.fields + .into_iter() + .find(|(k, _)| k == "line") + .map(|(_, v)| { + v.as_string() + .unwrap_or_else(|| String::from_utf8_lossy(&v.as_bytes()).into_owned()) + }) + .unwrap_or_default() + }) + .collect(); + Ok((lines, total)) + } + /// Paginated listing. /// /// - For `Waiting` / `Failed`: `cursor` is the last stream entry id @@ -507,6 +642,7 @@ impl Introspector { failure_reason: None, failure_detail: None, decode_failed: false, + progress: None, })) } @@ -657,6 +793,7 @@ impl Introspector { failure_reason: None, failure_detail: None, decode_failed: false, + progress: None, }); match last_score { Some(prev) if prev == score => { @@ -737,6 +874,7 @@ impl Introspector { failure_reason: None, failure_detail: None, decode_failed: false, + progress: None, }); } } @@ -854,6 +992,20 @@ fn value_as_bytes(v: &Value) -> Option { } } +/// Decode a Redis GET reply on the progress key into an `Option`. +/// `Null` (missing key) → `None`. Non-decimal or out-of-range values +/// also collapse to `None` so a forward-compat extension (e.g. a future +/// SDK stashing JSON in the same key) doesn't break admin lookups. +fn value_as_progress(v: &Value) -> Option { + let s = match v { + Value::String(s) => s.to_string(), + Value::Bytes(b) => std::str::from_utf8(b).ok()?.to_string(), + Value::Integer(n) => n.to_string(), + _ => return None, + }; + s.trim().parse::().ok().map(|n| n.min(100)) +} + async fn xrange_window( pool: &Pool, key: &str, @@ -932,6 +1084,7 @@ fn entry_to_info_if_match(entry: &XrangeEntry, id: &str, state: JobState) -> Opt failure_reason: None, failure_detail: None, decode_failed: false, + progress: None, }) } @@ -951,6 +1104,7 @@ fn stream_entry_to_info_any(entry: &XrangeEntry, state: JobState) -> Option { tracing::warn!( @@ -969,6 +1123,7 @@ fn stream_entry_to_info_any(entry: &XrangeEntry, state: JobState) -> Option JobInfo { failure_reason: Some(parsed.reason), failure_detail: parsed.detail, decode_failed, + progress: None, } } @@ -1199,6 +1355,35 @@ mod tests { use super::*; use fred::types::Value; + #[test] + fn progress_decoder_accepts_decimal_string_and_clamps() { + assert_eq!(value_as_progress(&Value::Null), None); + assert_eq!(value_as_progress(&Value::String("0".into())), Some(0)); + assert_eq!(value_as_progress(&Value::String("100".into())), Some(100)); + // The engine should not be writing values outside [0, 100], but + // tolerate a future SDK that does — values that parse as `u8` + // but exceed 100 clamp to 100 rather than surfacing a confusing + // "looks valid" 200. + assert_eq!(value_as_progress(&Value::String("250".into())), Some(100)); + assert_eq!(value_as_progress(&Value::String("200".into())), Some(100)); + // Values outside u8 range (`> 255`) fail the parse entirely. + assert_eq!(value_as_progress(&Value::String("1000".into())), None); + // Non-decimal payloads (future-format JSON, etc.) → None. + assert_eq!( + value_as_progress(&Value::String("not-a-number".into())), + None + ); + assert_eq!(value_as_progress(&Value::String("{\"v\":42}".into())), None); + // Bytes form (RESP2 bulk string returns Bytes). + assert_eq!( + value_as_progress(&Value::Bytes(bytes::Bytes::from_static(b"42"))), + Some(42) + ); + // Integer form (unlikely from GET, but tolerant). + assert_eq!(value_as_progress(&Value::Integer(42)), Some(42)); + assert_eq!(value_as_progress(&Value::Integer(500)), None); + } + #[test] fn xpending_summary_parser_extracts_range() { // [count, min_id, max_id, [[consumer, count]]] diff --git a/chasquimq/src/job.rs b/chasquimq/src/job.rs index 5729892..046db1e 100644 --- a/chasquimq/src/job.rs +++ b/chasquimq/src/job.rs @@ -1,4 +1,6 @@ +use crate::progress::JobHandle; use serde::{Deserialize, Serialize}; +use std::sync::Arc; use std::time::{SystemTime, UNIX_EPOCH}; pub type JobId = String; @@ -147,6 +149,17 @@ pub struct Job { /// - DLQ replay (`Producer::replay_dlq` re-emits `n` on the new XADD). #[serde(default, skip)] pub name: String, + /// Per-handler progress + log surface. `Some` when the consumer + /// dispatched this job to a user handler (the worker wires a fresh + /// [`JobHandle`] in just before the handler runs); `None` on + /// `Job` instances synthesized by the introspector or constructed + /// by hand for tests. + /// + /// `#[serde(skip)]` is load-bearing the same way as `name`: the + /// handle is a runtime-only Redis-connection backref, never part of + /// the on-wire payload. Decoding always defaults it to `None`. + #[serde(default, skip)] + pub handle: Option>, } impl Job { @@ -162,6 +175,7 @@ impl Job { attempt: 0, retry: None, name: String::new(), + handle: None, } } diff --git a/chasquimq/src/lib.rs b/chasquimq/src/lib.rs index f36d1bf..172b700 100644 --- a/chasquimq/src/lib.rs +++ b/chasquimq/src/lib.rs @@ -8,6 +8,7 @@ pub mod job; pub mod metrics; pub(crate) mod payload; pub mod producer; +pub mod progress; pub mod promoter; pub(crate) mod redis; pub mod repeat; @@ -26,6 +27,7 @@ pub use metrics::{ PromoterTick, ReaderBatch, RetryScheduled, noop_sink, }; pub use producer::{DlqEntry, DrainOptions, Producer, RemovalReport}; +pub use progress::JobHandle; pub use promoter::Promoter; pub use repeat::{MissedFiresPolicy, RepeatPattern, RepeatableMeta, RepeatableSpec}; pub use scheduler::Scheduler; diff --git a/chasquimq/src/producer/maintenance.rs b/chasquimq/src/producer/maintenance.rs index 38dc618..367b949 100644 --- a/chasquimq/src/producer/maintenance.rs +++ b/chasquimq/src/producer/maintenance.rs @@ -48,7 +48,7 @@ use crate::redis::commands::{ eval_remove_stream_entry_args, evalsha_cancel_delayed_args, evalsha_clean_stream_args, evalsha_drain_stream_args, evalsha_remove_stream_entry_args, script_load_args, }; -use crate::redis::keys::{dedup_marker_key, delayed_index_key}; +use crate::redis::keys::{dedup_marker_key, delayed_index_key, log_key, progress_key}; use crate::redis::parse::{XrangeEntry, parse_xrange_response}; use bytes::Bytes; use fred::clients::{Client, Pool}; @@ -173,6 +173,45 @@ fn stream_id_ms(id: &str) -> Option { id.split('-').next()?.parse::().ok() } +/// Unlink the per-job `progress` + `log` keys for each id in `job_ids`, +/// pipelined into a single round trip per call. Mirrors the +/// `UNLINK progress + UNLINK log` tail of `remove(id)` so the +/// bulk-removal paths (`clean_stream` / `clean_delayed` / +/// `clean_completed`) leave no orphaned auxiliary keys behind. All +/// per-job keys share the `{chasqui:}` hash tag so the pipeline +/// is Cluster-correct. Best-effort: a Redis error is swallowed (with a +/// warn) so a transient blip never reverts the primary cleanup the +/// caller already did. +async fn unlink_progress_and_log(pool: &Pool, queue_name: &str, job_ids: &[String]) { + if job_ids.is_empty() { + return; + } + let client = pool.next_connected(); + let pipeline = client.pipeline(); + let unlink_cmd = CustomCommand::new_static("UNLINK", ClusterHash::FirstKey, false); + for id in job_ids { + let p_key = progress_key(queue_name, id); + let l_key = log_key(queue_name, id); + if let Err(e) = pipeline + .custom::(unlink_cmd.clone(), vec![Value::from(p_key)]) + .await + { + tracing::warn!(error = %e, "maintenance: queue UNLINK progress failed"); + return; + } + if let Err(e) = pipeline + .custom::(unlink_cmd.clone(), vec![Value::from(l_key)]) + .await + { + tracing::warn!(error = %e, "maintenance: queue UNLINK log failed"); + return; + } + } + if let Err(e) = pipeline.all::().await { + tracing::warn!(error = %e, "maintenance: UNLINK progress+log pipeline failed"); + } +} + /// Locate the stream entry id whose msgpack envelope carries `job_id`, /// scanning a single bounded `XRANGE` window. Returns `None` if the id is /// not in the first `MAINTENANCE_SCAN_PAGE` entries — callers treat that @@ -303,16 +342,41 @@ pub(super) async fn remove( } } - // 4. Result key — a plain DEL. DEL returns the count of keys removed. + // 4. Result key + progress + log stream — pipelined so all three + // Redis calls share one round trip. The result key keeps its DEL + // (so we can attribute its removal count to the report's + // `result` field, unchanged public contract); the progress key + // and the log stream ride along as `UNLINK` (async reclaim — a + // multi-MB log stream never stalls the call). All three keys + // share the `{chasqui:}` hash tag so the pipeline is + // Cluster-correct. { - let key = crate::redis::keys::result_key(queue_name, job_id); + let r_key = crate::redis::keys::result_key(queue_name, job_id); + let p_key = progress_key(queue_name, job_id); + let l_key = log_key(queue_name, job_id); let client = pool.next_connected(); - let cmd = CustomCommand::new_static("DEL", ClusterHash::FirstKey, false); - let v: Value = client - .custom(cmd, vec![Value::from(key)]) + + let pipeline = client.pipeline(); + let del_cmd = CustomCommand::new_static("DEL", ClusterHash::FirstKey, false); + pipeline + .custom::(del_cmd, vec![Value::from(r_key.as_str())]) + .await + .map_err(Error::Redis)?; + let unlink_cmd = CustomCommand::new_static("UNLINK", ClusterHash::FirstKey, false); + pipeline + .custom::(unlink_cmd.clone(), vec![Value::from(p_key)]) .await .map_err(Error::Redis)?; - report.result = lua_int(&v) >= 1; + pipeline + .custom::(unlink_cmd, vec![Value::from(l_key)]) + .await + .map_err(Error::Redis)?; + let replies = pipeline.all::().await.map_err(Error::Redis)?; + // First reply is the DEL count for the result key. + report.result = match &replies { + Value::Array(items) => items.first().map(lua_int).unwrap_or(0) >= 1, + single => lua_int(single) >= 1, + }; } Ok(report) @@ -420,15 +484,22 @@ pub(super) async fn clean( return Ok(Vec::new()); } let cutoff = now_ms().saturating_sub(grace_ms); - match state { - JobState::Waiting => clean_stream(pool, stream_key, group, cutoff, limit, false).await, - JobState::Failed => clean_stream(pool, dlq_key, group, cutoff, limit, true).await, - JobState::Delayed => clean_delayed(pool, queue_name, delayed_key, cutoff, limit).await, - JobState::Completed => clean_completed(pool, queue_name, limit).await, + let removed = match state { + JobState::Waiting => clean_stream(pool, stream_key, group, cutoff, limit, false).await?, + JobState::Failed => clean_stream(pool, dlq_key, group, cutoff, limit, true).await?, + JobState::Delayed => clean_delayed(pool, queue_name, delayed_key, cutoff, limit).await?, + JobState::Completed => clean_completed(pool, queue_name, limit).await?, // Active jobs are in-flight; removing one mid-execution is a // footgun. `remove(id)` is the deliberate per-job escape hatch. - JobState::Active | JobState::Unknown => Ok(Vec::new()), - } + JobState::Active | JobState::Unknown => return Ok(Vec::new()), + }; + // Mirror `remove(id)`'s tail: every removed job's per-job progress + // key + log stream must also go. The per-state helpers above only + // touch the primary surface (stream / DLQ / delayed ZSET / result + // key); without this sweep the auxiliary keys would outlive the + // job and only be reclaimed by `obliterate`. + unlink_progress_and_log(pool, queue_name, &removed).await; + Ok(removed) } /// `XPENDING - + ` → the set of entry ids currently diff --git a/chasquimq/src/producer/mod.rs b/chasquimq/src/producer/mod.rs index 664c648..eb453dd 100644 --- a/chasquimq/src/producer/mod.rs +++ b/chasquimq/src/producer/mod.rs @@ -29,8 +29,9 @@ use std::sync::Arc; use std::time::{Duration, SystemTime, UNIX_EPOCH}; pub use crate::redis::keys::{ - dedup_marker_key, delayed_index_key, delayed_key, dlq_key, events_key, paused_key, - promoter_lock_key, repeat_key, repeat_spec_key, result_key, scheduler_lock_key, stream_key, + dedup_marker_key, delayed_index_key, delayed_key, dlq_key, events_key, log_key, paused_key, + progress_key, promoter_lock_key, repeat_key, repeat_spec_key, result_key, scheduler_lock_key, + stream_key, }; #[derive(Debug, Clone)] diff --git a/chasquimq/src/progress.rs b/chasquimq/src/progress.rs new file mode 100644 index 0000000..8b4b1f0 --- /dev/null +++ b/chasquimq/src/progress.rs @@ -0,0 +1,376 @@ +//! Per-handler `JobHandle` for in-handler progress reports and log lines. +//! +//! A `JobHandle` is attached to [`crate::Job`] by the consumer before the +//! user handler runs. Handlers call: +//! +//! - [`JobHandle::update_progress`] to record an integer 0..=100 against the +//! per-job progress key (`{chasqui:}:progress:`), readable by +//! the introspector and by external dashboards via the events stream. +//! - [`JobHandle::log`] to append a UTF-8 line to the per-job log stream +//! (`{chasqui:}:log:`), readable via +//! `Introspector::get_job_logs`. +//! +//! Design notes: +//! +//! - **Progress storage**: plain Redis STRING containing the ASCII decimal +//! of a `u8` (so a shim can read it with `parseInt` / `int(str(...))` +//! without a msgpack dependency). TTL `result_ttl_secs` so it disappears +//! alongside the result key after job completion. +//! - **Log storage**: Redis Stream, one entry per call, field `line`. +//! `MAXLEN ~ ` keeps the stream bounded; the trim +//! is approximate (the `~`) so Redis can do it cheaply. Each `log()` +//! refreshes an `EXPIRE` of `result_ttl_secs` on the stream key so the +//! log disappears alongside the result key after job completion; +//! without that, `MAXLEN` caps the entries but leaves the key itself +//! indefinitely. +//! - **Connection budget**: a `JobHandle` borrows a shared +//! [`fred::clients::Pool`] (sized 2–8) — never a client per worker. +//! - **Bounded lines**: lines exceeding `log_max_line_bytes` are truncated +//! on a UTF-8 char boundary with a `"[…truncated]"` marker appended, so +//! a malformed line cannot exhaust Redis memory. +//! - **Warn-once**: clamp and truncate each fire a single `tracing::warn!` +//! per handle so a hot-loop handler doesn't flood the log. +//! - **Best-effort events**: when `events_progress_enabled` is true the +//! handle emits an `e=progress` event after the SET succeeds. The event +//! write is best-effort (same contract as every other engine event); a +//! failed XADD never propagates back to the handler. + +use crate::error::{Error, Result}; +use crate::events::EventsWriter; +use crate::redis::keys::{log_key, progress_key}; +use fred::clients::Pool; +use fred::interfaces::ClientLike; +use fred::types::{ClusterHash, CustomCommand, Value}; +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, Ordering}; + +/// Truncation marker appended to oversize log lines. Encoded in UTF-8; +/// the truncation point is walked back to a char boundary before this +/// is appended so the assembled line stays well-formed. +const TRUNCATED_MARKER: &str = "[\u{2026}truncated]"; + +/// Per-handler progress + log surface. Attached to [`crate::Job::handle`] +/// by the consumer immediately before the user handler runs; absent +/// (`None`) on `Job` instances returned by the introspector's +/// read-only paths. +pub struct JobHandle { + job_id: Arc, + queue_name: Arc, + pool: Pool, + result_ttl_secs: u64, + log_max_stream_len: u64, + log_max_line_bytes: usize, + events: Option, + job_name: Option>, + events_progress_enabled: bool, + warned_clamp: AtomicBool, + warned_truncate: AtomicBool, +} + +impl std::fmt::Debug for JobHandle { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("JobHandle") + .field("job_id", &self.job_id) + .field("queue_name", &self.queue_name) + .field("result_ttl_secs", &self.result_ttl_secs) + .field("log_max_stream_len", &self.log_max_stream_len) + .field("log_max_line_bytes", &self.log_max_line_bytes) + .field("events_progress_enabled", &self.events_progress_enabled) + .finish() + } +} + +impl JobHandle { + /// Construct a handle. Engine-internal — the consumer wires this in + /// per-dispatch; user code never calls this directly. + #[allow(clippy::too_many_arguments)] + pub(crate) fn new( + job_id: Arc, + queue_name: Arc, + pool: Pool, + result_ttl_secs: u64, + log_max_stream_len: u64, + log_max_line_bytes: usize, + events: Option, + job_name: Option>, + events_progress_enabled: bool, + ) -> Self { + Self { + job_id, + queue_name, + pool, + result_ttl_secs, + log_max_stream_len, + log_max_line_bytes, + events, + job_name, + events_progress_enabled, + warned_clamp: AtomicBool::new(false), + warned_truncate: AtomicBool::new(false), + } + } + + /// Test-only constructor: opens a small `Pool` against `redis_url`, + /// omits the events writer + job name fields, and returns a handle + /// suitable for asserting against the SET / XADD / XLEN paths + /// without bringing up a full Consumer. Exposed as `pub` and + /// `#[doc(hidden)]` so the engine's integration tests + /// (`tests/progress_and_log.rs`) can use it; production code + /// constructs handles via the consumer's worker wiring. + #[doc(hidden)] + pub async fn new_for_test( + redis_url: &str, + job_id: Arc, + queue_name: Arc, + result_ttl_secs: u64, + log_max_stream_len: u64, + log_max_line_bytes: usize, + ) -> Result { + let pool = crate::redis::conn::connect_pool( + redis_url, + 2, + &crate::config::ConnectionTuning::default(), + ) + .await?; + Ok(Self::new( + job_id, + queue_name, + pool, + result_ttl_secs, + log_max_stream_len, + log_max_line_bytes, + None, + None, + false, + )) + } + + /// The job id this handle reports against. Stable for the handle's + /// lifetime. + pub fn job_id(&self) -> &str { + &self.job_id + } + + /// Record `n` (clamped to `0..=100`) against the per-job progress + /// key. A SET with TTL `result_ttl_secs` so the value disappears + /// alongside the result key after a successful completion. + /// + /// Out-of-range values (`n > 100`) are clamped to 100, and the first + /// such clamp logs a single `tracing::warn!` per handle so a + /// hot-loop handler doesn't flood the operator log. + /// + /// When `events_progress_enabled` is true (default), a best-effort + /// `e=progress` event is emitted after the SET succeeds. A failed + /// event-emit never causes this method to return `Err` — the + /// persisted state is the source of truth. + pub async fn update_progress(&self, n: u8) -> Result<()> { + let clamped = if n > 100 { + if !self.warned_clamp.swap(true, Ordering::Relaxed) { + tracing::warn!( + job_id = %self.job_id, + requested = n, + "update_progress: value > 100; clamping (warn-once per handle)" + ); + } + 100 + } else { + n + }; + + let key = progress_key(&self.queue_name, &self.job_id); + let client = self.pool.next_connected(); + let cmd = CustomCommand::new_static("SET", ClusterHash::FirstKey, false); + let ttl = i64::try_from(self.result_ttl_secs).unwrap_or(i64::MAX); + let args = vec![ + Value::from(key), + Value::from(clamped.to_string()), + Value::from("EX"), + Value::from(ttl), + ]; + client + .custom::(cmd, args) + .await + .map_err(Error::Redis)?; + + // SET-first-then-emit: the persisted progress value is the + // source of truth; a failed event-emit must never leave + // subscribers ahead of (or behind) what an introspector would + // read. Event emission itself is best-effort — `xadd` swallows + // errors and warns at the events module. + if self.events_progress_enabled + && let Some(events) = &self.events + { + let name = self.job_name.as_deref(); + events.emit_progress(&self.job_id, name, clamped).await; + } + + Ok(()) + } + + /// Append `line` to the per-job log stream and return the new stream + /// length (one XADD + XLEN + EXPIRE, pipelined into a single round + /// trip). + /// + /// Lines exceeding `log_max_line_bytes` are truncated to the largest + /// UTF-8 char boundary at or below that byte cap and have the marker + /// `"[…truncated]"` appended. The first truncation per handle logs a + /// single `tracing::warn!` so a hot-loop handler can't flood the + /// operator log. + /// + /// The trailing `EXPIRE log_key result_ttl_secs` keeps the stream + /// key from outliving the result it belongs to — `MAXLEN ~` caps the + /// entry count but not the key itself, so a job that logs once and + /// never logs again would leak the stream indefinitely without this. + pub async fn log(&self, line: &str) -> Result { + let payload = self.truncate_line(line); + + let key = log_key(&self.queue_name, &self.job_id); + let client = self.pool.next_connected(); + let pipeline = client.pipeline(); + + let xadd_cmd = CustomCommand::new_static("XADD", ClusterHash::FirstKey, false); + let xadd_args = vec![ + Value::from(key.as_str()), + Value::from("MAXLEN"), + Value::from("~"), + Value::from(i64::try_from(self.log_max_stream_len).unwrap_or(i64::MAX)), + Value::from("*"), + Value::from("line"), + Value::from(payload.as_ref()), + ]; + pipeline + .custom::(xadd_cmd, xadd_args) + .await + .map_err(Error::Redis)?; + + let xlen_cmd = CustomCommand::new_static("XLEN", ClusterHash::FirstKey, false); + pipeline + .custom::(xlen_cmd, vec![Value::from(key.as_str())]) + .await + .map_err(Error::Redis)?; + + let expire_cmd = CustomCommand::new_static("EXPIRE", ClusterHash::FirstKey, false); + let ttl = i64::try_from(self.result_ttl_secs).unwrap_or(i64::MAX); + pipeline + .custom::( + expire_cmd, + vec![Value::from(key.as_str()), Value::from(ttl)], + ) + .await + .map_err(Error::Redis)?; + + let results = pipeline.all::().await.map_err(Error::Redis)?; + Ok(extract_xlen(&results)) + } + + /// Returns the line as-is when it fits; otherwise walks back to the + /// nearest UTF-8 char boundary at-or-below `log_max_line_bytes` and + /// appends the truncation marker. + fn truncate_line<'a>(&self, line: &'a str) -> std::borrow::Cow<'a, str> { + if line.len() <= self.log_max_line_bytes { + return std::borrow::Cow::Borrowed(line); + } + if !self.warned_truncate.swap(true, Ordering::Relaxed) { + tracing::warn!( + job_id = %self.job_id, + len = line.len(), + cap = self.log_max_line_bytes, + "log: line exceeds log_max_line_bytes; truncating (warn-once per handle)" + ); + } + let cap = self.log_max_line_bytes; + let mut cut = cap.min(line.len()); + while cut > 0 && !line.is_char_boundary(cut) { + cut -= 1; + } + let mut out = String::with_capacity(cut + TRUNCATED_MARKER.len()); + out.push_str(&line[..cut]); + out.push_str(TRUNCATED_MARKER); + std::borrow::Cow::Owned(out) + } +} + +/// The pipeline returns `[XADD-reply, XLEN-reply, EXPIRE-reply]`; +/// recover the XLEN integer (the second element). Saturating-on- +/// non-integer means a surprise reply shape doesn't panic in the +/// user's handler. +fn extract_xlen(results: &Value) -> u64 { + let arr = match results { + Value::Array(items) => items, + _ => return 0, + }; + match arr.get(1) { + Some(Value::Integer(n)) => u64::try_from(*n).unwrap_or(0), + _ => 0, + } +} + +#[cfg(test)] +mod tests { + use super::*; + + /// `truncate_line` is the pure-function core of `log()`'s oversize + /// handling. Exercise it in isolation: a 1-byte cap, multibyte UTF-8 + /// at the cut point, and a marker that survives at the tail. We + /// build a handle with a stub pool only to instantiate the method; + /// no Redis is touched. + fn cap_truncate(input: &str, cap: usize) -> String { + let mut cut = cap.min(input.len()); + while cut > 0 && !input.is_char_boundary(cut) { + cut -= 1; + } + let mut out = String::with_capacity(cut + TRUNCATED_MARKER.len()); + out.push_str(&input[..cut]); + out.push_str(TRUNCATED_MARKER); + out + } + + #[test] + fn truncate_walks_back_to_utf8_boundary() { + let s = "a\u{1F600}bcd"; // "a" + 4-byte emoji + "bcd" + // emoji starts at byte 1, ends at byte 5. cap=3 lands in the middle + // of the emoji; walk-back must stop at byte 1. + let out = cap_truncate(s, 3); + assert!(out.starts_with('a'), "got: {out:?}"); + assert!(out.ends_with(TRUNCATED_MARKER)); + assert_eq!(&out[..1], "a"); + } + + #[test] + fn truncate_marker_appended_only_when_over_cap() { + let s = "hello"; + // cap >= len: bare string (the production path returns Borrowed). + // Here we model the marker-append path only, so emulate the + // production short-circuit explicitly. + if s.len() <= 10 { + assert_eq!(s, "hello"); + } else { + let out = cap_truncate(s, 10); + assert!(out.ends_with(TRUNCATED_MARKER)); + } + } + + #[test] + fn extract_xlen_pulls_second_element_integer() { + // Production shape: [XADD-reply, XLEN-reply, EXPIRE-reply]. + let v = Value::Array(vec![ + Value::String("1700000000000-0".into()), + Value::Integer(42), + Value::Integer(1), + ]); + assert_eq!(extract_xlen(&v), 42); + } + + #[test] + fn extract_xlen_defaults_to_zero_on_surprise_shape() { + assert_eq!(extract_xlen(&Value::Null), 0); + assert_eq!(extract_xlen(&Value::Array(vec![Value::Integer(1)])), 0); + assert_eq!( + extract_xlen(&Value::Array(vec![ + Value::String("x".into()), + Value::String("not-int".into()), + ])), + 0 + ); + } +} diff --git a/chasquimq/src/redis/keys.rs b/chasquimq/src/redis/keys.rs index 63a413e..b4f2139 100644 --- a/chasquimq/src/redis/keys.rs +++ b/chasquimq/src/redis/keys.rs @@ -107,3 +107,72 @@ pub fn delayed_index_key(queue_name: &str, job_id: &str) -> String { pub fn paused_key(queue_name: &str) -> String { format!("{{chasqui:{queue_name}}}:paused") } + +/// Per-queue, per-job-id progress key. Holds the latest progress value +/// (`0..=100`, written as a plain ASCII decimal string by the engine so +/// every shim can `parseInt` / `int(str(...))` it without a msgpack +/// dependency) with TTL `result_ttl_secs` so it disappears alongside the +/// result key after a successful job completes. Written by +/// [`crate::JobHandle::update_progress`] from inside a worker; read by +/// the introspector and by shim-side `Job.progress` / `Queue.getJob` +/// callers. Same `{chasqui:}` hash tag so it co-locates on the +/// same Redis Cluster slot as the stream and result key. +pub fn progress_key(queue_name: &str, job_id: &str) -> String { + format!("{{chasqui:{queue_name}}}:progress:{job_id}") +} + +/// Per-queue, per-job-id log stream. Each call to +/// [`crate::JobHandle::log`] appends one entry under field `line`. The +/// stream is `MAXLEN ~`-trimmed by `ConsumerConfig::log_max_stream_len` +/// so a chatty handler can't grow Redis unbounded. Read back via +/// `Introspector::get_job_logs` (XRANGE / XREVRANGE + XLEN). Same +/// `{chasqui:}` hash tag so it co-locates on the same Redis +/// Cluster slot as the stream and result key. +pub fn log_key(queue_name: &str, job_id: &str) -> String { + format!("{{chasqui:{queue_name}}}:log:{job_id}") +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Every per-queue key must carry the `{chasqui:}` hash tag + /// so Redis Cluster routes the whole keyspace to a single slot. The + /// engine's CustomCommand calls use `ClusterHash::FirstKey`, which + /// relies on this invariant — losing it would scatter a queue's keys + /// across slots and break atomic multi-key Lua. + #[test] + fn progress_and_log_keys_share_queue_hash_tag() { + let pk = progress_key("demo", "job-abc"); + let lk = log_key("demo", "job-abc"); + assert_eq!(pk, "{chasqui:demo}:progress:job-abc"); + assert_eq!(lk, "{chasqui:demo}:log:job-abc"); + + // The hash tag content (between the braces) must match the other + // per-queue keys exactly — otherwise Cluster places them on + // different slots than the stream / result key. + let stream = stream_key("demo"); + let tag = |s: &str| { + let start = s.find('{').unwrap(); + let end = s.find('}').unwrap(); + s[start..=end].to_string() + }; + assert_eq!(tag(&pk), tag(&stream)); + assert_eq!(tag(&lk), tag(&stream)); + assert_eq!(tag(&pk), tag(&result_key("demo", "job-abc"))); + } + + /// Job ids with `:` characters (legacy slug ids, user-supplied ids + /// from `add_with_id`) must not interfere with the hash tag or the + /// `progress:` / `log:` prefix — the tag is closed before the id is + /// concatenated, and the prefix is fixed. + #[test] + fn job_ids_with_colons_are_safe() { + let pk = progress_key("q", "user:42:retry"); + let lk = log_key("q", "user:42:retry"); + assert_eq!(pk, "{chasqui:q}:progress:user:42:retry"); + assert_eq!(lk, "{chasqui:q}:log:user:42:retry"); + assert!(pk.starts_with("{chasqui:q}:progress:")); + assert!(lk.starts_with("{chasqui:q}:log:")); + } +} diff --git a/chasquimq/tests/maintenance.rs b/chasquimq/tests/maintenance.rs index 301bbb3..d06a3d3 100644 --- a/chasquimq/tests/maintenance.rs +++ b/chasquimq/tests/maintenance.rs @@ -357,6 +357,117 @@ async fn remove_nonexistent_is_idempotent() { admin.quit().await.ok(); } +#[tokio::test] +#[ignore = "requires REDIS_URL"] +async fn remove_also_purges_progress_and_log_keys() { + let admin = admin().await; + let queue = "mnt_remove_progress_log"; + flush_all(&admin, queue).await; + + let id = "remove-target"; + let progress_key = format!("{{chasqui:{queue}}}:progress:{id}"); + let log_key = format!("{{chasqui:{queue}}}:log:{id}"); + let result_key = format!("{{chasqui:{queue}}}:result:{id}"); + + // Plant a progress key, a log entry, and a result key — all + // three are independent surfaces `remove` should sweep. + let _: Value = admin + .custom( + CustomCommand::new_static("SET", ClusterHash::FirstKey, false), + vec![Value::from(progress_key.clone()), Value::from("42")], + ) + .await + .expect("SET progress"); + let _: Value = admin + .custom( + CustomCommand::new_static("XADD", ClusterHash::FirstKey, false), + vec![ + Value::from(log_key.clone()), + Value::from("*"), + Value::from("line"), + Value::from("first log"), + ], + ) + .await + .expect("XADD log"); + let _: Value = admin + .custom( + CustomCommand::new_static("SET", ClusterHash::FirstKey, false), + vec![Value::from(result_key.clone()), Value::from("r")], + ) + .await + .expect("SET result"); + + assert!(exists(&admin, &progress_key).await); + assert!(exists(&admin, &log_key).await); + assert!(exists(&admin, &result_key).await); + + let producer: Producer = Producer::connect(&redis_url(), producer_cfg(queue)) + .await + .expect("connect"); + let report = producer + .remove(&id.to_string(), "default") + .await + .expect("remove"); + assert!(report.result, "result key removed"); + + assert!(!exists(&admin, &progress_key).await, "progress purged"); + assert!(!exists(&admin, &log_key).await, "log stream purged"); + assert!(!exists(&admin, &result_key).await, "result purged"); + + producer.shutdown().await.ok(); + admin.quit().await.ok(); +} + +#[tokio::test] +#[ignore = "requires REDIS_URL"] +async fn obliterate_sweeps_progress_and_log_keys() { + let admin = admin().await; + let queue = "mnt_obliterate_progress_log"; + flush_all(&admin, queue).await; + + // SCAN MATCH `{chasqui:}:*` already covers progress + log keys + // because they share the queue hash tag — pin that here so a + // future change to the key shape (or to obliterate's pattern) + // can't silently regress. + let progress_key = format!("{{chasqui:{queue}}}:progress:job-A"); + let log_key = format!("{{chasqui:{queue}}}:log:job-A"); + let _: Value = admin + .custom( + CustomCommand::new_static("SET", ClusterHash::FirstKey, false), + vec![Value::from(progress_key.clone()), Value::from("17")], + ) + .await + .expect("SET progress"); + let _: Value = admin + .custom( + CustomCommand::new_static("XADD", ClusterHash::FirstKey, false), + vec![ + Value::from(log_key.clone()), + Value::from("*"), + Value::from("line"), + Value::from("only line"), + ], + ) + .await + .expect("XADD log"); + + assert!(exists(&admin, &progress_key).await); + assert!(exists(&admin, &log_key).await); + + let producer: Producer = Producer::connect(&redis_url(), producer_cfg(queue)) + .await + .expect("connect"); + let _removed = producer.obliterate("default").await.expect("obliterate"); + + assert!(!exists(&admin, &progress_key).await, "progress swept"); + assert!(!exists(&admin, &log_key).await, "log swept"); + assert_eq!(count_keys(&admin, queue).await, 0, "entire keyspace nuked"); + + producer.shutdown().await.ok(); + admin.quit().await.ok(); +} + #[tokio::test] #[ignore = "requires REDIS_URL"] async fn remove_active_pending_job() { @@ -737,6 +848,76 @@ async fn clean_waiting_removes_old_entries() { admin.quit().await.ok(); } +#[tokio::test] +#[ignore = "requires REDIS_URL"] +async fn clean_purges_progress_and_log_keys() { + let admin = admin().await; + let queue = "mnt_clean_progress_log"; + flush_all(&admin, queue).await; + + let producer: Producer = Producer::connect(&redis_url(), producer_cfg(queue)) + .await + .expect("connect"); + + // Enqueue three waiting jobs and plant a progress key + a log + // stream entry against each one — the same per-job surfaces + // `remove(id)` is responsible for sweeping. `clean()` must do the + // same for every job it removes. + let mut ids: Vec = Vec::new(); + for n in 0..3_u32 { + let id = producer + .add(Sample { n, s: "w".into() }) + .await + .expect("add"); + let progress_key = format!("{{chasqui:{queue}}}:progress:{id}"); + let log_key = format!("{{chasqui:{queue}}}:log:{id}"); + let _: Value = admin + .custom( + CustomCommand::new_static("SET", ClusterHash::FirstKey, false), + vec![Value::from(progress_key.clone()), Value::from("17")], + ) + .await + .expect("SET progress"); + let _: Value = admin + .custom( + CustomCommand::new_static("XADD", ClusterHash::FirstKey, false), + vec![ + Value::from(log_key.clone()), + Value::from("*"), + Value::from("line"), + Value::from("first"), + ], + ) + .await + .expect("XADD log"); + assert!(exists(&admin, &progress_key).await); + assert!(exists(&admin, &log_key).await); + ids.push(id); + } + + let removed = producer + .clean("default", 0, 1000, JobState::Waiting) + .await + .expect("clean"); + assert_eq!(removed.len(), 3, "all 3 waiting cleaned"); + + for id in &ids { + let progress_key = format!("{{chasqui:{queue}}}:progress:{id}"); + let log_key = format!("{{chasqui:{queue}}}:log:{id}"); + assert!( + !exists(&admin, &progress_key).await, + "progress key purged by clean for {id}" + ); + assert!( + !exists(&admin, &log_key).await, + "log stream purged by clean for {id}" + ); + } + + producer.shutdown().await.ok(); + admin.quit().await.ok(); +} + #[tokio::test] #[ignore = "requires REDIS_URL"] async fn clean_grace_window_excludes_recent() { diff --git a/chasquimq/tests/progress_and_log.rs b/chasquimq/tests/progress_and_log.rs new file mode 100644 index 0000000..d60100e --- /dev/null +++ b/chasquimq/tests/progress_and_log.rs @@ -0,0 +1,539 @@ +//! Integration tests for the per-handler progress + log surface +//! ([`chasquimq::JobHandle`]). +//! +//! Each test runs against a real Redis (REDIS_URL) and asserts the +//! per-job progress key / log stream are populated as expected. The +//! handle is constructed directly (not via the worker dispatch wiring, +//! which is exercised by a separate commit) so the tests can isolate +//! the SET / XADD + XLEN paths. + +mod common; + +use chasquimq::introspect::{Introspector, JobState}; +use chasquimq::producer::{Producer, log_key, progress_key}; +use chasquimq::{ConnectionTuning, Consumer, ConsumerConfig, JobHandle, RetryConfig}; +use fred::interfaces::ClientLike; +use fred::types::{ClusterHash, CustomCommand, Value}; +use serde::{Deserialize, Serialize}; +use std::sync::Arc; +use std::time::Duration; +use tokio_util::sync::CancellationToken; + +use common::{admin, flush_all, producer_cfg, redis_url, wait_until}; + +#[derive(Serialize, Deserialize, Debug, Clone)] +struct ProgressSample { + n: u32, +} + +/// Helper: build a [`JobHandle`] bound to a fresh small pool. The test +/// owns the pool's connection budget so a misbehaving test can't drain +/// the engine's worker pool. +async fn make_handle( + queue: &str, + job_id: &str, + result_ttl_secs: u64, + log_max_stream_len: u64, + log_max_line_bytes: usize, +) -> JobHandle { + JobHandle::new_for_test( + &redis_url(), + Arc::from(job_id), + Arc::from(queue), + result_ttl_secs, + log_max_stream_len, + log_max_line_bytes, + ) + .await + .expect("connect") +} + +/// Wipe progress + log keys for `(queue, job_id)` so a re-run starts +/// clean. The shared `flush_all` only DELs the queue-scoped surfaces +/// (stream / dlq / delayed / events); per-job keys need their own cleanup. +async fn flush_progress_log(admin: &fred::clients::Client, queue: &str, job_id: &str) { + for key in [progress_key(queue, job_id), log_key(queue, job_id)] { + let _: Value = admin + .custom( + CustomCommand::new_static("DEL", ClusterHash::FirstKey, false), + vec![Value::from(key)], + ) + .await + .expect("DEL"); + } +} + +async fn redis_get(admin: &fred::clients::Client, key: &str) -> Option { + let v: Value = admin + .custom( + CustomCommand::new_static("GET", ClusterHash::FirstKey, false), + vec![Value::from(key)], + ) + .await + .expect("GET"); + match v { + Value::String(s) => Some(s.to_string()), + Value::Bytes(b) => std::str::from_utf8(&b).ok().map(|s| s.to_string()), + Value::Null => None, + other => panic!("unexpected GET reply: {other:?}"), + } +} + +async fn redis_ttl(admin: &fred::clients::Client, key: &str) -> i64 { + let v: Value = admin + .custom( + CustomCommand::new_static("TTL", ClusterHash::FirstKey, false), + vec![Value::from(key)], + ) + .await + .expect("TTL"); + match v { + Value::Integer(n) => n, + other => panic!("unexpected TTL reply: {other:?}"), + } +} + +async fn redis_pttl(admin: &fred::clients::Client, key: &str) -> i64 { + let v: Value = admin + .custom( + CustomCommand::new_static("PTTL", ClusterHash::FirstKey, false), + vec![Value::from(key)], + ) + .await + .expect("PTTL"); + match v { + Value::Integer(n) => n, + other => panic!("unexpected PTTL reply: {other:?}"), + } +} + +async fn xlen(admin: &fred::clients::Client, key: &str) -> i64 { + let v: Value = admin + .custom( + CustomCommand::new_static("XLEN", ClusterHash::FirstKey, false), + vec![Value::from(key)], + ) + .await + .expect("XLEN"); + match v { + Value::Integer(n) => n, + Value::Null => 0, + other => panic!("unexpected XLEN reply: {other:?}"), + } +} + +async fn xrange_lines(admin: &fred::clients::Client, key: &str) -> Vec { + let v: Value = admin + .custom( + CustomCommand::new_static("XRANGE", ClusterHash::FirstKey, false), + vec![Value::from(key), Value::from("-"), Value::from("+")], + ) + .await + .expect("XRANGE"); + let items = match v { + Value::Array(items) => items, + _ => return Vec::new(), + }; + let mut out = Vec::with_capacity(items.len()); + for entry in items { + let Value::Array(pair) = entry else { continue }; + let Some(Value::Array(fields)) = pair.into_iter().nth(1) else { + continue; + }; + let mut iter = fields.into_iter(); + while let (Some(k), Some(v)) = (iter.next(), iter.next()) { + let k = match k { + Value::String(s) => s.to_string(), + Value::Bytes(b) => String::from_utf8_lossy(&b).to_string(), + other => format!("{other:?}"), + }; + let v = match v { + Value::String(s) => s.to_string(), + Value::Bytes(b) => String::from_utf8_lossy(&b).to_string(), + other => format!("{other:?}"), + }; + if k == "line" { + out.push(v); + } + } + } + out +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn progress_writes_key_and_sets_ttl() { + let admin = admin().await; + let queue = "progress_log_p1"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-progress-1").await; + + let handle = make_handle(queue, "job-progress-1", 60, 1000, 4096).await; + handle.update_progress(42).await.expect("update_progress"); + + let key = progress_key(queue, "job-progress-1"); + let got = redis_get(&admin, &key).await.expect("progress key present"); + assert_eq!(got, "42", "ASCII decimal"); + let ttl = redis_ttl(&admin, &key).await; + assert!( + ttl > 0 && ttl <= 60, + "TTL must be set and within result_ttl_secs (got {ttl})" + ); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn progress_clamps_out_of_range() { + let admin = admin().await; + let queue = "progress_log_p2"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-clamp").await; + + let handle = make_handle(queue, "job-clamp", 60, 1000, 4096).await; + handle.update_progress(250).await.expect("update_progress"); + handle.update_progress(200).await.expect("warn-once second"); + + let key = progress_key(queue, "job-clamp"); + let got = redis_get(&admin, &key).await.expect("present"); + assert_eq!(got, "100", "clamped to 100"); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn log_appends_lines_in_order_and_returns_xlen() { + let admin = admin().await; + let queue = "progress_log_l1"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-log-1").await; + + let handle = make_handle(queue, "job-log-1", 60, 1000, 4096).await; + let n1 = handle.log("first").await.expect("log 1"); + let n2 = handle.log("second").await.expect("log 2"); + let n3 = handle.log("third").await.expect("log 3"); + assert_eq!((n1, n2, n3), (1, 2, 3), "XLEN grows monotonically"); + + let key = log_key(queue, "job-log-1"); + assert_eq!(xlen(&admin, &key).await, 3); + let lines = xrange_lines(&admin, &key).await; + assert_eq!(lines, vec!["first", "second", "third"]); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn log_truncates_oversize_line_on_utf8_boundary() { + let admin = admin().await; + let queue = "progress_log_l2"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-log-trunc").await; + + // Cap 8 bytes — well below the natural line length below. + let handle = make_handle(queue, "job-log-trunc", 60, 1000, 8).await; + let line = "abc\u{1F600}def\u{1F600}xyz"; // emoji = 4 bytes each + handle.log(line).await.expect("log"); + + let key = log_key(queue, "job-log-trunc"); + let lines = xrange_lines(&admin, &key).await; + assert_eq!(lines.len(), 1); + let got = &lines[0]; + assert!( + got.ends_with("[\u{2026}truncated]"), + "truncation marker appended: {got:?}" + ); + // Truncation must respect UTF-8: the head is a valid str (the + // assertion that `got` is a `String` already implies that — but + // confirm we didn't slice through the emoji at byte 4). + assert!(got.starts_with("abc"), "head preserved: {got:?}"); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +#[ignore = "requires REDIS_URL"] +async fn worker_dispatch_attaches_job_handle_and_handler_can_update_progress() { + let admin = admin().await; + let queue = "progress_log_dispatch"; + flush_all(&admin, queue).await; + + let producer: Producer = Producer::connect(&redis_url(), producer_cfg(queue)) + .await + .expect("connect producer"); + let job_id = producer.add(ProgressSample { n: 1 }).await.expect("add"); + flush_progress_log(&admin, queue, &job_id).await; + + let cfg = ConsumerConfig { + queue_name: queue.to_string(), + group: "default".to_string(), + consumer_id: format!("c-{}", uuid::Uuid::new_v4()), + block_ms: 50, + retry: RetryConfig { + initial_backoff_ms: 20, + max_backoff_ms: 500, + multiplier: 2.0, + jitter_ms: 0, + }, + max_attempts: 3, + delayed_enabled: false, + concurrency: 4, + ..Default::default() + }; + + let consumer: Consumer = Consumer::new(redis_url(), cfg); + let shutdown = CancellationToken::new(); + let shutdown_h = shutdown.clone(); + let handle = tokio::spawn(async move { + consumer + .run( + move |job| async move { + let h = job + .handle + .as_ref() + .expect("worker wired a JobHandle onto the dispatched Job"); + h.update_progress(50).await.expect("update_progress"); + Ok(chasquimq::Bytes::new()) + }, + shutdown_h, + ) + .await + }); + + let key = progress_key(queue, &job_id); + { + let admin = admin.clone(); + let key = key.clone(); + wait_until(Duration::from_secs(5), move || { + let admin = admin.clone(); + let key = key.clone(); + async move { redis_get(&admin, &key).await.as_deref() == Some("50") } + }) + .await; + } + + shutdown.cancel(); + let _ = tokio::time::timeout(Duration::from_secs(10), handle).await; + + let got = redis_get(&admin, &key).await.expect("present"); + assert_eq!(got, "50"); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn empty_line_appends_an_entry() { + let admin = admin().await; + let queue = "progress_log_l3"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-log-empty").await; + + let handle = make_handle(queue, "job-log-empty", 60, 1000, 4096).await; + let n = handle.log("").await.expect("log"); + assert_eq!(n, 1, "even an empty line bumps XLEN"); + + let key = log_key(queue, "job-log-empty"); + assert_eq!(xlen(&admin, &key).await, 1); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn introspector_get_job_populates_progress() { + let admin = admin().await; + let queue = "progress_log_i1"; + flush_all(&admin, queue).await; + + // Make a producer-side stream entry so `get_job` resolves to Waiting, + // then write a progress value via a handle and assert it surfaces. + let producer: Producer = Producer::connect(&redis_url(), producer_cfg(queue)) + .await + .expect("connect producer"); + let job_id = producer.add(ProgressSample { n: 1 }).await.expect("add"); + flush_progress_log(&admin, queue, &job_id).await; + + let handle = make_handle(queue, &job_id, 60, 1000, 4096).await; + handle.update_progress(73).await.expect("update"); + + let inspector = Introspector::connect(&redis_url(), queue, &ConnectionTuning::default(), None) + .await + .expect("introspector"); + let info = inspector + .get_job(&job_id) + .await + .expect("get_job") + .expect("Some"); + assert_eq!(info.state, JobState::Waiting); + assert_eq!(info.progress, Some(73)); + + inspector.shutdown().await.ok(); + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn introspector_get_job_progress_none_when_unset() { + let admin = admin().await; + let queue = "progress_log_i2"; + flush_all(&admin, queue).await; + + let producer: Producer = Producer::connect(&redis_url(), producer_cfg(queue)) + .await + .expect("connect producer"); + let job_id = producer.add(ProgressSample { n: 1 }).await.expect("add"); + flush_progress_log(&admin, queue, &job_id).await; + + let inspector = Introspector::connect(&redis_url(), queue, &ConnectionTuning::default(), None) + .await + .expect("introspector"); + let info = inspector + .get_job(&job_id) + .await + .expect("get_job") + .expect("Some"); + assert_eq!(info.progress, None, "no progress key = None"); + + inspector.shutdown().await.ok(); + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn get_job_logs_asc_and_desc_and_pagination() { + let admin = admin().await; + let queue = "progress_log_g1"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-logs").await; + + let handle = make_handle(queue, "job-logs", 60, 1000, 4096).await; + for i in 0..5 { + handle.log(&format!("line-{i}")).await.expect("log"); + } + + let inspector = Introspector::connect(&redis_url(), queue, &ConnectionTuning::default(), None) + .await + .expect("introspector"); + + // Full asc page. + let (asc, total) = inspector + .get_job_logs("job-logs", 0, -1, true) + .await + .expect("get_job_logs asc"); + assert_eq!(total, 5); + assert_eq!(asc, vec!["line-0", "line-1", "line-2", "line-3", "line-4"]); + + // Full desc page. + let (desc, _) = inspector + .get_job_logs("job-logs", 0, -1, false) + .await + .expect("get_job_logs desc"); + assert_eq!(desc, vec!["line-4", "line-3", "line-2", "line-1", "line-0"]); + + // Window [1, 3] asc. + let (page, _) = inspector + .get_job_logs("job-logs", 1, 3, true) + .await + .expect("get_job_logs window"); + assert_eq!(page, vec!["line-1", "line-2", "line-3"]); + + // Negative start: "last two lines, asc within that window". + let (tail, _) = inspector + .get_job_logs("job-logs", -2, -1, true) + .await + .expect("get_job_logs negative"); + assert_eq!(tail, vec!["line-3", "line-4"]); + + inspector.shutdown().await.ok(); + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn log_key_has_ttl_matching_result_ttl_secs() { + let admin = admin().await; + let queue = "progress_log_ttl"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-log-ttl").await; + + let result_ttl_secs: u64 = 60; + let handle = make_handle(queue, "job-log-ttl", result_ttl_secs, 1000, 4096).await; + handle.log("first line").await.expect("log"); + + let key = log_key(queue, "job-log-ttl"); + let pttl = redis_pttl(&admin, &key).await; + assert!( + pttl > 0 && pttl <= (result_ttl_secs * 1000) as i64, + "log key PTTL must be > 0 and <= result_ttl_secs * 1000 (got {pttl})" + ); + + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn get_job_logs_handles_extreme_negative_offsets() { + let admin = admin().await; + let queue = "progress_log_g3"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "job-extreme").await; + + let handle = make_handle(queue, "job-extreme", 60, 1000, 4096).await; + for i in 0..3 { + handle.log(&format!("line-{i}")).await.expect("log"); + } + + let inspector = Introspector::connect(&redis_url(), queue, &ConnectionTuning::default(), None) + .await + .expect("introspector"); + + // `i64::MIN` as `start` historically panicked in debug + // (`attempt to add with overflow`) and wrapped in release. With + // saturating arithmetic, start clamps to 0 and we get every entry. + let (lines, total) = inspector + .get_job_logs("job-extreme", i64::MIN, -1, true) + .await + .expect("get_job_logs must not panic on i64::MIN start"); + assert_eq!(total, 3); + assert_eq!(lines, vec!["line-0", "line-1", "line-2"]); + + // `i64::MIN` as `end` saturates below 0 → window is empty, return + // `(vec![], total)` rather than overflow. + let (lines, total) = inspector + .get_job_logs("job-extreme", 0, i64::MIN, true) + .await + .expect("get_job_logs must not panic on i64::MIN end"); + assert_eq!(total, 3); + assert!( + lines.is_empty(), + "i64::MIN end clamps to a below-zero hi → empty window" + ); + + inspector.shutdown().await.ok(); + let _: () = admin.quit().await.unwrap(); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +#[ignore = "requires REDIS_URL"] +async fn get_job_logs_empty_returns_zero_count() { + let admin = admin().await; + let queue = "progress_log_g2"; + flush_all(&admin, queue).await; + flush_progress_log(&admin, queue, "no-logs").await; + + let inspector = Introspector::connect(&redis_url(), queue, &ConnectionTuning::default(), None) + .await + .expect("introspector"); + let (logs, total) = inspector + .get_job_logs("no-logs", 0, -1, true) + .await + .expect("get_job_logs"); + assert!(logs.is_empty()); + assert_eq!(total, 0); + + inspector.shutdown().await.ok(); + let _: () = admin.quit().await.unwrap(); +} diff --git a/docs/engine.md b/docs/engine.md index a7f0f1a..aeffc73 100644 --- a/docs/engine.md +++ b/docs/engine.md @@ -91,10 +91,10 @@ Operational notes: Surface: -- **`remove(job_id, group) -> RemovalReport`** — delete one job everywhere it could live: the delayed ZSET (plus its `didx` / `dlid` side-indexes), a waiting or active main-stream entry, the DLQ, and the per-job result key. Idempotent — a `job_id` on no surface returns an all-`false` `RemovalReport { delayed, stream, dlq, result }`, not an error. The stable `JobId` lives inside the msgpack envelope, not the Redis stream entry id, so the stream / DLQ branches run a bounded `XRANGE` scan to translate the job id to an entry id before the atomic `XACKDEL` / `XDEL`. A job past the bounded scan window reports as "not on this surface" — pair with the introspection API to find jobs deep in a very large stream. The delayed branch reuses `CANCEL_DELAYED_SCRIPT` verbatim. +- **`remove(job_id, group) -> RemovalReport`** — delete one job everywhere it could live: the delayed ZSET (plus its `didx` / `dlid` side-indexes), a waiting or active main-stream entry, the DLQ, the per-job result key, and the per-job [progress + log keys](#progress-and-logs). Idempotent — a `job_id` on no surface returns an all-`false` `RemovalReport { delayed, stream, dlq, result }`, not an error. The stable `JobId` lives inside the msgpack envelope, not the Redis stream entry id, so the stream / DLQ branches run a bounded `XRANGE` scan to translate the job id to an entry id before the atomic `XACKDEL` / `XDEL`. A job past the bounded scan window reports as "not on this surface" — pair with the introspection API to find jobs deep in a very large stream. The delayed branch reuses `CANCEL_DELAYED_SCRIPT` verbatim. - **`drain(group, DrainOptions) -> u64`** — clear every *waiting* job (main-stream entries not in any consumer-group PEL) and, by default, the delayed ZSET. In-flight (pending) jobs are left running. `DrainOptions { delayed: false }` keeps scheduled future jobs. A ChasquiMQ stream mixes waiting and active entries on one Redis Stream, so `DRAIN_STREAM_SCRIPT` subtracts the `XPENDING` set from an `XRANGE` page and `XDEL`s the complement; the drain runs in bounded passes until a pass deletes nothing. Returns the total stream + delayed count removed. -- **`clean(group, grace_ms, limit, state) -> Vec`** — age- and state-filtered bulk delete; removes up to `limit` jobs in `state` older than `now - grace_ms` and returns the removed job ids. Supported states: `Waiting`, `Failed` (DLQ), `Delayed`, `Completed`. `Active` is a deliberate no-op (removing an in-flight job mid-execution is a footgun — use `remove`). Age basis: the stream entry id's millisecond prefix for `Waiting` / `Failed`; the job's `created_at_ms` for `Delayed`; `grace_ms` is **ignored** for `Completed` (a result key has no creation timestamp — its own `result_ttl_secs` handles age-out, so `clean(Completed, …)` is limit-only). -- **`obliterate(group) -> u64`** — tear the entire `{chasqui:}` keyspace down: the main stream and its consumer groups, the DLQ, the delayed ZSET, every `didx` / `dlid` side-index, every result key, all repeatable specs, the durable paused flag, the events stream, and the promoter / scheduler locks. Implemented as a batched `SCAN` + `UNLINK` (async reclaim, so a multi-GB stream never stalls Redis). Not atomic — but obliterate is a destructive admin op and a crash mid-teardown is fully recoverable by re-running (the next `SCAN` finds the remainder). Returns the count of Redis keys removed. +- **`clean(group, grace_ms, limit, state) -> Vec`** — age- and state-filtered bulk delete; removes up to `limit` jobs in `state` older than `now - grace_ms` and returns the removed job ids. Supported states: `Waiting`, `Failed` (DLQ), `Delayed`, `Completed`. `Active` is a deliberate no-op (removing an in-flight job mid-execution is a footgun — use `remove`). Age basis: the stream entry id's millisecond prefix for `Waiting` / `Failed`; the job's `created_at_ms` for `Delayed`; `grace_ms` is **ignored** for `Completed` (a result key has no creation timestamp — its own `result_ttl_secs` handles age-out, so `clean(Completed, …)` is limit-only). Per removed job the bulk path matches `remove`'s semantics: the [per-job progress + log keys](#progress-and-logs) are unlinked in the same pipeline. +- **`obliterate(group) -> u64`** — tear the entire `{chasqui:}` keyspace down: the main stream and its consumer groups, the DLQ, the delayed ZSET, every `didx` / `dlid` side-index, every result key, every progress + log key, all repeatable specs, the durable paused flag, the events stream, and the promoter / scheduler locks. Implemented as a batched `SCAN` + `UNLINK` (async reclaim, so a multi-GB stream never stalls Redis). Not atomic — but obliterate is a destructive admin op and a crash mid-teardown is fully recoverable by re-running (the next `SCAN` finds the remainder). Returns the count of Redis keys removed. Operational notes: @@ -103,6 +103,29 @@ Operational notes: - **`clean(Completed)` is limit-only.** No `grace_ms` filtering — result keys carry no creation timestamp. Rely on `result_ttl_secs` for time-based result expiry; use `clean(Completed, …)` only to reclaim result keys eagerly. - **The CLI exposes `clean` and `obliterate`.** `chasqui clean --state --grace-ms --limit ` and `chasqui obliterate `; both are destructive and prompt for confirmation unless `--yes` is passed. +## Progress and logs + +Per-handler write surface for in-flight job state. Attached to `Job::handle` as `Option` immediately before the user handler runs; absent on Jobs returned by `Introspector::get_job` / `get_jobs` (which throws a read-only error if a caller tries to write). + +Two side-channel Redis keys under the queue's existing `{chasqui:}` hash tag (single-slot on Redis Cluster): + +- **`{chasqui:}:progress:`** — STRING. ASCII-decimal `u8` (so any shim reads it with `parseInt` / `int(str(...))` without a msgpack dependency). TTL = `result_ttl_secs` so it disappears alongside the result key after a successful completion. Written by `JobHandle::update_progress(n)`; read by the introspector and surfaced on `JobInfo::progress: Option`. Values `> 100` clamp to 100 (warn-once per handle). +- **`{chasqui:}:log:`** — STREAM. One entry per `JobHandle::log(line)` call, under field `line`. `MAXLEN ~ log_max_stream_len` keeps the stream bounded. Each `log()` also pipelines `EXPIRE log_key result_ttl_secs` so the stream key disappears alongside the result key after job completion — `MAXLEN ~` caps entries but not the key itself, so without this an orphan one-shot log line would leak the stream indefinitely. Oversize lines (`> log_max_line_bytes`) truncate on a UTF-8 char boundary with a `[…truncated]` marker (warn-once per handle). Read back via `Introspector::get_job_logs(id, start, end, asc) -> (Vec, u64)` — `start = -N` means "N from the end" via XLEN (matches BullMQ's `getLogs` convention); the trailing `u64` is the current XLEN. + +Three new `ConsumerConfig` fields (also configurable through both shims): + +- `log_max_stream_len: u64 = 1000` — `MAXLEN ~` cap on each per-job log stream. Validated `≥ 16` at `Consumer::run` (below the minimum, the `MAXLEN ~` rounding leaves the stream effectively empty between writes). +- `log_max_line_bytes: usize = 4096` — per-line byte cap before truncation. +- `events_progress_enabled: bool = true` — gates the `e=progress` events-stream entry emitted after a successful `update_progress` SET. The persisted progress key is always written regardless; this only mutes the events fan-out, so a high-rate progress handler can opt out of the events flood while keeping introspector-visible state. + +Connection budget: `JobHandle` borrows a **shared 2–8-sized `fred::clients::Pool`** sized to consumer concurrency — never a client per worker. Handlers that never call `update_progress` / `log` pay nothing. + +Both keys are reaped on the existing maintenance paths: `Producer::remove(id)` unlinks them in the same pipeline as the result key; `Producer::clean(state, ...)` mirrors the same per-removed-job tail; `Producer::obliterate()` already deletes the whole `{chasqui:}` keyspace. + +**`progress` event on the events stream.** When `events_progress_enabled = true` (default), every `update_progress` call emits an `e=progress` entry on `{chasqui:}:events` after the SET succeeds (best-effort — a failed XADD never propagates back to the handler; the persisted key is the source of truth). The Node and Python shims fan this onto `Worker.on('progress', (job, n) => ...)` (via a lazy embedded `QueueEvents` subscriber, same zero-cost-when-unused pattern as `drained`) plus broadcast `'progress'` and per-id `'progress:'` channels on `QueueEvents`. + +**Read-only Job guard.** Jobs returned by `Queue.getJob` / `getJobs` / `Queue.add` (and any other introspector- or producer-side path) carry no per-handler `JobHandle`. Calling `updateProgress` / `log` on those raises a clear "read-only Job" error on both shims (`Error` with the marker message on Node, `RuntimeError` on Python). Only Jobs handed to a `Worker` processor have a live backref. + ## Observability Every load-bearing engine subsystem emits structured events through the single `chasquimq::MetricsSink` trait: diff --git a/docs/history.md b/docs/history.md index c5a2e0b..54e395a 100644 --- a/docs/history.md +++ b/docs/history.md @@ -340,6 +340,58 @@ Bench (same-host, no engine changes — empty `git diff main -- chasquimq/src` s Doc surfaces synced: this slice, both shim READMEs (symmetric "Subscribing to events" + "Awaiting a single job's completion" sections), `site/src/content/docs/reference/{node-api,python-api}.md` (Worker events table extended; new `waitUntilFinished` / `wait_until_finished` sections; QueueEvents per-id channels documented; `WaitUntilFinishedTimeoutError` in the errors section), a new `concepts/events-and-listeners.md` registered in `site/astro.config.mjs` (+ a link in `concepts/index.md`), and the root `README.md` feature table. +## Progress + logs (cross-FFI slice) + +**`Job.updateProgress(n)` + `Job.log(line)` + `Queue.getJobLogs(id)` shipped, cross-FFI, May 2026.** Closes the long-accepted-but-no-op `progress` / log gap on both shims (both were previously documented as "accepted for API parity but no-op — engine doesn't emit those transitions yet"). The slice adds a per-handler write surface that persists progress to a side-channel Redis STRING, appends log lines to a per-job Redis Stream, and re-fans both onto the events stream so existing `Worker` / `QueueEvents` subscribers observe them. The envelope (msgpack `Job`) is untouched — wire-format-stable. + +Engine surface: + +- **`JobHandle` (`chasquimq/src/progress.rs`)** — per-dispatch handle attached to `Job::handle` immediately before the user handler runs (`Option`); absent on Jobs returned by the introspector's read-only paths. + - `update_progress(n: u8)` writes `{chasqui:}:progress:` as an **ASCII decimal `u8`** STRING (so every shim can `parseInt` / `int(str(...))` it without a msgpack dependency) with TTL = `result_ttl_secs`. Values `> 100` are clamped to 100; the first clamp per handle fires a single `tracing::warn!`. After the SET succeeds, a best-effort `e=progress` events-stream entry is emitted (gated by `events_progress_enabled`). + - `log(line: &str)` `XADD`s one entry under field `line` to `{chasqui:}:log:` (Stream), pipelined with `XLEN` (returned) and `EXPIRE log_key result_ttl_secs`. `MAXLEN ~ log_max_stream_len` keeps the stream bounded. Oversize lines (`> log_max_line_bytes`) are truncated on a UTF-8 char boundary with a `[…truncated]` marker appended; first truncation per handle fires a single warn-once. + - Connection budget: a **shared 2–8-sized `fred::clients::Pool`** drives both APIs — never a client per worker. Zero round trips when the handler never calls these. + +- **Introspector (`chasquimq/src/introspect.rs`)** — `JobInfo` gains a `progress: Option` field, pipelined into every `get_job` / `get_jobs` path so the side-channel read adds no extra round trip in the common case. New `Introspector::get_job_logs(id, start, end, asc)` returns `(Vec, u64)` — the captured `line` field values plus the current XLEN. `start = -N` resolves to "this many from the end" via XLEN (matching BullMQ's `getLogs` convention); `end = -1` means "to end". + +- **`ConsumerConfig` (`chasquimq/src/config.rs`)** — three new fields with defaults: + - `log_max_stream_len: u64 = 1000` (validated `≥ 16` at `Consumer::run`; below the minimum, `MAXLEN ~` rounding leaves the stream effectively empty). + - `log_max_line_bytes: usize = 4096`. + - `events_progress_enabled: bool = true` — gates only the events-stream XADD; the persisted progress key is always written. + +- **Maintenance** — `Producer::remove(id)` was extended to pipeline `UNLINK` on the per-job progress + log keys alongside the existing surfaces; `clean()` reaps the same per removed job; `obliterate()` already deletes the whole `{chasqui:}` keyspace, including the new `progress:*` / `log:*` keys. + +Events: new `progress` event on the cross-process events stream (fields `e=progress`, `id`, `n`, `progress`). Best-effort fan-out — a failed events XADD never propagates back to the handler (the persisted progress key is the source of truth). + +Node shim (`chasquimq-node`): + +- `Job.updateProgress(n: number)` (was previously a stub) — forwards to the native `Job.updateProgress`. `Job.log(line)` returns `Promise` (new XLEN). Both throw `Error('Job.updateProgress() requires the Job be passed to your Worker handler; Jobs returned by Queue.getJob() are read-only')` when called on a synthesized read-only Job (no `_native` backref). +- `Queue.getJobLogs(jobId, start?, end?, asc?)` returns `{ logs: string[], count: number }` (`count` is the current XLEN, not `logs.length`). Reads via the introspector. +- `WorkerOptions` gains `logMaxLen` / `logMaxLineBytes` / `eventsProgressEnabled` — all forwarded to the native `ConsumerConfig` fields. +- `Worker` emits new `'progress'` event `(job, n)`. The shim lazily spawns an embedded `QueueEvents` subscriber the first time a `progress` listener attaches (same zero-cost-when-unused pattern as `drained`), torn down on `close()`. The forwarder re-uses the in-flight `Job` instance from the worker's `_inflight` map so handler-side `job.progress` and the EE callback observe identical state. +- `QueueEvents` gains broadcast `'progress'` + per-id `'progress:'` channels. +- **Breaking (TS types only):** `JobProgress` narrowed from `number | object` to `number`. No runtime impact — engine wire format never carried the object form. + +Python shim (`chasquimq-py`): + +- `Job.update_progress(n: int)` + `Job.log(line: str)` — same read-only Job guard (raises `RuntimeError`). +- `Queue.get_job_logs(job_id, *, start=0, end=-1, asc=True)` returns `(list[str], int)`. +- `Worker` keyword args gain `log_max_stream_len` / `log_max_line_bytes` / `events_progress_enabled`. +- `Worker` emits new `progress` event `(job, n)` via the same lazy embedded `QueueEvents` subscriber as `drained`. +- `QueueEvents` emits `progress` + per-id `progress:` channels. +- `Job` dataclass gains `progress: Optional[int]` (populated by introspector on read paths; mirrored by `update_progress` on the live path). + +Three follow-up bugs caught during post-implementation review and fixed in dedicated commits before this slice committed docs: + +1. **Log stream key TTL.** The original `log()` only set `MAXLEN ~`, which bounds entry count but not the key itself — a job that logs once then never logs again would leak the stream indefinitely. Fix: pipeline an `EXPIRE log_key result_ttl_secs` on every `log()` call so the stream key disappears alongside the result key after job completion. +2. **`clean()` progress/log leak.** `Producer::remove(id)` was extended to unlink the per-job progress + log keys, but the bulk `clean()` path only unlinked the stream/DLQ/result tail. Fix: extracted `unlink_progress_and_log` helper, called from `clean()` for each removed job so the bulk path matches the per-job semantics. +3. **`i64::MIN` in `get_job_logs` arithmetic.** Negative `start` is interpreted as "this many from the end" (`total + start`); plain `+` on `i64::MIN` panics in debug builds. Fix: switched to `saturating_add` so a malformed caller offset clamps to a sensible window instead of panicking inside the introspector. + +Bench (`benchmarks/progress-log-slice.md`): the slice touches the consumer dispatch path (`JobHandle` attached per dispatch) plus the introspector (`progress` field on `JobInfo`), so the host-load explanation is forfeited per the gate in `benchmarks/README.md`. Every per-scenario delta vs the 1.0 baseline is within one stddev — `queue-add-bulk` −2.4% (baseline stddev 4,909), `worker-concurrent` −1.1% (baseline stddev 4,246), `queue-add` +6.3%. No regression. `JobHandle` carries only `Arc` clones plus a shared pool reference (zero per-job allocation, zero extra round trips), and the introspector field is pipelined into the existing `get_job` lookups. + +Tests: 16 engine integration cases (live Redis — `tests/progress_and_log.rs`), 8 vitest cases (Node, `__test__/progress-and-log.test.ts`), 14 pytest cases (Python, `tests/test_progress_and_log.py`), + a cross-shim Node↔Python contract test pinning the ASCII-`u8` wire format in both directions. Plus `progress_throughput` Criterion bench scenario (`chasquimq-bench/benches/progress_throughput.rs`). + +Doc surfaces synced: this slice, root `README.md` (feature row), `docs/engine.md` (new "Progress and logs" section + ConsumerConfig fields + read-only Job guard), both shim READMEs (symmetric "Progress and logs" sections), `site/src/content/docs/reference/{node-api,python-api,rust-api}.md` (`Job.updateProgress` / `log`, `Queue.getJobLogs`, `JobHandle`, `Introspector::get_job_logs`, `JobInfo.progress`), `site/src/content/docs/reference/options.md` (three new ConsumerConfig fields), `site/src/content/docs/reference/wire-format.md` (new STRING + STREAM keys under the `{chasqui:}` hash tag), `site/src/content/docs/concepts/events-and-listeners.md` (`progress` event documented as live; `stalled` remains the only no-op listener), `benchmarks/README.md` index, and `benchmarks/progress-log-slice.md`. + ## Deferred follow-ups for 1.x - **Opt-in result-write bench scenario.** The PR #75 bench guard locked in the no-overhead-when-off claim (`store_results=false` regresses 0%). The opt-in path (`store_results=true` under sustained load) is not yet measured. diff --git a/site/src/content/docs/concepts/events-and-listeners.md b/site/src/content/docs/concepts/events-and-listeners.md index 8d7265d..ba0df5f 100644 --- a/site/src/content/docs/concepts/events-and-listeners.md +++ b/site/src/content/docs/concepts/events-and-listeners.md @@ -25,26 +25,29 @@ The events stream carries these transitions, all best-effort (a network blip on | `failed` | Worker, after the processor raises. | `jobId`, `name`, `failedReason`, `attempt` | | `retry-scheduled` | Retry relocator, after an atomic reschedule onto the delayed ZSET. | `jobId`, `name`, `attempt`, `backoffMs` | | `dlq` | DLQ relocator, after writing the entry to the DLQ stream. | `jobId`, `name`, `reason`, `attempt` | +| `progress` | Worker, after the handler's `updateProgress(n)` SET succeeds. | `jobId`, `name`, `progress` | | `drained` | Reader, on a full→empty transition (not on every empty poll). | (queue-scoped) | `retries-exhausted` is a synthetic alias of `dlq` (with the `reason` carried as the engine's `DlqReason` string) that the Node shim emits to match existing high-level-shim subscribers. -Two listener names are accepted on both shims for API stability but are currently no-op — the engine does not emit the underlying transition yet: +`progress` is best-effort fan-out — the persisted progress key (`{chasqui:}:progress:`) is the source of truth. A failed events XADD never propagates back to the handler. High-rate progress reporters that don't need cross-process fan-out can mute the events with `WorkerOptions.eventsProgressEnabled: false` (Node) / `Worker(events_progress_enabled=False)` (Python); the persisted key is still written. + +One listener name is accepted on both shims for API stability but is currently no-op — the engine does not emit the underlying transition yet: -- `progress` — requires engine support for in-handler progress updates. - `stalled` — requires a stalled-detector in the engine. -Wire them up safely; they'll start firing when the corresponding engine work lands. +Wire it up safely; it'll start firing when the corresponding engine work lands. ## Per-id channels -For events that carry a `jobId` (`active`, `completed`, `failed`), `QueueEvents` also fans the event onto a per-id channel named `:`. Targeted subscribers (like `Job.waitUntilFinished` / `Job.wait_until_finished`) listen there directly instead of filtering every broadcast event by id — at large fan-out this is the difference between an `O(N-listeners)` dispatch tax and an `O(1)` one. +For events that carry a `jobId` (`active`, `completed`, `failed`, `progress`), `QueueEvents` also fans the event onto a per-id channel named `:`. Targeted subscribers (like `Job.waitUntilFinished` / `Job.wait_until_finished`) listen there directly instead of filtering every broadcast event by id — at large fan-out this is the difference between an `O(N-listeners)` dispatch tax and an `O(1)` one. -The channel naming convention is `:` (e.g. `completed:` / `failed:`). Power users can subscribe directly: +The channel naming convention is `:` (e.g. `completed:` / `failed:` / `progress:`). Power users can subscribe directly: ```ts events.on(`completed:${jobId}`, ({ jobId }) => { /* this job, done */ }); events.on(`failed:${jobId}`, ({ failedReason }) => { /* this job, failed */ }); +events.on(`progress:${jobId}`, ({ progress }) => { /* this job, 0..=100 */ }); ``` ## The return-value choice @@ -67,10 +70,21 @@ For low-latency awaits of jobs you just enqueued, `waitUntilFinished` is the rig ## Lazy subscriber lifecycle -The `Worker.on('drained', ...)` listener is the only `Worker` event that requires cross-process traffic. The shim lazily spawns an embedded `QueueEvents` subscriber the first time a `drained` listener attaches; it's torn down on `Worker.close()`. Workers that never subscribe to `drained` pay no extra Redis connections — this is a strict zero-overhead-when-unused contract. +`Worker.on('drained', ...)` and `Worker.on('progress', ...)` are the only `Worker` events that require cross-process traffic. The shim lazily spawns one embedded `QueueEvents` subscriber the first time *either* listener attaches; it's torn down on `Worker.close()`. Workers that never subscribe pay no extra Redis connections — this is a strict zero-overhead-when-unused contract. The same lazy pattern applies on the Python `Worker`. Cross-shim symmetric. +## Muting the `progress` event for high-rate handlers + +`Job.updateProgress(n)` always writes the persisted progress key (`{chasqui:}:progress:` STRING, TTL = `result_ttl_secs`). On top of that, by default it also emits a cross-process `e=progress` events-stream entry so subscribers see live updates. + +For a handler that reports progress hundreds of times per job — a large file upload reporting per-chunk percent, a streaming media transcode, an ML training loop — the events fan-out can dominate Redis traffic without adding observability value (operators rarely watch sub-second progress). Mute the fan-out without losing the persisted state: + +- Node: `new Worker(name, handler, { eventsProgressEnabled: false, ... })` +- Python: `Worker(queue_name, handler, events_progress_enabled=False, ...)` + +The persisted progress key still updates on every call, so `Queue.getJob(id).progress` (introspector) returns the latest value. Only the events-stream `progress` channel (broadcast and per-id) goes quiet. + ## Lost-event race Events emitted *before* a subscriber's first `XREAD BLOCK` lands are missed. The shims minimise this race: diff --git a/site/src/content/docs/reference/node-api.md b/site/src/content/docs/reference/node-api.md index 4fcfdac..8aca9e4 100644 --- a/site/src/content/docs/reference/node-api.md +++ b/site/src/content/docs/reference/node-api.md @@ -257,6 +257,34 @@ async count(): Promise `waiting + active + delayed` — the number of jobs that could still run. +### `queue.getJobLogs(jobId, start?, end?, asc?)` + +```ts +async getJobLogs( + jobId: string, + start?: number, + end?: number, + asc?: boolean, +): Promise<{ logs: string[]; count: number }> +``` + +Read up to `end - start + 1` lines from a job's log stream +(`{chasqui:}:log:` STREAM, populated by +[`Job.log`](#joblogline) inside a processor). `start` / `end` are +inclusive entry offsets in the requested order; `end = -1` means +"to end"; negative `start` is "this many from the end" +(translated via XLEN), matching BullMQ's `Queue.getJobLogs` +convention. `asc` defaults to `true` (chronological). + +Returns `{ logs, count }`: + +- `logs` — captured `line` field values in the requested order. +- `count` — current XLEN of the log stream (**not** `logs.length`). + Lets paginating callers know how many entries exist without + walking the whole stream. + +Jobs that never called `Job.log` resolve with `{ logs: [], count: 0 }`. + ### `queue.remove(jobId)`, `queue.removeReport(jobId)` ```ts @@ -506,9 +534,12 @@ class Job ``` -In-memory progress update. The engine does not persist progress; -the worker shim surfaces this via the `progress` event when called -from inside a processor. +Persist a `0..=100` progress value for this job under the engine's +per-job progress key (`{chasqui:}:progress:` STRING, +TTL = `result_ttl_secs`), mirror it on the local `progress` field, +and (when `WorkerOptions.eventsProgressEnabled !== false`) emit an +`e=progress` events-stream entry that `QueueEvents` re-fans onto +the broadcast `'progress'` channel and the per-id +`'progress:'` channel. + +Values outside `0..=100` are clamped to `100` at the engine +boundary (no throw; the first clamp per handle logs a single +warn-once). + +**Read-only Job guard.** Throws when called on a Job returned by +[`queue.getJob`](#queuegetjobjobid) / [`queue.getJobs`](#queuegetjobstypes-start-end) +or constructed from [`queue.add`](#queueaddname-data-opts) — those +instances are synthesized from introspector / producer-side data +and carry no per-handler connection. Only Jobs handed to a +`Worker` processor have a live backref. Catch via +`err.message.startsWith('Job.updateProgress()')`. + +### `job.log(line)` + +```ts +async log(line: string): Promise +``` + +Append `line` to the per-job log stream +(`{chasqui:}:log:` STREAM) and return the new XLEN. +The stream is bounded by `WorkerOptions.logMaxLen` (default +`1000`) via `MAXLEN ~` and expires alongside the result key +(TTL = `result_ttl_secs`). Oversize lines (`> logMaxLineBytes`, +default `4096`) truncate on a UTF-8 char boundary with a +`[…truncated]` marker appended; first truncation per handle logs +a single warn-once. + +Same read-only Job guard as [`updateProgress`](#jobupdateprogressprogress). +Read back via [`queue.getJobLogs`](#queuegetjoblogsjobid-start-end-asc). ### `job.waitForResult(opts?)` @@ -614,7 +679,7 @@ Plain-object snapshot of the job for logging / serialization. ### Stubbed methods -`log`, `getState`, `remove`, `retry`, `discard`, `update`, +`getState`, `remove`, `retry`, `discard`, `update`, `updateData`, `isCompleted`, `isFailed`, `isActive`, `isWaiting` all throw `NotSupportedError` or return a fixed `false` in v1 — engine-side state queries land in a future slice. `isDelayed()` @@ -660,6 +725,7 @@ Implements `[Symbol.asyncDispose]`. | `delayed` | `({ jobId, name, delay }, eventId)` | Producer enqueued with `delay > 0`. | | `dlq` | `({ jobId, name, reason, attempt }, eventId)` | DLQ relocator wrote the entry to the DLQ stream. | | `retries-exhausted` | `({ jobId, name, attemptsMade, reason }, eventId)` | Synthetic alias of `dlq` (chasquimq-specific). | +| `progress` | `({ jobId, name, progress }, eventId)` | Handler called [`job.updateProgress(n)`](#jobupdateprogressprogress). `progress` is the clamped `0..=100` value the engine persisted. | | `drained` | `(eventId)` | Engine drained (queue-scoped, no `jobId`). | | `unknown` | `({ eventName, fields }, eventId)` | Forward-compat sink for unrecognized event types. | | `error` | `(err)` | Operational error during XREAD. | @@ -673,6 +739,7 @@ alongside the matching broadcast for events that carry a `jobId` | `active:` | `({ jobId, name, prev, attempt }, eventId)` | `active` | | `completed:` | `({ jobId, name, attempt, returnvalue }, eventId)` | `completed` | | `failed:` | `({ jobId, name, failedReason, attempt }, eventId)` | `failed` | +| `progress:` | `({ jobId, name, progress }, eventId)` | `progress` | Per-id channels let `Job.waitUntilFinished` (and any UI watching one job) wire a targeted listener without paying the O(N-listeners) @@ -744,6 +811,9 @@ interface WorkerOptions { schedulerTickMs?: number; storeResults?: boolean; resultTtlMs?: number; + logMaxLen?: number; + logMaxLineBytes?: number; + eventsProgressEnabled?: boolean; } ``` @@ -758,6 +828,18 @@ interface WorkerOptions { - `schedulerTickMs` — scheduler tick interval. **Default `1000`.** - `storeResults` — persist handler return values to `{chasqui:}:result:`. **Default `false`.** - `resultTtlMs` — TTL for stored results. **Default `3_600_000` (1h).** Rounded up to whole seconds at the FFI boundary. +- `logMaxLen` — `MAXLEN ~` cap on each per-job log stream + (`{chasqui:}:log:`). **Default `1000`.** Must be `>= 16` + (`Consumer::run` rejects sub-minimum values — below that, the + `MAXLEN ~` rounding can leave the stream effectively empty). +- `logMaxLineBytes` — per-line byte cap for [`Job.log`](#joblogline). + Lines exceeding this are truncated on a UTF-8 char boundary + with a `[…truncated]` marker appended. **Default `4096`.** +- `eventsProgressEnabled` — gates the `e=progress` events-stream + entry emitted by [`Job.updateProgress`](#jobupdateprogressprogress). + The persisted progress key is always written; this only mutes + the events fan-out a `QueueEvents` subscriber would observe. + **Default `true`.** ### `JobsOptions` @@ -930,7 +1012,7 @@ path. ```ts type JobState = "waiting" | "active" | "completed" | "failed" | "delayed" | "unknown"; type JobType = JobState | "paused" | "prioritized" | "waiting-children"; -type JobProgress = number | object; +type JobProgress = number; ``` `JobState` is the engine's job-state classification, used by @@ -940,6 +1022,14 @@ type JobProgress = number | object; `"waiting-children"` are accepted on `JobType` for call-site compatibility but have no engine semantics in v1. +`JobProgress` is `number` — the engine persists it as an ASCII +`u8` (0..=100), so any non-numeric or out-of-range value passed +to [`updateProgress`](#jobupdateprogressprogress) is clamped at +the engine boundary. **Breaking (TS types only):** previously +typed as `number | object` to mirror BullMQ; narrowed to +`number` in the progress-and-logs slice. No runtime impact — +the engine wire format never carried the object form. + ### `RemovalReport` ```ts diff --git a/site/src/content/docs/reference/options.md b/site/src/content/docs/reference/options.md index 6568164..5bd35f1 100644 --- a/site/src/content/docs/reference/options.md +++ b/site/src/content/docs/reference/options.md @@ -113,6 +113,14 @@ exists. | QueueEvents subscriber start id | `QueueEventsOptions.lastEventId` (**`"$"`**) | `QueueEvents(last_event_id="$")` | (build your own with `XREAD`) | Where to start tailing the events stream. | | QueueEvents block timeout (ms) | `QueueEventsOptions.blockingTimeout` (**10_000**) | `QueueEvents(block_ms=5000)` | n/a | `XREAD BLOCK` timeout. | +## Progress and logs + +| Option | Node | Python | Rust | Controls | +|---|---|---|---|---| +| Per-job log stream `MAXLEN ~` | `WorkerOptions.logMaxLen` (**1000**) | `Worker(log_max_stream_len=...)` (default engine **1000**) | `ConsumerConfig::log_max_stream_len` (**1000**) | `MAXLEN ~` cap on each per-job log stream (`{chasqui:}:log:`) written by [`Job.log`](/reference/rust-api/#jobhandle). Must be `≥ 16` (`Consumer::run` rejects sub-minimum values — below that, the `MAXLEN ~` rounding can leave the stream effectively empty between writes). The stream is also `EXPIRE`d to `result_ttl_secs` on every `log()` call so the key disappears alongside the result. | +| Per-line byte cap | `WorkerOptions.logMaxLineBytes` (**4096**) | `Worker(log_max_line_bytes=...)` (default engine **4096**) | `ConsumerConfig::log_max_line_bytes` (**4096**) | Lines longer than this are truncated on a UTF-8 char boundary with a `[…truncated]` marker appended. First truncation per handle logs a single warn-once. | +| Progress events fan-out | `WorkerOptions.eventsProgressEnabled` (**true**) | `Worker(events_progress_enabled=...)` (default engine **true**) | `ConsumerConfig::events_progress_enabled` (**true**) | Gates the `e=progress` events-stream entry emitted by `update_progress`. The persisted progress key (`{chasqui:}:progress:` STRING) is always written; setting this to `false` only mutes the cross-process fan-out, which a `QueueEvents` subscriber would otherwise observe on the broadcast `progress` channel and the per-id `progress:` channel. Useful for high-rate progress reporters that don't need cross-process fan-out. | + ## Introspection | Option | Node | Python | Rust | Controls | diff --git a/site/src/content/docs/reference/python-api.md b/site/src/content/docs/reference/python-api.md index 0dfabcb..0e46a61 100644 --- a/site/src/content/docs/reference/python-api.md +++ b/site/src/content/docs/reference/python-api.md @@ -388,6 +388,33 @@ and the job's creation time for `"delayed"`. `grace_ms` is **ignored** for `"completed"` — a stored result has no creation timestamp; rely on the result TTL for time-based expiry. +### `await queue.get_job_logs(job_id, *, start=0, end=-1, asc=True)` + +```python +async def get_job_logs( + self, + job_id: str, + *, + start: int = 0, + end: int = -1, + asc: bool = True, +) -> tuple[list[str], int] +``` + +Read up to `end - start + 1` lines from a job's log stream +(`{chasqui:}:log:` STREAM, populated by +[`Job.log`](#await-joblogline) inside a processor). `start` / +`end` are inclusive entry offsets in the requested order; +`end = -1` means "to end"; negative `start` is "this many from +the end" (translated via XLEN), matching BullMQ's +`Queue.getJobLogs` convention. `asc` defaults to `True` +(chronological). + +Returns `(lines, count)` where `count` is the current XLEN of +the log stream (**not** `len(lines)`) — lets paginating callers +know how many entries exist without walking the whole stream. +Jobs that never called `Job.log` resolve with `([], 0)`. + ### `await queue.obliterate()` ```python @@ -455,6 +482,9 @@ class Worker: scheduler_tick_ms: int | None = None, store_results: bool = False, result_ttl_ms: int | None = None, + log_max_stream_len: int | None = None, + log_max_line_bytes: int | None = None, + events_progress_enabled: bool | None = None, ) -> None: ... ``` @@ -479,6 +509,19 @@ on `{chasqui:}:scheduler:lock`. - `scheduler_tick_ms` — scheduler tick interval. **Default engine: `1000`.** - `store_results` — persist handler return values to the result key. **Default `False`.** - `result_ttl_ms` — TTL for stored results. **Default engine: `3_600_000` (1h).** Rounded up to whole seconds at the FFI boundary. +- `log_max_stream_len` — `MAXLEN ~` cap on each per-job log + stream (`{chasqui:}:log:`). **Default engine: `1000`.** + Must be `>= 16` (`Consumer::run` rejects sub-minimum values — + below that, the `MAXLEN ~` rounding can leave the stream + effectively empty). +- `log_max_line_bytes` — per-line byte cap for [`Job.log`](#await-joblogline). + Lines exceeding this are truncated on a UTF-8 char boundary + with a `[…truncated]` marker appended. **Default engine: `4096`.** +- `events_progress_enabled` — gates the `e=progress` + events-stream entry emitted by [`Job.update_progress`](#await-jobupdate_progressn). + The persisted progress key is always written; this only mutes + the events fan-out a `QueueEvents` subscriber would observe. + **Default engine: `True`.** ### `await worker.run()` @@ -556,12 +599,12 @@ swallowed so a buggy listener cannot crash the worker. | `drained` | `()` | Engine observed a full→empty transition on the main stream. **Cross-process scope.** Lazily wires an embedded `QueueEvents` subscriber on the first `worker.on('drained', ...)` call; torn down on `close()`. | | `paused` | `()` | `pause()` was called. Process-local. | | `resumed` | `()` | `resume()` was called. Process-local. | +| `progress` | `(job: Job, progress: int)` | Handler called [`job.update_progress(n)`](#await-jobupdate_progressn). **Cross-process scope.** Same lazy embedded `QueueEvents` subscriber as `drained` (zero-cost when no listener is attached). The worker re-uses the in-flight `Job` instance so handler-side `job.progress` and the callback observe identical state. Disable the events fan-out (and therefore this event) by passing `Worker(events_progress_enabled=False)`. | Names accepted for parity but currently never fire (engine doesn't emit the underlying transition yet — safe to wire up, will start firing when the corresponding engine work lands): -- `progress` — `(job: Job, progress)`. - `stalled` — `(job_id: str, prev: str)`. ```python @@ -588,12 +631,16 @@ class Job: data: Any attempt: int created_at_ms: int + progress: int | None = None ``` The lightweight value type passed to user handlers and returned -from `Queue.add`. v1 deliberately does not round-trip through -Redis for any field on this object — the engine streams jobs and -does not persist progress, return values, or per-job state. +from `Queue.add`. The engine streams jobs via `XREADGROUP` / +`XACK` and does not persist return values by default (opt in +with `Worker(store_results=True)`). Progress and log lines *are* +persisted to side-channel keys when the handler calls +[`update_progress`](#await-jobupdate_progressn) or +[`log`](#await-joblogline). ### Properties @@ -603,6 +650,7 @@ does not persist progress, return values, or per-job state. - `attempt` — 1-indexed attempt counter on the consumer side; `0` on the producer side. - `created_at_ms` — submission time in epoch ms. - `attempts_made` — alias of `attempt`, matches BullMQ naming. +- `progress` — latest value set via [`update_progress`](#await-jobupdate_progressn), or read back by the introspector when this Job was returned by [`Queue.get_job`](#await-queueget_jobjob_id) / [`Queue.get_jobs`](#await-queueget_jobsstatewaiting-offset0-limit100-cursornone). `None` until a progress value has been recorded. The dataclass is frozen-by-equality on the public fields; an optional internal `_queue` backreference is set when the job is @@ -610,6 +658,51 @@ returned by `Queue.add` so [`wait_for_result`](#await-jobwait_for_resulttimeoutp works without an extra connection. It is excluded from `repr` and `__eq__` to keep the dataclass shape stable. +### `await job.update_progress(n)` + +```python +async def update_progress(self, n: int) -> None +``` + +Persist a `0..=100` progress value for this job under the +engine's per-job progress key (`{chasqui:}:progress:` +STRING, TTL = `result_ttl_secs`), mirror it on the local +`progress` attribute, and (when +`Worker(events_progress_enabled=True)`, the default) emit an +`e=progress` events-stream entry that `QueueEvents` re-fans onto +the broadcast `'progress'` channel and the per-id +`'progress:'` channel. + +Values outside `0..=100` are clamped to `100` at the engine +boundary (no raise; the first clamp per handle logs a single +warn-once). + +**Read-only Job guard.** Raises `RuntimeError` when called on a +Job returned by [`Queue.get_job`](#await-queueget_jobjob_id) / +[`Queue.get_jobs`](#await-queueget_jobsstatewaiting-offset0-limit100-cursornone) +or constructed from [`Queue.add`](#await-queueaddname-data-delay_ms-delay-attempts-backoff-job_id-repeat-missed_fires) — +those instances are synthesized from introspector / +producer-side data and carry no per-handler connection. Only +Jobs handed to a `Worker` processor have a live backref. + +### `await job.log(line)` + +```python +async def log(self, line: str) -> int +``` + +Append `line` to the per-job log stream +(`{chasqui:}:log:` STREAM) and return the new XLEN. +The stream is bounded by `Worker(log_max_stream_len=...)` +(default `1000`) via `MAXLEN ~` and expires alongside the result +key (TTL = `result_ttl_secs`). Oversize lines +(`> log_max_line_bytes`, default `4096`) truncate on a UTF-8 +char boundary with a `[…truncated]` marker appended; first +truncation per handle logs a single warn-once. + +Same read-only Job guard as [`update_progress`](#await-jobupdate_progressn). +Read back via [`Queue.get_job_logs`](#await-queueget_job_logsjob_id-start0-end-1-asctrue). + ### `await job.wait_for_result(*, timeout, poll_interval)` ```python @@ -760,6 +853,7 @@ Event names accepted: | `delayed` | `(payload, event_id)` | Producer enqueued with `delay > 0`. | | `dlq` | `(payload, event_id)` | DLQ relocator wrote the entry to the DLQ stream. | | `retries-exhausted` | `(payload, event_id)` | Synthetic alias of `dlq` (chasquimq-specific). | +| `progress` | `(payload, event_id)` | Handler called [`Job.update_progress(n)`](#await-jobupdate_progressn). `payload['progress']` is the clamped `0..=100` value the engine persisted. | | `drained` | `(event_id,)` | Engine drained (queue-scoped, no `jobId`). | Per-id channels fire alongside the broadcast channel for events @@ -772,6 +866,7 @@ Used internally by | `active:` | `(payload, event_id)` | `active` | | `completed:` | `(payload, event_id)` | `completed` | | `failed:` | `(payload, event_id)` | `failed` | +| `progress:` | `(payload, event_id)` | `progress` | `await wait_until_ready()` blocks until the listener subscriber has issued its first `XREAD BLOCK` (i.e. the subscription window is diff --git a/site/src/content/docs/reference/rust-api.md b/site/src/content/docs/reference/rust-api.md index 2b6e4bc..16cecee 100644 --- a/site/src/content/docs/reference/rust-api.md +++ b/site/src/content/docs/reference/rust-api.md @@ -23,12 +23,12 @@ language shims so cross-references resolve. ## On this page - [Configs](#configs) — `ProducerConfig`, `ConsumerConfig`, `PromoterConfig`, `SchedulerConfig`, `RetryConfig`, `ConnectionTuning`. -- [Job types](#job-types) — `Job`, `JobId`, `JobRetryOverride`, `AddOptions`. +- [Job types](#job-types) — `Job`, `JobId`, `JobRetryOverride`, `AddOptions`, `JobHandle`. - [Producer](#producer) — every method. - [Consumer](#consumer) — constructor and `run`. - [Promoter](#promoter) — standalone delayed-job promoter. - [Scheduler](#scheduler) — standalone repeatable-spec scheduler. -- [Introspector](#introspector) — read-only `get_job` / `get_jobs` / `get_job_state` / `get_job_counts`. +- [Introspector](#introspector) — read-only `get_job` / `get_jobs` / `get_job_state` / `get_job_counts` / `get_job_logs`. - [Repeatable jobs](#repeatable-jobs) — `RepeatPattern`, `MissedFiresPolicy`, `RepeatableSpec`, `RepeatableMeta`. - [Backoff](#backoff) — `BackoffSpec`, `BackoffKind`. - [Errors](#errors) — `Error`, `HandlerError`, `Result`. @@ -241,6 +241,7 @@ pub struct Job { pub attempt: u32, pub retry: Option, pub name: String, + pub handle: Option>, } impl Job { @@ -254,7 +255,11 @@ impl Job { The msgpack-encoded envelope on the wire. `name` is `#[serde(skip)]` on the encode path — the dispatch name travels as a separate `n` field on the stream entry, not inside the msgpack body — and the -read path populates `Job::name` from that field. See +read path populates `Job::name` from that field. `handle` is also +`#[serde(skip)]`: the consumer attaches a [`JobHandle`](#jobhandle) +immediately before each dispatch so user handlers can call +`update_progress` / `log`; jobs decoded outside the dispatch path +(introspector, DLQ peek) leave it `None`. See [wire format](/reference/wire-format/) for the byte layout. ### `JobId` @@ -300,6 +305,44 @@ Per-job options for the `*_with_options` family of producer methods. `name` is capped at 256 bytes; oversize names are rejected with `Error::Config` at the producer boundary. +### `JobHandle` + +```rust +pub struct JobHandle; + +impl JobHandle { + pub fn job_id(&self) -> &str; + pub async fn update_progress(&self, n: u8) -> Result<()>; + pub async fn log(&self, line: &str) -> Result; +} +``` + +Per-handler write surface attached to `Job::handle` (an +`Option`) by the consumer immediately before the user +handler runs. Absent on Jobs returned by the introspector's +read-only paths — call sites should `let Some(handle) = +job.handle.as_ref()` and surface a "this Job has no live handle" +error rather than panicking. + +- `update_progress(n)` writes `{chasqui:}:progress:` + as an ASCII-decimal `u8` STRING with TTL = `result_ttl_secs`. + Values `> 100` clamp to 100 (warn-once per handle). When + `events_progress_enabled` is `true` (default), a best-effort + `e=progress` events-stream entry is emitted after the SET + succeeds — a failed XADD never propagates back to the handler. +- `log(line)` `XADD`s one entry under field `line` to + `{chasqui:}:log:` (STREAM, `MAXLEN ~ + log_max_stream_len`), pipelined with `XLEN` (returned) and + `EXPIRE log_key result_ttl_secs`. Oversize lines + (`> log_max_line_bytes`) truncate on a UTF-8 char boundary + with a `[…truncated]` marker (warn-once per handle). + +Connection budget: the handle borrows a shared 2–8-sized +`fred::clients::Pool` sized to consumer concurrency — never a +client per worker. Handlers that never call these pay nothing. +Read back the progress field via [`JobInfo::progress`](#jobinfo--jobspage) +and the log lines via [`Introspector::get_job_logs`](#introspector). + ## Producer ```rust @@ -623,6 +666,13 @@ impl Introspector { limit: u64, cursor: Option, ) -> Result; + pub async fn get_job_logs( + &self, + id: &str, + start: i64, + end: i64, + asc: bool, + ) -> Result<(Vec, u64)>; } ``` @@ -639,6 +689,17 @@ as `JobState::Waiting`, not `Completed`, during the race window. `Active` state. Defaults to `ConsumerConfig::default().group` (`"default"`). Pass `None` to take the default. +`get_job_logs(id, start, end, asc) -> (Vec, u64)` reads the +captured `line` field values from the per-job log stream +(`{chasqui:}:log:`, populated by +[`JobHandle::log`](#jobhandle)) and the current XLEN. `start` / +`end` are inclusive entry offsets in the order indicated by `asc` +(entry `0` is the oldest when `asc`, the newest when `!asc`). +`start = -N` is interpreted as "this many from the end" (translated +via XLEN, matching BullMQ's `getLogs` convention); `end = -1` means +"to end". A non-existent or never-logged job resolves to +`(Vec::new(), 0)`. + ### `JobState` ```rust @@ -691,6 +752,7 @@ pub struct JobInfo { pub failure_reason: Option, pub failure_detail: Option, pub decode_failed: bool, // set when the entry's envelope didn't decode + pub progress: Option, // latest JobHandle::update_progress value } pub struct JobsPage { diff --git a/site/src/content/docs/reference/wire-format.md b/site/src/content/docs/reference/wire-format.md index 4cf1556..e4364e7 100644 --- a/site/src/content/docs/reference/wire-format.md +++ b/site/src/content/docs/reference/wire-format.md @@ -30,6 +30,8 @@ all keys for a queue land on the same slot. | `{chasqui:}:repeat:spec:` | Hash | Full repeatable spec body, field `spec`. | | `{chasqui:}:events` | Stream | Per-queue event broadcast. | | `{chasqui:}:result:` | String | Stored handler return bytes (TTL). | +| `{chasqui:}:progress:` | String | Latest progress value (ASCII decimal `u8`, 0..=100) written by `Job.updateProgress`. TTL = `result_ttl_secs`. | +| `{chasqui:}:log:` | Stream | Per-job log stream written by `Job.log`. `MAXLEN ~ log_max_stream_len`; `EXPIRE`d to `result_ttl_secs` on every append. One entry per call, field `line`. | | `{chasqui:}:dlid:` | String | Idempotent-schedule dedup marker. | | `{chasqui:}:didx:` | String | Side-index for `cancel_delayed`. | | `{chasqui:}:promoter:lock` | String | Promoter leader-election lock. | @@ -259,7 +261,7 @@ generic Redis client. Fields per event: | Field | Type | When | |---|---|---| -| `e` | string | Event name (`"waiting"`, `"active"`, `"completed"`, `"failed"`, `"retry-scheduled"`, `"delayed"`, `"dlq"`, `"drained"`). | +| `e` | string | Event name (`"waiting"`, `"active"`, `"completed"`, `"failed"`, `"retry-scheduled"`, `"delayed"`, `"dlq"`, `"drained"`, `"progress"`). | | `id` | string | Job id. Absent for queue-scoped events. | | `n` | string | Dispatch name. Absent / empty when no name was set. | | `attempt` | int (decimal string) | Per-attempt events. | @@ -267,6 +269,7 @@ generic Redis client. Fields per event: | `delay_ms` | int | `delayed`. | | `duration_us` | int | `completed`, `failed` — handler wall-clock duration. | | `reason` | string | `failed`, `dlq` — DLQ reason. | +| `progress` | int (decimal string) | `progress` — clamped `0..=100` value the engine persisted. | | `ts` | int | Emit time (epoch ms). | Numeric fields are decimal strings on the wire; the Node and