Fix failed delivery were not logged with level=error #18

#18

cmd/server/main.go

@@ -2,6 +2,7 @@ package main
 
 import (
 	"errors"
+	"log/slog"
 	"net/http"
 	"os"
 	"time"
@@ -12,10 +13,16 @@ import (
 	"github.com/authgear/authgear-sms-gateway/pkg/lib/config"
 	"github.com/authgear/authgear-sms-gateway/pkg/lib/logger"
 	"github.com/authgear/authgear-sms-gateway/pkg/lib/sms"
+	"github.com/authgear/authgear-sms-gateway/pkg/lib/sms/smsclient"
 )
 
 func main() {
-	logger := logger.NewLogger()
+	stderrHandler := logger.NewTextHandler()
+	contextHandler := &logger.ContextHandler{
+		ContextKey: smsclient.SendContextKey,
+		Handler:    stderrHandler,
+	}
+	logger := slog.New(contextHandler)
 
 	err := godotenv.Load()
 	if errors.Is(err, os.ErrNotExist) {
@@ -42,11 +49,11 @@ func main() {
 	if err != nil {
 		panic(err)
 	}
-	smsClientMap := sms.NewSMSClientMap(cfg, httpClient, logger)
+	smsProviderMap := sms.NewSMSProviderMap(cfg, httpClient, logger)
 	smsService := &sms.SMSService{
-		Logger:       logger,
-		RootConfig:   cfg,
-		SMSClientMap: smsClientMap,
+		Logger:         logger,
+		RootConfig:     cfg,
+		SMSProviderMap: smsProviderMap,
 	}
 
 	http.Handle("/healthz", &handler.HealthzHandler{})

pkg/handler/api.go

@@ -46,8 +46,8 @@ func (c Code) HTTPStatusCode() int {
 }
 
 type ResponseBody struct {
-	Code             Code                      `json:"code"`
-	ErrorDescription string                    `json:"error_description,omitempty"`
-	DumpedResponse   []byte                    `json:"dumped_response,omitempty"`
-	Info             *smsclient.SendResultInfo `json:"info,omitempty"`
+	Code             Code                   `json:"code"`
+	ErrorDescription string                 `json:"error_description,omitempty"`
+	DumpedResponse   []byte                 `json:"dumped_response,omitempty"`
+	Info             *smsclient.SendContext `json:"info,omitempty"`
 }

pkg/handler/send.go

@@ -52,16 +52,22 @@ func (h *SendHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	logger := h.Logger.With(
-		"app_id", body.AppID,
-		"to", body.To,
-		"template_name", body.TemplateName,
-		"language_tag", body.LanguageTag,
-	)
+	r = r.WithContext(smsclient.WithSendContext(
+		r.Context(),
+		func(sendCtx *smsclient.SendContext) {
+			sendCtx.Root = &smsclient.SendContextRoot{
+				AppID:        body.AppID,
+				To:           body.To,
+				TemplateName: body.TemplateName,
+				LanguageTag:  body.LanguageTag,
+			}
+		},
+	))
 
-	logger.Info("received send request")
+	h.Logger.InfoContext(r.Context(), "received send request")
 
 	sendResult, err := h.SMSService.Send(
+		r.Context(),
 		body.AppID,
 		&smsclient.SendOptions{
 			To:                body.To,
@@ -73,22 +79,23 @@ func (h *SendHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	)
 
 	if err != nil {
-		var errorUnsuccessResponse *smsclient.SendResult
+		var errorUnsuccessResponse *smsclient.SendResultError
 		if errors.As(err, &errorUnsuccessResponse) {
-			logger.Error("unknown response",
+			h.Logger.ErrorContext(r.Context(), "unsuccessful response",
 				"dumped_response", string(errorUnsuccessResponse.DumpedResponse),
 				"error", err.Error(),
 			)
+			info := smsclient.GetSendContext(r.Context())
 			h.write(w, &ResponseBody{
 				Code:             CodeUnknownResponse,
 				DumpedResponse:   errorUnsuccessResponse.DumpedResponse,
 				ErrorDescription: err.Error(),
-				Info:             errorUnsuccessResponse.Info,
+				Info:             info,
 			})
 			return
 		}
 
-		logger.Error("unknown error",
+		h.Logger.ErrorContext(r.Context(), "unknown error",
 			"error", err.Error(),
 		)
 		h.write(w, &ResponseBody{
@@ -98,16 +105,13 @@ func (h *SendHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	var attrs []slog.Attr
-	if sendResult.Info.SendResultInfoTwilio != nil && sendResult.Info.SendResultInfoTwilio.SegmentCount != nil {
-		attrs = append(attrs, slog.Int("segment_count", *sendResult.Info.SendResultInfoTwilio.SegmentCount))
-	}
-	logger.LogAttrs(r.Context(), slog.LevelInfo, "finished send request", attrs...)
+	h.Logger.InfoContext(r.Context(), "finished send request")
 
+	info := smsclient.GetSendContext(r.Context())
 	h.write(w, &ResponseBody{
 		Code:           CodeOK,
 		DumpedResponse: sendResult.DumpedResponse,
-		Info:           sendResult.Info,
+		Info:           info,
 	})
 }
 

pkg/lib/logger/context.go

@@ -0,0 +1,9 @@
+package logger
+
+import (
+	"log/slog"
+)
+
+type LoggerContexter interface {
+	GetAttrs() []slog.Attr
+}

pkg/lib/logger/context_handler.go

@@ -0,0 +1,38 @@
+package logger
+
+import (
+	"context"
+	"log/slog"
+)
+
+type ContextHandler struct {
+	ContextKey interface{}
+	Handler    slog.Handler
+}
+
+var _ slog.Handler = &ContextHandler{}
+
+func (h *ContextHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	return h.Handler.Enabled(ctx, level)
+}
+
+func (h *ContextHandler) Handle(ctx context.Context, record slog.Record) error {
+	loggerContexter, ok := ctx.Value(h.ContextKey).(LoggerContexter)
+	if ok && loggerContexter != nil {
+		attrs := loggerContexter.GetAttrs()
+		record.AddAttrs(attrs...)
+	}
+	return h.Handler.Handle(ctx, record)
+}
+
+func (h *ContextHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return &ContextHandler{
+		Handler: h.Handler.WithAttrs(attrs),
+	}
+}
+
+func (h *ContextHandler) WithGroup(name string) slog.Handler {
+	return &ContextHandler{
+		Handler: h.Handler.WithGroup(name),
+	}
+}

pkg/lib/logger/text_handler.go

@@ -0,0 +1,10 @@
+package logger
+
+import (
+	"log/slog"
+	"os"
+)
+
+func NewTextHandler() *slog.TextHandler {
+	return slog.NewTextHandler(os.Stderr, nil)
+}

pkg/lib/sms/accessyou/sendsms.go

@@ -1,6 +1,7 @@
 package accessyou
 
 import (
+	"context"
 	"errors"
 	"io"
 	"log/slog"
@@ -21,6 +22,7 @@ func fixRespData(respData []byte) []byte {
 }
 
 func SendSMS(
+	ctx context.Context,
 	client *http.Client,
 	baseUrl string,
 	accountNo string,
@@ -69,7 +71,7 @@ func SendSMS(
 	if err != nil {
 		return nil, nil, errors.Join(
 			err,
-			&smsclient.SendResult{
+			&smsclient.SendResultError{
 				DumpedResponse: dumpedResponse,
 			},
 		)
@@ -80,13 +82,13 @@ func SendSMS(
 	if err != nil {
 		return nil, nil, errors.Join(
 			err,
-			&smsclient.SendResult{
+			&smsclient.SendResultError{
 				DumpedResponse: dumpedResponse,
 			},
 		)
 	}
 
-	logger.Info("accessyou response",
+	logger.InfoContext(ctx, "accessyou response",
 		"msg_id", sendSMSResponse.MessageID,
 		"msg_status", sendSMSResponse.Status,
 		"msg_status_desc", sendSMSResponse.Description,

pkg/lib/sms/accessyou/sendsms_test.go

@@ -2,6 +2,7 @@ package accessyou
 
 import (
 	"bytes"
+	"context"
 	"io"
 	"log/slog"
 	"net/http"
@@ -36,7 +37,8 @@ func TestSendSMS(t *testing.T) {
 			Body(bytes.NewReader([]byte(successResponseWithBOM)))
 
 		logger := slog.New(slog.NewTextHandler(io.Discard, nil))
-		dumpedResponse, parsedResponse, err := SendSMS(httpClient, baseUrl, accountNo, user, pwd, sender, to, body, logger)
+		ctx := context.Background()
+		dumpedResponse, parsedResponse, err := SendSMS(ctx, httpClient, baseUrl, accountNo, user, pwd, sender, to, body, logger)
 
 		So(err, ShouldBeNil)
 		So(string(dumpedResponse), ShouldEqual, "HTTP/1.1 200 OK\r\nContent-Length: 131\r\n\r\n"+successResponseWithBOM)

pkg/lib/sms/accessyou/smsclient.go

@@ -1,6 +1,7 @@
 package accessyou
 
 import (
+	"context"
 	"log/slog"
 	"net/http"
 	"regexp"
@@ -48,14 +49,11 @@ func fixPhoneNumber(phoneNumber string) string {
 	return plusHyphensRegexp.ReplaceAllString(phoneNumber, "")
 }
 
-func (n *AccessYouClient) Send(options *smsclient.SendOptions) (*smsclient.SendResult, error) {
-	info := &smsclient.SendResultInfo{
-		SendResultInfoAccessYou: &smsclient.SendResultInfoAccessYou{},
-	}
-
+func (n *AccessYouClient) Send(ctx context.Context, options *smsclient.SendOptions) (*smsclient.SendResultSuccess, error) {
 	to := fixPhoneNumber(string(options.To))
 
 	dumpedResponse, sendSMSResponse, err := SendSMS(
+		ctx,
 		n.Client,
 		n.BaseUrl,
 		n.AccountNo,
@@ -70,11 +68,17 @@ func (n *AccessYouClient) Send(options *smsclient.SendOptions) (*smsclient.SendR
 		return nil, err
 	}
 
-	return &smsclient.SendResult{
+	// Success case.
+	if sendSMSResponse.Status == "100" {
+		return &smsclient.SendResultSuccess{
+			DumpedResponse: dumpedResponse,
+		}, nil
+	}
+
+	// Failed case.
+	return nil, &smsclient.SendResultError{
 		DumpedResponse: dumpedResponse,
-		Success:        sendSMSResponse.Status == "100",
-		Info:           info,
-	}, nil
+	}
 }
 
 var _ smsclient.RawClient = &AccessYouClient{}

pkg/lib/sms/provider.go

@@ -9,20 +9,20 @@ import (
 	"github.com/authgear/authgear-sms-gateway/pkg/lib/sms/smsclient"
 )
 
-type SMSClientMap map[string]smsclient.RawClient
+type SMSProviderMap map[string]smsclient.RawClient
 
-func NewSMSClientMap(c *config.RootConfig, httpClient *http.Client, logger *slog.Logger) SMSClientMap {
+func NewSMSProviderMap(c *config.RootConfig, httpClient *http.Client, logger *slog.Logger) SMSProviderMap {
 	var clientMap = make(map[string]smsclient.RawClient)
 
 	for _, provider := range c.Providers {
 		client := NewClientFromConfigProvider(provider, httpClient, logger)
 		clientMap[provider.Name] = client
 	}
 
-	return SMSClientMap(clientMap)
+	return SMSProviderMap(clientMap)
 }
 
-func (s SMSClientMap) GetClientByName(name string) smsclient.RawClient {
+func (s SMSProviderMap) GetProviderByName(name string) smsclient.RawClient {
 	client := s[name]
 	if client == nil {
 		panic(fmt.Errorf("Unknown client %v", name))

pkg/lib/sms/selector.go

@@ -6,7 +6,7 @@ import (
 	"github.com/authgear/authgear-sms-gateway/pkg/lib/config"
 )
 
-func GetClientNameByMatch(c *config.RootConfig, ctx *MatchContext) string {
+func GetProviderNameByMatch(c *config.RootConfig, ctx *MatchContext) string {
 	var defaultClient string
 	for _, providerSelector := range c.ProviderSelector.Switch {
 		matcher := ParseMatcher(providerSelector)

pkg/lib/sms/selector_test.go

@@ -64,7 +64,7 @@ provider_selector:
 func TestSelector(t *testing.T) {
 	test := func(convey string, configYAML string, ctx *MatchContext, expectedName string) {
 		c, _ := config.ParseRootConfigFromYAML([]byte(configYAML))
-		res := GetClientNameByMatch(c, ctx)
+		res := GetProviderNameByMatch(c, ctx)
 		Convey(convey, t, func() {
 			So(res, ShouldEqual, expectedName)
 		})

pkg/lib/sms/sendcloud/send.go

@@ -1,6 +1,7 @@
 package sendcloud
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"io"
@@ -12,7 +13,7 @@ import (
 	"github.com/authgear/authgear-sms-gateway/pkg/lib/sms/smsclient"
 )
 
-func Send(client *http.Client, baseUrl string, sendRequest *SendRequest, smsKey string, logger *slog.Logger) ([]byte, *SendResponse, error) {
+func Send(ctx context.Context, client *http.Client, baseUrl string, sendRequest *SendRequest, smsKey string, logger *slog.Logger) ([]byte, *SendResponse, error) {
 	values := sendRequest.ToValues()
 	values.Set("signature", sendRequest.Sign(smsKey))
 
@@ -36,7 +37,7 @@ func Send(client *http.Client, baseUrl string, sendRequest *SendRequest, smsKey
 	if err != nil {
 		return nil, nil, errors.Join(
 			err,
-			&smsclient.SendResult{
+			&smsclient.SendResultError{
 				DumpedResponse: dumpedResponse,
 			},
 		)
@@ -46,13 +47,13 @@ func Send(client *http.Client, baseUrl string, sendRequest *SendRequest, smsKey
 	if err != nil {
 		return nil, nil, errors.Join(
 			err,
-			&smsclient.SendResult{
+			&smsclient.SendResultError{
 				DumpedResponse: dumpedResponse,
 			},
 		)
 	}
 
-	logger.Info("sendcloud response",
+	logger.InfoContext(ctx, "sendcloud response",
 		"result", sendResponse.Result,
 		"statusCode", sendResponse.StatusCode,
 		"message", sendResponse.Message,