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>

37 files changed, 110 insertions, 90 deletions

diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
index 4b93682f..03c606ac 100644
--- a/CONTRIBUTING.md
+++ b/CONTRIBUTING.md
@@ -240,6 +240,23 @@ by running `make fmt`.
 
 If gofumpt accepts your code it's most likely properly formatted.
 
+### Logging
+
+Aerc allows logging messages to a file. Either by redirecting the output to
+a file (e.g. `aerc > log`), or by configuring `log-file` in ``aerc.conf`.
+Logging messages are associated with a severity level, from lowest to highest:
+`trace`, `debug`, `info`, `warn`, `error`.
+
+Messages can be sent to the log file by using the following functions:
+
+- `logging.Errorf()`: Use to report serious (but non-fatal) errors.
+- `logging.Warnf()`: Use to report issues that do not affect normal use.
+- `logging.Infof()`: Use to display important messages that may concern
+  non-developers.
+- `logging.Debugf()`: Use to display non-important messages, or debuging
+  details.
+- `logging.Tracef()`: Use to display only low level debugging traces.
+
 ### Man pages
 
 All `doc/*.scd` files are written in the [scdoc][scdoc] format and compiled to
diff --git a/aerc.go b/aerc.go
index 09ddc43f..b7469768 100644
--- a/aerc.go
+++ b/aerc.go
@@ -113,7 +113,7 @@ func usage(msg string) {
 }
 
 func setWindowTitle() {
-	logging.Debugf("Parsing terminfo")
+	logging.Tracef("Parsing terminfo")
 	ti, err := terminfo.LoadFromEnv()
 	if err != nil {
 		logging.Warnf("Cannot get terminfo: %v", err)
@@ -125,7 +125,7 @@ func setWindowTitle() {
 		return
 	}
 
-	logging.Infof("Setting terminal title")
+	logging.Debugf("Setting terminal title")
 	buf := new(bytes.Buffer)
 	ti.Fprintf(buf, terminfo.ToStatusLine)
 	fmt.Fprint(buf, "aerc")
diff --git a/commands/account/export-mbox.go b/commands/account/export-mbox.go
index b68e1cc5..f51608b9 100644
--- a/commands/account/export-mbox.go
+++ b/commands/account/export-mbox.go
@@ -117,7 +117,7 @@ func (ExportMbox) Execute(aerc *widgets.Aerc, args []string) error {
 		}
 		statusInfo := fmt.Sprintf("Exported %d of %d messages to %s.", ctr, len(store.Uids()), filename)
 		aerc.PushStatus(statusInfo, 10*time.Second)
-		logging.Infof(statusInfo)
+		logging.Debugf(statusInfo)
 	}()
 
 	return nil
diff --git a/commands/account/import-mbox.go b/commands/account/import-mbox.go
index 5a8a2ee6..93408aca 100644
--- a/commands/account/import-mbox.go
+++ b/commands/account/import-mbox.go
@@ -55,7 +55,7 @@ func (ImportMbox) Execute(aerc *widgets.Aerc, args []string) error {
 	importFolder := func() {
 		statusInfo := fmt.Sprintln("Importing", filename, "to folder", folder)
 		aerc.PushStatus(statusInfo, 10*time.Second)
-		logging.Infof(statusInfo)
+		logging.Debugf(statusInfo)
 		f, err := os.Open(filename)
 		if err != nil {
 			aerc.PushError(err.Error())
@@ -123,7 +123,7 @@ func (ImportMbox) Execute(aerc *widgets.Aerc, args []string) error {
 			}
 		}
 		infoStr := fmt.Sprintf("%s: imported %d of %d sucessfully.", args[0], appended, len(messages))
-		logging.Infof(infoStr)
+		logging.Debugf(infoStr)
 		aerc.SetStatus(infoStr)
 	}
 
diff --git a/commands/account/search.go b/commands/account/search.go
index b4942bf5..125cb5d7 100644
--- a/commands/account/search.go
+++ b/commands/account/search.go
@@ -44,7 +44,7 @@ func (SearchFilter) Execute(aerc *widgets.Aerc, args []string) error {
 		cb := func(msg types.WorkerMessage) {
 			if _, ok := msg.(*types.Done); ok {
 				acct.SetStatus(statusline.FilterResult(strings.Join(args, " ")))
-				logging.Infof("Filter results: %v", store.Uids())
+				logging.Tracef("Filter results: %v", store.Uids())
 			}
 		}
 		store.Sort(store.GetCurrentSortCriteria(), cb)
@@ -52,7 +52,7 @@ func (SearchFilter) Execute(aerc *widgets.Aerc, args []string) error {
 		acct.SetStatus(statusline.Search("Searching..."))
 		cb := func(uids []uint32) {
 			acct.SetStatus(statusline.Search(strings.Join(args, " ")))
-			logging.Infof("Search results: %v", uids)
+			logging.Tracef("Search results: %v", uids)
 			store.ApplySearch(uids)
 			// TODO: Remove when stores have multiple OnUpdate handlers
 			ui.Invalidate()
diff --git a/commands/compose/attach.go b/commands/compose/attach.go
index af5c023c..de83ef0b 100644
--- a/commands/compose/attach.go
+++ b/commands/compose/attach.go
@@ -52,16 +52,12 @@ func (a Attach) addPath(aerc *widgets.Aerc, path string) error {
 		return err
 	}
 
-	logging.Debugf("attaching %s", path)
-
 	attachments, err := filepath.Glob(path)
 	if err != nil && errors.Is(err, filepath.ErrBadPattern) {
 		logging.Warnf("failed to parse as globbing pattern: %v", err)
 		attachments = []string{path}
 	}
 
-	logging.Debugf("filenames: %v", attachments)
-
 	composer, _ := aerc.SelectedTabContent().(*widgets.Composer)
 	for _, attach := range attachments {
 		logging.Debugf("attaching '%s'", attach)
@@ -134,6 +130,7 @@ func (a Attach) openMenu(aerc *widgets.Aerc, args []string) error {
 		_, err = picks.Seek(0, io.SeekStart)
 		if err != nil {
 			logging.Errorf("seek failed: %v", err)
+			return
 		}
 
 		scanner := bufio.NewScanner(picks)
@@ -142,11 +139,11 @@ func (a Attach) openMenu(aerc *widgets.Aerc, args []string) error {
 			if _, err := os.Stat(f); err != nil {
 				continue
 			}
-			logging.Infof("File picker attaches: %v", f)
+			logging.Tracef("File picker attaches: %v", f)
 			err := a.addPath(aerc, f)
 			if err != nil {
-				logging.Errorf("attach failed "+
-					"for file %s: %v", f, err)
+				logging.Errorf(
+					"attach failed for file %s: %v", f, err)
 			}
 
 		}
diff --git a/commands/compose/postpone.go b/commands/compose/postpone.go
index 7469b235..2572d8d5 100644
--- a/commands/compose/postpone.go
+++ b/commands/compose/postpone.go
@@ -47,7 +47,7 @@ func (Postpone) Execute(aerc *widgets.Aerc, args []string) error {
 		return errors.New("No Postpone location configured")
 	}
 
-	logging.Infof("Postponing mail")
+	logging.Tracef("Postponing mail")
 
 	header, err := composer.PrepareHeader()
 	if err != nil {
diff --git a/commands/msg/forward.go b/commands/msg/forward.go
index ccfaa086..74ee6575 100644
--- a/commands/msg/forward.go
+++ b/commands/msg/forward.go
@@ -74,7 +74,7 @@ func (forward) Execute(aerc *widgets.Aerc, args []string) error {
 	if err != nil {
 		return err
 	}
-	logging.Infof("Forwarding email %s", msg.Envelope.MessageId)
+	logging.Debugf("Forwarding email <%s>", msg.Envelope.MessageId)
 
 	h := &mail.Header{}
 	subject := "Fwd: " + msg.Envelope.Subject
diff --git a/commands/msg/recall.go b/commands/msg/recall.go
index b5c92f21..eb8195f8 100644
--- a/commands/msg/recall.go
+++ b/commands/msg/recall.go
@@ -70,7 +70,7 @@ func (Recall) Execute(aerc *widgets.Aerc, args []string) error {
 	if err != nil {
 		return errors.Wrap(err, "Recall failed")
 	}
-	logging.Infof("Recalling message %s", msgInfo.Envelope.MessageId)
+	logging.Debugf("Recalling message <%s>", msgInfo.Envelope.MessageId)
 
 	composer, err := widgets.NewComposer(aerc, acct, aerc.Config(),
 		acct.AccountConfig(), acct.Worker(), "", msgInfo.RFC822Headers,
@@ -200,7 +200,7 @@ func (Recall) Execute(aerc *widgets.Aerc, args []string) error {
 					}
 					bs, err := msg.BodyStructure().PartAtIndex(p)
 					if err != nil {
-						logging.Infof("cannot get PartAtIndex %v: %v", p, err)
+						logging.Warnf("cannot get PartAtIndex %v: %v", p, err)
 						continue
 					}
 					msg.FetchBodyPart(p, func(reader io.Reader) {
diff --git a/commands/msg/unsubscribe.go b/commands/msg/unsubscribe.go
index 022135eb..72c839fe 100644
--- a/commands/msg/unsubscribe.go
+++ b/commands/msg/unsubscribe.go
@@ -56,10 +56,10 @@ func (Unsubscribe) Execute(aerc *widgets.Aerc, args []string) error {
 	if len(methods) == 0 {
 		return fmt.Errorf("no methods found to unsubscribe")
 	}
-	logging.Infof("unsubscribe: found %d methods", len(methods))
+	logging.Debugf("unsubscribe: found %d methods", len(methods))
 
 	unsubscribe := func(method *url.URL) {
-		logging.Infof("unsubscribe: trying to unsubscribe using %s", method.Scheme)
+		logging.Debugf("unsubscribe: trying to unsubscribe using %s", method.Scheme)
 		var err error
 		switch strings.ToLower(method.Scheme) {
 		case "mailto":
diff --git a/config/accounts.go b/config/accounts.go
index e168231f..b33bdf09 100644
--- a/config/accounts.go
+++ b/config/accounts.go
@@ -112,7 +112,7 @@ func (config *AercConfig) parseAccounts(root string, accts []string) error {
 		}
 	}
 
-	logging.Infof("Parsing accounts configuration from %s", filename)
+	logging.Debugf("Parsing accounts configuration from %s", filename)
 
 	file, err := ini.Load(filename)
 	if err != nil {
diff --git a/config/binds.go b/config/binds.go
index 4b32e6da..281aebf6 100644
--- a/config/binds.go
+++ b/config/binds.go
@@ -77,7 +77,7 @@ func (config *AercConfig) parseBinds(root string) error {
 			return err
 		}
 	}
-	logging.Infof("Parsing key bindings configuration from %s", filename)
+	logging.Debugf("Parsing key bindings configuration from %s", filename)
 	binds, err := ini.Load(filename)
 	if err != nil {
 		return err
diff --git a/lib/attachment.go b/lib/attachment.go
index bc29a567..e926dfa9 100644
--- a/lib/attachment.go
+++ b/lib/attachment.go
@@ -153,7 +153,7 @@ func SetUtf8Charset(origParams map[string]string) map[string]string {
 	for k, v := range origParams {
 		switch strings.ToLower(k) {
 		case "charset":
-			logging.Infof("substitute charset %s with utf-8", v)
+			logging.Debugf("substitute charset %s with utf-8", v)
 			params[k] = "utf-8"
 		default:
 			params[k] = v
diff --git a/lib/crypto/gpg/gpgbin/gpgbin.go b/lib/crypto/gpg/gpgbin/gpgbin.go
index 1e8c7dcd..d83c45fb 100644
--- a/lib/crypto/gpg/gpgbin/gpgbin.go
+++ b/lib/crypto/gpg/gpgbin/gpgbin.go
@@ -129,7 +129,7 @@ func parse(r io.Reader, md *models.MessageDetails) error {
 		}
 		if strings.HasPrefix(line, "[GNUPG:]") {
 			msgCollecting = false
-			logging.Debugf(line)
+			logging.Tracef(line)
 		}
 		if msgCollecting {
 			msgContent = append(msgContent, scanner.Bytes()...)
diff --git a/lib/crypto/pgp/pgp.go b/lib/crypto/pgp/pgp.go
index f5612eea..fd9d13eb 100644
--- a/lib/crypto/pgp/pgp.go
+++ b/lib/crypto/pgp/pgp.go
@@ -29,7 +29,7 @@ var (
 )
 
 func (m *Mail) Init() error {
-	logging.Infof("Initializing PGP keyring")
+	logging.Debugf("Initializing PGP keyring")
 	err := os.MkdirAll(path.Join(xdg.DataHome(), "aerc"), 0o700)
 	if err != nil {
 		return fmt.Errorf("failed to create data directory: %w", err)
diff --git a/lib/msgstore.go b/lib/msgstore.go
index dfa25191..4205ea10 100644
--- a/lib/msgstore.go
+++ b/lib/msgstore.go
@@ -420,7 +420,7 @@ func (store *MessageStore) runThreadBuilder() {
 	}
 	if store.threadBuilderDebounce != nil {
 		if store.threadBuilderDebounce.Stop() {
-			logging.Infof("thread builder debounced")
+			logging.Tracef("thread builder debounced")
 		}
 	}
 	store.threadBuilderDebounce = time.AfterFunc(store.threadBuilderDelay, func() {
diff --git a/lib/open.go b/lib/open.go
index e091d913..9faa6d10 100644
--- a/lib/open.go
+++ b/lib/open.go
@@ -46,7 +46,7 @@ func XDGOpenMime(
 		args = append(args, uri)
 	}
 
-	logging.Infof("running command: %v", args)
+	logging.Tracef("running command: %v", args)
 	cmd := exec.Command(args[0], args[1:]...)
 	out, err := cmd.CombinedOutput()
 	logging.Debugf("command: %v exited. err=%v out=%s", args, err, out)
diff --git a/lib/socket.go b/lib/socket.go
index 4da3485b..1cfd0583 100644
--- a/lib/socket.go
+++ b/lib/socket.go
@@ -28,7 +28,7 @@ func StartServer() (*AercServer, error) {
 	if err := ConnectAndExec(""); err != nil {
 		os.Remove(sockpath)
 	}
-	logging.Infof("Starting Unix server: %s", sockpath)
+	logging.Debugf("Starting Unix server: %s", sockpath)
 	l, err := net.Listen("unix", sockpath)
 	if err != nil {
 		return nil, err
@@ -41,9 +41,13 @@ func StartServer() (*AercServer, error) {
 		for {
 			conn, err := l.Accept()
 			if err != nil {
-				// TODO: Something more useful, in some cases, on wednesdays,
-				// after 2 PM, I guess?
-				logging.Errorf("Closing Unix server: %v", err)
+				if !strings.Contains(err.Error(),
+					"use of closed network connection") {
+					// TODO: Something more useful, in some
+					// cases, on wednesdays, after 2 PM,
+					// I guess?
+					logging.Errorf("Closing Unix server: %v", err)
+				}
 				return
 			}
 			go func() {
@@ -76,7 +80,7 @@ func (as *AercServer) handleClient(conn net.Conn) {
 			logging.Errorf("failed to update deadline: %v", err)
 		}
 		msg := scanner.Text()
-		logging.Debugf("unix:%d got message %s", clientId, msg)
+		logging.Tracef("unix:%d got message %s", clientId, msg)
 		if !strings.ContainsRune(msg, ':') {
 			_, innererr := conn.Write([]byte("error: invalid command\n"))
 			if innererr != nil {
@@ -119,7 +123,7 @@ func (as *AercServer) handleClient(conn net.Conn) {
 			}
 		}
 	}
-	logging.Debugf("unix:%d closed connection", clientId)
+	logging.Tracef("unix:%d closed connection", clientId)
 }
 
 func ConnectAndExec(msg string) error {
diff --git a/lib/threadbuilder.go b/lib/threadbuilder.go
index 600f6539..34f143a4 100644
--- a/lib/threadbuilder.go
+++ b/lib/threadbuilder.go
@@ -67,7 +67,7 @@ func (builder *ThreadBuilder) Threads(uids []uint32, inverse bool, sort bool,
 	builder.RebuildUids(threads, inverse)
 
 	elapsed := time.Since(start)
-	logging.Infof("%d threads from %d uids created in %s", len(threads),
+	logging.Tracef("%d threads from %d uids created in %s", len(threads),
 		len(uids), elapsed)
 
 	return threads
diff --git a/widgets/account.go b/widgets/account.go
index 5bbe97e1..ca899c93 100644
--- a/widgets/account.go
+++ b/widgets/account.go
@@ -235,7 +235,7 @@ func (acct *AccountView) onMessage(msg types.WorkerMessage) {
 		switch msg.InResponseTo().(type) {
 		case *types.Connect, *types.Reconnect:
 			acct.SetStatus(statusline.ConnectionActivity("Listing mailboxes..."))
-			logging.Debugf("Listing mailboxes...")
+			logging.Tracef("Listing mailboxes...")
 			acct.dirlist.UpdateList(func(dirs []string) {
 				var dir string
 				for _, _dir := range dirs {
@@ -251,14 +251,14 @@ func (acct *AccountView) onMessage(msg types.WorkerMessage) {
 					acct.dirlist.Select(dir)
 				}
 				acct.msglist.SetInitDone()
-				logging.Infof("%s connected.", acct.acct.Name)
+				logging.Infof("[%s] connected.", acct.acct.Name)
 				acct.SetStatus(statusline.SetConnected(true))
 				acct.newConn = true
 			})
 		case *types.Disconnect:
 			acct.dirlist.ClearList()
 			acct.msglist.SetStore(nil)
-			logging.Infof("%s disconnected.", acct.acct.Name)
+			logging.Infof("[%s] disconnected.", acct.acct.Name)
 			acct.SetStatus(statusline.SetConnected(false))
 		case *types.OpenDirectory:
 			if store, ok := acct.dirlist.SelectedMsgStore(); ok {
@@ -347,13 +347,13 @@ func (acct *AccountView) onMessage(msg types.WorkerMessage) {
 	case *types.LabelList:
 		acct.labels = msg.Labels
 	case *types.ConnError:
-		logging.Errorf("%s connection error: %v", acct.acct.Name, msg.Error)
+		logging.Errorf("[%s] connection error: %v", acct.acct.Name, msg.Error)
 		acct.SetStatus(statusline.SetConnected(false))
 		acct.PushError(msg.Error)
 		acct.msglist.SetStore(nil)
 		acct.worker.PostAction(&types.Reconnect{}, nil)
 	case *types.Error:
-		logging.Errorf("%s unexpected error: %v", acct.acct.Name, msg.Error)
+		logging.Errorf("[%s] unexpected error: %v", acct.acct.Name, msg.Error)
 		acct.PushError(msg.Error)
 	}
 	acct.UpdateStatus()
@@ -427,7 +427,7 @@ func (acct *AccountView) CheckMail() {
 	dirs := acct.dirlist.List()
 	dirs = acct.dirlist.FilterDirs(dirs, acct.AccountConfig().CheckMailInclude, false)
 	dirs = acct.dirlist.FilterDirs(dirs, exclude, true)
-	logging.Infof("Checking for new mail on account %s", acct.Name())
+	logging.Debugf("Checking for new mail on account %s", acct.Name())
 	acct.SetStatus(statusline.ConnectionActivity("Checking for new mail..."))
 	msg := &types.CheckMail{
 		Directories: dirs,
diff --git a/widgets/aerc.go b/widgets/aerc.go
index 163ba9e0..dce28c3e 100644
--- a/widgets/aerc.go
+++ b/widgets/aerc.go
@@ -750,7 +750,7 @@ func (aerc *Aerc) Mbox(source string) error {
 		acctConf = *selectedAcct.acct
 		info := fmt.Sprintf("Loading outgoing mbox mail settings from account [%s]", selectedAcct.Name())
 		aerc.PushStatus(info, 10*time.Second)
-		logging.Infof(info)
+		logging.Debugf(info)
 	} else {
 		acctConf.From = "<user@localhost>"
 	}
diff --git a/widgets/compose.go b/widgets/compose.go
index ca7c8b8f..1bbdb477 100644
--- a/widgets/compose.go
+++ b/widgets/compose.go
@@ -109,7 +109,7 @@ func NewComposer(aerc *Aerc, acct *AccountView, conf *config.AercConfig,
 
 func (c *Composer) SwitchAccount(newAcct *AccountView) error {
 	if c.acct == newAcct {
-		logging.Infof("same accounts: no switch")
+		logging.Tracef("same accounts: no switch")
 		return nil
 	}
 	// sync the header with the editors
@@ -127,7 +127,7 @@ func (c *Composer) SwitchAccount(newAcct *AccountView) error {
 		editor.loadValue()
 	}
 	c.Invalidate()
-	logging.Infof("account sucessfully switched")
+	logging.Debugf("account sucessfully switched")
 	return nil
 }
 
diff --git a/widgets/dirlist.go b/widgets/dirlist.go
index 0f8431e9..4663d487 100644
--- a/widgets/dirlist.go
+++ b/widgets/dirlist.go
@@ -187,7 +187,7 @@ func (dirlist *DirectoryList) Select(name string) {
 				})
 			dirlist.Invalidate()
 		case <-ctx.Done():
-			logging.Debugf("dirlist: skip %s", name)
+			logging.Tracef("dirlist: skip %s", name)
 			return
 		}
 	}(ctx)
diff --git a/widgets/msgviewer.go b/widgets/msgviewer.go
index 1cc2d6f5..019f9d6e 100644
--- a/widgets/msgviewer.go
+++ b/widgets/msgviewer.go
@@ -240,7 +240,7 @@ func createSwitcher(acct *AccountView, switcher *PartSwitcher,
 			return err
 		}
 		selectedPriority := -1
-		logging.Infof("Selecting best message from %v", conf.Viewer.Alternatives)
+		logging.Tracef("Selecting best message from %v", conf.Viewer.Alternatives)
 		for i, pv := range switcher.parts {
 			// Switch to user's preferred mimetype
 			if switcher.selected == -1 && pv.part.MIMEType != "multipart" {
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()