djpbessems/ContainerImage.Pinniped
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge pull request #1145 from enj/enj/f/json_logs

Browse Source 
Switch to go.uber.org/zap for JSON formatted logging
This commit is contained in:
Mo Khan 2022-05-24 13:15:22 -04:00 committed by GitHub
commit 75a32ae243
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
63 changed files with 2033 additions and 470 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

11
cmd/pinniped-server/main.go
View File

@ -8,22 +8,23 @@
package main
import (
"fmt"
"os"
"path/filepath"
"k8s.io/apimachinery/pkg/util/sets"
"k8s.io/klog/v2"
concierge "go.pinniped.dev/internal/concierge/server"
// this side effect import ensures that we use fipsonly crypto in fips_strict mode.
concierge "go.pinniped.dev/internal/concierge/server"
_ "go.pinniped.dev/internal/crypto/ptls"
lua "go.pinniped.dev/internal/localuserauthenticator"
"go.pinniped.dev/internal/plog"
supervisor "go.pinniped.dev/internal/supervisor/server"
)
// nolint: gochecknoglobals // these are swapped during unit tests.
var (
fail = klog.Fatalf
fail = plog.Fatal
subcommands = map[string]func(){
"pinniped-concierge": concierge.Main,
"pinniped-supervisor": supervisor.Main,
@ -33,11 +34,11 @@ var (
func main() {
if len(os.Args) == 0 {
fail("missing os.Args")
fail(fmt.Errorf("missing os.Args"))
}
binary := filepath.Base(os.Args[0])
if subcommands[binary] == nil {
fail("must be invoked as one of %v, not %q", sets.StringKeySet(subcommands).List(), binary)
fail(fmt.Errorf("must be invoked as one of %v, not %q", sets.StringKeySet(subcommands).List(), binary))
}
subcommands[binary]()
}

7
cmd/pinniped-server/main_test.go
View File

@ -43,8 +43,11 @@ func TestEntrypoint(t *testing.T) {
var logBuf bytes.Buffer
testLog := log.New(&logBuf, "", 0)
exited := "exiting via fatal"
fail = func(format string, v ...interface{}) {
testLog.Printf(format, v...)
fail = func(err error, keysAndValues ...interface{}) {
testLog.Print(err)
if len(keysAndValues) > 0 {
testLog.Print(keysAndValues...)
}
panic(exited)
}

31
cmd/pinniped/cmd/kubeconfig.go
View File

@ -11,7 +11,6 @@ import (
"fmt"
"io"
"io/ioutil"
"log"
"net/http"
"os"
"strconv"
@ -19,8 +18,6 @@ import (
"time"
"github.com/coreos/go-oidc/v3/oidc"
"github.com/go-logr/logr"
"github.com/go-logr/stdr"
"github.com/spf13/cobra"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
clientauthenticationv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1"
@ -34,19 +31,20 @@ import (
conciergeclientset "go.pinniped.dev/generated/latest/client/concierge/clientset/versioned"
"go.pinniped.dev/internal/groupsuffix"
"go.pinniped.dev/internal/net/phttp"
"go.pinniped.dev/internal/plog"
)
type kubeconfigDeps struct {
getPathToSelf func() (string, error)
getClientset getConciergeClientsetFunc
log logr.Logger
log plog.MinLogger
}
func kubeconfigRealDeps() kubeconfigDeps {
return kubeconfigDeps{
getPathToSelf: os.Executable,
getClientset: getRealConciergeClientset,
log: stdr.New(log.New(os.Stderr, "", 0)),
log: plog.New(),
}
}
@ -175,6 +173,11 @@ func runGetKubeconfig(ctx context.Context, out io.Writer, deps kubeconfigDeps, f
ctx, cancel := context.WithTimeout(ctx, flags.timeout)
defer cancel()
// the log statements in this file assume that Info logs are unconditionally printed so we set the global level to info
if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, plog.LogSpec{Level: plog.LevelInfo, Format: plog.FormatCLI}); err != nil {
return err
}
// Validate api group suffix and immediately return an error if it is invalid.
if err := groupsuffix.Validate(flags.concierge.apiGroupSuffix); err != nil {
return fmt.Errorf("invalid API group suffix: %w", err)
@ -398,7 +401,7 @@ func waitForCredentialIssuer(ctx context.Context, clientset conciergeclientset.I
return credentialIssuer, nil
}
func discoverConciergeParams(credentialIssuer *configv1alpha1.CredentialIssuer, flags *getKubeconfigParams, v1Cluster *clientcmdapi.Cluster, log logr.Logger) error {
func discoverConciergeParams(credentialIssuer *configv1alpha1.CredentialIssuer, flags *getKubeconfigParams, v1Cluster *clientcmdapi.Cluster, log plog.MinLogger) error {
// Autodiscover the --concierge-mode.
frontend, err := getConciergeFrontend(credentialIssuer, flags.concierge.mode)
if err != nil {
@ -446,7 +449,7 @@ func discoverConciergeParams(credentialIssuer *configv1alpha1.CredentialIssuer,
return nil
}
func logStrategies(credentialIssuer *configv1alpha1.CredentialIssuer, log logr.Logger) {
func logStrategies(credentialIssuer *configv1alpha1.CredentialIssuer, log plog.MinLogger) {
for _, strategy := range credentialIssuer.Status.Strategies {
log.Info("found CredentialIssuer strategy",
"type", strategy.Type,
@ -457,7 +460,7 @@ func logStrategies(credentialIssuer *configv1alpha1.CredentialIssuer, log logr.L
}
}
func discoverAuthenticatorParams(authenticator metav1.Object, flags *getKubeconfigParams, log logr.Logger) error {
func discoverAuthenticatorParams(authenticator metav1.Object, flags *getKubeconfigParams, log plog.MinLogger) error {
switch auth := authenticator.(type) {
case *conciergev1alpha1.WebhookAuthenticator:
// If the --concierge-authenticator-type/--concierge-authenticator-name flags were not set explicitly, set
@ -556,7 +559,7 @@ func newExecKubeconfig(cluster *clientcmdapi.Cluster, execConfig *clientcmdapi.E
}
}
func lookupCredentialIssuer(clientset conciergeclientset.Interface, name string, log logr.Logger) (*configv1alpha1.CredentialIssuer, error) {
func lookupCredentialIssuer(clientset conciergeclientset.Interface, name string, log plog.MinLogger) (*configv1alpha1.CredentialIssuer, error) {
ctx, cancelFunc := context.WithTimeout(context.Background(), time.Second*20)
defer cancelFunc()
@ -582,7 +585,7 @@ func lookupCredentialIssuer(clientset conciergeclientset.Interface, name string,
return result, nil
}
func lookupAuthenticator(clientset conciergeclientset.Interface, authType, authName string, log logr.Logger) (metav1.Object, error) {
func lookupAuthenticator(clientset conciergeclientset.Interface, authType, authName string, log plog.MinLogger) (metav1.Object, error) {
ctx, cancelFunc := context.WithTimeout(context.Background(), time.Second*20)
defer cancelFunc()
@ -643,7 +646,7 @@ func writeConfigAsYAML(out io.Writer, config clientcmdapi.Config) error {
return nil
}
func validateKubeconfig(ctx context.Context, flags getKubeconfigParams, kubeconfig clientcmdapi.Config, log logr.Logger) error {
func validateKubeconfig(ctx context.Context, flags getKubeconfigParams, kubeconfig clientcmdapi.Config, log plog.MinLogger) error {
if flags.skipValidate {
return nil
}
@ -706,7 +709,7 @@ func validateKubeconfig(ctx context.Context, flags getKubeconfigParams, kubeconf
log.Info("validated connection to the cluster", "attempts", attempts)
return nil
}
log.Error(err, "could not connect to cluster, retrying...", "attempts", attempts, "remaining", time.Until(deadline).Round(time.Second).String())
log.Info("could not connect to cluster, retrying...", "error", err, "attempts", attempts, "remaining", time.Until(deadline).Round(time.Second).String())
}
}
}
@ -726,7 +729,7 @@ func hasPendingStrategy(credentialIssuer *configv1alpha1.CredentialIssuer) bool
return false
}
func discoverSupervisorUpstreamIDP(ctx context.Context, flags *getKubeconfigParams, log logr.Logger) error {
func discoverSupervisorUpstreamIDP(ctx context.Context, flags *getKubeconfigParams, log plog.MinLogger) error {
httpClient, err := newDiscoveryHTTPClient(flags.oidc.caBundle)
if err != nil {
return err
@ -898,7 +901,7 @@ func selectUpstreamIDPNameAndType(pinnipedIDPs []idpdiscoveryv1alpha1.PinnipedID
}
}
func selectUpstreamIDPFlow(discoveredIDPFlows []idpdiscoveryv1alpha1.IDPFlow, selectedIDPName string, selectedIDPType idpdiscoveryv1alpha1.IDPType, specifiedFlow string, log logr.Logger) (idpdiscoveryv1alpha1.IDPFlow, error) {
func selectUpstreamIDPFlow(discoveredIDPFlows []idpdiscoveryv1alpha1.IDPFlow, selectedIDPName string, selectedIDPType idpdiscoveryv1alpha1.IDPType, specifiedFlow string, log plog.MinLogger) (idpdiscoveryv1alpha1.IDPFlow, error) {
switch {
case len(discoveredIDPFlows) == 0:
// No flows listed by discovery means that we are talking to an old Supervisor from before this feature existed.

17
cmd/pinniped/cmd/login_oidc.go
View File

@ -20,7 +20,6 @@ import (
"github.com/spf13/cobra"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1"
"k8s.io/klog/v2/klogr"
idpdiscoveryv1alpha1 "go.pinniped.dev/generated/latest/apis/supervisor/idpdiscovery/v1alpha1"
"go.pinniped.dev/internal/execcredcache"
@ -125,7 +124,7 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command {
}
func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error { //nolint:funlen
pLogger, err := SetLogLevel(deps.lookupEnv)
pLogger, err := SetLogLevel(cmd.Context(), deps.lookupEnv)
if err != nil {
plog.WarningErr("Received error while setting log level", err)
}
@ -133,11 +132,11 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin
// Initialize the session cache.
var sessionOptions []filesession.Option
// If the hidden --debug-session-cache option is passed, log all the errors from the session cache with klog.
// If the hidden --debug-session-cache option is passed, log all the errors from the session cache.
if flags.debugSessionCache {
logger := klogr.New().WithName("session")
logger := plog.WithName("session")
sessionOptions = append(sessionOptions, filesession.WithErrorReporter(func(err error) {
logger.Error(err, "error during session cache operation")
logger.Error("error during session cache operation", err)
}))
}
sessionCache := filesession.New(flags.sessionCachePath, sessionOptions...)
@ -145,7 +144,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin
// Initialize the login handler.
opts := []oidcclient.Option{
oidcclient.WithContext(cmd.Context()),
oidcclient.WithLogger(klogr.New()),
oidcclient.WithLogger(plog.Logr()), // nolint: staticcheck // old code with lots of log statements
oidcclient.WithScopes(flags.scopes),
oidcclient.WithSessionCache(sessionCache),
}
@ -326,15 +325,15 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential {
return &cred
}
func SetLogLevel(lookupEnv func(string) (string, bool)) (plog.Logger, error) {
func SetLogLevel(ctx context.Context, lookupEnv func(string) (string, bool)) (plog.Logger, error) {
debug, _ := lookupEnv("PINNIPED_DEBUG")
if debug == "true" {
err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug)
err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, plog.LogSpec{Level: plog.LevelDebug, Format: plog.FormatCLI})
if err != nil {
return nil, err
}
}
logger := plog.New("Pinniped login: ")
logger := plog.New().WithName("pinniped-login")
return logger, nil
}

40
cmd/pinniped/cmd/login_oidc_test.go
View File

@ -10,18 +10,20 @@ import (
"fmt"
"io/ioutil"
"path/filepath"
"strings"
"testing"
"time"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1"
"k8s.io/klog/v2"
clocktesting "k8s.io/utils/clock/testing"
"go.pinniped.dev/internal/certauthority"
"go.pinniped.dev/internal/here"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
"go.pinniped.dev/internal/testutil/testlogger"
"go.pinniped.dev/pkg/conciergeclient"
"go.pinniped.dev/pkg/oidcclient"
"go.pinniped.dev/pkg/oidcclient/oidctypes"
@ -38,6 +40,10 @@ func TestLoginOIDCCommand(t *testing.T) {
time1 := time.Date(3020, 10, 12, 13, 14, 15, 16, time.UTC)
now, err := time.Parse(time.RFC3339Nano, "2028-10-11T23:37:26.953313745Z")
require.NoError(t, err)
nowStr := now.Local().Format(time.RFC1123)
tests := []struct {
name string
args []string
@ -342,8 +348,8 @@ func TestLoginOIDCCommand(t *testing.T) {
wantOptionsCount: 4,
wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{"interactive":false},"status":{"expirationTimestamp":"3020-10-12T13:14:15Z","token":"test-id-token"}}` + "\n",
wantLogs: []string{
"\"level\"=0 \"msg\"=\"Pinniped login: Performing OIDC login\" \"client id\"=\"test-client-id\" \"issuer\"=\"test-issuer\"",
"\"level\"=0 \"msg\"=\"Pinniped login: No concierge configured, skipping token credential exchange\"",
nowStr + ` pinniped-login cmd/login_oidc.go:222 Performing OIDC login {"issuer": "test-issuer", "client id": "test-client-id"}`,
nowStr + ` pinniped-login cmd/login_oidc.go:242 No concierge configured, skipping token credential exchange`,
},
},
{
@ -372,18 +378,20 @@ func TestLoginOIDCCommand(t *testing.T) {
wantOptionsCount: 11,
wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{"interactive":false},"status":{"token":"exchanged-token"}}` + "\n",
wantLogs: []string{
"\"level\"=0 \"msg\"=\"Pinniped login: Performing OIDC login\" \"client id\"=\"test-client-id\" \"issuer\"=\"test-issuer\"",
"\"level\"=0 \"msg\"=\"Pinniped login: Exchanging token for cluster credential\" \"authenticator name\"=\"test-authenticator\" \"authenticator type\"=\"webhook\" \"endpoint\"=\"https://127.0.0.1:1234/\"",
"\"level\"=0 \"msg\"=\"Pinniped login: Successfully exchanged token for cluster credential.\"",
"\"level\"=0 \"msg\"=\"Pinniped login: caching cluster credential for future use.\"",
nowStr + ` pinniped-login cmd/login_oidc.go:222 Performing OIDC login {"issuer": "test-issuer", "client id": "test-client-id"}`,
nowStr + ` pinniped-login cmd/login_oidc.go:232 Exchanging token for cluster credential {"endpoint": "https://127.0.0.1:1234/", "authenticator type": "webhook", "authenticator name": "test-authenticator"}`,
nowStr + ` pinniped-login cmd/login_oidc.go:240 Successfully exchanged token for cluster credential.`,
nowStr + ` pinniped-login cmd/login_oidc.go:247 caching cluster credential for future use.`,
},
},
}
for _, tt := range tests {
tt := tt
t.Run(tt.name, func(t *testing.T) {
testLogger := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements
klog.SetLogger(testLogger.Logger)
var buf bytes.Buffer
fakeClock := clocktesting.NewFakeClock(now)
ctx := plog.TestZapOverrides(context.Background(), t, &buf, nil, zap.WithClock(plog.ZapClock(fakeClock)))
var (
gotOptions []oidcclient.Option
)
@ -428,7 +436,7 @@ func TestLoginOIDCCommand(t *testing.T) {
cmd.SetOut(&stdout)
cmd.SetErr(&stderr)
cmd.SetArgs(tt.args)
err := cmd.Execute()
err = cmd.ExecuteContext(ctx)
if tt.wantError {
require.Error(t, err)
} else {
@ -438,7 +446,15 @@ func TestLoginOIDCCommand(t *testing.T) {
require.Equal(t, tt.wantStderr, stderr.String(), "unexpected stderr")
require.Len(t, gotOptions, tt.wantOptionsCount)
require.Equal(t, tt.wantLogs, testLogger.Lines())
require.Equal(t, tt.wantLogs, logLines(buf.String()))
})
}
}
func logLines(logs string) []string {
if len(logs) == 0 {
return nil
}
return strings.Split(strings.TrimSpace(logs), "\n")
}

8
cmd/pinniped/cmd/login_static.go
View File

@ -7,7 +7,6 @@ import (
"context"
"encoding/json"
"fmt"
"io"
"os"
"path/filepath"
"time"
@ -75,7 +74,7 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command {
cmd.Flags().StringVar(&flags.conciergeAPIGroupSuffix, "concierge-api-group-suffix", groupsuffix.PinnipedDefaultSuffix, "Concierge API group suffix")
cmd.Flags().StringVar(&flags.credentialCachePath, "credential-cache", filepath.Join(mustGetConfigDir(), "credentials.yaml"), "Path to cluster-specific credentials cache (\"\" disables the cache)")
cmd.RunE = func(cmd *cobra.Command, args []string) error { return runStaticLogin(cmd.OutOrStdout(), deps, flags) }
cmd.RunE = func(cmd *cobra.Command, args []string) error { return runStaticLogin(cmd, deps, flags) }
mustMarkDeprecated(cmd, "concierge-namespace", "not needed anymore")
mustMarkHidden(cmd, "concierge-namespace")
@ -83,8 +82,9 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command {
return cmd
}
func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error {
pLogger, err := SetLogLevel(deps.lookupEnv)
func runStaticLogin(cmd *cobra.Command, deps staticLoginDeps, flags staticLoginParams) error {
out := cmd.OutOrStdout()
pLogger, err := SetLogLevel(cmd.Context(), deps.lookupEnv)
if err != nil {
plog.WarningErr("Received error while setting log level", err)
}

25
cmd/pinniped/cmd/login_static_test.go
View File

@ -12,16 +12,15 @@ import (
"testing"
"time"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/testutil/testlogger"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1"
clocktesting "k8s.io/utils/clock/testing"
"go.pinniped.dev/internal/certauthority"
"go.pinniped.dev/internal/here"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
"go.pinniped.dev/pkg/conciergeclient"
)
@ -35,6 +34,10 @@ func TestLoginStaticCommand(t *testing.T) {
testCABundlePath := filepath.Join(tmpdir, "testca.pem")
require.NoError(t, ioutil.WriteFile(testCABundlePath, testCA.Bundle(), 0600))
now, err := time.Parse(time.RFC3339Nano, "2038-12-07T23:37:26.953313745Z")
require.NoError(t, err)
nowStr := now.Local().Format(time.RFC1123)
tests := []struct {
name string
args []string
@ -136,7 +139,9 @@ func TestLoginStaticCommand(t *testing.T) {
wantStderr: here.Doc(`
Error: could not complete Concierge credential exchange: some concierge error
`),
wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped login: exchanging static token for cluster credential\" \"authenticator name\"=\"test-authenticator\" \"authenticator type\"=\"webhook\" \"endpoint\"=\"https://127.0.0.1/\""},
wantLogs: []string{
nowStr + ` pinniped-login cmd/login_static.go:147 exchanging static token for cluster credential {"endpoint": "https://127.0.0.1/", "authenticator type": "webhook", "authenticator name": "test-authenticator"}`,
},
},
{
name: "invalid API group suffix",
@ -165,8 +170,10 @@ func TestLoginStaticCommand(t *testing.T) {
for _, tt := range tests {
tt := tt
t.Run(tt.name, func(t *testing.T) {
testLogger := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements
klog.SetLogger(testLogger.Logger)
var buf bytes.Buffer
fakeClock := clocktesting.NewFakeClock(now)
ctx := plog.TestZapOverrides(context.Background(), t, &buf, nil, zap.WithClock(plog.ZapClock(fakeClock)))
cmd := staticLoginCommand(staticLoginDeps{
lookupEnv: func(s string) (string, bool) {
v, ok := tt.env[s]
@ -194,7 +201,7 @@ func TestLoginStaticCommand(t *testing.T) {
cmd.SetOut(&stdout)
cmd.SetErr(&stderr)
cmd.SetArgs(tt.args)
err := cmd.Execute()
err := cmd.ExecuteContext(ctx)
if tt.wantError {
require.Error(t, err)
} else {
@ -203,7 +210,7 @@ func TestLoginStaticCommand(t *testing.T) {
require.Equal(t, tt.wantStdout, stdout.String(), "unexpected stdout")
require.Equal(t, tt.wantStderr, stderr.String(), "unexpected stderr")
require.Equal(t, tt.wantLogs, testLogger.Lines())
require.Equal(t, tt.wantLogs, logLines(buf.String()))
})
}
}

13
cmd/pinniped/cmd/root.go
View File

@ -4,9 +4,11 @@
package cmd
import (
"os"
"context"
"github.com/spf13/cobra"
"go.pinniped.dev/internal/plog"
)
// nolint: gochecknoglobals
@ -19,8 +21,11 @@ var rootCmd = &cobra.Command{
// Execute adds all child commands to the root command and sets flags appropriately.
// This is called by main.main(). It only needs to happen once to the rootCmd.
func Execute() {
if err := rootCmd.Execute(); err != nil {
os.Exit(1)
func Execute() error {
defer plog.Setup()()
// the context does not matter here because it is unused when CLI formatting is provided
if err := plog.ValidateAndSetLogLevelAndFormatGlobally(context.Background(), plog.LogSpec{Format: plog.FormatCLI}); err != nil {
return err
}
return rootCmd.Execute()
}

4
cmd/pinniped/main.go
View File

@ -21,5 +21,7 @@ func init() {
}
func main() {
cmd.Execute()
if err := cmd.Execute(); err != nil {
os.Exit(1)
}
}

8
deploy/concierge/deployment.yaml
View File

@ -86,8 +86,14 @@ data:
imagePullSecrets:
- image-pull-secret
(@ end @)
(@ if data.values.log_level or data.values.deprecated_log_format: @)
log:
(@ if data.values.log_level: @)
logLevel: (@= getAndValidateLogLevel() @)
level: (@= getAndValidateLogLevel() @)
(@ end @)
(@ if data.values.deprecated_log_format: @)
format: (@= data.values.deprecated_log_format @)
(@ end @)
(@ end @)
---
#@ if data.values.image_pull_dockerconfigjson and data.values.image_pull_dockerconfigjson != "":

4
deploy/concierge/values.yaml
View File

@ -54,6 +54,10 @@ api_serving_certificate_renew_before_seconds: 2160000
#! Specify the verbosity of logging: info ("nice to know" information), debug (developer
#! information), trace (timing information), all (kitchen sink).
log_level: #! By default, when this value is left unset, only warnings and errors are printed. There is no way to suppress warning and error logs.
#! Specify the format of logging: json (for machine parsable logs) and text (for legacy klog formatted logs).
#! By default, when this value is left unset, logs are formatted in json.
#! This configuration is deprecated and will be removed in a future release at which point logs will always be formatted as json.
deprecated_log_format:
run_as_user: 65532 #! run_as_user specifies the user ID that will own the process, see the Dockerfile for the reasoning behind this choice
run_as_group: 65532 #! run_as_group specifies the group ID that will own the process, see the Dockerfile for the reasoning behind this choice

8
deploy/supervisor/helpers.lib.yaml
View File

@ -54,8 +54,14 @@ _: #@ template.replace(data.values.custom_labels)
#@ "labels": labels(),
#@ "insecureAcceptExternalUnencryptedHttpRequests": data.values.deprecated_insecure_accept_external_unencrypted_http_requests
#@ }
#@ if data.values.log_level or data.values.deprecated_log_format:
#@ config["log"] = {}
#@ end
#@ if data.values.log_level:
#@ config["logLevel"] = getAndValidateLogLevel()
#@ config["log"]["level"] = getAndValidateLogLevel()
#@ end
#@ if data.values.deprecated_log_format:
#@ config["log"]["format"] = data.values.deprecated_log_format
#@ end
#@ if data.values.endpoints:
#@ config["endpoints"] = data.values.endpoints

4
deploy/supervisor/values.yaml
View File

@ -57,6 +57,10 @@ service_loadbalancer_ip: #! e.g. 1.2.3.4
#! Specify the verbosity of logging: info ("nice to know" information), debug (developer information), trace (timing information),
#! or all (kitchen sink). Do not use trace or all on production systems, as credentials may get logged.
log_level: #! By default, when this value is left unset, only warnings and errors are printed. There is no way to suppress warning and error logs.
#! Specify the format of logging: json (for machine parsable logs) and text (for legacy klog formatted logs).
#! By default, when this value is left unset, logs are formatted in json.
#! This configuration is deprecated and will be removed in a future release at which point logs will always be formatted as json.
deprecated_log_format:
run_as_user: 65532 #! run_as_user specifies the user ID that will own the process, see the Dockerfile for the reasoning behind this choice
run_as_group: 65532 #! run_as_group specifies the group ID that will own the process, see the Dockerfile for the reasoning behind this choice

3
go.mod
View File

@ -45,6 +45,7 @@ require (
github.com/go-ldap/ldap/v3 v3.4.3
github.com/go-logr/logr v1.2.3
github.com/go-logr/stdr v1.2.2
github.com/go-logr/zapr v1.2.3
github.com/gofrs/flock v0.8.1
github.com/golang/mock v1.6.0
github.com/google/go-cmp v0.5.8
@ -64,6 +65,7 @@ require (
github.com/stretchr/testify v1.7.1
github.com/tdewolff/minify/v2 v2.11.2
go.uber.org/atomic v1.9.0
go.uber.org/zap v1.21.0
golang.org/x/crypto v0.0.0-20220427172511-eb4f295cb31f
golang.org/x/net v0.0.0-20220425223048-2871e0cb64e4
golang.org/x/oauth2 v0.0.0-20220411215720-9780585627b5
@ -168,7 +170,6 @@ require (
go.opentelemetry.io/otel/trace v1.6.3 // indirect
go.opentelemetry.io/proto/otlp v0.15.0 // indirect
go.uber.org/multierr v1.8.0 // indirect
go.uber.org/zap v1.21.0 // indirect
golang.org/x/mod v0.6.0-dev.0.20220106191415-9b9b3d81d5e3 // indirect
golang.org/x/sys v0.0.0-20220422013727-9388b58f7150 // indirect
golang.org/x/time v0.0.0-20220411224347-583f2d630306 // indirect

2
go.sum
View File

@ -299,6 +299,8 @@ github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbV
github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
github.com/go-logr/zapr v1.2.0/go.mod h1:Qa4Bsj2Vb+FAVeAKsLD8RLQ+YRJB8YDmOAKxaBQf7Ro=
github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
github.com/go-logr/zapr v1.2.3/go.mod h1:eIauM6P8qSvTw5o2ez6UEAfGjQKrxQTl5EoK+Qa2oG4=
github.com/go-openapi/analysis v0.0.0-20180825180245-b006789cd277/go.mod h1:k70tL6pCuVxPJOHXQ+wIac1FUrvNkHolPie/cLEU6hI=
github.com/go-openapi/analysis v0.17.0/go.mod h1:IowGgpVeD0vNm45So8nr+IcQ3pxVtpRoBWb8PVZO0ik=
github.com/go-openapi/analysis v0.18.0/go.mod h1:IowGgpVeD0vNm45So8nr+IcQ3pxVtpRoBWb8PVZO0ik=

22
internal/concierge/server/server.go
View File

@ -15,12 +15,11 @@ import (
"k8s.io/apimachinery/pkg/runtime"
"k8s.io/apimachinery/pkg/runtime/schema"
"k8s.io/apimachinery/pkg/runtime/serializer"
apimachineryversion "k8s.io/apimachinery/pkg/version"
genericapiserver "k8s.io/apiserver/pkg/server"
genericoptions "k8s.io/apiserver/pkg/server/options"
"k8s.io/client-go/pkg/version"
"k8s.io/client-go/rest"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/certauthority/dynamiccertauthority"
"go.pinniped.dev/internal/concierge/apiserver"
@ -35,6 +34,7 @@ import (
"go.pinniped.dev/internal/here"
"go.pinniped.dev/internal/issuer"
"go.pinniped.dev/internal/kubeclient"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/registry/credentialrequest"
)
@ -100,7 +100,7 @@ func addCommandlineFlagsToCommand(cmd *cobra.Command, app *App) {
// Boot the aggregated API server, which will in turn boot the controllers.
func (a *App) runServer(ctx context.Context) error {
// Read the server config file.
cfg, err := concierge.FromPath(a.configPath)
cfg, err := concierge.FromPath(ctx, a.configPath)
if err != nil {
return fmt.Errorf("could not load config: %w", err)
}
@ -250,16 +250,20 @@ func getAggregatedAPIServerConfig(
return apiServerConfig, nil
}
func main() error { // return an error instead of klog.Fatal to allow defer statements to run
logs.InitLogs()
defer logs.FlushLogs()
func main() error { // return an error instead of plog.Fatal to allow defer statements to run
defer plog.Setup()()
// Dump out the time since compile (mostly useful for benchmarking our local development cycle latency).
var timeSinceCompile time.Duration
if buildDate, err := time.Parse(time.RFC3339, version.Get().BuildDate); err == nil {
timeSinceCompile = time.Since(buildDate).Round(time.Second)
}
klog.Infof("Running %s at %#v (%s since build)", rest.DefaultKubernetesUserAgent(), version.Get(), timeSinceCompile)
plog.Always("Running concierge",
"user-agent", rest.DefaultKubernetesUserAgent(),
"version", versionInfo(version.Get()),
"time-since-build", timeSinceCompile,
)
ctx := genericapiserver.SetupSignalContext()
@ -268,6 +272,8 @@ func main() error { // return an error instead of klog.Fatal to allow defer stat
func Main() {
if err := main(); err != nil {
klog.Fatal(err)
plog.Fatal(err)
}
}
type versionInfo apimachineryversion.Info // hide .String() method from plog

6
internal/config/concierge/config.go
View File

@ -6,6 +6,7 @@
package concierge
import (
"context"
"fmt"
"io/ioutil"
"strings"
@ -41,7 +42,7 @@ const (
// Note! The Config file should contain base64-encoded WebhookCABundle data.
// This function will decode that base64-encoded data to PEM bytes to be stored
// in the Config.
func FromPath(path string) (*Config, error) {
func FromPath(ctx context.Context, path string) (*Config, error) {
data, err := ioutil.ReadFile(path)
if err != nil {
return nil, fmt.Errorf("read file: %w", err)
@ -78,7 +79,8 @@ func FromPath(path string) (*Config, error) {
return nil, fmt.Errorf("validate names: %w", err)
}
if err := plog.ValidateAndSetLogLevelGlobally(config.LogLevel); err != nil {
plog.MaybeSetDeprecatedLogLevel(config.LogLevel, &config.Log)
if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, config.Log); err != nil {
return nil, fmt.Errorf("validate log level: %w", err)
}

186
internal/config/concierge/config_test.go
View File

@ -4,6 +4,7 @@
package concierge
import (
"context"
"io/ioutil"
"os"
"testing"
@ -90,9 +91,186 @@ func TestFromPath(t *testing.T) {
Image: pointer.StringPtr("kube-cert-agent-image"),
ImagePullSecrets: []string{"kube-cert-agent-image-pull-secret"},
},
LogLevel: plog.LevelDebug,
LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelDebug),
Log: plog.LogSpec{
Level: plog.LevelDebug,
},
},
},
{
name: "Fully filled out new log struct",
yaml: here.Doc(`
---
discovery:
url: https://some.discovery/url
api:
servingCertificate:
durationSeconds: 3600
renewBeforeSeconds: 2400
apiGroupSuffix: some.suffix.com
aggregatedAPIServerPort: 12345
impersonationProxyServerPort: 4242
names:
servingCertificateSecret: pinniped-concierge-api-tls-serving-certificate
credentialIssuer: pinniped-config
apiService: pinniped-api
kubeCertAgentPrefix: kube-cert-agent-prefix
impersonationLoadBalancerService: impersonationLoadBalancerService-value
impersonationClusterIPService: impersonationClusterIPService-value
impersonationTLSCertificateSecret: impersonationTLSCertificateSecret-value
impersonationCACertificateSecret: impersonationCACertificateSecret-value
impersonationSignerSecret: impersonationSignerSecret-value
impersonationSignerSecret: impersonationSignerSecret-value
agentServiceAccount: agentServiceAccount-value
extraName: extraName-value
labels:
myLabelKey1: myLabelValue1
myLabelKey2: myLabelValue2
kubeCertAgent:
namePrefix: kube-cert-agent-name-prefix-
image: kube-cert-agent-image
imagePullSecrets: [kube-cert-agent-image-pull-secret]
log:
level: all
format: json
`),
wantConfig: &Config{
DiscoveryInfo: DiscoveryInfoSpec{
URL: pointer.StringPtr("https://some.discovery/url"),
},
APIConfig: APIConfigSpec{
ServingCertificateConfig: ServingCertificateConfigSpec{
DurationSeconds: pointer.Int64Ptr(3600),
RenewBeforeSeconds: pointer.Int64Ptr(2400),
},
},
APIGroupSuffix: pointer.StringPtr("some.suffix.com"),
AggregatedAPIServerPort: pointer.Int64Ptr(12345),
ImpersonationProxyServerPort: pointer.Int64Ptr(4242),
NamesConfig: NamesConfigSpec{
ServingCertificateSecret: "pinniped-concierge-api-tls-serving-certificate",
CredentialIssuer: "pinniped-config",
APIService: "pinniped-api",
ImpersonationLoadBalancerService: "impersonationLoadBalancerService-value",
ImpersonationClusterIPService: "impersonationClusterIPService-value",
ImpersonationTLSCertificateSecret: "impersonationTLSCertificateSecret-value",
ImpersonationCACertificateSecret: "impersonationCACertificateSecret-value",
ImpersonationSignerSecret: "impersonationSignerSecret-value",
AgentServiceAccount: "agentServiceAccount-value",
},
Labels: map[string]string{
"myLabelKey1": "myLabelValue1",
"myLabelKey2": "myLabelValue2",
},
KubeCertAgentConfig: KubeCertAgentSpec{
NamePrefix: pointer.StringPtr("kube-cert-agent-name-prefix-"),
Image: pointer.StringPtr("kube-cert-agent-image"),
ImagePullSecrets: []string{"kube-cert-agent-image-pull-secret"},
},
Log: plog.LogSpec{
Level: plog.LevelAll,
Format: plog.FormatJSON,
},
},
},
{
name: "Fully filled out old log and new log struct",
yaml: here.Doc(`
---
discovery:
url: https://some.discovery/url
api:
servingCertificate:
durationSeconds: 3600
renewBeforeSeconds: 2400
apiGroupSuffix: some.suffix.com
aggregatedAPIServerPort: 12345
impersonationProxyServerPort: 4242
names:
servingCertificateSecret: pinniped-concierge-api-tls-serving-certificate
credentialIssuer: pinniped-config
apiService: pinniped-api
kubeCertAgentPrefix: kube-cert-agent-prefix
impersonationLoadBalancerService: impersonationLoadBalancerService-value
impersonationClusterIPService: impersonationClusterIPService-value
impersonationTLSCertificateSecret: impersonationTLSCertificateSecret-value
impersonationCACertificateSecret: impersonationCACertificateSecret-value
impersonationSignerSecret: impersonationSignerSecret-value
impersonationSignerSecret: impersonationSignerSecret-value
agentServiceAccount: agentServiceAccount-value
extraName: extraName-value
labels:
myLabelKey1: myLabelValue1
myLabelKey2: myLabelValue2
kubeCertAgent:
namePrefix: kube-cert-agent-name-prefix-
image: kube-cert-agent-image
imagePullSecrets: [kube-cert-agent-image-pull-secret]
logLevel: debug
log:
level: all
format: json
`),
wantConfig: &Config{
DiscoveryInfo: DiscoveryInfoSpec{
URL: pointer.StringPtr("https://some.discovery/url"),
},
APIConfig: APIConfigSpec{
ServingCertificateConfig: ServingCertificateConfigSpec{
DurationSeconds: pointer.Int64Ptr(3600),
RenewBeforeSeconds: pointer.Int64Ptr(2400),
},
},
APIGroupSuffix: pointer.StringPtr("some.suffix.com"),
AggregatedAPIServerPort: pointer.Int64Ptr(12345),
ImpersonationProxyServerPort: pointer.Int64Ptr(4242),
NamesConfig: NamesConfigSpec{
ServingCertificateSecret: "pinniped-concierge-api-tls-serving-certificate",
CredentialIssuer: "pinniped-config",
APIService: "pinniped-api",
ImpersonationLoadBalancerService: "impersonationLoadBalancerService-value",
ImpersonationClusterIPService: "impersonationClusterIPService-value",
ImpersonationTLSCertificateSecret: "impersonationTLSCertificateSecret-value",
ImpersonationCACertificateSecret: "impersonationCACertificateSecret-value",
ImpersonationSignerSecret: "impersonationSignerSecret-value",
AgentServiceAccount: "agentServiceAccount-value",
},
Labels: map[string]string{
"myLabelKey1": "myLabelValue1",
"myLabelKey2": "myLabelValue2",
},
KubeCertAgentConfig: KubeCertAgentSpec{
NamePrefix: pointer.StringPtr("kube-cert-agent-name-prefix-"),
Image: pointer.StringPtr("kube-cert-agent-image"),
ImagePullSecrets: []string{"kube-cert-agent-image-pull-secret"},
},
LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelDebug),
Log: plog.LogSpec{
Level: plog.LevelDebug,
Format: plog.FormatJSON,
},
},
},
{
name: "invalid log format",
yaml: here.Doc(`
---
names:
servingCertificateSecret: pinniped-concierge-api-tls-serving-certificate
credentialIssuer: pinniped-config
apiService: pinniped-api
impersonationLoadBalancerService: impersonationLoadBalancerService-value
impersonationClusterIPService: impersonationClusterIPService-value
impersonationTLSCertificateSecret: impersonationTLSCertificateSecret-value
impersonationCACertificateSecret: impersonationCACertificateSecret-value
impersonationSignerSecret: impersonationSignerSecret-value
agentServiceAccount: agentServiceAccount-value
log:
level: all
format: snorlax
`),
wantError: "decode yaml: error unmarshaling JSON: while decoding JSON: invalid log format, valid choices are the empty string, json and text",
},
{
name: "When only the required fields are present, causes other fields to be defaulted",
yaml: here.Doc(`
@ -404,6 +582,8 @@ func TestFromPath(t *testing.T) {
for _, test := range tests {
test := test
t.Run(test.name, func(t *testing.T) {
// this is a serial test because it sets the global logger
// Write yaml to temp file
f, err := ioutil.TempFile("", "pinniped-test-config-yaml-*")
require.NoError(t, err)
@ -417,7 +597,9 @@ func TestFromPath(t *testing.T) {
require.NoError(t, err)
// Test FromPath()
config, err := FromPath(f.Name())
ctx, cancel := context.WithCancel(context.Background())
t.Cleanup(cancel)
config, err := FromPath(ctx, f.Name())
if test.wantError != "" {
require.EqualError(t, err, test.wantError)

4
internal/config/concierge/types.go
View File

@ -15,7 +15,9 @@ type Config struct {
NamesConfig NamesConfigSpec `json:"names"`
KubeCertAgentConfig KubeCertAgentSpec `json:"kubeCertAgent"`
Labels map[string]string `json:"labels"`
LogLevel plog.LogLevel `json:"logLevel"`
// Deprecated: use log.level instead
LogLevel *plog.LogLevel `json:"logLevel"`
Log plog.LogSpec `json:"log"`
}
// DiscoveryInfoSpec contains configuration knobs specific to

6
internal/config/supervisor/config.go
View File

@ -6,6 +6,7 @@
package supervisor
import (
"context"
"fmt"
"io/ioutil"
"net"
@ -28,7 +29,7 @@ const (
// FromPath loads an Config from a provided local file path, inserts any
// defaults (from the Config documentation), and verifies that the config is
// valid (Config documentation).
func FromPath(path string) (*Config, error) {
func FromPath(ctx context.Context, path string) (*Config, error) {
data, err := ioutil.ReadFile(path)
if err != nil {
return nil, fmt.Errorf("read file: %w", err)
@ -53,7 +54,8 @@ func FromPath(path string) (*Config, error) {
return nil, fmt.Errorf("validate names: %w", err)
}
if err := plog.ValidateAndSetLogLevelGlobally(config.LogLevel); err != nil {
plog.MaybeSetDeprecatedLogLevel(config.LogLevel, &config.Log)
if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, config.Log); err != nil {
return nil, fmt.Errorf("validate log level: %w", err)
}

123
internal/config/supervisor/config_test.go
View File

@ -4,6 +4,7 @@
package supervisor
import (
"context"
"fmt"
"io/ioutil"
"os"
@ -13,6 +14,7 @@ import (
"k8s.io/utils/pointer"
"go.pinniped.dev/internal/here"
"go.pinniped.dev/internal/plog"
)
func TestFromPath(t *testing.T) {
@ -40,6 +42,7 @@ func TestFromPath(t *testing.T) {
network: tcp
address: 127.0.0.1:1234
insecureAcceptExternalUnencryptedHttpRequests: false
logLevel: trace
`),
wantConfig: &Config{
APIGroupSuffix: pointer.StringPtr("some.suffix.com"),
@ -61,8 +64,122 @@ func TestFromPath(t *testing.T) {
},
},
AllowExternalHTTP: false,
LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelTrace),
Log: plog.LogSpec{
Level: plog.LevelTrace,
},
},
},
{
name: "Happy with new log field",
yaml: here.Doc(`
---
apiGroupSuffix: some.suffix.com
labels:
myLabelKey1: myLabelValue1
myLabelKey2: myLabelValue2
names:
defaultTLSCertificateSecret: my-secret-name
endpoints:
https:
network: unix
address: :1234
http:
network: tcp
address: 127.0.0.1:1234
insecureAcceptExternalUnencryptedHttpRequests: false
log:
level: info
format: text
`),
wantConfig: &Config{
APIGroupSuffix: pointer.StringPtr("some.suffix.com"),
Labels: map[string]string{
"myLabelKey1": "myLabelValue1",
"myLabelKey2": "myLabelValue2",
},
NamesConfig: NamesConfigSpec{
DefaultTLSCertificateSecret: "my-secret-name",
},
Endpoints: &Endpoints{
HTTPS: &Endpoint{
Network: "unix",
Address: ":1234",
},
HTTP: &Endpoint{
Network: "tcp",
Address: "127.0.0.1:1234",
},
},
AllowExternalHTTP: false,
Log: plog.LogSpec{
Level: plog.LevelInfo,
Format: plog.FormatText,
},
},
},
{
name: "Happy with old and new log field",
yaml: here.Doc(`
---
apiGroupSuffix: some.suffix.com
labels:
myLabelKey1: myLabelValue1
myLabelKey2: myLabelValue2
names:
defaultTLSCertificateSecret: my-secret-name
endpoints:
https:
network: unix
address: :1234
http:
network: tcp
address: 127.0.0.1:1234
insecureAcceptExternalUnencryptedHttpRequests: false
logLevel: trace
log:
level: info
format: text
`),
wantConfig: &Config{
APIGroupSuffix: pointer.StringPtr("some.suffix.com"),
Labels: map[string]string{
"myLabelKey1": "myLabelValue1",
"myLabelKey2": "myLabelValue2",
},
NamesConfig: NamesConfigSpec{
DefaultTLSCertificateSecret: "my-secret-name",
},
Endpoints: &Endpoints{
HTTPS: &Endpoint{
Network: "unix",
Address: ":1234",
},
HTTP: &Endpoint{
Network: "tcp",
Address: "127.0.0.1:1234",
},
},
AllowExternalHTTP: false,
LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelTrace),
Log: plog.LogSpec{
Level: plog.LevelTrace,
Format: plog.FormatText,
},
},
},
{
name: "bad log format",
yaml: here.Doc(`
---
names:
defaultTLSCertificateSecret: my-secret-name
log:
level: info
format: cli
`),
wantError: "decode yaml: error unmarshaling JSON: while decoding JSON: invalid log format, valid choices are the empty string, json and text",
},
{
name: "When only the required fields are present, causes other fields to be defaulted",
yaml: here.Doc(`
@ -307,7 +424,7 @@ func TestFromPath(t *testing.T) {
for _, test := range tests {
test := test
t.Run(test.name, func(t *testing.T) {
t.Parallel()
// this is a serial test because it sets the global logger
// Write yaml to temp file
f, err := ioutil.TempFile("", "pinniped-test-config-yaml-*")
@ -322,7 +439,9 @@ func TestFromPath(t *testing.T) {
require.NoError(t, err)
// Test FromPath()
config, err := FromPath(f.Name())
ctx, cancel := context.WithCancel(context.Background())
t.Cleanup(cancel)
config, err := FromPath(ctx, f.Name())
if test.wantError != "" {
require.EqualError(t, err, test.wantError)

4
internal/config/supervisor/types.go
View File

@ -14,7 +14,9 @@ type Config struct {
APIGroupSuffix *string `json:"apiGroupSuffix,omitempty"`
Labels map[string]string `json:"labels"`
NamesConfig NamesConfigSpec `json:"names"`
LogLevel plog.LogLevel `json:"logLevel"`
// Deprecated: use log.level instead
LogLevel *plog.LogLevel `json:"logLevel"`
Log plog.LogSpec `json:"log"`
Endpoints *Endpoints `json:"endpoints"`
AllowExternalHTTP stringOrBoolAsBool `json:"insecureAcceptExternalUnencryptedHttpRequests"`
}

11
internal/controller/apicerts/certs_expirer.go
View File

@ -32,6 +32,8 @@ type certsExpirerController struct {
renewBefore time.Duration
secretKey string
logger plog.Logger
}
// NewCertsExpirerController returns a controllerlib.Controller that will delete a
@ -45,10 +47,12 @@ func NewCertsExpirerController(
withInformer pinnipedcontroller.WithInformerOptionFunc,
renewBefore time.Duration,
secretKey string,
logger plog.Logger,
) controllerlib.Controller {
const name = "certs-expirer-controller"
return controllerlib.New(
controllerlib.Config{
Name: "certs-expirer-controller",
Name: name,
Syncer: &certsExpirerController{
namespace: namespace,
certsSecretResourceName: certsSecretResourceName,
@ -56,6 +60,7 @@ func NewCertsExpirerController(
secretInformer: secretInformer,
renewBefore: renewBefore,
secretKey: secretKey,
logger: logger.WithName(name),
},
},
withInformer(
@ -74,7 +79,7 @@ func (c *certsExpirerController) Sync(ctx controllerlib.Context) error {
return fmt.Errorf("failed to get %s/%s secret: %w", c.namespace, c.certsSecretResourceName, err)
}
if notFound {
plog.Info("secret does not exist yet or was deleted",
c.logger.Info("secret does not exist yet or was deleted",
"controller", ctx.Name,
"namespace", c.namespace,
"name", c.certsSecretResourceName,
@ -91,7 +96,7 @@ func (c *certsExpirerController) Sync(ctx controllerlib.Context) error {
certAge := time.Since(notBefore)
renewDelta := certAge - c.renewBefore
plog.Debug("found renew delta",
c.logger.Debug("found renew delta",
"controller", ctx.Name,
"namespace", c.namespace,
"name", c.certsSecretResourceName,

13
internal/controller/apicerts/certs_expirer_test.go
View File

@ -4,12 +4,15 @@
package apicerts
import (
"bytes"
"context"
"crypto/ecdsa"
"crypto/elliptic"
"crypto/rand"
"crypto/x509"
"errors"
"io"
"strings"
"testing"
"time"
@ -24,6 +27,7 @@ import (
kubetesting "k8s.io/client-go/testing"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
)
@ -101,6 +105,7 @@ func TestExpirerControllerFilters(t *testing.T) {
withInformer.WithInformer,
0, // renewBefore, not needed
"", // not needed
plog.TestLogger(t, io.Discard),
)
unrelated := corev1.Secret{}
@ -125,10 +130,12 @@ func TestExpirerControllerSync(t *testing.T) {
fillSecretData func(*testing.T, map[string][]byte)
configKubeAPIClient func(*kubernetesfake.Clientset)
wantDelete bool
wantLog string
wantError string
}{
{
name: "secret does not exist",
wantLog: `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"certs-expirer-controller","caller":"apicerts/certs_expirer.go:<line>$apicerts.(*certsExpirerController).Sync","message":"secret does not exist yet or was deleted","controller":"","namespace":"some-namespace","name":"some-resource-name","key":"some-awesome-key","renewBefore":"0s"}`,
wantDelete: false,
},
{
@ -251,6 +258,8 @@ func TestExpirerControllerSync(t *testing.T) {
0,
)
var log bytes.Buffer
c := NewCertsExpirerController(
namespace,
certsSecretResourceName,
@ -259,6 +268,7 @@ func TestExpirerControllerSync(t *testing.T) {
controllerlib.WithInformer,
test.renewBefore,
fakeTestKey,
plog.TestLogger(t, &log),
)
// Must start informers before calling TestRunSynchronously().
@ -268,6 +278,9 @@ func TestExpirerControllerSync(t *testing.T) {
err := controllerlib.TestSync(t, c, controllerlib.Context{
Context: ctx,
})
if len(test.wantLog) > 0 {
require.Equal(t, test.wantLog, strings.TrimSpace(log.String()))
}
if test.wantError != "" {
require.EqualError(t, err, test.wantError)
return

4
internal/controller/apicerts/certs_manager.go
View File

@ -12,11 +12,11 @@ import (
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
corev1informers "k8s.io/client-go/informers/core/v1"
"k8s.io/client-go/kubernetes"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/certauthority"
pinnipedcontroller "go.pinniped.dev/internal/controller"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/plog"
)
const (
@ -139,6 +139,6 @@ func (c *certsManagerController) Sync(ctx controllerlib.Context) error {
return fmt.Errorf("could not create secret: %w", err)
}
klog.Info("certsManagerController Sync successfully created secret")
plog.Info("certsManagerController Sync successfully created secret")
return nil
}

6
internal/controller/apicerts/certs_observer.go
View File

@ -8,11 +8,11 @@ import (
k8serrors "k8s.io/apimachinery/pkg/api/errors"
corev1informers "k8s.io/client-go/informers/core/v1"
"k8s.io/klog/v2"
pinnipedcontroller "go.pinniped.dev/internal/controller"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/dynamiccert"
"go.pinniped.dev/internal/plog"
)
type certsObserverController struct {
@ -55,7 +55,7 @@ func (c *certsObserverController) Sync(_ controllerlib.Context) error {
return fmt.Errorf("failed to get %s/%s secret: %w", c.namespace, c.certsSecretResourceName, err)
}
if notFound {
klog.Info("certsObserverController Sync found that the secret does not exist yet or was deleted")
plog.Info("certsObserverController Sync found that the secret does not exist yet or was deleted")
// The secret does not exist yet or was deleted.
c.dynamicCertProvider.UnsetCertKeyContent()
return nil
@ -66,6 +66,6 @@ func (c *certsObserverController) Sync(_ controllerlib.Context) error {
return fmt.Errorf("failed to set serving cert/key content from secret %s/%s: %w", c.namespace, c.certsSecretResourceName, err)
}
klog.Info("certsObserverController Sync updated certs in the dynamic cert provider")
plog.Info("certsObserverController Sync updated certs in the dynamic cert provider")
return nil
}

4
internal/controller/conditionsutil/conditions_util.go.go
View File

@ -6,15 +6,15 @@ package conditionsutil
import (
"sort"
"github.com/go-logr/logr"
"k8s.io/apimachinery/pkg/api/equality"
v1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1"
"go.pinniped.dev/internal/plog"
)
// Merge merges conditions into conditionsToUpdate. If returns true if it merged any error conditions.
func Merge(conditions []*v1alpha1.Condition, observedGeneration int64, conditionsToUpdate *[]v1alpha1.Condition, log logr.Logger) bool {
func Merge(conditions []*v1alpha1.Condition, observedGeneration int64, conditionsToUpdate *[]v1alpha1.Condition, log plog.MinLogger) bool {
hadErrorCondition := false
for i := range conditions {
cond := conditions[i].DeepCopy()

5
internal/controller/impersonatorconfig/impersonator_config.go
View File

@ -45,6 +45,7 @@ import (
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/dynamiccert"
"go.pinniped.dev/internal/endpointaddr"
"go.pinniped.dev/internal/plog"
)
const (
@ -132,8 +133,8 @@ func NewImpersonatorConfigController(
impersonationSigningCertProvider: impersonationSigningCertProvider,
impersonatorFunc: impersonatorFunc,
tlsServingCertDynamicCertProvider: dynamiccert.NewServingCert("impersonation-proxy-serving-cert"),
infoLog: log.V(2),
debugLog: log.V(4),
infoLog: log.V(plog.KlogLevelInfo),
debugLog: log.V(plog.KlogLevelDebug),
},
},
withInformer(credentialIssuerInformer,

10
internal/controller/impersonatorconfig/impersonator_config_test.go
View File

@ -43,8 +43,8 @@ import (
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/dynamiccert"
"go.pinniped.dev/internal/kubeclient"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
"go.pinniped.dev/internal/testutil/testlogger"
)
func TestImpersonatorConfigControllerOptions(t *testing.T) {
@ -63,7 +63,6 @@ func TestImpersonatorConfigControllerOptions(t *testing.T) {
var credIssuerInformerFilter controllerlib.Filter
var servicesInformerFilter controllerlib.Filter
var secretsInformerFilter controllerlib.Filter
var testLog *testlogger.Logger
it.Before(func() {
r = require.New(t)
@ -73,7 +72,6 @@ func TestImpersonatorConfigControllerOptions(t *testing.T) {
credIssuerInformer := pinnipedInformerFactory.Config().V1alpha1().CredentialIssuers()
servicesInformer := sharedInformerFactory.Core().V1().Services()
secretsInformer := sharedInformerFactory.Core().V1().Secrets()
testLog = testlogger.New(t)
_ = NewImpersonatorConfigController(
installedInNamespace,
@ -94,7 +92,7 @@ func TestImpersonatorConfigControllerOptions(t *testing.T) {
nil,
caSignerName,
nil,
testLog.Logger,
plog.Logr(), // nolint: staticcheck // old test with no log assertions
)
credIssuerInformerFilter = observableWithInformerOption.GetFilterForInformer(credIssuerInformer)
servicesInformerFilter = observableWithInformerOption.GetFilterForInformer(servicesInformer)
@ -292,7 +290,6 @@ func TestImpersonatorConfigControllerSync(t *testing.T) {
var testHTTPServerInterruptCh chan struct{}
var queue *testQueue
var validClientCert *tls.Certificate
var testLog *testlogger.Logger
var impersonatorFunc = func(
port int,
@ -563,7 +560,7 @@ func TestImpersonatorConfigControllerSync(t *testing.T) {
impersonatorFunc,
caSignerName,
signingCertProvider,
testLog.Logger,
plog.Logr(), // nolint: staticcheck // old test with no log assertions
)
controllerlib.TestWrap(t, subject, func(syncer controllerlib.Syncer) controllerlib.Syncer {
tlsServingCertDynamicCertProvider = syncer.(*impersonatorConfigController).tlsServingCertDynamicCertProvider
@ -1120,7 +1117,6 @@ func TestImpersonatorConfigControllerSync(t *testing.T) {
signingCASecret = newSigningKeySecret(caSignerName, signingCACertPEM, signingCAKeyPEM)
validClientCert, err = ca.IssueClientCert("username", nil, time.Hour)
r.NoError(err)
testLog = testlogger.New(t)
})
it.After(func() {

4
internal/controller/kubecertagent/kubecertagent.go
View File

@ -28,7 +28,6 @@ import (
corev1informers "k8s.io/client-go/informers/core/v1"
"k8s.io/client-go/tools/clientcmd"
"k8s.io/klog/v2"
"k8s.io/klog/v2/klogr"
"k8s.io/utils/clock"
"k8s.io/utils/pointer"
@ -39,6 +38,7 @@ import (
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/dynamiccert"
"go.pinniped.dev/internal/kubeclient"
"go.pinniped.dev/internal/plog"
)
const (
@ -179,7 +179,7 @@ func NewAgentController(
dynamicCertProvider,
&clock.RealClock{},
cache.NewExpiring(),
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
)
}

50
internal/controller/kubecertagent/kubecertagent_test.go
View File

@ -4,8 +4,10 @@
package kubecertagent
import (
"bytes"
"context"
"fmt"
"strings"
"testing"
"time"
@ -35,8 +37,8 @@ import (
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/here"
"go.pinniped.dev/internal/kubeclient"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
"go.pinniped.dev/internal/testutil/testlogger"
"go.pinniped.dev/test/testlib"
)
@ -339,7 +341,7 @@ func TestAgentController(t *testing.T) {
"could not ensure agent deployment: some creation error",
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantStrategy: &configv1alpha1.CredentialIssuerStrategy{
Type: configv1alpha1.KubeClusterSigningCertificateStrategyType,
@ -386,7 +388,7 @@ func TestAgentController(t *testing.T) {
`could not ensure agent deployment: deployments.apps "pinniped-concierge-kube-cert-agent" already exists`,
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantAgentDeployment: healthyAgentDeployment,
wantDeploymentActionVerbs: []string{"list", "watch", "create"},
@ -435,7 +437,7 @@ func TestAgentController(t *testing.T) {
`could not ensure agent deployment: deployments.apps "pinniped-concierge-kube-cert-agent" already exists`,
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantAgentDeployment: healthyAgentDeploymentWithDefaultedPaths,
wantDeploymentActionVerbs: []string{"list", "watch", "create"},
@ -461,8 +463,8 @@ func TestAgentController(t *testing.T) {
"could not find a healthy agent pod (1 candidate)",
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`kube-cert-agent-controller "level"=0 "msg"="creating new deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantAgentDeployment: healthyAgentDeployment,
wantDeploymentActionVerbs: []string{"list", "watch", "delete", "create"}, // must recreate deployment when Selector field changes
@ -496,7 +498,7 @@ func TestAgentController(t *testing.T) {
"could not ensure agent deployment: some delete error",
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantAgentDeployment: healthyAgentDeploymentWithOldStyleSelector, // couldn't be deleted, so it didn't change
// delete to try to recreate deployment when Selector field changes, but delete always fails, so keeps trying to delete
@ -532,9 +534,9 @@ func TestAgentController(t *testing.T) {
"could not ensure agent deployment: some create error",
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`kube-cert-agent-controller "level"=0 "msg"="creating new deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantAgentDeployment: nil, // was deleted, but couldn't be recreated
// delete to try to recreate deployment when Selector field changes, but create always fails, so keeps trying to recreate
@ -584,7 +586,7 @@ func TestAgentController(t *testing.T) {
"could not find a healthy agent pod (1 candidate)",
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="updating existing deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"updating existing deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
wantAgentDeployment: healthyAgentDeploymentWithExtraLabels,
wantDeploymentActionVerbs: []string{"list", "watch", "update"},
@ -619,7 +621,7 @@ func TestAgentController(t *testing.T) {
LastUpdateTime: metav1.NewTime(now),
},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="updating existing deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"updating existing deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
},
},
{
@ -931,8 +933,8 @@ func TestAgentController(t *testing.T) {
// delete to try to recreate deployment when Selector field changes, but delete always fails, so keeps trying to delete
wantDeploymentActionVerbs: []string{"list", "watch", "delete", "delete"},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`,
`kube-cert-agent-controller "level"=0 "msg"="successfully loaded signing key from agent pod into cache"`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).loadSigningKey","message":"successfully loaded signing key from agent pod into cache"}`,
},
wantDeploymentDeleteActionOpts: []metav1.DeleteOptions{
testutil.NewPreconditions(healthyAgentDeploymentWithOldStyleSelector.UID, healthyAgentDeploymentWithOldStyleSelector.ResourceVersion),
@ -962,7 +964,7 @@ func TestAgentController(t *testing.T) {
wantAgentDeployment: healthyAgentDeployment,
wantDeploymentActionVerbs: []string{"list", "watch"},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="successfully loaded signing key from agent pod into cache"`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).loadSigningKey","message":"successfully loaded signing key from agent pod into cache"}`,
},
wantStrategy: &configv1alpha1.CredentialIssuerStrategy{
Type: configv1alpha1.KubeClusterSigningCertificateStrategyType,
@ -996,7 +998,7 @@ func TestAgentController(t *testing.T) {
wantAgentDeployment: healthyAgentDeployment,
wantDeploymentActionVerbs: []string{"list", "watch"},
wantDistinctLogs: []string{
`kube-cert-agent-controller "level"=0 "msg"="successfully loaded signing key from agent pod into cache"`,
`{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:<line>$kubecertagent.(*agentController).loadSigningKey","message":"successfully loaded signing key from agent pod into cache"}`,
},
wantStrategy: &configv1alpha1.CredentialIssuerStrategy{
Type: configv1alpha1.KubeClusterSigningCertificateStrategyType,
@ -1028,7 +1030,9 @@ func TestAgentController(t *testing.T) {
}
kubeInformers := informers.NewSharedInformerFactory(kubeClientset, 0)
log := testlogger.NewLegacy(t) // nolint: staticcheck // old test with lots of log statements
var buf bytes.Buffer
log := plog.TestZapr(t, &buf)
ctrl := gomock.NewController(t)
defer ctrl.Finish()
@ -1066,7 +1070,7 @@ func TestAgentController(t *testing.T) {
mockDynamicCert,
fakeClock,
execCache,
log.Logger,
log,
)
ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
@ -1081,7 +1085,7 @@ func TestAgentController(t *testing.T) {
allAllowedErrors = append(allAllowedErrors, tt.alsoAllowUndesiredDistinctErrors...)
assert.Subsetf(t, allAllowedErrors, actualErrors, "actual errors contained additional error(s) which is not expected by the test")
assert.Equal(t, tt.wantDistinctLogs, deduplicate(log.Lines()), "unexpected logs")
assert.Equal(t, tt.wantDistinctLogs, deduplicate(logLines(buf.String())), "unexpected logs")
// Assert on all actions that happened to deployments.
var actualDeploymentActionVerbs []string
@ -1124,6 +1128,14 @@ func TestAgentController(t *testing.T) {
}
}
func logLines(logs string) []string {
if len(logs) == 0 {
return nil
}
return strings.Split(strings.TrimSpace(logs), "\n")
}
func TestMergeLabelsAndAnnotations(t *testing.T) {
t.Parallel()

7
internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go
View File

@ -13,12 +13,10 @@ import (
"github.com/go-ldap/ldap/v3"
"github.com/google/uuid"
"k8s.io/apimachinery/pkg/api/equality"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/labels"
corev1informers "k8s.io/client-go/informers/core/v1"
"k8s.io/klog/v2/klogr"
"go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1"
pinnipedclientset "go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned"
@ -28,6 +26,7 @@ import (
"go.pinniped.dev/internal/controller/supervisorconfig/upstreamwatchers"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/oidc/provider"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/upstreamldap"
)
@ -360,7 +359,7 @@ func (c *activeDirectoryWatcherController) validateUpstream(ctx context.Context,
}
func (c *activeDirectoryWatcherController) updateStatus(ctx context.Context, upstream *v1alpha1.ActiveDirectoryIdentityProvider, conditions []*v1alpha1.Condition) {
log := klogr.New().WithValues("namespace", upstream.Namespace, "name", upstream.Name)
log := plog.WithValues("namespace", upstream.Namespace, "name", upstream.Name)
updated := upstream.DeepCopy()
hadErrorCondition := conditionsutil.Merge(conditions, upstream.Generation, &updated.Status.Conditions, log)
@ -379,7 +378,7 @@ func (c *activeDirectoryWatcherController) updateStatus(ctx context.Context, ups
ActiveDirectoryIdentityProviders(upstream.Namespace).
UpdateStatus(ctx, updated, metav1.UpdateOptions{})
if err != nil {
log.Error(err, "failed to update status")
log.Error("failed to update status", err)
}
}

6
internal/controller/supervisorconfig/ldapupstreamwatcher/ldap_upstream_watcher.go
View File

@ -12,7 +12,6 @@ import (
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/labels"
corev1informers "k8s.io/client-go/informers/core/v1"
"k8s.io/klog/v2/klogr"
"go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1"
pinnipedclientset "go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned"
@ -22,6 +21,7 @@ import (
"go.pinniped.dev/internal/controller/supervisorconfig/upstreamwatchers"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/oidc/provider"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/upstreamldap"
)
@ -252,7 +252,7 @@ func (c *ldapWatcherController) validateUpstream(ctx context.Context, upstream *
}
func (c *ldapWatcherController) updateStatus(ctx context.Context, upstream *v1alpha1.LDAPIdentityProvider, conditions []*v1alpha1.Condition) {
log := klogr.New().WithValues("namespace", upstream.Namespace, "name", upstream.Name)
log := plog.WithValues("namespace", upstream.Namespace, "name", upstream.Name)
updated := upstream.DeepCopy()
hadErrorCondition := conditionsutil.Merge(conditions, upstream.Generation, &updated.Status.Conditions, log)
@ -271,6 +271,6 @@ func (c *ldapWatcherController) updateStatus(ctx context.Context, upstream *v1al
LDAPIdentityProviders(upstream.Namespace).
UpdateStatus(ctx, updated, metav1.UpdateOptions{})
if err != nil {
log.Error(err, "failed to update status")
log.Error("failed to update status", err)
}
}

7
internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher.go
View File

@ -14,8 +14,6 @@ import (
"strings"
"time"
"k8s.io/apimachinery/pkg/util/sets"
"github.com/coreos/go-oidc/v3/oidc"
"github.com/go-logr/logr"
"golang.org/x/oauth2"
@ -24,6 +22,7 @@ import (
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/labels"
"k8s.io/apimachinery/pkg/util/cache"
"k8s.io/apimachinery/pkg/util/sets"
corev1informers "k8s.io/client-go/informers/core/v1"
"go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1"
@ -36,6 +35,7 @@ import (
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/net/phttp"
"go.pinniped.dev/internal/oidc/provider"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/upstreamoidc"
)
@ -331,8 +331,7 @@ func (c *oidcWatcherController) validateIssuer(ctx context.Context, upstream *v1
discoveredProvider, err = oidc.NewProvider(oidc.ClientContext(ctx, httpClient), upstream.Spec.Issuer)
if err != nil {
const klogLevelTrace = 6
c.log.V(klogLevelTrace).WithValues(
c.log.V(plog.KlogLevelTrace).WithValues(
"namespace", upstream.Namespace,
"name", upstream.Name,
"issuer", upstream.Spec.Issuer,

4
internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher_test.go
View File

@ -29,6 +29,7 @@ import (
"go.pinniped.dev/internal/certauthority"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/oidc/provider"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
"go.pinniped.dev/internal/testutil/oidctestutil"
"go.pinniped.dev/internal/testutil/testlogger"
@ -78,7 +79,6 @@ func TestOIDCUpstreamWatcherControllerFilterSecret(t *testing.T) {
pinnipedInformers := pinnipedinformers.NewSharedInformerFactory(fakePinnipedClient, 0)
fakeKubeClient := fake.NewSimpleClientset()
kubeInformers := informers.NewSharedInformerFactory(fakeKubeClient, 0)
testLog := testlogger.New(t)
cache := provider.NewDynamicUpstreamIDPProvider()
cache.SetOIDCIdentityProviders([]provider.UpstreamOIDCIdentityProviderI{
&upstreamoidc.ProviderConfig{Name: "initial-entry"},
@ -91,7 +91,7 @@ func TestOIDCUpstreamWatcherControllerFilterSecret(t *testing.T) {
nil,
pinnipedInformers.IDP().V1alpha1().OIDCIdentityProviders(),
secretInformer,
testLog.Logger,
plog.Logr(), // nolint: staticcheck // old test with no log assertions
withInformer.WithInformer,
)

3
internal/controllerlib/controller.go
View File

@ -15,7 +15,6 @@ import (
"k8s.io/client-go/tools/cache"
"k8s.io/client-go/tools/events"
"k8s.io/client-go/util/workqueue"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/plog"
)
@ -215,7 +214,7 @@ func (c *controller) handleKey(key Key, err error) {
if errors.Is(err, ErrSyntheticRequeue) {
// logging this helps detecting wedged controllers with missing pre-requirements
klog.V(4).InfoS("requested synthetic requeue", "controller", c.Name(), "key", key)
plog.Debug("requested synthetic requeue", "controller", c.Name(), "key", key)
} else {
utilruntime.HandleError(fmt.Errorf("%s: %v failed with: %w", c.Name(), key, err))
}

9
internal/controllerlib/option.go
View File

@ -13,7 +13,8 @@ import (
"k8s.io/client-go/tools/cache"
"k8s.io/client-go/tools/events"
"k8s.io/client-go/util/workqueue"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/plog"
)
type Option func(*controller)
@ -62,7 +63,7 @@ func WithInformer(getter InformerGetter, filter Filter, opt InformerOption) Opti
AddFunc: func(obj interface{}) {
object := metaOrDie(obj)
if filter.Add(object) {
klog.V(4).InfoS("handling add",
plog.Debug("handling add",
"controller", c.Name(),
"namespace", object.GetNamespace(),
"name", object.GetName(),
@ -76,7 +77,7 @@ func WithInformer(getter InformerGetter, filter Filter, opt InformerOption) Opti
oldObject := metaOrDie(oldObj)
newObject := metaOrDie(newObj)
if filter.Update(oldObject, newObject) {
klog.V(4).InfoS("handling update",
plog.Debug("handling update",
"controller", c.Name(),
"namespace", newObject.GetNamespace(),
"name", newObject.GetName(),
@ -101,7 +102,7 @@ func WithInformer(getter InformerGetter, filter Filter, opt InformerOption) Opti
}
}
if filter.Delete(accessor) {
klog.V(4).InfoS("handling delete",
plog.Debug("handling delete",
"controller", c.Name(),
"namespace", accessor.GetNamespace(),
"name", accessor.GetName(),

5
internal/controllerlib/recorder.go
View File

@ -8,7 +8,8 @@ import (
"k8s.io/apimachinery/pkg/runtime"
"k8s.io/client-go/tools/events"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/plog"
)
var _ events.EventRecorder = klogRecorder{}
@ -16,7 +17,7 @@ var _ events.EventRecorder = klogRecorder{}
type klogRecorder struct{}
func (n klogRecorder) Eventf(regarding runtime.Object, related runtime.Object, eventtype, reason, action, note string, args ...interface{}) {
klog.V(4).InfoS("recording event",
plog.Debug("recording event",
"regarding", regarding,
"related", related,
"eventtype", eventtype,

8
internal/controllerlib/test/integration/examplecontroller/controller/creating.go
View File

@ -14,10 +14,10 @@ import (
corev1informers "k8s.io/client-go/informers/core/v1"
corev1client "k8s.io/client-go/kubernetes/typed/core/v1"
"k8s.io/client-go/tools/events"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/controllerlib"
"go.pinniped.dev/internal/controllerlib/test/integration/examplecontroller/api"
"go.pinniped.dev/internal/plog"
)
//nolint:funlen
@ -59,7 +59,7 @@ func NewExampleCreatingController(
}
generateSecret := func(service *corev1.Service) error {
klog.V(4).InfoS("generating new secret for service", "namespace", service.Namespace, "name", service.Name)
plog.Debug("generating new secret for service", "namespace", service.Namespace, "name", service.Name)
secret := &corev1.Secret{
ObjectMeta: metav1.ObjectMeta{
@ -97,7 +97,7 @@ func NewExampleCreatingController(
return nil // drop from queue because we cannot safely update this secret
}
klog.V(4).InfoS("updating data in existing secret", "namespace", secret.Namespace, "name", secret.Name)
plog.Debug("updating data in existing secret", "namespace", secret.Namespace, "name", secret.Name)
// Actually update the secret in the regeneration case (the secret already exists but we want to update to new secretData).
_, updateErr := secretClient.Secrets(secret.Namespace).Update(context.TODO(), secret, metav1.UpdateOptions{})
return updateErr
@ -169,7 +169,7 @@ func NewExampleCreatingController(
utilruntime.HandleError(fmt.Errorf("unable to get service %s/%s: %w", secret.Namespace, serviceName, err))
return false
}
klog.V(4).InfoS("recreating secret", "namespace", service.Namespace, "name", service.Name)
plog.Debug("recreating secret", "namespace", service.Namespace, "name", service.Name)
return true
},
}, controllerlib.InformerOption{}),

14
internal/controllermanager/prepare_controllers.go
View File

@ -11,7 +11,6 @@ import (
k8sinformers "k8s.io/client-go/informers"
"k8s.io/client-go/kubernetes"
"k8s.io/klog/v2/klogr"
"k8s.io/utils/clock"
pinnipedclientset "go.pinniped.dev/generated/latest/client/concierge/clientset/versioned"
@ -34,6 +33,7 @@ import (
"go.pinniped.dev/internal/groupsuffix"
"go.pinniped.dev/internal/kubeclient"
"go.pinniped.dev/internal/leaderelection"
"go.pinniped.dev/internal/plog"
)
const (
@ -197,6 +197,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
controllerlib.WithInformer,
c.ServingCertRenewBefore,
apicerts.TLSCertificateChainSecretKey,
plog.New(),
),
singletonWorker,
).
@ -222,7 +223,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
agentConfig,
client,
informers.installationNamespaceK8s.Core().V1().Pods(),
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
),
singletonWorker,
).
@ -232,7 +233,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
webhookcachefiller.New(
c.AuthenticatorCache,
informers.pinniped.Authentication().V1alpha1().WebhookAuthenticators(),
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
),
singletonWorker,
).
@ -240,7 +241,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
jwtcachefiller.New(
c.AuthenticatorCache,
informers.pinniped.Authentication().V1alpha1().JWTAuthenticators(),
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
),
singletonWorker,
).
@ -249,7 +250,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
c.AuthenticatorCache,
informers.pinniped.Authentication().V1alpha1().WebhookAuthenticators(),
informers.pinniped.Authentication().V1alpha1().JWTAuthenticators(),
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
),
singletonWorker,
).
@ -275,7 +276,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
impersonator.New,
c.NamesConfig.ImpersonationSignerSecret,
c.ImpersonationSigningCertProvider,
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
),
singletonWorker,
).
@ -303,6 +304,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) {
controllerlib.WithInformer,
365*24*time.Hour-time.Hour, // 1 year minus 1 hour hard coded value (i.e. wait until the last moment to break the signer)
apicerts.CACertificateSecretKey,
plog.New(),
),
singletonWorker,
)

7
internal/crypto/ptls/fips_strict.go
View File

@ -20,7 +20,8 @@ import (
_ "crypto/tls/fipsonly" // restricts all TLS configuration to FIPS-approved settings.
"k8s.io/apiserver/pkg/server/options"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/plog"
)
// Always use TLS 1.2 for FIPs
@ -36,9 +37,7 @@ func init() {
// this init runs before we have parsed our config to determine our log level
// thus we must use a log statement that will always print instead of conditionally print
// for plog, that is only error and warning logs, neither of which seem appropriate here
// therefore, just use klog directly with no V level requirement
klog.InfoS("using boring crypto in fips only mode", "go version", runtime.Version())
plog.Always("using boring crypto in fips only mode", "go version", runtime.Version())
}
func Default(rootCAs *x509.CertPool) *tls.Config {

9
internal/groupsuffix/groupsuffix.go
View File

@ -16,7 +16,6 @@ import (
loginv1alpha1 "go.pinniped.dev/generated/latest/apis/concierge/login/v1alpha1"
"go.pinniped.dev/internal/constable"
"go.pinniped.dev/internal/kubeclient"
"go.pinniped.dev/internal/plog"
)
const (
@ -86,8 +85,8 @@ func New(apiGroupSuffix string) kubeclient.Middleware {
// want our middleware to be opinionated so that it can be really good at a specific task
// and give us specific feedback when it can't do that specific task
return fmt.Errorf(
"cannot replace token credential request %q without authenticator API group",
plog.KObj(obj),
"cannot replace token credential request %s/%s without authenticator API group",
obj.GetNamespace(), obj.GetName(),
)
}
@ -95,8 +94,8 @@ func New(apiGroupSuffix string) kubeclient.Middleware {
if !ok {
// see comment above about specificity of middleware
return fmt.Errorf(
"cannot replace token credential request %q authenticator API group %q with group suffix %q",
plog.KObj(obj),
"cannot replace token credential request %s/%s authenticator API group %q with group suffix %q",
obj.GetNamespace(), obj.GetName(),
*tokenCredentialRequest.Spec.Authenticator.APIGroup,
apiGroupSuffix,
)

4
internal/groupsuffix/groupsuffix_test.go
View File

@ -435,7 +435,7 @@ func TestMiddlware(t *testing.T) {
responseObj: tokenCredentialRequestWithNewGroup, // a token credential response does not contain a spec
wantMutateRequests: 3,
wantMutateResponses: 1,
wantMutateRequestErrors: []string{`cannot replace token credential request "/" authenticator API group "authentication.concierge.some.suffix.com" with group suffix "some.suffix.com"`},
wantMutateRequestErrors: []string{`cannot replace token credential request / authenticator API group "authentication.concierge.some.suffix.com" with group suffix "some.suffix.com"`},
wantResponseObj: tokenCredentialRequestWithNewGroup, // the middleware will reset object GVK for us
},
{
@ -475,7 +475,7 @@ func TestMiddlware(t *testing.T) {
responseObj: tokenCredentialRequestWithNewGroup, // a token credential response does not contain a spec
wantMutateRequests: 3,
wantMutateResponses: 1,
wantMutateRequestErrors: []string{`cannot replace token credential request "/" without authenticator API group`},
wantMutateRequestErrors: []string{`cannot replace token credential request / without authenticator API group`},
wantResponseObj: tokenCredentialRequestWithNewGroup, // the middleware will reset object GVK for us
},
{

4
internal/kubeclient/copied.go
View File

@ -39,9 +39,9 @@ func glogBody(prefix string, body []byte) {
if bytes.IndexFunc(body, func(r rune) bool {
return r < 0x0a
}) != -1 {
plog.Debug(prefix, "body", hex.Dump(body))
plog.All(prefix, "body", hex.Dump(body))
} else {
plog.Debug(prefix, "body", string(body))
plog.All(prefix, "body", string(body))
}
}
}

39
internal/localuserauthenticator/localuserauthenticator.go
View File

@ -22,6 +22,7 @@ import (
"os"
"os/signal"
"strings"
"syscall"
"time"
"golang.org/x/crypto/bcrypt"
@ -31,7 +32,6 @@ import (
kubeinformers "k8s.io/client-go/informers"
corev1informers "k8s.io/client-go/informers/core/v1"
"k8s.io/client-go/kubernetes"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/constable"
"go.pinniped.dev/internal/controller/apicerts"
@ -339,10 +339,7 @@ func waitForSignal() os.Signal {
return <-signalCh
}
func run() error {
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
func run(ctx context.Context) error {
client, err := kubeclient.New()
if err != nil {
return fmt.Errorf("cannot create k8s client: %w", err)
@ -378,13 +375,35 @@ func run() error {
return nil
}
func Main() {
func main() error { // return an error instead of plog.Fatal to allow defer statements to run
ctx := signalCtx()
// Hardcode the logging level to debug, since this is a test app and it is very helpful to have
// verbose logs to debug test failures.
if err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug); err != nil {
klog.Fatal(err)
if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, plog.LogSpec{Level: plog.LevelDebug}); err != nil {
plog.Fatal(err)
}
if err := run(); err != nil {
klog.Fatal(err)
return run(ctx)
}
func Main() {
if err := main(); err != nil {
plog.Fatal(err)
}
}
func signalCtx() context.Context {
signalCh := make(chan os.Signal, 1)
signal.Notify(signalCh, os.Interrupt, syscall.SIGTERM)
ctx, cancel := context.WithCancel(context.Background())
go func() {
defer cancel()
s := <-signalCh
plog.Debug("saw signal", "signal", s)
}()
return ctx
}

107
internal/plog/config.go Normal file
View File

@ -0,0 +1,107 @@
// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"context"
"encoding/json"
"strconv"
"time"
"go.uber.org/zap/zapcore"
"k8s.io/apimachinery/pkg/util/wait"
"k8s.io/component-base/logs"
"go.pinniped.dev/internal/constable"
)
type LogFormat string
func (l *LogFormat) UnmarshalJSON(b []byte) error {
switch string(b) {
case `""`, `"json"`:
*l = FormatJSON
case `"text"`:
*l = FormatText
// there is no "cli" case because it is not a supported option via our config
default:
return errInvalidLogFormat
}
return nil
}
const (
FormatJSON LogFormat = "json"
FormatText LogFormat = "text"
FormatCLI LogFormat = "cli" // only used by the pinniped CLI and not the server components
errInvalidLogLevel = constable.Error("invalid log level, valid choices are the empty string, info, debug, trace and all")
errInvalidLogFormat = constable.Error("invalid log format, valid choices are the empty string, json and text")
)
var _ json.Unmarshaler = func() *LogFormat {
var f LogFormat
return &f
}()
type LogSpec struct {
Level LogLevel `json:"level,omitempty"`
Format LogFormat `json:"format,omitempty"`
}
func MaybeSetDeprecatedLogLevel(level *LogLevel, log *LogSpec) {
if level != nil {
Warning("logLevel is deprecated, set log.level instead")
log.Level = *level
}
}
func ValidateAndSetLogLevelAndFormatGlobally(ctx context.Context, spec LogSpec) error {
klogLevel := klogLevelForPlogLevel(spec.Level)
if klogLevel < 0 {
return errInvalidLogLevel
}
// set the global log levels used by our code and the kube code underneath us
if _, err := logs.GlogSetter(strconv.Itoa(int(klogLevel))); err != nil {
panic(err) // programmer error
}
globalLevel.SetLevel(zapcore.Level(-klogLevel)) // klog levels are inverted when zap handles them
var encoding string
switch spec.Format {
case "", FormatJSON:
encoding = "json"
case FormatCLI:
encoding = "console"
case FormatText:
encoding = "text"
default:
return errInvalidLogFormat
}
log, flush, err := newLogr(ctx, encoding, klogLevel)
if err != nil {
return err
}
setGlobalLoggers(log, flush)
// nolint: exhaustive // the switch above is exhaustive for format already
switch spec.Format {
case FormatCLI:
return nil // do not spawn go routines on the CLI to allow the CLI to call this more than once
case FormatText:
Warning("setting log.format to 'text' is deprecated - this option will be removed in a future release")
}
// do spawn go routines on the server
go wait.UntilWithContext(ctx, func(_ context.Context) { flush() }, time.Minute)
go func() {
<-ctx.Done()
flush() // best effort flush before shutdown as this is not coordinated with a wait group
}()
return nil
}

359
internal/plog/config_test.go Normal file
View File

@ -0,0 +1,359 @@
// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"bufio"
"bytes"
"context"
"fmt"
"os"
"runtime"
"strconv"
"testing"
"time"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
"k8s.io/klog/v2/textlogger"
clocktesting "k8s.io/utils/clock/testing"
)
func TestFormat(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background())
t.Cleanup(cancel)
var buf bytes.Buffer
scanner := bufio.NewScanner(&buf)
now, err := time.Parse(time.RFC3339Nano, "2022-11-21T23:37:26.953313745Z")
require.NoError(t, err)
fakeClock := clocktesting.NewFakeClock(now)
nowStr := now.Local().Format(time.RFC1123)
ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock)))
err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug})
require.NoError(t, err)
wd, err := os.Getwd()
require.NoError(t, err)
const startLogLine = 46 // make this match the current line number
Info("hello", "happy", "day", "duration", time.Hour+time.Minute)
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.JSONEq(t, fmt.Sprintf(`
{
"level": "info",
"timestamp": "2022-11-21T23:37:26.953313Z",
"caller": "%s/config_test.go:%d$plog.TestFormat",
"message": "hello",
"happy": "day",
"duration": "1h1m0s"
}`, wd, startLogLine+2), scanner.Text())
Logr().WithName("burrito").Error(errInvalidLogLevel, "wee", "a", "b")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.JSONEq(t, fmt.Sprintf(`
{
"level": "error",
"timestamp": "2022-11-21T23:37:26.953313Z",
"caller": "%s/config_test.go:%d$plog.TestFormat",
"message": "wee",
"a": "b",
"error": "invalid log level, valid choices are the empty string, info, debug, trace and all",
"logger": "burrito"
}`, wd, startLogLine+2+13), scanner.Text())
Logr().V(klogLevelWarning).Info("hey") // note that this fails to set the custom warning key because it is not via plog
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.JSONEq(t, fmt.Sprintf(`
{
"level": "info",
"timestamp": "2022-11-21T23:37:26.953313Z",
"caller": "%s/config_test.go:%d$plog.TestFormat",
"message": "hey"
}`, wd, startLogLine+2+13+14), scanner.Text())
Warning("bad stuff") // note that this sets the custom warning key because it is via plog
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.JSONEq(t, fmt.Sprintf(`
{
"level": "info",
"timestamp": "2022-11-21T23:37:26.953313Z",
"caller": "%s/config_test.go:%d$plog.TestFormat",
"message": "bad stuff",
"warning": true
}`, wd, startLogLine+2+13+14+11), scanner.Text())
func() { DebugErr("something happened", errInvalidLogFormat, "an", "item") }()
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.JSONEq(t, fmt.Sprintf(`
{
"level": "debug",
"timestamp": "2022-11-21T23:37:26.953313Z",
"caller": "%s/config_test.go:%d$plog.TestFormat.func1",
"message": "something happened",
"error": "invalid log format, valid choices are the empty string, json and text",
"an": "item"
}`, wd, startLogLine+2+13+14+11+12), scanner.Text())
Trace("should not be logged", "for", "sure")
require.Empty(t, buf.String())
Logr().V(klogLevelAll).Info("also should not be logged", "open", "close")
require.Empty(t, buf.String())
ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock)), zap.AddStacktrace(LevelInfo))
err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug})
require.NoError(t, err)
WithName("stacky").WithName("does").Info("has a stack trace!")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.JSONEq(t, fmt.Sprintf(`
{
"level": "info",
"timestamp": "2022-11-21T23:37:26.953313Z",
"caller": "%s/config_test.go:%d$plog.TestFormat",
"message": "has a stack trace!",
"logger": "stacky.does",
"stacktrace": %s
}`, wd, startLogLine+2+13+14+11+12+24,
strconv.Quote(
fmt.Sprintf(
`go.pinniped.dev/internal/plog.TestFormat
%s/config_test.go:%d
testing.tRunner
%s/src/testing/testing.go:1439`,
wd, startLogLine+2+13+14+11+12+24, runtime.GOROOT(),
),
),
), scanner.Text())
ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock)))
err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug, Format: FormatCLI})
require.NoError(t, err)
DebugErr("something happened", errInvalidLogFormat, "an", "item")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(nowStr+` plog/config_test.go:%d something happened {"error": "invalid log format, valid choices are the empty string, json and text", "an": "item"}`,
startLogLine+2+13+14+11+12+24+28), scanner.Text())
Logr().WithName("burrito").Error(errInvalidLogLevel, "wee", "a", "b", "slightly less than a year", 363*24*time.Hour, "slightly more than 2 years", 2*367*24*time.Hour)
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(nowStr+` burrito plog/config_test.go:%d wee {"a": "b", "slightly less than a year": "363d", "slightly more than 2 years": "2y4d", "error": "invalid log level, valid choices are the empty string, info, debug, trace and all"}`,
startLogLine+2+13+14+11+12+24+28+6), scanner.Text())
origTimeNow := textlogger.TimeNow
t.Cleanup(func() {
textlogger.TimeNow = origTimeNow
})
textlogger.TimeNow = func() time.Time {
return now
}
old := New().WithName("created before mode change").WithValues("is", "old")
err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug, Format: FormatText})
require.NoError(t, err)
pid := os.Getpid()
// check for the deprecation warning
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config.go:96] "setting log.format to 'text' is deprecated - this option will be removed in a future release" warning=true`,
pid), scanner.Text())
Debug("what is happening", "does klog", "work?")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "what is happening" does klog="work?"`,
pid, startLogLine+2+13+14+11+12+24+28+6+26), scanner.Text())
Logr().WithName("panda").V(KlogLevelDebug).Info("are the best", "yes?", "yes.")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "panda: are the best" yes?="yes."`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6), scanner.Text())
New().WithName("hi").WithName("there").WithValues("a", 1, "b", 2).Always("do it")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "hi/there: do it" a=1 b=2`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6), scanner.Text())
l := WithValues("x", 33, "z", 22)
l.Debug("what to do")
l.Debug("and why")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "what to do" x=33 z=22`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7), scanner.Text())
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "and why" x=33 z=22`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1), scanner.Text())
old.Always("should be klog text format", "for", "sure")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change: should be klog text format" is="old" for="sure"`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10), scanner.Text())
// make sure child loggers do not share state
old1 := old.WithValues("i am", "old1")
old2 := old.WithName("old2")
old1.Warning("warn")
old2.Info("info")
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change: warn" is="old" i am="old1" warning=true`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+9), scanner.Text())
require.True(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change/old2: info" is="old"`,
pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+9+1), scanner.Text())
Trace("should not be logged", "for", "sure")
require.Empty(t, buf.String())
Logr().V(klogLevelAll).Info("also should not be logged", "open", "close")
require.Empty(t, buf.String())
require.False(t, scanner.Scan())
require.NoError(t, scanner.Err())
require.Empty(t, scanner.Text())
require.Empty(t, buf.String())
}
func TestValidateAndSetLogLevelGlobally(t *testing.T) {
originalLogLevel := getKlogLevel()
require.GreaterOrEqual(t, int(originalLogLevel), int(klog.Level(0)), "cannot get klog level")
tests := []struct {
name string
level LogLevel
wantLevel klog.Level
wantEnabled []LogLevel
wantErr string
}{
{
name: "unset",
wantLevel: 0,
wantEnabled: []LogLevel{LevelWarning},
},
{
name: "warning",
level: LevelWarning,
wantLevel: 0,
wantEnabled: []LogLevel{LevelWarning},
},
{
name: "info",
level: LevelInfo,
wantLevel: 2,
wantEnabled: []LogLevel{LevelWarning, LevelInfo},
},
{
name: "debug",
level: LevelDebug,
wantLevel: 4,
wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug},
},
{
name: "trace",
level: LevelTrace,
wantLevel: 6,
wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace},
},
{
name: "all",
level: LevelAll,
wantLevel: 108,
wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll},
},
{
name: "invalid level",
level: "panda",
wantLevel: originalLogLevel,
wantErr: errInvalidLogLevel.Error(),
},
}
for _, tt := range tests {
tt := tt // capture range variable
t.Run(tt.name, func(t *testing.T) {
defer func() {
undoGlobalLogLevelChanges(t, originalLogLevel)
}()
ctx, cancel := context.WithCancel(context.Background())
t.Cleanup(cancel)
err := ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: tt.level})
require.Equal(t, tt.wantErr, errString(err))
require.Equal(t, tt.wantLevel, getKlogLevel())
if tt.wantEnabled != nil {
allLevels := []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll}
for _, level := range allLevels {
if contains(tt.wantEnabled, level) {
require.Truef(t, Enabled(level), "wanted %q to be enabled", level)
} else {
require.False(t, Enabled(level), "did not want %q to be enabled", level)
}
}
}
})
}
require.Equal(t, originalLogLevel, getKlogLevel())
}
func contains(haystack []LogLevel, needle LogLevel) bool {
for _, hay := range haystack {
if hay == needle {
return true
}
}
return false
}
func errString(err error) string {
if err == nil {
return ""
}
return err.Error()
}
func undoGlobalLogLevelChanges(t *testing.T, originalLogLevel klog.Level) {
t.Helper()
_, err := logs.GlogSetter(strconv.Itoa(int(originalLogLevel)))
require.NoError(t, err)
}
func getKlogLevel() klog.Level {
// hack around klog not exposing a Get method
for i := klog.Level(0); i < 256; i++ {
if klog.V(i).Enabled() {
continue
}
return i - 1
}
return -1
}

77
internal/plog/global.go Normal file
View File

@ -0,0 +1,77 @@
// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"context"
"fmt"
"net/url"
"sync"
"github.com/go-logr/logr"
"go.uber.org/zap"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
)
// nolint: gochecknoglobals
var (
// note that these globals have no locks on purpose - they are expected to be set at init and then again after config parsing.
globalLevel zap.AtomicLevel
globalLogger logr.Logger
globalFlush func()
// used as a temporary storage for a buffer per call of newLogr. see the init function below for more details.
sinkMap sync.Map
)
// nolint: gochecknoinits
func init() {
// make sure we always have a functional global logger
globalLevel = zap.NewAtomicLevelAt(0) // log at the 0 verbosity level to start with, i.e. the "always" logs
// use json encoding to start with
// the context here is just used for test injection and thus can be ignored
log, flush, err := newLogr(context.Background(), "json", 0)
if err != nil {
panic(err) // default logging config must always work
}
setGlobalLoggers(log, flush)
// this is a little crazy but zap's builder code does not allow us to directly specify what
// writer we want to use as our log sink. to get around this limitation in tests, we use a
// global map to temporarily hold the writer (the key is a random string that is generated
// per invocation of newLogr). we register a fake "pinniped" scheme so that we can lookup
// the writer via pinniped:///<per newLogr invocation random string>.
if err := zap.RegisterSink("pinniped", func(u *url.URL) (zap.Sink, error) {
value, ok := sinkMap.Load(u.Path)
if !ok {
return nil, fmt.Errorf("key %q not in global sink", u.Path)
}
return value.(zap.Sink), nil
}); err != nil {
panic(err) // custom sink must always work
}
}
// Deprecated: Use New instead. This is meant for old code only.
// New provides a more ergonomic API and correctly responds to global log config change.
func Logr() logr.Logger {
return globalLogger
}
func Setup() func() {
logs.InitLogs()
return func() {
logs.FlushLogs()
globalFlush()
}
}
// setGlobalLoggers sets the plog and klog global loggers. it is *not* go routine safe.
func setGlobalLoggers(log logr.Logger, flush func()) {
// a contextual logger does its own level based enablement checks, which is true for all of our loggers
klog.SetLoggerWithOptions(log, klog.ContextualLogger(true), klog.FlushLogger(flush))
globalLogger = log
globalFlush = flush
}

32
internal/plog/klog.go
View File

@ -1,32 +0,0 @@
// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"fmt"
"k8s.io/klog/v2"
)
// KObj is (mostly) copied from klog - it is a standard way to represent a metav1.Object in logs.
func KObj(obj klog.KMetadata) string {
return fmt.Sprintf("%s/%s", obj.GetNamespace(), obj.GetName())
}
func klogLevelForPlogLevel(plogLevel LogLevel) klog.Level {
switch plogLevel {
case LevelWarning:
return klogLevelWarning // unset means minimal logs (Error and Warning)
case LevelInfo:
return klogLevelInfo
case LevelDebug:
return klogLevelDebug
case LevelTrace:
return klogLevelTrace
case LevelAll:
return klogLevelAll + 100 // make all really mean all
default:
return -1
}
}

55
internal/plog/level.go
View File

@ -4,18 +4,18 @@
package plog
import (
"strconv"
"k8s.io/component-base/logs"
"go.uber.org/zap/zapcore"
"k8s.io/klog/v2"
"go.pinniped.dev/internal/constable"
)
// LogLevel is an enum that controls verbosity of logs.
// Valid values in order of increasing verbosity are leaving it unset, info, debug, trace and all.
type LogLevel string
func (l LogLevel) Enabled(_ zapcore.Level) bool {
return Enabled(l) // this basically says "log if the global plog level is l or greater"
}
const (
// LevelWarning (i.e. leaving the log level unset) maps to klog log level 0.
LevelWarning LogLevel = ""
@ -27,33 +27,40 @@ const (
LevelTrace LogLevel = "trace"
// LevelAll maps to klog log level 100 (conceptually it is log level 8).
LevelAll LogLevel = "all"
errInvalidLogLevel = constable.Error("invalid log level, valid choices are the empty string, info, debug, trace and all")
)
var _ zapcore.LevelEnabler = LevelWarning
const (
klogLevelWarning = iota * 2
klogLevelInfo
klogLevelDebug
klogLevelTrace
KlogLevelInfo
KlogLevelDebug
KlogLevelTrace
klogLevelAll
)
func ValidateAndSetLogLevelGlobally(level LogLevel) error {
klogLevel := klogLevelForPlogLevel(level)
if klogLevel < 0 {
return errInvalidLogLevel
}
if _, err := logs.GlogSetter(strconv.Itoa(int(klogLevel))); err != nil {
panic(err) // programmer error
}
return nil
}
// Enabled returns whether the provided plog level is enabled, i.e., whether print statements at the
// provided level will show up.
func Enabled(level LogLevel) bool {
return klog.V(klogLevelForPlogLevel(level)).Enabled()
l := klogLevelForPlogLevel(level)
// check that both our global level and the klog global level agree that the plog level is enabled
// klog levels are inverted when zap handles them
return globalLevel.Enabled(zapcore.Level(-l)) && klog.V(l).Enabled()
}
func klogLevelForPlogLevel(plogLevel LogLevel) klog.Level {
switch plogLevel {
case LevelWarning:
return klogLevelWarning // unset means minimal logs (Error and Warning)
case LevelInfo:
return KlogLevelInfo
case LevelDebug:
return KlogLevelDebug
case LevelTrace:
return KlogLevelTrace
case LevelAll:
return klogLevelAll + 100 // make all really mean all
default:
return -1
}
}

128
internal/plog/level_test.go
View File

@ -1,128 +0,0 @@
// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"strconv"
"testing"
"github.com/stretchr/testify/require"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
)
func TestValidateAndSetLogLevelGlobally(t *testing.T) {
originalLogLevel := getKlogLevel()
require.GreaterOrEqual(t, int(originalLogLevel), int(klog.Level(0)), "cannot get klog level")
tests := []struct {
name string
level LogLevel
wantLevel klog.Level
wantEnabled []LogLevel
wantErr string
}{
{
name: "unset",
wantLevel: 0,
wantEnabled: []LogLevel{LevelWarning},
},
{
name: "warning",
level: LevelWarning,
wantLevel: 0,
wantEnabled: []LogLevel{LevelWarning},
},
{
name: "info",
level: LevelInfo,
wantLevel: 2,
wantEnabled: []LogLevel{LevelWarning, LevelInfo},
},
{
name: "debug",
level: LevelDebug,
wantLevel: 4,
wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug},
},
{
name: "trace",
level: LevelTrace,
wantLevel: 6,
wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace},
},
{
name: "all",
level: LevelAll,
wantLevel: 108,
wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll},
},
{
name: "invalid level",
level: "panda",
wantLevel: originalLogLevel,
wantErr: errInvalidLogLevel.Error(),
},
}
for _, tt := range tests {
tt := tt // capture range variable
t.Run(tt.name, func(t *testing.T) {
defer func() {
undoGlobalLogLevelChanges(t, originalLogLevel)
}()
err := ValidateAndSetLogLevelGlobally(tt.level)
require.Equal(t, tt.wantErr, errString(err))
require.Equal(t, tt.wantLevel, getKlogLevel())
if tt.wantEnabled != nil {
allLevels := []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll}
for _, level := range allLevels {
if contains(tt.wantEnabled, level) {
require.Truef(t, Enabled(level), "wanted %q to be enabled", level)
} else {
require.False(t, Enabled(level), "did not want %q to be enabled", level)
}
}
}
})
}
require.Equal(t, originalLogLevel, getKlogLevel())
}
func contains(haystack []LogLevel, needle LogLevel) bool {
for _, hay := range haystack {
if hay == needle {
return true
}
}
return false
}
func errString(err error) string {
if err == nil {
return ""
}
return err.Error()
}
func undoGlobalLogLevelChanges(t *testing.T, originalLogLevel klog.Level) {
t.Helper()
_, err := logs.GlogSetter(strconv.Itoa(int(originalLogLevel)))
require.NoError(t, err)
}
func getKlogLevel() klog.Level {
// hack around klog not exposing a Get method
for i := klog.Level(0); i < 256; i++ {
if klog.V(i).Enabled() {
continue
}
return i - 1
}
return -1
}

171
internal/plog/plog.go
View File

@ -1,7 +1,7 @@
// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
// Package plog implements a thin layer over klog to help enforce pinniped's logging convention.
// Package plog implements a thin layer over logr to help enforce pinniped's logging convention.
// Logs are always structured as a constant message with key and value pairs of related metadata.
//
// The logging levels in order of increasing verbosity are:
@ -26,10 +26,18 @@
// act of desperation to determine why the system is broken.
package plog
import "k8s.io/klog/v2"
import (
"os"
const errorKey = "error"
"github.com/go-logr/logr"
)
const errorKey = "error" // this matches zapr's default for .Error calls (which is asserted via tests)
// Logger implements the plog logging convention described above. The global functions in this package
// such as Info should be used when one does not intend to write tests assertions for specific log messages.
// If test assertions are desired, Logger should be passed in as an input. New should be used as the
// production implementation and TestLogger should be used to write test assertions.
type Logger interface {
Error(msg string, err error, keysAndValues ...interface{})
Warning(msg string, keysAndValues ...interface{})
@ -41,100 +49,155 @@ type Logger interface {
Trace(msg string, keysAndValues ...interface{})
TraceErr(msg string, err error, keysAndValues ...interface{})
All(msg string, keysAndValues ...interface{})
Always(msg string, keysAndValues ...interface{})
WithValues(keysAndValues ...interface{}) Logger
WithName(name string) Logger
// does not include Fatal on purpose because that is not a method you should be using
// for internal and test use only
withDepth(d int) Logger
withLogrMod(mod func(logr.Logger) logr.Logger) Logger
}
// MinLogger is the overlap between Logger and logr.Logger.
type MinLogger interface {
Info(msg string, keysAndValues ...interface{})
}
var _ Logger = pLogger{}
var _, _, _ MinLogger = pLogger{}, logr.Logger{}, Logger(nil)
type pLogger struct {
prefix string
mods []func(logr.Logger) logr.Logger
depth int
}
func New(prefix string) Logger {
return &pLogger{
depth: 0,
prefix: prefix,
}
func New() Logger {
return pLogger{}
}
func (p *pLogger) Error(msg string, err error, keysAndValues ...interface{}) {
klog.ErrorSDepth(p.depth+1, err, p.prefix+msg, keysAndValues...)
func (p pLogger) Error(msg string, err error, keysAndValues ...interface{}) {
p.logr().WithCallDepth(p.depth+1).Error(err, msg, keysAndValues...)
}
func (p *pLogger) warningDepth(msg string, depth int, keysAndValues ...interface{}) {
func (p pLogger) warningDepth(msg string, depth int, keysAndValues ...interface{}) {
if p.logr().V(klogLevelWarning).Enabled() {
// klog's structured logging has no concept of a warning (i.e. no WarningS function)
// Thus we use info at log level zero as a proxy
// klog's info logs have an I prefix and its warning logs have a W prefix
// Since we lose the W prefix by using InfoS, just add a key to make these easier to find
keysAndValues = append([]interface{}{"warning", "true"}, keysAndValues...)
if klog.V(klogLevelWarning).Enabled() {
klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...)
keysAndValues = append([]interface{}{"warning", true}, keysAndValues...)
p.logr().V(klogLevelWarning).WithCallDepth(depth+1).Info(msg, keysAndValues...)
}
}
func (p *pLogger) Warning(msg string, keysAndValues ...interface{}) {
func (p pLogger) Warning(msg string, keysAndValues ...interface{}) {
p.warningDepth(msg, p.depth+1, keysAndValues...)
}
// Use WarningErr to issue a Warning message with an error object as part of the message.
func (p *pLogger) WarningErr(msg string, err error, keysAndValues ...interface{}) {
func (p pLogger) WarningErr(msg string, err error, keysAndValues ...interface{}) {
p.warningDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...)
}
func (p *pLogger) infoDepth(msg string, depth int, keysAndValues ...interface{}) {
if klog.V(klogLevelInfo).Enabled() {
klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...)
func (p pLogger) infoDepth(msg string, depth int, keysAndValues ...interface{}) {
if p.logr().V(KlogLevelInfo).Enabled() {
p.logr().V(KlogLevelInfo).WithCallDepth(depth+1).Info(msg, keysAndValues...)
}
}
func (p *pLogger) Info(msg string, keysAndValues ...interface{}) {
func (p pLogger) Info(msg string, keysAndValues ...interface{}) {
p.infoDepth(msg, p.depth+1, keysAndValues...)
}
// Use InfoErr to log an expected error, e.g. validation failure of an http parameter.
func (p *pLogger) InfoErr(msg string, err error, keysAndValues ...interface{}) {
func (p pLogger) InfoErr(msg string, err error, keysAndValues ...interface{}) {
p.infoDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...)
}
func (p *pLogger) debugDepth(msg string, depth int, keysAndValues ...interface{}) {
if klog.V(klogLevelDebug).Enabled() {
klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...)
func (p pLogger) debugDepth(msg string, depth int, keysAndValues ...interface{}) {
if p.logr().V(KlogLevelDebug).Enabled() {
p.logr().V(KlogLevelDebug).WithCallDepth(depth+1).Info(msg, keysAndValues...)
}
}
func (p *pLogger) Debug(msg string, keysAndValues ...interface{}) {
func (p pLogger) Debug(msg string, keysAndValues ...interface{}) {
p.debugDepth(msg, p.depth+1, keysAndValues...)
}
// Use DebugErr to issue a Debug message with an error object as part of the message.
func (p *pLogger) DebugErr(msg string, err error, keysAndValues ...interface{}) {
func (p pLogger) DebugErr(msg string, err error, keysAndValues ...interface{}) {
p.debugDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...)
}
func (p *pLogger) traceDepth(msg string, depth int, keysAndValues ...interface{}) {
if klog.V(klogLevelTrace).Enabled() {
klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...)
func (p pLogger) traceDepth(msg string, depth int, keysAndValues ...interface{}) {
if p.logr().V(KlogLevelTrace).Enabled() {
p.logr().V(KlogLevelTrace).WithCallDepth(depth+1).Info(msg, keysAndValues...)
}
}
func (p *pLogger) Trace(msg string, keysAndValues ...interface{}) {
func (p pLogger) Trace(msg string, keysAndValues ...interface{}) {
p.traceDepth(msg, p.depth+1, keysAndValues...)
}
// Use TraceErr to issue a Trace message with an error object as part of the message.
func (p *pLogger) TraceErr(msg string, err error, keysAndValues ...interface{}) {
func (p pLogger) TraceErr(msg string, err error, keysAndValues ...interface{}) {
p.traceDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...)
}
func (p *pLogger) All(msg string, keysAndValues ...interface{}) {
if klog.V(klogLevelAll).Enabled() {
klog.InfoSDepth(p.depth+1, p.prefix+msg, keysAndValues...)
func (p pLogger) All(msg string, keysAndValues ...interface{}) {
if p.logr().V(klogLevelAll).Enabled() {
p.logr().V(klogLevelAll).WithCallDepth(p.depth+1).Info(msg, keysAndValues...)
}
}
var logger Logger = &pLogger{ //nolint:gochecknoglobals
depth: 1,
func (p pLogger) Always(msg string, keysAndValues ...interface{}) {
p.logr().WithCallDepth(p.depth+1).Info(msg, keysAndValues...)
}
// Use Error to log an unexpected system error.
func (p pLogger) WithValues(keysAndValues ...interface{}) Logger {
if len(keysAndValues) == 0 {
return p
}
return p.withLogrMod(func(l logr.Logger) logr.Logger {
return l.WithValues(keysAndValues...)
})
}
func (p pLogger) WithName(name string) Logger {
if len(name) == 0 {
return p
}
return p.withLogrMod(func(l logr.Logger) logr.Logger {
return l.WithName(name)
})
}
func (p pLogger) withDepth(d int) Logger {
out := p
out.depth += d // out is a copy so this does not mutate p
return out
}
func (p pLogger) withLogrMod(mod func(logr.Logger) logr.Logger) Logger {
out := p // make a copy and carefully avoid mutating the mods slice
mods := make([]func(logr.Logger) logr.Logger, 0, len(out.mods)+1)
mods = append(mods, out.mods...)
mods = append(mods, mod)
out.mods = mods
return out
}
func (p pLogger) logr() logr.Logger {
l := Logr() // grab the current global logger and its current config
for _, mod := range p.mods {
mod := mod
l = mod(l) // and then update it with all modifications
}
return l // this logger is guaranteed to have the latest config and all modifications
}
var logger = New().withDepth(1) //nolint:gochecknoglobals
func Error(msg string, err error, keysAndValues ...interface{}) {
logger.Error(msg, err, keysAndValues...)
}
@ -143,7 +206,6 @@ func Warning(msg string, keysAndValues ...interface{}) {
logger.Warning(msg, keysAndValues...)
}
// Use WarningErr to issue a Warning message with an error object as part of the message.
func WarningErr(msg string, err error, keysAndValues ...interface{}) {
logger.WarningErr(msg, err, keysAndValues...)
}
@ -152,7 +214,6 @@ func Info(msg string, keysAndValues ...interface{}) {
logger.Info(msg, keysAndValues...)
}
// Use InfoErr to log an expected error, e.g. validation failure of an http parameter.
func InfoErr(msg string, err error, keysAndValues ...interface{}) {
logger.InfoErr(msg, err, keysAndValues...)
}
@ -161,7 +222,6 @@ func Debug(msg string, keysAndValues ...interface{}) {
logger.Debug(msg, keysAndValues...)
}
// Use DebugErr to issue a Debug message with an error object as part of the message.
func DebugErr(msg string, err error, keysAndValues ...interface{}) {
logger.DebugErr(msg, err, keysAndValues...)
}
@ -170,7 +230,6 @@ func Trace(msg string, keysAndValues ...interface{}) {
logger.Trace(msg, keysAndValues...)
}
// Use TraceErr to issue a Trace message with an error object as part of the message.
func TraceErr(msg string, err error, keysAndValues ...interface{}) {
logger.TraceErr(msg, err, keysAndValues...)
}
@ -178,3 +237,23 @@ func TraceErr(msg string, err error, keysAndValues ...interface{}) {
func All(msg string, keysAndValues ...interface{}) {
logger.All(msg, keysAndValues...)
}
func Always(msg string, keysAndValues ...interface{}) {
logger.Always(msg, keysAndValues...)
}
func WithValues(keysAndValues ...interface{}) Logger {
// this looks weird but it is the same as New().WithValues(keysAndValues...) because it returns a new logger rooted at the call site
return logger.withDepth(-1).WithValues(keysAndValues...)
}
func WithName(name string) Logger {
// this looks weird but it is the same as New().WithName(name) because it returns a new logger rooted at the call site
return logger.withDepth(-1).WithName(name)
}
func Fatal(err error, keysAndValues ...interface{}) {
logger.Error("unrecoverable error encountered", err, keysAndValues...)
globalFlush()
os.Exit(1)
}

366
internal/plog/plog_test.go Normal file
View File

@ -0,0 +1,366 @@
// Copyright 2022 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"bytes"
"fmt"
"strings"
"testing"
"time"
"github.com/stretchr/testify/require"
)
func TestPlog(t *testing.T) {
tests := []struct {
name string
run func(Logger)
want string
}{
{
name: "basic",
run: testAllPlogMethods,
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":2}
`,
},
{
name: "with values",
run: func(l Logger) {
testAllPlogMethods(l.WithValues("hi", 42))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","hi":42,"panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","hi":42,"warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","hi":42,"warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","hi":42,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","hi":42,"error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","hi":42,"panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","hi":42,"error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","hi":42,"panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","hi":42,"error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","hi":42,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","hi":42,"panda":2}
`,
},
{
name: "with values conflict", // duplicate key is included twice ...
run: func(l Logger) {
testAllPlogMethods(l.WithValues("panda", false))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":false,"panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","panda":false,"warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","panda":false,"warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","panda":false,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","panda":false,"error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":false,"panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","panda":false,"error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":false,"panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","panda":false,"error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":false,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":false,"panda":2}
`,
},
{
name: "with values nested",
run: func(l Logger) {
testAllPlogMethods(l.WithValues("hi", 42).WithValues("not", time.Hour))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","hi":42,"not":"1h0m0s","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","hi":42,"not":"1h0m0s","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","hi":42,"not":"1h0m0s","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","hi":42,"not":"1h0m0s","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","hi":42,"not":"1h0m0s","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","hi":42,"not":"1h0m0s","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","hi":42,"not":"1h0m0s","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","hi":42,"not":"1h0m0s","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","hi":42,"not":"1h0m0s","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","hi":42,"not":"1h0m0s","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","hi":42,"not":"1h0m0s","panda":2}
`,
},
{
name: "with name",
run: func(l Logger) {
testAllPlogMethods(l.WithName("yoyo"))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":2}
`,
},
{
name: "with name nested",
run: func(l Logger) {
testAllPlogMethods(l.WithName("yoyo").WithName("gold"))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":2}
`,
},
{
name: "depth 3",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(3))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"always","panda":2}
`,
},
{
name: "depth 2",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(2))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func15","message":"always","panda":2}
`,
},
{
name: "depth 1",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(1))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"always","panda":2}
`,
},
{
name: "depth 0",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(0))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":2}
`,
},
{
name: "depth -1",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(-1))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Warning","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Debug","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Trace","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.All","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Always","message":"always","panda":2}
`,
},
{
name: "depth -2",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(-2))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.warningDepth","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.warningDepth","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.infoDepth","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.infoDepth","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.debugDepth","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.debugDepth","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.traceDepth","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.traceDepth","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"always","panda":2}
`,
},
{
name: "depth -3",
run: func(l Logger) {
testAllPlogMethods(l.withDepth(-3))
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.2.3/zapr.go:<line>$zapr.(*zapLogger).Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:<line>$logr.Logger.Info","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.2.3/zapr.go:<line>$zapr.(*zapLogger).Info","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.2.3/zapr.go:<line>$zapr.(*zapLogger).Info","message":"always","panda":2}
`,
},
{
name: "closure",
run: func(l Logger) {
func() {
func() {
testErr := fmt.Errorf("some err")
l.Error("e", testErr, "panda", 2)
l.Warning("w", "panda", 2)
l.WarningErr("we", testErr, "panda", 2)
l.Info("i", "panda", 2)
l.InfoErr("ie", testErr, "panda", 2)
l.Debug("d", "panda", 2)
l.DebugErr("de", testErr, "panda", 2)
l.Trace("t", "panda", 2)
l.TraceErr("te", testErr, "panda", 2)
l.All("all", "panda", 2)
l.Always("always", "panda", 2)
}()
}()
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func13.1.1","message":"always","panda":2}
`,
},
{
name: "closure depth -1",
run: func(l Logger) {
func() {
func() {
testErr := fmt.Errorf("some err")
l = l.withDepth(-1)
l.Error("e", testErr, "panda", 2)
l.Warning("w", "panda", 2)
l.WarningErr("we", testErr, "panda", 2)
l.Info("i", "panda", 2)
l.InfoErr("ie", testErr, "panda", 2)
l.Debug("d", "panda", 2)
l.DebugErr("de", testErr, "panda", 2)
l.Trace("t", "panda", 2)
l.TraceErr("te", testErr, "panda", 2)
l.All("all", "panda", 2)
l.Always("always", "panda", 2)
}()
}()
},
want: `
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Warning","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Debug","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Trace","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.All","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Always","message":"always","panda":2}
`,
},
}
for _, tt := range tests {
tt := tt
t.Run(tt.name, func(t *testing.T) {
t.Parallel()
var log bytes.Buffer
tt.run(TestLogger(t, &log))
require.Equal(t, strings.TrimSpace(tt.want), strings.TrimSpace(log.String()))
})
}
}
func testAllPlogMethods(l Logger) {
testErr := fmt.Errorf("some err")
l.Error("e", testErr, "panda", 2)
l.Warning("w", "panda", 2)
l.WarningErr("we", testErr, "panda", 2)
l.Info("i", "panda", 2)
l.InfoErr("ie", testErr, "panda", 2)
l.Debug("d", "panda", 2)
l.DebugErr("de", testErr, "panda", 2)
l.Trace("t", "panda", 2)
l.TraceErr("te", testErr, "panda", 2)
l.All("all", "panda", 2)
l.Always("always", "panda", 2)
}

120
internal/plog/testing.go Normal file
View File

@ -0,0 +1,120 @@
// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"context"
"io"
"math"
"strings"
"testing"
"time"
"github.com/go-logr/logr"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"k8s.io/utils/clock"
clocktesting "k8s.io/utils/clock/testing"
)
// contextKey type is unexported to prevent collisions.
type contextKey int
const zapOverridesKey contextKey = iota
func TestZapOverrides(ctx context.Context, t *testing.T, w io.Writer, f func(*zap.Config), opts ...zap.Option) context.Context {
t.Helper() // discourage use outside of tests
overrides := &testOverrides{
t: t,
w: w,
f: f,
opts: opts,
}
return context.WithValue(ctx, zapOverridesKey, overrides)
}
func TestLogger(t *testing.T, w io.Writer) Logger {
t.Helper()
return New().withLogrMod(func(l logr.Logger) logr.Logger {
return l.WithSink(TestZapr(t, w).GetSink())
})
}
func TestZapr(t *testing.T, w io.Writer) logr.Logger {
t.Helper()
now, err := time.Parse(time.RFC3339Nano, "2099-08-08T13:57:36.123456789Z")
require.NoError(t, err)
ctx, cancel := context.WithCancel(context.Background())
t.Cleanup(cancel)
ctx = TestZapOverrides(ctx, t, w,
func(config *zap.Config) {
config.Level = zap.NewAtomicLevelAt(math.MinInt8) // log everything during tests
// make test assertions less painful to write while keeping them as close to the real thing as possible
config.EncoderConfig.EncodeCaller = func(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) {
trimmed := caller.TrimmedPath()
if idx := strings.LastIndexByte(trimmed, ':'); idx != -1 {
trimmed = trimmed[:idx+1] + "<line>"
}
enc.AppendString(trimmed + funcEncoder(caller))
}
},
zap.WithClock(ZapClock(clocktesting.NewFakeClock(now))), // have the clock be static during tests
zap.AddStacktrace(nopLevelEnabler{}), // do not log stacktraces
)
// there is no buffering so we can ignore flush
zl, _, err := newLogr(ctx, "json", 0)
require.NoError(t, err)
return zl
}
var _ zapcore.Clock = &clockAdapter{}
type clockAdapter struct {
clock clock.Clock
}
func (c *clockAdapter) Now() time.Time {
return c.clock.Now()
}
func (c *clockAdapter) NewTicker(duration time.Duration) *time.Ticker {
return &time.Ticker{C: c.clock.Tick(duration)}
}
func ZapClock(c clock.Clock) zapcore.Clock {
return &clockAdapter{clock: c}
}
var _ zap.Sink = nopCloserSink{}
type nopCloserSink struct{ zapcore.WriteSyncer }
func (nopCloserSink) Close() error { return nil }
// newSink returns a wrapper around the input writer that is safe for concurrent use.
func newSink(w io.Writer) zap.Sink {
return nopCloserSink{WriteSyncer: zapcore.Lock(zapcore.AddSync(w))}
}
var _ zapcore.LevelEnabler = nopLevelEnabler{}
type nopLevelEnabler struct{}
func (nopLevelEnabler) Enabled(_ zapcore.Level) bool { return false }
type testOverrides struct {
t *testing.T
w io.Writer
f func(*zap.Config)
opts []zap.Option
}

187
internal/plog/zap.go Normal file
View File

@ -0,0 +1,187 @@
// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0
package plog
import (
"context"
"encoding/base64"
"fmt"
"io"
"os"
"strings"
"time"
"github.com/go-logr/logr"
"github.com/go-logr/zapr"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/util/duration"
"k8s.io/apimachinery/pkg/util/rand"
"k8s.io/klog/v2"
"k8s.io/klog/v2/textlogger"
)
func newLogr(ctx context.Context, encoding string, klogLevel klog.Level) (logr.Logger, func(), error) {
if encoding == "text" {
var w io.Writer = os.Stderr
flush := func() { _ = os.Stderr.Sync() }
// allow tests to override klog config (but cheat and re-use the zap override key)
if overrides, ok := ctx.Value(zapOverridesKey).(*testOverrides); ok {
if overrides.w != nil {
w = newSink(overrides.w) // make sure the value is safe for concurrent use
flush = func() {}
}
}
return textlogger.NewLogger(textlogger.NewConfig(textlogger.Verbosity(int(klogLevel)), textlogger.Output(w))), flush, nil
}
path := "stderr" // this is how zap refers to os.Stderr
f := func(config *zap.Config) {
if encoding == "console" {
config.EncoderConfig.LevelKey = zapcore.OmitKey
config.EncoderConfig.EncodeCaller = zapcore.ShortCallerEncoder
config.EncoderConfig.EncodeTime = humanTimeEncoder
config.EncoderConfig.EncodeDuration = humanDurationEncoder
}
}
var opts []zap.Option
// allow tests to override zap config
if overrides, ok := ctx.Value(zapOverridesKey).(*testOverrides); ok {
if overrides.w != nil {
// use a per invocation random string as the key into the global map
testKey := "/" + base64.RawURLEncoding.EncodeToString([]byte(rand.String(32)))
// tell zap to use our custom sink registry to find the writer
path = "pinniped://" + testKey
// the registry may be called multiple times so make sure the value is safe for concurrent use
sink := newSink(overrides.w)
// store the test's buffer where we can find it globally
actual, loaded := sinkMap.LoadOrStore(testKey, sink)
require.False(overrides.t, loaded)
require.Equal(overrides.t, sink, actual)
defer func() {
// delete buffer from the global map to prevent a memory leak
value, loaded := sinkMap.LoadAndDelete(testKey)
require.True(overrides.t, loaded)
require.Equal(overrides.t, sink, value)
}()
}
if overrides.f != nil {
f = overrides.f
}
if overrides.opts != nil {
opts = overrides.opts
}
}
// when using the trace or all log levels, an error log will contain the full stack.
// this is too noisy for regular use because things like leader election conflicts
// result in transient errors and we do not want all of that noise in the logs.
// this check is performed dynamically on the global log level.
return newZapr(globalLevel, LevelTrace, encoding, path, f, opts...)
}
func newZapr(level zap.AtomicLevel, addStack zapcore.LevelEnabler, encoding, path string, f func(config *zap.Config), opts ...zap.Option) (logr.Logger, func(), error) {
opts = append([]zap.Option{zap.AddStacktrace(addStack)}, opts...)
config := zap.Config{
Level: level,
Development: false,
DisableCaller: false,
DisableStacktrace: true, // handled via the AddStacktrace call above
Sampling: nil, // keep all logs for now
Encoding: encoding,
EncoderConfig: zapcore.EncoderConfig{
MessageKey: "message",
LevelKey: "level",
TimeKey: "timestamp",
NameKey: "logger",
CallerKey: "caller",
FunctionKey: zapcore.OmitKey, // included in caller
StacktraceKey: "stacktrace",
SkipLineEnding: false,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: levelEncoder,
// human-readable and machine parsable with microsecond precision (same as klog, kube audit event, etc)
EncodeTime: zapcore.TimeEncoderOfLayout(metav1.RFC3339Micro),
EncodeDuration: zapcore.StringDurationEncoder,
EncodeCaller: callerEncoder,
EncodeName: nil,
NewReflectedEncoder: nil,
ConsoleSeparator: " ",
},
OutputPaths: []string{path},
ErrorOutputPaths: []string{path},
InitialFields: nil,
}
f(&config)
log, err := config.Build(opts...)
if err != nil {
return logr.Logger{}, nil, fmt.Errorf("failed to build zap logger: %w", err)
}
return zapr.NewLogger(log), func() { _ = log.Sync() }, nil
}
func levelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
plogLevel := zapLevelToPlogLevel(l)
if len(plogLevel) == 0 {
return // this tells zap that it should handle encoding the level itself because we do not know the mapping
}
enc.AppendString(string(plogLevel))
}
func zapLevelToPlogLevel(l zapcore.Level) LogLevel {
if l > 0 {
// best effort mapping, the zap levels do not really translate to klog
// but this is correct for "error" level which is all we need for logr
return LogLevel(l.String())
}
// klog levels are inverted when zap handles them
switch {
case -l >= klogLevelAll:
return LevelAll
case -l >= KlogLevelTrace:
return LevelTrace
case -l >= KlogLevelDebug:
return LevelDebug
case -l >= KlogLevelInfo:
return LevelInfo
default:
return "" // warning is handled via a custom key since klog level 0 is ambiguous
}
}
func callerEncoder(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) {
enc.AppendString(caller.String() + funcEncoder(caller))
}
func funcEncoder(caller zapcore.EntryCaller) string {
funcName := caller.Function
if idx := strings.LastIndexByte(funcName, '/'); idx != -1 {
funcName = funcName[idx+1:] // keep everything after the last /
}
return "$" + funcName
}
func humanDurationEncoder(d time.Duration, enc zapcore.PrimitiveArrayEncoder) {
enc.AppendString(duration.HumanDuration(d))
}
func humanTimeEncoder(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
enc.AppendString(t.Local().Format(time.RFC1123))
}

2
internal/registry/credentialrequest/rest_test.go
View File

@ -71,7 +71,7 @@ func TestCreate(t *testing.T) {
it.Before(func() {
r = require.New(t)
ctrl = gomock.NewController(t)
logger = testutil.NewTranscriptLogger(t)
logger = testutil.NewTranscriptLogger(t) // nolint: staticcheck // old test with lots of log statements
klog.SetLogger(logr.New(logger)) // this is unfortunately a global logger, so can't run these tests in parallel :(
})

31
internal/supervisor/server/server.go
View File

@ -22,14 +22,12 @@ import (
"github.com/joshlf/go-acl"
appsv1 "k8s.io/api/apps/v1"
corev1 "k8s.io/api/core/v1"
apimachineryversion "k8s.io/apimachinery/pkg/version"
genericapifilters "k8s.io/apiserver/pkg/endpoints/filters"
kubeinformers "k8s.io/client-go/informers"
"k8s.io/client-go/kubernetes"
"k8s.io/client-go/pkg/version"
"k8s.io/client-go/rest"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
"k8s.io/klog/v2/klogr"
"k8s.io/utils/clock"
configv1alpha1 "go.pinniped.dev/generated/latest/apis/supervisor/config/v1alpha1"
@ -272,7 +270,7 @@ func prepareControllers(
pinnipedClient,
pinnipedInformers.IDP().V1alpha1().OIDCIdentityProviders(),
secretInformer,
klogr.New(),
plog.Logr(), // nolint: staticcheck // old controller with lots of log statements
controllerlib.WithInformer,
),
singletonWorker).
@ -315,7 +313,7 @@ func startControllers(ctx context.Context, shutdown *sync.WaitGroup, buildContro
}
//nolint:funlen
func runSupervisor(podInfo *downward.PodInfo, cfg *supervisor.Config) error {
func runSupervisor(ctx context.Context, podInfo *downward.PodInfo, cfg *supervisor.Config) error {
serverInstallationNamespace := podInfo.Namespace
dref, supervisorDeployment, supervisorPod, err := deploymentref.New(podInfo)
@ -389,7 +387,6 @@ func runSupervisor(podInfo *downward.PodInfo, cfg *supervisor.Config) error {
leaderElector,
)
ctx := signalCtx()
shutdown := &sync.WaitGroup{}
if err := startControllers(ctx, shutdown, buildControllersFunc); err != nil {
@ -504,12 +501,14 @@ func maybeSetupUnixPerms(endpoint *supervisor.Endpoint, pod *corev1.Pod) func()
}
}
func main() error { // return an error instead of klog.Fatal to allow defer statements to run
logs.InitLogs()
defer logs.FlushLogs()
func main() error { // return an error instead of plog.Fatal to allow defer statements to run
defer plog.Setup()()
klog.Infof("Running %s at %#v", rest.DefaultKubernetesUserAgent(), version.Get())
klog.Infof("Command-line arguments were: %s %s %s", os.Args[0], os.Args[1], os.Args[2])
plog.Always("Running supervisor",
"user-agent", rest.DefaultKubernetesUserAgent(),
"version", versionInfo(version.Get()),
"arguments", os.Args,
)
// Discover in which namespace we are installed.
podInfo, err := downward.Load(os.Args[1])
@ -517,17 +516,21 @@ func main() error { // return an error instead of klog.Fatal to allow defer stat
return fmt.Errorf("could not read pod metadata: %w", err)
}
ctx := signalCtx()
// Read the server config file.
cfg, err := supervisor.FromPath(os.Args[2])
cfg, err := supervisor.FromPath(ctx, os.Args[2])
if err != nil {
return fmt.Errorf("could not load config: %w", err)
}
return runSupervisor(podInfo, cfg)
return runSupervisor(ctx, podInfo, cfg)
}
func Main() {
if err := main(); err != nil {
klog.Fatal(err)
plog.Fatal(err)
}
}
type versionInfo apimachineryversion.Info // hide .String() method from plog

4
internal/testutil/testlogger/testlogger.go
View File

@ -24,14 +24,14 @@ type Logger struct {
buffer syncBuffer
}
// New returns a new test Logger. Use this for all new tests.
// Deprecated: Use plog.TestLogger or plog.TestZapr instead. This is meant for old tests only.
func New(t *testing.T) *Logger {
res := Logger{t: t}
res.Logger = stdr.New(log.New(&res.buffer, "", 0))
return &res
}
// Deprecated: NewLegacy returns a new test Logger. Use this for old tests if necessary.
// Deprecated: Use plog.TestLogger or plog.TestZapr instead. This is meant for old tests only.
func NewLegacy(t *testing.T) *Logger {
res := New(t)
res.Logger = newStdLogger(log.New(&res.buffer, "", 0))

1
internal/testutil/transcript_logger.go
View File

@ -24,6 +24,7 @@ type TranscriptLogMessage struct {
Message string
}
// Deprecated: Use plog.TestLogger or plog.TestZapr instead. This is meant for old tests only.
func NewTranscriptLogger(t *testing.T) *TranscriptLogger {
return &TranscriptLogger{t: t}
}

4
internal/upstreamoidc/upstreamoidc.go
View File

@ -411,13 +411,13 @@ func (p *ProviderConfig) maybeFetchUserInfo(ctx context.Context, tok *oauth2.Tok
func maybeLogClaims(msg, name string, claims map[string]interface{}) {
if plog.Enabled(plog.LevelAll) { // log keys and values at all level
data, _ := json.Marshal(claims) // nothing we can do if it fails, but it really never should
plog.Info(msg, "providerName", name, "claims", string(data))
plog.All(msg, "providerName", name, "claims", string(data))
return
}
if plog.Enabled(plog.LevelDebug) { // log keys at debug level
keys := sets.StringKeySet(claims).List() // note: this is only safe because the compiler asserts that claims is a map[string]<anything>
plog.Info(msg, "providerName", name, "keys", keys)
plog.Debug(msg, "providerName", name, "keys", keys)
return
}
}

29
pkg/oidcclient/login.go
View File

@ -33,6 +33,7 @@ import (
"go.pinniped.dev/internal/httputil/securityheader"
"go.pinniped.dev/internal/net/phttp"
"go.pinniped.dev/internal/oidc/provider"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/upstreamoidc"
"go.pinniped.dev/pkg/oidcclient/nonce"
"go.pinniped.dev/pkg/oidcclient/oidctypes"
@ -63,8 +64,6 @@ const (
defaultPasswordEnvVarName = "PINNIPED_PASSWORD" //nolint:gosec // this is not a credential
httpLocationHeaderName = "Location"
debugLogLevel = 4
)
// stdin returns the file descriptor for stdin as an int.
@ -356,7 +355,7 @@ func (h *handlerState) baseLogin() (*oidctypes.Token, error) {
// If the ID token is still valid for a bit, return it immediately and skip the rest of the flow.
cached := h.cache.GetToken(cacheKey)
if cached != nil && cached.IDToken != nil && time.Until(cached.IDToken.Expiry.Time) > minIDTokenValidity {
h.logger.V(debugLogLevel).Info("Pinniped: Found unexpired cached token.")
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Found unexpired cached token.")
return cached, nil
}
@ -520,7 +519,7 @@ func (h *handlerState) getUsernameAndPassword() (string, string, error) {
return "", "", fmt.Errorf("error prompting for username: %w", err)
}
} else {
h.logger.V(debugLogLevel).Info("Pinniped: Read username from environment variable", "name", defaultUsernameEnvVarName)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Read username from environment variable", "name", defaultUsernameEnvVarName)
}
password := h.getEnv(defaultPasswordEnvVarName)
@ -530,7 +529,7 @@ func (h *handlerState) getUsernameAndPassword() (string, string, error) {
return "", "", fmt.Errorf("error prompting for password: %w", err)
}
} else {
h.logger.V(debugLogLevel).Info("Pinniped: Read password from environment variable", "name", defaultPasswordEnvVarName)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Read password from environment variable", "name", defaultPasswordEnvVarName)
}
return username, password, nil
@ -542,7 +541,7 @@ func (h *handlerState) webBrowserBasedAuth(authorizeOptions *[]oauth2.AuthCodeOp
// Attempt to open a local TCP listener, logging but otherwise ignoring any error.
listener, err := h.listen("tcp", h.listenAddr)
if err != nil {
h.logger.V(debugLogLevel).Error(err, "could not open callback listener")
h.logger.V(plog.KlogLevelDebug).Error(err, "could not open callback listener")
}
// If the listener failed to start and stdin is not a TTY, then we have no hope of succeeding,
@ -578,7 +577,7 @@ func (h *handlerState) webBrowserBasedAuth(authorizeOptions *[]oauth2.AuthCodeOp
// Open the authorize URL in the users browser, logging but otherwise ignoring any error.
if err := h.openURL(authorizeURL); err != nil {
h.logger.V(debugLogLevel).Error(err, "could not open browser")
h.logger.V(plog.KlogLevelDebug).Error(err, "could not open browser")
}
// Prompt the user to visit the authorize URL, and to paste a manually-copied auth code (if possible).
@ -709,7 +708,7 @@ func (h *handlerState) initOIDCDiscovery() error {
return err
}
h.logger.V(debugLogLevel).Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer)
var err error
h.provider, err = oidc.NewProvider(h.ctx, h.issuer)
if err != nil {
@ -767,7 +766,7 @@ func stringSliceContains(slice []string, s string) bool {
}
func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) {
h.logger.V(debugLogLevel).Info("Pinniped: Performing RFC8693 token exchange", "requestedAudience", h.requestedAudience)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Performing RFC8693 token exchange", "requestedAudience", h.requestedAudience)
// Perform OIDC discovery. This may have already been performed if there was not a cached base token.
if err := h.initOIDCDiscovery(); err != nil {
return nil, err
@ -838,13 +837,13 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty
}
func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) {
h.logger.V(debugLogLevel).Info("Pinniped: Refreshing cached token.")
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Refreshing cached token.")
upstreamOIDCIdentityProvider := h.getProvider(h.oauth2Config, h.provider, h.httpClient)
refreshed, err := upstreamOIDCIdentityProvider.PerformRefresh(ctx, refreshToken.Token)
if err != nil {
// Ignore errors during refresh, but return nil which will trigger the full login flow.
h.logger.V(debugLogLevel).Info("Pinniped: Refresh failed.", "error", err.Error())
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Refresh failed.", "error", err.Error())
return nil, nil
}
@ -865,7 +864,7 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req
if h.useFormPost { // nolint:nestif
// Return HTTP 405 for anything that's not a POST or an OPTIONS request.
if r.Method != http.MethodPost && r.Method != http.MethodOptions {
h.logger.V(debugLogLevel).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method)
w.WriteHeader(http.StatusMethodNotAllowed)
return nil // keep listening for more requests
}
@ -883,11 +882,11 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req
origin := r.Header.Get("Origin")
if origin == "" {
// The CORS preflight request should have an origin.
h.logger.V(debugLogLevel).Info("Pinniped: Got OPTIONS request without origin header")
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got OPTIONS request without origin header")
w.WriteHeader(http.StatusBadRequest)
return nil // keep listening for more requests
}
h.logger.V(debugLogLevel).Info("Pinniped: Got CORS preflight request from browser", "origin", origin)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got CORS preflight request from browser", "origin", origin)
// To tell the browser that it is okay to make the real POST request, return the following response.
w.Header().Set("Access-Control-Allow-Origin", allowOrigin)
w.Header().Set("Vary", "*") // supposed to use Vary when Access-Control-Allow-Origin is a specific host
@ -921,7 +920,7 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req
} else {
// Return HTTP 405 for anything that's not a GET.
if r.Method != http.MethodGet {
h.logger.V(debugLogLevel).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method)
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method)
w.WriteHeader(http.StatusMethodNotAllowed)
return nil // keep listening for more requests
}

9
pkg/oidcclient/login_test.go
View File

@ -20,10 +20,6 @@ import (
"testing"
"time"
"go.pinniped.dev/internal/net/phttp"
"go.pinniped.dev/internal/testutil/tlsserver"
"github.com/coreos/go-oidc/v3/oidc"
"github.com/golang/mock/gomock"
"github.com/stretchr/testify/assert"
@ -35,9 +31,12 @@ import (
"go.pinniped.dev/internal/httputil/httperr"
"go.pinniped.dev/internal/httputil/roundtripper"
"go.pinniped.dev/internal/mocks/mockupstreamoidcidentityprovider"
"go.pinniped.dev/internal/net/phttp"
"go.pinniped.dev/internal/oidc/provider"
"go.pinniped.dev/internal/plog"
"go.pinniped.dev/internal/testutil"
"go.pinniped.dev/internal/testutil/testlogger"
"go.pinniped.dev/internal/testutil/tlsserver"
"go.pinniped.dev/internal/upstreamoidc"
"go.pinniped.dev/pkg/oidcclient/nonce"
"go.pinniped.dev/pkg/oidcclient/oidctypes"
@ -2334,7 +2333,7 @@ func TestHandleAuthCodeCallback(t *testing.T) {
state: state.State("test-state"),
pkce: pkce.Code("test-pkce"),
nonce: nonce.Nonce("test-nonce"),
logger: testlogger.New(t).Logger,
logger: plog.Logr(), // nolint: staticcheck // old test with no log assertions
issuer: "https://valid-issuer.com/with/some/path",
}
if tt.opt != nil {