diff --git a/cmd/hardlink/main.go b/cmd/hardlink/main.go index b760081..df11d4d 100644 --- a/cmd/hardlink/main.go +++ b/cmd/hardlink/main.go @@ -34,7 +34,7 @@ import ( ) const ( - buildVersion = "v1.3.4" + buildVersion = "v1.3.5" serviceName = "hardlink" pollingFrequency = 8 * time.Second ) diff --git a/internal/dispenser/dispenser.go b/internal/dispenser/dispenser.go index c86c832..c122b01 100644 --- a/internal/dispenser/dispenser.go +++ b/internal/dispenser/dispenser.go @@ -1,6 +1,7 @@ package dispenser import ( + "errors" "fmt" "strings" "time" @@ -22,9 +23,13 @@ const ( // cache freshness for "continuous status" reads (tune as you wish) defaultStatusTTL = 1500 * time.Millisecond + + CardWellEmptyMessage = "Card well is empty" ) var ( + ErrCardWellEmpty = errors.New(CardWellEmptyMessage) + SerialPort string Address []byte @@ -67,10 +72,9 @@ var ( // Status helpers // -------------------- -func logStatus(statusBytes []byte) { +func statusDescription(statusBytes []byte) string { if len(statusBytes) < 4 { - log.Infof("Dispenser status: ", len(statusBytes)) - return + return fmt.Sprintf("", len(statusBytes)) } posStatus := []struct { @@ -94,13 +98,58 @@ func logStatus(statusBytes []byte) { result.WriteString(statusMsg + "; ") } } - log.Infof("Dispenser status: %s", result.String()) + return result.String() +} + +func logStatus(statusBytes []byte) { + log.Infof("Dispenser status: %s", statusDescription(statusBytes)) } func isAtEncoderPosition(statusBytes []byte) bool { return len(statusBytes) >= 4 && statusBytes[3] == 0x33 } +func validateDispenserStatusData(statusBytes []byte) error { + if len(statusBytes) != 4 { + return fmt.Errorf("malformed dispenser status: got %d bytes, want 4", len(statusBytes)) + } + + statusMaps := []map[byte]string{statusPos0, statusPos1, statusPos2, statusPos3} + 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) + } + } + return nil +} + +func dispenserStatusError(statusBytes []byte) error { + switch statusBytes[0] { + case 0x34, 0x32, 0x36: + return fmt.Errorf("dispenser error: %s", statusPos0[statusBytes[0]]) + } + switch statusBytes[1] { + case 0x32, 0x31: + return fmt.Errorf("dispenser error: %s", statusPos1[statusBytes[1]]) + } + switch statusBytes[2] { + case 0x34, 0x32: + return fmt.Errorf("dispenser error: %s", statusPos2[statusBytes[2]]) + } + + return nil +} + +func isPreparationMoving(statusBytes []byte) bool { + return len(statusBytes) == 4 && + (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 c266944..d1473f1 100644 --- a/internal/dispenser/dispenserclient.go +++ b/internal/dispenser/dispenserclient.go @@ -30,12 +30,25 @@ type cmdResp struct { err error } +type sequenceTiming struct { + now func() time.Time + wait func(context.Context, time.Duration) error +} + +const ( + sequencePollInterval = time.Second + sequenceRetryAfter = 6 * time.Second + sequenceTimeout = 12 * time.Second +) + type Client struct { port *serial.Port reqCh chan cmdReq done chan struct{} + sequenceTiming sequenceTiming + // status cache mu sync.RWMutex lastStatus []byte @@ -54,15 +67,31 @@ func NewClient(port *serial.Port, queueSize int) *Client { queueSize = 16 } c := &Client{ - port: port, - reqCh: make(chan cmdReq, queueSize), - done: make(chan struct{}), + port: port, + reqCh: make(chan cmdReq, queueSize), + done: make(chan struct{}), + sequenceTiming: sequenceTiming{ + now: time.Now, + wait: waitForSequence, + }, statusTTL: defaultStatusTTL, } go c.loop() return c } +func waitForSequence(ctx context.Context, duration time.Duration) error { + timer := time.NewTimer(duration) + defer timer.Stop() + + select { + case <-timer.C: + return nil + case <-ctx.Done(): + return ctx.Err() + } +} + func (c *Client) Close() { select { case <-c.done: @@ -268,113 +297,152 @@ func (c *Client) DispenserPrepare(ctx context.Context) (string, error) { return stockStatus, nil } -func (c *Client) DispenserStart(ctx context.Context) (string, error) { - const funcName = "DispenserStart" - stockStatus := "" - - status, err := c.CheckStatus(ctx) +func (c *Client) readSequenceStatus(ctx context.Context, operation string) ([]byte, string, error) { + status, err := c.do(ctx, cmdStatus) if err != nil { - return stockStatus, fmt.Errorf("[%s] check status: %w", funcName, err) + 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) } - defer func() { + stockStatus := "" + if len(status) == 4 { + stockStatus = stockTake(status) + c.setStock(status) logStatus(status) - }() - stockStatus = stockTake(status) - c.setStock(status) + } + return status, stockStatus, nil +} - if isCardWellEmpty(status) { - return stockStatus, fmt.Errorf(stockStatus) +func preparationStatus(operation string, status []byte) (bool, error) { + if len(status) != 4 { + return false, fmt.Errorf("[%s] %w", operation, validateDispenserStatusData(status)) } 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 + } + 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, + retryCommand func(context.Context) error, +) (string, error) { + started := c.sequenceTiming.now() + halfway := started.Add(sequenceRetryAfter) + deadline := started.Add(sequenceTimeout) + retried := false + stockStatus := "" + + for { + if err := ctx.Err(); err != nil { + return stockStatus, fmt.Errorf("[%s] %w", operation, err) + } + + now := c.sequenceTiming.now() + if !now.Before(deadline) { + return stockStatus, fmt.Errorf("[%s] timed out after %s", operation, sequenceTimeout) + } + + status, currentStockStatus, err := c.readSequenceStatus(ctx, operation) + stockStatus = currentStockStatus + if err != nil { + return stockStatus, err + } + ready, err := preparationStatus(operation, status) + if err != nil { + return stockStatus, err + } + if ready { + return stockStatus, nil + } + + now = c.sequenceTiming.now() + if !now.Before(deadline) { + return stockStatus, fmt.Errorf("[%s] timed out after %s", operation, sequenceTimeout) + } + if retryCommand != nil && !retried && !now.Before(halfway) { + if err := retryCommand(ctx); err != nil { + return stockStatus, fmt.Errorf("[%s] retry command: %w", operation, err) + } + retried = true + } + + wait := sequencePollInterval + if remaining := deadline.Sub(now); remaining < wait { + wait = remaining + } + if err := c.sequenceTiming.wait(ctx, wait); err != nil { + return stockStatus, fmt.Errorf("[%s] %w", operation, err) + } + } +} + +func (c *Client) prepareCardAtEncoder(ctx context.Context, operation string) (string, error) { + status, stockStatus, err := c.readSequenceStatus(ctx, operation) + if err != nil { + return stockStatus, err + } + ready, err := preparationStatus(operation, status) + if err != nil { + return stockStatus, err + } + if ready { return stockStatus, nil } if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] to encoder: %w", funcName, err) - } - - halfway := time.Now().Add(6 * time.Second) - deadline := time.Now().Add(12 * time.Second) - - for { - time.Sleep(delay * 2) - switch { - case time.Now().After(halfway): - if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] to encoder: %w", funcName, err) - } - case time.Now().After(deadline): - return stockStatus, nil - } - - status, _ = c.do(ctx, cmdStatus) - - stockStatus = stockTake(status) - c.setStock(status) - logStatus(status) - - // error states first - if isCardWellEmpty(status) { - return stockStatus, fmt.Errorf(stockStatus) - } - - if isAtEncoderPosition(status) { - return stockStatus, nil - } + return stockStatus, fmt.Errorf("[%s] to encoder: %w", operation, err) } + return c.pollForEncoderPosition(ctx, operation, c.ToEncoder) } -func (c *Client) DispenserFinal(ctx context.Context) (string, error) { - const funcName = "DispenserFinal" - stockStatus := "" - var status []byte +// PrepareCurrentCard authoritatively places the card to be encoded at the encoder. +func (c *Client) PrepareCurrentCard(ctx context.Context) (string, error) { + return c.prepareCardAtEncoder(ctx, "PrepareCurrentCard") +} + +// DeliverCurrentCard presents the encoded card and confirms command acceptance. +func (c *Client) DeliverCurrentCard(ctx context.Context) (string, error) { + const operation = "DeliverCurrentCard" if err := c.OutOfMouth(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] out of mouth: %w", funcName, err) - } - - time.Sleep(delay) - status, err := c.do(ctx, cmdStatus) - if err == nil && len(status) >= 4 { - c.setStock(status) - } - - time.Sleep(delay) - if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] to encoder: %w", funcName, err) - } - - defer func() { - logStatus(status) - }() - - halfway := time.Now().Add(6 * time.Second) - deadline := time.Now().Add(12 * time.Second) - - for { - time.Sleep(delay * 2) - switch { - case time.Now().After(halfway): - if err := c.ToEncoder(ctx); err != nil { - return stockStatus, fmt.Errorf("[%s] to encoder: %w", funcName, err) - } - case time.Now().After(deadline): - return stockStatus, nil - } - - status, _ = c.do(ctx, cmdStatus) - - stockStatus = stockTake(status) - c.setStock(status) - logStatus(status) - - if isCardWellEmpty(status) { - return stockStatus, nil - } - - if isAtEncoderPosition(status) { - return stockStatus, nil - } + return "", fmt.Errorf("[%s] out of mouth: %w", operation, err) } + return "", nil +} + +// BeginPrepareNextCard starts moving the next card to the encoder without waiting for readiness. +func (c *Client) BeginPrepareNextCard(ctx context.Context) error { + if err := c.ToEncoder(ctx); err != nil { + return fmt.Errorf("[BeginPrepareNextCard] to encoder: %w", err) + } + return nil +} + +// PrepareNextCard places a new card at the encoder 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 new file mode 100644 index 0000000..cb3c019 --- /dev/null +++ b/internal/dispenser/dispenserclient_test.go @@ -0,0 +1,404 @@ +package dispenser + +import ( + "bytes" + "context" + "errors" + "strings" + "testing" + "time" + + log "github.com/sirupsen/logrus" +) + +type fakeSequenceDevice struct { + statusResponses []cmdResp + commandErrors map[cmdType][]error + commands []cmdType +} + +func newSequenceTestClient(t *testing.T, statusResponses ...cmdResp) (*Client, *fakeSequenceDevice) { + t.Helper() + + device := &fakeSequenceDevice{ + statusResponses: append([]cmdResp(nil), statusResponses...), + commandErrors: make(map[cmdType][]error), + } + now := time.Date(2026, time.July, 23, 12, 0, 0, 0, time.UTC) + client := &Client{ + reqCh: make(chan cmdReq), + done: make(chan struct{}), + sequenceTiming: sequenceTiming{ + now: func() time.Time { + return now + }, + wait: func(ctx context.Context, duration time.Duration) error { + select { + case <-ctx.Done(): + return ctx.Err() + default: + now = now.Add(duration) + return nil + } + }, + }, + } + + go func() { + for { + select { + case <-client.done: + return + case request := <-client.reqCh: + device.commands = append(device.commands, request.typ) + if request.typ == cmdStatus { + if len(device.statusResponses) == 0 { + request.respCh <- cmdResp{err: errors.New("unexpected status read")} + continue + } + response := device.statusResponses[0] + device.statusResponses = device.statusResponses[1:] + request.respCh <- response + continue + } + + var err error + if queued := device.commandErrors[request.typ]; len(queued) > 0 { + err = queued[0] + device.commandErrors[request.typ] = queued[1:] + } + request.respCh <- cmdResp{err: err} + } + } + }() + t.Cleanup(client.Close) + + return client, device +} + +func status(position byte) []byte { + return []byte{0x30, 0x30, 0x30, position} +} + +func commandCount(commands []cmdType, target cmdType) int { + count := 0 + for _, command := range commands { + if command == target { + count++ + } + } + return count +} + +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 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, 0x39}}, + 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}) + + stock, err := client.DeliverCurrentCard(context.Background()) + if err != nil { + t.Fatal(err) + } + if stock != "" { + t.Fatalf("stock status = %q, want empty", stock) + } + if got := commandCount(device.commands, cmdOutOfMouth); got != 1 { + t.Fatalf("out-of-mouth commands = %d, want 1", got) + } + if got := commandCount(device.commands, cmdStatus); got != 0 { + t.Fatalf("status reads = %d, want 0", got) + } + if len(device.statusResponses) != 1 { + t.Fatalf("queued status responses = %d, want stale status unread", len(device.statusResponses)) + } +} + +func TestDeliverCurrentCardRejectsCommandFailures(t *testing.T) { + tests := []struct { + name string + err error + }{ + {name: "serial dispatch failure", err: errors.New("serial write failed")}, + {name: "invalid acknowledgement", err: errors.New("unexpected response status")}, + {name: "missing acknowledgement", err: errors.New("no response from dispenser")}, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + client, device := newSequenceTestClient(t) + device.commandErrors[cmdOutOfMouth] = []error{test.err} + + _, err := client.DeliverCurrentCard(context.Background()) + if err == nil || !strings.Contains(err.Error(), test.err.Error()) { + t.Fatalf("error = %v, want containing %q", err, test.err) + } + if got := commandCount(device.commands, cmdOutOfMouth); got != 1 { + t.Fatalf("out-of-mouth commands = %d, want 1", got) + } + if got := commandCount(device.commands, cmdStatus); got != 0 { + t.Fatalf("status reads = %d, want 0", got) + } + }) + } +} + +func TestDeliverCurrentCardPreservesContextCancellation(t *testing.T) { + client, _ := newSequenceTestClient(t) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + _, err := client.DeliverCurrentCard(ctx) + if !errors.Is(err, context.Canceled) { + t.Fatalf("error = %v, want context.Canceled", err) + } +} + +func TestPrepareCurrentCardRetriesOnceThenTimesOut(t *testing.T) { + responses := make([]cmdResp, 13) + 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 != 13 { + t.Fatalf("status reads = %d, want 13", 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) + + if err := client.BeginPrepareNextCard(context.Background()); err != nil { + t.Fatal(err) + } + if got := commandCount(device.commands, cmdToEncoder); got != 1 { + t.Fatalf("to-encoder commands = %d, want 1", got) + } + if got := commandCount(device.commands, cmdStatus); got != 0 { + t.Fatalf("status reads = %d, want 0", got) + } +} + +func TestBeginPrepareNextCardReturnsDispatchFailureWithoutPolling(t *testing.T) { + client, device := newSequenceTestClient(t) + device.commandErrors[cmdToEncoder] = []error{errors.New("dispatch failed")} + + err := client.BeginPrepareNextCard(context.Background()) + if err == nil || !strings.Contains(err.Error(), "dispatch failed") { + t.Fatalf("error = %v, want dispatch failure", err) + } + if got := commandCount(device.commands, cmdToEncoder); got != 1 { + t.Fatalf("to-encoder commands = %d, want 1", got) + } + if got := commandCount(device.commands, cmdStatus); got != 0 { + t.Fatalf("status reads = %d, want 0", got) + } +} + +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) + } + }) + } +} diff --git a/internal/handlers/doorcard_handlers_test.go b/internal/handlers/doorcard_handlers_test.go new file mode 100644 index 0000000..2b399b0 --- /dev/null +++ b/internal/handlers/doorcard_handlers_test.go @@ -0,0 +1,313 @@ +package handlers + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "net/http" + "net/http/httptest" + "reflect" + "strings" + "testing" + "time" + + "gitea.futuresens.co.uk/futuresens/cmstypes" + "gitea.futuresens.co.uk/futuresens/hardlink/config" + "gitea.futuresens.co.uk/futuresens/hardlink/internal/dispenser" + "gitea.futuresens.co.uk/futuresens/hardlink/internal/lockserver" + log "github.com/sirupsen/logrus" +) + +type dispenserCallResult struct { + status string + err error +} + +type fakeDoorCardDispenser struct { + prepareCurrent dispenserCallResult + deliverCurrent dispenserCallResult + beginNextErr error + beginNext func() error + prepareNext dispenserCallResult + calls []string +} + +func (d *fakeDoorCardDispenser) PrepareCurrentCard(context.Context) (string, error) { + d.calls = append(d.calls, "prepare current") + return d.prepareCurrent.status, d.prepareCurrent.err +} + +func (d *fakeDoorCardDispenser) DeliverCurrentCard(context.Context) (string, error) { + d.calls = append(d.calls, "deliver current") + return d.deliverCurrent.status, d.deliverCurrent.err +} + +func (d *fakeDoorCardDispenser) BeginPrepareNextCard(context.Context) error { + d.calls = append(d.calls, "begin prepare next") + if d.beginNext != nil { + return d.beginNext() + } + return d.beginNextErr +} + +func (d *fakeDoorCardDispenser) PrepareNextCard(context.Context) (string, error) { + d.calls = append(d.calls, "prepare next") + return d.prepareNext.status, d.prepareNext.err +} + +type fakeDoorCardLockServer struct { + sequenceErr error + buildCalls int + sequenceCalls int +} + +func (l *fakeDoorCardLockServer) BuildCommand(lockserver.DoorCardRequest, time.Time, time.Time) error { + l.buildCalls++ + return nil +} + +func (l *fakeDoorCardLockServer) LockSequence() error { + l.sequenceCalls++ + return l.sequenceErr +} + +func performIssueDoorCardRequest( + t *testing.T, + dispenser *fakeDoorCardDispenser, + lock *fakeDoorCardLockServer, +) (*httptest.ResponseRecorder, cmstypes.StatusRec, *App) { + t.Helper() + + payload := lockserver.DoorCardRequest{ + RoomField: "101", + CheckinTime: "2026-07-23 15:00:00 +0100", + CheckoutTime: "2026-07-24 11:00:00 +0100", + FollowStr: "0", + } + body, err := json.Marshal(payload) + if err != nil { + t.Fatal(err) + } + + app := &App{ + disp: dispenser, + lockserver: lock, + cfg: &config.ConfigRec{}, + } + request := httptest.NewRequest(http.MethodPost, "/issuedoorcard", bytes.NewReader(body)) + request.Header.Set("Content-Type", "application/json") + recorder := httptest.NewRecorder() + + app.issueDoorCard(recorder, request) + + var response cmstypes.StatusRec + if err := json.Unmarshal(recorder.Body.Bytes(), &response); err != nil { + t.Fatalf("decode response %q: %v", recorder.Body.String(), err) + } + return recorder, response, app +} + +func TestIssueDoorCardPhysicalOutcomeContract(t *testing.T) { + encodingErr := errors.New("key encoding failed") + tests := []struct { + name string + dispenser fakeDoorCardDispenser + lockErr error + wantHTTP int + wantMessage string + wantCalls []string + wantLockSequence int + wantCardWell string + }{ + { + name: "initial dispenser preparation failure is unavailable", + dispenser: fakeDoorCardDispenser{ + prepareCurrent: dispenserCallResult{status: "Card jammed", err: errors.New("card jammed")}, + }, + wantHTTP: http.StatusServiceUnavailable, + wantMessage: "Dispense error: card jammed", + wantCalls: []string{"prepare current"}, + wantCardWell: "Card jammed", + }, + { + name: "initial empty card well has stable message", + dispenser: fakeDoorCardDispenser{ + prepareCurrent: dispenserCallResult{status: "Card empty", err: dispenser.ErrCardWellEmpty}, + }, + wantHTTP: http.StatusServiceUnavailable, + wantMessage: dispenser.CardWellEmptyMessage, + wantCalls: []string{"prepare current"}, + wantCardWell: "Card empty", + }, + { + name: "encoding and accepted delivery command succeed", + wantHTTP: http.StatusOK, + wantMessage: "Card issued successfully", + wantCalls: []string{"prepare current", "deliver current", "begin prepare next"}, + wantLockSequence: 1, + }, + { + name: "successful encoding with delivery command failure is unavailable", + 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"}, + wantLockSequence: 1, + wantCardWell: "Card jammed", + }, + { + name: "failed next-card dispatch does not undo delivered card", + dispenser: fakeDoorCardDispenser{ + beginNextErr: errors.New("dispatch failed"), + }, + wantHTTP: http.StatusOK, + wantMessage: "Card issued successfully", + wantCalls: []string{"prepare current", "deliver current", "begin prepare next"}, + wantLockSequence: 1, + }, + { + name: "encoding failure with safe recovery remains retryable", + lockErr: encodingErr, + wantHTTP: http.StatusBadGateway, + wantMessage: encodingErr.Error(), + wantCalls: []string{"prepare current", "deliver current", "prepare next"}, + wantLockSequence: 1, + }, + { + name: "encoding failure with failed-card delivery failure is unavailable", + 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", + wantCalls: []string{"prepare current", "deliver current"}, + wantLockSequence: 1, + wantCardWell: "Card jammed", + }, + { + name: "encoding failure with empty card well has stable message", + 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"}, + wantLockSequence: 1, + wantCardWell: "Card empty", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + dispenser := test.dispenser + lock := &fakeDoorCardLockServer{sequenceErr: test.lockErr} + + recorder, response, app := performIssueDoorCardRequest(t, &dispenser, lock) + + if recorder.Code != test.wantHTTP { + t.Fatalf("HTTP status = %d, want %d", recorder.Code, test.wantHTTP) + } + if response.Code != test.wantHTTP { + t.Fatalf("response code = %d, want %d", response.Code, test.wantHTTP) + } + if response.Message != test.wantMessage { + t.Fatalf("response message = %q, want %q", response.Message, test.wantMessage) + } + if !reflect.DeepEqual(dispenser.calls, test.wantCalls) { + t.Fatalf("dispenser calls = %#v, want %#v", dispenser.calls, test.wantCalls) + } + if lock.sequenceCalls != test.wantLockSequence { + t.Fatalf("lock sequence calls = %d, want %d", lock.sequenceCalls, test.wantLockSequence) + } + if test.wantLockSequence > 0 && lock.buildCalls != 1 { + t.Fatalf("build command calls = %d, want 1", lock.buildCalls) + } + if test.wantLockSequence == 0 && lock.buildCalls != 0 { + t.Fatalf("build command calls = %d, want 0", lock.buildCalls) + } + if got := app.CardWellStatus(); got != test.wantCardWell { + t.Fatalf("card-well status = %q, want %q", got, test.wantCardWell) + } + }) + } +} + +type responseTrackingRecorder struct { + *httptest.ResponseRecorder + wroteResponse bool +} + +func (r *responseTrackingRecorder) WriteHeader(statusCode int) { + r.wroteResponse = true + r.ResponseRecorder.WriteHeader(statusCode) +} + +func (r *responseTrackingRecorder) Write(body []byte) (int, error) { + r.wroteResponse = true + return r.ResponseRecorder.Write(body) +} + +func TestIssueDoorCardDispatchesNextCardBeforeHTTP200(t *testing.T) { + var recorder *responseTrackingRecorder + dispatchCalled := false + dispenser := &fakeDoorCardDispenser{ + beginNext: func() error { + dispatchCalled = true + if recorder.wroteResponse { + t.Error("HTTP response started before next-card preparation was dispatched") + } + return nil + }, + } + lock := &fakeDoorCardLockServer{} + payload := lockserver.DoorCardRequest{ + RoomField: "101", + CheckinTime: "2026-07-23 15:00:00 +0100", + CheckoutTime: "2026-07-24 11:00:00 +0100", + } + body, err := json.Marshal(payload) + if err != nil { + t.Fatal(err) + } + app := &App{disp: dispenser, lockserver: lock, cfg: &config.ConfigRec{}} + request := httptest.NewRequest(http.MethodPost, "/issuedoorcard", bytes.NewReader(body)) + request.Header.Set("Content-Type", "application/json") + recorder = &responseTrackingRecorder{ResponseRecorder: httptest.NewRecorder()} + + app.issueDoorCard(recorder, request) + + if !dispatchCalled { + t.Fatal("next-card preparation was not dispatched") + } + if recorder.Code != http.StatusOK { + t.Fatalf("HTTP status = %d, want %d", recorder.Code, http.StatusOK) + } +} + +func TestIssueDoorCardLogsNextCardDispatchFailureAndStillSucceeds(t *testing.T) { + var logOutput bytes.Buffer + standardLogger := log.StandardLogger() + previousOutput := standardLogger.Out + standardLogger.SetOutput(&logOutput) + t.Cleanup(func() { + standardLogger.SetOutput(previousOutput) + }) + + dispenser := &fakeDoorCardDispenser{beginNextErr: errors.New("dispatch failed")} + lock := &fakeDoorCardLockServer{} + recorder, _, _ := performIssueDoorCardRequest(t, dispenser, lock) + + if recorder.Code != http.StatusOK { + t.Fatalf("HTTP status = %d, want %d", recorder.Code, http.StatusOK) + } + logged := logOutput.String() + if !strings.Contains(logged, "dispatch failed") || + !strings.Contains(logged, "Next card preparation dispatch") { + t.Fatalf("dispatch failure log = %q", logged) + } +} diff --git a/internal/handlers/handlers.go b/internal/handlers/handlers.go index 2804031..d6e61b5 100644 --- a/internal/handlers/handlers.go +++ b/internal/handlers/handlers.go @@ -5,6 +5,8 @@ import ( "database/sql" "encoding/json" "encoding/xml" + "errors" + "fmt" "io" "net/http" "strings" @@ -25,8 +27,15 @@ import ( log "github.com/sirupsen/logrus" ) +type doorCardDispenser interface { + PrepareCurrentCard(context.Context) (string, error) + DeliverCurrentCard(context.Context) (string, error) + BeginPrepareNextCard(context.Context) error + PrepareNextCard(context.Context) (string, error) +} + type App struct { - disp *dispenser.Client + disp doorCardDispenser lockserver lockserver.LockServer paymentService *paymentsvc.Service isPayment bool @@ -376,47 +385,69 @@ func (app *App) issueDoorCard(w http.ResponseWriter, r *http.Request) { return } - // Ensure dispenser ready (card at encoder) BEFORE we attempt encoding. - // With queued dispenser ops, this will not clash with polling. - status, err := app.disp.DispenserStart(r.Context()) + status, err := app.disp.PrepareCurrentCard(r.Context()) app.SetCardWellStatus(status) if err != nil { logging.Error(types.ServiceName, err.Error(), "Dispense error", string(op), "", "", 0) + if errors.Is(err, dispenser.ErrCardWellEmpty) { + errorhandlers.WriteError(w, http.StatusServiceUnavailable, dispenser.CardWellEmptyMessage) + return + } errorhandlers.WriteError(w, http.StatusServiceUnavailable, "Dispense error: "+err.Error()) return } - // Always attempt to finalize after we have moved a card / started an issuance flow. - // This guarantees we eject and prepare the next card even on lock failures. - finalize := func() { - if app.disp == nil { - return - } - ctx, cancel := context.WithTimeout(context.Background(), 20*time.Second) - defer cancel() - - status, ferr := app.disp.DispenserFinal(ctx) - if ferr != nil { - logging.Error(types.ServiceName, ferr.Error(), "Dispenser final error", string(op), "", "", 0) - return - } - app.SetCardWellStatus(status) - } - // doorReq.RoomField = "104" // build lock server command app.lockserver.BuildCommand(doorReq, checkIn, checkOut) // lock server sequence - if err := app.lockserver.LockSequence(); err != nil { - logging.Error(types.ServiceName, err.Error(), "Key encoding", string(op), "", "", 0) - finalize() - errorhandlers.WriteError(w, http.StatusBadGateway, err.Error()) + encodingErr := app.lockserver.LockSequence() + if encodingErr != nil { + logging.Error(types.ServiceName, encodingErr.Error(), "Key encoding", string(op), "", "", 0) + } + + // Once encoding has started, finish the physical dispenser sequence even if + // the HTTP client disconnects. Finalization remains bounded by one shared timeout. + finalizeCtx, cancel := context.WithTimeout(context.Background(), 30*time.Second) + defer cancel() + + 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 } - // final dispenser steps - finalize() + 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 + } + + errorhandlers.WriteError(w, http.StatusBadGateway, encodingErr.Error()) + return + } + + if preparationErr := app.disp.BeginPrepareNextCard(finalizeCtx); preparationErr != nil { + logging.Error(types.ServiceName, preparationErr.Error(), "Next card preparation dispatch", string(op), "", "", 0) + } theResponse.Code = http.StatusOK theResponse.Message = "Card issued successfully" diff --git a/internal/handlers/testhandlers.go b/internal/handlers/testhandlers.go index e7a7cac..c512b6f 100644 --- a/internal/handlers/testhandlers.go +++ b/internal/handlers/testhandlers.go @@ -9,10 +9,10 @@ import ( "time" "gitea.futuresens.co.uk/futuresens/cmstypes" + "gitea.futuresens.co.uk/futuresens/hardlink/internal/creditcall" "gitea.futuresens.co.uk/futuresens/hardlink/internal/errorhandlers" "gitea.futuresens.co.uk/futuresens/hardlink/internal/lockserver" "gitea.futuresens.co.uk/futuresens/hardlink/internal/mail" - "gitea.futuresens.co.uk/futuresens/hardlink/internal/creditcall" "gitea.futuresens.co.uk/futuresens/hardlink/internal/types" "gitea.futuresens.co.uk/futuresens/logging" log "github.com/sirupsen/logrus" @@ -59,7 +59,7 @@ func (app *App) testIssueDoorCard(w http.ResponseWriter, r *http.Request) { // Ensure dispenser ready (card at encoder) BEFORE we attempt encoding. // With queued dispenser ops, this will not clash with polling. - status, err := app.disp.DispenserStart(r.Context()) + status, err := app.disp.PrepareCurrentCard(r.Context()) app.SetCardWellStatus(status) if err != nil { logging.Error(types.ServiceName, err.Error(), "Dispense error", string(op), "", "", 0) diff --git a/release notes.md b/release notes.md index ced29af..6b4cee5 100644 --- a/release notes.md +++ b/release notes.md @@ -2,6 +2,9 @@ builtVersion is a const in main.go +#### v1.3.5 - 23 July 2026 +fixed dispenser delivery confirmation + #### v1.3.4 - 23 July 2026 added support for Dojo terminal-unavailable responses