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

Warning thrown in server logs when a user visits job console of jobs either not assigned or not started writing to console #6325

Closed
adityasood opened this issue May 23, 2019 · 7 comments

Comments

Projects
5 participants
@adityasood
Copy link
Contributor

commented May 23, 2019

Issue Type
  • Bug Report
Summary

The following warning message is thrown if a user visits the job console of a job which is either not assigned or is assigned but hasn't started writing to the console.

Basic environment details
  • Go Version: 19.4.0-9139
  • JAVA Version: JDK10
  • OS: Ubuntu
  • Browser vendor and version (if relevant): Chrome
```019-05-23 09:25:43,563 WARN  [qtp1684890795-31] HttpChannel:590 - /go/files/hg-cred-as-attr/3/defaultStage/1/defaultJob/cruise-output/console.log
java.lang.IllegalStateException: WRITER
	at org.eclipse.jetty.server.Response.getOutputStream(Response.java:917)
	at javax.servlet.ServletResponseWrapper.getOutputStream(ServletResponseWrapper.java:142)
	at javax.servlet.ServletResponseWrapper.getOutputStream(ServletResponseWrapper.java:142)
	at javax.servlet.ServletResponseWrapper.getOutputStream(ServletResponseWrapper.java:142)
	at javax.servlet.ServletResponseWrapper.getOutputStream(ServletResponseWrapper.java:142)
	at com.thoughtworks.go.server.newsecurity.filters.AccessTokenAuthenticationFilter.onAuthenticationFailure(AccessTokenAuthenticationFilter.java:174)
	at com.thoughtworks.go.server.newsecurity.filters.AccessTokenAuthenticationFilter.doFilterInternal(AccessTokenAuthenticationFilter.java:95)
	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.filterWhenSecurityDisabled(AbstractBasicAuthenticationFilter.java:113)
	at com.thoughtworks.go.server.newsecurity.filters.AbstractBasicAuthenticationFilter.doFilterInternal(AbstractBasicAuthenticationFilter.java:71)
	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:65)
	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:67)
	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:106)
	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.RememberLastRequestUrlFilter.doFilterInternal(RememberLastRequestUrlFilter.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: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.AlwaysCreateSessionFilter.doFilterInternal(AlwaysCreateSessionFilter.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.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:81)
	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:77)
	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.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610)
	at com.thoughtworks.go.server.web.BackupFilter.doFilter(BackupFilter.java:90)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610)
	at com.thoughtworks.go.server.web.DefaultHeadersFilter.doFilter(DefaultHeadersFilter.java:50)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:753)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.Server.handle(Server.java:502)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:411)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:305)
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
	at java.lang.Thread.run(Thread.java:748)

@adityasood adityasood added this to the Release 19.4.0 milestone May 23, 2019

@arvindsv

This comment has been minimized.

Copy link
Member

commented May 23, 2019

If we're looking at this, have you noticed that you can't get the raw console logs of a job which is in progress?

@maheshp

This comment has been minimized.

Copy link
Member

commented May 24, 2019

I took a quick look, this is what I found. Once a job is assigned to an agent, the agent starts posting the console logs to the server. While the job is in progress the server keeps writing the logs to a temporary file and upon completion of the job the temporary file contents are are copied over to a permanent console.log file and is stored as an artifact.

For a job which is yet to be assigned the temporary file is not yet created, the above error occurs when trying to read from a non-existent console log.

If we're looking at this, have you noticed that you can't get the raw console logs of a job which is in progress?

Yes, as I mentioned earlier the server writes the logs to a temporary file till the job is completed. A request to the raw console logs tries to find the logs in the permanent file which does not exist.

Since we are close to a release I am moving this to 19.5.0

@arvindsv

This comment has been minimized.

Copy link
Member

commented May 24, 2019

Yes, as I mentioned earlier the server writes the logs to a temporary file till the job is completed. A request to the raw console logs tries to find the logs in the permanent file which does not exist.

I'd expect that it shows the same log that's being shown in the scrolling logs when that is clicked. Even though it's being updated. We will need to check that it's building and do that, right?

@akshaydewan

This comment has been minimized.

Copy link
Contributor

commented May 28, 2019

This issue is caused by a combination of a few things -

The ConsoleOutView catches a FileNotFoundException. In reality, the exception thrown was NoSuchFileException. (This probably changed in 2017 when some websocket related work was done and we started using java.nio). This didn't make any difference to the UI and nothing got logged.

More recently, we wrote AccessTokenAuthenticationFilter which has a try-catch block that catches all exceptions. The chain.doFilter is inside this try-catch block. As a result, the unhandled NoSuchFileException from the ConsoleOutView came into the catch block. We then tried to write an error message using response.getOutputStream(). But the ConsoleOutView had already called response.getWriter(). This caused Jetty to log the stacktrace we're seeing - java.lang.IllegalStateException: WRITER.

For the fix, I have handled the NoSuchFileException in ConsoleOutView and removed the catch-all exception block from AccessTokenAuthenticationFilter. Not sure if this will break something, so I'll wait for the PR build to assess that.

@akshaydewan

This comment has been minimized.

Copy link
Contributor

commented May 28, 2019

I'd expect that it shows the same log that's being shown in the scrolling logs when that is clicked. Even though it's being updated. We will need to check that it's building and do that, right?

@arvindsv For the raw console logs, we point to the final console.log file, not the temporary file. As a result, we can't see the raw logs until the build is finished. Not sure if this is existing behaviour or if it was changed accidentally. Nonetheless, it seems unrelated to this issue. We can fix it separately.

@maheshp maheshp moved this from To do to In progress in 19.5.0 May 28, 2019

@arvindsv

This comment has been minimized.

Copy link
Member

commented May 28, 2019

Nonetheless, it seems unrelated to this issue. We can fix it separately.

Makes sense. I opened #6350 for it.

Appreciate your detailed root-cause of the issue above. :)

@rajiesh

This comment has been minimized.

Copy link
Contributor

commented Jun 11, 2019

Verified on 19.5.0

@rajiesh rajiesh closed this Jun 11, 2019

@rajiesh rajiesh moved this from In progress to QA Done in 19.5.0 Jun 11, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.