Add initialization step logs

deploy/README.md

@@ -11,7 +11,7 @@
 
 `install.sh` downloads its release's `compose.yaml`, checks it against `compose-sha256sums.txt`, writes `.env`, and starts Compose. Core applies database migrations when it starts. The host needs Linux amd64 and Docker Compose 2.26 or newer. [Configuration](../docs/configuration.md) owns the installation layout and settings.
 
-`oac` is a Go command (`services/core/cmd/oac`) in the Core image and the ingress image. The host copy implements `apply`, `core-key` and `rotate-core-key`; `core-key --show` runs `oac-web core-key` in the Web container. Start, stop, logs and removal are `docker compose`. `apply` runs `oac-core check-config` before recreating services. The ingress image runs data initialization as `oac init`, verifies and copies its bundled node metadata without network access, and contains no Python. No service receives a Docker socket.
+`oac` is a Go command (`services/core/cmd/oac`) in the Core image and the ingress image. The host copy implements `apply`, `core-key` and `rotate-core-key`; `core-key --show` runs `oac-web core-key` in the Web container. Start, stop, logs and removal are `docker compose`. `apply` runs `oac-core check-config` before recreating services. The ingress image runs data initialization as `oac init`, verifies and copies its bundled node metadata without network access, and contains no Python. No service receives a Docker socket. Initialization writes structured logs to stderr for directory preparation, lock acquisition, existing-installation verification, bundled metadata verification and publication, credential generation or reuse, and receipt persistence. Each step records its start and completion; failures identify the current step, and completion records elapsed milliseconds. Credential values and digests are never logged. View these logs with `docker compose logs --timestamps init`.
 
 Web serves the console and forwards `/v1` and `/api/v1` to Core, so it is the only published service. HTTPS is terminated by the operator's reverse proxy or hosting platform, which routes to `web:8080`; `OAC_PUBLIC_URL` records that origin.
 

docs/getting-started/operations.md

@@ -41,8 +41,11 @@ Service health does not show that a harness or a model works. Use Session, Turn,
 ```sh
 docker compose -f "$HOME/.oac/core/compose.yaml" ps --all
 docker compose -f "$HOME/.oac/core/compose.yaml" logs --tail 200 core
+docker compose -f "$HOME/.oac/core/compose.yaml" logs --timestamps init
 ```
 
+The `init` service exits after initialization. Its step logs are described in [Deployment](https://github.com/MiniMax-AI/OpenAgentCore/blob/main/deploy/README.md#installation).
+
 Don't paste `docker compose config`, `docker inspect` or raw logs into public issue reports.
 
 ## Stop and restart

docs/zh/getting-started/operations.md

@@ -1,7 +1,7 @@
 ---
 title: "管理你的安装"
 source: docs/getting-started/operations.md
-source_hash: e60a6e96cd61692b6adc7664874ba0ed2ce489982e7da2fe2347631ee2a94c0a
+source_hash: 5ac3e57f943b8bb3fadbf9cda0a72399317ad101416ec28ca4037eea07703a82
 ---
 
 安装运维人员负责 Core 主机、存储和可用性。节点主机运行各自的服务；参阅[节点](nodes.md)。设置见[配置参考](../configuration.md)。
@@ -43,8 +43,11 @@ docker compose -f ~/.oac/core/compose.yaml ps
 ```sh
 docker compose -f "$HOME/.oac/core/compose.yaml" ps --all
 docker compose -f "$HOME/.oac/core/compose.yaml" logs --tail 200 core
+docker compose -f "$HOME/.oac/core/compose.yaml" logs --timestamps init
 ```
 
+`init` 服务在初始化完成后退出。其步骤日志见[部署说明](https://github.com/MiniMax-AI/OpenAgentCore/blob/main/deploy/README.md#installation)。
+
 不要将 `docker compose config`、`docker inspect` 或原始日志粘贴到公开问题报告。
 
 ## 停止与重启 {#stop-and-restart}

services/core/cmd/oac/init.go

@@ -1,19 +1,21 @@
 package main
 
 import (
+	"context"
 	"crypto/rand"
 	"crypto/sha256"
 	"encoding/base64"
 	"encoding/hex"
 	"encoding/json"
 	"errors"
-	"fmt"
 	"io/fs"
 	"os"
 	"path/filepath"
 	"strings"
 	"syscall"
+	"time"
 
+	"github.com/MiniMax-AI/OpenAgentCore/internal/obs/log"
 	"github.com/google/uuid"
 )
 
@@ -34,10 +36,14 @@ type releaseIdentity struct {
 func initCommand() error {
 	revision := os.Getenv("OAC_REVISION")
 	if revision == "" {
-		return errors.New("OAC_REVISION is required")
+		err := errors.New("OAC_REVISION is required")
+		log.Bg().Error("Initialization failed", "step", "validate_revision", "error", err)
+		return err
 	}
 	if revision != buildRevision {
-		return errors.New("initialization image does not match the Compose release")
+		err := errors.New("initialization image does not match the Compose release")
+		log.Bg().Error("Initialization failed", "step", "validate_revision", "revision", revision, "error", err)
+		return err
 	}
 	syscall.Umask(0o077)
 	release := releaseIdentity{revision}
@@ -89,7 +95,6 @@ func readRelease(root string, release releaseIdentity) (map[string][]byte, error
 	if manifest.SourceCommit != release.revision || manifest.Platform != "linux/amd64" {
 		return nil, errors.New("release identity mismatch")
 	}
-	fmt.Println("Bundled node installation metadata verified")
 	return files, nil
 }
 
@@ -134,7 +139,26 @@ type installReceipt struct {
 	Files        map[string]string `json:"files"`
 }
 
-func initialize(root string, release releaseIdentity, fetch func() (map[string][]byte, error)) error {
+func initialize(root string, release releaseIdentity, fetch func() (map[string][]byte, error)) (err error) {
+	ctx, _ := log.StartBackgroundTrace(context.Background(), "installation.init")
+	logger := log.With("component", "oac-init", "revision", release.revision)
+	started := time.Now()
+	step, stepStarted := "prepare_directories", started
+	logger.InfoContext(ctx, "Initialization started", "data_dir", root)
+	logger.InfoContext(ctx, "Initialization step started", "step", step)
+	nextStep := func(next string) {
+		logger.InfoContext(ctx, "Initialization step completed", "step", step, "duration_ms", time.Since(stepStarted).Milliseconds())
+		step, stepStarted = next, time.Now()
+		logger.InfoContext(ctx, "Initialization step started", "step", step)
+	}
+	defer func() {
+		if err != nil {
+			logger.ErrorContext(ctx, "Initialization failed", "step", step, "duration_ms", time.Since(started).Milliseconds(), "error", err)
+			return
+		}
+		logger.InfoContext(ctx, "Initialization step completed", "step", step, "duration_ms", time.Since(stepStarted).Milliseconds())
+		logger.InfoContext(ctx, "Initialization completed", "duration_ms", time.Since(started).Milliseconds())
+	}()
 	if err := os.Chmod(root, 0o755); err != nil {
 		return err
 	}
@@ -148,6 +172,7 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 			return err
 		}
 	}
+	nextStep("acquire_lock")
 	lock, err := os.OpenFile(filepath.Join(root, "secrets", ".init.lock"), os.O_CREATE|os.O_WRONLY, 0o600)
 	if err != nil {
 		return err
@@ -156,6 +181,7 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 	if err := syscall.Flock(int(lock.Fd()), syscall.LOCK_EX); err != nil {
 		return err
 	}
+	nextStep("verify_existing_installation")
 	marker := filepath.Join(root, "installation.json")
 	if raw, err := os.ReadFile(marker); err == nil {
 		var receipt installReceipt
@@ -174,11 +200,12 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 				return errors.New("installation files changed; restore the matching data directory")
 			}
 		}
-		fmt.Println("Existing installation verified")
+		logger.InfoContext(ctx, "Existing installation verified", "file_count", len(receipt.Files))
 		return nil
 	} else if !errors.Is(err, fs.ErrNotExist) {
 		return err
 	}
+	nextStep("verify_empty_data")
 	for _, name := range []string{"database", "state"} {
 		entries, err := os.ReadDir(filepath.Join(root, name))
 		if err != nil {
@@ -188,16 +215,20 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 			return errors.New("existing data requires its original installation files")
 		}
 	}
+	nextStep("verify_bundled_metadata")
 	files, err := fetch()
 	if err != nil {
 		return err
 	}
+	logger.InfoContext(ctx, "Bundled node installation metadata verified", "file_count", len(files))
+	nextStep("publish_node_metadata")
 	prefix := "node-payload/releases/" + release.revision + "/"
 	names := []string{}
 	for _, name := range releaseMembers {
 		if err := writeOwned(filepath.Join(root, prefix+name), files[name]); err != nil {
 			return err
 		}
+		logger.InfoContext(ctx, "Node metadata file copied", "file", name)
 		names = append(names, prefix+name)
 	}
 	active, _ := json.Marshal(map[string]string{"source_commit": release.revision})
@@ -215,6 +246,7 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 	}); err != nil {
 		return err
 	}
+	nextStep("prepare_credentials")
 	generators := []struct {
 		name     string
 		generate func() string
@@ -236,8 +268,11 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 			if err := writeOwned(path, []byte(secret.generate()+"\n")); err != nil {
 				return err
 			}
+			logger.InfoContext(ctx, "Credential file generated", "file", secret.name)
 		} else if err != nil {
 			return err
+		} else {
+			logger.InfoContext(ctx, "Credential file retained", "file", secret.name)
 		}
 		names = append(names, secret.name)
 	}
@@ -250,6 +285,7 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 		return err
 	}
 	names = append(names, "secrets/core/core-key-digests.json", "node-payload/active.json")
+	nextStep("write_installation_receipt")
 	receipt := installReceipt{SourceCommit: release.revision, Files: map[string]string{}}
 	for _, name := range names {
 		if receipt.Files[name], err = fileDigest(filepath.Join(root, name)); err != nil {
@@ -260,7 +296,7 @@ func initialize(root string, release releaseIdentity, fetch func() (map[string][
 	if err := writeOwned(marker, raw); err != nil {
 		return err
 	}
-	fmt.Println("Installation initialized; print the sign-in key with: docker compose exec web oac-web core-key")
+	logger.InfoContext(ctx, "Installation initialized", "sign_in_key_command", "docker compose exec web oac-web core-key")
 	return nil
 }
 

services/core/cmd/oac/init_test.go

@@ -6,13 +6,16 @@ import (
 	"encoding/base64"
 	"encoding/hex"
 	"encoding/json"
+	"errors"
 	"io/fs"
+	"log/slog"
 	"maps"
 	"os"
 	"path/filepath"
 	"strings"
 	"testing"
 
+	"github.com/MiniMax-AI/OpenAgentCore/internal/obs/log"
 	"github.com/google/uuid"
 )
 
@@ -202,3 +205,99 @@ func TestInitRejectsMismatchedImageBeforeTouchingData(t *testing.T) {
 		t.Fatalf("err = %v", err)
 	}
 }
+
+func captureInitLogs(t *testing.T) *bytes.Buffer {
+	t.Helper()
+	var output bytes.Buffer
+	previous := slog.Default()
+	slog.SetDefault(slog.New(log.NewContextHandler(slog.NewJSONHandler(&output, nil))))
+	t.Cleanup(func() { slog.SetDefault(previous) })
+	return &output
+}
+
+func TestInitializationLogsLifecycleWithoutCredentials(t *testing.T) {
+	root, release, files := initFixture(t)
+	output := captureInitLogs(t)
+	if err := initialize(root, release, fixed(files)); err != nil {
+		t.Fatal(err)
+	}
+	for _, message := range []string{"Initialization started", "Node metadata file copied", "Credential file generated", "Installation initialized", "Initialization completed"} {
+		if !strings.Contains(output.String(), message) {
+			t.Fatalf("missing %s", message)
+		}
+	}
+	var traceID string
+	for _, line := range strings.Split(strings.TrimSpace(output.String()), "\n") {
+		var entry map[string]any
+		if err := json.Unmarshal([]byte(line), &entry); err != nil {
+			t.Fatal(err)
+		}
+		if entry["component"] != "oac-init" || entry["revision"] != release.revision {
+			t.Fatalf("missing initialization identity: %v", entry)
+		}
+		trace, ok := entry["trace_id"].(string)
+		if !ok || trace == "" {
+			t.Fatal("missing trace ID")
+		}
+		if traceID == "" {
+			traceID = trace
+		}
+		if traceID != trace {
+			t.Fatal("initialization logs have different trace IDs")
+		}
+		if duration, ok := entry["duration_ms"].(float64); ok && duration < 0 {
+			t.Fatal("negative duration")
+		}
+	}
+	for _, name := range []string{"secrets/web/core.key", "secrets/database/password", "secrets/core/credential.key", "secrets/core/core-key-digests.json"} {
+		data, err := os.ReadFile(filepath.Join(root, name))
+		if err != nil {
+			t.Fatal(err)
+		}
+		for _, value := range []string{strings.TrimSpace(string(data)), keyDigest(strings.TrimSpace(string(data)))} {
+			if strings.Contains(output.String(), value) {
+				t.Fatalf("credential or digest leaked from %s", name)
+			}
+		}
+	}
+	output.Reset()
+	if err := initialize(root, release, refuseDownload(t)); err != nil {
+		t.Fatal(err)
+	}
+	if !strings.Contains(output.String(), "Existing installation verified") || strings.Contains(output.String(), "Credential file generated") {
+		t.Fatal("restart logs do not describe verification only")
+	}
+	output.Reset()
+	if err := os.Remove(filepath.Join(root, "installation.json")); err != nil {
+		t.Fatal(err)
+	}
+	if err := initialize(root, release, fixed(files)); err != nil {
+		t.Fatal(err)
+	}
+	if !strings.Contains(output.String(), "Credential file retained") || strings.Contains(output.String(), "Credential file generated") {
+		t.Fatal("interrupted initialization logs do not describe credential reuse")
+	}
+}
+
+func TestInitializationLogsFailureStep(t *testing.T) {
+	root, release, _ := initFixture(t)
+	output := captureInitLogs(t)
+	failure := errors.New("invalid bundled metadata")
+	if err := initialize(root, release, func() (map[string][]byte, error) { return nil, failure }); !errors.Is(err, failure) {
+		t.Fatalf("err = %v", err)
+	}
+	lines := strings.Split(strings.TrimSpace(output.String()), "\n")
+	var entry map[string]any
+	if err := json.Unmarshal([]byte(lines[len(lines)-1]), &entry); err != nil {
+		t.Fatal(err)
+	}
+	if entry["level"] != "ERROR" || entry["step"] != "verify_bundled_metadata" || entry["error"] != failure.Error() {
+		t.Fatalf("failure log = %v", entry)
+	}
+	if _, ok := entry["duration_ms"]; !ok {
+		t.Fatal("failure duration missing")
+	}
+	if strings.Contains(output.String(), "Initialization completed") || strings.Contains(output.String(), "Credential file generated") {
+		t.Fatal("failure logged success or generated credentials")
+	}
+}

services/core/cmd/oac/main.go

@@ -13,17 +13,24 @@ import (
 	"path/filepath"
 	"strings"
 	"syscall"
+
+	"github.com/MiniMax-AI/OpenAgentCore/internal/obs/log"
 )
 
 func main() {
 	if len(os.Args) < 2 {
 		usage()
 		os.Exit(2)
 	}
+	if os.Args[1] == "init" {
+		log.Init(log.ConfigFromEnv())
+	}
 	ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
 	defer stop()
 	if err := run(ctx, os.Args[1], os.Args[2:]); err != nil {
-		fmt.Fprintln(os.Stderr, err.Error())
+		if os.Args[1] != "init" {
+			fmt.Fprintln(os.Stderr, err.Error())
+		}
 		os.Exit(1)
 	}
 }