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.
This commit is contained in:
Gary Russell
2015-02-06 15:02:55 -05:00
committed by Artem Bilan
parent 0e5381dd90
commit 71051fdbbd
3 changed files with 22 additions and 3 deletions

View File

@@ -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 {

View File

@@ -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 {

View File

@@ -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>