phetsims / perennial

Maintenance tools that won't change with different versions of chipper checked out
MIT License
3 stars 5 forks source link

upgrade winston to latest #201

Open zepumph opened 3 years ago

zepumph commented 3 years ago

This is causing https://github.com/phetsims/chipper/issues/993 when loading perennials' gruntfile.

I applied this patch, but it didn't work right out of the bag, likely because winston's api has changed:

Index: package.json
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- package.json    (revision 00c8e4b97f5360c17efa7e4e0e6b819c5c0ae64d)
+++ package.json    (date 1605567703375)
@@ -23,7 +23,7 @@
     "rsync": "^0.6.1",
     "request-promise-native": "^1.0.5",
     "thread-sleep": "^2.0.0",
-    "winston": "^0.9.0",
+    "winston": "^3.3.3",
     "winston-loggly": "^1.3.1",
     "xml2js": "^0.4.15",
     "puppeteer": "^5.4.1",

I'm not sure what the priority of this issue should be, or who is responsible for winston in this repo. I don't know why our gruntfile uses winston, since it was meant to be logging for the build-server.

zepumph commented 3 years ago

When I apply this patch, I get messages like this for grunt print-phet-io-links:

 Michael ~/PhET/git/perennial (master)
 $ grunt print-phet-io-links
Running "print-phet-io-links" task
[winston] Attempt to write logs with no transports {"message":"getting phet-io metadata request with https://phet.colorado.edu/services/metadata/phetio?&active=true&latest=true","level":"info"}
[winston] Attempt to write logs with no transports {"message":"git checkout 1.2 on balancing-act","level":"info"}
[winston] Attempt to write logs with no transports {"message":"running git checkout 1.2 from ../balancing-act","level":"debug"}
[winston] Attempt to write logs with no transports {"message":"stdout: Your branch is behind 'origin/1.2' by 8 commits, and can be fast-forwarded.\n  (use \"git pull\" to update your local branch)\n","level":"debug"}
[winston] Attempt to write logs with no transports {"message":"stderr: Switched to branch '1.2'\n","level":"debug"}
[winston] Attempt to write logs with no transports {"message":"getting dependencies.json for balancing-act","level":"info"}

When I add this patch, I then get messages that look like this:

Index: js/grunt/Gruntfile.js
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- js/grunt/Gruntfile.js   (revision 00c8e4b97f5360c17efa7e4e0e6b819c5c0ae64d)
+++ js/grunt/Gruntfile.js   (date 1605568794317)
@@ -43,6 +43,8 @@

 module.exports = function ( grunt ) {

+  winston.add( new winston.transports.Console() );
+
   if ( grunt.option( 'debug' ) ) {
     winston.default.transports.console.level = 'debug';
   }
 Michael ~/PhET/git/perennial (master)
 $ grunt print-phet-io-links
Running "print-phet-io-links" task
{"message":"getting phet-io metadata request with https://phet.colorado.edu/services/metadata/phetio?&active=true&latest=true","level":"info"}
{"message":"git checkout 1.2 on balancing-act","level":"info"}
{"message":"getting dependencies.json for balancing-act","level":"info"}
{"message":"git checkout master on balancing-act","level":"info"}
{"message":"git check (in chipper) for whether 8db0653ee0cbb6ed716fa3b4d4759bcb75d8118a is an ancestor of 2aa9c4c6b8e8f29bc50288065706c34ec65c3980","level":"info"}
{"message":"git checkout 1.3-phetio on balloons-and-static-electricity","level":"info"}
{"message":"getting dependencies.json for balloons-and-static-electricity","level":"info"}
{"message":"git checkout master on balloons-and-static-electricity","level":"info"}

I don't know how winston is used in the build-server, but log.js would need to be brought up to a new API. I think also that we would want to use the upgrade guide https://github.com/winstonjs/winston/blob/HEAD/UPGRADE-3.0.md.

This is more work the getting rid of find-duplicates over in https://github.com/phetsims/chipper/issues/993, but it may not be too bad, and feels like we should upgrade since we are currently on a version before 1.0.

Over to @ariel-phet to see about getting rid of this warning in perennial.

ariel-phet commented 3 years ago

@jbphet @muedli is this Rosetta related? If so, perhaps something @muedli could tackle?

jbphet commented 3 years ago

It's not directly related to Rosetta, but we do use the same logger (winston) in both the build-server and rosetta, so @muedli could probably take care of it. Since it is build server code, which is pretty critical to our day-to-day operations, I would propose that @muedli make the changes and then have @mattpen review and approve them, and @mattpen should also deploy them since he is much more experienced with it.

@muedli - let us know if you're not comfortable with this.

@ariel-phet - assigning back to you too to make sure that you see my update.

ariel-phet commented 3 years ago

Sounds like a great plan to me @jbphet and a good experience for @muedli

samreid commented 3 years ago

Can we please increase the priority of this? It is unnecessary noise in many of our perennial operations. If @muedli won't be able to get to it soon, is this something @mattpen can work on? I noticed he added winston originally (at least to package.json).

UPDATE: Until this issue is fully addressed (if it will take more than a few business days), should we consider using Winston 2.4.5 which omits the error and may be more API compatible than 3.0? I read about it in https://github.com/winstonjs/winston/issues/1797#issuecomment-647300157 (not linked so our issue doesn't show up in their thread.

liammulh commented 3 years ago

@samreid, I haven't started work on this issue. I will take a look at it tomorrow and determine how long it will take. I will post an update in this issue.

liammulh commented 3 years ago

Update

I tried:

This didn't fix MK's problem. I stashed my changes. I think I'll have to look at invocations of Winston on a more granular level to see what's going on here. I probably won't be able to sink much time into this tomorrow.

@samreid, I also tried updating Winston to v2.4.5 and the output of grunt print-phet-io-links looked normal. I think we should update Winston to v2.4.5 for the time being.

liammulh commented 3 years ago

@samreid, if you scroll a bit further in the issue you posted (https://github.com/winstonjs/winston/issues/1797#issuecomment-730828150), it seems the issue can still happen when you've updated to v2.4.5. I still think we should update to v2.4.5 as a stop-gap measure to see if that would reduce the noise you speak of.

samreid commented 3 years ago

I updated to 2.4.5 locally without pushing changes to package.json and so far simple scripts like https://github.com/phetsims/perennial/issues/206 seem OK. But I haven't tried deploys or more complicated work. Perhaps it would be best to see if @mattpen can advise on a long-term solution? I don't know enough about how winston is used to attempt an upgrade to 3 on my own.

mattpen commented 3 years ago

@muedli - let's schedule some time next week to see if we can get this working.

liammulh commented 3 years ago

@mattpen and I worked on this today.

I'm going to

samreid commented 3 years ago

What is the proposed timeline for this issue? If it will take a long time, can we investigate upgrading to 2.4.5 to clean up our console output? I have been using 2.4.5 for a few months now and haven't noticed any adverse side-effects (though I know I don't run all of the tasks).

liammulh commented 3 years ago

@samreid, this fell off my radar. I will put it on my list of things to do, but I suspect I won't get around to it this week. The next two weeks or so are also busy in terms of school, but if there's a lull in QA I will spend some time on it. Once the semester is over (end of April), I should have plenty of time to work.

samreid commented 3 years ago

I updated to winston 2.4.5, which is the first minor problem that doesn't exhibit the problem:

(node:63283) Warning: Accessing non-existent property 'padLevels' of module exports inside circular dependency
(Use `node --trace-warnings ...` to show where the warning was created)

The winston changelog is here: https://github.com/winstonjs/winston/blob/master/CHANGELOG.md.

Here are the breaking changes between 0.9.0 and 2.4.5:

#587 Do not extend String prototypes as a side effect of using colors. (kenperkins)
#581 File transports now emit error on error of the underlying streams after maxRetries attempts. (ambbell).
#583, 92729a Use os.EOL for all file writing by default. (Mik13, indexzero)
#532 Delete logger instance from Container when close event is emitted. (snater)
#380 Rename duration to durationMs, which is now a number a not a string ending in ms. (neoziro)
#253 Do not set a default level. When level is falsey on any Transport instance, any Logger instance uses the configured level (instead of the Transport level) (jstamerj).

e0c9dde Remove winston.transports.Webhook. Use winston.transports.Http instead.
f71e638 Remove Logger.prototype.addRewriter and Logger.prototype.addFilter since they just push to an Array of functions. Use logger.filters.push or logger.rewriters.push explicitly instead.
a470ab5 No longer respect the handleExceptions option to new winston.Logger. Instead just pass in the exceptionHandlers option itself.
8cb7048 Removed Logger.prototype.extend functionality

0f82204 Move winston.transports.DailyRotateFile into a separate module: require('winston-daily-rotate-file');
fb9eec0 Reverse log levels in npm and cli configs to conform to RFC524. Fixes #424 #406 #290
8cd8368 Change the method signature to a filter function to be consistent with rewriter and log functions:

Marking as blocks-publication until we do a publication or two to make sure there are no problems on our build chain.

zepumph commented 3 years ago

@samreid mentioned during today's dev meeting that this wouldn't block publication for something, but that we should be on the look out about potential issues that this caused. @samreid and I will restart the build server to make sure that there are no problems there also.

Otherwise this is not blocking anymore. We can continue with the full upgrade.

zepumph commented 3 years ago

@samreid and I restarted build server and tested things out by ensuring that perennial was up to date on the build server, and then rc building chains. We saw in the logs that no usage of padLevels occurred. Ready to unblock.

liammulh commented 2 years ago

It looks like chipper is no longer using Winston as a logger. @samreid, @zepumph, can this issue be closed?

liammulh commented 2 years ago

Wow, that's embarrassing! Wrong repo.

liammulh commented 2 years ago

Okay, I'm not able to repro MK's problem, but since there are so many files affected by these changes, I think I probably need to pair with someone to test the changes a bit more extensively before I push them.