By: Cedric Ferraris user 12 Oct 2018 at 1:43 p.m. CDT

15 Responses
Cedric Ferraris gravatar
Hello, I see a lot of these error messages in the oxtrust.log file. It's flooding my log collector (especially since it's multi-lines). Any idea what's triggering it and if so, how to correct it? Example: ``` 2018-10-12 14:37:56,781 ERROR [Thread-8941] [org.gluu.oxtrust.ldap.service.EntityIDMonitoringService] (EntityIDMonitoringService.java:92) - Exception happened while monitoring EntityId java.lang.NullPointerException: null at org.apache.commons.collections.CollectionUtils.getCardinalityMap(CollectionUtils.java:230) ~[commons-collections-3.2.2.jar:3.2.2] at org.apache.commons.collections.CollectionUtils.disjunction(CollectionUtils.java:156) ~[commons-collections-3.2.2.jar:3.2.2] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService.process(EntityIDMonitoringService.java:128) ~[classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService$Proxy$_$$_WeldSubclass.process(Unknown Source) ~[classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService.processMetadataValidationTimerEvent(EntityIDMonitoringService.java:90) [classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService$Proxy$_$$_WeldSubclass.processMetadataValidationTimerEvent$$super(Unknown Source) [classes/:?] at sun.reflect.GeneratedMethodAccessor320.invoke(Unknown Source) ~[?:?] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_162] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_162] at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl-3.0.1.Final.jar:3.0.1.Final] at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [weld-core-impl-3.0.1.Final.jar:3.0.1.Final] at org.xdi.service.cdi.async.AsynchronousInterceptor$1.get(AsynchronousInterceptor.java:36) [oxcore-service-3.1.3.Final.jar:?] at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) [?:1.8.0_162] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162] ```

By Thomas Gasmyr Mougang staff 14 Oct 2018 at 6:55 a.m. CDT

Thomas Gasmyr Mougang gravatar
Hey Cedric, From my investigation there is a null pointer exception during EntityID monitoring. How many Trust relationship do you have in your server? can you export them and send us? Also apply the steps for more content rich log file: 1. Login into Gluu Admin 2. Enable the Debug mode under oxtrust json configuration 3. Restart oxtrust service 4. Then collect the log again and send us.

By Cedric Ferraris user 15 Oct 2018 at 10:25 a.m. CDT

Cedric Ferraris gravatar
Hello, We only have 2 SAML TR in our config. What do you need me to export exactly and how? I have enabled debug mode for oxtrust and attempted a login on the GUI (not even a login to one of the integrated SAML app) and the oxtrust.log file shows (i have hidden some text): ``` 2018-10-15 11:18:43,818 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:398) - authorizationCode : 8cf2d058-1f6a-4844-a738-dcff6e1d07e0 2018-10-15 11:18:43,819 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:401) - scopes : openid user_name email 2018-10-15 11:18:43,819 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:404) - clientID : @!4025.CA62.9BB6.16C5!0001!2212.0010!0008!5891.F259 2018-10-15 11:18:43,819 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:433) - Sending request to token endpoint 2018-10-15 11:18:43,820 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:435) - redirectURI : https://xxxxxxxxxx/identity/authentication/getauthcode 2018-10-15 11:18:43,962 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:453) - Session validation successful. User is logged in 2018-10-15 11:18:44,022 INFO [qtp1744347043-13] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:520) - user uid:xxxxxxxxx 2018-10-15 11:18:44,115 INFO [qtp1744347043-18] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:117) - Authenticating user 'xxxxxxx' 2018-10-15 11:18:44,120 INFO [qtp1744347043-18] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:132) - User 'xxxxxx' authenticated successfully 2018-10-15 11:18:44,908 INFO [qtp1744347043-13] [org.gluu.oxtrust.ldap.service.OrganizationService] (OrganizationService.java:233) - Starting App version null 2018-10-15 11:19:40,007 ERROR [Thread-36] [org.gluu.oxtrust.ldap.service.EntityIDMonitoringService] (EntityIDMonitoringService.java:92) - Exception happened while monitoring EntityId java.lang.NullPointerException: null at org.apache.commons.collections.CollectionUtils.getCardinalityMap(CollectionUtils.java:230) ~[commons-collections-3.2.2.jar:3.2.2] at org.apache.commons.collections.CollectionUtils.disjunction(CollectionUtils.java:156) ~[commons-collections-3.2.2.jar:3.2.2] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService.process(EntityIDMonitoringService.java:128) ~[classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService$Proxy$_$$_WeldSubclass.process(Unknown Source) ~[classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService.processMetadataValidationTimerEvent(EntityIDMonitoringService.java:90) [classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService$Proxy$_$$_WeldSubclass.processMetadataValidationTimerEvent$$super(Unknown Source) [classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_162] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_162] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_162] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_162] at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl-3.0.1.Final.jar:3.0.1.Final] at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [weld-core-impl-3.0.1.Final.jar:3.0.1.Final] at org.xdi.service.cdi.async.AsynchronousInterceptor$1.get(AsynchronousInterceptor.java:36) [oxcore-service-3.1.3.Final.jar:?] at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) [?:1.8.0_162] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162] ``` There is not much difference from without debug mode. Thx

By Thomas Gasmyr Mougang staff 15 Oct 2018 at 1:31 p.m. CDT

Thomas Gasmyr Mougang gravatar
It seems like setting the log level to **DEBUG** don't work well, have you restart the identity service after setting the log level to **DEBUG**? If so set the log level to **TRACE**. > We only have 2 SAML TR in our config. What do you need me to export exactly and how? Export both TR, you can use an LDAP explorer like jxplorer or apache studio.

By Cedric Ferraris user 15 Oct 2018 at 2:27 p.m. CDT

Cedric Ferraris gravatar
I had restarted the identity service. I have now set the log level to TRACE, restarted the identity service and the oxtrust.log file is similar after a GUI login : ``` 2018-10-15 15:23:14,005 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:398) - authorizationCode : fb9d80c9-0197-469a-a7b1-a3ee912acbf1 2018-10-15 15:23:14,006 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:401) - scopes : openid user_name email 2018-10-15 15:23:14,006 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:404) - clientID : @!4025.CA62.9BB6.16C5!0001!2212.0010!0008!5891.F259 2018-10-15 15:23:14,007 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:433) - Sending request to token endpoint 2018-10-15 15:23:14,007 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:435) - redirectURI : https://xxxxxxxxx/identity/authentication/getauthcode 2018-10-15 15:23:14,222 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:453) - Session validation successful. User is logged in 2018-10-15 15:23:14,283 INFO [qtp1744347043-14] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:520) - user uid:xxxxxxx 2018-10-15 15:23:14,367 INFO [qtp1744347043-11] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:117) - Authenticating user 'xxxxxx' 2018-10-15 15:23:14,377 INFO [qtp1744347043-11] [org.gluu.oxtrust.action.Authenticator] (Authenticator.java:132) - User 'xxxxxxx' authenticated successfully 2018-10-15 15:23:15,657 INFO [qtp1744347043-14] [org.gluu.oxtrust.ldap.service.OrganizationService] (OrganizationService.java:233) - Starting App version null 2018-10-15 15:23:18,462 ERROR [Thread-36] [org.gluu.oxtrust.ldap.service.EntityIDMonitoringService] (EntityIDMonitoringService.java:92) - Exception happened while monitoring EntityId java.lang.NullPointerException: null at org.apache.commons.collections.CollectionUtils.getCardinalityMap(CollectionUtils.java:230) ~[commons-collections-3.2.2.jar:3.2.2] at org.apache.commons.collections.CollectionUtils.disjunction(CollectionUtils.java:156) ~[commons-collections-3.2.2.jar:3.2.2] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService.process(EntityIDMonitoringService.java:128) ~[classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService$Proxy$_$$_WeldSubclass.process(Unknown Source) ~[classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService.processMetadataValidationTimerEvent(EntityIDMonitoringService.java:90) [classes/:?] at org.gluu.oxtrust.ldap.service.EntityIDMonitoringService$Proxy$_$$_WeldSubclass.processMetadataValidationTimerEvent$$super(Unknown Source) [classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_162] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_162] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_162] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_162] at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl-3.0.1.Final.jar:3.0.1.Final] at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [weld-core-impl-3.0.1.Final.jar:3.0.1.Final] at org.xdi.service.cdi.async.AsynchronousInterceptor$1.get(AsynchronousInterceptor.java:36) [oxcore-service-3.1.3.Final.jar:?] at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) [?:1.8.0_162] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162] ``` Like I said, I'm only attempting a login to the GUI and pasting the last log lines of the oxtrust.log file. What's the link with the SAML TR? In regards to exporting them, could you be a bit more specific? Using Apache studio and then doing what ?? Thanks

By Thomas Gasmyr Mougang staff 24 Oct 2018 at 2:04 a.m. CDT

Thomas Gasmyr Mougang gravatar
> What's the link with the SAML TR? EntityID belong to TR > Using Apache studio and then doing what ?? Use it to connect to LDAP and export all TRs.

By Cedric Ferraris user 24 Oct 2018 at 1:53 p.m. CDT

Cedric Ferraris gravatar
> EntityID belong to TR Ok. Since it was in oxtrust.log, I assumed it had nothing to do with TR. > Use it to connect to LDAP and export all TRs. Here is the [export](https://ufile.io/fqbs0). The link will expire in 7 days. Let me know if you can't access it (or send me an email address I can send it to).

By Thomas Gasmyr Mougang staff 29 Oct 2018 at 12:56 a.m. CDT

Thomas Gasmyr Mougang gravatar
Hi, The entity Id monitoring service runs against Trust relationships of type **Federation**. From the TRs file provide, there is not Trust Relationship of type federation. The **NullPointerException** may come from a null list pass through the method **CollectionUtils.disjunction()**. So try to create a TR of types federation, then restart the identity service and see if the error is still present.

By Cedric Ferraris user 29 Oct 2018 at 8:32 a.m. CDT

Cedric Ferraris gravatar
Hello, We only have 2 TR and none of them is of type federation. So I've created a fake federation TR : one with metadata as "None" and another one with metadata as "File" and fake values (URL, logout URL, etc.). Of course, validation fails and the TR shows as inactive but at least, the TR of type federation is created. In both cases, I can still see the "Exception happened while monitoring EntityId / java.lang.NullPointerException: null" error message. So the entityID monitoring service is running even if there is no federation TR? Anything else you want me to try? Thanks

By Thomas Gasmyr Mougang staff 31 Oct 2018 at 3:42 p.m. CDT

Thomas Gasmyr Mougang gravatar
Use this doc to create ferederation TR https://gluu.org/docs/ce/3.1.2/admin-guide/saml/#federation-configuration

By Cedric Ferraris user 05 Nov 2018 at 9:58 a.m. CST

Cedric Ferraris gravatar
Hello, I'm sorry but it seems like you don't understand what I'm saying. I am well aware of how to create a federation TR and I've done exactly what's in the doc to create a fake "test" one. Despite that, the error message is still present. But my point is, why do I need to create a fake federation TR just to make the error message disappear??? I don't need a federation TR in my config. Is that how the Gluu server works? Can we ping Mike on that subject? If that is confirmed (i.e I need a fake TR to make the error message disappear), then I guess I will have to live with that. Thanks

By Thomas Gasmyr Mougang staff 06 Nov 2018 at 12:31 a.m. CST

Thomas Gasmyr Mougang gravatar
> I am well aware of how to create a federation TR and I've done exactly what's in the doc to create a fake "test" one. Despite that, the error message is still present. I said: **Create a federation TR with EntityIDs** and i send you the docs to achieve that. The important point here is to create the **entityIds of that TR**. > I don't need a federation TR in my config. Is that how the Gluu server works? We haven't see that error before and we are in the troubleshooting process. If you can applied the suggestion i can't provide further assistance. > Can we ping Mike on that subject? Feel free.

By Cedric Ferraris user 06 Nov 2018 at 11:46 a.m. CST

Cedric Ferraris gravatar
I have applied your suggestion but it does not help: 1- I have created a fake federation TR with fake values (since I don't have real data to create a real federation TR). But it's not possible to activate it since validation fails (since it uses fake values). 2- Then I tried to create a SP TR with EntityID by selecting 'Federation' as the metadata location and the name of the federation TR created at step 1. But it's not showing up and I assume it's because the fake federation TR is not activated. So back to my initial question, I know how to create a federation TR with EntityID and I have followed the doc exactly but which data am I supposed to created that federation TR with??? If you have data about a real federation TR I can use, then give them to me. Otherwise, there is no way I can go ahead with your suggestion. Thanks

By Mohib Zico staff 07 Nov 2018 at 5:21 a.m. CST

Mohib Zico gravatar
>> Exception happened while monitoring EntityId.. I think I have seen this issue before... it's taking space.. true but not fatal. Generally this error means... Gluu Server's internal component cannot read 'entityID' of any SP specified in ldap. We need to check why it's happening and how to resolve that.

By Cedric Ferraris user 15 Nov 2018 at 1:15 p.m. CST

Cedric Ferraris gravatar
Hi Mohib, Have you been able to find the root cause of this issue? Thanks

By Mohib Zico staff 15 Nov 2018 at 1:22 p.m. CST

Mohib Zico gravatar
Hi Cedric, Sorry.. not yet; but it's in my ToDo list. I will let you know when I found something.