// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. #include #include "bufferedlogtest.logger1.h" #include "bufferedlogtest.logger2.h" #include #include #include #include LOG_SETUP("bufferedlogtest"); std::string readFile(const std::string& file) { std::ostringstream ost; std::ifstream is(file.c_str()); std::string line; while (std::getline(is, line)) { std::string::size_type pos = line.find('\t'); if (pos == std::string::npos) continue; std::string::size_type pos2 = line.find('\t', pos + 1); if (pos2 == std::string::npos) continue; std::string result = line.substr(0, pos) + "\tlocalhost" + line.substr(pos2); ost << result << "\n"; } return ost.str(); } void spamLog1(uint64_t& time, int diff) { for (int i=0; i<100; ++i) { time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: NOT CONNECTED"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: NOT_READY"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: BAAAH"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: RPC FAILURE"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: COSMIC RADIATION"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: ITS SATURDAY"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: Yeah, Right!!"); time += diff; LOGBT(error, "Failed to send to node 4", "Failed to send message to node 4: NOT CONNECTED"); time += diff; LOGBT(spam, "Failed to send to node 4", "Failed to send message to node 4: NOT CONNECTED"); time += diff; LOGBT(warning, "Failed to send to node 4", "Failed to send message to node 4: NOT CONNECTED"); time += diff * 10; LOGBT(warning, "Failed to send to node 3", "Failed to send message to node 3: NOT CONNECTED"); } } void spamLog2(uint64_t& time, int diff) { for (int i=0; i<100; ++i) { time += diff; std::ostringstream ost; ost << "Message " << i; LOGBT(info, ost.str(), "%s", ost.str().c_str()); } } void testThatEntriesWithHighCountIsKept(const std::string& file, uint64_t& timer) { std::cerr << "testThatEntriesWithHighCountIsKept ...\n"; timer = 10 * 1000000 + 4; LOGBM(info, "Starting up, using logfile %s", file.c_str()); timer = 100 * 1000000 + 4; LOGBT(warning, "Token", "message"); spamLog1(timer, 1); spamLog2(timer, 1); spamLog1(timer, 1); LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.highcountkept.log")); if (result != expected) { std::cerr << "Failed testThatEntriesWithHighCountIsKept\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.highcountkept.log") .c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void testThatEntriesWithHighCountsAreEventuallyRemoved( const std::string& file, uint64_t& timer) { std::cerr << "testThatEntriesWithHighCountsAreEventuallyRemoved ...\n"; // Same as above, just increase timer more between each log entry. // Should eventually throw out the entries with high count timer = 10 * 1000000 + 4; // Make sure we don't remove due to age. ns_log::BufferedLogger::logger.setMaxEntryAge(1000000); // Let each count, count for 5 seconds. ns_log::BufferedLogger::logger.setCountFactor(5); LOGBM(info, "Starting up, using logfile %s", file.c_str()); timer = 100 * 1000000 + 4; LOGBT(warning, "Token", "message"); spamLog1(timer, 1); spamLog2(timer, 10 * 1000000); spamLog1(timer, 1); LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.highcountexpire.log")); if (result != expected) { std::cerr << "Failed " << "testThatEntriesWithHighCountsAreEventuallyRemoved\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.highcountexpire.log") .c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void testThatEntriesExpire( const std::string& file, uint64_t& timer) { std::cerr << "testThatEntriesExpire ...\n"; // Test that we don't keep entries longer than max age timer = 10 * 1000000 + 4; // Time out after 120 seconds ns_log::BufferedLogger::logger.setMaxEntryAge(120); // Let counts count much, so they expire due to time instead ns_log::BufferedLogger::logger.setCountFactor(100000); LOGBM(info, "Starting up, using logfile %s", file.c_str()); timer = 100 * 1000000 + 4; LOGBT(warning, "Token", "message"); spamLog1(timer, 1); spamLog2(timer, 10 * 1000000); spamLog1(timer, 1); LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.expire.log")); if (result != expected) { std::cerr << "Failed " << "testThatEntriesExpire\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.expire.log").c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } // Spam 10+ different entries lots of times, to fill cache with high count // entries void spamLog3(uint64_t& time, int diff) { for (int i=0; i<100; ++i) { time += diff; LOGBT(warning, "Failed to talk to node 1", "Failed to send message to node 0x1: NOT CONNECTED"); time += diff; LOGBT(warning, "Failed to talk to node 2", "Failed to send message to node 0x2: NOT_READY"); time += diff; LOGBT(warning, "Failed to talk to node 3", "Failed to send message to node 0x3: BAAAH"); time += diff; LOGBT(warning, "Failed to talk to node 4", "Failed to send message to node 0x4: RPC FAILURE"); time += diff; LOGBT(warning, "Failed to talk to node 5", "Failed to send message to node 0x5: COSMIC RADIATION"); time += diff; LOGBT(warning, "Failed to talk to node 6", "Failed to send message to node 0x6: ITS SATURDAY"); time += diff; LOGBT(warning, "Failed to talk to node 7", "Failed to send message to node 0x7: Yeah, Right!!"); time += diff; LOGBT(error, "Failed to talk to node 8", "Failed to send message to node 0x8: NOT CONNECTED"); time += diff; LOGBT(info, "Failed to talk to node 9", "Failed to send message to node 0x9: NOT CONNECTED"); time += diff; LOGBT(warning, "Failed to talk to node 10", "Failed to send message to node 0xa: NOT CONNECTED"); } } void testThatHighCountEntriesDontStarveOthers( const std::string& file, uint64_t& timer) { std::cerr << "testThatHighCountEntriesDontStarveOthers ...\n"; timer = 10 * 1000000 + 4; // Long time out, we don't want to rely on timeout to prevent starvation ns_log::BufferedLogger::logger.setMaxEntryAge(12000000); // Let counts count much, so they score high ns_log::BufferedLogger::logger.setCountFactor(100000); LOGBM(info, "Starting up, using logfile %s", file.c_str()); timer = 100 * 1000000; LOGBT(warning, "Token", "message"); spamLog3(timer, 1); spamLog1(timer, 1); LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.nostarve.log")); if (result != expected) { std::cerr << "Failed " << "testThatHighCountEntriesDontStarveOthers\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.nostarve.log").c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void testNoTokenMatchAcrossComponents(const std::string& file, uint64_t& timer) { std::cerr << "testNoTokenMatchAcrossComponents ...\n"; LOGBP(info, "Starting up, using logfile %s", file.c_str()); timer = 200 * 1000000; for (uint32_t i=0; i<100; ++i) { std::ostringstream ost; ost << "Message " << i; logWithLogger1("Message", ost.str()); timer += 1; logWithLogger2("Message", ost.str()); timer += 1; } LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.tokenacrossloggers.log")); if (result != expected) { std::cerr << "Failed " << "testNoTokenMatchAcrossComponents\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.tokenacrossloggers.log").c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void testLogLocationAsToken(const std::string& file, uint64_t& timer) { std::cerr << "testLogLocationAsToken ...\n"; LOGBP(info, "Starting up, using logfile %s", file.c_str()); timer = 200 * 1000000; for (uint32_t i=0; i<100; ++i) { LOGBP(info, "Message %i", i); timer += 1; LOGBP(info, "Message %i", i); timer += 1; } LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.locationastoken.log")); if (result != expected) { std::cerr << "Failed " << "testLogLocationAsToken\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.locationastoken.log").c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void testLogMessageAsToken(const std::string& file, uint64_t& timer) { std::cerr << "testLogMessageAsToken ...\n"; LOGBM(info, "Starting up, using logfile %s", file.c_str()); timer = 200 * 1000000; for (uint32_t i=0; i<100; ++i) { LOGBM(info, "Message %i", i % 10); timer += 1; LOGBM(info, "Message %i", i % 10); timer += 1; } LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.messageastoken.log")); if (result != expected) { std::cerr << "Failed " << "testLogMessageAsToken\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.messageastoken.log").c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void testNonBufferedLoggerTriggersBufferedLogTrim(const std::string& file, uint64_t& timer) { std::cerr << "testNonBufferedLoggerTriggersBufferedLogTrim ...\n"; // Write a lot of buffered log. LOGBM(info, "Starting up, using logfile %s", file.c_str()); timer = 200 * 1000000; for (uint32_t i=0; i<100; ++i) { LOGBP(info, "Message %i", i); timer += 1; } // Advance time to time where we should have flushed long ago. timer = 100000 * 1000000ull; LOG(info, "This should cause buffered log flush"); // So flushing should have happened before this time. timer = 200000 * 1000000ull; LOGB_FLUSH(); std::string result(readFile(file)); std::string expected(readFile("bufferedlogtest.trimcache.log")); if (result != expected) { std::cerr << "Failed " << "testNonBufferedLoggerTriggersBufferedLogTrim\n"; [[maybe_unused]] int systemResult = system(("diff -u " + file + " bufferedlogtest.trimcache.log").c_str()); std::_Exit(EXIT_FAILURE); } unlink(file.c_str()); } void reset(uint64_t& timer) { timer = 0; ns_log::BufferedLogger::logger.setMaxEntryAge(300); ns_log::BufferedLogger::logger.setCountFactor(5); } int main(int argc, char **argv) { if (argc != 2) { std::cerr << "bufferedlogtest must be called with one argument\n"; return EXIT_FAILURE; } ns_log::Logger::fakePid = true; ns_log::BufferedLogger::logger.setMaxCacheSize(10); uint64_t timer; logger.setTimer(std::unique_ptr(new ns_log::TestTimer(timer))); ns_log::BufferedLogger::logger.setTimer(std::unique_ptr(new ns_log::TestTimer(timer))); reset(timer); testThatEntriesWithHighCountIsKept(argv[1], timer); reset(timer); testThatEntriesWithHighCountsAreEventuallyRemoved(argv[1], timer); reset(timer); testThatEntriesExpire(argv[1], timer); reset(timer); testThatHighCountEntriesDontStarveOthers(argv[1], timer); reset(timer); testNoTokenMatchAcrossComponents(argv[1], timer); reset(timer); testLogLocationAsToken(argv[1], timer); reset(timer); testLogMessageAsToken(argv[1], timer); reset(timer); testNonBufferedLoggerTriggersBufferedLogTrim(argv[1], timer); return EXIT_SUCCESS; }