8190346: improve unified JVM logging help message and warnings

Reviewed-by: lfoltan, rehn, hseigel
This commit is contained in:
Marcus Larsson 2018-02-28 09:30:06 +01:00
parent 3b8d9ef239
commit cb275ca384
13 changed files with 267 additions and 86 deletions

View File

@ -83,14 +83,15 @@ void LogConfiguration::post_initialize() {
if (log.is_info()) {
log.info("Log configuration fully initialized.");
log_develop_info(logging)("Develop logging is available.");
if (log.is_debug()) {
LogStream debug_stream(log.debug());
describe(&debug_stream);
if (log.is_trace()) {
LogStream trace_stream(log.trace());
LogTagSet::list_all_tagsets(&trace_stream);
}
}
LogStream info_stream(log.info());
describe_available(&info_stream);
LogStream debug_stream(log.debug());
LogTagSet::list_all_tagsets(&debug_stream);
ConfigurationLock cl;
describe_current_configuration(&info_stream);
}
}
@ -364,14 +365,24 @@ bool LogConfiguration::parse_command_line_arguments(const char* opts) {
bool success = parse_log_arguments(output, what, decorators, output_options, &ss);
if (ss.size() > 0) {
errbuf[strlen(errbuf) - 1] = '\0'; // Strip trailing newline
// If it failed, log the error. If it didn't fail, but something was written
// to the stream, log it as a warning.
if (!success) {
log_error(logging)("%s", ss.base());
} else {
log_warning(logging)("%s", ss.base());
}
LogLevelType level = success ? LogLevel::Warning : LogLevel::Error;
Log(logging) log;
char* start = errbuf;
char* end = strchr(start, '\n');
assert(end != NULL, "line must end with newline '%s'", start);
do {
assert(start < errbuf + sizeof(errbuf) &&
end < errbuf + sizeof(errbuf),
"buffer overflow");
*end = '\0';
log.write(level, "%s", start);
start = end + 1;
end = strchr(start, '\n');
assert(end != NULL || *start == '\0', "line must end with newline '%s'", start);
} while (end != NULL);
}
os::free(copy);
@ -459,7 +470,7 @@ void LogConfiguration::describe_available(outputStream* out){
void LogConfiguration::describe_current_configuration(outputStream* out){
out->print_cr("Log output configuration:");
for (size_t i = 0; i < _n_outputs; i++) {
out->print("#" SIZE_FORMAT ": ", i);
out->print(" #" SIZE_FORMAT ": ", i);
_outputs[i]->describe(out);
out->cr();
}
@ -471,68 +482,89 @@ void LogConfiguration::describe(outputStream* out) {
describe_current_configuration(out);
}
void LogConfiguration::print_command_line_help(FILE* out) {
jio_fprintf(out, "-Xlog Usage: -Xlog[:[what][:[output][:[decorators][:output-options]]]]\n"
"\t where 'what' is a combination of tags and levels of the form tag1[+tag2...][*][=level][,...]\n"
"\t Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.\n\n");
void LogConfiguration::print_command_line_help(outputStream* out) {
out->print_cr("-Xlog Usage: -Xlog[:[selections][:[output][:[decorators][:output-options]]]]");
out->print_cr("\t where 'selections' are combinations of tags and levels of the form tag1[+tag2...][*][=level][,...]");
out->print_cr("\t NOTE: Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.");
out->cr();
jio_fprintf(out, "Available log levels:\n");
out->print_cr("Available log levels:");
for (size_t i = 0; i < LogLevel::Count; i++) {
jio_fprintf(out, "%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
}
out->cr();
out->cr();
jio_fprintf(out, "\n\nAvailable log decorators: \n");
out->print_cr("Available log decorators: ");
for (size_t i = 0; i < LogDecorators::Count; i++) {
LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
jio_fprintf(out, "%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
}
jio_fprintf(out, "\n Decorators can also be specified as 'none' for no decoration.\n\n");
out->cr();
out->print_cr(" Decorators can also be specified as 'none' for no decoration.");
out->cr();
fileStream stream(out, false);
stream.print_cr("Available log tags:");
LogTag::list_tags(&stream);
stream.print_cr(" Specifying 'all' instead of a tag combination matches all tag combinations.");
stream.cr();
out->print_cr("Available log tags:");
LogTag::list_tags(out);
out->print_cr(" Specifying 'all' instead of a tag combination matches all tag combinations.");
out->cr();
LogTagSet::describe_tagsets(&stream);
LogTagSet::describe_tagsets(out);
jio_fprintf(out, "\nAvailable log outputs:\n"
" stdout, stderr, file=<filename>\n"
" Specifying %%p and/or %%t in the filename will expand to the JVM's PID and startup timestamp, respectively.\n\n"
out->print_cr("\nAvailable log outputs:");
out->print_cr(" stdout/stderr");
out->print_cr(" file=<filename>");
out->print_cr(" If the filename contains %%p and/or %%t, they will expand to the JVM's PID and startup timestamp, respectively.");
out->print_cr(" Additional output-options for file outputs:");
out->print_cr(" filesize=.. - Target byte size for log rotation (supports K/M/G suffix)."
" If set to 0, log rotation will not trigger automatically,"
" but can be performed manually (see the VM.log DCMD).");
out->print_cr(" filecount=.. - Number of files to keep in rotation (not counting the active file)."
" If set to 0, log rotation is disabled."
" This will cause existing log files to be overwritten.");
out->cr();
"Some examples:\n"
" -Xlog\n"
"\t Log all messages using 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.\n"
"\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).\n\n"
out->print_cr("Some examples:");
out->print_cr(" -Xlog");
out->print_cr("\t Log all messages using 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.");
out->print_cr("\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).");
out->cr();
" -Xlog:gc\n"
"\t Log messages tagged with 'gc' tag using 'info' level to stdout, with default decorations.\n\n"
out->print_cr(" -Xlog:gc");
out->print_cr("\t Log messages tagged with 'gc' tag using 'info' level to stdout, with default decorations.");
out->cr();
" -Xlog:gc,safepoint\n"
"\t Log messages tagged either with 'gc' or 'safepoint' tags, both using 'info' level, to stdout, with default decorations.\n"
"\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)\n\n"
out->print_cr(" -Xlog:gc,safepoint");
out->print_cr("\t Log messages tagged either with 'gc' or 'safepoint' tags, both using 'info' level, to stdout, with default decorations.");
out->print_cr("\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)");
out->cr();
" -Xlog:gc+ref=debug\n"
"\t Log messages tagged with both 'gc' and 'ref' tags, using 'debug' level, to stdout, with default decorations.\n"
"\t (Messages tagged only with one of the two tags will not be logged.)\n\n"
out->print_cr(" -Xlog:gc+ref=debug");
out->print_cr("\t Log messages tagged with both 'gc' and 'ref' tags, using 'debug' level, to stdout, with default decorations.");
out->print_cr("\t (Messages tagged only with one of the two tags will not be logged.)");
out->cr();
" -Xlog:gc=debug:file=gc.txt:none\n"
"\t Log messages tagged with 'gc' tag using 'debug' level to file 'gc.txt' with no decorations.\n\n"
out->print_cr(" -Xlog:gc=debug:file=gc.txt:none");
out->print_cr("\t Log messages tagged with 'gc' tag using 'debug' level to file 'gc.txt' with no decorations.");
out->cr();
" -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1m\n"
"\t Log messages tagged with 'gc' tag using 'trace' level to a rotating fileset of 5 files of size 1MB,\n"
"\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.\n\n"
out->print_cr(" -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1m");
out->print_cr("\t Log messages tagged with 'gc' tag using 'trace' level to a rotating fileset of 5 files of size 1MB,");
out->print_cr("\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.");
out->cr();
" -Xlog:gc::uptime,tid\n"
"\t Log messages tagged with 'gc' tag using 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.\n\n"
out->print_cr(" -Xlog:gc::uptime,tid");
out->print_cr("\t Log messages tagged with 'gc' tag using 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.");
out->cr();
" -Xlog:gc*=info,safepoint*=off\n"
"\t Log messages tagged with at least 'gc' using 'info' level, but turn off logging of messages tagged with 'safepoint'.\n"
"\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)\n\n"
out->print_cr(" -Xlog:gc*=info,safepoint*=off");
out->print_cr("\t Log messages tagged with at least 'gc' using 'info' level, but turn off logging of messages tagged with 'safepoint'.");
out->print_cr("\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)");
out->cr();
" -Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt\n"
"\t Turn off all logging, including warnings and errors,\n"
"\t and then enable messages tagged with 'safepoint' using 'trace' level to file 'safepointtrace.txt'.\n");
out->print_cr(" -Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt");
out->print_cr("\t Turn off all logging, including warnings and errors,");
out->print_cr("\t and then enable messages tagged with 'safepoint' using 'trace' level to file 'safepointtrace.txt'.");
}
void LogConfiguration::rotate_all_outputs() {

View File

@ -119,7 +119,7 @@ class LogConfiguration : public AllStatic {
static void describe(outputStream* out);
// Prints usage help for command line log configuration.
static void print_command_line_help(FILE* out);
static void print_command_line_help(outputStream* out);
// Rotates all LogOutput
static void rotate_all_outputs();

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -169,6 +169,7 @@ bool LogFileOutput::parse_options(const char* options, outputStream* errstream)
char* equals_pos = strchr(pos, '=');
if (equals_pos == NULL) {
errstream->print_cr("Invalid option '%s' for log file output.", pos);
success = false;
break;
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -85,7 +85,7 @@ class LogFileOutput : public LogFileStreamOutput {
virtual int write(const LogDecorations& decorations, const char* msg);
virtual int write(LogMessageBuffer::Iterator msg_iterator);
virtual void force_rotate();
virtual void describe(outputStream *out);
virtual void describe(outputStream* out);
virtual const char* name() const {
return _name;

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -84,15 +84,20 @@ void LogOutput::add_to_config_string(const LogTagSet* ts, LogLevelType level) {
void LogOutput::describe(outputStream *out) {
out->print("%s ", name());
out->print_raw(config_string());
out->print(" ");
char delimiter[2] = {0};
out->print_raw(config_string()); // raw printed because length might exceed O_BUFLEN
bool has_decorator = false;
char delimiter = ' ';
for (size_t d = 0; d < LogDecorators::Count; d++) {
LogDecorators::Decorator decorator = static_cast<LogDecorators::Decorator>(d);
if (decorators().is_decorator(decorator)) {
out->print("%s%s", delimiter, LogDecorators::name(decorator));
*delimiter = ',';
has_decorator = true;
out->print("%c%s", delimiter, LogDecorators::name(decorator));
delimiter = ',';
}
}
if (!has_decorator) {
out->print(" none");
}
}

View File

@ -23,11 +23,13 @@
*/
#include "precompiled.hpp"
#include "utilities/ostream.hpp"
#include "logging/log.hpp"
#include "logging/logSelection.hpp"
#include "logging/logTagSet.hpp"
#include "runtime/os.inline.hpp"
#include "utilities/globalDefinitions.hpp"
#include "utilities/ostream.hpp"
#include "utilities/quickSort.hpp"
const LogSelection LogSelection::Invalid;
@ -211,3 +213,120 @@ int LogSelection::describe(char* buf, size_t bufsize) const {
tot_written += written;
return tot_written;
}
double LogSelection::similarity(const LogSelection& other) const {
// Compute Soerensen-Dice coefficient as the similarity measure
size_t intersecting = 0;
for (size_t i = 0; i < _ntags; i++) {
for (size_t j = 0; j < other._ntags; j++) {
if (_tags[i] == other._tags[j]) {
intersecting++;
break;
}
}
}
return 2.0 * intersecting / (_ntags + other._ntags);
}
// Comparator used for sorting LogSelections based on their similarity to a specific LogSelection.
// A negative return value means that 'a' is more similar to 'ref' than 'b' is, while a positive
// return value means that 'b' is more similar.
// For the sake of giving short and effective suggestions, when two selections have an equal
// similarity score, the selection with the fewer tags (selecting the most tag sets) is considered
// more similar.
class SimilarityComparator {
const LogSelection& _ref;
public:
SimilarityComparator(const LogSelection& ref) : _ref(ref) {
}
int operator()(const LogSelection& a, const LogSelection& b) const {
const double epsilon = 1.0e-6;
// Sort by similarity (descending)
double s = _ref.similarity(b) - _ref.similarity(a);
if (fabs(s) > epsilon) {
return s < 0 ? -1 : 1;
}
// Then by number of tags (ascending)
int t = static_cast<int>(a.ntags() - (int)b.ntags());
if (t != 0) {
return t;
}
// Lastly by tag sets selected (descending)
return static_cast<int>(b.tag_sets_selected() - a.tag_sets_selected());
}
};
static const size_t suggestion_cap = 5;
static const double similarity_requirement = 0.3;
void LogSelection::suggest_similar_matching(outputStream* out) const {
LogSelection suggestions[suggestion_cap];
uint nsuggestions = 0;
// See if simply adding a wildcard would make the selection match
if (!_wildcard) {
LogSelection sel(_tags, true, _level);
if (sel.tag_sets_selected() > 0) {
suggestions[nsuggestions++] = sel;
}
}
// Check for matching tag sets with a single tag mismatching (a tag too many or short a tag)
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
LogTagType tags[LogTag::MaxTags] = { LogTag::__NO_TAG };
for (size_t i = 0; i < ts->ntags(); i++) {
tags[i] = ts->tag(i);
}
// Suggest wildcard selection unless the wildcard doesn't match anything extra
LogSelection sel(tags, true, _level);
if (sel.tag_sets_selected() == 1) {
sel = LogSelection(tags, false, _level);
}
double score = similarity(sel);
// Ignore suggestions with too low similarity
if (score < similarity_requirement) {
continue;
}
// Cap not reached, simply add the new suggestion and continue searching
if (nsuggestions < suggestion_cap) {
suggestions[nsuggestions++] = sel;
continue;
}
// Find the least matching suggestion already found, and if the new suggestion is a better match, replace it
double min = 1.0;
size_t pos = -1;
for (size_t i = 0; i < nsuggestions; i++) {
double score = similarity(suggestions[i]);
if (score < min) {
min = score;
pos = i;
}
}
if (score > min) {
suggestions[pos] = sel;
}
}
if (nsuggestions == 0) {
// Found no similar enough selections to suggest.
return;
}
// Sort found suggestions to suggest the best one first
SimilarityComparator sc(*this);
QuickSort::sort(suggestions, nsuggestions, sc, false);
out->print("Did you mean any of the following?");
for (size_t i = 0; i < nsuggestions; i++) {
char buf[128];
suggestions[i].describe_tags(buf, sizeof(buf));
out->print(" %s", buf);
}
}

View File

@ -62,6 +62,12 @@ class LogSelection : public StackObj {
int describe_tags(char* buf, size_t bufsize) const;
int describe(char* buf, size_t bufsize) const;
// List similar selections that matches existing tag sets on the given outputstream
void suggest_similar_matching(outputStream* out) const;
// Compute a similarity measure in the range [0, 1], where higher means more similar
double similarity(const LogSelection& other) const;
};
#endif // SHARE_VM_LOGGING_LOGSELECTION_HPP

View File

@ -40,19 +40,17 @@ bool LogSelectionList::verify_selections(outputStream* out) const {
return false;
}
if (valid) {
out->print("No tag set matches selection(s):");
}
out->print("No tag set matches selection:");
valid = false;
char buf[256];
_selections[i].describe_tags(buf, sizeof(buf));
out->print(" %s", buf);
out->print(" %s. ", buf);
_selections[i].suggest_similar_matching(out);
out->cr();
}
}
if (!valid && out != NULL) {
out->cr();
}
return valid;
}

View File

@ -141,7 +141,7 @@ void LogTagSet::vwrite(LogLevelType level, const char* fmt, va_list args) {
static const size_t TagSetBufferSize = 128;
void LogTagSet::describe_tagsets(outputStream* out) {
out->print_cr("Described tag combinations:");
out->print_cr("Described tag sets:");
for (const LogTagSetDescription* d = tagset_descriptions; d->tagset != NULL; d++) {
char buf[TagSetBufferSize];
d->tagset->label(buf, sizeof(buf), "+");
@ -169,7 +169,7 @@ void LogTagSet::list_all_tagsets(outputStream* out) {
qsort(tagset_labels, _ntagsets, sizeof(*tagset_labels), qsort_strcmp);
// Print and then free the labels
out->print("All available tag sets: ");
out->print("Available tag sets: ");
for (idx = 0; idx < _ntagsets; idx++) {
out->print("%s%s", (idx == 0 ? "" : ", "), tagset_labels[idx]);
os::free(tagset_labels[idx]);

View File

@ -3096,7 +3096,8 @@ jint Arguments::parse_each_vm_init_arg(const JavaVMInitArgs* args, bool* patch_m
} else if (match_option(option, "-Xlog", &tail)) {
bool ret = false;
if (strcmp(tail, ":help") == 0) {
LogConfiguration::print_command_line_help(defaultStream::output_stream());
fileStream stream(defaultStream::output_stream());
LogConfiguration::print_command_line_help(&stream);
vm_exit(0);
} else if (strcmp(tail, ":disable") == 0) {
LogConfiguration::disable_logging();
@ -3109,7 +3110,7 @@ jint Arguments::parse_each_vm_init_arg(const JavaVMInitArgs* args, bool* patch_m
}
if (ret == false) {
jio_fprintf(defaultStream::error_stream(),
"Invalid -Xlog option '-Xlog%s'\n",
"Invalid -Xlog option '-Xlog%s', see error log for details.\n",
tail);
return JNI_EINVAL;
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2016, 2017, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2016, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -225,7 +225,7 @@ TEST_VM_F(LogConfigurationTest, reconfigure_decorators) {
// Now reconfigure logging on stderr with no decorators
set_log_config("stderr", "all=off", "none");
EXPECT_TRUE(is_described("#1: stderr all=off \n")) << "Expecting no decorators";
EXPECT_TRUE(is_described("#1: stderr all=off none\n")) << "Expecting no decorators";
}
// Test that invalid options cause configuration errors
@ -383,7 +383,7 @@ TEST_VM_F(LogConfigurationTest, parse_invalid_tagset) {
bool success = LogConfiguration::parse_log_arguments("stdout", invalid_tagset, NULL, NULL, &ss);
const char* msg = ss.as_string();
EXPECT_TRUE(success) << "Should only cause a warning, not an error";
EXPECT_TRUE(string_contains_substring(msg, "No tag set matches selection(s):"));
EXPECT_TRUE(string_contains_substring(msg, "No tag set matches selection:"));
EXPECT_TRUE(string_contains_substring(msg, invalid_tagset));
}
@ -413,3 +413,21 @@ TEST_VM_F(LogConfigurationTest, output_name_normalization) {
ASSERT_NE(-1, ret);
delete_file(buf);
}
TEST_VM_F(LogConfigurationTest, suggest_similar_selection) {
static const char* nonexisting_tagset = "logging+start+exit+safepoint+gc";
ResourceMark rm;
stringStream ss;
LogConfiguration::parse_log_arguments("stdout", nonexisting_tagset, NULL, NULL, &ss);
const char* suggestion = ss.as_string();
SCOPED_TRACE(suggestion);
EXPECT_TRUE(string_contains_substring(ss.as_string(), "Did you mean any of the following?"));
EXPECT_TRUE(string_contains_substring(suggestion, "logging") ||
string_contains_substring(suggestion, "start") ||
string_contains_substring(suggestion, "exit") ||
string_contains_substring(suggestion, "safepoint") ||
string_contains_substring(suggestion, "gc")) <<
"suggestion must contain AT LEAST one of the tags in user supplied selection";
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -51,7 +51,8 @@ TEST_VM(LogTagSetDescriptions, command_line_help) {
const char* filename = "logtagset_descriptions";
FILE* fp = fopen(filename, "w+");
ASSERT_NE((void*)NULL, fp);
LogConfiguration::print_command_line_help(fp);
fileStream stream(fp);
LogConfiguration::print_command_line_help(&stream);
fclose(fp);
for (LogTagSetDescription* d = tagset_descriptions; d->tagset != NULL; d++) {

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2015, 2016, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -43,7 +43,7 @@ public class TestMultipleXlogArgs {
"-version");
OutputAnalyzer output = new OutputAnalyzer(pb.start());
// -Xlog:logging=trace means that the log configuration will be printed.
String stdoutConfigLine = "\\[logging *\\] #0: stdout .*";
String stdoutConfigLine = "\\[logging *\\] #0: stdout .*";
// Ensure logging=trace has overwritten logging=debug
output.shouldMatch(stdoutConfigLine + "logging=trace").shouldNotMatch(stdoutConfigLine + "logging=debug");
// Make sure safepoint=info is printed exactly once even though we're setting it twice