author | rehn |
Wed, 20 Feb 2019 14:44:58 +0100 | |
changeset 53848 | 8c6a3535b9cb |
parent 48157 | 7c4d43c26352 |
permissions | -rw-r--r-- |
41677 | 1 |
/* |
46560
388aa8d67c80
8181449: Fix debug.hpp / globalDefinitions.hpp dependency inversion
kbarrett
parents:
43431
diff
changeset
|
2 |
* Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved. |
41677 | 3 |
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. |
4 |
* |
|
5 |
* This code is free software; you can redistribute it and/or modify it |
|
6 |
* under the terms of the GNU General Public License version 2 only, as |
|
7 |
* published by the Free Software Foundation. |
|
8 |
* |
|
9 |
* This code is distributed in the hope that it will be useful, but WITHOUT |
|
10 |
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or |
|
11 |
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License |
|
12 |
* version 2 for more details (a copy is included in the LICENSE file that |
|
42908
22186844c94c
8171517: test_logMessageTest.cpp has "ac_heapanied" instead of "accompanied" inside copyright notice
kzhaldyb
parents:
41677
diff
changeset
|
13 |
* accompanied this code). |
41677 | 14 |
* |
15 |
* You should have received a copy of the GNU General Public License version |
|
16 |
* 2 along with this work; if not, write to the Free Software Foundation, |
|
17 |
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. |
|
18 |
* |
|
19 |
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA |
|
20 |
* or visit www.oracle.com if you need additional information or have any |
|
21 |
* questions. |
|
22 |
*/ |
|
42908
22186844c94c
8171517: test_logMessageTest.cpp has "ac_heapanied" instead of "accompanied" inside copyright notice
kzhaldyb
parents:
41677
diff
changeset
|
23 |
|
41677 | 24 |
#include "precompiled.hpp" |
47765
b7c7428eaab9
8189610: Reconcile jvm.h and all jvm_md.h between java.base and hotspot
coleenp
parents:
47216
diff
changeset
|
25 |
#include "jvm.h" |
41677 | 26 |
#include "logTestFixture.hpp" |
27 |
#include "logTestUtils.inline.hpp" |
|
28 |
#include "logging/log.hpp" |
|
29 |
#include "logging/logMessage.hpp" |
|
48157 | 30 |
#include "memory/allocation.inline.hpp" |
41677 | 31 |
#include "unittest.hpp" |
32 |
#include "utilities/globalDefinitions.hpp" |
|
33 |
||
34 |
class LogMessageTest : public LogTestFixture { |
|
35 |
protected: |
|
36 |
static Log(logging) _log; |
|
37 |
static const char* _level_filename[]; |
|
38 |
LogMessageTest(); |
|
39 |
~LogMessageTest(); |
|
40 |
}; |
|
41 |
||
53848 | 42 |
Log(logging) LogMessageTest::_log; |
43 |
||
41677 | 44 |
const char* LogMessageTest::_level_filename[] = { |
45 |
NULL, // LogLevel::Off |
|
46 |
#define LOG_LEVEL(name, printname) "multiline-" #printname ".log", |
|
47 |
LOG_LEVEL_LIST |
|
48 |
#undef LOG_LEVEL |
|
49 |
}; |
|
50 |
||
51 |
LogMessageTest::LogMessageTest() { |
|
52 |
for (int i = 0; i < LogLevel::Count; i++) { |
|
53 |
char buf[32]; |
|
54 |
// Attempt to remove possibly pre-existing log files |
|
55 |
remove(_level_filename[i]); |
|
56 |
||
57 |
jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i))); |
|
58 |
set_log_config(_level_filename[i], buf); |
|
59 |
} |
|
60 |
} |
|
61 |
||
62 |
LogMessageTest::~LogMessageTest() { |
|
63 |
// Stop logging to the files and remove them. |
|
64 |
for (int i = 0; i < LogLevel::Count; i++) { |
|
65 |
set_log_config(_level_filename[i], "all=off"); |
|
66 |
remove(_level_filename[i]); |
|
67 |
} |
|
68 |
} |
|
69 |
||
70 |
// Verify that messages with multiple levels are written |
|
71 |
// to outputs configured for all the corresponding levels |
|
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
72 |
TEST_VM_F(LogMessageTest, level_inclusion) { |
41677 | 73 |
const size_t message_count = 10; |
74 |
LogMessageBuffer msg[message_count]; |
|
75 |
||
76 |
struct { |
|
77 |
int message_number; |
|
78 |
LogLevelType level; |
|
79 |
} lines[] = { |
|
80 |
{ 0, LogLevel::Error }, |
|
81 |
{ 1, LogLevel::Info }, |
|
82 |
{ 2, LogLevel::Info }, { 2, LogLevel::Debug }, |
|
83 |
{ 3, LogLevel::Info }, { 3, LogLevel::Warning }, |
|
84 |
{ 4, LogLevel::Debug }, { 4, LogLevel::Warning }, |
|
85 |
{ 5, LogLevel::Trace }, { 5, LogLevel::Debug }, |
|
86 |
{ 6, LogLevel::Warning }, { 6, LogLevel::Error }, |
|
87 |
{ 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug }, |
|
88 |
{ 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info }, |
|
89 |
{ 8, LogLevel::Warning }, { 8, LogLevel::Error}, |
|
90 |
{ 9, LogLevel::Trace } |
|
91 |
}; |
|
92 |
||
93 |
// Fill in messages with the above lines |
|
94 |
for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { |
|
95 |
switch (lines[i].level) { |
|
96 |
#define LOG_LEVEL(name, printname) \ |
|
97 |
case LogLevel::name: \ |
|
98 |
msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \ |
|
99 |
break; |
|
100 |
LOG_LEVEL_LIST |
|
101 |
#undef LOG_LEVEL |
|
46630
75aa3e39d02c
8182299: Enable disabled clang warnings, build on OSX 10 + Xcode 8
jwilhelm
parents:
46560
diff
changeset
|
102 |
default: |
75aa3e39d02c
8182299: Enable disabled clang warnings, build on OSX 10 + Xcode 8
jwilhelm
parents:
46560
diff
changeset
|
103 |
break; |
41677 | 104 |
} |
105 |
} |
|
106 |
||
107 |
for (size_t i = 0; i < message_count; i++) { |
|
108 |
_log.write(msg[i]); |
|
109 |
} |
|
110 |
||
111 |
// Verify that lines are written to the expected log files |
|
112 |
for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { |
|
113 |
char expected[256]; |
|
114 |
jio_snprintf(expected, sizeof(expected), "msg[%d]: %s", |
|
115 |
lines[i].message_number, LogLevel::name(lines[i].level)); |
|
116 |
for (int level = lines[i].level; level > 0; level--) { |
|
117 |
EXPECT_TRUE(file_contains_substring(_level_filename[level], expected)) |
|
118 |
<< "line #" << i << " missing from log file " << _level_filename[level]; |
|
119 |
} |
|
120 |
for (int level = lines[i].level + 1; level < LogLevel::Count; level++) { |
|
121 |
EXPECT_FALSE(file_contains_substring(_level_filename[level], expected)) |
|
122 |
<< "line #" << i << " erroneously included in log file " << _level_filename[level]; |
|
123 |
} |
|
124 |
} |
|
125 |
} |
|
126 |
||
127 |
// Verify that messages are logged in the order they are added to the log message |
|
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
128 |
TEST_VM_F(LogMessageTest, line_order) { |
41677 | 129 |
LogMessageBuffer msg; |
130 |
msg.info("info line").error("error line").trace("trace line") |
|
131 |
.error("another error").warning("warning line").debug("debug line"); |
|
132 |
_log.write(msg); |
|
133 |
||
134 |
const char* expected[] = { "info line", "error line", "trace line", |
|
135 |
"another error", "warning line", "debug line", NULL }; |
|
136 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) |
|
137 |
<< "output missing or in incorrect order"; |
|
138 |
} |
|
139 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
140 |
TEST_VM_F(LogMessageTest, long_message) { |
41677 | 141 |
// Write 10K bytes worth of log data |
142 |
LogMessageBuffer msg; |
|
143 |
const size_t size = 10 * K; |
|
144 |
const char* start_marker = "#start#"; |
|
145 |
const char* end_marker = "#the end#"; |
|
146 |
char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging); |
|
147 |
||
148 |
// fill buffer with start_marker...some data...end_marker |
|
149 |
sprintf(data, "%s", start_marker); |
|
150 |
for (size_t i = strlen(start_marker); i < size; i++) { |
|
151 |
data[i] = '0' + (i % 10); |
|
152 |
} |
|
153 |
sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker); |
|
154 |
||
155 |
msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length. |
|
156 |
_log.write(msg); |
|
157 |
||
158 |
const char* expected[] = { start_marker, "0123456789", end_marker, NULL }; |
|
159 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) |
|
160 |
<< "unable to print long line"; |
|
161 |
FREE_C_HEAP_ARRAY(char, data); |
|
162 |
} |
|
163 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
164 |
TEST_VM_F(LogMessageTest, message_with_many_lines) { |
41677 | 165 |
const size_t lines = 100; |
166 |
const size_t line_length = 16; |
|
167 |
||
168 |
LogMessageBuffer msg; |
|
169 |
for (size_t i = 0; i < lines; i++) { |
|
170 |
msg.info("Line #" SIZE_FORMAT, i); |
|
171 |
} |
|
172 |
_log.write(msg); |
|
173 |
||
174 |
char expected_lines_data[lines][line_length]; |
|
175 |
const char* expected_lines[lines + 1]; |
|
176 |
for (size_t i = 0; i < lines; i++) { |
|
177 |
jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i); |
|
178 |
expected_lines[i] = expected_lines_data[i]; |
|
179 |
} |
|
180 |
expected_lines[lines] = NULL; |
|
181 |
||
182 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines)) |
|
183 |
<< "couldn't find all lines in multiline message"; |
|
184 |
} |
|
185 |
||
186 |
static size_t dummy_prefixer(char* buf, size_t len) { |
|
187 |
static int i = 0; |
|
188 |
const char* prefix = "some prefix: "; |
|
189 |
const size_t prefix_len = strlen(prefix); |
|
190 |
if (len < prefix_len) { |
|
191 |
return prefix_len; |
|
192 |
} |
|
193 |
jio_snprintf(buf, len, "%s", prefix); |
|
194 |
return prefix_len; |
|
195 |
} |
|
196 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
197 |
TEST_VM_F(LogMessageTest, prefixing) { |
41677 | 198 |
LogMessageBuffer msg; |
199 |
msg.set_prefix(dummy_prefixer); |
|
200 |
for (int i = 0; i < 3; i++) { |
|
201 |
msg.info("test %d", i); |
|
202 |
} |
|
203 |
msg.set_prefix(NULL); |
|
204 |
msg.info("test 3"); |
|
205 |
_log.write(msg); |
|
206 |
||
207 |
const char* expected[] = { |
|
208 |
"] some prefix: test 0", |
|
209 |
"] some prefix: test 1", |
|
210 |
"] some prefix: test 2", |
|
211 |
"] test 3", |
|
212 |
NULL |
|
213 |
}; |
|
214 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) |
|
215 |
<< "error in prefixed output"; |
|
216 |
} |
|
217 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
218 |
TEST_VM_F(LogMessageTest, scoped_messages) { |
41677 | 219 |
{ |
220 |
LogMessage(logging) msg; |
|
221 |
msg.info("scoped info"); |
|
222 |
msg.warning("scoped warn"); |
|
223 |
EXPECT_FALSE(file_contains_substring(_level_filename[LogLevel::Info], "scoped info")) |
|
224 |
<< "scoped log message written prematurely"; |
|
225 |
} |
|
226 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Info], "scoped info")) |
|
227 |
<< "missing output from scoped log message"; |
|
228 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Warning], "scoped warn")) |
|
229 |
<< "missing output from scoped log message"; |
|
230 |
} |
|
231 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
232 |
TEST_VM_F(LogMessageTest, scoped_flushing) { |
41677 | 233 |
{ |
234 |
LogMessage(logging) msg; |
|
235 |
msg.info("manual flush info"); |
|
236 |
msg.flush(); |
|
237 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Info], "manual flush info")) |
|
238 |
<< "missing output from manually flushed scoped log message"; |
|
239 |
} |
|
240 |
const char* tmp[] = {"manual flush info", "manual flush info", NULL}; |
|
241 |
EXPECT_FALSE(file_contains_substrings_in_order(_level_filename[LogLevel::Info], tmp)) |
|
242 |
<< "log file contains duplicate lines from single scoped log message"; |
|
243 |
} |
|
244 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
245 |
TEST_VM_F(LogMessageTest, scoped_reset) { |
41677 | 246 |
{ |
247 |
LogMessage(logging) msg, partial; |
|
248 |
msg.info("%s", "info reset msg"); |
|
249 |
msg.reset(); |
|
250 |
partial.info("%s", "info reset msg"); |
|
251 |
partial.reset(); |
|
252 |
partial.trace("%s", "trace reset msg"); |
|
253 |
} |
|
254 |
EXPECT_FALSE(file_contains_substring(_level_filename[LogLevel::Info], "info reset msg")) |
|
255 |
<< "reset message written anyway"; |
|
256 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Trace], "trace reset msg")) |
|
257 |
<< "missing message from partially reset scoped log message"; |
|
258 |
} |