Hi Mark,
Sorry for the long delay in responding. I figured out the problem was I was using user.data.firstName, etc... for the built-in profile fields. Instead, it should be user.firstName. It's working fine now; thank you for the guidance on how to debug it!
@dan No, nothing that seemed relevant. I ended up using Cloudflare as a proxy. That works fine, but it would be simpler to just enable HTTPS in FusionAuth.
@dan It doesn't seem fair that you can't modify a form without a license. I don't need to do anything elaborate, just rearrange some of the fields in the Admin User Form, delete fields I'm not using, and add the firstName field to the form. firstName should be one of the standard fields anyway.
I'm running v1.47.1. It's installed on a Ubuntu 22 server from your Debian package. I'm using Chrome, but the field is not present at all in the HTML, so the browser wouldn't matter. I haven't installed it locally, but I'm not sure what that would prove. The field shows up for you, so clearly it's supposed to be there. Perhaps the issue is specific to the Debian package. Everything else works fine, so I assume it was some oversight during the build process.
I upgraded. I haven't tried a new install nor do I want to. I understand why it's happening. Is it something you can fix in a future update, without my having to start over with a whole new install?
@dan I'm now on 1.53.2, but the First Name field still doesn't appear on the User Profile form. I noticed in the Github issue, they wrote:
We are naming the user.firstName field [Admin Registration : first name instead of [Admin User] first name so when we go build the default form we don't find a result because we look up the field with WHERE name = '[Admin User] first name'.
Therefore, I changed the field name in Customizations->Form Fields to [Admin User] first name.
Next, I edited the form and added the field. However, when I try to save the form, it says:
To modify a form that is currently in use must activate the Reactor with a valid license key.
When I navigate to the Reactor page, it shows that it's licensed with a Community Edition license.
Hi Mark,
Sorry for the long delay in responding. I figured out the problem was I was using user.data.firstName, etc... for the built-in profile fields. Instead, it should be user.firstName. It's working fine now; thank you for the guidance on how to debug it!
I sometimes see 404 errors in the SP server log like the following:
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:43 -0400] "POST /login/Saml HTTP/2" 302 - "https://auth.clinicalmatchme.com/" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /js/prime-min-1.6.4.js?version=1.48.1 HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /css/fusionauth-style.css?version=1.48.1 HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /js/oauth2/LocaleSelect.js?version=1.48.1 HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /js/jstz-min-1.0.6.js HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:43 -0400] "GET / HTTP/2" 302 - "https://auth.clinicalmatchme.com/" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /css/font-awesome-4.7.0.min.css HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /js/Util.js?version=1.48.1 HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /js/oauth2/Authorize.js?version=1.48.1 HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
2607:fb90:3f86:d16e:28de:bbcb:c285:4edf - - [04/Apr/2024:09:25:44 -0400] "GET /js/identityProvider/InProgress.js?version=1.48.1 HTTP/2" 404 139 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Mobile Safari/537.36"
Although these errors are occurring on the SP server, they're being triggered by the FusionAuth theme on the IdP server. In the first request, the user is being redirected to FusionAuth to start the login process. When it loads the FusionAuth theme template, it requests all those files, but instead of requesting them from the IdP server, it's requesting them from the SP server, but they don't exist there, hence the 404 errors.
In the theme template, I see lines like this:
<script src="${request.contextPath}/js/prime-min-1.6.4.js?version=${version}"></script>
So it seems the ${request.contextPath} variable is being incorrectly populated with the SP hostname, rather then the IdP hostname. I'm running FusionAuth 1.48.1 on a Ubuntu 22 server. I want to emphasize that this only happens every once in a while. Most of the time, users login without triggering these errors and I don't know under what conditions this happens.
Screenshot below. I can't provide sample code because the integration is with a third-party application. However, when I enable debug mode in that application, it logs the JWT token it's receiving from FusionAuth:
{"aud":"bfa366a7-9e50-4df3-82d5-d111028370f1","exp":1706394906,"iat":1706391306,"iss":"clinicalmatchme.com","sub":"c975ef0e-eb44-412c-b8ad-766177677da2","jti":"2497e0e4-97e2-46ee-a5b8-4d691a79
f13b","authenticationType":"PASSWORD","email":"brad@hostland.com","email_verified":true,"at_hash":"5f5J3oDmyYCplIBG8J8Vig","c_hash":"GuLPkMegupiDHNt_xOcVQg","scope":"openid profile email","nonce":"plwzij","sid":"93dd553e-0742-4675-906e-0f59
fc0ef3df","auth_time":1706391306,"tid":"035c049b-5e2e-11ee-877a-02904e6a3dbf"}
You can see the profile scope is present, but FA is not sending any of the profile info, even with the lambda function enabled.
I'm using FusionAuth as the OIDC IdP for an application. The application is configured to include the profile scope in the authentication request, but when FusionAuth sends the JWT token, it doesn't include any of the profile fields. Shouldn't it send the profile fields automatically when the profile scope is included in the request?
Anyway, I tried to force it to send the profile data using the following lambda function:
function populate(jwt, user, registration) {
jwt.name = user.data.fullName;
jwt.family_name = user.data.lastName;
jwt.given_name = user.data.firstName;
}
After creating this lambda, I enabled it in the JWT tab for the application. It's selected for both Access Token populate lambda and Id Token populate lambda, but it doesn't seem to do anything. It's still sending the JWT token without these fields.
@dan The database backend is AWS Aurora, and it's a big production instance, so it's unlikely that it would run out of connections. Also, other apps running on the same database continued to work fine. FusionAuth is currently in testing. Since we only have a couple of users testing it, the load is extremely light, so I don't see how it could have been under extereme load.
Any idea what happened here? The server was completely locked up and I had to do a force reboot. After rebooting, everything is working normally again.
2023-11-21 07:09:41.030 PM ERROR io.fusionauth.app.action.BaseOAuthCallbackAction - Unable to call FusionAuth Token endpoint using code [bpzbDSTDZeu5flug8js8gpr79ZWQs6vBSFNck01cKdQ]. HTTP Status Code [400]. Error message:
[{
"error" : "invalid_request",
"error_description" : "Invalid Authorization Code",
"error_reason" : "auth_code_not_found"
}]
2023-11-22 03:59:22.067 AM ERROR io.fusionauth.http.server.HTTPServerThread - An exception was thrown during processing
java.lang.NullPointerException: Cannot invoke "io.fusionauth.http.server.RequestPreambleState.store()" because "<local3>" is null
at io.fusionauth.http.server.HTTPRequestProcessor.processPreambleBytes(HTTPRequestProcessor.java:95)
at io.fusionauth.http.server.HTTP11Processor.read(HTTP11Processor.java:155)
at io.fusionauth.http.server.HTTPS11Processor.read(HTTPS11Processor.java:148)
at io.fusionauth.http.server.HTTPServerThread.read(HTTPServerThread.java:348)
at io.fusionauth.http.server.HTTPServerThread.run(HTTPServerThread.java:176)
2023-11-22 06:46:49.718 AM ERROR com.inversoft.scheduler.LogAndRetainFailureHandler - The scheduled service [class com.inversoft.authentication.api.service.AuthenticationKeyCacheLoader] failed but will be re-run.
org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 155614ms.
### The error may exist in com/inversoft/authentication/api/domain/AuthenticationKeyMapper.xml
### The error may involve com.inversoft.authentication.api.domain.AuthenticationKeyMapper.retrieveAll
### The error occurred while executing a query
### Cause: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 155614ms.
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:156)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:147)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:142)
at jdk.internal.reflect.GeneratedMethodAccessor28.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.apache.ibatis.session.SqlSessionManager$SqlSessionInterceptor.invoke(SqlSessionManager.java:355)
at jdk.proxy2/jdk.proxy2.$Proxy53.selectList(Unknown Source)
at org.apache.ibatis.session.SqlSessionManager.selectList(SqlSessionManager.java:204)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:147)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:80)
at org.apache.ibatis.binding.MapperProxy$PlainMethodInvoker.invoke(MapperProxy.java:142)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:86)
at jdk.proxy2/jdk.proxy2.$Proxy59.retrieveAll(Unknown Source)
at com.inversoft.authentication.api.service.AuthenticationKeyCacheLoader.internalLoad(AuthenticationKeyCacheLoader.java:38)
at com.inversoft.cache.BaseCacheLoader.load(BaseCacheLoader.java:21)
at com.inversoft.authentication.api.service.AuthenticationKeyCacheLoader.run(AuthenticationKeyCacheLoader.java:33)
at com.inversoft.scheduler.InjectableRunnable.run(InjectableRunnable.java:56)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 155614ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:181)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:146)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
at org.apache.ibatis.transaction.jdbc.JdbcTransaction.openConnection(JdbcTransaction.java:145)
at org.apache.ibatis.transaction.jdbc.JdbcTransaction.getConnection(JdbcTransaction.java:67)
at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:345)
at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:89)
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:64)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:333)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:158)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:110)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:90)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:154)
... 23 common frames omitted
2023-11-22 06:46:49.880 AM INFO io.fusionauth.api.service.system.NodeService - Node [951665d2-e50f-4914-8950-6b96246c7357] with address [http://10.144.65.18:8080] removed because it has not checked in for the last [213] seconds. Bye node.
2023-11-22 11:28:03.210 AM INFO io.fusionauth.api.service.system.NodeService - Node [951665d2-e50f-4914-8950-6b96246c7357] with address [http://10.144.65.18:8080] removed because it has not checked in for the last [209] seconds. Bye node.
2023-11-22 11:33:37.574 AM WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m13s351ms914µs201ns).
2023-11-22 11:35:16.620 AM WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=6m20s354ms981µs782ns).
2023-11-22 11:36:07.338 AM WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=50s941ms257µs890ns).
2023-11-22 11:37:09.289 AM WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=55s420ms783µs562ns).
2023-11-22 11:38:35.711 AM WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m23s325ms602µs713ns).
2023-11-22 11:39:31.981 AM WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m5s637ms113µs254ns).
2023-11-22 12:07:04.616 PM INFO io.fusionauth.api.configuration.DefaultFusionAuthConfiguration - Loading FusionAuth configuration file [/usr/local/fusionauth/config/fusionauth.properties]
2023-11-22 12:07:04.703 PM INFO io.fusionauth.api.configuration.DefaultFusionAuthConfiguration - Dynamically set property [fusionauth-app.url] set to [http://10.144.65.18:8080]
2023-11-22 12:07:04.705 PM INFO com.inversoft.configuration.BasePropertiesFileInversoftConfiguration -
- Overriding default value of property [database.mysql.enforce-utf8mb4] with value [true]
- Overriding default value of property [fusionauth-app.runtime-mode] with value [production]
- Overriding default value of property [search.type] with value [database]