Strange attempts to

Feb 2, 2011 at 3:09 PM

This is Fiddler's HTTP trace of beginning one of my succesfull conversations:


1) GET http://www.tst.t2wd.tele2.ru/t2wd/start HTTP/1.1
Accept: image/jpeg, image/gif, image/pjpeg, */*
Referer: http://www.tst.t2wd.tele2.ru/t2wd/error403.jsp
Accept-Language: ru-RU
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727)
Accept-Encoding: gzip, deflate
Connection: Keep-Alive
Cookie: JSESSIONID=3126A9CFCA7D081E5079572FF6CF78FA.T2RU-WDAPP-01
Host: www.tst.t2wd.tele2.ru

HTTP/1.1 401 Unauthorized
Date: Wed, 02 Feb 2011 15:08:17 GMT
Server: Apache/2.2.15 (Win32) mod_ssl/2.2.15 OpenSSL/0.9.8m mod_jk/1.2.30
X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1
Set-Cookie: JSESSIONID=C3BEB5AF3983BA259524B2EFA6A1BF23.T2RU-WDAPP-01; Path=/t2wd
Connection: keep-alive, Keep-Alive
WWW-Authenticate: Negotiate
WWW-Authenticate: NTLM
WWW-Authenticate: Basic realm="BasicSecurityFilterProvider"
Keep-Alive: timeout=5, max=98
Transfer-Encoding: chunked
Content-Type: text/plain
Proxy-Support: Session-Based-Authentication

------------------------------------------------------------------

2) GET http://www.tst.t2wd.tele2.ru/t2wd/start HTTP/1.1
Accept: image/jpeg, image/gif, image/pjpeg, */*
Referer: http://www.tst.t2wd.tele2.ru/t2wd/error403.jsp
Accept-Language: ru-RU
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727)
Accept-Encoding: gzip, deflate
Authorization: Negotiate TlRMT...
Connection: Keep-Alive
Cookie: JSESSIONID=C3BEB5AF3983BA259524B2EFA6A1BF23.T2RU-WDAPP-01
Host: www.tst.t2wd.tele2.ru

HTTP/1.1 401 Unauthorized
Date: Wed, 02 Feb 2011 15:08:17 GMT
Server: Apache/2.2.15 (Win32) mod_ssl/2.2.15 OpenSSL/0.9.8m mod_jk/1.2.30
X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1
WWW-Authenticate: Negotiate TlRMT...
Connection: keep-alive, Keep-Alive
Keep-Alive: timeout=5, max=97
Transfer-Encoding: chunked
Content-Type: text/plain
Proxy-Support: Session-Based-Authentication

------------------------------------------------------------------

3) GET http://www.tst.t2wd.tele2.ru/t2wd/start HTTP/1.1
Accept: image/jpeg, image/gif, image/pjpeg, */*
Referer: http://www.tst.t2wd.tele2.ru/t2wd/error403.jsp
Accept-Language: ru-RU
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727)
Accept-Encoding: gzip, deflate
Cookie: JSESSIONID=C3BEB5AF3983BA259524B2EFA6A1BF23.T2RU-WDAPP-01
Connection: Keep-Alive
Authorization: Negotiate TlRMT...
Host: www.tst.t2wd.tele2.ru


HTTP/1.1 302 Moved Temporarily
Date: Wed, 02 Feb 2011 15:08:17 GMT
Server: Apache/2.2.15 (Win32) mod_ssl/2.2.15 OpenSSL/0.9.8m mod_jk/1.2.30
X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1
Location: http://www.tst.t2wd.tele2.ru/t2wd/base3.zul?page=home
Content-Length: 0
Keep-Alive: timeout=5, max=96
Connection: Keep-Alive
Content-Type: text/plain

------------------------------------------------------------------

4) GET http://www.tst.t2wd.tele2.ru/t2wd/base3.zul?page=home HTTP/1.1
Accept: image/jpeg, image/gif, image/pjpeg, */*
Referer: http://www.tst.t2wd.tele2.ru/t2wd/error403.jsp
Accept-Language: ru-RU
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727)
Accept-Encoding: gzip, deflate
Connection: Keep-Alive
Cookie: JSESSIONID=C3BEB5AF3983BA259524B2EFA6A1BF23.T2RU-WDAPP-01
Host: www.tst.t2wd.tele2.ru

HTTP/1.1 200 OK
Date: Wed, 02 Feb 2011 15:08:17 GMT
Server: Apache/2.2.15 (Win32) mod_ssl/2.2.15 OpenSSL/0.9.8m mod_jk/1.2.30
X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1
Pragma: no-cache
Cache-Control: no-cache
Cache-Control: no-store
Expires: -1
Content-Encoding: gzip
Content-Language: ru-RU
Content-Length: 3790
Keep-Alive: timeout=5, max=95
Connection: Keep-Alive
Content-Type: text/html;charset=UTF-8

------------------------------------------------------------------

5) GET http://www.tst.t2wd.tele2.ru/t2wd/zkau/web/a5f28083/zul/css/zk.wcs HTTP/1.1
Accept: */*
Referer: http://www.tst.t2wd.tele2.ru/t2wd/base3.zul?page=home
Accept-Language: ru-RU
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727)
Accept-Encoding: gzip, deflate
Host: www.tst.t2wd.tele2.ru
Connection: Keep-Alive
Cookie: JSESSIONID=C3BEB5AF3983BA259524B2EFA6A1BF23.T2RU-WDAPP-01

HTTP/1.1 200 OK
Date: Wed, 02 Feb 2011 15:08:17 GMT
Server: Apache/2.2.15 (Win32) mod_ssl/2.2.15 OpenSSL/0.9.8m mod_jk/1.2.30
X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1
Cache-Control: public, max-age=31536000
Expires: Thu, 02 Feb 2012 15:08:17 GMT
Last-Modified: Tue, 01 Feb 2011 20:33:39 GMT
Content-Encoding: gzip
Content-Language: ru-RU
Content-Length: 16309
Keep-Alive: timeout=5, max=94
Connection: Keep-Alive
Content-Type: text/css;charset=UTF-8

------------------------------------------------------------------

6) GET http://www.tst.t2wd.tele2.ru/t2wd/zkau/web/a5f28083/js/zk.wpd HTTP/1.1
Accept: */*
Referer: http://www.tst.t2wd.tele2.ru/t2wd/base3.zul?page=home
Accept-Language: ru-RU
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727)
Accept-Encoding: gzip, deflate
Host: www.tst.t2wd.tele2.ru
Connection: Keep-Alive
Cookie: JSESSIONID=C3BEB5AF3983BA259524B2EFA6A1BF23.T2RU-WDAPP-01
Authorization: Negotiate TlRMT...

HTTP/1.1 401 Unauthorized
Date: Wed, 02 Feb 2011 15:08:17 GMT
Server: Apache/2.2.15 (Win32) mod_ssl/2.2.15 OpenSSL/0.9.8m mod_jk/1.2.30
X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1
WWW-Authenticate: Negotiate TlRMT...
Connection: keep-alive, Keep-Alive
Keep-Alive: timeout=5, max=100
Transfer-Encoding: chunked
Content-Type: application/vnd.wordperfect
Proxy-Support: Session-Based-Authentication

As I understand all authentication negotiations should be performed in requests 1), 2) and 3). What might cause IE8 sent in 6) request that NTLM Authorization header?

Coordinator
Feb 2, 2011 at 4:45 PM

It's possible that the protocol chosen is NTLM, in which case this is a connection-oriented authentication an not session-oriented one. So before 6) (say in 5)) the browser decided to open a new TCP/IP connection, which required a new handshake. A netmon trace would show that.

Feb 3, 2011 at 2:52 PM

Sometimes, our AJAX requests (js, images, css) leads to login dialog popup (HTTP trace one of the situation is above).

I've checked Tomcat's log (below). Here two threads (-0.0.0.0-8009-5 and -0.0.0.0-8009-2) operates on behalf of the same connection id (10.77.252.232:-1). Is it possible that I got concurrency issue here?

 

2011-02-03 18:24:00,154 INFO  (-0.0.0.0-8009-2) [ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter] GET /t2wd/zkau/web/a5f28083/zul/img/wnd/wnd-corner.png, contentlength: 0
2011-02-03 18:24:00,154 INFO  (-0.0.0.0-8009-2) [waffle.servlet.spi.NegotiateSecurityFilterProvider] security package: NTLM, connection id: 10.77.252.232:-1
2011-02-03 18:24:00,154 INFO  (-0.0.0.0-8009-2) [waffle.servlet.spi.NegotiateSecurityFilterProvider] token buffer: 40 byte(s)
2011-02-03 18:24:00,154 INFO  (-0.0.0.0-8009-5) [ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter] GET /t2wd/zkau/web/a5f28083/zul/img/wnd/wnd-hl.png, contentlength: 0
2011-02-03 18:24:00,154 INFO  (-0.0.0.0-8009-5) [waffle.servlet.spi.NegotiateSecurityFilterProvider] security package: NTLM, connection id: 10.77.252.232:-1
2011-02-03 18:24:00,154 INFO  (-0.0.0.0-8009-5) [waffle.servlet.spi.NegotiateSecurityFilterProvider] token buffer: 40 byte(s)
2011-02-03 18:24:00,154 WARN  (-0.0.0.0-8009-2) [ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter] Cant login user by header: NTLM TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAGAbAdAAAADw==
com.sun.jna.platform.win32.Win32Exception: The token supplied to the function is invalid

	at waffle.windows.auth.impl.WindowsAuthProviderImpl.acceptSecurityToken(Unknown Source)
	at waffle.servlet.spi.NegotiateSecurityFilterProvider.doFilter(Unknown Source)
	at waffle.servlet.spi.SecurityFilterProviderCollection.doFilter(Unknown Source)
	at ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter.doFilter(NegotiateSecurityFilter.java:74)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:187)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:79)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:169)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:419)
	at org.apache.coyote.ajp.AjpAprProtocol$AjpConnectionHandler.process(AjpAprProtocol.java:402)
	at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:2036)
	at java.lang.Thread.run(Thread.java:619)
2011-02-03 18:24:00,154 DEBUG (-0.0.0.0-8009-2) [ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter] sendUnauthorized(close=true)
2011-02-03 18:24:00,154 DEBUG (-0.0.0.0-8009-2) [org.springframework.security.web.context.HttpSessionSecurityContextRepository] SecurityContext is empty or anonymous - context will not be stored in HttpSession. 
2011-02-03 18:24:00,154 DEBUG (-0.0.0.0-8009-2) [org.springframework.security.web.context.SecurityContextPersistenceFilter] SecurityContextHolder now cleared, as request processing completed
2011-02-03 18:24:00,154 WARN  (-0.0.0.0-8009-5) [ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter] Cant login user by header: NTLM TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAGAbAdAAAADw==
com.sun.jna.platform.win32.Win32Exception: The handle specified is invalid

	at waffle.windows.auth.impl.WindowsSecurityContextImpl.dispose(Unknown Source)
	at waffle.windows.auth.impl.WindowsAuthProviderImpl.acceptSecurityToken(Unknown Source)
	at waffle.servlet.spi.NegotiateSecurityFilterProvider.doFilter(Unknown Source)
	at waffle.servlet.spi.SecurityFilterProviderCollection.doFilter(Unknown Source)
	at ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter.doFilter(NegotiateSecurityFilter.java:74)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:187)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:79)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:169)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:419)
	at org.apache.coyote.ajp.AjpAprProtocol$AjpConnectionHandler.process(AjpAprProtocol.java:402)
	at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:2036)
	at java.lang.Thread.run(Thread.java:619)
2011-02-03 18:24:00,154 DEBUG (-0.0.0.0-8009-5) [ru.massmo.common.security.authentication.waffle.NegotiateSecurityFilter] sendUnauthorized(close=true)
2011-02-03 18:24:00,154 DEBUG (-0.0.0.0-8009-5) [org.springframework.security.web.context.HttpSessionSecurityContextRepository] SecurityContext is empty or anonymous - context will not be stored in HttpSession. 
2011-02-03 18:24:00,154 DEBUG (-0.0.0.0-8009-5) [org.springframework.security.web.context.SecurityContextPersistenceFilter] SecurityContextHolder now cleared, as request processing completed

 

I.e this two different requests from the same client:

GET /t2wd/zkau/web/a5f28083/zul/img/wnd/wnd-corner.png
GET /t2wd/zkau/web/a5f28083/zul/img/wnd/wnd-hl.png

make race condition for WindowsAuthProviderImpl._continueContexts and Ntlm session?

Coordinator
Feb 4, 2011 at 4:12 AM

This looks wrong. The connection id shouldn't be -1 - it means that the server couldn't figure out what port the connection is on. That's how WAFFLE distinguishes between connections, so this can't work. Are you looking at the code? Looks like request.getRemotePort() is not returning a number.

Feb 4, 2011 at 6:58 AM

We are behind Apache. Found this in Apache-Tomcat's connector doc (http://tomcat.apache.org/connectors-doc/generic_howto/proxy.html):

The remote port number has been forgotten in the AJP13 protocol.

So getRemotePort() will incorrectly return 0 or -1. As a workaround you can forward the remote port by setting JkEnvVar REMOTE_PORT and then either using request.getAttribute("REMOTE_PORT") instead of getRemotePort() or wrapping the request in a filter and overriding getRemotePort() with request.getAttribute("REMOTE_PORT"). Recent versions of Tomcat might automatically respect the forwarded attribute REMOTE_PORT.

Ok, we will try mentioned workaround.

 

Feb 4, 2011 at 1:02 PM
Edited Feb 4, 2011 at 1:18 PM

Arhhh! Now I see that I got first request after commence on 61548 port and next request that should answer on challenge from first request on another 61549 port!

2011-02-04 16:51:53,048 DEBUG (  TP-Processor3) [rityFilterEntryPoint] [waffle.spring.NegotiateEntryPoint] commence
2011-02-04 16:51:53,050 DEBUG (  TP-Processor3) [ityContextRepository] SecurityContext is empty or anonymous - context will not be stored in HttpSession. 
2011-02-04 16:51:53,050 DEBUG (  TP-Processor3) [extPersistenceFilter] SecurityContextHolder now cleared, as request processing completed
2011-02-04 16:51:53,070 DEBUG (  TP-Processor3) [web.FilterChainProxy] Converted URL to lowercase, from: '/index.jsp'; to: '/index.jsp'
2011-02-04 16:51:53,070 DEBUG (  TP-Processor3) [web.FilterChainProxy] Candidate is: '/index.jsp'; pattern is /**; matched=true
2011-02-04 16:51:53,071 DEBUG (  TP-Processor3) [web.FilterChainProxy] /index.jsp at position 1 of 8 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
2011-02-04 16:51:53,071 DEBUG (  TP-Processor3) [ityContextRepository] HttpSession returned null object for SPRING_SECURITY_CONTEXT
2011-02-04 16:51:53,071 DEBUG (  TP-Processor3) [ityContextRepository] No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@55d7fc31. A new one will be created.
2011-02-04 16:51:53,071 DEBUG (  TP-Processor3) [web.FilterChainProxy] /index.jsp at position 2 of 8 in additional filter chain; firing Filter: 'NegotiateSecurityFilter'
2011-02-04 16:51:53,071 INFO  (  TP-Processor3) [otiateSecurityFilter] GET /waffle-spring-filter/, contentlength: 0
2011-02-04 16:51:53,073 DEBUG (  TP-Processor3) [curityFilterProvider] security package: NTLM, connection id: 10.77.252.227:61548
2011-02-04 16:51:53,075 DEBUG (  TP-Processor3) [curityFilterProvider] token buffer: 57 byte(s)
2011-02-04 16:51:53,221 DEBUG (  TP-Processor3) [curityFilterProvider] continue token: TlRMT....
2011-02-04 16:51:53,222 DEBUG (  TP-Processor3) [curityFilterProvider] continue required: true
2011-02-04 16:51:53,222 DEBUG (  TP-Processor3) [ityContextRepository] SecurityContext is empty or anonymous - context will not be stored in HttpSession. 
2011-02-04 16:51:53,222 DEBUG (  TP-Processor3) [extPersistenceFilter] SecurityContextHolder now cleared, as request processing completed
2011-02-04 16:51:53,235 DEBUG (  TP-Processor3) [web.FilterChainProxy] Converted URL to lowercase, from: '/index.jsp'; to: '/index.jsp'
2011-02-04 16:51:53,235 DEBUG (  TP-Processor3) [web.FilterChainProxy] Candidate is: '/index.jsp'; pattern is /**; matched=true
2011-02-04 16:51:53,235 DEBUG (  TP-Processor3) [web.FilterChainProxy] /index.jsp at position 1 of 8 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
2011-02-04 16:51:53,235 DEBUG (  TP-Processor3) [ityContextRepository] HttpSession returned null object for SPRING_SECURITY_CONTEXT
2011-02-04 16:51:53,236 DEBUG (  TP-Processor3) [ityContextRepository] No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@55d7fc31. A new one will be created.
2011-02-04 16:51:53,236 DEBUG (  TP-Processor3) [web.FilterChainProxy] /index.jsp at position 2 of 8 in additional filter chain; firing Filter: 'NegotiateSecurityFilter'
2011-02-04 16:51:53,236 INFO  (  TP-Processor3) [otiateSecurityFilter] GET /waffle-spring-filter/, contentlength: 0
2011-02-04 16:51:53,236 DEBUG (  TP-Processor3) [curityFilterProvider] security package: NTLM, connection id: 10.77.252.227:61549
2011-02-04 16:51:53,236 DEBUG (  TP-Processor3) [curityFilterProvider] token buffer: 88 byte(s)
2011-02-04 16:51:53,281 WARN  (  TP-Processor3) [otiateSecurityFilter] error logging in user: The token supplied to the function is invalid

2011-02-04 16:51:53,281 DEBUG (  TP-Processor3) [ityContextRepository] SecurityContext is empty or anonymous - context will not be stored in HttpSession. 
2011-02-04 16:51:53,282 DEBUG (  TP-Processor3) [extPersistenceFilter] SecurityContextHolder now cleared, as request processing completed

So user never passes authentication!

 

Coordinator
Feb 4, 2011 at 1:04 PM

This has to remain on a keep-alive connection, that's just what the protocol requires. The server should be saying Connection: Keep-alive in the right places and Connection: close in the others. I don't know how to tell AJP to respect that. Why are you using AJP anyway?

Feb 4, 2011 at 4:26 PM

Problem was in that our Apache closed all requests. Described here: http://httpd.apache.org/docs/2.0/ssl/ssl_faq.html, "Why do I get I/O errors when connecting via HTTPS to an Apache+mod_ssl server with Microsoft Internet Explorer (MSIE)?"

Coordinator
Feb 4, 2011 at 4:27 PM

Good. What exactly did you change?

Feb 4, 2011 at 7:03 PM

There is a default Apache settings to better support IE<=5.5 that disables keepalives in SSL for all MSIE browsers. It is there for years and usually doesn't brake anything. Removing it has elimenated the problem.

SetEnvIf User-Agent ".*MSIE.*" \
nokeepalive ssl-unclean-shutdown \
downgrade-1.0 force-response-1.0