improved logging for debug

cmd/any2anexoj-cli/main.go

@@ -21,6 +21,7 @@ var (
 	// remove/change default
 	platform = pflag.StringP("platform", "p", "trading212", "One of the supported platforms")
 	lang     = pflag.StringP("language", "l", language.Portuguese.String(), "The 2 letter language code")
+	debug    = pflag.BoolP("debug", "d", false, "Activate to log debug messages")
 	ofAPIKey = pflag.String("open-figi-api-key", "", "An OpenFIGI API key for faster report generation (better rate api rate limits)")
 	// TODO: improve documentation on selectors
 	selectors = pflag.StringSlice("selectors", nil, "Only process entries that conform to all the selectors:")
@@ -42,7 +43,11 @@ func run(ctx context.Context) error {
 
 	eg, ctx := errgroup.WithContext(ctx)
 
-	slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, nil)))
+	logLevel := slog.LevelInfo
+	if *debug {
+		logLevel = slog.LevelDebug
+	}
+	slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: logLevel})))
 
 	if platform == nil || len(*platform) == 0 {
 		slog.Error("--platform flag is required")

internal/open_figi.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"sync"
 	"time"
@@ -33,7 +34,10 @@ func NewOpenFIGI(c *http.Client, apiKey string) *OpenFIGI {
 	// Rate limits as per https://www.openfigi.com/api/documentation#rate-limits
 	limiter := rate.NewLimiter(rate.Every(time.Minute), 25)
 	if len(apiKey) > 0 {
+		slog.Debug("OpenFIGI client: created with API Key rate limits")
 		limiter = rate.NewLimiter(rate.Every(time.Second*6), 25)
+	} else {
+		slog.Debug("OpenFIGI client: created with puplic rate limits")
 	}
 
 	return &OpenFIGI{
@@ -48,10 +52,16 @@ func (of *OpenFIGI) SecurityTypeByISIN(ctx context.Context, isin string) (string
 	of.mu.RLock()
 	if secType, ok := of.securityTypeCache[isin]; ok {
 		of.mu.RUnlock()
+		slog.Debug("OpenFIGI client: SecurityTypeByISIN cache hit",
+			slog.String("isin", isin),
+			slog.String("security_type", secType))
 		return secType, nil
 	}
 	of.mu.RUnlock()
 
+	slog.Debug("OpenFIGI client: SecurityTypeByISIN cache miss",
+		slog.String("isin", isin))
+
 	of.mu.Lock()
 	defer of.mu.Unlock()
 
@@ -85,6 +95,10 @@ func (of *OpenFIGI) SecurityTypeByISIN(ctx context.Context, isin string) (string
 		req.Header.Add(OpenFIGIAPIKeyHeader, of.apiKey)
 	}
 
+	if !of.mappingLimiter.Allow() {
+		slog.Debug("OpenFIGI client: mapping limiter waiting for rate limiter capacity")
+	}
+
 	err = of.mappingLimiter.Wait(ctx)
 	if err != nil {
 		return "", fmt.Errorf("wait for mapping request capacity: %w", err)
@@ -123,6 +137,10 @@ func (of *OpenFIGI) SecurityTypeByISIN(ctx context.Context, isin string) (string
 
 	of.securityTypeCache[isin] = secType
 
+	slog.Debug("OpenFIGI client: SecurityTypeByISIN cached mapping",
+		slog.String("isin", isin),
+		slog.String("security_type", secType))
+
 	return secType, nil
 }
 

internal/report.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"time"
 
 	"github.com/shopspring/decimal"
@@ -58,10 +59,21 @@ type Selector func(Record) bool
 func BuildReport(ctx context.Context, reader RecordReader, writer ReportWriter, s Selector) error {
 	buys := make(map[string]*FillerQueue)
 
+	var buysCount, sellsCount int64
+	var lastTimestamp time.Time
+	progTicker := time.NewTicker(10 * time.Second)
+
 	for {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
+		case <-progTicker.C:
+			slog.InfoContext(ctx, "Progress update",
+				slog.Int64("total_records", buysCount+sellsCount),
+				slog.Int64("sell_records", sellsCount),
+				slog.Int64("buy_records", buysCount),
+				slog.Time("last_record_timestamp", lastTimestamp),
+			)
 		default:
 			rec, err := reader.ReadRecord(ctx)
 			if err != nil {
@@ -72,9 +84,21 @@ func BuildReport(ctx context.Context, reader RecordReader, writer ReportWriter,
 			}
 
 			if !s(rec) {
+				slog.Debug("Report: skipping record",
+					slog.String("symbol", rec.Symbol()),
+					slog.String("side", rec.Side().String()),
+				)
 				continue
 			}
 
+			if rec.Side().IsBuy() {
+				buysCount++
+			} else {
+				sellsCount++
+			}
+
+			lastTimestamp = rec.Timestamp()
+
 			buyQueue, ok := buys[rec.Symbol()]
 			if !ok {
 				buyQueue = new(FillerQueue)
@@ -85,11 +109,17 @@ func BuildReport(ctx context.Context, reader RecordReader, writer ReportWriter,
 			if err != nil {
 				return fmt.Errorf("processing record: %w", err)
 			}
+
 		}
 	}
 }
 
 func processRecord(ctx context.Context, q *FillerQueue, rec Record, writer ReportWriter) error {
+	slog.Debug("Report: processing record",
+		slog.String("symbol", rec.Symbol()),
+		slog.String("side", rec.Side().String()),
+	)
+
 	switch rec.Side() {
 	case SideBuy:
 		q.Push(NewFiller(rec))