04-debounced-logging.md
1 # Debounced Logging Optimization 2 3 ## Problem Statement 4 5 The logs show excessive and redundant logging in DaokoTube: 6 7 1. Repeated log messages for the same events (e.g., "Video is already unmuted") 8 2. Verbose logging of large data structures 9 3. No distinction between important and routine log messages 10 4. No rate limiting or debouncing of frequent log messages 11 5. Excessive logging of response time data 12 13 These issues lead to console spam, reduced developer productivity when debugging, and potential performance impacts from excessive string concatenation and console I/O. 14 15 ## Proposed Solution 16 17 Implement a sophisticated logging system that: 18 19 1. Debounces repeated log messages 20 2. Provides different log levels with appropriate visibility 21 3. Truncates large data structures in logs 22 4. Groups related log messages 23 5. Provides context for log messages 24 6. Can be configured to adjust verbosity based on environment 25 26 ## Implementation Plan 27 28 ### 1. Create a Debounced Logger 29 30 ```javascript 31 // app/utils/debug/debounced-logger.js 32 33 // Constants 34 const LOG_LEVELS = { 35 ERROR: 0, 36 WARN: 1, 37 INFO: 2, 38 DEBUG: 3, 39 TRACE: 4 40 }; 41 42 const LOG_LEVEL_NAMES = { 43 [LOG_LEVELS.ERROR]: 'ERROR', 44 [LOG_LEVELS.WARN]: 'WARN', 45 [LOG_LEVELS.INFO]: 'INFO', 46 [LOG_LEVELS.DEBUG]: 'DEBUG', 47 [LOG_LEVELS.TRACE]: 'TRACE' 48 }; 49 50 // Default configuration 51 const DEFAULT_CONFIG = { 52 level: LOG_LEVELS.INFO, 53 debounceTime: 5000, // 5 seconds 54 maxRepeats: 10, // Log after this many repeats 55 truncateObjects: true, 56 maxObjectDepth: 2, 57 maxArrayLength: 5, 58 maxStringLength: 200, 59 useGroups: true, 60 showTimestamps: true 61 }; 62 63 // Global configuration 64 let globalConfig = { ...DEFAULT_CONFIG }; 65 66 /** 67 * Set global logger configuration 68 * @param {Object} config - Configuration options 69 */ 70 export function configureLogger(config) { 71 globalConfig = { ...DEFAULT_CONFIG, ...config }; 72 } 73 74 /** 75 * Reset logger configuration to defaults 76 */ 77 export function resetLoggerConfig() { 78 globalConfig = { ...DEFAULT_CONFIG }; 79 } 80 81 /** 82 * Debounced logger class 83 */ 84 export class DebouncedLogger { 85 /** 86 * Create a new logger instance 87 * @param {string} prefix - Logger prefix 88 * @param {Object} config - Logger configuration 89 */ 90 constructor(prefix, config = {}) { 91 this.prefix = prefix; 92 this.config = { ...globalConfig, ...config }; 93 this.logCache = new Map(); 94 this.groupStack = []; 95 } 96 97 /** 98 * Log an error message 99 * @param {string} message - The message to log 100 * @param {...any} args - Additional arguments 101 */ 102 error(message, ...args) { 103 this._log(LOG_LEVELS.ERROR, message, args); 104 } 105 106 /** 107 * Log a warning message 108 * @param {string} message - The message to log 109 * @param {...any} args - Additional arguments 110 */ 111 warn(message, ...args) { 112 this._log(LOG_LEVELS.WARN, message, args); 113 } 114 115 /** 116 * Log an info message 117 * @param {string} message - The message to log 118 * @param {...any} args - Additional arguments 119 */ 120 info(message, ...args) { 121 this._log(LOG_LEVELS.INFO, message, args); 122 } 123 124 /** 125 * Log a debug message 126 * @param {string} message - The message to log 127 * @param {...any} args - Additional arguments 128 */ 129 debug(message, ...args) { 130 this._log(LOG_LEVELS.DEBUG, message, args); 131 } 132 133 /** 134 * Log a trace message 135 * @param {string} message - The message to log 136 * @param {...any} args - Additional arguments 137 */ 138 trace(message, ...args) { 139 this._log(LOG_LEVELS.TRACE, message, args); 140 } 141 142 /** 143 * Start a log group 144 * @param {string} label - Group label 145 * @param {boolean} collapsed - Whether the group should be collapsed 146 */ 147 group(label, collapsed = false) { 148 if (!this.config.useGroups) { 149 return; 150 } 151 152 const groupMethod = collapsed ? console.groupCollapsed : console.group; 153 groupMethod(`[${this.prefix}] ${label}`); 154 this.groupStack.push(label); 155 } 156 157 /** 158 * End the current log group 159 */ 160 groupEnd() { 161 if (!this.config.useGroups || this.groupStack.length === 0) { 162 return; 163 } 164 165 console.groupEnd(); 166 this.groupStack.pop(); 167 } 168 169 /** 170 * Clear the log cache 171 */ 172 clearCache() { 173 this.logCache.forEach(entry => { 174 if (entry.timeoutId) { 175 clearTimeout(entry.timeoutId); 176 } 177 }); 178 179 this.logCache.clear(); 180 } 181 182 /** 183 * Internal logging method 184 * @param {number} level - Log level 185 * @param {string} message - The message to log 186 * @param {Array} args - Additional arguments 187 * @private 188 */ 189 _log(level, message, args) { 190 // Check if we should log at this level 191 if (level > this.config.level) { 192 return; 193 } 194 195 // Process arguments 196 const processedArgs = this._processArgs(args); 197 198 // For error and warn, don't debounce 199 if (level <= LOG_LEVELS.WARN) { 200 this._writeLog(level, message, processedArgs); 201 return; 202 } 203 204 // For other levels, debounce repeated messages 205 const key = this._getCacheKey(level, message, processedArgs); 206 207 if (this.logCache.has(key)) { 208 const entry = this.logCache.get(key); 209 210 // Update count and clear previous timeout 211 entry.count++; 212 213 if (entry.timeoutId) { 214 clearTimeout(entry.timeoutId); 215 } 216 217 // If we've reached max repeats, log now 218 if (entry.count >= this.config.maxRepeats) { 219 this._writeLog(level, message, processedArgs, entry.count); 220 this.logCache.delete(key); 221 return; 222 } 223 224 // Set new timeout 225 entry.timeoutId = setTimeout(() => { 226 this._writeLog(level, message, processedArgs, entry.count); 227 this.logCache.delete(key); 228 }, this.config.debounceTime); 229 230 this.logCache.set(key, entry); 231 } else { 232 // First occurrence, log immediately 233 this._writeLog(level, message, processedArgs); 234 235 // Set timeout for future occurrences 236 const timeoutId = setTimeout(() => { 237 this.logCache.delete(key); 238 }, this.config.debounceTime); 239 240 this.logCache.set(key, { count: 1, timeoutId }); 241 } 242 } 243 244 /** 245 * Write a log message to the console 246 * @param {number} level - Log level 247 * @param {string} message - The message to log 248 * @param {Array} args - Additional arguments 249 * @param {number} repeatCount - Number of times the message was repeated 250 * @private 251 */ 252 _writeLog(level, message, args, repeatCount = 1) { 253 const logMethod = this._getLogMethod(level); 254 const prefix = this._getPrefix(level); 255 256 let formattedMessage = `${prefix} ${message}`; 257 258 if (repeatCount > 1) { 259 formattedMessage += ` (repeated ${repeatCount} times)`; 260 } 261 262 logMethod(formattedMessage, ...args); 263 } 264 265 /** 266 * Get the appropriate console method for a log level 267 * @param {number} level - Log level 268 * @returns {Function} - Console method 269 * @private 270 */ 271 _getLogMethod(level) { 272 switch (level) { 273 case LOG_LEVELS.ERROR: 274 return console.error; 275 case LOG_LEVELS.WARN: 276 return console.warn; 277 case LOG_LEVELS.INFO: 278 return console.info; 279 case LOG_LEVELS.DEBUG: 280 return console.debug; 281 case LOG_LEVELS.TRACE: 282 return console.trace; 283 default: 284 return console.log; 285 } 286 } 287 288 /** 289 * Get the log prefix 290 * @param {number} level - Log level 291 * @returns {string} - Formatted prefix 292 * @private 293 */ 294 _getPrefix(level) { 295 let prefix = `[${this.prefix}]`; 296 297 if (this.config.showTimestamps) { 298 const now = new Date(); 299 const timestamp = now.toISOString().split('T')[1].slice(0, 12); 300 prefix = `[${timestamp}] ${prefix}`; 301 } 302 303 if (level <= LOG_LEVELS.WARN) { 304 prefix = `${prefix} [${LOG_LEVEL_NAMES[level]}]`; 305 } 306 307 return prefix; 308 } 309 310 /** 311 * Process log arguments 312 * @param {Array} args - Arguments to process 313 * @returns {Array} - Processed arguments 314 * @private 315 */ 316 _processArgs(args) { 317 if (!this.config.truncateObjects) { 318 return args; 319 } 320 321 return args.map(arg => this._truncateValue(arg, this.config.maxObjectDepth)); 322 } 323 324 /** 325 * Truncate a value for logging 326 * @param {any} value - The value to truncate 327 * @param {number} depth - Maximum depth for objects 328 * @returns {any} - Truncated value 329 * @private 330 */ 331 _truncateValue(value, depth) { 332 if (depth <= 0) { 333 return '[Object]'; 334 } 335 336 if (value === null || value === undefined) { 337 return value; 338 } 339 340 if (typeof value === 'string' && value.length > this.config.maxStringLength) { 341 return value.substring(0, this.config.maxStringLength) + '...'; 342 } 343 344 if (Array.isArray(value)) { 345 if (value.length > this.config.maxArrayLength) { 346 return [ 347 ...value.slice(0, this.config.maxArrayLength).map(item => this._truncateValue(item, depth - 1)), 348 `... (${value.length - this.config.maxArrayLength} more items)` 349 ]; 350 } 351 352 return value.map(item => this._truncateValue(item, depth - 1)); 353 } 354 355 if (typeof value === 'object') { 356 const result = {}; 357 358 const entries = Object.entries(value); 359 const maxEntries = this.config.maxArrayLength; 360 361 if (entries.length > maxEntries) { 362 entries.slice(0, maxEntries).forEach(([key, val]) => { 363 result[key] = this._truncateValue(val, depth - 1); 364 }); 365 366 result[`... (${entries.length - maxEntries} more properties)`] = '[Truncated]'; 367 } else { 368 entries.forEach(([key, val]) => { 369 result[key] = this._truncateValue(val, depth - 1); 370 }); 371 } 372 373 return result; 374 } 375 376 return value; 377 } 378 379 /** 380 * Get a cache key for a log message 381 * @param {number} level - Log level 382 * @param {string} message - The message 383 * @param {Array} args - Additional arguments 384 * @returns {string} - Cache key 385 * @private 386 */ 387 _getCacheKey(level, message, args) { 388 try { 389 return `${level}:${message}:${JSON.stringify(args)}`; 390 } catch (e) { 391 // If JSON.stringify fails, use a simpler key 392 return `${level}:${message}:${args.length}_args`; 393 } 394 } 395 } 396 397 /** 398 * Create a new logger instance 399 * @param {string} prefix - Logger prefix 400 * @param {Object} config - Logger configuration 401 * @returns {DebouncedLogger} - Logger instance 402 */ 403 export function createLogger(prefix, config = {}) { 404 return new DebouncedLogger(prefix, config); 405 } 406 407 // Export constants 408 export { LOG_LEVELS }; 409 ``` 410 411 ### 2. Update the existing logger.js 412 413 ```javascript 414 // app/utils/debug/logger.js 415 416 import { createLogger as createDebouncedLogger, LOG_LEVELS, configureLogger } from './debounced-logger.js'; 417 418 // Configure logger based on environment 419 const isProduction = window.location.hostname.includes('.pages.dev'); 420 const isDevelopment = window.location.hostname === 'localhost'; 421 422 // Set default configuration 423 configureLogger({ 424 level: isProduction ? LOG_LEVELS.INFO : (isDevelopment ? LOG_LEVELS.DEBUG : LOG_LEVELS.INFO), 425 debounceTime: isProduction ? 10000 : 5000, 426 maxRepeats: isProduction ? 20 : 10, 427 truncateObjects: true, 428 maxObjectDepth: isProduction ? 1 : 2, 429 maxArrayLength: isProduction ? 3 : 5, 430 maxStringLength: isProduction ? 100 : 200, 431 useGroups: !isProduction, 432 showTimestamps: true 433 }); 434 435 /** 436 * Create a new logger instance 437 * @param {string} prefix - Logger prefix 438 * @returns {DebouncedLogger} - Logger instance 439 */ 440 export function createLogger(prefix) { 441 return createDebouncedLogger(prefix); 442 } 443 444 // Export for direct use 445 export default { 446 createLogger 447 }; 448 ``` 449 450 ### 3. Update VideoController to use the new logger 451 452 ```javascript 453 // app/services/video/controller.js 454 455 import { createLogger } from '../../utils/debug/logger.js'; 456 457 const logger = createLogger('VideoController'); 458 459 // Replace console.log/info/warn/error calls with logger 460 // For example: 461 // console.info('Video loaded from provider', provider, 'in', loadTime, 'ms'); 462 // becomes: 463 logger.info(`Video loaded from provider ${provider} in ${loadTime}ms`); 464 465 // For grouped logs: 466 logger.group('Video loading details'); 467 logger.info(`Provider: ${provider}`); 468 logger.info(`Load time: ${loadTime}ms`); 469 logger.info(`Average load time: ${avgLoadTime}ms`); 470 logger.groupEnd(); 471 ``` 472 473 ### 4. Update other components to use the new logger 474 475 Apply similar changes to other components that use console logging, such as: 476 477 - VideoRouter 478 - RecoveryCoordinator 479 - current-video-pretest.js 480 - next-video-pretest.js 481 - AudioStateManager 482 - etc. 483 484 ## Expected Benefits 485 486 1. **Reduced Console Spam**: By debouncing repeated log messages, we'll significantly reduce console spam. 487 2. **Improved Debugging**: Better formatted logs with context and grouping will make debugging easier. 488 3. **Performance Improvement**: Less string concatenation and console I/O will improve performance. 489 4. **Better Log Organization**: Log levels and prefixes will make it easier to find relevant logs. 490 5. **Environment-Specific Logging**: Different log levels for production and development will ensure appropriate verbosity. 491 492 ## Testing Plan 493 494 1. **Unit Tests**: Create unit tests for the DebouncedLogger class. 495 2. **Integration Tests**: Test the integration with various components. 496 3. **Performance Tests**: Measure the impact on performance before and after the changes. 497 4. **Environment Tests**: Test in different environments to ensure appropriate log levels. 498 5. **Edge Case Tests**: Test with large objects, arrays, and strings to ensure proper truncation. 499 500 ## Rollout Plan 501 502 1. **Development**: Implement the changes in a development environment. 503 2. **Testing**: Test the changes thoroughly. 504 3. **Gradual Adoption**: Update components one by one to use the new logger. 505 4. **Production**: Roll out to production, monitoring for any issues. 506 5. **Monitoring**: Monitor for any logging-related issues or performance impacts.