1 /*
2 * Copyright (c) 2015, 2016, 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
25 #include "precompiled.hpp"
26 #include "logging/log.hpp"
27 #include "memory/allocation.inline.hpp"
28
29 void LogWriteHelper::write_large(LogTagSet& lts,
30 LogLevelType level,
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 }
111
112 const char* name() {
113 return file_name;
114 }
115 };
116
117 class TestLogSavedConfig {
118 private:
119 char* _saved_config;
120 char* _new_output;
121 LogHandle(logging) _log;
122 public:
123 TestLogSavedConfig(const char* apply_output = NULL, const char* apply_setting = NULL) : _new_output(0) {
124 _saved_config = os::strdup_check_oom(LogOutput::Stdout->config_string());
125 bool success = LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, _log.error_stream());
126 assert(success, "test unable to turn all off");
127
128 if (apply_output) {
129 _new_output = os::strdup_check_oom(apply_output);
130 bool success = LogConfiguration::parse_log_arguments(_new_output, apply_setting, NULL, NULL, _log.error_stream());
131 assert(success, "test unable to apply test log configuration");
132 }
133 }
134
135 ~TestLogSavedConfig() {
136 if (_new_output) {
137 bool success = LogConfiguration::parse_log_arguments(_new_output, "all=off", NULL, NULL, _log.error_stream());
138 assert(success, "test unable to turn all off");
139 os::free(_new_output);
140 }
141
142 bool success = LogConfiguration::parse_log_arguments("stdout", _saved_config, NULL, NULL, _log.error_stream());
143 assert(success, "test unable to restore log configuration");
144 os::free(_saved_config);
145 }
146 };
147
148 void Test_configure_stdout() {
149 ResourceMark rm;
150 LogOutput* stdoutput = LogOutput::Stdout;
151 TestLogSavedConfig tlsc;
152
153 // Enable 'logging=info', verifying it has been set
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)");
441
442 LogConfiguration::disable_logging();
443 assert(Test_logconfiguration_subscribe_triggered == 3, "subscription not triggered (3)");
444
445 // We need to renable stderr error logging since "disable_logging" disable it all.
446 // TestLogSavedConfig log_cfg will only renable stdout for us.
447 LogConfiguration::parse_log_arguments("stderr", "all=warning", NULL, NULL, log.error_stream());
448 assert(Test_logconfiguration_subscribe_triggered == 4, "subscription not triggered (3)");
449 }
450
451 #define LOG_PREFIX_STR "THE_PREFIX "
452 #define LOG_LINE_STR "a log line"
453
454 size_t Test_log_prefix_prefixer(char* buf, size_t len) {
455 int ret = jio_snprintf(buf, len, LOG_PREFIX_STR);
456 assert(ret > 0, "Failed to print prefix. Log buffer too small?");
457 return (size_t) ret;
458 }
459
460 void Test_log_prefix() {
461 ResourceMark rm;
462 TestLogFile log_file("log_prefix");
463 TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
464
465 log_trace(logging, test)(LOG_LINE_STR);
466
467 FILE* fp = fopen(log_file.name(), "r");
468 assert(fp, "File read error");
469 char output[1024];
470 if (fgets(output, 1024, fp) != NULL) {
471 assert(strstr(output, LOG_PREFIX_STR LOG_LINE_STR), "logging prefix error");
472 }
473 fclose(fp);
474 }
475
476 void Test_log_big() {
477 char big_msg[4096] = {0};
478 char Xchar = '~';
479
480 ResourceMark rm;
481 TestLogFile log_file("log_big");
482 TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
483
484 memset(big_msg, Xchar, sizeof(big_msg) - 1);
485
486 log_trace(logging, test)("%s", big_msg);
487
488 FILE* fp = fopen(log_file.name(), "r");
489 assert(fp, "File read error");
490 char output[sizeof(big_msg)+128 /*decorators*/ ];
491 if (fgets(output, sizeof(output), fp) != NULL) {
492 assert(strstr(output, LOG_PREFIX_STR), "logging prefix error");
493 size_t count = 0;
494 for (size_t ps = 0 ; output[ps + count] != '\0'; output[ps + count] == Xchar ? count++ : ps++);
495 assert(count == (sizeof(big_msg) - 1) , "logging msg error");
496 }
497 fclose(fp);
498 }
499
500 void Test_logtagset_duplicates() {
501 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
502 char ts_name[512];
503 ts->label(ts_name, sizeof(ts_name), ",");
504
505 // verify that NO_TAG is never followed by a real tag
506 for (size_t i = 0; i < LogTag::MaxTags; i++) {
507 if (ts->tag(i) == LogTag::__NO_TAG) {
508 for (i++; i < LogTag::MaxTags; i++) {
509 assert(ts->tag(i) == LogTag::__NO_TAG,
510 "NO_TAG was followed by a real tag (%s) in tagset %s",
511 LogTag::name(ts->tag(i)), ts_name);
512 }
513 }
514 }
515
516 // verify that there are no duplicate tagsets (same tags in different order)
517 for (LogTagSet* other = ts->next(); other != NULL; other = other->next()) {
518 if (ts->ntags() != other->ntags()) {
519 continue;
520 }
521 bool equal = true;
522 for (size_t i = 0; i < ts->ntags(); i++) {
523 LogTagType tag = ts->tag(i);
524 if (!other->contains(tag)) {
525 equal = false;
526 break;
527 }
528 }
529 // Since tagsets are implemented using template arguments, using both of
530 // the (logically equivalent) tagsets (t1, t2) and (t2, t1) somewhere will
531 // instantiate two different LogTagSetMappings. This causes multiple
532 // tagset instances to be created for the same logical set. We want to
533 // avoid this to save time, memory and prevent any confusion around it.
534 if (equal) {
535 char other_name[512];
536 other->label(other_name, sizeof(other_name), ",");
537 assert(false, "duplicate LogTagSets found: '%s' vs '%s' "
538 "(tags must always be specified in the same order for each tagset)",
539 ts_name, other_name);
540 }
541 }
542 }
543 }
544
545 #endif // PRODUCT