search

rfoltyns / log4j2-elasticsearch

Log4j2 Elasticsearch Appender plugins
Apache License 2.0
174 stars 46 forks source link

Could not initialize ChronicleMapRetryFailoverPolicy #89

Open divxer opened 1 year ago

divxer commented 1 year ago

Description

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access using Lookup on net.openhft.chronicle.core.Jvm (jar:file:/app/service.jar!/BOOT-INF/lib/chronicle-core-2.24ea11.jar!/) to class java.lang.reflect.AccessibleObject
WARNING: Please consider reporting this to the maintainers of net.openhft.chronicle.core.Jvm
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2023-07-05 04:05:13,316 main ERROR Could not create plugin of type class org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicyPlugin for element ChronicleMapRetryFailoverPolicy: java.lang.IllegalStateException: Could not initialize ChronicleMapRetryFailoverPolicy java.lang.IllegalStateException: Could not initialize ChronicleMapRetryFailoverPolicy
    at org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicy$Builder.lazyInit(ChronicleMapRetryFailoverPolicy.java:280)
    at org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicyPlugin$Builder.build(ChronicleMapRetryFailoverPolicyPlugin.java:94)
    at org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicyPlugin$Builder.build(ChronicleMapRetryFailoverPolicyPlugin.java:55)
    at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:124)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1122)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1047)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1039)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1039)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1039)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:651)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:249)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:295)
    at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:621)
    at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:285)
    at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.loadConfiguration(Log4J2LoggingSystem.java:227)
    at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.loadConfiguration(Log4J2LoggingSystem.java:193)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithSpecificConfig(AbstractLoggingSystem.java:66)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:57)
    at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.initialize(Log4J2LoggingSystem.java:169)
    at org.apache.logging.log4j.spring.boot.Log4j2CloudConfigLoggingSystem.initialize(Log4j2CloudConfigLoggingSystem.java:81)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
    at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
    at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
    at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
    at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:343)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:301)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1292)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65)
Caused by: java.io.IOException: Not enough space to fallocate 13 MiB to / unallocated was 0 MiB
    at net.openhft.chronicle.hash.impl.VanillaChronicleHash.fallocate(VanillaChronicleHash.java:1114)
    at net.openhft.chronicle.hash.impl.VanillaChronicleHash.map(VanillaChronicleHash.java:1094)
    at net.openhft.chronicle.hash.impl.VanillaChronicleHash.createMappedStoreAndSegments(VanillaChronicleHash.java:515)
    at net.openhft.chronicle.map.ChronicleMapBuilder.createWithNewFile(ChronicleMapBuilder.java:1849)
    at net.openhft.chronicle.map.ChronicleMapBuilder.createWithFile(ChronicleMapBuilder.java:1747)
    at net.openhft.chronicle.map.ChronicleMapBuilder.createPersistedTo(ChronicleMapBuilder.java:1588)
    at net.openhft.chronicle.map.ChronicleMapBuilder.createOrRecoverPersistedTo(ChronicleMapBuilder.java:1609)
    at org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicy$Builder.createChronicleMap(ChronicleMapRetryFailoverPolicy.java:313)
    at org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicy$Builder.lazyInit(ChronicleMapRetryFailoverPolicy.java:276)
    ... 46 more

2023-07-05 04:05:13,319 main ERROR Unable to invoke factory method in class org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicyPlugin for element ChronicleMapRetryFailoverPolicy: java.lang.IllegalStateException: No factory method found for class org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicyPlugin java.lang.IllegalStateException: No factory method found for class org.appenders.log4j2.elasticsearch.failover.ChronicleMapRetryFailoverPolicyPlugin
    at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.findFactoryMethod(PluginBuilder.java:238)
    at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1122)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1047)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1039)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1039)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1039)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:651)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:249)
    at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:295)
    at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:621)
    at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:285)
    at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.loadConfiguration(Log4J2LoggingSystem.java:227)
    at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.loadConfiguration(Log4J2LoggingSystem.java:193)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithSpecificConfig(AbstractLoggingSystem.java:66)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:57)
    at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.initialize(Log4J2LoggingSystem.java:169)
    at org.apache.logging.log4j.spring.boot.Log4j2CloudConfigLoggingSystem.initialize(Log4j2CloudConfigLoggingSystem.java:81)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
    at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
    at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
    at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
    at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:343)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:301)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1292)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65)

Configuration

        <Elasticsearch name="auditLogger" messageOnly="true">
            <!-- zone is optional. OS timezone is used by default. separator is optional, - (hyphen, dash) is used by default. -->
            <RollingIndexName indexName="indexName" pattern="yyyy.MM" />
            <JacksonJsonLayout>
                <PooledItemSourceFactory poolName="itemPool"
                                         itemSizeInBytes="10240"
                                         initialPoolSize="2">
                </PooledItemSourceFactory>
            </JacksonJsonLayout>
            <AsyncBatchDelivery batchSize="50"
                                deliveryInterval="200" >
                <HCHttp serverUris="elasticsearch.url"
                        connTimeout="500"
                        readTimeout="30000"
                        maxTotalConnections="8">
                    <PooledItemSourceFactory poolName="batchPool"
                                             itemSizeInBytes="10240"
                                             initialPoolSize="2">
                    </PooledItemSourceFactory>
                    <BatchLimitBackoffPolicy maxBatchesInFlight="4" />
                    <Security>
                        <BasicCredentials username=".user" password="elasticsearchPassword" />
                    </Security>
                </HCHttp>
                <ChronicleMapRetryFailoverPolicy fileName="/auditlog-failover/failedItems-log4j2-elasticsearch-hc.chronicleMap"
                                                 numberOfEntries="10000"
                                                 averageValueSize="1024"
                                                 batchSize="5000"
                                                 retryDelay="3000"
                                                 monitored="true"
                                                 monitorTaskInterval="30000">
                    <SingleKeySequenceSelector sequenceId="1"/>
                </ChronicleMapRetryFailoverPolicy>
            </AsyncBatchDelivery>
        </Elasticsearch>

Runtime (please complete the following information):

Additional context File location of ChronicleMapRetryFailoverPolicy is a volume mounted to the container.

rfoltyns commented 1 year ago

Caused by: java.io.IOException: Not enough space to fallocate 13 MiB to / unallocated was 0 MiB looks sus.

Apart from that, this policy has more issues with SpringBoot logging subsystem re-initializing logging twice.

I've been working on a fix for that for a while now. I'll keep you updated

divxer commented 1 year ago

The root cause may lie in https://github.com/OpenHFT/Chronicle-Map/blob/ea/src/main/java/net/openhft/chronicle/hash/impl/VanillaChronicleHash.java

Line 1102-1105. Within a Docker environment, the code below does not properly enter the loop.

    private void fallocate(long mappingOffsetInFile, long length) throws IOException {
        FileSystem fileSystem = file.toPath().getFileSystem();

        long maxSize = 0;
        for (FileStore fileStore : fileSystem.getFileStores()) {
            long unallocatedSpace = fileStore.getUnallocatedSpace();
            if (unallocatedSpace > length * 11 / 10) {
                PosixFallocate.fallocate(raf.getFD(), mappingOffsetInFile, length);
                return;
            }
            maxSize = Math.max(maxSize, unallocatedSpace);
        }
        throw new IOException("Not enough space to fallocate " + (length >> 20) + " MiB to " + fileSystem.getRootDirectories().iterator().next() + " unallocated was " + (maxSize >> 20) + " MiB");
    }