Improve debugging and logging (#88)

Improves debugging and logging.
Subscribing to page events to catch errors from browser
when rendering image.
Possible to adjust log level using LOG_LEVEL
environment variable when running as service.
Possible to adjust console logging by configuration
file when running as service.

Closes #85

Author: marefr

default.json

@@ -6,6 +6,13 @@
       "enabled": false,
       "collectDefaultMetrics": true,
       "requestDurationBuckets": [1, 5, 7, 9, 11, 13, 15, 20, 30]
+    },
+    "logging": {
+      "level": "info",
+      "console": {
+        "json": true,
+        "colorize": false
+      }
     }
   },
   "rendering": {
@@ -17,6 +24,7 @@
     "clustering": {
       "mode": "browser",
       "maxConcurrency": 5
-    }
+    },
+    "verboseLogging": false
   }
 }

dev.json

@@ -6,6 +6,13 @@
       "enabled": true,
       "collectDefaultMetrics": true,
       "requestDurationBuckets": [1, 5, 7, 9, 11, 13, 15, 20, 30]
+    },
+    "logging": {
+      "level": "debug",
+      "console": {
+        "json": false,
+        "colorize": true
+      }
     }
   },
   "rendering": {
@@ -17,6 +24,7 @@
     "clustering": {
       "mode": "browser",
       "maxConcurrency": 5
-    }
+    },
+    "verboseLogging": false
   }
 }

docs/remote_rendering_using_docker.md

@@ -49,6 +49,15 @@ You can enable [Prometheus](https://prometheus.io/) metrics endpoint `/metrics`
 export ENABLE_METRICS=true
 ```
 
+**Log level:**
+
+Change the log level. Default is `info` and will include log messages with level `error`, `warning` and info.
+
+
+```bash
+export LOG_LEVEL=info
+```
+
 ## Configuration file
 
 You can override certain settings by using a configuration file, see [default.json](https://github.com/grafana/grafana-image-renderer/tree/master/default.json) for defaults. Note that any configured environment variable takes precedence over configuration file settings.

package.json

@@ -31,7 +31,8 @@
     "prom-client": "^11.5.3",
     "puppeteer": "^2.0.0",
     "puppeteer-cluster": "^0.18.0",
-    "unique-filename": "^1.1.0"
+    "unique-filename": "^1.1.0",
+    "winston": "^3.2.1"
   },
   "devDependencies": {
     "@types/express": "^4.11.1",

src/app.ts

@@ -34,14 +34,13 @@ async function main() {
     plugin.start();
   } else if (command === 'server') {
     let config: ServiceConfig = defaultServiceConfig;
-    const logger = new ConsoleLogger();
 
     if (argv.config) {
       try {
         const fileConfig = readJSONFileSync(argv.config);
         config = _.merge(config, fileConfig);
       } catch (e) {
-        logger.error('failed to read config from path', argv.config, 'error', e);
+        console.error('failed to read config from path', argv.config, 'error', e);
         return;
       }
     }
@@ -52,6 +51,7 @@ async function main() {
       timings = new MetricsBrowserTimings();
     }
 
+    const logger = new ConsoleLogger(config.service.logging);
     const browser = createBrowser(config.rendering, logger, timings);
     const server = new HttpServer(config, logger, browser);
 
@@ -101,6 +101,10 @@ function populateServiceConfigFromEnv(config: ServiceConfig, env: NodeJS.Process
     config.service.port = parseInt(env['HTTP_PORT'] as string, 10);
   }
 
+  if (env['LOG_LEVEL']) {
+    config.service.logging.level = env['LOG_LEVEL'] as string;
+  }
+
   if (env['IGNORE_HTTPS_ERRORS']) {
     config.rendering.ignoresHttpsErrors = env['IGNORE_HTTPS_ERRORS'] === 'true';
   }

src/browser/browser.ts

@@ -113,9 +113,12 @@ export class Browser {
           await browser.newPage()
       );
 
+      this.addPageListeners(page);
+
       return await this.takeScreenshot(page, options);
     } finally {
       if (page) {
+        this.removePageListeners(page);
         await page.close();
       }
       if (browser) {
@@ -164,4 +167,69 @@ export class Browser {
 
     return { filePath: options.filePath };
   }
+
+  addPageListeners(page: any) {
+    page.on('error', this.logError.bind);
+    page.on('pageerror', this.logPageError);
+    page.on('requestfailed', this.logRequestFailed);
+    page.on('console', this.logConsoleMessage);
+
+    if (this.config.verboseLogging) {
+      page.on('request', this.logRequest);
+      page.on('requestfinished', this.logRequestFinished);
+      page.on('close', this.logPageClosed);
+    }
+  }
+
+  removePageListeners(page: any) {
+    page.removeListener('error', this.logError);
+    page.removeListener('pageerror', this.logPageError);
+    page.removeListener('requestfailed', this.logRequestFailed);
+    page.removeListener('console', this.logConsoleMessage);
+
+    if (this.config.verboseLogging) {
+      page.removeListener('request', this.logRequest);
+      page.removeListener('requestfinished', this.logRequestFinished);
+      page.removeListener('close', this.logPageClosed);
+    }
+  }
+
+  logError = (err: Error) => {
+    this.log.error('Browser page crashed', 'error', err.toString());
+  };
+
+  logPageError = (err: Error) => {
+    this.log.error('Browser uncaught exception', 'error', err.toString());
+  };
+
+  logConsoleMessage = (msg: any) => {
+    const msgType = msg.type();
+    if (!this.config.verboseLogging && msgType !== 'error') {
+      return;
+    }
+
+    const loc = msg.location();
+    if (msgType === 'error') {
+      this.log.error('Browser console error', 'msg', msg.text(), 'url', loc.url, 'line', loc.lineNumber, 'column', loc.columnNumber);
+      return;
+    }
+
+    this.log.debug(`Browser console ${msgType}`, 'msg', msg.text(), 'url', loc.url, 'line', loc.lineNumber, 'column', loc.columnNumber);
+  };
+
+  logRequest = (req: any) => {
+    this.log.debug('Browser request', 'url', req._url, 'method', req._url);
+  };
+
+  logRequestFailed = (req: any) => {
+    this.log.error('Browser request failed', 'url', req._url, 'method', req._method);
+  };
+
+  logRequestFinished = (req: any) => {
+    this.log.debug('Browser request finished', 'url', req._url, 'method', req._method);
+  };
+
+  logPageClosed = () => {
+    this.log.debug('Browser page closed');
+  };
 }

src/browser/clustered.ts

@@ -31,7 +31,12 @@ export class ClusteredBrowser extends Browser {
         // set timezone
         await page.emulateTimezone(data.timezone);
       }
-      return await this.takeScreenshot(page, data);
+
+      try {
+        return await this.takeScreenshot(page, data);
+      } finally {
+        this.removePageListeners(page);
+      }
     });
   }
 

src/browser/reusable.ts

@@ -39,9 +39,12 @@ export class ReusableBrowser extends Browser {
         await page.emulateTimezone(options.timezone);
       }
 
+      this.addPageListeners(page);
+
       return await this.takeScreenshot(page, options);
     } finally {
       if (page) {
+        this.removePageListeners(page);
         await page.close();
       }
       if (context) {

src/config.ts

@@ -12,6 +12,7 @@ export interface RenderingConfig {
   timingMetrics: boolean;
   mode: string;
   clustering: ClusteringConfig;
+  verboseLogging: boolean;
 }
 
 export interface MetricsConfig {
@@ -20,11 +21,23 @@ export interface MetricsConfig {
   requestDurationBuckets: number[];
 }
 
+export interface ConsoleLoggerConfig {
+  level?: string;
+  json: boolean;
+  colorize: boolean;
+}
+
+export interface LoggingConfig {
+  level: string;
+  console?: ConsoleLoggerConfig;
+}
+
 export interface ServiceConfig {
   service: {
     host?: string;
     port: number;
     metrics: MetricsConfig;
+    logging: LoggingConfig;
   };
   rendering: RenderingConfig;
 }
@@ -49,6 +62,7 @@ const defaultRenderingConfig: RenderingConfig = {
     mode: 'browser',
     maxConcurrency: 5,
   },
+  verboseLogging: false,
 };
 
 export const defaultServiceConfig: ServiceConfig = {
@@ -60,6 +74,13 @@ export const defaultServiceConfig: ServiceConfig = {
       collectDefaultMetrics: true,
       requestDurationBuckets: [0.5, 1, 3, 5, 7, 10, 20, 30, 60],
     },
+    logging: {
+      level: 'info',
+      console: {
+        json: true,
+        colorize: false,
+      },
+    },
   },
   rendering: defaultRenderingConfig,
 };

src/logger.ts

@@ -1,29 +1,89 @@
+import winston = require('winston');
+import { LoggingConfig } from './config';
+
+export interface LogWriter {
+  write(message, encoding);
+}
+
 export interface Logger {
+  writer: LogWriter;
   debug(message?: string, ...optionalParams: any[]);
   info(message?: string, ...optionalParams: any[]);
   warn(message?: string, ...optionalParams: any[]);
   error(message?: string, ...optionalParams: any[]);
 }
 
-export class ConsoleLogger {
-  debug(message?: string, ...optionalParams: any[]) {
-    console.debug(message, ...optionalParams);
+export class ConsoleLogger implements Logger {
+  writer: LogWriter;
+  logger: winston.Logger;
+
+  constructor(config: LoggingConfig) {
+    const options2 = {
+      console: {
+        level: 'debug',
+        handleExceptions: true,
+        colorize: true,
+      },
+    };
+
+    const transports: any[] = [];
+
+    if (config.console) {
+      const options: any = {
+        exitOnError: false,
+      };
+      if (config.console.level) {
+        options.level = config.console.level;
+      }
+      const formatters: any[] = [];
+      if (config.console.colorize) {
+        formatters.push(winston.format.colorize());
+      }
+
+      if (config.console.json) {
+        formatters.push(winston.format.json());
+      } else {
+        formatters.push(winston.format.align());
+        formatters.push(winston.format.simple());
+      }
+
+      options.format = winston.format.combine(...(formatters as any));
+      transports.push(new winston.transports.Console(options));
+    }
+
+    this.logger = winston.createLogger({
+      level: config.level,
+      exitOnError: false,
+      transports: transports,
+    });
+
+    this.writer = {
+      write: message => {
+        this.logger.info(message);
+      },
+    };
   }
 
-  info(message?: string, ...optionalParams: any[]) {
-    console.info(message, ...optionalParams);
+  debug(message: string, ...optionalParams: any[]) {
+    this.logger.debug(message, optionalParams);
   }
 
-  warn(message?: string, ...optionalParams: any[]) {
-    console.warn(message, ...optionalParams);
+  info(message: string, ...optionalParams: any[]) {
+    this.logger.info(message, optionalParams);
   }
 
-  error(message?: string, ...optionalParams: any[]) {
-    console.error(message, ...optionalParams);
+  warn(message: string, ...optionalParams: any[]) {
+    this.logger.warn(message, optionalParams);
+  }
+
+  error(message: string, ...optionalParams: any[]) {
+    this.logger.error(message, optionalParams);
   }
 }
 
-export class PluginLogger {
+export class PluginLogger implements Logger {
+  writer: LogWriter;
+
   private logEntry(level: string, message?: string, ...optionalParams: any[]) {
     const logEntry = {
       '@level': level,