Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(ado-improvement-1): Intercept & adjust logging in scan process #1030

Merged
merged 18 commits into from Feb 8, 2022

Conversation

DaveTryon
Copy link
Contributor

@DaveTryon DaveTryon commented Feb 4, 2022

Details

As called out in #950, our logging output is hard to read because of a lot of noise that is inconsistently formatted. This PR helps to reduce the noise by blocking some of the noise completely, while other output is formatted to make it easier to filter in tools. Much of the logging is coming from transitive dependencies that are difficult to change, so the traditional approach of injecting a Logger into the class doesn't really do what we need. Instead, we intercept the stdout and stderr output streams where the data gets written, and apply a customized transformer to either remove or reformat the output, depending on the specific need.

Motivation

Part of ADO improvement feature

Output
Output before these changes--includes waitFor errors, mixes [Trace][info] and INFO as header tags in the stream, and has no ##[debug] header on things written by the extension:
packages/ado-extension >yarn start
yarn run v1.22.11
$ node scripts/run-locally.js
run-locally.js is setting up input outputDir to value _accessibility-reports
run-locally.js is setting up input siteDir to value .
run-locally.js is setting up input scanUrlRelativePath to value /
run-locally.js is setting up input maxUrls to value 100
run-locally.js is setting up input scanTimeout to value 90000
run-locally.js is setting up input singleWorker to value true
run-locally.js is setting up input url to value https://markreay.github.io/AU/before.html
beginning task execution below

installing runtime dependencies...
[1/4] πŸ”  Resolving packages...
warning Lockfile has incorrect entry for "apify-shared@^0.5.0". Ignoring it.
warning Lockfile has incorrect entry for "socket.io@^2.3.0". Ignoring it.
warning Lockfile has incorrect entry for "underscore@1.12.1". Ignoring it.
warning Lockfile has incorrect entry for "apify-shared@^0.6.0". Ignoring it.
warning Lockfile has incorrect entry for "apify-shared@^0.1.45". Ignoring it.
warning Lockfile has incorrect entry for "css-what@^5.0.0". Ignoring it.
warning Lockfile has incorrect entry for "http-signature@~1.2.0". Ignoring it.
warning Lockfile has incorrect entry for "css-what@2.1". Ignoring it.
warning Lockfile has incorrect entry for "nth-check@~1.0.1". Ignoring it.
warning accessibility-insights-scan > apify > socket.io > debug@4.1.1: Debug versions >=3.2.0 <3.2.7 || >=4 <4.3.1 have a low-severity ReDos regression when used in a Node.js environment. It is recommended you upgrade to 3.2.7 or 4.3.1. (https://github.com/visionmedia/debug/issues/797)
warning accessibility-insights-scan > apify > socket.io > engine.io > debug@4.1.1: Debug versions >=3.2.0 <3.2.7 || >=4 <4.3.1 have a low-severity ReDos regression when used in a Node.js environment. It is recommended you upgrade to 3.2.7 or 4.3.1. (https://github.com/visionmedia/debug/issues/797)
warning accessibility-insights-scan > apify > socket.io > socket.io-parser > debug@4.1.1: Debug versions >=3.2.0 <3.2.7 || >=4 <4.3.1 have a low-severity ReDos regression when used in a Node.js environment. It is recommended you upgrade to 3.2.7 or 4.3.1. (https://github.com/visionmedia/debug/issues/797)
warning Lockfile has incorrect entry for "axios@^0.21.1". Ignoring it.
warning Lockfile has incorrect entry for "marked@^2.0.0". Ignoring it.
[2/4] 🚚  Fetching packages...
[3/4] πŸ”—  Linking dependencies...
warning "accessibility-insights-report > office-ui-fabric-react@7.98.1" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react@7.98.1" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @fluentui/react-focus@7.18.1" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @fluentui/react-focus@7.18.1" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/foundation@7.10.1" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/foundation@7.10.1" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks@7.14.0" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks@7.14.0" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/utilities@7.33.5" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/utilities@7.33.5" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks > @fluentui/react-window-provider@1.0.2" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks > @fluentui/react-window-provider@1.0.2" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/styling > @fluentui/theme@1.7.4" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/styling > @fluentui/theme@1.7.4" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
[4/4] πŸ”¨  Building fresh packages...
##vso[task.debug]agent.TempDirectory=undefined
##vso[task.debug]agent.workFolder=undefined
##vso[task.debug]loading inputs and endpoints
##vso[task.debug]loading INPUT_OUTPUTDIR
##vso[task.debug]loading INPUT_SITEDIR
##vso[task.debug]loading INPUT_SCANURLRELATIVEPATH
##vso[task.debug]loading INPUT_MAXURLS
##vso[task.debug]loading INPUT_SCANTIMEOUT
##vso[task.debug]loading INPUT_SINGLEWORKER
##vso[task.debug]loading INPUT_URL
##vso[task.debug]loaded 7
##vso[task.debug]Agent.ProxyUrl=undefined
##vso[task.debug]Agent.CAInfo=undefined
##vso[task.debug]Agent.ClientCert=undefined
##vso[task.debug]Agent.SkipCertValidation=undefined
##vso[task.debug]scanTimeout=90000
##vso[task.debug]url=https://markreay.github.io/AU/before.html
##vso[task.debug]inputFile=undefined
##vso[task.debug]inputUrls=undefined
##vso[task.debug]discoveryPatterns=undefined
##vso[task.debug]outputDir=_accessibility-reports
##vso[task.debug]maxUrls=100
##vso[task.debug]chromePath=undefined
##vso[task.debug]url=https://markreay.github.io/AU/before.html
##vso[task.debug]singleWorker=true
##vso[task.debug]baselineFile=undefined
[Trace][info] === Starting accessibility scanning of URL https://markreay.github.io/AU/before.html
[Trace][info] === Chrome app executable: system default
INFO  PuppeteerCrawler:AutoscaledPool:Snapshotter: Setting max memory of this run to 4096 MB. Use the APIFY_MEMORY_MBYTES environment variable to override it.
INFO  PuppeteerCrawler:AutoscaledPool: state {"currentConcurrency":0,"desiredConcurrency":1,"systemStatus":{"isSystemIdle":true,"memInfo":{"isOverloaded":false,"limitRatio":0.2,"actualRatio":null},"eventLoopInfo":{"isOverloaded":false,"limitRatio":0.4,"actualRatio":null},"cpuInfo":{"isOverloaded":false,"limitRatio":0.4,"actualRatio":null},"clientInfo":{"isOverloaded":false,"limitRatio":0.3,"actualRatio":null}}}
INFO  Launching Puppeteer {"args":["--disable-dev-shm-usage","--no-sandbox","--disable-setuid-sandbox","--js-flags=--max-old-space-size=8192","--no-sandbox","--user-agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.75 Safari/537.36"],"defaultViewport":{"width":1920,"height":1080,"deviceScaleFactor":1},"timeout":15000,"headless":true}
waitFor is deprecated and will be removed in a future release. See https://github.com/puppeteer/puppeteer/issues/6214 for details and how to migrate your code.
waitFor is deprecated and will be removed in a future release. See https://github.com/puppeteer/puppeteer/issues/6214 for details and how to migrate your code.
waitFor is deprecated and will be removed in a future release. See https://github.com/puppeteer/puppeteer/issues/6214 for details and how to migrate your code.
Processing page https://markreay.github.io/AU/before.html
Discovered 4 links on page https://markreay.github.io/AU/before.html
Found 4 accessibility issues on page https://markreay.github.io/AU/before.html
INFO  PuppeteerCrawler: All the requests from request list and/or request queue have been processed, the crawler will shut down.
INFO  PuppeteerCrawler: Final request statistics: {"requestAvgFailedDurationMillis":null,"requestAvgFinishedDurationMillis":5224,"requestsFinishedPerMinute":11,"requestsFailedPerMinute":0,"requestTotalDurationMillis":5224,"requestsTotal":1,"crawlerRuntimeMillis":5325,"requestsFinished":1,"requestsFailed":0,"retryHistogram":[1]}
##vso[task.debug]outputDir=_accessibility-reports
[Trace][info] === Scan report saved successfully as ./packages/ado-extension/dist/pkg/_accessibility-reports/index.html
##vso[task.debug]failOnAccessibilityError=undefined
[Trace][info] === Accessibility scanning of URL https://markreay.github.io/AU/before.html completed
✨  Done in 64.58s.
Output after these changes--excludes waitFor errors. Normalizes [Trace][info] and INFO header tags to ##[debug] in the stream, and also adds '##[debug] ' prefix to output from the extension: A later PR will make this smarter about handling errors (Exceptions or otherwise)
packages/ado-extension >yarn start 
yarn run v1.22.11
$ node scripts/run-locally.js
run-locally.js is setting up input outputDir to value _accessibility-reports
run-locally.js is setting up input siteDir to value .
run-locally.js is setting up input scanUrlRelativePath to value /
run-locally.js is setting up input maxUrls to value 100
run-locally.js is setting up input scanTimeout to value 90000
run-locally.js is setting up input singleWorker to value true
run-locally.js is setting up input url to value https://markreay.github.io/AU/before.html
beginning task execution below

installing runtime dependencies...
[1/4] πŸ”  Resolving packages...
[2/4] 🚚  Fetching packages...
[3/4] πŸ”—  Linking dependencies...
warning "accessibility-insights-report > office-ui-fabric-react@7.98.1" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react@7.98.1" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @fluentui/react-focus@7.18.1" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @fluentui/react-focus@7.18.1" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/foundation@7.10.1" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/foundation@7.10.1" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks@7.14.0" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks@7.14.0" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/utilities@7.33.5" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/utilities@7.33.5" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks > @fluentui/react-window-provider@1.0.2" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/react-hooks > @fluentui/react-window-provider@1.0.2" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/styling > @fluentui/theme@1.7.4" has unmet peer dependency "@types/react@>=16.8.0 <17.0.0".
warning "accessibility-insights-report > office-ui-fabric-react > @uifabric/styling > @fluentui/theme@1.7.4" has unmet peer dependency "@types/react-dom@>=16.8.0 <17.0.0".
[4/4] πŸ”¨  Building fresh packages...
##vso[task.debug]agent.TempDirectory=undefined
##vso[task.debug]agent.workFolder=undefined
##vso[task.debug]loading inputs and endpoints
##vso[task.debug]loading INPUT_OUTPUTDIR
##vso[task.debug]loading INPUT_SITEDIR
##vso[task.debug]loading INPUT_SCANURLRELATIVEPATH
##vso[task.debug]loading INPUT_MAXURLS
##vso[task.debug]loading INPUT_SCANTIMEOUT
##vso[task.debug]loading INPUT_SINGLEWORKER
##vso[task.debug]loading INPUT_URL
##vso[task.debug]loaded 7
##vso[task.debug]Agent.ProxyUrl=undefined
##vso[task.debug]Agent.CAInfo=undefined
##vso[task.debug]Agent.ClientCert=undefined
##vso[task.debug]Agent.SkipCertValidation=undefined
##vso[task.debug]scanTimeout=90000
##vso[task.debug]url=https://markreay.github.io/AU/before.html
##vso[task.debug]inputFile=undefined
##vso[task.debug]inputUrls=undefined
##vso[task.debug]discoveryPatterns=undefined
##vso[task.debug]outputDir=_accessibility-reports
##vso[task.debug]maxUrls=100
##vso[task.debug]chromePath=undefined
##vso[task.debug]url=https://markreay.github.io/AU/before.html
##vso[task.debug]singleWorker=true
##vso[task.debug]baselineFile=undefined
##[debug] Starting accessibility scanning of URL https://markreay.github.io/AU/before.html
##[debug] Chrome app executable: system default
##[debug]  PuppeteerCrawler:AutoscaledPool:Snapshotter: Setting max memory of this run to 4096 MB. Use the APIFY_MEMORY_MBYTES environment variable to override it.
##[debug]  PuppeteerCrawler:AutoscaledPool: state {"currentConcurrency":0,"desiredConcurrency":1,"systemStatus":{"isSystemIdle":true,"memInfo":{"isOverloaded":false,"limitRatio":0.2,"actualRatio":null},"eventLoopInfo":{"isOverloaded":false,"limitRatio":0.4,"actualRatio":null},"cpuInfo":{"isOverloaded":false,"limitRatio":0.4,"actualRatio":null},"clientInfo":{"isOverloaded":false,"limitRatio":0.3,"actualRatio":null}}}
##[debug]  Launching Puppeteer {"args":["--disable-dev-shm-usage","--no-sandbox","--disable-setuid-sandbox","--js-flags=--max-old-space-size=8192","--no-sandbox","--user-agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.75 Safari/537.36"],"defaultViewport":{"width":1920,"height":1080,"deviceScaleFactor":1},"timeout":15000,"headless":true}
##[debug] Processing page https://markreay.github.io/AU/before.html
##[debug] Discovered 4 links on page https://markreay.github.io/AU/before.html
##[debug] Found 4 accessibility issues on page https://markreay.github.io/AU/before.html
##[debug]  PuppeteerCrawler: All the requests from request list and/or request queue have been processed, the crawler will shut down.
##[debug]  PuppeteerCrawler: Final request statistics: {"requestAvgFailedDurationMillis":null,"requestAvgFinishedDurationMillis":2723,"requestsFinishedPerMinute":21,"requestsFailedPerMinute":0,"requestTotalDurationMillis":2723,"requestsTotal":1,"crawlerRuntimeMillis":2821,"requestsFinished":1,"requestsFailed":0,"retryHistogram":[1]}
##vso[task.debug]outputDir=_accessibility-reports
##[debug] Scan report saved successfully as /Users/dtryon/repos/ada/action/MyFork/packages/ado-extension/dist/pkg/_accessibility-reports/index.html
##vso[task.debug]failOnAccessibilityError=undefined
##[debug] Accessibility scanning of URL https://markreay.github.io/AU/before.html completed
✨  Done in 8.21s.
Context

Pull request checklist

  • Addresses an existing issue: Improvees Task log output is too verbose, difficult to readΒ #950
  • Added relevant unit test for your changes. (yarn test)
  • Verified code coverage for the changes made. Check coverage report at: <rootDir>/test-results/unit/coverage
  • Ran precheckin (yarn precheckin)

@DaveTryon DaveTryon requested a review from a team as a code owner February 4, 2022 22:11
import { hookStream } from './hook-stream';
import { Writable } from 'stream';

/* eslint-disable @typescript-eslint/no-explicit-any */
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lint isn't a fan of any as a parameter type, but that's what the Node uses. It might be possible to scope these to single lines, but then we just have more of them. Happy to entertain options for other ways to accomplish this without needing the overrides.

// Copyright (c) Microsoft Corporation. All rights reserved.
// Licensed under the MIT License.

/* eslint-disable @typescript-eslint/unbound-method */
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lint isn't a fan of any as a parameter type, but that's what the Node uses. It might be possible to scope these to single lines, but then we just have more of them. Happy to entertain options for other ways to accomplish this without needing the overrides.

};

// This class simply records the contents of any _write calls for validation
class TestStream extends Writable {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried unsuccessfully to use a Mock here, but was ultimately unable to get things to work. The TestStream class allowed me to compactly mock out the piece that I care about. Please let me know if you have better ideas on how to do this.

method: (rawData: string, regex?: RegExp) => string;
};

const regexTransformations: RegexTransformation[] = [
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The first iteration of this code defaulted to not marking the output as ##[debug], but that would be difficult to maintain. This version reverses that and will prepend `##[debug] unless we find a regex-based reason not to mark it. We'll need to update this when we figure out how we report the final error, but this sets us up for that.


return prependDebugPrefix(rawData);
};

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is easy to pull into a separate file if stderr-transformer later needs to support regex


export const stderrTransformer = (rawData: string): string => {
if (rawData.startsWith('waitFor is deprecated')) return null;
if (rawData.startsWith('Some icons were re-registered.')) return null;
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The icon message just started to appear in my branch. It doesn't appear in main and I don't know where it came from, but it's not a user-actionable message either way

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

πŸ‘

@DaveTryon DaveTryon merged commit a27ffb2 into microsoft:main Feb 8, 2022
@DaveTryon DaveTryon deleted the ExploreStreamHandling branch February 8, 2022 20:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants