Skip to content

Commit 4a9be27

Browse files
committed
Add logger thorughout
1 parent 6284fed commit 4a9be27

12 files changed

Lines changed: 251 additions & 24 deletions

File tree

e2e/testGetSlot.e2e.ts

Lines changed: 213 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,213 @@
1+
#!/usr/bin/env ts-node
2+
/* eslint-disable @typescript-eslint/no-explicit-any */
3+
4+
import { program } from "commander";
5+
import winston from "winston";
6+
import { CachedSolanaRpcFactory } from "../src/providers/solana/cachedRpcFactory";
7+
import { ClusterUrl, type Commitment } from "@solana/kit";
8+
import { getSlot } from "../src/arch/svm/SpokeUtils";
9+
10+
/**
11+
* USAGE EXAMPLES:
12+
*
13+
* Basic usage (default settings):
14+
* npx ts-node testGetSlot.e2e.ts
15+
*
16+
* Test with specific endpoint:
17+
* npx ts-node testGetSlot.e2e.ts -e https://api.devnet.solana.com
18+
*
19+
* Test with more iterations:
20+
* npx ts-node testGetSlot.e2e.ts -n 20
21+
*
22+
* Test with different commitment level:
23+
* npx ts-node testGetSlot.e2e.ts -c finalized
24+
*/
25+
26+
// Configure winston logger
27+
const logger = winston.createLogger({
28+
level: "debug",
29+
format: winston.format.combine(
30+
winston.format.timestamp(),
31+
winston.format.colorize(),
32+
winston.format.printf(({ timestamp, level, message, ...meta }) => {
33+
const metaStr = Object.keys(meta).length ? JSON.stringify(meta, null, 2) : "";
34+
return `${timestamp} [${level}]: ${message} ${metaStr}`;
35+
})
36+
),
37+
transports: [new winston.transports.Console()],
38+
});
39+
40+
interface TestOptions {
41+
endpoint: string;
42+
retries: number;
43+
retryDelay: number;
44+
chainId: number;
45+
iterations: number;
46+
commitment: Commitment;
47+
}
48+
49+
async function testGetSlot(
50+
rpcClient: any,
51+
commitment: Commitment,
52+
iteration: number
53+
): Promise<{
54+
iteration: number;
55+
slot: string;
56+
success: boolean;
57+
commitment: Commitment;
58+
time: number;
59+
error?: string;
60+
}> {
61+
console.log(`--- Iteration ${iteration} (commitment: ${commitment}) ---`);
62+
const startTime = Date.now();
63+
64+
try {
65+
const slot = await getSlot(rpcClient, commitment, logger);
66+
const elapsedTime = Date.now() - startTime;
67+
68+
console.log(`✅ Slot ${slot.toString()} (commitment: ${commitment}) (${elapsedTime}ms)`);
69+
return {
70+
iteration,
71+
slot: slot.toString(),
72+
success: true,
73+
commitment,
74+
time: elapsedTime,
75+
};
76+
} catch (error: unknown) {
77+
const elapsedTime = Date.now() - startTime;
78+
const errorMsg = error instanceof Error ? error.message : String(error);
79+
console.log(`❌ Failed: ${errorMsg} (${elapsedTime}ms)`);
80+
return {
81+
iteration,
82+
slot: "unknown",
83+
success: false,
84+
commitment,
85+
error: errorMsg,
86+
time: elapsedTime,
87+
};
88+
}
89+
}
90+
91+
async function runTest(options: TestOptions) {
92+
console.log("🚀 Starting getSlot E2E Test");
93+
console.log("Configuration:", {
94+
endpoint: options.endpoint,
95+
retries: options.retries,
96+
retryDelay: options.retryDelay,
97+
iterations: options.iterations,
98+
commitment: options.commitment,
99+
});
100+
101+
// Create the RPC factory
102+
const rpcFactory = new CachedSolanaRpcFactory(
103+
"test-get-slot",
104+
undefined, // redisClient
105+
options.retries,
106+
options.retryDelay,
107+
10, // maxConcurrency
108+
0, // pctRpcCallsLogged
109+
logger,
110+
options.endpoint as ClusterUrl,
111+
options.chainId
112+
);
113+
114+
const rpcClient = rpcFactory.createRpcClient();
115+
116+
console.log(`\n📡 Running ${options.iterations} sequential tests...\n`);
117+
118+
const testStartTime = Date.now();
119+
const results: Array<{
120+
iteration: number;
121+
slot: string;
122+
success: boolean;
123+
commitment: Commitment;
124+
time: number;
125+
error?: string;
126+
}> = [];
127+
128+
for (let i = 0; i < options.iterations; i++) {
129+
const result = await testGetSlot(rpcClient, options.commitment, i + 1);
130+
results.push(result);
131+
}
132+
133+
const totalTime = Date.now() - testStartTime;
134+
135+
// Print summary
136+
console.log("\n📊 Test Summary:");
137+
console.log("================");
138+
const successful = results.filter((r) => r.success).length;
139+
const failed = results.filter((r) => !r.success).length;
140+
const retried = results.filter((r) => r.time > 1000); // We know an attempt retried if it took > 1 second
141+
const retryCount = retried.length;
142+
const retriedSuccessfully = retried.filter((r) => r.success).length;
143+
const avgTime = results.reduce((sum, r) => sum + r.time, 0) / results.length;
144+
const longestTime = results.reduce((max, r) => Math.max(max, r.time), 0);
145+
const retriedAvgTime = retried.reduce((sum, r) => sum + r.time, 0) / retried.length;
146+
const retriedLongestTime = retried.reduce((max, r) => Math.max(max, r.time), 0);
147+
148+
console.log(`Successful: ${successful} / ${options.iterations}`);
149+
console.log(`Failed: ${failed} / ${options.iterations}`);
150+
console.log(`Average time per call: ${avgTime.toFixed(0)}ms`);
151+
console.log(`Longest time per call: ${longestTime.toFixed(0)}ms`);
152+
console.log(`Retried: ${retryCount} / ${options.iterations}`);
153+
console.log(`Retried successfully: ${retriedSuccessfully} / ${retryCount}`);
154+
console.log(`Retried unsuccessfully: ${retryCount - retriedSuccessfully} / ${retryCount}`);
155+
console.log(`Retried average time: ${retriedAvgTime.toFixed(0)}ms`);
156+
console.log(`Retried longest time: ${retriedLongestTime.toFixed(0)}ms`);
157+
console.log(`Total test time: ${totalTime}ms`);
158+
159+
if (failed > 0) {
160+
console.log("\n❌ Failed tests:");
161+
results
162+
.filter((r) => !r.success)
163+
.forEach((r) => {
164+
console.log(` Iteration ${r.iteration}: ${r.error}`);
165+
});
166+
167+
// Show error patterns
168+
const errorPatterns = new Map<string, number>();
169+
results
170+
.filter((r) => !r.success && r.error)
171+
.forEach((r) => {
172+
const errorType = r.error!.split(":")[0].trim();
173+
errorPatterns.set(errorType, (errorPatterns.get(errorType) || 0) + 1);
174+
});
175+
176+
console.log("\n🔍 Error patterns:");
177+
errorPatterns.forEach((count, pattern) => {
178+
console.log(` ${pattern}: ${count} occurrences`);
179+
});
180+
}
181+
}
182+
183+
// CLI setup
184+
program.name("test-get-slot").description("Test getSlot function with configurable commitment parameter");
185+
186+
program
187+
.option("-e, --endpoint <url>", "Solana RPC endpoint URL", "https://api.mainnet-beta.solana.com")
188+
.option("-r, --retries <number>", "Number of retries on failure", "2")
189+
.option("-d, --retry-delay <seconds>", "Delay between retries in seconds", "1")
190+
.option("-i, --chain-id <number>", "Chain ID for Solana", "101")
191+
.option("-n, --iterations <number>", "Number of test iterations", "10")
192+
.option("-c, --commitment <commitment>", "Commitment level (processed, confirmed, finalized)", "confirmed")
193+
.action(async (options) => {
194+
// Validate commitment parameter
195+
const validCommitments: Commitment[] = ["processed", "confirmed", "finalized"];
196+
if (!validCommitments.includes(options.commitment as Commitment)) {
197+
console.error(`Invalid commitment level: ${options.commitment}. Valid options: ${validCommitments.join(", ")}`);
198+
process.exit(1);
199+
}
200+
201+
const testOptions: TestOptions = {
202+
endpoint: options.endpoint,
203+
retries: parseInt(options.retries),
204+
retryDelay: parseFloat(options.retryDelay),
205+
chainId: parseInt(options.chainId),
206+
iterations: parseInt(options.iterations),
207+
commitment: options.commitment as Commitment,
208+
};
209+
210+
await runTest(testOptions);
211+
});
212+
213+
program.parse();

src/arch/svm/SpokeUtils.ts

Lines changed: 14 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,7 @@ import {
3636
} from "@solana/kit";
3737
import assert from "assert";
3838
import { arrayify, hexZeroPad, hexlify } from "ethers/lib/utils";
39-
import winston, { Logger } from "winston";
39+
import winston from "winston";
4040
import { CHAIN_IDs, TOKEN_SYMBOLS_MAP } from "../../constants";
4141
import { DepositWithBlock, FillStatus, FillWithBlock, RelayData, RelayExecutionEventInfo } from "../../interfaces";
4242
import {
@@ -257,6 +257,7 @@ export function getDepositIdAtBlock(_contract: unknown, _blockTag: number): Prom
257257
export async function findDeposit(
258258
eventClient: SvmCpiEventsClient,
259259
depositId: BigNumber,
260+
logger: winston.Logger,
260261
slot?: bigint,
261262
secondsLookback = 2 * 24 * 60 * 60 // 2 days
262263
): Promise<DepositWithBlock | undefined> {
@@ -266,7 +267,7 @@ export async function findDeposit(
266267
}
267268

268269
const provider = eventClient.getRpc();
269-
const { slot: currentSlot } = await getNearestSlotTime(provider);
270+
const { slot: currentSlot } = await getNearestSlotTime(provider, logger);
270271

271272
// If no slot is provided, use the current slot
272273
// If a slot is provided, ensure it's not in the future
@@ -324,6 +325,7 @@ export async function relayFillStatus(
324325
relayData: RelayData,
325326
destinationChainId: number,
326327
svmEventsClient: SvmCpiEventsClient,
328+
logger: winston.Logger,
327329
atHeight?: number
328330
): Promise<FillStatus> {
329331
assert(chainIsSvm(destinationChainId), "Destination chain must be an SVM chain");
@@ -337,7 +339,7 @@ export async function relayFillStatus(
337339
const commitment = "confirmed";
338340
const [fillStatusAccount, { slot: currentSlot, timestamp }] = await Promise.all([
339341
fetchEncodedAccount(provider, fillStatusPda, { commitment }),
340-
getNearestSlotTime(provider, { commitment }),
342+
getNearestSlotTime(provider, logger, { commitment }),
341343
]);
342344
toSlot = currentSlot;
343345

@@ -374,8 +376,8 @@ export async function fillStatusArray(
374376
relayData: RelayData[],
375377
destinationChainId: number,
376378
svmEventsClient: SvmCpiEventsClient,
377-
atHeight?: number,
378-
logger?: Logger
379+
logger: winston.Logger,
380+
atHeight?: number
379381
): Promise<(FillStatus | undefined)[]> {
380382
assert(chainIsSvm(destinationChainId), "Destination chain must be an SVM chain");
381383
const provider = svmEventsClient.getRpc();
@@ -403,7 +405,7 @@ export async function fillStatusArray(
403405
// Otherwise, initialize all statuses as undefined
404406
const fillStatuses: (FillStatus | undefined)[] =
405407
atHeight === undefined
406-
? await fetchBatchFillStatusFromPdaAccounts(provider, fillStatusPdas, relayData)
408+
? await fetchBatchFillStatusFromPdaAccounts(provider, fillStatusPdas, relayData, logger)
407409
: new Array(relayData.length).fill(undefined);
408410

409411
// Collect indices of deposits that still need their status resolved
@@ -419,7 +421,7 @@ export async function fillStatusArray(
419421
const missingResults: { index: number; fillStatus: FillStatus }[] = [];
420422

421423
// Determine the toSlot to use for event reconstruction
422-
const toSlot = atHeight ? BigInt(atHeight) : (await getNearestSlotTime(provider)).slot;
424+
const toSlot = atHeight ? BigInt(atHeight) : (await getNearestSlotTime(provider, logger)).slot;
423425

424426
// @note: This path is mostly used for deposits past their fill deadline.
425427
// If it becomes a bottleneck, consider returning an "Unknown" status that can be handled downstream.
@@ -457,11 +459,12 @@ export async function findFillEvent(
457459
relayData: RelayData,
458460
destinationChainId: number,
459461
svmEventsClient: SvmCpiEventsClient,
462+
logger: winston.Logger,
460463
fromSlot: number,
461464
toSlot?: number
462465
): Promise<FillWithBlock | undefined> {
463466
assert(chainIsSvm(destinationChainId), "Destination chain must be an SVM chain");
464-
toSlot ??= Number((await getNearestSlotTime(svmEventsClient.getRpc())).slot);
467+
toSlot ??= Number((await getNearestSlotTime(svmEventsClient.getRpc(), logger)).slot);
465468

466469
// Get fillStatus PDA using relayData
467470
const programId = svmEventsClient.getProgramAddress();
@@ -1021,14 +1024,15 @@ async function resolveFillStatusFromPdaEvents(
10211024
async function fetchBatchFillStatusFromPdaAccounts(
10221025
provider: SVMProvider,
10231026
fillStatusPdas: Address[],
1024-
relayDataArray: RelayData[]
1027+
relayDataArray: RelayData[],
1028+
logger: winston.Logger
10251029
): Promise<(FillStatus | undefined)[]> {
10261030
const chunkSize = 100; // SVM method getMultipleAccounts allows a max of 100 addresses per request
10271031
const commitment = "confirmed";
10281032

10291033
const [pdaAccounts, { timestamp }] = await Promise.all([
10301034
Promise.all(chunk(fillStatusPdas, chunkSize).map((chunk) => fetchEncodedAccounts(provider, chunk, { commitment }))),
1031-
getNearestSlotTime(provider, { commitment }),
1035+
getNearestSlotTime(provider, logger, { commitment }),
10321036
]);
10331037

10341038
const fillStatuses = pdaAccounts.flat().map((account, index) => {

src/arch/svm/utils.ts

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ export async function getNearestSlotTime(
7272
opts: { slot: bigint } | { commitment: Commitment } = { commitment: "confirmed" }
7373
): Promise<{ slot: bigint; timestamp: number }> {
7474
let timestamp: number | undefined;
75-
let slot = "slot" in opts ? opts.slot : await getSlot(provider, opts.commitment, logger).send();
75+
let slot = "slot" in opts ? opts.slot : await getSlot(provider, opts.commitment, logger);
7676

7777
do {
7878
timestamp = await getTimestampForSlot(provider, slot, logger);
@@ -89,11 +89,12 @@ export async function getNearestSlotTime(
8989
*/
9090
export async function getLatestFinalizedSlotWithBlock(
9191
provider: SVMProvider,
92+
logger: winston.Logger,
9293
maxSlot: bigint,
9394
maxLookback = 1000
9495
): Promise<number> {
9596
const opts = { maxSupportedTransactionVersion: 0, transactionDetails: "none", rewards: false } as const;
96-
const { slot: finalizedSlot } = await getNearestSlotTime(provider, { commitment: "finalized" });
97+
const { slot: finalizedSlot } = await getNearestSlotTime(provider, logger, { commitment: "finalized" });
9798
const endSlot = biMin(maxSlot, finalizedSlot);
9899

99100
let slot = endSlot;

src/clients/AcrossConfigStoreClient/AcrossConfigStoreClient.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -102,7 +102,7 @@ export class AcrossConfigStoreClient extends BaseAbstractClient {
102102
eventSearchConfig: MakeOptional<EventSearchConfig, "to"> = { from: 0, maxLookBack: 0 },
103103
readonly configStoreVersion: number
104104
) {
105-
super(eventSearchConfig);
105+
super(logger, eventSearchConfig);
106106
this.firstHeightToSearch = eventSearchConfig.from;
107107
this.latestHeightSearched = 0;
108108
}

src/clients/BaseAbstractClient.ts

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ import { providers } from "ethers";
22
import { CachingMechanismInterface } from "../interfaces";
33
import { EventSearchConfig, isDefined, MakeOptional } from "../utils";
44
import { getNearestSlotTime, SVMProvider } from "../arch/svm";
5+
import winston from "winston";
56

67
export enum UpdateFailureReason {
78
NotReady,
@@ -27,6 +28,7 @@ export abstract class BaseAbstractClient {
2728
* @param cachingMechanism The caching mechanism to use for this client. If not provided, the client will not rely on an external cache.
2829
*/
2930
constructor(
31+
readonly logger: winston.Logger,
3032
readonly eventSearchConfig: MakeOptional<EventSearchConfig, "to"> = { from: 0, maxLookBack: 0 },
3133
protected cachingMechanism?: CachingMechanismInterface
3234
) {
@@ -72,7 +74,7 @@ export abstract class BaseAbstractClient {
7274
if (provider instanceof providers.Provider) {
7375
to = await provider.getBlockNumber();
7476
} else {
75-
const { slot } = await getNearestSlotTime(provider);
77+
const { slot } = await getNearestSlotTime(provider, this.logger);
7678
to = Number(slot);
7779
}
7880
if (to < from) {

src/clients/BundleDataClient/BundleDataClient.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1651,6 +1651,7 @@ export class BundleDataClient {
16511651
deposit,
16521652
spokePoolClient.chainId,
16531653
spokePoolClient.svmEventsClient,
1654+
spokePoolClient.logger,
16541655
spokePoolClient.deploymentBlock,
16551656
spokePoolClient.latestHeightSearched
16561657
);

src/clients/BundleDataClient/utils/PoolRebalanceUtils.ts

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -41,7 +41,11 @@ export async function getWidestPossibleExpectedBlockRange(
4141
assert(isSVMSpokePoolClient(spokePoolClient));
4242

4343
const maxSlot = resolveEndBlock(chainId, idx); // Respect any configured buffer for Solana.
44-
return getLatestFinalizedSlotWithBlock(spokePoolClient.svmEventsClient.getRpc(), BigInt(maxSlot));
44+
return getLatestFinalizedSlotWithBlock(
45+
spokePoolClient.svmEventsClient.getRpc(),
46+
spokePoolClient.logger,
47+
BigInt(maxSlot)
48+
);
4549
};
4650

4751
const latestPossibleBundleEndBlockNumbers = await Promise.all(

0 commit comments

Comments
 (0)