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 1 commit
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 @@ public static float clampDuration(float d) {
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 @@ public static CaseResult parse(SuiteResult parent, final XMLStreamReader reader,
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);
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,18 +338,16 @@ public static void parseProperties(Map<String, String> r, final XMLStreamReader
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()) {
Expand All @@ -374,9 +369,7 @@ public static void parseProperty(Map<String, String> r, final XMLStreamReader re
}
break;
default:
if (LOGGER.isLoggable(Level.FINEST)) {
LOGGER.finest("CaseResult.parseProperty encountered an unknown field: " + elementName);
}
LOGGER.finest(() -> "Unknown field in " + context + ": " + elementName);
}
}
}
Expand Down
37 changes: 13 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 @@ public SuiteResult(SuiteResult src) {
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 @@ public static SuiteResult parse(final XMLStreamReader reader, String ver) throws
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 @@ public static SuiteResult parse(final XMLStreamReader reader, String ver) throws
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,19 +211,17 @@ public static SuiteResult parse(final XMLStreamReader reader, String ver) throws
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();
Expand All @@ -238,16 +235,13 @@ public static void parseEnclosingBlocks(SuiteResult r, final XMLStreamReader rea
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();
Expand All @@ -261,16 +255,13 @@ public static void parseEnclosingBlockNames(SuiteResult r, final XMLStreamReader
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);
}
}
}
}

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 +271,10 @@ public static void parseCases(SuiteResult r, final XMLStreamReader reader, Strin
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);
}
}
}
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 TestResult(TestResult src) {
}
}

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 @@ private void parseXmlResult(final XMLStreamReader reader) throws XMLStreamExcept
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 @@ private void parseXmlResult(final XMLStreamReader reader) throws XMLStreamExcept
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);
}
}
}
}

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 @@ private void parseXmlSuites(final XMLStreamReader reader, String ver) throws XML
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);
}
}
}
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 @@ public synchronized TestResult getResult() {
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)) {
logger.warning(() -> "Took " + TimeUnit.NANOSECONDS.toMillis(d) + " ms to load test results for " + run);
}
return r;
}
Expand Down