Системный журнал EVTD#

У компонента есть собственный локальный журнал событий. Файлы хранения логов системного журнала:

  • $kafka_logs_dir/server.log — содержит ошибки подключения пользователей, события смены лидера, изменение количества синхронизированных реплик;

  • $kafka_logs_dir/kafka-authorizer.log — содержит ошибки авторизации пользователей. Для включения логирования необходимо прописать в config/log4j.properties строчку log4j.logger.kafka.authorizer.logger=INFO;

  • $kafka_logs_dir/controller.log — содержит события смены лидера партиции и события с брокерами в кластере.

В рамках установки EVTD устанавливаются рекомендуемые уровни логирования, при необходимости они могут быть переопределены пользователем с ролью «Администратор».

Пример конфигурации logger (logback):

<?xml version="1.0" encoding="UTF-8"?>
<!-- Enable configuration updates check every 30 seconds -->
<configuration scan="true" scanPeriod="30 seconds">

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

    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>

    <!-- level="info" - process latency data, don't write it to log (write it to other reporters, if present) -->
    <!-- level="off" - don't process latency data -->
    <logger name="ru.ss.kafka.clients.timestamp.reporter.LoggerReporter" level="info"/>

</configuration>

Часто встречающиеся события в файлах логов#

Часто встречающиеся события в файлах логов типа ERROR#

  1. Неверный пароль от хранилища (ssl.keystore.password или ssl.truststore.password):

   [2022-02-11 12:57:22,842] ERROR [KafkaServer id=1] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
org.apache.kafka.common.KafkaException: Failed to load SSL keystore *** of type JKS
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory$FileBasedStore.load(DefaultSslEngineFactory.java:377)
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory$FileBasedStore.<init>(DefaultSslEngineFactory.java:349)
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory.createKeystore(DefaultSslEngineFactory.java:299)
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory.configure(DefaultSslEngineFactory.java:161)
        at org.apache.kafka.common.security.ssl.SslFactory.instantiateSslEngineFactory(SslFactory.java:138)
        at org.apache.kafka.common.security.ssl.SslFactory.configure(SslFactory.java:95)
        at org.apache.kafka.common.network.SslChannelBuilder.configure(SslChannelBuilder.java:71)
        at org.apache.kafka.common.network.ChannelBuilders.create(ChannelBuilders.java:157)
        at org.apache.kafka.common.network.ChannelBuilders.serverChannelBuilder(ChannelBuilders.java:97)
        at kafka.network.Processor.<init>(SocketServer.scala:790)
        at kafka.network.SocketServer.newProcessor(SocketServer.scala:415)
        at kafka.network.SocketServer.$anonfun$addDataPlaneProcessors$1(SocketServer.scala:288)
        at kafka.network.SocketServer.addDataPlaneProcessors(SocketServer.scala:287)
        at kafka.network.SocketServer.$anonfun$createDataPlaneAcceptorsAndProcessors$1(SocketServer.scala:254)
        at kafka.network.SocketServer.$anonfun$createDataPlaneAcceptorsAndProcessors$1$adapted(SocketServer.scala:251)
        at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:553)
        at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:551)
        at scala.collection.AbstractIterable.foreach(Iterable.scala:920)
        at kafka.network.SocketServer.createDataPlaneAcceptorsAndProcessors(SocketServer.scala:251)
        at kafka.network.SocketServer.startup(SocketServer.scala:125)
        at kafka.server.KafkaServer.startup(KafkaServer.scala:303)
        at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
        at kafka.Kafka$.main(Kafka.scala:82)
        at kafka.Kafka.main(Kafka.scala)
Caused by: java.io.IOException: Keystore was tampered with, or password was incorrect
        at java.base/sun.security.provider.JavaKeyStore.engineLoad(JavaKeyStore.java:795)
        at java.base/sun.security.util.KeyStoreDelegator.engineLoad(KeyStoreDelegator.java:222)
        at java.base/java.security.KeyStore.load(KeyStore.java:1479)
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory$FileBasedStore.load(DefaultSslEngineFactory.java:374)
        ... 23 more
Caused by: java.security.UnrecoverableKeyException: Password verification failed
        at java.base/sun.security.provider.JavaKeyStore.engineLoad(JavaKeyStore.java:793)
        ... 26 more

  1. Неверный пароль от ключа в хранилище (значение ssl.key.password):

   [2022-02-11 12:58:45,350] ERROR [KafkaServer id=1] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
org.apache.kafka.common.KafkaException: java.security.UnrecoverableKeyException: Cannot recover key
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory.createSSLContext(DefaultSslEngineFactory.java:268)
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory.configure(DefaultSslEngineFactory.java:173)
        at org.apache.kafka.common.security.ssl.SslFactory.instantiateSslEngineFactory(SslFactory.java:138)
        at org.apache.kafka.common.security.ssl.SslFactory.configure(SslFactory.java:95)
        at org.apache.kafka.common.network.SslChannelBuilder.configure(SslChannelBuilder.java:71)
        at org.apache.kafka.common.network.ChannelBuilders.create(ChannelBuilders.java:157)
        at org.apache.kafka.common.network.ChannelBuilders.serverChannelBuilder(ChannelBuilders.java:97)
        at kafka.network.Processor.<init>(SocketServer.scala:790)
        at kafka.network.SocketServer.newProcessor(SocketServer.scala:415)
        at kafka.network.SocketServer.$anonfun$addDataPlaneProcessors$1(SocketServer.scala:288)
        at kafka.network.SocketServer.addDataPlaneProcessors(SocketServer.scala:287)
        at kafka.network.SocketServer.$anonfun$createDataPlaneAcceptorsAndProcessors$1(SocketServer.scala:254)
        at kafka.network.SocketServer.$anonfun$createDataPlaneAcceptorsAndProcessors$1$adapted(SocketServer.scala:251)
        at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:553)
        at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:551)
        at scala.collection.AbstractIterable.foreach(Iterable.scala:920)
        at kafka.network.SocketServer.createDataPlaneAcceptorsAndProcessors(SocketServer.scala:251)
        at kafka.network.SocketServer.startup(SocketServer.scala:125)
        at kafka.server.KafkaServer.startup(KafkaServer.scala:303)
        at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
        at kafka.Kafka$.main(Kafka.scala:82)
        at kafka.Kafka.main(Kafka.scala)
Caused by: java.security.UnrecoverableKeyException: Cannot recover key
        at java.base/sun.security.provider.KeyProtector.recover(KeyProtector.java:304)
        at java.base/sun.security.provider.JavaKeyStore.engineGetKey(JavaKeyStore.java:144)
        at java.base/sun.security.util.KeyStoreDelegator.engineGetKey(KeyStoreDelegator.java:90)
        at java.base/java.security.KeyStore.getKey(KeyStore.java:1057)
        at java.base/sun.security.ssl.SunX509KeyManagerImpl.<init>(SunX509KeyManagerImpl.java:145)
        at java.base/sun.security.ssl.KeyManagerFactoryImpl$SunX509.engineInit(KeyManagerFactoryImpl.java:70)
        at java.base/javax.net.ssl.KeyManagerFactory.init(KeyManagerFactory.java:271)
        at org.apache.kafka.common.security.ssl.DefaultSslEngineFactory.createSSLContext(DefaultSslEngineFactory.java:251)
        ... 21 more

  1. Ключом из conf/encrypt.pass невозможно расшифровать любое зашифрованное значение вида *${decode:C5eoLl0iVSaYIzTMYFs+DQ==}*:

 [2022-02-11 12:54:44,756] ERROR Exiting Kafka due to fatal exception (kafka.Kafka$)
org.jasypt.exceptions.EncryptionOperationNotPossibleException
        at org.jasypt.encryption.pbe.StandardPBEByteEncryptor.decrypt(StandardPBEByteEncryptor.java:1055)
        at org.jasypt.encryption.pbe.StandardPBEStringEncryptor.decrypt(StandardPBEStringEncryptor.java:725)
        at org.jasypt.util.text.BasicTextEncryptor.decrypt(BasicTextEncryptor.java:112)
        at ru.ss.password.decoder.EsPasswordDecoder.decode(EsPasswordDecoder.java:57)
        at ru.ss.kafka.DecryptionConfigProvider.$anonfun$get$1(DecryptionConfigProvider.scala:51)
        at scala.collection.StrictOptimizedIterableOps.map(StrictOptimizedIterableOps.scala:99)
        at scala.collection.StrictOptimizedIterableOps.map$(StrictOptimizedIterableOps.scala:86)
        at scala.collection.convert.JavaCollectionWrappers$JSetWrapper.map(JavaCollectionWrappers.scala:180)
        at ru.ss.kafka.DecryptionConfigProvider.get(DecryptionConfigProvider.scala:51)
        at org.apache.kafka.common.config.ConfigTransformer.transform(ConfigTransformer.java:103)
        at org.apache.kafka.common.config.AbstractConfig.resolveConfigVariables(AbstractConfig.java:495)
        at org.apache.kafka.common.config.AbstractConfig.<init>(AbstractConfig.java:107)
        at org.apache.kafka.common.config.AbstractConfig.<init>(AbstractConfig.java:142)
        at kafka.server.KafkaConfig.<init>(KafkaConfig.scala:1309)
        at kafka.server.KafkaConfig.<init>(KafkaConfig.scala:1312)
        at kafka.server.KafkaServerStartable$.fromProps(KafkaServerStartable.scala:34)
        at kafka.Kafka$.main(Kafka.scala:68)
        at kafka.Kafka.main(Kafka.scala)

  1. Невозможно подключиться к Zookeeper:

[2022-02-11 13:01:33,343] ERROR Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
kafka.zookeeper.ZooKeeperClientTimeoutException: Timed out waiting for connection while in state: CONNECTING
        at kafka.zookeeper.ZooKeeperClient.waitUntilConnected(ZooKeeperClient.scala:262)
        at kafka.zookeeper.ZooKeeperClient.<init>(ZooKeeperClient.scala:119)
        at kafka.zk.KafkaZkClient$.apply(KafkaZkClient.scala:1881)
        at kafka.server.KafkaServer.createZkClient$1(KafkaServer.scala:441)
        at kafka.server.KafkaServer.initZkClient(KafkaServer.scala:466)
        at kafka.server.KafkaServer.startup(KafkaServer.scala:233)
        at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
        at kafka.Kafka$.main(Kafka.scala:82)
        at kafka.Kafka.main(Kafka.scala)

  1. Не совпадают значения broker.id в файле конфигурации и в данных брокеров в файле meta.properties:

 [2022-02-11 13:03:15,339] ERROR Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
kafka.common.InconsistentBrokerIdException: Configured broker.id 4 doesn't match stored broker.id 1 in meta.properties. If you moved your data, make sure your configured broker.id matches. If you intend to create a new broker, you should remove all data in your data directories (log.dirs).
        at kafka.server.KafkaServer.getOrGenerateBrokerId(KafkaServer.scala:842)
        at kafka.server.KafkaServer.startup(KafkaServer.scala:255)
        at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
        at kafka.Kafka$.main(Kafka.scala:82)
        at kafka.Kafka.main(Kafka.scala)

  1. Не удается создать директории для данных:

[2022-02-11 13:04:29,163] ERROR Failed to create or validate data directory /KAFKADATA1 (kafka.server.LogDirFailureChannel)
java.io.IOException: Failed to create data directory /KAFKADATA1
        at kafka.log.LogManager.$anonfun$createAndValidateLogDirs$1(LogManager.scala:156)
        at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:553)
        at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:551)
        at scala.collection.AbstractIterable.foreach(Iterable.scala:920)
        at kafka.log.LogManager.createAndValidateLogDirs(LogManager.scala:147)
        at kafka.log.LogManager.<init>(LogManager.scala:81)
        at kafka.log.LogManager$.apply(LogManager.scala:1212)
        at kafka.server.KafkaServer.startup(KafkaServer.scala:290)
        at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
        at kafka.Kafka$.main(Kafka.scala:82)
        at kafka.Kafka.main(Kafka.scala)
[2022-02-11 13:04:29,168] ERROR Shutdown broker because none of the specified log dirs from /KAFKADATA1 can be created or validated (kafka.log.LogManager)

Часто встречающиеся события в файлах логов типа INFO#

Попытка подключения к Zookeeper:

[2022-02-11 13:01:14,247] INFO future isn't success, cause: (org.apache.zookeeper.ClientCnxnSocketNetty)
io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: hostname/ip:2181
Caused by: java.net.ConnectException: Connection refused
at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777)
at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:330)
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:707)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:829)