add inbound activity logger for debugging

.config/ci.yml

@@ -263,12 +263,17 @@ checkActivityPubGetSignature: false
 #     # default: false
 #     disableQueryTruncation: false
 
-# Log settings
-# logging:
-#   sql:
-#     # Outputs query parameters during SQL execution to the log.
-#     # default: false
-#     enableQueryParamLogging: false
-#     # Disable query truncation. If set to true, the full text of the query will be output to the log.
-#     # default: false
-#     disableQueryTruncation: false
+# Settings for the activity logger, which records inbound activities to the database.
+# Disabled by default due to the large volume of data it saves.
+#activityLogging:
+  # Log activities to the database (default: false)
+  #enabled: false
+
+  # Save the activity before processing, then update later with the results.
+  # This has the advantage of capturing activities that cause a hard-crash, but doubles the number of queries used.
+  # Default: false
+  #preSave: false
+
+  # How long to save each log entry before deleting it.
+  # Default: 2592000000 (1 week)
+  #maxAge: 2592000000

.config/cypress-devcontainer.yml

@@ -272,3 +272,18 @@ allowedPrivateNetworks: [
 #     # Disable query truncation. If set to true, the full text of the query will be output to the log.
 #     # default: false
 #     disableQueryTruncation: false
+
+# Settings for the activity logger, which records inbound activities to the database.
+# Disabled by default due to the large volume of data it saves.
+#activityLogging:
+  # Log activities to the database (default: false)
+  #enabled: false
+
+  # Save the activity before processing, then update later with the results.
+  # This has the advantage of capturing activities that cause a hard-crash, but doubles the number of queries used.
+  # Default: false
+  #preSave: false
+
+  # How long to save each log entry before deleting it.
+  # Default: 2592000000 (1 week)
+  #maxAge: 2592000000

.config/docker_example.yml

@@ -345,3 +345,18 @@ checkActivityPubGetSignature: false
 #     # Disable query truncation. If set to true, the full text of the query will be output to the log.
 #     # default: false
 #     disableQueryTruncation: false
+
+# Settings for the activity logger, which records inbound activities to the database.
+# Disabled by default due to the large volume of data it saves.
+#activityLogging:
+  # Log activities to the database (default: false)
+  #enabled: false
+
+  # Save the activity before processing, then update later with the results.
+  # This has the advantage of capturing activities that cause a hard-crash, but doubles the number of queries used.
+  # Default: false
+  #preSave: false
+
+  # How long to save each log entry before deleting it.
+  # Default: 2592000000 (1 week)
+  #maxAge: 2592000000

.config/example.yml

@@ -383,3 +383,18 @@ checkActivityPubGetSignature: false
 #     # Disable query truncation. If set to true, the full text of the query will be output to the log.
 #     # default: false
 #     disableQueryTruncation: false
+
+# Settings for the activity logger, which records inbound activities to the database.
+# Disabled by default due to the large volume of data it saves.
+#activityLogging:
+  # Log activities to the database (default: false)
+  #enabled: false
+
+  # Save the activity before processing, then update later with the results.
+  # This has the advantage of capturing activities that cause a hard-crash, but doubles the number of queries used.
+  # Default: false
+  #preSave: false
+
+  # How long to save each log entry before deleting it.
+  # Default: 2592000000 (1 week)
+  #maxAge: 2592000000

packages/backend/migration/1731565470048-add-activity-log.js

@@ -0,0 +1,28 @@
+/*
+ * SPDX-FileCopyrightText: hazelnoot and other Sharkey contributors
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+export class AddActivityLog1731565470048 {
+    name = 'AddActivityLog1731565470048'
+
+    async up(queryRunner) {
+        await queryRunner.query(`CREATE TABLE "activity_context" ("md5" text NOT NULL, "json" jsonb NOT NULL, CONSTRAINT "PK_activity_context" PRIMARY KEY ("md5"))`);
+        await queryRunner.query(`CREATE INDEX "IDK_activity_context_md5" ON "activity_context" ("md5") `);
+        await queryRunner.query(`CREATE TABLE "activity_log" ("id" character varying(32) NOT NULL, "at" TIMESTAMP WITH TIME ZONE NOT NULL, "key_id" text NOT NULL, "host" text NOT NULL, "verified" boolean NOT NULL, "accepted" boolean NOT NULL, "result" text NOT NULL, "activity" jsonb NOT NULL, "context_hash" text, "auth_user_id" character varying(32), CONSTRAINT "PK_activity_log" PRIMARY KEY ("id"))`);
+        await queryRunner.query(`CREATE INDEX "IDX_activity_log_at" ON "activity_log" ("at") `);
+        await queryRunner.query(`CREATE INDEX "IDX_activity_log_host" ON "activity_log" ("host") `);
+        await queryRunner.query(`ALTER TABLE "activity_log" ADD CONSTRAINT "FK_activity_log_context_hash" FOREIGN KEY ("context_hash") REFERENCES "activity_context"("md5") ON DELETE CASCADE ON UPDATE NO ACTION`);
+        await queryRunner.query(`ALTER TABLE "activity_log" ADD CONSTRAINT "FK_activity_log_auth_user_id" FOREIGN KEY ("auth_user_id") REFERENCES "user"("id") ON DELETE CASCADE ON UPDATE NO ACTION`);
+    }
+
+    async down(queryRunner) {
+        await queryRunner.query(`ALTER TABLE "activity_log" DROP CONSTRAINT "FK_activity_log_auth_user_id"`);
+        await queryRunner.query(`ALTER TABLE "activity_log" DROP CONSTRAINT "FK_activity_log_context_hash"`);
+        await queryRunner.query(`DROP INDEX "public"."IDX_activity_log_host"`);
+        await queryRunner.query(`DROP INDEX "public"."IDX_activity_log_at"`);
+        await queryRunner.query(`DROP TABLE "activity_log"`);
+        await queryRunner.query(`DROP INDEX "public"."IDK_activity_context_md5"`);
+        await queryRunner.query(`DROP TABLE "activity_context"`);
+		}
+}

packages/backend/src/boot/common.ts

@@ -13,6 +13,7 @@ import { ServerStatsService } from '@/daemons/ServerStatsService.js';
 import { ServerService } from '@/server/ServerService.js';
 import { MainModule } from '@/MainModule.js';
 import { envOption } from '@/env.js';
+import { ActivityLogCleanupService } from '@/daemons/ActivityLogCleanupService.js';
 
 export async function server() {
 	const app = await NestFactory.createApplicationContext(MainModule, {
@@ -28,6 +29,7 @@ export async function server() {
 	if (!envOption.noDaemons) {
 		app.get(QueueStatsService).start();
 		app.get(ServerStatsService).start();
+		app.get(ActivityLogCleanupService).start();
 	}
 
 	return app;

packages/backend/src/config.ts

@@ -129,6 +129,12 @@ type Source = {
 			enableQueryParamLogging? : boolean,
 		}
 	}
+
+	activityLogging?: {
+		enabled?: boolean;
+		preSave?: boolean;
+		maxAge?: number;
+	};
 };
 
 export type Config = {
@@ -238,6 +244,12 @@ export type Config = {
 
 	pidFile: string;
 	filePermissionBits?: string;
+
+	activityLogging: {
+		enabled: boolean;
+		preSave: boolean;
+		maxAge: number;
+	};
 };
 
 export type FulltextSearchProvider = 'sqlLike' | 'sqlPgroonga' | 'meilisearch';
@@ -380,6 +392,11 @@ export function loadConfig(): Config {
 		pidFile: config.pidFile,
 		filePermissionBits: config.filePermissionBits,
 		logging: config.logging,
+		activityLogging: {
+			enabled: config.activityLogging?.enabled ?? false,
+			preSave: config.activityLogging?.preSave ?? false,
+			maxAge: config.activityLogging?.maxAge ?? (1000 * 60 * 60 * 24 * 30),
+		},
 	};
 }
 
@@ -531,4 +548,5 @@ function applyEnvOverrides(config: Source) {
 	_apply_top(['import', ['downloadTimeout', 'maxFileSize']]);
 	_apply_top([['signToActivityPubGet', 'checkActivityPubGetSignature', 'setupPassword']]);
 	_apply_top(['logging', 'sql', ['disableQueryTruncation', 'enableQueryParamLogging']]);
+	_apply_top(['activityLogging', ['enabled', 'preSave', 'maxAge']]);
 }

packages/backend/src/daemons/ActivityLogCleanupService.ts

@@ -0,0 +1,64 @@
+/*
+ * SPDX-FileCopyrightText: hazelnoot and other Sharkey contributors
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import { Inject, Injectable, type OnApplicationShutdown } from '@nestjs/common';
+import { LessThan } from 'typeorm';
+import { DI } from '@/di-symbols.js';
+import type { Config } from '@/config.js';
+import { bindThis } from '@/decorators.js';
+import type { ActivityLogsRepository } from '@/models/_.js';
+
+// 10 minutes
+export const scanInterval = 1000 * 60 * 10;
+
+@Injectable()
+export class ActivityLogCleanupService implements OnApplicationShutdown {
+	private scanTimer: NodeJS.Timeout | null = null;
+
+	constructor(
+		@Inject(DI.config)
+		private readonly config: Config,
+
+		@Inject(DI.activityLogsRepository)
+		private readonly activityLogsRepository: ActivityLogsRepository,
+	) {}
+
+	@bindThis
+	public async start(): Promise<void> {
+		// Just in case start() gets called multiple times.
+		this.dispose();
+
+		// Prune at startup, in case the server was rebooted during the interval.
+		// noinspection ES6MissingAwait
+		this.tick();
+
+		// Prune on a regular interval for the lifetime of the server.
+		this.scanTimer = setInterval(this.tick, scanInterval);
+	}
+
+	@bindThis
+	private async tick(): Promise<void> {
+		// This is the date in UTC of the oldest log to KEEP
+		const oldestAllowed = new Date(Date.now() - this.config.activityLogging.maxAge);
+
+		// Delete all logs older than the threshold.
+		await this.activityLogsRepository.delete({
+			at: LessThan(oldestAllowed),
+		});
+	}
+
+	@bindThis
+	public onApplicationShutdown(): void {
+		this.dispose();
+	}
+
+	@bindThis
+	public dispose(): void {
+		if (this.scanTimer) {
+			clearInterval(this.scanTimer);
+			this.scanTimer = null;
+		}
+	}
+}

packages/backend/src/daemons/DaemonModule.ts

@@ -8,6 +8,7 @@ import { CoreModule } from '@/core/CoreModule.js';
 import { GlobalModule } from '@/GlobalModule.js';
 import { QueueStatsService } from './QueueStatsService.js';
 import { ServerStatsService } from './ServerStatsService.js';
+import { ActivityLogCleanupService } from './ActivityLogCleanupService.js';
 
 @Module({
 	imports: [
@@ -17,10 +18,12 @@ import { ServerStatsService } from './ServerStatsService.js';
 	providers: [
 		QueueStatsService,
 		ServerStatsService,
+		ActivityLogCleanupService,
 	],
 	exports: [
 		QueueStatsService,
 		ServerStatsService,
+		ActivityLogCleanupService,
 	],
 })
 export class DaemonModule {}

packages/backend/src/di-symbols.ts

@@ -22,6 +22,9 @@ export const DI = {
 	appsRepository: Symbol('appsRepository'),
 	avatarDecorationsRepository: Symbol('avatarDecorationsRepository'),
 	latestNotesRepository: Symbol('latestNotesRepository'),
+	activityContextRepository: Symbol('activityContextRepository'),
+	contextUsagesRepository: Symbol('contextUsagesRepository'),
+	activityLogsRepository: Symbol('activityLogsRepository'),
 	noteFavoritesRepository: Symbol('noteFavoritesRepository'),
 	noteThreadMutingsRepository: Symbol('noteThreadMutingsRepository'),
 	noteReactionsRepository: Symbol('noteReactionsRepository'),

packages/backend/src/models/RepositoryModule.ts

@@ -80,7 +80,9 @@ import {
 	MiUserPublickey,
 	MiUserSecurityKey,
 	MiWebhook,
-	NoteEdit
+	NoteEdit,
+	SkActivityContext,
+	SkActivityLog,
 } from './_.js';
 import type { DataSource } from 'typeorm';
 
@@ -126,6 +128,18 @@ const $latestNotesRepository: Provider = {
 	inject: [DI.db],
 };
 
+const $activityContextRepository: Provider = {
+	provide: DI.activityContextRepository,
+	useFactory: (db: DataSource) => db.getRepository(SkActivityContext).extend(miRepository as MiRepository<SkActivityContext>),
+	inject: [DI.db],
+};
+
+const $activityLogsRepository: Provider = {
+	provide: DI.activityLogsRepository,
+	useFactory: (db: DataSource) => db.getRepository(SkActivityLog).extend(miRepository as MiRepository<SkActivityLog>),
+	inject: [DI.db],
+};
+
 const $noteFavoritesRepository: Provider = {
 	provide: DI.noteFavoritesRepository,
 	useFactory: (db: DataSource) => db.getRepository(MiNoteFavorite).extend(miRepository as MiRepository<MiNoteFavorite>),
@@ -526,6 +540,8 @@ const $noteScheduleRepository: Provider = {
 		$appsRepository,
 		$avatarDecorationsRepository,
 		$latestNotesRepository,
+		$activityContextRepository,
+		$activityLogsRepository,
 		$noteFavoritesRepository,
 		$noteThreadMutingsRepository,
 		$noteReactionsRepository,
@@ -600,6 +616,8 @@ const $noteScheduleRepository: Provider = {
 		$appsRepository,
 		$avatarDecorationsRepository,
 		$latestNotesRepository,
+		$activityContextRepository,
+		$activityLogsRepository,
 		$noteFavoritesRepository,
 		$noteThreadMutingsRepository,
 		$noteReactionsRepository,

packages/backend/src/models/SkActivityContext.ts

@@ -0,0 +1,24 @@
+/*
+ * SPDX-FileCopyrightText: hazelnoot and other Sharkey contributors
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import { Column, PrimaryColumn, Entity, Index } from 'typeorm';
+
+@Entity('activity_context')
+export class SkActivityContext {
+	@PrimaryColumn('text')
+	@Index()
+	public md5: string;
+
+	@Column('jsonb')
+	// https://github.com/typeorm/typeorm/issues/8559
+	// eslint-disable-next-line @typescript-eslint/no-explicit-any
+	public json: any;
+
+	constructor(data?: Partial<SkActivityContext>) {
+		if (data) {
+			Object.assign(this, data);
+		}
+	}
+}

packages/backend/src/models/SkActivityLog.ts

@@ -0,0 +1,82 @@
+/*
+ * SPDX-FileCopyrightText: hazelnoot and other Sharkey contributors
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import { Column, Entity, Index, JoinColumn, ManyToOne, PrimaryColumn } from 'typeorm';
+import { SkActivityContext } from '@/models/SkActivityContext.js';
+import { MiUser } from '@/models/_.js';
+import { id } from './util/id.js';
+
+@Entity('activity_log')
+export class SkActivityLog {
+	@PrimaryColumn(id())
+	public id: string;
+
+	@Index()
+	@Column('timestamptz')
+	public at: Date;
+
+	@Column({
+		type: 'text',
+		name: 'key_id',
+	})
+	public keyId: string;
+
+	@Index()
+	@Column('text')
+	public host: string;
+
+	@Column('boolean')
+	public verified: boolean;
+
+	@Column('boolean')
+	public accepted: boolean;
+
+	@Column('text')
+	public result: string;
+
+	@Column('jsonb')
+	// https://github.com/typeorm/typeorm/issues/8559
+	// eslint-disable-next-line @typescript-eslint/no-explicit-any
+	public activity: any;
+
+	@Column({
+		type: 'text',
+		name: 'context_hash',
+		nullable: true,
+	})
+	public contextHash: string | null;
+
+	@ManyToOne(() => SkActivityContext, {
+		onDelete: 'CASCADE',
+		nullable: true,
+	})
+	@JoinColumn({
+		name: 'context_hash',
+	})
+	public context: SkActivityContext | null;
+
+	@Column({
+		type: 'varchar' as const,
+		length: 32,
+		name: 'auth_user_id',
+		nullable: true,
+	})
+	public authUserId: string | null;
+
+	@ManyToOne(() => MiUser, {
+		onDelete: 'CASCADE',
+		nullable: true,
+	})
+	@JoinColumn({
+		name: 'auth_user_id',
+	})
+	public authUser: MiUser | null;
+
+	constructor(data?: Partial<SkActivityLog>) {
+		if (data) {
+			Object.assign(this, data);
+		}
+	}
+}

packages/backend/src/models/_.ts

@@ -82,6 +82,8 @@ import { NoteEdit } from '@/models/NoteEdit.js';
 import { MiBubbleGameRecord } from '@/models/BubbleGameRecord.js';
 import { MiReversiGame } from '@/models/ReversiGame.js';
 import { MiNoteSchedule } from '@/models/NoteSchedule.js';
+import { SkActivityLog } from '@/models/SkActivityLog.js';
+import { SkActivityContext } from './SkActivityContext.js';
 import type { QueryDeepPartialEntity } from 'typeorm/query-builder/QueryPartialEntity.js';
 
 export interface MiRepository<T extends ObjectLiteral> {
@@ -129,6 +131,8 @@ export const miRepository = {
 
 export {
 	SkLatestNote,
+	SkActivityContext,
+	SkActivityLog,
 	MiAbuseUserReport,
 	MiAbuseReportNotificationRecipient,
 	MiAccessToken,
@@ -229,6 +233,8 @@ export type HashtagsRepository = Repository<MiHashtag> & MiRepository<MiHashtag>
 export type InstancesRepository = Repository<MiInstance> & MiRepository<MiInstance>;
 export type MetasRepository = Repository<MiMeta> & MiRepository<MiMeta>;
 export type LatestNotesRepository = Repository<SkLatestNote> & MiRepository<SkLatestNote>;
+export type ActivityContextRepository = Repository<SkActivityContext> & MiRepository<SkActivityContext>;
+export type ActivityLogsRepository = Repository<SkActivityLog> & MiRepository<SkActivityLog>;
 export type ModerationLogsRepository = Repository<MiModerationLog> & MiRepository<MiModerationLog>;
 export type MutingsRepository = Repository<MiMuting> & MiRepository<MiMuting>;
 export type RenoteMutingsRepository = Repository<MiRenoteMuting> & MiRepository<MiRenoteMuting>;

packages/backend/src/postgres.ts

@@ -85,6 +85,8 @@ import { Config } from '@/config.js';
 import MisskeyLogger from '@/logger.js';
 import { bindThis } from '@/decorators.js';
 import { SkLatestNote } from '@/models/LatestNote.js';
+import { SkActivityContext } from '@/models/SkActivityContext.js';
+import { SkActivityLog } from '@/models/SkActivityLog.js';
 
 pg.types.setTypeParser(20, Number);
 
@@ -171,6 +173,8 @@ class MyCustomLogger implements Logger {
 
 export const entities = [
 	SkLatestNote,
+	SkActivityContext,
+	SkActivityLog,
 	MiAnnouncement,
 	MiAnnouncementRead,
 	MiMeta,

packages/backend/src/queue/processors/InboxProcessorService.ts

@@ -4,6 +4,7 @@
  */
 
 import { URL } from 'node:url';
+import { createHash } from 'crypto';
 import { Inject, Injectable, OnApplicationShutdown } from '@nestjs/common';
 import httpSignature from '@peertube/http-signature';
 import * as Bull from 'bullmq';
@@ -29,6 +30,11 @@ import { CollapsedQueue } from '@/misc/collapsed-queue.js';
 import { MiNote } from '@/models/Note.js';
 import { MiMeta } from '@/models/Meta.js';
 import { DI } from '@/di-symbols.js';
+import { IdService } from '@/core/IdService.js';
+import { JsonValue } from '@/misc/json-value.js';
+import { SkActivityLog, SkActivityContext } from '@/models/_.js';
+import type { ActivityLogsRepository, ActivityContextRepository } from '@/models/_.js';
+import type { Config } from '@/config.js';
 import { QueueLoggerService } from '../QueueLoggerService.js';
 import type { InboxJobData } from '../types.js';
 
@@ -46,6 +52,9 @@ export class InboxProcessorService implements OnApplicationShutdown {
 		@Inject(DI.meta)
 		private meta: MiMeta,
 
+		@Inject(DI.config)
+		private config: Config,
+
 		private utilityService: UtilityService,
 		private apInboxService: ApInboxService,
 		private federatedInstanceService: FederatedInstanceService,
@@ -57,6 +66,13 @@ export class InboxProcessorService implements OnApplicationShutdown {
 		private apRequestChart: ApRequestChart,
 		private federationChart: FederationChart,
 		private queueLoggerService: QueueLoggerService,
+		private idService: IdService,
+
+		@Inject(DI.activityContextRepository)
+		private activityContextRepository: ActivityContextRepository,
+
+		@Inject(DI.activityLogsRepository)
+		private activityLogsRepository: ActivityLogsRepository,
 	) {
 		this.logger = this.queueLoggerService.logger.createSubLogger('inbox');
 		this.updateInstanceQueue = new CollapsedQueue(process.env.NODE_ENV !== 'test' ? 60 * 1000 * 5 : 0, this.collapseUpdateInstanceJobs, this.performUpdateInstance);
@@ -64,6 +80,42 @@ export class InboxProcessorService implements OnApplicationShutdown {
 
 	@bindThis
 	public async process(job: Bull.Job<InboxJobData>): Promise<string> {
+		if (this.config.activityLogging.enabled) {
+			return await this._processLogged(job);
+		} else {
+			return await this._process(job);
+		}
+	}
+
+	private async _processLogged(job: Bull.Job<InboxJobData>): Promise<string> {
+		const payload = job.data.activity;
+		const keyId = job.data.signature.keyId;
+		const log = this.createLog(payload, keyId);
+
+		// Pre-save the activity in case it leads to a hard-crash.
+		if (this.config.activityLogging.preSave) {
+			await this.recordLog(log);
+		}
+
+		try {
+			const result = await this._process(job, log);
+
+			log.accepted = result.startsWith('ok');
+			log.result = result;
+
+			return result;
+		} catch (err) {
+			log.accepted = false;
+			log.result = String(err);
+
+			throw err;
+		} finally {
+			// Save or finalize asynchronously
+			this.recordLog(log).catch(err => this.logger.error('Failed to record AP activity:', err));
+		}
+	}
+
+	private async _process(job: Bull.Job<InboxJobData>, log?: SkActivityLog): Promise<string> {
 		const signature = job.data.signature;	// HTTP-signature
 		let activity = job.data.activity;
 
@@ -197,6 +249,13 @@ export class InboxProcessorService implements OnApplicationShutdown {
 			delete activity.id;
 		}
 
+		// Attach log to verified user
+		if (log) {
+			log.verified = true;
+			log.authUser = authUser.user;
+			log.authUserId = authUser.user.id;
+		}
+
 		this.apRequestChart.inbox();
 		this.federationChart.inbox(authUser.user.host);
 
@@ -292,4 +351,47 @@ export class InboxProcessorService implements OnApplicationShutdown {
 	async onApplicationShutdown(signal?: string) {
 		await this.dispose();
 	}
+
+	private createLog(payload: IActivity, keyId: string): SkActivityLog {
+		const activity = Object.assign({}, payload, { '@context': undefined }) as unknown as JsonValue;
+		const host = this.utilityService.extractDbHost(keyId);
+
+		const log = new SkActivityLog({
+			id: this.idService.gen(),
+			at: new Date(),
+			verified: false,
+			accepted: false,
+			result: 'not processed',
+			activity,
+			keyId,
+			host,
+		});
+
+		const context = payload['@context'];
+		if (context) {
+			const md5 = createHash('md5').update(JSON.stringify(context)).digest('base64');
+			log.contextHash = md5;
+			log.context = new SkActivityContext({
+				md5,
+				json: context,
+			});
+		}
+
+		return log;
+	}
+
+	private async recordLog(log: SkActivityLog): Promise<void> {
+		if (log.context) {
+			// https://stackoverflow.com/a/47064558
+			await this.activityContextRepository
+				.createQueryBuilder('context_body')
+				.insert()
+				.into(SkActivityContext)
+				.values(log.context)
+				.orIgnore('md5')
+				.execute();
+		}
+
+		await this.activityLogsRepository.upsert(log, ['id']);
+	}
 }