From e26331ffa93a99d824015dca534770c7798a6b1e Mon Sep 17 00:00:00 2001 From: yurii Date: Sun, 27 Sep 2026 22:21:28 +0100 Subject: [PATCH] fix(dispenser): simplify card preparation and recovery --- internal/dispenser/delivery_test.go | 186 ++-- internal/dispenser/dispenser.go | 59 +- internal/dispenser/dispenserclient.go | 403 +++++---- internal/dispenser/dispenserclient_test.go | 920 +++++++------------- internal/handlers/doorcard_handlers_test.go | 60 +- internal/handlers/handlers.go | 34 +- 6 files changed, 710 insertions(+), 952 deletions(-) diff --git a/internal/dispenser/delivery_test.go b/internal/dispenser/delivery_test.go index 80288b6..a30f17e 100644 --- a/internal/dispenser/delivery_test.go +++ b/internal/dispenser/delivery_test.go @@ -95,18 +95,22 @@ func TestWorkerClearanceValidation(t *testing.T) { {"low stock clear", []byte{0x30, 0x30, 0x31, 0x30}, true}, {"residual encoder", status(0x33), false}, {"all sensors", status(0x37), false}, - {"mouth", status(0x34), false}, - {"unknown diagnostic", []byte{0x30, 0x30, 0xFF, 0x30}, false}, - {"jam", []byte{0x30, 0x30, 0x32, 0x30}, false}, - {"overlap", []byte{0x30, 0x30, 0x34, 0x30}, false}, - {"rejection", []byte{0x36, 0x30, 0x30, 0x30}, false}, + {"ready", status(0x34), true}, + {"unknown diagnostic", []byte{0x30, 0x30, 0xFF, 0x30}, true}, + {"jam", []byte{0x30, 0x30, 0x32, 0x30}, true}, + {"overlap", []byte{0x30, 0x30, 0x34, 0x30}, true}, + {"rejection", []byte{0x36, 0x30, 0x30, 0x30}, true}, {"empty", status(0x38), false}, + {"preparing", []byte{0x31, 0x30, 0x30, 0x30}, false}, + {"dispensing", []byte{0x30, 0x38, 0x30, 0x34}, false}, + {"capturing", []byte{0x30, 0x34, 0x30, 0x30}, false}, + {"ready with stale errors", []byte{0x36, 0x32, 0x34, 0x34}, true}, {"short payload", []byte{0x30, 0x30, 0x30}, false}, {"unknown position", status(0x40), false}, } { t.Run(tc.name, func(t *testing.T) { p := &scriptedTransport{chunks: [][]byte{vendorACK, apReply(tc.st), vendorACK}} - c := &Client{port: p, deliveryPending: true, deliveryStarted: time.Now(), lastStatus: status(0x30), lastStatusT: time.Now(), statusTTL: time.Hour} + c := &Client{port: p, deliveryPending: true, deliveryStarted: time.Now().Add(-deliveryMinimumWait), lastStatus: status(0x30), lastStatusT: time.Now(), statusTTL: time.Hour} r := workerRequest(c, context.Background(), cmdToEncoder) if (r.err == nil) != tc.clear || c.deliveryPending == tc.clear { t.Errorf("FC7(% X): err=%v pending=%v, want clear=%v", tc.st, r.err, c.deliveryPending, tc.clear) @@ -169,8 +173,6 @@ func TestDeliveryIncidentReplay(t *testing.T) { vendorACK, apReply(status(0x37)), // best effort must defer vendorACK, apReply(status(0x33)), // previous encoder sensor must not succeed vendorACK, apReply(status(0x34)), - vendorACK, apReply(status(0x37)), - vendorACK, apReply(status(0x30)), // clearance vendorACK, // FC7 vendorACK, apReply(status(0x33)), }} @@ -187,11 +189,11 @@ func TestDeliveryIncidentReplay(t *testing.T) { c.lastStatusT = time.Now() c.statusTTL = time.Hour c.mu.Unlock() - if err := c.BeginPrepareNextCard(context.Background()); !errors.Is(err, errDeliveryPending) { - t.Fatalf("BeginPrepareNextCard=%v, want deferred", err) + if err := c.BeginPrepareNextCard(context.Background()); err != nil { + t.Fatal(err) } - if got := wireCommands(p); !reflect.DeepEqual(got, []string{"AP", "FC0", "AP"}) { - t.Fatalf("before clearance commands=%v", got) + if got := wireCommands(p); !reflect.DeepEqual(got, []string{"AP", "FC0", "AP", "AP", "AP", "FC7"}) { + t.Fatalf("prestaging commands=%v, want clearance APs then one FC7", got) } prepare := c.PrepareCurrentCard if next { @@ -200,31 +202,36 @@ func TestDeliveryIncidentReplay(t *testing.T) { if _, err := prepare(context.Background()); err != nil { t.Fatal(err) } - want := []string{"AP", "FC0", "AP", "AP", "AP", "AP", "AP", "FC7", "AP"} + want := []string{"AP", "FC0", "AP", "AP", "AP", "FC7", "AP"} if got := wireCommands(p); !reflect.DeepEqual(got, want) { t.Errorf("incident commands=%v, want %v", got, want) } - if elapsed := now.Sub(time.Unix(0, 0)); elapsed != 3*time.Second { - t.Errorf("clearance waits=%s, want 3s", elapsed) + if elapsed := now.Sub(time.Unix(0, 0)); elapsed != 2*time.Second { + t.Errorf("clearance waits=%s, want 2s", elapsed) } }) } } -func TestDeliveryClearImmediately(t *testing.T) { - p := &scriptedTransport{chunks: [][]byte{vendorACK, vendorACK, apReply(status(0x30)), vendorACK, vendorACK, apReply(status(0x33))}} - c, now := deliveryWorkerClient(t, p) - if _, err := c.DeliverCurrentCard(context.Background()); err != nil { - t.Fatal(err) - } - if _, err := c.PrepareCurrentCard(context.Background()); err != nil { - t.Fatal(err) - } - if got := wireCommands(p); !reflect.DeepEqual(got, []string{"FC0", "AP", "FC7", "AP"}) { - t.Errorf("commands=%v, want FC0 AP FC7 AP", got) - } - if !now.Equal(time.Unix(0, 0)) { - t.Errorf("immediate clearance waited until %v", now) +func TestDeliveryClearWaitsTwoSeconds(t *testing.T) { + for _, position := range []byte{0x30, 0x34} { + p := &scriptedTransport{chunks: [][]byte{vendorACK, + vendorACK, apReply(status(position)), vendorACK, apReply(status(position)), vendorACK, apReply(status(position)), + vendorACK, vendorACK, apReply(status(0x37))}} + c, now := deliveryWorkerClient(t, p) + if _, err := c.DeliverCurrentCard(context.Background()); err != nil { + t.Fatal(err) + } + if _, err := c.PrepareCurrentCard(context.Background()); err != nil { + t.Fatal(err) + } + want := []string{"FC0", "AP", "AP", "AP", "FC7", "AP"} + if got := wireCommands(p); !reflect.DeepEqual(got, want) { + t.Errorf("clearance %X commands=%v, want %v", position, got, want) + } + if elapsed := now.Sub(time.Unix(0, 0)); elapsed != deliveryMinimumWait { + t.Errorf("clearance %X elapsed=%s, want 2s", position, elapsed) + } } } @@ -238,7 +245,7 @@ func TestDeliveryClearanceWaitStops(t *testing.T) { {name: "cancel", response: cmdResp{status: status(0x37), deliveryPending: true}, cancel: true}, {name: "timeout", response: cmdResp{status: status(0x37), deliveryPending: true}, timeout: true}, {name: "transport", response: cmdResp{err: io.ErrUnexpectedEOF}}, - {name: "jam", response: cmdResp{status: []byte{0x30, 0x30, 0x32, 0x30}, deliveryPending: true}}, + {name: "movement", response: cmdResp{status: []byte{0x31, 0x30, 0x32, 0x30}, deliveryPending: true}}, {name: "empty", response: cmdResp{status: status(0x38), deliveryPending: true}}, } { t.Run(tc.name, func(t *testing.T) { @@ -261,7 +268,7 @@ func TestDeliveryClearanceWaitStops(t *testing.T) { t.Errorf("error=%v, want canceled", err) } if tc.timeout { - if !errors.Is(err, context.DeadlineExceeded) || c.sequenceTiming.now().Sub(started) != sequenceTimeout { + if !errors.Is(err, context.DeadlineExceeded) || c.sequenceTiming.now().Sub(started) != deliveryClearanceTimeout { t.Errorf("timeout err=%v elapsed=%s", err, c.sequenceTiming.now().Sub(started)) } } @@ -275,27 +282,21 @@ func TestDeliveryClearanceWaitStops(t *testing.T) { } func TestDeliveryClearanceDoesNotConsumeRecoveryWindow(t *testing.T) { - responses := []cmdResp{{status: status(0x37), deliveryPending: true}, {status: status(0x33), deliveryPending: true}, {status: status(0x30)}} - responses = append(responses, prepareFailureResponses(0x32, 7)...) - responses = append(responses, cmdResp{status: status(0x30)}, cmdResp{status: status(0x33)}) + responses := make([]cmdResp, 15) + for i := range responses { + responses[i] = cmdResp{status: status(0x37), deliveryPending: true} + } + responses = append(responses, positionResponses(0x30, 17)...) c, d := newSequenceTestClient(t, responses...) - if _, err := c.PrepareCurrentCard(context.Background()); err != nil { - t.Fatal(err) + start := c.now() + if _, err := c.PrepareCurrentCard(context.Background()); !errors.Is(err, ErrPreparationExhausted) { + t.Fatalf("preparation error=%v, want exhausted", err) } - var initial, reset time.Time - for i, cmd := range d.commands { - if cmd == cmdToEncoder && initial.IsZero() { - initial = d.commandTimes[i] - } - if cmd == cmdReset { - reset = d.commandTimes[i] - } + if elapsed := c.now().Sub(start); elapsed != 33*time.Second { + t.Errorf("elapsed=%s, want clearance 15s + shakes 18s", elapsed) } - if reset.Sub(initial) != sequenceRetryAfter || commandCount(d.commands, cmdReset) != 1 || commandCount(d.commands, cmdToEncoder) != 2 { - t.Errorf("recovery commands=%v reset delay=%s, want two FC7 and one RS at 6s", d.commands, reset.Sub(initial)) - } - if got := c.sequenceTiming.now().Sub(reset); got != sequenceResetWait+sequencePollInterval { - t.Errorf("post-reset elapsed=%s, want settle plus poll=3s", got) + if commandCount(d.commands, cmdReset) != 3 || commandCount(d.commands, cmdToEncoder) != 4 { + t.Errorf("commands=%v, want 3 RS and 4 FC7", d.commands) } } @@ -332,18 +333,24 @@ func TestDeliveryClearanceRetainsFullPreparationTimeout(t *testing.T) { for i := range responses { responses[i] = cmdResp{status: status(0x37), deliveryPending: true} } - responses = append(responses, cmdResp{status: status(0x30)}) - responses = append(responses, prepareFailureResponses(0x32, 30)...) + responses = append(responses, positionResponses(0x30, 2)...) c, d := newSequenceTestClient(t, responses...) - started := c.sequenceTiming.now() - if _, err := c.PrepareCurrentCard(context.Background()); err == nil { - t.Fatal("persistent failure succeeded") + wait := c.sequenceTiming.wait + c.sequenceTiming.wait = func(ctx context.Context, duration time.Duration) error { + if commandCount(d.commands, cmdToEncoder) > 0 { + duration = sequenceTimeout + } + return wait(ctx, duration) } - if got := c.sequenceTiming.now().Sub(started); got != 8*time.Second+sequenceTimeout { - t.Errorf("total duration=%s, want clearance 8s + preparation 16s", got) + start := c.now() + if _, err := c.PrepareCurrentCard(context.Background()); !errors.Is(err, ErrPreparationExhausted) { + t.Fatalf("preparation error=%v, want exhausted", err) } - if commandCount(d.commands, cmdReset) != 1 || commandCount(d.commands, cmdToEncoder) != 2 { - t.Errorf("commands=%v, want one RS and two FC7", d.commands) + if elapsed := c.now().Sub(start); elapsed != 8*time.Second+sequenceTimeout { + t.Errorf("elapsed=%s, want clearance 8s + preparation 32s", elapsed) + } + if commandCount(d.commands, cmdReset) != 0 || commandCount(d.commands, cmdToEncoder) != 1 { + t.Errorf("commands=%v, want one FC7 and no RS after deadline", d.commands) } } @@ -352,7 +359,7 @@ func TestWorkerSerializesClearanceAndFC7(t *testing.T) { c, _ := deliveryWorkerClient(t, p) // Set initial state before any request can reach the worker. c.deliveryPending = true - c.deliveryStarted = time.Now() + c.deliveryStarted = c.now().Add(-deliveryMinimumWait) reading := make(chan struct{}) resume := make(chan struct{}) p.afterWrite = func() { @@ -389,3 +396,64 @@ func TestWorkerSerializesClearanceAndFC7(t *testing.T) { t.Errorf("serialized commands=%v, want %v", got, want) } } + +func TestDeliveryCancellationAfterFreshAPKeepsPending(t *testing.T) { + transportAddress(t) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + p := &scriptedTransport{chunks: [][]byte{vendorACK, apReply(status(0x34))}} + p.afterRead = func() { + if len(p.chunks) == 0 { + cancel() + } + } + c := &Client{port: p, deliveryPending: true, deliveryStarted: time.Now().Add(-time.Minute)} + r := workerRequest(c, ctx, cmdToEncoder) + if !errors.Is(r.err, context.Canceled) || !c.deliveryPending { + t.Errorf("AP cancellation err=%v pending=%t, want canceled and pending", r.err, c.deliveryPending) + } + if got := wireCommands(p); !reflect.DeepEqual(got, []string{"AP"}) { + t.Errorf("cancelled clearance commands=%v, want AP only", got) + } +} + +func TestPreparationWireFailuresNeverShake(t *testing.T) { + badBCC := apReply(status(0x30)) + badBCC[len(badBCC)-1] ^= 1 + for _, frame := range [][]byte{nil, apReply(status(0x30))[:8], badBCC, apReply(status(0x40))} { + p := &scriptedTransport{chunks: [][]byte{vendorACK, apReply(status(0x30)), vendorACK, vendorACK}} + if frame != nil { + p.chunks = append(p.chunks, frame) + } + c, _ := deliveryWorkerClient(t, p) + if _, err := c.PrepareCurrentCard(context.Background()); err == nil || errors.Is(err, ErrPreparationExhausted) { + t.Errorf("frame % X: err=%v, want transport/protocol failure", frame, err) + } + want := []string{"AP", "FC7", "AP"} + if got := wireCommands(p); !reflect.DeepEqual(got, want) { + t.Errorf("frame % X commands=%v, want %v without RS or resends", frame, got, want) + } + } +} + +func TestBeginPrepareNextCardWaitsForClearanceWithoutReadinessPolling(t *testing.T) { + for _, position := range []byte{0x30, 0x34} { + p := &scriptedTransport{chunks: [][]byte{vendorACK, + vendorACK, apReply(status(position)), vendorACK, apReply(status(position)), vendorACK, apReply(status(position)), + vendorACK}} + c, now := deliveryWorkerClient(t, p) + if _, err := c.DeliverCurrentCard(context.Background()); err != nil { + t.Fatal(err) + } + if err := c.BeginPrepareNextCard(context.Background()); err != nil { + t.Fatal(err) + } + want := []string{"FC0", "AP", "AP", "AP", "FC7"} + if got := wireCommands(p); !reflect.DeepEqual(got, want) { + t.Errorf("BeginPrepareNextCard(%X) commands = %v, want %v", position, got, want) + } + if elapsed := now.Sub(time.Unix(0, 0)); elapsed != deliveryMinimumWait { + t.Errorf("BeginPrepareNextCard(%X) waited %s, want %s", position, elapsed, deliveryMinimumWait) + } + } +} diff --git a/internal/dispenser/dispenser.go b/internal/dispenser/dispenser.go index 9a5c3c3..ec56c13 100644 --- a/internal/dispenser/dispenser.go +++ b/internal/dispenser/dispenser.go @@ -40,6 +40,9 @@ const ( var ( ErrCardWellEmpty = errors.New(CardWellEmptyMessage) + // ErrPreparationExhausted permits a new, independent UI preparation attempt. + ErrPreparationExhausted = errors.New("card preparation exhausted") + SerialPort string Address []byte @@ -142,38 +145,35 @@ func isAtEncoderPosition(statusBytes []byte) bool { return valid && flags&positionEncoder != 0 } -func validateDispenserStatusData(statusBytes []byte) error { - if len(statusBytes) != 4 { - return fmt.Errorf("malformed dispenser status: got %d bytes, want 4", len(statusBytes)) - } +type preparationClass string - statusMaps := []map[byte]string{statusPos0, statusPos1, statusPos2} - for position, mapper := range statusMaps { - if _, ok := mapper[statusBytes[position]]; !ok { - return fmt.Errorf("unknown dispenser status 0x%X at position %d", statusBytes[position], position+1) - } - } - if _, valid := decodePositionStatus(statusBytes[3]); !valid { - return fmt.Errorf("unknown dispenser status 0x%X at position 4", statusBytes[3]) - } - return nil -} +const ( + encoderConfirmed preparationClass = "encoder confirmed" + positionUncertain preparationClass = "valid but uncertain" + positionWellEmpty preparationClass = "empty" + positionNoCard preparationClass = "no card on sensors" +) -func dispenserStatusError(statusBytes []byte) error { - switch statusBytes[0] { - case 0x34, 0x32, 0x36: - return fmt.Errorf("dispenser error: %s", statusPos0[statusBytes[0]]) +// classifyPreparationStatus is the only readiness gate after AP wire validation. +// Diagnostics describe the device; they do not veto a physical position class. +func classifyPreparationStatus(status []byte) (preparationClass, error) { + if len(status) != 4 { + return "", fmt.Errorf("malformed dispenser status: got %d bytes, want 4", len(status)) } - switch statusBytes[1] { - case 0x32, 0x31: - return fmt.Errorf("dispenser error: %s", statusPos1[statusBytes[1]]) + flags, valid := decodePositionStatus(status[3]) + if !valid { + return "", fmt.Errorf("malformed dispenser position encoding: 0x%X", status[3]) } - switch statusBytes[2] { - case 0x34, 0x32: - return fmt.Errorf("dispenser error: %s", statusPos2[statusBytes[2]]) + switch { + case flags&positionEncoder != 0: + return encoderConfirmed, nil + case status[3] == 0x38: + return positionWellEmpty, nil + case status[3] == 0x30: + return positionNoCard, nil + default: + return positionUncertain, nil } - - return nil } func isPreparationMoving(statusBytes []byte) bool { @@ -181,11 +181,6 @@ func isPreparationMoving(statusBytes []byte) bool { (statusBytes[0] == 0x31 || statusBytes[1] == 0x38) } -func hasPreparationDiagnostics(statusBytes []byte) bool { - return len(statusBytes) == 4 && - (statusBytes[0] != 0x30 || statusBytes[1] != 0x30 || statusBytes[2] != 0x30) -} - func stockTake(statusBytes []byte) string { if len(statusBytes) < 4 { return "" diff --git a/internal/dispenser/dispenserclient.go b/internal/dispenser/dispenserclient.go index 117e74e..384ad54 100644 --- a/internal/dispenser/dispenserclient.go +++ b/internal/dispenser/dispenserclient.go @@ -41,10 +41,14 @@ type sequenceTiming struct { } const ( - sequencePollInterval = time.Second - sequenceRetryAfter = 6 * time.Second - sequenceResetWait = 2 * time.Second - sequenceTimeout = 16 * time.Second + sequencePollInterval = time.Second + sequenceShakeAfter = 3 * time.Second + sequenceResetWait = 2 * time.Second + sequenceTimeout = 32 * time.Second + sequenceUncertainWait = 4 * time.Second + sequenceMaxShakes = 3 + deliveryClearanceTimeout = 16 * time.Second + deliveryMinimumWait = 2 * time.Second ) type Client struct { @@ -217,19 +221,22 @@ func (c *Client) handle(req cmdReq) { } } err := cardToEncoderPosition(req.ctx, c.port) + log.Infof("FC7 dispatch finished; dispatched=%t error=%v", err == nil, err) c.invalidateStatusCache() req.respCh <- cmdResp{err: err} case cmdReset: err := resetDispenser(req.ctx, c.port) + log.Infof("RS dispatch finished; dispatched=%t error=%v", err == nil, err) c.invalidateStatusCache() req.respCh <- cmdResp{err: err} case cmdOutOfMouth: attempted, err := cardOutOfMouth(req.ctx, c.port) + log.Infof("FC0 dispatch finished; ENQ_attempted=%t error=%v", attempted, err) if attempted { c.deliveryPending = true - c.deliveryStarted = time.Now() + c.deliveryStarted = c.now() log.Info("delivery ENQ attempted; awaiting mechanical clearance") } // A movement command makes any previously cached position unreliable. @@ -243,19 +250,24 @@ func (c *Client) handle(req cmdReq) { // deliveryClearance deliberately does not apply encoder-success precedence. func deliveryClearance(status []byte) (bool, error) { - if err := validateDispenserStatusData(status); err != nil { + class, err := classifyPreparationStatus(status) + if err != nil { return false, err } - if isCardWellEmpty(status) { + if class == positionWellEmpty { return false, ErrCardWellEmpty } - if isPreparationMoving(status) { + if isPreparationMoving(status) || status[1] == 0x34 { return false, nil } - if err := dispenserStatusError(status); err != nil { - return false, err + return status[3] == 0x30 || status[3] == 0x34, nil +} + +func (c *Client) now() time.Time { + if c.sequenceTiming.now != nil { + return c.sequenceTiming.now() } - return status[0] == 0x30 && status[1] == 0x30 && status[3] == 0x30, nil + return time.Now() } // readWorkerStatus is called only by the serial worker and always reads fresh AP. @@ -264,13 +276,18 @@ func (c *Client) readWorkerStatus(ctx context.Context) ([]byte, error) { if err != nil { return st, err } + if err := ctx.Err(); err != nil { + return st, err + } if c.deliveryPending { + class, _ := classifyPreparationStatus(st) + log.Infof("delivery clearance AP; class=%s elapsed=%s raw status: % X", class, c.now().Sub(c.deliveryStarted), st) clear, clearanceErr := deliveryClearance(st) if clearanceErr != nil { log.Warnf("delivery clearance failed: %v; %s raw status: % X", clearanceErr, statusDescription(st), st) - } else if clear { + } else if clear && c.now().Sub(c.deliveryStarted) >= deliveryMinimumWait { c.deliveryPending = false - log.Infof("previous delivery cleared after %s; FC7 permitted", time.Since(c.deliveryStarted)) + log.Infof("previous delivery cleared after %s; FC7 permitted", c.now().Sub(c.deliveryStarted)) } } if len(st) == 4 { @@ -408,186 +425,12 @@ func (c *Client) readSequenceStatus(ctx context.Context, operation string) ([]by return status, stockStatus, nil } -func preparationStatus(operation string, status []byte, allowCombinedFailure bool) (bool, error) { - // A confirmed read sensor takes precedence over every other diagnostic. - if isAtEncoderPosition(status) { - if hasPreparationDiagnostics(status) { - log.Warnf( - "[%s] card confirmed at encoder with dispenser diagnostics: %s raw status: % X", - operation, - statusDescription(status), - status, - ) - } - return true, nil - } - if err := validateDispenserStatusData(status); err != nil { - return false, fmt.Errorf("[%s] %w", operation, err) - } - if isCardWellEmpty(status) { - return false, fmt.Errorf("[%s] %w", operation, ErrCardWellEmpty) - } - if isPreparationMoving(status) { - return false, nil - } - - // Some dispenser firmware briefly reports 0x32 ("Preparing card fails") - // while the card is still travelling to the encoder. Treat that one - // diagnostic as transient during an active preparation sequence and let - // pollForEncoderPosition decide encoder success or timeout. Do not mask - // independent hard errors reported in the other status bytes. - // Combined command rejection is also recoverable before the one retry. - if status[0] == 0x32 || (status[0] == 0x36 && allowCombinedFailure) { - statusWithoutPrepareFailure := append([]byte(nil), status...) - statusWithoutPrepareFailure[0] = 0x30 - if err := dispenserStatusError(statusWithoutPrepareFailure); err != nil { - return false, fmt.Errorf("[%s] %w", operation, err) - } - - log.Warnf( - "[%s] transient preparation failure (%s); waiting for encoder position, raw status: % X", - operation, - statusDescription(status), - status, - ) - return false, nil - } - - if err := dispenserStatusError(status); err != nil { - return false, fmt.Errorf("[%s] %w", operation, err) - } - return false, nil -} - -func (c *Client) pollForEncoderPosition(ctx context.Context, operation string) (stockStatus string, resultErr error) { - started := c.sequenceTiming.now() - recoveryAt := started.Add(sequenceRetryAfter) - deadline := started.Add(sequenceTimeout) - ctx, cancel := context.WithTimeout(ctx, sequenceTimeout) - defer cancel() - retried := false - resetAttempted := false - retryAfterReset := false - consecutiveFailures := 0 - stage := "initial polling" - var lastStatus []byte - defer func() { - if resultErr != nil { - log.Warnf("[%s] card preparation failed; stage=%s reset_attempted=%t raw status: % X: %v", operation, stage, resetAttempted, lastStatus, resultErr) - } - }() - - checkDeadline := func() error { - if err := ctx.Err(); err != nil { - return fmt.Errorf("[%s] %s: %w", operation, stage, err) - } - if !c.sequenceTiming.now().Before(deadline) { - return fmt.Errorf("[%s] %s: timed out after %s", operation, stage, sequenceTimeout) - } - return nil - } - - for { - if err := checkDeadline(); err != nil { - return stockStatus, err - } - status, currentStockStatus, err := c.readSequenceStatus(ctx, operation) - stockStatus = currentStockStatus - lastStatus = status - if err != nil { - return stockStatus, err - } - if err := checkDeadline(); err != nil { - return stockStatus, err - } - ready, err := preparationStatus(operation, status, !retried || retryAfterReset) - if err != nil { - return stockStatus, err - } - if ready { - if resetAttempted { - log.Infof("[%s] card preparation recovered after reset", operation) - } - return stockStatus, nil - } - - moving := isPreparationMoving(status) - prepareFailed := status[0] == 0x32 || status[0] == 0x36 - if prepareFailed && !moving { - consecutiveFailures++ - } else { - consecutiveFailures = 0 - } - if !moving && retryAfterReset { - stage = "post-reset FC7" - if err := checkDeadline(); err != nil { - return stockStatus, err - } - log.Infof("[%s] reset settle wait completed; retrying card preparation", operation) - if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] post-reset retry command: %w", operation, err) - } - retryAfterReset = false - stage = "polling after reset and retry" - } else if !moving && !retried && !c.sequenceTiming.now().Before(recoveryAt) { - if prepareFailed && consecutiveFailures >= 2 { - stage = "RS recovery" - if err := checkDeadline(); err != nil { - return stockStatus, err - } - retried = true - resetAttempted = true - log.Warnf("[%s] persistent prepare failure; resetting dispenser, raw status: % X", operation, status) - if err := c.Reset(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] reset command: %w", operation, err) - } - stage = "reset settle" - if err := checkDeadline(); err != nil { - return stockStatus, err - } - log.Infof("[%s] reset dispatched; waiting for mechanical settling", operation) - wait := sequenceResetWait - if remaining := deadline.Sub(c.sequenceTiming.now()); remaining < wait { - wait = remaining - } - if err := c.sequenceTiming.wait(ctx, wait); err != nil { - return stockStatus, fmt.Errorf("[%s] reset settle: %w", operation, err) - } - retryAfterReset = true - stage = "post-reset status" - continue // Always read fresh physical status before the retry. - } - if !prepareFailed { - stage = "FC7 retry" - if err := checkDeadline(); err != nil { - return stockStatus, err - } - retried = true - if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] retry command: %w", operation, err) - } - } - } - - if err := checkDeadline(); err != nil { - return stockStatus, err - } - wait := sequencePollInterval - if remaining := deadline.Sub(c.sequenceTiming.now()); remaining < wait { - wait = remaining - } - if err := c.sequenceTiming.wait(ctx, wait); err != nil { - return stockStatus, fmt.Errorf("[%s] %s: %w", operation, stage, err) - } - } -} - // waitForDeliveryClearance reuses the first clear AP as the initial preparation sample. -// Its bounded window is separate from recovery, which starts after initial FC7. +// Its bounded window is separate from subsequent preparation and recovery. func (c *Client) waitForDeliveryClearance(ctx context.Context, operation string) (status []byte, stock string, resultErr error) { - ctx, cancel := context.WithTimeout(ctx, sequenceTimeout) + ctx, cancel := context.WithTimeout(ctx, deliveryClearanceTimeout) defer cancel() - deadline := c.sequenceTiming.now().Add(sequenceTimeout) + deadline := c.sequenceTiming.now().Add(deliveryClearanceTimeout) var lastStatus []byte defer func() { if resultErr != nil { @@ -634,26 +477,143 @@ func (c *Client) waitForDeliveryClearance(ctx context.Context, operation string) } } -func (c *Client) prepareCardAtEncoder(ctx context.Context, operation string) (string, error) { - status, stockStatus, err := c.waitForDeliveryClearance(ctx, operation) +func (c *Client) prepareCardAtEncoder(parent context.Context, operation string) (stock string, resultErr error) { + status, stock, err := c.waitForDeliveryClearance(parent, operation) if err != nil { - return stockStatus, err + return stock, err } - ready, err := preparationStatus(operation, status, true) - if err != nil { - return stockStatus, err + started := c.now() + deadline := started.Add(sequenceTimeout) + ctx, cancel := context.WithTimeoutCause(parent, sequenceTimeout, ErrPreparationExhausted) + defer cancel() + shakes := 0 + stage := "initial status" + var lastFC7, uncertainSince time.Time + var previous preparationClass + defer func() { + log.Infof("[%s] preparation finished; stage=%s shakes=%d elapsed=%s raw status: % X error=%v", operation, stage, shakes, c.now().Sub(started), status, resultErr) + }() + checkDeadline := func() error { + if err := parent.Err(); err != nil { + return err + } + if !c.now().Before(deadline) || errors.Is(context.Cause(ctx), ErrPreparationExhausted) { + return ErrPreparationExhausted + } + return ctx.Err() } - if ready { - return stockStatus, nil + wait := func(duration time.Duration) error { + if err := checkDeadline(); err != nil { + return err + } + if remaining := deadline.Sub(c.now()); remaining < duration { + duration = remaining + } + if err := c.sequenceTiming.wait(ctx, duration); err != nil { + if deadlineErr := checkDeadline(); deadlineErr != nil { + return deadlineErr + } + return err + } + return checkDeadline() } - - if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] to encoder: %w", operation, err) + sendFC7 := func() error { + stage = "FC7 dispatch" + if err := checkDeadline(); err != nil { + return err + } + err := c.ToEncoder(ctx) + if deadlineErr := checkDeadline(); deadlineErr != nil { + return deadlineErr + } + if err != nil { + return fmt.Errorf("[%s] FC7 dispatch: %w", operation, err) + } + lastFC7 = c.now() + log.Infof("[%s] FC7 dispatched; shake=%d elapsed=%s", operation, shakes, lastFC7.Sub(started)) + return nil + } + for { + if err := checkDeadline(); err != nil { + return stock, err + } + class, err := classifyPreparationStatus(status) + if err != nil { + return stock, err + } + log.Infof("[%s] fresh AP; class=%s previous=%s elapsed=%s shake=%d raw status: % X", operation, class, previous, c.now().Sub(started), shakes, status) + previous = class + switch class { + case encoderConfirmed: + stage = "encoder sensor handoff" + return stock, checkDeadline() + case positionWellEmpty: + stage = "empty" + return stock, ErrCardWellEmpty + } + if lastFC7.IsZero() { + if err := sendFC7(); err != nil { + return stock, err + } + } else if class == positionNoCard && c.now().Sub(lastFC7) >= sequenceShakeAfter { + uncertainSince = time.Time{} + if shakes == sequenceMaxShakes { + stage = "three shakes exhausted" + return stock, ErrPreparationExhausted + } + shakes++ + stage = "RS dispatch" + if err := checkDeadline(); err != nil { + return stock, err + } + err := c.Reset(ctx) + if deadlineErr := checkDeadline(); deadlineErr != nil { + return stock, deadlineErr + } + if err != nil { + return stock, fmt.Errorf("[%s] RS dispatch: %w", operation, err) + } + stage = "reset settling" + log.Infof("[%s] RS dispatched; shake=%d settling=%s", operation, shakes, sequenceResetWait) + if err := wait(sequenceResetWait); err != nil { + return stock, err + } + log.Infof("[%s] reset settle wait completed; shake=%d", operation, shakes) + if err := sendFC7(); err != nil { + return stock, err + } + } else { + if class == positionUncertain { + if uncertainSince.IsZero() { + uncertainSince = c.now() + } + if c.now().Sub(uncertainSince) >= sequenceUncertainWait { + stage = "uncertain position handoff" + return stock, checkDeadline() + } + } else { + uncertainSince = time.Time{} + } + stage = "polling" + if err := wait(sequencePollInterval); err != nil { + return stock, err + } + } + stage = "fresh AP" + if err := checkDeadline(); err != nil { + return stock, err + } + status, stock, err = c.readSequenceStatus(ctx, operation) + if deadlineErr := checkDeadline(); deadlineErr != nil { + return stock, deadlineErr + } + if err != nil { + return stock, err + } } - return c.pollForEncoderPosition(ctx, operation) } -// PrepareCurrentCard authoritatively places the card to be encoded at the encoder. +// PrepareCurrentCard grants one encoder opportunity after bounded physical preparation. func (c *Client) PrepareCurrentCard(ctx context.Context) (string, error) { return c.prepareCardAtEncoder(ctx, "PrepareCurrentCard") } @@ -668,15 +628,42 @@ func (c *Client) DeliverCurrentCard(ctx context.Context) (string, error) { return "", nil } -// BeginPrepareNextCard starts moving the next card to the encoder without waiting for readiness. +// BeginPrepareNextCard waits for delivery clearance and dispatches FC7 once, +// without waiting for encoder readiness. func (c *Client) BeginPrepareNextCard(ctx context.Context) error { - if err := c.ToEncoder(ctx); err != nil { - return fmt.Errorf("[BeginPrepareNextCard] to encoder: %w", err) + ctx, cancel := context.WithTimeout(ctx, deliveryClearanceTimeout) + defer cancel() + deadline := c.now().Add(deliveryClearanceTimeout) + for { + if err := ctx.Err(); err != nil { + return err + } + if !c.now().Before(deadline) { + return context.DeadlineExceeded + } + // The worker checks fresh AP while delivery is pending and dispatches + // FC7 only once clear, within the same ownership boundary. + err := c.ToEncoder(ctx) + if !errors.Is(err, errDeliveryPending) { + if err != nil { + return fmt.Errorf("[BeginPrepareNextCard] to encoder: %w", err) + } + return nil + } + wait := sequencePollInterval + if remaining := deadline.Sub(c.now()); remaining < wait { + wait = remaining + } + if wait <= 0 { + return context.DeadlineExceeded + } + if err := c.sequenceTiming.wait(ctx, wait); err != nil { + return err + } } - return nil } -// PrepareNextCard places a new card at the encoder for a later issuance attempt. +// PrepareNextCard runs the same bounded physical preparation for a later issuance attempt. func (c *Client) PrepareNextCard(ctx context.Context) (string, error) { return c.prepareCardAtEncoder(ctx, "PrepareNextCard") } diff --git a/internal/dispenser/dispenserclient_test.go b/internal/dispenser/dispenserclient_test.go index 6958a4b..4ac16cc 100644 --- a/internal/dispenser/dispenserclient_test.go +++ b/internal/dispenser/dispenserclient_test.go @@ -9,8 +9,6 @@ import ( "strings" "testing" "time" - - log "github.com/sirupsen/logrus" ) type fakeSequenceDevice struct { @@ -18,6 +16,7 @@ type fakeSequenceDevice struct { commandErrors map[cmdType][]error commands []cmdType commandTimes []time.Time + onCommand func(cmdType) } func newSequenceTestClient(t *testing.T, statusResponses ...cmdResp) (*Client, *fakeSequenceDevice) { @@ -55,6 +54,9 @@ func newSequenceTestClient(t *testing.T, statusResponses ...cmdResp) (*Client, * case request := <-client.reqCh: device.commands = append(device.commands, request.typ) device.commandTimes = append(device.commandTimes, now) + if device.onCommand != nil { + device.onCommand(request.typ) + } if request.typ == cmdStatus { if len(device.statusResponses) == 0 { request.respCh <- cmdResp{err: errors.New("unexpected status read")} @@ -94,200 +96,6 @@ func commandCount(commands []cmdType, target cmdType) int { return count } -func prepareFailureResponses(code byte, count int) []cmdResp { - responses := make([]cmdResp, count) - for i := range responses { - responses[i] = cmdResp{status: []byte{code, 0x30, 0x30, 0x30}} - } - return responses -} - -func TestPreparationResetRecovery(t *testing.T) { - for _, operation := range []string{"current", "next"} { - for _, code := range []byte{0x32, 0x36} { - t.Run(operation+string(rune(code)), func(t *testing.T) { - responses := prepareFailureResponses(code, 9) // Initial read, seven polls, post-reset read. - responses = append(responses, cmdResp{status: status(0x33)}) - client, device := newSequenceTestClient(t, responses...) - // An apparently fresh passive cache must never replace physical reads. - client.lastStatus = status(0x33) - client.lastStatusT = time.Now() - client.statusTTL = time.Hour - prepare := client.PrepareCurrentCard - if operation == "next" { - prepare = client.PrepareNextCard - } - if _, err := prepare(context.Background()); err != nil { - t.Fatalf("prepare(%s, %X) = %v, want success", operation, code, err) - } - want := []cmdType{cmdStatus, cmdToEncoder} - for i := 0; i < 7; i++ { - want = append(want, cmdStatus) - } - want = append(want, cmdReset, cmdStatus, cmdToEncoder, cmdStatus) - if !reflect.DeepEqual(device.commands, want) { - t.Errorf("prepare commands = %v, want %v", device.commands, want) - } - if len(device.commandTimes) != len(want) { - t.Fatalf("command times = %d, want %d", len(device.commandTimes), len(want)) - } - if elapsed := device.commandTimes[9].Sub(device.commandTimes[1]); elapsed != sequenceRetryAfter { - t.Errorf("RS elapsed = %s, want %s", elapsed, sequenceRetryAfter) - } - if elapsed := device.commandTimes[10].Sub(device.commandTimes[9]); elapsed != sequenceResetWait { - t.Errorf("post-reset status elapsed = %s, want %s", elapsed, sequenceResetWait) - } - }) - } - } - -} - -func TestPreparationFailureAfterReset(t *testing.T) { - for _, test := range []struct { - name string - code byte - wantError string - }{ - {"prepare failure times out", 0x32, "timed out"}, - {"combined failure is final", 0x36, "Command cannot execute"}, - } { - t.Run(test.name, func(t *testing.T) { - client, device := newSequenceTestClient(t, prepareFailureResponses(test.code, 30)...) - _, err := client.PrepareCurrentCard(context.Background()) - if err == nil || !strings.Contains(err.Error(), test.wantError) { - t.Errorf("PrepareCurrentCard(%X) error = %v, want %q", test.code, err, test.wantError) - } - if resets, commands := commandCount(device.commands, cmdReset), commandCount(device.commands, cmdToEncoder); resets != 1 || commands != 2 { - t.Errorf("recovery commands = %v, want one RS and two FC7", device.commands) - } - }) - } -} - -func TestPreparationHardErrorsNeverReset(t *testing.T) { - for _, failure := range [][]byte{ - {0x32, 0x30, 0x32, 0x30}, // Jam alongside prepare failure. - {0x36, 0x30, 0x34, 0x30}, // Overlap alongside combined failure. - {0x32, 0x30, 0x30, 0x38}, // Empty. - {0x36, 0x32, 0x30, 0x30}, // Independent dispense error. - {0x32, 0x31, 0x30, 0x30}, // Independent capture error. - {0x34, 0x30, 0x30, 0x30}, // Command rejection alone. - {0x30, 0x30, 0x30, 0x40}, // Unknown. - {0x32}, // Malformed. - } { - responses := prepareFailureResponses(0x32, 7) - responses = append(responses, cmdResp{status: failure}) - client, device := newSequenceTestClient(t, responses...) - if _, err := client.PrepareCurrentCard(context.Background()); err == nil { - t.Errorf("PrepareCurrentCard(% X) error = nil, want hard error", failure) - } - if got := commandCount(device.commands, cmdReset); got != 0 { - t.Errorf("PrepareCurrentCard(% X) resets = %d, want 0", failure, got) - } - } -} - -func TestPreparationProgressAtRecoveryThreshold(t *testing.T) { - for _, moving := range [][]byte{{0x31, 0x30, 0x30, 0x30}, {0x32, 0x38, 0x30, 0x30}} { - responses := prepareFailureResponses(0x32, 7) - responses = append(responses, cmdResp{status: moving}, cmdResp{status: moving}, cmdResp{status: status(0x33)}) - client, device := newSequenceTestClient(t, responses...) - if _, err := client.PrepareCurrentCard(context.Background()); err != nil { - t.Fatalf("PrepareCurrentCard(moving % X) = %v, want success", moving, err) - } - if commandCount(device.commands, cmdReset) != 0 || commandCount(device.commands, cmdToEncoder) != 1 { - t.Errorf("PrepareCurrentCard(moving % X) commands = %v, want initial FC7 only", moving, device.commands) - } - } -} - -func TestPreparationRequiresConsecutiveFailures(t *testing.T) { - responses := prepareFailureResponses(0x32, 7) - responses = append(responses, - cmdResp{status: []byte{0x31, 0x30, 0x30, 0x30}}, - cmdResp{status: []byte{0x32, 0x30, 0x30, 0x30}}, - cmdResp{status: status(0x33)}, - ) - client, device := newSequenceTestClient(t, responses...) - if _, err := client.PrepareCurrentCard(context.Background()); err != nil { - t.Fatal(err) - } - if got := commandCount(device.commands, cmdReset); got != 0 { - t.Errorf("PrepareCurrentCard(interrupted failure sequence) resets = %d, want 0", got) - } -} - -func TestPreparationPostResetStatus(t *testing.T) { - for _, test := range []struct { - name string - responses []cmdResp - wantFC7 int - wantError string - }{ - {"already at encoder", []cmdResp{{status: status(0x33)}}, 1, ""}, - {"moving then encoder", []cmdResp{{status: []byte{0x31, 0x30, 0x30, 0x30}}, {status: status(0x33)}}, 1, ""}, - {"moving then stationary", []cmdResp{{status: []byte{0x31, 0x30, 0x30, 0x30}}, {status: status(0x30)}, {status: status(0x33)}}, 2, ""}, - {"hard error", []cmdResp{{status: []byte{0x32, 0x30, 0x32, 0x30}}}, 1, "Card jammed"}, - {"read failure", []cmdResp{{err: errors.New("post-reset read failed")}}, 1, "post-reset read failed"}, - } { - t.Run(test.name, func(t *testing.T) { - responses := append(prepareFailureResponses(0x32, 8), test.responses...) - client, device := newSequenceTestClient(t, responses...) - _, err := client.PrepareCurrentCard(context.Background()) - if test.wantError == "" && err != nil { - t.Errorf("PrepareCurrentCard(%s) = %v, want success", test.name, err) - } - if test.wantError != "" && (err == nil || !strings.Contains(err.Error(), test.wantError)) { - t.Errorf("PrepareCurrentCard(%s) = %v, want %q", test.name, err, test.wantError) - } - if commandCount(device.commands, cmdReset) != 1 || commandCount(device.commands, cmdToEncoder) != test.wantFC7 { - t.Errorf("PrepareCurrentCard(%s) commands = %v, want one RS and %d FC7", test.name, device.commands, test.wantFC7) - } - }) - } -} - -func TestPreparationRecoveryCommandFailures(t *testing.T) { - for _, command := range []cmdType{cmdReset, cmdToEncoder} { - client, device := newSequenceTestClient(t, prepareFailureResponses(0x32, 9)...) - failure := errors.New("command failed") - device.commandErrors[command] = []error{failure} - wantFC7 := 1 - if command == cmdToEncoder { - device.commandErrors[command] = []error{nil, failure} - wantFC7 = 2 - } - _, err := client.PrepareCurrentCard(context.Background()) - if !errors.Is(err, failure) { - t.Errorf("PrepareCurrentCard(failed command %v) = %v, want %v", command, err, failure) - } - if commandCount(device.commands, cmdReset) != 1 || commandCount(device.commands, cmdToEncoder) != wantFC7 { - t.Errorf("PrepareCurrentCard(failed command %v) commands = %v, want one RS and %d FC7", command, device.commands, wantFC7) - } - } -} - -func TestPreparationCancellationDuringResetSettle(t *testing.T) { - client, device := newSequenceTestClient(t, prepareFailureResponses(0x32, 9)...) - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - wait := client.sequenceTiming.wait - client.sequenceTiming.wait = func(ctx context.Context, duration time.Duration) error { - if duration == sequenceResetWait { - cancel() - } - return wait(ctx, duration) - } - _, err := client.PrepareCurrentCard(ctx) - if !errors.Is(err, context.Canceled) { - t.Errorf("PrepareCurrentCard(cancel during reset) = %v, want context.Canceled", err) - } - if commandCount(device.commands, cmdReset) != 1 || commandCount(device.commands, cmdToEncoder) != 1 || device.commands[len(device.commands)-1] != cmdReset { - t.Errorf("PrepareCurrentCard(cancel during reset) commands = %v, want no commands after RS", device.commands) - } -} - func TestResetPacket(t *testing.T) { got := createPacket([]byte{0x30, 0x30}, commandRS) want := []byte{0x02, 0x30, 0x30, 0x00, 0x02, 0x52, 0x53, 0x03, 0x02} @@ -296,234 +104,6 @@ func TestResetPacket(t *testing.T) { } } -func TestPreparationDeadlineDuringResetSettle(t *testing.T) { - client, device := newSequenceTestClient(t, prepareFailureResponses(0x32, 4)...) - wait := client.sequenceTiming.wait - waits := 0 - client.sequenceTiming.wait = func(ctx context.Context, duration time.Duration) error { - waits++ - if waits == 1 { - // Simulate a delayed poll, leaving only one second for recovery. - duration = 15 * time.Second - } else if duration != time.Second { - t.Errorf("reset settle duration = %s, want remaining 1s", duration) - } - return wait(ctx, duration) - } - _, err := client.PrepareCurrentCard(context.Background()) - if err == nil || !strings.Contains(err.Error(), "timed out") { - t.Errorf("PrepareCurrentCard(late recovery) = %v, want timeout", err) - } - want := []cmdType{cmdStatus, cmdToEncoder, cmdStatus, cmdStatus, cmdReset} - if !reflect.DeepEqual(device.commands, want) { - t.Errorf("PrepareCurrentCard(late recovery) commands = %v, want %v", device.commands, want) - } -} - -func TestPreparationPlainRetryConsumesRecoveryBudget(t *testing.T) { - responses := make([]cmdResp, 8) - for i := range responses { - responses[i] = cmdResp{status: status(0x34)} - } - responses = append(responses, prepareFailureResponses(0x32, 20)...) - client, device := newSequenceTestClient(t, responses...) - _, err := client.PrepareCurrentCard(context.Background()) - if err == nil || !strings.Contains(err.Error(), "timed out") { - t.Errorf("PrepareCurrentCard(failure after plain retry) = %v, want timeout", err) - } - if commandCount(device.commands, cmdReset) != 0 || commandCount(device.commands, cmdToEncoder) != 2 { - t.Errorf("PrepareCurrentCard(failure after plain retry) commands = %v, want two FC7 and no RS", device.commands) - } -} - -func TestPreparationFirstAttemptDoesNotReset(t *testing.T) { - for _, failures := range []int{0, 2} { - responses := []cmdResp{{status: status(0x34)}} - responses = append(responses, prepareFailureResponses(0x32, failures)...) - responses = append(responses, cmdResp{status: status(0x33)}) - client, device := newSequenceTestClient(t, responses...) - if _, err := client.PrepareCurrentCard(context.Background()); err != nil { - t.Errorf("PrepareCurrentCard(%d transient failures) = %v, want success", failures, err) - } - if commandCount(device.commands, cmdReset) != 0 || commandCount(device.commands, cmdToEncoder) != 1 { - t.Errorf("PrepareCurrentCard(%d transient failures) commands = %v, want one FC7 and no RS", failures, device.commands) - } - } -} - -func TestPrepareCurrentCardAcceptsEncoderPositionWithStaleDiagnostics(t *testing.T) { - tests := []struct { - name string - status []byte - wantStock string - }{ - { - name: "dispense error and jam", - status: []byte{0x30, 0x32, 0x32, 0x33}, - wantStock: "Card jammed", - }, - { - name: "supply diagnostics", - status: []byte{0x32, 0x30, 0x31, 0x33}, - wantStock: "Card pre-empty", - }, - { - name: "combined stale jam and supply diagnostics", - status: []byte{0x30, 0x32, 0x33, 0x33}, - }, - } - - for _, test := range tests { - t.Run(test.name, func(t *testing.T) { - var logOutput bytes.Buffer - standardLogger := log.StandardLogger() - previousOutput := standardLogger.Out - standardLogger.SetOutput(&logOutput) - t.Cleanup(func() { - standardLogger.SetOutput(previousOutput) - }) - - client, device := newSequenceTestClient(t, cmdResp{status: test.status}) - - stock, err := client.PrepareCurrentCard(context.Background()) - if err != nil { - t.Fatal(err) - } - if stock != test.wantStock { - t.Fatalf("stock status = %q, want %q", stock, test.wantStock) - } - if got := commandCount(device.commands, cmdToEncoder); got != 0 { - t.Fatalf("to-encoder commands = %d, want 0", got) - } - if got := commandCount(device.commands, cmdStatus); got != 1 { - t.Fatalf("status reads = %d, want 1", got) - } - logged := logOutput.String() - if !strings.Contains(logged, "card confirmed at encoder") || - !strings.Contains(logged, statusDescription(test.status)) || - !strings.Contains(logged, "raw status") { - t.Fatalf("encoder diagnostic log = %q", logged) - } - }) - } -} - -func TestPrepareCurrentCardToleratesTransientPrepareFailureUntilEncoder(t *testing.T) { - client, device := newSequenceTestClient(t, - cmdResp{status: []byte{0x32, 0x30, 0x30, 0x30}}, - cmdResp{status: []byte{0x32, 0x30, 0x30, 0x30}}, - cmdResp{status: []byte{0x32, 0x30, 0x30, 0x30}}, - cmdResp{status: []byte{0x32, 0x30, 0x30, 0x33}}, - ) - - stock, err := client.PrepareCurrentCard(context.Background()) - if err != nil { - t.Fatal(err) - } - if stock != "Preparing card fails" { - t.Fatalf("stock status = %q, want Preparing card fails", stock) - } - if got := commandCount(device.commands, cmdToEncoder); got != 1 { - t.Fatalf("to-encoder commands = %d, want 1", got) - } - if got := commandCount(device.commands, cmdStatus); got != 4 { - t.Fatalf("status reads = %d, want 4", got) - } -} - -func TestPrepareCurrentCardDoesNotMaskHardErrorAlongsideTransientPrepareFailure(t *testing.T) { - client, _ := newSequenceTestClient(t, - cmdResp{status: []byte{0x32, 0x30, 0x32, 0x30}}, - ) - - _, err := client.PrepareCurrentCard(context.Background()) - if err == nil || !strings.Contains(err.Error(), "Card jammed") { - t.Fatalf("error = %v, want Card jammed", err) - } -} - -func TestPrepareCurrentCardPollingAllowsTransientMovementWithStaleErrors(t *testing.T) { - client, device := newSequenceTestClient(t, - cmdResp{status: status(0x34)}, - cmdResp{status: []byte{0x31, 0x38, 0x32, 0x30}}, - cmdResp{status: []byte{0x30, 0x32, 0x32, 0x33}}, - ) - - stock, err := client.PrepareCurrentCard(context.Background()) - if err != nil { - t.Fatal(err) - } - if stock != "Card jammed" { - t.Fatalf("stock status = %q, want Card jammed", stock) - } - if got := commandCount(device.commands, cmdToEncoder); got != 1 { - t.Fatalf("to-encoder commands = %d, want 1", got) - } - if got := commandCount(device.commands, cmdStatus); got != 3 { - t.Fatalf("status reads = %d, want 3", got) - } -} - -func TestPrepareCurrentCardRejectsFailureWithoutEncoderOrMovement(t *testing.T) { - tests := []struct { - name string - response cmdResp - wantError string - wantStock string - }{ - { - name: "status read error", - response: cmdResp{err: errors.New("serial read failed")}, - wantError: "serial read failed", - }, - { - name: "malformed status", - response: cmdResp{status: []byte{0x30, 0x30, 0x31}}, - wantError: "malformed dispenser status", - }, - { - name: "unknown status", - response: cmdResp{status: []byte{0x30, 0x30, 0x30, 0x40}}, - wantError: "unknown dispenser status", - }, - { - name: "jammed preparation", - response: cmdResp{status: []byte{0x30, 0x30, 0x32, 0x34}}, - wantError: "Card jammed", - wantStock: "Card jammed", - }, - } - - for _, test := range tests { - t.Run(test.name, func(t *testing.T) { - client, _ := newSequenceTestClient(t, test.response) - - stock, err := client.PrepareCurrentCard(context.Background()) - if err == nil || !strings.Contains(err.Error(), test.wantError) { - t.Fatalf("error = %v, want containing %q", err, test.wantError) - } - if stock != test.wantStock { - t.Fatalf("stock status = %q, want %q", stock, test.wantStock) - } - }) - } -} - -func TestPrepareCurrentCardReturnsAuthoritativeEmptyWellError(t *testing.T) { - client, device := newSequenceTestClient(t, cmdResp{status: status(0x38)}) - - stock, err := client.PrepareCurrentCard(context.Background()) - if !errors.Is(err, ErrCardWellEmpty) { - t.Fatalf("error = %v, want ErrCardWellEmpty", err) - } - if stock != "Card empty" { - t.Fatalf("stock status = %q, want Card empty", stock) - } - if got := commandCount(device.commands, cmdToEncoder); got != 0 { - t.Fatalf("to-encoder commands = %d, want 0", got) - } -} - func TestDeliverCurrentCardSucceedsAfterCommandAcceptanceWithoutStatusPolling(t *testing.T) { staleStatus := []byte{0x30, 0x32, 0x32, 0x33} client, device := newSequenceTestClient(t, cmdResp{status: staleStatus}) @@ -586,42 +166,6 @@ func TestDeliverCurrentCardPreservesContextCancellation(t *testing.T) { } } -func TestPrepareCurrentCardRetriesOnceThenTimesOut(t *testing.T) { - responses := make([]cmdResp, 17) - for index := range responses { - responses[index] = cmdResp{status: status(0x34)} - } - client, device := newSequenceTestClient(t, responses...) - - _, err := client.PrepareCurrentCard(context.Background()) - if err == nil || !strings.Contains(err.Error(), "timed out") { - t.Fatalf("error = %v, want preparation timeout", err) - } - if got := commandCount(device.commands, cmdToEncoder); got != 2 { - t.Fatalf("to-encoder commands = %d, want initial command plus one halfway retry", got) - } - if got := commandCount(device.commands, cmdStatus); got != 17 { - t.Fatalf("status reads = %d, want 17", got) - } -} - -func TestPrepareCurrentCardPropagatesContextCancellation(t *testing.T) { - client, _ := newSequenceTestClient(t, - cmdResp{status: status(0x34)}, - cmdResp{status: status(0x34)}, - ) - ctx, cancel := context.WithCancel(context.Background()) - client.sequenceTiming.wait = func(context.Context, time.Duration) error { - cancel() - return ctx.Err() - } - - _, err := client.PrepareCurrentCard(ctx) - if !errors.Is(err, context.Canceled) { - t.Fatalf("error = %v, want context.Canceled", err) - } -} - func TestBeginPrepareNextCardDispatchesWithoutReadinessPolling(t *testing.T) { client, device := newSequenceTestClient(t) @@ -652,160 +196,6 @@ func TestBeginPrepareNextCardReturnsDispatchFailureWithoutPolling(t *testing.T) } } -func TestPrepareCardAtEncoderRequiresConfirmedEncoderState(t *testing.T) { - tests := []struct { - name string - responses []cmdResp - wantError string - wantToEncoder int - }{ - { - name: "already at encoder", - responses: []cmdResp{{status: status(0x33)}}, - wantToEncoder: 0, - }, - { - name: "moves ready card to encoder", - responses: []cmdResp{ - {status: status(0x34)}, - {status: status(0x33)}, - }, - wantToEncoder: 1, - }, - { - name: "empty card well", - responses: []cmdResp{{status: status(0x38)}}, - wantError: CardWellEmptyMessage, - wantToEncoder: 0, - }, - } - - for _, test := range tests { - t.Run(test.name, func(t *testing.T) { - client, device := newSequenceTestClient(t, test.responses...) - - _, err := client.PrepareNextCard(context.Background()) - if test.wantError == "" && err != nil { - t.Fatal(err) - } - if test.wantError != "" && (err == nil || !strings.Contains(err.Error(), test.wantError)) { - t.Fatalf("error = %v, want containing %q", err, test.wantError) - } - if got := commandCount(device.commands, cmdToEncoder); got != test.wantToEncoder { - t.Fatalf("to-encoder commands = %d, want %d", got, test.wantToEncoder) - } - }) - } -} - -func TestPositionFlags(t *testing.T) { - for position := byte(0x30); position <= 0x3F; position++ { - t.Run(fmt.Sprintf("%02X", position), func(t *testing.T) { - st := status(position) - wantEncoder := position&0x02 != 0 - wantEmpty := position&0x08 != 0 - if got := isAtEncoderPosition(st); got != wantEncoder { - t.Errorf("isAtEncoderPosition(% X) = %t, want %t", st, got, wantEncoder) - } - if got := isCardWellEmpty(st); got != wantEmpty { - t.Errorf("isCardWellEmpty(% X) = %t, want %t", st, got, wantEmpty) - } - if err := validateDispenserStatusData(st); err != nil { - t.Errorf("validateDispenserStatusData(% X) = %v, want nil", st, err) - } - ready, err := preparationStatus("test", st, true) - if ready != wantEncoder { - t.Errorf("preparationStatus(% X) ready = %t, want %t", st, ready, wantEncoder) - } - wantEmptyError := wantEmpty && !wantEncoder - if errors.Is(err, ErrCardWellEmpty) != wantEmptyError || (err != nil && !wantEmptyError) { - t.Errorf("preparationStatus(% X) error = %v, want empty error %t", st, err, wantEmptyError) - } - wantStock := "" - if wantEmpty { - wantStock = "Card empty" - } - if got := stockTake(st); got != wantStock { - t.Errorf("stockTake(% X) = %q, want %q", st, got, wantStock) - } - }) - } -} - -func TestEncoderPositionPrecedesDiagnostics(t *testing.T) { - for _, position := range []byte{0x32, 0x33, 0x36, 0x37, 0x3A, 0x3B, 0x3E, 0x3F} { - for _, diagnostics := range [][]byte{ - {0x30, 0x30, 0x30}, - {0x32, 0x30, 0x30}, - {0x36, 0x30, 0x30}, - {0x34, 0x32, 0x32}, - {0x30, 0x31, 0x34}, - {0xFF, 0xFF, 0xFF}, - } { - st := append(append([]byte(nil), diagnostics...), position) - for _, operation := range []string{"current", "next"} { - t.Run(fmt.Sprintf("%s/% X", operation, st), func(t *testing.T) { - client, device := newSequenceTestClient(t, cmdResp{status: st}) - prepare := client.PrepareCurrentCard - if operation == "next" { - prepare = client.PrepareNextCard - } - if _, err := prepare(context.Background()); err != nil { - t.Errorf("prepare(% X) = %v, want success", st, err) - } - want := []cmdType{cmdStatus} - if !reflect.DeepEqual(device.commands, want) { - t.Errorf("prepare(% X) commands = %v, want %v", st, device.commands, want) - } - }) - } - } - } -} - -func TestCombinedEncoderPositionStopsRecovery(t *testing.T) { - for _, afterReset := range []bool{false, true} { - t.Run(fmt.Sprintf("afterReset=%t", afterReset), func(t *testing.T) { - count := 7 // Encoder confirmation at the recovery threshold, before RS. - wantResets := 0 - if afterReset { - count = 8 // Encoder confirmation on the fresh post-reset read. - wantResets = 1 - } - responses := append(prepareFailureResponses(0x32, count), cmdResp{status: []byte{0x36, 0x32, 0x34, 0x3F}}) - client, device := newSequenceTestClient(t, responses...) - if _, err := client.PrepareCurrentCard(context.Background()); err != nil { - t.Errorf("PrepareCurrentCard(combined encoder) = %v, want success", err) - } - if got := commandCount(device.commands, cmdReset); got != wantResets { - t.Errorf("PrepareCurrentCard(combined encoder) RS count = %d, want %d", got, wantResets) - } - if got := commandCount(device.commands, cmdToEncoder); got != 1 { - t.Errorf("PrepareCurrentCard(combined encoder) FC7 count = %d, want 1", got) - } - }) - } -} - -func TestInvalidPositionEncoding(t *testing.T) { - for _, st := range [][]byte{nil, {0x30, 0x30, 0x30}, status(0x02), status(0x2F), status(0x40), status(0x72), status(0xFF)} { - if isAtEncoderPosition(st) || isCardWellEmpty(st) { - t.Errorf("invalid status % X confirmed encoder or empty, want neither", st) - } - if ready, err := preparationStatus("test", st, true); ready || err == nil { - t.Errorf("preparationStatus(% X) = (%t, %v), want false and error", st, ready, err) - } - } - st := []byte{0xFF, 0xFF, 0xFF, 0x37, 0xFF} - if ready, err := preparationStatus("test", st, false); !ready || err != nil { - t.Errorf("preparationStatus(% X) = (%t, %v), want encoder precedence", st, ready, err) - } - st = append(status(0x35), 0xFF) - if ready, err := preparationStatus("test", st, true); ready || err == nil { - t.Errorf("preparationStatus(% X) = (%t, %v), want malformed error", st, ready, err) - } -} - func TestPositionDescriptions(t *testing.T) { for _, test := range []struct { position byte @@ -825,3 +215,305 @@ func TestPositionDescriptions(t *testing.T) { } } } + +func positionResponses(position byte, count int) []cmdResp { + responses := make([]cmdResp, count) + for i := range responses { + responses[i] = cmdResp{status: status(position)} + } + return responses +} + +func TestPreparationClasses(t *testing.T) { + classes := map[preparationClass][]byte{ + encoderConfirmed: {0x32, 0x33, 0x36, 0x37, 0x3A, 0x3B, 0x3E, 0x3F}, + positionUncertain: {0x31, 0x34, 0x35, 0x39, 0x3C, 0x3D}, + positionWellEmpty: {0x38}, positionNoCard: {0x30}, + } + for want, positions := range classes { + for _, position := range positions { + st := []byte{0xFF, 0x36, 0x32, position} + if got, err := classifyPreparationStatus(st); got != want || err != nil { + t.Errorf("classify(% X)=%s,%v, want %s", st, got, err, want) + } + } + } + for _, st := range [][]byte{nil, {0x30}, status(0x02), status(0x40), status(0xFF), {0x30, 0x30, 0x30, 0x37, 0x30}} { + if got, err := classifyPreparationStatus(st); err == nil { + t.Errorf("classify(% X)=%s,nil, want malformed error", st, got) + } + } +} + +func TestPreparationAllPositionsBothMethods(t *testing.T) { + for _, next := range []bool{false, true} { + for position := byte(0x30); position <= 0x3F; position++ { + t.Run(fmt.Sprintf("next=%t/position=%X", next, position), func(t *testing.T) { + responses := positionResponses(position, 40) + for i := range responses { + responses[i].status[0], responses[i].status[1], responses[i].status[2] = 0xFF, 0x38, 0x34 + } + c, d := newSequenceTestClient(t, responses...) + // Passive encoder data must never replace fresh AP. + c.lastStatus, c.lastStatusT, c.statusTTL = status(0x33), time.Now(), time.Hour + prepare := c.PrepareCurrentCard + if next { + prepare = c.PrepareNextCard + } + started := c.now() + _, err := prepare(context.Background()) + wantFC7, wantRS, wantElapsed := 0, 0, time.Duration(0) + var wantErr error + switch position { + case 0x30: + wantFC7, wantRS, wantElapsed, wantErr = 4, 3, 18*time.Second, ErrPreparationExhausted + case 0x38: + wantErr = ErrCardWellEmpty + case 0x31, 0x34, 0x35, 0x39, 0x3C, 0x3D: + wantFC7, wantElapsed = 1, 4*time.Second + } + if !errors.Is(err, wantErr) { + t.Errorf("prepare(%X) error=%v, want %v", position, err, wantErr) + } + if commandCount(d.commands, cmdToEncoder) != wantFC7 || commandCount(d.commands, cmdReset) != wantRS { + t.Errorf("prepare(%X) commands=%v, want FC7=%d RS=%d", position, d.commands, wantFC7, wantRS) + } + if got := c.now().Sub(started); got != wantElapsed { + t.Errorf("prepare(%X) elapsed=%s, want %s", position, got, wantElapsed) + } + }) + } + } +} + +func TestThreeShakesAreRequestLocalAndSettled(t *testing.T) { + c, d := newSequenceTestClient(t, positionResponses(0x30, 34)...) + for request := 0; request < 2; request++ { + start := len(d.commands) + if _, err := c.PrepareCurrentCard(context.Background()); !errors.Is(err, ErrPreparationExhausted) { + t.Fatalf("request %d error=%v, want exhausted", request, err) + } + want := []cmdType{cmdStatus, cmdToEncoder} + for attempt := 0; attempt < 4; attempt++ { + want = append(want, cmdStatus, cmdStatus, cmdStatus, cmdStatus) + if attempt < 3 { + want = append(want, cmdReset, cmdToEncoder) + } + } + if !reflect.DeepEqual(d.commands[start:], want) { + t.Errorf("request %d commands=%v, want %v", request, d.commands[start:], want) + } + var lastFC7 time.Time + for i := start; i < len(d.commands); i++ { + if d.commands[i] == cmdReset && d.commandTimes[i].Sub(lastFC7) != 3*time.Second { + t.Errorf("RS at %s after FC7, want 3s", d.commandTimes[i].Sub(lastFC7)) + } + if d.commands[i] == cmdToEncoder { + if i > start && d.commands[i-1] == cmdReset && d.commandTimes[i].Sub(d.commandTimes[i-1]) != 2*time.Second { + t.Errorf("FC7 settle=%s, want 2s", d.commandTimes[i].Sub(d.commandTimes[i-1])) + } + lastFC7 = d.commandTimes[i] + } + } + } +} + +func TestPreparationReclassifiesEverySample(t *testing.T) { + for _, tc := range []struct { + name string + positions []byte + wantRS int + wantTime time.Duration + wantErr error + }{ + {"uncertain changes do not restart timer", []byte{0x30, 0x31, 0x34, 0x35, 0x39, 0x3C}, 0, 4 * time.Second, nil}, + {"uncertain becomes encoder", []byte{0x30, 0x34, 0x37}, 0, time.Second, nil}, + {"uncertain becomes empty", []byte{0x30, 0x34, 0x38}, 0, time.Second, ErrCardWellEmpty}, + {"no sensors becomes empty", []byte{0x30, 0x30, 0x38}, 0, time.Second, ErrCardWellEmpty}, + {"uncertain returns to shake path twice", []byte{0x30, 0x34, 0x30, 0x30, 0x30, 0x34, 0x34, 0x30, 0x30, 0x37}, 2, 10 * time.Second, nil}, + } { + t.Run(tc.name, func(t *testing.T) { + var responses []cmdResp + for _, p := range tc.positions { + responses = append(responses, cmdResp{status: status(p)}) + } + c, d := newSequenceTestClient(t, responses...) + start := c.now() + _, err := c.PrepareCurrentCard(context.Background()) + if !errors.Is(err, tc.wantErr) || c.now().Sub(start) != tc.wantTime || commandCount(d.commands, cmdReset) != tc.wantRS { + t.Errorf("prepare(%s) error=%v elapsed=%s commands=%v, want error=%v time=%s RS=%d", tc.name, err, c.now().Sub(start), d.commands, tc.wantErr, tc.wantTime, tc.wantRS) + } + }) + } +} + +func TestEveryShakeReclassifiesEncoderEmptyAndUncertain(t *testing.T) { + for shake := 1; shake <= 3; shake++ { + for _, position := range []byte{0x37, 0x38, 0x35} { + responses := positionResponses(0x30, 1+4*shake) + responses = append(responses, positionResponses(position, 5)...) + c, d := newSequenceTestClient(t, responses...) + _, err := c.PrepareCurrentCard(context.Background()) + var wantErr error + if position == 0x38 { + wantErr = ErrCardWellEmpty + } + if !errors.Is(err, wantErr) || commandCount(d.commands, cmdReset) != shake || commandCount(d.commands, cmdToEncoder) != shake+1 { + t.Errorf("shake %d position=%X error=%v commands=%v, want %v and no further shake", shake, position, err, d.commands, wantErr) + } + } + } +} + +func TestPreparationTransportAndDispatchFailuresDoNotShake(t *testing.T) { + failure := errors.New("serial failure") + for _, response := range []cmdResp{{err: failure}, {status: []byte{0x30}}, {status: status(0x40)}} { + c, d := newSequenceTestClient(t, cmdResp{status: status(0x30)}, response) + if _, err := c.PrepareCurrentCard(context.Background()); err == nil || errors.Is(err, ErrPreparationExhausted) { + t.Errorf("AP failure %v error=%v, want transport/malformed error", response, err) + } + if commandCount(d.commands, cmdToEncoder) != 1 || commandCount(d.commands, cmdReset) != 0 { + t.Errorf("AP failure commands=%v, want FC7 once and no RS", d.commands) + } + } + for _, command := range []cmdType{cmdToEncoder, cmdReset} { + c, d := newSequenceTestClient(t, positionResponses(0x30, 10)...) + d.commandErrors[command] = []error{failure} + if _, err := c.PrepareCurrentCard(context.Background()); !errors.Is(err, failure) { + t.Errorf("command %v error=%v, want serial failure", command, err) + } + if commandCount(d.commands, command) != 1 { + t.Errorf("command %v retried: %v", command, d.commands) + } + } +} + +func TestPreparationStopsAtCancellationAndDeadlineStages(t *testing.T) { + for _, stage := range []string{"initial AP", "FC7", "poll", "RS", "settle"} { + for _, callerCanceled := range []bool{false, true} { + t.Run(fmt.Sprintf("%s/cancel=%t", stage, callerCanceled), func(t *testing.T) { + c, d := newSequenceTestClient(t, positionResponses(0x30, 30)...) + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + now := c.now() + c.sequenceTiming.now = func() time.Time { return now } + stoppedAt := -1 + stop := func() { + if stoppedAt >= 0 { + return + } + stoppedAt = len(d.commands) + if callerCanceled { + cancel() + } else { + now = now.Add(sequenceTimeout) + } + } + c.sequenceTiming.wait = func(_ context.Context, duration time.Duration) error { + now = now.Add(duration) + if (stage == "poll" && duration == sequencePollInterval) || (stage == "settle" && duration == sequenceResetWait) { + stop() + } + return nil + } + d.onCommand = func(cmd cmdType) { + if (stage == "initial AP" && cmd == cmdStatus) || (stage == "FC7" && cmd == cmdToEncoder) || (stage == "RS" && cmd == cmdReset) { + stop() + } + } + _, err := c.PrepareCurrentCard(ctx) + wantErr := error(ErrPreparationExhausted) + if callerCanceled { + wantErr = context.Canceled + } else if stage == "initial AP" { + wantErr = context.DeadlineExceeded + } + if !errors.Is(err, wantErr) || len(d.commands) != stoppedAt { + t.Errorf("stage=%s cancel=%t error=%v commands=%v stoppedAt=%d, want %v and no commands after stop", stage, callerCanceled, err, d.commands, stoppedAt, wantErr) + } + }) + } + } +} + +func TestPositionFlagsRemainDiagnostic(t *testing.T) { + for position := byte(0x30); position <= 0x3F; position++ { + st := status(position) + if got := isAtEncoderPosition(st); got != (position&0x02 != 0) { + t.Errorf("encoder sensor(%X)=%t", position, got) + } + if got := isCardWellEmpty(st); got != (position&0x08 != 0) { + t.Errorf("stock empty flag(%X)=%t", position, got) + } + wantStock := "" + if position&0x08 != 0 { + wantStock = "Card empty" + } + if got := stockTake(st); got != wantStock { + t.Errorf("stockTake(%X)=%q, want %q", position, got, wantStock) + } + } +} + +func TestPreparationCallerDeadlineIsNotRetryableExhaustion(t *testing.T) { + c, d := newSequenceTestClient(t) + ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(-time.Second)) + defer cancel() + _, err := c.PrepareCurrentCard(ctx) + if !errors.Is(err, context.DeadlineExceeded) || errors.Is(err, ErrPreparationExhausted) || len(d.commands) != 0 { + t.Errorf("expired caller: err=%v commands=%v, want caller deadline and no commands", err, d.commands) + } +} + +func TestPreparationExpiredEncoderSampleDoesNotHandoff(t *testing.T) { + c, d := newSequenceTestClient(t, cmdResp{status: status(0x30)}, cmdResp{status: status(0x37)}) + now := c.now() + c.sequenceTiming.now = func() time.Time { return now } + d.onCommand = func(cmd cmdType) { + if cmd == cmdStatus && commandCount(d.commands, cmdStatus) == 2 { + now = now.Add(sequenceTimeout) + } + } + _, err := c.PrepareCurrentCard(context.Background()) + if !errors.Is(err, ErrPreparationExhausted) { + t.Errorf("late encoder sample: err=%v, want preparation exhausted", err) + } + if len(d.commands) != 3 { + t.Errorf("late encoder sample commands=%v, want AP FC7 AP", d.commands) + } +} + +func TestBeginPrepareNextCardStopsWhileDeliveryPending(t *testing.T) { + for _, mode := range []string{"cancel", "deadline", "clearance timeout", "transport failure"} { + t.Run(mode, func(t *testing.T) { + c, d := newSequenceTestClient(t) + d.commandErrors[cmdToEncoder] = []error{errDeliveryPending} + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + wantErr := error(context.Canceled) + c.sequenceTiming.wait = func(context.Context, time.Duration) error { + cancel() + return context.Canceled + } + switch mode { + case "deadline": + wantErr = context.DeadlineExceeded + c.sequenceTiming.wait = func(context.Context, time.Duration) error { return context.DeadlineExceeded } + case "clearance timeout": + wantErr = context.DeadlineExceeded + now := c.now() + c.sequenceTiming.now = func() time.Time { return now } + c.sequenceTiming.wait = func(context.Context, time.Duration) error { now = now.Add(deliveryClearanceTimeout); return nil } + case "transport failure": + wantErr = errors.New("AP read failed") + d.commandErrors[cmdToEncoder] = []error{wantErr} + } + if err := c.BeginPrepareNextCard(ctx); !errors.Is(err, wantErr) { + t.Errorf("BeginPrepareNextCard(%s) = %v, want %v", mode, err, wantErr) + } + if !reflect.DeepEqual(d.commands, []cmdType{cmdToEncoder}) { + t.Errorf("BeginPrepareNextCard(%s) commands = %v, want one guarded FC7 request", mode, d.commands) + } + }) + } +} diff --git a/internal/handlers/doorcard_handlers_test.go b/internal/handlers/doorcard_handlers_test.go index ff217a9..5947edd 100644 --- a/internal/handlers/doorcard_handlers_test.go +++ b/internal/handlers/doorcard_handlers_test.go @@ -140,6 +140,13 @@ func TestIssueDoorCardPhysicalOutcomeContract(t *testing.T) { wantCalls: []string{"prepare current"}, wantCardWell: "Card empty", }, + { + name: "exhausted preparation is retryable without encoding or delivery", + dispenser: fakeDoorCardDispenser{prepareCurrent: dispenserCallResult{err: errors.Join(errors.New("preparation"), dispenser.ErrPreparationExhausted)}}, + wantHTTP: http.StatusBadGateway, + wantMessage: "preparation\ncard preparation exhausted", + wantCalls: []string{"prepare current"}, + }, { name: "encoding and accepted delivery command succeed", wantHTTP: http.StatusOK, @@ -148,13 +155,13 @@ func TestIssueDoorCardPhysicalOutcomeContract(t *testing.T) { wantLockSequence: 1, }, { - name: "successful encoding with delivery command failure is unavailable", + name: "successful encoding with delivery command failure still prestages and succeeds", dispenser: fakeDoorCardDispenser{ deliverCurrent: dispenserCallResult{status: "Card jammed", err: errors.New("delivery jammed")}, }, - wantHTTP: http.StatusServiceUnavailable, - wantMessage: "Card delivery could not be confirmed", - wantCalls: []string{"prepare current", "deliver current"}, + wantHTTP: http.StatusOK, + wantMessage: "Card issued successfully", + wantCalls: []string{"prepare current", "deliver current", "begin prepare next"}, wantLockSequence: 1, wantCardWell: "Card jammed", }, @@ -179,36 +186,35 @@ func TestIssueDoorCardPhysicalOutcomeContract(t *testing.T) { wantLockSequence: 1, }, { - name: "encoding failure with safe recovery remains retryable", + name: "encoding failure ends after delivery", lockErr: encodingErr, wantHTTP: http.StatusBadGateway, wantMessage: encodingErr.Error(), - wantCalls: []string{"prepare current", "deliver current", "prepare next"}, + wantCalls: []string{"prepare current", "deliver current"}, wantLockSequence: 1, }, { - name: "encoding failure with failed-card delivery failure is unavailable", + name: "encoding failure remains retryable despite FC0 failure", dispenser: fakeDoorCardDispenser{ deliverCurrent: dispenserCallResult{status: "Card jammed", err: errors.New("delivery jammed")}, }, lockErr: encodingErr, - wantHTTP: http.StatusServiceUnavailable, - wantMessage: "Dispenser recovery failed; another encoding attempt is not safe", + wantHTTP: http.StatusBadGateway, + wantMessage: encodingErr.Error(), wantCalls: []string{"prepare current", "deliver current"}, wantLockSequence: 1, wantCardWell: "Card jammed", }, { - name: "encoding failure with empty card well has stable message", + name: "encoding failure never prepares next card", dispenser: fakeDoorCardDispenser{ prepareNext: dispenserCallResult{status: "Card empty", err: dispenser.ErrCardWellEmpty}, }, lockErr: encodingErr, - wantHTTP: http.StatusServiceUnavailable, - wantMessage: dispenser.CardWellEmptyMessage, - wantCalls: []string{"prepare current", "deliver current", "prepare next"}, + wantHTTP: http.StatusBadGateway, + wantMessage: encodingErr.Error(), + wantCalls: []string{"prepare current", "deliver current"}, wantLockSequence: 1, - wantCardWell: "Card empty", }, } @@ -321,3 +327,29 @@ func TestIssueDoorCardLogsNextCardDispatchFailureAndStillSucceeds(t *testing.T) t.Fatalf("dispatch failure log = %q", logged) } } + +func TestIssueDoorCardLogsDeliveryFailureWithoutReplacingEncoderOutcome(t *testing.T) { + for _, encodingErr := range []error{nil, errors.New("original encoder failure")} { + var output bytes.Buffer + logger := log.StandardLogger() + previous := logger.Out + logger.SetOutput(&output) + d := &fakeDoorCardDispenser{deliverCurrent: dispenserCallResult{err: errors.New("FC0 dispatch failed")}} + lock := &fakeDoorCardLockServer{sequenceErr: encodingErr} + recorder, response, _ := performIssueDoorCardRequest(t, d, lock) + logger.SetOutput(previous) + wantHTTP := http.StatusOK + if encodingErr != nil { + wantHTTP = http.StatusBadGateway + } + if recorder.Code != wantHTTP { + t.Errorf("issueDoorCard(%v) HTTP = %d, want %d", encodingErr, recorder.Code, wantHTTP) + } + if encodingErr != nil && response.Message != encodingErr.Error() { + t.Errorf("issueDoorCard message = %q, want %q", response.Message, encodingErr.Error()) + } + if !strings.Contains(output.String(), "FC0 dispatch failed") || !strings.Contains(output.String(), "Card delivery") { + t.Errorf("issueDoorCard delivery log = %q, want FC0 failure and Card delivery", output.String()) + } + } +} diff --git a/internal/handlers/handlers.go b/internal/handlers/handlers.go index b835309..dc55259 100644 --- a/internal/handlers/handlers.go +++ b/internal/handlers/handlers.go @@ -6,7 +6,6 @@ import ( "encoding/json" "encoding/xml" "errors" - "fmt" "io" "net/http" "strings" @@ -299,6 +298,10 @@ func (app *App) issueDoorCard(w http.ResponseWriter, r *http.Request) { errorhandlers.WriteError(w, http.StatusServiceUnavailable, dispenser.CardWellEmptyMessage) return } + if errors.Is(err, dispenser.ErrPreparationExhausted) { + errorhandlers.WriteError(w, http.StatusBadGateway, err.Error()) + return + } errorhandlers.WriteError(w, http.StatusServiceUnavailable, "Dispense error: "+err.Error()) return } @@ -307,8 +310,11 @@ func (app *App) issueDoorCard(w http.ResponseWriter, r *http.Request) { // build lock server command app.lockserver.BuildCommand(doorReq, checkIn, checkOut) - // lock server sequence + // Each request performs at most one encoder operation. + encodingStarted := time.Now() + log.Info("LockSequence started") encodingErr := app.lockserver.LockSequence() + log.Infof("LockSequence finished; success=%t duration=%s", encodingErr == nil, time.Since(encodingStarted)) if encodingErr != nil { logging.Error(types.ServiceName, encodingErr.Error(), "Key encoding", string(op), "", "", 0) } @@ -321,32 +327,10 @@ func (app *App) issueDoorCard(w http.ResponseWriter, r *http.Request) { status, deliveryErr := app.disp.DeliverCurrentCard(finalizeCtx) app.SetCardWellStatus(status) if deliveryErr != nil { - if encodingErr != nil { - recoveryErr := fmt.Errorf("key encoding failed: %v; dispenser recovery failed: %w", encodingErr, deliveryErr) - logging.Error(types.ServiceName, recoveryErr.Error(), "Dispenser recovery", string(op), "", "", 0) - errorhandlers.WriteError(w, http.StatusServiceUnavailable, "Dispenser recovery failed; another encoding attempt is not safe") - return - } - logging.Error(types.ServiceName, deliveryErr.Error(), "Card delivery", string(op), "", "", 0) - errorhandlers.WriteError(w, http.StatusServiceUnavailable, "Card delivery could not be confirmed") - return } - if encodingErr != nil { - status, preparationErr := app.disp.PrepareNextCard(finalizeCtx) - app.SetCardWellStatus(status) - if preparationErr != nil { - recoveryErr := fmt.Errorf("key encoding failed: %v; dispenser recovery failed: %w", encodingErr, preparationErr) - logging.Error(types.ServiceName, recoveryErr.Error(), "Dispenser recovery", string(op), "", "", 0) - if errors.Is(preparationErr, dispenser.ErrCardWellEmpty) { - errorhandlers.WriteError(w, http.StatusServiceUnavailable, dispenser.CardWellEmptyMessage) - return - } - errorhandlers.WriteError(w, http.StatusServiceUnavailable, "Dispenser recovery failed; another encoding attempt is not safe") - return - } - + // FC0 is attempted once; the next UI request owns all further preparation. errorhandlers.WriteError(w, http.StatusBadGateway, encodingErr.Error()) return }