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.

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

[JENKINS-21905] Present human readable error when archiving unreadable artifacts #2976

Merged
merged 10 commits into from Sep 24, 2017

Conversation

3 participants
@olivergondza
Member

olivergondza commented Aug 10, 2017

JENKINS-21905

One of the reocuring reason for the cryptic failure in the JIRA is the fact artifacts are not readable for user running slave agent. The exceptions got a bit better since then so it involves the filename and the fact permissions was denied, but user is still staring at ~70 lines of stacktraces. Consolidate this to an easy to grasp message.

To do this, several levels of nested exceptions was removed as it was effectively hiding the root cause.

Proposed changelog entries

Submitter checklist

  • JIRA issue is well described
  • Changelog entry appropriate for the audience affected by the change (users or developer, depending on the change). Examples
    * Use the Internal: prefix if the change has no user-visible impact (API, test frameworks, etc.)
  • Appropriate autotests or explanation to why this change has no tests

Error

Before:

Archiving artifacts
ERROR: Failed to archive artifacts: myfile
java.nio.file.AccessDeniedException: /some/path/workspace/test0/myfile
  at sun.nio.fs.UnixException.translateToIOException(UnixException.java:84)
  at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
  at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
  at sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:214)
  at java.nio.file.Files.newByteChannel(Files.java:361)
  at java.nio.file.Files.newByteChannel(Files.java:407)
  at java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:384)
  at java.nio.file.Files.newInputStream(Files.java:152)
  at hudson.util.io.TarArchiver.visit(TarArchiver.java:106)
  at hudson.util.DirScanner.scanSingle(DirScanner.java:49)
  at hudson.FilePath$ExplicitlySpecifiedDirScanner.scan(FilePath.java:2823)
  at hudson.FilePath.writeToTar(FilePath.java:2269)
  at hudson.FilePath.access$2100(FilePath.java:197)
  at hudson.FilePath$45.invoke(FilePath.java:2212)
  at hudson.FilePath$45.invoke(FilePath.java:2208)
  at hudson.FilePath$FileCallableWrapper.call(FilePath.java:2750)
  at hudson.remoting.UserRequest.perform(UserRequest.java:181)
  at hudson.remoting.UserRequest.perform(UserRequest.java:52)
  at hudson.remoting.Request$2.run(Request.java:336)
  at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  at java.lang.Thread.run(Thread.java:748)
Caused: java.io.IOException: Error writing to tar file from: /some/path/workspace/test0/myfile
  at hudson.util.io.TarArchiver.visit(TarArchiver.java:113)
  at hudson.util.DirScanner.scanSingle(DirScanner.java:49)
  at hudson.FilePath$ExplicitlySpecifiedDirScanner.scan(FilePath.java:2823)
  at hudson.FilePath.writeToTar(FilePath.java:2269)
  at hudson.FilePath.access$2100(FilePath.java:197)
  at hudson.FilePath$45.invoke(FilePath.java:2212)
  at hudson.FilePath$45.invoke(FilePath.java:2208)
  at hudson.FilePath$FileCallableWrapper.call(FilePath.java:2750)
  at hudson.remoting.UserRequest.perform(UserRequest.java:181)
  at hudson.remoting.UserRequest.perform(UserRequest.java:52)
  at hudson.remoting.Request$2.run(Request.java:336)
  at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  at java.lang.Thread.run(Thread.java:748)
  at ......remote call to slave0(Native Method)
  at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1554)
  at hudson.remoting.UserResponse.retrieve(UserRequest.java:281)
  at hudson.remoting.Channel$2.adapt(Channel.java:869)
Caused: java.util.concurrent.ExecutionException
  at hudson.remoting.Channel$2.adapt(Channel.java:871)
  at hudson.remoting.Channel$2.adapt(Channel.java:866)
  at hudson.remoting.FutureAdapter.get(FutureAdapter.java:55)
  at hudson.FilePath.copyRecursiveTo(FilePath.java:2231)
Caused: java.io.IOException
  at hudson.FilePath.copyRecursiveTo(FilePath.java:2233)
  at jenkins.model.StandardArtifactManager.archive(StandardArtifactManager.java:61)
  at hudson.tasks.ArtifactArchiver.perform(ArtifactArchiver.java:244)
  at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:81)
  at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
  at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:730)
  at hudson.model.AbstractBuild$AbstractBuildExecution.performAllBuildSteps(AbstractBuild.java:676)
  at hudson.model.Build$BuildExecution.post2(Build.java:186)
  at hudson.model.AbstractBuild$AbstractBuildExecution.post(AbstractBuild.java:621)
  at hudson.model.Run.execute(Run.java:1760)
  at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
  at hudson.model.ResourceController.execute(ResourceController.java:97)
  at hudson.model.Executor.run(Executor.java:415)
Build step 'Archive the artifacts' changed build result to FAILURE
Finished: FAILURE

After:

ERROR: Step ‘Archive the artifacts’ failed: java.nio.file.AccessDeniedException: /some/path/workspace/test0/myfile
@daniel-beck

This comment has been minimized.

Show comment
Hide comment
@daniel-beck

daniel-beck Aug 10, 2017

Member

Would it not be useful to print the stack on a low (e.g. FINE) log level to at least give a chance to figure out more details in case this catches more than it should?

Member

daniel-beck commented Aug 10, 2017

Would it not be useful to print the stack on a low (e.g. FINE) log level to at least give a chance to figure out more details in case this catches more than it should?

@olivergondza

This comment has been minimized.

Show comment
Hide comment
@olivergondza

olivergondza Aug 11, 2017

Member

Sure, this is how it would look like:

WARNING: Diagnosing anticipated Exception
java.nio.file.AccessDeniedException: /home/ogondza/code/jenkins/jenkins/test/target/jenkinsTests.tmp/jenkins8657221315180995243test/workspace/test0/myfile
	at sun.nio.fs.UnixException.translateToIOException(UnixException.java:84)
	at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
	at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
	at sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:214)
	at java.nio.file.Files.newByteChannel(Files.java:361)
	at java.nio.file.Files.newByteChannel(Files.java:407)
	at java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:384)
	at java.nio.file.Files.newInputStream(Files.java:152)
	at hudson.util.io.TarArchiver.visit(TarArchiver.java:106)
	at hudson.util.DirScanner.scanSingle(DirScanner.java:49)
	at hudson.FilePath$ExplicitlySpecifiedDirScanner.scan(FilePath.java:2834)
	at hudson.FilePath.writeToTar(FilePath.java:2280)
	at hudson.FilePath.access$2100(FilePath.java:197)
	at hudson.FilePath$45.invoke(FilePath.java:2217)
	at hudson.FilePath$45.invoke(FilePath.java:2213)
	at hudson.FilePath$FileCallableWrapper.call(FilePath.java:2761)
	at hudson.remoting.UserRequest.perform(UserRequest.java:181)
	at hudson.remoting.UserRequest.perform(UserRequest.java:52)
	at hudson.remoting.Request$2.run(Request.java:336)
	at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at ......remote call to slave0(Native Method)
	at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1554)
	at hudson.remoting.UserResponse.retrieve(UserRequest.java:281)
	at hudson.remoting.Channel$2.adapt(Channel.java:869)
	at hudson.remoting.Channel$2.adapt(Channel.java:866)
	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:55)
	at hudson.FilePath.copyRecursiveTo(FilePath.java:2237)
	at jenkins.model.StandardArtifactManager.archive(StandardArtifactManager.java:61)
	at hudson.tasks.ArtifactArchiver.perform(ArtifactArchiver.java:245)
	at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:81)
	at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
	at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:730)
	at hudson.model.AbstractBuild$AbstractBuildExecution.performAllBuildSteps(AbstractBuild.java:676)
	at hudson.model.Build$BuildExecution.post2(Build.java:186)
	at hudson.model.AbstractBuild$AbstractBuildExecution.post(AbstractBuild.java:621)
	at hudson.model.Run.execute(Run.java:1760)
	at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
	at hudson.model.ResourceController.execute(ResourceController.java:97)
	at hudson.model.Executor.run(Executor.java:415)
Member

olivergondza commented Aug 11, 2017

Sure, this is how it would look like:

WARNING: Diagnosing anticipated Exception
java.nio.file.AccessDeniedException: /home/ogondza/code/jenkins/jenkins/test/target/jenkinsTests.tmp/jenkins8657221315180995243test/workspace/test0/myfile
	at sun.nio.fs.UnixException.translateToIOException(UnixException.java:84)
	at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
	at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
	at sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:214)
	at java.nio.file.Files.newByteChannel(Files.java:361)
	at java.nio.file.Files.newByteChannel(Files.java:407)
	at java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:384)
	at java.nio.file.Files.newInputStream(Files.java:152)
	at hudson.util.io.TarArchiver.visit(TarArchiver.java:106)
	at hudson.util.DirScanner.scanSingle(DirScanner.java:49)
	at hudson.FilePath$ExplicitlySpecifiedDirScanner.scan(FilePath.java:2834)
	at hudson.FilePath.writeToTar(FilePath.java:2280)
	at hudson.FilePath.access$2100(FilePath.java:197)
	at hudson.FilePath$45.invoke(FilePath.java:2217)
	at hudson.FilePath$45.invoke(FilePath.java:2213)
	at hudson.FilePath$FileCallableWrapper.call(FilePath.java:2761)
	at hudson.remoting.UserRequest.perform(UserRequest.java:181)
	at hudson.remoting.UserRequest.perform(UserRequest.java:52)
	at hudson.remoting.Request$2.run(Request.java:336)
	at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at ......remote call to slave0(Native Method)
	at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1554)
	at hudson.remoting.UserResponse.retrieve(UserRequest.java:281)
	at hudson.remoting.Channel$2.adapt(Channel.java:869)
	at hudson.remoting.Channel$2.adapt(Channel.java:866)
	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:55)
	at hudson.FilePath.copyRecursiveTo(FilePath.java:2237)
	at jenkins.model.StandardArtifactManager.archive(StandardArtifactManager.java:61)
	at hudson.tasks.ArtifactArchiver.perform(ArtifactArchiver.java:245)
	at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:81)
	at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
	at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:730)
	at hudson.model.AbstractBuild$AbstractBuildExecution.performAllBuildSteps(AbstractBuild.java:676)
	at hudson.model.Build$BuildExecution.post2(Build.java:186)
	at hudson.model.AbstractBuild$AbstractBuildExecution.post(AbstractBuild.java:621)
	at hudson.model.Run.execute(Run.java:1760)
	at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
	at hudson.model.ResourceController.execute(ResourceController.java:97)
	at hudson.model.Executor.run(Executor.java:415)
@daniel-beck

This comment has been minimized.

Show comment
Hide comment
@daniel-beck
Member

daniel-beck commented Aug 11, 2017

@olivergondza Thanks!

@olivergondza

This comment has been minimized.

Show comment
Hide comment
@olivergondza

olivergondza Aug 17, 2017

Member

Skipping the test on windows after all as the permission manipulation does not seem to work there.

Member

olivergondza commented Aug 17, 2017

Skipping the test on windows after all as the permission manipulation does not seem to work there.

@olivergondza olivergondza reopened this Aug 17, 2017

@oleg-nenashev oleg-nenashev self-requested a review Aug 19, 2017

@oleg-nenashev

This comment has been minimized.

Show comment
Hide comment
@oleg-nenashev

oleg-nenashev Aug 19, 2017

Member

I will try to review it next week. Retriggering CI

Member

oleg-nenashev commented Aug 19, 2017

I will try to review it next week. Retriggering CI

@oleg-nenashev oleg-nenashev reopened this Aug 19, 2017

@oleg-nenashev oleg-nenashev self-assigned this Aug 19, 2017

@oleg-nenashev

The changes look good to me, excepting FilePath. Something is missing there imho

@@ -2199,7 +2199,12 @@ public Void invoke(File f, VirtualChannel channel) throws IOException {
future.get();
return future2.get();
} catch (ExecutionException e) {
throw new IOException(e);
Throwable cause = e.getCause();

This comment has been minimized.

@oleg-nenashev

oleg-nenashev Aug 25, 2017

Member

It loses the track of ExecutionException. I would add it to suppressed at least

@oleg-nenashev

oleg-nenashev Aug 25, 2017

Member

It loses the track of ExecutionException. I would add it to suppressed at least

This comment has been minimized.

@olivergondza

olivergondza Sep 8, 2017

Member

That is intentional as that is just a wrapper to clearly signify what exceptions are coming from the asynchronous framework and which are thrown by the task itself. We know it is the task that failed and I do not see much value in informing people it was executed asynchronously. The main motivation though was to get rid of the clutter there was a lot of.

@olivergondza

olivergondza Sep 8, 2017

Member

That is intentional as that is just a wrapper to clearly signify what exceptions are coming from the asynchronous framework and which are thrown by the task itself. We know it is the task that failed and I do not see much value in informing people it was executed asynchronously. The main motivation though was to get rid of the clutter there was a lot of.

This comment has been minimized.

@oleg-nenashev

oleg-nenashev Sep 9, 2017

Member

Hmm, OK. Maybe it would be useful to push more details, e.g. if the FINE logging enabled for the class.

@oleg-nenashev

oleg-nenashev Sep 9, 2017

Member

Hmm, OK. Maybe it would be useful to push more details, e.g. if the FINE logging enabled for the class.

Show outdated Hide outdated core/src/main/java/hudson/util/io/TarArchiver.java
@olivergondza

This comment has been minimized.

Show comment
Hide comment
@olivergondza

olivergondza Sep 8, 2017

Member

Review comments addressed.

Member

olivergondza commented Sep 8, 2017

Review comments addressed.

@oleg-nenashev

This comment has been minimized.

Show comment
Hide comment
@oleg-nenashev
Member

oleg-nenashev commented Sep 15, 2017

@oleg-nenashev oleg-nenashev changed the title from Present human readable error when archiving unreadable artifacts to [JENKINS-21905] Present human readable error when archiving unreadable artifacts Sep 22, 2017

@oleg-nenashev

This comment has been minimized.

Show comment
Hide comment
@oleg-nenashev

oleg-nenashev Sep 22, 2017

Member

@olivergondza It's definitely ready to go, but I am not sure how to properly note it and how to properly squash it since there are 2 issues mentioned in commit history. IIUC JENKINS-21905 is just a diagnosability improvement on the top of JENKINS-19473.

Could you please integrate the change in a way you find the best?

Member

oleg-nenashev commented Sep 22, 2017

@olivergondza It's definitely ready to go, but I am not sure how to properly note it and how to properly squash it since there are 2 issues mentioned in commit history. IIUC JENKINS-21905 is just a diagnosability improvement on the top of JENKINS-19473.

Could you please integrate the change in a way you find the best?

@olivergondza olivergondza merged commit fd08d75 into jenkinsci:master Sep 24, 2017

1 check passed

continuous-integration/jenkins/pr-head This commit looks good
Details

olivergondza added a commit that referenced this pull request Sep 24, 2017

Merge pull request #2976 from olivergondza/JENKINS-19473
[FIXED JENKINS-21905] Present human readable error when archiving unreadable artifacts
@olivergondza

This comment has been minimized.

Show comment
Hide comment
@olivergondza

olivergondza Sep 24, 2017

Member

Rebased and retagged to refer to JENKINS-21905 I intend to close so all future reports will be relevant for eventual finetuning.

Member

olivergondza commented Sep 24, 2017

Rebased and retagged to refer to JENKINS-21905 I intend to close so all future reports will be relevant for eventual finetuning.

@daniel-beck

This comment has been minimized.

Show comment
Hide comment
@daniel-beck

daniel-beck Sep 25, 2017

Member

To do this, several levels of nested exceptions was removed as it was effectively hiding the root cause.

Notably since https://jenkins.io/changelog/#v2.43 we're already listing the innermost exception on top. The actual error here was already on the first 2-3 lines.

Member

daniel-beck commented Sep 25, 2017

To do this, several levels of nested exceptions was removed as it was effectively hiding the root cause.

Notably since https://jenkins.io/changelog/#v2.43 we're already listing the innermost exception on top. The actual error here was already on the first 2-3 lines.

@olivergondza

This comment has been minimized.

Show comment
Hide comment
@olivergondza

olivergondza Sep 25, 2017

Member

@daniel-beck, right, for user consumption, yes. Though, the exception was cumbersome to act upon when wrapped in all that clutter and that is what this PR took advantage of.


Not that I agree we rearrange exception order like this in general - especially if we fail to be consistent doing that. The remoting exceptions are quire hard to navigate on its own and adding potential inverted listing, depending on which part of Jenkins has printed it, is not helping.

Member

olivergondza commented Sep 25, 2017

@daniel-beck, right, for user consumption, yes. Though, the exception was cumbersome to act upon when wrapped in all that clutter and that is what this PR took advantage of.


Not that I agree we rearrange exception order like this in general - especially if we fail to be consistent doing that. The remoting exceptions are quire hard to navigate on its own and adding potential inverted listing, depending on which part of Jenkins has printed it, is not helping.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment