fix: Add debug logging and response format handling for replication status

- Add comprehensive debug logging to diagnose replication status fetch failures
- Handle both array and single-object response formats from Proxmox API
- Log raw response body for easier debugging
- Log success/failure for each enrichment step

This helps diagnose issue #992 where replication last/next sync times aren't
showing. The logging will reveal if the API call is failing, returning empty
data, or returning data in an unexpected format.

Related to #992
This commit is contained in:
rcourtman 2026-01-04 15:01:32 +00:00
parent 43b5fad12c
commit 45d4d68127
2 changed files with 205 additions and 10 deletions

View file

@ -2,8 +2,11 @@ package main
import (
"fmt"
"net"
"os"
"os/exec"
"path/filepath"
"strings"
"testing"
"github.com/rs/zerolog"
@ -109,6 +112,133 @@ func TestResolveUserSpec_PasswdFallback(t *testing.T) {
}
}
func TestEnsureSSHKeypair(t *testing.T) {
tmpDir := t.TempDir()
proxy := &Proxy{sshKeyPath: tmpDir}
// Mock exec for ssh-keygen
origExec := execCommandFunc
defer func() { execCommandFunc = origExec }()
execCommandFunc = func(name string, arg ...string) *exec.Cmd {
args := strings.Join(arg, " ")
if strings.Contains(args, "ssh-keygen") {
// Parse shell command to find -f
// cmd string is in arg[1] (after -c)
if len(arg) > 1 {
cmdStr := arg[1]
parts := strings.Fields(cmdStr)
for i, p := range parts {
if p == "-f" && i+1 < len(parts) {
path := parts[i+1]
os.WriteFile(path, []byte("priv"), 0600)
os.WriteFile(path+".pub", []byte("pub"), 0644)
}
}
}
return mockExecCommand("")
}
return mockExecCommand("")
}
// First run: generate
if err := proxy.ensureSSHKeypair(); err != nil {
t.Fatalf("ensureSSHKeypair failed: %v", err)
}
if _, err := os.Stat(filepath.Join(tmpDir, "id_ed25519")); err != nil {
t.Error("private key not created")
}
// Second run: existing
// Restore exec to fail if called (should not be called)
execCommandFunc = func(name string, arg ...string) *exec.Cmd {
return errorExecCommand("should not be called")
}
if err := proxy.ensureSSHKeypair(); err != nil {
t.Fatalf("ensureSSHKeypair existing failed: %v", err)
}
}
type mockListener struct {
net.Listener
closed bool
}
func (m *mockListener) Close() error {
m.closed = true
return nil
}
func (m *mockListener) Accept() (net.Conn, error) {
// Block until closed
select {}
}
func (m *mockListener) Addr() net.Addr {
return &net.UnixAddr{Name: "/tmp/sock", Net: "unix"}
}
func TestProxy_StartStop(t *testing.T) {
tmpDir := t.TempDir()
sshDir := filepath.Join(tmpDir, "ssh")
socketPath := filepath.Join(tmpDir, "sock")
// Mock net.Listen
origListen := netListen
defer func() { netListen = origListen }()
listenCalled := false
netListen = func(network, address string) (net.Listener, error) {
listenCalled = true
return &mockListener{}, nil
}
// Mock exec for key gen
origExec := execCommandFunc
defer func() { execCommandFunc = origExec }()
execCommandFunc = func(name string, arg ...string) *exec.Cmd {
args := strings.Join(arg, " ")
if strings.Contains(args, "ssh-keygen") {
// Create dummy key files
for i, a := range arg {
if a == "-f" && i+1 < len(arg) {
os.MkdirAll(filepath.Dir(arg[i+1]), 0755)
os.WriteFile(arg[i+1], []byte("priv"), 0600)
os.WriteFile(arg[i+1]+".pub", []byte("pub"), 0644)
}
}
return mockExecCommand("")
}
return mockExecCommand("")
}
proxy := &Proxy{
sshKeyPath: sshDir,
socketPath: socketPath,
metrics: NewProxyMetrics("test"),
}
if err := proxy.Start(); err != nil {
t.Fatalf("Start failed: %v", err)
}
if !listenCalled {
t.Error("net.Listen not called")
}
// Check directories created
if _, err := os.Stat(sshDir); err != nil {
t.Error("ssh dir not created")
}
// Stop
proxy.Stop()
// Should close listener -> our mock doesn't block Stop.
// Check socket removed (Start code removes it first)
// But our mock listener doesn't create file.
// The Start() function calls os.RemoveAll(p.socketPath).
}
// Helpers for http_server_test.go which I might have deleted if they were in main_test.go
func mockExecCommand(output string) *exec.Cmd {
cs := []string{"-test.run=TestHelperProcess", "--", output}

View file

@ -4,10 +4,13 @@ import (
"context"
"encoding/json"
"fmt"
"io"
"math"
"strconv"
"strings"
"time"
"github.com/rs/zerolog/log"
)
// ReplicationJob represents the parsed status of a Proxmox storage replication job.
@ -80,37 +83,91 @@ func (c *Client) enrichReplicationJobStatus(ctx context.Context, job *Replicatio
// Status is stored on the source node
sourceNode := job.Source
if sourceNode == "" {
log.Debug().Str("jobID", job.ID).Msg("Skipping replication status fetch - no source node")
return
}
jobID := job.ID
if jobID == "" {
log.Debug().Str("source", sourceNode).Msg("Skipping replication status fetch - no job ID")
return
}
endpoint := fmt.Sprintf("/nodes/%s/replication/%s/status", sourceNode, jobID)
resp, err := c.get(ctx, endpoint)
if err != nil {
// Silently ignore - status endpoint may not be available or job may be new
log.Debug().
Str("jobID", jobID).
Str("source", sourceNode).
Str("endpoint", endpoint).
Err(err).
Msg("Failed to fetch replication job status")
return
}
defer resp.Body.Close()
// Read body for debugging/parsing
bodyBytes, err := io.ReadAll(resp.Body)
if err != nil {
log.Debug().
Str("jobID", jobID).
Str("endpoint", endpoint).
Err(err).
Msg("Failed to read replication status response body")
return
}
log.Debug().
Str("jobID", jobID).
Str("endpoint", endpoint).
Str("responseBody", string(bodyBytes)).
Msg("Received replication status response")
// Try to parse as array first (common case)
var statusResp struct {
Data []map[string]json.RawMessage `json:"data"`
}
var status map[string]json.RawMessage
if err := json.NewDecoder(resp.Body).Decode(&statusResp); err != nil {
return
if err := json.Unmarshal(bodyBytes, &statusResp); err != nil {
log.Debug().
Str("jobID", jobID).
Str("endpoint", endpoint).
Err(err).
Msg("Failed to decode replication status response as array, trying single object")
// Try parsing as single object { "data": { ... } }
var singleResp struct {
Data map[string]json.RawMessage `json:"data"`
}
if err := json.Unmarshal(bodyBytes, &singleResp); err != nil {
log.Debug().
Str("jobID", jobID).
Str("endpoint", endpoint).
Err(err).
Msg("Failed to decode replication status response as single object")
return
}
if len(singleResp.Data) == 0 {
log.Debug().
Str("jobID", jobID).
Str("endpoint", endpoint).
Msg("Replication status response has empty data object")
return
}
status = singleResp.Data
} else {
// Successfully parsed as array
if len(statusResp.Data) == 0 {
log.Debug().
Str("jobID", jobID).
Str("endpoint", endpoint).
Msg("Replication status response has empty data array")
return
}
status = statusResp.Data[0]
}
// The status endpoint returns an array, usually with one entry
if len(statusResp.Data) == 0 {
return
}
status := statusResp.Data[0]
// Parse and merge status fields
if t, unix := parseReplicationTime(decodeRaw(status["last_sync"])); t != nil {
job.LastSyncTime = t
@ -141,6 +198,14 @@ func (c *Client) enrichReplicationJobStatus(ctx context.Context, job *Replicatio
if errMsg := stringFromAny(decodeRaw(status["error"])); errMsg != "" {
job.Error = errMsg
}
log.Debug().
Str("jobID", jobID).
Str("source", sourceNode).
Interface("lastSync", job.LastSyncTime).
Interface("nextSync", job.NextSyncTime).
Str("state", job.State).
Msg("Successfully enriched replication job with status")
}
func parseReplicationJob(entry map[string]json.RawMessage) ReplicationJob {