/ @reviews / 04-debounced-logging.md
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.