January 2012 - logback-user

Log Messages duplicate when running unit tests.
by Matt Bertolini 06 Jan '12

06 Jan '12

Hello. I am trying to implement logback/slf4j and an extremely frustrating thing is occurring when I run my unit tests. All of the log messages are being duplicated. I am aware of the whole additive nature of appenders and I am pretty sure that I am doing things correctly in that regard but the messages continue to duplicate when running unit tests. When I run through a main method, they do not. Here is my configuration and the messages that are displayed when running unit tests. Dependencies I have included (via Ivy): <dependency org="org.slf4j" name="slf4j-api" rev="1.6.4"/> <dependency org="ch.qos.logback" name="logback-core" rev="1.0.0"/> <dependency org="ch.qos.logback" name="logback-classic" rev="1.0.0"/> Configuration: <configuration debug="true"> <contextName>example-test</contextName> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level %logger - %msg%n</pattern> </encoder> </appender> <logger name="com.example" level="debug"/> <root level="warn"> <appender-ref ref="STDOUT"/> </root> </configuration> Log output when running unit tests: 13:44:23,308 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [example-test] 13:44:23,308 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 13:44:23,313 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] 13:44:23,344 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 13:44:23,431 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example] to DEBUG 13:44:23,431 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN 13:44:23,431 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] 13:44:23,433 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 13:44:23.453 INFO com.example.project.service.impl.ExampleClassImpl - This is a test. 13:44:23.466 INFO com.example.project.service.impl.ExampleClassImpl - This is a test. Log output when running under main method: 13:48:16,729 |-INFO in ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger context name as [example-test] 13:48:16,729 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 13:48:16,734 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] 13:48:16,760 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 13:48:16,825 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example] to DEBUG 13:48:16,825 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN 13:48:16,825 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] 13:48:16,827 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 13:48:16.843 INFO com.example.project.service.impl.ExampleClassImpl - This is a test. I know that the unit tests are picking up my configuration correctly. When I examine my unit test results, I can see that tests are only being run once so I it is not a duplicate execution of the code. Is there anything special I have to do to stop the duplicates when running unit tests? Thanks for your help. --Matt--

2 2

JaninoEventEvaluator and class loader
by Glyn Normington 06 Jan '12

06 Jan '12

I am attempting to get Janino 2.6.1 working with Logback 0.9.28 (or later, but that's the version we are using in Eclipse Virgo right now) - see [0] for background. Unfortunately Janino ends up using the thread context class loader as its "parent" class loader and fails with a runtime exception. I have discussed this ([1]) on the Janino mailing list and it seems that it is necessary to set the parent class loader in Janino. I am somewhat at the mercy of Logback here. The surprising thing is that the code in Logback 0.9.24 looked pretty usable in this respect. JaninoEventEvaluator.start had the following sequence: ClassLoader cl = context.getClass().getClassLoader(); ee = new ExpressionEvaluator(getDecoratedExpression(), EXPRESSION_TYPE, getParameterNames(), getParameterTypes(), THROWN_EXCEPTIONS, cl); thus setting the parent class loader to a value which I could ensure would be capable of loading the necessary types. In 0.9.28 this code has been replaced by: scriptEvaluator = new ScriptEvaluator(getDecoratedExpression(), EXPRESSION_TYPE, getParameterNames(), getParameterTypes(), THROWN_EXCEPTIONS); which causes the current TCCL to be used as the parent class loader and ultimately results in Janino failing. I can't control the TCCL that happens to be in use when start is called as that is driven out of a logging call which can come from an arbitrary thread. I found the relevant commit ([2]), but I can't tell from that why this specific change was made. If it is absolutely necessary to use ScriptEvaluator rather than ExpressionEvaluator, the following code sequence (based on a suggestion from Arno Unkrig) would reproduce the parent class loader behaviour of 0.9.24: ClassLoader cl = context.getClass().getClassLoader(); scriptEvaluator = new ScriptEvaluator(); scriptEvaluator.setParentClassLoader(cl); scriptEvaluator.setReturnType(EXPRESSION_TYPE); scriptEvaluator.setParameterNames(getParameterNames()); scriptEvaluator.setParameterTypes(getParameterTypes()); scriptEvaluator.setThrownExceptions(THROWN_EXCEPTIONS); scriptEvaluator.cook(getDecoratedExpression()); The alternative of using ExpressionEvaluator is much neater and seems to be close to the ScriptEvaluator variant since ExpressionEvaluator extends ScriptEvaluator. Any suggestions gratefully received. Regards, Glyn [0] https://bugs.eclipse.org/bugs/show_bug.cgi?id=333920 [1] mailing list archive link currently broken - if I can get a link to it, I'll post this later [2] https://github.com/ceki/logback/commit/06a5b692f14560636bd92d7bd7cf1f85830f…

2 2

Issues configuring GMail appender
by Greg Silin 04 Jan '12

04 Jan '12

Hi, I'm trying to setup logback for a fairly simple appender configuration.. DEBUG, INFO, WARN: System.out Console Appender, File Appender ERROR: System.err Console Appender, File Appender, SMTPAppender configured for GMail. Following instructions to setup GMail appender, I have the following: Appender config:  <appender name="MailAppender" class="ch.qos.logback.classic.net.SMTPAppender"> <smtpHost>smtp.gmail.com</smtpHost> <smtpPort>465</smtpPort> <ssl>true</ssl> <username>MyUsername</username> <password>MyPassword</password> <to>greg(a)klout.com</to>  <from>noreply(a)gmail.com</from> <subject>LOGGED ERROR: %logger{20} - %m</subject> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern>%date %-5level %logger{35} - %message%n%xEx{35}</pattern> </layout> </appender> Appender inclusion: <root level="ERROR"> <appender-ref ref="StdErrAppender" /> <appender-ref ref="FileAppender" /> <appender-ref ref="MailAppender" /> </root> All appropriate maven dependencies: logger jars <slf4j.version>1.6.4</slf4j.version> <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>${slf4j.version}</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-access</artifactId> <version>1.0.0</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.0.0</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-core</artifactId> <version>1.0.0</version> </dependency> java mail <dependency> <groupId>javax.mail</groupId> <artifactId>mail</artifactId> <version>1.4.4</version> </dependency> All the other appenders work just fine as configured. I see that the SMTPAppender is being loaded w/o error (at least nothing I see reported) .. yet on ERROR nothing gets sent. Username & password are all correct. I've confirmed with our operations that we don't have any special spam filters set up. Thoughts on what could be wrong / what I need to check? Thanks -greg

2 1

Are special charcters allowed in logger configurations?
by Noman Amir Jamil 04 Jan '12

04 Jan '12

Hi, I would like to know if the following issue is resolved in logback, it was previously encountered in log4j: "there are known issues with using this naming convention (with square brackets) in log4j XML based configuration files" I am using a similar configuration with square brackets: logger name="org.apache.catalina.core.ContainerBase.[Catalina].[localhost]" level="INFO" additivity="false"> But it appears that the portion after ContainerBase is being ignored or not processed. I would really appreciate any help on this. Thanks Noman A.

2 4

SMTPAppender OSGi-Problem within Glassfish v3.1.1 (Apache Felix)
by cinhtau 04 Jan '12

04 Jan '12

Hi @all, I try to use SMTPAppender for logging errors to respective users via E-Mail in OSGi. My configuration is: OS: Ubuntu Linux 10.04.03 LTS Application Environment: Glassfish 3.1.1 using Apache Felix Logback: tried logback classic Version 0.29 and current Version 1.0 leading to same results Glassfish has following bundles g! lb mail START LEVEL 10 ID|State |Level|Name 227|Resolved | 1|JavaMail API (1.4.4) I write following BundleActivator (I switch the real addresses with stubs), sending an email via SMTPAppender and Java Mail from scratch. package de.sgbs.log; import java.util.logging.Level; import javax.mail.Message; import javax.mail.MessagingException; import javax.mail.Session; import javax.mail.Transport; import javax.mail.internet.InternetAddress; import javax.mail.internet.MimeMessage; import org.osgi.framework.BundleActivator; import org.osgi.framework.BundleContext; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.slf4j.Marker; import org.slf4j.MarkerFactory; import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.joran.JoranConfigurator; import ch.qos.logback.core.joran.spi.JoranException; public class Activator implements BundleActivator { private final static Logger logger = LoggerFactory.getLogger(Activator.class); @Override public void start(BundleContext context) throws Exception { try { LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); JoranConfigurator configurator = new JoranConfigurator(); configurator.setContext(lc); lc.reset(); lc.putProperty("application-name", Activator.class.getSimpleName()); configurator.doConfigure("logback.xml"); Marker notifyAdmin = MarkerFactory.getMarker("NOTIFY_ADMIN"); logger.error(notifyAdmin, "This is a serious an error requiring the admin's attention", new Exception("Just testing")); } catch (JoranException ex) { java.util.logging.Logger.getLogger(Activator.class.getName()).log(Level.SEVERE, null, ex); } sendEMail(); } private void sendEMail() throws MessagingException { java.util.Properties props = new java.util.Properties(); props.put("mail.smtp.host", "smtp"); props.put("mail.smtp.port", "25"); Session session = Session.getDefaultInstance(props, null); // Construct the message Message msg = new MimeMessage(session); msg.setFrom(new InternetAddress("me(a)gmail.com")); msg.setRecipient(Message.RecipientType.TO, new InternetAddress("foo(a)bar.com")); msg.setSubject("Test"); msg.setText("Hello user, you got an error:"); // Send the message Transport.send(msg); } @Override public void stop(BundleContext context) { logger.info("Goodbye Community!"); } } My logback.xml NOTIFY_ADMIN TRANSACTION_FAILURE smtp foo(a)bar.com me(a)gmail.com TESTING: %logger{20} - %m %date %-5level %logger{35} - %message%n Sending from scratch works. SMTPAppender raises an error. This error is given on the osgi console: 10:14:46,850 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EMAIL] to Logger[ROOT] 10:14:47,048 |-ERROR in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - Error occured while sending e-mail notification. javax.mail.MessagingException: IOException while sending message; nested exception is: javax.activation.UnsupportedDataTypeException: no object DCH for MIME type multipart/mixed; boundary="----=_Part_5_17758761.1325668486851" at javax.mail.MessagingException: IOException while sending message at at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1141) at at javax.mail.Transport.send0(Transport.java:195) at at javax.mail.Transport.send(Transport.java:124) at at ch.qos.logback.core.net.SMTPAppenderBase.sendBuffer(SMTPAppenderBase.java:343) at at ch.qos.logback.core.net.SMTPAppenderBase.append(SMTPAppenderBase.java:179) at at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85) at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at at ch.qos.logback.classic.Logger.error(Logger.java:610) at at de.sgbs.log.Activator.start(Activator.java:37) at at org.apache.felix.framework.util.SecureAction.startActivator(SecureAction.java:629) ... Caused by: javax.activation.UnsupportedDataTypeException: no object DCH for MIME type multipart/mixed; boundary="----=_Part_5_17758761.1325668486851" at at javax.activation.ObjectDataContentHandler.writeTo(DataHandler.java:877) at at javax.activation.DataHandler.writeTo(DataHandler.java:302) at at javax.mail.internet.MimeBodyPart.writeTo(MimeBodyPart.java:1476) at at javax.mail.internet.MimeMessage.writeTo(MimeMessage.java:1772) at at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1099) at ... 47 common frames omitted 10:14:47,049 |-INFO in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - SMTPAppender [EMAIL] is tracking [1] buffers First I thought MIME type multipart/mixed is the cause. I checked my SMTP Server Settings, sending email is ok. I tried googlemail. It's working too. I found another https://bugs.eclipse.org/bugs/show_bug.cgi?id=322398 resource with the same error message. Could it be an classloader problem? Could someone help me to pinpoint the problem? Thanks in advance. -- View this message in context: http://old.nabble.com/SMTPAppender-OSGi-Problem-within-Glassfish-v3.1.1-%28… Sent from the Logback User mailing list archive at Nabble.com.

2 2

logback in WebLogic 11g/12c
by Thai Dang Vu 02 Jan '12

02 Jan '12

Hi All, My application is in an exploded EAR directory which has a war and a jar module. Its directory structure can be seen in the attached fig1.png (where log4j and commons-logging are used) and fig4.png (where logback is used). The application.xml is in fig2.png. The log4j.properties and logback.xml are in the jar module so that other modules (war, ejb) can use it. The servlet (fig3.png) writes to the log. The application works fine with log4j, but nothing is printed out in case of logback. The application is in again.zip. The exploded EAR directory can be generated with running "mvn clean package" in the root directory. Does anybody know where I'm wrong with logback? Regards.

1 0