Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve recently added log messages by adding context to indicate which build is relevant #640

Merged
merged 2 commits into from
Aug 22, 2024
Merged

Improve recently added log messages by adding context to indicate which build is relevant #640

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
b5fe744
Improve recently added log messages by adding context to indicate whi…
dwnusbaum Aug 22, 2024
3c7bc62
Spotless
dwnusbaum Aug 22, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 8 additions & 15 deletions src/main/java/hudson/tasks/junit/CaseResult.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,6 @@
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.logging.Level;
import java.util.logging.Logger;
import javax.xml.stream.XMLStreamException;
import javax.xml.stream.XMLStreamReader;
Expand Down Expand Up @@ -269,7 +268,7 @@
return Math.min(365.0f * 24 * 60 * 60, Math.max(0.0f, d));
}

public static CaseResult parse(SuiteResult parent, final XMLStreamReader reader, String ver)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As far as I know nothing should be using these new methods from #625, so I made them all package-private, but if that is not true, let me know and I will revert that part of the change.

static CaseResult parse(SuiteResult parent, final XMLStreamReader reader, String context, String ver)
throws XMLStreamException {
CaseResult r = new CaseResult(parent, null, null, null);
while (reader.hasNext()) {
Expand Down Expand Up @@ -318,19 +317,17 @@
break;
case "properties":
r.properties = new HashMap<>();
parseProperties(r.properties, reader, ver);
parseProperties(r.properties, reader, context, ver);
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("CaseResult.parse encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);

Check warning on line 323 in src/main/java/hudson/tasks/junit/CaseResult.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered line 

Line 323 is not covered by tests
Copy link
Member Author

@dwnusbaum dwnusbaum Aug 22, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I also checked whether XMLReader.getLocation included a file name to avoid having to pass context everywhere, but getPublicID and getSystemID just return null (and IDK what they would even return if they weren't null). We could add line and column numbers to give even more context, but I don't really think it would be helpful in practice.

}
}
}
return r;
}

public static void parseProperties(Map<String, String> r, final XMLStreamReader reader, String ver)
static void parseProperties(Map<String, String> r, final XMLStreamReader reader, String context, String ver)
throws XMLStreamException {
while (reader.hasNext()) {
final int event = reader.next();
Expand All @@ -341,42 +338,38 @@
final String elementName = reader.getLocalName();
switch (elementName) {
case "entry":
parseProperty(r, reader, ver);
parseProperty(r, reader, context, ver);
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("CaseResult.parseProperties encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);
}
}
}
}

public static void parseProperty(Map<String, String> r, final XMLStreamReader reader, String ver)
static void parseProperty(Map<String, String> r, final XMLStreamReader reader, String context, String ver)
throws XMLStreamException {
String name = null, value = null;
while (reader.hasNext()) {
final int event = reader.next();
if (event == XMLStreamReader.END_ELEMENT && reader.getLocalName().equals("entry")) {
if (name != null && value != null) {
r.put(name, value);
}
return;
}
if (event == XMLStreamReader.START_ELEMENT) {
final String elementName = reader.getLocalName();
switch (elementName) {
case "string":
if (name == null) {
name = reader.getElementText();
} else {
value = reader.getElementText();
}
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("CaseResult.parseProperty encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);

Check warning on line 372 in src/main/java/hudson/tasks/junit/CaseResult.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered lines 

Lines 344-372 are not covered by tests
}
}
}
Expand Down
38 changes: 14 additions & 24 deletions src/main/java/hudson/tasks/junit/SuiteResult.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,6 @@
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
Expand Down Expand Up @@ -160,7 +159,7 @@
this.properties.putAll(src.properties);
}

public static SuiteResult parse(final XMLStreamReader reader, String ver) throws XMLStreamException {
static SuiteResult parse(final XMLStreamReader reader, String context, String ver) throws XMLStreamException {
SuiteResult r = new SuiteResult("", null, null, null);
while (reader.hasNext()) {
final int event = reader.next();
Expand All @@ -171,7 +170,7 @@
final String elementName = reader.getLocalName();
switch (elementName) {
case "cases":
parseCases(r, reader, ver);
parseCases(r, reader, context, ver);
break;
case "file":
r.file = reader.getElementText();
Expand Down Expand Up @@ -199,10 +198,10 @@
r.nodeId = reader.getElementText();
break;
case "enclosingBlocks":
parseEnclosingBlocks(r, reader, ver);
parseEnclosingBlocks(r, reader, context, ver);
break;
case "enclosingBlockNames":
parseEnclosingBlockNames(r, reader, ver);
parseEnclosingBlockNames(r, reader, context, ver);
break;
case "stdout":
r.stdout = reader.getElementText();
Expand All @@ -212,65 +211,58 @@
break;
case "properties":
r.properties = new HashMap<>();
CaseResult.parseProperties(r.properties, reader, ver);
CaseResult.parseProperties(r.properties, reader, context, ver);
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("SuiteResult.parse encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);
}
}
}
return r;
}

public static void parseEnclosingBlocks(SuiteResult r, final XMLStreamReader reader, String ver)
static void parseEnclosingBlocks(SuiteResult r, final XMLStreamReader reader, String context, String ver)
throws XMLStreamException {
while (reader.hasNext()) {
final int event = reader.next();
if (event == XMLStreamReader.END_ELEMENT && reader.getLocalName().equals("enclosingBlocks")) {
return;
}
if (event == XMLStreamReader.START_ELEMENT) {
final String elementName = reader.getLocalName();
switch (elementName) {
case "string":
r.enclosingBlocks.add(reader.getElementText());
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest(
"SuiteResult.parseEnclosingBlocks encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);
}
}
}
}

public static void parseEnclosingBlockNames(SuiteResult r, final XMLStreamReader reader, String ver)
static void parseEnclosingBlockNames(SuiteResult r, final XMLStreamReader reader, String context, String ver)
throws XMLStreamException {
while (reader.hasNext()) {
final int event = reader.next();
if (event == XMLStreamReader.END_ELEMENT && reader.getLocalName().equals("enclosingBlockNames")) {
return;
}
if (event == XMLStreamReader.START_ELEMENT) {
final String elementName = reader.getLocalName();
switch (elementName) {
case "string":
r.enclosingBlockNames.add(reader.getElementText());
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("SuiteResult.parseEnclosingBlockNames encountered an unknown field: "
+ elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);

Check warning on line 258 in src/main/java/hudson/tasks/junit/SuiteResult.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered lines 

Lines 217-258 are not covered by tests
}
}
}
}

public static void parseCases(SuiteResult r, final XMLStreamReader reader, String ver) throws XMLStreamException {
static void parseCases(SuiteResult r, final XMLStreamReader reader, String context, String ver)
throws XMLStreamException {
while (reader.hasNext()) {
final int event = reader.next();
if (event == XMLStreamReader.END_ELEMENT && reader.getLocalName().equals("cases")) {
Expand All @@ -280,12 +272,10 @@
final String elementName = reader.getLocalName();
switch (elementName) {
case "case":
r.cases.add(CaseResult.parse(r, reader, ver));
r.cases.add(CaseResult.parse(r, reader, context, ver));
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("SuiteResult.parseCases encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);

Check warning on line 278 in src/main/java/hudson/tasks/junit/SuiteResult.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered line 

Line 278 is not covered by tests
}
}
}
Expand Down
22 changes: 9 additions & 13 deletions src/main/java/hudson/tasks/junit/TestResult.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -312,25 +312,25 @@
}
}

public static XMLInputFactory getXmlFactory() {
static XMLInputFactory getXmlFactory() {
return xmlFactory;
}

public void parse(XmlFile f) throws XMLStreamException, IOException {
void parse(XmlFile f) throws XMLStreamException, IOException {
try (Reader r = f.readRaw()) {
final XMLStreamReader reader = getXmlFactory().createXMLStreamReader(r);
while (reader.hasNext()) {
final int event = reader.next();
if (event == XMLStreamReader.START_ELEMENT
&& reader.getName().getLocalPart().equals("result")) {
parseXmlResult(reader);
parseXmlResult(reader, f.getFile().toString());
}
}
r.close();
}
}

private void parseXmlResult(final XMLStreamReader reader) throws XMLStreamException {
private void parseXmlResult(final XMLStreamReader reader, String context) throws XMLStreamException {
String ver = reader.getAttributeValue(null, "plugin");
while (reader.hasNext()) {
int event = reader.next();
Expand All @@ -341,7 +341,7 @@
final String elementName = reader.getLocalName();
switch (elementName) {
case "suites":
parseXmlSuites(reader, ver);
parseXmlSuites(reader, context, ver);
break;
case "duration":
duration = CaseResult.clampDuration(new TimeToFloat(reader.getElementText()).parse());
Expand All @@ -366,15 +366,13 @@
startTime = Long.parseLong(reader.getElementText());
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("TestResult.parseXmlResult encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);

Check warning on line 369 in src/main/java/hudson/tasks/junit/TestResult.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered line 

Line 369 is not covered by tests
}
}
}
}

private void parseXmlSuites(final XMLStreamReader reader, String ver) throws XMLStreamException {
private void parseXmlSuites(final XMLStreamReader reader, String context, String ver) throws XMLStreamException {
while (reader.hasNext()) {
final int event = reader.next();
if (event == XMLStreamReader.END_ELEMENT && reader.getLocalName().equals("suites")) {
Expand All @@ -384,12 +382,10 @@
final String elementName = reader.getLocalName();
switch (elementName) {
case "suite":
suites.add(SuiteResult.parse(reader, ver));
suites.add(SuiteResult.parse(reader, context, ver));
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("TestResult.parseXmlSuites encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);

Check warning on line 388 in src/main/java/hudson/tasks/junit/TestResult.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered line 

Line 388 is not covered by tests
}
}
}
Expand Down
6 changes: 3 additions & 3 deletions src/main/java/hudson/tasks/junit/TestResultAction.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,6 +51,7 @@
import java.util.Collections;
import java.util.List;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.TimeUnit;
import java.util.logging.Level;
import java.util.logging.Logger;
import jenkins.tasks.SimpleBuildStep;
Expand All @@ -69,7 +70,6 @@
@SuppressFBWarnings(value = "UG_SYNC_SET_UNSYNC_GET", justification = "False positive")
public class TestResultAction extends AbstractTestResultAction<TestResultAction>
implements StaplerProxy, SimpleBuildStep.LastBuildAction {
private static final Logger LOGGER = Logger.getLogger(TestResultAction.class.getName());
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was added in #625, but we already had a logger at the bottom of the file, it was just named lowercase logger.

private transient WeakReference<TestResult> result;

/** null only if there is a {@link JunitTestResultStorage} */
Expand Down Expand Up @@ -179,8 +179,8 @@
skipCount = r.getSkipCount();
}
long d = System.nanoTime() - started;
if (d > 500000000L && LOGGER.isLoggable(Level.WARNING)) {
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

500000000 is 5e8, or 0.5 seconds. I adjusted the code to use TimeUnit to make it clearer, but I could switch it to 500 * 1000 * 1000 or whatever you think is clearest.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(I also wonder if this threshold is too low for WARNING and it should be increased to 1-2 seconds, maybe logging at FINE for stuff between 0.5-1 seconds)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the idea of setting the threshold higher for logging at less than 2 seconds, but approve this pull request with or without that change.

LOGGER.warning("TestResultAction.load took " + d / 1000000L + " ms.");
if (d > TimeUnit.MILLISECONDS.toNanos(500)) {

Check warning on line 182 in src/main/java/hudson/tasks/junit/TestResultAction.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Partially covered line 

Line 182 is only partially covered, one branch is missing
logger.warning(() -> "Took " + TimeUnit.NANOSECONDS.toMillis(d) + " ms to load test results for " + run);

Check warning on line 183 in src/main/java/hudson/tasks/junit/TestResultAction.java

View check run for this annotation

ci.jenkins.io / Code Coverage

Not covered line 

Line 183 is not covered by tests
}
return r;
}
Expand Down