[JENKINS-56446] Do not permanently close the log stream in FileLogStorage if an interrupted thread attempts to write to it

[dwnusbaum]

See JENKINS-56446.

While investigating other changes I finally tracked down an issue I have seen before where the main Pipeline log gets closed for some unknown reason, blocking all further writes. I will look for a JENKINS ticket shortly, and I know there is a CloudBees-internal ticket about this issue.

The problem is that FileLogStorage.checkId uses a FileChannel method to get the current position of the log whenever the log output switches from one step to another. FileChannel methods close the channel, and in this case the stream it was derived from, if the thread is interrupted when performing any IO operations. This behavior is undesirable for Pipeline, because it means that any thread writing log output for a step has the ability to inadvertently close the log stream permanently if that thread is interrupted, even if the interruption is expected/controlled (e.g. the timeout step).

For some additional context, I also saw a similar issue with another implementation of LogStorage that attempted to use FileChannel, and in that case we avoided it completely in favor of plain FileOutputStream to fix the issue.

Testing done

Submitter checklist

Preview Give feedback

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

[dwnusbaum]

Without the fix, only overall 1 gets written to the log, and you get the "failed to flush" messages in the JENKINS ticket from BuildWatcher in the log as it copies the output which calls maybeFlush.

[jglick]

Looks straightforward.

Many thanks for tracking this down! Out of curiosity, do you know what about the previously posted reproduction scenarios would lead to a thread interruption?

[jglick]

Disabling automerge since I noticed

workflow-api-plugin/src/main/java/org/jenkinsci/plugins/workflow/log/FileLogStorage.java

Line 95 in e929275

osStartPosition = log.length();

would not be well covered by existing tests: none of the ones in this plugin using JenkinsSessionRule seem to check anything interesting about log text. I probably need to either add a cross-restart test to LogStorageTestBase, or introduce a new test case specifically about FileLogStorage verifying that the append mode actually appends and that the index keeps up accordingly.

[dwnusbaum]

do you know what about the previously posted reproduction scenarios would lead to a thread interruption?

No, I do not. @jgreffe and I saw this same issue with an alternate implementation of LogStorage which used FileChannel extensively. We are both on Mac, but for whatever reason he would consistently see the same behavior as in the reported issue, just running mostly normal Pipelines with a lot of log output, but for me things were working fine. I was not sure how to track down the source of the interrupts though, perhaps it could be done with a Java agent or some other kind of JVM instrumentation? I looked briefly through searches like this at that time but nothing particularly stood out.

In this particular case I am prototyping some unrelated changes in workflow-job which caused WorkflowRunRestartTest.interruptedWhileStartingPerformanceOptimized to fail and allowed me to reproduce this issue consistently.

[jglick]

I was not sure how to track down the source of the interrupts though, perhaps it could be done with a Java agent or some other kind of JVM instrumentation?

It is a good question. It is very unfortunate that InterruptedException carries no stack trace from the thread doing the interrupting.

[dwnusbaum]

I probably need to either add a cross-restart test to LogStorageTestBase, or introduce a new test case specifically about FileLogStorage verifying that the append mode actually appends and that the index keeps up accordingly.

Is this something you are actively working on? If not I can look into it, but I will probably not be able to get to it today.

[jglick]

Is this something you are actively working on?

Yes. Actually backing up a bit to try to let pipeline-cloudwatch-logs tests be run using SSO (needed anyway to validate jenkinsci/workflow-durable-task-step-plugin#323). One way or another, I hope to file a separate PR introducing better test coverage for logs across controller restarts in this repo, then get that reviewed & merged, then merge that into this PR so we can enable automerge again with confidence.

[jglick]

Never mind. After exploring a bit, I found that in fact changing

workflow-api-plugin/src/main/java/org/jenkinsci/plugins/workflow/log/FileLogStorage.java

Line 88 in 1679fa2

os = new FileOutputStream(log, true);

to false causes

workflow-api-plugin/src/test/java/org/jenkinsci/plugins/workflow/log/LogStorageTestBase.java

Lines 139 to 143 in 1679fa2

	overallHtmlPos = assertOverallLog(overallHtmlPos, lines(
	"resuming",
	"<span class=\"pipeline-node-1\">one #4",
	"</span><span class=\"pipeline-node-3\">three #1",
	"</span>ending"), true);

to fail. So does changing

workflow-api-plugin/src/main/java/org/jenkinsci/plugins/workflow/log/FileLogStorage.java

Line 97 in b763772

osStartPosition = log.length();

to 0.