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