Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

What's the best place to log final response? #13

Open
iredmail opened this issue Sep 14, 2023 · 8 comments · May be fixed by #17
Open

What's the best place to log final response? #13

iredmail opened this issue Sep 14, 2023 · 8 comments · May be fixed by #17

Comments

@iredmail
Copy link

I tried to log final response of processed message inAbort(), Cleanup(), but they both got called 2 or more times for one message.

So the question is, where should i log final response of processed message? and it should be called only once.

@d--j
Copy link
Owner

d--j commented Sep 14, 2023

Cleanup() ist the right place. Abort() e.g. also gets called after the client of the MTA sessions issued a STARTTLS so not at the end of the transaction.

Cleanup() might in deed be called multiple times – but it is guranteed to be at least called once for each SMTP transaction. Since your milter backend is only valid for one transaction, just set a boolean

func (b *MyBackend) Cleanup() {
  if b.cleanupCalled {
    return
  }
  b.cleanupCalled = true
  // do cleanup
}

@iredmail
Copy link
Author

Thanks for the suggestion.
Is it better add a new method to be called ONCE after processed?

@d--j
Copy link
Owner

d--j commented Sep 14, 2023

On second thought, Cleanup() is called at the end of the SMTP session (or when a SMFIC_QUIT_NC message is sent, or when the connection to the MTA fails). An SMTP session can have multiple messages.

So Cleanup() could log that the SMTP session has ended, but not that a single message has been processed.

The start and end of a message has to be figured out in the Milter backend. Have a look at https://github.com/d--j/go-milter/blob/main/mailfilter/backend.go to see how the mailfilter Backend does this.

Cleanup() is for cleaning up resources you may have opened for this SMTP transaction, e.g.:

func (t *transaction) cleanup() {
t.headers = nil
t.origHeaders = nil
t.rcptTos = nil
t.origRcptTos = nil
t.quarantineReason = nil
t.closeReplacementBody()
if t.body != nil {
_ = t.body.Close()
t.body = nil
}
}

@iredmail
Copy link
Author

iredmail commented Sep 15, 2023

Can we add a new method which will be called ONCE after a single message has been processed?

For easy maintenance and troubleshooting, Milter server must log the final response and basic info of each message, so this method will be very neat and make milter development easier. :)

Maybe one more method for end of smtp transaction (and called just once)?

@iredmail
Copy link
Author

iredmail commented Sep 15, 2023

Checked session.go, Cleanup() is called in 4 places:

  1. case wire.CodeQuitNewConn:

    go-milter/session.go

    Lines 308 to 310 in 115badd

    case wire.CodeQuitNewConn:
    // abort current connection and start over
    m.backend.Cleanup()
  2. case wire.CodeQuit:

    go-milter/session.go

    Lines 316 to 317 in 115badd

    case wire.CodeQuit:
    m.backend.Cleanup()
  3. !resp.Continue():

    go-milter/session.go

    Lines 393 to 394 in 115badd

    if !resp.Continue() {
    m.backend.Cleanup()
  4. m.backend != nil:

    go-milter/session.go

    Lines 329 to 333 in 115badd

    func (m *serverSession) HandleMilterCommands() {
    defer func() {
    if m.backend != nil {
    m.backend.Cleanup()
    }

Seems none of them can precisely match each processed message.
I suggest adding a new method to be called at the end of each processed message.

@d--j
Copy link
Owner

d--j commented Sep 18, 2023

Sorry for beeing a little bit slow in understanding – can you explain why you need something other than EndOfMessage()?

go-milter/server.go

Lines 69 to 75 in 30d4d62

// EndOfMessage is called at the end of each message. All changes to message's
// content & attributes must be done here.
// The MTA can start over with another message in the same connection but that is handled in a new Milter instance.
//
// If this method returns an error the error will be logged and the connection will be closed.
// If there is a [Response] this response will be sent before closing the connection.
EndOfMessage(m *Modifier) (*Response, error)

In case the milter backend opts to reject the message before this callback, the milter backend already knows that the current message has ended, why should the serverSession need to tell the backend what the backend already told it?

@iredmail
Copy link
Author

iredmail commented Sep 19, 2023

EndOfMessage is not applicable at all, for example:

  • client sends AUTH command but login failed, client (or Postfix) disconnects.
  • client successfully login and send further SMTP commands, but Postfix rejects it due to, e.g. blacklisted or greylisted.
  • Milter plugin rejects message in either Connect, Helo, MailFrom, RcptTo state.

There's no email message submitted at all, hence it doesn't go through EndOfMessage, so it doesn't trigger the logging.

@d--j d--j linked a pull request Oct 6, 2023 that will close this issue
@d--j
Copy link
Owner

d--j commented Oct 6, 2023

Hello @iredmail

Please have a look at PR #17 – I introduced a new method ConnectionClosed that gets called when the the connection to the MTA was closed. Hopefully this might be useful for your logging purposes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants