refactor: use slog for logging

Add structured logging for greater viability into the transaction
mappings. Also use a decoder for the YNAB cleared status, simply done to
have less log statements.

commit-id:2fc69e1c

cmd/ynabber/main.go

@@ -3,8 +3,8 @@ package main
 import (
 	"fmt"
 	"log"
+	"log/slog"
 	"os"
-	"strings"
 	"time"
 
 	"github.com/carlmjohnson/versioninfo"
@@ -15,27 +15,29 @@ import (
 	"github.com/martinohansen/ynabber/writer/ynab"
 )
 
-func main() {
-	log.Println("Version:", versioninfo.Short())
+func setupLogging(debug bool) {
+	programLevel := slog.LevelInfo
+	if debug {
+		programLevel = slog.LevelDebug
+	}
+	logger := slog.New(slog.NewTextHandler(
+		os.Stderr, &slog.HandlerOptions{
+			Level: programLevel,
+		}))
+	slog.SetDefault(logger)
+}
 
+func main() {
 	// Read config from env
 	var cfg ynabber.Config
 	err := envconfig.Process("", &cfg)
 	if err != nil {
 		log.Fatal(err.Error())
 	}
 
-	// Check that some values are valid
-	cfg.YNAB.Cleared = strings.ToLower(cfg.YNAB.Cleared)
-	if cfg.YNAB.Cleared != "cleared" &&
-		cfg.YNAB.Cleared != "uncleared" &&
-		cfg.YNAB.Cleared != "reconciled" {
-		log.Fatal("YNAB_CLEARED must be one of cleared, uncleared or reconciled")
-	}
-
-	if cfg.Debug {
-		log.Printf("Config: %+v\n", cfg)
-	}
+	setupLogging(cfg.Debug)
+	slog.Info("starting...", "version", versioninfo.Short())
+	slog.Debug("", "config", cfg)
 
 	ynabber := ynabber.Ynabber{}
 	for _, reader := range cfg.Readers {
@@ -49,7 +51,7 @@ func main() {
 	for _, writer := range cfg.Writers {
 		switch writer {
 		case "ynab":
-			ynabber.Writers = append(ynabber.Writers, ynab.Writer{Config: &cfg})
+			ynabber.Writers = append(ynabber.Writers, ynab.NewWriter(&cfg))
 		case "json":
 			ynabber.Writers = append(ynabber.Writers, json.Writer{})
 		default:
@@ -58,22 +60,23 @@ func main() {
 	}
 
 	for {
-		err = run(ynabber, cfg.Interval)
+		start := time.Now()
+		err = run(ynabber)
 		if err != nil {
 			panic(err)
 		} else {
-			log.Printf("Run succeeded")
-		}
-		if cfg.Interval > 0 {
-			log.Printf("Waiting %s before running again...", cfg.Interval)
-			time.Sleep(cfg.Interval)
-		} else {
-			os.Exit(0)
+			slog.Info("run succeeded", "in", time.Since(start))
+			if cfg.Interval > 0 {
+				slog.Info("waiting for next run", "in", cfg.Interval)
+				time.Sleep(cfg.Interval)
+			} else {
+				os.Exit(0)
+			}
 		}
 	}
 }
 
-func run(y ynabber.Ynabber, interval time.Duration) error {
+func run(y ynabber.Ynabber) error {
 	var transactions []ynabber.Transaction
 
 	// Read transactions from all readers

config.go

@@ -2,6 +2,8 @@ package ynabber
 
 import (
 	"encoding/json"
+	"fmt"
+	"strings"
 	"time"
 )
 
@@ -30,6 +32,30 @@ func (accountMap *AccountMap) Decode(value string) error {
 	return nil
 }
 
+type TransactionStatus string
+
+const (
+	Cleared    TransactionStatus = "cleared"
+	Uncleared  TransactionStatus = "uncleared"
+	Reconciled TransactionStatus = "reconciled"
+)
+
+// Decode implements `envconfig.Decoder` for TransactionStatus
+func (cs *TransactionStatus) Decode(value string) error {
+	lowered := strings.ToLower(value)
+	switch lowered {
+	case string(Cleared), string(Uncleared), string(Reconciled):
+		*cs = TransactionStatus(lowered)
+		return nil
+	default:
+		return fmt.Errorf("unknown value %s", value)
+	}
+}
+
+func (cs TransactionStatus) String() string {
+	return string(cs)
+}
+
 // Config is loaded from the environment during execution with cmd/ynabber
 type Config struct {
 	// DataDir is the path for storing files
@@ -115,7 +141,7 @@ type YNAB struct {
 	// Default is uncleared for historical reasons but recommend setting this
 	// to cleared because ynabber transactions are cleared by bank.
 	// They'd still be unapproved until approved in YNAB.
-	Cleared string `envconfig:"YNAB_CLEARED" default:"uncleared"`
+	Cleared TransactionStatus `envconfig:"YNAB_CLEARED" default:"uncleared"`
 
 	// SwapFlow changes inflow to outflow and vice versa for any account with a
 	// IBAN number in the list. This maybe be relevant for credit card accounts.

reader/nordigen/nordigen.go

@@ -2,7 +2,7 @@ package nordigen
 
 import (
 	"fmt"
-	"log"
+	"log/slog"
 	"regexp"
 	"strings"
 
@@ -12,8 +12,8 @@ import (
 
 type Reader struct {
 	Config *ynabber.Config
-
 	Client *nordigen.Client
+	logger *slog.Logger
 }
 
 // NewReader returns a new nordigen reader or panics
@@ -26,6 +26,10 @@ func NewReader(cfg *ynabber.Config) Reader {
 	return Reader{
 		Config: cfg,
 		Client: client,
+		logger: slog.Default().With(
+			"reader", "nordigen",
+			"bank_id", cfg.Nordigen.BankID,
+		),
 	}
 }
 
@@ -54,6 +58,7 @@ func (r Reader) toYnabbers(a ynabber.Account, t nordigen.AccountTransactions) ([
 	y := []ynabber.Transaction{}
 	for _, v := range t.Transactions.Booked {
 		transaction, err := r.toYnabber(a, v)
+		r.logger.Debug("mapping transaction", "from", v, "to", transaction)
 		if err != nil {
 			return nil, err
 		}
@@ -70,8 +75,9 @@ func (r Reader) Bulk() (t []ynabber.Transaction, err error) {
 		return nil, fmt.Errorf("failed to authorize: %w", err)
 	}
 
-	log.Printf("Found %v accounts", len(req.Accounts))
+	r.logger.Info("bulk reading", "accounts", len(req.Accounts))
 	for _, account := range req.Accounts {
+		logger := r.logger.With("account", account)
 		accountMetadata, err := r.Client.GetAccountMetadata(account)
 		if err != nil {
 			return nil, fmt.Errorf("failed to get account metadata: %w", err)
@@ -81,11 +87,7 @@ func (r Reader) Bulk() (t []ynabber.Transaction, err error) {
 		// requisition.
 		switch accountMetadata.Status {
 		case "EXPIRED", "SUSPENDED":
-			log.Printf(
-				"Account: %s is %s. Going to recreate the requisition...",
-				account,
-				accountMetadata.Status,
-			)
+			logger.Info("recreating requisition", "status", accountMetadata.Status)
 			r.createRequisition()
 		}
 
@@ -95,17 +97,12 @@ func (r Reader) Bulk() (t []ynabber.Transaction, err error) {
 			IBAN: accountMetadata.Iban,
 		}
 
-		log.Printf("Reading transactions from account: %s", account.Name)
-
+		logger.Info("reading transactions")
 		transactions, err := r.Client.GetAccountTransactions(string(account.ID))
 		if err != nil {
 			return nil, fmt.Errorf("failed to get transactions: %w", err)
 		}
 
-		if r.Config.Debug {
-			log.Printf("Transactions received from Nordigen: %+v", transactions)
-		}
-
 		x, err := r.toYnabbers(account, transactions)
 		if err != nil {
 			return nil, fmt.Errorf("failed to convert transaction: %w", err)

writer/ynab/ynab.go

@@ -5,9 +5,8 @@ import (
 	"crypto/sha256"
 	"encoding/json"
 	"fmt"
-	"log"
+	"log/slog"
 	"net/http"
-	"net/http/httputil"
 	"regexp"
 	"strings"
 	"time"
@@ -18,10 +17,6 @@ import (
 const maxMemoSize int = 200  // Max size of memo field in YNAB API
 const maxPayeeSize int = 100 // Max size of payee field in YNAB API
 
-type Writer struct {
-	Config *ynabber.Config
-}
-
 var space = regexp.MustCompile(`\s+`) // Matches all whitespace characters
 
 // Ytransaction is a single YNAB transaction
@@ -41,6 +36,22 @@ type Ytransactions struct {
 	Transactions []Ytransaction `json:"transactions"`
 }
 
+type Writer struct {
+	Config *ynabber.Config
+	logger *slog.Logger
+}
+
+// NewWriter returns a new YNAB writer
+func NewWriter(cfg *ynabber.Config) Writer {
+	return Writer{
+		Config: cfg,
+		logger: slog.Default().With(
+			"writer", "ynab",
+			"budget_id", cfg.YNAB.BudgetID,
+		),
+	}
+}
+
 // accountParser takes IBAN and returns the matching YNAB account ID in
 // accountMap
 func accountParser(iban string, accountMap map[string]string) (string, error) {
@@ -53,7 +64,7 @@ func accountParser(iban string, accountMap map[string]string) (string, error) {
 }
 
 // makeID returns a unique YNAB import ID to avoid duplicate transactions.
-func makeID(cfg ynabber.Config, t ynabber.Transaction) string {
+func makeID(t ynabber.Transaction) string {
 	date := t.Date.Format("2006-01-02")
 	amount := t.Amount.String()
 
@@ -67,48 +78,47 @@ func makeID(cfg ynabber.Config, t ynabber.Transaction) string {
 	return fmt.Sprintf("YBBR:%x", hash)[:32]
 }
 
-func ynabberToYNAB(cfg ynabber.Config, t ynabber.Transaction) (Ytransaction, error) {
-	accountID, err := accountParser(t.Account.IBAN, cfg.YNAB.AccountMap)
+func (w Writer) toYNAB(t ynabber.Transaction) (Ytransaction, error) {
+	accountID, err := accountParser(t.Account.IBAN, w.Config.YNAB.AccountMap)
 	if err != nil {
 		return Ytransaction{}, err
 	}
+	logger := w.logger.With("account", accountID)
 
 	date := t.Date.Format("2006-01-02")
 
 	// Trim consecutive spaces from memo and truncate if too long
 	memo := strings.TrimSpace(space.ReplaceAllString(t.Memo, " "))
 	if len(memo) > maxMemoSize {
-		log.Printf("Memo on account %s on date %s is too long - truncated to %d characters",
-			t.Account.Name, date, maxMemoSize)
+		logger.Warn("memo too long", "transaction", t, "max_size", maxMemoSize)
 		memo = memo[0:(maxMemoSize - 1)]
 	}
 
 	// Trim consecutive spaces from payee and truncate if too long
 	payee := strings.TrimSpace(space.ReplaceAllString(string(t.Payee), " "))
 	if len(payee) > maxPayeeSize {
-		log.Printf("Payee on account %s on date %s is too long - truncated to %d characters",
-			t.Account.Name, date, maxPayeeSize)
+		logger.Warn("payee too long", "transaction", t, "max_size", maxPayeeSize)
 		payee = payee[0:(maxPayeeSize - 1)]
 	}
 
 	// If SwapFlow is defined check if the account is configured to swap inflow
 	// to outflow. If so swap it by using the Negate method.
-	if cfg.YNAB.SwapFlow != nil {
-		for _, account := range cfg.YNAB.SwapFlow {
+	if w.Config.YNAB.SwapFlow != nil {
+		for _, account := range w.Config.YNAB.SwapFlow {
 			if account == t.Account.IBAN {
 				t.Amount = t.Amount.Negate()
 			}
 		}
 	}
 
 	return Ytransaction{
-		ImportID:  makeID(cfg, t),
+		ImportID:  makeID(t),
 		AccountID: accountID,
 		Date:      date,
 		Amount:    t.Amount.String(),
 		PayeeName: payee,
 		Memo:      memo,
-		Cleared:   cfg.YNAB.Cleared,
+		Cleared:   string(w.Config.YNAB.Cleared),
 		Approved:  false,
 	}, nil
 }
@@ -136,26 +146,22 @@ func (w Writer) Bulk(t []ynabber.Transaction) error {
 			continue
 		}
 
-		transaction, err := ynabberToYNAB(*w.Config, v)
+		transaction, err := w.toYNAB(v)
 		if err != nil {
 			// If we fail to parse a single transaction we log it but move on so
 			// we don't halt the entire program.
-			log.Printf("Failed to parse transaction: %s: %s", v, err)
+			w.logger.Error("parsing", "transaction", v, "err", err)
 			failed += 1
 			continue
 		}
 		y.Transactions = append(y.Transactions, transaction)
 	}
 
 	if len(t) == 0 || len(y.Transactions) == 0 {
-		log.Println("No transactions to write")
+		w.logger.Info("No transactions to write")
 		return nil
 	}
 
-	if w.Config.Debug {
-		log.Printf("Request to YNAB: %+v", y)
-	}
-
 	url := fmt.Sprintf("https://api.youneedabudget.com/v1/budgets/%s/transactions", w.Config.YNAB.BudgetID)
 
 	payload, err := json.Marshal(y)
@@ -178,18 +184,18 @@ func (w Writer) Bulk(t []ynabber.Transaction) error {
 	}
 	defer res.Body.Close()
 
-	if w.Config.Debug {
-		b, _ := httputil.DumpResponse(res, true)
-		log.Printf("Response from YNAB: %s", b)
-	}
-
 	if res.StatusCode != http.StatusCreated {
 		return fmt.Errorf("failed to send request: %s", res.Status)
 	} else {
-		log.Printf(
-			"Successfully sent %v transaction(s) to YNAB. %d got skipped and %d failed.",
+		w.logger.Info(
+			"Request sent",
+			"status",
+			res.Status,
+			"transactions",
 			len(y.Transactions),
+			"skipped",
 			skipped,
+			"failed",
 			failed,
 		)
 	}