diff --git a/packages/ceramic-cli/src/bin/ceramic.ts b/packages/ceramic-cli/src/bin/ceramic.ts index 913d1790f1..293fdbe4b0 100644 --- a/packages/ceramic-cli/src/bin/ceramic.ts +++ b/packages/ceramic-cli/src/bin/ceramic.ts @@ -12,9 +12,10 @@ program .option('--pinning-store-path ', `The directory path used for pinning service. Defaults to WORKING_DIR/${DEFAULT_PINNING_STORE_PATH}`) .option('--gateway', 'Makes read only endpoints available. It is disabled by default') .option('--port ', 'Port daemon is availabe. Default is 7007') + .option('--debug', 'Enable debug logging level. Default is false') .description('Start the daemon') - .action(async ({ ipfsApi, ethereumRpc, anchorServiceApi, validateDocs, pinning, stateStorePath, gateway, port }) => { - await CeramicCliUtils.createDaemon(ipfsApi, ethereumRpc, anchorServiceApi, validateDocs, pinning, stateStorePath, gateway, port) + .action(async ({ ipfsApi, ethereumRpc, anchorServiceApi, validateDocs, pinning, stateStorePath, gateway, port, debug }) => { + await CeramicCliUtils.createDaemon(ipfsApi, ethereumRpc, anchorServiceApi, validateDocs, pinning, stateStorePath, gateway, port, debug) }) program diff --git a/packages/ceramic-cli/src/ceramic-cli-utils.ts b/packages/ceramic-cli/src/ceramic-cli-utils.ts index 9eea41ac7b..aebb71f383 100644 --- a/packages/ceramic-cli/src/ceramic-cli-utils.ts +++ b/packages/ceramic-cli/src/ceramic-cli-utils.ts @@ -49,8 +49,9 @@ export class CeramicCliUtils { * @param stateStorePath - State store path * @param gateway - read only endpoints available. It is disabled by default * @param port - port daemon is availabe. Default is 7007 + * @param debug - Enable debug logging level */ - static async createDaemon(ipfsApi: string, ethereumRpc: string, anchorServiceApi: string, validateDocs: boolean, pinning: string[], stateStorePath: string, gateway: boolean, port: number): Promise { + static async createDaemon(ipfsApi: string, ethereumRpc: string, anchorServiceApi: string, validateDocs: boolean, pinning: string[], stateStorePath: string, gateway: boolean, port: number, debug: boolean): Promise { if (stateStorePath == null) { stateStorePath = DEFAULT_PINNING_STORE_PATH } @@ -62,7 +63,8 @@ export class CeramicCliUtils { validateDocs, pinning: pinning, gateway, - port + port, + debug } if (ipfsApi) { diff --git a/packages/ceramic-cli/src/ceramic-daemon.ts b/packages/ceramic-cli/src/ceramic-daemon.ts index 7c39d533ec..a2420d7165 100644 --- a/packages/ceramic-cli/src/ceramic-daemon.ts +++ b/packages/ceramic-cli/src/ceramic-daemon.ts @@ -3,10 +3,9 @@ import ipfsClient from 'ipfs-http-client' import express, { Request, Response, NextFunction } from 'express' import Ceramic from '@ceramicnetwork/ceramic-core' import type { CeramicConfig } from "@ceramicnetwork/ceramic-core"; -import { DoctypeUtils } from "@ceramicnetwork/ceramic-common" +import { DoctypeUtils, DefaultLoggerFactory, Logger } from "@ceramicnetwork/ceramic-common" const DEFAULT_PORT = 7007 -const DEBUG = true const toApiPath = (ending: string): string => '/api/v0' + ending const DEFAULT_ANCHOR_SERVICE_URL = "https://cas.3box.io:8081/api/v0/requests" @@ -23,22 +22,21 @@ interface CreateOpts { validateDocs?: boolean; pinning?: string[]; gateway?: boolean; -} - -function logErrors (err: Error, req: Request, res: Response, next: NextFunction): void { - console.error(err) - next(err) -} - -function sendErrorResponse(err: Error, req: Request, res: Response, next: NextFunction): void { - res.json({ error: err.message }) - next(err) + debug: boolean; } class CeramicDaemon { private server: any + private logger: Logger + private readonly debug: boolean constructor (public ceramic: Ceramic, opts: CreateOpts) { + this.debug = opts.debug + this.logger = DefaultLoggerFactory.getLogger(CeramicDaemon.name) + if (this.debug) { + this.logger.setLevel('debug') + } + const app = express() app.use(express.json()) app.use((req: Request, res: Response, next: NextFunction) => { @@ -48,10 +46,68 @@ class CeramicDaemon { this.registerAPIPaths(app, opts.gateway) - if (DEBUG) { - app.use(logErrors) + if (this.debug) { + app.use((err: Error, req: Request, res: Response, next: NextFunction): void => { + this.logger.error(err) + next(err) + }) + app.use((req: Request, res: Response, next: NextFunction) => { + const requestStart = Date.now(); + const { rawHeaders, httpVersion, method, socket, url } = req; + const { remoteAddress, remoteFamily } = socket; + + this.logger.debug( + JSON.stringify({ + timestamp: Date.now(), + rawHeaders, + httpVersion, + method, + remoteAddress, + remoteFamily, + url + }) + ); + + let errorMessage: string = null; + let body: string | any = []; + req.on("data", chunk => { + body.push(chunk) + }) + req.on("end", () => { + body = Buffer.concat(body) + body = body.toString() + }); + req.on("error", error => { + errorMessage = error.message + }); + + res.on("finish", () => { + const { rawHeaders, httpVersion, method, socket, url } = req + const { remoteAddress, remoteFamily } = socket + + this.logger.debug( + JSON.stringify({ + timestamp: Date.now(), + processingTime: Date.now() - requestStart, + rawHeaders, + body, + errorMessage, + httpVersion, + method, + remoteAddress, + remoteFamily, + url + }) + ) + }) + + next() + }) } - app.use(sendErrorResponse) + app.use((err: Error, req: Request, res: Response, next: NextFunction): void => { + res.json({ error: err.message }) + next(err) + }) const port = opts.port || DEFAULT_PORT this.server = app.listen(port, () => { console.log('Ceramic API running on port ' + port) diff --git a/packages/ceramic-common/package.json b/packages/ceramic-common/package.json index 19e43f6d33..07a1edbe9e 100644 --- a/packages/ceramic-common/package.json +++ b/packages/ceramic-common/package.json @@ -31,7 +31,9 @@ "cids": "^1.0.0", "dag-jose": "^0.2.0", "did-resolver": "^2.1.1", - "lodash.clonedeep": "^4.5.0" + "lodash.clonedeep": "^4.5.0", + "loglevel": "^1.7.0", + "loglevel-plugin-prefix": "^0.8.4" }, "devDependencies": { "@babel/core": "^7.9.0", diff --git a/packages/ceramic-common/src/index.ts b/packages/ceramic-common/src/index.ts index ae1de4a89b..6ecd51fea4 100644 --- a/packages/ceramic-common/src/index.ts +++ b/packages/ceramic-common/src/index.ts @@ -3,3 +3,4 @@ export * from './ceramic-api' export * from './context' export * from './doctype' export * from './utils/doctype-utils' +export * from './logger-factory' diff --git a/packages/ceramic-common/src/logger-factory.ts b/packages/ceramic-common/src/logger-factory.ts new file mode 100644 index 0000000000..19c7377162 --- /dev/null +++ b/packages/ceramic-common/src/logger-factory.ts @@ -0,0 +1,262 @@ +import chalk from 'chalk' +import log, { Logger, LogLevelDesc, MethodFactory } from 'loglevel' +import prefix from 'loglevel-plugin-prefix' + +/** + * Logger colors + */ +const colors: Record = { + TRACE: chalk.magenta, + DEBUG: chalk.cyan, + INFO: chalk.blue, + WARN: chalk.yellow, + ERROR: chalk.red, +} + +/** + * Default logger options + */ +const defaultOpts: Options = { + colors: false, + level: 'info', + format: 'text', + stacktrace: { + levels: ['trace', 'warn', 'error'], + depth: 3, + excess: 0, + } +} + +/** + * Logger options + */ +interface Options { + level?: string; + colors?: boolean; + format: string; // [text | json] + stacktrace: { + levels: ['trace', 'warn', 'error']; + depth: 3; + excess: 0; + }; +} + +/** + * Global Logger factory + */ +class LoggerFactory { + + private options: Options & {} + + constructor(opts = {}) { + this.options = Object.assign(defaultOpts, opts) + + if (this.options.level) { + log.setLevel(this.options.level as LogLevelDesc) + } else { + log.enableAll() // enable all levels (TRACE) + } + + this._applyPrefix() + this._includeJsonPlugin() + } + + /** + * Gets logger by name + * @param name + */ + getLogger(name: string): Logger { + return log.getLogger(name) + } + + /** + * Applies prefix + * @private + */ + _applyPrefix(): void { + const { options } = this + prefix.reg(log) + prefix.apply(log, { + format(level, name, timestamp) { + return LoggerFactory._toText(options, timestamp, level, name) + }, + timestampFormatter(date) { + return date.toISOString() + } + }) + } + + /** + * Simple JSON plugin + * @private + */ + _includeJsonPlugin(): void { + const originalFactory = log.methodFactory; + + const { options } = this + log.methodFactory = (methodName: string, logLevel: any, loggerName: string): MethodFactory => { + const rawMethod = originalFactory(methodName, logLevel, loggerName); + return (...args: any[]): any => { + if (options.format !== 'json') { + rawMethod(...args) + return + } + const timestamp = new Date().toISOString() + const hasStacktrace = !!LoggerFactory._stacktrace() + const needStack = hasStacktrace && options.stacktrace.levels.some(level => level === methodName) + + let stacktrace = needStack ? LoggerFactory._stacktrace() : ''; + if (stacktrace) { + const lines = stacktrace.split('\n'); + lines.splice(0, options.stacktrace.excess + 3); + const { depth } = options.stacktrace; + if (depth && lines.length !== depth + 1) { + const shrink = lines.splice(0, depth); + stacktrace = shrink.join('\n'); + if (lines.length) { + stacktrace += `\n and ${lines.length} more`; + } + } else { + stacktrace = lines.join('\n'); + } + } + + rawMethod(JSON.stringify({ + message: LoggerFactory._interpolate(args), + level: { + label: methodName, value: logLevel, + }, + logger: loggerName || '', + timestamp, + stacktrace, + })) + } + }; + log.setLevel(log.getLevel()); + } + + /** + * Formats to text + */ + static _toText(options: Options, timestamp: any, level: any, name: any): string { + if (options.format === 'json') { + return "" // no prefix + } + if (!options.colors) { + return `[${timestamp}] ${level} ${name}:` + } + return `${chalk.gray(`[${timestamp}]`)} ${colors[level.toUpperCase()](level)} ${chalk.green(`${name}:`)}` + } + + /** + * Gets possible stacktrace + * @private + */ + static _stacktrace(): any[string] { + try { + throw new Error(); + } catch (trace) { + return trace.stack; + } + } + + /** + * Interpolate parameters + * https://github.com/kutuluk/loglevel-plugin-remote/blob/master/src/remote.js + * @private + */ + static _interpolate(array: any[]): string { + let result = ''; + let index = 0; + + if (array.length > 1 && typeof array[0] === 'string') { + result = array[0].replace(/(%?)(%([sdjo]))/g, (match, escaped, ptn, flag) => { + if (!escaped) { + index += 1; + const arg = array[index]; + let a = ''; + switch (flag) { + case 's': + a += arg; + break; + case 'd': + a += +arg; + break; + case 'j': + a = LoggerFactory._safeStringify(arg); + break; + case 'o': { + let obj = LoggerFactory._safeStringify(arg); + if (obj[0] !== '{' && obj[0] !== '[') { + obj = `<${obj}>`; + } + a = LoggerFactory._constructorName(arg) + obj; + break; + } + } + return a; + } + return match; + }); + + // update escaped %% values + result = result.replace(/%{2,2}/g, '%'); + index += 1; + } + + // arguments remaining after formatting + if (array.length > index) { + if (result) result += ' '; + result += array.slice(index).join(' '); + } + return result; + } + + /** + * Gets possible constructor name + * @private + */ + static _constructorName(obj: any): string { + if (!Object.getOwnPropertyDescriptor || !Object.getPrototypeOf) { + return Object.prototype.toString.call(obj).slice(8, -1); + } + // https://github.com/nodejs/node/blob/master/lib/internal/util.js + while (obj) { + const descriptor = Object.getOwnPropertyDescriptor(obj, 'constructor'); + if (descriptor !== undefined && typeof descriptor.value === 'function' && descriptor.value.name !== '') { + return descriptor.value.name; + } + obj = Object.getPrototypeOf(obj); + } + return ''; + } + + /** + * Tries to JSON stringify + * @param obj - Input + * @param indent - Ident value + * @private + */ + static _safeStringify(obj: any, indent = 0): string { + let cache: any[] = []; + const retVal = JSON.stringify( + obj, (key, value) => + typeof value === "object" && value !== null + ? cache.includes(value) + ? undefined // Duplicate reference found, discard key + : cache.push(value) && value // Store value in our collection + : value, + indent + ); + cache = null + return retVal + } +} + +const _instance = new LoggerFactory() +Object.freeze(_instance) // freeze API +export { + _instance as DefaultLoggerFactory, + LoggerFactory, // should be exposed for customization + Logger, +} diff --git a/packages/ceramic-core/src/__tests__/dispatcher.test.ts b/packages/ceramic-core/src/__tests__/dispatcher.test.ts index 2f2256dc26..9706318660 100644 --- a/packages/ceramic-core/src/__tests__/dispatcher.test.ts +++ b/packages/ceramic-core/src/__tests__/dispatcher.test.ts @@ -29,6 +29,7 @@ describe('Dispatcher', () => { it('is constructed correctly', async () => { const disp = new Dispatcher(ipfs) + await disp.init() expect(disp._documents).toEqual({}) expect(ipfs.pubsub.subscribe).toHaveBeenCalledWith(TOPIC, expect.anything()) }) @@ -36,6 +37,7 @@ describe('Dispatcher', () => { it('makes registration correctly', async () => { const id = '/ceramic/bagjqcgzaday6dzalvmy5ady2m5a5legq5zrbsnlxfc2bfxej532ds7htpova' const disp = new Dispatcher(ipfs) + await disp.init() const doc = new Document(id, disp, null) await disp.register(doc) expect(ipfs.pubsub.publish).toHaveBeenCalledWith(TOPIC, JSON.stringify({ typ: MsgType.REQUEST, id })) @@ -43,11 +45,13 @@ describe('Dispatcher', () => { it('store record correctly', async () => { const disp = new Dispatcher(ipfs) + await disp.init() expect(await disp.storeRecord('data')).toEqual(FAKE_CID) }) it('retrieves record correctly', async () => { const disp = new Dispatcher(ipfs) + await disp.init() expect(await disp.retrieveRecord(FAKE_CID)).toEqual('data') }) @@ -55,6 +59,7 @@ describe('Dispatcher', () => { const id = '/ceramic/3id/234' const head = 'bafy9h3f08erf' const disp = new Dispatcher(ipfs) + await disp.init() disp.publishHead(id, head) expect(ipfs.pubsub.publish).toHaveBeenCalledWith(TOPIC, JSON.stringify({ typ: MsgType.UPDATE, id, cid: head })) }) @@ -62,6 +67,7 @@ describe('Dispatcher', () => { it('handle message correctly', async () => { const id = '/ceramic/bagjqcgzaday6dzalvmy5ady2m5a5legq5zrbsnlxfc2bfxej532ds7htpova' const disp = new Dispatcher(ipfs) + await disp.init() const doc = new Document(id, disp, null) await disp.register(doc) @@ -78,6 +84,7 @@ describe('Dispatcher', () => { it('closes correctly', async () => { const disp = new Dispatcher(ipfs) + await disp.init() await disp.close() expect(ipfs.pubsub.unsubscribe).toHaveBeenCalledTimes(1) expect(ipfs.pubsub.unsubscribe).toHaveBeenCalledWith(TOPIC) diff --git a/packages/ceramic-core/src/ceramic.ts b/packages/ceramic-core/src/ceramic.ts index 5bdca861b9..9513f6c70e 100644 --- a/packages/ceramic-core/src/ceramic.ts +++ b/packages/ceramic-core/src/ceramic.ts @@ -111,6 +111,7 @@ class Ceramic implements CeramicApi { */ static async create(ipfs: Ipfs.Ipfs, config: CeramicConfig = {}): Promise { const dispatcher = new Dispatcher(ipfs) + await dispatcher.init() const anchorServiceFactory = new AnchorServiceFactory(dispatcher, config) const anchorService = anchorServiceFactory.get(); diff --git a/packages/ceramic-core/src/dispatcher.ts b/packages/ceramic-core/src/dispatcher.ts index 4c4a2e23fd..5aa7276fb5 100644 --- a/packages/ceramic-core/src/dispatcher.ts +++ b/packages/ceramic-core/src/dispatcher.ts @@ -4,7 +4,7 @@ import CID from 'cids' import cloneDeep from 'lodash.clonedeep' import type Document from "./document" -import { DoctypeUtils } from "@ceramicnetwork/ceramic-common" +import { DoctypeUtils, DefaultLoggerFactory, Logger } from "@ceramicnetwork/ceramic-common" export enum MsgType { UPDATE, @@ -18,12 +18,22 @@ export default class Dispatcher extends EventEmitter { private _peerId: string private readonly _documents: Record + private logger: Logger private _isRunning = true constructor (public _ipfs: Ipfs.Ipfs) { super() this._documents = {} - this._ipfs.pubsub.subscribe(TOPIC, this.handleMessage.bind(this)) // this returns promise, we should await + this.logger = DefaultLoggerFactory.getLogger(Dispatcher.name) + } + + /** + * Initialized Dispatcher + */ + async init(): Promise { + this._peerId = this._peerId || (await this._ipfs.id()).id + await this._ipfs.pubsub.subscribe(TOPIC, this.handleMessage.bind(this)) + this.logger.info(`${this._peerId} successfully subscribed to pubsub topic ${TOPIC}`) } async register (document: Document): Promise { @@ -62,22 +72,25 @@ export default class Dispatcher extends EventEmitter { async publishHead (id: string, head: CID): Promise { if (!this._isRunning) { - console.error('Dispatcher has been closed') + this.logger.error('Dispatcher has been closed') return } - await this._ipfs.pubsub.publish(TOPIC, JSON.stringify({ typ: MsgType.UPDATE, id, cid: head.toString() })) + const payload = JSON.stringify({ typ: MsgType.UPDATE, id, cid: head.toString() }) + await this._ipfs.pubsub.publish(TOPIC, payload) + this.logger.info(`${this._peerId} successfully published to pubsub topic ${TOPIC}. Payload: ${payload}`) } async handleMessage (message: any): Promise { if (!this._isRunning) { - console.error('Dispatcher has been closed') + this.logger.error('Dispatcher has been closed') return } - this._peerId = this._peerId || (await this._ipfs.id()).id if (message.from !== this._peerId) { const { typ, id, cid } = JSON.parse(message.data) + this.logger.info(`${this._peerId} received message from ${message.from}. Payload: ${JSON.stringify({typ, id, cid})}`) + if (this._documents[id]) { switch (typ) { case MsgType.UPDATE: diff --git a/packages/ceramic-core/src/document.ts b/packages/ceramic-core/src/document.ts index e8460271a0..e26163723e 100644 --- a/packages/ceramic-core/src/document.ts +++ b/packages/ceramic-core/src/document.ts @@ -15,7 +15,9 @@ import { Context, DoctypeUtils, CeramicApi, - DocMetadata + DocMetadata, + DefaultLoggerFactory, + Logger } from "@ceramicnetwork/ceramic-common" import {PinStore} from "./store/pin-store"; @@ -35,11 +37,14 @@ class Document extends EventEmitter { public readonly id: string public readonly version: CID + private logger: Logger + constructor (id: string, public dispatcher: Dispatcher, public pinStore: PinStore) { super() const normalized = DoctypeUtils.normalizeDocId(id) this.id = DoctypeUtils.getBaseDocId(normalized); this.version = DoctypeUtils.getVersionId(normalized) + this.logger = DefaultLoggerFactory.getLogger(Document.name) this._applyQueue = async.queue(async (task: QueueTask, callback) => { try { @@ -51,7 +56,7 @@ class Document extends EventEmitter { } } } catch (e) { - console.error(e) + callback(e) } finally { callback() }