From 9b32926005798323035abc50b0d2709b8ceed7a0 Mon Sep 17 00:00:00 2001 From: Brandon Cook Date: Mon, 26 Sep 2022 14:38:26 +1000 Subject: [PATCH] [CSE-1] Improve logging of CSV export (#285) * [CSE-1] Improve logging of CSV export - Standardised the fields coming out of the regular exporter - Added timing information from the CSV exporter * Encode ts in JSON logs as ISO timestamps --- internal/app/feed/exporter_csv.go | 25 ++++++++-- internal/app/feed/exporter_schema.go | 2 +- internal/app/feed/exporter_sql.go | 4 +- internal/app/feed/feed.go | 31 ------------ internal/app/feed/feed_action.go | 20 ++++---- internal/app/feed/feed_action_assignees.go | 16 +++++-- internal/app/feed/feed_group.go | 14 ++++-- internal/app/feed/feed_group_user.go | 14 ++++-- internal/app/feed/feed_inspection.go | 22 +++++---- internal/app/feed/feed_inspection_item.go | 20 ++++---- internal/app/feed/feed_issue.go | 9 +++- internal/app/feed/feed_schedule.go | 14 ++++-- internal/app/feed/feed_schedule_assginee.go | 6 ++- internal/app/feed/feed_schedule_occurrence.go | 14 ++++-- internal/app/feed/feed_site.go | 14 ++++-- internal/app/feed/feed_site_member.go | 14 ++++-- internal/app/feed/feed_template.go | 16 +++++-- internal/app/feed/feed_template_permission.go | 15 ++++-- internal/app/feed/feed_test.go | 47 ------------------- internal/app/feed/feed_user.go | 14 ++++-- internal/app/util/logger.go | 4 +- 21 files changed, 183 insertions(+), 152 deletions(-) delete mode 100644 internal/app/feed/feed_test.go diff --git a/internal/app/feed/exporter_csv.go b/internal/app/feed/exporter_csv.go index 8c83e7fe..e96b3b35 100644 --- a/internal/app/feed/exporter_csv.go +++ b/internal/app/feed/exporter_csv.go @@ -22,7 +22,10 @@ type CSVExporter struct { // CreateSchema generated schema for a feed in csv format func (e *CSVExporter) CreateSchema(feed Feed, rows interface{}) error { - e.Logger.Infof("%s: writing out CSV schema file", feed.Name()) + logger := e.Logger.With( + "feed", feed.Name(), + ) + logger.Info("writing out CSV schema file") exportFilePath := filepath.Join(e.ExportPath, fmt.Sprintf("%s.csv", feed.Name())) _, err := os.Stat(exportFilePath) @@ -36,14 +39,17 @@ func (e *CSVExporter) CreateSchema(feed Feed, rows interface{}) error { return gocsv.Marshal(rows, file) } - e.Logger.Infof("%s: skipping. CSV file already exists.", feed.Name()) + logger.Info("CSV file already exists, skipping") return nil } // FinaliseExport closes out an export func (e *CSVExporter) FinaliseExport(feed Feed, rows interface{}) error { - e.Logger.Infof("%s: writing out CSV file", feed.Name()) + logger := e.Logger.With( + "feed", feed.Name(), + ) + logger.Info("writing out CSV file") err := e.cleanOldFiles(feed.Name()) if err != nil { @@ -58,6 +64,7 @@ func (e *CSVExporter) FinaliseExport(feed Feed, rows interface{}) error { rowsAdded := 0 var file *os.File for { + preTime := time.Now() resp := e.DB.Table(feed.Name()). Order(feed.Order()). Limit(limit). @@ -66,6 +73,7 @@ func (e *CSVExporter) FinaliseExport(feed Feed, rows interface{}) error { if resp.Error != nil { return resp.Error } + postQueryTime := time.Now() if resp.RowsAffected == 0 || resp.RowsAffected == -1 { break @@ -97,9 +105,20 @@ func (e *CSVExporter) FinaliseExport(feed Feed, rows interface{}) error { } } + postWriteTime := time.Now() + offset = offset + limit rowsAdded += int(resp.RowsAffected) + + logger.With( + "rows_added", resp.RowsAffected, + "total_time_ms", postWriteTime.Sub(preTime).Milliseconds(), + "query_time_ms", postQueryTime.Sub(preTime).Milliseconds(), + "write_time_ms", postWriteTime.Sub(postQueryTime).Milliseconds(), + ).Info("writing out CSV batch") } + + logger.Info("CSV exported") return nil } diff --git a/internal/app/feed/exporter_schema.go b/internal/app/feed/exporter_schema.go index 7671aff0..d1bae7fd 100644 --- a/internal/app/feed/exporter_schema.go +++ b/internal/app/feed/exporter_schema.go @@ -35,7 +35,7 @@ func isPrimaryKey(pk int) string { // WriteSchema writes schema of a feed to output in tabular format func (e *SchemaExporter) WriteSchema(feed Feed) error { - e.Logger.Infof("Schema for %s:", feed.Name()) + e.Logger.With("feed", feed.Name()).Info("writing schema") schema := &[]*schema{} diff --git a/internal/app/feed/exporter_sql.go b/internal/app/feed/exporter_sql.go index 6455444c..3d2ddbc9 100644 --- a/internal/app/feed/exporter_sql.go +++ b/internal/app/feed/exporter_sql.go @@ -63,7 +63,9 @@ func (e *SQLExporter) InitFeed(feed Feed, opts *InitFeedOptions) error { } if opts.Truncate { - e.Logger.Infof("%s: truncating", feed.Name()) + e.Logger.With( + "feed", feed.Name(), + ).Info("truncating") result := e.DB.Session(&gorm.Session{AllowGlobalUpdate: true}).Unscoped().Delete(model) if result.Error != nil { return errors.Wrap(result.Error, "Unable to truncate table") diff --git a/internal/app/feed/feed.go b/internal/app/feed/feed.go index 1aa5b117..8263e9ca 100644 --- a/internal/app/feed/feed.go +++ b/internal/app/feed/feed.go @@ -2,7 +2,6 @@ package feed import ( "context" - "fmt" "time" "github.com/SafetyCulture/iauditor-exporter/internal/app/api" @@ -44,33 +43,3 @@ type Exporter interface { SupportsUpsert() bool ParameterLimit() int } - -// LogStringConfig is the config for GetLogString function -type LogStringConfig struct { - RemainingRecords int64 - HTTPDuration time.Duration - ExporterDuration time.Duration -} - -// GetLogString build a log string based on input arguments -func GetLogString(feedName string, cfg *LogStringConfig) string { - var args = []any{feedName} - var format = "%s: " - - if cfg != nil { - format = format + "%d remaining." - args = append(args, cfg.RemainingRecords) - - if cfg.HTTPDuration.Milliseconds() != 0 { - format = format + " Last http call was %dms." - args = append(args, cfg.HTTPDuration.Milliseconds()) - } - - if cfg.ExporterDuration.Milliseconds() != 0 { - format = format + " Last export operation was %dms." - args = append(args, cfg.ExporterDuration.Milliseconds()) - } - } - - return fmt.Sprintf(format, args...) -} diff --git a/internal/app/feed/feed_action.go b/internal/app/feed/feed_action.go index a627a723..3d6dd958 100644 --- a/internal/app/feed/feed_action.go +++ b/internal/app/feed/feed_action.go @@ -95,8 +95,10 @@ func (f *ActionFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *ActionFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) exporter.InitFeed(f, &InitFeedOptions{ // Delete data if incremental refresh is disabled so there is no duplicates @@ -107,7 +109,9 @@ func (f *ActionFeed) Export(ctx context.Context, apiClient *api.Client, exporter f.ModifiedAfter, err = exporter.LastModifiedAt(f, f.ModifiedAfter, orgID) util.Check(err, "unable to load modified after") - logger.Infof("%s: exporting for org_id: %s since: %s", feedName, orgID, f.ModifiedAfter.Format(time.RFC1123)) + logger.With( + "modified_after", f.ModifiedAfter.Format(time.RFC1123), + ).Info("exporting") err = apiClient.DrainFeed(ctx, &api.GetFeedRequest{ InitialURL: "/feed/actions", @@ -136,11 +140,11 @@ func (f *ActionFeed) Export(ctx context.Context, apiClient *api.Client, exporter } } - logger.Info(GetLogString(f.Name(), &LogStringConfig{ - RemainingRecords: resp.Metadata.RemainingRecords, - HTTPDuration: apiClient.Duration, - ExporterDuration: exporter.GetDuration(), - })) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_action_assignees.go b/internal/app/feed/feed_action_assignees.go index a5290a05..e2b3aa4d 100644 --- a/internal/app/feed/feed_action_assignees.go +++ b/internal/app/feed/feed_action_assignees.go @@ -97,8 +97,10 @@ func (f *ActionAssigneeFeed) writeRows(ctx context.Context, exporter Exporter, r // Export exports the feed to the supplied exporter func (f *ActionAssigneeFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) exporter.InitFeed(f, &InitFeedOptions{ // Delete data if incremental refresh is disabled so there is no duplicates @@ -109,7 +111,9 @@ func (f *ActionAssigneeFeed) Export(ctx context.Context, apiClient *api.Client, f.ModifiedAfter, err = exporter.LastModifiedAt(f, f.ModifiedAfter, orgID) util.Check(err, "unable to load modified after") - logger.Infof("%s: exporting for org_id: %s since: %s", feedName, orgID, f.ModifiedAfter.Format(time.RFC1123)) + logger.With( + "modified_after", f.ModifiedAfter.Format(time.RFC1123), + ).Info("exporting") err = apiClient.DrainFeed(ctx, &api.GetFeedRequest{ InitialURL: "/feed/action_assignees", @@ -127,7 +131,11 @@ func (f *ActionAssigneeFeed) Export(ctx context.Context, apiClient *api.Client, util.Check(err, "Failed to write data to exporter") } - logger.Infof("%s: %d remaining", feedName, resp.Metadata.RemainingRecords) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_group.go b/internal/app/feed/feed_group.go index 89aca4a3..3f39ddcc 100644 --- a/internal/app/feed/feed_group.go +++ b/internal/app/feed/feed_group.go @@ -61,10 +61,12 @@ func (f *GroupFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *GroupFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Truncate files if upserts aren't supported. @@ -96,7 +98,11 @@ func (f *GroupFeed) Export(ctx context.Context, apiClient *api.Client, exporter } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_group_user.go b/internal/app/feed/feed_group_user.go index 80cfdfe5..7ab895d7 100644 --- a/internal/app/feed/feed_group_user.go +++ b/internal/app/feed/feed_group_user.go @@ -62,10 +62,12 @@ func (f *GroupUserFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *GroupUserFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Truncate files if upserts aren't supported. @@ -101,7 +103,11 @@ func (f *GroupUserFeed) Export(ctx context.Context, apiClient *api.Client, expor } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_inspection.go b/internal/app/feed/feed_inspection.go index ca0cef69..9ebd113f 100644 --- a/internal/app/feed/feed_inspection.go +++ b/internal/app/feed/feed_inspection.go @@ -161,8 +161,10 @@ func (f *InspectionFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *InspectionFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) exporter.InitFeed(f, &InitFeedOptions{ // Delete data if incremental refresh is disabled so there is no duplicates @@ -173,7 +175,10 @@ func (f *InspectionFeed) Export(ctx context.Context, apiClient *api.Client, expo f.ModifiedAfter, err = exporter.LastModifiedAt(f, f.ModifiedAfter, orgID) util.Check(err, "unable to load modified after") - logger.Infof("%s: exporting for org_id: %s since: %s - %s", feedName, orgID, f.ModifiedAfter.Format(time.RFC1123), f.WebReportLink) + logger.With( + "modified_after", f.ModifiedAfter.Format(time.RFC1123), + "web_report_link_type", f.WebReportLink, + ).Info("exporting") // Process Inspections err = f.processNewInspections(ctx, apiClient, exporter) @@ -214,11 +219,12 @@ func (f *InspectionFeed) processNewInspections(ctx context.Context, apiClient *a } } - lg.Info(GetLogString(f.Name(), &LogStringConfig{ - RemainingRecords: resp.Metadata.RemainingRecords, - HTTPDuration: apiClient.Duration, - ExporterDuration: exporter.GetDuration(), - })) + lg.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") + return nil } diff --git a/internal/app/feed/feed_inspection_item.go b/internal/app/feed/feed_inspection_item.go index bad71d91..a1b60eda 100644 --- a/internal/app/feed/feed_inspection_item.go +++ b/internal/app/feed/feed_inspection_item.go @@ -222,8 +222,10 @@ func (f *InspectionItemFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *InspectionItemFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) exporter.InitFeed(f, &InitFeedOptions{ // Delete data if incremental refresh is disabled so there is no duplicates @@ -234,7 +236,9 @@ func (f *InspectionItemFeed) Export(ctx context.Context, apiClient *api.Client, f.ModifiedAfter, err = exporter.LastModifiedAt(f, f.ModifiedAfter, orgID) util.Check(err, "unable to load modified after") - logger.Infof("%s: exporting for org_id: %s since: %s", feedName, orgID, f.ModifiedAfter.Format(time.RFC1123)) + logger.With( + "modified_after", f.ModifiedAfter.Format(time.RFC1123), + ).Info("exporting") err = apiClient.DrainFeed(ctx, &api.GetFeedRequest{ InitialURL: "/feed/inspection_items", @@ -257,11 +261,11 @@ func (f *InspectionItemFeed) Export(ctx context.Context, apiClient *api.Client, util.Check(err, "Failed to write data to exporter") } - logger.Info(GetLogString(f.Name(), &LogStringConfig{ - RemainingRecords: resp.Metadata.RemainingRecords, - HTTPDuration: apiClient.Duration, - ExporterDuration: exporter.GetDuration(), - })) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_issue.go b/internal/app/feed/feed_issue.go index 8268bc71..92b9fae6 100644 --- a/internal/app/feed/feed_issue.go +++ b/internal/app/feed/feed_issue.go @@ -3,9 +3,10 @@ package feed import ( "context" "encoding/json" + "time" + "github.com/SafetyCulture/iauditor-exporter/internal/app/api" "github.com/SafetyCulture/iauditor-exporter/internal/app/util" - "time" ) const ( @@ -118,7 +119,11 @@ func (f *IssueFeed) Export(ctx context.Context, apiClient *api.Client, exporter } } - logger.Infof("%s: %d remaining. Last call was %dms", f.Name(), resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil } diff --git a/internal/app/feed/feed_schedule.go b/internal/app/feed/feed_schedule.go index 7bc199f8..edd68207 100644 --- a/internal/app/feed/feed_schedule.go +++ b/internal/app/feed/feed_schedule.go @@ -91,10 +91,12 @@ func (f *ScheduleFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *ScheduleFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Truncate files if upserts aren't supported. @@ -128,7 +130,11 @@ func (f *ScheduleFeed) Export(ctx context.Context, apiClient *api.Client, export } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_schedule_assginee.go b/internal/app/feed/feed_schedule_assginee.go index 96cddd25..73151b38 100644 --- a/internal/app/feed/feed_schedule_assginee.go +++ b/internal/app/feed/feed_schedule_assginee.go @@ -105,7 +105,11 @@ func (f *ScheduleAssigneeFeed) Export(ctx context.Context, apiClient *api.Client } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_schedule_occurrence.go b/internal/app/feed/feed_schedule_occurrence.go index c7991adb..33320838 100644 --- a/internal/app/feed/feed_schedule_occurrence.go +++ b/internal/app/feed/feed_schedule_occurrence.go @@ -82,10 +82,12 @@ func (f *ScheduleOccurrenceFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *ScheduleOccurrenceFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Always truncate. This data must be refreshed in order to be accurate @@ -118,7 +120,11 @@ func (f *ScheduleOccurrenceFeed) Export(ctx context.Context, apiClient *api.Clie } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_site.go b/internal/app/feed/feed_site.go index 945151cd..e971bb96 100644 --- a/internal/app/feed/feed_site.go +++ b/internal/app/feed/feed_site.go @@ -74,10 +74,12 @@ func (f *SiteFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *SiteFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Truncate files if upserts aren't supported. @@ -113,7 +115,11 @@ func (f *SiteFeed) Export(ctx context.Context, apiClient *api.Client, exporter E } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_site_member.go b/internal/app/feed/feed_site_member.go index d000bea9..f3ab8252 100644 --- a/internal/app/feed/feed_site_member.go +++ b/internal/app/feed/feed_site_member.go @@ -57,10 +57,12 @@ func (f *SiteMemberFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *SiteMemberFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Truncate files if upserts aren't supported. @@ -91,7 +93,11 @@ func (f *SiteMemberFeed) Export(ctx context.Context, apiClient *api.Client, expo } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_template.go b/internal/app/feed/feed_template.go index d3d6567e..6b99571b 100644 --- a/internal/app/feed/feed_template.go +++ b/internal/app/feed/feed_template.go @@ -80,8 +80,10 @@ func (f *TemplateFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *TemplateFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) exporter.InitFeed(f, &InitFeedOptions{ // Delete data if incremental refresh is disabled so there is no duplicates @@ -92,7 +94,9 @@ func (f *TemplateFeed) Export(ctx context.Context, apiClient *api.Client, export f.ModifiedAfter, err = exporter.LastModifiedAt(f, f.ModifiedAfter, orgID) util.Check(err, "unable to load modified after") - logger.Infof("%s: exporting for org_id: %s since: %s", feedName, orgID, f.ModifiedAfter.Format(time.RFC1123)) + logger.With( + "modified_after", f.ModifiedAfter, + ).Info("exporting") err = apiClient.DrainFeed(ctx, &api.GetFeedRequest{ InitialURL: "/feed/templates", @@ -120,7 +124,11 @@ func (f *TemplateFeed) Export(ctx context.Context, apiClient *api.Client, export } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_template_permission.go b/internal/app/feed/feed_template_permission.go index 97e9caef..ccd472f7 100644 --- a/internal/app/feed/feed_template_permission.go +++ b/internal/app/feed/feed_template_permission.go @@ -68,10 +68,12 @@ func (f *TemplatePermissionFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *TemplatePermissionFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger.Info("exporting") exporter.InitFeed(f, &InitFeedOptions{ // Always truncate. This data must be refreshed in order to be accurate @@ -104,7 +106,12 @@ func (f *TemplatePermissionFeed) Export(ctx context.Context, apiClient *api.Clie } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") + return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/feed/feed_test.go b/internal/app/feed/feed_test.go deleted file mode 100644 index bae1cc39..00000000 --- a/internal/app/feed/feed_test.go +++ /dev/null @@ -1,47 +0,0 @@ -package feed_test - -import ( - "github.com/SafetyCulture/iauditor-exporter/internal/app/feed" - "github.com/stretchr/testify/assert" - "testing" - "time" -) - -func TestGetLogString_WhenNoArgumentsArePassed(t *testing.T) { - result := feed.GetLogString("TEST_FEED", nil) - assert.EqualValues(t, "TEST_FEED: ", result) -} - -func TestGetLogString_WhenMinimumArgumentsArePassed(t *testing.T) { - cfg := feed.LogStringConfig{RemainingRecords: 10} - result := feed.GetLogString("TEST_FEED", &cfg) - assert.EqualValues(t, "TEST_FEED: 10 remaining.", result) -} - -func TestGetLogString_WhenHTTPDuration(t *testing.T) { - cfg := feed.LogStringConfig{ - RemainingRecords: 40, - HTTPDuration: time.Second * 5, - } - result := feed.GetLogString("TEST_FEED", &cfg) - assert.EqualValues(t, "TEST_FEED: 40 remaining. Last http call was 5000ms.", result) -} - -func TestGetLogString_WhenExporterDuration(t *testing.T) { - cfg := feed.LogStringConfig{ - RemainingRecords: 20, - ExporterDuration: time.Second * 2, - } - result := feed.GetLogString("TEST_FEED", &cfg) - assert.EqualValues(t, "TEST_FEED: 20 remaining. Last export operation was 2000ms.", result) -} - -func TestGetLogString_WhenAllDataIsPresent(t *testing.T) { - cfg := feed.LogStringConfig{ - RemainingRecords: 50, - ExporterDuration: time.Second * 1, - HTTPDuration: time.Millisecond * 44, - } - result := feed.GetLogString("TEST_FEED", &cfg) - assert.EqualValues(t, "TEST_FEED: 50 remaining. Last http call was 44ms. Last export operation was 1000ms.", result) -} diff --git a/internal/app/feed/feed_user.go b/internal/app/feed/feed_user.go index 75539f2a..f0fe3e51 100644 --- a/internal/app/feed/feed_user.go +++ b/internal/app/feed/feed_user.go @@ -69,10 +69,10 @@ func (f *UserFeed) CreateSchema(exporter Exporter) error { // Export exports the feed to the supplied exporter func (f *UserFeed) Export(ctx context.Context, apiClient *api.Client, exporter Exporter, orgID string) error { - logger := util.GetLogger() - feedName := f.Name() - - logger.Infof("%s: exporting for org_id: %s", feedName, orgID) + logger := util.GetLogger().With( + "feed", f.Name(), + "org_id", orgID, + ) exporter.InitFeed(f, &InitFeedOptions{ // Truncate files if upserts aren't supported. @@ -104,7 +104,11 @@ func (f *UserFeed) Export(ctx context.Context, apiClient *api.Client, exporter E } } - logger.Infof("%s: %d remaining. Last call was %dms", feedName, resp.Metadata.RemainingRecords, apiClient.Duration.Milliseconds()) + logger.With( + "estimated_remaining", resp.Metadata.RemainingRecords, + "duration_ms", apiClient.Duration.Milliseconds(), + "export_duration_ms", exporter.GetDuration().Milliseconds(), + ).Info("export batch complete") return nil }) util.Check(err, "Failed to export feed") diff --git a/internal/app/util/logger.go b/internal/app/util/logger.go index 0ca13ad6..6dcbe80e 100644 --- a/internal/app/util/logger.go +++ b/internal/app/util/logger.go @@ -102,7 +102,9 @@ func GetLogger() *zap.SugaredLogger { return slg } - logFileEncoder := zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()) + prodConfig := zap.NewProductionEncoderConfig() + prodConfig.EncodeTime = zapcore.ISO8601TimeEncoder + logFileEncoder := zapcore.NewJSONEncoder(prodConfig) consoleEncoder := zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()) file, err := os.OpenFile("logs.log", os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)