author | jwilhelm |
Thu, 06 Jul 2017 01:50:26 +0200 | |
changeset 46630 | 75aa3e39d02c |
parent 46560 | 388aa8d67c80 |
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" |
25 |
#include "logTestFixture.hpp" |
|
26 |
#include "logTestUtils.inline.hpp" |
|
27 |
#include "logging/log.hpp" |
|
28 |
#include "logging/logMessage.hpp" |
|
46560
388aa8d67c80
8181449: Fix debug.hpp / globalDefinitions.hpp dependency inversion
kbarrett
parents:
43431
diff
changeset
|
29 |
#include "prims/jvm.h" |
41677 | 30 |
#include "unittest.hpp" |
31 |
#include "utilities/globalDefinitions.hpp" |
|
32 |
||
33 |
class LogMessageTest : public LogTestFixture { |
|
34 |
protected: |
|
35 |
static Log(logging) _log; |
|
36 |
static const char* _level_filename[]; |
|
37 |
LogMessageTest(); |
|
38 |
~LogMessageTest(); |
|
39 |
}; |
|
40 |
||
41 |
const char* LogMessageTest::_level_filename[] = { |
|
42 |
NULL, // LogLevel::Off |
|
43 |
#define LOG_LEVEL(name, printname) "multiline-" #printname ".log", |
|
44 |
LOG_LEVEL_LIST |
|
45 |
#undef LOG_LEVEL |
|
46 |
}; |
|
47 |
||
48 |
LogMessageTest::LogMessageTest() { |
|
49 |
for (int i = 0; i < LogLevel::Count; i++) { |
|
50 |
char buf[32]; |
|
51 |
// Attempt to remove possibly pre-existing log files |
|
52 |
remove(_level_filename[i]); |
|
53 |
||
54 |
jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i))); |
|
55 |
set_log_config(_level_filename[i], buf); |
|
56 |
} |
|
57 |
} |
|
58 |
||
59 |
LogMessageTest::~LogMessageTest() { |
|
60 |
// Stop logging to the files and remove them. |
|
61 |
for (int i = 0; i < LogLevel::Count; i++) { |
|
62 |
set_log_config(_level_filename[i], "all=off"); |
|
63 |
remove(_level_filename[i]); |
|
64 |
} |
|
65 |
} |
|
66 |
||
67 |
// Verify that messages with multiple levels are written |
|
68 |
// 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
|
69 |
TEST_VM_F(LogMessageTest, level_inclusion) { |
41677 | 70 |
const size_t message_count = 10; |
71 |
LogMessageBuffer msg[message_count]; |
|
72 |
||
73 |
struct { |
|
74 |
int message_number; |
|
75 |
LogLevelType level; |
|
76 |
} lines[] = { |
|
77 |
{ 0, LogLevel::Error }, |
|
78 |
{ 1, LogLevel::Info }, |
|
79 |
{ 2, LogLevel::Info }, { 2, LogLevel::Debug }, |
|
80 |
{ 3, LogLevel::Info }, { 3, LogLevel::Warning }, |
|
81 |
{ 4, LogLevel::Debug }, { 4, LogLevel::Warning }, |
|
82 |
{ 5, LogLevel::Trace }, { 5, LogLevel::Debug }, |
|
83 |
{ 6, LogLevel::Warning }, { 6, LogLevel::Error }, |
|
84 |
{ 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug }, |
|
85 |
{ 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info }, |
|
86 |
{ 8, LogLevel::Warning }, { 8, LogLevel::Error}, |
|
87 |
{ 9, LogLevel::Trace } |
|
88 |
}; |
|
89 |
||
90 |
// Fill in messages with the above lines |
|
91 |
for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { |
|
92 |
switch (lines[i].level) { |
|
93 |
#define LOG_LEVEL(name, printname) \ |
|
94 |
case LogLevel::name: \ |
|
95 |
msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \ |
|
96 |
break; |
|
97 |
LOG_LEVEL_LIST |
|
98 |
#undef LOG_LEVEL |
|
46630
75aa3e39d02c
8182299: Enable disabled clang warnings, build on OSX 10 + Xcode 8
jwilhelm
parents:
46560
diff
changeset
|
99 |
default: |
75aa3e39d02c
8182299: Enable disabled clang warnings, build on OSX 10 + Xcode 8
jwilhelm
parents:
46560
diff
changeset
|
100 |
break; |
41677 | 101 |
} |
102 |
} |
|
103 |
||
104 |
for (size_t i = 0; i < message_count; i++) { |
|
105 |
_log.write(msg[i]); |
|
106 |
} |
|
107 |
||
108 |
// Verify that lines are written to the expected log files |
|
109 |
for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { |
|
110 |
char expected[256]; |
|
111 |
jio_snprintf(expected, sizeof(expected), "msg[%d]: %s", |
|
112 |
lines[i].message_number, LogLevel::name(lines[i].level)); |
|
113 |
for (int level = lines[i].level; level > 0; level--) { |
|
114 |
EXPECT_TRUE(file_contains_substring(_level_filename[level], expected)) |
|
115 |
<< "line #" << i << " missing from log file " << _level_filename[level]; |
|
116 |
} |
|
117 |
for (int level = lines[i].level + 1; level < LogLevel::Count; level++) { |
|
118 |
EXPECT_FALSE(file_contains_substring(_level_filename[level], expected)) |
|
119 |
<< "line #" << i << " erroneously included in log file " << _level_filename[level]; |
|
120 |
} |
|
121 |
} |
|
122 |
} |
|
123 |
||
124 |
// 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
|
125 |
TEST_VM_F(LogMessageTest, line_order) { |
41677 | 126 |
LogMessageBuffer msg; |
127 |
msg.info("info line").error("error line").trace("trace line") |
|
128 |
.error("another error").warning("warning line").debug("debug line"); |
|
129 |
_log.write(msg); |
|
130 |
||
131 |
const char* expected[] = { "info line", "error line", "trace line", |
|
132 |
"another error", "warning line", "debug line", NULL }; |
|
133 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) |
|
134 |
<< "output missing or in incorrect order"; |
|
135 |
} |
|
136 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
137 |
TEST_VM_F(LogMessageTest, long_message) { |
41677 | 138 |
// Write 10K bytes worth of log data |
139 |
LogMessageBuffer msg; |
|
140 |
const size_t size = 10 * K; |
|
141 |
const char* start_marker = "#start#"; |
|
142 |
const char* end_marker = "#the end#"; |
|
143 |
char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging); |
|
144 |
||
145 |
// fill buffer with start_marker...some data...end_marker |
|
146 |
sprintf(data, "%s", start_marker); |
|
147 |
for (size_t i = strlen(start_marker); i < size; i++) { |
|
148 |
data[i] = '0' + (i % 10); |
|
149 |
} |
|
150 |
sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker); |
|
151 |
||
152 |
msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length. |
|
153 |
_log.write(msg); |
|
154 |
||
155 |
const char* expected[] = { start_marker, "0123456789", end_marker, NULL }; |
|
156 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) |
|
157 |
<< "unable to print long line"; |
|
158 |
FREE_C_HEAP_ARRAY(char, data); |
|
159 |
} |
|
160 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
161 |
TEST_VM_F(LogMessageTest, message_with_many_lines) { |
41677 | 162 |
const size_t lines = 100; |
163 |
const size_t line_length = 16; |
|
164 |
||
165 |
LogMessageBuffer msg; |
|
166 |
for (size_t i = 0; i < lines; i++) { |
|
167 |
msg.info("Line #" SIZE_FORMAT, i); |
|
168 |
} |
|
169 |
_log.write(msg); |
|
170 |
||
171 |
char expected_lines_data[lines][line_length]; |
|
172 |
const char* expected_lines[lines + 1]; |
|
173 |
for (size_t i = 0; i < lines; i++) { |
|
174 |
jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i); |
|
175 |
expected_lines[i] = expected_lines_data[i]; |
|
176 |
} |
|
177 |
expected_lines[lines] = NULL; |
|
178 |
||
179 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines)) |
|
180 |
<< "couldn't find all lines in multiline message"; |
|
181 |
} |
|
182 |
||
183 |
static size_t dummy_prefixer(char* buf, size_t len) { |
|
184 |
static int i = 0; |
|
185 |
const char* prefix = "some prefix: "; |
|
186 |
const size_t prefix_len = strlen(prefix); |
|
187 |
if (len < prefix_len) { |
|
188 |
return prefix_len; |
|
189 |
} |
|
190 |
jio_snprintf(buf, len, "%s", prefix); |
|
191 |
return prefix_len; |
|
192 |
} |
|
193 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
194 |
TEST_VM_F(LogMessageTest, prefixing) { |
41677 | 195 |
LogMessageBuffer msg; |
196 |
msg.set_prefix(dummy_prefixer); |
|
197 |
for (int i = 0; i < 3; i++) { |
|
198 |
msg.info("test %d", i); |
|
199 |
} |
|
200 |
msg.set_prefix(NULL); |
|
201 |
msg.info("test 3"); |
|
202 |
_log.write(msg); |
|
203 |
||
204 |
const char* expected[] = { |
|
205 |
"] some prefix: test 0", |
|
206 |
"] some prefix: test 1", |
|
207 |
"] some prefix: test 2", |
|
208 |
"] test 3", |
|
209 |
NULL |
|
210 |
}; |
|
211 |
EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) |
|
212 |
<< "error in prefixed output"; |
|
213 |
} |
|
214 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
215 |
TEST_VM_F(LogMessageTest, scoped_messages) { |
41677 | 216 |
{ |
217 |
LogMessage(logging) msg; |
|
218 |
msg.info("scoped info"); |
|
219 |
msg.warning("scoped warn"); |
|
220 |
EXPECT_FALSE(file_contains_substring(_level_filename[LogLevel::Info], "scoped info")) |
|
221 |
<< "scoped log message written prematurely"; |
|
222 |
} |
|
223 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Info], "scoped info")) |
|
224 |
<< "missing output from scoped log message"; |
|
225 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Warning], "scoped warn")) |
|
226 |
<< "missing output from scoped log message"; |
|
227 |
} |
|
228 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
229 |
TEST_VM_F(LogMessageTest, scoped_flushing) { |
41677 | 230 |
{ |
231 |
LogMessage(logging) msg; |
|
232 |
msg.info("manual flush info"); |
|
233 |
msg.flush(); |
|
234 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Info], "manual flush info")) |
|
235 |
<< "missing output from manually flushed scoped log message"; |
|
236 |
} |
|
237 |
const char* tmp[] = {"manual flush info", "manual flush info", NULL}; |
|
238 |
EXPECT_FALSE(file_contains_substrings_in_order(_level_filename[LogLevel::Info], tmp)) |
|
239 |
<< "log file contains duplicate lines from single scoped log message"; |
|
240 |
} |
|
241 |
||
43431
5ffa076f526d
8172098: A lot of gtests uses TEST instead of TEST_VM
kzhaldyb
parents:
42908
diff
changeset
|
242 |
TEST_VM_F(LogMessageTest, scoped_reset) { |
41677 | 243 |
{ |
244 |
LogMessage(logging) msg, partial; |
|
245 |
msg.info("%s", "info reset msg"); |
|
246 |
msg.reset(); |
|
247 |
partial.info("%s", "info reset msg"); |
|
248 |
partial.reset(); |
|
249 |
partial.trace("%s", "trace reset msg"); |
|
250 |
} |
|
251 |
EXPECT_FALSE(file_contains_substring(_level_filename[LogLevel::Info], "info reset msg")) |
|
252 |
<< "reset message written anyway"; |
|
253 |
EXPECT_TRUE(file_contains_substring(_level_filename[LogLevel::Trace], "trace reset msg")) |
|
254 |
<< "missing message from partially reset scoped log message"; |
|
255 |
} |