November 2012 - logback-user

How to change the underlying buffer size of BufferedOutputStream used by logback's FileAppender?
by Tim Shi 23 Nov '12

23 Nov '12

Hi, We are using logback as our logging framework. We noticed that the FileAppender uses ResilientFileOutputStream which is backed by an BufferedOutputStream. We are wondering if there's a way to configure the buffer size of this BufferedOutputStream instance so that we can tune the performance of logback. Thanks, Tim

1 0

Logging uncaught exceptions that go to server.log
by Pegram, David 20 Nov '12

20 Nov '12

Greetings! I have a web app built with Maven I've added Logback to handle the logging with two rolling file appenders. Unfortunately, some exceptions (below) still bubble up to the server.log and are not captured in the logback generated files. How can I capture these with logback and keep them out of server.log? 15:46:41,888 SEVERE [javax.enterprise.resource.webcontainer.jsf.context] (http-) JSF1073: javax.faces.event.AbortProcessingException caught during processing of PROCESS_VALIDATIONS 3 : UIComponent-ClientId=templateForm:ddlCarrierView, Message=/foo/bar.xhtml @144,91 valueChangeListener="#{BackingBean.method}": java.lang.NullPointerException 15:46:41,889 SEVERE [javax.enterprise.resource.webcontainer.jsf.context] (http-) /foo/bar.xhtml @144,91 valueChangeListener="#{BackingBean.method}": java.lang.NullPointerException: javax.faces.event.AbortProcessingException: /foo/bar.xhtml @144,91 valueChangeListener="#{BackingBean.method}": java.lang.NullPointerException at javax.faces.event.MethodExpressionValueChangeListener.processValueChange(MethodExpressionValueChangeListener.java:157) [jboss-jsf-api_2.1_spec-2.0.2.Final-redhat-1.jar:2.0.2.Final-redhat-1] ... Caused by: java.lang.NullPointerException at my.app.BackingBean.method(BackingBean.java:298) [classes:] ... Below are the relevant configuration pieces. Thank you for your help! - D. Pegram pom.xml: <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.0.7</version> </dependency> Logback.xml: <?xml version="1.0" ?> <configuration debug="true"> <appender class="ch.qos.logback.core.rolling.RollingFileAppender" name="InfoFileAppender"> <append>true</append> <file>${jboss.server.log.dir}/maApp.log</file> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>INFO</level> </filter> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>${jboss.server.log.dir}/myApp.%d{yyyy-MM-dd}.gz</fileNamePattern> <maxHistory>30</maxHistory> </rollingPolicy> <encoder> <pattern>%date, %level, %logger, Account: %X{accountId} Session: %X{sessionId} %msg %ex%n</pattern> </encoder> </appender> <appender class="ch.qos.logback.core.rolling.RollingFileAppender" name="DebugFileAppender"> <append>true</append> <file>${jboss.server.log.dir}/myApp-debug.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>${jboss.server.log.dir}/myApp-debug.%d{yyyy-MM-dd}.gz</fileNamePattern> <maxHistory>30</maxHistory> </rollingPolicy> <encoder> <pattern> %date, %level, %thread, %logger, %class, %method, %line: Account: %X{accountId} Session: %X{sessionId} %msg %ex%n </pattern> </encoder> </appender> <root> <level value="debug" /> <appender-ref ref="InfoFileAppender" /> <appender-ref ref="DebugFileAppender" /> </root> </configuration> ________________________________ The contents contained herein may contain confidential information. If you are not the intended recipient, you are hereby notified that any disclosure, copying, distribution, printing or action taken on the contents is strictly prohibited. If you have received this email in error, please notify the sender immediately and delete this message.

2 1

ReconfigureOnChangeFilter throws ConcurrentModificationException when launching up.
by Zhangguangchao 20 Nov '12

20 Nov '12

Hi, I met ConcurrentModificationException exception when launching my app. Here is the stack : 2012-11-20 11:37:07,020|ERROR|osgi_launcher>Exception in thread "Thread-21" java.util.ConcurrentModificationException 2012-11-20 11:37:07,034|ERROR|osgi_launcher> at java.util.AbstractList$Itr.checkForComodification(AbstractList.java:372) 2012-11-20 11:37:07,034|ERROR|osgi_launcher> at java.util.AbstractList$Itr.next(AbstractList.java:343) 2012-11-20 11:37:07,034|ERROR|osgi_launcher> at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:375) 2012-11-20 11:37:07,035|ERROR|osgi_launcher> at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:220) 2012-11-20 11:37:07,035|ERROR|osgi_launcher> at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter$ReconfiguringThread.run(ReconfigureOnChangeFilter.java:157) My circumstance is as follows : Suse 11 + felix3.2 + slf4j1.6.1 + logback0.9.28. Of course, this exception is not thrown every time. After reading the source code, I think perhaps here is the point. When my app is first launched, logback.xml will be modified by app asynchronizingly. At the same time, the logback.xml is configured by JoranConfigurator. Then that's the point. So I think the childrenList in ch.qos.logback.classic. Logger should be synchronized accessed. Right? This problem cause the log record is not logged into log file sometimes. Does this exception affect the logging? Thanks for your response.

1 0

SizeAndTimeBasedArchiveRemover: Unexpected periodsElapsed value 0
by Gaurav Kumar 19 Nov '12

19 Nov '12

Hi, I am seeing the following error when rollover happens (this keeps coming continuously on stdout/err): *20:25:38,351 |-WARN in c.q.l.co.rolling.helper.RenameUtil - Failed to rename file [D:\test.log] to [D:\test.2012-11-08.202336641.log]. ... 20:25:38,351 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@6d3374 - Unexpected periodsElapsed value 0 * I am using RollingFileAppender with TimeBasedRollingPolicy and trigger is timeBasedFileNamingAndTriggeringPolicy with class="MyOwnSizeAndTimeBasedFNATP" defined as: @NoAutoStart public class MyOwnSizeAndTimeBasedFNATP<E> extends SizeAndTimeBasedFNATP<E> { private final AtomicBoolean trigger = new AtomicBoolean(); @Override public boolean isTriggeringEvent(final File activeFile, final E event) { if (trigger.compareAndSet(false, true) && activeFile.length() > 0) { String maxFileSize = getMaxFileSize(); setMaxFileSize("1"); super.isTriggeringEvent(activeFile, event); setMaxFileSize(maxFileSize); return true; } return super.isTriggeringEvent(activeFile, event); } Any suggestions on what could have gone wrong here? I tried to dig deeper into the logback code to identify the problem. I feel I am somehow entering RollingFileAppender's subAppend() multiple times or violating the synchronised behaviour as mentioned in the comment in the code. Any pointers please? Thanks!

1 4

ignoring logback.xml files embedded in other jars
by Sebastian Esponda 15 Nov '12

15 Nov '12

Hello, We are developing a web application that has its logging configuration under /classes. Unfortunately, we depend on another JAR (which we can't modify) which also has a its own logback.xml file. During the startup process logback detects and uses both files. Is there any way to set it up so that the one included in the JAR is ignored? Thanks,

4 4

SMTPAppender, HTMLLayout with text/plain
by Filipe Sousa 14 Nov '12

14 Nov '12

Hi. For some reason I'm receiving email reports with mime type text/plain and my email client shows all the html code. I'm attaching a report sent by logback. I'm using javax.mail 1.4.4 and this logback (1.0.3) configuration <?xml version="1.0" encoding="UTF-8"?> <configuration scan="true" scanPeriod="5000"> <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>../logs/sama.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern> <maxHistory>30</maxHistory> </rollingPolicy> <encoder> <pattern>%d [%thread] %-5level %logger{36} - %msg%n</pattern> </encoder> </appender> <appender name="mail" class="ch.qos.logback.classic.net.SMTPAppender"> <smtpHost>mail.ipb.pt</smtpHost> <to>filipe(a)ipb.pt</to> <from>noreply(a)ipb.pt</from> <subject>[sama]: %logger{20} - %m</subject> <layout class="ch.qos.logback.classic.html.HTMLLayout" /> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>WARN</level> </filter> </appender> <logger name="org.eclipse.jetty" level="WARN" /> <logger name="org.apache.cxf" level="WARN"/> <logger name="pt.ipb.sama" level="WARN" /> <root level="WARN"> <appender-ref ref="file" /> <appender-ref ref="mail"/> </root> </configuration> Thanks -- Filipe Sousa

2 1

Structured Logging with logback
by Moebius.Jonathan＠swm.de 14 Nov '12

14 Nov '12

Hello List, I would like to be able to automatically relate log-messages of different executions of my application. Goal of the exercise is to automatically detect certain tendencies within the application - for example detecting that fluctuating values are slowly but steadily approaching critical barriers. To do so, I would like to employ two appenders, one file-appender for a superficial check whether the application run ok and one (automatic) in depth analysis whether there are any problems lingering beyond the horizon. My initial idea was to employ MDCs for this, however, that seems rather odd, because MDCs are bound to the log-invoking thread and thus my code would look a lot like MDC.put(key, value); log.info(...); MDC.remove(key); which can't be right. So my idea was to enforce a certain pattern in the logmessages, say <message>::<key>=<value>;<key>=<value>... . With this format (and given a custom db-appender) messages could be written into a database in a way were the intended datamining is possible. Next comes the idea, how to force the application developer to adhere to this pattern? Ideally, there would be a Logger.info(msg, param[]) method, where the params are appended to the message not according to the curly braces but according to the abovementioned pattern. This method - of course - does not exist. I thought about writing a Logger-wrapper which enforces abovementioned message-format, but that would ruin the method/line detection of Class CallerData, as the FQCN property in the Logger cannot be set from the outside. So I dug out the big irons and tried to inherit from ch.qos.logback.classic.Logger, which does not work, because this class is final. Comes the even bigger iron of reflection... You can see that this is heading in a very wrong direction. So, am I really the only one trying to log auto-analysable data or did I miss something out? Is it even something which could/should be included in the standard? Could/should I simply abuse the param-array of the LoggingEvent Object in a custom appender, instead of using LoggingEvent.getFormattedMessage()? Kind regards, Jonathan

1 0

Rolling policy with overlapping logs
by DTBFNATP 13 Nov '12

13 Nov '12

I need to configure logback to do the following: Write a log file to a directory, target1/ At 1am each day, move this file to another directory, target2/ (add a timestamp to the file, not tar'ed, not zip'ed) A new logfile should begin in target1/ but not from 1am, rather it should begin from midnight the hour before. Hence the two logfiles in target1/ and target2/ shall have ovelapping logs from midnight to 1am each day Any suggestions to do this with configuration would be appreciated. Or writing a custom appender is a possibility. I looked at this briefly, but was caught in a few places by package protected properties without public accessors. Thanks in advance! -- View this message in context: http://old.nabble.com/Rolling-policy-with-overlapping-logs-tp34668953p34668… Sent from the Logback User mailing list archive at Nabble.com.

1 0

Syslog Appender: Short Host Name
by Luke Bond 13 Nov '12

13 Nov '12

The 3rd party tool that collects and analyzes (syslog) logs is strictly working in a general syslog layout: Nov 12 16:19:57 hostname username: ERROR ..message.. where the hostname should not be FQDN, but a short name one instead. For example, instead of "thisserver.xyz.mars" it should just be a "thisserver". In fact logging from a shell using a "logger" results in a a short host name by default. Logback uses a Syslog Converter ( http://www.jarvana.com/jarvana/view/ch/qos/logback/logback-classic/0.9.3/lo… SyslogStartConverter ) which looks up the host as: InetAddress.getLocalHost().getHostName() This returns a FQDN, which breaks the syslog monitor (since it expects it to be in a short hostname form). What would be the way to inject my own "SyslogStartConverter" into a Syslog Appender? Or maybe there is a better/simpler solution that allows to overwrite this in some way? Thank you! -- View this message in context: http://old.nabble.com/Syslog-Appender%3A-Short-Host-Name-tp34675141p3467514… Sent from the Logback User mailing list archive at Nabble.com.

1 0

logback configuration variable substitution: Exception during parsing (NumberFormatException)
by Gerrit Hübbers 13 Nov '12

13 Nov '12

In my environment, there are OS environment variables called OPENSHIFT_DB_HOST and OPENSHIFT_DB_PORT. These variables can be used to build the address pointing to a MySQL server. Both variables have sensible values (e.g. OPENSHIFT_DB_HOST = 127.0.0.1 .... OPENSHIFT_DB_PORT = 3306 ) In a logback XML configuration file, I'm configuring a DBAppender. I'm using logback's variable substitution in the following line. <url>jdbc:mysql://${OPENSHIFT_DB_HOST}:${OPENSHIFT_DB_PORT}/mydb?useUnicode=true&characterEncoding=UTF-8</url> As you can see, I'm using both OS environment variables to build the address, separated by a colon (":"). The resulting URL should therefore look like "jdbc:mysql://127.0.0.1:3306/mydb?useUnicode=true&characterEncoding=UTF-8" When logback parses my logback XML configuration file, I get the following exception: ~~~Begin: Exception stack trace~~~ 18:44:06,288 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.db.DBAppender] 18:44:06,299 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [db] 18:44:07,180 |-WARN in ch.qos.logback.core.db.DataSourceConnectionSource@12c662b - Could not get a connection to discover the dialect to use. com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Cannot load connection class because of underlying exceptio n: 'java.lang.NumberFormatException: For input string: "${OPENSHIFT_DB_PORT}"'. at com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Cannot load connection class because of underlying exception: 'java.lang.NumberFormatException: For input string: "${OPENSHIFT_DB_PORT}"'. at at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at at java.lang.reflect.Constructor.newInstance(Constructor.java:525) at at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at at com.mysql.jdbc.Util.getInstance(Util.java:386) at at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1014) at at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:988) at at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:974) at at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919) at at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:343) at at com.mysql.jdbc.jdbc2.optional.MysqlDataSource.getConnection(MysqlDataSource.java:443) at at com.mysql.jdbc.jdbc2.optional.MysqlDataSource.getConnection(MysqlDataSource.java:141) at at com.mysql.jdbc.jdbc2.optional.MysqlDataSource.getConnection(MysqlDataSource.java:111) at at ch.qos.logback.core.db.DataSourceConnectionSource.getConnection(DataSourceConnectionSource.java:72) at at ch.qos.logback.core.db.DataSourceConnectionSource.start(DataSourceConnectionSource.java:46) at at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:167) at at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:318) at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:197) at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:183) at at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:157) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:143) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:106) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:56) at at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75) at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148) at at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84) at at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:54) at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128) at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107) at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295) at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:269) at at org.eclipse.jetty.util.log.Slf4jLog.<init>(Slf4jLog.java:38) at at org.eclipse.jetty.util.log.Slf4jLog.<init>(Slf4jLog.java:32) at at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at at java.lang.reflect.Constructor.newInstance(Constructor.java:525) at at java.lang.Class.newInstance0(Class.java:372) at at java.lang.Class.newInstance(Class.java:325) at at org.eclipse.jetty.util.log.Log.initialized(Log.java:161) at at org.eclipse.jetty.util.log.Log.getLogger(Log.java:435) at at org.eclipse.jetty.util.log.Log.getLogger(Log.java:425) at at org.eclipse.jetty.xml.XmlConfiguration.<clinit>(XmlConfiguration.java:72) at at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at at java.lang.reflect.Method.invoke(Method.java:601) at at org.eclipse.jetty.start.Main.invokeMain(Main.java:468) at at org.eclipse.jetty.start.Main.start(Main.java:616) at at org.eclipse.jetty.start.Main.main(Main.java:92) Caused by: java.lang.NumberFormatException: For input string: "${OPENSHIFT_DB_PORT}" at at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) at at java.lang.Integer.parseInt(Integer.java:481) at at java.lang.Integer.parseInt(Integer.java:527) at at com.mysql.jdbc.NonRegisteringDriver.port(NonRegisteringDriver.java:866) at at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:334) at ... 41 common frames omitted ~~~End: Exception stack trace~~~ As you can see, logback seems to have not substituted the second variable called ${OPENSHIFT_DB_PORT}, and instead took the raw string "${OPENSHIFT_DB_PORT}" to pass it to the underlying URL parser. Can it be that * logback has problems substituting two (and more?) variables in a single expression? * logback has problems when two variables are separated by a colon? Cheers

2 2