cli/operation/LogDivertAppender.java

0001 /**
0002  * Licensed to the Apache Software Foundation (ASF) under one
0003  * or more contributor license agreements.  See the NOTICE file
0004  * distributed with this work for additional information
0005  * regarding copyright ownership.  The ASF licenses this file
0006  * to you under the Apache License, Version 2.0 (the
0007  * "License"); you may not use this file except in compliance
0008  * with the License.  You may obtain a copy of the License at
0009  *
0010  *     http://www.apache.org/licenses/LICENSE-2.0
0011  *
0012  * Unless required by applicable law or agreed to in writing, software
0013  * distributed under the License is distributed on an "AS IS" BASIS,
0014  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
0015  * See the License for the specific language governing permissions and
0016  * limitations under the License.
0017  */
0018
0019 package org.apache.hive.service.cli.operation;
0020 import java.io.CharArrayWriter;
0021 import java.util.Enumeration;
0022 import java.util.regex.Pattern;
0023
0024 import org.apache.hadoop.hive.ql.exec.Task;
0025 import org.apache.hadoop.hive.ql.log.PerfLogger;
0026 import org.apache.hadoop.hive.ql.session.OperationLog;
0027 import org.apache.hadoop.hive.ql.session.OperationLog.LoggingLevel;
0028 import org.apache.hive.service.cli.CLIServiceUtils;
0029 import org.apache.log4j.Appender;
0030 import org.apache.log4j.ConsoleAppender;
0031 import org.apache.log4j.Layout;
0032 import org.apache.log4j.Logger;
0033 import org.apache.log4j.WriterAppender;
0034 import org.apache.log4j.spi.Filter;
0035 import org.apache.log4j.spi.LoggingEvent;
0036
0037 import com.google.common.base.Joiner;
0038
0039 /**
0040  * An Appender to divert logs from individual threads to the LogObject they belong to.
0041  */
0042 public class LogDivertAppender extends WriterAppender {
0043   private static final Logger LOG = Logger.getLogger(LogDivertAppender.class.getName());
0044   private final OperationManager operationManager;
0045   private boolean isVerbose;
0046   private Layout verboseLayout;
0047
0048   /**
0049    * A log filter that filters messages coming from the logger with the given names.
0050    * It be used as a white list filter or a black list filter.
0051    * We apply black list filter on the Loggers used by the log diversion stuff, so that
0052    * they don't generate more logs for themselves when they process logs.
0053    * White list filter is used for less verbose log collection
0054    */
0055   private static class NameFilter extends Filter {
0056     private Pattern namePattern;
0057     private LoggingLevel loggingMode;
0058     private OperationManager operationManager;
0059
0060     /* Patterns that are excluded in verbose logging level.
0061      * Filter out messages coming from log processing classes, or we'll run an infinite loop.
0062      */
0063     private static final Pattern verboseExcludeNamePattern = Pattern.compile(Joiner.on("|")
0064       .join(new String[] {LOG.getName(), OperationLog.class.getName(),
0065       OperationManager.class.getName()}));
0066
0067     /* Patterns that are included in execution logging level.
0068      * In execution mode, show only select logger messages.
0069      */
0070     private static final Pattern executionIncludeNamePattern = Pattern.compile(Joiner.on("|")
0071       .join(new String[] {"org.apache.hadoop.mapreduce.JobSubmitter",
0072       "org.apache.hadoop.mapreduce.Job", "SessionState", Task.class.getName(),
0073       "org.apache.hadoop.hive.ql.exec.spark.status.SparkJobMonitor"}));
0074
0075     /* Patterns that are included in performance logging level.
0076      * In performance mode, show execution and performance logger messages.
0077      */
0078     private static final Pattern performanceIncludeNamePattern = Pattern.compile(
0079       executionIncludeNamePattern.pattern() + "|" + PerfLogger.class.getName());
0080
0081     private void setCurrentNamePattern(OperationLog.LoggingLevel mode) {
0082       if (mode == OperationLog.LoggingLevel.VERBOSE) {
0083         this.namePattern = verboseExcludeNamePattern;
0084       } else if (mode == OperationLog.LoggingLevel.EXECUTION) {
0085         this.namePattern = executionIncludeNamePattern;
0086       } else if (mode == OperationLog.LoggingLevel.PERFORMANCE) {
0087         this.namePattern = performanceIncludeNamePattern;
0088       }
0089     }
0090
0091     NameFilter(
0092       OperationLog.LoggingLevel loggingMode, OperationManager op) {
0093       this.operationManager = op;
0094       this.loggingMode = loggingMode;
0095       setCurrentNamePattern(loggingMode);
0096     }
0097
0098     @Override
0099     public int decide(LoggingEvent ev) {
0100       OperationLog log = operationManager.getOperationLogByThread();
0101       boolean excludeMatches = (loggingMode == OperationLog.LoggingLevel.VERBOSE);
0102
0103       if (log == null) {
0104         return Filter.DENY;
0105       }
0106
0107       OperationLog.LoggingLevel currentLoggingMode = log.getOpLoggingLevel();
0108       // If logging is disabled, deny everything.
0109       if (currentLoggingMode == OperationLog.LoggingLevel.NONE) {
0110         return Filter.DENY;
0111       }
0112       // Look at the current session's setting
0113       // and set the pattern and excludeMatches accordingly.
0114       if (currentLoggingMode != loggingMode) {
0115         loggingMode = currentLoggingMode;
0116         setCurrentNamePattern(loggingMode);
0117       }
0118
0119       boolean isMatch = namePattern.matcher(ev.getLoggerName()).matches();
0120
0121       if (excludeMatches == isMatch) {
0122         // Deny if this is black-list filter (excludeMatches = true) and it
0123         // matched
0124         // or if this is whitelist filter and it didn't match
0125         return Filter.DENY;
0126       }
0127       return Filter.NEUTRAL;
0128     }
0129   }
0130
0131   /** This is where the log message will go to */
0132   private final CharArrayWriter writer = new CharArrayWriter();
0133
0134   private void setLayout(boolean isVerbose, Layout lo) {
0135     if (isVerbose) {
0136       if (lo == null) {
0137         lo = CLIServiceUtils.verboseLayout;
0138         LOG.info("Cannot find a Layout from a ConsoleAppender. Using default Layout pattern.");
0139       }
0140     } else {
0141       lo = CLIServiceUtils.nonVerboseLayout;
0142     }
0143     setLayout(lo);
0144   }
0145
0146   private void initLayout(boolean isVerbose) {
0147     // There should be a ConsoleAppender. Copy its Layout.
0148     Logger root = Logger.getRootLogger();
0149     Layout layout = null;
0150
0151     Enumeration<?> appenders = root.getAllAppenders();
0152     while (appenders.hasMoreElements()) {
0153       Appender ap = (Appender) appenders.nextElement();
0154       if (ap.getClass().equals(ConsoleAppender.class)) {
0155         layout = ap.getLayout();
0156         break;
0157       }
0158     }
0159     setLayout(isVerbose, layout);
0160   }
0161
0162   public LogDivertAppender(OperationManager operationManager,
0163     OperationLog.LoggingLevel loggingMode) {
0164     isVerbose = (loggingMode == OperationLog.LoggingLevel.VERBOSE);
0165     initLayout(isVerbose);
0166     setWriter(writer);
0167     setName("LogDivertAppender");
0168     this.operationManager = operationManager;
0169     this.verboseLayout = isVerbose ? layout : CLIServiceUtils.verboseLayout;
0170     addFilter(new NameFilter(loggingMode, operationManager));
0171   }
0172
0173   @Override
0174   public void doAppend(LoggingEvent event) {
0175     OperationLog log = operationManager.getOperationLogByThread();
0176
0177     // Set current layout depending on the verbose/non-verbose mode.
0178     if (log != null) {
0179       boolean isCurrModeVerbose = (log.getOpLoggingLevel() == OperationLog.LoggingLevel.VERBOSE);
0180
0181       // If there is a logging level change from verbose->non-verbose or vice-versa since
0182       // the last subAppend call, change the layout to preserve consistency.
0183       if (isCurrModeVerbose != isVerbose) {
0184         isVerbose = isCurrModeVerbose;
0185         setLayout(isVerbose, verboseLayout);
0186       }
0187     }
0188     super.doAppend(event);
0189   }
0190
0191   /**
0192    * Overrides WriterAppender.subAppend(), which does the real logging. No need
0193    * to worry about concurrency since log4j calls this synchronously.
0194    */
0195   @Override
0196   protected void subAppend(LoggingEvent event) {
0197     super.subAppend(event);
0198     // That should've gone into our writer. Notify the LogContext.
0199     String logOutput = writer.toString();
0200     writer.reset();
0201
0202     OperationLog log = operationManager.getOperationLogByThread();
0203     if (log == null) {
0204       LOG.debug(" ---+++=== Dropped log event from thread " + event.getThreadName());
0205       return;
0206     }
0207     log.writeOperationLog(logOutput);
0208   }
0209 }