start: make sure to print "Starting QEMU" logs

Signed-off-by: Akihiro Suda <akihiro.suda.cz@hco.ntt.co.jp>

cmd/limactl/stop.go

@@ -59,16 +59,17 @@ func stopInstanceGracefully(inst *store.Instance) error {
 		return errors.Errorf("expected status %q, got %q", store.StatusRunning, inst.Status)
 	}
 
+	begin := time.Now() // used for logrus propagation
 	logrus.Infof("Sending SIGINT to hostagent process %d", inst.HostAgentPID)
 	if err := syscall.Kill(inst.HostAgentPID, syscall.SIGINT); err != nil {
 		logrus.Error(err)
 	}
 
 	logrus.Info("Waiting for the host agent and the qemu processes to shut down")
-	return waitForHostAgentTermination(context.TODO(), inst)
+	return waitForHostAgentTermination(context.TODO(), inst, begin)
 }
 
-func waitForHostAgentTermination(ctx context.Context, inst *store.Instance) error {
+func waitForHostAgentTermination(ctx context.Context, inst *store.Instance, begin time.Time) error {
 	ctx2, cancel := context.WithTimeout(ctx, 3*time.Minute)
 	defer cancel()
 
@@ -87,7 +88,7 @@ func waitForHostAgentTermination(ctx context.Context, inst *store.Instance) erro
 	haStdoutPath := filepath.Join(inst.Dir, filenames.HostAgentStdoutLog)
 	haStderrPath := filepath.Join(inst.Dir, filenames.HostAgentStderrLog)
 
-	if err := hostagentapi.WatchEvents(ctx2, haStdoutPath, haStderrPath, onEvent); err != nil {
+	if err := hostagentapi.WatchEvents(ctx2, haStdoutPath, haStderrPath, begin, onEvent); err != nil {
 		return err
 	}
 

pkg/hostagent/api/eventwatcher.go

@@ -10,8 +10,7 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-func WatchEvents(ctx context.Context, haStdoutPath, haStderrPath string, onEvent func(Event) bool) error {
-	begin := time.Now()
+func WatchEvents(ctx context.Context, haStdoutPath, haStderrPath string, begin time.Time, onEvent func(Event) bool) error {
 	haStdoutTail, err := tail.TailFile(haStdoutPath,
 		tail.Config{
 			Follow:    true,

pkg/logrusutil/logrusutil.go

@@ -8,6 +8,8 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
+const epsilon = 1 * time.Second
+
 // PropagateJSON propagates JSONFormatter lines.
 //
 // PanicLevel and FatalLevel are converted to ErrorLevel.
@@ -24,7 +26,7 @@ func PropagateJSON(logger *logrus.Logger, jsonLine []byte, header string, begin
 	if err := json.Unmarshal(jsonLine, &j); err != nil {
 		goto fallback
 	}
-	if !j.Time.IsZero() && !begin.IsZero() && begin.After(j.Time) {
+	if !j.Time.IsZero() && !begin.IsZero() && begin.After(j.Time.Add(epsilon)) {
 		return
 	}
 	lv, err = logrus.ParseLevel(j.Level)

pkg/start/start.go

@@ -80,6 +80,8 @@ func Start(ctx context.Context, inst *store.Instance) error {
 	haCmd.Stdout = haStdoutW
 	haCmd.Stderr = haStderrW
 
+	begin := time.Now() // used for logrus propagation
+
 	if err := haCmd.Start(); err != nil {
 		return err
 	}
@@ -88,7 +90,7 @@ func Start(ctx context.Context, inst *store.Instance) error {
 		return err
 	}
 
-	return watchHostAgentEvents(ctx, inst.Name, haStdoutPath, haStderrPath)
+	return watchHostAgentEvents(ctx, inst.Name, haStdoutPath, haStderrPath, begin)
 	// leave the hostagent process running
 }
 
@@ -106,7 +108,7 @@ func waitHostAgentStart(ctx context.Context, haPIDPath, haStderrPath string) err
 	}
 }
 
-func watchHostAgentEvents(ctx context.Context, instName, haStdoutPath, haStderrPath string) error {
+func watchHostAgentEvents(ctx context.Context, instName, haStdoutPath, haStderrPath string, begin time.Time) error {
 	ctx2, cancel := context.WithTimeout(ctx, 10*time.Minute)
 	defer cancel()
 
@@ -142,7 +144,7 @@ func watchHostAgentEvents(ctx context.Context, instName, haStdoutPath, haStderrP
 		return false
 	}
 
-	if xerr := hostagentapi.WatchEvents(ctx2, haStdoutPath, haStderrPath, onEvent); xerr != nil {
+	if xerr := hostagentapi.WatchEvents(ctx2, haStdoutPath, haStderrPath, begin, onEvent); xerr != nil {
 		return xerr
 	}