diff --git a/internal/pproflogging/pproflogging.go b/internal/pproflogging/pproflogging.go index 06263c260..ca6836694 100644 --- a/internal/pproflogging/pproflogging.go +++ b/internal/pproflogging/pproflogging.go @@ -63,23 +63,33 @@ ProfileNameCPU = "cpu" ) -// ProfileConfig configuration flags for a profile. -type ProfileConfig struct { - flags []string - buf *bytes.Buffer +var ( + // ErrEmptyProfileName returned when a profile configuration flag has no argument. + ErrEmptyProfileName = errors.New("empty profile flag") + + //nolint:gochecknoglobals + pprofConfigs = newProfileConfigs(os.Stderr) +) + +// Writer interface supports destination for PEM output. +type Writer interface { + io.Writer + io.StringWriter } // ProfileConfigs configuration flags for all requested profiles. type ProfileConfigs struct { mu sync.Mutex - + // wrt represents the final destination for the PPROF PEM output. Typically, + // this is attached to stderr or log output. A custom writer is used because + // not all loggers support line oriented output through the io.Writer interface... + // support is often attached th a io.StringWriter. + // +checklocks:mu + wrt Writer // +checklocks:mu pcm map[ProfileName]*ProfileConfig } -//nolint:gochecknoglobals -var pprofConfigs = &ProfileConfigs{} - type pprofSetRate struct { setter func(int) defaultValue int @@ -97,6 +107,37 @@ type pprofSetRate struct { }, } +func newProfileConfigs(wrt Writer) *ProfileConfigs { + q := &ProfileConfigs{ + wrt: wrt, + } + + return q +} + +// LoadProfileConfig configure PPROF profiling from the config in ppconfigss. +func LoadProfileConfig(ctx context.Context, ppconfigss string) (map[ProfileName]*ProfileConfig, error) { + // if empty, then don't bother configuring but emit a log message - user might be expecting them to be configured + if ppconfigss == "" { + log(ctx).Debug("no profile configuration. skipping PPROF setup") + return nil, nil + } + + bufSizeB := DefaultDebugProfileDumpBufferSizeB + + // look for matching services. "*" signals all services for profiling + log(ctx).Info("configuring profile buffers") + + // acquire global lock when performing operations with global side-effects + return parseProfileConfigs(bufSizeB, ppconfigss) +} + +// ProfileConfig configuration flags for a profile. +type ProfileConfig struct { + flags []string + buf *bytes.Buffer +} + // GetValue get the value of the named flag, `s`. False will be returned // if the flag does not exist. True will be returned if flag exists without // a value. @@ -117,7 +158,7 @@ func (p ProfileConfig) GetValue(s string) (string, bool) { return "", false } -func parseProfileConfigs(bufSizeB int, ppconfigs string) map[ProfileName]*ProfileConfig { +func parseProfileConfigs(bufSizeB int, ppconfigs string) (map[ProfileName]*ProfileConfig, error) { pbs := map[ProfileName]*ProfileConfig{} allProfileOptions := strings.Split(ppconfigs, ":") @@ -127,14 +168,19 @@ func parseProfileConfigs(bufSizeB int, ppconfigs string) map[ProfileName]*Profil flagValue := "" if len(profileFlagNameValuePairs) > 1 { + // only = allowed flagValue = profileFlagNameValuePairs[1] } - flagKey := ProfileName(strings.ToLower(profileFlagNameValuePairs[0])) + flagKey := ProfileName(profileFlagNameValuePairs[0]) + if flagKey == "" { + return nil, ErrEmptyProfileName + } + pbs[flagKey] = newProfileConfig(bufSizeB, flagValue) } - return pbs + return pbs, nil } // newProfileConfig create a new profiling configuration. @@ -207,7 +253,7 @@ func StartProfileBuffers(ctx context.Context) { ppconfigs := os.Getenv(EnvVarKopiaDebugPprof) // if empty, then don't bother configuring but emit a log message - use might be expecting them to be configured if ppconfigs == "" { - log(ctx).Debug("no profile buffers enabled") + log(ctx).Warn("no profile buffers enabled") return } @@ -220,7 +266,13 @@ func StartProfileBuffers(ctx context.Context) { pprofConfigs.mu.Lock() defer pprofConfigs.mu.Unlock() - pprofConfigs.pcm = parseProfileConfigs(bufSizeB, ppconfigs) + var err error + + pprofConfigs.pcm, err = parseProfileConfigs(bufSizeB, ppconfigs) + if err != nil { + log(ctx).With("cause", err).Warnf("cannot start PPROF config, %q, due to parse error", ppconfigs) + return + } // profiling rates need to be set before starting profiling setupProfileFractions(ctx, pprofConfigs.pcm) @@ -249,18 +301,22 @@ func DumpPem(bs []byte, types string, wrt *os.File) error { // will make best use of output buffer and help prevent overflows or // stalls in the output path. pr, pw := io.Pipe() + + // ensure read-end of the pipe is close + //nolint:errcheck + defer pr.Close() + // encode PEM in the background and output in a line oriented // fashion - this prevents the need for a large buffer to hold // the encoded PEM. go func() { // writer close on exit of background process + // pipe writer will not return a meaningful error //nolint:errcheck defer pw.Close() + // do the encoding err0 = pem.Encode(pw, blk) - if err0 != nil { - return - } }() // connect rdr to pipe reader @@ -281,7 +337,10 @@ func DumpPem(bs []byte, types string, wrt *os.File) error { return fmt.Errorf("could not write PEM: %w", err2) } - // did not get a read error. file ends in newline + if err0 != nil { + return fmt.Errorf("could not write PEM: %w", err0) + } + if err1 == nil { return nil } diff --git a/internal/pproflogging/pproflogging_test.go b/internal/pproflogging/pproflogging_test.go index 06dceef04..3aed28248 100644 --- a/internal/pproflogging/pproflogging_test.go +++ b/internal/pproflogging/pproflogging_test.go @@ -1,24 +1,70 @@ package pproflogging import ( + "bytes" + "context" "fmt" + "io" + "os" + "regexp" "testing" "github.com/stretchr/testify/require" + "golang.org/x/exp/maps" + + "github.com/kopia/kopia/repo/logging" ) -func TestDebug_parseProfileConfigs(t *testing.T) { +func TestDebug_StartProfileBuffers(t *testing.T) { + saveLockEnv(t) + // placeholder to make coverage happy tcs := []struct { - in string - key ProfileName - expect []string + in string + rx *regexp.Regexp }{ + { + in: "", + rx: regexp.MustCompile("no profile buffers enabled"), + }, + { + in: ":", + rx: regexp.MustCompile(`cannot start PPROF config, ".*", due to parse error`), + }, + } + for _, tc := range tcs { + lg := &bytes.Buffer{} + ctx := logging.WithLogger(context.Background(), logging.ToWriter(lg)) + + t.Setenv(EnvVarKopiaDebugPprof, tc.in) + StartProfileBuffers(ctx) + require.Regexp(t, tc.rx, lg.String()) + } +} + +func TestDebug_parseProfileConfigs(t *testing.T) { + saveLockEnv(t) + + tcs := []struct { + in string + key ProfileName + expect []string + expectError error + expectMissing bool + n int + }{ + { + in: "foo", + key: "foo", + expect: nil, + n: 1, + }, { in: "foo=bar", key: "foo", expect: []string{ "bar", }, + n: 1, }, { in: "first=one=1", @@ -26,6 +72,7 @@ func TestDebug_parseProfileConfigs(t *testing.T) { expect: []string{ "one=1", }, + n: 1, }, { in: "foo=bar:first=one=1", @@ -33,6 +80,7 @@ func TestDebug_parseProfileConfigs(t *testing.T) { expect: []string{ "one=1", }, + n: 2, }, { in: "foo=bar:first=one=1,two=2", @@ -41,6 +89,7 @@ func TestDebug_parseProfileConfigs(t *testing.T) { "one=1", "two=2", }, + n: 2, }, { in: "foo=bar:first=one=1,two=2:second:third", @@ -49,6 +98,7 @@ func TestDebug_parseProfileConfigs(t *testing.T) { "one=1", "two=2", }, + n: 4, }, { in: "foo=bar:first=one=1,two=2:second:third", @@ -56,24 +106,67 @@ func TestDebug_parseProfileConfigs(t *testing.T) { expect: []string{ "bar", }, + n: 4, }, { in: "foo=bar:first=one=1,two=2:second:third", key: "second", expect: nil, + n: 4, }, { in: "foo=bar:first=one=1,two=2:second:third", key: "third", expect: nil, + n: 4, + }, + { + in: "=", + key: "", + expectMissing: true, + expectError: ErrEmptyProfileName, + }, + { + in: ":", + key: "", + expectMissing: true, + expectError: ErrEmptyProfileName, + }, + { + in: ",", + key: ",", + expect: nil, + n: 1, + }, + { + in: "=,:", + key: "", + expectMissing: true, + expectError: ErrEmptyProfileName, + }, + { + in: "", + key: "", + expectMissing: true, + expectError: ErrEmptyProfileName, + }, + { + in: ":=", + key: "cpu", + expectMissing: true, + expectError: ErrEmptyProfileName, }, } for i, tc := range tcs { t.Run(fmt.Sprintf("%d %s", i, tc.in), func(t *testing.T) { - pbs := parseProfileConfigs(1<<10, tc.in) + pbs, err := parseProfileConfigs(1<<10, tc.in) + require.ErrorIs(t, tc.expectError, err) + require.Len(t, pbs, tc.n) pb, ok := pbs[tc.key] // no negative testing for missing keys (see newProfileConfigs) - require.True(t, ok) - require.NotNil(t, pb) // always not nil + require.Equalf(t, !tc.expectMissing, ok, "key %q for set %q expect missing %t", tc.key, maps.Keys(pbs), tc.expectMissing) + if tc.expectMissing { + return + } require.Equal(t, 1<<10, pb.buf.Cap()) // bufsize is always 1024 require.Equal(t, 0, pb.buf.Len()) require.Equal(t, tc.expect, pb.flags) @@ -82,6 +175,8 @@ func TestDebug_parseProfileConfigs(t *testing.T) { } func TestDebug_newProfileConfigs(t *testing.T) { + saveLockEnv(t) + tcs := []struct { in string key string @@ -124,3 +219,140 @@ func TestDebug_newProfileConfigs(t *testing.T) { }) } } + +func TestDebug_LoadProfileConfigs(t *testing.T) { + // save environment and restore after testing + saveLockEnv(t) + + ctx := context.Background() + + tcs := []struct { + inArgs string + profileKey ProfileName + profileFlagKey string + expectProfileFlagValue string + expectProfileFlagExists bool + expectConfigurationCount int + expectError error + expectProfileConfigNotExists bool + }{ + { + inArgs: "", + expectConfigurationCount: 0, + profileKey: "", + expectError: nil, + expectProfileConfigNotExists: true, + }, + { + inArgs: "block=rate=10:cpu:mutex=10", + expectConfigurationCount: 3, + profileKey: "block", + profileFlagKey: "rate", + expectProfileFlagExists: true, + expectProfileFlagValue: "10", + expectError: nil, + }, + { + inArgs: "block=rate=10:cpu:mutex=10", + expectConfigurationCount: 3, + profileKey: "cpu", + profileFlagKey: "rate", + expectProfileFlagExists: false, + }, + { + inArgs: "block=rate=10:cpu:mutex=10", + expectConfigurationCount: 3, + profileKey: "mutex", + profileFlagKey: "10", + expectProfileFlagExists: true, + }, + { + inArgs: "mutex=10", + expectConfigurationCount: 1, + profileKey: "cpu", + profileFlagKey: "10", + expectProfileConfigNotExists: true, + }, + } + + for i, tc := range tcs { + t.Run(fmt.Sprintf("%d: %q", i, tc.inArgs), func(t *testing.T) { + pmp, err := LoadProfileConfig(ctx, tc.inArgs) + require.ErrorIs(t, tc.expectError, err) + if err != nil { + return + } + val, ok := pmp[tc.profileKey] + require.Equalf(t, tc.expectProfileConfigNotExists, !ok, "expecting key %q to %t exist", tc.profileKey, !tc.expectProfileConfigNotExists) + if tc.expectProfileConfigNotExists { + return + } + flagValue, ok := val.GetValue(tc.profileFlagKey) + require.Equal(t, tc.expectProfileFlagExists, ok, "expecting key %q to %t exist", tc.profileKey, tc.expectProfileFlagExists) + if tc.expectProfileFlagExists { + return + } + require.Equal(t, tc.expectProfileFlagValue, flagValue) + }) + } +} + +//nolint:gocritic +func saveLockEnv(t *testing.T) { + t.Helper() + + oldEnv := os.Getenv(EnvVarKopiaDebugPprof) + + t.Cleanup(func() { + // restore the old environment + t.Setenv(EnvVarKopiaDebugPprof, oldEnv) + }) +} + +func TestErrorWriter(t *testing.T) { + eww := &ErrorWriter{mx: 5, err: io.EOF} + n, err := eww.WriteString("Hello World") + require.ErrorIs(t, io.EOF, err) + require.Equal(t, 5, n) + require.Equal(t, "Hello", string(eww.bs)) +} + +// ErrorWriter allows injection of errors into the write stream. There are a few +// failures in PPROF dumps that are worth modeling for tests ([io.EOF] is one) +// For use specify the error, ErrorWriter.err, and byte index, ErrorWriter.mx, +// in which it should occur. +type ErrorWriter struct { + bs []byte + mx int + err error +} + +func (p *ErrorWriter) Write(bs []byte) (int, error) { + n := len(bs) + + if len(bs)+len(p.bs) > p.mx { + // error will be produced at p.mx + // so don't return any more than + // n + n = p.mx - len(p.bs) + } + + // append the bytes to the local buffer just + // in case someone wants to know. + p.bs = append(p.bs, bs[:n]...) + if n < len(bs) { + // here we assume that any less than len(bs) + // bytes written returns an error. This + // allows setting ErrorWriter up once + // to produce an error after multiple + // writes + return n, p.err + } + + return n, nil +} + +//nolint:gocritic +func (p *ErrorWriter) WriteString(s string) (int, error) { + return p.Write([]byte(s)) +}