Skip to content
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

JSON file generation failed while deploying the a pipeline #12672

Open
samuelvgo opened this issue Apr 5, 2024 · 7 comments
Open

JSON file generation failed while deploying the a pipeline #12672

samuelvgo opened this issue Apr 5, 2024 · 7 comments

Comments

@samuelvgo
Copy link

Issue Type
  • Bug Report
Summary

While triggering a pipeline that contains multiple stages with automatic approval for the next stage, we are seeing an error in generating the JSON file.
The pipeline is successful, but our internal deployment tool can't receive the JSON file because of the generation failure, the previous stages and different pipelines without the multiple automatic approval works without issues.

Environment
Basic environment details
  • Go Version: 23.5.0 (18179-7702b283accd1f90f014f0087aa2e9bd8baf4a97)
  • JAVA Version: 17.0.9
  • OS: Linux 4.19.0-23-cloud-amd64
Additional Environment Details
Expected Results

We expected it to behave normally like the previous stage:

2024-04-05 13:33:49,061 INFO  [qtp380095890-28] ScheduleService:226 - [Stage Schedule] Scheduling stage sandbox-europe-west4 for pipeline ppro-girogate
2024-04-05 13:33:50,786 INFO  [108@MessageListener for WorkFinder] BuildAssignmentService:190 - [Agent Assignment] Assigned job [JobIdentifier[ppro-girogate, 7, 1.7.0, sandbox-europe-west4, 1, deploy-gcp, 51499]] to agent [Agent [sandbox-europe-west4-gocd-agent-0, 172.20.0.29, 7a8015ac-7c44-4230-98e0-78fc991535e3]]
Actual Results

See the log snippet

Possible Fix
Log snippets
2024-04-05 13:36:41,126 INFO  [qtp380095890-26] ScheduleService:226 - [Stage Schedule] Scheduling stage opglive-europe-west1 for pipeline ppro-girogate
2024-04-05 13:36:41,848 ERROR [qtp380095890-38] JsonOutputWriter:85 - There was an error generating JSON
java.lang.RuntimeException: java.lang.NullPointerException: Cannot invoke "java.sql.Timestamp.getTime()" because the return value of "com.thoughtworks.go.domain.Stage.getLastTransitionedTime()" is null
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson$ConsumerWhichThrows.accept(JsonOutputWriter.java:291)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.withExceptionHandling(JsonOutputWriter.java:278)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.forTopLevelObject(JsonOutputWriter.java:298)
        at com.thoughtworks.go.api.base.JsonOutputWriter.lambda$forTopLevelObject$0(JsonOutputWriter.java:59)
        at com.thoughtworks.go.api.base.JsonOutputWriter.bufferWriterAndFlushWhenDone(JsonOutputWriter.java:80)
        at com.thoughtworks.go.api.base.JsonOutputWriter.forTopLevelObject(JsonOutputWriter.java:57)
        at com.thoughtworks.go.api.ControllerMethods.writerForTopLevelObject(ControllerMethods.java:91)
        at com.thoughtworks.go.apiv3.stageinstance.StageInstanceControllerV3.instanceByCounter(StageInstanceControllerV3.java:160)
        at spark.RouteImpl$1.handle(RouteImpl.java:72)
        at spark.RouteImpl$1.handle(RouteImpl.java:72)
        at spark.http.matching.Routes.execute(Routes.java:61)
        at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:130)
        at spark.servlet.SparkFilter.doFilter(SparkFilter.java:173)
        at com.thoughtworks.go.spark.SparkPreFilter.doFilter(SparkPreFilter.java:62)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:616)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1580)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:680)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:215)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:135)
        at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:381)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.web.FlashLoadingFilter.doFilterInternal(FlashLoadingFilter.java:39)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.DenyIfRefererIsNotFilesFilter.doFilterInternal(DenyIfRefererIsNotFilesFilter.java:52)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.VerifyAuthorityFilter.doFilterInternal(VerifyAuthorityFilter.java:57)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)

Code snippets/Screenshots

image

Any other info
@chadlwilson
Copy link
Member

chadlwilson commented Apr 5, 2024

Thanks for reporting with some details. This has been reported before at https://groups.google.com/g/go-cd/c/gQ5wWIadNqg however without narrowing it down, or knowing some approach to replicate it, I am not sure how to resolve it. In theory I don't think this value should ever be null (although there is some very weird code and DB triggers which are responsible for updating it when jobs complete....), which means something has gone wrong somewhere.

  • I assume this was a problem only for a specific individual run/insance of that pipeline, not ALL runs? Can you confirm?
  • Can you share which stage in the pipeline has the bad value here? Is it sandbox-europe-west4 that has the API call failure?
  • Was there anything "interesting" done for this stage, e.g the stage was re-run or something like that?
  • Do you know how it was triggered? If it's a manual approval, was it done via the UI, or done via an API call?
  • What database do you use behind the scenes? H2 DB (default) or perhaps Postgres?
  • Does the API call work for the same stage after a restart of the server?

I could just YOLO it and make the code in the serializer nullsafe, however I'm afraid something else might break if I do that without understanding if it's an expected situation....

jsonWriter.add("last_transitioned_time", stage.getLastTransitionedTime().getTime());

(Note for myself: This field was only added to V3 of the API in #8681/#8690 for 20.9.0, V2 of the API was removed by me in #9987 for 21.4.0)

@samuelvgo
Copy link
Author

Hi @chadlwilson,

  • I assume this was a problem only for a specific individual run/insance of that pipeline, not ALL runs? Can you confirm?
    R = Yes, this happened only on that run for that pipeline, but it was the first and only one we triggered after the Upgrade to version 23.5.0 that had the automatic move forward thing.

  • Can you share which stage in the pipeline has the bad value here? Is it sandbox-europe-west4 that has the API call failure?
    R = No, sandbox-europe-west4 did the job correctly, we saw the error in the next one opglive-europe-west1

  • Was there anything "interesting" done for this stage, e.g the stage was re-run or something like that?
    R = No, nothing different from the usual.

  • Do you know how it was triggered? If it's a manual approval, was it done via the UI, or done via an API call?
    R = It was done via an API call, using https://api.gocd.org/current/#run-stage:
    /go/api/stages/{self.pipeline}/{counter}/{stage}/run this is how we have that in our deployment tool

  • What database do you use behind the scenes? H2 DB (default) or perhaps Postgres?
    R = H2DB

  • Does the API call work for the same stage after a restart of the server?
    R = We didn't try that because we would need a new release from the product created, however, the API call itself didn't fail from my understanding, because we can see all stages green and deployed, but we can't get the output only.

Let me know if I can provide more details.

@chadlwilson
Copy link
Member

* I assume this was a problem only for a specific individual run/insance of that pipeline, not ALL runs? Can you confirm?
  R = Yes, this happened only on that run for that pipeline, but it was the first and only one we triggered after the Upgrade to version 23.5.0 that had the automatic move forward thing.

It sounds to me like the GoCD server version change is probably a coincidence, however which GoCD server version were you running previously that you hadn't seen this issue with?

* Can you share which stage in the pipeline has the bad value here? Is it sandbox-europe-west4 that has the API call failure?
  R = No, sandbox-europe-west4 did the job correctly, we saw the error in the next one `opglive-europe-west1`

OK, this is interesting, thanks. You might want to check the logs of the gocd-server during the period that opglive-europe-west1 was running/completing to see if anything unusual happened, like the server restarting; or errors/stack traces in the logs that might be relevant. Otherwise sharing the logs during the period that pipeline was running would be useful (may need to check and partially redact them).

* Does the API call work for the same stage after a restart of the server?
  R = We didn't try that because we would need a new release from the product created, however, the API call itself didn't fail from my understanding, because we can see all stages green and deployed, but we can't get the output only.

Yes, I was referring to the API call to retrieve the output, not the API call to trigger the stage/pipeline run.

Why do you need a new release of the product? You can test the same API call manually offline outside your deploy triggering tool to see whether it is consistently failing for opglive-europe-west1, and then try it again after a GoCD server restart?

The reason to ask to test the API call to get-stage-instance via GET /go/api/stages/{pipeline}/{pipeline_counter}/opglive-europe-west1/{stage_counter} after a GoCD server restart is to determine if the data is just "bad" in a GoCD server cache, or whether the data is bad in the underlying H2DB database.

@samuelvgo
Copy link
Author

  • It sounds to me like the GoCD server version change is probably a coincidence, however which GoCD server version were you running previously that you hadn't seen this issue with?

R = We had version 19.12 before, and we performed a upgrade to 23.5

  • OK, this is interesting, thanks. You might want to check the logs of the gocd-server during the period that opglive-europe-west1 was running/completing to see if anything unusual happened, like the server restarting; or errors/stack traces in the logs that might be relevant. Otherwise sharing the logs during the period that pipeline was running would be useful (may need to check and partially redact them).

Those are the logs during that run, there are a few hanging jobs that are not related to this one (but they were also successfully completed and are hanging in the UI after the server upgrade):

2024-04-05 13:36:41,126 INFO  [qtp380095890-26] ScheduleService:226 - [Stage Schedule] Scheduling stage opglive-europe-west1 for pipeline ppro-girogate
2024-04-05 13:36:41,848 ERROR [qtp380095890-38] JsonOutputWriter:85 - There was an error generating JSON
java.lang.RuntimeException: java.lang.NullPointerException: Cannot invoke "java.sql.Timestamp.getTime()" because the return value of "com.thoughtworks.go.domain.Stage.getLastTransitionedTime()" is null
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson$ConsumerWhichThrows.accept(JsonOutputWriter.java:291)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.withExceptionHandling(JsonOutputWriter.java:278)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.forTopLevelObject(JsonOutputWriter.java:298)
        at com.thoughtworks.go.api.base.JsonOutputWriter.lambda$forTopLevelObject$0(JsonOutputWriter.java:59)
        at com.thoughtworks.go.api.base.JsonOutputWriter.bufferWriterAndFlushWhenDone(JsonOutputWriter.java:80)
        at com.thoughtworks.go.api.base.JsonOutputWriter.forTopLevelObject(JsonOutputWriter.java:57)
        at com.thoughtworks.go.api.ControllerMethods.writerForTopLevelObject(ControllerMethods.java:91)
        at com.thoughtworks.go.apiv3.stageinstance.StageInstanceControllerV3.instanceByCounter(StageInstanceControllerV3.java:160)
        at spark.RouteImpl$1.handle(RouteImpl.java:72)
        at spark.RouteImpl$1.handle(RouteImpl.java:72)
        at spark.http.matching.Routes.execute(Routes.java:61)
        at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:130)
        at spark.servlet.SparkFilter.doFilter(SparkFilter.java:173)
        at com.thoughtworks.go.spark.SparkPreFilter.doFilter(SparkPreFilter.java:62)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:616)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1580)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:680)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:215)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:135)
        at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:381)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.web.FlashLoadingFilter.doFilterInternal(FlashLoadingFilter.java:39)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.DenyIfRefererIsNotFilesFilter.doFilterInternal(DenyIfRefererIsNotFilesFilter.java:52)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.VerifyAuthorityFilter.doFilterInternal(VerifyAuthorityFilter.java:57)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractUserEnabledCheckFilter.doFilterInternal(AbstractUserEnabledCheckFilter.java:66)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.ThreadLocalUserFilter.doFilterInternal(ThreadLocalUserFilter.java:41)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.AccessTokenAuthenticationFilter.filterWhenSecurityEnabled(AccessTokenAuthenticationFilter.java:128)
        at com.thoughtworks.go.server.newsecurity.filters.AccessTokenAuthenticationFilter.doFilterInternal(AccessTokenAuthenticationFilter.java:94)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractBasicAuthenticationFilter.doFilterInternal(AbstractBasicAuthenticationFilter.java:56)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AssumeAnonymousUserFilter.doFilterInternal(AssumeAnonymousUserFilter.java:64)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractReAuthenticationFilter.doFilterInternal(AbstractReAuthenticationFilter.java:74)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.InvalidateAuthenticationOnSecurityConfigChangeFilter.doFilterInternal(InvalidateAuthenticationOnSecurityConfigChangeFilter.java:105)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.AlwaysCreateSessionFilter.doFilterInternal(AlwaysCreateSessionFilter.java:40)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractSessionReduceIdleTimeoutFilter.doFilterInternal(AbstractSessionReduceIdleTimeoutFilter.java:44)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.ModeAwareFilter.doFilter(ModeAwareFilter.java:76)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.web.BackupFilter.doFilterInternal(BackupFilter.java:79)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
        at com.thoughtworks.go.server.newsecurity.filterchains.MainFilterChain.doFilter(MainFilterChain.java:79)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at com.thoughtworks.go.server.web.DefaultHeadersFilter.doFilter(DefaultHeadersFilter.java:51)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:598)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1580)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:192)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.Server.handle(Server.java:563)
        at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
        at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
        at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NullPointerException: Cannot invoke "java.sql.Timestamp.getTime()" because the return value of "com.thoughtworks.go.domain.Stage.getLastTransitionedTime()" is null
        at com.thoughtworks.go.apiv3.stageinstance.representers.StageRepresenter.toJSON(StageRepresenter.java:30)
        at com.thoughtworks.go.apiv3.stageinstance.StageInstanceControllerV3.lambda$instanceByCounter$6(StageInstanceControllerV3.java:160)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.lambda$forTopLevelObject$21(JsonOutputWriter.java:300)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson$ConsumerWhichThrows.accept(JsonOutputWriter.java:289)
        ... 159 common frames omitted
2024-04-05 13:36:46,064 INFO  [108@MessageListener for WorkFinder] BuildAssignmentService:190 - [Agent Assignment] Assigned job [JobIdentifier[ppro-girogate, 7, 1.7.0, opglive-europe-west1, 1, deploy-gcp, 51500]] to agent [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 781d843e-1f98-4142-ac1e-80b2f6a94cf5]]
2024-04-05 13:36:52,752 INFO  [goThreadPoolTaskScheduler-2] ConsoleActivityMonitor:111 - Job 'tech-docs/131/opglive-europe-west4/1/deploy-docker' hung for more than '2856' minutes
2024-04-05 13:36:52,753 INFO  [goThreadPoolTaskScheduler-2] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/sandbox-europe-west4/1/deploy-docker' hung for more than '1505' minutes
2024-04-05 13:36:52,753 INFO  [goThreadPoolTaskScheduler-2] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/opglive-europe-west4/1/deploy-docker' hung for more than '1504' minutes
2024-04-05 13:36:52,753 INFO  [goThreadPoolTaskScheduler-2] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/stage/1/deploy-docker' hung for more than '1506' minutes
2024-04-05 13:36:52,753 INFO  [goThreadPoolTaskScheduler-2] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/stage/1/deploy' hung for more than '1506' minutes
2024-04-05 13:37:03,479 INFO  [qtp380095890-31] BuildRepositoryRemoteImpl:96 - [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 781d843e-1f98-4142-ac1e-80b2f6a94cf5, b78bd3e3-bc67-4df6-a3e5-b1d740507385]] is reporting status [Preparing] for [Build [ppro-girogate/7/opglive-europe-west1/1/deploy-gcp/51500]]
2024-04-05 13:37:09,135 INFO  [qtp380095890-31] BuildRepositoryRemoteImpl:96 - [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 781d843e-1f98-4142-ac1e-80b2f6a94cf5, b78bd3e3-bc67-4df6-a3e5-b1d740507385]] is reporting status [Building] for [Build [ppro-girogate/7/opglive-europe-west1/1/deploy-gcp/51500]]
2024-04-05 13:37:22,753 INFO  [goThreadPoolTaskScheduler-6] ConsoleActivityMonitor:111 - Job 'tech-docs/131/opglive-europe-west4/1/deploy-docker' hung for more than '2857' minutes
2024-04-05 13:37:22,753 INFO  [goThreadPoolTaskScheduler-6] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/sandbox-europe-west4/1/deploy-docker' hung for more than '1506' minutes
2024-04-05 13:37:22,753 INFO  [goThreadPoolTaskScheduler-6] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/opglive-europe-west4/1/deploy-docker' hung for more than '1505' minutes
2024-04-05 13:37:22,753 INFO  [goThreadPoolTaskScheduler-6] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/stage/1/deploy-docker' hung for more than '1507' minutes
2024-04-05 13:37:22,753 INFO  [goThreadPoolTaskScheduler-6] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/stage/1/deploy' hung for more than '1507' minutes
2024-04-05 13:37:52,754 INFO  [goThreadPoolTaskScheduler-10] ConsoleActivityMonitor:111 - Job 'tech-docs/131/opglive-europe-west4/1/deploy-docker' hung for more than '2857' minutes
2024-04-05 13:37:52,754 INFO  [goThreadPoolTaskScheduler-10] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/sandbox-europe-west4/1/deploy-docker' hung for more than '1506' minutes
2024-04-05 13:37:52,754 INFO  [goThreadPoolTaskScheduler-10] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/opglive-europe-west4/1/deploy-docker' hung for more than '1505' minutes
2024-04-05 13:37:52,754 INFO  [goThreadPoolTaskScheduler-10] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/stage/1/deploy-docker' hung for more than '1507' minutes
2024-04-05 13:37:52,754 INFO  [goThreadPoolTaskScheduler-10] ConsoleActivityMonitor:111 - Job 'grafana-dashboards/382/stage/1/deploy' hung for more than '1507' minutes
2024-04-05 13:38:13,382 INFO  [qtp380095890-24] BuildRepositoryRemoteImpl:96 - [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 781d843e-1f98-4142-ac1e-80b2f6a94cf5, b78bd3e3-bc67-4df6-a3e5-b1d740507385]] is reporting result [Passed] for [Build [ppro-girogate/7/opglive-europe-west1/1/deploy-gcp/51500]]
2024-04-05 13:38:13,452 INFO  [qtp380095890-24] BuildRepositoryRemoteImpl:96 - [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 781d843e-1f98-4142-ac1e-80b2f6a94cf5, b78bd3e3-bc67-4df6-a3e5-b1d740507385]] is reporting status [Completing] for [Build [ppro-girogate/7/opglive-europe-west1/1/deploy-gcp/51500]]
2024-04-05 13:38:13,696 INFO  [qtp380095890-35] BuildRepositoryRemoteImpl:96 - [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 781d843e-1f98-4142-ac1e-80b2f6a94cf5, b78bd3e3-bc67-4df6-a3e5-b1d740507385]] is reporting status and result [Completed, Passed] for [Build [ppro-girogate/7/opglive-europe-west1/1/deploy-gcp/51500]]
2024-04-05 13:38:13,698 INFO  [qtp380095890-35] Stage:236 - Stage is being completed by transition id: 305134
  • API call results before a restart:
{
  "name" : "opglive-europe-west1",
  "counter" : 1,
  "approval_type" : "manual",
  "approved_by" : "operations",
  "scheduled_at" : 1712317001126,
  "last_transitioned_time" : 1712317093697,
  "result" : "Passed",
  "rerun_of_counter" : null,
  "fetch_materials" : true,
  "clean_working_directory" : false,
  "artifacts_deleted" : false,
  "pipeline_name" : "ppro-girogate",
  "pipeline_counter" : 7,
  "jobs" : [ {
    "name" : "deploy-gcp",
    "state" : "Completed",
    "result" : "Passed",
    "scheduled_date" : 1712317001125,
    "rerun" : false,
    "original_job_id" : null,
    "agent_uuid" : "781d843e-1f98-4142-ac1e-80b2f6a94cf5",
    "pipeline_name" : null,
    "pipeline_counter" : null,
    "stage_name" : null,
    "stage_counter" : null,
    "job_state_transitions" : [ {
      "state" : "Scheduled",
      "state_change_time" : 1712317001125
    }, {
      "state" : "Assigned",
      "state_change_time" : 1712317006061
    }, {
      "state" : "Preparing",
      "state_change_time" : 1712317023480
    }, {
      "state" : "Building",
      "state_change_time" : 1712317029135
    }, {
      "state" : "Completing",
      "state_change_time" : 1712317093383
    }, {
      "state" : "Completed",
      "state_change_time" : 1712317093697
    } ]
  } ]
}#
  • API call after the restart:
{
  "name" : "opglive-europe-west1",
  "counter" : 1,
  "approval_type" : "manual",
  "approved_by" : "operations",
  "scheduled_at" : 1712317001126,
  "last_transitioned_time" : 1712317093697,
  "result" : "Passed",
  "rerun_of_counter" : null,
  "fetch_materials" : true,
  "clean_working_directory" : false,
  "artifacts_deleted" : false,
  "pipeline_name" : "ppro-girogate",
  "pipeline_counter" : 7,
  "jobs" : [ {
    "name" : "deploy-gcp",
    "state" : "Completed",
    "result" : "Passed",
    "scheduled_date" : 1712317001125,
    "rerun" : false,
    "original_job_id" : null,
    "agent_uuid" : "781d843e-1f98-4142-ac1e-80b2f6a94cf5",
    "pipeline_name" : null,
    "pipeline_counter" : null,
    "stage_name" : null,
    "stage_counter" : null,
    "job_state_transitions" : [ {
      "state" : "Scheduled",
      "state_change_time" : 1712317001125
    }, {
      "state" : "Assigned",
      "state_change_time" : 1712317006061
    }, {
      "state" : "Preparing",
      "state_change_time" : 1712317023480
    }, {
      "state" : "Building",
      "state_change_time" : 1712317029135
    }, {
      "state" : "Completing",
      "state_change_time" : 1712317093383
    }, {
      "state" : "Completed",
      "state_change_time" : 1712317093697
    } ]
  } ]
}

@chadlwilson
Copy link
Member

  • It sounds to me like the GoCD server version change is probably a coincidence, however which GoCD server version were you running previously that you hadn't seen this issue with?

R = We had version 19.12 before, and we performed a upgrade to 23.5

OK, thanks - this implies someone must have done an H2 database migration, as 20.5.0 had a forced database migration. Is that correct? Any idea how large your migrated H2 database was?

* API call results before a restart:
{
  "name" : "opglive-europe-west1",
  "counter" : 1,
  "approval_type" : "manual",
  "approved_by" : "operations",
  "scheduled_at" : 1712317001126,
  "last_transitioned_time" : 1712317093697,
  # snip

OK, opglive-europe-west1 was manually/API triggered too.

The stack trace implies the API call is failing whereas the above indicates successful calls to get the stage instance status. These results imply that the stage now has a last_transitioned_time, so it either fixed itself or is not whatever stage is causing the error/stack trace.

Are you saying that there are no longer issues with the stage instance which earlier had a problem? Are you sure you are checking the right pipeline/stage instance that your deploy tool had a problem with? We are wanting to make sure we are looking at the one which had an error at 2024-04-05 13:36:41,848 when the stack trace from a get-instance-instance API call was.

If your deploy tool constantly polls the API to get all of the stage instances in the pipeline (even ones it did not directly trigger), perhaps it's possible that this error is temporarily created due to a race condition (job status is completed in DB, but trigger to populate the stage transition time not yet fired) after which it fixes itself?

I'd probably need to understand a bit more about how your deploy tool interacts with the various APIs to guess as to whether that is what is happening and see if I can replicate it?

if your deploy tool is polling APIs, a workaround for now might be to tell it to try the get-stage-instance call again on a 500 error so it otherwise keeps working. Or perhaps that's what you currently do?

@samuelvgo
Copy link
Author

OK, thanks - this implies someone must have done an H2 database migration, as 20.5.0 had a forced database migration. Is that correct? Any idea how large your migrated H2 database was?

Yes, the migration was done using the migration tool. H2 DB size was around 240MB.
We have migrated the DB from H2 to PostgreSQL recently after a DB crash while restarting the go-server.

Are you saying that there are no longer issues with the stage instance which earlier had a problem

No, we still have the issue with multiple pipelines.

Regarding our deploy tool, yes it constantly polls the API to get all the stage instances, we followed the suggestion to increase the time of the polls and see if we could avoid the race condition, however, no new deployments similar to the failed ones were triggered since then.

I'd probably need to understand a bit more about how your deploy tool interacts with the various APIs to guess as to whether that is what is happening and see if I can replicate it?

The deploy tool is python based, and uses the following via requests to trigger a deployment:

        headers = {"Accept": "application/vnd.go.cd+json", "X-GoCD-Confirm": "true"}
        path = f"/go/api/stages/{self.pipeline}/{counter}/{stage}/run"

And the following also via requests to get the status:

if int(self.get_version().split(".")[0]) > 19:
            path = f"/go/api/stages/{self.pipeline}/{pipeline_counter}/{stage}/{stage_counter}"
        else:
            path = f"/go/api/stages/{self.pipeline}/{stage}/instance/{pipeline_counter}/{stage_counter}"
        return self.my_requests(path)

All of it is triggered from a slack bot that interacts with the python library, it has also permissions for users, and the output of errors or successful pipelines go to slack as well. In our case, instead of the output we are receiving the error mentioned when the issue was opened.

@samuelvgo
Copy link
Author

As a new update, that just happened today with a different pipeline even after the polling time increase:

Logs from the server at the moment:

2024-04-23 15:27:56,334 INFO  [qtp1871368707-32] ScheduleService:226 - [Stage Schedule] Scheduling stage opglive-europe-west1 for pipeline checkout-web-sdk
2024-04-23 15:27:57,482 ERROR [qtp1871368707-26] JsonOutputWriter:85 - There was an error generating JSON
java.lang.RuntimeException: java.lang.NullPointerException: Cannot invoke "java.sql.Timestamp.getTime()" because the return value of "com.thoughtworks.go.domain.Stage.getLastTransitionedTime()" is null
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson$ConsumerWhichThrows.accept(JsonOutputWriter.java:291)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.withExceptionHandling(JsonOutputWriter.java:278)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.forTopLevelObject(JsonOutputWriter.java:298)
        at com.thoughtworks.go.api.base.JsonOutputWriter.lambda$forTopLevelObject$0(JsonOutputWriter.java:59)
        at com.thoughtworks.go.api.base.JsonOutputWriter.bufferWriterAndFlushWhenDone(JsonOutputWriter.java:80)
        at com.thoughtworks.go.api.base.JsonOutputWriter.forTopLevelObject(JsonOutputWriter.java:57)
        at com.thoughtworks.go.api.ControllerMethods.writerForTopLevelObject(ControllerMethods.java:91)
        at com.thoughtworks.go.apiv3.stageinstance.StageInstanceControllerV3.instanceByCounter(StageInstanceControllerV3.java:160)
        at spark.RouteImpl$1.handle(RouteImpl.java:72)
        at spark.RouteImpl$1.handle(RouteImpl.java:72)
        at spark.http.matching.Routes.execute(Routes.java:61)
        at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:130)
        at spark.servlet.SparkFilter.doFilter(SparkFilter.java:173)
        at com.thoughtworks.go.spark.SparkPreFilter.doFilter(SparkPreFilter.java:62)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:616)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1580)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:680)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:215)
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:135)
        at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:381)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.web.FlashLoadingFilter.doFilterInternal(FlashLoadingFilter.java:39)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.DenyIfRefererIsNotFilesFilter.doFilterInternal(DenyIfRefererIsNotFilesFilter.java:52)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.VerifyAuthorityFilter.doFilterInternal(VerifyAuthorityFilter.java:57)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractUserEnabledCheckFilter.doFilterInternal(AbstractUserEnabledCheckFilter.java:66)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.ThreadLocalUserFilter.doFilterInternal(ThreadLocalUserFilter.java:41)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.AccessTokenAuthenticationFilter.filterWhenSecurityEnabled(AccessTokenAuthenticationFilter.java:128)
        at com.thoughtworks.go.server.newsecurity.filters.AccessTokenAuthenticationFilter.doFilterInternal(AccessTokenAuthenticationFilter.java:94)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractBasicAuthenticationFilter.doFilterInternal(AbstractBasicAuthenticationFilter.java:56)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AssumeAnonymousUserFilter.doFilterInternal(AssumeAnonymousUserFilter.java:64)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractReAuthenticationFilter.doFilterInternal(AbstractReAuthenticationFilter.java:74)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.InvalidateAuthenticationOnSecurityConfigChangeFilter.doFilterInternal(InvalidateAuthenticationOnSecurityConfigChangeFilter.java:105)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
        at com.thoughtworks.go.server.newsecurity.filters.AlwaysCreateSessionFilter.doFilterInternal(AlwaysCreateSessionFilter.java:40)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.AbstractSessionReduceIdleTimeoutFilter.doFilterInternal(AbstractSessionReduceIdleTimeoutFilter.java:44)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.newsecurity.filters.ModeAwareFilter.doFilter(ModeAwareFilter.java:76)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at com.thoughtworks.go.server.web.BackupFilter.doFilterInternal(BackupFilter.java:79)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
        at com.thoughtworks.go.server.newsecurity.filterchains.MainFilterChain.doFilter(MainFilterChain.java:79)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at com.thoughtworks.go.server.web.DefaultHeadersFilter.doFilter(DefaultHeadersFilter.java:51)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:598)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1580)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:192)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
        at org.eclipse.jetty.server.Server.handle(Server.java:563)
        at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
        at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277)
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
        at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NullPointerException: Cannot invoke "java.sql.Timestamp.getTime()" because the return value of "com.thoughtworks.go.domain.Stage.getLastTransitionedTime()" is null
        at com.thoughtworks.go.apiv3.stageinstance.representers.StageRepresenter.toJSON(StageRepresenter.java:30)
        at com.thoughtworks.go.apiv3.stageinstance.StageInstanceControllerV3.lambda$instanceByCounter$6(StageInstanceControllerV3.java:160)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson.lambda$forTopLevelObject$21(JsonOutputWriter.java:300)
        at com.thoughtworks.go.api.base.JsonOutputWriter$JsonOutputWriterUsingJackson$ConsumerWhichThrows.accept(JsonOutputWriter.java:289)
        ... 159 common frames omitted
2024-04-23 15:28:02,166 INFO  [108@MessageListener for WorkFinder] BuildAssignmentService:190 - [Agent Assignment] Assigned job [JobIdentifier[checkout-web-sdk, 24, 0.19.0, opglive-europe-west1, 1, deploy-gcp, 52173]] to agent [Agent [opglive-europe-west1-gocd-agent-0, 10.100.36.3, 55c4ceac-2c44-4707-9c23-197ee7d47bbf]]

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

No branches or pull requests

2 participants