[JIRA] (JENKINS-37625) exception in logs when hitting /monitoring?action=gc

13 views
Skip to first unread message

grayaii@gmail.com (JIRA)

unread,
Aug 23, 2016, 8:40:03 AM8/23/16
to jenkinsc...@googlegroups.com
Alex Gray created an issue
 
Jenkins / Bug JENKINS-37625
exception in logs when hitting /monitoring?action=gc
Issue Type: Bug Bug
Assignee: evernat
Components: monitoring-plugin
Created: 2016/Aug/23 12:39 PM
Environment: monitoring plugin: 1.60.0
jenkins version: 2.7.2
Priority: Minor Minor
Reporter: Alex Gray

We have a script that runs GC periodically by hitting "/monitoring?action=gc".

We upgraded to the latest version of the monitoring plugin and Jenkins and we are now getting the following exception in the logs:

/monitoring?action=gc
java.lang.IllegalStateException: Response is committed
	at org.eclipse.jetty.server.Request.getSession(Request.java:1400)
	at org.eclipse.jetty.security.authentication.FormAuthenticator.validateRequest(FormAuthenticator.java:260)
	at org.eclipse.jetty.security.authentication.DeferredAuthentication.authenticate(DeferredAuthentication.java:68)
	at org.eclipse.jetty.server.Request.getUserPrincipal(Request.java:1479)
	at org.eclipse.jetty.server.Request.getRemoteUser(Request.java:1087)
	at winstone.accesslog.SimpleAccessLogger.log(SimpleAccessLogger.java:89)
	at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:113)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)

It looks benign, but it's something that we haven't seen before.

I can't tell if the "/monitoring?action=gc" is actually working, but it looks like it is.
If it is not, I'll upgrade the severity of this ticket.

Add Comment Add Comment
 
This message was sent by Atlassian JIRA (v7.1.7#71011-sha1:2526d7c)
Atlassian logo

evernat@free.fr (JIRA)

unread,
Sep 14, 2016, 6:35:04 AM9/14/16
to jenkinsc...@googlegroups.com
evernat commented on Bug JENKINS-37625
 
Re: exception in logs when hitting /monitoring?action=gc

I have not reproduced the issue using Jenkins 2.21 and monitoring plugin 1.61.0.

batmat@batmat.net (JIRA)

unread,
Dec 19, 2016, 8:09:02 AM12/19/16
to jenkinsc...@googlegroups.com

I think this bug report is missinig a critical piece of information. I think this issue is triggered when the access logging is enabled. We encountered this on some plugin, and I found this issue searching for similar stack trace.

evernat add --accessLoggerClassName=winstone.accesslog.SimpleAccessLogger --simpleAccessLogger.format=combined --simpleAccessLogger.file=$(pwd)/access_log to the jenkins startup options and I guess this should show you the stack trace above.

Alex Gray can you confirm access logging is enabled on your instance?

Thank you
HTH

batmat@batmat.net (JIRA)

unread,
Dec 19, 2016, 8:13:01 AM12/19/16
to jenkinsc...@googlegroups.com
Baptiste Mathus edited a comment on Bug JENKINS-37625
I think this bug report is missinig missing a critical piece of information. I think this issue is triggered when the access logging is enabled. We encountered this on some plugin, and I found this issue searching for similar stack trace.

I just managed to reproduce it with the monitoring plugin.

[~evernat] add {{--accessLoggerClassName=winstone.accesslog.SimpleAccessLogger --simpleAccessLogger.format=combined --simpleAccessLogger.file=$(pwd)/access_log}} to the jenkins startup options and I guess this should show you the stack trace above.

[~grayaii] can you confirm access logging is enabled on your instance?

Thank you
HTH

grayaii@gmail.com (JIRA)

unread,
Dec 19, 2016, 2:34:01 PM12/19/16
to jenkinsc...@googlegroups.com

Wow, it is indeed enabled!

JENKINS_ENABLE_ACCESS_LOG="yes"
JENKINS_ACCESSLOG="--accessLoggerClassName=winstone.accesslog.SimpleAccessLogger --simpleAccessLogger.format=combined --simpleAccessLogger.file=/var/log/jenkins/access.log"

evernat@free.fr (JIRA)

unread,
Dec 21, 2016, 9:39:02 AM12/21/16
to jenkinsc...@googlegroups.com
evernat commented on Bug JENKINS-37625

For related info:
http://stackoverflow.com/questions/41191519/fail-to-get-views-config-xml-via-python-requests-to-secure-jenkins-self-signed

Alex Gray: Do you have some "user:password" in the url called from the script?

Anyway, I don't think that this is an issue of the monitoring plugin. I think it is an issue of the winstone SimpleAccessLogger: that logger calls Request.getRemoteUser() at some point which calls authenticate and Request.getSession(true). And so the monitoring plugin probably can't do anything about it.

Alex Gray: If you can, I suggest to execute a system groovy script inside a Jenkins job instead of calling the /monitoirng?action=gc URL. The script for GC would be:

import net.bull.javamelody.*;

before = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
System.gc();
after = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
println I18N.getFormattedString("ramasse_miette_execute", Math.round((before - after) / 1024));

For that you will need the groovy plugin.
And you can see the documentation with several monitoring scripts

evernat@free.fr (JIRA)

unread,
Dec 21, 2016, 9:41:01 AM12/21/16
to jenkinsc...@googlegroups.com
evernat edited a comment on Bug JENKINS-37625
[~grayaii]: Do you have some "user:password" in the url called from the script?


Anyway, I don't think that this is an issue of the monitoring plugin. I think it is an issue of the winstone SimpleAccessLogger: that logger calls Request.getRemoteUser() at some point which calls authenticate and Request.getSession(true). And so the monitoring plugin probably can't do anything about it.

[~grayaii]: If you can, I suggest as a workaround to execute a system groovy script inside a Jenkins job instead of calling the /monitoirng?action=gc URL. The script for GC would be:

{code:java}

import net.bull.javamelody.*;

before = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
System.gc();
after = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
println I18N.getFormattedString("ramasse_miette_execute", Math.round((before - after) / 1024));
{code}

For that you will need the [groovy plugin|https://wiki.jenkins-ci.org/display/JENKINS/Groovy+plugin].
And you can see the [documentation with several monitoring scripts|https://wiki.jenkins-ci.org/display/JENKINS/Monitoring+Scripts]

evernat@free.fr (JIRA)

unread,
Dec 21, 2016, 9:43:01 AM12/21/16
to jenkinsc...@googlegroups.com
evernat assigned an issue to Unassigned
 
Change By: evernat
Component/s: winstone-jetty
Component/s: monitoring-plugin
Assignee: evernat

evernat@free.fr (JIRA)

unread,
Dec 21, 2016, 9:44:01 AM12/21/16
to jenkinsc...@googlegroups.com
evernat edited a comment on Bug JENKINS-37625
For related info:
http://stackoverflow.com/questions/41191519/fail-to-get-views-config-xml-via-python-requests-to-secure-jenkins-self-signed

[~grayaii]: Do you have some "user:password" in the url called from the script?

Anyway, I don't think that this is an issue of the monitoring plugin. I think it is an issue of the winstone SimpleAccessLogger: that logger calls Request.getRemoteUser() at some point which calls authenticate and Request.getSession(true). And so the monitoring plugin probably can't do anything about it.

[~grayaii]: If you can, I suggest as a workaround to execute a system groovy script inside a Jenkins job instead of calling the / monitoirng monitoring ?action=gc URL. The script for GC would be:


{code:java}
import net.bull.javamelody.*;

before = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
System.gc();
after = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
println I18N.getFormattedString("ramasse_miette_execute", Math.round((before - after) / 1024));
{code}

For that you will need the [groovy plugin|https://wiki.jenkins-ci.org/display/JENKINS/Groovy+plugin].
And you can see the [documentation with several monitoring scripts|https://wiki.jenkins-ci.org/display/JENKINS/Monitoring+Scripts]

cleclerc@cloudbees.com (JIRA)

unread,
Dec 21, 2016, 10:48:01 AM12/21/16
to jenkinsc...@googlegroups.com

There seem to be a bug in winstone.accesslog.SimpleAccessLogger regarding the remote user.

Could Jenkins rely on the standard Jetty Access Log implementation with RequestLogHandler and NCSARequestLog ? Are there reasons why Jenkins couldn't use it?

As we can see on AbstractNCSARequestLog.java#L130, we should test for anonymous before trying to get the remote user.

https://github.com/eclipse/jetty.project/blob/jetty-9.4.0.v20161208/jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java#L130

Authentication authentication = request.getAuthentication();
append(buf,(authentication instanceof Authentication.User)?((Authentication.User)authentication).getUserIdentity().getUserPrincipal().getName():null);

scm_issue_link@java.net (JIRA)

unread,
Jan 16, 2017, 12:00:02 PM1/16/17
to jenkinsc...@googlegroups.com

Code changed in jenkins
User: Cyrille Le Clerc
Path:
src/java/winstone/accesslog/SimpleAccessLogger.java
http://jenkins-ci.org/commit/winstone/3a1b4fd46de4ab1629b92ff709f8a8d4d1593013
Log:
JENKINS-37625 Don’t get the request.remoteUser if it’s a deferred authentication (`org.eclipse.jetty.server.Authentication.Deferred`) to prevent "IllegalStateException: Response is committed"

```


java.lang.IllegalStateException: Response is committed
at org.eclipse.jetty.server.Request.getSession(Request.java:1400)
at org.eclipse.jetty.security.authentication.FormAuthenticator.validateRequest(FormAuthenticator.java:260)
at org.eclipse.jetty.security.authentication.DeferredAuthentication.authenticate(DeferredAuthentication.java:68)
at org.eclipse.jetty.server.Request.getUserPrincipal(Request.java:1479)
at org.eclipse.jetty.server.Request.getRemoteUser(Request.java:1087)
at winstone.accesslog.SimpleAccessLogger.log(SimpleAccessLogger.java:89)
at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:113)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at org.eclipse.jetty.server.Server.handle(Server.java:499)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

```

scm_issue_link@java.net (JIRA)

unread,
Jan 16, 2017, 12:00:06 PM1/16/17
to jenkinsc...@googlegroups.com

Code changed in jenkins
User: Oleg Nenashev
Path:
src/java/winstone/accesslog/SimpleAccessLogger.java
http://jenkins-ci.org/commit/winstone/784537203190576eb8523deab79cf035fe6da40a
Log:
Merge pull request #31 from cyrille-leclerc/master

JENKINS-37625 Don’t get the request.remoteUser if it’s a deferred authentication

jglick@cloudbees.com (JIRA)

unread,
Jan 17, 2017, 11:40:05 AM1/17/17
to jenkinsc...@googlegroups.com

jglick@cloudbees.com (JIRA)

unread,
Jan 17, 2017, 11:40:05 AM1/17/17
to jenkinsc...@googlegroups.com

jglick@cloudbees.com (JIRA)

unread,
Jan 17, 2017, 11:40:05 AM1/17/17
to jenkinsc...@googlegroups.com
Jesse Glick started work on Bug JENKINS-37625
 
Change By: Jesse Glick
Status: Open In Progress

jglick@cloudbees.com (JIRA)

unread,
Jan 17, 2017, 12:20:01 PM1/17/17
to jenkinsc...@googlegroups.com
Jesse Glick commented on Bug JENKINS-37625
 
Re: exception in logs when hitting /monitoring?action=gc

I believe this is at root a Jetty bug, so I filed it as such.

jglick@cloudbees.com (JIRA)

unread,
Jan 17, 2017, 12:40:01 PM1/17/17
to jenkinsc...@googlegroups.com

scm_issue_link@java.net (JIRA)

unread,
Jan 18, 2017, 11:28:01 AM1/18/17
to jenkinsc...@googlegroups.com

Code changed in jenkins
User: Jesse Glick
Path:
war/pom.xml
http://jenkins-ci.org/commit/jenkins/1e5e53a5fbf1e40ba637f1b21214e0fb8a0bee8b
Log:
[FIXED JENKINS-37625] Update Winstone to fix an IllegalStateException.

jglick@cloudbees.com (JIRA)

unread,
Jan 18, 2017, 11:28:04 AM1/18/17
to jenkinsc...@googlegroups.com

ogondza@gmail.com (JIRA)

unread,
Jan 18, 2017, 2:59:01 PM1/18/17
to jenkinsc...@googlegroups.com
Oliver Gondža updated an issue
Change By: Oliver Gondža
Labels: 2.32.2-rejected lts-candidate

ogondza@gmail.com (JIRA)

unread,
Feb 3, 2017, 6:44:02 AM2/3/17
to jenkinsc...@googlegroups.com
Oliver Gondža updated an issue
Change By: Oliver Gondža
Labels: 2.32.2-rejected lts 2.32.3 - candidate fixed

scm_issue_link@java.net (JIRA)

unread,
Feb 3, 2017, 6:52:01 AM2/3/17
to jenkinsc...@googlegroups.com

Code changed in jenkins
User: Jesse Glick
Path:
war/pom.xml


Log:
[FIXED JENKINS-37625] Update Winstone to fix an IllegalStateException.

(cherry picked from commit 1e5e53a5fbf1e40ba637f1b21214e0fb8a0bee8b)

Reply all
Reply to author
Forward
0 new messages