misc(logger): 1.3.0, package types, timeDecorate, add tests #6740

connorjclark · 2018-12-06T19:59:30Z

Breaking up #6515. This is part one.

Next part will roll out usages of the new timeDecorate functions.

patrickhulce

I think this LGTM!

I think you addressed the specific list of concerns @brendankenny had about usability (stack and debugging I think it was?) but if he's back soon might as well wait for his quick look to double check.

patrickhulce · 2018-12-06T20:23:51Z

lighthouse-logger/index.js

@@ -1,17 +1,59 @@
 /**
- * @license Copyright 2016 Google Inc. All Rights Reserved.


I'm not sure what the policy is here, we haven't historically updated years because we touched the file, but it conceptually makes sense to do 2016-2018 here

@brendankenny you're our usual license police :)

legally it doesnt matter one bit, so let's leave it back on 2016. seems like our rough policy is use current year when introducing new files.

patrickhulce · 2018-12-06T20:24:19Z

lighthouse-logger/index.js

+
+/**
+ * @template {Function} F
+ * @typedef {import('./helpers').ArgumentTypes<F>} ArgumentTypes


WDYT about clarifying that file name as type-helpers?

patrickhulce · 2018-12-06T20:28:10Z

lighthouse-logger/index.js

+      if (typeof opts.msg === 'string') {
+        msg = opts.msg;
+      } else if (typeof opts.msg === 'function') {
+        // TODO turn on --strictBindCallApply when tsc is upgraded to 3.2


🚗 🏁 #6684

patrickhulce · 2018-12-06T20:32:06Z

lighthouse-logger/package.json

  "license": "Apache-2.0",
  "dependencies": {
    "debug": "^2.6.8",
    "marky": "^1.2.0"
+  },
+  "devDependencies": {
+    "@types/debug": "^0.0.31"


none of these types are exposed in our API right?

…ome/lighthouse into issue-6425-auto-mark-pr-logger

patrickhulce · 2018-12-06T21:51:01Z

@hoten might have to hoist that @types/debug travis isn't a happy camper.

paulirish

seems cool. :)

paulirish · 2018-12-07T17:26:47Z

lighthouse-logger/index.js

@@ -1,17 +1,59 @@
 /**
- * @license Copyright 2016 Google Inc. All Rights Reserved.


legally it doesnt matter one bit, so let's leave it back on 2016. seems like our rough policy is use current year when introducing new files.

paulirish · 2018-12-07T17:27:44Z

lighthouse-logger/index.js

   */
  static formatProtocol(prefix, data, level) {
-    const columns = (!process || process.browser) ? Infinity : process.stdout.columns;
+    const columns = isBrowser ? Infinity : (process.stdout.columns || Infinity);


paulirish · 2018-12-07T17:30:21Z

lighthouse-logger/index.js

+        result = originalFn.apply(this, args);
+      } catch (err) {
+        Log.timeEnd(status, timeEndLogLevel);
+        err.stack = err.stack.replace(/.* at timeDecoratedFn .*\n/g, '');


add a comment to explain this hack?

paulirish · 2018-12-07T18:30:42Z

lighthouse-logger/index.js

+    /**
+     * @type {(this: *, ...args: *[]) => string}
+     */
+    const computeMsg = (_this, args) => {


could this fn be as simple as:

const computeMsg = (_this, args) => { if (typeof opts.msg === 'string') return opts.msg; if (typeof opts.msg === 'function') return opts.msg.apply(_this, args); throw new Error('expected msg'); };

and same with computeId()

checking that the first two cases don't return something falsy seems.. unnecessary to me, but w/e

oh ya for sure

this only made sense before I figured out how to strongly type all this. had to verify this at runtime. but now TSC does the heavy lifting here :)

connorjclark · 2018-12-07T19:08:59Z

lighthouse-logger/index.js

+        id = opts.id;
+      } else if (typeof opts.id === 'function') {
+        // TODO turn on --strictBindCallApply when tsc is upgraded to 3.2
+        id = opts.id.apply(this, args);


oops! should be _this

connorjclark · 2018-12-10T23:34:31Z

merged master, fixed some TSC issues and added the strict strictBindCallApply flag (side note, why wasn't it named strictApplyBindCall ...)

brendankenny

Sorry this took so long.

Lots of comments, but the approach looks good. Hopefully some helpful suggestions that can get us 90% of the benefits while simplifying things a bit.

brendankenny · 2018-12-11T01:11:30Z

lighthouse-core/lib/log.js

+'use strict';
+
+/** @type {typeof import('../../lighthouse-logger')} */
+module.exports = require('lighthouse-logger');


is this file used anywhere?

It will be, but I should have removed it as part of breaking up the original PR (#6515). It'll be needed so that importing the logger has types, w/o needing to use the /** @type comment everywhere.

Will delete from this PR.

brendankenny · 2018-12-11T01:13:10Z

lighthouse-logger/index.js

@@ -6,12 +6,54 @@
 'use strict';

 const debug = require('debug');
+// @ts-ignore
 const marky = require('marky');


can you add a type file for marky in types/marky? It looks like it should be fairly minimal.

yah?
It looks like it's basically

declare module 'marky' { class Marky { static mark(name: string): void; static stop(name: string): void; static getEntries(): PerformanceEntry[]; static clear(): void; } export = Marky; }

or whatever of the many variations that would work in types/marky/index.d.ts

brendankenny · 2018-12-11T22:47:29Z

tsconfig.json

@@ -6,6 +6,7 @@
    "allowJs": true,
    "checkJs": true,
    "strict": true,
+    "strictBindCallApply": true,


strict includes strictBindCallApply, so no need to add it as well

I found that this error only happens when setting strictBindCallApply explicitly.

for

/** * @param {Status} param0 * @param {LogAction} level */ static time({msg, id, args = []}, level = 'log') { marky.mark(id); Log[level]('status', msg, ...args); }

I found that this error only happens when setting strictBindCallApply explicitly

Maybe they fixed this in 3.2.1 or 3.2.2? I see the error with or without strictBindCallApply, and strictBindCallApply is indeed a Strict_Type_Checking_Options

brendankenny · 2018-12-11T22:49:29Z

package.json

@@ -31,9 +31,11 @@
    "unit-core:ci": "jest --runInBand --coverage --ci \"lighthouse-core/\"",
    "unit-cli": "jest  --runInBand \"lighthouse-cli/\"",
    "unit-cli:ci": "jest --runInBand --coverage --ci \"lighthouse-cli/\"",
+    "unit-logger": "jest  --runInBand \"lighthouse-logger/\"",
+    "unit-logger:ci": "jest --runInBand --coverage --ci \"lighthouse-logger/\"",


is there a reason this ends up with a different reporter style (reporting each test instead of just each file) than the other unit-* ones? Nothing different is jumping out at me here.

I added a second test file and it switched to the per-file report.

I added a second test file and it switched to the per-file report.

oh. Boooo jest

brendankenny · 2018-12-11T22:51:20Z

lighthouse-logger/type-helpers.d.ts

+ */
+
+export type ArgumentTypes<F extends Function> = F extends (...args: infer A) => any ? A : never;
+export type IsFunction<T> = T extends Function ? T : never;


We've been putting these helpers in types/externs.d.ts (seems fine to have them there and global until(/if) we ever move our types to all be module based)

move to types/externs.d.ts? Or is the issue the lighthouse-logger/lighthouse split?

Since the logger is still its own package it should remain within the lighthouse-logger folder

brendankenny · 2018-12-12T00:00:46Z

lighthouse-logger/index.js

 const isWindows = process.platform === 'win32';

 // process.browser is set when browserify'd via the `process` npm module
+// @ts-ignore


combine the comments? (// @ts-ignore - process.browser is set...)

brendankenny · 2018-12-12T00:01:27Z

lighthouse-logger/index.js

@@ -24,6 +66,7 @@ const colors = {
 };

 // whitelist non-red/yellow colors for debug()
+// @ts-ignore


combine comments (and maybe add something about it being non-public to explain the ts-ignore)

brendankenny · 2018-12-12T00:02:34Z

lighthouse-logger/index.js

@@ -118,33 +174,149 @@ class Log {
    return level_ === 'verbose';
  }

-  static time({msg, id, args = []}, level = 'log') {
+  /**
+   * @param {Status} param0


maybe s/param0/status?

brendankenny · 2018-12-12T00:42:29Z

lighthouse-logger/index.js

+ * @template {*[]} Args
+ * @typedef {{
+ *  msg: string | ((this: Class, ...args: Args) => string),
+ *  id?: string | ((this: Class, ...args: Args) => string),


what if we drop the dynamic messages and only support strings here (at least for now)? It would make this file simpler to read, simpler for type checking, and reduces the non-local reasoning needed where the timeDecorateClass calls are located.

AFAICT, the only places we need dynamically created strings are for

running beforePass/pass/afterPass for a gatherer, and

running an audit

computing a computed artifact.

Due to the structure of gatherRunner there's no good place to decorate the gatherer functions, so #6515 only included dynamic messages for last two. We could do those with manual log.time()/log.timeEnd() calls (only two pairs of them needed) and be able to get rid of a lot of machinery in here.

And then at a later date we can always add support if we find we want it.

It'll be most immediately needed by #6410, since each call to sendCommand has a timing with an id derived from the input. As soon as this lands I'll be pushing that issue forward again. With that in mind, should this stay?

hmm, yeah, that's useful enough that I guess we should probably keep it

brendankenny · 2018-12-12T00:50:19Z

lighthouse-logger/index.js

+        result = originalFn.apply(this, args);
+      } catch (err) {
+        Log.timeEnd(status, timeEndLogLevel);
+        // intercept any errors and elide the time decoration from the stack trace


Sooooo...I should have been more clear in #6425 (comment). I really meant, if the stack traces are bad we should consider this. Are they? Because if not it can be really confusing why all the function calls that actually happened aren't in the trace.

Maybe we should punt on this and add it later if we find the stack traces difficult to work with? Or have you found it helpful to get clean stack traces so far?

(I'm also curious how official decorators plan on handling this)

It didn't really come up, so I can't say I found it useful.

Monitoring tools like Rollbar do their best to clean up calls to their lib functions from stack traces. But our case is very minor, and theirs is an library meant for monitoring ...

I could go either way with this. If you think of a stack trace as primarily a tool developers use to navigate code flow, It's a nice idea to hide function calls. If you want to see exactly the whole picture, you wouldn't want things hidden. I imagine it won't ever come up again either way we go with.

It didn't really come up, so I can't say I found it useful.

OK, cool, sounds like we should remove it then? Keeping the implementation simple(r) is always 👍

connorjclark · 2018-12-12T21:11:31Z

Should have resolved all of your comments now @brendankenny

brendankenny · 2018-12-12T23:35:34Z

lighthouse-logger/index.js

@@ -6,12 +6,54 @@
 'use strict';

 const debug = require('debug');
+// @ts-ignore
 const marky = require('marky');


yah?
It looks like it's basically

declare module 'marky' { class Marky { static mark(name: string): void; static stop(name: string): void; static getEntries(): PerformanceEntry[]; static clear(): void; } export = Marky; }

or whatever of the many variations that would work in types/marky/index.d.ts

brendankenny · 2018-12-12T23:36:07Z

lighthouse-logger/index.js

 debug.colors = [colors.cyan, colors.green, colors.blue, colors.magenta];

 class Emitter extends EventEmitter {
  /**
   * Fires off all status updates. Listen with
   * `require('lib/log').events.addListener('status', callback)`
   * @param {string} title
+   * @param {string|Error} message


brendankenny · 2018-12-13T00:15:29Z

lighthouse-logger/index.js

+        result = originalFn.apply(this, args);
+      } catch (err) {
+        Log.timeEnd(status, timeEndLogLevel);
+        // intercept any errors and elide the time decoration from the stack trace


It didn't really come up, so I can't say I found it useful.

OK, cool, sounds like we should remove it then? Keeping the implementation simple(r) is always 👍

brendankenny · 2018-12-13T00:28:00Z

lighthouse-logger/test/index-test.js

+'use strict';
+
+/* eslint-env jest */
+/* eslint-disable no-invalid-this */


since this is only needed for the "retains this binding" test, isolate to just in there so inadvertent lint errors will still alert

brendankenny · 2018-12-13T00:29:45Z

lighthouse-logger/test/index-test.js

+/* eslint-disable no-invalid-this */
+
+const assert = require('assert');
+const log = require('..');


we're moving to prefer the explicit require('../index.js'); to make everything a bit more explicit

brendankenny · 2018-12-13T00:51:10Z

lighthouse-logger/index.js

+     */
+    const fn = function timeDecoratedFn(...args) {
+      const timeStartLogLevel = opts.timeStartLogLevel || 'log';
+      const timeEndLogLevel = opts.timeEndLogLevel || 'verbose';


move outside fn?

brendankenny · 2018-12-13T00:51:38Z

lighthouse-logger/index.js

+    /**
+     * @type {(this: T, ...args: Args) => R}
+     */
+    const fn = function timeDecoratedFn(...args) {


drop the const fn =, or is there a reason for it?

brendankenny · 2018-12-13T00:52:28Z

lighthouse-logger/index.js

+   * Decorates (like timeDecorate) specified methods of a class.
+   * If decorating instance methods, use the class's prototype.
+   * If decorating static methods, use the class directly.
+   * @template {Object|Function} Class


can we be more specific? This is just any

I want to accept anything newable (classes, so basically any function) or objects (prototypes). I suppose objects and functions covers everything :P

What about something silly like this?

brendankenny · 2018-12-13T01:48:24Z

lighthouse-logger/index.js

+   * If decorating instance methods, use the class's prototype.
+   * If decorating static methods, use the class directly.
+   * @template {Object|Function} Class
+   * @template {keyof Class} Prop


should be limited to properties that are functions? E.g. you can pass a number property in (and it will accept any parameters for msg and id)

this part guards against non-functions:

* @param {{[key in Prop]: TimeDecorateOpts<Class, Parameters<IsFunction<Class[key]>>>}} methods

IsFunction<T> resolves to never if T does not extend Function.

brendankenny · 2018-12-13T01:50:49Z

lighthouse-logger/index.js

+        opts.id = `lh:${className}:${method}`;
+      }
+      /** @type {IsFunction<Class[typeof method]>} */
+      const original = klass[method];


I'm concerned that basically everything in this and the above function are typed as any :)

I wonder if there's something simpler (or defining more in a d.ts file if necessary) to get us some constraints enforced. Or we go the opposite, keeping the interface as strict as possible and going explicitly any inside (this is partially where timeDecorate has gone, at least with the return value).

I'm not sure. My main goal was to only allow property names of functions of klass in methods. The current typing achieves that, but the local typing is a bit out of my reach (or TypeScript's?). But the ol' gut type checker seems right to me (AKA it looks correct).

paulirish · 2019-01-04T01:06:48Z

@brendankenny wanna take a last pass?

connorjclark · 2019-01-15T23:44:25Z

@brendankenny whatcha think?

brendankenny · 2019-01-30T02:17:00Z

OK, so a ton of work went into this, but my vote is to not land it :/

I'm interested in what others think.

Since #3745 landed, it turns out that

all the log.time()/log.timeEnd() calls haven't been nearly the unsightly reading overhead that they appeared that they would be in the beginning, and
many of the LR performance fires have either been put out or haven't needed the higher levels of logging flexibility that we thought we would need

Adding this level of logging, however, adds non-locally-defined behavior to many of our core classes (called in a non-obvious way), isn't sound in our current type system, and adds a lot of complexity that folks who are trying to use or modify lighthouse will need to understand (it's relatively invisible until it runs into a problem, at which point there's a lot of magic to figure out).

So I think the extra complexity for all of Lighthouse isn't worth it at this point. We have some timing numbers today, we can run a profiler when we need more, and we can wait for language-level decorators to hit Stage 4 in Node 12 or whatever and we'll get first-class language and tooling support for them.

patrickhulce · 2019-01-30T02:47:15Z

I think it's a readability improvement and would like to see it land.

That being said @brendankenny brings up some points that make me think I might misunderstand what's going on.

isn't sound in our current type system

Is this referring to it destroying types of what it's used on, or its internal mechanics aren't sound?
I'm fine with the latter, but if it's the former that'd be a deal breaker IMO.

non-locally-defined behavior

Is this just that it's potentially augmenting promises and whatnot or is there something more I might be missing?

adds a lot of complexity that folks who are trying to use or modify lighthouse will need to understand (it's relatively invisible until it runs into a problem, at which point there's a lot of magic to figure out)

I think this is where I'm potentially underestimating. What problems might we foresee that they're even going to be aware of this functionality at all? Right now my impression is it's pretty much just going to be us.

many of the LR performance fires have either been put out

This is a compelling argument for not starting this work, but seeing as it's done... IMO the question becomes what kind of maintenance burden does this become and how much additional work is it. @hoten maybe you have a better sense of this?

we can wait for language-level decorators to hit Stage 4 in Node 12 or whatever and we'll get first-class language and tooling support for them.

(node 12 hits LTS in April 2021)

connorjclark · 2019-02-01T17:41:57Z

I think the improvements to readability are still valid. Take a look at some functions that get reduced to just one line from ~6. Then there's the functions of greater length that are bookended with timing code. I like the idea of moving timing concerns out of functionality.

This is a compelling argument for not starting this work, but seeing as it's done... IMO the question becomes what kind of maintenance burden does this become and how much additional work is it. @hoten maybe you have a better sense of this?

I don't imagine any new functionality would be needed - the dynamic msg and id fields were the big unknown for me going into this, and that's been resolved. I believe the only possible maintenance would come from upgrading TypeScript, but we are basically anying the internals so nothing should break there.

Related to maintenance, how's the usage of timeDecorateClass? It makes plenty sense to me and I'd imagine to anyone looking at one or two instances of usage, but I'm biased.

Is this referring to it destroying types of what it's used on, or its internal mechanics aren't sound?
I'm fine with the latter, but if it's the former that'd be a deal breaker IMO.

The latter. The typing issues don't spread globally across the codebase, just the internal mechanics.

connorjclark · 2019-04-02T22:59:35Z

@brendankenny want to close this?

brendankenny · 2019-04-05T01:07:28Z

want to close this?

I think so. If we get back in a spot where we need much more timing info we can revisit (composing generics has gotten a lot better in tsc 3.3. and 3.4 :)

misc(logger): 1.3.0, package types, timeDecorate, add tests

37270f2

connorjclark requested a review from patrickhulce December 6, 2018 19:59

connorjclark requested review from brendankenny and paulirish as code owners December 6, 2018 19:59

Delete computed-artifact.js

c25a48e

patrickhulce approved these changes Dec 6, 2018

View reviewed changes

connorjclark added 2 commits December 6, 2018 13:35

rename file

7979cc1

Merge branch 'issue-6425-auto-mark-pr-logger' of github.com:GoogleChr…

95d9d96

…ome/lighthouse into issue-6425-auto-mark-pr-logger

hoist @types/debug

9df9f7d

paulirish reviewed Dec 7, 2018

View reviewed changes

connorjclark commented Dec 7, 2018

View reviewed changes

connorjclark added 3 commits December 7, 2018 11:29

pr changes

722d955

Merge branch 'master' into issue-6425-auto-mark-pr-logger

e5e1f5c

tsc 3.2 changes

0cd2951

brendankenny reviewed Dec 12, 2018

View reviewed changes

connorjclark added 4 commits December 11, 2018 17:01

Delete log.js

e28f037

make message required for log fns

eba785a

use tsc builtin Parameters<>

93a8afa

pr changes

c4d5a08

brendankenny reviewed Dec 13, 2018

View reviewed changes

connorjclark added 5 commits December 13, 2018 07:19

pr changes

6bf64d3

update this retain test

2ea9423

_this

2001a5c

remove this type for timeDecorate

b2c7dab

args

83c60f7

paulirish assigned brendankenny Jan 4, 2019

patrickhulce added the waiting4reviewer label Jan 8, 2019

connorjclark added the 4.1 label Jan 15, 2019

connorjclark added 4.2 and removed 4.1 labels Jan 28, 2019

brendankenny closed this Apr 5, 2019

brendankenny deleted the issue-6425-auto-mark-pr-logger branch April 5, 2019 01:07

		@@ -1,17 +1,59 @@
		/**
		* @license Copyright 2016 Google Inc. All Rights Reserved.

misc(logger): 1.3.0, package types, timeDecorate, add tests #6740

misc(logger): 1.3.0, package types, timeDecorate, add tests #6740

Conversation

connorjclark commented Dec 6, 2018

patrickhulce 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

patrickhulce commented Dec 6, 2018

paulirish 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

connorjclark commented Dec 10, 2018

brendankenny 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

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

connorjclark commented Dec 12, 2018

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

connorjclark Dec 13, 2018 • 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

paulirish commented Jan 4, 2019

connorjclark commented Jan 15, 2019

brendankenny commented Jan 30, 2019

patrickhulce commented Jan 30, 2019

connorjclark commented Feb 1, 2019

connorjclark commented Apr 2, 2019

brendankenny commented Apr 5, 2019

connorjclark Dec 13, 2018 •

edited

Loading