1 /* 2 * Copyright (c) 2015, 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 "logging/log.hpp" 32 #include "logging/logConfiguration.hpp" 33 #include "logging/logMessage.hpp" 34 #include "logging/logMessageBuffer.hpp" 35 #include "logging/logOutput.hpp" 36 #include "memory/resourceArea.hpp" 37 38 static bool file_contains_substrings_in_order(const char* filename, const char* substrs[]) { 39 FILE* fp = fopen(filename, "r"); 40 assert(fp, "File read error"); 41 char buffer[1024]; 42 for (int i = 0; substrs[i] != NULL; i++) { 43 assert(sizeof(buffer) > strlen(substrs[i]), "insufficient buffer"); 44 bool found = false; 45 while (fgets(buffer, sizeof(buffer), fp) != NULL) { 46 if (strstr(buffer, substrs[i]) != NULL) { 47 found = true; 48 break; 49 } 50 } 51 if (!found) { 52 return false; 53 } 54 } 55 fclose(fp); 56 return true; 57 } 58 59 static bool file_contains_substring(const char* filename, const char* substr) { 60 const char* strs[] = {substr, NULL}; 61 return file_contains_substrings_in_order(filename, strs); 62 } 63 64 void Test_log_length() { 65 remove("loglengthoutput.txt"); 66 67 // Write long message to output file 68 ResourceMark rm; 69 LogHandle(logging) log; 70 bool success = LogConfiguration::parse_log_arguments("loglengthoutput.txt", "logging=trace", 71 NULL, NULL, log.error_stream()); 72 assert(success, "test unable to configure logging"); 73 log.trace("01:1234567890-" 74 "02:1234567890-" 75 "03:1234567890-" 76 "04:1234567890-" 77 "05:1234567890-" 78 "06:1234567890-" 79 "07:1234567890-" 80 "08:1234567890-" 81 "09:1234567890-" 82 "10:1234567890-" 83 "11:1234567890-" 84 "12:1234567890-" 85 "13:1234567890-" 86 "14:1234567890-" 87 "15:1234567890-" 88 "16:1234567890-" 89 "17:1234567890-" 90 "18:1234567890-" 91 "19:1234567890-" 92 "20:1234567890-" 93 "21:1234567890-" 94 "22:1234567890-" 95 "23:1234567890-" 96 "24:1234567890-" 97 "25:1234567890-" 98 "26:1234567890-" 99 "27:1234567890-" 100 "28:1234567890-" 101 "29:1234567890-" 102 "30:1234567890-" 103 "31:1234567890-" 104 "32:1234567890-" 105 "33:1234567890-" 106 "34:1234567890-" 107 "35:1234567890-" 108 "36:1234567890-" 109 "37:1234567890-"); 110 LogConfiguration::parse_log_arguments("loglengthoutput.txt", "all=off", 111 NULL, NULL, log.error_stream()); 112 113 // Look for end of message in output file 114 assert(file_contains_substring("loglengthoutput.txt", "37:1234567890-"), "logging print size error"); 115 remove("loglengthoutput.txt"); 116 } 117 118 #define assert_str_eq(s1, s2) \ 119 assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2) 120 121 #define assert_char_in(c, s) \ 122 assert(strchr(s, c) != NULL, "Expected '%s' to contain character '%c'", s, c) 123 124 #define assert_char_not_in(c, s) \ 125 assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c) 126 127 void Test_configure_stdout() { 128 ResourceMark rm; 129 LogHandle(logging) log; 130 LogOutput* stdoutput = LogOutput::Stdout; 131 132 // Save current stdout config and clear it 133 char* saved_config = os::strdup_check_oom(stdoutput->config_string()); 134 LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, log.error_stream()); 135 136 // Enable 'logging=info', verifying it has been set 137 LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging)); 138 assert_str_eq("logging=info,", stdoutput->config_string()); 139 assert(log_is_enabled(Info, logging), "logging was not properly enabled"); 140 141 // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled 142 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc)); 143 // No '+' character means only single tags are enabled, and no combinations 144 assert_char_not_in('+', stdoutput->config_string()); 145 assert(log_is_enabled(Debug, gc), "logging was not properly enabled"); 146 147 // Enable 'gc*=trace' (with wildcard), verifying at least one tag combination is enabled (gc+...) 148 LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc)); 149 assert_char_in('+', stdoutput->config_string()); 150 assert(log_is_enabled(Trace, gc), "logging was not properly enabled"); 151 152 // Disable 'gc*' and 'logging', verifying all logging is properly disabled 153 LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc)); 154 LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging)); 155 assert_str_eq("all=off", stdoutput->config_string()); 156 157 // Restore saved configuration 158 LogConfiguration::parse_log_arguments("stdout", saved_config, NULL, NULL, log.error_stream()); 159 os::free(saved_config); 160 } 161 162 class LogMessageTest { 163 private: 164 static LogHandle(logging) _log; 165 static const char* _level_filename[]; 166 167 static void test_level_inclusion(); 168 static void test_long_message(); 169 static void test_message_with_many_lines(); 170 static void test_line_order(); 171 static void test_prefixing(); 172 static void test_scoped_messages(); 173 174 public: 175 static void test(); 176 }; 177 178 const char* LogMessageTest::_level_filename[] = { 179 NULL, // LogLevel::Off 180 #define LOG_LEVEL(name, printname) "multiline-" #printname ".log", 181 LOG_LEVEL_LIST 182 #undef LOG_LEVEL 183 }; 184 185 void Test_multiline_logging() { 186 LogMessageTest::test(); 187 } 188 189 void LogMessageTest::test() { 190 ResourceMark rm; 191 192 for (int i = 0; i < LogLevel::Count; i++) { 193 char buf[32]; 194 // Attempt to remove possibly pre-existing log files 195 remove(_level_filename[i]); 196 197 jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i))); 198 bool success = LogConfiguration::parse_log_arguments(_level_filename[i], buf, 199 NULL, NULL, _log.error_stream()); 200 assert(success, "unable to configure logging to file '%s'", _level_filename[i]); 201 } 202 203 test_level_inclusion(); 204 test_line_order(); 205 test_long_message(); 206 test_message_with_many_lines(); 207 test_prefixing(); 208 test_scoped_messages(); 209 210 // Stop logging to the files and remove them. 211 for (int i = 0; i < LogLevel::Count; i++) { 212 LogConfiguration::parse_log_arguments(_level_filename[i], "all=off", NULL, NULL, _log.error_stream()); 213 remove(_level_filename[i]); 214 } 215 } 216 217 // Verify that messages with multiple levels are written 218 // to outputs configured for all the corresponding levels 219 void LogMessageTest::test_level_inclusion() { 220 const size_t message_count = 10; 221 LogMessageBuffer msg[message_count]; 222 223 struct { 224 int message_number; 225 LogLevelType level; 226 } lines[] = { 227 { 0, LogLevel::Error }, 228 { 1, LogLevel::Info }, 229 { 2, LogLevel::Info }, { 2, LogLevel::Debug }, 230 { 3, LogLevel::Info }, { 3, LogLevel::Warning }, 231 { 4, LogLevel::Debug }, { 4, LogLevel::Warning }, 232 { 5, LogLevel::Trace }, { 5, LogLevel::Debug }, 233 { 6, LogLevel::Warning }, { 6, LogLevel::Error }, 234 { 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug }, 235 { 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info }, 236 { 8, LogLevel::Warning }, { 8, LogLevel::Error}, 237 { 9, LogLevel::Trace } 238 }; 239 240 // Fill in messages with the above lines 241 for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { 242 switch (lines[i].level) { 243 #define LOG_LEVEL(name, printname) \ 244 case LogLevel::name: \ 245 msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \ 246 break; 247 LOG_LEVEL_LIST 248 #undef LOG_LEVEL 249 } 250 } 251 252 for (size_t i = 0; i < message_count; i++) { 253 _log.write(msg[i]); 254 } 255 256 // Verify that lines are written to the expected log files 257 for (size_t i = 0; i < ARRAY_SIZE(lines); i++) { 258 char expected[256]; 259 jio_snprintf(expected, sizeof(expected), "msg[%d]: %s", 260 lines[i].message_number, LogLevel::name(lines[i].level)); 261 for (int level = lines[i].level; level > 0; level--) { 262 assert(file_contains_substring(_level_filename[level], expected), 263 "line #" SIZE_FORMAT " missing from log file '%s'", i, _level_filename[level]); 264 } 265 for (int level = lines[i].level + 1; level < LogLevel::Count; level++) { 266 assert(!file_contains_substring(_level_filename[level], expected), 267 "line #" SIZE_FORMAT " erroneously included in log file '%s'", i, _level_filename[level]); 268 } 269 } 270 } 271 272 // Verify that messages are logged in the order they are added to the log message 273 void LogMessageTest::test_line_order() { 274 LogMessageBuffer msg; 275 msg.info("info line").error("error line").trace("trace line") 276 .error("another error").warning("warning line").debug("debug line"); 277 _log.write(msg); 278 279 const char* expected[] = { "info line", "error line", "trace line", 280 "another error", "warning line", "debug line", NULL }; 281 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), 282 "output missing or in incorrect order"); 283 } 284 285 void LogMessageTest::test_long_message() { 286 // Write 10K bytes worth of log data 287 LogMessageBuffer msg; 288 const size_t size = 10 * K; 289 const char* start_marker = "#start#"; 290 const char* end_marker = "#the end#"; 291 char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging); 292 293 // fill buffer with start_marker...some data...end_marker 294 sprintf(data, "%s", start_marker); 295 for (size_t i = strlen(start_marker); i < size; i++) { 296 data[i] = '0' + (i % 10); 297 } 298 sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker); 299 300 msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length. 301 _log.write(msg); 302 303 const char* expected[] = { start_marker, "0123456789", end_marker, NULL }; 304 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), 305 "unable to print long line"); 306 FREE_C_HEAP_ARRAY(char, data); 307 } 308 309 void LogMessageTest::test_message_with_many_lines() { 310 const size_t lines = 100; 311 const size_t line_length = 16; 312 313 LogMessageBuffer msg; 314 for (size_t i = 0; i < lines; i++) { 315 msg.info("Line #" SIZE_FORMAT, i); 316 } 317 _log.write(msg); 318 319 char expected_lines_data[lines][line_length]; 320 const char* expected_lines[lines + 1]; 321 for (size_t i = 0; i < lines; i++) { 322 jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i); 323 expected_lines[i] = expected_lines_data[i]; 324 } 325 expected_lines[lines] = NULL; 326 327 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines), 328 "couldn't find all lines in multiline message"); 329 } 330 331 static size_t dummy_prefixer(char* buf, size_t len) { 332 static int i = 0; 333 const char* prefix = "some prefix: "; 334 const size_t prefix_len = strlen(prefix); 335 if (len < prefix_len) { 336 return prefix_len; 337 } 338 jio_snprintf(buf, len, "%s", prefix); 339 return prefix_len; 340 } 341 342 void LogMessageTest::test_prefixing() { 343 LogMessageBuffer msg; 344 msg.set_prefix(dummy_prefixer); 345 for (int i = 0; i < 3; i++) { 346 msg.info("test %d", i); 347 } 348 msg.set_prefix(NULL); 349 msg.info("test 3"); 350 _log.write(msg); 351 352 const char* expected[] = { 353 "] some prefix: test 0", 354 "] some prefix: test 1", 355 "] some prefix: test 2", 356 "] test 3", 357 NULL 358 }; 359 assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), "error in prefixed output"); 360 } 361 362 void LogMessageTest::test_scoped_messages() { 363 { 364 LogMessage(logging) msg; 365 msg.info("scoped info"); 366 } 367 assert(file_contains_substring(_level_filename[LogLevel::Info], "scoped info"), 368 "missing output from scoped log message"); 369 } 370 371 #endif // PRODUCT