Improve startup diagnostics

deploy/README.md

@@ -9,7 +9,7 @@
 
 ## Installation
 
-`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.
+`install.sh` downloads its release's `compose.yaml`, checks it against `compose-sha256sums.txt`, writes `.env`, and starts Compose. Installation commands stream their progress and report elapsed time; [startup diagnostics](../docs/getting-started/operations.md#startup-diagnostics) describes service logs. 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.
 

deploy/compose/compose.yaml

@@ -11,6 +11,9 @@ services:
     command: [/usr/local/bin/oac, init]
     environment:
       OAC_REVISION: __OAC_REVISION__
+      OAC_LOG_LEVEL: ${OAC_LOG_LEVEL:-}
+      OAC_LOG_FORMAT: ${OAC_LOG_FORMAT:-}
+      OAC_LOG_ADD_SOURCE: ${OAC_LOG_ADD_SOURCE:-}
     volumes:
       - type: bind
         source: ${OAC_DATA_DIR:-./data}

deploy/install.sh

@@ -73,7 +73,6 @@ if [[ "$version" != latest ]]; then
   asset_base="https://github.com/${repository}/releases/download/${version}"
 fi
 
-log="$(mktemp)"
 cleanup() {
   if [[ "$kept" != 1 && -d "$install_dir" ]]; then
     (
@@ -82,18 +81,23 @@ cleanup() {
       docker compose down --remove-orphans
       # Containers own data/; remove it from a container as well.
       if [[ -d data ]]; then docker compose run --rm --no-deps --volume "$install_dir/data:/data" --entrypoint find database /data -mindepth 1 -delete; fi
-    ) >/dev/null 2>&1 || true
+    ) || true
     rm -rf "$install_dir"
   fi
-  rm -f "$log"
 }
 trap cleanup EXIT
 
-# step DESCRIPTION COMMAND... prints the command's output only when it fails.
+# step DESCRIPTION COMMAND... streams progress and reports elapsed time.
 step() {
-  printf '%s... ' "$1"
+  local description="$1" step_started="$SECONDS"
+  printf '%s...\n' "$description"
   shift
-  if "$@" >"$log" 2>&1; then echo done; else echo failed; cat "$log" >&2; return 1; fi
+  if "$@"; then
+    printf '%s completed (%ss).\n' "$description" "$((SECONDS - step_started))"
+  else
+    printf '%s failed (%ss).\n' "$description" "$((SECONDS - step_started))" >&2
+    return 1
+  fi
 }
 
 # The source address of this host's default route, when it is a private one.
@@ -131,7 +135,6 @@ step "Starting services" docker compose up -d --wait
 key="$(./oac core-key --show)"
 kept=1
 trap - EXIT
-rm -f "$log"
 
 sudo=""
 if [[ "$EUID" == 0 && -n "${SUDO_USER:-}" ]]; then sudo="sudo "; fi

deploy/test_install.py

@@ -22,7 +22,7 @@ def install(self, root, *args, compose_up=0, route="1.1.1.1 via 10.0.0.1 dev eth
             printf '%s\\n' "$*" >> {log}
             if [ "$1" = compose ] && [ "$2" = version ]; then printf 'v2.29.1\\n'; exit 0; fi
             if [ "$1" = compose ] && [ "$2" = cp ]; then printf '#!/bin/sh\\necho oac_core_fixture\\n' > ./oac; chmod +x ./oac; exit 0; fi
-            if [ "$1" = compose ] && [ "$2" = up ]; then exit {compose_up}; fi
+            if [ "$1" = compose ] && [ "$2" = up ]; then printf 'fixture startup progress\\n'; exit {compose_up}; fi
             exit 0
             """))
         self.write_executable(bin_dir / "curl", textwrap.dedent("""\
@@ -61,6 +61,8 @@ def test_the_private_address_is_the_default_public_url(self):
             self.assertIn("OAC_PUBLIC_URL=http://10.0.0.5:8080\n", (root / "oac/.env").read_text())
             self.assertIn("Console   http://10.0.0.5:8080", completed.stdout)
             self.assertIn("Core key  oac_core_fixture", completed.stdout)
+            self.assertIn("fixture startup progress", completed.stdout)
+            self.assertIn("Starting services completed (", completed.stdout)
             self.assertNotIn("Only this host", completed.stdout)
 
     def test_without_a_private_address_only_this_host_reaches_web(self):

docs/getting-started/operations.md

@@ -40,11 +40,27 @@ 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 --tail 200 init database core
 ```
 
 Don't paste `docker compose config`, `docker inspect` or raw logs into public issue reports.
 
+### Startup diagnostics
+
+At the default `info` level, initialization and Core log `Stage started`, `Stage completed` and `Stage failed` with `component`, `stage` and completion `elapsed_ms`. Initialization stages cover directories, the installation lock, existing data checks, metadata verification/publication, secrets and the installation receipt. Core stages cover configuration, database migrations/connection, services, Runtime setup, the execution worker and the HTTP listener. `Core HTTP listener ready` means its socket is bound; a failure in `running` occurs after startup. A normal signal starts `shutdown`.
+
+Configuration validation also identifies the setting and an authored reason without repeating its value. Failures report typed `error_kind` facts without arbitrary error text. Filesystem failures include `operation`, `path` and numeric `errno`; database errors can include `sqlstate`. File contents, credentials and database connection strings are excluded. `unclassified` means no supported typed cause was available; use the stage and adjacent service logs to investigate.
+
+| `error_kind` | Check |
+| --- | --- |
+| `not_found`, `permission_denied` | The named file, its mount source, ownership and permissions |
+| `connection_refused`, `connection_reset` | The dependency's container status and logs |
+| `timeout`, `canceled` | Dependency availability, elapsed time and shutdown events |
+| `unexpected_eof`, `eof` | The stage and dependency logs; an interrupted stream alone does not identify its cause |
+| `database_error` | PostgreSQL logs and the reported `sqlstate` |
+
+The host installer streams command progress and reports each step's elapsed seconds, including failures. For file preparation details, set `OAC_LOG_LEVEL=debug` and follow [process settings](../configuration.md#process-settings-configjson). Initialization diagnostics are emitted when its container runs; an already completed one-time container does not run again merely because Core restarts.
+
 ## Stop and restart
 
 Let active work settle before a planned restart:

docs/zh/getting-started/operations.md

@@ -1,7 +1,7 @@
 ---
 title: "管理你的安装"
 source: docs/getting-started/operations.md
-source_hash: e60a6e96cd61692b6adc7664874ba0ed2ce489982e7da2fe2347631ee2a94c0a
+source_hash: 3158dbf2ec3254f22fe832cd1113b23137eb2f487fb6c04b828d73e40945cf68
 ---
 
 安装运维人员负责 Core 主机、存储和可用性。节点主机运行各自的服务；参阅[节点](nodes.md)。设置见[配置参考](../configuration.md)。
@@ -42,11 +42,27 @@ 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 --tail 200 init database core
 ```
 
 不要将 `docker compose config`、`docker inspect` 或原始日志粘贴到公开问题报告。
 
+### 启动诊断 {#startup-diagnostics}
+
+在默认 `info` 级别下，初始化和 Core 会记录 `Stage started`、`Stage completed` 与 `Stage failed`，包含 `component`、`stage` 以及完成时的 `elapsed_ms`。初始化阶段覆盖目录、安装锁、已有数据检查、元数据验证与发布、机密信息以及安装记录。Core 阶段覆盖配置、数据库迁移与连接、服务、Runtime 配置、执行工作线程以及 HTTP 监听器。`Core HTTP listener ready` 表示套接字已绑定；`running` 阶段的失败发生在启动完成后。正常信号会开始 `shutdown`。
+
+配置校验还会指出配置项和明确的原因，不重复其值。失败日志通过类型化的 `error_kind` 描述原因，不输出任意错误文本。文件系统失败包含 `operation`、`path` 和数字 `errno`；数据库错误可包含 `sqlstate`。日志不包含文件内容、凭据或数据库连接字符串。`unclassified` 表示没有可识别的类型化原因；结合阶段及相邻服务日志排查。
+
+| `error_kind` | 检查内容 |
+| --- | --- |
+| `not_found`、`permission_denied` | 指定文件、挂载来源、所有者与权限 |
+| `connection_refused`、`connection_reset` | 依赖服务的容器状态和日志 |
+| `timeout`、`canceled` | 依赖服务可用性、耗时和停止事件 |
+| `unexpected_eof`、`eof` | 阶段和依赖服务日志；流被中断本身不能确定原因 |
+| `database_error` | PostgreSQL 日志及记录的 `sqlstate` |
+
+宿主机安装器实时显示命令进度，并记录每一步的耗时秒数，包括失败步骤。要查看文件准备细节，设置 `OAC_LOG_LEVEL=debug` 并遵循[进程设置](../configuration.md#process-settings-configjson)。初始化诊断在其容器运行时输出；已经完成的一次性容器不会仅因 Core 重启而再次运行。
+
 ## 停止与重启 {#stop-and-restart}
 
 计划重启前，先等待活动工作结束：

internal/obs/log/stage.go

@@ -0,0 +1,77 @@
+package log
+
+import (
+	"context"
+	"errors"
+	"io"
+	"io/fs"
+	"net"
+	"os"
+	"syscall"
+	"time"
+)
+
+// StartStage reports progress without logging operation inputs or error text.
+// Call the returned function once with the stage's result.
+func StartStage(stage string, fields ...any) func(error) {
+	logger := With(fields...).With("stage", stage)
+	started := time.Now()
+	logger.Info("Stage started")
+	return func(err error) {
+		elapsed := time.Since(started).Milliseconds()
+		if err != nil {
+			logger.Error("Stage failed", append([]any{"elapsed_ms", elapsed}, ErrorFields(err)...)...)
+		} else {
+			logger.Info("Stage completed", "elapsed_ms", elapsed)
+		}
+	}
+}
+
+// ErrorFields preserves typed diagnostic facts, never arbitrary error messages.
+func ErrorFields(err error) []any {
+	kind := "unclassified"
+	switch {
+	case errors.Is(err, context.Canceled):
+		kind = "canceled"
+	case errors.Is(err, context.DeadlineExceeded):
+		kind = "timeout"
+	case errors.Is(err, fs.ErrNotExist):
+		kind = "not_found"
+	case errors.Is(err, fs.ErrPermission):
+		kind = "permission_denied"
+	case errors.Is(err, syscall.ECONNREFUSED):
+		kind = "connection_refused"
+	case errors.Is(err, syscall.ECONNRESET):
+		kind = "connection_reset"
+	case errors.Is(err, io.ErrUnexpectedEOF):
+		kind = "unexpected_eof"
+	case errors.Is(err, io.EOF):
+		kind = "eof"
+	}
+	var timeout net.Error
+	if kind == "unclassified" && errors.As(err, &timeout) && timeout.Timeout() {
+		kind = "timeout"
+	}
+	fields := []any{"error_kind", kind}
+	var path *os.PathError
+	if errors.As(err, &path) {
+		fields = append(fields, "operation", path.Op, "path", path.Path)
+	}
+	var errno syscall.Errno
+	if errors.As(err, &errno) {
+		fields = append(fields, "errno", int(errno))
+	}
+	var sql interface{ SQLState() string }
+	if errors.As(err, &sql) {
+		state := sql.SQLState()
+		valid := len(state) == 5
+		for _, c := range state {
+			valid = valid && (c >= '0' && c <= '9' || c >= 'A' && c <= 'Z')
+		}
+		if valid {
+			fields[1] = "database_error"
+			fields = append(fields, "sqlstate", state)
+		}
+	}
+	return fields
+}

internal/obs/log/stage_test.go

@@ -0,0 +1,67 @@
+package log
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"io"
+	"log/slog"
+	"os"
+	"strings"
+	"syscall"
+	"testing"
+)
+
+type databaseFailure struct{ state string }
+
+func (e databaseFailure) Error() string    { return "private database credentials" }
+func (e databaseFailure) SQLState() string { return e.state }
+
+func TestStageFailureReportsTypedFactsWithoutErrorText(t *testing.T) {
+	cases := []struct {
+		name string
+		err  error
+		kind string
+	}{
+		{"permission", &os.PathError{Op: "open", Path: "/run/oac/installation.id", Err: syscall.EACCES}, "permission_denied"},
+		{"missing", fmt.Errorf("private credentials: %w", os.ErrNotExist), "not_found"},
+		{"refused", fmt.Errorf("private credentials: %w", syscall.ECONNREFUSED), "connection_refused"},
+		{"truncated", io.ErrUnexpectedEOF, "unexpected_eof"},
+		{"timeout", context.DeadlineExceeded, "timeout"},
+		{"database", databaseFailure{"40P01"}, "database_error"},
+		{"unknown", errors.New("private credentials"), "unclassified"},
+		{"invalid SQL state", databaseFailure{"private credentials"}, "unclassified"},
+	}
+	for _, tc := range cases {
+		t.Run(tc.name, func(t *testing.T) {
+			var output bytes.Buffer
+			previous := slog.Default()
+			slog.SetDefault(buildLogger(Config{Out: &output, Format: "json"}))
+			defer slog.SetDefault(previous)
+			finish := StartStage("database_connection", "component", "core")
+			finish(tc.err)
+			if strings.Contains(output.String(), "private") {
+				t.Fatalf("error text leaked: %s", output.String())
+			}
+			lines := strings.Split(strings.TrimSpace(output.String()), "\n")
+			if len(lines) != 2 {
+				t.Fatalf("logs = %s", output.String())
+			}
+			var event map[string]any
+			if err := json.Unmarshal([]byte(lines[1]), &event); err != nil {
+				t.Fatal(err)
+			}
+			if event["msg"] != "Stage failed" || event["stage"] != "database_connection" || event["error_kind"] != tc.kind || event["elapsed_ms"] == nil {
+				t.Fatalf("event = %v", event)
+			}
+			if tc.name == "permission" && (event["path"] != "/run/oac/installation.id" || event["operation"] != "open") {
+				t.Fatalf("path facts = %v", event)
+			}
+			if tc.name == "database" && event["sqlstate"] != "40P01" {
+				t.Fatalf("SQL state = %v", event)
+			}
+		})
+	}
+}

scripts/compose-smoke.py

@@ -114,7 +114,7 @@ def main():
 
     override.write_text(json.dumps({'services': {'init': {'network_mode': 'none'}}}))
     env = {**os.environ, 'COMPOSE_PROGRESS': 'plain', 'OAC_DATA_DIR': str(data),
-           'OAC_HOST': '127.0.0.1', 'OAC_WEB_PORT': '0',
+           'OAC_HOST': '127.0.0.1', 'OAC_WEB_PORT': '0', 'OAC_LOG_LEVEL': 'info', 'OAC_LOG_FORMAT': 'json',
            **{'OAC_IMAGE_' + name.upper(): image for name, image in images.items()}}
     env.pop('OAC_PUBLIC_URL', None)
     command = ['docker', 'compose', '--env-file', os.devnull, '-p', project,
@@ -193,7 +193,9 @@ def terminate(_signum, _frame):
                 'Content-Type: text/plain\r\n\r\n').encode() + content + f'\r\n--{boundary}--\r\n'.encode()
         uploaded = get('/v1/files', body=body, headers={**api, 'Content-Type': 'multipart/form-data; boundary=' + boundary})
         assert uploaded['bytes'] == len(content), 'Upload was truncated'
-        private_logs(key, project_key)
+        initial_logs = private_logs(key, project_key)
+        assert '"stage":"metadata_verification"' in initial_logs, 'Initialization progress is missing'
+        assert '"msg":"Core HTTP listener ready"' in initial_logs, 'Core readiness diagnostic is missing'
 
         print('Configuring a reachable URL and recreating containers with the same data directory', flush=True)
         # Retain the assigned port across recreation, without claiming a fixed host port.
@@ -211,7 +213,13 @@ def terminate(_signum, _frame):
         assert updated['public_url'] == origin, 'The new public URL did not take effect'
         assert any(p['id'] == project_data['id'] for p in get('/core/v1/projects')['data']), 'Project was lost'
         assert get('/v1/files/' + uploaded['id'], headers=api)['bytes'] == len(content), 'Uploaded file metadata was lost'
-        assert 'Bundled node installation metadata verified' not in private_logs(key, project_key), 'Completed initialization recopied metadata'
+        assert '"stage":"metadata_verification"' not in private_logs(key, project_key), 'Completed initialization recopied metadata'
+        compose('stop', 'core')
+        stopped_logs = private_logs(key, project_key)
+        assert any(
+            '"msg":"Stage completed"' in line and '"stage":"shutdown"' in line for line in stopped_logs.splitlines()
+        ), 'Normal stop did not complete the shutdown stage'
+        assert not any('"msg":"Stage failed"' in line and '"stage":"running"' in line for line in stopped_logs.splitlines()), 'Normal stop was reported as a runtime failure'
         print('PASS: startup, origin validation, sign-in, API, upload, node installer and persistent installation', flush=True)
     except BaseException:
         # Service status identifies failed containers without dumping secret-bearing logs.