Page MenuHomePhabricator

Alert email sent from backupmon1001 didn't reach engineer's google inbox (was: check-dbbackup-time sometimes doesn't send email alerts)
Closed, ResolvedPublic

Description

An issue was detected here, but I didn't get the email:

Jun 27 01:00:02 backupmon1001 systemd[1]: Starting Checks and alerts by email if ES backups are too slow...
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: About to execute query:    SELECT id, name, status, source, host, type, section, start_da>
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]:                              end_date, total_size
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]:                         FROM backups
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]:                        WHERE start_date >= now() - INTERVAL 1 WEEK
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]:                          AND TIMESTAMPDIFF(SECOND, start_date,
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]:                                  IF(end_date IS NULL, now(), end_date)) > %s
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]:                     ORDER BY id
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: Max seconds: 43200.0
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: Report run at 2024-06-27T01:00:02.795183 at backupmon1001.
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: 3 backups were found in the last week that took over 12.0 hours:
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: * dump of es4 in codfw started at 2024-06-25T08:46:29 and finished at 2024-06-26T09:11:37>
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: * dump of es5 in codfw started at 2024-06-25T08:46:29 and finished at 2024-06-26T00:23:41>
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: * dump of es4 in eqiad started at 2024-06-26T08:18:41 and finished at 2024-06-26T23:59:30>
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: Check `https://wikitech.wikimedia.org/wiki/MariaDB/Backups/Long_running` for more details>
Jun 27 01:00:02 backupmon1001 check-dbbackup-time[1835289]: Email sent to sre-data-persistence@wikimedia.org
Jun 27 01:00:02 backupmon1001 systemd[1]: check-es-backups-duration.service: Succeeded.
Jun 27 01:00:02 backupmon1001 systemd[1]: Finished Checks and alerts by email if ES backups are too slow.

The exim logs confirm the email was sent outside the host, so not a script issue (unless if failed randomly for some header issue afterwards):

2024-06-27 01:00:02 1sMdUY-007hRX-QG <= backupmon1001@wikimedia.org H=localhost (backupmon1001.eqiad.wmnet) [::1]:48358 I=[::1]:25 P=esmtp S=1117
2024-06-27 01:00:03 1sMdUY-007hRX-QG => sre-data-persistence@wikimedia.org R=smart_route T=remote_smtp S=1148 H=mx1001.wikimedia.org [2620:0:861:3:208
:80:154:76] I=[2620:0:861:107:10:64:48:150] C="250 OK id=1sMdUW-00BXbG-2v" DT=0s
2024-06-27 01:00:03 1sMdUY-007hRX-QG Completed

Event Timeline

Running it manually it worked every time, so I am confused- it doesn't seem to be a script issue. Could it be a mailing subsystem issue?

Checking exim logs, the email was sent:

2024-06-27 01:00:02 1sMdUY-007hRX-QG <= backupmon1001@wikimedia.org H=localhost (backupmon1001.eqiad.wmnet) [::1]:48358 I=[::1]:25 P=esmtp S=1117
2024-06-27 01:00:03 1sMdUY-007hRX-QG => sre-data-persistence@wikimedia.org R=smart_route T=remote_smtp S=1148 H=mx1001.wikimedia.org [2620:0:861:3:208
:80:154:76] I=[2620:0:861:107:10:64:48:150] C="250 OK id=1sMdUW-00BXbG-2v" DT=0s
2024-06-27 01:00:03 1sMdUY-007hRX-QG Completed

So to me this is an mx or google issue, not monitoring. IF people, could you give a heads up if there was some mail delivery issues last week?

• jcrespo renamed this task from check-dbbackup-time sometimes doesn't send email alerts to Alert email sent from backupmon1001 didn't reach engineer's google inbox (was: check-dbbackup-time sometimes doesn't send email alerts).Jul 4 2024, 8:16 AM
• jcrespo updated the task description. (Show Details)

There is T369341: Some VRTS emails to Gmail accounts fail the SPF check but the switch to new outgoing MX servers only happened on July 3rd so may be unrelated.

[it might be worth making sure we emit emails with a deliverable return-path, so we can differentiate between "google attempted to bounce, but there was no-where to bounce to" and "google silently dropped the mail"]

jhathaway subscribed.

I'll take a look at this today

I'll take a look at this today

Sorry for the delay in looking at this, from our logs it looks like the email was successfully sent to gmail:

2024-06-27 01:00:03 1sMdUW-00BXbG-2v <= backupmon1001@wikimedia.org H=backupmon1001.eqiad.wmnet [2620:0:861:107:10:64:48:150]:38398 I=[2620:0:861:3:208:80:154:76]:25 P=esmtp S=1387
2024-06-27 01:00:03 1sMdUW-00BXbG-2v => sre-data-persistence@wikimedia.org R=gsuite_account T=remote_smtp S=1420 H=aspmx.l.google.com [172.253.115.27] I=[208.80.154.76] X=TLS1.3:ECDHE_X25519__ECDSA_SECP256R1_SHA256__AES_256_GCM:256 CV=yes DN="CN=mx.google.com" K C="250 2.0.0 OK d75a77b69052e-4464222b652si2501861cf.755 - gsmtp" DT=0s
2024-06-27 01:00:03 1sMdUW-00BXbG-2v Completed

I'll ask ITS if they are able to ask google about a specific message id.

I don't see a record of this email in the Google logs. I see an email sent from backupmon1001@wikimedia.org on October 18, 2023. Then the next email I see from backupmon1001@ is July 3.

[it might be worth making sure we emit emails with a deliverable return-path, so we can differentiate between "google attempted to bounce, but there was no-where to bounce to" and "google silently dropped the mail"]

Given that google seems to have accepted the email, I would hope that they would send a proper bounce message later, so I agree this should be the next step. Does @jcrespo or anyone else have access to a backup email with full headers?

Thanks, everone. I think @MatthewVernon 's suggestion is fair, and something I should have done. I will update the code's headers so bounces get sent to root@. While I know mail is not reliable, I just found weird that the same kind of message (as it is automated) got filtered only that one time.

One thing I would like to have in the future is some kind of private dashboard for alerts, so we don't depend on email for those. Sadly, prometheus is semi-public, and while most of our alerts are also public, there are some data-related alerts that for privacy cannot be public.

• jcrespo lowered the priority of this task from High to Low.

I've sent a path here to resolve this, but I won't merge until I fix CI for bookworm, which will take me some time:

https://gitlab.wikimedia.org/repos/sre/wmfbackups/-/merge_requests/6/diffs?commit_id=b2e3822ef461661cc02ff940e2b23f1b264e13a9

• jcrespo claimed this task.

This was fixed 5 months ago when the new version was realeased for both bookworm, and then for trixie: https://gitlab.wikimedia.org/repos/sre/wmfbackups/-/commits/v0.8.4_bookworm?ref_type=tags