Internal Server Error on first login & interactive apps rsync input/output error issue

All,

Apologies for the posts recently as we work through issues and solve them, we are working on OnDemand integration with Duo/ADFS on a new VM and could use some guidance.

Everything seems to be working well except we have a strange issue, where the first time anyone logs in, they are presented with a page “Internal Server Error: The server encountered an internal error or misconfiguration and was unable to complete your request…”. As soon as the person refreshes the page, they are logged in without further issue. I do not see anything out of the ordinary in the logs. Is there something we can look at that might point to what the issue is?

Another user seems to be having an issue when launching interactive apps. They get:

rsync: mkstemp “/home/user/ondemand/data/sys/dashboard/batch_connect/sys/jupyterlab/output/6a9ca682-cf2b-4ab8-89ae-86681ec79cf6/.after.sh.HBJD5t” failed: Input/output error (5)
rsync: mkstemp “/home/user/ondemand/data/sys/dashboard/batch_connect/sys/jupyterlab/output/6a9ca682-cf2b-4ab8-89ae-86681ec79cf6/.before.sh.erb.oTykOr” failed: Input/output error (5)
rsync: mkstemp “/home/user/ondemand/data/sys/dashboard/batch_connect/sys/jupyterlab/output/6a9ca682-cf2b-4ab8-89ae-86681ec79cf6/.script.sh.erb.0PXcxp” failed: Input/output error (5)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1179) [sender=3.1.2]

Others have the same issue, other users, like me, can launch the interactive apps just fine.

Any ideas on how to solve these two issues would be greatly appreciated.

No issues with the posts - we budget both in time and money for answering questions. So that’s no issue at all!

There should be something in apache’s error logs /var/log/httpd24-httpd for this. Whether it’s meaningful or not I can’t say but that’s our best bet to see any output there.

My guess is, there’s something funny with one of your HOME drives. At OSC our HOME drives are partitioned to maybe 4-5 storage nodes. One can blow up with a lot of lag and affect a certain number of folks but not others.

That is, my thinking is one of your storage devices is not working well, so it affects a subset of your users. Those users who happen to use that storage device.

There may be something in dmesg or journalctl about this, but I’m guessing you’ll have to run more tests on that file location with your storage folks.

Thanks Jeff for the reply. Good news is, we’ve resolved the issue with the input/output error. However, still getting the Internal Server Error just on the first login for people.

We’ve looked through the logs and really cannot see anything out of the ordinary that would cause this problem. We see the user map successfully, and that’s it, nothing more in the logs to note. It’s on debug as well so we should be getting all of the output. Do you know of anyone else who has seen this issue? A refresh of the page always fixes it, but it throws people off when they first see the error and they think the site is down.

That’s good to hear about the disk drives.

As to your auth issues, I’m not sure. Seems like something in the ADFS handshake flow is going wrong? Maybe you can try MellonDiagnosticsEnable and/or get some info from the browser.

This is an example of what I’d be looking for. From chrome, because chrome can capture stuff on redirects (though you may have to enable it?).

In any case, you can se I get a 302, 302, then I hit the dashboard with 200 response codes. I’m wondering what your flow looks like and where you’re 500 is coming from (which page/network call).

Jeff, I have quite a few logs to report back on, I don’t know if much of this is relevant to the issue with “Internal Server Error” or not. What I am pasting is an attempt from one of our users, it failed with “internal server error” at first then he refreshed and got in. If people get this error, they are always able to refresh the page and get in immediately after. Usually that error will appear, but not always. Apologies in advance for the incoming wall of text.

I diffed the two entries where someone had an unsuccessful login vs. a successful login. These are the only differences that I see, again not sure of relevance:

Successful: has req_handler=“proxy_server” (unsuccessful has req_handler=“”)
Successful: has res_content_length=“9018” (unsuccessful has res_content_length=“527”)
Successful: has req_referer=“https://ondemand.sdstate.edu/pun/sys/dashboard” (unsuccessful has req_referer=“https://adfs.sdstate.edu/”)
Successful: has res_content_disp=“inline; filename=‘icon.png’” (unsuccessful has res_content_disp=“”)
Successful: has req_filename=“proxy:http://localhost/pun/sys/dashboard/apps/icon/RStudio/sys/sys” req_uri=“/pun/sys/dashboard/apps/icon/RStudio/sys/sys” (unsuccessful has req_filename=“/opt/rh/httpd24/root/var/www/html/pun” req_uri=“/pun/sys/dashboard”)
Successful: has req_accept_encoding=“gzip, deflate, br”, referer: https://adfs.sdstate.edu/ (unsuccessful has req_accept_encoding=“gzip, deflate, br”, referer: https://ondemand.sdstate.edu/pun/sys/dashboard)

[Tue Aug 09 13:32:00.576456 2022] [ssl:info] [pid 17136] [client IP:60527] AH01964: Connection to child 8 established (server ondemand.sdstate.edu:443)
[Tue Aug 09 13:32:00.588525 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.588556 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.588562 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.591200 2022] [auth_mellon:debug] [pid 17136] auth_mellon_util.c(2622): [client IP:60527] have_paos_media_type=False valid_paos_header=False is_paos=False error_code=0 ecp options=
[Tue Aug 09 13:32:00.591226 2022] [auth_mellon:debug] [pid 17136] auth_mellon_util.c(54): [client IP:60527] reconstruct_url: url==“https://ondemand.sdstate.edu/pun/sys/dashboard”, unparsed_uri==“/pun/sys/dashboard”
[Tue Aug 09 13:32:00.642330 2022] [auth_mellon:debug] [pid 17136] auth_mellon_handler.c(278): [client IP:60527] loaded IdP “http://adfs.sdstate.edu/adfs/services/trust” from “/opt/rh/httpd24/root/etc/httpd/mellon-new/idpmetadata.xml”.
[Tue Aug 09 13:32:00.642356 2022] [auth_mellon:debug] [pid 17136] auth_mellon_handler.c(3597): [client IP:60527] Redirecting to login URL: https://ondemand.sdstate.edu/mellon/login?ReturnTo=https%3A%2F%2Fondemand.sdstate.edu%2Fpun%2Fsys%2Fdashboard&IdP=http%3A%2F%2Fadfs.sdstate.edu%2Fadfs%2Fservices%2Ftrust
[Tue Aug 09 13:32:00.643029 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.643043 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.643048 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.645859 2022] [auth_mellon:debug] [pid 17136] auth_mellon_util.c(54): [client IP:60527] reconstruct_url: url==“https://ondemand.sdstate.edu/mellon/login?ReturnTo=https%3A%2F%2Fondemand.sdstate.edu%2Fpun%2Fsys%2Fdashboard&IdP=http%3A%2F%2Fadfs.sdstate.edu%2Fadfs%2Fservices%2Ftrust”, unparsed_uri==“/mellon/login?ReturnTo=https%3A%2F%2Fondemand.sdstate.edu%2Fpun%2Fsys%2Fdashboard&IdP=http%3A%2F%2Fadfs.sdstate.edu%2Fadfs%2Fservices%2Ftrust”
[Tue Aug 09 13:32:00.645875 2022] [auth_mellon:debug] [pid 17136] auth_mellon_cookie.c(211): cookie_set: mellon-cookie=cookietest; Version=1; Path=/; Domain=ondemand.sdstate.edu;
[Tue Aug 09 13:32:00.694014 2022] [auth_mellon:debug] [pid 17136] auth_mellon_handler.c(278): [client IP:60527] loaded IdP “http://adfs.sdstate.edu/adfs/services/trust” from “/opt/rh/httpd24/root/etc/httpd/mellon-new/idpmetadata.xml”.
[Tue Aug 09 13:32:00.697231 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.697246 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:00.697252 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table
[Tue Aug 09 13:32:02.093909 2022] [auth_mellon:debug] [pid 17136] auth_mellon_handler.c(278): [client IP:60527] loaded IdP “http://adfs.sdstate.edu/adfs/services/trust” from “/opt/rh/httpd24/root/etc/httpd/mellon-new/idpmetadata.xml”., referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.097656 2022] [auth_mellon:debug] [pid 17136] auth_mellon_util.c(54): [client IP:60527] reconstruct_url: url==“https://ondemand.sdstate.edu/mellon/postResponse”, unparsed_uri==“/mellon/postResponse”, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.097690 2022] [auth_mellon:debug] [pid 17136] auth_mellon_cookie.c(211): cookie_set: mellon-cookie=7757423f37b3bb7e8ef2893476565133; Version=1; Path=/; Domain=ondemand.sdstate.edu;
[Tue Aug 09 13:32:02.097777 2022] [auth_mellon:debug] [pid 17136] auth_mellon_handler.c(551): [client IP:60527] The current LassoProfile object doesn’t contain a LassoIdentity object., referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.097901 2022] [auth_mellon:debug] [pid 17136] auth_mellon_util.c(54): [client IP:60527] reconstruct_url: url==“https://ondemand.sdstate.edu/mellon/postResponse”, unparsed_uri==“/mellon/postResponse”, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.098353 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.098386 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.098396 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103121 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103137 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103143 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103147 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103151 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103156 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103160 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103164 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103169 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103173 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103179 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching user → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103184 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching clock → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.103188 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching escape → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115080 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching clock → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115102 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching debug → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115129 2022] [lua:debug] [pid 17136] @/opt/ood/mod_ood_proxy/lib/ood/user_map.lua(21): [client IP:60527] Mapped ‘firstname.lastname’ => ‘firstname.lastname’ [11.911 ms], referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115135 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115144 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115177 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching unparsed_uri → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115203 2022] [lua:debug] [pid 17136] lua_request.c(1874): [client IP:60527] AH01490: request_rec->dispatching is_https → boolean, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115209 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching hostname → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115213 2022] [lua:debug] [pid 17136] lua_request.c(1865): [client IP:60527] AH01489: request_rec->dispatching port → int, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115223 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching escape → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:02.115229 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching escape → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.117961 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching info → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118006 2022] [lua:info] [pid 17136] [client IP:60527] socket seems to exist on count 0, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118011 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching info → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118594 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118610 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118615 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching subprocess_env → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118619 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching clock → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118636 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching log_id → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118642 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching user → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118646 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching useragent_ip → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118650 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching method → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118654 2022] [lua:debug] [pid 17136] lua_request.c(1865): [client IP:60527] AH01489: request_rec->dispatching status → int, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118657 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching uri → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118661 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching protocol → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118675 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching hostname → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118679 2022] [lua:debug] [pid 17136] lua_request.c(1865): [client IP:60527] AH01489: request_rec->dispatching port → int, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118684 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching server_name → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118688 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching handler → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118691 2022] [lua:debug] [pid 17136] lua_request.c(1856): [client IP:60527] AH01488: request_rec->dispatching filename → string, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118695 2022] [lua:debug] [pid 17136] lua_request.c(1874): [client IP:60527] AH01490: request_rec->dispatching is_https → boolean, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118699 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118705 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118715 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118723 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118729 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118733 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118737 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118741 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118745 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118749 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_in → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118753 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118758 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118762 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118766 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118770 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118777 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118781 2022] [lua:debug] [pid 17136] lua_request.c(1838): [client IP:60527] AH01486: request_rec->dispatching headers_out → apr table, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118844 2022] [lua:debug] [pid 17136] lua_request.c(1848): [client IP:60527] AH01487: request_rec->dispatching info → lua_CFunction, referer: https://adfs.sdstate.edu/
[Tue Aug 09 13:32:04.118855 2022] [lua:info] [pid 17136] [client IP:60527] req_protocol=“HTTP/1.1” req_handler=“” req_method=“GET” req_accept=“text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,/;q=0.8” req_user_agent=“Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:103.0) Gecko/20100101 Firefox/103.0” res_content_length=“527” req_content_type=“” res_content_encoding=“” req_status=“500” req_origin=“” time_user_map=“11.911” local_user=“firstname.lastname” req_referer=“https://adfs.sdstate.edu/” res_content_language=“” req_port=“443” req_is_websocket=“false” req_server_name=“ondemand.sdstate.edu” log_hook=“ood” req_accept_charset=“” req_hostname=“ondemand.sdstate.edu” log_id=“YvKoIs5B1@gywap7TDmyNQAAAAg” res_content_location=“” res_location=“” log_time=“2022-08-09T18:32:04.118622Z” remote_user=“firstname.lastname” req_user_ip=“IP” res_content_disp=“” req_is_https=“true” req_filename=“/opt/rh/httpd24/root/var/www/html/pun” req_uri=“/pun/sys/dashboard” time_proxy=“0” res_content_type=“text/html; charset=iso-8859-1” req_accept_language=“en-us,en;q=0.5” req_cache_control=“” req_accept_encoding=“gzip, deflate, br”, referer: https://adfs.sdstate.edu/

OK - I apologize for this, but that seems to be a red herring. Meaning it would appear that we move past anything that mod_auth_mellon does and in fact fail in our LUA blocks.

I think you still have a patch we were testing some time ago.I believe this was a debug log line that I added to debug another issue you were having - meaning we modified it from the original distribution. I’d reset back to the RPM installed files by re-installing. That’ll wipe all the files we modified and put them back to the originals.

Now the issue at hand looks like we’re failing in code that we wrote ourselves. I wonder if it’s simply a timing issue? That is, we’re passing traffic to the PUN before it’s actually started up? Because if you retry, it immediately starts working.

When this occurs, do you see anything interesting in /var/log/ondemand-nginx/$USER/error.log (the PUNs logs for a given user)?

It would seem we’re trying to contact the PUN and the 500 is originating from it.

Jeff, thanks for the pointers. It may be a couple weeks before we can make any changes to our VM but when we can I will do this and report back.