Shore up logging behavior #74

jasonkarns · 2018-12-18T17:36:10Z

Goals

align with Unix philosophy as a CLI tool
be as user friendly as possible on the CLI (piping, etc)
conform to npm's conventions as much as possible

Proposal

All scripty output goes to STDERR at all times.

Any output that scripty itself reports is purely diagnostic by
definition. Only the output from the scripts that scripty executes
should be considered "core data" and thus only the script output should
go to STDOUT.

Benefits: scripty becomes pipeable by default because the wrapped script
output is alone on STDOUT; scripty's STDERR output can be redirected
and/or ignored.

Conform to Unix and GNU conventions: silent and quiet flags are
aliases; accept verbose, dryRun implies INFO
Leverage npm's example and have a single logLevel setting that is
impacted by silent/quiet/verbose/dry-run flags.

Implementation

This PR introduces the following LOG LEVELS

verbose
info * (the default)
warn
error
silent

When executing a script, the message noting which script is about to be
executed is info level.

The contents of the script are printed at verbose level.

Scripty warnings and errors correspond to warn/error, respectively.

Therefore, by default, scripty's only output is the preamble to the
script, noting the path of the script about to be executed. (This is
similar to npm's default output for run-script.)

To be user-friendly per unix/gnu guidelines, the silent/quiet/verbose
flags all map to the logLevel option.

The logLevel option takes precedence if provided. Otherwise, in case of
conflicting flags (e.g. both silent and verbose), the noisier flag
takes precedence.

TODO or followup

Match npm's output prefix ( add the > prefix for info output)
colorize ? (especially error output)
docs
inherit npm's log level by default
conventional prefixing of warnings/errors

closes #70

searls · 2018-12-18T22:03:46Z

Woah, nice

codeclimate · 2018-12-19T21:03:34Z

lib/log.test.js

+      subject.warn('ing')
+      td.verify(console.error('ing'))
+    },
+    error: function () {


Similar blocks of code found in 3 locations. Consider refactoring.

Wonder if we should be excluding codeclimate from analyzing tests? I think their default config ignores tests. thoughts @searls ?

¯_(ツ)_/¯ it's your thingy man, whatever you want!

codeclimate · 2018-12-19T21:03:34Z

lib/derive-log-level.js

+
+  if (userOptions.dryRun) return level.INFO
+
+  if (userOptions.silent || userOptions.quiet) return level.SILENT


Avoid too many return statements within this function.

codeclimate · 2018-12-19T21:03:34Z

lib/log.test.js

+      subject.info('mation')
+      td.verify(console.error('mation'))
+    },
+    warn: function () {


Similar blocks of code found in 3 locations. Consider refactoring.

codeclimate · 2018-12-19T21:03:34Z

lib/log.test.js

+      subject.verbose('ity')
+      td.verify(console.error('ity'))
+    },
+    info: function () {


Similar blocks of code found in 3 locations. Consider refactoring.

codeclimate · 2018-12-19T21:03:35Z

lib/derive-log-level.js

@@ -0,0 +1,13 @@
+var level = require('./log').levels
+
+module.exports = function deriveLogLevel (userOptions) {


Function deriveLogLevel has a Cognitive Complexity of 6 (exceeds 5 allowed). Consider refactoring.

Originally, the log level derivation (respecting verbose/silent/dryrun/quiet flags) happened at the CLI level. This was a level too high because it meant that direct invocations of scripty would not resolve the same log level (based on the other flags). Now we do the log level resolution at the same point where all the options are defaulted: within the optionify wrapper of scripty itself. This way we still have access to distinguish the user-provided values vs the defaults, and can apply the aliases and various supported flags. Downside is that now the CLI needs to read in all the various flags to pass them down, but that's an acceptable tradeoff.

This way logs can be written during the script resolution process.

The logger is needed before the run process begins so it's no longer a local dep of just the run process. (For instance, to write errors/warnings during the loading process.)

0.10 doesn't have fs.access and 0.10 was supported in the initial scripty release. We no longer support 0.10 so we can drop this homegrown module. However, there is a quirk in that the old code specifically changed the permission bits, but that didn't necessarily mean the file was actually readable or executable. For instance, a file with an +x but -r is not actually executable. (Since the file needs read to actually execute.) In addition, a non user-executable file with a group exec bit is not actually executable by the node process. Both of these scenarios are covered by fs.access.

codeclimate · 2018-12-21T02:13:33Z

lib/derive-log-level.js

+
+  if (userOptions.dryRun) return log.info
+
+  if (userOptions.silent || userOptions.quiet) return log.silent


Avoid too many return statements within this function.

jasonkarns · 2018-12-21T03:08:15Z

Sample outputs given a script/foo which prints one line to STDOUT and one line to STDERR:

Things to note about this output:

The script about to execute is printed at INFO level with one blank line before and after itself. This separates it from npm's preamble as well as separates from the script's own output (or script body in verbose mode)
ALL scripty messages are prefixed with scripty , followed by a leader – > for VERBOSE and INFO, WARN for WARN, and ERR! for ERROR. The latter two copy npm directly. (No colorization yet.)
Script body is printed only in VERBOSE mode. (with all lines prefixed) This means, by default, scripty only prints the script "preamble" (script name about to execute), and the script's own output.
DryRun just adds one additional line about being in dry run mode (at INFO level)
script failure prints the name of the script that failed, and the exit status at ERROR level
"unable to run script": prints WARN level message about read/exec bit and continues (it may find other scripts to exec, but most likely will be followed with "no script found error"
"no script found" is printed at ERROR level, and splits the globs 1-per line to more easily see the list

Default configuration

$ npm run foo

> @nodenv/[email protected] foo /Users/jasonkarns/Projects/nodenv/node-build
> scripty

scripty > Executing "/Users/jasonkarns/Projects/nodenv/node-build/script/foo":

Data to STDOUT
Diagnostics to STDERR

Verbose

$ SCRIPTY_VERBOSE=true npm run foo

> @nodenv/[email protected] foo /Users/jasonkarns/Projects/nodenv/node-build
> scripty

scripty > Executing "/Users/jasonkarns/Projects/nodenv/node-build/script/foo":

scripty > #!/bin/bash
scripty > 
scripty > echo "Data to STDOUT"
scripty > echo "Diagnostics to STDERR" >&2

Data to STDOUT
Diagnostics to STDERR

Silent

$ SCRIPTY_SILENT=true npm run foo

> @nodenv/[email protected] foo /Users/jasonkarns/Projects/nodenv/node-build
> scripty

Data to STDOUT
Diagnostics to STDERR

Silent + npm silent

$ SCRIPTY_SILENT=true npm -s run foo
Data to STDOUT
Diagnostics to STDERR

Dry Run

$ SCRIPTY_DRY_RUN=true npm run foo

> @nodenv/[email protected] foo /Users/jasonkarns/Projects/nodenv/node-build
> scripty

scripty > This is a dry run. Executed scripts would be:

scripty > Executing "/Users/jasonkarns/Projects/nodenv/node-build/script/foo":

Default with script fail

$ npm run foo

> @nodenv/[email protected] foo /Users/jasonkarns/Projects/nodenv/node-build
> scripty

scripty > Executing "/Users/jasonkarns/Projects/nodenv/node-build/script/foo":

Data to STDOUT
Diagnostics to STDERR
scripty ERR! script failed: '/Users/jasonkarns/Projects/nodenv/node-build/script/foo'
scripty ERR! exit status: 1
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! @nodenv/[email protected] foo: `scripty`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the @nodenv/[email protected] foo script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /usr/local/cache/npm/_logs/2018-12-21T02_48_04_397Z-debug.log

Default with un-executable script (or executable but not readable)

$ npm run foo

> @nodenv/[email protected] foo /Users/jasonkarns/Projects/nodenv/node-build
> scripty

scripty WARN Ignoring script '/Users/jasonkarns/Projects/nodenv/node-build/script/foo' because it was not readable/executable.
scripty WARN Run `chmod u+rx '/Users/jasonkarns/Projects/nodenv/node-build/script/foo'` if you want scripty to run it.
scripty ERR! No script found for npm lifecycle 'foo' matching any of:
scripty ERR!   /Users/jasonkarns/Projects/nodenv/node-build/script/foo+(|.*)
scripty ERR!   /Users/jasonkarns/Projects/nodenv/node-build/script/foo/index+(|.*)
scripty ERR!   /Users/jasonkarns/Projects/nodenv/node-build/script/foo/*
scripty ERR!   /Users/jasonkarns/Projects/scripty/scripts/foo+(|.*)
scripty ERR!   /Users/jasonkarns/Projects/scripty/scripts/foo/index+(|.*)
scripty ERR!   /Users/jasonkarns/Projects/scripty/scripts/foo/*
scripty ERR! Either define a script or remove "scripty" from 'scripts.foo' in your package.json.
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! @nodenv/[email protected] foo: `scripty`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the @nodenv/[email protected] foo script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /usr/local/cache/npm/_logs/2018-12-21T02_49_47_988Z-debug.log

jasonkarns · 2018-12-21T15:10:04Z

Merging as-is for now, will release as pre 2.0 and let it bake a bit. (dogfooding)

jasonkarns changed the title ~~Shore up logging behavior~~ WIP: Shore up logging behavior Dec 18, 2018

jasonkarns requested a review from Schoonology December 18, 2018 17:36

jasonkarns self-assigned this Dec 18, 2018

codeclimate bot reviewed Dec 19, 2018

View reviewed changes

jasonkarns added 20 commits December 20, 2018 21:10

De-duplicate the initial log state

022e967

Leverage util.format for pretty-printing log messages

6618d31

All scripty output goes to STDERR

1e7d82f

Output goes through the logger

ae9d110

Leverage util.format for printf-style logging

283d7b2

Derive the log level from various rules

721e90b

Adds methods to logger that respect the level

6c11456

Log with explicit level-specific methods

c54fe66

Derive log level at CLI start; Set log level when running

5198abf

Removes usage of old silent option

b930b54

Normalize the log level when setting the level

8f41cca

Git rid of log.shush helper

ab092d7

cleanup exports

3e53a14

Log level must be set before running

6b6444e

This way logs can be written during the script resolution process.

Moves log from lib/run/ to lib/

a88be5e

The logger is needed before the run process begins so it's no longer a local dep of just the run process. (For instance, to write errors/warnings during the loading process.)

Write caught errors using our logger which respects logLevel

f8ff105

Strip the stacktrace from printed errors

c58c48d

Refactor and reformat logging messages

40a9363

codeclimate bot reviewed Dec 21, 2018

View reviewed changes

jasonkarns force-pushed the silent-default branch from 7317717 to 029e7e7 Compare December 21, 2018 02:24

Update to config v2

c8cd2d2

jasonkarns force-pushed the silent-default branch from 029e7e7 to c8cd2d2 Compare December 21, 2018 02:37

Readme docs

2b78bf4

jasonkarns changed the title ~~WIP: Shore up logging behavior~~ Shore up logging behavior Dec 21, 2018

jasonkarns merged commit 00cbfad into master Dec 21, 2018

jasonkarns deleted the silent-default branch December 21, 2018 15:10

jasonkarns mentioned this pull request Dec 21, 2018

Infer log level from npm's own logLevel #78

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Shore up logging behavior #74

Shore up logging behavior #74

jasonkarns commented Dec 18, 2018 •

edited

Loading

searls commented Dec 18, 2018

codeclimate bot Dec 19, 2018

jasonkarns Dec 19, 2018

searls Dec 19, 2018

codeclimate bot Dec 19, 2018

codeclimate bot Dec 19, 2018

codeclimate bot Dec 19, 2018

codeclimate bot Dec 19, 2018

codeclimate bot Dec 21, 2018

jasonkarns commented Dec 21, 2018

jasonkarns commented Dec 21, 2018


		if (userOptions.dryRun) return level.INFO

		if (userOptions.silent \|\| userOptions.quiet) return level.SILENT

		@@ -0,0 +1,13 @@
		var level = require('./log').levels

		module.exports = function deriveLogLevel (userOptions) {


		if (userOptions.dryRun) return log.info

		if (userOptions.silent \|\| userOptions.quiet) return log.silent

Shore up logging behavior #74

Shore up logging behavior #74

Conversation

jasonkarns commented Dec 18, 2018 • edited Loading

Goals

Proposal

Implementation

TODO or followup

searls commented Dec 18, 2018

codeclimate bot Dec 19, 2018

Choose a reason for hiding this comment

jasonkarns Dec 19, 2018

Choose a reason for hiding this comment

searls Dec 19, 2018

Choose a reason for hiding this comment

codeclimate bot Dec 19, 2018

Choose a reason for hiding this comment

codeclimate bot Dec 19, 2018

Choose a reason for hiding this comment

codeclimate bot Dec 19, 2018

Choose a reason for hiding this comment

codeclimate bot Dec 19, 2018

Choose a reason for hiding this comment

codeclimate bot Dec 21, 2018

Choose a reason for hiding this comment

jasonkarns commented Dec 21, 2018

jasonkarns commented Dec 21, 2018

jasonkarns commented Dec 18, 2018 •

edited

Loading