refactor: clean up verbose diagnostic logging from storage adapters

Remove verbose info logs from GCS and S3 storage adapters while keeping
critical warnings and error messages. This cleanup makes production logs
more actionable and less noisy.

Changes:
- Remove verbose cache check logging (structure details, field validation)
- Remove verbose GCS/S3 operation logs (download progress, parsing steps)
- Remove verbose pagination diagnostic logs (per-shard, per-file details)
- Keep critical warnings for invalid cache, null cache, recovery actions
- Keep error logs for actual failures
- Move successful operation details to trace level

Benefits:
- Production logs are now clean and actionable
- Critical issues still surface with warnings
- Debug details available via trace level when needed
- v3.37.8 cache validation remains fully functional

This completes the GCS persistence debugging journey (v3.35.0 → v3.38.0)
This commit is contained in:
David Snelling 2025-10-13 09:23:27 -07:00
parent 38b563c981
commit 1b13505da5
2 changed files with 28 additions and 152 deletions

View file

@ -466,9 +466,8 @@ export class GcsStorage extends BaseStorage {
// This prevents cache pollution from HNSW's lazy-loading nodes (vector: []) // This prevents cache pollution from HNSW's lazy-loading nodes (vector: [])
if (node.vector && Array.isArray(node.vector) && node.vector.length > 0) { if (node.vector && Array.isArray(node.vector) && node.vector.length > 0) {
this.nounCacheManager.set(node.id, node) 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 // Increment noun count
const metadata = await this.getNounMetadata(node.id) const metadata = await this.getNounMetadata(node.id)
@ -519,53 +518,29 @@ export class GcsStorage extends BaseStorage {
protected async getNode(id: string): Promise<HNSWNode | null> { protected async getNode(id: string): Promise<HNSWNode | null> {
await this.ensureInitialized() await this.ensureInitialized()
// Check cache first WITH LOGGING // Check cache first
const cached: HNSWNode | null = await this.nounCacheManager.get(id) const cached: HNSWNode | null = await this.nounCacheManager.get(id)
// DIAGNOSTIC LOGGING: Reveal cache poisoning // Validate cached object before returning (v3.37.8+)
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
if (cached !== undefined && cached !== null) { 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!) // Validate cached object has required fields (including non-empty vector!)
if (!cached.id || !cached.vector || !Array.isArray(cached.vector) || cached.vector.length === 0) { if (!cached.id || !cached.vector || !Array.isArray(cached.vector) || cached.vector.length === 0) {
prodLog.error(`[getNode] ❌ INVALID cached object for ${id.substring(0, 8)}...:`, { // Invalid cache detected - log and auto-recover
reason: !cached.id ? 'missing id' : prodLog.warn(`[GCS] Invalid cached object for ${id.substring(0, 8)} (${
!cached.vector ? 'missing vector' : !cached.id ? 'missing id' :
!Array.isArray(cached.vector) ? 'vector not array' : !cached.vector ? 'missing vector' :
cached.vector.length === 0 ? 'vector is empty array' : !Array.isArray(cached.vector) ? 'vector not array' :
'unknown' 'empty vector'
}) }) - removing from cache and reloading`)
prodLog.error(`[getNode] Removing invalid object from cache and loading from GCS`)
this.nounCacheManager.delete(id) this.nounCacheManager.delete(id)
// Fall through to load from GCS // Fall through to load from GCS
} else { } else {
prodLog.info(`[getNode] ✅ Valid cached object - returning`) // Valid cache hit
this.logger.trace(`Cache hit for noun ${id}`) this.logger.trace(`Cache hit for noun ${id}`)
return cached return cached
} }
} else if (cached === null) { } else if (cached === null) {
prodLog.warn(`[getNode] ⚠️ Cache contains NULL for ${id.substring(0, 8)}... - ignoring and loading from GCS`) prodLog.warn(`[GCS] Cache contains null for ${id.substring(0, 8)} - reloading from storage`)
} else {
prodLog.info(`[getNode] ❌ Cache MISS - loading from GCS for ${id.substring(0, 8)}...`)
} }
// Apply backpressure // Apply backpressure
@ -577,23 +552,12 @@ export class GcsStorage extends BaseStorage {
// Get the GCS key with UUID-based sharding // Get the GCS key with UUID-based sharding
const key = this.getNounKey(id) 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 // Download from GCS
const file = this.bucket!.file(key) const file = this.bucket!.file(key)
prodLog.info(`[getNode] 📥 Downloading file...`)
const [contents] = await file.download() const [contents] = await file.download()
prodLog.info(`[getNode] ✅ Download successful: ${contents.length} bytes`)
// Parse JSON // Parse JSON
prodLog.info(`[getNode] 🔧 Parsing JSON...`)
const data = JSON.parse(contents.toString()) const data = JSON.parse(contents.toString())
prodLog.info(`[getNode] ✅ JSON parsed successfully, id: ${data.id}`)
// Convert serialized connections back to Map<number, Set<string>> // Convert serialized connections back to Map<number, Set<string>>
const connections = new Map<number, Set<string>>() const connections = new Map<number, Set<string>>()
@ -614,9 +578,8 @@ export class GcsStorage extends BaseStorage {
// CRITICAL FIX: Only cache valid nodes with non-empty vectors (never cache null or empty) // 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) { if (node && node.id && node.vector && Array.isArray(node.vector) && node.vector.length > 0) {
this.nounCacheManager.set(id, node) this.nounCacheManager.set(id, node)
prodLog.info(`[getNode] 💾 Cached node ${id.substring(0, 8)}... successfully`)
} else { } 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}`) this.logger.trace(`Successfully retrieved node ${id}`)
@ -1109,14 +1072,6 @@ export class GcsStorage extends BaseStorage {
const limit = options.limit || 100 const limit = options.limit || 100
const useCache = options.useCache !== false 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 { try {
const nodes: HNSWNode[] = [] const nodes: HNSWNode[] = []
@ -1133,7 +1088,6 @@ export class GcsStorage extends BaseStorage {
for (let shardIndex = startShardIndex; shardIndex < TOTAL_SHARDS; shardIndex++) { for (let shardIndex = startShardIndex; shardIndex < TOTAL_SHARDS; shardIndex++) {
const shardId = getShardIdByIndex(shardIndex) const shardId = getShardIdByIndex(shardIndex)
const shardPrefix = `${this.nounPrefix}${shardId}/` const shardPrefix = `${this.nounPrefix}${shardId}/`
shardsChecked++
// List objects in this shard // List objects in this shard
// Cap maxResults to GCS API limit to prevent "Invalid unsigned integer" errors // 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 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 // Extract node IDs from file names
if (files && files.length > 0) { if (files && files.length > 0) {
const nodeIds = files const nodeIds = files
@ -1170,22 +1117,11 @@ export class GcsStorage extends BaseStorage {
}) })
.filter((id: string) => id && id.length > 0) .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 // Load nodes
for (const id of nodeIds) { for (const id of nodeIds) {
// DIAGNOSTIC LOGGING: Show each getNode() attempt
prodLog.info(`[Shard ${shardId}] Calling getNode("${id}")...`)
const node = await this.getNode(id) const node = await this.getNode(id)
if (node) { if (node) {
nodes.push(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) { if (nodes.length >= limit) {
@ -1224,15 +1160,6 @@ export class GcsStorage extends BaseStorage {
} }
// No more shards or nodes // 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 { return {
nodes, nodes,
totalCount: this.totalNounCount, totalCount: this.totalNounCount,

View file

@ -1083,51 +1083,29 @@ export class S3CompatibleStorage extends BaseStorage {
protected async getNode(id: string): Promise<HNSWNode | null> { protected async getNode(id: string): Promise<HNSWNode | null> {
await this.ensureInitialized() await this.ensureInitialized()
// Check cache first WITH LOGGING // Check cache first
const cached = this.nodeCache.get(id) const cached = this.nodeCache.get(id)
// DIAGNOSTIC LOGGING: Reveal cache poisoning // Validate cached object before returning (v3.37.8+)
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
if (cached !== undefined && cached !== null) { 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!) // Validate cached object has required fields (including non-empty vector!)
if (!cached.id || !cached.vector || !Array.isArray(cached.vector) || cached.vector.length === 0) { if (!cached.id || !cached.vector || !Array.isArray(cached.vector) || cached.vector.length === 0) {
prodLog.error(`[getNode] ❌ INVALID cached object for ${id.substring(0, 8)}...:`, { // Invalid cache detected - log and auto-recover
reason: !cached.id ? 'missing id' : prodLog.warn(`[S3] Invalid cached object for ${id.substring(0, 8)} (${
!cached.vector ? 'missing vector' : !cached.id ? 'missing id' :
!Array.isArray(cached.vector) ? 'vector not array' : !cached.vector ? 'missing vector' :
cached.vector.length === 0 ? 'vector is empty array' : !Array.isArray(cached.vector) ? 'vector not array' :
'unknown' 'empty vector'
}) }) - removing from cache and reloading`)
prodLog.error(`[getNode] Removing invalid object from cache and loading from S3`)
this.nodeCache.delete(id) this.nodeCache.delete(id)
// Fall through to load from S3 // Fall through to load from S3
} else { } else {
prodLog.info(`[getNode] ✅ Valid cached object - returning`) // Valid cache hit
this.logger.trace(`Cache hit for node ${id}`) this.logger.trace(`Cache hit for node ${id}`)
return cached return cached
} }
} else if (cached === null) { } else if (cached === null) {
prodLog.warn(`[getNode] ⚠️ Cache contains NULL for ${id.substring(0, 8)}... - ignoring and loading from S3`) prodLog.warn(`[S3] Cache contains null for ${id.substring(0, 8)} - reloading from storage`)
} else {
prodLog.info(`[getNode] ❌ Cache MISS - loading from S3 for ${id.substring(0, 8)}...`)
} }
try { try {
@ -1137,14 +1115,7 @@ export class S3CompatibleStorage extends BaseStorage {
// Use getNounKey() to properly handle sharding // Use getNounKey() to properly handle sharding
const key = this.getNounKey(id) 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 // Try to get the node from the nouns directory
prodLog.info(`[getNode] 📥 Downloading file...`)
const response = await this.s3Client!.send( const response = await this.s3Client!.send(
new GetObjectCommand({ new GetObjectCommand({
Bucket: this.bucketName, Bucket: this.bucketName,
@ -1154,18 +1125,13 @@ export class S3CompatibleStorage extends BaseStorage {
// Check if response is null or undefined // Check if response is null or undefined
if (!response || !response.Body) { 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 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() 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) const parsedNode = JSON.parse(bodyContents)
prodLog.info(`[getNode] ✅ JSON parsed successfully, id: ${parsedNode.id}`)
// Ensure the parsed node has the expected properties // Ensure the parsed node has the expected properties
if ( 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) // 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) { if (node && node.id && node.vector && Array.isArray(node.vector) && node.vector.length > 0) {
this.nodeCache.set(id, node) this.nodeCache.set(id, node)
prodLog.info(`[getNode] 💾 Cached node ${id.substring(0, 8)}... successfully`)
} else { } 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}`) this.logger.trace(`Successfully retrieved node ${id}`)
return node return node
} catch (error: any) { } 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") // Check if this is a "not found" error (S3 uses "NoSuchKey")
if (error?.name === 'NoSuchKey' || error?.Code === 'NoSuchKey' || error?.$metadata?.httpStatusCode === 404) { if (error?.name === 'NoSuchKey' || error?.Code === 'NoSuchKey' || error?.$metadata?.httpStatusCode === 404) {
prodLog.warn(`[getNode] Identified as 404/NoSuchKey error - returning null WITHOUT caching`) // File not found - not cached, just return null
// CRITICAL FIX: Do NOT cache null values
return null return null
} }
// Handle throttling // Handle throttling
if (this.isThrottlingError(error)) { if (this.isThrottlingError(error)) {
prodLog.warn(`[getNode] Identified as throttling error - rethrowing`)
await this.handleThrottling(error) await this.handleThrottling(error)
throw error throw error
} }
// All other errors should throw, not return null // All other errors should throw, not return null
prodLog.error(`[getNode] Unhandled error - rethrowing`)
this.logger.error(`Failed to get node ${id}:`, error) this.logger.error(`Failed to get node ${id}:`, error)
throw BrainyError.fromError(error, `getNoun(${id})`) throw BrainyError.fromError(error, `getNoun(${id})`)
} }