Announcement Announcement Module
Collapse
No announcement yet.
AmqpAppender is not sending messages to my queue Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • AmqpAppender is not sending messages to my queue

    Hi,

    I am using spring-rabbit 1.2.0.RELEASE and I have defined a AmqpAppender in log4j.xml as shown below.

    Code:
    <?xml version="1.0" encoding="UTF-8" ?>
    <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
    
    <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    
    	<appender name="console" class="org.apache.log4j.ConsoleAppender">
    		<param name="Target" value="System.out" />
    		<layout class="org.apache.log4j.PatternLayout">
    			<param name="ConversionPattern" value="%-5p %c{1} - %m%n" />
    		</layout>
    	</appender>
        
        <!-- Complete Logger -->
    	<appender name="amqp" class="org.springframework.amqp.rabbit.log4j.AmqpAppender">
    		<param name="host" value="idv-dev-java02" />
    		<param name="port" value="5672" />
    		<param name="virtualHost" value="platform" />
    		<param name="username" value="username" />
    		<param name="password" value="password" />
            <param name="exchangeName" value="testExchange" />
            <param name="exchangeType" value="topic" />
            <param name="routingKeyPattern" value="test" />
    		<param name="applicationId" value="ErrorsAppenderTest" />
            <param name="declareExchange" value="true" />
            <param name="durable" value="true" />
            <param name="contentType" value="text/plain" />
            <param name="senderPoolSize" value="2" />
            <param name="maxSenderRetries" value="30" />
            <layout class="org.apache.log4j.PatternLayout">
    			<param name="ConversionPattern" value="%-5p %c{1} - %m%n" />
    		</layout>
        </appender>
         
    	<root>
    		<!-- <level value="debug" /> -->
    		<priority value="debug" />
    		<appender-ref ref="amqp" />
    		<appender-ref ref="console" />
    	</root>
    	
    </log4j:configuration>
    I then wrote a small unit that that just calls on logger.debug("Hello World"). I can see the exchange testExchange being created and I have bound a queue to it called log4j.errors using the routing key "#" so it receives all messages. The problem is the appender is connection to my rabbit to create the exchange but no messages are being sent to the queue. I have tried using a direct exchange and a queue with and without a routing key. Nothing ever seems to be sent.

    Thanks

  • #2
    Your config works fine for me; do you have a queue bound to exchange 'testExchange' with routing key 'test' ??

    Bear in mind also that you really don't want to log all amqp logs themselves to amqp at debug level, otherwise you'll get an infinite loop because the debug log generates a log etc, etc; you at least need to restrict the RabbitTemplate logs to console...

    Code:
    	<logger name="org.springframework.amqp.rabbit.core.RabbitTemplate">
    		<level value="warn" />
    		<appender-ref ref="console" />
    	</logger>
    Last edited by Gary Russell; Aug 16th, 2013, 11:40 AM.

    Comment


    • #3
      Yeah I've tried that not getting anything. Thanks for the tip about the logger.

      The project has nothing in it, it's purely a POC for the logging so very little could go wrong here. Do I need to run with anything special in the JUnit test like a spring context or anything.

      The code for the test is below.

      Code:
      package com.gfid.test;
      
      import static org.junit.Assert.*;
      
      import org.junit.Test;
      import org.slf4j.Logger;
      import org.slf4j.LoggerFactory;
      
      public class TestLoggingRabbitMQ {
      
      	private final Logger logger = LoggerFactory.getLogger(getClass());
      	
      	@Test
      	public void testMessageIsSentToRabbitMQ() throws Exception {
      		logger.debug("Hello World");
      		logger.error("Hello World Error");
      	}
      }

      Comment


      • #4
        I didn't do anything special; just copied your config into one of my existing spring-amqp projects; saw it create the exchange; bound a queue and events started showing up.

        I'll try with a new project, but I don't expect any issues.

        Comment


        • #5
          Worked fine for me in a new project (but using log4j directly, not slf4j). Do you have the slf4j -> log4j adapter on the classpath?

          Comment


          • #6
            Originally posted by Gary Russell View Post
            Worked fine for me in a new project (but using log4j directly, not slf4j). Do you have the slf4j -> log4j adapter on the classpath?
            Thanks I just switched out sl4j with log4j and it started producing messages.

            Your help is much appreciated.

            Comment


            • #7
              Originally posted by DeliveryNinja View Post
              Thanks I just switched out sl4j with log4j and it started producing messages.

              Your help is much appreciated.
              Okay so it wasn't so simple. We changed the logger on one machine and got 5 messages on the Queue. We tidied up the code and boom, it's stopped working again. Now even changing to log4j from sl4j makes no difference. I gave the code to another of the senior developers to have a look at as I thought I might have missed something simple. They also can't get it working. It seems that the last part we can debug is the component where the startSenders is invoked. No messages are then sent and no logging output is given.

              The one time that it did work it did show a debug message saying it was trying to declare the exchange but the exchange was already declared. Now this message does not show anymore instead it just happily says it's declaring the exchange again (even though it's already there) and it will do this fine if we delete it the exchange is redeclared.

              If I use an expression during a debug session I can get a RabbitTemplate reference from the RabbitAdmin on line 416 and send a message to a queue myself manually using the parameters I provided for exchangeName and routingKey. I can see that for each debug message in the test the AmqpAppender.doAppend(LoggingEvent event) is being called but I do not seem to be able to debug the EventSender object.

              I have extracted the AmqpAppender to my own class of the same name and added some sys out statements so I could see what was occuring in the EventSender. If I put a statement at the top saying "Invoking Event Sender" I can see this corresponds to the number of senders I have configured (in my case 2) now I add some statements below just before it sends the messages and nothing is printed for those (just before rabbitTemplate.send on line 556). I try to debug on the first line of EventSender where it prints the message and immediately the application stops printing the message "Invoking Event Sender" and never hits the breakpoint.

              So although log4j seems to be sending LoggingEvents to the Appender it does not want to send these the RabbitMQ. I have even got a handle on the Appender in test code and sent a LoggingEvent directly through the doAppend method to no avail.

              Comment


              • #8
                It sounds to me like events are not reaching the appender.

                stops printing the message "Invoking Event Sender"
                That will only be invoked once per sender (if you put it at the top outside of the while loop).

                You need to put a sysout right before events.take() if you want to see it for every event.

                You should also add a sysout right after events.add() in append() - that's where the event is put into a queue for one of the senders to pick up.

                Comment


                • #9
                  Originally posted by Gary Russell View Post
                  It sounds to me like events are not reaching the appender.



                  That will only be invoked once per sender (if you put it at the top outside of the while loop).

                  You need to put a sysout right before events.take() if you want to see it for every event.

                  You should also add a sysout right after events.add() in append() - that's where the event is put into a queue for one of the senders to pick up.
                  The code is as you say right before events.take();

                  Code:
                      System.out.println("INVOKING EVENT SENDER");
                      final Event event = events.take();
                      LoggingEvent logEvent = event.getEvent();
                  I've also added a syso just after event.add()

                  Code:
                      events.add(new Event(event, event.
                      System.out.println("Event Added");
                  I also added a syso statement just above the message sending

                  Code:
                      System.out.println("About to send a message");
                      System.out.println("Exchange: " + exchangeName);
                      System.out.println("Routing Key: " + routingKey);
                      System.out.println("Message: " + message);
                      rabbitTemplate.send(exchangeName, routingKey, message);
                  The test

                  Code:
                  package com.gfid.test;
                  
                  import static org.junit.Assert.*;
                  
                  import org.apache.log4j.Logger;
                  import org.junit.Test;
                  
                  public class TestLoggingRabbitMQ {
                  
                  	private final Logger logger = Logger.getLogger(getClass());
                  	
                  	@Test
                  	public void testMessageIsSentToRabbitMQ() throws Exception {
                  		logger.debug("Hello World Debug");
                  		logger.error("Hello World Error");
                  		logger.error("Hello World Error");
                  		logger.error("Hello World Error");
                  		logger.error("Hello World Error");
                  	}
                  }
                  The console output

                  Code:
                  Event Added
                  DEBUG CachingConnectionFactory - Using hostname [W5093711] for hostname.
                  Event Added
                  DEBUG TestLoggingRabbitMQ - Hello World Debug
                  Event Added
                  INVOKING EVENT SENDER
                  ERROR TestLoggingRabbitMQ - Hello World Error
                  Event Added
                  INVOKING EVENT SENDER
                  ERROR TestLoggingRabbitMQ - Hello World Error
                  Event Added
                  ERROR TestLoggingRabbitMQ - Hello World Error
                  Event Added
                  ERROR TestLoggingRabbitMQ - Hello World Error

                  Comment


                  • #10
                    Okay this time I have it working consistently. It seems that the events added to the queue are not picked up in time before the unit test completes.

                    Adding a Thread.sleep(1000) at the end allows the threads time to take events off the queue and send them via RabbitMQ.

                    Comment


                    • #11
                      Thanks; this is good info. This makes me think the sender threads are "stuck" someplace (or have exited for some reason).

                      Next step is to put t.printStackTrace() in the catch{} block at the bottom of the EventSender. If that doesn't fire, it means the thread is blocked someplace. If that's the case, take a thread dump (find the processid and use jstack <pid> to get a thread dump - or use VisualVM). That way, we can figure out what the threads are doing.

                      Comment


                      • #12
                        Ah - ok; good news.

                        Comment


                        • #13

                          Originally posted by Gary Russell View Post
                          Ah - ok; good news.
                          I really appreciate your help and quick replies it's really helped!

                          Thanks

                          Comment

                          Working...
                          X