Switch to a proper logging library

Structured logs can be enabled with `-log.json`.

auth/imap.go

@@ -1,13 +1,12 @@
 package auth
 
 import (
-	"log"
 	"net/http"
 
+	"github.com/rs/zerolog/log"
+
 	"github.com/emersion/go-imap/client"
 	"github.com/emersion/go-sasl"
-
-	"git.sr.ht/~sircmpwn/tokidoki/debug"
 )
 
 type IMAPProvider struct {
@@ -20,7 +19,7 @@ func NewIMAP(addr string, tls bool) AuthProvider {
 	prov := &IMAPProvider{addr, tls}
 	conn, err := prov.dial()
 	if err != nil {
-		log.Fatalf("Error dialing configured IMAP auth server: %s", err.Error())
+		log.Fatal().Err(err).Msg("error dialing configured IMAP auth server")
 	}
 	conn.Close()
 	return prov
@@ -45,7 +44,7 @@ func (prov *IMAPProvider) doAuth(next http.Handler,
 
 	conn, err := prov.dial()
 	if err != nil {
-		debug.Printf("Auth dial error: %v", err)
+		log.Debug().Err(err).Msg("auth dial error")
 		http.Error(w, "Temporary authentication error, try again later", http.StatusServiceUnavailable)
 		return
 	}
@@ -53,7 +52,7 @@ func (prov *IMAPProvider) doAuth(next http.Handler,
 
 	auth := sasl.NewPlainClient("", user, pass)
 	if err := conn.Authenticate(auth); err != nil {
-		debug.Printf("Auth error: %v", err)
+		log.Debug().Err(err).Msg("auth error")
 		http.Error(w, "Invalid username or password", http.StatusUnauthorized)
 		return
 	}

auth/pam.go

@@ -7,8 +7,7 @@ import (
 	"net/http"
 
 	"github.com/msteinert/pam"
-
+	"github.com/rs/zerolog/log"
-	"git.sr.ht/~sircmpwn/tokidoki/debug"
 )
 
 type pamProvider struct{}
@@ -34,7 +33,7 @@ func pamAuth(next http.Handler, w http.ResponseWriter, r *http.Request) {
 	}
 
 	t, err := pam.StartFunc("login", user, func(s pam.Style, msg string) (string, error) {
-		debug.Printf("%v %v", s, msg)
+		log.Debug().Str("style", fmt.Sprintf("%v", s)).Msg(msg)
 		switch s {
 		case pam.PromptEchoOff:
 			return pass, nil
@@ -45,26 +44,26 @@ func pamAuth(next http.Handler, w http.ResponseWriter, r *http.Request) {
 		}
 	})
 	if err != nil {
-		debug.Printf("Failed to start PAM conversation: %v", err)
+		log.Debug().Err(err).Msg("failed to start PAM conversation")
 		http.Error(w, "Temporary authentication error, try again later", http.StatusServiceUnavailable)
 		return
 	}
 
 	if err := t.Authenticate(0); err != nil {
-		debug.Printf("Auth error: %v", err)
+		log.Debug().Err(err).Msg("auth error")
 		http.Error(w, "Invalid username or password", http.StatusUnauthorized)
 		return
 	}
 
 	if err := t.AcctMgmt(0); err != nil {
-		debug.Printf("Account unavailable: %v", err)
+		log.Debug().Err(err).Msg("account unavailable")
 		http.Error(w, "Account unavailable", http.StatusUnauthorized)
 		return
 	}
 
 	user, err = t.GetItem(pam.User)
 	if err != nil {
-		debug.Printf("Failed to get PAM username: %v", err)
+		log.Debug().Err(err).Msg("failed to get PAM username")
 		http.Error(w, "Temporary authentication error, try again later", http.StatusServiceUnavailable)
 		return
 	}

cmd/tokidoki/main.go

@@ -5,7 +5,6 @@ import (
 	"encoding/base64"
 	"flag"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 
@@ -14,9 +13,10 @@ import (
 	"github.com/emersion/go-webdav/carddav"
 	"github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 
 	"git.sr.ht/~sircmpwn/tokidoki/auth"
-	"git.sr.ht/~sircmpwn/tokidoki/debug"
 	"git.sr.ht/~sircmpwn/tokidoki/storage"
 )
 
@@ -85,12 +85,15 @@ func main() {
 	var (
 		addr       string
 		authURL    string
+		debug      bool
+		jsonLog    bool
 		storageURL string
 	)
 	flag.StringVar(&addr, "addr", ":8080", "listening address")
 	flag.StringVar(&authURL, "auth.url", "", "auth backend URL (required)")
 	flag.StringVar(&storageURL, "storage.url", "", "storage backend URL (required)")
-	flag.BoolVar(&debug.Enable, "debug", false, "enable debug output")
+	flag.BoolVar(&debug, "log.debug", false, "enable debug logs")
+	flag.BoolVar(&jsonLog, "log.json", false, "enable structured logs")
 	flag.Parse()
 
 	if len(flag.Args()) != 0 || authURL == "" || storageURL == "" {
@@ -98,6 +101,15 @@ func main() {
 		os.Exit(1)
 	}
 
+	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
+	zerolog.SetGlobalLevel(zerolog.InfoLevel)
+	if debug {
+		zerolog.SetGlobalLevel(zerolog.DebugLevel)
+	}
+	if !jsonLog {
+		log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
+	}
+
 	for _, method := range []string{
 		"PROPFIND",
 		"PROPPATCH",
@@ -113,7 +125,7 @@ func main() {
 
 	authProvider, err := auth.NewFromURL(authURL)
 	if err != nil {
-		log.Fatalf("failed to load auth provider: %s", err.Error())
+		log.Fatal().Err(err).Msg("failed to load auth provider")
 	}
 	mux.Use(authProvider.Middleware())
 
@@ -121,7 +133,7 @@ func main() {
 
 	caldavBackend, carddavBackend, err := storage.NewFromURL(storageURL, "/calendar/", "/contacts/", upBackend)
 	if err != nil {
-		log.Fatalf("failed to load storage backend: %s", err.Error())
+		log.Fatal().Err(err).Msg("failed to load storage backend")
 	}
 
 	carddavHandler := carddav.Handler{Backend: carddavBackend}
@@ -144,11 +156,11 @@ func main() {
 		Handler: mux,
 	}
 
-	log.Printf("Server running on %s", addr)
+	log.Info().Str("address", addr).Msg("starting server")
-	debug.Printf("Debug output enabled")
+	log.Debug().Msg("debug output enabled")
 
 	err = server.ListenAndServe()
 	if err != http.ErrServerClosed {
-		log.Fatalf("ListenAndServe: %s", err.Error())
+		log.Fatal().Err(err).Msg("ListenAndServe() error")
 	}
 }

debug/debug.go

@@ -1,15 +0,0 @@
-package debug
-
-import (
-	"log"
-)
-
-var (
-	Enable = false
-)
-
-func Printf(format string, v ...any) {
-	if Enable {
-		log.Printf("[debug] "+format, v...)
-	}
-}

go.mod

@@ -10,9 +10,13 @@ require (
 	github.com/emersion/go-webdav v0.3.2-0.20221122105813-ac9af45270fb
 	github.com/go-chi/chi/v5 v5.0.7
 	github.com/msteinert/pam v1.0.0
+	github.com/rs/zerolog v1.28.0
 )
 
 require (
+	github.com/mattn/go-colorable v0.1.12 // indirect
+	github.com/mattn/go-isatty v0.0.14 // indirect
 	github.com/teambition/rrule-go v1.7.2 // indirect
+	golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 // indirect
 	golang.org/x/text v0.3.7 // indirect
 )

go.sum

@@ -1,3 +1,4 @@
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/emersion/go-ical v0.0.0-20220601085725-0864dccc089f h1:feGUUxxvOtWVOhTko8Cbmp33a+tU0IMZxMEmnkoAISQ=
 github.com/emersion/go-ical v0.0.0-20220601085725-0864dccc089f/go.mod h1:2MKFUgfNMULRxqZkadG1Vh44we3y5gJAtTBlVsx1BKQ=
 github.com/emersion/go-imap v1.2.0 h1:lyUQ3+EVM21/qbWE/4Ya5UG9r5+usDxlg4yfp3TgHFA=
@@ -14,11 +15,22 @@ github.com/emersion/go-webdav v0.3.2-0.20221122105813-ac9af45270fb h1:hf7lieMeu2
 github.com/emersion/go-webdav v0.3.2-0.20221122105813-ac9af45270fb/go.mod h1:lkPYZO/vsDNV9GPyVMBBsAUZzzxINL97bEVFykApo58=
 github.com/go-chi/chi/v5 v5.0.7 h1:rDTPXLDHGATaeHvVlLcR4Qe0zftYethFucbjVQ1PxU8=
 github.com/go-chi/chi/v5 v5.0.7/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/msteinert/pam v1.0.0 h1:4XoXKtMCH3+e6GIkW41uxm6B37eYqci/DH3gzSq7ocg=
 github.com/msteinert/pam v1.0.0/go.mod h1:M4FPeAW8g2ITO68W8gACDz13NDJyOQM9IQsQhrR6TOI=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.28.0 h1:MirSo27VyNi7RJYP3078AA1+Cyzd2GB66qy3aUHvsWY=
+github.com/rs/zerolog v1.28.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0=
 github.com/teambition/rrule-go v1.7.2 h1:goEajFWYydfCgavn2m/3w5U+1b3PGqPUHx/fFSVfTy0=
 github.com/teambition/rrule-go v1.7.2/go.mod h1:mBJ1Ht5uboJ6jexKdNUJg2NcwP8uUMNvStWXlJD3MvU=
-golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1 h1:SrN+KX8Art/Sf4HNj6Zcz06G7VEz+7w9tdXTPOZ7+l4=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 h1:foEbQz/B0Oz6YIqu/69kfXPYeFQAuuMYFkjaqXzl5Wo=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20210927222741-03fcf44c2211 h1:JGgROgKl9N8DuW20oFS5gxc+lE67/N3FcwmBPMe7ArY=
 golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/text v0.3.7 h1:olpwvP2KacW1ZWvsR7uQhoyTYvKAupfQrRGBFM352Gk=

storage/filesystem.go

@@ -11,11 +11,11 @@ import (
 	"regexp"
 	"strings"
 
+	"github.com/rs/zerolog/log"
+
 	"github.com/emersion/go-webdav"
 	"github.com/emersion/go-webdav/caldav"
 	"github.com/emersion/go-webdav/carddav"
-
-	"git.sr.ht/~sircmpwn/tokidoki/debug"
 )
 
 type filesystemBackend struct {
@@ -83,7 +83,7 @@ func (b *filesystemBackend) safeLocalPath(homeSetPath string, urlPath string) (s
 	}
 	// only accept simple file names for now
 	if !validFilenameRegex.MatchString(file) {
-		debug.Printf("%s does not match regex!\n", file)
+		log.Debug().Str("file", file).Msg("file name does not match regex")
 		err := fmt.Errorf("invalid file name: %s", file)
 		return "", webdav.NewHTTPError(400, err)
 	}

storage/filesystem_caldav.go

@@ -12,11 +12,11 @@ import (
 	"path"
 	"path/filepath"
 
+	"github.com/rs/zerolog/log"
+
 	"github.com/emersion/go-ical"
 	"github.com/emersion/go-webdav"
 	"github.com/emersion/go-webdav/caldav"
-
-	"git.sr.ht/~sircmpwn/tokidoki/debug"
 )
 
 func (b *filesystemBackend) CalendarHomeSetPath(ctx context.Context) (string, error) {
@@ -100,7 +100,7 @@ func (b *filesystemBackend) loadAllCalendars(ctx context.Context, propFilter []s
 		return nil
 	})
 
-	debug.Printf("filesystem.loadAllCalendars() returning %d results from %s", len(result), localPath)
+	log.Debug().Int("results", len(result)).Str("path", localPath).Msg("filesystem.loadAllCalendars() successful")
 	return result, err
 }
 
@@ -124,7 +124,7 @@ func createDefaultCalendar(path, localPath string) error {
 }
 
 func (b *filesystemBackend) Calendar(ctx context.Context) (*caldav.Calendar, error) {
-	debug.Printf("filesystem.Calendar()")
+	log.Debug().Msg("filesystem.Calendar()")
 
 	localPath, err := b.localCalDAVPath(ctx, "")
 	if err != nil {
@@ -132,7 +132,7 @@ func (b *filesystemBackend) Calendar(ctx context.Context) (*caldav.Calendar, err
 	}
 	localPath = filepath.Join(localPath, "calendar.json")
 
-	debug.Printf("loading calendar from %s", localPath)
+	log.Debug().Str("local_path", localPath).Msg("loading calendar")
 
 	data, readErr := ioutil.ReadFile(localPath)
 	if os.IsNotExist(readErr) {
@@ -141,7 +141,7 @@ func (b *filesystemBackend) Calendar(ctx context.Context) (*caldav.Calendar, err
 			return nil, err
 		}
 		urlPath = path.Join(urlPath, defaultResourceName) + "/"
-		debug.Printf("creating default calendar (URL:path): %s:%s", urlPath, localPath)
+		log.Debug().Str("local_path", localPath).Str("url_path", urlPath).Msg("creating calendar")
 		err = createDefaultCalendar(urlPath, localPath)
 		if err != nil {
 			return nil, err
@@ -161,7 +161,7 @@ func (b *filesystemBackend) Calendar(ctx context.Context) (*caldav.Calendar, err
 }
 
 func (b *filesystemBackend) GetCalendarObject(ctx context.Context, objPath string, req *caldav.CalendarCompRequest) (*caldav.CalendarObject, error) {
-	debug.Printf("filesystem.GetCalendarObject(%s, %v)", objPath, req)
+	log.Debug().Str("url_path", objPath).Msg("filesystem.GetCalendarObject()")
 
 	localPath, err := b.localCalDAVPath(ctx, objPath)
 	if err != nil {
@@ -171,7 +171,7 @@ func (b *filesystemBackend) GetCalendarObject(ctx context.Context, objPath strin
 	info, err := os.Stat(localPath)
 	if err != nil {
 		if errors.Is(err, fs.ErrNotExist) {
-			debug.Printf("not found: %s", localPath)
+			log.Debug().Str("local_path", localPath).Msg("object not found")
 			return nil, webdav.NewHTTPError(404, err)
 		}
 		return nil, err
@@ -184,7 +184,7 @@ func (b *filesystemBackend) GetCalendarObject(ctx context.Context, objPath strin
 
 	calendar, err := calendarFromFile(localPath, propFilter)
 	if err != nil {
-		debug.Printf("error reading calendar: %v", err)
+		log.Debug().Err(err).Msg("error reading calendar")
 		return nil, err
 	}
 
@@ -204,7 +204,7 @@ func (b *filesystemBackend) GetCalendarObject(ctx context.Context, objPath strin
 }
 
 func (b *filesystemBackend) ListCalendarObjects(ctx context.Context, req *caldav.CalendarCompRequest) ([]caldav.CalendarObject, error) {
-	debug.Printf("filesystem.ListCalendarObjects(%v)", req)
+	log.Debug().Msg("filesystem.ListCalendarObjects()")
 
 	var propFilter []string
 	if req != nil && !req.AllProps {
@@ -215,7 +215,7 @@ func (b *filesystemBackend) ListCalendarObjects(ctx context.Context, req *caldav
 }
 
 func (b *filesystemBackend) QueryCalendarObjects(ctx context.Context, query *caldav.CalendarQuery) ([]caldav.CalendarObject, error) {
-	debug.Printf("filesystem.QueryCalendarObjects(%v)", query)
+	log.Debug().Msg("filesystem.QueryCalendarObjects()")
 
 	var propFilter []string
 	if query != nil && !query.CompRequest.AllProps {
@@ -231,7 +231,7 @@ func (b *filesystemBackend) QueryCalendarObjects(ctx context.Context, query *cal
 }
 
 func (b *filesystemBackend) PutCalendarObject(ctx context.Context, objPath string, calendar *ical.Calendar, opts *caldav.PutCalendarObjectOptions) (loc string, err error) {
-	debug.Printf("filesystem.PutCalendarObject(%s, %v, %v)", objPath, calendar, opts)
+	log.Debug().Str("url_path", objPath).Msg("filesystem.PutCalendarObject()")
 
 	_, uid, err := caldav.ValidateCalendarObject(calendar)
 	if err != nil {
@@ -289,7 +289,7 @@ func (b *filesystemBackend) PutCalendarObject(ctx context.Context, objPath strin
 }
 
 func (b *filesystemBackend) DeleteCalendarObject(ctx context.Context, path string) error {
-	debug.Printf("filesystem.DeleteCalendarObject(%s)", path)
+	log.Debug().Str("url_path", path).Msg("filesystem.DeleteCalendarObject()")
 
 	localPath, err := b.localCalDAVPath(ctx, path)
 	if err != nil {

storage/filesystem_carddav.go

@@ -12,11 +12,11 @@ import (
 	"path"
 	"path/filepath"
 
+	"github.com/rs/zerolog/log"
+
 	"github.com/emersion/go-vcard"
 	"github.com/emersion/go-webdav"
 	"github.com/emersion/go-webdav/carddav"
-
-	"git.sr.ht/~sircmpwn/tokidoki/debug"
 )
 
 func (b *filesystemBackend) AddressbookHomeSetPath(ctx context.Context) (string, error) {
@@ -95,14 +95,14 @@ func createDefaultAddressBook(path, localPath string) error {
 }
 
 func (b *filesystemBackend) AddressBook(ctx context.Context) (*carddav.AddressBook, error) {
-	debug.Printf("filesystem.AddressBook()")
+	log.Debug().Msg("filesystem.AddressBook()")
 	localPath, err := b.localCardDAVPath(ctx, "")
 	if err != nil {
 		return nil, err
 	}
 	localPath = filepath.Join(localPath, "addressbook.json")
 
-	debug.Printf("loading addressbook from %s", localPath)
+	log.Debug().Str("local_path", localPath).Msg("loading addressbook")
 
 	data, readErr := ioutil.ReadFile(localPath)
 	if os.IsNotExist(readErr) {
@@ -111,7 +111,7 @@ func (b *filesystemBackend) AddressBook(ctx context.Context) (*carddav.AddressBo
 			return nil, err
 		}
 		urlPath = path.Join(urlPath, defaultResourceName) + "/"
-		debug.Printf("creating default addressbook (URL:path): %s:%s", urlPath, localPath)
+		log.Debug().Str("local_path", localPath).Str("url_path", urlPath).Msg("creating addressbook")
 		err = createDefaultAddressBook(urlPath, localPath)
 		if err != nil {
 			return nil, err
@@ -131,7 +131,7 @@ func (b *filesystemBackend) AddressBook(ctx context.Context) (*carddav.AddressBo
 }
 
 func (b *filesystemBackend) GetAddressObject(ctx context.Context, objPath string, req *carddav.AddressDataRequest) (*carddav.AddressObject, error) {
-	debug.Printf("filesystem.GetAddressObject(%s, %v)", objPath, req)
+	log.Debug().Str("url_path", objPath).Msg("filesystem.GetAddressObject()")
 	localPath, err := b.localCardDAVPath(ctx, objPath)
 	if err != nil {
 		return nil, err
@@ -213,12 +213,12 @@ func (b *filesystemBackend) loadAllContacts(ctx context.Context, propFilter []st
 		return nil
 	})
 
-	debug.Printf("filesystem.loadAllContacts() returning %d results from %s", len(result), localPath)
+	log.Debug().Int("results", len(result)).Str("path", localPath).Msg("filesystem.loadAllContacts() successful")
 	return result, err
 }
 
 func (b *filesystemBackend) ListAddressObjects(ctx context.Context, req *carddav.AddressDataRequest) ([]carddav.AddressObject, error) {
-	debug.Printf("filesystem.ListAddressObjects(%v)", req)
+	log.Debug().Msg("filesystem.ListAddressObjects()")
 	var propFilter []string
 	if req != nil && !req.AllProp {
 		propFilter = req.Props
@@ -228,7 +228,7 @@ func (b *filesystemBackend) ListAddressObjects(ctx context.Context, req *carddav
 }
 
 func (b *filesystemBackend) QueryAddressObjects(ctx context.Context, query *carddav.AddressBookQuery) ([]carddav.AddressObject, error) {
-	debug.Printf("filesystem.QueryAddressObjects(%v)", query)
+	log.Debug().Msg("filesystem.QueryAddressObjects()")
 	var propFilter []string
 	if query != nil && !query.DataRequest.AllProp {
 		propFilter = query.DataRequest.Props
@@ -243,7 +243,7 @@ func (b *filesystemBackend) QueryAddressObjects(ctx context.Context, query *card
 }
 
 func (b *filesystemBackend) PutAddressObject(ctx context.Context, objPath string, card vcard.Card, opts *carddav.PutAddressObjectOptions) (loc string, err error) {
-	debug.Printf("filesystem.PutAddressObject(%v, %v, %v)", objPath, card, opts)
+	log.Debug().Str("url_path", objPath).Msg("filesystem.PutAddressObject()")
 
 	// Object always get saved as <UID>.vcf
 	dirname, _ := path.Split(objPath)
@@ -296,7 +296,7 @@ func (b *filesystemBackend) PutAddressObject(ctx context.Context, objPath string
 }
 
 func (b *filesystemBackend) DeleteAddressObject(ctx context.Context, path string) error {
-	debug.Printf("filesystem.DeleteAddressObject(%s)", path)
+	log.Debug().Str("url_path", path).Msg("filesystem.DeleteAddressObject()")
 
 	localPath, err := b.localCardDAVPath(ctx, path)
 	if err != nil {