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 #include "precompiled.hpp"
25 #include "logging/log.hpp"
26 #include "logging/logConfiguration.hpp"
27 #include "logging/logDecorations.hpp"
28 #include "logging/logDecorators.hpp"
29 #include "logging/logDiagnosticCommand.hpp"
30 #include "logging/logFileOutput.hpp"
31 #include "logging/logOutput.hpp"
32 #include "logging/logStream.hpp"
33 #include "logging/logTagLevelExpression.hpp"
34 #include "logging/logTagSet.hpp"
35 #include "memory/allocation.inline.hpp"
36 #include "memory/resourceArea.hpp"
37 #include "runtime/os.inline.hpp"
38 #include "runtime/semaphore.hpp"
39 #include "utilities/globalDefinitions.hpp"
40
41 LogOutput** LogConfiguration::_outputs = NULL;
42 size_t LogConfiguration::_n_outputs = 0;
43
44 LogConfiguration::UpdateListenerFunction* LogConfiguration::_listener_callbacks = NULL;
45 size_t LogConfiguration::_n_listener_callbacks = 0;
46
47 // Stack object to take the lock for configuring the logging.
48 // Should only be held during the critical parts of the configuration
49 // (when calling configure_output or reading/modifying the outputs array).
50 // Thread must never block when holding this lock.
51 class ConfigurationLock : public StackObj {
52 private:
53 // Semaphore used as lock
54 static Semaphore _semaphore;
55 debug_only(static intx _locking_thread_id;)
56 public:
57 ConfigurationLock() {
58 _semaphore.wait();
59 debug_only(_locking_thread_id = os::current_thread_id());
60 }
61 ~ConfigurationLock() {
62 debug_only(_locking_thread_id = -1);
63 _semaphore.signal();
64 }
65 debug_only(static bool current_thread_has_lock();)
66 };
67
68 Semaphore ConfigurationLock::_semaphore(1);
69 #ifdef ASSERT
70 intx ConfigurationLock::_locking_thread_id = -1;
71 bool ConfigurationLock::current_thread_has_lock() {
72 return _locking_thread_id == os::current_thread_id();
73 }
74 #endif
75
76 void LogConfiguration::post_initialize() {
77 LogDiagnosticCommand::registerCommand();
78 Log(logging) log;
79 if (log.is_info()) {
80 log.info("Log configuration fully initialized.");
81 log_develop_info(logging)("Develop logging is available.");
82 if (log.is_debug()) {
83 LogStream debug_stream(log.debug());
84 describe(&debug_stream);
85 if (log.is_trace()) {
86 LogStream trace_stream(log.trace());
87 LogTagSet::list_all_tagsets(&trace_stream);
88 }
89 }
90 }
91 }
92
93 void LogConfiguration::initialize(jlong vm_start_time) {
94 LogFileOutput::set_file_name_parameters(vm_start_time);
95 LogDecorations::initialize(vm_start_time);
96 assert(_outputs == NULL, "Should not initialize _outputs before this function, initialize called twice?");
97 _outputs = NEW_C_HEAP_ARRAY(LogOutput*, 2, mtLogging);
98 _outputs[0] = LogOutput::Stdout;
99 _outputs[1] = LogOutput::Stderr;
100 _n_outputs = 2;
101 }
102
103 void LogConfiguration::finalize() {
104 for (size_t i = 2; i < _n_outputs; i++) {
105 delete _outputs[i];
106 }
107 FREE_C_HEAP_ARRAY(LogOutput*, _outputs);
108 }
109
110 size_t LogConfiguration::find_output(const char* name) {
111 for (size_t i = 0; i < _n_outputs; i++) {
112 if (strcmp(_outputs[i]->name(), name) == 0) {
113 return i;
114 }
115 }
116 return SIZE_MAX;
117 }
118
119 LogOutput* LogConfiguration::new_output(char* name, const char* options, outputStream* errstream) {
120 const char* type;
121 char* equals_pos = strchr(name, '=');
122 if (equals_pos == NULL) {
123 type = "file";
124 } else {
125 *equals_pos = '\0';
126 type = name;
127 name = equals_pos + 1;
128 }
129
130 // Check if name is quoted, and if so, strip the quotes
131 char* quote = strchr(name, '"');
132 if (quote != NULL) {
133 char* end_quote = strchr(name + 1, '"');
134 if (end_quote == NULL) {
135 errstream->print_cr("Output name has opening quote but is missing a terminating quote.");
136 return NULL;
137 } else if (quote != name || end_quote[1] != '\0') {
138 errstream->print_cr("Output name can not be partially quoted."
139 " Either surround the whole name with quotation marks,"
140 " or do not use quotation marks at all.");
141 return NULL;
142 }
143 name++;
144 *end_quote = '\0';
145 }
146
147 LogOutput* output;
148 if (strcmp(type, "file") == 0) {
149 output = new LogFileOutput(name);
150 } else {
151 errstream->print_cr("Unsupported log output type.");
152 return NULL;
153 }
154
155 bool success = output->initialize(options, errstream);
156 if (!success) {
157 errstream->print_cr("Initialization of output '%s' using options '%s' failed.", name, options);
158 delete output;
159 return NULL;
160 }
161 return output;
162 }
163
164 size_t LogConfiguration::add_output(LogOutput* output) {
165 size_t idx = _n_outputs++;
166 _outputs = REALLOC_C_HEAP_ARRAY(LogOutput*, _outputs, _n_outputs, mtLogging);
167 _outputs[idx] = output;
168 return idx;
169 }
170
171 void LogConfiguration::delete_output(size_t idx) {
172 assert(idx > 1 && idx < _n_outputs,
173 "idx must be in range 1 < idx < _n_outputs, but idx = " SIZE_FORMAT
174 " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);
175 LogOutput* output = _outputs[idx];
176 // Swap places with the last output and shrink the array
177 _outputs[idx] = _outputs[--_n_outputs];
178 _outputs = REALLOC_C_HEAP_ARRAY(LogOutput*, _outputs, _n_outputs, mtLogging);
179 delete output;
180 }
181
182 void LogConfiguration::configure_output(size_t idx, const LogTagLevelExpression& tag_level_expression, const LogDecorators& decorators) {
183 assert(ConfigurationLock::current_thread_has_lock(), "Must hold configuration lock to call this function.");
184 assert(idx < _n_outputs, "Invalid index, idx = " SIZE_FORMAT " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);
185 LogOutput* output = _outputs[idx];
186
187 // Clear the previous config description
188 output->clear_config_string();
189
190 bool enabled = false;
191 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
192 LogLevelType level = tag_level_expression.level_for(*ts);
193
194 // Ignore tagsets that do not, and will not log on the output
195 if (!ts->has_output(output) && (level == LogLevel::NotMentioned || level == LogLevel::Off)) {
196 continue;
197 }
198
199 // Update decorators before adding/updating output level,
200 // so that the tagset will have the necessary decorators when requiring them.
201 if (level != LogLevel::Off) {
202 ts->update_decorators(decorators);
203 }
204
205 // Set the new level, if it changed
206 if (level != LogLevel::NotMentioned) {
207 ts->set_output_level(output, level);
208 }
209
210 if (level != LogLevel::Off) {
211 // Keep track of whether or not the output is ever used by some tagset
212 enabled = true;
213
214 if (level == LogLevel::NotMentioned) {
215 // Look up the previously set level for this output on this tagset
216 level = ts->level_for(output);
217 }
218
219 // Update the config description with this tagset and level
220 output->add_to_config_string(ts, level);
221 }
222 }
223
224 // It is now safe to set the new decorators for the actual output
225 output->set_decorators(decorators);
226
227 // Update the decorators on all tagsets to get rid of unused decorators
228 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
229 ts->update_decorators();
230 }
231
232 if (enabled) {
233 assert(strlen(output->config_string()) > 0,
234 "Should always have a config description if the output is enabled.");
235 } else if (idx > 1) {
236 // Output is unused and should be removed.
237 delete_output(idx);
238 } else {
239 // Output is either stdout or stderr, which means we can't remove it.
240 // Update the config description to reflect that the output is disabled.
241 output->set_config_string("all=off");
242 }
243 }
244
245 void LogConfiguration::disable_output(size_t idx) {
246 LogOutput* out = _outputs[idx];
247
248 // Remove the output from all tagsets.
249 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
250 ts->set_output_level(out, LogLevel::Off);
251 ts->update_decorators();
252 }
253
254 // Delete the output unless stdout/stderr
255 if (out != LogOutput::Stderr && out != LogOutput::Stdout) {
256 delete_output(find_output(out->name()));
257 } else {
258 out->set_config_string("all=off");
259 }
260 }
261
262 void LogConfiguration::disable_logging() {
263 ConfigurationLock cl;
264 for (size_t i = 0; i < _n_outputs; i++) {
265 disable_output(i);
266 }
267 notify_update_listeners();
268 }
269
270 void LogConfiguration::configure_stdout(LogLevelType level, bool exact_match, ...) {
271 size_t i;
272 va_list ap;
273 LogTagLevelExpression expr;
274 va_start(ap, exact_match);
275 for (i = 0; i < LogTag::MaxTags; i++) {
276 LogTagType tag = static_cast<LogTagType>(va_arg(ap, int));
277 expr.add_tag(tag);
278 if (tag == LogTag::__NO_TAG) {
279 assert(i > 0, "Must specify at least one tag!");
280 break;
281 }
282 }
283 assert(i < LogTag::MaxTags || static_cast<LogTagType>(va_arg(ap, int)) == LogTag::__NO_TAG,
284 "Too many tags specified! Can only have up to " SIZE_FORMAT " tags in a tag set.", LogTag::MaxTags);
285 va_end(ap);
286
287 if (!exact_match) {
288 expr.set_allow_other_tags();
289 }
290 expr.set_level(level);
291 expr.new_combination();
292
293 // Apply configuration to stdout (output #0), with the same decorators as before.
294 ConfigurationLock cl;
295 configure_output(0, expr, LogOutput::Stdout->decorators());
296 notify_update_listeners();
297 }
298
299 bool LogConfiguration::parse_command_line_arguments(const char* opts) {
300 char* copy = os::strdup_check_oom(opts, mtLogging);
301
302 // Split the option string to its colon separated components.
303 char* str = copy;
304 char* substrings[4] = {0};
305 for (int i = 0 ; i < 4; i++) {
306 substrings[i] = str;
307
308 // Find the next colon or quote
309 char* next = strpbrk(str, ":\"");
310 while (next != NULL && *next == '"') {
311 char* end_quote = strchr(next + 1, '"');
312 if (end_quote == NULL) {
313 log_error(logging)("Missing terminating quote in -Xlog option '%s'", str);
314 os::free(copy);
315 return false;
316 }
317 // Keep searching after the quoted substring
318 next = strpbrk(end_quote + 1, ":\"");
319 }
320
321 if (next != NULL) {
322 *next = '\0';
323 str = next + 1;
324 } else {
325 break;
326 }
327 }
328
329 // Parse and apply the separated configuration options
330 char* what = substrings[0];
331 char* output = substrings[1];
332 char* decorators = substrings[2];
333 char* output_options = substrings[3];
334 char errbuf[512];
335 stringStream ss(errbuf, sizeof(errbuf));
336 bool success = parse_log_arguments(output, what, decorators, output_options, &ss);
337 if (!success) {
338 errbuf[strlen(errbuf) - 1] = '\0'; // Strip trailing newline.
339 log_error(logging)("%s", errbuf);
340 }
341
342 os::free(copy);
343 return success;
344 }
345
346 bool LogConfiguration::parse_log_arguments(const char* outputstr,
347 const char* what,
348 const char* decoratorstr,
349 const char* output_options,
350 outputStream* errstream) {
351 if (outputstr == NULL || strlen(outputstr) == 0) {
352 outputstr = "stdout";
353 }
354
355 LogTagLevelExpression expr;
356 if (!expr.parse(what, errstream)) {
357 return false;
358 }
359
360 LogDecorators decorators;
361 if (!decorators.parse(decoratorstr, errstream)) {
362 return false;
363 }
364
365 ConfigurationLock cl;
366 size_t idx;
367 if (outputstr[0] == '#') {
368 int ret = sscanf(outputstr+1, SIZE_FORMAT, &idx);
369 if (ret != 1 || idx >= _n_outputs) {
370 errstream->print_cr("Invalid output index '%s'", outputstr);
371 return false;
372 }
373 } else {
374 idx = find_output(outputstr);
375 if (idx == SIZE_MAX) {
376 char* tmp = os::strdup_check_oom(outputstr, mtLogging);
377 LogOutput* output = new_output(tmp, output_options, errstream);
378 os::free(tmp);
379 if (output == NULL) {
380 return false;
381 }
382 idx = add_output(output);
383 } else if (output_options != NULL && strlen(output_options) > 0) {
384 errstream->print_cr("Output options for existing outputs are ignored.");
385 }
386 }
387 configure_output(idx, expr, decorators);
388 notify_update_listeners();
389 return true;
390 }
391
392 void LogConfiguration::describe_available(outputStream* out){
393 out->print("Available log levels:");
394 for (size_t i = 0; i < LogLevel::Count; i++) {
395 out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
396 }
397 out->cr();
398
399 out->print("Available log decorators:");
400 for (size_t i = 0; i < LogDecorators::Count; i++) {
401 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
402 out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
403 }
404 out->cr();
405
406 out->print("Available log tags:");
407 for (size_t i = 1; i < LogTag::Count; i++) {
408 out->print("%s %s", (i == 1 ? "" : ","), LogTag::name(static_cast<LogTagType>(i)));
409 }
410 out->cr();
411
412 LogTagSet::describe_tagsets(out);
413 }
414
415 void LogConfiguration::describe_current_configuration(outputStream* out){
416 out->print_cr("Log output configuration:");
417 for (size_t i = 0; i < _n_outputs; i++) {
418 out->print("#" SIZE_FORMAT ": ", i);
419 _outputs[i]->describe(out);
420 out->cr();
421 }
422 }
423
424 void LogConfiguration::describe(outputStream* out) {
425 describe_available(out);
426 ConfigurationLock cl;
427 describe_current_configuration(out);
428 }
429
430 void LogConfiguration::print_command_line_help(FILE* out) {
431 jio_fprintf(out, "-Xlog Usage: -Xlog[:[what][:[output][:[decorators][:output-options]]]]\n"
432 "\t where 'what' is a combination of tags and levels on the form tag1[+tag2...][*][=level][,...]\n"
433 "\t Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.\n\n");
434
435 jio_fprintf(out, "Available log levels:\n");
436 for (size_t i = 0; i < LogLevel::Count; i++) {
437 jio_fprintf(out, "%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
438 }
439
440 jio_fprintf(out, "\n\nAvailable log decorators: \n");
441 for (size_t i = 0; i < LogDecorators::Count; i++) {
442 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
443 jio_fprintf(out, "%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
444 }
445 jio_fprintf(out, "\n Decorators can also be specified as 'none' for no decoration.\n\n");
446
447 jio_fprintf(out, "Available log tags:\n");
448 for (size_t i = 1; i < LogTag::Count; i++) {
449 jio_fprintf(out, "%s %s", (i == 1 ? "" : ","), LogTag::name(static_cast<LogTagType>(i)));
450 }
451 jio_fprintf(out, "\n Specifying 'all' instead of a tag combination matches all tag combinations.\n\n");
452
453 fileStream stream(out, false);
454 LogTagSet::describe_tagsets(&stream);
455
456 jio_fprintf(out, "\nAvailable log outputs:\n"
457 " stdout, stderr, file=<filename>\n"
458 " Specifying %%p and/or %%t in the filename will expand to the JVM's PID and startup timestamp, respectively.\n\n"
459
460 "Some examples:\n"
461 " -Xlog\n"
462 "\t Log all messages using 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.\n"
463 "\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).\n\n"
464
465 " -Xlog:gc\n"
466 "\t Log messages tagged with 'gc' tag using 'info' level to stdout, with default decorations.\n\n"
467
468 " -Xlog:gc=debug:file=gc.txt:none\n"
469 "\t Log messages tagged with 'gc' tag using 'debug' level to file 'gc.txt' with no decorations.\n\n"
470
471 " -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1m\n"
472 "\t Log messages tagged with 'gc' tag using 'trace' level to a rotating fileset of 5 files of size 1MB,\n"
473 "\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.\n\n"
474
475 " -Xlog:gc::uptime,tid\n"
476 "\t Log messages tagged with 'gc' tag using 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.\n\n"
477
478 " -Xlog:gc*=info,safepoint*=off\n"
479 "\t Log messages tagged with at least 'gc' using 'info' level, but turn off logging of messages tagged with 'safepoint'.\n"
480 "\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)\n\n"
481
482 " -Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt\n"
483 "\t Turn off all logging, including warnings and errors,\n"
484 "\t and then enable messages tagged with 'safepoint' using 'trace' level to file 'safepointtrace.txt'.\n");
485 }
486
487 void LogConfiguration::rotate_all_outputs() {
488 // Start from index 2 since neither stdout nor stderr can be rotated.
489 for (size_t idx = 2; idx < _n_outputs; idx++) {
490 _outputs[idx]->force_rotate();
491 }
492 }
493
494 void LogConfiguration::register_update_listener(UpdateListenerFunction cb) {
495 assert(cb != NULL, "Should not register NULL as listener");
496 ConfigurationLock cl;
497 size_t idx = _n_listener_callbacks++;
498 _listener_callbacks = REALLOC_C_HEAP_ARRAY(UpdateListenerFunction,
499 _listener_callbacks,
500 _n_listener_callbacks,
501 mtLogging);
502 _listener_callbacks[idx] = cb;
503 }
504
505 void LogConfiguration::notify_update_listeners() {
506 assert(ConfigurationLock::current_thread_has_lock(), "notify_update_listeners must be called in ConfigurationLock scope (lock held)");
507 for (size_t i = 0; i < _n_listener_callbacks; i++) {
508 _listener_callbacks[i]();
509 }
510 }