feat: enhance logging for agent registration, heartbeat, and configuration sync processes

atsf_agent/cmd/agent/main.go

@@ -24,6 +24,7 @@ func main() {
 	if err != nil {
 		log.Fatal(err)
 	}
+	log.Printf("agent config loaded: server=%s node=%s ip=%s heartbeat_interval=%s sync_interval=%s route_config=%s cert_dir=%s", cfg.ServerURL, cfg.NodeName, cfg.NodeIP, cfg.HeartbeatInterval, cfg.SyncInterval, cfg.RouteConfigPath, cfg.CertDir)
 
 	client := httpclient.New(cfg.ServerURL, cfg.AgentToken, cfg.RequestTimeout)
 	stateStore := state.NewStore(cfg.StatePath)
@@ -49,8 +50,10 @@ func main() {
 
 	ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
 	defer stop()
+	log.Printf("agent process started")
 
 	if err = runner.Run(ctx); err != nil && err != context.Canceled {
 		log.Fatal(err)
 	}
+	log.Printf("agent process stopped")
 }

atsf_agent/internal/agent/runner.go

@@ -32,15 +32,22 @@ func (r *Runner) Run(ctx context.Context) error {
 	if err != nil {
 		return err
 	}
+	log.Printf("agent runner started: node_id=%s node=%s ip=%s", nodeID, r.Config.NodeName, r.Config.NodeIP)
 	if err = r.HeartbeatService.Register(ctx, r.nodePayload(nodeID)); err != nil {
 		log.Printf("agent register failed: %v", err)
+	} else {
+		log.Printf("agent register succeeded: node_id=%s", nodeID)
 	}
 	if err = r.SyncService.SyncOnStartup(ctx); err != nil {
 		r.recordSyncError(err)
 		log.Printf("agent startup sync failed: %v", err)
+	} else {
+		log.Printf("agent startup sync completed")
 	}
 	if err = r.HeartbeatService.Heartbeat(ctx, r.nodePayload(nodeID)); err != nil {
 		log.Printf("agent startup heartbeat failed: %v", err)
+	} else {
+		log.Printf("agent startup heartbeat succeeded: node_id=%s", nodeID)
 	}
 
 	heartbeatTicker := time.NewTicker(r.Config.HeartbeatInterval)
@@ -51,15 +58,19 @@ func (r *Runner) Run(ctx context.Context) error {
 	for {
 		select {
 		case <-ctx.Done():
+			log.Printf("agent runner shutting down: %v", ctx.Err())
 			return ctx.Err()
 		case <-heartbeatTicker.C:
 			if err = r.HeartbeatService.Heartbeat(ctx, r.nodePayload(nodeID)); err != nil {
 				log.Printf("agent heartbeat failed: %v", err)
 			}
 		case <-syncTicker.C:
+			log.Printf("agent sync tick: node_id=%s", nodeID)
 			if err = r.SyncService.SyncOnce(ctx); err != nil {
 				r.recordSyncError(err)
 				log.Printf("agent sync failed: %v", err)
+			} else {
+				log.Printf("agent sync completed")
 			}
 		}
 	}
@@ -75,6 +86,7 @@ func (r *Runner) recordSyncError(err error) {
 		return
 	}
 	snapshot.LastError = err.Error()
+	log.Printf("recording sync error into state: %s", snapshot.LastError)
 	if saveErr := r.StateStore.Save(snapshot); saveErr != nil {
 		log.Printf("save state after sync error failed: %v", saveErr)
 	}

atsf_agent/internal/httpclient/client.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"log"
 	"net/http"
 	"strings"
 	"time"
@@ -29,6 +30,7 @@ func New(baseURL string, token string, timeout time.Duration) *Client {
 }
 
 func (c *Client) RegisterNode(ctx context.Context, payload protocol.NodePayload) error {
+	log.Printf("http register node request: node_id=%s current_version=%s", payload.NodeID, payload.CurrentVersion)
 	return c.postJSON(ctx, "/api/agent/nodes/register", payload, nil)
 }
 
@@ -37,6 +39,7 @@ func (c *Client) Heartbeat(ctx context.Context, payload protocol.NodePayload) er
 }
 
 func (c *Client) GetActiveConfig(ctx context.Context) (*protocol.ActiveConfigResponse, error) {
+	log.Printf("http get active config request")
 	resp := protocol.APIResponse[protocol.ActiveConfigResponse]{}
 	if err := c.getJSON(ctx, "/api/agent/config-versions/active", &resp); err != nil {
 		return nil, err
@@ -44,10 +47,12 @@ func (c *Client) GetActiveConfig(ctx context.Context) (*protocol.ActiveConfigRes
 	if !resp.Success {
 		return nil, errors.New(resp.Message)
 	}
+	log.Printf("http get active config response: version=%s checksum=%s support_files=%d", resp.Data.Version, resp.Data.Checksum, len(resp.Data.SupportFiles))
 	return &resp.Data, nil
 }
 
 func (c *Client) ReportApplyLog(ctx context.Context, payload protocol.ApplyLogPayload) error {
+	log.Printf("http report apply log request: node_id=%s version=%s result=%s", payload.NodeID, payload.Version, payload.Result)
 	return c.postJSON(ctx, "/api/agent/apply-logs", payload, nil)
 }
 
@@ -75,23 +80,47 @@ func (c *Client) postJSON(ctx context.Context, path string, body any, target any
 }
 
 func (c *Client) do(req *http.Request, target any) error {
+	if !isHeartbeatRequest(req) {
+		log.Printf("http request start: method=%s path=%s", req.Method, req.URL.Path)
+	}
 	res, err := c.httpClient.Do(req)
 	if err != nil {
+		log.Printf("http request failed: method=%s path=%s error=%v", req.Method, req.URL.Path, err)
 		return err
 	}
 	defer res.Body.Close()
 	if res.StatusCode != http.StatusOK {
+		log.Printf("http request returned non-200: method=%s path=%s status=%s", req.Method, req.URL.Path, res.Status)
 		return errors.New(res.Status)
 	}
 	if target == nil {
 		var wrapper protocol.APIResponse[json.RawMessage]
 		if err = json.NewDecoder(res.Body).Decode(&wrapper); err != nil {
+			log.Printf("http response decode failed: method=%s path=%s error=%v", req.Method, req.URL.Path, err)
 			return err
 		}
 		if !wrapper.Success {
+			log.Printf("http api response failed: method=%s path=%s message=%s", req.Method, req.URL.Path, wrapper.Message)
 			return errors.New(wrapper.Message)
 		}
+		if !isHeartbeatRequest(req) {
+			log.Printf("http request succeeded: method=%s path=%s", req.Method, req.URL.Path)
+		}
 		return nil
 	}
-	return json.NewDecoder(res.Body).Decode(target)
+	if err = json.NewDecoder(res.Body).Decode(target); err != nil {
+		log.Printf("http response decode failed: method=%s path=%s error=%v", req.Method, req.URL.Path, err)
+		return err
+	}
+	if !isHeartbeatRequest(req) {
+		log.Printf("http request succeeded: method=%s path=%s", req.Method, req.URL.Path)
+	}
+	return nil
+}
+
+func isHeartbeatRequest(req *http.Request) bool {
+	if req == nil || req.URL == nil {
+		return false
+	}
+	return req.Method == http.MethodPost && req.URL.Path == "/api/agent/nodes/heartbeat"
 }

atsf_agent/internal/nginx/manager.go

@@ -6,6 +6,7 @@ import (
 	"encoding/hex"
 	"errors"
 	"fmt"
+	"log"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -41,18 +42,22 @@ type PathExecutor struct {
 }
 
 func (e *PathExecutor) Test(ctx context.Context) error {
+	log.Printf("running nginx test with binary: %s", e.Path)
 	output, err := e.Runner.Run(ctx, e.Path, "-t")
 	if err != nil {
 		return fmt.Errorf("nginx -t failed: %w: %s", err, string(output))
 	}
+	log.Printf("nginx test succeeded with binary: %s", e.Path)
 	return nil
 }
 
 func (e *PathExecutor) Reload(ctx context.Context) error {
+	log.Printf("running nginx reload with binary: %s", e.Path)
 	output, err := e.Runner.Run(ctx, e.Path, "-s", "reload")
 	if err != nil {
 		return fmt.Errorf("nginx reload failed: %w: %s", err, string(output))
 	}
+	log.Printf("nginx reload succeeded with binary: %s", e.Path)
 	return nil
 }
 
@@ -71,6 +76,7 @@ type DockerExecutor struct {
 }
 
 func (e *DockerExecutor) Test(ctx context.Context) error {
+	log.Printf("running docker nginx test: container=%s image=%s", e.ContainerName, e.Image)
 	output, err := e.Runner.Run(
 		ctx,
 		e.DockerBinary,
@@ -87,6 +93,7 @@ func (e *DockerExecutor) Test(ctx context.Context) error {
 	if err != nil {
 		return fmt.Errorf("docker nginx -t failed: %w: %s", err, string(output))
 	}
+	log.Printf("docker nginx test succeeded: container=%s", e.ContainerName)
 	return nil
 }
 
@@ -95,6 +102,7 @@ func (e *DockerExecutor) Reload(ctx context.Context) error {
 }
 
 func (e *DockerExecutor) EnsureRuntime(ctx context.Context, recreate bool) error {
+	log.Printf("ensuring docker nginx runtime: container=%s recreate=%t", e.ContainerName, recreate)
 	output, err := e.Runner.Run(ctx, e.DockerBinary, "inspect", "-f", "{{.State.Running}}", e.ContainerName)
 	if err == nil {
 		if recreate {
@@ -104,6 +112,7 @@ func (e *DockerExecutor) EnsureRuntime(ctx context.Context, recreate bool) error
 			return e.runContainer(ctx)
 		}
 		if strings.TrimSpace(string(output)) == "true" {
+			log.Printf("docker nginx runtime already healthy: container=%s", e.ContainerName)
 			return nil
 		}
 		if err := e.removeContainer(ctx); err != nil {
@@ -115,6 +124,7 @@ func (e *DockerExecutor) EnsureRuntime(ctx context.Context, recreate bool) error
 }
 
 func (e *DockerExecutor) removeContainer(ctx context.Context) error {
+	log.Printf("removing docker nginx container: container=%s", e.ContainerName)
 	output, err := e.Runner.Run(ctx, e.DockerBinary, "rm", "-f", e.ContainerName)
 	if err != nil {
 		text := string(output)
@@ -123,10 +133,12 @@ func (e *DockerExecutor) removeContainer(ctx context.Context) error {
 		}
 		return fmt.Errorf("docker rm nginx failed: %w: %s", err, text)
 	}
+	log.Printf("docker nginx container removed: container=%s", e.ContainerName)
 	return nil
 }
 
 func (e *DockerExecutor) runContainer(ctx context.Context) error {
+	log.Printf("starting docker nginx container: container=%s image=%s", e.ContainerName, e.Image)
 	runArgs := []string{
 		"run", "-d",
 		"--name", e.ContainerName,
@@ -140,6 +152,7 @@ func (e *DockerExecutor) runContainer(ctx context.Context) error {
 	if runErr != nil {
 		return fmt.Errorf("docker run nginx failed: %w: %s", runErr, string(runOutput))
 	}
+	log.Printf("docker nginx container started: container=%s", e.ContainerName)
 	return nil
 }
 
@@ -151,27 +164,33 @@ type Manager struct {
 }
 
 func (m *Manager) Apply(ctx context.Context, content string, supportFiles []protocol.SupportFile) error {
+	log.Printf("nginx apply started: route_config=%s support_files=%d", m.RouteConfigPath, len(supportFiles))
 	backup, err := m.backup()
 	if err != nil {
 		return err
 	}
 	if err = m.writeSupportFiles(supportFiles); err != nil {
+		log.Printf("writing support files failed, restoring backup: error=%v", err)
 		_ = m.restore(backup)
 		return err
 	}
 	renderedContent := m.renderConfig(content)
 	if err = os.WriteFile(m.RouteConfigPath, []byte(renderedContent), 0o644); err != nil {
+		log.Printf("writing nginx route config failed, restoring backup: error=%v", err)
 		_ = m.restore(backup)
 		return err
 	}
 	if err = m.Executor.Test(ctx); err != nil {
+		log.Printf("nginx test failed after config write, restoring backup: error=%v", err)
 		_ = m.restore(backup)
 		return err
 	}
 	if err = m.Executor.Reload(ctx); err != nil {
+		log.Printf("nginx reload failed after config write, restoring backup: error=%v", err)
 		_ = m.restore(backup)
 		return err
 	}
+	log.Printf("nginx apply completed successfully: route_config=%s", m.RouteConfigPath)
 	return nil
 }
 
@@ -179,6 +198,7 @@ func (m *Manager) EnsureRuntime(ctx context.Context, recreate bool) error {
 	if m.Executor == nil {
 		return errors.New("executor 未配置")
 	}
+	log.Printf("nginx ensure runtime requested: recreate=%t", recreate)
 	return m.Executor.EnsureRuntime(ctx, recreate)
 }
 
@@ -201,7 +221,9 @@ func (m *Manager) CurrentChecksum() (string, error) {
 	if err != nil {
 		return "", err
 	}
-	return bundleChecksum(normalized, files), nil
+	result := bundleChecksum(normalized, files)
+	log.Printf("nginx current checksum calculated: route_config=%s checksum=%s support_files=%d", m.RouteConfigPath, result, len(files))
+	return result, nil
 }
 
 type ExecutorOptions struct {
@@ -272,6 +294,7 @@ func (m *Manager) backup() (*backupState, error) {
 		return nil, err
 	}
 	state.Files = files
+	log.Printf("nginx backup captured: route_exists=%t support_files=%d", state.RouteExisted, len(state.Files))
 	return state, nil
 }
 
@@ -279,6 +302,7 @@ func (m *Manager) restore(state *backupState) error {
 	if state == nil {
 		return nil
 	}
+	log.Printf("restoring nginx backup: route_existed=%t support_files=%d", state.RouteExisted, len(state.Files))
 	if state.RouteExisted {
 		if err := os.WriteFile(m.RouteConfigPath, state.RouteData, 0o644); err != nil {
 			return err
@@ -304,6 +328,7 @@ func (m *Manager) restore(state *backupState) error {
 			return err
 		}
 	}
+	log.Printf("nginx backup restored")
 	return nil
 }
 
@@ -311,6 +336,7 @@ func (m *Manager) writeSupportFiles(supportFiles []protocol.SupportFile) error {
 	if m.CertDir == "" {
 		return nil
 	}
+	log.Printf("writing nginx support files: cert_dir=%s count=%d", m.CertDir, len(supportFiles))
 	if err := os.RemoveAll(m.CertDir); err != nil && !os.IsNotExist(err) {
 		return err
 	}
@@ -326,6 +352,7 @@ func (m *Manager) writeSupportFiles(supportFiles []protocol.SupportFile) error {
 			return err
 		}
 	}
+	log.Printf("nginx support files written: cert_dir=%s count=%d", m.CertDir, len(supportFiles))
 	return nil
 }
 

atsf_agent/internal/sync/service.go

@@ -2,6 +2,7 @@ package sync
 
 import (
 	"context"
+	"log"
 
 	"atsflare-agent/internal/protocol"
 	"atsflare-agent/internal/state"
@@ -46,33 +47,48 @@ func (s *Service) SyncOnStartup(ctx context.Context) error {
 }
 
 func (s *Service) sync(ctx context.Context, startup bool) error {
+	mode := "periodic"
+	if startup {
+		mode = "startup"
+	}
+	log.Printf("sync started: mode=%s", mode)
 	snapshot, err := s.stateStore.Load()
 	if err != nil {
 		return err
 	}
 	config, err := s.client.GetActiveConfig(ctx)
 	if err != nil {
+		log.Printf("fetch active config failed: mode=%s error=%v", mode, err)
 		return err
 	}
+	log.Printf("active config fetched: mode=%s version=%s checksum=%s support_files=%d", mode, config.Version, config.Checksum, len(config.SupportFiles))
 	currentChecksum, err := s.nginxManager.CurrentChecksum()
 	if err != nil {
 		return err
 	}
+	log.Printf("current local checksum loaded: mode=%s checksum=%s", mode, currentChecksum)
 	if currentChecksum == config.Checksum {
+		log.Printf("local nginx config already up to date: mode=%s version=%s", mode, config.Version)
 		if startup {
+			log.Printf("ensuring nginx runtime on startup: version=%s", config.Version)
 			if err = s.nginxManager.EnsureRuntime(ctx, true); err != nil {
 				return err
 			}
+			log.Printf("nginx runtime ensured on startup: version=%s", config.Version)
 		}
 		snapshot.CurrentVersion = config.Version
 		snapshot.CurrentChecksum = config.Checksum
 		snapshot.LastError = ""
+		log.Printf("sync finished without changes: mode=%s version=%s", mode, config.Version)
 		return s.stateStore.Save(snapshot)
 	}
 	if snapshot.CurrentVersion == config.Version && snapshot.CurrentChecksum == config.Checksum && !startup {
+		log.Printf("skipping apply because state already records target version/checksum: version=%s checksum=%s", config.Version, config.Checksum)
 		return nil
 	}
+	log.Printf("applying new nginx config: mode=%s from_version=%s to_version=%s old_checksum=%s new_checksum=%s", mode, snapshot.CurrentVersion, config.Version, currentChecksum, config.Checksum)
 	if err = s.nginxManager.Apply(ctx, config.RenderedConfig, config.SupportFiles); err != nil {
+		log.Printf("apply nginx config failed: mode=%s version=%s error=%v", mode, config.Version, err)
 		snapshot.LastError = err.Error()
 		_ = s.stateStore.Save(snapshot)
 		reportErr := s.client.ReportApplyLog(ctx, protocol.ApplyLogPayload{
@@ -82,20 +98,28 @@ func (s *Service) sync(ctx context.Context, startup bool) error {
 			Message: err.Error(),
 		})
 		if reportErr != nil {
+			log.Printf("report failed apply log failed: version=%s error=%v", config.Version, reportErr)
 			return reportErr
 		}
+		log.Printf("failed apply log reported: version=%s", config.Version)
 		return err
 	}
+	log.Printf("nginx config applied successfully: mode=%s version=%s", mode, config.Version)
 	snapshot.CurrentVersion = config.Version
 	snapshot.CurrentChecksum = config.Checksum
 	snapshot.LastError = ""
 	if err = s.stateStore.Save(snapshot); err != nil {
 		return err
 	}
-	return s.client.ReportApplyLog(ctx, protocol.ApplyLogPayload{
+	if err = s.client.ReportApplyLog(ctx, protocol.ApplyLogPayload{
 		NodeID:  snapshot.NodeID,
 		Version: config.Version,
 		Result:  ApplyResultSuccess,
 		Message: "apply success",
-	})
+	}); err != nil {
+		log.Printf("report successful apply log failed: version=%s error=%v", config.Version, err)
+		return err
+	}
+	log.Printf("successful apply log reported: version=%s", config.Version)
+	return nil
 }