[coverage] Conformance findings: LOGGING-002 (#494)

CHANGELOG.md

@@ -1,5 +1,10 @@
 # Release History
 
+## Unreleased
+
+- `DBSQLLogger`: a `filepath` naming an existing directory now writes to `databricks-sql-nodejs.log` inside it, instead of silently producing no logs. (#565)
+- `DBSQLLogger`: if the log file can't be opened (including when its directory can't be created, which used to throw from the constructor), the logger now logs to the console only, leaves `transports.file` undefined, and emits a process warning with code `DBSQL_LOG_FILE_UNAVAILABLE`. Previously an unwritable file could silently stall all logging, including the console. (#565)
+
 ## 3.0.0
 
 - Upgrade the native kernel backend to 1.4.0.

lib/DBSQLLogger.ts

@@ -1,6 +1,51 @@
+import fs from 'fs';
+import path from 'path';
 import winston, { Logger } from 'winston';
 import IDBSQLLogger, { LoggerOptions, LogLevel } from './contracts/IDBSQLLogger';
 
+const DEFAULT_LOG_FILE_NAME = 'databricks-sql-nodejs.log';
+
+export const LOG_FILE_UNAVAILABLE_WARNING_CODE = 'DBSQL_LOG_FILE_UNAVAILABLE';
+
+// An existing directory resolves to a default file inside it. Anything else is
+// returned as the path winston will open (which drops a trailing separator).
+function resolveLogFilePath(filepath: string): string {
+  try {
+    if (fs.statSync(filepath).isDirectory()) {
+      return path.join(filepath, DEFAULT_LOG_FILE_NAME);
+    }
+  } catch {
+    // doesn't exist or isn't accessible: treat it as a file path
+  }
+  return path.join(path.dirname(filepath), path.basename(filepath));
+}
+
+// winston's File transport only `debug`-logs errors opening its write stream
+// (EISDIR, EACCES, ...), and the logger then stalls for every transport once
+// its buffer fills. Its `stat` errors (e.g. ENOTDIR) are emitted instead and,
+// with no listener, crash the process. So probe the file once up front,
+// creating it and its directory as winston would. Later failures (e.g. disk
+// full) aren't covered. Paths that exist but aren't regular files or
+// directories are left to winston: opening a FIFO blocks until it has a reader.
+function checkLogFileWritable(filename: string): Error | undefined {
+  try {
+    const stat = fs.statSync(filename, { throwIfNoEntry: false });
+    if (stat && !stat.isFile() && !stat.isDirectory()) {
+      return undefined;
+    }
+    const dir = path.dirname(filename);
+    // Like winston, only create a missing directory: on Windows, mkdir of a
+    // drive root throws EPERM even with `recursive`.
+    if (!fs.existsSync(dir)) {
+      fs.mkdirSync(dir, { recursive: true });
+    }
+    fs.closeSync(fs.openSync(filename, 'a'));
+    return undefined;
+  } catch (error) {
+    return error instanceof Error ? error : new Error(String(error));
+  }
+}
+
 export default class DBSQLLogger implements IDBSQLLogger {
   logger: Logger;
 
@@ -21,8 +66,16 @@ export default class DBSQLLogger implements IDBSQLLogger {
       transports: [this.transports.console],
     });
     if (filepath) {
-      this.transports.file = new winston.transports.File({ filename: filepath, handleExceptions: true, level });
-      this.logger.add(this.transports.file);
+      const filename = resolveLogFilePath(filepath);
+      const error = checkLogFileWritable(filename);
+      if (error) {
+        process.emitWarning(`Cannot write to log file ${filename}, logging to console only: ${error.message}`, {
+          code: LOG_FILE_UNAVAILABLE_WARNING_CODE,
+        });
+      } else {
+        this.transports.file = new winston.transports.File({ filename, handleExceptions: true, level });
+        this.logger.add(this.transports.file);
+      }
     }
   }
 

lib/contracts/IDBSQLLogger.ts

@@ -1,4 +1,11 @@
 export interface LoggerOptions {
+  /**
+   * Optional: a log file to write to, in addition to the console. If it names an
+   * existing directory, logs go to `databricks-sql-nodejs.log` inside it. If the
+   * file can't be opened for writing, the logger logs to the console only
+   * (`DBSQLLogger.transports.file` stays undefined) and emits a process warning
+   * with code `DBSQL_LOG_FILE_UNAVAILABLE`.
+   */
   filepath?: string;
   level?: LogLevel;
 }

tests/unit/DBSQLLogger.test.ts

@@ -12,10 +12,28 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+import { execFileSync } from 'child_process';
+import fs from 'fs';
+import os from 'os';
+import path from 'path';
 import { expect } from 'chai';
-import DBSQLLogger from '../../lib/DBSQLLogger';
+import sinon from 'sinon';
+import winston from 'winston';
+import DBSQLLogger, { LOG_FILE_UNAVAILABLE_WARNING_CODE } from '../../lib/DBSQLLogger';
 import { LogLevel } from '../../lib/contracts/IDBSQLLogger';
 
+async function waitForFileContent(file: string, text: string, timeoutMs = 2000): Promise<string> {
+  const deadline = Date.now() + timeoutMs;
+  const read = () => (fs.existsSync(file) ? fs.readFileSync(file, 'utf8') : '');
+  while (!read().includes(text) && Date.now() < deadline) {
+    // eslint-disable-next-line no-await-in-loop
+    await new Promise((resolve) => {
+      setTimeout(resolve, 20);
+    });
+  }
+  return read();
+}
+
 describe('DBSQLLogger level subscription', () => {
   it('getLevel reflects the configured level', () => {
     const logger = new DBSQLLogger({ level: LogLevel.warn });
@@ -60,3 +78,216 @@ describe('DBSQLLogger level subscription', () => {
     expect(logger.getLevel()).to.equal(LogLevel.debug);
   });
 });
+
+describe('DBSQLLogger file transport path resolution', () => {
+  let tmpDir: string;
+  let logger: DBSQLLogger | undefined;
+  let fileSettled: Promise<void> | undefined;
+
+  // The File transport opens its stream asynchronously; teardown waits for that
+  // before closing the logger and deleting the directory.
+  function createLogger(filepath: string, level?: LogLevel): DBSQLLogger {
+    const instance = new DBSQLLogger({ filepath, level });
+    const file = instance.transports.file;
+    fileSettled = file
+      ? new Promise<void>((resolve) => {
+          file.once('open', () => resolve());
+          file.once('error', () => resolve());
+        })
+      : undefined;
+    return instance;
+  }
+
+  beforeEach(() => {
+    tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'dbsql-logger-'));
+  });
+
+  afterEach(async () => {
+    if (fileSettled) {
+      await fileSettled;
+    }
+    logger?.logger.close();
+    logger = undefined;
+    fileSettled = undefined;
+    fs.rmSync(tmpDir, { recursive: true, force: true });
+  });
+
+  it('writes to a default file inside the directory when filepath is an existing directory', () => {
+    logger = createLogger(tmpDir);
+
+    expect(logger.transports.file).to.not.be.undefined;
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('databricks-sql-nodejs.log');
+  });
+
+  it('writes log lines to the default file inside the directory', async () => {
+    logger = createLogger(tmpDir);
+    logger.transports.console.silent = true;
+
+    await logger.log(LogLevel.info, 'hello from DBSQLLogger test');
+
+    const content = await waitForFileContent(path.join(tmpDir, 'databricks-sql-nodejs.log'), 'hello from');
+    expect(content).to.contain('hello from DBSQLLogger test');
+  });
+
+  it('resolves an existing directory with a trailing separator to the default file inside it', () => {
+    logger = createLogger(`${tmpDir}${path.sep}`);
+
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('databricks-sql-nodejs.log');
+  });
+
+  it('keeps writing to an existing file when filepath has a trailing separator', () => {
+    const filepath = path.join(tmpDir, 'logs');
+    fs.writeFileSync(filepath, '');
+    logger = createLogger(`${filepath}${path.sep}`);
+
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('logs');
+  });
+
+  it('treats a non-existent filepath with a trailing separator as a file, as in 3.0.0', () => {
+    const filepath = path.join(tmpDir, 'logs');
+    logger = createLogger(`${filepath}${path.sep}`);
+
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('logs');
+    expect(fs.statSync(filepath).isFile()).to.be.true;
+  });
+
+  it('does not open a FIFO synchronously', async function fifoTest() {
+    if (process.platform === 'win32') {
+      this.skip();
+    }
+    const fifo = path.join(tmpDir, 'pipe.log');
+    execFileSync('mkfifo', [fifo]);
+    // A non-blocking reader lets any writer open the FIFO without waiting. Keep
+    // it open until winston's own open completes, or that open (and the test
+    // process) would hang.
+    const readerFd = fs.openSync(fifo, fs.constants.O_RDONLY | fs.constants.O_NONBLOCK);
+    const openSync = sinon.spy(fs, 'openSync');
+    try {
+      logger = createLogger(fifo);
+    } finally {
+      openSync.restore();
+    }
+    await fileSettled;
+    fs.closeSync(readerFd);
+
+    expect(openSync.called).to.be.false;
+    expect(logger.transports.file?.filename).to.equal('pipe.log');
+  });
+
+  describe('when the log file cannot be opened', () => {
+    let emitWarning: sinon.SinonStub;
+
+    beforeEach(() => {
+      emitWarning = sinon.stub(process, 'emitWarning');
+    });
+
+    afterEach(() => {
+      emitWarning.restore();
+    });
+
+    const cases = [
+      {
+        name: 'a parent path is a regular file',
+        filepath: (dir: string) => {
+          fs.writeFileSync(path.join(dir, 'not-a-dir'), '');
+          return path.join(dir, 'not-a-dir', 'driver.log');
+        },
+      },
+      {
+        name: 'the resolved log file is a directory (EISDIR)',
+        filepath: (dir: string) => {
+          fs.mkdirSync(path.join(dir, 'databricks-sql-nodejs.log'));
+          return dir;
+        },
+      },
+    ];
+
+    for (const { name, filepath } of cases) {
+      it(`falls back to console only with a process warning when ${name}`, () => {
+        logger = createLogger(filepath(tmpDir), LogLevel.error);
+
+        expect(logger.transports.file).to.be.undefined;
+        expect(emitWarning.calledOnce).to.be.true;
+        expect(emitWarning.firstCall.args[0]).to.contain('logging to console only');
+        expect(emitWarning.firstCall.args[1]).to.deep.equal({ code: LOG_FILE_UNAVAILABLE_WARNING_CODE });
+      });
+    }
+
+    it('keeps delivering console logs after the fallback', async () => {
+      fs.mkdirSync(path.join(tmpDir, 'databricks-sql-nodejs.log'));
+      const seen: string[] = [];
+      const consoleLog = sinon.stub(winston.transports.Console.prototype, 'log').callsFake((...args: unknown[]) => {
+        seen.push((args[0] as { message: string }).message);
+        (args[1] as () => void)();
+      });
+      try {
+        logger = createLogger(tmpDir);
+        // Far more than the logger's stream buffers hold; an unopened file
+        // transport used to stall delivery to every transport at that point.
+        const lines = 1000;
+        for (let i = 0; i < lines; i += 1) {
+          logger.logger.info(`line ${i} ${'x'.repeat(100)}`);
+        }
+        const deadline = Date.now() + 1500;
+        while (seen.length < lines && Date.now() < deadline) {
+          // eslint-disable-next-line no-await-in-loop
+          await new Promise((resolve) => {
+            setTimeout(resolve, 20);
+          });
+        }
+
+        expect(seen).to.have.length(lines);
+        expect(seen[lines - 1]).to.match(new RegExp(`^line ${lines - 1} `));
+      } finally {
+        consoleLog.restore();
+      }
+    });
+  });
+
+  it('uses a non-existent filepath unchanged', () => {
+    const filepath = path.join(tmpDir, 'custom.log');
+    logger = createLogger(filepath);
+
+    expect(logger.transports.file).to.not.be.undefined;
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('custom.log');
+  });
+
+  it('creates missing parent directories and still attaches the file transport', () => {
+    const nestedDir = path.join(tmpDir, 'a', 'b');
+    const filepath = path.join(nestedDir, 'driver.log');
+    logger = createLogger(filepath);
+
+    expect(logger.transports.file).to.not.be.undefined;
+    expect(logger.transports.file?.dirname).to.equal(nestedDir);
+    expect(logger.transports.file?.filename).to.equal('driver.log');
+    expect(fs.statSync(nestedDir).isDirectory()).to.be.true;
+    expect(fs.existsSync(filepath)).to.be.true;
+  });
+
+  it('does not mkdir an existing directory (mkdir of a Windows drive root throws EPERM)', () => {
+    const mkdirSync = sinon.stub(fs, 'mkdirSync').throws(Object.assign(new Error('EPERM'), { code: 'EPERM' }));
+    try {
+      logger = createLogger(path.join(tmpDir, 'driver.log'));
+    } finally {
+      mkdirSync.restore();
+    }
+
+    expect(mkdirSync.called).to.be.false;
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('driver.log');
+  });
+
+  it('uses an existing file path unchanged', () => {
+    const filepath = path.join(tmpDir, 'existing.log');
+    fs.writeFileSync(filepath, '');
+    logger = createLogger(filepath);
+
+    expect(logger.transports.file?.dirname).to.equal(tmpDir);
+    expect(logger.transports.file?.filename).to.equal('existing.log');
+  });
+});