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>

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

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")

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

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)
 	}
 

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()

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)
 			}
 
 		}

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 {

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

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) {

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":

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 {

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

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

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()...)

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)

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() {

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)

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 {

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

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,

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>"
 	}

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
 }
 

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)

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" {

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)
 }

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{

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,
 	}

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)
 }

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)

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)
 }

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

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

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 {

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

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)

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 := ""

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()