From 138e3dfc0216544b8f329c9d465b663a95b1172e Mon Sep 17 00:00:00 2001 From: opeyemi Date: Mon, 6 Jan 2020 13:25:05 +0100 Subject: [PATCH] fix(log): updated to stern from kubectl (#1437) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(log): updated to stern from kubectl * chore(stern): log test * fix(stern): updated to use stern for tail * improvement(logger): enable dynamic section widths * improvement(test): added test to handle zero been falsey * chore(test): added tests to k8s utilities * style(stern): use more idiomatic boolean check * style(stern): added more idomatic way of doing things * style(stern): linter issues * chore(stern): change test regex Co-authored-by: Eyþór Magnússon --- garden-service/src/commands/logs.ts | 6 +- garden-service/src/logger/log-entry.ts | 4 + garden-service/src/logger/renderers.ts | 20 ++- garden-service/src/plugins/kubernetes/logs.ts | 116 +++++++++++++++--- garden-service/src/plugins/kubernetes/util.ts | 20 +++ garden-service/test/e2e/src/pre-release.ts | 4 +- .../test/unit/src/logger/log-entry.ts | 49 ++++++++ .../test/unit/src/logger/renderers.ts | 65 +++++++--- .../test/unit/src/plugins/kubernetes/util.ts | 40 ++++++ 9 files changed, 283 insertions(+), 41 deletions(-) diff --git a/garden-service/src/commands/logs.ts b/garden-service/src/commands/logs.ts index dab1606a9b..adb0b1b5aa 100644 --- a/garden-service/src/commands/logs.ts +++ b/garden-service/src/commands/logs.ts @@ -8,6 +8,7 @@ import { Command, CommandResult, CommandParams, StringsParameter, IntegerParameter, BooleanParameter } from "./base" import chalk from "chalk" +import { maxBy } from "lodash" import { ServiceLogEntry } from "../types/plugin/service/getServiceLogs" import Bluebird = require("bluebird") import { Service } from "../types/service" @@ -65,6 +66,8 @@ export class LogsCommand extends Command { const { follow, tail } = opts const graph = await garden.getConfigGraph(log) const services = await graph.getServices(args.services) + const serviceNames = services.map((s) => s.name).filter(Boolean) + const maxServiceName = (maxBy(serviceNames, (serviceName) => serviceName.length) || "").length const result: ServiceLogEntry[] = [] const stream = new Stream() @@ -82,7 +85,8 @@ export class LogsCommand extends Command { log.info({ section: entry.serviceName, - msg: `${timestamp} → ${chalk.white(entry.msg)}`, + msg: `${chalk.yellowBright(timestamp)} → ${chalk.white(entry.msg)}`, + maxSectionWidth: maxServiceName, }) if (!follow) { diff --git a/garden-service/src/logger/log-entry.ts b/garden-service/src/logger/log-entry.ts index bbb26e3dfe..86e566731f 100644 --- a/garden-service/src/logger/log-entry.ts +++ b/garden-service/src/logger/log-entry.ts @@ -41,6 +41,7 @@ interface MessageBase { symbol?: LogSymbol append?: boolean data?: any + maxSectionWidth?: number } export interface MessageState extends MessageBase { @@ -106,6 +107,7 @@ export class LogEntry extends LogNode { symbol: params.symbol, status: params.level === LogLevel.error ? "error" : params.status, data: params.data, + maxSectionWidth: params.maxSectionWidth, }) } } @@ -131,6 +133,8 @@ export class LogEntry extends LogNode { // Next state does not inherit the append field append: updateParams.append, timestamp: Date.now(), + maxSectionWidth: + updateParams.maxSectionWidth !== undefined ? updateParams.maxSectionWidth : messageState.maxSectionWidth, } // Hack to preserve section alignment if spinner disappears diff --git a/garden-service/src/logger/renderers.ts b/garden-service/src/logger/renderers.ts index 5de8310cc7..cbb6ca42b4 100644 --- a/garden-service/src/logger/renderers.ts +++ b/garden-service/src/logger/renderers.ts @@ -26,13 +26,21 @@ type RenderFn = (entry: LogEntry) => string /*** STYLE HELPERS ***/ -const SECTION_PREFIX_WIDTH = 25 +export const MAX_SECTION_WIDTH = 25 const cliPadEnd = (s: string, width: number): string => { const diff = width - stringWidth(s) return diff <= 0 ? s : s + repeat(" ", diff) } -const truncateSection = (s: string) => cliTruncate(s, SECTION_PREFIX_WIDTH) -const sectionStyle = (s: string) => chalk.cyan.italic(cliPadEnd(truncateSection(s), SECTION_PREFIX_WIDTH)) + +function styleSection(section: string, width: number = MAX_SECTION_WIDTH) { + const minWidth = Math.min(width, MAX_SECTION_WIDTH) + const formattedSection = [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)) export const errorStyle = (s: string) => (hasAnsi(s) ? s : chalk.red(s)) @@ -153,11 +161,11 @@ export function renderData(entry: LogEntry): string { } export function renderSection(entry: LogEntry): string { - const { msg, section } = entry.getMessageState() + const { msg, section, maxSectionWidth } = entry.getMessageState() if (section && msg) { - return `${sectionStyle(section)} → ` + return `${styleSection(section, maxSectionWidth)} → ` } else if (section) { - return sectionStyle(section) + return styleSection(section, maxSectionWidth) } return "" } diff --git a/garden-service/src/plugins/kubernetes/logs.ts b/garden-service/src/plugins/kubernetes/logs.ts index da35404a0d..3445de26ba 100644 --- a/garden-service/src/plugins/kubernetes/logs.ts +++ b/garden-service/src/plugins/kubernetes/logs.ts @@ -11,16 +11,18 @@ import { omit } from "lodash" import moment = require("moment") import { GetServiceLogsResult, ServiceLogEntry } from "../../types/plugin/service/getServiceLogs" -import { splitFirst } from "../../util/util" -import { kubectl } from "./kubectl" import { KubernetesResource, KubernetesPod } from "./types" -import { getAllPods } from "./util" +import { getAllPods, getStaticLabelsFromPod, getSelectorString } from "./util" import { KubeApi } from "./api" import { Service } from "../../types/service" import Stream from "ts-stream" import { LogEntry } from "../../logger/log-entry" import Bluebird from "bluebird" import { KubernetesProvider } from "./config" +import { BinaryCmd } from "../../util/ext-tools" +import { kubectl } from "./kubectl" +import { splitFirst } from "../../util/util" +import { ChildProcess } from "child_process" interface GetLogsBaseParams { defaultNamespace: string @@ -44,6 +46,27 @@ interface GetLogsParams extends GetLogsBaseParams { pod: KubernetesPod } +const STERN_NAME = "stern" +const STERN_TIME_OUT = 300 +const stern = new BinaryCmd({ + name: STERN_NAME, + defaultTimeout: STERN_TIME_OUT, + specs: { + darwin: { + url: "https://github.com/wercker/stern/releases/download/1.11.0/stern_darwin_amd64", + sha256: "7aea3b6691d47b3fb844dfc402905790665747c1e6c02c5cabdd41994533d7e9", + }, + linux: { + url: "https://github.com/wercker/stern/releases/download/1.11.0/stern_linux_amd64", + sha256: "e0b39dc26f3a0c7596b2408e4fb8da533352b76aaffdc18c7ad28c833c9eb7db", + }, + win32: { + url: "https://github.com/wercker/stern/releases/download/1.11.0/stern_windows_amd64.exe", + sha256: "75708b9acf6ef0eeffbe1f189402adc0405f1402e6b764f1f5152ca288e3109e", + }, + }, +}) + /** * Stream all logs for the given pod names and service. */ @@ -56,11 +79,9 @@ export async function getPodLogs(params: GetPodLogsParams) { return resolve({}) } for (const proc of procs) { - proc.on("error", reject) + proc.on("error", () => reject) - proc.on("exit", () => { - resolve({}) - }) + proc.on("exit", () => resolve({})) } }) } @@ -75,13 +96,23 @@ export async function getAllLogs(params: GetAllLogsParams) { } async function getLogs({ log, provider, service, stream, tail, follow, pod }: GetLogsParams) { - // TODO: do this via API instead of kubectl - const kubectlArgs = ["logs", "--tail", String(tail), "--timestamps=true", "--all-containers=true"] - if (follow) { - kubectlArgs.push("--follow=true") + return followLogs(log, provider, service, stream, tail, pod) } + return readLogs(log, provider, service, stream, tail, pod) +} + +async function readLogs( + log: LogEntry, + provider: KubernetesProvider, + service: Service, + stream: Stream, + tail: number, + pod: KubernetesPod +) { + const kubectlArgs = ["logs", "--tail", String(tail), "--timestamps=true", "--all-containers=true"] + kubectlArgs.push(`pod/${pod.metadata.name}`) const proc = await kubectl.spawn({ @@ -90,22 +121,79 @@ async function getLogs({ log, provider, service, stream, tail, follow, pod }: Ge provider, namespace: pod.metadata.namespace, }) + + handleLogMessageStreamFromProcess(proc, stream, service) + return proc +} +async function followLogs( + log: LogEntry, + provider: KubernetesProvider, + service: Service, + stream: Stream, + tail: number, + pod: KubernetesPod +) { + const sternArgs = [ + `--context=${provider.config.context}`, + `--namespace=${pod.metadata.namespace}`, + `--exclude-container=garden-*`, + "--tail", + String(tail), + "--output=json", + "-t", + ] + + /* 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}`) + } + + const proc = await stern.spawn({ + args: sternArgs, + log, + }) + + handleLogMessageStreamFromProcess(proc, stream, service, true) + return proc +} + +function handleLogMessageStreamFromProcess( + proc: ChildProcess, + stream: Stream, + service: Service, + json?: boolean +) { let timestamp: Date proc.stdout!.pipe(split()).on("data", (s) => { if (!s) { return } - const [timestampStr, msg] = splitFirst(s, " ") + const [timestampStr, msg] = json ? parseSternLogMessage(s) : splitFirst(s, " ") try { timestamp = moment(timestampStr).toDate() } catch {} void stream.write({ serviceName: service.name, timestamp, - msg: `${pod.metadata.name} ${msg}`, + msg: `${msg}`, }) }) +} - return proc +function parseSternLogMessage(message: string): string[] { + let log = JSON.parse(message) + const logMessageChunks = log.message.split(" ") + return [ + logMessageChunks[0], + logMessageChunks + .slice(1, logMessageChunks.length) + .join(" ") + .trimEnd(), + ] } diff --git a/garden-service/src/plugins/kubernetes/util.ts b/garden-service/src/plugins/kubernetes/util.ts index 7d9bbe3a60..8f4eec9aa6 100644 --- a/garden-service/src/plugins/kubernetes/util.ts +++ b/garden-service/src/plugins/kubernetes/util.ts @@ -20,6 +20,7 @@ import { ConfigurationError } from "../../exceptions" import { KubernetesProvider } from "./config" import { LogEntry } from "../../logger/log-entry" +const STATIC_LABEL_REGEX = /[0-9]/g export const workloadTypes = ["Deployment", "DaemonSet", "ReplicaSet", "StatefulSet"] export function getAnnotation(obj: KubernetesResource, key: string): string | null { @@ -381,3 +382,22 @@ export async function getRunningPodInDeployment(deploymentName: string, provider return sample(pods) } + +export function getStaticLabelsFromPod(pod: KubernetesPod): { [key: string]: string } { + const labels: { [key: string]: string } = {} + + for (const label in pod.metadata.labels) { + if (!pod.metadata.labels[label].match(STATIC_LABEL_REGEX)) { + labels[label] = pod.metadata.labels[label] + } + } + return labels +} + +export function getSelectorString(labels: { [key: string]: string }) { + let selectorString: string = "-l" + for (const label in labels) { + selectorString += `${label}=${labels[label]},` + } + return selectorString.trimEnd().slice(0, -1) +} diff --git a/garden-service/test/e2e/src/pre-release.ts b/garden-service/test/e2e/src/pre-release.ts index c4e70ba385..98ee0b0604 100644 --- a/garden-service/test/e2e/src/pre-release.ts +++ b/garden-service/test/e2e/src/pre-release.ts @@ -173,7 +173,7 @@ describe("PreReleaseTests", () => { description: "get logs for node-service", condition: async () => { const logEntries = await runWithEnv(["logs", "node-service"]) - return searchLog(logEntries, /node-service-v-.* App started/) + return searchLog(logEntries, /App started/) }, }, changeFileStep(resolve(hotReloadProjectPath, "node-service/app.js"), "change node-service/app.js"), @@ -181,7 +181,7 @@ describe("PreReleaseTests", () => { description: "get logs for node-service after hot reload event", condition: async () => { const logEntries = await runWithEnv(["logs", "node-service"]) - return searchLog(logEntries, /node-service-v-.* App started/) + return searchLog(logEntries, /App started/) }, }, ] diff --git a/garden-service/test/unit/src/logger/log-entry.ts b/garden-service/test/unit/src/logger/log-entry.ts index e347b57563..556cfe1143 100644 --- a/garden-service/test/unit/src/logger/log-entry.ts +++ b/garden-service/test/unit/src/logger/log-entry.ts @@ -67,6 +67,7 @@ describe("LogEntry", () => { status: undefined, data: undefined, append: undefined, + maxSectionWidth: undefined, } it("should update entry state", () => { const timestamp = freezeTime().valueOf() @@ -86,6 +87,7 @@ describe("LogEntry", () => { status: "done", data: { some: "data" }, metadata: { task: taskMetadata }, + maxSectionWidth: 8, }) expect(entry.getMessageStates()).to.eql([ @@ -98,10 +100,38 @@ describe("LogEntry", () => { data: { some: "data" }, append: undefined, timestamp, + maxSectionWidth: 8, }, ]) expect(entry.getMetadata()).to.eql({ task: taskMetadata }) }) + it("should update maxSectionWidth to zero", () => { + const timestamp = freezeTime().valueOf() + const entry = logger.placeholder() + entry.setState({ + msg: "hello", + emoji: "haircut", + section: "caesar", + symbol: "info", + status: "done", + data: { some: "data" }, + maxSectionWidth: 0, + }) + + expect(entry.getMessageStates()).to.eql([ + { + msg: "hello", + emoji: "haircut", + section: "caesar", + symbol: "info", + status: "done", + data: { some: "data" }, + append: undefined, + timestamp, + maxSectionWidth: 0, + }, + ]) + }) it("should overwrite previous values", () => { const timestamp = freezeTime().valueOf() const entry = logger.placeholder() @@ -112,11 +142,17 @@ describe("LogEntry", () => { symbol: "info", status: "done", data: { some: "data" }, + maxSectionWidth: 8, }) entry.setState({ msg: "world", emoji: "hamburger", data: { some: "data_updated" }, + maxSectionWidth: 10, + }) + + entry.setState({ + maxSectionWidth: 0, }) expect(entry.getMessageStates()).to.eql([ { @@ -128,6 +164,18 @@ describe("LogEntry", () => { data: { some: "data" }, append: undefined, timestamp, + maxSectionWidth: 8, + }, + { + msg: "world", + emoji: "hamburger", + section: "caesar", + symbol: "info", + status: "done", + data: { some: "data_updated" }, + append: undefined, + timestamp, + maxSectionWidth: 10, }, { msg: "world", @@ -138,6 +186,7 @@ describe("LogEntry", () => { data: { some: "data_updated" }, append: undefined, timestamp, + maxSectionWidth: 0, }, ]) }) diff --git a/garden-service/test/unit/src/logger/renderers.ts b/garden-service/test/unit/src/logger/renderers.ts index 665471feb7..b75aaef3db 100644 --- a/garden-service/test/unit/src/logger/renderers.ts +++ b/garden-service/test/unit/src/logger/renderers.ts @@ -9,11 +9,14 @@ import { chainMessages, renderError, formatForJson, + renderSection, + MAX_SECTION_WIDTH, } from "../../../../src/logger/renderers" import { GardenError } from "../../../../src/exceptions" import dedent = require("dedent") import { TaskMetadata } from "../../../../src/logger/log-entry" import logSymbols = require("log-symbols") +import stripAnsi = require("strip-ansi") const logger: any = getLogger() @@ -58,28 +61,54 @@ describe("renderers", () => { 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` + }) + 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") - }) + }) + 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("renderSection", () => { + it("should render the log entry section", () => { + const entry = logger.info({ msg: "foo", section: "hello" }) + const withWhitespace = "hello".padEnd(MAX_SECTION_WIDTH, " ") + const rendered = stripAnsi(renderSection(entry)) + expect(rendered).to.equal(`${withWhitespace} → `) + }) + it("should not render arrow if message is empty", () => { + const entry = logger.info({ section: "hello" }) + const withWhitespace = "hello".padEnd(MAX_SECTION_WIDTH, " ") + const rendered = stripAnsi(renderSection(entry)) + expect(rendered).to.equal(`${withWhitespace}`) + }) + it("should optionally set a custom section width", () => { + const entry = logger.info({ msg: "foo", section: "hello", maxSectionWidth: 8 }) + const withWhitespace = "hello".padEnd(8, " ") + const rendered = stripAnsi(renderSection(entry)) + expect(rendered).to.equal(`${withWhitespace} → `) + }) + it("should not let custom section width exceed max section width", () => { + const entry = logger.info({ msg: "foo", section: "hello", maxSectionWidth: 99 }) + const withWhitespace = "hello".padEnd(MAX_SECTION_WIDTH, " ") + const rendered = stripAnsi(renderSection(entry)) + expect(rendered).to.equal(`${withWhitespace} → `) }) }) describe("chainMessages", () => { diff --git a/garden-service/test/unit/src/plugins/kubernetes/util.ts b/garden-service/test/unit/src/plugins/kubernetes/util.ts index 6f49a0f323..c0829bb065 100644 --- a/garden-service/test/unit/src/plugins/kubernetes/util.ts +++ b/garden-service/test/unit/src/plugins/kubernetes/util.ts @@ -5,6 +5,8 @@ import { kilobytesToString, flattenResources, deduplicatePodsByLabel, + getStaticLabelsFromPod, + getSelectorString, } from "../../../../../src/plugins/kubernetes/util" import { KubernetesServerResource } from "../../../../../src/plugins/kubernetes/types" import { V1Pod } from "@kubernetes/client-node" @@ -259,3 +261,41 @@ describe("flattenResources", () => { expect(flattenResources(resources).map((r) => r.metadata.name)).to.eql(["a", "d", "e"]) }) }) + +describe("getStaticLabelsFromPod", () => { + it("should should only select labels without characters", () => { + const pod = ({ + apiVersion: "v1", + kind: "Pod", + metadata: { + creationTimestamp: new Date("2019-11-12T14:44:26Z"), + labels: { + module: "a", + service: "a", + lean: "5", + checksum: "a1b2c3d4", + }, + }, + spec: {}, + } as unknown) as KubernetesServerResource + + const labels = getStaticLabelsFromPod(pod) + + expect(labels).to.eql({ + module: "a", + service: "a", + }) + }) +}) + +describe("getSelectorString", () => { + it("should format a label map to comma separated key value string ", () => { + const labels = { + module: "a", + service: "a", + } + const selectorString = getSelectorString(labels) + + expect(selectorString).to.eql("-lmodule=a,service=a") + }) +})