1 | /* |
2 | * Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved. |
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 |
13 | * accompanied this code). |
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 | */ |
23 | |
24 | #include "precompiled.hpp" |
25 | #include "jvm.h" |
26 | #include "logTestFixture.hpp" |
27 | #include "logTestUtils.inline.hpp" |
28 | #include "logging/log.hpp" |
29 | #include "logging/logMessage.hpp" |
30 | #include "memory/allocation.inline.hpp" |
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 | |
42 | Log(logging) LogMessageTest::_log; |
43 | |
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 |
72 | TEST_VM_F(LogMessageTest, level_inclusion) { |
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 |
102 | default: |
103 | break; |
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 |
128 | TEST_VM_F(LogMessageTest, line_order) { |
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 | |
140 | TEST_VM_F(LogMessageTest, long_message) { |
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 | |
164 | TEST_VM_F(LogMessageTest, message_with_many_lines) { |
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 | |
197 | TEST_VM_F(LogMessageTest, prefixing) { |
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 | |
218 | TEST_VM_F(LogMessageTest, scoped_messages) { |
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 | |
232 | TEST_VM_F(LogMessageTest, scoped_flushing) { |
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 | |
245 | TEST_VM_F(LogMessageTest, scoped_reset) { |
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 | } |
259 | |