Skip to content

Commit

Permalink
smtpserver: when logging recipients, actually show something about th…
Browse files Browse the repository at this point in the history 
…e recipient

before this change, we were logging an empty string, which turned into "[]",
looking like an empty array. misleading and unhelpful.

this is fixed by making struct fields on type recipient "exported" so they can
get logged, and by changing the logging code to log nested
struct/pointer/interface fields if we would otherwise wouldn't log anything
(when only logging more basic data types).

we'll now get log lines like:

	l=info m="deliver attempt to unknown user(s)" pkg=smtpserver recipients="[[email protected]]"

for issue #232 by snabb, thanks for reporting!
  • Loading branch information
@mjl-
mjl- committed Nov 1, 2024
1 parent 879477a commit 598c5ea
Show file tree
Hide file tree
Showing 2 changed files with 66 additions and 56 deletions.
50 changes: 30 additions & 20 deletions mlog/log.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -426,29 +426,39 @@ func stringValue(iscid, nested bool, v any) string {
}
n := rv.NumField()
t := rv.Type()
b := &strings.Builder{}
first := true
for i := 0; i < n; i++ {
fv := rv.Field(i)
if !t.Field(i).IsExported() {
continue
}
if fv.Kind() == reflect.Struct || fv.Kind() == reflect.Ptr || fv.Kind() == reflect.Interface {
// Don't recurse.
continue
}
vs := stringValue(false, true, fv.Interface())
if vs == "" {
continue

// We first try making a string without recursing into structs/pointers/interfaces,
// but will try again with those fields if we otherwise would otherwise log an
// empty string.
for j := 0; j < 2; j++ {
first := true
b := &strings.Builder{}
for i := 0; i < n; i++ {
fv := rv.Field(i)
if !t.Field(i).IsExported() {
continue
}
if j == 0 && (fv.Kind() == reflect.Struct || fv.Kind() == reflect.Ptr || fv.Kind() == reflect.Interface) {
// Don't recurse.
continue
}
vs := stringValue(false, true, fv.Interface())
if vs == "" {
continue
}
if !first {
b.WriteByte(' ')
}
first = false
k := strings.ToLower(t.Field(i).Name)
b.WriteString(k + "=" + vs)
}
if !first {
b.WriteByte(' ')
rs := b.String()
if rs != "" {
return rs
}
first = false
k := strings.ToLower(t.Field(i).Name)
b.WriteString(k + "=" + vs)
}
return b.String()
return ""
}

func writeAttr(w io.Writer, separator, group string, a slog.Attr) {
Expand Down
72 changes: 36 additions & 36 deletions smtpserver/server.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -344,24 +344,24 @@ type conn struct {
}

type rcptAccount struct {
accountName string
destination config.Destination
canonicalAddress string // Optional catchall part stripped and/or lowercased.
AccountName string
Destination config.Destination
CanonicalAddress string // Optional catchall part stripped and/or lowercased.
}

type rcptAlias struct {
alias config.Alias
canonicalAddress string // Optional catchall part stripped and/or lowercased.
Alias config.Alias
CanonicalAddress string // Optional catchall part stripped and/or lowercased.
}

type recipient struct {
addr smtp.Path
Addr smtp.Path

// If account and alias are both not set, this is not for a local address. This is
// normal for submission, where messages are added to the queue. For incoming
// deliveries, this will result in an error.
account *rcptAccount // If set, recipient address is for this local account.
alias *rcptAlias // If set, for a local alias.
Account *rcptAccount // If set, recipient address is for this local account.
Alias *rcptAlias // If set, for a local alias.
}

func isClosed(err error) bool {
Expand Down Expand Up @@ -1732,7 +1732,7 @@ func (c *conn) isSMTPUTF8Required(part *message.Part) bool {
}
// Check all "RCPT TO".
for _, rcpt := range c.recipients {
if hasNonASCII(strings.NewReader(string(rcpt.addr.Localpart))) {
if hasNonASCII(strings.NewReader(string(rcpt.Addr.Localpart))) {
return true
}
}
Expand Down Expand Up @@ -2037,7 +2037,7 @@ func (c *conn) submit(ctx context.Context, recvHdrFor func(string) string, msgWr
err = c.account.DB.Read(ctx, func(tx *bstore.Tx) error {
rcpts := make([]smtp.Path, len(c.recipients))
for i, r := range c.recipients {
rcpts[i] = r.addr
rcpts[i] = r.Addr
}
msglimit, rcptlimit, err := c.account.SendLimitReached(tx, rcpts)
xcheckf(err, "checking sender limit")
Expand Down Expand Up @@ -2136,7 +2136,7 @@ func (c *conn) submit(ctx context.Context, recvHdrFor func(string) string, msgWr
qml := make([]queue.Msg, len(c.recipients))
for i, rcpt := range c.recipients {
if Localserve {
code, timeout := mox.LocalserveNeedsError(rcpt.addr.Localpart)
code, timeout := mox.LocalserveNeedsError(rcpt.Addr.Localpart)
if timeout {
c.log.Info("timing out submission due to special localpart")
mox.Sleep(mox.Context, time.Hour)
Expand All @@ -2160,11 +2160,11 @@ func (c *conn) submit(ctx context.Context, recvHdrFor func(string) string, msgWr
// messages in a single smtp transaction.
var rcptTo string
if len(c.recipients) == 1 {
rcptTo = rcpt.addr.String()
rcptTo = rcpt.Addr.String()
}
xmsgPrefix := append([]byte(recvHdrFor(rcptTo)), msgPrefix...)
msgSize := int64(len(xmsgPrefix)) + msgWriter.Size
qm := queue.MakeMsg(fp, rcpt.addr, msgWriter.Has8bit, c.msgsmtputf8, msgSize, messageID, xmsgPrefix, c.requireTLS, now, header.Get("Subject"))
qm := queue.MakeMsg(fp, rcpt.Addr, msgWriter.Has8bit, c.msgsmtputf8, msgSize, messageID, xmsgPrefix, c.requireTLS, now, header.Get("Subject"))
if !c.futureRelease.IsZero() {
qm.NextAttempt = c.futureRelease
qm.FutureReleaseRequest = c.futureReleaseRequest
Expand All @@ -2190,15 +2190,15 @@ func (c *conn) submit(ctx context.Context, recvHdrFor func(string) string, msgWr
for i, rcpt := range c.recipients {
c.log.Info("messages queued for delivery",
slog.Any("mailfrom", *c.mailFrom),
slog.Any("rcptto", rcpt.addr),
slog.Any("rcptto", rcpt.Addr),
slog.Bool("smtputf8", c.smtputf8),
slog.Bool("msgsmtputf8", c.msgsmtputf8),
slog.Int64("msgsize", qml[i].Size))
}

err = c.account.DB.Write(ctx, func(tx *bstore.Tx) error {
for _, rcpt := range c.recipients {
outgoing := store.Outgoing{Recipient: rcpt.addr.XString(true)}
outgoing := store.Outgoing{Recipient: rcpt.Addr.XString(true)}
if err := tx.Insert(&outgoing); err != nil {
return fmt.Errorf("adding outgoing message: %v", err)
}
Expand Down Expand Up @@ -2418,7 +2418,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// Give immediate response if all recipients are unknown.
nunknown := 0
for _, r := range c.recipients {
if r.account == nil && r.alias == nil {
if r.Account == nil && r.Alias == nil {
nunknown++
}
}
Expand Down Expand Up @@ -2653,7 +2653,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
}
var deliverErrors []deliverError
addError := func(rcpt recipient, code int, secode string, userError bool, errmsg string) {
e := deliverError{rcpt.addr, code, secode, userError, errmsg}
e := deliverError{rcpt.Addr, code, secode, userError, errmsg}
c.log.Info("deliver error",
slog.Any("rcptto", e.rcptTo),
slog.Int("code", code),
Expand All @@ -2666,9 +2666,9 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// Sort recipients: local accounts, aliases, unknown. For ensuring we don't deliver
// to an alias destination that was also explicitly sent to.
rcptScore := func(r recipient) int {
if r.account != nil {
if r.Account != nil {
return 0
} else if r.alias != nil {
} else if r.Alias != nil {
return 1
}
return 2
Expand All @@ -2682,9 +2682,9 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// addressee. Relies on c.recipients being sorted as above.
regularRecipient := func(addr smtp.Path) bool {
for _, rcpt := range c.recipients {
if rcpt.account == nil {
if rcpt.Account == nil {
break
} else if rcpt.addr.Equal(addr) {
} else if rcpt.Addr.Equal(addr) {
return true
}
}
Expand Down Expand Up @@ -2761,7 +2761,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// we will consider a message delivered if we delivered it to at least one account
// (others may be over quota).
processRecipient := func(rcpt recipient) {
log := c.log.With(slog.Any("mailfrom", c.mailFrom), slog.Any("rcptto", rcpt.addr))
log := c.log.With(slog.Any("mailfrom", c.mailFrom), slog.Any("rcptto", rcpt.Addr))

// If this is not a valid local user, we send back a DSN. This can only happen when
// there are also valid recipients, and only when remote is SPF-verified, so the DSN
Expand All @@ -2771,7 +2771,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// deliveries, and return an error at the end? Though the failure conditions will
// probably prevent any other successful deliveries too...
// We'll continue delivering to other recipients. ../rfc/5321:3275
if rcpt.account == nil && rcpt.alias == nil {
if rcpt.Account == nil && rcpt.Alias == nil {
metricDelivery.WithLabelValues("unknownuser", "").Inc()
addError(rcpt, smtp.C550MailboxUnavail, smtp.SeAddr1UnknownDestMailbox1, true, "no such user")
return
Expand All @@ -2792,17 +2792,17 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// check. We check all alias destinations, even if we already explicitly delivered
// to them: they may be the only destination that would accept the message.
var a0 *analysis // Analysis we've used for accept/reject decision.
if rcpt.alias != nil {
if rcpt.Alias != nil {
// Check if msgFrom address is acceptable. This doesn't take validation into
// consideration. If the header was forged, the message may be rejected later on.
if !aliasAllowedMsgFrom(rcpt.alias.alias, msgFrom) {
if !aliasAllowedMsgFrom(rcpt.Alias.Alias, msgFrom) {
addError(rcpt, smtp.C550MailboxUnavail, smtp.SePol7ExpnProhibited2, true, "not allowed to send to destination")
return
}

la = make([]analysis, 0, len(rcpt.alias.alias.ParsedAddresses))
for _, aa := range rcpt.alias.alias.ParsedAddresses {
a, err := messageAnalyze(log, rcpt.addr, aa.Address.Path(), aa.AccountName, aa.Destination, rcpt.alias.canonicalAddress)
la = make([]analysis, 0, len(rcpt.Alias.Alias.ParsedAddresses))
for _, aa := range rcpt.Alias.Alias.ParsedAddresses {
a, err := messageAnalyze(log, rcpt.Addr, aa.Address.Path(), aa.AccountName, aa.Destination, rcpt.Alias.CanonicalAddress)
if err != nil {
addError(rcpt, smtp.C451LocalErr, smtp.SeSys3Other0, false, "error processing")
return
Expand All @@ -2818,7 +2818,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
a0 = &la[0]
}
} else {
a, err := messageAnalyze(log, rcpt.addr, rcpt.addr, rcpt.account.accountName, rcpt.account.destination, rcpt.account.canonicalAddress)
a, err := messageAnalyze(log, rcpt.Addr, rcpt.Addr, rcpt.Account.AccountName, rcpt.Account.Destination, rcpt.Account.CanonicalAddress)
if err != nil {
addError(rcpt, smtp.C451LocalErr, smtp.SeSys3Other0, false, "error processing")
return
Expand Down Expand Up @@ -2893,7 +2893,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
"Return-Path: <" + c.mailFrom.String() + ">\r\n" + // ../rfc/5321:3300
rcptAuthResults.Header() +
receivedSPF.Header() +
recvHdrFor(rcpt.addr.String()),
recvHdrFor(rcpt.Addr.String()),
)
la[i].d.m.Size += int64(len(la[i].d.m.MsgPrefix))
}
Expand Down Expand Up @@ -2986,7 +2986,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
Disposition: disposition,
AlignedDKIMPass: dmarcResult.AlignedDKIMPass,
AlignedSPFPass: dmarcResult.AlignedSPFPass,
EnvelopeTo: rcpt.addr.IPDomain.String(),
EnvelopeTo: rcpt.Addr.IPDomain.String(),
EnvelopeFrom: c.mailFrom.IPDomain.String(),
HeaderFrom: msgFrom.Domain.Name(),
}
Expand Down Expand Up @@ -3034,7 +3034,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
if !a0.accept {
for _, a := range la {
// Don't add message if address was also explicitly present in a RCPT TO command.
if rcpt.alias != nil && regularRecipient(a.d.deliverTo) {
if rcpt.Alias != nil && regularRecipient(a.d.deliverTo) {
continue
}

Expand Down Expand Up @@ -3084,7 +3084,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
}

delayFirstTime := true
if rcpt.account != nil && a0.dmarcReport != nil {
if rcpt.Account != nil && a0.dmarcReport != nil {
// todo future: add rate limiting to prevent DoS attacks. ../rfc/7489:2570
if err := dmarcdb.AddReport(ctx, a0.dmarcReport, msgFrom.Domain); err != nil {
log.Errorx("saving dmarc aggregate report in database", err)
Expand All @@ -3094,7 +3094,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
delayFirstTime = false
}
}
if rcpt.account != nil && a0.tlsReport != nil {
if rcpt.Account != nil && a0.tlsReport != nil {
// todo future: add rate limiting to prevent DoS attacks.
if err := tlsrptdb.AddReport(ctx, c.log, msgFrom.Domain, c.mailFrom.String(), a0.d.destination.HostTLSReports, a0.tlsReport); err != nil {
log.Errorx("saving TLSRPT report in database", err)
Expand All @@ -3115,7 +3115,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
}

if Localserve {
code, timeout := mox.LocalserveNeedsError(rcpt.addr.Localpart)
code, timeout := mox.LocalserveNeedsError(rcpt.Addr.Localpart)
if timeout {
log.Info("timing out due to special localpart")
mox.Sleep(mox.Context, time.Hour)
Expand Down Expand Up @@ -3147,7 +3147,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
for _, a := range la {
// Don't deliver to recipient that was explicitly present in SMTP transaction, or
// is sending the message to an alias they are member of.
if rcpt.alias != nil && (regularRecipient(a.d.deliverTo) || a.d.deliverTo.Equal(msgFrom.Path())) {
if rcpt.Alias != nil && (regularRecipient(a.d.deliverTo) || a.d.deliverTo.Equal(msgFrom.Path())) {
continue
}

Expand Down

0 comments on commit 598c5ea

Please sign in to comment.