feat: add DatabaseQueryLog model for auditing SQL queries (HEXA-1668)#1900
feat: add DatabaseQueryLog model for auditing SQL queries (HEXA-1668)#1900DimitriKwihangana wants to merge 13 commits into
Conversation
mrivar
left a comment
There was a problem hiding this comment.
Very solid PR, with very extensive testing!
Just some code comments, mainly on improving maintainability and DRY / applying Solid principles, it just needs some fiddling to be prod ready 😄
@bramj Given that this new table is going to grow wih every query we do unbounded, with full query text (TextField, uncapped), it might be that it quickly becomes one of our biggest tables. I'd say it is worth to create a ticket to investigate pruning/retention strategies or TTL/archival/partitioning (out of scope from this task)
We might also want to look into whether queries sometimes have personal data and if so how to treat it/clean it (also out of scope from this task)
| DatabaseQueryLog.Status.ERROR, | ||
| result_code=e.pgcode, | ||
| error_message=str(e).strip(), | ||
| duration_ms=int((time.monotonic() - started_at) * 1000), |
There was a problem hiding this comment.
We can extract this into a tiny helper.
Actually if you merge from main there is a 4th instance of the same calculation, so we can change it to use the helper as well (might be worth exploring if there's a difference between time.monotonic() and time.perf_counter())
There was a problem hiding this comment.
Good catch! I will extract this into small helper which will be reusable
| _log_executed_query( | ||
| request, | ||
| workspace, | ||
| query, | ||
| origin, | ||
| DatabaseQueryLog.Status.SUCCESS, | ||
| result_code="00000", | ||
| duration_ms=int((time.monotonic() - started_at) * 1000), | ||
| row_count=result["row_count"], | ||
| truncated=result["truncated"], | ||
| ) |
There was a problem hiding this comment.
As we always end up doing _log_executed_query, this part can be improved by avoiding repeating the same (or similar) type of code by having a finally that absorbs the _log_executed_query. E.g. Something like:
status, log_fields = None, {}
started_at = time.monotonic()
try:
...
result = execute_database_query(...)
status = DatabaseQueryLog.Status.SUCCESS
log_fields = {"result_code": "00000", "row_count": result["row_count"],
"truncated": result["truncated"], "duration_ms": _elapsed(started_at)}
return {"success": True, "errors": [], **result}
except MultipleStatementsError as e:
status, log_fields = DatabaseQueryLog.Status.REJECTED, {"error_message": str(e)}
return {...}
...
finally:
if status:
_log_executed_query(request, workspace, query, origin, status, **log_fields)| # "00000" on success, null when the query never reached the database | ||
| result_code = models.CharField(max_length=5, null=True, blank=True) |
There was a problem hiding this comment.
Well documented, didn't know about that! It would be nice to extract this "00000" success result error into a constant for better maintainability
| class Origin(models.TextChoices): | ||
| API = "API" | ||
| DATA_STUDIO = "DATA_STUDIO" |
There was a problem hiding this comment.
Right now ExecuteSQLOrigin and DatabaseQueryLog.Origin share the same values for contract purposes, which is needed, but it would be nice if we find a way so that they are always closely related. It would give us better maintainability (if a value is added/changed in one of the two, the contract breaks. But if they're closely coupled, changing a value in one them changes it in both).
You can get some inspiration in the codebase with FileEncoding and file_encoding_enum.
| # capped to a server-side hard limit. | ||
| executeSQL(query: String!, maxRows: Int): ExecuteSQLResult! | ||
| # 'origin' identifies where the query comes from for auditing purposes; it defaults to API. | ||
| executeSQL(query: String!, maxRows: Int, origin: ExecuteSQLOrigin): ExecuteSQLResult! |
There was a problem hiding this comment.
Given we already merged #1889, it is worth it to update the frontend to already use ExecuteSQLOrigin, to make sure we start logging the 'DATA_STUDIO' queries correctly from the beginning (instead of being tagged as API by default)
| try: | ||
| DatabaseQueryLog.objects.create( | ||
| workspace=workspace, | ||
| user=request.user if isinstance(request.user, User) else None, |
There was a problem hiding this comment.
Minor: Currently if a request user doesn't have a proper User instance, we ignore and save None, losing track of it (right now this is not reachable, so it is not a real risk, but it might happen if me change it in the future unknowingly).
We can mitigate this by detecting the user that don't have a direct user attached (PipelineRunUser / DAGRunUser) and getting their real_user.
It's more of a safety net than anything and an easy quick win, so I would vote to add it
| """ | ||
| enum ExecuteSQLOrigin { | ||
| """ | ||
| The query was submitted directly through the API. | ||
| """ | ||
| API |
There was a problem hiding this comment.
Not sure API is a great name, maybe we just need a OTHER
| logger.exception( | ||
| "Failed to log database query for workspace %s", workspace.slug | ||
| ) |
There was a problem hiding this comment.
If we keep this : Should we add more details about the error and/or the context maybe ?
There was a problem hiding this comment.
You mean to also add user id and origin of the error. That's helpful
There was a problem hiding this comment.
You can include the exception, this is a pattern we use int he codebase
openhexa-app/backend/hexa/core/admin.py
Lines 70 to 76 in 120f169
| _log_executed_query( | ||
| request, | ||
| workspace, | ||
| query, | ||
| origin, | ||
| DatabaseQueryLog.Status.REJECTED, | ||
| error_message=str(e), | ||
| ) |
There was a problem hiding this comment.
Those calls should probably live at a lower level for instance in execute_database_query
There was a problem hiding this comment.
About the coverage I think I would keep it at the resolver level because the DENIED case never reaches the
execute_database_query and the function has no access to the request/user/origin that the log entry needs. Since the resolver is the only caller today, the API boundary covers everything. I've added a not in docstring so that a second caller wont miss it. let me know what you think.
There was a problem hiding this comment.
The new version looks already better but I think we should enclose the logic in one function to avoid repeating ourself and avoid dealing with logging logic in the resolver layer :
we can have a wrapper of execute_database_query that accepts the correct args (the one required for the query execution and the one for the logging), catch exceptions, logs accordingly and raise the exception to the resolver.
There was a problem hiding this comment.
The goal is to maintain a single point of entry for executing SQL from the resolver layer. It's easier to test, maintain and not forget to call the log entry creation if we add a new exception type handling to the resolver
| # Auditing must never break query execution, hence the broad except. | ||
| try: | ||
| DatabaseQueryLog.objects.create( | ||
| workspace=workspace, | ||
| user=request.user if isinstance(request.user, User) else None, | ||
| query=query, | ||
| origin=origin, | ||
| status=status, | ||
| **fields, | ||
| ) |
There was a problem hiding this comment.
Since we store those logs in the database (and not a distant server), there is no reason to assume this can fail. So I would assume that if this raises that there is a bug and we shouldn't catch it
Adds the DatabaseQueryLog model to track SQL queries executed against workspace databases, including status, origin, duration, row count, and error details.
df104f9 to
f1123de
Compare
Log all SQL queries executed against workspace databases via the executeSQL GraphQL field, for auditing and to enable a future query history component
Changes
Please list / describe the changes in the codebase for the reviewer(s).