Set up file logging when shutting down the Jenkins test instance. #657

Vlatombe · 2023-09-21T15:14:03Z

Matching change to jenkinsci/jenkins#8513

This should help to identify race conditions during tests without causing too much noise as it only kicks in just before cleaning up the instance.

Testing done

Submitter checklist

Give feedback

Make sure you are opening from a topic/feature/bugfix branch (right side) and not your main branch!
Ensure that the pull request title represents the desired changelog entry
Please describe what you did
Link to relevant issues in GitHub or Jira
Link to relevant pull requests, esp. upstream and downstream changes
Ensure you have provided tests - that demonstrates feature works or fixes the issue
Options

This should help to identify race conditions

src/main/java/org/jvnet/hudson/test/JenkinsRule.java

basil · 2023-09-25T19:02:12Z

src/main/java/org/jvnet/hudson/test/JenkinsRule.java

        if (exception.getSuppressed().length > 0) {
            throw exception;
        }
    }

+    private static final class TemporaryConsoleLogTweak implements AutoCloseable {


Why is this temporary, and how will we ensure that it does not become permanent?

This is not meant to be temporary, I renamed the class to clarify the intent.

This is not meant to be temporary

What would its value be after we diagnose and fix the bug seen in https://github.com/jenkinsci/jenkins/pull/8511/checks?check_run_id=17000216956?

If there is no more race condition, I would fine removing it, but the thing is with this kind of issue is that it always pop up at an unexpected time and you often don't have enough data to investigate. On the other hand its impact is very light (under normal condition this adds one stacktrace writing queue.xml) since you wouldn't expect much xmlfile write being donc between stopping the test Jenkins instance and the cleanup sequence.

Fine with the merge of this PR if and only if it is reverted once its diagnostic value has been exhausted.

Clarify that this is not temporary, just applied within the block.

jglick

Looks helpful; has it be shown to work anywhere?

Vlatombe · 2023-09-28T06:51:23Z

Looks helpful; has it be shown to work anywhere?

I tested this change locally against the test failing in https://github.com/jenkinsci/jenkins/pull/8511/checks?check_run_id=17000216956, it shows correctly the queue.xml being written just before cleanup, so I think it would be enough to show the race condition if it rehappens.

jglick · 2023-09-28T12:16:02Z

Ah so this is going to print

FINEST	hudson.XmlFile#write: Writing …/queue.xml
java.lang.Throwable
	at hudson.XmlFile.write(XmlFile.java:205)
	at hudson.model.Queue.save(Queue.java:472)
	at jenkins.model.Jenkins._cleanUpPersistQueue(Jenkins.java:3921)
	at jenkins.model.Jenkins.cleanUp(Jenkins.java:3676)
	at org.jvnet.hudson.test.JenkinsRule._stopJenkins(JenkinsRule.java:569)
	at org.jvnet.hudson.test.JenkinsRule.after(JenkinsRule.java:517)
	at org.jvnet.hudson.test.JenkinsRule$1.evaluate(JenkinsRule.java:665)

at the end of every test, which is not really desirable, since it is adding noise about a normal event. We would certainly want to know about writes after cleanUp. What this addition does not show is config.xml being written very late, which might be the issue according to the stack trace of the flake.

jglick

Might work. Hard to predict.

Vlatombe · 2023-09-28T12:36:42Z

Might work. Hard to predict.

Yeah, at least this is not polluting every test log anymore.

jglick · 2023-09-28T13:11:52Z

I reran all of QuietDownCommandTest with this patch and did not see any XmlFile stack traces, so I think this is reasonable to merge as is, and we can hope it reveals something.

basil · 2023-09-28T17:14:04Z

#657 (comment)

Set up file logging when shutting down the Jenkins test instance.

85eae18

This should help to identify race conditions

Vlatombe mentioned this pull request Sep 21, 2023

Logging XmlFile write to help track race conditions during tests. jenkinsci/jenkins#8513

Merged

Vlatombe marked this pull request as ready for review September 21, 2023 15:16

jtnord reviewed Sep 25, 2023

View reviewed changes

src/main/java/org/jvnet/hudson/test/JenkinsRule.java Outdated Show resolved Hide resolved

Apply log tweak temporarily

ecd9a7d

jtnord approved these changes Sep 25, 2023

View reviewed changes

basil reviewed Sep 25, 2023

View reviewed changes

Vlatombe added 2 commits September 26, 2023 09:16

Improvements

4653178

Clarify that this is not temporary, just applied within the block.

handler/logger levels can be null

f9201e2

jglick approved these changes Sep 27, 2023

View reviewed changes

jglick mentioned this pull request Sep 28, 2023

Diagnostics for QuietDownCommandTest.quietDownShouldSuccessWithBlockPlusNonExpiredTimeoutAndRunningExecutor jenkinsci/jenkins#8534

Merged

Capture logging around cleaning up filesystem instead.

fb35837

jglick approved these changes Sep 28, 2023

View reviewed changes

jglick added the enhancement label Sep 28, 2023

jglick merged commit ac531db into jenkinsci:master Sep 28, 2023
13 checks passed

Vlatombe deleted the set-up-logging-on-stop branch September 28, 2023 13:14

jtnord mentioned this pull request Oct 4, 2023

[JENKINS-71971][JEP-237] FIPS-140 compliant version of HudsonPrivateSecurityRealm jenkinsci/jenkins#8393

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Set up file logging when shutting down the Jenkins test instance. #657

Set up file logging when shutting down the Jenkins test instance. #657

Vlatombe commented Sep 21, 2023 •

edited

Loading

Submitter checklist

basil Sep 25, 2023

Vlatombe Sep 26, 2023

basil Sep 26, 2023

Vlatombe Sep 28, 2023

basil Sep 28, 2023

jglick left a comment

Vlatombe commented Sep 28, 2023

jglick commented Sep 28, 2023

jglick left a comment

Vlatombe commented Sep 28, 2023

jglick commented Sep 28, 2023

basil commented Sep 28, 2023

Set up file logging when shutting down the Jenkins test instance. #657

Set up file logging when shutting down the Jenkins test instance. #657

Conversation

Vlatombe commented Sep 21, 2023 • edited Loading

Testing done

Submitter checklist

basil Sep 25, 2023

Choose a reason for hiding this comment

Vlatombe Sep 26, 2023

Choose a reason for hiding this comment

basil Sep 26, 2023

Choose a reason for hiding this comment

Vlatombe Sep 28, 2023

Choose a reason for hiding this comment

basil Sep 28, 2023

Choose a reason for hiding this comment

jglick left a comment

Choose a reason for hiding this comment

Vlatombe commented Sep 28, 2023

jglick commented Sep 28, 2023

jglick left a comment

Choose a reason for hiding this comment

Vlatombe commented Sep 28, 2023

jglick commented Sep 28, 2023

basil commented Sep 28, 2023

Vlatombe commented Sep 21, 2023 •

edited

Loading