Incorrect table definition after executing rollback_to_snapshot procedure

[ebyhr]

Apache Iceberg version

0.14.0 (latest release)

Query engine

Spark

Please describe the bug 🐞

Spark returns the latest table definition even after executing rollback_to_snapshot procedure.

Steps to reproduce

> CREATE TABLE test USING iceberg AS SELECT 1 c1;
> ALTER TABLE test ADD COLUMN c2 int;
> INSERT INTO test VALUES (1, 1);
> SELECT * FROM iceberg_test.default.test.snapshots;
2022-08-19 07:32:29.499	2770581293596517273 ...
2022-08-19 07:32:50.006	6893045681966948046 ...

> DESC iceberg_test.default.test.snapshot_id_2770581293596517273;
c1                  	int

# Partitioning
Not partitioned

> CALL iceberg_test.system.rollback_to_snapshot('default.test', 2770581293596517273);
> DESC iceberg_test.default.test;
c1                  	int
c2                  	int

The result is same even after I executed REFRESH TABLE iceberg_test.default.test after rollback_to_snapshot.

Relates to https://apache-iceberg.slack.com/archives/C025PH0G1D4/p1660895079836159
Trino issue trinodb/trino#13699

[Fokko]

I'm able to reproduce it and it looks like the data is rolebacked, but the schema isn't.

%%sql

CREATE TABLE test.test USING iceberg AS SELECT 1 c1;

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

%%sql

ALTER TABLE test.test ADD COLUMN c2 int;

%%sql

INSERT INTO test.test VALUES (1, 1);

%%sql

SELECT * FROM test.test;

c1	c2
1	None
1	1

%%sql

SELECT * FROM test.test.snapshots;

committed_at	snapshot_id	parent_id	operation	manifest_list	summary
2022-08-22 07:47:45.143000	5161623784319151399	None	append	s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/snap-5161623784319151399-1-cde4c05b-670c-47dd-8860-bcd6f07756f9.avro	{'added-data-files': '1', 'total-equality-deletes': '0', 'added-records': '1', 'partition-summaries-included': 'true', 'partitions.': 'added-data-files=1,added-records=1,added-files-size=389', 'total-records': '1', 'spark.app.id': 'local-1661154453400', 'changed-partition-count': '1', 'total-position-deletes': '0', 'added-files-size': '389', 'total-delete-files': '0', 'total-files-size': '389', 'total-data-files': '1'}
2022-08-22 07:47:52.492000	2279922865032537001	5161623784319151399	append	s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/snap-2279922865032537001-1-58b2d439-1420-49c2-bf06-228c77f1ebd0.avro	{'added-data-files': '1', 'total-equality-deletes': '0', 'added-records': '1', 'partition-summaries-included': 'true', 'partitions.': 'added-data-files=1,added-records=1,added-files-size=599', 'total-records': '2', 'spark.app.id': 'local-1661154453400', 'changed-partition-count': '1', 'total-position-deletes': '0', 'added-files-size': '599', 'total-delete-files': '0', 'total-files-size': '988', 'total-data-files': '2'}

%%sql

CALL system.rollback_to_snapshot('test.test', 5161623784319151399)

previous_snapshot_id	current_snapshot_id
2279922865032537001	5161623784319151399

%%sql

SELECT * FROM test.test;

c1	c2
1	None

%%sql

DESCRIBE TABLE test.test;

col_name	data_type	comment
c1	int
c2	int
# Partitioning
Not partitioned

%%sql

SELECT * FROM test.test.snapshots;

committed_at	snapshot_id	parent_id	operation	manifest_list	summary
2022-08-22 07:47:45.143000	5161623784319151399	None	append	s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/snap-5161623784319151399-1-cde4c05b-670c-47dd-8860-bcd6f07756f9.avro	{'added-data-files': '1', 'total-equality-deletes': '0', 'added-records': '1', 'partition-summaries-included': 'true', 'partitions.': 'added-data-files=1,added-records=1,added-files-size=389', 'total-records': '1', 'spark.app.id': 'local-1661154453400', 'changed-partition-count': '1', 'total-position-deletes': '0', 'added-files-size': '389', 'total-delete-files': '0', 'total-files-size': '389', 'total-data-files': '1'}
2022-08-22 07:47:52.492000	2279922865032537001	5161623784319151399	append	s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/snap-2279922865032537001-1-58b2d439-1420-49c2-bf06-228c77f1ebd0.avro	{'added-data-files': '1', 'total-equality-deletes': '0', 'added-records': '1', 'partition-summaries-included': 'true', 'partitions.': 'added-data-files=1,added-records=1,added-files-size=599', 'total-records': '2', 'spark.app.id': 'local-1661154453400', 'changed-partition-count': '1', 'total-position-deletes': '0', 'added-files-size': '599', 'total-delete-files': '0', 'total-files-size': '988', 'total-data-files': '2'}

%%sql

REFRESH TABLE test.test

%%sql

SELECT * FROM test.test;

c1	c2
1	None

Waiting one minute

%%sql

SELECT * FROM test.test;

c1	c2
1	None

[Fokko]

It looks like the current_schema_id is not being updated when rolling back to an earlier snapshot:

➜  iceberg git:(master) ✗ pyiceberg describe test.test
Table format version  1                                                                                                                                                                                                                               
Metadata location     s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/00003-8b6eeb0f-76fc-435f-a25f-12db7baf62ff.gz.metadata.json                                                    
Table UUID            43fe073e-9360-4f4e-8ee7-d22d4969f9d1                                                                                                                                                                                            
Last Updated          1661154486212                                                                                                                                                                                                                   
Partition spec        []                                                                                                                                                                                                                              
Sort order            []                                                                                                                                                                                                                              
Current schema        Schema, id=1                                                                                                                                                                                                                    
                      ├── 1: c1: optional int                                                                                                                                                                                                         
                      └── 2: c2: optional int                                                                                                                                                                                                         
Current snapshot      id=5161623784319151399, schema_id=0                                                                                                                                                                                             
Snapshots             Snapshots                                                                                                                                                                                                                       
                      ├── Snapshot 5161623784319151399, schema 0:                                                                                                                                                                                     
                      │   s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/snap-5161623784319151399-1-cde4c05b-670c-47dd-8860-bcd6f07756f9.avro                                       
                      └── Snapshot 2279922865032537001, schema 1:                                                                                                                                                                                     
                          s3://tabular-wh-us-west-2-dev/8bcb0838-50fc-472d-9ddb-8feb89ef5f1e/03b32560-7561-4f96-992b-01ef730946f5/metadata/snap-2279922865032537001-1-58b2d439-1420-49c2-bf06-228c77f1ebd0.avro                                       
Properties            write.delete.parquet.compression-codec  zstd                                                                                                                                                                                    
                      write.metadata.compression-codec        gzip                                                                                                                                                                                    
                      write.summary.partition-limit           100                                                                                                                                                                                     
                      write.parquet.compression-codec         zstd  

[Fokko]

@ebyhr Thanks for reporting this, this looks like a bug 🐛 I've created a PR to fix this, but I would love to get some input from other maintainers.

[rdblue]

This isn't a bug. Metadata and data updates are intended to be separate, although I can see why there are cases where you'd assume that they are not.

If you update the schema and commit data in a single job, then it isn't unreasonable to assume the schema change would be rolled back. But if I concurrently add a column while someone else commits, then a rollback should be independent. Expectations can go both ways.

While expectations differ, Iceberg never rolls back to a previous schema because that operation is unsafe. For example, if someone deletes a required column and then tries to roll that back, there may have been data written without that column. You can recover the column, but you need to make it optional (or in the future, set a read default).

[Fokko]

@rdblue thanks for the background information. I see the point.

One question, are there situations where it is possible to do a rollback, but still have additional data being written? I would expect that the rollback would cause a conflict on a concurrent write. And then it would fail because of a schema mismatch.

[rdblue]

Schema evolution rules allow always being able to write with an older schema, so that there is no need to check whether the schema a writer is using is allowed. That cuts down on commit conflicts, but it also means that schemas should always be rolled forward and never backward. I don't think that we want to start adding extra validation to support a case where we roll back a schema.

[ebyhr]

This isn't a bug.

Could you please document the behavior or is it mentioned in somewhere? I believe the current behavior isn't intuitive and I saw some other people in Iceberg community said "it's a bug".

[findepi]

From end-user perspective, there is a difference between

1. querying table state at given snapshot -- at least in Trino, this uses the "schema current at that time", so includes columns that have been dropped since then

2. query table state after rollback_to_snapshot -- if this uses current schema, this doesn't include columns that have been dropped since the snapshot

Now consider example

-- add new column
ALTER TABLE orders ADD COLUMN order_timestamp timestamp(6) with time zone;
-- feel in data for new column
UPDATE orders SET order_timestamp = CAST(json_value(order_data, '$.timestamp') AS timestamp(6) with time zone);
-- drop the now-redundant column
ALTER TABLE orders DROP COLUMN order_data;

-- imagine now that comparing this uncovered that `order_data` was encoded in a bad way, so we need to roll this all back
CALL rollback_to_snapshot(.....)

As a user, i would expect to see order_data column back in my table.
Per this issue, i understand this wouldn't be the case. As a user I would call it a data loss (and so a bug).

cc @alexjo2144 @electrum