Add mid_delay.py — ESA mail log MID delay analyzer
Features: multi-file parsing, delay threshold, status filtering, pending/partial/aborted exclusion, and --start timeframe filter.
This commit is contained in:
2
.gitignore
vendored
Normal file
2
.gitignore
vendored
Normal file
@@ -0,0 +1,2 @@
|
||||
CLAUDE.md
|
||||
*.s
|
||||
255
mid_delay.py
Normal file
255
mid_delay.py
Normal file
@@ -0,0 +1,255 @@
|
||||
import re
|
||||
import sys
|
||||
import argparse
|
||||
from datetime import datetime
|
||||
|
||||
# --- Regexes ---
|
||||
|
||||
RE_LINE = re.compile(r'^(\w{3} \w{3}\s+\d{1,2} \d{2}:\d{2}:\d{2} \d{4}) \w+: (.+)$')
|
||||
RE_START = re.compile(r'Start MID (\d+) ICID')
|
||||
RE_FINISHED = re.compile(r'Message finished MID (\d+) (done|aborted)')
|
||||
RE_ABORTED = re.compile(r'Message aborted MID (\d+) (.+)')
|
||||
RE_DELAYED = re.compile(r'Delayed: DCID \d+ MID (\d+) to RID \d+ - [\d.]+ - (.+)')
|
||||
RE_REWRITTEN = re.compile(r'MID (\d+) rewritten to MID (\d+)')
|
||||
RE_DELIVERY_START = re.compile(r'Delivery start DCID \d+ MID (\d+)')
|
||||
|
||||
TS_FORMAT = '%a %b %d %H:%M:%S %Y'
|
||||
|
||||
|
||||
def parse_ts(raw):
|
||||
return datetime.strptime(raw.strip(), TS_FORMAT)
|
||||
|
||||
|
||||
def parse_log(filepath, records=None):
|
||||
if records is None:
|
||||
records = {}
|
||||
|
||||
def get(mid):
|
||||
if mid not in records:
|
||||
records[mid] = {
|
||||
'mid': mid,
|
||||
'start_ts': None,
|
||||
'start_fallback': False, # True if start_ts came from Delivery start, not Start MID
|
||||
'end_ts': None,
|
||||
'end_status': None,
|
||||
'delayed_ts': None,
|
||||
'delay_count': 0,
|
||||
'delay_reason': None,
|
||||
'abort_reason': None,
|
||||
}
|
||||
return records[mid]
|
||||
|
||||
with open(filepath, encoding='utf-8', errors='replace') as f:
|
||||
for line in f:
|
||||
if 'MID' not in line and 'Delayed' not in line:
|
||||
continue
|
||||
m = RE_LINE.match(line)
|
||||
if not m:
|
||||
continue
|
||||
ts_raw, msg = m.group(1), m.group(2)
|
||||
ts = None
|
||||
|
||||
def get_ts():
|
||||
nonlocal ts
|
||||
if ts is None:
|
||||
ts = parse_ts(ts_raw)
|
||||
return ts
|
||||
|
||||
if m2 := RE_START.search(msg):
|
||||
rec = get(m2.group(1))
|
||||
if rec['start_ts'] is None:
|
||||
rec['start_ts'] = get_ts()
|
||||
elif m2 := RE_FINISHED.search(msg):
|
||||
rec = get(m2.group(1))
|
||||
rec['end_ts'] = get_ts()
|
||||
rec['end_status'] = m2.group(2)
|
||||
elif m2 := RE_ABORTED.search(msg):
|
||||
rec = get(m2.group(1))
|
||||
if rec['abort_reason'] is None:
|
||||
rec['abort_reason'] = m2.group(2).strip()
|
||||
elif m2 := RE_DELAYED.search(msg):
|
||||
rec = get(m2.group(1))
|
||||
rec['delay_count'] += 1
|
||||
if rec['delayed_ts'] is None:
|
||||
rec['delayed_ts'] = get_ts()
|
||||
rec['delay_reason'] = m2.group(2).strip()
|
||||
elif m2 := RE_DELIVERY_START.search(msg):
|
||||
rec = get(m2.group(1))
|
||||
# Fallback: use first Delivery start as start_ts if no Start MID was seen
|
||||
if rec['start_ts'] is None:
|
||||
rec['start_ts'] = get_ts()
|
||||
rec['start_fallback'] = True
|
||||
elif m2 := RE_REWRITTEN.search(msg):
|
||||
get(m2.group(1))
|
||||
get(m2.group(2))
|
||||
|
||||
return records
|
||||
|
||||
|
||||
def classify(rec, threshold):
|
||||
start = rec['start_ts']
|
||||
end = rec['end_ts']
|
||||
status = rec['end_status']
|
||||
delayed_ts = rec['delayed_ts']
|
||||
|
||||
if delayed_ts:
|
||||
if end is not None:
|
||||
delay = (end - start).total_seconds() / 60 if start else (end - delayed_ts).total_seconds() / 60
|
||||
else:
|
||||
delay = (delayed_ts - start).total_seconds() / 60 if start else 0.0
|
||||
if delay > threshold:
|
||||
return ('delayed', delay)
|
||||
|
||||
if start and end:
|
||||
delay = (end - start).total_seconds() / 60
|
||||
if delay > threshold:
|
||||
label = 'slow_done' if status == 'done' else 'slow_aborted'
|
||||
return (label, delay)
|
||||
|
||||
return None
|
||||
|
||||
|
||||
def format_output(results, top_n, show_status):
|
||||
if top_n:
|
||||
results = results[:top_n]
|
||||
|
||||
ts_fmt = '%Y-%m-%d %H:%M:%S'
|
||||
if show_status:
|
||||
col = f"{'MID':<15} {'Start':<21} {'End/Delayed':<20} {'Delay(m)':>9} {'Status':<20} Reason"
|
||||
else:
|
||||
col = f"{'MID':<15} {'Start':<21} {'End/Delayed':<20} {'Delay(m)':>9} Reason"
|
||||
print(col)
|
||||
print('-' * len(col))
|
||||
|
||||
for delay, mid, start, end, label, reason, start_fallback in results:
|
||||
if start is None:
|
||||
start_str = '(unknown)'
|
||||
elif start_fallback:
|
||||
start_str = start.strftime(ts_fmt) + '*' # * = fallback from Delivery start
|
||||
else:
|
||||
start_str = start.strftime(ts_fmt)
|
||||
end_str = end.strftime(ts_fmt) if end else '(pending)'
|
||||
if show_status:
|
||||
print(f"{mid:<15} {start_str:<21} {end_str:<20} {delay:>9.0f} {label:<20} {reason[:60]}")
|
||||
else:
|
||||
print(f"{mid:<15} {start_str:<21} {end_str:<20} {delay:>9.0f} {reason[:60]}")
|
||||
|
||||
print()
|
||||
print("* start time is a fallback from 'Delivery start' — original Start MID not in this log")
|
||||
print(f"Total reported: {len(results)}")
|
||||
|
||||
|
||||
def main():
|
||||
parser = argparse.ArgumentParser(
|
||||
description='Report delayed MIDs from a Cisco ESA mail log.',
|
||||
epilog=(
|
||||
'examples:\n'
|
||||
' python3 mid_delay.py mail.@20260303T005159.s # run with defaults (threshold=0.5m, all statuses)\n'
|
||||
' python3 mid_delay.py mail* # parse all mail.* files together\n'
|
||||
' python3 mid_delay.py mail.current mail.@*.s # explicit multi-file list\n'
|
||||
' python3 mid_delay.py --top 20 # show only the 20 worst delays\n'
|
||||
' python3 mid_delay.py -t 5 -n 50 # threshold 5 minutes, top 50\n'
|
||||
' python3 mid_delay.py -s delayed # only MIDs with explicit retry events\n'
|
||||
' python3 mid_delay.py -s slow_done # slow but no retry event\n'
|
||||
' python3 mid_delay.py --no-partial -n 10 # exclude MIDs without a start in this log\n'
|
||||
' python3 mid_delay.py mail* --start 2026-03-03 # MIDs starting on/after a date\n'
|
||||
' python3 mid_delay.py mail* --start "2026-03-03 12:00:00" # MIDs starting on/after a time\n'
|
||||
'\n'
|
||||
'status categories:\n'
|
||||
' delayed had an explicit Delayed: retry event in the log\n'
|
||||
' slow_done no retry event, but start→finish exceeded threshold (minutes), delivered\n'
|
||||
' slow_aborted no retry event, but start→finish exceeded threshold (minutes), aborted\n'
|
||||
),
|
||||
formatter_class=argparse.RawDescriptionHelpFormatter,
|
||||
)
|
||||
parser.add_argument(
|
||||
'logfile',
|
||||
nargs='+',
|
||||
help='Path(s) to ESA mail log file(s); supports shell globs like mail*',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--threshold', '-t',
|
||||
type=float,
|
||||
default=0.5,
|
||||
help='Delay threshold in minutes for slow MIDs (default: 0.5)',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--top', '-n',
|
||||
type=int,
|
||||
default=20,
|
||||
help='Show only the top N results (default: 20)',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--status', '-s',
|
||||
choices=['delayed', 'slow_done', 'slow_aborted', 'all'],
|
||||
default=None,
|
||||
help='Filter by status category and show Status column (default: show all, no Status column)',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--pending',
|
||||
action='store_true',
|
||||
help='Show only MIDs that never finished delivery in this log',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--no-partial',
|
||||
action='store_true',
|
||||
help='Exclude MIDs with no start timestamp in this log',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--no-aborted',
|
||||
action='store_true',
|
||||
help='Exclude MIDs that were aborted',
|
||||
)
|
||||
parser.add_argument(
|
||||
'--start',
|
||||
metavar='DATETIME',
|
||||
default=None,
|
||||
help='Only include MIDs whose start time is at or after this value (format: "YYYY-MM-DD" or "YYYY-MM-DD HH:MM:SS")',
|
||||
)
|
||||
args = parser.parse_args()
|
||||
|
||||
since_dt = None
|
||||
if args.start:
|
||||
for fmt in ('%Y-%m-%d %H:%M:%S', '%Y-%m-%d'):
|
||||
try:
|
||||
since_dt = datetime.strptime(args.start, fmt)
|
||||
break
|
||||
except ValueError:
|
||||
pass
|
||||
if since_dt is None:
|
||||
parser.error(f"--start: unrecognized date format '{args.start}'; use YYYY-MM-DD or YYYY-MM-DD HH:MM:SS")
|
||||
|
||||
# Sort files so archived logs (mail.@...) come before mail.current
|
||||
logfiles = sorted(args.logfile)
|
||||
records = {}
|
||||
for logfile in logfiles:
|
||||
print(f"Parsing {logfile} ...", file=sys.stderr)
|
||||
parse_log(logfile, records)
|
||||
print(f"Parsed {len(records)} unique MIDs across {len(logfiles)} file(s).", file=sys.stderr)
|
||||
|
||||
results = []
|
||||
for rec in records.values():
|
||||
if args.no_partial and rec['start_ts'] is None:
|
||||
continue
|
||||
entry = classify(rec, args.threshold)
|
||||
if entry is None:
|
||||
continue
|
||||
label, delay = entry
|
||||
if args.status and args.status != 'all' and label != args.status:
|
||||
continue
|
||||
if args.pending and rec['end_ts'] is not None:
|
||||
continue
|
||||
if args.no_aborted and rec['end_status'] == 'aborted':
|
||||
continue
|
||||
if since_dt and (rec['start_ts'] is None or rec['start_ts'] < since_dt):
|
||||
continue
|
||||
reason = rec['delay_reason'] or rec['abort_reason'] or ''
|
||||
results.append((delay, rec['mid'], rec['start_ts'], rec['end_ts'], label, reason, rec['start_fallback']))
|
||||
|
||||
results.sort(key=lambda x: x[0], reverse=True)
|
||||
show_status = args.status is not None
|
||||
format_output(results, args.top, show_status)
|
||||
|
||||
|
||||
if __name__ == '__main__':
|
||||
main()
|
||||
Reference in New Issue
Block a user