Compare commits

...

23 commits

Author SHA1 Message Date
tamaina a7ec9241ab stackいじらない 2024-03-05 18:37:19 +00:00
tamaina a84cbeb155 remove pino 2024-03-05 18:26:45 +00:00
tamaina 285c8ab334 logger.tsを戻す 2024-03-05 18:24:46 +00:00
tamaina 40781f56e7 fix? 2024-03-04 14:17:40 +00:00
tamaina 973d18a552 !envOption.logJson 2024-03-04 14:16:14 +00:00
tamaina 78238d427a stringify inbox data 2024-03-04 14:04:10 +00:00
tamaina 1433a7aecf err, data 2024-03-04 13:49:30 +00:00
tamaina b42577e3ad trimはやめる 2024-03-04 13:46:51 +00:00
tamaina 493829b3ee truncate stack 2024-03-04 13:44:21 +00:00
tamaina 7ce4a26970 force show stack 2024-03-04 13:43:51 +00:00
tamaina 1f79cd1760 🎨 2024-03-04 13:03:41 +00:00
まっちゃとーにゅ 8e55285e48 chore(logging): severityフィールドがログに出てくる問題を修正 (MisskeyIO#431) 2024-03-04 12:41:17 +00:00
まっちゃとーにゅ 198d38431a spec(backend): severityのラベルをJSON形式のログに追加 (MisskeyIO#425) 2024-03-04 12:40:55 +00:00
tamaina c8fe7b337e add pino pinp-pretty 2024-03-04 12:40:32 +00:00
まっちゃとーにゅ a7e3f6c1a9 enhance(logging): ログの処理をpinoに置き換える (MisskeyIO#364) 2024-03-04 12:39:49 +00:00
まっちゃとーにゅ 670d509696 fix: MK_LOG_JSONのcontextの値が正常に表示されない問題を修正 (MisskeyIO#347)
fix bug from MisskeyIO#346
2024-03-04 12:31:29 +00:00
まっちゃとーにゅ ec914d9f0c feat(logging): JSON形式の構造化ログでログを出力できるように (MisskeyIO#346) 2024-03-04 12:31:11 +00:00
tamaina 18f13cea98 エラーを先に表示する 2024-03-04 12:18:16 +00:00
tamaina d803ec3e3e compact: false 2024-03-04 12:16:44 +00:00
tamaina d84a5767bf force one-line log (queue processor) 2024-03-04 12:07:03 +00:00
tamaina 84a6877f57 failed((${err.message})) 2024-03-04 11:44:03 +00:00
tamaina c9ff8d0624 🎨 2024-03-04 11:35:46 +00:00
tamaina f7e8862d28 enhance(backend): loggerでデータの表示にutil.inspectを使用する 2024-03-04 11:32:08 +00:00
7 changed files with 69 additions and 41 deletions

View file

@ -28,7 +28,7 @@ const bootLogger = logger.createSubLogger('boot', 'magenta', false);
const themeColor = chalk.hex('#86b300'); const themeColor = chalk.hex('#86b300');
function greet() { function greet() {
if (!envOption.quiet) { if (!envOption.quiet && !envOption.logJson) {
//#region Misskey logo //#region Misskey logo
const v = `v${meta.version}`; const v = `v${meta.version}`;
console.log(themeColor(' _____ _ _ ')); console.log(themeColor(' _____ _ _ '));
@ -46,7 +46,7 @@ function greet() {
} }
bootLogger.info('Welcome to Misskey!'); bootLogger.info('Welcome to Misskey!');
bootLogger.info(`Misskey v${meta.version}`, null, true); bootLogger.info(`Misskey v${meta.version}`, { version: meta.version, hostname: os.hostname(), pid: process.pid }, true);
} }
/** /**

View file

@ -16,6 +16,6 @@ export class LoggerService {
@bindThis @bindThis
public getLogger(domain: string, color?: KEYWORD | undefined, store?: boolean) { public getLogger(domain: string, color?: KEYWORD | undefined, store?: boolean) {
return new Logger(domain, color, store); return new Logger(domain);
} }
} }

View file

@ -9,6 +9,7 @@ const envOption = {
noDaemons: false, noDaemons: false,
disableClustering: false, disableClustering: false,
verbose: false, verbose: false,
logJson: false,
withLogTime: false, withLogTime: false,
quiet: false, quiet: false,
}; };

View file

@ -50,6 +50,19 @@ export default class Logger {
return; return;
} }
if (envOption.logJson) {
console.log(JSON.stringify({
time: new Date().toISOString(),
level: level,
message: message,
data: data,
important: important,
context: [this.context].concat(subContexts).join('.'),
cluster: cluster.isPrimary ? 'primary' : `worker-${cluster.worker!.id}`,
}));
return;
}
const time = dateFormat(new Date(), 'HH:mm:ss'); const time = dateFormat(new Date(), 'HH:mm:ss');
const worker = cluster.isPrimary ? '*' : cluster.worker!.id; const worker = cluster.isPrimary ? '*' : cluster.worker!.id;
const l = const l =

View file

@ -80,8 +80,9 @@ import { MiBubbleGameRecord } from '@/models/BubbleGameRecord.js';
import { MiReversiGame } from '@/models/ReversiGame.js'; import { MiReversiGame } from '@/models/ReversiGame.js';
import { Config } from '@/config.js'; import { Config } from '@/config.js';
import MisskeyLogger from '@/logger.js';
import { bindThis } from '@/decorators.js'; import { bindThis } from '@/decorators.js';
import { envOption } from './env.js';
import MisskeyLogger from '@/logger.js';
export const dbLogger = new MisskeyLogger('db'); export const dbLogger = new MisskeyLogger('db');
@ -90,6 +91,8 @@ const sqlLogger = dbLogger.createSubLogger('sql', 'gray', false);
class MyCustomLogger implements Logger { class MyCustomLogger implements Logger {
@bindThis @bindThis
private highlight(sql: string) { private highlight(sql: string) {
if (envOption.logJson) return sql;
return highlight.highlight(sql, { return highlight.highlight(sql, {
language: 'sql', ignoreIllegals: true, language: 'sql', ignoreIllegals: true,
}); });
@ -97,7 +100,7 @@ class MyCustomLogger implements Logger {
@bindThis @bindThis
public logQuery(query: string, parameters?: any[]) { public logQuery(query: string, parameters?: any[]) {
sqlLogger.info(this.highlight(query).substring(0, 100)); sqlLogger.debug(this.highlight(query));
} }
@bindThis @bindThis

View file

@ -9,6 +9,7 @@ import type { Config } from '@/config.js';
import { DI } from '@/di-symbols.js'; import { DI } from '@/di-symbols.js';
import type Logger from '@/logger.js'; import type Logger from '@/logger.js';
import { bindThis } from '@/decorators.js'; import { bindThis } from '@/decorators.js';
import { envOption } from '@/env.js';
import { WebhookDeliverProcessorService } from './processors/WebhookDeliverProcessorService.js'; import { WebhookDeliverProcessorService } from './processors/WebhookDeliverProcessorService.js';
import { EndedPollNotificationProcessorService } from './processors/EndedPollNotificationProcessorService.js'; import { EndedPollNotificationProcessorService } from './processors/EndedPollNotificationProcessorService.js';
import { DeliverProcessorService } from './processors/DeliverProcessorService.js'; import { DeliverProcessorService } from './processors/DeliverProcessorService.js';
@ -41,6 +42,7 @@ import { CleanProcessorService } from './processors/CleanProcessorService.js';
import { AggregateRetentionProcessorService } from './processors/AggregateRetentionProcessorService.js'; import { AggregateRetentionProcessorService } from './processors/AggregateRetentionProcessorService.js';
import { QueueLoggerService } from './QueueLoggerService.js'; import { QueueLoggerService } from './QueueLoggerService.js';
import { QUEUE, baseQueueOptions } from './const.js'; import { QUEUE, baseQueueOptions } from './const.js';
import type { InboxJobData } from './types.js';
// ref. https://github.com/misskey-dev/misskey/pull/7635#issue-971097019 // ref. https://github.com/misskey-dev/misskey/pull/7635#issue-971097019
function httpRelatedBackoff(attemptsMade: number) { function httpRelatedBackoff(attemptsMade: number) {
@ -68,13 +70,31 @@ function getJobInfo(job: Bull.Job | undefined, increment = false): string {
return `id=${job.id} attempts=${currentAttempts}/${maxAttempts} age=${formated}`; return `id=${job.id} attempts=${currentAttempts}/${maxAttempts} age=${formated}`;
} }
function renderError(e: Error): any {
if (e) { // 何故かeがundefinedで来ることがある
return {
...Object.getOwnPropertyNames(e).reduce((acc, key) => {
//@ts-expect-error Element implicitly has an 'any' type because expression of type 'string' can't be used to index type 'Error'.
acc[key] = e[key];
return acc;
}, {} as Record<string, any>),
};
} else {
return {
stack: '?',
message: '?',
name: '?',
};
}
}
@Injectable() @Injectable()
export class QueueProcessorService implements OnApplicationShutdown { export class QueueProcessorService implements OnApplicationShutdown {
private logger: Logger; private logger: Logger;
private systemQueueWorker: Bull.Worker; private systemQueueWorker: Bull.Worker;
private dbQueueWorker: Bull.Worker; private dbQueueWorker: Bull.Worker;
private deliverQueueWorker: Bull.Worker; private deliverQueueWorker: Bull.Worker;
private inboxQueueWorker: Bull.Worker; private inboxQueueWorker: Bull.Worker<InboxJobData>;
private webhookDeliverQueueWorker: Bull.Worker; private webhookDeliverQueueWorker: Bull.Worker;
private relationshipQueueWorker: Bull.Worker; private relationshipQueueWorker: Bull.Worker;
private objectStorageQueueWorker: Bull.Worker; private objectStorageQueueWorker: Bull.Worker;
@ -118,22 +138,6 @@ export class QueueProcessorService implements OnApplicationShutdown {
) { ) {
this.logger = this.queueLoggerService.logger; this.logger = this.queueLoggerService.logger;
function renderError(e: Error): any {
if (e) { // 何故かeがundefinedで来ることがある
return {
stack: e.stack,
message: e.message,
name: e.name,
};
} else {
return {
stack: '?',
message: '?',
name: '?',
};
}
}
//#region system //#region system
this.systemQueueWorker = new Bull.Worker(QUEUE.SYSTEM, (job) => { this.systemQueueWorker = new Bull.Worker(QUEUE.SYSTEM, (job) => {
switch (job.name) { switch (job.name) {
@ -155,8 +159,8 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.systemQueueWorker this.systemQueueWorker
.on('active', (job) => systemLogger.debug(`active id=${job.id}`)) .on('active', (job) => systemLogger.debug(`active id=${job.id}`))
.on('completed', (job, result) => systemLogger.debug(`completed(${result}) id=${job.id}`)) .on('completed', (job, result) => systemLogger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => systemLogger.warn(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) })) .on('failed', (job, err) => systemLogger.warn(`failed(${err.message}) id=${job ? job.id : '-'}`, { err: renderError(err), data: job?.data }))
.on('error', (err: Error) => systemLogger.error(`error ${err.stack}`, { e: renderError(err) })) .on('error', (err: Error) => systemLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => systemLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => systemLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion
@ -194,8 +198,8 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.dbQueueWorker this.dbQueueWorker
.on('active', (job) => dbLogger.debug(`active id=${job.id}`)) .on('active', (job) => dbLogger.debug(`active id=${job.id}`))
.on('completed', (job, result) => dbLogger.debug(`completed(${result}) id=${job.id}`)) .on('completed', (job, result) => dbLogger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => dbLogger.warn(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) })) .on('failed', (job, err) => dbLogger.warn(`failed(${err.message}) id=${job ? job.id : '-'}`, { err: renderError(err), job }))
.on('error', (err: Error) => dbLogger.error(`error ${err.stack}`, { e: renderError(err) })) .on('error', (err: Error) => dbLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => dbLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => dbLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion
@ -218,8 +222,8 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.deliverQueueWorker this.deliverQueueWorker
.on('active', (job) => deliverLogger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`)) .on('active', (job) => deliverLogger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`))
.on('completed', (job, result) => deliverLogger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`)) .on('completed', (job, result) => deliverLogger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`))
.on('failed', (job, err) => deliverLogger.warn(`failed(${err.stack}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`)) .on('failed', (job, err) => deliverLogger.warn(`failed(${err.message}) ${getJobInfo(job)} id=${job ? job.id : '-'} to=${job?.data.to}`, { err: renderError(err), data: job?.data }))
.on('error', (err: Error) => deliverLogger.error(`error ${err.stack}`, { e: renderError(err) })) .on('error', (err: Error) => deliverLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => deliverLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => deliverLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion
@ -242,8 +246,11 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.inboxQueueWorker this.inboxQueueWorker
.on('active', (job) => inboxLogger.debug(`active ${getJobInfo(job, true)}`)) .on('active', (job) => inboxLogger.debug(`active ${getJobInfo(job, true)}`))
.on('completed', (job, result) => inboxLogger.debug(`completed(${result}) ${getJobInfo(job, true)}`)) .on('completed', (job, result) => inboxLogger.debug(`completed(${result}) ${getJobInfo(job, true)}`))
.on('failed', (job, err) => inboxLogger.warn(`failed(${err.stack}) ${getJobInfo(job)} activity=${job ? (job.data.activity ? job.data.activity.id : 'none') : '-'}`, { job, e: renderError(err) })) .on('failed', (job, err) => inboxLogger.warn(
.on('error', (err: Error) => inboxLogger.error(`error ${err.stack}`, { e: renderError(err) })) `failed(${err.message}) ${getJobInfo(job)} activity=${job ? (job.data.activity ? job.data.activity.id : 'none') : '-'}`,
{ err: renderError(err), data: (job && !envOption.logJson) ? { activity: JSON.stringify(job.data.activity), signature: JSON.stringify(job.data.signature) } : null },
))
.on('error', (err: Error) => inboxLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => inboxLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => inboxLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion
@ -266,8 +273,8 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.webhookDeliverQueueWorker this.webhookDeliverQueueWorker
.on('active', (job) => webhookLogger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`)) .on('active', (job) => webhookLogger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`))
.on('completed', (job, result) => webhookLogger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`)) .on('completed', (job, result) => webhookLogger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`))
.on('failed', (job, err) => webhookLogger.warn(`failed(${err.stack}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`)) .on('failed', (job, err) => webhookLogger.warn(`failed(${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`, { err: renderError(err) }))
.on('error', (err: Error) => webhookLogger.error(`error ${err.stack}`, { e: renderError(err) })) .on('error', (err: Error) => webhookLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => webhookLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => webhookLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion
@ -295,8 +302,8 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.relationshipQueueWorker this.relationshipQueueWorker
.on('active', (job) => relationshipLogger.debug(`active id=${job.id}`)) .on('active', (job) => relationshipLogger.debug(`active id=${job.id}`))
.on('completed', (job, result) => relationshipLogger.debug(`completed(${result}) id=${job.id}`)) .on('completed', (job, result) => relationshipLogger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => relationshipLogger.warn(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) })) .on('failed', (job, err) => relationshipLogger.warn(`failed(${err.message}) id=${job ? job.id : '-'}`, { err: renderError(err), job }))
.on('error', (err: Error) => relationshipLogger.error(`error ${err.stack}`, { e: renderError(err) })) .on('error', (err: Error) => relationshipLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => relationshipLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => relationshipLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion
@ -318,8 +325,8 @@ export class QueueProcessorService implements OnApplicationShutdown {
this.objectStorageQueueWorker this.objectStorageQueueWorker
.on('active', (job) => objectStorageLogger.debug(`active id=${job.id}`)) .on('active', (job) => objectStorageLogger.debug(`active id=${job.id}`))
.on('completed', (job, result) => objectStorageLogger.debug(`completed(${result}) id=${job.id}`)) .on('completed', (job, result) => objectStorageLogger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => objectStorageLogger.warn(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) })) .on('failed', (job, err) => objectStorageLogger.warn(`failed(${err.message}) id=${job ? job.id : '-'}`, { err: renderError(err), job }))
.on('error', (err: Error) => objectStorageLogger.error(`error ${err.stack}`, { e: renderError(err) })) .on('error', (err: Error) => objectStorageLogger.error('error', { err: renderError(err) }))
.on('stalled', (jobId) => objectStorageLogger.warn(`stalled id=${jobId}`)); .on('stalled', (jobId) => objectStorageLogger.warn(`stalled id=${jobId}`));
//#endregion //#endregion

View file

@ -6646,7 +6646,7 @@ packages:
ts-dedent: 2.2.0 ts-dedent: 2.2.0
type-fest: 2.19.0 type-fest: 2.19.0
vue: 3.4.21(typescript@5.3.3) vue: 3.4.21(typescript@5.3.3)
vue-component-type-helpers: 1.8.27 vue-component-type-helpers: 2.0.5
transitivePeerDependencies: transitivePeerDependencies:
- encoding - encoding
- supports-color - supports-color
@ -11636,7 +11636,7 @@ packages:
fast-json-stringify: 5.8.0 fast-json-stringify: 5.8.0
find-my-way: 7.7.0 find-my-way: 7.7.0
light-my-request: 5.11.0 light-my-request: 5.11.0
pino: 8.17.0 pino: 8.19.0
process-warning: 3.0.0 process-warning: 3.0.0
proxy-addr: 2.0.7 proxy-addr: 2.0.7
rfdc: 1.3.0 rfdc: 1.3.0
@ -16037,8 +16037,8 @@ packages:
resolution: {integrity: sha512-KO0m2f1HkrPe9S0ldjx7za9BJjeHqBku5Ch8JyxETxT8dEFGz1PwgrHaOQupVYitpzbFSYm7nnljxD8dik2c+g==} resolution: {integrity: sha512-KO0m2f1HkrPe9S0ldjx7za9BJjeHqBku5Ch8JyxETxT8dEFGz1PwgrHaOQupVYitpzbFSYm7nnljxD8dik2c+g==}
dev: false dev: false
/pino@8.17.0: /pino@8.19.0:
resolution: {integrity: sha512-ey+Mku+PVPhvxglLXMg1l1zQMwSHuNrKC3MD40EDZbkckJmmuY7DYZLIOwwjZ8ix/Nvhe9dZt5H99cgkot9bAw==} resolution: {integrity: sha512-oswmokxkav9bADfJ2ifrvfHUwad6MLp73Uat0IkQWY3iAw5xTRoznXbXksZs8oaOUMpmhVWD+PZogNzllWpJaA==}
hasBin: true hasBin: true
dependencies: dependencies:
atomic-sleep: 1.0.0 atomic-sleep: 1.0.0
@ -16046,7 +16046,7 @@ packages:
on-exit-leak-free: 2.1.0 on-exit-leak-free: 2.1.0
pino-abstract-transport: 1.1.0 pino-abstract-transport: 1.1.0
pino-std-serializers: 6.1.0 pino-std-serializers: 6.1.0
process-warning: 2.2.0 process-warning: 3.0.0
quick-format-unescaped: 4.0.4 quick-format-unescaped: 4.0.4
real-require: 0.2.0 real-require: 0.2.0
safe-stable-stringify: 2.4.2 safe-stable-stringify: 2.4.2
@ -19445,6 +19445,10 @@ packages:
resolution: {integrity: sha512-6bnLkn8O0JJyiFSIF0EfCogzeqNXpnjJ0vW/SZzNHfe6sPx30lTtTXlE5TFs2qhJlAtDFybStVNpL73cPe3OMQ==} resolution: {integrity: sha512-6bnLkn8O0JJyiFSIF0EfCogzeqNXpnjJ0vW/SZzNHfe6sPx30lTtTXlE5TFs2qhJlAtDFybStVNpL73cPe3OMQ==}
dev: true dev: true
/vue-component-type-helpers@2.0.5:
resolution: {integrity: sha512-v9N4ufDSnd8YHcDq/vURPjxDyBVak5ZVAQ6aGNIrf7ZAj/VxRKpLZXFHEaqt9yHkWi0/TZp76Jmf8yNJxDQi4g==}
dev: true
/vue-demi@0.14.7(vue@3.4.21): /vue-demi@0.14.7(vue@3.4.21):
resolution: {integrity: sha512-EOG8KXDQNwkJILkx/gPcoL/7vH+hORoBaKgGe+6W7VFMvCYJfmF2dGbvgDroVnI8LU7/kTu8mbjRZGBU1z9NTA==} resolution: {integrity: sha512-EOG8KXDQNwkJILkx/gPcoL/7vH+hORoBaKgGe+6W7VFMvCYJfmF2dGbvgDroVnI8LU7/kTu8mbjRZGBU1z9NTA==}
engines: {node: '>=12'} engines: {node: '>=12'}