From 0a8ccb6714e729cb803c1801de3bd86c163305e8 Mon Sep 17 00:00:00 2001 From: pvbouwel <463976+pvbouwel@users.noreply.github.com> Date: Sat, 8 Feb 2025 21:55:17 +0100 Subject: [PATCH] tests: metrics and request log (#24) * refactor: use handlerfunc for Serverable feature: allow exposing metrics. * refactor: make nonDeterministicLimitedRandReadSeeker re-usable across packages * test: add test coverage for metrics gathering bugfix: fix metrics such that they can pass test * refactor: make log fixture re-usable across packages * feature: allow enabling metrics endpoint for CLI app * refactor: undo change of refactor move where we changed logBufferToLines to be public as there is no need to have it as a public method * tests: add coverage for request log * lint: add errro checking to satisfy linter --------- Co-authored-by: Peter Van Bouwel --- aws/service/s3/loghelpers_test.go | 53 ------ aws/service/s3/policy-iam-action_test.go | 4 +- aws/service/s3/proxys3_test.go | 4 +- aws/service/s3/s3-errors.go | 7 - aws/service/s3/s3-errors_test.go | 2 +- aws/service/s3/server.go | 45 ++--- aws/service/sts/api/apiactions.go | 9 + aws/service/sts/api/stsoperation_string.go | 24 +++ aws/service/sts/server.go | 46 ++--- aws/service/sts/server_test.go | 2 +- cmd/almost-e2e_test.go | 92 +++++++++- cmd/benchmark_test.go | 41 +---- cmd/config.go | 9 + cmd/proxys3.go | 56 +++--- cmd/proxysts.go | 8 +- cmd/test-utils.go | 2 - go.mod | 11 +- go.sum | 23 ++- middleware/observability.go | 74 +++++++- server/basicserver.go | 64 +++++++ server/dummy.go | 32 ---- server/interface.go | 9 +- server/server.go | 86 ++++++++-- server/server_test.go | 190 +++++++++++++++++++++ testutils/loghelpers.go | 137 +++++++++++++++ testutils/random.go | 43 +++++ 26 files changed, 806 insertions(+), 267 deletions(-) delete mode 100644 aws/service/s3/loghelpers_test.go create mode 100644 aws/service/sts/api/apiactions.go create mode 100644 aws/service/sts/api/stsoperation_string.go create mode 100644 server/basicserver.go delete mode 100644 server/dummy.go create mode 100644 server/server_test.go create mode 100644 testutils/loghelpers.go create mode 100644 testutils/random.go diff --git a/aws/service/s3/loghelpers_test.go b/aws/service/s3/loghelpers_test.go deleted file mode 100644 index faa4c94..0000000 --- a/aws/service/s3/loghelpers_test.go +++ /dev/null @@ -1,53 +0,0 @@ -package s3 - -import ( - "bytes" - "io" - "log/slog" - "testing" - - "github.com/VITObelgium/fakes3pp/logging" -) - -//For testing only get lines out of a buffer -func logBufferToLines(tb testing.TB, buf *bytes.Buffer) []string { - var lines = []string{} - lineDelimiter := byte('\n') - for i:=0 ; i < 10000; i++ { - line, err := buf.ReadString(lineDelimiter) - if err == nil { - lines = append(lines, line) - } else { - if err == io.EOF { - return lines - } - tb.Errorf("Encountered error while processing log buffer: %s", err) - tb.FailNow() - } - } - return lines -} - -//A fixture to start capturing logs. It returns the following: -// - a teardown callback to stop the log capture. -// - a getCapturedLogLines callback which gets the log lines captured since the last run -func captureLogFixture(tb testing.TB, lvl slog.Level, fe logging.ForceEnabler) (teardown func()(), getCapturedLogLines func()([]string)) { - loggerBeforeFixture := slog.Default() - buf := &bytes.Buffer{} - logging.InitializeLogging(lvl, fe, buf) - var fixtureActive = true - - teardown = func() { - if fixtureActive { - slog.SetDefault(loggerBeforeFixture) - fixtureActive = false - } - } - - getCapturedLogLines = func() (lines []string) { - lines = logBufferToLines(tb, buf) - return lines - } - - return teardown, getCapturedLogLines -} \ No newline at end of file diff --git a/aws/service/s3/policy-iam-action_test.go b/aws/service/s3/policy-iam-action_test.go index e1d5b4a..20bee28 100644 --- a/aws/service/s3/policy-iam-action_test.go +++ b/aws/service/s3/policy-iam-action_test.go @@ -99,10 +99,8 @@ func runListObjectsV2AndReturnError(t *testing.T, s server.Serverable) error { func runListObjectsV2AndReturnErrorAlternateEndpoint(t *testing.T, s server.Serverable) error { _, certFile, certKey := s.GetTls() sWithAlternateEndpoint := &S3Server{ + BasicServer: *server.NewBasicServer(s.GetPort(), "localhost2", certFile, certKey, nil), fqdns: []string{"localhost2"}, - port: s.GetPort(), - tlsCertFilePath: certFile, - tlsKeyFilePath: certKey, } return runListObjectsV2AndReturnErrorForEndpoint(t, sWithAlternateEndpoint) } diff --git a/aws/service/s3/proxys3_test.go b/aws/service/s3/proxys3_test.go index 9947c1c..5b4e02d 100644 --- a/aws/service/s3/proxys3_test.go +++ b/aws/service/s3/proxys3_test.go @@ -120,7 +120,7 @@ func setupSuiteProxyS3( t testing.TB, proxyHB interfaces.HandlerBuilderI, pm *iam.PolicyManager, bm interfaces.BackendManager, mws []middleware.Middleware, tlsEnabled bool, ) (func(t testing.TB), *S3Server) { s := NewTestS3Server(t, proxyHB, pm, bm, mws, tlsEnabled) - stsProxyDone, stsProxySrv, err := server.CreateAndStart(s) + stsProxyDone, stsProxySrv, err := server.CreateAndStart(s, server.ServerOpts{}) if err != nil { t.Errorf("Could not spawn fake STS server %s", err) } @@ -458,7 +458,7 @@ func TestAllowEnablingTracingAtClientSide(t *testing.T) { os.Setenv(logging.ENV_FORCE_LOGGING_FOR_REQUEST_ID_PREFIX, "00AABBCC") //Given a way to capture logs - stopLogCapture, getLogLines := captureLogFixture(t, slog.LevelError, nil) + stopLogCapture, getLogLines := testutils.CaptureLogFixture(t, slog.LevelError, nil) defer stopLogCapture() //Given a uuid4 that starts with the prefix diff --git a/aws/service/s3/s3-errors.go b/aws/service/s3/s3-errors.go index 8f99543..b2fc80d 100644 --- a/aws/service/s3/s3-errors.go +++ b/aws/service/s3/s3-errors.go @@ -24,7 +24,6 @@ package s3 import ( "context" "encoding/xml" - "errors" "log/slog" "net/http" @@ -85,12 +84,6 @@ func writeS3ErrorResponse(ctx context.Context, w http.ResponseWriter, errCode S3 service.WriteResponse(ctx, w, s3Err.HTTPStatusCode, encodedErrorResponse, service.MimeXML) } -func writeS3ErrorAccessDeniedResponse(ctx context.Context, w http.ResponseWriter) { - // nolint:staticcheck - writeS3ErrorResponse(ctx, w, ErrS3AccessDenied, errors.New("access Denied")) -} - - type S3ErrorResponse struct { XMLName xml.Name `xml:"Error" json:"-"` Code string `xml:"Code"` diff --git a/aws/service/s3/s3-errors_test.go b/aws/service/s3/s3-errors_test.go index 46d20ba..9397031 100644 --- a/aws/service/s3/s3-errors_test.go +++ b/aws/service/s3/s3-errors_test.go @@ -25,7 +25,7 @@ func TestS3Error(t *testing.T) { r.Header.Set(requestctx.XRequestID, testReqID) rr := httptest.NewRecorder() ctx := requestctx.NewContextFromHttpRequest(r) - writeS3ErrorAccessDeniedResponse(ctx, rr) + writeS3ErrorResponse(ctx, rr, ErrS3AccessDenied, nil) bodyBytes, err := io.ReadAll(rr.Body) if err != nil { t.Errorf("Could not read response body %s", err) diff --git a/aws/service/s3/server.go b/aws/service/s3/server.go index 1fca722..424febc 100644 --- a/aws/service/s3/server.go +++ b/aws/service/s3/server.go @@ -1,7 +1,7 @@ package s3 import ( - "log/slog" + "errors" "net/http" "strings" "time" @@ -11,24 +11,17 @@ import ( "github.com/VITObelgium/fakes3pp/middleware" "github.com/VITObelgium/fakes3pp/server" "github.com/VITObelgium/fakes3pp/utils" - "github.com/minio/mux" ) type S3Server struct{ + server.BasicServer + //The Key material that is used for signing JWT tokens. Needed for verification. jwtKeyMaterial utils.KeyPairKeeper fqdns []string - port int - - //The TLS certificate used to encrypt traffic with if omitted HTTP server will be spawned - tlsCertFilePath string - - //The TLS key used to encrypt traffic with if omitted HTTP server will be spawned - tlsKeyFilePath string - pm *iam.PolicyManager signedUrlGracePeriod time.Duration @@ -95,13 +88,15 @@ func newS3Server( if err != nil { return nil, err } + if len(fqdns) == 0 { + return nil, errors.New("must at least pass in 1 fqdn to create a server") + } + basicServer := server.NewBasicServer(serverPort, fqdns[0], tlsCertFilePath, tlsKeyFilePath, nil) s = &S3Server{ + BasicServer: *basicServer, jwtKeyMaterial: key, fqdns: fqdns, - port: serverPort, - tlsCertFilePath: tlsCertFilePath, - tlsKeyFilePath: tlsKeyFilePath, pm: pm, signedUrlGracePeriod: time.Duration(signedUrlGraceTimeSeconds) * time.Second, proxyHB: proxyHB, @@ -117,6 +112,7 @@ func newS3Server( } } s.mws = mws + s.SetHandlerFunc(s.BuildHandlerfunc()) return s, nil } @@ -141,29 +137,10 @@ func (s *S3Server)IsVirtualHostingRequest(req *http.Request) bool { return true } - -func (s *S3Server) GetPort() (int) { - return s.port -} - -func (s *S3Server) GetTls() (enabled bool, certFile string, keyFile string) { - enabled = true - if certFile == "" { - slog.Debug("Disabling TLS", "reason", "no certFile provided") - enabled = false - } else if keyFile == "" { - slog.Debug("Disabling TLS", "reason", "no keyFile provided") - enabled = false - } - return enabled, s.tlsCertFilePath, s.tlsKeyFilePath -} - //Register routes to S3 router //For real cases the proxyHB HandlerBuilder should build a handler function //that sends the request upstream and passes back the response. -func (s *S3Server) RegisterRoutes(router *mux.Router) error { +func (s *S3Server) BuildHandlerfunc() http.HandlerFunc{ h := s.proxyHB.Build(s.s3BackendManager) - - router.NewRoute().HandlerFunc(middleware.Chain(h, s.mws...)) - return nil + return middleware.Chain(h, s.mws...) } \ No newline at end of file diff --git a/aws/service/sts/api/apiactions.go b/aws/service/sts/api/apiactions.go new file mode 100644 index 0000000..ada0855 --- /dev/null +++ b/aws/service/sts/api/apiactions.go @@ -0,0 +1,9 @@ +package api + +type STSOperation int + +//go:generate stringer -type=STSOperation $GOFILE +const ( + UnknownOperation STSOperation = iota + AssumeRoleWithWebIdentity +) \ No newline at end of file diff --git a/aws/service/sts/api/stsoperation_string.go b/aws/service/sts/api/stsoperation_string.go new file mode 100644 index 0000000..874e18b --- /dev/null +++ b/aws/service/sts/api/stsoperation_string.go @@ -0,0 +1,24 @@ +// Code generated by "stringer -type=STSOperation apiactions.go"; DO NOT EDIT. + +package api + +import "strconv" + +func _() { + // An "invalid array index" compiler error signifies that the constant values have changed. + // Re-run the stringer command to generate them again. + var x [1]struct{} + _ = x[UnknownOperation-0] + _ = x[AssumeRoleWithWebIdentity-1] +} + +const _STSOperation_name = "UnknownOperationAssumeRoleWithWebIdentity" + +var _STSOperation_index = [...]uint8{0, 16, 41} + +func (i STSOperation) String() string { + if i < 0 || i >= STSOperation(len(_STSOperation_index)-1) { + return "STSOperation(" + strconv.FormatInt(int64(i), 10) + ")" + } + return _STSOperation_name[_STSOperation_index[i]:_STSOperation_index[i+1]] +} diff --git a/aws/service/sts/server.go b/aws/service/sts/server.go index 1b9bf97..1094162 100644 --- a/aws/service/sts/server.go +++ b/aws/service/sts/server.go @@ -12,6 +12,7 @@ import ( "github.com/VITObelgium/fakes3pp/aws/credentials" "github.com/VITObelgium/fakes3pp/aws/service" "github.com/VITObelgium/fakes3pp/aws/service/iam" + "github.com/VITObelgium/fakes3pp/aws/service/sts/api" "github.com/VITObelgium/fakes3pp/aws/service/sts/oidc" "github.com/VITObelgium/fakes3pp/aws/service/sts/session" "github.com/VITObelgium/fakes3pp/requestctx" @@ -23,19 +24,13 @@ import ( type STSServer struct{ + server.BasicServer + //The Key material that is used for signing JWT tokens. jwtKeyMaterial utils.KeyPairKeeper fqdns []string - port int - - //The TLS certificate used to encrypt traffic with if omitted HTTP server will be spawned - tlsCertFilePath string - - //The TLS key used to encrypt traffic with if omitted HTTP server will be spawned - tlsKeyFilePath string - //The verifier for OIDC IDP tokens oidcVerifier oidc.OIDCVerifier @@ -92,42 +87,32 @@ func newSTSServer( if err != nil { return nil, err } + if len(fqdns) == 0 { + return nil, errors.New("must pass at least 1 FQDN") + } s = &STSServer{ + BasicServer: *server.NewBasicServer(serverPort, fqdns[0], tlsCertFilePath, tlsKeyFilePath, nil), jwtKeyMaterial: key, fqdns: fqdns, - port: serverPort, - tlsCertFilePath: tlsCertFilePath, - tlsKeyFilePath: tlsKeyFilePath, oidcVerifier: oidcVerifier, pm: pm, maxAllowedDuration: time.Duration(maxDurationSeconds) * time.Second, } + s.SetHandlerFunc(s.CreateHandler()) return s, nil } -func (s *STSServer) GetPort() (int) { - return s.port -} - -func (s *STSServer) GetTls() (bool, string, string) { - enabled := true - if s.tlsCertFilePath == "" { - slog.Debug("Disabling TLS", "reason", "no certFile provided") - enabled = false - } else if s.tlsKeyFilePath == "" { - slog.Debug("Disabling TLS", "reason", "no keyFile provided") - enabled = false - } - return enabled, s.tlsCertFilePath, s.tlsKeyFilePath -} - -func (s *STSServer) RegisterRoutes(router *mux.Router) error { +func (s *STSServer) CreateHandler() http.HandlerFunc { + router := mux.NewRouter() stsRouter := router.NewRoute().PathPrefix(server.SlashSeparator).Subrouter() stsRouter.Methods(http.MethodPost).HandlerFunc(s.processSTSPost) stsRouter.PathPrefix("/").HandlerFunc(justLog) - return nil + + return func(w http.ResponseWriter, r *http.Request) { + stsRouter.ServeHTTP(w, r) + } } func justLog(w http.ResponseWriter, r *http.Request) { @@ -186,9 +171,10 @@ type stsClaims map[string]interface{} // - RoleSessionName // - WebIdentityToken following the structure func (s *STSServer)assumeRoleWithWebIdentity(ctx context.Context, w http.ResponseWriter, r *http.Request) { - + requestctx.SetOperation(r, api.AssumeRoleWithWebIdentity) claims := stsClaims{} defer slog.InfoContext(ctx, "Auditlog", "claims", claims) + requestctx.AddAccessLogInfo(r, "sts", slog.Any("claims", claims)) token := r.Form.Get(stsWebIdentityToken) diff --git a/aws/service/sts/server_test.go b/aws/service/sts/server_test.go index 88ae2b7..1b12827 100644 --- a/aws/service/sts/server_test.go +++ b/aws/service/sts/server_test.go @@ -211,7 +211,7 @@ func TestProxyStsAssumeRoleWithWebIdentitySessionTagsToken(t *testing.T) { // This works like a fixture see https://medium.com/nerd-for-tech/setup-and-teardown-unit-test-in-go-bd6fa1b785cd func setupSuiteProxySTS(t testing.TB, pm *iam.PolicyManager, oidcConfig string, tlsEnabled bool) (func(t testing.TB), *STSServer) { s := NewTestSTSServer(t, pm, 3600, oidcConfig, tlsEnabled) - stsProxyDone, stsProxySrv, err := server.CreateAndStart(s) + stsProxyDone, stsProxySrv, err := server.CreateAndStart(s, server.ServerOpts{}) if err != nil { t.Errorf("Could not spawn fake STS server %s", err) } diff --git a/cmd/almost-e2e_test.go b/cmd/almost-e2e_test.go index b6fb4ba..971a22c 100644 --- a/cmd/almost-e2e_test.go +++ b/cmd/almost-e2e_test.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" "testing" "time" @@ -85,10 +86,10 @@ func TestMain(m *testing.M) { } func setupSuiteProxyS3( - t testing.TB, + t testing.TB, opts server.ServerOpts, ) (func(t testing.TB), *s3proxy.S3Server) { s := buildS3Server() - s3ProxyDone, s3ProxySrv, err := server.CreateAndStart(s) + s3ProxyDone, s3ProxySrv, err := server.CreateAndStart(s, opts) if err != nil { t.Errorf("Could not spawn fake STS server %s", err) } @@ -109,10 +110,10 @@ func setupSuiteProxyS3( } func setupSuiteProxySTS( - t testing.TB, + t testing.TB, opts server.ServerOpts, ) (func(t testing.TB), *stsproxy.STSServer) { s := buildSTSServer() - stsProxyDone, stsProxySrv, err := server.CreateAndStart(s) + stsProxyDone, stsProxySrv, err := server.CreateAndStart(s, opts) if err != nil { t.Errorf("Could not spawn fake STS server %s", err) } @@ -189,9 +190,30 @@ func defaultPolicyFixture(t testing.TB) (teardown func ()()) { ) } + + //This is the testing fixture. It starts an sts and s3 proxy which //are configured with the S3 backends detailed in testing/README.md. -func testingFixture(t testing.TB) (tearDown func ()(), getToken func(subject string, d time.Duration, tags session.AWSSessionTags) string, stsServer server.Serverable, s3Server server.Serverable){ +func testingFixture(t testing.TB) ( + tearDown func ()(), + getToken func(subject string, d time.Duration, tags session.AWSSessionTags) string, + stsServer server.Serverable, + s3Server server.Serverable, + ){ + return testingFixtureCustomServerOpts( + t, + server.ServerOpts{}, + server.ServerOpts{}, + ) +} + + +func testingFixtureCustomServerOpts(t testing.TB, stsServerOpts server.ServerOpts, s3ServerOpts server.ServerOpts) ( + tearDown func ()(), + getToken func(subject string, d time.Duration, tags session.AWSSessionTags) string, + stsServer server.Serverable, + s3Server server.Serverable, + ){ skipIfNoTestingBackends(t) //Configure backends to be the testing S3 backends stageTestingBackendsConfig(t) @@ -199,10 +221,9 @@ func testingFixture(t testing.TB) (tearDown func ()(), getToken func(subject str teardownPolicies := defaultPolicyFixture(t) defer teardownPolicies() - //Given valid server config - teardownSuiteSTS, stsServer := setupSuiteProxySTS(t) - teardownSuiteS3, s3Server := setupSuiteProxyS3(t) + teardownSuiteSTS, stsServer := setupSuiteProxySTS(t, stsServerOpts) + teardownSuiteS3, s3Server := setupSuiteProxyS3(t, s3ServerOpts) keyStorage := getTestingKeyStorage(t) @@ -577,4 +598,57 @@ func TestListingOfS3BucketHasExpectedObjects(t *testing.T) { //THEN it should report the known objects "region.txt" and "team.txt" assertObjectInBucketListing(t, listObjects, "region.txt") assertObjectInBucketListing(t, listObjects, "team.txt") -} \ No newline at end of file +} + +func TestAuditLogEntry(t *testing.T) { + tearDownProxy, getSignedToken, stsServer, s3Server := testingFixture(t) + defer tearDownProxy() + teardownLog, getCapturedStructuredLogEntries := testutils.CaptureStructuredLogsFixture(t, slog.LevelInfo, nil) + defer teardownLog() + + //GIVEN we run another test scenario + //_GIVEN token for team that does have access + token := getSignedToken("mySubject", time.Minute * 20, session.AWSSessionTags{PrincipalTags: map[string][]string{testTeamTag: {testAllowedTeam}}}) + creds := getCredentialsFromTestStsProxy(t, token, "my-session", testPolicyAllowTeamFolderARN, stsServer) + + //_WHEN access is attempted that required the team information + content, err := getTestBucketObjectContent(t, testRegion1, testTeamFile, credentials.FromAwsFormat(creds), s3Server) + + //_THEN the file content should be returned + if err != nil { + t.Errorf("Could not get team file even though part of correct team. got %s", err) + } + expectedContent := "teamSecret123" + if content != expectedContent { + t.Errorf("Got %s, expected %s", content, expectedContent) + } + + //WHEN we get the logs + logEntries := getCapturedStructuredLogEntries() + //THEN we have 1 access log entry per service (sts & s3) + accesslogEntries := logEntries.GetEntriesWithMsg(t, "Request end") + if len(accesslogEntries) != 2 { + t.Errorf("Invalid number of access log entries. Expected 2 got: %d", len(accesslogEntries)) + } + + //WHEN we check the s3 auditlog entry + s3Entry := accesslogEntries.GetEntriesContainingField(t, "s3")[0] + //Then the operation should be GetObject + operation := s3Entry.GetStringField(t, "Operation") + if operation != "GetObject" { + t.Errorf("Wrong operation present in s3 access log. Expected GetObject got %s", operation) + } + if s3Entry.GetFloat64(t, "HTTP status") != 200 { + t.Error("HTTPS status should have been a 200") + } + + //WHEN we check the sts audit log entry + stsEntry := accesslogEntries.GetEntriesContainingField(t, "sts")[0] + //Then the operation should be AssumeRoleWithWebIdentity + operation = stsEntry.GetStringField(t, "Operation") + if operation != "AssumeRoleWithWebIdentity" { + t.Errorf("Wrong operation present in sts access log. Expected AssumeRoleWithWebIdentity got %s", operation) + + } + +} diff --git a/cmd/benchmark_test.go b/cmd/benchmark_test.go index a18b931..d60a7e5 100644 --- a/cmd/benchmark_test.go +++ b/cmd/benchmark_test.go @@ -2,7 +2,6 @@ package cmd import ( "context" - "crypto/rand" "errors" "fmt" "io" @@ -23,49 +22,13 @@ import ( func getS3ClientAgainstFakeS3Backend(t testing.TB, region string, creds aws.Credentials) (*s3.Client) { - backendServer := server.NewHttpDummyServer(fakeTestBackendPorts[region], fakeTestBackendHostnames[region]) + backendServer := server.NewBasicServer(fakeTestBackendPorts[region], fakeTestBackendHostnames[region], "", "", nil) return testutils.GetTestClientS3(t, region, credentials.FromAwsFormat(creds), backendServer) } -//This is a helper to be able to read a random string limited to a size while making it seekable. -//NonDeterministic is an imporant characteristic to be careful with. If you seek the start (offset=0) you can again read N bytes from it but -//they would not be the same as bytes read previously. -//While s3.PutObjectInput takes a Reader it actually requires a ReadSeeker for singing the request (when using HTTPS -//the s3.PutObjectInput does not sign the payload but when sending over HTTP then it will). So we must reset N of the limited reader when we -//Seek because the Signing middle ware would consume the reader and the actual request would have an exhausted LimitedReader if we don't action the -//Seek which would lead in 0-byte objects being sent. -//You can only use this against dummy backends which do not check Payload signature (like moto which is used in our test cases) -type nonDeterministicLimitedRandReadSeeker struct{ - lr io.LimitedReader - N int64 //How much can be maximally read -} - -func newNonDeterministicLimitedRandReadSeeker(n int64) *nonDeterministicLimitedRandReadSeeker{ - return &nonDeterministicLimitedRandReadSeeker{ - lr: io.LimitedReader{ - R: rand.Reader, - N: n, - }, - N: n, - } -} - -func (ndlrrs *nonDeterministicLimitedRandReadSeeker) Read(b []byte) (n int, err error) { - return ndlrrs.lr.Read(b) -} - -func (ndlrrs *nonDeterministicLimitedRandReadSeeker) Seek(offset int64, whence int) (int64, error) { - //Reset how much can be read based on the offset seeked - if offset > ndlrrs.N { - return -1, errors.New("Seek beyond Limit of Limited reader") - } - ndlrrs.lr.N = ndlrrs.N - offset - return offset, nil -} - func createRandomObjectInBackend(c *s3.Client, bucket, key string, size int64) (*s3.PutObjectOutput, error) { - rr := newNonDeterministicLimitedRandReadSeeker(size) + rr := testutils.NewNonDeterministicLimitedRandReadSeeker(size) putObjectInput := s3.PutObjectInput{ Bucket: &bucket, Key: &key, diff --git a/cmd/config.go b/cmd/config.go index 23ccb5b..3b426e0 100644 --- a/cmd/config.go +++ b/cmd/config.go @@ -52,6 +52,7 @@ const( signedUrlGraceTimeSeconds = "signedUrlGraceTimeSeconds" enableLegacyBehaviorInvalidRegionToDefaultRegion = "enableLegacyBehaviorInvalidRegionToDefaultRegion" logLevel = "logLevel" + metricsPort = "metricsPort" //Environment variables are upper cased @@ -74,6 +75,7 @@ const( FAKES3PP_SIGNEDURL_GRACE_TIME_SECONDS = "FAKES3PP_SIGNEDURL_GRACE_TIME_SECONDS" ENABLE_LEGACY_BEHAVIOR_INVALID_REGION_TO_DEFAULT_REGION = "ENABLE_LEGACY_BEHAVIOR_INVALID_REGION_TO_DEFAULT_REGION" LOG_LEVEL = "LOG_LEVEL" + FAKES3PP_METRICS_PORT = "FAKES3PP_METRICS_PORT" ) var envVarDefs = []envVarDef{ @@ -205,6 +207,13 @@ var envVarDefs = []envVarDef{ "The Loglevel at which to run (DEBUG, INFO (default), WARN, ERROR)", []string{proxys3, proxysts}, }, + { + metricsPort, + FAKES3PP_METRICS_PORT, + false, + "The port on which to run the /metrics endpoint", + []string{proxys3, proxysts}, + }, } func getMaxStsDurationSeconds() int { diff --git a/cmd/proxys3.go b/cmd/proxys3.go index 781b54b..e0c6f0e 100644 --- a/cmd/proxys3.go +++ b/cmd/proxys3.go @@ -15,35 +15,35 @@ const proxys3 = "proxys3" func buildS3Server() (server.Serverable) { BindEnvVariables(proxys3) - pm, err := initializePolicyManager() - if err != nil { - slog.Error("Could not initialize PolicyManager", "error", err) - panic(fmt.Sprintf("Clould not initialize PolicyManager %s", err)) - } + pm, err := initializePolicyManager() + if err != nil { + slog.Error("Could not initialize PolicyManager", "error", err) + panic(fmt.Sprintf("Clould not initialize PolicyManager %s", err)) + } - fqdns, err := getS3ProxyFQDNs() - if err != nil { - slog.Error("Could not get sts proxy fqdns", "error", err) - panic(fmt.Sprintf("Could not get sts proxy fqdns: %s", err)) - } + fqdns, err := getS3ProxyFQDNs() + if err != nil { + slog.Error("Could not get sts proxy fqdns", "error", err) + panic(fmt.Sprintf("Could not get sts proxy fqdns: %s", err)) + } - s, err := s3.NewS3Server( - viper.GetString(s3ProxyJwtPrivateRSAKey), - viper.GetInt(s3ProxyPort), - fqdns, - viper.GetString(s3ProxyCertFile), - viper.GetString(s3ProxyKeyFile), - pm, - viper.GetInt(signedUrlGraceTimeSeconds), - nil, - viper.GetString(s3BackendConfigFile), - viper.GetBool(enableLegacyBehaviorInvalidRegionToDefaultRegion), - ) - if err != nil { - slog.Error("Could not create S3 server", "error", err) - panic(fmt.Sprintf("Could not create S3 server: %s", err)) - } - return s + s, err := s3.NewS3Server( + viper.GetString(s3ProxyJwtPrivateRSAKey), + viper.GetInt(s3ProxyPort), + fqdns, + viper.GetString(s3ProxyCertFile), + viper.GetString(s3ProxyKeyFile), + pm, + viper.GetInt(signedUrlGraceTimeSeconds), + nil, + viper.GetString(s3BackendConfigFile), + viper.GetBool(enableLegacyBehaviorInvalidRegionToDefaultRegion), + ) + if err != nil { + slog.Error("Could not create S3 server", "error", err) + panic(fmt.Sprintf("Could not create S3 server: %s", err)) + } + return s } // proxys3Cmd represents the proxyS3 command @@ -53,7 +53,7 @@ var proxys3Cmd = &cobra.Command{ Long: `Spawn a server process that listens for requests and takes API calls that follow the S3 API.`, Run: func(cmd *cobra.Command, args []string) { - server.CreateAndStartSync(buildS3Server()) + server.CreateAndStartSync(buildS3Server(), getServerOptsFromViper()) }, } diff --git a/cmd/proxysts.go b/cmd/proxysts.go index 41616f6..cfe97cf 100644 --- a/cmd/proxysts.go +++ b/cmd/proxysts.go @@ -69,6 +69,12 @@ func buildSTSServer() (server.Serverable) { return s } +func getServerOptsFromViper() server.ServerOpts{ + return server.ServerOpts{ + MetricsPort: viper.GetInt(metricsPort), + } +} + // proxystsCmd represents the proxysts command var proxystsCmd = &cobra.Command{ Use: proxysts, @@ -76,7 +82,7 @@ var proxystsCmd = &cobra.Command{ Long: `Spawn a server process that listens for requests and takes API calls that follow the STS API. There are only few supporte`, Run: func(cmd *cobra.Command, args []string) { - server.CreateAndStartSync(buildSTSServer()) + server.CreateAndStartSync(buildSTSServer(), getServerOptsFromViper()) }, } diff --git a/cmd/test-utils.go b/cmd/test-utils.go index 7d6788e..23a9667 100644 --- a/cmd/test-utils.go +++ b/cmd/test-utils.go @@ -12,8 +12,6 @@ func initializeTestLogging() { logging.InitializeLogging(slog.LevelError, nil, nil) } - - //utility function to not run a test if there are no testing backends in the build environment. func skipIfNoTestingBackends(t testing.TB) { if os.Getenv("NO_TESTING_BACKENDS") != "" { diff --git a/go.mod b/go.mod index 7bbfb33..88799b6 100644 --- a/go.mod +++ b/go.mod @@ -15,6 +15,7 @@ require ( github.com/joho/godotenv v1.5.1 github.com/micahhausler/aws-iam-policy v0.4.2 github.com/minio/mux v1.9.0 + github.com/prometheus/client_golang v1.20.5 github.com/spf13/cobra v1.8.1 github.com/spf13/viper v1.19.0 sigs.k8s.io/yaml v1.4.0 @@ -34,12 +35,18 @@ require ( github.com/aws/aws-sdk-go-v2/service/internal/s3shared v1.17.17 // indirect github.com/aws/aws-sdk-go-v2/service/sso v1.22.8 // indirect github.com/aws/aws-sdk-go-v2/service/ssooidc v1.26.8 // indirect + github.com/beorn7/perks v1.0.1 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/hashicorp/hcl v1.0.0 // indirect github.com/inconshreveable/mousetrap v1.1.0 // indirect + github.com/klauspost/compress v1.17.9 // indirect github.com/magiconair/properties v1.8.7 // indirect github.com/mitchellh/mapstructure v1.5.0 // indirect + github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/pelletier/go-toml/v2 v2.2.2 // indirect - github.com/rogpeppe/go-internal v1.10.0 // indirect + github.com/prometheus/client_model v0.6.1 // indirect + github.com/prometheus/common v0.55.0 // indirect + github.com/prometheus/procfs v0.15.1 // indirect github.com/sagikazarmark/locafero v0.4.0 // indirect github.com/sagikazarmark/slog-shim v0.1.0 // indirect github.com/sourcegraph/conc v0.3.0 // indirect @@ -51,7 +58,7 @@ require ( golang.org/x/exp v0.0.0-20240823005443-9b4947da3948 // indirect golang.org/x/sys v0.25.0 // indirect golang.org/x/text v0.18.0 // indirect - gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c // indirect + google.golang.org/protobuf v1.34.2 // indirect gopkg.in/ini.v1 v1.67.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 27d9dc6..987d59c 100644 --- a/go.sum +++ b/go.sum @@ -34,6 +34,10 @@ github.com/aws/aws-sdk-go-v2/service/sts v1.30.8 h1:bAi+4p5EKnni+jrfcAhb7iHFQ24b github.com/aws/aws-sdk-go-v2/service/sts v1.30.8/go.mod h1:NXi1dIAGteSaRLqYgarlhP/Ij0cFT+qmCwiJqWh/U5o= github.com/aws/smithy-go v1.20.4 h1:2HK1zBdPgRbjFOHlfeQZfpC4r72MOb9bZkiFwggKO+4= github.com/aws/smithy-go v1.20.4/go.mod h1:irrKGvNn1InZwb2d7fkIRNucdfwR8R+Ts3wxYa/cJHg= +github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= +github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/cpuguy83/go-md2man/v2 v2.0.4/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46tRHOmNcaadrF8o= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -58,13 +62,14 @@ github.com/inconshreveable/mousetrap v1.1.0 h1:wN+x4NVGpMsO7ErUn/mUI3vEoE6Jt13X2 github.com/inconshreveable/mousetrap v1.1.0/go.mod h1:vpF70FUmC8bwa3OWnCshd2FqLfsEA9PFc4w1p2J65bw= github.com/joho/godotenv v1.5.1 h1:7eLL/+HRGLY0ldzfGMeQkb7vMd0as4CfYvUVzLqw0N0= github.com/joho/godotenv v1.5.1/go.mod h1:f4LDr5Voq0i2e/R5DDNOoa2zzDfwtkZa6DnEwAbqwq4= -github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI= +github.com/klauspost/compress v1.17.9 h1:6KIumPrER1LHsvBVuDa0r5xaG0Es51mhhB9BQB2qeMA= +github.com/klauspost/compress v1.17.9/go.mod h1:Di0epgTjJY877eYKx5yC51cX2A2Vl2ibi7bDH9ttBbw= github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= -github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= -github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= +github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc= +github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= github.com/magiconair/properties v1.8.7 h1:IeQXZAiQcpL9mgcAe1Nu6cX9LLw6ExEHKjN0VQdvPDY= github.com/magiconair/properties v1.8.7/go.mod h1:Dhd985XPs7jluiymwWYZ0G4Z61jb3vdS329zhj2hYo0= github.com/micahhausler/aws-iam-policy v0.4.2 h1:HF7bERLnpqEmffV9/wTT4jZ7TbSNVk0JbpXo1Cj3up0= @@ -73,11 +78,21 @@ github.com/minio/mux v1.9.0 h1:dWafQFyEfGhJvK6AwLOt83bIG5bxKxKJnKMCi0XAaoA= github.com/minio/mux v1.9.0/go.mod h1:1pAare17ZRL5GpmNL+9YmqHoWnLmMZF9C/ioUCfy0BQ= github.com/mitchellh/mapstructure v1.5.0 h1:jeMsZIYE/09sWLaz43PL7Gy6RuMjD2eJVyuac5Z2hdY= github.com/mitchellh/mapstructure v1.5.0/go.mod h1:bFUtVrKA4DC2yAKiSyO/QUcy7e+RRV2QTWOzhPopBRo= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= github.com/pelletier/go-toml/v2 v2.2.2 h1:aYUidT7k73Pcl9nb2gScu7NSrKCSHIDE89b3+6Wq+LM= github.com/pelletier/go-toml/v2 v2.2.2/go.mod h1:1t835xjRzz80PqgE6HHgN2JOsmgYu/h4qDAS4n929Rs= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U= github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/prometheus/client_golang v1.20.5 h1:cxppBPuYhUnsO6yo/aoRol4L7q7UFfdm+bR9r+8l63Y= +github.com/prometheus/client_golang v1.20.5/go.mod h1:PIEt8X02hGcP8JWbeHyeZ53Y/jReSnHgO035n//V5WE= +github.com/prometheus/client_model v0.6.1 h1:ZKSh/rekM+n3CeS952MLRAdFwIKqeY8b62p8ais2e9E= +github.com/prometheus/client_model v0.6.1/go.mod h1:OrxVMOVHjw3lKMa8+x6HeMGkHMQyHDk9E3jmP2AmGiY= +github.com/prometheus/common v0.55.0 h1:KEi6DK7lXW/m7Ig5i47x0vRzuBsHuvJdi5ee6Y3G1dc= +github.com/prometheus/common v0.55.0/go.mod h1:2SECS4xJG1kd8XF9IcM1gMX6510RAEL65zxzNImwdc8= +github.com/prometheus/procfs v0.15.1 h1:YagwOFzUgYfKKHX6Dr+sHT7km/hxC76UB0learggepc= +github.com/prometheus/procfs v0.15.1/go.mod h1:fB45yRUv8NstnjriLhBQLuOUt+WW4BsoGhij/e3PBqk= github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ= github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= @@ -116,6 +131,8 @@ golang.org/x/sys v0.25.0 h1:r+8e+loiHxRqhXVl6ML1nO3l1+oFoWbnlu2Ehimmi34= golang.org/x/sys v0.25.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/text v0.18.0 h1:XvMDiNzPAl0jr17s6W9lcaIhGUfUORdGCNsuLmPG224= golang.org/x/text v0.18.0/go.mod h1:BuEKDfySbSR4drPmRPG/7iBdf8hvFMuRexcpahXilzY= +google.golang.org/protobuf v1.34.2 h1:6xV6lTsCfpGD21XK49h7MhtcApnLqkfYgPcdHftf6hg= +google.golang.org/protobuf v1.34.2/go.mod h1:qYOHts0dSfpeUzUFpOMr/WGzszTmLH+DiWniOlNbLDw= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= diff --git a/middleware/observability.go b/middleware/observability.go index 2a5e9fd..52ddd91 100644 --- a/middleware/observability.go +++ b/middleware/observability.go @@ -8,6 +8,8 @@ import ( "github.com/VITObelgium/fakes3pp/httptracking" "github.com/VITObelgium/fakes3pp/requestctx" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" ) //The log Middleware has as responsibility to make sure to allow for: @@ -17,7 +19,49 @@ import ( //other components can have enriched logging. //It takes a healthcheck function because health checks should not follow other log //semantics. -func LogMiddleware(requestLogLvl slog.Level, hc HealthChecker) Middleware { +func LogMiddleware(requestLogLvl slog.Level, hc HealthChecker, promReg prometheus.Registerer) Middleware { + var buckets []float64 + var requestsTotal *prometheus.CounterVec + var requestDuration *prometheus.HistogramVec + var requestSize *prometheus.CounterVec + var responseSize *prometheus.CounterVec + var requestsFinished *prometheus.CounterVec + if promReg != nil { + requestsTotal = promauto.With(promReg).NewCounterVec( + prometheus.CounterOpts{ + Name: "http_requests_started_total", + Help: "Tracks the number of HTTP requests.", + }, []string{"method"}, + ) + requestDuration = promauto.With(promReg).NewHistogramVec( + prometheus.HistogramOpts{ + Name: "http_request_duration_seconds", + Help: "Tracks the latencies for HTTP requests.", + Buckets: buckets, + }, + []string{"operation"}, + ) + requestSize = promauto.With(promReg).NewCounterVec( + prometheus.CounterOpts{ + Name: "http_request_size_bytes", + Help: "Tracks the size of HTTP requests.", + }, + []string{"operation"}, + ) + responseSize = promauto.With(promReg).NewCounterVec( + prometheus.CounterOpts{ + Name: "http_response_size_bytes", + Help: "Tracks the size of HTTP responses.", + }, + []string{"operation"}, + ) + requestsFinished = promauto.With(promReg).NewCounterVec( + prometheus.CounterOpts{ + Name: "http_requests_finished_total", + Help: "Tracks the number of HTTP requests.", + }, []string{"method", "operation"}, + ) + } return func(next http.HandlerFunc) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { startTime := time.Now() @@ -27,7 +71,7 @@ func LogMiddleware(requestLogLvl slog.Level, hc HealthChecker) Middleware { if r.Body != nil { defer r.Body.Close() } - + //Make sure we have a requestctx to know about RequestId and to track information ctx := requestctx.NewContextFromHttpRequestWithStartTime(r, startTime) rCtx, ok := requestctx.FromContext(ctx) @@ -54,6 +98,24 @@ func LogMiddleware(requestLogLvl slog.Level, hc HealthChecker) Middleware { defer logFinalRequestDetails(ctx, logLvl, startTime, rCtx) if !wasHealthCheck{ + if promReg != nil { + //We can increase the request counter already + lbls := prometheus.Labels{"method": r.Method} + requestsTotal.With(lbls).Inc() + //But end of action metrics we must defer to the final stage + defer func() { + operation := "" + if rCtx.Operation != nil { + operation = rCtx.Operation.String() + } + opLabel := prometheus.Labels{"operation": operation} + requestDuration.With(opLabel).Observe(time.Since(startTime).Seconds()) + requestSize.With(opLabel).Add(float64(rCtx.BytesReceived)) + responseSize.With(opLabel).Add(float64(rCtx.BytesSent)) + opmetLabels := prometheus.Labels{"operation": operation, "method": r.Method} + requestsFinished.With(opmetLabels).Inc() + }() + } next.ServeHTTP(trackingW, r.WithContext(ctx)) } } @@ -64,6 +126,12 @@ func logFinalRequestDetails(ctx context.Context, lvl slog.Level, startTime time. requestLogAttrs := getRequestCtxLogAttrs(rCtx) requestLogAttrs = append(requestLogAttrs, slog.Int64("Total ms", time.Since(startTime).Milliseconds())) requestLogAttrs = append(requestLogAttrs, slog.Uint64("Bytes sent", rCtx.BytesSent)) + requestLogAttrs = append(requestLogAttrs, slog.Uint64("Bytes received", rCtx.BytesReceived)) + operation := "unknown" + if rCtx.Operation != nil { + operation = rCtx.Operation.String() + } + requestLogAttrs = append(requestLogAttrs, slog.String("Operation", operation)) requestLogAttrs = append(requestLogAttrs, slog.Int("HTTP status", rCtx.HTTPStatus)) requestLogAttrs = append(requestLogAttrs, rCtx.GetAccessLogInfo()...) slog.LogAttrs( @@ -76,7 +144,7 @@ func logFinalRequestDetails(ctx context.Context, lvl slog.Level, startTime time. func getRequestCtxLogAttrs(r *requestctx.RequestCtx) (logAttrs []slog.Attr) { - logAttrs = append(logAttrs, slog.Time("Time", r.Time)) + logAttrs = append(logAttrs, slog.Time("StartTime", r.Time)) logAttrs = append(logAttrs, slog.String("RemoteIP", r.RemoteIP)) logAttrs = append(logAttrs, slog.String("RequestURI", r.RequestURI)) logAttrs = append(logAttrs, slog.String("Referer", r.Referer)) diff --git a/server/basicserver.go b/server/basicserver.go new file mode 100644 index 0000000..23f3318 --- /dev/null +++ b/server/basicserver.go @@ -0,0 +1,64 @@ +package server + +import ( + "log/slog" + "net/http" +) + +//A dummy server mostly to convey access info +type BasicServer struct { + // The port on which to listen for incoming requests + port int + + //The hostname at which the server is reachable + hostname string + + //The TLS certificate used to encrypt traffic with if omitted HTTP server will be spawned + tlsCertFilePath string + + //The TLS key used to encrypt traffic with if omitted HTTP server will be spawned + tlsKeyFilePath string + + handlerFunc http.HandlerFunc +} + +func (s *BasicServer) GetPort() int { + return s.port +} + +func (s *BasicServer) GetListenHost() string { + return s.hostname +} + +func (s *BasicServer) GetTls() (enabled bool, certFile string, keyFile string) { + enabled = true + if certFile == "" { + slog.Debug("Disabling TLS", "reason", "no certFile provided") + enabled = false + } else if keyFile == "" { + slog.Debug("Disabling TLS", "reason", "no keyFile provided") + enabled = false + } + return enabled, s.tlsCertFilePath, s.tlsKeyFilePath +} + +func (s *BasicServer) ServeHTTP(w http.ResponseWriter, r *http.Request) { + if s.handlerFunc != nil { + s.handlerFunc(w, r) + } +} + +func NewBasicServer(port int, hostname string, tlsCertFilePath string, + tlsKeyFilePath string, handlerFunc http.HandlerFunc) *BasicServer { + return &BasicServer{ + port: port, + hostname: hostname, + tlsCertFilePath: tlsCertFilePath, + tlsKeyFilePath: tlsKeyFilePath, + handlerFunc: handlerFunc, + } +} + +func (s *BasicServer) SetHandlerFunc(f http.HandlerFunc) { + s.handlerFunc = f +} \ No newline at end of file diff --git a/server/dummy.go b/server/dummy.go deleted file mode 100644 index 95aae59..0000000 --- a/server/dummy.go +++ /dev/null @@ -1,32 +0,0 @@ -package server - -import "github.com/minio/mux" - -//A dummy server mostly to convey access info -type dummyServer struct { - port int - hostname string -} - -func (s *dummyServer) GetPort() int { - return s.port -} - -func (s *dummyServer) GetListenHost() string { - return s.hostname -} - -func (s *dummyServer) GetTls() (enabled bool, certFile string, keyFile string) { - return -} - -func (s *dummyServer) RegisterRoutes(router *mux.Router) (error) { - return nil -} - -func NewHttpDummyServer(port int, hostname string) Serverable { - return &dummyServer{ - port: port, - hostname: hostname, - } -} \ No newline at end of file diff --git a/server/interface.go b/server/interface.go index 7b065d2..ea3fbac 100644 --- a/server/interface.go +++ b/server/interface.go @@ -1,8 +1,12 @@ package server -import "github.com/minio/mux" +import ( + "net/http" +) type Serverable interface { + http.Handler + //Get the port name on which to listen GetPort() int @@ -11,8 +15,5 @@ type Serverable interface { //Get information to setup TLS GetTls() (enabled bool, certFile string, keyFile string) - - //Callback to add routes to a router - RegisterRoutes(router *mux.Router) (error) } diff --git a/server/server.go b/server/server.go index c759cbb..0880301 100644 --- a/server/server.go +++ b/server/server.go @@ -10,29 +10,89 @@ import ( "sync" "github.com/VITObelgium/fakes3pp/middleware" - "github.com/minio/mux" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/collectors" + "github.com/prometheus/client_golang/prometheus/promhttp" ) +//Defines optional configuration for a Serverable +type ServerOpts struct { + //The default of 0 means no metrics are exposed + MetricsPort int + + //The loglevel at which request start and stop events are logged + RequestLogLvl slog.Level + + //The healthchecker used + healthchecker middleware.HealthChecker +} + +func StartPrometheusMetricsServer(port int) (func(), prometheus.Registerer) { + if port == 0 { + return nil, nil + } + // Create non-global registry. + reg := prometheus.NewRegistry() + + // Add go runtime metrics and process collectors. + reg.MustRegister( + collectors.NewGoCollector(), + collectors.NewProcessCollector(collectors.ProcessCollectorOpts{}), + ) + + mux := http.NewServeMux() + // Expose /metrics HTTP endpoint using the created custom registry. + mux.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{Registry: reg})) + var addr = fmt.Sprintf(":%d", port) + + metricsSrvDone := &sync.WaitGroup{} + metricsSrvDone.Add(1) + var metricsSrv = &http.Server{Addr: addr} + metricsSrv.Handler = mux + + go func() { + defer metricsSrvDone.Done() + err := metricsSrv.ListenAndServe() + + if err != http.ErrServerClosed { + slog.Error(err.Error()) + } + }() + + shutdownMetricsServerSync := func(){ + err := metricsSrv.Shutdown(context.Background()) + if err != nil { + panic(err) + } + } + + return shutdownMetricsServerSync, reg +} + //Start a server in the background but return a waitGroup. // -func CreateAndStart(s Serverable) (*sync.WaitGroup, *http.Server, error) { +func CreateAndStart(s Serverable, opts ServerOpts) (*sync.WaitGroup, *http.Server, error) { + shutdownMetricsServerSync, reg := StartPrometheusMetricsServer(opts.MetricsPort) + serverDone := &sync.WaitGroup{} serverDone.Add(1) portNr := s.GetPort() tlsEnabled, tlsCertFile, tlsKeyFile := s.GetTls() - router := mux.NewRouter().SkipClean(true).UseEncodedPath() - err := s.RegisterRoutes(router) - if err != nil { - return nil, nil, err - } listenAddress := fmt.Sprintf(":%d", portNr) slog.Info("Started listening", "port", portNr) srv := &http.Server{Addr: listenAddress} + if shutdownMetricsServerSync != nil { + srv.RegisterOnShutdown(shutdownMetricsServerSync) + } + healthchecker := opts.healthchecker + if healthchecker == nil { + healthchecker = middleware.NewPingPongHealthCheck(slog.LevelDebug) + } srv.Handler = middleware.NewMiddlewarePrefixedHandler( - router, - middleware.LogMiddleware(slog.LevelInfo, middleware.NewPingPongHealthCheck(slog.LevelInfo),), + s, + middleware.LogMiddleware(opts.RequestLogLvl, healthchecker, reg), ) // Start proxy in the background but manage waitgroup @@ -56,8 +116,8 @@ func CreateAndStart(s Serverable) (*sync.WaitGroup, *http.Server, error) { } //Create a server and await until its health check is passing -func CreateAndAwaitHealthy(s Serverable) (*sync.WaitGroup, *http.Server, error) { - serverDone, srv, err := CreateAndStart(s) +func CreateAndAwaitHealthy(s Serverable, opts ServerOpts) (*sync.WaitGroup, *http.Server, error) { + serverDone, srv, err := CreateAndStart(s, opts) if err != nil { return serverDone, srv, err } @@ -75,8 +135,8 @@ func CreateAndAwaitHealthy(s Serverable) (*sync.WaitGroup, *http.Server, error) return serverDone, srv, nil } -func CreateAndStartSync(s Serverable) { - proxyDone, _, err := CreateAndAwaitHealthy(s) +func CreateAndStartSync(s Serverable, opts ServerOpts) { + proxyDone, _, err := CreateAndAwaitHealthy(s, opts) if err != nil { panic(err) } diff --git a/server/server_test.go b/server/server_test.go new file mode 100644 index 0000000..7f42397 --- /dev/null +++ b/server/server_test.go @@ -0,0 +1,190 @@ +package server_test + +import ( + "context" + "fmt" + "io" + "net/http" + "strings" + "testing" + "time" + + "github.com/VITObelgium/fakes3pp/server" + "github.com/VITObelgium/fakes3pp/testutils" + io_prometheus_client "github.com/prometheus/client_model/go" + "github.com/prometheus/common/expfmt" + "google.golang.org/protobuf/proto" +) + + +func CreateTestHandler(t testing.TB, sendSize int64) http.HandlerFunc{ + return func(w http.ResponseWriter, r *http.Request) { + _, err := io.Copy(io.Discard, r.Body) + + if err != nil { + t.Error("Got a problem when reading all the bytes") + t.FailNow() + } + w.WriteHeader(http.StatusOK) + _, err = io.Copy(w, testutils.NewNonDeterministicLimitedRandReadSeeker(sendSize)) + if err != nil { + t.Error("vould not copy in random string") + t.FailNow() + } + } +} + +func isMetricOfInterest(metricName string) bool { + if strings.HasPrefix(metricName, "go_") { + return false + } else if strings.HasPrefix(metricName, "process_") { + return false + } + return true +} + +func getMetrics(t testing.TB, r io.Reader) (metrics map[string][]*io_prometheus_client.Metric){ + var tp expfmt.TextParser + notNormalized, err := tp.TextToMetricFamilies(r) + if err != nil { + t.Errorf("converting reader to metric families failed: %s", err) + t.FailNow() + } + metrics = map[string][]*io_prometheus_client.Metric{} + + for _, metric := range notNormalized { + if !isMetricOfInterest(*metric.Name) { + continue + } + if metric.Help == nil { + metric.Help = proto.String("") + } + metrics[*metric.Name] = metric.GetMetric() + } + return metrics +} + +//Get metrics from a counter where n is the amount of actual metic measurements. +func getCounterMetric(t testing.TB, metricsPort int, metricName string) (n int, sum float64){ + res, err := http.Get(fmt.Sprintf("http://localhost:%d/metrics", metricsPort)) + if err != nil { + t.Error("Cannot get metrics", "error", err) + t.FailNow() + } + metricDict := getMetrics(t, res.Body) + + requestSizeBytesMetrics, ok := metricDict[metricName] + if !ok { + return 0, 0 + } + n , sum = sumCounters(requestSizeBytesMetrics) + return +} + + +//A test to make sure metrics are expose when metrics are enabled and they must be close to reality. +func TestCheckMetricsServer(t *testing.T) { + //Given responseSize + var responseSize int64 = 123043 + var sendSize int64 = 53421 + testPort := 8443 + metricsPort := 5555 + //Given a test server which sends a response of a given size and reads everythign + s := server.NewBasicServer(testPort, "localhost", "", "", CreateTestHandler(t, int64(responseSize))) + //Given it is started with metrics exposed + wg, ts, err :=server.CreateAndAwaitHealthy(s, server.ServerOpts{MetricsPort: metricsPort}) + if err != nil { + t.Error("Could not start server") + t.FailNow() + } + //WHEN we do a request with a given size + r, err := http.NewRequest("POST", fmt.Sprintf("http://localhost:%d", testPort), testutils.NewNonDeterministicLimitedRandReadSeeker(sendSize)) + if err != nil { + t.Error("Could not create request") + t.FailNow() + } + client := &http.Client{} + res, err := client.Do(r) + if err != nil { + t.Error("Could not perform HTTP request", "error", err) + t.FailNow() + } + + defer res.Body.Close() + + //THEN the metrics must become available in scrapes + //At least within due time which should be rather fast + n := 0 + var requestSizeBytes float64 + for i := 0 ; i < 3 ; i++ { // First time fetching metrics make sure they have actually propagated. + n, requestSizeBytes = getCounterMetric(t, metricsPort, "http_request_size_bytes") + if n != 0 { + break + } + time.Sleep(time.Millisecond * time.Duration(100)) + } + + //THEN there must be 1 measuring point for request size + if n != 1 { + if n < 1 { + t.Error("There was not a single request performed") + } else { + t.Error("There was more than 1 request performed") + } + } + //THEN the returned size should be close to the actual request size + assertCloseEnough(t, sendSize, requestSizeBytes, 0.001) + + //THEN we have the same expectations for response size + n, responseSizeBytes := getCounterMetric(t, metricsPort, "http_response_size_bytes") + + if n != 1 { + if n < 1 { + t.Error("There was not a single request performed") + } else { + t.Error("There was more than 1 request performed") + } + } + assertCloseEnough(t, responseSize, responseSizeBytes, 0.001) + + //Then the counter for finished responses must be correct + n, finishedRequests := getCounterMetric(t, metricsPort, "http_requests_finished_total") + + if n != 1 { + if n < 1 { + t.Error("There was not a single request performed") + } else { + t.Error("There was more than 1 request performed") + } + } + assertCloseEnough(t, 1, finishedRequests, 0.001) + err = ts.Shutdown(context.Background()) + if err != nil { + t.Error("Got an error", err) + } + wg.Wait() +} + +func sumCounters(metrics []*io_prometheus_client.Metric) (n int, sum float64) { + n = 0 + for _, m := range metrics { + n += 1 + counter := m.GetCounter() + if counter == nil { continue } + sum += *counter.Value + } + return n, sum +} + +//percentage is how close it needs to be for example 0.01 means it should be +- 1 percent +func assertCloseEnough(t testing.TB, targetValue int64, actualValue float64, percentage float64) { + lowerBound := float64(targetValue) - float64(targetValue) * float64(percentage) + upperBound := float64(targetValue) + float64(targetValue) * float64(percentage) + if actualValue < lowerBound { + t.Errorf("Actual value too small expected %d, got %f", targetValue, actualValue) + } + if actualValue > upperBound { + t.Errorf("Actual value too big expected %d, got %f", targetValue, actualValue) + + } +} diff --git a/testutils/loghelpers.go b/testutils/loghelpers.go new file mode 100644 index 0000000..8ad3ae9 --- /dev/null +++ b/testutils/loghelpers.go @@ -0,0 +1,137 @@ +package testutils + +import ( + "bytes" + "encoding/json" + "io" + "log/slog" + "testing" + + "github.com/VITObelgium/fakes3pp/logging" +) + +//For testing only get lines out of a buffer +func logBufferToLines(tb testing.TB, buf *bytes.Buffer) []string { + var lines = []string{} + lineDelimiter := byte('\n') + for i:=0 ; i < 10000; i++ { + line, err := buf.ReadString(lineDelimiter) + if err == nil { + lines = append(lines, line) + } else { + if err == io.EOF { + return lines + } + tb.Errorf("Encountered error while processing log buffer: %s", err) + tb.FailNow() + } + } + return lines +} + +//A fixture to start capturing logs. It returns the following: +// - a teardown callback to stop the log capture. +// - a getCapturedLogLines callback which gets the log lines captured since the last run +func CaptureLogFixture(tb testing.TB, lvl slog.Level, fe logging.ForceEnabler) (teardown func()(), getCapturedLogLines func()([]string)) { + loggerBeforeFixture := slog.Default() + buf := &bytes.Buffer{} + logging.InitializeLogging(lvl, fe, buf) + var fixtureActive = true + + teardown = func() { + if fixtureActive { + slog.SetDefault(loggerBeforeFixture) + fixtureActive = false + } + } + + getCapturedLogLines = func() (lines []string) { + lines = logBufferToLines(tb, buf) + return lines + } + + return teardown, getCapturedLogLines +} + +//A fixture to capture structured logs +func CaptureStructuredLogsFixture (tb testing.TB, lvl slog.Level, fe logging.ForceEnabler) (teardown func()(), getCapturedLogEntries func()(StructuredLogEntries)) { + teardown, getCapturedLogLines := CaptureLogFixture(tb, lvl, fe) + + getCapturedLogEntries = func() (StructuredLogEntries) { + capturedEntries := StructuredLogEntries{} + for _, line := range getCapturedLogLines() { + entry := StructuredLogEntry{} + err := json.Unmarshal([]byte(line), &entry) + if err != nil { + tb.Errorf("could not convert %s to structured logging entry", line) + tb.Fail() + } else { + capturedEntries = append(capturedEntries, entry) + } + } + return capturedEntries + } + return teardown, getCapturedLogEntries +} + +type StructuredLogEntry map[string]any +type StructuredLogEntries []StructuredLogEntry + +func (s StructuredLogEntry) GetStringField(t testing.TB, fieldName string) (string) { + fieldValue, ok := s[fieldName] + if ok { + stringValue, ok := fieldValue.(string) + if ok { + return stringValue + } + t.Errorf("field %s is not a string", fieldName) + } + t.Errorf("field %s is not present", fieldName) + t.FailNow() + return "" +} + +//Default choice by a JSON unmarshaller for a number +func (s StructuredLogEntry) GetFloat64(t testing.TB, fieldName string) (float64) { + fieldValue, ok := s[fieldName] + if ok { + floatValue, ok := fieldValue.(float64) + if ok { + return floatValue + } + t.Errorf("field %s is not a number", fieldName) + } + t.Errorf("field %s is not present", fieldName) + t.FailNow() + return 0.0 +} + +func (s StructuredLogEntry) GetLevel(t testing.TB) (string) { + return s.GetStringField(t, "level") +} + +func (s StructuredLogEntry) GetMsg(t testing.TB) (string) { + return s.GetStringField(t, "msg") +} + +func (s *StructuredLogEntries) GetEntriesWithMsg(t testing.TB, msgValue string) (StructuredLogEntries) { + filteredEntries := StructuredLogEntries{} + for _, entry := range *s { + msg := entry.GetMsg(t) + if msg == msgValue { + filteredEntries = append(filteredEntries, entry) + } + } + return filteredEntries +} + +func (s *StructuredLogEntries) GetEntriesContainingField(t testing.TB, fieldName string) (StructuredLogEntries) { + filteredEntries := StructuredLogEntries{} + for _, entry := range *s { + _, ok := entry[fieldName] + if ok { + filteredEntries = append(filteredEntries, entry) + } + } + return filteredEntries +} diff --git a/testutils/random.go b/testutils/random.go new file mode 100644 index 0000000..a74755f --- /dev/null +++ b/testutils/random.go @@ -0,0 +1,43 @@ +package testutils + +import ( + "crypto/rand" + "errors" + "io" +) + +//This is a helper to be able to read a random string limited to a size while making it seekable. +//NonDeterministic is an imporant characteristic to be careful with. If you seek the start (offset=0) you can again read N bytes from it but +//they would not be the same as bytes read previously. +//While s3.PutObjectInput takes a Reader it actually requires a ReadSeeker for singing the request (when using HTTPS +//the s3.PutObjectInput does not sign the payload but when sending over HTTP then it will). So we must reset N of the limited reader when we +//Seek because the Signing middle ware would consume the reader and the actual request would have an exhausted LimitedReader if we don't action the +//Seek which would lead in 0-byte objects being sent. +//You can only use this against dummy backends which do not check Payload signature (like moto which is used in our test cases) +type nonDeterministicLimitedRandReadSeeker struct{ + lr io.LimitedReader + N int64 //How much can be maximally read +} + +func NewNonDeterministicLimitedRandReadSeeker(n int64) *nonDeterministicLimitedRandReadSeeker{ + return &nonDeterministicLimitedRandReadSeeker{ + lr: io.LimitedReader{ + R: rand.Reader, + N: n, + }, + N: n, + } +} + +func (ndlrrs *nonDeterministicLimitedRandReadSeeker) Read(b []byte) (n int, err error) { + return ndlrrs.lr.Read(b) +} + +func (ndlrrs *nonDeterministicLimitedRandReadSeeker) Seek(offset int64, whence int) (int64, error) { + //Reset how much can be read based on the offset seeked + if offset > ndlrrs.N { + return -1, errors.New("Seek beyond Limit of Limited reader") + } + ndlrrs.lr.N = ndlrrs.N - offset + return offset, nil +} \ No newline at end of file