logging: homogenize levels

The main goal is to ensure that by default, the log file (if configured)
does not grow out of proportions. Most of the logging messages in aerc
are actually for debugging and/or trace purposes.

Define clear rules for logging levels. Enforce these rules everywhere.

After this patch, here is what the log file looks like after starting up
with a single account:

INFO  2022/11/24 20:26:16.147164 aerc.go:176: Starting up version 0.13.0-100-g683981479c60 (go1.18.7 amd64 linux)
INFO  2022/11/24 20:26:17.546448 account.go:254: [work] connected.

Signed-off-by: Robin Jarry <robin@jarry.cc>
Tested-by: Bence Ferdinandy <bence@ferdinandy.com>
Acked-by: Tim Culverhouse <tim@timculverhouse.com>

13 files changed, 47 insertions, 45 deletions

diff --git a/worker/imap/cache.go b/worker/imap/cache.go
index c32131d3..cf92dfaa 100644
--- a/worker/imap/cache.go
+++ b/worker/imap/cache.go
@@ -45,9 +45,9 @@ func (w *IMAPWorker) initCacheDb(acct string) {
 		return
 	}
 	w.cache = db
-	logging.Infof("cache db opened: %s", p)
+	logging.Debugf("cache db opened: %s", p)
 	if w.config.cacheMaxAge.Hours() > 0 {
-		go w.cleanCache()
+		go w.cleanCache(p)
 	}
 }
 
@@ -84,7 +84,7 @@ func (w *IMAPWorker) cacheHeader(mi *models.MessageInfo) {
 }
 
 func (w *IMAPWorker) getCachedHeaders(msg *types.FetchMessageHeaders) []uint32 {
-	logging.Debugf("Retrieving headers from cache: %v", msg.Uids)
+	logging.Tracef("Retrieving headers from cache: %v", msg.Uids)
 	var need []uint32
 	uv := fmt.Sprintf("%d", w.selected.UidValidity)
 	for _, uid := range msg.Uids {
@@ -122,7 +122,7 @@ func (w *IMAPWorker) getCachedHeaders(msg *types.FetchMessageHeaders) []uint32 {
 		if err != nil {
 			mi.Refs = refs
 		}
-		logging.Debugf("located cached header %s.%s", uv, u)
+		logging.Tracef("located cached header %s.%s", uv, u)
 		w.worker.PostMessage(&types.MessageInfo{
 			Message:    types.RespondTo(msg),
 			Info:       mi,
@@ -144,7 +144,7 @@ func cacheDir() (string, error) {
 }
 
 // cleanCache removes stale entries from the selected mailbox cachedb
-func (w *IMAPWorker) cleanCache() {
+func (w *IMAPWorker) cleanCache(path string) {
 	start := time.Now()
 	var scanned, removed int
 	iter := w.cache.NewIterator(nil, nil)
@@ -170,5 +170,6 @@ func (w *IMAPWorker) cleanCache() {
 	}
 	iter.Release()
 	elapsed := time.Since(start)
-	logging.Infof("cleaned cache, removed %d of %d entries in %s", removed, scanned, elapsed)
+	logging.Debugf("%s: removed %d/%d expired entries in %s",
+		path, removed, scanned, elapsed)
 }
diff --git a/worker/imap/checkmail.go b/worker/imap/checkmail.go
index e0aef71b..0f347e09 100644
--- a/worker/imap/checkmail.go
+++ b/worker/imap/checkmail.go
@@ -20,7 +20,7 @@ func (w *IMAPWorker) handleCheckMailMessage(msg *types.CheckMail) {
 			continue
 		}
 
-		logging.Debugf("Getting status of directory %s", dir)
+		logging.Tracef("Getting status of directory %s", dir)
 		status, err := w.client.Status(dir, items)
 		if err != nil {
 			w.worker.PostMessage(&types.Error{
diff --git a/worker/imap/fetch.go b/worker/imap/fetch.go
index f5407087..9256c6eb 100644
--- a/worker/imap/fetch.go
+++ b/worker/imap/fetch.go
@@ -27,7 +27,7 @@ func (imapw *IMAPWorker) handleFetchMessageHeaders(
 			nil)
 		return
 	}
-	logging.Infof("Fetching message headers: %v", toFetch)
+	logging.Tracef("Fetching message headers: %v", toFetch)
 	section := &imap.BodySectionName{
 		BodyPartName: imap.BodyPartName{
 			Specifier: imap.HeaderSpecifier,
@@ -84,7 +84,7 @@ func (imapw *IMAPWorker) handleFetchMessageHeaders(
 func (imapw *IMAPWorker) handleFetchMessageBodyPart(
 	msg *types.FetchMessageBodyPart,
 ) {
-	logging.Infof("Fetching message %d part: %v", msg.Uid, msg.Part)
+	logging.Tracef("Fetching message %d part: %v", msg.Uid, msg.Part)
 
 	var partHeaderSection imap.BodySectionName
 	partHeaderSection.Peek = true
@@ -158,7 +158,7 @@ func (imapw *IMAPWorker) handleFetchMessageBodyPart(
 func (imapw *IMAPWorker) handleFetchFullMessages(
 	msg *types.FetchFullMessages,
 ) {
-	logging.Infof("Fetching full messages: %v", msg.Uids)
+	logging.Tracef("Fetching full messages: %v", msg.Uids)
 	section := &imap.BodySectionName{
 		Peek: true,
 	}
diff --git a/worker/imap/idler.go b/worker/imap/idler.go
index 65ba6b9b..da018334 100644
--- a/worker/imap/idler.go
+++ b/worker/imap/idler.go
@@ -166,5 +166,5 @@ func (i *idler) waitOnIdle() {
 
 func (i *idler) log(format string, v ...interface{}) {
 	msg := fmt.Sprintf(format, v...)
-	logging.Debugf("idler (%p) [idle:%t,wait:%t] %s", i, i.isIdleing(), i.isWaiting(), msg)
+	logging.Tracef("idler (%p) [idle:%t,wait:%t] %s", i, i.isIdleing(), i.isWaiting(), msg)
 }
diff --git a/worker/imap/list.go b/worker/imap/list.go
index 67d4c33d..c3211f21 100644
--- a/worker/imap/list.go
+++ b/worker/imap/list.go
@@ -10,7 +10,7 @@ import (
 
 func (imapw *IMAPWorker) handleListDirectories(msg *types.ListDirectories) {
 	mailboxes := make(chan *imap.MailboxInfo)
-	logging.Infof("Listing mailboxes")
+	logging.Tracef("Listing mailboxes")
 	done := make(chan interface{})
 
 	go func() {
@@ -62,7 +62,7 @@ func (imapw *IMAPWorker) handleSearchDirectory(msg *types.SearchDirectory) {
 		}, nil)
 	}
 
-	logging.Infof("Executing search")
+	logging.Tracef("Executing search")
 	criteria, err := parseSearch(msg.Argv)
 	if err != nil {
 		emitError(err)
diff --git a/worker/imap/observer.go b/worker/imap/observer.go
index 866fac62..867b57d9 100644
--- a/worker/imap/observer.go
+++ b/worker/imap/observer.go
@@ -150,5 +150,5 @@ func (o *observer) emit(errMsg string) {
 
 func (o *observer) log(format string, args ...interface{}) {
 	msg := fmt.Sprintf(format, args...)
-	logging.Debugf("observer (%p) [running:%t] %s", o, o.running, msg)
+	logging.Tracef("observer (%p) [running:%t] %s", o, o.running, msg)
 }
diff --git a/worker/imap/open.go b/worker/imap/open.go
index f3f20a59..f554d524 100644
--- a/worker/imap/open.go
+++ b/worker/imap/open.go
@@ -10,7 +10,7 @@ import (
 )
 
 func (imapw *IMAPWorker) handleOpenDirectory(msg *types.OpenDirectory) {
-	logging.Infof("Opening %s", msg.Directory)
+	logging.Debugf("Opening %s", msg.Directory)
 
 	sel, err := imapw.client.Select(msg.Directory, false)
 	if err != nil {
@@ -27,7 +27,7 @@ func (imapw *IMAPWorker) handleOpenDirectory(msg *types.OpenDirectory) {
 func (imapw *IMAPWorker) handleFetchDirectoryContents(
 	msg *types.FetchDirectoryContents,
 ) {
-	logging.Infof("Fetching UID list")
+	logging.Tracef("Fetching UID list")
 
 	searchCriteria, err := parseSearch(msg.FilterCriteria)
 	if err != nil {
@@ -64,7 +64,7 @@ func (imapw *IMAPWorker) handleFetchDirectoryContents(
 			Error:   err,
 		}, nil)
 	} else {
-		logging.Infof("Found %d UIDs", len(uids))
+		logging.Tracef("Found %d UIDs", len(uids))
 		if len(msg.FilterCriteria) == 1 {
 			// Only initialize if we are not filtering
 			imapw.seqMap.Initialize(uids)
@@ -105,7 +105,7 @@ func translateSortCriterions(
 func (imapw *IMAPWorker) handleDirectoryThreaded(
 	msg *types.FetchDirectoryThreaded,
 ) {
-	logging.Infof("Fetching threaded UID list")
+	logging.Tracef("Fetching threaded UID list")
 
 	searchCriteria, err := parseSearch(msg.FilterCriteria)
 	if err != nil {
@@ -125,7 +125,7 @@ func (imapw *IMAPWorker) handleDirectoryThreaded(
 	} else {
 		aercThreads, count := convertThreads(threads, nil)
 		sort.Sort(types.ByUID(aercThreads))
-		logging.Infof("Found %d threaded messages", count)
+		logging.Tracef("Found %d threaded messages", count)
 		if len(msg.FilterCriteria) == 1 {
 			// Only initialize if we are not filtering
 			var uids []uint32
diff --git a/worker/imap/worker.go b/worker/imap/worker.go
index 506eb182..c3021f91 100644
--- a/worker/imap/worker.go
+++ b/worker/imap/worker.go
@@ -93,14 +93,14 @@ func (w *IMAPWorker) newClient(c *client.Client) {
 	sort, err := w.client.sort.SupportSort()
 	if err == nil && sort {
 		w.caps.Sort = true
-		logging.Infof("Server Capability found: Sort")
+		logging.Debugf("Server Capability found: Sort")
 	}
 	for _, alg := range []sortthread.ThreadAlgorithm{sortthread.References, sortthread.OrderedSubject} {
 		ok, err := w.client.Support(fmt.Sprintf("THREAD=%s", string(alg)))
 		if err == nil && ok {
 			w.threadAlgorithm = alg
 			w.caps.Thread = true
-			logging.Infof("Server Capability found: Thread (algorithm: %s)", string(alg))
+			logging.Debugf("Server Capability found: Thread (algorithm: %s)", string(alg))
 			break
 		}
 	}
@@ -233,7 +233,7 @@ func (w *IMAPWorker) handleMessage(msg types.WorkerMessage) error {
 }
 
 func (w *IMAPWorker) handleImapUpdate(update client.Update) {
-	logging.Debugf("(= %T", update)
+	logging.Tracef("(= %T", update)
 	switch update := update.(type) {
 	case *client.MailboxUpdate:
 		status := update.Mailbox
diff --git a/worker/maildir/search.go b/worker/maildir/search.go
index 729d521f..0f3f6a42 100644
--- a/worker/maildir/search.go
+++ b/worker/maildir/search.go
@@ -91,7 +91,7 @@ func getParsedFlag(name string) maildir.Flag {
 
 func (w *Worker) search(criteria *searchCriteria) ([]uint32, error) {
 	requiredParts := getRequiredParts(criteria)
-	logging.Infof("Required parts bitmask for search: %b", requiredParts)
+	logging.Debugf("Required parts bitmask for search: %b", requiredParts)
 
 	keys, err := w.c.UIDs(*w.selected)
 	if err != nil {
diff --git a/worker/maildir/worker.go b/worker/maildir/worker.go
index 2cf7897a..2a8a49bd 100644
--- a/worker/maildir/worker.go
+++ b/worker/maildir/worker.go
@@ -200,7 +200,7 @@ func (w *Worker) getDirectoryInfo(name string) *models.DirectoryInfo {
 			keyFlags[key] = flags
 		}
 	} else {
-		logging.Infof("disabled flags cache: %q: %v", dir, err)
+		logging.Tracef("disabled flags cache: %q: %v", dir, err)
 	}
 
 	uids, err := w.c.UIDs(dir)
@@ -221,7 +221,8 @@ func (w *Worker) getDirectoryInfo(name string) *models.DirectoryInfo {
 			ok := false
 			flags, ok = keyFlags[message.key]
 			if !ok {
-				logging.Debugf("message (key=%q uid=%d) not found in map cache", message.key, message.uid)
+				logging.Tracef("message (key=%q uid=%d) not found in map cache",
+					message.key, message.uid)
 				flags, err = message.Flags()
 				if err != nil {
 					logging.Errorf("could not get flags: %v", err)
@@ -320,7 +321,7 @@ func (w *Worker) handleConfigure(msg *types.Configure) error {
 		return err
 	}
 	w.c = c
-	logging.Infof("configured base maildir: %s", dir)
+	logging.Debugf("configured base maildir: %s", dir)
 	return nil
 }
 
@@ -357,7 +358,7 @@ func (w *Worker) handleListDirectories(msg *types.ListDirectories) error {
 }
 
 func (w *Worker) handleOpenDirectory(msg *types.OpenDirectory) error {
-	logging.Infof("opening %s", msg.Directory)
+	logging.Debugf("opening %s", msg.Directory)
 
 	// open the directory
 	dir, err := w.c.OpenDirectory(msg.Directory)
@@ -767,13 +768,13 @@ func (w *Worker) handleAppendMessage(msg *types.AppendMessage) error {
 	dest := w.c.Store.Dir(msg.Destination)
 	_, writer, err := dest.Create(lib.ToMaildirFlags(msg.Flags))
 	if err != nil {
-		logging.Errorf("could not create message at %s: %v", msg.Destination, err)
-		return err
+		return fmt.Errorf("could not create message at %s: %w",
+			msg.Destination, err)
 	}
 	defer writer.Close()
 	if _, err := io.Copy(writer, msg.Reader); err != nil {
-		logging.Errorf("could not write message to destination: %v", err)
-		return err
+		return fmt.Errorf(
+			"could not write message to destination: %w", err)
 	}
 	w.worker.PostMessage(&types.Done{
 		Message: types.RespondTo(msg),
@@ -785,12 +786,12 @@ func (w *Worker) handleAppendMessage(msg *types.AppendMessage) error {
 }
 
 func (w *Worker) handleSearchDirectory(msg *types.SearchDirectory) error {
-	logging.Infof("Searching directory %v with args: %v", *w.selected, msg.Argv)
+	logging.Debugf("Searching directory %v with args: %v", *w.selected, msg.Argv)
 	criteria, err := parseSearch(msg.Argv)
 	if err != nil {
 		return err
 	}
-	logging.Infof("Searching with parsed criteria: %#v", criteria)
+	logging.Tracef("Searching with parsed criteria: %#v", criteria)
 	uids, err := w.search(criteria)
 	if err != nil {
 		return err
diff --git a/worker/mbox/worker.go b/worker/mbox/worker.go
index a786a65e..19a4497f 100644
--- a/worker/mbox/worker.go
+++ b/worker/mbox/worker.go
@@ -69,7 +69,7 @@ func (w *mboxWorker) handleMessage(msg types.WorkerMessage) error {
 			reterr = err
 			break
 		} else {
-			logging.Infof("configured with mbox file %s", dir)
+			logging.Debugf("configured with mbox file %s", dir)
 		}
 
 	case *types.Connect, *types.Reconnect, *types.Disconnect:
@@ -106,7 +106,7 @@ func (w *mboxWorker) handleMessage(msg types.WorkerMessage) error {
 			Info: w.data.DirectoryInfo(msg.Directory),
 		}, nil)
 		w.worker.PostMessage(&types.Done{Message: types.RespondTo(msg)}, nil)
-		logging.Infof("%s opened", msg.Directory)
+		logging.Debugf("%s opened", msg.Directory)
 
 	case *types.FetchDirectoryContents:
 		uids, err := filterUids(w.folder, w.folder.Uids(), msg.FilterCriteria)
@@ -377,7 +377,7 @@ func filterUids(folder *container, uids []uint32, args []string) ([]uint32, erro
 	if err != nil {
 		return nil, err
 	}
-	logging.Infof("Search with parsed criteria: %#v", criteria)
+	logging.Debugf("Search with parsed criteria: %#v", criteria)
 	m := make([]lib.RawMessage, 0, len(uids))
 	for _, uid := range uids {
 		msg, err := folder.Message(uid)
diff --git a/worker/notmuch/worker.go b/worker/notmuch/worker.go
index 0acd4e78..5f5e403c 100644
--- a/worker/notmuch/worker.go
+++ b/worker/notmuch/worker.go
@@ -275,7 +275,7 @@ func (w *worker) getDirectoryInfo(name string, query string) *models.DirectoryIn
 }
 
 func (w *worker) handleOpenDirectory(msg *types.OpenDirectory) error {
-	logging.Infof("opening %s", msg.Directory)
+	logging.Tracef("opening %s", msg.Directory)
 
 	var isDynamicFolder bool
 	q := ""
diff --git a/worker/types/worker.go b/worker/types/worker.go
index d21a46a5..67cb9874 100644
--- a/worker/types/worker.go
+++ b/worker/types/worker.go
@@ -84,9 +84,9 @@ func (worker *Worker) PostAction(msg WorkerMessage, cb func(msg WorkerMessage))
 	worker.setId(msg)
 
 	if resp := msg.InResponseTo(); resp != nil {
-		logging.Debugf("PostAction %T:%T", msg, resp)
+		logging.Tracef("PostAction %T:%T", msg, resp)
 	} else {
-		logging.Debugf("PostAction %T", msg)
+		logging.Tracef("PostAction %T", msg)
 	}
 	// write to Actions channel without blocking
 	worker.queue(msg)
@@ -107,9 +107,9 @@ func (worker *Worker) PostMessage(msg WorkerMessage,
 	msg.setAccount(worker.Name)
 
 	if resp := msg.InResponseTo(); resp != nil {
-		logging.Debugf("PostMessage %T:%T", msg, resp)
+		logging.Tracef("PostMessage %T:%T", msg, resp)
 	} else {
-		logging.Debugf("PostMessage %T", msg)
+		logging.Tracef("PostMessage %T", msg)
 	}
 	ui.MsgChannel <- msg
 
@@ -122,9 +122,9 @@ func (worker *Worker) PostMessage(msg WorkerMessage,
 
 func (worker *Worker) ProcessMessage(msg WorkerMessage) WorkerMessage {
 	if resp := msg.InResponseTo(); resp != nil {
-		logging.Debugf("ProcessMessage %T(%d):%T(%d)", msg, msg.getId(), resp, resp.getId())
+		logging.Tracef("ProcessMessage %T(%d):%T(%d)", msg, msg.getId(), resp, resp.getId())
 	} else {
-		logging.Debugf("ProcessMessage %T(%d)", msg, msg.getId())
+		logging.Tracef("ProcessMessage %T(%d)", msg, msg.getId())
 	}
 	if inResponseTo := msg.InResponseTo(); inResponseTo != nil {
 		worker.Lock()
@@ -144,9 +144,9 @@ func (worker *Worker) ProcessMessage(msg WorkerMessage) WorkerMessage {
 
 func (worker *Worker) ProcessAction(msg WorkerMessage) WorkerMessage {
 	if resp := msg.InResponseTo(); resp != nil {
-		logging.Debugf("ProcessAction %T(%d):%T(%d)", msg, msg.getId(), resp, resp.getId())
+		logging.Tracef("ProcessAction %T(%d):%T(%d)", msg, msg.getId(), resp, resp.getId())
 	} else {
-		logging.Debugf("ProcessAction %T(%d)", msg, msg.getId())
+		logging.Tracef("ProcessAction %T(%d)", msg, msg.getId())
 	}
 	if inResponseTo := msg.InResponseTo(); inResponseTo != nil {
 		worker.Lock()