/*
* Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*/
#include "precompiled.hpp"
#include "logging/logDecorations.hpp"
#include "logging/logTagSet.hpp"
#include "runtime/os.hpp"
#include "unittest.hpp"
#include "utilities/globalDefinitions.hpp"
static const LogTagSet& tagset = LogTagSetMapping<LOG_TAGS(logging, safepoint)>::tagset();
static const LogDecorators default_decorators;
TEST_VM(LogDecorations, level) {
for (uint l = LogLevel::First; l <= LogLevel::Last; l++) {
LogLevelType level = static_cast<LogLevelType>(l);
// Create a decorations object for the current level
LogDecorations decorations(level, tagset, default_decorators);
// Verify that the level decoration matches the specified level
EXPECT_STREQ(LogLevel::name(level), decorations.decoration(LogDecorators::level_decorator));
// Test changing level after object creation time
LogLevelType other_level;
if (l != LogLevel::Last) {
other_level = static_cast<LogLevelType>(l + 1);
} else {
other_level = static_cast<LogLevelType>(LogLevel::First);
}
decorations.set_level(other_level);
EXPECT_STREQ(LogLevel::name(other_level), decorations.decoration(LogDecorators::level_decorator))
<< "Decoration reports incorrect value after changing the level";
}
}
TEST_VM(LogDecorations, uptime) {
// Verify the format of the decoration
int a, b;
char decimal_point;
LogDecorations decorations(LogLevel::Info, tagset, default_decorators);
const char* uptime = decorations.decoration(LogDecorators::uptime_decorator);
int read = sscanf(uptime, "%d%c%ds", &a, &decimal_point, &b);
EXPECT_EQ(3, read) << "Invalid uptime decoration: " << uptime;
EXPECT_TRUE(decimal_point == '.' || decimal_point == ',') << "Invalid uptime decoration: " << uptime;
// Verify that uptime increases
double prev = 0;
for (int i = 0; i < 3; i++) {
os::naked_short_sleep(10);
LogDecorations d(LogLevel::Info, tagset, default_decorators);
double cur = strtod(d.decoration(LogDecorators::uptime_decorator), NULL);
ASSERT_LT(prev, cur);
prev = cur;
}
}
TEST_VM(LogDecorations, tags) {
char expected_tags[1 * K];
tagset.label(expected_tags, sizeof(expected_tags));
// Verify that the expected tags are included in the tags decoration
LogDecorations decorations(LogLevel::Info, tagset, default_decorators);
EXPECT_STREQ(expected_tags, decorations.decoration(LogDecorators::tags_decorator));
}
// Test each variation of the different timestamp decorations (ms, ns, uptime ms, uptime ns)
TEST_VM(LogDecorations, timestamps) {
struct {
const LogDecorators::Decorator decorator;
const char* suffix;
} test_decorator[] = {
{ LogDecorators::timemillis_decorator, "ms" },
{ LogDecorators::uptimemillis_decorator, "ms" },
{ LogDecorators::timenanos_decorator, "ns" },
{ LogDecorators::uptimenanos_decorator, "ns" }
};
for (uint i = 0; i < ARRAY_SIZE(test_decorator); i++) {
LogDecorators::Decorator decorator = test_decorator[i].decorator;
LogDecorators decorator_selection;
ASSERT_TRUE(decorator_selection.parse(LogDecorators::name(decorator)));
// Create decorations with the decorator we want to test included
LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
const char* decoration = decorations.decoration(decorator);
// Verify format of timestamp
const char* suffix;
for (suffix = decoration; isdigit(*suffix); suffix++) {
// Skip over digits
}
EXPECT_STREQ(test_decorator[i].suffix, suffix);
// Verify timestamp values
julong prev = 0;
for (int i = 0; i < 3; i++) {
os::naked_short_sleep(5);
LogDecorations d(LogLevel::Info, tagset, decorator_selection);
julong val = strtoull(d.decoration(decorator), NULL, 10);
ASSERT_LT(prev, val);
prev = val;
}
}
}
// Test the time decoration
TEST(LogDecorations, iso8601_time) {
LogDecorators decorator_selection;
ASSERT_TRUE(decorator_selection.parse("time"));
LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
const char *timestr = decorations.decoration(LogDecorators::time_decorator);
time_t expected_ts = time(NULL);
// Verify format
int y, M, d, h, m, s, ms;
int read = sscanf(timestr, "%d-%d-%dT%d:%d:%d.%d", &y, &M, &d, &h, &m, &s, &ms);
ASSERT_EQ(7, read) << "Invalid format: " << timestr;
// Verify reported time & date
struct tm reported_time = {0};
reported_time.tm_year = y - 1900;
reported_time.tm_mon = M - 1;
reported_time.tm_mday = d;
reported_time.tm_hour = h;
reported_time.tm_min = m;
reported_time.tm_sec = s;
reported_time.tm_isdst = -1; // let mktime deduce DST settings
time_t reported_ts = mktime(&reported_time);
expected_ts = mktime(localtime(&expected_ts));
time_t diff = reported_ts - expected_ts;
if (diff < 0) {
diff = -diff;
}
// Allow up to 10 seconds in difference
ASSERT_LE(diff, 10) << "Reported time: " << reported_ts << " (" << timestr << ")"
<< ", expected time: " << expected_ts;
}
// Test the utctime decoration
TEST(LogDecorations, iso8601_utctime) {
LogDecorators decorator_selection;
ASSERT_TRUE(decorator_selection.parse("utctime"));
LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
const char *timestr = decorations.decoration(LogDecorators::utctime_decorator);
time_t expected_ts = time(NULL);
// Verify format
char trailing_character;
int y, M, d, h, m, s, ms, offset;
int read = sscanf(timestr, "%d-%d-%dT%d:%d:%d.%d%c%d", &y, &M, &d, &h, &m, &s, &ms, &trailing_character, &offset);
ASSERT_EQ(9, read) << "Invalid format: " << timestr;
// Ensure time is UTC (no offset)
ASSERT_EQ('+', trailing_character) << "Invalid trailing character for UTC: "
<< trailing_character;
ASSERT_EQ(0, offset) << "Invalid offset: " << timestr;
struct tm reported_time = {0};
reported_time.tm_year = y - 1900;
reported_time.tm_mon = M - 1;
reported_time.tm_mday = d;
reported_time.tm_hour = h;
reported_time.tm_min = m;
reported_time.tm_sec = s;
reported_time.tm_isdst = 0; // No DST for UTC timestamps
time_t reported_ts = mktime(&reported_time);
expected_ts = mktime(gmtime(&expected_ts));
time_t diff = reported_ts - expected_ts;
if (diff < 0) {
diff = -diff;
}
// Allow up to 10 seconds in difference
ASSERT_LE(diff, 10) << "Reported time: " << reported_ts << " (" << timestr << ")"
<< ", expected time: " << expected_ts;
}
// Test the pid and tid decorations
TEST(LogDecorations, identifiers) {
LogDecorators decorator_selection;
ASSERT_TRUE(decorator_selection.parse("pid,tid"));
LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
struct {
intx expected;
LogDecorators::Decorator decorator;
} ids[] = {
{ os::current_process_id(), LogDecorators::pid_decorator },
{ os::current_thread_id(), LogDecorators::tid_decorator },
};
for (uint i = 0; i < ARRAY_SIZE(ids); i++) {
const char* reported = decorations.decoration(ids[i].decorator);
// Verify format
const char* str;
for (str = reported; isdigit(*str); str++) {
// Skip over digits
}
EXPECT_EQ('\0', *str) << "Should only contain digits";
// Verify value
EXPECT_EQ(ids[i].expected, strtol(reported, NULL, 10));
}
}