Hmm, SPNEGO not playing nicely THIS TIME

So I'm seeing a blank screen where I should be seeing a BPM Process Portal, and am seeing this in the AppCluster logs: -

...

[25/04/18 13:53:12:228 BST] 00000194 ServerCache   I   DYNA1001I: WebSphere Dynamic Cache instance named ws/WSSecureMapNotShared initialized successfully.

[25/04/18 13:53:12:230 BST] 00000194 ServerCache   I   DYNA1071I: The cache provider "default" is being used.
[25/04/18 13:53:12:617 BST] 00000194 ServletWrappe I com.ibm.ws.webcontainer.servlet.ServletWrapper init SRVE0242I: [IBM_BPM_Repository_AppCluster] [/ProcessCenter] [/login.jsp]: Initialization successful.
[25/04/18 13:53:12:983 BST] 00000194 WebContainer  E com.ibm.ws.webcontainer.internal.WebContainer handleRequest SRVE0255E: A WebGroup/Virtual Host to handle /favicon.ico has not been defined.
[25/04/18 13:56:25:739 BST] 00000194 FfdcProvider  W com.ibm.ws.ffdc.impl.FfdcProvider logIncident FFDC1003I: FFDC Incident emitted on /opt/ibm/WebSphereProfiles/AppSrv01/logs/ffdc/AppClusterMember1_a6b879bd_18.04.25_13.56.25.7281859129348691234731.txt com.ibm.ws.ssl.channel.impl.SSLReadServiceContext 192
[25/04/18 13:56:35:615 BST] 00000194 ServletWrappe I com.ibm.ws.webcontainer.servlet.ServletWrapper init SRVE0242I: [IBM_BPM_Repository_AppCluster] [/ProcessCenter] [/welcome.jsp]: Initialization successful.
[25/04/18 13:56:35:941 BST] 00000194 ServerCredent I com.ibm.ws.security.spnego.ServerCredentialsFactory initializeServer CWSPN0016I: Ready to process host: bpm857.uk.ibm.com.
[25/04/18 13:56:35:942 BST] 00000194 TrustAssociat I com.ibm.ws.security.spnego.TrustAssociationInterceptorImpl initialize CWSPN0006I: SPNEGO Trust Association Interceptor initialization is complete. Configuration follows:
        SPNEGO Web Authentication:
        enabled = true
        dynamically update = true
        allowAppAuthMethodFallback = false
        krb5Config = /opt/ibm/WebSphere/AppServer/java/jre/lib/security/krb5.conf
        krb5Keytab = /home/wasadmin/bpm857.keytab
        Server configuration:
        Kerberos ServicePrincipalName=HTTP/bpm857.uk.ibm.com@UK
        com.ibm.ws.security.spnego.SPN.filter=null
        com.ibm.ws.security.spnego.SPN.filterClass=com.ibm.ws.security.spnego.HTTPHeaderFilter@f1c79289
        com.ibm.ws.security.spnego.SPN.NTLMTokenReceivedPage=null
        com.ibm.ws.security.spnego.SPN.spnegoNotSupportedPage=null
        cannonicalSupport=true
[25/04/18 13:56:36:062 BST] 00000194 Context       E com.ibm.ws.security.spnego.Context begin CWSPN0011E: A non-valid SPNEGO token has been encountered while authenticating a HttpServletRequest: 0000:  a1143012 a0030a01 01a10b06 092a8648    ..0. .... .... .*.H
0010:  82f71201 0202                          .... ..

[25/04/18 13:56:36:135 BST] 00000194 WebContainer  E com.ibm.ws.webcontainer.internal.WebContainer handleRequest SRVE0255E: A WebGroup/Virtual Host to handle /favicon.ico has not been defined.
[25/04/18 13:57:07:953 BST] 00000194 Context       E com.ibm.ws.security.spnego.Context begin CWSPN0011E: A non-valid SPNEGO token has been encountered while authenticating a HttpServletRequest: 0000:  a1143012 a0030a01 01a10b06 092a8648    ..0. .... .... .*.H
0010:  82f71201 0202                          .... ..

[25/04/18 13:58:23:688 BST] 00000194 Context       E com.ibm.ws.security.spnego.Context begin CWSPN0011E: A non-valid SPNEGO token has been encountered while authenticating a HttpServletRequest: 0000:  a1143012 a0030a01 01a10b06 092a8648    ..0. .... .... .*.H
0010:  82f71201 0202                          .... ..

[25/04/18 13:58:23:745 BST] 00000194 WebContainer  E com.ibm.ws.webcontainer.internal.WebContainer handleRequest SRVE0255E: A WebGroup/Virtual Host to handle /favicon.ico has not been defined.
[25/04/18 14:16:39:148 BST] 00000194 Context       E com.ibm.ws.security.spnego.Context begin CWSPN0011E: A non-valid SPNEGO token has been encountered while authenticating a HttpServletRequest: 0000:  a1143012 a0030a01 01a10b06 092a8648    ..0. .... .... .*.H
0010:  82f71201 0202                          .... ..
...

Now last time I saw this, the two boxes ( BPM on Linux and Active Directory on Windows ) were out-of-sync.

This time, Windows says this: -

and Linux says this: -

date

Wed 25 Apr 14:18:31 BST 2018

which is pretty close.

However, given that this all worked before I suspended/reawakened my VMs, I restart the AppCluster.

Alas, this made no difference.

So I then rebooted the Windows VM …

Alas, this made no difference.

So I then rebooted the Linux VM …

And then restarted the Deployment Environment….

But still this …

...
[25/04/18 14:56:20:090 BST] 00000172 ServerCredent I com.ibm.ws.security.spnego.ServerCredentialsFactory initializeServer CWSPN0016I: Ready to process host: bpm857.uk.ibm.com.
[25/04/18 14:56:20:091 BST] 00000172 TrustAssociat I com.ibm.ws.security.spnego.TrustAssociationInterceptorImpl initialize CWSPN0006I: SPNEGO Trust Association Interceptor initialization is complete. Configuration follows:
SPNEGO Web Authentication:
enabled = true
dynamically update = true
allowAppAuthMethodFallback = false
krb5Config = /opt/ibm/WebSphere/AppServer/java/jre/lib/security/krb5.conf
krb5Keytab = /home/wasadmin/bpm857.keytab
Server configuration:
Kerberos ServicePrincipalName=HTTP/bpm857.uk.ibm.com@UK
com.ibm.ws.security.spnego.SPN.filter=null
com.ibm.ws.security.spnego.SPN.filterClass=com.ibm.ws.security.spnego.HTTPHeaderFilter@becc3490
com.ibm.ws.security.spnego.SPN.NTLMTokenReceivedPage=null
com.ibm.ws.security.spnego.SPN.spnegoNotSupportedPage=null
cannonicalSupport=true
[25/04/18 14:56:20:168 BST] 00000172 Context       E com.ibm.ws.security.spnego.Context begin CWSPN0011E: A non-valid SPNEGO token has been encountered while authenticating a HttpServletRequest: 0000:  a1143012 a0030a01 01a10b06 092a8648    ..0. .... .... .*.H
0010:  82f71201 0202                          .... ..
...

So, rather than trialling and erring, I switched on some debugging, via these two JVM Custom Properties: -

com.ibm.security.jgss.debug = all
com.ibm.security.krb5.Krb5Debug = all

for the AppCluster JVM, and saw this: -

...

[25/04/18 16:32:55:885 BST] 0000014b SystemOut     O [KRB_DBG_CRYP] Rc4HMac:WebContainer : 0:   Checksum arrays = [B@ce870b1e newchecksum:[B@600dad29
[25/04/18 16:32:55:917 BST] 0000014b SystemOut     O [JGSS_DBG_CTX]  WebContainer : 0 Error authenticating request. Reporting to client
Major code = 11, Minor code = 0
org.ietf.jgss.GSSException, major code: 11, minor code: 0
major string: General failure, unspecified at GSSAPI level
minor string: Kerberos error while decoding and verifying token: com.ibm.security.krb5.internal.crypto.KrbCryptoException, status code: 0
message: Checksum error; received checksum does not match computed checksum
[25/04/18 16:32:55:918 BST] 0000014b SystemOut     O [JGSS_DBG_CTX]  WebContainer : 0 >>SPNEGO: wrap the response data to a gss token
[25/04/18 16:32:55:918 BST] 0000014b SystemOut     O [JGSS_DBG_CTX]  WebContainer : 0 >>SPNEGO: no response token
[25/04/18 16:32:55:918 BST] 0000014b SystemOut     O [JGSS_DBG_CTX]  WebContainer : 0 >>SPNEGO: target accept incomplete
[25/04/18 16:32:55:922 BST] 0000014b SystemOut     O [JGSS_DBG_CTX]  WebContainer : 0 >>SPNEGO: target select preferred mechanism
[25/04/18 16:32:55:923 BST] 0000014b SystemOut     O [JGSS_DBG_CTX]  WebContainer : 0 com.ibm.security.jgss.spnego2478 = false
[25/04/18 16:32:55:924 BST] 0000014b Context       E com.ibm.ws.security.spnego.Context begin CWSPN0011E: A non-valid SPNEGO token has been encountered while authenticating a HttpServletRequest: 0000:  a1143012 a0030a01 01a10b06 092a8648    ..0. .... .... .*.H
0010:  82f71201 0202                          .... ..
…

I dug around and around and around, and then found this: -

SPNEGO troubleshooting tips

which said, in part: -

…

The password used when generating the keytab file with ktpass does not match the password assigned to the service account. When the password changes you should regenerate and redistribute the keys., even if it is reset to the same password.

In addition, the ktpass tool might generate a keytab file with a non-matching password as in the following cases:

• If the password entered to ktpass matches the password for the service account, then the produced keytab file does work.

• If the password entered to ktpass does not match the password for the service account, and is less than 7 characters in length, ktpass stops and does not produce a keytab file.

• If the password entered to ktpass does not match the password for the service account, and is greater than 6 characters in length, ktpass does not stop. Instead, it produces a keytab file containing an invalid key. Use of this key to decrypt a SPNEGO token produces the checksum error previously listed.

Use a non-null password for the service account, and then use that password when invoking ktpass.

…

which reminded me of this post FROM MY OWN DARN BLOG: -

WAS and AD and SPNEGO - Oops, I broke my LDAP

where I wrote about how using ktpass with the WRONG password had broken my WAS -> LDAP bind account.

Which made me think ….

So I regenerated the keytab WITH THE RIGHT PASSWORD: -

ktpass -out bpm857.keytab -princ HTTP/bpm857.uk.ibm.com@UK -mapUser UK\bpmbind -mapOp set -pass Qp455w0rd -ptype KRB5_NT_PRINCIPAL

and then placed the new keytab back into WAS: -

as referenced in the krb5.conf file: -

cat /opt/ibm/WebSphere/AppServer/java/jre/lib/security/krb5.conf

[libdefaults]
default_realm = UK.IBM.COM
default_keytab_name = FILE:/home/wasadmin/bpm857.keytab
default_tkt_enctypes = des3-cbc-sha1
default_tgs_enctypes = des3-cbc-sha1
forwardable  = true
renewable  = true
noaddresses = true
clockskew  = 300
[realms]
UK.IBM.COM = {
kdc = ad2012.uk.ibm.com.com:88
default_domain = uk.ibm.com
}
[domain_realm]
.uk.ibm.com = UK.IBM.COM

So that was fun.

In solving one problem, I caused another.

But I learned yet more about the way that SPNEGO works, and how to debug it when things go wrong  ( cough ).

As ever, every day is a school day.