Log4j 2
  1. Log4j 2
  2. LOG4J2-676

Failed to write log event to CouchDB due to error: Connection pool shut down

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: None
    • Component/s: Appenders
    • Environment:

      Description

      I'm trying to setup a NoSQL logger using Apache CouchDB. After logging a single message, the logger fails with the following exception:


      2014-06-22 10:22:18,590 ERROR An exception occurred processing Appender databaseAppender org.apache.logging.log4j.core.appender.AppenderLoggingException: Failed to write log event to CouchDB due to error: Connection pool shut down
      at org.apache.logging.log4j.core.appender.db.nosql.couchdb.CouchDBConnection.insertObject(CouchDBConnection.java:57)
      at org.apache.logging.log4j.core.appender.db.nosql.NoSQLDatabaseManager.writeInternal(NoSQLDatabaseManager.java:148)
      at org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:159)
      at org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:103)
      at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
      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:367)
      at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
      at org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:577)
      at be.pw999.kbomap.controller.KboMapController.getJson(KboMapController.java:65)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:601)
      at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
      at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:125)
      at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:195)
      at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:91)
      at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:346)
      at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:341)
      at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:101)
      at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:224)
      at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
      at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
      at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
      at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
      at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
      at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
      at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:198)
      at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:946)
      at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:323)
      at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:372)
      at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:335)
      at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:218)
      at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
      at org.apache.logging.log4j.core.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:66)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
      at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
      at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:174)
      at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:357)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:260)
      at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:188)
      at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:191)
      at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:168)
      at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:189)
      at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
      at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
      at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
      at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
      at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
      at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
      at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
      at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:564)
      at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:544)
      at java.lang.Thread.run(Thread.java:722)
      Caused by: java.lang.IllegalStateException: Connection pool shut down
      at org.apache.http.util.Asserts.check(Asserts.java:34)
      at org.apache.http.pool.AbstractConnPool.lease(AbstractConnPool.java:169)
      at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.requestConnection(PoolingHttpClientConnectionManager.java:217)
      at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:158)
      at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
      at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
      at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
      at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:186)
      at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
      at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
      at org.lightcouch.CouchDbClientBase.executeRequest(CouchDbClientBase.java:409)
      at org.lightcouch.CouchDbClientBase.put(CouchDbClientBase.java:517)
      at org.lightcouch.CouchDbClientBase.save(CouchDbClientBase.java:273)
      at org.apache.logging.log4j.core.appender.db.nosql.couchdb.CouchDBConnection.insertObject(CouchDBConnection.java:51)
      ... 66 more]]

      The log4j2.xml file is:

      <?xml version="1.0" encoding="UTF-8"?>
      <Configuration status="info">
        <Appenders>
          <NoSql name="databaseAppender">
            <CouchDb databaseName="kbomaplog" protocol="http" server="127.0.0.1" port="5984"
                     username="loguser" password="meh" />
          </NoSql>
        </Appenders>
        <Loggers>
          <Root level="info">
            <AppenderRef ref="databaseAppender"/>
          </Root>
        </Loggers>
      </Configuration>
      

      And the piece of code I'm using to test is:

      	private Logger logger = LogManager.getLogger(KboMapController.class);
      	
      	/**
      	 * Does nothing special. Returns a simple JSON object with a count of the code table for testing purposes.
      	 * 
      	 * @param id unused
      	 * @param test unused
      	 * @return a JSON representation of the filled in {@link Enterprise} object.
      	 */
      	@GET
      	@Produces(MediaType.APPLICATION_JSON)
      	@Path("{id}/{test}")
      	public Enterprise getJson(@PathParam("id") String id, @PathParam("test") String test) {
      		try {
      			logger.error("whoaaaaaah");
      			return new Enterprise("SUCCESS", "COUNT=" + dao.count());
      		} catch (SQLException e) {
      			return new Enterprise("ERROR", e.getMessage());
      		}
      
      	}
      

      The same issue occurs when the logger is static final

        Activity

        Hide
        Matt Sicker added a comment -

        This could be related to LOG4J2-591.

        Show
        Matt Sicker added a comment - This could be related to LOG4J2-591 .
        Hide
        Matt Sicker added a comment -

        I believe this should be fixed as of revision 1604636 in the trunk. Could you verify this? It's not in RC2, but it would make it into RC3 or GA if it solves the problem!

        Show
        Matt Sicker added a comment - I believe this should be fixed as of revision 1604636 in the trunk. Could you verify this? It's not in RC2, but it would make it into RC3 or GA if it solves the problem!
        Hide
        Phillip added a comment - - edited

        I checked out both the current HEAD revision and revision 1604636 of the trunk and neither of them seem to work because of this error:

        [2014-06-26T19:08:44.913+0200] [glassfish 4.0] [INFO] [] [] [tid: _ThreadID=18 _ThreadName=Thread-3] [timeMillis: 1403802524913] [levelValue: 800] [[
          2014-06-26 19:08:44,913 ERROR Appenders contains an invalid element or attribute "NoSql"]]
        

        My current log4j2.xml file is

        log4j2.xml
        <?xml version="1.0" encoding="UTF-8"?>
        <Configuration status="info">
        	<Appenders>
        		<NoSql name="databaseAppender">
        			<CouchDb databaseName="kbomaplog" protocol="http" server="127.0.0.1"
        				port="5984" username="meh" password="meh" ignoreExceptions="false" />
        		</NoSql>
        		<!--RollingFile name="RollingFile" fileName="logs/kbomap.log"
        			filePattern="logs/app-%d{MM-dd-yyyy}.log.gz" ignoreExceptions="false">
        			<PatternLayout>
        				<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
        			</PatternLayout>
        			<TimeBasedTriggeringPolicy />
        		</RollingFile>
        		<Failover name="Failover" primary="databaseAppender">
        			<Failovers>
        				<AppenderRef ref="RollingFile" />
        			</Failovers>
        		</Failover-->
        	</Appenders>
        	<Loggers>
        		<Root level="info">
        			<AppenderRef ref="databaseAppender" />
        		</Root>
        	</Loggers>
        </Configuration>
        
        Show
        Phillip added a comment - - edited I checked out both the current HEAD revision and revision 1604636 of the trunk and neither of them seem to work because of this error: [2014-06-26T19:08:44.913+0200] [glassfish 4.0] [INFO] [] [] [tid: _ThreadID=18 _ThreadName=Thread-3] [timeMillis: 1403802524913] [levelValue: 800] [[ 2014-06-26 19:08:44,913 ERROR Appenders contains an invalid element or attribute "NoSql"]] My current log4j2.xml file is log4j2.xml <?xml version= "1.0" encoding= "UTF-8" ?> <Configuration status= "info" > <Appenders> <NoSql name= "databaseAppender" > <CouchDb databaseName= "kbomaplog" protocol= "http" server= "127.0.0.1" port= "5984" username= "meh" password= "meh" ignoreExceptions= " false " /> </NoSql> <!--RollingFile name= "RollingFile" fileName= "logs/kbomap.log" filePattern= "logs/app-%d{MM-dd-yyyy}.log.gz" ignoreExceptions= " false " > <PatternLayout> <Pattern>%d %p %c{1.} [%t] %m%n</Pattern> </PatternLayout> <TimeBasedTriggeringPolicy /> </RollingFile> <Failover name= "Failover" primary= "databaseAppender" > <Failovers> <AppenderRef ref= "RollingFile" /> </Failovers> </Failover--> </Appenders> <Loggers> <Root level= "info" > <AppenderRef ref= "databaseAppender" /> </Root> </Loggers> </Configuration>
        Hide
        Phillip added a comment - - edited

        This issue exists since rc2. I'll create a bug for it if it doesn't exist yet.
        //edit: Bug LOG4J2-691 was created for this issue.

        Show
        Phillip added a comment - - edited This issue exists since rc2. I'll create a bug for it if it doesn't exist yet. //edit: Bug LOG4J2-691 was created for this issue.
        Hide
        Phillip added a comment -

        Verified with trunk revision 1604636 that this bug is fixed.

        Show
        Phillip added a comment - Verified with trunk revision 1604636 that this bug is fixed.

          People

          • Assignee:
            Unassigned
            Reporter:
            Phillip
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development