updates

internal/sms/http_sender.go

@@ -0,0 +1,191 @@
+package sms
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"io"
+	"net/http"
+	"os"
+	"strings"
+	"time"
+
+	"doormile/utils"
+)
+
+// A provider-agnostic HTTP gateway, and the wiring that installs it.
+//
+// This package called itself "the seam, not the integration", with a logging
+// sink standing in until a gateway was plugged in. The sink was never replaced:
+// sms.Register had no callers anywhere in the tree, so every customer
+// verification code since this surface shipped has gone to the application log
+// and nowhere else. Two consequences, both live in production:
+//
+//  1. No customer can complete sign-in without somebody reading the server log
+//     to them. That is the single blocker on the customer app, and it is why
+//     the app's offline dev mode became the only practical way in — which in
+//     turn is why bookings "made" in it never reached the admin console.
+//  2. Every OTP ever issued is sitting in log storage as plaintext. A
+//     credential in a log file is a credential in the wrong place.
+//
+// Rather than hard-coding one vendor, this posts to whatever gateway the
+// deployment names. The Indian providers this would plausibly use — MSG91,
+// Gupshup, Textlocal, Fast2SMS — all accept an authenticated POST carrying a
+// destination and a body, so one templated request covers them and swapping
+// vendors is configuration rather than a release.
+//
+// Configuration, all read once at startup. An absent SMS_GATEWAY_URL leaves the
+// log sink exactly where it is, so this change cannot break a deployment that
+// has not been configured yet:
+//
+//	SMS_GATEWAY_URL     endpoint to POST to; absent means "stay on the log sink"
+//	SMS_GATEWAY_METHOD  HTTP method, default POST
+//	SMS_GATEWAY_AUTH    Authorization header value, for vendors that use one
+//	SMS_GATEWAY_HEADER  one extra "Name: value" header, for vendors with their own key header
+//	SMS_GATEWAY_BODY    body template; {{phone}}, {{message}} and {{sender}} are substituted
+//	SMS_GATEWAY_TYPE    content type, default application/json
+//	SMS_SENDER_ID       the registered sender id, substituted as {{sender}}
+
+const gatewayTimeout = 10 * time.Second
+
+type httpSender struct {
+	url         string
+	method      string
+	auth        string
+	headerName  string
+	headerValue string
+	bodyTmpl    string
+	contentType string
+	senderID    string
+	client      *http.Client
+}
+
+func (httpSender) Name() string { return "http-gateway" }
+
+func (s httpSender) Send(phone, message string) error {
+	body := s.bodyTmpl
+	body = strings.ReplaceAll(body, "{{phone}}", phone)
+	body = strings.ReplaceAll(body, "{{message}}", jsonEscape(message))
+	body = strings.ReplaceAll(body, "{{sender}}", s.senderID)
+
+	ctx, cancel := context.WithTimeout(context.Background(), gatewayTimeout)
+	defer cancel()
+
+	req, err := http.NewRequestWithContext(ctx, s.method, s.url, bytes.NewReader([]byte(body)))
+	if err != nil {
+		return fmt.Errorf("sms: build gateway request: %w", err)
+	}
+	req.Header.Set("Content-Type", s.contentType)
+	if s.auth != "" {
+		req.Header.Set("Authorization", s.auth)
+	}
+	if s.headerName != "" {
+		req.Header.Set(s.headerName, s.headerValue)
+	}
+
+	resp, err := s.client.Do(req)
+	if err != nil {
+		return fmt.Errorf("sms: gateway unreachable: %w", err)
+	}
+	defer resp.Body.Close()
+
+	// Read a bounded slice of the response for the log. The gateway's reason
+	// for refusing — "insufficient balance", "DLT template not approved" — is
+	// the entire diagnosis, and it only ever appears in the body.
+	snippet, _ := io.ReadAll(io.LimitReader(resp.Body, 512))
+
+	if resp.StatusCode < 200 || resp.StatusCode >= 300 {
+		// The number is masked and the message is NOT logged: the message
+		// contains the code, which is the thing this whole file exists to keep
+		// out of the log.
+		utils.Error("sms: gateway rejected the send",
+			"status", resp.StatusCode,
+			"phone", maskPhone(phone),
+			"response", strings.TrimSpace(string(snippet)))
+		return fmt.Errorf("sms: gateway returned %d", resp.StatusCode)
+	}
+
+	utils.Info("sms: code delivered", "phone", maskPhone(phone))
+	return nil
+}
+
+// jsonEscape makes a message safe to interpolate into a JSON body template.
+// The OTP text carries no quotes today, but a template is a template and the
+// next message to go through here will not be this one.
+func jsonEscape(s string) string {
+	var b strings.Builder
+	for _, r := range s {
+		switch r {
+		case '"':
+			b.WriteString(`\"`)
+		case '\\':
+			b.WriteString(`\\`)
+		case '\n':
+			b.WriteString(`\n`)
+		case '\r':
+			b.WriteString(`\r`)
+		case '\t':
+			b.WriteString(`\t`)
+		default:
+			b.WriteRune(r)
+		}
+	}
+	return b.String()
+}
+
+// Configure installs a real gateway when one is configured, and says plainly
+// which transport the process ended up with.
+//
+// Called once from main() after config load. Deliberately loud in both
+// directions: a deployment that believes it can send texts and cannot is the
+// exact failure that has been live in this service since the customer surface
+// shipped, so it must not be possible to start without the answer appearing in
+// the boot log.
+func Configure() {
+	url := strings.TrimSpace(os.Getenv("SMS_GATEWAY_URL"))
+	if url == "" {
+		utils.Warn("SMS: no gateway configured (SMS_GATEWAY_URL is unset). " +
+			"Verification codes are written to THIS LOG and no text is sent. " +
+			"Customer sign-in cannot complete unless somebody reads the code out " +
+			"of here, or CX_STAGING_OTP is set on a non-production deployment.")
+		return
+	}
+
+	method := strings.ToUpper(strings.TrimSpace(os.Getenv("SMS_GATEWAY_METHOD")))
+	if method == "" {
+		method = http.MethodPost
+	}
+
+	bodyTmpl := os.Getenv("SMS_GATEWAY_BODY")
+	if strings.TrimSpace(bodyTmpl) == "" {
+		bodyTmpl = `{"to":"{{phone}}","message":"{{message}}","sender":"{{sender}}"}`
+	}
+
+	contentType := strings.TrimSpace(os.Getenv("SMS_GATEWAY_TYPE"))
+	if contentType == "" {
+		contentType = "application/json"
+	}
+
+	var headerName, headerValue string
+	if raw := strings.TrimSpace(os.Getenv("SMS_GATEWAY_HEADER")); raw != "" {
+		if name, value, ok := strings.Cut(raw, ":"); ok {
+			headerName = strings.TrimSpace(name)
+			headerValue = strings.TrimSpace(value)
+		} else {
+			utils.Warn("SMS: SMS_GATEWAY_HEADER is not in 'Name: value' form and was ignored",
+				"value", raw)
+		}
+	}
+
+	Register(httpSender{
+		url:         url,
+		method:      method,
+		auth:        strings.TrimSpace(os.Getenv("SMS_GATEWAY_AUTH")),
+		headerName:  headerName,
+		headerValue: headerValue,
+		bodyTmpl:    bodyTmpl,
+		contentType: contentType,
+		senderID:    strings.TrimSpace(os.Getenv("SMS_SENDER_ID")),
+		client:      &http.Client{Timeout: gatewayTimeout},
+	})
+}

internal/sms/http_sender_test.go

@@ -0,0 +1,186 @@
+package sms
+
+import (
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+	"time"
+)
+
+// The gateway that closes the sign-in blocker.
+//
+// sms.Register had no callers anywhere in the tree, so logSender was never
+// replaced and every customer verification code went to the application log
+// instead of to a phone. That is why nobody could sign in, why the app's
+// offline dev mode became the only practical way in, and why bookings "made"
+// in that mode never reached the admin console.
+
+func restoreSender(t *testing.T) {
+	t.Helper()
+	previous := active
+	t.Cleanup(func() { active = previous })
+}
+
+func testSender(url, bodyTmpl string) httpSender {
+	if bodyTmpl == "" {
+		bodyTmpl = `{"to":"{{phone}}","message":"{{message}}","sender":"{{sender}}"}`
+	}
+	return httpSender{
+		url:         url,
+		method:      http.MethodPost,
+		bodyTmpl:    bodyTmpl,
+		contentType: "application/json",
+		senderID:    "DRMILE",
+		client:      &http.Client{Timeout: 5 * time.Second},
+	}
+}
+
+// The destination and the code have to actually reach the gateway.
+func TestGatewaySendsPhoneAndCode(t *testing.T) {
+	var got string
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		b, _ := io.ReadAll(r.Body)
+		got = string(b)
+		w.WriteHeader(http.StatusOK)
+	}))
+	defer srv.Close()
+
+	restoreSender(t)
+	Register(testSender(srv.URL, ""))
+
+	if err := SendOTP("+919876543210", "4821"); err != nil {
+		t.Fatalf("SendOTP: %v", err)
+	}
+	for _, want := range []string{"+919876543210", "4821", "DRMILE"} {
+		if !strings.Contains(got, want) {
+			t.Errorf("gateway body %q is missing %q", got, want)
+		}
+	}
+}
+
+// A refused send — no balance, unapproved DLT template — must surface as an
+// error. Swallowing it tells the customer a code is on its way when it is not,
+// which is precisely the failure logSender has been producing all along.
+func TestGatewayRefusalIsReported(t *testing.T) {
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusPaymentRequired)
+		_, _ = w.Write([]byte(`{"error":"insufficient balance"}`))
+	}))
+	defer srv.Close()
+
+	restoreSender(t)
+	Register(testSender(srv.URL, ""))
+
+	if err := SendOTP("+919876543210", "4821"); err == nil {
+		t.Error("a rejected send reported success — the customer would wait for a " +
+			"text that is never coming")
+	}
+}
+
+// An unreachable gateway is an error, not a silent no-op.
+func TestUnreachableGatewayIsReported(t *testing.T) {
+	restoreSender(t)
+	Register(testSender("http://127.0.0.1:1/unreachable", ""))
+
+	if err := SendOTP("+919876543210", "4821"); err == nil {
+		t.Error("an unreachable gateway reported success")
+	}
+}
+
+// A quote in the message must not break a JSON body template.
+func TestMessageIsEscapedForJSON(t *testing.T) {
+	var got string
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		b, _ := io.ReadAll(r.Body)
+		got = string(b)
+		w.WriteHeader(http.StatusOK)
+	}))
+	defer srv.Close()
+
+	restoreSender(t)
+	Register(testSender(srv.URL, ""))
+
+	if err := active.Send("+919876543210", `say "hello"`); err != nil {
+		t.Fatalf("send: %v", err)
+	}
+	if strings.Contains(got, `say "hello"`) {
+		t.Errorf("an unescaped quote reached the JSON body: %q", got)
+	}
+	if !strings.Contains(got, `say \"hello\"`) {
+		t.Errorf("the message was not escaped as expected: %q", got)
+	}
+}
+
+// Vendors differ; the template is what makes one sender cover all of them.
+func TestBodyTemplateIsVendorAgnostic(t *testing.T) {
+	var got string
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		b, _ := io.ReadAll(r.Body)
+		got = string(b)
+		w.WriteHeader(http.StatusOK)
+	}))
+	defer srv.Close()
+
+	restoreSender(t)
+	Register(testSender(srv.URL, "mobiles={{phone}}&message={{message}}&sender={{sender}}"))
+
+	if err := SendOTP("+919876543210", "4821"); err != nil {
+		t.Fatalf("send: %v", err)
+	}
+	if !strings.HasPrefix(got, "mobiles=+919876543210&message=") {
+		t.Errorf("form-encoded template not honoured: %q", got)
+	}
+}
+
+// Configure is what gives sms.Register its first caller. With no URL it must
+// leave the log sink exactly where it is, so this change cannot break a
+// deployment that has not been configured yet.
+func TestConfigureLeavesTheLogSinkWhenUnset(t *testing.T) {
+	restoreSender(t)
+	active = logSender{}
+	setEnv(t, "SMS_GATEWAY_URL", "")
+
+	Configure()
+
+	if Configured() {
+		t.Error("Configure installed a gateway with no SMS_GATEWAY_URL set")
+	}
+	if Transport() != "log" {
+		t.Errorf("Transport() = %q, want \"log\"", Transport())
+	}
+}
+
+func TestConfigureInstallsTheGatewayWhenSet(t *testing.T) {
+	restoreSender(t)
+	active = logSender{}
+	setEnv(t, "SMS_GATEWAY_URL", "https://sms.example.invalid/send")
+
+	Configure()
+
+	if !Configured() {
+		t.Fatal("Configure did not install a gateway despite SMS_GATEWAY_URL being set")
+	}
+	if Transport() != "http-gateway" {
+		t.Errorf("Transport() = %q, want \"http-gateway\"", Transport())
+	}
+}
+
+// In production the log sink must refuse rather than write a live credential
+// to the log and report success.
+func TestLogSenderRefusesInProduction(t *testing.T) {
+	restoreSender(t)
+	active = logSender{}
+
+	setEnv(t, "ENV", "production")
+	if err := SendOTP("+919876543210", "4821"); err == nil {
+		t.Error("with no gateway in production, SendOTP reported success — the code " +
+			"went to the log and the customer was told it was sent")
+	}
+
+	setEnv(t, "ENV", "development")
+	if err := SendOTP("+919876543210", "4821"); err != nil {
+		t.Errorf("outside production the log sink must still work for QA: %v", err)
+	}
+}

internal/sms/sms.go

@@ -39,6 +39,17 @@ type logSender struct{}
 func (logSender) Name() string { return "log" }
 
 func (logSender) Send(phone, message string) error {
+	// In production this is a failure, not a fallback. A code that only
+	// reaches the application log has not been delivered, and returning nil
+	// reports a send that did not happen: the customer waits for a text that
+	// is never coming, and the endpoint cheerfully answers sent:true. An
+	// error at least surfaces as a clear failure on the sign-in screen.
+	if strings.EqualFold(strings.TrimSpace(os.Getenv("ENV")), "production") {
+		utils.Error("SMS NOT CONFIGURED in production — refusing to write a live "+
+			"verification code to the log. Set SMS_GATEWAY_URL.", "phone", maskPhone(phone))
+		return fmt.Errorf("sms: no gateway configured")
+	}
+
 	utils.Warn("SMS NOT CONFIGURED — code written to the log instead of being sent",
 		"phone", maskPhone(phone), "message", message)
 	return nil

main.go

@@ -15,6 +15,7 @@ import (
 	"doormile/internal/assignment"
 	"doormile/internal/notify"
 	"doormile/internal/routing"
+	"doormile/internal/sms"
 	"doormile/internal/worker"
 	"doormile/middlewares"
 	"doormile/migrations"
@@ -92,6 +93,13 @@ func main() {
 	db.InitNATS(cfg)
 	notify.InitFCM()
 
+	// Install the SMS gateway. Until this call existed, sms.Register had no
+	// callers anywhere in the tree, so every customer verification code was
+	// written to this log and no text was ever sent — the single blocker on
+	// customer sign-in, and the reason bookings were being made in the app's
+	// offline mode and never reaching the console.
+	sms.Configure()
+
 	// 3. Run GORM migrations for logistics tables
 	if db.DB != nil {
 		err := migrations.Migrate(db.DB)

middlewares/idempotency.go

@@ -70,10 +70,27 @@ func Idempotency() fiber.Handler {
 			return err
 		}
 
-		// Cache only deterministic outcomes (2xx/4xx). A 5xx is transient — the
-		// retry should get a genuine second attempt, not a cached failure.
+		// Cache SUCCESS only.
+		//
+		// This used to store any status below 500, on the reasoning that a 4xx
+		// is deterministic. A 4xx is not deterministic — it is a refusal made
+		// against state that moves. POST /customer/auth/otp/verify returns 401
+		// when the submitted code does not match the one in Redis, and the whole
+		// point of that screen is that the customer then gets the code right.
+		// With the refusal cached for 24 hours, the retry that should have
+		// worked replayed the old 401 instead — confirmed live against
+		// api.doormile.com, where the second attempt came back carrying
+		// Idempotent-Replay: true. One typo locked a customer out for a day.
+		// The same shape applies to 403 after a permission is granted, 404 after
+		// a record is created, and 429 after a window rolls over.
+		//
+		// Nothing is lost by narrowing it. This middleware exists to stop a retry
+		// repeating a SIDE EFFECT — a second pickup, a second COD collection, a
+		// second session. A request that ended 4xx performed no side effect, so
+		// re-executing it is exactly as safe as the first attempt was, and
+		// strictly more correct than replaying a stale no.
 		status := c.Response().StatusCode()
-		if status < 500 {
+		if isCacheableStatus(status) {
 			body := string(c.Response().Body())
 			db.Rdb.Set(context.Background(), base, strconv.Itoa(status)+sep+body, ttl)
 		}
@@ -82,6 +99,12 @@ func Idempotency() fiber.Handler {
 	}
 }
 
+// isCacheableStatus reports whether a response may be stored and replayed to
+// a later request carrying the same key. Only a 2xx may — see above.
+func isCacheableStatus(status int) bool {
+	return status >= 200 && status < 300
+}
+
 // idempotencyScope namespaces a key so one caller's stored response can never
 // be replayed to another.
 //

middlewares/idempotency_test.go

@@ -120,3 +120,53 @@ func TestPincodeInOperatingCity(t *testing.T) {
 		}
 	}
 }
+
+// What may be replayed from the idempotency cache.
+//
+// The middleware exists to stop a retry repeating a SIDE EFFECT — a second
+// pickup, a second COD collection, a second session. It used to cache every
+// status below 500, which quietly extended that to refusals.
+//
+// POST /customer/auth/otp/verify is where it bit: a wrong code returns 401, and
+// the whole purpose of the screen is that the customer then gets it right. With
+// the 401 cached for 24 hours, the retry that should have worked replayed the
+// old refusal. Confirmed live against api.doormile.com — the second attempt
+// came back carrying `Idempotent-Replay: true`.
+
+func TestOnlySuccessfulResponsesAreCacheable(t *testing.T) {
+	cases := []struct {
+		status int
+		want   bool
+		why    string
+	}{
+		{200, true, "a completed mutation is exactly what must not run twice"},
+		{201, true, "a created booking must not be created again"},
+		{204, true, "a completed no-content mutation still ran"},
+
+		{400, false, "a malformed body performed no side effect; re-running is free"},
+		{401, false, "the code was wrong; the retry is meant to be right"},
+		{403, false, "a permission can be granted between attempts"},
+		{404, false, "the record can exist by the time of the retry"},
+		{409, false, "a conflict can clear"},
+		{422, false, "a district can reopen"},
+		{429, false, "the rate-limit window rolls over"},
+
+		{500, false, "transient; the retry deserves a genuine second attempt"},
+		{503, false, "the dependency can come back"},
+	}
+
+	for _, tc := range cases {
+		if got := isCacheableStatus(tc.status); got != tc.want {
+			t.Errorf("status %d cacheable = %v, want %v — %s", tc.status, got, tc.want, tc.why)
+		}
+	}
+}
+
+// The specific regression, stated as itself: a failed sign-in must never be
+// replayed to a customer who has since typed the right code.
+func TestAFailedOtpVerifyIsNotCached(t *testing.T) {
+	if isCacheableStatus(fiber.StatusUnauthorized) {
+		t.Fatal("a 401 from /customer/auth/otp/verify would be cached for 24 hours, " +
+			"so the retry with the correct code replays the refusal instead of running")
+	}
+}

routes/routes.go

@@ -7,6 +7,7 @@ import (
 	"doormile/config"
 	"doormile/controllers"
 	"doormile/db"
+	"doormile/internal/sms"
 	"doormile/internal/ws"
 	"doormile/middlewares"
 
@@ -73,6 +74,15 @@ func RegisterRoutes(app *fiber.App, cfg *config.Config) {
 			"checks": fiber.Map{
 				"postgres": dbStatus,
 				"redis":    redisStatus,
+				// Reported, but deliberately NOT gating readiness: the miler and
+				// console surfaces work perfectly without SMS. It is here because
+				// 'the OTP never arrived' was answerable only by reading code, and
+				// for this service's whole life the answer has been that no gateway
+				// was ever registered.
+				"sms": fiber.Map{
+					"transport":  sms.Transport(),
+					"configured": sms.Configured(),
+				},
 			},
 		})
 	})