From 9835048a95ccd677a01214f3c9e29e1d88f2f6bd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E3=81=BE=E3=81=A3=E3=81=A1=E3=82=83=E3=81=A8=E3=83=BC?= =?UTF-8?q?=E3=81=AB=E3=82=85?= <17376330+u1-liquid@users.noreply.github.com> Date: Fri, 16 Feb 2024 22:17:06 +0900 Subject: [PATCH] =?UTF-8?q?spec(backend):=20=E4=B8=80=E9=83=A8=E3=81=AE?= =?UTF-8?q?=E3=82=A8=E3=83=B3=E3=83=89=E3=83=9D=E3=82=A4=E3=83=B3=E3=83=88?= =?UTF-8?q?=E3=81=AB=E3=83=AD=E3=82=B0=E3=82=92=E8=BF=BD=E5=8A=A0=20(Missk?= =?UTF-8?q?eyIO#457)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- packages/backend/src/logger.ts | 5 +++ .../src/server/api/SigninApiService.ts | 23 +++++++++++- .../src/server/api/SignupApiService.ts | 33 +++++++++++++++++ .../api/endpoints/federation/instances.ts | 11 ++++-- .../src/server/api/endpoints/notes/create.ts | 35 +++++++++++++++++-- 5 files changed, 101 insertions(+), 6 deletions(-) diff --git a/packages/backend/src/logger.ts b/packages/backend/src/logger.ts index 34b5368516..21711e6a78 100644 --- a/packages/backend/src/logger.ts +++ b/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): void { + this.logger = this.logger.child({ context }); + } + @bindThis public error(x: string | Error, context?: Record | null, important = false): void { // 実行を継続できない状況で使う if (context === null) context = undefined; diff --git a/packages/backend/src/server/api/SigninApiService.ts b/packages/backend/src/server/api/SigninApiService.ts index edac9b3beb..c671d42932 100644 --- a/packages/backend/src/server/api/SigninApiService.ts +++ b/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; } diff --git a/packages/backend/src/server/api/SignupApiService.ts b/packages/backend/src/server/api/SignupApiService.ts index 546de48e6b..2b2ece6c46 100644 --- a/packages/backend/src/server/api/SignupApiService.ts +++ b/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()); } } diff --git a/packages/backend/src/server/api/endpoints/federation/instances.ts b/packages/backend/src/server/api/endpoints/federation/instances.ts index ac0968d1b1..24aa4f7d10 100644 --- a/packages/backend/src/server/api/endpoints/federation/instances.ts +++ b/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 { // 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 { // 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); }); diff --git a/packages/backend/src/server/api/endpoints/notes/create.ts b/packages/backend/src/server/api/endpoints/notes/create.ts index aedc3497ac..3f43ed6b03 100644 --- a/packages/backend/src/server/api/endpoints/notes/create.ts +++ b/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 { // 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 { // 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 { // 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 { // 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 { // 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 { // 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 { // 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 { // 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 { // 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 { // 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 { // 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); }