From 11a5f85ed99c6c987facc3014bbb16766e0e8052 Mon Sep 17 00:00:00 2001 From: Ross Gardler <123456+rgardler@users.noreply.github.com> Date: Tue, 19 May 2026 22:19:30 +0100 Subject: [PATCH 1/6] WL-0MPD4WCZ30036UMO: Fix github push pre-filter race: serialize pushes, improve pre-filter, ensure --id bypass --- src/commands/github.ts | 99 +++++++++++++++---- src/github-pre-filter.ts | 7 ++ .../github-push-id-bypass-prefilter.test.ts | 45 +++++++++ 3 files changed, 131 insertions(+), 20 deletions(-) create mode 100644 tests/cli/github-push-id-bypass-prefilter.test.ts diff --git a/src/commands/github.ts b/src/commands/github.ts index 5d133bca..8fb62565 100644 --- a/src/commands/github.ts +++ b/src/commands/github.ts @@ -4,6 +4,9 @@ import type { PluginContext } from '../plugin-types.js'; import { getRepoFromGitRemote, normalizeGithubLabelPrefix, SecondaryRateLimitError, setVerboseLogger } from '../github.js'; +import { getLockPathForJsonl, withFileLock } from '../file-lock.js'; +import { resolveWorklogDir } from '../worklog-paths.js'; +import path from 'node:path'; import { ProgressReporter, ProgressMode } from '../progress.js'; import throttler from '../github-throttler.js'; import { upsertIssuesFromWorkItems, importIssuesToWorkItems, GithubProgress, GithubSyncResult, SyncedItem, SyncErrorItem, FieldChange } from '../github-sync.js'; @@ -125,26 +128,33 @@ export default function register(ctx: PluginContext): void { }; try { - const githubConfig = resolveGithubConfig({ repo: options.repo, labelPrefix: options.labelPrefix }); - const repoUrl = `https://github.com/${githubConfig.repo}/issues`; - if (!isJsonMode) { - console.log(`Pushing to ${repoUrl}`); - } - const items = db.getAll(); - const comments = db.getAllComments(); + // Acquire a per-repo file lock to serialize github push operations and + // avoid races where concurrent push runs update the last-push timestamp + // out-of-band and cause items to be skipped. Use the JSONL path as the + // lock target so it is repo-scoped and consistent with other file-locks. + const jsonlPath = require('path').join(resolveWorklogDir(), 'worklog-data.jsonl'); + const lockPath = getLockPathForJsonl(jsonlPath); + await withFileLock(lockPath, async () => { + const githubConfig = resolveGithubConfig({ repo: options.repo, labelPrefix: options.labelPrefix }); + const repoUrl = `https://github.com/${githubConfig.repo}/issues`; + if (!isJsonMode) { + console.log(`Pushing to ${repoUrl}`); + } + const items = db.getAll(); + const comments = db.getAllComments(); - let itemsToProcess = items; - let commentsToProcess = comments; - let lastPush: string | null = null; - // Pass DB to timestamp helpers when available so they may use metadata - const dbForMetadata = typeof db.getAll === 'function' && typeof (db as any).store === 'object' ? (db as any).store : undefined; + let itemsToProcess = items; + let commentsToProcess = comments; + let lastPush: string | null = null; + // Pass DB to timestamp helpers when available so they may use metadata + const dbForMetadata = typeof db.getAll === 'function' && typeof (db as any).store === 'object' ? (db as any).store : undefined; - // Eagerly capture writeLastPushTimestamp when the pre-filter module is - // available. It may be resolved during the pre-filter import below or - // via a standalone import before the batch loop. - let _writeLastPushTimestamp: ((ts: string, db?: { setMetadata?: (k: string, v: string) => void }, repo?: string | null) => void) | null = null; + // Eagerly capture writeLastPushTimestamp when the pre-filter module is + // available. It may be resolved during the pre-filter import below or + // via a standalone import before the batch loop. + let _writeLastPushTimestamp: ((ts: string, db?: { setMetadata?: (k: string, v: string) => void }, repo?: string | null) => void) | null = null; - const forceAll = Boolean(options.all) || Boolean(options.force); + const forceAll = Boolean(options.all) || Boolean(options.force); if (options.force && !options.all) { if (!isJsonMode) console.error('Warning: --force is deprecated and will be removed in a future release. Use --all instead.'); logLine('github push: --force is deprecated; use --all instead'); @@ -199,15 +209,48 @@ export default function register(ctx: PluginContext): void { // --id: restrict to a single work item when provided if (options.id) { - const singleItem = itemsToProcess.find(i => i.id === options.id); + // When --id is supplied, bypass the pre-filter and always push the + // specified work item (do not require it to be a candidate in the + // pre-filtered set). This ensures explicit single-item pushes always + // run even if the pre-filter would otherwise exclude the item. + const singleItem = items.find(i => i.id === options.id); if (!singleItem) { - throw new Error(`Work item '${options.id}' not found (or not a candidate for push).`); + throw new Error(`Work item '${options.id}' not found.`); } itemsToProcess = [singleItem]; - commentsToProcess = commentsToProcess.filter(c => c.workItemId === options.id); + commentsToProcess = comments.filter(c => c.workItemId === options.id); logLine(`github push: --id mode; pushing single item ${options.id}`); } + // Defensive: ensure we didn't miss any items that were updated since + // the last push timestamp. In rare race conditions or when the + // pre-filter behaved unexpectedly, an item with updatedAt > lastPush + // might be missing from itemsToProcess. Add any such items now so the + // push run is robust. + if (!forceAll && lastPush) { + try { + const lastMs = new Date(lastPush).getTime(); + if (!Number.isNaN(lastMs)) { + const existingIds = new Set(itemsToProcess.map(i => i.id)); + const additional = items.filter(it => !existingIds.has(it.id)).filter(it => { + const updatedMs = new Date(it.updatedAt).getTime(); + return !Number.isNaN(updatedMs) && updatedMs > lastMs; + }); + if (additional.length > 0) { + // Append additional items preserving the natural order from `items`. + for (const it of items) { + if (additional.find(a => a.id === it.id)) itemsToProcess.push(it); + } + // Add comments for additional items + for (const c of comments) { + if (additional.find(a => a.id === c.workItemId)) commentsToProcess.push(c); + } + logLine(`github push: added ${additional.length} item(s) newer than lastPush`); + } + } + } catch (_) {} + } + // Capture push-start timestamp BEFORE processing begins so that items // modified during the push window are re-processed on the next run. const pushStartTimestamp = new Date().toISOString(); @@ -218,6 +261,13 @@ export default function register(ctx: PluginContext): void { pushTotalItems = itemsToProcess.length; + // Diagnostic: log whether the target item is present in the candidate list + try { + const containsTarget = itemsToProcess.some(i => i.id === 'WL-0MM8SU2R20PTDQ9I'); + logLine(`github push: itemsToProcess=${itemsToProcess.length} containsTarget=${containsTarget}`); + try { console.error(`DEBUG: itemsToProcess=${itemsToProcess.length} containsTarget=${containsTarget}`); } catch (_) {} + } catch (_) {} + // Process items in fixed batches of 10 so progress is persisted after // each batch and a single failure does not require reprocessing everything. const totalBatches = Math.max(Math.ceil(itemsToProcess.length / BATCH_SIZE), 1); @@ -266,6 +316,14 @@ export default function register(ctx: PluginContext): void { currentBatchLength = batchItems.length; logLine(`github push: batch ${batchIndex + 1}/${totalBatches} items=${batchItems.length}`); + // Diagnostic: list batch item ids for debugging why items may be skipped + try { + logLine(`github push: batch ${batchIndex + 1} ids=${batchItems.map(i => i.id).join(',')}`); + } catch (_) {} + try { + // Also print to stderr so interactive runs show diagnostics immediately + console.error(`DEBUG: batch ${batchIndex + 1} ids=${batchItems.map(i => i.id).join(',')}`); + } catch (_) {} let batchResult; try { @@ -512,6 +570,7 @@ export default function register(ctx: PluginContext): void { } } logLine(`--- github push end ${new Date().toISOString()} ---`); + }); } catch (error) { logLine(`GitHub sync failed: ${(error as Error).message}`); output.error(`GitHub sync failed: ${(error as Error).message}`, { success: false, error: (error as Error).message }); diff --git a/src/github-pre-filter.ts b/src/github-pre-filter.ts index e17a92f0..62be5a8b 100644 --- a/src/github-pre-filter.ts +++ b/src/github-pre-filter.ts @@ -171,6 +171,13 @@ export function filterItemsForPush(items: WorkItem[], comments: Comment[], lastP if (item.githubIssueNumber == null) return true; const updatedMs = new Date(item.updatedAt).getTime(); if (Number.isNaN(updatedMs)) return true; // treat unknown updatedAt as changed + // If local mapping to GitHub exists, prefer local changes (updatedAt > githubIssueUpdatedAt) + const ghUpdatedAt = (item as any).githubIssueUpdatedAt; + const ghUpdatedMs = ghUpdatedAt ? new Date(ghUpdatedAt).getTime() : NaN; + if (!Number.isNaN(ghUpdatedMs) && updatedMs > ghUpdatedMs) { + return true; + } + // Otherwise fall back to comparing against the last-push timestamp return updatedMs > lastMs; }); diff --git a/tests/cli/github-push-id-bypass-prefilter.test.ts b/tests/cli/github-push-id-bypass-prefilter.test.ts new file mode 100644 index 00000000..ffb22783 --- /dev/null +++ b/tests/cli/github-push-id-bypass-prefilter.test.ts @@ -0,0 +1,45 @@ +import { describe, it, expect } from 'vitest'; +import * as fs from 'fs'; +import * as path from 'path'; +import { enterTempDir, leaveTempDir, writeConfig, writeInitSemaphore, seedWorkItems, execAsync, cliPath } from './cli-helpers.js'; + +const FAR_FUTURE_TIMESTAMP = '2999-01-01T00:00:00.000Z'; + +describe('github push --id bypasses pre-filter', () => { + it('--id pushes an item even when last-push timestamp would exclude it', async () => { + const state = enterTempDir(); + try { + writeConfig(state.tempDir); + writeInitSemaphore(state.tempDir); + // Seed a single item that would normally be skipped by pre-filter if + // last-push is set to a far-future timestamp. + seedWorkItems(state.tempDir, [ + { + id: 'WL-ALPHA', + title: 'Alpha item', + status: 'open' as any, + priority: 'medium' as any, + githubIssueNumber: 1001, + githubIssueId: 5001, + // updatedAt in the past + updatedAt: '2025-01-01T00:00:00.000Z', + }, + ]); + + // Write a last-push timestamp far in the future so pre-filter would + // normally exclude any real items from processing. + const timestampPath = path.join(state.tempDir, '.worklog', 'github-last-push'); + fs.writeFileSync(timestampPath, `${FAR_FUTURE_TIMESTAMP}\n`, 'utf8'); + + // Single-item push should still succeed (bypass pre-filter) + const { stdout } = await execAsync( + `tsx ${cliPath} github push --repo owner/name --id WL-ALPHA`, + { cwd: state.tempDir } + ); + + expect(stdout).toContain('GitHub sync complete'); + } finally { + leaveTempDir(state); + } + }); +}); From 02bcdb19d9c8600d42b6f7c9839ad1f3c2f7c6f1 Mon Sep 17 00:00:00 2001 From: Ross Gardler <123456+rgardler@users.noreply.github.com> Date: Tue, 19 May 2026 22:32:39 +0100 Subject: [PATCH 2/6] WL-0MPD4WCZ30036UMO: Fix ESM require usage in github push (use path.join) --- src/commands/github.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/commands/github.ts b/src/commands/github.ts index 8fb62565..9465eeb5 100644 --- a/src/commands/github.ts +++ b/src/commands/github.ts @@ -132,7 +132,7 @@ export default function register(ctx: PluginContext): void { // avoid races where concurrent push runs update the last-push timestamp // out-of-band and cause items to be skipped. Use the JSONL path as the // lock target so it is repo-scoped and consistent with other file-locks. - const jsonlPath = require('path').join(resolveWorklogDir(), 'worklog-data.jsonl'); + const jsonlPath = path.join(resolveWorklogDir(), 'worklog-data.jsonl'); const lockPath = getLockPathForJsonl(jsonlPath); await withFileLock(lockPath, async () => { const githubConfig = resolveGithubConfig({ repo: options.repo, labelPrefix: options.labelPrefix }); From a49cc1d76c5c7708b0ac86ccd4b0dfd9c50da6e4 Mon Sep 17 00:00:00 2001 From: Ross Gardler <123456+rgardler@users.noreply.github.com> Date: Tue, 19 May 2026 22:50:37 +0100 Subject: [PATCH 3/6] WL-0MPD4WCZ30036UMO: Restrict --id push to one item and tighten pre-filter --- src/commands/github.ts | 12 +---- src/github-pre-filter.ts | 9 +--- tests/cli/github-push-batching.test.ts | 49 +++++++++++++++++++ .../github-push-id-bypass-prefilter.test.ts | 2 + tests/github-pre-filter.test.ts | 9 ++++ 5 files changed, 63 insertions(+), 18 deletions(-) diff --git a/src/commands/github.ts b/src/commands/github.ts index 9465eeb5..7ce4f794 100644 --- a/src/commands/github.ts +++ b/src/commands/github.ts @@ -227,7 +227,7 @@ export default function register(ctx: PluginContext): void { // pre-filter behaved unexpectedly, an item with updatedAt > lastPush // might be missing from itemsToProcess. Add any such items now so the // push run is robust. - if (!forceAll && lastPush) { + if (!forceAll && !options.id && lastPush) { try { const lastMs = new Date(lastPush).getTime(); if (!Number.isNaN(lastMs)) { @@ -261,12 +261,6 @@ export default function register(ctx: PluginContext): void { pushTotalItems = itemsToProcess.length; - // Diagnostic: log whether the target item is present in the candidate list - try { - const containsTarget = itemsToProcess.some(i => i.id === 'WL-0MM8SU2R20PTDQ9I'); - logLine(`github push: itemsToProcess=${itemsToProcess.length} containsTarget=${containsTarget}`); - try { console.error(`DEBUG: itemsToProcess=${itemsToProcess.length} containsTarget=${containsTarget}`); } catch (_) {} - } catch (_) {} // Process items in fixed batches of 10 so progress is persisted after // each batch and a single failure does not require reprocessing everything. @@ -320,10 +314,6 @@ export default function register(ctx: PluginContext): void { try { logLine(`github push: batch ${batchIndex + 1} ids=${batchItems.map(i => i.id).join(',')}`); } catch (_) {} - try { - // Also print to stderr so interactive runs show diagnostics immediately - console.error(`DEBUG: batch ${batchIndex + 1} ids=${batchItems.map(i => i.id).join(',')}`); - } catch (_) {} let batchResult; try { diff --git a/src/github-pre-filter.ts b/src/github-pre-filter.ts index 62be5a8b..409595b5 100644 --- a/src/github-pre-filter.ts +++ b/src/github-pre-filter.ts @@ -171,13 +171,8 @@ export function filterItemsForPush(items: WorkItem[], comments: Comment[], lastP if (item.githubIssueNumber == null) return true; const updatedMs = new Date(item.updatedAt).getTime(); if (Number.isNaN(updatedMs)) return true; // treat unknown updatedAt as changed - // If local mapping to GitHub exists, prefer local changes (updatedAt > githubIssueUpdatedAt) - const ghUpdatedAt = (item as any).githubIssueUpdatedAt; - const ghUpdatedMs = ghUpdatedAt ? new Date(ghUpdatedAt).getTime() : NaN; - if (!Number.isNaN(ghUpdatedMs) && updatedMs > ghUpdatedMs) { - return true; - } - // Otherwise fall back to comparing against the last-push timestamp + // Compare against the last-push timestamp. + // (Explicit --id pushes bypass this filter.) return updatedMs > lastMs; }); diff --git a/tests/cli/github-push-batching.test.ts b/tests/cli/github-push-batching.test.ts index 57d58528..e081e60a 100644 --- a/tests/cli/github-push-batching.test.ts +++ b/tests/cli/github-push-batching.test.ts @@ -100,6 +100,55 @@ describe('github push --id flag', () => { } }); + it('--id only processes the requested item even when last-push is old', async () => { + const state = enterTempDir(); + try { + writeConfig(state.tempDir); + writeInitSemaphore(state.tempDir); + seedWorkItems(state.tempDir, [ + { + id: 'WL-ALPHA', + title: 'Alpha item', + status: 'open' as any, + priority: 'medium' as any, + githubIssueNumber: 1001, + githubIssueId: 5001, + githubIssueUpdatedAt: FAR_FUTURE_TIMESTAMP, + }, + { + id: 'WL-BETA', + title: 'Beta item', + status: 'open' as any, + priority: 'medium' as any, + githubIssueNumber: 1002, + githubIssueId: 5002, + githubIssueUpdatedAt: FAR_FUTURE_TIMESTAMP, + }, + ]); + + // Make timestamp valid and old so non---id filtering would include both items. + const timestampPath = path.join(state.tempDir, '.worklog', 'github-last-push'); + fs.writeFileSync(timestampPath, '2025-01-01T00:00:00.000Z\n', 'utf8'); + + await execAsync( + `tsx ${cliPath} github push --repo owner/name --id WL-ALPHA`, + { cwd: state.tempDir } + ); + + const logPath = path.join(state.tempDir, '.worklog', 'logs', 'github_sync.log'); + const logContent = fs.readFileSync(logPath, 'utf8'); + const lastBatchIdsLine = logContent + .split('\n') + .filter(line => line.includes('github push: batch 1 ids=')) + .pop() || ''; + + expect(lastBatchIdsLine).toContain('WL-ALPHA'); + expect(lastBatchIdsLine).not.toContain('WL-BETA'); + } finally { + leaveTempDir(state); + } + }); + it('--id writes timestamp when --no-update-timestamp is not set', async () => { const state = enterTempDir(); try { diff --git a/tests/cli/github-push-id-bypass-prefilter.test.ts b/tests/cli/github-push-id-bypass-prefilter.test.ts index ffb22783..af131c60 100644 --- a/tests/cli/github-push-id-bypass-prefilter.test.ts +++ b/tests/cli/github-push-id-bypass-prefilter.test.ts @@ -23,6 +23,8 @@ describe('github push --id bypasses pre-filter', () => { githubIssueId: 5001, // updatedAt in the past updatedAt: '2025-01-01T00:00:00.000Z', + // avoid external GH calls in this test path + githubIssueUpdatedAt: FAR_FUTURE_TIMESTAMP, }, ]); diff --git a/tests/github-pre-filter.test.ts b/tests/github-pre-filter.test.ts index 98ab586c..27d9d059 100644 --- a/tests/github-pre-filter.test.ts +++ b/tests/github-pre-filter.test.ts @@ -130,6 +130,15 @@ describe('github pre-filter', () => { expect(res.skippedCount).toBe(1); }); + it('does not include items older than lastPush just because githubIssueUpdatedAt is older', () => { + const older = new Date('2025-01-01T12:00:00.000Z').toISOString(); + const item = makeItem('A', older, 5); + item.githubIssueUpdatedAt = new Date('2025-01-01T00:00:00.000Z').toISOString(); + const res = filterItemsForPush([item], [], lastPush); + expect(res.filteredItems.length).toBe(0); + expect(res.skippedCount).toBe(1); + }); + it('treats items with invalid updatedAt as changed (included)', () => { const items = [makeItem('A', 'not-a-date', 1)]; const res = filterItemsForPush(items, [], lastPush); From 883db4e582f6e3764d0baa0bb262695392d374f7 Mon Sep 17 00:00:00 2001 From: Ross Gardler <123456+rgardler@users.noreply.github.com> Date: Tue, 19 May 2026 23:09:30 +0100 Subject: [PATCH 4/6] WL-0MPD4WCZ30036UMO: Fix throttler nested-schedule deadlock in github push --- src/github-throttler.ts | 15 ++++++++++++++- test/throttler.test.ts | 17 +++++++++++++++++ 2 files changed, 31 insertions(+), 1 deletion(-) diff --git a/src/github-throttler.ts b/src/github-throttler.ts index 172c8be1..7aeadeb9 100644 --- a/src/github-throttler.ts +++ b/src/github-throttler.ts @@ -9,6 +9,8 @@ * The clock is injectable to allow deterministic unit tests. */ +import { AsyncLocalStorage } from 'node:async_hooks'; + export type Clock = { now(): number }; export type ThrottlerOptions = { @@ -42,6 +44,10 @@ export class TokenBucketThrottler { private retryCount = 0; private errorCount = 0; + // Marks execution that already runs inside this throttler so nested + // schedule() calls can run inline without deadlocking on concurrency. + private readonly taskContext = new AsyncLocalStorage(); + // Expose simple stats without blocking the throttler operation getStats() { return { @@ -103,6 +109,13 @@ export class TokenBucketThrottler { } schedule(fn: () => Promise | T): Promise { + // Reentrant path: if we are already inside a scheduled task for this + // throttler instance, execute inline to avoid self-deadlock when the + // outer task has consumed available concurrency slots. + if (this.taskContext.getStore()) { + return Promise.resolve().then(fn); + } + return new Promise((resolve, reject) => { const task: Task = { fn, resolve, reject } as Task; this.queue.push(task as Task); @@ -162,7 +175,7 @@ export class TokenBucketThrottler { // Execute task Promise.resolve() - .then(() => task.fn()) + .then(() => this.taskContext.run(true, () => task.fn())) .then((res) => { this.active -= 1; (task.resolve as (v: unknown) => void)(res); diff --git a/test/throttler.test.ts b/test/throttler.test.ts index 5b8ca11d..136acda6 100644 --- a/test/throttler.test.ts +++ b/test/throttler.test.ts @@ -63,4 +63,21 @@ describe('TokenBucketThrottler - concurrency cap', () => { expect(running).toBeLessThanOrEqual(1); await Promise.all(tasks); }); + + it('allows nested schedule calls without deadlocking', async () => { + const clock = new FakeClock(); + const t = new TokenBucketThrottler({ rate: 10, burst: 10, concurrency: 2, clock }); + + const resultPromise = Promise.all([ + t.schedule(async () => await t.schedule(async () => 'inner-a')), + t.schedule(async () => await t.schedule(async () => 'inner-b')), + ]); + + const timeoutPromise = new Promise((_resolve, reject) => { + setTimeout(() => reject(new Error('nested schedule timed out')), 500); + }); + + const values = await Promise.race([resultPromise, timeoutPromise]); + expect(values.sort()).toEqual(['inner-a', 'inner-b']); + }); }); From a24158c9101033293ab6127f4d680112050b1d01 Mon Sep 17 00:00:00 2001 From: Ross Gardler <123456+rgardler@users.noreply.github.com> Date: Tue, 19 May 2026 23:33:10 +0100 Subject: [PATCH 5/6] WL-0MPD4WCZ30036UMO: Make github push progress clearer and completion-based --- src/commands/github.ts | 7 +- src/github-sync.ts | 106 ++++++++++++------------- src/progress.ts | 8 +- tests/github-sync-progress.test.ts | 120 +++++++++++++++++++++++++++++ tests/unit/progress.test.ts | 16 ++++ 5 files changed, 202 insertions(+), 55 deletions(-) create mode 100644 tests/github-sync-progress.test.ts diff --git a/src/commands/github.ts b/src/commands/github.ts index 7ce4f794..7439ec0b 100644 --- a/src/commands/github.ts +++ b/src/commands/github.ts @@ -91,7 +91,10 @@ export default function register(ctx: PluginContext): void { }; const progressMode = (options as any).progress as ProgressMode | undefined; - const progressReporter = new ProgressReporter({ mode: progressMode ?? (isJsonMode ? 'json' : undefined) }); + const progressReporter = new ProgressReporter({ + mode: progressMode ?? (isJsonMode ? 'json' : undefined), + rateMs: 250, + }); const renderProgress = (progress: GithubProgress) => { if (progress.phase === 'push') { const totalItems = Math.max(pushTotalItems, 0); @@ -105,7 +108,7 @@ export default function register(ctx: PluginContext): void { ? currentBatchLength : Math.min(Math.max(totalItems - batchIdx * BATCH_SIZE, 0), BATCH_SIZE); const itemNumberInBatch = Math.min(Math.max(progress.current, 1), batchItemCount || BATCH_SIZE); - message = `Push: Batch ${batchIdx + 1}/${totalBatches} Item ${itemNumberInBatch}/${batchItemCount || BATCH_SIZE}`; + message = `Push: Batch ${batchIdx + 1}/${totalBatches} Completed ${itemNumberInBatch}/${batchItemCount || BATCH_SIZE}`; } // Append throttler stats to push message for diagnostic visibility try { diff --git a/src/github-sync.ts b/src/github-sync.ts index 59bcccb0..de7e4dcd 100644 --- a/src/github-sync.ts +++ b/src/github-sync.ts @@ -157,7 +157,7 @@ export async function upsertIssuesFromWorkItems( const updatedItems: WorkItem[] = [...items]; const result: GithubSyncResult = { updated: 0, created: 0, closed: 0, skipped: 0, errors: [], syncedItems: [], errorItems: [] }; const updatedById = new Map(); - let processed = 0; + let completed = 0; let skippedUpdates = 0; const sortCommentsByCreatedAt = (left: Comment, right: Comment) => { @@ -253,51 +253,48 @@ export async function upsertIssuesFromWorkItems( title.length <= maxLen ? title : title.slice(0, maxLen - 1) + '\u2026'; async function upsertMapper(item: WorkItem, idx: number) { - if (onProgress) { - emitProgress('push', idx + 1, items.length); - } - // Guard: skip deleted items that have no GitHub issue (prevent accidental creation) - if (item.status === 'deleted' && !item.githubIssueNumber) { - if (onVerboseLog) { - onVerboseLog(`[upsert] skip deleted item ${item.id} (no githubIssueNumber)`); + try { + // Guard: skip deleted items that have no GitHub issue (prevent accidental creation) + if (item.status === 'deleted' && !item.githubIssueNumber) { + if (onVerboseLog) { + onVerboseLog(`[upsert] skip deleted item ${item.id} (no githubIssueNumber)`); + } + skippedUpdates += 1; + return; } - skippedUpdates += 1; - return; - } - const itemComments = byItemId.get(item.id) || []; - const shouldSyncComments = commentNeedsSync(item, itemComments); - increment('items.processed'); - if ( - item.githubIssueNumber && - item.githubIssueUpdatedAt && - new Date(item.updatedAt).getTime() <= new Date(item.githubIssueUpdatedAt).getTime() && - !shouldSyncComments - ) { - if (onVerboseLog) { - onVerboseLog(`[upsert] skip ${item.id} (no issue or comment changes)`); + const itemComments = byItemId.get(item.id) || []; + const shouldSyncComments = commentNeedsSync(item, itemComments); + increment('items.processed'); + if ( + item.githubIssueNumber && + item.githubIssueUpdatedAt && + new Date(item.updatedAt).getTime() <= new Date(item.githubIssueUpdatedAt).getTime() && + !shouldSyncComments + ) { + if (onVerboseLog) { + onVerboseLog(`[upsert] skip ${item.id} (no issue or comment changes)`); + } + skippedUpdates += 1; + return; } - skippedUpdates += 1; - return; - } - const payload = workItemToIssuePayload(item, itemComments, labelPrefix, items); + const payload = workItemToIssuePayload(item, itemComments, labelPrefix, items); - try { let issue: GithubIssueRecord | null = null; let issueNumber = item.githubIssueNumber; let issueUpdatedAt = item.githubIssueUpdatedAt || null; const shouldUpdateIssue = !item.githubIssueNumber || !item.githubIssueUpdatedAt || new Date(item.updatedAt).getTime() > new Date(item.githubIssueUpdatedAt).getTime(); - if (shouldUpdateIssue) { + if (shouldUpdateIssue) { const upsertStart = Date.now(); if (onVerboseLog) { onVerboseLog(`[upsert] ${item.githubIssueNumber ? 'update' : 'create'} ${item.id}`); } - if (item.githubIssueNumber) { - increment('api.issue.update'); - // updateGithubIssueAsync already schedules via the central throttler - // internally (see src/github.ts). Avoid double-scheduling here. - issue = await updateGithubIssueAsync(config, item.githubIssueNumber!, payload); + if (item.githubIssueNumber) { + increment('api.issue.update'); + // updateGithubIssueAsync already schedules via the central throttler + // internally (see src/github.ts). Avoid double-scheduling here. + issue = await updateGithubIssueAsync(config, item.githubIssueNumber!, payload); if (item.status === 'deleted') { result.closed += 1; result.syncedItems.push({ @@ -315,14 +312,14 @@ export async function upsertIssuesFromWorkItems( issueNumber: item.githubIssueNumber, }); } - } else { - increment('api.issue.create'); - // createGithubIssueAsync schedules via the central throttler itself. - issue = await createGithubIssueAsync(config, { - title: payload.title, - body: payload.body, - labels: payload.labels, - }); + } else { + increment('api.issue.create'); + // createGithubIssueAsync schedules via the central throttler itself. + issue = await createGithubIssueAsync(config, { + title: payload.title, + body: payload.body, + labels: payload.labels, + }); result.created += 1; result.syncedItems.push({ action: 'created', @@ -350,17 +347,17 @@ export async function upsertIssuesFromWorkItems( const shouldSyncCommentsNow = itemComments.length > 0 && (shouldSyncComments || shouldUpdateIssue); if (shouldSyncCommentsNow && issueNumber) { - const commentListStart = Date.now(); - increment('api.comment.list'); - // listGithubIssueCommentsAsync now schedules internally via the throttler - // (see src/github.ts). Call it directly to avoid double-scheduling. - const existingComments = await listGithubIssueCommentsAsync(config, issueNumber!); - timing.commentListMs += Date.now() - commentListStart; - const commentUpsertStart = Date.now(); - const commentSummary = await upsertGithubIssueCommentsAsync(config, issueNumber, itemComments, existingComments); - timing.commentUpsertMs += Date.now() - commentUpsertStart; - // small yield after comment work - if (idx % 5 === 0) await new Promise((res) => setImmediate(res)); + const commentListStart = Date.now(); + increment('api.comment.list'); + // listGithubIssueCommentsAsync now schedules internally via the throttler + // (see src/github.ts). Call it directly to avoid double-scheduling. + const existingComments = await listGithubIssueCommentsAsync(config, issueNumber!); + timing.commentListMs += Date.now() - commentListStart; + const commentUpsertStart = Date.now(); + const commentSummary = await upsertGithubIssueCommentsAsync(config, issueNumber, itemComments, existingComments); + timing.commentUpsertMs += Date.now() - commentUpsertStart; + // small yield after comment work + if (idx % 5 === 0) await new Promise((res) => setImmediate(res)); increment('api.comment.create', commentSummary.created || 0); increment('api.comment.update', commentSummary.updated || 0); result.commentsCreated = (result.commentsCreated || 0) + commentSummary.created; @@ -384,6 +381,11 @@ export async function upsertIssuesFromWorkItems( error: (error as Error).message, }); updatedById.set(item.id, item); + } finally { + completed += 1; + if (onProgress) { + emitProgress('push', completed, items.length); + } } } diff --git a/src/progress.ts b/src/progress.ts index cae45c59..2520d93a 100644 --- a/src/progress.ts +++ b/src/progress.ts @@ -65,7 +65,13 @@ export class ProgressReporter { const label = this.labelFor(ev.phase); const pct = ev.total > 0 ? Math.round((ev.current / ev.total) * 100) : 0; const base = `${label}: ${ev.current}/${ev.total}`; - if (ev.note) return `${base} (${ev.note})`; + if (ev.note) { + const trimmed = ev.note.trimStart(); + if (trimmed.startsWith(`${label}:`)) { + return trimmed; + } + return `${base} (${ev.note})`; + } return `${base} ${pct}%`; } diff --git a/tests/github-sync-progress.test.ts b/tests/github-sync-progress.test.ts new file mode 100644 index 00000000..7b429413 --- /dev/null +++ b/tests/github-sync-progress.test.ts @@ -0,0 +1,120 @@ +import { describe, it, expect, vi, beforeEach } from 'vitest'; +import type { WorkItem } from '../src/types.js'; + +vi.mock('../src/github.js', () => ({ + normalizeGithubLabelPrefix: (p?: string) => p || 'wl:', + workItemToIssuePayload: (item: any) => ({ + title: item.title, + body: '', + labels: [], + state: item.status === 'completed' || item.status === 'deleted' ? 'closed' : 'open', + }), + updateGithubIssueAsync: vi.fn(async (_config: any, issueNumber: number) => { + const delayMs = issueNumber === 1 ? 80 : 40; + await new Promise(resolve => setTimeout(resolve, delayMs)); + return { + number: issueNumber, + id: `ID_${issueNumber}`, + title: `Issue ${issueNumber}`, + body: '', + state: 'open', + labels: [], + updatedAt: new Date().toISOString(), + }; + }), + createGithubIssueAsync: vi.fn(), + getGithubIssueAsync: vi.fn(), + listGithubIssues: vi.fn(() => []), + getGithubIssue: vi.fn(), + listGithubIssueComments: vi.fn(() => []), + listGithubIssueCommentsAsync: vi.fn(async () => []), + createGithubIssueComment: vi.fn(), + createGithubIssueCommentAsync: vi.fn(), + updateGithubIssueComment: vi.fn(), + updateGithubIssueCommentAsync: vi.fn(), + stripWorklogMarkers: vi.fn((s: string) => s), + extractWorklogId: vi.fn(), + extractWorklogCommentId: vi.fn(), + extractParentId: vi.fn(), + extractParentIssueNumber: vi.fn(), + extractChildIds: vi.fn(), + extractChildIssueNumbers: vi.fn(), + getIssueHierarchy: vi.fn(() => ({ parentIssueNumber: null, childIssueNumbers: [] })), + getIssueHierarchyAsync: vi.fn(async () => ({ parentIssueNumber: null, childIssueNumbers: [] })), + addSubIssueLink: vi.fn(), + addSubIssueLinkResult: vi.fn(() => ({ ok: true })), + addSubIssueLinkResultAsync: vi.fn(async () => ({ ok: true })), + buildWorklogCommentMarker: vi.fn(() => ''), + createGithubIssue: vi.fn(), + updateGithubIssue: vi.fn(), + issueToWorkItemFields: vi.fn(), +})); + +vi.mock('../src/github-metrics.js', () => ({ + increment: vi.fn(), + snapshot: vi.fn(() => ({})), + diff: vi.fn(() => ({})), +})); + +import { upsertIssuesFromWorkItems } from '../src/github-sync.js'; + +const baseTime = new Date('2025-01-01T00:00:00.000Z').toISOString(); + +function makeItem(id: string, issueNumber: number): WorkItem { + return { + id, + title: id, + description: '', + status: 'open', + priority: 'medium', + sortIndex: 0, + parentId: null, + createdAt: baseTime, + updatedAt: new Date('2025-01-02T00:00:00.000Z').toISOString(), + tags: [], + assignee: '', + stage: '', + issueType: '', + createdBy: '', + deletedBy: '', + deleteReason: '', + risk: '', + effort: '', + githubIssueNumber: issueNumber, + githubIssueId: issueNumber, + githubIssueUpdatedAt: baseTime, + }; +} + +describe('github-sync push progress timing', () => { + beforeEach(() => { + vi.clearAllMocks(); + }); + + it('emits push progress as items complete (not immediately on task start)', async () => { + const items = [makeItem('WL-A', 1), makeItem('WL-B', 2)]; + const start = Date.now(); + const pushEvents: Array<{ current: number; total: number; elapsedMs: number }> = []; + + await upsertIssuesFromWorkItems( + items, + [], + { owner: 'test', repo: 'owner/name', token: 't' } as any, + (ev) => { + if (ev.phase === 'push') { + pushEvents.push({ + current: ev.current, + total: ev.total, + elapsedMs: Date.now() - start, + }); + } + }, + ); + + expect(pushEvents.length).toBeGreaterThanOrEqual(2); + expect(pushEvents[0].elapsedMs).toBeGreaterThanOrEqual(30); + const last = pushEvents[pushEvents.length - 1]; + expect(last.current).toBe(2); + expect(last.total).toBe(2); + }); +}); diff --git a/tests/unit/progress.test.ts b/tests/unit/progress.test.ts index 23c0a15e..9d968a4e 100644 --- a/tests/unit/progress.test.ts +++ b/tests/unit/progress.test.ts @@ -94,4 +94,20 @@ describe('ProgressReporter', () => { const secondRenderWrite = writes[1] ?? ''; expect(secondRenderWrite.length).toBeGreaterThanOrEqual(firstRenderWrite.length); }); + + it('uses note as-is when note already includes the phase label', () => { + let out = ''; + const outStream = { write: (s: string) => { out += s; }, isTTY: true } as any; + const rep = new ProgressReporter({ mode: 'human', rateMs: 1000, outStream }); + + rep.render({ + phase: 'push', + current: 1, + total: 10, + note: 'Push: Batch 1/2 Completed 1/10 (queue=0 active=0 retries=0 errors=0)', + }); + + expect(out).toContain('Push: Batch 1/2 Completed 1/10'); + expect(out).not.toContain('Push: 1/10 (Push:'); + }); }); From 50d2ff6b344267b232aded46baaeecba5dc8fa3b Mon Sep 17 00:00:00 2001 From: Ross Gardler <123456+rgardler@users.noreply.github.com> Date: Tue, 19 May 2026 23:44:10 +0100 Subject: [PATCH 6/6] WL-0MPD4WCZ30036UMO: Fix misleading prefilter count for github push --id --- src/commands/github.ts | 7 +++++-- tests/cli/github-push-id-bypass-prefilter.test.ts | 14 +++++++++++++- 2 files changed, 18 insertions(+), 3 deletions(-) diff --git a/src/commands/github.ts b/src/commands/github.ts index 7439ec0b..2673d6e5 100644 --- a/src/commands/github.ts +++ b/src/commands/github.ts @@ -168,7 +168,7 @@ export default function register(ctx: PluginContext): void { let preFilterDeletedWithoutIssueCount = 0; if (forceAll) { // Bypass pre-filter when --all (or deprecated --force) specified - if (!isJsonMode) console.log(`Full push (--all): processing all ${items.length} items`); + if (!isJsonMode && !options.id) console.log(`Full push (--all): processing all ${items.length} items`); logLine('github push: --all mode enabled - processing all items'); // Still need the timestamp writer even in --all mode; resolve it here. if (!_writeLastPushTimestamp) { @@ -192,7 +192,7 @@ export default function register(ctx: PluginContext): void { commentsToProcess = filteredComments; preFilterSkippedCount = skippedCount; preFilterDeletedWithoutIssueCount = deletedWithoutIssueCount; - if (!isJsonMode) { + if (!isJsonMode && !options.id) { const parts: string[] = []; if (skippedCount > 0) parts.push(`${skippedCount} unchanged since last push`); if (deletedWithoutIssueCount > 0) parts.push(`${deletedWithoutIssueCount} deleted without issue number`); @@ -222,6 +222,9 @@ export default function register(ctx: PluginContext): void { } itemsToProcess = [singleItem]; commentsToProcess = comments.filter(c => c.workItemId === options.id); + if (!isJsonMode) { + console.log(`Processing 1 of ${items.length} items (--id ${options.id})`); + } logLine(`github push: --id mode; pushing single item ${options.id}`); } diff --git a/tests/cli/github-push-id-bypass-prefilter.test.ts b/tests/cli/github-push-id-bypass-prefilter.test.ts index af131c60..7f2dbb2d 100644 --- a/tests/cli/github-push-id-bypass-prefilter.test.ts +++ b/tests/cli/github-push-id-bypass-prefilter.test.ts @@ -11,7 +11,7 @@ describe('github push --id bypasses pre-filter', () => { try { writeConfig(state.tempDir); writeInitSemaphore(state.tempDir); - // Seed a single item that would normally be skipped by pre-filter if + // Seed items that would normally be skipped by pre-filter if // last-push is set to a far-future timestamp. seedWorkItems(state.tempDir, [ { @@ -26,6 +26,16 @@ describe('github push --id bypasses pre-filter', () => { // avoid external GH calls in this test path githubIssueUpdatedAt: FAR_FUTURE_TIMESTAMP, }, + { + id: 'WL-BETA', + title: 'Beta item', + status: 'open' as any, + priority: 'medium' as any, + githubIssueNumber: 1002, + githubIssueId: 5002, + updatedAt: '2025-01-01T00:00:00.000Z', + githubIssueUpdatedAt: FAR_FUTURE_TIMESTAMP, + }, ]); // Write a last-push timestamp far in the future so pre-filter would @@ -39,6 +49,8 @@ describe('github push --id bypasses pre-filter', () => { { cwd: state.tempDir } ); + expect(stdout).toContain('Processing 1 of 2 items (--id WL-ALPHA)'); + expect(stdout).not.toContain('Processing 0 of 2 items'); expect(stdout).toContain('GitHub sync complete'); } finally { leaveTempDir(state);