Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improvements to logging #8098

Merged
merged 11 commits into from
Nov 1, 2021
Merged

Improvements to logging #8098

merged 11 commits into from
Nov 1, 2021

Conversation

DonJayamanne
Copy link
Contributor

Stop displaying user names in logs (I find lots of users strip out the first few parts of the logs as it contains their user names)

  • This change ensures we use ~ where possible in our logs (minimizing displaying user names in logs)
    • As a resuult the text is also smaller
  • CHanged some of the logging levels to verbose (logging environment variables is unnecessary, i don't think we've used this)

const pid = output.pid ? ` (pid: ${output.pid})` : '';
const msg = `Python Daemon${pid}: ${output.msg}`;
if (output.level === 'DEBUG' || output.level === 'NOTSET') {
traceVerbose(msg);
} else if (output.level === 'INFO') {
traceInfo(msg);
traceVerbose(msg);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need any Python logging being displayed in our logs.
If we want that, we can turn on verbose logging.

@@ -89,7 +89,7 @@ export class PythonKernelDaemon extends BasePythonDaemon implements IPythonKerne
// This is why when we run `execModule` in the Kernel daemon, it finishes (comes back) quickly.
// However in reality it is running in the background.
// See `m_exec_module_observable` in `kernel_launcher_daemon.py`.
traceInfo(`Starting kernel from scratch with options ${JSON.stringify(options)}`);
traceVerbose(`Starting kernel from scratch with options ${JSON.stringify(options)}`);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Turning this into verbose, as optoins contains the full env varialbles as well, I don't think this is necessary, we log a tonne of other information thats more useful.
I've never looked at this.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we could just skip it.

}
this.subject.next(out);
},
(out) => this.subject.next(out),
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added this because I thought when we have stderr output coming from the kernel it might die.
Found that this is totally unnecessary as the output is sent up and we log this again (here all we do is just log a warning with a message possibly died, which is unnecessary.

@@ -122,7 +122,7 @@ export namespace traceDecorators {
const DEFAULT_OPTS: TraceOptions = TraceOptions.Arguments | TraceOptions.ReturnValue;

export function verbose(message: string, opts: TraceOptions = DEFAULT_OPTS) {
return createTracingDecorator([globalLogger], { message, opts });
return createTracingDecorator([globalLogger], { message, opts, level: LogLevel.Trace });
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bug, when somethign was verbose, we'd still log as info.

@@ -6,7 +6,7 @@ import { format } from 'winston';
import { isTestExecution } from '../common/constants';
import { getLevel, LogLevel, LogLevelName } from './levels';

const TIMESTAMP = 'YYYY-MM-DD HH:mm:ss';
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't need year, moves content out further to the right unnecessarily

@codecov-commenter
Copy link

codecov-commenter commented Oct 29, 2021

Codecov Report

Merging #8098 (3965e18) into main (fb51ceb) will increase coverage by 0%.
The diff coverage is 83%.

@@          Coverage Diff          @@
##            main   #8098   +/-   ##
=====================================
  Coverage     70%     70%           
=====================================
  Files        367     367           
  Lines      22701   22733   +32     
  Branches    3437    3441    +4     
=====================================
+ Hits       16091   16124   +33     
- Misses      5222    5223    +1     
+ Partials    1388    1386    -2     
Impacted Files Coverage Δ
...lient/datascience/kernel-launcher/kernelProcess.ts 76% <33%> (+1%) ⬆️
...nt/datascience/notebook/outputs/plotSaveHandler.ts 25% <33%> (+1%) ⬆️
src/client/logging/formatters.ts 51% <33%> (-4%) ⬇️
...notebook/intellisense/jupyterCompletionProvider.ts 65% <40%> (+<1%) ⬆️
...nt/datascience/notebook/outputs/plotViewHandler.ts 28% <50%> (+2%) ⬆️
src/client/logging/_global.ts 75% <50%> (ø)
...atascience/kernel-launcher/kernelLauncherDaemon.ts 90% <66%> (+<1%) ⬆️
src/client/logging/trace.ts 75% <66%> (-4%) ⬇️
src/client/api/pythonApi.ts 68% <100%> (+<1%) ⬆️
src/client/common/platform/fs-paths.ts 80% <100%> (+5%) ⬆️
... and 22 more

@@ -32,6 +32,9 @@ function normalizeLevel(name: LogLevelName): string {
return norm;
}
}
if ((name as any) === 'silly') {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we should display Silly in console logs.

@@ -66,7 +66,11 @@ function logResult(loggers: ILogger[], info: LogInfo, traced: TraceInfo, call?:
const formatted = formatMessages(info, traced, call);
if (traced.err === undefined) {
// The call did not fail.
if (!info.level || info.level > LogLevel.Error) {
if (info.level && info.level === LogLevel.Error) {
Copy link
Contributor Author

@DonJayamanne DonJayamanne Oct 29, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bug, verbose & other levels are not logged

@DonJayamanne DonJayamanne changed the title Better logging Improvements to logging Oct 29, 2021
@DonJayamanne DonJayamanne marked this pull request as ready for review October 29, 2021 20:22
@DonJayamanne DonJayamanne requested a review from a team as a code owner October 29, 2021 20:22
@DonJayamanne DonJayamanne merged commit c5a3eed into main Nov 1, 2021
@DonJayamanne DonJayamanne deleted the logging branch November 1, 2021 16:28
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants