8 Replies Latest reply on Oct 20, 2011 12:00 PM by matukituki

    Log4j JDBC log appender datasource not bound

    matukituki

      Hi,

       

      I'm trying to configure a custom jdbc log appender in the conf/jboss-log4j.xml file.

      The problem I'm getting is datasource not bound.

       

      Here is the relevant part of my jboss-log4j.xml file:

       

      <appender name="SMTT-JDBC" class="com.smartmatic.log.SMTTAppender">
                      <errorHandler class="org.apache.log4j.varia.FallbackErrorHandler">
                              <appender-ref ref="FILE"/>
                      </errorHandler>
                      <param name="Threshold" value="INFO"/>
                      <param name="DataSourceJNDIName" value="java:LOG_DS"/>
      
                      <layout class="org.apache.log4j.PatternLayout">
                              <param name="ConversionPattern"
                                      value="INSERT INTO LOG
                                      (LOG_CODE, LOG_DATE, CATEGORY, DESCRIPTION, PRIORITY, LOG_SESSION_ID, IP_SERVER, ERROR_CODE, USER_CODE, WILDCARD1, WILDCARD2, WILDCARD3, APPL_NUMBER)
                                      VALUES
                                      (S_LOG.NEXTVAL, to_date('%d{yyyy-MM-dd HH:mm:ss}', 'yyyy-mm/-dd hh24:mi:ss'), '%c', '%m', '%p', '%X{SMTTsessionId}', '%X{SMTTaddress}', '%X{SMTTmessageCode}', '%X{SMTTclientCode}', '%X{SMTTwildcard1}', '%X{SMTTwildcard2}', '%X{SMTTwildcard3}', 8)" />
                      </layout>
         </appender>
      

       

      And here is a part of the stacktrace error I'm getting:

       

      09:46:22,768 INFO  [JMXKernel] Legacy JMX core initialized

      09:46:23,864 INFO  [ProfileServiceBootstrap] Loading profile: ProfileKey@53c7378f[domain=default, server=default, name=ems]

      09:46:24,942 INFO  [WebService] Using RMI server codebase: http://127.0.0.1:8083/

      09:46:24,961 ERROR [STDERR] There is a problem obtaining the configured datasource

      ERROR: invalid console appender config detected, console stream is looping09:46:24,963 ERROR [STDERR] javax.naming.NameNotFoundException: LOG_DS not bound

      09:46:24,967 ERROR [STDERR]     at org.jnp.server.NamingServer.getBinding(NamingServer.java:771)

      09:46:24,973 ERROR [STDERR]     at org.jnp.server.NamingServer.getBinding(NamingServer.java:779)

      09:46:24,979 ERROR [STDERR]     at org.jnp.server.NamingServer.getObject(NamingServer.java:785)

      09:46:24,986 ERROR [STDERR]     at org.jnp.server.NamingServer.lookup(NamingServer.java:443)

      09:46:24,993 ERROR [STDERR]     at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:726)

      09:46:25,000 ERROR [STDERR]     at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:686)

      09:46:25,009 ERROR [STDERR]     at javax.naming.InitialContext.lookup(InitialContext.java:409)

      09:46:25,019 ERROR [STDERR]     at com.smartmatic.log.SMTTAppender.getConnection(SMTTAppender.java:77)

      09:46:25,028 ERROR [STDERR]     at com.smartmatic.log.SMTTAppender.execute(SMTTAppender.java:147)

      09:46:25,040 ERROR [STDERR]     at org.apache.log4j.jdbc.JDBCAppender.flushBuffer(JDBCAppender.java:250)

      09:46:25,052 ERROR [STDERR]     at org.apache.log4j.jdbc.JDBCAppender.append(JDBCAppender.java:146)

      09:46:25,063 ERROR [STDERR]     at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)

      09:46:25,074 ERROR [STDERR]     at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)

      09:46:25,086 ERROR [STDERR]     at org.apache.log4j.Category.callAppenders(Category.java:203)

      09:46:25,098 ERROR [STDERR]     at org.apache.log4j.Category.forcedLog(Category.java:388)

      09:46:25,104 ERROR [STDERR]     at org.apache.log4j.Category.log(Category.java:853)

      09:46:25,112 ERROR [STDERR]     at org.jboss.logging.log4j.Log4jLoggerPlugin.info(Log4jLoggerPlugin.java:184)

      09:46:25,120 ERROR [STDERR]     at org.jboss.logging.Logger.info(Logger.java:296)

      09:46:25,156 ERROR [STDERR]     at org.jboss.web.WebService.createService(WebService.java:309)

      09:46:25,163 ERROR [STDERR]     at org.jboss.system.ServiceMBeanSupport.jbossInternalCreate(ServiceMBeanSupport.java:344)

      09:46:25,170 ERROR [STDERR]     at org.jboss.system.ServiceMBeanSupport.jbossInternalLifecycle(ServiceMBeanSupport.java:320)

      09:46:25,178 ERROR [STDERR]     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

      09:46:25,185 ERROR [STDERR]     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

      09:46:25,193 ERROR [STDERR]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

      09:46:25,202 ERROR [STDERR]     at java.lang.reflect.Method.invoke(Method.java:616)

      09:46:25,210 ERROR [STDERR]     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)

      09:46:25,222 ERROR [STDERR]     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)

      09:46:25,232 ERROR [STDERR]     at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)

      09:46:25,241 ERROR [STDERR]     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)

      09:46:25,254 ERROR [STDERR]     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)

      09:46:25,266 ERROR [STDERR]     at org.jboss.system.microcontainer.ServiceProxy.invoke(ServiceProxy.java:189)

      09:46:25,278 ERROR [STDERR]     at $Proxy38.create(Unknown Source)

      09:46:25,288 ERROR [STDERR]     at org.jboss.system.microcontainer.CreateDestroyLifecycleAction.installAction(CreateDestroyLifecycleAction.java:42)

      09:46:25,299 ERROR [STDERR]     at org.jboss.system.microcontainer.CreateDestroyLifecycleAction.installAction(CreateDestroyLifecycleAction.java:37)

      09:46:25,311 ERROR [STDERR]     at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62)

      09:46:25,323 ERROR [STDERR]     at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71)

      09:46:25,334 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51)

      09:46:25,347 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)

      09:46:25,363 ERROR [STDERR]     at org.jboss.system.microcontainer.ServiceControllerContext.install(ServiceControllerContext.java:286)

      09:46:25,386 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)

      09:46:25,398 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)

      09:46:25,411 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)

      09:46:25,425 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)

      09:46:25,438 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)

      09:46:25,452 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)

      09:46:25,466 ERROR [STDERR]     at org.jboss.system.ServiceController.doChange(ServiceController.java:688)

      09:46:25,482 ERROR [STDERR]     at org.jboss.system.ServiceController.create(ServiceController.java:422)

      09:46:25,497 ERROR [STDERR]     at org.jboss.system.ServiceController.create(ServiceController.java:387)

      09:46:25,512 ERROR [STDERR]     at org.jboss.system.deployers.ServiceDeployer.create(ServiceDeployer.java:158)

      09:46:25,527 ERROR [STDERR]     at org.jboss.system.deployers.ServiceDeployer.deploy(ServiceDeployer.java:96)

      09:46:25,542 ERROR [STDERR]     at org.jboss.system.deployers.ServiceDeployer.deploy(ServiceDeployer.java:46)

      09:46:25,562 ERROR [STDERR]     at org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer.internalDeploy(AbstractSimpleRealDeployer.java:62)

      09:46:25,577 ERROR [STDERR]     at org.jboss.deployers.spi.deployer.helpers.AbstractRealDeployer.deploy(AbstractRealDeployer.java:50)

      09:46:25,593 ERROR [STDERR]     at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:171)

      09:46:25,609 ERROR [STDERR]     at org.jboss.deployers.plugins.deployers.DeployersImpl.doDeploy(DeployersImpl.java:1439)

      09:46:25,636 ERROR [STDERR]     at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1157)

      09:46:25,666 ERROR [STDERR]     at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1178)

      09:46:25,696 ERROR [STDERR]     at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:1098)

      09:46:25,727 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)

      09:46:25,757 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)

      09:46:25,788 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)

      09:46:25,816 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)

      09:46:25,838 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)

      09:46:25,860 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)

      09:46:25,889 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)

      09:46:25,907 ERROR [STDERR]     at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:781)

      09:46:25,925 ERROR [STDERR]     at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:702)

      09:46:25,943 ERROR [STDERR]     at org.jboss.system.server.profileservice.repository.MainDeployerAdapter.process(MainDeployerAdapter.java:117)

      09:46:25,967 ERROR [STDERR]     at org.jboss.system.server.profileservice.repository.ProfileDeployAction.install(ProfileDeployAction.java:70)

      09:46:25,986 ERROR [STDERR]     at org.jboss.system.server.profileservice.repository.AbstractProfileAction.install(AbstractProfileAction.java:53)

      09:46:26,005 ERROR [STDERR]     at org.jboss.system.server.profileservice.repository.AbstractProfileService.install(AbstractProfileService.java:361)

      09:46:26,024 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)

      09:46:26,043 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)

      09:46:26,063 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)

      09:46:26,083 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)

      09:46:26,103 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)

      09:46:26,123 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)

      09:46:26,144 ERROR [STDERR]     at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)

      09:46:26,165 ERROR [STDERR]     at org.jboss.system.server.profileservice.repository.AbstractProfileService.activateProfile(AbstractProfileService.java:306)

      09:46:26,189 ERROR [STDERR]     at org.jboss.system.server.profileservice.ProfileServiceBootstrap.start(ProfileServiceBootstrap.java:271)

      09:46:26,210 ERROR [STDERR]     at org.jboss.bootstrap.AbstractServerImpl.start(AbstractServerImpl.java:461)

      09:46:26,243 ERROR [STDERR]     at org.jboss.Main.boot(Main.java:221)

      09:46:26,265 ERROR [STDERR]     at org.jboss.Main$1.run(Main.java:556)

      09:46:26,287 ERROR [STDERR]     at java.lang.Thread.run(Thread.java:636)

       

      Here is the getConnection method of my custom jdbc appender:

       

      public class SMTTAppender extends JDBCAppender {
      
      /**
           * The configured jndi datasource name.
           */
      
      public Connection getConnection() throws SQLException {
      
      
          private String dataSourceJNDIName;
      
              if (this.dataSource == null) {
                  if (this.getDataSourceJNDIName() == null) {
                      System.err
                              .println("There is not a datasource jndi name configured");
                      return null;
                  }
      
                  try {
                      Context context = new InitialContext();
                      this.dataSource = (DataSource) context.lookup(this
                              .getDataSourceJNDIName());
                  } catch (NamingException e) {
                      System.err
                              .println("There is a problem obtaining the configured datasource");
                      e.printStackTrace();
                      throw new SQLException(e);
                  }
              }
      
              try {
                  return this.dataSource.getConnection();
              } catch (SQLException e) {
                  System.err
                          .println("There is a problem obtaining the connection from the configured datasource");
                  e.printStackTrace();
                  throw e;
              }
          }
      ...
      

       

      I have to configure some file in order to the log appender wait until the datasource is bound?

       

      Any help would be appreciated.

      Regards.

        • 1. Re: Log4j JDBC log appender datasource not bound
          meme

          Have you tried java:jdbc/LOG_DS ?

          • 2. Re: Log4j JDBC log appender datasource not bound
            matukituki

            Hi.

            That's not the problem because before I added the jdbc appender to my log4j configuration, my datasource was bound to java:LOG_DS.

            Anyway, I have tried java:jdbc/LOG_DS but I got the same error.

            • 3. Re: Log4j JDBC log appender datasource not bound
              meme

              Ah, I think you run into trouble when starting the JBoss. The Logger (and your JDBC-Log-Appender) will be initialized and used before

              the datasources are bound. The logger-initialization will start when the server.log is generated, at this point there is no datasource available.

              • 4. Re: Log4j JDBC log appender datasource not bound
                matukituki

                Exactly, that's the problem, but it is possible. I have another application (another .ear file)  that it is deployed in another server context and it is working.

                In fact if I deployed the problematic application in the previous server's context folder it works.

                I have made a full comparison between the two servers context configuration files, but I have not found anything special.

                 

                Maybe it is by code that the precedence it is resolved. I have seen the code but I have found nothing.

                I thought this was a common problem when using jdbc appender but  I have been searching in the web

                and is not a common problem.

                • 5. Re: Log4j JDBC log appender datasource not bound
                  beubanks

                  I have a custom JDBC appender that gets its connection from JNDI, and it works fine. Mine datasource, however, does not use the Java context. Thus, my appender definition does not include the "java:" part in the JNDI name.

                   

                  Datasource:

                  {code:xml}  <local-tx-datasource>

                      <jndi-name>jdbc/example</jndi-name>

                      <use-java-context>false</use-java-context>

                      <!-- [SNIP] -->

                    </local-tx-datasource>{code}

                   

                  Appender Definition:

                  {code:xml}  <appender name="exampleAppender" class="com.example.ExampleAppender">

                      <param name="jndiName" value="jdbc/example" />

                    </appender>{code}

                   

                  This works fine for me.

                   

                  If that doesn't fix it, it sounds like it's getting called very early during server startup. Does the appender only fail the first few times it is called (before the DS is initialized properly), or does it fail every time? If it gets called before JBoss binds the datasource, maybe you should just print the exception to standard out the first time it fails (use a boolean to indicate first failure), return null (rather than throwing a new exception), and do not append anything. You'll only get one exception printed that way. Any append calls after JBoss binds the DS should succeed.

                  • 6. Re: Log4j JDBC log appender datasource not bound
                    matukituki

                    Hi.

                     

                    The appender fails when Jboss is parsing the jboss-log4j.xml configuration file that is performed just right when Jboss is starting and do not let the server continue the deployment because it enters in a loop trying to get the datasource.

                     

                    As I have mentioned in the previous post with the other server context folder and the other application is working. When I debug the working application, when jboss is started and the log configuration is read it, it prints by console the following line:

                     

                    INFO  [org.jboss.logbridge.LogNotificationListener] Adding notification listener for logging mbean "jboss.system:service=Logging,type=Log4jService" to server org.jboss.mx.server.MBeanServerImpl@7987b5ff[ defaultDomain='jboss' ]

                     

                    and then, later, when the datasources are bind, the getConnection method of my custom JDBC appender is invoked. But this not happend in that way when I deploy the other application in its server context folder using the same custom JDBC appender.

                     

                    I know it is weird and probably is an error I have in some place but I really don't know where it is.

                    • 7. Re: Log4j JDBC log appender datasource not bound
                      beubanks

                      Ah, yes, I think it makes perfect sense. Is the root logger using your appender? In my configuration, only my own applications are using it. Since they start after the datasources (and logger) are configured, the appender never gets called before the datasource is bound. Therefore, the appender never tries to retrieve an unbound datasource.

                       

                      Your stack trace shows that a JBoss class is resposible for the logger call:

                       

                      {code}09:46:25,156 ERROR [STDERR]   at org.jboss.web.WebService.createService(WebService.java:309){code}

                       

                       

                      It's probably just a JBoss service logging something during startup.

                       

                      Your getConnection() method throws an exception. Since it doesn't get caught by the appender, JBoss itself catches it and says, "Hey, an exception was thrown. I better log this." It tries to log it, and it happens all over again. Throwing an exception will just make it try to log the exception, and a broken logger trying to log that it's broken doesn't make sense.

                       

                      So ... change your getConnection() method. In the catch block, keep the e.printStackTrace(); line so that you'll have a record of the failure in the normal standard out log file. Then, return null rather than throwing a new SqlException(e). Just make sure that the code that calls getConnection() can handle a null connection. If the connection it gets back is null, it should just silently return from the append call.

                      • 8. Re: Log4j JDBC log appender datasource not bound
                        matukituki

                        Hey man thank you very much.

                         

                        That was the problem. I removed the JDBC appender from the root category and it worked fine.

                         

                        The getConnection method is throwing the SQLException because if the database it's not available the show must go on (in my application this could happen). In that case if a message could not be logged into the database, then it is logged in the server log file as is indicated by the FILE appender. That is performed by the errorHandler in the appender configuration. The FallbackErrorHandler class requires that the JDBC appender do not consume the Exception to manage the error and redirect the message to the referenced appender.

                         

                        Thanks again.