Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SLOW_GET_HELPER renders bad time in the logs #22312

Closed
gilmrjc opened this issue Mar 3, 2025 · 2 comments · Fixed by #22420
Closed

SLOW_GET_HELPER renders bad time in the logs #22312

gilmrjc opened this issue Mar 3, 2025 · 2 comments · Fixed by #22420
Assignees

Comments

@gilmrjc
Copy link

gilmrjc commented Mar 3, 2025

The get helper has the following code:

            if (totalMs > threshold) {
                logging[logLevel](new errors.HelperWarning({
                    message: `{{#get}} helper took ${totalMs}ms to complete`,
                    code: 'SLOW_GET_HELPER',
                    errorDetails: {
                        api: `${controllerName}.${action}`,
                        apiOptions,
                        returnedRows: returnedRowsCount
                    }
                }), {
                    time: totalMs
                });
            }

This makes the time field to be the time used to query the database. When using this data in the logger, it's used as the logging time.

For example:

2025-03-03T06:50:58.612491147Z [1970-01-01 00:00:00] WARN {{#get}} helper took 231ms to complete

Because the query took 213ms, the field time is parsed as a few milliseconds after the epoc time.

Originally posted by @gilmrjc in #20427 (comment)

@github-actions github-actions bot added the needs:triage [triage] this needs to be triaged by the Ghost team label Mar 3, 2025
@gilmrjc
Copy link
Author

gilmrjc commented Mar 3, 2025

A possible solution may be to change the field name to query_time.

@daniellockyer daniellockyer self-assigned this Mar 10, 2025
daniellockyer added a commit that referenced this issue Mar 10, 2025
fixes #22312

- we were passing `time` as a field to the logging library, but that
  library will interpret it as the time that the log occured
- instead, we can just pass it into the errorDetails to avoid this
@github-actions github-actions bot removed the needs:triage [triage] this needs to be triaged by the Ghost team label Mar 10, 2025
@daniellockyer
Copy link
Member

Fixed for the next release, thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants