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 "Dimitry Declercq (JIRA)" <ji...@apache.org> on 2013/11/12 13:25:19 UTC

[jira] [Comment Edited] (LOG4J2-449) JDBCDatabaseManager not closing timed-out connection

    [ https://issues.apache.org/jira/browse/LOG4J2-449?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13820057#comment-13820057 ] 

Dimitry Declercq edited comment on LOG4J2-449 at 11/12/13 12:25 PM:
--------------------------------------------------------------------

Need to work on my JIRA Search Skills, this behaviour is described as well in issue LOG4J2-407 (with more attention to the log4j code)
Any progress? This is quite important for us...



was (Author: dredalious):
Need to work on my JIRA Search Skills, this behaviour is describe as well in issue LOG4J2-407
Any progress? This is quite important for us...


> JDBCDatabaseManager not closing timed-out connection
> ----------------------------------------------------
>
>                 Key: LOG4J2-449
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-449
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 2.0-beta9
>         Environment: Jetty 9.0.6 with JNDI (jdbc/logging) through BoneCP 0.8.0-RELEASE with MySQL Connector/J 5.1.26
>            Reporter: Dimitry Declercq
>
> Using the config below we receive following error when writing to DB after a few days of inactivity. 
> Assume 2 Applications and a configured connection pool (BoneCP 30m idle timeout, mysql wait_timeout=8h) accessed by 'jdbc/logging'
> - App 1 logs frequently (every 5 minutes)
> - App 2 logs only errors (1-2 a week)
> App 1 works fine, no errors, logs are written to database
> App 2 shows trouble when logging errors more than 1 day after deploy
> Error:
> {code}
> ERROR Unable to write to database [jdbcManager{ description=databaseAppender, bufferSize=0, connectionSource=dataSource{ name=java:/comp/env/jdbc/logging, value=JDBC URL = jdbc:mysql://host1,host2/logging?failOverReadOnly=false&amp;secondsBeforeRetryMaster=60, Username = <<removed>>, partitions = 1, max (per partition) = 10, min (per partition) = 2, idle max age = 30 min, idle test period = 5 min, strategy = DEFAULT }, tableName=application_log, columns=[ { name=host, layout=acc-appserver-1, literal=null, timestamp=false }, { name=context, layout=/websocket, literal=null, timestamp=false }, { name=eventDate, layout=null, literal=null, timestamp=true }, { name=level, layout=%level, literal=null, timestamp=false }, { name=class, layout=%c, literal=null, timestamp=false }, { name=message, layout=%message, literal=null, timestamp=false }, { name=exception, layout=%ex{full}, literal=null, timestamp=false } ] }] for appender [databaseAppender]. java.lang.reflect.UndeclaredThrowableException
>         at com.sun.proxy.$Proxy33.setNString(Unknown Source)
>         at com.jolbox.bonecp.PreparedStatementHandle.setNString(PreparedStatementHandle.java:472)
>         at org.apache.logging.log4j.core.appender.db.jdbc.JDBCDatabaseManager.writeInternal(JDBCDatabaseManager.java:93)
>         at org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:136)
>         at org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:103)
>         at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
>         at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
>         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
>         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
>         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
>         at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
>         at org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
>         at org.slf4j.impl.SLF4JLogger.warn(SLF4JLogger.java:333)
>         at com.lynx.websocket.gateway.GatewayMessageProcessor.handleMessage(GatewayMessageProcessor.java:34)
>         at com.lynx.websocket.queue.WebSocketConsumer.handleMessage(WebSocketConsumer.java:47)
>         at com.lynx.queue.consumer.QueueConsumer.handleDelivery(QueueConsumer.java:75)
>         at com.rabbitmq.client.impl.ConsumerDispatcher$4.run(ConsumerDispatcher.java:121)
>         at com.rabbitmq.client.impl.ConsumerWorkService$WorkPoolRunnable.run(ConsumerWorkService.java:76)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:724)
> Caused by: java.lang.reflect.InvocationTargetException
>         at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:606)
>         at com.jolbox.bonecp.MemorizeTransactionProxy.invoke(MemorizeTransactionProxy.java:233)
>         ... 21 more
> Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
>         at sun.reflect.GeneratedConstructorAccessor292.newInstance(Unknown Source)
>         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
>         at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
>         at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
>         at com.mysql.jdbc.Util.getInstance(Util.java:386)
>         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
>         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989)
>         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:975)
>         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:920)
>         at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:461)
>         at com.mysql.jdbc.PreparedStatement.setNString(PreparedStatement.java:5316)
>         ... 25 more
> {code}
> Config:
> {code}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration>
>     <Properties>
>         <Property name="applicationName">${web:contextPath}</Property>
>         <Property name="host">${web:hostName}</Property>
>     </Properties>
>     <Appenders>
>        <JDBC name="databaseAppender" tableName="logging_table">
>             <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
>             <DataSource jndiName="java:/comp/env/jdbc/logging"/>
>             <Column name="host" pattern="${host}"/>
>             <Column name="context" pattern="${applicationName}"/>
>             <Column name="eventDate" isEventTimestamp="true"/>
>             <Column name="level" pattern="%level"/>
>             <Column name="class" pattern="%c"/>
>             <Column name="message" pattern="%message"/>
>             <Column name="exception" pattern="%ex{full}"/>
>         </JDBC>
>     </Appenders>
>     <Loggers>
>         <Logger name="com.lynx" level="TRACE"/>
>         <Root level="WARN">
>             <AppenderRef ref="applicationLog"/>
>             <AppenderRef ref="databaseAppender"/>
>         </Root>
>     </Loggers>
> </Configuration>
> {code}
> After a quick look at the code I think the connection is retrieved and opened upon application start. Would there be a possibility to either retrieves connections from the pool when the actual on log event occurs or to reconnect in case of connection problems?



--
This message was sent by Atlassian JIRA
(v6.1#6144)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org