From dabc3459d7e286c94c5cb629f159165414c1477b Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Thu, 22 Jun 2023 14:46:40 -0400 Subject: [PATCH 01/12] fix: non-zero finality block count for chains with instant finality --- packages/core/src/config/networks.ts | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/packages/core/src/config/networks.ts b/packages/core/src/config/networks.ts index de73dc49e..b159d3050 100644 --- a/packages/core/src/config/networks.ts +++ b/packages/core/src/config/networks.ts @@ -115,7 +115,7 @@ function getFinalityBlockCount(network: { chainId: number }) { // Optimism. case 10: case 420: - finalityBlockCount = 0; + finalityBlockCount = 5; break; // Polygon. case 137: @@ -125,10 +125,13 @@ function getFinalityBlockCount(network: { chainId: number }) { // Arbitrum. case 42161: case 421613: - finalityBlockCount = 0; + finalityBlockCount = 40; break; + // Zora. + case 7777777: + finalityBlockCount = 5; default: - finalityBlockCount = 0; + finalityBlockCount = 5; } return finalityBlockCount; From 7d91d6da1c7d4368dc5d5572db7cd18bde36a75d Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Thu, 22 Jun 2023 14:47:04 -0400 Subject: [PATCH 02/12] feat: handle thirdweb getLogs limit error --- packages/core/src/historical-sync/service.ts | 25 ++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/packages/core/src/historical-sync/service.ts b/packages/core/src/historical-sync/service.ts index dc7a61817..fc467dda1 100644 --- a/packages/core/src/historical-sync/service.ts +++ b/packages/core/src/historical-sync/service.ts @@ -329,6 +329,31 @@ export class HistoricalSyncService extends Emittery { return; } + // Handle thirdweb block range limit error. + if ( + task.kind === "LOG_SYNC" && + error instanceof InvalidParamsRpcError && + error.details.includes("block range less than 20000") + ) { + const midpoint = Math.floor( + (task.toBlock - task.fromBlock) / 2 + task.fromBlock + ); + queue.addTask( + { ...task, toBlock: midpoint }, + { priority: Number.MAX_SAFE_INTEGER - task.fromBlock } + ); + queue.addTask( + { ...task, fromBlock: midpoint + 1 }, + { priority: Number.MAX_SAFE_INTEGER - midpoint + 1 } + ); + // Splitting the task into two parts increases the total count by 1. + this.metrics.ponder_historical_scheduled_tasks.inc({ + network: this.network.name, + kind: "log", + }); + return; + } + // Handle Quicknode block range limit error (should never happen). if ( task.kind === "LOG_SYNC" && From facf9e5e724c21c4897baee83701e1e2c4df205b Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Mon, 26 Jun 2023 15:41:42 -0400 Subject: [PATCH 03/12] change user store versionId to be public --- packages/core/src/user-store/postgres/store.ts | 2 +- packages/core/src/user-store/sqlite/store.ts | 2 +- packages/core/src/user-store/store.ts | 1 + 3 files changed, 3 insertions(+), 2 deletions(-) diff --git a/packages/core/src/user-store/postgres/store.ts b/packages/core/src/user-store/postgres/store.ts index 8cb483398..554b8d0a5 100644 --- a/packages/core/src/user-store/postgres/store.ts +++ b/packages/core/src/user-store/postgres/store.ts @@ -29,7 +29,7 @@ export class PostgresUserStore implements UserStore { db: Kysely; schema?: Schema; - private versionId?: string; + versionId?: string; constructor({ pool, diff --git a/packages/core/src/user-store/sqlite/store.ts b/packages/core/src/user-store/sqlite/store.ts index c425ebddf..760fea94f 100644 --- a/packages/core/src/user-store/sqlite/store.ts +++ b/packages/core/src/user-store/sqlite/store.ts @@ -29,7 +29,7 @@ export class SqliteUserStore implements UserStore { db: Kysely; schema?: Schema; - private versionId?: string; + versionId?: string; constructor({ db }: { db: Sqlite.Database }) { this.db = new Kysely({ diff --git a/packages/core/src/user-store/store.ts b/packages/core/src/user-store/store.ts index f225dfc79..9e9635bad 100644 --- a/packages/core/src/user-store/store.ts +++ b/packages/core/src/user-store/store.ts @@ -33,6 +33,7 @@ export type ModelInstance = { export interface UserStore { schema?: Schema; + versionId?: string; reload(options?: { schema?: Schema }): Promise; teardown(): Promise; From 616434344ea092f01fbc13ce6691cc9948a999bc Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Mon, 26 Jun 2023 15:44:35 -0400 Subject: [PATCH 04/12] new logger service --- packages/core/package.json | 2 + packages/core/src/logs/service.ts | 67 +++++++++++++ pnpm-lock.yaml | 155 ++++++++++++++++++++++++++---- 3 files changed, 205 insertions(+), 19 deletions(-) create mode 100644 packages/core/src/logs/service.ts diff --git a/packages/core/package.json b/packages/core/package.json index 9b975dd3f..f3c6259e6 100644 --- a/packages/core/package.json +++ b/packages/core/package.json @@ -46,6 +46,8 @@ "p-queue": "^6.6.2", "pg": "^8.9.0", "picocolors": "^1.0.0", + "pino": "^8.14.1", + "pino-pretty": "^10.0.0", "prettier": "^2.6.2", "prom-client": "^14.2.0", "react": "17", diff --git a/packages/core/src/logs/service.ts b/packages/core/src/logs/service.ts new file mode 100644 index 000000000..26cac2ce6 --- /dev/null +++ b/packages/core/src/logs/service.ts @@ -0,0 +1,67 @@ +import path from "node:path"; +import pino, { type Logger, type LevelWithSilent } from "pino"; +import pretty from "pino-pretty"; + +type LogFunctionArgs = + | [obj: object, msg?: string, ...args: any[]] + | [obj: unknown, msg?: string, ...args: any[]] + | [msg: string, ...args: any[]]; + +export class LoggerService { + private logger: Logger; + + constructor({ + level = "info", + dir, + }: { level?: LevelWithSilent; dir?: string } = {}) { + const streams: (pino.DestinationStream | pino.StreamEntry)[] = []; + + if (level !== "silent") { + streams.push({ + level, + stream: pretty({ + // Write logs in the main thread (worse performance, better DX). + sync: true, + // Only include the level, time, and msg properties. + // All structured properties will still be included in the log file. + include: "level,time", + // Use UTC timestamps rather than local (the default). + translateTime: "UTC:HH:MM:ss.l", + customPrettifiers: { + // Remove the default enclosing brackets. + time: (timestamp) => `${timestamp}`, + }, + }), + }); + } + + if (dir) { + const logFile = path.join(dir, `${new Date().toISOString()}.log`); + streams.push({ + level: "trace", + stream: pino.destination({ dest: logFile, sync: false, mkdir: true }), + }); + } + + this.logger = pino({ level: "trace" }, pino.multistream(streams)); + } + + fatal = (...args: LogFunctionArgs) => { + this.logger.fatal(...(args as [any])); + }; + error = (...args: LogFunctionArgs) => { + this.logger.error(...(args as [any])); + }; + warn = (...args: LogFunctionArgs) => { + this.logger.warn(...(args as [any])); + }; + info = (...args: LogFunctionArgs) => { + this.logger.info(...(args as [any])); + }; + debug = (...args: LogFunctionArgs) => { + this.logger.debug(...(args as [any])); + }; + trace = (...args: LogFunctionArgs) => { + this.logger.trace(...(args as [any])); + }; +} diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index e9a97a1bf..4a6c5d59e 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -185,6 +185,8 @@ importers: p-queue: ^6.6.2 pg: ^8.9.0 picocolors: ^1.0.0 + pino: ^8.14.1 + pino-pretty: ^10.0.0 prettier: ^2.6.2 prom-client: ^14.2.0 react: '17' @@ -224,6 +226,8 @@ importers: p-queue: 6.6.2 pg: 8.9.0 picocolors: 1.0.0 + pino: 8.14.1 + pino-pretty: 10.0.0 prettier: 2.8.2 prom-client: 14.2.0 react: 17.0.2 @@ -4142,7 +4146,6 @@ packages: engines: {node: '>=6.5'} dependencies: event-target-shim: 5.0.1 - dev: true /accepts/1.3.8: resolution: {integrity: sha512-PYAthTa2m2VKxuvSD3DPC/Gy+U+sOA1LAuT8mkmRuvw+NACSaeXEQ+NHcVF7rONl6qcaxV3Uuemwawk+7+SJLw==} @@ -4464,6 +4467,11 @@ packages: engines: {node: '>= 4.0.0'} dev: true + /atomic-sleep/1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + dev: false + /auto-bind/4.0.0: resolution: {integrity: sha512-Hdw8qdNiqdJ8LqT0iK0sVzkFbzg6fhnQqqfWhBDxcHZvU75+B+ayzTy8x+k5Ix0Y92XOhOUlx74ps+bA6BeYMQ==} engines: {node: '>=8'} @@ -4619,7 +4627,7 @@ packages: dependencies: buffer: 5.7.1 inherits: 2.0.4 - readable-stream: 3.6.1 + readable-stream: 3.6.2 dev: false /blakejs/1.2.1: @@ -4780,7 +4788,6 @@ packages: dependencies: base64-js: 1.5.1 ieee754: 1.2.1 - dev: true /bundle-require/4.0.1_esbuild@0.17.11: resolution: {integrity: sha512-9NQkRHlNdNpDBGmLpngF3EFDcwodhMUuLz9PaWYciVcQF9SE4LFjM2DB/xV1Li5JiuDMv7ZUWuC3rGbqR0MAXQ==} @@ -5098,6 +5105,10 @@ packages: /color-name/1.1.4: resolution: {integrity: sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==} + /colorette/2.0.20: + resolution: {integrity: sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==} + dev: false + /colors/1.4.0: resolution: {integrity: sha512-a+UqTh4kgZg/SlGvfbzDHpgRu7AAQOmmqRHJnxhRZICKFUT91brVhNNt58CMWU9PsBbv3PDCZUHbVxuDiH2mtA==} engines: {node: '>=0.1.90'} @@ -5366,6 +5377,10 @@ packages: resolution: {integrity: sha512-68s5jYdlvasItOJnCuI2Q9s4q98g0pCyL3HrcKJu8KNugUl8ahgmZYg38ysLTgQjjXX3H8CJLkAvWrclWfcalw==} dev: true + /dateformat/4.6.3: + resolution: {integrity: sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==} + dev: false + /debug/2.6.9: resolution: {integrity: sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==} peerDependencies: @@ -6773,12 +6788,16 @@ packages: /event-target-shim/5.0.1: resolution: {integrity: sha512-i/2XbnSz/uxRCU6+NdVJgKWDTM427+MqYbkQzD321DuCQJUqOuJKIA0IM2+W2xtYHdKOmZ4dR6fExsd4SXL+WQ==} engines: {node: '>=6'} - dev: true /eventemitter3/4.0.7: resolution: {integrity: sha512-8guHBZCwKnFhYdHr2ysuRWErTwhoN2X8XELRlrRwpmfeY2jjuUN4taQMsULKUVo1K4DvZl+0pgfyoysHxvmvEw==} dev: false + /events/3.3.0: + resolution: {integrity: sha512-mQw+2fkQbALzQ7V0MY0IqdnXNOeTtP4r0lN9z7AAawCXgqea7bDii20AYrIBrFd/Hx0M2Ocz6S111CaFkUcb0Q==} + engines: {node: '>=0.8.x'} + dev: false + /evp_bytestokey/1.0.3: resolution: {integrity: sha512-/f2Go4TognH/KvCISP7OUsHn85hT9nUkxxA9BEWxFn+Oj9o8ZNLm/40hdlgSLyuOimsrTKLUMEorQexp/aPQeA==} dependencies: @@ -6918,6 +6937,10 @@ packages: engines: {node: '> 0.1.90'} dev: true + /fast-copy/3.0.1: + resolution: {integrity: sha512-Knr7NOtK3HWRYGtHoJrjkaWepqT8thIVGAwt0p0aUs1zqkAzXZV4vo9fFNwyb5fcqK1GKYFYxldQdIDVKhUAfA==} + dev: false + /fast-decode-uri-component/1.0.1: resolution: {integrity: sha512-WKgKWg5eUxvRZGwW8FvfbaH7AXSh2cL+3j5fMGzUMCxWBJ3dV3a7Wz8y2f/uQ0e3B6WmodD3oS54jTQ9HVTIIg==} dev: true @@ -6984,9 +7007,13 @@ packages: fast-decode-uri-component: 1.0.1 dev: true + /fast-redact/3.2.0: + resolution: {integrity: sha512-zaTadChr+NekyzallAMXATXLOR8MNx3zqpZ0MUF2aGf4EathnG0f32VLODNlY8IuGY3HoRO2L6/6fSzNsLaHIw==} + engines: {node: '>=6'} + dev: false + /fast-safe-stringify/2.1.1: resolution: {integrity: sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==} - dev: true /fast-url-parser/1.1.3: resolution: {integrity: sha512-5jOCVXADYNuRkKFzNJ0dCCewsZiYo0dz8QNYljkOpFC6r2U4OBmKtvm/Tsuh4w1YYdDqDb31a8TVhBJ2OJKdqQ==} @@ -7670,6 +7697,13 @@ packages: resolution: {integrity: sha512-Pkw+xBHuV6xFeJprJe2BBEoDV+AvQySaz3pPDRUs5PNZEMQjpXJJueqrpcHIXxnWTcAGi/UOCgVShlkY6kLoqg==} dev: false + /help-me/4.2.0: + resolution: {integrity: sha512-TAOnTB8Tz5Dw8penUuzHVrKNKlCIbwwbHnXraNJxPwf8LRtE2HlM84RYuezMFcwOJmoYOCWVDyJ8TQGxn9PgxA==} + dependencies: + glob: 8.1.0 + readable-stream: 3.6.2 + dev: false + /hexoid/1.0.0: resolution: {integrity: sha512-QFLV0taWQOZtvIRIAdBChesmogZrtuXvVWsFHZTk2SU+anspqZ2vMnoLg7IE1+Uk16N19APic1BuF8bC8c2m5g==} engines: {node: '>=8'} @@ -8428,7 +8462,6 @@ packages: /joycon/3.1.1: resolution: {integrity: sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==} engines: {node: '>=10'} - dev: true /js-sha3/0.8.0: resolution: {integrity: sha512-gF1cRrHhIzNfToc802P800N8PpXS+evLLXfsVpowqmAFR9uwbi89WvXg2QspOmXL8QL86J4T1EpFu+yUkwJY3Q==} @@ -9447,7 +9480,6 @@ packages: /minimist/1.2.8: resolution: {integrity: sha512-2yyAR8qBkN3YuheJanUpWC5U3bb5osDywNB8RzDVlDwDHbocAJveqqj1u8+SVD7jkWT4yvsHCpWqqWqAxb0zCA==} - dev: true /minipass/3.3.6: resolution: {integrity: sha512-DxiNidxSEK+tHG6zOIklvNOwm3hvCrbUrdtzY74U6HKTJxvIDfOUL5W5P2Ghd3DTkhhKPYGqeNUIh5qcM4YBfw==} @@ -9903,6 +9935,10 @@ packages: es-abstract: 1.21.2 dev: true + /on-exit-leak-free/2.1.0: + resolution: {integrity: sha512-VuCaZZAjReZ3vUwgOB8LxAosIurDiAW0s13rI1YwmaP++jvcxP77AWoQvenZebpCA2m8WC1/EosPYPMjnRAp/w==} + dev: false + /on-finished/2.4.1: resolution: {integrity: sha512-oVlzkg3ENAhCk2zdv7IJwd/QUD4z2RxRwpkcGY8psCVcCYZNq4wYnVWALHM+brtuJjePWiYF/ClmuDr8Ch5+kg==} engines: {node: '>= 0.8'} @@ -10304,6 +10340,54 @@ packages: engines: {node: '>=6'} dev: true + /pino-abstract-transport/1.0.0: + resolution: {integrity: sha512-c7vo5OpW4wIS42hUVcT5REsL8ZljsUfBjqV/e2sFxmFEFZiq1XLUp5EYLtuDH6PEHq9W1egWqRbnLUP5FuZmOA==} + dependencies: + readable-stream: 4.4.0 + split2: 4.1.0 + dev: false + + /pino-pretty/10.0.0: + resolution: {integrity: sha512-zKFjYXBzLaLTEAN1ayKpHXtL5UeRQC7R3lvhKe7fWs7hIVEjKGG/qIXwQt9HmeUp71ogUd/YcW+LmMwRp4KT6Q==} + hasBin: true + dependencies: + colorette: 2.0.20 + dateformat: 4.6.3 + fast-copy: 3.0.1 + fast-safe-stringify: 2.1.1 + help-me: 4.2.0 + joycon: 3.1.1 + minimist: 1.2.8 + on-exit-leak-free: 2.1.0 + pino-abstract-transport: 1.0.0 + pump: 3.0.0 + readable-stream: 4.4.0 + secure-json-parse: 2.7.0 + sonic-boom: 3.3.0 + strip-json-comments: 3.1.1 + dev: false + + /pino-std-serializers/6.2.1: + resolution: {integrity: sha512-wHuWB+CvSVb2XqXM0W/WOYUkVSPbiJb9S5fNB7TBhd8s892Xq910bRxwHtC4l71hgztObTjXL6ZheZXFjhDrDQ==} + dev: false + + /pino/8.14.1: + resolution: {integrity: sha512-8LYNv7BKWXSfS+k6oEc6occy5La+q2sPwU3q2ljTX5AZk7v+5kND2o5W794FyRaqha6DJajmkNRsWtPpFyMUdw==} + hasBin: true + dependencies: + atomic-sleep: 1.0.0 + fast-redact: 3.2.0 + on-exit-leak-free: 2.1.0 + pino-abstract-transport: 1.0.0 + pino-std-serializers: 6.2.1 + process-warning: 2.2.0 + quick-format-unescaped: 4.0.4 + real-require: 0.2.0 + safe-stable-stringify: 2.4.3 + sonic-boom: 3.3.0 + thread-stream: 2.3.0 + dev: false + /pirates/4.0.5: resolution: {integrity: sha512-8V9+HQPupnaXMA23c5hvl69zXvTwTzyAYasnkb0Tts4XvO4CliqONMOnvlq26rkhLC3nWDFBJf73LU1e1VZLaQ==} engines: {node: '>= 6'} @@ -10475,6 +10559,15 @@ packages: resolution: {integrity: sha512-3ouUOpQhtgrbOa17J7+uxOTpITYWaGP7/AhoR3+A+/1e9skrzelGi/dXzEYyvbxubEF6Wn2ypscTKiKJFFn1ag==} dev: true + /process-warning/2.2.0: + resolution: {integrity: sha512-/1WZ8+VQjR6avWOgHeEPd7SDQmFQ1B5mC1eRXsCm5TarlNmx/wCsa5GEaxGm05BORRtyG/Ex/3xq3TuRvq57qg==} + dev: false + + /process/0.11.10: + resolution: {integrity: sha512-cdGef/drWFoydD1JsMzuFf8100nZl+GT+yacc2bEced5f9Rjk4z+WtFUTBu9PhOi9j/jfmBPu0mMEY4wIdAF8A==} + engines: {node: '>= 0.6.0'} + dev: false + /prom-client/14.2.0: resolution: {integrity: sha512-sF308EhTenb/pDRPakm+WgiN+VdM/T1RaHj1x+MvAuT8UiQP8JmOEbxVqtkbfR4LrvOg5n7ic01kRBDGXjYikA==} engines: {node: '>=10'} @@ -10613,6 +10706,10 @@ packages: /queue-microtask/1.2.3: resolution: {integrity: sha512-NuaNSa6flKT5JaSYQzJok04JzTL1CA6aGhv5rfLW3PgqA+M2ChpZQnAC8h8i4ZFkBS8X5RqkDBHA7r4hej3K9A==} + /quick-format-unescaped/4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + dev: false + /quick-lru/4.0.1: resolution: {integrity: sha512-ARhCpm70fzdcvNQfPoy49IaanKkTlRWF2JMzqhcJbhSFRZv7nPTvZJdcY7301IPmvW+/p0RgIWnQDLJxifsQ7g==} engines: {node: '>=8'} @@ -10759,15 +10856,6 @@ packages: util-deprecate: 1.0.2 dev: true - /readable-stream/3.6.1: - resolution: {integrity: sha512-+rQmrWMYGA90yenhTYsLWAsLsqVC8osOw6PKE1HDYiO0gdPeKe/xDHNzIAIn4C91YQ6oenEhfYqqc1883qHbjQ==} - engines: {node: '>= 6'} - dependencies: - inherits: 2.0.4 - string_decoder: 1.3.0 - util-deprecate: 1.0.2 - dev: false - /readable-stream/3.6.2: resolution: {integrity: sha512-9u/sniCrY3D5WdsERHzHE4G2YCXqoG5FTHUiCC4SIbr6XcLZBY05ya9EKjYek9O5xOAwjGq+1JdGBAS7Q9ScoA==} engines: {node: '>= 6'} @@ -10775,7 +10863,16 @@ packages: inherits: 2.0.4 string_decoder: 1.3.0 util-deprecate: 1.0.2 - dev: true + + /readable-stream/4.4.0: + resolution: {integrity: sha512-kDMOq0qLtxV9f/SQv522h8cxZBqNZXuXNyjyezmfAAuribMyVXziljpQ/uQhfE1XLg2/TLTW2DsnoE4VAi/krg==} + engines: {node: ^12.22.0 || ^14.17.0 || >=16.0.0} + dependencies: + abort-controller: 3.0.0 + buffer: 6.0.3 + events: 3.3.0 + process: 0.11.10 + dev: false /readdirp/3.6.0: resolution: {integrity: sha512-hOS089on8RduqdbhvQ5Z37A0ESjsqz6qnRcffsMU3495FuTdqSm+7bhJ29JvIOsBDEEnan5DPu9t3To9VRlMzA==} @@ -10787,6 +10884,11 @@ packages: resolution: {integrity: sha512-onYyVhBNr4CmAxFsKS7bz+uTLRakypIe4R+5A824vBSkQy/hB3fZepoVEf8OVAxzLvK+H/jm9TzpI3ETSm64Kg==} dev: false + /real-require/0.2.0: + resolution: {integrity: sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==} + engines: {node: '>= 12.13.0'} + dev: false + /receptacle/1.3.2: resolution: {integrity: sha512-HrsFvqZZheusncQRiEE7GatOAETrARKV/lnfYicIm8lbvp/JQOdADOfhjBd2DajvoszEyxSM6RlAAIZgEoeu/A==} dependencies: @@ -11180,6 +11282,10 @@ packages: kind-of: 6.0.3 dev: false + /secure-json-parse/2.7.0: + resolution: {integrity: sha512-6aU+Rwsezw7VR8/nyvKTx8QpWH9FrcYiXXlqC4z5d5XQBDRqtbfsRjnwGyqbi3gddNtWHuEk9OANUotL26qKUw==} + dev: false + /semver-compare/1.0.0: resolution: {integrity: sha512-YM3/ITh2MJ5MtzaM429anh+x2jiLVjqILF4m4oyQB18W7Ggea7BfqdH/wGMK7dDiMghv/6WG7znWMwUDzJiXow==} dev: false @@ -11383,6 +11489,12 @@ packages: yargs: 15.4.1 dev: true + /sonic-boom/3.3.0: + resolution: {integrity: sha512-LYxp34KlZ1a2Jb8ZQgFCK3niIHzibdwtwNUWKg0qQRzsDoJ3Gfgkf8KdBTFU3SkejDEIlWwnSnpVdOZIhFMl/g==} + dependencies: + atomic-sleep: 1.0.0 + dev: false + /source-map-js/1.0.2: resolution: {integrity: sha512-R0XvVJ9WusLiqTCEiGCmICCMplcCkIwwR11mOSD9CR5u+IXYdiseeEuXCVAjS54zqwkLcPNnmU4OeJ6tUrWhDw==} engines: {node: '>=0.10.0'} @@ -11690,7 +11802,6 @@ packages: /strip-json-comments/3.1.1: resolution: {integrity: sha512-6fPc+R4ihwqP6N/aIv2f1gMH8lOVtWQHoqC4yK6oSDVVocumAsfCqjkXnqiYMhmMwS/mEHLp7Vehlt3ql6lEig==} engines: {node: '>=8'} - dev: true /strip-literal/1.0.1: resolution: {integrity: sha512-QZTsipNpa2Ppr6v1AmJHESqJ3Uz247MUS0OjrnnZjFAvEoWqxuyFuXn2xLgMtRnijJShAa1HL0gtJyUs7u7n3Q==} @@ -11899,7 +12010,7 @@ packages: end-of-stream: 1.4.4 fs-constants: 1.0.0 inherits: 2.0.4 - readable-stream: 3.6.1 + readable-stream: 3.6.2 dev: false /tar/6.1.15: @@ -11959,6 +12070,12 @@ packages: any-promise: 1.3.0 dev: true + /thread-stream/2.3.0: + resolution: {integrity: sha512-kaDqm1DET9pp3NXwR8382WHbnpXnRkN9xGN9dQt3B2+dmXiW8X1SOwmFOxAErEQ47ObhZ96J6yhZNXuyCOL7KA==} + dependencies: + real-require: 0.2.0 + dev: false + /through/2.3.8: resolution: {integrity: sha512-w89qg7PI8wAdvX60bMDP+bFoD5Dvhm9oLheFp5O4a2QF0cSBGsBX4qZmadPMvVqlLJBBci+WqGGOAPvcDeNSVg==} dev: true From cb39af9177fa8f376d80df985893f04c71901505 Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Mon, 26 Jun 2023 15:45:51 -0400 Subject: [PATCH 05/12] update options to use string log levels and log dir --- .../core/src/_test/art-gobblers/app.test.ts | 6 +++++- packages/core/src/_test/ens/app.test.ts | 6 +++++- packages/core/src/_test/utils.ts | 4 ++-- packages/core/src/bin/ponder.ts | 6 +++++- packages/core/src/config/options.ts | 17 +++++++++++++++-- 5 files changed, 32 insertions(+), 7 deletions(-) diff --git a/packages/core/src/_test/art-gobblers/app.test.ts b/packages/core/src/_test/art-gobblers/app.test.ts index 0d8fef6bc..11a3aa095 100644 --- a/packages/core/src/_test/art-gobblers/app.test.ts +++ b/packages/core/src/_test/art-gobblers/app.test.ts @@ -21,7 +21,11 @@ const setup = async ({ context }: { context: TestContext }) => { configFile: "ponder.config.ts", }, }); - const testOptions = { ...options, uiEnabled: false, logLevel: 1 }; + const testOptions = { + ...options, + uiEnabled: false, + logLevel: "error", + } as const; const ponder = new Ponder({ config: testConfig, diff --git a/packages/core/src/_test/ens/app.test.ts b/packages/core/src/_test/ens/app.test.ts index e50c0c1db..3320c8c6f 100644 --- a/packages/core/src/_test/ens/app.test.ts +++ b/packages/core/src/_test/ens/app.test.ts @@ -21,7 +21,11 @@ const setup = async ({ context }: { context: TestContext }) => { configFile: "ponder.config.ts", }, }); - const testOptions = { ...options, uiEnabled: false, logLevel: 1 }; + const testOptions = { + ...options, + uiEnabled: false, + logLevel: "error", + } as const; const ponder = new Ponder({ config: testConfig, diff --git a/packages/core/src/_test/utils.ts b/packages/core/src/_test/utils.ts index a34a6f250..1dd180271 100644 --- a/packages/core/src/_test/utils.ts +++ b/packages/core/src/_test/utils.ts @@ -11,7 +11,7 @@ import { buildOptions } from "@/config/options"; import { ErrorService } from "@/errors/ErrorService"; import { MetricsService } from "@/metrics/service"; import { Resources } from "@/Ponder"; -import { LoggerService } from "@/utils/logger"; +import { LoggerService } from "@/logs/service"; // Anvil test setup adapted from @viem/anvil `example-vitest` repository. // https://github.com/wagmi-dev/anvil.js/tree/main/examples/example-vitest @@ -58,7 +58,7 @@ export const walletClient = createWalletClient({ }); export const testResources: Resources = { - logger: new LoggerService({ options: { logLevel: 0 } }), + logger: new LoggerService({ level: "silent" }), options: buildOptions({ cliOptions: { configFile: "", rootDir: "" }, }), diff --git a/packages/core/src/bin/ponder.ts b/packages/core/src/bin/ponder.ts index cec6f324f..22e881958 100644 --- a/packages/core/src/bin/ponder.ts +++ b/packages/core/src/bin/ponder.ts @@ -72,7 +72,11 @@ cli const config = await buildPonderConfig({ configFile }); const options = buildOptions({ cliOptions, configOptions: config.options }); - const codegenOptions = { ...options, uiEnabled: false, logLevel: 0 }; + const codegenOptions = { + ...options, + uiEnabled: false, + logLevel: "silent", + } as const; const ponder = new Ponder({ config, options: codegenOptions }); registerKilledProcessListener(() => ponder.kill()); diff --git a/packages/core/src/config/options.ts b/packages/core/src/config/options.ts index 197238c86..5d6660b17 100644 --- a/packages/core/src/config/options.ts +++ b/packages/core/src/config/options.ts @@ -1,4 +1,5 @@ import path from "node:path"; +import type { LevelWithSilent } from "pino"; import type { PonderCliOptions } from "@/bin/ponder"; @@ -11,11 +12,12 @@ export type PonderOptions = { srcDir: string; generatedDir: string; ponderDir: string; + logDir: string; port: number; maxHealthcheckDuration: number; - logLevel: number; + logLevel: LevelWithSilent; uiEnabled: boolean; }; @@ -30,6 +32,15 @@ export const buildOptions = ({ ? Math.max(Number(process.env.RAILWAY_HEALTHCHECK_TIMEOUT_SEC) - 5, 0) // Add 5 seconds of buffer. : undefined; + const logLevel = ( + process.env.PONDER_LOG_LEVEL && + ["silent", "fatal", "error", "warn", "info", "debug", "trace"].includes( + process.env.PONDER_LOG_LEVEL + ) + ? process.env.PONDER_LOG_LEVEL + : "info" + ) as LevelWithSilent; + const defaults = { rootDir: path.resolve(cliOptions.rootDir), configFile: cliOptions.configFile, @@ -37,12 +48,13 @@ export const buildOptions = ({ srcDir: "src", generatedDir: "generated", ponderDir: ".ponder", + logDir: ".ponder/logs", port: Number(process.env.PORT ?? 42069), maxHealthcheckDuration: configOptions?.maxHealthcheckDuration ?? railwayHealthcheckTimeout ?? 240, - logLevel: Number(process.env.PONDER_LOG_LEVEL ?? 2), + logLevel, uiEnabled: true, }; @@ -54,5 +66,6 @@ export const buildOptions = ({ srcDir: path.join(defaults.rootDir, defaults.srcDir), generatedDir: path.join(defaults.rootDir, defaults.generatedDir), ponderDir: path.join(defaults.rootDir, defaults.ponderDir), + logDir: path.join(defaults.rootDir, defaults.logDir), }; }; From 7f8af1a596db2150730bb6ca07ca99a03b338f6f Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Mon, 26 Jun 2023 15:46:26 -0400 Subject: [PATCH 06/12] wip service logs --- packages/core/src/Ponder.ts | 116 ++++++++---------- packages/core/src/historical-sync/service.ts | 81 +++++++++++- .../core/src/realtime-sync/service.test.ts | 87 ++++--------- packages/core/src/realtime-sync/service.ts | 69 +++++++++-- packages/core/src/reload/readHandlers.ts | 4 +- packages/core/src/reload/service.ts | 19 ++- packages/core/src/server/service.ts | 36 ++++-- packages/core/src/ui/app.tsx | 4 +- packages/core/src/ui/service.ts | 2 +- packages/core/src/user-handlers/service.ts | 23 +++- packages/core/src/utils/logger.ts | 72 ----------- 11 files changed, 275 insertions(+), 238 deletions(-) delete mode 100644 packages/core/src/utils/logger.ts diff --git a/packages/core/src/Ponder.ts b/packages/core/src/Ponder.ts index 664cf349c..b99bedab8 100644 --- a/packages/core/src/Ponder.ts +++ b/packages/core/src/Ponder.ts @@ -1,4 +1,5 @@ import pico from "picocolors"; +import path from "node:path"; import { CodegenService } from "@/codegen/service"; import { buildContracts } from "@/config/contracts"; @@ -22,8 +23,8 @@ import { EventHandlerService } from "@/user-handlers/service"; import { PostgresUserStore } from "@/user-store/postgres/store"; import { SqliteUserStore } from "@/user-store/sqlite/store"; import { type UserStore } from "@/user-store/store"; -import { formatEta, formatPercentage } from "@/utils/format"; -import { LoggerService } from "@/utils/logger"; +import { formatEta } from "@/utils/format"; +import { LoggerService } from "@/logs/service"; export type Resources = { options: PonderOptions; @@ -55,6 +56,8 @@ export class Ponder { codegenService: CodegenService; uiService: UiService; + private killFunctions: (() => any)[] = []; + constructor({ options, config, @@ -67,7 +70,10 @@ export class Ponder { eventStore?: EventStore; userStore?: UserStore; }) { - const logger = new LoggerService({ options }); + const logger = new LoggerService({ + level: options.logLevel, + dir: options.logDir, + }); const errors = new ErrorService(); const metrics = new MetricsService(); @@ -103,12 +109,14 @@ export class Ponder { logFilters: logFiltersForNetwork, historicalSyncService: new HistoricalSyncService({ metrics, + logger, eventStore: this.eventStore, network, logFilters: logFiltersForNetwork, }), realtimeSyncService: new RealtimeSyncService({ metrics, + logger, eventStore: this.eventStore, network, logFilters: logFiltersForNetwork, @@ -145,6 +153,10 @@ export class Ponder { } async setup() { + this.resources.logger.debug({ + msg: `Using config at ${this.resources.options.configFile}`, + }); + this.registerServiceDependencies(); this.registerUiHandlers(); @@ -185,7 +197,7 @@ export class Ponder { async dev() { const setupError = await this.setup(); if (setupError) { - this.resources.logger.logMessage("error", setupError.message); + // this.resources.logger.logMessage("error", setupError.message); return await this.kill(); } @@ -207,7 +219,7 @@ export class Ponder { async start() { const setupError = await this.setup(); if (setupError) { - this.resources.logger.logMessage("error", setupError.message); + // this.resources.logger.error("error", setupError.message); return await this.kill(); } @@ -238,6 +250,9 @@ export class Ponder { } async kill() { + this.killFunctions.forEach((fn) => { + fn(); + }); this.eventAggregatorService.clearListeners(); await Promise.all( @@ -254,10 +269,15 @@ export class Ponder { this.eventHandlerService.kill(); await this.serverService.teardown(); await this.userStore.teardown(); + + this.resources.logger.debug({ msg: `Shutdown sequence completed` }); } private registerServiceDependencies() { this.reloadService.on("ponderConfigChanged", async () => { + this.resources.logger.fatal({ + msg: "Detected change in ponder.config.ts", + }); await this.kill(); }); @@ -311,16 +331,16 @@ export class Ponder { }); }); - // TODO: Decide what to do after a deep reorg. - realtimeSyncService.on( - "deepReorg", - ({ detectedAtBlockNumber, minimumDepth }) => { - this.resources.logger.logMessage( - "error", - `WARNING: Deep reorg detected on ${network.name} at block ${detectedAtBlockNumber} with a minimum depth of ${minimumDepth}` - ); - } - ); + // // TODO: Decide what to do after a deep reorg. + // realtimeSyncService.on( + // "deepReorg", + // ({ detectedAtBlockNumber, minimumDepth }) => { + // this.resources.logger.logMessage( + // "error", + // `WARNING: Deep reorg detected on ${network.name} at block ${detectedAtBlockNumber} with a minimum depth of ${minimumDepth}` + // ); + // } + // ); }); this.eventAggregatorService.on("newCheckpoint", ({ timestamp }) => { @@ -341,62 +361,36 @@ export class Ponder { this.eventAggregatorService.historicalSyncCompletedAt && toTimestamp >= this.eventAggregatorService.historicalSyncCompletedAt ) { - this.serverService.isHistoricalEventProcessingComplete = true; - this.resources.logger.logMessage( - "indexer", - "historical sync complete (server now responding as healthy)" - ); + this.serverService.setIsHistoricalEventProcessingComplete(); } }); } private registerUiHandlers() { - this.resources.errors.on("handlerError", ({ error }) => { - this.resources.logger.logMessage("error", error.message); - }); + // this.resources.errors.on("handlerError", ({ error }) => { + // this.resources.logger.logMessage("error", error.message); + // }); this.networkSyncServices.forEach((networkSyncService) => { - const { historicalSyncService, realtimeSyncService, logFilters } = - networkSyncService; + const { historicalSyncService, logFilters } = networkSyncService; - historicalSyncService.on("error", ({ error }) => { - this.resources.logger.logMessage("error", error.message); - }); + // historicalSyncService.on("error", ({ error }) => { + // this.resources.logger.logMessage("error", error.message); + // }); - realtimeSyncService.on("error", ({ error }) => { - this.resources.logger.logMessage("error", error.message); - }); + // realtimeSyncService.on("error", ({ error }) => { + // this.resources.logger.logMessage("error", error.message); + // }); historicalSyncService.on("syncStarted", () => { logFilters.forEach(({ name }) => { this.uiService.ui.historicalSyncLogFilterStats[name].startTimestamp = Date.now(); - - this.resources.logger.logMessage( - "historical", - `started historical sync for ${pico.bold(name)} (${formatPercentage( - historicalSyncService.stats.logFilters[name].cacheRate - )} cached)` - ); }); }); - - realtimeSyncService.on("finalityCheckpoint", ({ timestamp }) => { - this.resources.logger.logMessage( - "realtime", - `finality checkpoint, timestamp: ${timestamp}` - ); - }); - - realtimeSyncService.on("shallowReorg", ({ commonAncestorTimestamp }) => { - this.resources.logger.logMessage( - "realtime", - `reorg detected, common ancestor timestamp: ${commonAncestorTimestamp}` - ); - }); }); - setInterval(() => { + const interval = setInterval(() => { this.networkSyncServices.forEach((networkSyncService) => { const { network, realtimeSyncService } = networkSyncService; @@ -433,6 +427,9 @@ export class Ponder { this.uiService.ui.handlersToTimestamp = this.eventHandlerService.metrics.latestHandledEventTimestamp; }, 17); + this.killFunctions.push(() => { + clearInterval(interval); + }); this.eventHandlerService.on("reset", () => { this.uiService.ui.handlersCurrent = 0; @@ -454,18 +451,7 @@ export class Ponder { this.uiService.render(); }); - this.serverService.on("serverStarted", ({ desiredPort, port }) => { - if (desiredPort !== port) { - this.resources.logger.logMessage( - "event", - `port ${desiredPort} unavailable, server listening on port ${port}` - ); - } else { - this.resources.logger.logMessage( - "event", - `server listening on port ${port}` - ); - } + this.serverService.on("serverStarted", ({ port }) => { this.uiService.ui.port = port; }); diff --git a/packages/core/src/historical-sync/service.ts b/packages/core/src/historical-sync/service.ts index fc467dda1..36f4d248e 100644 --- a/packages/core/src/historical-sync/service.ts +++ b/packages/core/src/historical-sync/service.ts @@ -16,6 +16,8 @@ import { type Queue, createQueue } from "@/utils/queue"; import { startClock } from "@/utils/timer"; import { findMissingIntervals } from "./intervals"; +import { LoggerService } from "@/logs/service"; +import { formatEta, formatPercentage } from "@/utils/format"; type HistoricalSyncEvents = { /** @@ -78,6 +80,7 @@ type HistoricalSyncQueue = Queue; export class HistoricalSyncService extends Emittery { private metrics: MetricsService; + private logger: LoggerService; private eventStore: EventStore; private logFilters: LogFilter[]; network: Network; @@ -95,11 +98,13 @@ export class HistoricalSyncService extends Emittery { constructor({ metrics, + logger, eventStore, logFilters, network, }: { metrics: MetricsService; + logger: LoggerService; eventStore: EventStore; logFilters: LogFilter[]; network: Network; @@ -107,6 +112,7 @@ export class HistoricalSyncService extends Emittery { super(); this.metrics = metrics; + this.logger = logger; this.eventStore = eventStore; this.logFilters = logFilters; this.network = network; @@ -160,6 +166,10 @@ export class HistoricalSyncService extends Emittery { acc + (Number(cur.endBlock) + 1 - Number(cur.startBlock)), 0 ); + const cacheRate = Math.min( + 1, + cachedBlockCount / (totalBlockCount || 1) + ); this.metrics.ponder_historical_total_blocks.set( { @@ -177,10 +187,17 @@ export class HistoricalSyncService extends Emittery { ); this.stats.logFilters[logFilter.name].totalBlockCount = totalBlockCount; - this.stats.logFilters[logFilter.name].cacheRate = Math.min( - 1, - cachedBlockCount / (totalBlockCount || 1) - ); + this.stats.logFilters[logFilter.name].cacheRate = cacheRate; + + this.logger.info({ + msg: `Historical sync started with ${formatPercentage( + cacheRate + )} cached (network=${this.network.name})`, + network: this.network.name, + logFilter: logFilter.name, + totalBlockCount, + cacheRate, + }); for (const blockRange of requiredBlockRanges) { const [startBlock, endBlock] = blockRange; @@ -223,6 +240,13 @@ export class HistoricalSyncService extends Emittery { timestamp: Math.round(Date.now() / 1000), }); this.emit("syncComplete"); + this.logger.info({ + msg: `Historical sync completed in ${formatEta( + this.stats.duration + )} (network=${this.network.name})`, + network: this.network.name, + duration: this.stats.duration, + }); } } @@ -236,6 +260,9 @@ export class HistoricalSyncService extends Emittery { this.queue.clear(); // TODO: Figure out if it's necessary to wait for the queue to be idle before killing it. // await this.onIdle(); + this.logger.debug({ + msg: `Killed historical sync service (network=${this.network.name})`, + }); }; onIdle = async () => { @@ -281,6 +308,25 @@ export class HistoricalSyncService extends Emittery { ); } + this.logger.debug({ + msg: + task.kind === "LOG_SYNC" + ? `Historical sync log task completed` + : `Historical sync block task completed`, + network: this.network.name, + logFilter: logFilter.name, + ...(task.kind === "LOG_SYNC" + ? { + fromBlock: task.fromBlock, + toBlock: task.toBlock, + } + : { + blockNumberToCacheFrom: task.blockNumberToCacheFrom, + blockNumber: task.blockNumber, + requiredTransactionCount: task.requiredTxHashes.size, + }), + }); + this.metrics.ponder_historical_completed_tasks.inc({ network: this.network.name, kind: task.kind === "LOG_SYNC" ? "log" : "block", @@ -392,6 +438,26 @@ export class HistoricalSyncService extends Emittery { }); this.emit("error", { error: queueError }); + this.logger.error({ + msg: + task.kind === "LOG_SYNC" + ? `Historical sync log task failed` + : `Historical sync block task failed`, + network: this.network.name, + logFilter: logFilter.name, + ...(task.kind === "LOG_SYNC" + ? { + fromBlock: task.fromBlock, + toBlock: task.toBlock, + } + : { + blockNumberToCacheFrom: task.blockNumberToCacheFrom, + blockNumber: task.blockNumber, + requiredTransactionCount: task.requiredTxHashes.size, + }), + error, + }); + // Default to a retry (uses the retry options passed to the queue). const priority = Number.MAX_SAFE_INTEGER - @@ -405,6 +471,13 @@ export class HistoricalSyncService extends Emittery { this.stats.duration = this.stats.endDuration(); this.stats.isComplete = true; this.emit("syncComplete"); + this.logger.info({ + msg: `Historical sync completed in ${formatEta( + this.stats.duration + )} (network=${this.network.name})`, + network: this.network.name, + duration: this.stats.duration, + }); }, }); diff --git a/packages/core/src/realtime-sync/service.test.ts b/packages/core/src/realtime-sync/service.test.ts index c7d2f02e2..c007eba9d 100644 --- a/packages/core/src/realtime-sync/service.test.ts +++ b/packages/core/src/realtime-sync/service.test.ts @@ -17,7 +17,6 @@ import { range } from "@/utils/range"; import { RealtimeSyncService } from "./service"; -const { metrics } = testResources; const network: Network = { name: "mainnet", chainId: 1, @@ -46,6 +45,13 @@ const logFilters: LogFilter[] = [ }, ]; +const config = { + metrics: testResources.metrics, + logger: testResources.logger, + logFilters, + network, +}; + const sendUsdcTransferTransaction = async () => { await walletClient.writeContract({ ...usdcContractConfig, @@ -62,12 +68,7 @@ beforeEach(async () => { test("setup() returns the finalized block number", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); const { finalizedBlockNumber } = await service.setup(); expect(finalizedBlockNumber).toEqual(16379995); // ANVIL_FORK_BLOCK - finalityBlockCount @@ -78,12 +79,8 @@ test("setup() returns the finalized block number", async (context) => { test("fetches blocks from finalized to latest", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + await service.setup(); await service.start(); await service.onIdle(); @@ -98,12 +95,8 @@ test("fetches blocks from finalized to latest", async (context) => { test("fetches transactions from finalized to latest", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + await service.setup(); await service.start(); await service.onIdle(); @@ -129,12 +122,8 @@ test("fetches transactions from finalized to latest", async (context) => { test("fetches logs from finalized to latest", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + await service.setup(); await service.start(); await service.onIdle(); @@ -175,12 +164,8 @@ test("fetches logs from finalized to latest", async (context) => { test("handles new blocks", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + await service.setup(); await service.start(); @@ -228,12 +213,8 @@ test("handles new blocks", async (context) => { test("emits realtimeCheckpoint events", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + const emitSpy = vi.spyOn(service, "emit"); await service.setup(); @@ -264,12 +245,8 @@ test("emits realtimeCheckpoint events", async (context) => { test("marks block data as finalized", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + const emitSpy = vi.spyOn(service, "emit"); const { finalizedBlockNumber: originalFinalizedBlockNumber } = @@ -307,12 +284,8 @@ test("marks block data as finalized", async (context) => { test("handles 1 block shallow reorg", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + await service.setup(); await service.start(); @@ -366,12 +339,8 @@ test("handles 1 block shallow reorg", async (context) => { test("handles 3 block shallow reorg", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + const emitSpy = vi.spyOn(service, "emit"); await service.setup(); @@ -451,12 +420,8 @@ test("handles 3 block shallow reorg", async (context) => { test("handles deep reorg", async (context) => { const { eventStore } = context; - const service = new RealtimeSyncService({ - metrics, - eventStore, - logFilters, - network, - }); + const service = new RealtimeSyncService({ ...config, eventStore }); + const emitSpy = vi.spyOn(service, "emit"); await service.setup(); diff --git a/packages/core/src/realtime-sync/service.ts b/packages/core/src/realtime-sync/service.ts index a6f47acb6..5e4944cfb 100644 --- a/packages/core/src/realtime-sync/service.ts +++ b/packages/core/src/realtime-sync/service.ts @@ -19,6 +19,7 @@ import { type LightBlock, rpcBlockToLightBlock, } from "./format"; +import { LoggerService } from "@/logs/service"; type RealtimeSyncEvents = { realtimeCheckpoint: { timestamp: number }; @@ -49,6 +50,7 @@ type RealtimeSyncQueue = Queue; export class RealtimeSyncService extends Emittery { private metrics: MetricsService; + private logger: LoggerService; private eventStore: EventStore; private logFilters: LogFilter[]; network: Network; @@ -66,11 +68,13 @@ export class RealtimeSyncService extends Emittery { constructor({ metrics, + logger, eventStore, logFilters, network, }: { metrics: MetricsService; + logger: LoggerService; eventStore: EventStore; logFilters: LogFilter[]; network: Network; @@ -78,6 +82,7 @@ export class RealtimeSyncService extends Emittery { super(); this.metrics = metrics; + this.logger = logger; this.eventStore = eventStore; this.logFilters = logFilters; this.network = network; @@ -90,6 +95,12 @@ export class RealtimeSyncService extends Emittery { // Fetch the latest block for the network. const latestBlock = await this.getLatestBlock(); + this.logger.info({ + msg: `Fetched latest block at ${hexToNumber( + latestBlock.number + )} (network=${this.network.name})`, + }); + this.stats.isConnected = true; // Set the finalized block number according to the network's finality threshold. @@ -102,7 +113,8 @@ export class RealtimeSyncService extends Emittery { // Add the latest block to the unfinalized block queue. // The queue won't start immediately; see syncUnfinalizedData for details. - this.queue.addTask(latestBlock); + const priority = Number.MAX_SAFE_INTEGER - hexToNumber(latestBlock.number); + this.queue.addTask(latestBlock, { priority }); return { finalizedBlockNumber }; }; @@ -118,6 +130,9 @@ export class RealtimeSyncService extends Emittery { endBlock !== undefined && endBlock < this.finalizedBlockNumber ) ) { + this.logger.info({ + msg: `Killed realtime service, no realtime log filters found (network=${this.network.name})`, + }); return; } @@ -143,6 +158,12 @@ export class RealtimeSyncService extends Emittery { stopClock() ); + this.logger.info({ + msg: `Fetched finalized block at ${hexToNumber( + finalizedBlock.number! + )} (network=${this.network.name})`, + }); + // Add the finalized block as the first element of the list of unfinalized blocks. this.blocks.push(rpcBlockToLightBlock(finalizedBlock)); @@ -169,6 +190,10 @@ export class RealtimeSyncService extends Emittery { this.queue.clear(); // TODO: Figure out if it's necessary to wait for the queue to be idle before killing it. // await this.onIdle(); + + this.logger.debug({ + msg: `Killed realtime sync service (network=${this.network.name})`, + }); }; onIdle = async () => { @@ -195,7 +220,8 @@ export class RealtimeSyncService extends Emittery { addNewLatestBlock = async () => { const block = await this.getLatestBlock(); - this.queue.addTask(block); + const priority = Number.MAX_SAFE_INTEGER - hexToNumber(block.number); + this.queue.addTask(block, { priority }); }; private buildQueue = () => { @@ -235,6 +261,9 @@ export class RealtimeSyncService extends Emittery { // 1) We already saw and handled this block. No-op. if (this.blocks.find((b) => b.hash === newBlock.hash)) { + this.logger.debug({ + msg: `Skipped block, already processed (${this.network.name}, ${newBlock.number})`, + }); return; } @@ -313,6 +342,11 @@ export class RealtimeSyncService extends Emittery { newBlock.timestamp ); + this.logger.info({ + msg: `Processed new head block at ${newBlock.number} (network=${this.network.name})`, + matchedLogCount, + }); + this.stats.blocks[newBlock.number] = { bloom: { hit: isMatchedLogPresentInBlock, @@ -355,6 +389,11 @@ export class RealtimeSyncService extends Emittery { this.emit("finalityCheckpoint", { timestamp: newFinalizedBlock.timestamp, }); + + this.logger.info({ + msg: `Updated finality checkpoint to ${newFinalizedBlock.number} (network=${this.network.name})`, + matchedLogCount, + }); } return; @@ -394,12 +433,18 @@ export class RealtimeSyncService extends Emittery { const missingBlocks = await Promise.all(missingBlockRequests); // Add blocks to the queue from oldest to newest. Include the current block. - for (const block of [...missingBlocks, newBlockWithTransactions].sort( - (a, b) => hexToNumber(a.number) - hexToNumber(b.number) - )) { - this.queue.addTask(block); + for (const block of [...missingBlocks, newBlockWithTransactions]) { + const priority = Number.MAX_SAFE_INTEGER - hexToNumber(block.number); + this.queue.addTask(block, { priority }); } + this.logger.info({ + msg: `Fetched missing block range [${ + (missingBlockNumbers[0], + missingBlockNumbers[missingBlockNumbers.length - 1]) + }] (network=${this.network.name})`, + }); + return; } @@ -442,17 +487,21 @@ export class RealtimeSyncService extends Emittery { // Add blocks from the canonical chain (they've already been fetched). for (const block of canonicalBlocksWithTransactions) { - this.queue.addTask(block); + const priority = Number.MAX_SAFE_INTEGER - hexToNumber(block.number); + this.queue.addTask(block, { priority }); } // Also add a new latest block, so we don't have to wait for the next poll to // start fetching any newer blocks on the canonical chain. await this.addNewLatestBlock(); - this.emit("shallowReorg", { commonAncestorTimestamp: commonAncestorBlock.timestamp, }); + this.logger.info({ + msg: `Reconciled ${depth}-block reorg with common ancestor block ${commonAncestorBlock.number} (network=${this.network.name})`, + }); + return; } @@ -487,5 +536,9 @@ export class RealtimeSyncService extends Emittery { detectedAtBlockNumber: newBlock.number, minimumDepth: depth, }); + + this.logger.warn({ + msg: `Unable to reconcile >${depth}-block reorg (network=${this.network.name})`, + }); }; } diff --git a/packages/core/src/reload/readHandlers.ts b/packages/core/src/reload/readHandlers.ts index d220400c2..90ea98e93 100644 --- a/packages/core/src/reload/readHandlers.ts +++ b/packages/core/src/reload/readHandlers.ts @@ -8,7 +8,7 @@ import { PonderOptions } from "@/config/options"; import { Block } from "@/types/block"; import { Log } from "@/types/log"; import { Transaction } from "@/types/transaction"; -import { LoggerService } from "@/utils/logger"; +import { LoggerService } from "@/logs/service"; export interface LogEvent { name: string; @@ -118,7 +118,7 @@ export const readHandlers = async ({ outDir: buildDir, }); } else { - logger.logMessage( + logger.warn( "warning", `tsconfig.json not found, unable to resolve "@/*" path aliases. Expected at: ${tsconfigPath}` ); diff --git a/packages/core/src/reload/service.ts b/packages/core/src/reload/service.ts index 13cad956d..27d9175b3 100644 --- a/packages/core/src/reload/service.ts +++ b/packages/core/src/reload/service.ts @@ -25,7 +25,7 @@ export class ReloadService extends Emittery { resources: Resources; latestFileHashes: Record = {}; - kill?: () => Promise; + closeWatcher?: () => Promise; constructor({ resources }: { resources: Resources }) { super(); @@ -40,17 +40,12 @@ export class ReloadService extends Emittery { ]; const watcher = chokidar.watch(watchFiles); - this.kill = async () => { + this.closeWatcher = async () => { await watcher.close(); }; watcher.on("change", async (filePath) => { if (filePath === this.resources.options.configFile) { - this.resources.logger.logMessage( - "error", - "detected change in ponder.config.ts. " + - pico.bold("Restart the server.") - ); this.emit("ponderConfigChanged"); return; } @@ -58,10 +53,7 @@ export class ReloadService extends Emittery { if (this.isFileChanged(filePath)) { const fileName = path.basename(filePath); - this.resources.logger.logMessage( - "event", - "detected change in " + pico.bold(fileName) - ); + this.resources.logger.info({ msg: `Detected change in ${fileName}` }); this.resources.errors.clearHandlerError(); @@ -74,6 +66,11 @@ export class ReloadService extends Emittery { }); } + async kill() { + this.closeWatcher?.(); + this.resources.logger.debug({ msg: `Killed build service` }); + } + async loadHandlers() { try { const handlers = await readHandlers({ diff --git a/packages/core/src/server/service.ts b/packages/core/src/server/service.ts index 7c73bc1f5..872823c96 100644 --- a/packages/core/src/server/service.ts +++ b/packages/core/src/server/service.ts @@ -10,7 +10,7 @@ import { Resources } from "@/Ponder"; import { UserStore } from "@/user-store/store"; export type ServerServiceEvents = { - serverStarted: { desiredPort: number; port: number }; + serverStarted: { port: number }; }; export class ServerService extends Emittery { @@ -18,6 +18,7 @@ export class ServerService extends Emittery { userStore: UserStore; app?: express.Express; + private resolvedPort?: number; private terminate?: () => Promise; private graphqlMiddleware?: express.Handler; @@ -40,15 +41,22 @@ export class ServerService extends Emittery { this.app.use(cors()); // If the desired port is unavailable, detect-port will find the next available port. - const resolvedPort = await detectPort(this.resources.options.port); + this.resolvedPort = await detectPort(this.resources.options.port); - const server = this.app.listen(resolvedPort); + const server = this.app.listen(this.resolvedPort); const terminator = createHttpTerminator({ server }); this.terminate = () => terminator.terminate(); this.emit("serverStarted", { - desiredPort: this.resources.options.port, - port: resolvedPort, + port: this.resolvedPort, + }); + + this.resources.logger.info({ + msg: `Server started on port ${this.resolvedPort} ${ + this.resolvedPort !== this.resources.options.port + ? `(port ${this.resources.options.port} was unavailable)` + : "" + }`, }); this.app.post("/metrics", async (_, res) => { @@ -82,10 +90,9 @@ export class ServerService extends Emittery { const elapsed = Math.floor(process.uptime()); if (elapsed > max) { - this.resources.logger.logMessage( - "warning", - `Historical sync duration has exceeded the max healthcheck duration of ${max} seconds (current: ${elapsed}). Sevice is now responding as healthy and may serve incomplete data.` - ); + this.resources.logger.warn({ + msg: `Historical sync duration has exceeded the max healthcheck duration of ${max} seconds (current: ${elapsed}). Sevice is now responding as healthy and may serve incomplete data.`, + }); return res.status(200).send(); } @@ -108,5 +115,16 @@ export class ServerService extends Emittery { async teardown() { await this.terminate?.(); + this.resources.logger.debug({ + msg: `Killed server on port ${this.resolvedPort}`, + }); + } + + setIsHistoricalEventProcessingComplete() { + this.isHistoricalEventProcessingComplete = true; + + this.resources.logger.info({ + msg: `Server now responding as healthy`, + }); } } diff --git a/packages/core/src/ui/app.tsx b/packages/core/src/ui/app.tsx index 2b9d86f17..9fc4da974 100644 --- a/packages/core/src/ui/app.tsx +++ b/packages/core/src/ui/app.tsx @@ -144,11 +144,11 @@ export const setupInkApp = (ui: UiState) => { const { rerender, unmount: inkUnmount, clear } = inkRender(); const render = (ui: UiState) => { - rerender(); + // rerender(); }; const unmount = () => { - clear(); + // clear(); inkUnmount(); }; return { render, unmount }; diff --git a/packages/core/src/ui/service.ts b/packages/core/src/ui/service.ts index d8943471c..49bb6235f 100644 --- a/packages/core/src/ui/service.ts +++ b/packages/core/src/ui/service.ts @@ -98,7 +98,7 @@ export class UiService { const countText = `${cachedBlocks + completedBlocks}/${totalBlocks}`; - this.resources.logger.logMessage( + this.resources.logger.info( "historical", `${contract.name}: ${`(${etaText + " | " + countText})`}` ); diff --git a/packages/core/src/user-handlers/service.ts b/packages/core/src/user-handlers/service.ts index 83397ec09..9565b480e 100644 --- a/packages/core/src/user-handlers/service.ts +++ b/packages/core/src/user-handlers/service.ts @@ -103,8 +103,8 @@ export class EventHandlerService extends Emittery { this.eventAggregatorService = eventAggregatorService; this.logFilters = logFilters; - // Build the injected contract objects. They depend only on contract config, - // so they can't be hot reloaded. + // Build the injected contract objects here. + // They depend only on contract config, so they can't be hot reloaded. contracts.forEach((contract) => { this.injectedContracts[contract.name] = getInjectedContract({ contract, @@ -113,13 +113,14 @@ export class EventHandlerService extends Emittery { }); }); - // Setup the event processing mutex. this.eventProcessingMutex = new Mutex(); } kill = () => { this.queue?.clear(); this.eventProcessingMutex.cancel(); + + this.resources.logger.debug({ msg: `Killed user handler service` }); }; reset = async ({ @@ -160,9 +161,17 @@ export class EventHandlerService extends Emittery { }); } + // If either the schema or handlers have not been provided yet, + // we're not ready to process events, so it's safe to return early. + if (!this.schema || !this.handlers) return; + this.resetEventQueue(); await this.userStore.reload({ schema: this.schema }); + this.resources.logger.debug({ + msg: `Reset user store (versionId=${this.userStore.versionId})`, + }); + this.eventsHandledToTimestamp = 0; this.metrics.latestHandledEventTimestamp = 0; @@ -179,6 +188,10 @@ export class EventHandlerService extends Emittery { this.resetEventQueue(); await this.userStore.revert({ safeTimestamp: commonAncestorTimestamp }); + this.resources.logger.debug({ + msg: `Reverted user store to safe timestamp ${commonAncestorTimestamp}`, + }); + this.eventsHandledToTimestamp = commonAncestorTimestamp; this.metrics.latestHandledEventTimestamp = commonAncestorTimestamp; @@ -236,6 +249,10 @@ export class EventHandlerService extends Emittery { count: events.length, toTimestamp: toTimestamp, }); + + this.resources.logger.debug({ + msg: `Processed ${events.length} events in timestamp range [${fromTimestamp}, ${toTimestamp}]`, + }); }); } catch (error) { // Pending locks get cancelled in resetEventQueue. This is expected, so it's safe to diff --git a/packages/core/src/utils/logger.ts b/packages/core/src/utils/logger.ts deleted file mode 100644 index 3717556f5..000000000 --- a/packages/core/src/utils/logger.ts +++ /dev/null @@ -1,72 +0,0 @@ -import pico from "picocolors"; - -/** - * Log levels: - * 0 -> silent - * 1 -> error - * 2 -> info - * 3 -> warn - * 4 -> debug - * 5 -> trace - */ - -export class LoggerService { - logLevel: number; - - constructor({ options }: { options: { logLevel: number } }) { - this.logLevel = options.logLevel; - } - - error = (...args: Parameters) => { - if (this.logLevel > 0) console.log(...args); - }; - info = (...args: Parameters) => { - if (this.logLevel > 1) console.log(...args); - }; - warn = (...args: Parameters) => { - if (this.logLevel > 2) console.log(...args); - }; - debug = (...args: Parameters) => { - if (this.logLevel > 3) console.log(...args); - }; - trace = (...args: Parameters) => { - if (this.logLevel > 4) console.log(...args); - }; - - private maxWidth = 0; - // This function is specifically for message logs. - logMessage( - kind: "event" | "error" | "warning" | "historical" | "realtime" | "indexer", - message: string - ) { - this.maxWidth = Math.max(this.maxWidth, kind.length); - const padded = kind.padEnd(this.maxWidth, " "); - - switch (kind) { - case "event": { - this.info(pico.magenta(padded) + " - " + message); - break; - } - case "error": { - this.error(pico.red(padded) + " - " + message); - break; - } - case "warning": { - this.error(pico.yellow(padded) + " - " + message); - break; - } - case "historical": { - this.info(pico.yellow(padded) + " - " + message); - break; - } - case "realtime": { - this.info(pico.cyan(padded) + " - " + message); - break; - } - case "indexer": { - this.info(pico.blue(padded) + " - " + message); - break; - } - } - } -} From 6cdd7828932a90244132b00cbcb00d12048fa871 Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Mon, 26 Jun 2023 23:01:01 -0400 Subject: [PATCH 07/12] more logs, improve log format --- packages/core/src/Ponder.ts | 12 ++++- packages/core/src/codegen/service.ts | 10 ++++ packages/core/src/historical-sync/service.ts | 26 +++++---- packages/core/src/logs/service.ts | 57 ++++++++++++++++---- packages/core/src/realtime-sync/service.ts | 39 ++++++++++---- packages/core/src/reload/readHandlers.ts | 12 +---- packages/core/src/reload/service.ts | 15 +++--- packages/core/src/server/service.ts | 4 ++ packages/core/src/user-handlers/service.ts | 18 +++++-- 9 files changed, 141 insertions(+), 52 deletions(-) diff --git a/packages/core/src/Ponder.ts b/packages/core/src/Ponder.ts index b99bedab8..10ba3e086 100644 --- a/packages/core/src/Ponder.ts +++ b/packages/core/src/Ponder.ts @@ -154,7 +154,11 @@ export class Ponder { async setup() { this.resources.logger.debug({ - msg: `Using config at ${this.resources.options.configFile}`, + service: "app", + msg: `Started using config file: ${path.relative( + this.resources.options.rootDir, + this.resources.options.configFile + )}`, }); this.registerServiceDependencies(); @@ -270,12 +274,16 @@ export class Ponder { await this.serverService.teardown(); await this.userStore.teardown(); - this.resources.logger.debug({ msg: `Shutdown sequence completed` }); + this.resources.logger.debug({ + service: "app", + msg: `Finished shutdown sequence`, + }); } private registerServiceDependencies() { this.reloadService.on("ponderConfigChanged", async () => { this.resources.logger.fatal({ + service: "build", msg: "Detected change in ponder.config.ts", }); await this.kill(); diff --git a/packages/core/src/codegen/service.ts b/packages/core/src/codegen/service.ts index 57a97a3b0..8e764bb55 100644 --- a/packages/core/src/codegen/service.ts +++ b/packages/core/src/codegen/service.ts @@ -81,6 +81,11 @@ export class CodegenService extends Emittery { const filePath = path.join(this.resources.options.generatedDir, "index.ts"); ensureDirExists(filePath); writeFileSync(filePath, final, "utf8"); + + this.resources.logger.debug({ + service: "codegen", + msg: `Wrote new file at generated/index.ts`, + }); } generateSchemaFile({ graphqlSchema }: { graphqlSchema: GraphQLSchema }) { @@ -97,5 +102,10 @@ export class CodegenService extends Emittery { ); ensureDirExists(filePath); writeFileSync(filePath, final, "utf8"); + + this.resources.logger.debug({ + service: "codegen", + msg: `Wrote new file at generated/schema.graphql`, + }); } } diff --git a/packages/core/src/historical-sync/service.ts b/packages/core/src/historical-sync/service.ts index 36f4d248e..8eb2cf15b 100644 --- a/packages/core/src/historical-sync/service.ts +++ b/packages/core/src/historical-sync/service.ts @@ -190,7 +190,8 @@ export class HistoricalSyncService extends Emittery { this.stats.logFilters[logFilter.name].cacheRate = cacheRate; this.logger.info({ - msg: `Historical sync started with ${formatPercentage( + service: "historical", + msg: `Started sync with ${formatPercentage( cacheRate )} cached (network=${this.network.name})`, network: this.network.name, @@ -241,9 +242,10 @@ export class HistoricalSyncService extends Emittery { }); this.emit("syncComplete"); this.logger.info({ - msg: `Historical sync completed in ${formatEta( - this.stats.duration - )} (network=${this.network.name})`, + service: "historical", + msg: `Completed sync in ${formatEta(this.stats.duration)} (network=${ + this.network.name + })`, network: this.network.name, duration: this.stats.duration, }); @@ -261,6 +263,7 @@ export class HistoricalSyncService extends Emittery { // TODO: Figure out if it's necessary to wait for the queue to be idle before killing it. // await this.onIdle(); this.logger.debug({ + service: "historical", msg: `Killed historical sync service (network=${this.network.name})`, }); }; @@ -308,11 +311,12 @@ export class HistoricalSyncService extends Emittery { ); } - this.logger.debug({ + this.logger.trace({ + service: "historical", msg: task.kind === "LOG_SYNC" - ? `Historical sync log task completed` - : `Historical sync block task completed`, + ? `Completed log sync task` + : `Completed block sync task`, network: this.network.name, logFilter: logFilter.name, ...(task.kind === "LOG_SYNC" @@ -439,6 +443,7 @@ export class HistoricalSyncService extends Emittery { this.emit("error", { error: queueError }); this.logger.error({ + service: "historical", msg: task.kind === "LOG_SYNC" ? `Historical sync log task failed` @@ -472,9 +477,10 @@ export class HistoricalSyncService extends Emittery { this.stats.isComplete = true; this.emit("syncComplete"); this.logger.info({ - msg: `Historical sync completed in ${formatEta( - this.stats.duration - )} (network=${this.network.name})`, + service: "historical", + msg: `Completed sync in ${formatEta(this.stats.duration)} (network=${ + this.network.name + })`, network: this.network.name, duration: this.stats.duration, }); diff --git a/packages/core/src/logs/service.ts b/packages/core/src/logs/service.ts index 26cac2ce6..a52124c05 100644 --- a/packages/core/src/logs/service.ts +++ b/packages/core/src/logs/service.ts @@ -1,11 +1,12 @@ import path from "node:path"; import pino, { type Logger, type LevelWithSilent } from "pino"; import pretty from "pino-pretty"; +import pc from "picocolors"; type LogFunctionArgs = - | [obj: object, msg?: string, ...args: any[]] - | [obj: unknown, msg?: string, ...args: any[]] - | [msg: string, ...args: any[]]; + | [string] + | [{ msg: string; service?: string } & { [key: string]: any }] + | [string, { service?: string } & { [key: string]: any }]; export class LoggerService { private logger: Logger; @@ -22,15 +23,10 @@ export class LoggerService { stream: pretty({ // Write logs in the main thread (worse performance, better DX). sync: true, - // Only include the level, time, and msg properties. + // Exclude all properties from default formatting provided by `pino-pretty`. // All structured properties will still be included in the log file. - include: "level,time", - // Use UTC timestamps rather than local (the default). - translateTime: "UTC:HH:MM:ss.l", - customPrettifiers: { - // Remove the default enclosing brackets. - time: (timestamp) => `${timestamp}`, - }, + include: "", + messageFormat: formatMessage, }), }); } @@ -65,3 +61,42 @@ export class LoggerService { this.logger.trace(...(args as [any])); }; } + +const levels = { + 60: { label: "FATAL", colorize: (s: string) => pc.bgRed(s) }, + 50: { label: "ERROR", colorize: (s: string) => pc.red(s) }, + 40: { label: "WARN ", colorize: (s: string) => pc.yellow(s) }, + 30: { label: "INFO ", colorize: (s: string) => pc.green(s) }, + 20: { label: "DEBUG", colorize: (s: string) => pc.blue(s) }, + 10: { label: "TRACE", colorize: (s: string) => pc.gray(s) }, +} as const; + +const formatMessage = (log: { [key: string]: any }) => { + let result = ""; + + const timestamp = log["time"] as number; + const level = levels[(log["level"] as keyof typeof levels) ?? 30]; + const message = log["msg"] as string | undefined; + const service = log["service"] as string | undefined; + + const date = new Date(timestamp); + const hours = String(date.getUTCHours()).padStart(2, "0"); + const minutes = String(date.getUTCMinutes()).padStart(2, "0"); + const seconds = String(date.getUTCSeconds()).padStart(2, "0"); + const millis = String(date.getUTCMilliseconds()).padStart(3, "0"); + const time = `${hours}:${minutes}:${seconds}.${millis} `; + + result += pc.isColorSupported ? pc.gray(time) : time; + + result += pc.isColorSupported ? level.colorize(level.label) : level.label; + + if (service) { + result += pc.isColorSupported + ? " " + pc.cyan(service.padEnd(10, " ")) + : " " + service.padEnd(10, " "); + } + + result += pc.reset(` ${message}`); + + return result; +}; diff --git a/packages/core/src/realtime-sync/service.ts b/packages/core/src/realtime-sync/service.ts index 5e4944cfb..2aa885a96 100644 --- a/packages/core/src/realtime-sync/service.ts +++ b/packages/core/src/realtime-sync/service.ts @@ -96,6 +96,7 @@ export class RealtimeSyncService extends Emittery { const latestBlock = await this.getLatestBlock(); this.logger.info({ + service: "realtime", msg: `Fetched latest block at ${hexToNumber( latestBlock.number )} (network=${this.network.name})`, @@ -130,8 +131,9 @@ export class RealtimeSyncService extends Emittery { endBlock !== undefined && endBlock < this.finalizedBlockNumber ) ) { - this.logger.info({ - msg: `Killed realtime service, no realtime log filters found (network=${this.network.name})`, + this.logger.warn({ + service: "realtime", + msg: `No realtime log filters found (network=${this.network.name})`, }); return; } @@ -159,6 +161,7 @@ export class RealtimeSyncService extends Emittery { ); this.logger.info({ + service: "realtime", msg: `Fetched finalized block at ${hexToNumber( finalizedBlock.number! )} (network=${this.network.name})`, @@ -192,6 +195,7 @@ export class RealtimeSyncService extends Emittery { // await this.onIdle(); this.logger.debug({ + service: "realtime", msg: `Killed realtime sync service (network=${this.network.name})`, }); }; @@ -262,7 +266,8 @@ export class RealtimeSyncService extends Emittery { // 1) We already saw and handled this block. No-op. if (this.blocks.find((b) => b.hash === newBlock.hash)) { this.logger.debug({ - msg: `Skipped block, already processed (${this.network.name}, ${newBlock.number})`, + service: "realtime", + msg: `Skipped new block at ${newBlock.number}, already seen (network=${this.network.name})`, }); return; } @@ -342,11 +347,24 @@ export class RealtimeSyncService extends Emittery { newBlock.timestamp ); - this.logger.info({ + this.logger.debug({ + service: "realtime", msg: `Processed new head block at ${newBlock.number} (network=${this.network.name})`, - matchedLogCount, }); + if (matchedLogCount > 0) { + this.logger.info({ + service: "realtime", + msg: `Found ${ + matchedLogCount === 1 + ? "1 matched log" + : `${matchedLogCount} matched logs` + } in new head block ${newBlock.number} (network=${ + this.network.name + })`, + }); + } + this.stats.blocks[newBlock.number] = { bloom: { hit: isMatchedLogPresentInBlock, @@ -390,7 +408,8 @@ export class RealtimeSyncService extends Emittery { timestamp: newFinalizedBlock.timestamp, }); - this.logger.info({ + this.logger.debug({ + service: "realtime", msg: `Updated finality checkpoint to ${newFinalizedBlock.number} (network=${this.network.name})`, matchedLogCount, }); @@ -439,9 +458,9 @@ export class RealtimeSyncService extends Emittery { } this.logger.info({ - msg: `Fetched missing block range [${ - (missingBlockNumbers[0], - missingBlockNumbers[missingBlockNumbers.length - 1]) + service: "realtime", + msg: `Fetched unfinalized block range [${missingBlockNumbers[0]}, ${ + missingBlockNumbers[missingBlockNumbers.length - 1] }] (network=${this.network.name})`, }); @@ -499,6 +518,7 @@ export class RealtimeSyncService extends Emittery { }); this.logger.info({ + service: "realtime", msg: `Reconciled ${depth}-block reorg with common ancestor block ${commonAncestorBlock.number} (network=${this.network.name})`, }); @@ -538,6 +558,7 @@ export class RealtimeSyncService extends Emittery { }); this.logger.warn({ + service: "realtime", msg: `Unable to reconcile >${depth}-block reorg (network=${this.network.name})`, }); }; diff --git a/packages/core/src/reload/readHandlers.ts b/packages/core/src/reload/readHandlers.ts index 90ea98e93..7e6b7086f 100644 --- a/packages/core/src/reload/readHandlers.ts +++ b/packages/core/src/reload/readHandlers.ts @@ -8,7 +8,6 @@ import { PonderOptions } from "@/config/options"; import { Block } from "@/types/block"; import { Log } from "@/types/log"; import { Transaction } from "@/types/transaction"; -import { LoggerService } from "@/logs/service"; export interface LogEvent { name: string; @@ -69,13 +68,7 @@ export class PonderApp> { } } -export const readHandlers = async ({ - options, - logger, -}: { - options: PonderOptions; - logger: LoggerService; -}) => { +export const readHandlers = async ({ options }: { options: PonderOptions }) => { const entryAppFilename = path.join(options.generatedDir, "index.ts"); if (!existsSync(entryAppFilename)) { throw new Error( @@ -118,8 +111,7 @@ export const readHandlers = async ({ outDir: buildDir, }); } else { - logger.warn( - "warning", + throw new Error( `tsconfig.json not found, unable to resolve "@/*" path aliases. Expected at: ${tsconfigPath}` ); } diff --git a/packages/core/src/reload/service.ts b/packages/core/src/reload/service.ts index 27d9175b3..8381de646 100644 --- a/packages/core/src/reload/service.ts +++ b/packages/core/src/reload/service.ts @@ -53,7 +53,10 @@ export class ReloadService extends Emittery { if (this.isFileChanged(filePath)) { const fileName = path.basename(filePath); - this.resources.logger.info({ msg: `Detected change in ${fileName}` }); + this.resources.logger.info({ + service: "build", + msg: `Detected change in ${fileName}`, + }); this.resources.errors.clearHandlerError(); @@ -68,15 +71,15 @@ export class ReloadService extends Emittery { async kill() { this.closeWatcher?.(); - this.resources.logger.debug({ msg: `Killed build service` }); + this.resources.logger.debug({ + service: "build", + msg: `Killed build service`, + }); } async loadHandlers() { try { - const handlers = await readHandlers({ - options: this.resources.options, - logger: this.resources.logger, - }); + const handlers = await readHandlers({ options: this.resources.options }); this.emit("newHandlers", { handlers }); } catch (error_) { const error = error_ as Error; diff --git a/packages/core/src/server/service.ts b/packages/core/src/server/service.ts index 872823c96..d9fa6e7f7 100644 --- a/packages/core/src/server/service.ts +++ b/packages/core/src/server/service.ts @@ -52,6 +52,7 @@ export class ServerService extends Emittery { }); this.resources.logger.info({ + service: "server", msg: `Server started on port ${this.resolvedPort} ${ this.resolvedPort !== this.resources.options.port ? `(port ${this.resources.options.port} was unavailable)` @@ -91,6 +92,7 @@ export class ServerService extends Emittery { if (elapsed > max) { this.resources.logger.warn({ + service: "server", msg: `Historical sync duration has exceeded the max healthcheck duration of ${max} seconds (current: ${elapsed}). Sevice is now responding as healthy and may serve incomplete data.`, }); return res.status(200).send(); @@ -116,6 +118,7 @@ export class ServerService extends Emittery { async teardown() { await this.terminate?.(); this.resources.logger.debug({ + service: "server", msg: `Killed server on port ${this.resolvedPort}`, }); } @@ -124,6 +127,7 @@ export class ServerService extends Emittery { this.isHistoricalEventProcessingComplete = true; this.resources.logger.info({ + service: "server", msg: `Server now responding as healthy`, }); } diff --git a/packages/core/src/user-handlers/service.ts b/packages/core/src/user-handlers/service.ts index 9565b480e..736e025f0 100644 --- a/packages/core/src/user-handlers/service.ts +++ b/packages/core/src/user-handlers/service.ts @@ -120,7 +120,10 @@ export class EventHandlerService extends Emittery { this.queue?.clear(); this.eventProcessingMutex.cancel(); - this.resources.logger.debug({ msg: `Killed user handler service` }); + this.resources.logger.debug({ + service: "handlers", + msg: `Killed user handler service`, + }); }; reset = async ({ @@ -169,6 +172,7 @@ export class EventHandlerService extends Emittery { await this.userStore.reload({ schema: this.schema }); this.resources.logger.debug({ + service: "handlers", msg: `Reset user store (versionId=${this.userStore.versionId})`, }); @@ -189,6 +193,7 @@ export class EventHandlerService extends Emittery { await this.userStore.revert({ safeTimestamp: commonAncestorTimestamp }); this.resources.logger.debug({ + service: "handlers", msg: `Reverted user store to safe timestamp ${commonAncestorTimestamp}`, }); @@ -250,9 +255,14 @@ export class EventHandlerService extends Emittery { toTimestamp: toTimestamp, }); - this.resources.logger.debug({ - msg: `Processed ${events.length} events in timestamp range [${fromTimestamp}, ${toTimestamp}]`, - }); + if (events.length > 0) { + this.resources.logger.info({ + service: "handlers", + msg: `Processed ${ + events.length === 1 ? "1 event" : `${events.length} events` + } in timestamp range [${fromTimestamp}, ${toTimestamp + 1})`, + }); + } }); } catch (error) { // Pending locks get cancelled in resetEventQueue. This is expected, so it's safe to From ba9a6f40a0e1cac728d2a2f30bcfb4544416021d Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Tue, 27 Jun 2023 00:58:51 -0400 Subject: [PATCH 08/12] remove pino-pretty, use console log, fix ui --- packages/core/package.json | 1 - packages/core/src/Ponder.ts | 19 ++--------- packages/core/src/logs/service.ts | 21 +++++++----- packages/core/src/server/service.ts | 6 ++-- packages/core/src/ui/HandlersBar.tsx | 6 ++-- packages/core/src/ui/app.tsx | 8 ++--- packages/core/src/ui/service.ts | 8 ++--- pnpm-lock.yaml | 49 +++------------------------- 8 files changed, 33 insertions(+), 85 deletions(-) diff --git a/packages/core/package.json b/packages/core/package.json index f3c6259e6..ec3d7c028 100644 --- a/packages/core/package.json +++ b/packages/core/package.json @@ -47,7 +47,6 @@ "pg": "^8.9.0", "picocolors": "^1.0.0", "pino": "^8.14.1", - "pino-pretty": "^10.0.0", "prettier": "^2.6.2", "prom-client": "^14.2.0", "react": "17", diff --git a/packages/core/src/Ponder.ts b/packages/core/src/Ponder.ts index 10ba3e086..4207fe724 100644 --- a/packages/core/src/Ponder.ts +++ b/packages/core/src/Ponder.ts @@ -254,9 +254,7 @@ export class Ponder { } async kill() { - this.killFunctions.forEach((fn) => { - fn(); - }); + this.killFunctions.forEach((fn) => fn()); this.eventAggregatorService.clearListeners(); await Promise.all( @@ -303,8 +301,7 @@ export class Ponder { }); this.networkSyncServices.forEach((networkSyncService) => { - const { network, historicalSyncService, realtimeSyncService } = - networkSyncService; + const { historicalSyncService, realtimeSyncService } = networkSyncService; historicalSyncService.on("historicalCheckpoint", ({ timestamp }) => { this.eventAggregatorService.handleNewHistoricalCheckpoint({ @@ -338,17 +335,6 @@ export class Ponder { timestamp: commonAncestorTimestamp, }); }); - - // // TODO: Decide what to do after a deep reorg. - // realtimeSyncService.on( - // "deepReorg", - // ({ detectedAtBlockNumber, minimumDepth }) => { - // this.resources.logger.logMessage( - // "error", - // `WARNING: Deep reorg detected on ${network.name} at block ${detectedAtBlockNumber} with a minimum depth of ${minimumDepth}` - // ); - // } - // ); }); this.eventAggregatorService.on("newCheckpoint", ({ timestamp }) => { @@ -435,6 +421,7 @@ export class Ponder { this.uiService.ui.handlersToTimestamp = this.eventHandlerService.metrics.latestHandledEventTimestamp; }, 17); + this.killFunctions.push(() => { clearInterval(interval); }); diff --git a/packages/core/src/logs/service.ts b/packages/core/src/logs/service.ts index a52124c05..e6f493861 100644 --- a/packages/core/src/logs/service.ts +++ b/packages/core/src/logs/service.ts @@ -1,6 +1,5 @@ import path from "node:path"; import pino, { type Logger, type LevelWithSilent } from "pino"; -import pretty from "pino-pretty"; import pc from "picocolors"; type LogFunctionArgs = @@ -20,14 +19,18 @@ export class LoggerService { if (level !== "silent") { streams.push({ level, - stream: pretty({ - // Write logs in the main thread (worse performance, better DX). - sync: true, - // Exclude all properties from default formatting provided by `pino-pretty`. - // All structured properties will still be included in the log file. - include: "", - messageFormat: formatMessage, - }), + stream: { + write(logString: string) { + const log = JSON.parse(logString); + const prettyLog = formatMessage(log); + console.log(prettyLog); + + // If there is an "error" property, log it. + if (log.error) { + console.log(log.error); + } + }, + }, }); } diff --git a/packages/core/src/server/service.ts b/packages/core/src/server/service.ts index d9fa6e7f7..0b006ff05 100644 --- a/packages/core/src/server/service.ts +++ b/packages/core/src/server/service.ts @@ -53,7 +53,7 @@ export class ServerService extends Emittery { this.resources.logger.info({ service: "server", - msg: `Server started on port ${this.resolvedPort} ${ + msg: `Started listening on port ${this.resolvedPort} ${ this.resolvedPort !== this.resources.options.port ? `(port ${this.resources.options.port} was unavailable)` : "" @@ -119,7 +119,7 @@ export class ServerService extends Emittery { await this.terminate?.(); this.resources.logger.debug({ service: "server", - msg: `Killed server on port ${this.resolvedPort}`, + msg: `Stopped listening on port ${this.resolvedPort}`, }); } @@ -128,7 +128,7 @@ export class ServerService extends Emittery { this.resources.logger.info({ service: "server", - msg: `Server now responding as healthy`, + msg: `Started responding as healthy`, }); } } diff --git a/packages/core/src/ui/HandlersBar.tsx b/packages/core/src/ui/HandlersBar.tsx index 687ea7475..495fa1c3b 100644 --- a/packages/core/src/ui/HandlersBar.tsx +++ b/packages/core/src/ui/HandlersBar.tsx @@ -39,10 +39,10 @@ export const HandlersBar = ({ ui }: { ui: UiState }) => { const isStarted = ui.handlersToTimestamp > 0; const titleText = () => { - if (isUpToDate) return (up to date); + if (isUpToDate) return (up to date); if (isStarted) return ( - + (up to {ui.handlersToTimestamp === 0 ? "" : dateText}) ); @@ -73,7 +73,7 @@ export const HandlersBar = ({ ui }: { ui: UiState }) => { return ( - Handlers + Event handlers {titleText()} {/* {!isUpToDate && ( */} diff --git a/packages/core/src/ui/app.tsx b/packages/core/src/ui/app.tsx index 9fc4da974..b3e6b9514 100644 --- a/packages/core/src/ui/app.tsx +++ b/packages/core/src/ui/app.tsx @@ -90,11 +90,11 @@ const App = (ui: UiState) => { Historical sync {isHistoricalSyncComplete ? ( - + (done in {historicalSyncDuration}) ) : ( - (in progress) + (in progress) )} {!isHistoricalSyncComplete && ( @@ -144,11 +144,11 @@ export const setupInkApp = (ui: UiState) => { const { rerender, unmount: inkUnmount, clear } = inkRender(); const render = (ui: UiState) => { - // rerender(); + rerender(); }; const unmount = () => { - // clear(); + clear(); inkUnmount(); }; return { render, unmount }; diff --git a/packages/core/src/ui/service.ts b/packages/core/src/ui/service.ts index 49bb6235f..4b8f3f9c1 100644 --- a/packages/core/src/ui/service.ts +++ b/packages/core/src/ui/service.ts @@ -98,10 +98,10 @@ export class UiService { const countText = `${cachedBlocks + completedBlocks}/${totalBlocks}`; - this.resources.logger.info( - "historical", - `${contract.name}: ${`(${etaText + " | " + countText})`}` - ); + // this.resources.logger.info( + // "historical", + // `${contract.name}: ${`(${etaText + " | " + countText})`}` + // ); }); } } diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 4a6c5d59e..51472a286 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -186,7 +186,6 @@ importers: pg: ^8.9.0 picocolors: ^1.0.0 pino: ^8.14.1 - pino-pretty: ^10.0.0 prettier: ^2.6.2 prom-client: ^14.2.0 react: '17' @@ -227,7 +226,6 @@ importers: pg: 8.9.0 picocolors: 1.0.0 pino: 8.14.1 - pino-pretty: 10.0.0 prettier: 2.8.2 prom-client: 14.2.0 react: 17.0.2 @@ -5105,10 +5103,6 @@ packages: /color-name/1.1.4: resolution: {integrity: sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==} - /colorette/2.0.20: - resolution: {integrity: sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==} - dev: false - /colors/1.4.0: resolution: {integrity: sha512-a+UqTh4kgZg/SlGvfbzDHpgRu7AAQOmmqRHJnxhRZICKFUT91brVhNNt58CMWU9PsBbv3PDCZUHbVxuDiH2mtA==} engines: {node: '>=0.1.90'} @@ -5377,10 +5371,6 @@ packages: resolution: {integrity: sha512-68s5jYdlvasItOJnCuI2Q9s4q98g0pCyL3HrcKJu8KNugUl8ahgmZYg38ysLTgQjjXX3H8CJLkAvWrclWfcalw==} dev: true - /dateformat/4.6.3: - resolution: {integrity: sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==} - dev: false - /debug/2.6.9: resolution: {integrity: sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==} peerDependencies: @@ -6937,10 +6927,6 @@ packages: engines: {node: '> 0.1.90'} dev: true - /fast-copy/3.0.1: - resolution: {integrity: sha512-Knr7NOtK3HWRYGtHoJrjkaWepqT8thIVGAwt0p0aUs1zqkAzXZV4vo9fFNwyb5fcqK1GKYFYxldQdIDVKhUAfA==} - dev: false - /fast-decode-uri-component/1.0.1: resolution: {integrity: sha512-WKgKWg5eUxvRZGwW8FvfbaH7AXSh2cL+3j5fMGzUMCxWBJ3dV3a7Wz8y2f/uQ0e3B6WmodD3oS54jTQ9HVTIIg==} dev: true @@ -7014,6 +7000,7 @@ packages: /fast-safe-stringify/2.1.1: resolution: {integrity: sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==} + dev: true /fast-url-parser/1.1.3: resolution: {integrity: sha512-5jOCVXADYNuRkKFzNJ0dCCewsZiYo0dz8QNYljkOpFC6r2U4OBmKtvm/Tsuh4w1YYdDqDb31a8TVhBJ2OJKdqQ==} @@ -7697,13 +7684,6 @@ packages: resolution: {integrity: sha512-Pkw+xBHuV6xFeJprJe2BBEoDV+AvQySaz3pPDRUs5PNZEMQjpXJJueqrpcHIXxnWTcAGi/UOCgVShlkY6kLoqg==} dev: false - /help-me/4.2.0: - resolution: {integrity: sha512-TAOnTB8Tz5Dw8penUuzHVrKNKlCIbwwbHnXraNJxPwf8LRtE2HlM84RYuezMFcwOJmoYOCWVDyJ8TQGxn9PgxA==} - dependencies: - glob: 8.1.0 - readable-stream: 3.6.2 - dev: false - /hexoid/1.0.0: resolution: {integrity: sha512-QFLV0taWQOZtvIRIAdBChesmogZrtuXvVWsFHZTk2SU+anspqZ2vMnoLg7IE1+Uk16N19APic1BuF8bC8c2m5g==} engines: {node: '>=8'} @@ -8462,6 +8442,7 @@ packages: /joycon/3.1.1: resolution: {integrity: sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==} engines: {node: '>=10'} + dev: true /js-sha3/0.8.0: resolution: {integrity: sha512-gF1cRrHhIzNfToc802P800N8PpXS+evLLXfsVpowqmAFR9uwbi89WvXg2QspOmXL8QL86J4T1EpFu+yUkwJY3Q==} @@ -9480,6 +9461,7 @@ packages: /minimist/1.2.8: resolution: {integrity: sha512-2yyAR8qBkN3YuheJanUpWC5U3bb5osDywNB8RzDVlDwDHbocAJveqqj1u8+SVD7jkWT4yvsHCpWqqWqAxb0zCA==} + dev: true /minipass/3.3.6: resolution: {integrity: sha512-DxiNidxSEK+tHG6zOIklvNOwm3hvCrbUrdtzY74U6HKTJxvIDfOUL5W5P2Ghd3DTkhhKPYGqeNUIh5qcM4YBfw==} @@ -10347,26 +10329,6 @@ packages: split2: 4.1.0 dev: false - /pino-pretty/10.0.0: - resolution: {integrity: sha512-zKFjYXBzLaLTEAN1ayKpHXtL5UeRQC7R3lvhKe7fWs7hIVEjKGG/qIXwQt9HmeUp71ogUd/YcW+LmMwRp4KT6Q==} - hasBin: true - dependencies: - colorette: 2.0.20 - dateformat: 4.6.3 - fast-copy: 3.0.1 - fast-safe-stringify: 2.1.1 - help-me: 4.2.0 - joycon: 3.1.1 - minimist: 1.2.8 - on-exit-leak-free: 2.1.0 - pino-abstract-transport: 1.0.0 - pump: 3.0.0 - readable-stream: 4.4.0 - secure-json-parse: 2.7.0 - sonic-boom: 3.3.0 - strip-json-comments: 3.1.1 - dev: false - /pino-std-serializers/6.2.1: resolution: {integrity: sha512-wHuWB+CvSVb2XqXM0W/WOYUkVSPbiJb9S5fNB7TBhd8s892Xq910bRxwHtC4l71hgztObTjXL6ZheZXFjhDrDQ==} dev: false @@ -11282,10 +11244,6 @@ packages: kind-of: 6.0.3 dev: false - /secure-json-parse/2.7.0: - resolution: {integrity: sha512-6aU+Rwsezw7VR8/nyvKTx8QpWH9FrcYiXXlqC4z5d5XQBDRqtbfsRjnwGyqbi3gddNtWHuEk9OANUotL26qKUw==} - dev: false - /semver-compare/1.0.0: resolution: {integrity: sha512-YM3/ITh2MJ5MtzaM429anh+x2jiLVjqILF4m4oyQB18W7Ggea7BfqdH/wGMK7dDiMghv/6WG7znWMwUDzJiXow==} dev: false @@ -11802,6 +11760,7 @@ packages: /strip-json-comments/3.1.1: resolution: {integrity: sha512-6fPc+R4ihwqP6N/aIv2f1gMH8lOVtWQHoqC4yK6oSDVVocumAsfCqjkXnqiYMhmMwS/mEHLp7Vehlt3ql6lEig==} engines: {node: '>=8'} + dev: true /strip-literal/1.0.1: resolution: {integrity: sha512-QZTsipNpa2Ppr6v1AmJHESqJ3Uz247MUS0OjrnnZjFAvEoWqxuyFuXn2xLgMtRnijJShAa1HL0gtJyUs7u7n3Q==} From aba6cfd3d3481e9ac44f95698ab615192742e0d7 Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Tue, 27 Jun 2023 13:30:40 -0400 Subject: [PATCH 09/12] more error logging improvements --- packages/core/src/Ponder.ts | 33 ++------- packages/core/src/_test/utils.ts | 4 +- packages/core/src/errors/ErrorService.ts | 20 ----- packages/core/src/errors/eventHandler.ts | 37 ---------- packages/core/src/errors/postgres.ts | 2 +- packages/core/src/errors/queue.ts | 2 +- packages/core/src/errors/service.ts | 16 ++++ packages/core/src/errors/sqlite.ts | 2 +- packages/core/src/errors/user.ts | 15 ++++ .../core/src/historical-sync/service.test.ts | 11 ++- packages/core/src/logs/service.ts | 61 ++++++++------- packages/core/src/reload/service.ts | 38 ++++++++-- packages/core/src/user-handlers/service.ts | 74 +++++++++++-------- packages/core/src/user-handlers/trace.ts | 35 +++++---- .../src/{errors/utils.ts => utils/print.ts} | 2 +- 15 files changed, 183 insertions(+), 169 deletions(-) delete mode 100644 packages/core/src/errors/ErrorService.ts delete mode 100644 packages/core/src/errors/eventHandler.ts create mode 100644 packages/core/src/errors/service.ts create mode 100644 packages/core/src/errors/user.ts rename packages/core/src/{errors/utils.ts => utils/print.ts} (98%) diff --git a/packages/core/src/Ponder.ts b/packages/core/src/Ponder.ts index 4207fe724..c1c83f66d 100644 --- a/packages/core/src/Ponder.ts +++ b/packages/core/src/Ponder.ts @@ -1,4 +1,3 @@ -import pico from "picocolors"; import path from "node:path"; import { CodegenService } from "@/codegen/service"; @@ -8,12 +7,13 @@ import { buildLogFilters, LogFilter } from "@/config/logFilters"; import { type Network, buildNetwork } from "@/config/networks"; import { type PonderOptions } from "@/config/options"; import { type ResolvedPonderConfig } from "@/config/ponderConfig"; -import { ErrorService } from "@/errors/ErrorService"; +import { UserErrorService } from "@/errors/service"; import { EventAggregatorService } from "@/event-aggregator/service"; import { PostgresEventStore } from "@/event-store/postgres/store"; import { SqliteEventStore } from "@/event-store/sqlite/store"; import { type EventStore } from "@/event-store/store"; import { HistoricalSyncService } from "@/historical-sync/service"; +import { LoggerService } from "@/logs/service"; import { MetricsService } from "@/metrics/service"; import { RealtimeSyncService } from "@/realtime-sync/service"; import { ReloadService } from "@/reload/service"; @@ -24,12 +24,11 @@ import { PostgresUserStore } from "@/user-store/postgres/store"; import { SqliteUserStore } from "@/user-store/sqlite/store"; import { type UserStore } from "@/user-store/store"; import { formatEta } from "@/utils/format"; -import { LoggerService } from "@/logs/service"; export type Resources = { options: PonderOptions; logger: LoggerService; - errors: ErrorService; + errors: UserErrorService; metrics: MetricsService; }; @@ -74,7 +73,7 @@ export class Ponder { level: options.logLevel, dir: options.logDir, }); - const errors = new ErrorService(); + const errors = new UserErrorService(); const metrics = new MetricsService(); const resources = { options, logger, errors, metrics }; @@ -361,21 +360,9 @@ export class Ponder { } private registerUiHandlers() { - // this.resources.errors.on("handlerError", ({ error }) => { - // this.resources.logger.logMessage("error", error.message); - // }); - this.networkSyncServices.forEach((networkSyncService) => { const { historicalSyncService, logFilters } = networkSyncService; - // historicalSyncService.on("error", ({ error }) => { - // this.resources.logger.logMessage("error", error.message); - // }); - - // realtimeSyncService.on("error", ({ error }) => { - // this.resources.logger.logMessage("error", error.message); - // }); - historicalSyncService.on("syncStarted", () => { logFilters.forEach(({ name }) => { this.uiService.ui.historicalSyncLogFilterStats[name].startTimestamp = @@ -411,7 +398,7 @@ export class Ponder { ); } - this.uiService.ui.handlerError = this.eventHandlerService.metrics.error; + this.uiService.ui.handlerError = this.resources.errors.hasUserError; this.uiService.ui.handlersHandledTotal = this.eventHandlerService.metrics.eventsAddedToQueue; this.uiService.ui.handlersCurrent = @@ -434,7 +421,7 @@ export class Ponder { }); this.eventHandlerService.on("taskCompleted", () => { - this.uiService.ui.handlerError = this.eventHandlerService.metrics.error; + this.uiService.ui.handlerError = this.resources.errors.hasUserError; this.uiService.ui.handlersHandledTotal = this.eventHandlerService.metrics.eventsAddedToQueue; this.uiService.ui.handlersCurrent = @@ -449,13 +436,5 @@ export class Ponder { this.serverService.on("serverStarted", ({ port }) => { this.uiService.ui.port = port; }); - - this.resources.errors.on("handlerError", () => { - this.uiService.ui.handlerError = true; - }); - - this.resources.errors.on("handlerErrorCleared", () => { - this.uiService.ui.handlerError = false; - }); } } diff --git a/packages/core/src/_test/utils.ts b/packages/core/src/_test/utils.ts index 1dd180271..d2a2a649c 100644 --- a/packages/core/src/_test/utils.ts +++ b/packages/core/src/_test/utils.ts @@ -8,7 +8,7 @@ import { import { mainnet } from "viem/chains"; import { buildOptions } from "@/config/options"; -import { ErrorService } from "@/errors/ErrorService"; +import { UserErrorService } from "@/errors/service"; import { MetricsService } from "@/metrics/service"; import { Resources } from "@/Ponder"; import { LoggerService } from "@/logs/service"; @@ -62,6 +62,6 @@ export const testResources: Resources = { options: buildOptions({ cliOptions: { configFile: "", rootDir: "" }, }), - errors: new ErrorService(), + errors: new UserErrorService(), metrics: new MetricsService(), }; diff --git a/packages/core/src/errors/ErrorService.ts b/packages/core/src/errors/ErrorService.ts deleted file mode 100644 index d632c69a0..000000000 --- a/packages/core/src/errors/ErrorService.ts +++ /dev/null @@ -1,20 +0,0 @@ -import Emittery from "emittery"; - -type ErrorServiceEvents = { - handlerError: { error: Error }; - handlerErrorCleared: undefined; -}; - -export class ErrorService extends Emittery { - isHandlerError = false; - - submitHandlerError({ error }: { error: Error }) { - this.isHandlerError = true; - this.emit("handlerError", { error }); - } - - clearHandlerError() { - this.isHandlerError = false; - this.emit("handlerErrorCleared"); - } -} diff --git a/packages/core/src/errors/eventHandler.ts b/packages/core/src/errors/eventHandler.ts deleted file mode 100644 index 320661b5e..000000000 --- a/packages/core/src/errors/eventHandler.ts +++ /dev/null @@ -1,37 +0,0 @@ -import { BaseError } from "./base"; -import { prettyPrint } from "./utils"; - -export class EventHandlerError extends BaseError { - name = "EventHandlerError"; - - constructor({ - eventName, - blockNumber, - params, - stackTrace, - codeFrame, - cause, - }: { - eventName: string; - blockNumber?: bigint; - params?: any; - stackTrace?: string; - codeFrame?: string; - cause?: Error; - }) { - const shortMessage = - `Error while handling \`${eventName}\` event` + - (blockNumber ? ` at block ${blockNumber}` : ""); - - const metaMessages = []; - - if (stackTrace) metaMessages.push(`Trace:\n${stackTrace}`); - if (codeFrame) metaMessages.push(codeFrame); - if (params) metaMessages.push(`Event params:\n${prettyPrint(params)}`); - - super(shortMessage, { - metaMessages, - cause, - }); - } -} diff --git a/packages/core/src/errors/postgres.ts b/packages/core/src/errors/postgres.ts index 3f97364fb..e6af589cc 100644 --- a/packages/core/src/errors/postgres.ts +++ b/packages/core/src/errors/postgres.ts @@ -1,7 +1,7 @@ import { DatabaseError } from "pg"; import { BaseError } from "./base"; -import { prettyPrint } from "./utils"; +import { prettyPrint } from "@/utils/print"; export class PostgresError extends BaseError { name = "PostgresError"; diff --git a/packages/core/src/errors/queue.ts b/packages/core/src/errors/queue.ts index 01c81db64..6cfef182f 100644 --- a/packages/core/src/errors/queue.ts +++ b/packages/core/src/errors/queue.ts @@ -1,5 +1,5 @@ import { BaseError } from "./base"; -import { prettyPrint } from "./utils"; +import { prettyPrint } from "@/utils/print"; export class QueueError extends BaseError { name = "QueueError"; diff --git a/packages/core/src/errors/service.ts b/packages/core/src/errors/service.ts new file mode 100644 index 000000000..ca5180788 --- /dev/null +++ b/packages/core/src/errors/service.ts @@ -0,0 +1,16 @@ +import Emittery from "emittery"; + +import { UserError } from "./user"; + +type UserErrorEvents = { + error: { error: UserError }; +}; + +export class UserErrorService extends Emittery { + hasUserError = false; + + submitUserError({ error }: { error: UserError }) { + this.hasUserError = true; + this.emit("error", { error }); + } +} diff --git a/packages/core/src/errors/sqlite.ts b/packages/core/src/errors/sqlite.ts index 552876f2f..a5ad6de74 100644 --- a/packages/core/src/errors/sqlite.ts +++ b/packages/core/src/errors/sqlite.ts @@ -1,5 +1,5 @@ import { BaseError } from "./base"; -import { prettyPrint } from "./utils"; +import { prettyPrint } from "@/utils/print"; export class SqliteError extends BaseError { name = "SqliteError"; diff --git a/packages/core/src/errors/user.ts b/packages/core/src/errors/user.ts new file mode 100644 index 000000000..3ab9f2baa --- /dev/null +++ b/packages/core/src/errors/user.ts @@ -0,0 +1,15 @@ +export class UserError extends Error { + name = "UserError"; + + meta?: string; + + constructor( + message: string, + options: { stack?: string; meta?: string; cause?: unknown } = {} + ) { + super(message, options.cause ? { cause: options.cause } : undefined); + + this.stack = options.stack; + this.meta = options.meta; + } +} diff --git a/packages/core/src/historical-sync/service.test.ts b/packages/core/src/historical-sync/service.test.ts index d8ef1e54e..93b22c956 100644 --- a/packages/core/src/historical-sync/service.test.ts +++ b/packages/core/src/historical-sync/service.test.ts @@ -9,7 +9,7 @@ import { Network } from "@/config/networks"; import { HistoricalSyncService } from "./service"; -const { metrics } = testResources; +const { metrics, logger } = testResources; const network: Network = { name: "mainnet", chainId: 1, @@ -42,6 +42,7 @@ test("setup() calculates cached and total block counts", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -59,6 +60,7 @@ test("start() runs log tasks and block tasks", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -81,6 +83,7 @@ test("start() adds events to event store", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -131,6 +134,7 @@ test("start() inserts cached ranges", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -160,6 +164,7 @@ test("start() retries errors", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -199,6 +204,7 @@ test("start() handles Alchemy 'Log response size exceeded' error", async (contex const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -237,6 +243,7 @@ test("start() handles Quicknode 'eth_getLogs and eth_newFilter are limited to a const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -266,6 +273,7 @@ test("start() emits sync started and completed events", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, @@ -286,6 +294,7 @@ test("start() emits historicalCheckpoint event", async (context) => { const service = new HistoricalSyncService({ metrics, + logger, eventStore, logFilters, network, diff --git a/packages/core/src/logs/service.ts b/packages/core/src/logs/service.ts index e6f493861..c5531768c 100644 --- a/packages/core/src/logs/service.ts +++ b/packages/core/src/logs/service.ts @@ -1,11 +1,8 @@ import path from "node:path"; -import pino, { type Logger, type LevelWithSilent } from "pino"; import pc from "picocolors"; +import pino, { type LevelWithSilent, type Logger } from "pino"; -type LogFunctionArgs = - | [string] - | [{ msg: string; service?: string } & { [key: string]: any }] - | [string, { service?: string } & { [key: string]: any }]; +type LogOptions = { msg?: string; service?: string } & { [key: string]: any }; export class LoggerService { private logger: Logger; @@ -25,9 +22,15 @@ export class LoggerService { const prettyLog = formatMessage(log); console.log(prettyLog); - // If there is an "error" property, log it. - if (log.error) { - console.log(log.error); + // If there is an "error" property, log the stack trace. + if (log.error?.stack) console.log(log.error.stack); + if (log.error?.meta) console.log(log.error.meta); + + // If the "error" property has an inner "cause" error with a stack trace, + // log that too. + if (log.error?.cause?.stack) { + console.log("Details:"); + console.log(" " + log.error.cause.stack); } }, }, @@ -42,26 +45,32 @@ export class LoggerService { }); } - this.logger = pino({ level: "trace" }, pino.multistream(streams)); + this.logger = pino( + { + level: "trace", + serializers: { error: pino.stdSerializers.errWithCause }, + }, + pino.multistream(streams) + ); } - fatal = (...args: LogFunctionArgs) => { - this.logger.fatal(...(args as [any])); + fatal = (options: LogOptions & { error?: Error }) => { + this.logger.fatal(options); }; - error = (...args: LogFunctionArgs) => { - this.logger.error(...(args as [any])); + error = (options: LogOptions & { error: Error }) => { + this.logger.error(options); }; - warn = (...args: LogFunctionArgs) => { - this.logger.warn(...(args as [any])); + warn = (options: LogOptions & { msg: string }) => { + this.logger.warn(options); }; - info = (...args: LogFunctionArgs) => { - this.logger.info(...(args as [any])); + info = (options: LogOptions & { msg: string }) => { + this.logger.info(options); }; - debug = (...args: LogFunctionArgs) => { - this.logger.debug(...(args as [any])); + debug = (options: LogOptions & { msg: string }) => { + this.logger.debug(options); }; - trace = (...args: LogFunctionArgs) => { - this.logger.trace(...(args as [any])); + trace = (options: LogOptions & { msg: string }) => { + this.logger.trace(options); }; } @@ -77,10 +86,12 @@ const levels = { const formatMessage = (log: { [key: string]: any }) => { let result = ""; - const timestamp = log["time"] as number; - const level = levels[(log["level"] as keyof typeof levels) ?? 30]; - const message = log["msg"] as string | undefined; - const service = log["service"] as string | undefined; + const timestamp = log.time as number; + const level = levels[(log.level as keyof typeof levels) ?? 30]; + const msg = log.msg as string | undefined; + const errorMessage = log.error?.message as string | undefined; + const message = msg ?? errorMessage; + const service = log.service as string | undefined; const date = new Date(timestamp); const hours = String(date.getUTCHours()).padStart(2, "0"); diff --git a/packages/core/src/reload/service.ts b/packages/core/src/reload/service.ts index 8381de646..35ecfd58d 100644 --- a/packages/core/src/reload/service.ts +++ b/packages/core/src/reload/service.ts @@ -4,8 +4,8 @@ import { GraphQLSchema } from "graphql"; import { createHash } from "node:crypto"; import { readFileSync } from "node:fs"; import path from "node:path"; -import pico from "picocolors"; +import { UserError } from "@/errors/user"; import { Resources } from "@/Ponder"; import { buildSchema } from "@/schema/schema"; import { Schema } from "@/schema/types"; @@ -58,7 +58,7 @@ export class ReloadService extends Emittery { msg: `Detected change in ${fileName}`, }); - this.resources.errors.clearHandlerError(); + this.resources.errors.hasUserError = false; if (filePath === this.resources.options.schemaFile) { this.loadSchema(); @@ -83,8 +83,19 @@ export class ReloadService extends Emittery { this.emit("newHandlers", { handlers }); } catch (error_) { const error = error_ as Error; - error.message = "Building event handlers: " + error.message; - this.resources.errors.submitHandlerError({ error }); + + // TODO: Build the UserError object within readHandlers, check instanceof, + // then log/submit as-is if it's already a UserError. + const message = `Error while building handlers: ${error.message}`; + const userError = new UserError(message, { + stack: error.stack, + }); + + this.resources.logger.error({ + service: "build", + error: userError, + }); + this.resources.errors.submitUserError({ error: userError }); } } @@ -99,9 +110,22 @@ export class ReloadService extends Emittery { return { schema, graphqlSchema }; } catch (error_) { const error = error_ as Error; - error.message = "Building schema: " + error.message; - error.stack = ""; - this.resources.errors.submitHandlerError({ error }); + + // TODO: Parse GraphQLError instances better here. + // We can use the `.locations` property to build a pretty codeframe. + + // TODO: Build the UserError object within readHandlers, check instanceof, + // then log/submit as-is if it's already a UserError. + const message = `Error while building schema.graphql: ${error.message}`; + const userError = new UserError(message, { + stack: error.stack, + }); + + this.resources.logger.error({ + service: "build", + error: userError, + }); + this.resources.errors.submitUserError({ error: userError }); } } diff --git a/packages/core/src/user-handlers/service.ts b/packages/core/src/user-handlers/service.ts index 736e025f0..6a2010f53 100644 --- a/packages/core/src/user-handlers/service.ts +++ b/packages/core/src/user-handlers/service.ts @@ -6,7 +6,7 @@ import { encodeEventTopics, getAbiItem, Hex } from "viem"; import type { Contract } from "@/config/contracts"; import type { LogFilter } from "@/config/logFilters"; -import { EventHandlerError } from "@/errors/eventHandler"; +import { UserError } from "@/errors/user"; import type { EventAggregatorService, LogEvent, @@ -18,10 +18,11 @@ import type { Schema } from "@/schema/types"; import type { ReadOnlyContract } from "@/types/contract"; import type { Model } from "@/types/model"; import type { ModelInstance, UserStore } from "@/user-store/store"; +import { prettyPrint } from "@/utils/print"; import { type Queue, type Worker, createQueue } from "@/utils/queue"; import { getInjectedContract } from "./contract"; -import { getStackTraceAndCodeFrame } from "./trace"; +import { getStackTrace } from "./trace"; type EventHandlerEvents = { reset: undefined; @@ -40,10 +41,7 @@ type EventHandlerMetrics = { }; type SetupTask = { kind: "SETUP" }; -type LogEventTask = { - kind: "LOG"; - event: LogEvent; -}; +type LogEventTask = { kind: "LOG"; event: LogEvent }; type EventHandlerTask = SetupTask | LogEventTask; type EventHandlerQueue = Queue; @@ -81,6 +79,7 @@ export class EventHandlerService extends Emittery { private currentEventBlockNumber = 0n; private currentEventTimestamp = 0; + private hasEventHandlerError = false; constructor({ resources, @@ -206,7 +205,7 @@ export class EventHandlerService extends Emittery { }; processEvents = async ({ toTimestamp }: { toTimestamp: number }) => { - if (this.resources.errors.isHandlerError) return; + if (this.hasEventHandlerError) return; if (toTimestamp === 0) return; try { @@ -277,6 +276,8 @@ export class EventHandlerService extends Emittery { this.eventProcessingMutex.cancel(); this.eventProcessingMutex = new Mutex(); + this.hasEventHandlerError = false; + this.metrics = { ...this.metrics, error: false, @@ -369,19 +370,24 @@ export class EventHandlerService extends Emittery { // Remove all remaining tasks from the queue. queue.clear(); + this.hasEventHandlerError = true; + this.metrics.error = true; + const error = error_ as Error; - const { stackTrace, codeFrame } = getStackTraceAndCodeFrame( - error, - this.resources.options - ); - this.resources.errors.submitHandlerError({ - error: new EventHandlerError({ - eventName: "setup", - stackTrace: stackTrace, - codeFrame: codeFrame, - cause: error, - }), + const trace = getStackTrace(error, this.resources.options); + + const message = `Error while handling "setup" event: ${error.message}`; + + const userError = new UserError(message, { + stack: trace, + cause: error, }); + + this.resources.logger.error({ + service: "handlers", + error: userError, + }); + this.resources.errors.submitUserError({ error: userError }); } this.emit("taskCompleted"); @@ -414,23 +420,29 @@ export class EventHandlerService extends Emittery { // Remove all remaining tasks from the queue. queue.clear(); + this.hasEventHandlerError = true; this.metrics.error = true; const error = error_ as Error; - const { stackTrace, codeFrame } = getStackTraceAndCodeFrame( - error, - this.resources.options - ); - this.resources.errors.submitHandlerError({ - error: new EventHandlerError({ - stackTrace: stackTrace, - codeFrame: codeFrame, - cause: error, - eventName: event.eventName, - blockNumber: event.block.number, - params: event.params, - }), + const trace = getStackTrace(error, this.resources.options); + + const message = `Error while handling "${event.logFilterName}:${ + event.eventName + }" event at block ${Number(event.block.number)}: ${error.message}`; + + const metaMessage = `Event params:\n${prettyPrint(event.params)}`; + + const userError = new UserError(message, { + stack: trace, + meta: metaMessage, + cause: error, + }); + + this.resources.logger.error({ + service: "handlers", + error: userError, }); + this.resources.errors.submitUserError({ error: userError }); } this.metrics.latestHandledEventTimestamp = this.currentEventTimestamp; diff --git a/packages/core/src/user-handlers/trace.ts b/packages/core/src/user-handlers/trace.ts index 210c7fae6..d12394e68 100644 --- a/packages/core/src/user-handlers/trace.ts +++ b/packages/core/src/user-handlers/trace.ts @@ -13,11 +13,8 @@ import { parse as parseStackTrace, StackFrame } from "stacktrace-parser"; import { PonderOptions } from "@/config/options"; -export const getStackTraceAndCodeFrame = ( - error: Error, - options: PonderOptions -) => { - if (!error.stack) return { stackTrace: undefined, codeFrame: undefined }; +export const getStackTrace = (error: Error, options: PonderOptions) => { + if (!error.stack) return undefined; const buildDir = path.join(options.ponderDir, "out"); @@ -75,19 +72,27 @@ export const getStackTraceAndCodeFrame = ( .filter((f): f is StackFrame => !!f); if (sourceMappedStackTrace.length === 0 || !codeFrame) { - return { stackTrace: undefined, codeFrame: undefined }; + return undefined; } - const formattedStackTrace = sourceMappedStackTrace - .map( - (frame) => - ` at ${frame.methodName} (${frame.file}:${frame.lineNumber}${ - frame.column !== null ? `:${frame.column}` : "" - })` - ) - .join("\n"); + const formattedStackTrace = [ + ...sourceMappedStackTrace.map((frame) => { + let result = " at"; - return { stackTrace: formattedStackTrace, codeFrame }; + result += ` ${ + frame.methodName === "" ? "(anonymous)" : frame.methodName + }`; + + result += ` (${frame.file}:${frame.lineNumber}${ + frame.column !== null ? `:${frame.column}` : "" + })`; + + return result; + }), + codeFrame, + ].join("\n"); + + return formattedStackTrace; }; function getSourceMappedStackFrame( diff --git a/packages/core/src/errors/utils.ts b/packages/core/src/utils/print.ts similarity index 98% rename from packages/core/src/errors/utils.ts rename to packages/core/src/utils/print.ts index 59c65bbec..0012737d4 100644 --- a/packages/core/src/errors/utils.ts +++ b/packages/core/src/utils/print.ts @@ -1,7 +1,7 @@ // Adapted from viem. // https://github.com/wagmi-dev/viem/blob/021ce8e5a3fb02db6139564345a91fc77cba08a6/src/errors/transaction.ts#L6-L19 export function prettyPrint( - args: Record + args: Record ) { const entries = Object.entries(args) .map(([key, value]) => { From 396e83bbd144f4b0866982f1dce5a237d246a994 Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Tue, 27 Jun 2023 13:42:56 -0400 Subject: [PATCH 10/12] fix sqlite error parameters --- packages/core/src/config/database.ts | 2 +- packages/core/src/errors/postgres.ts | 8 +++----- packages/core/src/errors/queue.ts | 3 ++- packages/core/src/errors/sqlite.ts | 3 ++- packages/core/src/logs/service.ts | 11 +++++------ 5 files changed, 13 insertions(+), 14 deletions(-) diff --git a/packages/core/src/config/database.ts b/packages/core/src/config/database.ts index e71b19898..837e04afd 100644 --- a/packages/core/src/config/database.ts +++ b/packages/core/src/config/database.ts @@ -67,7 +67,7 @@ export const patchSqliteDatabase = ({ db }: { db: any }) => { } catch (error) { throw new SqliteError({ statement: source, - parameters: args, + parameters: args[0], sqliteError: error as Error, }); } diff --git a/packages/core/src/errors/postgres.ts b/packages/core/src/errors/postgres.ts index e6af589cc..3e55a01c3 100644 --- a/packages/core/src/errors/postgres.ts +++ b/packages/core/src/errors/postgres.ts @@ -1,8 +1,9 @@ import { DatabaseError } from "pg"; -import { BaseError } from "./base"; import { prettyPrint } from "@/utils/print"; +import { BaseError } from "./base"; + export class PostgresError extends BaseError { name = "PostgresError"; @@ -17,10 +18,7 @@ export class PostgresError extends BaseError { }) { const params = parameters.reduce>( (acc, parameter, idx) => { - acc[idx + 1] = - typeof parameter === "string" && parameter.length > 80 - ? parameter.slice(0, 80).concat("...") - : parameter; + acc[idx + 1] = parameter; return acc; }, {} diff --git a/packages/core/src/errors/queue.ts b/packages/core/src/errors/queue.ts index 6cfef182f..142c06d4b 100644 --- a/packages/core/src/errors/queue.ts +++ b/packages/core/src/errors/queue.ts @@ -1,6 +1,7 @@ -import { BaseError } from "./base"; import { prettyPrint } from "@/utils/print"; +import { BaseError } from "./base"; + export class QueueError extends BaseError { name = "QueueError"; diff --git a/packages/core/src/errors/sqlite.ts b/packages/core/src/errors/sqlite.ts index a5ad6de74..65dc094a9 100644 --- a/packages/core/src/errors/sqlite.ts +++ b/packages/core/src/errors/sqlite.ts @@ -1,6 +1,7 @@ -import { BaseError } from "./base"; import { prettyPrint } from "@/utils/print"; +import { BaseError } from "./base"; + export class SqliteError extends BaseError { name = "SqliteError"; diff --git a/packages/core/src/logs/service.ts b/packages/core/src/logs/service.ts index c5531768c..d08b2aa00 100644 --- a/packages/core/src/logs/service.ts +++ b/packages/core/src/logs/service.ts @@ -26,12 +26,11 @@ export class LoggerService { if (log.error?.stack) console.log(log.error.stack); if (log.error?.meta) console.log(log.error.meta); - // If the "error" property has an inner "cause" error with a stack trace, - // log that too. - if (log.error?.cause?.stack) { - console.log("Details:"); - console.log(" " + log.error.cause.stack); - } + // TODO: Consider also logging any inner `cause` errors. + // if (log.error?.cause?.stack) { + // console.log("Details:"); + // console.log(" " + log.error.cause.stack); + // } }, }, }); From 2a1734dbffcb7b8b1c1a988af42c8d52003d4f60 Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Tue, 27 Jun 2023 13:59:29 -0400 Subject: [PATCH 11/12] fix lint errors --- packages/core/src/_test/utils.ts | 2 +- packages/core/src/config/networks.ts | 1 + packages/core/src/historical-sync/service.ts | 4 ++-- packages/core/src/realtime-sync/service.ts | 2 +- 4 files changed, 5 insertions(+), 4 deletions(-) diff --git a/packages/core/src/_test/utils.ts b/packages/core/src/_test/utils.ts index d2a2a649c..7c12bcd38 100644 --- a/packages/core/src/_test/utils.ts +++ b/packages/core/src/_test/utils.ts @@ -9,9 +9,9 @@ import { mainnet } from "viem/chains"; import { buildOptions } from "@/config/options"; import { UserErrorService } from "@/errors/service"; +import { LoggerService } from "@/logs/service"; import { MetricsService } from "@/metrics/service"; import { Resources } from "@/Ponder"; -import { LoggerService } from "@/logs/service"; // Anvil test setup adapted from @viem/anvil `example-vitest` repository. // https://github.com/wagmi-dev/anvil.js/tree/main/examples/example-vitest diff --git a/packages/core/src/config/networks.ts b/packages/core/src/config/networks.ts index b159d3050..e32966b86 100644 --- a/packages/core/src/config/networks.ts +++ b/packages/core/src/config/networks.ts @@ -130,6 +130,7 @@ function getFinalityBlockCount(network: { chainId: number }) { // Zora. case 7777777: finalityBlockCount = 5; + break; default: finalityBlockCount = 5; } diff --git a/packages/core/src/historical-sync/service.ts b/packages/core/src/historical-sync/service.ts index 8eb2cf15b..6bd67528c 100644 --- a/packages/core/src/historical-sync/service.ts +++ b/packages/core/src/historical-sync/service.ts @@ -11,13 +11,13 @@ import type { LogFilter } from "@/config/logFilters"; import type { Network } from "@/config/networks"; import { QueueError } from "@/errors/queue"; import type { EventStore } from "@/event-store/store"; +import { LoggerService } from "@/logs/service"; import { MetricsService } from "@/metrics/service"; +import { formatEta, formatPercentage } from "@/utils/format"; import { type Queue, createQueue } from "@/utils/queue"; import { startClock } from "@/utils/timer"; import { findMissingIntervals } from "./intervals"; -import { LoggerService } from "@/logs/service"; -import { formatEta, formatPercentage } from "@/utils/format"; type HistoricalSyncEvents = { /** diff --git a/packages/core/src/realtime-sync/service.ts b/packages/core/src/realtime-sync/service.ts index 2aa885a96..53f30a099 100644 --- a/packages/core/src/realtime-sync/service.ts +++ b/packages/core/src/realtime-sync/service.ts @@ -6,6 +6,7 @@ import type { LogFilter } from "@/config/logFilters"; import type { Network } from "@/config/networks"; import { QueueError } from "@/errors/queue"; import type { EventStore } from "@/event-store/store"; +import { LoggerService } from "@/logs/service"; import { MetricsService } from "@/metrics/service"; import { poll } from "@/utils/poll"; import { type Queue, createQueue } from "@/utils/queue"; @@ -19,7 +20,6 @@ import { type LightBlock, rpcBlockToLightBlock, } from "./format"; -import { LoggerService } from "@/logs/service"; type RealtimeSyncEvents = { realtimeCheckpoint: { timestamp: number }; From bfd41882d96939731d0fe8ec0f973e5c1d021f37 Mon Sep 17 00:00:00 2001 From: typedarray <90073088+0xOlias@users.noreply.github.com> Date: Tue, 27 Jun 2023 14:03:27 -0400 Subject: [PATCH 12/12] chore: changeset --- .changeset/forty-tigers-fly.md | 5 +++++ .changeset/happy-wasps-destroy.md | 5 +++++ .changeset/shy-tables-mix.md | 5 +++++ 3 files changed, 15 insertions(+) create mode 100644 .changeset/forty-tigers-fly.md create mode 100644 .changeset/happy-wasps-destroy.md create mode 100644 .changeset/shy-tables-mix.md diff --git a/.changeset/forty-tigers-fly.md b/.changeset/forty-tigers-fly.md new file mode 100644 index 000000000..f6f912f40 --- /dev/null +++ b/.changeset/forty-tigers-fly.md @@ -0,0 +1,5 @@ +--- +"@ponder/core": patch +--- + +Fixed a bug where the default finality checkpoint of several chains (including Arbitrum) was set to zero. The target finality interval for reorg-safe chains like Arbitrum and Optimism is now 10 seconds (e.g. 40 blocks on Arbitrum). diff --git a/.changeset/happy-wasps-destroy.md b/.changeset/happy-wasps-destroy.md new file mode 100644 index 000000000..fa075f147 --- /dev/null +++ b/.changeset/happy-wasps-destroy.md @@ -0,0 +1,5 @@ +--- +"@ponder/core": patch +--- + +Fixed a bug where the realtime sync service would process blocks out of order, leading to less efficient RPC request patterns. diff --git a/.changeset/shy-tables-mix.md b/.changeset/shy-tables-mix.md new file mode 100644 index 000000000..7ebf7297f --- /dev/null +++ b/.changeset/shy-tables-mix.md @@ -0,0 +1,5 @@ +--- +"@ponder/core": patch +--- + +Updated Ponder's logging behavior. Stdout log lines will not include timestamps, log level, service name, and a message. Logs are also written to files located at `/.ponder/logs/{timestamp}.log` in JSON format. There are now more log levels: `"silent"`, `"fatal"`, `"error"`, `"warn"`, `"info"`, `"debug"`, and `"trace"`. These can be configured using the `PONDER_LOG_LEVEL` environment variable.