Log Implementation #302

bryceitoc9 · 2019-02-20T21:50:27Z

Types of changes

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Infrastructure (change which improves the lifecycle management (CI/CD, build, package, deploy, lint, etc) of the application, but does not change functionality.)
Technical debt (change which improves the maintainability of the codebase, but does not change functionality)
Testing (change which modifies or adds test coverage, but does not change functionality)
Documentation (change which modifies or adds documentation, but does not change functionality)

Description

Adding winston logging

Logs are outputted to both an in-IDE output channel and to the path located at:
- Windows: ~\AppData\Roaming\Code\logs
- Linux: ~/.config/Code/logs
- Mac: ~Library/Application Support/Code/logs
Logs by default capture anything at an info state or higher. This is configurable through File > Preferences > Settings > Extensions > AWS Configuration > Log Level
Same log file/output channel is usable across files by default
- Additional loggers can also be created albeit without a "global" scope (you'll have to keep track of the object yourself)
Default log file can be opened via Command Palette: AWS: View AWS Toolkit Logs for a direct link to the persistent file (vs. the ephemeral Output Channel).

Currently logs, look like the following (on Windows):

Error logs for this session can be found in <user directory>\AppData\Roaming\Code\logs\aws_toolkit\aws_toolkit_<timestamp>.log
2019-03-01 14:27:12: [INFO]: > Downloading latest toolkits endpoint data

TBDs

Check if log level is valid before setting value
Register goto log commands in command palette
Register setting for log level
- x ] Use value set in settings menu as log level
Develop comprehensive formatting rules for log entries
- Do we want to be uniform across output console and log file? --> yes
- Add timestamps
- Handle arbitrary values that winston can handle, specifically, meta params and LogEntry object parameter
Backport all existing console.* commands to use logger.log

Motivation and Context

We don't have logs for users. Now we do!

A bit more context: we only outputted messages to stdout and stderr through console.* calls. This allows us to set additional logging that persists on disk that can help users troubleshoot and send issues to us.

Related Issue(s)

#293

Testing

Tests pass and logs are generated on normal run.

Screenshots (if appropriate)

Checklist

I have read the README document
I have read the CONTRIBUTING document
My code follows the code style of this project
I have added tests to cover my changes
All new and existing tests passed
A short description of the change has been added to the CHANGELOG

License

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

codecov-io · 2019-02-20T21:55:00Z

Codecov Report

Merging #302 into develop will increase coverage by 0.67%.
The diff coverage is 55.44%.

@@             Coverage Diff             @@
##           develop     #302      +/-   ##
===========================================
+ Coverage    50.16%   50.84%   +0.67%     
===========================================
  Files           95       97       +2     
  Lines         3267     3432     +165     
  Branches       457      477      +20     
===========================================
+ Hits          1639     1745     +106     
- Misses        1628     1687      +59

Impacted Files	Coverage Δ
src/shared/sam/cli/samCliBuild.ts	`0% <0%> (ø)`	⬆️
src/shared/defaultResourceFetcher.ts	`0% <0%> (ø)`	⬆️
src/extension.ts	`0% <0%> (ø)`	⬆️
src/shared/codelens/typescriptCodeLensProvider.ts	`0% <0%> (ø)`	⬆️
src/shared/credentials/userCredentialsUtils.ts	`88.63% <100%> (+0.54%)`	⬆️
src/lambda/lambdaPolicy.ts	`98.64% <100%> (+0.05%)`	⬆️
src/shared/treeview/awsTreeErrorHandlerNode.ts	`100% <100%> (ø)`	⬆️
src/shared/sam/cli/samCliDeploy.ts	`14.28% <16.66%> (+1.78%)`	⬆️
src/shared/sam/cli/samCliPackage.ts	`13.63% <20%> (+2.52%)`	⬆️
src/shared/sam/cli/samCliInit.ts	`14.28% <20%> (+2.52%)`	⬆️
... and 13 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update d366cc9...0dc2134. Read the comment docs.

…tter (nothing reads from this), localized strings

mpiroc

As far as what information to include on each line, my initial thoughts are:

Log Level
Timestamp
Maybe module? I.e. the source file calling log.

For metadata that does not change over the course of a session (i.e. version numbers), we only need to log it once per session.

mpiroc · 2019-02-21T00:07:14Z

src/shared/logger.ts

+        this.setLevel(level)
+    }
+
+    public getOutputChannel(): vscode.OutputChannel {


Better to use property accessors for these:

public get level(): string { return this.logger.level } public set level(value: string): void { this.logger.level = level }

mpiroc · 2019-02-21T00:09:44Z

src/shared/logger.ts

+// TODO: Add ability to handle arbitrary values, through meta parameter or LogEntry parameter
+export function log(level: string, message: string): void {
+    logSettings.getLogger().log(level, message)
+    logSettings.getOutputChannel().appendLine(`[${level}]: ${message}`)


Would it make sense to write a winston transport for VS Code output channels instead of doing it manually?

It would be awesome is winston handled formatting and text color for the OutputChannel.

I'll take a look to see if that's possible.

I have a rudimentary transport right now, but I'm not 100% sure if the formatted message is accessible (which seems extremely strange to me). Still looking into it though--this would be nice because then we can just return the winston logger object and to have handlers for all of the different levels and mechanisms.

mpiroc · 2019-02-21T00:10:27Z

src/shared/logger.ts

+// TODO: Format correctly/uniformly
+// TODO: Add timestamps
+// TODO: Add ability to handle arbitrary values, through meta parameter or LogEntry parameter
+export function log(level: string, message: string): void {


Nit: log(level: 'info' | 'warn' | 'error', ...)

mpiroc · 2019-02-21T00:11:09Z

src/shared/logger.ts

+    }
+
+    public setLevel(level: string): void {
+        // TODO: Ensure log level is valid


If you change the type from string to 'info' | 'warn' | 'error', the compiler will validate this for us.

Looks like this is on an outdated version, current version validates against winston's set levels: https://github.com/aws/aws-toolkit-vscode/pull/302/files#diff-4fdc113ff641e6c27c6f66c0d90c90b8R40

mpiroc · 2019-02-21T00:20:38Z

src/shared/logger.ts

+
+export function initialize(context: vscode.ExtensionContext): void {
+    const outputChannel: vscode.OutputChannel = vscode.window.createOutputChannel('AWS Toolkit Logs')
+    const logPath = context.logPath + '.log'


Is context.logPath a file or directory?

Unclear. context.logPath doesn't have a file extension, but also doesn't create a directory. I would say that this solution works unless we want to add additional log files

Would it make sense to validate that context.logPath does not end with path.sep, to protect against future changes to the VS Code API implementation?:

The docs say:

An absolute file path of a directory in which the extension can create log files. The directory might not exist on disk and creation is up to the extension. However, the parent directory is guaranteed to be existent.

mpiroc · 2019-02-21T00:24:24Z

src/shared/logger.ts

+        return this.logger
+    }
+
+    public setLevel(level: string): void {


Instead of validating the level at runtime, change it's type to 'info' | 'warn' | 'error' and the compiler will validate it for us.

Could alternately use the winston preset levels as well.

String enum please :)

micholas

Did you consider supporting ILogService to leverage VS Code built-in capabilities? This way we could plug-in to existing framework via MultiplexLogService
Consider using VS Code common/log LogLevel
How does VS Code do file logging? Can we simply leverage that?

Supporting VS Code's logging integration would enable native logging functionality such:

Setting the log level
Show logs (eventually)
Probably other log access/management that might exist now of in the future

micholas · 2019-02-21T18:29:49Z

src/shared/logger.ts

+    }
+}
+
+export function initialize(context: vscode.ExtensionContext): void {


Favor precise, explicit params:

export function initialize(params: { logPath: Pick<vscode.ExtensionContext, 'logPath'> // or just string }) : void

micholas · 2019-02-21T18:48:07Z

src/shared/logger.ts

+// TODO: Format correctly/uniformly
+// TODO: Add timestamps
+// TODO: Add ability to handle arbitrary values, through meta parameter or LogEntry parameter
+export function log(level: string, message: string): void {


Favor destructuring params for clarity and support of future API evolution. Argument list is especially dangerous with multiple ordered arguments of the same type because:

Compile can't help when order is swapped

Looks reasonable to developer and code reviewer when order is swapped

Adding multiple optional params later will result in ugly union types and type checking

Intent of code is unclear to reader unless they open the implementation of the code. This is exacerbated with multiple nested instances of argument list functions/constructors. The only way to understand intent is to read all of the code.

Use should read like this (similar to winston's log):

log({ level: Level.Error ,// consider making level a string enum message: 'Oh my, something to log' })

In this case in the future we could do any of these without breaking existing code or doing any crazy union type mumbo jumbo.:

Add a default for level perhaps to Level.info

Add an an optional key which if provided could look up the message bundle and substitute the message as the first param for the corresponding template

Add an optional boolean show attribute that determines whether channel should show when message is logged

Add an optional preserveFocus?: boolean

This function is removed in my working branch. I refactored to run everything through a winston transport, which means that we're using purely Winston-based functionality.

micholas · 2019-02-21T20:00:03Z

src/shared/logger.ts

+const localize = nls.loadMessageBundle()
+let logSettings: LogSettings
+
+class LogSettings {


Favor factory pattern to class.

Consider making LogSettings an interface with a corresponding getLogger(params) that returns something that perhaps implements logging interface such as ILogService or an extension of it.

It's worth trying out. All of the private readonly declarations disappear. No more this.<propertyName> = <propertyName>. At first a factory might seem like an unexpected approach but in JS/TS it's often a cleaner more flexible solution than a class. This approach is favorable in many languages such as Java where it's often skipped since it's more verbose to implement in Java.

Using a factory getLogger() could also support the singleton pattern if we decide it's desirable.

I'm not 100% sure if this will work with Winston since I don't want to risk overwriting existing output channels or log files. I can look into it though. See my notes re: ILogService below, however; that is not currently an option.

bryceitoc9 · 2019-02-22T22:15:40Z

@micholas I've looked into ILogService...the functionality is not exposed by VSCode and as far as I can tell is not planned to be exposed. It seems like they had grander plans for logging but have since shut them down due to conflicts with the existing output channels. See:

I would prefer to use something internal if it became available as this would mean we can hook into VSCode's log levels and log level selector in the preferences (I'm making a Winston-specific one for the toolkit) but unfortunately at this point it doesn't appear that that's the case.

bryceitoc9 · 2019-02-26T22:41:37Z

Spoke with @micholas and am changing a few things for the next revision:

Currently, there are race conditions if getLogger is called before initializing the logger object in extension.ts. This shows up in two places:

Anywhere that getLogger is called outside of a function or a class since this will be picked up when loading dependencies.
While running tests since tests do not initiate the whole extension.

The only reason we need to initialize the logger in extension.ts is because we currently rely on the vscode.ExtensionContext object that this receives for the file path. We have decided that the best way around this will be to use a general AWS log directory; this will allow us to create logs no matter what by initializing the logger internally to the logger file if it doesn't already exist.

Windows stores logs in ~\AppData\Roaming\Code\logs
Linux stores logs in ~/.config/Code/logs
Mac stores logs in ~Library/Application Support/Code/logs

Additionally, looking to refactor this from a class to a function based file.

…d and modified tests

bryceitoc9 · 2019-03-01T22:12:16Z

Realizing that the outputted timestamp is incorrect. Fixing now...

bryceitoc9 · 2019-03-01T22:33:42Z

package.json

@@ -303,9 +326,12 @@
        "semver": "^5.6.0",
        "sleep-promise": "^8.0.1",
        "tcp-port-used": "^1.0.1",
+        "triple-beam": "^1.3.0",


I thought this was removed, but it looks like it made its way back in. Will delete.

mpiroc · 2019-03-01T22:41:16Z

src/lambda/commands/invokeLambda.ts

-                console.log('invoking lambda function with the following payload:')
-                console.log(message.value)
+                logger.info('invoking lambda function with the following payload:')
+                logger.info(message.value ? message.value.toString() : '')


There's a shortcut: Replace message.value ? message.value.toString() : '' with String(message.value).

mpiroc · 2019-03-01T22:46:52Z

src/shared/logger.ts

-let logSettings: LogSettings
+// creates default logger object
+// can overwrite defaultLogger if you include params
+export function initialize(params?: LoggerParams): Logger {


I think this is fine as long as each test only calls initialize once, because our mocha tests are executed in serial.

If not, we may need to wrap this and getLogger with async-lock.

Does that only work with async functions, or does it force a block of code to run synchronously? There's no actually-written-as-async functionality built into this code (the exception is the registered VS Code open-in-editor function, but that's completely separate from the core logging functionality). There's a quasi-async required if you want to check a file's output, but there's no way to confirm this creation through Winston's functionality, either through async or callback. My workaround for this was the waitForLogFile function in logger.test.ts, but this is only required if you need to check the logs output--Winston doesn't care about whether or not the file is created to function.

If you see this as a significant concern, I can move waitForLogFile to loggerUtils.ts so we can use this functionality elsewhere.

No action required here, I was just thinking out-loud >_>

bryceitoc9 · 2019-03-01T22:55:49Z

src/shared/logger.ts

+    `${padNumber(d.getDate())}${chooseSpacer(isFilename, 'T', ' ')}` +
+    `${padNumber(d.getHours())}${chooseSpacer(isFilename, '', ':')}` +
+    `${padNumber(d.getMinutes())}${chooseSpacer(isFilename, '', ':')}` +
+    `${padNumber(d.getSeconds())}${chooseSpacer(isFilename, '', ':')}`


Remove this last chooseSpacer call to remove the trailing colon:
2019-03-01 14:53:12: [ERROR]: InvalidClientTokenId: The security token included in the request is invalid.

mpiroc · 2019-03-04T23:44:53Z

src/shared/logger.ts

+    return num < 10 ? '0' + num.toString() : num.toString()
+}
+
+function chooseSpacer(isFilename: boolean, ifTrue: string, ifFalse: string): string {


Any reason not to just use a ternary statement here? I.e.

isFilename ? '' : '-'

Instead of

chooseSpacer(isFilename, '', '-')

Not really, I think I was just in a bit of a haze of refactoring and thought this would make more sense. Now that I see it written out, it's perfectly readable. I'll go ahead and add that.

mpiroc · 2019-03-04T23:50:20Z

src/shared/logger.ts

-let logSettings: LogSettings
+// creates default logger object
+// can overwrite defaultLogger if you include params
+export function initialize(params?: LoggerParams): Logger {


No action required here, I was just thinking out-loud >_>

awschristou · 2019-03-06T02:16:44Z

src/shared/logger.ts

+            logPath: getDefaultLogPath()
+        })
+        // only the default logger (with default params) gets a registered command
+        vscode.commands.registerCommand(


Trying to register a command that is already registered causes an error. It might be worth guarding against this if possible. getCommands might help

awschristou · 2019-03-06T02:18:13Z

src/shared/logger.ts

+}
+
+// creates and returns custom logger
+// it's the caller's responsibility to keep track of this logger object


If it is the caller's responsibility to call some sort of dispose/cleanup method, please add what the method(s) are in the comment.

Do we have any conventions for adding method usage instructions to the tooltips? Might be a good place to add that there.

In VS Code if you place your cursor on the (blank) line above a function and type /** and press enter, you should get the comment template. Within a comment, you can type @ to bring up some of the sections, like description, param, and returns.

https://code.visualstudio.com/docs/languages/javascript#_js-doc-support

awschristou · 2019-03-06T02:19:46Z

src/shared/logger.ts

+        const configuration: SettingsConfiguration = new DefaultSettingsConfiguration(extensionSettingsPrefix)
+        level =
+            configuration.readSetting<string>('logLevel') ?
+            configuration.readSetting<string>('logLevel') as string : DEFAULT_LOG_LEVEL


Consider calling configuration.readSetting<string>('logLevel') once only

Initial winston logging implementation

24975e7

bryceitoc9 mentioned this pull request Feb 20, 2019

Users can find toolkit logs in a file on their machine. #293

Closed

Added Command Palette command for opening logfile, added log level se…

6aed477

…tter (nothing reads from this), localized strings

mpiroc reviewed Feb 21, 2019

View reviewed changes

micholas reviewed Feb 21, 2019

View reviewed changes

Using winston transport for output channel

8c69808

Added logger framework, converted console calls to logger calls, adde…

68882f1

…d and modified tests

bryceitoc9 requested a review from awschristou March 1, 2019 22:08

bryceitoc9 changed the title ~~Initial winston logging implementation (DO NOT SHIP YET--MANY TBDS)~~ Initial winston logging implementation Mar 1, 2019

Changed logfile timestamp formatting

f8aa418

bryceitoc9 commented Mar 1, 2019

View reviewed changes

bryceitoc9 changed the title ~~Initial winston logging implementation~~ Log Implementation Mar 1, 2019

mpiroc approved these changes Mar 1, 2019

View reviewed changes

bryceitoc9 commented Mar 1, 2019

View reviewed changes

bryceitoc9 added 3 commits March 4, 2019 09:41

Minor tweaks and additional comments

02044a4

Merging deploy

783d6ca

Fixing a test to ensure logger is active during its run

0d99bf7

bryceitoc9 mentioned this pull request Mar 4, 2019

Adding general explorer features to menu in AWS pane #333

Merged

12 tasks

mpiroc reviewed Mar 4, 2019

View reviewed changes

mpiroc approved these changes Mar 4, 2019

View reviewed changes

Removing extraneous function

1de031d

awschristou reviewed Mar 6, 2019

View reviewed changes

bryceitoc9 added 2 commits March 6, 2019 15:09

Addressing feedback--ensuring registerCommand is called only once

3ab48f5

Merging develop

a3d629d

awschristou approved these changes Mar 6, 2019

View reviewed changes

Finishing merge from develop...

0dc2134

bryceitoc9 merged commit 79963f8 into develop Mar 7, 2019

bryceitoc9 deleted the bryceito/winston-logging branch March 7, 2019 00:00

Log Implementation #302

Log Implementation #302

Conversation

bryceitoc9 commented Feb 20, 2019 • edited Loading

Types of changes

Description

TBDs

Motivation and Context

We don't have logs for users. Now we do!

Related Issue(s)

Testing

Screenshots (if appropriate)

Checklist

License

codecov-io commented Feb 20, 2019 • edited Loading

Codecov Report

mpiroc left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

micholas left a comment • edited Loading

Choose a reason for hiding this comment

micholas Feb 21, 2019 • edited Loading

Choose a reason for hiding this comment

micholas Feb 21, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

micholas Feb 21, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bryceitoc9 commented Feb 22, 2019 • edited Loading

bryceitoc9 commented Feb 26, 2019

bryceitoc9 commented Mar 1, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mpiroc Mar 4, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mpiroc Mar 4, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bryceitoc9 commented Feb 20, 2019 •

edited

Loading

codecov-io commented Feb 20, 2019 •

edited

Loading

micholas left a comment •

edited

Loading

micholas Feb 21, 2019 •

edited

Loading

micholas Feb 21, 2019 •

edited

Loading

micholas Feb 21, 2019 •

edited

Loading

bryceitoc9 commented Feb 22, 2019 •

edited

Loading

mpiroc Mar 4, 2019 •

edited

Loading

mpiroc Mar 4, 2019 •

edited

Loading