Back to Repositories

Testing Logger Implementation and Console Management in video.js

This test suite validates the logging functionality in video.js, covering console output handling, log levels, history management, and custom logger creation. It ensures robust logging capabilities with proper message formatting and level-based filtering.

Test Coverage Overview

The test suite comprehensively covers the logging utility’s core functionality:

Basic logging operations across different levels (debug, info, warn, error)
Log level management and filtering
History tracking with size limitations
Custom logger creation with naming chains
Fallback behavior for unsupported console methods

Implementation Analysis

The testing approach utilizes QUnit framework with sinon for spying on console methods. Tests are structured using beforeEach/afterEach hooks for consistent console mocking and cleanup. The implementation verifies both synchronous logging operations and state management through detailed assertion chains.

Technical Details

Key technical components include:

QUnit test framework integration
Sinon.js for console method spying
Mock console implementation
Custom assertion patterns for log message verification
Environment cleanup routines

Best Practices Demonstrated

The test suite exemplifies several testing best practices:

Proper test isolation through mock console implementation
Comprehensive edge case coverage
Consistent state cleanup between tests
Clear test organization and naming
Thorough verification of both positive and negative cases

videojs/videoJs

test/unit/utils/log.test.js

            
/* eslint-env qunit */
import log from '../../../src/js/utils/log.js';
import window from 'global/window';
import sinon from 'sinon';

QUnit.module('utils/log', {

  beforeEach() {

    // Back up the original console.
    this.originalConsole = window.console;

    // Replace the native console for testing. In IE8 `console.log` is not a
    // 'function' so sinon chokes on it when trying to spy:
    //   https://github.com/cjohansen/Sinon.JS/issues/386
    //
    // Instead we'll temporarily replace them with no-op functions
    window.console = {
      debug: sinon.spy(),
      info: sinon.spy(),
      log: sinon.spy(),
      warn: sinon.spy(),
      error: sinon.spy()
    };
  },

  afterEach() {

    // Restore the native/original console.
    window.console = this.originalConsole;

    // Restore the default logging level.
    log.level(log.levels.DEFAULT);

    // Empty the logger's history.
    log.history.clear();
  }
});

QUnit.test('logging functions should work', function(assert) {

  // Need to reset history here because there are extra messages logged
  // when running via Karma.
  log.history.clear();

  log('log1', 'log2');
  log.debug('debug1', 'debug2');
  log.warn('warn1', 'warn2');
  log.error('error1', 'error2');

  assert.ok(window.console.log.called, 'log was called');
  assert.deepEqual(
    window.console.log.firstCall.args,
    ['VIDEOJS:', 'log1', 'log2']
  );

  // debug isn't enabled by default
  assert.notOk(window.console.debug.called, 'debug was not called');

  assert.ok(window.console.warn.called, 'warn was called');
  assert.deepEqual(
    window.console.warn.firstCall.args,
    ['VIDEOJS:', 'WARN:', 'warn1', 'warn2']
  );

  assert.ok(window.console.error.called, 'error was called');
  assert.deepEqual(
    window.console.error.firstCall.args,
    ['VIDEOJS:', 'ERROR:', 'error1', 'error2']
  );

  const history = log.history();

  assert.equal(history.length, 4, 'there should be four messages in the log history');
  assert.deepEqual(
    history[0],
    ['VIDEOJS:', 'log1', 'log2'],
    'history recorded the correct arguments'
  );
  // although not enabled by default, history should still maintain the record
  assert.deepEqual(
    history[1],
    ['VIDEOJS:', 'DEBUG:', 'debug1', 'debug2'],
    'history recorded the correct arguments'
  );
  assert.deepEqual(
    history[2],
    ['VIDEOJS:', 'WARN:', 'warn1', 'warn2'],
    'history recorded the correct arguments'
  );
  assert.deepEqual(
    history[3],
    ['VIDEOJS:', 'ERROR:', 'error1', 'error2'],
    'history recorded the correct arguments'
  );
});

QUnit.test('setting the log level changes what is actually logged', function(assert) {

  // Need to reset history here because there are extra messages logged
  // when running via Karma.
  log.history.clear();

  log.level('error');

  log('log1', 'log2');
  log.warn('warn1', 'warn2');
  log.error('error1', 'error2');

  assert.notOk(window.console.log.called, 'console.log was not called');
  assert.notOk(window.console.warn.called, 'console.warn was not called');
  assert.ok(window.console.error.called, 'console.error was called');

  const history = log.history();

  assert.deepEqual(history[0], ['VIDEOJS:', 'log1', 'log2'], 'history is maintained even when logging is not performed');
  assert.deepEqual(history[1], ['VIDEOJS:', 'WARN:', 'warn1', 'warn2'], 'history is maintained even when logging is not performed');
  assert.deepEqual(history[2], ['VIDEOJS:', 'ERROR:', 'error1', 'error2'], 'history is maintained even when logging is not performed');

  log.level('off');

  log('log1', 'log2');
  log.warn('warn1', 'warn2');
  log.error('error1', 'error2');

  assert.notOk(window.console.log.called, 'console.log was not called');
  assert.notOk(window.console.warn.called, 'console.warn was not called');
  assert.strictEqual(window.console.error.callCount, 1, 'console.error was not called again');

  assert.throws(
    () => log.level('foobar'),
    new Error('"foobar" in not a valid log level'),
    'log.level() only accepts valid log levels when used as a setter'
  );
});

QUnit.test('history can be enabled/disabled', function(assert) {

  // Need to reset history here because there are extra messages logged
  // when running via Karma.
  log.history.clear();

  log.history.disable();
  log('log1');
  log.warn('warn1');
  log.error('error1');

  let history = log.history();

  assert.strictEqual(history.length, 0, 'no history was tracked');

  log.history.enable();
  log('log1');
  log.warn('warn1');
  log.error('error1');

  history = log.history();

  assert.strictEqual(history.length, 3, 'history was tracked');
});

QUnit.test('supports debug logging', function(assert) {
  // Need to reset history here because there are extra messages logged
  // when running via Karma.
  log.history.clear();

  log.level('debug');

  log('log1', 'log2');
  log.debug('debug1', 'debug2');
  log.warn('warn1', 'warn2');
  log.error('error1', 'error2');

  assert.ok(window.console.log.called, 'console.log was called');
  assert.ok(window.console.debug.called, 'console.debug was called');
  assert.ok(window.console.warn.called, 'console.warn was called');
  assert.ok(window.console.error.called, 'console.error called');

  const history = log.history();

  assert.equal(history.length, 4, 'four messages in history');
  assert.deepEqual(history[0], ['VIDEOJS:', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[1], ['VIDEOJS:', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[2], ['VIDEOJS:', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[3], ['VIDEOJS:', 'ERROR:', 'error1', 'error2'], 'history is maintained');
});

QUnit.test('falls back to info and log when debug is not supported', function(assert) {
  // Need to reset history here because there are extra messages logged
  // when running via Karma.
  log.history.clear();

  log.level('debug');

  window.console.debug = null;
  log.debug('debug1', 'debug2');

  assert.ok(window.console.info.called, 'info was called');
  assert.notOk(window.console.log.called, 'log was not called');
  assert.notOk(window.console.warn.called, 'warn was not called');
  assert.notOk(window.console.error.called, 'error was not called');
  assert.deepEqual(
    window.console.info.firstCall.args,
    ['VIDEOJS:', 'DEBUG:', 'debug1', 'debug2'],
    'logged the right message'
  );

  window.console.info = null;
  log.debug('debug3', 'debug4');

  assert.ok(window.console.log.called, 'log was called');
  assert.notOk(window.console.warn.called, 'warn was not called');
  assert.notOk(window.console.error.called, 'error was not called');
  assert.deepEqual(
    window.console.log.firstCall.args,
    ['VIDEOJS:', 'DEBUG:', 'debug3', 'debug4'],
    'logged the right message'
  );

  // when no comparable level logs are available, there should not be any logging
  window.console.log = null;
  log.debug('debug5', 'debug6');

  assert.notOk(window.console.warn.called, 'warn was not called');
  assert.notOk(window.console.error.called, 'error was not called');
});

QUnit.test('history only retains 1000 items', function(assert) {
  // Need to reset history here because there are extra messages logged
  // when running via Karma.
  log.history.clear();

  for (let i = 1; i <= 1005; i++) {
    log(i);
  }

  const hist = log.history();

  assert.equal(hist.length, 1000, 'only 1000 items in history');
  assert.deepEqual([hist[0], hist[hist.length - 1 ]], [['VIDEOJS:', 6], ['VIDEOJS:', 1005]], 'keeps most recent items');
});

QUnit.test('create logger should create sub-logger with naming chain', function(assert) {
  log.history.clear();

  const subLogger = log.createLogger('SubModule');

  subLogger.level('debug');

  subLogger('log1', 'log2');
  subLogger.debug('debug1', 'debug2');
  subLogger.warn('warn1', 'warn2');
  subLogger.error('error1', 'error2');

  assert.ok(window.console.log.called, 'console.log was called');
  assert.ok(window.console.debug.called, 'console.debug was called');
  assert.ok(window.console.warn.called, 'console.warn was called');
  assert.ok(window.console.error.called, 'console.error called');

  const history = log.history();

  assert.equal(history.length, 4, 'four messages in history');
  assert.deepEqual(history[0], ['VIDEOJS : SubModule:', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[1], ['VIDEOJS : SubModule:', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[2], ['VIDEOJS : SubModule:', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[3], ['VIDEOJS : SubModule:', 'ERROR:', 'error1', 'error2'], 'history is maintained');
});

QUnit.test('create a new logger should override existing sub names', function(assert) {
  log.history.clear();

  const newLogger = log.createNewLogger('Module');

  newLogger.level('debug');

  newLogger('log1', 'log2');
  newLogger.debug('debug1', 'debug2');
  newLogger.warn('warn1', 'warn2');
  newLogger.error('error1', 'error2');

  assert.ok(window.console.log.called, 'console.log was called');
  assert.ok(window.console.debug.called, 'console.debug was called');
  assert.ok(window.console.warn.called, 'console.warn was called');
  assert.ok(window.console.error.called, 'console.error called');

  const history = log.history();

  assert.equal(history.length, 4, 'four messages in history');
  assert.deepEqual(history[0], ['Module:', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[1], ['Module:', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[2], ['Module:', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[3], ['Module:', 'ERROR:', 'error1', 'error2'], 'history is maintained');
});

QUnit.test('create logger applies delimiter and styles if presented', function(assert) {
  log.history.clear();

  const subLogger = log.createLogger('SubModule', '>', 'background: #333; padding: 3px; color: #bada55');

  subLogger.level('debug');

  subLogger('log1', 'log2');
  subLogger.debug('debug1', 'debug2');
  subLogger.warn('warn1', 'warn2');
  subLogger.error('error1', 'error2');

  assert.ok(window.console.log.called, 'console.log was called');
  assert.ok(window.console.debug.called, 'console.debug was called');
  assert.ok(window.console.warn.called, 'console.warn was called');
  assert.ok(window.console.error.called, 'console.error called');

  const history = log.history();

  assert.equal(history.length, 4, 'four messages in history');
  assert.deepEqual(history[0], ['%cVIDEOJS > SubModule:', 'background: #333; padding: 3px; color: #bada55', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[1], ['%cVIDEOJS > SubModule:', 'background: #333; padding: 3px; color: #bada55', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[2], ['%cVIDEOJS > SubModule:', 'background: #333; padding: 3px; color: #bada55', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[3], ['%cVIDEOJS > SubModule:', 'background: #333; padding: 3px; color: #bada55', 'ERROR:', 'error1', 'error2'], 'history is maintained');
});

QUnit.test('create new logger applies delimiter and styles if presented', function(assert) {
  log.history.clear();

  const newLogger = log.createNewLogger('Module', '>', 'background: #333; padding: 3px; color: #bada55');
  const subModule1 = newLogger.createLogger('SubModule1');
  const subModule2 = subModule1.createLogger('SubModule2', '->', '');

  newLogger.level('debug');

  newLogger('log1', 'log2');
  newLogger.debug('debug1', 'debug2');
  newLogger.warn('warn1', 'warn2');
  newLogger.error('error1', 'error2');

  subModule1('log1', 'log2');
  subModule1.debug('debug1', 'debug2');
  subModule1.warn('warn1', 'warn2');
  subModule1.error('error1', 'error2');

  subModule2('log1', 'log2');
  subModule2.debug('debug1', 'debug2');
  subModule2.warn('warn1', 'warn2');
  subModule2.error('error1', 'error2');

  assert.ok(window.console.log.called, 'console.log was called');
  assert.ok(window.console.debug.called, 'console.debug was called');
  assert.ok(window.console.warn.called, 'console.warn was called');
  assert.ok(window.console.error.called, 'console.error called');

  const history = log.history();

  assert.equal(history.length, 12, '12 messages in history');
  assert.deepEqual(history[0], ['%cModule:', 'background: #333; padding: 3px; color: #bada55', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[1], ['%cModule:', 'background: #333; padding: 3px; color: #bada55', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[2], ['%cModule:', 'background: #333; padding: 3px; color: #bada55', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[3], ['%cModule:', 'background: #333; padding: 3px; color: #bada55', 'ERROR:', 'error1', 'error2'], 'history is maintained');

  assert.deepEqual(history[4], ['%cModule > SubModule1:', 'background: #333; padding: 3px; color: #bada55', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[5], ['%cModule > SubModule1:', 'background: #333; padding: 3px; color: #bada55', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[6], ['%cModule > SubModule1:', 'background: #333; padding: 3px; color: #bada55', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[7], ['%cModule > SubModule1:', 'background: #333; padding: 3px; color: #bada55', 'ERROR:', 'error1', 'error2'], 'history is maintained');

  assert.deepEqual(history[8], ['Module > SubModule1 -> SubModule2:', 'log1', 'log2'], 'history is maintained');
  assert.deepEqual(history[9], ['Module > SubModule1 -> SubModule2:', 'DEBUG:', 'debug1', 'debug2'], 'history is maintained');
  assert.deepEqual(history[10], ['Module > SubModule1 -> SubModule2:', 'WARN:', 'warn1', 'warn2'], 'history is maintained');
  assert.deepEqual(history[11], ['Module > SubModule1 -> SubModule2:', 'ERROR:', 'error1', 'error2'], 'history is maintained');
});