OAuth NullPointerException in NIDPLogXMLFormatter with authorization code flow

Hi!

I stumbled across very strange problem.

Summary: When trying to use authorization code flow OAuth authentication, NAM returns http/400 (bad request) and there is NullPointerException in NIDPLogXMLFormatter logged in catalina.out.

Details:

This is NAM 4.5.3.1 and customer is using this setup heavily for oauth authentication, but until now only with resource owner code flow.

Now we have also enabled authorization and implicit grant types, and all token types are enabled in global settings. Also this specific client has authorization code, implicit and resource owner grants enabled.

I have checked all configuration but although I've done this multiple times I cannot find error in configuration.

Error happens when request for authorization code is sent (response_type=code), so before code should be exchanged for token.

<amLogEntry> 2021-03-23T11:53:02.781Z INFO NIDS OAuth *Server has received a request on thread https-jsse-nio-10.0.1.11-8443-exec-21 GET idp.org.com/.../authz 51658 > host : idp.org.com 51658 > connection : keep-alive 51658 > upgrade-insecure-requests : 1 51658 > user-agent : Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Postman/8.0.7 Chrome/83.0.4103.122 El ectron/9.4.3 Safari/537.36 51658 > accept : text/html,application/xhtml xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 51658 > sec-fetch-site : none 51658 > sec-fetch-mode : navigate 51658 > sec-fetch-user : ?1 51658 > sec-fetch-dest : document 51658 > accept-encoding : gzip, deflate, br 51658 > accept-language : en-US 51658 > cookie : UrnNovellNidpClusterMemberId=~03~02fg~7B~19~0E~0Eu; JSESSIONID=A1486D7A9C3D4B34A2CEEE33E280747A </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z DEBUG NIDS OAuth: Method:NIDPLoginService.getUserApprovedGrants Thread: https-jsse-nio-10.0.1.11-8443-exec-21 Before call getAttribute() - ReplicaId: null </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z DEBUG NIDS OAuth: Method:NIDPLoginService.getUserApprovedGrants Thread: https-jsse-nio-10.0.1.11-8443-exec-21 After call getAttribute() - ReplicaId: 53f412d7-4dab-3b9c-ab56-82e28e2ee79a </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z DEBUG NIDS OAuth: Method:OAuth2ConfigManager.isIssueCodeInJWTEnabled Thread: https-jsse-nio-10.0.1.11-8443-exec-21 The default authorization code format is Binary </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z INFO NIDS OAuth: Method:TokenServiceImpl.getAuthzCode Thread: https-jsse-nio-10.0.1.11-8443-exec-21 Generate Authorization Code success </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z INFO NIDS OAuth: Method:NIDPKeyService.getTokenEncKey Thread: https-jsse-nio-10.0.1.11-8443-exec-21 Searching enc key with alias name=OAuth2_Enc_key_2 </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z INFO NIDS OAuth: Method:NIDPKeyService.getTokenSigningKey Thread: https-jsse-nio-10.0.1.11-8443-exec-21 Searching signing key with alias name=OAuth2_Signing_key_2 </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z DEBUG NIDS OAuth: Method:OAuth2TokenFactory.getExtFormatTokenType Thread: https-jsse-nio-10.0.1.11-8443-exec-21 The token format is Binary </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z INFO NIDS OAuth: Method:NIDPKeyService.getTokenEncKey Thread: https-jsse-nio-10.0.1.11-8443-exec-21 Searching enc key with alias name=OAuth2_Enc_key_2 </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z INFO NIDS OAuth: Method:NIDPKeyService.getTokenSigningKey Thread: https-jsse-nio-10.0.1.11-8443-exec-21 Searching signing key with alias name=OAuth2_Signing_key_2 </amLogEntry> java.util.logging.ErrorManager: 5 java.lang.NullPointerException at com.novell.nidp.logging.NIDPLogXMLFormatter.format(y:2179) at java.util.logging.StreamHandler.publish(StreamHandler.java:211) at java.util.logging.FileHandler.publish(FileHandler.java:701) at java.util.logging.Logger.log(Logger.java:738) at java.util.logging.Logger.doLog(Logger.java:765) at java.util.logging.Logger.log(Logger.java:788) at com.novell.nam.nidp.oauth.core.logging.OAuthLog.severe(OAuthLog.java:45) at com.novell.nam.nidp.oauth.core.AuthorizationEndPoint.handleAuthorizeRequest(AuthorizationEndPoint.java:364) at com.novell.nam.nidp.oauth.core.AuthorizationEndPoint.authorize(AuthorizationEndPoint.java:90) at sun.reflect.GeneratedMethodAccessor298.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ... <amLogEntry> 2021-03-23T11:53:02Z SEVERE NIDS OAuth: null </amLogEntry> <amLogEntry> 2021-03-23T11:53:02Z INFO NIDS OAuth: Event Id: 3014707, Target: genlan-oauth-admin, Note 1: 1616500382787, Note 2: {"tokenIdIssuedToClient":"a_GenLan_Test_OAuth","grantType":"Authorization code"}, Numeric 1: 0 </amLogEntry> <amLogEntry> 2021-03-23T11:53:02.787Z INFO NIDS OAuth *Server responded with a response on thread https-jsse-nio-10.0.1.11-8443-exec-21 51659 < 400 51659 < Bad Request 51659 < Content-Type : text/plain </amLogEntry>

 

Any idea what could be causing NullPointerException?

  • Does it bypass and gives code if you disable the OAuth logging.

  • Unfortunately not. But although I have disabled all logging (everything set to off), even disabled "File Logging", I can still see similar entries in catalina.out:

     

    <amLogEntry> 2021-03-24T17:42:55.574Z INFO NIDS OAuth *Server has received a request on thread https-jsse-nio-10.0.1.11-8443-exec-20 GET idp.server.net/.../authz 940239 > host : idp.server.net 940239 > connection : keep-alive 940239 > upgrade-insecure-requests : 1 940239 > user-agent : Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Postman/8.0.7 Chrome/83.0.4103.122 Electron/9.4.3 Safari/537.36 940239 > accept : text/html,application/xhtml xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 940239 > sec-fetch-site : none 940239 > sec-fetch-mode : navigate 940239 > sec-fetch-user : ?1 940239 > sec-fetch-dest : document 940239 > accept-encoding : gzip, deflate, br 940239 > accept-language : en-US 940239 > cookie : UrnNovellNidpClusterMemberId=~03~02fg~7B~19~0E~0Eu; JSESSIONID=40FC65B76044C24F3AE5B5D7574E3F3C </amLogEntry> <amLogEntry> 2021-03-24T17:42:55.576Z INFO NIDS OAuth *Server has received a request on thread https-jsse-nio-10.0.1.11-8443-exec-9 POST idp.server.net/.../token 940240 > accept : application/json, application/x-www-form-urlencoded 940240 > content-type : application/x-www-form-urlencoded 940240 > cache-control : no-cache 940240 > pragma : no-cache 940240 > user-agent : Java/1.8.0_252 940240 > host : idp.server.net 940240 > connection : keep-alive 940240 > content-length : 117 </amLogEntry>

     

     

    So it looks like logging is still configured somewhere... Do you have any idea where could that be?

  • I can see the same. If you disable everything on logging then also you can see OAuth Logging with INFO.

    I restarted the IDP server and i can see following in the IDP logs:

    2021-03-24T19:14:25 org.glassfish.jersey.server.ApplicationHandler initialize
    INFO: Initiating Jersey application, version Jersey: 2.10.1 2014-06-30 13:53:32...
    ERROR StatusLogger No Log4j 2 configuration file found. Using default configuration (logging only errors to the console), or user programmatically provided configurations. Set system property 'log4j2.debug' to show Log4j 2 internal initialization logging. See https://logging.apache.org/log4j/2.x/manual/configuration.html for instructions on how to configure Log4j 2
    2021-03-24T19:14:25 com.novell.nam.nidp.oauth.core.logging.OAuthLog info

    So there is some logs by default enabled for OAuth.

    For your issue i see the error showing when it trying to get the Keys for code encryption. Trying setting the resouce server 'Identity Provider' to do not encrypt. Also send the resource server parameter with value as Identity Provider.

  • It did not help.

    Resource server is set to "Do not encrypt" (see screenshot attached), and you were probably talking about resourceServer parameter, right?

    So my request was:

     

    idp.server.org/.../authz Provider&response_type=code&state=state&client_id=<clientid>&scope=profile&redirect_uri=www.postman.com/.../callback

     

     

    Result was http/400 and in catalina.out I can see (logging set to Warning only):

     

    <amLogEntry> 2021-03-27T15:27:40.445Z INFO NIDS OAuth *Server has received a request on thread https-jsse-nio-10.0.1.11-8443-exec-104 GET idp.server.org/.../authz Provider&response_type=code&state=state&client_id=<clientid>&scope=profile&redirect_uri=www.postman.com/.../callback 3038528 > host : idp.server.org 3038528 > connection : keep-alive 3038528 > upgrade-insecure-requests : 1 3038528 > user-agent : Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Postman/8.0.8 Chrome/83.0.4103.122 Electron/9.4.3 Safari/537.36 3038528 > accept : text/html,application/xhtml xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 3038528 > sec-fetch-site : none 3038528 > sec-fetch-mode : navigate 3038528 > sec-fetch-user : ?1 3038528 > sec-fetch-dest : document 3038528 > accept-encoding : gzip, deflate, br 3038528 > accept-language : en-US 3038528 > cookie : UrnNovellNidpClusterMemberId=~03~02fg~7B~19~0E~0Eu; JSESSIONID=68046014333B247CCDED52CDAB94E937 </amLogEntry> <amLogEntry> 2021-03-27T15:27:40Z SEVERE NIDS OAuth: null </amLogEntry> <amLogEntry> 2021-03-27T15:27:40.451Z INFO NIDS OAuth *Server responded with a response on thread https-jsse-nio-10.0.1.11-8443-exec-104 3038529 < 400 3038529 < Bad Request 3038529 < Content-Type : text/plain </amLogEntry>

     

     

    Kind ergards,

    Sebastijan

     

  • A bit more troubleshooting revealed that something might be wrong when default contract is pointing to external SAML identity provider.

    To summarize, error happens if default contract is external SAML contract ("Satisfiable by External Provider") and if using authorization code flow.

    If I change default contract to "standard" one (one with method), authorization code flow works without problem.

    If I change OAuth flow to implicit, even with default contract pointing to external SAML IDP authentication works.