Skip to content

Commit e2928a2

Browse files
floehopperchrislo
andcommitted
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 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>
1 parent e00291c commit e2928a2

1 file changed

Lines changed: 21 additions & 0 deletions

File tree

app/models/immunisation_import.rb

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,8 @@ class ImmunisationImport < ApplicationRecord
4444
has_and_belongs_to_many :sessions
4545
has_and_belongs_to_many :vaccination_records
4646

47+
after_create :log_started
48+
4749
def type_label
4850
"Vaccination records"
4951
end
@@ -89,6 +91,7 @@ def process!
8991
post_commit!
9092

9193
update_columns(processed_at: Time.zone.now, status: :processed, **counts)
94+
log_finished
9295
end
9396

9497
private
@@ -190,4 +193,22 @@ def post_commit!
190193

191194
TeamCachedCounts.new(team).reset_import_issues!
192195
end
196+
197+
def log_started
198+
with_logger_tags { logger.info("started") }
199+
end
200+
201+
def log_finished
202+
with_logger_tags do
203+
logger.info(
204+
"finished",
205+
duration_ms: ((processed_at - created_at) * 1000).to_i,
206+
count: rows_count
207+
)
208+
end
209+
end
210+
211+
def with_logger_tags(&)
212+
SemanticLogger.tagged(id:, team_workgroup: team.workgroup, &)
213+
end
193214
end

0 commit comments

Comments
 (0)