OpenID Connect: java.net.UnknownHostException with truncated log

[lamuertepeluda]

OpenID Connect: java.net.UnknownHostException with truncated log

Description

Hi, this is an issue following #548 (thanks for fixing that one!). So, after upgrading to 1.15.8 and successfully performing authentication in the 3rd party OpenID provider, I get stuck to this screen.

In the event log, sadly, there isn't much information helping, since the error appears truncated.

I was also trying to access some log file in my fusionauth app docker container, but there is none.

The Debug Log (orange one, with a bug icon) shows this

The Error event log (red triangle) shows this:

There is a truncated error stack, with insufficient information to understand what is going on, e.g. if this is an error on the provider side, a misconfiguration or something else. I would also like to access the requests sent and responses received by FusionAuth towards the ID provider in order to debug.

As I mentioned in the #548, I run the docker container on localhost address behind a nginx reverse proxy that handles SSL Termination and so on. Is there perhaps any header I am missing?

Is there any way to do this? E.g. Log verbosity? Or is this a bug in the event system presentation?

Steps to reproduce

Steps to reproduce the behavior:

See #548

Expected behavior

FusionAuth gets the token from the 3rd party provider. If failing (e.g. endpoint error, whatever...), the error event should present more information than the one provided.

Screenshots

See description

Platform

FusionAuth 1.15.8 Device: any OS: any Browser: Google Chrome | 80.0.3987.149

Additional context

See #548 Host is a linux VM. FusionAuth runs in a docker container behind a nginx reverse proxy.

[robotdan]

The UnknownHostException looks to be the root cause.

Ensure that hostname is resolvable be FusionAuth.

[lamuertepeluda]

How can I check that from FusionAuth? From the host machine it seems ok:

host demo.miniorange.com
demo.miniorange.com has address 34.239.150.97

However the fusionauth container it does not appear to have any utility installed for dns resolution. I mean I got into the container

docker exec -i -t fusionauth-containers_fusionauth_1 bash

and I could not host, ping etc... Any suggestions?

[lamuertepeluda]

Ok it appears to be a firewall/docker configuration conflict

[lamuertepeluda]

Once solved DNS issues, however I get this

Failed to complete a login for Identity Provider [MiniOrange Test].

The following errors occurred:

{
  "fieldErrors" : { },
  "generalErrors" : [ {
    "code" : "[Exception]",
    "message" : "FusionAuth encountered an unexpected error. Please contact support for assistance."
  } ]
}

@robotdan where can I find the logs?

[robotdan]

If you're running in docker, the logs will be managed by docker.

Otherwise the logs are documented here. https://fusionauth.io/docs/v1/tech/troubleshooting

[lamuertepeluda]

That's right, sorry! I thought I'd found only stdout and not stderr :sweat_smile:

Here is the stack. A bad null pointer exception. I see it seems related to JWT reconcile. May be some configuration missing? Or just a bug?

fusionauth_1  | Apr 11, 2020 4:48:20.018 PM ERROR io.fusionauth.app.primeframework.error.ExceptionExceptionHandler - An unhandled exception was thrown
fusionauth_1  | java.lang.NullPointerException: null
fusionauth_1  |         at io.fusionauth.api.service.authentication.OpenIdConnectIdentityProviderAuthenticationService.reconcile(OpenIdConnectIdentityProviderAuthenticationService.java:111)
fusionauth_1  |         at io.fusionauth.app.action.api.identityProvider.LoginAction.post(LoginAction.java:64)
fusionauth_1  |         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
fusionauth_1  |         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
fusionauth_1  |         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
fusionauth_1  |         at java.lang.reflect.Method.invoke(Method.java:498)
fusionauth_1  |         at org.primeframework.mvc.util.ReflectionUtils.invoke(ReflectionUtils.java:414)
fusionauth_1  |         at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.execute(DefaultActionInvocationWorkflow.java:79)
fusionauth_1  |         at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.perform(DefaultActionInvocationWorkflow.java:62)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.validation.DefaultValidationWorkflow.perform(DefaultValidationWorkflow.java:47)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.security.DefaultSecurityWorkflow.perform(DefaultSecurityWorkflow.java:60)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.parameter.DefaultPostParameterWorkflow.perform(DefaultPostParameterWorkflow.java:50)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.content.DefaultContentWorkflow.perform(DefaultContentWorkflow.java:52)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.parameter.DefaultParameterWorkflow.perform(DefaultParameterWorkflow.java:57)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.parameter.DefaultURIParameterWorkflow.perform(DefaultURIParameterWorkflow.java:102)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.scope.DefaultScopeRetrievalWorkflow.perform(DefaultScopeRetrievalWorkflow.java:58)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.message.DefaultMessageWorkflow.perform(DefaultMessageWorkflow.java:45)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at io.fusionauth.app.primeframework.FrontEndTenantWorkflow.perform(FrontEndTenantWorkflow.java:71)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.action.DefaultActionMappingWorkflow.perform(DefaultActionMappingWorkflow.java:126)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.workflow.StaticResourceWorkflow.perform(StaticResourceWorkflow.java:97)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.parameter.RequestBodyWorkflow.perform(RequestBodyWorkflow.java:89)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at org.primeframework.mvc.security.DefaultSavedRequestWorkflow.perform(DefaultSavedRequestWorkflow.java:57)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at io.fusionauth.app.primeframework.CORSFilter.handleNonCORS(CORSFilter.java:291)
fusionauth_1  |         at io.fusionauth.app.primeframework.CORSFilter.doFilter(CORSFilter.java:252)
fusionauth_1  |         at io.fusionauth.app.primeframework.CORSRequestWorkflow.perform(CORSRequestWorkflow.java:48)
fusionauth_1  |         at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
fusionauth_1  |         at io.fusionauth.app.primeframework.FusionAuthMVCWorkflow.perform(FusionAuthMVCWorkflow.java:88)
fusionauth_1  |         at org.primeframework.mvc.workflow.DefaultWorkflowChain.continueWorkflow(DefaultWorkflowChain.java:44)
fusionauth_1  |         at org.primeframework.mvc.servlet.FilterWorkflowChain.continueWorkflow(FilterWorkflowChain.java:50)
fusionauth_1  |         at org.primeframework.mvc.servlet.PrimeFilter.doFilter(PrimeFilter.java:82)
fusionauth_1  |         at com.inversoft.maintenance.servlet.MaintenanceModePrimeFilter.doFilter(MaintenanceModePrimeFilter.java:59)
fusionauth_1  |         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
fusionauth_1  |         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
fusionauth_1  |         at com.inversoft.servlet.UTF8Filter.doFilter(UTF8Filter.java:27)
fusionauth_1  |         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
fusionauth_1  |         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
fusionauth_1  |         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
fusionauth_1  |         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
fusionauth_1  |         at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
fusionauth_1  |         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
fusionauth_1  |         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
fusionauth_1  |         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
fusionauth_1  |         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
fusionauth_1  |         at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:798)
fusionauth_1  |         at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
fusionauth_1  |         at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:808)
fusionauth_1  |         at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
fusionauth_1  |         at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
fusionauth_1  |         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
fusionauth_1  |         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
fusionauth_1  |         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
fusionauth_1  |         at java.lang.Thread.run(Thread.java:748)

[robotdan]

What OpenID Connect provider are you using? That exception is caused because the Token endpoint returned success but did not return a access_token value in the JSON response.

You can recreate the login workflow in Postman or Insomnia or something like that an inspect the response from the Token endpoint.

A successful response should always contain an access_token property. https://openid.net/specs/openid-connect-core-1_0.html#TokenResponse

[lamuertepeluda]

@robotdan we spent quite a lot of time trying to understand this issue, and also contacted the Miniorange team. Sadly no luck.

They suggested to look at the logs. As I am running in a docker container, when I try to find them in the path suggested here

docker exec -i -t fusionauth-containers_fusionauth_1 bash
fusionauth@d9674d0087be:/$ cd /usr/local/fusionauth/logs/
fusionauth@d9674d0087be:/usr/local/fusionauth/logs$ ls
fusionauth@d9674d0087be:/usr/local/fusionauth/logs$ #no files! 😞 

Therefore I tried with docker logs (the compose file is the same from fusionauth containers repo)

docker-compose logs fusionauth

The output is the NullPointerEception in my previous post.

The containers are on a remote server with a public URL, that was added to the Provider. Not knowing how to reproduce via PostMan locally (because of the configuration on the OpenID Provider, Authorized Request URL and so on), we tried a tcpdump + WireShark approach.

Now, although some calls are obfuscated by the encryption, I don't see any POST to the OpenID provider token endpoint, while I see the GET to the authorize endpoint. Is this correct?

Is there any way of getting more detailed logs out of FusionAuth (e.g. some env variable), like logging the requests is trying to make and/or HTTP Error codes?

[robotdan]

FusionAuth will create a debug event log when enabled in the IdP config - however, because this NPE is not expected it blows our event log before we write it. In a future release we can fix this to be more defensive - but currently - we don't have much debug than what you're seeing.

The first thing to do is capture the actual response from their Token endpoint to see if the contents are as we expect.

If you have a support contract with FusionAuth you can provide some additional details in your slack channel or via a support ticket and we can try to recreate and assist in debugging.

[lamuertepeluda]

@robotdan I see. I think improving debug, or at least what's get written on the logs/stdout/stderr is quite important for investigating unexpected errors. Anyway from our tcpdump their Token endpoint doesn't seem to get called at all by FusionAuth, as I mentioned before. Are you 100% sure that this NullPointerException occurs only if the endpoint did not return a access_token value in the JSON response, and there can't be any other condition causing it (e.g. cannot get the URL correctly from the configuration, whatever...)?

Miniorange support team also told us that they are not receiving the call to the token endpoint, after checking their logs.

[robotdan]

Because there are some many variables here and I don't know how MiniOrange works, or how your integration is configured, there isn't much I can help you with outside of seeing the entire OAuth flow to see if they are sending back a proper token response.

All I can tell you is the endpoint you have configured in FusionAuth for the Token endpoint returned a 200 status code which tells us it was successful, and then response did not contain the access_token field.

I have no idea if the configured token endpoint is the correct endpoint, or if their token endpoint responds in a spec compliant way if there are validation issues, etc. So I'm sort of in the dark there.

The endpoint I see in your screenshot indicates you're using some sort of Joomla specific plugin with MiniOrange -and I do not know anything about that specific offering from MiniOrange.

Outside of a support contract I don't have enough information to debug this further.

[lamuertepeluda]

I closed the issue since, after deep investigation, it came out that the problem was caused by the token that the IdP was issuing is not a valid JWT, but a simple Bearer token. There is currently no way to make it compliant (although this is also outside of FusionAuth scope).

For the records, in order to add Joomla as IdP, we had to use SAMLv2.

[robotdan]

Thanks for the update @lamuertepeluda