Launching Tor Weather breaks with password authentication error
No timeline items have been added yet.
- #41252Debian 12 bookworm upgrade
- status-site #32
- tpo/network-health/metrics/monitoring-and-alerting #24
- #41400Debian 12 bookworm upgrade
- #41485Debian 13 trixie upgrade
- #41879Debian 13 trixie upgrade
Activity
Oh, and this issue is presumably causing a
{"message": "Internal Server Error"}on https://weather.torproject.org/api/login after logging in...assigned to @lavamind
added Next label
changed milestone to %Debian 12 bookworm upgrade
Ok the authentication issue is related to PostgreSQL. It seems the
torweatherdatabase doesn't exist on the PostgreSQL 15 cluster, and the old PostgreSQL 13 cluster is not present anymore, which suggests that the cluster was upgraded to 15.@anarcat Did anything unusual happen with the PostgreSQL upgrade on this machine?
added Needs Information label and removed Next label
added PostgreSQL label
marked this issue as related to #41252 (closed)
okay so clearly something was deeply messed up in the postgresql upgrade procedure. the whole cluster is gone. normally, we make a backup of the old backups when we rotate the new cluster in place, and we did do so here, but that backup was cleared after a week, as per our policies.
so i don't know how else to put this, but the database is completely gone. zlit. boom. deleted. forever. there might be a way to do forensics on the server to try to recover the deleted files, but it's been so long that I doubt we'll find anything.
how can we rebuild this server from scratch? how important is the historical data here? i guess we lost the user database of people that registered? maybe we can recover some of this through the mail logs?
mentioned in issue status-site#31 (closed)
-
current status: scrubbing the backup server for a copy of the last full backup:
Disk /dev/mapper/vg_bulk-backups--pg - 3298 GB / 3072 GiB (RO) Partition Start End Size in sectors P ext4 0 0 1 2147483647 0 1 6442450944 Destination /srv/backups/bacula/recup_dir Pass 2 - Reading sector 696400712/6442450944, 1909 files found Elapsed time 0h13m37s - Estimated time to completion 1h52m21 txt: 1842 recovered swf: 59 recovered gz: 6 recovered mov: 1 recovered pap: 1 recoveredso far the recovered files are truncated gzip files, which cannot be used for recovery. ETA ~2h.
-
i have made a snapshot/dd dump of the weather-01 root filesystem in
fsn-node-01:weather-01-rootfs-20231108T154128.dump.i have found a partial dump that might actually be recent enough:
root@bungei:/srv/backups/bacula# for file in /root/RECOVERDIR/recup_dir.1/*.gz recup_dir.*/*gz; do tar -O -x -z -f $file backup_label 2>/dev/null | grep weather && echo $file; done LABEL: bungei.torproject.org-20221222-005448-weather-01.torproject.org-main-13-backup recup_dir.10/f1191248128.gz LABEL: bungei.torproject.org-20231008-005104-weather-01.torproject.org-main-13-backup recup_dir.18/f1959051264.gz LABEL: bungei.torproject.org-20231027-062310-weather-01.torproject.org-main-13-backup recup_dir.20/f3005349888.gz root@bungei:/srv/backups/bacula# ls -alh recup_dir.20/f3005349888.gz -rw-r--r-- 1 root root 3.1G Oct 27 06:23 recup_dir.20/f3005349888.gz root@bungei:/srv/backups/bacula#will try to recover from this now to see if postgres can load it, which involves restarting the VM.
-
actually, those new files are way too small:
root@bungei:/srv/backups/bacula# for file in /root/RECOVERDIR/recup_dir.1/*.gz recup_dir.*/*gz; do tar -O -x -z -f $file backup_label 2>/dev/null | grep weather && ls -alh $file; done LABEL: bungei.torproject.org-20221222-005448-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 13G Dec 22 2022 recup_dir.10/f1191248128.gz LABEL: bungei.torproject.org-20231008-005104-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 3.5G Oct 8 00:51 recup_dir.18/f1959051264.gz LABEL: bungei.torproject.org-20231027-062310-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 3.1G Oct 27 06:23 recup_dir.20/f3005349888.gz... but that older copy has more potential, since it's larger... i am still confused by this because I don't see a drop in the disk usage in grafana when i supposedly destroyed that database... that should have been visible...
in #41252 (closed), I "marked the checklist item weather-01.torproject.org (@anarcat) as completed 31 Oct 2023, 16:05", which means some time on Oct 31st, i cleared out the old database. but looking at the last 14 days, i see no such drop:
there is a slight bump in there:
... but it's only 130MB being freed...
so this is really puzzling.
-
actually, those new files are way too small:
i have tried to restore the 13GB backup:
root@weather-01:/srv# mkdir f1191248128 root@weather-01:/srv# cd f1191248128/1 -bash: cd: f1191248128/1: No such file or directory root@weather-01:/srv# cd f1191248128/ root@weather-01:/srv/f1191248128# tar zfx ../f1191248128.gz gzip: stdin: invalid compressed data--format violated tar: Unexpected EOF in archive tar: Unexpected EOF in archive tar: Error is not recoverable: exiting now root@weather-01:/srv/f1191248128# ls PG_VERSION base pg_notify pg_subtrans tablespace_map backup_label global pg_stat pg_tblspc root@weather-01:/srv/f1191248128# du -sch . 17M . 17M total root@weather-01:/srv/f1191248128# ls -alh ../f1191248128.gz -rw-r--r-- 1 root root 13G Nov 8 17:07 ../f1191248128.gz root@weather-01:/srv/f1191248128# cat backup_label START WAL LOCATION: 0/B1000028 (file 0000000100000000000000B1) CHECKPOINT LOCATION: 0/B1000060 BACKUP METHOD: streamed BACKUP FROM: master START TIME: 2022-12-22 00:54:48 UTC LABEL: bungei.torproject.org-20221222-005448-weather-01.torproject.org-main-13-backup START TIMELINE: 1clearly that file size might be incorrect...
another, more recent but smaller archive:
root@weather-01:/srv# mkdir f1959051264 root@weather-01:/srv# cd f1959051264/ root@weather-01:/srv/f1959051264# tar zfx ../f1959051264.gz gzip: stdin: decompression OK, trailing garbage ignored tar: Child returned status 2 tar: Error is not recoverable: exiting now root@weather-01:/srv/f1959051264# cd ^C root@weather-01:/srv/f1959051264# du -sch . 39M . 39M total root@weather-01:/srv/f1959051264# ls -alh ../f1959051264.gz -rw-r--r-- 1 root root 3.5G Nov 8 17:14 ../f1959051264.gz root@weather-01:/srv/f1959051264# cat backup_label START WAL LOCATION: E/46000028 (file 000000010000000E00000046) CHECKPOINT LOCATION: E/46000060 BACKUP METHOD: streamed BACKUP FROM: master START TIME: 2023-10-08 00:51:04 UTC LABEL: bungei.torproject.org-20231008-005104-weather-01.torproject.org-main-13-backup START TIMELINE: 1and it's quite promising, that thing, actually:
root@weather-01:/srv/f1959051264# /usr/lib/postgresql/13/bin/pg_verifybackup -n . backup successfully verifiedi'll try the most recent backup as well.
-
the photorec job completed on bungei:
PhotoRec 7.1, Data Recovery Utility, July 2019 Christophe GRENIER <grenier@cgsecurity.org> https://www.cgsecurity.org Disk /dev/mapper/vg_bulk-backups--pg - 3298 GB / 3072 GiB (RO) Partition Start End Size in sectors P ext4 0 0 1 2147483647 0 1 6442450944 24827 files saved in /srv/backups/bacula/recup_dir directory. Recovery completed. You are welcome to donate to support and encourage further development https://www.cgsecurity.org/wiki/Donationi think it's now safe to remount the pg partition on bungei, as i don't think we can recover anything else from there, agreed @lavamind?
-
those are the actual backup files recovered:
root@bungei:/srv/backups/bacula# for file in /root/RECOVERDIR/recup_dir.1/*.gz recup_dir.*/*gz; do tar -O -x -z -f $file backup_label 2>/dev/null | grep weather && ls -alh $file; done LABEL: bungei.torproject.org-20221222-005448-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 13G Dec 22 2022 recup_dir.10/f1191248128.gz LABEL: bungei.torproject.org-20231008-005104-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 3.5G Oct 8 00:51 recup_dir.18/f1959051264.gz LABEL: bungei.torproject.org-20231027-062310-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 3.1G Oct 27 06:23 recup_dir.20/f3005349888.gz LABEL: bungei.torproject.org-20231017-095114-weather-01.torproject.org-main-13-backup -rw-r--r-- 1 root root 1.2G Oct 17 09:51 recup_dir.35/f5669519360.gzneedless to say i'm not even attempting to recover the WAL files here. i think we'll be happy with losing a few days of data: it would be pretty hard to find the WAL files and order them properly, considering their names is so important.
-
the october 27th backup:
root@weather-01:/srv# mkdir f3005349888 root@weather-01:/srv# cd f3005349888 root@weather-01:/srv/f3005349888# tar zxf ../f3005349888.gz gzip: stdin: decompression OK, trailing garbage ignored tar: Child returned status 2 tar: Error is not recoverable: exiting now root@weather-01:/srv/f3005349888# ls PG_VERSION pg_commit_ts pg_replslot pg_subtrans postgresql.auto.conf backup_label pg_dynshmem pg_serial pg_tblspc tablespace_map backup_manifest pg_logical pg_snapshots pg_twophase base pg_multixact pg_stat pg_wal global pg_notify pg_stat_tmp pg_xact root@weather-01:/srv/f3005349888# du -sch . 39M . 39M total root@weather-01:/srv/f3005349888# ls -alh ../f3005349888.gz -rw-r--r-- 1 root root 3.1G Nov 8 17:22 ../f3005349888.gz root@weather-01:/srv/f3005349888# /usr/lib/postgresql/13/bin/pg_verifybackup -n . backup successfully verified root@weather-01:/srv/f3005349888# cat backup_label START WAL LOCATION: E/BE000028 (file 000000010000000E000000BE) CHECKPOINT LOCATION: E/BE000060 BACKUP METHOD: streamed BACKUP FROM: master START TIME: 2023-10-27 06:23:11 UTC LABEL: bungei.torproject.org-20231027-062310-weather-01.torproject.org-main-13-backup START TIMELINE: 1this seems to match the other backups that are < 100MB... the file recovery probably just inflated the file size, padding it with garbage.
i think i'll try to restore that database next. but first i'll take a short break for lunch.
i'm hoping we can recover the data back to 2023-10-27 06:23:11 UTC. it's not the best, but it beats total loss.
and it would be important to document how this recovery happened in the howto/backup page!
added Doing label and removed Needs Information label
- Resolved by anarcat
i believe i have restored the latter dump with relative fidelity. it's possible that deleted records might reappear or that committed records were lost, but it meats having absolutely fuckall:
root@weather-01:/srv/dump# sudo -u postgres psql -p 5433 psql (15.3 (Debian 15.3-0+deb12u1), server 13.11 (Debian 13.11-0+deb11u1)) Type "help" for help. postgres=# \c torweather psql (15.3 (Debian 15.3-0+deb12u1), server 13.11 (Debian 13.11-0+deb11u1)) You are now connected to database "torweather" as user "postgres". torweather=# \d List of relations Schema | Name | Type | Owner --------+-----------------------------+----------+------------ public | admin | table | torweather public | admin_id_seq | sequence | torweather public | node_bandwidth_sub | table | torweather public | node_bandwidth_sub_id_seq | sequence | torweather public | node_down_sub | table | torweather public | node_down_sub_id_seq | sequence | torweather public | node_flag_exit_sub | table | torweather public | node_flag_exit_sub_id_seq | sequence | torweather public | node_flag_fast_sub | table | torweather public | node_flag_fast_sub_id_seq | sequence | torweather public | node_flag_guard_sub | table | torweather public | node_flag_guard_sub_id_seq | sequence | torweather public | node_flag_stable_sub | table | torweather public | node_flag_stable_sub_id_seq | sequence | torweather public | node_flag_valid_sub | table | torweather public | node_flag_valid_sub_id_seq | sequence | torweather public | node_version_sub | table | torweather public | node_version_sub_id_seq | sequence | torweather public | relay | table | torweather public | relay_id_seq | sequence | torweather public | subscriber | table | torweather public | subscriber_id_seq | sequence | torweather public | subscription | table | torweather public | subscription_id_seq | sequence | torweather (24 rows) torweather=# select count(*) from subscriber; count ------- 185 (1 row) torweather=# select count(*) from subscription; count ------- 7670 (1 row)the procedure to restore is as follows:
rsync -a /srv/f3005349888/ /var/lib/postgresql/13/main/ chown postgres:postgres /var/lib/postgresql/13/main/ chmod 750 /var/lib/postgresql/13/main/ sudo -u postgres /usr/lib/postgresql/13/bin/pg_resetwal -f . echo max_wal_senders = 0 > /etc/postgresql/13/main/conf.d/wal.conf echo hot_standby = no >> /etc/postgresql/13/main/conf.d/wal.conf echo restore_command = true > /etc/postgresql/13/main/conf.d/recovery.conf sudo -u postgres touch /var/lib/postgresql/13/main/recovery.signal rm /var/lib/postgresql/13/main/backup_label systemctl start postgresql@13-main.service sudo -u postgres pg_dumpall -p 5433 | pv > /srv/dump/dump.sqlso now there's a dump in
/srv/dump/dump.sql. the next step is to import it in the psql 15 cluster.Edited by anarcat - Last reply by Jérôme Charaoui
- Resolved by anarcat
i have recovered the dump:
sudo -u postgres psql < /srv/dump/dump.sqlthis loaded the records in the production, PostgreSQL 15 database. it now looks like the frontpage loads properly:
https://weather.torproject.org/login
i don't actually have an account on this, can someone else test that it works?
- Last reply by Georg Koppen
added Needs Review label and removed Doing label
mentioned in issue #41252 (closed)
-
i have done a timeline analysis of this incident, as part of a post-mortem. interesting take aways:
- this issue was open about 13 hours after the backups were restored. had it been filed a day before, recovery would have been much easier, without data loss. obviously, @anarcat should have notified the service admin to test the service after the upgrade as well. not having clear contact information on servers is partly in cause (I wasn't sure who the service admin was)
- Nagios did notice something wrong with the service (503 error) but this was somehow fixed by @lavamind even though the actual service was down, our monitoring of this service is therefore inadequate and we need to figure out a better way
i've also added a checklist to the issue summary, for next steps. the next step now is for me to review the upgrade log to see what exactly I did wrong in the upgrade procedure so that this never happens again in the first place.
-
@anarcat should have notified the service admin to test the service after the upgrade as well. not having clear contact information on servers is partly in cause (I wasn't sure who the service admin was)
I am not sure what you mean by "not having clear contact information"? There is https://gitlab.torproject.org/tpo/tpa/team/-/wikis/service/tor-weather where it says (see "Maintainer" there):
tor-weather is maintained by the network-health team.That's boiling down to pinging either me or hiro as a starter (although, arguably, the link on that document might better go to https://gitlab.torproject.org/tpo/network-health/team). But, if you need more than just a general pointer to network health, then feel free to mention particular people directly on the doc (even though I think a pointer to the team (as we have it right now) is a smarter idea).
-
Yep, failure on my part there, I guess.
I think one problem is we don't have that "in-band", on the server. Like this could be part of the
motdfor example, or in LDAP. It's not always obvious which "service" is bound to the server as well... in this case, I should really just have looked in the wiki, but I don't really feel the wiki is actually the best place to document this. It's just a temporary solution.So no blame here but my own: we need better inventory mechanisms, simply (#30273).
...
On 2023-11-09 08:22:05, Georg Koppen wrote:
Georg Koppen commented on a discussion: #41388 (comment 2963787)
@anarcat should have notified the service admin to test the service after the upgrade as well. not having clear contact information on servers is partly in cause (I wasn't sure who the service admin was)
I am not sure what you mean by "not having clear contact information"? There is https://gitlab.torproject.org/tpo/tpa/team/-/wikis/service/tor-weather where it says (see "Maintainer" there):
tor-weather is maintained by the network-health team.That's boiling down to pinging either me or hiro as a starter (although, arguably, the link on that document might better go to https://gitlab.torproject.org/tpo/network-health/team). But, if you need more than just a general pointer to network health, then feel free to mention particular people directly on the doc (even though I think a pointer to the team (as we have it right now) is a smarter idea).
-
upgrade tty recording analysis:
- step 8 actually purged the
postgresql13package... - ... but the package prompted as to whether or not we wanted to remove the data, and I responded
no, so that's not where the data was lost (although it could have been there) - after step 8, the PostgreSQL upgrade procedure was followed with the following command:
root@weather-01:~# export LC_ALL=C.UTF-8 && printf "about to stop cluster main on postgresql-13, press enter to continue" && read _ && pg_dropcluster --stop 13 main && pg_upgradecluster -m upgrade -k 13 main && for cluster in `ls /etc/postgresql/13/`; do mv /etc/postgresql/13/$cluster/conf.d/* /etc/postgresql/15/$cluster/conf.d/ done about to stop cluster main on postgresql-13, press enter to continueThat pipeline failed with the error:
Error: specified cluster does not existThe problem there is that I thought it was the
pg_dropclustercommand that failed, but that wasn't it! The failure was:root@weather-01:~# pg_upgradecluster -m upgrade -k 13 main Error: specified cluster does not existAnd at this point, the 13 cluster was gone. This was a critical error in the upgrade procedure: the
dropclustercommand should have targeted the new cluster, not the old one. An improvement to the procedure might be to make sure the new cluster is actually "empty", somehow.I even noticed the database being destroyed, according to the log (
ls /var/lib/postgresqlonly showed the 15 cluster andpsqlonly showed an empty database). At this point, it seems like I started recovering the old database by installing the postgresql-13 package. But somehow, during the restore procedure, I got confused and thought the database was already restored somehow.So instead of completing the recovery from the backup server, I went back to the upgrade procedure to upgrade the (now empty) 13 cluster to 15. Part of the confusion was due to this back-and-forth between the restore and the upgrade procedure. I got stuck on trying to make the new cluster talk with the backup server, for example, which was very distracting.
Having all PostgreSQL servers properly managed by Puppet (as opposed to having to manually update
pg_hba.conf) would improve that situation as well.So that's it! The root cause of the problem was a faulty upgrade procedure that was destroying the live, production database server, compounded with a lack of proper monitoring, lack of communication of the upgrade, and lack of automation of the database servers.
Recommendations:
- fix the upgrade procedure to ensure the
pg_dropclustercommand is only ran on an empty database (alternatively: automate the procedure so that it's hard or impossible to confuse the production (13 in this case) and target (15) clusters - properly monitor the Weather service, possibly through prometheus and the
prometheus-alertsrepository - properly communicate to service admins the upgrade completion
- puppetize all PostgreSQL servers
- step 8 actually purged the
marked the checklist item analyze upgrade logs to figure out what happened and how to prevent it (@anarcat) as completed
marked the checklist item recommend (monitoring?) improvements to prevent this from happening again (@anarcat) as completed
-
@gk / @sarthikg i think the service is back now, could you confirm? i also feel like monitoring on this service is really bad, could you see if you can figure out a merge request to add alerting for the service in https://gitlab.torproject.org/tpo/tpa/prometheus-alerts/?
marked the checklist item post-mortem (@anarcat) as completed
marked the checklist item document data recovery procedures (@anarcat) as completed
mentioned in commit wiki-replica@e745c9c0
mentioned in commit wiki-replica@6c23d5ea
mentioned in commit status-site@1b01edc9
mentioned in merge request status-site!40 (merged)
mentioned in commit status-site@c87c5ae6
-
@lavamind / @gk i made a MR to update the status page to reflect the recovery, can one of you review/push? status-site!40 (merged)
mentioned in issue tpo/community/hackweek#26 (closed)
mentioned in commit status-site@ef6b441f
-
i just realized another thing: a key problem here is the backups were destroyed after 7 days. that's a tad short: database backups are normally kept for four weeks, if my memory is correct, so maybe we could change the procedure to do that.
in fact, i wonder why we move that directory around in the first place. shouldn't we just keep it in the same directory and leave the normal backup rotation operate?
something to review anyway, adding to the checklist here.
marked the checklist item mark incident as resolved in status site (@anarcat, see status-site!40 (merged)) as completed
mentioned in issue status-site#32 (closed)
marked this incident as related to status-site#32 (closed)
- Resolved by anarcat
@lavamind what's the status on status-site!40 (merged)? the branch was merged, but prod wasn't push, is that intentional?
i opened status-site#32 (closed) to propose to remove the staging as a consequence of this and also other similar situations, rationale detailed there.
- Last reply by anarcat
mentioned in commit status-site@b586131b
mentioned in merge request status-site!41 (merged)
mentioned in commit status-site@0ded775f
mentioned in commit status-site@c4dced70
mentioned in commit status-site@568bb01e
mentioned in commit status-site@14a5a417
mentioned in commit status-site@32303d81
mentioned in commit status-site@a478b9cd
mentioned in commit status-site@43e49f7c
mentioned in commit status-site@96005bba
mentioned in commit status-site@9308551d
mentioned in commit status-site@35aa9461
mentioned in commit status-site@700e7d8d
mentioned in commit status-site@c2bbdef4
mentioned in commit status-site@7291b33f
