[
https://issues.apache.org/jira/browse/IMPALA-14628?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18045084#comment-18045084
]
Quanlong Huang commented on IMPALA-14628:
-----------------------------------------
With more runs I'm able to reproduce the issue locally:
{code:java}
[ERROR]
org.apache.impala.catalog.events.MetastoreEventsProcessorTest.testDisableEventSyncFlag
Time elapsed: 108.674 s <<< FAILURE!
java.lang.AssertionError: expected:<1765768080> but was:<1765768081> {code}
Here are some logs in logs/fe_tests/FeSupport.INFO:
{noformat}
I20251215 11:08:00.943428 791608 MetastoreEvents.java:936] EventId: 394564
EventType: CREATE_DATABASE Target: events_test_db. Successfully added database
events_test_db
I20251215 11:08:00.943497 791608 MetastoreEvents.java:936] EventId: 394564
EventType: CREATE_DATABASE Target: events_test_db. Scheduling delay: 17ms,
Process time:
I20251215 11:08:00.953441 791609 MetastoreEvents.java:936] EventId: 394565
EventType: CREATE_TABLE Target: events_test_db.runddltestswithflags. Found
table level flag impala.disableHmsSync is set to true for table
events_test_db.runddltestswithflags
I20251215 11:08:00.953528 791609 MetastoreEvents.java:936] EventId: 394565
EventType: CREATE_TABLE Target: events_test_db.runddltestswithflags. Skipping
this event because of flag evaluation
I20251215 11:08:00.953598 791609 MetastoreEvents.java:936] EventId: 394565
EventType: CREATE_TABLE Target: events_test_db.runddltestswithflags. Scheduling
delay: 27ms, Process time:
I20251215 11:08:00.953728 791609 MetastoreEvents.java:936] EventId: 394566
EventType: ADD_PARTITION Target: events_test_db.runddltestswithflags. Found
table level flag impala.disableHmsSync is set to true for table
events_test_db.runddltestswithflags
I20251215 11:08:00.953771 791609 MetastoreEvents.java:936] EventId: 394566
EventType: ADD_PARTITION Target: events_test_db.runddltestswithflags. Skipping
this event because of flag evaluation
I20251215 11:08:00.953819 791609 MetastoreEvents.java:936] EventId: 394566
EventType: ADD_PARTITION Target: events_test_db.runddltestswithflags.
Scheduling delay: 27ms, Process time:
I20251215 11:08:00.959358 791449 MetastoreEventsProcessor.java:1454] Latest
event in HMS: id=394566, time=1765768080. Greatest synced event: id=394566,
time=1765768080.
I20251215 11:08:01.010174 791449 MetastoreEventsProcessor.java:1288] Received 3
events. First event id: 394567.
I20251215 11:08:01.012128 791449 MetastoreEventsProcessor.java:1288] Received 3
events. First event id: 394567.
I20251215 11:08:01.013628 791449 MetastoreEvents.java:310] Total number of
events received: 3 Total number of events filtered out: 0
I20251215 11:08:01.013837 791449 MetastoreEvents.java:936] EventId: 394569
EventType: ALTER_BATCH_PARTITIONS Target: events_test_db.runddltestswithflags.
Created a batch event for 3 events between 394567 and 394569
I20251215 11:08:01.014129 791449 MetastoreEventsProcessor.java:1708] Time
elapsed in dispatching event batch: 1.780ms
I20251215 11:08:01.023505 791609 MetastoreEvents.java:936] EventId: 394569
EventType: ALTER_BATCH_PARTITIONS Target: events_test_db.runddltestswithflags.
Found table level flag impala.disableHmsSync is set to true for table
events_test_db.runddltestswithflags
I20251215 11:08:01.023607 791609 MetastoreEvents.java:936] EventId: 394569
EventType: ALTER_BATCH_PARTITIONS Target: events_test_db.runddltestswithflags.
Skipping this event because of flag evaluation
I20251215 11:08:01.023686 791609 MetastoreEvents.java:936] EventId: 394569
EventType: ALTER_BATCH_PARTITIONS Target: events_test_db.runddltestswithflags.
Scheduling delay: 10ms, Process time:
I20251215 11:08:01.026310 791449 MetastoreEventsProcessor.java:1454] Latest
event in HMS: id=394569, time=1765768081. Greatest synced event: id=394569,
time=1765768080.{noformat}
The last line is problematic that the greatest synced event id is updated but
the greatest event time remains unchanged (it's still the time of event
id=394566).
> testDisableEventSyncFlag failed due to greatestSyncedEventTime !=
> lastSyncedEventTime
> -------------------------------------------------------------------------------------
>
> Key: IMPALA-14628
> URL: https://issues.apache.org/jira/browse/IMPALA-14628
> Project: IMPALA
> Issue Type: Bug
> Reporter: Quanlong Huang
> Assignee: Venugopal Reddy K
> Priority: Critical
>
> FE test MetastoreEventsProcessorTest.testDisableEventSyncFlag is flaky. Here
> is an error in a downstream run:
> {noformat}
> java.lang.AssertionError: expected:<1765626451> but was:<1765626452>
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.failNotEquals(Assert.java:834)
> at org.junit.Assert.assertEquals(Assert.java:645)
> at org.junit.Assert.assertEquals(Assert.java:631)
> at
> org.apache.impala.catalog.events.SynchronousHMSEventProcessorForTests.verifyEventSyncedMetrics(SynchronousHMSEventProcessorForTests.java:78)
> at
> org.apache.impala.catalog.events.SynchronousHMSEventProcessorForTests.processEvents(SynchronousHMSEventProcessorForTests.java:53)
> at
> org.apache.impala.catalog.events.MetastoreEventsProcessorTest.testDDLOpUsingEvent(MetastoreEventsProcessorTest.java:2291)
> at
> org.apache.impala.catalog.events.MetastoreEventsProcessorTest.runDDLTestsWithFlags(MetastoreEventsProcessorTest.java:2145)
> at
> org.apache.impala.catalog.events.MetastoreEventsProcessorTest.testDisableEventSyncFlag(MetastoreEventsProcessorTest.java:2091)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at
> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:316)
> at
> org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:240)
> at
> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:214)
> at
> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:155)
> at
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
> at
> org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
> at
> org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
> at
> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495){noformat}
> The failed assertion is "greatestSyncedEventTime == lastSyncedEventTime" in
> the following code:
> {code}
> Assert.assertEquals(greatestSyncedEventId, lastSyncedEventId);
> Assert.assertEquals(greatestSyncedEventTime, lastSyncedEventTime); // failed
> here{code}
> https://github.com/apache/impala/blob/9d112dae23870b6729473047da94f1bc0ea89ceb/fe/src/test/java/org/apache/impala/catalog/events/SynchronousHMSEventProcessorForTests.java#L78
> This means the event ids are identical but the event time are different.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
