Enhanced console logging

Introduce new environment variables:
  * MQ_LOGGING_CONSOLE_SOURCE
  * MQ_LOGGING_CONSOLE_FORMAT
  * MQ_LOGGING_CONSOLE_EXCLUDE_ID

Authored-by: Avinash Ganesh <avinash.v.g@in.ibm.com> and BHAVYA K R <bhavkris@in.ibm.com>
This commit is contained in:
Avinash Ganesh
2023-01-30 19:49:58 +05:30
committed by GitHub Enterprise
parent 5c4422badf
commit 4588cd44f9
8 changed files with 645 additions and 41 deletions

View File

@@ -1,5 +1,5 @@
/*
© Copyright IBM Corporation 2018, 2021
© Copyright IBM Corporation 2018, 2023
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
@@ -19,6 +19,7 @@ import (
"fmt"
"io/ioutil"
"os"
"strings"
"syscall"
"github.com/ibm-messaging/mq-container/internal/htpasswd"
@@ -30,7 +31,20 @@ import (
var log *logger.Logger
func getLogFormat() string {
return os.Getenv("LOG_FORMAT")
logFormat := strings.ToLower(strings.TrimSpace(os.Getenv("MQ_LOGGING_CONSOLE_FORMAT")))
//old-style env var is used.
if logFormat == "" {
logFormat = strings.ToLower(strings.TrimSpace(os.Getenv("LOG_FORMAT")))
}
if logFormat != "" && (logFormat == "basic" || logFormat == "json") {
return logFormat
} else {
//this is the case where value is either empty string or set to something other than "basic"/"json"
logFormat = "basic"
}
return logFormat
}
func getDebug() bool {

View File

@@ -1,5 +1,5 @@
/*
© Copyright IBM Corporation 2017, 2022
© Copyright IBM Corporation 2017, 2023
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
@@ -58,7 +58,20 @@ func logTermination(args ...interface{}) {
}
func getLogFormat() string {
return os.Getenv("LOG_FORMAT")
logFormat := strings.ToLower(strings.TrimSpace(os.Getenv("MQ_LOGGING_CONSOLE_FORMAT")))
//old-style env var is used.
if logFormat == "" {
logFormat = strings.ToLower(strings.TrimSpace(os.Getenv("LOG_FORMAT")))
}
if logFormat != "" && (logFormat == "basic" || logFormat == "json") {
return logFormat
} else {
//this is the case where value is either empty string or set to something other than "basic"/"json"
logFormat = "basic"
}
return logFormat
}
// formatBasic formats a log message parsed from JSON, as "basic" text
@@ -81,6 +94,92 @@ func formatBasic(obj map[string]interface{}) string {
}
// Convert time zone information from some logs (e.g. Liberty) for consistency
obj["ibm_datetime"] = strings.Replace(obj["ibm_datetime"].(string), "+0000", "Z", 1)
if obj["type"] != nil && (obj["type"] == "liberty_message" || obj["type"] == "liberty_trace") {
timeStamp := obj["ibm_datetime"]
threadID := ""
srtModuleName := ""
logLevel := ""
ibmClassName := ""
srtIbmClassName := ""
ibmMethodName := ""
message := ""
if obj["loglevel"] != nil {
//threadID is captured below
if obj["ibm_threadId"] != nil {
threadID = obj["ibm_threadId"].(string)
}
//logLevel character to be mirrored in console web server logging is decided below
logLevelTmp := obj["loglevel"].(string)
switch logLevelTmp {
case "AUDIT":
logLevel = "A"
case "INFO":
logLevel = "I"
case "EVENT":
logLevel = "1"
case "ENTRY":
logLevel = ">"
case "EXIT":
logLevel = "<"
case "FINE":
logLevel = "1"
case "FINER":
logLevel = "2"
case "FINEST":
logLevel = "3"
default:
logLevel = string(logLevelTmp[0])
}
//This is a 13 characters string present in extracted out of module node
if obj["module"] != nil {
srtModuleNameArr := strings.Split(obj["module"].(string), ".")
arrLen := len(srtModuleNameArr)
srtModuleName = srtModuleNameArr[arrLen-1]
if len(srtModuleName) > 13 {
srtModuleName = srtModuleName[0:13]
}
}
if obj["ibm_className"] != nil {
ibmClassName = obj["ibm_className"].(string)
//A 13 character string is extracted from class name. This is required for FINE, FINER & FINEST log lines
ibmClassNameArr := strings.Split(ibmClassName, ".")
arrLen := len(ibmClassNameArr)
srtIbmClassName = ibmClassNameArr[arrLen-1]
if len(srtModuleName) > 13 {
srtIbmClassName = srtIbmClassName[0:13]
}
}
if obj["ibm_methodName"] != nil {
ibmMethodName = obj["ibm_methodName"].(string)
}
if obj["message"] != nil {
message = obj["message"].(string)
}
//For AUDIT & INFO logging
if logLevel == "A" || logLevel == "I" {
return fmt.Sprintf("%s %s %-13s %s %s %s %s\n", timeStamp, threadID, srtModuleName, logLevel, ibmClassName, ibmMethodName, message)
}
//For EVENT logLevel
if logLevelTmp == "EVENT" {
return fmt.Sprintf("%s %s %-13s %s %s\n", timeStamp, threadID, srtModuleName, logLevel, message)
}
//For ENTRY & EXIT
if logLevel == ">" || logLevel == "<" {
return fmt.Sprintf("%s %s %-13s %s %s %s\n", timeStamp, threadID, srtModuleName, logLevel, ibmMethodName, message)
}
//For deeper log levels
if logLevelTmp == "FINE" || logLevel == "2" || logLevel == "3" {
return fmt.Sprintf("%s %s %-13s %s %s %s %s\n", timeStamp, threadID, srtIbmClassName, logLevel, ibmClassName, ibmMethodName, message)
}
}
}
return fmt.Sprintf("%s %s\n", obj["ibm_datetime"], obj["message"])
}
@@ -131,6 +230,11 @@ func configureLogger(name string) (mirrorFunc, error) {
return nil, err
}
return func(msg string, isQMLog bool) bool {
arrLoggingConsoleExcludeIds := strings.Split(strings.ToUpper(os.Getenv("MQ_LOGGING_CONSOLE_EXCLUDE_ID")), ",")
if isExcludedMsgIdPresent(msg, arrLoggingConsoleExcludeIds) {
//If excluded id is present do not mirror it, return back
return false
}
// Check if the message is JSON
if len(msg) > 0 && msg[0] == '{' {
obj, err := processLogMessage(msg)
@@ -155,6 +259,11 @@ func configureLogger(name string) (mirrorFunc, error) {
return nil, err
}
return func(msg string, isQMLog bool) bool {
arrLoggingConsoleExcludeIds := strings.Split(strings.ToUpper(os.Getenv("MQ_LOGGING_CONSOLE_EXCLUDE_ID")), ",")
if isExcludedMsgIdPresent(msg, arrLoggingConsoleExcludeIds) {
//If excluded id is present do not mirror it, return back
return false
}
// Check if the message is JSON
if len(msg) > 0 && msg[0] == '{' {
// Parse the JSON message, and print a simplified version
@@ -197,6 +306,16 @@ func filterQMLogMessage(obj map[string]interface{}) bool {
return false
}
// Function to check if ids provided in MQ_LOGGING_CONSOLE_EXCLUDE_ID are present in given log line or not
func isExcludedMsgIdPresent(msg string, envExcludeIds []string) bool {
for _, id := range envExcludeIds {
if id != "" && strings.Contains(msg, strings.TrimSpace(id)) {
return true
}
}
return false
}
func logDiagnostics() {
if getDebug() {
log.Debug("--- Start Diagnostics ---")
@@ -238,3 +357,68 @@ func logDiagnostics() {
log.Debug("--- End Diagnostics ---")
}
}
// Returns the value of MQ_LOGGING_CONSOLE_SOURCE environment variable
func getMQLogConsoleSource() string {
return strings.ToLower(strings.TrimSpace(os.Getenv("MQ_LOGGING_CONSOLE_SOURCE")))
}
// Function to check if valid values are provided for environment variable MQ_LOGGING_CONSOLE_SOURCE. If not valid, main program throws a warning to console
func isLogConsoleSourceValid() bool {
mqLogSource := getMQLogConsoleSource()
retValue := false
//If nothing is set, we will mirror all, so valid
if mqLogSource == "" {
return true
}
logConsoleSource := strings.Split(mqLogSource, ",")
//This will find out if the environment variable contains permitted values and is comma separated
for _, src := range logConsoleSource {
switch strings.TrimSpace(src) {
//If it is a permitted value, it is valid. Keep it as true, but dont return it. We may encounter something junk soon
case "qmgr", "web", "":
retValue = true
//If invalid entry arrives in-between/anywhere, just return false, there is no turning back
default:
return false
}
}
return retValue
}
// To check which all logs have to be mirrored
func checkLogSourceForMirroring(source string) bool {
logsrcs := getMQLogConsoleSource()
//Nothing set, this is when we mirror all
if logsrcs == "" {
return true
}
//Split the csv environment value so that we get an accurate comparison instead of a contains() check
logSrcArr := strings.Split(logsrcs, ",")
//Iterate through the array to decide on mirroring
for _, arr := range logSrcArr {
switch strings.TrimSpace(arr) {
case "qmgr":
//If value of source is qmgr and it exists in environment variable, mirror qmgr logs
if source == "qmgr" {
return true
}
case "web":
//If value of source is web and it exists in environment variable, and mirror web logs
if source == "web" {
//If older environment variable is set make sure to print appropriate message
if os.Getenv("MQ_ENABLE_EMBEDDED_WEB_SERVER_LOG") != "" {
log.Println("Environment variable MQ_ENABLE_EMBEDDED_WEB_SERVER_LOG has now been replaced. Use MQ_LOGGING_CONSOLE_SOURCE instead.")
}
return true
}
}
}
return false
}

View File

@@ -1,5 +1,5 @@
/*
© Copyright IBM Corporation 2020
© Copyright IBM Corporation 2020, 2023
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
@@ -18,6 +18,7 @@ package main
import (
"encoding/json"
"fmt"
"os"
"strings"
"testing"
)
@@ -53,3 +54,86 @@ func TestFormatBasic(t *testing.T) {
})
}
}
// This test covers for functions isLogConsoleSourceValid() & checkLogSourceForMirroring()
var mqLogSourcesTests = []struct {
testNum int
logsrc string
exptValid bool
exptQmgrSrc bool
exptWebSrc bool
}{
{1, "qmgr,web", true, true, true},
{2, "qmgr", true, true, false},
{3, "web,qmgr", true, true, true},
{4, "web", true, false, true},
{5, " ", true, true, true},
{6, "QMGR,WEB", true, true, true},
{7, "qmgr, ", true, true, false},
{8, "qmgr , web", true, true, true},
{9, "qmgr,dummy", false, true, false},
{10, "fake,dummy", false, false, false},
{11, "qmgr,fake,dummy", false, true, false},
{12, "fake,dummy,web", false, false, true},
{13, "true", false, false, false},
{14, "false", false, false, false},
{15, "", true, true, true},
}
func TestLoggingConsoleSourceInputs(t *testing.T) {
for _, mqlogsrctest := range mqLogSourcesTests {
err := os.Setenv("MQ_LOGGING_CONSOLE_SOURCE", mqlogsrctest.logsrc)
if err != nil {
t.Error(err)
}
isValid := isLogConsoleSourceValid()
if isValid != mqlogsrctest.exptValid {
t.Errorf("Expected return value from isLogConsoleSourceValid() is %v for MQ_LOGGING_CONSOLE_SOURCE='%v', got %v\n", mqlogsrctest.exptValid, mqlogsrctest.logsrc, isValid)
}
isLogSrcQmgr := checkLogSourceForMirroring("qmgr")
if isLogSrcQmgr != mqlogsrctest.exptQmgrSrc {
t.Errorf("Expected return value from checkLogSourceForMirroring() is %v for MQ_LOGGING_CONSOLE_SOURCE='%v', got %v\n", mqlogsrctest.exptQmgrSrc, mqlogsrctest.logsrc, isLogSrcQmgr)
}
isLogSrcWeb := checkLogSourceForMirroring("web")
if isLogSrcWeb != mqlogsrctest.exptWebSrc {
t.Errorf("Expected return value from checkLogSourceForMirroring() is %v for MQ_LOGGING_CONSOLE_SOURCE='%v', got %v\n", mqlogsrctest.exptWebSrc, mqlogsrctest.logsrc, isLogSrcWeb)
}
}
}
// This test covers for function isExcludedMsgIdPresent()
var mqExcludeIDTests = []struct {
testNum int
exculdeIDsArr []string
expectedRetVal bool
logEntry string
}{
{
1,
[]string{"AMQ5051I", "AMQ5037I", "AMQ5975I"},
true,
"{\"ibm_messageId\":\"AMQ5051I\",\"ibm_arithInsert1\":0,\"ibm_arithInsert2\":1,\"message\":\"AMQ5051I: The queue manager task 'AUTOCONFIG' has started.\"}",
},
{
2,
[]string{"AMQ5975I", "AMQ5037I"},
false,
"{\"ibm_messageId\":\"AMQ5051I\",\"ibm_arithInsert1\":0,\"ibm_arithInsert2\":1,\"message\":\"AMQ5051I: The queue manager task 'AUTOCONFIG' has started.\"}",
},
{
3,
[]string{""},
false,
"{\"ibm_messageId\":\"AMQ5051I\",\"ibm_arithInsert1\":0,\"ibm_arithInsert2\":1,\"message\":\"AMQ5051I: The queue manager task 'AUTOCONFIG' has started.\"}",
},
}
func TestIsExcludedMsgIDPresent(t *testing.T) {
for _, excludeIDTest := range mqExcludeIDTests {
retVal := isExcludedMsgIdPresent(excludeIDTest.logEntry, excludeIDTest.exculdeIDsArr)
if retVal != excludeIDTest.expectedRetVal {
t.Errorf("%v. Expected return value from isExcludedMsgIdPresent() is %v for MQ_LOGGING_CONSOLE_EXCLUDE_ID='%v', got %v\n",
excludeIDTest.testNum, excludeIDTest.expectedRetVal, excludeIDTest.exculdeIDsArr, retVal)
}
}
}

View File

@@ -160,6 +160,11 @@ func doMain() error {
return err
}
//Validate MQ_LOG_CONSOLE_SOURCE variable
if !isLogConsoleSourceValid() {
log.Println("One or more invalid value is provided for MQ_LOGGING_CONSOLE_SOURCE. Allowed values are 'qmgr' & 'web' in csv format")
}
err = postInit(name, keyLabel, defaultP12Truststore)
if err != nil {
logTermination(err)
@@ -210,17 +215,24 @@ func doMain() error {
log.Debug("Cancel log mirroring")
cancelMirror()
}()
// TODO: Use the error channel
_, err = mirrorSystemErrorLogs(ctx, &wg, mf)
if err != nil {
logTermination(err)
return err
}
_, err = mirrorQueueManagerErrorLogs(ctx, &wg, name, newQM, mf)
if err != nil {
logTermination(err)
return err
//For mirroring mq system logs and qm logs, if environment variable is set
if checkLogSourceForMirroring("qmgr") {
//Mirror MQ system logs
_, err = mirrorSystemErrorLogs(ctx, &wg, mf)
if err != nil {
logTermination(err)
return err
}
//Mirror queue manager logs
_, err = mirrorQueueManagerErrorLogs(ctx, &wg, name, newQM, mf)
if err != nil {
logTermination(err)
return err
}
}
if *devFlag {
_, err = mirrorHTPasswdLogs(ctx, &wg, name, newQM, mf)
if err != nil {
@@ -228,9 +240,9 @@ func doMain() error {
return err
}
}
// Recommended to use this option in conjunction with setting WLP_LOGGING_MESSAGE_FORMAT=JSON
mirrorWebLog := os.Getenv("MQ_ENABLE_EMBEDDED_WEB_SERVER_LOG")
if mirrorWebLog == "true" || mirrorWebLog == "1" {
//For mirroring web server logs if source variable is set
if checkLogSourceForMirroring("web") {
_, err = mirrorWebServerLogs(ctx, &wg, name, newQM, mf)
if err != nil {
logTermination(err)