diff --git a/CHANGELOG.md b/CHANGELOG.md index d3f3dc8b..a53cb9c6 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/lib/DBSQLLogger.ts b/lib/DBSQLLogger.ts index 3d298b9b..02dff91a 100644 --- a/lib/DBSQLLogger.ts +++ b/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); + } } } diff --git a/lib/contracts/IDBSQLLogger.ts b/lib/contracts/IDBSQLLogger.ts index cbf73b6b..cc3291c2 100644 --- a/lib/contracts/IDBSQLLogger.ts +++ b/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; } diff --git a/tests/unit/DBSQLLogger.test.ts b/tests/unit/DBSQLLogger.test.ts index 05cb60b6..d6f39a64 100644 --- a/tests/unit/DBSQLLogger.test.ts +++ b/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 { + 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 | 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((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'); + }); +});