Better logging

This commit is contained in:
syuilo 2019-02-03 16:45:13 +09:00
parent ca91709801
commit 75558add17
No known key found for this signature in database
GPG key ID: BDC4C49D06AB9D69
11 changed files with 62 additions and 68 deletions

View file

@ -8,7 +8,6 @@ require('events').EventEmitter.defaultMaxListeners = 128;
import * as os from 'os'; import * as os from 'os';
import * as cluster from 'cluster'; import * as cluster from 'cluster';
import * as debug from 'debug';
import chalk from 'chalk'; import chalk from 'chalk';
import * as portscanner from 'portscanner'; import * as portscanner from 'portscanner';
import * as isRoot from 'is-root'; import * as isRoot from 'is-root';
@ -30,10 +29,6 @@ const bootLogger = logger.createSubLogger('boot', 'magenta');
const clusterLog = logger.createSubLogger('cluster', 'orange'); const clusterLog = logger.createSubLogger('cluster', 'orange');
const ev = new Xev(); const ev = new Xev();
if (process.env.NODE_ENV != 'production' && process.env.DEBUG == null) {
debug.enable('misskey');
}
//#region Command line argument definitions //#region Command line argument definitions
program program
.version(pkg.version) .version(pkg.version)

View file

@ -31,19 +31,24 @@ export default class Logger {
} }
public error(message: string | Error): void { // 実行を継続できない状況で使う public error(message: string | Error): void { // 実行を継続できない状況で使う
this.log(chalk.red.bold('ERROR'), chalk.red.bold(message.toString())); this.log(chalk.red('ERR '), chalk.red(message.toString()));
} }
public warn(message: string, important = false): void { // 実行を継続できるが改善すべき状況で使う public warn(message: string, important = false): void { // 実行を継続できるが改善すべき状況で使う
this.log(chalk.yellow.bold('WARN'), chalk.yellow.bold(message), important); this.log(chalk.yellow('WARN'), chalk.yellow(message), important);
} }
public succ(message: string, important = false): void { // 何かに成功した状況で使う public succ(message: string, important = false): void { // 何かに成功した状況で使う
this.log(chalk.blue.green('DONE'), chalk.green.bold(message), important); this.log(chalk.green('DONE'), chalk.green(message), important);
} }
public info(message: string, important = false): void { // それ以外 public info(message: string, important = false): void { // それ以外
this.log(chalk.blue.bold('INFO'), message, important); this.log(chalk.blue('INFO'), message, important);
} }
public debug(message: string, important = false): void { // デバッグ用に使う
if (process.env.NODE_ENV != 'production') {
this.log(chalk.gray('VERB'), chalk.gray(message), important);
}
}
} }

View file

@ -1,12 +1,11 @@
import * as debug from 'debug';
import uploadFromUrl from '../../../services/drive/upload-from-url'; import uploadFromUrl from '../../../services/drive/upload-from-url';
import { IRemoteUser } from '../../../models/user'; import { IRemoteUser } from '../../../models/user';
import DriveFile, { IDriveFile } from '../../../models/drive-file'; import DriveFile, { IDriveFile } from '../../../models/drive-file';
import Resolver from '../resolver'; import Resolver from '../resolver';
import fetchMeta from '../../../misc/fetch-meta'; import fetchMeta from '../../../misc/fetch-meta';
import { apLogger } from '../logger';
const log = debug('misskey:activitypub'); const logger = apLogger;
/** /**
* Imageを作成します * Imageを作成します
@ -23,7 +22,7 @@ export async function createImage(actor: IRemoteUser, value: any): Promise<IDriv
throw new Error('invalid image: url not privided'); throw new Error('invalid image: url not privided');
} }
log(`Creating the Image: ${image.url}`); logger.info(`Creating the Image: ${image.url}`);
const instance = await fetchMeta(); const instance = await fetchMeta();
const cache = instance.cacheRemoteFiles; const cache = instance.cacheRemoteFiles;

View file

@ -1,5 +1,4 @@
import * as mongo from 'mongodb'; import * as mongo from 'mongodb';
import * as debug from 'debug';
import config from '../../../config'; import config from '../../../config';
import Resolver from '../resolver'; import Resolver from '../resolver';
@ -16,8 +15,9 @@ import { toUnicode } from 'punycode';
import { unique, concat, difference } from '../../../prelude/array'; import { unique, concat, difference } from '../../../prelude/array';
import { extractPollFromQuestion } from './question'; import { extractPollFromQuestion } from './question';
import vote from '../../../services/note/polls/vote'; import vote from '../../../services/note/polls/vote';
import { apLogger } from '../logger';
const log = debug('misskey:activitypub'); const logger = apLogger;
/** /**
* Noteをフェッチします * Noteをフェッチします
@ -53,13 +53,13 @@ export async function createNote(value: any, resolver?: Resolver, silent = false
const object = await resolver.resolve(value) as any; const object = await resolver.resolve(value) as any;
if (object == null || object.type !== 'Note') { if (object == null || object.type !== 'Note') {
log(`invalid note: ${object}`); logger.error(`invalid note: ${object}`);
return null; return null;
} }
const note: INoteActivityStreamsObject = object; const note: INoteActivityStreamsObject = object;
log(`Creating the Note: ${note.id}`); logger.info(`Creating the Note: ${note.id}`);
// 投稿者をフェッチ // 投稿者をフェッチ
const actor = await resolvePerson(note.attributedTo, null, resolver) as IRemoteUser; const actor = await resolvePerson(note.attributedTo, null, resolver) as IRemoteUser;
@ -116,14 +116,14 @@ export async function createNote(value: any, resolver?: Resolver, silent = false
if (reply && reply.poll && text != null) { if (reply && reply.poll && text != null) {
const m = text.match(/([0-9])$/); const m = text.match(/([0-9])$/);
if (m) { if (m) {
log(`vote from AP: actor=${actor.username}@${actor.host}, note=${note.id}, choice=${m[0]}`); logger.info(`vote from AP: actor=${actor.username}@${actor.host}, note=${note.id}, choice=${m[0]}`);
await vote(actor, reply, Number(m[1])); await vote(actor, reply, Number(m[1]));
return null; return null;
} }
} }
const emojis = await extractEmojis(note.tag, actor.host).catch(e => { const emojis = await extractEmojis(note.tag, actor.host).catch(e => {
console.log(`extractEmojis: ${e}`); logger.info(`extractEmojis: ${e}`);
return [] as IEmoji[]; return [] as IEmoji[];
}); });
@ -215,7 +215,7 @@ export async function extractEmojis(tags: ITag[], host_: string) {
return exists; return exists;
} }
log(`register emoji host=${host}, name=${name}`); logger.info(`register emoji host=${host}, name=${name}`);
return await Emoji.insert({ return await Emoji.insert({
host, host,

View file

@ -1,6 +1,5 @@
import * as mongo from 'mongodb'; import * as mongo from 'mongodb';
import { toUnicode } from 'punycode'; import { toUnicode } from 'punycode';
import * as debug from 'debug';
import config from '../../../config'; import config from '../../../config';
import User, { validateUsername, isValidName, IUser, IRemoteUser, isRemoteUser } from '../../../models/user'; import User, { validateUsername, isValidName, IUser, IRemoteUser, isRemoteUser } from '../../../models/user';
@ -20,8 +19,9 @@ import { IEmoji } from '../../../models/emoji';
import { ITag, extractHashtags } from './tag'; import { ITag, extractHashtags } from './tag';
import Following from '../../../models/following'; import Following from '../../../models/following';
import { IIdentifier } from './identifier'; import { IIdentifier } from './identifier';
import { apLogger } from '../logger';
const log = debug('misskey:activitypub'); const logger = apLogger;
/** /**
* Validate Person object * Validate Person object
@ -119,7 +119,7 @@ export async function createPerson(uri: string, resolver?: Resolver): Promise<IU
const person: IPerson = object; const person: IPerson = object;
log(`Creating the Person: ${person.id}`); logger.info(`Creating the Person: ${person.id}`);
const [followersCount = 0, followingCount = 0, notesCount = 0] = await Promise.all([ const [followersCount = 0, followingCount = 0, notesCount = 0] = await Promise.all([
resolver.resolve(person.followers).then( resolver.resolve(person.followers).then(
@ -183,7 +183,7 @@ export async function createPerson(uri: string, resolver?: Resolver): Promise<IU
throw new Error('already registered'); throw new Error('already registered');
} }
console.error(e); logger.error(e);
throw e; throw e;
} }
@ -247,7 +247,7 @@ export async function createPerson(uri: string, resolver?: Resolver): Promise<IU
//#region カスタム絵文字取得 //#region カスタム絵文字取得
const emojis = await extractEmojis(person.tag, host).catch(e => { const emojis = await extractEmojis(person.tag, host).catch(e => {
console.log(`extractEmojis: ${e}`); logger.info(`extractEmojis: ${e}`);
return [] as IEmoji[]; return [] as IEmoji[];
}); });
@ -260,7 +260,7 @@ export async function createPerson(uri: string, resolver?: Resolver): Promise<IU
}); });
//#endregion //#endregion
await updateFeatured(user._id).catch(err => console.log(err)); await updateFeatured(user._id).catch(err => logger.error(err));
return user; return user;
} }
@ -300,7 +300,7 @@ export async function updatePerson(uri: string, resolver?: Resolver, hint?: obje
const person: IPerson = object; const person: IPerson = object;
log(`Updating the Person: ${person.id}`); logger.info(`Updating the Person: ${person.id}`);
const [followersCount = 0, followingCount = 0, notesCount = 0] = await Promise.all([ const [followersCount = 0, followingCount = 0, notesCount = 0] = await Promise.all([
resolver.resolve(person.followers).then( resolver.resolve(person.followers).then(
@ -329,7 +329,7 @@ export async function updatePerson(uri: string, resolver?: Resolver, hint?: obje
// カスタム絵文字取得 // カスタム絵文字取得
const emojis = await extractEmojis(person.tag, exist.host).catch(e => { const emojis = await extractEmojis(person.tag, exist.host).catch(e => {
console.log(`extractEmojis: ${e}`); logger.info(`extractEmojis: ${e}`);
return [] as IEmoji[]; return [] as IEmoji[];
}); });
@ -393,7 +393,7 @@ export async function updatePerson(uri: string, resolver?: Resolver, hint?: obje
multi: true multi: true
}); });
await updateFeatured(exist._id).catch(err => console.log(err)); await updateFeatured(exist._id).catch(err => logger.error(err));
} }
/** /**
@ -480,7 +480,7 @@ export async function updateFeatured(userId: mongo.ObjectID) {
if (!isRemoteUser(user)) return; if (!isRemoteUser(user)) return;
if (!user.featured) return; if (!user.featured) return;
log(`Updating the featured: ${user.uri}`); logger.info(`Updating the featured: ${user.uri}`);
const resolver = new Resolver(); const resolver = new Resolver();

View file

@ -1,11 +1,11 @@
import * as Limiter from 'ratelimiter'; import * as Limiter from 'ratelimiter';
import * as debug from 'debug';
import limiterDB from '../../db/redis'; import limiterDB from '../../db/redis';
import { IEndpoint } from './endpoints'; import { IEndpoint } from './endpoints';
import getAcct from '../../misc/acct/render'; import getAcct from '../../misc/acct/render';
import { IUser } from '../../models/user'; import { IUser } from '../../models/user';
import Logger from '../../misc/logger';
const log = debug('misskey:limiter'); const logger = new Logger('limiter');
export default (endpoint: IEndpoint, user: IUser) => new Promise((ok, reject) => { export default (endpoint: IEndpoint, user: IUser) => new Promise((ok, reject) => {
// Redisがインストールされてない場合は常に許可 // Redisがインストールされてない場合は常に許可
@ -49,7 +49,7 @@ export default (endpoint: IEndpoint, user: IUser) => new Promise((ok, reject) =>
return reject('ERR'); return reject('ERR');
} }
log(`@${getAcct(user)} ${endpoint.name} min remaining: ${info.remaining}`); logger.debug(`@${getAcct(user)} ${endpoint.name} min remaining: ${info.remaining}`);
if (info.remaining === 0) { if (info.remaining === 0) {
reject('BRIEF_REQUEST_INTERVAL'); reject('BRIEF_REQUEST_INTERVAL');
@ -77,7 +77,7 @@ export default (endpoint: IEndpoint, user: IUser) => new Promise((ok, reject) =>
return reject('ERR'); return reject('ERR');
} }
log(`@${getAcct(user)} ${endpoint.name} max remaining: ${info.remaining}`); logger.debug(`@${getAcct(user)} ${endpoint.name} max remaining: ${info.remaining}`);
if (info.remaining === 0) { if (info.remaining === 0) {
reject('RATE_LIMIT_EXCEEDED'); reject('RATE_LIMIT_EXCEEDED');

View file

@ -24,7 +24,7 @@ import { sum } from '../prelude/array';
import User from '../models/user'; import User from '../models/user';
import Logger from '../misc/logger'; import Logger from '../misc/logger';
const logger = new Logger('server'); const logger = new Logger('server', 'gray');
// Init app // Init app
const app = new Koa(); const app = new Koa();

View file

@ -24,6 +24,8 @@ import fetchMeta from '../../misc/fetch-meta';
import { GenerateVideoThumbnail } from './generate-video-thumbnail'; import { GenerateVideoThumbnail } from './generate-video-thumbnail';
import { driveLogger } from './logger'; import { driveLogger } from './logger';
const logger = driveLogger.createSubLogger('register', 'yellow');
/*** /***
* Save file * Save file
* @param path Path for original * @param path Path for original
@ -40,7 +42,7 @@ async function save(path: string, name: string, type: string, hash: string, size
let webpublicType = 'image/jpeg'; let webpublicType = 'image/jpeg';
if (!metadata.uri) { // from local instance if (!metadata.uri) { // from local instance
driveLogger.info(`creating web image of ${name}`); logger.info(`creating web image of ${name}`);
if (['image/jpeg'].includes(type)) { if (['image/jpeg'].includes(type)) {
webpublic = await sharp(path) webpublic = await sharp(path)
@ -81,10 +83,10 @@ async function save(path: string, name: string, type: string, hash: string, size
webpublicExt = 'png'; webpublicExt = 'png';
webpublicType = 'image/png'; webpublicType = 'image/png';
} else { } else {
driveLogger.info(`web image not created (not an image)`); logger.info(`web image not created (not an image)`);
} }
} else { } else {
driveLogger.info(`web image not created (from remote)`); logger.info(`web image not created (from remote)`);
} }
// #endregion webpublic // #endregion webpublic
@ -121,7 +123,7 @@ async function save(path: string, name: string, type: string, hash: string, size
try { try {
thumbnail = await GenerateVideoThumbnail(path); thumbnail = await GenerateVideoThumbnail(path);
} catch (e) { } catch (e) {
driveLogger.error(`GenerateVideoThumbnail failed: ${e}`); logger.error(`GenerateVideoThumbnail failed: ${e}`);
} }
} }
// #endregion thumbnail // #endregion thumbnail
@ -139,18 +141,18 @@ async function save(path: string, name: string, type: string, hash: string, size
const webpublicKey = `${config.drive.prefix}/${uuid.v4()}.${webpublicExt}`; const webpublicKey = `${config.drive.prefix}/${uuid.v4()}.${webpublicExt}`;
const thumbnailKey = `${config.drive.prefix}/${uuid.v4()}.${thumbnailExt}`; const thumbnailKey = `${config.drive.prefix}/${uuid.v4()}.${thumbnailExt}`;
driveLogger.info(`uploading original: ${key}`); logger.info(`uploading original: ${key}`);
const uploads = [ const uploads = [
upload(key, fs.createReadStream(path), type) upload(key, fs.createReadStream(path), type)
]; ];
if (webpublic) { if (webpublic) {
driveLogger.info(`uploading webpublic: ${webpublicKey}`); logger.info(`uploading webpublic: ${webpublicKey}`);
uploads.push(upload(webpublicKey, webpublic, webpublicType)); uploads.push(upload(webpublicKey, webpublic, webpublicType));
} }
if (thumbnail) { if (thumbnail) {
driveLogger.info(`uploading thumbnail: ${thumbnailKey}`); logger.info(`uploading thumbnail: ${thumbnailKey}`);
uploads.push(upload(thumbnailKey, thumbnail, thumbnailType)); uploads.push(upload(thumbnailKey, thumbnail, thumbnailType));
} }
@ -200,7 +202,7 @@ async function save(path: string, name: string, type: string, hash: string, size
fs.createReadStream(path).pipe(writeStream); fs.createReadStream(path).pipe(writeStream);
}); });
driveLogger.info(`original stored to ${originalFile._id}`); logger.info(`original stored to ${originalFile._id}`);
// #endregion store original // #endregion store original
// #region store webpublic // #region store webpublic
@ -220,7 +222,7 @@ async function save(path: string, name: string, type: string, hash: string, size
writeStream.end(webpublic); writeStream.end(webpublic);
}); });
driveLogger.info(`web stored ${webFile._id}`); logger.info(`web stored ${webFile._id}`);
} }
// #endregion store webpublic // #endregion store webpublic
@ -240,7 +242,7 @@ async function save(path: string, name: string, type: string, hash: string, size
writeStream.end(thumbnail); writeStream.end(thumbnail);
}); });
driveLogger.info(`thumbnail stored ${tuhmFile._id}`); logger.info(`thumbnail stored ${tuhmFile._id}`);
} }
return originalFile; return originalFile;
@ -349,7 +351,7 @@ export default async function(
const [hash, [mime, ext], size] = await Promise.all([calcHash, detectMime, getFileSize]); const [hash, [mime, ext], size] = await Promise.all([calcHash, detectMime, getFileSize]);
driveLogger.info(`hash: ${hash}, mime: ${mime}, ext: ${ext}, size: ${size}`); logger.info(`hash: ${hash}, mime: ${mime}, ext: ${ext}, size: ${size}`);
// detect name // detect name
const detectedName = name || (ext ? `untitled.${ext}` : 'untitled'); const detectedName = name || (ext ? `untitled.${ext}` : 'untitled');
@ -363,7 +365,7 @@ export default async function(
}); });
if (much) { if (much) {
driveLogger.info(`file with same hash is found: ${much._id}`); logger.info(`file with same hash is found: ${much._id}`);
return much; return much;
} }
} }
@ -393,7 +395,7 @@ export default async function(
return 0; return 0;
}); });
driveLogger.info(`drive usage is ${usage}`); logger.info(`drive usage is ${usage}`);
const instance = await fetchMeta(); const instance = await fetchMeta();
const driveCapacity = 1024 * 1024 * (isLocalUser(user) ? instance.localDriveCapacityMb : instance.remoteDriveCapacityMb); const driveCapacity = 1024 * 1024 * (isLocalUser(user) ? instance.localDriveCapacityMb : instance.remoteDriveCapacityMb);
@ -436,12 +438,12 @@ export default async function(
// Calc width and height // Calc width and height
const calcWh = async () => { const calcWh = async () => {
driveLogger.info('calculating image width and height...'); logger.debug('calculating image width and height...');
// Calculate width and height // Calculate width and height
const meta = await img.metadata(); const meta = await img.metadata();
driveLogger.info(`image width and height is calculated: ${meta.width}, ${meta.height}`); logger.debug(`image width and height is calculated: ${meta.width}, ${meta.height}`);
properties['width'] = meta.width; properties['width'] = meta.width;
properties['height'] = meta.height; properties['height'] = meta.height;
@ -449,7 +451,7 @@ export default async function(
// Calc average color // Calc average color
const calcAvg = async () => { const calcAvg = async () => {
driveLogger.info('calculating average color...'); logger.debug('calculating average color...');
try { try {
const info = await (img as any).stats(); const info = await (img as any).stats();
@ -458,7 +460,7 @@ export default async function(
const g = Math.round(info.channels[1].mean); const g = Math.round(info.channels[1].mean);
const b = Math.round(info.channels[2].mean); const b = Math.round(info.channels[2].mean);
driveLogger.info(`average color is calculated: ${r}, ${g}, ${b}`); logger.debug(`average color is calculated: ${r}, ${g}, ${b}`);
const value = info.isOpaque ? [r, g, b] : [r, g, b, 255]; const value = info.isOpaque ? [r, g, b] : [r, g, b, 255];
@ -514,14 +516,14 @@ export default async function(
} catch (e) { } catch (e) {
// duplicate key error (when already registered) // duplicate key error (when already registered)
if (e.code === 11000) { if (e.code === 11000) {
driveLogger.info(`already registered ${metadata.uri}`); logger.info(`already registered ${metadata.uri}`);
driveFile = await DriveFile.findOne({ driveFile = await DriveFile.findOne({
'metadata.uri': metadata.uri, 'metadata.uri': metadata.uri,
'metadata.userId': user._id 'metadata.userId': user._id
}); });
} else { } else {
driveLogger.error(e); logger.error(e);
throw e; throw e;
} }
} }
@ -529,7 +531,7 @@ export default async function(
driveFile = await (save(path, detectedName, mime, hash, size, metadata)); driveFile = await (save(path, detectedName, mime, hash, size, metadata));
} }
driveLogger.succ(`drive file has been created ${driveFile._id}`); logger.succ(`drive file has been created ${driveFile._id}`);
pack(driveFile).then(packedFile => { pack(driveFile).then(packedFile => {
// Publish driveFileCreated event // Publish driveFileCreated event

View file

@ -1,7 +1,5 @@
import * as fs from 'fs'; import * as fs from 'fs';
import * as URL from 'url'; import * as URL from 'url';
import * as debug from 'debug';
import * as tmp from 'tmp'; import * as tmp from 'tmp';
import * as request from 'request'; import * as request from 'request';
@ -10,8 +8,9 @@ import create from './add-file';
import config from '../../config'; import config from '../../config';
import { IUser } from '../../models/user'; import { IUser } from '../../models/user';
import * as mongodb from 'mongodb'; import * as mongodb from 'mongodb';
import { driveLogger } from './logger';
const log = debug('misskey:drive:upload-from-url'); const logger = driveLogger.createSubLogger('downloader');
export default async ( export default async (
url: string, url: string,
@ -22,14 +21,14 @@ export default async (
force = false, force = false,
link = false link = false
): Promise<IDriveFile> => { ): Promise<IDriveFile> => {
log(`REQUESTED: ${url}`); logger.info(`REQUESTED: ${url}`);
let name = URL.parse(url).pathname.split('/').pop(); let name = URL.parse(url).pathname.split('/').pop();
if (!validateFileName(name)) { if (!validateFileName(name)) {
name = null; name = null;
} }
log(`name: ${name}`); logger.info(`name: ${name}`);
// Create temp file // Create temp file
const [path, cleanup] = await new Promise<[string, any]>((res, rej) => { const [path, cleanup] = await new Promise<[string, any]>((res, rej) => {
@ -82,10 +81,10 @@ export default async (
try { try {
driveFile = await create(user, path, name, null, folderId, force, link, url, uri, sensitive); driveFile = await create(user, path, name, null, folderId, force, link, url, uri, sensitive);
log(`got: ${driveFile._id}`); logger.succ(`got: ${driveFile._id}`);
} catch (e) { } catch (e) {
error = e; error = e;
log(`failed: ${e}`); logger.error(`failed: ${e}`);
} }
// clean-up // clean-up

View file

@ -1,8 +1,5 @@
import * as debug from 'debug';
import Emoji from '../models/emoji'; import Emoji from '../models/emoji';
debug.enable('*');
async function main(name: string, url: string, alias?: string): Promise<any> { async function main(name: string, url: string, alias?: string): Promise<any> {
const aliases = alias != null ? [ alias ] : []; const aliases = alias != null ? [ alias ] : [];

View file

@ -1,8 +1,5 @@
import parseAcct from '../misc/acct/parse'; import parseAcct from '../misc/acct/parse';
import resolveUser from '../remote/resolve-user'; import resolveUser from '../remote/resolve-user';
import * as debug from 'debug';
debug.enable('*');
async function main(acct: string): Promise<any> { async function main(acct: string): Promise<any> {
const { username, host } = parseAcct(acct); const { username, host } = parseAcct(acct);