logging: make default logging less verbose, add useful logs

Author: timonegk

cmd/calendarsync/main.go

@@ -103,6 +103,8 @@ func main() {
 }
 
 func Run(c *cli.Context) error {
+	log.Info("started calendarsync")
+
 	if c.Bool(flagVersion) {
 		fmt.Println("Version:", Version)
 		os.Exit(0)
@@ -112,7 +114,7 @@ func Run(c *cli.Context) error {
 	if err != nil {
 		return err
 	}
-	log.Info("loaded config file", "path", cfg.Path)
+	log.Debug("loaded config file", "path", cfg.Path)
 
 	if len(c.String(flagStorageEncryptionKey)) > 0 {
 		log.Warn("Parsing the encryption key using the flag is deprecated. Please use the environment variable $CALENDARSYNC_ENCRYPTION_KEY instead.")
@@ -164,7 +166,7 @@ func Run(c *cli.Context) error {
 	if err != nil {
 		return err
 	}
-	log.Info("loaded source adapter", "adapter", cfg.Source.Adapter.Type, "calendar", cfg.Source.Adapter.Calendar)
+	log.Debug("loaded source adapter", "adapter", cfg.Source.Adapter.Type, "calendar", cfg.Source.Adapter.Calendar)
 
 	sinkLogger := log.With("adapter", cfg.Sink.Adapter.Type, "type", "sink")
 
@@ -179,7 +181,7 @@ func Run(c *cli.Context) error {
 	if err != nil {
 		return err
 	}
-	log.Info("loaded sink adapter", "adapter", cfg.Sink.Adapter.Type, "calendar", cfg.Sink.Adapter.Calendar)
+	log.Debug("loaded sink adapter", "adapter", cfg.Sink.Adapter.Type, "calendar", cfg.Sink.Adapter.Calendar)
 
 	// By default go runs a garbage collection once the memory usage doubles compared to the last GC run.
 	// Decrypting the storage in NewSourceAdapterFromConfig/NewSinkAdapterFromConfig requires a lot of memory,
@@ -197,7 +199,7 @@ func Run(c *cli.Context) error {
 	if cfg.UpdateConcurrency != 0 {
 		controller.SetConcurrency(cfg.UpdateConcurrency)
 	}
-	log.Info("loaded sync controller")
+	log.Debug("loaded sync controller")
 
 	if c.Bool("clean") {
 		err = controller.CleanUp(c.Context, startTime, endTime)
@@ -211,5 +213,6 @@ func Run(c *cli.Context) error {
 			log.Fatalf("we had some errors during synchronization:\n%v", err)
 		}
 	}
+	log.Info("sync complete")
 	return nil
 }

internal/adapter/google/adapter.go

@@ -94,7 +94,7 @@ func (c *CalendarAPI) SetupOauth2(ctx context.Context, credentials auth.Credenti
 		}
 
 		c.authenticated = true
-		c.logger.Info("using stored credentials")
+		c.logger.Debug("using stored credentials")
 	}
 
 	return nil
@@ -178,7 +178,7 @@ func (c *CalendarAPI) EventsInTimeframe(ctx context.Context, start time.Time, en
 		return nil, err
 	}
 
-	c.logger.Infof("loaded %d events between %s and %s.", len(events), start.Format(time.RFC1123), end.Format(time.RFC1123))
+	c.logger.Infof("loaded %d events between %s and %s.", len(events), start.Format(time.DateOnly), end.Format(time.DateOnly))
 
 	return events, nil
 }

internal/adapter/outlook_http/adapter.go

@@ -154,7 +154,7 @@ func (c *CalendarAPI) SetupOauth2(ctx context.Context, credentials auth.Credenti
 		}
 
 		c.authenticated = true
-		c.logger.Info("using stored credentials")
+		c.logger.Debug("using stored credentials")
 		c.logger.Debugf("expiry time of stored token: %s", expiry.String())
 	}
 
@@ -207,7 +207,7 @@ func (c *CalendarAPI) EventsInTimeframe(ctx context.Context, start time.Time, en
 		return nil, err
 	}
 
-	c.logger.Infof("loaded %d events between %s and %s.", len(events), start.Format(time.RFC1123), end.Format(time.RFC1123))
+	c.logger.Infof("loaded %d events between %s and %s.", len(events), start.Format(time.DateOnly), end.Format(time.DateOnly))
 
 	return events, nil
 }

internal/adapter/zep/client.go

@@ -32,13 +32,15 @@ type CalendarAPI struct {
 	client *caldav.Client
 
 	calendarID string
+	logger     *log.Logger
 
 	principal string
 	homeSet   string
 }
 
 // Assert that the expected interfaces are implemented
 var _ port.Configurable = &CalendarAPI{}
+var _ port.LogSetter = &CalendarAPI{}
 
 func (zep *CalendarAPI) GetCalendarHash() string {
 	var id []byte
@@ -95,6 +97,9 @@ func (zep *CalendarAPI) EventsInTimeframe(ctx context.Context, start time.Time,
 	}
 
 	var syncEvents []models.Event
+
+	zep.logger.Infof("loaded %d events between %s and %s.", len(absences), start.Format(time.DateOnly), end.Format(time.DateOnly))
+
 	for _, v := range absences {
 		syncEvents = append(syncEvents,
 			models.Event{
@@ -204,3 +209,7 @@ func safeGetComponentPropValueString(event ical.Event, key string) string {
 	}
 	return prop.Value
 }
+
+func (zep *CalendarAPI) SetLogger(logger *log.Logger) {
+	zep.logger = logger
+}

internal/sync/controller.go

@@ -80,7 +80,7 @@ func (p Controller) SynchroniseTimeframe(ctx context.Context, start time.Time, e
 	filteredEventsInSource := []models.Event{}
 
 	for _, filter := range p.filters {
-		p.logger.Info("loaded filter", "name", filter.Name())
+		p.logger.Debug("loaded filter", "name", filter.Name())
 	}
 
 	for _, event := range eventsInSource {
@@ -96,14 +96,15 @@ func (p Controller) SynchroniseTimeframe(ctx context.Context, start time.Time, e
 
 	// Output which transformers were loaded
 	for _, trans := range p.transformers {
-		p.logger.Info("loaded transformer", "name", trans.Name())
+		p.logger.Debug("loaded transformer", "name", trans.Name())
 	}
 
 	for _, event := range filteredEventsInSource {
 		transformedEventsInSource = append(transformedEventsInSource, TransformEvent(event, p.transformers...))
 	}
 
 	toCreate, toUpdate, toDelete := p.diffEvents(transformedEventsInSource, eventsInSink)
+	log.Infof("found %d new, %d changed, and %d deleted events", len(toCreate), len(toUpdate), len(toDelete))
 	if dryRun {
 		p.logger.Warn("we're running in dry run mode, no changes will be executed")
 		return nil
@@ -200,7 +201,7 @@ func (p Controller) diffEvents(sourceEvents []models.Event, sinkEvents []models.
 			// - Delete event (in calendar A)
 			// - Run sync from calendar B to calendar A. This will copy (and thereby resurrect) the event.
 			//
-			// Solution: Ignore events the originate from the sink, but no longer exist there.
+			// Solution: Ignore events that originate from the sink, but no longer exist there.
 			if event.Metadata.SourceID == p.sink.GetCalendarHash() {
 				p.logger.Info("skipping event as it originates from the sink, but no longer exists there", logFields(event)...)
 				continue