hanke580 opened a new issue, #4145:
URL: https://github.com/apache/iceberg-python/issues/4145
### 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):
```python
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:
```bash
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
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
