How I did (not) recover from a data loss (featuring ZFS, LXD and PostgreSQL)

databasehomelablinuxlxdsysadminzfs
How I did (not) recover from a data loss (featuring ZFS, LXD and PostgreSQL)

As some may know, I'm running a Mastodon instance. It's a quite big instance with about 1000 weekly active users and 13k local accounts in total.

My current setup is a Hetzner Cloud CX41 VM running LXC containers with LXD. They are stored on a dedicated zpool on a separate partition of the disk. In this case, I have a dedicated container for the PostgreSQL server.

I was quite surprised when I looked at the state of my zpool last week:

root@kokoro ~# zpool status -v
  pool: zpool-lxd
 state: ONLINE
status: One or more devices has experienced an error resulting in data
 corruption. Applications may be affected.
action: Restore the file in question if possible. Otherwise restore the
 entire pool from backup.
   see: http://zfsonlinux.org/msg/ZFS-8000-8A
  scan: scrub repaired 0B in 0h56m with 7 errors on Sun Mar 3 18:29:34 2019
config:

 NAME STATE READ WRITE CKSUM
 zpool-lxd ONLINE 0 0 0
   sda3 ONLINE 0 0 0

errors: Permanent errors have been detected in the following files:

        <0x1f40>:<0x6f840>
        <0x1f40>:<0x1858a>
        <0x1956>:<0x18e13>
        <0x1956>:<0x18bcc>
        <0xc63>:<0x3604c>
        <0x8bbf>:<0x952e>
        zpool-lxd/containers/postgresql:/rootfs/var/lib/postgresql/11/main/base/20415/20819.9

The hexadecimal stuff are deleted auto-snapshots of some datasets, but what is concerning is the PostgreSQL file. I tried multiple ZFS scrubs without success.

I checked the PostgreSQL logs and there was indeed a few failing queries:

root@postgresql ~# grep 'Input/output error' /var/log/postgresql/postgresql-11-main.log | tail
2019-03-06 20:54:19.224 CET [11371] ERROR: could not read block 1264349 in file "base/20415/20819.9": Input/output error
2019-03-06 20:54:19.225 CET [11284] mstdn@mstdn ERROR: could not read block 1264349 in file "base/20415/20819.9": Input/output error
2019-03-06 22:05:04.540 CET [11533] mstdn@mstdn ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
2019-03-07 00:02:48.709 CET [12615] mstdn@mstdn ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
2019-03-07 02:25:30.946 CET [13670] mstdn@mstdn ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
2019-03-07 04:07:40.608 CET [14447] mstdn@mstdn ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
2019-03-07 06:09:58.351 CET [15667] mstdn@mstdn ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
2019-03-07 06:56:37.034 CET [16238] mstdn@mstdn ERROR: could not read block 1264341 in file "base/20415/20819.9": Input/output error
2019-03-07 06:56:57.828 CET [16505] ERROR: could not read block 1264341 in file "base/20415/20819.9": Input/output error
2019-03-07 06:56:57.830 CET [15870] mstdn@mstdn ERROR: could not read block 1264341 in file "base/20415/20819.9": Input/output error

Now, the PSQL server is handling about ~200 queries per second, so there are actually very few queries failing.

I could also confirm there was some errors in the application's logs:

Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b] method=GET path=/api/v1/timelines/tag/fun format=html controller=Api::V1::Timelines::TagController action=show status=500 error='ActiveRecord::StatementInvalid: PG::IoError: ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b]
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b] ActiveRecord::StatementInvalid (PG::IoError: ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b]
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b] app/controllers/application_controller.rb:109:in `cache_collection'
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b] app/controllers/api/v1/timelines/tag_controller.rb:25:in `cached_tagged_statuses'
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b] app/controllers/api/v1/timelines/tag_controller.rb:21:in `load_statuses'
Mar 06 22:05:04 mstdn bundle[4703]: [7160cec0-24f8-4930-b249-f85f755f900b] app/controllers/api/v1/timelines/tag_controller.rb:10:in `show'

...

2019-03-04 06:08:21.734 CET [19320] mstdn@mstdn ERROR: could not read block 843725 in file "base/20415/20819.6": Input/output error
2019-03-04 06:08:21.734 CET [19320] mstdn@mstdn CONTEXT: parallel worker
2019-03-04 06:08:21.734 CET [19320] mstdn@mstdn STATEMENT: SELECT DISTINCT "statuses"."id", "statuses"."updated_at" FROM "statuses" INNER JOIN "statuses_tags" ON "statuses_tags"."status_id" = "statuses"."id" LEFT OUTER JOIN "accounts" ON "accounts"."id" = "statuses"."account_id" WHERE "statuses"."visibility" = 0 AND (statuses.reblog_of_id IS NULL) AND "statuses_tags"."tag_id" = 210 AND "statuses"."account_id" NOT IN (245693, 20285) AND "accounts"."silenced" = FALSE ORDER BY "statuses"."id" DESC LIMIT 4

...

2019-03-04 04:20:04.149 CET [18597] mstdn@mstdn ERROR: could not read block 843720 in file "base/20415/20819.6": Input/output error
2019-03-04 04:20:04.149 CET [18597] mstdn@mstdn STATEMENT: SELECT DISTINCT "statuses"."id", "statuses"."updated_at" FROM "statuses" INNER JOIN "statuses_tags" ON "statuses_tags"."status_id" = "statuses"."id" LEFT OUTER JOIN "accounts" ON "accounts"."id" = "statuses"."account_id" WHERE "statuses"."visibility" = 0 AND (statuses.reblog_of_id IS NULL) AND "statuses_tags"."tag_id" = 2721 AND "accounts"."silenced" = FALSE ORDER BY "statuses"."id" DESC LIMIT 20

This is still concerning because the corrupted file is about 1 GB.

The most important issue was that all my dumps for the past few days have been failing:

postgres@postgresql:~$ pg_dump -Fc mstdn -f mstdn.dump
pg_dump: Dumping the contents of table "statuses" failed: PQgetResult() failed.
pg_dump: Error message from server: ERROR: could not read block 1264336 in file "base/20415/20819.9": Input/output error
pg_dump: The command was: COPY public.statuses (id, uri, text, created_at, updated_at, in_reply_to_id, reblog_of_id, url, sensitive, visibility, spoiler_text, reply, language, conversation_id, local, account_id, application_id, in_reply_to_account_id) TO stdout;

The public.statuses is by far the biggest table in the database since it contains all of the local and foreign toots (43M rows) so I can't skip it.

It turned out I couldn't do anything that required reading this file.

I couldn't:

  • dump the database
  • copy the database raw files (with either cp or dd)
  • export the LXD container or a snapshot
  • migrate the LXD container or a snapshot to another host
  • export the containers' ZFS dataset

Each of these would fail when they encountered of the corrupted blocks of the file.

root@postgresql ~# cp /var/lib/postgresql/11/main/base/20415/20819.9 .
cp: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
root@postgresql ~# ll /var/lib/postgresql/11/main/base/20415/20819.9
-rw------- 1 postgres postgres 1.0G Mar 11 22:57 /var/lib/postgresql/11/main/base/20415/20819.9
root@postgresql ~# ll 20819.9
-rw------- 1 root root 662M Mar 11 23:00 20819.9
root@postgresql ~# dd if=/var/lib/postgresql/11/main/base/20415/20819.9 of=20819.9.dd
dd: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
1355008+0 records in
1355008+0 records out
693764096 bytes (694 MB, 662 MiB) copied, 14.2534 s, 48.7 MB/s
root@postgresql ~#

Also, it was out of question to restore a backup since it would mean I'd lost multiple days of data, which is way worse that a few failing requests a day. But I couldn't leave thing like this.

My zpool seems corrupted in a way or another, since it reports some corrupted files, then after a few hours, they're not corrupted anymore, and some other files seem to be corrupted. These symptoms indicate a failing disk, but I have virtual disk on top of the hypervisor's SSD RAID... I really don't know what's wrong.

Anyway, out of all the "corrupted" files, /var/lib/postgresql/11/main/base/20415/20819.9 was not getting better, so it meant it was really corrupted.

Lost for lost, I decided to do something that would really make me loose this data forever: remove the corrupted blocks from the file.

FYI, I launched a new VM from an older snaphost in order to test this before doing it on the production VM.

As shown above, dd would fail when it encountered the first corrupted block.

The solution is to use the noerror option, which means dd will ignore the errors and continue. Our new file will have the same content but will be empty where the corrupted blocks were.

The result is - somewhat - a success. I'm not sure what the default block size is, but dd failed 256 times around 662 MiB.

root@postgresql ~# dd if=/var/lib/postgresql/11/main/base/20415/20819.9 of=20819.9.dd conv=sync,noerror
dd: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
1355008+0 records in
1355008+0 records out
693764096 bytes (694 MB, 662 MiB) copied, 14.0675 s, 49.3 MB/s
dd: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
1355008+1 records in
1355009+0 records out
693764608 bytes (694 MB, 662 MiB) copied, 14.0689 s, 49.3 MB/s
dd: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
1355008+2 records in
1355010+0 records out
693765120 bytes (694 MB, 662 MiB) copied, 14.0696 s, 49.3 MB/s

...

dd: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
1355008+254 records in
1355262+0 records out
693894144 bytes (694 MB, 662 MiB) copied, 14.3103 s, 48.5 MB/s
dd: error reading '/var/lib/postgresql/11/main/base/20415/20819.9': Input/output error
1355008+255 records in
1355263+0 records out
693894656 bytes (694 MB, 662 MiB) copied, 14.3117 s, 48.5 MB/s
2096896+256 records in
2097152+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 22.1875 s, 48.4 MB/s

Some simple calculations. Errors start at 693764096 and ends at 693894656 which means 130560 B = 127.5 KiB of corrupted/lost data. That's 0,000003% of the database size, so I guess I should be able to live with it. It's also infuriating (but logical) that such a tiny amount of data can make such a mess.

Let's replace the file:

root@postgresql ~# ll 20819.9.dd
-rw-r--r-- 1 root root 1.0G Mar 11 23:37 20819.9.dd
root@postgresql ~# cd /var/lib/postgresql/11/main/base/20415/
root@postgresql /v/l/p/1/m/b/20415# mv 20819.9 20819.9.old
root@postgresql /v/l/p/1/m/b/20415# cp ~/20819.9.dd 20819.9
root@postgresql /v/l/p/1/m/b/20415# chown postgres:postgres 20819.9

Of course I stopped the PostgreSQL server during the operation.

Since then, I have not had a single failing query related to I/O:

root@postgresql ~# grep 'Input/output error' /var/log/postgresql/postgresql-11-main.log | wc -l
0
root@postgresql ~# grep 'Input/output error' /var/log/postgresql/postgresql-11-main.log.1 | tail -5
2019-03-09 16:22:46.269 CET [14465] mstdn@mstdn ERROR: could not read block 1264350 in file "base/20415/20819.9": Input/output error
2019-03-09 17:32:08.646 CET [16096] mstdn@mstdn ERROR: could not read block 1264350 in file "base/20415/20819.9": Input/output error
2019-03-09 17:43:54.887 CET [16763] mstdn@mstdn ERROR: could not read block 1264346 in file "base/20415/20819.9": Input/output error
2019-03-09 19:24:59.579 CET [17444] mstdn@mstdn ERROR: could not read block 1264350 in file "base/20415/20819.9": Input/output error
2019-03-09 21:24:06.808 CET [408] mstdn@mstdn ERROR: could not read block 1264351 in file "base/20415/20819.9": Input/output error
root@postgresql ~# date
Sat Mar 16 15:43:15 CET 2019

Success! I can now dump the database too.

As expected the 20819.9 file was not reported as corrupted by zpool status -v, but 20819.9.old was, so I deleted it since I didn't need it anymore.

I'm not an expert in file systems or databases, but I thought it was an experience worth sharing. I definitely lost a bit of non-critical data, but it was the best outcome. I had very little downtime and I didn't have to restore dumps which would have make me loss way more data. The same issue affecting the accounts table could have been disastrous.

I still have errors that come and go on my zpool. I am a bit concerned since I don't know the source of these errors. Is the underlying storage corrupted or unreliable? Did I corrupt something myself? Is it a bug with ZOL? LXD? I don't know.

This VM is not even a month old but I guess I have to start a new one from scratch and migrate my containers. Will use ZFS though? I'm not sure.

Stanislas
Author
Stanislas
I like building things with code and computers

Related Posts

How I fixed ZFS data corruption errors on Hetzner Cloud
How I fixed ZFS data corruption errors on Hetzner Cloud
Setup a ZFS pool for your LXC containers with LXD
Setup a ZFS pool for your LXC containers with LXD
Doing in-place, single-node Postgres upgrades with almost no downtime
Doing in-place, single-node Postgres upgrades with almost no downtime

Comments

11Atom feed
Markdown supported
  1. Edward Torvalds

    Isn't ZFS supposed to fix corrupted data and meta? Did you try repairing the file system? If ZOL has bug may be you should try BTRFS?

    1. StanislasAuthor

      That's what I thought too. Apparently it only does so with multiple disks. I tried scrubs without success. I don't know if it's a ZOL bug, but I've heard worse stories about btrfs...

    2. Anonymous

      ZFS does repair corrupted data and metadata, but you need to actually have a copy of the uncorrupted data and metadata in order to repair it. ZFS does have some additional tricks to help protect metadata (it gets replicated with more copies than data) but it's simply very bad practice to put important data on a disk without any redundancy (regardless of whether you're using ZFS). If you'd had a mirror then you wouldn't have had an issue and the data would've been auto-corrected. Yes, this logic also applies to fake disks created by a hypervisor.

      ZFS isn't magic, it still has to obey the laws of physics.

  2. Ivan

    Good write-up about how you repaired the thing, thank you for sharing!

    Regarding the ZFS stuff, since you're running it on single virtual drive the whole replication stuff is out of your control I guess. There is myriad of things that could go wrong, some of them already mentioned by you but worth repeating:

    • VM crashed in the middle of write operation
    • backing block storage has suffered some issues
    • bug in ZoL
    • bug in PostgreSQL (fsync)

    To mitigate such issues it is best to have mirror of drives or other kind of RAID setup. The next best thing after that, if you really only can have one drive, is to have copies=2, that will effectively double disk space usage since ZFS will keep 2 copies of each block.

    If there is only 1 copy of the block ZFS can't recover, but at least it can detect and you can hope snapshot holds the good data so you can restore from that (hint: hidden .zfs folder in each dataset, can't see it by default but you can cd into it, to have it visible you can set snapdir to visible)

    In either case I wholeheartedly recommend going with ZFS wherever. As for Hetzner, look at their dedicated server offerings. I have gotten myself a used server via https://www.hetzner.com/sb , they're not too expensive, and you get real hardware.

    1. StanislasAuthor

      Thanks for your comment and tips, especially for the .zfs one, that's so cool!

  3. Vincib

    thanks for the post :) and good luck for the migration! I'm using ZFS since years here, and never had an issue, and I'm really wondering what went wrong ... Did you test your memory (and not just for a few seconds, at least a few hours ...)? I don't see anything else that could crash a ZFS filesystem THAT badly :(

  4. Stef

    Hi Angristan,

    I was wondering if you'd found he root cause of this issue ? Do you still use ZFS with lxd ? (mitigation plan ?) Maybe ZFS is not the best option with a cloud server :-(

    2. Stef

      Hello, Thanks for your answer.

      You can add a "block volume" as a mirror to the zpool which should help too !

      I'll read these posts & cross fingers ! :-)

  5. sola

    I recommend using pgBackrest or similar for your Postgres database. That protects agains running corruptions like this by archiving the WAL log on top of periodic full backups. That way you can always restore your database.

↑