Logging infrastructure: See qpidd --long-help for details.

* src/qpid/log/*: Logging infrastructure, QPID_LOG macro.
* src/*: changed output to cout/cerr to logging.
* src/qpidd.cpp: logging options.
* src/tests/Makefile.am: fixed issues with valgrind
* src/tests/kill|start_broker: use broker daemon options.
* src/tests/run_test: run tests in valgrind. Disabled till leaks in
  client_test are fixed.
* src/test/unit/logging.cpp: Logging unit test using boost test framework.
  Eventually we should move all unit tests to boost & drop CppUnit.
* src/test/unit/test_tools.h: useful extensions to boost framework:
  Regular expression check, ostream << for vectors.


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

14 files changed, 51 insertions, 45 deletions

diff --git a/cpp/src/qpid/sys/Module.h b/cpp/src/qpid/sys/Module.h
index 89cea36a74..e812f57d7a 100644
--- a/cpp/src/qpid/sys/Module.h
+++ b/cpp/src/qpid/sys/Module.h
@@ -29,4 +29,3 @@
 #endif
 
 #endif //ifndef _sys_Module_h
-
diff --git a/cpp/src/qpid/sys/apr/APRAcceptor.cpp b/cpp/src/qpid/sys/apr/APRAcceptor.cpp
index e9ce24ac2d..0f0853b35d 100644
--- a/cpp/src/qpid/sys/apr/APRAcceptor.cpp
+++ b/cpp/src/qpid/sys/apr/APRAcceptor.cpp
@@ -18,6 +18,7 @@
  * under the License.
  *
  */
+#include "qpid/log/Statement.h"
 #include "qpid/sys/Acceptor.h"
 #include "qpid/sys/ConnectionInputHandlerFactory.h"
 #include "qpid/sys/Mutex.h"
@@ -80,7 +81,7 @@ uint16_t APRAcceptor::getPort() const {
 void APRAcceptor::run(ConnectionInputHandlerFactory* factory) {
     running = true;
     processor.start();
-    std::cout << "Listening on port " << getPort() << "..." << std::endl;
+    QPID_LOG(info, "Listening on port " << getPort());
     while(running) {
             apr_socket_t* client;
             apr_status_t status = apr_socket_accept(&client, socket, APRPool::get());
@@ -97,7 +98,7 @@ void APRAcceptor::run(ConnectionInputHandlerFactory* factory) {
             Mutex::ScopedLock locker(shutdownLock);                
             if(running) {
                 if(status != APR_EINTR){
-                    std::cout << "ERROR: " << get_desc(status) << std::endl;
+                    QPID_LOG(error, get_desc(status));
                 }
                 shutdownImpl();
             }
diff --git a/cpp/src/qpid/sys/apr/APRBase.cpp b/cpp/src/qpid/sys/apr/APRBase.cpp
index ba7dfc08d4..f527e0d0b2 100644
--- a/cpp/src/qpid/sys/apr/APRBase.cpp
+++ b/cpp/src/qpid/sys/apr/APRBase.cpp
@@ -19,6 +19,7 @@
  *
  */
 #include <iostream>
+#include "qpid/log/Statement.h"
 #include "qpid/QpidError.h"
 #include "APRBase.h"
 
@@ -73,9 +74,8 @@ void APRBase::_decrement(){
 
 void APRBase::increment(){
     int count = 0;
-    while(count++ < 2 && !getInstance()->_increment()){
-        std::cout << "WARNING: APR initialization triggered concurrently with termination." << std::endl;
-    }
+    while(count++ < 2 && !getInstance()->_increment())
+        QPID_LOG(warning, "APR initialization triggered concurrently with termination.");
 }
 
 void APRBase::decrement(){
diff --git a/cpp/src/qpid/sys/apr/APRSocket.cpp b/cpp/src/qpid/sys/apr/APRSocket.cpp
index 96dbd132a1..3086bafc7c 100644
--- a/cpp/src/qpid/sys/apr/APRSocket.cpp
+++ b/cpp/src/qpid/sys/apr/APRSocket.cpp
@@ -20,6 +20,7 @@
  */
 #include "APRBase.h"
 #include "APRSocket.h"
+#include "qpid/log/Statement.h"
 #include <assert.h>
 #include <iostream>
 
@@ -53,7 +54,7 @@ void APRSocket::write(qpid::framing::Buffer& buffer){
 
 void APRSocket::close(){
     if(!closed){
-        std::cout << "Closing socket " << socket << "@" << this << std::endl;
+        QPID_LOG(warning, "Closing socket " << socket << "@" << this);
         CHECK_APR_SUCCESS(apr_socket_close(socket));
         closed = true;
     }
diff --git a/cpp/src/qpid/sys/apr/LFProcessor.cpp b/cpp/src/qpid/sys/apr/LFProcessor.cpp
index 9e139c874c..bb53e45a83 100644
--- a/cpp/src/qpid/sys/apr/LFProcessor.cpp
+++ b/cpp/src/qpid/sys/apr/LFProcessor.cpp
@@ -19,6 +19,7 @@
  *
  */
 #include <sstream>
+#include "qpid/log/Statement.h"
 #include "qpid/QpidError.h"
 #include "qpid/sys/Mutex.h"
 #include "LFProcessor.h"
@@ -136,7 +137,7 @@ void LFProcessor::run(){
             }
         }
     }catch(std::exception e){
-	std::cout << e.what() << std::endl;
+	QPID_LOG(error,  e.what());
     }
 }
 
diff --git a/cpp/src/qpid/sys/apr/LFSessionContext.cpp b/cpp/src/qpid/sys/apr/LFSessionContext.cpp
index 4f5fcb269e..2672b168e5 100644
--- a/cpp/src/qpid/sys/apr/LFSessionContext.cpp
+++ b/cpp/src/qpid/sys/apr/LFSessionContext.cpp
@@ -21,6 +21,7 @@
 #include "LFSessionContext.h"
 #include "APRBase.h"
 #include "qpid/QpidError.h"
+#include "qpid/log/Statement.h"
 #include <assert.h>
 
 using namespace qpid::sys;
@@ -60,20 +61,18 @@ void LFSessionContext::read(){
         AMQFrame frame;
         try{
             while(frame.decode(in)){
-                if(debug) log("RECV", &frame);
+                QPID_LOG(debug, "RECV: " << frame);
                 handler->received(&frame);
             }
-        }catch(QpidError error){
-            std::cout << "Error [" << error.code << "] " << error.msg
-                      << " (" << error.loc.file << ":" << error.loc.line
-                      << ")" << std::endl;
+        }catch(const std::exception& e){
+            QPID_LOG(error, e.what());
         }
     }else{
         ProtocolInitiation protocolInit;
         if(protocolInit.decode(in)){
             handler->initiated(protocolInit);
             initiated = true;
-            if(debug) std::cout << "INIT [" << &socket << "]" << std::endl;
+            QPID_LOG(debug, "INIT [" << &socket << "]");
         }
     }
     in.compact();
@@ -99,7 +98,7 @@ void LFSessionContext::write(){
                 while(frame && out.available() >= frame->size()){
                     encoded = true;
                     frame->encode(out);
-                    if(debug) log("SENT", frame);
+                    QPID_LOG(debug, "SENT: " << frame);
                     delete frame;
                     framesToWrite.pop();
                     frame = framesToWrite.empty() ? 0 : framesToWrite.front();
@@ -156,7 +155,7 @@ void LFSessionContext::close(){
 
 void LFSessionContext::handleClose(){
     handler->closed();
-    std::cout << "Session closed [" << &socket << "]" << std::endl;
+    QPID_LOG(info, "Session closed [" << &socket << "]");
     delete handler;
     delete this;
 }
@@ -171,9 +170,3 @@ void LFSessionContext::init(ConnectionInputHandler* _handler){
     processor->add(&fd);
 }
 
-void LFSessionContext::log(const std::string& desc, AMQFrame* const frame){
-    Mutex::ScopedLock l(logLock);
-    std::cout << desc << " [" << &socket << "]: " << *frame << std::endl;
-}
-
-Mutex LFSessionContext::logLock;
diff --git a/cpp/src/qpid/sys/apr/LFSessionContext.h b/cpp/src/qpid/sys/apr/LFSessionContext.h
index 3c90c4a381..5248d8f5bd 100644
--- a/cpp/src/qpid/sys/apr/LFSessionContext.h
+++ b/cpp/src/qpid/sys/apr/LFSessionContext.h
@@ -61,11 +61,6 @@ class LFSessionContext : public virtual qpid::sys::ConnectionOutputHandler
     bool processing;
     bool closing;
 
-    static qpid::sys::Mutex logLock;
-    void log(const std::string& desc,
-             qpid::framing::AMQFrame* const frame);
-        
-
   public:
     LFSessionContext(apr_pool_t* pool, apr_socket_t* socket, 
                      LFProcessor* const processor, 
diff --git a/cpp/src/qpid/sys/apr/Module.h b/cpp/src/qpid/sys/apr/Module.h
index d77cc0f388..ff93a0eaf0 100644
--- a/cpp/src/qpid/sys/apr/Module.h
+++ b/cpp/src/qpid/sys/apr/Module.h
@@ -21,7 +21,7 @@
  * under the License.
  *
  */
-
+#include "qpid/log/Statement.h"
 #include "qpid/QpidError.h"
 #include "APRBase.h"
 #include "APRPool.h"
@@ -85,7 +85,7 @@ template <class T> Module<T>::~Module() throw()
         }
         if (handle) unload();
     } catch (std::exception& e) {
-        std::cout << "Error while destroying module: " << e.what() << std::endl;
+        QPID_LOG(error, "Error while destroying module: " << e.what());
     }
     destroy = 0;
     handle = 0;
diff --git a/cpp/src/qpid/sys/apr/Thread.h b/cpp/src/qpid/sys/apr/Thread.h
index ce876efbdf..8cbbc0456e 100644
--- a/cpp/src/qpid/sys/apr/Thread.h
+++ b/cpp/src/qpid/sys/apr/Thread.h
@@ -37,6 +37,12 @@ class Thread
 {
   public:
     inline static Thread current();
+
+    /** ID of current thread for logging.
+     * Workaround for broken Thread::current() in APR 
+     */
+    inline static long logId();
+
     inline static void yield();
 
     inline Thread();
@@ -46,7 +52,7 @@ class Thread
     inline void join();
 
     inline long id();
-        
+
   private:
     static void* APR_THREAD_FUNC runRunnable(apr_thread_t* thread, void *data);
     inline Thread(apr_thread_t* t);
@@ -75,6 +81,13 @@ long Thread::id() {
     return long(thread);
 }
 
+/** ID of current thread for logging.
+ * Workaround for broken Thread::current() in APR
+ */
+long Thread::logId() {
+    return static_cast<long>(apr_os_thread_current());
+}
+
 Thread::Thread(apr_thread_t* t) : thread(t) {}
 
 Thread Thread::current(){
diff --git a/cpp/src/qpid/sys/posix/EventChannel.cpp b/cpp/src/qpid/sys/posix/EventChannel.cpp
index 8dc736ed0b..6db397a165 100644
--- a/cpp/src/qpid/sys/posix/EventChannel.cpp
+++ b/cpp/src/qpid/sys/posix/EventChannel.cpp
@@ -33,6 +33,7 @@
 
 #include "qpid/QpidError.h"
 #include "qpid/sys/Monitor.h"
+#include "qpid/log/Statement.h"
 
 #include "check.h"
 #include "EventChannel.h"
@@ -190,9 +191,8 @@ Event* EventChannel::getEvent()
                                     &epollEvent, 1, infiniteTimeout);
         if (eventCount < 0) {
             if (errno != EINTR) {
-                // TODO aconway 2006-11-28: Proper handling/logging of errors.
-                cerr << BOOST_CURRENT_FUNCTION << " ignoring error "
-                     << PosixError::getMessage(errno) << endl;
+                QPID_LOG(warn, "Ignoring error: "
+                         << PosixError::getMessage(errno));
                 assert(0);
             }
         }
diff --git a/cpp/src/qpid/sys/posix/EventChannelConnection.cpp b/cpp/src/qpid/sys/posix/EventChannelConnection.cpp
index 73e617ea83..0c1c81b6fe 100644
--- a/cpp/src/qpid/sys/posix/EventChannelConnection.cpp
+++ b/cpp/src/qpid/sys/posix/EventChannelConnection.cpp
@@ -24,6 +24,7 @@
 #include "EventChannelConnection.h"
 #include "qpid/sys/ConnectionInputHandlerFactory.h"
 #include "qpid/QpidError.h"
+#include "qpid/log/Statement.h"
 
 using namespace std;
 using namespace qpid;
@@ -132,8 +133,7 @@ void EventChannelConnection::startWrite() {
     }
     // No need to lock here - only one thread can be writing at a time.
     out.clear();
-    if (isTrace)
-        cout << "Send on socket " << writeFd << ": " << *frame << endl;
+    QPID_LOG(trace, "Send on socket " << writeFd << ": " << *frame);
     frame->encode(out);
     out.flip();
     writeEvent = WriteEvent(
@@ -215,10 +215,8 @@ void EventChannelConnection::endRead() {
         in.flip();
         AMQFrame frame;
         while (frame.decode(in)) {
-            // TODO aconway 2006-11-30: received should take Frame&
-            if (isTrace)
-                cout << "Received on socket " << readFd
-                     << ": " << frame << endl;
+            QPID_LOG(trace, "Received on socket " << readFd
+                     << ": " << frame);
             handler->received(&frame); 
         }
         in.compact();
diff --git a/cpp/src/qpid/sys/posix/EventChannelThreads.cpp b/cpp/src/qpid/sys/posix/EventChannelThreads.cpp
index ec58a03671..68c57405d5 100644
--- a/cpp/src/qpid/sys/posix/EventChannelThreads.cpp
+++ b/cpp/src/qpid/sys/posix/EventChannelThreads.cpp
@@ -18,6 +18,7 @@
 
 #include "EventChannelThreads.h"
 #include "qpid/sys/Runnable.h"
+#include "qpid/log/Statement.h"
 #include <iostream>
 using namespace std;
 #include <boost/bind.hpp>
@@ -106,13 +107,10 @@ void EventChannelThreads::run()
         }
     }
     catch (const std::exception& e) {
-        // TODO aconway 2006-11-15: need better logging across the board.
-        std::cerr << "EventChannelThreads::run() caught: " << e.what()
-                  << std::endl;
+        QPID_LOG(error, e.what());
     }
     catch (...) {
-        std::cerr << "EventChannelThreads::run() caught unknown exception."
-                  << std::endl;
+        QPID_LOG(error, "unknown exception");
     }
 }
 
diff --git a/cpp/src/qpid/sys/posix/Module.h b/cpp/src/qpid/sys/posix/Module.h
index af3d6ac6ef..a02b9d1a52 100644
--- a/cpp/src/qpid/sys/posix/Module.h
+++ b/cpp/src/qpid/sys/posix/Module.h
@@ -23,6 +23,7 @@
  */
  
 #include "qpid/QpidError.h"
+#include "qpid/log/Statement.h"
 
 #include <boost/noncopyable.hpp>
 #include <iostream>
@@ -83,7 +84,7 @@ template <class T> Module<T>::~Module() throw()
         }
         if (handle) unload();
     } catch (std::exception& e) {
-        std::cout << "Error while destroying module: " << e.what() << std::endl;
+        QPID_LOG(error, "Error while destroying module: " << e.what());
     }
     destroy = 0;
     handle = 0;
diff --git a/cpp/src/qpid/sys/posix/Thread.h b/cpp/src/qpid/sys/posix/Thread.h
index 9de7299f5a..631a5d5378 100644
--- a/cpp/src/qpid/sys/posix/Thread.h
+++ b/cpp/src/qpid/sys/posix/Thread.h
@@ -34,6 +34,12 @@ class Thread
 {
   public:
     inline static Thread current();
+
+    /** ID of current thread for logging.
+     * Workaround for broken Thread::current() in APR
+     */
+    static long logId() { return current().id(); }
+
     inline static void yield();
 
     inline Thread();