Skip to content

Commit

Permalink
log error stacktrace on console on fetch failure
Browse files Browse the repository at this point in the history
  • Loading branch information
@ndeloof
ndeloof committed Feb 9, 2015
1 parent 66dcd56 commit 1c397db
Showing 1 changed file with 1 addition and 0 deletions.
1 change: 1 addition & 0 deletions src/main/java/hudson/plugins/git/GitSCM.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -986,6 +986,7 @@ private void retrieveChanges(Run build, GitClient git, TaskListener listener) th
* GitException. See JENKINS-20531. */
String message = "Error fetching remote repo '" + remoteRepository.getName() + "'";
listener.error(message);
ex.printStackTrace(listener.getLogger());
throw new AbortException(message);
}
}
Expand Down

32 comments on commit 1c397db

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👎 I don't need to see java stacktraces in job log. I need only error message returned from git client.
Also, could you contribute your changes through PRs?

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Every time i see stacktrace i think that plugin code is broken, this becomes really annoying because you not sure whether it real fetch/push error or broken code.

@ndeloof
Copy link
Contributor Author

@ndeloof ndeloof commented on 1c397db Feb 9, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@KostyaSha I've been git-plugin maintainer for 2 years ...
When fetch issue do occur, user don't have any feedback on build log on what went wrong. This is uncommon but required to offer any useful diagnostic

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ndeloof for such cases there is logging, btw maybe time to replace this file .debug to normal logging?

@ndeloof
Copy link
Contributor Author

@ndeloof ndeloof commented on 1c397db Feb 9, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logging won't be included in build log, I want the root error to be displayed in build log so user knows things went wrong and what to look at. Same as build tool failing to start.

@rbywater
Copy link
Member

@rbywater rbywater commented on 1c397db Feb 9, 2015 via email

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Then fix error messages to be informative, all plugins are in the same situation and printing stacktraces is bad behavior. All traces that i see are just a stack of calls downto CliGit implementations.

Yes, admins, normal user shouldn't care about stacktraces. Also regular user will be unable to provide details about jenkins setup for creating informative issue in jira.

@ndeloof
Copy link
Contributor Author

@ndeloof ndeloof commented on 1c397db Feb 9, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@KostyaSha feel free to propose an alternate implementation as a pull-request

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ndeloof just e.getMessage() in the end of error. As example https://github.com/jenkinsci/git-plugin/pull/303/files#diff-b107125a2f24443b55804b5eedfe15b6R255 if i'm not mistaken for git client it returns real error reason

@ite-klass
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I definitely have to agree with @KostyaSha here.
Writing exception stack traces into logs is the absolutely worst and most annoying user-visible thing in the java world. I hate it.

Which end-user is supposed to understand and follow stacktraces?

String message = "Error fetching remote repo '" + remoteRepository.getName() + "'";
message += " " + ex.getMessage();
listener.error(message);
throw new AbortException(message);

would be much more specific, and would show the causing issue - if the exception has adequate error text, which it definitely should have.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ndeloof let's try expose exception messages instead of stacktraces and if you will have real problems everybody will agree to blow traces? I will rebase and extend my PR bit later. Also will try review other parts where errors are hidden.

@MarkEWaite
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While investigating a question from the Jenkins CI users mailing list, I found a case where a useful exception message was being hidden from the user. I created a change in the git client plugin handling of command line exceptions . My apologies that I submitted it directly to the git-client-plugin rather than using any review process. I'm willing to discard or refine the change as needed (along with the tests I wrote which show that the information which was previously being lost is no longer lost).

Comments on that commit are encouraged, even though it is not a pull request. I'm sure it is imperfect, but wanted to use it with a real user problem in hopes the real user problem would show if the technique is useful (or not).

I need to also note that the "hiding" of the additional exception information may actually be my fault. I haven't investigated deeply enough to prove it, but I allowed an exception handling change some time ago in order to allow retries in certain cases. That exception handling change may be the root cause of the information being hidden when an exception is thrown on fetch.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@MarkEWaite your change looks good, you are printing real error messages and not stacktrace, so 👍

@ndeloof
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm open to any "better way" to expose the underlying error. In my case I need the stacktrace to track checkout error down to the root cause, main issue is I don't know what this root cause can be so can't filter. Admittedly not a nice UX for end-user, so open to proposals.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ndeloof do you have issue number? In this place i see that even getMessage() was not printed from exception before.

@tartur
Copy link

@tartur tartur commented on 1c397db Feb 19, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I work on a project that has about 100 active jenkins jobs, on a cluster of 30 jenkins nodes. We have this issue every day randomly and it is frustrating to not have the real root cause. So I agree with @ndeloof on printing the stacktrace. It is not a big deal compared to the obscurity of the error. Jenkins users are developers after all or at least IT people :)

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tartur have you looked at code? This part has no root cause message at all.

@tartur
Copy link

@tartur tartur commented on 1c397db Feb 19, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I looked at it and I see that the exception could be thrown in the fetchFrom() method. I did not look at gitclient source code. So I don't understand why we don't have root causes at this part of code?

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because ex.getMessage() was lost and instead of printing it @ndeloof printed whole exception with stacktrace.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And even worse this already released. 👎

@tartur
Copy link

@tartur tartur commented on 1c397db Feb 19, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pardon my slowness but I cannot follow you. In fetchFrom() method the code throws a new GitException with as cause the root GitException (or at least the previous one).

throw new GitException("Failed to fetch from "+url.toString(), ex);

Then when we print the stacktrace of this newly created exception, we print all the Caused by exceptions in the log no? So I don't understand why the ex.getMessage() is lost. Please tell me if I'm wrong.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tartur please read the whole conversation, have nothing to be added.
"Jenkins users are developers after all or at least IT people :)" - yes that's why when i see stacktraces i starting fixing code. And when end-users see such job they report stacktraces and not even reading git error that is just "git push fastworward failed" with real message. Because even regular users knows that stacktrace - is broken code and we can't trust to the whole execution when it has stacktrace!

@ndeloof
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@KostyaSha as it sounds this is a huge pain for you, please open your favorite IDE and provide a better implementation as a pull request that won't hurt users and at same time provide all required diagnostic information to plugin maintainers when anything goes wrong.

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ndeloof i do, please provide issue id so i will be able better test changes for this case.
Also i found history, initial commit 3c952ce had message + stacktrace, then it was simplified and lost both information 54cd07e
Thats why we had regression in diagnostics.

@MarkEWaite
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shame on me for that mistake. Thanks for detecting it.

@ite-klass
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Jenkins users are developers after all or at least IT people :)

That does not mean I want to read stack traces, or scan through them for the actual exception message.
Stack traces always make reading logs harder, because they are magnitudes bigger than any other standard log message.

We are using libraries and other abstraction with defined APIs to be able to blend out the details of their implementations. And that’s exactly what I want to do with plugins. When I’m just using them, I don’t want to see stack traces.

Doesn’t jenkins provide filtered loggers in the manage jenkins -> log section!?
Can the (git) plugins not just print the exception message as a single-line error to the build log (like any other info, warning or error) and log the stack trace as DEBUG into an adequate logger, which you can configure to display in the jenkins logs!?
That way users of the plugin will just see the error message, which is all they want to see, and developers or people trying to find out where this error comes from (debugging) create an adequate log with adequate log level.

@tartur
Copy link

@tartur tartur commented on 1c397db Feb 20, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried the latest version that embed this change and it works like a charm

ERROR: Error fetching remote repo 'origin'
hudson.plugins.git.GitException: Failed to fetch from ssh://repo.MYCOMPANY.lan:29418/MYPRODUCT
    at hudson.plugins.git.GitSCM.fetchFrom(GitSCM.java:735)
    at hudson.plugins.git.GitSCM.retrieveChanges(GitSCM.java:983)
    at hudson.plugins.git.GitSCM.checkout(GitSCM.java:1016)
    at hudson.scm.SCM.checkout(SCM.java:484)
    at hudson.model.AbstractProject.checkout(AbstractProject.java:1265)
    at hudson.model.AbstractBuild$AbstractBuildExecution.defaultCheckout(AbstractBuild.java:622)
    at jenkins.scm.SCMCheckoutStrategy.checkout(SCMCheckoutStrategy.java:86)
    at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:528)
    at hudson.model.Run.execute(Run.java:1759)
    at hudson.model.Build.run(Build.java:113)
    at hudson.model.ResourceController.execute(ResourceController.java:89)
    at hudson.model.Executor.run(Executor.java:240)
Caused by: hudson.plugins.git.GitException: Command "C:\Program Files (x86)\Git\bin\git clean -fdx" returned status code 1:
stdout: Removing MYPRODUCT/QA/target/

stderr: warning: failed to remove MYPRODUCT/QA/target/

    at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1591)
    at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1567)
    at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1563)
    at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommand(CliGitAPIImpl.java:1249)
    at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommand(CliGitAPIImpl.java:1261)
    at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.clean(CliGitAPIImpl.java:615)
    at hudson.plugins.git.GitAPI.clean(GitAPI.java:311)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at hudson.remoting.RemoteInvocationHandler$RPCRequest.perform(RemoteInvocationHandler.java:326)
    at hudson.remoting.RemoteInvocationHandler$RPCRequest.call(RemoteInvocationHandler.java:301)
    at hudson.remoting.RemoteInvocationHandler$RPCRequest.call(RemoteInvocationHandler.java:260)
    at hudson.remoting.UserRequest.perform(UserRequest.java:121)
    at hudson.remoting.UserRequest.perform(UserRequest.java:49)
    at hudson.remoting.Request$2.run(Request.java:324)
    at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
    at java.util.concurrent.FutureTask.run(FutureTask.java:138)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)
    at ......remote call to 7-64-dev-hw-01(Native Method)
    at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1356)
    at hudson.remoting.UserResponse.retrieve(UserRequest.java:221)
    at hudson.remoting.Channel.call(Channel.java:752)
    at hudson.remoting.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:179)
    at $Proxy51.clean(Unknown Source)
    at org.jenkinsci.plugins.gitclient.RemoteGitImpl.clean(RemoteGitImpl.java:444)
    at hudson.plugins.git.extensions.impl.CleanBeforeCheckout.decorateFetchCommand(CleanBeforeCheckout.java:32)
    at hudson.plugins.git.GitSCM.fetchFrom(GitSCM.java:731)
    ... 11 more

Even if this is harder to read, it is far far better than having a very meaningless error message, which still there of course. I cannot see why you prefer swallowing exceptions on blocking issues. In this critical plugin, failure on cloning/fetching/checkouting the source code means a build failure.

If it were the publisher plugin, I don't care that much, but a VCS plugin should be more helpful. However even the publisher plugin is not swallowing fatal errors

ERROR: Publisher hudson.tasks.junit.JUnitResultArchiver aborted due to exception
hudson.AbortException: Test reports were found but none of them are new. Did tests run? 
For example, C:\hudson\workspace\MYPRODUCT\QA\target\report\junit\TEST-com.foo.myproduct.qa.benchmark.testcases.SendOrder.xml is 2 j 22 h old

    at hudson.tasks.junit.TestResult.parse(TestResult.java:178)
    at hudson.tasks.junit.TestResult.parse(TestResult.java:146)
    at hudson.tasks.junit.TestResult.<init>(TestResult.java:122)
    at hudson.tasks.junit.JUnitParser$ParseResultCallable.invoke(JUnitParser.java:119)
    at hudson.tasks.junit.JUnitParser$ParseResultCallable.invoke(JUnitParser.java:93)
    at hudson.FilePath$FileCallableWrapper.call(FilePath.java:2677)
    at hudson.remoting.UserRequest.perform(UserRequest.java:121)
    at hudson.remoting.UserRequest.perform(UserRequest.java:49)
    at hudson.remoting.Request$2.run(Request.java:324)
    at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
    at java.util.concurrent.FutureTask.run(FutureTask.java:138)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)
    at ......remote call to 7-64-dev-hw-01(Native Method)
    at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1356)
    at hudson.remoting.UserResponse.retrieve(UserRequest.java:221)
    at hudson.remoting.Channel.call(Channel.java:752)
    at hudson.FilePath.act(FilePath.java:970)
    at hudson.FilePath.act(FilePath.java:959)
    at hudson.tasks.junit.JUnitParser.parseResult(JUnitParser.java:90)
    at hudson.tasks.junit.JUnitResultArchiver.parse(JUnitResultArchiver.java:120)
    at hudson.tasks.junit.JUnitResultArchiver.perform(JUnitResultArchiver.java:137)
    at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:74)
    at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
    at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:770)
    at hudson.model.AbstractBuild$AbstractBuildExecution.performAllBuildSteps(AbstractBuild.java:734)
    at hudson.model.Build$BuildExecution.post2(Build.java:183)
    at hudson.model.AbstractBuild$AbstractBuildExecution.post(AbstractBuild.java:683)
    at hudson.model.Run.execute(Run.java:1784)
    at hudson.model.Build.run(Build.java:113)
    at hudson.model.ResourceController.execute(ResourceController.java:89)
    at hudson.model.Executor.run(Executor.java:240)

Writing exception stack traces into logs is the absolutely worst and most annoying user-visible thing in the java world. I hate it
That does not mean I want to read stack traces
That way users of the plugin will just see the error message, which is all they want to see

@ite-klass May be I'm a weird guy :) but that is what I'm looking for when an issue occurs. Who are your plugin users if not developers? Every developer I met during my career is relieved to see a stack trace when problems occurs. Even business people are happy to see stack traces because they know this helps a lot in problems investigation. That's why I cannot agree your statements.

Unless you master your context and could provide a meaningful error message, you should never try to swallow an exception, especially in a such critical/blocking path.

Anyway, thank you guys and especially @ndeloof, this change saved us several investigation hours

@KostyaSha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Your diagnostic absolutely useless. Reason in error message and not in stacktrace.

Also core must not print stacktraces for AbortException, this is core bug.

@tartur
Copy link

@tartur tartur commented on 1c397db Feb 21, 2015

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@KostyaSha if you don't want feedback from users on your product, then I'm not surprised that the trend is going towards Teamcity :) !

@ite-klass
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tartur Thanks for the elaborative and exemplary reply. :)

The error message should always be so specific that you get all the information you are looking for from a stac trace from it (except code file and line of course).
In the example by the publisher plugin you provided, that is the case.

hudson.AbortException: Test reports were found but none of them are new. Did tests run?

This message is very specific on what went "wrong", and even gives you a hint on the most common cause.

In the example you provided from the git plugin the message is less helpful.

ERROR: Error fetching remote repo 'origin'
[…]
Caused by: hudson.plugins.git.GitException: Command "C:\Program Files (x86)\Git\bin\git clean -fdx" returned status code 1:

In this case, both messages would have to be combined for a really useful and complete error message. And even then, just because the error is not specific but just "return code was 1", it's obviously not that helpful. It is not specific enough.

I’m not necessarily talking about what you have to do, but what it should be like. Sometimes, when the exception messages provided by a library you have no control over are not good enough, using stacktraces is an adequate workaround. But it’s not the/a good solution IMHO.
In the Java world, printing stacktraces is too simple and too common of a workaround though, where it would not actually be needed IMO (like in the publisher plugin case you named, where the message is all you need to understand the issue, and could even find the code path yourself).

Of course, stacktraces are a valuable source of information for the actual plugin developer, when he traces an error in his source code. Thus, as I suggested, the stack traces should optionally be loggable to a separate log. Separate to not be visible to the user, who does not work with the source. Optional, because stacktraces are magnitudes bigger in the log, and not necessary if the error message is complete/descriptive enough.

@ite-klass
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tartur To explicitly reply to some of your closing arguments:

Who are your plugin users if not developers?

Even if they are developers, they should not be thrown at with implementation details of libraries they used for abstraction. We’re using APIs because we want to hide implementation details away behind them, to reduce complexity - and in this case noise.

Even business people are happy to see stack traces because they know this helps a lot in problems investigation.

I want your business people as customers and business people :O

Unless you master your context and could provide a meaningful error message, you should never try to swallow an exception, especially in a such critical/blocking path.

Is optionally logging to a separate log swallowing?

@ndeloof
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ite-klass mais issue is git plugin relies on git cli, and this one does not provide useful information we can easily capture. From this point of view git-plugin is still under development, trying to capture all the scenario we can diagnose from the code to offer a better diagnostic, but this is far from being completed yet.

Please sign in to comment.