[BALUG-Admin] very delayed: [BALUG-Announce] BALUG: meeting TODAY!: Tu 2024-02-20 & other BALUG News

Tue Mar 19 08:43:05 UTC 2024

+balug-admin@lists.balug.org - don't send/cc/bcc to that email if
you're not on that list

Oh, and most of the timezones are UTC, unless indicated otherwise.

So ... first we look at full headers of the received.  To make that
simpler, I first unfolded (any header lines starting with a space I
joined to line above), then removed all lines except those with a date
or timestamp or the like and also retaining those that might be
relatively usefully informative, and dropped the rest.  Then for
readability I (re)folded those more than 72 characters wide, with a
space indent where folded.  And I preserved ordering.  That leaves us
with:

Date: Tue, 20 Feb 2024 05:07:35 -0800
To: BALUG-Announce <balug-announce@lists.balug.org>
Message-ID: <94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu>
Received-SPF: none client-ip=198.144.192.42;
 envelope-from=Michael.Paoli@cal.berkeley.edu; helo=shell1.rawbw.com
Subject: [BALUG-Announce] BALUG: meeting TODAY!: Tu 2024-02-20 & other
 BALUG News
From: Michael Paoli via BALUG-Announce <balug-announce@lists.balug.org>
Reply-To: Michael Paoli <Michael.Paoli@cal.berkeley.edu>
Errors-To: balug-announce-bounces@lists.balug.org
Sender: BALUG-Announce <balug-announce-bounces@lists.balug.org>

So, we see the big time gap here:

Received: from localhost ([127.0.0.1] helo=balug.org) by
 balug-sf-lug-v2.balug.org with esmtp (Exim 4.92) (envelope-from
 <balug-announce-bounces@lists.balug.org>) id 1rkfsB-0002wb-L7; Thu, 14
 Mar 2024 07:51:31 +0000
Received: from shell1.rawbw.com ([198.144.192.42]) by
 balug-sf-lug-v2.balug.org with esmtp (Exim 4.92) (envelope-from
 <Michael.Paoli@cal.berkeley.edu>) id 1rcPqS-0002KU-Ko for
 balug-announce@lists.balug.org; Tue, 20 Feb 2024 13:07:36 +0000

Those Received: headers are read from bottom up in order of processing,
newer Received: headers are added atop any existing.  That's not only
useful for tracing route of mail, but these also generally include
timestamps.

So, I sent it from one of my ISP's email to the list, and that was
received, then it took a long time for the next hop - which was entirely
local on the same host - so something went wrong there between MTA
and/or mailman.  If I convert those timestamps to ISO
format, have:
2024-02-20T13:07:36+0000
2024-03-14T07:51:31+0000

$ who -r
         run-level 5  Mar 14 06:51

So, between that and a presumed exponential back-off on retries on the
sending MTA, that would presumably account for when the MTA received
that, presuming for the period before that there was some reason it
couldn't or wouldn't.  And looking at receiving MTA logs, no shortage
of logs between those timestamps, so ... what happened?  We do have:
Message-ID: <94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu>
and that should be unique, so can be quite useful for, e.g. searching
in mail logs.  What (if anything) can we find for that in the time range
in question?

MTA exim4 ... I don't have mainlog files going back that far, but I do
have rejectlog files going back that far.  In chronological order by
mtime for files covering range:
2024-02-20T13:07:36+0000
2024-03-14T07:51:31+0000
have files matching these patterns:
rejectlog.{5{9,8,7,6,5,4,3,2,1,0},4{9,8,7,6,5,4,3,2,1,0},3{9,8,7,6,5,4,3,2,1,0},2{9,8,7}}.gz
paniclog
rejectlog.{2{6,5,4,3,2,1,0},1{9,8,7,6,5,4,3,2,1,0}}.gz
mainlog.10.gz
eval echo \{rejectlog,mainlog\}{.{9,8,7,6,5,4,3,2,1}.gz,}

checking for that Message-ID, have:
(
  Message_ID='94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu'
  eval set -- \
    rejectlog.{5{9,8,7,6,5,4,3,2,1,0},4{9,8,7,6,5,4,3,2,1,0},3{9,8,7,6,5,4,3,2,1,0},2{9,8,7}}.gz
\
    paniclog \
    rejectlog.{2{6,5,4,3,2,1,0},1{9,8,7,6,5,4,3,2,1,0}}.gz \
    mainlog.10.gz \
    \{rejectlog,mainlog\}{.{9,8,7,6,5,4,3,2}.gz,.1,}
  for f
  do
    case "$f" in
      *.gz)
        gzip -d < "$f" |
        grep -F -q -e "$Message_ID" &&
        {
          echo "$f"
          gzip -d < "$f" | grep -F -e "$Message_ID"
        }
      ;;
      *)
        grep -F -l -e "$Message_ID" "$f" &&
        grep -F -e "$Message_ID" "$f"
      ;;
    esac
  done
)
mainlog.5.gz
2024-03-14 07:51:31 1rkfsB-0002wb-L7 <=
balug-announce-bounces@lists.balug.org H=localhost (balug.org)
[127.0.0.1] P=esmtp S=7761
id=94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu
2024-03-14 07:51:31 1rkfsB-0002wb-Me <=
balug-announce-bounces@lists.balug.org H=localhost (balug.org)
[127.0.0.1] P=esmtp S=7761
id=94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu
2024-03-14 07:51:31 1rkfsB-0002wb-TW <=
balug-announce-bounces@lists.balug.org H=localhost (balug.org)
[127.0.0.1] P=esmtp S=7761
id=94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu
2024-03-14 07:51:31 1rkfsB-0002wb-UG <=
balug-announce-bounces@lists.balug.org H=localhost (balug.org)
[127.0.0.1] P=esmtp S=7761
id=94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu
2024-03-14 07:51:41 1rkfsB-0002wb-L7 => <REDACTED>
...

So, basically it comes in (apparently goes through multiple times in
processing), and then lots of sends out very shortly after that.
Unfortunately don't have the earlier mainlog files, so not sure what may
have happened then - at least as far as MTA goes.

Let's see about mailman. For log files in the relevant time frame, and
ignoring those which are compressed empty files (yeah, I should have
logrotate not compress empty files), these are the files in
chronological order (by mtime):
vette.4.gz
mischief.1
error.3.gz
error.2.gz
security
qrunner.5.gz
smtp-failure.5.gz
locks.5.gz
smtp.5.gz
qrunner.4.gz
bounce.1
subscribe

And going through those files, nothing relevant in the applicable
time frame.

So ... thus far best guess is something that was essentially somewhere
along that chain failed or wedged or died or crashed or the like,
didn't particularly log anything indicating the problem in the
meantime, and things went back to "normal" and got unjammed after host
rebooted.

Oh, mailman did also add it to the archives ... can we see when, that
may provide a clue.

>From Michael.Paoli@cal.berkeley.edu Tue Feb 20 13:07:36 2024
Received: from shell1.rawbw.com ([198.144.192.42]) by
 balug-sf-lug-v2.balug.org with esmtp (Exim 4.92) (envelope-from
 <Michael.Paoli@cal.berkeley.edu>) id 1rcPqS-0002KU-Ko for
balug-announce@lists.balug.org; Tue, 20 Feb 2024 13:07:36 +0000
Received: from webmail.rawbw.com (mail0.rawbw.com [198.144.192.41]) by
 shell1.rawbw.com (8.15.1/8.15.1) with ESMTP id 41KD7ZwB068218; Tue, 20
 Feb 2024 05:07:35 -0800 (PST) (envelope-from
 Michael.Paoli@cal.berkeley.edu)
From: Michael Paoli <Michael.Paoli@cal.berkeley.edu>
To: BALUG-Announce <balug-announce@lists.balug.org>
Message-ID: <94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu>
X-Sender: Michael.Paoli@cal.berkeley.edu
Subject: [BALUG-Announce] BALUG: meeting TODAY!: Tu 2024-02-20 & other
 BALUG News
X-BeenThere: balug-announce@lists.balug.org
Date: Tue, 20 Feb 2024 13:07:36 -0000
X-Original-Date: Tue, 20 Feb 2024 05:07:35 -0800
X-List-Received-Date: Tue, 20 Feb 2024 13:07:36 -0000

At least what shows in the archive (complete mbox file), from the full
headers, looks like it got it in timely manner.  What about where
it processes those for showing on web?

# pwd -P && ls -ontr $(find * ! -mtime +30 -type f -print | fgrep Feb)
/var/lib/mailman/archives/private/balug-announce
-rw-rw-r-- 1 38 5689 Mar 14 06:51 2024-February.txt
-rw-rw-r-- 1 38 1729 Mar 14 06:51 2024-February/date.html
-rw-rw-r-- 1 38 1723 Mar 14 06:51 2024-February/subject.html
-rw-rw-r-- 1 38 1725 Mar 14 06:51 2024-February/author.html
-rw-rw-r-- 1 38 1752 Mar 14 06:51 2024-February/thread.html
-rw-rw-r-- 1 38 8276 Mar 14 06:51 2024-February/000340.html
-rw-rw---- 1 38  136 Mar 14 06:51 database/2024-February-thread
-rw-rw---- 1 38  183 Mar 14 06:51 database/2024-February-subject
-rw-rw---- 1 38  131 Mar 14 06:51 database/2024-February-date
-rw-rw---- 1 38  150 Mar 14 06:51 database/2024-February-author
-rw-rw---- 1 38 1259 Mar 14 06:51 database/2024-February-article
-rw-rw-r-- 1 38 2687 Mar 15 03:27 2024-February.txt.gz
#

Yeah, it would seem to implicate a problem within mailman.
Looks like our sequence went about like this:
2024-02-20T13:07:36+0000 email generated on sending MTA,
looks like it made it to receiving MTA and into mailman,
notably mailman show it in the mbox full archive with
corresponding timestamps, but then looks like it stuck at some point
after that, notably not even the archiving was fully processed,
as the web archive files didn't catch up until
2024-03-14T06:51+0000
we have a reboot
$ who -r
         run-level 5  Mar 14 06:51
And the mailman web archive files catch up. Then, an hour later:
2024-03-14T07:51:31+0000
mail to list recipients is actually sent out (perhaps some retry logic
caused the hour's delay at that point).

Anyway, that's my best guestimation based on the evidence.

---------- Forwarded message ---------
From: Michael Paoli <michael.paoli@cal.berkeley.edu>
Date: Thu, Mar 14, 2024 at 8:26 PM
Subject: Re: [BALUG-Announce] BALUG: meeting TODAY!: Tu 2024-02-20 &
other BALUG News
To: aaronco36 <aaronco36@sdf.org>, <balug-admin@lists.balug.org>
Cc: Rick Moen <rick@linuxmafia.com>

+balug-admin@lists.balug.org - don't send/cc/bcc to that email if
you're not on that list

Yeah, ... I noticed that too - haven't dug down yet to figure out what happened,
but some list mail went out (or went out again?) very late - like weeks late.
And like I say, haven't dug down to the bottom of it to figure out what happened
yet.  "Other than that" didn't notice anything unusual.  But ... maybe
some queue
got stuck or some demon that was supposed to be running wasn't, and then
perhaps with some reboot or update or the like, somehow things got unjammed
and/or reprocessed?  Still guessing a bit at this point - will need to review
logs and some full headers and other details to figure out what happened.
Anyway, maybe I get to it sometime this weekend(ish) or so.  Shouldn't have
happened, but there isn't an "undo" for mail sent, so 'bout best can do with it
is figure out (hopefully) how it happened, and hopefully prevent a
repeat of that.
Possible some queue got stuck or daemon down or crashed or stuck, and I didn't
catch it earlier, and things just got inordinately delayed ... that'd
at least be my first
guess, though there are certainly other possibilities.

And it wasn't just that one BALUG-Announce mail, but a moderate spattering of
mailman and/or exim4 mail that was impacted - all came through at once.
I think I saw about 20 emails or so (most of which were for list admin
or the like)
all come through at or right around the same time.

Anyway, probably answers to be found in the full headers and/or other
log data and such.

On Thu, Mar 14, 2024 at 7:58 PM aaronco36 <aaronco36@sdf.org> wrote:
>
> Hello Rick and Michael,
>
> > Quoting aaronco36 (aaronco36@sdf.org):
> >
> >> ????
> >> Now ~12:15 PDT (UTC-07:00) on Thursday 2024-03-14.
> >>
> >> aaronco36(at)SDF.org
> >
> > I'm not sure what you're talking about Aaron.  The most recent
> > balug-announce posting (this one, from Michael P.:)
> > https://lists.balug.org/pipermail/balug-announce/2024-February/000340.html)
> > really did go out on Tue Feb 20 13:07:36 UTC 2024, not today.
> >
> >
>
> Hmmmm, mystery to me as well :-\
> Perhaps very delayed transmission having something to do with the top pair
> of "Received:" sections dated this morning, below ??
>
> -A
>
> Contents of the Full Header of today's message:
> ~~~~~~~~~~~~~~~~ quoting in full ~~~~~~~~~~~~~~~~~~~~~
>
> Return-Path: <balug-announce-bounces@lists.balug.org>
> Received: from balug-sf-lug-v2.balug.org (balug.org [96.86.170.229])
>      by mx.sdf.org (8.16.1/8.14.3) with ESMTPS id 42E8VA6p012184
>      (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256 bits) verified
> NO)
>      for <aaronco36@sdf.org>; Thu, 14 Mar 2024 08:31:10 GMT
> Received: from localhost ([127.0.0.1] helo=balug.org)
>      by balug-sf-lug-v2.balug.org with esmtp (Exim 4.92)
>      (envelope-from <balug-announce-bounces@lists.balug.org>)
>      id 1rkfsB-0002wb-Me; Thu, 14 Mar 2024 07:51:31 +0000
> Received: from shell1.rawbw.com ([198.144.192.42])
>      by balug-sf-lug-v2.balug.org with esmtp (Exim 4.92)
>      (envelope-from <Michael.Paoli@cal.berkeley.edu>) id 1rcPqS-0002KU-Ko
>      for balug-announce@lists.balug.org; Tue, 20 Feb 2024 13:07:36 +0000
> Received: from webmail.rawbw.com (mail0.rawbw.com [198.144.192.41])
>      by shell1.rawbw.com (8.15.1/8.15.1) with ESMTP id 41KD7ZwB068218;
>      Tue, 20 Feb 2024 05:07:35 -0800 (PST)
>      (envelope-from Michael.Paoli@cal.berkeley.edu)
> X-Authentication-Warning: shell1.rawbw.com: Host mail0.rawbw.com
>      [198.144.192.41] claimed to be webmail.rawbw.com
> MIME-Version: 1.0
> Date: Tue, 20 Feb 2024 05:07:35 -0800
> To: BALUG-Announce <balug-announce@lists.balug.org>
> Message-ID: <94cc17d1e831608786fb59c3a4eb70a9@cal.berkeley.edu>
> X-Sender: Michael.Paoli@cal.berkeley.edu
> Received-SPF: none client-ip=198.144.192.42;
>      envelope-from=Michael.Paoli@cal.berkeley.edu; helo=shell1.rawbw.com
> Subject: [BALUG-Announce] BALUG: meeting TODAY!: Tu 2024-02-20 & other BALUG
>      News
> X-BeenThere: balug-announce@lists.balug.org
> X-Mailman-Version: 2.1.29
> Precedence: list
> List-Id: Announcements for and by BALUG <balug-announce.lists.balug.org>
> List-Unsubscribe:
> <https://lists.balug.org/cgi-bin/mailman/options/balug-announce>,
>      <mailto:balug-announce-request@lists.balug.org?subject=unsubscribe>
> List-Archive: <https://lists.balug.org/pipermail/balug-announce/>
> List-Post: <mailto:balug-announce@lists.balug.org>
> List-Help: <mailto:balug-announce-request@lists.balug.org?subject=help>
> List-Subscribe:
> <https://lists.balug.org/cgi-bin/mailman/listinfo/balug-announce>,
>      <mailto:balug-announce-request@lists.balug.org?subject=subscribe>
> From: Michael Paoli via BALUG-Announce <balug-announce@lists.balug.org>
> Reply-To: Michael Paoli <Michael.Paoli@cal.berkeley.edu>
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset="us-ascii"; Format="flowed"
> Errors-To: balug-announce-bounces@lists.balug.org
> Sender: "BALUG-Announce" <balug-announce-bounces@lists.balug.org>
>
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>