// 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;
}
