apache / apache/hudi

[SUPPORT] NPE occurs when enabling metadata on table which does'nt has metadata previously.

Open
#7,824 6 comments 0 reactions 1 assignee Claimed by @danny0405 View on GitHub
area:metadata-table area:table-service engine:flink priority:high
Dominant language
Java
Stars
6.2k
Forks
2.5k
Avg merge
2d 8h
Merged PRs (30d)
111

Description

**Describe the problem you faced**
When enabling metadata on a table which don't has metadata previously, NPE occurs.

**To Reproduce**

Steps to reproduce the behavior:

1. setup a table with metadata disabled.
2. restart the job and enabling the metadata option.
3. NPE occurs

**Expected behavior**

No NPE

**Environment Description**

* Hudi version : 0.13.0-rc1

* Spark version : N/A

* Hive version : 3.1.2

* Hadoop version : 3.1.3

* Storage (HDFS/S3/GCS..) : OSS

* Running on Docker? (yes/no) : yes, HA VVP

**Additional context**

**Stacktrace**

```LOG
2023-02-01 00:36:05,417 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test
2023-02-01 00:36:05,418 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Loading HoodieTableMetaClient from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/metadata
2023-02-01 00:36:05,435 WARN org.apache.hudi.metadata.HoodieBackedTableMetadata [] - Metadata table was not found at path oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/metadata
2023-02-01 00:36:05,436 INFO org.apache.hudi.common.table.view.FileSystemViewManager [] - Creating View Manager with storage type :REMOTE_FIRST
2023-02-01 00:36:05,436 INFO org.apache.hudi.common.table.view.FileSystemViewManager [] - Creating remote first table view
2023-02-01 00:36:05,438 INFO org.apache.hudi.client.transaction.lock.LockManager [] - LockProvider org.apache.hudi.client.transaction.lock.FileSystemBasedLockProvider
2023-02-01 00:36:05,618 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Loading HoodieTableMetaClient from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test
2023-02-01 00:36:05,635 INFO org.apache.hudi.common.table.HoodieTableConfig [] - Loading table properties from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/hoodie.properties
2023-02-01 00:36:05,647 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test
2023-02-01 00:36:05,776 INFO org.apache.hudi.common.table.timeline.HoodieActiveTimeline [] - Loaded instants upto : Option{val=[==>20230201003302911__deltacommit__INFLIGHT]}
2023-02-01 00:36:05,778 WARN org.apache.hudi.metadata.HoodieBackedTableMetadataWriter [] - Cannot initialize metadata table as operation(s) are in progress on the dataset: [[==>20230131214246466__compaction__INFLIGHT], [==>20230131214554966__compaction__REQUESTED], [==>20230131215522662__compaction__REQUESTED], [==>20230131220449842__compaction__REQUESTED], [==>20230201000246991__compaction__REQUESTED], [==>20230201001718618__rollback__INFLIGHT], [==>20230201003302911__deltacommit__INFLIGHT]]
2023-02-01 00:36:05,778 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Loading HoodieTableMetaClient from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test
2023-02-01 00:36:05,789 INFO org.apache.hudi.common.table.HoodieTableConfig [] - Loading table properties from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/hoodie.properties
2023-02-01 00:36:05,798 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test
2023-02-01 00:36:05,799 INFO org.apache.hudi.common.table.HoodieTableMetaClient [] - Loading HoodieTableMetaClient from oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/metadata
2023-02-01 00:36:05,814 WARN org.apache.hudi.metadata.HoodieBackedTableMetadata [] - Metadata table was not found at path oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/metadata
2023-02-01 00:36:05,938 INFO org.apache.hadoop.hive.conf.HiveConf [] - Found configuration file jar:file:../usrlib/ververica-connector-hudi-1.15-vvr-6.0-hive312-0.13.0-rc1-SNAPSHOT-jar-with-dependencies-20230131234928.jar!/hive-site.xml
2023-02-01 00:36:06,099 WARN org.apache.hadoop.hive.conf.HiveConf [] - HiveConf of name hive.dummyparam.test.server.specific.config.override does not exist
2023-02-01 00:36:06,100 WARN org.apache.hadoop.hive.conf.HiveConf [] - HiveConf of name hive.dummyparam.test.server.specific.config.metastoresite does not exist
2023-02-01 00:36:06,105 INFO org.apache.flink.runtime.jobmaster.JobMaster [] - Starting scheduling with scheduling strategy [org.apache.flink.runtime.scheduler.strategy.PipelinedRegionSchedulingStrategy]
2023-02-01 00:36:06,105 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - Job 1c7f0fe9-c059-491d-86eb-322554d24d0f (84b59a238dfd41e9968de83d5280df5d) switched from state CREATED to RUNNING.

...........

2023-02-01 00:36:24,740 INFO org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Executor executes action [handle write metadata event for instant ] success!
2023-02-01 00:36:24,800 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - Sink: compact_commit (1/1) #0 (b732feaa948ea68f9bf1c0df9689f8f4) switched from INITIALIZING to RUNNING.
2023-02-01 00:36:24,886 INFO org.apache.hudi.client.BaseHoodieWriteClient [] - Generate a new instant time: 20230201003624886 action: deltacommit
2023-02-01 00:36:25,295 INFO org.apache.hudi.common.table.timeline.HoodieActiveTimeline [] - Loaded instants upto : Option{val=[==>20230201003624920__rollback__REQUESTED]}
2023-02-01 00:36:25,297 INFO org.apache.hudi.client.heartbeat.HoodieHeartbeatClient [] - Received request to start heartbeat for instant time 20230201003624886
2023-02-01 00:36:25,329 INFO org.apache.hudi.common.table.timeline.HoodieActiveTimeline [] - Creating a new instant [==>20230201003624886__deltacommit__REQUESTED]
2023-02-01 00:36:25,364 INFO org.apache.hudi.common.table.timeline.HoodieActiveTimeline [] - Checking for file exists ?oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/20230201003624886.deltacommit.requested
2023-02-01 00:36:25,394 INFO org.apache.hudi.common.table.timeline.HoodieActiveTimeline [] - Create new file for toInstant ?oss://dengine-lake-zjk/cloudcode_pre/tmp_hudi_hive_test/.hoodie/20230201003624886.deltacommit.inflight
2023-02-01 00:36:25,435 INFO org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Create instant [20230201003624886] for table [tbl_resp_sink] with type [MERGE_ON_READ]
2023-02-01 00:36:25,439 INFO org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Executor executes action [initialize instant ] success!
2023-02-01 00:36:25,746 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - compact_plan_generate (1/1) #0 (06c8d064a1b42253bf7dba8786f881a0) switched from INITIALIZING to FAILED on job-84b59a23-8dfd-41e9-968d-e83d5280df5d-taskmanager-1-1 @ bd-flink011088139163.na63.tbsite.net (dataPort=23011).
java.lang.NullPointerException: null
at org.apache.hudi.metadata.HoodieBackedTableMetadataWriter.update(HoodieBackedTableMetadataWriter.java:933) ~[?:?]
at org.apache.hudi.table.action.BaseActionExecutor.lambda$writeTableMetadata$2(BaseActionExecutor.java:76) ~[?:?]
at org.apache.hudi.common.util.Option.ifPresent(Option.java:97) ~[?:?]
at org.apache.hudi.table.action.BaseActionExecutor.writeTableMetadata(BaseActionExecutor.java:76) ~[?:?]
at org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor.finishRollback(BaseRollbackActionExecutor.java:246) ~[?:?]
at org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor.runRollback(BaseRollbackActionExecutor.java:114) ~[?:?]
at org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor.execute(BaseRollbackActionExecutor.java:135) ~[?:?]
at org.apache.hudi.table.HoodieFlinkMergeOnReadTable.rollback(HoodieFlinkMergeOnReadTable.java:128) ~[?:?]
at org.apache.hudi.table.HoodieTable.rollbackInflightInstant(HoodieTable.java:626) ~[?:?]
at org.apache.hudi.table.HoodieTable.rollbackInflightCompaction(HoodieTable.java:600) ~[?:?]
at org.apache.hudi.table.HoodieTable.rollbackInflightCompaction(HoodieTable.java:584) ~[?:?]
at org.apache.hudi.util.CompactionUtil.lambda$rollbackCompaction$1(CompactionUtil.java:190) ~[?:?]
at java.util.ArrayList.forEach(ArrayList.java:1249) ~[?:1.8.0_102]
at org.apache.hudi.util.CompactionUtil.rollbackCompaction(CompactionUtil.java:188) ~[?:?]
at org.apache.hudi.sink.compact.CompactionPlanOperator.open(CompactionPlanOperator.java:75) ~[?:?]
at org.apache.flink.streaming.runtime.tasks.RegularOperatorChain.initializeStateAndOpenOperators(RegularOperatorChain.java:107) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.streaming.runtime.tasks.StreamTask.restoreGates(StreamTask.java:851) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.streaming.runtime.tasks.StreamTaskActionExecutor$1.call(StreamTaskActionExecutor.java:55) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.streaming.runtime.tasks.StreamTask.restoreInternal(StreamTask.java:798) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.streaming.runtime.tasks.StreamTask.restore(StreamTask.java:765) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.runtime.taskmanager.Task.runWithSystemExitMonitoring(Task.java:954) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.runtime.taskmanager.Task.restoreAndInvoke(Task.java:923) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:746) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at org.apache.flink.runtime.taskmanager.Task.run(Task.java:568) ~[flink-dist-1.15-vvr-6.0.4-SNAPSHOT.jar:1.15-vvr-6.0.4-SNAPSHOT]
at java.lang.Thread.run(Thread.java:834) ~[?:1.8.0_102]
2023-02-01 00:36:25,780 INFO org.apache.flink.runtime.executiongraph.failover.flip1.RestartPipelinedRegionFailoverStrategy [] - Calculating tasks to restart to recover the failed task d14c81370450f18851be93e3825a2d06_0.
2023-02-01 00:36:25,785 INFO org.apache.flink.runtime.jobmaster.JobMaster [] - 14 tasks should be restarted to recover the failed task d14c81370450f18851be93e3825a2d06_0.
2023-02-01 00:36:25,785 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - Job 1c7f0fe9-c059-491d-86eb-322554d24d0f (84b59a238dfd41e9968de83d5280df5d) switched from state RUNNING to RESTARTING.
2023-02-01 00:36:25,787 WARN org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Reset the event for task [2]
2023-02-01 00:36:25,787 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - bucket_write: tbl_resp_sink (3/4) #0 (88f02c5d12f53da0b571729af1aae985) switched from RUNNING to CANCELING.
2023-02-01 00:36:25,788 WARN org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Reset the event for task [3]
2023-02-01 00:36:25,788 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - bucket_write: tbl_resp_sink (4/4) #0 (4101dbc91d55a0711db769e51450689c) switched from RUNNING to CANCELING.
2023-02-01 00:36:25,788 WARN org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Reset the event for task [0]
2023-02-01 00:36:25,788 INFO org.apache.flink.runtime.executiongraph.ExecutionGraph [] - bucket_write: tbl_resp_sink (1/4) #0 (bdcc0b8232bc1939fd6d29256bab09c3) switched from RUNNING to CANCELING.
2023-02-01 00:36:25,788 WARN org.apache.hudi.sink.StreamWriteOperatorCoordinator [] - Reset the event for task [1]
``

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.