diff --git a/src/storage/adapters/gcsStorage.ts b/src/storage/adapters/gcsStorage.ts index 0ae60c19..02910fee 100644 --- a/src/storage/adapters/gcsStorage.ts +++ b/src/storage/adapters/gcsStorage.ts @@ -466,9 +466,8 @@ export class GcsStorage extends BaseStorage { // This prevents cache pollution from HNSW's lazy-loading nodes (vector: []) if (node.vector && Array.isArray(node.vector) && node.vector.length > 0) { this.nounCacheManager.set(node.id, node) - } else { - prodLog.warn(`[saveNode] Not caching node ${node.id.substring(0, 8)}... with empty vector (HNSW lazy mode)`) } + // Note: Empty vectors are intentional during HNSW lazy mode - not logged // Increment noun count const metadata = await this.getNounMetadata(node.id) @@ -519,53 +518,29 @@ export class GcsStorage extends BaseStorage { protected async getNode(id: string): Promise { await this.ensureInitialized() - // Check cache first WITH LOGGING + // Check cache first const cached: HNSWNode | null = await this.nounCacheManager.get(id) - // DIAGNOSTIC LOGGING: Reveal cache poisoning - prodLog.info(`[getNode] 🔍 Cache check for ${id.substring(0, 8)}...:`, { - hasCached: cached !== undefined, - isNull: cached === null, - isObject: cached !== null && typeof cached === 'object', - type: typeof cached - }) - - // CRITICAL FIX (v3.37.8): Validate cached object before returning + // Validate cached object before returning (v3.37.8+) if (cached !== undefined && cached !== null) { - // Log cached object structure to diagnose incomplete objects - prodLog.info(`[getNode] Cached object structure:`, { - hasId: !!cached.id, - idMatches: cached.id === id, - hasVector: !!cached.vector, - vectorLength: cached.vector?.length, - hasConnections: !!cached.connections, - connectionsType: typeof cached.connections, - hasLevel: cached.level !== undefined, - level: cached.level, - objectKeys: Object.keys(cached || {}) - }) - // Validate cached object has required fields (including non-empty vector!) if (!cached.id || !cached.vector || !Array.isArray(cached.vector) || cached.vector.length === 0) { - prodLog.error(`[getNode] ❌ INVALID cached object for ${id.substring(0, 8)}...:`, { - reason: !cached.id ? 'missing id' : - !cached.vector ? 'missing vector' : - !Array.isArray(cached.vector) ? 'vector not array' : - cached.vector.length === 0 ? 'vector is empty array' : - 'unknown' - }) - prodLog.error(`[getNode] Removing invalid object from cache and loading from GCS`) + // Invalid cache detected - log and auto-recover + prodLog.warn(`[GCS] Invalid cached object for ${id.substring(0, 8)} (${ + !cached.id ? 'missing id' : + !cached.vector ? 'missing vector' : + !Array.isArray(cached.vector) ? 'vector not array' : + 'empty vector' + }) - removing from cache and reloading`) this.nounCacheManager.delete(id) // Fall through to load from GCS } else { - prodLog.info(`[getNode] ✅ Valid cached object - returning`) + // Valid cache hit this.logger.trace(`Cache hit for noun ${id}`) return cached } } else if (cached === null) { - prodLog.warn(`[getNode] ⚠️ Cache contains NULL for ${id.substring(0, 8)}... - ignoring and loading from GCS`) - } else { - prodLog.info(`[getNode] ❌ Cache MISS - loading from GCS for ${id.substring(0, 8)}...`) + prodLog.warn(`[GCS] Cache contains null for ${id.substring(0, 8)} - reloading from storage`) } // Apply backpressure @@ -577,23 +552,12 @@ export class GcsStorage extends BaseStorage { // Get the GCS key with UUID-based sharding const key = this.getNounKey(id) - // DIAGNOSTIC LOGGING: Show exact path being accessed - prodLog.info(`[getNode] 🔍 Attempting to load:`) - prodLog.info(`[getNode] UUID: ${id}`) - prodLog.info(`[getNode] Path: ${key}`) - prodLog.info(`[getNode] Bucket: ${this.bucketName}`) - // Download from GCS const file = this.bucket!.file(key) - - prodLog.info(`[getNode] 📥 Downloading file...`) const [contents] = await file.download() - prodLog.info(`[getNode] ✅ Download successful: ${contents.length} bytes`) // Parse JSON - prodLog.info(`[getNode] 🔧 Parsing JSON...`) const data = JSON.parse(contents.toString()) - prodLog.info(`[getNode] ✅ JSON parsed successfully, id: ${data.id}`) // Convert serialized connections back to Map> const connections = new Map>() @@ -614,9 +578,8 @@ export class GcsStorage extends BaseStorage { // CRITICAL FIX: Only cache valid nodes with non-empty vectors (never cache null or empty) if (node && node.id && node.vector && Array.isArray(node.vector) && node.vector.length > 0) { this.nounCacheManager.set(id, node) - prodLog.info(`[getNode] 💾 Cached node ${id.substring(0, 8)}... successfully`) } else { - prodLog.warn(`[getNode] ⚠️ NOT caching invalid node for ${id.substring(0, 8)}... (missing id/vector or empty vector)`) + prodLog.warn(`[GCS] Not caching invalid node ${id.substring(0, 8)} (missing id/vector or empty vector)`) } this.logger.trace(`Successfully retrieved node ${id}`) @@ -1109,14 +1072,6 @@ export class GcsStorage extends BaseStorage { const limit = options.limit || 100 const useCache = options.useCache !== false - // DIAGNOSTIC LOGGING: Track pagination performance - prodLog.info(`[getNodesWithPagination] Starting pagination: limit=${limit}, cursor=${options.cursor || 'none'}`) - const startTime = Date.now() - let shardsChecked = 0 - let filesFound = 0 - let nodesLoaded = 0 - let nodesFailed = 0 - try { const nodes: HNSWNode[] = [] @@ -1133,7 +1088,6 @@ export class GcsStorage extends BaseStorage { for (let shardIndex = startShardIndex; shardIndex < TOTAL_SHARDS; shardIndex++) { const shardId = getShardIdByIndex(shardIndex) const shardPrefix = `${this.nounPrefix}${shardId}/` - shardsChecked++ // List objects in this shard // Cap maxResults to GCS API limit to prevent "Invalid unsigned integer" errors @@ -1146,13 +1100,6 @@ export class GcsStorage extends BaseStorage { pageToken: shardIndex === startShardIndex ? gcsPageToken : undefined }) - // DIAGNOSTIC LOGGING: Show files found per shard (only log non-empty shards) - if (files && files.length > 0) { - filesFound += files.length - prodLog.info(`[Shard ${shardId}] Found ${files.length} files in "${shardPrefix}"`) - prodLog.info(`[Shard ${shardId}] Sample file names: ${files.slice(0, 3).map((f: any) => f.name).join(', ')}`) - } - // Extract node IDs from file names if (files && files.length > 0) { const nodeIds = files @@ -1170,22 +1117,11 @@ export class GcsStorage extends BaseStorage { }) .filter((id: string) => id && id.length > 0) - // DIAGNOSTIC LOGGING: Show extracted UUIDs - prodLog.info(`[Shard ${shardId}] Extracted ${nodeIds.length} UUIDs: ${nodeIds.slice(0, 3).join(', ')}...`) - // Load nodes for (const id of nodeIds) { - // DIAGNOSTIC LOGGING: Show each getNode() attempt - prodLog.info(`[Shard ${shardId}] Calling getNode("${id}")...`) const node = await this.getNode(id) - if (node) { nodes.push(node) - nodesLoaded++ - prodLog.info(`[Shard ${shardId}] ✅ Successfully loaded node ${id}`) - } else { - nodesFailed++ - prodLog.warn(`[Shard ${shardId}] ❌ getNode("${id}") returned null!`) } if (nodes.length >= limit) { @@ -1224,15 +1160,6 @@ export class GcsStorage extends BaseStorage { } // No more shards or nodes - // DIAGNOSTIC LOGGING: Final summary - const elapsedTime = Date.now() - startTime - prodLog.info(`[getNodesWithPagination] COMPLETED in ${elapsedTime}ms:`) - prodLog.info(` - Shards checked: ${shardsChecked}/${TOTAL_SHARDS}`) - prodLog.info(` - Files found: ${filesFound}`) - prodLog.info(` - Nodes loaded: ${nodesLoaded}`) - prodLog.info(` - Nodes failed: ${nodesFailed}`) - prodLog.info(` - Success rate: ${filesFound > 0 ? ((nodesLoaded / filesFound) * 100).toFixed(1) : 'N/A'}%`) - return { nodes, totalCount: this.totalNounCount, diff --git a/src/storage/adapters/s3CompatibleStorage.ts b/src/storage/adapters/s3CompatibleStorage.ts index 8a4f65a9..45808d85 100644 --- a/src/storage/adapters/s3CompatibleStorage.ts +++ b/src/storage/adapters/s3CompatibleStorage.ts @@ -1083,51 +1083,29 @@ export class S3CompatibleStorage extends BaseStorage { protected async getNode(id: string): Promise { await this.ensureInitialized() - // Check cache first WITH LOGGING + // Check cache first const cached = this.nodeCache.get(id) - // DIAGNOSTIC LOGGING: Reveal cache poisoning - prodLog.info(`[getNode] 🔍 Cache check for ${id.substring(0, 8)}...:`, { - hasCached: cached !== undefined, - isNull: cached === null, - isObject: cached !== null && typeof cached === 'object', - type: typeof cached - }) - - // CRITICAL FIX (v3.37.8): Validate cached object before returning + // Validate cached object before returning (v3.37.8+) if (cached !== undefined && cached !== null) { - // Log cached object structure to diagnose incomplete objects - prodLog.info(`[getNode] Cached object structure:`, { - hasId: !!cached.id, - idMatches: cached.id === id, - hasVector: !!cached.vector, - vectorLength: cached.vector?.length, - hasConnections: !!cached.connections, - connectionsType: typeof cached.connections, - objectKeys: Object.keys(cached || {}) - }) - // Validate cached object has required fields (including non-empty vector!) if (!cached.id || !cached.vector || !Array.isArray(cached.vector) || cached.vector.length === 0) { - prodLog.error(`[getNode] ❌ INVALID cached object for ${id.substring(0, 8)}...:`, { - reason: !cached.id ? 'missing id' : - !cached.vector ? 'missing vector' : - !Array.isArray(cached.vector) ? 'vector not array' : - cached.vector.length === 0 ? 'vector is empty array' : - 'unknown' - }) - prodLog.error(`[getNode] Removing invalid object from cache and loading from S3`) + // Invalid cache detected - log and auto-recover + prodLog.warn(`[S3] Invalid cached object for ${id.substring(0, 8)} (${ + !cached.id ? 'missing id' : + !cached.vector ? 'missing vector' : + !Array.isArray(cached.vector) ? 'vector not array' : + 'empty vector' + }) - removing from cache and reloading`) this.nodeCache.delete(id) // Fall through to load from S3 } else { - prodLog.info(`[getNode] ✅ Valid cached object - returning`) + // Valid cache hit this.logger.trace(`Cache hit for node ${id}`) return cached } } else if (cached === null) { - prodLog.warn(`[getNode] ⚠️ Cache contains NULL for ${id.substring(0, 8)}... - ignoring and loading from S3`) - } else { - prodLog.info(`[getNode] ❌ Cache MISS - loading from S3 for ${id.substring(0, 8)}...`) + prodLog.warn(`[S3] Cache contains null for ${id.substring(0, 8)} - reloading from storage`) } try { @@ -1137,14 +1115,7 @@ export class S3CompatibleStorage extends BaseStorage { // Use getNounKey() to properly handle sharding const key = this.getNounKey(id) - // DIAGNOSTIC LOGGING: Show exact path being accessed - prodLog.info(`[getNode] 🔍 Attempting to load:`) - prodLog.info(`[getNode] UUID: ${id}`) - prodLog.info(`[getNode] Path: ${key}`) - prodLog.info(`[getNode] Bucket: ${this.bucketName}`) - // Try to get the node from the nouns directory - prodLog.info(`[getNode] 📥 Downloading file...`) const response = await this.s3Client!.send( new GetObjectCommand({ Bucket: this.bucketName, @@ -1154,18 +1125,13 @@ export class S3CompatibleStorage extends BaseStorage { // Check if response is null or undefined if (!response || !response.Body) { - prodLog.warn(`[getNode] ❌ Response or Body is null/undefined`) + prodLog.warn(`[S3] Response or Body is null/undefined for ${id.substring(0, 8)}`) return null } - // Convert the response body to a string + // Convert the response body to a string and parse JSON const bodyContents = await response.Body.transformToString() - prodLog.info(`[getNode] ✅ Download successful: ${bodyContents.length} bytes`) - - // Parse the JSON string - prodLog.info(`[getNode] 🔧 Parsing JSON...`) const parsedNode = JSON.parse(bodyContents) - prodLog.info(`[getNode] ✅ JSON parsed successfully, id: ${parsedNode.id}`) // Ensure the parsed node has the expected properties if ( @@ -1197,43 +1163,26 @@ export class S3CompatibleStorage extends BaseStorage { // CRITICAL FIX: Only cache valid nodes with non-empty vectors (never cache null or empty) if (node && node.id && node.vector && Array.isArray(node.vector) && node.vector.length > 0) { this.nodeCache.set(id, node) - prodLog.info(`[getNode] 💾 Cached node ${id.substring(0, 8)}... successfully`) } else { - prodLog.warn(`[getNode] ⚠️ NOT caching invalid node for ${id.substring(0, 8)}... (missing id/vector or empty vector)`) + prodLog.warn(`[S3] Not caching invalid node ${id.substring(0, 8)} (missing id/vector or empty vector)`) } this.logger.trace(`Successfully retrieved node ${id}`) return node } catch (error: any) { - // DIAGNOSTIC LOGGING: Log EVERY error before any conditional checks - const key = this.getNounKey(id) - prodLog.error(`[getNode] ❌ EXCEPTION CAUGHT:`) - prodLog.error(`[getNode] UUID: ${id}`) - prodLog.error(`[getNode] Path: ${key}`) - prodLog.error(`[getNode] Bucket: ${this.bucketName}`) - prodLog.error(`[getNode] Error type: ${error?.constructor?.name || typeof error}`) - prodLog.error(`[getNode] Error name: ${error?.name}`) - prodLog.error(`[getNode] Error code: ${JSON.stringify(error?.Code || error?.code)}`) - prodLog.error(`[getNode] Error message: ${error?.message || String(error)}`) - prodLog.error(`[getNode] HTTP status: ${error?.$metadata?.httpStatusCode}`) - prodLog.error(`[getNode] Error object:`, JSON.stringify(error, null, 2)) - // Check if this is a "not found" error (S3 uses "NoSuchKey") if (error?.name === 'NoSuchKey' || error?.Code === 'NoSuchKey' || error?.$metadata?.httpStatusCode === 404) { - prodLog.warn(`[getNode] Identified as 404/NoSuchKey error - returning null WITHOUT caching`) - // CRITICAL FIX: Do NOT cache null values + // File not found - not cached, just return null return null } // Handle throttling if (this.isThrottlingError(error)) { - prodLog.warn(`[getNode] Identified as throttling error - rethrowing`) await this.handleThrottling(error) throw error } // All other errors should throw, not return null - prodLog.error(`[getNode] Unhandled error - rethrowing`) this.logger.error(`Failed to get node ${id}:`, error) throw BrainyError.fromError(error, `getNoun(${id})`) }