diff options
| author | Alan Conway <aconway@apache.org> | 2007-05-30 16:13:58 +0000 |
|---|---|---|
| committer | Alan Conway <aconway@apache.org> | 2007-05-30 16:13:58 +0000 |
| commit | 1d63a898503d20e3221be43fc222f0091971a0ce (patch) | |
| tree | 78d8673b9ed8820e431b6a6f353ba0143adeb800 | |
| parent | f2b034ea3f4fa70e512fafdf18fd42c370194329 (diff) | |
| download | qpid-python-1d63a898503d20e3221be43fc222f0091971a0ce.tar.gz | |
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
50 files changed, 1516 insertions, 168 deletions
diff --git a/cpp/docs/man/Makefile.am b/cpp/docs/man/Makefile.am index c8df4eab6a..f9fff2d520 100644 --- a/cpp/docs/man/Makefile.am +++ b/cpp/docs/man/Makefile.am @@ -15,6 +15,6 @@ SUFFIXES = .x .1 .x.1: @rm -f $@ @echo "Updating man page $@" - $(HELP2MAN) --no-info --include=$(srcdir)/$*.x --output=$@-t ../../src/$* + $(HELP2MAN) --no-info --include=$(srcdir)/$*.x --output=$@-t -h --long-help ../../src/$* @chmod a-w $@-t @mv $@-t $@ diff --git a/cpp/src/Makefile.am b/cpp/src/Makefile.am index 4293719a6f..acc3507d24 100644 --- a/cpp/src/Makefile.am +++ b/cpp/src/Makefile.am @@ -21,7 +21,7 @@ EXTRA_DIST=generate.sh $(generated_cpp) $(generated_h) $(platform_dist) AM_CXXFLAGS = $(WARNING_CFLAGS) $(APR_CXXFLAGS) AM_LDFLAGS = -version-info $(LIBTOOL_VERSION_INFO_ARG) -INCLUDES = -I$(builddir)/gen -I$(srcdir)/gen +INCLUDES = -Igen -I$(srcdir)/gen qpidd_LDADD = \ libqpidbroker.la \ @@ -103,11 +103,22 @@ endif lib_LTLIBRARIES = libqpidcommon.la libqpidbroker.la libqpidclient.la +# The logger library uses boost::date_time to format time. +# We have to disable the unused parameters warning to get around +# unused parameters in boost::date_time headers. So we build it +# in a convenience library to link into libqpid_common. +# +noinst_LTLIBRARIES=libLogger.la +libLogger_la_SOURCES=qpid/log/Logger.cpp qpid/log/Logger.h +libLogger_la_CXXFLAGS=$(AM_CXXFLAGS) -Wno-unused-parameter + libqpidcommon_la_LIBADD = \ -lboost_program_options \ + libLogger.la \ $(APR_LIBS) \ $(LIB_DLOPEN) \ $(LIB_CLOCK_GETTIME) + libqpidcommon_la_SOURCES = \ $(platform_src) \ qpid/framing/AMQBody.cpp \ @@ -143,8 +154,14 @@ libqpidcommon_la_SOURCES = \ qpid/QpidError.cpp \ qpid/sys/Runnable.cpp \ qpid/sys/ProducerConsumer.cpp \ - qpid/CommonOptions.cpp - + qpid/CommonOptions.cpp \ + qpid/log/Options.cpp \ + qpid/log/Options.h \ + qpid/log/Selector.cpp \ + qpid/log/Selector.h \ + qpid/log/Statement.cpp \ + qpid/log/Statement.h \ + qpid/memory.h libqpidbroker_la_LIBADD = libqpidcommon.la -ldaemon -lboost_filesystem libqpidbroker_la_SOURCES = \ diff --git a/cpp/src/qpid/CommonOptions.cpp b/cpp/src/qpid/CommonOptions.cpp index f272c71a27..2224f0e75b 100644 --- a/cpp/src/qpid/CommonOptions.cpp +++ b/cpp/src/qpid/CommonOptions.cpp @@ -17,6 +17,7 @@ */ #include "CommonOptions.h" +#include "qpid/Exception.h" #include <fstream> #include <algorithm> #include <iostream> @@ -39,6 +40,10 @@ std::string env2option(const std::string& env) { return std::string(); } +std::string prettyArg(const std::string& name, const std::string& value) { + return value.empty() ? name : name+" (="+value+")"; +} + } // namespace program_options const int CommonOptions::DEFAULT_PORT=5672; @@ -69,13 +74,19 @@ void parseOptions( throw po::error(std::string("parsing environment variables: ") + e.what()); } - po::notify(vm); // So we can use the value of config. - try { - std::ifstream conf(configFile.c_str()); - po::store(po::parse_config_file(conf, desc), vm); - } - catch (const po::error& e) { - throw po::error(std::string("parsing config file: ")+ e.what()); + po::notify(vm); // configFile may be updated from arg/env options. + if (!configFile.empty()) { + try { + using namespace std; + ifstream conf(configFile.c_str()); + if (conf.good()) { + conf.exceptions(ifstream::failbit|ifstream::badbit); + po::store(po::parse_config_file(conf, desc), vm); + } + } + catch (const std::exception& e) { + throw Exception(std::string("error parsing config file: ")+ e.what()); + } } po::notify(vm); } diff --git a/cpp/src/qpid/CommonOptions.h b/cpp/src/qpid/CommonOptions.h index e166e8f7c9..8a67babfde 100644 --- a/cpp/src/qpid/CommonOptions.h +++ b/cpp/src/qpid/CommonOptions.h @@ -24,6 +24,9 @@ #include <boost/program_options.hpp> #include <boost/format.hpp> +#include <sstream> +#include <iterator> +#include <algorithm> namespace qpid { @@ -43,9 +46,12 @@ class OptionValue : public typed_value<T> { std::string argName; }; +///@internal +std::string prettyArg(const std::string& name, const std::string& value); + /** * Like boost::program_options::value() with more convenient signature - * for updating a value by reference and nicer help formatting. + * for updating a value by reference and prettier help formatting. * *@param value displayed as default in help, updated from options. * Must support ostream << operator. @@ -54,12 +60,20 @@ class OptionValue : public typed_value<T> { *@see CommonOptions.cpp for example of use. */ template<class T> -value_semantic* optValue(T& value, const char* arg) { - std::string val(boost::lexical_cast<std::string>(value)); - std::string argName( - val.empty() ? std::string(arg) : - (boost::format("%s (=%s) ") % arg % val).str()); - return new OptionValue<T>(value, argName); +value_semantic* optValue(T& value, const char* name) { + std::string valstr(boost::lexical_cast<std::string>(value)); + return new OptionValue<T>(value, prettyArg(name, valstr)); +} + +template <class T> +value_semantic* optValue(std::vector<T>& value, const char* name) { + using namespace std; + ostringstream os; + copy(value.begin(), value.end(), ostream_iterator<T>(os, " ")); + string val=os.str(); + if (!val.empty()) + val.erase(val.end()-1); // Remove trailing " " + return (new OptionValue<vector<T> >(value, prettyArg(name, val))); } /** Environment-to-option name mapping. diff --git a/cpp/src/qpid/QpidError.h b/cpp/src/qpid/QpidError.h index 12e80c9bd9..24c2b74dde 100644 --- a/cpp/src/qpid/QpidError.h +++ b/cpp/src/qpid/QpidError.h @@ -69,6 +69,8 @@ class QpidError : public Exception #define THROW_QPID_ERROR(CODE, MESSAGE) throw QPID_ERROR(CODE,MESSAGE) +#define THROW_QPID_ERRNO_IF(cond) if (cond) QPID_ERROR(INTERNAL, strError(errno)); + const int PROTOCOL_ERROR = 10000; const int APR_ERROR = 20000; const int FRAMING_ERROR = 30000; diff --git a/cpp/src/qpid/broker/AutoDelete.cpp b/cpp/src/qpid/broker/AutoDelete.cpp index 8f1f38b184..45ce12c036 100644 --- a/cpp/src/qpid/broker/AutoDelete.cpp +++ b/cpp/src/qpid/broker/AutoDelete.cpp @@ -19,6 +19,7 @@ * */ #include "AutoDelete.h" +#include "qpid/log/Statement.h" #include "qpid/sys/Time.h" using namespace qpid::broker; @@ -51,7 +52,7 @@ void AutoDelete::process(){ }else if(q->canAutoDelete()){ std::string name(q->getName()); registry->destroy(name); - std::cout << "INFO: Auto-deleted queue named " << name << std::endl; + QPID_LOG(info, "Auto-deleted queue named " << name); }else{ add(q); if(!seen) seen = q; diff --git a/cpp/src/qpid/broker/BrokerMessage.cpp b/cpp/src/qpid/broker/BrokerMessage.cpp index ce21a2cca4..83b6f2bf18 100644 --- a/cpp/src/qpid/broker/BrokerMessage.cpp +++ b/cpp/src/qpid/broker/BrokerMessage.cpp @@ -26,6 +26,7 @@ #include "InMemoryContent.h" #include "LazyLoadedContent.h" #include "MessageStore.h" +#include "qpid/log/Statement.h" #include "qpid/framing/BasicDeliverBody.h" #include "qpid/framing/BasicGetOkBody.h" #include "qpid/framing/AMQContentBody.h" @@ -76,8 +77,6 @@ void BasicMessage::deliver(ChannelAdapter& channel, const string& consumerTag, uint64_t deliveryTag, uint32_t framesize) { - // CCT -- TODO - Update code generator to take pointer/ not - // instance to avoid extra contruction channel.send( new BasicDeliverBody( channel.getVersion(), consumerTag, deliveryTag, @@ -91,8 +90,6 @@ void BasicMessage::sendGetOk(const MethodContext& context, uint64_t deliveryTag, uint32_t framesize) { - // CCT -- TODO - Update code generator to take pointer/ not - // instance to avoid extra contruction context.channel->send( new BasicGetOkBody( context.channel->getVersion(), @@ -155,7 +152,7 @@ void BasicMessage::decodeContent(Buffer& buffer, uint32_t chunkSize) { uint64_t expected = expectedContentSize(); if (expected != buffer.available()) { - std::cout << "WARN: Expected " << expectedContentSize() << " bytes, got " << buffer.available() << std::endl; + QPID_LOG(error, "Expected " << expectedContentSize() << " bytes, got " << buffer.available()); throw Exception("Cannot decode content, buffer not large enough."); } diff --git a/cpp/src/qpid/broker/BrokerQueue.cpp b/cpp/src/qpid/broker/BrokerQueue.cpp index 0fbff0f8fd..ee1a913a96 100644 --- a/cpp/src/qpid/broker/BrokerQueue.cpp +++ b/cpp/src/qpid/broker/BrokerQueue.cpp @@ -21,6 +21,7 @@ #include <boost/format.hpp> +#include "qpid/log/Statement.h" #include "BrokerQueue.h" #include "MessageStore.h" #include "qpid/sys/Monitor.h" @@ -78,7 +79,7 @@ bool Queue::dispatch(Message::shared_ptr& msg){ return false; }else if(exclusive){ if(!exclusive->deliver(msg)){ - std::cout << "WARNING: Dropping undeliverable message from queue with exclusive consumer." << std::endl; + QPID_LOG(warning, "Dropping undeliverable message from queue with exclusive consumer."); } return true; }else{ diff --git a/cpp/src/qpid/broker/Connection.cpp b/cpp/src/qpid/broker/Connection.cpp index 88015ce310..15031ff243 100644 --- a/cpp/src/qpid/broker/Connection.cpp +++ b/cpp/src/qpid/broker/Connection.cpp @@ -18,6 +18,7 @@ * under the License. * */ +#include "qpid/log/Statement.h" #include <iostream> #include <assert.h> @@ -99,8 +100,8 @@ void Connection::closed(){ exclusiveQueues.erase(exclusiveQueues.begin()); } } catch(std::exception& e) { - std::cout << "Caught unhandled exception while closing session: " << - e.what() << std::endl; + QPID_LOG(error, " Unhandled exception while closing session: " << + e.what()); assert(0); } } diff --git a/cpp/src/qpid/broker/DirectExchange.cpp b/cpp/src/qpid/broker/DirectExchange.cpp index ec77efa0f3..01817144d6 100644 --- a/cpp/src/qpid/broker/DirectExchange.cpp +++ b/cpp/src/qpid/broker/DirectExchange.cpp @@ -18,6 +18,7 @@ * under the License. * */ +#include "qpid/log/Statement.h" #include "DirectExchange.h" #include <iostream> @@ -64,7 +65,7 @@ void DirectExchange::route(Deliverable& msg, const string& routingKey, const Fie msg.deliverTo(*i); } if(!count){ - std::cout << "WARNING: DirectExchange " << getName() << " could not route message with key " << routingKey << std::endl; + QPID_LOG(warning, "DirectExchange " << getName() << " could not route message with key " << routingKey); } } diff --git a/cpp/src/qpid/broker/NullMessageStore.cpp b/cpp/src/qpid/broker/NullMessageStore.cpp index 686c2238ff..49feb163bf 100644 --- a/cpp/src/qpid/broker/NullMessageStore.cpp +++ b/cpp/src/qpid/broker/NullMessageStore.cpp @@ -20,8 +20,8 @@ */ #include "NullMessageStore.h" - #include "RecoveryManager.h" +#include "qpid/log/Statement.h" #include <iostream> @@ -31,60 +31,60 @@ NullMessageStore::NullMessageStore(bool _warn) : warn(_warn){} void NullMessageStore::create(const PersistableQueue& queue) { - if (warn) std::cout << "WARNING: Can't create durable queue '" << queue.getName() << "'. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't create durable queue '" << queue.getName() << "'. Persistence not enabled."); } void NullMessageStore::destroy(const PersistableQueue& queue) { - if (warn) std::cout << "WARNING: Can't destroy durable queue '" << queue.getName() << "'. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't destroy durable queue '" << queue.getName() << "'. Persistence not enabled."); } void NullMessageStore::create(const PersistableExchange& exchange) { - if (warn) std::cout << "WARNING: Can't create durable exchange '" << exchange.getName() << "'. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't create durable exchange '" + << exchange.getName() << "'. Persistence not enabled."); } -void NullMessageStore::destroy(const PersistableExchange& exchange) -{ - if (warn) std::cout << "WARNING: Can't destroy durable exchange '" << exchange.getName() << "'. Persistence not enabled." << std::endl; -} +void NullMessageStore::destroy(const PersistableExchange& ) +{} + void NullMessageStore::bind(const PersistableExchange&, const PersistableQueue&, const std::string&, const framing::FieldTable&){} void NullMessageStore::unbind(const PersistableExchange&, const PersistableQueue&, const std::string&, const framing::FieldTable&){} void NullMessageStore::recover(RecoveryManager&) { - if (warn) std::cout << "WARNING: Persistence not enabled, no recovery of queues or messages." << std::endl; + QPID_LOG(warning, "Persistence not enabled, no recovery of queues or messages."); } void NullMessageStore::stage(PersistableMessage&) { - if (warn) std::cout << "WARNING: Can't stage message. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't stage message. Persistence not enabled."); } void NullMessageStore::destroy(PersistableMessage&) { - if (warn) std::cout << "WARNING: No need to destroy staged message. Persistence not enabled." << std::endl; + QPID_LOG(warning, "No need to destroy staged message. Persistence not enabled."); } void NullMessageStore::appendContent(PersistableMessage&, const string&) { - if (warn) std::cout << "WARNING: Can't append content. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't load content. Persistence not enabled."); } void NullMessageStore::loadContent(PersistableMessage&, string&, uint64_t, uint32_t) { - if (warn) std::cout << "WARNING: Can't load content. Persistence not enabled." << std::endl; + QPID_LOG(warning, "WARNING: Can't load content. Persistence not enabled."); } void NullMessageStore::enqueue(TransactionContext*, PersistableMessage&, const PersistableQueue& queue) { - if (warn) std::cout << "WARNING: Can't enqueue message onto '" << queue.getName() << "'. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't enqueue message onto '" << queue.getName() << "'. Persistence not enabled."); } void NullMessageStore::dequeue(TransactionContext*, PersistableMessage&, const PersistableQueue& queue) { - if (warn) std::cout << "WARNING: Can't dequeue message from '" << queue.getName() << "'. Persistence not enabled." << std::endl; + QPID_LOG(warning, "Can't dequeue message from '" << queue.getName() << "'. Persistence not enabled."); } std::auto_ptr<TransactionContext> NullMessageStore::begin() diff --git a/cpp/src/qpid/broker/TxAck.cpp b/cpp/src/qpid/broker/TxAck.cpp index 60d8049102..b02e669f02 100644 --- a/cpp/src/qpid/broker/TxAck.cpp +++ b/cpp/src/qpid/broker/TxAck.cpp @@ -19,6 +19,7 @@ * */ #include "TxAck.h" +#include "qpid/log/Statement.h" using std::bind1st; using std::bind2nd; @@ -40,7 +41,7 @@ bool TxAck::prepare(TransactionContext* ctxt) throw(){ } return true; }catch(...){ - std::cout << "TxAck::prepare() - Failed to prepare" << std::endl; + QPID_LOG(error, "Failed to prepare"); return false; } } diff --git a/cpp/src/qpid/broker/TxPublish.cpp b/cpp/src/qpid/broker/TxPublish.cpp index 687505909c..6e03f37dcd 100644 --- a/cpp/src/qpid/broker/TxPublish.cpp +++ b/cpp/src/qpid/broker/TxPublish.cpp @@ -18,6 +18,7 @@ * under the License. * */ +#include "qpid/log/Statement.h" #include "TxPublish.h" using namespace qpid::broker; @@ -29,7 +30,7 @@ bool TxPublish::prepare(TransactionContext* ctxt) throw(){ for_each(queues.begin(), queues.end(), Prepare(ctxt, msg)); return true; }catch(...){ - std::cout << "TxPublish::prepare() - Failed to prepare" << std::endl; + QPID_LOG(error, "Failed to prepare"); return false; } } diff --git a/cpp/src/qpid/client/BasicMessageChannel.cpp b/cpp/src/qpid/client/BasicMessageChannel.cpp index 96aaad05dc..91849c735e 100644 --- a/cpp/src/qpid/client/BasicMessageChannel.cpp +++ b/cpp/src/qpid/client/BasicMessageChannel.cpp @@ -15,6 +15,7 @@ * limitations under the License. * */ +#include "qpid/log/Statement.h" #include "BasicMessageChannel.h" #include "qpid/framing/AMQMethodBody.h" #include "ClientChannel.h" @@ -320,12 +321,11 @@ void BasicMessageChannel::run() { } } catch (const ShutdownException&) { - /* Orderly shutdown */ + // Orderly shutdown. } catch (const Exception& e) { // FIXME aconway 2007-02-20: Report exception to user. - cout << "client::BasicMessageChannel::run() terminated by: " - << e.toString() << endl; + QPID_LOG(error, e.what()); } } } diff --git a/cpp/src/qpid/client/ClientChannel.cpp b/cpp/src/qpid/client/ClientChannel.cpp index 05f01227f6..0cb0931155 100644 --- a/cpp/src/qpid/client/ClientChannel.cpp +++ b/cpp/src/qpid/client/ClientChannel.cpp @@ -18,6 +18,7 @@ * under the License. * */ +#include "qpid/log/Statement.h" #include <iostream> #include "ClientChannel.h" #include "qpid/sys/Monitor.h" @@ -112,8 +113,7 @@ void Channel::protocolInit( //ignore for now ConnectionRedirectBody::shared_ptr redirect( shared_polymorphic_downcast<ConnectionRedirectBody>(openResponse)); - cout << "Received redirection to " << redirect->getHost() - << endl; + QPID_LOG(error, "Ignoring redirect to " << redirect->getHost()); } else { THROW_QPID_ERROR(PROTOCOL_ERROR, "Bad response to Connection.open"); } @@ -189,9 +189,8 @@ void Channel::rollback(){ void Channel::handleMethodInContext( AMQMethodBody::shared_ptr method, const MethodContext&) { - // TODO aconway 2007-03-23: Special case for consume OK as it - // is both an expected response and needs handling in this thread. - // Need to review & reationalize the client-side processing model. + // Special case for consume OK as it is both an expected response + // and needs handling in this thread. if (method->isA<BasicConsumeOkBody>()) { messaging->handle(method); responses.signalResponse(method); diff --git a/cpp/src/qpid/client/ClientConnection.cpp b/cpp/src/qpid/client/ClientConnection.cpp index 177c9c4b73..d6d03680c1 100644 --- a/cpp/src/qpid/client/ClientConnection.cpp +++ b/cpp/src/qpid/client/ClientConnection.cpp @@ -25,6 +25,7 @@ #include "Connection.h" #include "ClientChannel.h" #include "ClientMessage.h" +#include "qpid/log/Statement.h" #include "qpid/QpidError.h" #include <iostream> #include <sstream> @@ -78,7 +79,7 @@ void Connection::shutdown() { //this indicates that the socket to the server has closed we do //not want to send a close request (or any other requests) if(markClosed()) { - std::cout << "Connection to peer closed!" << std::endl; + QPID_LOG(info, "Connection to peer closed!"); closeChannels(); } } @@ -88,11 +89,13 @@ void Connection::close( ) { if(markClosed()) { - // TODO aconway 2007-01-29: Exception handling - could end up - // partly closed with threads left unjoined. - channel0.sendAndReceive<ConnectionCloseOkBody>( - make_shared_ptr(new ConnectionCloseBody( - getVersion(), code, msg, classId, methodId))); + try { + channel0.sendAndReceive<ConnectionCloseOkBody>( + make_shared_ptr(new ConnectionCloseBody( + getVersion(), code, msg, classId, methodId))); + } catch (const std::exception& e) { + QPID_LOG(error, "Exception closing channel: " << e.what()); + } closeChannels(); connector->close(); } diff --git a/cpp/src/qpid/client/Connector.cpp b/cpp/src/qpid/client/Connector.cpp index 3447467fda..18cb0e064b 100644 --- a/cpp/src/qpid/client/Connector.cpp +++ b/cpp/src/qpid/client/Connector.cpp @@ -19,6 +19,7 @@ * */ #include <iostream> +#include "qpid/log/Statement.h" #include "qpid/QpidError.h" #include "qpid/sys/Time.h" #include "Connector.h" @@ -82,7 +83,7 @@ void Connector::send(AMQFrame* f){ std::auto_ptr<AMQFrame> frame(f); AMQBody::shared_ptr body = frame->getBody(); writeBlock(frame.get()); - if(debug) std::cout << "SENT: " << *frame << std::endl; + QPID_LOG(trace, "SENT: " << *frame); } void Connector::writeBlock(AMQDataBlock* data){ @@ -182,7 +183,7 @@ void Connector::run(){ AMQFrame frame(version); while(frame.decode(inbuf)){ - if(debug) std::cout << "RECV: " << frame << std::endl; + QPID_LOG(trace, "RECV: " << frame); input->received(&frame); } //need to compact buffer to preserve any 'extra' data @@ -190,7 +191,7 @@ void Connector::run(){ } } } catch (const std::exception& e) { - std::cout << e.what() << std::endl; + QPID_LOG(error, e.what()); handleClosed(); } } diff --git a/cpp/src/qpid/client/MessageMessageChannel.cpp b/cpp/src/qpid/client/MessageMessageChannel.cpp index 6ba5e00153..c73f501ec5 100644 --- a/cpp/src/qpid/client/MessageMessageChannel.cpp +++ b/cpp/src/qpid/client/MessageMessageChannel.cpp @@ -381,7 +381,7 @@ void MessageMessageChannel::run() { // } // if(handler == 0) { // // TODO aconway 2007-02-20: proper logging. -// cout << "Message returned: " << msg.getData() << endl; +// QPID_LOG(warn, "No handler for message."); // } // else // handler->returned(msg); @@ -407,9 +407,7 @@ void MessageMessageChannel::run() { // /* Orderly shutdown */ // } // catch (const Exception& e) { -// // FIXME aconway 2007-02-20: Report exception to user. -// cout << "client::Message::run() terminated by: " << e.toString() -// << "(" << typeid(e).name() << ")" << endl; +// QPID_LOG(error, e.what()); // } // } } diff --git a/cpp/src/qpid/log/Logger.cpp b/cpp/src/qpid/log/Logger.cpp new file mode 100644 index 0000000000..065d4508c7 --- /dev/null +++ b/cpp/src/qpid/log/Logger.cpp @@ -0,0 +1,204 @@ +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "Logger.h" +#include "Options.h" +#include "qpid/memory.h" +#include "qpid/sys/Thread.h" +#include <boost/pool/detail/singleton.hpp> +#include <boost/bind.hpp> +#include <boost/function.hpp> +#include <boost/date_time/posix_time/posix_time.hpp> +#include <boost/scoped_ptr.hpp> +#include <algorithm> +#include <sstream> +#include <fstream> +#include <iomanip> +#include <syslog.h> + + +namespace qpid { +namespace log { + +using namespace std; + +typedef sys::Mutex::ScopedLock ScopedLock; + +inline void Logger::enable_unlocked(Statement* s) { + s->enabled=selector.isEnabled(s->level, s->file); +} + +struct OstreamOutput : public Logger::Output { + OstreamOutput(std::ostream& o) : out(&o) {} + + OstreamOutput(const string& file) + : out(new ofstream(file.c_str())), mine(out) + { + if (!out->good()) + throw Exception("Can't open log file: "+file); + } + + void log(const Statement&, const std::string& m) { + *out << m << flush; + } + + ostream* out; + boost::scoped_ptr<ostream> mine; +}; + +struct SyslogOutput : public Logger::Output { + SyslogOutput(const std::string& name, int facility_=LOG_USER) + : progName(name), facility(facility_) + { + ::openlog(name.c_str(), LOG_PID, facility); + } + + ~SyslogOutput() { + ::closelog(); + } + + void log(const Statement& s, const std::string& m) + { + syslog(LevelTraits::priority(s.level), "%s", m.c_str()); + } + + std::string progName; + int facility; +}; + +Logger& Logger::instance() { + return boost::details::pool::singleton_default<Logger>::instance(); +} + +Logger::Logger() : flags(0) {} +Logger::~Logger() {} + +void Logger::select(const Selector& s) { + ScopedLock l(lock); + selector=s; + std::for_each(statements.begin(), statements.end(), + boost::bind(&Logger::enable_unlocked, this, _1)); +} + +Logger::Output::Output() {} +Logger::Output::~Output() {} + +void Logger::log(const Statement& s, const std::string& msg) { + // Format the message outside the lock. + std::ostringstream os; + if (flags&TIME) + os << boost::posix_time::second_clock::local_time() << " "; + if (flags&LEVEL) + os << LevelTraits::name(s.level) << " "; + if (flags&THREAD) + os << "[" << hex << qpid::sys::Thread::logId() << "] "; + if (flags&FILE) + os << s.file << ":"; + if (flags&LINE) + os << dec << s.line << ":"; + if (flags&FUNCTION) + os << s.function << ":"; + if (flags & (FILE|LINE|FUNCTION)) + os << " "; + os << msg << endl; + std::string formatted=os.str(); + + { + ScopedLock l(lock); + std::for_each(outputs.begin(), outputs.end(), + boost::bind(&Output::log, _1, s, formatted)); + } +} + +void Logger::output(std::auto_ptr<Output> out) { + ScopedLock l(lock); + outputs.push_back(out.release()); +} + +void Logger::output(std::ostream& out) { + output(make_auto_ptr<Output>(new OstreamOutput(out))); +} + +void Logger::syslog(const std::string& progName) { + output(make_auto_ptr<Output>(new SyslogOutput(progName))); +} + +void Logger::output(const std::string& name) { + if (name=="stderr") + output(clog); + else if (name=="stdout") + output(cout); + else if (name=="syslog") + syslog(syslogName); + else + output(make_auto_ptr<Output>(new OstreamOutput(name))); +} + +void Logger::clear() { + select(Selector()); // locked + format(0); // locked + ScopedLock l(lock); + outputs.clear(); +} + +void Logger::format(int formatFlags) { + ScopedLock l(lock); + flags=formatFlags; +} + +static int bitIf(bool test, int bit) { + return test ? bit : 0; +} + +int Logger::format(const Options& opts) { + int flags= + bitIf(opts.level, LEVEL) | + bitIf(opts.time, TIME) | + bitIf(opts.source, (FILE|LINE)) | + bitIf(opts.function, FUNCTION) | + bitIf(opts.thread, THREAD); + format(flags); + return flags; +} + +void Logger::add(Statement& s) { + ScopedLock l(lock); + enable_unlocked(&s); + statements.insert(&s); +} + +void Logger::remove(Statement& s) { + ScopedLock l(lock); + s.enabled = false; + statements.erase(&s); +} + +void Logger::configure(const Options& o, const std::string& prog) +{ + { + ScopedLock l(lock); + syslogName=prog; + } + format(o); + select(Selector(o)); + void (Logger::* outputFn)(const std::string&) = &Logger::output; + for_each(o.outputs.begin(), o.outputs.end(), + boost::bind(outputFn, this, _1)); +} + +}} // namespace qpid::log diff --git a/cpp/src/qpid/log/Logger.h b/cpp/src/qpid/log/Logger.h new file mode 100644 index 0000000000..a2103f5ec6 --- /dev/null +++ b/cpp/src/qpid/log/Logger.h @@ -0,0 +1,116 @@ +#ifndef LOGGER_H +#define LOGGER_H + +/* + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "Selector.h" +#include "qpid/sys/Mutex.h" +#include <boost/ptr_container/ptr_vector.hpp> +#include <boost/noncopyable.hpp> +#include <set> + +namespace qpid { +namespace log { + +class Options; + +/** + * Central logging agent. + * + * Thread safe, singleton. + */ +class Logger : private boost::noncopyable { + public: + /** Flags indicating what to include in the log output */ + enum FormatFlag { FILE=1, LINE=2, FUNCTION=4, LEVEL=8, TIME=16, THREAD=32}; + + /** Interface for log output destination. + * + * Implementations must be thread safe. + */ + class Output { + public: + Output(); + virtual ~Output(); + /** Receives the statemnt of origin and formatted message to log. */ + virtual void log(const Statement&, const std::string&) =0; + }; + + static Logger& instance(); + + Logger(); + ~Logger(); + + /** Select the messages to be logged. */ + void select(const Selector& s); + + /** Set the formatting flags, bitwise OR of FormatFlag values. */ + void format(int formatFlags); + + /** Set format flags from options object. + *@returns computed flags. + */ + int format(const Options&); + + /** Configure logger from Options */ + void configure(const Options& o, const std::string& progname); + + /** Add a statement. */ + void add(Statement& s); + + /** Remove a statement */ + void remove(Statement& s); + + /** Log a message. */ + void log(const Statement&, const std::string&); + + /** Add an ostream to outputs. + * + * The ostream must not be destroyed while the Logger might + * still be using it. This is the case for std streams cout, + * cerr, clog. + */ + void output(std::ostream&); + + /** Add syslog to outputs. */ + void syslog(const std::string& programName); + + /** Add an output. + *@param name a file name or one of the special tokens: + *stdout, stderr, syslog. + */ + void output(const std::string& name); + + /** Add an output destination for messages */ + void output(std::auto_ptr<Output> out); + + /** Reset the logger to it's original state */ + void clear(); + + private: + typedef boost::ptr_vector<Output> Outputs; + typedef std::set<Statement*> Statements; + + sys::Mutex lock; + inline void enable_unlocked(Statement* s); + + std::string syslogName; + Statements statements; + Outputs outputs; + Selector selector; + int flags; +}; + +}} // namespace qpid::log + + +#endif /*!LOGGER_H*/ diff --git a/cpp/src/qpid/log/Options.cpp b/cpp/src/qpid/log/Options.cpp new file mode 100644 index 0000000000..3e117663ff --- /dev/null +++ b/cpp/src/qpid/log/Options.cpp @@ -0,0 +1,69 @@ +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "Options.h" +#include "Statement.h" +#include "qpid/CommonOptions.h" + +namespace qpid { +namespace log { + +using namespace std; + +Options::Options() : + time(true), level(true), thread(false), source(false), function(false) +{ + outputs.push_back("stderr"); + selectors.push_back("error+"); +} + +void Options::addTo(po::options_description& desc) { + using namespace po; + ostringstream levels; + levels << LevelTraits::name(Level(0)); + for (int i = 1; i < LevelTraits::COUNT; ++i) + levels << " " << LevelTraits::name(Level(i)); + desc.add_options() + ("log.enable", optValue(selectors, "RULE"), + "You can specify this option mutliple times.\n" + "RULE is of the form 'LEVEL[+][:COMPONENT]'" + "Levels are: trace, debug, info, notice, warning, error, critical." + "For example:\n" + "\t'--log.enable warning+' " + "enables all warning, error and critical messages.\n" + "\t'--log.enable debug:framing' " + "enables debug messages from the framing component.") + ("log.output", optValue(outputs, "FILE"), + "File to receive log output, or one of these special values: " + "'stderr', 'stdout', 'syslog'.") + ("log.time", optValue(time, "yes|no"), + "Include time in log messages") + ("log.level", optValue(level,"yes|no"), + "Include severity level in log messages") + ("log.source", optValue(source,"yes|no"), + "Include source file:line in log messages") + ("log.thread", optValue(thread,"yes|no"), + "Include thread ID in log messages") + ("log.function", optValue(function,"yes|no"), + "Include function signature in log messages"); + +} + + + +}} // namespace qpid::log diff --git a/cpp/src/qpid/log/Options.h b/cpp/src/qpid/log/Options.h new file mode 100644 index 0000000000..39261c9b5d --- /dev/null +++ b/cpp/src/qpid/log/Options.h @@ -0,0 +1,42 @@ +#ifndef OPTIONS_H +#define OPTIONS_H + +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ +#include "qpid/CommonOptions.h" + + +namespace qpid { +namespace log { + +/** Logging options for config parser. */ +struct Options { + Options(); + void addTo(po::options_description&); + + std::vector<std::string> selectors; + std::vector<std::string> outputs; + bool time, level, thread, source, function; +}; + + +}} // namespace qpid::log + + + +#endif /*!OPTIONS_H*/ diff --git a/cpp/src/qpid/log/Selector.cpp b/cpp/src/qpid/log/Selector.cpp new file mode 100644 index 0000000000..e8cef2b17d --- /dev/null +++ b/cpp/src/qpid/log/Selector.cpp @@ -0,0 +1,66 @@ +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "Selector.h" +#include "Options.h" +#include <boost/bind.hpp> +#include <algorithm> + +namespace qpid { +namespace log { + +using namespace std; + +void Selector::enable(const string& enableStr) { + string level, pattern; + size_t c=enableStr.find(':'); + if (c==string::npos) { + level=enableStr; + } + else { + level=enableStr.substr(0,c); + pattern=enableStr.substr(c+1); + } + if (!level.empty() && level[level.size()-1]=='+') { + for (int i = LevelTraits::level(level.substr(0,level.size()-1)); + i < LevelTraits::COUNT; + ++i) + enable(Level(i), pattern); + } + else { + enable(LevelTraits::level(level), pattern); + } +} + +Selector::Selector(const Options& opt){ + for_each(opt.selectors.begin(), opt.selectors.end(), + boost::bind(&Selector::enable, this, _1)); +} + +bool Selector::isEnabled(Level level, const std::string& file) { + for (std::vector<std::string>::iterator i=substrings[level].begin(); + i != substrings[level].end(); + ++i) + { + if (file.find(*i) != std::string::npos) + return true; + } + return false; +} + +}} // namespace qpid::log diff --git a/cpp/src/qpid/log/Selector.h b/cpp/src/qpid/log/Selector.h new file mode 100644 index 0000000000..329541b7fc --- /dev/null +++ b/cpp/src/qpid/log/Selector.h @@ -0,0 +1,68 @@ +#ifndef SELECTOR_H +#define SELECTOR_H + +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "Statement.h" +#include <vector> + +namespace qpid { +namespace log { +class Options; + +/** + * A selector identifies the set of log messages to enable. + * + * Thread object unsafe, pass-by-value type. + */ +class Selector { + public: + /** Empty selector selects nothing */ + Selector() {} + + /** Set selector from Options */ + Selector(const Options&); + + /** Equavlient to: Selector s; s.enable(l, s) */ + Selector(Level l, const std::string& s=std::string()) { + enable(l,s); + } + /** + * Enable messages with level in levels where the file + * name contains substring. Empty string matches all. + */ + void enable(Level level, const std::string& substring=std::string()) { + substrings[level].push_back(substring); + } + + /** Enable based on a 'level[+]:file' string */ + void enable(const std::string& enableStr); + + /** True if level is enabld for file. */ + bool isEnabled(Level level, const std::string& file); + + private: + std::vector<std::string> substrings[LevelTraits::COUNT]; +}; + + +}} // namespace qpid::log + + +#endif /*!SELECTOR_H*/ diff --git a/cpp/src/qpid/log/Statement.cpp b/cpp/src/qpid/log/Statement.cpp new file mode 100644 index 0000000000..9ab314b81c --- /dev/null +++ b/cpp/src/qpid/log/Statement.cpp @@ -0,0 +1,67 @@ +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "Statement.h" +#include "Logger.h" +#include "qpid/Exception.h" +#include <syslog.h> + +namespace qpid { +namespace log { + +void Statement::log(const std::string& message) { + Logger::instance().log(*this,message); +} + +Statement::Initializer::Initializer(Statement& s) : statement(s) { + Logger::instance().add(s); +} + +Statement::Initializer::~Initializer() { + Logger::instance().remove(statement); +} + +namespace { +const char* names[LevelTraits::COUNT] = { + "trace", "debug", "info", "notice", "warning", "error", "critical" +}; + +int priorities[LevelTraits::COUNT] = { + LOG_DEBUG, LOG_DEBUG, LOG_INFO, LOG_NOTICE, + LOG_WARNING, LOG_ERR, LOG_CRIT +}; + +} // namespace + +Level LevelTraits::level(const char* name) { + for (int i =0; i < LevelTraits::COUNT; ++i) { + if (strcmp(names[i], name)==0) + return Level(i); + } + throw qpid::Exception(std::string("Invalid log level name: ")+name); +} + +const char* LevelTraits::name(Level l) { + return names[l]; +} + +int LevelTraits::priority(Level l) { + return priorities[l]; +} + +}} // namespace qpid::log diff --git a/cpp/src/qpid/log/Statement.h b/cpp/src/qpid/log/Statement.h new file mode 100644 index 0000000000..a04755012b --- /dev/null +++ b/cpp/src/qpid/log/Statement.h @@ -0,0 +1,124 @@ +#ifndef STATEMENT_H +#define STATEMENT_H + +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "qpid/log/Statement.h" +#include <boost/current_function.hpp> +#include <sstream> + +namespace qpid { +namespace log { + +/** Debugging severity levels + * - trace: High-volume debugging messages. + * - debug: Debugging messages. + * - info: Informational messages. + * - notice: Normal but significant condition. + * - warning: Warn of a possible problem. + * - error: A definite error has occured. + * - critical: System in danger of severe failure. + */ +enum Level { trace, debug, info, notice, warning, error, critical }; +struct LevelTraits { + static const int COUNT=critical+1; + + /** Get level from string name. + *@exception if name invalid. + */ + static Level level(const char* name); + + /** Get level from string name. + *@exception if name invalid. + */ + static Level level(const std::string& name) { + return level(name.c_str()); + } + + /** String name of level */ + static const char* name(Level); + + /** Syslog priority of level */ + static int priority(Level); +}; + +/** POD struct representing a logging statement in source code. */ +struct Statement { + bool enabled; + const char* file; + int line; + const char* function; + Level level; + + void log(const std::string& message); + + struct Initializer { + Initializer(Statement& s); + ~Initializer(); + Statement& statement; + }; +}; + +///@internal trickery to make QPID_LOG_STRINGSTREAM work. +inline std::ostream& noop(std::ostream& s) { return s; } + +///@internal static initializer for a Statement. +#define QPID_LOG_STATEMENT_INIT(level) \ + { 0, __FILE__, __LINE__, BOOST_CURRENT_FUNCTION, (::qpid::log::level) } + +///@internal Stream streamable message and return a string. +#define QPID_LOG_STRINGSTREAM(message) \ + static_cast<std::ostringstream&>( \ + std::ostringstream() << qpid::log::noop << message).str() + +/** + * Macro for log statements. Example of use: + * @code + * QPID_LOG(debug, "There are " << foocount << " foos in the bar."); + * QPID_LOG(error, boost::format("Dohickey %s exploded") % dohicky.name()); + * @endcode + * + * All code with logging statements should be built with + * -DQPID_COMPONENT=<component name> + * where component name is the name of the component this file belongs to. + * + * You can subscribe to log messages by level, by component, by filename + * or a combination @see Configuration. + + *@param LEVEL severity Level for message, should be one of: + * debug, info, notice, warning, error, critical. NB no qpid::log:: prefix. + *@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_LOG_STRINGSTREAM(message)); \ + } while(0) + + +}} // namespace qpid::log + + + + +#endif /*!STATEMENT_H*/ + diff --git a/cpp/src/qpid/memory.h b/cpp/src/qpid/memory.h new file mode 100644 index 0000000000..99d7a71e7b --- /dev/null +++ b/cpp/src/qpid/memory.h @@ -0,0 +1,32 @@ +#ifndef QPID_AUTO_PTR_H +#define QPID_AUTO_PTR_H + +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include <memory> +namespace qpid { +/** Convenient template for creating auto_ptr in-place in an argument list. */ +template <class T> +std::auto_ptr<T> make_auto_ptr(T* ptr) { return std::auto_ptr<T>(ptr); } + +} // namespace qpid + + + +#endif /*!QPID_AUTO_PTR_H*/ 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(); diff --git a/cpp/src/qpidd.cpp b/cpp/src/qpidd.cpp index 7b4c537d94..92935ed838 100644 --- a/cpp/src/qpidd.cpp +++ b/cpp/src/qpidd.cpp @@ -19,12 +19,15 @@ * */ #include "qpid/broker/Broker.h" +#include "qpid/sys/posix/check.h" +#include "qpid/broker/Daemon.h" +#include "qpid/log/Statement.h" +#include "qpid/log/Options.h" +#include "qpid/log/Logger.h" +#include "config.h" #include <iostream> #include <fstream> #include <signal.h> -#include "config.h" -#include "qpid/sys/posix/check.h" -#include "qpid/broker/Daemon.h" using namespace qpid; using namespace qpid::broker; @@ -34,15 +37,16 @@ using namespace std; Broker::shared_ptr brokerPtr; void handle_signal(int /*signal*/){ - std::cerr << "Shutting down..." << std::endl; + QPID_LOG(notice, "Shutting down..."); brokerPtr->shutdown(); } /** Command line options */ -struct QpiddOptions : public Broker::Options +struct QpiddOptions : public Broker::Options, public log::Options { bool help; + bool longHelp; bool version; bool daemon; bool quit; @@ -51,50 +55,56 @@ struct QpiddOptions : public Broker::Options bool ppid; int wait; string config; - po::options_description desc; + po::options_description mainOpts; + po::options_description allOpts; + po::options_description logOpts; QpiddOptions() : help(false), version(false), daemon(false), quit(false), kill(false), check(false), ppid(false), wait(10), config("/etc/qpidd.conf"), - desc("Options") + mainOpts("Options"), + logOpts("Logging Options") { using namespace po; - desc.add_options() + mainOpts.add_options() ("daemon,d", optValue(daemon), "Run as a daemon.") ("quit,q", optValue(quit), "Stop the running daemon politely.") ("kill,k", optValue(kill), "Kill the running daemon harshly.") ("check,c", optValue(check), "If daemon is running return 0.") ("wait", optValue(wait, "SECONDS"), "Maximum wait for daemon response.") - ("ppid", optValue(ppid), "Print daemon pid to stdout" ); + ("ppid", optValue(ppid), "Print daemon pid to stdout." ); po::options_description brokerOpts; - Broker::Options::addTo(desc); - desc.add_options() - ("config", optValue(config, "FILE"), "Configuration file") - ("help,h", optValue(help), "Print help message") - ("version,v", optValue(version), "Print version information"); + Broker::Options::addTo(mainOpts); + mainOpts.add_options() + ("config", optValue(config, "FILE"), "Configuation file.") + ("help,h", optValue(help), "Print help message.") + ("long-help", optValue(longHelp), "Show complete list of options.") + ("version,v", optValue(version), "Print version information."); + + log::Options::addTo(logOpts); + allOpts.add(mainOpts).add(logOpts); } void parse(int argc, char* argv[]) { - parseOptions(desc, argc, argv, config); + parseOptions(allOpts, argc, argv, config); } - void usage(ostream& out) const { - out << "Usage: qpidd [OPTIONS]" << endl << endl - << desc << endl; + void usage(const po::options_description& opts) const { + cout << "Usage: qpidd [OPTIONS]" << endl << endl + << opts << endl; }; }; -ostream& operator<<(ostream& out, const QpiddOptions& config) { - config.usage(out); return out; -} - int main(int argc, char* argv[]) { QpiddOptions config; try { config.parse(argc, argv); + if (config.trace) + config.selectors.push_back("trace"); + log::Logger::instance().configure(config, argv[0]); string name=(boost::format("%s.%d") % Daemon::nameFromArgv0(argv[0]) % (config.port)).str(); @@ -102,17 +112,18 @@ int main(int argc, char* argv[]) Daemon demon(name, config.wait); // Options that just print information. - if(config.help) { - config.usage(cout); - return 0; - } - if (config.version) { - cout << "qpidd (" << PACKAGE_NAME << ") version " - << PACKAGE_VERSION << endl; + if(config.help || config.longHelp || config.version) { + if (config.version) + cout << "qpidd (" << PACKAGE_NAME << ") version " + << PACKAGE_VERSION << endl; + if (config.longHelp) + config.usage(config.allOpts); + else if (config.help) + config.usage(config.mainOpts); return 0; } - // Options that affect an already running daemon. + // Options that act on an already running daemon. if (config.quit || config.kill || config.check) { pid_t pid = demon.check(); if (config.ppid && pid > 0) @@ -136,8 +147,7 @@ int main(int argc, char* argv[]) demon.ready(); // Notify parent we're ready. brokerPtr->run(); } catch (const exception& e) { - // TODO aconway 2007-04-26: Log this, cerr is lost. - cerr << "Broker daemon failed: " << e.what() << endl; + QPID_LOG(critical, "Broker daemon startup failed: " << e.what()); demon.failed(); // Notify parent we failed. return 1; } @@ -147,7 +157,7 @@ int main(int argc, char* argv[]) cout << pid << endl; return 0; } - else { // pid < 0 + else { // pid < 0 throw Exception("fork failed"+strError(errno)); } } // Non-daemon broker. @@ -163,6 +173,8 @@ int main(int argc, char* argv[]) << "Type 'qpidd --help' for usage." << endl; } catch(const exception& e) { + // Could be child or parent so log and print. + QPID_LOG(error, e.what()); cerr << "Error: " << e.what() << endl; } return 1; diff --git a/cpp/src/tests/.valgrind.supp b/cpp/src/tests/.valgrind.supp-default index 8b13789179..8b13789179 100644 --- a/cpp/src/tests/.valgrind.supp +++ b/cpp/src/tests/.valgrind.supp-default diff --git a/cpp/src/tests/AccumulatedAckTest.cpp b/cpp/src/tests/AccumulatedAckTest.cpp index aa90de5b42..edd4b0d807 100644 --- a/cpp/src/tests/AccumulatedAckTest.cpp +++ b/cpp/src/tests/AccumulatedAckTest.cpp @@ -1,3 +1,4 @@ + /* * * Licensed to the Apache Software Foundation (ASF) under one diff --git a/cpp/src/tests/Makefile.am b/cpp/src/tests/Makefile.am index 198c9ce7ef..699a2f073c 100644 --- a/cpp/src/tests/Makefile.am +++ b/cpp/src/tests/Makefile.am @@ -1,6 +1,17 @@ AM_CXXFLAGS = $(WARNING_CFLAGS) $(CPPUNIT_CXXFLAGS) $(APR_CXXFLAGS) INCLUDES = -I$(srcdir)/.. -I$(srcdir)/../gen -I$(top_builddir)/src/gen + +# Unit test programs +UNIT_TESTS= + +UNIT_TESTS+=logging +logging_SOURCES=unit/logging.cpp unit/test_tools.h +logging_LDADD=-lboost_unit_test_framework -lboost_regex $(lib_common) + +# NB: CppUnit test libraries below will be migrated to boost test programs. +# UNIT_TESTS+= ... + # Unit tests broker_unit_tests = \ AccumulatedAckTest \ @@ -52,19 +63,24 @@ testprogs = \ topic_listener \ topic_publisher -noinst_PROGRAMS = $(testprogs) +check_PROGRAMS = $(UNIT_TESTS) $(testprogs) +# FIXME aconway 2007-05-30: TESTS_ENVIRONMENT should have ./run_test +# as below to run valgrind on all test programs. +# Disabled temporarily till leaks in client_test are fixed. +# +#TESTS_ENVIRONMENT = VALGRIND=$(VALGRIND) srcdir=$(srcdir) ./run_test TESTS_ENVIRONMENT = VALGRIND=$(VALGRIND) srcdir=$(srcdir) -CLIENT_TESTS = client_test quick_topictest -TESTS = run-unit-tests start_broker $(CLIENT_TESTS) python_tests kill_broker daemon_test +SYSTEM_TESTS = client_test quick_topictest +TESTS = $(UNIT_TESTS) run-unit-tests start_broker $(SYSTEM_TESTS) python_tests kill_broker daemon_test EXTRA_DIST = \ test_env \ run-unit-tests start_broker python_tests kill_broker daemon_test \ quick_topictest \ topictest \ - .valgrind.supp \ + .valgrind.supp-default \ .valgrindrc-default \ InProcessBroker.h \ MockChannel.h \ @@ -103,20 +119,21 @@ gen.mk: Makefile.am > $@-t mv $@-t $@ -check: .valgrindrc ../qpidd +check: .valgrindrc .valgrind.supp check-unit: - $(MAKE) check TESTS=run-unit-tests + $(MAKE) check TESTS=$(UNIT_TESTS) run-unit-tests # Create a copy so that can be modified without risk of committing the changes. .valgrindrc: .valgrindrc-default - cp $(srcdir)/.valgrindrc-default .valgrindrc + cp $^ $@ +.valgrind.supp: .valgrind.supp-default + cp $^ $@ # Tell GNU make not to build targets in this directory in parallel. # This is necessary because with two or more identical and simultaneous # ltmain invocations, one may corrupt the temporaries of the other. .NOTPARALLEL: -CLEANFILES=valgrind.out qpidd.log -DISTCLEANFILES=.valgrindrc +CLEANFILES=valgrind.out qpidd.log .valgrindrc .valgrind.supp MAINTAINERCLEANFILES=gen.mk diff --git a/cpp/src/tests/kill_broker b/cpp/src/tests/kill_broker index b71ca22ffd..e6331d6876 100755 --- a/cpp/src/tests/kill_broker +++ b/cpp/src/tests/kill_broker @@ -1,3 +1,2 @@ #!/bin/sh -PID=qpidd.pid -if [ -f $PID ] ; then kill -9 `cat $PID` ; rm -f $PID ; fi +../qpidd --quit diff --git a/cpp/src/tests/run_test b/cpp/src/tests/run_test new file mode 100755 index 0000000000..ef608e55ca --- /dev/null +++ b/cpp/src/tests/run_test @@ -0,0 +1,60 @@ +#!/bin/sh +# +# Run a test executable. Output nothing if test passes, +# show the output if it fails. Leave output in <test>.log for +# examination. +# +# If $VALGRIND if is set run under valgrind. If there are +# valgrind erros show valgrind output, also leave it in +# <test>.valgrind for examination. +# + +vg_failed() { + cat $VG_LOG 1>&2 + echo $1 1>&2 + exit 1 +} + +vg_check() +{ + test -f $VG_LOG || vg_failed Valgrind log file $VG_LOG missing. + # Ensure there is an ERROR SUMMARY line. + grep -E '^==[0-9]+== ERROR SUMMARY:' $VG_LOG > /dev/null || \ + vg_failed "No valgrind ERROR SUMMARY line in $$vg_failed." + # Ensure that the number of errors is 0. + grep -E '^==[0-9]+== ERROR SUMMARY: [^0] ' $VG_LOG > /dev/null && \ + vg_failed "Valgrind reported errors in $vg_out; see above." + # Check for leaks. + grep -E '^==[0-9]+== +.* lost: [^0]' $VG_LOG && \ + vg_failed "Found memory leaks (see log file, $VG_LOG); see above." + true +} + +# Export variables from makefile. +export VALGRIND srcdir + +VG_LOG="$1.vglog" +TEST_LOG="$1.log" +rm -f $VG_LOG $TEST_LOG + +if grep -l "^# Generated by .*libtool" "$1" >/dev/null 2>&1; then + # This is a libtool "executable". Valgrind it if VALGRIND specified. + test -n "$VALGRIND" && VALGRIND="$VALGRIND --log-file-exactly=$VG_LOG --" + # Hide output unless there's an error. + libtool --mode=execute $VALGRIND "$@" >$TEST_LOG 2>&1 || { + ERROR=$? + cat $TEST_LOG + } + test -n "$VALGRIND" && vg_check +else + # This is a non-libtool shell script, just execute it. + "$@" +fi + +if test -z "$ERROR"; then + # Clean up logs if there was no error. + rm -f $VG_LOG $TEST_LOG + exit 0 +else + exit $ERROR +fi diff --git a/cpp/src/tests/start_broker b/cpp/src/tests/start_broker index dfbaee6bcc..515a3a2b5e 100755 --- a/cpp/src/tests/start_broker +++ b/cpp/src/tests/start_broker @@ -1,14 +1,5 @@ #!/bin/sh -set -e - -LOG=`pwd`/qpidd.log -PID=`pwd`/qpidd.pid - -rm -rf $LOG $PID - -# Start the daemon, recording its PID. -../qpidd > $LOG 2>&1 & echo $! > $PID - -# FIXME aconway 2007-01-18: qpidd should not return till it is accepting -# connections, remove arbitrary sleep. -sleep 30 +fail() { echo FAIL: $0:$* 1>&2; exit 1; } +qpidd=../qpidd +PID=`$qpidd --check --ppid` && fail $qpidd already running $PID +$qpidd --log.output qpidd.log --daemon || fail $qpidd startup: `cat qpidd.log` diff --git a/cpp/src/tests/unit/logging.cpp b/cpp/src/tests/unit/logging.cpp new file mode 100644 index 0000000000..3dbe68ad2b --- /dev/null +++ b/cpp/src/tests/unit/logging.cpp @@ -0,0 +1,373 @@ +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#include "test_tools.h" +#include "qpid/log/Logger.h" +#include "qpid/log/Options.h" +#include "qpid/memory.h" +#include "qpid/CommonOptions.h" +#include <boost/test/floating_point_comparison.hpp> +#include <boost/format.hpp> +#include <exception> +#include <time.h> +#include <fstream> + + +using namespace std; +using namespace boost; +using namespace qpid::log; + +BOOST_AUTO_TEST_CASE(testStatementInit) { + Statement s=QPID_LOG_STATEMENT_INIT(debug); int line=__LINE__; + BOOST_CHECK(!s.enabled); + BOOST_CHECK_EQUAL(string(__FILE__), s.file); + BOOST_CHECK_EQUAL(line, s.line); + BOOST_CHECK_EQUAL(string("void testStatementInit()"), s.function); + BOOST_CHECK_EQUAL(debug, s.level); +} + + +BOOST_AUTO_TEST_CASE(testSelector_enable) { + Selector s; + // Simple enable + s.enable(debug,"foo"); + BOOST_CHECK(s.isEnabled(debug,"foo")); + BOOST_CHECK(!s.isEnabled(error,"foo")); + BOOST_CHECK(!s.isEnabled(error,"bar")); + + // Substring match + BOOST_CHECK(s.isEnabled(debug, "bazfoobar")); + BOOST_CHECK(!s.isEnabled(debug, "bazbar")); + + // Different levels for different substrings. + s.enable(info, "bar"); + BOOST_CHECK(s.isEnabled(debug, "foobar")); + BOOST_CHECK(s.isEnabled(info, "foobar")); + BOOST_CHECK(!s.isEnabled(debug, "bar")); + BOOST_CHECK(!s.isEnabled(info, "foo")); + + // Enable-strings + s.enable("notice:blob"); + BOOST_CHECK(s.isEnabled(notice, "blob")); + s.enable("error+:oops"); + BOOST_CHECK(s.isEnabled(error, "oops")); + BOOST_CHECK(s.isEnabled(critical, "oops")); +} + +Logger& clearLogger() { + Logger::instance().clear(); + return Logger::instance(); +} + +BOOST_AUTO_TEST_CASE(testStatementEnabled) { + // Verify that the logger enables and disables log statements. + Logger& l=clearLogger(); + l.select(Selector(debug)); + Statement s=QPID_LOG_STATEMENT_INIT(debug); + BOOST_CHECK(!s.enabled); + Statement::Initializer init(s); + BOOST_CHECK(s.enabled); + + Statement s2=QPID_LOG_STATEMENT_INIT(warning); + Statement::Initializer init2(s2); + BOOST_CHECK(!s2.enabled); + + l.select(Selector(warning)); + BOOST_CHECK(!s.enabled); + BOOST_CHECK(s2.enabled); +} + +struct TestOutput : public Logger::Output { + vector<string> msg; + vector<Statement> stmt; + + TestOutput() { + Logger::instance().output(qpid::make_auto_ptr<Logger::Output>(this)); + } + void log(const Statement& s, const string& m) { + msg.push_back(m); + stmt.push_back(s); + } + string last() { return msg.back(); } +}; + +using boost::assign::list_of; + +BOOST_AUTO_TEST_CASE(testLoggerOutput) { + Logger& l=clearLogger(); + l.select(Selector(debug)); + Statement s=QPID_LOG_STATEMENT_INIT(debug); + TestOutput* out=new TestOutput(); + + // Verify message is output. + l.log(s, "foo"); + vector<string> expect=list_of("foo\n"); + BOOST_CHECK_EQUAL(expect, out->msg); + + // Verify multiple outputs + TestOutput* out2=new TestOutput(); + l.log(Statement(), "baz"); + expect.push_back("baz\n"); + BOOST_CHECK_EQUAL(expect, out->msg); + expect.erase(expect.begin()); + BOOST_CHECK_EQUAL(expect, out2->msg); +} + +BOOST_AUTO_TEST_CASE(testMacro) { + Logger& l = clearLogger(); + l.select(Selector(info)); + TestOutput* out=new TestOutput(); + QPID_LOG(info, "foo"); + vector<string> expect=list_of("foo\n"); + BOOST_CHECK_EQUAL(expect, out->msg); + BOOST_CHECK_EQUAL(__FILE__, out->stmt.front().file); + BOOST_CHECK_EQUAL("void testMacro()", out->stmt.front().function); + + // Not enabled: + QPID_LOG(debug, "bar"); + BOOST_CHECK_EQUAL(expect, out->msg); + + QPID_LOG(info, 42 << " bingo"); + expect.push_back("42 bingo\n"); + BOOST_CHECK_EQUAL(expect, out->msg); +} + +BOOST_AUTO_TEST_CASE(testLoggerFormat) { + Logger& l=clearLogger(); + l.select(Selector(critical)); + TestOutput* out=new TestOutput(); + + // Time format is YYY-Month-dd hh:mm:ss + l.format(Logger::TIME); + QPID_LOG(critical, "foo"); + string re("\\d\\d\\d\\d-[A-Z][a-z]+-\\d\\d \\d\\d:\\d\\d:\\d\\d foo\n"); + BOOST_CHECK_REGEX(re, out->last()); + + l.format(Logger::FILE); + QPID_LOG(critical, "foo"); + BOOST_CHECK_EQUAL(out->last(), string(__FILE__)+": foo\n"); + + l.format(Logger::FILE|Logger::LINE); + QPID_LOG(critical, "foo"); + BOOST_CHECK_REGEX(string(__FILE__)+":\\d+: foo\n", out->last()); + + l.format(Logger::FUNCTION); + QPID_LOG(critical, "foo"); + BOOST_CHECK_EQUAL("void testLoggerFormat(): foo\n", out->last()); + + l.format(Logger::LEVEL); + QPID_LOG(critical, "foo"); + BOOST_CHECK_EQUAL("critical foo\n", out->last()); + + l.format(~0); // Everything + QPID_LOG(critical, "foo"); + re=".* critical \\[[0-9a-f]*] "+string(__FILE__)+":\\d+:void testLoggerFormat\\(\\): foo\n"; + BOOST_CHECK_REGEX(re, out->last()); +} + +BOOST_AUTO_TEST_CASE(testOstreamOutput) { + Logger& l=clearLogger(); + l.select(Selector(error)); + ostringstream os; + l.output(os); + QPID_LOG(error, "foo"); + QPID_LOG(error, "bar"); + QPID_LOG(error, "baz"); + BOOST_CHECK_EQUAL("foo\nbar\nbaz\n", os.str()); + l.clear(); +} + +#if 0 // This test requires manual intervention. Normally disabled. +BOOST_AUTO_TEST_CASE(testSyslogOutput) { + Logger& l = clearLogger(); + l.select(Selector(info)); + l.syslog("qpid_test"); + QPID_LOG(info, "Testing QPID"); + BOOST_ERROR("Manually verify that /var/log/messages contains a recent line 'Testing QPID'"); +} +#endif // 0 + +int count() { + static int n = 0; + return n++; +} + +int loggedCount() { + static int n = 0; + QPID_LOG(debug, "counting: " << n); + return n++; +} + + +using namespace qpid::sys; + +// Measure CPU time. +clock_t timeLoop(int times, int (*fp)()) { + clock_t start=clock(); + while (times-- > 0) + (*fp)(); + return clock() - start; +} + +// Overhead test disabled because it consumes a ton of CPU and takes +// forever under valgrind. Not friendly for regular test runs. +// +#if 0 +BOOST_AUTO_TEST_CASE(testOverhead) { + // Ensure that the ratio of CPU time for an incrementing loop + // with and without disabled log statements is in acceptable limits. + // + int times=100000000; + clock_t noLog=timeLoop(times, count); + clock_t withLog=timeLoop(times, loggedCount); + double ratio=double(withLog)/double(noLog); + + // NB: in initial tests the ratio was consistently below 1.5, + // 2.5 is reasonable and should avoid spurios failures + // due to machine load. + // + BOOST_CHECK_SMALL(ratio, 2.5); +} +#endif // 0 + +Statement statement( + Level level, const char* file="", int line=0, const char* fn=0) +{ + Statement s={0, file, line, fn, level}; + return s; +} + + +struct TestOptions : public Options { + TestOptions(int argc, char** argv) { + qpid::po::options_description desc; + addTo(desc); + qpid::parseOptions(desc, argc, argv); + } +}; + +#define ARGC(argv) (sizeof(argv)/sizeof(char*)) + +BOOST_AUTO_TEST_CASE(testOptionsParse) { + char* argv[]={ + 0, + "--log.enable", "error+:foo", + "--log.enable", "debug:bar", + "--log.enable", "info", + "--log.output", "x", + "--log.output", "y", + "--log.level", "yes", + "--log.source", "1", + "--log.thread", "true", + "--log.function", "YES" + }; + TestOptions opts(ARGC(argv), argv); + vector<string> expect=list_of("error+:foo")("debug:bar")("info"); + BOOST_CHECK_EQUAL(expect, opts.selectors); + expect=list_of("x")("y"); + BOOST_CHECK_EQUAL(expect, opts.outputs); + BOOST_CHECK(opts.level); + BOOST_CHECK(opts.source); + BOOST_CHECK(opts.function); + BOOST_CHECK(opts.thread); +} + +BOOST_AUTO_TEST_CASE(testOptionsDefault) { + Options opts; + vector<string> expect=list_of("stderr"); + BOOST_CHECK_EQUAL(expect, opts.outputs); + expect=list_of("error+"); + BOOST_CHECK_EQUAL(expect, opts.selectors); + BOOST_CHECK(opts.time && opts.level); + BOOST_CHECK(!(opts.source || opts.function || opts.thread)); +} + +BOOST_AUTO_TEST_CASE(testSelectorFromOptions) { + char* argv[]={ + 0, + "--log.enable", "error+:foo", + "--log.enable", "debug:bar", + "--log.enable", "info" + }; + TestOptions opts(ARGC(argv), argv); + vector<string> expect=list_of("error+:foo")("debug:bar")("info"); + BOOST_CHECK_EQUAL(expect, opts.selectors); + Selector s(opts); + BOOST_CHECK(!s.isEnabled(warning, "x")); + BOOST_CHECK(!s.isEnabled(debug, "x")); + BOOST_CHECK(s.isEnabled(debug, "bar")); + BOOST_CHECK(s.isEnabled(error, "foo")); + BOOST_CHECK(s.isEnabled(critical, "foo")); +} + +BOOST_AUTO_TEST_CASE(testOptionsFormat) { + Logger& l = clearLogger(); + Options opts; + BOOST_CHECK_EQUAL(Logger::TIME|Logger::LEVEL, l.format(opts)); + char* argv[]={ + 0, + "--log.time", "no", + "--log.level", "no", + "--log.source", "1", + "--log.thread", "1" + }; + qpid::po::options_description desc; + opts.addTo(desc); + qpid::parseOptions(desc, ARGC(argv), argv); + BOOST_CHECK_EQUAL( + Logger::FILE|Logger::LINE|Logger::THREAD, l.format(opts)); + opts = Options(); // Clear. + char* argv2[]={ + 0, + "--log.level", "no", + "--log.thread", "true", + "--log.function", "YES", + "--log.time", "YES" + }; + qpid::po::options_description desc2; + opts.addTo(desc2); + qpid::parseOptions(desc2, ARGC(argv2), argv2); + BOOST_CHECK_EQUAL( + Logger::THREAD|Logger::FUNCTION|Logger::TIME, + l.format(opts)); +} + + +BOOST_AUTO_TEST_CASE(testLoggerConfigure) { + Logger& l = clearLogger(); + Options opts; + char* argv[]={ + 0, + "--log.time", "no", + "--log.source", "yes", + "--log.output", "logging.tmp", + "--log.enable", "critical" + }; + qpid::po::options_description desc; + opts.addTo(desc); + qpid::parseOptions(desc, ARGC(argv), argv); + l.configure(opts, "test"); + QPID_LOG(critical, "foo"); int srcline=__LINE__; + ifstream log("logging.tmp"); + string line; + getline(log, line); + string expect=(format("critical %s:%d: foo")%__FILE__%srcline).str(); + BOOST_CHECK_EQUAL(expect, line); + log.close(); + unlink("logging.tmp"); +} diff --git a/cpp/src/tests/unit/test_tools.h b/cpp/src/tests/unit/test_tools.h new file mode 100644 index 0000000000..a941cf40eb --- /dev/null +++ b/cpp/src/tests/unit/test_tools.h @@ -0,0 +1,53 @@ +#ifndef TEST_TOOLS_H +#define TEST_TOOLS_H + +/* + * + * Copyright (c) 2006 The Apache Software Foundation + * + * 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 + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +#define BOOST_AUTO_TEST_MAIN // Must come before #include<boost/test/*> +#include <boost/test/auto_unit_test.hpp> +#include <boost/assign/list_of.hpp> +#include <boost/regex.hpp> +#include <vector> + +/** Stream operator so BOOST_CHECK_EQUALS works on vectors. */ +namespace std { +template <class T> +ostream& operator <<(ostream& o, const vector<T>& v) { + o << " {"; + typename vector<T>::const_iterator i = v.begin(); + if (i != v.end()) + o << *i++; + while (i != v.end()) + o << ", " << *i++; + return o << "}"; +} +} // namespace std + +/** NB: order of parameters is regex first, in line with + * CHECK(expected, actual) convention. + */ +inline bool regexPredicate(const std::string& re, const std::string& text) { + return boost::regex_match(text, boost::regex(re)); +} + +/** Check for regular expression match. You must #include <boost/regex.hpp> */ +#define BOOST_CHECK_REGEX(re, text) \ + BOOST_CHECK_PREDICATE(regexPredicate, (re)(text)) + +#endif /*!TEST_TOOLS_H*/ |