Slow login with ondemand-dex

Get Help
1

Not sure what’s going on behind the scenes but it’s quite slow to initialize a user session. Here’s the log entries during login, from the time I hit ‘enter’ on my credentials to when I land on the dashboard. As you can see, it takes a full ten seconds. This is agonizing for the user experience. Our ldap server responds to queries perfectly fine, you see it gets to a ‘login successful’ message in a few seconds, but then it takes a while to continue. How can I speed this up?

==> syslog <==
Jun 19 13:35:03 ood01 ondemand-dex[1672065]: time=2025-06-19T13:35:03.630-04:00 level=INFO msg="performing ldap search" connector.type=ldap connector.id=ldap base_dn="ou=People,dc=vector,dc=local" scope=sub filter="(&(&(objectClass=posixAccount)(host=ondemand))(uid=sebastian))"
Jun 19 13:35:03 ood01 ondemand-dex[1672065]: time=2025-06-19T13:35:03.635-04:00 level=INFO msg="username mapped to entry" connector.type=ldap connector.id=ldap username=sebastian user_dn="uid=sebastian,ou=People,dc=vector,dc=local"



Jun 19 13:35:07 ood01 ondemand-dex[1672065]: time=2025-06-19T13:35:07.583-04:00 level=INFO msg="login successful" connector_id=ldap username="Sebastian Burlacu" preferred_username=sebastian email=sebastian.burlacu@vectorinstitute.ai groups=[] request_id=463ccc18-dcac-434a-bd35-b9442e5f0f43




==> apache2/ondemand.vectorinstitute.ai_access_ssl.log <==
10.1.1.1 - - [19/Jun/2025:13:35:01 -0400] "POST /dex/auth/ldap/login?back=&state=bggrpydgqvqd3ymsz24wctxsr HTTP/1.1" 303 2994 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=bggrpydgqvqd3ymsz24wctxsr" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"
127.0.0.1 - - [19/Jun/2025:13:35:12 -0400] "GET /dex/.well-known/openid-configuration HTTP/1.1" 200 4246 "-" "mod_auth_openidc"



127.0.0.1 - - [19/Jun/2025:13:35:12 -0400] "POST /dex/token HTTP/1.1" 200 4927 "-" "mod_auth_openidc"
127.0.0.1 - - [19/Jun/2025:13:35:13 -0400] "GET /dex/keys HTTP/1.1" 200 5521 "-" "mod_auth_openidc"
127.0.0.1 - - [19/Jun/2025:13:35:13 -0400] "GET /dex/userinfo HTTP/1.1" 200 3288 "-" "mod_auth_openidc"
10.1.1.1 - sebastian [19/Jun/2025:13:35:11 -0400] "GET /oidc?code=mwou5p3hoojy7ii2sleyrm3ev&state=9hTkqU1RK7R4lUlkmrOiWo4CjZQ HTTP/1.1" 302 988 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=bggrpydgqvqd3ymsz24wctxsr" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"

==> ondemand-nginx/sebastian/error.log <==
App 1671949 output: [2025-06-19 13:35:13 -0400 ]  WARN "Announcement file not found: /etc/ood/config/announcement.md"
App 1671949 output: [2025-06-19 13:35:13 -0400 ]  WARN "Announcement file not found: /etc/ood/config/announcement.yml"
App 1671949 output: [2025-06-19 13:35:13 -0400 ]  WARN "Error opening MOTD at \nException: bad URI(is not URI?): nil"
App 1671949 output: [2025-06-19 13:35:13 -0400 ]  INFO "method=GET path=/pun/sys/dashboard/ format=html controller=DashboardController action=index status=200 allocations=17658 duration=50.96 view=23.61"

==> ondemand-nginx/sebastian/access.log <==
unix: - - [19/Jun/2025:13:35:13 -0400] "GET /pun/sys/dashboard HTTP/1.1" 200 11599 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=bggrpydgqvqd3ymsz24wctxsr" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0" "24.246.63.88, 10.1.1.1"
2

Not sure what can be done. I see that it is all time in Dex though, not OnDemand so at least that’s a clue.

Looks like it takes dex 4 seconds to perform lookups and log you in. The remaining 5 seconds, I’m not so sure.

By “fine” I assume you mean “correctly”, but do you also mean “quickly”? You may be able to turn dex’s logging a bit higher and see timings within it to further debug. That’s what I’d do turn the logging up to debug or higher in dex and see what timings there are within it.

3

Hi Jeff,

Thanks for the reply. Yes, LDAP is quick as well. A regular ldap search works instantly. I tried moving the VM disks to local storage, rather than the shared Ceph storage (they’re on Proxmox), but it didn’t seem to help much.

I set apache logging to debug. I can see a pause here:

[Fri Jul 11 10:36:39.475671 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(2601): [client 10.1.1.1:13236] AH00944: connecting http://localhost/pun/sys/dashboard/ to localhost:80, referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj
[Fri Jul 11 10:36:39.475683 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(2637): [client 10.1.1.1:13236] AH02545: http: has determined UDS as /var/run/ondemand-nginx/sebastian/passenger.sock, referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj
[Fri Jul 11 10:36:39.475835 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(2824): [client 10.1.1.1:13236] AH00947: connected /pun/sys/dashboard/ to httpd-UDS:0, referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj
[Fri Jul 11 10:36:39.475932 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(3191): AH02823: http: connection established with Unix domain socket /var/run/ondemand-nginx/sebastian/passenger.sock (*)
[Fri Jul 11 10:36:39.475984 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(3476): AH00962: http: connection complete to 0.0.0.0:0 (httpd-UDS)
[Fri Jul 11 10:36:39.476006 2025] [core:debug] [pid 9628:tid 139787226838592] core.c(5289): (95)Operation not supported: [remote /var/run/ondemand-nginx/sebastian/passenger.sock:12150] AH00139: apr_socket_opt_set(APR_TCP_NODELAY)

==> ondemand-nginx/sebastian/error.log <==
App 9712 output: [2025-07-11 10:36:44 -0400 ]  WARN "Announcement file not found: /etc/ood/config/announcement.yml"
App 9712 output: [2025-07-11 10:36:44 -0400 ]  WARN "Error opening MOTD at \nException: bad URI(is not URI?): nil"
App 9712 output: [2025-07-11 10:36:44 -0400 ]  INFO "execve = [{\"SLURM_CONF\"=>\"/opt/slurm/etc/slurm.conf\"}, \"/opt/slurm/bin/sacctmgr\", \"-nP\", \"show\", \"users\", \"withassoc\", \"format=account,cluster,partition,qos\", \"where\", \"user=sebastian\"]"
App 9712 output: [2025-07-11 10:36:44 -0400 ]  INFO "execve = [{\"SLURM_CONF\"=>\"/opt/slurm/etc/slurm.conf\"}, \"/opt/slurm/bin/scontrol\", \"show\", \"part\", \"-o\"]"
App 9712 output: [2025-07-11 10:36:44 -0400 ]  INFO "method=GET path=/pun/sys/dashboard/ format=html controller=DashboardController action=index status=200 allocations=121030 duration=422.48 view=277.67"

==> ondemand-nginx/sebastian/access.log <==
unix: - - [11/Jul/2025:10:36:44 -0400] "GET /pun/sys/dashboard/ HTTP/1.1" 200 12393 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0" "24.246.63.88, 10.1.1.1"

==> apache2/ondemand.vectorinstitute.ai_error_ssl.log <==
[Fri Jul 11 10:36:44.780062 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(2553): AH00943: *: has released connection for (*)
[Fri Jul 11 10:36:44.780124 2025] [proxy:debug] [pid 9628:tid 139787226838592] proxy_util.c(3400): [remote /var/run/ondemand-nginx/sebastian/passenger.sock:12150] AH02642: proxy: connection shutdown
[Fri Jul 11 10:36:44.780270 2025] [deflate:debug] [pid 9628:tid 139787226838592] mod_deflate.c(869): [client 10.1.1.1:13236] AH01384: Zlib: Compressed 12380 to 3378 : URL /pun/sys/dashboard/, referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj
[Fri Jul 11 10:36:44.781256 2025] [lua:info] [pid 9628:tid 139787226838592] [client 10.1.1.1:13236] res_content_disp="" local_user="sebastian" allowed_hosts="ondemand.vectorinstitute.ai" req_status="200" log_id="aHEhd_WFYU1H6jZAQwVADQAAAE4" req_is_https="true" req_content_type="" res_content_location="" req_handler="proxy:unix:/var/run/ondemand-nginx/sebastian/passenger.sock|http://localhost" req_user_agent="Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0" req_hostname="ondemand.vectorinstitute.ai" req_is_websocket="false" res_content_type="text/html; charset=utf-8" req_protocol="HTTP/1.1" req_accept="text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8" req_accept_encoding="gzip, deflate, br, zstd" req_port="443" time_proxy="5305.653" req_server_name="ondemand.vectorinstitute.ai" req_filename="proxy:http://localhost/pun/sys/dashboard/" req_accept_language="en-us,en;q=0.5" req_referer="https://ondemand.vectorinstitute.ai/dex/auth/ldap/login" log_time="2025-07-11T14:36:44.781065.0Z" res_content_length="3396" res_location="" req_accept_charset="" time_user_map="0.003" res_content_language="" remote_user="sebastian" req_cache_control="" req_origin="" res_content_encoding="gzip" req_uri="/pun/sys/dashboard/" req_method="GET" req_user_ip="10.1.1.1" log_hook="ood", referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj

==> apache2/ondemand.vectorinstitute.ai_access_ssl.log <==
10.1.1.1 - sebastian [11/Jul/2025:10:36:39 -0400] "GET /pun/sys/dashboard/ HTTP/1.1" 200 4772 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=t7zdioyesmejnfo63gte33voj" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"

==> apache2/ondemand.vectorinstitute.ai_error_ssl.log <==
[Fri Jul 11 10:36:44.878528 2025] [ssl:info] [pid 9627:tid 139788116006464] [client 10.1.1.1:13252] AH01964: Connection to child 6 established (server ondemand.vectorinstitute.ai:443)
[Fri Jul 11 10:36:44.878556 2025] [ssl:info] [pid 9628:tid 139787210053184] [client 10.1.1.1:13254] AH01964: Connection to child 80 established (server ondemand.vectorinstitute.ai:443)
[Fri Jul 11 10:36:44.878639 2025] [ssl:debug] [pid 9628:tid 139787218445888] ssl_engine_kernel.c(415): [client 10.1.1.1:13236] AH02034: Subsequent (No.8) HTTPS request received for child 79 (server ondemand.vectorinstitute.ai:443), referer: https://ondemand.vectorinstitute.ai/pun/sys/dashboard/
[Fri Jul 11 10:36:44.878778 2025] [authz_core:debug] [pid 9628:tid 139787218445888] mod_authz_core.c(815): [client 10.1.1.1:13236] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://ondemand.vectorinstitute.ai/pun/sys/dashboard/
[Fri Jul 11 10:36:44.878803 2025] [authz_core:debug] [pid 9628:tid 139787218445888] mod_authz_core.c(815): [client 10.1.1.1:13236] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://ondemand.vectorinstitute.ai/pun/sys/dashboard/
[Fri Jul 11 10:36:44.878820 2025] [auth_openidc:debug] [pid 9628:tid 139787218445888] src/mod_auth_openidc.c(3952): [client 10.1.1.1:13236] oidc_check_user_id: incoming request: "/pun/sys/dashboard/apps/icon/codeserver/sys/sys?(null)", ap_is_initial_req(r)=1, referer: https://ondemand.vectorinstitute.ai/pun/sys/dashboard/
4

Here is a bigger dump of logs. I’m also reading and trying to parse them, but am not confident I can understand them.

## entered credentials and pressed log in

[Fri Jul 11 10:44:39.696407 2025] [ssl:info] [pid 8901:tid 140052709504576] [client 10.1.1.1:23168] AH01964: Connection to child 14 established (server ondemand.vectorinstitute.ai:443)
[Fri Jul 11 10:44:39.696823 2025] [ssl:debug] [pid 8901:tid 140052709504576] ssl_engine_kernel.c(2395): [client 10.1.1.1:23168] AH02043: SSL virtual host for servername ondemand.vectorinstitute.ai found
[Fri Jul 11 10:44:39.696867 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(545): AH00835: socache_shmcb_retrieve (0x00 -> subcache 0)
[Fri Jul 11 10:44:39.696880 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(931): AH00851: shmcb_subcache_retrieve found no match
[Fri Jul 11 10:44:39.696889 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(556): AH00836: leaving socache_shmcb_retrieve successfully
[Fri Jul 11 10:44:39.696976 2025] [core:debug] [pid 8901:tid 140052709504576] protocol.c(2460): [client 10.1.1.1:23168] AH03155: select protocol from , choices=http/1.1,h2 for server ondemand.vectorinstitute.ai
[Fri Jul 11 10:44:39.698182 2025] [ssl:debug] [pid 8901:tid 140052709504576] ssl_engine_kernel.c(2254): [client 10.1.1.1:23168] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_128_GCM_SHA256 (128/128 bits)
[Fri Jul 11 10:44:39.698258 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0xee -> subcache 14)
[Fri Jul 11 10:44:39.698309 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(862): AH00847: insert happened at idx=2, data=(415:447)
[Fri Jul 11 10:44:39.698319 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=0/3, data_pos/data_used=0/635
[Fri Jul 11 10:44:39.698327 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Fri Jul 11 10:44:39.698422 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0xd0 -> subcache 16)
[Fri Jul 11 10:44:39.698452 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(862): AH00847: insert happened at idx=0, data=(0:32)
[Fri Jul 11 10:44:39.698467 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/220
[Fri Jul 11 10:44:39.698476 2025] [socache_shmcb:debug] [pid 8901:tid 140052709504576] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Fri Jul 11 10:44:39.698758 2025] [ssl:debug] [pid 8901:tid 140052709504576] ssl_engine_kernel.c(415): [client 10.1.1.1:23168] AH02034: Initial (No.1) HTTPS request received for child 14 (server ondemand.vectorinstitute.ai:443)
[Fri Jul 11 10:44:39.698808 2025] [authz_core:debug] [pid 8901:tid 140052709504576] mod_authz_core.c(843): [client 10.1.1.1:23168] AH01628: authorization result: granted (no directives)
[Fri Jul 11 10:44:39.699063 2025] [proxy:debug] [pid 8901:tid 140052709504576] mod_proxy.c(1513): [client 10.1.1.1:23168] AH01143: Running scheme http handler (attempt 0)
[Fri Jul 11 10:44:39.699085 2025] [proxy:debug] [pid 8901:tid 140052709504576] proxy_util.c(2538): AH00942: http: has acquired connection for (localhost)
[Fri Jul 11 10:44:39.699097 2025] [proxy:debug] [pid 8901:tid 140052709504576] proxy_util.c(2601): [client 10.1.1.1:23168] AH00944: connecting http://localhost:5556/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 to localhost:5556
[Fri Jul 11 10:44:39.699109 2025] [proxy:debug] [pid 8901:tid 140052709504576] proxy_util.c(2824): [client 10.1.1.1:23168] AH00947: connected /dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 to localhost:5556
[Fri Jul 11 10:44:39.700552 2025] [proxy:debug] [pid 8901:tid 140052709504576] proxy_util.c(2553): AH00943: http: has released connection for (localhost)
[Fri Jul 11 10:44:39.700635 2025] [deflate:debug] [pid 8901:tid 140052709504576] mod_deflate.c(869): [client 10.1.1.1:23168] AH01384: Zlib: Compressed 2257 to 876 : URL /dex/auth/ldap/login

==> apache2/ondemand.vectorinstitute.ai_access_ssl.log <==
10.1.1.1 - - [11/Jul/2025:10:44:39 -0400] "GET /dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 HTTP/1.1" 200 3852 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"

pause

==> apache2/ondemand.vectorinstitute.ai_error_ssl.log <==
[Fri Jul 11 10:44:43.808244 2025] [ssl:debug] [pid 8901:tid 140052701111872] ssl_engine_kernel.c(415): [client 10.1.1.1:23168] AH02034: Subsequent (No.2) HTTPS request received for child 15 (server ondemand.vectorinstitute.ai:443)
[Fri Jul 11 10:44:43.808359 2025] [authz_core:debug] [pid 8901:tid 140052701111872] mod_authz_core.c(843): [client 10.1.1.1:23168] AH01628: authorization result: granted (no directives)
[Fri Jul 11 10:44:43.808660 2025] [proxy:debug] [pid 8901:tid 140052701111872] mod_proxy.c(1513): [client 10.1.1.1:23168] AH01143: Running scheme http handler (attempt 0)
[Fri Jul 11 10:44:43.808687 2025] [proxy:debug] [pid 8901:tid 140052701111872] proxy_util.c(2538): AH00942: http: has acquired connection for (localhost)
[Fri Jul 11 10:44:43.808703 2025] [proxy:debug] [pid 8901:tid 140052701111872] proxy_util.c(2601): [client 10.1.1.1:23168] AH00944: connecting http://localhost:5556/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 to localhost:5556
[Fri Jul 11 10:44:43.808718 2025] [proxy:debug] [pid 8901:tid 140052701111872] proxy_util.c(2824): [client 10.1.1.1:23168] AH00947: connected /dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 to localhost:5556
[Fri Jul 11 10:44:43.810222 2025] [proxy:debug] [pid 8901:tid 140052701111872] proxy_util.c(2553): AH00943: http: has released connection for (localhost)
[Fri Jul 11 10:44:43.810336 2025] [deflate:debug] [pid 8901:tid 140052701111872] mod_deflate.c(869): [client 10.1.1.1:23168] AH01384: Zlib: Compressed 2257 to 876 : URL /dex/auth/ldap/login

==> apache2/ondemand.vectorinstitute.ai_access_ssl.log <==
10.1.1.1 - - [11/Jul/2025:10:44:43 -0400] "GET /dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 HTTP/1.1" 200 1264 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"

==> apache2/ondemand.vectorinstitute.ai_error_ssl.log <==
[Fri Jul 11 10:44:48.812574 2025] [ssl:debug] [pid 8901:tid 140052692719168] ssl_engine_io.c(1147): [client 10.1.1.1:23168] AH02001: Connection closed to child 16 with standard shutdown (server ondemand.vectorinstitute.ai:443)

pause

now the dashboard loaded for me - 15 seconds later

[Fri Jul 11 10:44:55.579992 2025] [ssl:info] [pid 8901:tid 140052684326464] [client 10.1.1.1:23190] AH01964: Connection to child 17 established (server ondemand.vectorinstitute.ai:443)
[Fri Jul 11 10:44:55.580392 2025] [ssl:debug] [pid 8901:tid 140052684326464] ssl_engine_kernel.c(2395): [client 10.1.1.1:23190] AH02043: SSL virtual host for servername ondemand.vectorinstitute.ai found
[Fri Jul 11 10:44:55.580436 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(545): AH00835: socache_shmcb_retrieve (0x0b -> subcache 11)
[Fri Jul 11 10:44:55.580453 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(931): AH00851: shmcb_subcache_retrieve found no match
[Fri Jul 11 10:44:55.580463 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(556): AH00836: leaving socache_shmcb_retrieve successfully
[Fri Jul 11 10:44:55.580568 2025] [core:debug] [pid 8901:tid 140052684326464] protocol.c(2460): [client 10.1.1.1:23190] AH03155: select protocol from , choices=http/1.1,h2 for server ondemand.vectorinstitute.ai
[Fri Jul 11 10:44:55.581844 2025] [ssl:debug] [pid 8901:tid 140052684326464] ssl_engine_kernel.c(2254): [client 10.1.1.1:23190] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_128_GCM_SHA256 (128/128 bits)
[Fri Jul 11 10:44:55.581919 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x92 -> subcache 18)
[Fri Jul 11 10:44:55.581938 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(862): AH00847: insert happened at idx=1, data=(221:253)
[Fri Jul 11 10:44:55.581947 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=0/2, data_pos/data_used=0/441
[Fri Jul 11 10:44:55.581956 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Fri Jul 11 10:44:55.582051 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x27 -> subcache 7)
[Fri Jul 11 10:44:55.582068 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(862): AH00847: insert happened at idx=1, data=(194:226)
[Fri Jul 11 10:44:55.582077 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=0/2, data_pos/data_used=0/414
[Fri Jul 11 10:44:55.582085 2025] [socache_shmcb:debug] [pid 8901:tid 140052684326464] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Fri Jul 11 10:44:55.582366 2025] [ssl:debug] [pid 8901:tid 140052684326464] ssl_engine_kernel.c(415): [client 10.1.1.1:23190] AH02034: Initial (No.1) HTTPS request received for child 17 (server ondemand.vectorinstitute.ai:443), referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4
[Fri Jul 11 10:44:55.582419 2025] [authz_core:debug] [pid 8901:tid 140052684326464] mod_authz_core.c(843): [client 10.1.1.1:23190] AH01628: authorization result: granted (no directives), referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4
[Fri Jul 11 10:44:55.582683 2025] [proxy:debug] [pid 8901:tid 140052684326464] mod_proxy.c(1513): [client 10.1.1.1:23190] AH01143: Running scheme http handler (attempt 0), referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4
[Fri Jul 11 10:44:55.582706 2025] [proxy:debug] [pid 8901:tid 140052684326464] proxy_util.c(2538): AH00942: http: has acquired connection for (localhost)
[Fri Jul 11 10:44:55.582739 2025] [proxy:debug] [pid 8901:tid 140052684326464] proxy_util.c(2601): [client 10.1.1.1:23190] AH00944: connecting http://localhost:5556/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 to localhost:5556, referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4
[Fri Jul 11 10:44:55.582753 2025] [proxy:debug] [pid 8901:tid 140052684326464] proxy_util.c(2824): [client 10.1.1.1:23190] AH00947: connected /dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4 to localhost:5556, referer: https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=s75rmqzojw7agen3uqck2joo4
[Fri Jul 11 10:44:56.011654 2025] [proxy:debug] [pid 8901:tid 140052684326464] proxy_util.c(2553): AH00943: http: has released connection for (localhost)
5

Adding %D to apache log format shows getting the dashboard takes a long time. 10917353 micro seconds = 10.9 seconds. Still have no idea why. Once I do log in and back out, subsequent logins (within a certain amount of time) are quick enough - not sure what is being cached.

127.0.0.1 - - [11/Jul/2025:14:24:03 -0400] 125957 "POST /dex/token HTTP/1.1" 200 1964 "-" "mod_auth_openidc"
127.0.0.1 - - [11/Jul/2025:14:24:03 -0400] 1785 "GET /dex/keys HTTP/1.1" 200 2553 "-" "mod_auth_openidc"
127.0.0.1 - - [11/Jul/2025:14:24:04 -0400] 2018 "GET /dex/userinfo HTTP/1.1" 200 369 "-" "mod_auth_openidc"
10.1.1.1 - sebastian [11/Jul/2025:14:24:03 -0400] 449085 "GET /oidc?code=fj4ervkqsltyofoxbhmnqo5bp&state=7k1xHSm_bYg4YM5bgU0mu
qbkIvg HTTP/1.1" 302 331 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=a5u3uoe42z5obaqiswsrydafx" "Mozi
lla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"
10.1.1.1 - sebastian [11/Jul/2025:14:24:04 -0400] 10917353 "GET /pun/sys/dashboard HTTP/1.1" 200 3042 "https://ondemand.vectorinstitute.ai/dex/auth/ldap/login?back=&state=a5u3uoe42z5obaqiswsrydafx" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"
10.1.1.1 - sebastian [11/Jul/2025:14:24:15 -0400] 128848 "GET /pun/sys/dashboard/apps/icon/codeserver/sys/sys HTTP/1.1" 304 - "https://ondemand.vectorinstitute.ai/pun/sys/dashboard" "Mozilla/5.0 (X11; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0"
6

It could be as simple as it just takes 10 seconds for Nginx and everything else to boot up. That’s around what I’ve observed at OSC.