From 7586cea049ad2dc2a510fc9906f171299d216ce7 Mon Sep 17 00:00:00 2001 From: Blaine Gardner Date: Thu, 23 Sep 2021 10:56:42 -0600 Subject: [PATCH] core: create TRACE_INSECURE log level Create a new log level for Rook that is hidden from users. This is the most verbose log level, and it is the level developers would like to use to get debug logs that are important for debugging but that could leak senstivie information like credentials in production use. If a user sets their debug level to "TRACE", they will merely get "DEBUG" level logs. Only if they set "TRACE_INSECURE" will they get trace logs, and those are likely to include insecure information. Rook tries very hard not to leak sensitive information in logs even with verbose "DEBUG" logs. Resolves #8778 Signed-off-by: Blaine Gardner --- cluster/charts/rook-ceph/values.yaml | 2 +- .../kubernetes/ceph/operator-openshift.yaml | 2 +- .../examples/kubernetes/ceph/operator.yaml | 2 +- cmd/rook/rook/rook.go | 17 +----- pkg/clusterd/context.go | 4 -- pkg/daemon/ceph/client/config_test.go | 8 +-- pkg/operator/ceph/controller.go | 20 ++----- pkg/operator/ceph/object/admin.go | 6 +- pkg/util/logging.go | 54 ++++++++++++++++++ pkg/util/logging_test.go | 55 +++++++++++++++++++ 10 files changed, 125 insertions(+), 45 deletions(-) create mode 100644 pkg/util/logging.go create mode 100644 pkg/util/logging_test.go diff --git a/cluster/charts/rook-ceph/values.yaml b/cluster/charts/rook-ceph/values.yaml index 573d92c22..e7b3fd4f8 100644 --- a/cluster/charts/rook-ceph/values.yaml +++ b/cluster/charts/rook-ceph/values.yaml @@ -41,7 +41,7 @@ currentNamespaceOnly: false ## Annotations to be added to pod annotations: {} -## LogLevel can be set to: TRACE, DEBUG, INFO, NOTICE, WARNING, ERROR or CRITICAL +## The logging level for the operator: ERROR | WARNING | INFO | DEBUG logLevel: INFO ## If true, create & use RBAC resources diff --git a/cluster/examples/kubernetes/ceph/operator-openshift.yaml b/cluster/examples/kubernetes/ceph/operator-openshift.yaml index 512f0d17c..1fccd7299 100644 --- a/cluster/examples/kubernetes/ceph/operator-openshift.yaml +++ b/cluster/examples/kubernetes/ceph/operator-openshift.yaml @@ -100,7 +100,7 @@ metadata: # should be in the namespace of the operator namespace: rook-ceph # namespace:operator data: - # The logging level for the operator: INFO | DEBUG + # The logging level for the operator: ERROR | WARNING | INFO | DEBUG ROOK_LOG_LEVEL: "INFO" # Enable the CSI driver. diff --git a/cluster/examples/kubernetes/ceph/operator.yaml b/cluster/examples/kubernetes/ceph/operator.yaml index b95f4c387..04b27e1e4 100644 --- a/cluster/examples/kubernetes/ceph/operator.yaml +++ b/cluster/examples/kubernetes/ceph/operator.yaml @@ -22,7 +22,7 @@ metadata: # should be in the namespace of the operator namespace: rook-ceph # namespace:operator data: - # The logging level for the operator: INFO | DEBUG + # The logging level for the operator: ERROR | WARNING | INFO | DEBUG ROOK_LOG_LEVEL: "INFO" # Enable the CSI driver. diff --git a/cmd/rook/rook/rook.go b/cmd/rook/rook/rook.go index e2235213f..f9b584f81 100644 --- a/cmd/rook/rook/rook.go +++ b/cmd/rook/rook/rook.go @@ -28,6 +28,7 @@ import ( rookclient "github.com/rook/rook/pkg/client/clientset/versioned" "github.com/rook/rook/pkg/clusterd" "github.com/rook/rook/pkg/operator/k8sutil" + "github.com/rook/rook/pkg/util" "github.com/rook/rook/pkg/util/exec" "github.com/rook/rook/pkg/util/flags" "github.com/rook/rook/pkg/version" @@ -55,20 +56,15 @@ var ( logLevelRaw string operatorImage string serviceAccountName string - Cfg = &Config{} logger = capnslog.NewPackageLogger("github.com/rook/rook", "rookcmd") ) -type Config struct { - LogLevel capnslog.LogLevel -} - // Initialize the configuration parameters. The precedence from lowest to highest is: // 1) default value (at compilation) // 2) environment variables (upper case, replace - with _, and rook prefix. For example, discovery-url is ROOK_DISCOVERY_URL) // 3) command line parameter func init() { - RootCmd.PersistentFlags().StringVar(&logLevelRaw, "log-level", "INFO", "logging level for logging/tracing output (valid values: CRITICAL,ERROR,WARNING,NOTICE,INFO,DEBUG,TRACE)") + RootCmd.PersistentFlags().StringVar(&logLevelRaw, "log-level", "INFO", "logging level for logging/tracing output (valid values: ERROR,WARNING,INFO,DEBUG)") RootCmd.PersistentFlags().StringVar(&operatorImage, "operator-image", "", "Override the image url that the operator uses. The default is read from the operator pod.") RootCmd.PersistentFlags().StringVar(&serviceAccountName, "service-account", "", "Override the service account that the operator uses. The default is read from the operator pod.") @@ -79,13 +75,7 @@ func init() { // SetLogLevel set log level based on provided log option. func SetLogLevel() { - // parse given log level string then set up corresponding global logging level - ll, err := capnslog.ParseLevel(logLevelRaw) - if err != nil { - logger.Warningf("failed to set log level %s. %+v", logLevelRaw, err) - } - Cfg.LogLevel = ll - capnslog.SetGlobalLogLevel(Cfg.LogLevel) + util.SetGlobalLogLevel(logLevelRaw, logger) } // LogStartupInfo log the version number, arguments, and all final flag values (environment variable overrides have already been taken into account) @@ -103,7 +93,6 @@ func NewContext() *clusterd.Context { context := &clusterd.Context{ Executor: &exec.CommandExecutor{}, ConfigDir: k8sutil.DataDir, - LogLevel: Cfg.LogLevel, } // Try to read config from in-cluster env diff --git a/pkg/clusterd/context.go b/pkg/clusterd/context.go index f8c318478..70c625450 100644 --- a/pkg/clusterd/context.go +++ b/pkg/clusterd/context.go @@ -17,7 +17,6 @@ limitations under the License. package clusterd import ( - "github.com/coreos/pkg/capnslog" netclient "github.com/k8snetworkplumbingwg/network-attachment-definition-client/pkg/client/clientset/versioned/typed/k8s.cni.cncf.io/v1" rookclient "github.com/rook/rook/pkg/client/clientset/versioned" "github.com/rook/rook/pkg/util/exec" @@ -58,9 +57,6 @@ type Context struct { // The root configuration directory used by services ConfigDir string - // A value indicating the desired logging/tracing level - LogLevel capnslog.LogLevel - // The full path to a config file that can be used to override generated settings ConfigFileOverride string diff --git a/pkg/daemon/ceph/client/config_test.go b/pkg/daemon/ceph/client/config_test.go index 8a60614a8..7391a0e1a 100644 --- a/pkg/daemon/ceph/client/config_test.go +++ b/pkg/daemon/ceph/client/config_test.go @@ -29,7 +29,6 @@ import ( v1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" - "github.com/coreos/pkg/capnslog" "github.com/go-ini/ini" "github.com/rook/rook/pkg/clusterd" cephver "github.com/rook/rook/pkg/operator/ceph/version" @@ -49,9 +48,7 @@ func TestCreateDefaultCephConfig(t *testing.T) { } // start with INFO level logging - context := &clusterd.Context{ - LogLevel: capnslog.INFO, - } + context := &clusterd.Context{} cephConfig, err := CreateDefaultCephConfig(context, clusterInfo) if err != nil { @@ -59,9 +56,6 @@ func TestCreateDefaultCephConfig(t *testing.T) { } verifyConfig(t, cephConfig, clusterInfo, 0) - // now use DEBUG level logging - context.LogLevel = capnslog.DEBUG - cephConfig, err = CreateDefaultCephConfig(context, clusterInfo) if err != nil { t.Fatalf("failed to create default ceph config. %+v", err) diff --git a/pkg/operator/ceph/controller.go b/pkg/operator/ceph/controller.go index 5be6eb9dd..9a29db1bf 100644 --- a/pkg/operator/ceph/controller.go +++ b/pkg/operator/ceph/controller.go @@ -18,7 +18,6 @@ package operator import ( "context" - "strings" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -27,12 +26,12 @@ import ( "sigs.k8s.io/controller-runtime/pkg/reconcile" "sigs.k8s.io/controller-runtime/pkg/source" - "github.com/coreos/pkg/capnslog" "github.com/pkg/errors" "github.com/rook/rook/pkg/clusterd" opcontroller "github.com/rook/rook/pkg/operator/ceph/controller" "github.com/rook/rook/pkg/operator/discover" "github.com/rook/rook/pkg/operator/k8sutil" + "github.com/rook/rook/pkg/util" v1 "k8s.io/api/core/v1" kerrors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -127,10 +126,7 @@ func (r *ReconcileConfig) reconcile(request reconcile.Request) (reconcile.Result opcontroller.SetCephCommandsTimeout(r.config.Parameters) // Reconcile Operator's logging level - err = reconcileOperatorLogLevel(opConfig.Data) - if err != nil { - return opcontroller.ImmediateRetryResult, err - } + reconcileOperatorLogLevel(opConfig.Data) // Reconcile discovery daemon err = r.reconcileDiscoveryDaemon() @@ -145,15 +141,9 @@ func (r *ReconcileConfig) reconcile(request reconcile.Request) (reconcile.Result return reconcile.Result{}, nil } -func reconcileOperatorLogLevel(data map[string]string) error { - rookLogLevel := k8sutil.GetValue(data, "ROOK_LOG_LEVEL", "INFO") - logLevel, err := capnslog.ParseLevel(strings.ToUpper(rookLogLevel)) - if err != nil { - return errors.Wrapf(err, "failed to load ROOK_LOG_LEVEL %q.", rookLogLevel) - } - - capnslog.SetGlobalLogLevel(logLevel) - return nil +func reconcileOperatorLogLevel(data map[string]string) { + rookLogLevel := k8sutil.GetValue(data, "ROOK_LOG_LEVEL", util.DefaultLogLevel.String()) + util.SetGlobalLogLevel(rookLogLevel, logger) } func (r *ReconcileConfig) reconcileDiscoveryDaemon() error { diff --git a/pkg/operator/ceph/object/admin.go b/pkg/operator/ceph/object/admin.go index 1c60da838..dbc271244 100644 --- a/pkg/operator/ceph/object/admin.go +++ b/pkg/operator/ceph/object/admin.go @@ -72,7 +72,8 @@ func (c *debugHTTPClient) Do(req *http.Request) (*http.Response, error) { if err != nil { return nil, err } - c.logger.Debugf("\n%s\n", string(dump)) + // this can leak credentials for making requests + c.logger.Tracef("\n%s\n", string(dump)) resp, err := c.client.Do(req) if err != nil { @@ -84,7 +85,8 @@ func (c *debugHTTPClient) Do(req *http.Request) (*http.Response, error) { if err != nil { return nil, err } - c.logger.Debugf("\n%s\n", string(dump)) + // this can leak any sensitive info like credentials in the response + c.logger.Tracef("\n%s\n", string(dump)) return resp, nil } diff --git a/pkg/util/logging.go b/pkg/util/logging.go new file mode 100644 index 000000000..a3f68c4c9 --- /dev/null +++ b/pkg/util/logging.go @@ -0,0 +1,54 @@ +/* +Copyright 2021 The Rook Authors. All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package util + +import ( + "github.com/coreos/pkg/capnslog" +) + +const DefaultLogLevel = capnslog.INFO + +func SetGlobalLogLevel(userLogLevelSelection string, logger *capnslog.PackageLogger) { + // capnslog supports trace level logging, but in Rook we want to treat trace logging as insecure + // and block users from finding the value in most circumstances. If they request "TRACE" level + // logging, just output debug logs. + if userLogLevelSelection == "TRACE" { + userLogLevelSelection = "DEBUG" + } + // only if users give the super secret "TRACE_INSECURE" log level will they get real trace + // logging, which might leak credentials and other insecure nasties into their logs. + if userLogLevelSelection == "TRACE_INSECURE" { + userLogLevelSelection = "TRACE" + } + + // parse given log level string then set up corresponding global logging level + logLevel, err := capnslog.ParseLevel(userLogLevelSelection) + if err != nil { + logger.Errorf("failed to parse log level %q. defaulting to %q. %v", userLogLevelSelection, DefaultLogLevel.String(), err) + logLevel = DefaultLogLevel + } + + // If capnslog changes in the future to allow a more verbose level than TRACE and a user somehow + // enters it, then reject that log level, and revert to default. This can't be unit tested, but + // it'll probably never happen in the wild anyway, just here for safety. + if logLevel > capnslog.TRACE { + logger.Infof("not setting log level %q more verbose than TRACE. reverting to default %q", logLevel.String(), DefaultLogLevel.String()) + logLevel = DefaultLogLevel + } + + capnslog.SetGlobalLogLevel(logLevel) +} diff --git a/pkg/util/logging_test.go b/pkg/util/logging_test.go new file mode 100644 index 000000000..727baecab --- /dev/null +++ b/pkg/util/logging_test.go @@ -0,0 +1,55 @@ +/* +Copyright 2021 The Rook Authors. All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package util + +import ( + "testing" + + "github.com/coreos/pkg/capnslog" + "github.com/stretchr/testify/assert" +) + +func TestSetGlobalLogLevel(t *testing.T) { + logger := capnslog.NewPackageLogger("github.com/rook/rook", "pkg/util/logging_test") + + tests := []struct { + name string + userLogLevelSelection string + desiredLogLevel capnslog.LogLevel + }{ + {"INFO is supported", "INFO", capnslog.INFO}, + {"DEBUG is supported", "DEBUG", capnslog.DEBUG}, + {"WARNING is supported", "WARNING", capnslog.WARNING}, + {"ERROR is supported", "ERROR", capnslog.ERROR}, + {"TRACE will be turned into DEBUG", "TRACE", capnslog.DEBUG}, + {"TRACE_INSECURE will be turned into TRACE", "TRACE_INSECURE", capnslog.TRACE}, + {"an invalid input will be turned into INFO", "INVALID", capnslog.INFO}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + SetGlobalLogLevel(tt.userLogLevelSelection, logger) + t.Logf("asserting that log level %d can be shown", tt.desiredLogLevel) + assert.True(t, logger.LevelAt(tt.desiredLogLevel)) + // logger.LevelAt will only tell whether the logger will output logs at the desired log + // level, but it won't actually tell what the log level is specifically. To make sure we + // won't output MORE logs, we should check for the next more verbose log level also. + nextMostVerboseLevel := tt.desiredLogLevel + 1 + t.Logf("asserting that log level %d can NOT be shown", nextMostVerboseLevel) + assert.False(t, logger.LevelAt(nextMostVerboseLevel)) + }) + } +}