SQL Lab UI does not populate results - query/updated_since endpoint unexpectedly returns empty array

[spyoungtech]

SQL Lab utilizes the /api/v1/query/updated_since endpoint to retrieve updated queries in order to ultimately display results. We are experiencing a problem where results are not populating in the SQL Lab UI. Upon our own investigation, this appears to be caused by this endpoint unexpectedly returning an empty array.

How to reproduce the bug

1. Start superset and superset workers with caching and a result backend (redis) configured
2. Configure asynchronous results for your database connection (database connections -> edit -> advanced -> performance)
3. Open SQLLab
4. (with browser network inspector open) Select database and schema and run a simple query
5. Observe this (may) succeed, populating the query result data in the UI and:
   • The call to /api/v1/query/updated_since returned a non-empty array containing the relevant query result key
   • There is a subsequent network call to retrieve the result data using the result key from the previous response
6. (With browser inspector still open) Run another query -- this can be the same query or a different one
7. Observe that the query results are unexpectedly not displayed with the message "Run a query to display results" shown and:
   • The call to /api/v1/query/updated_since returned an empty array
   • No subsequent network calls are made
8. Check the superset worker logs to confirm there are no errors in processing the query or storing results
9. Obtain the result key from the superset worker logs and confirm results actually exist

Expected results

It is expected that whenever a query is run in the SQL Lab that results will populate in the UI and will not show the message "Run a query to display results" -- or perhaps specifically that the /api/v1/query/updated_since does not return an empty array

Actual results

No updated queries are returned by the call to /api/v1/query/updated_since and hence the UI never populates any result data, despite the fact the query indeed runs and has results

Screenshots

Here are a couple videos showing the problem as described

full video

vid2.mov

short video

vid1.mov

Environment

(please complete the following information):

• browser type and version: firefox 114.0.1 on MacOS
• superset version: docker latest (apache/superset:45901dafbb1258f57dd314a03e211fd81b258a58)
• python version: 3.9.16 (from docker image)
• node.js version: (not sure? N/A)
• any feature flags active: None

Checklist

Make sure to follow these steps before submitting your issue - thank you!

• I have checked the superset logs for python stacktraces and included it here as text if there are any.
• I have reproduced the issue with at least the latest released version of superset.
• I have checked the issue tracker for the same issue and I haven't found one similar.

Additional context

We have tried manually editing and resending the request to the api/v1/query/updated_since endpoint with modified values for last_updated_ms (less than and greater than the original value by varying amounts between 5000 and 50000) but still received the same empty array.

Additional investigation has revealed the following relevant information:

• Requests that unexpectedly fail seem to have an unexpected value for last_updated_ms -- that is, the value is a timestamp in the distant future.
  In one example, the database record for the relevant query has start_time as 1687470749474.695000 which reflects the accurate date/time the query was requested -- meanwhile the last_updated_ms value in the javascript-generated request was 1687490271194 -- quite some time in the future.
• We have ensured the system time for both the client and servers hosting superset are set correctly.
• The problem is reproducible across at least 3 different client systems

[spyoungtech]

Our current understanding is this value for last_updated_ms is generated by calling Date.parse on the changed_on attribute returned from the call to the /sqllab/execute endpoint. For example, one such value returned was (accurately) "changed_on": "2023-06-22T21:52:29.488110". However, then this value is run through Date.parse the returned value is obviously not as intended:

Date.parse("2023-06-22T21:52:29.488110")
1687495949488  // in ISO format: 2023-06-23T04:52:29.488000

This appears to be the source of the bug. My estimation is that either the parsing method in javascript or format of data returned by the /sqllab/execute endpoint needs to be changed to fix this.

Adding the Zulu time specifier seems to do the correct thing:

Date.parse("2023-06-22T21:52:29.488110Z")
1687470749488 // in ISO format: 2023-06-22T21:52:29.488000

[yousoph]

cc @villebro @hughhhh

[villebro]

This must be a regression from #24422. I think I know how this should be changed to work correctly, but I'm unfortunately tied up right now and can't work on it until Monday next week. If this is a critical blocker I suggest reverting it until a proper fix is put in place. Ping @yousoph @hughhhh

[villebro]

@spyoungtech thanks for the detailed analysis. Please take a look at #24513 which should resolve the issue. cc: @yousoph @hughhhh

[spyoungtech]

Thanks for the speedy response @villebro #24513 looks good to me -- happy to test and confirm fixed once a docker image with this change is published.

[villebro]

@spyoungtech it would be very much appreciated if you can give the latest master branch cut a test ride and report back your findings!

[spyoungtech]

@villebro Confirmed -- the issue is resolved on the latest build including this change. Thanks for the speedy fix. 🎉