From 3778d238b4e1bbbd9efa161a329cbe16253d427c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ey=C3=BE=C3=B3r=20Magn=C3=BAsson?= Date: Thu, 13 May 2021 13:00:10 +0200 Subject: [PATCH] improvement(core): better logs command This PR makes some improvements to the logs stream. E.g.: - More resilient logs follow mode - Color code logs - Add --since flag - Interleave logs when not in follow mode --- core/package.json | 5 +- core/src/cli/params.ts | 54 ++- core/src/commands/enterprise/enterprise.ts | 4 +- core/src/commands/logs.ts | 207 ++++++--- core/src/logger/logger.ts | 8 + core/src/logger/renderers.ts | 10 +- core/src/plugins/kubernetes/api.ts | 5 + core/src/plugins/kubernetes/kubernetes.ts | 1 + core/src/plugins/kubernetes/logs.ts | 424 +++++++++++++---- core/src/plugins/kubernetes/status/pod.ts | 3 +- .../types/plugin/service/getServiceLogs.ts | 25 +- core/src/util/util.ts | 3 +- core/test/helpers.ts | 24 +- .../src/plugins/kubernetes/container/logs.ts | 216 ++++++++- core/test/unit/src/commands/login.ts | 31 +- core/test/unit/src/commands/logout.ts | 23 +- core/test/unit/src/commands/logs.ts | 426 ++++++++++++++++++ docs/reference/commands.md | 21 +- examples/demo-project/garden.yml | 2 +- yarn.lock | 13 +- 20 files changed, 1277 insertions(+), 228 deletions(-) create mode 100644 core/test/unit/src/commands/logs.ts diff --git a/core/package.json b/core/package.json index f9a6e62814..e2ab28d8e2 100644 --- a/core/package.json +++ b/core/package.json @@ -111,6 +111,7 @@ "normalize-url": "^5.0.0", "open": "^7.0.4", "p-retry": "^4.2.0", + "parse-duration": "^1.0.0", "parse-git-config": "^3.0.0", "path-is-inside": "^1.0.2", "pluralize": "^8.0.0", @@ -134,7 +135,7 @@ "tmp-promise": "^3.0.2", "toposort": "^2.0.2", "tough-cookie": "^4.0.0", - "ts-stream": "^2.0.1", + "ts-stream": "^3.0.0", "typeorm-with-better-sqlite3": "^0.2.27", "typescript-memoize": "^1.0.0-alpha.3", "uniqid": "^5.2.0", @@ -262,4 +263,4 @@ ] }, "gitHead": "b0647221a4d2ff06952bae58000b104215aed922" -} \ No newline at end of file +} diff --git a/core/src/cli/params.ts b/core/src/cli/params.ts index b3ef63dd34..3b56fc2f71 100644 --- a/core/src/cli/params.ts +++ b/core/src/cli/params.ts @@ -14,7 +14,7 @@ import { joi, DeepPrimitiveMap } from "../config/common" import { ParameterError } from "../exceptions" import { parseEnvironment } from "../config/project" import { LOGGER_TYPES, getLogLevelChoices, envSupportsEmoji } from "../logger/logger" -import { deline } from "../util/string" +import { dedent, deline } from "../util/string" import chalk = require("chalk") import { LogLevel } from "../logger/log-node" import { safeDumpYaml } from "../util/util" @@ -32,6 +32,15 @@ export const OUTPUT_RENDERERS = { }, } +export const validDurationUnits = ["d", "h", "m", "s"] + +function splitDuration(duration: string) { + return duration + .trim() + .split(/([0-9]+)/) + .filter(Boolean) +} + export interface ParameterConstructor { help: string required?: boolean @@ -158,6 +167,49 @@ export class PathParameter extends Parameter { } } +export class DurationParameter extends Parameter { + type = "moment" + schema = joi.string() + + coerce(input: string): string { + const parts = splitDuration(input) + const expectedType = dedent` + Duration where unit is one of ${validDurationUnits.join( + ", " + )} and length is an integer. For example '1d', '10m', '20s'. + ` + if (parts.length !== 2) { + throw new ParameterError(`Could not parse "${input}" as duration`, { + expectedType, + input, + }) + } + const length = parseInt(parts[0], 10) + const unit = parts[1] + if (isNaN(length)) { + throw new ParameterError( + `Could not parse "${input}" as duration, length must be an integer. Received ${length}`, + { + expectedType, + input, + } + ) + } + if (!validDurationUnits.includes(unit)) { + throw new ParameterError( + `Could not parse "${input}" as duration, unit must be one of ${validDurationUnits.join( + ", " + )}. Received ${unit}`, + { + expectedType, + input, + } + ) + } + return input + } +} + export class PathsParameter extends StringsParameter { type = "array:path" diff --git a/core/src/commands/enterprise/enterprise.ts b/core/src/commands/enterprise/enterprise.ts index 6b3444555e..4760fedc7c 100644 --- a/core/src/commands/enterprise/enterprise.ts +++ b/core/src/commands/enterprise/enterprise.ts @@ -15,8 +15,8 @@ import { UsersCommand } from "./users/users" export class EnterpriseCommand extends CommandGroup { name = "enterprise" help = dedent` - [EXPERIMENTAL] Manage Garden Enterprise resources such as users, groups and secrets. Requires - Garden Enterprise 1.14.0 or higher. + [EXPERIMENTAL] Manage Garden Enterprise resources such as users, groups and secrets. + Requires Garden Enterprise 1.14.0 or higher. ` subCommands = [SecretsCommand, UsersCommand, GroupsCommand] diff --git a/core/src/commands/logs.ts b/core/src/commands/logs.ts index 85c5e08835..f0fb6c5c79 100644 --- a/core/src/commands/logs.ts +++ b/core/src/commands/logs.ts @@ -8,17 +8,19 @@ import { Command, CommandResult, CommandParams } from "./base" import chalk from "chalk" -import { maxBy } from "lodash" +import { maxBy, sortBy } from "lodash" import { ServiceLogEntry } from "../types/plugin/service/getServiceLogs" import Bluebird = require("bluebird") import { GardenService } from "../types/service" import Stream from "ts-stream" -import { LoggerType } from "../logger/logger" -import dedent = require("dedent") +import { LoggerType, logLevelMap } from "../logger/logger" +import { StringsParameter, BooleanParameter, IntegerParameter, DurationParameter } from "../cli/params" +import { printHeader, renderDivider } from "../logger/util" +import stripAnsi = require("strip-ansi") import { LogLevel } from "../logger/log-node" -import { emptyRuntimeContext } from "../runtime-context" -import { StringsParameter, BooleanParameter, IntegerParameter } from "../cli/params" -import { printHeader } from "../logger/util" +import hasAnsi = require("has-ansi") +import { dedent } from "../util/string" +import { formatSection } from "../logger/renderers" const logsArgs = { services: new StringsParameter({ @@ -29,35 +31,70 @@ const logsArgs = { } const logsOpts = { - follow: new BooleanParameter({ + "follow": new BooleanParameter({ help: "Continuously stream new logs from the service(s).", alias: "f", cliOnly: true, }), - tail: new IntegerParameter({ - help: "Number of lines to show for each service. Defaults to -1, showing all log lines.", + "tail": new IntegerParameter({ + help: dedent` + Number of lines to show for each service. Defaults to showing all log lines (up to a certain limit). Takes precedence over + the \`--since\` flag if both are set. Note that we don't recommend using a large value here when in follow mode. + `, alias: "t", - defaultValue: -1, }), - // TODO - // since: new MomentParameter({ help: "Retrieve logs from the specified point onwards" }), + "show-container": new BooleanParameter({ + help: "Show the name of the container with log output. May not apply to all providers", + defaultValue: false, + }), + "timestamps": new BooleanParameter({ + help: "Show timestamps with log output.", + }), + "since": new DurationParameter({ + help: dedent` + Only show logs newer than a relative duration like 5s, 2m, or 3h. Defaults to \`"1m"\` when \`--follow\` is true + unless \`--tail\` is set. Note that we don't recommend using a large value here when in follow mode. + `, + }), + "original-color": new BooleanParameter({ + help: "Show the original color output of the logs instead of color coding them.", + defaultValue: false, + }), + "hide-service": new BooleanParameter({ + help: "Hide the service name and render the logs directly.", + defaultValue: false, + }), } type Args = typeof logsArgs type Opts = typeof logsOpts +export const colors = ["green", "cyan", "magenta", "yellow", "blueBright", "red"] + +/** + * Skip empty entries. + */ +function skipEntry(entry: ServiceLogEntry) { + const validDate = entry.timestamp && entry.timestamp instanceof Date && !isNaN(entry.timestamp.getTime()) + return !entry.msg && !validDate +} + export class LogsCommand extends Command { name = "logs" help = "Retrieves the most recent logs for the specified service(s)." description = dedent` - Outputs logs for all or specified services, and optionally waits for news logs to come in. + Outputs logs for all or specified services, and optionally waits for news logs to come in. Defaults + to getting logs from the last minute when in \`--follow\` mode. You can change this with the \`--since\` option. Examples: - garden logs # prints latest logs from all services - garden logs my-service # prints latest logs for my-service - garden logs -t # keeps running and streams all incoming logs to the console + garden logs # interleaves color-coded logs from all services (up to a certain limit) + garden logs --since 2d # interleaves color-coded logs from all services from the last 2 days + garden logs --tail 100 # interleaves the last 100 log lines from all services + garden logs service-a,service-b # interleaves color-coded logs for service-a and service-b + garden logs --follow # keeps running and streams all incoming logs to the console + garden logs --original-color # interleaves logs from all services and prints the original output color ` arguments = logsArgs @@ -72,61 +109,129 @@ export class LogsCommand extends Command { } async action({ garden, log, args, opts }: CommandParams): Promise> { - const { follow, tail } = opts + const { follow, timestamps } = opts + let tail = opts.tail as number | undefined + let since = opts.since as string | undefined + const originalColor = opts["original-color"] + const showContainer = opts["show-container"] + const hideService = opts["hide-service"] + + if (tail) { + // Tail takes precedence over since... + since = undefined + } else if (follow && !since) { + // ...but if tail is not set and we're in follow mode, we default to getting the most recent logs. + since = "1m" + } + const graph = await garden.getConfigGraph(log) - const services = graph.getServices({ names: args.services }) + const allServices = graph.getServices() + const services = args.services ? allServices.filter((s) => args.services?.includes(s.name)) : allServices + const serviceNames = services.map((s) => s.name).filter(Boolean) const maxServiceName = (maxBy(serviceNames, (serviceName) => serviceName.length) || "").length + // If the container name should be displayed, we align the output wrt to the longest container name + let maxContainerName = 1 const result: ServiceLogEntry[] = [] const stream = new Stream() - - void stream.forEach((entry) => { - // TODO: color each service differently for easier visual parsing - let timestamp = " " - - // bad timestamp values can cause crash if not caught - if (entry.timestamp) { + let details: string = "" + + if (tail) { + details = ` (showing last ${tail} lines from each service)` + } else if (since) { + details = ` (from the last '${since}' for each service)` + } + + log.info("") + log.info(chalk.white.bold("Service logs" + details + ":")) + log.info(chalk.white.bold(renderDivider())) + log.root.stop() + + // Map all service names in the project to a specific color. This ensures + // that in most cases services have the same color (unless any have been added/removed), + // regardless of what params you pass to the command. + const allServiceNames = allServices + .map((s) => s.name) + .filter(Boolean) + .sort() + const colorMap = allServiceNames.reduce((acc, serviceName, idx) => { + const color = colors[idx % colors.length] + acc[serviceName] = color + return acc + }, {}) + + const formatEntry = (entry: ServiceLogEntry) => { + const style = chalk[colorMap[entry.serviceName]] + const sectionStyle = style.bold + const serviceLog = originalColor ? entry.msg : stripAnsi(entry.msg) + + let timestamp: string | undefined + let container: string | undefined + + if (timestamps && entry.timestamp) { + timestamp = " " try { timestamp = entry.timestamp.toISOString() } catch {} } - log.info({ - section: entry.serviceName, - msg: `${chalk.yellowBright(timestamp)} → ${chalk.white(entry.msg)}`, - maxSectionWidth: maxServiceName, - }) + if (showContainer && entry.containerName) { + maxContainerName = Math.max(maxContainerName, entry.containerName.length) + container = entry.containerName + } - if (!follow) { + let out = "" + if (!hideService) { + out += `${sectionStyle(formatSection(entry.serviceName, maxServiceName))} → ` + } + if (container) { + out += `${sectionStyle(formatSection(container, maxContainerName))} → ` + } + if (timestamp) { + out += `${chalk.gray(timestamp)} → ` + } + if (originalColor) { + // If the line doesn't have ansi encoding, we color it white to prevent logger from applying styles. + out += hasAnsi(serviceLog) ? serviceLog : chalk.white(serviceLog) + } else { + out += style(serviceLog) + } + + return out + } + + void stream.forEach((entry) => { + // Skip emtpy entries + if (skipEntry(entry)) { + return + } + + if (follow) { + const levelStr = logLevelMap[entry.level || LogLevel.info] || "info" + const msg = formatEntry(entry) + log[levelStr]({ msg }) + } else { result.push(entry) } }) const actions = await garden.getActionRouter() - const voidLog = log.placeholder({ level: LogLevel.silly, childEntriesInheritLevel: true }) await Bluebird.map(services, async (service: GardenService) => { - const status = await actions.getServiceStatus({ - devMode: false, - hotReload: false, - log: voidLog, - // This shouldn't matter for this context, we're just checking if the service is up or not - runtimeContext: emptyRuntimeContext, - service, - }) - - if (status.state === "ready" || status.state === "outdated") { - await actions.getServiceLogs({ log, service, stream, follow, tail }) - } else { - await stream.write({ - serviceName: service.name, - timestamp: new Date(), - msg: chalk.yellow(``), - }) - } + await actions.getServiceLogs({ log, service, stream, follow, tail, since }) }) - return { result } + const sorted = sortBy(result, "timestamp") + + if (!follow) { + for (const entry of sorted) { + const levelStr = logLevelMap[entry.level || LogLevel.info] || "info" + const msg = formatEntry(entry) + log[levelStr]({ msg }) + } + } + + return { result: sorted } } } diff --git a/core/src/logger/logger.ts b/core/src/logger/logger.ts index 8033d29805..bfdd6c3f3e 100644 --- a/core/src/logger/logger.ts +++ b/core/src/logger/logger.ts @@ -25,6 +25,14 @@ import { range } from "lodash" export type LoggerType = "quiet" | "basic" | "fancy" | "fullscreen" | "json" export const LOGGER_TYPES = new Set(["quiet", "basic", "fancy", "fullscreen", "json"]) +export const logLevelMap = { + [LogLevel.error]: "error", + [LogLevel.warn]: "warn", + [LogLevel.info]: "info", + [LogLevel.verbose]: "verbose", + [LogLevel.debug]: "debug", + [LogLevel.silly]: "silly", +} const getLogLevelNames = () => getEnumKeys(LogLevel) const getNumericLogLevels = () => range(getLogLevelNames().length) // Allow string or numeric log levels as CLI choices diff --git a/core/src/logger/renderers.ts b/core/src/logger/renderers.ts index 9f20fb53bb..101f8e1f15 100644 --- a/core/src/logger/renderers.ts +++ b/core/src/logger/renderers.ts @@ -30,13 +30,12 @@ const cliPadEnd = (s: string, width: number): string => { return diff <= 0 ? s : s + repeat(" ", diff) } -function styleSection(section: string, width: number = MAX_SECTION_WIDTH) { +export function formatSection(section: string, width: number = MAX_SECTION_WIDTH) { const minWidth = Math.min(width, MAX_SECTION_WIDTH) - const formattedSection = [section] + return [section] .map((s) => cliTruncate(s, minWidth)) .map((s) => cliPadEnd(s, minWidth)) .pop() - return chalk.cyan.italic(formattedSection) } export const msgStyle = (s: string) => (hasAnsi(s) ? s : chalk.gray(s)) @@ -166,11 +165,12 @@ export function renderData(entry: LogEntry): string { } export function renderSection(entry: LogEntry): string { + const style = chalk.cyan.italic const { msg: msg, section, maxSectionWidth } = entry.getLatestMessage() if (section && msg) { - return `${styleSection(section, maxSectionWidth)} → ` + return `${style(formatSection(section, maxSectionWidth))} → ` } else if (section) { - return styleSection(section, maxSectionWidth) + return style(formatSection(section, maxSectionWidth)) } return "" } diff --git a/core/src/plugins/kubernetes/api.ts b/core/src/plugins/kubernetes/api.ts index a8835c7edd..2ea6f2eeec 100644 --- a/core/src/plugins/kubernetes/api.ts +++ b/core/src/plugins/kubernetes/api.ts @@ -33,6 +33,7 @@ import { Attach, V1Deployment, V1Service, + Log, } from "@kubernetes/client-node" import AsyncLock = require("async-lock") import request = require("request-promise") @@ -798,6 +799,10 @@ export class KubeApi { return handler.attach(namespace, podName, containerName, stdout || null, stderr || null, stdin || null, tty) } + getLogger() { + return new Log(this.config) + } + /** * Create an ad-hoc Pod. Use this method to handle race-condition cases when creating Pods. */ diff --git a/core/src/plugins/kubernetes/kubernetes.ts b/core/src/plugins/kubernetes/kubernetes.ts index 69303fb5e5..6ff6a7c165 100644 --- a/core/src/plugins/kubernetes/kubernetes.ts +++ b/core/src/plugins/kubernetes/kubernetes.ts @@ -255,5 +255,6 @@ export const gardenPlugin = () => handlers: containerHandlers, }, ], + // DEPRECATED: Remove stern in v0.13 tools: [kubectlSpec, helm3Spec, mutagenCliSpec, sternSpec], }) diff --git a/core/src/plugins/kubernetes/logs.ts b/core/src/plugins/kubernetes/logs.ts index f1a86e02b4..9ee62a49c6 100644 --- a/core/src/plugins/kubernetes/logs.ts +++ b/core/src/plugins/kubernetes/logs.ts @@ -6,14 +6,13 @@ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ -import chalk from "chalk" -import split from "split" import { omit, sortBy } from "lodash" import moment from "moment" +import parseDuration from "parse-duration" -import { GetServiceLogsResult, ServiceLogEntry } from "../../types/plugin/service/getServiceLogs" -import { KubernetesResource, KubernetesPod } from "./types" -import { getAllPods, getStaticLabelsFromPod, getSelectorString } from "./util" +import { ServiceLogEntry } from "../../types/plugin/service/getServiceLogs" +import { KubernetesResource, KubernetesPod, BaseResource } from "./types" +import { getAllPods } from "./util" import { KubeApi } from "./api" import { GardenService } from "../../types/service" import Stream from "ts-stream" @@ -24,6 +23,13 @@ import { PluginToolSpec } from "../../types/plugin/tools" import { PluginContext } from "../../plugin-context" import { getPodLogs } from "./status/pod" import { splitFirst } from "../../util/util" +import { Writable } from "stream" +import request from "request" +import { LogLevel } from "../../logger/log-node" + +// When not following logs, the entire log is read into memory and sorted. +// We therefore set a maximum on the number of lines we fetch. +const maxLogLinesInMemory = 100000 interface GetAllLogsParams { ctx: PluginContext @@ -33,7 +39,8 @@ interface GetAllLogsParams { service: GardenService stream: Stream follow: boolean - tail: number + tail?: number + since?: string resources: KubernetesResource[] } @@ -42,29 +49,27 @@ interface GetAllLogsParams { */ export async function streamK8sLogs(params: GetAllLogsParams) { const api = await KubeApi.factory(params.log, params.ctx, params.provider) - const pods = await getAllPods(api, params.defaultNamespace, params.resources) if (params.follow) { - const procs = await Bluebird.map(pods, (pod) => followLogs({ ...omit(params, "pods"), pod })).filter(Boolean) - - return new Promise((resolve, reject) => { - // Make sure to resolve if no processes get created - if (procs.length === 0) { - return resolve({}) - } - for (const proc of procs) { - proc.on("error", () => reject) - - proc.on("exit", () => resolve({})) - } - }) + const logsFollower = new K8sLogFollower({ ...params, k8sApi: api }) + await logsFollower.followLogs({ tail: params.tail, since: params.since }) } else { - await Bluebird.map(pods, (pod) => readLogsFromApi({ ...omit(params, "pods"), pod })) - return {} + const pods = await getAllPods(api, params.defaultNamespace, params.resources) + let tail = params.tail + if (!tail) { + const containers = pods.flatMap((pod) => { + return pod.spec!.containers.map((c) => c.name).filter((n) => !n.match(/garden-/)) + }) + tail = Math.floor(maxLogLinesInMemory / containers.length) + + params.log.debug(`Tail parameter not set explicitly. Setting to ${tail} to prevent log overflow.`) + } + await Bluebird.map(pods, (pod) => readLogs({ ...omit(params, "pods"), pod, tail })) } + return {} } -async function readLogsFromApi({ +async function readLogs({ log, ctx, provider, @@ -73,6 +78,7 @@ async function readLogsFromApi({ tail, pod, defaultNamespace, + since, }: { log: LogEntry ctx: PluginContext @@ -82,6 +88,7 @@ async function readLogsFromApi({ tail?: number pod: KubernetesPod defaultNamespace: string + since?: string }) { const api = await KubeApi.factory(log, ctx, provider) @@ -89,20 +96,23 @@ async function readLogsFromApi({ api, namespace: pod.metadata?.namespace || defaultNamespace, pod, - lineLimit: tail === -1 ? undefined : tail, + lineLimit: tail, timestamps: true, + sinceSeconds: since ? parseDuration(since, "s") || undefined : undefined, }) const serviceName = service.name const allLines = logs.flatMap(({ containerName, log: _log }) => { return _log.split("\n").map((line) => { + line = line.trimEnd() + const res = { serviceName, containerName } try { const [timestampStr, msg] = splitFirst(line, " ") const timestamp = moment(timestampStr).toDate() - return { serviceName, timestamp, msg: formatLine(containerName, msg) } + return { ...res, timestamp, msg } } catch { - return { serviceName, msg: formatLine(containerName, line) } + return { ...res, msg: line } } }) }) @@ -112,86 +122,320 @@ async function readLogsFromApi({ } } -function formatLine(containerName: string, line: string) { - return chalk.gray(containerName + " → ") + line.trimEnd() -} +type ConnectionStatus = "connected" | "error" | "closed" -async function followLogs({ - ctx, - log, - provider, - service, - stream, - tail, - pod, - defaultNamespace, -}: { - ctx: PluginContext - log: LogEntry - provider: KubernetesProvider - service: GardenService - stream: Stream - tail: number +interface LogConnection { pod: KubernetesPod - defaultNamespace: string -}) { - const sternArgs = [ - `--context=${provider.config.context}`, - `--namespace=${pod.metadata?.namespace || defaultNamespace}`, - `--exclude-container=garden-*`, - "--tail", - String(tail), - "--output=json", - "-t", - ] - - if (provider.config.kubeconfig) { - sternArgs.push(`--kubeconfig=${provider.config.kubeconfig}`) + containerName: string + namespace: string + request: request.Request + status: ConnectionStatus +} + +interface LogOpts { + tail?: number + since?: string +} + +const defaultRetryIntervalMs = 10000 + +/** + * A helper class for following logs and managing the logs connections. + * + * The class operates kind of like a control loop, fetching the state of all pods for a given service at + * an interval, comparing the result against current active connections and attempting re-connects as needed. + */ +export class K8sLogFollower { + private connections: { [key: string]: LogConnection } + private stream: Stream + private service: GardenService + private k8sApi: KubeApi + private defaultNamespace: string + private resources: KubernetesResource[] + private intervalId: NodeJS.Timer | null + private resolve: ((val: unknown) => void) | null + private retryIntervalMs: number + + constructor({ + service, + stream, + defaultNamespace, + k8sApi, + resources, + retryIntervalMs = defaultRetryIntervalMs, + }: { + service: GardenService + stream: Stream + k8sApi: KubeApi + defaultNamespace: string + resources: KubernetesResource[] + retryIntervalMs?: number + }) { + this.stream = stream + this.connections = {} + this.k8sApi = k8sApi + this.service = service + this.defaultNamespace = defaultNamespace + this.resources = resources + this.intervalId = null + this.resolve = null + this.retryIntervalMs = retryIntervalMs } - /* Getting labels on the pod with no numbers, - The Idea is these labels are less likely to change between different deployments of these pods - */ - const labels = getStaticLabelsFromPod(pod) - if (Object.keys(labels).length > 0) { - sternArgs.push(`${getSelectorString(labels)}`) - } else { - sternArgs.push(`${service.name}`) + /** + * Start following logs. This function doesn't return and simply keeps running + * until outside code calls the close method. + */ + public async followLogs(opts: LogOpts = {}) { + await this.createConnections(opts) + + this.intervalId = setInterval(async () => { + await this.createConnections(opts) + }, this.retryIntervalMs) + + return new Promise((resolve, _reject) => { + this.resolve = resolve + }) } - const proc = await ctx.tools["kubernetes.stern"].spawn({ - args: sternArgs, - log, - }) + /** + * Cleans up all active network requests and resolves the promise that was created + * when the logs following was started. + */ + public close() { + if (this.intervalId) { + clearInterval(this.intervalId) + this.intervalId = null + } + Object.values(this.connections).forEach((conn) => { + try { + conn.request.abort() + } catch {} + }) + this.resolve && this.resolve({}) + } - proc.stdout!.pipe(split()).on("data", (s: Buffer) => { - if (!s) { - return + private handleConnectionClose(connectionId: string, status: ConnectionStatus, reason: string) { + const conn = this.connections[connectionId] + const prevStatus = conn.status + this.connections[connectionId] = { + ...conn, + status, } - let timestamp: Date | undefined = undefined - let msg: string + + // There's no need to log the closed event that happens after an error event + if (!(prevStatus === "error" && status === "closed")) { + this.write({ + msg: ``, + containerName: conn.containerName, + level: LogLevel.debug, + }) + } + } + + private async createConnections({ tail, since }: LogOpts) { + let pods: KubernetesPod[] + try { - const parsed = JSON.parse(s.toString()) - let [timestampStr, line] = splitFirst(parsed.message, " ") - msg = formatLine(parsed.containerName, line) - timestamp = moment(timestampStr).toDate() + pods = await getAllPods(this.k8sApi, this.defaultNamespace, this.resources) } catch (err) { - /** - * If the message was supposed to be JSON but parsing failed, we stream the message unparsed. It may contain - * error information useful for debugging. - */ - msg = s.toString() + // Log the error and keep trying. + this.write({ + msg: ``, + level: LogLevel.debug, + }) + return } - void stream.write({ - serviceName: service.name, + const containers = pods.flatMap((pod) => { + const podContainers = pod.spec!.containers.map((c) => c.name).filter((n) => !n.match(/garden-/)) + return podContainers.map((containerName) => ({ + pod, + containerName, + })) + }) + + if (containers.length === 0) { + this.write({ + msg: ``, + level: LogLevel.debug, + }) + } + + await Bluebird.map(containers, async ({ pod, containerName }) => { + const connectionId = this.getConnectionId(pod, containerName) + // Cast type to make it explicit that it can be undefined + const conn = this.connections[connectionId] as LogConnection | undefined + + if (conn && conn.status === "connected") { + // Nothing to do + return + } else if (conn) { + // The connection has been registered but is not active + this.write({ + msg: ``, + level: LogLevel.silly, + }) + } + + const isRetry = !!conn?.status + const namespace = pod.metadata?.namespace || this.defaultNamespace + + const _self = this + // The ts-stream library that we use for service logs entries doesn't properly implement + // a writeable stream which the K8s API expects so we wrap it here. + const writableStream = new Writable({ + write(chunk, _encoding, next) { + const line = chunk?.toString()?.trimEnd() + + if (!line) { + return + } + + let timestamp: Date | undefined + // Fallback to printing the full line if we can't parse the timestamp + let msg = line + try { + const parts = splitFirst(line, " ") + timestamp = new Date(parts[0]) + msg = parts[1] + } catch {} + _self.write({ + msg, + containerName, + timestamp, + }) + next() + }, + }) + + const doneCallback = (error: any) => { + if (error) { + this.handleConnectionClose(connectionId, "error", error.message) + } + } + + let req: request.Request + try { + req = await this.getPodLogs({ + namespace, + containerName, + podName: pod.metadata.name, + doneCallback, + stream: writableStream, + tail, + timestamps: true, + // If we're retrying, presunmably because the connection was cut, we only want the latest logs. + // Otherwise we might end up fetching logs that have already been rendered. + since: isRetry ? "10s" : since, + }) + } catch (err) { + // Log the error and keep trying. + this.write({ + msg: ``, + level: LogLevel.debug, + containerName, + }) + return + } + this.connections[connectionId] = { + namespace, + pod, + request: req, + containerName, + status: "connected", + } + + req.on("response", async () => { + this.write({ + msg: ``, + containerName, + level: LogLevel.debug, + }) + }) + req.on("error", (error) => this.handleConnectionClose(connectionId, "error", error.message)) + req.on("close", () => this.handleConnectionClose(connectionId, "closed", "Request closed")) + req.on("socket", (socket) => { + // If the socket is idle for 30 seconds, we kill the connection and reconnect. + const socketTimeoutMs = 30000 + socket.setTimeout(socketTimeoutMs) + socket.setKeepAlive(true, socketTimeoutMs / 2) + socket.on("error", (err) => { + this.handleConnectionClose(connectionId, "error", `Socket error: ${err.message}`) + }) + socket.on("timeout", () => { + this.write({ + msg: ``, + containerName, + level: LogLevel.debug, + }) + // This will trigger a "close" event which we handle separately + socket.destroy() + }) + }) + }) + } + + private async getPodLogs({ + namespace, + podName, + containerName, + doneCallback, + stream, + tail, + since, + timestamps, + }: { + namespace: string + podName: string + containerName: string + stream: Writable + tail?: number + timestamps?: boolean + since?: string + doneCallback: (err: any) => void + }) { + const logger = this.k8sApi.getLogger() + const sinceSeconds = since ? parseDuration(since, "s") || undefined : undefined + + const opts = { + follow: true, + limitBytes: 5000, + pretty: false, + previous: false, + sinceSeconds, + tailLines: tail, + timestamps, + } + + return logger.log(namespace, podName, containerName, stream, doneCallback, opts) + } + + private getConnectionId(pod: KubernetesPod, containerName: string) { + return `${pod.metadata.name}-${containerName}` + } + + private write({ + msg, + containerName, + level = LogLevel.info, + timestamp = new Date(), + }: { + msg: string + containerName?: string + level?: LogLevel + timestamp?: Date + }) { + void this.stream.write({ + serviceName: this.service.name, timestamp, msg, + containerName, + level, }) - }) - - return proc + } } +// DEPRECATED: Remove stern in v0.13 export const sternSpec: PluginToolSpec = { name: "stern", description: "Utility CLI for streaming logs from Kubernetes.", diff --git a/core/src/plugins/kubernetes/status/pod.ts b/core/src/plugins/kubernetes/status/pod.ts index 5e63a98631..bda86c2296 100644 --- a/core/src/plugins/kubernetes/status/pod.ts +++ b/core/src/plugins/kubernetes/status/pod.ts @@ -78,6 +78,7 @@ export async function getPodLogs({ byteLimit, lineLimit, timestamps, + sinceSeconds, }: { api: KubeApi namespace: string @@ -86,6 +87,7 @@ export async function getPodLogs({ byteLimit?: number lineLimit?: number timestamps?: boolean + sinceSeconds?: number }) { let podContainers = pod.spec!.containers.map((c) => c.name).filter((n) => !n.match(/garden-/)) @@ -99,7 +101,6 @@ export async function getPodLogs({ const follow = false const insecureSkipTLSVerify = false const pretty = undefined - const sinceSeconds = undefined try { log = await api.core.readNamespacedPodLog( diff --git a/core/src/types/plugin/service/getServiceLogs.ts b/core/src/types/plugin/service/getServiceLogs.ts index c893e8c7ce..1af73c003a 100644 --- a/core/src/types/plugin/service/getServiceLogs.ts +++ b/core/src/types/plugin/service/getServiceLogs.ts @@ -12,12 +12,15 @@ import { dedent } from "../../../util/string" import { GardenModule } from "../../module" import { runtimeContextSchema } from "../../../runtime-context" import { joi } from "../../../config/common" +import { LogLevel } from "../../../logger/log-node" +import { string } from "@hapi/joi" export interface GetServiceLogsParams extends PluginServiceActionParamsBase { stream: Stream follow: boolean - tail: number + tail?: number + since?: string startTime?: Date } @@ -25,6 +28,8 @@ export interface ServiceLogEntry { serviceName: string timestamp?: Date msg: string + level?: LogLevel + containerName?: string } export const serviceLogEntrySchema = () => @@ -34,6 +39,13 @@ export const serviceLogEntrySchema = () => serviceName: joi.string().required().description("The name of the service the log entry originated from."), timestamp: joi.date().required().description("The time when the log entry was generated by the service."), msg: joi.string().required().description("The content of the log entry."), + containerName: string().description("The name of the container the service runs, if appicable."), + level: joi.string().description( + dedent` + The log level of the entry. The 'info' level should be reserved for logs from the service proper. + Other levels can be used to print warnings or debug information from the plugin. + ` + ), }) .description("A log entry returned by a getServiceLogs action handler.") @@ -41,7 +53,9 @@ export interface GetServiceLogsResult {} export const getServiceLogs = () => ({ description: dedent` - Retrieve a stream of logs for the specified service, optionally waiting listening for new logs. + Retrieve a stream of logs for the specified service, optionally waiting for new logs. + Note that when not listening for new logs, all logs are loaded into memory and sorted. The plugin handler + should therefore take care to set a sensible limit on the number of log lines retrieved. Called by the \`garden logs\` command. `, @@ -50,10 +64,13 @@ export const getServiceLogs = () => ({ runtimeContext: runtimeContextSchema(), stream: joi.object().description("A Stream object, to write the logs to."), follow: joi.boolean().description("Whether to keep listening for logs until aborted."), + since: joi.string().description(`Only return logs newer than a relative duration like 5s, 2m, or 3h.`), tail: joi .number() - .description("Number of lines to get from end of log. Defaults to -1, showing all log lines.") - .default(-1), + .optional() + .description( + "Number of lines to get from end of log. Defaults to showing all log lines (up to a certain limit) if not defined." + ), startTime: joi.date().optional().description("If set, only return logs that are as new or newer than this date."), }), diff --git a/core/src/util/util.ts b/core/src/util/util.ts index 54ec41fa03..510c39215c 100644 --- a/core/src/util/util.ts +++ b/core/src/util/util.ts @@ -54,6 +54,7 @@ export type Unpacked = T extends (infer U)[] : T extends Promise ? W : T +export type ExcludesFalsy = (x: T | false | null | undefined) => x is T const MAX_BUFFER_SIZE = 1024 * 1024 @@ -359,7 +360,7 @@ export async function dumpYamlMulti(yamlPath: string, objects: object[]) { /** * Splits the input string on the first occurrence of `delimiter`. */ -export function splitFirst(s: string, delimiter: string) { +export function splitFirst(s, delimiter) { const parts = s.split(delimiter) return [parts[0], parts.slice(1).join(delimiter)] } diff --git a/core/test/helpers.ts b/core/test/helpers.ts index 4ca2660911..efb584e88b 100644 --- a/core/test/helpers.ts +++ b/core/test/helpers.ts @@ -30,14 +30,14 @@ import { GARDEN_CORE_ROOT, LOCAL_CONFIG_FILENAME, DEFAULT_API_VERSION, gardenEnv import { isPromise, uuidv4 } from "../src/util/util" import { LogEntry } from "../src/logger/log-entry" import timekeeper = require("timekeeper") -import { ParameterValues, globalOptions, GlobalOptions } from "../src/cli/params" +import { ParameterValues, globalOptions, GlobalOptions, Parameters } from "../src/cli/params" import { RunModuleParams } from "../src/types/plugin/module/runModule" import { ConfigureModuleParams } from "../src/types/plugin/module/configure" import { RunServiceParams } from "../src/types/plugin/service/runService" import { RunResult } from "../src/types/plugin/base" import { ExternalSourceType, getRemoteSourceRelPath, hashRepoUrl } from "../src/util/ext-source-util" import { ActionRouter } from "../src/actions" -import { ProcessCommandResult } from "../src/commands/base" +import { CommandParams, ProcessCommandResult } from "../src/commands/base" import stripAnsi from "strip-ansi" import { RunTaskParams, RunTaskResult } from "../src/types/plugin/task/runTask" import { SuiteFunction, TestFunction } from "mocha" @@ -646,3 +646,23 @@ export function initTestLogger() { export async function cleanupAuthTokens() { await ClientAuthToken.createQueryBuilder().delete().execute() } + +export function makeCommandParams({ + garden, + args, + opts, +}: { + garden: Garden + args: T + opts: U +}): CommandParams { + const log = garden.log + return { + garden, + log, + headerLog: log, + footerLog: log, + args, + opts: withDefaultGlobalOpts(opts), + } +} diff --git a/core/test/integ/src/plugins/kubernetes/container/logs.ts b/core/test/integ/src/plugins/kubernetes/container/logs.ts index 8d7ce7a15b..846e84e003 100644 --- a/core/test/integ/src/plugins/kubernetes/container/logs.ts +++ b/core/test/integ/src/plugins/kubernetes/container/logs.ts @@ -10,32 +10,37 @@ import { expect } from "chai" import { Garden } from "../../../../../../src/garden" import { getDataDir, makeTestGarden } from "../../../../../helpers" import { ConfigGraph } from "../../../../../../src/config-graph" -import { Provider } from "../../../../../../src/config/provider" import { DeployTask } from "../../../../../../src/tasks/deploy" import { getServiceLogs } from "../../../../../../src/plugins/kubernetes/container/logs" import { Stream } from "ts-stream" import { ServiceLogEntry } from "../../../../../../src/types/plugin/service/getServiceLogs" -import { PluginContext } from "../../../../../../src/plugin-context" +import { KubernetesPluginContext, KubernetesProvider } from "../../../../../../src/plugins/kubernetes/config" +import { K8sLogFollower } from "../../../../../../src/plugins/kubernetes/logs" +import { KubeApi } from "../../../../../../src/plugins/kubernetes/api" +import { emptyRuntimeContext } from "../../../../../../src/runtime-context" +import { createWorkloadManifest } from "../../../../../../src/plugins/kubernetes/container/deployment" +import { sleep } from "../../../../../../src/util/util" +import { DeleteServiceTask } from "../../../../../../src/tasks/delete-service" describe("kubernetes", () => { - describe("getServiceLogs", () => { - let garden: Garden - let graph: ConfigGraph - let provider: Provider - let ctx: PluginContext - - before(async () => { - const root = getDataDir("test-projects", "container") - garden = await makeTestGarden(root) - graph = await garden.getConfigGraph(garden.log) - provider = await garden.resolveProvider(garden.log, "local-kubernetes") - ctx = await garden.getPluginContext(provider) - }) + let garden: Garden + let graph: ConfigGraph + let provider: KubernetesProvider + let ctx: KubernetesPluginContext - after(async () => { - await garden.close() - }) + before(async () => { + const root = getDataDir("test-projects", "container") + garden = await makeTestGarden(root) + graph = await garden.getConfigGraph(garden.log) + provider = (await garden.resolveProvider(garden.log, "local-kubernetes")) as KubernetesProvider + ctx = (await garden.getPluginContext(provider)) as KubernetesPluginContext + }) + after(async () => { + await garden.close() + }) + + describe("getServiceLogs", () => { it("should write service logs to stream", async () => { const module = graph.getModule("simple-service") const service = graph.getService("simple-service") @@ -67,10 +72,183 @@ describe("kubernetes", () => { log: garden.log, stream, follow: false, - tail: -1, }) expect(entries[0].msg).to.include("Server running...") }) + describe("K8sLogsFollower", () => { + let logsFollower: K8sLogFollower + + afterEach(() => { + logsFollower.close() + }) + + it("should write service logs to stream and listen for more", async () => { + const service = graph.getService("simple-service") + const log = garden.log + const namespace = provider.config.namespace!.name! + const api = await KubeApi.factory(log, ctx, provider) + + const entries: ServiceLogEntry[] = [] + + const deployTask = new DeployTask({ + force: true, + forceBuild: true, + garden, + graph, + log: garden.log, + service, + devModeServiceNames: [], + hotReloadServiceNames: [], + }) + + await garden.processTasks([deployTask], { throwOnError: true }) + const stream = new Stream() + + void stream.forEach((entry) => { + entries.push(entry) + }) + + const resources = [ + await createWorkloadManifest({ + api, + provider, + service, + // No need for the proper context here + runtimeContext: emptyRuntimeContext, + namespace, + enableDevMode: false, + enableHotReload: false, + production: ctx.production, + log, + blueGreen: provider.config.deploymentStrategy === "blue-green", + }), + ] + logsFollower = new K8sLogFollower({ + defaultNamespace: provider.config.namespace!.name!, + service, + stream, + resources, + k8sApi: api, + }) + + setTimeout(() => { + logsFollower.close() + }, 2500) + await logsFollower.followLogs() + + const debugEntry = entries.find((e) => e.msg.includes("Connected to container 'simple-service'")) + const serviceLog = entries.find((e) => e.msg.includes("Server running...")) + + expect(debugEntry).to.exist + expect(debugEntry!.serviceName).to.eql("simple-service") + expect(debugEntry!.timestamp).to.be.an.instanceOf(Date) + expect(debugEntry!.level).to.eql(4) + + expect(serviceLog).to.exist + expect(serviceLog!.serviceName).to.eql("simple-service") + expect(serviceLog!.timestamp).to.be.an.instanceOf(Date) + expect(serviceLog!.level).to.eql(2) + }) + it("should automatically connect if a service that was missing is deployed", async () => { + const service = graph.getService("simple-service") + const log = garden.log + const namespace = provider.config.namespace!.name! + const api = await KubeApi.factory(log, ctx, provider) + + const entries: ServiceLogEntry[] = [] + + const deployTask = new DeployTask({ + force: true, + forceBuild: true, + garden, + graph, + log: garden.log, + service, + devModeServiceNames: [], + hotReloadServiceNames: [], + }) + const deleteTask = new DeleteServiceTask({ + garden, + graph, + log: garden.log, + service, + }) + + const stream = new Stream() + + void stream.forEach((entry) => { + entries.push(entry) + }) + + const resources = [ + await createWorkloadManifest({ + api, + provider, + service, + // No need for the proper context here + runtimeContext: emptyRuntimeContext, + namespace, + enableDevMode: false, + enableHotReload: false, + production: ctx.production, + log, + blueGreen: provider.config.deploymentStrategy === "blue-green", + }), + ] + const retryIntervalMs = 1000 + logsFollower = new K8sLogFollower({ + defaultNamespace: provider.config.namespace!.name!, + service, + stream, + resources, + k8sApi: api, + retryIntervalMs, + }) + + // Start by deleting the service in case it already exists + await garden.processTasks([deleteTask], { throwOnError: true }) + + // Start following logs even when no services is deployed + // (we don't wait for the Promise since it won't resolve unless we close the connection) + // tslint:disable-next-line: no-floating-promises + logsFollower.followLogs() + await sleep(1500) + + // Deploy the service + await garden.processTasks([deployTask], { throwOnError: true }) + await sleep(1500) + + logsFollower.close() + + const missingContainerDebugEntry = entries.find((e) => + e.msg.includes(``) + ) + const connectedDebugEntry = entries.find((e) => + e.msg.includes(" e.msg.includes("Server running...")) + + // First we expect to see a "missing container" entry because the service hasn't been deployed + expect(missingContainerDebugEntry).to.exist + expect(missingContainerDebugEntry!.serviceName).to.eql("simple-service") + expect(missingContainerDebugEntry!.timestamp).to.be.an.instanceOf(Date) + expect(missingContainerDebugEntry!.level).to.eql(4) + + // Then we expect to see a "container connected" entry when the service has been deployed + expect(connectedDebugEntry).to.exist + expect(connectedDebugEntry!.serviceName).to.eql("simple-service") + expect(connectedDebugEntry!.timestamp).to.be.an.instanceOf(Date) + expect(connectedDebugEntry!.timestamp!.getTime() > missingContainerDebugEntry!.timestamp!.getTime()).to.be.true + expect(connectedDebugEntry!.level).to.eql(4) + + // Finally we expect to see the service log + expect(serviceLog).to.exist + expect(serviceLog!.serviceName).to.eql("simple-service") + expect(serviceLog!.timestamp).to.be.an.instanceOf(Date) + expect(serviceLog!.timestamp!.getTime() > connectedDebugEntry!.timestamp!.getTime()).to.be.true + expect(serviceLog!.level).to.eql(2) + }) + }) }) }) diff --git a/core/test/unit/src/commands/login.ts b/core/test/unit/src/commands/login.ts index 3cb2c1018b..8bfe175e0d 100644 --- a/core/test/unit/src/commands/login.ts +++ b/core/test/unit/src/commands/login.ts @@ -8,13 +8,12 @@ import { expect } from "chai" import td from "testdouble" -import { withDefaultGlobalOpts, expectError, getDataDir, cleanupAuthTokens, getLogMessages } from "../../../helpers" +import { expectError, getDataDir, cleanupAuthTokens, getLogMessages, makeCommandParams } from "../../../helpers" import { AuthRedirectServer } from "../../../../src/enterprise/auth" import { LoginCommand } from "../../../../src/commands/login" import stripAnsi from "strip-ansi" import { makeDummyGarden } from "../../../../src/cli/cli" -import { Garden } from "../../../../src" import { ClientAuthToken } from "../../../../src/db/entities/client-auth-token" import { dedent, randomString } from "../../../../src/util/string" import { EnterpriseApi } from "../../../../src/enterprise/api" @@ -22,18 +21,6 @@ import { LogLevel } from "../../../../src/logger/log-node" import { gardenEnv } from "../../../../src/constants" import { EnterpriseApiError } from "../../../../src/exceptions" -function makeCommandParams(garden: Garden) { - const log = garden.log - return { - garden, - log, - headerLog: log, - footerLog: log, - args: {}, - opts: withDefaultGlobalOpts({}), - } -} - // In the tests below we stub out the auth redirect server but still emit the // token received event. describe("LoginCommand", () => { @@ -64,7 +51,7 @@ describe("LoginCommand", () => { garden.events.emit("receivedToken", testToken) }, 500) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const savedToken = await ClientAuthToken.findOne() expect(savedToken).to.exist @@ -90,7 +77,7 @@ describe("LoginCommand", () => { td.replace(EnterpriseApi.prototype, "checkClientAuthToken", async () => true) td.replace(EnterpriseApi.prototype, "startInterval", async () => {}) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const savedToken = await ClientAuthToken.findOne() expect(savedToken).to.exist @@ -119,7 +106,7 @@ describe("LoginCommand", () => { garden.events.emit("receivedToken", testToken) }, 500) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const savedToken = await ClientAuthToken.findOne() expect(savedToken).to.exist expect(savedToken!.token).to.eql(testToken.token) @@ -132,7 +119,7 @@ describe("LoginCommand", () => { }) const command = new LoginCommand() await expectError( - () => command.action(makeCommandParams(garden)), + () => command.action(makeCommandParams({ garden, args: {}, opts: {} })), (err) => expect(stripAnsi(err.message)).to.match(/Project config is missing an enterprise domain and\/or a project ID./) ) @@ -164,7 +151,7 @@ describe("LoginCommand", () => { expect(savedToken!.refreshToken).to.eql(testToken.refreshToken) await expectError( - () => command.action(makeCommandParams(garden)), + () => command.action(makeCommandParams({ garden, args: {}, opts: {} })), (err) => expect(stripAnsi(err.message)).to.match(/bummer/) ) }) @@ -195,7 +182,7 @@ describe("LoginCommand", () => { expect(savedToken!.refreshToken).to.eql(testToken.refreshToken) await expectError( - () => command.action(makeCommandParams(garden)), + () => command.action(makeCommandParams({ garden, args: {}, opts: {} })), (err) => expect(stripAnsi(err.message)).to.match(/bummer/) ) @@ -222,7 +209,7 @@ describe("LoginCommand", () => { td.replace(EnterpriseApi.prototype, "checkClientAuthToken", async () => true) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const logOutput = getLogMessages(garden.log, (entry) => entry.level === LogLevel.info).join("\n") @@ -239,7 +226,7 @@ describe("LoginCommand", () => { td.replace(EnterpriseApi.prototype, "checkClientAuthToken", async () => false) await expectError( - () => command.action(makeCommandParams(garden)), + () => command.action(makeCommandParams({ garden, args: {}, opts: {} })), (err) => expect(stripAnsi(err.message)).to.match( /The provided access token is expired or has been revoked, please create a new one from the Garden Enterprise UI./ diff --git a/core/test/unit/src/commands/logout.ts b/core/test/unit/src/commands/logout.ts index c34048cb4d..8a8ba0d68f 100644 --- a/core/test/unit/src/commands/logout.ts +++ b/core/test/unit/src/commands/logout.ts @@ -8,27 +8,14 @@ import { expect } from "chai" import td from "testdouble" -import { withDefaultGlobalOpts, getDataDir, cleanupAuthTokens, getLogMessages } from "../../../helpers" +import { getDataDir, cleanupAuthTokens, getLogMessages, makeCommandParams } from "../../../helpers" import { makeDummyGarden } from "../../../../src/cli/cli" -import { Garden } from "../../../../src" import { ClientAuthToken } from "../../../../src/db/entities/client-auth-token" import { randomString } from "../../../../src/util/string" import { EnterpriseApi } from "../../../../src/enterprise/api" import { LogLevel } from "../../../../src/logger/log-node" import { LogOutCommand } from "../../../../src/commands/logout" -function makeCommandParams(garden: Garden) { - const log = garden.log - return { - garden, - log, - headerLog: log, - footerLog: log, - args: {}, - opts: withDefaultGlobalOpts({}), - } -} - describe("LogoutCommand", () => { beforeEach(async () => { await cleanupAuthTokens() @@ -63,7 +50,7 @@ describe("LogoutCommand", () => { expect(savedToken!.token).to.eql(testToken.token) expect(savedToken!.refreshToken).to.eql(testToken.refreshToken) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const tokenAfterLogout = await ClientAuthToken.findOne() const logOutput = getLogMessages(garden.log, (entry) => entry.level === LogLevel.info).join("\n") @@ -79,7 +66,7 @@ describe("LogoutCommand", () => { commandInfo: { name: "foo", args: {}, opts: {} }, }) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const logOutput = getLogMessages(garden.log, (entry) => entry.level === LogLevel.info).join("\n") expect(logOutput).to.include("You're already logged out from Garden Enterprise.") @@ -111,7 +98,7 @@ describe("LogoutCommand", () => { expect(savedToken!.token).to.eql(testToken.token) expect(savedToken!.refreshToken).to.eql(testToken.refreshToken) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const tokenAfterLogout = await ClientAuthToken.findOne() const logOutput = getLogMessages(garden.log, (entry) => entry.level === LogLevel.info).join("\n") @@ -146,7 +133,7 @@ describe("LogoutCommand", () => { expect(savedToken!.token).to.eql(testToken.token) expect(savedToken!.refreshToken).to.eql(testToken.refreshToken) - await command.action(makeCommandParams(garden)) + await command.action(makeCommandParams({ garden, args: {}, opts: {} })) const tokenAfterLogout = await ClientAuthToken.findOne() const logOutput = getLogMessages(garden.log, (entry) => entry.level === LogLevel.info).join("\n") diff --git a/core/test/unit/src/commands/logs.ts b/core/test/unit/src/commands/logs.ts new file mode 100644 index 0000000000..ef420d7343 --- /dev/null +++ b/core/test/unit/src/commands/logs.ts @@ -0,0 +1,426 @@ +/* + * Copyright (C) 2018-2021 Garden Technologies, Inc. + * + * This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. + */ + +import tmp from "tmp-promise" +import { expect } from "chai" +import { Garden } from "../../../../src" +import { colors, LogsCommand } from "../../../../src/commands/logs" +import { joi } from "../../../../src/config/common" +import { ProjectConfig, defaultNamespace } from "../../../../src/config/project" +import { createGardenPlugin, GardenPlugin } from "../../../../src/types/plugin/plugin" +import { GetServiceLogsParams } from "../../../../src/types/plugin/service/getServiceLogs" +import { TestGarden } from "../../../../src/util/testing" +import { projectRootA, withDefaultGlobalOpts } from "../../../helpers" +import execa from "execa" +import { DEFAULT_API_VERSION } from "../../../../src/constants" +import { formatForTerminal } from "../../../../src/logger/renderers" +import chalk from "chalk" + +function makeCommandParams({ + garden, + args = { services: undefined }, + opts = {}, +}: { + garden: Garden + args?: any + opts?: any +}) { + const log = garden.log + return { + garden, + log, + headerLog: log, + footerLog: log, + args, + opts: withDefaultGlobalOpts({ + ...opts, + }), + } +} + +async function makeGarden(tmpDir: tmp.DirectoryResult, plugin: GardenPlugin) { + const config: ProjectConfig = { + apiVersion: DEFAULT_API_VERSION, + kind: "Project", + name: "test", + path: tmpDir.path, + defaultEnvironment: "default", + dotIgnoreFiles: [], + environments: [{ name: "default", defaultNamespace, variables: {} }], + providers: [{ name: "test" }], + variables: {}, + } + + const garden = await TestGarden.factory(projectRootA, { config, plugins: [plugin] }) + garden.setModuleConfigs([ + { + apiVersion: DEFAULT_API_VERSION, + name: "test", + type: "test", + allowPublish: false, + disabled: false, + build: { dependencies: [] }, + path: tmpDir.path, + serviceConfigs: [ + { + name: "test-service-a", + dependencies: [], + disabled: false, + hotReloadable: false, + spec: {}, + }, + ], + taskConfigs: [], + testConfigs: [], + spec: { bla: "fla" }, + }, + ]) + return garden +} + +// Returns all entries that match the logMsg as string, sorted by service name. +function getLogOutput(garden: TestGarden, msg: string) { + const entries = garden.log.getChildEntries().filter((e) => e.getLatestMessage().msg?.includes(msg))! + return ( + entries + // .sort((a, b) => (stripAnsi(a.getLatestMessage().msg!) > stripAnsi(b.getLatestMessage().msg!) ? 1 : -1)) + .map((e) => formatForTerminal(e, "basic").trim()) + ) + // .join("\n") +} + +describe("LogsCommand", () => { + let tmpDir: tmp.DirectoryResult + const timestamp = new Date() + const originalColor = chalk.bgRedBright + const logMsg = "Yes, this is log" + const logMsgWithColor = originalColor(logMsg) + + const color = chalk[colors[0]] + const defaultGetServiceLogsHandler = async ({ stream }: GetServiceLogsParams) => { + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }) + return {} + } + + const makeTestPlugin = (getServiceLogsHandler = defaultGetServiceLogsHandler) => { + return createGardenPlugin({ + name: "test", + createModuleTypes: [ + { + name: "test", + docs: "test", + schema: joi.object(), + handlers: { + getServiceLogs: getServiceLogsHandler, + }, + }, + ], + }) + } + + before(async () => { + tmpDir = await tmp.dir({ unsafeCleanup: true }) + + await execa("git", ["init"], { cwd: tmpDir.path }) + }) + + after(async () => { + await tmpDir.cleanup() + }) + + context("follow=false", () => { + it("should return service logs", async () => { + const garden = await makeGarden(tmpDir, makeTestPlugin()) + const command = new LogsCommand() + const res = await command.action(makeCommandParams({ garden })) + expect(res).to.eql({ + result: [ + { + containerName: "my-container", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }, + ], + }) + }) + it("should sort entries by timestamp", async () => { + const getServiceLogsHandler = async ({ stream }: GetServiceLogsParams) => { + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: "3", + timestamp: new Date("2021-05-13T20:03:00.000Z"), + }) + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: "4", + timestamp: new Date("2021-05-13T20:04:00.000Z"), + }) + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: "2", + timestamp: new Date("2021-05-13T20:02:00.000Z"), + }) + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: "1", + timestamp: new Date("2021-05-13T20:01:00.000Z"), + }) + return {} + } + const garden = await makeGarden(tmpDir, makeTestPlugin(getServiceLogsHandler)) + + const command = new LogsCommand() + const res = await command.action(makeCommandParams({ garden })) + + expect(res).to.eql({ + result: [ + { + containerName: "my-container", + serviceName: "test-service-a", + msg: "1", + timestamp: new Date("2021-05-13T20:01:00.000Z"), + }, + { + containerName: "my-container", + serviceName: "test-service-a", + msg: "2", + timestamp: new Date("2021-05-13T20:02:00.000Z"), + }, + { + containerName: "my-container", + serviceName: "test-service-a", + msg: "3", + timestamp: new Date("2021-05-13T20:03:00.000Z"), + }, + { + containerName: "my-container", + serviceName: "test-service-a", + timestamp: new Date("2021-05-13T20:04:00.000Z"), + msg: "4", + }, + ], + }) + }) + it("should skip empty entries", async () => { + const getServiceLogsHandler = async ({ stream }: GetServiceLogsParams) => { + // Empty message and invalid date + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: "", + timestamp: new Date(""), + }) + // Empty message and empty date + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: "", + timestamp: undefined, + }) + return {} + } + const garden = await makeGarden(tmpDir, makeTestPlugin(getServiceLogsHandler)) + + const command = new LogsCommand() + const res = await command.action(makeCommandParams({ garden })) + + expect(res).to.eql({ result: [] }) + }) + it("should render the service name by default", async () => { + const garden = await makeGarden(tmpDir, makeTestPlugin()) + const command = new LogsCommand() + await command.action(makeCommandParams({ garden })) + + const out = getLogOutput(garden, logMsg) + + expect(out[0]).to.eql(`${color.bold("test-service-a")} → ${color("Yes, this is log")}`) + }) + it("should optionally skip rendering the service name", async () => { + const garden = await makeGarden(tmpDir, makeTestPlugin()) + const command = new LogsCommand() + await command.action(makeCommandParams({ garden, opts: { "hide-service": true } })) + + const out = getLogOutput(garden, logMsg) + + expect(out[0]).to.eql(color("Yes, this is log")) + }) + it("should optionally show the container name", async () => { + const garden = await makeGarden(tmpDir, makeTestPlugin()) + const command = new LogsCommand() + await command.action(makeCommandParams({ garden, opts: { "show-container": true } })) + + const out = getLogOutput(garden, logMsg) + + expect(out[0]).to.eql( + `${color.bold("test-service-a")} → ${color.bold("my-container")} → ${color("Yes, this is log")}` + ) + }) + it("should align content wrt to container names when visible", async () => { + const getServiceLogsHandler = async ({ stream }: GetServiceLogsParams) => { + void stream.write({ + containerName: "short", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }) + void stream.write({ + containerName: "very-long", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }) + void stream.write({ + containerName: "short", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }) + void stream.write({ + containerName: "very-very-long", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }) + void stream.write({ + containerName: "short", + serviceName: "test-service-a", + msg: logMsgWithColor, + timestamp, + }) + return {} + } + const garden = await makeGarden(tmpDir, makeTestPlugin(getServiceLogsHandler)) + + const command = new LogsCommand() + await command.action(makeCommandParams({ garden, opts: { "show-container": true } })) + + const out = getLogOutput(garden, logMsg) + + expect(out[0]).to.eql(`${color.bold("test-service-a")} → ${color.bold("short")} → ${color("Yes, this is log")}`) + expect(out[1]).to.eql( + `${color.bold("test-service-a")} → ${color.bold("very-long")} → ${color("Yes, this is log")}` + ) + expect(out[2]).to.eql( + `${color.bold("test-service-a")} → ${color.bold("short ")} → ${color("Yes, this is log")}` + ) + expect(out[3]).to.eql( + `${color.bold("test-service-a")} → ${color.bold("very-very-long")} → ${color("Yes, this is log")}` + ) + expect(out[4]).to.eql( + `${color.bold("test-service-a")} → ${color.bold("short ")} → ${color("Yes, this is log")}` + ) + }) + it("should optionally show timestamps", async () => { + const garden = await makeGarden(tmpDir, makeTestPlugin()) + const command = new LogsCommand() + await command.action(makeCommandParams({ garden, opts: { timestamps: true } })) + + const out = getLogOutput(garden, logMsg) + + expect(out[0]).to.eql( + `${color.bold("test-service-a")} → ${chalk.gray(timestamp.toISOString())} → ${color("Yes, this is log")}` + ) + }) + it("should optionally show the original log color", async () => { + const garden = await makeGarden(tmpDir, makeTestPlugin()) + const command = new LogsCommand() + await command.action(makeCommandParams({ garden, opts: { "original-color": true } })) + + const out = getLogOutput(garden, logMsg) + + expect(out[0]).to.eql(`${color.bold("test-service-a")} → ${originalColor("Yes, this is log")}`) + }) + context("multiple services", () => { + let gardenMultiService: TestGarden + const getServiceLogsHandler = async ({ stream, service }: GetServiceLogsParams) => { + if (service.name === "test-service-a") { + void stream.write({ + containerName: "my-container", + serviceName: "test-service-a", + msg: logMsg, + timestamp, + }) + } else { + void stream.write({ + containerName: "my-container", + serviceName: "test-service-b", + msg: logMsg, + timestamp, + }) + } + return {} + } + beforeEach(async () => { + gardenMultiService = await makeGarden(tmpDir, makeTestPlugin(getServiceLogsHandler)) + gardenMultiService.setModuleConfigs([ + { + apiVersion: DEFAULT_API_VERSION, + name: "test", + type: "test", + allowPublish: false, + disabled: false, + build: { dependencies: [] }, + path: tmpDir.path, + serviceConfigs: [ + { + name: "test-service-a", + dependencies: [], + disabled: false, + hotReloadable: false, + spec: {}, + }, + { + name: "test-service-b", + dependencies: [], + disabled: false, + hotReloadable: false, + spec: {}, + }, + ], + taskConfigs: [], + testConfigs: [], + spec: { bla: "fla" }, + }, + ]) + }) + it("should give each service a unique color", async () => { + // Given a project with multiple services... + const command = new LogsCommand() + // ...when we get the logs for all of them... + await command.action(makeCommandParams({ garden: gardenMultiService })) + + const out = getLogOutput(gardenMultiService, logMsg) + const color2 = chalk[colors[1]] + + // ...then they each get assigned a unique color... + expect(out[0]).to.eql(`${color.bold("test-service-a")} → ${color("Yes, this is log")}`) + expect(out[1]).to.eql(`${color2.bold("test-service-b")} → ${color2("Yes, this is log")}`) + }) + it("should assign the same color to each service, regardless of which service logs are streamed", async () => { + const command = new LogsCommand() + await command.action(makeCommandParams({ garden: gardenMultiService, args: { services: ["test-service-b"] } })) + + const out = getLogOutput(gardenMultiService, logMsg) + const color2 = chalk[colors[1]] + + // Assert that the service gets the "second" color, even though its the only one we're fetching logs for. + expect(out[0]).to.eql(`${color2.bold("test-service-b")} → ${color2("Yes, this is log")}`) + }) + }) + }) +}) diff --git a/docs/reference/commands.md b/docs/reference/commands.md index 3d780c3724..8b144ad137 100644 --- a/docs/reference/commands.md +++ b/docs/reference/commands.md @@ -2690,13 +2690,17 @@ sources: **Retrieves the most recent logs for the specified service(s).** -Outputs logs for all or specified services, and optionally waits for news logs to come in. +Outputs logs for all or specified services, and optionally waits for news logs to come in. Defaults +to getting logs from the last minute when in `--follow` mode. You can change this with the `--since` option. Examples: - garden logs # prints latest logs from all services - garden logs my-service # prints latest logs for my-service - garden logs -t # keeps running and streams all incoming logs to the console + garden logs # interleaves color-coded logs from all services (up to a certain limit) + garden logs --since 2d # interleaves color-coded logs from all services from the last 2 days + garden logs --tail 100 # interleaves the last 100 log lines from all services + garden logs service-a,service-b # interleaves color-coded logs for service-a and service-b + garden logs --follow # keeps running and streams all incoming logs to the console + garden logs --original-color # interleaves logs from all services and prints the original output color | Supported in workflows | | | ---------------------- |---| @@ -2717,7 +2721,14 @@ Examples: | Argument | Alias | Type | Description | | -------- | ----- | ---- | ----------- | | `--follow` | `-f` | boolean | Continuously stream new logs from the service(s). - | `--tail` | `-t` | number | Number of lines to show for each service. Defaults to -1, showing all log lines. + | `--tail` | `-t` | number | Number of lines to show for each service. Defaults to showing all log lines (up to a certain limit). Takes precedence over +the `--since` flag if both are set. Note that we don't recommend using a large value here when in follow mode. + | `--show-container` | | boolean | Show the name of the container with log output. May not apply to all providers + | `--timestamps` | | boolean | Show timestamps with log output. + | `--since` | | moment | Only show logs newer than a relative duration like 5s, 2m, or 3h. Defaults to `"1m"` when `--follow` is true +unless `--tail` is set. Note that we don't recommend using a large value here when in follow mode. + | `--original-color` | | boolean | Show the original color output of the logs instead of color coding them. + | `--hide-service` | | boolean | Hide the service name and render the logs directly. ### garden migrate diff --git a/examples/demo-project/garden.yml b/examples/demo-project/garden.yml index 31eb6174da..1ac193a068 100644 --- a/examples/demo-project/garden.yml +++ b/examples/demo-project/garden.yml @@ -13,4 +13,4 @@ providers: context: gke_garden-dev-200012_europe-west1-b_garden-dev-1 namespace: demo-project-testing-${local.env.USER || local.username} defaultHostname: ${local.env.USER || local.username}-demo-project.dev-1.sys.garden - buildMode: kaniko \ No newline at end of file + buildMode: kaniko diff --git a/yarn.lock b/yarn.lock index d0b77c52f8..0ce22f5aba 100644 --- a/yarn.lock +++ b/yarn.lock @@ -13538,6 +13538,11 @@ parse-asn1@^5.0.0, parse-asn1@^5.1.5: pbkdf2 "^3.0.3" safe-buffer "^5.1.1" +parse-duration@^1.0.0: + version "1.0.0" + resolved "https://registry.yarnpkg.com/parse-duration/-/parse-duration-1.0.0.tgz#8605651745f61088f6fb14045c887526c291858c" + integrity sha512-X4kUkCTHU1N/kEbwK9FpUJ0UZQa90VzeczfS704frR30gljxDG0pSziws06XlK+CGRSo/1wtG1mFIdBFQTMQNw== + parse-entities@^2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/parse-entities/-/parse-entities-2.0.0.tgz#53c6eb5b9314a1f4ec99fa0fdf7ce01ecda0cbe8" @@ -17784,10 +17789,10 @@ ts-pnp@^1.1.6: resolved "https://registry.yarnpkg.com/ts-pnp/-/ts-pnp-1.2.0.tgz#a500ad084b0798f1c3071af391e65912c86bca92" integrity sha512-csd+vJOb/gkzvcCHgTGSChYpy5f1/XKNsmvBGO4JXS+z1v2HobugDz4s1IeFXM3wZB44uczs+eazB5Q/ccdhQw== -ts-stream@^2.0.1: - version "2.0.2" - resolved "https://registry.yarnpkg.com/ts-stream/-/ts-stream-2.0.2.tgz#5ce2ecd97b73b50cee748eef3b5bebfe0dbdc740" - integrity sha512-uzlo7pwDcbhlImCikr895lYkm5fpbEvlANM62Z0IoNFdb03futr3bo3BaO4RdONqL1J7gieDP/LyiCycnD+ljg== +ts-stream@^3.0.0: + version "3.0.0" + resolved "https://registry.yarnpkg.com/ts-stream/-/ts-stream-3.0.0.tgz#7f3c1749a8345695cb43ca10cf64c96908f909dd" + integrity sha512-inSYkFNWYRDKu+fEriDeTV8KP6BLx/CujUb047sIuMH1YUZcUdjYpwiGsXVyWIEREOFb02e0z6b/cK8lG1i4cw== dependencies: "@types/node" "*"