Skip to content

Commit 2ccff19

Browse files
peco-engineer-bot[bot]peco-engineer-bot[bot]vuanhphungIsaac
authored
[coverage] Conformance findings: LOGGING-002 (#494) (#565)
* [coverage] Conformance findings: LOGGING-002 (#494) Signed-off-by: peco-engineer-bot[bot] <3815206+peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (1 review thread) Addresses: - #4476824300 at lib/DBSQLLogger.ts:11 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (3 review threads) Addresses: - #4476845245 at tests/unit/DBSQLLogger.test.ts:76 - #4476845255 at lib/DBSQLLogger.ts:13 - #4476845259 at lib/DBSQLLogger.ts:7 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (1 review thread) Addresses: - #4476880210 at tests/e2e/logging.test.ts:23 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * Fall back to console when the log file can't be opened Drop the trailing-separator rule. On an existing file (which is what `filepath: 'logs/'` created in 3.0.0) it resolved to a path under a regular file and crashed the process with ENOTDIR. A trailing separator now behaves as in 3.0.0 unless the path is an existing directory. winston's File transport swallows stream open errors and then stalls every transport, so check the file is writable before adding it, and otherwise warn and log to the console only. Replace the live-warehouse e2e spec with unit tests that read the log file back and cover both cases. Co-authored-by: Isaac <no-reply@databricks.com> Signed-off-by: Vu Anh Phung <vu.phung@databricks.com> * ai: apply changes for #565 (2 review threads) Addresses: - #4477535158 at lib/DBSQLLogger.ts:57 - #4477535166 at lib/DBSQLLogger.ts:26 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (2 review threads) Addresses: - #4477563176 at lib/DBSQLLogger.ts:61 - #4477563184 at lib/DBSQLLogger.ts:29 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (1 review thread) Addresses: - #4477590259 at lib/DBSQLLogger.ts:64 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (1 review thread) Addresses: - #4477606208 at lib/DBSQLLogger.ts:29 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * ai: apply changes for #565 (2 review threads) Addresses: - #4477606208 at lib/DBSQLLogger.ts:34 - #4477625054 at tests/unit/DBSQLLogger.test.ts:157 Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> * Report log file fallback via process warning; don't probe FIFOs - Emit the console-only fallback with process.emitWarning (code DBSQL_LOG_FILE_UNAVAILABLE) instead of an error-level log line, so it doesn't trip error alerting and is visible at any logger level. - Only probe regular files and directories (and missing paths). openSync on a FIFO blocked the constructor until a reader appeared. - Correct the probe comment: winston emits stat errors (ENOTDIR) and only swallows stream open errors, so a runtime error handler on the File transport wouldn't help. Drop that follow-up note. - Test the EISDIR open failure, console delivery after the fallback (the stall), the non-existent trailing-separator path, and the FIFO. - Add an Unreleased CHANGELOG section. Co-authored-by: Isaac <no-reply@databricks.com> Signed-off-by: Vu Anh Phung <vu.phung@databricks.com> * Only mkdir a missing log directory, like winston On Windows, mkdirSync of a drive root throws EPERM even with `recursive`, so `filepath: 'D:\\dbsql.log'` (which worked in 3.0.0) fell back to console only. Guard with existsSync as winston's File transport does; real permission problems still fail at openSync. Co-authored-by: Isaac <no-reply@databricks.com> Signed-off-by: Vu Anh Phung <vu.phung@databricks.com> * Export logger warning code and test read-only log files Signed-off-by: Vu Anh Phung <vu.phung@databricks.com> --------- Signed-off-by: peco-engineer-bot[bot] <3815206+peco-engineer-bot[bot]@users.noreply.github.com> Signed-off-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> Signed-off-by: Vu Anh Phung <vu.phung@databricks.com> Co-authored-by: peco-engineer-bot[bot] <3815206+peco-engineer-bot[bot]@users.noreply.github.com> Co-authored-by: peco-engineer-bot[bot] <peco-engineer-bot[bot]@users.noreply.github.com> Co-authored-by: Vu Anh Phung <vu.phung@databricks.com> Co-authored-by: Isaac <no-reply@databricks.com>
1 parent 418db1d commit 2ccff19

5 files changed

Lines changed: 317 additions & 3 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,8 @@
44

55
- Report untyped NULL columns as STRING in kernel result metadata, matching Thrift. (#470)
66
- Reject non-scalar query parameter values at bind time with a `ParameterError` on both the Thrift and kernel backends, instead of stringifying them (which could leave a Thrift operation stuck before FINISHED). Newly rejected on the Thrift backend: arrays, plain objects, boxed primitives (e.g. `new String('x')`, `new Number(1)`), functions, symbols, and a `DBSQLParameter` that wraps another `DBSQLParameter`. Primitives, `Date`, `Int64`, and `DBSQLParameter` are still accepted.
7+
- `DBSQLLogger`: a `filepath` naming an existing directory now writes to `databricks-sql-nodejs.log` inside it, instead of silently producing no logs. (#565)
8+
- `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)
79

810
## 3.0.0
911

‎lib/DBSQLLogger.ts‎

Lines changed: 55 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,51 @@
1+
import fs from 'fs';
2+
import path from 'path';
13
import winston, { Logger } from 'winston';
24
import IDBSQLLogger, { LoggerOptions, LogLevel } from './contracts/IDBSQLLogger';
35

6+
const DEFAULT_LOG_FILE_NAME = 'databricks-sql-nodejs.log';
7+
8+
export const LOG_FILE_UNAVAILABLE_WARNING_CODE = 'DBSQL_LOG_FILE_UNAVAILABLE';
9+
10+
// An existing directory resolves to a default file inside it. Anything else is
11+
// returned as the path winston will open (which drops a trailing separator).
12+
function resolveLogFilePath(filepath: string): string {
13+
try {
14+
if (fs.statSync(filepath).isDirectory()) {
15+
return path.join(filepath, DEFAULT_LOG_FILE_NAME);
16+
}
17+
} catch {
18+
// doesn't exist or isn't accessible: treat it as a file path
19+
}
20+
return path.join(path.dirname(filepath), path.basename(filepath));
21+
}
22+
23+
// winston's File transport only `debug`-logs errors opening its write stream
24+
// (EISDIR, EACCES, ...), and the logger then stalls for every transport once
25+
// its buffer fills. Its `stat` errors (e.g. ENOTDIR) are emitted instead and,
26+
// with no listener, crash the process. So probe the file once up front,
27+
// creating it and its directory as winston would. Later failures (e.g. disk
28+
// full) aren't covered. Paths that exist but aren't regular files or
29+
// directories are left to winston: opening a FIFO blocks until it has a reader.
30+
function checkLogFileWritable(filename: string): Error | undefined {
31+
try {
32+
const stat = fs.statSync(filename, { throwIfNoEntry: false });
33+
if (stat && !stat.isFile() && !stat.isDirectory()) {
34+
return undefined;
35+
}
36+
const dir = path.dirname(filename);
37+
// Like winston, only create a missing directory: on Windows, mkdir of a
38+
// drive root throws EPERM even with `recursive`.
39+
if (!fs.existsSync(dir)) {
40+
fs.mkdirSync(dir, { recursive: true });
41+
}
42+
fs.closeSync(fs.openSync(filename, 'a'));
43+
return undefined;
44+
} catch (error) {
45+
return error instanceof Error ? error : new Error(String(error));
46+
}
47+
}
48+
449
export default class DBSQLLogger implements IDBSQLLogger {
550
logger: Logger;
651

@@ -21,8 +66,16 @@ export default class DBSQLLogger implements IDBSQLLogger {
2166
transports: [this.transports.console],
2267
});
2368
if (filepath) {
24-
this.transports.file = new winston.transports.File({ filename: filepath, handleExceptions: true, level });
25-
this.logger.add(this.transports.file);
69+
const filename = resolveLogFilePath(filepath);
70+
const error = checkLogFileWritable(filename);
71+
if (error) {
72+
process.emitWarning(`Cannot write to log file ${filename}, logging to console only: ${error.message}`, {
73+
code: LOG_FILE_UNAVAILABLE_WARNING_CODE,
74+
});
75+
} else {
76+
this.transports.file = new winston.transports.File({ filename, handleExceptions: true, level });
77+
this.logger.add(this.transports.file);
78+
}
2679
}
2780
}
2881

‎lib/contracts/IDBSQLLogger.ts‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,11 @@
11
export interface LoggerOptions {
2+
/**
3+
* Optional: a log file to write to, in addition to the console. If it names an
4+
* existing directory, logs go to `databricks-sql-nodejs.log` inside it. If the
5+
* file can't be opened for writing, the logger logs to the console only
6+
* (`DBSQLLogger.transports.file` stays undefined) and emits a process warning
7+
* with code `DBSQL_LOG_FILE_UNAVAILABLE`.
8+
*/
29
filepath?: string;
310
level?: LogLevel;
411
}

‎lib/index.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ import { LogLevel } from './contracts/IDBSQLLogger';
2323
// Re-export types for TypeScript users
2424
export type { default as ITokenProvider } from './connection/auth/tokenProvider/ITokenProvider';
2525

26+
export { LOG_FILE_UNAVAILABLE_WARNING_CODE } from './DBSQLLogger';
2627
export { CircuitBreakerOpenError, CIRCUIT_BREAKER_OPEN_CODE } from './telemetry/CircuitBreaker';
2728
export { TelemetryTerminalError } from './telemetry/DatabricksTelemetryExporter';
2829

‎tests/unit/DBSQLLogger.test.ts‎

Lines changed: 252 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -12,10 +12,28 @@
1212
// See the License for the specific language governing permissions and
1313
// limitations under the License.
1414

15+
import { execFileSync } from 'child_process';
16+
import fs from 'fs';
17+
import os from 'os';
18+
import path from 'path';
1519
import { expect } from 'chai';
16-
import DBSQLLogger from '../../lib/DBSQLLogger';
20+
import sinon from 'sinon';
21+
import winston from 'winston';
22+
import DBSQLLogger, { LOG_FILE_UNAVAILABLE_WARNING_CODE } from '../../lib/DBSQLLogger';
1723
import { LogLevel } from '../../lib/contracts/IDBSQLLogger';
1824

25+
async function waitForFileContent(file: string, text: string, timeoutMs = 2000): Promise<string> {
26+
const deadline = Date.now() + timeoutMs;
27+
const read = () => (fs.existsSync(file) ? fs.readFileSync(file, 'utf8') : '');
28+
while (!read().includes(text) && Date.now() < deadline) {
29+
// eslint-disable-next-line no-await-in-loop
30+
await new Promise((resolve) => {
31+
setTimeout(resolve, 20);
32+
});
33+
}
34+
return read();
35+
}
36+
1937
describe('DBSQLLogger level subscription', () => {
2038
it('getLevel reflects the configured level', () => {
2139
const logger = new DBSQLLogger({ level: LogLevel.warn });
@@ -60,3 +78,236 @@ describe('DBSQLLogger level subscription', () => {
6078
expect(logger.getLevel()).to.equal(LogLevel.debug);
6179
});
6280
});
81+
82+
describe('DBSQLLogger file transport path resolution', () => {
83+
let tmpDir: string;
84+
let logger: DBSQLLogger | undefined;
85+
let fileSettled: Promise<void> | undefined;
86+
87+
// The File transport opens its stream asynchronously; teardown waits for that
88+
// before closing the logger and deleting the directory.
89+
function createLogger(filepath: string, level?: LogLevel): DBSQLLogger {
90+
const instance = new DBSQLLogger({ filepath, level });
91+
const file = instance.transports.file;
92+
fileSettled = file
93+
? new Promise<void>((resolve) => {
94+
file.once('open', () => resolve());
95+
file.once('error', () => resolve());
96+
})
97+
: undefined;
98+
return instance;
99+
}
100+
101+
beforeEach(() => {
102+
tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'dbsql-logger-'));
103+
});
104+
105+
afterEach(async () => {
106+
if (fileSettled) {
107+
await fileSettled;
108+
}
109+
logger?.logger.close();
110+
logger = undefined;
111+
fileSettled = undefined;
112+
fs.rmSync(tmpDir, { recursive: true, force: true });
113+
});
114+
115+
it('writes to a default file inside the directory when filepath is an existing directory', () => {
116+
logger = createLogger(tmpDir);
117+
118+
expect(logger.transports.file).to.not.be.undefined;
119+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
120+
expect(logger.transports.file?.filename).to.equal('databricks-sql-nodejs.log');
121+
});
122+
123+
it('writes log lines to the default file inside the directory', async () => {
124+
logger = createLogger(tmpDir);
125+
logger.transports.console.silent = true;
126+
127+
await logger.log(LogLevel.info, 'hello from DBSQLLogger test');
128+
129+
const content = await waitForFileContent(path.join(tmpDir, 'databricks-sql-nodejs.log'), 'hello from');
130+
expect(content).to.contain('hello from DBSQLLogger test');
131+
});
132+
133+
it('resolves an existing directory with a trailing separator to the default file inside it', () => {
134+
logger = createLogger(`${tmpDir}${path.sep}`);
135+
136+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
137+
expect(logger.transports.file?.filename).to.equal('databricks-sql-nodejs.log');
138+
});
139+
140+
it('keeps writing to an existing file when filepath has a trailing separator', () => {
141+
const filepath = path.join(tmpDir, 'logs');
142+
fs.writeFileSync(filepath, '');
143+
logger = createLogger(`${filepath}${path.sep}`);
144+
145+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
146+
expect(logger.transports.file?.filename).to.equal('logs');
147+
});
148+
149+
it('treats a non-existent filepath with a trailing separator as a file, as in 3.0.0', () => {
150+
const filepath = path.join(tmpDir, 'logs');
151+
logger = createLogger(`${filepath}${path.sep}`);
152+
153+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
154+
expect(logger.transports.file?.filename).to.equal('logs');
155+
expect(fs.statSync(filepath).isFile()).to.be.true;
156+
});
157+
158+
it('does not open a FIFO synchronously', async function fifoTest() {
159+
if (process.platform === 'win32') {
160+
this.skip();
161+
}
162+
const fifo = path.join(tmpDir, 'pipe.log');
163+
execFileSync('mkfifo', [fifo]);
164+
// A non-blocking reader lets any writer open the FIFO without waiting. Keep
165+
// it open until winston's own open completes, or that open (and the test
166+
// process) would hang.
167+
const readerFd = fs.openSync(fifo, fs.constants.O_RDONLY | fs.constants.O_NONBLOCK);
168+
const openSync = sinon.spy(fs, 'openSync');
169+
try {
170+
logger = createLogger(fifo);
171+
} finally {
172+
openSync.restore();
173+
}
174+
await fileSettled;
175+
fs.closeSync(readerFd);
176+
177+
expect(openSync.called).to.be.false;
178+
expect(logger.transports.file?.filename).to.equal('pipe.log');
179+
});
180+
181+
describe('when the log file cannot be opened', () => {
182+
let emitWarning: sinon.SinonStub;
183+
184+
beforeEach(() => {
185+
emitWarning = sinon.stub(process, 'emitWarning');
186+
});
187+
188+
afterEach(() => {
189+
emitWarning.restore();
190+
});
191+
192+
const cases = [
193+
{
194+
name: 'a parent path is a regular file',
195+
filepath: (dir: string) => {
196+
fs.writeFileSync(path.join(dir, 'not-a-dir'), '');
197+
return path.join(dir, 'not-a-dir', 'driver.log');
198+
},
199+
},
200+
{
201+
name: 'the resolved log file is a directory (EISDIR)',
202+
filepath: (dir: string) => {
203+
fs.mkdirSync(path.join(dir, 'databricks-sql-nodejs.log'));
204+
return dir;
205+
},
206+
},
207+
];
208+
209+
for (const { name, filepath } of cases) {
210+
it(`falls back to console only with a process warning when ${name}`, () => {
211+
logger = createLogger(filepath(tmpDir), LogLevel.error);
212+
213+
expect(logger.transports.file).to.be.undefined;
214+
expect(emitWarning.calledOnce).to.be.true;
215+
expect(emitWarning.firstCall.args[0]).to.contain('logging to console only');
216+
expect(emitWarning.firstCall.args[1]).to.deep.equal({ code: LOG_FILE_UNAVAILABLE_WARNING_CODE });
217+
});
218+
}
219+
220+
it('falls back to console only for a read-only log file (EACCES)', function readOnlyLogFileTest() {
221+
if (process.platform === 'win32' || process.getuid?.() === 0) {
222+
this.skip();
223+
}
224+
const filepath = path.join(tmpDir, 'readonly.log');
225+
fs.writeFileSync(filepath, '');
226+
fs.chmodSync(filepath, 0o444);
227+
try {
228+
logger = createLogger(filepath, LogLevel.error);
229+
230+
expect(logger.transports.file).to.be.undefined;
231+
expect(emitWarning.calledOnce).to.be.true;
232+
expect(emitWarning.firstCall.args[0]).to.contain('EACCES');
233+
expect(emitWarning.firstCall.args[0]).to.contain('logging to console only');
234+
expect(emitWarning.firstCall.args[1]).to.deep.equal({ code: LOG_FILE_UNAVAILABLE_WARNING_CODE });
235+
} finally {
236+
fs.chmodSync(filepath, 0o600);
237+
}
238+
});
239+
240+
it('keeps delivering console logs after the fallback', async () => {
241+
fs.mkdirSync(path.join(tmpDir, 'databricks-sql-nodejs.log'));
242+
const seen: string[] = [];
243+
const consoleLog = sinon.stub(winston.transports.Console.prototype, 'log').callsFake((...args: unknown[]) => {
244+
seen.push((args[0] as { message: string }).message);
245+
(args[1] as () => void)();
246+
});
247+
try {
248+
logger = createLogger(tmpDir);
249+
// Far more than the logger's stream buffers hold; an unopened file
250+
// transport used to stall delivery to every transport at that point.
251+
const lines = 1000;
252+
for (let i = 0; i < lines; i += 1) {
253+
logger.logger.info(`line ${i} ${'x'.repeat(100)}`);
254+
}
255+
const deadline = Date.now() + 1500;
256+
while (seen.length < lines && Date.now() < deadline) {
257+
// eslint-disable-next-line no-await-in-loop
258+
await new Promise((resolve) => {
259+
setTimeout(resolve, 20);
260+
});
261+
}
262+
263+
expect(seen).to.have.length(lines);
264+
expect(seen[lines - 1]).to.match(new RegExp(`^line ${lines - 1} `));
265+
} finally {
266+
consoleLog.restore();
267+
}
268+
});
269+
});
270+
271+
it('uses a non-existent filepath unchanged', () => {
272+
const filepath = path.join(tmpDir, 'custom.log');
273+
logger = createLogger(filepath);
274+
275+
expect(logger.transports.file).to.not.be.undefined;
276+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
277+
expect(logger.transports.file?.filename).to.equal('custom.log');
278+
});
279+
280+
it('creates missing parent directories and still attaches the file transport', () => {
281+
const nestedDir = path.join(tmpDir, 'a', 'b');
282+
const filepath = path.join(nestedDir, 'driver.log');
283+
logger = createLogger(filepath);
284+
285+
expect(logger.transports.file).to.not.be.undefined;
286+
expect(logger.transports.file?.dirname).to.equal(nestedDir);
287+
expect(logger.transports.file?.filename).to.equal('driver.log');
288+
expect(fs.statSync(nestedDir).isDirectory()).to.be.true;
289+
expect(fs.existsSync(filepath)).to.be.true;
290+
});
291+
292+
it('does not mkdir an existing directory (mkdir of a Windows drive root throws EPERM)', () => {
293+
const mkdirSync = sinon.stub(fs, 'mkdirSync').throws(Object.assign(new Error('EPERM'), { code: 'EPERM' }));
294+
try {
295+
logger = createLogger(path.join(tmpDir, 'driver.log'));
296+
} finally {
297+
mkdirSync.restore();
298+
}
299+
300+
expect(mkdirSync.called).to.be.false;
301+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
302+
expect(logger.transports.file?.filename).to.equal('driver.log');
303+
});
304+
305+
it('uses an existing file path unchanged', () => {
306+
const filepath = path.join(tmpDir, 'existing.log');
307+
fs.writeFileSync(filepath, '');
308+
logger = createLogger(filepath);
309+
310+
expect(logger.transports.file?.dirname).to.equal(tmpDir);
311+
expect(logger.transports.file?.filename).to.equal('existing.log');
312+
});
313+
});

0 commit comments

Comments
 (0)