diff --git a/.prettierignore b/.prettierignore index 009af54..9d33e7c 100644 --- a/.prettierignore +++ b/.prettierignore @@ -1,2 +1,6 @@ dist coverage + +# Generated by the release workflow, which doesn't run prettier over its own +# output — formatting it by hand only lasts until the next release. +CHANGELOG.md diff --git a/README.md b/README.md index 026a825..9e44d0b 100644 --- a/README.md +++ b/README.md @@ -111,10 +111,18 @@ Every failed round logs which fields went wrong, so you can fix the schema (or the scraper) without digging through the returned `droppedItems`: ``` -pushDataWithSchemaRepair: schema validation failed on attempt 1: 12 invalid item(s); repaired fields: /age (type integer), /name (required), /tags/[] (type string); dropped 2 item(s) on unfixable fields: /email (format); retrying with 10 item(s). -pushDataWithSchemaRepair: gave up after 5 attempts; dropped 3 item(s) still failing on fields: /sku (pattern); pushing the 9 valid item(s) left. +WARN pushDataWithSchemaRepair: schema validation failed on attempt 1: 12 invalid item(s); repaired fields: /age (type integer), /name (required), /tags/[] (type string); dropped 2 item(s) on unfixable fields: /email (format); retrying with 10 item(s). +WARN pushDataWithSchemaRepair: gave up after 5 attempts; dropped 3 item(s) still failing on fields: /sku (pattern); pushing the 9 valid item(s) left. ``` +Lines go through [`@apify/log`](https://www.npmjs.com/package/@apify/log) (a +required peer dependency) at **`WARNING`** level — every one of them means a +push was rejected and items were altered or lost, which is never routine. The +wrapper uses a `log.child({ prefix: 'pushDataWithSchemaRepair' })`, so the lines +inherit whatever level, format and prefix the Actor configured: set +`APIFY_LOG_LEVEL=ERROR` to silence them, or `log.setOptions({ logger: new +LoggerJson() })` to get them as JSON. + The field list is a **set**, not a per-item breakdown — one bad field usually shows up on many items in a batch, and knowing which item had which problem rarely changes what you do about it. Array indices collapse diff --git a/src/pushDataWithSchemaRepair.ts b/src/pushDataWithSchemaRepair.ts index 0584504..d1aff82 100644 --- a/src/pushDataWithSchemaRepair.ts +++ b/src/pushDataWithSchemaRepair.ts @@ -9,6 +9,14 @@ // loop, but requires heavier code (locating + loading the schema, resolving // $refs, walking the schema tree). Something to consider in the future. +import baseLog from '@apify/log'; + +// A child of the Actor's own logger, so these lines inherit its level and +// format and carry the `pushDataWithSchemaRepair` prefix without every message +// spelling it out. Everything here logs at WARNING: each line means the push +// was rejected and items were altered or lost, which is never routine. +const log = baseLog.child({ prefix: 'pushDataWithSchemaRepair' }); + const SCHEMA_ERROR_TYPE = 'schema-validation-error'; // Cap on how many distinct field issues we spell out in one log line. A @@ -196,9 +204,7 @@ async function cleanAndRetry( // position outside the batch we actually sent) instead of // crashing on `working[i]` being undefined. if (i < 0 || i >= working.length) { - console.log( - `pushDataWithSchemaRepair: ignoring out-of-range itemPosition ${i} in validation error response.`, - ); + log.warning(`ignoring out-of-range itemPosition ${i} in validation error response.`); continue; } const { item: cleaned, blockingErrors } = cleanItemFields( @@ -222,7 +228,7 @@ async function cleanAndRetry( } const report = [ - `pushDataWithSchemaRepair: schema validation failed on attempt ${attempts}: ${lastError.data.invalidItems.length} invalid item(s)`, + `schema validation failed on attempt ${attempts}: ${lastError.data.invalidItems.length} invalid item(s)`, ]; if (repairedFields.size > 0) report.push(`repaired fields: ${formatFields(repairedFields)}`); if (droppedThisRound > 0) { @@ -235,7 +241,7 @@ async function cleanAndRetry( if (working.length === 0) report.push('nothing left to retry.'); else if (attempts < maxAttempts) report.push(`retrying with ${working.length} item(s).`); else report.push(`attempt cap reached with ${working.length} item(s) left.`); - console.log(report.join('; ')); + log.warning(report.join('; ')); if (working.length === 0) return result(attempts); @@ -255,14 +261,14 @@ async function cleanAndRetry( unresolved++; dropAt(i, roundErrors[i]); } - const giveUp = [`pushDataWithSchemaRepair: gave up after ${maxAttempts} attempts`]; + const giveUp = [`gave up after ${maxAttempts} attempts`]; if (unresolved > 0) { giveUp.push(`dropped ${unresolved} item(s) still failing on fields: ${formatFields(unresolvedFields)}`); } giveUp.push( working.length > 0 ? `pushing the ${working.length} valid item(s) left.` : 'nothing to salvage.', ); - console.log(giveUp.join('; ')); + log.warning(giveUp.join('; ')); if (working.length === 0) return result(maxAttempts); @@ -277,9 +283,7 @@ async function cleanAndRetry( for (const invalid of err.data.invalidItems) { errorsAt.set(invalid.itemPosition, invalid.validationErrors); } - console.log( - `pushDataWithSchemaRepair: final push of ${working.length} item(s) was rejected too; dropping them.`, - ); + log.warning(`final push of ${working.length} item(s) was rejected too; dropping them.`); for (let i = working.length - 1; i >= 0; i--) dropAt(i, errorsAt.get(i) ?? NO_ERRORS); return result(attempts); } diff --git a/test/pushDataWithSchemaRepair.test.ts b/test/pushDataWithSchemaRepair.test.ts index edb88a8..d0db184 100644 --- a/test/pushDataWithSchemaRepair.test.ts +++ b/test/pushDataWithSchemaRepair.test.ts @@ -1,4 +1,6 @@ -import { expect, test } from 'vitest'; +import { expect, test, vi } from 'vitest'; + +import { Log } from '@apify/log'; import { isSchemaValidationError, @@ -69,18 +71,19 @@ function requiredStringName(item: Item): ValidationError[] | null { return null; } -// Swap console.log for a recorder, run `fn`, restore. Returns every logged -// line so the assertions can inspect what the wrapper reported. +// Record what the wrapper logs while `fn` runs, then restore. The wrapper logs +// through a `@apify/log` child logger, so we intercept at the class rather than +// reaching for the module-private instance. The recorded lines exclude the +// `pushDataWithSchemaRepair` prefix — the logger adds that at render time. async function captureLogs(fn: () => Promise): Promise { const lines: string[] = []; - const original = console.log; - console.log = (...args: unknown[]) => { - lines.push(args.join(' ')); - }; + const spy = vi.spyOn(Log.prototype, 'warning').mockImplementation((message: string) => { + lines.push(message); + }); try { await fn(); } finally { - console.log = original; + spy.mockRestore(); } return lines; } @@ -462,7 +465,7 @@ test('a dropped item reports only the fields that blocked it, not the ones repai // Every blocker is named at once, so one log line tells you the whole // story instead of the first offender in sort order. expect(lines[1]).toBe( - 'pushDataWithSchemaRepair: schema validation failed on attempt 2: 1 invalid item(s); ' + + 'schema validation failed on attempt 2: 1 invalid item(s); ' + 'dropped 1 item(s) on unfixable fields: /imagesCount (type number), /isAd (type boolean); ' + 'nothing left to retry.', ); @@ -492,7 +495,7 @@ test('a required field whose own value failed an unfillable type is named, not s expect(res.droppedItems[0].errors.map((e) => e.instancePath).sort()).toEqual(['/imagesCount', '/isAd']); }); expect(lines[1]).toBe( - 'pushDataWithSchemaRepair: schema validation failed on attempt 2: 1 invalid item(s); ' + + 'schema validation failed on attempt 2: 1 invalid item(s); ' + 'dropped 1 item(s) on unfixable fields: /imagesCount (type number), /isAd (type boolean); ' + 'nothing left to retry.', ); @@ -1059,9 +1062,7 @@ test('when even the salvage push is rejected, nothing counts as pushed', async ( { instancePath: '/ok', keyword: 'type', params: { type: 'string' }, message: 'late' }, ]); }); - expect(lines[lines.length - 1]).toBe( - 'pushDataWithSchemaRepair: final push of 1 item(s) was rejected too; dropping them.', - ); + expect(lines[lines.length - 1]).toBe('final push of 1 item(s) was rejected too; dropping them.'); }); test('maxAttempts: 1 leaves no room to repair but still gets the valid items in', async () => { @@ -1133,6 +1134,37 @@ test('maxAttempts <= 0 is clamped to 1 (attempts always matches real pushFn call expect(res.attemptCount).toBe(1); }); +test('reports through @apify/log at WARNING level, under its own prefix', async () => { + // The other log tests intercept `Log.warning`, which would still pass if + // the prefix or the level were wrong. This one lets the real logger render + // and checks where the line actually lands: `console.warn` is WARNING's + // output channel, and the prefix has to survive into the rendered text. + const { pushFn } = makeMockPush(requiredStringName); + const warned: string[] = []; + const logged: string[] = []; + const warnSpy = vi.spyOn(console, 'warn').mockImplementation((line: string) => { + warned.push(line); + }); + const logSpy = vi.spyOn(console, 'log').mockImplementation((line: string) => { + logged.push(line); + }); + try { + const res = await pushDataWithSchemaRepair(pushFn, [{ age: 1 }]); + expect(res.pushedCount).toBe(1); + } finally { + warnSpy.mockRestore(); + logSpy.mockRestore(); + } + expect(warned.length).toBe(2); + // Colour codes sit between the prefix and the message, so match the prefix + // token itself rather than a contiguous `prefix: message`. + for (const line of warned) expect(line).toContain('pushDataWithSchemaRepair:'); + expect(warned[0]).toContain('WARN'); + expect(warned[0]).toContain('schema validation failed on attempt 1'); + // Nothing goes to stdout any more — these are warnings, not chatter. + expect(logged).toEqual([]); +}); + test('round log names the offending fields, deduped across items', async () => { const validate = (item: Item): ValidationError[] | null => { const errors: ValidationError[] = []; @@ -1166,7 +1198,7 @@ test('round log names the offending fields, deduped across items', async () => { // collapse into one `/tags/[]` entry — the log reports fields, not // occurrences. expect(lines[0]).toBe( - 'pushDataWithSchemaRepair: schema validation failed on attempt 1: 2 invalid item(s); ' + + 'schema validation failed on attempt 1: 2 invalid item(s); ' + 'repaired fields: /age (type integer), /tags/[] (type string); retrying with 2 item(s).', ); }); @@ -1194,7 +1226,7 @@ test('round log separates dropped items and their unfixable fields', async () => expect(res.droppedItems.length).toBe(1); }); expect(lines[0]).toBe( - 'pushDataWithSchemaRepair: schema validation failed on attempt 1: 1 invalid item(s); ' + + 'schema validation failed on attempt 1: 1 invalid item(s); ' + 'dropped 1 item(s) on unfixable fields: (item root) (type object); nothing left to retry.', ); }); @@ -1210,7 +1242,7 @@ test('round log says so plainly when the API named no usable fields', async () = // No errors to name, so the log doesn't dangle an empty "unfixable // fields:" list. expect(lines[0]).toBe( - 'pushDataWithSchemaRepair: schema validation failed on attempt 1: 1 invalid item(s); ' + + 'schema validation failed on attempt 1: 1 invalid item(s); ' + 'dropped 1 item(s) the API reported no usable errors for; nothing left to retry.', ); }); @@ -1222,7 +1254,7 @@ test('give-up log names the fields that are still failing and what it salvages', }); expect(lines[2].endsWith('attempt cap reached with 2 item(s) left.'), lines[2]).toBe(true); expect(lines[3]).toBe( - 'pushDataWithSchemaRepair: gave up after 3 attempts; dropped 1 item(s) still failing on fields: /c (type string); ' + + 'gave up after 3 attempts; dropped 1 item(s) still failing on fields: /c (type string); ' + 'pushing the 1 valid item(s) left.', ); }); @@ -1403,12 +1435,10 @@ test('out-of-range itemPosition is logged once per occurrence', async () => { const lines = await captureLogs(async () => { await pushDataWithSchemaRepair(pushFn, [{ age: 30 }], { maxAttempts: 1 }); }); - expect(lines[0]).toBe( - 'pushDataWithSchemaRepair: ignoring out-of-range itemPosition 5 in validation error response.', - ); + expect(lines[0]).toBe('ignoring out-of-range itemPosition 5 in validation error response.'); // Nothing in range failed, so the round has no fields to report. expect(lines[1]).toBe( - 'pushDataWithSchemaRepair: schema validation failed on attempt 1: 1 invalid item(s); attempt cap reached with 1 item(s) left.', + 'schema validation failed on attempt 1: 1 invalid item(s); attempt cap reached with 1 item(s) left.', ); });