Merge pull request #1155 from oracle/tbarnes-script-logging-updates

Pod/job script logging improvements

Author: rjeberhard

operator/src/main/java/oracle/kubernetes/operator/helpers/JobHelper.java

@@ -4,6 +4,9 @@
 
 package oracle.kubernetes.operator.helpers;
 
+import java.io.BufferedReader;
+import java.io.IOException;
+import java.io.StringReader;
 import java.util.List;
 
 import io.kubernetes.client.models.V1DeleteOptions;
@@ -34,6 +37,7 @@
 import oracle.kubernetes.weblogic.domain.model.DomainSpec;
 import oracle.kubernetes.weblogic.domain.model.ManagedServer;
 
+
 public class JobHelper {
 
   static final String START_TIME = "WlsRetriever-startTime";
@@ -329,6 +333,11 @@ public NextAction onSuccess(Packet packet, CallResponse<String> callResponse) {
       // Log output to Operator log
       LOGGER.fine("+++++ ReadDomainIntrospectorPodLogResponseStep: \n" + result);
 
+      // Parse out each job log message and log to Operator as SEVERE, FINE, etc...
+      if (result != null) {
+        convertJobLogsToOperatorLogs(result);
+      }
+
       V1Job domainIntrospectorJob = (V1Job) packet.get(ProcessingConstants.DOMAIN_INTROSPECTOR_JOB);
       if (domainIntrospectorJob != null && JobWatcher.isComplete(domainIntrospectorJob)) {
         if (result != null) {
@@ -406,4 +415,68 @@ public NextAction onSuccess(Packet packet, CallResponse<V1PodList> callResponse)
       return doNext(packet);
     }
   }
+
+  // Convert a job log message to an operator log message
+  //   - assumes the messages contins a string like '[SEVERE]', etc, if
+  //     not, then assumes the log level is 'FINE'.
+  private static void logToOperator(StringBuffer logStr, StringBuffer extraStr) {
+    String logMsg = "Introspector Job Log: " 
+                    + logStr 
+                    + (extraStr.length() == 0 ? "" : "\n")
+                    + extraStr;
+    String regExp = ".*\\[(SEVERE|ERROR|WARNING|INFO|FINE|FINER|FINEST)\\].*";
+    String logLevel = logStr.toString().toUpperCase().replaceAll(regExp,"$1");
+    switch (logLevel) {
+      case "ERROR":   LOGGER.severe(logMsg);  
+                      break;
+      case "SEVERE":  LOGGER.severe(logMsg);  
+                      break;
+      case "WARNING": LOGGER.warning(logMsg); 
+                      break;
+      case "INFO":    LOGGER.info(logMsg);    
+                      break;
+      case "FINE":    LOGGER.fine(logMsg);    
+                      break;
+      case "FINER":   LOGGER.finer(logMsg);   
+                      break;
+      case "FINEST":  LOGGER.finest(logMsg);  
+                      break;
+      default:        LOGGER.fine(logMsg);    
+                      break;
+    }
+  }
+
+  // Parse log messages out of a Job Log 
+  //  - assumes each job log message starts with '@['
+  //  - assumes any lines that don't start with '@[' are part 
+  //    of the previous log message
+  //  - ignores all lines in the log up to the first line that starts with '@['
+  private static void convertJobLogsToOperatorLogs(String jobLogs) {
+    try { 
+      StringBuffer logString = new StringBuffer(1000);
+      StringBuffer logExtra = new StringBuffer(1000);
+      try (BufferedReader reader = new BufferedReader(new StringReader(jobLogs))) {
+        for (String line = reader.readLine(); line != null; line = reader.readLine()) {
+          if (line.startsWith("@[")) {
+            if (logString.length() > 0) { 
+              logToOperator(logString, logExtra);
+              logString.setLength(0);
+              logExtra.setLength(0);
+            }
+            logString.append(line);
+          } else if (logString.length() != 0) {
+            if (logExtra.length() > 0) { 
+              logExtra.append('\n');
+            }
+            logExtra.append(line);
+          }
+        }
+        if (logString.length() > 0) { 
+          logToOperator(logString, logExtra);
+        }
+      }
+    } catch (IOException ioe) {
+      LOGGER.fine(MessageKeys.JOB_LOG_PARSE_FAILURE, ioe.toString(), jobLogs);
+    }
+  }
 }

operator/src/main/java/oracle/kubernetes/operator/logging/MessageKeys.java

@@ -154,6 +154,7 @@ public class MessageKeys {
   public static final String EXTERNAL_CHANNEL_SERVICE_EXISTS = "WLSKO-0152";
   public static final String WLS_HEALTH_READ_FAILED_NO_HTTPCLIENT = "WLSKO-0153";
   public static final String JOB_DEADLINE_EXCEEDED_MESSAGE = "WLSKO-0154";
+  public static final String JOB_LOG_PARSE_FAILURE = "WLSKO-0155";
 
   private MessageKeys() {
   }

operator/src/main/resources/Operator.properties

@@ -160,4 +160,4 @@ WLSKO-0154=Job {0} failed due to reason: DeadlineExceeded. \
   The job may be retried by the operator up to {3} \
   times with longer ActiveDeadlineSeconds value in each subsequent retry. \
   Use tuning parameter 'domainPresenceFailureRetryMaxCount' to configure max retries.
-
+WLSKO-0155=Unexpected exception, {0}, while parsing introspect job log [{1}].

operator/src/main/resources/scripts/introspectDomain.py

@@ -210,7 +210,7 @@ def printFile(self, path):
   def getEnv(self, name):
     val = os.getenv(name)
     if val is None or val == "null":
-      trace("ERROR: Env var "+name+" not set.")
+      trace("SEVERE","Env var "+name+" not set.")
       sys.exit(1)
     return val
 
@@ -930,7 +930,7 @@ def __init__(self, env):
         self.macroStr+=', '
       self.macroStr+='${' + key + '}'
 
-    trace("available macros: '" + self.macroStr + "'")
+    trace("Available macros: '" + self.macroStr + "'")
 
     # Populate module maps with known module files and names, log them
 
@@ -1149,19 +1149,21 @@ def main(env):
       env.close()
     exit(exitcode=0)
   except WLSTException, e:
+    trace("SEVERE","Domain introspection failed with WLST exception: " + str(e))
     print e
-    trace("Domain introspection failed with WLST exception:")
     traceback.print_exc()
+    dumpStack()
     exit(exitcode=1)
   except UndeclaredThrowableException, f:
-    dumpStack()
+    trace("SEVERE","Domain introspection failed with undeclared exception: " + str(f))
     print f
-    trace("Domain introspection failed with undeclared exception:")
     traceback.print_exc()
+    dumpStack()
     exit(exitcode=1)
   except:
-    trace("Domain introspection unexpectedly failed:")
+    trace("SEVERE","Domain introspection unexpectedly failed:")
     traceback.print_exc()
+    dumpStack()
     exit(exitcode=1)
 
 main(OfflineWlstEnv())

operator/src/main/resources/scripts/introspectDomain.sh

@@ -41,12 +41,11 @@ SCRIPTPATH="$( cd "$(dirname "$0")" > /dev/null 2>&1 ; pwd -P )"
 # setup tracing
 
 source ${SCRIPTPATH}/utils.sh
-[ $? -ne 0 ] && echo "Error: missing file ${SCRIPTPATH}/utils.sh" && exit 1 
+[ $? -ne 0 ] && echo "[SEVERE] Missing file ${SCRIPTPATH}/utils.sh" && exit 1 
 
 trace "Introspecting the domain"
 
-trace "Current environment:"
-env
+env | tracePipe "Current environment:"
 
 # set defaults
 
@@ -68,11 +67,11 @@ checkEnv DOMAIN_UID \
 for script_file in "${SCRIPTPATH}/wlst.sh" \
                    "${SCRIPTPATH}/startNodeManager.sh"  \
                    "${SCRIPTPATH}/introspectDomain.py"; do
-  [ ! -f "$script_file" ] && trace "Error: missing file '${script_file}'." && exit 1 
+  [ ! -f "$script_file" ] && trace SEVERE "Missing file '${script_file}'." && exit 1 
 done 
 
 for dir_var in DOMAIN_HOME JAVA_HOME WL_HOME MW_HOME ORACLE_HOME; do
-  [ ! -d "${!dir_var}" ] && trace "Error: missing ${dir_var} directory '${!dir_var}'." && exit 1
+  [ ! -d "${!dir_var}" ] && trace SEVERE "Missing ${dir_var} directory '${!dir_var}'." && exit 1
 done
 
 # check DOMAIN_HOME for a config/config.xml, reset DOMAIN_HOME if needed
@@ -94,7 +93,6 @@ ${SCRIPTPATH}/startNodeManager.sh || exit 1
 
 trace "Running introspector WLST script ${SCRIPTPATH}/introspectDomain.py"
 
-
 ${SCRIPTPATH}/wlst.sh ${SCRIPTPATH}/introspectDomain.py || exit 1
 
 trace "Domain introspection complete"

operator/src/main/resources/scripts/livenessProbe.sh

@@ -13,7 +13,7 @@ RETVAL=$(test -f /weblogic-operator/debug/livenessProbeSuccessOverride ; echo $?
 
 SCRIPTPATH="$( cd "$(dirname "$0")" > /dev/null 2>&1 ; pwd -P )"
 source ${SCRIPTPATH}/utils.sh
-[ $? -ne 0 ] && echo "Error: missing file ${SCRIPTPATH}/utils.sh" && exit $RETVAL
+[ $? -ne 0 ] && echo "[SEVERE] Missing file ${SCRIPTPATH}/utils.sh" && exit $RETVAL
 
 # check DOMAIN_HOME for a config/config.xml, reset DOMAIN_HOME if needed:
 exportEffectiveDomainHome || exit $RETVAL
@@ -26,12 +26,12 @@ STATEFILE=${DH}/servers/${SN}/data/nodemanager/${SN}.state
 
 if [ "${MOCK_WLS}" != 'true' ]; then
   if [ `jps -l | grep -c " weblogic.NodeManager"` -eq 0 ]; then
-    trace "Error: WebLogic NodeManager process not found."
+    trace SEVERE "WebLogic NodeManager process not found."
     exit $RETVAL
   fi
 fi
 if [ -f ${STATEFILE} ] && [ `grep -c "FAILED_NOT_RESTARTABLE" ${STATEFILE}` -eq 1 ]; then
-  trace "Error: WebLogic Server state is FAILED_NOT_RESTARTABLE."
+  trace SEVERE "WebLogic Server state is FAILED_NOT_RESTARTABLE."
   exit $RETVAL
 fi
 exit 0

operator/src/main/resources/scripts/monitorLog.sh

@@ -15,6 +15,7 @@ echo $$ > /tmp/monitorLog-pid
 
 SCRIPTPATH="$( cd "$(dirname "$0")" > /dev/null 2>&1 ; pwd -P )"
 source ${SCRIPTPATH}/utils.sh
+[ $? -ne 0 ] && echo "[SEVERE] Missing file ${SCRIPTPATH}/utils.sh" && exit 1
 
 trace "Monitoring server log file $1 every $2 seconds for selected known log messages."
 
@@ -27,7 +28,7 @@ while true; do
          "For details, please search your pod log or"
          "${SERVER_OUT_FILE} for the keyword 'situational'."
         )
-    trace "${msg[*]}"
+    trace SEVERE "${msg[*]}"
     exit 0
   fi
   if grep -q "BEA-000360" $1 ; then

operator/src/main/resources/scripts/readState.sh

@@ -9,7 +9,7 @@
 
 SCRIPTPATH="$( cd "$(dirname "$0")" > /dev/null 2>&1 ; pwd -P )"
 source ${SCRIPTPATH}/utils.sh
-[ $? -ne 0 ] && echo "Error: missing file ${SCRIPTPATH}/utils.sh" && exit 1
+[ $? -ne 0 ] && echo "[SEVERE] Missing file ${SCRIPTPATH}/utils.sh" && exit 1
 
 # check DOMAIN_HOME for a config/config.xml, reset DOMAIN_HOME if needed:
 exportEffectiveDomainHome || exit 1
@@ -26,7 +26,7 @@ if [ `jps -v | grep -c " -Dweblogic.Name=${SERVER_NAME} "` -eq 0 ]; then
 fi
 
 if [ ! -f ${STATEFILE} ]; then
-  trace "Error: WebLogic Server state file not found."
+  trace "WebLogic Server state file not found."
   exit 2
 fi
 

operator/src/main/resources/scripts/startNodeManager.sh

@@ -48,7 +48,7 @@
 SCRIPTPATH="$( cd "$(dirname "$0")" > /dev/null 2>&1 ; pwd -P )"
 
 source ${SCRIPTPATH}/utils.sh 
-[ $? -ne 0 ] && echo "Error: missing file ${SCRIPTPATH}/utils.sh" && exit 1 
+[ $? -ne 0 ] && echo "[SEVERE] Missing file ${SCRIPTPATH}/utils.sh" && exit 1 
 
 export WL_HOME="${WL_HOME:-/u01/oracle/wlserver}"
 
@@ -67,11 +67,11 @@ else
   checkEnv SERVER_NAME ADMIN_NAME AS_SERVICE_NAME SERVICE_NAME USER_MEM_ARGS || exit 1
 fi
 
-[ ! -d "${JAVA_HOME}" ]                     && trace "Error: JAVA_HOME directory not found '${JAVA_HOME}'."           && exit 1 
-[ ! -d "${DOMAIN_HOME}" ]                   && trace "Error: DOMAIN_HOME directory not found '${DOMAIN_HOME}'."       && exit 1 
-[ ! -f "${DOMAIN_HOME}/config/config.xml" ] && trace "Error: '${DOMAIN_HOME}/config/config.xml' not found."           && exit 1 
-[ ! -d "${WL_HOME}" ]                       && trace "Error: WL_HOME '${WL_HOME}' not found."                         && exit 1 
-[ ! -f "${stm_script}" ]                    && trace "Error: Missing script '${stm_script}' in WL_HOME '${WL_HOME}'." && exit 1 
+[ ! -d "${JAVA_HOME}" ]                     && trace SEVERE "JAVA_HOME directory not found '${JAVA_HOME}'."           && exit 1 
+[ ! -d "${DOMAIN_HOME}" ]                   && trace SEVERE "DOMAIN_HOME directory not found '${DOMAIN_HOME}'."       && exit 1 
+[ ! -f "${DOMAIN_HOME}/config/config.xml" ] && trace SEVERE "'${DOMAIN_HOME}/config/config.xml' not found."           && exit 1 
+[ ! -d "${WL_HOME}" ]                       && trace SEVERE "WL_HOME '${WL_HOME}' not found."                         && exit 1 
+[ ! -f "${stm_script}" ]                    && trace SEVERE "Missing script '${stm_script}' in WL_HOME '${WL_HOME}'." && exit 1 
 
 #
 # Helper fn to create a folder
@@ -80,7 +80,7 @@ fi
 function createFolder {
   mkdir -m 750 -p "$1"
   if [ ! -d "$1" ]; then
-    trace "Unable to create folder '$1'."
+    trace SEVERE "Unable to create folder '$1'."
     exit 1
   fi
 }
@@ -118,12 +118,12 @@ createFolder ${NODEMGR_HOME}
 NODEMGR_LOG_HOME=${NODEMGR_LOG_HOME:-${LOG_HOME:-${NODEMGR_HOME}/${DOMAIN_UID}}}
 FAIL_BOOT_ON_SITUATIONAL_CONFIG_ERROR=${FAIL_BOOT_ON_SITUATIONAL_CONFIG_ERROR:-true}
 
-trace "Info: NODEMGR_HOME='${NODEMGR_HOME}'"
-trace "Info: LOG_HOME='${LOG_HOME}'"
-trace "Info: SERVER_NAME='${SERVER_NAME}'"
-trace "Info: DOMAIN_UID='${DOMAIN_UID}'"
-trace "Info: NODEMGR_LOG_HOME='${NODEMGR_LOG_HOME}'"
-trace "Info: FAIL_BOOT_ON_SITUATIONAL_CONFIG_ERROR='${FAIL_BOOT_ON_SITUATIONAL_CONFIG_ERROR}'"
+trace "NODEMGR_HOME='${NODEMGR_HOME}'"
+trace "LOG_HOME='${LOG_HOME}'"
+trace "SERVER_NAME='${SERVER_NAME}'"
+trace "DOMAIN_UID='${DOMAIN_UID}'"
+trace "NODEMGR_LOG_HOME='${NODEMGR_LOG_HOME}'"
+trace "FAIL_BOOT_ON_SITUATIONAL_CONFIG_ERROR='${FAIL_BOOT_ON_SITUATIONAL_CONFIG_ERROR}'"
 
 createFolder ${NODEMGR_LOG_HOME}
 
@@ -153,7 +153,7 @@ rm -f ${nodemgr_lck_file}
 # is the domain name:
 domain_name=`cat ${DOMAIN_HOME}/config/config.xml | sed 's/[[:space:]]//g' | grep '^<name>' | head -1 | awk -F'<|>' '{print $3}'`
 if [ "$domain_name" = "" ]; then
-  trace "Could not determine domain name"
+  trace SEVERE "Could not determine domain name"
   exit 1
 fi
 
@@ -170,7 +170,7 @@ cat <<EOF > ${nm_domains_file}
   ${domain_name}=${DOMAIN_HOME}
 EOF
 
-  [ ! $? -eq 0 ] && trace "Failed to create '${nm_domains_file}'." && exit 1
+  [ ! $? -eq 0 ] && trace SEVERE "Failed to create '${nm_domains_file}'." && exit 1
 
 cat <<EOF > ${nm_props_file}
   #Node manager properties
@@ -202,7 +202,7 @@ cat <<EOF > ${nm_props_file}
 
 EOF
 
-  [ ! $? -eq 0 ] && trace "Failed to create '${nm_props_file}'." && exit 1
+  [ ! $? -eq 0 ] && trace SEVERE "Failed to create '${nm_props_file}'." && exit 1
 
 ###############################################################################
 #
@@ -225,7 +225,8 @@ if [ ! "${SERVER_NAME}" = "introspector" ]; then
 
   if [ -f "$wl_state_file" ]; then
     trace "Removing stale file '$wl_state_file'."
-    rm -f ${wl_state_file} || exit 1
+    rm -f ${wl_state_file} 
+    [ ! $? -eq 0 ] && trace SEVERE "Could not remove stale file '$wl_state_file'." && exit 1
   fi
 
 
@@ -248,7 +249,7 @@ Arguments=${USER_MEM_ARGS} -XX\\:+UnlockExperimentalVMOptions -XX\\:+UseCGroupMe
 
 EOF
 
-  [ ! $? -eq 0 ] && trace "Failed to create '${wl_props_file}'." && exit 1
+  [ ! $? -eq 0 ] && trace SEVERE "Failed to create '${wl_props_file}'." && exit 1
 
   if [ ! "${ADMIN_NAME}" = "${SERVER_NAME}" ]; then
     admin_protocol="http"
@@ -295,8 +296,10 @@ export JAVA_OPTIONS="${JAVA_OPTIONS} -Dweblogic.RootDirectory=${DOMAIN_HOME}"
 
 trace "Start the nodemanager, node manager home is '${NODEMGR_HOME}', log file is '${nodemgr_log_file}', out file is '${nodemgr_out_file}'."
 
-rm -f ${nodemgr_log_file} || exit 1
-rm -f ${nodemgr_out_file} || exit 1
+rm -f ${nodemgr_log_file}
+[ ! $? -eq 0 ] && trace SEVERE "Could not remove old file '$nodemgr_log_file'." && exit 1
+rm -f ${nodemgr_out_file}
+[ ! $? -eq 0 ] && trace SEVERE "Could not remove old file '$nodemgr_out_file'." && exit 1
 
 ${stm_script} > ${nodemgr_out_file} 2>&1 &
 
@@ -309,11 +312,11 @@ while [ 1 -eq 1 ]; do
     break
   fi
   if [ $((SECONDS - $start_secs)) -ge $max_wait_secs ]; then
-    trace "Info: Contents of node manager log '$nodemgr_log_file':"
+    trace INFO "Contents of node manager log '$nodemgr_log_file':"
     cat ${nodemgr_log_file}
-    trace "Info: Contents of node manager out '$nodemgr_out_file':"
+    trace INFO "Contents of node manager out '$nodemgr_out_file':"
     cat ${NODEMGR_OUT_FILE}
-    trace "Error: node manager failed to start within $max_wait_secs seconds."
+    trace SEVERE "Node manager failed to start within $max_wait_secs seconds."
     exit 1
   fi
   wait_count=$((wait_count + 1))