31 const char* prefix,
32 size_t prefix_len,
33 size_t msg_len,
34 const char* fmt,
35 va_list args) {
36 size_t newbuf_len = prefix_len + msg_len + 1;
37 char* newbuf = NEW_C_HEAP_ARRAY(char, newbuf_len, mtLogging);
38 memcpy(newbuf, prefix, prefix_len);
39 int ret = os::log_vsnprintf(newbuf + prefix_len, newbuf_len - prefix_len, fmt, args);
40 assert(ret >= 0, "Log message buffer issue");
41 lts.log(level, newbuf);
42 FREE_C_HEAP_ARRAY(char, newbuf);
43 }
44
45 /////////////// Unit tests ///////////////
46
47 #ifndef PRODUCT
48
49 #include "logging/log.hpp"
50 #include "logging/logConfiguration.hpp"
51 #include "logging/logOutput.hpp"
52 #include "memory/resourceArea.hpp"
53
54 #define assert_str_eq(s1, s2) \
55 assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2)
56
57 #define assert_char_in(c, s) \
58 assert(strchr(s, c) != NULL, "Expected '%s' to contain character '%c'", s, c)
59
60 #define assert_char_not_in(c, s) \
61 assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c)
62
63 class TestLogFile {
64 private:
65 char file_name[256];
66
67 void set_name(const char* test_name) {
68 const char* tmpdir = os::get_temp_directory();
69 int pos = jio_snprintf(file_name, sizeof(file_name), "%s%svmtest.%s.%d.log", tmpdir, os::file_separator(), test_name, os::current_process_id());
70 assert(pos > 0, "too small log file name buffer");
71 assert((size_t)pos < sizeof(file_name), "too small log file name buffer");
72 }
73
74 public:
75 TestLogFile(const char* test_name) {
76 set_name(test_name);
77 remove(name());
78 }
79
80 ~TestLogFile() {
81 remove(name());
82 }
126 LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
127 assert_str_eq("logging=info,", stdoutput->config_string());
128 assert(log_is_enabled(Info, logging), "logging was not properly enabled");
129
130 // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled
131 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
132 // No '+' character means only single tags are enabled, and no combinations
133 assert_char_not_in('+', stdoutput->config_string());
134 assert(log_is_enabled(Debug, gc), "logging was not properly enabled");
135
136 // Enable 'gc*=trace' (with wildcard), verifying at least one tag combination is enabled (gc+...)
137 LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc));
138 assert_char_in('+', stdoutput->config_string());
139 assert(log_is_enabled(Trace, gc), "logging was not properly enabled");
140
141 // Disable 'gc*' and 'logging', verifying all logging is properly disabled
142 LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
143 LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
144 assert_str_eq("all=off", stdoutput->config_string());
145 }
146
147 static int Test_logconfiguration_subscribe_triggered = 0;
148
149 static void Test_logconfiguration_subscribe_helper() {
150 Test_logconfiguration_subscribe_triggered++;
151 }
152
153 void Test_logconfiguration_subscribe() {
154 ResourceMark rm;
155 LogHandle(logging) log;
156
157 TestLogSavedConfig log_cfg("stdout", "logging+test=trace");
158
159 LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);
160
161 LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream());
162 assert(Test_logconfiguration_subscribe_triggered == 1, "subscription not triggered (1)");
163
164 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
165 assert(Test_logconfiguration_subscribe_triggered == 2, "subscription not triggered (2)");
|
31 const char* prefix,
32 size_t prefix_len,
33 size_t msg_len,
34 const char* fmt,
35 va_list args) {
36 size_t newbuf_len = prefix_len + msg_len + 1;
37 char* newbuf = NEW_C_HEAP_ARRAY(char, newbuf_len, mtLogging);
38 memcpy(newbuf, prefix, prefix_len);
39 int ret = os::log_vsnprintf(newbuf + prefix_len, newbuf_len - prefix_len, fmt, args);
40 assert(ret >= 0, "Log message buffer issue");
41 lts.log(level, newbuf);
42 FREE_C_HEAP_ARRAY(char, newbuf);
43 }
44
45 /////////////// Unit tests ///////////////
46
47 #ifndef PRODUCT
48
49 #include "logging/log.hpp"
50 #include "logging/logConfiguration.hpp"
51 #include "logging/logMessage.hpp"
52 #include "logging/logMessageBuffer.hpp"
53 #include "logging/logOutput.hpp"
54 #include "memory/resourceArea.hpp"
55
56 #define assert_str_eq(s1, s2) \
57 assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2)
58
59 #define assert_char_in(c, s) \
60 assert(strchr(s, c) != NULL, "Expected '%s' to contain character '%c'", s, c)
61
62 #define assert_char_not_in(c, s) \
63 assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c)
64
65 static bool file_contains_substrings_in_order(const char* filename, const char* substrs[]) {
66 FILE* fp = fopen(filename, "r");
67 assert(fp, "File read error");
68 char buffer[1024];
69 for (int i = 0; substrs[i] != NULL; i++) {
70 assert(sizeof(buffer) > strlen(substrs[i]), "insufficient buffer");
71 bool found = false;
72 while (fgets(buffer, sizeof(buffer), fp) != NULL) {
73 if (strstr(buffer, substrs[i]) != NULL) {
74 found = true;
75 break;
76 }
77 }
78 if (!found) {
79 return false;
80 }
81 }
82 fclose(fp);
83 return true;
84 }
85
86 static bool file_contains_substring(const char* filename, const char* substr) {
87 const char* strs[] = {substr, NULL};
88 return file_contains_substrings_in_order(filename, strs);
89 }
90
91 class TestLogFile {
92 private:
93 char file_name[256];
94
95 void set_name(const char* test_name) {
96 const char* tmpdir = os::get_temp_directory();
97 int pos = jio_snprintf(file_name, sizeof(file_name), "%s%svmtest.%s.%d.log", tmpdir, os::file_separator(), test_name, os::current_process_id());
98 assert(pos > 0, "too small log file name buffer");
99 assert((size_t)pos < sizeof(file_name), "too small log file name buffer");
100 }
101
102 public:
103 TestLogFile(const char* test_name) {
104 set_name(test_name);
105 remove(name());
106 }
107
108 ~TestLogFile() {
109 remove(name());
110 }
154 LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
155 assert_str_eq("logging=info,", stdoutput->config_string());
156 assert(log_is_enabled(Info, logging), "logging was not properly enabled");
157
158 // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled
159 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
160 // No '+' character means only single tags are enabled, and no combinations
161 assert_char_not_in('+', stdoutput->config_string());
162 assert(log_is_enabled(Debug, gc), "logging was not properly enabled");
163
164 // Enable 'gc*=trace' (with wildcard), verifying at least one tag combination is enabled (gc+...)
165 LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc));
166 assert_char_in('+', stdoutput->config_string());
167 assert(log_is_enabled(Trace, gc), "logging was not properly enabled");
168
169 // Disable 'gc*' and 'logging', verifying all logging is properly disabled
170 LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
171 LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
172 assert_str_eq("all=off", stdoutput->config_string());
173 }
174
175 class LogMessageTest {
176 private:
177 static LogHandle(logging) _log;
178 static const char* _level_filename[];
179
180 static void test_level_inclusion();
181 static void test_long_message();
182 static void test_message_with_many_lines();
183 static void test_line_order();
184 static void test_prefixing();
185 static void test_scoped_messages();
186 static void test_scoped_flushing();
187 static void test_scoped_reset();
188
189 public:
190 static void test();
191 };
192
193 const char* LogMessageTest::_level_filename[] = {
194 NULL, // LogLevel::Off
195 #define LOG_LEVEL(name, printname) "multiline-" #printname ".log",
196 LOG_LEVEL_LIST
197 #undef LOG_LEVEL
198 };
199
200 void Test_multiline_logging() {
201 LogMessageTest::test();
202 }
203
204 void LogMessageTest::test() {
205 ResourceMark rm;
206
207 for (int i = 0; i < LogLevel::Count; i++) {
208 char buf[32];
209 // Attempt to remove possibly pre-existing log files
210 remove(_level_filename[i]);
211
212 jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i)));
213 bool success = LogConfiguration::parse_log_arguments(_level_filename[i], buf,
214 NULL, NULL, _log.error_stream());
215 assert(success, "unable to configure logging to file '%s'", _level_filename[i]);
216 }
217
218 test_level_inclusion();
219 test_line_order();
220 test_long_message();
221 test_message_with_many_lines();
222 test_prefixing();
223 test_scoped_messages();
224 test_scoped_flushing();
225 test_scoped_reset();
226
227 // Stop logging to the files and remove them.
228 for (int i = 0; i < LogLevel::Count; i++) {
229 LogConfiguration::parse_log_arguments(_level_filename[i], "all=off", NULL, NULL, _log.error_stream());
230 remove(_level_filename[i]);
231 }
232 }
233
234 // Verify that messages with multiple levels are written
235 // to outputs configured for all the corresponding levels
236 void LogMessageTest::test_level_inclusion() {
237 const size_t message_count = 10;
238 LogMessageBuffer msg[message_count];
239
240 struct {
241 int message_number;
242 LogLevelType level;
243 } lines[] = {
244 { 0, LogLevel::Error },
245 { 1, LogLevel::Info },
246 { 2, LogLevel::Info }, { 2, LogLevel::Debug },
247 { 3, LogLevel::Info }, { 3, LogLevel::Warning },
248 { 4, LogLevel::Debug }, { 4, LogLevel::Warning },
249 { 5, LogLevel::Trace }, { 5, LogLevel::Debug },
250 { 6, LogLevel::Warning }, { 6, LogLevel::Error },
251 { 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug },
252 { 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info },
253 { 8, LogLevel::Warning }, { 8, LogLevel::Error},
254 { 9, LogLevel::Trace }
255 };
256
257 // Fill in messages with the above lines
258 for (size_t i = 0; i < ARRAY_SIZE(lines); i++) {
259 switch (lines[i].level) {
260 #define LOG_LEVEL(name, printname) \
261 case LogLevel::name: \
262 msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \
263 break;
264 LOG_LEVEL_LIST
265 #undef LOG_LEVEL
266 }
267 }
268
269 for (size_t i = 0; i < message_count; i++) {
270 _log.write(msg[i]);
271 }
272
273 // Verify that lines are written to the expected log files
274 for (size_t i = 0; i < ARRAY_SIZE(lines); i++) {
275 char expected[256];
276 jio_snprintf(expected, sizeof(expected), "msg[%d]: %s",
277 lines[i].message_number, LogLevel::name(lines[i].level));
278 for (int level = lines[i].level; level > 0; level--) {
279 assert(file_contains_substring(_level_filename[level], expected),
280 "line #" SIZE_FORMAT " missing from log file '%s'", i, _level_filename[level]);
281 }
282 for (int level = lines[i].level + 1; level < LogLevel::Count; level++) {
283 assert(!file_contains_substring(_level_filename[level], expected),
284 "line #" SIZE_FORMAT " erroneously included in log file '%s'", i, _level_filename[level]);
285 }
286 }
287 }
288
289 // Verify that messages are logged in the order they are added to the log message
290 void LogMessageTest::test_line_order() {
291 LogMessageBuffer msg;
292 msg.info("info line").error("error line").trace("trace line")
293 .error("another error").warning("warning line").debug("debug line");
294 _log.write(msg);
295
296 const char* expected[] = { "info line", "error line", "trace line",
297 "another error", "warning line", "debug line", NULL };
298 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected),
299 "output missing or in incorrect order");
300 }
301
302 void LogMessageTest::test_long_message() {
303 // Write 10K bytes worth of log data
304 LogMessageBuffer msg;
305 const size_t size = 10 * K;
306 const char* start_marker = "#start#";
307 const char* end_marker = "#the end#";
308 char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging);
309
310 // fill buffer with start_marker...some data...end_marker
311 sprintf(data, "%s", start_marker);
312 for (size_t i = strlen(start_marker); i < size; i++) {
313 data[i] = '0' + (i % 10);
314 }
315 sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker);
316
317 msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length.
318 _log.write(msg);
319
320 const char* expected[] = { start_marker, "0123456789", end_marker, NULL };
321 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected),
322 "unable to print long line");
323 FREE_C_HEAP_ARRAY(char, data);
324 }
325
326 void LogMessageTest::test_message_with_many_lines() {
327 const size_t lines = 100;
328 const size_t line_length = 16;
329
330 LogMessageBuffer msg;
331 for (size_t i = 0; i < lines; i++) {
332 msg.info("Line #" SIZE_FORMAT, i);
333 }
334 _log.write(msg);
335
336 char expected_lines_data[lines][line_length];
337 const char* expected_lines[lines + 1];
338 for (size_t i = 0; i < lines; i++) {
339 jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i);
340 expected_lines[i] = expected_lines_data[i];
341 }
342 expected_lines[lines] = NULL;
343
344 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines),
345 "couldn't find all lines in multiline message");
346 }
347
348 static size_t dummy_prefixer(char* buf, size_t len) {
349 static int i = 0;
350 const char* prefix = "some prefix: ";
351 const size_t prefix_len = strlen(prefix);
352 if (len < prefix_len) {
353 return prefix_len;
354 }
355 jio_snprintf(buf, len, "%s", prefix);
356 return prefix_len;
357 }
358
359 void LogMessageTest::test_prefixing() {
360 LogMessageBuffer msg;
361 msg.set_prefix(dummy_prefixer);
362 for (int i = 0; i < 3; i++) {
363 msg.info("test %d", i);
364 }
365 msg.set_prefix(NULL);
366 msg.info("test 3");
367 _log.write(msg);
368
369 const char* expected[] = {
370 "] some prefix: test 0",
371 "] some prefix: test 1",
372 "] some prefix: test 2",
373 "] test 3",
374 NULL
375 };
376 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), "error in prefixed output");
377 }
378
379 void LogMessageTest::test_scoped_messages() {
380 {
381 LogMessage(logging) msg;
382 msg.info("scoped info");
383 msg.warning("scoped warn");
384 assert(!file_contains_substring(_level_filename[LogLevel::Info], "scoped info"),
385 "scoped log message written prematurely");
386 }
387 assert(file_contains_substring(_level_filename[LogLevel::Info], "scoped info"),
388 "missing output from scoped log message");
389 assert(file_contains_substring(_level_filename[LogLevel::Warning], "scoped warn"),
390 "missing output from scoped log message");
391 }
392
393 void LogMessageTest::test_scoped_flushing() {
394 {
395 LogMessage(logging) msg;
396 msg.info("manual flush info");
397 msg.flush();
398 assert(file_contains_substring(_level_filename[LogLevel::Info], "manual flush info"),
399 "missing output from manually flushed scoped log message");
400 }
401 const char* tmp[] = {"manual flush info", "manual flush info", NULL};
402 assert(!file_contains_substrings_in_order(_level_filename[LogLevel::Info], tmp),
403 "log file contains duplicate lines from single scoped log message");
404 }
405
406 void LogMessageTest::test_scoped_reset() {
407 {
408 LogMessage(logging) msg, partial;
409 msg.info("%s", "info reset msg");
410 msg.reset();
411 partial.info("%s", "info reset msg");
412 partial.reset();
413 partial.trace("%s", "trace reset msg");
414 }
415 assert(!file_contains_substring(_level_filename[LogLevel::Info], "info reset msg"),
416 "reset message written anyway");
417 assert(file_contains_substring(_level_filename[LogLevel::Trace], "trace reset msg"),
418 "missing message from partially reset scoped log message");
419 }
420
421
422 static int Test_logconfiguration_subscribe_triggered = 0;
423
424 static void Test_logconfiguration_subscribe_helper() {
425 Test_logconfiguration_subscribe_triggered++;
426 }
427
428 void Test_logconfiguration_subscribe() {
429 ResourceMark rm;
430 LogHandle(logging) log;
431
432 TestLogSavedConfig log_cfg("stdout", "logging+test=trace");
433
434 LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);
435
436 LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream());
437 assert(Test_logconfiguration_subscribe_triggered == 1, "subscription not triggered (1)");
438
439 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
440 assert(Test_logconfiguration_subscribe_triggered == 2, "subscription not triggered (2)");
|