Can a cas server configured spnego authentication support nginx forwarding?

[Roman Brown]

Hello,

CAS Version: 5.1, 

Deployment:  

1. CAS server: By build a WAR overlay project which contains spnego configurations. And deployed  the cas.war on apache-tomcat-9.0.37. cas runs on OS: Linux（Red Hat 7.5) (kerberos installed and configured).

2. kdc(AD domain controller): windows server 2012.

3. client: windows 10 Professional, joined the AD domain.

4. nginx reverse proxy: nginx/1.16.1 (runs on Red Hat 7.5)

Problem description:

First, without nginx, when I accessed cas server directly, I can see the login success page directly without entering username or password. Or when I accessed an application which had been remoulded to a cas client(as well a kdc client) , I can access it directly without login. That is I realized the spnego feature.

But, considering hign availability, I need to deploy a cas cluster. Before cluster deployment, I conducted a test with one nginx server and one cas server, to test if some problems will  appear when HTTP requests were fowarded by nginx. Then, problems appeared. Spnego didn't work, I got the login page. The architecture is like this:

client->nginx->cas server->kdc, nginx is a single node, cas server is also a single node, kdc is also a single node.

By combining the nginx log and the cas log,  it looks like cas get a wrong spnego token which is decoded from the authorization header. But I have no idea that why cas get a wrong token.

cas log:

I tuned the cas log level to debug, and the error log is:

2020-10-15 12:11:01,538 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'startSpnegoAuthenticate' of flow 'login'>

2020-10-15 12:11:01,538 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@52a9f67a expression = negociateSpnego, resultExpression = [null]]>

2020-10-15 12:11:01,538 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1eab5ae5>

2020-10-15 12:11:01,538 DEBUG [org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction] - <Authorization header [Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAO5CAAAADw==], User Agent header [Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36]>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1eab5ae5; result = success>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@52a9f67a expression = negociateSpnego, resultExpression = [null]]; result = success>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@20916eb1 on = success, to = spnego]>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'startSpnegoAuthenticate'>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'spnego' of flow 'login'>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@643b792 expression = spnego, resultExpression = [null]]>

2020-10-15 12:11:01,539 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoCredentialsAction@288b9d98>

2020-10-15 12:11:01,540 DEBUG [org.apereo.cas.web.flow.SpnegoCredentialsAction] - <SPNEGO Authorization header located as [Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAO5CAAAADw==]>

2020-10-15 12:11:01,541 DEBUG [org.apereo.cas.web.flow.SpnegoCredentialsAction] - <SPNEGO Authorization header found with [56] bytes>

2020-10-15 12:11:01,543 DEBUG [org.apereo.cas.web.flow.SpnegoCredentialsAction] - <Obtained token: [NTLMSSP  ?? B ?].Creating SPNEGO credential...>

2020-10-15 12:11:04,047 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Located client IP address as [172.28.5.156]>

2020-10-15 12:11:04,048 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <User agent [Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36] is authorized to proceed>

2020-10-15 12:11:04,048 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Adaptive authentication policy has authorized client [172.28.5.156] to proceed.>

2020-10-15 12:11:04,049 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>

2020-10-15 12:11:04,050 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Located ticket-granting ticket [null] from the request context>

2020-10-15 12:11:04,051 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Located service [null] from the request context>

2020-10-15 12:11:04,052 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Provided value for [renew] request parameter is [null]>

2020-10-15 12:11:04,052 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Request is not eligible to be issued service tickets just yet>

2020-10-15 12:11:04,053 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>

2020-10-15 12:11:04,070 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [Active DirectoryJcifsSpnegoAuthenticationHandlerHttpBasedServiceCredentialsAuthenticationHandler]>

2020-10-15 12:11:07,822 DEBUG [org.apereo.cas.support.spnego.authentication.handler.support.JcifsSpnegoAuthenticationHandler] - <Processing SPNEGO authentication>

2020-10-15 12:11:07,823 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <[JcifsSpnegoAuthenticationHandler] failed authenticating [unknown]>

2020-10-15 12:11:07,828 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <[JcifsSpnegoAuthenticationHandler] exception details: [Error performing NTLM authentication: java.net.UnknownHostException: CAS.TEST.COM  #<1C>]>

2020-10-15 12:11:07,829 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <[JcifsSpnegoAuthenticationHandler] failed authenticating [unknown]>

2020-10-15 12:11:07,830 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <[JcifsSpnegoAuthenticationHandler] exception details: [Error performing NTLM authentication: java.net.UnknownHostException: CAS.TEST.COM  #<1C>]>

2020-10-15 12:11:07,835 WARN [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication has failed. Credentials may be incorrect or CAS cannot find authentication handler that supports [unknown] of type [SpnegoCredential], which suggests a configuration problem.>

2020-10-15 12:11:07,836 WARN [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication has failed. Credentials may be incorrect or CAS cannot find authentication handler that supports [unknown] of type [SpnegoCredential], which suggests a configuration problem.>

nginx log:

the relevant log of nginx:

2020/10/15 12:13:53 [debug] 22689#0: *103 http process request header line
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Host: nginx.test.com:9991"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Connection: keep-alive"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Authorization: Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAO5CAAAADw=="
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Upgrade-Insecure-Requests: 1"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Purpose: prefetch"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Accept-Encoding: gzip, deflate"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header: "Accept-Language: zh-CN,zh;q=0.9"
2020/10/15 12:13:53 [debug] 22689#0: *103 http header done
2020/10/15 12:13:53 [debug] 22689#0: *103 generic phase: 0
2020/10/15 12:13:53 [debug] 22689#0: *103 rewrite phase: 1
2020/10/15 12:13:53 [debug] 22689#0: *103 test location: "/"
2020/10/15 12:13:53 [debug] 22689#0: *103 using configuration "/"
2020/10/15 12:13:53 [debug] 22689#0: *103 http cl:-1 max:1048576000
2020/10/15 12:13:53 [debug] 22689#0: *103 rewrite phase: 3
2020/10/15 12:13:53 [debug] 22689#0: *103 post rewrite phase: 4
2020/10/15 12:13:53 [debug] 22689#0: *103 generic phase: 5
2020/10/15 12:13:53 [debug] 22689#0: *103 generic phase: 6
2020/10/15 12:13:53 [debug] 22689#0: *103 generic phase: 7
2020/10/15 12:13:53 [debug] 22689#0: *103 access phase: 8
2020/10/15 12:13:53 [debug] 22689#0: *103 access phase: 9
2020/10/15 12:13:53 [debug] 22689#0: *103 access phase: 10
2020/10/15 12:13:53 [debug] 22689#0: *103 post access phase: 11
2020/10/15 12:13:53 [debug] 22689#0: *103 generic phase: 12
2020/10/15 12:13:53 [debug] 22689#0: *103 generic phase: 13
2020/10/15 12:13:53 [debug] 22689#0: *103 http init upstream, client timer: 0
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: "X-Forwarded-For"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script var: "172.28.28.178"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: "X-Real-IP"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script var: "172.28.28.178"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: "Host"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script var: "nginx.test.com:9991"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: "Connection"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: "close"
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: ""
2020/10/15 12:13:53 [debug] 22689#0: *103 http script copy: ""
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "Authorization: Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAO5CAAAADw=="
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "Upgrade-Insecure-Requests: 1"
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36"
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "Purpose: prefetch"
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "Accept-Encoding: gzip, deflate"
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header: "Accept-Language: zh-CN,zh;q=0.9"
2020/10/15 12:13:53 [debug] 22689#0: *103 http proxy header:
"GET /cas/login HTTP/1.0


X-Forwarded-For: 172.28.28.178


X-Real-IP: 172.28.28.178


Host: nginx.test.com:9991


Connection: close


Authorization: Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAO5CAAAADw==


Upgrade-Insecure-Requests: 1


User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36


Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9


Purpose: prefetch


Accept-Encoding: gzip, deflate


Accept-Language: zh-CN,zh;q=0.9






"
2020/10/15 12:13:53 [debug] 22689#0: *103 http cleanup add: 00000000008B1F78
2020/10/15 12:13:53 [debug] 22689#0: *103 get rr peer, try: 1
2020/10/15 12:13:53 [debug] 22689#0: *103 stream socket 14
2020/10/15 12:13:53 [debug] 22689#0: *103 epoll add connection: fd:14 ev:80002005
2020/10/15 12:13:53 [debug] 22689#0: *103 connect to 172.28.5.146:8080, fd:14 #109
2020/10/15 12:13:53 [debug] 22689#0: *103 http upstream connect: -2
2020/10/15 12:13:53 [debug] 22689#0: *103 posix_memalign: 00000000008680C0:128 @16
2020/10/15 12:13:53 [debug] 22689#0: *103 event timer add: 14: 60000:4502709212
2020/10/15 12:13:53 [debug] 22689#0: *103 http finalize request: -4, "/cas/login?" a:1, c:2
2020/10/15 12:13:53 [debug] 22689#0: *103 http request count:2 blk:0
2020/10/15 12:13:53 [debug] 22689#0: *103 http run request: "/cas/login?"
2020/10/15 12:13:53 [debug] 22689#0: *103 http upstream check client, write event:1, "/cas/login"
2020/10/15 12:13:53 [debug] 22689#0: timer delta: 98
2020/10/15 12:13:53 [debug] 22689#0: worker cycle
2020/10/15 12:13:53 [debug] 22689#0: epoll timer: 60000
2020/10/15 12:13:53 [debug] 22689#0: epoll: fd:14 ev:0004 d:00007FA77C2E8790
2020/10/15 12:13:53 [debug] 22689#0: *103 http upstream request: "/cas/login?"
2020/10/15 12:13:53 [debug] 22689#0: *103 http upstream send request handler
2020/10/15 12:13:53 [debug] 22689#0: *103 http upstream send request
2020/10/15 12:13:53 [debug] 22689#0: *103 http upstream send request body
2020/10/15 12:13:53 [debug] 22689#0: *103 chain writer buf fl:1 s:597
2020/10/15 12:13:53 [debug] 22689#0: *103 chain writer in: 00000000008B1FB8
2020/10/15 12:13:53 [debug] 22689#0: *103 writev: 597 of 597
2020/10/15 12:13:53 [debug] 22689#0: *103 chain writer out: 0000000000000000
2020/10/15 12:13:53 [debug] 22689#0: *103 event timer del: 14: 4502709212
2020/10/15 12:13:53 [debug] 22689#0: *103 event timer add: 14: 3600000:4506249215

My analysis:

The client obtained a service ticket from kdc already, and the client sended the spnego token(i.e. the http authorization header) to nginx. Nginx forwarded the request to cas server. So, Nginx forwaded the request that carried the spnego token already, the authorization header was also forwarded. The cas server also received the request which contains the spnego token already.

But the spnego token that is obtained from kdc is wrong.

The correct spnego token is like this(When a client access cas server directly,without nginx, the spnego token the cas server obtained is correct ): 

and the correct authorization header is long enough:

2020-10-14 11:56:26,302 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoCredentialsAction@381eab18>

2020-10-14 11:56:26,302 DEBUG [org.apereo.cas.web.flow.SpnegoCredentialsAction] - <SPNEGO Authorization header located as [Negotiate YIIGXgYGKwYBBQUCoIIGUjCCBk6gMDAuBgkqhkiC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHgYKKwYBBAGCNwICCqKCBhgEggYUYIIGEAYJKoZIhvcSAQICAQBuggX/MIIF+6ADAgEFoQMCAQ6iBwMFACAAAACjggRLYYIERzCCBEOgAwIBBaEKGwhURVNULkNPTaIfMB2gAwIBAqEWMBQbBEhUVFAbDGNhcy50ZXN0LmNvbaOCBA0wggQJoAMCARehAwIBBqKCA/sEggP3jLzYsT7ktodtwO886WRH/OfAZCy8Yz5SxoyWO4bC0mI+IV+lrFlKDu3wwxorPb6QGi1GKcSwAmaWIAodb4rcDrguWLtUe2yOSgX/O0lFKg1CKxLLLYUKTWG0yjdWtOUcUPsn9quZw6bvAuYnb+SHVzH/Zk0MxHyR7pO6RbFiHAyRUFfLjMRj1KOHFwPIaY7kSEQC4gPRGYxn6umg45k7BLVXhCP/dl6WGm44GT+dZSgNFhgWYH5QMEFIY9cbW3Ac4glq2SsdOcdMVIBjtTd5VbAz9O5Z5XwcjXbL/tqcDfBo6hr0NwN0KGsE1ODFi8tXpYYWzmzZjRM3FNZu4AeZUwRgoJPD8yBfgYSX/U+f2k5zwCmgHAvn1/gvL0p+qj75kV2FmK4vL6UaGSd19GOFq1J4nBZLUVMaCpBEHb1r9O9IddND/pmUcrw5OUS2x39DbgEEXXivNSD9oFx0fJrKKY+VKEcWMYKR73iBoXJle4sR1gpt0J4K5XKDyi5Htgdni+f4OVT02YzcRzNo/9Hjc67lQ7ZR8I/B9Yh84wGx0rNPkE8xeybN/fChPIr/ShMcQ0b7kG853uUY7wbzHjiKewk/Kxg+T8a4Sv+lLf5oJBD1vh05dNdrKTYA2365TsbU8t3GyKp9+86Hy4mB8kcrMYXvLnhcZ2nXxG23m+xROOgSUDsw/62XJ5ioATIXWNKStRC3W3OUtjxKNbX1N+lg7JKcBrIpJom2eWpYGb7RawFL4c5KGOFzFVeWL0isMfMnJ/0Ms769Yu0zQvn8zVHzbG3/DzUcS1VSiPZ9yX+PrVvV1gsny8ujCKE01al9p/8MLURtqkVzdDnKrENh+kV2Kr88YKHVEVLEDigDepdaZI3tbEFFEQ9ZLbecCXNcCqi+in4p3IOsDA27wdI+JV6FST5Y4/Lubbj11gSvbZDKc7OrttUNTkpDWu4tBEftx7N7k2qDAFD7UNRKptb6+Cd9x52IPZGm3PMqUl/MYydYEyQrtCQ/JGd1w9rHLkhgk+7WEyh0Hef+chE0O0v5kUpv8kGvX/udCU6K9Su4Ejr0saCgs/9lddK/MkavJrgAKwzL2jWeZTdqgI2Cg1KAj12SYBcb/URNRUDddd2HjDET9a8NReATNXcnL21HvBHTMA4FX7QheGRrM9JhJXh+5+7wSRdM0Y1zUQDYJrwdiCFCoN7Ot3qf97kXRAc1Vj24a5a5dIXVLNRy8hzykIEohoeGYkVTsaUCAmMl4Ev0zdk7VwlNg6igQH1pv5G0mKYUo9/mq69L7CO3dwNqUhMLSIn8Axj+VItxxf8Msv6dzcTga2eFLa64H2jIFNxDWj0ujGah9OZCfq9qH6SCAZUwggGRoAMCAReiggGIBIIBhBXCMBUR/B4e3VitNUAbo5p6Yy6GxOPdyITHLVNml7v0ckXLCcW4iCxHTuC17lvWRbbYIW7h8GQ27zubgTuaZJK7AOKqRuIUnlymUKTEDwy4TWS0ctTVk1lEdzrQM3f9k1VjIL06lsvvHkxCv9sTSKttyoQDjM9UP4qQnfrrAvEiniJmv/TovT65scZRaKfjan0kdR51PjN1uBPfSIgIlDxtOP2mpLTjrbZA2Jr0YP0uJ1gnSycgwkwTnQYGiGRcHns9YwZr+yICyuIemQ+RM6Jb4/X3uI/MgkeuM+Xqv9r6HXjbugqrUGc+s9ufbaG3PUCFJ+cC4zO/DN8DAQ4RSkUhu/uQgS+6OXf9DqKczRIqNrdiFfFNbFtoulZdvH9XYUl6Lm0IXVImDGvxgBccJpQbwu9GZbLo0C8V9tWJwdU0YsQp+SyZe7+9SBYvRHXzYTURXUJrUmxtFt6mmsiYu6zjh4c+mBwfPv8wdVaKNa/wtGb3vZ1EwerkcPFbY9Aa1vHK7oI=]>

2020-10-14 11:56:26,303 DEBUG [org.apereo.cas.web.flow.SpnegoCredentialsAction] - <SPNEGO Authorization header found with [2180] bytes>

Can anyone suggest what might be the issue? Or if a cas server configured spnego supports cluster deployment?

Thanks And Regards,

Roman Brown

[Ritesh Tripathi]

Hi Roman

Were able to successfully configure the SPNEGO authentication?

Best Regards

Ritesh