diff --git a/src/__tests__/services/LibraryServicePathMutations.test.ts b/src/__tests__/services/LibraryServicePathMutations.test.ts index acc9d71..c156559 100644 --- a/src/__tests__/services/LibraryServicePathMutations.test.ts +++ b/src/__tests__/services/LibraryServicePathMutations.test.ts @@ -328,6 +328,187 @@ describe('LibraryService — path-mutating flows (move / rename / folder_in_out) expect(moveFileMock).not.toHaveBeenCalled(); }); + + it('pins source_path to the pre-move key when the relocation fails, so the row still names the object that exists', async () => { + const trx = getTestTransaction(); + const user = await createTestUser(trx); + const book = await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Legacy.m4b', + source_path: null, + }); + await createTestLibraryItem(trx, { + user_id: user.id_user, + key: '0_FINISHED', + type: 0, + }); + moveFileMock.mockImplementation(async () => false); + // The copy failed, but the object is still sitting at its old key. + fileExistsMock.mockImplementation(async () => true); + + await service.moveLibraryObject(user as any, { + origin: 'Legacy.m4b', + destination: '0_FINISHED', + }); + + const bookAfter = await trx('library_items') + .where({ id_library_item: book.id_library_item }) + .first(); + // The move still commits — it is a display-path change — but the row now + // points at the object's real, un-moved location instead of at nothing. + expect(bookAfter.key).toBe('0_FINISHED/Legacy.m4b'); + expect(bookAfter.source_path).toBe('Legacy.m4b'); + }); + + it('does not strip the source_path of items relocated earlier in the same batch', async () => { + const trx = getTestTransaction(); + const user = await createTestUser(trx); + await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Series', + type: 0, + }); + const moved = await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Series/a.m4b', + source_path: null, + }); + const stranded = await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Series/b.m4b', + source_path: null, + }); + await createTestLibraryItem(trx, { + user_id: user.id_user, + key: '0_FINISHED', + type: 0, + }); + // Only the second child fails to relocate. + moveFileMock.mockImplementation(async (params: unknown) => { + const { sourceKey } = params as { sourceKey: string }; + return !sourceKey.endsWith('b.m4b'); + }); + fileExistsMock.mockImplementation(async () => true); + + await service.moveLibraryObject(user as any, { + origin: 'Series', + destination: '0_FINISHED', + }); + + const movedAfter = await trx('library_items') + .where({ id_library_item: moved.id_library_item }) + .first(); + const strandedAfter = await trx('library_items') + .where({ id_library_item: stranded.id_library_item }) + .first(); + // The one that did relocate keeps the timestamped key naming its new + // object (ROOT_FOLDER is not set in CI, so assert the shape, not the + // prefix)... + expect(movedAfter.key).toBe('0_FINISHED/Series/a.m4b'); + expect(movedAfter.source_path).toMatch(/_a\.m4b$/); + expect(movedAfter.source_path).not.toBe('Series/a.m4b'); + // ...while the one that did not is pinned to where its bytes still are. + expect(strandedAfter.key).toBe('0_FINISHED/Series/b.m4b'); + expect(strandedAfter.source_path).toBe('Series/b.m4b'); + }); + + it('leaves source_path null when the relocation failed because nothing was at the old key', async () => { + const trx = getTestTransaction(); + const user = await createTestUser(trx); + const book = await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Phantom.m4b', + source_path: null, + }); + await createTestLibraryItem(trx, { + user_id: user.id_user, + key: '0_FINISHED', + type: 0, + }); + moveFileMock.mockImplementation(async () => false); + fileExistsMock.mockImplementation(async () => false); + + await service.moveLibraryObject(user as any, { + origin: 'Phantom.m4b', + destination: '0_FINISHED', + }); + + const bookAfter = await trx('library_items') + .where({ id_library_item: book.id_library_item }) + .first(); + // There are no bytes at either key, so pinning would only record a path + // that holds nothing — and freeze the item, since a set source_path + // skips the relocation on every later move. + expect(bookAfter.key).toBe('0_FINISHED/Phantom.m4b'); + expect(bookAfter.source_path).toBeNull(); + }); + + it('pins to the new key when the delete landed but its response was lost', async () => { + const trx = getTestTransaction(); + const user = await createTestUser(trx); + const book = await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Lost.m4b', + source_path: null, + }); + await createTestLibraryItem(trx, { + user_id: user.id_user, + key: '0_FINISHED', + type: 0, + }); + // moveFile is copy-then-delete: the copy landed and the delete actually + // ran on S3, but the SDK call threw, so the move reports failure while + // the bytes are already at the target and gone from the source. + moveFileMock.mockImplementation(async () => false); + fileExistsMock.mockImplementation(async (params: unknown) => { + const { key } = params as { key: string }; + return key !== 'test-prefix/Lost.m4b'; + }); + + await service.moveLibraryObject(user as any, { + origin: 'Lost.m4b', + destination: '0_FINISHED', + }); + + const bookAfter = await trx('library_items') + .where({ id_library_item: book.id_library_item }) + .first(); + // The move really did happen, so pin to the target, not the dead source. + expect(bookAfter.key).toBe('0_FINISHED/Lost.m4b'); + expect(bookAfter.source_path).not.toBeNull(); + expect(bookAfter.source_path).not.toBe('Lost.m4b'); + expect(bookAfter.source_path).toMatch(/_Lost\.m4b$/); + }); + + it('still pins to the old key when the existence probe itself fails', async () => { + const trx = getTestTransaction(); + const user = await createTestUser(trx); + const book = await createTestLibraryItem(trx, { + user_id: user.id_user, + key: 'Probe.m4b', + source_path: null, + }); + await createTestLibraryItem(trx, { + user_id: user.id_user, + key: '0_FINISHED', + type: 0, + }); + moveFileMock.mockImplementation(async () => false); + // null = could not determine. Must not be read as "absent", or the row + // would be left naming nothing — the bug this whole path guards against. + fileExistsMock.mockImplementation(async () => null); + + await service.moveLibraryObject(user as any, { + origin: 'Probe.m4b', + destination: '0_FINISHED', + }); + + const bookAfter = await trx('library_items') + .where({ id_library_item: book.id_library_item }) + .first(); + expect(bookAfter.key).toBe('0_FINISHED/Probe.m4b'); + expect(bookAfter.source_path).toBe('Probe.m4b'); + }); }); describe('renameLibraryObject — /rename body { relativePath, newName, uuid }', () => { diff --git a/src/__tests__/services/S3ServiceFileExists.test.ts b/src/__tests__/services/S3ServiceFileExists.test.ts new file mode 100644 index 0000000..97364e7 --- /dev/null +++ b/src/__tests__/services/S3ServiceFileExists.test.ts @@ -0,0 +1,70 @@ +import { describe, it, expect, beforeEach, jest } from '@jest/globals'; +import { S3Service } from '../../services/S3Service'; +import { mockLoggerService } from '../setup'; + +/** + * fileExists is tri-state, and LibraryService.processMovedFiles depends on the + * distinction: only a definitive `false` from BOTH the source and target probe + * lets it conclude a moved item's bytes are nowhere and leave source_path null. + * A probe that merely could not determine the answer must come back as null, or + * that path records "nothing exists" on an object it was simply unable to read. + */ +describe('S3Service.fileExists — tri-state', () => { + let service: S3Service; + let headObjectMock: jest.Mock; + + beforeEach(() => { + service = new S3Service(); + headObjectMock = jest.fn(); + (service as any).client = { headObject: headObjectMock }; + (service as any)._logger = mockLoggerService; + mockLoggerService.log.mockClear(); + }); + + it('returns true when the object is there', async () => { + headObjectMock.mockImplementation(async () => ({ + $metadata: { httpStatusCode: 200 }, + })); + await expect(service.fileExists('prefix/root/a.m4b')).resolves.toBe(true); + }); + + it('returns false for a 404 — definitively absent', async () => { + headObjectMock.mockImplementation(async () => { + throw Object.assign(new Error('Not Found'), { + $metadata: { httpStatusCode: 404 }, + }); + }); + await expect(service.fileExists('prefix/root/a.m4b')).resolves.toBe(false); + }); + + it('returns null for a 403 — denied is not the same as absent', async () => { + headObjectMock.mockImplementation(async () => { + throw Object.assign(new Error('Forbidden'), { + $metadata: { httpStatusCode: 403 }, + }); + }); + await expect(service.fileExists('prefix/root/a.m4b')).resolves.toBeNull(); + }); + + it('returns null for any other failure', async () => { + headObjectMock.mockImplementation(async () => { + throw Object.assign(new Error('boom'), { + $metadata: { httpStatusCode: 500 }, + }); + }); + await expect(service.fileExists('prefix/root/a.m4b')).resolves.toBeNull(); + }); + + it('does not log the storage prefix, which can be the account email', async () => { + headObjectMock.mockImplementation(async () => { + throw Object.assign(new Error('Forbidden'), { + $metadata: { httpStatusCode: 403 }, + }); + }); + await service.fileExists('someone@example.com/root/a.m4b'); + + const logged = JSON.stringify(mockLoggerService.log.mock.calls); + expect(logged).not.toContain('someone@example.com'); + expect(logged).toContain('root/a.m4b'); + }); +}); diff --git a/src/__tests__/utils/stripStoragePrefix.test.ts b/src/__tests__/utils/stripStoragePrefix.test.ts new file mode 100644 index 0000000..c6bf2c5 --- /dev/null +++ b/src/__tests__/utils/stripStoragePrefix.test.ts @@ -0,0 +1,37 @@ +import { describe, it, expect } from '@jest/globals'; +import { stripStoragePrefix } from '../../utils'; + +/** + * stripStoragePrefix is what keeps a legacy account's email address out of + * CloudWatch: the per-user storage prefix is `users.external_id`, or that + * address for accounts predating it (see StoragePrefixService). These cases + * pin the edges so a later simplification cannot quietly reintroduce the leak. + */ +describe('stripStoragePrefix', () => { + it('drops the prefix segment and keeps the rest of the key', () => { + expect(stripStoragePrefix('someone@example.com/root/1_a.mp3')).toBe( + 'root/1_a.mp3', + ); + }); + + it('keeps every segment after the first', () => { + expect( + stripStoragePrefix('someone@example.com/TV/Bluey/S01/[E01] Bike.mp3'), + ).toBe('TV/Bluey/S01/[E01] Bike.mp3'); + }); + + it('returns empty for a bare prefix, rather than echoing the address', () => { + expect(stripStoragePrefix('someone@example.com')).toBe(''); + }); + + it('returns empty for missing or empty input', () => { + expect(stripStoragePrefix(undefined)).toBe(''); + expect(stripStoragePrefix('')).toBe(''); + }); + + it('handles an external_id prefix the same way', () => { + expect( + stripStoragePrefix('001172.22b2d822a90b45bf8c4d250c3dda4d6a.1714/root/x.m4b'), + ).toBe('root/x.m4b'); + }); +}); diff --git a/src/services/LibraryService.ts b/src/services/LibraryService.ts index 998a719..e36cca1 100644 --- a/src/services/LibraryService.ts +++ b/src/services/LibraryService.ts @@ -1253,11 +1253,7 @@ export class LibraryService { !fileMoved.source_path && parseInt(fileMoved.type) === parseInt(LibraryItemType.BOOK) ) { - const suffix = - parseInt(fileMoved.type) === parseInt(LibraryItemType.BOOK) - ? '' - : '/'; - const sourceKey = `${storagePrefix}/${fileMoved.old_key}${suffix}`; + const sourceKey = `${storagePrefix}/${fileMoved.old_key}`; const original_filename = `${ process.env.ROOT_FOLDER }/${moment().format('YYYYMMDDHHmmss')}_${ @@ -1268,16 +1264,83 @@ export class LibraryService { sourceKey, targetKey, }); - if (isMoved) { - await this._libraryDB.updateBySourcePath( + // Either way the row must end up naming the object that actually + // exists. A legacy item (source_path IS NULL) is read back at + // `${prefix}/${key}`, so once the key rewrite commits, an object + // still sitting at old_key is unreachable — the row would point at + // nothing while the bytes are orphaned under the pre-move path. + // + // Throwing to roll the rewrite back is not an option: the items + // relocated earlier in this batch are already at their new keys, + // and the rollback would strip the source_path that names them, + // orphaning those instead. So on failure we record where the file + // really is. The move itself still succeeds — it is a display-path + // change — and the item stays playable from its legacy key. + // Where the object is, as best we can establish it. + let pinnedSourcePath = original_filename; + + if (!isMoved) { + // A failed move does not locate the bytes on its own. moveFile + // is copy-then-delete, so the failure may be a copy that never + // landed (bytes at old_key) or a delete that landed on S3 but + // lost its response (bytes at the target, source already gone). + // fileExists also reports 403 as false, so a false is "could not + // find it", not "it is not there". Probe before concluding. + const sourceStillThere = await this._storage.fileExists({ + key: sourceKey, + }); + const targetLanded = + sourceStillThere === false + ? await this._storage.fileExists({ key: targetKey }) + : null; + + // Anything short of a definitive "source is gone" means the + // object is, or is presumed, still at the old key — the common + // case, and the safe default when the probe itself failed + // (fileExists returns null then). + if (sourceStillThere !== false) { + pinnedSourcePath = fileMoved.old_key; + } + + // Nothing found at either key. Pinning would record a path that + // holds nothing and freeze the row: the guard above skips items + // that already have a source_path, so no later move would retry + // the relocation. Leave it null instead — still broken, but + // still detectable and still retryable. + const foundNothing = + sourceStillThere === false && targetLanded !== true; + + this._logger.log( { - user_id: user.id_user, - key: fileMoved.key, - source_path: original_filename, + origin: 'LibraryService.processMovedFiles', + message: 'Storage relocation failed', + data: { + id_user: user.id_user, + oldKey: fileMoved.old_key, + newKey: fileMoved.key, + sourceStillThere, + targetLanded, + // The decision itself, not just its inputs. A remediation + // sweep can then separate a confirmed phantom (both + // probes 404) from one where the target probe only came + // back indeterminate. + foundNothing, + targetIndeterminate: targetLanded === null, + pinnedSourcePath: foundNothing ? null : pinnedSourcePath, + }, }, - trx, + 'error', ); + if (foundNothing) continue; } + await this._libraryDB.updateBySourcePath( + { + user_id: user.id_user, + key: fileMoved.key, + source_path: pinnedSourcePath, + }, + trx, + ); } } }), diff --git a/src/services/S3Service.ts b/src/services/S3Service.ts index 25ac57d..19d1902 100644 --- a/src/services/S3Service.ts +++ b/src/services/S3Service.ts @@ -17,13 +17,23 @@ import { S3ClientHeaders, StorageAction, StorageItem } from '../types/user'; import moment from 'moment'; import { logger } from './LoggerService'; import { Readable } from 'stream'; +import { stripStoragePrefix } from '../utils'; export class S3Service { private readonly _logger = logger; private client = new S3({ region: process.env.S3_REGION }); private clientObject = new S3Client({ region: process.env.S3_REGION }); - async fileExists(key: string): Promise { + /** + * Tri-state on purpose: true/false are definitive, null means the probe + * could not determine it and the caller must not read that as "absent". + * + * A 403 is indeterminate, not absent. S3 masks a missing key as 403 only + * when the caller lacks s3:ListBucket, and this role holds it (see + * getDirectoryContent / calculateFolderSize, which call ListObjectsV2), so + * a 403 here means a permission or KMS problem rather than a missing key. + */ + async fileExists(key: string): Promise { try { const data = await this.client.headObject({ Bucket: process.env.S3_BUCKET, @@ -35,13 +45,31 @@ export class S3Service { if (error.$metadata?.httpStatusCode === 404) { return false; } else if (error.$metadata?.httpStatusCode === 403) { - return false; + // Indeterminate, not absent — see the tri-state note above. Returning + // false here would let a permission failure read as "the object is + // nowhere", which is how a caller ends up recording that nothing + // exists when in fact it could not look. + this._logger.log( + { + origin: 'S3Service.fileExists', + message: 'Existence probe denied (403); treating as indeterminate', + data: { key: stripStoragePrefix(key) }, + }, + 'warn', + ); + return null; } else { - this._logger.log({ - origin: 'S3: fileExists', - message: error.message, - data: { key }, - }); + // Same level as the 403 branch: this is the wider indeterminate class + // (5xx, timeouts, SDK failures) and it drives the same caller + // decision, so it has to clear the production LOG_LEVEL of 'warn' too. + this._logger.log( + { + origin: 'S3Service.fileExists', + message: error.message, + data: { key: stripStoragePrefix(key), errorName: error.name }, + }, + 'warn', + ); return null; } } @@ -121,6 +149,11 @@ export class S3Service { } async moveFile(sourceKey: string, targetKey: string): Promise { + // Copy-then-delete, so a failure has two very different shapes: the copy + // never landed (bytes only at sourceKey) or the copy landed and the delete + // did not (bytes at both). `copied` tells them apart in the log — the + // caller only sees false either way. + let copied = false; try { await this.clientObject.send( new CopyObjectCommand({ @@ -131,6 +164,7 @@ export class S3Service { )}`, }), ); + copied = true; await this.clientObject.send( new DeleteObjectCommand({ Bucket: process.env.S3_BUCKET, @@ -139,12 +173,24 @@ export class S3Service { ); return true; } catch (error) { - this._logger.log({ - origin: 'S3: moveFile', - message: error.message, - data: { sourceKey, targetKey }, - }); - return null; + // 'error': a failed relocation desynchronizes the DB key from the object + // it names, so it has to survive the production LOG_LEVEL of 'warn'. + // Keys are prefix-stripped: for legacy accounts that prefix is the user's + // email, and this path serves exactly those accounts. + this._logger.log( + { + origin: 'S3Service.moveFile', + message: error.message, + data: { + sourceKey: stripStoragePrefix(sourceKey), + targetKey: stripStoragePrefix(targetKey), + copied, + errorName: error.name, + }, + }, + 'error', + ); + return false; } } diff --git a/src/services/StorageService.ts b/src/services/StorageService.ts index 1c7f876..bf61c0a 100644 --- a/src/services/StorageService.ts +++ b/src/services/StorageService.ts @@ -7,20 +7,22 @@ import { import { logger } from './LoggerService'; import { S3Service } from './S3Service'; import { Readable } from 'stream'; +import { stripStoragePrefix } from '../utils'; export class StorageService { private readonly _logger = logger; constructor(private _s3Service: S3Service = new S3Service()) {} + /** Tri-state; see S3Service.fileExists. null means "could not determine". */ async fileExists(params: { key: string; origin?: StorageOrigin; - }): Promise { + }): Promise { try { const { key, origin } = params; const storageOrigin = origin || StorageOrigin.S3; - let exist = false; + let exist: boolean | null = false; switch (storageOrigin) { case StorageOrigin.S3: exist = await this._s3Service.fileExists(key); @@ -30,11 +32,17 @@ export class StorageService { } return exist; } catch (error) { - this._logger.log({ - origin: 'Storage: fileExists', - message: error.message, - data: params, - }); + // Prefix-stripped and at 'warn' for the same reasons as the moveFile + // catches: params.key carries the per-user prefix, which is the account + // email for legacy accounts, and this null drives the caller's pin. + this._logger.log( + { + origin: 'StorageService.fileExists', + message: error.message, + data: { key: stripStoragePrefix(params.key) }, + }, + 'warn', + ); return null; } } @@ -118,12 +126,22 @@ export class StorageService { } return moved; } catch (error) { - this._logger.log({ - origin: 'Storage: moveFile', - message: error.message, - data: params, - }); - return null; + // See S3Service.moveFile: logged at 'error' so the desync is visible in + // production, where LOG_LEVEL is 'warn'. `params` is not logged whole — + // its keys carry the per-user storage prefix, which is the account's + // email for the legacy accounts this path serves. + this._logger.log( + { + origin: 'StorageService.moveFile', + message: error.message, + data: { + sourceKey: stripStoragePrefix(params.sourceKey), + targetKey: stripStoragePrefix(params.targetKey), + }, + }, + 'error', + ); + return false; } } diff --git a/src/utils/index.ts b/src/utils/index.ts index bcba6b2..84d8267 100644 --- a/src/utils/index.ts +++ b/src/utils/index.ts @@ -28,6 +28,21 @@ export function isValidUUID(testUuid?: string): boolean { return UUID_REGEX.test(testUuid); } +/** + * Drops the per-user storage prefix from an S3 key so the remainder is safe to + * log. The prefix is always a single segment — `users.external_id`, or, for + * legacy accounts, the account's email address (see StoragePrefixService) — + * and LoggerService redacts only password/token/secret/authorization, so a + * whole key logged verbatim would publish that address. + * @param storageKey - A prefixed key, e.g. `someone@example.com/root/1_a.mp3` + * @returns The key without its first segment, e.g. `root/1_a.mp3` + */ +export const stripStoragePrefix = (storageKey?: string): string => { + if (!storageKey) return ''; + const separator = storageKey.indexOf('/'); + return separator === -1 ? '' : storageKey.slice(separator + 1); +}; + export const splitArrayGroups = (array: unknown[], chunkSize: number) => { const chunks = []; for (let i = 0; i < array.length; i += chunkSize) {