From 728a42d28d526b82448d6c39856b37e99f8c1563 Mon Sep 17 00:00:00 2001 From: Joel Chen Date: Mon, 3 Aug 2020 15:41:46 -0700 Subject: [PATCH] implement HTML log viewer using event source to do streaming --- .../src/lib/dev-admin/admin-http.ts | 216 +++++++++-- .../src/lib/dev-admin/admin-server.ts | 25 +- .../src/lib/dev-admin/log-parser.ts | 11 +- .../src/lib/dev-admin/log-view.js | 355 ++++++++++++++++++ .../xarc-app-dev/src/lib/dev-admin/log.html | 254 +------------ .../src/lib/dev-admin/redbird-proxy.ts | 2 + packages/xarc-app-dev/test/test-admin-http.ts | 46 +++ 7 files changed, 618 insertions(+), 291 deletions(-) create mode 100644 packages/xarc-app-dev/src/lib/dev-admin/log-view.js create mode 100644 packages/xarc-app-dev/test/test-admin-http.ts diff --git a/packages/xarc-app-dev/src/lib/dev-admin/admin-http.ts b/packages/xarc-app-dev/src/lib/dev-admin/admin-http.ts index c6cd464c1..8bf5c3312 100644 --- a/packages/xarc-app-dev/src/lib/dev-admin/admin-http.ts +++ b/packages/xarc-app-dev/src/lib/dev-admin/admin-http.ts @@ -4,83 +4,217 @@ import * as http from "http"; import * as Path from "path"; import * as Fs from "fs"; import * as Url from "url"; -import * as AnsiConvert from "ansi-to-html"; -import { AdminServer } from "./admin-server"; import { getLogEventAsHtml } from "./log-parser"; import * as QS from "querystring"; +import * as _ from "lodash"; export type AdminHttpOptions = { port?: number; - admin: any; + getLogs?: Function; }; +/** + * Track each log entry with timestamp from Date.now() as ID. + * + * If two entry has the same timestamp, then it's expected they are consecutively + * generated, and add a second part tx that's an incrementing number starting at 1. + * + * When client request logs, it's expected to send a query param `entryId` that's + * the stringified version in the format of "," + */ +type LogEntryId = { + ts: number; + tx?: number; +}; + +type EventClient = { + lastEntryId: LogEntryId; + res: http.ServerResponse; +}; + +function parseEntryId(str: string): LogEntryId { + if (str.indexOf(",") > 0) { + const parts = str.split(","); + return { + ts: parseInt(parts[0]), + tx: parseInt(parts[1]) + }; + } + + return { ts: parseInt(str) }; +} + +function compareEntryId(a: LogEntryId, b: LogEntryId) { + if (a.ts === b.ts) { + return (a.tx || 0) - (b.tx || 0); + } + return a.ts - b.ts; +} + +function stringifyEntryId(entryId) { + return entryId.tx ? `${entryId.ts},${entryId.tx}` : `${entryId.ts}`; +} + export class AdminHttp { _server: http.Server; - _admin: AdminServer; + _getLogs: Function; _logHtml: string; _adminHtml: string; _port: number; _instanceId: number; + _eventClientId: number; + _eventClients: Record; + _sendStreamTimer: NodeJS.Timeout; constructor(options: AdminHttpOptions) { this._server = http.createServer(this.requestListener.bind(this)); - this._admin = options.admin; + this._getLogs = options.getLogs; this._port = options.port || 9001; this._server.listen(this._port); this._instanceId = Date.now(); + this._eventClientId = 0; + this._eventClients = {}; } - _readAsset(filename: string, memoize: string): string { + _readAsset(filename: string, memoize: string, processor?: Function): string { if (!this[memoize]) { - this[memoize] = Fs.readFileSync(filename).toString(); + let content = Fs.readFileSync(filename).toString(); + if (processor) { + content = processor(content); + } + this[memoize] = content; } return this[memoize]; } _serveHtml(res: http.ServerResponse, content: string) { - res.setHeader("content-type", "text/html; charset=UTF-8"); - res.writeHead(200); + res.writeHead(200, { + "content-type": "text/html; charset=UTF-8" + }); res.end(content); } + _prepareLogs(lastEntryId: LogEntryId, name = "app") { + const logs = this._getLogs(name); + + const htmlLogs = logs + .filter(event => { + return compareEntryId(event as LogEntryId, lastEntryId) > 0; + }) + .map(event => { + const message = getLogEventAsHtml(event); + const record: any = { + level: event.level, + ts: event.ts, + message + }; + if (event.jsonData) { + record.json = true; + } + if (event.tx) { + record.tx = event.tx; + } + return record; + }); + + return htmlLogs; + } + _serveLogs(url: Url.UrlWithStringQuery, res: http.ServerResponse) { - const logs = this._admin.getLogs("app"); const query: any = QS.parse(url.query); const id = parseInt(query.id, 10); - let start = 0; + let entryIdStr = "0"; if (id === this._instanceId) { - start = parseInt(query.start, 10) || 0; - } - - const htmlLogs = []; - for (let ix = start; ix < logs.length; ix++) { - const event: any = logs[ix]; - const message = getLogEventAsHtml(event); - const record: any = { - level: event.level, - message - }; - if (event.jsonData) { - record.json = true; - } - htmlLogs.push(record); + entryIdStr = query.entryId || "0"; } const data = { - start, - logs: htmlLogs, - total: logs.length, + logs: this._prepareLogs(parseEntryId(entryIdStr)), instanceId: this._instanceId }; - res.setHeader("content-type", "application/json"); - res.writeHead(200); + res.writeHead(200, { + "content-type": "application/json" + }); res.end(JSON.stringify(data)); } + _streamLogsHandler(url: Url.UrlWithStringQuery, res: http.ServerResponse) { + const query: any = QS.parse(url.query); + res.writeHead(200, { + "content-type": "text/event-stream", + "cache-control": "no-cache", + "access-control-allow-origin": "*" + }); + + res.socket.setKeepAlive(true); + + let entryId = "0"; + if (query.id === this._instanceId) { + entryId = query.entryId || "0"; + } + + const eventClientId = this._eventClientId++; + this._eventClients[eventClientId] = { res, lastEntryId: parseEntryId(entryId) }; + + res.connection.on("close", () => { + delete this._eventClients[eventClientId]; + }); + + this.sendLogsToStreamClients(); + } + + sendLogsToStreamClients() { + if (this._sendStreamTimer) { + clearTimeout(this._sendStreamTimer); + } + + this._sendStreamTimer = setTimeout(() => this._sendLogsToStreamClients(), 100); + } + + _sendLogsToStreamClients() { + this._sendStreamTimer = null; + const logs = this._getLogs("app").filter(x => x); + const lastLog = _.last(logs) || { ts: 0, tx: 0 }; + const clients = Object.entries(this._eventClients) + .map(e => e[1]) + .filter(client => { + return client.lastEntryId && lastLog + ? compareEntryId(client.lastEntryId, lastLog as LogEntryId) < 0 + : true; + }) + .sort((a, b) => { + return compareEntryId(a.lastEntryId, b.lastEntryId); + }); + + if (clients.length === 0) { + return; + } + + const minTsTx = clients[0].lastEntryId; + const htmlLogs = this._prepareLogs(minTsTx); + + clients.forEach(client => { + const startIx = htmlLogs.findIndex(l => { + //l.ts > client.start; + return compareEntryId(l as LogEntryId, client.lastEntryId) > 0; + }); + const data = { + logs: htmlLogs.slice(startIx), + instanceId: this._instanceId + }; + + client.res.write(`event: log-stream\n`); + client.res.write(`data: ${JSON.stringify(data)}`); + client.res.write(`\n\n`); + + client.lastEntryId = { ts: lastLog.ts, tx: lastLog.tx }; + }); + } + requestListener(req: http.IncomingMessage, res: http.ServerResponse) { const url = Url.parse(req.url); switch (url.pathname) { @@ -95,7 +229,22 @@ export class AdminHttp { return this._serveLogs(url, res); case "/log": case "/__electrode_dev/log": - return this._serveHtml(res, this._readAsset(Path.join(__dirname, "log.html"), "_logHtml")); + return this._serveHtml( + res, + this._readAsset( + Path.join(__dirname, "log.html"), + "_logHtml", + (content: string): string => { + return content.replace( + "/*{{LOG_VIEW_JS}}*/", + Fs.readFileSync(Path.join(__dirname, "log-view.js")).toString() + ); + } + ) + ); + case "/stream-logs": + case "/__electrode_dev/stream-logs": + return this._streamLogsHandler(url, res); default: res.writeHead(404); return res.end("dev admin http 404 " + req.url); @@ -108,6 +257,9 @@ export class AdminHttp { shutdown() { const server = this._server; this._server = null; + Object.entries(this._eventClients).forEach(([, client]) => { + client.res.end("shutdown", () => client.res.destroy()); + }); if (server) { server.close(); } diff --git a/packages/xarc-app-dev/src/lib/dev-admin/admin-server.ts b/packages/xarc-app-dev/src/lib/dev-admin/admin-server.ts index cb3ca9a7a..18cd0eea1 100644 --- a/packages/xarc-app-dev/src/lib/dev-admin/admin-server.ts +++ b/packages/xarc-app-dev/src/lib/dev-admin/admin-server.ts @@ -94,7 +94,10 @@ export class AdminServer { this._shutdown = false; this._fullAppLogUrl = formUrl({ ...fullDevServer, path: controlPaths.appLog }); - this._adminHttp = new AdminHttp({ admin: this, port: this._opts.port }); + this._adminHttp = new AdminHttp({ + getLogs: (app: string) => this.getLogs(app), + port: this._opts.port + }); } async start() { @@ -503,9 +506,15 @@ ${instruction}` deferLogsOutput(context, showFullLink = true, delay = 250) { const { tag, store } = context; + const now = Date.now(); if (context._deferTimer) { - clearTimeout(context._deferTimer); + // avoid starving defer output + if (now - context._initialDefer < 150) { + clearTimeout(context._deferTimer); + context._deferTimer = null; + } } else { + context._initialDefer = now; context._deferIx = []; } @@ -517,9 +526,13 @@ ${instruction}` context._showFullLink = showFullLink; } + if (context._deferTimer) { + return; + } + context._deferTimestamp = Date.now(); context._deferTimer = setTimeout(() => { - context._deferTimer = undefined; + context._deferTimer = null; let currentIx = 0; const logsToShow = context._deferIx.reduce((logs, deferIx) => { if (currentIx > deferIx) { @@ -572,9 +585,9 @@ ${instruction}` const str = data.toString(); context.checkLine && context.checkLine(str); if (!str.trim()) { - store.push({ level: "info", message: "" }); + store.push({ ts: Date.now(), level: "info", message: "" }); } else { - const entry = parseLog(str.trimRight()); + const entry = parseLog(str.trimRight(), _.last(store)); // consider lines with at least two leading white spaces to be potential // continuation of previous error/warning messages. if (continuation && str.startsWith(" ")) { @@ -588,6 +601,8 @@ ${instruction}` this.deferLogsOutput(context, entry.show > 1); } } + + this._adminHttp.sendLogsToStreamClients(); }; inputs.forEach(input => { diff --git a/packages/xarc-app-dev/src/lib/dev-admin/log-parser.ts b/packages/xarc-app-dev/src/lib/dev-admin/log-parser.ts index 7b3c75b20..7ad3cc1ae 100644 --- a/packages/xarc-app-dev/src/lib/dev-admin/log-parser.ts +++ b/packages/xarc-app-dev/src/lib/dev-admin/log-parser.ts @@ -22,7 +22,7 @@ const tagLevelMap = { "debugger listening on": "silly" }; -export function parse(str) { +export function parse(str: string, last: any) { let jsonData; let show; @@ -59,12 +59,19 @@ export function parse(str) { } } - return { + const entry: any = { level: level || "info", + ts: Date.now(), message: message || str, json: jsonData, show }; + + if (last && entry.ts === last.ts) { + entry.tx = (last.tx || 0) + 1; + } + + return entry; } const Levels = { diff --git a/packages/xarc-app-dev/src/lib/dev-admin/log-view.js b/packages/xarc-app-dev/src/lib/dev-admin/log-view.js new file mode 100644 index 000000000..9c042eac0 --- /dev/null +++ b/packages/xarc-app-dev/src/lib/dev-admin/log-view.js @@ -0,0 +1,355 @@ +"use strict"; + +/* eslint-disable no-magic-numbers, no-use-before-define, no-unused-vars */ +/* eslint-disable no-console, max-statements, no-param-reassign, complexity */ +/* global window, document, EventSource, fetch */ + +let logStream; +let logStreamReconnectDelay = 5000; +let logStreamReconnectTimer; +let debugStreamEvents; + +function startLogStream() { + const close = () => { + if (logStream) { + logStream.close(); + } + logStream = null; + }; + + close(); + clearTimeout(logStreamReconnectTimer); + logStreamReconnectTimer = null; + + logStream = new EventSource("/__electrode_dev/stream-logs"); + logStream.addEventListener("log-stream", e => { + if (debugStreamEvents) { + console.log("stream event", e); + } + const data = JSON.parse(e.data); + updateLogs(data); + }); + logStream.addEventListener("open", e => { + console.log("log stream opened"); + logStreamReconnectDelay = 5000; + }); + logStream.addEventListener("error", (e, a) => { + console.log("log stream connect error", e); + close(); + logStreamReconnectTimer = setTimeout(() => { + console.log("trying to reconnect log stream", logStreamReconnectDelay); + startLogStream(); + if (logStreamReconnectDelay < 1000 * 60) { + logStreamReconnectDelay = Math.floor(logStreamReconnectDelay * 1.5); + } else { + logStreamReconnectDelay = 1000 * 60; + } + }, logStreamReconnectDelay); + }); +} + +setTimeout(startLogStream, 100); + +const logDisplayElement = document.getElementById("logs"); +// this is the ID of last received and displayed entry +// when received new entries, only those with ID after this are kept +let lastEntryId = { ts: 0, tx: 0 }; + +function compareEntryId(a, b) { + if (a.ts === b.ts) { + return (a.tx || 0) - (b.tx || 0); + } + return a.ts - b.ts; +} + +function stringifyEntryId(entryId) { + return entryId.tx ? `${entryId.ts},${entryId.tx}` : `${entryId.ts}`; +} + +// track logs from across restarted dev servers +let instanceId = -1; + +const defaultLevelSelections = { + error: true, + warn: true, + info: true, + http: true, + verbose: true, + debug: true, + silly: true +}; + +class HashValues { + constructor() { + this.setFromUrl(); + } + + setFromUrl() { + const hash = window.location.hash; + if (hash) { + this._hash = hash + .substr(1) + .split("&") + .reduce((acc, val) => { + const kvp = val.split("="); + if (kvp.length === 2 && kvp[0]) { + acc[kvp[0]] = kvp[1]; + } + return acc; + }, {}); + } else { + this._hash = {}; + } + } + + toUrl() { + const str = Object.keys(this._hash) + .sort() + .map(k => `${k}=${this._hash[k]}`) + .join("&"); + + return str ? "#" + str : ""; + } + + changed() { + const str = this.toUrl(); + return str !== window.location.hash; + } + + add(values) { + this._hash = { ...this._hash, ...values }; + this.update(); + } + + remove(values) { + [].concat(values).forEach(k => delete this._hash[k]); + this.update(); + } + + update() { + if (this._updateTimer) { + return; + } + this._updateTimer = setTimeout(() => { + this._updateTimer = undefined; + const str = this.toUrl(); + if (str !== window.location.hash) { + window.history.pushState( + this._hash, + document.title, + window.location.pathname + window.location.search + str + ); + } + }, 10); + } + + getInt(name, defaultVal = 0) { + const int = parseInt(this._hash[name], 10); + if (Number.isInteger(int)) { + return int; + } + return defaultVal; + } + + get(name) { + return this._hash[name]; + } + + has(name) { + return this._hash.hasOwnProperty(name); + } + + keys() { + return Object.keys(this._hash); + } +} + +const hashVal = new HashValues(); + +function getLevelSelections() { + const levels = Object.keys(defaultLevelSelections); + const levelSelections = levels.reduce((acc, level) => { + const checkBox = document.getElementById("level." + level); + acc[level] = checkBox.checked; + return acc; + }, {}); + return { ...defaultLevelSelections, ...levelSelections }; +} + +function levelChangeHandler() { + refreshLogs(getLevelSelections(), false); +} + +function refreshLogs(levelSelections, scrollToEnd = true) { + levelSelections = levelSelections || getLevelSelections(); + + for (let line = logDisplayElement.firstChild; line !== null; line = line.nextSibling) { + const lvl = line.getAttribute("lvl"); + if (!levelSelections[lvl]) { + line.setAttribute("class", "hide"); + } else { + line.removeAttribute("class"); + } + } + + const offLevels = Object.keys(levelSelections).reduce((acc, k) => { + if (!levelSelections[k]) { + acc[k] = false; + } + return acc; + }, {}); + + hashVal.remove(Object.keys(levelSelections)); + hashVal.add(offLevels); +} + +function clearLogs() { + while (logDisplayElement.lastChild) { + logDisplayElement.removeChild(logDisplayElement.lastChild); + } +} + +function wipeLogs() { + const last = logDisplayElement.lastChild; + + console.log("wipe logs, last", last); + if (last) { + const entryId = last.getAttribute("entryId"); + lastEntryId = parseEntryId(entryId); + hashVal.add({ entryId, id: instanceId }); + } else { + lastEntryId = { ts: Date.now(), tx: 0 }; + hashVal.add({ entryId: `${Date.now()}`, id: instanceId }); + } + clearLogs(); +} + +async function updateLogs(data, levelSelections, scrollToEnd = true) { + levelSelections = levelSelections || getLevelSelections(); + + if (hashVal.has("id")) { + instanceId = hashVal.getInt("id"); + } + + let newLogs = data.logs; + + // different instanceId means server would've returned all logs + if (data.instanceId && instanceId !== data.instanceId) { + if (hashVal.has("entryId") && instanceId > 0) { + hashVal.remove(["entryId", "id"]); + lastEntryId = { ts: 0 }; + } + instanceId = data.instanceId; + // instance ID completely different, need to start a clean slate log + clearLogs(); + } else { + // filter received logs by timestamp, only the ones after current timestamp are kept + + newLogs = data.logs.filter(l => { + return compareEntryId(l, lastEntryId) > 0; + }); + } + + const bounding = logDisplayElement.getBoundingClientRect(); + // check if bottom is in view (< -25 to account for our top margin of 30px) + const bottomInView = + bounding.bottom - (window.innerHeight || document.documentElement.clientHeight) < -25; + + if (newLogs.length > 0) { + newLogs.forEach(event => { + const newLine = document.createElement("div"); + newLine.setAttribute("lvl", event.level); + newLine.setAttribute("entryId", stringifyEntryId(event)); + if (!levelSelections[event.level]) { + newLine.setAttribute("class", "hide"); + } + newLine.innerHTML = event.message; + logDisplayElement.appendChild(newLine); + }); + } + + // console.log(bounding.bottom, window.innerHeight); + + // only auto scroll to end if bottom was already visible in view + if (scrollToEnd && bottomInView) { + setTimeout(() => window.scrollTo(0, document.body.scrollHeight - 30), 0); + } +} + +async function displayLogs(levelSelections, scrollToEnd = true) { + levelSelections = levelSelections || getLevelSelections(); + + if (hashVal.has("id")) { + instanceId = hashVal.getInt("id"); + } + + // if we have no logs displaying, we need to fetch all logs from start index + // else we just fetch new logs since last fetch + let entryId; + if (logDisplayElement.childElementCount === 0) { + entryId = stringifyEntryId(lastEntryId); + } else { + const children = logDisplayElement.children; + const last = children[children.length - 1]; + entryId = last.getAttribute("entryId"); + } + + const logResponse = await fetch( + `/__electrode_dev/log-events?entryId=${entryId}&id=${instanceId}` + ); + const data = await logResponse.json(); + + updateLogs(data, levelSelections, scrollToEnd); +} + +function updateLevelCheckboxes() { + Object.keys(defaultLevelSelections).forEach(k => { + const elem = document.getElementById(`level.${k}`); + if (elem) { + elem.checked = hashVal.get(k) !== "false"; + } + }); +} + +function parseEntryId(str) { + if (str.indexOf(",") > 0) { + const parts = str.split(","); + return { + ts: parseInt(parts[0]), + tx: parseInt(parts[1]) + }; + } + + return { ts: parseInt(str), tx: 0 }; +} + +window.addEventListener( + "hashchange", + () => { + if (hashVal.changed()) { + hashVal.setFromUrl(); + updateLevelCheckboxes(); + const entryId = parseEntryId(hashVal.get("entryId") || "0"); + // const start = hashVal.getInt("start"); + if (compareEntryId(entryId, lastEntryId) !== 0) { + hashVal.add({ entryId: stringifyEntryId(entryId) }); + clearLogs(); + lastEntryId = entryId; + displayLogs(); + } else { + refreshLogs(); + } + } + }, + false +); + +window.addEventListener("keypress", function(event) { + if (event.ctrlKey && event.code === "KeyK") { + wipeLogs(); + } +}); + +lastEntryId = parseEntryId(hashVal.get("entryId") || "0"); +updateLevelCheckboxes(); +// setTimeout(displayLogs, 10); diff --git a/packages/xarc-app-dev/src/lib/dev-admin/log.html b/packages/xarc-app-dev/src/lib/dev-admin/log.html index ab07956f3..31a3e8fbb 100644 --- a/packages/xarc-app-dev/src/lib/dev-admin/log.html +++ b/packages/xarc-app-dev/src/lib/dev-admin/log.html @@ -43,7 +43,7 @@ white-space: -o-pre-wrap; word-wrap: break-word; font-family: Menlo, Monaco, Consolas, "Courier New", monospace; - font-size: small; + font-size: medium; line-height: normal; } @@ -90,257 +90,7 @@ 

     
     
   
 
diff --git a/packages/xarc-app-dev/src/lib/dev-admin/redbird-proxy.ts b/packages/xarc-app-dev/src/lib/dev-admin/redbird-proxy.ts
index 261ea7094..eaefd496a 100644
--- a/packages/xarc-app-dev/src/lib/dev-admin/redbird-proxy.ts
+++ b/packages/xarc-app-dev/src/lib/dev-admin/redbird-proxy.ts
@@ -122,12 +122,14 @@ const registerElectrodeDevRules = ({
 }) => {
   const { dev: devPath, admin: adminPath, hmr: hmrPath, appLog, reporter } = controlPaths;
   const logEventsPath = `${devPath}/log-events`;
+  const logStreamsPath = `${devPath}/stream-logs`;
   const appForwards = [
     [{}, { port: appPort }],
     [{ path: `/js` }, { path: `/js`, port: webpackDevPort }],
     [{ path: hmrPath }, { path: hmrPath, port: webpackDevPort }],
     [{ path: appLog }, { path: appLog, port: settings.devAdminPort }],
     [{ path: logEventsPath }, { path: logEventsPath, port: settings.devAdminPort }],
+    [{ path: logStreamsPath }, { path: logStreamsPath, port: settings.devAdminPort }],
     [{ path: devPath }, { path: devPath, port: webpackDevPort }],
     [{ path: reporter }, { path: reporter, port: webpackDevPort }],
     [{ path: `${adminPath}/test-google` }, { protocol: "https", host: "www.google.com" }]
diff --git a/packages/xarc-app-dev/test/test-admin-http.ts b/packages/xarc-app-dev/test/test-admin-http.ts
new file mode 100644
index 000000000..b94957c6a
--- /dev/null
+++ b/packages/xarc-app-dev/test/test-admin-http.ts
@@ -0,0 +1,46 @@
+/**
+ * A simple test to run a admin HTTP standalone with a mock logging generator
+ * for testing the log viewer in streaming mode
+ *
+ */
+import { AdminHttp } from "../src/lib/dev-admin/admin-http";
+
+const logs = [];
+
+const ah = new AdminHttp({
+  getLogs(app) {
+    return logs;
+  }
+});
+
+let lineId = 1;
+
+let now;
+let tx = 0;
+const i1 = setInterval(() => {
+  if (tx === 0) {
+    now = Date.now();
+  }
+  const entry: any = {
+    level: "info",
+    ts: now,
+    message: "log line " + lineId + " " + now + " " + tx
+  };
+  if (tx) {
+    entry.tx = tx;
+  }
+  logs.push(entry);
+  lineId++;
+  tx++;
+  if (tx > 4) {
+    tx = 0;
+  }
+}, 100);
+
+const i2 = setInterval(() => {
+  ah.sendLogsToStreamClients();
+}, 250);
+
+// setTimeout(() => {
+//   clearInterval(i1);
+// }, 5000);