From 46b26a05139d12894ed5a0f58ccbdc73583d2706 Mon Sep 17 00:00:00 2001 From: Rhys Bartels-Waller Date: Thu, 29 Apr 2021 16:25:12 +1000 Subject: [PATCH] fix: Reorder logging arguments based on Bunyan interface --- .../src/CardanoNodeClient.ts | 18 +++-- .../src/DataSyncController.ts | 51 +++++++------- packages/api-cardano-db-hasura/src/Db.ts | 12 ++-- .../api-cardano-db-hasura/src/HasuraClient.ts | 66 +++++++++++-------- packages/server/src/Server.ts | 18 ++--- .../util/src/data_fetching/DataFetcher.ts | 4 +- 6 files changed, 93 insertions(+), 76 deletions(-) diff --git a/packages/api-cardano-db-hasura/src/CardanoNodeClient.ts b/packages/api-cardano-db-hasura/src/CardanoNodeClient.ts index 5b00b9d0..cf16bda7 100644 --- a/packages/api-cardano-db-hasura/src/CardanoNodeClient.ts +++ b/packages/api-cardano-db-hasura/src/CardanoNodeClient.ts @@ -29,13 +29,13 @@ export class CardanoNodeClient { public async getTipSlotNo () { const tip = await this.stateQueryClient.ledgerTip() const slotNo = tip === 'origin' ? 0 : tip.slot - this.logger.debug('getTipSlotNo', { module: 'CardanoNodeClient', value: slotNo }) + this.logger.debug({ module: 'CardanoNodeClient', slotNo }, 'getTipSlotNo') return slotNo } public async getProtocolParams () { const protocolParams = await this.stateQueryClient.currentProtocolParameters() - this.logger.debug('getProtocolParams', { module: 'CardanoNodeClient', value: protocolParams }) + this.logger.debug({ module: 'CardanoNodeClient', protocolParams }, 'getProtocolParams') return protocolParams } @@ -45,7 +45,7 @@ export class CardanoNodeClient { this.stateQueryClient = await createStateQueryClient(options) this.txSubmissionClient = await createTxSubmissionClient(options) if (!(await this.isInCurrentEra())) { - this.logger.warn('cardano-node is still synchronizing', { module: 'CardanoNodeClient' }) + this.logger.warn({ module: 'CardanoNodeClient' }, 'cardano-node is still synchronizing') throw new Error() } }, { @@ -60,13 +60,11 @@ export class CardanoNodeClient { private async isInCurrentEra () { const { protocolVersion } = await this.getProtocolParams() - this.logger.debug('Comparing current protocol params with last known major version from cardano-node config', { + this.logger.debug({ module: 'CardanoNodeClient', - value: { - currentProtocolVersion: protocolVersion, - lastConfiguredMajorVersion: this.lastConfiguredMajorVersion - } - }) + currentProtocolVersion: protocolVersion, + lastConfiguredMajorVersion: this.lastConfiguredMajorVersion + }, 'Comparing current protocol params with last known major version from cardano-node config') return protocolVersion.major >= this.lastConfiguredMajorVersion } @@ -81,7 +79,7 @@ export class CardanoNodeClient { try { await this.txSubmissionClient.submitTx(transaction) const hash = getHashOfSignedTransaction(transaction) - this.logger.info('submitTransaction', { module: 'CardanoNodeClient', hash }) + this.logger.info({ module: 'CardanoNodeClient', hash }, 'submitTransaction') return hash } catch (error) { if (!isEraMismatch(error.message)) { diff --git a/packages/api-cardano-db-hasura/src/DataSyncController.ts b/packages/api-cardano-db-hasura/src/DataSyncController.ts index d4d49e65..a14fdb75 100644 --- a/packages/api-cardano-db-hasura/src/DataSyncController.ts +++ b/packages/api-cardano-db-hasura/src/DataSyncController.ts @@ -77,8 +77,8 @@ export class DataSyncController { const batchSize = 500 const assetsWithoutMetadataCount = await this.hasuraClient.assetsWithoutMetadataCount({ _lte: 2 }) this.logger.debug( - 'Newly discovered assets missing metadata', - { module: 'DataSyncController', value: assetsWithoutMetadataCount } + { module: 'DataSyncController', qty: assetsWithoutMetadataCount }, + 'Newly discovered assets missing metadata' ) const batchQty = Math.ceil(assetsWithoutMetadataCount / batchSize) let totalCount = 0 @@ -93,7 +93,7 @@ export class DataSyncController { } return totalCount }, - pollingInterval.initial, + pollingInterval.initial * 10, this.logger ), ongoing: new DataFetcher( @@ -103,8 +103,8 @@ export class DataSyncController { const assetsEligibleForMetadataRefreshCount = await this.hasuraClient.assetsEligibleForMetadataRefreshCount({ _gt: 2 }) this.logger.debug( - 'Assets eligible for metadata refresh', - { module: 'DataSyncController', value: assetsEligibleForMetadataRefreshCount } + { module: 'DataSyncController', qty: assetsEligibleForMetadataRefreshCount }, + 'Assets eligible for metadata refresh' ) const batchQty = Math.ceil(assetsEligibleForMetadataRefreshCount / batchSize) let totalCount = 0 @@ -119,7 +119,7 @@ export class DataSyncController { } return totalCount }, - pollingInterval.ongoing, + pollingInterval.ongoing * 10, this.logger ) } @@ -130,8 +130,8 @@ export class DataSyncController { const batchSize = 500 const distinctAssetsInTokensCount = await this.hasuraClient.distinctAssetsInTokensCount() this.logger.debug( - 'Distinct assets in tokens count', - { module: 'DataSyncController', value: distinctAssetsInTokensCount } + { module: 'DataSyncController', qty: distinctAssetsInTokensCount }, + 'Distinct assets in tokens count' ) const batchQty = Math.ceil(distinctAssetsInTokensCount / batchSize) let totalCount = 0 @@ -142,11 +142,13 @@ export class DataSyncController { const assetsAlreadyInDb = await this.hasuraClient.getAssetsById(assetsInBatch.map(asset => asset.assetId)) this.logger.debug( - 'Assets from tokens', { module: 'DataSyncController', - value: { batch: i, qty: assetsInBatch.length, existing: assetsAlreadyInDb.length } - } + batch: i, + qty: assetsInBatch.length, + existing: assetsAlreadyInDb.length + }, + 'Assets from tokens' ) const newAssets = assetsInBatch .filter(asset => assetsAlreadyInDb.find(existingAsset => @@ -158,19 +160,22 @@ export class DataSyncController { policyId: asset.policyId, metadataFetchAttempts: 0 })) - this.logger.debug('asset IDs diff', { module: 'DataSyncController', value: newAssets.length }) + this.logger.debug( + { module: 'DataSyncController', qty: newAssets.length }, + 'asset IDs diff' + ) if (newAssets.length > 0) { totalCount = totalCount + newAssets.length await this.hasuraClient.insertAssets(newAssets) this.logger.debug( - 'synchronised assets table from tokens', - { module: 'DataSyncController', value: { batch: i, qty: newAssets.length } } + { module: 'DataSyncController', batch: i, qty: newAssets.length }, + 'synchronised assets table from tokens' ) } } return totalCount }, - 120 * 1000, + 1200 * 1000, this.logger ) } @@ -196,8 +201,8 @@ export class DataSyncController { ...{ metadataHash: hash(obj.metadata) } })) this.logger.debug( - 'Metadata with updates to apply', - { module: 'DataSyncController', value: assetsWithMetadata.length } + { module: 'DataSyncController', qty: assetsWithMetadata.length }, + 'Metadata with updates to apply' ) if (assetsWithMetadata.length > 0) { await this.hasuraClient.addMetadata(assetsWithMetadata) @@ -220,7 +225,7 @@ export class DataSyncController { return response.data.subjects } catch (error) { if (error.code === 'ENOTFOUND') { - this.logger.error(error.message) + this.logger.error({ err: error }) } else { throw error } @@ -251,7 +256,7 @@ export class DataSyncController { } public async initialize () { - this.logger.info('Initializing', { module: 'DataSyncController' }) + this.logger.info({ module: 'DataSyncController' }, 'Initializing') await this.ensureAssetFingerprints() await this.assetSynchronizer.initialize() if (this.metadataServerUri) { @@ -259,16 +264,18 @@ export class DataSyncController { await this.metadataSynchronizer.initial.initialize() await this.metadataSynchronizer.ongoing.initialize() } - this.logger.info('Initialized', { module: 'DataSyncController' }) + this.logger.info({ module: 'DataSyncController' }, 'Initialized') } public async shutdown () { - this.logger.info('Shutting down', { module: 'DataSyncController' }) + this.logger.info({ module: 'DataSyncController' }, 'Shutting down') if (this.metadataServerUri) { await this.metadataSynchronizer.initial.shutdown() await this.metadataSynchronizer.ongoing.shutdown() } await this.assetSynchronizer.shutdown() - this.logger.info('Shutdown complete', { module: 'DataSyncController' }) + this.logger.info( + { module: 'DataSyncController' }, + 'Shutdown complete') } } diff --git a/packages/api-cardano-db-hasura/src/Db.ts b/packages/api-cardano-db-hasura/src/Db.ts index 8cb43aac..8c5c4e68 100644 --- a/packages/api-cardano-db-hasura/src/Db.ts +++ b/packages/api-cardano-db-hasura/src/Db.ts @@ -16,33 +16,33 @@ export class Db { public async init ({ onDbSetup }: { onDbSetup: Function }): Promise { this.pgSubscriber.events.on('connected', async () => { - this.logger.debug('DbClient.pgSubscriber: Connected') + this.logger.debug({ module: 'Db' }, 'pgSubscriber: Connected') await onDbSetup() }) this.pgSubscriber.events.on('reconnect', (attempt) => { - this.logger.warn(`DbClient.pgSubscriber: Reconnecting attempt ${attempt}`) + this.logger.warn({ module: 'Db' }, `pgSubscriber: Reconnecting attempt ${attempt}`) }) this.pgSubscriber.events.on('error', (error) => { - this.logger.error('DbClient.pgSubscriber: Fatal database connection error:', error) + this.logger.error({ module: 'Db', err: error }, 'pgSubscriber') process.exit(1) }) this.pgSubscriber.notifications.on('cardano_db_sync_startup', async payload => { switch (payload) { case 'init' : - this.logger.warn('DbClient.pgSubscriber: cardano-db-sync-extended starting, schema will be reset') + this.logger.warn({ module: 'Db' }, 'pgSubscriber: cardano-db-sync-extended starting, schema will be reset') break case 'db-setup' : await onDbSetup() break default : - this.logger.error(`DbClient.pgSubscriber: Unknown message payload ${payload}`) + this.logger.error({ module: 'Db' }, `DbClient.pgSubscriber: Unknown message payload ${payload}`) } }) try { await this.pgSubscriber.connect() await this.pgSubscriber.listenTo('cardano_db_sync_startup') } catch (error) { - this.logger.error(error) + this.logger.error({ err: error }) } } diff --git a/packages/api-cardano-db-hasura/src/HasuraClient.ts b/packages/api-cardano-db-hasura/src/HasuraClient.ts index e2effea1..8e5b054e 100644 --- a/packages/api-cardano-db-hasura/src/HasuraClient.ts +++ b/packages/api-cardano-db-hasura/src/HasuraClient.ts @@ -49,7 +49,7 @@ export class HasuraClient { if (error.message !== notInCurrentEraMessage) { throw error } - this.logger.debug(error.message) + this.logger.debug({ err: error }) } }, pollingInterval, @@ -58,9 +58,12 @@ export class HasuraClient { this.currentProtocolVersionFetcher = new DataFetcher( 'ProtocolParams', async () => { - const getCurrentProtocolVersion = await this.getCurrentProtocolVersion() - this.logger.debug(getCurrentProtocolVersion) - return getCurrentProtocolVersion + const currentProtocolVersion = await this.getCurrentProtocolVersion() + this.logger.debug( + { module: 'HasuraClient', currentProtocolVersion }, + 'currentProtocolVersionFetcher' + ) + return currentProtocolVersion }, 1000 * 60, this.logger @@ -115,7 +118,7 @@ export class HasuraClient { withdrawals_aggregate: withdrawalsAggregate } = result if (cardano[0].currentEpoch === null) { - this.logger.debug(notInCurrentEraMessage) + this.logger.debug({ module: 'HasuraClient' }, notInCurrentEraMessage) throw new Error(notInCurrentEraMessage) } const rewards = new BigNumber(rewardsAggregate.aggregate.sum.amount) @@ -136,7 +139,7 @@ export class HasuraClient { if (error) { reject(error) } - this.logger.debug(stdout) + this.logger.debug({ module: 'HasuraClient' }, stdout) resolve() } ) @@ -144,7 +147,7 @@ export class HasuraClient { } public async initialize () { - this.logger.info('Initializing', { module: 'HasuraClient' }) + this.logger.info({ module: 'HasuraClient' }, 'Initializing') await this.applySchemaAndMetadata() await pRetry(async () => { this.schema = await this.buildHasuraSchema() @@ -156,7 +159,7 @@ export class HasuraClient { this.logger ) }) - this.logger.debug('graphql-engine setup', { module: 'HasuraClient' }) + this.logger.debug({ module: 'HasuraClient' }, 'graphql-engine setup') await pRetry(async () => { const result = await this.client.request( gql`query { @@ -168,7 +171,7 @@ export class HasuraClient { }` ) if (result.cardano[0].currentEpoch === null) { - this.logger.debug(notInCurrentEraMessage) + this.logger.debug({ module: 'HasuraClient' }, notInCurrentEraMessage) throw new Error(notInCurrentEraMessage) } }, { @@ -179,10 +182,10 @@ export class HasuraClient { this.logger ) }) - this.logger.debug('DB is in current era', { module: 'HasuraClient' }) + this.logger.debug({ module: 'HasuraClient' }, 'DB is in current era') await this.currentProtocolVersionFetcher.initialize() await this.adaPotsToCalculateSupplyFetcher.initialize() - this.logger.info('Initialized', { module: 'HasuraClient' }) + this.logger.info({ module: 'HasuraClient' }, 'Initialized') } public async shutdown () { @@ -229,7 +232,7 @@ export class HasuraClient { }) return fetchResult.json() } catch (error) { - this.logger.error(error) + this.logger.error({ err: error }) throw error } } @@ -488,7 +491,7 @@ export class HasuraClient { ) return result.assets_aggregate.aggregate.count } catch (error) { - this.logger.error(error) + this.logger.error({ err: error }) throw error } } @@ -537,8 +540,8 @@ export class HasuraClient { }` ) this.logger.debug( - 'Assets without a fingerprint stored', - { module: 'HasuraClient', value: result.assets_aggregate.aggregate.count } + { module: 'HasuraClient', qty: result.assets_aggregate.aggregate.count }, + 'Assets without a fingerprint stored' ) return new BigNumber(result.assets_aggregate.aggregate.count).isGreaterThan(0) } @@ -611,7 +614,7 @@ export class HasuraClient { ) return result.assets_aggregate.aggregate.count } catch (error) { - this.logger.error(error) + this.logger.error({ err: error }) throw error } } @@ -651,18 +654,21 @@ export class HasuraClient { public async isInCurrentEra () { const protocolVersion = this.currentProtocolVersionFetcher.value - this.logger.debug('Comparing current protocol params with last known major version from cardano-node config', { + this.logger.debug({ module: 'CardanoNodeClient', - value: { - currentProtocolVersion: protocolVersion, - lastConfiguredMajorVersion: protocolVersion.major - } - }) + currentProtocolVersion: protocolVersion, + lastConfiguredMajorVersion: protocolVersion.major + }, + 'Comparing current protocol params with last known major version from cardano-node config' + ) return protocolVersion.major >= this.lastConfiguredMajorVersion } public addAssetFingerprints (assets: Pick[]) { - this.logger.debug('Adding fingerprint to assets', { module: 'HasuraClient', value: assets.length }) + this.logger.debug( + { module: 'HasuraClient', qty: assets.length }, + 'Adding fingerprint to assets' + ) return this.client.request( gql`mutation AddAssetFingerprint($assets: [Asset_insert_input!]!) { insert_assets( @@ -684,7 +690,10 @@ export class HasuraClient { } public addMetadata (assets: (Pick & { metadataHash: string })[]) { - this.logger.info('Adding metadata to assets', { module: 'HasuraClient', value: assets.length }) + this.logger.info( + { module: 'HasuraClient', qty: assets.length }, + 'Adding metadata to assets' + ) return this.client.request( gql`mutation AddAssetMetadata($assets: [Asset_insert_input!]!) { insert_assets( @@ -714,8 +723,8 @@ export class HasuraClient { public incrementMetadataFetchAttempts (assetIds: AssetWithoutTokens['assetId'][]) { this.logger.debug( - 'Incrementing metadata fetch attempt', - { module: 'HasuraClient', value: assetIds.length } + { module: 'HasuraClient', qty: assetIds.length }, + 'Incrementing metadata fetch attempt' ) return this.client.request( gql`mutation IncrementAssetMetadataFetchAttempt( @@ -742,7 +751,10 @@ export class HasuraClient { } public async insertAssets (assets: AssetWithoutTokens[]) { - this.logger.debug('inserting assets found in tokens', { module: 'HasuraClient', value: assets.length }) + this.logger.debug( + { module: 'HasuraClient', qty: assets.length }, + 'inserting assets found in tokens' + ) const result = await this.client.request( gql`mutation InsertAssets($assets: [Asset_insert_input!]!) { insert_assets(objects: $assets) { diff --git a/packages/server/src/Server.ts b/packages/server/src/Server.ts index 42c38951..bc4e3235 100644 --- a/packages/server/src/Server.ts +++ b/packages/server/src/Server.ts @@ -56,9 +56,9 @@ export class Server { const file = await fs.readFile(this.config.allowListPath, 'utf8') allowList = JSON.parse(file) this.app.use('/', json(), allowListMiddleware(allowList)) - this.logger.info('The server will only allow only operations from the provided list') + this.logger.info({ module: 'Server' }, 'The server will only allow only operations from the provided list') } catch (error) { - this.logger.error(`Cannot read or parse allow-list JSON file at ${this.config.allowListPath}`) + this.logger.error({ module: 'Server' }, `Cannot read or parse allow-list JSON file at ${this.config.allowListPath}`) throw error } } @@ -67,7 +67,7 @@ export class Server { throw new TracingRequired('Prometheus') } plugins.push(prometheusMetricsPlugin(this.app)) - this.logger.info('Prometheus metrics will be served at /metrics') + this.logger.info({ module: 'Server' }, 'Prometheus metrics will be served at /metrics') } if (this.config.queryDepthLimit) { validationRules.push(depthLimit(this.config.queryDepthLimit)) @@ -94,10 +94,10 @@ export class Server { async start () { this.httpServer = await listenPromise(this.app, this.config.apiPort, this.config.listenAddress) - this.logger.info(`GraphQL HTTP server at http://${this.config.listenAddress}:` + + this.logger.info({ module: 'Server' }, `GraphQL HTTP server at http://${this.config.listenAddress}:` + `${this.config.apiPort}${this.apolloServer.graphqlPath} started` ) - this.logger.debug('Checking DB status', { module: 'Server' }) + this.logger.debug({ module: 'Server' }, 'Checking DB status') this.syncProgress = setIntervalAsync(async () => { const result = await this.apolloServer.executeOperation( { @@ -110,14 +110,14 @@ export class Server { } ) if (result.errors !== undefined) { - this.logger.debug(JSON.stringify(result.errors)) + this.logger.debug({ module: 'Server' }, JSON.stringify(result.errors)) return } if (result.data.cardanoDbMeta.initialized) { - this.logger.info('DB ready') + this.logger.info({ module: 'Server' }, 'DB ready') await clearIntervalAsync(this.syncProgress) } else { - this.logger.info(`DB sync progress: ${result.data.cardanoDbMeta.syncPercentage} %`) + this.logger.info({ module: 'Server' }, `DB sync progress: ${result.data.cardanoDbMeta.syncPercentage} %`) } }, 5000) } @@ -126,7 +126,7 @@ export class Server { await clearIntervalAsync(this.syncProgress) if (this.httpServer !== undefined) { this.httpServer.close() - this.logger.info(`GraphQL HTTP server at http://${this.config.listenAddress}:` + + this.logger.info({ module: 'Server' }, `GraphQL HTTP server at http://${this.config.listenAddress}:` + `${this.config.apiPort}${this.apolloServer.graphqlPath} shutting down` ) } diff --git a/packages/util/src/data_fetching/DataFetcher.ts b/packages/util/src/data_fetching/DataFetcher.ts index 66f190c4..7e231108 100644 --- a/packages/util/src/data_fetching/DataFetcher.ts +++ b/packages/util/src/data_fetching/DataFetcher.ts @@ -25,10 +25,10 @@ export class DataFetcher { public async initialize () { await this.fetch() - this.logger.debug('initial value fetched', { module: 'DataFetcher', instance: this.name, value: this.value }) + this.logger.debug({ module: 'DataFetcher', instance: this.name, value: this.value }, 'Initial value fetched') this.pollingQueryTimer = setIntervalAsync(async () => { await this.fetch() - this.logger.debug(`value fetched after ${this.pollingInterval / 1000} seconds`, { module: 'DataFetcher', instance: this.name, value: this.value }) + this.logger.debug({ module: 'DataFetcher', instance: this.name, value: this.value }, `value fetched after ${this.pollingInterval / 1000} seconds`) }, this.pollingInterval) }