Merge pull request #4331 from vanhalenar/logfix2

USHIFT-5221: Fix StartupRecorder race condition

Author: openshift-merge-bot[bot]

pkg/cmd/run.go

@@ -262,7 +262,6 @@ func RunMicroshift(cfg *config.Config) error {
 	select {
 	case <-ready:
 		startRec.MicroshiftReady()
-		startRec.OutputData()
 
 		os.Setenv("NOTIFY_SOCKET", notifySocket)
 		if supported, err := daemon.SdNotify(false, daemon.SdNotifyReady); err != nil {

pkg/servicemanager/manager.go

@@ -59,6 +59,8 @@ func (m *ServiceManager) Run(ctx context.Context, ready chan<- struct{}, stopped
 	defer close(stopped)
 
 	services := m.services
+
+	m.startRec.ServiceCount = len(services)
 	// No need for topological sorting here as long as we enforce order while adding services.
 	// services, err := m.topoSort(services)
 	// if err != nil {

pkg/servicemanager/startuprecorder/startuprecorder.go

@@ -32,11 +32,15 @@ type StartupData struct {
 type StartupRecorder struct {
 	Data StartupData
 
-	m sync.Mutex
+	ServiceCount int
+	allLogged    chan struct{}
+	m            sync.Mutex
 }
 
 func New() *StartupRecorder {
-	return &StartupRecorder{}
+	return &StartupRecorder{
+		allLogged: make(chan struct{}),
+	}
 }
 
 func (l *StartupRecorder) ServiceReady(serviceName string, dependencies []string, start time.Time) {
@@ -56,6 +60,10 @@ func (l *StartupRecorder) ServiceReady(serviceName string, dependencies []string
 	l.m.Lock()
 	defer l.m.Unlock()
 	l.Data.Services = append(l.Data.Services, serviceData)
+	l.ServiceCount--
+	if l.ServiceCount == 0 {
+		close(l.allLogged)
+	}
 }
 
 func (l *StartupRecorder) MicroshiftStarts(start time.Time) {
@@ -69,6 +77,8 @@ func (l *StartupRecorder) MicroshiftReady() {
 	klog.InfoS("MICROSHIFT READY", "since-start", time.Since(l.Data.Microshift.Start))
 	l.Data.Microshift.Ready = ready
 	l.Data.Microshift.TimeToReady = ready.Sub(l.Data.Microshift.Start)
+
+	l.OutputData()
 }
 
 func (l *StartupRecorder) ServicesStart(start time.Time) {
@@ -77,18 +87,25 @@ func (l *StartupRecorder) ServicesStart(start time.Time) {
 }
 
 func (l *StartupRecorder) OutputData() {
-	jsonOutput, err := json.Marshal(l.Data)
-	if err != nil {
-		klog.Error("Failed to marshal startup data")
-	}
-
-	klog.Infof("Startup data: %s", string(jsonOutput))
-
-	path, ok := os.LookupEnv("STARTUP_LOGS_PATH")
-	if ok {
-		err = os.WriteFile(path, jsonOutput, 0600)
-		if err != nil {
-			klog.Error("Failed to write startup data to file")
+	go func() {
+		select {
+		case <-l.allLogged:
+			jsonOutput, err := json.Marshal(l.Data)
+			if err != nil {
+				klog.Error("Failed to marshal startup data")
+			}
+
+			klog.Infof("Startup data: %s", string(jsonOutput))
+
+			path, ok := os.LookupEnv("STARTUP_LOGS_PATH")
+			if ok {
+				err = os.WriteFile(path, jsonOutput, 0600)
+				if err != nil {
+					klog.Error("Failed to write startup data to file")
+				}
+			}
+		case <-time.After(30 * time.Second):
+			klog.Error("StartupRecorder timed out")
 		}
-	}
+	}()
 }