Commit 000162d
Log started & finished for ImmunisationImport
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 seconds) 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.
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>1 parent d909e92 commit 000162d
1 file changed
Lines changed: 21 additions & 0 deletions
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
44 | 44 | | |
45 | 45 | | |
46 | 46 | | |
| 47 | + | |
| 48 | + | |
47 | 49 | | |
48 | 50 | | |
49 | 51 | | |
| |||
89 | 91 | | |
90 | 92 | | |
91 | 93 | | |
| 94 | + | |
92 | 95 | | |
93 | 96 | | |
94 | 97 | | |
| |||
190 | 193 | | |
191 | 194 | | |
192 | 195 | | |
| 196 | + | |
| 197 | + | |
| 198 | + | |
| 199 | + | |
| 200 | + | |
| 201 | + | |
| 202 | + | |
| 203 | + | |
| 204 | + | |
| 205 | + | |
| 206 | + | |
| 207 | + | |
| 208 | + | |
| 209 | + | |
| 210 | + | |
| 211 | + | |
| 212 | + | |
| 213 | + | |
193 | 214 | | |
0 commit comments