Log4j 2
  1. Log4j 2
  2. LOG4J2-126

Failover appender doesn't fail over on JMS Queue appender error

    Details

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

      Description

      My goal is to send log messages via a JMS Queue unless the message broker is down, when I simple want send the logs to the Console.

      I configured a failover appender for this purpose:
      :
      <appenders>

      ...

      <JMSQueue name="LiffLog4j2Queue" queueBindingName="Log4j2Queue" factoryBindingName="QueueConnectionFactory"/>
      <Failover name="FailoverLiffLog4j2Queue" primary="LiffLog4j2Queue" suppressExceptions="false">
      <Failovers>
      <appender-ref ref="Console"/>
      </Failovers>
      </Failover>
      </appenders>
      <loggers>
      <root level="debug">
      <appender-ref ref="FailoverLiffLog4j2Queue"/>
      </root>

      All works as expected when the message broker is up.

      When I shut down the message broker while running my application, instead of the log message I get this message to my console :
      2012-11-21 21:51:15,726 ERROR Could not publish message via JMS JMSQueue:QueueConnectionFactory.Log4j2Queue

      Using a failover appender I expected to get the log messages on the console.

      Also tried to start my application without ever starting message broker. In this case it correctly fails to connect :

      2012-11-21 22:10:08,315 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.JMSQueueAppender for element JMSQueue with params(name="LiffLog4j2Queue", factoryName="null", providerURL="null", urlPkgPrefixes="null", securityPrincipalName="null", securityCredentials="null", factoryBindingName="QueueConnectionFactory", queueBindingName="Log4j2Queue", userName="null", password="null", null, null, suppressExceptions="null")
      2012-11-21 22:10:10,167 ERROR Unable to establish connection javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616. Reason: java.net.ConnectException: Connection refused: connect
      at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:35)
      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:293)
      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:238)
      at org.apache.activemq.ActiveMQConnectionFactory.createQueueConnection(ActiveMQConnectionFactory.java:199)
      at org.apache.logging.log4j.core.net.JMSQueueManager$JMSQueueManagerFactory.createManager(JMSQueueManager.java:152)
      at org.apache.logging.log4j.core.net.JMSQueueManager$JMSQueueManagerFactory.createManager(JMSQueueManager.java:141)
      at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:68)
      at org.apache.logging.log4j.core.net.JMSQueueManager.getJMSQueueManager(JMSQueueManager.java:86)
      at org.apache.logging.log4j.core.appender.JMSQueueAppender.createAppender(JMSQueueAppender.java:94)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.apache.logging.log4j.core.config.BaseConfiguration.createPluginObject(BaseConfiguration.java:711)
      at org.apache.logging.log4j.core.config.BaseConfiguration.createConfiguration(BaseConfiguration.java:477)
      at org.apache.logging.log4j.core.config.BaseConfiguration.createConfiguration(BaseConfiguration.java:469)
      at org.apache.logging.log4j.core.config.BaseConfiguration.doConfigure(BaseConfiguration.java:156)
      at org.apache.logging.log4j.core.config.BaseConfiguration.start(BaseConfiguration.java:114)
      at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:251)
      at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:267)
      at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:134)
      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:75)
      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:30)
      at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:165)
      at com.szabi.experiment.gui.Liff.<clinit>(Liff.java:16)
      Caused by: java.net.ConnectException: Connection refused: connect
      at java.net.PlainSocketImpl.socketConnect(Native Method)
      at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
      at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
      at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
      at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
      at java.net.Socket.connect(Socket.java:529)
      at org.apache.activemq.transport.tcp.TcpTransport.connect(TcpTransport.java:504)
      at org.apache.activemq.transport.tcp.TcpTransport.doStart(TcpTransport.java:467)
      at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)
      at org.apache.activemq.transport.AbstractInactivityMonitor.start(AbstractInactivityMonitor.java:132)
      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
      at org.apache.activemq.transport.WireFormatNegotiator.start(WireFormatNegotiator.java:72)
      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
      at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:58)
      at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:273)
      ... 23 more

      2012-11-21 22:10:10,177 ERROR Unable to invoke method createAppender in class org.apache.logging.log4j.core.appender.JMSQueueAppender for element JMSQueue java.lang.reflect.InvocationTargetException
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.apache.logging.log4j.core.config.BaseConfiguration.createPluginObject(BaseConfiguration.java:711)
      at org.apache.logging.log4j.core.config.BaseConfiguration.createConfiguration(BaseConfiguration.java:477)
      at org.apache.logging.log4j.core.config.BaseConfiguration.createConfiguration(BaseConfiguration.java:469)
      at org.apache.logging.log4j.core.config.BaseConfiguration.doConfigure(BaseConfiguration.java:156)
      at org.apache.logging.log4j.core.config.BaseConfiguration.start(BaseConfiguration.java:114)
      at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:251)
      at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:267)
      at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:134)
      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:75)
      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:30)
      at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:165)
      at com.szabi.experiment.gui.Liff.<clinit>(Liff.java:16)
      Caused by: java.lang.IllegalStateException: Unable to create a manager
      at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:70)
      at org.apache.logging.log4j.core.net.JMSQueueManager.getJMSQueueManager(JMSQueueManager.java:86)
      at org.apache.logging.log4j.core.appender.JMSQueueAppender.createAppender(JMSQueueAppender.java:94)
      ... 16 more

      BUT shortly afterwards my application exits with :

      2012-11-21 22:10:10,238 ERROR Unable to locate primary Appender LiffLog4j2Queue
      2012-11-21 22:10:10,239 DEBUG Reconfiguration completed
      2012-11-21 22:10:10,277 ERROR Attempted to append to non-started appender FailoverLiffLog4j2Queue
      2012-11-21 22:10:10,288 ERROR Attempted to append to non-started appender FailoverLiffLog4j2Queue
      2012-11-21 22:10:10,292 DEBUG Shutting down FileManager output/experiment.log
      Exception in thread "main" org.apache.logging.log4j.core.appender.AppenderRuntimeException: Attempted to append to non-started appender FailoverLiffLog4j2Queue
      at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
      at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:335)

      As it can not find primary appender (JMSQueue) it can not start the failover appender either.

        Activity

        Hide
        Ralph Goers added a comment -

        The JMS Queue and Topic appenders will now initialize even if the queue or topic is unavailable and will retry the connection. Failover works as long as supressExceptions is set to false. Please verify and close.

        Show
        Ralph Goers added a comment - The JMS Queue and Topic appenders will now initialize even if the queue or topic is unavailable and will retry the connection. Failover works as long as supressExceptions is set to false. Please verify and close.
        Hide
        Szabolcs Beki added a comment -

        Thanks for the fix. I still have some doubt whether certain behavior is a feature or a bug.

        Currently it works the following way for me :

        Case 1 : JMS connection initially available, but later it goes down while the application is still running
        Failover appender works well and starts using the secondary appender (Console), and does NOT try to use primary appender any more
        Case 2 : JMS connection initially not available
        Failover appender works and starts using the secondary appender (Console), but also keep trying to initialize the primary appender (JMSQueue), at each log message.

        In case 1 it doesn't reinitialize the primary connection, but in case 2 it tries it all the time, and this causes a major setback in performance.

        I think in both cases the initialization of the primary appender should work the same way.

        Preferably, after the first attempt it should not try to initialize primary connection in any of the cases, only if there is a reconfiguration or an explicit flag set.

        Show
        Szabolcs Beki added a comment - Thanks for the fix. I still have some doubt whether certain behavior is a feature or a bug. Currently it works the following way for me : Case 1 : JMS connection initially available, but later it goes down while the application is still running Failover appender works well and starts using the secondary appender (Console), and does NOT try to use primary appender any more Case 2 : JMS connection initially not available Failover appender works and starts using the secondary appender (Console), but also keep trying to initialize the primary appender (JMSQueue), at each log message. In case 1 it doesn't reinitialize the primary connection, but in case 2 it tries it all the time, and this causes a major setback in performance. I think in both cases the initialization of the primary appender should work the same way. Preferably, after the first attempt it should not try to initialize primary connection in any of the cases, only if there is a reconfiguration or an explicit flag set.
        Hide
        Ralph Goers added a comment - - edited

        Actually, I suspect both case 1 and 2 are operating the same way. The difference is that when the connection is initially not available the appender tries to reconnect on every event. When the connection is initially available and fails it is not clearing the connection information and so keeps trying to send to the broken connection (which will fail) and then fails over to the failover.

        Show
        Ralph Goers added a comment - - edited Actually, I suspect both case 1 and 2 are operating the same way. The difference is that when the connection is initially not available the appender tries to reconnect on every event. When the connection is initially available and fails it is not clearing the connection information and so keeps trying to send to the broken connection (which will fail) and then fails over to the failover.
        Hide
        Szabolcs Beki added a comment -

        Yes, that's true. The real question is :

        Is it useful trying to reconnect on every event, when the appender initially is not available?

        In case of failing JMS queue appender initialization, the continuous reconnect attempts bog down the whole application and of course it does even make sense trying to reconnect after a few milliseconds.

        Show
        Szabolcs Beki added a comment - Yes, that's true. The real question is : Is it useful trying to reconnect on every event, when the appender initially is not available? In case of failing JMS queue appender initialization, the continuous reconnect attempts bog down the whole application and of course it does even make sense trying to reconnect after a few milliseconds.
        Hide
        Ralph Goers added a comment -

        I agree with you.

        I have modified the JMS appenders so that they always retry if the connection fails. I have modified the FailoverAppender so that once the primary fails it will not invoke it again until some configurable time has elapsed. The default is 60 seconds. Please check out the latest from trunk and confirm it is now working as expected.

        Show
        Ralph Goers added a comment - I agree with you. I have modified the JMS appenders so that they always retry if the connection fails. I have modified the FailoverAppender so that once the primary fails it will not invoke it again until some configurable time has elapsed. The default is 60 seconds. Please check out the latest from trunk and confirm it is now working as expected.
        Hide
        Szabolcs Beki added a comment -

        Thanks. Now, it works as I imagined.

        Show
        Szabolcs Beki added a comment - Thanks. Now, it works as I imagined.

          People

          • Assignee:
            Ralph Goers
            Reporter:
            Szabolcs Beki
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development