Reduce noisy logging for best-effort backend operations · rowanpaulflynn.dev/opnshelf@d947fd6

+29 -3

backend/src/auth/auth.service.spec.ts

··· 122 122 token_endpoint_auth_method: "none", 123 123 dpop_bound_access_tokens: true, 124 124 }, 125 - stateStore: expect.any(Object), 126 - sessionStore: expect.any(Object), 127 - requestLock: expect.any(Function), 125 + stateStore: { 126 + set: expect.any(Function), 127 + get: expect.any(Function), 128 + del: expect.any(Function), 129 + }, 130 + sessionStore: { 131 + set: expect.any(Function), 132 + get: expect.any(Function), 133 + del: expect.any(Function), 134 + }, 135 + requestLock: undefined, 128 136 allowHttp: true, 129 137 }); 130 138 }); ··· 604 612 }, 605 613 getProfile: jest.fn(), 606 614 })); 615 + const warnSpy = jest.spyOn( 616 + ( 617 + service as unknown as { 618 + logger: { warn: (...args: unknown[]) => void }; 619 + } 620 + ).logger, 621 + "warn", 622 + ); 607 623 608 624 await expect(service.hasBlueskyProfile("did:plc:abc123")).resolves.toBe( 609 625 false, 610 626 ); 627 + expect(warnSpy).not.toHaveBeenCalled(); 611 628 }); 612 629 613 630 it("should return false when the session cannot be restored", async () => { ··· 621 638 restore: mockRestore, 622 639 })); 623 640 service.onModuleInit(); 641 + const warnSpy = jest.spyOn( 642 + ( 643 + service as unknown as { 644 + logger: { warn: (...args: unknown[]) => void }; 645 + } 646 + ).logger, 647 + "warn", 648 + ); 624 649 625 650 await expect(service.hasBlueskyProfile("did:plc:abc123")).resolves.toBe( 626 651 false, 627 652 ); 653 + expect(warnSpy).not.toHaveBeenCalled(); 628 654 }); 629 655 }); 630 656

+15 -10

backend/src/auth/auth.service.ts

··· 223 223 * created app.bsky.actor.profile/self, which should not count as linked. 224 224 */ 225 225 async hasBlueskyProfile(did: string): Promise<boolean> { 226 - const session = await this.restore(did); 227 - if (!session) { 228 - return false; 229 - } 230 - 231 226 try { 227 + const session = await this.getRestoredSessionQuietly(did); 228 + if (!session) { 229 + return false; 230 + } 231 + 232 232 const agent = new Agent( 233 233 session as unknown as ConstructorParameters<typeof Agent>[0], 234 234 ); ··· 238 238 rkey: "self", 239 239 }); 240 240 return true; 241 - } catch (error) { 242 - this.logger.warn( 243 - `Failed to determine Bluesky profile status for ${did}`, 244 - error instanceof Error ? error.stack : undefined, 245 - ); 241 + } catch { 246 242 return false; 243 + } 244 + } 245 + 246 + private async getRestoredSessionQuietly(did: string) { 247 + const client = this.getOAuthClient(); 248 + try { 249 + return await client.restore(did); 250 + } catch { 251 + return undefined; 247 252 } 248 253 } 249 254

+39

backend/src/ingester/ingester.service.spec.ts

··· 262 262 ); 263 263 }); 264 264 265 + it("logs missing record payloads at debug instead of warn", async () => { 266 + const recordHandler = setupRecordHandler(); 267 + const debugSpy = jest.spyOn( 268 + ( 269 + service as unknown as { 270 + logger: { debug: (...args: unknown[]) => void }; 271 + } 272 + ).logger, 273 + "debug", 274 + ); 275 + const warnSpy = jest.spyOn( 276 + ( 277 + service as unknown as { 278 + logger: { warn: (...args: unknown[]) => void }; 279 + } 280 + ).logger, 281 + "warn", 282 + ); 283 + 284 + await recordHandler({ 285 + id: 6, 286 + type: "record", 287 + action: "create", 288 + did: "did:plc:abc123", 289 + rev: "rev-follow-missing", 290 + collection: "xyz.opnshelf.follow", 291 + rkey: "follow-rkey-missing", 292 + cid: "cid-follow-missing", 293 + live: true, 294 + }); 295 + 296 + expect(debugSpy).toHaveBeenCalledWith( 297 + "Record event missing record data: at://did:plc:abc123/xyz.opnshelf.follow/follow-rkey-missing", 298 + ); 299 + expect(warnSpy).not.toHaveBeenCalledWith( 300 + "Record event missing record data: at://did:plc:abc123/xyz.opnshelf.follow/follow-rkey-missing", 301 + ); 302 + }); 303 + 265 304 it("should upsert tracked movie for xyz.opnshelf.movie create", async () => { 266 305 const recordHandler = setupRecordHandler(); 267 306 mockPrismaService.user.findUnique.mockResolvedValue({

+6 -6

backend/src/ingester/ingester.service.ts

··· 221 221 private async handleFollowEvent(evt: RecordEvent, uri: string) { 222 222 if (evt.action === "create" || evt.action === "update") { 223 223 if (!evt.record) { 224 - this.logger.warn(`Record event missing record data: ${uri}`); 224 + this.logger.debug(`Record event missing record data: ${uri}`); 225 225 return; 226 226 } 227 227 ··· 255 255 private async handleMovieEvent(evt: RecordEvent, uri: string) { 256 256 if (evt.action === "create" || evt.action === "update") { 257 257 if (!evt.record) { 258 - this.logger.warn(`Record event missing record data: ${uri}`); 258 + this.logger.debug(`Record event missing record data: ${uri}`); 259 259 return; 260 260 } 261 261 ··· 321 321 private async handleProfileEvent(evt: RecordEvent, uri: string) { 322 322 if (evt.action === "create" || evt.action === "update") { 323 323 if (!evt.record) { 324 - this.logger.warn(`Record event missing record data: ${uri}`); 324 + this.logger.debug(`Record event missing record data: ${uri}`); 325 325 return; 326 326 } 327 327 ··· 357 357 private async handleListEvent(evt: RecordEvent, uri: string) { 358 358 if (evt.action === "create" || evt.action === "update") { 359 359 if (!evt.record) { 360 - this.logger.warn(`Record event missing record data: ${uri}`); 360 + this.logger.debug(`Record event missing record data: ${uri}`); 361 361 return; 362 362 } 363 363 ··· 393 393 private async handleEpisodeEvent(evt: RecordEvent, uri: string) { 394 394 if (evt.action === "create" || evt.action === "update") { 395 395 if (!evt.record) { 396 - this.logger.warn(`Record event missing record data: ${uri}`); 396 + this.logger.debug(`Record event missing record data: ${uri}`); 397 397 return; 398 398 } 399 399 ··· 470 470 private async handleListItemEvent(evt: RecordEvent, uri: string) { 471 471 if (evt.action === "create" || evt.action === "update") { 472 472 if (!evt.record) { 473 - this.logger.warn(`Record event missing record data: ${uri}`); 473 + this.logger.debug(`Record event missing record data: ${uri}`); 474 474 return; 475 475 } 476 476

+32

backend/src/movies/movies.service.spec.ts

··· 722 722 }); 723 723 }); 724 724 725 + it("should ignore missing PDS records in all mode without warning", async () => { 726 + const mockSession = { did: "did:plc:abc123" }; 727 + const allWatches = [ 728 + { id: "tracked-1", rkey: "movie-123-1234567890", movieId: "123" }, 729 + ]; 730 + const warnSpy = jest.spyOn( 731 + ( 732 + service as unknown as { 733 + logger: { warn: (...args: unknown[]) => void }; 734 + } 735 + ).logger, 736 + "warn", 737 + ); 738 + 739 + mockPrismaService.trackedMovie.findMany.mockResolvedValue(allWatches); 740 + mockDeleteRecord.mockRejectedValue(new Error("RecordNotFound")); 741 + 742 + const result = await service.unmarkWatched( 743 + "did:plc:abc123", 744 + mockSession, 745 + "123", 746 + "all", 747 + ); 748 + 749 + expect(result).toEqual({ 750 + movieId: "123", 751 + mode: "all", 752 + deletedCount: 1, 753 + }); 754 + expect(warnSpy).not.toHaveBeenCalled(); 755 + }); 756 + 725 757 it("should return empty result when no watch record found in latest mode", async () => { 726 758 const mockSession = { did: "did:plc:abc123" }; 727 759

+1 -5

backend/src/movies/movies.service.ts

··· 294 294 this.logger.log( 295 295 `Deleted AT record for movie ${movieId} with rkey ${tracked.rkey}`, 296 296 ); 297 - } catch { 298 - this.logger.warn( 299 - `Failed to delete record ${tracked.rkey}, may not exist in PDS`, 300 - ); 301 - } 297 + } catch {} 302 298 } 303 299 304 300 return { movieId, mode, deletedCount: trackedMovies.length };

+40

backend/src/social/social.service.spec.ts

···

+1 -1

backend/src/social/social.service.ts

···

+73

backend/src/users/users.service.spec.ts

··· 167 167 displayName: "Updated User", 168 168 avatar: "https://example.com/avatar.jpg", 169 169 }); 170 + const logSpy = jest.spyOn( 171 + (service as unknown as { logger: { log: (...args: unknown[]) => void } }) 172 + .logger, 173 + "log", 174 + ); 170 175 expect(profileService.updateProfile).toHaveBeenCalledWith( 171 176 "did:plc:123", 172 177 session, ··· 176 181 ); 177 182 expect(listsService.hasAllDefaultLists).toHaveBeenCalledWith("did:plc:123"); 178 183 expect(listsService.provisionDefaultLists).not.toHaveBeenCalled(); 184 + expect(logSpy).not.toHaveBeenCalled(); 185 + }); 186 + 187 + it("updates user settings without logging routine success", async () => { 188 + prisma.user.findUnique = jest 189 + .fn() 190 + .mockResolvedValue({ did: "did:plc:123" }); 191 + prisma.user.update = jest.fn().mockResolvedValue({ 192 + timezone: "Europe/Amsterdam", 193 + timeFormat: "24h", 194 + }); 195 + const logSpy = jest.spyOn( 196 + (service as unknown as { logger: { log: (...args: unknown[]) => void } }) 197 + .logger, 198 + "log", 199 + ); 200 + 201 + await expect( 202 + service.updateUserSettings("did:plc:123", { 203 + timezone: "Europe/Amsterdam", 204 + timeFormat: "24h", 205 + }), 206 + ).resolves.toEqual({ 207 + timezone: "Europe/Amsterdam", 208 + timeFormat: "24h", 209 + }); 210 + 211 + expect(logSpy).not.toHaveBeenCalled(); 179 212 }); 180 213 181 214 it("throws when updating profile for missing user", async () => { ··· 204 237 mimetype: "image/png", 205 238 size: 6, 206 239 }; 240 + const logSpy = jest.spyOn( 241 + (service as unknown as { logger: { log: (...args: unknown[]) => void } }) 242 + .logger, 243 + "log", 244 + ); 207 245 208 246 await expect( 209 247 service.uploadUserAvatar("did:plc:123", session, file), ··· 219 257 }, 220 258 ); 221 259 expect(listsService.provisionDefaultLists).not.toHaveBeenCalled(); 260 + expect(logSpy).not.toHaveBeenCalled(); 222 261 }); 223 262 224 263 it("deletes a user avatar through the profile service", async () => { ··· 230 269 avatar: null, 231 270 }); 232 271 const session = { did: "did:plc:123" }; 272 + const logSpy = jest.spyOn( 273 + (service as unknown as { logger: { log: (...args: unknown[]) => void } }) 274 + .logger, 275 + "log", 276 + ); 233 277 234 278 await expect( 235 279 service.deleteUserAvatar("did:plc:123", session), ··· 242 286 session, 243 287 ); 244 288 expect(listsService.provisionDefaultLists).not.toHaveBeenCalled(); 289 + expect(logSpy).not.toHaveBeenCalled(); 245 290 }); 246 291 247 292 it("provisions default lists after the first profile save", async () => { ··· 510 555 prisma.user.findUnique = jest 511 556 .fn() 512 557 .mockResolvedValueOnce({ did: "did:plc:self" }); 558 + const warnSpy = jest.spyOn( 559 + (service as unknown as { logger: { warn: (...args: unknown[]) => void } }) 560 + .logger, 561 + "warn", 562 + ); 513 563 514 564 global.fetch = jest.fn().mockResolvedValue({ 515 565 ok: false, ··· 520 570 await expect(service.importBlueskyFollows("did:plc:self")).rejects.toThrow( 521 571 BadGatewayException, 522 572 ); 573 + expect(warnSpy).not.toHaveBeenCalled(); 574 + }); 575 + 576 + it("maps Bluesky network failures to a gateway error without warning noise", async () => { 577 + prisma.user.findUnique = jest 578 + .fn() 579 + .mockResolvedValueOnce({ did: "did:plc:self" }); 580 + const warnSpy = jest.spyOn( 581 + (service as unknown as { logger: { warn: (...args: unknown[]) => void } }) 582 + .logger, 583 + "warn", 584 + ); 585 + 586 + global.fetch = jest 587 + .fn() 588 + .mockRejectedValue( 589 + new Error("socket timeout"), 590 + ) as unknown as typeof fetch; 591 + 592 + await expect(service.importBlueskyFollows("did:plc:self")).rejects.toThrow( 593 + BadGatewayException, 594 + ); 595 + expect(warnSpy).not.toHaveBeenCalled(); 523 596 }); 524 597 525 598 it("throws when public profile handle is missing", async () => {

-14

backend/src/users/users.service.ts

··· 94 94 }, 95 95 }); 96 96 97 - this.logger.log(`Updated settings for user ${did}`); 98 - 99 97 return { 100 98 timezone: updatedUser.timezone, 101 99 timeFormat: updatedUser.timeFormat, ··· 122 120 }), 123 121 ); 124 122 125 - this.logger.log(`Updated OpnShelf profile for user ${did}`); 126 - 127 123 return updatedProfile; 128 124 } 129 125 ··· 150 146 avatar: file, 151 147 }), 152 148 ); 153 - this.logger.log(`Uploaded avatar for user ${did}`); 154 149 return updatedProfile; 155 150 } 156 151 ··· 169 164 session, 170 165 () => this.profileService.deleteAvatar(did, session), 171 166 ); 172 - this.logger.log(`Deleted avatar for user ${did}`); 173 167 return updatedProfile; 174 168 } 175 169 ··· 411 405 signal: AbortSignal.timeout(5000), 412 406 }); 413 407 if (!response.ok) { 414 - this.logger.warn( 415 - `Bluesky follows import failed for ${actorDid}: ${response.status} ${response.statusText}`, 416 - ); 417 408 throw new BadGatewayException( 418 409 "Could not import Bluesky follows right now", 419 410 ); ··· 436 427 if (error instanceof BadGatewayException) { 437 428 throw error; 438 429 } 439 - 440 - this.logger.warn( 441 - `Failed to import Bluesky follows for ${actorDid}`, 442 - error, 443 - ); 444 430 throw new BadGatewayException( 445 431 "Could not import Bluesky follows right now", 446 432 );

Configure Feed

Configure Feed