feat(cli): 1B: PPROF extensions: load profile config (#3668)

Co-authored-by: Shikhar Mall <mall.shikhar.in@gmail.com>

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 <key>=<value> 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
 	}

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))
+}