// Test updating an existing log output TEST_VM_F(LogConfigurationTest, update_output) { // Update stdout twice, first using it's name, and the second time its index # const char* test_outputs[] = { "stdout", "#0" }; for (size_t i = 0; i < ARRAY_SIZE(test_outputs); i++) { set_log_config(test_outputs[i], "all=info"); // Verify configuration using LogConfiguration::describe EXPECT_TRUE(is_described("#0: stdout")); EXPECT_TRUE(is_described("logging=info")); // Verify by iterating over tagsets LogOutput* o = &StdoutLog; for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { EXPECT_TRUE(ts->has_output(o)); EXPECT_TRUE(ts->is_level(LogLevel::Info)); EXPECT_FALSE(ts->is_level(LogLevel::Debug)); } // Now change the level and verify the change propagated set_log_config(test_outputs[i], "all=debug"); for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { EXPECT_TRUE(ts->has_output(o)); EXPECT_TRUE(ts->is_level(LogLevel::Debug)); EXPECT_FALSE(ts->is_level(LogLevel::Trace)); } } }
TEST_VM_F(LogConfigurationTest, output_name_normalization) { const char* patterns[] = { "%s", "file=%s", "\"%s\"", "file=\"%s\"" }; char buf[1 * K]; for (size_t i = 0; i < ARRAY_SIZE(patterns); i++) { int ret = jio_snprintf(buf, sizeof(buf), patterns[i], TestLogFileName); ASSERT_NE(-1, ret); set_log_config(buf, "logging=trace"); EXPECT_TRUE(is_described("#2: ")); EXPECT_TRUE(is_described(TestLogFileName)); EXPECT_FALSE(is_described("#3: ")) << "duplicate file output due to incorrect normalization for pattern: " << patterns[i]; } // Make sure prefixes are ignored when used within quotes // (this should create a log with "file=" in its filename) int ret = jio_snprintf(buf, sizeof(buf), "\"file=%s\"", TestLogFileName); ASSERT_NE(-1, ret); set_log_config(buf, "logging=trace"); EXPECT_TRUE(is_described("#3: ")) << "prefix within quotes not ignored as it should be"; set_log_config(buf, "all=off"); // Remove the extra log file created ret = jio_snprintf(buf, sizeof(buf), "file=%s", TestLogFileName); ASSERT_NE(-1, ret); delete_file(buf); }
// Test disabling a particular output TEST_VM_F(LogConfigurationTest, disable_output) { // Disable the default configuration for stdout set_log_config("stdout", "all=off"); // Verify configuration using LogConfiguration::describe EXPECT_TRUE(is_described("#0: stdout all=off")); // Verify by iterating over tagsets LogOutput* o = &StdoutLog; for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { EXPECT_FALSE(ts->has_output(o)); EXPECT_FALSE(ts->is_level(LogLevel::Error)); } // Add a new file output const char* what = "all=debug"; set_log_config(TestLogFileName, what); EXPECT_TRUE(is_described(TestLogFileName)); // Now disable it, verifying it is removed completely set_log_config(TestLogFileName, "all=off"); EXPECT_FALSE(is_described(TestLogFileName)); for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { EXPECT_FALSE(ts->is_level(LogLevel::Error)); } }
// Test reconfiguration of the selected decorators for an output TEST_VM_F(LogConfigurationTest, reconfigure_decorators) { // Configure stderr with all decorators set_log_config("stderr", "all=off", _all_decorators); char buf[256]; int ret = jio_snprintf(buf, sizeof(buf), "#1: stderr all=off %s", _all_decorators); ASSERT_NE(-1, ret); EXPECT_TRUE(is_described(buf)) << "'" << buf << "' not described after reconfiguration"; // Now reconfigure logging on stderr with no decorators set_log_config("stderr", "all=off", "none"); EXPECT_TRUE(is_described("#1: stderr all=off \n")) << "Expecting no decorators"; }
TEST_VM_F(GCTraceTimeTest, no_heap) { set_log_config(TestLogFileName, "gc=debug,gc+start=debug"); LogTarget(Debug, gc) gc_debug; LogTarget(Debug, gc, start) gc_start_debug; EXPECT_TRUE(gc_debug.is_enabled()); EXPECT_TRUE(gc_start_debug.is_enabled()); { GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, false); } const char* expected[] = { // [2.975s][debug][gc,start] Test GC (Allocation Failure) "[gc,start", "] Test GC (Allocation Failure)", // [2.975s][debug][gc ] Test GC (Allocation Failure) 0.026ms "[gc", "] Test GC (Allocation Failure) ", "ms", NULL }; EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); const char* not_expected[] = { // [2.975s][debug][gc ] Test GC 59M->59M(502M) 0.026ms "[gc", "] Test GC ", "M) ", "ms", }; EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected)); }
// Test that invalid options cause configuration errors TEST_VM_F(LogConfigurationTest, invalid_configure_options) { LogConfiguration::disable_logging(); const char* invalid_outputs[] = { "#2", "invalidtype=123", ":invalid/path}to*file?" }; for (size_t i = 0; i < ARRAY_SIZE(invalid_outputs); i++) { EXPECT_FALSE(set_log_config(invalid_outputs[i], "", "", "", true)) << "Accepted invalid output '" << invalid_outputs[i] << "'"; } EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all=invalid_level")); EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("what=invalid")); EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all::invalid_decorator")); }
int main( int argc, char ** argv) { struct bootconfig bc; uint32_t idx; struct btblock * res; { uint32_t channels, levels; get_log_config(&channels, &levels); set_log_config(channels, BC_LOG_STDERR); } initialised = 1; /* first pass: w/ index pointer */ bc.info.eb_cnt = 5; bc.info.min_io_size = 2342; bc.blocks = _alloc_blocks( bc.info.eb_cnt ); memcpy( &bc.blocks[0], "Boot", 4); bc.blocks[0].epoch = 4; memcpy( &bc.blocks[2], "Boot", 4); bc.blocks[2].epoch = 12; memcpy( &bc.blocks[4], "Boot", 4); bc.blocks[4].epoch = 9; bc.blocks[1].epoch = 12955; res = bc_ll_get_current( &bc, &idx ); TEST_ASSERT( &bc.blocks[2], res, struct btblock *); TEST_ASSERT( 12, res->epoch, uint32_t ); TEST_ASSERT( 2, idx, uint32_t ); /* second pass: w/o index pointer (i.e. NULL index pointer) */ memcpy( &bc.blocks[0], "!$%§", 4); bc.blocks[0].epoch = 19; bc.blocks[2].epoch = 3; bc.blocks[4].epoch = 54; bc.blocks[3].epoch = 991233; res = bc_ll_get_current( &bc, NULL ); TEST_ASSERT( &bc.blocks[4], res, struct btblock *); TEST_ASSERT( 54, res->epoch, uint32_t ); /* third pass: no valid boot record */ memcpy( &bc.blocks[2], "pfui", 4); memcpy( &bc.blocks[4], "baba", 4); res = bc_ll_get_current( &bc, NULL ); TEST_ASSERT( NULL, res, struct btblock *); return 0; }
TEST_VM_F(LogConfigurationTest, describe) { ResourceMark rm; stringStream ss; LogConfiguration::describe(&ss); const char* description = ss.as_string(); // Verify that stdout and stderr are listed by default EXPECT_PRED2(string_contains_substring, description, StdoutLog.name()); EXPECT_PRED2(string_contains_substring, description, StderrLog.name()); // Verify that each tag, level and decorator is listed for (size_t i = 0; i < LogTag::Count; i++) { EXPECT_PRED2(string_contains_substring, description, LogTag::name(static_cast<LogTagType>(i))); } for (size_t i = 0; i < LogLevel::Count; i++) { EXPECT_PRED2(string_contains_substring, description, LogLevel::name(static_cast<LogLevelType>(i))); } for (size_t i = 0; i < LogDecorators::Count; i++) { EXPECT_PRED2(string_contains_substring, description, LogDecorators::name(static_cast<LogDecorators::Decorator>(i))); } // Verify that the default configuration is printed char expected_buf[256]; int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "=%s", LogLevel::name(LogLevel::Default)); ASSERT_NE(-1, ret); EXPECT_PRED2(string_contains_substring, description, expected_buf); EXPECT_PRED2(string_contains_substring, description, "#1: stderr all=off"); // Verify default decorators are listed LogDecorators default_decorators; expected_buf[0] = '\0'; for (size_t i = 0; i < LogDecorators::Count; i++) { LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i); if (default_decorators.is_decorator(d)) { ASSERT_LT(strlen(expected_buf), sizeof(expected_buf)); ret = jio_snprintf(expected_buf + strlen(expected_buf), sizeof(expected_buf) - strlen(expected_buf), "%s%s", strlen(expected_buf) > 0 ? "," : "", LogDecorators::name(d)); ASSERT_NE(-1, ret); } } EXPECT_PRED2(string_contains_substring, description, expected_buf); // Add a new output and verify that it gets described after it has been added const char* what = "all=trace"; EXPECT_FALSE(is_described(TestLogFileName)) << "Test output already exists!"; set_log_config(TestLogFileName, what); EXPECT_TRUE(is_described(TestLogFileName)); EXPECT_TRUE(is_described("logging=trace")); }
TEST_VM_F(LogConfigurationTest, disable_logging) { // Add TestLogFileName as an output set_log_config(TestLogFileName, "logging=info"); // Add a second file output char other_file_name[2 * K]; jio_snprintf(other_file_name, sizeof(other_file_name), "%s-other", TestLogFileName); set_log_config(other_file_name, "logging=info"); LogConfiguration::disable_logging(); // Verify that both file outputs were disabled EXPECT_FALSE(is_described(TestLogFileName)); EXPECT_FALSE(is_described(other_file_name)); delete_file(other_file_name); // Verify that no tagset has logging enabled for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { EXPECT_FALSE(ts->has_output(&StdoutLog)); EXPECT_FALSE(ts->has_output(&StderrLog)); EXPECT_FALSE(ts->is_level(LogLevel::Error)); } }
// Test adding a new output to the configuration TEST_VM_F(LogConfigurationTest, add_new_output) { const char* what = "all=trace"; ASSERT_FALSE(is_described(TestLogFileName)); set_log_config(TestLogFileName, what); // Verify new output using LogConfiguration::describe EXPECT_TRUE(is_described(TestLogFileName)); EXPECT_TRUE(is_described("logging=trace")); // Also verify by iterating over tagsets, checking levels on tagsets for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { EXPECT_TRUE(ts->is_level(LogLevel::Trace)); } }
TEST_F(LogConfigurationTest, subscribe) { ResourceMark rm; Log(logging) log; set_log_config("stdout", "logging*=trace"); LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper); LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream()); ASSERT_EQ(1, Test_logconfiguration_subscribe_triggered); LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc)); ASSERT_EQ(2, Test_logconfiguration_subscribe_triggered); LogConfiguration::disable_logging(); ASSERT_EQ(3, Test_logconfiguration_subscribe_triggered); }
TEST_VM_F(GCTraceTimeTest, full_multitag) { set_log_config(TestLogFileName, "gc+ref=debug,gc+ref+start=debug"); LogTarget(Debug, gc, ref) gc_debug; LogTarget(Debug, gc, ref, start) gc_start_debug; EXPECT_TRUE(gc_debug.is_enabled()); EXPECT_TRUE(gc_start_debug.is_enabled()); { ThreadInVMfromNative tvn(JavaThread::current()); MutexLocker lock(Heap_lock); // Needed to read heap usage GCTraceTime(Debug, gc, ref) timer("Test GC", NULL, GCCause::_allocation_failure, true); } const char* expected[] = { "[gc,ref,start", "] Test GC (Allocation Failure)", "[gc,ref", "] Test GC (Allocation Failure) ", "M) ", "ms", NULL }; EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); }
TEST_VM_F(GCTraceTimeTest, no_cause) { set_log_config(TestLogFileName, "gc=debug,gc+start=debug"); LogTarget(Debug, gc) gc_debug; LogTarget(Debug, gc, start) gc_start_debug; EXPECT_TRUE(gc_debug.is_enabled()); EXPECT_TRUE(gc_start_debug.is_enabled()); { ThreadInVMfromNative tvn(JavaThread::current()); MutexLocker lock(Heap_lock); // Needed to read heap usage GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, true); } const char* expected[] = { // [2.975s][debug][gc,start] Test GC "[gc,start", "] Test GC", // [2.975s][debug][gc ] Test GC 59M->59M(502M) 0.026ms "[gc", "] Test GC ", "M) ", "ms", NULL }; EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); }
int main( int argc, char ** argv) { struct bootconfig bc; enum bt_ll_parttype which = kernel; int res; { uint32_t channels, levels; get_log_config(&channels, &levels); set_log_config(channels, BC_LOG_STDERR); } MOCK_CB_SET( mtd_read, my_mtd_read ); initialised = 1; bc.info.eb_cnt = 6; bc.info.min_io_size = 9876; bc.blocks = _alloc_blocks( bc.info.eb_cnt ); bc.dev = "/test/device"; memcpy( &bc.blocks[0], "BAD!", 4); bc.blocks[0].epoch = 99; memcpy( &bc.blocks[2], "Boot", 4); bc.blocks[2].epoch = 12; memcpy( &bc.blocks[3], "Boot", 4); bc.blocks[3].epoch = 2; bc.blocks[2].kernel.partition = 1; bc.blocks[2].kernel.n_booted = 1; bc.blocks[2].kernel.n_healthy = 0; bc.blocks[2].rootfs.partition = 0; bc.blocks[2].rootfs.n_booted = 1; bc.blocks[2].rootfs.n_healthy = 1; bc.blocks[1].kernel.partition = 0; bc.blocks[1].kernel.n_booted = 0; bc.blocks[1].kernel.n_healthy = 0; bc.blocks[1].rootfs.partition = 1; bc.blocks[1].rootfs.n_booted = 0; bc.blocks[1].rootfs.n_healthy = 0; MOCK_3_CALL( -1, mtd_is_bad, &bc.info, bc.fd, 3 ); MOCK_3_CALL( 0, mtd_is_bad, &bc.info, bc.fd, 4 ); MOCK_4_CALL( -1, mtd_erase, bc.mtd, &bc.info, bc.fd, 4 ); MOCK_3_CALL( 1, mtd_is_bad, &bc.info, bc.fd, 4 ); MOCK_3_CALL( 0, mtd_is_bad, &bc.info, bc.fd, 5 ); MOCK_4_CALL( 0, mtd_erase, bc.mtd, &bc.info, bc.fd, 5 ); MOCK_10_CALL(-1, mtd_write, bc.mtd, &bc.info, bc.fd, 5, 0, DONT_CHECK_PARAM, bc.info.min_io_size, NULL, 0, 0 ); MOCK_3_CALL( -1, mtd_is_bad, &bc.info, bc.fd, 5 ); MOCK_3_CALL( 0, mtd_is_bad, &bc.info, bc.fd, 1 ); MOCK_4_CALL( 0, mtd_erase, bc.mtd, &bc.info, bc.fd, 1 ); MOCK_10_CALL( 0, mtd_write, bc.mtd, &bc.info, bc.fd, 1, 0, DONT_CHECK_PARAM, bc.info.min_io_size, NULL, 0, 0 ); MOCK_3_CALL( -1, mtd_is_bad, &bc.info, bc.fd, 0 ); MOCK_3_CALL( 0, mtd_is_bad, &bc.info, bc.fd, 1 ); MOCK_6_CALL( 0, mtd_read, &bc.info, bc.fd, 1, 0, &bc.blocks[1], sizeof( *bc.blocks ) ); MOCK_3_CALL( 0, mtd_is_bad, &bc.info, bc.fd, 2 ); MOCK_6_CALL( 0, mtd_read, &bc.info, bc.fd, 2, 0, &bc.blocks[2], sizeof( *bc.blocks ) ); MOCK_3_CALL( -1, mtd_is_bad, &bc.info, bc.fd, 3 ); MOCK_3_CALL( -1, mtd_is_bad, &bc.info, bc.fd, 4 ); MOCK_3_CALL( -1, mtd_is_bad, &bc.info, bc.fd, 5 ); res = bc_ll_set_partition( &bc, kernel, 1 ); TEST_ASSERT( 0, res, int); TEST_ASSERT( 1, !!(0 != memcmp( &bc.blocks[0], "BAD!", 4)), int ); TEST_ASSERT( 0, memcmp( &bc.blocks[1], "Boot", 4) ,int ); TEST_ASSERT( 0, memcmp( &bc.blocks[2], "Boot", 4) ,int ); TEST_ASSERT( 1, !!(0 != memcmp( &bc.blocks[3], "BAD!", 4)),int ); TEST_ASSERT( 0, memcmp( &bc.blocks[4], "BAD!", 4), int ); TEST_ASSERT( 1, !!(0 != memcmp( &bc.blocks[5], "BAD!", 4)),int ); TEST_ASSERT( 1, bc.blocks[1].kernel.partition, int ); TEST_ASSERT( 1, bc.blocks[1].kernel.n_booted, int); TEST_ASSERT( 1, bc.blocks[1].kernel.n_healthy, int); TEST_ASSERT( 0, bc.blocks[1].rootfs.partition, int) TEST_ASSERT( 1, bc.blocks[1].rootfs.n_booted, int); TEST_ASSERT( 1, bc.blocks[1].rootfs.n_healthy, int); TEST_ASSERT( 11, _mtd_is_bad_called_count, int ); TEST_ASSERT( 2, _mtd_erase_called_count, int ); TEST_ASSERT( 1, _mtd_write_called_count, int ); return 0; }