Merge pull request #2554 from mononaut/unfurler-logging

Add logging & syslog support to unfurler

unfurler/config.sample.json

@@ -1,7 +1,8 @@
 {
   "SERVER": {
     "HOST": "http://localhost",
-    "HTTP_PORT": 4201
+    "HTTP_PORT": 4201,
+    "STDOUT_LOG_MIN_PRIORITY": "debug",
   },
   "MEMPOOL": {
     "HTTP_HOST": "http://localhost",
@@ -14,5 +15,12 @@
     "EXEC_PATH": "/usr/local/bin/chrome", // optional
     "MAX_PAGE_AGE": 86400, // maximum lifetime of a page session (in seconds)
     "RENDER_TIMEOUT": 3000, // timeout for preview image rendering (in ms) (optional)
+  },
+  "SYSLOG": {
+    "ENABLED": true,
+    "HOST": "127.0.0.1",
+    "PORT": 514,
+    "MIN_PRIORITY": "info",
+    "FACILITY": "local7"
   }
 }

unfurler/puppeteer.config.json

@@ -1,5 +1,6 @@
 {
   "headless": true,
+  "dumpio": true,
   "defaultViewport": {
     "width": 1200,
     "height": 600

unfurler/src/concurrency/ReusablePage.ts

@@ -1,6 +1,7 @@
 import * as puppeteer from 'puppeteer';
 import ConcurrencyImplementation from 'puppeteer-cluster/dist/concurrency/ConcurrencyImplementation';
 import { timeoutExecute } from 'puppeteer-cluster/dist/util';
+import logger from '../logger';
 
 import config from '../config';
 const mempoolHost = config.MEMPOOL.HTTP_HOST + (config.MEMPOOL.HTTP_PORT ? ':' + config.MEMPOOL.HTTP_PORT : '');
@@ -43,13 +44,13 @@ export default class ReusablePage extends ConcurrencyImplementation {
     }
 
     this.repairing = true;
-    console.log('Starting repair');
+    logger.info('Starting repair');
 
     try {
       // will probably fail, but just in case the repair was not necessary
       await (<puppeteer.Browser>this.browser).close();
     } catch (e) {
-      console.log('Unable to close browser.');
+      logger.warn('Unable to close browser.');
     }
 
     try {
@@ -65,11 +66,17 @@ export default class ReusablePage extends ConcurrencyImplementation {
 
   public async init() {
     this.browser = await this.puppeteer.launch(this.options);
+    if (this.browser != null) {
+      const proc = this.browser.process();
+      if (proc) {
+        initBrowserLogging(proc);
+      }
+    }
     const promises = []
     for (let i = 0; i < maxConcurrency; i++) {
       const newPage = await this.initPage();
       newPage.index = this.pages.length;
-      console.log('initialized page ', newPage.index);
+      logger.info(`initialized page ${newPage.index}`);
       this.pages.push(newPage);
     }
   }
@@ -82,15 +89,29 @@ export default class ReusablePage extends ConcurrencyImplementation {
     const page = await (this.browser as puppeteer.Browser).newPage() as RepairablePage;
     page.language = null;
     page.createdAt = Date.now();
-    const defaultUrl = mempoolHost + '/preview/block/1';
+    let defaultUrl
+    if (config.MEMPOOL.NETWORK !== 'bisq') {
+      // preload the preview module
+      defaultUrl = mempoolHost + '/preview/block/1';
+    } else {
+      // no preview module implemented yet for bisq
+      defaultUrl = mempoolHost;
+    }
     page.on('pageerror', (err) => {
       page.repairRequested = true;
     });
-    await page.goto(defaultUrl, { waitUntil: "load" });
+    if (config.MEMPOOL.NETWORK !== 'bisq') {
-    await Promise.race([
+      try {
-      page.waitForSelector('meta[property="og:preview:ready"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 }).then(() => true),
+        await page.goto(defaultUrl, { waitUntil: "load" });
-      page.waitForSelector('meta[property="og:preview:fail"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 }).then(() => false)
+        await Promise.race([
-    ])
+          page.waitForSelector('meta[property="og:preview:ready"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 }).then(() => true),
+          page.waitForSelector('meta[property="og:preview:fail"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 }).then(() => false)
+        ])
+      } catch (e) {
+        logger.err(`failed to load frontend during page initialization: ` + (e instanceof Error ? e.message : `${e}`));
+        page.repairRequested = true;
+      }
+    }
     page.free = true;
     return page
   }
@@ -98,7 +119,7 @@ export default class ReusablePage extends ConcurrencyImplementation {
   protected async createResources(): Promise<ResourceData> {
     const page = this.pages.find(p => p.free);
     if (!page) {
-      console.log('no free pages!')
+      logger.err('no free pages!')
       throw new Error('no pages available');
     } else {
       page.free = false;
@@ -117,7 +138,7 @@ export default class ReusablePage extends ConcurrencyImplementation {
     try {
       await page.goto('about:blank', {timeout: 200}); // prevents memory leak (maybe?)
     } catch (e) {
-      console.log('unexpected page repair error');
+      logger.err('unexpected page repair error');
     }
     await page.close();
     return newPage;
@@ -161,3 +182,26 @@ export default class ReusablePage extends ConcurrencyImplementation {
     };
   }
 }
+
+function initBrowserLogging(proc) {
+  if (proc.stderr && proc.stdout) {
+    proc.on('error', msg => {
+      logger.err('BROWSER ERROR ' + msg);
+    })
+    proc.stderr.on('data', buf => {
+      const msg = String(buf);
+      // For some reason everything (including js console logs) is piped to stderr
+      // so this kludge splits logs back into their priority levels
+      if (msg.includes(':INFO:')) {
+        logger.info('BROWSER' + msg, true);
+      } else if (msg.includes(':WARNING:')) {
+        logger.warn('BROWSER' + msg, true);
+      } else {
+        logger.err('BROWSER' + msg, true);
+      }
+    })
+    proc.stdout.on('data', buf => {
+      logger.info('BROWSER' + String(buf));
+    })
+  }
+}

unfurler/src/config.ts

@@ -4,6 +4,7 @@ interface IConfig {
   SERVER: {
     HOST: 'http://localhost';
     HTTP_PORT: number;
+    STDOUT_LOG_MIN_PRIORITY: string;
   };
   MEMPOOL: {
     HTTP_HOST: string;
@@ -17,12 +18,20 @@ interface IConfig {
     MAX_PAGE_AGE?: number;
     RENDER_TIMEOUT?: number;
   };
+  SYSLOG: {
+    ENABLED: boolean;
+    HOST: string;
+    PORT: number;
+    MIN_PRIORITY: 'emerg' | 'alert' | 'crit' | 'err' | 'warn' | 'notice' | 'info' | 'debug';
+    FACILITY: string;
+  };
 }
 
 const defaults: IConfig = {
   'SERVER': {
     'HOST': 'http://localhost',
     'HTTP_PORT': 4201,
+    'STDOUT_LOG_MIN_PRIORITY': 'debug',
   },
   'MEMPOOL': {
     'HTTP_HOST': 'http://localhost',
@@ -32,18 +41,27 @@ const defaults: IConfig = {
     'ENABLED': true,
     'CLUSTER_SIZE': 1,
   },
+  'SYSLOG': {
+    'ENABLED': true,
+    'HOST': '127.0.0.1',
+    'PORT': 514,
+    'MIN_PRIORITY': 'info',
+    'FACILITY': 'local7'
+  },
 };
 
 class Config implements IConfig {
   SERVER: IConfig['SERVER'];
   MEMPOOL: IConfig['MEMPOOL'];
   PUPPETEER: IConfig['PUPPETEER'];
+  SYSLOG: IConfig['SYSLOG'];
 
   constructor() {
     const configs = this.merge(configFile, defaults);
     this.SERVER = configs.SERVER;
     this.MEMPOOL = configs.MEMPOOL;
     this.PUPPETEER = configs.PUPPETEER;
+    this.SYSLOG = configs.SYSLOG;
   }
 
   merge = (...objects: object[]): IConfig => {

unfurler/src/index.ts

@@ -7,6 +7,7 @@ import { Cluster } from 'puppeteer-cluster';
 import ReusablePage from './concurrency/ReusablePage';
 import { parseLanguageUrl } from './language/lang';
 import { matchRoute } from './routes';
+import logger from './logger';
 const puppeteerConfig = require('../puppeteer.config.json');
 
 if (config.PUPPETEER.EXEC_PATH) {
@@ -55,7 +56,7 @@ class Server {
     this.server = http.createServer(this.app);
 
     this.server.listen(config.SERVER.HTTP_PORT, () => {
-      console.log(`Mempool Unfurl Server is running on port ${config.SERVER.HTTP_PORT}`);
+      logger.info(`Mempool Unfurl Server is running on port ${config.SERVER.HTTP_PORT}`);
     });
   }
 
@@ -102,20 +103,23 @@ class Server {
 
       // wait for preview component to initialize
       await page.waitForSelector('meta[property="og:preview:loading"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 })
-      let success = false;
+      let success;
       success = await Promise.race([
         page.waitForSelector('meta[property="og:preview:ready"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 }).then(() => true),
         page.waitForSelector('meta[property="og:preview:fail"]', { timeout: config.PUPPETEER.RENDER_TIMEOUT || 3000 }).then(() => false)
       ])
-      if (success) {
+      if (success === true) {
         const screenshot = await page.screenshot();
         return screenshot;
+      } else if (success === false) {
+        logger.warn(`failed to render page preview for ${action} due to client-side error, e.g. requested an invalid txid`);
+        page.repairRequested = true;
       } else {
-        console.log(`failed to render page preview for ${action} due to client-side error. probably requested an invalid ID`);
+        logger.warn(`failed to render page preview for ${action} due to puppeteer timeout`);
         page.repairRequested = true;
       }
     } catch (e) {
-      console.log(`failed to render page for ${action}`, e instanceof Error ? e.message : e);
+      logger.err(`failed to render page for ${action}: ` + (e instanceof Error ? e.message : `${e}`));
       page.repairRequested = true;
     }
   }
@@ -150,7 +154,7 @@ class Server {
         res.send(img);
       }
     } catch (e) {
-      console.log(e);
+      logger.err(e instanceof Error ? e.message : `${e}`);
       res.status(500).send(e instanceof Error ? e.message : e);
     }
   }
@@ -202,7 +206,7 @@ class Server {
 const server = new Server();
 
 process.on('SIGTERM', async () => {
-  console.info('Shutting down Mempool Unfurl Server');
+  logger.info('Shutting down Mempool Unfurl Server');
   await server.stopServer();
   process.exit(0);
 });

unfurler/src/logger.ts

@@ -0,0 +1,142 @@
+import config from './config';
+import * as dgram from 'dgram';
+
+class Logger {
+  static priorities = {
+    emerg: 0,
+    alert: 1,
+    crit: 2,
+    err: 3,
+    warn: 4,
+    notice: 5,
+    info: 6,
+    debug: 7
+  };
+  static facilities = {
+    kern: 0,
+    user: 1,
+    mail: 2,
+    daemon: 3,
+    auth: 4,
+    syslog: 5,
+    lpr: 6,
+    news: 7,
+    uucp: 8,
+    local0: 16,
+    local1: 17,
+    local2: 18,
+    local3: 19,
+    local4: 20,
+    local5: 21,
+    local6: 22,
+    local7: 23
+  };
+
+  // @ts-ignore
+  public emerg: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public alert: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public crit: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public err: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public warn: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public notice: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public info: ((msg: string, quiet: boolean = false) => void);
+  // @ts-ignore
+  public debug: ((msg: string, quiet: boolean = false) => void);
+
+  private name = 'mempool';
+  private client: dgram.Socket;
+  private network: string;
+
+  constructor() {
+    let prio;
+    for (prio in Logger.priorities) {
+      if (true) {
+        this.addprio(prio);
+      }
+    }
+    this.client = dgram.createSocket('udp4');
+    this.network = this.getNetwork();
+  }
+
+  private addprio(prio): void {
+    this[prio] = (function(_this) {
+      return function(msg, quiet) {
+        return _this.msg(prio, msg, quiet);
+      };
+    })(this);
+  }
+
+  private getNetwork(): string {
+    return config.MEMPOOL.NETWORK || 'bitcoin';
+  }
+
+  private msg(priority, msg, quiet) {
+    let consolemsg, prionum, syslogmsg;
+    if (typeof msg === 'string' && msg.length > 0) {
+      while (msg[msg.length - 1].charCodeAt(0) === 10) {
+        msg = msg.slice(0, msg.length - 1);
+      }
+    }
+    const network = this.network ? ' <' + this.network + '-unfurler>' : '';
+    prionum = Logger.priorities[priority] || Logger.priorities.info;
+    consolemsg = `${this.ts()} [${process.pid}] ${priority.toUpperCase()}:${network} ${msg}`;
+
+    if (config.SYSLOG.ENABLED && Logger.priorities[priority] <= Logger.priorities[config.SYSLOG.MIN_PRIORITY]) {
+      syslogmsg = `<${(Logger.facilities[config.SYSLOG.FACILITY] * 8 + prionum)}> ${this.name}[${process.pid}]: ${priority.toUpperCase()}${network} ${msg}`;
+      this.syslog(syslogmsg);
+    }
+    if (quiet || Logger.priorities[priority] > Logger.priorities[config.SERVER.STDOUT_LOG_MIN_PRIORITY]) {
+      return;
+    }
+    if (priority === 'warning') {
+      priority = 'warn';
+    }
+    if (priority === 'debug') {
+      priority = 'info';
+    }
+    if (priority === 'err') {
+      priority = 'error';
+    }
+    return (console[priority] || console.error)(consolemsg);
+  }
+
+  private syslog(msg) {
+    let msgbuf;
+    msgbuf = Buffer.from(msg);
+    this.client.send(msgbuf, 0, msgbuf.length, config.SYSLOG.PORT, config.SYSLOG.HOST, function(err, bytes) {
+      if (err) {
+        console.log(err);
+      }
+    });
+  }
+
+  private leadZero(n: number): number | string {
+    if (n < 10) {
+      return '0' + n;
+    }
+    return n;
+  }
+
+  private ts() {
+    let day, dt, hours, minutes, month, months, seconds;
+    dt = new Date();
+    hours = this.leadZero(dt.getHours());
+    minutes = this.leadZero(dt.getMinutes());
+    seconds = this.leadZero(dt.getSeconds());
+    month = dt.getMonth();
+    day = dt.getDate();
+    if (day < 10) {
+      day = ' ' + day;
+    }
+    months = ['Jan', 'Feb', 'Mar', 'Apr', 'May', 'Jun', 'Jul', 'Aug', 'Sep', 'Oct', 'Nov', 'Dec'];
+    return months[month] + ' ' + day + ' ' + hours + ':' + minutes + ':' + seconds;
+  }
+}
+
+export default new Logger();