Gateway Timeout on validation page during load

[hepcat72]

BUG DESCRIPTION

Problem

There appears to be an infrequent issue where form submissions on the start a submission page randomly hang and encounter a gateway timeout. THIS MAY ONLY BE DURING A LOAD ON THE COMMAND LINE OR DURING CONCURRENT VALIDATIONS.

Steps to reproduce

• Concurrent load and validation
  1. Edit TraceBase/.env to set SQL_LOGGING=True
  2. In terminal window 1
  3. python manage.py runserver
  4. In terminal window 2
  5. python manage.py load_study --infile __a_large_study_doc_like_the_water_study__
  6. In browser window 1, on the submission validate page (after noting that the load has started making SQL queries)
  7. Submit a large study doc, like the water study
• Concurrent validation submissions
  1. Edit TraceBase/.env to set SQL_LOGGING=True
  2. In terminal window 1
  3. python manage.py runserver
  4. In browser window 1, on the submission validate page
  5. Submit a large study doc, like the water study
  6. In browser window 2, on the submission validate page (after noting that the first validation has started making SQL queries)
  7. Submit a large study doc, like the water study

Previous Notes:

I have not been able to make it happen on purpose, but it can happen with apparently any submission, regardless of size. A study doc submission that repeatedly takes perhaps 3 seconds can encounter the timeout. It might have something to do with concurrent user submissions or perhaps a browser cache issue (though I seriously doubt it), because it can happen repeatedly, and happened to succeed after restarting the browser.

Perhaps a resource contention or deadlock? The file that I was using when I encountered the timeout was: study_workbook-johns_errors1.xlsx

Current behavior

The Concurrent load and validation case above is the clearest example, because you can see the SQL query that hangs in the runserver window:

SELECT "DataRepo_study"."id", "DataRepo_study"."name", "DataRepo_study"."description" FROM "DataRepo_study" WHERE ...

And you can watch the progress of the load in the other terminal window. When the load finishes, you can observe that the validation process resumes immediately.

In the Concurrent validation submissions case, it's harder to see what is going on, because both jobs are outputting to the same console, but you can time the 2 browser windows and note that the second window takes twice as long as the first one.

Previous Notes:

The page hangs for maybe a minute and then you get a gateway timeout. The log files are too verbose right now (intentionally for (issue-specific) debugging on dev) to find these random occurrences, but I did obtain access to the web logs and could not find anything obvious with a brief glance (hours after the issue occurred) - needs a focussed look. Sven said that memory usage was completely fine, but there was some heavy cpu usage that could have caused the issue, though the timing didn't seem to correspond with the first occurrence (first occurrence was before 12:19pm July 29th 2024) and the spike in the logs was around 2:15pm (that could have corresponded with us encountering the issue while trying to debug it).

It's possible it could be data-specific maybe (although I feel like that's a long shot, since the same file can either take 3 seconds or time out)?

It's also possible it could be related to CAS, as the file being submitted was at one point, selected off the ms data share, which required netid authentication to mount...

Expected behavior

Every validation job should finish without a timeout error, despite concurrent requests.

Suggested Change

There are 2 things to solve here:

1. Long running database loads that can take in excess of an hour should definitely be a sort of downtime maintenance thing. At the least, the validation page (and admin edit pages) could have downtime messages.
2. Concurrent study validation requests (any one of which should take under a minute), are effectively processed serially, meaning that if the combined running time of 2 jobs is over a minute, the second one will encounter a timeout error.

There are a number of possible steps to take to deal with the concurrent validation issue:

• The likely impossible holy grail option: In some way, tell the database to ignore table/row locks because we promise not to commit anything.
• Optimize the loading code to make it as fast as possible so that multiple concurrent submissions, despite having to run serially, complete within the server's timeout deadline. The problem here is that there's only so much you can do in this regard. The simple fact is, we're dealing with large datasets, and with automated peak picking, it is expected to grow by up to 2 orders of magnitude.
• In some way, catch these blocking concurrent validations and
  • Tell the user that the server is busy, and to try again later.
  • Schedule validation jobs and email the results.
• Employ an asynchronous job scheduler like Celery that spawns the job in a separate process that reports progress in the form of a waiting page/progress bar.
• Implement a totally different validation process that only makes queries instead of attempting loads inside an atomic transaction that never commits.

Previous Notes:

If this is due to concurrent submissions or submissions during a command line (dry-run) load, we may be able to queue submissions and/or temporarily disable validation during loads. We should probably also schedule loads to happen over night. The issue can also be mitigated by speeding up the load scripts.

~We need to figure out how to reproduce the issue reliably. I was thinking of trying multiple concurrent submissions to see if that can cause it, but I haven't done it yet. Should also watch the log.~

Comment

None

---

ISSUE OWNER SECTION

Assumptions

1. List of assumptions made WRT the code
2. E.g. We will assume input is correct (explaining why there is no validation)

Limitations

1. A list of things this work will specifically not do
2. E.g. This feature will only handle the most frequent use case X

Affected Components

• change: File path or DB table ...
• add: Environment variable or server setting
• delete: External executable or cron job

Requirements

• [ ] 1. List of numbered conditions to be met for the feature
• [ ] 2. E.g. Every column/row must display a value, i.e. cannot be empty
• [ ] 3. Numbers for reference & checkboxes for progress tracking

DESIGN

GUI Change description

None provided

Code Change Description

None provided

Tests

• [ ] 1. A description of at least one test for each requirement above.
• [ ] 2. E.g. Test for req 2 that there's an exception when display value is ''
• [ ] 3. Numbers for reference & checkboxes for progress tracking

[hepcat72]

A couple weeks ago, Sven implemented a way to always allow access to the web logs. I just ran into a gateway timeout error and at the end of the tracebase error log, I see this:

Timeout when reading response headers from daemon process 'tracebase': /var/www/tracebase/TraceBase/wsgi.py, referer: https://tracebase-dev.princeton.edu/DataRepo/submission

This appears to be potentially due to C extension packages being run in sub-interpreters (which explains the randomness of the issue), according to:

• https://stackoverflow.com/a/40414207/2057516
• https://serverfault.com/a/514251/271933

The solution is to add this to the httpd.conf file:

WSGIApplicationGroup %{GLOBAL}

[hepcat72]

The full log line on tracebase-dev that alerted me to the cause:

/var/log/httpd/tracebase-error_log

[Sun Sep 01 12:21:00.236470 2024] [wsgi:error] [pid 1807785:tid 1807825] [client 172.20.196.21:60293] Timeout when reading response headers from daemon process 'tracebase': /var/www/tracebase/TraceBase/wsgi.py, referer: https://tracebase-dev.princeton.edu/DataRepo/submission

[hepcat72]

@jcmatese - I think I found the cause of those timeouts you reported. See above.

[hepcat72]

I will point out that it appears that the timeouts seem to repeatedly (anecdotally) coincide with me running a load on the command line (i.e. not an apache process).

[hepcat72]

Sven implemented the above suggestion from ticket 105658. I will see if I can reproduce the timeout on dev and get back to Sven about also implementing on prod.

@jcmatese - Could you please see if you can get your gateway timeout to happen again on dev?

[hepcat72]

Sven's changes appeared to break tracebase-dev. He reverted those changes. I poked around in the linked stack posts some more. It looks like there could be multiple possible contention problems. The next likely candidate is database access, as this did happen while I was running a load script on tracebase-dev. I'm going to do some more testing to confirm that possibility.

In the meantime @jcmatese - there's no need for you to test anything.

[hepcat72]

I asked on the Django forum and they said that it could be due to the atomic transaction. To debug, they referred me to a postgresql doc on lock monitoring. Here is the forum post link:

https://forum.djangoproject.com/t/operability-during-long-running-loads/35843/2

[hepcat72]

I did some testing on this today and learned some things...

I tested 2 scenarios:

• Run a validation during a command line load
  • Conditions: I ran a load of a large study doc on the command line and then tried to validate the same large study doc on the submission validate page, in my sandbox. Each takes approximately 1 minute to run. I started the command line load, and waited for the console to start spitting out load messages, then I started the validation and watched the console in another terminal window.
  • Results:
  • The web console (validation) hung at the first get_or_create on the Study model and did not proceed until the load in the other terminal window finished.
  • Conclusion:
  • Based on my reading, the atomic transaction makes create or get_or_create calls in the second submission to hang/wait until the first transaction releases its model and/or row locks.
  • Usually, loading involves the peak annotation files, which takes much longer to run (currently, an hour or more). I only loaded the study doc, which takes under a minute. This would mean that anytime there's a load going, the submission validate interface is effectively disabled and will produce timeout errors.
• Run 2 concurrent validations at the same time in different browser windows
  • Conditions: I ran the same large study doc in 2 windows using my sandbox. Each takes approximately 1 minute to validate. I started one, and waited for the console to start spitting out load messages, then I started the other.
  • Results:
  • The first submission finished in just under a minute.
  • The second submission took just under 2 minutes.
  • Conclusion:
  • Based on my reading, the atomic transaction makes create or get_or_create calls in the second submission to hang/wait until the first transaction releases its model and/or row locks.
  • Usually, study docs will be relatively small and take a handful of seconds to complete, meaning that 2 or 3 concurrent validations are not a big deal. Losers (those who submit 2nd or 3rd) will just have to wait longer.

Discussion

It seems to me that, given my understanding of atomic transactions from the django docs, it is DB row locks that are likely happening that make subsequent create-related operations hang until the lock is released. Queries are supposed to be able to work during these transactions, and given the SQL output I observed in my testing, a few pure selects did work before it got to the Study record creation. Likely, specific rows can be locked for update-purposes occurring in the transaction, but probably new row creations are locked as well - or perhaps it specifically has to do with AutoFields - so that you're not skipping numbers in other transactions when the first transaction fails and rolls back? Regardless, the end result is that only 1 validation or load can happen at one time.

I could not find a way to allow concurrent atomic transactions that do loads.

I did find a way to be able to test to see if a lock currently exists...

try:
    Study.objects.select_for_update(nowait=True).get_or_create(**rec_dict)
except DatabaseError as de:
    # A lock exists that prevents us from creating a record

I'm not actually sure if the above actually works on a create or get_or_create (the docs use .filter()), but if it does, this could be used to tell the user to wait and try again later, or report what position in the queue they're in.

It may also be required that this has to be executed outside of any atomic transaction...

According to the django docs:

Usually, if another transaction has already acquired a lock on one of the selected rows, the query will block until the lock is released. If this is not the behavior you want, call select_for_update(nowait=True). This will make the call non-blocking. If a conflicting lock is already acquired by another transaction, DatabaseError will be raised when the queryset is evaluated.

Conclusion

A quick solution might be to check if there's a lock on a row of the study table. If there is, render a page for the user that tells them that the server is busy and to try again later.

A more complete solution would be to finally install celery and queue up these jobs, reporting the users in front of the current request.

An ultimate solution (which I don't think is possible) would be to tell django that we intend to roll back anyway and just allow the validation to proceed as if this will never be committed. I.e. don't reserve an ID in an AutoField and we don't care if another process is updating the same record.