Log started & finished events for Immunisation Import#6718
Open
Log started & finished events for Immunisation Import#6718
Conversation
ab2fab9 to
000162d
Compare
000162d to
1fcac7d
Compare
1fcac7d to
1dfe96b
Compare
thomasleese
approved these changes
Apr 30, 2026
This adds logging for the point where an `ImmunisationImport` is created
(typically in `ImmunisationImportsController#create`) and the point where its
processing is completed.
We chose to associate the logging with the `ImmunisationImport` model rather
than the `ProcessImportJob`, partly because we're only interested in
`ImmunisationImport` at the moment (not the other import types) and partly
because some of the other imports span multiple jobs. Ultimately we care about
the end-to-end user journey from when they initiate an import to when the
system is ready for them to proceed.
We're using `SemanticLogger` rather than directly talking to AWS Cloudwatch
Logs, because it feels like it reduces coupling between the Rails app and other
systems.
We're relying on Semantic Logger's built-in functionality for recording the
`name` of the class that logged the message [1] to associate each of the logged
events with the `ImmunisationImport` class. We're also relying on the
`timestamp` that is automatically recorded for every event. This should be
accurate enough for our purposes.
We've chosen to calculate the `duration` (in milliseconds) and include it in
the "finished" event rather than having to calculate it in Cloudwatch/Grafana
from the difference between the `timestamp` on the "started" and "finished"
events. We're also recording the number of rows so that we can "normalize" the
durations of the imports.
Like in `Metrics::ExportSchoolMovesCountJob`, we're recording the `workgroup`
of the `Team` associated with the `ImmunisationImport`.
For the moment we've explicitly decided not to add any specs for these changes,
because we think the existing specs exercise the logging sufficiently to be
confident it doesn't break anything. Our thinking it that we'll add specs later
once we've got a Cloudwatch/Grafana dashboard to reference, i.e. to indicate
that the app needs to log certain things in order to support the relevant
dashboard.
We've tested the logging in development by wiring it up to a manually created
Cloudwatch Log Stream via a Semantic Logger Cloudwatch Logs appender with the
appender format set to `:json` and we see log events like this:
{
"host": "skua",
"application": "Semantic Logger",
"environment": "test",
"timestamp": "2026-04-29T15:30:42.721497Z",
"level": "info",
"level_index": 2,
"pid": 84031,
"thread": "5584",
"named_tags": {
"id": 1,
"team_workgroup": "w1"
},
"name": "ImmunisationImport",
"message": "started"
}
{
"host": "skua",
"application": "Semantic Logger",
"environment": "test",
"timestamp": "2026-04-29T15:30:47.982389Z",
"level": "info",
"level_index": 2,
"pid": 84031,
"thread": "5584",
"named_tags": {
"id": 1,
"team_workgroup": "w1"
},
"name": "ImmunisationImport",
"message": "finished",
"payload": {
"duration_ms": 5259,
"count": 11
}
}
[1]: https://logger.rocketjob.io/
Co-authored-by: Chris Lowis <chris.lowis@gofreerange.com>
1dfe96b to
e2928a2
Compare
Contributor
|
@thomasleese Since you approved this, we;ve made a small change to use |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
This adds logging for the point where an
ImmunisationImportis created (typically inImmunisationImportsController#create) and the point where its processing is completed.We chose to associate the logging with the
ImmunisationImportmodel rather than theProcessImportJob, partly because we're only interested inImmunisationImportat the moment (not the other import types) and partly because some of the other imports span multiple jobs. Ultimately we care about the end-to-end user journey from when they initiate an import to when the system is ready for them to proceed.We're using
SemanticLoggerrather than directly talking to AWS Cloudwatch Logs, because it feels like it reduces coupling between the Rails app and other systems.We're relying on Semantic Logger's built-in functionality for recording the
nameof the class that logged the message to associate each of the logged events with theImmunisationImportclass. We're also relying on thetimestampthat is automatically recorded for every event. This should be accurate enough for our purposes.We've chosen to calculate the
duration(in milliseconds) and include it in the "finished" event rather than having to calculate it in Cloudwatch/Grafana from the difference between thetimestampon the "started" and "finished" events. We're also recording the number of rows so that we can "normalize" the durations of the imports.Like in
Metrics::ExportSchoolMovesCountJob, we're recording theworkgroupof theTeamassociated with theImmunisationImport.For the moment we've explicitly decided not to add any specs for these changes, because we think the existing specs exercise the logging sufficiently to be confident it doesn't break anything. Our thinking it that we'll add specs later once we've got a Cloudwatch/Grafana dashboard to reference, i.e. to indicate that the app needs to log certain things in order to support the relevant dashboard.
We've tested the logging in development by wiring it up to a manually created Cloudwatch Log Stream via a Semantic Logger Cloudwatch Logs appender with the appender format set to
:jsonand we see log events like this:{ "host": "skua", "application": "Semantic Logger", "environment": "test", "timestamp": "2026-04-29T15:30:42.721497Z", "level": "info", "level_index": 2, "pid": 84031, "thread": "5584", "named_tags": { "id": 1, "team_workgroup": "w1" }, "name": "ImmunisationImport", "message": "started" }{ "host": "skua", "application": "Semantic Logger", "environment": "test", "timestamp": "2026-04-29T15:30:47.982389Z", "level": "info", "level_index": 2, "pid": 84031, "thread": "5584", "named_tags": { "id": 1, "team_workgroup": "w1" }, "name": "ImmunisationImport", "message": "finished", "payload": { "duration_ms": 5259, "count": 11 } }Jira Issue - MAV-7301