VAULT-19681 allow users to specify files for agent child process stdout/stderr (#22812)

* allow users to specify files for child process stdout/stderr

* added changelog

* check if exec config is nil

* fix test

* first attempt at a test

* revise test

* passing test

* added failing test

* Apply suggestions from code review

Co-authored-by: Anton Averchenkov <84287187+averche@users.noreply.github.com>

* code review suggestions

* always close log files

* refactor to use real files

* hopefully fixed tests

* add back bool gates so we don't close global stdout/stderr

* compare to os.Stdout/os.Stderr

* remove unused

---------

Co-authored-by: Anton Averchenkov <84287187+averche@users.noreply.github.com>

changelog/22812.txt

@@ -0,0 +1,3 @@
+```release-note:improvement
+agent: allow users to specify files for child process stdout/stderr
+```

command/agent.go

@@ -729,13 +729,17 @@ func (c *AgentCommand) Run(args []string) int {
 			ExitAfterAuth: config.ExitAfterAuth,
 		})
 
-		es := exec.NewServer(&exec.ServerConfig{
+		es, err := exec.NewServer(&exec.ServerConfig{
 			AgentConfig: c.config,
 			Namespace:   templateNamespace,
 			Logger:      c.logger.Named("exec.server"),
 			LogLevel:    c.logger.GetLevel(),
 			LogWriter:   c.logWriter,
 		})
+		if err != nil {
+			c.logger.Error("could not create exec server", "error", err)
+			return 1
+		}
 
 		g.Add(func() error {
 			return ah.Run(ctx, method)
@@ -800,6 +804,7 @@ func (c *AgentCommand) Run(args []string) int {
 				leaseCache.SetShuttingDown(true)
 			}
 			cancelFunc()
+			es.Close()
 		})
 
 	}

command/agent/config/config.go

@@ -171,6 +171,8 @@ type ExecConfig struct {
 	Command                []string  `hcl:"command,attr" mapstructure:"command"`
 	RestartOnSecretChanges string    `hcl:"restart_on_secret_changes,optional" mapstructure:"restart_on_secret_changes"`
 	RestartStopSignal      os.Signal `hcl:"-" mapstructure:"restart_stop_signal"`
+	ChildProcessStdout     string    `mapstructure:"child_process_stdout"`
+	ChildProcessStderr     string    `mapstructure:"child_process_stderr"`
 }
 
 func NewConfig() *Config {

command/agent/exec/exec.go

@@ -65,9 +65,11 @@ type Server struct {
 
 	logger hclog.Logger
 
-	childProcess      *child.Child
-	childProcessState childProcessState
-	childProcessLock  sync.Mutex
+	childProcess       *child.Child
+	childProcessState  childProcessState
+	childProcessLock   sync.Mutex
+	childProcessStdout io.WriteCloser
+	childProcessStderr io.WriteCloser
 
 	// exit channel of the child process
 	childProcessExitCh chan int
@@ -85,15 +87,38 @@ func (e *ProcessExitError) Error() string {
 	return fmt.Sprintf("process exited with %d", e.ExitCode)
 }
 
-func NewServer(cfg *ServerConfig) *Server {
+func NewServer(cfg *ServerConfig) (*Server, error) {
+	var err error
+
+	childProcessStdout := os.Stdout
+	childProcessStderr := os.Stderr
+
+	if cfg.AgentConfig.Exec != nil {
+		if cfg.AgentConfig.Exec.ChildProcessStdout != "" {
+			childProcessStdout, err = os.OpenFile(cfg.AgentConfig.Exec.ChildProcessStdout, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
+			if err != nil {
+				return nil, fmt.Errorf("could not open %q, %w", cfg.AgentConfig.Exec.ChildProcessStdout, err)
+			}
+		}
+
+		if cfg.AgentConfig.Exec.ChildProcessStderr != "" {
+			childProcessStderr, err = os.OpenFile(cfg.AgentConfig.Exec.ChildProcessStderr, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
+			if err != nil {
+				return nil, fmt.Errorf("could not open %q, %w", cfg.AgentConfig.Exec.ChildProcessStdout, err)
+			}
+		}
+	}
+
 	server := Server{
 		logger:             cfg.Logger,
 		config:             cfg,
 		childProcessState:  childProcessStateNotStarted,
 		childProcessExitCh: make(chan int),
+		childProcessStdout: childProcessStdout,
+		childProcessStderr: childProcessStderr,
 	}
 
-	return &server
+	return &server, nil
 }
 
 func (s *Server) Run(ctx context.Context, incomingVaultToken chan string) error {
@@ -152,6 +177,7 @@ func (s *Server) Run(ctx context.Context, incomingVaultToken chan string) error
 				s.childProcess.Stop()
 			}
 			s.childProcessState = childProcessStateStopped
+			s.close()
 			s.childProcessLock.Unlock()
 			return nil
 
@@ -291,8 +317,8 @@ func (s *Server) restartChildProcess(newEnvVars []string) error {
 
 	childInput := &child.NewInput{
 		Stdin:        os.Stdin,
-		Stdout:       os.Stdout,
-		Stderr:       os.Stderr,
+		Stdout:       s.childProcessStdout,
+		Stderr:       s.childProcessStderr,
 		Command:      args[0],
 		Args:         args[1:],
 		Timeout:      0, // let it run forever
@@ -333,3 +359,18 @@ func (s *Server) restartChildProcess(newEnvVars []string) error {
 
 	return nil
 }
+
+func (s *Server) Close() {
+	s.childProcessLock.Lock()
+	defer s.childProcessLock.Unlock()
+	s.close()
+}
+
+func (s *Server) close() {
+	if s.childProcessStdout != os.Stdout {
+		_ = s.childProcessStdout.Close()
+	}
+	if s.childProcessStderr != os.Stderr {
+		_ = s.childProcessStderr.Close()
+	}
+}

command/agent/exec/exec_test.go

@@ -257,7 +257,7 @@ func TestExecServer_Run(t *testing.T) {
 				strconv.Itoa(testCase.testAppPort),
 			}
 
-			execServer := NewServer(&ServerConfig{
+			execServer, err := NewServer(&ServerConfig{
 				Logger: logging.NewVaultLogger(hclog.Trace),
 				AgentConfig: &config.Config{
 					Vault: &config.Vault{
@@ -280,6 +280,9 @@ func TestExecServer_Run(t *testing.T) {
 				LogLevel:  hclog.Trace,
 				LogWriter: hclog.DefaultOutput,
 			})
+			if err != nil {
+				t.Fatalf("could not create exec server: %q", err)
+			}
 
 			// start the exec server
 			var (
@@ -380,3 +383,187 @@ func TestExecServer_Run(t *testing.T) {
 		})
 	}
 }
+
+func TestExecServer_LogFiles(t *testing.T) {
+	goBinary, err := exec.LookPath("go")
+	if err != nil {
+		t.Fatalf("could not find go binary on path: %s", err)
+	}
+
+	testAppBinary := filepath.Join(os.TempDir(), "test-app")
+
+	if err := exec.Command(goBinary, "build", "-o", testAppBinary, "./test-app").Run(); err != nil {
+		t.Fatalf("could not build the test application: %s", err)
+	}
+	t.Cleanup(func() {
+		if err := os.Remove(testAppBinary); err != nil {
+			t.Fatalf("could not remove %q test application: %s", testAppBinary, err)
+		}
+	})
+
+	testCases := map[string]struct {
+		testAppPort int
+		testAppArgs []string
+		stderrFile  string
+		stdoutFile  string
+
+		expectedError error
+	}{
+		"can_log_stderr_to_file": {
+			testAppPort: 34001,
+			stderrFile:  "vault-exec-test.stderr.log",
+		},
+		"can_log_stdout_to_file": {
+			testAppPort: 34002,
+			stdoutFile:  "vault-exec-test.stdout.log",
+			testAppArgs: []string{"-log-to-stdout"},
+		},
+		"cant_open_file": {
+			testAppPort:   34003,
+			stderrFile:    "/file/does/not/exist",
+			expectedError: os.ErrNotExist,
+		},
+	}
+
+	for tcName, testCase := range testCases {
+		t.Run(tcName, func(t *testing.T) {
+			fakeVault := fakeVaultServer(t)
+			defer fakeVault.Close()
+
+			testAppCommand := []string{
+				testAppBinary,
+				"--port",
+				strconv.Itoa(testCase.testAppPort),
+				"--stop-after",
+				"60s",
+			}
+
+			execConfig := &config.ExecConfig{
+				RestartOnSecretChanges: "always",
+				Command:                append(testAppCommand, testCase.testAppArgs...),
+			}
+
+			if testCase.stdoutFile != "" {
+				execConfig.ChildProcessStdout = filepath.Join(os.TempDir(), "vault-agent-exec.stdout.log")
+				t.Cleanup(func() {
+					_ = os.Remove(execConfig.ChildProcessStdout)
+				})
+			}
+
+			if testCase.stderrFile != "" {
+				execConfig.ChildProcessStderr = filepath.Join(os.TempDir(), "vault-agent-exec.stderr.log")
+				t.Cleanup(func() {
+					_ = os.Remove(execConfig.ChildProcessStderr)
+				})
+			}
+
+			execServer, err := NewServer(&ServerConfig{
+				Logger: logging.NewVaultLogger(hclog.Trace),
+				AgentConfig: &config.Config{
+					Vault: &config.Vault{
+						Address: fakeVault.URL,
+						Retry: &config.Retry{
+							NumRetries: 3,
+						},
+					},
+					Exec: execConfig,
+					EnvTemplates: []*ctconfig.TemplateConfig{{
+						Contents:                 pointerutil.StringPtr(`{{ with secret "kv/my-app/creds" }}{{ .Data.data.user }}{{ end }}`),
+						MapToEnvironmentVariable: pointerutil.StringPtr("MY_USER"),
+					}},
+					TemplateConfig: &config.TemplateConfig{
+						ExitOnRetryFailure:    true,
+						StaticSecretRenderInt: 5 * time.Second,
+					},
+				},
+				LogLevel:  hclog.Trace,
+				LogWriter: hclog.DefaultOutput,
+			})
+			if err != nil {
+				if testCase.expectedError != nil {
+					if errors.Is(err, testCase.expectedError) {
+						t.Log("test passes! caught expected err")
+						return
+					} else {
+						t.Fatalf("caught error %q did not match expected error %q", err, testCase.expectedError)
+					}
+				}
+				t.Fatalf("could not create exec server: %q", err)
+			}
+
+			ctx, cancel := context.WithCancel(context.Background())
+			defer cancel()
+
+			// start the exec server
+			var (
+				execServerErrCh   = make(chan error)
+				execServerTokenCh = make(chan string, 1)
+			)
+			go func() {
+				execServerErrCh <- execServer.Run(ctx, execServerTokenCh)
+			}()
+
+			// send a dummy token to kick off the server
+			execServerTokenCh <- "my-token"
+
+			// ensure the test app is running after 500ms
+			var (
+				testAppAddr      = fmt.Sprintf("http://localhost:%d", testCase.testAppPort)
+				testAppStartedCh = make(chan error)
+			)
+			time.AfterFunc(500*time.Millisecond, func() {
+				_, err := retryablehttp.Head(testAppAddr)
+				testAppStartedCh <- err
+			})
+
+			select {
+			case <-ctx.Done():
+				t.Fatal("timeout reached before templates were rendered")
+
+			case err := <-execServerErrCh:
+				if testCase.expectedError == nil && err != nil {
+					t.Fatalf("exec server did not expect an error, got: %v", err)
+				}
+
+				if errors.Is(err, testCase.expectedError) {
+					t.Fatalf("exec server expected error %v; got %v", testCase.expectedError, err)
+				}
+
+				t.Log("exec server exited without an error")
+
+				return
+
+			case <-testAppStartedCh:
+				t.Log("test app started successfully")
+			}
+
+			// let the app run a bit
+			time.Sleep(5 * time.Second)
+			// stop the app
+			cancel()
+			// wait for app to stop
+			time.Sleep(5 * time.Second)
+
+			// check if the files have content
+			if testCase.stdoutFile != "" {
+				stdoutInfo, err := os.Stat(execConfig.ChildProcessStdout)
+				if err != nil {
+					t.Fatalf("error calling stat on stdout file: %q", err)
+				}
+				if stdoutInfo.Size() == 0 {
+					t.Fatalf("stdout log file does not have any data!")
+				}
+			}
+
+			if testCase.stderrFile != "" {
+				stderrInfo, err := os.Stat(execConfig.ChildProcessStderr)
+				if err != nil {
+					t.Fatalf("error calling stat on stderr file: %q", err)
+				}
+				if stderrInfo.Size() == 0 {
+					t.Fatalf("stderr log file does not have any data!")
+				}
+			}
+		})
+	}
+}

command/agent/exec/test-app/main.go

@@ -29,11 +29,11 @@ import (
 
 var (
 	port                 uint
-	ignoreStopSignal     bool
 	sleepAfterStopSignal time.Duration
 	useSigusr1StopSignal bool
 	stopAfter            time.Duration
 	exitCode             int
+	logToStdout          bool
 )
 
 func init() {
@@ -42,6 +42,7 @@ func init() {
 	flag.BoolVar(&useSigusr1StopSignal, "use-sigusr1", false, "use SIGUSR1 as the stop signal, instead of the default SIGTERM")
 	flag.DurationVar(&stopAfter, "stop-after", 0, "stop the process after duration (overrides all other flags if set)")
 	flag.IntVar(&exitCode, "exit-code", 0, "exit code to return when this script exits")
+	flag.BoolVar(&logToStdout, "log-to-stdout", false, "log to stdout instead of stderr")
 }
 
 type Response struct {
@@ -78,8 +79,15 @@ func handler(w http.ResponseWriter, r *http.Request) {
 }
 
 func main() {
-	logger := log.New(os.Stderr, "test-app: ", log.LstdFlags)
+	flag.Parse()
 
+	logOut := os.Stderr
+	if logToStdout {
+		logOut = os.Stdout
+	}
+	logger := log.New(logOut, "test-app: ", log.LstdFlags)
+
+	logger.Printf("running on port %d", port)
 	if err := run(logger); err != nil {
 		log.Fatalf("error: %v\n", err)
 	}
@@ -96,8 +104,6 @@ func run(logger *log.Logger) error {
 	ctx, cancelContextFunc := context.WithTimeout(context.Background(), 60*time.Second)
 	defer cancelContextFunc()
 
-	flag.Parse()
-
 	server := http.Server{
 		Addr:         fmt.Sprintf(":%d", port),
 		Handler:      http.HandlerFunc(handler),