[node-tracing] Replace winston with a small built-in logger

Author: romainneutron

package.json

@@ -25,8 +25,7 @@
   "author": "blackfire.io",
   "license": "MIT",
   "dependencies": {
-    "dd-trace": "^5.92.0",
-    "winston": "^3.9.0"
+    "dd-trace": "^5.92.0"
   },
   "devDependencies": {
     "@stylistic/eslint-plugin": "^2.9.0",

src/index.js

@@ -1,32 +1,9 @@
 const os = require('os');
-const winston = require('winston');
 const ddtrace = require('dd-trace');
+const { createLogger } = require('./logger');
 const { version } = require('../package.json');
 
-const DEFAULT_LOG_LEVEL = 1;
-const logLevels = {
-  4: 'debug',
-  3: 'info',
-  2: 'warn',
-  1: 'error',
-};
-
-// initialize logger
-const logger = winston.createLogger({
-  format: winston.format.combine(
-    winston.format.timestamp(),
-    winston.format.splat(),
-    winston.format.simple(),
-  ),
-  level: logLevels[process.env.BLACKFIRE_LOG_LEVEL || DEFAULT_LOG_LEVEL],
-});
-
-const logFile = process.env.BLACKFIRE_LOG_FILE;
-if (logFile && logFile !== 'stderr') {
-  logger.add(new winston.transports.File({ filename: logFile }));
-} else {
-  logger.add(new winston.transports.Console());
-}
+const logger = createLogger();
 
 const currentProfilingSession = {
   stop: undefined,

src/logger.js

@@ -0,0 +1,58 @@
+const fs = require('fs');
+const util = require('util');
+
+const DEFAULT_LOG_LEVEL = 1;
+const LOG_LEVELS = {
+  4: 'debug',
+  3: 'info',
+  2: 'warn',
+  1: 'error',
+};
+
+function createLogger(env = process.env) {
+  const requested = Number(env.BLACKFIRE_LOG_LEVEL);
+  // Clamp to a known level so the gate and the `level` string always agree, even for '0'/'5'/'foo'.
+  const numericLevel = requested in LOG_LEVELS ? requested : DEFAULT_LOG_LEVEL;
+  const level = LOG_LEVELS[numericLevel];
+
+  const logFile = env.BLACKFIRE_LOG_FILE;
+
+  let stream = null;
+  if (logFile && logFile !== 'stderr') {
+    // A bad BLACKFIRE_LOG_FILE must never crash the host app: warn once, then fall back to stderr.
+    const degradeToStderr = (err) => {
+      stream = null;
+      process.stderr.write(`blackfire: cannot write log file ${logFile}, falling back to stderr: ${err.message}\n`);
+    };
+    try {
+      // Open synchronously so a bad path fails fast and loses no early lines; writes stay non-blocking.
+      stream = fs.createWriteStream(logFile, { fd: fs.openSync(logFile, 'a') });
+      stream.on('error', degradeToStderr);
+    } catch (err) {
+      degradeToStderr(err);
+    }
+  }
+
+  const write = (line) => {
+    if (stream) {
+      stream.write(`${line}\n`);
+    } else {
+      process.stderr.write(`${line}\n`);
+    }
+  };
+
+  const log = (severity, name, message, args) => {
+    if (severity > numericLevel) return;
+    write(`${new Date().toISOString()} ${name}: ${util.format(message, ...args)}`);
+  };
+
+  return {
+    level,
+    error: (message, ...args) => log(1, 'error', message, args),
+    warn: (message, ...args) => log(2, 'warn', message, args),
+    info: (message, ...args) => log(3, 'info', message, args),
+    debug: (message, ...args) => log(4, 'debug', message, args),
+  };
+}
+
+module.exports = { createLogger };

tests/logger.test.js

@@ -0,0 +1,126 @@
+const fs = require('fs');
+const os = require('os');
+const path = require('path');
+const { EventEmitter } = require('events');
+const { createLogger } = require('../src/logger');
+
+let stderr;
+
+beforeEach(() => {
+  stderr = jest.spyOn(process.stderr, 'write').mockImplementation(() => true);
+});
+
+afterEach(() => {
+  jest.restoreAllMocks();
+});
+
+describe('level resolution and gating', () => {
+  test('defaults to error when BLACKFIRE_LOG_LEVEL is unset', () => {
+    const logger = createLogger({});
+    expect(logger.level).toBe('error');
+
+    logger.debug('d');
+    logger.info('i');
+    logger.warn('w');
+    expect(stderr).not.toHaveBeenCalled();
+
+    logger.error('e');
+    expect(stderr).toHaveBeenCalledTimes(1);
+  });
+
+  test('level 4 yields debug and emits every level', () => {
+    const logger = createLogger({ BLACKFIRE_LOG_LEVEL: '4' });
+    expect(logger.level).toBe('debug');
+
+    logger.debug('d');
+    logger.info('i');
+    logger.warn('w');
+    logger.error('e');
+    expect(stderr).toHaveBeenCalledTimes(4);
+  });
+
+  // Invalid/out-of-range values clamp to error so the gate and the `level` string stay consistent.
+  test.each(['0', '5', 'foo'])('level %s clamps to error and emits only error', (value) => {
+    const logger = createLogger({ BLACKFIRE_LOG_LEVEL: value });
+    expect(logger.level).toBe('error');
+
+    logger.debug('d');
+    logger.warn('w');
+    expect(stderr).not.toHaveBeenCalled();
+
+    logger.error('e');
+    expect(stderr).toHaveBeenCalledTimes(1);
+  });
+});
+
+test('interpolates printf-style placeholders', () => {
+  const logger = createLogger({});
+  logger.error('hi %s', 'there');
+
+  const line = stderr.mock.calls[0][0];
+  expect(line).toContain('error: hi there');
+});
+
+describe('sink selection', () => {
+  test('writes to stderr when BLACKFIRE_LOG_FILE is "stderr"', () => {
+    const logger = createLogger({ BLACKFIRE_LOG_FILE: 'stderr' });
+    logger.error('e');
+    expect(stderr).toHaveBeenCalledTimes(1);
+  });
+
+  test('writes formatted lines to the configured log file with a timestamp', (done) => {
+    const logFile = path.join(os.tmpdir(), `blackfire-logger-${process.pid}-${process.hrtime.bigint()}.log`);
+    const realCreate = fs.createWriteStream;
+    let stream;
+    jest.spyOn(fs, 'createWriteStream').mockImplementation((file, opts) => {
+      stream = realCreate(file, opts);
+      return stream;
+    });
+
+    const logger = createLogger({ BLACKFIRE_LOG_FILE: logFile });
+    logger.error('to file %s', 'here');
+
+    // end() flushes the buffered write before we read the file back.
+    stream.end(() => {
+      const contents = fs.readFileSync(logFile, 'utf8');
+      expect(contents).toContain('error: to file here');
+      expect(contents).toMatch(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}/);
+      expect(stderr).not.toHaveBeenCalled();
+      fs.rmSync(logFile, { force: true });
+      done();
+    });
+  });
+
+  test('falls back to stderr and warns once when the log file cannot be opened', () => {
+    // openSync throws synchronously on a bad path, so no early lines are buffered into a dead stream.
+    jest.spyOn(fs, 'openSync').mockImplementation(() => {
+      throw new Error('EACCES');
+    });
+
+    const logger = createLogger({ BLACKFIRE_LOG_FILE: '/nope/blackfire.log' });
+    expect(stderr).toHaveBeenCalledTimes(1);
+    expect(stderr.mock.calls[0][0]).toContain('cannot write log file /nope/blackfire.log');
+
+    // Subsequent logs route to stderr instead of the dead stream.
+    logger.error('after failure');
+    expect(stderr).toHaveBeenCalledTimes(2);
+    expect(stderr.mock.calls[1][0]).toContain('error: after failure');
+  });
+
+  test('falls back to stderr if the stream errors after opening', () => {
+    jest.spyOn(fs, 'openSync').mockReturnValue(123);
+    const stream = new EventEmitter();
+    stream.write = jest.fn();
+    jest.spyOn(fs, 'createWriteStream').mockReturnValue(stream);
+
+    const logger = createLogger({ BLACKFIRE_LOG_FILE: '/some/blackfire.log' });
+    stream.emit('error', new Error('ENOSPC'));
+
+    expect(stderr).toHaveBeenCalledTimes(1);
+    expect(stderr.mock.calls[0][0]).toContain('cannot write log file /some/blackfire.log');
+
+    logger.error('after failure');
+    expect(stderr).toHaveBeenCalledTimes(2);
+    expect(stderr.mock.calls[1][0]).toContain('error: after failure');
+  });
+});