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 27 /////////////// Unit tests /////////////// 28 29 #ifndef PRODUCT 30 31 #include "gc/shared/gcTraceTime.inline.hpp" 32 #include "logging/log.hpp" 33 #include "logging/logConfiguration.hpp" 34 #include "logging/logFileOutput.hpp" 35 #include "logging/logMessage.hpp" 36 #include "logging/logMessageBuffer.hpp" 37 #include "logging/logOutput.hpp" 38 #include "logging/logTagLevelExpression.hpp" 39 #include "logging/logTagSet.hpp" 40 #include "logging/logTagSetDescriptions.hpp" 41 #include "logging/logStream.inline.hpp" 42 #include "memory/resourceArea.hpp" 43 44 #define assert_str_eq(s1, s2) \ 45 assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2) 46 47 #define assert_char_in(c, s) \ 48 assert(strchr(s, c) != NULL, "Expected '%s' to contain character '%c'", s, c) 49 50 #define assert_char_not_in(c, s) \ 51 assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c) 52 53 void Test_log_tag_combinations_limit() { 54 assert(LogTagLevelExpression::MaxCombinations > LogTagSet::ntagsets(), 55 "Combination limit (" SIZE_FORMAT ") not sufficient " 56 "for configuring all available tag sets (" SIZE_FORMAT ")", 57 LogTagLevelExpression::MaxCombinations, LogTagSet::ntagsets()); 58 } 59 60 // Read a complete line from fp and return it as a resource allocated string. 61 // Returns NULL on EOF. 62 static char* read_line(FILE* fp) { 63 assert(fp != NULL, "bad fp"); 64 int buflen = 512; 65 char* buf = NEW_RESOURCE_ARRAY(char, buflen); 66 long pos = ftell(fp); 67 68 char* ret = fgets(buf, buflen, fp); 69 while (ret != NULL && buf[strlen(buf) - 1] != '\n' && !feof(fp)) { 70 // retry with a larger buffer 71 buf = REALLOC_RESOURCE_ARRAY(char, buf, buflen, buflen * 2); 72 buflen *= 2; 73 // rewind to beginning of line 74 fseek(fp, pos, SEEK_SET); 75 // retry read with new buffer 76 ret = fgets(buf, buflen, fp); 77 } 78 return ret; 79 } 80 81 static bool file_contains_substrings_in_order(const char* filename, const char* substrs[]) { 82 FILE* fp = fopen(filename, "r"); 83 assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno)); 84 85 size_t idx = 0; 86 while (substrs[idx] != NULL) { 87 ResourceMark rm; 88 char* line = read_line(fp); 89 if (line == NULL) { 90 break; 91 } 92 for (char* match = strstr(line, substrs[idx]); match != NULL;) { 93 size_t match_len = strlen(substrs[idx]); 94 idx++; 95 if (substrs[idx] == NULL) { 96 break; 97 } 98 match = strstr(match + match_len, substrs[idx]); 99 } 100 } 101 102 fclose(fp); 103 return substrs[idx] == NULL; 104 } 105 106 static bool file_contains_substring(const char* filename, const char* substr) { 107 const char* strs[] = {substr, NULL}; 108 return file_contains_substrings_in_order(filename, strs); 109 } 110 111 static size_t number_of_lines_with_substring_in_file(const char* filename, 112 const char* substr) { 113 FILE* fp = fopen(filename, "r"); 114 assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno)); 115 116 size_t ret = 0; 117 for (;;) { 118 ResourceMark rm; 119 char* line = read_line(fp); 120 if (line == NULL) { 121 break; 122 } 123 if (strstr(line, substr) != NULL) { 124 ret++; 125 } 126 } 127 128 fclose(fp); 129 return ret; 130 } 131 132 static bool file_exists(const char* filename) { 133 struct stat st; 134 return os::stat(filename, &st) == 0; 135 } 136 137 static void delete_file(const char* filename) { 138 if (!file_exists(filename)) { 139 return; 140 } 141 int ret = remove(filename); 142 assert(ret == 0, "failed to remove file '%s': %s", filename, strerror(errno)); 143 } 144 145 static void create_directory(const char* name) { 146 assert(!file_exists(name), "can't create directory: %s already exists", name); 147 bool failed; 148 #ifdef _WINDOWS 149 failed = !CreateDirectory(name, NULL); 150 #else 151 failed = mkdir(name, 0777); 152 #endif 153 assert(!failed, "failed to create directory %s", name); 154 } 155 156 class TestLogFile { 157 private: 158 char file_name[256]; 159 160 void set_name(const char* test_name) { 161 const char* tmpdir = os::get_temp_directory(); 162 int pos = jio_snprintf(file_name, sizeof(file_name), "%s%svmtest.%s.%d.log", tmpdir, os::file_separator(), test_name, os::current_process_id()); 163 assert(pos > 0, "too small log file name buffer"); 164 assert((size_t)pos < sizeof(file_name), "too small log file name buffer"); 165 } 166 167 public: 168 TestLogFile(const char* test_name) { 169 set_name(test_name); 170 remove(name()); 171 } 172 173 ~TestLogFile() { 174 remove(name()); 175 } 176 177 const char* name() { 178 return file_name; 179 } 180 }; 181 182 class TestLogSavedConfig { 183 private: 184 char* _saved_config; 185 char* _new_output; 186 Log(logging) _log; 187 public: 188 TestLogSavedConfig(const char* apply_output = NULL, const char* apply_setting = NULL) : _new_output(0) { 189 ResourceMark rm; 190 _saved_config = os::strdup_check_oom(LogOutput::Stdout->config_string()); 191 bool success = LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, _log.error_stream()); 192 assert(success, "test unable to turn all off"); 193 194 if (apply_output) { 195 _new_output = os::strdup_check_oom(apply_output); 196 bool success = LogConfiguration::parse_log_arguments(_new_output, apply_setting, NULL, NULL, _log.error_stream()); 197 assert(success, "test unable to apply test log configuration"); 198 } 199 } 200 201 ~TestLogSavedConfig() { 202 ResourceMark rm; 203 if (_new_output) { 204 bool success = LogConfiguration::parse_log_arguments(_new_output, "all=off", NULL, NULL, _log.error_stream()); 205 assert(success, "test unable to turn all off"); 206 os::free(_new_output); 207 } 208 209 bool success = LogConfiguration::parse_log_arguments("stdout", _saved_config, NULL, NULL, _log.error_stream()); 210 assert(success, "test unable to restore log configuration"); 211 os::free(_saved_config); 212 } 213 }; 214 215 void Test_configure_stdout() { 216 LogOutput* stdoutput = LogOutput::Stdout; 217 TestLogSavedConfig tlsc; 218 219 // Enable 'logging=info', verifying it has been set 220 LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging)); 221 assert_str_eq("logging=info", stdoutput->config_string()); 222 assert(log_is_enabled(Info, logging), "logging was not properly enabled"); 223 224 // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled 225 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc)); 226 // No '+' character means only single tags are enabled, and no combinations 227 assert_char_not_in('+', stdoutput->config_string()); 228 assert(log_is_enabled(Debug, gc), "logging was not properly enabled"); 229 230 // Enable 'gc*=trace' (with wildcard), verifying at least one tag combination is enabled (gc+...) 231 LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc)); 232 assert_char_in('+', stdoutput->config_string()); 233 assert(log_is_enabled(Trace, gc), "logging was not properly enabled"); 234 235 // Disable 'gc*' and 'logging', verifying all logging is properly disabled 236 LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc)); 237 LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging)); 238 assert_str_eq("all=off", stdoutput->config_string()); 239 } 240 241 static const char* ExpectedLine = "a (hopefully) unique log line for testing"; 242 243 static void init_file(const char* filename, const char* options = "") { 244 LogConfiguration::parse_log_arguments(filename, "logging=trace", "", options, 245 Log(logging)::error_stream()); 246 log_debug(logging)("%s", ExpectedLine); 247 LogConfiguration::parse_log_arguments(filename, "all=off", "", "", 248 Log(logging)::error_stream()); 249 } 250 251 void Test_log_file_startup_rotation() { 252 ResourceMark rm; 253 const size_t rotations = 5; 254 const char* filename = "start-rotate-test"; 255 char* rotated_file[rotations]; 256 for (size_t i = 0; i < rotations; i++) { 257 size_t len = strlen(filename) + 3; 258 rotated_file[i] = NEW_RESOURCE_ARRAY(char, len); 259 jio_snprintf(rotated_file[i], len, "%s." SIZE_FORMAT, filename, i); 260 delete_file(rotated_file[i]); 261 }; 262 263 delete_file(filename); 264 init_file(filename); 265 assert(file_exists(filename), 266 "configured logging to file '%s' but file was not found", filename); 267 268 // Initialize the same file a bunch more times to trigger rotations 269 for (size_t i = 0; i < rotations; i++) { 270 init_file(filename); 271 assert(file_exists(rotated_file[i]), "existing file was not rotated"); 272 } 273 274 // Remove a file and expect its slot to be re-used 275 delete_file(rotated_file[1]); 276 init_file(filename); 277 assert(file_exists(rotated_file[1]), "log file not properly rotated"); 278 279 // Clean up after test 280 delete_file(filename); 281 for (size_t i = 0; i < rotations; i++) { 282 delete_file(rotated_file[i]); 283 } 284 } 285 286 void Test_log_file_startup_truncation() { 287 ResourceMark rm; 288 const char* filename = "start-truncate-test"; 289 const char* archived_filename = "start-truncate-test.0"; 290 291 delete_file(filename); 292 delete_file(archived_filename); 293 294 // Use the same log file twice and expect it to be overwritten/truncated 295 init_file(filename, "filecount=0"); 296 assert(file_exists(filename), "couldn't find log file: %s", filename); 297 298 init_file(filename, "filecount=0"); 299 assert(file_exists(filename), "couldn't find log file: %s", filename); 300 assert(!file_exists(archived_filename), 301 "existing log file %s was not properly truncated when filecount was 0", 302 filename); 303 304 // Verify that the file was really truncated and not just appended 305 assert(number_of_lines_with_substring_in_file(filename, ExpectedLine) == 1, 306 "log file %s appended rather than truncated", filename); 307 308 delete_file(filename); 309 delete_file(archived_filename); 310 } 311 312 class LogMessageTest { 313 private: 314 static Log(logging) _log; 315 static const char* _level_filename[]; 316 317 static void test_level_inclusion(); 318 static void test_long_message(); 319 static void test_message_with_many_lines(); 320 static void test_line_order(); 321 static void test_prefixing(); 322 static void test_scoped_messages(); 323 static void test_scoped_flushing(); 324 static void test_scoped_reset(); 325 326 public: 327 static void test(); 328 }; 329 330 const char* LogMessageTest::_level_filename[] = { 331 NULL, // LogLevel::Off 332 #define LOG_LEVEL(name, printname) "multiline-" #printname ".log", 333 LOG_LEVEL_LIST 334 #undef LOG_LEVEL 335 }; 336 337 void Test_multiline_logging() { 338 LogMessageTest::test(); 339 } 340 341 void LogMessageTest::test() { 342 ResourceMark rm; 343 344 for (int i = 0; i < LogLevel::Count; i++) { 345 char buf[32]; 346 // Attempt to remove possibly pre-existing log files 347 remove(_level_filename[i]); 348 349 jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i))); 350 bool success = LogConfiguration::parse_log_arguments(_level_filename[i], buf, 351 NULL, NULL, _log.error_stream()); 352 assert(success, "unable to configure logging to file '%s'", _level_filename[i]); 353 } 354 355 test_level_inclusion(); 356 test_line_order(); 357 test_long_message(); 358 test_message_with_many_lines(); 359 test_prefixing(); 360 test_scoped_messages(); 361 test_scoped_flushing(); 362 test_scoped_reset(); 363 364 // Stop logging to the files and remove them. 365 for (int i = 0; i < LogLevel::Count; i++) { 366 LogConfiguration::parse_log_arguments(_level_filename[i], "all=off", NULL, NULL, _log.error_stream()); 367 remove(_level_filename[i]); 368 } 369 } 370 371 // Verify that messages with multiple levels are written 372 // to outputs configured for all the corresponding levels 373 void LogMessageTest::test_level_inclusion() { 374 const size_t message_count = 10; 375 LogMessageBuffer msg[message_count]; 376 377 struct { 378 int message_number; 379 LogLevelType level; 380 } lines[] = { 381 { 0, LogLevel::Error }, 382 { 1, LogLevel::Info }, 383 { 2, LogLevel::Info }, { 2, LogLevel::Debug }, 384 { 3, LogLevel::Info }, { 3, LogLevel::Warning }, 385 { 4, LogLevel::Debug }, { 4, LogLevel::Warning }, 386 { 5, LogLevel::Trace }, { 5, LogLevel::Debug }, 387 { 6, LogLevel::Warning }, { 6, LogLevel::Error }, 388 { 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug }, 389 { 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info }, 390 { 8, LogLevel::Warning }, { 8, LogLevel::Error}, 391 { 9, LogLevel::Trace } 392 }; 393 394 // Fill in messages with the above lines 395 for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { 396 switch (lines[i].level) { 397 #define LOG_LEVEL(name, printname) \ 398 case LogLevel::name: \ 399 msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \ 400 break; 401 LOG_LEVEL_LIST 402 #undef LOG_LEVEL 403 } 404 } 405 406 for (size_t i = 0; i < message_count; i++) { 407 _log.write(msg[i]); 408 } 409 410 // Verify that lines are written to the expected log files 411 for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { 412 char expected[256]; 413 jio_snprintf(expected, sizeof(expected), "msg[%d]: %s", 414 lines[i].message_number, LogLevel::name(lines[i].level)); 415 for (int level = lines[i].level; level > 0; level--) { 416 assert(file_contains_substring(_level_filename[level], expected), 417 "line #" SIZE_FORMAT " missing from log file '%s'", i, _level_filename[level]); 418 } 419 for (int level = lines[i].level + 1; level < LogLevel::Count; level++) { 420 assert(!file_contains_substring(_level_filename[level], expected), 421 "line #" SIZE_FORMAT " erroneously included in log file '%s'", i, _level_filename[level]); 422 } 423 } 424 } 425 426 // Verify that messages are logged in the order they are added to the log message 427 void LogMessageTest::test_line_order() { 428 LogMessageBuffer msg; 429 msg.info("info line").error("error line").trace("trace line") 430 .error("another error").warning("warning line").debug("debug line"); 431 _log.write(msg); 432 433 const char* expected[] = { "info line", "error line", "trace line", 434 "another error", "warning line", "debug line", NULL }; 435 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), 436 "output missing or in incorrect order"); 437 } 438 439 void LogMessageTest::test_long_message() { 440 // Write 10K bytes worth of log data 441 LogMessageBuffer msg; 442 const size_t size = 10 * K; 443 const char* start_marker = "#start#"; 444 const char* end_marker = "#the end#"; 445 char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging); 446 447 // fill buffer with start_marker...some data...end_marker 448 sprintf(data, "%s", start_marker); 449 for (size_t i = strlen(start_marker); i < size; i++) { 450 data[i] = '0' + (i % 10); 451 } 452 sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker); 453 454 msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length. 455 _log.write(msg); 456 457 const char* expected[] = { start_marker, "0123456789", end_marker, NULL }; 458 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), 459 "unable to print long line"); 460 FREE_C_HEAP_ARRAY(char, data); 461 } 462 463 void LogMessageTest::test_message_with_many_lines() { 464 const size_t lines = 100; 465 const size_t line_length = 16; 466 467 LogMessageBuffer msg; 468 for (size_t i = 0; i < lines; i++) { 469 msg.info("Line #" SIZE_FORMAT, i); 470 } 471 _log.write(msg); 472 473 char expected_lines_data[lines][line_length]; 474 const char* expected_lines[lines + 1]; 475 for (size_t i = 0; i < lines; i++) { 476 jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i); 477 expected_lines[i] = expected_lines_data[i]; 478 } 479 expected_lines[lines] = NULL; 480 481 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines), 482 "couldn't find all lines in multiline message"); 483 } 484 485 static size_t dummy_prefixer(char* buf, size_t len) { 486 static int i = 0; 487 const char* prefix = "some prefix: "; 488 const size_t prefix_len = strlen(prefix); 489 if (len < prefix_len) { 490 return prefix_len; 491 } 492 jio_snprintf(buf, len, "%s", prefix); 493 return prefix_len; 494 } 495 496 void LogMessageTest::test_prefixing() { 497 LogMessageBuffer msg; 498 msg.set_prefix(dummy_prefixer); 499 for (int i = 0; i < 3; i++) { 500 msg.info("test %d", i); 501 } 502 msg.set_prefix(NULL); 503 msg.info("test 3"); 504 _log.write(msg); 505 506 const char* expected[] = { 507 "] some prefix: test 0", 508 "] some prefix: test 1", 509 "] some prefix: test 2", 510 "] test 3", 511 NULL 512 }; 513 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), "error in prefixed output"); 514 } 515 516 void LogMessageTest::test_scoped_messages() { 517 { 518 LogMessage(logging) msg; 519 msg.info("scoped info"); 520 msg.warning("scoped warn"); 521 assert(!file_contains_substring(_level_filename[LogLevel::Info], "scoped info"), 522 "scoped log message written prematurely"); 523 } 524 assert(file_contains_substring(_level_filename[LogLevel::Info], "scoped info"), 525 "missing output from scoped log message"); 526 assert(file_contains_substring(_level_filename[LogLevel::Warning], "scoped warn"), 527 "missing output from scoped log message"); 528 } 529 530 void LogMessageTest::test_scoped_flushing() { 531 { 532 LogMessage(logging) msg; 533 msg.info("manual flush info"); 534 msg.flush(); 535 assert(file_contains_substring(_level_filename[LogLevel::Info], "manual flush info"), 536 "missing output from manually flushed scoped log message"); 537 } 538 const char* tmp[] = {"manual flush info", "manual flush info", NULL}; 539 assert(!file_contains_substrings_in_order(_level_filename[LogLevel::Info], tmp), 540 "log file contains duplicate lines from single scoped log message"); 541 } 542 543 void LogMessageTest::test_scoped_reset() { 544 { 545 LogMessage(logging) msg, partial; 546 msg.info("%s", "info reset msg"); 547 msg.reset(); 548 partial.info("%s", "info reset msg"); 549 partial.reset(); 550 partial.trace("%s", "trace reset msg"); 551 } 552 assert(!file_contains_substring(_level_filename[LogLevel::Info], "info reset msg"), 553 "reset message written anyway"); 554 assert(file_contains_substring(_level_filename[LogLevel::Trace], "trace reset msg"), 555 "missing message from partially reset scoped log message"); 556 } 557 558 559 static int Test_logconfiguration_subscribe_triggered = 0; 560 561 static void Test_logconfiguration_subscribe_helper() { 562 Test_logconfiguration_subscribe_triggered++; 563 } 564 565 void Test_logconfiguration_subscribe() { 566 ResourceMark rm; 567 Log(logging) log; 568 569 TestLogSavedConfig log_cfg("stdout", "logging*=trace"); 570 571 LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper); 572 573 LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream()); 574 assert(Test_logconfiguration_subscribe_triggered == 1, "subscription not triggered (1)"); 575 576 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc)); 577 assert(Test_logconfiguration_subscribe_triggered == 2, "subscription not triggered (2)"); 578 579 LogConfiguration::disable_logging(); 580 assert(Test_logconfiguration_subscribe_triggered == 3, "subscription not triggered (3)"); 581 } 582 583 #define LOG_PREFIX_STR "THE_PREFIX " 584 #define LOG_LINE_STR "a log line" 585 586 size_t Test_log_prefix_prefixer(char* buf, size_t len) { 587 int ret = jio_snprintf(buf, len, LOG_PREFIX_STR); 588 assert(ret > 0, "Failed to print prefix. Log buffer too small?"); 589 return (size_t) ret; 590 } 591 592 void Test_log_prefix() { 593 TestLogFile log_file("log_prefix"); 594 TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace"); 595 596 log_trace(logging, test)(LOG_LINE_STR); 597 598 FILE* fp = fopen(log_file.name(), "r"); 599 assert(fp, "File read error"); 600 char output[1024]; 601 if (fgets(output, 1024, fp) != NULL) { 602 assert(strstr(output, LOG_PREFIX_STR LOG_LINE_STR), "logging prefix error"); 603 } 604 fclose(fp); 605 } 606 607 void Test_log_big() { 608 char big_msg[4096] = {0}; 609 char Xchar = '~'; 610 611 TestLogFile log_file("log_big"); 612 TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace"); 613 614 memset(big_msg, Xchar, sizeof(big_msg) - 1); 615 616 log_trace(logging, test)("%s", big_msg); 617 618 FILE* fp = fopen(log_file.name(), "r"); 619 assert(fp, "File read error"); 620 char output[sizeof(big_msg)+128 /*decorators*/ ]; 621 if (fgets(output, sizeof(output), fp) != NULL) { 622 assert(strstr(output, LOG_PREFIX_STR), "logging prefix error"); 623 size_t count = 0; 624 for (size_t ps = 0 ; output[ps + count] != '\0'; output[ps + count] == Xchar ? count++ : ps++); 625 assert(count == (sizeof(big_msg) - 1) , "logging msg error"); 626 } 627 fclose(fp); 628 } 629 630 void Test_logtagset_duplicates() { 631 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { 632 char ts_name[512]; 633 ts->label(ts_name, sizeof(ts_name), ","); 634 635 // verify that NO_TAG is never followed by a real tag 636 for (size_t i = 0; i < LogTag::MaxTags; i++) { 637 if (ts->tag(i) == LogTag::__NO_TAG) { 638 for (i++; i < LogTag::MaxTags; i++) { 639 assert(ts->tag(i) == LogTag::__NO_TAG, 640 "NO_TAG was followed by a real tag (%s) in tagset %s", 641 LogTag::name(ts->tag(i)), ts_name); 642 } 643 } 644 } 645 646 // verify that there are no duplicate tagsets (same tags in different order) 647 for (LogTagSet* other = ts->next(); other != NULL; other = other->next()) { 648 if (ts->ntags() != other->ntags()) { 649 continue; 650 } 651 bool equal = true; 652 for (size_t i = 0; i < ts->ntags(); i++) { 653 LogTagType tag = ts->tag(i); 654 if (!other->contains(tag)) { 655 equal = false; 656 break; 657 } 658 } 659 // Since tagsets are implemented using template arguments, using both of 660 // the (logically equivalent) tagsets (t1, t2) and (t2, t1) somewhere will 661 // instantiate two different LogTagSetMappings. This causes multiple 662 // tagset instances to be created for the same logical set. We want to 663 // avoid this to save time, memory and prevent any confusion around it. 664 if (equal) { 665 char other_name[512]; 666 other->label(other_name, sizeof(other_name), ","); 667 assert(false, "duplicate LogTagSets found: '%s' vs '%s' " 668 "(tags must always be specified in the same order for each tagset)", 669 ts_name, other_name); 670 } 671 } 672 } 673 } 674 675 #define Test_logtarget_string_literal "First line" 676 677 678 static void Test_logtarget_on() { 679 TestLogFile log_file("log_target"); 680 TestLogSavedConfig tlsc(log_file.name(), "gc=debug"); 681 682 LogTarget(Debug, gc) log; 683 684 assert(log.is_enabled(), "assert"); 685 686 // Log the line and expect it to be available in the output file. 687 log.print(Test_logtarget_string_literal); 688 689 FILE* fp = fopen(log_file.name(), "r"); 690 assert(fp != NULL, "File read error"); 691 692 char output[256 /* Large enough buffer */]; 693 char* res = fgets(output, sizeof(output), fp); 694 assert(res != NULL, "assert"); 695 696 assert(strstr(output, Test_logtarget_string_literal) != NULL, "log line missing"); 697 698 fclose(fp); 699 } 700 701 static void Test_logtarget_off() { 702 TestLogFile log_file("log_target"); 703 TestLogSavedConfig tlsc(log_file.name(), "gc=info"); 704 705 LogTarget(Debug, gc) log; 706 707 if (log.is_enabled()) { 708 // The log config could have been redirected gc=debug to a file. If gc=debug 709 // is enabled, we can only test that the LogTarget returns the same value 710 // as the log_is_enabled function. The rest of the test will be ignored. 711 assert(log.is_enabled() == log_is_enabled(Debug, gc), "assert"); 712 log_warning(logging)("This test doesn't support runs with -Xlog"); 713 return; 714 } 715 716 // Try to log, but expect this to be filtered out. 717 log.print(Test_logtarget_string_literal); 718 719 // Log a dummy line so that fgets doesn't return NULL because the file is empty. 720 log_info(gc)("Dummy line"); 721 722 FILE* fp = fopen(log_file.name(), "r"); 723 assert(fp != NULL, "File read error"); 724 725 char output[256 /* Large enough buffer */]; 726 char* res = fgets(output, sizeof(output), fp); 727 assert(res != NULL, "assert"); 728 729 assert(strstr(output, Test_logtarget_string_literal) == NULL, "log line not missing"); 730 731 fclose(fp); 732 } 733 734 void Test_logtarget() { 735 Test_logtarget_on(); 736 Test_logtarget_off(); 737 } 738 739 740 static void Test_logstream_helper(outputStream* stream) { 741 TestLogFile log_file("log_stream"); 742 TestLogSavedConfig tlsc(log_file.name(), "gc=debug"); 743 744 // Try to log, but expect this to be filtered out. 745 stream->print("%d ", 3); stream->print("workers"); stream->cr(); 746 747 FILE* fp = fopen(log_file.name(), "r"); 748 assert(fp != NULL, "File read error"); 749 750 char output[256 /* Large enough buffer */]; 751 char* res = fgets(output, sizeof(output), fp); 752 assert(res != NULL, "assert"); 753 754 assert(strstr(output, "3 workers") != NULL, "log line missing"); 755 756 fclose(fp); 757 } 758 759 static void Test_logstream_log() { 760 Log(gc) log; 761 LogStream stream(log.debug()); 762 763 Test_logstream_helper(&stream); 764 } 765 766 static void Test_logstream_logtarget() { 767 LogTarget(Debug, gc) log; 768 LogStream stream(log); 769 770 Test_logstream_helper(&stream); 771 } 772 773 static void Test_logstream_logstreamhandle() { 774 LogStreamHandle(Debug, gc) stream; 775 776 Test_logstream_helper(&stream); 777 } 778 779 static void Test_logstream_no_rm() { 780 ResourceMark rm; 781 outputStream* stream = LogTarget(Debug, gc)::stream(); 782 783 Test_logstream_helper(stream); 784 } 785 786 static void Test_logstreamcheap_log() { 787 Log(gc) log; 788 LogStreamCHeap stream(log.debug()); 789 790 Test_logstream_helper(&stream); 791 } 792 793 static void Test_logstreamcheap_logtarget() { 794 LogTarget(Debug, gc) log; 795 LogStreamCHeap stream(log); 796 797 Test_logstream_helper(&stream); 798 } 799 800 void Test_logstream() { 801 // Test LogStreams with embedded ResourceMark. 802 Test_logstream_log(); 803 Test_logstream_logtarget(); 804 Test_logstream_logstreamhandle(); 805 806 // Test LogStreams without embedded ResourceMark. 807 Test_logstream_no_rm(); 808 809 // Test LogStreams backed by CHeap memory. 810 Test_logstreamcheap_log(); 811 Test_logstreamcheap_logtarget(); 812 } 813 814 void Test_loghandle_on() { 815 TestLogFile log_file("log_handle"); 816 TestLogSavedConfig tlsc(log_file.name(), "gc=debug"); 817 818 Log(gc) log; 819 LogHandle log_handle(log); 820 821 assert(log_handle.is_debug(), "assert"); 822 823 // Try to log through a LogHandle. 824 log_handle.debug("%d workers", 3); 825 826 FILE* fp = fopen(log_file.name(), "r"); 827 assert(fp, "File read error"); 828 829 char output[256 /* Large enough buffer */]; 830 char* res = fgets(output, sizeof(output), fp); 831 assert(res != NULL, "assert"); 832 833 assert(strstr(output, "3 workers") != NULL, "log line missing"); 834 835 fclose(fp); 836 } 837 838 void Test_loghandle_off() { 839 TestLogFile log_file("log_handle"); 840 TestLogSavedConfig tlsc(log_file.name(), "gc=info"); 841 842 Log(gc) log; 843 LogHandle log_handle(log); 844 845 if (log_handle.is_debug()) { 846 // The log config could have been redirected gc=debug to a file. If gc=debug 847 // is enabled, we can only test that the LogTarget returns the same value 848 // as the log_is_enabled function. The rest of the test will be ignored. 849 assert(log_handle.is_debug() == log_is_enabled(Debug, gc), "assert"); 850 log_warning(logging)("This test doesn't support runs with -Xlog"); 851 return; 852 } 853 854 // Try to log through a LogHandle. Should fail, since only info is turned on. 855 log_handle.debug("%d workers", 3); 856 857 // Log a dummy line so that fgets doesn't return NULL because the file is empty. 858 log_info(gc)("Dummy line"); 859 860 FILE* fp = fopen(log_file.name(), "r"); 861 assert(fp, "File read error"); 862 863 char output[256 /* Large enough buffer */]; 864 char* res = fgets(output, sizeof(output), fp); 865 assert(res != NULL, "assert"); 866 867 assert(strstr(output, "3 workers") == NULL, "log line missing"); 868 869 fclose(fp); 870 } 871 872 void Test_loghandle() { 873 Test_loghandle_on(); 874 Test_loghandle_off(); 875 } 876 877 static void Test_logtargethandle_on() { 878 TestLogFile log_file("log_handle"); 879 TestLogSavedConfig tlsc(log_file.name(), "gc=debug"); 880 881 LogTarget(Debug, gc) log; 882 LogTargetHandle log_handle(log); 883 884 assert(log_handle.is_enabled(), "assert"); 885 886 // Try to log through a LogHandle. 887 log_handle.print("%d workers", 3); 888 889 FILE* fp = fopen(log_file.name(), "r"); 890 assert(fp, "File read error"); 891 892 char output[256 /* Large enough buffer */]; 893 char* res = fgets(output, sizeof(output), fp); 894 assert(res != NULL, "assert"); 895 896 assert(strstr(output, "3 workers") != NULL, "log line missing"); 897 898 fclose(fp); 899 } 900 901 static void Test_logtargethandle_off() { 902 TestLogFile log_file("log_handle"); 903 TestLogSavedConfig tlsc(log_file.name(), "gc=info"); 904 905 LogTarget(Debug, gc) log; 906 LogTargetHandle log_handle(log); 907 908 if (log_handle.is_enabled()) { 909 // The log config could have been redirected gc=debug to a file. If gc=debug 910 // is enabled, we can only test that the LogTarget returns the same value 911 // as the log_is_enabled function. The rest of the test will be ignored. 912 assert(log_handle.is_enabled() == log_is_enabled(Debug, gc), "assert"); 913 log_warning(logging)("This test doesn't support runs with -Xlog"); 914 return; 915 } 916 917 // Try to log through a LogHandle. Should fail, since only info is turned on. 918 log_handle.print("%d workers", 3); 919 920 // Log a dummy line so that fgets doesn't return NULL because the file is empty. 921 log_info(gc)("Dummy line"); 922 923 FILE* fp = fopen(log_file.name(), "r"); 924 assert(fp, "File read error"); 925 926 char output[256 /* Large enough buffer */]; 927 char* res = fgets(output, sizeof(output), fp); 928 assert(res != NULL, "assert"); 929 930 assert(strstr(output, "3 workers") == NULL, "log line missing"); 931 932 fclose(fp); 933 } 934 935 void Test_logtargethandle() { 936 Test_logtargethandle_on(); 937 Test_logtargethandle_off(); 938 } 939 940 static void Test_log_gctracetime_full() { 941 TestLogFile log_file("log_gctracetime"); 942 TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); 943 944 LogTarget(Debug, gc) gc_debug; 945 LogTarget(Debug, gc, start) gc_start_debug; 946 947 assert(gc_debug.is_enabled(), "assert"); 948 assert(gc_start_debug.is_enabled(), "assert"); 949 950 { 951 MutexLocker lock(Heap_lock); // Needed to read heap usage 952 GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, true); 953 } 954 955 FILE* fp = fopen(log_file.name(), "r"); 956 assert(fp, "File read error"); 957 958 char output[256 /* Large enough buffer */]; 959 960 char* res = fgets(output, sizeof(output), fp); 961 assert(res != NULL, "assert"); 962 963 // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) 964 assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); 965 assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); 966 assert(strstr(output, "s)") != NULL, "Incorrect log line"); 967 968 res = fgets(output, sizeof(output), fp); 969 assert(res != NULL, "assert"); 970 971 // [2.975s][debug][gc ] Test GC (Allocation Failure) 59M->59M(502M) (2.975s, 2.975s) 0.026ms 972 assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); 973 assert(strstr(output, "] Test GC (Allocation Failure) ") != NULL, "Incorrect log line"); 974 assert(strstr(output, "M) (") != NULL, "Incorrect log line"); 975 assert(strstr(output, "s, ") != NULL, "Incorrect log line"); 976 assert(strstr(output, "s) ") != NULL, "Incorrect log line"); 977 assert(strstr(output, "ms") != NULL, "Incorrect log line"); 978 979 fclose(fp); 980 } 981 982 static void Test_log_gctracetime_full_multitag() { 983 TestLogFile log_file("log_gctracetime"); 984 TestLogSavedConfig tlsc(log_file.name(), "gc+ref=debug,gc+ref+start=debug"); 985 986 LogTarget(Debug, gc, ref) gc_debug; 987 LogTarget(Debug, gc, ref, start) gc_start_debug; 988 989 assert(gc_debug.is_enabled(), "assert"); 990 assert(gc_start_debug.is_enabled(), "assert"); 991 992 { 993 MutexLocker lock(Heap_lock); // Needed to read heap usage 994 GCTraceTime(Debug, gc, ref) timer("Test GC", NULL, GCCause::_allocation_failure, true); 995 } 996 997 FILE* fp = fopen(log_file.name(), "r"); 998 assert(fp, "File read error"); 999 1000 char output[256 /* Large enough buffer */]; 1001 1002 char* res = fgets(output, sizeof(output), fp); 1003 assert(res != NULL, "assert"); 1004 1005 // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) 1006 assert(strstr(output, "[gc,ref,start") != NULL, "Incorrect tag set"); 1007 assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); 1008 assert(strstr(output, "s)") != NULL, "Incorrect log line"); 1009 1010 res = fgets(output, sizeof(output), fp); 1011 assert(res != NULL, "assert"); 1012 1013 // [2.975s][debug][gc ] Test GC (Allocation Failure) 59M->59M(502M) (2.975s, 2.975s) 0.026ms 1014 assert(strstr(output, "[gc,ref ") != NULL, "Incorrect tag set"); 1015 assert(strstr(output, "] Test GC (Allocation Failure) ") != NULL, "Incorrect log line"); 1016 assert(strstr(output, "M) (") != NULL, "Incorrect log line"); 1017 assert(strstr(output, "s, ") != NULL, "Incorrect log line"); 1018 assert(strstr(output, "s) ") != NULL, "Incorrect log line"); 1019 assert(strstr(output, "ms") != NULL, "Incorrect log line"); 1020 1021 fclose(fp); 1022 } 1023 1024 static void Test_log_gctracetime_no_heap() { 1025 TestLogFile log_file("log_gctracetime"); 1026 TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); 1027 1028 LogTarget(Debug, gc) gc_debug; 1029 LogTarget(Debug, gc, start) gc_start_debug; 1030 1031 assert(gc_debug.is_enabled(), "assert"); 1032 assert(gc_start_debug.is_enabled(), "assert"); 1033 1034 { 1035 GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, false); 1036 } 1037 1038 FILE* fp = fopen(log_file.name(), "r"); 1039 assert(fp, "File read error"); 1040 1041 char output[256 /* Large enough buffer */]; 1042 1043 char* res = fgets(output, sizeof(output), fp); 1044 assert(res != NULL, "assert"); 1045 1046 // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) 1047 assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); 1048 assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); 1049 assert(strstr(output, "s)") != NULL, "Incorrect log line"); 1050 1051 res = fgets(output, sizeof(output), fp); 1052 assert(res != NULL, "assert"); 1053 1054 // [2.975s][debug][gc ] Test GC (Allocation Failure) (2.975s, 2.975s) 0.026ms 1055 assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); 1056 assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); 1057 assert(strstr(output, "M) (") == NULL, "Incorrect log line"); 1058 assert(strstr(output, "s, ") != NULL, "Incorrect log line"); 1059 assert(strstr(output, "s) ") != NULL, "Incorrect log line"); 1060 assert(strstr(output, "ms") != NULL, "Incorrect log line"); 1061 1062 fclose(fp); 1063 } 1064 1065 static void Test_log_gctracetime_no_cause() { 1066 TestLogFile log_file("log_gctracetime"); 1067 TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); 1068 1069 LogTarget(Debug, gc) gc_debug; 1070 LogTarget(Debug, gc, start) gc_start_debug; 1071 1072 assert(gc_debug.is_enabled(), "assert"); 1073 assert(gc_start_debug.is_enabled(), "assert"); 1074 1075 { 1076 MutexLocker lock(Heap_lock); // Needed to read heap usage 1077 GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, true); 1078 } 1079 1080 FILE* fp = fopen(log_file.name(), "r"); 1081 assert(fp, "File read error"); 1082 1083 char output[256 /* Large enough buffer */]; 1084 1085 char* res = fgets(output, sizeof(output), fp); 1086 assert(res != NULL, "assert"); 1087 1088 // [2.975s][debug][gc,start] Test GC (2.975s) 1089 assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); 1090 assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line"); 1091 assert(strstr(output, "s)") != NULL, "Incorrect log line"); 1092 1093 res = fgets(output, sizeof(output), fp); 1094 assert(res != NULL, "assert"); 1095 1096 // [2.975s][debug][gc ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms 1097 assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); 1098 assert(strstr(output, "] Test GC ") != NULL, "Incorrect log line"); 1099 assert(strstr(output, "M) (") != NULL, "Incorrect log line"); 1100 assert(strstr(output, "s, ") != NULL, "Incorrect log line"); 1101 assert(strstr(output, "s) ") != NULL, "Incorrect log line"); 1102 assert(strstr(output, "ms") != NULL, "Incorrect log line"); 1103 1104 fclose(fp); 1105 } 1106 1107 static void Test_log_gctracetime_no_heap_no_cause() { 1108 TestLogFile log_file("log_gctracetime"); 1109 TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); 1110 1111 LogTarget(Debug, gc) gc_debug; 1112 LogTarget(Debug, gc, start) gc_start_debug; 1113 1114 assert(gc_debug.is_enabled(), "assert"); 1115 assert(gc_start_debug.is_enabled(), "assert"); 1116 1117 { 1118 MutexLocker lock(Heap_lock); // Needed to read heap usage 1119 GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, false); 1120 } 1121 1122 FILE* fp = fopen(log_file.name(), "r"); 1123 assert(fp, "File read error"); 1124 1125 char output[256 /* Large enough buffer */]; 1126 1127 char* res = fgets(output, sizeof(output), fp); 1128 assert(res != NULL, "assert"); 1129 1130 // [2.975s][debug][gc,start] Test GC (2.975s) 1131 assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); 1132 assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line"); 1133 assert(strstr(output, "s)") != NULL, "Incorrect log line"); 1134 1135 res = fgets(output, sizeof(output), fp); 1136 assert(res != NULL, "assert"); 1137 1138 // [2.975s][debug][gc ] Test GC (2.975s, 2.975s) 0.026ms 1139 assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); 1140 assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line"); 1141 assert(strstr(output, "M) (") == NULL, "Incorrect log line"); 1142 assert(strstr(output, "s, ") != NULL, "Incorrect log line"); 1143 assert(strstr(output, "s) ") != NULL, "Incorrect log line"); 1144 assert(strstr(output, "ms") != NULL, "Incorrect log line"); 1145 1146 fclose(fp); 1147 } 1148 1149 void Test_log_gctracetime() { 1150 Test_log_gctracetime_full(); 1151 Test_log_gctracetime_full_multitag(); 1152 Test_log_gctracetime_no_heap(); 1153 Test_log_gctracetime_no_cause(); 1154 Test_log_gctracetime_no_heap_no_cause(); 1155 } 1156 1157 void Test_invalid_log_file() { 1158 ResourceMark rm; 1159 stringStream ss; 1160 const char* target_name = "tmplogdir"; 1161 1162 // Attempt to log to a directory (existing log not a regular file) 1163 create_directory(target_name); 1164 LogFileOutput bad_file("file=tmplogdir"); 1165 assert(bad_file.initialize("", &ss) == false, "file was initialized " 1166 "when there was an existing directory with the same name"); 1167 assert(strstr(ss.as_string(), "tmplogdir is not a regular file") != NULL, 1168 "missing expected error message, received msg: %s", ss.as_string()); 1169 ss.reset(); 1170 remove(target_name); 1171 } 1172 1173 // Ensure -Xlog:help and LogConfiguration::describe contain tagset descriptions 1174 void Test_logtagset_descriptions() { 1175 for (LogTagSetDescription* d = tagset_descriptions; d->tagset != NULL; d++) { 1176 char expected[1024]; 1177 d->tagset->label(expected, sizeof(expected), "+"); 1178 jio_snprintf(expected + strlen(expected), 1179 sizeof(expected) - strlen(expected), 1180 ": %s", d->descr); 1181 1182 ResourceMark rm; 1183 stringStream ss; 1184 LogConfiguration::describe(&ss); 1185 assert(strstr(ss.as_string(), expected) != NULL, 1186 "missing log tag set descriptions in LogConfiguration::describe"); 1187 1188 TestLogFile file("log_tagset_descriptions"); 1189 FILE* fp = fopen(file.name(), "w+"); 1190 assert(fp != NULL, "File open error"); 1191 LogConfiguration::print_command_line_help(fp); 1192 fclose(fp); 1193 assert(number_of_lines_with_substring_in_file(file.name(), expected) > 0, 1194 "missing log tag set descriptions in -Xlog:help output"); 1195 } 1196 } 1197 #endif // PRODUCT