feat: add configurabile logging

Author: gsanchietti

README.md

@@ -16,6 +16,7 @@ The proxy is configured via environment variables. Minimal required env:
 - `SUPER_ADMIN_TOKEN`: the Application Service `as_token` from your registration file
 - `PROXY_PORT` (optional): port to listen on (default: `8080`)
 - `AS_USER_ID` (optional): the user ID of the Application Service bot (default: `@_acrobits_proxy:matrix.example`)
+- `LOGLEVEL` (optional): logging verbosity level - `DEBUG`, `INFO`, `WARNING`, `CRITICAL` (default: `INFO`)
 
 Building and running
 
@@ -28,9 +29,21 @@ export MATRIX_HOMESERVER_URL="https://matrix.your-homeserver-name.com"
 export SUPER_ADMIN_TOKEN="YOUR_SECURE_APPLICATION_SERVICE_TOKEN"
 export PROXY_PORT=8080
 export AS_USER_ID="@_acrobits_proxy:your-homeserver-name.com"
+export LOGLEVEL=INFO
 ./matrix2acrobits
 ```
 
+### Logging Levels
+
+The `LOGLEVEL` environment variable controls the verbosity of application logs:
+
+- **DEBUG**: Detailed information for diagnosing issues (shows all API calls, mapping lookups, Matrix operations)
+- **INFO**: General informational messages (successful operations, server startup) - **Default**
+- **WARNING**: Warning messages for potentially problematic situations
+- **CRITICAL**: Only critical errors
+
+For debugging mapping and API issues, set `LOGLEVEL=DEBUG` to see detailed trace information.
+
 ## Extra info
 
 - [Deploying with NS8](docs/DEPLOY_NS8.md)

agents.md

@@ -21,6 +21,7 @@ The proxy translates Acrobits' proprietary HTTP API calls for messaging into sta
 - **Language:** Golang (1.23+)
 - **Web Framework:** Standard Echo (v4) framework
 - **Matrix SDK:** `mautrix-go` (recommended)
+- **Logging:** `zerolog` for structured logging with configurable levels
 - **Testing:** Standard testing package with `testify/assert` and `testify/mock`
 
 ---
@@ -53,6 +54,7 @@ The proxy translates Acrobits' proprietary HTTP API calls for messaging into sta
 
 ```
 cmd/              # Main application entry point
+internal/logger/  # Structured logging with configurable levels (DEBUG, INFO, WARNING, CRITICAL)
 internal/api/     # HTTP handlers for Acrobits endpoints
 internal/matrix/  # Matrix client wrapper and logic
 internal/service/ # Business logic (translation between Acrobits <-> Matrix models)
@@ -74,6 +76,7 @@ go build -o matrix2acrobits .
 export MATRIX_HOMESERVER_URL="https://matrix.your-homeserver-name.com"
 export SUPER_ADMIN_TOKEN="YOUR_SECURE_APPLICATION_SERVICE_TOKEN"
 export PROXY_PORT=8080
+export LOGLEVEL=INFO  # DEBUG, INFO, WARNING, or CRITICAL
 ./matrix2acrobits
 ```
 

api/routes.go

@@ -6,6 +6,7 @@ import (
 	"strings"
 
 	"github.com/labstack/echo/v4"
+	"github.com/nethesis/matrix2acrobits/logger"
 	"github.com/nethesis/matrix2acrobits/models"
 	"github.com/nethesis/matrix2acrobits/service"
 )
@@ -29,26 +30,38 @@ type handler struct {
 func (h handler) sendMessage(c echo.Context) error {
 	var req models.SendMessageRequest
 	if err := c.Bind(&req); err != nil {
+		logger.Warn().Str("endpoint", "send_message").Err(err).Msg("invalid request payload")
 		return echo.NewHTTPError(http.StatusBadRequest, "invalid payload")
 	}
 
+	logger.Debug().Str("endpoint", "send_message").Str("from", req.From).Str("to", req.SMSTo).Msg("processing send message request")
+
 	resp, err := h.svc.SendMessage(c.Request().Context(), &req)
 	if err != nil {
+		logger.Error().Str("endpoint", "send_message").Str("from", req.From).Str("to", req.SMSTo).Err(err).Msg("failed to send message")
 		return mapServiceError(err)
 	}
+
+	logger.Info().Str("endpoint", "send_message").Str("from", req.From).Str("to", req.SMSTo).Str("sms_id", resp.SMSID).Msg("message sent successfully")
 	return c.JSON(http.StatusOK, resp)
 }
 
 func (h handler) fetchMessages(c echo.Context) error {
 	var req models.FetchMessagesRequest
 	if err := c.Bind(&req); err != nil {
+		logger.Warn().Str("endpoint", "fetch_messages").Err(err).Msg("invalid request payload")
 		return echo.NewHTTPError(http.StatusBadRequest, "invalid payload")
 	}
 
+	logger.Debug().Str("endpoint", "fetch_messages").Str("username", req.Username).Str("last_id", req.LastID).Msg("processing fetch messages request")
+
 	resp, err := h.svc.FetchMessages(c.Request().Context(), &req)
 	if err != nil {
+		logger.Error().Str("endpoint", "fetch_messages").Str("username", req.Username).Err(err).Msg("failed to fetch messages")
 		return mapServiceError(err)
 	}
+
+	logger.Info().Str("endpoint", "fetch_messages").Str("username", req.Username).Int("received", len(resp.ReceivedSMSS)).Int("sent", len(resp.SentSMSS)).Msg("messages fetched successfully")
 	return c.JSON(http.StatusOK, resp)
 }
 
@@ -59,12 +72,19 @@ func (h handler) postMapping(c echo.Context) error {
 
 	var req models.MappingRequest
 	if err := c.Bind(&req); err != nil {
+		logger.Warn().Str("endpoint", "post_mapping").Err(err).Msg("invalid request payload")
 		return echo.NewHTTPError(http.StatusBadRequest, "invalid payload")
 	}
+
+	logger.Debug().Str("endpoint", "post_mapping").Str("sms_number", req.SMSNumber).Str("room_id", req.RoomID).Msg("saving mapping")
+
 	resp, err := h.svc.SaveMapping(&req)
 	if err != nil {
+		logger.Error().Str("endpoint", "post_mapping").Str("sms_number", req.SMSNumber).Err(err).Msg("failed to save mapping")
 		return echo.NewHTTPError(http.StatusBadRequest, err.Error())
 	}
+
+	logger.Info().Str("endpoint", "post_mapping").Str("sms_number", req.SMSNumber).Str("room_id", req.RoomID).Msg("mapping saved successfully")
 	return c.JSON(http.StatusOK, resp)
 }
 
@@ -75,21 +95,30 @@ func (h handler) getMapping(c echo.Context) error {
 
 	smsNumber := strings.TrimSpace(c.QueryParam("sms_number"))
 	if smsNumber == "" {
+		logger.Debug().Str("endpoint", "get_mapping").Msg("listing all mappings")
 		// return full mappings list when sms_number is not provided
 		respList, err := h.svc.ListMappings()
 		if err != nil {
+			logger.Error().Str("endpoint", "get_mapping").Err(err).Msg("failed to list mappings")
 			return echo.NewHTTPError(http.StatusInternalServerError, err.Error())
 		}
+		logger.Info().Str("endpoint", "get_mapping").Int("count", len(respList)).Msg("listed all mappings")
 		return c.JSON(http.StatusOK, respList)
 	}
 
+	logger.Debug().Str("endpoint", "get_mapping").Str("sms_number", smsNumber).Msg("looking up mapping")
+
 	resp, err := h.svc.LookupMapping(smsNumber)
 	if err != nil {
 		if errors.Is(err, service.ErrMappingNotFound) {
+			logger.Warn().Str("endpoint", "get_mapping").Str("sms_number", smsNumber).Msg("mapping not found")
 			return echo.NewHTTPError(http.StatusNotFound, err.Error())
 		}
+		logger.Error().Str("endpoint", "get_mapping").Str("sms_number", smsNumber).Err(err).Msg("failed to lookup mapping")
 		return echo.NewHTTPError(http.StatusInternalServerError, err.Error())
 	}
+
+	logger.Info().Str("endpoint", "get_mapping").Str("sms_number", smsNumber).Str("room_id", resp.RoomID).Msg("mapping found")
 	return c.JSON(http.StatusOK, resp)
 }
 

logger/logger.go

@@ -0,0 +1,94 @@
+package logger
+
+import (
+	"io"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/rs/zerolog"
+)
+
+var log zerolog.Logger
+
+// Level represents the logging level
+type Level string
+
+const (
+	LevelDebug    Level = "DEBUG"
+	LevelInfo     Level = "INFO"
+	LevelWarning  Level = "WARNING"
+	LevelCritical Level = "CRITICAL"
+)
+
+// Init initializes the global logger with the specified level
+func Init(level Level) {
+	var zLevel zerolog.Level
+	switch strings.ToUpper(string(level)) {
+	case string(LevelDebug):
+		zLevel = zerolog.DebugLevel
+	case string(LevelInfo):
+		zLevel = zerolog.InfoLevel
+	case string(LevelWarning):
+		zLevel = zerolog.WarnLevel
+	case string(LevelCritical):
+		zLevel = zerolog.ErrorLevel
+	default:
+		zLevel = zerolog.InfoLevel
+	}
+
+	zerolog.SetGlobalLevel(zLevel)
+	// Configure zerolog for human-readable output
+	log = zerolog.New(zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}).With().Timestamp().Logger()
+}
+
+// InitWithWriter initializes the logger with a custom writer (useful for testing)
+func InitWithWriter(level Level, w io.Writer) {
+	var zLevel zerolog.Level
+	switch strings.ToUpper(string(level)) {
+	case string(LevelDebug):
+		zLevel = zerolog.DebugLevel
+	case string(LevelInfo):
+		zLevel = zerolog.InfoLevel
+	case string(LevelWarning):
+		zLevel = zerolog.WarnLevel
+	case string(LevelCritical):
+		zLevel = zerolog.ErrorLevel
+	default:
+		zLevel = zerolog.InfoLevel
+	}
+
+	zerolog.SetGlobalLevel(zLevel)
+	// Configure zerolog for human-readable output
+	log = zerolog.New(zerolog.ConsoleWriter{Out: w, TimeFormat: time.RFC3339}).With().Timestamp().Logger()
+}
+
+// Debug logs a debug message
+func Debug() *zerolog.Event {
+	return log.Debug()
+}
+
+// Info logs an info message
+func Info() *zerolog.Event {
+	return log.Info()
+}
+
+// Warn logs a warning message
+func Warn() *zerolog.Event {
+	return log.Warn()
+}
+
+// Error logs an error message (CRITICAL level)
+func Error() *zerolog.Event {
+	return log.Error()
+}
+
+// Fatal logs a fatal message and exits
+func Fatal() *zerolog.Event {
+	return log.Fatal()
+}
+
+// With creates a child logger with additional fields
+func With() zerolog.Context {
+	return log.With()
+}

logger/logger_test.go

@@ -0,0 +1,138 @@
+package logger
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestInit(t *testing.T) {
+	tests := []struct {
+		name  string
+		level Level
+	}{
+		{
+			name:  "Debug level",
+			level: LevelDebug,
+		},
+		{
+			name:  "Info level",
+			level: LevelInfo,
+		},
+		{
+			name:  "Warning level",
+			level: LevelWarning,
+		},
+		{
+			name:  "Critical level",
+			level: LevelCritical,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			// Just ensure it doesn't panic
+			Init(tt.level)
+		})
+	}
+}
+
+func TestLogLevels(t *testing.T) {
+	var buf bytes.Buffer
+	InitWithWriter(LevelDebug, &buf)
+
+	Debug().Msg("debug message")
+	assert.Contains(t, buf.String(), "debug message")
+	assert.Contains(t, buf.String(), "DBG")
+
+	buf.Reset()
+	Info().Msg("info message")
+	assert.Contains(t, buf.String(), "info message")
+	assert.Contains(t, buf.String(), "INF")
+
+	buf.Reset()
+	Warn().Msg("warning message")
+	assert.Contains(t, buf.String(), "warning message")
+	assert.Contains(t, buf.String(), "WRN")
+
+	buf.Reset()
+	Error().Msg("error message")
+	assert.Contains(t, buf.String(), "error message")
+	assert.Contains(t, buf.String(), "ERR")
+}
+
+func TestLogLevelFiltering(t *testing.T) {
+	var buf bytes.Buffer
+	InitWithWriter(LevelWarning, &buf)
+
+	// Debug and Info should not be logged at WARNING level
+	Debug().Msg("debug message")
+	assert.Empty(t, buf.String())
+
+	Info().Msg("info message")
+	assert.Empty(t, buf.String())
+
+	// Warning should be logged
+	Warn().Msg("warning message")
+	assert.Contains(t, buf.String(), "warning message")
+
+	buf.Reset()
+	Error().Msg("error message")
+	assert.Contains(t, buf.String(), "error message")
+}
+
+func TestLogWithFields(t *testing.T) {
+	var buf bytes.Buffer
+	InitWithWriter(LevelInfo, &buf)
+
+	Info().Str("user", "@alice:example.com").Int("count", 42).Msg("user action")
+
+	output := buf.String()
+	assert.Contains(t, output, "user action")
+	assert.Contains(t, output, "@alice:example.com")
+	assert.Contains(t, output, "42")
+}
+
+func TestDefaultLevel(t *testing.T) {
+	var buf bytes.Buffer
+	// Invalid level should default to INFO
+	InitWithWriter("INVALID", &buf)
+
+	Debug().Msg("debug message")
+	assert.Empty(t, buf.String())
+
+	Info().Msg("info message")
+	assert.Contains(t, buf.String(), "info message")
+}
+
+func TestCaseInsensitiveLevel(t *testing.T) {
+	tests := []struct {
+		name     string
+		level    Level
+		expected string
+	}{
+		{
+			name:     "lowercase debug",
+			level:    Level(strings.ToLower(string(LevelDebug))),
+			expected: "debug",
+		},
+		{
+			name:     "mixed case info",
+			level:    Level("InFo"),
+			expected: "info",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var buf bytes.Buffer
+			InitWithWriter(tt.level, &buf)
+			// Just ensure it doesn't panic
+			assert.NotPanics(t, func() {
+				Info().Msg("test")
+			})
+		})
+	}
+}