[
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:09 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 made another GET,
maintaining the original session id. I think the intent of the last
interaction is to show that the user has not 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
for each HTTP interaction.
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.
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 Jetty 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.
Normal trace from HttpURLConnection
{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 made 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 for each HTTP
interaction.
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.
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 Jetty 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.
Normal trace from HttpURLConnection
{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}
> 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: [email protected]
For additional commands, e-mail: [email protected]
