Hi Remko,
the xml configuration is created dynamically:
<?xml version="1.0" encoding="UTF-8"?> <!-- Attribut "monitorIntervall" nicht
verwenden, da Persis intern dynamisch umkonfiguriert und dies sonst verloren
gehen würde! --> <configuration> <properties> <property
name="filename">persis.log</property> </properties> <appenders>
<Routing name="PERSIS_GLOBAL"> <Routes
pattern="$${ctx:log.uid}-$${ctx:caller}"> <Route>
<RollingRandomAccessFile name="Rolling-${ctx:log.uid}-${ctx:caller}"
fileName =
"${ctx:log.dir}/${ctx:caller}/${ctx:log.uid}_${filename}"
filePattern =
"${ctx:log.dir}/${ctx:caller}/${ctx:log.uid}_persis-%d{yyyy-MM-dd}-%3i.log">
<!--<RegexFilter regex=".*SystemHandler\.fileHandler.*" onMatch="DENY"
onMismatch="NEUTRAL"/>--> <!-- file/null Seiten herausfiltern -->
<ThreadContextMapFilter onMatch="DENY" onMismatch="NEUTRAL" operator="or">
<KeyValuePair key="page" value="file/null"/> </ThreadContextMapFilter>
<PatternLayout charset="UTF-8">
<pattern>[%d{HH:mm:ss.SSS}|<!--%X{remoteAddr}-->|<!--%X{session}-->|%X{subThread}|%X{page}|%X{includeStack}|%X{taskID}|%X{levelNo}|%X{location}]
# %m%n</pattern> </PatternLayout>
<Policies> <SizeBasedTriggeringPolicy size="20
MB"/> </Policies> <DefaultRolloverStrategy max="1000"/>
</RollingRandomAccessFile> </Route>
</Routes> </Routing> <Console name="PERSIS_STDOUT"
target="SYSTEM_OUT"> <PatternLayout charset="UTF-8">
<pattern>[%d{HH:mm:ss.SSS}|%X{remoteAddr}|%X{session}|%X{subThread}|%X{page}|%X{includeStack}|%X{taskID}|%X{levelNo}|%X{location}]
# %m%n</pattern> </PatternLayout> </Console>
</appenders> <loggers> <root level="ALL"> <!-- Hier im
AppenderRef bitte den globalen Log-Level anpassen! --> <!-- Levels:
OFF, ERROR, WARN, INFO, DEBUG, ALL --> <AppenderRef
ref="PERSIS_GLOBAL" level="DEBUG" /> <!-- Appender
PERSIS_STDOUT wird von Engine aktiviert bei LogRecorder.setLoggingToStdout()
--> <AppenderRef ref="PERSIS_STDOUT" level="OFF" />
</root> <logger
name="86FBECE50808FBF684422F95AAAE408E.P011Tomcat70002" level="ALL">
<AppenderRef ref="PERSIS_GLOBAL" level="DEBUG" /> </logger> <logger
name="192.168.0.138" level="ALL"> <AppenderRef ref="PERSIS_GLOBAL"
level="DEBUG" /> </logger> <logger name="192.168.0.160" level="ALL">
<AppenderRef ref="PERSIS_GLOBAL" level="DEBUG" /> </logger> <logger
name="192.168.0.150" level="ALL"> <AppenderRef ref="PERSIS_GLOBAL"
level="DEBUG" /> </logger> <logger name="Scheduler" level="ALL">
<AppenderRef ref="PERSIS_GLOBAL" level="DEBUG" /> </logger> <logger
name="658DC3BEDF712A4D173ED74089235AE5.P011Tomcat70002" level="ALL">
<AppenderRef ref="PERSIS_GLOBAL" level="DEBUG" /> </logger> <logger
name="FEF75997582B3043FF49B83E76494E2E.P011Tomcat70002" level="ALL">
<AppenderRef ref="PERSIS_GLOBAL" level="WARN" /> </logger> <logger
name="192.168.0.140" level="ALL"> <AppenderRef ref="PERSIS_GLOBAL"
level="DEBUG" /> </logger> <logger
name="A5CFB78C823A53D0058EA517E1E722D6.P011Tomcat70002" level="ALL">
<AppenderRef ref="PERSIS_GLOBAL" level="DEBUG" /> </logger> </loggers>
</configuration>
So, if I change something this configuration is reloaded.
Maybe there is still running an old configuration while using a new one?
Regards
Mr. L. Alice
Software developer
Von: Remko Popma [mailto:[email protected]]
Gesendet: Mittwoch, 19. Februar 2014 12:20
An: Log4J Developers List
Betreff: Re: Same log entries multiple times
Hi Luigi,
The first thing that comes to mind is that this may be caused by a log4j
feature called additivity. (Documented here:
http://logging.apache.org/log4j/2.x/manual/configuration.html#Additivity )
Basically, if your configuration is such that multiple loggers receive a log
event, then each logger will add an identical log file entry unless Additivity
is switched off.
Can you check if this is the case?
Best regards,
Remko
Sent from my iPhone
On 2014/02/19, at 19:12, Luigi Alice
<[email protected]<mailto:[email protected]>> wrote:
Hello,
sometimes I have the same log entries multiple times in the log files.
...
[08:55:25.406|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|DBStatementImpl.executeQuery()] # Abgesetzter SQL-Befehl: [se=
lect * from Z_DUMMY]
[08:55:25.406|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|DBStatementImpl.executeQuery()] # Abgesetzter SQL-Befehl: [se=
lect * from Z_DUMMY]
[08:55:25.406|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|DBStatementImpl.executeQuery()] # Abgesetzter SQL-Befehl abge=
schlossen. Execution-time: 0 ms
[08:55:25.406|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|DBStatementImpl.executeQuery()] # Abgesetzter SQL-Befehl abge=
schlossen. Execution-time: 0 ms
[08:55:25.407|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|SelectCommand.executeCommand()] # Select-Kommando: [selMA.sel=
Blub.selBlub]; Anzahl Datens=E4tze: [1]; Execution-time: [0 ms (sum); 0 ms =
(self)];
[08:55:25.407|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|SelectCommand.executeCommand()] # Select-Kommando: [selMA.sel=
Blub.selBlub]; Anzahl Datens=E4tze: [1]; Execution-time: [0 ms (sum); 0 ms =
(self)];
[08:55:25.407|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|SelectCommand.executeCommand()] # Select-Kommando: [selMA.sel=
Blub]; Anzahl Datens=E4tze: [1]; Execution-time: [2 ms (sum); 0 ms (self)];
[08:55:25.407|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|4|SelectCommand.executeCommand()] # Select-Kommando: [selMA.sel=
Blub]; Anzahl Datens=E4tze: [1]; Execution-time: [2 ms (sum); 0 ms (self)];
[08:55:25.407|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|3|CommandSequence.fireSubCommandEvent()] # Logging deaktiviert =
ab: selMA.selAtts
[08:55:25.407|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|3|CommandSequence.fireSubCommandEvent()] # Logging deaktiviert =
ab: selMA.selAtts
[08:55:25.409|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|3|CommandSequence.fireSubCommandEvent()] # Logging wieder aktiv=
iert nach: selMA.selAtts
[08:55:25.409|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|3|CommandSequence.fireSubCommandEvent()] # Logging wieder aktiv=
iert nach: selMA.selAtts
[08:55:25.409|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|3|CommandSequence.executeCommand()] # F=FChre Kommandosequenz a=
us: 'selMA.selBlub'
[08:55:25.409|0:0:0:0:0:0:0:1|DC4CFAAC6E824F77BA23D01CB2F0D38A||la.test/dyn=
_table||251|3|CommandSequence.executeCommand()] # F=FChre Kommandosequenz a=
us: 'selMA.selBlub'
...
I suppose it has something to do with initializing the configuration, but I=
don't' know.
private void startConfig(String config)
{
synchronized(LogRecorder.class) // parallele Initialisierung ka= nn
zu Deadlock f=FChren
{
try {
MDC.put("log.dir", this.logDir); // sonst: java.io.File=
NotFoundException: ${ctx:log.dir}\persis.log
final ConfigurationFactory.ConfigurationSource source = =3D
new ConfigurationFactory.ConfigurationSource(new ByteArrayInputStream(c=
onfig.getBytes("UTF-8")));
final LoggerContext ctx =3D Configurator.initialize(nul= l,
source);
this.currentConfig =3D config;
// XMLConfiguration cfg =3D new XMLConfiguration(sc);
// Logger l =3D (Logger) LogManager.getLogger(LogManager=
.ROOT_LOGGER_NAME);
// l.getContext().start(cfg);
} catch (UnsupportedEncodingException ex) {
throw new RuntimeException(ex);
}
}
}
Does anyone know this problem or have an idea?
Regards
Mr. L. Alice
Software developer
