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 Mark Womack <ma...@womacknet.com> on 2006/01/20 05:11:21 UTC
TimeBasedRolling unit test fails (sometimes)
I haven't had a chance to look at this, but it has happened to me twice at
various times. Sometimes the TimeBasedRolling unit test fails. Most of the
time it is fine, but sometimes there is a missing file:
TimeBasedRolling:
[junit] Running org.apache.log4j.rolling.TimeBasedRollingTest
[junit] Tests run: 9, Failures: 0, Errors: 1, Time elapsed: 27.58 sec
[junit] Testsuite: org.apache.log4j.rolling.TimeBasedRollingTest
[junit] Tests run: 9, Failures: 0, Errors: 1, Time elapsed: 27.58 sec
[junit] ------------- Standard Output ---------------
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:15,103 [main] DEBUG
rolling.TimeBasedRollingTest#test1:105 - Hello---0
[junit] 20:08:15,614 [main] DEBUG
rolling.TimeBasedRollingTest#test1:105 - Hello---1
[junit] 20:08:16,125 [main] DEBUG
rolling.TimeBasedRollingTest#test1:105 - Hello---2
[junit] 20:08:16,626 [main] DEBUG
rolling.TimeBasedRollingTest#test1:105 - Hello---3
[junit] 20:08:17,126 [main] DEBUG
rolling.TimeBasedRollingTest#test1:105 - Hello---4
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:18,108 [main] DEBUG
rolling.TimeBasedRollingTest#test2:150 - Hello---0
[junit] 20:08:18,608 [main] DEBUG
rolling.TimeBasedRollingTest#test2:150 - Hello---1
[junit] 20:08:19,109 [main] DEBUG
rolling.TimeBasedRollingTest#test2:150 - Hello---2
[junit] 20:08:19,620 [main] DEBUG
rolling.TimeBasedRollingTest#test2:169 - Hello---3
[junit] 20:08:20,121 [main] DEBUG
rolling.TimeBasedRollingTest#test2:169 - Hello---4
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:21,102 [main] DEBUG
rolling.TimeBasedRollingTest#test3:214 - Hello---0
[junit] 20:08:21,603 [main] DEBUG
rolling.TimeBasedRollingTest#test3:214 - Hello---1
[junit] 20:08:22,104 [main] DEBUG
rolling.TimeBasedRollingTest#test3:214 - Hello---2
[junit] 20:08:22,624 [main] DEBUG
rolling.TimeBasedRollingTest#test3:214 - Hello---3
[junit] 20:08:23,125 [main] DEBUG
rolling.TimeBasedRollingTest#test3:214 - Hello---4
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:24,096 [main] DEBUG
rolling.TimeBasedRollingTest#test4:265 - Hello---0
[junit] 20:08:24,607 [main] DEBUG
rolling.TimeBasedRollingTest#test4:265 - Hello---1
[junit] 20:08:25,108 [main] DEBUG
rolling.TimeBasedRollingTest#test4:265 - Hello---2
[junit] 20:08:25,629 [main] DEBUG
rolling.TimeBasedRollingTest#test4:285 - Hello---3
[junit] 20:08:26,129 [main] DEBUG
rolling.TimeBasedRollingTest#test4:285 - Hello---4
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:27,101 [main] DEBUG
rolling.TimeBasedRollingTest#test5:331 - Hello---0
[junit] 20:08:27,601 [main] DEBUG
rolling.TimeBasedRollingTest#test5:331 - Hello---1
[junit] 20:08:28,102 [main] DEBUG
rolling.TimeBasedRollingTest#test5:331 - Hello---2
[junit] 20:08:28,623 [main] DEBUG
rolling.TimeBasedRollingTest#test5:331 - Hello---3
[junit] 20:08:29,124 [main] DEBUG
rolling.TimeBasedRollingTest#test5:331 - Hello---4
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:30,105 [main] DEBUG
rolling.TimeBasedRollingTest#test6:375 - Hello---0
[junit] 20:08:30,606 [main] DEBUG
rolling.TimeBasedRollingTest#test6:375 - Hello---1
[junit] 20:08:31,106 [main] DEBUG
rolling.TimeBasedRollingTest#test6:375 - Hello---2
[junit] 20:08:31,617 [main] DEBUG
rolling.TimeBasedRollingTest#test6:375 - Hello---3
[junit] 20:08:32,118 [main] DEBUG
rolling.TimeBasedRollingTest#test6:375 - Hello---4
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,839 DEBUG [main]
org.apache.log4j.joran.action.ConfigurationAction#begin
:42)- Starting internal logs on console.
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,859 DEBUG [main]
org.apache.log4j.joran.action.AppenderAction#begin:52)-
About to instantiate appender of type
[org.apache.log4j.rolling.RollingFileAppender]
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,859 DEBUG [main]
org.apache.log4j.joran.action.AppenderAction#begin:67)-
Appender named as [ROLL]
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,859 DEBUG [main]
org.apache.log4j.joran.action.AppenderAction#begin:78)-
Pushing appender on to the object stack.
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,949 DEBUG [main]
org.apache.log4j.joran.action.ParamAction#begin:61)- In
ParamAction setting parameter [fileNamePattern] to value
[output/test1-%d{yyyy-MM-dd_HH_mm_ss}].
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,969 DEBUG [main]
org.apache.log4j.joran.action.LayoutAction#begin:45)- A
bout to instantiate layout of type [org.apache.log4j.PatternLayout]
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,969 DEBUG [main]
org.apache.log4j.joran.action.LayoutAction#begin:56)- P
ushing layout on top of the object stack.
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,969 DEBUG [main]
org.apache.log4j.joran.action.ParamAction#begin:61)- In
ParamAction setting parameter [ConversionPattern] to value [%c{1} - %m%n].
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,979 DEBUG [main]
org.apache.log4j.joran.action.LayoutAction#end:86)- Pop
ping layout from the object stack
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,989 DEBUG [main]
org.apache.log4j.joran.action.LayoutAction#end:90)- Abo
ut to set the layout of the containing appender.
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,989 DEBUG [main]
org.apache.log4j.rolling.RollingFileAppender#setFile:25
5)- setFile called: output/test1-2006-01-19_20_08_32, true
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.rolling.RollingFileAppender#setFile:29
5)- setFile ended
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.AppenderAction#end:110)-
Popping appender named [ROLL] from the object stack
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.LoggerAction#begin:60)- L
ogger name is [org.apache.log4j.rolling.TimeBasedRollingTest].
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.LoggerAction#begin:67)- R
etreiving an instance of org.apache.log4j.getLogger().
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.LoggerAction#begin:90)- S
etting [org.apache.log4j.rolling.TimeBasedRollingTest] additivity to [true].
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.LoggerAction#begin:94)- P
ushing logger named [org.apache.log4j.rolling.TimeBasedRollingTest].
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.AppenderRefAction#begin:8
8)- Attaching appender named [ROLL] to logger named
[org.apache.log4j.rolling.TimeBasedRollingTest].
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.LoggerAction#end:99)- end
() called.
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:32,999 DEBUG [main]
org.apache.log4j.joran.action.LoggerAction#end:102)- Re
moving logger from stack.
[junit] LOG4J-INTERNAL: 2006-01-19 20:08:33,009 DEBUG [main]
org.apache.log4j.joran.action.ConfigurationAction#end:4
9)- Will stop writing internal logs on console.
[junit] 20:08:32,839 [main] DEBUG action.ConfigurationAction#begin:42 -
Starting internal logs on console.
[junit] 20:08:32,859 [main] DEBUG action.AppenderAction#begin:52 - About
to instantiate appender of type [org.apache
.log4j.rolling.RollingFileAppender]
[junit] 20:08:32,859 [main] DEBUG action.AppenderAction#begin:67 -
Appender named as [ROLL]
[junit] 20:08:32,859 [main] DEBUG action.AppenderAction#begin:78 -
Pushing appender on to the object stack.
[junit] 20:08:32,949 [main] DEBUG action.ParamAction#begin:61 - In
ParamAction setting parameter [fileNamePattern] t
o value [output/test1-%d{yyyy-MM-dd_HH_mm_ss}].
[junit] 20:08:32,969 [main] DEBUG action.LayoutAction#begin:45 - About
to instantiate layout of type [org.apache.log
4j.PatternLayout]
[junit] 20:08:32,969 [main] DEBUG action.LayoutAction#begin:56 - Pushing
layout on top of the object stack.
[junit] 20:08:32,969 [main] DEBUG action.ParamAction#begin:61 - In
ParamAction setting parameter [ConversionPattern]
to value [%c{1} - %m%n].
[junit] 20:08:32,979 [main] DEBUG action.LayoutAction#end:86 - Popping
layout from the object stack
[junit] 20:08:32,989 [main] DEBUG action.LayoutAction#end:90 - About to
set the layout of the containing appender.
[junit] 20:08:32,989 [main] DEBUG
rolling.RollingFileAppender#setFile:255 - setFile called:
output/test1-2006-01-19_
20_08_32, true
[junit] 20:08:32,999 [main] DEBUG
rolling.RollingFileAppender#setFile:295 - setFile ended
[junit] 20:08:32,999 [main] DEBUG action.AppenderAction#end:110 -
Popping appender named [ROLL] from the object stac
k
[junit] 20:08:32,999 [main] DEBUG action.LoggerAction#begin:60 - Logger
name is [org.apache.log4j.rolling.TimeBasedR
ollingTest].
[junit] 20:08:32,999 [main] DEBUG action.LoggerAction#begin:67 -
Retreiving an instance of org.apache.log4j.getLogge
r().
[junit] 20:08:32,999 [main] DEBUG action.LoggerAction#begin:90 - Setting
[org.apache.log4j.rolling.TimeBasedRollingT
est] additivity to [true].
[junit] 20:08:32,999 [main] DEBUG action.LoggerAction#begin:94 - Pushing
logger named [org.apache.log4j.rolling.Time
BasedRollingTest].
[junit] 20:08:32,999 [main] DEBUG action.AppenderRefAction#begin:88 -
Attaching appender named [ROLL] to logger name
d [org.apache.log4j.rolling.TimeBasedRollingTest].
[junit] 20:08:32,999 [main] DEBUG action.LoggerAction#end:99 - end()
called.
[junit] 20:08:32,999 [main] DEBUG action.LoggerAction#end:102 - Removing
logger from stack.
[junit] 20:08:33,009 [main] DEBUG action.ConfigurationAction#end:49 -
Will stop writing internal logs on console.
[junit] 20:08:33,009 [main] DEBUG
joran.JoranConfigurator#doConfigure:172 - Finished parsing.
[junit] Waiting until next second and 100 millis.
[junit] Done waiting.
[junit] 20:08:34,101 [main] DEBUG
rolling.TimeBasedRollingTest#testWithJoran1:414 - Hello---0
[junit] 20:08:34,601 [main] DEBUG
rolling.TimeBasedRollingTest#testWithJoran1:414 - Hello---1
[junit] 20:08:35,102 [main] DEBUG
rolling.TimeBasedRollingTest#testWithJoran1:414 - Hello---2
[junit] 20:08:35,603 [main] DEBUG
rolling.TimeBasedRollingTest#testWithJoran1:414 - Hello---3
[junit] 20:08:36,104 [main] DEBUG
rolling.TimeBasedRollingTest#testWithJoran1:414 - Hello---4
[junit] ------------- ---------------- ---------------
[junit] Testcase: test1 took 3.545 sec
[junit] Testcase: test2 took 2.964 sec
[junit] Testcase: test3 took 3.025 sec
[junit] Testcase: test4 took 2.984 sec
[junit] Testcase: test5 took 3.004 sec
[junit] Testcase: test6 took 2.995 sec
[junit] Testcase: testWithJoran1 took 3.955 sec
[junit] Caused an ERROR
[junit] output\test1-2006-01-19_20_08_33 (The system cannot find the
file specified)
[junit] java.io.FileNotFoundException: output\test1-2006-01-19_20_08_33
(The system cannot find the file specified)
[junit] at java.io.FileInputStream.open(Native Method)
[junit] at java.io.FileInputStream.<init>(FileInputStream.java:106)
[junit] at java.io.FileInputStream.<init>(FileInputStream.java:66)
[junit] at java.io.FileReader.<init>(FileReader.java:41)
[junit] at org.apache.log4j.util.Compare.compare(Compare.java:34)
[junit] at
org.apache.log4j.rolling.TimeBasedRollingTest.testWithJoran1(TimeBasedRollingTest.java:423)
[junit] Testcase: test1 took 2.564 sec
[junit] Testcase: test2 took 2.524 sec
BUILD FAILED
F:\development\code-svn-apache-projects\logging-log4j\tests\build.xml:560:
Test org.apache.log4j.rolling.TimeBasedRollin
gTest failed
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org