MathematicalMedicine / diver-issues

Semipublic tracking of issues for the DIVER front end
0 stars 0 forks source link

RC testing: "Failed to generate download data for preview" error first time, worked second time without changing anything #273

Closed Viqsi closed 2 weeks ago

Viqsi commented 2 weeks ago

So this happened. Reported by Jake (see bolded):

Interest: Compare current global assessment scale scores by age of onset of first eating disorder symptoms.

Selected items age of onset variables for disordered eating behaviors and downcoded into 3 categories: “under10”, “10plus”, and UNK. Low weight (I16180) -> low_weight_age_group Bingeing (I16310) -> binge_age_group Bingeing with compensatory behaviors (V2163) -> comp_age_group

Combined these such that if any was under 10, the final value is “earlier_under_10”, otherwise “earliest_over_10” or “UNK”. See custom variables “EDO_onset_combine1” and “EDO_onset_combine2”. Downcoded dist_dx_nimh so dx “anorexia nervosa”, “bulimia nervosa”, and “other eating disorder” were all coded as “any_edo”, and any other value is “not_edo”.

Made subset cohort for subjects with “any_edo”. Then downloaded data for the “EDO_onset_combine2”, the original contributing variables (I16180, I16310, V2163), dist_dx_nimh, dist_yob, dist_age_years, and I16800 (global assessment scale for the last month). Got “Failed to generate download data for preview” error, but tried again without changing anything and it worked.

Was able to find this in the logs readily enough:

[2024-11-04 11:23:11,300] INFO in diverRPC: 127.0.0.1 POST https:///api/v0/cohort/download/new? | Args: None | Body:                        {'cohortid': 1593, 'varsetid': 158}
[2024-11-04 11:23:11,549] INFO in diverRPC: Validated user: CrowdUser(name='jts240', privs='["admin"]')
[2024-11-04 11:23:22,393] ERROR in diverRPC: ERROR DETAILS: {'message': 'Unhandled application error'}, 500
Traceback (most recent call last):
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/flask/app.py", line 1523, in full_dispatch_request
    rv = self.dispatch_request()
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/flask/app.py", line 1509, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
  File "/var/lib/diver/diverRPC/diverRPC.py", line 409, in get_verified_user
    return endpoint(verify_user(), *args, **kwargs)
  File "/var/lib/diver/diverRPC/diverRPC.py", line 733, in route_prep_cohort_download
    diverAPI.prep_cohort_download(user, cohortid, varsetid, projectid))
  File "/var/lib/diver/diverRPC/diverAPI.py", line 570, in prep_cohort_download
    candidateresult = proccall_nextset(cursor)
  File "/var/lib/diver/diverRPC/diverAPI.py", line 206, in proccall_nextset
    if cursor.nextset():
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/cursors.py", line 96, in nextset
    return self._nextset(False)
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/cursors.py", line 91, in _nextset
    conn.next_result(unbuffered=unbuffered)
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/connections.py", line 552, in next_result
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/connections.py", line 775, in _read_query_result        49170     result.read()
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/connections.py", line 1156, in read
    first_packet = self.connection._read_packet()
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/connections.py", line 725, in _read_packet
    packet.raise_for_error()
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File "/var/lib/diver/mambaforge/lib/python3.9/site-packages/pymysql/err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.ProgrammingError: (1064, "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'NULL' at line 1")

[2024-11-04 11:24:08,300] INFO in diverRPC: 127.0.0.1 POST https:///api/v0/cohort/download/new? | Args: None | Body: {'cohortid': 1593, 'varsetid': 158}
[2024-11-04 11:24:08,551] INFO in diverRPC: Validated user: CrowdUser(name='jts240', privs='["admin"]')
[2024-11-04 11:24:18,299] INFO in diverRPC: 127.0.0.1 GET https:///api/v0/cohort/download/preview?downloadid=29 | Args: ImmutableMultiDict([('downloadid', '29')]) | Body: None

So, indeed, first try failed, second try with same params with no other requests in between is fine.

On inspecting the Diag table, I noted that there's also an "edo_present" custom variable, and it's where things exploded. (NOTE: Diag output rows are in reverse order; read from bottom to top):

*************************** 661. row ***************************
      DiagId: 100266
ConnectionId: NULL
  InsertTime: 2024-11-04 11:23:22
     Message: Cannot find variable edo_present anywhere, FAIL!
*************************** 662. row ***************************
      DiagId: 100265
ConnectionId: NULL
  InsertTime: 2024-11-04 11:23:22
     Message: Recreating TEMP_AECIds for edo_present
*************************** 663. row ***************************
      DiagId: 100264
ConnectionId: NULL
  InsertTime: 2024-11-04 11:23:22
     Message: API_BuildALLEXISTSCohort entry with inUserName [jts240], inProjectId [1], inVariableName [edo_present], inRecursiveDepth [0]

Huh. What was the last successful AEC reation entry, prior to that?

*************************** 677. row ***************************
      DiagId: 100250
ConnectionId: NULL
  InsertTime: 2024-11-04 11:23:11
     Message: API_BuildALLEXISTSCohort entry with inUserName [jts240], inProjectId [85], inVariableName [dist_yob], inRecursiveDepth [0]

Wait a minute. Why is the inProjectId suddenly different? Because that's clearly why edo_present couldn't be found - it must be in project 85, but the AEC creation call specified project 1! Going through the intervening rows, we eventually find the first place the projectId inexplicably changed:

*************************** 672. row ***************************
      DiagId: 100255
ConnectionId: NULL
  InsertTime: 2024-11-04 11:23:11
     Message: API_buildkibbleset entry:in_variable_name [dist_yob], inUserName [(NULL)], inProjectId [1],

There, it doesn't matter, because dist_yob is a distribution variable (FHV) and so doesn't care about the project ID. But any subsequent custom variables do care.

So clearly someting along the way in generating an AEC for this distribution variable reset the project id. My guess is that we have the habit of using a @projectid variable, and that got overwritten by one of the procedures somewhere along the way while all these were being worked on

Why did it work the second time? Because no AEC needed to be generated for dist_yob that time - it'd been done the first try through - and so there was no opportunity for Whatever The Bad Thing Was to reset the project id.

The simple fix is to find where that reset happened and why and eliminate it. The real fix is to stop using an @ variable and DECLARE something so that scope issues can't bite us. Grrarrrgh.