From b9b2a524dd859996b608205f78006696521408f5 Mon Sep 17 00:00:00 2001 From: yurii Date: Mon, 28 Sep 2026 19:43:35 +0100 Subject: [PATCH] fix(dispenser): tolerate unusable AP observations during card preparation --- cmd/hardlink/main.go | 2 +- internal/dispenser/delivery_test.go | 112 +-------- internal/dispenser/dispenserclient.go | 206 +++++++++-------- internal/dispenser/dispenserclient_test.go | 56 ++--- internal/dispenser/observation_test.go | 242 ++++++++++++++++++++ internal/handlers/doorcard_handlers_test.go | 28 ++- internal/handlers/handlers.go | 2 +- release notes.md | 3 + 8 files changed, 403 insertions(+), 248 deletions(-) create mode 100644 internal/dispenser/observation_test.go diff --git a/cmd/hardlink/main.go b/cmd/hardlink/main.go index 9faa7fa..8c68eef 100644 --- a/cmd/hardlink/main.go +++ b/cmd/hardlink/main.go @@ -33,7 +33,7 @@ import ( ) const ( - buildVersion = "v2.0.3" + buildVersion = "v2.1.0" serviceName = "hardlink" pollingFrequency = 8 * time.Second ) diff --git a/internal/dispenser/delivery_test.go b/internal/dispenser/delivery_test.go index a30f17e..a518e84 100644 --- a/internal/dispenser/delivery_test.go +++ b/internal/dispenser/delivery_test.go @@ -111,14 +111,11 @@ func TestWorkerClearanceValidation(t *testing.T) { 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().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 { + r := workerRequest(c, context.Background(), cmdStatus) + if c.deliveryPending == tc.clear { t.Errorf("FC7(% X): err=%v pending=%v, want clear=%v", tc.st, r.err, c.deliveryPending, tc.clear) } want := []string{"AP"} - if tc.clear { - want = append(want, "FC7") - } if got := wireCommands(p); !reflect.DeepEqual(got, want) { t.Errorf("commands=%v, want %v", got, want) } @@ -129,7 +126,7 @@ func TestWorkerClearanceValidation(t *testing.T) { frame[len(frame)-1] ^= 1 p := &scriptedTransport{chunks: [][]byte{vendorACK, frame}} c := &Client{port: p, deliveryPending: true} - r := workerRequest(c, context.Background(), cmdToEncoder) + r := workerRequest(c, context.Background(), cmdStatus) if r.err == nil || !c.deliveryPending { t.Errorf("bad BCC: err=%v pending=%v", r.err, c.deliveryPending) } @@ -235,71 +232,6 @@ func TestDeliveryClearWaitsTwoSeconds(t *testing.T) { } } -func TestDeliveryClearanceWaitStops(t *testing.T) { - for _, tc := range []struct { - name string - response cmdResp - cancel bool - timeout bool - }{ - {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: "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) { - responses := make([]cmdResp, 20) - for i := range responses { - responses[i] = tc.response - } - c, d := newSequenceTestClient(t, responses...) - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - if tc.cancel { - c.sequenceTiming.wait = func(context.Context, time.Duration) error { cancel(); return ctx.Err() } - } - started := c.sequenceTiming.now() - _, err := c.PrepareCurrentCard(ctx) - if err == nil { - t.Fatal("preparation succeeded while clearance unavailable") - } - if tc.cancel && !errors.Is(err, context.Canceled) { - t.Errorf("error=%v, want canceled", err) - } - if tc.timeout { - 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)) - } - } - for _, cmd := range d.commands { - if cmd != cmdStatus { - t.Errorf("clearance dispatched command %v, want only AP", cmd) - } - } - }) - } -} - -func TestDeliveryClearanceDoesNotConsumeRecoveryWindow(t *testing.T) { - 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...) - start := c.now() - if _, err := c.PrepareCurrentCard(context.Background()); !errors.Is(err, ErrPreparationExhausted) { - t.Fatalf("preparation error=%v, want exhausted", err) - } - if elapsed := c.now().Sub(start); elapsed != 33*time.Second { - t.Errorf("elapsed=%s, want clearance 15s + shakes 18s", elapsed) - } - if commandCount(d.commands, cmdReset) != 3 || commandCount(d.commands, cmdToEncoder) != 4 { - t.Errorf("commands=%v, want 3 RS and 4 FC7", d.commands) - } -} - func TestDeliveryPendingIsNotPersisted(t *testing.T) { c := NewClient(nil, 1) defer c.Close() @@ -328,32 +260,6 @@ func TestDeliveryCancellationAfterACKDoesNotSetPending(t *testing.T) { } } -func TestDeliveryClearanceRetainsFullPreparationTimeout(t *testing.T) { - responses := make([]cmdResp, 8) - for i := range responses { - responses[i] = cmdResp{status: status(0x37), deliveryPending: true} - } - responses = append(responses, positionResponses(0x30, 2)...) - c, d := newSequenceTestClient(t, responses...) - 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) - } - start := c.now() - if _, err := c.PrepareCurrentCard(context.Background()); !errors.Is(err, ErrPreparationExhausted) { - t.Fatalf("preparation error=%v, want exhausted", err) - } - 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) - } -} - func TestWorkerSerializesClearanceAndFC7(t *testing.T) { p := &scriptedTransport{chunks: [][]byte{vendorACK, apReply(status(0x30)), vendorACK, vendorACK, vendorACK, apReply(status(0x37))}} c, _ := deliveryWorkerClient(t, p) @@ -388,10 +294,8 @@ func TestWorkerSerializesClearanceAndFC7(t *testing.T) { if r := <-fc0; r.err != nil { t.Fatal(r.err) } - if err := c.ToEncoder(ctx); !errors.Is(err, errDeliveryPending) { - t.Errorf("FC7 after queued FC0=%v, want deferred", err) - } - want := []string{"AP", "FC7", "FC0", "AP"} + + want := []string{"AP", "FC7", "FC0"} if got := wireCommands(p); !reflect.DeepEqual(got, want) { t.Errorf("serialized commands=%v, want %v", got, want) } @@ -426,10 +330,10 @@ func TestPreparationWireFailuresNeverShake(t *testing.T) { 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) + if _, err := c.PrepareCurrentCard(context.Background()); err != nil { + t.Errorf("frame % X: err=%v, want encoder opportunity", frame, err) } - want := []string{"AP", "FC7", "AP"} + want := []string{"AP", "FC7", "AP", "AP", "AP", "AP", "AP"} if got := wireCommands(p); !reflect.DeepEqual(got, want) { t.Errorf("frame % X commands=%v, want %v without RS or resends", frame, got, want) } diff --git a/internal/dispenser/dispenserclient.go b/internal/dispenser/dispenserclient.go index 384ad54..a5f196f 100644 --- a/internal/dispenser/dispenserclient.go +++ b/internal/dispenser/dispenserclient.go @@ -19,6 +19,7 @@ const ( cmdToEncoder cmdOutOfMouth cmdReset + cmdDeliveryClearance ) type cmdReq struct { @@ -27,8 +28,6 @@ type cmdReq struct { respCh chan cmdResp } -var errDeliveryPending = errors.New("next-card preparation deferred: previous delivery is not clear") - type cmdResp struct { deliveryPending bool status []byte @@ -47,7 +46,7 @@ const ( sequenceTimeout = 32 * time.Second sequenceUncertainWait = 4 * time.Second sequenceMaxShakes = 3 - deliveryClearanceTimeout = 16 * time.Second + deliveryClearanceTimeout = 6 * time.Second deliveryMinimumWait = 2 * time.Second ) @@ -204,18 +203,13 @@ func (c *Client) handle(req cmdReq) { st, err := c.readWorkerStatus(req.ctx) req.respCh <- cmdResp{status: st, err: err, deliveryPending: c.deliveryPending} + case cmdDeliveryClearance: + st, err := c.waitWorkerDeliveryClearance(req.ctx) + req.respCh <- cmdResp{status: st, err: err, deliveryPending: c.deliveryPending} + case cmdToEncoder: if c.deliveryPending { - // Stay inside port ownership: never enqueue a request from the worker. - st, err := c.readWorkerStatus(req.ctx) - if err == nil { - _, err = deliveryClearance(st) - } - if err == nil && c.deliveryPending { - err = errDeliveryPending - log.Debugf("next-card preparation deferred; raw status: % X", st) - } - if err != nil { + if _, err := c.waitWorkerDeliveryClearance(req.ctx); err != nil { req.respCh <- cmdResp{err: err} return } @@ -405,16 +399,13 @@ func (c *Client) DispenserPrepare(ctx context.Context) (string, error) { func (c *Client) readSequenceStatus(ctx context.Context, operation string) ([]byte, string, error) { response := c.doResponse(ctx, cmdStatus) - status, err := response.status, response.err - if err == nil && response.deliveryPending { - err = errDeliveryPending + if err := ctx.Err(); err != nil { + return nil, "", err } - if err != nil { - if ctxErr := ctx.Err(); ctxErr != nil { - return nil, "", fmt.Errorf("[%s] read status: %w", operation, ctxErr) - } - return nil, "", fmt.Errorf("[%s] read status: %w", operation, err) + if response.deliveryPending { + return c.waitForDeliveryClearance(ctx, operation) } + status := usableObservation(response.status, response.err, operation) stockStatus := "" if len(status) == 4 { @@ -425,63 +416,85 @@ func (c *Client) readSequenceStatus(ctx context.Context, operation string) ([]by return status, stockStatus, nil } -// waitForDeliveryClearance reuses the first clear AP as the initial preparation sample. -// 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, deliveryClearanceTimeout) +// waitWorkerDeliveryClearance runs only inside the serial worker. +// An unusable observation never becomes a fabricated physical position. +func (c *Client) waitWorkerDeliveryClearance(parent context.Context) ([]byte, error) { + ctx, cancel := context.WithTimeout(parent, deliveryClearanceTimeout) defer cancel() - deadline := c.sequenceTiming.now().Add(deliveryClearanceTimeout) - var lastStatus []byte - defer func() { - if resultErr != nil { - log.Warnf("[%s] delivery clearance stopped: %v; %s raw status: % X", operation, resultErr, statusDescription(lastStatus), lastStatus) - } - }() + deadline := c.now().Add(deliveryClearanceTimeout) + var latest []byte for { - if err := ctx.Err(); err != nil { - return nil, stock, fmt.Errorf("[%s] delivery clearance: %w", operation, err) + if err := parent.Err(); err != nil { + return nil, err } - if !c.sequenceTiming.now().Before(deadline) { - return nil, stock, fmt.Errorf("[%s] delivery clearance: %w", operation, context.DeadlineExceeded) + if !c.now().Before(deadline) || ctx.Err() != nil { + class, err := classifyPreparationStatus(latest) + if err == nil && class == positionWellEmpty { + return latest, ErrCardWellEmpty + } + if err == nil && (isPreparationMoving(latest) || latest[1] == 0x34) { + return latest, context.DeadlineExceeded + } + c.deliveryPending = false + log.Warn("delivery clearance assumed after bounded observation fallback") + return latest, nil } - r := c.doResponse(ctx, cmdStatus) - if len(r.status) > 0 { - lastStatus = r.status + st, err := c.readWorkerStatus(ctx) + if parent.Err() != nil { + return nil, parent.Err() } - if r.err != nil { - return nil, stock, fmt.Errorf("[%s] delivery clearance status: %w", operation, r.err) + latest = usableObservation(st, err, "delivery clearance") + if latest != nil && latest[3] == 0x38 { + return latest, ErrCardWellEmpty } - if len(r.status) == 4 { - stock = stockTake(r.status) - c.setStock(r.status) + if !c.deliveryPending { + return latest, nil } - if err := ctx.Err(); err != nil { - return nil, stock, err - } - if !c.sequenceTiming.now().Before(deadline) { - return nil, stock, fmt.Errorf("[%s] delivery clearance: %w", operation, context.DeadlineExceeded) - } - if !r.deliveryPending { - return r.status, stock, nil - } - if _, err := deliveryClearance(r.status); err != nil { - return nil, stock, fmt.Errorf("[%s] delivery clearance: %w", operation, err) + remaining := deadline.Sub(c.now()) + if remaining <= 0 || ctx.Err() != nil { + continue } wait := sequencePollInterval - if remaining := deadline.Sub(c.sequenceTiming.now()); remaining < wait { + if remaining < wait { wait = remaining } - if err := c.sequenceTiming.wait(ctx, wait); err != nil { - return nil, stock, fmt.Errorf("[%s] delivery clearance: %w", operation, err) + if err := c.sequenceTiming.wait(ctx, wait); err != nil && parent.Err() != nil { + return nil, parent.Err() } } } +// usableObservation preserves strict validation while discarding unusable telemetry. +func usableObservation(status []byte, err error, operation string) []byte { + if err == nil { + _, err = classifyPreparationStatus(status) + } + if err != nil { + log.Warnf("[%s] unusable AP observation; raw status: % X error=%v", operation, status, err) + return nil + } + return status +} + +// waitForDeliveryClearance uses a worker request; no worker recursively enqueues. +func (c *Client) waitForDeliveryClearance(ctx context.Context, operation string) ([]byte, string, error) { + r := c.doResponse(ctx, cmdDeliveryClearance) + stock := "" + if len(r.status) == 4 { + stock = stockTake(r.status) + } + if r.err != nil { + return nil, stock, fmt.Errorf("[%s] delivery clearance: %w", operation, r.err) + } + return r.status, stock, nil +} + func (c *Client) prepareCardAtEncoder(parent context.Context, operation string) (stock string, resultErr error) { status, stock, err := c.waitForDeliveryClearance(parent, operation) if err != nil { return stock, err } + status = usableObservation(status, nil, operation) started := c.now() deadline := started.Add(sequenceTimeout) ctx, cancel := context.WithTimeoutCause(parent, sequenceTimeout, ErrPreparationExhausted) @@ -502,6 +515,26 @@ func (c *Client) prepareCardAtEncoder(parent context.Context, operation string) } return ctx.Err() } + // Only observation exhaustion can grant a deadline handoff. Command and + // reset-settle failures never pass through this policy. + observationResult := func(err error) error { + if parent.Err() != nil { + return parent.Err() + } + if !errors.Is(err, ErrPreparationExhausted) || lastFC7.IsZero() { + return err + } + class, _ := classifyPreparationStatus(status) + switch class { + case positionWellEmpty: + return ErrCardWellEmpty + case positionNoCard: + return err + default: + stage = "observation deadline encoder handoff" + return nil + } + } wait := func(duration time.Duration) error { if err := checkDeadline(); err != nil { return err @@ -535,18 +568,17 @@ func (c *Client) prepareCardAtEncoder(parent context.Context, operation string) } for { if err := checkDeadline(); err != nil { - return stock, err - } - class, err := classifyPreparationStatus(status) - if err != nil { - return stock, err + return stock, observationResult(err) } + class, _ := classifyPreparationStatus(status) + // No class means unusable telemetry, sharing the uncertainty timer. + 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() + return stock, observationResult(checkDeadline()) case positionWellEmpty: stage = "empty" return stock, ErrCardWellEmpty @@ -583,29 +615,29 @@ func (c *Client) prepareCardAtEncoder(parent context.Context, operation string) return stock, err } } else { - if class == positionUncertain { + if class == positionUncertain || class == "" { if uncertainSince.IsZero() { uncertainSince = c.now() } if c.now().Sub(uncertainSince) >= sequenceUncertainWait { stage = "uncertain position handoff" - return stock, checkDeadline() + return stock, observationResult(checkDeadline()) } } else { uncertainSince = time.Time{} } stage = "polling" if err := wait(sequencePollInterval); err != nil { - return stock, err + return stock, observationResult(err) } } stage = "fresh AP" if err := checkDeadline(); err != nil { - return stock, err + return stock, observationResult(err) } status, stock, err = c.readSequenceStatus(ctx, operation) if deadlineErr := checkDeadline(); deadlineErr != nil { - return stock, deadlineErr + return stock, observationResult(deadlineErr) } if err != nil { return stock, err @@ -628,39 +660,13 @@ func (c *Client) DeliverCurrentCard(ctx context.Context) (string, error) { return "", nil } -// BeginPrepareNextCard waits for delivery clearance and dispatches FC7 once, -// without waiting for encoder readiness. +// BeginPrepareNextCard waits for worker-owned clearance and dispatches one FC7. +// It does not wait for encoder readiness. func (c *Client) BeginPrepareNextCard(ctx context.Context) error { - 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 - } + if err := c.ToEncoder(ctx); err != nil { + return fmt.Errorf("[BeginPrepareNextCard] to encoder: %w", err) } + return nil } // PrepareNextCard runs the same bounded physical preparation for a later issuance attempt. diff --git a/internal/dispenser/dispenserclient_test.go b/internal/dispenser/dispenserclient_test.go index 4ac16cc..cafb3c9 100644 --- a/internal/dispenser/dispenserclient_test.go +++ b/internal/dispenser/dispenserclient_test.go @@ -52,6 +52,10 @@ func newSequenceTestClient(t *testing.T, statusResponses ...cmdResp) (*Client, * case <-client.done: return case request := <-client.reqCh: + clearance := request.typ == cmdDeliveryClearance + if clearance { + request.typ = cmdStatus + } device.commands = append(device.commands, request.typ) device.commandTimes = append(device.commandTimes, now) if device.onCommand != nil { @@ -63,6 +67,10 @@ func newSequenceTestClient(t *testing.T, statusResponses ...cmdResp) (*Client, * continue } response := device.statusResponses[0] + if clearance && request.ctx.Err() == nil { + response.status = usableObservation(response.status, response.err, "fake clearance") + response.err = nil + } device.statusResponses = device.statusResponses[1:] request.respCh <- response continue @@ -369,8 +377,8 @@ 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 _, err := c.PrepareCurrentCard(context.Background()); err != nil { + t.Errorf("AP failure %v error=%v, want encoder opportunity", 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) @@ -391,6 +399,9 @@ func TestPreparationTransportAndDispatchFailuresDoNotShake(t *testing.T) { func TestPreparationStopsAtCancellationAndDeadlineStages(t *testing.T) { for _, stage := range []string{"initial AP", "FC7", "poll", "RS", "settle"} { for _, callerCanceled := range []bool{false, true} { + if stage == "initial AP" && !callerCanceled { + continue + } 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()) @@ -465,7 +476,7 @@ func TestPreparationCallerDeadlineIsNotRetryableExhaustion(t *testing.T) { } } -func TestPreparationExpiredEncoderSampleDoesNotHandoff(t *testing.T) { +func TestPreparationExpiredEncoderSampleHandsOff(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 } @@ -475,45 +486,10 @@ func TestPreparationExpiredEncoderSampleDoesNotHandoff(t *testing.T) { } } _, err := c.PrepareCurrentCard(context.Background()) - if !errors.Is(err, ErrPreparationExhausted) { - t.Errorf("late encoder sample: err=%v, want preparation exhausted", err) + if err != nil { + t.Errorf("late encoder sample: err=%v, want handoff", 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/dispenser/observation_test.go b/internal/dispenser/observation_test.go new file mode 100644 index 0000000..031032d --- /dev/null +++ b/internal/dispenser/observation_test.go @@ -0,0 +1,242 @@ +package dispenser + +import ( + "context" + "errors" + "fmt" + "io" + "testing" + "time" +) + +func TestStrictAPFailuresBecomeUnusablePreparationObservations(t *testing.T) { + transportAddress(t) + cases := []struct { + name string + chunks [][]byte + readErr error + }{ + {"invalid ACK 10 06 30", [][]byte{{0x10, 0x06, 0x30}}, nil}, + {"truncated", [][]byte{vendorACK, vendorAP[:8]}, nil}, + {"no response", nil, nil}, + {"timeout", nil, context.DeadlineExceeded}, + {"read failure", nil, io.ErrClosedPipe}, + } + for _, offset := range []int{0, 1, 2, 3, 4, 5, 6, 11, 12} { + frame := append([]byte(nil), vendorAP...) + frame[offset] ^= 0xff + if offset == 5 || offset == 6 || offset == 11 { + frame[12] = calculateBCC(frame[:12]) + } + cases = append(cases, struct { + name string + chunks [][]byte + readErr error + }{fmt.Sprintf("frame byte %d", offset), [][]byte{vendorACK, frame}, nil}) + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + p := &scriptedTransport{chunks: tc.chunks, readErr: tc.readErr} + st, err := queryStatus(context.Background(), p, vendorFrames[0].command, 4, 0) + if err == nil { + t.Fatal("strict queryStatus accepted invalid transaction") + } + c, d := newSequenceTestClient(t, cmdResp{status: st, err: err}, cmdResp{status: status(0x37)}) + if _, err := c.PrepareCurrentCard(context.Background()); err != nil { + t.Errorf("preparation after %s = %v, want opportunity", tc.name, err) + } + if commandCount(d.commands, cmdToEncoder) != 1 || commandCount(d.commands, cmdReset) != 0 { + t.Errorf("commands=%v, want one FC7 and no RS", d.commands) + } + }) + } +} + +func TestUnusableObservationsReclassifyAndShareUncertainty(t *testing.T) { + for _, later := range []byte{0x38, 0x30, 0x37, 0x35, 0x40} { + t.Run(fmt.Sprintf("later %X", later), func(t *testing.T) { + responses := []cmdResp{{err: io.ErrUnexpectedEOF}, {status: status(0x40)}} + responses = append(responses, positionResponses(later, 25)...) + c, d := newSequenceTestClient(t, responses...) + _, err := c.PrepareCurrentCard(context.Background()) + var want error + if later == 0x38 { + want = ErrCardWellEmpty + } + if later == 0x30 { + want = ErrPreparationExhausted + } + if !errors.Is(err, want) { + t.Errorf("later %X error=%v, want %v", later, err, want) + } + resets := 0 + if later == 0x30 { + resets = 3 + } + if commandCount(d.commands, cmdReset) != resets { + t.Errorf("later %X commands=%v, want %d RS", later, d.commands, resets) + } + }) + } + c, d := newSequenceTestClient(t, cmdResp{err: io.EOF}, cmdResp{err: io.EOF}, cmdResp{status: status(0x35)}, cmdResp{status: status(0x40)}, cmdResp{err: io.EOF}, cmdResp{status: status(0x39)}) + start := c.now() + if _, err := c.PrepareCurrentCard(context.Background()); err != nil { + t.Fatal(err) + } + if elapsed := c.now().Sub(start); elapsed != sequenceUncertainWait { + t.Errorf("mixed uncertainty elapsed=%v, want %v", elapsed, sequenceUncertainWait) + } + if commandCount(d.commands, cmdToEncoder) != 1 { + t.Errorf("mixed uncertainty commands=%v, want one FC7", d.commands) + } +} + +func TestObservationAtPreparationDeadline(t *testing.T) { + for _, last := range []cmdResp{{err: io.EOF}, {status: status(0x40)}, {status: status(0x35)}, {status: status(0x30)}, {status: status(0x38)}} { + c, d := newSequenceTestClient(t, cmdResp{status: status(0x30)}, last) + 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()) + var want error + if len(last.status) == 4 && last.status[3] == 0x30 { + want = ErrPreparationExhausted + } + if len(last.status) == 4 && last.status[3] == 0x38 { + want = ErrCardWellEmpty + } + if !errors.Is(err, want) { + t.Errorf("deadline observation=%v error=%v, want %v", last, err, want) + } + } +} + +func TestWorkerClearanceFallbackAndMovement(t *testing.T) { + for _, mode := range []string{"unusable", "ambiguous", "movement", "movement then unusable", "empty", "cancel"} { + t.Run(mode, func(t *testing.T) { + p := &scriptedTransport{} + for i := 0; i < 6; i++ { + switch mode { + case "unusable", "cancel": + p.chunks = append(p.chunks, []byte{0x10, 0x06, 0x30}) + case "ambiguous": + p.chunks = append(p.chunks, vendorACK, apReply(status(0x37))) + case "empty": + p.chunks = append(p.chunks, vendorACK, apReply(status(0x38))) + default: + if mode == "movement then unusable" && i > 0 { + p.chunks = append(p.chunks, []byte{0x10, 0x06, 0x30}) + } else { + p.chunks = append(p.chunks, vendorACK, apReply([]byte{0x31, 0x30, 0x30, 0x34})) + } + } + } + c, now := deliveryWorkerClient(t, p) + c.sequenceTiming.wait = func(ctx context.Context, d time.Duration) error { + if ctx.Err() != nil { + return ctx.Err() + } + *now = now.Add(2 * d) + return nil + } + c.deliveryPending = true + c.deliveryStarted = c.now() + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + if mode == "cancel" { + p.afterRead = cancel + } + r := c.doResponse(ctx, cmdDeliveryClearance) + if mode == "cancel" { + if !errors.Is(r.err, context.Canceled) { + t.Errorf("cancel=%v", r.err) + } + return + } + var want error + if mode == "movement" { + want = context.DeadlineExceeded + } + if mode == "empty" { + want = ErrCardWellEmpty + } + if !errors.Is(r.err, want) { + t.Errorf("clearance %s error=%v want %v", mode, r.err, want) + } + if c.deliveryPending != (want != nil) { + t.Errorf("clearance %s pending=%t", mode, c.deliveryPending) + } + if mode != "empty" && now.Sub(time.Unix(0, 0)) != deliveryClearanceTimeout { + t.Errorf("clearance %s wait=%v want 6s", mode, now.Sub(time.Unix(0, 0))) + } + for _, command := range wireCommands(p) { + if command != "AP" { + t.Errorf("clearance issued %s, want AP only", command) + } + } + }) + } +} + +func TestWorkerAssumedClearanceAllowsOneFC7(t *testing.T) { + for _, prepare := range []bool{false, true} { + p := &scriptedTransport{} + dispatched := false + p.afterWrite = func() { + w := p.writes[len(p.writes)-1] + if len(w) <= 6 || w[0] != STX { + return + } + switch string(w[5 : len(w)-2]) { + case "AP": + if dispatched { + p.chunks = append(p.chunks, vendorACK, apReply(status(0x35))) + } else { + p.chunks = append(p.chunks, []byte{0x10, 0x06, 0x30}) + } + case "FC7": + dispatched = true + p.chunks = append(p.chunks, vendorACK) + } + } + c, now := deliveryWorkerClient(t, p) + c.deliveryPending = true + c.deliveryStarted = c.now() + var err error + if prepare { + _, err = c.PrepareCurrentCard(context.Background()) + } else { + err = c.BeginPrepareNextCard(context.Background()) + } + if err != nil { + t.Fatalf("prepare=%t error=%v", prepare, err) + } + wantElapsed := deliveryClearanceTimeout + if prepare { + wantElapsed += sequenceUncertainWait + } + if elapsed := now.Sub(time.Unix(0, 0)); elapsed != wantElapsed { + t.Errorf("prepare=%t elapsed=%v want %v", prepare, elapsed, wantElapsed) + } + commands := wireCommands(p) + fc7 := 0 + for _, cmd := range commands { + if cmd == "FC7" { + fc7++ + } + if cmd == "RS" { + t.Errorf("unexpected RS: %v", commands) + } + } + if fc7 != 1 || c.deliveryPending { + t.Errorf("prepare=%t commands=%v pending=%t, want one FC7 and cleared", prepare, commands, c.deliveryPending) + } + if !prepare && commands[len(commands)-1] != "FC7" { + t.Errorf("prestaging polled after FC7: %v", commands) + } + } +} diff --git a/internal/handlers/doorcard_handlers_test.go b/internal/handlers/doorcard_handlers_test.go index 5947edd..7b13b63 100644 --- a/internal/handlers/doorcard_handlers_test.go +++ b/internal/handlers/doorcard_handlers_test.go @@ -121,11 +121,11 @@ func TestIssueDoorCardPhysicalOutcomeContract(t *testing.T) { wantCardWell string }{ { - name: "initial dispenser preparation failure is unavailable", + name: "initial dispenser preparation failure is retryable", dispenser: fakeDoorCardDispenser{ prepareCurrent: dispenserCallResult{status: "Card jammed", err: errors.New("card jammed")}, }, - wantHTTP: http.StatusServiceUnavailable, + wantHTTP: http.StatusBadGateway, wantMessage: "Dispense error: card jammed", wantCalls: []string{"prepare current"}, wantCardWell: "Card jammed", @@ -353,3 +353,27 @@ func TestIssueDoorCardLogsDeliveryFailureWithoutReplacingEncoderOutcome(t *testi } } } + +func TestIssueDoorCardOnlyEmptyPreparationReturns503(t *testing.T) { + for _, failure := range []error{ + dispenser.ErrCardWellEmpty, errors.Join(errors.New("wrapped"), dispenser.ErrCardWellEmpty), + dispenser.ErrPreparationExhausted, context.Canceled, context.DeadlineExceeded, + errors.New("malformed AP"), errors.New("truncated AP"), errors.New("no response"), + errors.New("serial read failed"), errors.New("serial write failed"), errors.New("FC7 dispatch failed"), + errors.New("RS dispatch failed"), errors.New(dispenser.CardWellEmptyMessage), errors.New("other preparation error"), + } { + d := &fakeDoorCardDispenser{prepareCurrent: dispenserCallResult{err: failure}} + lock := &fakeDoorCardLockServer{} + recorder, response, _ := performIssueDoorCardRequest(t, d, lock) + want := http.StatusBadGateway + if errors.Is(failure, dispenser.ErrCardWellEmpty) { + want = http.StatusServiceUnavailable + } + if recorder.Code != want || response.Code != want { + t.Errorf("preparation %v HTTP=%d body=%d, want %d", failure, recorder.Code, response.Code, want) + } + if lock.sequenceCalls != 0 || !reflect.DeepEqual(d.calls, []string{"prepare current"}) { + t.Errorf("preparation %v encoder=%d calls=%v, want no physical continuation", failure, lock.sequenceCalls, d.calls) + } + } +} diff --git a/internal/handlers/handlers.go b/internal/handlers/handlers.go index dc55259..354e3be 100644 --- a/internal/handlers/handlers.go +++ b/internal/handlers/handlers.go @@ -302,7 +302,7 @@ func (app *App) issueDoorCard(w http.ResponseWriter, r *http.Request) { errorhandlers.WriteError(w, http.StatusBadGateway, err.Error()) return } - errorhandlers.WriteError(w, http.StatusServiceUnavailable, "Dispense error: "+err.Error()) + errorhandlers.WriteError(w, http.StatusBadGateway, "Dispense error: "+err.Error()) return } diff --git a/release notes.md b/release notes.md index 3513979..c70d255 100644 --- a/release notes.md +++ b/release notes.md @@ -2,6 +2,9 @@ builtVersion is a const in main.go +#### v2.1.0 - 28 September 2026 +fix(dispenser): tolerate unusable AP observations during card preparation + #### v2.0.3 - 24 September 2026 fix(dispenser): recover stuck card preparation with reset