Памятка по логированию в Scala и вообще мире Java

12 августа 2015

Ни одно серьезное приложение не обходится без логирования, будь то сайтик, GUI или даже что-нибудь под Android. В мире Java ситуация с логированием на первый взгляд несколько запутанная. Есть какие-то SLF4J, какой-то Logback, зачем-то нужно создавать XML-файлы, вот это все. Но, как это часто бывает, если сесть, и не спеша во всем разобраться, на самом деле все оказывается очень просто и логично.

Итак, есть штука под названием SLF4J. Это что-то вроде интерфейса, который должны поддерживать все библиотеки для логирования. То есть, интерфейс один, а реализаций много. Есть java.util.logging (JUL), Common Logging (JCL), log4j, Logback. Наибольшей популярностью, похоже, пользуется Logback. Так вот, авторы библиотек пишут все логи через SLF4J и ничего не знают о том, какая конкретная реализация используется в том или ином приложении. Авторы программ выбирают конкретную реализацию. SLF4J как-то там сам ее находит, в результате чего весь проект использует эту одну реализацию. Правда, круто?

В случае со Scala есть заслуживающая внимания библиотека scala-logging, являющаяся оберткой над SLF4J. Используя макросы Scala, она добавляет проверку перед записью строки в лог, будет ли при текущих настройках эта строка на самом деле куда-то записана.

То есть, вы пишете:

log.debug(s"Test $msg")

… а после развертывания макроса это превращается в:

if(log.isDebugEnabled) log.debug(s"Test $msg")

В результате, если отладочные логи отключены, не будет выделяться и освобождаться память под строку, не будет выполняться интерполяция, и так далее. Таким образом получаем существенно большую производительность.

Давайте попробуем прикрутить логирование к нашему REST-сервису на базе Finagle. В build.sbt дописываем зависимости:

"ch.qos.logback" % "logback-classic" % "1.1.3",
"com.typesafe.scala-logging" %% "scala-logging" % "3.1.0"

В конструкторе класса FinagleServiceExample создаем логер:

import com.typesafe.scalalogging._
import org.slf4j.LoggerFactory

// ...

private val logger = Logger(LoggerFactory.getLogger(this.getClass))

После чего берем и просто пишем логи:

logger.info(s"service started")
logger.debug(s"reading $key")
logger.error(s"bad request: $req")

Существуют следующие уровни логирования, от меньшего к большему: TRACE, DEBUG, INFO, WARN, ERROR. В настройках, речь о которых пойдет ниже, выбирается эффективный уровень. При выборе определенного эффективного уровня в лог попадают все сообщения этого уровня и выше. Например, если выбран эффективный уровень INFO, в логах вы увидите все INFO, WARN и ERROR сообщения. Кроме того, есть особый эффективный уровень OFF, который отключает все логирование.

Logback ищет файл с настройками по следующим правилам:

Если в classpath есть logback.groovy, используется он;
Иначе в classpath ищется файл logback-test.xml;
Если нет и его, пробуем найти logback.xml;
Если и он не найден, используем настройки по умолчанию, то есть, пишем просто в консоль;

Давайте положим в src/test/resources файл logback-test.xml следующего содержания:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>
        %d{HH:mm:ss.SSS} %-5level [%thread] %logger{128} - %msg%n
      </pattern>
    </encoder>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Как несложно догадаться, здесь мы говорим Logback писать все сообщения уровня DEBUG и выше в STDOUT, используя заданный формат. Если теперь запустить тесты, в выводе вы действительно увидите все DEBUG, INFO и ERROR логи. Можете заменить уровень в строке <root level="DEBUG"> на INFO или ERROR и убедиться, что логов становится меньше.

В каталоге src/main/resources создадим logback.xml немного иного содержания:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>
        %date %-5level [%thread] %logger{128} - %msg%n
      </pattern>
    </encoder>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>finagle-example.log</file>
    <encoder>
      <pattern>
        %date %-5level [%thread] %logger{128} - %msg%n
      </pattern>
    </encoder>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE" />
  </root>
</configuration>

Эти настройки тоже в особых пояснениях не нуждаются. Мы говорим писать как в консоль, так и в файл, используя немного другой формат логов. Можно собрать standalone jar, используя команду:

sbt assembly

… затем запустить его, сказав:

java -jar ./target/scala-2.11/finagle-example-assembly-0.1.jar

… и проверить, что Logback успешно подхватывает настройки.

Можно переопределить настройки без пересборки jar, сказав:

java -Dlogback.configurationFile=path/to/logback.xml \
  -jar ./target/scala-2.11/finagle-example-assembly-0.1.jar

Можно заставить Logback автоматически перечитывать документацию, изменив первую строчку в logback.xml примерно так:

<configuration scan="true" scanPeriod="10 seconds" >

Можно фильтровать логи по классам и пакетам, при этом относительно иерархий работает интуитивная семантика:

<logger name="me.eax.some.package" level="INFO" />

В appender-секциях можно указывать минимальный уровень сообщений:

<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
  <level>INFO</level>
</filter>

Логи конкретных пакетов и классов можно направлять в заданные аппендеры:

<logger name="me.eax.some.package" level="INFO">
  <appender-ref ref="FILE" />
</logger>

Можно настроить ротацию и архивацию логов:

<appender name="FILE"
  class="ch.qos.logback.core.rolling.RollingFileAppender">
  
  <file>/path/to/application.log</file>
  <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
    <pattern>%date %-5level [%thread] %logger{128} - %msg%n</pattern>
  </encoder>

  <rollingPolicy
    class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
    
    <FileNamePattern>/path/to/application.%i.log.zip</FileNamePattern>
    <MinIndex>1</MinIndex>
    <MaxIndex>10</MaxIndex>
  </rollingPolicy>

  <triggeringPolicy
    class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
    
    <MaxFileSize>2MB</MaxFileSize>
  </triggeringPolicy>
</appender>

Альтернативный вариант:

<appender name="FILE"
  class="ch.qos.logback.core.rolling.RollingFileAppender">

  <file>/path/to/application.log</file>
  <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
    <pattern>%date %-5level [%thread] %logger{128} - %msg%n</pattern>
  </encoder>

  <rollingPolicy
    class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>
      /path/to/application-%d{yyyy-MM-dd}.log.gz
    </fileNamePattern>
    <maxHistory>10</maxHistory>
  </rollingPolicy>
</appender>

Как видите, все очень гибко, очень мощно и не сказать, чтобы супер сложно.

Ссылки по теме:

А чем вы пишете логи?