pongasoft / glu

Deployment Automation Platform
Apache License 2.0
518 stars 99 forks source link

Grails Runtime Exception (500) when viewing a deployment status #18

Closed rantav closed 11 years ago

rantav commented 13 years ago

Most of the time this works OK, but in one case when I wanted to view the status of a failed deployment (which actually failed with a timeout, I used shell.waitFor) then I got this nasty groovy internal server error.

The URL is at: http://glu.outbrain.com:8080/console/plan/deployments/89?showErrorsOnly=true

And the screen had:

Error 500: Error processing GroovyPageView: Error executing tag : Error executing tag cl:renderStepExecution: null at /WEB-INF/grails-app/views/plan/_deploymentDetails.gsp:37 at /WEB-INF/grails-app/views/plan/deploymentDetails.gsp:95 Servlet: grails URI: /console/grails/plan/deployments.dispatch Exception Message: Caused by: Error processing GroovyPageView: Error executing tag : Error executing tag cl:renderStepExecution: null at /WEB-INF/grails-app/views/plan/_deploymentDetails.gsp:37 at /WEB-INF/grails-app/views/plan/deploymentDetails.gsp:95 Class: gsp_console_plan_deploymentDetails_gsp At Line: [65] Code Snippet: Stack Trace

org.codehaus.groovy.grails.web.pages.exceptions.GroovyPagesException: Error processing GroovyPageView: Error executing tag : Error executing tag cl:renderStepExecution: null at /WEB-INF/grails-app/views/plan/_deploymentDetails.gsp:37 at /WEB-INF/grails-app/views/plan/deploymentDetails.gsp:95

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:534)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1351)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:473)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:929)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:403)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:184)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:864)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)

at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:285)

at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:116)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:359)

at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:275)

at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)

at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)

at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:343)

at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:272)

at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:83)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.apache.shiro.grails.SavedRequestFilter.doFilter(SavedRequestFilter.java:55)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1322)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:473)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:479)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:929)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:403)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:184)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:864)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)

at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)

at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)

at org.eclipse.jetty.server.Server.handle(Server.java:352)

at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:596)

at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1051)

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)

at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)

at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:426)

at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:508)

at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)

at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451)

at java.lang.Thread.run(Thread.java:619)

Caused by: org.codehaus.groovy.grails.web.taglib.exceptions.GrailsTagException: Error executing tag : Error executing tag cl:renderStepExecution: null at /WEB-INF/grails-app/views/plan/_deploymentDetails.gsp:37 at /WEB-INF/grails-app/views/plan/deploymentDetails.gsp:95

at gsp_console_plandeploymentDetails_gsp$_run_closure2.doCall(gsp_console_plandeploymentDetails_gsp.groovy:57)

at gsp_console_plandeploymentDetails_gsp$_run_closure2.doCall(gsp_console_plandeploymentDetails_gsp.groovy)

at gsp_console_plandeploymentDetails_gsp.run(gsp_console_plandeploymentDetails_gsp.groovy:60)

... 54 more

Caused by: org.codehaus.groovy.grails.web.taglib.exceptions.GrailsTagException: Error executing tag cl:renderStepExecution: null at /WEB-INF/grails-app/views/plan/_deploymentDetails.gsp:37

at gsp_console_plan_deploymentDetails_gsp.run(gsp_console_plan_deploymentDetails_gsp.groovy:65)

... 57 more

Caused by: java.lang.NullPointerException

ypujante commented 13 years ago

I suspect this is a race condition. Did it happen while the plan while still executing ? Or was the plan done ? If you reloaded the page did you get the same exception ? Or was it gone ?

rantav commented 13 years ago

Actually I don't think it's a race condition. I was able to repro this a few times. It always happened when the deployment failed due to a timeout. What would happen is that I'm unable to see the plan execution page (e.g. /console/plan/deployments/xxx) AND I'm also unable to see the agent's page, can't read its logs etc and it's always if not exactly the same, a very similar issue. I don't have a repro right now b/c all my deployments were successful but it happened a few times on agents on which the deployments were unsuccessful due to a timeout (otherwise unsuccessful deployments were OK in that sense) The only way to fix that was to redeploy that "damaged" agent and hope there won't be a timeout.

When I say timeout I mean this kind of block in the agent's start() code:

shell.waitFor(timeout: '5m', heartbeat: '2000') {
  try {
    log.info "Checking version at ${versionUrl}. Expected version: ${params.version}"
    versionXmlFile = shell.fetch(versionUrl)
    return true
  } catch (java.io.IOException e) {
    log.warn "Got an IOException but will try again shoon. Sleeping for 5sec...  ${e}"
  } catch (Throwable t) {
    log.warn "Got an error while trying /version. Will give it another try soon... ${t}"
  }   
  return false
}   

Actually now that I see this code I have a wild guess what's killing grails. Isn't it the ${e} or ${t}? I can remove them and replace with getMessage or something. But it's still something you'd probably want to fix...

ypujante commented 13 years ago

If I understand correctly, the ${e} / ${t} code is in your glu script correct ? I doubt it has any impact on the console since when you write log.warn... it is executed on the agent side and not propagated to the console.

If you have a way of consistently reproducing it then that would be great because I never see this kind of error.

rantav commented 13 years ago

I was guessing that the output of ${e} creates a string on the agent that is then passed on to the server (log output) and which may make grails freak out. Maybe with < or > etc

And yes, the ${e}/${t} are in the agent's code

eranharel commented 13 years ago

It happened to me as well during a long deployment

ypujante commented 13 years ago

I will take another look. The good news is that it is only a UI bug and it should not prevent the plan for completing properly (you should be able to refresh the page).

eranharel commented 13 years ago

Refreshing doesn't really help. I still get the exception.

ypujante commented 13 years ago

Is is the exact same stack trace ? If not, do you mind posting it ?

eranharel commented 13 years ago

It is still the same stack trace

eranharel commented 13 years ago

I have an additional input:

I noticed that when I get this error the execution plan seem to have been hang. That is I was following a deployment execution, which seems to have been hanging. When I reenter the plan, I get the exception.

ypujante commented 13 years ago

I just spent some time double checking the code and I cannot figure out what the problem is. Since I am unable to reproduce it, it is really hard for me to understand what the issue is. I see a 'NullPointerException' but there does not seem to be any stack trace associated to it. Next time it happens can you please do the following and post the results:

1) view the source of the page to see if there are more details (more complete stack trace) about the exception and post here 2) on the Plans page, click on the 'Archive' submenu and then click on the plan that was causing problem. Do you get the same error from the Archive submenu ? The rendering on this page is different and displays the plan as plain xml... so it should not trigger the same error since it is a totally different rendering/code path. Please post the xml of the plan causing the issue as it may contain some information to help figure out the issue.

Thanks

ypujante commented 13 years ago

Ran added more information about the issue: http://glu.977617.n3.nabble.com/null-pointer-exception-at-the-console-for-some-of-the-failed-deployments-td2947340.html

rantav commented 13 years ago

with glu console 2.4.0 I'm still getting this error (or maybe it's a similar error) See a screenshot here https://skitch.com/rantav/fyhnp/outbrain-grails-runtime-exception

I tried really hard to debug this but, for the life of me, I just couldn't make jetty reload the gsp pages dynamically, no matter what I tried...

Here's a text version of that last screenshot...

Error 500: Executing action [renderDelta] of controller [org.linkedin.glu.console.controllers.DashboardController] caused exception: Cannot get property 'name' on null object Servlet: grails URI: /console/grails/system/filter.dispatch Exception Message: Cannot get property 'name' on null object Caused by: Cannot get property 'name' on null object Class: gsp_console_systemfilter_gsp At Line: [81]

java.lang.NullPointerException: Cannot get property 'name' on null object
at gsp_console_dashboard_delta_gsp.run(gsp_console_dashboard_delta_gsp.groovy:62)
at org.linkedin.glu.console.controllers.DashboardController$_closure3.doCall(DashboardController.groovy:47)
at org.linkedin.glu.console.controllers.DashboardController$_closure3.doCall(DashboardController.groovy)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:534)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:475)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
ypujante commented 13 years ago

Hey Ran

I don't know if the 2 issues are related or not but in any case, clearly there is an issue :(

I was actually able to change the gsp at runtime! Here is how I did:

in your configuration add the following line (if you use the prepackaged jetty, it is under console-server/conf/glu-console-webapp.groovy):

grails.gsp.enable.reload=true

and stop/restart the console

Then you can go to wherever jetty unpacks the war (in my case there was a warning message that pointed me to the folder):

2011/05/23 08:46:48.116 WARN [ConfigurationFactory] No configuration found. Configuring ehcache from ehcache-failsafe.xml  found in the classpath: jar:file:/private/var/folders/P4/P4x7IuIl2RWsJE+BYw4-qU+++TQ/-Tmp-/jetty-0.0.0.0-8080-org.linkedin.glu.console-webapp-2.4.0.war-_console-any-/webapp/WEB-INF/lib/ehcache-1.4.1.jar!/ehcache-failsafe.xml

in there, you can go to WEB-INF/grails-app/views

and modify any gsp file

I simply added this line to auth/login.gsp

<h1>Dynamic!!</h1>

and could verify on the login screen that it works.

I am sorry that the stack trace provide really no value at all :( and would certainly appreciate if you could 'debug' the gsp a little to try to narrow which line/value is null when it should not.

Thanks a lot

rantav commented 13 years ago

I have tried something similar: grails.gsp.reload.enable=true, which I assume is what you meant. Either it didn't work or that I was changing the wrong gsp. I'll have to give it another look. Anyway, I tried changing it both in glu-console-webapp.groovy and also in the Config.groovy which I compiled to Config.class (and resulting anonymous classes) and copied over to the exploded war. But nothing seemed to have worked. I'll give this another chance next week...

On Mon, May 23, 2011 at 6:56 PM, ypujante < reply@reply.github.com>wrote:

Hey Ran

I don't know if the 2 issues are related or not but in any case, clearly there is an issue :(

I was actually able to change the gsp at runtime! Here is how I did:

in your configuration add the following line (if you use the prepackaged jetty, it is under console-server/conf/glu-console-webapp.groovy):

grails.gsp.enable.reload=true

and stop/restart the console

Then you can go to wherever jetty unpacks the war (in my case there was a warning message that pointed me to the folder):

2011/05/23 08:46:48.116 WARN [ConfigurationFactory] No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/private/var/folders/P4/P4x7IuIl2RWsJE+BYw4-qU+++TQ/-Tmp-/jetty-0.0.0.0-8080-org.linkedin.glu.console-webapp-2.4.0.war-_console-any-/webapp/WEB-INF/lib/ehcache-1.4.1.jar!/ehcache-failsafe.xml

in there, you can go to WEB-INF/grails-app/views

and modify any gsp file

I simply added this line to auth/login.gsp

Dynamic!!

and could verify on the login screen that it works.

I am sorry that the stack trace provide really no value at all :( and would certainly appreciate if you could 'debug' the gsp a little to try to narrow which line/value is null when it should not.

Thanks a lot

Reply to this email directly or view it on GitHub: https://github.com/linkedin/glu/issues/18#comment_1222382

/Ran

ypujante commented 13 years ago

I really meant:

grails.gsp.enable.reload=true

This is what I found in the documentation and what I have used. If you have a chance to use the console-server provided with glu, then the instructions I detailed will work.

Yan

On Tue, May 24, 2011 at 2:05 AM, rantav < reply@reply.github.com>wrote:

I have tried something similar: grails.gsp.reload.enable=true, which I assume is what you meant. Either it didn't work or that I was changing the wrong gsp. I'll have to give it another look. Anyway, I tried changing it both in glu-console-webapp.groovy and also in the Config.groovy which I compiled to Config.class (and resulting anonymous classes) and copied over to the exploded war. But nothing seemed to have worked. I'll give this another chance next week...

On Mon, May 23, 2011 at 6:56 PM, ypujante < reply@reply.github.com>wrote:

Hey Ran

I don't know if the 2 issues are related or not but in any case, clearly there is an issue :(

I was actually able to change the gsp at runtime! Here is how I did:

in your configuration add the following line (if you use the prepackaged jetty, it is under console-server/conf/glu-console-webapp.groovy):

grails.gsp.enable.reload=true

and stop/restart the console

Then you can go to wherever jetty unpacks the war (in my case there was a warning message that pointed me to the folder):

2011/05/23 08:46:48.116 WARN [ConfigurationFactory] No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath:

jar:file:/private/var/folders/P4/P4x7IuIl2RWsJE+BYw4-qU+++TQ/-Tmp-/jetty-0.0.0.0-8080-org.linkedin.glu.console-webapp-2.4.0.war-_console-any-/webapp/WEB-INF/lib/ehcache-1.4.1.jar!/ehcache-failsafe.xml

in there, you can go to WEB-INF/grails-app/views

and modify any gsp file

I simply added this line to auth/login.gsp

Dynamic!!

and could verify on the login screen that it works.

I am sorry that the stack trace provide really no value at all :( and would certainly appreciate if you could 'debug' the gsp a little to try to narrow which line/value is null when it should not.

Thanks a lot

Reply to this email directly or view it on GitHub: https://github.com/linkedin/glu/issues/18#comment_1222382

/Ran

Reply to this email directly or view it on GitHub: https://github.com/linkedin/glu/issues/18#comment_1226976

rantav commented 13 years ago

interesting... there are too many forums bogged with that bogus string grails.gsp.reload.enable. I'll give the correct one a try then...

On Tue, May 24, 2011 at 3:01 PM, ypujante < reply@reply.github.com>wrote:

I really meant:

grails.gsp.enable.reload=true

This is what I found in the documentation and what I have used. If you have a chance to use the console-server provided with glu, then the instructions I detailed will work.

Yan

On Tue, May 24, 2011 at 2:05 AM, rantav < reply@reply.github.com>wrote:

I have tried something similar: grails.gsp.reload.enable=true, which I assume is what you meant. Either it didn't work or that I was changing the wrong gsp. I'll have to give it another look. Anyway, I tried changing it both in glu-console-webapp.groovy and also in the Config.groovy which I compiled to Config.class (and resulting anonymous classes) and copied over to the exploded war. But nothing seemed to have worked. I'll give this another chance next week...

On Mon, May 23, 2011 at 6:56 PM, ypujante < reply@reply.github.com>wrote:

Hey Ran

I don't know if the 2 issues are related or not but in any case, clearly there is an issue :(

I was actually able to change the gsp at runtime! Here is how I did:

in your configuration add the following line (if you use the prepackaged jetty, it is under console-server/conf/glu-console-webapp.groovy):

grails.gsp.enable.reload=true

and stop/restart the console

Then you can go to wherever jetty unpacks the war (in my case there was a warning message that pointed me to the folder):

2011/05/23 08:46:48.116 WARN [ConfigurationFactory] No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath:

jar:file:/private/var/folders/P4/P4x7IuIl2RWsJE+BYw4-qU+++TQ/-Tmp-/jetty-0.0.0.0-8080-org.linkedin.glu.console-webapp-2.4.0.war-_console-any-/webapp/WEB-INF/lib/ehcache-1.4.1.jar!/ehcache-failsafe.xml

in there, you can go to WEB-INF/grails-app/views

and modify any gsp file

I simply added this line to auth/login.gsp

Dynamic!!

and could verify on the login screen that it works.

I am sorry that the stack trace provide really no value at all :( and would certainly appreciate if you could 'debug' the gsp a little to try to narrow which line/value is null when it should not.

Thanks a lot

Reply to this email directly or view it on GitHub: https://github.com/linkedin/glu/issues/18#comment_1222382

/Ran

Reply to this email directly or view it on GitHub: https://github.com/linkedin/glu/issues/18#comment_1226976

Reply to this email directly or view it on GitHub: https://github.com/linkedin/glu/issues/18#comment_1227694

/Ran

ypujante commented 11 years ago

I am closing this very old bug for now. There has not been any new report of it. We can always reopen if necessary.