/* * Copyright (c) 2021 Daniel R. Carvalho * All rights reserved * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions are * met: redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer; * redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution; * neither the name of the copyright holders nor the names of its * contributors may be used to endorse or promote products derived from * this software without specific prior written permission. * * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. */ #include #include #include #include "base/gtest/cur_tick_fake.hh" #include "base/gtest/logging.hh" #include "base/named.hh" #include "base/trace.hh" using namespace gem5; // In test SetGetLogger this logger will be assigned to be the one returned // by Tracer::getDebugLogger(). All tests before that test should assume // that getDebugLogger() returns a cerr-based logger, and all tests after // that test should assume that this logger is returned std::stringstream ss; Trace::OstreamLogger main_logger(ss); // Instantiate the mock class to have a valid curTick of 0 GTestTickHandler tickHandler; namespace gem5 { namespace debug { /** Debug flag used for the tests in this file. */ SimpleFlag TraceTestDebugFlag("TraceTestDebugFlag", "Exclusive debug flag for the trace tests"); } // namespace debug } // namespace gem5 /** @return The ostream as a std::string. */ std::string getString(std::ostream &os) { auto buf = os.rdbuf(); std::ostringstream oss; oss << buf; return oss.str(); } /** @return The logger's ostream as a std::string. */ std::string getString(Trace::Logger *logger) { return getString(logger->getOstream()); } /** Test creating a simple log message. */ TEST(TraceTest, LogSimpleMessage) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.logMessage(Tick(100), "", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Test message"); } /** Test creating a simple log message with a name. */ TEST(TraceTest, LogMessageName) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); } /** Test that when the tick is set to MaxTick it is not printed. */ TEST(TraceTest, LogMessageMaxTick) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.logMessage(MaxTick, "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), "Foo: Test message"); } /** Test that by default the flag is not printed. */ TEST(TraceTest, LogMessageFlagDisabled) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.logMessage(Tick(100), "Foo", "Bar", "Test message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); } /** * Test creating a simple log message without tick information and that * enabling and disabling format flags work. */ TEST(TraceTest, LogMessageTickDisabledAndEnableDisable) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); Trace::enable(); EXPECT_TRUE(debug::changeFlag("FmtTicksOff", true)); logger.logMessage(Tick(200), "Foo", "", "Test message"); #if TRACING_ON ASSERT_EQ(getString(&logger), "Foo: Test message"); #else ASSERT_EQ(getString(&logger), " 200: Foo: Test message"); #endif debug::changeFlag("FmtTicksOff", false); Trace::disable(); logger.logMessage(Tick(300), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), " 300: Foo: Test message"); } /** * Test creating a full log message to verify expected order of appearance. * This does not include the backtrace. */ TEST(TraceTest, LogMessageFlagEnabled) { std::stringstream ss; Trace::OstreamLogger logger(ss); Trace::enable(); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); logger.logMessage(Tick(100), "Foo", "Bar", "Test message"); #if TRACING_ON ASSERT_EQ(getString(&logger), " 100: Bar: Foo: Test message"); #else ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); #endif debug::changeFlag("FmtFlag", false); Trace::disable(); } /** Test that log messages are not displayed for ignored objects (single). */ TEST(TraceTest, LogMessageIgnoreOne) { std::stringstream ss; Trace::OstreamLogger logger(ss); ObjectMatch ignore_foo("Foo"); ObjectMatch ignore_bar("Bar"); // Ignore foo logger.setIgnore(ignore_foo); logger.logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), ""); logger.logMessage(Tick(100), "Bar", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Bar: Test message"); // Make sure that when setting a new ignore the old ignores are not kept logger.setIgnore(ignore_bar); logger.logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); logger.logMessage(Tick(100), "Bar", "", "Test message"); ASSERT_EQ(getString(&logger), ""); } /** Test that log messages are not displayed for ignored objects (multiple). */ TEST(TraceTest, LogMessageIgnoreMultiple) { std::stringstream ss; Trace::OstreamLogger logger(ss); ObjectMatch ignore_foo("Foo"); ObjectMatch ignore_bar("Bar"); ObjectMatch ignore_thy("Thy"); // Ignore foo and bar logger.setIgnore(ignore_foo); logger.addIgnore(ignore_bar); logger.logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), ""); logger.logMessage(Tick(100), "Bar", "", "Test message"); ASSERT_EQ(getString(&logger), ""); logger.logMessage(Tick(100), "Thy", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Thy: Test message"); // Make sure that when setting a new ignore, the old sub-ignores // are not kept logger.setIgnore(ignore_thy); logger.logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); logger.logMessage(Tick(100), "Bar", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Bar: Test message"); logger.logMessage(Tick(100), "Thy", "", "Test message"); ASSERT_EQ(getString(&logger), ""); } /** Test that dumping for an ignored name does not log anything. */ TEST(TraceTest, DumpIgnored) { std::stringstream ss; Trace::OstreamLogger logger(ss); ObjectMatch ignore_foo("Foo"); logger.setIgnore(ignore_foo); std::string message = "Test message"; logger.dump(Tick(100), "Foo", message.c_str(), message.size(), ""); ASSERT_EQ(getString(&logger), ""); } /** * Test that a regular dump will change the message so that it contains both * the hex and char representation of every byte. There is a space between * every 8 bytes. For each 16-byte line of a message the order of appearance is * <2 spaces> <8 spaced bytes> <1 space> <8 spaced bytes> * <3-spaces missing to fill 16 bytes> <1 space> <16 bytes as chars> <\n> */ TEST(TraceTest, DumpSimple) { std::stringstream ss; Trace::OstreamLogger logger(ss); Trace::enable(); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); std::string message = "Test message"; logger.dump(Tick(100), "Foo", message.c_str(), message.size(), "Bar"); #if TRACING_ON ASSERT_EQ(getString(&logger), // logMessage prefix " 100: Bar: Foo: " // Byte number + 2 spaces "00000000 " // 8 bytes + 1 space + 4 bytes + ((16 - 12) * 3) spaces "54 65 73 74 20 6d 65 73 73 61 67 65 " // 1 space + 12 chars + \n " Test message\n"); #else ASSERT_EQ(getString(&logger), // logMessage prefix " 100: Foo: " // Byte number + 2 spaces "00000000 " // 8 bytes + 1 space + 4 bytes + ((16 - 12) * 3) spaces "54 65 73 74 20 6d 65 73 73 61 67 65 " // 1 space + 12 chars + \n " Test message\n"); #endif debug::changeFlag("FmtFlag", false); Trace::disable(); } /** * Test that a regular dump will change the message so that it contains both * the hex and char representation of every byte, for a multi-line message. */ TEST(TraceTest, DumpMultiLine) { std::stringstream ss; Trace::OstreamLogger logger(ss); std::string message = "This is a very long line that will span over multiple lines"; logger.dump(Tick(100), "Foo", message.c_str(), message.size(), ""); ASSERT_EQ(getString(&logger), " 100: Foo: 00000000 " "54 68 69 73 20 69 73 20 61 20 76 65 72 79 20 6c This is a very l\n" " 100: Foo: 00000010 " "6f 6e 67 20 6c 69 6e 65 20 74 68 61 74 20 77 69 ong line that wi\n" " 100: Foo: 00000020 " "6c 6c 20 73 70 61 6e 20 6f 76 65 72 20 6d 75 6c ll span over mul\n" " 100: Foo: 00000030 " "74 69 70 6c 65 20 6c 69 6e 65 73 tiple lines\n"); } /** * Test that when no logger exists a logger is created redirecting to cerr. * This is the only test that uses cerr. All other test will use main_logger. */ TEST(TraceTest, DISABLED_GetNullLogger) { Trace::Logger *logger = Trace::getDebugLogger(); ASSERT_FALSE(logger == nullptr); gtestLogOutput.str(""); logger->logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(gtestLogOutput.str(), " 100: Foo: Test message"); } /** Test that the logger is set properly. */ TEST(TraceTest, SetGetLogger) { // NOTE: From now on getDebugLogger will use main_logger to avoid // having to check cerr. This assumes that tests are run in the order // they appear from line 1 to the last line of this file. Trace::setDebugLogger(&main_logger); // Set message with local variable, and retrieve the string with // the debug-logger getter main_logger.logMessage(Tick(100), "Foo", "", "Test message"); auto logger_from_getter = Trace::getDebugLogger(); ASSERT_EQ(getString(logger_from_getter), " 100: Foo: Test message"); } /** Test that output() gets the ostream of the current debug logger. */ TEST(TraceTest, Output) { Trace::getDebugLogger()->logMessage(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(Trace::output()), " 100: Foo: Test message"); } /** Test dprintf_flag with ignored name. */ TEST(TraceTest, DprintfFlagIgnore) { std::stringstream ss; Trace::OstreamLogger logger(ss); ObjectMatch ignore_foo("Foo"); logger.setIgnore(ignore_foo); logger.dprintf_flag(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), ""); } /** Test dprintf_flag with zero args. */ TEST(TraceTest, DprintfFlagZeroArgs) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.dprintf_flag(Tick(100), "Foo", "", "Test message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); } /** Test dprintf_flag with one arg. */ TEST(TraceTest, DprintfFlagOneArg) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.dprintf_flag(Tick(100), "Foo", "", "Test %s", "message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); } /** Test dprintf_flag with multiple args. */ TEST(TraceTest, DprintfFlagMultipleArgs) { std::stringstream ss; Trace::OstreamLogger logger(ss); logger.dprintf_flag(Tick(100), "Foo", "", "Test %s %c %d %x", "message", 'A', 217, 0x30); ASSERT_EQ(getString(&logger), " 100: Foo: Test message A 217 30"); } /** Test dprintf_flag with flag. */ TEST(TraceTest, DprintfFlagEnabled) { std::stringstream ss; Trace::OstreamLogger logger(ss); Trace::enable(); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); logger.dprintf_flag(Tick(100), "Foo", "Bar", "Test %s", "message"); #if TRACING_ON ASSERT_EQ(getString(&logger), " 100: Bar: Foo: Test message"); #else ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); #endif debug::changeFlag("FmtFlag", false); Trace::disable(); } /** Test dprintf with ignored name. */ TEST(TraceTest, DprintfIgnore) { std::stringstream ss; Trace::OstreamLogger logger(ss); ObjectMatch ignore_foo("Foo"); logger.setIgnore(ignore_foo); logger.dprintf(Tick(100), "Foo", "Test message"); ASSERT_EQ(getString(&logger), ""); } /** Test that dprintf does not have a flag. */ TEST(TraceTest, DprintfEnabled) { std::stringstream ss; Trace::OstreamLogger logger(ss); Trace::enable(); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); logger.dprintf(Tick(100), "Foo", "Test %s", "message"); ASSERT_EQ(getString(&logger), " 100: Foo: Test message"); debug::changeFlag("FmtFlag", false); Trace::disable(); } /** Test that dprintf is just a flagless wrapper for dprintf_flag. */ TEST(TraceTest, DprintfWrapper) { std::stringstream ss, ss_flag; Trace::OstreamLogger logger(ss); Trace::OstreamLogger logger_flag(ss_flag); logger.dprintf(Tick(100), "Foo", "Test %s %c %d %x", "message", 'A', 217, 0x30); logger_flag.dprintf_flag(Tick(100), "Foo", "", "Test %s %c %d %x", "message", 'A', 217, 0x30); ASSERT_EQ(getString(&logger), getString(&logger_flag)); } /** Test DDUMP with tracing on. */ TEST(TraceTest, MacroDDUMP) { StringWrap name("Foo"); std::string message = "Test message"; // Flag enabled Trace::enable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true)); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); DDUMP(TraceTestDebugFlag, message.c_str(), message.size()); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), " 0: TraceTestDebugFlag: Foo: 00000000 " "54 65 73 74 20 6d 65 73 73 61 67 65 Test message\n"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif // Flag disabled Trace::disable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false)); DDUMP(TraceTestDebugFlag, message.c_str(), message.size()); ASSERT_EQ(getString(Trace::output()), ""); } /** Test DPRINTF with tracing on. */ TEST(TraceTest, MacroDPRINTF) { StringWrap name("Foo"); // Flag enabled Trace::enable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true)); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); DPRINTF(TraceTestDebugFlag, "Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), " 0: TraceTestDebugFlag: Foo: Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif // Flag disabled Trace::disable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false)); DPRINTF(TraceTestDebugFlag, "Test message"); ASSERT_EQ(getString(Trace::output()), ""); } /** Test DPRINTFS with tracing on. */ TEST(TraceTest, MacroDPRINTFS) { Named named("Foo"); #if TRACING_ON Named *named_ptr = &named; #endif // Flag enabled Trace::enable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true)); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); #if TRACING_ON DPRINTFS(TraceTestDebugFlag, named_ptr, "Test message"); ASSERT_EQ(getString(Trace::output()), " 0: TraceTestDebugFlag: Foo: Test message"); #endif // Flag disabled Trace::disable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false)); #if TRACING_ON DPRINTFS(TraceTestDebugFlag, named_ptr, "Test message"); ASSERT_EQ(getString(Trace::output()), ""); #endif } /** Test DPRINTFR with tracing on. */ TEST(TraceTest, MacroDPRINTFR) { // Flag enabled Trace::enable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true)); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); DPRINTFR(TraceTestDebugFlag, "Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), "TraceTestDebugFlag: Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif // Flag disabled Trace::disable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false)); DPRINTFR(TraceTestDebugFlag, "Test message"); ASSERT_EQ(getString(Trace::output()), ""); } /** Test DPRINTFN with tracing on. */ TEST(TraceTest, MacroDPRINTFN) { StringWrap name("Foo"); DPRINTFN("Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), " 0: Foo: Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif } /** Test DPRINTFNR with tracing on. */ TEST(TraceTest, MacroDPRINTFNR) { DPRINTFNR("Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), "Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif } /** Test DPRINTF_UNCONDITIONAL with tracing on. */ TEST(TraceTest, MacroDPRINTF_UNCONDITIONAL) { StringWrap name("Foo"); // Flag enabled Trace::enable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true)); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); DPRINTF_UNCONDITIONAL(TraceTestDebugFlag, "Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), " 0: TraceTestDebugFlag: Foo: Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif // Flag disabled Trace::disable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false)); DPRINTF_UNCONDITIONAL(TraceTestDebugFlag, "Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), " 0: Foo: Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif } /** * Test that there is a global name() to fall through when a locally scoped * name() is not defined. */ TEST(TraceTest, GlobalName) { // Flag enabled Trace::enable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true)); EXPECT_TRUE(debug::changeFlag("FmtFlag", true)); DPRINTF(TraceTestDebugFlag, "Test message"); #if TRACING_ON ASSERT_EQ(getString(Trace::output()), " 0: TraceTestDebugFlag: global: Test message"); #else ASSERT_EQ(getString(Trace::output()), ""); #endif // Flag disabled Trace::disable(); EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false)); DPRINTF(TraceTestDebugFlag, "Test message"); ASSERT_EQ(getString(Trace::output()), ""); }