diff --git a/internal/sms/http_sender.go b/internal/sms/http_sender.go new file mode 100644 index 0000000..0de2d30 --- /dev/null +++ b/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}, + }) +} diff --git a/internal/sms/http_sender_test.go b/internal/sms/http_sender_test.go new file mode 100644 index 0000000..c24d46a --- /dev/null +++ b/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) + } +} diff --git a/internal/sms/sms.go b/internal/sms/sms.go index 241e829..c374462 100644 --- a/internal/sms/sms.go +++ b/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 diff --git a/main.go b/main.go index 4ddc62e..93a55cb 100644 --- a/main.go +++ b/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) diff --git a/middlewares/idempotency.go b/middlewares/idempotency.go index 785d685..9308e78 100644 --- a/middlewares/idempotency.go +++ b/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. // diff --git a/middlewares/idempotency_test.go b/middlewares/idempotency_test.go index a9db02f..df9a8f5 100644 --- a/middlewares/idempotency_test.go +++ b/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") + } +} diff --git a/routes/routes.go b/routes/routes.go index 966419a..f3eed09 100644 --- a/routes/routes.go +++ b/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(), + }, }, }) })