Getting 451 soft rejections on incoming emails with v3.0.4

[DoobleD]

Hi,

We're currently testing v3.0.4 and getting 451 errors on incoming emails, but can't figure out why.

The rejection message appears empty, we're just getting the 451 code and the ID, e.g.:

[NOTICE] [core] queue code=CONT msg=" (BB3E0490-E92C-410E-A87A-698FCF6D332A.1)"
[PROTOCOL] [core] S: 451  (BB3E0490-E92C-410E-A87A-698FCF6D332A.1)

• There appears to be 2 spaces between the error code and the open bracket containing the ID, as if the specific reason was an empty string.
• The rejection doesn't appear to be due to a DENYSOFTDISCONNECT, because the connection is not closed right away.
• Subsequent delivery attempts from the sending SMTP server also end up in the same 451 error.
• We see nothing is the logs that mentions what could be the core part or plugin or reason for this rejection.
• We tried adding a plugin with a deny hook to identify what plugin is causing this if any, but the hook is never called. I suppose this is consistent with the fact that according to the log line the rejection comes from core.

Anybody else experiencing this? Any idea to identify the reason?

[msimerson]

Please add some additional log messages around the errors for context. Also, include a list of what plugins you are running.

[DoobleD]

Thank you @msimerson. I have removed all plugins except a dead simple hook_rcpt one that simply does next(OK), and here is the full log:

[DEBUG] [-] [core] addOCSP: 'ocsp' not available
[NOTICE] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] connect ip=209.85.160.48 port=52514 local_ip=<obfuscated> local_port=25
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] running connect_init hooks
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] running connect_init_respond
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] running lookup_rdns hooks
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] running connect hooks
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] S: 220 <obfuscated> ESMTP Haraka/3.0.4 ready
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] C: EHLO mail-oa1-f48.google.com state=1
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] running ehlo hooks
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] running capabilities hooks
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] S: 250-<obfuscated> Hello mail-oa1-f48.google.com [209.85.160.48], , <obfuscated> is at your service
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] S: 250-PIPELINING
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] S: 250-8BITMIME
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] S: 250-SMTPUTF8
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] S: 250 SIZE 36700160
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B] [core] C: MAIL FROM:<<obfuscated>@gmail.com> SIZE=3348 state=1
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running mail hooks
[NOTICE] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] sender <<obfuscated>@gmail.com> code=CONT msg=""
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] S: 250 sender <<obfuscated>@gmail.com> OK
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] C: RCPT TO:<obfuscated> state=1
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running rcpt hooks
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running rcpt hook in rcpt_plugin plugin
[INFO] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core]  hook=rcpt plugin=rcpt_plugin function=hook_rcpt params=<obfuscated> retval=OK msg=""
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running rcpt_ok hooks
[NOTICE] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] recipient <obfuscated> code=OK msg="" sender=<obfuscated>@gmail.com
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] S: 250 recipient <obfuscated> OK
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] C: DATA state=1
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running data hooks
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] S: 354 go ahead, make my day
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running data_post hooks
[NOTICE] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] message mid="<CAEfn5bKCW9M3C-uNs=vqwu5vaPPLTOaCcGdh6i7TQVoOAjLp5Q@mail.gmail.com>" size=3351 rcpts=1/0/0 delay=0.001 code=CONT msg=""
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running queue hooks
[NOTICE] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] queue code=CONT msg=" (330383EA-FABA-4C76-BAED-32998C622A3B.1)"
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] S: 451  (330383EA-FABA-4C76-BAED-32998C622A3B.1)
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running reset_transaction hooks
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] C: QUIT state=1
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running quit hooks
[PROTOCOL] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] S: 221 <obfuscated> closing connection. Have a jolly good day.
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] client has disconnected
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] running disconnect hooks
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] client has disconnected
[DEBUG] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] client has disconnected
[NOTICE] [330383EA-FABA-4C76-BAED-32998C622A3B.1] [core] disconnect ip=209.85.160.48 rdns=mail-oa1-f48.google.com helo=mail-oa1-f48.google.com relay=N early=N esmtp=Y tls=N pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=0/1/0 bytes=3351 lr="451  (330383EA-FABA-4C76-BAED-32998C622A3B.1)" time=0.159

Rcpt plugin:

'use strict';

exports.hook_rcpt = async function (next, connection, params) {
    return next(OK);
};

[DoobleD]

I also tried adding a hook_deny to that same no real plugin version:

exports.hook_deny = function (next, connection, params) {
    connection.loginfo(this, `HOOK DENY ${JSON.stringify(params)}`);
}

$ grep deny /var/log/haraka/test.log 
[DEBUG] [-] [plugins] registered hook deny to deny_plugin.hook_deny priority 0

But the additional logging doesn't show up in the logs.

[DoobleD]

I can actually reproduce it with 3.0.3 as well with that no real plugin setup, whereas 3.0.3 works fine with our usual setup and 3.0.4 produces the unidentified 451.

[DoobleD]

Okay, I think I pinned it. When I introduced queue/lmtp back to the plugins of the minimal test setup, I could reproduce the difference in behavior between 3.0.3 and 3.0.4.

In 3.0.3, queue/lmtp returns OK, whereas in 3.0.4 it returns CONT. This is due to this change:

In my tests, txn.notes.get('queue.wants') is undefined, which in the previous version wouldn't satisfy the condition, but in the new version does.

[msimerson]

I see that. That change wasn't intentional. Would you like to create the PR to revert it or shall I?

[DoobleD]

I see that. That change wasn't intentional. Would you like to create the PR to revert it or shall I?

It might be best that you do it, as I'm unsure of the process in this case since it may need to be backported to 3.0.4 or be in a new fix release?

[msimerson]

@DoobleD , please review #3407

Thanks.

[DoobleD]

Looks good. Thanks @msimerson!