From 1f7334e3d1d17a60c5db62cd5730d193bd500b7b Mon Sep 17 00:00:00 2001 From: Avinash Ganesh Date: Thu, 1 Jun 2023 17:23:50 +0530 Subject: [PATCH] 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 | 2 +- cmd/runmqserver/main.go | 43 ++++++++++++------------ test/container/docker_api_test.go | 45 ++++++++++++++++++++++++++ test/container/docker_api_test_util.go | 24 ++++++++++++-- 4 files changed, 88 insertions(+), 26 deletions(-) diff --git a/cmd/runmqserver/logging.go b/cmd/runmqserver/logging.go index 1cf8d80..7b756e9 100644 --- a/cmd/runmqserver/logging.go +++ b/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 { diff --git a/cmd/runmqserver/main.go b/cmd/runmqserver/main.go index 09218ad..3d7cfc7 100644 --- a/cmd/runmqserver/main.go +++ b/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) diff --git a/test/container/docker_api_test.go b/test/container/docker_api_test.go index 110d8e3..8147c56 100644 --- a/test/container/docker_api_test.go +++ b/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" diff --git a/test/container/docker_api_test_util.go b/test/container/docker_api_test_util.go index 36497ab..c8ed267 100644 --- a/test/container/docker_api_test_util.go +++ b/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) } } }