SAML SSO stops working every so often - The assertion is not signed correctly

1
Hi all, every few weeks SAML SSO stops working, the users get a message saying Unable to validate SAML message.  Everytime it has happened the fix has been to set up the IdP again, I am trying to find out what is going wrong to stop this happening again.   From the SAML Module I have downloaded the request and response for two attempts by the same user to log in, one when it was not working and another soon after I added the new IdP. The are pretty much identical apart from the time. No errors returned, all is how it should be.   The logs however show me this (i’ve since changed the log levels to TRACE so when it happens again I will see more information) Can any provide any insight? Many thanks.   ERROR - SAML_SSO: Unable to validate Response, see SAMLRequest overview for detailed response. Error: org.opensaml.xml.validation.ValidationException: The assertion is not signed correctly 2019-04-18T00:18:09.321861 [APP/PROC/WEB/0]   ERROR - SAML_SSO: org.opensaml.common.SAMLException: org.opensaml.xml.validation.ValidationException: The assertion is not signed correctly 2019-04-18T00:18:09.321934 [APP/PROC/WEB/0]       at saml20.implementation.ArtifactHandler.handleSAMLResponse(ArtifactHandler.java:175) 2019-04-18T00:18:09.321973 [APP/PROC/WEB/0]       at saml20.implementation.ArtifactHandler.handleRequest(ArtifactHandler.java:33) 2019-04-18T00:18:09.322013 [APP/PROC/WEB/0]       at saml20.implementation.SAMLRequestHandler.processRequest(SAMLRequestHandler.java:167) 2019-04-18T00:18:09.322064 [APP/PROC/WEB/0]       at com.mendix.externalinterface.connector.RequestHandler.doProcessRequest(RequestHandler.java:40) 2019-04-18T00:18:09.322126 [APP/PROC/WEB/0]       at com.mendix.external.connector.MxRuntimeConnector$1.execute(MxRuntimeConnector.java:72) 2019-04-18T00:18:09.322187 [APP/PROC/WEB/0]       at com.mendix.external.connector.MxRuntimeConnector$1.execute(MxRuntimeConnector.java:69) 2019-04-18T00:18:09.322221 [APP/PROC/WEB/0]       at com.mendix.util.classloading.Runner.doRunUsingClassLoaderOf(Runner.java:32) 2019-04-18T00:18:09.322247 [APP/PROC/WEB/0]       at com.mendix.external.connector.MxRuntimeConnector.processRequest(MxRuntimeConnector.java:75) 2019-04-18T00:18:09.322294 [APP/PROC/WEB/0]       at com.mendix.basis.impl.MxRuntimeImpl.processRequest(MxRuntimeImpl.java:909) 2019-04-18T00:18:09.322333 [APP/PROC/WEB/0]       at com.mendix.m2ee.appcontainer.server.handler.RuntimeHandler.service(RuntimeHandler.java:42) 2019-04-18T00:18:09.322358 [APP/PROC/WEB/0]       at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) 2019-04-18T00:18:09.322393 [APP/PROC/WEB/0]       at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:867) 2019-04-18T00:18:09.322444 [APP/PROC/WEB/0]       at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:542) 2019-04-18T00:18:09.322500 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) 2019-04-18T00:18:09.322510 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588) 2019-04-18T00:18:09.322550 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) 2019-04-18T00:18:09.322587 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) 2019-04-18T00:18:09.322620 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) 2019-04-18T00:18:09.322651 [APP/PROC/WEB/0]       at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) 2019-04-18T00:18:09.322682 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557) 2019-04-18T00:18:09.322739 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) 2019-04-18T00:18:09.322773 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) 2019-04-18T00:18:09.322808 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) 2019-04-18T00:18:09.322840 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) 2019-04-18T00:18:09.322886 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.Server.handle(Server.java:502) 2019-04-18T00:18:09.322917 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364) 2019-04-18T00:18:09.322946 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) 2019-04-18T00:18:09.322982 [APP/PROC/WEB/0]       at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) 2019-04-18T00:18:09.323030 [APP/PROC/WEB/0]       at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) 2019-04-18T00:18:09.323049 [APP/PROC/WEB/0]       at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) 2019-04-18T00:18:09.323091 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) 2019-04-18T00:18:09.323118 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) 2019-04-18T00:18:09.323182 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) 2019-04-18T00:18:09.323200 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) 2019-04-18T00:18:09.323240 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) 2019-04-18T00:18:09.323261 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) 2019-04-18T00:18:09.323318 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) 2019-04-18T00:18:09.323348 [APP/PROC/WEB/0]       at java.lang.Thread.run(Thread.java:748) 2019-04-18T00:18:09.323404 [APP/PROC/WEB/0]   Caused by: org.opensaml.xml.validation.ValidationException: The assertion is not signed correctly 2019-04-18T00:18:09.323453 [APP/PROC/WEB/0]       at saml20.implementation.wrapper.MxSAMLResponse.validateResponse(MxSAMLResponse.java:115) 2019-04-18T00:18:09.323486 [APP/PROC/WEB/0]       at saml20.implementation.ArtifactHandler.handleSAMLResponse(ArtifactHandler.java:60) 2019-04-18T00:18:09.323519 [APP/PROC/WEB/0]       at saml20.implementation.ArtifactHandler.handleRequest(ArtifactHandler.java:33) 2019-04-18T00:18:09.323546 [APP/PROC/WEB/0]       at saml20.implementation.SAMLRequestHandler.processRequest(SAMLRequestHandler.java:167) 2019-04-18T00:18:09.323594 [APP/PROC/WEB/0]       at com.mendix.externalinterface.connector.RequestHandler.doProcessRequest(RequestHandler.java:40) 2019-04-18T00:18:09.323626 [APP/PROC/WEB/0]       at com.mendix.external.connector.MxRuntimeConnector$1.execute(MxRuntimeConnector.java:72) 2019-04-18T00:18:09.323663 [APP/PROC/WEB/0]       at com.mendix.external.connector.MxRuntimeConnector$1.execute(MxRuntimeConnector.java:69) 2019-04-18T00:18:09.323687 [APP/PROC/WEB/0]       at com.mendix.util.classloading.Runner.doRunUsingClassLoaderOf(Runner.java:32) 2019-04-18T00:18:09.323736 [APP/PROC/WEB/0]       at com.mendix.external.connector.MxRuntimeConnector.processRequest(MxRuntimeConnector.java:75) 2019-04-18T00:18:09.323768 [APP/PROC/WEB/0]       at com.mendix.basis.impl.MxRuntimeImpl.processRequest(MxRuntimeImpl.java:909) 2019-04-18T00:18:09.323798 [APP/PROC/WEB/0]       at com.mendix.m2ee.appcontainer.server.handler.RuntimeHandler.service(RuntimeHandler.java:42) 2019-04-18T00:18:09.323834 [APP/PROC/WEB/0]       at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) 2019-04-18T00:18:09.323879 [APP/PROC/WEB/0]       at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:867) 2019-04-18T00:18:09.323915 [APP/PROC/WEB/0]       at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:542) 2019-04-18T00:18:09.323941 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) 2019-04-18T00:18:09.323973 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588) 2019-04-18T00:18:09.324021 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) 2019-04-18T00:18:09.324051 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) 2019-04-18T00:18:09.324085 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) 2019-04-18T00:18:09.324111 [APP/PROC/WEB/0]       at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) 2019-04-18T00:18:09.324156 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557) 2019-04-18T00:18:09.324185 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) 2019-04-18T00:18:09.324215 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) 2019-04-18T00:18:09.324254 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) 2019-04-18T00:18:09.324290 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) 2019-04-18T00:18:09.324316 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.Server.handle(Server.java:502) 2019-04-18T00:18:09.324350 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364) 2019-04-18T00:18:09.324379 [APP/PROC/WEB/0]       at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) 2019-04-18T00:18:09.324424 [APP/PROC/WEB/0]       at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) 2019-04-18T00:18:09.324456 [APP/PROC/WEB/0]       at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) 2019-04-18T00:18:09.324483 [APP/PROC/WEB/0]       at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) 2019-04-18T00:18:09.324527 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) 2019-04-18T00:18:09.324567 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) 2019-04-18T00:18:09.324595 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) 2019-04-18T00:18:09.324633 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) 2019-04-18T00:18:09.324663 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) 2019-04-18T00:18:09.324708 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) 2019-04-18T00:18:09.324736 [APP/PROC/WEB/0]       at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) 2019-04-18T00:18:09.324769 [APP/PROC/WEB/0]       at java.lang.Thread.run(Thread.java:748)   EDIT: In response to Ronald I spoke with out infrastructure team and they have replied:   it looks like the SAML link is being established directly with Azure via   https://login.microsoftonline.com/mencap.org.uk/FederationMetadata/2007-06/FederationMetadata.xml   Looking at this certificate gives the following info     However that doesn’t mean that the certificate hasn’t been cycled by Microsoft, we will have no control or visibility of this.   This domain will also be targeting server farms which could have a range of certificates across the nodes, which we cannot manage or control however, they will all be valid.  
asked
3 answers
0

An error like this means that there is something wrong with the certificates. Indeed by creating a fresh iDP setup the certificates are refreshed so everything starts working again. Is the metadata refreshed daily and does that work correctly? Is it true that the certificates indeed have been changed? Because if the certificates have not been changed something strange is going on.

Regards,

Ronald

 

 

answered
0

If you look inside <IDPSSODescriptor> it contains 3 signing certificates. Could it be that the validation exceptions occurred around these dates?

Common Name: accounts.accesscontrol.windows.net
Valid From: March 13, 2019
Valid To: March 13, 2021
Serial Number: 59cabce0275584a54470a6d974c38c1a
Common Name: accounts.accesscontrol.windows.net
Valid From: January 31, 2019
Valid To: January 31, 2021
Serial Number: 3fcb1457885fd99c4f7f0e430743bd0a
Common Name: login.microsoftonline.us
Valid From: October 13, 2018
Valid To: October 13, 2020
Serial Number: 7c45a54d5735b8834473d4418baa8732

 

answered
0

Did you resolve the problem? What was the resolution? We are hitting the identical issue in production.

answered