[JENKINS-54346] && [JENKINS-55505] Fix stream handling in tee. #62
Conversation
|
No works for me. I'm exception I'm test on my jenkins infra :
With it's script and |
|
dia38, can you please post the whole exception log? By the way, using 'sh' and 'ls' on a Windows node? Isn't that what causing the issue here? |
|
@tolnaisz, yes |
|
@dia38 No idea. It is working fine for me. Can you please run the same script but without the tee and post the output? |
|
@tolnaisz You used API master for create File (on linux) You could see in exception problem serialization between master on linux, and slave on windows. |
|
@dia38 Ok, I see the issue now. |
|
@dia38 Can you please try the new commit? |
|
@tolnaisz test success |
| @@ -63,6 +62,20 @@ public StepExecution start(StepContext context) throws Exception { | |||
| return new Execution(context, file); | |||
| } | |||
|
|
|||
| private static final class TeeTail extends BodyExecutionCallback.TailCall { | |||
There was a problem hiding this comment.
Apparently, since I lack write permission in this repository, I cannot mark my own review comments as resolved! @github surely that is not by design?
| import java.io.OutputStream; | ||
| import java.io.Serializable; | ||
|
|
||
| import java.io.*; |
There was a problem hiding this comment.
As a stylistic matter, prefer to revert to explicit imports.
|
|
||
| @SuppressWarnings("rawtypes") | ||
| @Override | ||
| public OutputStream decorateLogger(Run build, final OutputStream logger) throws IOException, InterruptedException { |
There was a problem hiding this comment.
Would be a lot easier to follow the diff if this were moved back up to where it was.
| if (stream == null) { | ||
| stream = f.act(new TeeFile(append)); | ||
| // From now on, when resumed and the stream gets recreated append new data. | ||
| append = true; |
There was a problem hiding this comment.
You would also need to call StepContext.saveState.
| return Files.newOutputStream(f.toPath(), StandardOpenOption.CREATE, StandardOpenOption.APPEND/*, StandardOpenOption.DSYNC*/); | ||
| } catch (InvalidPathException e) { | ||
| throw new IOException(e); | ||
| private final Boolean append; |
| @@ -76,6 +76,47 @@ public void smokes() throws Exception { | |||
| }); | |||
| } | |||
|
|
|||
| @Test | |||
There was a problem hiding this comment.
If this is verifying a fix for a specific bug, it should be marked with @Issue. Though if I understand correctly, this is just asserting that new tee steps wipe out the previous file contents, which is not a fix for a reported issue. (Whether it is even desirable, I am unsure. I would be inclined to leave the original behavior, since you can always delete the file before running tee if that is what you wanted.)
| }); | ||
| } | ||
|
|
||
| @Test |
There was a problem hiding this comment.
This does sound like a test for a fix of JENKINS-54346—of which JENKINS-55505 sounds like a duplicate, though I do not see a test for that specifically (two bat statements inside one tee).
|
|
||
| private void readObject(ObjectInputStream ois) throws IOException, ClassNotFoundException { | ||
| ois.defaultReadObject(); | ||
| if (ois.readBoolean()) { |
There was a problem hiding this comment.
This scheme has a minor problem: it will throw an error when a tee step is resumed across an upgrade of the plugin, since it changes the serial form even in program.dat where that must not be done.
The issue could be fixed, I think, by using writeReplace and readResolve rather than writeObject and readObject: when Channel.current() == null, just replace with this; when replacing for Remoting, use a special struct class which just resolves back to a filter with the stream configured.
There was a problem hiding this comment.
By the way these kinds of bugs can generally be reproduced, when anyone wants to bother, in a test using @LocalData. In the case of the tee step that would be hard since the serial form in program.dat encodes an absolute file path, which would be invalid when running the test later. Testing resumption of sh steps suffers from the same problem. JenkinsRule offers no good way around this, though someday I might write a special test-only PickleFactory which replaces any File, Path, or String mentioning a file path starting with $JENKINS_HOME or an agent remoteFS root.
| @@ -89,50 +103,92 @@ public boolean start() throws Exception { | |||
| private static class TeeFilter extends ConsoleLogFilter implements Serializable { | |||
|
|
|||
| private final FilePath f; | |||
| private boolean append = false; // By default create a new output. | |||
There was a problem hiding this comment.
This would also cause truncation of files when resuming across an upgrade.
|
While I think the basic change here is right, it took me a while to get the context. Also the bug fix is entangled with a behavioral change (truncating the file upon starting the step), which not only makes the code more complex but also arguably introduces a regression for scripts not expecting this. That part would be best extracted to a follow-on PR if really needed (as previously noted you can also simply delete any existing file before starting), and made opt-in for compatibility. So prior to JEP-210 I suppose the only actual problem was an unclosed file handle, which could have been addressed much more simply by stashing a transient stream field in the filter and adding the #51 & #61 introduced tests against JEP-210 mode, in which |
|
Actually I think the lazy initialization of the stream is likely to lead to a subtle bug: if the first nested step output inside If true (and this ought to be reproducible in a test), then the fix would be to eagerly initialize the stream in the master-side filter when starting or resuming the step (could use |
Unfortunately this could make for worse performance when using remote-printing steps, as ¹Compare |
|
@jglick I din't get your comments around the JEP-210. I have tried to fix the resume after plug-in upgrade issue. Hopefully it is fixed now. Not sure how to test. Removed the 'append'-related modifications. There is no simple way to fix the original implementation just by adding a tail callback. The original version might have opened the stream multiple times. Regarding the lazy initialization. The stream gets created the first time it is needed either when a local step gets executed and the Regarding the performance. I don't see a real way around this as, as you also mentioned, the |
|
Cannot access the details of the build/checks failure. Can somebody fix the link? |
Well the link is fine, the server is not! |
There was a problem hiding this comment.
I think the lazy initialization of the stream is likely to lead to a subtle bug
Still appears to be true after the recent changes.
This scheme has a minor problem: it will throw an error when a
teestep is resumed across an upgrade of the plugin, since it changes the serial form even inprogram.datwhere that must not be done.
Ditto.
| @@ -63,6 +62,20 @@ public StepExecution start(StepContext context) throws Exception { | |||
| return new Execution(context, file); | |||
| } | |||
|
|
|||
| private static final class TeeTail extends BodyExecutionCallback.TailCall { | |||
There was a problem hiding this comment.
Apparently, since I lack write permission in this repository, I cannot mark my own review comments as resolved! @github surely that is not by design?
| " echo 'first message'\n" + | ||
| " }\n" + | ||
| " if (isUnix()) {sh 'rm x.log'} else {bat 'del x.log'}\n" + | ||
| " writeFile file: 'x.log', text: 'second message'\n" + |
There was a problem hiding this comment.
Huh? What is this testing? You are deleting a file, rewriting it with some new contents, reading those same contents back, and asserting you read what you just wrote?
There was a problem hiding this comment.
It tests that the file gets closed properly so it can be deleted, rewritten and the new content read back. This test the exact scenario of the JENKINS-54346 bug where the file wasn't closed after the tee step.
There was a problem hiding this comment.
To reproduce that I think it would suffice to just have the del on Windows, right?
| " if (!isUnix()) { bat 'echo second message' }\n" + | ||
| " }\n" + | ||
| " if (isUnix()) {sh 'rm x.log'} else {bat 'del x.log'}\n" + | ||
| " writeFile file: 'x.log', text: 'third message'\n" + |
There was a problem hiding this comment.
Here again I am unclear on what exactly is being tested.
There was a problem hiding this comment.
This test the JENKINS-55505 (I think) ensuring that 2 writes using bat step doesn't lead to the tee output file being kept open. Ensures that it gets closed and can be deleted and overwritten.
Not simple to explain I am afraid; that JEP involved a lot of changes, some of which affect this step. I would probably need to take over this PR to get some of the details right. In the meantime it may be better to just avoid the step; certainly you do not need it when the block only involves |
I don't see where the lazy initialization of the stream can cause an issue. It gets initialized always on the master when it is needed and then used on the master or transferred to the remote. I am not really familiar with the serialization. My assumption is that the object gets created and any field from the serialization stream gets restored. As the |
The problem is that the filter may be transferred from master to agent, the copy initialized on the agent, then the original initialized on the master—opening the stream twice. It depends on the behavior of the step using the filter. For example, given node {
tee('log') {
bat 'echo 1'
echo '2'
}
}would fail in this way.
Perhaps. In the absence of a test case (and as I mentioned earlier, a |
To transfer the filter to agent the filter must be serialized to a stream first using
Sorry I am not really sure how to use |
Due to oos.writeObject(stream = append(f, stream));I suppose? If so, it would be nice to be able to prove this as sketched in #62 (comment).
Right, which is why you use I think this is mergeable; my outstanding concerns are just about style and test coverage. Thank you for your patience with this difficult fix. |
|
Any movement on the test failure? |
|
Not sure if anyone is actively maintaining this. |
|
I've had quite a few drive by contributions where my code reviews haven't been addressed. If anyone wants to take over the PR I would be happy to merge that. |
Based on work from roel0 this change hopefully fixes the tee issue. It opens the stream only once and closes it at the end of the tee step.
The underlying file gets created and truncated. This is different from the current behavior but I think it is the right one as tee by default (re-)creates the file so it contains only the content tee'd into it.