NTLM authorization error when starting NTLM handshake: Status: 0x80090308; SubStatus: 0x0; FailureReason: %%2304.

[Kalbek Bykapov]

Hi. We experiencing problems with NTLM authorization. Current configuration: Apache Http Server+Tomcat+Spring + waffle NegotiateSecurotyFilterProvider. Tomcat is running as a service under system account.

<bean name="NegotiateSecurityFilterProvider" class="waffle.servlet.spi.NegotiateSecurityFilterProvider">

    <constructor-arg ref="waffleauthprovider"/>

    <property name="protocols">

        <util:list>

    <value>NTLM</value>

</util:list>

    </property>

</bean>

We forced NTLM protocol earlier due to configuration complications introduced by Kerberos. Issue was reproduced on waffle versions 1.8.1 and then on 1.7.5. 

First, user requests some page and recieves  401 status + "NTLM" header (last two logged headers are "Authorization" sent by client and "WWW-Authenticate" responded by server): 

[29/Jul/2016:14:54:00 +0300] "GET /mira/ HTTP/1.1" 401 - "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E; InfoPath.3)"  "-"  "NTLM"

So browser makes next request with NTLM type 1 message:

[29/Jul/2016:14:54:00 +0300] "GET /mira/ HTTP/1.1" 401 - "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E; InfoPath.3)"  "NTLM TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw=="  "NTLM" 

Waffle now makes Secur32.dll native call in waffle.windows.auth.impl.WindowsAuthProviderImpl#acceptSecurityToken method. And result is the following error, so we send 401 status and "NTLM" header back to the client again. That causes browser to show popup window asking for credentials. 

http-bio-8080-exec-14#localhost 2016-07-29 15:54:00.714 [http://10.33.10.28/mira guest 10.66.20.43] DEBUG(waffle.servlet.spi.NegotiateSecurityFilterProvider): security package: NTLM, connection id: 127.0.0.1:61320
http-bio-8080-exec-14#localhost 2016-07-29 15:54:00.714 [http://10.33.10.28/mira guest 10.66.20.43] DEBUG(waffle.servlet.spi.NegotiateSecurityFilterProvider): token buffer: 40 byte(s)
http-bio-8080-exec-14#localhost 2016-07-29 15:54:00.714 [http://10.33.10.28/mira guest 10.66.20.43] WARN(lms.system.access.waffle.NTLMAuthenticationService): Error on get Identity
java.io.IOException: com.sun.jna.platform.win32.Win32Exception: The token supplied to the function is invalid
        at waffle.servlet.spi.SecurityFilterProviderCollection.doFilter(SecurityFilterProviderCollection.java:150)
        at lms.system.access.waffle.NTLMAuthenticationService.getIdentity(NTLMAuthenticationService.java:263)
        at lms.system.access.waffle.NTLMAuthenticationService.logInWithNTLM(NTLMAuthenticationService.java:182)
        at lms.system.access.waffle.NTLMAuthenticationService.isAuthenticated(NTLMAuthenticationService.java:163)
        at org.mirapolis.mvc.FilterServlet.processChain(FilterServlet.java:97)
        at org.mirapolis.mvc.FilterServlet.access$000(FilterServlet.java:30)
        at org.mirapolis.mvc.FilterServlet$1.run(FilterServlet.java:71)
        at org.mirapolis.mvc.FilterServlet$2.run(FilterServlet.java:133)
        at org.mirapolis.core.Context.runInUserContext(Context.java:470)
        at org.mirapolis.mvc.FilterServlet.runInContext(FilterServlet.java:130)
        at org.mirapolis.mvc.FilterServlet.doFilter(FilterServlet.java:67)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.logging.log4j.core.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:66)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:315)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)
Caused by: com.sun.jna.platform.win32.Win32Exception: The token supplied to the function is invalid
        at waffle.windows.auth.impl.WindowsAuthProviderImpl.acceptSecurityToken(WindowsAuthProviderImpl.java:170)
        at waffle.servlet.spi.NegotiateSecurityFilterProvider.doFilter(NegotiateSecurityFilterProvider.java:144)
        at waffle.servlet.spi.SecurityFilterProviderCollection.doFilter(SecurityFilterProviderCollection.java:148)
        ... 29 more

There is some more info about error in windows event log:

 <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name="Microsoft-Windows-Security-Auditing" Guid="{54849625-5478-4994-A5BA-3E3B0328C30D}" /> 
  <EventID>4625</EventID> 
  <Version>0</Version> 
  <Level>0</Level> 
  <Task>12544</Task> 
  <Opcode>0</Opcode> 
  <Keywords>0x8010000000000000</Keywords> 
  <TimeCreated SystemTime="2016-07-29T11:54:00.714207700Z" /> 
  <EventRecordID>67620</EventRecordID> 
  <Correlation /> 
  <Execution ProcessID="552" ThreadID="4700" /> 
  <Channel>Security</Channel> 
  <Computer>***</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data Name="SubjectUserSid">S-1-0-0</Data> 
  <Data Name="SubjectUserName">-</Data> 
  <Data Name="SubjectDomainName">-</Data> 
  <Data Name="SubjectLogonId">0x0</Data> 
  <Data Name="TargetUserSid">S-1-0-0</Data> 
  <Data Name="TargetUserName" /> 
  <Data Name="TargetDomainName" /> 
  <Data Name="Status">0x80090308</Data> 
  <Data Name="FailureReason">%%2304</Data> 
  <Data Name="SubStatus">0x0</Data> 
  <Data Name="LogonType">3</Data> 
  <Data Name="LogonProcessName" /> 
  <Data Name="AuthenticationPackageName">NTLM</Data> 
  <Data Name="WorkstationName" /> 
  <Data Name="TransmittedServices">-</Data> 
  <Data Name="LmPackageName">-</Data> 
  <Data Name="KeyLength">0</Data> 
  <Data Name="ProcessId">0x0</Data> 
  <Data Name="ProcessName">-</Data> 
  <Data Name="IpAddress">-</Data> 
  <Data Name="IpPort">-</Data> 
  </EventData>
  </Event>

I googled this error and cannot find nothing helpful.

Next, user closes popup window and reloads the page. And now authorization works well:

10.33.10.28:50010 10.66.20.43 - - [29/Jul/2016:14:55:05 +0300] "GET /mira/ HTTP/1.1" 401 - "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E; InfoPath.3)"  "-"  "NTLM" 

10.33.10.28:50010 10.66.20.43 - - [29/Jul/2016:14:55:05 +0300] "GET /mira/ HTTP/1.1" 401 - "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E; InfoPath.3)"  "NTLM TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw=="  "NTLM TlRMTVNTUAACAAAABAAEADgAAAAFgomiXh1rMMBdwfEAAAAAAAAAAJgAmAA8AAAABgOAJQAAAA9IAFEAAgAEAEgAUQABABwAUgBHAE0ALQBUAFMALQBXAEUAQgBBAFAAMAA1AAQAFABIAFEALgBSAE8ATwBUAC4AQQBEAAMAMgByAGcAbQAtAHQAcwAtAHcAZQBiAGEAcAAwADUALgBIAFEALgBSAE8ATwBUAC4AQQBEAAUADgBSAE8ATwBUAC4AQQBEAAcACADI8hwMkOnRAQAAAAA=" 
10.33.10.28:50010 10.66.20.43 - - [29/Jul/2016:14:55:05 +0300] "GET /mira/ HTTP/1.1" 200 4866 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E; InfoPath.3)"  "NTLM TlRMTVNTUAADAAAAGAAYAJQAAABAAUABrAAAAAQABABYAAAAGgAaAFwAAAAeAB4AdgAAAAAAAADsAQAABYKIogYBsR0AAAAP3NZFLY1QyRGXdWexLCt2F0gAUQBWAGkAcwBoAG4AZQB2AHMAawBpAHkATQBBAFIARwBNAC0AVgBEAC0AVwA3AEEASQAtADAAMgA4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAKvRdClq7C4h75hzNtUWJtcBAQAAAAAAAMjyHAyQ6dEBWurKz3Oy7BEAAAAAAgAEAEgAUQABABwAUgBHAE0ALQBUAFMALQBXAEUAQgBBAFAAMAA1AAQAFABIAFEALgBSAE8ATwBUAC4AQQBEAAMAMgByAGcAbQAtAHQAcwAtAHcAZQBiAGEAcAAwADUALgBIAFEALgBSAE8ATwBUAC4AQQBEAAUADgBSAE8ATwBUAC4AQQBEAAcACADI8hwMkOnRAQYABAAGAAAACAAwADAAAAAAAAAAAQAAAAAgAACLHmnMubKY4bsBUuk9T6z/cV9tnpa49rtfKiyXjYcy9goAEAAAAAAAAAAAAAAAAAAAAAAACQAgAEgAVABUAFAALwAxADAALgAzADMALgAxADAALgAyADgAAAAAAAAAAAAAAAAA"  "-"

Type 1 message is exactly the same as in first attempt, but now native call succeeds and status 200 is returned. User agent is IE 11, but issue also reproduced in chrome. Browser configuration is OK. 

First time we reproduced it it in version 1.8.1, so we decided it can be related to this IWindowsCredentialsHandle-reuse issue: https://github.com/dblock/waffle/issues/268. After downgrade it's still there, but now with another user.

Do you have any ideas what might it be and where to look at? 

Thanks.

[Daniel Doubrovkine]

Unfortunately, as you know by now, these "token supplied to the function is invalid" errors aren't very helpful. It's a generic "this doesn't work". 

It's possible that this has something to do with concurrent requests, but I wouldn't be so sure. Either way I'd be looking for a more repeatable pattern. Sorry I cannot be more helpful :(

--
You received this message because you are subscribed to the Google Groups "waffle" group.
To unsubscribe from this group and stop receiving emails from it, send an email to waffle-users...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

dB. | Moscow - Geneva - Seattle - New York
code.dblock.org - @dblockdotorg - artsy.net - github/dblock

[Kodanda Ramaiah Kolluri]

I have been into similar situation spent hell lot of time where solution is simple. do you have multiple tomcat servers or one behind your http server? if you have multiple try testing with one running and rest shutdown.

Thanks

Ram

[Kalbek Bykapov]

No, there's currently only one tomcat.

--
You received this message because you are subscribed to a topic in the Google Groups "waffle" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/waffle-users/ADLS9_klbNQ/unsubscribe.
To unsubscribe from this group and all its topics, send an email to waffle-users+unsubscribe@googlegroups.com.