builder/build/cnb/phase_logger_test.go

Rama main · réplica de lectura del repositorio original.

package cnb

import (
	"bytes"
	"context"
	"encoding/json"
	"errors"
	"io"
	"strings"
	"sync"
	"testing"
	"time"

	"github.com/eapache/channels"
	"github.com/goodrain/rainbond/builder/build"
	"github.com/goodrain/rainbond/builder/parser/code"
	"github.com/goodrain/rainbond/event"
	corev1 "k8s.io/api/core/v1"
)

func readCNBMessages(t *testing.T, logs chan []byte) []map[string]string {
	t.Helper()
	var entries []map[string]string
	for len(logs) > 0 {
		var entry map[string]string
		if err := json.Unmarshal(<-logs, &entry); err != nil {
			t.Fatal(err)
		}
		entries = append(entries, entry)
	}
	return entries
}

// capability_id: rainbond.cnb.phase-timing
func TestCNBPhaseTiming(t *testing.T) {
	for _, style := range []struct {
		name   string
		prefix string
		suffix string
	}{
		{name: "plain"},
		{name: "lifecycle cyan", prefix: "\x1b[36m", suffix: "\x1b[0m"},
		{name: "bold cyan", prefix: "\x1b[1;36m", suffix: "\x1b[0m"},
		{name: "true color", prefix: "\x1b[38:2:0:200:200m", suffix: "\x1b[m"},
	} {
		t.Run(style.name, func(t *testing.T) {
			logs := make(chan []byte, 20)
			var output bytes.Buffer
			writer := newCNBPhaseWriter(&output, event.NewLogger("test", logs))
			now := time.Unix(0, 0)
			writer.now = func() time.Time { return now }
			var input strings.Builder
			phases := []string{"ANALYZING", "DETECTING", "RESTORING", "BUILDING", "EXPORTING"}
			for i, phase := range phases {
				line := style.prefix + "===> " + phase + style.suffix + "\r\n"
				input.WriteString(line)
				if _, err := writer.Write([]byte(line)); err != nil {
					t.Fatal(err)
				}
				now = now.Add(time.Duration(i+1) * time.Second)
			}
			writer.finish()
			writer.finish()
			if output.String() != input.String() {
				t.Fatalf("original logs changed: %q", output.String())
			}
			entries := readCNBMessages(t, logs)
			if len(entries) != len(phases) {
				t.Fatalf("got %d timing records, want %d: %v", len(entries), len(phases), entries)
			}
			for i, entry := range entries {
				want := time.Duration(i+1) * time.Second
				if entry["step"] != "build-timing" || entry["phase"] != phases[i] || !strings.Contains(entry["message"], want.String()) {
					t.Errorf("unexpected timing entry: %v", entry)
				}
				if strings.Contains(entry["message"], "success") {
					t.Errorf("elapsed time must not imply build success: %v", entry)
				}
			}
		})
	}
}

// capability_id: rainbond.cnb.phase-timing
func TestCNBPhaseTimingHandlesFragmentedLogs(t *testing.T) {
	logs := make(chan []byte, 10)
	var output bytes.Buffer
	writer := newCNBPhaseWriter(&output, event.NewLogger("test", logs))
	now := time.Unix(0, 0)
	writer.now = func() time.Time { return now }
	writer.Write([]byte("===> REST"))
	writer.Write([]byte("ORING\nordinary log\n===> RESTORING\n===> UNKNOWN\n"))
	now = now.Add(7 * time.Second)
	writer.Write([]byte("===> BUILDING"))
	writer.finish()
	entries := readCNBMessages(t, logs)
	if len(entries) != 2 || entries[0]["phase"] != "RESTORING" || entries[0]["duration_ms"] != "7000" || entries[1]["phase"] != "BUILDING" {
		t.Fatalf("unexpected fragmented timing records: %v", entries)
	}
	if output.String() != "===> RESTORING\nordinary log\n===> RESTORING\n===> UNKNOWN\n===> BUILDING" {
		t.Fatalf("fragmented logs were changed: %q", output.String())
	}
}

type failingCNBWriter struct{}

func (failingCNBWriter) Write([]byte) (int, error) { return 0, io.ErrClosedPipe }

// capability_id: rainbond.cnb.phase-timing
func TestCNBPhaseTimingPreservesWriterErrors(t *testing.T) {
	logs := make(chan []byte, 10)
	writer := newCNBPhaseWriter(failingCNBWriter{}, event.NewLogger("test", logs))
	if n, err := writer.Write([]byte("===> BUILDING\n")); n != 0 || !errors.Is(err, io.ErrClosedPipe) {
		t.Fatalf("writer result = (%d, %v), want (0, closed pipe)", n, err)
	}
	writer.finish()
	if len(logs) != 0 {
		t.Fatal("failed writes must not produce phase timing")
	}
}

// capability_id: rainbond.cnb.phase-timing
func TestCNBPhaseTimingSerializesConcurrentWrites(t *testing.T) {
	logs := make(chan []byte, 10)
	var output bytes.Buffer
	writer := newCNBPhaseWriter(&output, event.NewLogger("test", logs))
	var group sync.WaitGroup
	for i := 0; i < 10; i++ {
		group.Add(1)
		go func() {
			defer group.Done()
			writer.Write([]byte("build output\n"))
		}()
	}
	group.Wait()
	writer.finish()
	if strings.Count(output.String(), "build output\n") != 10 || len(logs) != 0 {
		t.Fatalf("concurrent output was lost or misclassified: %q", output.String())
	}
}

// capability_id: rainbond.cnb.phase-timing
func TestCNBJobEmitsFinalPhaseTiming(t *testing.T) {
	for _, status := range []string{"complete", "failed"} {
		t.Run(status, func(t *testing.T) {
			logs := make(chan []byte, 40)
			ctrl := &mockJobCtrl{execJobFn: func(ctx context.Context, pod *corev1.Pod, writer io.Writer, result *channels.RingChannel) error {
				io.WriteString(writer, "===> RESTORING\n===> BUILDING\n")
				go func() {
					result.In() <- status
					result.In() <- "logcomplete"
				}()
				return nil
			}}
			re := &build.Request{ServiceID: "svc", DeployVersion: "v1", RbdNamespace: "ns", Arch: "amd64", SourceDir: newNodeDir(t), Lang: code.Nodejs, BuildEnvs: map[string]string{}, Logger: event.NewLogger("test", logs)}
			var entries []map[string]string
			b := newTestBuilder(ctrl)
			b.jobCtrl = &timingCleanupJobCtrl{mockJobCtrl: ctrl, beforeCleanup: func() {
				entries = readCNBMessages(t, logs)
			}}
			err := b.runCNBBuildJob(re, "registry.test/app:v1")
			if (err != nil) != (status == "failed") {
				t.Fatalf("unexpected result for status %s: %v", status, err)
			}
			var phases []string
			for _, entry := range entries {
				if entry["step"] == "build-timing" {
					phases = append(phases, entry["phase"])
				}
			}
			if strings.Join(phases, ",") != "RESTORING,BUILDING" {
				t.Fatalf("missing final phase timing before cleanup on %s: %v", status, phases)
			}
		})
	}
}

type timingCleanupJobCtrl struct {
	*mockJobCtrl
	beforeCleanup func()
}

func (c *timingCleanupJobCtrl) DeleteJob(name string) {
	c.beforeCleanup()
	c.mockJobCtrl.DeleteJob(name)
}