lucene/gradle/validation/validate-log-calls.gradle

/*
 * Licensed to the Apache Software Foundation (ASF) under one or more
 * contributor license agreements.  See the NOTICE file distributed with
 * this work for additional information regarding copyright ownership.
 * The ASF licenses this file to You under the Apache License, Version 2.0
 * (the "License"); you may not use this file except in compliance with
 * the License.  You may obtain a copy of the License at
 *
 *     http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

import org.apache.tools.ant.BuildException

// Checks logging calls to keep from using patterns that might be expensive
// either in CPU or unnecessary object creation. Some of the checks are a little
// over-zealous, but it's worth a bit of aggravation to catch the egregious
// mistakes before they accrue.

// This all started with Java Flight Recorder showing a massive number of
// objects allocated and garbage collected. Tracing a bunch of them down showed
// that we have a number of calls like:
// log.debug("some string" + very_expensive_object_to_make_a_string).
// which _always_ constructed the very expensive ojbect even if the log level
// was INFO or more severe. Rather than leave lots of confusing formats laying
// about or expecting people to remember the rules, we opted to make this
// check part of Gradle precommit. It will be included by default in Solr
// 9.0.

// See the associated help task "gradlew helpValidateLogCalls"

configure(subprojects.findAll { it.path.startsWith(':solr') }) {
  plugins.withType(JavaPlugin) {
    task validateLogCalls(type: ValidateLogCallsTask) { task ->
      description "Checks that log calls are either validated or conform to efficient patterns."
      group "verification"

      // This task has no proper outputs.
      setupDummyOutputs(task)

      sourceFiles = files(sourceSets*.java)
    }
 
    // Add log validation to per-project checks as well.
    check.dependsOn validateLogCalls
 }
}

class ValidateLogCallsTask extends DefaultTask {
  def logLevels = ["log.trace", "log.debug", "log.info", "log.warn", "log.error", "log.fatal"]

  def errsFound = 0;
  def violations = new ArrayList();

  def reportViolation(String msg) {
    violations.add(System.lineSeparator + msg);
    errsFound++;
  }

  // We have a log.something line, check for patterns we're not fond of.
  def checkLine(File file, String line, int lineNumber, String previous) {
    boolean violation = false

    // If the line has been explicitly OK'd, then it's OK!
    if (line.replaceAll("\\s", "").toLowerCase().contains("//logok")) {
      return
    }
    // Strip all of the comments, things in quotes and the like.
    def stripped =
        line.replaceFirst("//.*", " ") // remove comment to EOL. May be fragile due to the possibility of embedded double slashes
            .replaceFirst(/.*?\(/, " ") // Get rid of "log.whatever("
            .replaceFirst(/\);/, " ") // get rid of the closing ");"
            .replaceFirst("/\\*.*?\\*/", " ") // replace embedded comments "/*....*/"
            .replaceAll(/".*?"/, '""') // remove anything between quotes. This is a bit fragile if there are embedded double quotes.
            .replaceAll(/timeLeft\(.*?\)/, " ") // used all over tests, it's benign
            .replaceAll(/TimeUnit\..*?\.convert\(.*?\)/, " ") // again, a pattern that's efficient
            .replaceAll("\\s", "")

    // The compiler will pre-assemble patterns like 'log.info("string const1 {}" + " string const2 {}", obj1, obj2)'
    // to log.info("string const1 {} string const2 {}", obj1, obj2)', so don't worry about any plus preceded and
    // followed by double quotes, otherwise flag it.
    def hasPlus = false
    for (int idx = 0; idx < stripped.length(); ++idx) {
      if (stripped.charAt(idx) == '+') {
        if (idx == 0 || idx == stripped.length() - 1
            || stripped.charAt(idx - 1) != '"' || stripped.charAt(idx + 1) != '"') {
          hasPlus = true
          break
        }
      }
    }
    //TODO remove me
    String cause =  ""
    // Get the level of this log message.
    // We don't really care about checking for method calls for WARN and more severe, the presumption
    // is that they _should_ always be reported.

    def level = ""
    def lev = (line =~ "log\\.(.*?)\\(")
    if (lev.find()) {
      level = lev.group(1).toLowerCase().trim()
    }
    if (logLevels.contains("log." + level) == false) {
      reportViolation(String.format("Found an unexpected log level: %s, file: %s:%d"
          , level, file.getAbsolutePath(), lineNumber))
    }
    boolean persnicketyLevel = !(level.equals("fatal") || level.equals("error") || level.equals("warn"))

    // Check that previous line isn't an if statement for always-reported log levels.
    // There's a convention to declare a member variable for whether a level is enabled and check that rather than
    // isDebugEnabled so we need to check both.
    String prevLine = previous.replaceAll("\\s+", "").toLowerCase()
    boolean prevLineNotIf = ((prevLine.contains("if(log.is" + level + "enabled") == false
        && prevLine.contains("if(" + level + ")") == false))

    if (hasPlus) {
      cause = "hasPlus: " + hasPlus
      violation = true
    }
    if (violation == false) {
      def m = stripped =~ "\\(.*?\\)"
      def hasParens = m.find()

      if (hasParens && prevLineNotIf && persnicketyLevel) {
        cause = "hasParens " + hasParens + " prevLineNotIf " + prevLineNotIf + " pernicketyLevel " + persnicketyLevel
        violation = true
      }
    }

    // Always report toString(). Note, this over-reports some constructs
    // but just add //logOK if it's really OK.
    if (violation == false) {
      if (line.contains("toString(") == true && prevLineNotIf) {
        cause = "Line contains toString"
        violation = true
      }
    }
    if (stripped.contains("getMessage()") || stripped.contains("getCause()")) {
      cause = "getMessage or getCause in log line";
      violation = true;
    }
    if (violation) {
      reportViolation(String.format("cause: '%s' Suspicious logging call, Parameterize and possibly surround with 'if (log.is*Enabled) {..}'. Help at: 'gradlew helpValidateLogCalls' %s    %s:%d"
          , cause , System.lineSeparator, file.getAbsolutePath(), lineNumber))
    }
    return
  }

// Require all our logger definitions lower case "log", except a couple of special ones.
  def checkLogName(File file, String line) {
    // It's many times faster to do check this way than use a regex
    if (line.contains("static ") && line.contains("getLogger") && line.contains(" log ") == false) {
      String name = file.name
      if (name.equals("LoggerFactory.java")) {
        return
      }
      if (name.equals("SolrCore.java") && (line.contains("requestLog") || line.contains("slowLog"))) {
        return
      }
      if (name.equals("StartupLoggingUtils.java") && line.contains("getLoggerImplStr")) {
        return
      }
      // Apparently the Hadoop code expectes upper-case LOG, so...

      if ((name.equals("HttpServer2.java") || name.equals("BlockPoolSlice.java") || name.equals("FileUtil.java"))
        && line.contains(" LOG ")) {
        return
      }

      reportViolation("Change the logger name to lower-case 'log' in " + file.name + " " + line + " project" + project)
    }
  }

  def checkFile(File file) {
    int state = 0
    int lineNumber = 0
    StringBuilder sb = new StringBuilder();

    // We have to assemble line-by-line to get the full log statement. We require that all loggers (except requestLog
    // and slowLog) be exactly "log". That will be checked as well.
    String prevLine = ""
    file.eachLine { String line ->
      lineNumber++
      checkLogName(file, line)
      switch (state) {
        case 0: // Not collecting a logging line.
          logLevels.each {
            if (line.contains(it)) {
              if (line.contains(");")) {
                state = 2
              } else {
                state = 1
              }
              sb.setLength(0)
              sb.append(line)
            }
          }
          break

        case 1: // collecting a log line
          if (line.replaceFirst("//.*", " ")
              .replaceFirst("/\\*.*?\\*/", " ") // replace embedded comments "/*....*/"
              .replaceAll(/".*?"/, '""') // remove anything between quotes. This is a bit fragile if there are embedded double quotes.
              .trim().endsWith(");")) {
            state = 2
          }
          sb.append(line)
          break

        default:
          reportViolation("Bad state, should be 0-1 in the switch statement") // make people aware the code sucks
          break
      }

      // It's just easier to do this here rather than read another line in the switch above.
      if (state == 0) {
          // Not collecting a log line
          prevLine = line.toLowerCase();
      } else if (state == 1) {
          // collecting a logging line.
      } else if (state == 2) {
          // We've collected the complete log line.
          checkLine(file, sb.toString(), lineNumber, prevLine)
          state = 0
      } else {
          assert false
      }
    }
  }

  @InputFiles
  FileCollection sourceFiles

  @TaskAction
  def checkLogLines() {
    sourceFiles.each { checkFile(it) }
    logger.info("Checked: ${sourceFiles.files.size()}")

    if (errsFound > 0) {
      throw new BuildException(String.format(Locale.ENGLISH, 'Found %d violations in source files (%s).',
          errsFound, violations.join(', ')));
    }
  }
}