Mailing List Archive

Spurious "BDAT command used when CHUNKING not advertised"?
Just recently, starting on May 4th, we began bouncing some messages from
Gmail with the following error:

2022-05-09 15:32:48 H=mail-lj1-x234.google.com
[2a00:1450:4864:20::234]:46864 I=[2620:0:861:3:208:80:154:76]:25
X=TLS1.3:ECDHE_SECP256R1__RSA_PSS_RSAE_SHA256__AES_256_GCM:256 CV=no
F=<translations+caf_=jsoby=wikimedia.org@wikimedia.org> rejected RCPT
<jsoby@wikimedia.org>: Previous (cached) callout verification failure
2022-05-09 15:32:48 SMTP protocol error in "BDAT 18952 LAST"
H=mail-lj1-x234.google.com [2a00:1450:4864:20::234]:46864
I=[2620:0:861:3:208:80:154:76]:25 BDAT command used when CHUNKING not
advertised
2022-05-09 15:32:48 SMTP syntax error in "Received: by
mail-lj1-x234.google.com with SMTP id 16so17499146lju.13"
H=mail-lj1-x234.google.com [2a00:1450:4864:20::234]:46864
I=[2620:0:861:3:208:80:154:76]:25 unrecognized command
2022-05-09 15:32:48 SMTP syntax error in " for
<jsoby@wikimedia.org>; Mon, 09 May 2022 08:32:48 -0700 (PDT)"
H=mail-lj1-x234.google.com [2a00:1450:4864:20::234]:46864
I=[2620:0:861:3:208:80:154:76]:25 unrecognized command
2022-05-09 15:32:48 SMTP syntax error in "X-Google-DKIM-Signature:
v=1; a=rsa-sha256; c=relaxed/relaxed;" H=mail-lj1-x234.google.com
[2a00:1450:4864:20::234]:46864 I=[2620:0:861:3:208:80:154:76]:25
unrecognized command
2022-05-09 15:32:48 SMTP call from mail-lj1-x234.google.com
[2a00:1450:4864:20::234]:46864 I=[2620:0:861:3:208:80:154:76]:25
dropped: too many syntax or protocol errors (last command was
"X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;",
C=EHLO,STARTTLS,EHLO,MAIL,RCPT,BDAT,RSET,NOOP,MAIL,RCPT,BDAT)

We are currently running exim 4.94 on Debian. In trying to understand the root
cause of the issue I noticed a recent commit included in 4.96:

JH/26 Fix CHUNKING on a continued-transport. Previously the usabliility of the
the facility was not passed across execs, and only the first message passed
over a connection could use BDAT; any further ones using DATA.

Is this commit at all related? Is there a chance Gmail changed their sending
behavior?

Any insight is much appreciated, thanks, Jesse Hathaway

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
On Mon, May 9, 2022 at 4:44 PM Jesse Hathaway <jhathaway@wikimedia.org> wrote:
> We are currently running exim 4.94 on Debian. In trying to understand the root
> cause of the issue I noticed a recent commit included in 4.96:

I forgot to mention that disabling chunking stopped the bounces.

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
On 09/05/2022 22:44, Jesse Hathaway via Exim-users wrote:
> Just recently, starting on May 4th, we began bouncing some messages from
> Gmail with the following error:
>
> 2022-05-09 15:32:48 H=mail-lj1-x234.google.com
> [2a00:1450:4864:20::234]:46864 I=[2620:0:861:3:208:80:154:76]:25
> X=TLS1.3:ECDHE_SECP256R1__RSA_PSS_RSAE_SHA256__AES_256_GCM:256 CV=no
> F=<translations+caf_=jsoby=wikimedia.org@wikimedia.org> rejected RCPT
> <jsoby@wikimedia.org>: Previous (cached) callout verification failure

You receiving from G, doing a verify, would have been a callout
but using a cached previous-fail record. Can't tell if R- or S-verify.

What does your config require, for verifies?

> 2022-05-09 15:32:48 SMTP protocol error in "BDAT 18952 LAST"
> H=mail-lj1-x234.google.com [2a00:1450:4864:20::234]:46864
> I=[2620:0:861:3:208:80:154:76]:25 BDAT command used when CHUNKING not
> advertised

You receiving from G, same conn as above. We claim G did
something wrong...

> 2022-05-09 15:32:48 SMTP syntax error in "Received: by
> mail-lj1-x234.google.com with SMTP id 16so17499146lju.13"
> H=mail-lj1-x234.google.com [2a00:1450:4864:20::234]:46864
> I=[2620:0:861:3:208:80:154:76]:25 unrecognized command

Now we're just confused, interpreting message header data
as an SMTP command. We're out-of-sync by now.

> 2022-05-09 15:32:48 SMTP syntax error in " for
> <jsoby@wikimedia.org>; Mon, 09 May 2022 08:32:48 -0700 (PDT)"
> H=mail-lj1-x234.google.com [2a00:1450:4864:20::234]:46864
> I=[2620:0:861:3:208:80:154:76]:25 unrecognized command
> 2022-05-09 15:32:48 SMTP syntax error in "X-Google-DKIM-Signature:
> v=1; a=rsa-sha256; c=relaxed/relaxed;" H=mail-lj1-x234.google.com
> [2a00:1450:4864:20::234]:46864 I=[2620:0:861:3:208:80:154:76]:25
> unrecognized command

ditto

> 2022-05-09 15:32:48 SMTP call from mail-lj1-x234.google.com
> [2a00:1450:4864:20::234]:46864 I=[2620:0:861:3:208:80:154:76]:25
> dropped: too many syntax or protocol errors (last command was
> "X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;",
> C=EHLO,STARTTLS,EHLO,MAIL,RCPT,BDAT,RSET,NOOP,MAIL,RCPT,BDAT)

and we finally recognise that and drop the conn. We recorded
the sequence of SMTP commandss used on the conn; it looks reasonable,
it would be useful to know if this source IP did have a good
message reception immediately before, or not.

If it did, then that reception did use chunking, which implies
we did advertise it - so the later later claim we did not
seems like our bug (exposed by some recent G change).

If it did not... do you think your config *should* be advertising
chunking to G ?

>
> We are currently running exim 4.94 on Debian. In trying to understand the root
> cause of the issue I noticed a recent commit included in 4.96:
>
> JH/26 Fix CHUNKING on a continued-transport. Previously the usabliility of the
> the facility was not passed across execs, and only the first message passed
> over a connection could use BDAT; any further ones using DATA.
>
> Is this commit at all related?

I don't think so. We're looking at receiving from G here, and that
was dealing with sending.

> Is there a chance Gmail changed their sending
> behavior?

Entirely possible. You imply you've see more than one of these.
How often? Are you in a position to build and use 4.96 (we have
neater debug tooling there)?
--
Cheers,
Jeremy

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
On Mon, May 9, 2022 at 5:32 PM Jeremy Harris via Exim-users
<exim-users@exim.org> wrote:
> What does your config require, for verifies?

begin acl:
...snip...
# If the destination domain is a domain we relay for,
# check if the local part exists at the destination,
# reject if it doesn't.
# Accept if the destination cannot be reached within 30s.
deny domains = +relay_domains
! verify = recipient/callout=10s,maxwait=30s,defer_ok

# Check whether the sender address domain exists
require verify = sender

# Gsuite accounts
gsuite_account:
driver = manualroute
domains = wikimedia.org
local_part_suffix = +*
local_part_suffix_optional
transport = remote_smtp
route_list = * aspmx.l.google.com

> and we finally recognise that and drop the conn. We recorded
> the sequence of SMTP commandss used on the conn; it looks reasonable,
> it would be useful to know if this source IP did have a good
> message reception immediately before, or not.

From looking at the logs I don't see any successful receives from that
IP, though we had some successful receives for other IPs, where we
emitted the same error message. One curious piece is that almost all of
the errors are preceded by a similar callout failure:

2022-05-08 19:56:59 H=mail-oa1-x2f.google.com
[2001:4860:4864:20::2f]:41512 I=[2620:0:861:3:208:80:154:76]:25
X=TLS1.3:ECDHE_SECP256R1__RSA_PSS_RSAE_SHA256__AES_256_GCM:256 CV=no
F=<translations+caf_=jsoby=wikimedia.org@wikimedia.org> rejected RCPT
<jsoby@wikimedia.org>: Previous (cached) callout verification failure

> If it did, then that reception did use chunking, which implies
> we did advertise it - so the later later claim we did not
> seems like our bug (exposed by some recent G change).
>
> If it did not... do you think your config *should* be advertising
> chunking to G ?

Yes it was enabled, as we did not override the default, and we verified
with a manual test

> > Is there a chance Gmail changed their sending
> > behavior?
>
> Entirely possible. You imply you've see more than one of these.
> How often? Are you in a position to build and use 4.96 (we have
> neater debug tooling there)?

We were getting a pretty constant rate, until we disabled chunking, e.g.
we had 2466 of these messages on May 8th. I'm happy to test a 4.96
build, just let me know what logging options would be helpful.

Thanks for all the help, Jesse

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
Jesse Hathaway via Exim-users <exim-users@exim.org> writes:

> We were getting a pretty constant rate, until we disabled chunking, e.g.
> we had 2466 of these messages on May 8th. I'm happy to test a 4.96
> build, just let me know what logging options would be helpful.
>
> Thanks for all the help, Jesse

I was getting this too, I neglected to notice this until now but we had
incoming messages bouncing from google at a steady rate for several
days. However, it stopped this morning. The last error was 8:28 eastern
time. I will be monitoring for it to start up again.

Some differences on our system compared to Jesse's report:

* We are running an older exim: 4.90.1-1ubuntu1.8+9.0trisquel4

* Our errors don't correlate with any "Previous (cached) callout
verification failure". We do verify callout, "verify =
sender/callout=60s", and that quoted callout verification log message
appears for some other non-google hosts unrelated to this error.



Example log:

2022-05-11 08:28:15.488 [5010] H=mail-qt1-x835.google.com [2607:f8b0:4864:20::835]:34672 I=[2001:470:142:3::10]:25 X=TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128 CV=no SNI="eggs.gnu.org" F=<edgerhoover776@gmail.com> rejected RCPT <bugstow@gnu.org>: fencepost.gnu.org [2001:470:142:3::e] : SMTP error from remote mail server after RCPT TO:<bugstow@gnu.org>: 550 Unrouteable address
2022-05-11 08:28:15.489 [5010] SMTP protocol error in "BDAT 3927 LAST" H=mail-qt1-x835.google.com [2607:f8b0:4864:20::835]:34672 I=[2001:470:142:3::10]:25 BDAT command used when CHUNKING not advertised
2022-05-11 08:28:15.489 [5010] SMTP syntax error in "Received: by mail-qt1-x835.google.com with SMTP id k2so1833832qtp.1" H=mail-qt1-x835.google.com [2607:f8b0:4864:20::835]:34672 I=[2001:470:142:3::10]:25 unrecognized command
2022-05-11 08:28:15.489 [5010] SMTP syntax error in " for <bugstow@gnu.org>; Wed, 11 May 2022 05:28:13 -0700 (PDT)" H=mail-qt1-x835.google.com [2607:f8b0:4864:20::835]:34672 I=[2001:470:142:3::10]:25 unrecognized command
2022-05-11 08:28:15.489 [5010] SMTP syntax error in "DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;" H=mail-qt1-x835.google.com [2607:f8b0:4864:20::835]:34672 I=[2001:470:142:3::10]:25 unrecognized command
2022-05-11 08:28:15.489 [5010] SMTP call from mail-qt1-x835.google.com [2607:f8b0:4864:20::835]:34672 I=[2001:470:142:3::10]:25 dropped: too many syntax or protocol errors (last command was "DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;")

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
Ian Kelling <iank@fsf.org> writes:

> However, it stopped this morning.

Correction: yesterday morning, May 11th 8:28 eastern.

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
On 12/05/2022 18:45, Ian Kelling wrote:
> * We are running an older exim: 4.90.1-1ubuntu1.8+9.0trisquel4

Well, at least it's not something I broke this year, then...

With 4.96 you can set up speculative debug, using ACL.
Anybody want to try getting a capture?
--
Cheers,
Jeremy

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
On Thu, May 12, 2022 at 5:30 PM Jeremy Harris <jgh@wizmail.org> wrote:
> With 4.96 you can set up speculative debug, using ACL.
> Anybody want to try getting a capture?

Thanks to Jeremy's patch in 462e2cd306 we did not see these errors again
when running a 4.96-RC1 build for a couple of days.

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: Spurious "BDAT command used when CHUNKING not advertised"? [ In reply to ]
Jesse Hathaway via Exim-users <exim-users@exim.org> writes:

> On Thu, May 12, 2022 at 5:30 PM Jeremy Harris <jgh@wizmail.org> wrote:
>> With 4.96 you can set up speculative debug, using ACL.
>> Anybody want to try getting a capture?
>
> Thanks to Jeremy's patch in 462e2cd306 we did not see these errors again
> when running a 4.96-RC1 build for a couple of days.

I didn't change my exim, hoping google had fixed whatever they were
doing, but they started causing the error again recently.

I chose to disabled BDAT rather than upgrade to a development version,
and for anyone else curious: this is the option in the main config I
came up with:

chunking_advertise_hosts = ! google.com : ! *.google.com

--
Ian Kelling | Senior Systems Administrator, Free Software Foundation
GPG Key: B125 F60B 7B28 7FF6 A2B7 DF8F 170A F0E2 9542 95DF
https://fsf.org | https://gnu.org

--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/