fix(common): stop warning with a stack trace when a partition metafile already exists - #19494
Conversation
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
test. Two small nits: a British-spelling inconsistency on summarise and a duplicated TestLogAppender inner class across two test files.
| */ | ||
| @VisibleForTesting | ||
| static String summarise(Throwable t) { | ||
| Throwable rootCause = t; |
There was a problem hiding this comment.
🤖 nit: summarise uses British spelling — could you rename it to summarize to stay consistent with Java's own conventions and the rest of the Hudi codebase (e.g. Collectors.summarizingInt, DoubleSummaryStatistics)?
There was a problem hiding this comment.
Fair point, renamed to summarize in both the helper and its test.
Checked before changing it rather than assuming: the codebase had one file using the American spelling against the two I had just added with the British one, and the JDK itself is Collectors.summarizingInt / DoubleSummaryStatistics. No occurrences of summarise remain.
| @@ -89,6 +107,116 @@ public void testTextFormatMetaFile(Option<HoodieFileFormat> format) throws IOExc | |||
| assertEquals(3, readMetadata.getPartitionDepth()); | |||
There was a problem hiding this comment.
🤖 nit: TestLogAppender is defined identically in both TestRetryHelper and TestHoodiePartitionMetadata — could it live in a shared test-utility class (e.g. HoodieTestLogAppender under a testutils module) so the two test files can just import it?
There was a problem hiding this comment.
Agreed, and done — diff confirmed the two copies were byte identical, which made it worth doing properly rather than leaving for the next log assertion test to copy a third time.
It now lives at hudi-common/src/test/java/org/apache/hudi/common/testutils/HoodieTestLogAppender.java. That module works for both call sites because hudi-hadoop-common already declares hudi-common with <type>test-jar</type>, and org.apache.hudi.common.testutils is where the existing shared harnesses sit.
Two things worth noting on the way it landed:
- The name matters. Surefire collects
Test*.java, so a standaloneTestLogAppender.javawould have been picked up as a test class.HoodieTestLogAppenderavoids that, and the class javadoc says why so nobody renames it back. - I also moved the attach and detach boilerplate into the utility, since both call sites were repeating the same four lines of
LogManager.getLogger/start/addAppenderand the matching teardown. Each site is nownew HoodieTestLogAppender().attachTo(RetryHelper.class)withappender.detach()in thefinally.
This does mean the PR touches two modules and adds a test utility class, which is a little wider than the bug fix itself. Happy to split the extraction into a follow up if a committer would rather keep this one minimal.
Verified after the change: TestRetryHelper 4/4, TestHoodiePartitionMetadata 7/7, checkstyle and rat clean on both modules. Also rebased onto master.
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## master #19494 +/- ##
============================================
+ Coverage 77.54% 77.72% +0.17%
- Complexity 32931 32998 +67
============================================
Files 2524 2524
Lines 139525 139543 +18
Branches 16786 16788 +2
============================================
+ Hits 108197 108457 +260
+ Misses 23742 23460 -282
- Partials 7586 7626 +40
Flags with carried forward coverage won't be shown. Click here to find out more.
🚀 New features to boost your workflow:
|
d197558 to
e719f8f
Compare
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! The PR turns a lost partition-metafile creation race into a quiet success in HoodiePartitionMetadata.trySave() and stops RetryHelper from dumping a full stack trace on every retry attempt. The core race handling and the logging changes look sound; one edge case around the existence re-check in the catch block is worth double-checking in the inline comment. Please take a look, and this should be ready for a Hudi committer or PMC member to take it from here. One small naming inconsistency worth fixing; otherwise the code is clean and readable.
| // to create it and all but the winner fail with an 'already exists' error. Losing that | ||
| // race means the metafile is in place, which is what the caller asked for: retrying | ||
| // would only re-observe the same file, and warning about it is pure noise. | ||
| if (!storage.exists(metaPath)) { |
There was a problem hiding this comment.
🤖 This re-check storage.exists(metaPath) can itself throw IOException (e.g. transient throttling on an object store — plausible right when the write just failed transiently). If it throws, the original e is lost and a raw IOException propagates instead. That new exception isn't in this RetryHelper's retry list (only HoodieIOException is), so the original retryable write failure no longer gets retried, and a checked IOException can slip past callers that catch only HoodieIOException. Would it be safer to rethrow the original e when the existence re-check fails, so a genuine transient write error still flows through the normal retry path?
There was a problem hiding this comment.
Good catch, this is a real defect in what the PR adds — fixed in 2c12664e9f0a.
Chasing it down turned the concern from "could throw" into something concrete. RetryHelper here is built with HoodieIOException.class.getName(), so retryExceptionsClasses is exactly [HoodieIOException], and start() does:
} catch (Exception e) {
if (!checkIfExceptionInRetryList(e)) {
throw e; // straight out, no retry
}The write failure out of createImmutableFileInPath is a HoodieIOException, so it is retryable. A bare IOException from the existence check is not. So a single failed check did not merely lose the original: it downgraded a retryable write failure into one thrown immediately, which on an object store is precisely when the retry was worth having.
The check now cannot replace the failure it was meant to soften:
private boolean metafileExistsAfterFailedWrite(StoragePath metaPath, Exception writeFailure) {
try {
return storage.exists(metaPath);
} catch (IOException checkFailure) {
writeFailure.addSuppressed(checkFailure);
return false;
}
}A check that cannot answer reports the metafile as absent, so the original failure is thrown with its retry classification intact, and the check failure is kept as suppressed rather than dropped.
Covered by testTrySaveKeepsWriteFailureWhenExistenceRecheckFails, which stubs exists to slip through the pre-write check and then fail the recheck, and asserts the thrown exception is not the check failure and that the check failure survives as suppressed. Verified it is bound to the fix: reverting to the direct storage.exists(metaPath) fails exactly that test with expected: not same but was: <java.io.IOException: storage unavailable>, and leaves the other seven passing.
Worth noting for anyone reading the test: the stub alternates rather than using a fixed sequence, because the write failure is retryable. With a doReturn(false).doThrow(...) sequence, Mockito repeats the last stub once exhausted, so the second attempt throws from the pre-write check, which sits outside the try and escapes for a different reason entirely.
| } | ||
| } | ||
|
|
||
| @Test |
There was a problem hiding this comment.
🤖 nit: could you rename this to testSummarizeKeepsRootCauseOnASingleLine to match the spelling of the production method summarize? The British-vs-American mismatch is a small speed-bump when scanning for which test covers which method.
There was a problem hiding this comment.
Renamed to testSummarizeKeepsRootCauseOnASingleLine.
Correcting my earlier reply on the other thread: I said no occurrences of summarise remained, and that was wrong. My rename used sed s/summarise/summarize/g and I verified it with grep -n summarise — both case sensitive, so testSummariseKeepsRootCauseOnASingleLine was never touched and my check could not have caught it. A case sensitive check cannot validate a case sensitive fix.
Redone with the capitalised form included and verified with grep -rni summaris across .java, .scala and .md. That now returns nothing.
github-actions
Bot
added
size:L
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! This PR treats a lost .hoodie_partition_metadata creation race as the success it is (re-checking for the immutable metafile before propagating a write failure) and stops RetryHelper from logging a full stack trace on every retry attempt. I traced the race-handling and exception-classification paths (object-store direct-create vs. HDFS temp+rename, recheck-fails-transiently, and genuine-failure cases) and the retry-list preservation, and the logic holds up. Prior rounds already covered the recheck-can-throw defect (fixed) and the spelling nits, so nothing new to flag from this automated pass — a Hudi committer or PMC member can take it from here for a final review. Code is clean and well-documented; one minor import suggestion below.
cc @yihua
| /** | ||
| * Starts this appender and attaches it to the logger of the given class. | ||
| */ | ||
| public HoodieTestLogAppender attachTo(Class<?> clazz) { |
There was a problem hiding this comment.
🤖 nit: could you import org.apache.logging.log4j.LogManager and use LogManager.getLogger(clazz) here instead of the fully-qualified reference? reads a bit cleaner.
There was a problem hiding this comment.
Done in 65f99a982c0d. LogManager is imported now and the line reads:
attachedLogger = (Logger) LogManager.getLogger(clazz);Worth noting why it was qualified in the first place: this class already imports
org.apache.logging.log4j.core.Logger, and I wanted to be sure adding
org.apache.logging.log4j.LogManager did not collide with it. The simple names differ, so there is
no clash and the import is clean.
Also rebased onto master in the same push. The branch had drifted 37 commits behind; GitHub still
reported it mergeable, but CI results against a base that stale are not worth much. The rebase was
clean, no conflicts.
Re-verified after both changes: TestRetryHelper 4/4, TestHoodiePartitionMetadata 8/8, and
checkstyle:check plus apache-rat:check clean on hudi-common and hudi-hadoop-common.
Checkstyle was the one to watch here, since a new import has to land in the right group for the
ImportOrder rule.
…e already exists
Tasks writing to the same partition concurrently race to create
.hoodie_partition_metadata. The existence check in trySave() narrows the window
but cannot close it, so the losers of the race get an 'already exists' error
back from the storage layer. That error was handed to the retry helper, which
logged a full stack trace at WARN and slept a second before retrying, only to
find the very file it had just been told about:
WARN RetryHelper: Catch Exception for N/A, will retry after 1000 ms.
org.apache.hudi.exception.HoodieIOException: Failed to create file
.../.hoodie/metadata/column_stats/.hoodie_partition_metadata
... 40 frames ...
Caused by: org.apache.hadoop.fs.FileAlreadyExistsException: File already exists
The metafile is immutable, so losing the race means the file the caller asked
for is in place. Treat it as the success it is: re-check for the metafile and
only propagate the failure if it is genuinely absent. This removes both the
scary warning and a pointless one second stall per racing task.
Note this only surfaces on storage that creates the metafile directly. Local
and HDFS storage write to a temp file and rename, and a losing rename is
already silent, so the noise is confined to object stores.
Separately, the retry helper no longer prints a stack trace for every failed
attempt. A retry that goes on to succeed does not warrant one, and printing it
per attempt buries genuine failures. The trace is still available at DEBUG, and
is still logged at ERROR once the retries are exhausted.
The existing coverage for HUDI-9095 asserted the absence of the retry backoff,
which is only a proxy for the reported symptom. These two tests assert the
symptom itself by capturing what actually reaches the log.
TestRetryHelper drives a retry that eventually succeeds and asserts the warn
event carries no throwable, so the logger has no stack trace to print, while the
message still names the failure and its root cause.
TestHoodiePartitionMetadata asserts that losing the metafile creation race
produces no warn-or-worse event at all. Reverting the fix fails it with the
warning it is meant to prevent:
losing the metafile creation race must not be logged as a problem, got:
[Task [N/A] failed. current retry number 1, will retry after 1000 ms.]
- Rename RetryHelper.summarise to summarize, matching the spelling used by the JDK and the rest of the codebase. - Move the log capturing appender into hudi-common testutils as HoodieTestLogAppender, where both tests can share it, instead of the same inner class copied into each. It is named so surefire does not collect it as a test class, and it now owns the attach and detach boilerplate the two call sites were repeating.
…ck fails The recheck that recognises a lost creation race can itself throw, and when it did the original write failure was replaced by that IOException. RetryHelper is configured here to retry HoodieIOException only, so the substitute was not retried at all: one failed existence check turned a retryable write failure into an immediate one. Treat a recheck that cannot answer as the metafile being absent, keep the check failure on the original as suppressed, and let the original be thrown so it keeps its retry classification. Also rename the test for summarize, which kept the older spelling.
2c12664 to
65f99a9
Compare
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! This PR treats a lost partition-metafile creation race as the success it is by re-checking existence before propagating the write failure, and stops RetryHelper from logging a full stack trace on every retry attempt. I traced the exception and retry-classification path, the object-store race path, and the existence re-check, and the logic holds up. No correctness issues found. A few style/readability suggestions in the inline comments. Please take a look, and this should be ready for a Hudi committer or PMC member to take it from here.; a Hudi committer or PMC member can take it from here for a final review. One naming nit below, otherwise the code is clean and well-documented.
cc @yihua
| */ | ||
| public class HoodieTestLogAppender extends AbstractAppender { | ||
|
|
||
| private final List<LogEvent> log = new ArrayList<>(); |
There was a problem hiding this comment.
🤖 nit: could you rename log to capturedEvents (or just events)? In a class that is itself a log appender, log reads like a logger field at a quick glance, and getLog() returning a List is a small double-take that getCapturedEvents() would avoid.
4 participants
Describe the issue this Pull Request addresses
Closes #17374
Tasks writing to the same partition concurrently race to create
.hoodie_partition_metadata. Theexistence check in
HoodiePartitionMetadata.trySave()narrows the window but cannot close it, sothe losers get an "already exists" error back from the storage layer. That error was handed to
RetryHelper, which logged a full stack trace at WARN and slept a second before retrying, only tofind the very file it had just been told about:
The reporter saw it twice in one session, during
INSERTand again duringCREATE INDEX.Summary and Changelog
HoodiePartitionMetadata.trySave()treats a lost race as the success it is. The metafile isimmutable, so if a peer created it first, the file the caller asked for is in place. The write is
now wrapped so that on failure it re-checks for the metafile and only propagates the error if it is
genuinely absent. This removes the warning and a pointless one second stall per racing task.
The catch is a strict superset of what could previously produce the warning, which is what makes it
storage independent:
trySaveonly ever retriedHoodieIOException,createImmutableFileInPathwraps every
IOExceptioninto one, and the new catch isIOException | HoodieIOException. It doesnot pattern match on the exception, it re-checks the filesystem, so whatever a given object store
throws for an existing key is handled.
RetryHelperno longer prints a stack trace for every failed attempt. A retry that goes on tosucceed does not warrant one, and printing it per attempt buries the genuine failures. The WARN now
carries a single line naming the failure and its root cause; the full trace is still logged at DEBUG,
and still at ERROR once the retries are exhausted.
These are separable, and reviewers may prefer them apart. The first alone closes the reported
symptom, verified below. The second is the reporter's literal suggestion, "maybe we should avoid
logging stack traces in such warning messages", generalised to the other callers. Happy to split
the
RetryHelperchange into its own PR if that is preferred, since it touches twelve call sites(lock manager, timeline client, Kafka consumer, Flink jobs) while the first change touches one
method.
Impact
Concurrent writers no longer log an alarming stack trace, nor pay a retry backoff, for a benign
race. On a table with many partitions that is a real latency saving as well as quieter logs.
This surfaces on storage that creates the metafile directly. Local and HDFS storage write to a temp
file and rename, and a losing rename is already silent, so the noise is confined to object stores.
Note that means the reporter's original
file:///tmpscenario no longer reproduces on master, sinceb6957f020d00gave local storage the temp-file path.No configuration or public API change.
Risk Level
low
Documentation Update
none
Verification
hudi-common,common.util.**+common.model.**hudi-hadoop-common,common.model.**+storage.**checkstyle:check, both modulesThree tests were added, each confirmed to fail against the unmodified code:
TestHoodiePartitionMetadata.testTrySaveWhenMetafileConcurrentlyCreatedcaptures the log eventsemitted while the race is lost and asserts none is WARN or worse. Without the fix it fails with
the warning it is meant to prevent:
Task [N/A] failed. current retry number 1, will retry after 1000 ms.It also asserts the call does not pay the retry backoff.TestHoodiePartitionMetadata.testConcurrentTrySaveWritesOneMetafileruns eight writers at thesame partition and asserts one metafile and no failures.
TestRetryHelper.testRetryWarningCarriesNoStackTracedrives a retry that eventually succeeds andasserts the WARN event carries no throwable, so the logger has no trace to print, while the
message still names the failure and its root cause.
The object-store path is reached in tests by stubbing the storage scheme, not by writing to a real
bucket, so the behaviour against a live object store is argued from the exception-handling above
rather than observed.
Contributor's checklist