fix: Add timestamps to logs

src/services/asset-discovery-service.ts

@@ -4,7 +4,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 { logError, profile } from '../utils/logger'
+import { addLogDate, logError, profile } from '../utils/logger'
 import { cacheResponse, getResponseCache } from '../utils/response-cache'
 import waitForNetworkIdle from '../utils/wait-for-network-idle'
 import PercyClientService from './percy-client-service'
@@ -102,7 +102,7 @@ export class AssetDiscoveryService extends PercyClientService {
 
     rootResourceUrl = this.parseRequestPath(rootResourceUrl)
 
-    logger.debug(`discovering assets for URL: ${rootResourceUrl}`)
+    logger.debug(addLogDate(`discovering assets for URL: ${rootResourceUrl}`))
 
     const {
       enableJavaScript = false,
@@ -177,7 +177,7 @@ export class AssetDiscoveryService extends PercyClientService {
     requestHeaders: any = {},
     logger: any,
   ): Promise<any[]> {
-    logger.debug(`discovering assets for width: ${width}`)
+    logger.debug(addLogDate(`discovering assets for width: ${width}`))
 
     profile('--> assetDiscoveryService.pool.acquire', { url: rootResourceUrl })
     const page = await pool.acquire()
@@ -208,7 +208,7 @@ export class AssetDiscoveryService extends PercyClientService {
         }
 
         if (this.configuration['cache-responses'] === true && getResponseCache(requestUrl)) {
-          logger.debug(`Asset cache hit for ${requestUrl}`)
+          logger.debug(addLogDate(`Asset cache hit for ${requestUrl}`))
           await request.respond(getResponseCache(requestUrl))
 
           return
@@ -242,13 +242,13 @@ export class AssetDiscoveryService extends PercyClientService {
         promise.catch(logError)
         maybeResourcePromises.push(promise)
       } else {
-        logger.debug(`No response for ${request.url()}. Skipping.`)
+        logger.debug(addLogDate(`No response for ${request.url()}. Skipping.`))
       }
     })
 
     // Debug log failed requests.
     page.on('requestfailed', async (request) => {
-      logger.debug(`Failed to load ${request.url()} : ${request.failure()!.errorText}}`)
+      logger.debug(addLogDate(`Failed to load ${request.url()} : ${request.failure()!.errorText}}`))
     })
 
     let maybeResources: any[] = []

src/services/resource-service.ts

@@ -1,5 +1,5 @@
 import * as path from 'path'
-import { logError, profile } from '../utils/logger'
+import { addLogDate, logError, profile } from '../utils/logger'
 import PercyClientService from './percy-client-service'
 
 export default class ResourceService extends PercyClientService {
@@ -16,7 +16,7 @@ export default class ResourceService extends PercyClientService {
     const sha = path.basename(copyFilePath)
     const resourceUrl = responseUrl
 
-    logger.debug('creating resource')
+    logger.debug(addLogDate('creating resource'))
     logger.debug(`-> response: ${responseUrl}`)
     logger.debug(`-> copyFilePath: ${copyFilePath}`)
     logger.debug(`-> resourceUrl: ${resourceUrl}`)

src/services/response-service.ts

@@ -8,6 +8,7 @@ import * as path from 'path'
 import * as puppeteer from 'puppeteer'
 import { URL } from 'url'
 import domainMatch from '../utils/domain-match'
+import { addLogDate } from '../utils/logger'
 import Constants from './constants'
 import PercyClientService from './percy-client-service'
 import ResourceService from './resource-service'
@@ -47,7 +48,7 @@ export default class ResponseService extends PercyClientService {
     width: number,
     logger: any,
   ): Promise<any | null> {
-    logger.debug(`processing response: ${response.url()} for width: ${width}`)
+    logger.debug(addLogDate(`processing response: ${response.url()} for width: ${width}`))
     const url = this.parseRequestPath(response.url())
 
     // skip responses already processed
@@ -61,19 +62,19 @@ export default class ResponseService extends PercyClientService {
 
     if (request.url() === rootResourceUrl) {
       // Always skip the root resource
-      logger.debug(`Skipping [is_root_resource]: ${request.url()}`)
+      logger.debug(addLogDate(`Skipping [is_root_resource]: ${request.url()}`))
       return
     }
 
     if (!ALLOWED_RESPONSE_STATUSES.includes(response.status())) {
       // Only allow 2XX responses:
-      logger.debug(`Skipping [disallowed_response_status_${response.status()}] [${width} px]: ${response.url()}`)
+      logger.debug(addLogDate(`Skipping [disallowed_response_status_${response.status()}] [${width} px]: ${response.url()}`))
       return
     }
 
     if (!this.shouldCaptureResource(rootUrl, request.url())) {
       // Disallow remote resource requests.
-      logger.debug(`Skipping [is_remote_resource] [${width} px]: ${request.url()}`)
+      logger.debug(addLogDate(`Skipping [is_remote_resource] [${width} px]: ${request.url()}`))
       return
     }
 
@@ -82,7 +83,7 @@ export default class ResponseService extends PercyClientService {
       // `followRedirects` is the npm package axios uses to follow redirected requests
       // we'll use their max redirect setting as a guard here
       if (request.redirectChain().length > followRedirects.maxRedirects) {
-        logger.debug(`Skipping [redirect_too_deep: ${request.redirectChain().length}] [${width} px]: ${response.url()}`)
+        logger.debug(addLogDate(`Skipping [redirect_too_deep: ${request.redirectChain().length}] [${width} px]: ${response.url()}`))
         return
       }
 
@@ -92,7 +93,7 @@ export default class ResponseService extends PercyClientService {
 
     if (request.resourceType() === 'other' && (await response.text()).length === 0) {
       // Skip empty other resource types (browser resource hints)
-      logger.debug(`Skipping [is_empty_other]: ${request.url()}`)
+      logger.debug(addLogDate(`Skipping [is_empty_other]: ${request.url()}`))
       return
     }
 
@@ -112,7 +113,7 @@ export default class ResponseService extends PercyClientService {
     width: number,
     logger: any,
   ) {
-    logger.debug(`Making local copy of redirected response: ${originalURL}`)
+    logger.debug(addLogDate(`Making local copy of redirected response: ${originalURL}`))
 
     try {
       const { data, headers } = await Axios(originalURL, {
@@ -127,11 +128,11 @@ export default class ResponseService extends PercyClientService {
       const { fileIsTooLarge, responseBodySize } = this.checkFileSize(localCopy)
 
       if (!didWriteFile) {
-        logger.debug(`Skipping file copy [already_copied]: ${originalURL}`)
+        logger.debug(addLogDate(`Skipping file copy [already_copied]: ${originalURL}`))
       }
 
       if (fileIsTooLarge) {
-        logger.debug(`Skipping [max_file_size_exceeded_${responseBodySize}] [${width} px]: ${originalURL}`)
+        logger.debug(addLogDate(`Skipping [max_file_size_exceeded_${responseBodySize}] [${width} px]: ${originalURL}`))
         return
       }
 
@@ -144,7 +145,7 @@ export default class ResponseService extends PercyClientService {
       return resource
     } catch (err) {
       logger.debug(`${err}`)
-      logger.debug(`Failed to make a local copy of redirected response: ${originalURL}`)
+      logger.debug(addLogDate(`Failed to make a local copy of redirected response: ${originalURL}`))
 
       return
     }
@@ -155,22 +156,22 @@ export default class ResponseService extends PercyClientService {
    * take the response object from Puppeteer and save the asset locally.
    */
   async handlePuppeteerResource(url: string, response: puppeteer.Response, width: number, logger: any) {
-    logger.debug(`Making local copy of response: ${response.url()}`)
+    logger.debug(addLogDate(`Making local copy of response: ${response.url()}`))
 
     const buffer = await response.buffer()
     const sha = crypto.createHash('sha256').update(buffer).digest('hex')
     const localCopy = path.join(os.tmpdir(), sha)
     const didWriteFile = this.maybeWriteFile(localCopy, buffer)
 
     if (!didWriteFile) {
-      logger.debug(`Skipping file copy [already_copied]: ${response.url()}`)
+      logger.debug(addLogDate(`Skipping file copy [already_copied]: ${response.url()}`))
     }
 
     const contentType = response.headers()['content-type']
     const { fileIsTooLarge, responseBodySize } = this.checkFileSize(localCopy)
 
     if (fileIsTooLarge) {
-      logger.debug(`Skipping [max_file_size_exceeded_${responseBodySize}] [${width} px]: ${response.url()}`)
+      logger.debug(addLogDate(`Skipping [max_file_size_exceeded_${responseBodySize}] [${width} px]: ${response.url()}`))
       return
     }
 

src/utils/logger.ts

@@ -3,6 +3,10 @@ import * as winston from 'winston'
 
 const LOG_LEVEL = process.env.LOG_LEVEL || 'info'
 
+export function addLogDate(log: string) {
+  return `${log} | ${new Date().toString()}`
+}
+
 function createConsoleTransport() {
   return new winston.transports.Console({
     level: LOG_LEVEL,

src/utils/response-cache.ts

@@ -1,4 +1,5 @@
 import { Response } from 'puppeteer'
+import { addLogDate } from './logger'
 let responseCache = {} as any
 
 /**
@@ -13,7 +14,7 @@ export async function cacheResponse(response: Response, logger: any) {
   const statusCode = response.status()
 
   if (!!responseCache[responseUrl]) {
-    logger.debug(`Asset already in cache ${responseUrl}`)
+    logger.debug(addLogDate(`Asset already in cache ${responseUrl}`))
     return
   }
 
@@ -30,9 +31,9 @@ export async function cacheResponse(response: Response, logger: any) {
       body: buffer,
     }
 
-    logger.debug(`Added ${responseUrl} to asset discovery cache`)
+    logger.debug(addLogDate(`Added ${responseUrl} to asset discovery cache`))
   } catch (error) {
-    logger.debug(`Could not cache response ${responseUrl}: ${error}`)
+    logger.debug(addLogDate(`Could not cache response ${responseUrl}: ${error}`))
   }
 }