0

So... who likes detective work, pouring over a log record??? Here's one for the sleuths amongst us!

One of our users states they encountered an error page while sitting a quiz on our site. Below I attach some text from our server logs related to the moment they reported.

I think the third column (8 or 9) refers to the thread on the server. So at 07:36:31, the user is having an HTML reponse being prepared for them via a series of function calls in response to a POST from the user (answering previous quiz question).

But after a second POST from the user at 07:36:44 for some reason the server seems to have spawned two threads running in parallel in response to what I presume is a single POST request.

You can see the error at the end and the reason for it. For the first thread (8), an entry was saved to the database. When the second thread reaches that point just milliseconds later, we get an integrity error because a record with that key already exists (thanks to thread 8).

I've never had this problem before. Any ideas as to WHY suddenly our server decided to suddenly spawn two threads resulting in an unexpected race condition??

My technology stack: * Heroku server * Django python web framework

07:36:31 : 95.XX.67.113      https:POST   status:200  "/en/main/"
..<snip>..
07:36:31 : wrappers       9  INFO   : User Aysegul: starting main.views.quiz_class.ask_quiz_question    
07:36:31 : wrappers       9  INFO   : User Aysegul: starting grammar.views.assess.run_quiz
07:36:31 : wrappers       9  INFO   : User Aysegul: starting main.views.quiz_class.get_next_scheduled_q
07:36:31 : wrappers       9  INFO   : User Aysegul: starting main.views.quiz_class.ask_quiz_question
07:36:44 : 95.XX.67.113      https:POST   status:200  "/en/main/"
07:36:44 : wrappers       8  INFO   : User Aysegul: starting main.views.main.switchboard
07:36:44 : wrappers       9  INFO   : User Aysegul: starting main.views.main.switchboard
07:36:44 : wrappers       8  INFO   : User Aysegul: starting main.views.main.load_session_data
07:36:44 : wrappers       9  INFO   : User Aysegul: starting main.views.main.load_session_data
07:36:44 : user_profile   8  DEBUG  : Model UserProfile Instance saved:[<User: Aysegul>]
07:36:44 : main           8  DEBUG  : Aysegul switchboard - returning control back to run_quiz
07:36:44 : wrappers       8  INFO   : User Aysegul: starting grammar.views.assess.run_quiz
07:36:44 : user_profile   9  DEBUG  : Model UserProfile Instance saved:[<User: Aysegul>]
07:36:44 : main           9  DEBUG  : Aysegul switchboard - returning control back to run_quiz
07:36:44 : wrappers       9  INFO   : User Aysegul: starting grammar.views.assess.run_quiz
07:36:44 : wrappers       8  INFO   : User Aysegul: starting main.views.quiz_class.record_answer
07:36:44 : wrappers       9  INFO   : User Aysegul: starting main.views.quiz_class.record_answer
07:36:44 : wrappers       8  INFO   : User Aysegul: starting main.views.quiz_class.question_feedback
07:36:44 : log            9  ERROR  : Internal Server Error: /en/main/
07:36:44 : Traceback (most recent call last):
07:36:44 :   File "/app/.heroku/python/lib/python3.6/site-packages/django/db/backends/utils.py", line 85, in _execute
07:36:44 :     return self.cursor.execute(sql, params)
07:36:44 : psycopg2.IntegrityError: duplicate key value violates unique constraint "grammar_entry_question_id_text_d90c1
7cd_uniq"
07:36:44 : DETAIL:  Key (question_id, text)=(1385, Üç günden beri hasta oluyor) already exists.

P.S. Interestingly this issue also occured with a heroku/django combination... Heroku one request spawns two responses that crashes my app

talkingtoaj
  • 848
  • 8
  • 27

1 Answers1

0

Reading around, I think the answer is this:

Heroku's router may occasionally malfunction and spawn two response threads for a single received request. This is unfortunate, but luckily rare.

A potential solution might be to have your backend code check if a request thread is already underway for the user (for example by writing a timestamp to the database or a shared universal cache). If another thread is underway, then the latter thread could quit.

talkingtoaj
  • 848
  • 8
  • 27