Improved logging for session state.

git-svn-id: https://svn.apache.org/repos/asf/incubator/qpid/trunk/qpid@659127 13f79535-47bb-0310-9956-ffa450edef68

2 files changed, 33 insertions, 15 deletions

diff --git a/cpp/src/qpid/SessionState.cpp b/cpp/src/qpid/SessionState.cpp
index 2a6b8303b3..b57035b586 100644
--- a/cpp/src/qpid/SessionState.cpp
+++ b/cpp/src/qpid/SessionState.cpp
@@ -71,6 +71,7 @@ SessionPoint SessionState::senderGetReplayPoint() const { return sender.replayPo
 SessionState::ReplayRange SessionState::senderExpected(const SessionPoint& expect) {
     if (expect < sender.replayPoint || sender.sendPoint < expect)
         throw InvalidArgumentException(QPID_MSG(getId() << ": expected command-point out of range."));
+    QPID_LOG(debug, getId() << ": sender expected point moved to " << expect);
     ReplayList::iterator i = sender.replayList.begin();
     SessionPoint p = sender.replayPoint;
     while (i != sender.replayList.end() && p.command < expect.command)
@@ -81,6 +82,7 @@ SessionState::ReplayRange SessionState::senderExpected(const SessionPoint& expec
 
 void SessionState::senderRecord(const AMQFrame& f) {
     if (isControl(f)) return;   // Ignore control frames.
+    QPID_LOG_IF(debug, f.getMethod(), getId() << ": sent cmd " << sender.sendPoint.command << ": " << *f.getMethod());
     stateful = true;
     sender.replayList.push_back(f);
     sender.unflushedSize += f.size();
@@ -104,6 +106,7 @@ void SessionState::senderRecordFlush() {
 void SessionState::senderConfirmed(const SessionPoint& confirmed) {
     if (confirmed > sender.sendPoint)
         throw InvalidArgumentException(QPID_MSG(getId() << "Confirmed commands not yet sent."));
+    QPID_LOG(debug, getId() << ": sender confirmed point moved to " << confirmed);
     ReplayList::iterator i = sender.replayList.begin();
     while (i != sender.replayList.end() && sender.replayPoint.command < confirmed.command) {
         sender.replayPoint.advance(*i);
@@ -121,6 +124,7 @@ void SessionState::senderConfirmed(const SessionPoint& confirmed) {
 
 void SessionState::senderCompleted(const SequenceSet& commands) {
     if (commands.empty()) return;
+    QPID_LOG(debug, getId() << ": sender marked completed: " << commands);
     sender.incomplete -= commands;
     // Completion implies confirmation but we don't handle out-of-order
     // confirmation, so confirm only the first contiguous range of commands.
@@ -130,6 +134,7 @@ void SessionState::senderCompleted(const SequenceSet& commands) {
 void SessionState::receiverSetCommandPoint(const SessionPoint& point) {
     if (hasState() && point > receiver.received)
         throw InvalidArgumentException(QPID_MSG(getId() << ": Command-point out of range."));
+    QPID_LOG(debug, getId() << ": receiver command-point set to: " << point);
     receiver.expected = point;
     if (receiver.expected > receiver.received)
         receiver.received = receiver.expected;
@@ -139,14 +144,12 @@ bool SessionState::receiverRecord(const AMQFrame& f) {
     if (isControl(f)) return true; // Ignore control frames.
     stateful = true;
     receiver.expected.advance(f);
-    if (receiver.expected > receiver.received) {
+    bool firstTime = receiver.expected > receiver.received;
+    if (firstTime)
         receiver.received = receiver.expected;
-        return true;
-    }
-    else {
-        QPID_LOG(debug, "Ignoring duplicate: " << f);
-    return false;
-}
+    QPID_LOG_IF(debug, f.getMethod(), getId() << ": recv cmd " << receiverGetCurrent() << ": " << *f.getMethod());
+    QPID_LOG_IF(debug, !firstTime, "Ignoring duplicate frame: " << receiverGetCurrent() << ": " << f);
+    return firstTime;
 }
     
 void SessionState::receiverCompleted(SequenceNumber command, bool cumulative) {
@@ -157,13 +160,14 @@ void SessionState::receiverCompleted(SequenceNumber command, bool cumulative) {
     else
         receiver.unknownCompleted += command;
     receiver.firstIncomplete = receiver.unknownCompleted.rangeContaining(receiver.firstIncomplete).end();
-    QPID_LOG(debug, "Completed " << command << " unknown=" << receiver.unknownCompleted);
+    QPID_LOG(debug, getId() << ": receiver marked completed: " << command << " unknown: " << receiver.unknownCompleted);
 }
 
 void SessionState::receiverKnownCompleted(const SequenceSet& commands) {
     if (!commands.empty() && commands.back() > receiver.received.command)
         throw InvalidArgumentException(QPID_MSG(getId() << ": Known-completed has invalid commands."));
     receiver.unknownCompleted -= commands;
+    QPID_LOG(debug, getId() << ": receiver known completed: " << commands << " unknown: " << receiver.unknownCompleted);
 }
 
 const SessionPoint& SessionState::receiverGetExpected() const { return receiver.expected; }
diff --git a/cpp/src/qpid/log/Statement.h b/cpp/src/qpid/log/Statement.h
index 18162971b0..f765df1cf4 100644
--- a/cpp/src/qpid/log/Statement.h
+++ b/cpp/src/qpid/log/Statement.h
@@ -79,6 +79,26 @@ struct Statement {
     { 0, __FILE__, __LINE__,  BOOST_CURRENT_FUNCTION, (::qpid::log::level) }
 
 /**
+ * Like QPID_LOG but computes an additional boolean test expression
+ * to determine if the message should be logged. Evaluation of both
+ * the test and  message expressions occurs only if the requested log level
+ * is enabled.
+ *@param LEVEL severity Level for message, should be one of:
+ * debug, info, notice, warning, error, critical. NB no qpid::log:: prefix.
+ *@param TEST message is logged only if expression TEST evaluates to true.
+ *@param MESSAGE any object with an @eostream operator<<, or a sequence
+ * like of ostreamable objects separated by @e<<.
+ */
+#define QPID_LOG_IF(LEVEL, TEST, MESSAGE)                       \
+    do {                                                        \
+        using ::qpid::log::Statement;                           \
+        static Statement stmt_= QPID_LOG_STATEMENT_INIT(LEVEL); \
+        static Statement::Initializer init_(stmt_);             \
+        if (stmt_.enabled && (TEST))                            \
+            stmt_.log(::qpid::Msg() << MESSAGE);                \
+    } while(0)
+
+/**
  * Macro for log statements. Example of use:
  * @code
  * QPID_LOG(debug, "There are " << foocount << " foos in the bar.");
@@ -97,13 +117,7 @@ struct Statement {
  *@param MESSAGE any object with an @eostream operator<<, or a sequence
  * like of ostreamable objects separated by @e<<.
  */
-#define QPID_LOG(level, message)                                        \
-    do {                                                                \
-        static ::qpid::log::Statement stmt_= QPID_LOG_STATEMENT_INIT(level); \
-        static ::qpid::log::Statement::Initializer init_(stmt_);        \
-        if (stmt_.enabled)                                              \
-            stmt_.log(::qpid::Msg() << message);                        \
-    } while(0)
+#define QPID_LOG(LEVEL, MESSAGE) QPID_LOG_IF(LEVEL, true, MESSAGE);
 
 }} // namespace qpid::log