From 71051fdbbda21ea8ce2dfae5a7ce9dc281009c66 Mon Sep 17 00:00:00 2001
From: Gary Russell <grussell@pivotal.io>
Date: Fri, 6 Feb 2015 15:02:55 -0500
Subject: [PATCH] AMQP-474: Fix Log Appenders

JIRA: https://jira.spring.io/browse/AMQP-474

When logs are generated soon after initialization (as is the case for
the test cases), some log messages could (infrequently) be lost.

This is due to the `EventSender` seeing a `null` `applicationId`, generating
a routing key:

    [null.org.springframework.amqp.rabbit.logback.AmqpAppenderIntegrationTests.DEBUG]

instead of:

    [AmqpAppenderTest.org.springframework.amqp.rabbit.logback.AmqpAppenderIntegrationTests.DEBUG]

(in the case of the logback test case).

Since this does not match a binding, the log message is discarded and the test fails.

Since the `applicationId` setter is called before `start()`, on the same thread, the
only way this can happen is if the `EventSender` runs on a CPU that has a stale
copy of the `AmqpAppender` in its cache (the applicationId field is not marked `volatile`).

Rather than making all the log variables volatile, synchronized blocks are now
used during `EventSender` initialization, to ensure the senders see the variable
values correctly.
---
 .../amqp/rabbit/log4j/AmqpAppender.java              | 11 ++++++++++-
 .../amqp/rabbit/logback/AmqpAppender.java            | 12 +++++++++++-
 spring-rabbit/src/test/resources/logback-test.xml    |  2 +-
 3 files changed, 22 insertions(+), 3 deletions(-)

diff --git a/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/log4j/AmqpAppender.java b/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/log4j/AmqpAppender.java
index 9a870a3c..635d4c9a 100644
--- a/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/log4j/AmqpAppender.java
+++ b/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/log4j/AmqpAppender.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2011-2014 by the original author(s).
+ * Copyright (c) 2011-2015 by the original author(s).
  *
  * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
  * the License. You may obtain a copy of the License at
@@ -409,6 +409,8 @@ public class AmqpAppender extends AppenderSkeleton {
 	 */
 	protected void startSenders() {
 		senderPool = Executors.newCachedThreadPool();
+		synchronized(this) {
+		} // (logically) flush all variables to main memory
 		for (int i = 0; i < senderPoolSize; i++) {
 			senderPool.submit(new EventSender());
 		}
@@ -495,6 +497,13 @@ public class AmqpAppender extends AppenderSkeleton {
 	 * Helper class to actually send LoggingEvents asynchronously.
 	 */
 	protected class EventSender implements Runnable {
+
+		public EventSender() {
+			synchronized(AmqpAppender.this) {
+				// (logically) invalidate the CPU cache so we see all outer class fields correctly
+			}
+		}
+
 		@Override
 		public void run() {
 			try {
diff --git a/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/logback/AmqpAppender.java b/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/logback/AmqpAppender.java
index 59de5cdb..2dd497c4 100644
--- a/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/logback/AmqpAppender.java
+++ b/spring-rabbit/src/main/java/org/springframework/amqp/rabbit/logback/AmqpAppender.java
@@ -1,5 +1,5 @@
 /*
- * Copyright 2014 the original author or authors.
+ * Copyright 2014-2015 the original author or authors.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -73,6 +73,7 @@ import ch.qos.logback.core.Layout;
  * </pre>
  *
  * @author Artem Bilan
+ * @author Gary Russell
  * @since 1.4
  */
 public class AmqpAppender extends AppenderBase<ILoggingEvent> {
@@ -389,6 +390,8 @@ public class AmqpAppender extends AppenderBase<ILoggingEvent> {
 		this.connectionFactory.setVirtualHost(this.virtualHost);
 		maybeDeclareExchange();
 		this.senderPool = Executors.newCachedThreadPool();
+		synchronized(this) {
+		} // (logically) flush all variables to main memory
 		for (int i = 0; i < this.senderPoolSize; i++) {
 			this.senderPool.submit(new EventSender());
 		}
@@ -454,6 +457,13 @@ public class AmqpAppender extends AppenderBase<ILoggingEvent> {
 	 * Helper class to actually send LoggingEvents asynchronously.
 	 */
 	protected class EventSender implements Runnable {
+
+		public EventSender() {
+			synchronized(AmqpAppender.this) {
+				// (logically) invalidate the CPU cache so we see all outer class fields correctly
+			}
+		}
+
 		@Override
 		public void run() {
 			try {
diff --git a/spring-rabbit/src/test/resources/logback-test.xml b/spring-rabbit/src/test/resources/logback-test.xml
index c640b0e1..6d7aa382 100644
--- a/spring-rabbit/src/test/resources/logback-test.xml
+++ b/spring-rabbit/src/test/resources/logback-test.xml
@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<configuration>
+<configuration debug="true">
 
 	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
 		<encoder>