35 #include "logging/logMessage.hpp"

    36 #include "logging/logMessageBuffer.hpp"

    57 }

    58 

    59 // Read a complete line from fp and return it as a resource allocated string.

    60 // Returns NULL on EOF.

    61 static char* read_line(FILE* fp) {

    62   assert(fp != NULL, "bad fp");

    63   int buflen = 512;

    64   char* buf = NEW_RESOURCE_ARRAY(char, buflen);

    65   long pos = ftell(fp);

    66 

    67   char* ret = fgets(buf, buflen, fp);

    68   while (ret != NULL && buf[strlen(buf) - 1] != '\n' && !feof(fp)) {

    69     // retry with a larger buffer

    70     buf = REALLOC_RESOURCE_ARRAY(char, buf, buflen, buflen * 2);

    71     buflen *= 2;

    72     // rewind to beginning of line

    73     fseek(fp, pos, SEEK_SET);

    74     // retry read with new buffer

    75     ret = fgets(buf, buflen, fp);

    76   }

    77   return ret;

    78 }

    79 

    80 static bool file_contains_substrings_in_order(const char* filename, const char* substrs[]) {

    81   FILE* fp = fopen(filename, "r");

    82   assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));

    83 

    84   size_t idx = 0;

    85   while (substrs[idx] != NULL) {

    86     ResourceMark rm;

    87     char* line = read_line(fp);

    88     if (line == NULL) {

    89       break;

    90     }

    91     for (char* match = strstr(line, substrs[idx]); match != NULL;) {

    92       size_t match_len = strlen(substrs[idx]);

    93       idx++;

    94       if (substrs[idx] == NULL) {

    95         break;

    96       }

    97       match = strstr(match + match_len, substrs[idx]);

    98     }

    99   }

   100 

   101   fclose(fp);

   102   return substrs[idx] == NULL;

   103 }

   104 

   105 static bool file_contains_substring(const char* filename, const char* substr) {

   106   const char* strs[] = {substr, NULL};

   107   return file_contains_substrings_in_order(filename, strs);

   108 }

   109 

   110 static size_t number_of_lines_with_substring_in_file(const char* filename,

   111                                                      const char* substr) {

   112   FILE* fp = fopen(filename, "r");

   113   assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));

   114 

   115   size_t ret = 0;

   116   for (;;) {

   117     ResourceMark rm;

   118     char* line = read_line(fp);

   119     if (line == NULL) {

   120       break;

   121     }

   122     if (strstr(line, substr) != NULL) {

   123       ret++;

   124     }

   125   }

   126 

   127   fclose(fp);

   128   return ret;

   129 }

   130 

   131 static bool file_exists(const char* filename) {

   132   struct stat st;

   133   return os::stat(filename, &st) == 0;

   134 }

   135 

   136 static void delete_file(const char* filename) {

   137   if (!file_exists(filename)) {

   138     return;

   139   }

   140   int ret = remove(filename);

   141   assert(ret == 0, "failed to remove file '%s': %s", filename, strerror(errno));

   142 }

   143 

   144 static void create_directory(const char* name) {

   145   assert(!file_exists(name), "can't create directory: %s already exists", name);

   146   bool failed;

   147 #ifdef _WINDOWS

   148   failed = !CreateDirectory(name, NULL);

   149 #else

   150   failed = mkdir(name, 0777);

   151 #endif

   152   assert(!failed, "failed to create directory %s", name);

   310 

   311 class LogMessageTest {

   312  private:

   313   static Log(logging) _log;

   314   static const char* _level_filename[];

   315 

   316   static void test_level_inclusion();

   317   static void test_long_message();

   318   static void test_message_with_many_lines();

   319   static void test_line_order();

   320   static void test_prefixing();

   321   static void test_scoped_messages();

   322   static void test_scoped_flushing();

   323   static void test_scoped_reset();

   324 

   325  public:

   326   static void test();

   327 };

   328 

   329 const char* LogMessageTest::_level_filename[] = {

   330   NULL, // LogLevel::Off

   331 #define LOG_LEVEL(name, printname) "multiline-" #printname ".log",

   332   LOG_LEVEL_LIST

   333 #undef LOG_LEVEL

   334 };

   335 

   336 void Test_multiline_logging() {

   337   LogMessageTest::test();

   338 }

   339 

   340 void LogMessageTest::test() {

   341   ResourceMark rm;

   342 

   343   for (int i = 0; i < LogLevel::Count; i++) {

   344     char buf[32];

   345     // Attempt to remove possibly pre-existing log files

   346     remove(_level_filename[i]);

   347 

   348     jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i)));

   349     bool success = LogConfiguration::parse_log_arguments(_level_filename[i], buf,

   350                                                          NULL, NULL, _log.error_stream());

   351     assert(success, "unable to configure logging to file '%s'", _level_filename[i]);

   352   }

   353 

   354   test_level_inclusion();

   355   test_line_order();

   356   test_long_message();

   357   test_message_with_many_lines();

   358   test_prefixing();

   359   test_scoped_messages();

   360   test_scoped_flushing();

   361   test_scoped_reset();

   362 

   363   // Stop logging to the files and remove them.

   364   for (int i = 0; i < LogLevel::Count; i++) {

   365     LogConfiguration::parse_log_arguments(_level_filename[i], "all=off", NULL, NULL, _log.error_stream());

   366     remove(_level_filename[i]);

   367   }

   368 }

   369 

   370 // Verify that messages with multiple levels are written

   371 // to outputs configured for all the corresponding levels

   372 void LogMessageTest::test_level_inclusion() {

   373   const size_t message_count = 10;

   374   LogMessageBuffer msg[message_count];

   375 

   376   struct {

   377     int message_number;

   378     LogLevelType level;

   379   } lines[] = {

   380     { 0, LogLevel::Error },

   381     { 1, LogLevel::Info },

   382     { 2, LogLevel::Info }, { 2, LogLevel::Debug },

   383     { 3, LogLevel::Info }, { 3, LogLevel::Warning },

   384     { 4, LogLevel::Debug }, { 4, LogLevel::Warning },

   385     { 5, LogLevel::Trace }, { 5, LogLevel::Debug },

   386     { 6, LogLevel::Warning }, { 6, LogLevel::Error },

   387     { 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug },

   388     { 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info },

   389     { 8, LogLevel::Warning }, { 8, LogLevel::Error},

   390     { 9, LogLevel::Trace }

   391   };

   392 

   393   // Fill in messages with the above lines

   394   for (size_t i = 0; i < ARRAY_SIZE(lines); i++) {

   395     switch (lines[i].level) {

   396 #define LOG_LEVEL(name, printname) \

   397     case LogLevel::name: \

   398       msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \

   399       break;

   400 LOG_LEVEL_LIST

   401 #undef LOG_LEVEL

   402     }

   403   }

   404 

   405   for (size_t i = 0; i < message_count; i++) {

   406     _log.write(msg[i]);

   407   }

   408 

   409   // Verify that lines are written to the expected log files

   410   for (size_t i = 0; i < ARRAY_SIZE(lines); i++) {

   411     char expected[256];

   412     jio_snprintf(expected, sizeof(expected), "msg[%d]: %s",

   413                  lines[i].message_number, LogLevel::name(lines[i].level));

   414     for (int level = lines[i].level; level > 0; level--) {

   415       assert(file_contains_substring(_level_filename[level], expected),

   416       "line #" SIZE_FORMAT " missing from log file '%s'", i, _level_filename[level]);

   417     }

   418     for (int level = lines[i].level + 1; level < LogLevel::Count; level++) {

   419       assert(!file_contains_substring(_level_filename[level], expected),

   420       "line #" SIZE_FORMAT " erroneously included in log file '%s'", i, _level_filename[level]);

   421     }

   422   }

   423 }

   424 

   425 // Verify that messages are logged in the order they are added to the log message

   426 void LogMessageTest::test_line_order() {

   427   LogMessageBuffer msg;

   428   msg.info("info line").error("error line").trace("trace line")

   429       .error("another error").warning("warning line").debug("debug line");

   430   _log.write(msg);

   431 

   432   const char* expected[] = { "info line", "error line", "trace line",

   433                              "another error", "warning line", "debug line", NULL };

   434   assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected),

   435          "output missing or in incorrect order");

   436 }

   437 

   438 void LogMessageTest::test_long_message() {

   439   // Write 10K bytes worth of log data

   440   LogMessageBuffer msg;

   441   const size_t size = 10 * K;

   442   const char* start_marker = "#start#";

   443   const char* end_marker = "#the end#";

   444   char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging);

   445 

   446   // fill buffer with start_marker...some data...end_marker

   447   sprintf(data, "%s", start_marker);

   448   for (size_t i = strlen(start_marker); i < size; i++) {

   449     data[i] = '0' + (i % 10);

   450   }

   451   sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker);

   452 

   453   msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length.

   454   _log.write(msg);

   455 

   456   const char* expected[] = { start_marker, "0123456789", end_marker, NULL };

   457   assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected),

   458          "unable to print long line");

   459   FREE_C_HEAP_ARRAY(char, data);

   460 }

   461 

   462 void LogMessageTest::test_message_with_many_lines() {

   463   const size_t lines = 100;

   464   const size_t line_length = 16;

   465 

   466   LogMessageBuffer msg;

   467   for (size_t i = 0; i < lines; i++) {

   468     msg.info("Line #" SIZE_FORMAT, i);

   469   }

   470   _log.write(msg);

   471 

   472   char expected_lines_data[lines][line_length];

   473   const char* expected_lines[lines + 1];

   474   for (size_t i = 0; i < lines; i++) {

   475     jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i);

   476     expected_lines[i] = expected_lines_data[i];

   477   }

   478   expected_lines[lines] = NULL;

   479 

   480   assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines),

   481          "couldn't find all lines in multiline message");

   482 }

   483 

   484 static size_t dummy_prefixer(char* buf, size_t len) {

   485   static int i = 0;

   486   const char* prefix = "some prefix: ";

   487   const size_t prefix_len = strlen(prefix);

   488   if (len < prefix_len) {

   489     return prefix_len;

   490   }

   491   jio_snprintf(buf, len, "%s", prefix);

   492   return prefix_len;

   493 }

   494 

   495 void LogMessageTest::test_prefixing() {

   496   LogMessageBuffer msg;

   497   msg.set_prefix(dummy_prefixer);

   498   for (int i = 0; i < 3; i++) {

   499     msg.info("test %d", i);

   500   }

   501   msg.set_prefix(NULL);

   502   msg.info("test 3");

   503   _log.write(msg);

   504 

   505   const char* expected[] = {

   506     "] some prefix: test 0",

   507     "] some prefix: test 1",

   508     "] some prefix: test 2",

   509     "] test 3",

   510     NULL

   511   };

   512   assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), "error in prefixed output");

   513 }

   514 

   515 void LogMessageTest::test_scoped_messages() {

   516   {

   517     LogMessage(logging) msg;

   518     msg.info("scoped info");

   519     msg.warning("scoped warn");

   520     assert(!file_contains_substring(_level_filename[LogLevel::Info], "scoped info"),

   521            "scoped log message written prematurely");

   522   }

   523   assert(file_contains_substring(_level_filename[LogLevel::Info], "scoped info"),

   524          "missing output from scoped log message");

   525   assert(file_contains_substring(_level_filename[LogLevel::Warning], "scoped warn"),

   526          "missing output from scoped log message");

   527 }

   528 

   529 void LogMessageTest::test_scoped_flushing() {

   530   {

   531     LogMessage(logging) msg;

   532     msg.info("manual flush info");

   533     msg.flush();

   534     assert(file_contains_substring(_level_filename[LogLevel::Info], "manual flush info"),

   535            "missing output from manually flushed scoped log message");

   536   }

   537   const char* tmp[] = {"manual flush info", "manual flush info", NULL};

   538   assert(!file_contains_substrings_in_order(_level_filename[LogLevel::Info], tmp),

   539          "log file contains duplicate lines from single scoped log message");

   540 }

   541 

   542 void LogMessageTest::test_scoped_reset() {

   543   {

   544     LogMessage(logging) msg, partial;

   545     msg.info("%s", "info reset msg");

   546     msg.reset();

   547     partial.info("%s", "info reset msg");

   548     partial.reset();

   549     partial.trace("%s", "trace reset msg");

   550   }

   551   assert(!file_contains_substring(_level_filename[LogLevel::Info], "info reset msg"),

   552          "reset message written anyway");

   553   assert(file_contains_substring(_level_filename[LogLevel::Trace], "trace reset msg"),

   554          "missing message from partially reset scoped log message");

   555 }

   556