You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Keith Wall (JIRA)" <ji...@apache.org> on 2016/08/02 18:04:20 UTC
[jira] [Comment Edited] (QPID-7369) SaslServlet.getRandom failed
with IllegalStateException
[ https://issues.apache.org/jira/browse/QPID-7369?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15404489#comment-15404489 ]
Keith Wall edited comment on QPID-7369 at 8/2/16 6:04 PM:
----------------------------------------------------------
The test sends separate, serial, http requests to test the behaviour when the SASL authentication is attempted for a user that does not exist. The test caused a failed authentication attempt (which correctly ended with a 401 and the session would have been invalidated). The test then makes another GET, maintaining the original session id. I think the intent of the last interaction is to show that the user has inadvertently become authenticated. In the failing case, the attempt to read a session attribute failed internally within Jetty. The test grabs the JSESSION from the cookie jar at the beginning of the test and maintains it al the way through the test.
I can't see an issue in the Qpid code and to me the failure suggests a Jetty issue. The servlet container is obliged to create a new session if presented with a JSESSIONID it doesn't (or no longer) recognises and indeed this is normally what seems to happen (see trace below - notice JSESSIONID change at last step). It seems that in the failing case, that behaviour for some reason did not occur.
However, there is no recorded Jetty bug that matches this problem for either Jetty 8 or more recent (supported) versions. (We are on 8.1.17 - latest on 8.1 is 8.1.19).
I do see some similar reported issues for other projects, but nothing conclusively identifies a client defect.
http://git.eclipse.org/c/jetty/org.eclipse.jetty.project.git/tree/VERSION.txt?h=jetty-8
If the defect were to occur, the Broker's operation would be unaffected. The client would receive a 500 and retrying would most probably work normally.
{noformat}
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@543295b07 pairs: {POST /service/sasl HTTP/1.1: null}{User-Agent: Java/1.8.0_101}{Host: localhost:51622}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}{Content-type: application/x-www-form-urlencoded}{Content-Length: 18}
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream used: http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@54422e185 pairs: {null: HTTP/1.1 200 OK}{Set-Cookie: JSESSIONID_0=1x709oemaqymq1me1ebzkjal96;Path=/}{Expires: Thu, 01 Jan 1970 00:00:00 GMT}{Content-Type: application/json;charset=UTF-8}{Content-Length: 118}
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream retrieved from the cache, sun.net.www.http.HttpClient(http://localhost:51622/service/sasl)
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@383dc82c8 pairs: {POST /service/sasl HTTP/1.1: null}{Cookie: JSESSIONID_0=1x709oemaqymq1me1ebzkjal96}{User-Agent: Java/1.8.0_101}{Host: localhost:51622}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}{Content-type: application/x-www-form-urlencoded}{Content-Length: 92}
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream used: http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@4a07d6053 pairs: {null: HTTP/1.1 401 Unauthorized}{Content-Type: application/json;charset=UTF-8}{Content-Length: 3}
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getServerAuthentication
FINER: Server Authentication for AuthenticationHeader: prefer null returned null
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@7d7758be6 pairs: {GET /service/sasl HTTP/1.1: null}{Cookie: JSESSIONID_0=1x709oemaqymq1me1ebzkjal96}{User-Agent: Java/1.8.0_101}{Host: localhost:51622}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream used: http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@2bdd83947 pairs: {null: HTTP/1.1 200 OK}{Set-Cookie: JSESSIONID_0=1jd092g9a5wavjh2gbpvyhjl1;Path=/}{Content-Type: application/json;charset=UTF-8}{Cache-Control: no-cache}{Pragma: no-cache}{Expires: Thu, 01 Jan 1970 00:00:00 GMT}{Content-Length: 76}
{noformat}
was (Author: k-wall):
The test sends separate, serial, http requests to test the behaviour when the SASL authentication is attempted for a user that does not exist. The test caused a failed authentication attempt (which correctly ended with a 401 and the session would have been invalidated). The test then makes another GET, maintaining the original session id. I think the intent of the last interaction is to show that the user has inadvertently become authenticated. In the failing case, the attempt to read a session attribute failed internally within Jetty. The test grabs the JSESSION from the cookie jar at the beginning of the test and maintains it al the way through the test.
I can't see an issue in the Qpid code and to me the failure suggests a Jetty issue. The servlet container is obliged to create a new session if presented with a JSESSIONID it doesn't (or no longer) recognises and indeed this is normally what seems to happen (see trace below - notice JSESSIONID change at last step). It seems that in the failing case, that behaviour for some reason did not occur.
However, there is no recorded Jetty bug that matches this problem for either Jetty 8 or more recent (supported) versions. (We are on 8.1.17 - latest on 8.1 is 8.1.19).
I do see some similar reported issues for other projects, but nothing conclusively identifies a client defect.
http://git.eclipse.org/c/jetty/org.eclipse.jetty.project.git/tree/VERSION.txt?h=jetty-8
If the defect were to occur, the Broker's operation would be unaffected. The client would receive a 500 and retrying would most probably work normally.
{no format}
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@543295b07 pairs: {POST /service/sasl HTTP/1.1: null}{User-Agent: Java/1.8.0_101}{Host: localhost:51622}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}{Content-type: application/x-www-form-urlencoded}{Content-Length: 18}
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream used: http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@54422e185 pairs: {null: HTTP/1.1 200 OK}{Set-Cookie: JSESSIONID_0=1x709oemaqymq1me1ebzkjal96;Path=/}{Expires: Thu, 01 Jan 1970 00:00:00 GMT}{Content-Type: application/json;charset=UTF-8}{Content-Length: 118}
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream retrieved from the cache, sun.net.www.http.HttpClient(http://localhost:51622/service/sasl)
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@383dc82c8 pairs: {POST /service/sasl HTTP/1.1: null}{Cookie: JSESSIONID_0=1x709oemaqymq1me1ebzkjal96}{User-Agent: Java/1.8.0_101}{Host: localhost:51622}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}{Content-type: application/x-www-form-urlencoded}{Content-Length: 92}
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream used: http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@4a07d6053 pairs: {null: HTTP/1.1 401 Unauthorized}{Content-Type: application/json;charset=UTF-8}{Content-Length: 3}
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getServerAuthentication
FINER: Server Authentication for AuthenticationHeader: prefer null returned null
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@7d7758be6 pairs: {GET /service/sasl HTTP/1.1: null}{Cookie: JSESSIONID_0=1x709oemaqymq1me1ebzkjal96}{User-Agent: Java/1.8.0_101}{Host: localhost:51622}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
Aug 02, 2016 6:24:40 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream used: http://localhost:51622/service/sasl
Aug 02, 2016 6:24:40 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@2bdd83947 pairs: {null: HTTP/1.1 200 OK}{Set-Cookie: JSESSIONID_0=1jd092g9a5wavjh2gbpvyhjl1;Path=/}{Content-Type: application/json;charset=UTF-8}{Cache-Control: no-cache}{Pragma: no-cache}{Expires: Thu, 01 Jan 1970 00:00:00 GMT}{Content-Length: 76}
{noformat}
The test failed on the last HTTP interaction, immediately following the failed authentication attempt (which correctly returned a 401
> SaslServlet.getRandom failed with IllegalStateException
> --------------------------------------------------------
>
> Key: QPID-7369
> URL: https://issues.apache.org/jira/browse/QPID-7369
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Reporter: Keith Wall
> Fix For: qpid-java-6.1
>
> Attachments: TEST-org.apache.qpid.systest.rest.SaslRestTest.testCramMD5SaslAuthenticationForNonExistingUser.txt
>
>
> The following test failed on Apache CI with a IllegalStateException from Jetty within {{SaslServlet.getRandom}}. on trunk. Could this have something to do with the work of QPID-7046?
> https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Java-Java-BDB-TestMatrix/2335/jdk=JDK%201.7%20(latest),label=Ubuntu,profile=java-bdb.0-10/testReport/junit/org.apache.qpid.systest.rest/SaslRestTest/testCramMD5SaslAuthenticationForNonExistingUser/
> {noformat}
> 2016-07-27 15:50:48,396 ERROR [HttpManagement-http-90208] o.a.q.s.m.p.f.ExceptionHandlingFilter Unexpected exception in servlet '/service/sasl':
> java.lang.IllegalStateException: null
> at org.eclipse.jetty.server.session.AbstractSession.checkValid(AbstractSession.java:109) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
> at org.eclipse.jetty.server.session.HashedSession.checkValid(HashedSession.java:73) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
> at org.eclipse.jetty.server.session.AbstractSession.getAttribute(AbstractSession.java:132) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
> at org.apache.qpid.server.management.plugin.servlet.rest.SaslServlet.getRandom(SaslServlet.java:99) ~[qpid-broker-plugins-management-http-6.1.0-SNAPSHOT.jar:6.1.0-SNAPSHOT]
> at org.apache.qpid.server.management.plugin.servlet.rest.SaslServlet.doGetWithSubjectAndActor(SaslServlet.java:72) ~[qpid-broker-plugins-management-http-6.1.0-SNAPSHOT.jar:6.1.0-SNAPSHOT]
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet$1.run(AbstractServlet.java:89) ~[qpid-broker-plugins-management-http-6.1.0-SNAPSHOT.jar:6.1.0-SNAPSHOT]
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet$1.run(AbstractServlet.java:85) ~[qpid-broker-plugins-management-http-6.1.0-SNAPSHOT.jar:6.1.0-SNAPSHOT]
> at java.security.AccessController.doPrivileged(Native Method) ~[na:1.7.0_25]
> at javax.security.auth.Subject.doAs(Subject.java:415) ~[na:1.7.0_25]
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet.doWithSubjectAndActor(AbstractServlet.java:214) ~[qpid-broker-plugins-management-http-6.1.0-SNAPSHOT.jar:6.1.0-SNAPSHOT]
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org