diff --git a/changelog/v1.15.0-beta15/test-service-logging.yaml b/changelog/v1.15.0-beta15/test-service-logging.yaml new file mode 100644 index 00000000000..5582010a095 --- /dev/null +++ b/changelog/v1.15.0-beta15/test-service-logging.yaml @@ -0,0 +1,9 @@ +changelog: + - type: NON_USER_FACING + issueLink: https://github.com/solo-io/solo-projects/issues/5006 + resolvesIssue: true + description: >- + Expose configuration to control verbosity of service logging in e2e tests + + skipCI-kube-tests:true + skipCI-docs-build:true \ No newline at end of file diff --git a/test/e2e/README.md b/test/e2e/README.md index 9d6e7e46814..404e76debea 100644 --- a/test/e2e/README.md +++ b/test/e2e/README.md @@ -39,26 +39,60 @@ The `run-tests` make target runs ginkgo with a set of useful flags. The followin | TEST_PKG | "" | The path to the package of the test suite you want to run | | WAIT_ON_FAIL | 0 | Set to 1 to prevent Ginkgo from cleaning up the Gloo Edge installation in case of failure. Useful to exec into inspect resources created by the test. A command to resume the test run (and thus clean up resources) will be logged to the output. | | INVALID_TEST_REQS | fail | The behavior for tests which depend on environment conditions that aren't satisfied. Options are `skip`, `run`, `fail` | +| SERVICE_LOG_LEVEL | "" | The log levels used for services. See "Controlling Log Verbosity of Services" below. | + +#### Controlling Log Verbosity of Services +Multiple services (Gloo, Envoy, Discovery) are executed in parallel to run these tests. By default, these services log at the `info` level. To change the log level of a service, set the `SERVICE_LOG_LEVEL` environment variable to a comma separated list of `service:level` pairs. + +Options for services are: +- gateway-proxy +- gloo +- uds +- fds + +Options for log levels are: +- debug +- info +- warn +- error + +For example, to set the log level of the Gloo service to `debug` and the Envoy service to `error`, you would set: + +```bash +SERVICE_LOG_LEVEL=gloo:debug,gateway-proxy:error TEST_PKG=./test/e2e/... make test +``` + +*If the same service has multiple log levels specified, we will log a warning and the last one defined will be used.* + +#### Controlling Log Verbosity of Ginkgo Runner +Ginkgo has 4 verbosity settings, whose details can be found in the [Ginkgo docs](https://onsi.github.io/ginkgo/#controlling-verbosity) + +To control these settings, you must pass the flags using the `GINKGO_USER_FLAGS` environment variable. + +For example, to set the Ginkgo runner to `very verbose` mode, you would set: +```bash +GINKGO_USER_FLAGS=-vv TEST_PKG=./test/e2e/... make test +``` #### Using Recently Published Image (Most Common) This is the most common pattern. If you did not make changes to the `gateway-proxy` component, and do not specify an `ENVOY_IMAGE_TAG` our tests will identify the most recently published image (for your LTS branch) and use that version. ```bash -TEST_PKG=./test/e2e/... make run-tests +TEST_PKG=./test/e2e/... make test ``` #### Using Previously Published Image If you want to specify a particular version that was previously published, you can also do that by specifying the `ENVOY_IMAGE_TAG`. ```bash -ENVOY_IMAGE_TAG=1.13.0 TEST_PKG=./test/e2e/... make run-tests +ENVOY_IMAGE_TAG=1.13.0 TEST_PKG=./test/e2e/... make test ``` #### Using Locally Built Image If you have made changes to the component, you will have had to rebuild the image locally (see [setup tests](#setup)). After you rebuild the image, you need to supply the tag of that image when running the tests: ```bash -ENVOY_IMAGE_TAG=0.0.1-local TEST_PKG=./test/e2e/... make run-tests +ENVOY_IMAGE_TAG=0.0.1-local TEST_PKG=./test/e2e/... make test ``` ### Debugging Tests diff --git a/test/e2e/staged_transformation_test.go b/test/e2e/staged_transformation_test.go index e2d7fb96359..fe7642e1c91 100644 --- a/test/e2e/staged_transformation_test.go +++ b/test/e2e/staged_transformation_test.go @@ -3,7 +3,10 @@ package e2e_test import ( "encoding/base64" + "github.com/solo-io/gloo/test/services" + "github.com/solo-io/gloo/test/services/envoy" "github.com/solo-io/gloo/test/testutils" + "go.uber.org/zap/zapcore" "google.golang.org/protobuf/types/known/wrapperspb" "github.com/golang/protobuf/ptypes/wrappers" @@ -30,14 +33,26 @@ var _ = Describe("Staged Transformation", func() { var ( testContext *e2e.TestContext + + // This test relies on running the gateway-proxy with debug logging enabled + // This variable allows us to reset the original log level after the test + resetLogLevel func() ) BeforeEach(func() { + originalProxyLogLevel := services.GetLogLevel(envoy.ServiceName) + services.SetLogLevel(envoy.ServiceName, zapcore.DebugLevel) + resetLogLevel = func() { + services.SetLogLevel(envoy.ServiceName, originalProxyLogLevel) + } + testContext = testContextFactory.NewTestContext() testContext.BeforeEach() }) AfterEach(func() { + resetLogLevel() + testContext.AfterEach() }) diff --git a/test/services/envoy/factory.go b/test/services/envoy/factory.go index 82e029bb391..15aadb36577 100644 --- a/test/services/envoy/factory.go +++ b/test/services/envoy/factory.go @@ -11,6 +11,9 @@ import ( "strings" "text/template" + "github.com/solo-io/gloo/test/services" + "go.uber.org/zap/zapcore" + "github.com/solo-io/gloo/projects/gloo/pkg/defaults" "github.com/onsi/ginkgo/v2" @@ -25,6 +28,7 @@ var _ Factory = new(factoryImpl) const ( envoyBinaryName = "envoy" + ServiceName = "gateway-proxy" ) // Factory is a helper for running multiple envoy instances @@ -208,6 +212,7 @@ func (f *factoryImpl) newInstanceOrError() (*Instance, error) { AccessLogPort: NextAccessLogPort(), AccessLogAddr: gloo, ApiVersion: "V3", + logLevel: getInstanceLogLevel(), RequestPorts: &RequestPorts{ HttpPort: defaults.HttpPort, HttpsPort: defaults.HttpsPort, @@ -221,6 +226,21 @@ func (f *factoryImpl) newInstanceOrError() (*Instance, error) { } +func getInstanceLogLevel() string { + logLevel := services.GetLogLevel(ServiceName) + + // Envoy log level options do not match Gloo's log level options, so we must convert + // https://www.envoyproxy.io/docs/envoy/latest/start/quick-start/run-envoy#debugging-envoy + // There are a few options which are available in Envoy, but not in Gloo ("trace", "critical", "off") + // We opted not to support those options, to provide developers a consistent experience + switch logLevel { + case zapcore.DebugLevel, zapcore.InfoLevel, zapcore.WarnLevel, zapcore.ErrorLevel: + return logLevel.String() + } + + return zapcore.InfoLevel.String() +} + func localAddr() (string, error) { ip := os.Getenv("GLOO_IP") if ip != "" { diff --git a/test/services/envoy/instance.go b/test/services/envoy/instance.go index fa20a0ff934..faffb485d81 100644 --- a/test/services/envoy/instance.go +++ b/test/services/envoy/instance.go @@ -41,6 +41,7 @@ type Instance struct { envoypath string envoycfg string logs *SafeBuffer + logLevel string cmd *exec.Cmd GlooAddr string // address for gloo and services Port uint32 @@ -170,7 +171,7 @@ func (ei *Instance) runWithAll(eic InstanceConfig, bootstrapBuilder bootstrapBui return ei.runContainer(eic.Context()) } - args := []string{"--config-yaml", ei.envoycfg, "--disable-hot-restart", "--log-level", "debug"} + args := []string{"--config-yaml", ei.envoycfg, "--disable-hot-restart", "--log-level", ei.logLevel} // run directly cmd := exec.CommandContext(eic.Context(), ei.envoypath, args...) @@ -251,7 +252,7 @@ func (ei *Instance) runContainer(ctx context.Context) error { "--entrypoint=envoy", ei.DockerImage, "--disable-hot-restart", - "--log-level", "debug", + "--log-level", ei.logLevel, "--config-yaml", ei.envoycfg, ) diff --git a/test/services/gloo.go b/test/services/gloo.go index 79d8ed3749a..0a3070df99f 100644 --- a/test/services/gloo.go +++ b/test/services/gloo.go @@ -75,6 +75,12 @@ import ( var glooPortBase = int32(30400) +const ( + GlooServiceName = "gloo" + FdsServiceName = "fds" + UdsServiceName = "uds" +) + func AllocateGlooPort() int32 { return atomic.AddInt32(&glooPortBase, 1) + int32(parallel.GetPortOffset()) } @@ -134,33 +140,45 @@ func RunGlooGatewayUdsFds(ctx context.Context, runOptions *RunOptions) TestClien // could use the same setup code, but in the meantime, we use constructTestOpts to mirror the functionality bootstrapOpts := constructTestOpts(ctx, runOptions, settings) - go func() { + go func(bootstrapOpts bootstrap.Opts) { defer GinkgoRecover() + ctxWithLogLevel := contextutils.WithExistingLogger(bootstrapOpts.WatchOpts.Ctx, MustGetSugaredLogger(GlooServiceName)) + bootstrapOpts.WatchOpts.Ctx = ctxWithLogLevel + if runOptions.ExtensionsBuilders.Gloo == nil { _ = setup.RunGloo(bootstrapOpts) } else { glooExtensions := runOptions.ExtensionsBuilders.Gloo(ctx, bootstrapOpts) _ = setup.RunGlooWithExtensions(bootstrapOpts, glooExtensions) } - }() + }(bootstrapOpts) if !runOptions.WhatToRun.DisableFds { - go func() { + go func(bootstrapOpts bootstrap.Opts) { defer GinkgoRecover() + + ctxWithLogLevel := contextutils.WithExistingLogger(bootstrapOpts.WatchOpts.Ctx, MustGetSugaredLogger(FdsServiceName)) + bootstrapOpts.WatchOpts.Ctx = ctxWithLogLevel + if runOptions.ExtensionsBuilders.Fds == nil { _ = fds_syncer.RunFDS(bootstrapOpts) } else { fdsExtensions := runOptions.ExtensionsBuilders.Fds(ctx, bootstrapOpts) _ = fds_syncer.RunFDSWithExtensions(bootstrapOpts, fdsExtensions) } - }() + }(bootstrapOpts) } + if !runOptions.WhatToRun.DisableUds { - go func() { + go func(bootstrapOpts bootstrap.Opts) { defer GinkgoRecover() + + ctxWithLogLevel := contextutils.WithExistingLogger(bootstrapOpts.WatchOpts.Ctx, MustGetSugaredLogger(UdsServiceName)) + bootstrapOpts.WatchOpts.Ctx = ctxWithLogLevel + _ = uds_syncer.RunUDS(bootstrapOpts) - }() + }(bootstrapOpts) } testClients := getTestClients(ctx, bootstrapOpts) diff --git a/test/services/logging.go b/test/services/logging.go new file mode 100644 index 00000000000..950f86b920d --- /dev/null +++ b/test/services/logging.go @@ -0,0 +1,146 @@ +package services + +import ( + "fmt" + "os" + "strings" + "sync" + + "k8s.io/apimachinery/pkg/util/sets" + + "github.com/onsi/gomega" + errors "github.com/rotisserie/eris" + "github.com/solo-io/gloo/test/testutils" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +const ( + // _loggingConfigRegex is the format of the string that can be passed to configure the log level of services + // It is currently unused, but is here for reference + // In general, we try to use the name of the deployment, e.g. gateway-proxy, gloo, discovery, etc. + // for the name of the service. To confirm the name of the service that is being used, check the + // invocation for the given service + _loggingConfigRegex = "serviceA:logLevel,serviceB:logLevel" + pairSeparator = "," + nameValueSeparator = ":" +) + +var ( + logProviderSingleton = &logProvider{ + defaultLogLevel: zapcore.InfoLevel, + serviceLogLevel: make(map[string]zapcore.Level, 3), + } +) + +func init() { + // Initialize the log provider with the log level provided in the environment variable + LoadUserDefinedLogLevelFromEnv() +} + +// LoadUserDefinedLogLevelFromEnv loads the log level from the environment variable +// and resets the entire LogProvider state to the values in that environment variable +func LoadUserDefinedLogLevelFromEnv() { + logProviderSingleton.ReloadFromEnv() +} + +// LoadUserDefinedLogLevel loads the log level from the provided string +// and resets the entire LogProvider state to the values in that string +func LoadUserDefinedLogLevel(userDefinedLogLevel string) { + logProviderSingleton.ReloadFromString(userDefinedLogLevel) +} + +// GetLogLevel returns the log level for the given service +func GetLogLevel(serviceName string) zapcore.Level { + return logProviderSingleton.GetLogLevel(serviceName) +} + +// SetLogLevel sets the log level for the given service +func SetLogLevel(serviceName string, logLevel zapcore.Level) { + logProviderSingleton.SetLogLevel(serviceName, logLevel) +} + +// IsDebugLogLevel returns true if the given service is logging at the debug level +func IsDebugLogLevel(serviceName string) bool { + logLevel := GetLogLevel(serviceName) + return logLevel == zapcore.DebugLevel +} + +// MustGetSugaredLogger returns a sugared logger for the given service +// This logger is configured with the appropriate log level +func MustGetSugaredLogger(serviceName string) *zap.SugaredLogger { + logLevel := GetLogLevel(serviceName) + + config := zap.NewProductionConfig() + config.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + config.Level.SetLevel(logLevel) + + logger, err := config.Build() + gomega.Expect(err).NotTo(gomega.HaveOccurred(), "failed to build logger for: %s", serviceName) + + return logger.Sugar() +} + +// logProvider is a helper for managing the log level of multiple services +type logProvider struct { + sync.RWMutex + + defaultLogLevel zapcore.Level + serviceLogLevel map[string]zapcore.Level +} + +func (l *logProvider) GetLogLevel(serviceName string) zapcore.Level { + l.RLock() + defer l.RUnlock() + + logLevel, ok := l.serviceLogLevel[serviceName] + if !ok { + return l.defaultLogLevel + } + return logLevel +} + +func (l *logProvider) SetLogLevel(serviceName string, logLevel zapcore.Level) { + l.Lock() + defer l.Unlock() + + l.serviceLogLevel[serviceName] = logLevel +} + +func (l *logProvider) ReloadFromEnv() { + l.ReloadFromString(os.Getenv(testutils.ServiceLogLevel)) +} + +func (l *logProvider) ReloadFromString(userDefinedLogLevel string) { + l.Lock() + defer l.Unlock() + + serviceLogPairs := strings.Split(userDefinedLogLevel, pairSeparator) + serviceNameSet := sets.NewString() + for _, serviceLogPair := range serviceLogPairs { + nameValue := strings.Split(serviceLogPair, nameValueSeparator) + if len(nameValue) != 2 { + continue + } + + serviceName := nameValue[0] + logLevelStr := nameValue[1] + + if serviceNameSet.Has(serviceName) { + // This isn't an error, but we want to warn the user that with multiple definitions + // there may be unknown behavior + fmt.Printf("WARNING: duplicate service name found in log level string: %s\n", serviceName) + } + + logLevel, err := zapcore.ParseLevel(logLevelStr) + // We intentionally error loudly here + // This will occur if the user passes an invalid log level string + if err != nil { + panic(errors.Wrapf(err, "invalid log level string: %s", logLevelStr)) + } + + // This whole function operates with a lock, so we can modify the map directly + logProviderSingleton.serviceLogLevel[serviceName] = logLevel + serviceNameSet.Insert(serviceName) + } +} diff --git a/test/services/logging_test.go b/test/services/logging_test.go new file mode 100644 index 00000000000..ab1cdd4d7fa --- /dev/null +++ b/test/services/logging_test.go @@ -0,0 +1,50 @@ +package services_test + +import ( + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" + "github.com/solo-io/gloo/test/services" + "go.uber.org/zap/zapcore" +) + +var _ = Describe("Logging", func() { + + Context("GetLogLevel", func() { + + It("should default to info when no log level defined", func() { + services.LoadUserDefinedLogLevel("") + Expect(services.GetLogLevel("undefined-service")).To(Equal(zapcore.InfoLevel)) + }) + + It("should return the correct log level", func() { + services.LoadUserDefinedLogLevel("gateway-proxy:debug,gloo:error") + Expect(services.GetLogLevel("gateway-proxy")).To(Equal(zapcore.DebugLevel)) + Expect(services.GetLogLevel("gloo")).To(Equal(zapcore.ErrorLevel)) + }) + + }) + + Context("IsDebugLogLevel", func() { + + It("should return true when log level is debug", func() { + services.LoadUserDefinedLogLevel("service:debug") + Expect(services.IsDebugLogLevel("service")).To(BeTrue()) + }) + + It("should return false when log level is not debug", func() { + services.LoadUserDefinedLogLevel("service:error") + Expect(services.IsDebugLogLevel("service")).To(BeFalse()) + }) + + }) + + Context("MustGetSugaredLogger", func() { + + It("should return logger with proper log level configured", func() { + services.LoadUserDefinedLogLevel("service:debug") + Expect(services.MustGetSugaredLogger("service").Level()).To(Equal(zapcore.DebugLevel)) + }) + + }) + +}) diff --git a/test/services/services_suite_test.go b/test/services/services_suite_test.go new file mode 100644 index 00000000000..39d3c582740 --- /dev/null +++ b/test/services/services_suite_test.go @@ -0,0 +1,14 @@ +package services_test + +import ( + "testing" + + "github.com/solo-io/go-utils/testutils" + + . "github.com/onsi/ginkgo/v2" +) + +func TestServices(t *testing.T) { + testutils.RegisterCommonFailHandlers() + RunSpecs(t, "Services Suite") +} diff --git a/test/testutils/env.go b/test/testutils/env.go index 887aedb3801..8932002a20d 100644 --- a/test/testutils/env.go +++ b/test/testutils/env.go @@ -50,6 +50,9 @@ const ( // VaultBinary is used in e2e tests to specify the path to the vault binary to use for the tests VaultBinary = "VAULT_BINARY" + + // ServiceLogLevel is used to set the log level for the test services. See services/logging.go for more details + ServiceLogLevel = "SERVICE_LOG_LEVEL" ) // ShouldTearDown returns true if any assets that were created before a test (for example Gloo being installed)