[bug] Uncaught exception re: parsing error preventing feedback report generation.

[ADPennington]

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

After releasing sprint 90 code to prod, and reviewing error feedback via frontend/admin/parsers/parsererror/, I noticed that the error messages do not include the friendly names implemented in 2599. To be sure, I also checked the frontend for the error report associated with the errors generated, and noticed that the processing status was still "pending" and no error report was available to download.

Action Taken

• As an Admin, navigate to frontend/admin/parsers/parsererror/ and peruse parsing error messages
• After identifying the file source of the errors, navigate to frontend/data-files page > make appropriate STT and fiscal period selections > navigate to submission history tab and check the processing status.
• via cloud.gov, navigate to backend app logs and review data parsing information for the data submission associated with the abovementioned errors.
• to be sure, I used the test files used in the 2599 PR review in the staging environment since the staging environment mirrors the prod environment.

What I expected to see

• I expected to see error messages that include friendly names and a feedback report generated.

What I did see

data submission

data submission history showing pending status

parsing errors without friendly names

cloud.gov logs during data submission showing uncaught exceptions

uth check PASS for user: alexandra.pennington@acf.hhs.gov on 2024-01-24 18:44:43.977024+00:00
13:44:43.978: [APP/PROC/WEB.0] 10.255.158.7 - - [24/Jan/2024:18:44:43 +0000] "GET /v1/auth_check HTTP/1.0" 200 1591 "https://tdp-frontend-staging.acf.hhs.gov/data-files" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
13:44:45.142: [APP/PROC/WEB.0] 2024-01-24 18:44:45,141 DEBUG views.py::create:L57 :  DataFileViewSet: <rest_framework.request.Request: POST '/v1/data_files/'>
13:44:45.142: [APP/PROC/WEB.0] DataFileViewSet: <rest_framework.request.Request: POST '/v1/data_files/'>
13:44:45.143: [APP/PROC/WEB.0] 2024-01-24 18:44:45,143 DEBUG validators.py::validate_file_infection:L54 :  CLAMAV_NEEDED noted as True, proceeding with scan.
13:44:45.143: [APP/PROC/WEB.0] CLAMAV_NEEDED noted as True, proceeding with scan.
13:44:45.143: [APP/PROC/WEB.0] 2024-01-24 18:44:45,143 DEBUG clients.py::__init__:L37 :  Set clamav endpoint_url as 'http://tdp-clamav-nginx-staging.apps.internal:9000/scan'
13:44:45.143: [APP/PROC/WEB.0] Set clamav endpoint_url as 'http://tdp-clamav-nginx-staging.apps.internal:9000/scan'
13:44:45.144: [APP/PROC/WEB.0] 2024-01-24 18:44:45,143 DEBUG clients.py::scan_file:L64 :  Initiating virus scan for file: tanf_section1_2599.txt
13:44:45.144: [APP/PROC/WEB.0] Initiating virus scan for file: tanf_section1_2599.txt
13:44:45.160: [APP/PROC/WEB.0] 2024-01-24 18:44:45,160 DEBUG clients.py::scan_file:L90 :  File scan marked as CLEAN for file: tanf_section1_2599.txt
13:44:45.160: [APP/PROC/WEB.0] File scan marked as CLEAN for file: tanf_section1_2599.txt
13:44:45.349: [APP/PROC/WEB.0] 2024-01-24 18:44:45,348 DEBUG views.py::create:L65 :  DataFileViewSet: status: 201
13:44:45.349: [APP/PROC/WEB.0] DataFileViewSet: status: 201
13:44:45.354: [APP/PROC/WEB.0] 2024-01-24 18:44:45,353 INFO views.py::create:L71 :  Preparing parse task: User META -> user: alexandra.pennington@acf.hhs.gov, stt: Alabama (01). Datafile META -> datafile: 302, section: Active Case Data, quarter Q1, year 2024.
13:44:45.354: [APP/PROC/WEB.0] Preparing parse task: User META -> user: alexandra.pennington@acf.hhs.gov, stt: Alabama (01). Datafile META -> datafile: 302, section: Active Case Data, quarter Q1, year 2024.
13:44:45.355: [APP/PROC/WEB.0] 2024-01-24 18:44:45,355 INFO views.py::create:L76 :  Submitted parse task to queue for datafile 302.
13:44:45.355: [APP/PROC/WEB.0] Submitted parse task to queue for datafile 302.
13:44:45.357: [APP/PROC/WEB.0] 2024-01-24 18:44:45,356 INFO views.py::create:L85 :  Submitted upload task to redis for datafile 302.
13:44:45.357: [APP/PROC/WEB.0] Submitted upload task to redis for datafile 302.
13:44:45.378: [APP/PROC/WEB.0] 2024-01-24 18:44:45,378 INFO parser_task.py::parse:L22 :  DataFile parsing started for file ADS.E2J.NDM1.TS01
13:44:45.378: [APP/PROC/WEB.0] [2024-01-24 18:44:45,378: INFO/ForkPoolWorker-1] DataFile parsing started for file ADS.E2J.NDM1.TS01
13:44:45.483: [APP/PROC/WEB.0] 2024-01-24 18:44:45,482 DEBUG views.py::create:L114 :  DataFileViewSet: return val: <Response status_code=201, "text/html; charset=utf-8">
13:44:45.483: [APP/PROC/WEB.0] DataFileViewSet: return val: <Response status_code=201, "text/html; charset=utf-8">
13:44:45.484: [APP/PROC/WEB.0] 10.255.158.7 - - [24/Jan/2024:18:44:45 +0000] "POST /v1/data_files/ HTTP/1.0" 201 448 "https://tdp-frontend-staging.acf.hhs.gov/data-files" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG fields.py::parse_value:L46 :  Field: 'tribe_code' at position: [14, 17) is empty.
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG fields.py::parse_value:L46 :  Field: 'encryption' at position: [21, 22) is empty.
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG fields.py::parse_value:L46 :  Field: 'tribe_code' at position: [14, 17) is empty.
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG fields.py::parse_value:L46 :  Field: 'encryption' at position: [21, 22) is empty.
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG parse.py::parse_datafile:L51 :  Datafile has encrypted fields: False.
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG parse.py::parse_datafile:L52 :  Datafile: {id: 302, filename: tanf_section1_2599.txt, STT: Alabama (01), S3 location: data_files/2024/Q1/1/Active Case Data/tanf_section1_2599.txt}, is Tribal: False.
13:44:45.500: [APP/PROC/WEB.0] 2024-01-24 18:44:45,499 DEBUG parse.py::parse_datafile:L57 :  Program type: TAN, Section: A.
13:44:45.512: [APP/PROC/WEB.0] 2024-01-24 18:44:45,511 DEBUG fields.py::parse_value:L46 :  Field: 'BLANK' at position: [117, 156) is empty.
13:44:45.512: [APP/PROC/WEB.0] 2024-01-24 18:44:45,511 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: invalid literal for int() with base 10: '#2'
13:44:45.512: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG parse.py::parse_datafile_lines:L220 :  Record #0 from line 2 is invalid.
13:44:45.512: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_HISPANIC' at position: [38, 39) is empty.
13:44:45.512: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_AMER_INDIAN' at position: [39, 40) is empty.
13:44:45.512: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_ASIAN' at position: [40, 41) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_BLACK' at position: [41, 42) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_HAWAIIAN' at position: [42, 43) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_WHITE' at position: [43, 44) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'AID_AGED_BLIND' at position: [48, 49) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'MARITAL_STATUS' at position: [50, 51) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'PARENT_MINOR_CHILD' at position: [53, 54) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'NEEDS_PREGNANT_WOMAN' at position: [54, 55) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'EDUCATION_LEVEL' at position: [55, 57) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'CITIZENSHIP_STATUS' at position: [57, 58) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'COOPERATION_CHILD_SUPPORT' at position: [58, 59) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'MONTHS_FED_TIME_LIMIT' at position: [59, 62) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'MONTHS_STATE_TIME_LIMIT' at position: [62, 64) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'CURRENT_MONTH_STATE_EXEMPT' at position: [64, 65) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'EMPLOYMENT_STATUS' at position: [65, 66) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,512 DEBUG fields.py::parse_value:L46 :  Field: 'WORK_PART_STATUS' at position: [68, 70) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'UNSUB_EMPLOYMENT' at position: [70, 72) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'SUB_PRIVATE_EMPLOYMENT' at position: [72, 74) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'SUB_PUBLIC_EMPLOYMENT' at position: [74, 76) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'WORK_EXPERIENCE_HOP' at position: [76, 78) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'WORK_EXPERIENCE_EA' at position: [78, 80) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'WORK_EXPERIENCE_HOL' at position: [80, 82) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'OJT' at position: [82, 84) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'JOB_SEARCH_HOP' at position: [84, 86) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'JOB_SEARCH_EA' at position: [86, 88) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'JOB_SEARCH_HOL' at position: [88, 90) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'COMM_SERVICES_HOP' at position: [90, 92) is empty.
13:44:45.513: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'COMM_SERVICES_EA' at position: [92, 94) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'COMM_SERVICES_HOL' at position: [94, 96) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'VOCATIONAL_ED_TRAINING_HOP' at position: [96, 98) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'VOCATIONAL_ED_TRAINING_EA' at position: [98, 100) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'VOCATIONAL_ED_TRAINING_HOL' at position: [100, 102) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'JOB_SKILLS_TRAINING_HOP' at position: [102, 104) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'JOB_SKILLS_TRAINING_EA' at position: [104, 106) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'JOB_SKILLS_TRAINING_HOL' at position: [106, 108) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'ED_NO_HIGH_SCHOOL_DIPL_HOP' at position: [108, 110) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'ED_NO_HIGH_SCHOOL_DIPL_EA' at position: [110, 112) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'ED_NO_HIGH_SCHOOL_DIPL_HOL' at position: [112, 114) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'SCHOOL_ATTENDENCE_HOP' at position: [114, 116) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'SCHOOL_ATTENDENCE_EA' at position: [116, 118) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'SCHOOL_ATTENDENCE_HOL' at position: [118, 120) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,513 DEBUG fields.py::parse_value:L46 :  Field: 'PROVIDE_CC_HOP' at position: [120, 122) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG fields.py::parse_value:L46 :  Field: 'PROVIDE_CC_EA' at position: [122, 124) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG fields.py::parse_value:L46 :  Field: 'PROVIDE_CC_HOL' at position: [124, 126) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG fields.py::parse_value:L46 :  Field: 'OTHER_WORK_ACTIVITIES' at position: [126, 128) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG fields.py::parse_value:L46 :  Field: 'DEEMED_HOURS_FOR_OVERALL' at position: [128, 130) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG fields.py::parse_value:L46 :  Field: 'UNEARNED_INCOME_TAX_CREDIT' at position: [136, 140) is empty.
13:44:45.514: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,514 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: int() argument must be a string, a bytes-like object or a real number, not 'NoneType'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: int() argument must be a string, a bytes-like object or a real number, not 'NoneType'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: int() argument must be a string, a bytes-like object or a real number, not 'NoneType'
13:44:45.515: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: int() argument must be a string, a bytes-like object or a real number, not 'NoneType'
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG parse.py::parse_datafile_lines:L220 :  Record #0 from line 3 is invalid.
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG fields.py::parse_value:L46 :  Field: 'RACE_HISPANIC' at position: [37, 38) is empty.
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,515 DEBUG validators.py::validator:L34 :  Caught exception in validator. Exception: '>=' not supported between instances of 'NoneType' and 'int'
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,516 DEBUG parse.py::parse_datafile_lines:L220 :  Record #0 from line 4 is invalid.
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,516 DEBUG util.py::get_schema_options:L231 :  Model #T not found in schema_defs
13:44:45.516: [APP/PROC/WEB.0] 2024-01-24 18:44:45,516 ERROR parse.py::manager_parse_line:L271 :  'list' object has no attribute 'update_encrypted_fields'
13:44:45.517: [APP/PROC/WEB.0] 2024-01-24 18:44:45,516 DEBUG parse.py::parse_datafile_lines:L220 :  Record #0 from line 5 is invalid.
13:44:45.517: [APP/PROC/WEB.0] 2024-01-24 18:44:45,516 DEBUG fields.py::parse_value:L46 :  Field: 'blank' at position: [14, 23) is empty.
13:44:45.517: [APP/PROC/WEB.0] 2024-01-24 18:44:45,516 DEBUG parse.py::bulk_create_records:L81 :  Bulk creating records.
13:44:45.901: [APP/PROC/WEB.0] 10.255.158.7 - - [24/Jan/2024:18:44:45 +0000] "POST /v1/logs/ HTTP/1.0" 200 9 "https://tdp-frontend-staging.acf.hhs.gov/data-files" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
13:44:46.092: [APP/PROC/WEB.0] [2024-01-24 18:44:46,091: INFO/ForkPoolWorker-1] POST https://vpc-cg-broker-prd-ed6xg0aa5-onpilzszxrtxo6aoiy5xezh4fm.us-gov-west-1.es.amazonaws.com:443/_bulk?refresh=true [status:200 request:0.567s]
13:44:46.092: [APP/PROC/WEB.0] [2024-01-24 18:44:46,091: DEBUG/ForkPoolWorker-1] > {"index":{"_id":"d97cf280-1a40-4088-83a5-d7061456bc10","_index":"tanf_t1_submissions"}}
13:44:46.092: [APP/PROC/WEB.0] {"datafile":{"id":302,"created_at":"2024-01-24T18:44:45.182820+00:00","version":9,"quarter":"Q1","year":2024},"RecordType":"T1","RPT_MONTH_YEAR":202310,"CASE_NUMBER":"11111116935","COUNTY_FIPS_CODE":"242","STRATUM":"#2","ZIP_CODE":"40198","FUNDING_STREAM":1,"DISPOSITION":1,"NEW_APPLICANT":2,"NBR_FAMILY_MEMBERS":2,"FAMILY_TYPE":3,"RECEIVES_SUB_HOUSING":1,"RECEIVES_MED_ASSISTANCE":1,"RECEIVES_FOOD_STAMPS":1,"AMT_FOOD_STAMP_ASSISTANCE":100,"RECEIVES_SUB_CC":3,"AMT_SUB_CC":0,"CHILD_SUPPORT_AMT":0,"FAMILY_CASH_RESOURCES":0,"CASH_AMOUNT":483,"NBR_MONTHS":0,"CC_AMOUNT":0,"CHILDREN_COVERED":0,"CC_NBR_MONTHS":0,"TRANSP_AMOUNT":0,"TRANSP_NBR_MONTHS":0,"TRANSITION_SERVICES_AMOUNT":0,"TRANSITION_NBR_MONTHS":0,"OTHER_AMOUNT":0,"OTHER_NBR_MONTHS":1,"SANC_REDUCTION_AMT":0,"WORK_REQ_SANCTION":2,"FAMILY_SANC_ADULT":2,"SANC_TEEN_PARENT":2,"NON_COOPERATION_CSE":2,"FAILURE_TO_COMPLY":2,"OTHER_SANCTION":2,"RECOUPMENT_PRIOR_OVRPMT":0,"OTHER_TOTAL_REDUCTIONS":0,"FAMILY_CAP":2,"REDUCTIONS_ON_RECEIPTS":2,"OTHER_NON_SANCTION":2,"WAIVER_EVAL_CONTROL_GRPS":"9","FAMILY_EXEMPT_TIME_LIMITS":2,"FAMILY_NEW_CHILD":2}
13:44:46.092: [APP/PROC/WEB.0] [2024-01-24 18:44:46,091: DEBUG/ForkPoolWorker-1] < {"took":424,"errors":true,"items":[{"index":{"_index":"tanf_t1_submissions","_type":"_doc","_id":"d97cf280-1a40-4088-83a5-d7061456bc10","status":400,"error":{"type":"mapper_parsing_exception","reason":"failed to parse field [STRATUM] of type [long] in document with id 'd97cf280-1a40-4088-83a5-d7061456bc10'. Preview of field's value: '#2'","caused_by":{"type":"illegal_argument_exception","reason":"For input string: \"#2\""}}}}]}
13:44:46.105: [APP/PROC/WEB.0] [2024-01-24 18:44:46,104: ERROR/ForkPoolWorker-1] Task tdpservice.scheduling.parser_task.parse[f4d017ac-8c75-48fe-9854-19bc6b4bc638] raised unexpected: BulkIndexError('1 document(s) failed to index.', [{'index': {'_index': 'tanf_t1_submissions', '_type': '_doc', '_id': 'd97cf280-1a40-4088-83a5-d7061456bc10', 'status': 400, 'error': {'type': 'mapper_parsing_exception', 'reason': "failed to parse field [STRATUM] of type [long] in document with id 'd97cf280-1a40-4088-83a5-d7061456bc10'. Preview of field's value: '#2'", 'caused_by': {'type': 'illegal_argument_exception', 'reason': 'For input string: "#2"'}}, 'data': {'datafile': {'id': 302, 'created_at': datetime.datetime(2024, 1, 24, 18, 44, 45, 182820, tzinfo=<UTC>), 'version': 9, 'quarter': 'Q1', 'year': 2024}, 'RecordType': 'T1', 'RPT_MONTH_YEAR': 202310, 'CASE_NUMBER': '11111116935', 'COUNTY_FIPS_CODE': '242', 'STRATUM': '#2', 'ZIP_CODE': '40198', 'FUNDING_STREAM': 1, 'DISPOSITION': 1, 'NEW_APPLICANT': 2, 'NBR_FAMILY_MEMBERS': 2, 'FAMILY_TYPE': 3, 'RECEIVES_SUB_HOUSING': 1, 'RECEIVES_MED_ASSISTANCE': 1, 'RECEIVES_FOOD_STAMPS': 1, 'AMT_FOOD_STAMP_ASSISTANCE': 100, 'RECEIVES_SUB_CC': 3, 'AMT_SUB_CC': 0, 'CHILD_SUPPORT_AMT': 0, 'FAMILY_CASH_RESOURCES': 0, 'CASH_AMOUNT': 483, 'NBR_MONTHS': 0, 'CC_AMOUNT': 0, 'CHILDREN_COVERED': 0, 'CC_NBR_MONTHS': 0, 'TRANSP_AMOUNT': 0, 'TRANSP_NBR_MONTHS': 0, 'TRANSITION_SERVICES_AMOUNT': 0, 'TRANSITION_NBR_MONTHS': 0, 'OTHER_AMOUNT': 0, 'OTHER_NBR_MONTHS': 1, 'SANC_REDUCTION_AMT': 0, 'WORK_REQ_SANCTION': 2, 'FAMILY_SANC_ADULT': 2, 'SANC_TEEN_PARENT': 2, 'NON_COOPERATION_CSE': 2, 'FAILURE_TO_COMPLY': 2, 'OTHER_SANCTION': 2, 'RECOUPMENT_PRIOR_OVRPMT': 0, 'OTHER_TOTAL_REDUCTIONS': 0, 'FAMILY_CAP': 2, 'REDUCTIONS_ON_RECEIPTS': 2, 'OTHER_NON_SANCTION': 2, 'WAIVER_EVAL_CONTROL_GRPS': '9', 'FAMILY_EXEMPT_TIME_LIMITS': 2, 'FAMILY_NEW_CHILD': 2}}}])
13:44:46.105: [APP/PROC/WEB.0] Traceback (most recent call last):
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/celery/app/trace.py", line 451, in trace_task
13:44:46.105: [APP/PROC/WEB.0] R = retval = fun(*args, **kwargs)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/celery/app/trace.py", line 734, in __protected_call__
13:44:46.105: [APP/PROC/WEB.0] return self.run(*args, **kwargs)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/app/tdpservice/scheduling/parser_task.py", line 25, in parse
13:44:46.105: [APP/PROC/WEB.0] errors = parse_datafile(data_file)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/app/tdpservice/parsers/parse.py", line 72, in parse_datafile
13:44:46.105: [APP/PROC/WEB.0] line_errors = parse_datafile_lines(datafile, program_type, section, is_encrypted)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/app/tdpservice/parsers/parse.py", line 252, in parse_datafile_lines
13:44:46.105: [APP/PROC/WEB.0] all_created, unsaved_records = bulk_create_records(unsaved_records, line_number, header_count, flush=True)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/app/tdpservice/parsers/parse.py", line 89, in bulk_create_records
13:44:46.105: [APP/PROC/WEB.0] num_elastic_records_created += document.update(created_objs)[0]
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/django_elasticsearch_dsl/documents.py", line 238, in update
13:44:46.105: [APP/PROC/WEB.0] return self._bulk(
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/django_elasticsearch_dsl/documents.py", line 215, in _bulk
13:44:46.105: [APP/PROC/WEB.0] return self.bulk(*args, **kwargs)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/django_elasticsearch_dsl/documents.py", line 164, in bulk
13:44:46.105: [APP/PROC/WEB.0] response = bulk(client=self._get_connection(), actions=actions, **kwargs)
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 410, in bulk
13:44:46.105: [APP/PROC/WEB.0] for ok, item in streaming_bulk(
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 329, in streaming_bulk
13:44:46.105: [APP/PROC/WEB.0] for data, (ok, info) in zip(
13:44:46.105: [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
13:44:46.105: [APP/PROC/WEB.0] for item in gen:
13:44:46.105: [APP/PROC/WEB.0] File "/home/vcap/deps/1/python/lib/python3.10/site-packages/elasticsearch/helpers/actions.py", line 187, in _process_bulk_chunk_success
13:44:46.105: [APP/PROC/WEB.0] raise BulkIndexError("%i document(s) failed to index." % len(errors), errors)
13:44:46.105: [APP/PROC/WEB.0] elasticsearch.helpers.errors.BulkIndexError: ('1 document(s) failed to index.', [{'index': {'_index': 'tanf_t1_submissions', '_type': '_doc', '_id': 'd97cf280-1a40-4088-83a5-d7061456bc10', 'status': 400, 'error': {'type': 'mapper_parsing_exception', 'reason': "failed to parse field [STRATUM] of type [long] in document with id 'd97cf280-1a40-4088-83a5-d7061456bc10'. Preview of field's value: '#2'", 'caused_by': {'type': 'illegal_argument_exception', 'reason': 'For input string: "#2"'}}, 'data': {'datafile': {'id': 302, 'created_at': datetime.datetime(2024, 1, 24, 18, 44, 45, 182820, tzinfo=<UTC>), 'version': 9, 'quarter': 'Q1', 'year': 2024}, 'RecordType': 'T1', 'RPT_MONTH_YEAR': 202310, 'CASE_NUMBER': '11111116935', 'COUNTY_FIPS_CODE': '242', 'STRATUM': '#2', 'ZIP_CODE': '40198', 'FUNDING_STREAM': 1, 'DISPOSITION': 1, 'NEW_APPLICANT': 2, 'NBR_FAMILY_MEMBERS': 2, 'FAMILY_TYPE': 3, 'RECEIVES_SUB_HOUSING': 1, 'RECEIVES_MED_ASSISTANCE': 1, 'RECEIVES_FOOD_STAMPS': 1, 'AMT_FOOD_STAMP_ASSISTANCE': 100, 'RECEIVES_SUB_CC': 3, 'AMT_SUB_CC': 0, 'CHILD_SUPPORT_AMT': 0, 'FAMILY_CASH_RESOURCES': 0, 'CASH_AMOUNT': 483, 'NBR_MONTHS': 0, 'CC_AMOUNT': 0, 'CHILDREN_COVERED': 0, 'CC_NBR_MONTHS': 0, 'TRANSP_AMOUNT': 0, 'TRANSP_NBR_MONTHS': 0, 'TRANSITION_SERVICES_AMOUNT': 0, 'TRANSITION_NBR_MONTHS': 0, 'OTHER_AMOUNT': 0, 'OTHER_NBR_MONTHS': 1, 'SANC_REDUCTION_AMT': 0, 'WORK_REQ_SANCTION': 2, 'FAMILY_SANC_ADULT': 2, 'SANC_TEEN_PARENT': 2, 'NON_COOPERATION_CSE': 2, 'FAILURE_TO_COMPLY': 2, 'OTHER_SANCTION': 2, 'RECOUPMENT_PRIOR_OVRPMT': 0, 'OTHER_TOTAL_REDUCTIONS': 0, 'FAMILY_CAP': 2, 'REDUCTIONS_ON_RECEIPTS': 2, 'OTHER_NON_SANCTION': 2, 'WAIVER_EVAL_CONTROL_GRPS': '9', 'FAMILY_EXEMPT_TIME_LIMITS': 2, 'FAMILY_NEW_CHILD': 2}}}])
13:44:48.481: [APP/PROC/WEB.0] 2024-01-24 18:44:48,480 INFO sftp_task.py::upload:L97 :  File ADS.E2J.NDM1.TS01 has been successfully uploaded to acftitan.cit.nih.gov
13:44:48.481: [APP/PROC/WEB.0] [2024-01-24 18:44:48,480: INFO/ForkPoolWorker-1] File ADS.E2J.NDM1.TS01 has been successfully uploaded to acftitan.cit.nih.gov

Other Helpful Information

• URL of the page I was on: https://tdp-frontend-staging.acf.hhs.gov/
• Is the issue repeatable?: yes
• Has the issue occurred more than once?: yes
• this issue may have been introduced in #2772
• Dev MM thread

[jtimpe]

• try to rebuild indexes with

  python manage.py search_index --rebuild

• add exception handling for elastic exceptions to bulk_create_records

• look at auto-refreshing indexes (possibly in the future) - https://django-elasticsearch-dsl.readthedocs.io/en/latest/settings.html#elasticsearch-dsl-auto-refresh

[jtimpe]

closing, as #2835 has merged and #2870 addresses the remaining automation tasks