CD2 error Invalid token....After one hour of processing 4 small tables

[jsimon3]

With the plethora of issues w/ CD2 in the past few weeks middleware errors to overload errors I might as well throw a new one into the mix....
I get an invalid token response after an hour of doing a postIncremental update...
The tarballs that it produces are less than 4Kb
5 of 45 tables are downloaded 
happening now for 2 days
after several attempts using the token it ceases to produce even one 2Kb table....

My last logs w/timestamps
```

{
...CD2-2-Tables-Update/CD2-2-Tables/bin/Debug/CD2_2_Tables.exe
    Authorization  OK: 11/2/2023 9:13:06 PM
    ...\CD2\download\accounts!part-00000-d74e3224-8c5e-4b2f-84ef-f51ccbxxx.csv.gz
    accounts Completed
    accounts done at: 11/2/2023 9:20:09 PM
    ...\CD2\download\assignment_groups!part-00000-d4d3f2c0-40fc-41f6-adcf-db2f29xxxcsv.gz
     assignment_groups Completed
     assignment_groups done at: 11/2/2023 10:00:40 PM
    ...CD2\download\assignment_override_students!part-00000-ced395e2-6f75-4aa4-8037-2246931e6xxx.csv.gz
     assignment_override_students Completed
     assignment_override_students done at: 11/2/2023 10:07:52 PM
...\CD2\download\assignment_overrides!part-00000-da454737-a2bf-418d-b5xx.csv.gz
     assignment_overrides Completed
    assignment_overrides done at: 11/2/2023 10:08:19 PM
}
{
PullCanvasData2.CanvasDataException:
    {
       "error":"The Token has expired on 2023-11-02T22:13:06Z."
    }
       at PullCanvasData2.CanvasData.AssertSuccess(HttpResponseMessage response)
       at PullCanvasData2.CanvasData.<GetJobStatus>d__11`1.MoveNext()
}

```

[mclark19]

We've been experiencing the same thing. It seems that the dap jobs are not completing in a reasonable amount of time. After an hour of polling for job status the token times out so we end up with a 401 Unauthorized error when trying to retrieve the status and the job fails. We've got a separate Informatica process for each table, so this means that it is taking more than 60 minutes for dap to return a completed job status for a single table. The failures seem to have no relation to the size of the table. 

[mclark19]

To be more specific, here's a snippet from our log. We start polling for completion at 7:03 am and the token expires at 8:03 am, leading to an error:

2023-11-03 07:03:22,838 [INFO] Latest timestamp for table scores: 2023-11-02T09:11:02Z
2023-11-03 07:03:23,591 [INFO] Attempting again in 5 seconds
2023-11-03 07:03:28,755 [INFO] Attempting again in 5 seconds
<Truncated>
2023-11-03 08:03:08,521 [INFO] Attempting again in 5 seconds
2023-11-03 08:03:13,752 [INFO] Attempting again in 5 seconds
2023-11-03 08:03:19,071 [INFO] Attempting again in 5 seconds
Traceback (most recent call last):
File ".../canvas/cd2_canvas_ingest_v1.py", line 595, in <module>
download(table_name,"incremental","csv","jsonl")
File ".../canvas/cd2_canvas_ingest_v1.py", line 572, in download
objects = fetch_request_objects(token_received_from_api, id_to_fetch_objects, INGEST_METHOD)
File ".../canvas/cd2_canvas_ingest_v1.py", line 268, in fetch_request_objects
response.raise_for_status()
File "/usr/local/lib/python3.6/site-packages/requests/models.py", line 953, in raise_for_status
raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 401 Client Error: Unauthorized for url: https://api-gateway.instructure.com/dap/job/2df51c6a-0f8c-411e-b94b-a6991b62593a

We've got some retry logic that will restart a failed job up to three times, so we were eventually able to get the data on the second try. Note that it still took around 10 minutes to get the data for a table that consisted of just a single file.

2023-11-03 08:03:58,722 [INFO] Latest timestamp for table scores: 2023-11-02T09:11:02Z
2023-11-03 08:03:59,639 [INFO] Attempting again in 5 seconds
2023-11-03 08:04:04,824 [INFO] Attempting again in 5 seconds
<truncated>
2023-11-03 08:13:27,846 [INFO] Attempting again in 5 seconds
2023-11-03 08:13:33,002 [INFO] Attempting again in 5 seconds
2023-11-03 08:13:38,360 [INFO] Data fetch complete
2023-11-03 08:13:38,758 [INFO] Checking if folder 2023-11-03 exists in the S3 bucket
2023-11-03 08:13:39,363 [INFO] Stored part-00000-e175e7df-7a1b-4774-92df-a2533b959299-c000.json.gz in S3 bucket
2023-11-03 08:13:39,421 [INFO] Pushed part-00000-e175e7df-7a1b-4774-92df-a2533b959299-c000.json.gz in active processing path in S3 bucket
2023-11-03 08:13:40,315 [INFO] Objects pushed to S3 buckets successfully

Is there some maximum limit to auto-scaling that needs to be rethought on the Instructure side to give dap more capacity?

[jwals]

We had 66 out of 90 tables fail this morning. We have implemented an AWS-based solution that kicks off a Lambda process for each table. We have the processes configured to time out after five minutes, retry once, and then fail. So we're not hitting the sixty minute token expiration issue, but a majority of our queries didn't receive a reply after ten minutes. An example from our logging is below.

2023-11-03T09:23:57.514-04:00	[INFO] 2023-11-03T13:23:57.514Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Beginning incremental sync for scores
2023-11-03T09:23:58.228-04:00	[INFO] 2023-11-03T13:23:58.228Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Query started with job ID: 6dc4533a-a8c0-42d4-8bc7-8f128b6d8c9c
2023-11-03T09:23:58.228-04:00	[INFO] 2023-11-03T13:23:58.228Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Query job still in status: running. Checking again in 5 seconds...
2023-11-03T09:24:03.344-04:00	[INFO] 2023-11-03T13:24:03.344Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Query job still in status: running. Checking again in 5 seconds...
<truncated>
2023-11-03T09:28:50.389-04:00	[INFO] 2023-11-03T13:28:50.389Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Query job still in status: running. Checking again in 5 seconds...
2023-11-03T09:28:55.523-04:00	[INFO] 2023-11-03T13:28:55.523Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Query job still in status: running. Checking again in 5 seconds...
2023-11-03T09:28:57.522-04:00	2023-11-03T13:28:57.522Z c8a78efc-5998-4d91-88a9-b5a09b3e16dc Task timed out after 300.01 seconds 

[jsimon3]

One note that I would to share with everyone that you all helped me learn from this experience that we baked into the nuget (https://github.com/uvadev/PullCanvasData2/pkgs/nuget/PullCanvasData2) package:
---   the JWT expires in an hour after authentication...  ---
Its in the API documentation here:  https://api-gateway.instructure.com/doc/ 
But shame on us we didn’t include a catch for it, then it bit us in the ass: 

 

But now:
-  It dynamically retries auth whenever the token is close to expiring

-  In that object is the duration until the token expires

-  So when a request is made and the token is set to expire in under 10 minutes from that point, it async yields while the authentication function gets called again