From 7631f2f522de38f0d61bf6eeb5fb69718fd3bba2 Mon Sep 17 00:00:00 2001 From: tilacog Date: Thu, 9 Nov 2023 15:23:15 -0300 Subject: [PATCH] common, agent: logging improvements --- packages/indexer-agent/src/agent.ts | 17 ++++++-- packages/indexer-agent/src/commands/start.ts | 13 +----- .../src/__tests__/grafting.test.ts | 20 +++++---- packages/indexer-common/src/grafting.ts | 43 +++++++++++++++++-- packages/indexer-common/src/graph-node.ts | 9 ++-- .../indexer-common/src/subgraph-deployment.ts | 18 +++++--- packages/indexer-common/src/subgraphs.ts | 2 +- 7 files changed, 83 insertions(+), 39 deletions(-) diff --git a/packages/indexer-agent/src/agent.ts b/packages/indexer-agent/src/agent.ts index b91801786..eec4b6aab 100644 --- a/packages/indexer-agent/src/agent.ts +++ b/packages/indexer-agent/src/agent.ts @@ -36,6 +36,7 @@ import { networkIsL2, networkIsL1, DeploymentManagementMode, + deploySubgraph, } from '@graphprotocol/indexer-common' import PQueue from 'p-queue' @@ -195,6 +196,7 @@ export class Agent { offchainSubgraphs: SubgraphDeploymentID[] autoMigrationSupport: boolean deploymentManagement: DeploymentManagementMode + ipfsURL: URL constructor( logger: Logger, @@ -206,6 +208,7 @@ export class Agent { offchainSubgraphs: SubgraphDeploymentID[], autoMigrationSupport: boolean, deploymentManagement: DeploymentManagementMode, + ipfsURL: URL, ) { this.logger = logger.child({ component: 'Agent' }) this.metrics = metrics @@ -215,6 +218,7 @@ export class Agent { this.offchainSubgraphs = offchainSubgraphs this.autoMigrationSupport = !!autoMigrationSupport this.deploymentManagement = deploymentManagement + this.ipfsURL = ipfsURL } async start(): Promise { @@ -986,10 +990,15 @@ export class Agent { deployment: deployment.display, }) - // Ensure the deployment is deployed to the indexer - // Note: we're not waiting here, as sometimes indexing a subgraph - // will block if the IPFS files cannot be retrieved - await this.graphNode.ensure(name, deployment) + await deploySubgraph( + name, + deployment, + this.graphNode, + this.ipfsURL, + this.indexerManagement, + 'eip155:5', + this.logger, + ) }), ) diff --git a/packages/indexer-agent/src/commands/start.ts b/packages/indexer-agent/src/commands/start.ts index f701a52b8..e47f8d216 100644 --- a/packages/indexer-agent/src/commands/start.ts +++ b/packages/indexer-agent/src/commands/start.ts @@ -226,18 +226,6 @@ export const start = { default: 100, group: 'Query Fees', }) - .option('ipfs-endpoint', { - description: `Endpoint to an ipfs node to quickly query subgraph manifest data`, - type: 'string', - default: 'https://ipfs.network.thegraph.com', - group: 'Indexer Infrastructure', - }) - .option('auto-graft-resolver-limit', { - description: `Maximum depth of grafting dependency to automatically resolve`, - type: 'number', - default: 0, - group: 'Indexer Infrastructure', - }) .option('inject-dai', { description: 'Inject the GRT to DAI/USDC conversion rate into cost model variables', @@ -648,6 +636,7 @@ export async function run( argv.offchainSubgraphs.map((s: string) => new SubgraphDeploymentID(s)), argv.enableAutoMigrationSupport, argv.deploymentManagement, + argv.ipfsEndpoint, ) await agent.start() } diff --git a/packages/indexer-common/src/__tests__/grafting.test.ts b/packages/indexer-common/src/__tests__/grafting.test.ts index baa007bb0..5f226c61a 100644 --- a/packages/indexer-common/src/__tests__/grafting.test.ts +++ b/packages/indexer-common/src/__tests__/grafting.test.ts @@ -6,11 +6,13 @@ import { } from '../grafting' import { SubgraphDeploymentID } from '@graphprotocol/common-ts' import { IndexerErrorCode } from '../errors' -import { SubgraphDeploymentDecisionKind } from '../types' +import { LoggerInterface, SubgraphDeploymentDecisionKind } from '../types' // Create a mock for the fetchSubgraphManifest function const fakeSubgraphManifestResolver = jest.fn() +const fakeLogger = jest.fn() as unknown as LoggerInterface + // Fake IPFS Hashes: const target = 'QmWaVSK24D1m53Ej2PaddWcb1HZKAV4bjiKkrUwtP3HrZX' const base1 = 'QmWaVSK24D1m53Ej2PaddWcb1HZKAV4bjiKkrUwtP3HrYj' @@ -93,7 +95,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { let threwError = false try { - determineSubgraphDeploymentDecisions(subgraphLineage) + determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) } catch (err) { expect(err.code).toStrictEqual(IndexerErrorCode.IE075) expect(err.cause).toStrictEqual( @@ -122,7 +124,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { }, ], } - expect(determineSubgraphDeploymentDecisions(subgraphLineage)).toEqual([]) + expect(determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger)).toEqual([]) }) test('should throw an error if an unsynced base is unhealthy', () => { @@ -146,7 +148,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { let threwError = false try { - determineSubgraphDeploymentDecisions(subgraphLineage) + determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) } catch (err) { expect(err.code).toStrictEqual(IndexerErrorCode.IE075) expect(err.cause).toStrictEqual({ @@ -169,7 +171,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { }, ], } - const decisions = determineSubgraphDeploymentDecisions(subgraphLineage) + const decisions = determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) const expected = [ { deployment: new SubgraphDeploymentID(base1), @@ -196,7 +198,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { }, ], } - const decisions = determineSubgraphDeploymentDecisions(subgraphLineage) + const decisions = determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) const expected = [ { deployment: new SubgraphDeploymentID(base2), @@ -224,7 +226,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { }, ], } - const decisions = determineSubgraphDeploymentDecisions(subgraphLineage) + const decisions = determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) const expected = [ { deployment: new SubgraphDeploymentID(base1), @@ -268,7 +270,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { }, ], } - const decisions = determineSubgraphDeploymentDecisions(subgraphLineage) + const decisions = determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) const expected = [ { deployment: new SubgraphDeploymentID(base3), @@ -332,7 +334,7 @@ describe('determineSubgraphDeploymentDecisions function', () => { }, ], } - const decisions = determineSubgraphDeploymentDecisions(subgraphLineage) + const decisions = determineSubgraphDeploymentDecisions(subgraphLineage, fakeLogger) const expected = [ { deployment: new SubgraphDeploymentID(base4), diff --git a/packages/indexer-common/src/grafting.ts b/packages/indexer-common/src/grafting.ts index 67e763a6c..50e673cec 100644 --- a/packages/indexer-common/src/grafting.ts +++ b/packages/indexer-common/src/grafting.ts @@ -120,9 +120,15 @@ export async function getIndexingStatus( export function determineSubgraphDeploymentDecisions( subgraphLineage: SubgraphLineageWithStatus, + parentLogger: LoggerInterface, ): GraftBaseDeploymentDecision[] { const deploymentDecisions: GraftBaseDeploymentDecision[] = [] + const logger = parentLogger.child({ + function: 'determineSubgraphDeploymentDecisions', + subgraphLineage: formatLineage(subgraphLineage), + }) + // Check lineage size before making any assumptions. if (!subgraphLineage.bases.length) { throw indexerError( @@ -143,10 +149,17 @@ export function determineSubgraphDeploymentDecisions( for (let i = lastIndex; i >= 0; i--) { const graft = subgraphLineage.bases[i] const desiredBlockHeight = graft.block + const traceLogger = logger.child({ + graft: formatDeploymentContainer(graft), + earliestValidBaseIndex, + graftIndex: i, + }) + traceLogger.trace('Inspecting graft base deployment status') if (!graft.indexingStatus || !graft.indexingStatus.latestBlock) { // Ignore undeployed graft bases beyond the earliest valid one. if (i <= earliestValidBaseIndex) { // Graph Node is not aware of this subgraph deployment. We must deploy it and look no further. + traceLogger.trace('Deploy candidate found') deploymentDecisions.push({ deployment: graft.deployment, kind: SubgraphDeploymentDecisionKind.DEPLOY, @@ -157,7 +170,9 @@ export function determineSubgraphDeploymentDecisions( } else { // Deployment exists. // Is it sufficiently synced? + traceLogger.trace('Deployment exists') if (graft.indexingStatus.latestBlock.number >= desiredBlockHeight) { + traceLogger.trace('Deployment is sufficiently synced') // If so, we can stop syncing it. deploymentDecisions.push({ deployment: graft.deployment, @@ -187,9 +202,6 @@ export async function queryGraftBaseStatuses( concurrency: number = 5, ): Promise { const logger = parentLogger.child({ function: 'queryGraftBaseStatuses' }) - logger.debug('Attempting to resolve graft bases for target subgraph') - - // Fetch deployment details for each graft base logger.debug('Querying Graph-Node for graft bases deployment status') const graftBasesDeploymentStatus = await pMap( subgraphLineage.bases, @@ -199,9 +211,34 @@ export async function queryGraftBaseStatuses( concurrency, }, ) + logger.trace('Got graft bases deployment statuses from Graph-Node', { + graftBasesDeploymentStatus: formatDeploymentContainers(graftBasesDeploymentStatus), + }) return { target: subgraphLineage.target, bases: graftBasesDeploymentStatus, } } + +// Logging utilities + +export function formatDeploymentContainer(base: { deployment: SubgraphDeploymentID }) { + return { + ...base, + deployment: base.deployment.display, + } +} + +export function formatDeploymentContainers( + bases: { deployment: SubgraphDeploymentID }[], +): any { + return bases.map(formatDeploymentContainer) +} + +export function formatLineage(lineage: SubgraphLineageWithStatus): any { + return { + target: lineage.target.display, + bases: formatDeploymentContainers(lineage.bases), + } +} diff --git a/packages/indexer-common/src/graph-node.ts b/packages/indexer-common/src/graph-node.ts index 946d6bb72..29ca2c41d 100644 --- a/packages/indexer-common/src/graph-node.ts +++ b/packages/indexer-common/src/graph-node.ts @@ -189,7 +189,7 @@ export class GraphNode implements GraphNodeInterface { async indexNodes(): Promise { try { - this.logger.trace(`Querying indexing statuses`) + this.logger.trace(`Querying index nodes`) const result = await this.status .query(gql` { @@ -205,7 +205,7 @@ export class GraphNode implements GraphNodeInterface { throw result.error } - this.logger.trace(`Queried indexing statuses`, { + this.logger.trace(`Queried index nodes`, { data: result.data, }) @@ -461,7 +461,6 @@ export class GraphNode implements GraphNodeInterface { } catch (error) { throw indexerError(IndexerErrorCode.IE018, error) } - return ( result.data.indexingStatuses // eslint-disable-next-line @typescript-eslint/no-explicit-any @@ -473,7 +472,7 @@ export class GraphNode implements GraphNodeInterface { } try { - return await pRetry(queryIndexingStatuses, { + const indexingStatuses = await pRetry(queryIndexingStatuses, { retries: 5, maxTimeout: 10000, onFailedAttempt: (err) => { @@ -485,6 +484,8 @@ export class GraphNode implements GraphNodeInterface { }) }, } as pRetry.Options) + this.logger.trace('Queried indexing statuses', indexingStatuses) + return indexingStatuses } catch (error) { const err = indexerError(IndexerErrorCode.IE018, error) this.logger.error(`Failed to query indexing status API`, { diff --git a/packages/indexer-common/src/subgraph-deployment.ts b/packages/indexer-common/src/subgraph-deployment.ts index 3b03e4e13..236d3aded 100644 --- a/packages/indexer-common/src/subgraph-deployment.ts +++ b/packages/indexer-common/src/subgraph-deployment.ts @@ -8,6 +8,8 @@ import { SubgraphLineage, queryGraftBaseStatuses, GraftBaseDeploymentDecision, + formatGraftBases, + formatGraftBase, } from './grafting' import { SubgraphIdentifierType, fetchSubgraphManifest } from './subgraphs' import { @@ -55,9 +57,9 @@ export async function deploySubgraph( // Inspect target subgraph's grafting lineage. const logger = parentLogger.child({ function: 'deploySubgraph', - subgraphDeployment, + subgraphDeployment: subgraphDeployment.display, }) - logger.debug('Attempting to resolve graft bases for target subgraph.') + logger.debug('Resolving graft bases for target subgraph deployment.') const subgraphManifestResolver = async (subgraphID: SubgraphDeploymentID) => await fetchSubgraphManifest(ipfsURL, subgraphID, logger) const subgraphLineage = await discoverLineage( @@ -90,10 +92,13 @@ async function deployGraftedSubgraph( ): Promise { const logger = parentLogger.child({ function: 'deployGraftedSubgraph', - targetSubgraph: subgraphLineage.target.ipfsHash, - graftBases: subgraphLineage.bases, + targetSubgraph: subgraphLineage.target.display, + graftBases: formatGraftBases(subgraphLineage.bases), }) - logger.debug('Attempting to deploy first viable base for grafted subgraph.') + logger.debug( + 'Target subgraph deployment has graft bases. ' + + 'Deploying first viable base for grafted subgraph.', + ) // Fetch the deployment status for all graft bases. const lineageDeploymentStatus = await queryGraftBaseStatuses( @@ -105,6 +110,7 @@ async function deployGraftedSubgraph( // Inspect if we need to deploy or remove a sufficiently synced graft base. const deploymentDecisions = determineSubgraphDeploymentDecisions( lineageDeploymentStatus, + logger, ) for (const deploymentDecision of deploymentDecisions) { switch (deploymentDecision.kind) { @@ -193,7 +199,7 @@ async function deleteTemporaryIndexingRule( } const logger = parentLogger.child({ identifier, - deploymentDecision, + deploymentDecision: formatGraftBase(deploymentDecision), }) // Query indexing management client for a indexing rule matching the IPFS hash of this diff --git a/packages/indexer-common/src/subgraphs.ts b/packages/indexer-common/src/subgraphs.ts index e01e207dd..e8420503f 100644 --- a/packages/indexer-common/src/subgraphs.ts +++ b/packages/indexer-common/src/subgraphs.ts @@ -536,7 +536,7 @@ export async function fetchSubgraphManifest( const logger = parentLogger.child({ function: 'fetchSubgraphManifest', - subgraphDeployment: SubgraphDeploymentID, + targetDeployment: targetDeployment.display, subgraphManifestSearchURL, })