[JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response #2834

jglick · 2017-04-04T23:26:22Z

Description

While debugging problems servicing a POST to /cli in #2795, I saw a bizarre stack trace from Jetty: it was complaining that someone was trying to write to a committed servlet response. But the error talked about request.getSession() in JEXL (that would be layout.jelly) being a problem, even though this is not a GUI page being served! Turns out that InstallUncaughtExceptionHandler was trying to redirect to oops.jelly, which is certainly not going to work for a non-HTML client. (In my case the exception was in fact thrown near the end of the response handling cycle.)

Switched to just logging the error in case we are already serving content, which prevented Jetty from exploding.

This might also fix a problem I have seen whereby a page gets partially rendered and then an oops appears halfway down, but in totally garbled HTML. (Not to be confused with cases where a separate HTTP response is rendered in an iframe or injected into the innerHTML of something.)

Changelog entries

JENKINS-21695: if an exception is thrown while rendering an HTTP response, just log the stack trace on the server side, without trying to send an error page to the client.

Desired reviewers

@reviewbybees, @jenkinsci/code-reviewers

…ite to a committed response.

ghost · 2017-04-04T23:31:56Z

This pull request originates from a CloudBees employee. At CloudBees, we require that all pull requests be reviewed by other CloudBees employees before we seek to have the change accepted. If you want to learn more about our process please see this explanation.

jglick · 2017-04-06T13:51:37Z

Build failure is from nodejs.org.

oleg-nenashev

I think the changelog is required here, maybe even backporting since it is potentially reproducible in Jenkins without debugging.

If we consider this fix as a backporting-candidate, there should be a JIRA issue.

oleg-nenashev · 2017-04-07T08:28:20Z

core/src/main/java/hudson/init/impl/InstallUncaughtExceptionHandler.java

    @Initializer
    public static void init(final Jenkins j) throws IOException {
        CompressionFilter.setUncaughtExceptionHandler(j.servletContext, new UncaughtExceptionHandler() {
            @Override
            public void reportException(Throwable e, ServletContext context, HttpServletRequest req, HttpServletResponse rsp) throws ServletException, IOException {
+                if (rsp.isCommitted()) {
+                    LOGGER.log(Level.WARNING, null, e);


Maybe makes sense to explicitly say that the response is already committed in the log message

Not really informative. The default expectation is for errors on the server to be logged as such on the server. Arguably it is a bug that errors are ever sent to the client using something like oops.jelly.

oleg-nenashev · 2017-04-07T08:33:40Z

core/src/main/java/hudson/init/impl/InstallUncaughtExceptionHandler.java

@@ -20,11 +20,18 @@
 * @author Kohsuke Kawaguchi
 */
 public class InstallUncaughtExceptionHandler {
+
+    private static final Logger LOGGER = Logger.getLogger(InstallUncaughtExceptionHandler.class.getName());


The class name does not change, so it's perfectly fine

oleg-nenashev · 2017-04-07T08:36:14Z

🐛 till we discuss the approach. And I think we should not integrate any bugfixes without changelogs and JIRA issues. And "Jetty explodes" use-case seems to be a valid bug independently of reproduction steps

jglick · 2017-04-07T15:06:23Z

I am not proposing a backport or a changelog entry, because I am not aware of a specific user-visible symptom. It is just something I saw while testing some changes (which I later modified anyway) and which seemed incorrect.

jglick · 2017-04-11T19:25:05Z

Dug up an old issue JENKINS-21695 with a roughly similar stack trace (Jetty has since been updated).

MarkEWaite

I'm not an expert on handling uncaught exceptions. As far as I can tell, this code is correct.

The change adds a private constructor to the class so the constructor can't be called from a child class. I assume that is more about correctness and protection against future mistakes than it is about this specific fix.

This change needs logging within the class so it moves the logger declaration from its previous location in an inner class into the class itself.

jglick · 2017-04-12T19:46:02Z

The change adds a private constructor to the class so the constructor can't be called from a child class. I assume that is more about correctness and protection against future mistakes than it is about this specific fix.

Yes, it is a utility class so the private constructor prevents accidental subclassing/instantiation.

This change needs logging within the class so it moves the logger declaration from its previous location in an inner class into the class itself.

Correct.

jglick · 2017-04-12T21:04:21Z

FTR what errors look like without this patch:

… hudson.ExpressionFactory2$JexlExpression evaluate
WARNING: Caught exception evaluating: request.getSession() in /cli. Reason: java.lang.IllegalStateException: Response is committed
java.lang.IllegalStateException: Response is committed
	at org.eclipse.jetty.server.Request.getSession(Request.java:1400)
	at org.eclipse.jetty.server.Request.getSession(Request.java:1378)
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:279)
	at sun.reflect.GeneratedMethodAccessor116.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.commons.jexl.util.introspection.UberspectImpl$VelMethodImpl.invoke(UberspectImpl.java:258)
	at org.apache.commons.jexl.parser.ASTMethod.execute(ASTMethod.java:104)
	at org.apache.commons.jexl.parser.ASTReference.execute(ASTReference.java:83)
	at org.apache.commons.jexl.parser.ASTReference.value(ASTReference.java:57)
	at org.apache.commons.jexl.parser.ASTReferenceExpression.value(ASTReferenceExpression.java:51)
	at org.apache.commons.jexl.ExpressionImpl.evaluate(ExpressionImpl.java:80)
	at hudson.ExpressionFactory2$JexlExpression.evaluate(ExpressionFactory2.java:74)
	at org.apache.commons.jelly.tags.core.CoreTagLibrary$3.run(CoreTagLibrary.java:134)
	at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
	at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
	at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120)
	at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
	at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
	at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95)
	at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:63)
	at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:53)
	at org.kohsuke.stapler.jelly.JellyFacet$1.dispatch(JellyFacet.java:97)
	at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:715)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:845)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:649)
	at hudson.init.impl.InstallUncaughtExceptionHandler$1.reportException(InstallUncaughtExceptionHandler.java:31)
	at org.kohsuke.stapler.compression.CompressionFilter.reportException(CompressionFilter.java:77)
	at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:52)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:82)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:553)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

As you can see, there is no information about the original exception.

jglick · 2017-04-12T21:05:05Z

@oleg-nenashev ping, I would like to get this merged already.

svanoort

Looks fine to me now. 🐝

Though I think the SEVERE error for being unable to add the logging is perhaps a bit harsh since it's logging and not a full on "Jenkins is completely hosed" error. But that's a matter of preference I guess.

jglick · 2017-04-18T22:30:42Z

I think the SEVERE error for being unable to add the logging is perhaps a bit harsh

I would tend to agree, but I did not write that code and am not intending to modify it. I was just moving the Logger around.

Predates issue linking and further discussion.

oleg-nenashev

🐝 and @reviewbybees done. Will merge towards the next weekly

… not attempt to write to a committed response. (#2834) (cherry picked from commit 0c7e7bb)

The CompressionFilter.uncaughtExceptionHandler must not attempt to wr…

28610e6

…ite to a committed response.

Merge branch 'master' into InstallUncaughtExceptionHandler-snafu

56b9d68

jglick mentioned this pull request Apr 6, 2017

[JENKINS-41745] Non-Remoting-based CLI #2795

Merged

26 tasks

oleg-nenashev previously requested changes Apr 7, 2017

View reviewed changes

oleg-nenashev added needs-jira-issue A JIRA issue should be created for this PR. It is usually needed for the LTS backporting process needs-more-reviews Complex change, which would benefit from more eyes labels Apr 7, 2017

jglick removed the needs-jira-issue A JIRA issue should be created for this PR. It is usually needed for the LTS backporting process label Apr 11, 2017

MarkEWaite approved these changes Apr 12, 2017

View reviewed changes

oleg-nenashev changed the title ~~The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response~~ [JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response Apr 12, 2017

svanoort approved these changes Apr 14, 2017

View reviewed changes

jglick added ready-for-merge The PR is ready to go, and it will be merged soon if there is no negative feedback and removed needs-more-reviews Complex change, which would benefit from more eyes labels Apr 18, 2017

oleg-nenashev approved these changes Apr 19, 2017

View reviewed changes

oleg-nenashev merged commit 0c7e7bb into jenkinsci:master Apr 21, 2017

jglick deleted the InstallUncaughtExceptionHandler-snafu branch April 24, 2017 17:52

olivergondza pushed a commit that referenced this pull request May 2, 2017

[JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must…

161095e

… not attempt to write to a committed response. (#2834) (cherry picked from commit 0c7e7bb)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response #2834

[JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response #2834

jglick commented Apr 4, 2017 •

edited

Loading

ghost commented Apr 4, 2017

jglick commented Apr 6, 2017

oleg-nenashev left a comment

oleg-nenashev Apr 7, 2017

jglick Apr 11, 2017

oleg-nenashev Apr 7, 2017

oleg-nenashev commented Apr 7, 2017

jglick commented Apr 7, 2017

jglick commented Apr 11, 2017

MarkEWaite left a comment

jglick commented Apr 12, 2017

jglick commented Apr 12, 2017

jglick commented Apr 12, 2017

svanoort left a comment

jglick commented Apr 18, 2017

oleg-nenashev left a comment

[JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response #2834

[JENKINS-21695] - The CompressionFilter.uncaughtExceptionHandler must not attempt to write to a committed response #2834

Conversation

jglick commented Apr 4, 2017 • edited Loading

Description

Changelog entries

Desired reviewers

ghost commented Apr 4, 2017

jglick commented Apr 6, 2017

oleg-nenashev left a comment

Choose a reason for hiding this comment

oleg-nenashev Apr 7, 2017

Choose a reason for hiding this comment

jglick Apr 11, 2017

Choose a reason for hiding this comment

oleg-nenashev Apr 7, 2017

Choose a reason for hiding this comment

oleg-nenashev commented Apr 7, 2017

jglick commented Apr 7, 2017

jglick commented Apr 11, 2017

MarkEWaite left a comment

Choose a reason for hiding this comment

jglick commented Apr 12, 2017

jglick commented Apr 12, 2017

jglick commented Apr 12, 2017

svanoort left a comment

Choose a reason for hiding this comment

jglick commented Apr 18, 2017

oleg-nenashev left a comment

Choose a reason for hiding this comment

jglick commented Apr 4, 2017 •

edited

Loading