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:[email protected]] 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 <[email protected]<mailto:[email protected]>> 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:[email protected]<javascript:_e(%7B%7D,'cvml','[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.
