From ebae0799ad7decc2c202ac31c9eb78873f4ffd76 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 12:40:21 +0300 Subject: [PATCH 1/9] fix: align indirect Go module requirements Signed-off-by: Roman Berezkin --- go.mod | 6 +++--- go.sum | 4 ++++ 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/go.mod b/go.mod index db391afe..10c07930 100644 --- a/go.mod +++ b/go.mod @@ -129,9 +129,9 @@ require ( golang.org/x/sys v0.48.0 // indirect golang.org/x/term v0.46.0 // indirect golang.org/x/text v0.42.0 // indirect - golang.org/x/tools v0.48.0 // indirect - google.golang.org/genproto/googleapis/api v0.0.0-20260720211330-0afa2a65878a // indirect - google.golang.org/genproto/googleapis/rpc v0.0.0-20260720211330-0afa2a65878a // indirect + golang.org/x/tools v0.49.0 // indirect + google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d // indirect + google.golang.org/genproto/googleapis/rpc v0.0.0-20260803160001-6ac0973c030d // indirect google.golang.org/grpc v1.83.2 // indirect google.golang.org/protobuf v1.36.12-0.20260120151049-f2248ac996af // indirect gopkg.in/evanphx/json-patch.v4 v4.13.0 // indirect diff --git a/go.sum b/go.sum index 30b968ad..a26d4537 100644 --- a/go.sum +++ b/go.sum @@ -435,8 +435,12 @@ gonum.org/v1/gonum v0.17.0 h1:VbpOemQlsSMrYmn7T2OUvQ4dqxQXU+ouZFQsZOx50z4= gonum.org/v1/gonum v0.17.0/go.mod h1:El3tOrEuMpv2UdMrbNlKEh9vd86bmQ6vqIcDwxEOc1E= google.golang.org/genproto/googleapis/api v0.0.0-20260720211330-0afa2a65878a h1:97PfJ4tCxY5C7NzzgGqQEMZmXbISdvSArNNEOoUGKBg= google.golang.org/genproto/googleapis/api v0.0.0-20260720211330-0afa2a65878a/go.mod h1:1brfde68Npq6+WA75c1EHWPijZEG1kMus61ygPZfn4A= +google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d h1:FarXi840EJWSHYTN3ERkADbPWjl307+FGrA22KAVjjc= +google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d/go.mod h1:K/+WGbmBY7aNW1HDw1fJnKYo10i0DkAX6pows00dLig= google.golang.org/genproto/googleapis/rpc v0.0.0-20260720211330-0afa2a65878a h1:qI/YMH1ep2qQtqcp00gMQyoU7mjvbhg88GJKCvfoLj0= google.golang.org/genproto/googleapis/rpc v0.0.0-20260720211330-0afa2a65878a/go.mod h1:4Hqkh8ycfw05ld/3BWL7rJOSfebL2Q+DVDeRgYgxUU8= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260803160001-6ac0973c030d h1:IL4hdHzcUv2l/gcg98/Rj3FbtE6axwqslOW8SW0C+S0= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260803160001-6ac0973c030d/go.mod h1:4Hqkh8ycfw05ld/3BWL7rJOSfebL2Q+DVDeRgYgxUU8= google.golang.org/grpc v1.83.2 h1:EManeRomTObA0BU7I8vXgg/78uE5MJ9M8B39EX2WscU= google.golang.org/grpc v1.83.2/go.mod h1:YPI1hK3kDked6iHvgX3tR0y+nX/qpMFKhPgFsokw1S8= google.golang.org/protobuf v1.36.12-0.20260120151049-f2248ac996af h1:+5/Sw3GsDNlEmu7TfklWKPdQ0Ykja5VEmq2i817+jbI= From a7afdb486f425799ae0d655532b4aaea6af8c6b2 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 12:40:31 +0300 Subject: [PATCH 2/9] fix: restore and verify multi-platform container images Signed-off-by: Roman Berezkin --- .dockerignore | 3 ++- .github/workflows/images.yaml | 34 +++++++++++++++++++++++++ Dockerfile | 17 +++++++------ scripts/ci/verify-image.sh | 48 +++++++++++++++++++++++++++++++++++ 4 files changed, 93 insertions(+), 9 deletions(-) create mode 100644 .github/workflows/images.yaml create mode 100644 scripts/ci/verify-image.sh diff --git a/.dockerignore b/.dockerignore index 4d248e6d..ffa14334 100644 --- a/.dockerignore +++ b/.dockerignore @@ -2,6 +2,7 @@ docs examples scripts +!scripts/ci/verify-image.sh test libjq @@ -10,4 +11,4 @@ libjq Dockerfile LICENSE *.md -*.png \ No newline at end of file +*.png diff --git a/.github/workflows/images.yaml b/.github/workflows/images.yaml new file mode 100644 index 00000000..a694f537 --- /dev/null +++ b/.github/workflows/images.yaml @@ -0,0 +1,34 @@ +name: Container images +on: + pull_request: + types: [opened, synchronize] + +permissions: + contents: read + +jobs: + build: + name: Build and verify (${{ matrix.platform }}) + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + platform: [linux/amd64, linux/arm64, linux/arm/v7] + steps: + - name: Check out shell-operator code + uses: actions/checkout@v7 + - name: Set up QEMU + uses: docker/setup-qemu-action@v4.2.0 + with: + platforms: arm64,arm + - name: Set up Docker Buildx + uses: docker/setup-buildx-action@v4 + - name: Build and verify image + env: + PLATFORM: ${{ matrix.platform }} + run: | + docker buildx build \ + --platform "$PLATFORM" \ + --build-arg appVersion=ci \ + --output type=cacheonly \ + . diff --git a/Dockerfile b/Dockerfile index 84fca7d6..83ab04cc 100644 --- a/Dockerfile +++ b/Dockerfile @@ -1,8 +1,4 @@ -# Prebuilt jq from deckhouse base images (v1.0.40). -FROM --platform=${TARGETPLATFORM:-linux/amd64} registry.deckhouse.io/container-factory@sha256:4b36dcf53c35b50e0afbc445232713aff15f788a61b832cd720bf9e88fc9fba8 AS libjq - -# Go builder stage (builder/golang-alpine, Go 1.26.4 on alpine 3.22). -FROM --platform=${TARGETPLATFORM:-linux/amd64} registry.deckhouse.io/container-factory@sha256:193e8ed6cd7fc19015ab615ccf92d0fe02471e66e3e5abf560b3a87fb05bdb62 AS builder +FROM --platform=${TARGETPLATFORM:-linux/amd64} golang:1.26.4-alpine3.23@sha256:18b460dd17542c2ba43299a633cf6ebfc1115101509531471d7cfce1019af083 AS builder ARG appVersion=latest @@ -32,8 +28,7 @@ RUN GOOS=linux \ -o shell-operator \ ./cmd/shell-operator -# Final runtime image (builder/alpine 3.22 from deckhouse base images v1.0.40). -FROM --platform=${TARGETPLATFORM:-linux/amd64} registry.deckhouse.io/container-factory@sha256:8fa8cf713bf8cfc9038901e5b2fbc97d0403794d834dc4a619e9e81312a6feef +FROM --platform=${TARGETPLATFORM:-linux/amd64} alpine:3.23@sha256:ff7f0c727dd796aa36787bfcd9a64bf35a6ce72a73451b3359fde849b6703d63 ARG TARGETPLATFORM ARG kubectlVersion=v1.35.8 @@ -44,6 +39,7 @@ RUN apk --no-cache add \ bash \ sed \ tini \ + jq \ curl # Determine kubectl architecture and download @@ -58,9 +54,14 @@ RUN mkdir /hooks # Copy necessary files ADD frameworks/shell /frameworks/shell ADD shell_lib.sh / -COPY --from=libjq /usr/bin/jq /usr/bin/jq COPY --from=builder /app/shell-operator / +# Reject incorrect architectures before the image can be published. +RUN --mount=type=bind,source=scripts/ci/verify-image.sh,target=/tmp/verify-image.sh \ + apk add --no-cache --virtual .image-verification file && \ + sh /tmp/verify-image.sh "${TARGETPLATFORM:-linux/amd64}" && \ + apk del .image-verification + # Set working directory WORKDIR / diff --git a/scripts/ci/verify-image.sh b/scripts/ci/verify-image.sh new file mode 100644 index 00000000..4462d956 --- /dev/null +++ b/scripts/ci/verify-image.sh @@ -0,0 +1,48 @@ +#!/bin/sh +set -eu + +platform=$1 +case "$platform" in + linux/amd64) + apk_arch=x86_64 + elf_pattern='^ELF 64-bit LSB .*, x86-64,' + ;; + linux/arm64) + apk_arch=aarch64 + elf_pattern='^ELF 64-bit LSB .*, ARM aarch64,' + ;; + linux/arm/v7) + apk_arch=armv7 + elf_pattern='^ELF 32-bit LSB .*, ARM, EABI5' + ;; + *) + echo "Unsupported platform: $platform" >&2 + exit 1 + ;; +esac + +actual_arch=$(apk --print-arch) +if [ "$actual_arch" != "$apk_arch" ]; then + echo "Expected Alpine architecture $apk_arch for $platform, got $actual_arch" >&2 + exit 1 +fi + +# Emulation can run a binary for the wrong platform, so inspect its ELF header. +for binary in /shell-operator /usr/bin/jq /bin/busybox /sbin/tini /bin/kubectl; do + description=$(file -bL "$binary") + echo "$binary: $description" + if ! printf '%s\n' "$description" | grep -Eq "$elf_pattern"; then + echo "Unexpected binary architecture for $platform: $binary" >&2 + exit 1 + fi +done + +/sbin/tini -- /shell-operator version +/bin/kubectl version --client + +context_file=$(mktemp) +trap 'rm -f "$context_file"' EXIT +printf '%s\n' '[{"binding":"image-verification"}]' > "$context_file" +export BINDING_CONTEXT_PATH="$context_file" +export BINDING_CONTEXT_CURRENT_INDEX=0 +bash -ec 'source /shell_lib.sh; test "$(context::get --required binding)" = image-verification' From fbd398132cbeedfee57bad5bafcd749e958eb0ac Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 13:54:45 +0300 Subject: [PATCH 3/9] ci: clarify image architecture verification messages Signed-off-by: Roman Berezkin --- scripts/ci/verify-image.sh | 37 +++++++++++++++++++++++++++++++++---- 1 file changed, 33 insertions(+), 4 deletions(-) diff --git a/scripts/ci/verify-image.sh b/scripts/ci/verify-image.sh index 4462d956..991a32e5 100644 --- a/scripts/ci/verify-image.sh +++ b/scripts/ci/verify-image.sh @@ -1,18 +1,46 @@ #!/bin/sh set -eu +report_architecture_error() { + cat >&2 <&2 - exit 1 + report_architecture_error "Alpine base image" \ + "$(describe_architecture "$apk_arch")" "$(describe_architecture "$actual_arch")" fi # Emulation can run a binary for the wrong platform, so inspect its ELF header. @@ -32,8 +60,7 @@ for binary in /shell-operator /usr/bin/jq /bin/busybox /sbin/tini /bin/kubectl; description=$(file -bL "$binary") echo "$binary: $description" if ! printf '%s\n' "$description" | grep -Eq "$elf_pattern"; then - echo "Unexpected binary architecture for $platform: $binary" >&2 - exit 1 + report_architecture_error "$binary" "$expected_cpu" "$(describe_architecture "$description")" fi done @@ -46,3 +73,5 @@ printf '%s\n' '[{"binding":"image-verification"}]' > "$context_file" export BINDING_CONTEXT_PATH="$context_file" export BINDING_CONTEXT_CURRENT_INDEX=0 bash -ec 'source /shell_lib.sh; test "$(context::get --required binding)" = image-verification' + +printf '✅ %s: Alpine and all 5 checked binaries have the expected CPU architecture.\n' "$platform" From c4f1d12e6323e03f4ed8aa512cd30c3428107070 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 14:41:07 +0300 Subject: [PATCH 4/9] ci: build all platforms only when base images change Signed-off-by: Roman Berezkin --- .github/workflows/images.yaml | 39 +++++++++++++++++++++++++++++++++++ 1 file changed, 39 insertions(+) diff --git a/.github/workflows/images.yaml b/.github/workflows/images.yaml index a694f537..46766379 100644 --- a/.github/workflows/images.yaml +++ b/.github/workflows/images.yaml @@ -2,12 +2,51 @@ name: Container images on: pull_request: types: [opened, synchronize] + workflow_dispatch: permissions: contents: read jobs: + changes: + name: Check base images + runs-on: ubuntu-latest + outputs: + build: ${{ steps.check.outputs.build }} + steps: + - name: Check out shell-operator code + if: github.event_name == 'pull_request' + uses: actions/checkout@v7 + - name: Decide whether to build images + id: check + shell: bash + env: + EVENT_NAME: ${{ github.event_name }} + BEFORE_SHA: ${{ github.event.before || github.event.pull_request.base.sha }} + AFTER_SHA: ${{ github.event.pull_request.head.sha }} + run: | + if [ "$EVENT_NAME" = workflow_dispatch ]; then + echo "Manual run: building all platforms." + echo "build=true" >> "$GITHUB_OUTPUT" + exit 0 + fi + + # Compare this push so unrelated commits do not repeat the full build. + git fetch --no-tags --depth=1 origin "$BEFORE_SHA" "$AFTER_SHA" + git show "$BEFORE_SHA:Dockerfile" | awk 'toupper($1) == "FROM" { $1=$1; print }' > "$RUNNER_TEMP/base-images-before" + git show "$AFTER_SHA:Dockerfile" | awk 'toupper($1) == "FROM" { $1=$1; print }' > "$RUNNER_TEMP/base-images-after" + + if cmp -s "$RUNNER_TEMP/base-images-before" "$RUNNER_TEMP/base-images-after"; then + echo "Base images unchanged: skipping container builds." + echo "build=false" >> "$GITHUB_OUTPUT" + else + echo "Base images changed: building all platforms." + echo "build=true" >> "$GITHUB_OUTPUT" + fi + build: + needs: changes + if: needs.changes.outputs.build == 'true' name: Build and verify (${{ matrix.platform }}) runs-on: ubuntu-latest strategy: From 2a1bd815f24a1f1b56c5690a33514d7f79947cf1 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 14:55:21 +0300 Subject: [PATCH 5/9] ci: clarify base image architecture check logs Signed-off-by: Roman Berezkin --- .github/workflows/images.yaml | 12 +++++++----- scripts/ci/verify-image.sh | 2 ++ 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/.github/workflows/images.yaml b/.github/workflows/images.yaml index 46766379..21220dcb 100644 --- a/.github/workflows/images.yaml +++ b/.github/workflows/images.yaml @@ -1,4 +1,4 @@ -name: Container images +name: Base image architecture checks on: pull_request: types: [opened, synchronize] @@ -9,7 +9,7 @@ permissions: jobs: changes: - name: Check base images + name: Detect base image changes runs-on: ubuntu-latest outputs: build: ${{ steps.check.outputs.build }} @@ -26,7 +26,7 @@ jobs: AFTER_SHA: ${{ github.event.pull_request.head.sha }} run: | if [ "$EVENT_NAME" = workflow_dispatch ]; then - echo "Manual run: building all platforms." + echo "▶️ Manual run requested: building and checking all platforms." echo "build=true" >> "$GITHUB_OUTPUT" exit 0 fi @@ -37,10 +37,11 @@ jobs: git show "$AFTER_SHA:Dockerfile" | awk 'toupper($1) == "FROM" { $1=$1; print }' > "$RUNNER_TEMP/base-images-after" if cmp -s "$RUNNER_TEMP/base-images-before" "$RUNNER_TEMP/base-images-after"; then - echo "Base images unchanged: skipping container builds." + echo "⏭️ Base images unchanged. Skipping builds and architecture checks." echo "build=false" >> "$GITHUB_OUTPUT" else - echo "Base images changed: building all platforms." + echo "🔄 Base image changes detected." + echo "🚀 Full build and architecture checks requested for all platforms." echo "build=true" >> "$GITHUB_OUTPUT" fi @@ -66,6 +67,7 @@ jobs: env: PLATFORM: ${{ matrix.platform }} run: | + echo "🏗️ Building $PLATFORM image with architecture verification enabled." docker buildx build \ --platform "$PLATFORM" \ --build-arg appVersion=ci \ diff --git a/scripts/ci/verify-image.sh b/scripts/ci/verify-image.sh index 991a32e5..0fb27d94 100644 --- a/scripts/ci/verify-image.sh +++ b/scripts/ci/verify-image.sh @@ -49,6 +49,8 @@ case "$platform" in ;; esac +printf '🔍 %s: starting architecture consistency checks for the base image and built binaries.\n' "$platform" + actual_arch=$(apk --print-arch) if [ "$actual_arch" != "$apk_arch" ]; then report_architecture_error "Alpine base image" \ From 6001fbaf75d8fc2fb6def21c4d7a1fdd8e40592a Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 15:06:20 +0300 Subject: [PATCH 6/9] ci: clarify skipped architecture check message Signed-off-by: Roman Berezkin --- .github/workflows/images.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/images.yaml b/.github/workflows/images.yaml index 21220dcb..37ca73c9 100644 --- a/.github/workflows/images.yaml +++ b/.github/workflows/images.yaml @@ -37,7 +37,7 @@ jobs: git show "$AFTER_SHA:Dockerfile" | awk 'toupper($1) == "FROM" { $1=$1; print }' > "$RUNNER_TEMP/base-images-after" if cmp -s "$RUNNER_TEMP/base-images-before" "$RUNNER_TEMP/base-images-after"; then - echo "⏭️ Base images unchanged. Skipping builds and architecture checks." + echo "⏭️ Base images unchanged. Skipping architecture checks." echo "build=false" >> "$GITHUB_OUTPUT" else echo "🔄 Base image changes detected." From aaf21a5ce4830417061804dbd244985bbd462722 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 15:08:38 +0300 Subject: [PATCH 7/9] ci: document base image architecture workflow Signed-off-by: Roman Berezkin --- .github/workflows/images.yaml | 3 +++ 1 file changed, 3 insertions(+) diff --git a/.github/workflows/images.yaml b/.github/workflows/images.yaml index 37ca73c9..1752a8a5 100644 --- a/.github/workflows/images.yaml +++ b/.github/workflows/images.yaml @@ -1,3 +1,6 @@ +# - Detect base-image changes in Dockerfile FROM instructions. +# - Build amd64, arm64 and arm/v7 only when bases change or on manual runs. +# - Check base-image and binary architectures and run smoke tests without publishing images. name: Base image architecture checks on: pull_request: From a1c3432f193cfe862ff7bb23f0d417bc37886e92 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 18:05:53 +0300 Subject: [PATCH 8/9] ci: use supported Python for codespell Signed-off-by: Roman Berezkin --- .github/workflows/lint.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/lint.yaml b/.github/workflows/lint.yaml index cfdc9192..6be6ea4b 100644 --- a/.github/workflows/lint.yaml +++ b/.github/workflows/lint.yaml @@ -39,7 +39,7 @@ jobs: steps: - uses: actions/setup-python@v6 with: - python-version: 3.8 + python-version: "3.12" - name: Check out addon-operator code uses: actions/checkout@v7 - name: Run codespell From 38665d3a75b8c24aefaa19a3d2368a8cfbff3978 Mon Sep 17 00:00:00 2001 From: Roman Berezkin Date: Wed, 28 Oct 2026 18:08:46 +0300 Subject: [PATCH 9/9] fix: preserve hook log records across writes Signed-off-by: Roman Berezkin --- pkg/executor/executor.go | 155 ++++++++++++------------ pkg/executor/proxy_logger_test.go | 191 ++++++++++++++++++++++++++++++ 2 files changed, 272 insertions(+), 74 deletions(-) create mode 100644 pkg/executor/proxy_logger_test.go diff --git a/pkg/executor/executor.go b/pkg/executor/executor.go index f745443a..2dcf52ae 100644 --- a/pkg/executor/executor.go +++ b/pkg/executor/executor.go @@ -4,6 +4,7 @@ import ( "bufio" "bytes" "context" + stdjson "encoding/json" "errors" "fmt" "io" @@ -252,6 +253,8 @@ func (e *Executor) RunAndLogLines(ctx context.Context, logLabels map[string]stri e.cmd.Stderr = io.MultiWriter(ple, stdErr) usage, err := e.runner.Run(ctx, e.cmd) + plo.flush() + ple.flush() if err != nil { if len(stdErr.Bytes()) > 0 { return nil, &StderrError{Message: stdErr.String()} @@ -270,105 +273,109 @@ type proxyLogger struct { proxyJsonLogKey string logger *log.Logger buf []byte + jsonBuf []byte } func (pl *proxyLogger) Write(p []byte) (int, error) { - if !pl.logProxyHookJSON { - pl.writerScanner(p) - - return len(p), nil - } - - // join all parts of json pl.buf = append(pl.buf, p...) - var line interface{} - err := json.Unmarshal(pl.buf, &line) - if err != nil { - if err.Error() == "unexpected end of JSON input" { - return len(p), nil + for len(pl.buf) > 0 { + lineSize := bytes.IndexByte(pl.buf, '\n') + 1 + if !pl.hasPendingJSON() && len(pl.buf) >= bufio.MaxScanTokenSize && (lineSize == 0 || lineSize > bufio.MaxScanTokenSize) { + lineSize = bufio.MaxScanTokenSize + } + if lineSize == 0 { + break } - pl.logger.Debug("output is not json", log.Err(err)) - pl.writerScanner(p) - - return len(p), nil + pl.logLine(pl.buf[:lineSize]) + pl.buf = pl.buf[lineSize:] } - - logMap, ok := line.(map[string]interface{}) - defer func() { - pl.buf = pl.buf[:0] - }() - - if !ok { - pl.logger.Debug("json log line not map[string]interface{}", slog.Any(pkg.LogKeyLine, line)) - - // fall back to using the logger - pl.logger.Info(string(p)) - - return len(p), nil + if len(pl.buf) == 0 { + pl.buf = nil } - pl.mergeAndLogInputLog(pl.ctx, logMap, "hook") - return len(p), nil } -func (pl *proxyLogger) writerScanner(p []byte) { - scanner := bufio.NewScanner(bytes.NewReader(p)) - scanner.Buffer(make([]byte, bufio.MaxScanTokenSize), bufio.MaxScanTokenSize) +func (pl *proxyLogger) hasPendingJSON() bool { + if len(pl.jsonBuf) > 0 { + return true + } + line := bytes.TrimLeft(pl.buf, " \t\r\n") + return bytes.HasPrefix(line, []byte("{")) || (pl.logProxyHookJSON && (bytes.HasPrefix(line, []byte("[")) || bytes.HasPrefix(line, []byte("\"")))) +} - var jsonBuf []string - // Split large entries into chunks - chunkSize := bufio.MaxScanTokenSize // 64KB - splitFunc := func(data []byte, atEOF bool) (int, []byte, error) { - if len(data) >= chunkSize { - return chunkSize, data[:chunkSize], nil - } - return bufio.ScanLines(data, atEOF) - } - scanner.Split(splitFunc) - // Scan the input and write it to the logger using the specified print function - for scanner.Scan() { - // Prevent empty logging - line := strings.TrimSpace(scanner.Text()) - if line == "" { - continue - } +// flush logs the final unterminated record after the output stream ends. +func (pl *proxyLogger) flush() { + if len(pl.buf) > 0 { + pl.logLine(pl.buf) + pl.buf = nil + } + if len(pl.jsonBuf) > 0 { + pl.logText(string(pl.jsonBuf)) + pl.jsonBuf = nil + } +} - if len(jsonBuf) > 0 || strings.HasPrefix(line, "{") { - jsonBuf = append(jsonBuf, line) - joined := strings.Join(jsonBuf, "\n") - if err := pl.tryLogJSON(joined); err == nil { - jsonBuf = nil - } - continue - } +func (pl *proxyLogger) logLine(raw []byte) { + line := strings.TrimSpace(string(raw)) + if line == "" && len(pl.jsonBuf) == 0 { + return + } - if len(line) > 10000 { - line = fmt.Sprintf("%s:truncated", line[:10000]) + // JSON records can span both physical lines and separate Write calls. + if len(pl.jsonBuf) > 0 || strings.HasPrefix(line, "{") || (pl.logProxyHookJSON && (strings.HasPrefix(line, "[") || strings.HasPrefix(line, "\""))) { + pl.jsonBuf = append(pl.jsonBuf, raw...) + err := pl.tryLogJSON(string(pl.jsonBuf)) + if errors.Is(err, io.ErrUnexpectedEOF) { + return } - - if err := pl.tryLogJSON(line); err == nil { - continue + if err != nil { + pl.logText(string(pl.jsonBuf)) } - pl.logger.Info(line) + pl.jsonBuf = nil + return + } + + if err := pl.tryLogJSON(string(raw)); err == nil { + return } - // If there was an error while scanning the input, log an error - if err := scanner.Err(); err != nil { - pl.logger.Error("reading from scanner", log.Err(err)) + pl.logText(line) +} + +func (pl *proxyLogger) logText(line string) { + line = strings.TrimSpace(line) + if len(line) > 10000 { + line = fmt.Sprintf("%s:truncated", line[:10000]) } + pl.logger.Info(line) } -// tryLogJSON tries to parse the string as JSON and log it if it succeeds +// tryLogJSON logs a complete JSON record with the hook's structured fields. func (pl *proxyLogger) tryLogJSON(s string) error { - var m map[string]interface{} - err := json.Unmarshal([]byte(s), &m) - if err == nil { - pl.mergeAndLogInputLog(pl.ctx, m, "hook") + var value interface{} + if err := json.Unmarshal([]byte(s), &value); err != nil { + // go-json reports some incomplete documents as syntax errors. + var raw stdjson.RawMessage + if decodeErr := stdjson.NewDecoder(strings.NewReader(s)).Decode(&raw); errors.Is(decodeErr, io.ErrUnexpectedEOF) { + return io.ErrUnexpectedEOF + } + return err + } + + logMap, ok := value.(map[string]interface{}) + if ok || (value == nil && !pl.logProxyHookJSON) { + pl.mergeAndLogInputLog(pl.ctx, logMap, "hook") return nil } - return fmt.Errorf("failed to parse json: %w", err) + if !pl.logProxyHookJSON { + return errors.New("json log line is not an object") + } + + pl.logger.Debug("json log line not map[string]interface{}", slog.Any(pkg.LogKeyLine, value)) + pl.logger.Info(s) + return nil } // level = level diff --git a/pkg/executor/proxy_logger_test.go b/pkg/executor/proxy_logger_test.go new file mode 100644 index 00000000..3f186a52 --- /dev/null +++ b/pkg/executor/proxy_logger_test.go @@ -0,0 +1,191 @@ +package executor + +import ( + "bytes" + "context" + "errors" + "fmt" + "strings" + "testing" + "time" + + "github.com/deckhouse/deckhouse/pkg/log" + "github.com/stretchr/testify/require" + + json "github.com/flant/shell-operator/pkg/utils/json" +) + +func TestProxyLoggerWriteBoundaries(t *testing.T) { + cases := []struct { + name string + proxy bool + input string + expected []map[string]any + }{ + { + name: "mixed JSON and text", + proxy: true, + input: "{\"level\":\"error\",\"msg\":\"quoted \\\"{value}\\\"\",\"value\":\"Привет\"}\r\n" + + "plain text\r\n" + "{\r\n\"a\":\"b\",\r\n\"c\":\"d\"\r\n}", + expected: []map[string]any{ + {"level": "error", "msg": `quoted "{value}"`, "hook_value": "Привет", "output": "stdout", "proxyJsonLog": true}, + {"level": "info", "msg": "plain text", "output": "stdout"}, + {"level": "info", "msg": "hook result", "hook_a": "b", "hook_c": "d", "output": "stdout", "proxyJsonLog": true}, + }, + }, + { + name: "plain text without JSON proxy", + input: "first line\r\n\nПривет\nlast line", + expected: []map[string]any{ + {"level": "info", "msg": "first line", "output": "stdout"}, + {"level": "info", "msg": "Привет", "output": "stdout"}, + {"level": "info", "msg": "last line", "output": "stdout"}, + }, + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Run("whole", func(t *testing.T) { + require.Equal(t, tc.expected, proxyLoggerRecords(t, tc.proxy, tc.input)) + }) + for split := 1; split < len(tc.input); split++ { + t.Run(fmt.Sprintf("split_%d", split), func(t *testing.T) { + require.Equal(t, tc.expected, proxyLoggerRecords(t, tc.proxy, tc.input[:split], tc.input[split:])) + }) + } + t.Run("bytewise", func(t *testing.T) { + chunks := make([]string, len(tc.input)) + for i := range chunks { + chunks[i] = tc.input[i : i+1] + } + require.Equal(t, tc.expected, proxyLoggerRecords(t, tc.proxy, chunks...)) + }) + }) + } +} + +func TestProxyLoggerFlushIncompleteJSON(t *testing.T) { + require.Equal(t, []map[string]any{ + {"level": "info", "msg": `{"unfinished":`, "output": "stdout"}, + }, proxyLoggerRecords(t, true, `{"unfin`, `ished":`)) +} + +func TestProxyLoggerMalformedJSON(t *testing.T) { + require.Equal(t, []map[string]any{ + {"level": "info", "msg": `{"value": broken}`, "output": "stdout"}, + {"level": "info", "msg": "hook result", "hook_value": "next", "output": "stdout", "proxyJsonLog": true}, + }, proxyLoggerRecords(t, true, "{\"value\": broken}\n{\"value\":\"next\"}\n")) +} + +func TestProxyLoggerMultilineArray(t *testing.T) { + input := "[\n\n\"first\",\n\"second\"\n]\n" + require.Equal(t, []map[string]any{ + {"level": "info", "msg": input, "output": "stdout"}, + }, proxyLoggerRecords(t, true, input[:4], input[4:])) +} + +func TestProxyLoggerLongRecords(t *testing.T) { + t.Run("plain text is truncated across writes", func(t *testing.T) { + line := "result " + strings.Repeat("x", 20000) + records := proxyLoggerRecords(t, false, line[:4096], line[4096:]+"\nafter\n") + require.Equal(t, []map[string]any{ + {"level": "info", "msg": line[:10000] + ":truncated", "output": "stdout"}, + {"level": "info", "msg": "after", "output": "stdout"}, + }, records) + }) + + t.Run("JSON fields are truncated across writes", func(t *testing.T) { + input := `{"payload":"` + strings.Repeat("x", 70000) + `"}` + records := proxyLoggerRecords(t, true, input[:32768], input[32768:]+"\n") + require.Equal(t, []map[string]any{ + { + "level": "info", "msg": "hook result", "output": "stdout", "proxyJsonLog": true, + "hook": map[string]any{"truncated": input[:10000] + ":truncated"}, + }, + }, records) + }) + + t.Run("non-object JSON remains raw text", func(t *testing.T) { + input := `"` + strings.Repeat("x", 70000) + "\"\n" + require.Equal(t, []map[string]any{ + {"level": "info", "msg": input, "output": "stdout"}, + }, proxyLoggerRecords(t, true, input[:32768], input[32768:])) + }) +} + +func TestRunAndLogLinesFlushesBothStreams(t *testing.T) { + for _, failed := range []bool{false, true} { + t.Run(fmt.Sprintf("failed_%t", failed), func(t *testing.T) { + logger, output := newProxyLoggerTestLogger() + runner := &fakeRunner{stdout: `{"value":"out"}`, stderr: "stderr tail"} + if failed { + runner.err = errors.New("hook failed") + } + ex := NewExecutor("", "hook", nil, nil). + WithRunner(runner). + WithLogProxyHookJSON(true). + WithLogger(logger) + + _, err := ex.RunAndLogLines(context.Background(), nil) + if failed { + var stderrErr *StderrError + require.ErrorAs(t, err, &stderrErr) + require.Equal(t, runner.stderr, stderrErr.Message) + } else { + require.NoError(t, err) + } + require.Equal(t, []map[string]any{ + {"level": "info", "msg": "hook result", "hook_value": "out", "output": "stdout", "proxyJsonLog": true}, + {"level": "info", "msg": "stderr tail", "output": "stderr"}, + }, decodeProxyLoggerRecords(t, output.String())) + }) + } +} + +func proxyLoggerRecords(t *testing.T, proxy bool, chunks ...string) []map[string]any { + t.Helper() + logger, output := newProxyLoggerTestLogger() + pl := &proxyLogger{ + ctx: context.Background(), + logProxyHookJSON: proxy, + proxyJsonLogKey: "proxyJsonLog", + logger: logger.With("output", "stdout"), + } + for _, chunk := range chunks { + n, err := pl.Write([]byte(chunk)) + require.NoError(t, err) + require.Equal(t, len(chunk), n) + } + pl.flush() + result := output.String() + pl.flush() + require.Equal(t, result, output.String(), "flushing again must not duplicate records") + return decodeProxyLoggerRecords(t, result) +} + +func newProxyLoggerTestLogger() (*log.Logger, *bytes.Buffer) { + logger := log.NewLogger(log.WithTimeFunc(func(time.Time) time.Time { + return time.Date(2006, time.January, 2, 15, 4, 5, 0, time.UTC) + })) + logger.SetLevel(log.LevelInfo) + output := new(bytes.Buffer) + logger.SetOutput(output) + return logger, output +} + +func decodeProxyLoggerRecords(t *testing.T, output string) []map[string]any { + t.Helper() + var records []map[string]any + for _, line := range strings.Split(strings.TrimSpace(output), "\n") { + if line == "" { + continue + } + var record map[string]any + require.NoError(t, json.Unmarshal([]byte(line), &record)) + require.Equal(t, "2006-01-02T15:04:05Z", record["time"]) + delete(record, "time") + records = append(records, record) + } + return records +}