To fix web server logs' header missing issue (#424)

* Fix for issue

* Tests case added

* Update main.go

Keep the mirror code ready before web server comes up and would start logging. For this, moved the postInit() function call after checkLogSourceForMirroring("web").

* Updates post review meeting

* Update docker_api_test.go

To fix travis build error

* Comment altered

cmd/runmqserver/logging.go

@@ -211,7 +211,7 @@ func mirrorHTPasswdLogs(ctx context.Context, wg *sync.WaitGroup, name string, fr
 
 // mirrorWebServerLogs starts a goroutine to mirror the contents of the Liberty web server messages.log
 func mirrorWebServerLogs(ctx context.Context, wg *sync.WaitGroup, name string, fromStart bool, mf mirrorFunc) (chan error, error) {
-	return mirrorLog(ctx, wg, "/var/mqm/web/installations/Installation1/servers/mqweb/logs/messages.log", false, mf, true)
+	return mirrorLog(ctx, wg, "/var/mqm/web/installations/Installation1/servers/mqweb/logs/messages.log", fromStart, mf, true)
 }
 
 func getDebug() bool {

cmd/runmqserver/main.go

@@ -165,6 +165,27 @@ func doMain() error {
 		log.Println("One or more invalid value is provided for MQ_LOGGING_CONSOLE_SOURCE. Allowed values are 'qmgr' & 'web' in csv format")
 	}
 
+	var wg sync.WaitGroup
+	defer func() {
+		log.Debug("Waiting for log mirroring to complete")
+		wg.Wait()
+	}()
+	ctx, cancelMirror := context.WithCancel(context.Background())
+	defer func() {
+		log.Debug("Cancel log mirroring")
+		cancelMirror()
+	}()
+
+	//For mirroring web server logs if source variable is set
+	if checkLogSourceForMirroring("web") {
+		// Always log from the end of the web server messages.log, because the log rotation should happen as soon as the web server starts
+		_, err = mirrorWebServerLogs(ctx, &wg, name, false, mf)
+		if err != nil {
+			logTermination(err)
+			return err
+		}
+	}
+
 	err = postInit(name, keyLabel, defaultP12Truststore)
 	if err != nil {
 		logTermination(err)
@@ -205,17 +226,6 @@ func doMain() error {
 		}
 	}
 
-	var wg sync.WaitGroup
-	defer func() {
-		log.Debug("Waiting for log mirroring to complete")
-		wg.Wait()
-	}()
-	ctx, cancelMirror := context.WithCancel(context.Background())
-	defer func() {
-		log.Debug("Cancel log mirroring")
-		cancelMirror()
-	}()
-
 	//For mirroring mq system logs and qm logs, if environment variable is set
 	if checkLogSourceForMirroring("qmgr") {
 		//Mirror MQ system logs
@@ -241,17 +251,6 @@ func doMain() error {
 		}
 	}
 
-	//For mirroring web server logs if source variable is set
-	if checkLogSourceForMirroring("web") {
-		// Always log from the start of the web server messages.log, as
-		// Liberty resets it.
-		_, err = mirrorWebServerLogs(ctx, &wg, name, true, mf)
-		if err != nil {
-			logTermination(err)
-			return err
-		}
-	}
-
 	err = updateCommandLevel()
 	if err != nil {
 		logTermination(err)

test/container/docker_api_test.go

@@ -1672,6 +1672,51 @@ func TestLoggingConsoleSetToQmgr(t *testing.T) {
 	stopContainer(t, cli, id)
 }
 
+func TestWebLogsHeaderRotation(t *testing.T) {
+
+	t.Parallel()
+	cli := ce.NewContainerClient()
+	containerConfig := ce.ContainerConfig{
+		Env: []string{
+			"LICENSE=accept",
+			"MQ_QMGR_NAME=qm1",
+			"MQ_ENABLE_EMBEDDED_WEB_SERVER=true",
+			"MQ_LOGGING_CONSOLE_SOURCE=qmgr,web",
+		},
+	}
+	id := runContainer(t, cli, &containerConfig)
+	defer cleanContainer(t, cli, id)
+	waitForReady(t, cli, id)
+
+	consoleLogs, errJson := waitForMessageInLog(t, cli, id, "CWWKF0011I")
+	if errJson != nil {
+		t.Errorf("%v", errJson)
+	}
+	//The below variable represents the first message in messages.log of web server, considered as the header message
+	webLogheader := "product = WebSphere Application Server"
+
+	if !strings.Contains(consoleLogs, webLogheader) {
+		t.Errorf("Console log is without web server header message\n \"%v\"", consoleLogs)
+	}
+
+	// Stop the container cleanly
+	stopContainer(t, cli, id)
+	startContainer(t, cli, id)
+	waitForReady(t, cli, id)
+
+	consoleLogs2, errJson := waitForMessageCountInLog(t, cli, id, "CWWKF0011I", 2)
+	if errJson != nil {
+		t.Errorf("%v", errJson)
+	}
+	t.Logf("Total headers found is %v", strings.Count(consoleLogs2, webLogheader))
+	if strings.Count(consoleLogs2, webLogheader) != 2 {
+		t.Errorf("Console logs do not contain header message after restart \"%v\"", consoleLogs2)
+	}
+
+	// Stop the container cleanly
+	stopContainer(t, cli, id)
+}
+
 // Test queue manager with both personal and CA certificate having the same DN
 func TestSameSubDNError(t *testing.T) {
 	expectedOutput := "Error: The Subject DN of the Issuer Certificate and the Queue Manager are same"

test/container/docker_api_test_util.go

@@ -827,7 +827,7 @@ func testLogFilePages(t *testing.T, cli ce.ContainerInterface, id string, qmName
 }
 
 // waitForMessageInLog will check for a particular message with wait
-func waitForMessageInLog(t *testing.T, cli ce.ContainerInterface, id string, expecteMessageId string) (string, error) {
+func waitForMessageInLog(t *testing.T, cli ce.ContainerInterface, id string, expectedMessageId string) (string, error) {
 	var jsonLogs string
 	ctx, cancel := context.WithTimeout(context.Background(), 2*time.Minute)
 	defer cancel()
@@ -835,11 +835,29 @@ func waitForMessageInLog(t *testing.T, cli ce.ContainerInterface, id string, exp
 		select {
 		case <-time.After(1 * time.Second):
 			jsonLogs = inspectLogs(t, cli, id)
-			if strings.Contains(jsonLogs, expecteMessageId) {
+			if strings.Contains(jsonLogs, expectedMessageId) {
 				return jsonLogs, nil
 			}
 		case <-ctx.Done():
-			return "", fmt.Errorf("Expected message Id %s was not logged.", expecteMessageId)
+			return "", fmt.Errorf("expected message Id %s was not logged", expectedMessageId)
+		}
+	}
+}
+
+// waitForMessageCountInLog will check for a particular message with wait and must occur exact number of times in log as specified by count
+func waitForMessageCountInLog(t *testing.T, cli ce.ContainerInterface, id string, expectedMessageId string, count int) (string, error) {
+	var jsonLogs string
+	ctx, cancel := context.WithTimeout(context.Background(), 2*time.Minute)
+	defer cancel()
+	for {
+		select {
+		case <-time.After(1 * time.Second):
+			jsonLogs = inspectLogs(t, cli, id)
+			if strings.Contains(jsonLogs, expectedMessageId) && strings.Count(jsonLogs, expectedMessageId) == count {
+				return jsonLogs, nil
+			}
+		case <-ctx.Done():
+			return "", fmt.Errorf("expected message Id %s was not logged or it was not logged %v times", expectedMessageId, count)
 		}
 	}
 }