clh: Improve hypervisor logging

Use systemd-cat to collect hypervisor output. The `systemd-cat` program
will open a journal fd and call `cat(1)` to redirect all the output to
the fd. This requires an extra binary to read from hypervisor stdout
(that has combined stdin, stderr and serial terminal). But because it is
cat the overhead is minimal and only is started on Kata debug mode.

Fixes: kata-containers#2439

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>

virtcontainers/clh.go

@@ -6,10 +6,10 @@
 package virtcontainers
 
 import (
-	"bytes"
 	"context"
 	"encoding/json"
 	"fmt"
+	"io/ioutil"
 	"net"
 	"net/http"
 	"os"
@@ -59,9 +59,7 @@ const (
 	clhStopSandboxTimeout = 3
 	clhSocket             = "clh.sock"
 	clhAPISocket          = "clh-api.sock"
-	clhLogFile            = "clh.log"
 	virtioFsSocket        = "virtiofsd.sock"
-	clhSerial             = "serial-tty.log"
 	supportedMajorVersion = 0
 	supportedMinorVersion = 5
 	defaultClhPath        = "/usr/local/bin/cloud-hypervisor"
@@ -120,7 +118,6 @@ type cloudHypervisor struct {
 	APIClient clhClient
 	version   CloudHypervisorVersion
 	vmconfig  chclient.VmConfig
-	cmdOutput bytes.Buffer
 	virtiofsd Virtiofsd
 	store     persistapi.PersistDriver
 }
@@ -290,13 +287,8 @@ func (clh *cloudHypervisor) createSandbox(ctx context.Context, id string, networ
 
 	// set the serial console to the cloud hypervisor
 	if clh.config.Debug {
-		serialPath, err := clh.serialPath(clh.id)
-		if err != nil {
-			return err
-		}
 		clh.vmconfig.Serial = chclient.ConsoleConfig{
-			Mode: cctFILE,
-			File: serialPath,
+			Mode: cctTTY,
 		}
 
 	} else {
@@ -372,17 +364,12 @@ func (clh *cloudHypervisor) startSandbox(timeout int) error {
 	var strErr string
 	strErr, pid, err := clh.LaunchClh()
 	if err != nil {
-		return fmt.Errorf("failed to launch cloud-hypervisor: %s, error messages from log: %s", err, strErr)
-	}
-	clh.state.PID = pid
-
-	if err := clh.waitVMM(clhTimeout); err != nil {
-		clh.Logger().WithField("error", err).WithField("output", clh.cmdOutput.String()).Warn("cloud-hypervisor init failed")
 		if shutdownErr := clh.virtiofsd.Stop(); shutdownErr != nil {
 			clh.Logger().WithField("error", shutdownErr).Warn("error shutting down Virtiofsd")
 		}
-		return err
+		return fmt.Errorf("failed to launch cloud-hypervisor: %q, hypervisor output:\n%s", err, strErr)
 	}
+	clh.state.PID = pid
 
 	if err := clh.bootVM(ctx); err != nil {
 		return err
@@ -775,18 +762,10 @@ func (clh *cloudHypervisor) vsockSocketPath(id string) (string, error) {
 	return utils.BuildSocketPath(clh.store.RunVMStoragePath(), id, clhSocket)
 }
 
-func (clh *cloudHypervisor) serialPath(id string) (string, error) {
-	return utils.BuildSocketPath(clh.store.RunVMStoragePath(), id, clhSerial)
-}
-
 func (clh *cloudHypervisor) apiSocketPath(id string) (string, error) {
 	return utils.BuildSocketPath(clh.store.RunVMStoragePath(), id, clhAPISocket)
 }
 
-func (clh *cloudHypervisor) logFilePath(id string) (string, error) {
-	return utils.BuildSocketPath(clh.store.RunVMStoragePath(), id, clhLogFile)
-}
-
 func (clh *cloudHypervisor) waitVMM(timeout uint) error {
 	clhRunning, err := clh.isClhRunning(timeout)
 
@@ -877,45 +856,61 @@ func (clh *cloudHypervisor) getAvailableVersion() error {
 
 func (clh *cloudHypervisor) LaunchClh() (string, int, error) {
 
-	errStr := ""
-
 	clhPath, err := clh.clhPath()
 	if err != nil {
 		return "", -1, err
 	}
 
 	args := []string{cscAPIsocket, clh.state.apiSocket}
 	if clh.config.Debug {
-
-		logfile, err := clh.logFilePath(clh.id)
-		if err != nil {
-			return "", -1, err
-		}
-		args = append(args, cscLogFile)
-		args = append(args, logfile)
+		args = append(args, "-vvv")
 	}
 
 	clh.Logger().WithField("path", clhPath).Info()
 	clh.Logger().WithField("args", strings.Join(args, " ")).Info()
 
-	cmd := exec.Command(clhPath, args...)
-	cmd.Stdout = &clh.cmdOutput
-	cmd.Stderr = &clh.cmdOutput
+	cmdHypervisor := exec.Command(clhPath, args...)
 
 	if clh.config.Debug {
-		cmd.Env = os.Environ()
-		cmd.Env = append(cmd.Env, "RUST_BACKTRACE=full")
+		cmdHypervisor.Env = os.Environ()
+		cmdHypervisor.Env = append(cmdHypervisor.Env, "RUST_BACKTRACE=full")
+	}
+
+	hypervisorOutput, err := cmdHypervisor.StdoutPipe()
+	if err != nil {
+		return "", -1, err
 	}
+	cmdHypervisor.Stderr = cmdHypervisor.Stdout
 
-	if err := utils.StartCmd(cmd); err != nil {
-		fmt.Println("Error starting cloudHypervisor", err)
-		if cmd.Process != nil {
-			cmd.Process.Kill()
+	err = utils.StartCmd(cmdHypervisor)
+	if err != nil {
+		return "", -1, err
+	}
+
+	if err := clh.waitVMM(clhTimeout); err != nil {
+		clh.Logger().WithField("error", err).Warn("cloud-hypervisor init failed")
+		var output string
+
+		b, errRead := ioutil.ReadAll(hypervisorOutput)
+		if errRead != nil {
+			output = "failed to read hypervisor output to get error information"
+		} else {
+			output = string(b)
+		}
+
+		return output, -1, err
+	}
+
+	if clh.config.Debug {
+		cmdLogger := utils.NewProgramLogger("kata-hypervisor")
+		clh.Logger().Debugf("Starting process logger(%s) for hypervisor", cmdLogger)
+		if err := cmdLogger.StartLogger(hypervisorOutput); err != nil {
+			// Not critical to run a container, but output wont be logged
+			clh.Logger().Warnf("Failed start process logger(%s) %s", cmdLogger, err)
 		}
-		return errStr, 0, err
 	}
 
-	return errStr, cmd.Process.Pid, nil
+	return "", cmdHypervisor.Process.Pid, nil
 }
 
 //###########################################################################
@@ -926,13 +921,12 @@ func (clh *cloudHypervisor) LaunchClh() (string, int, error) {
 
 const (
 	cctOFF  string = "Off"
-	cctFILE string = "File"
 	cctNULL string = "Null"
+	cctTTY  string = "Tty"
 )
 
 const (
 	cscAPIsocket string = "--api-socket"
-	cscLogFile   string = "--log-file"
 )
 
 //****************************************

virtcontainers/utils/utils.go

@@ -9,6 +9,7 @@ import (
 	"crypto/rand"
 	"errors"
 	"fmt"
+	"io"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -275,3 +276,23 @@ const (
 	MiB          = KiB << 10
 	GiB          = MiB << 10
 )
+
+// Binary to use to log program output
+const LoggerBinaryName = "systemd-cat"
+
+type ProgramLogger struct {
+	cmd *exec.Cmd
+}
+
+func NewProgramLogger(loggerLabel string) ProgramLogger {
+	return ProgramLogger{cmd: exec.Command(LoggerBinaryName, "-t", loggerLabel)}
+}
+
+func (p *ProgramLogger) StartLogger(output io.ReadCloser) error {
+	p.cmd.Stdin = output
+	return StartCmd(p.cmd)
+}
+
+func (p ProgramLogger) String() string {
+	return p.cmd.Path
+}