Issues with Log4j2Plugins.dat when shading with maven-shade-plugin

[marcusbb]

Description
Configuring a simple java application to log into a local Elastic node

Configuration
pom.xml

 <dependencies>
        <dependency>
            <groupId>org.apache.kafka</groupId>
            <artifactId>kafka-clients</artifactId>
            <version>1.1.0</version>
        </dependency>
        <dependency>
            <groupId>commons-cli</groupId>
            <artifactId>commons-cli</artifactId>
            <version>1.4</version>
        </dependency>
        <dependency>
            <groupId>io.dropwizard.metrics</groupId>
            <artifactId>metrics-core</artifactId>
            <version>4.1.5</version>
        </dependency>
        <dependency>
            <groupId>com.google.code.gson</groupId>
            <artifactId>gson</artifactId>
            <version>2.8.6</version>
        </dependency>
        <dependency>
            <groupId>com.google.guava</groupId>
            <artifactId>guava</artifactId>
            <version>22.0</version>
        </dependency>
        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.13</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-slf4j-impl</artifactId>
            <version>2.13.2</version>
        </dependency>
        <dependency>
            <groupId>org.appenders.log4j</groupId>
            <artifactId>log4j2-elasticsearch-hc</artifactId>
            <version>1.4.2</version>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-databind</artifactId>
            <version>2.11.0</version>

        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-core</artifactId>
            <version>2.11.0</version>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-annotations</artifactId>
            <version>2.11.0</version>
        </dependency>
        <dependency>
            <groupId>io.netty</groupId>
            <artifactId>netty-buffer</artifactId>
            <version>4.1.32.Final</version>
        </dependency>
        <dependency>
            <groupId>net.openhft</groupId>
            <artifactId>chronicle-map</artifactId>
            <version>3.19.4</version>
        </dependency>
        <dependency>
            <groupId>com.lmax</groupId>
            <artifactId>disruptor</artifactId>
            <version>3.4.2</version>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.module</groupId>
            <artifactId>jackson-module-afterburner</artifactId>
            <version>2.11.0</version>
        </dependency>
        </dependencies>

log4j2.xml - Basically copy and paste from your examples

<?xml version="1.0" encoding="UTF-8"?>
<Configuration >
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>
        <!-- This configuration is much more verbose than the minimal one (few lines). It's here just to demonstrate the optional features -->
        <Elasticsearch name="elasticsearch">
            <RollingIndexName indexName="logs-audit-" pattern="yyyy-MM-dd"  />
            <ThresholdFilter level="DEBUG" onMatch="ACCEPT"/>
            <JacksonJsonLayout>
                <VirtualProperty name="hostname" value="$${sys:hostname:-undefined}" />
                <PooledItemSourceFactory poolName="itemPool" itemSizeInBytes="1024" initialPoolSize="6000"
                                         monitored="true" monitorTaskInterval="10000" resizeTimeout="500">
                    <UnlimitedResizePolicy resizeFactor="0.6" />
                </PooledItemSourceFactory>
            </JacksonJsonLayout>

            <AsyncBatchDelivery batchSize="10" deliveryInterval="200">
                <!-- Use 'classpath:BOOT-INF/classes/<template file name>' if template file is in the Spring Boot app resources (yes, it's ugly) -->
                <!-- Use 'classpath:<template file name>' if template file is provided by one of your dependencies -->
                <IndexTemplate name="logs-audit-" path="classpath:indexTemplate.json" />
                <HCHttp serverUris="http://localhost:9200"
                        connTimeout="500"
                        readTimeout="30000"
                        maxTotalConnections="1">
                    <Security>
                        <BasicCredentials username="elastic" password="changeit" />
                    </Security>
                    <PooledItemSourceFactory poolName="batchPool" itemSizeInBytes="2048000" initialPoolSize="3"
                                             monitored="true" monitorTaskInterval="10000" resizeTimeout="500">
                        <UnlimitedResizePolicy resizeFactor="0.70" />
                    </PooledItemSourceFactory>
                    <BatchLimitBackoffPolicy maxBatchesInFlight="4" />
                </HCHttp>
                <!--<ChronicleMapRetryFailoverPolicy fileName="failedItems.chronicleMap"
                                                 numberOfEntries="100000"
                                                 averageValueSize="2048"
                                                 batchSize="1000"
                                                 retryDelay="4000"
                                                 monitored="true"
                                                 monitorTaskInterval="30000">
                    <SingleKeySequenceSelector sequenceId="2"/>
                </ChronicleMapRetryFailoverPolicy>-->
            </AsyncBatchDelivery>
        </Elasticsearch>
    </Appenders>
    <Loggers>
        <AsyncLogger name="elasticsearch">
            <AppenderRef ref="elasticsearch" />
        </AsyncLogger>
        <Root level="debug">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Runtime (please complete the following information):

• log4j2-elasticsearch-jest:1.4.2
• plain jar
• openJDK11
• Ubuntu

Additional context
log4j messages printed out fine but no index or other information in debug messages.

[rfoltyns]

Looks like it didn't start properly. Let's find out why.

I've noticed that you've changed

<Configuration status="INFO">

to

<Configuration >

You may find some useful logs there.

If that doesn't help, try to run this HC example with your XML config with status logging and

<Root level="info">

(cause debug is way too noisy there)

<IndexTemplate name="logs-audit-" path="classpath:BOOT-INF/classes/indexTemplate.json" />

(cause template file will not be resolved otherwise)

and dependencies you specified.

With no other modifications to HC example, cURL should return this:

$ curl http://localhost:9200/_cat/indices/logs-audit*?v
health status index                  uuid                   pri rep docs.count docs.deleted store.size pri.store.size
yellow open   logs-audit--2020-05-21 sukzSdpUQ6S9hyJaij4VVA   1   1          1            0      6.1kb          6.1kb

[marcusbb]

I've changed the Configuration back to status=INFO.

2020-05-21 10:35:49,154 main ERROR Error processing element Elasticsearch ([Appenders: null]): CLASS_NOT_FOUND
2020-05-21 10:35:49,247 main ERROR Unable to locate appender "elasticsearch" for logger config "elasticsearch"

This is when I build the application, and run it with java -jar. I did notice some maven shading errors thrown out when packaging it, which may be part of the problem

[WARNING] Discovered module-info.class. Shading will break its strong encapsulation.
[WARNING] Discovered module-info.class. Shading will break its strong encapsulation.
[WARNING] Discovered module-info.class. Shading will break its strong encapsulation.
[WARNING] Discovered module-info.class. Shading will break its strong encapsulation.
[WARNING] jcl-over-slf4j-1.6.6.jar, pax-url-aether-2.4.5.jar define 3 overlapping resources: 
[WARNING]   - META-INF/maven/org.slf4j/jcl-over-slf4j/pom.properties
[WARNING]   - META-INF/maven/org.slf4j/jcl-over-slf4j/pom.xml
[WARNING]   - META-INF/services/org.apache.commons.logging.LogFactory
[WARNING] xmlpull-1.1.3.1.jar, xpp3_min-1.1.4c.jar define 2 overlapping classes: 
[WARNING]   - org.xmlpull.v1.XmlPullParser
[WARNING]   - org.xmlpull.v1.XmlPullParserException
[WARNING] netty-buffer-4.1.32.Final.jar, netty-common-4.1.32.Final.jar define 1 overlapping resources: 
[WARNING]   - META-INF/io.netty.versions.properties
[WARNING] affinity-3.2.2.jar, animal-sniffer-annotations-1.14.jar, annotations-12.0.jar, annotations-17.0.0.jar, audit-load.jar, chronicle-algorithms-2.19.0.jar, chronicle-bytes-2.19.1.jar, chronicle-core-2.19.0.jar, chronicle-map-3.19.4.jar, chronicle-threads-2.19.1.jar, chronicle-values-2.19.0.jar, chronicle-wire-2.19.0.jar, commons-cli-1.4.jar, commons-codec-1.10.jar, commons-logging-1.2.jar, compiler-2.3.5.jar, disruptor-3.4.2.jar, error_prone_annotations-2.0.18.jar, gson-2.8.6.jar, guava-22.0.jar, httpasyncclient-4.1.4.jar, httpclient-4.5.6.jar, httpcore-4.4.10.jar, httpcore-nio-4.4.10.jar, j2objc-annotations-1.1.jar, jackson-annotations-2.11.0.jar, jackson-core-2.11.0.jar, jackson-databind-2.11.0.jar, javapoet-1.5.1.jar, jcl-over-slf4j-1.6.6.jar, jettison-1.3.8.jar, jna-4.2.1.jar, jna-platform-4.2.1.jar, jsr305-1.3.9.jar, kafka-clients-1.1.0.jar, log4j-api-2.13.2.jar, log4j-core-2.13.2.jar, log4j-slf4j-impl-2.13.2.jar, log4j2-elasticsearch-core-1.4.2.jar, log4j2-elasticsearch-hc-1.4.2.jar, lz4-java-1.4.jar, metrics-core-4.1.5.jar, netty-buffer-4.1.32.Final.jar, netty-common-4.1.32.Final.jar, org.jacoco.agent-0.8.3-runtime.jar, pax-url-aether-2.4.5.jar, slf4j-api-1.7.25.jar, snappy-java-1.1.7.1.jar, stax-api-1.0.1.jar, xmlpull-1.1.3.1.jar, xpp3_min-1.1.4c.jar, xstream-1.4.9.jar define 1 overlapping resources: 
[WARNING]   - META-INF/MANIFEST.MF
[WARNING] httpasyncclient-4.1.4.jar, httpclient-4.5.6.jar, httpcore-4.4.10.jar, httpcore-nio-4.4.10.jar, jackson-core-2.11.0.jar, jackson-databind-2.11.0.jar, log4j-api-2.13.2.jar, log4j-core-2.13.2.jar, log4j-slf4j-impl-2.13.2.jar, pax-url-aether-2.4.5.jar define 1 overlapping resources: 
[WARNING]   - META-INF/NOTICE
[WARNING] log4j-core-2.13.2.jar, log4j2-elasticsearch-core-1.4.2.jar, log4j2-elasticsearch-hc-1.4.2.jar define 1 overlapping resources: 
[WARNING]   - META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat
[WARNING] kafka-clients-1.1.0.jar, log4j2-elasticsearch-core-1.4.2.jar, log4j2-elasticsearch-hc-1.4.2.jar define 1 overlapping resources: 
[WARNING]   - LICENSE
[WARNING] annotations-12.0.jar, annotations-17.0.0.jar define 30 overlapping classes: 
[WARNING]   - org.intellij.lang.annotations.Identifier
[WARNING]   - org.intellij.lang.annotations.JdkConstants
[WARNING]   - org.intellij.lang.annotations.JdkConstants$AdjustableOrientation
[WARNING]   - org.intellij.lang.annotations.JdkConstants$BoxLayoutAxis
[WARNING]   - org.intellij.lang.annotations.JdkConstants$CalendarMonth
[WARNING]   - org.intellij.lang.annotations.JdkConstants$CursorType
[WARNING]   - org.intellij.lang.annotations.JdkConstants$FlowLayoutAlignment
[WARNING]   - org.intellij.lang.annotations.JdkConstants$FontStyle
[WARNING]   - org.intellij.lang.annotations.JdkConstants$HorizontalAlignment
[WARNING]   - org.intellij.lang.annotations.JdkConstants$InputEventMask
[WARNING]   - 20 more...
[WARNING] commons-logging-1.2.jar, jcl-over-slf4j-1.6.6.jar define 6 overlapping classes: 
[WARNING]   - org.apache.commons.logging.Log
[WARNING]   - org.apache.commons.logging.LogConfigurationException
[WARNING]   - org.apache.commons.logging.LogFactory
[WARNING]   - org.apache.commons.logging.impl.NoOpLog
[WARNING]   - org.apache.commons.logging.impl.SimpleLog
[WARNING]   - org.apache.commons.logging.impl.SimpleLog$1
[WARNING] httpasyncclient-4.1.4.jar, httpclient-4.5.6.jar, httpcore-4.4.10.jar, httpcore-nio-4.4.10.jar, jackson-annotations-2.11.0.jar, jackson-core-2.11.0.jar, jackson-databind-2.11.0.jar, jettison-1.3.8.jar, log4j-api-2.13.2.jar, log4j-core-2.13.2.jar, log4j-slf4j-impl-2.13.2.jar, pax-url-aether-2.4.5.jar define 1 overlapping resources: 
[WARNING]   - META-INF/LICENSE
[WARNING] httpclient-4.5.6.jar, pax-url-aether-2.4.5.jar define 2 overlapping resources: 
[WARNING]   - META-INF/maven/org.apache.httpcomponents/httpclient/pom.properties
[WARNING]   - META-INF/maven/org.apache.httpcomponents/httpclient/pom.xml
[WARNING] commons-codec-1.10.jar, pax-url-aether-2.4.5.jar define 2 overlapping resources: 
[WARNING]   - META-INF/maven/commons-codec/commons-codec/pom.properties
[WARNING]   - META-INF/maven/commons-codec/commons-codec/pom.xml
[WARNING] httpcore-4.4.10.jar, pax-url-aether-2.4.5.jar define 2 overlapping resources: 
[WARNING]   - META-INF/maven/org.apache.httpcomponents/httpcore/pom.properties
[WARNING]   - META-INF/maven/org.apache.httpcomponents/httpcore/pom.xml
[WARNING] commons-cli-1.4.jar, commons-codec-1.10.jar, commons-logging-1.2.jar, pax-url-aether-2.4.5.jar define 2 overlapping resources: 
[WARNING]   - META-INF/LICENSE.txt
[WARNING]   - META-INF/NOTICE.txt
[WARNING] org.jacoco.agent-0.8.3-runtime.jar, pax-url-aether-2.4.5.jar define 1 overlapping resources: 
[WARNING]   - about.html
[WARNING] httpasyncclient-4.1.4.jar, httpclient-4.5.6.jar, httpcore-4.4.10.jar, httpcore-nio-4.4.10.jar, log4j-api-2.13.2.jar, log4j-core-2.13.2.jar, log4j-slf4j-impl-2.13.2.jar, pax-url-aether-2.4.5.jar define 1 overlapping resources: 
[WARNING]   - META-INF/DEPENDENCIES
[WARNING] maven-shade-plugin has detected that some class files are
[WARNING] present in two or more JARs. When this happens, only one
[WARNING] single version of the class is copied to the uber jar.
[WARNING] Usually this is not harmful and you can skip these warnings,
[WARNING] otherwise try to manually exclude artifacts based on
[WARNING] mvn dependency:tree -Ddetail=true and the above output.

I'm not running a spring boot application, it's just a plain java application, so I thought that classpath:indexTemplate.json was required.

I tried building the example but it failed to build:

[ERROR] Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.8.1:compile (default-compile) on project log4j2-elasticsearch-hc-springboot: Compilation failure: Compilation failure: 
[ERROR] error reading /mnt/repository/org/apache/logging/log4j/log4j-core/2.12.1/log4j-core-2.12.1.jar; ZipFile invalid LOC header (bad signature)
[ERROR] /home/marcus/idea-workspace/log4j2-elasticsearch-examples/log4j2-elasticsearch-hc-springboot/src/main/java/com/github/rfoltyns/Application.java:[1,1] cannot access com.github.rfoltyns
[ERROR]   invalid block type

The end goal for me is to insert this configuration into a Spark job (which will have different set of dependencies).

[rfoltyns]

2020-05-21 10:35:49,154 main ERROR Error processing element Elasticsearch ([Appenders: null]): CLASS_NOT_FOUND

actually means "I couldn't find the Elasticsearch plugin after collecting all META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat files". Since you're shading, exploded jars will just override each other's .dat files. And yes, you got a warning regarding this file:

[WARNING] log4j-core-2.13.2.jar, log4j2-elasticsearch-core-1.4.2.jar, log4j2-elasticsearch-hc-1.4.2.jar define 1 overlapping resources: 
[WARNING]   - META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat

I've found an article on this issue, but I haven't testsed this solution and I'm not sure whether this would be acceptable for you (TLDR: java -cp <jars_with_dat_files>): http://www.codepreference.com/2017/02/how-to-fix-log4j2-problem-with-maven-shade-plugin.html.

SpringBoot doesn't have this problem because all jars are kept separately, so each file is loaded as separate resource. Given that, onejar-maven-plugin looks very promising.

Fortunately, there's a way to avoid Log4j2 Plugins and XML config completely and use HCHttp as an ES client directly:

asyncBatchDelivery.add(indexName, itemSourceFactory.create(logEvent, objectWriter));

Have a look at programmatic config. JacksonJsonLayout and Log4j2 bits can be easily carved out. However, you'll have to take care of the Lifecycle on your own:

asyncBatchDelivery.start();

before you put anything in there.

classpath:indexTemplate.json may be a way to go, but you have to provide it on your own - it's not included in any of the jars (apart from test jars), cause everyone has his own needs when it comes to mapping, index setting, etc.

As for your compile issues, I'm not sure how to help you.. At first glance it looks like corrupted download? Try to clean your repository and build again.

[marcusbb]

I've managed to build your examples thanks, it was a corrupt log4j dependency.
And it's working as advertised creating a template and index.

And I've re-jigged my dependencies in my app to match SpringBoot example, and it appears that your appender (no classpath issues) is getting configured and run, but still no output to Elastic.

Output below

2020-05-21 16:23:51,432 com.pcc.Logging.main() INFO Reusing expired key sequence: 00000000-0000-0002-0000-000000000000
2020-05-21 16:23:51,665 com.pcc.Logging.main() INFO Current key sequence: 00000000-0000-0002-0000-000000000000
2020-05-21 16:23:51,729 com.pcc.Logging.main() INFO BatchEmitterFactory class found org.appenders.log4j2.elasticsearch.hc.BulkEmitterFactory
2020-05-21 16:23:51,730 com.pcc.Logging.main() INFO Using org.appenders.log4j2.elasticsearch.hc.BulkEmitterFactory@6f084771 as BatchEmitterFactoryProvider
2020-05-21 16:23:51,852 com.pcc.Logging.main() INFO Pool [batchPool] 3 pooled elements added. Total pooled elements: 3. Took: 33ms
2020-05-21 16:23:51,894 Retry-metrics INFO sequenceId: 2, total: 2, enqueued: 0
2020-05-21 16:23:51,948 com.pcc.Logging.main() INFO Pool [itemPool] 6000 pooled elements added. Total pooled elements: 6000. Took: 83ms
hello world
logging 0
logging 1
logging 2
logging 3
logging 4
logging 5
logging 6
logging 7
2020-05-21 16:23:52,857 batchPool-1 INFO { poolName: batchPool, initialPoolSize: 3, totalPoolSize: 3, availablePoolSize: 3, additionalMetrics: UnpooledByteBufAllocator$UnpooledByteBufAllocatorMetric(usedHeapMemory: 6144000; usedDirectMemory: 0)}
logging 8
logging 9
logging 10
2020-05-21 16:23:53,162 itemPool-2 INFO { poolName: itemPool, initialPoolSize: 6000, totalPoolSize: 6000, availablePoolSize: 6000, additionalMetrics: UnpooledByteBufAllocator$UnpooledByteBufAllocatorMetric(usedHeapMemory: 6144000; usedDirectMemory: 0)}
logging 11
...
logging 98
logging 99
2020-05-21 16:24:02,860 batchPool-2 INFO { poolName: batchPool, initialPoolSize: 3, totalPoolSize: 3, availablePoolSize: 3, additionalMetrics: UnpooledByteBufAllocator$UnpooledByteBufAllocatorMetric(usedHeapMemory: 6144000; usedDirectMemory: 0)}
2020-05-21 16:24:02,953 itemPool-2 INFO { poolName: itemPool, initialPoolSize: 6000, totalPoolSize: 6000, availablePoolSize: 6000, additionalMetrics: UnpooledByteBufAllocator$UnpooledByteBufAllocatorMetric(usedHeapMemory: 6144000; usedDirectMemory: 0)}
^C2020-05-21 16:24:04,488 pool-1-thread-1 INFO Waiting for last items... 5s, 0 items enqueued
2020-05-21 16:24:04,493 DelayedShutdown WARN 4995 ms before proceeding
2020-05-21 16:24:05,493 pool-1-thread-1 INFO Waiting for last items... 4s, 0 items enqueued
2020-05-21 16:24:05,504 DelayedShutdown WARN 3995 ms before proceeding
2020-05-21 16:24:06,495 pool-1-thread-1 INFO Waiting for last items... 3s, 0 items enqueued
2020-05-21 16:24:06,505 DelayedShutdown WARN 2995 ms before proceeding
2020-05-21 16:24:07,496 pool-1-thread-1 INFO Waiting for last items... 2s, 0 items enqueued
2020-05-21 16:24:07,508 DelayedShutdown WARN 1995 ms before proceeding
2020-05-21 16:24:08,500 pool-1-thread-1 INFO Waiting for last items... 1s, 0 items enqueued
2020-05-21 16:24:08,511 DelayedShutdown WARN 995 ms before proceeding
[WARNING] 
net.openhft.chronicle.hash.ChronicleHashClosedException: Access to ChronicleMap{name=org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicy$Builder, file=/home/marcus/idea-workspace/es-log4j/failedItems.chronicleMap, identityHashCode=370435364} after close()
    at net.openhft.chronicle.map.VanillaChronicleMap.i (VanillaChronicleMap.java:362)
    at net.openhft.chronicle.map.VanillaChronicleMap.iterationContext (VanillaChronicleMap.java:394)
    at net.openhft.chronicle.map.VanillaChronicleMap.longSize (VanillaChronicleMap.java:200)
    at net.openhft.chronicle.hash.impl.VanillaChronicleHash.size (VanillaChronicleHash.java:726)
    at org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicy.lambda$delayedShutdown$3 (ChronicleMapRetryFailoverPolicy.java:184)
    at org.appenders.log4j2.elasticsearch.DelayedShutdown.run (DelayedShutdown.java:156)

[rfoltyns]

Output looks good (apart from the ChronicleMap error at the end.. should be fixed soon). However, it should also include a line communicating the allocation of response buffer

INFO Pool [hc-responseBufferPool] 1 pooled elements added. Total pooled elements: 1. Took: <x>ms

If it's not there, it means that the response was not received - was there a request at all? What does the cURL say?

$ curl http://localhost:9200/_cat/indices/logs-audit*?v

There is a chance that logs are not getting to ElasticsearchAppender. Do to you get the logger by name?

LogManager.getLogger("elasticsearch");

or by class?

LogManager.getLogger(com.pcc.Logging.class);

If former, debugging ElasticsearchAppender.append() or HCResultCallback.completed() is the only way to figure out what happened. I'll add some more DEBUG logging in future releases to identify these issues earlier, but for now, I ran out of options.

[rfoltyns]

@marcusbb Did you manage to identify the issue?

[rfoltyns]

@marcusbb Are still having this issue? Is there anything I can help you with?

[marcusbb]

@rfoltyns - thanks I got distracted and am on a new strategy for collecting and publishing logs. I may end up returning to this or one of my peers.