feat: enhance logging and refactor database handling

This commit is contained in:
peio
2026-01-23 17:54:15 +00:00
parent b067a23bba
commit 179866e6d3
14 changed files with 222 additions and 92 deletions

View File

@@ -2,6 +2,7 @@ package mailcloak
import (
"fmt"
"log"
"os"
"gopkg.in/yaml.v3"
@@ -58,12 +59,15 @@ func LoadConfig(path string) (*Config, error) {
}
if cfg.Policy.CacheTTLSeconds <= 0 {
cfg.Policy.CacheTTLSeconds = 120
log.Printf("config: policy.cache_ttl_seconds not set, defaulting to %d", cfg.Policy.CacheTTLSeconds)
}
if cfg.Policy.KeycloakFailureMode == "" {
cfg.Policy.KeycloakFailureMode = "tempfail"
log.Printf("config: policy.keycloak_failure_mode not set, defaulting to %s", cfg.Policy.KeycloakFailureMode)
}
if cfg.Daemon.User == "" {
cfg.Daemon.User = "mailcloak"
log.Printf("config: daemon.user not set, defaulting to %s", cfg.Daemon.User)
}
return &cfg, nil
}

View File

@@ -5,6 +5,7 @@ import (
"encoding/json"
"fmt"
"io"
"log"
"net/http"
"net/url"
"strings"
@@ -43,18 +44,22 @@ func (k *Keycloak) token(ctx context.Context) (string, error) {
resp, err := k.hc.Do(req)
if err != nil {
log.Printf("keycloak token request error: %v", err)
return "", err
}
defer resp.Body.Close()
if resp.StatusCode/100 != 2 {
b, _ := io.ReadAll(io.LimitReader(resp.Body, 2048))
log.Printf("keycloak token non-2xx: %d", resp.StatusCode)
return "", fmt.Errorf("token http %d: %s", resp.StatusCode, string(b))
}
var tr tokenResp
if err := json.NewDecoder(resp.Body).Decode(&tr); err != nil {
log.Printf("keycloak token decode error: %v", err)
return "", err
}
if tr.AccessToken == "" {
log.Printf("keycloak token response missing access_token")
return "", fmt.Errorf("empty access_token")
}
return tr.AccessToken, nil
@@ -82,15 +87,18 @@ func (k *Keycloak) adminGet(ctx context.Context, bearer, path string, q url.Valu
resp, err := k.hc.Do(req)
if err != nil {
log.Printf("keycloak admin request error: %v", err)
return nil, err
}
defer resp.Body.Close()
if resp.StatusCode/100 != 2 {
b, _ := io.ReadAll(io.LimitReader(resp.Body, 2048))
log.Printf("keycloak admin non-2xx: %d", resp.StatusCode)
return nil, fmt.Errorf("admin http %d: %s", resp.StatusCode, string(b))
}
var users []kcUser
if err := json.NewDecoder(resp.Body).Decode(&users); err != nil {
log.Printf("keycloak admin decode error: %v", err)
return nil, err
}
return users, nil
@@ -108,11 +116,13 @@ func (k *Keycloak) EmailByUsername(ctx context.Context, username string) (string
q.Set("exact", "true")
users, err := k.adminGet(ctx, bearer, "/users", q)
if err != nil {
log.Printf("keycloak admin exact username lookup failed for %s: %v", username, err)
// fallback: search
q2 := url.Values{}
q2.Set("search", username)
users, err = k.adminGet(ctx, bearer, "/users", q2)
if err != nil {
log.Printf("keycloak admin search username lookup failed for %s: %v", username, err)
return "", false, err
}
}
@@ -136,11 +146,13 @@ func (k *Keycloak) EmailExists(ctx context.Context, email string) (bool, error)
q.Set("exact", "true")
users, err := k.adminGet(ctx, bearer, "/users", q)
if err != nil {
log.Printf("keycloak admin exact email lookup failed for %s: %v", email, err)
// fallback: search
q2 := url.Values{}
q2.Set("search", email)
users, err = k.adminGet(ctx, bearer, "/users", q2)
if err != nil {
log.Printf("keycloak admin search email lookup failed for %s: %v", email, err)
return false, err
}
}

View File

@@ -51,11 +51,12 @@ func OpenPolicyListener(cfg *Config) (net.Listener, error) {
_ = l.Close()
return nil, err
}
log.Printf("policy listener ready on %s", sock)
return l, nil
}
func ServePolicy(ctx context.Context, cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, l net.Listener) error {
func ServePolicy(ctx context.Context, cfg *Config, db *MailcloakDB, kc *Keycloak, cache *Cache, l net.Listener) error {
defer l.Close()
for {
@@ -65,6 +66,7 @@ func ServePolicy(ctx context.Context, cfg *Config, db *AliasDB, kc *Keycloak, ca
case <-ctx.Done():
return nil
default:
log.Printf("policy accept error: %v", err)
return err
}
}
@@ -72,7 +74,7 @@ func ServePolicy(ctx context.Context, cfg *Config, db *AliasDB, kc *Keycloak, ca
}
}
func RunPolicy(ctx context.Context, cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache) error {
func RunPolicy(ctx context.Context, cfg *Config, db *MailcloakDB, kc *Keycloak, cache *Cache) error {
l, err := OpenPolicyListener(cfg)
if err != nil {
return err
@@ -80,7 +82,7 @@ func RunPolicy(ctx context.Context, cfg *Config, db *AliasDB, kc *Keycloak, cach
return ServePolicy(ctx, cfg, db, kc, cache, l)
}
func handlePolicyConn(conn net.Conn, cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache) {
func handlePolicyConn(conn net.Conn, cfg *Config, db *MailcloakDB, kc *Keycloak, cache *Cache) {
defer conn.Close()
r := bufio.NewReader(conn)
@@ -99,6 +101,8 @@ func handlePolicyConn(conn net.Conn, cfg *Config, db *AliasDB, kc *Keycloak, cac
}
}
log.Printf("policy request: state=%s sasl=%s sender=%s rcpt=%s client=%s helo=%s", req["protocol_state"], req["sasl_username"], req["sender"], req["recipient"], req["client_address"], req["helo_name"])
// Decide based on protocol_state
state := req["protocol_state"] // e.g. RCPT, MAIL
saslUser := req["sasl_username"]
@@ -110,19 +114,28 @@ func handlePolicyConn(conn net.Conn, cfg *Config, db *AliasDB, kc *Keycloak, cac
switch state {
case "RCPT":
action = policyRCPT(cfg, db, kc, cache, rcpt)
case "MAIL":
// On MAIL stage we can validate sender if authenticated (submission)
if saslUser != "" && sender != "" {
if action == "DUNNO" {
action = policyMAIL(cfg, db, kc, cache, saslUser, sender)
}
case "MAIL":
// With "smtpd_delay_reject = yes" in Postfix, MAIL stage is bypassed
// So we move all checks to RCPT stage
action = "DUNNO"
// On MAIL stage we can validate sender if authenticated (submission)
//if saslUser != "" && sender != "" {
// action = policyMAIL(cfg, db, kc, cache, saslUser, sender)
//}
default:
action = "DUNNO"
}
log.Printf("policy decision: state=%s action=%s sasl=%s sender=%s rcpt=%s", state, action, saslUser, sender, rcpt)
fmt.Fprintf(conn, "action=%s\n\n", action)
}
func policyRCPT(cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, rcpt string) string {
func policyRCPT(cfg *Config, db *MailcloakDB, kc *Keycloak, cache *Cache, rcpt string) string {
if rcpt == "" {
return "DUNNO"
}
@@ -142,6 +155,7 @@ func policyRCPT(cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, rcpt strin
defer cancel()
exists, err := kc.EmailExists(ctx, rcpt)
if err != nil {
log.Printf("keycloak email exists lookup error for %s: %v", rcpt, err)
if cfg.Policy.KeycloakFailureMode == "dunno" {
return "DUNNO"
}
@@ -166,7 +180,7 @@ func policyRCPT(cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, rcpt strin
return "550 5.1.1 No such user"
}
func policyMAIL(cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, saslUser, sender string) string {
func policyMAIL(cfg *Config, db *MailcloakDB, kc *Keycloak, cache *Cache, saslUser, sender string) string {
// Allow empty sender (bounce)
if sender == "" || sender == "<>" {
return "DUNNO"
@@ -184,6 +198,7 @@ func policyMAIL(cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, saslUser,
defer cancel()
e, exists, err := kc.EmailByUsername(ctx, saslUser)
if err != nil {
log.Printf("keycloak email-by-username lookup error for %s: %v", saslUser, err)
if cfg.Policy.KeycloakFailureMode == "dunno" {
return "DUNNO"
}
@@ -208,5 +223,17 @@ func policyMAIL(cfg *Config, db *AliasDB, kc *Keycloak, cache *Cache, saslUser,
return "DUNNO"
}
// 3) sender is allowed for app (saslUser = app_id)
if saslUser != "" {
allowed, err := db.AppFromAllowed(saslUser, sender)
if err != nil {
log.Printf("sqlite app sender lookup error: %v", err)
return "451 4.3.0 Temporary internal error"
}
if allowed {
return "DUNNO"
}
}
return "553 5.7.1 Sender not owned by authenticated user"
}

View File

@@ -2,6 +2,7 @@ package mailcloak
import (
"fmt"
"log"
"os"
"os/user"
"strconv"
@@ -29,6 +30,7 @@ func DropPrivileges(cfg *Config) error {
euid := os.Geteuid()
if euid == uid {
log.Printf("privileges: already running as %s", userName)
return nil
}
if euid != 0 {
@@ -56,5 +58,7 @@ func DropPrivileges(cfg *Config) error {
return fmt.Errorf("setuid: %w", err)
}
log.Printf("privileges: dropped to %s (uid=%d gid=%d)", userName, uid, gid)
return nil
}

View File

@@ -2,6 +2,7 @@ package mailcloak
import (
"fmt"
"log"
"os"
"os/user"
"strconv"
@@ -27,5 +28,6 @@ func ChownChmodSocket(path string, cfg *Config) error {
if err != nil {
return fmt.Errorf("bad socket_mode: %w", err)
}
log.Printf("socket perms: chown %s:%s mode %s on %s", cfg.Sockets.SocketOwnerUser, cfg.Sockets.SocketOwnerGroup, cfg.Sockets.SocketMode, path)
return os.Chmod(path, os.FileMode(mode))
}

View File

@@ -3,8 +3,10 @@ package mailcloak
import (
"bufio"
"context"
"errors"
"fmt"
"io"
"log"
"net"
"os"
"strconv"
@@ -24,11 +26,12 @@ func OpenSocketmapListener(cfg *Config) (net.Listener, error) {
_ = l.Close()
return nil, err
}
log.Printf("socketmap listener ready on %s", sock)
return l, nil
}
func ServeSocketmap(ctx context.Context, cfg *Config, db *AliasDB, l net.Listener) error {
func ServeSocketmap(ctx context.Context, cfg *Config, db *MailcloakDB, l net.Listener) error {
defer l.Close()
for {
@@ -38,6 +41,7 @@ func ServeSocketmap(ctx context.Context, cfg *Config, db *AliasDB, l net.Listene
case <-ctx.Done():
return nil
default:
log.Printf("socketmap accept error: %v", err)
return err
}
}
@@ -45,7 +49,7 @@ func ServeSocketmap(ctx context.Context, cfg *Config, db *AliasDB, l net.Listene
}
}
func RunSocketmap(ctx context.Context, cfg *Config, db *AliasDB) error {
func RunSocketmap(ctx context.Context, cfg *Config, db *MailcloakDB) error {
l, err := OpenSocketmapListener(cfg)
if err != nil {
return err
@@ -54,33 +58,40 @@ func RunSocketmap(ctx context.Context, cfg *Config, db *AliasDB) error {
}
// Postfix socketmap framing: "<len>:<payload>,"
func handleSocketmapConn(conn net.Conn, cfg *Config, db *AliasDB) {
func handleSocketmapConn(conn net.Conn, cfg *Config, db *MailcloakDB) {
defer conn.Close()
r := bufio.NewReader(conn)
for {
payload, err := readSocketmapFrame(r)
if err != nil {
if !errors.Is(err, io.EOF) && !errors.Is(err, io.ErrUnexpectedEOF) {
log.Printf("socketmap read error: %v", err)
}
// normal close
return
}
payload = strings.TrimSpace(payload)
if payload == "" {
log.Printf("socketmap request: empty payload")
_ = writeSocketmapFrame(conn, "NOTFOUND")
continue
}
parts := strings.SplitN(payload, " ", 2)
if len(parts) != 2 {
log.Printf("socketmap request: malformed payload=%q", payload)
_ = writeSocketmapFrame(conn, "TEMP")
continue
}
mapName := parts[0]
key := strings.ToLower(strings.TrimSpace(parts[1]))
log.Printf("socketmap request: map=%s key=%s", mapName, key)
if mapName != "alias" {
log.Printf("socketmap decision: map=%s action=NOTFOUND", mapName)
_ = writeSocketmapFrame(conn, "NOTFOUND")
continue
}
@@ -88,22 +99,27 @@ func handleSocketmapConn(conn net.Conn, cfg *Config, db *AliasDB) {
// Only handle our domain
domain := strings.ToLower(cfg.Policy.Domain)
if !strings.HasSuffix(key, "@"+domain) {
log.Printf("socketmap decision: map=alias key=%s action=NOTFOUND (other domain)", key)
_ = writeSocketmapFrame(conn, "NOTFOUND")
continue
}
username, ok, err := db.AliasOwner(key)
if err != nil {
log.Printf("socketmap db error: key=%s err=%v", key, err)
_ = writeSocketmapFrame(conn, "TEMP")
continue
}
if !ok {
log.Printf("socketmap decision: map=alias key=%s action=NOTFOUND", key)
_ = writeSocketmapFrame(conn, "NOTFOUND")
continue
}
// rewrite alias -> username@domain
_ = writeSocketmapFrame(conn, fmt.Sprintf("OK %s@%s", username, domain))
reply := fmt.Sprintf("OK %s@%s", username, domain)
log.Printf("socketmap decision: map=alias key=%s action=%s", key, reply)
_ = writeSocketmapFrame(conn, reply)
}
}

View File

@@ -3,50 +3,43 @@ package mailcloak
import (
"database/sql"
"fmt"
"log"
"os"
"path/filepath"
"strings"
_ "modernc.org/sqlite"
)
type AliasDB struct{ DB *sql.DB }
type MailcloakDB struct{ DB *sql.DB }
func OpenMailcloakDB(path string) (*MailcloakDB, error) {
log.Printf("sqlite: opening db at %s", path)
if err := ensureDBExists(path); err != nil {
return nil, err
}
func OpenAliasDB(path string) (*AliasDB, error) {
db, err := sql.Open("sqlite", path)
if err != nil {
return nil, err
}
if _, err := db.Exec(`
PRAGMA foreign_keys=ON;
CREATE TABLE IF NOT EXISTS aliases (
alias_email TEXT PRIMARY KEY,
username TEXT NOT NULL,
enabled INTEGER NOT NULL DEFAULT 1,
updated_at INTEGER NOT NULL DEFAULT (strftime('%s','now'))
);
CREATE INDEX IF NOT EXISTS idx_aliases_username ON aliases(username);
CREATE TABLE IF NOT EXISTS apps (
app_id TEXT PRIMARY KEY,
secret_hash TEXT NOT NULL,
enabled INTEGER NOT NULL DEFAULT 1,
created_at INTEGER NOT NULL
);
CREATE TABLE IF NOT EXISTS app_from (
app_id TEXT NOT NULL,
from_addr TEXT NOT NULL,
enabled INTEGER NOT NULL DEFAULT 1,
PRIMARY KEY (app_id, from_addr),
FOREIGN KEY (app_id) REFERENCES apps(app_id) ON DELETE CASCADE
);
PRAGMA journal_mode=WAL;
PRAGMA synchronous=NORMAL;
`); err != nil {
_ = db.Close()
return nil, fmt.Errorf("init schema: %w", err)
return nil, fmt.Errorf("init pragmas: %w", err)
}
return &AliasDB{DB: db}, nil
log.Printf("sqlite: db ready")
return &MailcloakDB{DB: db}, nil
}
func (a *AliasDB) Close() error { return a.DB.Close() }
func (a *MailcloakDB) Close() error { return a.DB.Close() }
// Returns username owning alias, ok
func (a *AliasDB) AliasOwner(aliasEmail string) (string, bool, error) {
func (a *MailcloakDB) AliasOwner(aliasEmail string) (string, bool, error) {
var username string
var enabled int
err := a.DB.QueryRow(`SELECT username, enabled FROM aliases WHERE alias_email=?`, aliasEmail).Scan(&username, &enabled)
@@ -63,7 +56,7 @@ func (a *AliasDB) AliasOwner(aliasEmail string) (string, bool, error) {
}
// Returns true if alias belongs to username
func (a *AliasDB) AliasBelongsTo(aliasEmail, username string) (bool, error) {
func (a *MailcloakDB) AliasBelongsTo(aliasEmail, username string) (bool, error) {
var enabled int
err := a.DB.QueryRow(`SELECT enabled FROM aliases WHERE alias_email=? AND username=?`, aliasEmail, username).Scan(&enabled)
if err == sql.ErrNoRows {
@@ -74,3 +67,53 @@ func (a *AliasDB) AliasBelongsTo(aliasEmail, username string) (bool, error) {
}
return enabled == 1, nil
}
// Returns true if app_id is enabled and sender is allowed for app
func (a *MailcloakDB) AppFromAllowed(appID, fromAddr string) (bool, error) {
var appEnabled int
var fromEnabled int
err := a.DB.QueryRow(`
SELECT a.enabled, af.enabled
FROM app_from af
JOIN apps a ON a.app_id = af.app_id
WHERE af.app_id=? AND af.from_addr=?`, appID, fromAddr).Scan(&appEnabled, &fromEnabled)
if err == sql.ErrNoRows {
return false, nil
}
if err != nil {
return false, err
}
return appEnabled == 1 && fromEnabled == 1, nil
}
func ensureDBExists(path string) error {
if path == ":memory:" || strings.HasPrefix(path, "file:") {
return nil
}
if path == "" {
return fmt.Errorf("sqlite path is empty")
}
dir := filepath.Dir(path)
if dir == "." || dir == "" {
if _, err := os.Stat(path); err != nil {
if os.IsNotExist(err) {
return fmt.Errorf("sqlite db not found at %s; create it with 'mailcloakctl init'", path)
}
return err
}
return nil
}
if _, err := os.Stat(dir); err != nil {
if os.IsNotExist(err) {
return fmt.Errorf("sqlite db directory not found at %s; create the db with 'mailcloakctl init'", dir)
}
return err
}
if _, err := os.Stat(path); err != nil {
if os.IsNotExist(err) {
return fmt.Errorf("sqlite db not found at %s; create it with 'mailcloakctl init'", path)
}
return err
}
return nil
}