Story #7577
CN Synchronization updates SM.dateSysMetadataModified on harvest
100%
Description
During integration testing for the CCI-2.0.2 release, I noticed that some integration tests were failing. The tests in question checked if the CN updated SM.dateSysMetadataModified (they expected that it did not). Turns out synchronization does update this field. It's unclear what the intention is, but the code has been updating this field for many years and comments in the code indicate that it is important to the harvest process.
TransferObjectTask.java in d1_synchronization:
// All though this should take place when the object is processsed, it needs to be
// performed here due to the way last DateSysMetadataModified is used to
// determine the next batch of records to retreive from a MemberNode
systemMetadata.setDateSysMetadataModified(new Date());
History
#1 Updated by Ben Leinfelder over 8 years ago
- Tracker changed from Task to Story
#2 Updated by Robert Waltz about 8 years ago
The class TransferObjectTask.java is no longer used. TransferObjectTaskV2.java is the current implementation. We should move TransferObjectTaskV2.java to TransferObjectTask.java in order to remove any confusion.
#3 Updated by Rob Nahf about 8 years ago
(changed comment) CNodeService seems to be only changing modification date for methods called by (v1) end-users, so is probably ok.
The CN modification date is 15 seconds after the MN modification date, and about 600ms after the second replica time (set when the replica is REQUESTED.
How long would it take for a MN to send a setReplicationStatus back to the CN?
thinking out loud, could v1.cn.replication APIs be responsible?
#4 Updated by Rob Nahf about 8 years ago
sync logs show that the new modification date (2015-11-19T07:24:11.842+00:00) happens some time in the createObject routine (which lasts at least 1.4 seconds)
root@cn-sandbox-ucsb-1:/var/log/dataone/synchronize# grep testUpdateReplicationMetadata_dateModified_obj5 cn-synchronization.log.6
[DEBUG] 2015-11-19 07:24:10,140 (ObjectListHarvestTask:call:194) placed on hzSyncObjectQueue- Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5
[ INFO] 2015-11-19 07:24:10,209 (SyncObjectTask:call:141) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 received
[ INFO] 2015-11-19 07:24:10,209 (SyncObjectTask:call:158) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 submitted for execution
[ INFO] 2015-11-19 07:24:10,210 (V2TransferObjectTask:call:186) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Locking task, attempt 1
[ INFO] 2015-11-19 07:24:10,280 (V2TransferObjectTask:call:192) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Processing SyncObject
[ INFO] 2015-11-19 07:24:10,578 (V2TransferObjectTask:retrieveMNSystemMetadata:266) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Retrieved SystemMetadata Identifier:testUpdateReplicationMetadata_dateModified_obj5 from node urn:node:mnSandboxUCSB1 for ObjectInfo Identifier testUpdateReplicationMetadata_dateModified_obj5
[ INFO] 2015-11-19 07:24:10,578 (V2TransferObjectTask:call:194) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 MN system metadata retrieved...
[DEBUG] 2015-11-19 07:24:10,579 (V2TransferObjectTask:processTask:367) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering processTask...
[DEBUG] 2015-11-19 07:24:10,579 (V2TransferObjectTask:validateSeriesId:509) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering validateSeriesId...
[DEBUG] 2015-11-19 07:24:10,579 (V2TransferObjectTask:resolve:592) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering resolve...
[ INFO] 2015-11-19 07:24:10,883 (V2TransferObjectTask:resolve:600) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 PID testUpdateReplicationMetadata_dateModified_obj5 does not exist on the CN.
[DEBUG] 2015-11-19 07:24:10,883 (V2TransferObjectTask:processNewObject:409) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering processNewObject...
[ INFO] 2015-11-19 07:24:11,100 (V2TransferObjectTask:processNewObject:422) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Pid is not reserved by anyone.
[DEBUG] 2015-11-19 07:24:11,100 (V2TransferObjectTask:populateInitialReplicaList:443) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering populateInitialReplicaList
[DEBUG] 2015-11-19 07:24:11,100 (V2TransferObjectTask:populateInitialReplicaList:458) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Included replica for original MN
[DEBUG] 2015-11-19 07:24:11,101 (V2TransferObjectTask:populateInitialReplicaList:462) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Get Object Format
[DEBUG] 2015-11-19 07:24:11,120 (V2TransferObjectTask:populateInitialReplicaList:473) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Added CN as replica because formatType METADATA is not DATA
[DEBUG] 2015-11-19 07:24:11,121 (V2TransferObjectTask:createObject:629) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering createObject...
[DEBUG] 2015-11-19 07:24:11,138 (V2TransferObjectTask:validateChecksum:719) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 entering validateChecksum...
[DEBUG] 2015-11-19 07:24:11,312 (V2TransferObjectTask:createObject:656) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 getting ScienceMetadata
[ INFO] 2015-11-19 07:24:11,624 (V2TransferObjectTask:createObject:693) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Creating Object
[ INFO] 2015-11-19 07:24:12,775 (V2TransferObjectTask:createObject:696) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Created Object
[DEBUG] 2015-11-19 07:24:12,847 (V2TransferObjectTask:call:249) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Unlocked Pid.
[DEBUG] 2015-11-19 07:25:40,815 (SyncObjectTask:reapFutures:245) trying future Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5
[DEBUG] 2015-11-19 07:25:40,815 (SyncObjectTask:reapFutures:252) Task-urn:node:mnSandboxUCSB1-testUpdateReplicationMetadata_dateModified_obj5 Returned from the Future :(1):
root@cn-sandbox-ucsb-1:/var/log/dataone/synchronize#
#5 Updated by Dave Vieglais about 8 years ago
- Target version changed from CCI-2.0.3 to CCI-2.1.0
#6 Updated by Rob Nahf about 8 years ago
- Assignee changed from Dave Vieglais to Rob Nahf
#7 Updated by Rob Nahf about 8 years ago
- % Done changed from 0 to 100
- Status changed from New to Closed
rerunning the test in a clear environment shows all tests passing again.
I have to assume that is was the state of the SANDBOX environment which was the cause of the problem.
