[jira] [Commented] (GEODE-3810) CI failure: UpdateVersionDUnitTest.testUpdateVersionAfterCreateWithSerialSenderOnDR failed with AssertionError

["Barry Oglesby (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/GEODE-3810?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16200627#comment-16200627 ] 

Barry Oglesby commented on GEODE-3810:
--------------------------------------

This failure is happening on the local site, not the remote site. It is comparing the entry's {{VersionStamp}} time to the test-generated timestamp, and its failing.

With some added logging in the test, I see:

The {{VersionStamp}} from the entry {{VersionStamp stamp = regionEntry.getVersionStamp())}} reports:
{noformat}
[vm0] [warn 2017/10/10 13:52:49.590 PDT <RMI TCP Connection(1)-192.168.2.6> tid=19] XXX UpdateVersionDUnitTest.call invoked stamp1=NonLocalRegionEntry(key-1; value=VMCachedDeserializable@703608312; version={v2; rv2; ds=1; time=1507676208606}
{noformat}
The generated {{VersionTag}} created with {{System.currentTimeMillis}} is an earlier time:
{noformat}
[vm0] [warn 2017/10/10 13:52:49.591 PDT <RMI TCP Connection(1)-192.168.2.6> tid=19] XXX UpdateVersionDUnitTest.call invoked tag={v1; rv0; mbr=192.168.2.6(70798)<ec><v0>:32770; ds=1; time=1507676208605; remote}
{noformat}
And the {{VersionStamp}} from the entry is the original one:
{noformat}
[vm0] [warn 2017/10/10 13:52:49.591 PDT <RMI TCP Connection(1)-192.168.2.6> tid=19] XXX UpdateVersionDUnitTest.call invoked stamp2=NonLocalRegionEntry(key-1; value=VMCachedDeserializable@703608312; version={v2; rv2; ds=1; time=1507676208606}
{noformat}

There are three put operations in this test - two using public API and one using internal API. All of them were generated at the same time, but the time is incremented by one in the second one in {{AbstractRegionEntry.generateVersionTag}}.

I added some logging in {{AbstractRegionEntry.generateVersionTag}}:
{noformat}
   long time = region.cacheTimeMillis();
==>System.out.println("cts=" + time);
   int dsid = region.getDistributionManager().getDistributedSystemId();
   // a locally generated change should always have a later timestamp than
   // one received from a wan gateway, so fake a timestamp if necessary
==>System.out.println("dsid=" + dsid + ";tagDsid=" + tag.getDistributedSystemId());
   if (time <= stamp.getVersionTimeStamp() && dsid != tag.getDistributedSystemId()) {
     time = stamp.getVersionTimeStamp() + 1;
==>  System.out.println("cts2=" + time);
   }
{noformat}

It shows:
{{AbstractRegionEntry.generateVersionTag}} generates timestamp=1507676208605 for the first put:
{noformat}
[vm0] About to put 1
[vm0] cts=1507676208605
[vm0] dsid=1;tagDsid=0
[vm0] Done put 1
{noformat}
{{AbstractRegionEntry.generateVersionTag}} generates the same timestamp for the second put, but increments it by 1:
{noformat}
[vm0] About to put 2
[vm0] cts=1507676208605
[vm0] dsid=1;tagDsid=0
[vm0] cts2=1507676208606
[vm0] Done put 2
{noformat}
The timestamp generated by the test using {{System.currentTimeMillis()}} in the 3rd put is the same, which causes the {{AssertionError}}:
{noformat}
[vm0] tagTs=1507676208605; dsid=1; tagDsid=1
{noformat}
{noformat}
[vm0] [info 2017/10/10 15:56:48.612 PDT <RMI TCP Connection(1)-192.168.2.6> tid=0x13] Got result: EXCEPTION_OCCURRED
[vm0] java.lang.AssertionError: Time stamp did NOT get updated by UPDATE_VERSION operation on LocalRegion expected:<1507676208605> but was:<1507676208606>
[vm0] 	at org.junit.Assert.fail(Assert.java:88)
{noformat}
I'm not sure I understand the reason {{AbstractRegionEntry.generateVersionTag}} increments the timestamp:
{noformat}
if (time <= stamp.getVersionTimeStamp() && dsid != tag.getDistributedSystemId()) {
  time = stamp.getVersionTimeStamp() + 1;
  System.out.println("cts2=" + time);
}
{noformat}
The {{tag}} being used in this call has just been created in this method, so its {{distributedSystemId}} has not been set:
{noformat}
VersionTag tag = VersionTag.create(member);
{noformat}
Its always going to be 0, so the second clause will be true. Is that correct behavior?

All four test cases in this test can fail for the same reason.

Also, I see the {{UpdateVersionJUnitTest}} increments the timestamp by one when it generates the timestamp for the third put:
{noformat}
long time = System.currentTimeMillis() + 1;
{noformat}

> CI failure: UpdateVersionDUnitTest.testUpdateVersionAfterCreateWithSerialSenderOnDR failed with AssertionError
> --------------------------------------------------------------------------------------------------------------
>
>                 Key: GEODE-3810
>                 URL: https://issues.apache.org/jira/browse/GEODE-3810
>             Project: Geode
>          Issue Type: Bug
>          Components: core
>            Reporter: Barry Oglesby
>
> {noformat}
> org.apache.geode.internal.cache.UpdateVersionDUnitTest > testUpdateVersionAfterCreateWithSerialSenderOnDR FAILED
>     org.apache.geode.test.dunit.RMIException: While invoking org.apache.geode.internal.cache.UpdateVersionDUnitTest$4.call in VM 0 running on Host e7658d4217a2 with 8 VMs
>         at org.apache.geode.test.dunit.VM.invoke(VM.java:393)
>         at org.apache.geode.test.dunit.VM.invoke(VM.java:363)
>         at org.apache.geode.test.dunit.VM.invoke(VM.java:331)
>         at org.apache.geode.internal.cache.UpdateVersionDUnitTest.testUpdateVersionAfterCreateWithSerialSenderOnDR(UpdateVersionDUnitTest.java:272)
>         Caused by:
>         java.lang.AssertionError: Time stamp did NOT get updated by UPDATE_VERSION operation on LocalRegion expected:<1507601466346> but was:<1507601466347>
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)