Repository: google/exposure-notifications-server
Pull request #1353 (2021-02-05 22:01:20)

Move publish to middleware/server pattern
**Release Note**

<!-- Enter your extended release note in the below block. If the PR requires
additional action from users switching to the new release, include the string
"action required". If no release note is required, write "NONE". -->

```release-note
Move publish to middleware/server pattern
```

/assign @mikehelmick  

google-oss-robot: @sethvargo: GitHub didn't allow me to assign the following users: thealamu.

Note that only [google members](https://github.com/orgs/google/people), repo collaborators and people who have commented on this issue/PR can be assigned. Additionally, issues/PRs can only have 10 assignees at the same time.
For more information please see [the contributor guide](https://git.k8s.io/community/contributors/guide/first-contribution.md#issue-assignment-in-github)

<details>

In response to [this](https://github.com/google/exposure-notifications-server/pull/1353):

>**Release Note**
>
><!-- Enter your extended release note in the below block. If the PR requires
>additional action from users switching to the new release, include the string
>"action required". If no release note is required, write "NONE". -->
>
>```release-note
>Move publish to middleware/server pattern
>```
>
>/assign @thealamu 


Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository.
</details>
google-oss-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/google/exposure-notifications-server/pull/1353#" title="Author self-approved">sethvargo</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=google%2Fexposure-notifications-server).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/google/exposure-notifications-server/blob/main/OWNERS)~~ [sethvargo]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
sethvargo: /assign @mikehelmick 
google-oss-robot: @sethvargo: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-en-server-release-unit | 644a07d3a9b4bd20d5cfef0fdb05254fb6f87ec2 | [link](https://oss-prow.knative.dev/view/gs/oss-prow/pr-logs/pull/google_exposure-notifications-server/1353/pull-en-server-release-unit/1357811578459656192) | `/test pull-en-server-release-unit`

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository. I understand the commands that are listed [here](https://go.k8s.io/bot-commands).
</details>
<!-- test report -->
google-oss-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/google/exposure-notifications-server/pull/1353#pullrequestreview-584752083" title="Approved">mikehelmick</a>*, *<a href="https://github.com/google/exposure-notifications-server/pull/1353#" title="Author self-approved">sethvargo</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=google%2Fexposure-notifications-server).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/google/exposure-notifications-server/blob/main/OWNERS)~~ [mikehelmick,sethvargo]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->

Patch:
diff --git a/cmd/exposure/main.go b/cmd/exposure/main.go
index 24fc9ea..5348c45 100644
--- a/cmd/exposure/main.go
+++ b/cmd/exposure/main.go
@@ -18,8 +18,6 @@ package main
 import (
 	"context"
 	"fmt"
-	"net/http"
-	"os"
 
 	"github.com/google/exposure-notifications-server/internal/buildinfo"
 	"github.com/google/exposure-notifications-server/internal/publish"
@@ -27,7 +25,6 @@ import (
 	"github.com/google/exposure-notifications-server/pkg/logging"
 	_ "github.com/google/exposure-notifications-server/pkg/observability"
 	"github.com/google/exposure-notifications-server/pkg/server"
-	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
 	"github.com/sethvargo/go-signalcontext"
 )
@@ -59,8 +56,8 @@ func main() {
 func realMain(ctx context.Context) error {
 	logger := logging.FromContext(ctx)
 
-	var config publish.Config
-	env, err := setup.Setup(ctx, &config)
+	var cfg publish.Config
+	env, err := setup.Setup(ctx, &cfg)
 	if err != nil {
 		return fmt.Errorf("setup.Setup: %w", err)
 	}
@@ -69,30 +66,15 @@ func realMain(ctx context.Context) error {
 	r := mux.NewRouter()
 	r.Handle("/health", server.HandleHealthz())
 
-	publishServer, err := publish.NewServer(ctx, &config, env)
+	publishServer, err := publish.NewServer(ctx, &cfg, env)
 	if err != nil {
-		return fmt.Errorf("publish.NewHandler: %w", err)
+		return fmt.Errorf("publish.NewServer: %w", err)
 	}
 
-	// Handle v1 API - this route has to come before the v1alpha route because of
-	// path matching.
-	r.Handle("/v1/publish", publishServer.Handle())
-	r.Handle("/v1/publish/", http.NotFoundHandler())
-
-	// Handle stats retrieval API
-	r.Handle("/v1/stats", publishServer.HandleStats())
-	r.Handle("/v1/stats/", http.NotFoundHandler())
-
-	// Serving of v1alpha1 is on by default, but can be disabled through env var.
-	if config.EnableV1Alpha1API {
-		r.Handle("/", publishServer.HandleV1Alpha1())
-	}
-
-	srv, err := server.New(config.Port)
+	srv, err := server.New(cfg.Port)
 	if err != nil {
 		return fmt.Errorf("server.New: %w", err)
 	}
-	logger.Infof("listening on :%s", config.Port)
-
-	return srv.ServeHTTPHandler(ctx, handlers.CombinedLoggingHandler(os.Stdout, r))
+	logger.Infow("server listening", "port", cfg.Port)
+	return srv.ServeHTTPHandler(ctx, publishServer.Routes(ctx, &cfg))
 }
diff --git a/go.mod b/go.mod
index e3d2e52..a4ed5d9 100644
--- a/go.mod
+++ b/go.mod
@@ -31,7 +31,6 @@ require (
 	github.com/google/go-cmp v0.5.4
 	github.com/google/mako v0.2.0
 	github.com/google/uuid v1.1.2
-	github.com/gorilla/handlers v1.5.1
 	github.com/gorilla/mux v1.8.0
 	github.com/gostaticanalysis/analysisutil v0.6.1 // indirect
 	github.com/grpc-ecosystem/grpc-gateway v1.16.0 // indirect
diff --git a/go.sum b/go.sum
index cc0ecca..826751b 100644
--- a/go.sum
+++ b/go.sum
@@ -380,8 +380,6 @@ github.com/fatih/color v1.9.0 h1:8xPHl4/q1VyqGIPif1F+1V3Y3lSmrq01EabUW3CoW5s=
 github.com/fatih/color v1.9.0/go.mod h1:eQcE1qtQxscV5RaZvpXrrb8Drkc3/DdQ+uUYCNjL+zU=
 github.com/fatih/structs v1.1.0 h1:Q7juDM0QtcnhCpeyLGQKyg4TOIghuNXrkL32pHAUMxo=
 github.com/fatih/structs v1.1.0/go.mod h1:9NiDSp5zOcgEDl+j00MP/WkGVPOlPRLejGD8Ga6PJ7M=
-github.com/felixge/httpsnoop v1.0.1 h1:lvB5Jl89CsZtGIWuTcDM1E/vkVs49/Ml7JJe07l8SPQ=
-github.com/felixge/httpsnoop v1.0.1/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U=
 github.com/form3tech-oss/jwt-go v3.2.2+incompatible h1:TcekIExNqud5crz4xD2pavyTgWiPvpYe4Xau31I0PRk=
 github.com/form3tech-oss/jwt-go v3.2.2+incompatible/go.mod h1:pbq4aXjuKjdthFRnoDwaVPLA+WlJuPGy+QneDUgJi2k=
 github.com/franela/goblin v0.0.0-20200105215937-c9ffbefa60db/go.mod h1:7dvUGVsVBjqR7JHJk0brhHOZYGmfBYOrK0ZhYMEtBr4=
@@ -604,8 +602,6 @@ github.com/gorhill/cronexpr v0.0.0-20180427100037-88b0669f7d75 h1:f0n1xnMSmBLzVf
 github.com/gorhill/cronexpr v0.0.0-20180427100037-88b0669f7d75/go.mod h1:g2644b03hfBX9Ov0ZBDgXXens4rxSxmqFBbhvKv2yVA=
 github.com/gorilla/context v1.1.1/go.mod h1:kBGZzfjB9CEq2AlWe17Uuf7NDRt0dE0s8S51q0aT7Yg=
 github.com/gorilla/handlers v1.4.2/go.mod h1:Qkdc/uu4tH4g6mTK6auzZ766c4CA0Ng8+o/OAirnOIQ=
-github.com/gorilla/handlers v1.5.1 h1:9lRY6j8DEeeBT10CvO9hGW0gmky0BprnvDI5vfhUHH4=
-github.com/gorilla/handlers v1.5.1/go.mod h1:t8XrUpc4KVXb7HGyJ4/cEnwQiaxrX/hz1Zv/4g96P1Q=
 github.com/gorilla/mux v1.6.2/go.mod h1:1lud6UwP+6orDFRuTfBEV8e9/aOM/c4fVVCaMa2zaAs=
 github.com/gorilla/mux v1.7.3/go.mod h1:1lud6UwP+6orDFRuTfBEV8e9/aOM/c4fVVCaMa2zaAs=
 github.com/gorilla/mux v1.7.4 h1:VuZ8uybHlWmqV03+zRzdwKL4tUnIp1MAQtp1mIFE1bc=
diff --git a/internal/integration/client.go b/internal/integration/client.go
index 6c46c46..46e977f 100644
--- a/internal/integration/client.go
+++ b/internal/integration/client.go
@@ -37,7 +37,7 @@ func (c *Client) PublishKeys(payload *verifyapi.Publish) (*verifyapi.PublishResp
 		return nil, fmt.Errorf("failed to marshal json: %w", err)
 	}
 
-	resp, err := c.client.Post("/publish", "application/json", bytes.NewReader(j))
+	resp, err := c.client.Post("/publish/v1/publish", "application/json", bytes.NewReader(j))
 	if err != nil {
 		return nil, fmt.Errorf("failed to POST /publish: %w", err)
 	}
diff --git a/internal/integration/helpers.go b/internal/integration/helpers.go
index fe63b35..7318a9b 100644
--- a/internal/integration/helpers.go
+++ b/internal/integration/helpers.go
@@ -192,8 +192,7 @@ func NewTestServer(tb testing.TB) (*serverenv.ServerEnv, *Client) {
 	if err != nil {
 		tb.Fatal(err)
 	}
-	federationInHandler := http.StripPrefix("/federation-in", federationInServer.Routes(ctx))
-	r.PathPrefix("/federation-in/").Handler(federationInHandler)
+	r.PathPrefix("/federation-in/").Handler(http.StripPrefix("/federation-in", federationInServer.Routes(ctx)))
 
 	// Federation out
 	// TODO: this is a grpc listener and requires a lot of setup.
@@ -235,7 +234,7 @@ func NewTestServer(tb testing.TB) (*serverenv.ServerEnv, *Client) {
 	if err != nil {
 		tb.Fatal(err)
 	}
-	r.Handle("/publish", publishServer.Handle())
+	r.PathPrefix("/publish/").Handler(http.StripPrefix("/publish", publishServer.Routes(ctx, &publishConfig)))
 
 	srv, err := server.New("")
 	if err != nil {
diff --git a/internal/publish/database/exposure.go b/internal/publish/database/exposure.go
index 5d296d9..9ead061 100644
--- a/internal/publish/database/exposure.go
+++ b/internal/publish/database/exposure.go
@@ -117,7 +117,8 @@ func (db *PublishDB) IterateExposures(ctx context.Context, criteria IterateExpos
 		return "", fmt.Errorf("generating where: %v", err)
 	}
 
-	logging.FromContext(ctx).Debugw("iterator query", "query", query, "args", args)
+	logger := logging.FromContext(ctx).Named("IterateExposures")
+	logger.Debugw("iterator query", "query", query, "args", args)
 
 	// TODO: this is a pretty weak cursor solution, but not too bad since we'll
 	// typically have queries ahead of the cleanup and before the current
diff --git a/internal/publish/model/exposure_model.go b/internal/publish/model/exposure_model.go
index 4863240..ade1255 100644
--- a/internal/publish/model/exposure_model.go
+++ b/internal/publish/model/exposure_model.go
@@ -489,7 +489,6 @@ func TransformExposureKey(exposureKey verifyapi.ExposureKey, appPackageName stri
 // Only keys that need to be revised or are being created for the first time
 // are returned in the output set.
 func ReviseKeys(ctx context.Context, existing map[string]*Exposure, incoming []*Exposure) ([]*Exposure, error) {
-	//logger := logging.FromContext(ctx)
 	output := make([]*Exposure, 0, len(incoming))
 
 	// Iterate over incoming keys.
@@ -561,9 +560,10 @@ type TransformPublishResult struct {
 // errors that occur.
 //
 func (t *Transformer) TransformPublish(ctx context.Context, inData *verifyapi.Publish, regions []string, claims *verification.VerifiedClaims, batchTime time.Time) (*TransformPublishResult, error) {
-	logger := logging.FromContext(ctx)
+	logger := logging.FromContext(ctx).Named("TransformPublish")
+
 	if t.debugReleaseSameDay {
-		logger.Warnw("DEBUG SERVER - current day keys are not being embargoed!")
+		logger.Warnw("DEBUG SERVER - CURRENT DAYS KEYS ARE NOT EMBARGOED!")
 	}
 
 	// Validate the number of keys that want to be published.
diff --git a/internal/publish/publish.go b/internal/publish/publish.go
index e1131b7..36e8796 100644
--- a/internal/publish/publish.go
+++ b/internal/publish/publish.go
@@ -29,6 +29,7 @@ import (
 	"go.opencensus.io/trace"
 
 	"github.com/google/exposure-notifications-server/internal/authorizedapp"
+	"github.com/google/exposure-notifications-server/internal/middleware"
 	"github.com/google/exposure-notifications-server/internal/pb"
 	"github.com/google/exposure-notifications-server/internal/publish/database"
 	"github.com/google/exposure-notifications-server/internal/publish/model"
@@ -40,6 +41,8 @@ import (
 	verifyapi "github.com/google/exposure-notifications-server/pkg/api/v1"
 	"github.com/google/exposure-notifications-server/pkg/base64util"
 	"github.com/google/exposure-notifications-server/pkg/logging"
+	"github.com/google/exposure-notifications-server/pkg/server"
+	"github.com/gorilla/mux"
 	"github.com/mikehelmick/go-chaff"
 )
 
@@ -127,6 +130,33 @@ func NewServer(ctx context.Context, cfg *Config, env *serverenv.ServerEnv) (*Ser
 	}, nil
 }
 
+func (s *Server) Routes(ctx context.Context, cfg *Config) *mux.Router {
+	logger := logging.FromContext(ctx).Named("publish")
+
+	r := mux.NewRouter()
+	r.Use(middleware.PopulateRequestID())
+	r.Use(middleware.PopulateObservability())
+	r.Use(middleware.PopulateLogger(logger))
+
+	r.Handle("/health", server.HandleHealthz())
+
+	// Handle v1 API - this route has to come before the v1alpha route because of
+	// path matching.
+	r.Handle("/v1/publish", s.handlePublishV1())
+	r.Handle("/v1/publish/", http.NotFoundHandler())
+
+	// Handle stats retrieval API
+	r.Handle("/v1/stats", s.handleStats())
+	r.Handle("/v1/stats/", http.NotFoundHandler())
+
+	// Serving of v1alpha1 is on by default, but can be disabled through env var.
+	if cfg.EnableV1Alpha1API {
+		r.Handle("/", s.handlePublishV1Alpha1())
+	}
+
+	return r
+}
+
 type response struct {
 	status      int
 	pubResponse *verifyapi.PublishResponse
@@ -182,7 +212,8 @@ func (s *Server) process(ctx context.Context, data *verifyapi.Publish, platform
 	ctx, span := trace.StartSpan(ctx, "(*publish.PublishHandler).process")
 	defer span.End()
 
-	logger := logging.FromContext(ctx).With("health_authority_id", data.HealthAuthorityID)
+	logger := logging.FromContext(ctx).Named("process").
+		With("health_authority_id", data.HealthAuthorityID)
 
 	logger.Info("publish API request")
 
diff --git a/internal/publish/publish_v1.go b/internal/publish/publish_v1.go
index f60e263..cc4cbca 100644
--- a/internal/publish/publish_v1.go
+++ b/internal/publish/publish_v1.go
@@ -60,19 +60,21 @@ func (s *Server) handleRequest(w http.ResponseWriter, r *http.Request) *response
 	return s.process(ctx, &data, clientPlatform, newVersionBridge([]string{}))
 }
 
-// Handle returns an http.Handler that can process V1 publish requests.
-func (s *Server) Handle() http.Handler {
+// handlePublishV1 returns an http.Handler that can process V1 publish requests.
+func (s *Server) handlePublishV1() http.Handler {
 	mResponder := maintenance.New(s.config)
 	return s.tracker.HandleTrack(chaff.HeaderDetector("X-Chaff"),
 		mResponder.Handle(
 			http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-				response := s.handleRequest(w, r)
-
 				ctx := r.Context()
 
+				logger := logging.FromContext(ctx).Named("handlePublishV1")
+
+				response := s.handleRequest(w, r)
+
 				if padding, err := generatePadding(s.config.ResponsePaddingMinBytes, s.config.ResponsePaddingRange); err != nil {
 					stats.Record(ctx, mPaddingFailed.M(1))
-					logging.FromContext(ctx).Errorw("failed to pad response", "error", err)
+					logger.Errorw("failed to pad response", "error", err)
 				} else {
 					response.pubResponse.Padding = padding
 				}
diff --git a/internal/publish/publish_v1alpha1.go b/internal/publish/publish_v1alpha1.go
index fc45197..37afd1e 100644
--- a/internal/publish/publish_v1alpha1.go
+++ b/internal/publish/publish_v1alpha1.go
@@ -78,18 +78,20 @@ func (s *Server) handleV1Apha1Request(w http.ResponseWriter, r *http.Request) *r
 	return s.process(ctx, &publish, clientPlatform, bridge)
 }
 
-func (s *Server) HandleV1Alpha1() http.Handler {
+func (s *Server) handlePublishV1Alpha1() http.Handler {
 	mResponder := maintenance.New(s.config)
 	return s.tracker.HandleTrack(chaff.HeaderDetector("X-Chaff"),
 		mResponder.Handle(
 			http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-				response := s.handleV1Apha1Request(w, r)
-
 				ctx := r.Context()
 
+				logger := logging.FromContext(ctx).Named("handlePublishV1Alpha1")
+
+				response := s.handleV1Apha1Request(w, r)
+
 				if padding, err := generatePadding(s.config.ResponsePaddingMinBytes, s.config.ResponsePaddingRange); err != nil {
 					stats.Record(ctx, mPaddingFailed.M(1))
-					logging.FromContext(ctx).Errorw("failed to padd response", "error", err)
+					logger.Errorw("failed to pad response", "error", err)
 				} else {
 					response.pubResponse.Padding = padding
 				}
diff --git a/internal/publish/stats.go b/internal/publish/stats.go
index 0e15f89..b588281 100644
--- a/internal/publish/stats.go
+++ b/internal/publish/stats.go
@@ -31,7 +31,7 @@ import (
 	"github.com/mikehelmick/go-chaff"
 )
 
-func (s *Server) HandleStats() http.Handler {
+func (s *Server) handleStats() http.Handler {
 	mResponder := maintenance.New(s.config)
 	return s.tracker.HandleTrack(chaff.HeaderDetector("X-Chaff"), mResponder.Handle(
 		http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
@@ -64,15 +64,18 @@ func (s *Server) HandleStats() http.Handler {
 }
 
 func (s *Server) addMetricsPadding(ctx context.Context, response *verifyapi.StatsResponse) {
+	logger := logging.FromContext(ctx).Named("addMetricsPadding")
+
 	if padding, err := generatePadding(s.config.StatsResponsePaddingMinBytes, s.config.StatsResponsePaddingRange); err != nil {
-		logging.FromContext(ctx).Errorw("failed to pad response", "error", err)
+		logger.Errorw("failed to pad response", "error", err)
 	} else {
 		response.Padding = padding
 	}
 }
 
 func (s *Server) handleMetricsRequest(ctx context.Context, bearerToken string, request *verifyapi.StatsRequest) (*verifyapi.StatsResponse, int) {
-	logger := logging.FromContext(ctx)
+	logger := logging.FromContext(ctx).Named("handleMetricsRequest")
+
 	response := &verifyapi.StatsResponse{}
 
 	if !strings.HasPrefix(bearerToken, "Bearer ") {


Test patch:
diff --git a/internal/publish/publish_test.go b/internal/publish/publish_test.go
index e5b6bb6..e3695ec 100644
--- a/internal/publish/publish_test.go
+++ b/internal/publish/publish_test.go
@@ -514,9 +514,9 @@ func TestPublishWithBypass(t *testing.T) {
 				if err != nil {
 					t.Fatalf("unable to create publish handler: %v", err)
 				}
-				handler := publishServer.Handle()
+				handler := publishServer.handlePublishV1()
 				if ver == useV1Alpha1 {
-					handler = publishServer.HandleV1Alpha1()
+					handler = publishServer.handlePublishV1Alpha1()
 				}
 
 				// See if there is a health authority to set up.
@@ -878,7 +878,7 @@ func TestKeyRevision(t *testing.T) {
 	if err != nil {
 		t.Fatalf("unable to create publish handler: %v", err)
 	}
-	handler := publishServer.Handle()
+	handler := publishServer.handlePublishV1()
 	pubDB := pubdb.New(testDB)
 
 	// the first key in each publish will be at this time.
diff --git a/internal/publish/stats_test.go b/internal/publish/stats_test.go
index 7c8cf13..18899ab 100644
--- a/internal/publish/stats_test.go
+++ b/internal/publish/stats_test.go
@@ -124,7 +124,7 @@ func TestRetrieveMetrics(t *testing.T) {
 	if err != nil {
 		t.Fatalf("unable to create publish handler: %v", err)
 	}
-	metricsHandler := publishServer.HandleStats()
+	metricsHandler := publishServer.handleStats()
 
 	// get the authentication token.
 	jwtConfig := &testutil.StatsJWTConfig{
@@ -243,7 +243,7 @@ func TestRetrieveMetrics_AuthErrors(t *testing.T) {
 	if err != nil {
 		t.Fatalf("unable to create publish handler: %v", err)
 	}
-	metricsHandler := publishServer.HandleStats()
+	metricsHandler := publishServer.handleStats()
 
 	// get the authentication token.
 	jwtConfig := &testutil.StatsJWTConfig{