Local warehouse (`file://`): data files, manifests and `metadata.json` are never fsynced before the catalog commit; after a power loss the table cannot be loaded

Start with PyArrowLocalFileSystem.open_output_stream and PyArrowFile.create in pyiceberg/io/pyarrow.py, then trace Catalog._write_metadata and SqlCatalog.commit_table in pyiceberg/catalog/init.py and pyiceberg/catalog/sql.py. The report links open PR #4146, so work may already be underway. Done means files and directories referenced by a committed catalog pointer are durable before that pointer changes; verify with the provided strace and power-cut reproductions.

Apache Iceberg version

main (development)

Please describe the bug 🐞

With a local warehouse (warehouse="file://...", PyArrowFileIO with PyArrowLocalFileSystem), PyIceberg writes
every new file (Parquet data files, *-m0.avro manifests, snap-*.avro manifest lists, NNNNN-<uuid>.metadata.json)
through pyarrow.fs.LocalFileSystem.open_output_stream() and closes it, but never calls fsync on any of them or on
their directories. It then swaps the catalog pointer to the new metadata.json. The catalog backend syncs its own
commit (SQLite: fdatasync of the journal, the directory and the database file), and that commit also forces the
ext4 journal, which makes the creation of the new files durable while their contents are still only in the page
cache.

After a power loss (or kernel crash) shortly after an acknowledged commit, every file PyIceberg wrote is present
but 0 bytes, and the catalog points to a 0-byte metadata.json:

pyiceberg.catalog.load_table("ns.t")
  ValidationError: 1 validation error for TableMetadataWrapper
  Invalid JSON: EOF while parsing a value at line 1 column 0 [type=json_invalid, input_value='', input_type=str]

So one commit makes the whole table unloadable, including every earlier snapshot, because the table is opened
only through the newest metadata file and the older metadata files are just as empty. There is no supported way
to fall back. A plain process kill (no power loss) is always fine, because the page cache survives.

With the SQLite catalog there is a second, smaller effect: SQLite's default rollback journal (journal_mode=DELETE,
synchronous=FULL) commits by unlinking catalog.db-journal without syncing the directory, so after the power
loss the hot journal rolls back the most recent catalog transaction. The catalog then points to the previous
metadata.json (also 0 bytes), and a table created just before the cut disappears from the catalog. That part
would be fixed by PRAGMA synchronous=EXTRA (or WAL mode) on the SQLite connection. The main problem, the
unsynced warehouse files, is independent of the catalog: with a PostgreSQL catalog (on another disk) and a local warehouse
the new pointer survives the cut and points to a metadata.json that is either missing (cut before ext4's next
journal commit: FileNotFoundError) or 0 bytes (cut after it: the same ValidationError).

How to reproduce

Linux, ext4. pip install "pyiceberg[sql-sqlite,pyarrow] @ git+https://github.com/apache/iceberg-python@main" (or
pyiceberg[sql-sqlite,pyarrow]==0.12.0); pyarrow 25.0.1 / 19.0.1, SQLAlchemy 2.0.55.

ice_write.py (create a table and append n batches):

import sys
import pyarrow as pa
from pyiceberg.catalog.sql import SqlCatalog
d, n = sys.argv[1], int(sys.argv[2])
cat = SqlCatalog("default", uri=f"sqlite:///{d}/catalog.db", warehouse=f"file://{d}/wh")
cat.create_namespace("ns")
schema = pa.schema([("id", pa.int64()), ("v", pa.string())])
t = cat.create_table("ns.t", schema=schema)
print("ACK create_table ns.t", flush=True)
for i in range(n):
    lo = i * 100
    t.append(pa.table({"id": list(range(lo, lo + 100)), "v": [f"r{j}" for j in range(lo, lo + 100)]}, schema=schema))
    print(f"ACK append {lo}..{lo + 100}", flush=True)

1. The missing syncs, no power cut needed. Trace the writer (one append):

mkdir -p /tmp/w
strace -f -y -qq -e trace=openat,fsync,fdatasync,rename,unlink -o trace.txt python ice_write.py /tmp/w 1

Relevant lines (paths shortened to D):

openat(... "D/wh/ns/t/metadata/00000-cf4c...metadata.json", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
fdatasync(4<D/catalog.db-journal>) = 0         <- SQLite commits create_table
fdatasync(5<D>) = 0
fdatasync(4<D/catalog.db-journal>) = 0
fdatasync(3<D/catalog.db>) = 0
unlink("D/catalog.db-journal") = 0
openat(... "D/wh/ns/t/data/00000-0-5714...parquet", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
openat(... "D/wh/ns/t/metadata/5714...-m0.avro", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
openat(... "D/wh/ns/t/metadata/snap-7160...avro", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
openat(... "D/wh/ns/t/metadata/00001-1f6f...metadata.json", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
fdatasync(4<D/catalog.db-journal>) = 0         <- SQLite commits the new metadata_location
fdatasync(5<D>) = 0
fdatasync(4<D/catalog.db-journal>) = 0
fdatasync(3<D/catalog.db>) = 0
unlink("D/catalog.db-journal") = 0

No fsync/fdatasync of any file under wh/ and of no directory under wh/, before or after the catalog commit.

2. Emulated power cut. The warehouse is on ext4 over a device-mapper linear target; after the writer has exited,
the table is switched to error without flushing, which drops everything not yet on the device, like a power cut
(commit=3600 only makes the run deterministic by disabling ext4's own 5 s journal commit; with the default
commit=5 we got the same result for cuts up to about 10 s after the writer exited, after which background writeback
had usually written the files). As root:

W=$(mktemp -d); IMG=$W/disk.img; MP=$W/mnt; mkdir -p $MP
truncate -s 1G $IMG; LOOP=$(losetup -f --show $IMG)
dmsetup create icecut --table "0 2097152 linear $LOOP 0"
mkfs.ext4 -q /dev/mapper/icecut; mount -o noatime,commit=3600 /dev/mapper/icecut $MP; sync -f $MP
python ice_write.py $MP 2                    # ACK create_table, ACK append 0..100, ACK append 100..200
sleep 2
# power cut
dmsetup suspend --noflush --nolockfs icecut
dmsetup load icecut --table "0 2097152 error"; dmsetup resume icecut
umount -l $MP; dmsetup remove icecut; losetup -d $LOOP
# "reboot"
LOOP=$(losetup -f --show $IMG); mount $LOOP $MP
find $MP/wh -type f -printf '%s %p\n'
python -c "
from pyiceberg.catalog.sql import SqlCatalog
cat = SqlCatalog('default', uri='sqlite:///$MP/catalog.db', warehouse='file://$MP/wh')
print(cat.load_table('ns.t').scan().to_arrow().num_rows)"
umount $MP; losetup -d $LOOP

Output on main (before the cut the same load_table returns 200 rows):

0 .../wh/ns/t/data/00000-0-74ed3971-...parquet
0 .../wh/ns/t/data/00000-0-d879fe98-...parquet
0 .../wh/ns/t/metadata/00000-c4457e76-...metadata.json
0 .../wh/ns/t/metadata/00001-30081b89-...metadata.json
0 .../wh/ns/t/metadata/00002-03b3aab8-...metadata.json
0 .../wh/ns/t/metadata/74ed3971-...-m0.avro
0 .../wh/ns/t/metadata/d879fe98-...-m0.avro
0 .../wh/ns/t/metadata/snap-4421089994007795917-0-d879fe98-...avro
0 .../wh/ns/t/metadata/snap-9103608114772306948-0-74ed3971-...avro
pydantic_core._pydantic_core.ValidationError: 1 validation error for TableMetadataWrapper
  Invalid JSON: EOF while parsing a value at line 1 column 0 [type=json_invalid, input_value='', input_type=str]

(The catalog row now points to 00001-...metadata.json, previous 00000-...: the last SQLite transaction was
rolled back from the hot journal, see above. Both files are empty.) With n = 0 (only create_table), the table
is gone: NoSuchTableError: Table does not exist: ns.t.

We ran the same with a longer workload (appends, delete, overwrite, a schema change, a second table created and
dropped; 1 to 10 commits, plain cut and cut right after an ext4 journal commit): every run after the first data
commit ends with the ValidationError above, on main and on 0.12.0. Plain SIGKILL at the same points: the table
loads with all acknowledged rows.

Expected behavior

Once append() / create_table() / any commit returns, the files the new metadata references and the
metadata.json itself are durable before the catalog pointer is swapped, so that a power loss leaves the table at
the last acknowledged commit (or, at worst, at an earlier one), never pointing at a file that is empty.

On object stores an acknowledged PUT is durable, so the commit protocol is safe there. On a local file system the
FileIO has to provide the same guarantee: fsync each written file before closing it (data files, manifests,
manifest lists, metadata JSON) and fsync the directories it created entries in, before the catalog commit.

Where in the code (main @ eb30d8ae)

• PyArrowLocalFileSystem.open_output_stream only creates the parent directory and delegates to
  pyarrow.fs.LocalFileSystem, whose output stream does not sync on close:
  https://github.com/apache/iceberg-python/blob/eb30d8ae6ac4054f751b91cb04d4ae5026354cc2/pyiceberg/io/pyarrow.py#L252-L256
• PyArrowFile.create returns that stream for every file PyIceberg writes:
  https://github.com/apache/iceberg-python/blob/eb30d8ae6ac4054f751b91cb04d4ae5026354cc2/pyiceberg/io/pyarrow.py#L357-L385
• Catalog._write_metadata writes the new metadata JSON through it:
  https://github.com/apache/iceberg-python/blob/eb30d8ae6ac4054f751b91cb04d4ae5026354cc2/pyiceberg/catalog/__init__.py#L1126-L1127
• SqlCatalog.commit_table writes the metadata file and then commits the new metadata_location:
  https://github.com/apache/iceberg-python/blob/eb30d8ae6ac4054f751b91cb04d4ae5026354cc2/pyiceberg/catalog/sql.py#L479-L560
  (create_table likewise, L245-L296).
• file maps to PyArrowFileIO, falling back to FsspecFileIO, whose local file system does not sync either:
  https://github.com/apache/iceberg-python/blob/eb30d8ae6ac4054f751b91cb04d4ae5026354cc2/pyiceberg/io/__init__.py#L325

The documentation describes the local SQLite + local file system getting-started setup as not for production "due to
the limited scalability", and says "SQLite is not built for concurrency, you should use this catalog for exploratory
or development purposes"; neither it nor the FileIO docs say that a local (file://) warehouse, with any catalog, can
be left unloadable by a power loss after an acknowledged commit.

For comparison: the Java HadoopFileIO on file:// (Hadoop RawLocalFileSystem) does not sync on close either,
while iceberg-rust's local file IO goes through OpenDAL's fs service, whose writer calls sync_all() on close.

Related

No earlier report found (searched issues/PRs for fsync, power loss, durability, crash, empty metadata).
#1328 shows the same TableMetadataWrapper "Invalid JSON" error, caused there by an S3 permission problem.

Willingness to contribute

• I can contribute a fix for this bug independently
• I would be willing to contribute a fix for this bug with guidance from the Iceberg community
• I cannot contribute a fix for this bug at this time