QPID-4175: HA code rationalize logging

Clean up and rationalize log messages and levels.

notice: Major broker-level events: connecting, failing-over, primary active, backup ready.
info: Major queue level events: subscriptions ready, replicators created etc.
debug: Detailed replication events: accept/reject conections, details of queue replication protocol.
trace: dumping raw QMF messages

git-svn-id: https://svn.apache.org/repos/asf/qpid/branches/0.18@1367547 13f79535-47bb-0310-9956-ffa450edef68

6 files changed, 34 insertions, 18 deletions

diff --git a/qpid/cpp/src/qpid/ha/Backup.cpp b/qpid/cpp/src/qpid/ha/Backup.cpp
index 4ec8af588c..bac6fd23c8 100644
--- a/qpid/cpp/src/qpid/ha/Backup.cpp
+++ b/qpid/cpp/src/qpid/ha/Backup.cpp
@@ -115,4 +115,16 @@ void Backup::setBrokerUrl(const Url& url) {
         initialize(url);        // Deferred initialization
 }
 
+void Backup::setStatus(BrokerStatus status) {
+    switch (status) {
+      case READY:
+        QPID_LOG(notice, logPrefix << "Ready to become primary.");
+        break;
+      case CATCHUP:
+        QPID_LOG(notice, logPrefix << "Catching up on primary, cannot be promoted.");
+      default:
+        assert(0);
+    }
+}
+
 }} // namespace qpid::ha
diff --git a/qpid/cpp/src/qpid/ha/Backup.h b/qpid/cpp/src/qpid/ha/Backup.h
index c3c4fbbbfc..1233a473ec 100644
--- a/qpid/cpp/src/qpid/ha/Backup.h
+++ b/qpid/cpp/src/qpid/ha/Backup.h
@@ -50,12 +50,12 @@ class Backup
     Backup(HaBroker&, const Settings&);
     ~Backup();
     void setBrokerUrl(const Url&);
+    void setStatus(BrokerStatus);
 
   private:
     bool isSelf(const Address& a) const;
     Url removeSelf(const Url&) const;
     void initialize(const Url&);
-
     std::string logPrefix;
 
     sys::Mutex lock;
diff --git a/qpid/cpp/src/qpid/ha/BrokerReplicator.cpp b/qpid/cpp/src/qpid/ha/BrokerReplicator.cpp
index f590fd8c95..6a17555b6f 100644
--- a/qpid/cpp/src/qpid/ha/BrokerReplicator.cpp
+++ b/qpid/cpp/src/qpid/ha/BrokerReplicator.cpp
@@ -216,11 +216,10 @@ void BrokerReplicator::initializeBridge(Bridge& bridge, SessionHandler& sessionH
     userId = link->getConnection()->getUserId();
     remoteHost = link->getConnection()->getUrl();
 
-    qpid::Address primary;
     link->getRemoteAddress(primary);
     string queueName = bridge.getQueueName();
 
-    QPID_LOG(info, logPrefix << (initialized ? "Connecting" : "Failing-over")
+    QPID_LOG(info, logPrefix << (initialized ? "Connecting" : "Failing over")
              << " to primary " << primary
              << " status:" << printable(haBroker.getStatus()));
     initialized = true;
@@ -245,15 +244,15 @@ void BrokerReplicator::initializeBridge(Bridge& bridge, SessionHandler& sessionH
     sendQuery(ORG_APACHE_QPID_BROKER, QUEUE, queueName, sessionHandler);
     sendQuery(ORG_APACHE_QPID_BROKER, EXCHANGE, queueName, sessionHandler);
     sendQuery(ORG_APACHE_QPID_BROKER, BINDING, queueName, sessionHandler);
-
-    QPID_LOG(debug, logPrefix << "Connected to primary " << primary
-             << "(" << queueName << ")" << " status:" << printable(haBroker.getStatus()));
 }
 
 void BrokerReplicator::route(Deliverable& msg) {
     // We transition from JOINING->CATCHUP on the first message received from the primary.
     // Until now we couldn't be sure if we had a good connection to the primary.
-    if (haBroker.getStatus() == JOINING) haBroker.setStatus(CATCHUP);
+    if (haBroker.getStatus() == JOINING) {
+        haBroker.setStatus(CATCHUP);
+        QPID_LOG(notice, logPrefix << "Connected to primary " << primary);
+    }
 
     const framing::FieldTable* headers = msg.getMessage().getApplicationHeaders();
     const MessageProperties* messageProperties = msg.getMessage().getProperties<MessageProperties>();
diff --git a/qpid/cpp/src/qpid/ha/BrokerReplicator.h b/qpid/cpp/src/qpid/ha/BrokerReplicator.h
index dbe4822d74..69653b876a 100644
--- a/qpid/cpp/src/qpid/ha/BrokerReplicator.h
+++ b/qpid/cpp/src/qpid/ha/BrokerReplicator.h
@@ -25,6 +25,7 @@
 #include "types.h"
 #include "ReplicationTest.h"
 #include "AlternateExchangeSetter.h"
+#include "qpid/Address.h"
 #include "qpid/broker/Exchange.h"
 #include "qpid/types/Variant.h"
 #include "qpid/management/ManagementObject.h"
@@ -119,6 +120,7 @@ class BrokerReplicator : public broker::Exchange,
     boost::shared_ptr<broker::Link> link;
     bool initialized;
     AlternateExchangeSetter alternates;
+    qpid::Address primary;
 };
 }} // namespace qpid::broker
 
diff --git a/qpid/cpp/src/qpid/ha/HaBroker.cpp b/qpid/cpp/src/qpid/ha/HaBroker.cpp
index fcb47e9d8f..d126639813 100644
--- a/qpid/cpp/src/qpid/ha/HaBroker.cpp
+++ b/qpid/cpp/src/qpid/ha/HaBroker.cpp
@@ -110,16 +110,17 @@ void HaBroker::initialize() {
     if (!settings.clientUrl.empty()) setClientUrl(Url(settings.clientUrl));
     if (!settings.brokerUrl.empty()) setBrokerUrl(Url(settings.brokerUrl));
 
+
+    QPID_LOG(notice, logPrefix << "Initializing: " << brokerInfo);
+
     // NOTE: lock is not needed in a constructor, but create one
     // to pass to functions that have a ScopedLock parameter.
     Mutex::ScopedLock l(lock);
     statusChanged(l);
-
-    QPID_LOG(notice, logPrefix << "Broker starting: " << brokerInfo);
 }
 
 HaBroker::~HaBroker() {
-    QPID_LOG(debug, logPrefix << "Broker shut down: " << brokerInfo);
+    QPID_LOG(notice, logPrefix << "Shut down: " << brokerInfo);
     broker.getConnectionObservers().remove(observer);
 }
 
@@ -271,7 +272,7 @@ bool checkTransition(BrokerStatus from, BrokerStatus to) {
 } // namespace
 
 void HaBroker::setStatus(BrokerStatus newStatus, Mutex::ScopedLock& l) {
-    QPID_LOG(notice, logPrefix << "Status change: "
+    QPID_LOG(info, logPrefix << "Status change: "
              << printable(status) << " -> " << printable(newStatus));
     bool legal = checkTransition(status, newStatus);
     assert(legal);
@@ -299,11 +300,14 @@ void HaBroker::membershipUpdated(Mutex::ScopedLock&) {
 void HaBroker::setMembership(const Variant::List& brokers) {
     Mutex::ScopedLock l(lock);
     membership.assign(brokers);
-    QPID_LOG(debug, logPrefix << "Membership update: " <<  membership);
+    QPID_LOG(info, logPrefix << "Membership update: " <<  membership);
     BrokerInfo info;
-    // Update my status to what the primary thinks.
-    if (membership.get(systemId, info) && status != info.getStatus())
+    // Update my status to what the primary says it is.  The primary can toggle
+    // status between READY and CATCHUP based on the state of our subscriptions.
+    if (membership.get(systemId, info) && status != info.getStatus()) {
         setStatus(info.getStatus(), l);
+        if (backup.get()) backup->setStatus(status);
+    }
     membershipUpdated(l);
 }
 
diff --git a/qpid/cpp/src/qpid/ha/Primary.cpp b/qpid/cpp/src/qpid/ha/Primary.cpp
index 951320d7fb..e7aa4858be 100644
--- a/qpid/cpp/src/qpid/ha/Primary.cpp
+++ b/qpid/cpp/src/qpid/ha/Primary.cpp
@@ -81,13 +81,13 @@ Primary::Primary(HaBroker& hb, const BrokerInfo::Set& expect) :
     assert(instance == 0);
     instance = this;            // Let queue replicators find us.
     if (expect.empty()) {
-        QPID_LOG(debug, logPrefix << "Promoted, no expected backups");
+        QPID_LOG(notice, logPrefix << "Promoted to primary. No expected backups.");
     }
     else {
         // NOTE: RemoteBackups must be created before we set the ConfigurationObserver
         // or ConnectionObserver so that there is no client activity while
         // the QueueGuards are created.
-        QPID_LOG(debug, logPrefix << "Promoted, expected backups: " << expect);
+        QPID_LOG(notice, logPrefix << "Promoted to primary. Expected backups: " << expect);
         for (BrokerInfo::Set::const_iterator i = expect.begin(); i != expect.end(); ++i) {
             boost::shared_ptr<RemoteBackup> backup(
                 new RemoteBackup(*i, haBroker.getReplicationTest(), false));
@@ -130,14 +130,13 @@ void Primary::checkReady(BackupMap::iterator i, Mutex::ScopedLock& l)  {
     if (i != backups.end() && i->second->reportReady()) {
         BrokerInfo info = i->second->getBrokerInfo();
         info.setStatus(READY);
-        QPID_LOG(info, "Expected backup is ready: " << info);
         haBroker.addBroker(info);
         if (expectedBackups.erase(i->second)) {
             QPID_LOG(info, logPrefix << "Expected backup is ready: " << info);
             checkReady(l);
         }
         else
-            QPID_LOG(info, logPrefix << "Backup is ready: " << info);
+            QPID_LOG(info, logPrefix << "New backup is ready: " << info);
     }
 }