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