runtime: Collect QEMU's stderr

LaunchQemu now connects a pipe to QEMU's stderr and makes it
usable by callers through a Go io.ReadCloser object. As
explained in [0], all messages should be read from the pipe
before calling cmd.Wait : introduce a LogAndWait helper to handle
that.

Fixes #5780

Signed-off-by: Greg Kurz <groug@kaod.org>

src/runtime/pkg/govmm/qemu/examples_test.go

@@ -32,7 +32,7 @@ func Example() {
 	// flag.
 	// It will set up a unix domain socket called /tmp/qmp-socket that we
 	// can use to manage the instance.
-	proc, err := qemu.LaunchCustomQemu(context.Background(), "", params, nil, nil, nil)
+	proc, _, err := qemu.LaunchCustomQemu(context.Background(), "", params, nil, nil, nil)
 	if err != nil {
 		panic(err)
 	}

src/runtime/pkg/govmm/qemu/qemu.go

@@ -16,6 +16,7 @@ package qemu
 import (
 	"context"
 	"fmt"
+	"io"
 	"log"
 	"os"
 	"os/exec"
@@ -2985,7 +2986,7 @@ func (config *Config) appendFwCfg(logger QMPLog) {
 // The Config parameter contains a set of qemu parameters and settings.
 //
 // See LaunchCustomQemu for more information.
-func LaunchQemu(config Config, logger QMPLog) (*exec.Cmd, error) {
+func LaunchQemu(config Config, logger QMPLog) (*exec.Cmd, io.ReadCloser, error) {
 	config.appendName()
 	config.appendUUID()
 	config.appendMachine()
@@ -3008,7 +3009,7 @@ func LaunchQemu(config Config, logger QMPLog) (*exec.Cmd, error) {
 	config.appendSeccompSandbox()
 
 	if err := config.appendCPUs(); err != nil {
-		return nil, err
+		return nil, nil, err
 	}
 
 	ctx := config.Ctx
@@ -3039,11 +3040,12 @@ func LaunchQemu(config Config, logger QMPLog) (*exec.Cmd, error) {
 //
 // This function writes its log output via logger parameter.
 //
-// The function returns cmd, nil where cmd is a Go exec.Cmd object
-// representing the QEMU process if launched successfully. Otherwise
-// nil, err where err is a Go error object is returned.
+// The function returns cmd, reader, nil where cmd is a Go exec.Cmd object
+// representing the QEMU process and reader a Go io.ReadCloser object
+// connected to QEMU's stderr, if launched successfully. Otherwise
+// nil, nil, err where err is a Go error object is returned.
 func LaunchCustomQemu(ctx context.Context, path string, params []string, fds []*os.File,
-	attr *syscall.SysProcAttr, logger QMPLog) (*exec.Cmd, error) {
+	attr *syscall.SysProcAttr, logger QMPLog) (*exec.Cmd, io.ReadCloser, error) {
 	if logger == nil {
 		logger = qmpNullLogger{}
 	}
@@ -3061,12 +3063,17 @@ func LaunchCustomQemu(ctx context.Context, path string, params []string, fds []*
 
 	cmd.SysProcAttr = attr
 
+	reader, err := cmd.StderrPipe()
+	if err != nil {
+		logger.Errorf("Unable to connect stderr to a pipe")
+		return nil, nil, err
+	}
 	logger.Infof("launching %s with: %v", path, params)
 
-	err := cmd.Start()
+	err = cmd.Start()
 	if err != nil {
 		logger.Errorf("Unable to launch %s: %v", path, err)
-		return nil, err
+		return nil, nil, err
 	}
-	return cmd, nil
+	return cmd, reader, nil
 }

src/runtime/virtcontainers/qemu.go

@@ -13,11 +13,14 @@ import (
 	"encoding/hex"
 	"encoding/json"
 	"fmt"
+	"io"
 	"math"
 	"net"
 	"os"
+	"os/exec"
 	"os/user"
 	"path/filepath"
+	"regexp"
 	"strconv"
 	"strings"
 	"sync"
@@ -865,6 +868,24 @@ func (q *qemu) setupEarlyQmpConnection() (net.Conn, error) {
 	return conn, nil
 }
 
+func (q *qemu) LogAndWait(qemuCmd *exec.Cmd, reader io.ReadCloser) {
+	pid := qemuCmd.Process.Pid
+	q.Logger().Infof("Start logging QEMU (qemuPid=%d)", pid)
+	scanner := bufio.NewScanner(reader)
+	warnRE := regexp.MustCompile("(^[^:]+: )warning: ")
+	for scanner.Scan() {
+		text := scanner.Text()
+		if warnRE.MatchString(text) {
+			text = warnRE.ReplaceAllString(text, "$1")
+			q.Logger().WithField("qemuPid", pid).Warning(text)
+		} else {
+			q.Logger().WithField("qemuPid", pid).Error(text)
+		}
+	}
+	q.Logger().Infof("Stop logging QEMU (qemuPid=%d)", pid)
+	qemuCmd.Wait()
+}
+
 // StartVM will start the Sandbox's VM.
 func (q *qemu) StartVM(ctx context.Context, timeout int) error {
 	span, ctx := katatrace.Trace(ctx, q.Logger(), "StartVM", qemuTracingTags, map[string]string{"sandbox_id": q.id})
@@ -941,7 +962,7 @@ func (q *qemu) StartVM(ctx context.Context, timeout int) error {
 
 	}
 
-	qemuCmd, err := govmmQemu.LaunchQemu(q.qemuConfig, newQMPLogger())
+	qemuCmd, reader, err := govmmQemu.LaunchQemu(q.qemuConfig, newQMPLogger())
 	if err != nil {
 		q.Logger().WithError(err).Error("failed to launch qemu")
 		return fmt.Errorf("failed to launch qemu: %s", err)
@@ -952,10 +973,9 @@ func (q *qemu) StartVM(ctx context.Context, timeout int) error {
 		// actually started.
 		qemuCmd.Wait()
 	} else {
-		// Ensure the QEMU process is reaped after termination
-		go func() {
-			qemuCmd.Wait()
-		}()
+		// Log QEMU errors and ensure the QEMU process is reaped after
+		// termination.
+		go q.LogAndWait(qemuCmd, reader)
 	}
 
 	err = q.waitVM(ctx, qmpConn, timeout)