spec(backend): 一部のエンドポイントにログを追加 (MisskeyIO#457)

packages/backend/src/logger.ts

@@ -55,6 +55,11 @@ export default class Logger {
 		return new Logger(domain, undefined, false, this);
 	}
 
+	@bindThis
+	public setContext(context: Record<string, any>): void {
+		this.logger = this.logger.child({ context });
+	}
+
 	@bindThis
 	public error(x: string | Error, context?: Record<string, any> | null, important = false): void { // 実行を継続できない状況で使う
 		if (context === null) context = undefined;

packages/backend/src/server/api/SigninApiService.ts

@@ -5,7 +5,6 @@
 
 import { Inject, Injectable } from '@nestjs/common';
 import bcrypt from 'bcryptjs';
-import * as OTPAuth from 'otpauth';
 import { IsNull } from 'typeorm';
 import { DI } from '@/di-symbols.js';
 import type {
@@ -20,6 +19,7 @@ import { IdService } from '@/core/IdService.js';
 import { bindThis } from '@/decorators.js';
 import { WebAuthnService } from '@/core/WebAuthnService.js';
 import { UserAuthService } from '@/core/UserAuthService.js';
+import { LoggerService } from '@/core/LoggerService.js';
 import { RateLimiterService } from './RateLimiterService.js';
 import { SigninService } from './SigninService.js';
 import type { AuthenticationResponseJSON } from '@simplewebauthn/types';
@@ -41,6 +41,7 @@ export class SigninApiService {
 		private signinsRepository: SigninsRepository,
 
 		private idService: IdService,
+		private loggerService: LoggerService,
 		private rateLimiterService: RateLimiterService,
 		private signinService: SigninService,
 		private userAuthService: UserAuthService,
@@ -60,6 +61,10 @@ export class SigninApiService {
 		}>,
 		reply: FastifyReply,
 	) {
+		const logger = this.loggerService.getLogger('api:signin');
+		logger.setContext({ username: request.body.username, ip: request.ip, headers: request.headers });
+		logger.info('Requested to sign in.');
+
 		reply.header('Access-Control-Allow-Origin', this.config.url);
 		reply.header('Access-Control-Allow-Credentials', 'true');
 
@@ -77,6 +82,7 @@ export class SigninApiService {
 		// not more than 1 attempt per second and not more than 10 attempts per hour
 			await this.rateLimiterService.limit({ key: 'signin', duration: 60 * 60 * 1000, max: 10, minInterval: 1000 }, getIpHash(request.ip));
 		} catch (err) {
+			logger.warn('Too many failed attempts to sign in.');
 			reply.code(429);
 			return {
 				error: {
@@ -88,16 +94,19 @@ export class SigninApiService {
 		}
 
 		if (typeof username !== 'string') {
+			logger.warn('Invalid parameter: username is not a string.');
 			reply.code(400);
 			return;
 		}
 
 		if (typeof password !== 'string') {
+			logger.warn('Invalid parameter: password is not a string.');
 			reply.code(400);
 			return;
 		}
 
 		if (token != null && typeof token !== 'string') {
+			logger.warn('Invalid parameter: token is not a string.');
 			reply.code(400);
 			return;
 		}
@@ -109,12 +118,14 @@ export class SigninApiService {
 		}) as MiLocalUser;
 
 		if (user == null) {
+			logger.error('No such user.');
 			return error(404, {
 				id: '6cc579cc-885d-43d8-95c2-b8c7fc963280',
 			});
 		}
 
 		if (user.isSuspended) {
+			logger.error('User is suspended.');
 			return error(403, {
 				id: 'e03a5f46-d309-4865-9b69-56282d94e1eb',
 			});
@@ -140,8 +151,10 @@ export class SigninApiService {
 
 		if (!profile.twoFactorEnabled) {
 			if (same) {
+				logger.info('Successfully signed in with password.');
 				return this.signinService.signin(request, reply, user);
 			} else {
+				logger.error('Invalid request: incorrect password.');
 				return await fail(403, {
 					id: '932c904e-9460-45b7-9ce6-7ed33be7eb2c',
 				});
@@ -150,6 +163,7 @@ export class SigninApiService {
 
 		if (token) {
 			if (!same) {
+				logger.error('Invalid request: incorrect password.');
 				return await fail(403, {
 					id: '932c904e-9460-45b7-9ce6-7ed33be7eb2c',
 				});
@@ -158,14 +172,17 @@ export class SigninApiService {
 			try {
 				await this.userAuthService.twoFactorAuthenticate(profile, token);
 			} catch (e) {
+				logger.error('Invalid request: Unable to authenticate with two-factor token.');
 				return await fail(403, {
 					id: 'cdf1235b-ac71-46d4-a3a6-84ccce48df6f',
 				});
 			}
 
+			logger.info('Successfully signed in with password and two-factor token.');
 			return this.signinService.signin(request, reply, user);
 		} else if (body.credential) {
 			if (!same && !profile.usePasswordLessLogin) {
+				logger.error('Invalid request: incorrect password.');
 				return await fail(403, {
 					id: '932c904e-9460-45b7-9ce6-7ed33be7eb2c',
 				});
@@ -174,14 +191,17 @@ export class SigninApiService {
 			const authorized = await this.webAuthnService.verifyAuthentication(user.id, body.credential);
 
 			if (authorized) {
+				logger.info('Successfully signed in with WebAuthn authentication.');
 				return this.signinService.signin(request, reply, user);
 			} else {
+				logger.error('Invalid request: Unable to authenticate with WebAuthn credential.');
 				return await fail(403, {
 					id: '93b86c4b-72f9-40eb-9815-798928603d1e',
 				});
 			}
 		} else {
 			if (!same && !profile.usePasswordLessLogin) {
+				logger.error('Invalid request: incorrect password.');
 				return await fail(403, {
 					id: '932c904e-9460-45b7-9ce6-7ed33be7eb2c',
 				});
@@ -189,6 +209,7 @@ export class SigninApiService {
 
 			const authRequest = await this.webAuthnService.initiateAuthentication(user.id);
 
+			logger.info('Successfully initiated WebAuthn authentication.');
 			reply.code(200);
 			return authRequest;
 		}

packages/backend/src/server/api/SignupApiService.ts

@@ -19,6 +19,7 @@ import { MiLocalUser } from '@/models/User.js';
 import { FastifyReplyError } from '@/misc/fastify-reply-error.js';
 import { bindThis } from '@/decorators.js';
 import { L_CHARS, secureRndstr } from '@/misc/secure-rndstr.js';
+import { LoggerService } from '@/core/LoggerService.js';
 import { SigninService } from './SigninService.js';
 import type { FastifyRequest, FastifyReply } from 'fastify';
 
@@ -43,6 +44,7 @@ export class SignupApiService {
 		@Inject(DI.registrationTicketsRepository)
 		private registrationTicketsRepository: RegistrationTicketsRepository,
 
+		private loggerService: LoggerService,
 		private userEntityService: UserEntityService,
 		private idService: IdService,
 		private metaService: MetaService,
@@ -70,6 +72,10 @@ export class SignupApiService {
 		}>,
 		reply: FastifyReply,
 	) {
+		const logger = this.loggerService.getLogger('api:signup');
+		logger.setContext({ username: request.body.username, email: request.body.emailAddress, ip: request.ip, headers: request.headers });
+		logger.info('Requested to create user account.');
+
 		const body = request.body;
 
 		const instance = await this.metaService.fetch(true);
@@ -79,24 +85,28 @@ export class SignupApiService {
 		if (process.env.NODE_ENV !== 'test') {
 			if (instance.enableHcaptcha && instance.hcaptchaSecretKey) {
 				await this.captchaService.verifyHcaptcha(instance.hcaptchaSecretKey, body['hcaptcha-response']).catch(err => {
+					logger.error('Failed to verify hCaptcha.', { error: err });
 					throw new FastifyReplyError(400, err);
 				});
 			}
 
 			if (instance.enableMcaptcha && instance.mcaptchaSecretKey && instance.mcaptchaSitekey && instance.mcaptchaInstanceUrl) {
 				await this.captchaService.verifyMcaptcha(instance.mcaptchaSecretKey, instance.mcaptchaSitekey, instance.mcaptchaInstanceUrl, body['m-captcha-response']).catch(err => {
+					logger.error('Failed to verify mCaptcha.', { error: err });
 					throw new FastifyReplyError(400, err);
 				});
 			}
 
 			if (instance.enableRecaptcha && instance.recaptchaSecretKey) {
 				await this.captchaService.verifyRecaptcha(instance.recaptchaSecretKey, body['g-recaptcha-response']).catch(err => {
+					logger.error('Failed to verify reCAPTCHA.', { error: err });
 					throw new FastifyReplyError(400, err);
 				});
 			}
 
 			if (instance.enableTurnstile && instance.turnstileSecretKey) {
 				await this.captchaService.verifyTurnstile(instance.turnstileSecretKey, body['turnstile-response']).catch(err => {
+					logger.error('Failed to verify Turnstile.', { error: err });
 					throw new FastifyReplyError(400, err);
 				});
 			}
@@ -110,12 +120,14 @@ export class SignupApiService {
 
 		if (instance.emailRequiredForSignup) {
 			if (emailAddress == null || typeof emailAddress !== 'string') {
+				logger.error('Invalid request: email address is required.');
 				reply.code(400);
 				return;
 			}
 
 			const res = await this.emailService.validateEmailForAccount(emailAddress);
 			if (!res.available) {
+				logger.error('Failed to validate email address.', { reason: res.reason });
 				reply.code(400);
 				return;
 			}
@@ -125,6 +137,7 @@ export class SignupApiService {
 
 		if (instance.disableRegistration) {
 			if (invitationCode == null || typeof invitationCode !== 'string') {
+				logger.error('Invalid request: invitation code is required.');
 				reply.code(400);
 				return;
 			}
@@ -134,11 +147,13 @@ export class SignupApiService {
 			});
 
 			if (ticket == null || ticket.usedById != null) {
+				logger.error('Invalid request: invalid invitation code.');
 				reply.code(400);
 				return;
 			}
 
 			if (ticket.expiresAt && ticket.expiresAt < new Date()) {
+				logger.error('Invalid request: expired invitation code.');
 				reply.code(400);
 				return;
 			}
@@ -147,16 +162,19 @@ export class SignupApiService {
 			if (instance.emailRequiredForSignup) {
 				// メアド認証済みならエラー
 				if (ticket.usedBy) {
+					logger.error('Invalid request: invitation code is already used.');
 					reply.code(400);
 					return;
 				}
 
 				// 認証しておらず、メール送信から30分以内ならエラー
 				if (ticket.usedAt && ticket.usedAt.getTime() + (1000 * 60 * 30) > Date.now()) {
+					logger.error('Invalid request: invitation code is already used.');
 					reply.code(400);
 					return;
 				}
 			} else if (ticket.usedAt) {
+				logger.error('Invalid request: invitation code is already used.');
 				reply.code(400);
 				return;
 			}
@@ -164,16 +182,19 @@ export class SignupApiService {
 
 		if (instance.emailRequiredForSignup) {
 			if (await this.usersRepository.exists({ where: { usernameLower: username.toLowerCase(), host: IsNull() } })) {
+				logger.error('Invalid request: username is already taken by another user.');
 				throw new FastifyReplyError(400, 'DUPLICATED_USERNAME');
 			}
 
 			// Check deleted username duplication
 			if (await this.usedUsernamesRepository.exists({ where: { username: username.toLowerCase() } })) {
+				logger.error('Invalid request: username is already used.');
 				throw new FastifyReplyError(400, 'USED_USERNAME');
 			}
 
 			const isPreserved = instance.preservedUsernames.map(x => x.toLowerCase()).includes(username.toLowerCase());
 			if (isPreserved) {
+				logger.error('Invalid request: username is preserved.');
 				throw new FastifyReplyError(400, 'DENIED_USERNAME');
 			}
 
@@ -198,12 +219,14 @@ export class SignupApiService {
 				`To complete signup, please click this link: ${link}`);
 
 			if (ticket) {
+				logger.info('Update invitation code as used by pending user.', { ticketId: ticket.id, pendingUserId: pendingUser.id, pendingUsername: pendingUser.username });
 				await this.registrationTicketsRepository.update(ticket.id, {
 					usedAt: new Date(),
 					pendingUserId: pendingUser.id,
 				});
 			}
 
+			logger.info('Successfully created pending user.', { pendingUserId: pendingUser.id });
 			reply.code(204);
 			return;
 		} else {
@@ -218,6 +241,7 @@ export class SignupApiService {
 				});
 
 				if (ticket) {
+					logger.info('Update invitation code as used by user.', { ticketId: ticket.id, userId: account.id, username });
 					await this.registrationTicketsRepository.update(ticket.id, {
 						usedAt: new Date(),
 						usedBy: account,
@@ -225,11 +249,13 @@ export class SignupApiService {
 					});
 				}
 
+				logger.info('Successfully created user.', { userId: account.id });
 				return {
 					...res,
 					token: secret,
 				};
 			} catch (err) {
+				logger.error('Failed to create user.', { error: err });
 				throw new FastifyReplyError(400, typeof err === 'string' ? err : (err as Error).toString());
 			}
 		}
@@ -237,6 +263,10 @@ export class SignupApiService {
 
 	@bindThis
 	public async signupPending(request: FastifyRequest<{ Body: { code: string; } }>, reply: FastifyReply) {
+		const logger = this.loggerService.getLogger('api:signup:pending');
+		logger.setContext({ code: request.body.code, ip: request.ip, headers: request.headers });
+		logger.info('Requested to complete creating user account.');
+
 		const body = request.body;
 
 		const code = body['code'];
@@ -245,6 +275,7 @@ export class SignupApiService {
 			const pendingUser = await this.userPendingsRepository.findOneByOrFail({ code });
 
 			if (this.idService.parse(pendingUser.id).date.getTime() + (1000 * 60 * 30) < Date.now()) {
+				logger.error('Invalid request: expired code.', { code });
 				throw new FastifyReplyError(400, 'EXPIRED');
 			}
 
@@ -274,8 +305,10 @@ export class SignupApiService {
 				});
 			}
 
+			logger.info('Successfully created user.', { userId: account.id });
 			return this.signinService.signin(request, reply, account as MiLocalUser);
 		} catch (err) {
+			logger.error('Failed to complete creating user account.', { error: err });
 			throw new FastifyReplyError(400, typeof err === 'string' ? err : (err as Error).toString());
 		}
 	}

packages/backend/src/server/api/endpoints/federation/instances.ts

@@ -7,6 +7,7 @@ import { Inject, Injectable } from '@nestjs/common';
 import { Endpoint } from '@/server/api/endpoint-base.js';
 import type { InstancesRepository } from '@/models/_.js';
 import { InstanceEntityService } from '@/core/entities/InstanceEntityService.js';
+import { LoggerService } from '@/core/LoggerService.js';
 import { MetaService } from '@/core/MetaService.js';
 import { DI } from '@/di-symbols.js';
 import { sqlLikeEscape } from '@/misc/sql-like-escape.js';
@@ -73,10 +74,15 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 		@Inject(DI.instancesRepository)
 		private instancesRepository: InstancesRepository,
 
-		private instanceEntityService: InstanceEntityService,
 		private metaService: MetaService,
+		private loggerService: LoggerService,
+		private instanceEntityService: InstanceEntityService,
 	) {
-		super(meta, paramDef, async (ps, me) => {
+		super(meta, paramDef, async (ps, me, _token, _file, _cleanup, ip, headers) => {
+			const logger = this.loggerService.getLogger('api:federation:instances');
+			logger.setContext({ params: ps, user: me?.id, ip, headers });
+			logger.info('Requested to fetch federated instances.');
+
 			const query = this.instancesRepository.createQueryBuilder('instance');
 
 			switch (ps.sort) {
@@ -169,6 +175,7 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 			}
 
 			const instances = await query.limit(ps.limit).offset(ps.offset).getMany();
+			logger.info('Fetched federated instances.', { count: instances.length });
 
 			return await this.instanceEntityService.packMany(instances);
 		});

packages/backend/src/server/api/endpoints/notes/create.ts

@@ -20,6 +20,7 @@ import { NoteCreateService } from '@/core/NoteCreateService.js';
 import { DI } from '@/di-symbols.js';
 import { isPureRenote } from '@/misc/is-pure-renote.js';
 import { IdentifiableError } from '@/misc/identifiable-error.js';
+import { LoggerService } from '@/core/LoggerService.js';
 import { ApiError } from '../../error.js';
 
 export const meta = {
@@ -239,19 +240,30 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 		@Inject(DI.channelsRepository)
 		private channelsRepository: ChannelsRepository,
 
+		private loggerService: LoggerService,
 		private noteEntityService: NoteEntityService,
 		private noteCreateService: NoteCreateService,
 	) {
-		super(meta, paramDef, async (ps, me) => {
+		super(meta, paramDef, async (ps, me, _token, _file, _cleanup, ip, headers) => {
+			const logger = this.loggerService.getLogger('api:notes:create');
 			const hash = createHash('sha256').update(JSON.stringify(ps)).digest('base64');
+			logger.setContext({ userId: me.id, hash, ip, headers });
+			logger.info('Requested to create a note.');
+
 			const idempotent = process.env.FORCE_IGNORE_IDEMPOTENCY_FOR_TESTING !== 'true' ? await this.redisForTimelines.get(`note:idempotent:${me.id}:${hash}`) : null;
-			if (idempotent === '_') throw new ApiError(meta.errors.processing); // 他のサーバーで処理中
+			if (idempotent === '_') { // 他のサーバーで処理中
+				logger.warn('The request is being processed by another server.');
+				throw new ApiError(meta.errors.processing);
+			}
 
 			// すでに同じリクエストが処理されている場合、そのノートを返す
 			// ただし、記録されているノート見つからない場合は、新規として処理を続行
 			if (idempotent) {
 				const note = await this.notesRepository.findOneBy({ id: idempotent });
-				if (note) return { createdNote: await this.noteEntityService.pack(note, me) };
+				if (note) {
+					logger.info('The request has already been processed.', { noteId: note.id });
+					return { createdNote: await this.noteEntityService.pack(note, me) };
+				}
 			}
 
 			// 30秒の間、リクエストを処理中として記録
@@ -277,6 +289,7 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 					.getMany();
 
 				if (files.length !== fileIds.length) {
+					logger.error('Some files are not found.', { missingFileIds: fileIds.filter(id => !files.some(file => file.id === id)) });
 					throw new ApiError(meta.errors.noSuchFile);
 				}
 			}
@@ -287,8 +300,10 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 				renote = await this.notesRepository.findOneBy({ id: ps.renoteId });
 
 				if (renote == null) {
+					logger.error('No such renote target.', { renoteId: ps.renoteId });
 					throw new ApiError(meta.errors.noSuchRenoteTarget);
 				} else if (isPureRenote(renote)) {
+					logger.error('Cannot Renote a pure Renote.', { renoteId: ps.renoteId });
 					throw new ApiError(meta.errors.cannotReRenote);
 				}
 
@@ -301,15 +316,18 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 						},
 					});
 					if (blockExist) {
+						logger.error('User has been blocked by the user who wrote the note.', { renoteUserId: renote.userId });
 						throw new ApiError(meta.errors.youHaveBeenBlocked);
 					}
 				}
 
 				if (renote.visibility === 'followers' && renote.userId !== me.id) {
 					// 他人のfollowers noteはreject
+					logger.error('Cannot Renote due to target visibility.', { renoteId: ps.renoteId, renoteVisibility: renote.visibility });
 					throw new ApiError(meta.errors.cannotRenoteDueToVisibility);
 				} else if (renote.visibility === 'specified') {
 					// specified / direct noteはreject
+					logger.error('Cannot Renote due to target visibility.', { renoteId: ps.renoteId, renoteVisibility: renote.visibility });
 					throw new ApiError(meta.errors.cannotRenoteDueToVisibility);
 				}
 
@@ -319,9 +337,11 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 					const renoteChannel = await this.channelsRepository.findOneBy({ id: renote.channelId });
 					if (renoteChannel == null) {
 						// リノートしたいノートが書き込まれているチャンネルが無い
+						logger.error('No such channel.', { channelId: renote.channelId });
 						throw new ApiError(meta.errors.noSuchChannel);
 					} else if (!renoteChannel.allowRenoteToExternal) {
 						// リノート作成のリクエストだが、対象チャンネルがリノート禁止だった場合
+						logger.error('Cannot renote outside of channel.', { channelId: renote.channelId });
 						throw new ApiError(meta.errors.cannotRenoteOutsideOfChannel);
 					}
 				}
@@ -333,10 +353,13 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 				reply = await this.notesRepository.findOneBy({ id: ps.replyId });
 
 				if (reply == null) {
+					logger.error('No such reply target.', { replyId: ps.replyId });
 					throw new ApiError(meta.errors.noSuchReplyTarget);
 				} else if (isPureRenote(reply)) {
+					logger.error('Cannot reply to a pure Renote.', { replyId: ps.replyId });
 					throw new ApiError(meta.errors.cannotReplyToPureRenote);
 				} else if (!await this.noteEntityService.isVisibleForMe(reply, me.id)) {
+					logger.error('Cannot reply to an invisible Note.', { replyId: ps.replyId });
 					throw new ApiError(meta.errors.cannotReplyToInvisibleNote);
 				}
 
@@ -349,6 +372,7 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 						},
 					});
 					if (blockExist) {
+						logger.error('User has been blocked by the user who wrote the note.', { replyUserId: reply.userId });
 						throw new ApiError(meta.errors.youHaveBeenBlocked);
 					}
 				}
@@ -357,6 +381,7 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 			if (ps.poll) {
 				if (typeof ps.poll.expiresAt === 'number') {
 					if (ps.poll.expiresAt < Date.now()) {
+						logger.error('Poll is already expired.', { expiresAt: ps.poll.expiresAt });
 						throw new ApiError(meta.errors.cannotCreateAlreadyExpiredPoll);
 					}
 				} else if (typeof ps.poll.expiredAfter === 'number') {
@@ -369,6 +394,7 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 				channel = await this.channelsRepository.findOneBy({ id: ps.channelId, isArchived: false });
 
 				if (channel == null) {
+					logger.error('No such channel.', { channelId: ps.channelId });
 					throw new ApiError(meta.errors.noSuchChannel);
 				}
 			}
@@ -400,6 +426,7 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 				// 1分間、リクエストの処理結果を記録
 				await this.redisForTimelines.set(`note:idempotent:${me.id}:${hash}`, note.id, 'EX', 60);
 
+				logger.info('Successfully created a note.', { noteId: note.id });
 				return {
 					createdNote: await this.noteEntityService.pack(note, me),
 				};
@@ -407,6 +434,8 @@ export default class extends Endpoint<typeof meta, typeof paramDef> { // eslint-
 				// エラーが発生した場合、リクエストの処理結果を削除
 				await this.redisForTimelines.unlink(`note:idempotent:${me.id}:${hash}`);
 
+				logger.error('Failed to create a note.', { error: err });
+
 				if (err instanceof IdentifiableError) {
 					if (err.id === '057d8d3e-b7ca-4f8b-b38c-dcdcbf34dc30') throw new ApiError(meta.errors.containsProhibitedWords);
 				}