Remove ora, use Pino #735

drwpow · 2020-08-04T16:59:05Z

Changes

Part of #648, but since all that won’t fit into one PR, it’s probably important to outline the intended scope of this change:

Goals

Remove Ora
Provide some pattern for easier logging. I’ve grown to like Pino because it’s lightweight, low level, moves logs off the main thread, and has a very nice API, but feedback welcome if there are alternatives.
Provide some way to either silence Snowpack’s output altogether (--silent?), or make it noisier (--debug?)
Provide some logging cleanup, such as fewer lines logged and some consistency improvements (but not all the cleanup).

Non-goals

This does NOT make all logs completely consistent with one another (I think that’ll take multiple passes). However this PR hopefully sets a pattern to make the path to consistency clearer.
This does NOT do anything with the full-screen dev dashboard (possibly an exploration in Ink 3, but will be a big PR either way that can be isolated from this)

Screenshots

Idea: prefix logs with a [name] so users can see what’s logging (e.g. if Snowpack is logging something, or Rollup, or a CLI tool, or it’s user debugging, etc.)

Basic build

Basic install

Plugin errors (note the name)!

Other ideas

Some other thoughts

Permanent once written: There’s no spinner here. After reading more on logging philosophy, best practices, and re-reading the feedback we‘ve gotten from users, I’m almost thinking that redrawing is an anti-pattern in logs (unless you are doing full-screen repaints like in dev). So this moves us toward a philosophy where if we’re logging linearly, it stays. No spinners, no updates, etc. It may not be as cool, but it is friendlier to CI, and doesn’t assume the user is watching a terminal output and miss something (they probably aren’t).
Adds option for no color: Inspired by Rollup, this uses the https://no-color.org/ community spec
Moves logging off main thread: probably a micro-optimization, but I do like the general idea that as we’re logging things we’re doing so efficiently
Common formatting: this lets us run all logs through a formatter function, which means we can get fancy! E.g. automatically color errors red, prefix some messages with an icon, you name it.

Testing

Tests should pass, but evaluating should come down to whether or not the snowpack build and snowpack install commands look good! ✨

vercel · 2020-08-04T16:59:11Z

This pull request is being automatically deployed with Vercel (learn more).
To see the status of your deployment, click below or on the icon next to each commit.

🔍 Inspect: https://vercel.com/pikapkg/snowpack/7gtqdd9zq
✅ Preview: https://snowpack-git-drwpow-logging.pikapkg.vercel.app

packages/snowpack/src/build/build-pipeline.ts

drwpow · 2020-08-04T17:02:18Z

packages/snowpack/src/build/build-pipeline.ts

-      return result;
-    } else {
-      continue;
+    logger.debug(`[${step.name}] running load()`);


Now we have the idea of debug! 🎉. These won’t show unless enabled.

TODO: add a --debug flag or something because the current PR doesn’t have a way to actually show these

Awesome! nit: If I was debugging, I'd want to see what file was loaded. Something like:

Suggested change

logger.debug(`[${step.name}] running load()`);

// TODO: const relativeSrcPath = ...

logger.debug(`[${step.name}] running load() for ${relativeSrcPath}`);

ditto for other hooks as well (although fine to put off if it starts to get confusing about which path to print once the file no longer exists on disk. Maybe just the file name since the load() call would be right above it?)

drwpow · 2020-08-04T17:02:48Z

packages/snowpack/src/build/build-pipeline.ts

+      } else {
+        continue;
+      }
+    } catch (err) {


Change I’ve been thinking about: let plugins throw errors, and we’ll show the result to the user. I personally like that approach better than logging (though they can log, too)

+1, I'm on board, especially for the dev use case.

During build, I'd expect a thrown error to exit the build (or at least, cause it to return an exit code / fail in CI).

drwpow · 2020-08-04T17:03:52Z

packages/snowpack/src/logger.ts

+const BRACKET_NAME_MATCH = /^\[[^\]]+\]/; // match [name] in brackets at beginning of string
+
+/** http://getpino.io/#/docs/pretty */
+function prettifier() {


Since we’re piping all logs through a utility, this is where we can do some consistent formatting.

drwpow · 2020-08-04T17:44:45Z

packages/snowpack/src/commands/install.ts

-      logError(err.message || err);
-      if (err.hint) {
-        // Note: Wait 1ms to guarantee a log message after the spinner
-        setTimeout(() => console.log(err.hint), 1);


clensing snowpack of one of my many sins in this codebase

stramel · 2020-08-04T19:28:34Z

Adds option for no color: Inspired by Rollup, this uses the no-color.org community spec

👍

Provide some way to either silence Snowpack’s output altogether (--silent?), or make it noisier (--debug?)

I like the idea of exposing a --loglevel flag and maybe a few shorthand flags or environment variables?
https://github.com/pinojs/pino/blob/master/docs/api.md#level-string

Overall, I like the direction of this.

FredKSchott

This looks amazing!

I don't see it here, but @snowpack/plugin-run-script currently users the old log() method, and TypeScript specifically was using the messageBus to report it's status via "WORKER_COMPLETE", etc. Make sure that that doesn't break in this PR (you can run a TypeScript CSA app locally to confirm).

I think the argument could be made for run() to get a special logger, since it's sole purpose is to run tooling with Snowpack and connect it's output back into the dev console. A run plugin isn't just logging, but is actually representing a tool's "state" in the dev console / build (ex: "TypeScript is currently failing with 1 error: \n...\n", "TypeScript is currently passing with 0 errors.", etc.)

A good follow up discussion (and then PR) would be to decide what that interface would look like, and then publicly document it for the run hook.

FredKSchott · 2020-08-04T22:54:10Z

packages/snowpack/package.json

@@ -83,8 +83,8 @@
    "mkdirp": "^1.0.3",
    "npm-run-path": "^4.0.1",
    "open": "^7.0.4",
-    "ora": "^4.0.4",


FredKSchott · 2020-08-04T22:56:08Z

packages/snowpack/src/build/build-pipeline.ts

-      return result;
-    } else {
-      continue;
+    logger.debug(`[${step.name}] running load()`);


Awesome! nit: If I was debugging, I'd want to see what file was loaded. Something like:

Suggested change

logger.debug(`[${step.name}] running load()`);

// TODO: const relativeSrcPath = ...

logger.debug(`[${step.name}] running load() for ${relativeSrcPath}`);

ditto for other hooks as well (although fine to put off if it starts to get confusing about which path to print once the file no longer exists on disk. Maybe just the file name since the load() call would be right above it?)

FredKSchott · 2020-08-04T22:57:52Z

packages/snowpack/src/build/build-pipeline.ts

+      } else {
+        continue;
+      }
+    } catch (err) {


+1, I'm on board, especially for the dev use case.

During build, I'd expect a thrown error to exit the build (or at least, cause it to return an exit code / fail in CI).

FredKSchott · 2020-08-04T22:59:01Z

packages/snowpack/src/commands/install.ts

-      logError(err.message || err);
-      if (err.hint) {
-        // Note: Wait 1ms to guarantee a log message after the spinner
-        setTimeout(() => console.log(err.hint), 1);


clensing snowpack of one of my many sins in this codebase

mprinc · 2020-08-05T15:18:03Z

Yes please! :) I had to, literally, record my screen :D or put process.exit() in snowpack to see logs to be able catch some tricky errors while enabling injection of non-compiled npm dependencies:

And yes, pino is great!

drwpow · 2020-08-05T19:35:48Z

.gitignore

@@ -7,7 +7,7 @@ docs/index.md
 lerna-debug.log
 node_modules
 package-lock.json
-packages/**/build
+packages/@snowpack/**/build


So funny enough we were ignoring packages/snowpack/src/build 😅. Oops! (no wonder I could never jump straight to build-pipeline.ts

i was wondering that too!

drwpow · 2020-08-05T19:36:06Z

jest.config.js

@@ -3,4 +3,5 @@ module.exports = {
    '<rootDir>/packages/@snowpack/app-template-', // don’t run tests intended as user examples
    '<rootDir>/test/create-snowpack-app/test-install', // don’t run tests inside our mock create-snowpack-app install
  ],
+  testEnvironment: 'node',


I was hoping this would speed up tests. Sadly, it didn’t.

drwpow · 2020-08-05T19:37:18Z

test/integration/install.test.js

-    /[\u001B\u009B][[\]()#;?]*(?:(?:(?:[a-zA-Z\d]*(?:;[-a-zA-Z\d\/#&.:=?%@~_]*)*)?\u0007)|(?:(?:\d{1,4}(?:;\d{0,4})*)?[\dA-PR-TZcf-ntqry=><~]))/g,
-    '',
-  );
-}


We actually handle this a little better now with the NO_COLOR env var in our test command ("test": "NO_COLOR=true jest …")

drwpow · 2020-08-05T19:37:26Z

test/integration/install.test.js

-    // TODO: remove when ora is replaced
-    if (['dep-types-only', 'error-node-builtin-unresolved'].includes(testName)) {
-      continue; // this test is skipped because the ora failure message causes the output to flake depending on Node version + OS
-    }


We’re testing all the files again! 🎉

drwpow · 2020-08-05T19:39:35Z

packages/snowpack/src/commands/install.ts

@@ -43,19 +44,15 @@ import {
  findMatchingAliasEntry,
 } from '../util.js';

+const logger = createLogger({name: 'snowpack'});


Passing a name in is how logs are prefixed with [snowpack]. This can be changed for plugins (e.g. [@snowpack/plugin-babel] …).

drwpow · 2020-08-05T23:55:27Z

test/integration/error-node-builtin-unresolved/expected-output.win.txt

+[snowpack] Entry module cannot be external (http).
+[snowpack] install skipped (nothing to install)
+[snowpack] ../../../node_modules/bad-node-builtin-pkg/entrypoint.js
+   "XXXX" (Node.js built-in) could not be resolved. (https://www.snowpack.dev/#node-built-in-could-not-be-resolved)


@FredKSchott I tried

At least we sorta re-enabled this test! Now we’re not skipping anything 🎉

this feels like a great solution

FredKSchott

+1, this is good to merge for me!

Comment for after merging: I know you mentioned wanting to add --debug and --silent modes, just checking that that's still in your plan since those are usually a more intuitive for a user who doesn't know what different log levels mean.

I'm fine supporting all 3 (those two + --log-level) or just those two.

FredKSchott · 2020-08-06T19:31:35Z

packages/snowpack/src/build/build-pipeline.ts

+          filePath,
+          isDev,
+          // @ts-ignore: internal API only
+          log: (msg, data: any = {}) => {


now that we have a good logger, we can pass it directly to the different plugin hooks as our documented, public way to log. Since these are internal only at the moment, no worries about breaking changes.

I like that. Also using a documented logger like Pino seems easy-to-use, too.

drwpow · 2020-08-06T19:31:37Z

I know you mentioned wanting to add --debug and --silent modes, just checking that that's still in your plan

Yeah I went back-and-forth on that. Some things have them; others don’t. We’ll need --log-level no matter what, but maybe those two would make good shortcuts? But that can happen in a followup.

drwpow commented Aug 4, 2020

View reviewed changes

packages/snowpack/src/build/build-pipeline.ts Outdated Show resolved Hide resolved

drwpow commented Aug 4, 2020

View reviewed changes

drwpow force-pushed the drwpow/logging branch from 752a5bf to 0f55d32 Compare August 4, 2020 17:13

vercel bot deployed to Preview August 4, 2020 17:13 View deployment

drwpow commented Aug 4, 2020

View reviewed changes

drwpow force-pushed the drwpow/logging branch from 0f55d32 to 999aa7c Compare August 4, 2020 17:45

vercel bot deployed to Preview August 4, 2020 17:45 View deployment

FredKSchott approved these changes Aug 4, 2020

View reviewed changes

drwpow force-pushed the drwpow/logging branch from 999aa7c to 125cdab Compare August 5, 2020 15:13

vercel bot deployed to Preview August 5, 2020 15:13 View deployment

drwpow force-pushed the drwpow/logging branch from 125cdab to cc49907 Compare August 5, 2020 18:51

vercel bot deployed to Preview August 5, 2020 18:51 View deployment

Remove ora, use Pino

2199c83

drwpow force-pushed the drwpow/logging branch from cc49907 to 2199c83 Compare August 5, 2020 19:32

vercel bot deployed to Preview August 5, 2020 19:32 View deployment

drwpow changed the title ~~[Draft] Remove ora, use Pino~~ Remove ora, use Pino Aug 5, 2020

drwpow marked this pull request as ready for review August 5, 2020 19:34

drwpow requested a review from a team as a code owner August 5, 2020 19:34

drwpow commented Aug 5, 2020

View reviewed changes

Add some CLI flags to docs

1273b5b

vercel bot deployed to Preview August 5, 2020 19:45 View deployment

Add log level to build pipeline

52d5392

drwpow force-pushed the drwpow/logging branch from 0f647e6 to 52d5392 Compare August 5, 2020 19:46

vercel bot deployed to Preview August 5, 2020 19:46 View deployment

vercel bot deployed to Preview August 5, 2020 19:53 View deployment

drwpow force-pushed the drwpow/logging branch from 7017fe1 to 5e66960 Compare August 5, 2020 20:03

vercel bot deployed to Preview August 5, 2020 20:03 View deployment

drwpow force-pushed the drwpow/logging branch from 5e66960 to 2679435 Compare August 5, 2020 21:47

vercel bot deployed to Preview August 5, 2020 21:47 View deployment

Restore run-script event emitter

d9e1db3

drwpow force-pushed the drwpow/logging branch from 2679435 to d9e1db3 Compare August 5, 2020 23:45

vercel bot deployed to Preview August 5, 2020 23:45 View deployment

drwpow requested a review from FredKSchott August 5, 2020 23:54

drwpow commented Aug 5, 2020

View reviewed changes

FredKSchott approved these changes Aug 6, 2020

View reviewed changes

drwpow merged commit 9adc85a into master Aug 6, 2020

drwpow deleted the drwpow/logging branch August 6, 2020 19:30

FredKSchott reviewed Aug 6, 2020

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Remove ora, use Pino #735

Remove ora, use Pino #735

drwpow commented Aug 4, 2020 •

edited

vercel bot commented Aug 4, 2020 •

edited

drwpow Aug 4, 2020

FredKSchott Aug 4, 2020 •

edited

drwpow Aug 5, 2020

drwpow Aug 4, 2020

FredKSchott Aug 4, 2020

drwpow Aug 4, 2020

drwpow Aug 4, 2020

FredKSchott Aug 4, 2020

stramel commented Aug 4, 2020

FredKSchott left a comment

FredKSchott Aug 4, 2020

FredKSchott Aug 4, 2020 •

edited

FredKSchott Aug 4, 2020

FredKSchott Aug 4, 2020

mprinc commented Aug 5, 2020 •

edited

drwpow Aug 5, 2020

FredKSchott Aug 6, 2020

drwpow Aug 5, 2020

drwpow Aug 5, 2020

drwpow Aug 5, 2020

drwpow Aug 5, 2020

drwpow Aug 5, 2020

FredKSchott Aug 6, 2020

FredKSchott left a comment

FredKSchott Aug 6, 2020

drwpow Aug 6, 2020

drwpow commented Aug 6, 2020

	logger.debug(`[${step.name}] running load()`);
	// TODO: const relativeSrcPath = ...
	logger.debug(`[${step.name}] running load() for ${relativeSrcPath}`);

Remove ora, use Pino #735

Remove ora, use Pino #735

Conversation

drwpow commented Aug 4, 2020 • edited

Changes

Screenshots

Other ideas

Testing

vercel bot commented Aug 4, 2020 • edited

Choose a reason for hiding this comment

FredKSchott Aug 4, 2020 • edited

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

stramel commented Aug 4, 2020

FredKSchott left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FredKSchott Aug 4, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mprinc commented Aug 5, 2020 • edited

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

FredKSchott left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

drwpow commented Aug 6, 2020

drwpow commented Aug 4, 2020 •

edited

vercel bot commented Aug 4, 2020 •

edited

FredKSchott Aug 4, 2020 •

edited

FredKSchott Aug 4, 2020 •

edited

mprinc commented Aug 5, 2020 •

edited