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