refactoring process management: no more orphan processes and quicker chrome startup

cmd/gotenberg/main.go

@@ -1,7 +1,6 @@
 package main
 
 import (
-	"context"
 	"fmt"
 	"net/http"
 	"os"
@@ -28,9 +27,8 @@ func main() {
 	systemLogger.InfofOp(op, "Gotenberg %s", version)
 	systemLogger.DebugfOp(op, "configuration: %+v", config)
 	if !config.DisableGoogleChrome() {
-		// start Google Chrome.
-		_, err = chrome.Start(context.Background(), systemLogger)
-		if err != nil {
+		// start Google Chrome headless.
+		if err := chrome.Start(systemLogger); err != nil {
 			systemLogger.FatalOp(op, err)
 		}
 	}

internal/pkg/chrome/chrome.go

@@ -4,6 +4,8 @@ import (
 	"context"
 	"os"
 	"os/exec"
+	"strings"
+	"syscall"
 	"time"
 
 	"github.com/mafredri/cdp/devtool"
@@ -13,66 +15,26 @@ import (
 	"github.com/thecodingmachine/gotenberg/internal/pkg/xtime"
 )
 
-func Start(ctx context.Context, logger xlog.Logger) (*os.Process, error) {
+// Start starts Google Chrome headless in background.
+func Start(logger xlog.Logger) error {
 	const op string = "chrome.Start"
-	logger.DebugOp(op, "starting new Google Chrome process on port 9222...")
-	resolver := func() (*os.Process, error) {
-		binary := "google-chrome-stable"
-		args := []string{
-			"--no-sandbox",
-			"--headless",
-			// see https://github.com/GoogleChrome/puppeteer/issues/2410.
-			"--font-render-hinting=medium",
-			"--remote-debugging-port=9222",
-			"--disable-gpu",
-			"--disable-translate",
-			"--disable-extensions",
-			"--disable-background-networking",
-			"--safebrowsing-disable-auto-update",
-			"--disable-sync",
-			"--disable-default-apps",
-			"--hide-scrollbars",
-			"--metrics-recording-only",
-			"--mute-audio",
-			"--no-first-run",
-		}
-		cmd, err := xexec.CommandContext(ctx, logger, binary, args...)
+	logger.DebugOp(op, "starting new Google Chrome headless process on port 9222...")
+	resolver := func() error {
+		cmd, err := cmd(logger)
 		if err != nil {
-			return nil, err
+			return err
 		}
 		// we try to start the process.
 		xexec.LogBeforeExecute(logger, cmd)
 		if err := cmd.Start(); err != nil {
-			return cmd.Process, err
+			return err
 		}
-		// we wait the process to be ready.
-		warmup(logger)
 		// if the process failed to start correctly,
 		// we have to restart it.
 		if !isViable(logger) {
-			return restart(ctx, logger, cmd)
+			return restart(logger, cmd.Process)
 		}
-		return cmd.Process, nil
-	}
-	proc, err := resolver()
-	if err != nil {
-		if errKill := Kill(logger, proc); errKill != nil {
-			logger.ErrorOp(op, errKill)
-		}
-		return nil, xerror.New(op, err)
-	}
-	return proc, nil
-}
-
-func Kill(logger xlog.Logger, proc *os.Process) error {
-	const op string = "chrome.Kill"
-	resolver := func() error {
-		logger.DebugOp(op, "removing Google Chrome process using port 9222...")
-		if proc == nil {
-			logger.DebugOp(op, "no Google Chrome process using port 9222 found, skipping")
-			return nil
-		}
-		return proc.Kill()
+		return nil
 	}
 	if err := resolver(); err != nil {
 		return xerror.New(op, err)
@@ -80,60 +42,125 @@ func Kill(logger xlog.Logger, proc *os.Process) error {
 	return nil
 }
 
-func restart(ctx context.Context, logger xlog.Logger, cmd *exec.Cmd) (*os.Process, error) {
+func cmd(logger xlog.Logger) (*exec.Cmd, error) {
+	const op string = "chrome.cmd"
+	binary := "google-chrome-stable"
+	args := []string{
+		"--no-sandbox",
+		"--headless",
+		// see https://github.com/GoogleChrome/puppeteer/issues/2410.
+		"--font-render-hinting=medium",
+		"--remote-debugging-port=9222",
+		"--disable-gpu",
+		"--disable-translate",
+		"--disable-extensions",
+		"--disable-background-networking",
+		"--safebrowsing-disable-auto-update",
+		"--disable-sync",
+		"--disable-default-apps",
+		"--hide-scrollbars",
+		"--metrics-recording-only",
+		"--mute-audio",
+		"--no-first-run",
+	}
+	cmd, err := xexec.Command(logger, binary, args...)
+	if err != nil {
+		return nil, xerror.New(op, err)
+	}
+	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
+	return cmd, nil
+}
+
+func kill(logger xlog.Logger, proc *os.Process) error {
+	const op string = "chrome.kill"
+	logger.DebugOp(op, "killing Google Chrome headless process using port 9222...")
+	resolver := func() error {
+		err := syscall.Kill(-proc.Pid, syscall.SIGKILL)
+		if err == nil {
+			return nil
+		}
+		if strings.Contains(err.Error(), "no such process") {
+			return nil
+		}
+		return err
+	}
+	if err := resolver(); err != nil {
+		return xerror.New(op, err)
+	}
+	return nil
+}
+
+func restart(logger xlog.Logger, proc *os.Process) error {
 	const op string = "chrome.restart"
-	resolver := func() (*os.Process, error) {
+	logger.DebugOp(op, "restarting Google Chrome headless process using port 9222...")
+	resolver := func() error {
+		// kill the existing process first.
+		if err := kill(logger, proc); err != nil {
+			return err
+		}
+		cmd, err := cmd(logger)
+		if err != nil {
+			return err
+		}
 		// we try to restart the process.
 		xexec.LogBeforeExecute(logger, cmd)
 		if err := cmd.Start(); err != nil {
-			return cmd.Process, err
+			return err
 		}
-		// we wait the process to be ready.
-		warmup(logger)
 		// if the process failed to restart correctly,
 		// we have to restart it again.
 		if !isViable(logger) {
-			return restart(ctx, logger, cmd)
+			return restart(logger, cmd.Process)
 		}
-		return cmd.Process, nil
+		return nil
 	}
-	proc, err := resolver()
-	if err != nil {
-		return proc, xerror.New(op, err)
+	if err := resolver(); err != nil {
+		return xerror.New(op, err)
 	}
-	return proc, err
+	return nil
 }
 
 func isViable(logger xlog.Logger) bool {
-	const op string = "chrome.isViable"
-	ctx, cancel := context.WithCancel(context.Background())
-	defer cancel()
-	endpoint := "http://localhost:9222"
-	logger.DebugfOp(
-		op,
-		"checking Google Chrome process viability via endpoint '%s/json/version'",
-		endpoint,
+	const (
+		op                string = "chrome.isViable"
+		maxViabilityTests int    = 5
 	)
-	v, err := devtool.New(endpoint).Version(ctx)
-	if err != nil {
-		logger.ErrorfOp(
+	viable := func() bool {
+		ctx, cancel := context.WithCancel(context.Background())
+		defer cancel()
+		endpoint := "http://localhost:9222"
+		logger.DebugfOp(
 			op,
-			"Google Chrome is not viable as endpoint returned '%v'",
-			err,
+			"checking Google Chrome process viability via endpoint '%s/json/version'",
+			endpoint,
 		)
-		return false
+		v, err := devtool.New(endpoint).Version(ctx)
+		if err != nil {
+			logger.ErrorfOp(
+				op,
+				"Google Chrome is not viable as endpoint returned '%v'",
+				err,
+			)
+			return false
+		}
+		logger.DebugfOp(
+			op,
+			"Google Chrome is viable as endpoint returned '%v'",
+			v,
+		)
+		return true
 	}
-	logger.DebugfOp(
-		op,
-		"Google Chrome is viable as endpoint returned '%v'",
-		v,
-	)
-	return true
+	result := false
+	for i := 0; i < maxViabilityTests && !result; i++ {
+		warmup(logger)
+		result = viable()
+	}
+	return result
 }
 
 func warmup(logger xlog.Logger) {
 	const op string = "chrome.warmup"
-	warmupTime := xtime.Duration(10)
+	warmupTime := xtime.Duration(0.5)
 	logger.DebugfOp(
 		op,
 		"waiting '%v' for allowing Google Chrome to warmup",

internal/pkg/printer/merge.go

@@ -59,12 +59,7 @@ func (p mergePrinter) Print(destination string) error {
 		var args []string
 		args = append(args, p.fpaths...)
 		args = append(args, "cat", "output", destination)
-		cmd, err := xexec.CommandContext(p.ctx, p.logger, "pdftk", args...)
-		if err != nil {
-			return err
-		}
-		xexec.LogBeforeExecute(p.logger, cmd)
-		return cmd.Run()
+		return xexec.Run(p.ctx, p.logger, "pdftk", args...)
 	}
 	if err := resolver(); err != nil {
 		return xcontext.MustHandleError(

internal/pkg/printer/office.go

@@ -5,8 +5,6 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
-	"strings"
-	"syscall"
 
 	"github.com/phayes/freeport"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/conf"
@@ -106,43 +104,7 @@ func unoconv(ctx context.Context, logger xlog.Logger, fpath, destination string,
 			args = append(args, "--printer", "PaperOrientation=landscape")
 		}
 		args = append(args, "--output", destination, fpath)
-		cmd, err := xexec.Command(
-			logger,
-			"unoconv",
-			args...,
-		)
-		if err != nil {
-			return err
-		}
-		xexec.LogBeforeExecute(logger, cmd)
-		// see https://medium.com/@felixge/killing-a-child-process-and-all-of-its-children-in-go-54079af94773.
-		kill := func() {
-			err := syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL)
-			if err == nil {
-				return
-			}
-			if !strings.Contains(err.Error(), "no such process") {
-				logger.ErrorOp(op, err)
-			}
-		}
-		cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
-		if err := cmd.Start(); err != nil {
-			return err
-		}
-		result := make(chan error, 1)
-		go func() {
-			result <- cmd.Wait()
-		}()
-		select {
-		case err := <-result:
-			logger.DebugfOp(op, "command '%s' finished", strings.Join(cmd.Args, " "))
-			kill()
-			return err
-		case <-ctx.Done():
-			logger.DebugfOp(op, "command '%s' failed to finish before context.Context deadline", strings.Join(cmd.Args, " "))
-			kill()
-			return ctx.Err()
-		}
+		return xexec.Run(ctx, logger, "unoconv", args...)
 	}
 	if err := resolver(); err != nil {
 		return xerror.New(op, err)

internal/pkg/xexec/doc.go

@@ -1,6 +1,7 @@
 /*
 Package xexec helps creating exec.Cmd
-with logging.
+with logging and executing those commands
+without leaking orphan processes.
 
 All functions return our standard xerror.Error
 in case of error.

internal/pkg/xexec/xexec.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"os/exec"
 	"strings"
+	"syscall"
 
 	"github.com/thecodingmachine/gotenberg/internal/pkg/xerror"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/xlog"
@@ -43,6 +44,61 @@ func CommandContext(ctx context.Context, logger xlog.Logger, binary string, args
 	return cmd, nil
 }
 
+/*
+Run runs a command.
+
+If command finishes or fails to finish
+before context.Context deadline, kill the
+corresponding process in a way which does
+not leak orphan processes.
+*/
+func Run(ctx context.Context, logger xlog.Logger, binary string, args ...string) error {
+	const op string = "xexec.Run"
+	resolver := func() error {
+		cmd, err := Command(
+			logger,
+			binary,
+			args...,
+		)
+		if err != nil {
+			return err
+		}
+		LogBeforeExecute(logger, cmd)
+		// see https://medium.com/@felixge/killing-a-child-process-and-all-of-its-children-in-go-54079af94773.
+		kill := func() {
+			err := syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL)
+			if err == nil {
+				return
+			}
+			if !strings.Contains(err.Error(), "no such process") {
+				logger.ErrorOp(op, err)
+			}
+		}
+		cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
+		if err := cmd.Start(); err != nil {
+			return err
+		}
+		result := make(chan error, 1)
+		go func() {
+			result <- cmd.Wait()
+		}()
+		select {
+		case err := <-result:
+			logger.DebugfOp(op, "command '%s' finished", strings.Join(cmd.Args, " "))
+			kill()
+			return err
+		case <-ctx.Done():
+			logger.DebugfOp(op, "command '%s' failed to finish before context.Context deadline", strings.Join(cmd.Args, " "))
+			kill()
+			return ctx.Err()
+		}
+	}
+	if err := resolver(); err != nil {
+		return xerror.New(op, err)
+	}
+	return nil
+}
+
 // LogBeforeExecute logs a command before its execution.
 func LogBeforeExecute(logger xlog.Logger, cmd *exec.Cmd) {
 	const op string = "xexec.LogBeforeExecute"
@@ -87,7 +143,7 @@ func logCommandOutput(logger xlog.Logger, reader io.ReadCloser, outputType strin
 	for {
 		line, _, err := r.ReadLine()
 		if err != nil {
-			if err != io.EOF {
+			if err != io.EOF && !strings.Contains(err.Error(), "file already closed") {
 				logger.ErrorOp(op, err)
 			}
 			break

internal/pkg/xexec/xexec_test.go

@@ -5,6 +5,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/thecodingmachine/gotenberg/internal/pkg/xcontext"
 	"github.com/thecodingmachine/gotenberg/test"
 )
 
@@ -37,3 +38,16 @@ func TestCommandContext(t *testing.T) {
 	LogBeforeExecute(logger, cmd)
 	assert.Nil(t, err)
 }
+
+func TestRun(t *testing.T) {
+	logger := test.DebugLogger()
+	// should run without issue.
+	err := Run(context.Background(), logger, "echo", "Hello", "World")
+	assert.Nil(t, err)
+	// should not be OK as context.Context
+	// should timeout.
+	ctx, cancel := xcontext.WithTimeout(logger, 0)
+	defer cancel()
+	err = Run(ctx, logger, "echo", "Hello", "World")
+	assert.NotNil(t, err)
+}

test/cmd/chrome.go

@@ -1,8 +1,6 @@
 package main
 
 import (
-	"context"
-
 	"github.com/thecodingmachine/gotenberg/internal/pkg/chrome"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/conf"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/xlog"
@@ -15,9 +13,8 @@ func main() {
 	if err != nil {
 		systemLogger.FatalOp(op, err)
 	}
-	// start Google Chrome.
-	_, err = chrome.Start(context.Background(), systemLogger)
-	if err != nil {
+	// start Google Chrome headless.
+	if err := chrome.Start(systemLogger); err != nil {
 		systemLogger.FatalOp(op, err)
 	}
 }