[
https://issues.apache.org/jira/browse/LOG4J2-1162?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14962329#comment-14962329
]
Remko Popma edited comment on LOG4J2-1162 at 10/18/15 1:30 PM:
---------------------------------------------------------------
I think this was caused by LOG4J2-1166: since 2.5 the monitorInterval causes an
executor service to be started. This was a non-daemon thread by mistake so the
shutdown hook was not called.
Can you try again?
I tested a standalone test app with the configuration you specified and now I
get this output:
note the line {{MMapAppender closing. Setting logs/memmap.log length to 2004
(offset 0 + position 2004)}}
{noformat}
...
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Stopping
LoggerContext[name=1554547125,
org.apache.logging.log4j.core.LoggerContext@75c072cb]...
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean ...
(snip MBean stuff) ...
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE Stopping
XmlConfiguration[location=C:\Users\remko\workspace\log4j-issues\bin\log4j2-1162-memmap.xml]...
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration notified 4
ReliabilityStrategies that config will be stopped.
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration stopped 0
AsyncLoggerConfigs.
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration stopped 0
AsyncAppenders.
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration notified 4
ReliabilityStrategies that appenders will be stopped.
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Shutting down
MemoryMappedFileManager logs/memmap.log
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG MMapAppender unmapping old
buffer...
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG MMapAppender unmapped buffer OK
in 2.687763 millis
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG MMapAppender closing. Setting
logs/memmap.log length to 2004 (offset 0 + position 2004)
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG Shutting down
RollingRandomAccessFileManager logs/dv.log-OFF
2015-10-18 22:25:09,976 pool-2-thread-1 TRACE XmlConfiguration stopped 3
Appenders.
2015-10-18 22:25:09,976 pool-2-thread-1 TRACE XmlConfiguration stopped 4
LoggerConfigs.
2015-10-18 22:25:09,976 pool-2-thread-1 TRACE XmlConfiguration stopping
Log4j2ConfigWatcher thread.
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG Stopped
XmlConfiguration[location=C:\Users\remko\workspace\log4j-issues\bin\log4j2-1162-memmap.xml]
OK
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG Stopped
LoggerContext[name=1554547125,
org.apache.logging.log4j.core.LoggerContext@75c072cb]...
{noformat}
was (Author: [email protected]):
I think this was caused by LOG4J2-1166: since 2.5 the monitorInterval causes an
executor service to be started. This was a non-daemon thread by mistake so the
shutdown hook was not called.
Can you try again?
I tested a standalone test app with the configuration you specified and now I
get this output:
note the line {{MMapAppender closing. Setting logs/memmap.log length to 2004
(offset 0 + position 2004)}}
{noformat}
...
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Stopping
LoggerContext[name=1554547125,
org.apache.logging.log4j.core.LoggerContext@75c072cb]...
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=StatusLogger
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=ContextSelector
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Loggers,name=javax.management
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Loggers,name=com.rs.dv.util.LoggerEnvironmentReporter
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Loggers,name=sun.rmi
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Loggers,name=
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Appenders,name=RollingFile
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Appenders,name=MemMapFile
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Unregistering MBean
org.apache.logging.log4j2:type=1554547125,component=Appenders,name=Console
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE Stopping
XmlConfiguration[location=C:\Users\remko\workspace\log4j-issues\bin\log4j2-1162-memmap.xml]...
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration notified 4
ReliabilityStrategies that config will be stopped.
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration stopped 0
AsyncLoggerConfigs.
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration stopped 0
AsyncAppenders.
2015-10-18 22:25:09,960 pool-2-thread-1 TRACE XmlConfiguration notified 4
ReliabilityStrategies that appenders will be stopped.
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG Shutting down
MemoryMappedFileManager logs/memmap.log
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG MMapAppender unmapping old
buffer...
2015-10-18 22:25:09,960 pool-2-thread-1 DEBUG MMapAppender unmapped buffer OK
in 2.687763 millis
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG MMapAppender closing. Setting
logs/memmap.log length to 2004 (offset 0 + position 2004)
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG Shutting down
RollingRandomAccessFileManager logs/dv.log-OFF
2015-10-18 22:25:09,976 pool-2-thread-1 TRACE XmlConfiguration stopped 3
Appenders.
2015-10-18 22:25:09,976 pool-2-thread-1 TRACE XmlConfiguration stopped 4
LoggerConfigs.
2015-10-18 22:25:09,976 pool-2-thread-1 TRACE XmlConfiguration stopping
Log4j2ConfigWatcher thread.
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG Stopped
XmlConfiguration[location=C:\Users\remko\workspace\log4j-issues\bin\log4j2-1162-memmap.xml]
OK
2015-10-18 22:25:09,976 pool-2-thread-1 DEBUG Stopped
LoggerContext[name=1554547125,
org.apache.logging.log4j.core.LoggerContext@75c072cb]...
{noformat}
> Memory-mapped file appender creates null-padded files.
> ------------------------------------------------------
>
> Key: LOG4J2-1162
> URL: https://issues.apache.org/jira/browse/LOG4J2-1162
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.4.1
> Environment: Apache Maven 3.3.3
> (7994120775791599e205a5524ec3e0dfe41d4a06; 2015-04-22T04:57:37-07:00)
> Maven home: C:\Java\apache-maven-3.3.3\bin\..
> Java version: 1.7.0_79, vendor: Oracle Corporation
> Java home: C:\Program Files\Java\jdk1.7.0_79\jre
> Default locale: en_US, platform encoding: Cp1252
> OS name: "windows 7", version: "6.1", arch: "amd64", family: "windows"
> Reporter: Gary Gregory
>
> Memory-mapped file appender creates null-padded files.
> If configured my app like this:
> {code:xml}
> <?xml version="1.0" encoding="UTF-8"?>
> <!-- Copyright 2014-2015 Rocket Software, Inc. All rights reserved. -->
> <Configuration status="WARN" monitorInterval="5">
> <Appenders>
> <Console name="Console" target="SYSTEM_OUT">
> <PatternLayout noConsoleNoAnsi="true"
> pattern="%style{%d}{white} %highlight{%-5level}{TRACE=white}
> %style{[%t][%logger]}{white} %highlight{%msg%n%throwable}{TRACE=white}" />
> </Console>
> <RollingRandomAccessFile name="RollingFile" append="false"
> fileName="/test/dv/logs/dv.log-OFF"
>
> filePattern="/test/dv/logs/$${date:yyyy-MM}/dv-%d{yyyy-MM-dd}-%i.log.gz">
> <PatternLayout>
> <Pattern>%d %-5level [%t][%logger] %msg%n%throwable</Pattern>
> </PatternLayout>
> <Policies>
> <SizeBasedTriggeringPolicy size="100 MB" />
> </Policies>
> </RollingRandomAccessFile>
> <MemoryMappedFile name="MemMapFile" append="false"
> fileName="/test/dv/logs/dv.log">
> <PatternLayout>
> <Pattern>%d %-5level [%t][%logger] %msg%n%throwable</Pattern>
> </PatternLayout>
> </MemoryMappedFile>
> </Appenders>
> <Loggers>
> <Root level="trace">
> <!-- <AppenderRef ref="Console" /> -->
> <!-- <AppenderRef ref="RollingFile" /> -->
> <AppenderRef ref="MemMapFile" />
> </Root>
> <Logger name="javax.management" level="INFO" />
> <Logger name="sun.rmi" level="INFO" />
> <Logger name="com.rs.dv.util.LoggerEnvironmentReporter" level="OFF" />
> </Loggers>
> <!-- Filters -->
> <Filters>
> <!-- SQL only -->
> <!-- <MarkerFilter marker="DV.SQL" onMatch="ACCEPT" onMismatch="DENY" />
> <MarkerFilter marker="DV.SQL.QUERY" onMatch="ACCEPT"
> onMismatch="DENY" /> <MarkerFilter marker="DV.SQL.UPDATE"
> onMatch="ACCEPT" onMismatch="DENY" /> -->
> <!-- No buffer hex dumps -->
> <!-- <MarkerFilter marker="DV.BUFFER" onMatch="DENY" onMismatch="NEUTRAL"
> /> -->
> </Filters>
> </Configuration>
> {code}
> After the app runs, I have a 32 MB log file, with the later 2/3 of the file,
> all null bytes.
> Clearly, we need to limit what we write out.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
