From b68f34351a9b9c9ff0467ce65986d23ccae660e4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ey=C3=BE=C3=B3r=20Magn=C3=BAsson?= Date: Tue, 27 Aug 2019 13:29:32 +0200 Subject: [PATCH] improvement(logger): store all message states --- garden-service/src/commands/logs.ts | 7 +- garden-service/src/logger/log-entry.ts | 239 +++++++++++------- garden-service/src/logger/log-node.ts | 46 ++-- garden-service/src/logger/logger.ts | 14 +- garden-service/src/logger/renderers.ts | 55 ++-- garden-service/src/logger/util.ts | 4 +- .../logger/writers/basic-terminal-writer.ts | 7 +- .../logger/writers/fancy-terminal-writer.ts | 10 +- garden-service/src/server/commands.ts | 2 +- garden-service/test/run-garden.ts | 4 +- .../test/unit/src/logger/log-entry.ts | 181 +++++++++++-- garden-service/test/unit/src/logger/logger.ts | 2 +- .../test/unit/src/logger/renderers.ts | 58 ++++- 13 files changed, 438 insertions(+), 191 deletions(-) diff --git a/garden-service/src/commands/logs.ts b/garden-service/src/commands/logs.ts index f0164eb802..5aeb75bf16 100644 --- a/garden-service/src/commands/logs.ts +++ b/garden-service/src/commands/logs.ts @@ -85,10 +85,7 @@ export class LogsCommand extends Command { } catch { } } - log.info({ - section: entry.serviceName, - msg: [timestamp, chalk.white(entry.msg)], - }) + log.info({ section: entry.serviceName, msg: `${timestamp} → ${chalk.white(entry.msg)}` }) if (!follow) { result.push(entry) @@ -98,7 +95,7 @@ export class LogsCommand extends Command { const actions = await garden.getActionHelper() await Bluebird.map(services, async (service: Service) => { - const voidLog = log.placeholder(LogLevel.silly, { childEntriesInheritLevel: true }) + const voidLog = log.placeholder(LogLevel.silly, true) const runtimeContext = await getServiceRuntimeContext(garden, graph, service) const status = await actions.getServiceStatus({ log: voidLog, service, hotReload: false, runtimeContext }) diff --git a/garden-service/src/logger/log-entry.ts b/garden-service/src/logger/log-entry.ts index 109f3980c6..16fd90d550 100644 --- a/garden-service/src/logger/log-entry.ts +++ b/garden-service/src/logger/log-entry.ts @@ -8,12 +8,11 @@ import * as logSymbols from "log-symbols" import * as nodeEmoji from "node-emoji" -import { flatten } from "lodash" -import { LogNode, LogLevel } from "./log-node" -import { getChildEntries, findParentEntry, sanitizeObject } from "./util" -import { GardenError } from "../exceptions" +import { LogNode, LogLevel, CreateNodeParams } from "./log-node" import { Omit } from "../util/util" +import { getChildEntries, findParentEntry } from "./util" +import { GardenError } from "../exceptions" import { Logger } from "./logger" export type EmojiName = keyof typeof nodeEmoji.emoji @@ -32,106 +31,147 @@ export interface TaskMetadata { durationMs?: number, } -export interface UpdateOpts { - msg?: string | string[] - data?: any // to be rendered as e.g. YAML or JSON - section?: string +interface MessageBase { + msg?: string emoji?: EmojiName + status?: EntryStatus + section?: string symbol?: LogSymbol append?: boolean - fromStdStream?: boolean - showDuration?: boolean - error?: GardenError - status?: EntryStatus - indent?: number - childEntriesInheritLevel?: boolean +} + +export interface MessageState extends MessageBase { + timestamp: number, +} + +export interface UpdateLogEntryParams extends MessageBase { metadata?: LogEntryMetadata } -export interface CreateOpts extends UpdateOpts { +export interface LogEntryParams extends UpdateLogEntryParams { + error?: GardenError + data?: any // to be rendered as e.g. YAML or JSON + indent?: number + childEntriesInheritLevel?: boolean + fromStdStream?: boolean id?: string } -export type CreateParam = string | CreateOpts - -export interface LogEntryConstructor { +export interface LogEntryConstructor extends LogEntryParams { level: LogLevel - opts: CreateOpts root: Logger parent?: LogEntry + isPlaceholder?: boolean } -// TODO Fix any cast -export function resolveParam(param?: string | T): T { - return typeof param === "string" ? { msg: param } : param || {} +function resolveParams(params?: string | UpdateLogEntryParams): UpdateLogEntryParams { + if (!params) { + return {} + } else if (typeof params === "string") { + return { msg: params } + } else { + return params + } } export class LogEntry extends LogNode { - public opts: UpdateOpts - public root: Logger - - constructor({ level, opts, root, parent }: LogEntryConstructor) { - const { id, ...otherOpts } = opts - super(level, parent, id) - this.root = root - this.opts = otherOpts - if (this.level === LogLevel.error) { - this.opts.status = "error" + private messageStates?: MessageState[] + private metadata?: LogEntryMetadata + public readonly root: Logger + public readonly data?: any + public readonly fromStdStream?: boolean + public readonly indent?: number + public readonly errorData?: GardenError + public readonly childEntriesInheritLevel?: boolean + public readonly id?: string + + constructor(params: LogEntryConstructor) { + super(params.level, params.parent, params.id) + + this.root = params.root + this.data = params.data + this.fromStdStream = params.fromStdStream + this.indent = params.indent + this.errorData = params.error + this.childEntriesInheritLevel = params.childEntriesInheritLevel + this.metadata = params.metadata + this.id = params.id + + if (!params.isPlaceholder) { + this.update({ + msg: params.msg, + emoji: params.emoji, + section: params.section, + symbol: params.symbol, + status: params.level === LogLevel.error ? "error" : params.status, + }) } } - private setOwnState(nextOpts: UpdateOpts): void { - let msg: string | string[] | undefined - const { append, msg: nextMsg } = nextOpts - const prevMsg = this.opts.msg - if (prevMsg !== undefined && nextMsg && append) { - msg = flatten([...[prevMsg], ...[nextMsg]]) - } else if (nextMsg) { - msg = nextMsg - } else { - msg = prevMsg + /** + * Updates the log entry with a few invariants: + * 1. msg, emoji, section, status, and symbol can only be replaced with a value of same type, not removed + * 2. append is always set explicitly (the next message state does not inherit the previous value) + * 3. next metadata is merged with the previous metadata + */ + protected update(updateParams: UpdateLogEntryParams): void { + const messageState = this.getMessageState() + + // Explicitly set all the fields so the shape stays consistent + const nextMessageState: MessageState = { + // Ensure empty string gets set + msg: typeof updateParams.msg === "string" ? updateParams.msg : messageState.msg, + emoji: updateParams.emoji || messageState.emoji, + section: updateParams.section || messageState.section, + status: updateParams.status || messageState.status, + symbol: updateParams.symbol || messageState.symbol, + // Next state does not inherit the append field + append: updateParams.append, + timestamp: Date.now(), } - // Hack to preserve section alignment if symbols or spinners disappear - const hadSymbolOrSpinner = this.opts.symbol || this.opts.status === "active" - const hasSymbolOrSpinner = nextOpts.symbol || nextOpts.status === "active" - if (this.opts.section && hadSymbolOrSpinner && !hasSymbolOrSpinner) { - nextOpts.symbol = "empty" + // Hack to preserve section alignment if spinner disappears + const hadSpinner = messageState.status === "active" + const hasSymbolOrSpinner = nextMessageState.symbol || nextMessageState.status === "active" + if (nextMessageState.section && hadSpinner && !hasSymbolOrSpinner) { + nextMessageState.symbol = "empty" } - this.opts = { ...this.opts, ...nextOpts, msg } + this.messageStates = [...this.messageStates || [], nextMessageState] + + if (updateParams.metadata) { + this.metadata = { ...this.metadata || {}, ...updateParams.metadata } + } } // Update node and child nodes - private deepSetState(opts: UpdateOpts): void { - const wasActive = this.opts.status === "active" + private deepUpdate(updateParams: UpdateLogEntryParams): void { + const wasActive = this.getMessageState().status === "active" - this.setOwnState(opts) + this.update(updateParams) - // Stop active child nodes if parent is no longer active - if (wasActive && this.opts.status !== "active") { + // Stop active child nodes if no longer active + if (wasActive && updateParams.status !== "active") { getChildEntries(this).forEach(entry => { - if (entry.opts.status === "active") { - entry.setOwnState({ status: "done" }) + if (entry.getMessageState().status === "active") { + entry.update({ status: "done" }) } }) } } - protected createNode(level: LogLevel, param: CreateParam) { - const opts = { - indent: (this.opts.indent || 0) + 1, - ...resolveParam(param), - } + protected createNode(params: CreateNodeParams) { + const indent = params.indent !== undefined ? params.indent : (this.indent || 0) + 1 - // If childEntriesInheritLevel is set to true, all children must have a level geq the level + // If childEntriesInheritLevel is set to true, all children must have a level geq to the level // of the parent entry that set the flag. - const parentWithPreserveFlag = findParentEntry(this, entry => !!entry.opts.childEntriesInheritLevel) - const childLevel = parentWithPreserveFlag ? Math.max(parentWithPreserveFlag.level, level) : level + const parentWithPreserveFlag = findParentEntry(this, entry => !!entry.childEntriesInheritLevel) + const level = parentWithPreserveFlag ? Math.max(parentWithPreserveFlag.level, params.level) : params.level return new LogEntry({ - opts, - level: childLevel, + ...params, + indent, + level, root: this.root, parent: this, }) @@ -141,70 +181,77 @@ export class LogEntry extends LogNode { this.root.onGraphChange(node) } - placeholder(level: LogLevel = LogLevel.info, param?: CreateParam): LogEntry { + getMetadata() { + return this.metadata + } + + getMessageStates() { + return this.messageStates + } + + /** + * Returns a deep copy of the latest message state, if availble. + * Otherwise return an empty object of type MessageState for convenience. + */ + getMessageState() { + if (!this.messageStates) { + return {} + } + + // Use spread operator to clone the array + const msgState = [...this.messageStates][this.messageStates.length - 1] + // ...and the object itself + return { ...msgState } + } + + placeholder(level: LogLevel = LogLevel.info, childEntriesInheritLevel = false): LogEntry { // Ensure placeholder child entries align with parent context - const indent = Math.max((this.opts.indent || 0) - 1, - 1) - return this.appendNode(level, { ...resolveParam(param), indent }) + const indent = Math.max((this.indent || 0) - 1, - 1) + return this.addNode({ level, indent, childEntriesInheritLevel, isPlaceholder: true }) } // Preserves status - setState(param?: string | UpdateOpts): LogEntry { - this.deepSetState({ ...resolveParam(param), status: this.opts.status }) + setState(params?: string | UpdateLogEntryParams): LogEntry { + this.deepUpdate({ ...resolveParams(params) }) this.root.onGraphChange(this) return this } - setDone(param?: string | Omit): LogEntry { - this.deepSetState({ ...resolveParam(param), status: "done" }) + setDone(params?: string | Omit): LogEntry { + this.deepUpdate({ ...resolveParams(params), status: "done" }) this.root.onGraphChange(this) return this } - setSuccess(param?: string | Omit): LogEntry { - this.deepSetState({ ...resolveParam(param), symbol: "success", status: "success" }) + setSuccess(params?: string | Omit): LogEntry { + this.deepUpdate({ ...resolveParams(params), symbol: "success", status: "success" }) this.root.onGraphChange(this) return this } - setError(param?: string | Omit): LogEntry { - this.deepSetState({ ...resolveParam(param), symbol: "error", status: "error" }) + setError(params?: string | Omit): LogEntry { + this.deepUpdate({ ...resolveParams(params), symbol: "error", status: "error" }) this.root.onGraphChange(this) return this } - setWarn(param?: string | Omit): LogEntry { - this.deepSetState({ ...resolveParam(param), symbol: "warning", status: "warn" }) + setWarn(param?: string | Omit): LogEntry { + this.deepUpdate({ ...resolveParams(param), symbol: "warning", status: "warn" }) this.root.onGraphChange(this) return this } - fromStdStream(): boolean { - return !!this.opts.fromStdStream - } - stopAll() { return this.root.stop() } stop() { // Stop gracefully if still in active state - if (this.opts.status === "active") { - this.setOwnState({ symbol: "empty", status: "done" }) + if (this.getMessageState().status === "active") { + this.update({ symbol: "empty", status: "done" }) this.root.onGraphChange(this) } return this } - inspect() { - console.log(JSON.stringify(sanitizeObject({ - ...this.opts, - level: this.level, - children: this.children, - }))) - } - - filterBySection(section: string): LogEntry[] { - return getChildEntries(this).filter(entry => entry.opts.section === section) - } - } diff --git a/garden-service/src/logger/log-node.ts b/garden-service/src/logger/log-node.ts index e04d43d9f5..4fc79b57b8 100644 --- a/garden-service/src/logger/log-node.ts +++ b/garden-service/src/logger/log-node.ts @@ -9,7 +9,7 @@ import * as uniqid from "uniqid" import { round } from "lodash" -import { LogEntry, CreateParam } from "./log-entry" +import { LogEntry, LogEntryParams } from "./log-entry" export enum LogLevel { error = 0, @@ -20,6 +20,18 @@ export enum LogLevel { silly = 5, } +export interface CreateNodeParams extends LogEntryParams { + level: LogLevel + isPlaceholder?: boolean +} + +export function resolveParams(level: LogLevel, params: string | LogEntryParams): CreateNodeParams { + if (typeof params === "string") { + return { msg: params, level } + } + return { ...params, level } +} + export abstract class LogNode { public readonly timestamp: number public readonly key: string @@ -35,44 +47,44 @@ export abstract class LogNode { this.children = [] } - protected abstract createNode(level: LogLevel, param: CreateParam): LogEntry + protected abstract createNode(params: CreateNodeParams): LogEntry protected abstract onGraphChange(node: LogEntry): void /** * A placeholder entry is an empty entry whose children should be aligned with the parent context. * Useful for setting a placeholder in the middle of the log that can later be populated. */ - abstract placeholder(level: LogLevel, param?: CreateParam): LogEntry + abstract placeholder(level: LogLevel, childEntriesInheritLevel?: boolean): LogEntry - protected appendNode(level: LogLevel, param: CreateParam): LogEntry { - const node = this.createNode(level, param) + protected addNode(params: CreateNodeParams): LogEntry { + const node = this.createNode(params) this.children.push(node) this.onGraphChange(node) return node } - silly(param: CreateParam): LogEntry { - return this.appendNode(LogLevel.silly, param) + silly(params: string | LogEntryParams): LogEntry { + return this.addNode(resolveParams(LogLevel.silly, params)) } - debug(param: CreateParam): LogEntry { - return this.appendNode(LogLevel.debug, param) + debug(params: string | LogEntryParams): LogEntry { + return this.addNode(resolveParams(LogLevel.debug, params)) } - verbose(param: CreateParam): LogEntry { - return this.appendNode(LogLevel.verbose, param) + verbose(params: string | LogEntryParams): LogEntry { + return this.addNode(resolveParams(LogLevel.verbose, params)) } - info(param: CreateParam): LogEntry { - return this.appendNode(LogLevel.info, param) + info(params: string | LogEntryParams): LogEntry { + return this.addNode(resolveParams(LogLevel.info, params)) } - warn(param: CreateParam): LogEntry { - return this.appendNode(LogLevel.warn, param) + warn(params: string | LogEntryParams): LogEntry { + return this.addNode(resolveParams(LogLevel.warn, params)) } - error(param: CreateParam): LogEntry { - return this.appendNode(LogLevel.error, param) + error(params: string | LogEntryParams): LogEntry { + return this.addNode(resolveParams(LogLevel.error, params)) } /** diff --git a/garden-service/src/logger/logger.ts b/garden-service/src/logger/logger.ts index 48028997ac..a1702d5dfa 100644 --- a/garden-service/src/logger/logger.ts +++ b/garden-service/src/logger/logger.ts @@ -6,8 +6,8 @@ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ -import { LogNode } from "./log-node" -import { LogEntry, CreateOpts, resolveParam } from "./log-entry" +import { LogNode, CreateNodeParams } from "./log-node" +import { LogEntry } from "./log-entry" import { getChildEntries, findLogNode } from "./util" import { Writer } from "./writers/base" import { InternalError, ParameterError } from "../exceptions" @@ -119,13 +119,13 @@ export class Logger extends LogNode { this.useEmoji = config.useEmoji === false ? false : true } - protected createNode(level: LogLevel, opts: CreateOpts): LogEntry { - return new LogEntry({ level, root: this, opts: resolveParam(opts) }) + protected createNode(params: CreateNodeParams): LogEntry { + return new LogEntry({ ...params, root: this }) } placeholder(level: LogLevel = LogLevel.info): LogEntry { // Ensure placeholder child entries align with parent context - return this.appendNode(level, { indent: - 1 }) + return this.addNode({ level, indent: - 1, isPlaceholder: true }) } onGraphChange(entry: LogEntry) { @@ -133,11 +133,11 @@ export class Logger extends LogNode { } getLogEntries(): LogEntry[] { - return getChildEntries(this).filter(entry => !entry.fromStdStream()) + return getChildEntries(this).filter(entry => !entry.fromStdStream) } filterBySection(section: string): LogEntry[] { - return getChildEntries(this).filter(entry => entry.opts.section === section) + return getChildEntries(this).filter(entry => entry.getMessageState().section === section) } findById(id: string): LogEntry | void { diff --git a/garden-service/src/logger/renderers.ts b/garden-service/src/logger/renderers.ts index 92ffb2d921..d5c104a664 100644 --- a/garden-service/src/logger/renderers.ts +++ b/garden-service/src/logger/renderers.ts @@ -21,7 +21,7 @@ import cliTruncate = require("cli-truncate") import stringWidth = require("string-width") import hasAnsi = require("has-ansi") -import { LogEntry } from "./log-entry" +import { LogEntry, MessageState } from "./log-entry" import { JsonLogEntry } from "./writers/json-terminal-writer" import { highlightYaml, deepFilter } from "../util/util" import { isNumber } from "util" @@ -59,6 +59,24 @@ function applyRenderers(renderers: Renderers): Function { return flow(curried) } +/** + * Returns the most recent message's `msg` field if it has `append` set to `false`. + * Otherwise returns longest chain of messages with `append: true` (starting from the most recent message). + */ +export function chainMessages(messageStates: MessageState[], chain: string[] = []): string | string[] { + const latestState = messageStates[messageStates.length - 1] + if (!latestState) { + return chain.length === 1 ? chain[0] : chain.reverse() + } + + chain = latestState.msg !== undefined ? [...chain, latestState.msg] : chain + + if (latestState.append) { + return chainMessages(messageStates.slice(0, -1), chain) + } + return chain.reverse() +} + export function combine(renderers: Renderers): string { const initOutput = [] return applyRenderers(renderers)(initOutput).join("") @@ -66,11 +84,11 @@ export function combine(renderers: Renderers): string { /*** RENDERERS ***/ export function leftPad(entry: LogEntry): string { - return "".padStart((entry.opts.indent || 0) * 3) + return "".padStart((entry.indent || 0) * 3) } export function renderEmoji(entry: LogEntry): string { - const { emoji } = entry.opts + const { emoji } = entry.getMessageState() if (emoji) { return printEmoji(emoji, entry) + " " } @@ -78,7 +96,7 @@ export function renderEmoji(entry: LogEntry): string { } export function renderError(entry: LogEntry) { - const { msg, error } = entry.opts + const { errorData: error } = entry if (error) { const { detail, message, stack } = error let out = stack || message @@ -99,11 +117,13 @@ export function renderError(entry: LogEntry) { } return out } + + const msg = chainMessages(entry.getMessageStates() || []) return isArray(msg) ? msg.join(" ") : msg || "" } export function renderSymbol(entry: LogEntry): string { - const { symbol } = entry.opts + const { symbol } = entry.getMessageState() if (symbol === "empty") { return " " } @@ -111,7 +131,9 @@ export function renderSymbol(entry: LogEntry): string { } export function renderMsg(entry: LogEntry): string { - const { fromStdStream, msg, status } = entry.opts + const { fromStdStream } = entry + const { status } = entry.getMessageState() + const msg = chainMessages(entry.getMessageStates() || []) if (fromStdStream) { return isArray(msg) ? msg.join(" ") : msg || "" @@ -127,7 +149,7 @@ export function renderMsg(entry: LogEntry): string { } export function renderData(entry: LogEntry): string { - const { data } = entry.opts + const { data } = entry if (!data) { return "" } @@ -136,7 +158,7 @@ export function renderData(entry: LogEntry): string { } export function renderSection(entry: LogEntry): string { - const { msg, section } = entry.opts + const { msg, section } = entry.getMessageState() if (section && msg) { return `${sectionStyle(section)} → ` } else if (section) { @@ -145,16 +167,9 @@ export function renderSection(entry: LogEntry): string { return "" } -export function renderDuration(entry: LogEntry): string { - const { showDuration = false } = entry.opts - return showDuration - ? msgStyle(` (finished in ${entry.getDuration()}s)`) - : "" -} - export function formatForTerminal(entry: LogEntry): string { - const { msg, data, section, emoji, showDuration, symbol } = entry.opts - const empty = [msg, data, section, emoji, showDuration, symbol].every(val => val === undefined) + const { msg, emoji, section, symbol } = entry.getMessageState() + const empty = [msg, section, emoji, symbol].every(val => val === undefined) if (empty) { return "" } @@ -165,7 +180,6 @@ export function formatForTerminal(entry: LogEntry): string { [renderEmoji, [entry]], [renderMsg, [entry]], [renderData, [entry]], - [renderDuration, [entry]], ["\n"], ]) } @@ -184,12 +198,13 @@ export function cleanWhitespace(str) { } export function formatForJSON(entry: LogEntry): JsonLogEntry { - const { msg, data, section, showDuration, metadata } = entry.opts + const { data } = entry + const metadata = entry.getMetadata() + const { msg, section } = entry.getMessageState() return { msg: cleanForJSON(msg), data, metadata, section: cleanForJSON(section), - durationMs: showDuration ? entry.getDuration(3) * 1000 : undefined, } } diff --git a/garden-service/src/logger/util.ts b/garden-service/src/logger/util.ts index 1fbb02b921..c1bbbb7f53 100644 --- a/garden-service/src/logger/util.ts +++ b/garden-service/src/logger/util.ts @@ -10,13 +10,13 @@ import * as nodeEmoji from "node-emoji" import chalk from "chalk" import * as CircularJSON from "circular-json" import { LogNode } from "./log-node" -import { LogEntry, CreateOpts, EmojiName } from "./log-entry" +import { LogEntry, LogEntryParams, EmojiName } from "./log-entry" export interface Node { children: any[] } -export type LogOptsResolvers = { [K in keyof CreateOpts]?: Function } +export type LogOptsResolvers = { [K in keyof LogEntryParams]?: Function } export type ProcessNode = (node: T) => boolean diff --git a/garden-service/src/logger/writers/basic-terminal-writer.ts b/garden-service/src/logger/writers/basic-terminal-writer.ts index 8acf608d50..7610766bb2 100644 --- a/garden-service/src/logger/writers/basic-terminal-writer.ts +++ b/garden-service/src/logger/writers/basic-terminal-writer.ts @@ -19,8 +19,11 @@ export class BasicTerminalWriter extends Writer { const level = this.level || logger.level if (level >= entry.level) { // Use info symbol for active entries because basic logger doesn't have a spinner - if (entry.opts.status === "active" && !entry.opts.symbol) { - entry.opts.symbol = "info" + const msgState = entry.getMessageState() + if (msgState.status === "active" && !msgState.symbol) { + msgState.symbol = "info" + // We know that entry.messages isn't empty if the status is defined + entry.getMessageStates()![entry.getMessageStates()!.length - 1] = msgState } return formatForTerminal(entry) } diff --git a/garden-service/src/logger/writers/fancy-terminal-writer.ts b/garden-service/src/logger/writers/fancy-terminal-writer.ts index d4b8ca5e29..8dc289bfc9 100644 --- a/garden-service/src/logger/writers/fancy-terminal-writer.ts +++ b/garden-service/src/logger/writers/fancy-terminal-writer.ts @@ -140,7 +140,7 @@ export class FancyTerminalWriter extends Writer { this.updatePending = false // Suspend processing and write immediately if a lot of data is being intercepted, e.g. when user is typing in input - if (log.fromStdStream() && !didWrite) { + if (log.fromStdStream && !didWrite) { const now = Date.now() const throttleProcessing = this.lastInterceptAt && (now - this.lastInterceptAt) < THROTTLE_MS this.lastInterceptAt = now @@ -195,7 +195,7 @@ export class FancyTerminalWriter extends Writer { let spinnerX let spinnerCoords: Coords | undefined - if (entry.opts.status === "active") { + if (entry.getMessageState().status === "active") { spinnerX = leftPad(entry).length spinnerFrame = this.tickSpinner(entry.key) spinnerCoords = [spinnerX, currentLineNumber] @@ -204,11 +204,7 @@ export class FancyTerminalWriter extends Writer { } const text = [entry] - .map(e => ( - e.fromStdStream() - ? renderMsg(e) - : formatForTerminal(e) - )) + .map(e => e.fromStdStream ? renderMsg(e) : formatForTerminal(e)) .map(str => ( spinnerFrame ? `${str.slice(0, spinnerX)}${spinnerStyle(spinnerFrame)} ${str.slice(spinnerX)}` diff --git a/garden-service/src/server/commands.ts b/garden-service/src/server/commands.ts index fe49c2649d..9b0db82840 100644 --- a/garden-service/src/server/commands.ts +++ b/garden-service/src/server/commands.ts @@ -67,7 +67,7 @@ export async function resolveRequest( const command = commandSpec.command // We generally don't want actions to log anything in the server. - const cmdLog = log.placeholder(LogLevel.silly, { childEntriesInheritLevel: true }) + const cmdLog = log.placeholder(LogLevel.silly, true) const cmdArgs = mapParams(ctx, request.parameters, command.arguments) const optParams = extend({ ...GLOBAL_OPTIONS, ...command.options }) diff --git a/garden-service/test/run-garden.ts b/garden-service/test/run-garden.ts index 5a6c1f058a..f58bc4843b 100644 --- a/garden-service/test/run-garden.ts +++ b/garden-service/test/run-garden.ts @@ -9,7 +9,7 @@ import { JsonLogEntry } from "../src/logger/writers/json-terminal-writer" import { ParameterError } from "../src/exceptions" import { dedent, deline } from "../src/util/string" import { GARDEN_SERVICE_ROOT } from "../src/constants" -import { UpdateOpts } from "../src/logger/log-entry" +import { UpdateLogEntryParams } from "../src/logger/log-entry" import chalk from "chalk" export const gardenBinPath = parsedArgs.binPath || resolve(GARDEN_SERVICE_ROOT, "bin", "garden") @@ -87,7 +87,7 @@ export function commandReloadedStep(): WatchTestStep { } } -function stringifyJsonLog(entries: UpdateOpts[]) { +function stringifyJsonLog(entries: UpdateLogEntryParams[]) { return entries .map(l => { const msg = chalk.white(l.msg || "") diff --git a/garden-service/test/unit/src/logger/log-entry.ts b/garden-service/test/unit/src/logger/log-entry.ts index 4ce48c3193..21a0219d76 100644 --- a/garden-service/test/unit/src/logger/log-entry.ts +++ b/garden-service/test/unit/src/logger/log-entry.ts @@ -1,7 +1,8 @@ import { expect } from "chai" import { getLogger } from "../../../../src/logger/logger" - +import { freezeTime } from "../../../helpers" +import { TaskMetadata } from "../../../../src/logger/log-entry" const logger = getLogger() beforeEach(() => { @@ -16,11 +17,11 @@ describe("LogEntry", () => { const nested = nonEmpty.info("foo") const nestedPh = nested.placeholder() const indents = [ - ph1.opts.indent, - ph2.opts.indent, - nonEmpty.opts.indent, - nested.opts.indent, - nestedPh.opts.indent, + ph1.indent, + ph2.indent, + nonEmpty.indent, + nested.indent, + nestedPh.indent, ] expect(indents).to.eql([-1, -1, 0, 1, 0]) }) @@ -32,12 +33,12 @@ describe("LogEntry", () => { const deepDeepPh = deepDeepNested.placeholder() const deepDeepNested2 = deepDeepPh.info("") const indents = [ - entry.opts.indent, - nested.opts.indent, - deepNested.opts.indent, - deepDeepNested.opts.indent, - deepDeepPh.opts.indent, - deepDeepNested2.opts.indent, + entry.indent, + nested.indent, + deepNested.indent, + deepDeepNested.indent, + deepDeepPh.indent, + deepDeepNested2.indent, ] expect(indents).to.eql([undefined, 1, 2, 3, 2, 3]) }) @@ -63,51 +64,175 @@ describe("LogEntry", () => { }) }) describe("setState", () => { - it("should update entry state and optionally append new msg to previous msg", () => { - const entry = logger.info("") - entry.setState("new") - expect(entry.opts.msg).to.equal("new") - entry.setState({ msg: "new2", append: true }) - expect(entry.opts.msg).to.eql(["new", "new2"]) + const emptyState = { + msg: undefined, + emoji: undefined, + section: undefined, + symbol: undefined, + status: undefined, + append: undefined, + } + it("should update entry state", () => { + const timestamp = freezeTime().valueOf() + const taskMetaData: TaskMetadata = { + type: "a", + key: "a", + status: "active", + uid: "1", + versionString: "123", + } + const entry = logger.placeholder() + entry.setState({ + msg: "hello", + emoji: "haircut", + section: "caesar", + symbol: "info", + status: "done", + metadata: { task: taskMetaData }, + }) + + expect(entry.getMessageStates()).to.eql([{ + msg: "hello", + emoji: "haircut", + section: "caesar", + symbol: "info", + status: "done", + append: undefined, + timestamp, + }]) + expect(entry.getMetadata()).to.eql({ task: taskMetaData }) + }) + it("should overwrite previous values", () => { + const timestamp = freezeTime().valueOf() + const entry = logger.placeholder() + entry.setState({ + msg: "hello", + emoji: "haircut", + section: "caesar", + symbol: "info", + status: "done", + }) + entry.setState({ + msg: "world", + emoji: "hamburger", + }) + expect(entry.getMessageStates()).to.eql([ + { + msg: "hello", + emoji: "haircut", + section: "caesar", + symbol: "info", + status: "done", + append: undefined, + timestamp, + }, + { + msg: "world", + emoji: "hamburger", + section: "caesar", + symbol: "info", + status: "done", + append: undefined, + timestamp, + }, + ]) + }) + it("should set the 'append' field separately for each message state", () => { + const timestamp = freezeTime().valueOf() + const entry = logger.placeholder() + + entry.setState({ append: true }) + expect(entry.getMessageStates()).to.eql([ + { ...emptyState, append: true, timestamp }, + ]) + + entry.setState({ msg: "boo" }) + expect(entry.getMessageStates()).to.eql([ + { ...emptyState, append: true, timestamp }, + { ...emptyState, append: undefined, msg: "boo", timestamp }, + ]) + + entry.setState({ append: true }) + expect(entry.getMessageStates()).to.eql([ + { ...emptyState, append: true, timestamp }, + { ...emptyState, append: undefined, msg: "boo", timestamp }, + { ...emptyState, append: true, msg: "boo", timestamp }, + ]) }) - }) - describe("setState", () => { it("should preserve status", () => { const entry = logger.info("") entry.setSuccess() entry.setState("change text") - expect(entry.opts.status).to.equal("success") + expect(entry.getMessageState().status).to.equal("success") + }) + it("should set symbol to empty if entry has section and spinner disappears (to preserve alignment)", () => { + const entry = logger.info({ status: "active", section: "foo" }) + entry.setState({ status: "error" }) + expect(entry.getMessageState().symbol).to.equal("empty") + + const newEntry = logger.info({ status: "active", section: "foo", symbol: "info" }) + newEntry.setState({ status: "error" }) + expect(newEntry.getMessageState().symbol).to.equal("info") + }) + it("should update the metadata property", () => { + const timestamp = freezeTime().valueOf() + const taskMetaDataA: TaskMetadata = { + type: "a", + key: "a", + status: "active", + uid: "1", + versionString: "123", + } + const taskMetaDataB: TaskMetadata = { + ...taskMetaDataA, + status: "error", + } + const entry = logger.placeholder() + entry.setState({ metadata: { task: taskMetaDataA } }) + expect(entry.getMetadata()).to.eql({ task: taskMetaDataA }) + // Message states should not change + expect(entry.getMessageStates()).to.eql([ + { ...emptyState, timestamp }, + ]) + + entry.setState({ metadata: { task: taskMetaDataB } }) + expect(entry.getMetadata()).to.eql({ task: taskMetaDataB }) + expect(entry.getMessageStates()).to.eql([ + { ...emptyState, timestamp }, + { ...emptyState, timestamp }, + ]) + }) }) describe("setDone", () => { it("should update entry state and set status to done", () => { const entry = logger.info("") entry.setDone() - expect(entry.opts.status).to.equal("done") + expect(entry.getMessageState().status).to.equal("done") }) }) describe("setSuccess", () => { it("should update entry state and set status and symbol to success", () => { const entry = logger.info("") entry.setSuccess() - expect(entry.opts.status).to.equal("success") - expect(entry.opts.symbol).to.equal("success") + expect(entry.getMessageState().status).to.equal("success") + expect(entry.getMessageState().symbol).to.equal("success") }) }) describe("setError", () => { it("should update entry state and set status and symbol to error", () => { const entry = logger.info("") entry.setError() - expect(entry.opts.status).to.equal("error") - expect(entry.opts.symbol).to.equal("error") + expect(entry.getMessageState().status).to.equal("error") + expect(entry.getMessageState().symbol).to.equal("error") }) }) describe("setWarn", () => { it("should update entry state and set status and symbol to warn", () => { const entry = logger.info("") entry.setWarn() - expect(entry.opts.status).to.equal("warn") - expect(entry.opts.symbol).to.equal("warning") + expect(entry.getMessageState().status).to.equal("warn") + expect(entry.getMessageState().symbol).to.equal("warning") }) }) }) diff --git a/garden-service/test/unit/src/logger/logger.ts b/garden-service/test/unit/src/logger/logger.ts index 00a9d6adbd..afc19da05f 100644 --- a/garden-service/test/unit/src/logger/logger.ts +++ b/garden-service/test/unit/src/logger/logger.ts @@ -15,7 +15,7 @@ describe("Logger", () => { logger.info({ msg: "0" }) logger.info({ msg: "a1", id: "a" }) logger.info({ msg: "a2", id: "a" }) - expect(logger.findById("a")["opts"]["msg"]).to.eql("a1") + expect(logger.findById("a")["messageStates"][0]["msg"]).to.eql("a1") expect(logger.findById("z")).to.be.undefined }) }) diff --git a/garden-service/test/unit/src/logger/renderers.ts b/garden-service/test/unit/src/logger/renderers.ts index 636685ca28..10a6f5bebf 100644 --- a/garden-service/test/unit/src/logger/renderers.ts +++ b/garden-service/test/unit/src/logger/renderers.ts @@ -6,7 +6,11 @@ import { msgStyle, errorStyle, formatForTerminal, + chainMessages, + renderError, } from "../../../../src/logger/renderers" +import { GardenError } from "../../../../src/exceptions" +import dedent = require("dedent") const logger = getLogger() @@ -25,7 +29,8 @@ describe("renderers", () => { expect(renderMsg(entry)).to.equal(msgStyle("hello message")) }) it("should join an array of messages with an arrow symbol and render with the message style", () => { - const entry = logger.info({ msg: ["message a", "message b"] }) + const entry = logger.info("message a") + entry.setState({ msg: "message b", append: true }) expect(renderMsg(entry)).to.equal(msgStyle("message a") + msgStyle(" → ") + msgStyle("message b")) }) it("should render the message without styles if the entry is from an intercepted stream", () => { @@ -33,7 +38,8 @@ describe("renderers", () => { expect(renderMsg(entry)).to.equal("hello stream") }) it("should join an array of messages and render without styles if the entry is from an intercepted stream", () => { - const entry = logger.info({ fromStdStream: true, msg: ["stream a", "stream b"] }) + const entry = logger.info({ fromStdStream: true, msg: "stream a" }) + entry.setState({ msg: "stream b", append: true }) expect(renderMsg(entry)).to.equal("stream a stream b") }) it("should render the message with the error style if the entry has error status", () => { @@ -42,9 +48,55 @@ describe("renderers", () => { }) it("should join an array of messages with an arrow symbol and render with the error style" + " if the entry has error status", () => { - const entry = logger.info({ msg: ["error a", "error b"], status: "error" }) + const entry = logger.info({ msg: "error a", status: "error" }) + entry.setState({ msg: "error b", append: true }) expect(renderMsg(entry)).to.equal(errorStyle("error a") + errorStyle(" → ") + errorStyle("error b")) }) + describe("renderError", () => { + it("should render error object if present", () => { + const error: GardenError = { + message: "hello error", + type: "a", + detail: { + foo: "bar", + _internal: "no show", + }, + } + const entry = logger.info({ msg: "foo", error }) + expect(renderError(entry)).to.equal(dedent` + hello error + Error Details: + foo: bar\n + `) + }) + it("should join an array of messages if no error object", () => { + const entry = logger.info({ msg: "error a" }) + entry.setState({ msg: "moar", append: true }) + expect(renderError(entry)).to.eql("error a moar") + }) + }) + }) + describe("chainMessages", () => { + it("should correctly chain log messages", () => { + const timestamp = Date.now() + const messageStateTable = [ + [{ msg: "1", append: true }, { msg: "2", append: true }, { msg: "3", append: true }], + [{ msg: "1", append: false }, { msg: "2", append: true }, { msg: "3", append: true }], + [{ msg: "1", append: true }, { msg: "2", append: false }, { msg: "3", append: true }], + [{ msg: "1", append: false }, { msg: "2", append: false }, { msg: "3", append: true }], + [{ msg: "1", append: false }, { msg: "2", append: false }, { msg: "3", append: false }], + ].map(msgStates => msgStates.map(msgState => ({ ...msgState, timestamp }))) + const expects = [ + ["1", "2", "3"], + ["1", "2", "3"], + ["2", "3"], + ["2", "3"], + ["3"], + ] + messageStateTable.forEach((msgState, index) => { + expect(chainMessages(msgState)).to.eql(expects[index]) + }) + }) }) describe("formatForTerminal", () => { it("should return the entry as a formatted string with a new line character", () => {