hotspot/src/share/vm/logging/log.cpp
changeset 37201 928cf689af1a
parent 37200 e601cf49b2d8
child 37242 91e5f98fff6f
child 37239 a6cda2376a19
equal deleted inserted replaced
37200:e601cf49b2d8 37201:928cf689af1a
    21  * questions.
    21  * questions.
    22  *
    22  *
    23  */
    23  */
    24 
    24 
    25 #include "precompiled.hpp"
    25 #include "precompiled.hpp"
       
    26 #include "logging/log.hpp"
       
    27 #include "memory/allocation.inline.hpp"
       
    28 
       
    29 void LogWriteHelper::write_large(LogTagSet& lts,
       
    30                                  LogLevelType level,
       
    31                                  const char* prefix,
       
    32                                  size_t prefix_len,
       
    33                                  size_t msg_len,
       
    34                                  const char* fmt,
       
    35                                  va_list args) {
       
    36   size_t newbuf_len = prefix_len + msg_len + 1;
       
    37   char* newbuf = NEW_C_HEAP_ARRAY(char, newbuf_len, mtLogging);
       
    38   memcpy(newbuf, prefix, prefix_len);
       
    39   int ret = os::log_vsnprintf(newbuf + prefix_len, newbuf_len - prefix_len, fmt, args);
       
    40   assert(ret >= 0, "Log message buffer issue");
       
    41   lts.log(level, newbuf);
       
    42   FREE_C_HEAP_ARRAY(char, newbuf);
       
    43 }
    26 
    44 
    27 /////////////// Unit tests ///////////////
    45 /////////////// Unit tests ///////////////
    28 
    46 
    29 #ifndef PRODUCT
    47 #ifndef PRODUCT
    30 
    48 
    31 #include "logging/log.hpp"
    49 #include "logging/log.hpp"
    32 #include "logging/logConfiguration.hpp"
    50 #include "logging/logConfiguration.hpp"
    33 #include "logging/logOutput.hpp"
    51 #include "logging/logOutput.hpp"
    34 #include "memory/resourceArea.hpp"
    52 #include "memory/resourceArea.hpp"
    35 
    53 
    36 void Test_log_length() {
       
    37   remove("loglengthoutput.txt");
       
    38 
       
    39   // Write long message to output file
       
    40   ResourceMark rm;
       
    41   LogHandle(logging) log;
       
    42   bool success = LogConfiguration::parse_log_arguments("loglengthoutput.txt", "logging=trace",
       
    43     NULL, NULL, log.error_stream());
       
    44   assert(success, "test unable to configure logging");
       
    45   log.trace("01:1234567890-"
       
    46             "02:1234567890-"
       
    47             "03:1234567890-"
       
    48             "04:1234567890-"
       
    49             "05:1234567890-"
       
    50             "06:1234567890-"
       
    51             "07:1234567890-"
       
    52             "08:1234567890-"
       
    53             "09:1234567890-"
       
    54             "10:1234567890-"
       
    55             "11:1234567890-"
       
    56             "12:1234567890-"
       
    57             "13:1234567890-"
       
    58             "14:1234567890-"
       
    59             "15:1234567890-"
       
    60             "16:1234567890-"
       
    61             "17:1234567890-"
       
    62             "18:1234567890-"
       
    63             "19:1234567890-"
       
    64             "20:1234567890-"
       
    65             "21:1234567890-"
       
    66             "22:1234567890-"
       
    67             "23:1234567890-"
       
    68             "24:1234567890-"
       
    69             "25:1234567890-"
       
    70             "26:1234567890-"
       
    71             "27:1234567890-"
       
    72             "28:1234567890-"
       
    73             "29:1234567890-"
       
    74             "30:1234567890-"
       
    75             "31:1234567890-"
       
    76             "32:1234567890-"
       
    77             "33:1234567890-"
       
    78             "34:1234567890-"
       
    79             "35:1234567890-"
       
    80             "36:1234567890-"
       
    81             "37:1234567890-");
       
    82   LogConfiguration::parse_log_arguments("loglengthoutput.txt", "all=off",
       
    83     NULL, NULL, log.error_stream());
       
    84 
       
    85   // Look for end of message in output file
       
    86   FILE* fp = fopen("loglengthoutput.txt", "r");
       
    87   assert(fp, "File read error");
       
    88   char output[600];
       
    89   if (fgets(output, 600, fp) != NULL) {
       
    90     assert(strstr(output, "37:1234567890-"), "logging print size error");
       
    91   }
       
    92   fclose(fp);
       
    93   remove("loglengthoutput.txt");
       
    94 }
       
    95 
       
    96 #define assert_str_eq(s1, s2) \
    54 #define assert_str_eq(s1, s2) \
    97   assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2)
    55   assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2)
    98 
    56 
    99 #define assert_char_in(c, s) \
    57 #define assert_char_in(c, s) \
   100   assert(strchr(s, c) != NULL, "Expected '%s' to contain character '%c'", s, c)
    58   assert(strchr(s, c) != NULL, "Expected '%s' to contain character '%c'", s, c)
   101 
    59 
   102 #define assert_char_not_in(c, s) \
    60 #define assert_char_not_in(c, s) \
   103   assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c)
    61   assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c)
   104 
    62 
       
    63 class TestLogFile {
       
    64  private:
       
    65   char file_name[256];
       
    66 
       
    67   void set_name(const char* test_name) {
       
    68     const char* tmpdir = os::get_temp_directory();
       
    69     int pos = jio_snprintf(file_name, sizeof(file_name), "%s%svmtest.%s.%d.log", tmpdir, os::file_separator(), test_name, os::current_process_id());
       
    70     assert(pos > 0, "too small log file name buffer");
       
    71     assert((size_t)pos < sizeof(file_name), "too small log file name buffer");
       
    72   }
       
    73 
       
    74  public:
       
    75   TestLogFile(const char* test_name) {
       
    76     set_name(test_name);
       
    77     remove(name());
       
    78   }
       
    79 
       
    80   ~TestLogFile() {
       
    81     remove(name());
       
    82   }
       
    83 
       
    84   const char* name() {
       
    85     return file_name;
       
    86   }
       
    87 };
       
    88 
       
    89 class TestLogSavedConfig {
       
    90  private:
       
    91   char* _saved_config;
       
    92   char* _new_output;
       
    93   LogHandle(logging) _log;
       
    94  public:
       
    95   TestLogSavedConfig(const char* apply_output = NULL, const char* apply_setting = NULL) : _new_output(0) {
       
    96     _saved_config = os::strdup_check_oom(LogOutput::Stdout->config_string());
       
    97     bool success = LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, _log.error_stream());
       
    98     assert(success, "test unable to turn all off");
       
    99 
       
   100     if (apply_output) {
       
   101       _new_output = os::strdup_check_oom(apply_output);
       
   102       bool success = LogConfiguration::parse_log_arguments(_new_output, apply_setting,  NULL, NULL, _log.error_stream());
       
   103       assert(success, "test unable to apply test log configuration");
       
   104     }
       
   105   }
       
   106 
       
   107   ~TestLogSavedConfig() {
       
   108     if (_new_output) {
       
   109       bool success = LogConfiguration::parse_log_arguments(_new_output, "all=off", NULL, NULL, _log.error_stream());
       
   110       assert(success, "test unable to turn all off");
       
   111       os::free(_new_output);
       
   112     }
       
   113 
       
   114     bool success = LogConfiguration::parse_log_arguments("stdout", _saved_config, NULL, NULL, _log.error_stream());
       
   115     assert(success, "test unable to restore log configuration");
       
   116     os::free(_saved_config);
       
   117   }
       
   118 };
       
   119 
   105 void Test_configure_stdout() {
   120 void Test_configure_stdout() {
   106   ResourceMark rm;
   121   ResourceMark rm;
   107   LogHandle(logging) log;
       
   108   LogOutput* stdoutput = LogOutput::Stdout;
   122   LogOutput* stdoutput = LogOutput::Stdout;
   109 
   123   TestLogSavedConfig tlsc;
   110   // Save current stdout config and clear it
       
   111   char* saved_config = os::strdup_check_oom(stdoutput->config_string());
       
   112   LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, log.error_stream());
       
   113 
   124 
   114   // Enable 'logging=info', verifying it has been set
   125   // Enable 'logging=info', verifying it has been set
   115   LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
   126   LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
   116   assert_str_eq("logging=info,", stdoutput->config_string());
   127   assert_str_eq("logging=info,", stdoutput->config_string());
   117   assert(log_is_enabled(Info, logging), "logging was not properly enabled");
   128   assert(log_is_enabled(Info, logging), "logging was not properly enabled");
   129 
   140 
   130   // Disable 'gc*' and 'logging', verifying all logging is properly disabled
   141   // Disable 'gc*' and 'logging', verifying all logging is properly disabled
   131   LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
   142   LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
   132   LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
   143   LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
   133   assert_str_eq("all=off", stdoutput->config_string());
   144   assert_str_eq("all=off", stdoutput->config_string());
   134 
       
   135   // Restore saved configuration
       
   136   LogConfiguration::parse_log_arguments("stdout", saved_config, NULL, NULL, log.error_stream());
       
   137   os::free(saved_config);
       
   138 }
   145 }
   139 
   146 
   140 static int Test_logconfiguration_subscribe_triggered = 0;
   147 static int Test_logconfiguration_subscribe_triggered = 0;
   141 
   148 
   142 static void Test_logconfiguration_subscribe_helper() {
   149 static void Test_logconfiguration_subscribe_helper() {
   145 
   152 
   146 void Test_logconfiguration_subscribe() {
   153 void Test_logconfiguration_subscribe() {
   147   ResourceMark rm;
   154   ResourceMark rm;
   148   LogHandle(logging) log;
   155   LogHandle(logging) log;
   149 
   156 
       
   157   TestLogSavedConfig log_cfg("stdout", "logging+test=trace");
       
   158 
   150   LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);
   159   LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);
   151 
   160 
   152   LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream());
   161   LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream());
   153   assert(Test_logconfiguration_subscribe_triggered == 1, "subscription not triggered (1)");
   162   assert(Test_logconfiguration_subscribe_triggered == 1, "subscription not triggered (1)");
   154 
   163 
   155   LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
   164   LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
   156   assert(Test_logconfiguration_subscribe_triggered == 2, "subscription not triggered (2)");
   165   assert(Test_logconfiguration_subscribe_triggered == 2, "subscription not triggered (2)");
   157 
   166 
   158   LogConfiguration::disable_logging();
   167   LogConfiguration::disable_logging();
   159   assert(Test_logconfiguration_subscribe_triggered == 3, "subscription not triggered (3)");
   168   assert(Test_logconfiguration_subscribe_triggered == 3, "subscription not triggered (3)");
       
   169 
       
   170   // We need to renable stderr error logging since "disable_logging" disable it all.
       
   171   // TestLogSavedConfig log_cfg will only renable stdout for us.
       
   172   LogConfiguration::parse_log_arguments("stderr", "all=warning", NULL, NULL, log.error_stream());
       
   173   assert(Test_logconfiguration_subscribe_triggered == 4, "subscription not triggered (3)");
       
   174 }
       
   175 
       
   176 #define LOG_PREFIX_STR "THE_PREFIX "
       
   177 #define LOG_LINE_STR "a log line"
       
   178 
       
   179 size_t Test_log_prefix_prefixer(char* buf, size_t len) {
       
   180   int ret = jio_snprintf(buf, len, LOG_PREFIX_STR);
       
   181   assert(ret > 0, "Failed to print prefix. Log buffer too small?");
       
   182   return (size_t) ret;
       
   183 }
       
   184 
       
   185 void Test_log_prefix() {
       
   186   ResourceMark rm;
       
   187   TestLogFile log_file("log_prefix");
       
   188   TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
       
   189 
       
   190   log_trace(logging, test)(LOG_LINE_STR);
       
   191 
       
   192   FILE* fp = fopen(log_file.name(), "r");
       
   193   assert(fp, "File read error");
       
   194   char output[1024];
       
   195   if (fgets(output, 1024, fp) != NULL) {
       
   196     assert(strstr(output, LOG_PREFIX_STR LOG_LINE_STR), "logging prefix error");
       
   197   }
       
   198   fclose(fp);
       
   199 }
       
   200 
       
   201 void Test_log_big() {
       
   202   char big_msg[4096] = {0};
       
   203   char Xchar = '~';
       
   204 
       
   205   ResourceMark rm;
       
   206   TestLogFile log_file("log_big");
       
   207   TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
       
   208 
       
   209   memset(big_msg, Xchar, sizeof(big_msg) - 1);
       
   210 
       
   211   log_trace(logging, test)("%s", big_msg);
       
   212 
       
   213   FILE* fp = fopen(log_file.name(), "r");
       
   214   assert(fp, "File read error");
       
   215   char output[sizeof(big_msg)+128 /*decorators*/ ];
       
   216   if (fgets(output, sizeof(output), fp) != NULL) {
       
   217     assert(strstr(output, LOG_PREFIX_STR), "logging prefix error");
       
   218     size_t count = 0;
       
   219     for (size_t ps = 0 ; output[ps + count] != '\0'; output[ps + count] == Xchar ? count++ : ps++);
       
   220     assert(count == (sizeof(big_msg) - 1) , "logging msg error");
       
   221   }
       
   222   fclose(fp);
   160 }
   223 }
   161 
   224 
   162 void Test_logtagset_duplicates() {
   225 void Test_logtagset_duplicates() {
   163   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
   226   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
   164     char ts_name[512];
   227     char ts_name[512];