You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Luigi Alice <Lu...@persis.de> on 2014/02/19 11:12:34 UTC
Same log entries multiple times
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
AW: Same log entries multiple times
Posted by Luigi Alice <Lu...@persis.de>.
Hi Remko,
thanks for your reply.
I don't use "monitorIntervall" because I dynamically create the configuration as XML string in memory based on log4j2.xml file.
So the log4j2.xml does not reflect the actual configuration und should therefore not be reloaded.
Regards
Luigi
Von: Remko Popma [mailto:remko.popma@gmail.com]
Gesendet: Mittwoch, 19. Februar 2014 14:22
An: Log4J Developers List
Betreff: Re: Same log entries multiple times
Hi Luigi,
Thanks for the config. This confirms my hypothesis. If you change the config for the named loggers to add attribute
additivity="false"
then you should no longer see the duplicate entries. Please refer to the docs on additivity for why it works this way.
By the way, your config has a comment (in German, so not 100% sure) that you are not using the "monitorInterval" attribute because you are worried that reconfiguration will result in lost log events. This was a problem in log4j-1.2, but this is no longer an issue in log4j2. I hope that this is useful information.
Best regards,
Remko
On Wednesday, February 19, 2014, Luigi Alice <Lu...@persis.de>> wrote:
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:remko.popma@gmail.com<javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>]
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 <Lu...@persis.de>> 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.
Re: Same log entries multiple times
Posted by Remko Popma <re...@gmail.com>.
Hi Luigi,
Thanks for the config. This confirms my hypothesis. If you change the
config for the named loggers to add attribute
additivity="false"
then you should no longer see the duplicate entries. Please refer to the
docs on additivity for why it works this way.
By the way, your config has a comment (in German, so not 100% sure) that
you are not using the "monitorInterval" attribute because you are worried
that reconfiguration will result in lost log events. This was a problem in
log4j-1.2, but this is no longer an issue in log4j2. I hope that this is
useful information.
Best regards,
Remko
On Wednesday, February 19, 2014, Luigi Alice <Lu...@persis.de> wrote:
> 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:remko.popma@gmail.com<javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>]
>
> *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 <Lu...@persis.de> 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.
>
>
AW: Same log entries multiple times
Posted by Luigi Alice <Lu...@persis.de>.
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:remko.popma@gmail.com]
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 <Lu...@persis.de>> 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
Re: Same log entries multiple times
Posted by Remko Popma <re...@gmail.com>.
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 <Lu...@persis.de> 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
>