Skip to content

Commit 899c6cd

Browse files
author
Eric Snow
authored
Logging cleanup: move and split files. (microsoft#11161)
For microsoft#9837. This change is strictly about moving code around.
1 parent 9fef09f commit 899c6cd

10 files changed

Lines changed: 495 additions & 346 deletions

File tree

‎src/client/common/logger.ts‎

Lines changed: 10 additions & 339 deletions
Original file line numberDiff line numberDiff line change
@@ -1,339 +1,10 @@
1-
// tslint:disable:no-console no-any
2-
import * as path from 'path';
3-
import * as util from 'util';
4-
import { createLogger, format, transports } from 'winston';
5-
import { EXTENSION_ROOT_DIR } from '../constants';
6-
import { sendTelemetryEvent } from '../telemetry';
7-
import { isTestExecution } from './constants';
8-
import { LogLevel } from './types';
9-
import { StopWatch } from './utils/stopWatch';
10-
11-
// tslint:disable-next-line: no-var-requires no-require-imports
12-
const TransportStream = require('winston-transport');
13-
14-
// Initialize the loggers as soon as this module is imported.
15-
const consoleLogger = createLogger();
16-
const fileLogger = createLogger();
17-
initializeConsoleLogger();
18-
initializeFileLogger();
19-
20-
const logLevelMap = {
21-
[LogLevel.Error]: 'error',
22-
[LogLevel.Information]: 'info',
23-
[LogLevel.Warning]: 'warn'
24-
};
25-
26-
function log(logLevel: LogLevel, ...args: any[]) {
27-
if (consoleLogger.transports.length > 0) {
28-
const message = args.length === 0 ? '' : util.format(args[0], ...args.slice(1));
29-
consoleLogger.log(logLevelMap[logLevel], message);
30-
}
31-
logToFile(logLevel, ...args);
32-
}
33-
function logToFile(logLevel: LogLevel, ...args: any[]) {
34-
if (fileLogger.transports.length === 0) {
35-
return;
36-
}
37-
const message = args.length === 0 ? '' : util.format(args[0], ...args.slice(1));
38-
fileLogger.log(logLevelMap[logLevel], message);
39-
}
40-
41-
/**
42-
* Initialize the logger for console.
43-
* We do two things here:
44-
* - Anything written to the logger will be displayed in the console window as well
45-
* This is the behavior of the extension when running it.
46-
* When running tests on CI, we might not want this behavior, as it'll pollute the
47-
* test output with logging (as mentioned this is optional).
48-
* Messages logged using our logger will be prefixed with `Python Extension: ....` for console window.
49-
* This way, its easy to identify messages specific to the python extension.
50-
* - Monkey patch the console.log and similar methods to send messages to the file logger.
51-
* When running UI tests or similar, and we want to see everything that was dumped into `console window`,
52-
* then we need to hijack the console logger.
53-
* To do this we need to monkey patch the console methods.
54-
* This is optional (generally done when running tests on CI).
55-
*/
56-
// tslint:disable-next-line: max-func-body-length
57-
function initializeConsoleLogger() {
58-
const logMethods = {
59-
log: Symbol.for('log'),
60-
info: Symbol.for('info'),
61-
error: Symbol.for('error'),
62-
debug: Symbol.for('debug'),
63-
warn: Symbol.for('warn')
64-
};
65-
66-
function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...args: any[]) {
67-
if (['info', 'error', 'warn', 'log', 'debug'].indexOf(stream) === -1) {
68-
stream = 'log';
69-
}
70-
// Further below we monkeypatch the console.log, etc methods.
71-
const fn = (console as any)[logMethods[stream]] || console[stream] || console.log;
72-
fn(...args);
73-
}
74-
75-
// Hijack `console.log` when running tests on CI.
76-
if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) {
77-
/*
78-
What we're doing here is monkey patching the console.log so we can send everything sent to console window into our logs.
79-
This is only required when we're directly writing to `console.log` or not using our `winston logger`.
80-
This is something we'd generally turn on, only on CI so we can see everything logged to the console window (via the logs).
81-
*/
82-
// Keep track of the original functions before we monkey patch them.
83-
// Using symbols guarantee the properties will be unique & prevents clashing with names other code/library may create or have created.
84-
(console as any)[logMethods.log] = console.log;
85-
(console as any)[logMethods.info] = console.info;
86-
(console as any)[logMethods.error] = console.error;
87-
(console as any)[logMethods.debug] = console.debug;
88-
(console as any)[logMethods.warn] = console.warn;
89-
90-
// tslint:disable-next-line: no-function-expression
91-
console.log = function () {
92-
const args = Array.prototype.slice.call(arguments);
93-
logToConsole('log', ...args);
94-
logToFile(LogLevel.Information, ...args);
95-
};
96-
// tslint:disable-next-line: no-function-expression
97-
console.info = function () {
98-
const args = Array.prototype.slice.call(arguments);
99-
logToConsole('info', ...args);
100-
logToFile(LogLevel.Information, ...args);
101-
};
102-
// tslint:disable-next-line: no-function-expression
103-
console.warn = function () {
104-
const args = Array.prototype.slice.call(arguments);
105-
logToConsole('warn', ...args);
106-
logToFile(LogLevel.Warning, ...args);
107-
};
108-
// tslint:disable-next-line: no-function-expression
109-
console.error = function () {
110-
const args = Array.prototype.slice.call(arguments);
111-
logToConsole('error', ...args);
112-
logToFile(LogLevel.Error, ...args);
113-
};
114-
// tslint:disable-next-line: no-function-expression
115-
console.debug = function () {
116-
const args = Array.prototype.slice.call(arguments);
117-
logToConsole('debug', ...args);
118-
logToFile(LogLevel.Information, ...args);
119-
};
120-
}
121-
122-
if (isTestExecution() && !process.env.VSC_PYTHON_FORCE_LOGGING) {
123-
// Do not log to console if running tests on CI and we're not asked to do so.
124-
return;
125-
}
126-
127-
// Rest of this stuff is just to instantiate the console logger.
128-
// I.e. when we use our logger, ensure we also log to the console (for end users).
129-
const formattedMessage = Symbol.for('message');
130-
class ConsoleTransport extends TransportStream {
131-
constructor(options?: any) {
132-
super(options);
133-
}
134-
public log?(info: { level: string; message: string; [formattedMessage]: string }, next: () => void): any {
135-
setImmediate(() => this.emit('logged', info));
136-
logToConsole(info.level as any, info[formattedMessage] || info.message);
137-
if (next) {
138-
next();
139-
}
140-
}
141-
}
142-
const consoleFormatter = format.printf(({ level, message, label, timestamp }) => {
143-
// If we're on CI server, no need for the label (prefix)
144-
// Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors.
145-
const prefix = `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${
146-
process.env.TF_BUILD ? '' : label
147-
}`;
148-
return `${prefix.trim()} ${timestamp}: ${message}`;
149-
});
150-
const consoleFormat = format.combine(
151-
format.label({ label: 'Python Extension:' }),
152-
format.timestamp({
153-
format: 'YYYY-MM-DD HH:mm:ss'
154-
}),
155-
consoleFormatter
156-
);
157-
consoleLogger.add(new ConsoleTransport({ format: consoleFormat }) as any);
158-
}
159-
160-
/**
161-
* Send all logging output to a log file.
162-
* We log to the file only if a file has been specified as an env variable.
163-
* Currently this is setup on CI servers.
164-
*/
165-
function initializeFileLogger() {
166-
if (!process.env.VSC_PYTHON_LOG_FILE) {
167-
return;
168-
}
169-
const fileFormatter = format.printf(({ level, message, timestamp }) => {
170-
// Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors.
171-
return `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${timestamp}: ${message}`;
172-
});
173-
const fileFormat = format.combine(
174-
format.timestamp({
175-
format: 'YYYY-MM-DD HH:mm:ss'
176-
}),
177-
fileFormatter
178-
);
179-
const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE)
180-
? process.env.VSC_PYTHON_LOG_FILE
181-
: path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE);
182-
const logFileSink = new transports.File({
183-
format: fileFormat,
184-
filename: logFilePath,
185-
handleExceptions: true
186-
});
187-
fileLogger.add(logFileSink);
188-
}
189-
190-
/**
191-
* What do we want to log.
192-
* @export
193-
* @enum {number}
194-
*/
195-
export enum LogOptions {
196-
None = 0,
197-
Arguments = 1,
198-
ReturnValue = 2
199-
}
200-
201-
// tslint:disable-next-line:no-any
202-
function argsToLogString(args: any[]): string {
203-
try {
204-
return (args || [])
205-
.map((item, index) => {
206-
if (item === undefined) {
207-
return `Arg ${index + 1}: undefined`;
208-
}
209-
if (item === null) {
210-
return `Arg ${index + 1}: null`;
211-
}
212-
try {
213-
if (item && item.fsPath) {
214-
return `Arg ${index + 1}: <Uri:${item.fsPath}>`;
215-
}
216-
return `Arg ${index + 1}: ${JSON.stringify(item)}`;
217-
} catch {
218-
return `Arg ${index + 1}: <argument cannot be serialized for logging>`;
219-
}
220-
})
221-
.join(', ');
222-
} catch {
223-
return '';
224-
}
225-
}
226-
227-
// tslint:disable-next-line:no-any
228-
function returnValueToLogString(returnValue: any): string {
229-
const returnValueMessage = 'Return Value: ';
230-
if (returnValue === undefined) {
231-
return `${returnValueMessage}undefined`;
232-
}
233-
if (returnValue === null) {
234-
return `${returnValueMessage}null`;
235-
}
236-
try {
237-
return `${returnValueMessage}${JSON.stringify(returnValue)}`;
238-
} catch {
239-
return `${returnValueMessage}<Return value cannot be serialized for logging>`;
240-
}
241-
}
242-
243-
export function traceVerbose(...args: any[]) {
244-
log(LogLevel.Information, ...args);
245-
}
246-
247-
export function traceError(...args: any[]) {
248-
log(LogLevel.Error, ...args);
249-
}
250-
251-
export function traceInfo(...args: any[]) {
252-
log(LogLevel.Information, ...args);
253-
}
254-
255-
export function traceWarning(...args: any[]) {
256-
log(LogLevel.Warning, ...args);
257-
}
258-
259-
export namespace traceDecorators {
260-
export function verbose(message: string, options: LogOptions = LogOptions.Arguments | LogOptions.ReturnValue) {
261-
return trace(message, options);
262-
}
263-
export function error(message: string) {
264-
return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Error);
265-
}
266-
export function info(message: string) {
267-
return trace(message);
268-
}
269-
export function warn(message: string) {
270-
return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Warning);
271-
}
272-
}
273-
function trace(message: string, options: LogOptions = LogOptions.None, logLevel?: LogLevel) {
274-
// tslint:disable-next-line:no-function-expression no-any
275-
return function (_: Object, __: string, descriptor: TypedPropertyDescriptor<any>) {
276-
const originalMethod = descriptor.value;
277-
// tslint:disable-next-line:no-function-expression no-any
278-
descriptor.value = function (...args: any[]) {
279-
const className = _ && _.constructor ? _.constructor.name : '';
280-
// tslint:disable-next-line:no-any
281-
function writeSuccess(elapsedTime: number, returnValue: any) {
282-
if (logLevel === LogLevel.Error) {
283-
return;
284-
}
285-
writeToLog(elapsedTime, returnValue);
286-
}
287-
function writeError(elapsedTime: number, ex: Error) {
288-
writeToLog(elapsedTime, undefined, ex);
289-
}
290-
// tslint:disable-next-line:no-any
291-
function writeToLog(elapsedTime: number, returnValue?: any, ex?: Error) {
292-
const messagesToLog = [message];
293-
messagesToLog.push(
294-
`Class name = ${className}, completed in ${elapsedTime}ms, has a ${
295-
returnValue ? 'truthy' : 'falsy'
296-
} return value`
297-
);
298-
if ((options & LogOptions.Arguments) === LogOptions.Arguments) {
299-
messagesToLog.push(argsToLogString(args));
300-
}
301-
if ((options & LogOptions.ReturnValue) === LogOptions.ReturnValue) {
302-
messagesToLog.push(returnValueToLogString(returnValue));
303-
}
304-
if (ex) {
305-
log(LogLevel.Error, messagesToLog.join(', '), ex);
306-
sendTelemetryEvent('ERROR' as any, undefined, undefined, ex);
307-
} else {
308-
log(LogLevel.Information, messagesToLog.join(', '));
309-
}
310-
}
311-
const timer = new StopWatch();
312-
try {
313-
// tslint:disable-next-line:no-invalid-this no-use-before-declare no-unsafe-any
314-
const result = originalMethod.apply(this, args);
315-
// If method being wrapped returns a promise then wait for it.
316-
// tslint:disable-next-line:no-unsafe-any
317-
if (result && typeof result.then === 'function' && typeof result.catch === 'function') {
318-
// tslint:disable-next-line:prefer-type-cast
319-
(result as Promise<void>)
320-
.then((data) => {
321-
writeSuccess(timer.elapsedTime, data);
322-
return data;
323-
})
324-
.catch((ex) => {
325-
writeError(timer.elapsedTime, ex);
326-
});
327-
} else {
328-
writeSuccess(timer.elapsedTime, result);
329-
}
330-
return result;
331-
} catch (ex) {
332-
writeError(timer.elapsedTime, ex);
333-
throw ex;
334-
}
335-
};
336-
337-
return descriptor;
338-
};
339-
}
1+
export {
2+
// aliases:
3+
// (temporarily for backward compatibility and to avoid churn)
4+
traceDecorators,
5+
traceError,
6+
traceInfo,
7+
traceVerbose,
8+
traceWarning
9+
} from '../logging/_trace';
10+
export { TraceOptions as LogOptions } from '../logging/types';

‎src/client/common/types.ts‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -65,12 +65,6 @@ export type ExecutionInfo = {
6565
product?: Product;
6666
};
6767

68-
export enum LogLevel {
69-
Information = 'Information',
70-
Error = 'Error',
71-
Warning = 'Warning'
72-
}
73-
7468
export enum InstallerResponse {
7569
Installed,
7670
Disabled,
@@ -313,6 +307,12 @@ export interface IExperiments {
313307
readonly optOutFrom: string[];
314308
}
315309

310+
export enum AnalysisSettingsLogLevel {
311+
Information = 'Information',
312+
Error = 'Error',
313+
Warning = 'Warning'
314+
}
315+
316316
export type LanguageServerDownloadChannels = 'stable' | 'beta' | 'daily';
317317
export interface IAnalysisSettings {
318318
readonly downloadChannel?: LanguageServerDownloadChannels;
@@ -324,7 +324,7 @@ export interface IAnalysisSettings {
324324
readonly information: string[];
325325
readonly disabled: string[];
326326
readonly traceLogging: boolean;
327-
readonly logLevel: LogLevel;
327+
readonly logLevel: AnalysisSettingsLogLevel;
328328
}
329329

330330
export interface IVariableQuery {

0 commit comments

Comments
 (0)