Django.log displaying handling duplicate doc id

Hello there,

while looking at the Django logs I've seen something like the following:

021-03-09 12:39:29,114 INFO Handling duplicate doc id 0a4c6197-79d4-4fb9-8216-23578047b135 for domain fmoh-echis
2021-03-09 12:39:29,887 INFO Finished duplicate processing for Form 11a331f3-5e27-4821-977e-bd0d5708fac6 with original id 0a4c6197-79d4-4fb9-8216-23578047b1352
.......

> ......and get another error after a while(not lnked with the above output actually)

2021-03-09 19:16:14,400 INFO Processing form 51021541-cfdc-4b78-a5cd-85ab71978f43 as a device log
2021-03-09 19:16:15,202 INFO Processing form 70ff021c-3de1-49e7-84a1-dc4d0fabd972 as a device log
2021-03-09 19:16:15,407 INFO Processing form 70ff021c-3de1-49e7-84a1-dc4d0fabd972 as a device log
2021-03-09 19:16:15,613 ERROR Notify Exception: Error processing device log
Traceback (most recent call last):
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/backends/utils.py", line 84, in _execute
return self.cursor.execute(sql, params)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "phonelog_userentry_xform_id_i_8d53578a_uniq"
DETAIL: Key (xform_id, i)=(70ff021c-3de1-49e7-84a1-dc4d0fabd972, 0) already exists.

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
File "/home/cchq/www/echis/releases/2021-03-08_16.29/corehq/form_processor/submission_post.py", line 553, in process_device_log
process_device_log(self.domain, device_log_form, self.force_logs)
File "/usr/lib/python3.6/contextlib.py", line 52, in inner
return func(*args, **kwds)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/corehq/ex-submodules/phonelog/utils.py", line 55, in process_device_log
_process_user_subreport(xform)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/corehq/ex-submodules/phonelog/utils.py", line 77, in _process_user_subreport
UserEntry.objects.bulk_create(to_save)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/models/manager.py", line 82, in manager_method
return getattr(self.get_queryset(), name)(*args, *kwargs)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/models/query.py", line 474, in bulk_create
ids = self._batched_insert(objs_without_pk, fields, batch_size, ignore_conflicts=ignore_conflicts)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/models/query.py", line 1204, in _batched_insert
ignore_conflicts=ignore_conflicts,
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/models/query.py", line 1186, in _insert
return query.get_compiler(using=using).execute_sql(return_id)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 1377, in execute_sql
cursor.execute(sql, params)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/sentry_sdk/integrations/django/init.py", line 489, in execute
return real_execute(self, sql, params)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/backends/utils.py", line 67, in execute
return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/backends/utils.py", line 76, in _execute_with_wrappers
return executor(sql, params, many, context)
File "/home/cchq/www/echis/releases/2021-03-08_16.29/python_env-3.6/lib/python3.6/site-packages/django/db/backends/utils.py", line 84, in _execute
[0] 0:[tmux]

Is this normal or some kind of problem with blob storage? I said this because I have made some modifications with the minio proxy server (nginx in our case). That is i enable caching for recently accessed blob data.

The duplicate issue is not uncommon, and can happen if the phone submits a form and doesn't receive a success response from HQ (which can just be a race condition related to network failures, etc.). It will retry and HQ just treats the form as a duplicate.

I'm not familiar with the device log stack trace, but I suspect it's not a problem. It looks like the duplicate form is a deice log which has already been processed, and it's failing to be processed a second time. Probably we should have checks that don't process duplicate device logs if we don't already.