We’ve had our Keycloak instance setup for several years with federated LDAP to our Active Directory environment. Some groups have Keycloak roles directly assigned. We use roles to influence authentication flow behavior and noticed overnight our authentication flow was no longer working.
Upon examination we found that the LDAP Group IDs in the database (in the keycloak_group table) had changed and thus the role mapping was no longer present for the ‘new’ Group ID (in the group_role_mapping table). What is strange is most of the group IDs remained the same but about one third of the groups now have a new id value in the database.
We’ve never seen this happen and aren’t sure what could have changed causing Keycloak to delete and recreate groups with new IDs. We have not made any changes inside Keycloak and the LDAP backend has not been modified. Any ideas how this could happen?
I found where this happened in the logs, but no idea why it happened. It appears there was a TLS error which instead of causing the app to retry it must have used the partial data returned instead and removed 33 groups.
I found an option in the AD Groups mapper “Drop non-existing groups during sync” that was enabled. I’ve disabled it as my assumption is that if this happens in the future it will not delete the groups, and should not recreate them with new IDs on the next sync.
Aug 29 03:32:29 server kc.sh[1054]: 2024-08-29 03:32:29,708 INFO [org.bouncycastle.jsse.provider.ProvTlsClient] (Timer-0) [client #10429 @7619188f] opening connection to 172.1.1.112:636
Aug 29 03:32:29 server kc.sh[1054]: 2024-08-29 03:32:29,725 INFO [org.bouncycastle.jsse.provider.ProvTlsClient] (Timer-0) [client #10429 @7619188f] established connection with 172.1.1.112:636
Aug 29 03:32:29 server kc.sh[1054]: 2024-08-29 03:32:29,807 INFO [org.bouncycastle.jsse.provider.ProvTlsClient] (Thread-10441) [client #10429 @7619188f] raised fatal(2) bad_record_mac(20) alert: Failed to read record: org.bouncycastle.tls.TlsFatalAlert: bad_record_mac(20)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.crypto.impl.TlsAEADCipher.decodeCiphertext(TlsAEADCipher.java:308)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.RecordStream.decodeAndVerify(RecordStream.java:255)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.RecordStream.readRecord(RecordStream.java:240)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.TlsProtocol.safeReadRecord(TlsProtocol.java:879)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.TlsProtocol.readApplicationData(TlsProtocol.java:842)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.jsse.provider.ProvSSLSocketDirect$AppDataInput.read(ProvSSLSocketDirect.java:591)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:244)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:343)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.naming/com.sun.jndi.ldap.Connection.readFully(Connection.java:1059)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.naming/com.sun.jndi.ldap.Connection.run(Connection.java:958)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/java.lang.Thread.run(Thread.java:840)
Aug 29 03:32:29 server kc.sh[1054]: Caused by: java.lang.IllegalStateException:
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.crypto.impl.jcajce.Exceptions.illegalStateException(Exceptions.java:10)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.crypto.impl.jcajce.JceAEADCipherImpl.doFinal(JceAEADCipherImpl.java:173)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.crypto.impl.TlsAEADCipher.decodeCiphertext(TlsAEADCipher.java:303)
Aug 29 03:32:29 server kc.sh[1054]: #011... 11 more
Aug 29 03:32:29 server kc.sh[1054]: Caused by: javax.crypto.AEADBadTagException: Error finalising cipher data: mac check in GCM failed
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:481)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.jcajce.provider.ClassUtil.throwBadTagException(Unknown Source)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.jcajce.provider.BaseCipher.engineDoFinal(Unknown Source)
Aug 29 03:32:29 server kc.sh[1054]: #011at java.base/javax.crypto.Cipher.doFinal(Cipher.java:2417)
Aug 29 03:32:29 server kc.sh[1054]: #011at org.bouncycastle.tls.crypto.impl.jcajce.JceAEADCipherImpl.doFinal(JceAEADCipherImpl.java:169)
Aug 29 03:32:29 server kc.sh[1054]: #011... 12 more
Aug 29 03:32:29 server kc.sh[1054]: 2024-08-29 03:32:29,808 INFO [org.bouncycastle.jsse.provider.ProvTlsClient] (Thread-10441) [client #10429 @7619188f] disconnected from 172.28.195.112:636
Aug 29 03:32:29 server kc.sh[1054]: 2024-08-29 03:32:29,809 WARN [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (Timer-0) Did not receive response controls for paginated query using DN [OU=Something,DC=some,DC=com], filter [(&(objectclass=group))]. Did you hit a query result size limit?
Aug 29 03:32:30 server kc.sh[1054]: 2024-08-29 03:32:30,498 INFO [org.keycloak.storage.ldap.LDAPStorageProviderFactory] (Timer-0) Sync of federation mapper 'AD Groups' finished. Status: UserFederationSyncResult [ 0 imported groups, 80 updated groups, 33 removed groups ]