Skip to content

Commit 5aaca27

Browse files
Logging cleanup. (#11606)
For #9837
1 parent 226b8f8 commit 5aaca27

File tree

15 files changed

+631
-364
lines changed

15 files changed

+631
-364
lines changed

src/client/common/logger.ts

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,10 @@
1+
// These are all just temporary aliases, for backward compatibility
2+
// and to avoid churn.
13
export {
2-
// aliases:
3-
// (temporarily for backward compatibility and to avoid churn)
44
traceDecorators,
5-
traceError,
6-
traceInfo,
7-
traceVerbose,
8-
traceWarning
9-
} from '../logging/_trace';
10-
export { TraceOptions as LogOptions } from '../logging/types';
5+
logError as traceError,
6+
logInfo as traceInfo,
7+
logVerbose as traceVerbose,
8+
logWarning as traceWarning
9+
} from '../logging';
10+
export { TraceOptions as LogOptions } from '../logging/trace';

src/client/common/utils/async.ts

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,16 @@ export async function waitForPromise<T>(promise: Promise<T>, timeout: number): P
2727
});
2828
}
2929

30+
// tslint:disable-next-line: no-any
31+
export function isThenable<T>(v: any): v is Thenable<T> {
32+
return typeof v?.then === 'function';
33+
}
34+
35+
// tslint:disable-next-line: no-any
36+
export function isPromise<T>(v: any): v is Promise<T> {
37+
return typeof v?.then === 'function' && typeof v?.catch === 'function';
38+
}
39+
3040
//======================
3141
// Deferred
3242

src/client/common/utils/decorators.ts

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import { traceError, traceVerbose } from '../logger';
88
import { Resource } from '../types';
99
import { createDeferred, Deferred } from './async';
1010
import { getCacheKeyFromFunctionArgs, getGlobalCacheStore, InMemoryInterpreterSpecificCache } from './cacheUtils';
11+
import { TraceInfo, tracing } from './misc';
1112

1213
// tslint:disable-next-line:no-require-imports no-var-requires
1314
const _debounce = require('lodash/debounce') as typeof import('lodash/debounce');
@@ -225,3 +226,37 @@ export function displayProgress(title: string, location = ProgressLocation.Windo
225226
};
226227
};
227228
}
229+
230+
// Information about a function/method call.
231+
export type CallInfo = {
232+
kind: string; // "Class", etc.
233+
name: string;
234+
// tslint:disable-next-line:no-any
235+
args: any[];
236+
};
237+
238+
// Return a decorator that traces the decorated function.
239+
export function trace(log: (c: CallInfo, t: TraceInfo) => void) {
240+
// tslint:disable-next-line:no-function-expression no-any
241+
return function (_: Object, __: string, descriptor: TypedPropertyDescriptor<any>) {
242+
const originalMethod = descriptor.value;
243+
// tslint:disable-next-line:no-function-expression no-any
244+
descriptor.value = function (...args: any[]) {
245+
const call = {
246+
kind: 'Class',
247+
name: _ && _.constructor ? _.constructor.name : '',
248+
args
249+
};
250+
// tslint:disable-next-line:no-this-assignment no-invalid-this
251+
const scope = this;
252+
return tracing(
253+
// "log()"
254+
(t) => log(call, t),
255+
// "run()"
256+
() => originalMethod.apply(scope, args)
257+
);
258+
};
259+
260+
return descriptor;
261+
};
262+
}

src/client/common/utils/misc.ts

Lines changed: 42 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,8 @@
44
import { Uri } from 'vscode';
55
import { InterpreterUri } from '../installer/types';
66
import { IAsyncDisposable, IDisposable, Resource } from '../types';
7+
import { isPromise } from './async';
8+
import { StopWatch } from './stopWatch';
79

810
// tslint:disable-next-line:no-empty
911
export function noop() {}
@@ -38,6 +40,46 @@ export async function usingAsync<T extends IAsyncDisposable, R>(
3840
}
3941
}
4042

43+
// Information about a traced function/method call.
44+
export type TraceInfo = {
45+
elapsed: number; // milliseconds
46+
// Either returnValue or err will be set.
47+
// tslint:disable-next-line:no-any
48+
returnValue?: any;
49+
err?: Error;
50+
};
51+
52+
// Call run(), call log() with the trace info, and return the result.
53+
export function tracing<T>(log: (t: TraceInfo) => void, run: () => T): T {
54+
const timer = new StopWatch();
55+
try {
56+
// tslint:disable-next-line:no-invalid-this no-use-before-declare no-unsafe-any
57+
const result = run();
58+
59+
// If method being wrapped returns a promise then wait for it.
60+
if (isPromise(result)) {
61+
// tslint:disable-next-line:prefer-type-cast
62+
(result as Promise<void>)
63+
.then((data) => {
64+
log({ elapsed: timer.elapsedTime, returnValue: data });
65+
return data;
66+
})
67+
.catch((ex) => {
68+
log({ elapsed: timer.elapsedTime, err: ex });
69+
// tslint:disable-next-line:no-suspicious-comment
70+
// TODO(GH-11645) Re-throw the error like we do
71+
// in the non-Promise case.
72+
});
73+
} else {
74+
log({ elapsed: timer.elapsedTime, returnValue: result });
75+
}
76+
return result;
77+
} catch (ex) {
78+
log({ elapsed: timer.elapsedTime, err: ex });
79+
throw ex;
80+
}
81+
}
82+
4183
/**
4284
* Checking whether something is a Resource (Uri/undefined).
4385
* Using `instanceof Uri` doesn't always work as the object is not an instance of Uri (at least not in tests).

src/client/logging/_console.ts

Lines changed: 0 additions & 74 deletions
This file was deleted.

src/client/logging/_global.ts

Lines changed: 157 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,157 @@
1+
// Copyright (c) Microsoft Corporation. All rights reserved.
2+
// Licensed under the MIT License.
3+
'use strict';
4+
5+
import { isCI, isTestExecution } from '../common/constants';
6+
import { CallInfo } from '../common/utils/decorators';
7+
import { LogLevel } from './levels';
8+
import { configureLogger, createLogger, ILogger, LoggerConfig, logToAll } from './logger';
9+
import { createTracingDecorator, LogInfo, TraceOptions, tracing as _tracing } from './trace';
10+
import { Arguments } from './util';
11+
12+
const globalLogger = createLogger();
13+
initialize();
14+
15+
/**
16+
* Initialize the logger.
17+
*
18+
* For console we do two things here:
19+
* - Anything written to the logger will be displayed in the console
20+
* window as well This is the behavior of the extension when running
21+
* it. When running tests on CI, we might not want this behavior, as
22+
* it'll pollute the test output with logging (as mentioned this is
23+
* optional). Messages logged using our logger will be prefixed with
24+
* `Python Extension: ....` for console window. This way, its easy
25+
* to identify messages specific to the python extension.
26+
* - Monkey patch the console.log and similar methods to send messages
27+
* to the file logger. When running UI tests or similar, and we want
28+
* to see everything that was dumped into `console window`, then we
29+
* need to hijack the console logger. To do this we need to monkey
30+
* patch the console methods. This is optional (generally done when
31+
* running tests on CI).
32+
*
33+
* For the logfile:
34+
* - we send all logging output to a log file. We log to the file
35+
* only if a file has been specified as an env variable. Currently
36+
* this is setup on CI servers.
37+
*/
38+
function initialize() {
39+
const config: LoggerConfig = {};
40+
let nonConsole = false;
41+
42+
// Do not log to console if running tests and we're not
43+
// asked to do so.
44+
if (!isTestExecution() || process.env.VSC_PYTHON_FORCE_LOGGING) {
45+
config.console = {};
46+
// In CI there's no need for the label.
47+
if (!isCI) {
48+
config.console.label = 'Python Extension:';
49+
}
50+
}
51+
if (process.env.VSC_PYTHON_LOG_FILE) {
52+
config.file = {
53+
logfile: process.env.VSC_PYTHON_LOG_FILE
54+
};
55+
nonConsole = true;
56+
}
57+
configureLogger(globalLogger, config);
58+
59+
if (isCI && nonConsole) {
60+
delete config.console;
61+
// Send console.*() to the non-console loggers.
62+
monkeypatchConsole(
63+
// This is a separate logger that matches our config but
64+
// does not do any console logging.
65+
createLogger(config)
66+
);
67+
}
68+
}
69+
70+
// Emit a log message derived from the args to all enabled transports.
71+
export function log(logLevel: LogLevel, ...args: Arguments) {
72+
logToAll([globalLogger], logLevel, args);
73+
}
74+
75+
// tslint:disable-next-line:no-any
76+
export function logVerbose(...args: any[]) {
77+
log(LogLevel.Info, ...args);
78+
}
79+
80+
// tslint:disable-next-line:no-any
81+
export function logError(...args: any[]) {
82+
log(LogLevel.Error, ...args);
83+
}
84+
85+
// tslint:disable-next-line:no-any
86+
export function logInfo(...args: any[]) {
87+
log(LogLevel.Info, ...args);
88+
}
89+
90+
// tslint:disable-next-line:no-any
91+
export function logWarning(...args: any[]) {
92+
log(LogLevel.Warn, ...args);
93+
}
94+
95+
// This is like a "context manager" that logs tracing info.
96+
export function tracing<T>(info: LogInfo, run: () => T, call?: CallInfo): T {
97+
return _tracing([globalLogger], info, run, call);
98+
}
99+
100+
export namespace traceDecorators {
101+
const DEFAULT_OPTS: TraceOptions = TraceOptions.Arguments | TraceOptions.ReturnValue;
102+
103+
export function verbose(message: string, opts: TraceOptions = DEFAULT_OPTS) {
104+
return createTracingDecorator([globalLogger], { message, opts });
105+
}
106+
export function error(message: string) {
107+
const opts = DEFAULT_OPTS;
108+
const level = LogLevel.Error;
109+
return createTracingDecorator([globalLogger], { message, opts, level });
110+
}
111+
export function info(message: string) {
112+
const opts = TraceOptions.None;
113+
return createTracingDecorator([globalLogger], { message, opts });
114+
}
115+
export function warn(message: string) {
116+
const opts = DEFAULT_OPTS;
117+
const level = LogLevel.Warn;
118+
return createTracingDecorator([globalLogger], { message, opts, level });
119+
}
120+
}
121+
122+
// Ensure that the console functions are bound before monkeypatching.
123+
import './transports';
124+
125+
/**
126+
* What we're doing here is monkey patching the console.log so we can
127+
* send everything sent to console window into our logs. This is only
128+
* required when we're directly writing to `console.log` or not using
129+
* our `winston logger`. This is something we'd generally turn on, only
130+
* on CI so we can see everything logged to the console window
131+
* (via the logs).
132+
*/
133+
function monkeypatchConsole(logger: ILogger) {
134+
// The logging "streams" (methods) of the node console.
135+
const streams = ['log', 'error', 'warn', 'info', 'debug', 'trace'];
136+
const levels: { [key: string]: LogLevel } = {
137+
error: LogLevel.Error,
138+
warn: LogLevel.Warn
139+
};
140+
// tslint:disable-next-line:no-any
141+
const consoleAny: any = console;
142+
for (const stream of streams) {
143+
// Using symbols guarantee the properties will be unique & prevents
144+
// clashing with names other code/library may create or have created.
145+
// We could use a closure but it's a bit trickier.
146+
const sym = Symbol.for(stream);
147+
consoleAny[sym] = consoleAny[stream];
148+
// tslint:disable-next-line: no-function-expression
149+
consoleAny[stream] = function () {
150+
const args = Array.prototype.slice.call(arguments);
151+
const fn = consoleAny[sym];
152+
fn(...args);
153+
const level = levels[stream] || LogLevel.Info;
154+
logToAll([logger], level, args);
155+
};
156+
}
157+
}

0 commit comments

Comments
 (0)