Service timeout blocks parsing completion

Thank you for taking the time to let us know about the issue you found. The basic rule for bug reporting is that something isn't working the way one would expect it to work. Please provide us with the information requested below and we will look at it as soon as we are able.

Description

Backend did not gracefully handle a connection failure for the elasticsearch service resulting in erroneous status handling.

Action Taken

Data submissions were stuck pending since mid-afternoon.

What I expected to see

Successful upload and parsing of these data files.

What I did see

Bad request, parsing error failures in logs.

Other Helpful Information

Relevant bulk_create line where this uncaught exception happened.

Consider catching ElasticsearchException to avoid running into anymore erroneous uncaught exceptions.

15:33:27.235: [APP/PROC/WEB.0] [2024-06-28 19:33:27,233: WARNING/ForkPoolWorker-1] POST https://vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com:443/_bulk?refresh=true [status:N/A request:10.074s]
15:33:27.235: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.237: [APP/PROC/WEB.0]     errors = parse_datafile(data_file, dfs)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467, in _make_request
15:33:27.235: [APP/PROC/WEB.0]     six.raise_from(e, None)
15:33:27.235: [APP/PROC/WEB.0]   File "<string>", line 3, in raise_from
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 462, in _make_request
15:33:27.235: [APP/PROC/WEB.0]     httplib_response = conn.getresponse()
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/http/client.py", line 1374, in getresponse
15:33:27.235: [APP/PROC/WEB.0]     response.begin()
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/http/client.py", line 318, in begin
15:33:27.235: [APP/PROC/WEB.0]     version, status, reason = self._read_status()
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/http/client.py", line 279, in _read_status
15:33:27.235: [APP/PROC/WEB.0]     line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/socket.py", line 705, in readinto
15:33:27.235: [APP/PROC/WEB.0]     return self._sock.recv_into(b)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/ssl.py", line 1274, in recv_into
15:33:27.235: [APP/PROC/WEB.0]     return self.read(nbytes, buffer)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/ssl.py", line 1130, in read
15:33:27.235: [APP/PROC/WEB.0]     return self._sslobj.read(len, buffer)
15:33:27.235: [APP/PROC/WEB.0] TimeoutError: The read operation timed out
15:33:27.235: [APP/PROC/WEB.0] During handling of the above exception, another exception occurred:
15:33:27.235: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/requests/adapters.py", line 440, in send
15:33:27.235: [APP/PROC/WEB.0]     resp = conn.urlopen(
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 799, in urlopen
15:33:27.235: [APP/PROC/WEB.0]     retries = retries.increment(
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/util/retry.py", line 550, in increment
15:33:27.235: [APP/PROC/WEB.0]     raise six.reraise(type(error), error, _stacktrace)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/packages/six.py", line 770, in reraise
15:33:27.235: [APP/PROC/WEB.0]     raise value
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 715, in urlopen
15:33:27.235: [APP/PROC/WEB.0]     httplib_response = self._make_request(
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 469, in _make_request
15:33:27.235: [APP/PROC/WEB.0]     self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 358, in _raise_timeout
15:33:27.235: [APP/PROC/WEB.0]     raise ReadTimeoutError(
15:33:27.235: [APP/PROC/WEB.0] urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10)
15:33:27.235: [APP/PROC/WEB.0] During handling of the above exception, another exception occurred:
15:33:27.235: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/connection/http_requests.py", line 166, in perform_request
15:33:27.235: [APP/PROC/WEB.0]     response = self.session.send(prepared_request, **send_kwargs)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/requests/sessions.py", line 645, in send
15:33:27.235: [APP/PROC/WEB.0]     r = adapter.send(request, **kwargs)
15:33:27.235: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/requests/adapters.py", line 532, in send
15:33:27.235: [APP/PROC/WEB.0]     raise ReadTimeout(e, request=request)
15:33:27.235: [APP/PROC/WEB.0] requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10)
15:33:27.235: [APP/PROC/WEB.0] [2024-06-28 19:33:27,234: DEBUG/ForkPoolWorker-1] > {"index":{"_id":"2894c988-09a3-4627-a9ad-d81f3affa15b","_index":"tanf_t7_submissions"}}
15:33:27.235: [APP/PROC/WEB.0] {"datafile":{"id":4344,"created_at":"2024-06-28T19:33:16.900556+00:00","version":3,"quarter":"Q2","year":2024,"stt":{"name":"California","type":"state","stt_code":"06"}},"RecordType":"T7","CALENDAR_QUARTER":20241,"RPT_MONTH_YEAR":"202401","TDRS_SECTION_IND":"1","STRATUM":"01","FAMILIES_MONTH":237715}
15:33:27.237: [APP/PROC/WEB.0] [2024-06-28 19:33:27,236: ERROR/ForkPoolWorker-1] Task tdpservice.scheduling.parser_task.parse[2483a1c4-c3af-4122-bd5e-e9bab7dcd08c] raised unexpected: ConnectionTimeout('TIMEOUT', "HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10)", ReadTimeout(ReadTimeoutError("HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10)")))
15:33:27.237: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467, in _make_request
15:33:27.237: [APP/PROC/WEB.0]     six.raise_from(e, None)
15:33:27.237: [APP/PROC/WEB.0]   File "<string>", line 3, in raise_from
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 462, in _make_request
15:33:27.237: [APP/PROC/WEB.0]     httplib_response = conn.getresponse()
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/http/client.py", line 1374, in getresponse
15:33:27.237: [APP/PROC/WEB.0]     response.begin()
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/http/client.py", line 318, in begin
15:33:27.237: [APP/PROC/WEB.0]     version, status, reason = self._read_status()
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/http/client.py", line 279, in _read_status
15:33:27.237: [APP/PROC/WEB.0]     line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/socket.py", line 705, in readinto
15:33:27.237: [APP/PROC/WEB.0]     return self._sock.recv_into(b)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/ssl.py", line 1274, in recv_into
15:33:27.237: [APP/PROC/WEB.0]     return self.read(nbytes, buffer)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/ssl.py", line 1130, in read
15:33:27.237: [APP/PROC/WEB.0]     return self._sslobj.read(len, buffer)
15:33:27.237: [APP/PROC/WEB.0] TimeoutError: The read operation timed out
15:33:27.237: [APP/PROC/WEB.0] During handling of the above exception, another exception occurred:
15:33:27.237: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/requests/adapters.py", line 440, in send
15:33:27.237: [APP/PROC/WEB.0]     resp = conn.urlopen(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 799, in urlopen
15:33:27.237: [APP/PROC/WEB.0]     retries = retries.increment(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/util/retry.py", line 550, in increment
15:33:27.237: [APP/PROC/WEB.0]     raise six.reraise(type(error), error, _stacktrace)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/packages/six.py", line 770, in reraise
15:33:27.237: [APP/PROC/WEB.0]     raise value
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 715, in urlopen
15:33:27.237: [APP/PROC/WEB.0]     httplib_response = self._make_request(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 469, in _make_request
15:33:27.237: [APP/PROC/WEB.0]     self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/urllib3/connectionpool.py", line 358, in _raise_timeout
15:33:27.237: [APP/PROC/WEB.0]     raise ReadTimeoutError(
15:33:27.237: [APP/PROC/WEB.0] urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10)
15:33:27.237: [APP/PROC/WEB.0] During handling of the above exception, another exception occurred:
15:33:27.237: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/connection/http_requests.py", line 166, in perform_request
15:33:27.237: [APP/PROC/WEB.0]     response = self.session.send(prepared_request, **send_kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/requests/sessions.py", line 645, in send
15:33:27.237: [APP/PROC/WEB.0]     r = adapter.send(request, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/requests/adapters.py", line 532, in send
15:33:27.237: [APP/PROC/WEB.0]     raise ReadTimeout(e, request=request)
15:33:27.237: [APP/PROC/WEB.0] requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10)
15:33:27.237: [APP/PROC/WEB.0] During handling of the above exception, another exception occurred:
15:33:27.237: [APP/PROC/WEB.0] Traceback (most recent call last):
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/celery/app/trace.py", line 451, in trace_task
15:33:27.237: [APP/PROC/WEB.0]     R = retval = fun(*args, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/celery/app/trace.py", line 734, in __protected_call__
15:33:27.237: [APP/PROC/WEB.0]     return self.run(*args, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/app/tdpservice/scheduling/parser_task.py", line 28, in parse
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/app/tdpservice/parsers/parse.py", line 99, in parse_datafile
15:33:27.237: [APP/PROC/WEB.0]     line_errors = parse_datafile_lines(datafile, dfs, program_type, section, is_encrypted, case_consistency_validator)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/app/tdpservice/parsers/parse.py", line 331, in parse_datafile_lines
15:33:27.237: [APP/PROC/WEB.0]     all_created, unsaved_records = bulk_create_records(unsaved_records, line_number, header_count, datafile, dfs,
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/app/tdpservice/parsers/parse.py", line 119, in bulk_create_records
15:33:27.237: [APP/PROC/WEB.0]     num_elastic_records_created += document.update(created_objs)[0]
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/django_elasticsearch_dsl/documents.py", line 238, in update
15:33:27.237: [APP/PROC/WEB.0]     return self._bulk(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/django_elasticsearch_dsl/documents.py", line 215, in _bulk
15:33:27.237: [APP/PROC/WEB.0]     return self.bulk(*args, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/django_elasticsearch_dsl/documents.py", line 164, in bulk
15:33:27.237: [APP/PROC/WEB.0]     response = bulk(client=self._get_connection(), actions=actions, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 410, in bulk
15:33:27.237: [APP/PROC/WEB.0]     for ok, item in streaming_bulk(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 329, in streaming_bulk
15:33:27.237: [APP/PROC/WEB.0]     for data, (ok, info) in zip(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 256, in _process_bulk_chunk
15:33:27.237: [APP/PROC/WEB.0]     for item in gen:
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 195, in _process_bulk_chunk_error
15:33:27.237: [APP/PROC/WEB.0]     raise error
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 240, in _process_bulk_chunk
15:33:27.237: [APP/PROC/WEB.0]     resp = client.bulk("\n".join(bulk_actions) + "\n", *args, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/client/utils.py", line 168, in _wrapped
15:33:27.237: [APP/PROC/WEB.0]     return func(*args, params=params, headers=headers, **kwargs)
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/client/__init__.py", line 463, in bulk
15:33:27.237: [APP/PROC/WEB.0]     return self.transport.perform_request(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/transport.py", line 415, in perform_request
15:33:27.237: [APP/PROC/WEB.0]     raise e
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/transport.py", line 381, in perform_request
15:33:27.237: [APP/PROC/WEB.0]     status, headers_response, data = connection.perform_request(
15:33:27.237: [APP/PROC/WEB.0]   File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/connection/http_requests.py", line 183, in perform_request
15:33:27.237: [APP/PROC/WEB.0]     raise ConnectionTimeout("TIMEOUT", str(e), e)
15:33:27.237: [APP/PROC/WEB.0] elasticsearch.exceptions.ConnectionTimeout: ConnectionTimeout caused by - ReadTimeout(HTTPSConnectionPool(host='vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com', port=443): Read timed out. (read timeout=10))
15:33:27.282: [APP/PROC/WEB.0] 2024-06-28 19:33:27,281 INFO sftp_task.py::upload:L58 :  Attempt 1 to upload file ADS.E2J.FTP4.TS06

Proxy app:

15:06:41.924: [APP/PROC/WEB.0] time="2024-28-06 19:06:41" level=error msg="Get \"https://vpc-cg-broker-prd-h9a8o3te0-c23nqypoz4ffhymqwsqeryebpu.us-gov-west-1.es.amazonaws.com/_nodes?filter_path=nodes.%2A.version%2Cnodes.%2A.http.publish_address%2Cnodes.%2A.ip\": context deadline exceeded (Client.Timeout exceeded while awaiting 
headers)"

Kibana app:

{"type":"log","@timestamp":"2024-06-28T19:49:11Z","tags":["status","plugin:elasticsearch@7.4.2","error"],"pid":36,"state":"red","message":"Status changed from green to red - Bad Request","prevState":"green","prevMsg":"Ready"}
15:49:35.918: [APP/PROC/WEB.0] {"type":"log","@timestamp":"2024-06-28T19:49:35Z","tags":["status","plugin:elasticsearch@7.4.2","info"],"pid":36,"state":"green","message":"Status changed from red to green - Ready","prevState":"red","prevMsg":"Bad Request"}
oh and this: 5:43:45.931: [APP/PROC/WEB.0] {"type":"log","@timestamp":"2024-06-28T19:43:45Z","tags":["status","plugin:elasticsearch@7.4.2","info"],"pid":36,"state":"green","message":"Status changed from red to green - Ready","prevState":"red","prevMsg":"Service Unavailable"}

URL of the page I was on:
Browser and version:
Operating System: ( Windows | MacOS X | Linux | Other )
Is the issue repeatable?: ( yes | no | don't know )
Has the issue occurred more than once?:

raft-tech / TANF-app