Skip to content

Commit 07cd38e

Browse files
coodoscoodos
committed
chore: debug logs
1 parent e1dce49 commit 07cd38e

3 files changed

Lines changed: 127 additions & 28 deletions

File tree

‎infrastructure/evault-core/src/core/db/db.service.ts‎

Lines changed: 40 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import neo4j, { type Driver } from "neo4j-driver";
22
import { W3IDBuilder } from "w3id";
3+
import { timed } from "../utils/timing";
34
import { deserializeValue, serializeValue } from "./schema";
45
import type {
56
AppendEnvelopeOperationLogParams,
@@ -41,12 +42,19 @@ export class DbService {
4142
* @returns The result of the query execution
4243
*/
4344
private async runQueryInternal(query: string, params: Record<string, any>) {
44-
const session = this.driver.session();
45-
try {
46-
return await session.run(query, params);
47-
} finally {
48-
await session.close();
49-
}
45+
const firstLine = query.trim().split("\n")[0].slice(0, 80);
46+
return timed(`db.query "${firstLine}"`, async () => {
47+
const session = await timed("db.session.open", async () =>
48+
this.driver.session(),
49+
);
50+
try {
51+
return await timed("db.session.run", () =>
52+
session.run(query, params),
53+
);
54+
} finally {
55+
await timed("db.session.close", () => session.close());
56+
}
57+
});
5058
}
5159

5260
/**
@@ -74,11 +82,14 @@ export class DbService {
7482
acl: string[],
7583
eName: string,
7684
): Promise<StoreMetaEnvelopeResult<T>> {
85+
return timed("db.storeMetaEnvelope", async () => {
7786
if (!eName) {
7887
throw new Error("eName is required for storing meta-envelopes");
7988
}
8089

81-
const w3id = await new W3IDBuilder().build();
90+
const w3id = await timed("db.storeMetaEnvelope.buildMetaId", () =>
91+
new W3IDBuilder().build(),
92+
);
8293

8394
const cypher: string[] = [
8495
`CREATE (m:MetaEnvelope { id: $metaId, ontology: $ontology, acl: $acl, eName: $eName })`,
@@ -128,7 +139,9 @@ export class DbService {
128139
counter++;
129140
}
130141

131-
await this.runQueryInternal(cypher.join("\n"), envelopeParams);
142+
await timed("db.storeMetaEnvelope.runQuery", () =>
143+
this.runQueryInternal(cypher.join("\n"), envelopeParams),
144+
);
132145

133146
return {
134147
metaEnvelope: {
@@ -138,6 +151,7 @@ export class DbService {
138151
},
139152
envelopes: createdEnvelopes,
140153
};
154+
});
141155
}
142156

143157
/**
@@ -528,24 +542,31 @@ export class DbService {
528542
acl: string[],
529543
eName: string,
530544
): Promise<StoreMetaEnvelopeResult<T>> {
545+
return timed("db.updateMetaEnvelopeById", async () => {
531546
if (!eName) {
532547
throw new Error("eName is required for updating meta-envelopes");
533548
}
534549

535550
try {
536-
let existing = await this.findMetaEnvelopeById<T>(id, eName);
551+
let existing = await timed(
552+
"db.updateMetaEnvelopeById.findExisting",
553+
() => this.findMetaEnvelopeById<T>(id, eName),
554+
);
537555
if (!existing) {
538-
const metaW3id = await new W3IDBuilder().build();
539-
await this.runQueryInternal(
540-
`
556+
await timed(
557+
"db.updateMetaEnvelopeById.createMissing",
558+
() =>
559+
this.runQueryInternal(
560+
`
541561
CREATE (m:MetaEnvelope {
542562
id: $id,
543563
ontology: $ontology,
544564
acl: $acl,
545565
eName: $eName
546566
})
547567
`,
548-
{ id, ontology: meta.ontology, acl, eName },
568+
{ id, ontology: meta.ontology, acl, eName },
569+
),
549570
);
550571
existing = {
551572
id,
@@ -557,12 +578,14 @@ export class DbService {
557578
}
558579

559580
// Update the meta-envelope properties (ensure eName matches)
560-
await this.runQueryInternal(
561-
`
581+
await timed("db.updateMetaEnvelopeById.updateMetaProps", () =>
582+
this.runQueryInternal(
583+
`
562584
MATCH (m:MetaEnvelope { id: $id, eName: $eName })
563585
SET m.ontology = $ontology, m.acl = $acl
564586
`,
565-
{ id, ontology: meta.ontology, acl, eName },
587+
{ id, ontology: meta.ontology, acl, eName },
588+
),
566589
);
567590

568591
// Deduplicate envelopes — if multiple Envelope nodes share the
@@ -705,6 +728,7 @@ export class DbService {
705728
console.error("Error in updateMetaEnvelopeById:", error);
706729
throw error;
707730
}
731+
});
708732
}
709733

710734
/**

‎infrastructure/evault-core/src/core/protocol/vault-access-guard.ts‎

Lines changed: 50 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import type { YogaInitialContext } from "graphql-yoga";
33
import * as jose from "jose";
44
import type { DbService } from "../db/db.service";
55
import type { MetaEnvelope } from "../db/types";
6+
import { newTraceId, timed } from "../utils/timing";
67

78
export type VaultContext = YogaInitialContext & {
89
currentUser: string | null;
@@ -51,17 +52,26 @@ export class VaultAccessGuard {
5152
const now = Date.now();
5253
let cached = jwksCache.get(jwksUrl);
5354
if (!cached || cached.expiresAt <= now) {
54-
const jwksResponse = await axios.get(jwksUrl, {
55-
timeout: JWKS_FETCH_TIMEOUT_MS,
56-
});
55+
const jwksResponse = await timed(
56+
"guard.validateToken.fetchJWKS",
57+
() =>
58+
axios.get(jwksUrl, {
59+
timeout: JWKS_FETCH_TIMEOUT_MS,
60+
}),
61+
);
5762
cached = {
5863
jwks: jose.createLocalJWKSet(jwksResponse.data),
5964
expiresAt: now + JWKS_TTL_MS,
6065
};
6166
jwksCache.set(jwksUrl, cached);
67+
} else {
68+
console.log("[timing] guard.validateToken.jwksCacheHit");
6269
}
6370

64-
const { payload } = await jose.jwtVerify(token, cached.jwks);
71+
const { payload } = await timed(
72+
"guard.validateToken.jwtVerify",
73+
() => jose.jwtVerify(token, cached!.jwks),
74+
);
6575

6676
return payload;
6777
} catch (error) {
@@ -242,6 +252,13 @@ export class VaultAccessGuard {
242252
) => Promise<any>,
243253
) {
244254
return async (parent: T, args: Args, context: VaultContext) => {
255+
const traceId = newTraceId("op");
256+
const opKind = args.id
257+
? "id-targeted"
258+
: args.envelopeId
259+
? "envelope-targeted"
260+
: "bulk";
261+
console.log(`[timing] ${traceId} guard.middleware.begin ${opKind}`);
245262
// Check if this is storeMetaEnvelope operation (has input with ontology, payload, acl)
246263
const isStoreOperation =
247264
args.input &&
@@ -252,12 +269,20 @@ export class VaultAccessGuard {
252269
!args.id; // storeMetaEnvelope doesn't have id, updateMetaEnvelopeById does
253270

254271
// CRITICAL: Validate authentication BEFORE executing any resolver
255-
await this.validateAuthentication(context, isStoreOperation);
272+
await timed(
273+
"guard.validateAuthentication",
274+
() => this.validateAuthentication(context, isStoreOperation),
275+
traceId,
276+
);
256277

257278
// For operations that don't require a specific meta envelope ID (bulk queries)
258279
if (!args.id && !args.envelopeId) {
259280
// Authentication validated, now execute resolver
260-
const result = await resolver(parent, args, context);
281+
const result = await timed(
282+
"guard.resolver(bulk)",
283+
() => resolver(parent, args, context),
284+
traceId,
285+
);
261286

262287
// If the result is an array
263288
if (Array.isArray(result)) {
@@ -282,20 +307,29 @@ export class VaultAccessGuard {
282307
const metaEnvelopeId = args.id || args.envelopeId;
283308
if (!metaEnvelopeId) {
284309
// Authentication validated, now execute resolver
285-
const result = await resolver(parent, args, context);
310+
const result = await timed(
311+
"guard.resolver(no-id)",
312+
() => resolver(parent, args, context),
313+
traceId,
314+
);
286315
return this.filterACL(result);
287316
}
288317

289318
// Check if envelope exists and user has access
290-
const { hasAccess, exists } = await this.checkAccess(
291-
metaEnvelopeId,
292-
context,
319+
const { hasAccess, exists } = await timed(
320+
"guard.checkAccess",
321+
() => this.checkAccess(metaEnvelopeId, context),
322+
traceId,
293323
);
294324

295325
// For update operations with input, allow in-place creation if envelope doesn't exist
296326
if (!exists && args.input) {
297327
// Envelope doesn't exist for this eName - allow in-place creation
298-
const result = await resolver(parent, args, context);
328+
const result = await timed(
329+
"guard.resolver(in-place-create)",
330+
() => resolver(parent, args, context),
331+
traceId,
332+
);
299333
return this.filterACL(result);
300334
}
301335

@@ -309,7 +343,11 @@ export class VaultAccessGuard {
309343
}
310344

311345
// Execute resolver and filter ACL
312-
const result = await resolver(parent, args, context);
346+
const result = await timed(
347+
"guard.resolver(targeted)",
348+
() => resolver(parent, args, context),
349+
traceId,
350+
);
313351

314352
// If result is null (envelope not found), return null
315353
if (result === null) {

‎infrastructure/evault-core/src/core/utils/timing.ts‎

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,37 @@
1+
const ENABLED = process.env.EVAULT_TIMING !== "0";
2+
const SLOW_MS = Number(process.env.EVAULT_TIMING_SLOW_MS) || 0;
3+
4+
let counter = 0;
5+
export function newTraceId(prefix = "t"): string {
6+
counter = (counter + 1) % 1_000_000;
7+
return `${prefix}${Date.now().toString(36)}${counter.toString(36)}`;
8+
}
9+
10+
export async function timed<T>(
11+
label: string,
12+
fn: () => Promise<T>,
13+
traceId?: string,
14+
): Promise<T> {
15+
if (!ENABLED) return fn();
16+
const start = performance.now();
17+
try {
18+
const result = await fn();
19+
const ms = performance.now() - start;
20+
if (ms >= SLOW_MS) {
21+
console.log(
22+
`[timing]${traceId ? ` ${traceId}` : ""} ${label} ${ms.toFixed(1)}ms`,
23+
);
24+
}
25+
return result;
26+
} catch (err) {
27+
const ms = performance.now() - start;
28+
console.log(
29+
`[timing]${traceId ? ` ${traceId}` : ""} ${label} ${ms.toFixed(1)}ms (failed)`,
30+
);
31+
throw err;
32+
}
33+
}
34+
35+
export function timingEnabled(): boolean {
36+
return ENABLED;
37+
}

0 commit comments

Comments
 (0)