[logback-dev] [JIRA] Updated: (LBCLASSIC-207) LoggingEventVO is using a simply toString during serialization, fumbling with arrays.
Joern Huxhorn (JIRA)
noreply-jira at qos.ch
Thu May 6 14:58:16 CEST 2010
[ http://jira.qos.ch/browse/LBCLASSIC-207?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Joern Huxhorn updated LBCLASSIC-207:
------------------------------------
Attachment: LoggingEventVOSerializationTest.java
I have written a small test that will currently fail but shouldn't.
Expected :[Three, Four, Five]
Actual :[Ljava.lang.String;@377653ae
I still have serious problems building Logback, though.
SMTPAppender_SubethaSMTPTest still hangs (ThreadDump below) and TimeBasedRollingWithArchiveRemovalTest failed once with a Timeout, too.
TEST 14:48:28.537 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:56367
TEST 14:48:28.537 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:56367
TEST 14:48:28.537 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:56367
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.3-b01-101 mixed mode):
"SocketAcceptorIoProcessor-2.0" prio=5 tid=0x000000010674f000 nid=0x114e5d000 runnable [0x0000000114e5c000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136)
at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x00000001069822b0> (a sun.nio.ch.Util$1)
- locked <0x0000000106982298> (a java.util.Collections$UnmodifiableSet)
- locked <0x0000000106981f38> (a sun.nio.ch.KQueueSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:480)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:637)
"SocketAcceptor-2" prio=5 tid=0x0000000102578800 nid=0x114b54000 runnable [0x0000000114b53000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136)
at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x00000001077a0150> (a sun.nio.ch.Util$1)
- locked <0x00000001077a0168> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000001077a00d8> (a sun.nio.ch.KQueueSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
at org.apache.mina.transport.socket.nio.SocketAcceptor$Worker.run(SocketAcceptor.java:220)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:637)
"Low Memory Detector" daemon prio=5 tid=0x0000000102021000 nid=0x114290000 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"CompilerThread1" daemon prio=9 tid=0x0000000106093000 nid=0x11418d000 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"CompilerThread0" daemon prio=9 tid=0x0000000106092800 nid=0x11408a000 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=9 tid=0x0000000106091800 nid=0x113f87000 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Surrogate Locker Thread (CMS)" daemon prio=5 tid=0x0000000106091000 nid=0x113e84000 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=0x000000010607b000 nid=0x113bf8000 in Object.wait() [0x0000000113bf7000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000107cc4b50> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x0000000107cc4b50> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x000000010607a800 nid=0x113af5000 in Object.wait() [0x0000000113af4000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000107cc0018> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x0000000107cc0018> (a java.lang.ref.Reference$Lock)
"main" prio=5 tid=0x0000000102000800 nid=0x100501000 runnable [0x00000001004fe000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:97)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
- locked <0x000000010690fd18> (a java.io.BufferedInputStream)
at com.sun.mail.util.LineInputStream.readLine(LineInputStream.java:75)
at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:1440)
at com.sun.mail.smtp.SMTPTransport.issueSendCommand(SMTPTransport.java:1376)
at com.sun.mail.smtp.SMTPTransport.finishData(SMTPTransport.java:1215)
at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:586)
- locked <0x000000010690c418> (a com.sun.mail.smtp.SMTPTransport)
at javax.mail.Transport.send0(Transport.java:169)
at javax.mail.Transport.send(Transport.java:98)
at ch.qos.logback.core.net.SMTPAppenderBase.sendBuffer(SMTPAppenderBase.java:292)
at ch.qos.logback.core.net.SMTPAppenderBase.append(SMTPAppenderBase.java:159)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)
- locked <0x00000001077a04c0> (a ch.qos.logback.classic.net.SMTPAppender)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:283)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:471)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:425)
at ch.qos.logback.classic.Logger.error(Logger.java:588)
at ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest.htmlLong(SMTPAppender_SubethaSMTPTest.java:195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:345)
at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1009)
"VM Thread" prio=9 tid=0x0000000102020800 nid=0x105f5c000 runnable
"Gang worker#0 (Parallel GC Threads)" prio=9 tid=0x0000000106000000 nid=0x105a05000 runnable
"Gang worker#1 (Parallel GC Threads)" prio=9 tid=0x0000000106001000 nid=0x105b08000 runnable
"Concurrent Mark-Sweep GC Thread" prio=9 tid=0x0000000106040000 nid=0x105e59000 runnable
"VM Periodic Task Thread" prio=10 tid=0x0000000102022000 nid=0x114393000 waiting on condition
"Exception Catcher Thread" prio=10 tid=0x0000000102001800 nid=0x102901000 runnable
JNI global references: 938
Heap
par new generation total 18624K, used 3939K [0x0000000106800000, 0x0000000107cc0000, 0x0000000107cc0000)
eden space 16000K, 17% used [0x0000000106800000, 0x0000000106ab73e0, 0x00000001077a0000)
from space 2624K, 44% used [0x00000001077a0000, 0x00000001078c1938, 0x0000000107a30000)
to space 2624K, 0% used [0x0000000107a30000, 0x0000000107a30000, 0x0000000107cc0000)
concurrent mark-sweep generation total 62656K, used 4194K [0x0000000107cc0000, 0x000000010b9f0000, 0x000000010bc00000)
concurrent-mark-sweep perm gen total 35236K, used 21273K [0x000000010bc00000, 0x000000010de69000, 0x0000000111000000)
> LoggingEventVO is using a simply toString during serialization, fumbling with arrays.
> -------------------------------------------------------------------------------------
>
> Key: LBCLASSIC-207
> URL: http://jira.qos.ch/browse/LBCLASSIC-207
> Project: logback-classic
> Issue Type: Bug
> Components: appender
> Affects Versions: 0.9.20
> Reporter: Joern Huxhorn
> Assignee: Logback dev list
> Attachments: LoggingEventVOSerializationTest.java
>
>
> Any array used as parameter shows up unreadable.
> It should instead use the same toString logic used by MessageFormatter.
> I'd have submitted a patch/branch for this issue but - unfortunately - SLF4J MessageFormatter does not have a method that's performing just the String conversion.
> Please see
> http://github.com/huxi/lilith/blob/master/lilith-data/logging/src/main/java/de/huxhorn/lilith/data/logging/MessageFormatter.java
> especially the method
> String deepToString(Object o)
> Because of this, a fix (providing and using said method) would span over both SLF4J and Logback.
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the logback-dev
mailing list