FIX #27

cmd/vocat/main.go

@@ -192,7 +192,7 @@ func run(logger *slog.Logger, logs *loghub.Hub) error {
 	}
 
 	cardReaders := pcsc.New()
-	deviceManager, err := device.NewManager(device.Options{CardReaders: cardReaders})
+	deviceManager, err := device.NewManager(device.Options{CardReaders: cardReaders, Logger: logger})
 	if err != nil {
 		return fmt.Errorf("create device manager: %w", err)
 	}

internal/device/logging.go

@@ -0,0 +1,84 @@
+package device
+
+import (
+	"regexp"
+	"strings"
+	"unicode"
+
+	"vocat/internal/modem"
+)
+
+const maxHardwareErrorDetail = 1024
+
+var longHexPayload = regexp.MustCompile(`(?i)\b[0-9a-f]{48,}\b`)
+
+// HardwareErrorDetail returns a diagnostic error suitable for persistent and
+// browser-visible logs. AT payloads can contain APDU authentication material,
+// SMS data, or APN credentials, so CommandError values retain only the command
+// name and modem final result. Very long hexadecimal payloads from wrapped
+// protocol errors are removed as a second line of defence.
+func HardwareErrorDetail(err error) string {
+	if err == nil {
+		return ""
+	}
+	detail := redactCommandErrors(err.Error(), err)
+	detail = longHexPayload.ReplaceAllString(detail, "[redacted hex payload]")
+	detail = strings.Map(func(character rune) rune {
+		if unicode.IsControl(character) && character != '\t' && character != '\n' {
+			return ' '
+		}
+		return character
+	}, strings.TrimSpace(detail))
+	runes := []rune(detail)
+	if len(runes) > maxHardwareErrorDetail {
+		detail = string(runes[:maxHardwareErrorDetail]) + "..."
+	}
+	return detail
+}
+
+func redactCommandErrors(detail string, err error) string {
+	if commandErr, ok := err.(*modem.CommandError); ok {
+		detail = strings.ReplaceAll(detail, commandErr.Error(), safeCommandError(commandErr))
+	}
+	switch wrapped := err.(type) {
+	case interface{ Unwrap() []error }:
+		for _, child := range wrapped.Unwrap() {
+			detail = redactCommandErrors(detail, child)
+		}
+	case interface{ Unwrap() error }:
+		if child := wrapped.Unwrap(); child != nil {
+			detail = redactCommandErrors(detail, child)
+		}
+	}
+	return detail
+}
+
+func safeCommandError(err *modem.CommandError) string {
+	command := safeATCommandName(err.Command)
+	final := strings.TrimSpace(err.Final)
+	if final == "" {
+		final = "unknown modem error"
+	}
+	return command + " failed: " + final
+}
+
+func safeATCommandName(command string) string {
+	command = strings.ToUpper(strings.TrimSpace(command))
+	if command == "" {
+		return "AT command"
+	}
+	if strings.HasPrefix(command, "ATD") {
+		return "ATD"
+	}
+	for index, character := range command {
+		if character == '=' || character == '?' || character == ',' ||
+			character == '"' || unicode.IsSpace(character) {
+			command = command[:index]
+			break
+		}
+	}
+	if !strings.HasPrefix(command, "AT") || len(command) > 32 {
+		return "AT command"
+	}
+	return command
+}

internal/device/logging_test.go

@@ -0,0 +1,68 @@
+package device
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"log/slog"
+	"strings"
+	"testing"
+
+	"vocat/internal/loghub"
+	"vocat/internal/modem"
+)
+
+func TestHardwareErrorDetailRedactsATPayload(t *testing.T) {
+	const payload = "00880081221000112233445566778899AABBCCDDEEFF1000112233445566778899AABBCCDDEEFF00"
+	commandErr := &modem.CommandError{
+		Command: `AT+CSIM=78,"` + payload + `"`,
+		Final:   "+CME ERROR: 13",
+		Lines:   []string{payload},
+	}
+	err := fmt.Errorf("select ISIM: %w", errors.Join(errors.New("reader reset failed"), commandErr))
+	detail := HardwareErrorDetail(err)
+	if strings.Contains(detail, payload) || strings.Contains(detail, "AT+CSIM=") {
+		t.Fatalf("hardware error exposed AT payload: %q", detail)
+	}
+	if !strings.Contains(detail, "select ISIM") || !strings.Contains(detail, "AT+CSIM failed: +CME ERROR: 13") {
+		t.Fatalf("hardware error lost useful diagnostics: %q", detail)
+	}
+}
+
+func TestManagerLogsNewHardwareFailuresWithoutPollingSpam(t *testing.T) {
+	commandError := func() error {
+		return &modem.CommandError{Command: "AT+CSQ", Final: "+CME ERROR: 13"}
+	}
+	client := &transcriptClient{steps: []clientStep{
+		{command: "AT+CSQ", err: commandError()},
+		{command: "AT+CSQ", err: commandError()},
+		{command: "AT+CSQ", response: okResponse("+CSQ: 20,99")},
+		{command: "AT+CSQ", err: commandError()},
+	}}
+	manager, id := newStartedTestManager(t, client)
+	hub := loghub.New(nil, 100)
+	manager.logger = slog.New(hub)
+
+	for attempt := 0; attempt < 2; attempt++ {
+		_, _ = manager.ExecuteAT(context.Background(), id, "AT+CSQ")
+	}
+	if entries := hub.History(10, slog.LevelDebug, ""); len(entries) != 1 {
+		t.Fatalf("continuous failure produced %d log entries, want 1", len(entries))
+	}
+	_, _ = manager.ExecuteAT(context.Background(), id, "AT+CSQ")
+	_, _ = manager.ExecuteAT(context.Background(), id, "AT+CSQ")
+
+	entries := hub.History(10, slog.LevelDebug, "")
+	if len(entries) != 2 {
+		t.Fatalf("failure after recovery produced %d total log entries, want 2", len(entries))
+	}
+	for _, entry := range entries {
+		if entry.Message != "hardware operation failed" || entry.Fields["device_id"] != id {
+			t.Fatalf("hardware log entry = %#v", entry)
+		}
+		if entry.Fields["error"] != "AT+CSQ failed: +CME ERROR: 13" {
+			t.Fatalf("hardware log detail = %#v", entry.Fields["error"])
+		}
+	}
+	client.assertDone(t)
+}

internal/device/manager.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log/slog"
 	"sort"
 	"strings"
 	"sync"
@@ -21,6 +22,7 @@ type Options struct {
 	SMSTimeout     time.Duration
 	ScanTimeout    time.Duration
 	CardReaders    *pcsc.Service
+	Logger         *slog.Logger
 }
 
 type Manager struct {
@@ -38,6 +40,7 @@ type Manager struct {
 	smsTimeout     time.Duration
 	scanTimeout    time.Duration
 	cardReaders    *pcsc.Service
+	logger         *slog.Logger
 
 	qmiRadioOpener                qmiRadioSessionOpener
 	nativeQMIRegistrationMu       sync.Mutex
@@ -120,6 +123,7 @@ func NewManager(options Options) (*Manager, error) {
 		smsTimeout:     options.SMSTimeout,
 		scanTimeout:    options.ScanTimeout,
 		cardReaders:    options.CardReaders,
+		logger:         options.Logger,
 
 		qmiRadioOpener:                openQMIRadioSession,
 		nativeQMIRegistrationInFlight: make(map[string]struct{}),
@@ -373,10 +377,11 @@ func (manager *Manager) setResult(
 	err error,
 ) {
 	manager.mu.Lock()
-	defer manager.mu.Unlock()
 	if manager.devices[id] != state {
+		manager.mu.Unlock()
 		return
 	}
+	previousError := state.lastError
 	if snapshot != nil {
 		value := *snapshot
 		value.Warnings = append([]string(nil), snapshot.Warnings...)
@@ -388,6 +393,19 @@ func (manager *Manager) setResult(
 	} else {
 		state.lastError = ""
 	}
+	shouldLog := err != nil && manager.logger != nil && previousError != err.Error()
+	backend := state.backend
+	hardwareKind := state.candidate.HardwareKind
+	manager.mu.Unlock()
+	if shouldLog {
+		manager.logger.Warn(
+			"hardware operation failed",
+			"device_id", id,
+			"backend", backend,
+			"hardware_kind", hardwareKind,
+			"error", HardwareErrorDetail(err),
+		)
+	}
 }
 
 func (manager *Manager) candidateFor(state *managedDevice) modem.Candidate {

internal/server/device_api.go

@@ -1421,9 +1421,9 @@ func (s *Server) writeDeviceError(w http.ResponseWriter, err error) {
 	case errors.Is(err, context.Canceled):
 		writeError(w, http.StatusRequestTimeout, "request_canceled", "the modem request was canceled")
 	default:
-		// Device errors may echo an AT command. Authentication commands can
-		// contain APN credentials, so keep raw errors out of logs and responses.
-		s.logger.Warn("device operation failed")
+		// Preserve the hardware failure reason in the operator-visible log while
+		// keeping AT payloads and long APDU material out of it.
+		s.logger.Warn("device operation failed", "error", device.HardwareErrorDetail(err))
 		writeError(w, http.StatusBadGateway, "modem_error", "the device operation failed")
 	}
 }