From 828cb66cb84225385fdd2cf163fe74739ec86126 Mon Sep 17 00:00:00 2001 From: Link Date: Tue, 10 Oct 2023 15:22:15 +0800 Subject: [PATCH] refactor: improve log format --- .github/workflows/cd.yaml | 1 + config/default.yaml | 1 + config/mainnet.yaml | 2 ++ config/testnet.yaml | 2 ++ ecosystem.config.js | 6 ++--- src/config.ts | 1 + src/controller/update.ts | 53 +++++++++++++++++++++------------------ src/log.ts | 8 ++++++ src/utils/env.ts | 33 ++++++++++++++++++++++++ src/utils/helper.ts | 52 ++++++++------------------------------ 10 files changed, 90 insertions(+), 69 deletions(-) create mode 100644 src/utils/env.ts diff --git a/.github/workflows/cd.yaml b/.github/workflows/cd.yaml index 217a012..b6d106b 100644 --- a/.github/workflows/cd.yaml +++ b/.github/workflows/cd.yaml @@ -7,6 +7,7 @@ on: workflows: [ci] types: [completed] branches: [main, develop] + workflow_dispatch: jobs: deploy-to-mainnet: diff --git a/config/default.yaml b/config/default.yaml index 446cecc..f5f67f2 100644 --- a/config/default.yaml +++ b/config/default.yaml @@ -5,6 +5,7 @@ CKB_WS_URL: 'ws://127.0.0.1:28114' LARK_API_KEY: '' loglevel: 'info' +env: '' # Define the servers and its IP address, mainly used for making notification much more readable in lark. servers: {} diff --git a/config/mainnet.yaml b/config/mainnet.yaml index 7866546..72de608 100644 --- a/config/mainnet.yaml +++ b/config/mainnet.yaml @@ -1,4 +1,6 @@ --- +env: mainnet + CellDeps: # index-state-cell-type - outPoint: { txHash: '0xe9116d651c371662b6e29e2102422e23f90656b8619df82c48b782ff4db43a37', index: '0x0' } diff --git a/config/testnet.yaml b/config/testnet.yaml index 8be009d..9739c76 100644 --- a/config/testnet.yaml +++ b/config/testnet.yaml @@ -1,4 +1,6 @@ --- +env: testnet + CellDeps: # index-state-cell-type - outPoint: { txHash: '0x654f8a271dde2d99f548ff5b9369a55c0cfbe19a315efb5dacf34f72d7f3ea64', index: '0x0' } diff --git a/ecosystem.config.js b/ecosystem.config.js index 8d24652..ac3dd38 100644 --- a/ecosystem.config.js +++ b/ecosystem.config.js @@ -13,7 +13,7 @@ function generateApp (name, entry, args, env) { watch: false, error_file: `logs/${appName}.stderr.log`, out_file: `logs/${appName}.stdout.log`, - log_date_format: 'MM-DD HH:mm:ss', + // log_date_format: 'MM-DD HH:mm:ss', kill_timeout: 10 * 1000, // ms listen_timeout: 10 * 1000, // ms max_memory_restart: '256M', @@ -30,8 +30,8 @@ module.exports = { * http://pm2.keymetrics.io/docs/usage/application-declaration/ */ apps: [ - generateApp('time', 'dist/main.js', 'update -t timestamp', process.env.NODE_ENV), - generateApp('height', 'dist/main.js', 'update -t blocknumber', process.env.NODE_ENV), + // generateApp('time', 'dist/main.js', 'update -t timestamp', process.env.NODE_ENV), + // generateApp('height', 'dist/main.js', 'update -t blocknumber', process.env.NODE_ENV), generateApp('quote', 'dist/main.js', 'update -t quote', process.env.NODE_ENV), ] } diff --git a/src/config.ts b/src/config.ts index 96244e7..65717cf 100644 --- a/src/config.ts +++ b/src/config.ts @@ -21,6 +21,7 @@ interface Config { LARK_API_KEY: string, loglevel: string, + env: string, // Define the servers and its IP address, mainly used for making notification much more readable in lark. servers: any, diff --git a/src/controller/update.ts b/src/controller/update.ts index 1491206..b950b53 100644 --- a/src/controller/update.ts +++ b/src/controller/update.ts @@ -26,18 +26,20 @@ import { IndexStateModel } from '../model/index_state_model' import { InfoModel } from '../model/info_model' import { EMPTY_WITNESS_ARGS } from '@nervosnetwork/ckb-sdk-utils/lib/const' -async function findIndexStateCell (typeScript: CKBComponents.Script) { +async function findIndexStateCell (logger: Logger, typeScript: CKBComponents.Script) { const indexStateCells = await getCells(typeScript, 'type') if (indexStateCells.length > 1) { - // await notifyWithThrottle('index-state-cells-error', TIME_1_M * 60, 'Found more than one IndexStateCells on-chain, please recycle redundant cells as soon as possible.') + // await notifyWithThrottle(logger, 'index-state-cells-error', TIME_1_M * 60, 'Found more than one IndexStateCells on-chain, please recycle redundant cells as soon as possible.') + logger.warn('Found more than one IndexStateCells on-chain, please recycle redundant cells as soon as possible.') } const cell = indexStateCells[0] const model = IndexStateModel.fromHex(cell.output_data) if (model.total !== SUM_OF_INFO_CELLS) { - // await notifyWithThrottle('index-state-cells-error', TIME_1_M * 60, 'Total number of InfoCells is different from code and cell data, please update code as soon as possible.') + // await notifyWithThrottle(logger, 'index-state-cells-error', TIME_1_M * 60, 'Total number of InfoCells is different from code and cell data, please update code as soon as possible.') + logger.warn('Total number of InfoCells is different from code and cell data, please update code as soon as possible.') } return { @@ -47,11 +49,12 @@ async function findIndexStateCell (typeScript: CKBComponents.Script) { } } -async function findInfoCell (typeScript: CKBComponents.Script, index: number) { +async function findInfoCell (logger: Logger, typeScript: CKBComponents.Script, index: number) { const infoCells = await getCells(typeScript, 'type') if (infoCells.length > SUM_OF_INFO_CELLS) { - // await notifyWithThrottle('info-cells-error', TIME_1_M * 60, `Found more than ${SUM_OF_INFO_CELLS} InfoCells on-chain, please recycle redundant cells as soon as possible.`) + // await notifyWithThrottle(logger, 'info-cells-error', TIME_1_M * 60, `Found more than ${SUM_OF_INFO_CELLS} InfoCells on-chain, please recycle redundant cells as soon as possible.`) + logger.warn(`Found more than ${SUM_OF_INFO_CELLS} InfoCells on-chain, please recycle redundant cells as soon as possible.`) } for (const cell of infoCells) { @@ -82,12 +85,12 @@ export async function updateController (argv: Arguments<{ type: string }>) { server.on('update', (data: RPC.Header) => { (async () => { if (txHash && waitedBlocks <= maxWaitingBlocks) { - logger.verbose('Found pending transaction, check if transaction committed ...', { txHash: txHash }) + logger.verbose(`Found pending transaction ${txHash}, check if transaction committed ...`) const tx = await getTransaction(txHash) // tx maybe null if (!tx || tx.txStatus.status !== 'committed') { - logger.info('Previous transaction is pending, wait for it.', { txHash: txHash }) + logger.info(`${txHash} is pending, wait for it.`) waitedBlocks++ return } @@ -96,7 +99,7 @@ export async function updateController (argv: Arguments<{ type: string }>) { // Calculate new outputs_data of IndexStateCell and InfoCell let resultOfIndex: { out_point: RPC.OutPoint, output: RPC.CellOutput, model: IndexStateModel } try { - resultOfIndex = await findIndexStateCell(indexStateTypeScript) + resultOfIndex = await findIndexStateCell(logger, indexStateTypeScript) } catch (e) { logger.error(`Failed to find IndexStateCells: ${e.toString()}`) return @@ -107,7 +110,7 @@ export async function updateController (argv: Arguments<{ type: string }>) { let resultOfInfo: { out_point: RPC.OutPoint, output: RPC.CellOutput, model: InfoModel } try { - resultOfInfo = await findInfoCell(infoCellTypeScript, indexModel.index) + resultOfInfo = await findInfoCell(logger, infoCellTypeScript, indexModel.index) } catch (e) { logger.error(`Failed to find InfoCells: ${e.toString()}`) return @@ -124,17 +127,17 @@ export async function updateController (argv: Arguments<{ type: string }>) { try { infoModel.infoData = await getLatestTimestamp(data.number) } catch (e) { - await notifyWithThreshold('fetch-timestamp-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `${e}`, 'Check if CKB node is offline and its JSON RPC is reachable.') + await notifyWithThreshold(logger, 'fetch-timestamp-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `${e}`, 'Check if CKB node is offline and its JSON RPC is reachable.') return } since = dataToSince(infoModel.infoData, SinceFlag.AbsoluteTimestamp) break case 'quote': try { - infoModel.infoData = await getCkbPrice() + infoModel.infoData = await getCkbPrice(logger) } catch (e) { logger.error(`Failed to fetch the quote from exchanges, the error is: ${e}`) - await notifyWithThreshold('fetch-quote-error', THEORETIC_BLOCK_1_M * 10, TIME_1_M * 10, `${e}`, 'Check if the coingecko API(https://api.coingecko.com/api/v3/simple/price?ids=nervos-network&vs_currencies=usd) is available.') + await notifyWithThreshold(logger, 'fetch-quote-error', THEORETIC_BLOCK_1_M * 10, TIME_1_M * 10, `${e}`, 'Check if the coingecko API(https://api.coingecko.com/api/v3/simple/price?ids=nervos-network&vs_currencies=usd) is available.') return } break @@ -153,15 +156,15 @@ export async function updateController (argv: Arguments<{ type: string }>) { let collected try { - collected = await collectInputs(lockScript, config.fee.update) + collected = await collectInputs(logger, lockScript, config.fee.update) inputs = inputs.concat(collected.inputs) } catch (e) { if (e.toString().includes('capacity')) { logger.error(`Collect inputs failed, expected ${config.fee.update} shannon but only ${collected.capacity} shannon found.`) - await notifyWithThreshold('collect-inputs-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `Collect inputs failed, expected ${config.fee.update} shannon but only ${collected.capacity} shannon found.`, 'Check if the balance of deploy address is enough.') + await notifyWithThreshold(logger, 'collect-inputs-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `Collect inputs failed, expected ${config.fee.update} shannon but only ${collected.capacity} shannon found.`, 'Check if the balance of deploy address is enough.') } else { logger.error(`Collect inputs error.(${e.toString()})`) - await notifyWithThreshold('collect-inputs-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `Collect inputs error.(${e.toString()})`, 'Check if ckb-indexer is offline and the get_cells interface is reachable.') + await notifyWithThreshold(logger, 'collect-inputs-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `Collect inputs error.(${e.toString()})`, 'Check if ckb-indexer is offline and the get_cells interface is reachable.') } return } @@ -210,7 +213,7 @@ export async function updateController (argv: Arguments<{ type: string }>) { await ckb.loadDeps() } catch (e) { logger.error(`Load cell_deps from node RPC API failed.(${e})`) - await notifyWithThreshold('load-cell-deps-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `Load cell_deps from node RPC API failed.(${e})`, 'Check if CKB node is offline and its JSON RPC is reachable.') + await notifyWithThreshold(logger, 'load-cell-deps-error', THEORETIC_BLOCK_1_M * 5, TIME_1_M * 5, `Load cell_deps from node RPC API failed.(${e})`, 'Check if CKB node is offline and its JSON RPC is reachable.') return } @@ -219,7 +222,7 @@ export async function updateController (argv: Arguments<{ type: string }>) { signedRawTx = ckb.signTransaction(config[argv.type].PayersPrivateKey)(rawTx) } catch (e) { logger.error(`Sign transaction failed.(${e})`) - await notifyWithThrottle('sign-transaction-error', TIME_1_M * 10, `Sign transaction failed.(${e})`, 'Try to find out what the error message means it mostly because the private key is not match.') + await notifyWithThrottle(logger, 'sign-transaction-error', TIME_1_M * 10, `Sign transaction failed.(${e})`, 'Try to find out what the error message means it mostly because the private key is not match.') return } @@ -236,15 +239,15 @@ export async function updateController (argv: Arguments<{ type: string }>) { case -302: case -1107: // These error are caused by cell occupation, could retry automatically. - logger.warn(`Update cell failed.(${data.message})`, { code: data.code }) + logger.warn(`Update cell failed.(${data.code}: ${data.message})`) return default: - logger.error(`Update cell failed.(${data.message})`, { code: data.code }) - await notifyWithThrottle('update-error', TIME_1_M * 10, `Update cell failed.(${data.message})`, 'Try to find out what the error message means.') + logger.error(`Update cell failed.(${data.code}: ${data.message})`) + await notifyWithThrottle(logger, 'update-error', TIME_1_M * 10, `Update cell failed.(${data.message})`, 'Try to find out what the error message means.') } } catch (e) { logger.error(`Update cell occurred unknown error.(${err})`) - await notifyWithThrottle('update-error', TIME_1_M * 10, `Update cell occurred unknown error.(${err})`, 'Try to find out what the error message means.') + await notifyWithThrottle(logger, 'update-error', TIME_1_M * 10, `Update cell occurred unknown error.(${err})`, 'Try to find out what the error message means.') } } @@ -340,6 +343,7 @@ class Server extends EventEmitter { // The key point here is eventTimeoutLimit, enlarge it is the only way status.timer_notify = setTimeout(async () => { await notifyLark( + this.logger, `There is no new block for ${this.newBlockNotifyLimit / 1000} seconds.`, `This problem occasionally occurs and can be safely ignored, a formal warning will be triggered afer ${this.newBlockWarnLimit / 1000} seconds.`, false, @@ -348,6 +352,7 @@ class Server extends EventEmitter { status.timer_warn = setTimeout(async () => { await notifyLark( + this.logger, `There is no new block for ${this.newBlockWarnLimit / 1000} seconds.`, 'Check if CKB node is offline and the get_tip_header interface is reachable.', true, @@ -357,7 +362,7 @@ class Server extends EventEmitter { } protected async onClose (code: number, reason: string) { - this.logger.warn('Connection closed, will retry connecting later.', { code, reason }) + this.logger.warn(`Connection closed, will retry connecting later.(${code}: ${reason})`) setTimeout(() => { clearTimeout(this.eventStatus.timer_notify) @@ -368,7 +373,7 @@ class Server extends EventEmitter { protected async onError (err: Error) { this.logger.error(`Connection error occurred.(${err})`) - await notifyWithThrottle('ws-error', TIME_1_M * 10, `Connection error occurred.(${err})`, 'Check if CKB node is offline and the get_tip_header interface is reachable.') + await notifyWithThrottle(this.logger, 'ws-error', TIME_1_M * 10, `Connection error occurred.(${err})`, 'Check if CKB node is offline and the get_tip_header interface is reachable.') } protected heartbeat () { @@ -377,7 +382,7 @@ class Server extends EventEmitter { clearTimeout(status.timer) status.timer = setTimeout(async () => { - await notifyWithThrottle('heartbeat', TIME_1_M * 10, 'Connection timeout.', 'Check if CKB node is offline and the get_tip_header interface is reachable.') + await notifyWithThrottle(this.logger, 'heartbeat', TIME_1_M * 10, 'Connection timeout.', 'Check if CKB node is offline and the get_tip_header interface is reachable.') this.ws.terminate() }, TIME_30_S) diff --git a/src/log.ts b/src/log.ts index 8c31304..612d24a 100644 --- a/src/log.ts +++ b/src/log.ts @@ -1,9 +1,17 @@ import { createLogger, format, transports } from 'winston' import config from './config' +import { getCurrentServer } from './utils/env' + +const server = getCurrentServer(); export const rootLogger = createLogger({ level: config.loglevel, + defaultMeta: { + server: server, + pid: process.pid, + env: config.env, + }, format: format.combine( format.metadata(), format.timestamp(), diff --git a/src/utils/env.ts b/src/utils/env.ts new file mode 100644 index 0000000..d3a25eb --- /dev/null +++ b/src/utils/env.ts @@ -0,0 +1,33 @@ +import config from '../config'; +import { networkInterfaces } from 'os'; + + +export function getCurrentServer (): string { + const ip = getCurrentIP() + const servers = config.servers + + if (servers && servers[ip]) { + return servers[ip] + } else { + return ip + } +} + +export function getCurrentIP () { + const nets = networkInterfaces() + let address = 'parse failed' + + for (const name of Object.keys(nets)) { + if (['eth', 'eno', 'ens', 'enp'].includes(name.substring(0, 3))) { + for (const net of nets[name]) { + if (net.family === 'IPv4' && !net.internal) { + address = net.address + break + } + } + } + } + + return address +} + diff --git a/src/utils/helper.ts b/src/utils/helper.ts index 34c4538..0945b8c 100644 --- a/src/utils/helper.ts +++ b/src/utils/helper.ts @@ -1,10 +1,10 @@ import fetch from 'node-fetch' -import { networkInterfaces } from 'os' +import { Logger } from 'winston' import config from '../config' import { CellType, EXCHANGES, LOWEST_CELL_CAPACITY, SinceFlag, TIME_1_M } from '../const' import { getCells, rpcFormat } from './rpc' -import { rootLogger } from '../log' +import { getCurrentServer } from './env' export function remove0x (hex: string) { if (hex.startsWith('0x')) { @@ -63,7 +63,7 @@ export function dataToSince (data: bigint, flag: SinceFlag) { * get ckb price * precision: 1/10000 of 1 cent, 0.000001 */ -export async function getCkbPrice(): Promise { +export async function getCkbPrice(logger: Logger): Promise { // Try to get the quote of CKB/USDT from exchanges, break when it is successful at the first time. let price = -1; for (const exchange of EXCHANGES) { @@ -73,7 +73,6 @@ export async function getCkbPrice(): Promise { price = ticker.close break } catch (err) { - const logger = rootLogger.child({ command: 'update', cell_type: 'unknown' }) logger.error(`Query the quote from ${exchange.name} failed, try the next exchange.`) } } @@ -85,14 +84,13 @@ export async function getCkbPrice(): Promise { return BigInt(Math.floor(price * 100 * 10000)) } -export async function collectInputs (lockScript: CKBComponents.Script, needCapacity: bigint) { +export async function collectInputs (logger: Logger, lockScript: CKBComponents.Script, needCapacity: bigint) { const liveCells = await getCells(lockScript, 'lock', {output_data_len_range: ['0x0', '0x1']}) const addressTotalCapacity = liveCells.map(cell => BigInt(cell.output.capacity)).reduce((prev, curr) => prev + curr, BigInt(0)) if (addressTotalCapacity <= BigInt(10_000_000_000)) { - const logger = rootLogger.child({ command: 'update', cell_type: 'unknown' }) logger.error('The THQ service is about to run out of transaction fee.') - notifyWithThrottle('collect-inputs-warning', TIME_1_M * 10, 'The THQ service is about to run out of transaction fee.', 'Please recharge as soon as possible.') + notifyWithThrottle(logger, 'collect-inputs-warning', TIME_1_M * 10, 'The THQ service is about to run out of transaction fee.', 'Please recharge as soon as possible.') } const inputs = [] @@ -127,7 +125,7 @@ const thresholdSources: { [key: string]: { count: number, startAt: number } } = * @param {string} how_to_fix * @returns {Promise} */ -export async function notifyWithThreshold(source: string, max_count: number, period: number, msg: string, how_to_fix = '') { +export async function notifyWithThreshold(logger: Logger, source: string, max_count: number, period: number, msg: string, how_to_fix = '') { const now = Date.now() if (thresholdSources[source]) { let { count, startAt } = thresholdSources[source]; @@ -143,7 +141,7 @@ export async function notifyWithThreshold(source: string, max_count: number, per if (count > max_count) { // Send notification if it gets out of the max count. thresholdSources[source] = null - await notifyLark(msg, how_to_fix) + await notifyLark(logger, msg, how_to_fix) } else { // Suppress notification if it still does not reach the max count. thresholdSources[source] = { count, startAt } @@ -157,7 +155,7 @@ export async function notifyWithThreshold(source: string, max_count: number, per } const throttleSources = {}; -export async function notifyWithThrottle(source: string, duration: number, msg: string, how_to_fix = '') { +export async function notifyWithThrottle(logger: Logger, source: string, duration: number, msg: string, how_to_fix = '') { // Limit notify frequency. const now = Date.now() if (now - throttleSources[source] <= duration) { @@ -165,10 +163,10 @@ export async function notifyWithThrottle(source: string, duration: number, msg: } throttleSources[source] = now - await notifyLark(msg, how_to_fix) + await notifyLark(logger, msg, how_to_fix) } -export async function notifyLark(msg: string, how_to_fix = '', should_at = true) { +export async function notifyLark(logger: Logger, msg: string, how_to_fix = '', should_at = true) { try { const content: any[] = [ [{tag: 'text', un_escaped: true, text: `server: ${getCurrentServer()}`}], @@ -198,7 +196,6 @@ export async function notifyLark(msg: string, how_to_fix = '', should_at = true) console.error(`helper: send Lark notify failed, response ${res.status} ${res.statusText}`) } } else { - const logger = rootLogger.child({ command: 'update', cell_type: 'unknown' }) logger.warn(`msg: ${msg}, how_to_fix: ${how_to_fix}`) } } catch (e) { @@ -206,35 +203,6 @@ export async function notifyLark(msg: string, how_to_fix = '', should_at = true) } } -export function getCurrentServer() { - const ip = getCurrentIP() - const servers = config.servers - - if (servers && servers[ip]) { - return servers[ip] - } else { - ip - } -} - -export function getCurrentIP() { - const nets = networkInterfaces() - let address = 'parse failed'; - - for (const name of Object.keys(nets)) { - if (name.startsWith('eno') || name.startsWith('eth')) { - for (const net of nets[name]) { - if (net.family === 'IPv4' && !net.internal) { - address = net.address - break - } - } - } - } - - return address -} - export function sortLiveCells(cells: IndexerLiveCell[]): IndexerLiveCell[] { cells.sort((a, b) => { return a.block_number > b.block_number ? 1 : (a.block_number < b.block_number ? -1 : 0)