feat: Automatically capture Winston logs per-snapshot (#343)

* Update winston to 3.x

The biggest change is how formatting is applied. Winston 3 does not have default
formatting and format-specific options like showLevel and label have been moved
into a more robust format syntax.

* Capture and upload per-snapshot logs

* Pass snapshot logger on to service handlers

A multitude of services are involved when taking a snapshot. The agent service
creates the snapshot logger when a snapshot is taken, it then passes it onto the
snapshot service, which passes it to the asset discovery service, which passes
it to the resource service, which then passes it to the response service.

* Tell winston to send error logs to stderr

In winston 3.x this is no longer the default behavior

package.json

@@ -35,7 +35,7 @@
     "percy-client": "^3.0.3",
     "puppeteer": "^1.13.0",
     "retry-axios": "^1.0.1",
-    "winston": "^2.0.0"
+    "winston": "^3.0.0"
   },
   "devDependencies": {
     "@babel/core": "^7.4.0",

src/commands/percy-command.ts

@@ -9,7 +9,7 @@ export default class PercyCommand extends Command {
 
   agentService: AgentService
   processService: ProcessService
-  logger: winston.LoggerInstance
+  logger: winston.Logger
   percyToken: string
 
   constructor(argv: string[], config: any) {

src/services/agent-service.ts

@@ -1,11 +1,13 @@
 import * as bodyParser from 'body-parser'
 import * as cors from 'cors'
 import * as express from 'express'
-import {Server} from 'http'
+import { Server } from 'http'
+import * as os from 'os'
+import * as path from 'path'
 import { Configuration } from '../configuration/configuration'
-import {SnapshotOptions} from '../percy-agent-client/snapshot-options'
-import logger, {profile} from '../utils/logger'
-import {HEALTHCHECK_PATH, SNAPSHOT_PATH, STOP_PATH} from './agent-service-constants'
+import { SnapshotOptions } from '../percy-agent-client/snapshot-options'
+import logger, { createFileLogger, profile } from '../utils/logger'
+import { HEALTHCHECK_PATH, SNAPSHOT_PATH, STOP_PATH } from './agent-service-constants'
 import BuildService from './build-service'
 import ConfigurationService from './configuration-service'
 import Constants from './constants'
@@ -79,13 +81,15 @@ export class AgentService {
       domSnapshotLog += `[truncated at ${Constants.MAX_LOG_LENGTH}]`
     }
 
-    logger.debug('handling snapshot:')
-    logger.debug(`-> headers: ${JSON.stringify(request.headers)}`)
-    logger.debug(`-> name: ${request.body.name}`)
-    logger.debug(`-> url: ${request.body.url}`)
-    logger.debug(`-> clientInfo: ${request.body.clientInfo}`)
-    logger.debug(`-> environmentInfo: ${request.body.environmentInfo}`)
-    logger.debug(`-> domSnapshot: ${domSnapshotLog}`)
+    const snapshotLog = path.join(os.tmpdir(), `percy.${Date.now()}.log`)
+    const snapshotLogger = createFileLogger(snapshotLog)
+    snapshotLogger.debug('handling snapshot:')
+    snapshotLogger.debug(`-> headers: ${JSON.stringify(request.headers)}`)
+    snapshotLogger.debug(`-> name: ${request.body.name}`)
+    snapshotLogger.debug(`-> url: ${request.body.url}`)
+    snapshotLogger.debug(`-> clientInfo: ${request.body.clientInfo}`)
+    snapshotLogger.debug(`-> environmentInfo: ${request.body.environmentInfo}`)
+    snapshotLogger.debug(`-> domSnapshot: ${domSnapshotLog}`)
 
     if (!this.snapshotService) { return response.json({success: false}) }
 
@@ -105,10 +109,15 @@ export class AgentService {
       return response.json({success: true})
     }
 
-    const resources = await this.snapshotService.buildResources(
+    let resources = await this.snapshotService.buildResources(
       request.body.url,
       domSnapshot,
       snapshotOptions,
+      snapshotLogger,
+    )
+
+    resources = resources.concat(
+      this.snapshotService.buildLogResource(snapshotLog),
     )
 
     const snapshotCreation = this.snapshotService.create(

src/services/asset-discovery-service.ts

@@ -3,7 +3,7 @@ import * as puppeteer from 'puppeteer'
 import { AssetDiscoveryConfiguration } from '../configuration/asset-discovery-configuration'
 import { DEFAULT_CONFIGURATION } from '../configuration/configuration'
 import { SnapshotOptions } from '../percy-agent-client/snapshot-options'
-import logger, {logError, profile} from '../utils/logger'
+import { logError, profile } from '../utils/logger'
 import waitForNetworkIdle from '../utils/wait-for-network-idle'
 import PercyClientService from './percy-client-service'
 import ResponseService from './response-service'
@@ -75,7 +75,12 @@ export class AssetDiscoveryService extends PercyClientService {
     return page
   }
 
-  async discoverResources(rootResourceUrl: string, domSnapshot: string, options: SnapshotOptions): Promise<any[]> {
+  async discoverResources(
+    rootResourceUrl: string,
+    domSnapshot: string,
+    options: SnapshotOptions,
+    logger: any,
+  ): Promise<any[]> {
     profile('-> assetDiscoveryService.discoverResources')
 
     if (this.browser === null) {
@@ -105,13 +110,19 @@ export class AssetDiscoveryService extends PercyClientService {
     // the number of pages in our pool. If we wanted to do something smarter here, we should consider
     // switching to use puppeteer-cluster instead.
     profile('--> assetDiscoveryService.discoverForWidths', {url: rootResourceUrl})
-    const resourcePromises: Array<Promise<any[]>> = []
-    for (const width of widths) {
-      const promise = this.resourcesForWidth(this.pagePool, width, domSnapshot, rootResourceUrl, enableJavaScript)
-      resourcePromises.push(promise)
-    }
-    const resourceArrays: any[][] = await Promise.all(resourcePromises)
-    let resources: any[] = ([] as any[]).concat(...resourceArrays)
+
+    let resources: any[] = [].concat(...(await Promise.all(
+      widths.map((width) => this.resourcesForWidth(
+        // @ts-ignore - for some reason, ts thinks we're assigning null here
+        this.pagePool,
+        width,
+        domSnapshot,
+        rootResourceUrl,
+        enableJavaScript,
+        logger,
+      )),
+    )) as any[])
+
     profile('--> assetDiscoveryService.discoverForWidths')
 
     const resourceUrls: string[] = []
@@ -157,6 +168,7 @@ export class AssetDiscoveryService extends PercyClientService {
     domSnapshot: string,
     rootResourceUrl: string,
     enableJavaScript: boolean,
+    logger: any,
   ): Promise<any[]> {
     logger.debug(`discovering assets for width: ${width}`)
 
@@ -196,7 +208,13 @@ export class AssetDiscoveryService extends PercyClientService {
       if (response) {
         // Parallelize the work in processResponse as much as possible, but make sure to
         // wait for it to complete before returning from the asset discovery phase.
-        const promise = this.responseService.processResponse(rootResourceUrl, response, width)
+        const promise = this.responseService.processResponse(
+          rootResourceUrl,
+          response,
+          width,
+          logger,
+        )
+
         promise.catch(logError)
         maybeResourcePromises.push(promise)
       } else {
@@ -231,7 +249,8 @@ export class AssetDiscoveryService extends PercyClientService {
 
       return maybeResources.filter((maybeResource) => maybeResource != null)
     } catch (error) {
-      logError(error)
+      logger.error(`${error.name} ${error.message}`)
+      logger.debug(error)
     }
 
     return []

src/services/resource-service.ts

@@ -1,5 +1,5 @@
 import * as path from 'path'
-import logger, {logError, profile} from '../utils/logger'
+import { logError, profile } from '../utils/logger'
 import PercyClientService from './percy-client-service'
 
 export default class ResourceService extends PercyClientService {
@@ -11,7 +11,7 @@ export default class ResourceService extends PercyClientService {
     this.buildId = buildId
   }
 
-  createResourceFromFile(responseUrl: string, copyFilePath: string, contentType = ''): any {
+  createResourceFromFile(responseUrl: string, copyFilePath: string, contentType = '', logger: any): any {
     const copyFullPath = path.resolve(copyFilePath)
     const sha = path.basename(copyFilePath)
     const resourceUrl = responseUrl

src/services/response-service.ts

@@ -3,8 +3,7 @@ import * as fs from 'fs'
 import * as os from 'os'
 import * as path from 'path'
 import * as puppeteer from 'puppeteer'
-import {URL} from 'url'
-import logger from '../utils/logger'
+import { URL } from 'url'
 import Constants from './constants'
 import PercyClientService from './percy-client-service'
 import ResourceService from './resource-service'
@@ -38,7 +37,12 @@ export default class ResponseService extends PercyClientService {
     return false
   }
 
-  async processResponse(rootResourceUrl: string, response: puppeteer.Response, width: number): Promise<any | null> {
+  async processResponse(
+    rootResourceUrl: string,
+    response: puppeteer.Response,
+    width: number,
+    logger: any,
+  ): Promise<any | null> {
     logger.debug(`processing response: ${response.url()} for width: ${width}`)
     const url = this.parseRequestPath(response.url())
 
@@ -74,7 +78,7 @@ export default class ResponseService extends PercyClientService {
       return
     }
 
-    const localCopy = await this.makeLocalCopy(response)
+    const localCopy = await this.makeLocalCopy(response, logger)
 
     const responseBodySize = fs.statSync(localCopy).size
     if (responseBodySize > Constants.MAX_FILE_SIZE_BYTES) {
@@ -84,13 +88,13 @@ export default class ResponseService extends PercyClientService {
     }
 
     const contentType = response.headers()['content-type']
-    const resource = this.resourceService.createResourceFromFile(url, localCopy, contentType)
+    const resource = this.resourceService.createResourceFromFile(url, localCopy, contentType, logger)
     this.responsesProcessed.set(url, resource)
 
     return resource
   }
 
-  async makeLocalCopy(response: puppeteer.Response): Promise<string> {
+  async makeLocalCopy(response: puppeteer.Response, logger: any): Promise<string> {
     logger.debug(`Making local copy of response: ${response.url()}`)
 
     const buffer = await response.buffer()

src/services/snapshot-service.ts

@@ -1,7 +1,10 @@
+import * as crypto from 'crypto'
+import * as fs from 'fs'
+import * as path from 'path'
 import { AssetDiscoveryConfiguration } from '../configuration/asset-discovery-configuration'
-import {SnapshotOptions} from '../percy-agent-client/snapshot-options'
-import {logError, profile} from '../utils/logger'
-import {AssetDiscoveryService} from './asset-discovery-service'
+import { SnapshotOptions } from '../percy-agent-client/snapshot-options'
+import { logError, profile } from '../utils/logger'
+import { AssetDiscoveryService } from './asset-discovery-service'
 import PercyClientService from './percy-client-service'
 import ResourceService from './resource-service'
 
@@ -23,24 +26,36 @@ export default class SnapshotService extends PercyClientService {
     rootResourceUrl: string,
     domSnapshot = '',
     options: SnapshotOptions,
+    logger: any,
   ): Promise<any[]> {
-    const rootResource = await this.percyClient.makeResource({
+    const rootResource = this.percyClient.makeResource({
       resourceUrl: rootResourceUrl,
       content: domSnapshot,
       isRoot: true,
       mimetype: 'text/html',
     })
 
-    let resources: any[] = []
     const discoveredResources = await this.assetDiscoveryService.discoverResources(
       rootResourceUrl,
       domSnapshot,
       options,
+      logger,
     )
-    resources = resources.concat([rootResource])
-    resources = resources.concat(discoveredResources)
 
-    return resources
+    return [rootResource].concat(discoveredResources)
+  }
+
+  buildLogResource(localPath: string) {
+    const fileName = path.basename(localPath)
+    const buffer = fs.readFileSync(path.resolve(localPath))
+    const sha = crypto.createHash('sha256').update(buffer).digest('hex')
+
+    return this.percyClient.makeResource({
+      resourceUrl: `/${fileName}`,
+      mimetype: 'text/plain',
+      localPath,
+      sha,
+    })
   }
 
   create(

src/utils/logger.ts

@@ -1,28 +1,24 @@
 import * as colors from 'colors'
 import * as winston from 'winston'
 
-const logger = new winston.Logger({
-  transports: [
-    new winston.transports.Console({
-      level: (process.env.LOG_LEVEL || 'info'),
-      showLevel: false,
-      label: colors.magenta('percy'),
-    }),
-  ],
+const LOG_LEVEL = process.env.LOG_LEVEL || 'info'
+
+const consoleTransport = new winston.transports.Console({
+  level: LOG_LEVEL,
+  stderrLevels: ['error'],
+  format: winston.format.combine(
+    winston.format.label({ label: colors.magenta('percy') }),
+    winston.format.printf(({ label, message }) => `[${label}] ${message}`),
+  ),
+})
+
+const logger = winston.createLogger({
+  transports: [consoleTransport],
 })
 
-export function profile(
-  id: string, meta?: any,
-  callback?: (err: Error, level: string, msg: string, meta: any) => void,
-): winston.LoggerInstance | undefined {
-  if (process.env.LOG_LEVEL === 'debug') {
-    // Only pass the callback through if it is defined, because the winston.Logger implementation
-    // does not behave as expected if you pass a null callback (it will ignore the meta parameter).
-    if (callback) {
-      return logger.profile(id, id, meta, callback)
-    } else {
-      return logger.profile(id, id, meta)
-    }
+export function profile(id: string, meta?: any): winston.Logger | undefined {
+  if (LOG_LEVEL === 'debug') {
+    return logger.profile(id, { level: 'debug', ...meta })
   }
 }
 
@@ -31,4 +27,9 @@ export function logError(error: any) {
   logger.debug(error)
 }
 
+export function createFileLogger(filename: string) {
+  const fileTransport = new winston.transports.File({ filename, level: 'debug' })
+  return winston.createLogger({ transports: [consoleTransport, fileTransport] })
+}
+
 export default logger