| /* |
| * |
| * 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/log/OstreamOutput.h" |
| #include "qpid/memory.h" |
| #include "qpid/Options.h" |
| #if defined (_WIN32) |
| # include "qpid/log/windows/SinkOptions.h" |
| #else |
| # include "qpid/log/posix/SinkOptions.h" |
| #endif |
| |
| #include <boost/test/floating_point_comparison.hpp> |
| #include <boost/algorithm/string/predicate.hpp> |
| #include <boost/format.hpp> |
| #include "unit_test.h" |
| |
| #include <exception> |
| #include <fstream> |
| #include <time.h> |
| |
| |
| namespace qpid { |
| namespace tests { |
| |
| QPID_AUTO_TEST_SUITE(loggingTestSuite) |
| |
| using namespace std; |
| using namespace qpid::log; |
| using boost::ends_with; |
| using boost::contains; |
| using boost::format; |
| |
| QPID_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(debug, s.level); |
| } |
| |
| |
| QPID_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")); |
| } |
| |
| QPID_AUTO_TEST_CASE(testSelector_disable) { |
| Selector s; |
| // Simple enable/disable |
| s.enable(trace,"foo"); |
| BOOST_CHECK(s.isEnabled(trace,"foo")); |
| BOOST_CHECK(!s.isDisabled(trace,"foo")); |
| s.disable(trace,"foo"); |
| BOOST_CHECK(s.isEnabled(trace,"foo")); |
| BOOST_CHECK(s.isDisabled(trace,"foo")); |
| } |
| |
| QPID_AUTO_TEST_CASE(testStatementEnabled) { |
| // Verify that the singleton enables and disables static |
| // log statements. |
| Logger& l = Logger::instance(); |
| ScopedSuppressLogging ls(l); |
| l.select(Selector(debug)); |
| static Statement s=QPID_LOG_STATEMENT_INIT(debug); |
| BOOST_CHECK(!s.enabled); |
| static Statement::Initializer init(s); |
| BOOST_CHECK(s.enabled); |
| |
| static Statement s2=QPID_LOG_STATEMENT_INIT(warning); |
| static 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& l) { |
| l.output(std::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; |
| |
| QPID_AUTO_TEST_CASE(testLoggerOutput) { |
| Logger l; |
| l.clear(); |
| l.select(Selector(debug)); |
| Statement s=QPID_LOG_STATEMENT_INIT(debug); |
| |
| TestOutput* out=new TestOutput(l); |
| |
| // 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); |
| 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); |
| } |
| |
| QPID_AUTO_TEST_CASE(testMacro) { |
| Logger& l=Logger::instance(); |
| ScopedSuppressLogging ls(l); |
| l.select(Selector(info)); |
| TestOutput* out=new TestOutput(l); |
| 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); |
| |
| // 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); |
| } |
| |
| QPID_AUTO_TEST_CASE(testLoggerFormat) { |
| Logger& l = Logger::instance(); |
| ScopedSuppressLogging ls(l); |
| l.select(Selector(critical)); |
| TestOutput* out=new TestOutput(l); |
| |
| 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_EQUAL(out->last().find(__FILE__), 0u); |
| |
| l.format(Logger::FUNCTION); |
| QPID_LOG(critical, "foo"); |
| BOOST_CHECK( ends_with( out->last(), ": foo\n")); |
| string name = out->last().substr(0, out->last().length() - 6); |
| BOOST_CHECK( contains( string(BOOST_CURRENT_FUNCTION), name)); |
| |
| l.format(Logger::LEVEL); |
| QPID_LOG(critical, "foo"); |
| BOOST_CHECK_EQUAL("critical foo\n", out->last()); |
| } |
| |
| QPID_AUTO_TEST_CASE(testOstreamOutput) { |
| Logger& l=Logger::instance(); |
| ScopedSuppressLogging ls(l); |
| l.select(Selector(error)); |
| ostringstream os; |
| l.output(qpid::make_auto_ptr<Logger::Output>(new OstreamOutput(os))); |
| QPID_LOG(error, "foo"); |
| QPID_LOG(error, "bar"); |
| QPID_LOG(error, "baz"); |
| BOOST_CHECK_EQUAL("foo\nbar\nbaz\n", os.str()); |
| } |
| |
| #if 0 // This test requires manual intervention. Normally disabled. |
| QPID_AUTO_TEST_CASE(testSyslogOutput) { |
| Logger& l=Logger::instance(); |
| Logger::StateSaver ls(l); |
| l.clear(); |
| 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 |
| QPID_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, ::qpid::log::unspecified}; |
| return s; |
| } |
| |
| |
| #define ARGC(argv) (sizeof(argv)/sizeof(char*)) |
| |
| QPID_AUTO_TEST_CASE(testOptionsParse) { |
| const char* argv[]={ |
| 0, |
| "--log-enable", "error+:foo", |
| "--log-enable", "debug:bar", |
| "--log-enable", "info", |
| "--log-disable", "error+:foo", |
| "--log-disable", "debug:bar", |
| "--log-disable", "info", |
| "--log-to-stderr", "no", |
| "--log-to-file", "logout", |
| "--log-level", "yes", |
| "--log-source", "1", |
| "--log-thread", "true", |
| "--log-function", "YES" |
| }; |
| qpid::log::Options opts(""); |
| #ifdef _WIN32 |
| qpid::log::windows::SinkOptions sinks("test"); |
| #else |
| qpid::log::posix::SinkOptions sinks("test"); |
| #endif |
| opts.parse(ARGC(argv), const_cast<char**>(argv)); |
| sinks = *opts.sinkOptions; |
| vector<string> expect=list_of("error+:foo")("debug:bar")("info"); |
| BOOST_CHECK_EQUAL(expect, opts.selectors); |
| BOOST_CHECK_EQUAL(expect, opts.deselectors); |
| BOOST_CHECK(!sinks.logToStderr); |
| BOOST_CHECK(!sinks.logToStdout); |
| BOOST_CHECK(sinks.logFile == "logout"); |
| BOOST_CHECK(opts.level); |
| BOOST_CHECK(opts.source); |
| BOOST_CHECK(opts.function); |
| BOOST_CHECK(opts.thread); |
| } |
| |
| QPID_AUTO_TEST_CASE(testOptionsDefault) { |
| qpid::log::Options opts(""); |
| #ifdef _WIN32 |
| qpid::log::windows::SinkOptions sinks("test"); |
| #else |
| qpid::log::posix::SinkOptions sinks("test"); |
| #endif |
| sinks = *opts.sinkOptions; |
| BOOST_CHECK(sinks.logToStderr); |
| BOOST_CHECK(!sinks.logToStdout); |
| BOOST_CHECK(sinks.logFile.length() == 0); |
| vector<string> expect=list_of("notice+"); |
| BOOST_CHECK_EQUAL(expect, opts.selectors); |
| BOOST_CHECK(opts.time && opts.level); |
| BOOST_CHECK(!(opts.source || opts.function || opts.thread)); |
| } |
| |
| QPID_AUTO_TEST_CASE(testSelectorFromOptions) { |
| const char* argv[]={ |
| 0, |
| "--log-enable", "error+:foo", |
| "--log-enable", "debug:bar", |
| "--log-enable", "info" |
| }; |
| qpid::log::Options opts(""); |
| opts.parse(ARGC(argv), const_cast<char**>(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")); |
| } |
| |
| QPID_AUTO_TEST_CASE(testDeselectorFromOptions) { |
| const char* argv[]={ |
| 0, |
| "--log-disable", "error-:foo", |
| "--log-disable", "debug:bar", |
| "--log-disable", "info" |
| }; |
| qpid::log::Options opts(""); |
| opts.parse(ARGC(argv), const_cast<char**>(argv)); |
| vector<string> expect=list_of("error-:foo")("debug:bar")("info"); |
| BOOST_CHECK_EQUAL(expect, opts.deselectors); |
| Selector s(opts); |
| BOOST_CHECK(!s.isDisabled(warning, "x")); |
| BOOST_CHECK(!s.isDisabled(debug, "x")); |
| BOOST_CHECK(s.isDisabled(debug, "bar")); |
| BOOST_CHECK(s.isDisabled(trace, "foo")); |
| BOOST_CHECK(s.isDisabled(debug, "foo")); |
| BOOST_CHECK(s.isDisabled(info, "foo")); |
| BOOST_CHECK(s.isDisabled(notice, "foo")); |
| BOOST_CHECK(s.isDisabled(warning, "foo")); |
| BOOST_CHECK(s.isDisabled(error, "foo")); |
| BOOST_CHECK(!s.isDisabled(critical, "foo")); |
| } |
| |
| QPID_AUTO_TEST_CASE(testMultiConflictingSelectorFromOptions) { |
| const char* argv[]={ |
| 0, |
| "--log-enable", "trace+:foo", |
| "--log-disable", "error-:foo", |
| "--log-enable", "debug:bar", |
| "--log-disable", "debug:bar", |
| "--log-enable", "info", |
| "--log-disable", "info", |
| "--log-enable", "debug+:Model", |
| "--log-disable", "info-:Model" |
| }; |
| qpid::log::Options opts(""); |
| opts.parse(ARGC(argv), const_cast<char**>(argv)); |
| Selector s(opts); |
| BOOST_CHECK(!s.isEnabled(warning, "x", log::broker)); |
| BOOST_CHECK(!s.isEnabled(debug, "x", log::broker)); |
| BOOST_CHECK(!s.isEnabled(trace, "foo", log::broker)); |
| BOOST_CHECK(!s.isEnabled(debug, "foo", log::broker)); |
| BOOST_CHECK(!s.isEnabled(info, "foo", log::broker)); |
| BOOST_CHECK(!s.isEnabled(notice, "foo", log::broker)); |
| BOOST_CHECK(!s.isEnabled(warning, "foo", log::broker)); |
| BOOST_CHECK(!s.isEnabled(error, "foo", log::broker)); |
| BOOST_CHECK(s.isEnabled(critical, "foo", log::broker)); |
| BOOST_CHECK(!s.isEnabled(debug, "bar", log::model)); |
| BOOST_CHECK(!s.isEnabled(trace, "zaz", log::model)); |
| BOOST_CHECK(!s.isEnabled(debug, "zaz", log::model)); |
| BOOST_CHECK(!s.isEnabled(info, "zaz", log::model)); |
| BOOST_CHECK(s.isEnabled(notice, "zaz", log::model)); |
| BOOST_CHECK(s.isEnabled(warning, "zaz", log::model)); |
| BOOST_CHECK(s.isEnabled(error, "zaz", log::model)); |
| BOOST_CHECK(s.isEnabled(critical, "zaz", log::model)); |
| } |
| |
| QPID_AUTO_TEST_CASE(testLoggerStateure) { |
| Logger& l=Logger::instance(); |
| ScopedSuppressLogging ls(l); |
| qpid::log::Options opts("test"); |
| const char* argv[]={ |
| 0, |
| "--log-time", "no", |
| "--log-source", "yes", |
| "--log-to-stderr", "no", |
| "--log-to-file", "logging.tmp", |
| "--log-enable", "critical" |
| }; |
| opts.parse(ARGC(argv), const_cast<char**>(argv)); |
| l.configure(opts); |
| QPID_LOG_CAT(critical, test, "foo"); int srcline=__LINE__; |
| ifstream log("logging.tmp"); |
| string line; |
| getline(log, line); |
| string expect=(format("[Test] critical %s:%d: foo")%__FILE__%srcline).str(); |
| BOOST_CHECK_EQUAL(expect, line); |
| log.close(); |
| unlink("logging.tmp"); |
| } |
| |
| QPID_AUTO_TEST_CASE(testQuoteNonPrintable) { |
| Logger& l=Logger::instance(); |
| ScopedSuppressLogging ls(l); |
| qpid::log::Options opts("test"); |
| opts.time=false; |
| #ifdef _WIN32 |
| qpid::log::windows::SinkOptions *sinks = |
| dynamic_cast<qpid::log::windows::SinkOptions *>(opts.sinkOptions.get()); |
| #else |
| qpid::log::posix::SinkOptions *sinks = |
| dynamic_cast<qpid::log::posix::SinkOptions *>(opts.sinkOptions.get()); |
| #endif |
| sinks->logToStderr = false; |
| sinks->logFile = "logging.tmp"; |
| l.configure(opts); |
| |
| char s[] = "null\0tab\tspace newline\nret\r\x80\x99\xff"; |
| string str(s, sizeof(s)); |
| QPID_LOG_CAT(critical, test, str); |
| ifstream log("logging.tmp"); |
| string line; |
| getline(log, line, '\0'); |
| string expect="[Test] critical null\\x00tab\tspace newline\nret\r\\x80\\x99\\xFF\\x00\n"; |
| BOOST_CHECK_EQUAL(expect, line); |
| log.close(); |
| unlink("logging.tmp"); |
| } |
| |
| QPID_AUTO_TEST_CASE(testSelectorElements) { |
| SelectorElement s("debug"); |
| BOOST_CHECK_EQUAL(s.levelStr, "debug"); |
| BOOST_CHECK_EQUAL(s.patternStr, ""); |
| BOOST_CHECK_EQUAL(s.level, debug); |
| BOOST_CHECK(!s.isDisable); |
| BOOST_CHECK(!s.isCategory); |
| BOOST_CHECK(!s.isLevelAndAbove); |
| BOOST_CHECK(!s.isLevelAndBelow); |
| |
| SelectorElement t("debug:Broker"); |
| BOOST_CHECK_EQUAL(t.levelStr, "debug"); |
| BOOST_CHECK_EQUAL(t.patternStr, "Broker"); |
| BOOST_CHECK_EQUAL(t.level, debug); |
| BOOST_CHECK_EQUAL(t.category, broker); |
| BOOST_CHECK(!t.isDisable); |
| BOOST_CHECK(t.isCategory); |
| BOOST_CHECK(!t.isLevelAndAbove); |
| BOOST_CHECK(!t.isLevelAndBelow); |
| |
| SelectorElement u("info+:qmf::"); |
| BOOST_CHECK_EQUAL(u.levelStr, "info"); |
| BOOST_CHECK_EQUAL(u.patternStr, "qmf::"); |
| BOOST_CHECK_EQUAL(u.level, info); |
| BOOST_CHECK(!u.isDisable); |
| BOOST_CHECK(!u.isCategory); |
| BOOST_CHECK(u.isLevelAndAbove); |
| BOOST_CHECK(!u.isLevelAndBelow); |
| |
| SelectorElement v("critical-"); |
| BOOST_CHECK_EQUAL(v.levelStr, "critical"); |
| BOOST_CHECK_EQUAL(v.patternStr, ""); |
| BOOST_CHECK_EQUAL(v.level, critical); |
| BOOST_CHECK(!v.isDisable); |
| BOOST_CHECK(!v.isCategory); |
| BOOST_CHECK(!v.isLevelAndAbove); |
| BOOST_CHECK(v.isLevelAndBelow); |
| |
| SelectorElement w("!warning-:Management"); |
| BOOST_CHECK_EQUAL(w.levelStr, "warning"); |
| BOOST_CHECK_EQUAL(w.patternStr, "Management"); |
| BOOST_CHECK_EQUAL(w.level, warning); |
| BOOST_CHECK_EQUAL(w.category, management); |
| BOOST_CHECK(w.isDisable); |
| BOOST_CHECK(w.isCategory); |
| BOOST_CHECK(!w.isLevelAndAbove); |
| BOOST_CHECK(w.isLevelAndBelow); |
| } |
| |
| QPID_AUTO_TEST_SUITE_END() |
| |
| }} // namespace qpid::tests |