Add handleApiEvent, logApiResponse, op error types

The HTTP implemention now guarantees that all errors are reported via
the HTTP response, not by returning an error to the Lambda framework.
All HTTP requests are now logged by the Lambda function, in addition to
any logging by the API Gateway.

In the process, I learned why it's always good practice to return
"error" instead of a custom error type:

- "Go FAQ: Why is my nil error value not equal to nil?"
  https://go.dev/doc/faq#nil_error

handler/handler.go

@@ -42,14 +42,19 @@ func NewHandler(
 	}
 }
 
+type errorWithStatus struct {
+	HttpStatus int
+	Message    string
+}
+
+func (err *errorWithStatus) Error() string {
+	return err.Message
+}
+
 func (h *Handler) HandleEvent(event *Event) (any, error) {
 	switch event.Type {
 	case ApiRequest:
-		if req, err := newApiRequest(&event.ApiRequest); err != nil {
-			return nil, err
-		} else {
-			return h.handleApiRequest(req)
-		}
+		return h.handleApiEvent(&event.ApiRequest), nil
 	case MailtoEvent:
 		// If I understand the contract correctly, there should only ever be one
 		// valid Record per event. However, we have the technology to deal
@@ -64,6 +69,47 @@ func (h *Handler) HandleEvent(event *Event) (any, error) {
 	return nil, fmt.Errorf("unexpected event type: %s: %+v", event.Type, event)
 }
 
+func (h *Handler) handleApiEvent(
+	origReq *events.APIGatewayV2HTTPRequest,
+) *events.APIGatewayV2HTTPResponse {
+	var res *events.APIGatewayV2HTTPResponse = nil
+	req, err := newApiRequest(origReq)
+
+	if err == nil {
+		res, err = h.handleApiRequest(req)
+	}
+
+	if err != nil {
+		errorStatus := http.StatusInternalServerError
+		if apiErr, ok := err.(*errorWithStatus); ok {
+			errorStatus = apiErr.HttpStatus
+		}
+		res = &events.APIGatewayV2HTTPResponse{StatusCode: errorStatus}
+	}
+	logApiResponse(origReq, res, err)
+	return res
+}
+
+func logApiResponse(
+	req *events.APIGatewayV2HTTPRequest,
+	res *events.APIGatewayV2HTTPResponse,
+	err error,
+) {
+	reqId := req.RequestContext.RequestID
+	desc := req.RequestContext.HTTP
+	errMsg := ""
+
+	if err != nil {
+		errMsg = ": " + err.Error()
+	}
+
+	log.Printf(`%s: %s "%s %s %s" %d%s`,
+		reqId,
+		desc.SourceIP, desc.Method, desc.Path, desc.Protocol, res.StatusCode,
+		errMsg,
+	)
+}
+
 func newApiRequest(req *events.APIGatewayV2HTTPRequest) (*apiRequest, error) {
 	contentType, foundContentType := req.Headers["content-type"]
 	body := req.Body
@@ -121,14 +167,12 @@ func (h *Handler) handleApiRequest(
 
 	if op, err := parseApiRequest(req); err != nil {
 		return h.respondToParseError(res, err)
-	} else if result, err := h.performOperation(op, err); err != nil {
-		res.StatusCode = http.StatusInternalServerError
-		return res, err
+	} else if result, err := h.performOperation(op); err != nil {
+		return nil, err
 	} else if op.OneClick {
 		res.StatusCode = http.StatusOK
 	} else if redirect, ok := h.Redirects[result]; !ok {
-		res.StatusCode = http.StatusInternalServerError
-		return res, fmt.Errorf("no redirect for op result: %s", result)
+		return nil, fmt.Errorf("no redirect for op result: %s", result)
 	} else {
 		res.StatusCode = http.StatusSeeOther
 		res.Headers["location"] = redirect
@@ -146,8 +190,7 @@ func (h *Handler) respondToParseError(
 		response.StatusCode = http.StatusBadRequest
 		response.Body = fmt.Sprintf("%s\n", err)
 	} else if redirect, ok := h.Redirects[ops.Invalid]; !ok {
-		response.StatusCode = http.StatusInternalServerError
-		return response, fmt.Errorf("no redirect for invalid operation")
+		return nil, errors.New("no redirect for invalid operation")
 	} else {
 		response.StatusCode = http.StatusSeeOther
 		response.Headers["location"] = redirect
@@ -156,17 +199,26 @@ func (h *Handler) respondToParseError(
 }
 
 func (h *Handler) performOperation(
-	op *eventOperation, err error,
+	op *eventOperation,
 ) (ops.OperationResult, error) {
+	result := ops.Invalid
+	var err error = nil
+
 	switch op.Type {
 	case SubscribeOp:
-		return h.Agent.Subscribe(op.Email)
+		result, err = h.Agent.Subscribe(op.Email)
 	case VerifyOp:
-		return h.Agent.Verify(op.Email, op.Uid)
+		result, err = h.Agent.Verify(op.Email, op.Uid)
 	case UnsubscribeOp:
-		return h.Agent.Unsubscribe(op.Email, op.Uid)
+		result, err = h.Agent.Unsubscribe(op.Email, op.Uid)
+	default:
+		err = fmt.Errorf("can't handle operation type: %s", op.Type)
+	}
+
+	if opErr, ok := err.(*ops.OperationErrorExternal); ok {
+		err = &errorWithStatus{http.StatusBadGateway, opErr.Error()}
 	}
-	return ops.Invalid, fmt.Errorf("can't handle operation type: %s", op.Type)
+	return result, err
 }
 
 func newMailtoEvent(ses *events.SimpleEmailService) *mailtoEvent {

handler/handler_test.go

@@ -2,8 +2,11 @@ package handler
 
 import (
 	"encoding/base64"
+	"errors"
 	"fmt"
+	"log"
 	"net/http"
+	"strings"
 	"testing"
 
 	"github.com/aws/aws-lambda-go/events"
@@ -50,6 +53,8 @@ type fixture struct {
 const testEmailDomain = "mike-bland.com"
 const testUnsubscribeAddress = "unsubscribe@" + testEmailDomain
 
+// const testValidUid = "00000000-1111-2222-3333-444444444444"
+
 var testRedirects = RedirectPaths{
 	Invalid:           "invalid",
 	AlreadySubscribed: "already-subscribed",
@@ -88,6 +93,66 @@ func TestNewHandler(t *testing.T) {
 	})
 }
 
+func captureLogs() (*strings.Builder, func()) {
+	origWriter := log.Writer()
+	builder := &strings.Builder{}
+	log.SetOutput(builder)
+
+	return builder, func() {
+		log.SetOutput(origWriter)
+	}
+}
+
+func apiGatewayRequest(method, path string) *events.APIGatewayV2HTTPRequest {
+	return &events.APIGatewayV2HTTPRequest{
+		RawPath: path,
+		RequestContext: events.APIGatewayV2HTTPRequestContext{
+			RequestID: "deadbeef",
+			HTTP: events.APIGatewayV2HTTPRequestContextHTTPDescription{
+				SourceIP: "192.168.0.1",
+				Method:   method,
+				Path:     path,
+				Protocol: "HTTP/2",
+			},
+		},
+	}
+}
+
+func apiGatewayResponse(status int) *events.APIGatewayV2HTTPResponse {
+	return &events.APIGatewayV2HTTPResponse{StatusCode: status}
+}
+
+func TestLogApiResponse(t *testing.T) {
+	req := apiGatewayRequest(
+		http.MethodGet, "/verify/mbland%40acm.org/0123-456-789",
+	)
+
+	t.Run("WithoutError", func(t *testing.T) {
+		logs, teardown := captureLogs()
+		defer teardown()
+		res := apiGatewayResponse(http.StatusOK)
+
+		logApiResponse(req, res, nil)
+
+		expectedMsg := `192.168.0.1 ` +
+			`"GET /verify/mbland%40acm.org/0123-456-789 HTTP/2" 200`
+		assert.Assert(t, is.Contains(logs.String(), expectedMsg))
+	})
+
+	t.Run("WithError", func(t *testing.T) {
+		logs, teardown := captureLogs()
+		defer teardown()
+		res := apiGatewayResponse(http.StatusInternalServerError)
+
+		logApiResponse(req, res, errors.New("unexpected problem"))
+
+		expectedMsg := `192.168.0.1 ` +
+			`"GET /verify/mbland%40acm.org/0123-456-789 HTTP/2" ` +
+			`500: unexpected problem`
+		assert.Assert(t, is.Contains(logs.String(), expectedMsg))
+	})
+}
+
 func TestNewApiRequest(t *testing.T) {
 	const requestId = "deadbeef"
 	const rawPath = UnsubscribePrefix + "/mbland%40acm.org/0123-456-789"
@@ -235,6 +300,60 @@ func TestSubscribeRequest(t *testing.T) {
 	})
 }
 
+func TestHandleApiEvent(t *testing.T) {
+	req := apiGatewayRequest(http.MethodPost, "/subscribe")
+	logs, teardown := captureLogs()
+	defer teardown()
+
+	req.Body = "email=mbland%40acm.org"
+	req.Headers = map[string]string{
+		"content-type": "application/x-www-form-urlencoded",
+	}
+
+	t.Run("SetsInternalServerErrorByDefault", func(t *testing.T) {
+		f := newFixture()
+		badReq := apiGatewayRequest(http.MethodPost, "/subscribe")
+		defer logs.Reset()
+
+		badReq.Body = "Definitely not base64 encoded"
+		badReq.IsBase64Encoded = true
+
+		res := f.h.handleApiEvent(badReq)
+
+		assert.Assert(t, res != nil)
+		assert.Equal(t, http.StatusInternalServerError, res.StatusCode)
+		assert.Assert(
+			t, is.Contains(logs.String(), "500: failed to base64 decode body"),
+		)
+	})
+
+	t.Run("SetsStatusFromErrorIfPresent", func(t *testing.T) {
+		f := newFixture()
+		f.ta.Error = &ops.OperationErrorExternal{Message: "db operation failed"}
+		defer logs.Reset()
+
+		res := f.h.handleApiEvent(req)
+
+		assert.Assert(t, res != nil)
+		assert.Equal(t, http.StatusBadGateway, res.StatusCode)
+		assert.Assert(
+			t, is.Contains(logs.String(), "502: db operation failed"),
+		)
+	})
+
+	t.Run("Succeeds", func(t *testing.T) {
+		f := newFixture()
+		f.ta.ReturnValue = ops.VerifyLinkSent
+		defer logs.Reset()
+
+		res := f.h.handleApiEvent(req)
+
+		assert.Assert(t, res != nil)
+		assert.Equal(t, http.StatusSeeOther, res.StatusCode)
+		assert.Assert(t, strings.HasSuffix(logs.String(), " 303\n"))
+	})
+}
+
 func TestMailtoEventDoesNothingUntilImplemented(t *testing.T) {
 	f := newFixture()
 

ops/result.go

@@ -28,3 +28,19 @@ func (r OperationResult) String() string {
 	}
 	return "Unknown"
 }
+
+type OperationErrorInternal struct {
+	Message string
+}
+
+func (err *OperationErrorInternal) Error() string {
+	return err.Message
+}
+
+type OperationErrorExternal struct {
+	Message string
+}
+
+func (err *OperationErrorExternal) Error() string {
+	return err.Message
+}