diff --git a/cmd/vocat/main.go b/cmd/vocat/main.go index 65f1dbe..acfe769 100644 --- a/cmd/vocat/main.go +++ b/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) } diff --git a/internal/device/logging.go b/internal/device/logging.go new file mode 100644 index 0000000..eb0d8bd --- /dev/null +++ b/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 +} diff --git a/internal/device/logging_test.go b/internal/device/logging_test.go new file mode 100644 index 0000000..d4b352e --- /dev/null +++ b/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) +} diff --git a/internal/device/manager.go b/internal/device/manager.go index c101017..4aa0088 100644 --- a/internal/device/manager.go +++ b/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 { diff --git a/internal/server/device_api.go b/internal/server/device_api.go index 34d5495..ca07ff9 100644 --- a/internal/server/device_api.go +++ b/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") } }