Task #8054: Debug the failed-sync eml object from EBird - Infrastructure - DataONE Tasks

Task #8054

Debug the failed-sync eml object from EBird

Added by Jing Tao over 7 years ago. Updated over 7 years ago.

Status:

Closed

Priority:

Normal

Assignee:

Jing Tao

Category:

Target version:

Start date:

2017-03-28

Due date:

% Done:

100%

Milestone:

None

Product Version:

Story Points:

Sprint:

Description

On 3/10/17 10:09 AM, Moyers, Laura Burton (Laura) wrote:

Hi, Jing,



We are hoping that you will recognize what is going on with a new package that eBIRD (CLOEBIRD) is trying to sync to production.  They are a Metacat installation, running a v2 MN.  Here is what we know about it so far:



The “new” package consists of an ORE (CLO_EOD-2015a.csv), a scimeta EML doc (CLO_EOD-2015a.eml), and data (CLO_EOD-2015a.csv.gz).  (Thanks for enabling that gzip format support, BTW!)



The ORE and the data have sync’d but the EML has not.  Mark and Roger have done some investigating in the log files, and here is something:



AGE="0d 0h 55m"  TIME="2017-03-17 02:33:15"  LOG="D1-PROCESSING-JSVC"  LEVEL="ERROR"



(SyncFailedTask:submitSynchronizationFailed:132) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml <?xml version="1.0"

encoding="UTF-8"?>

<error detailCode="2161" errorCode="500" name="ServiceFailure">

<description>The processing instruction target matching "[xX][mM][lL]" is not allowed.</description>

</error>



Not quite sure what that means, but, could it have something to do with the fact that this EML doc doesn’t have an XML declaration at the beginning (like this: <?xml version="1.0"?>)? 



Additionally, there is an “old” package for CLOEBIRD out there, fully sync’d, consisting of an ORE (CLO_EOD-2015.csv), a scimeta EML doc (CLO_EOD-2015.eml), and data (CLO_EOD-2015.csv.gz).  Interestingly (maybe), the “old” EML (at least what is present on the CNs) does not have an XML declaration, either.



One difference Mark noted is that the namespace declaration is different between the “old” and the “new”:



<ns0:eml xmlns:ns0="eml://ecoinformatics.org/eml-2.1.0”      namespace on the “old” 



<eml:eml xmlns:eml="eml://ecoinformatics.org/eml-2.1.1"      namespace on the “new”



Does anything leap out at you right away that would cause the “new” EML to not sync?  Any guidance you can provide will be MOST appreciated!



Thanks!
Laura

History

#1 Updated by Jing Tao over 7 years ago

Hi everyone:

After I looked the log file and tested on cn-stage, I found that this error message is for submitting synchronization failure, not the synchronization itself:

[ERROR] 2017-03-10 02:33:15,275 (SyncFailedTask:submitSynchronizationFailed:132) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>

The processing instruction target matching "[xX][mM][lL]" is not allowed.

A snippet of log file on cn-stage make things clearer:

[ WARN] 2017-03-10 22:39:11,456 (SyncFailedTask:submitSynchronizationFailed:116) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>

Synchronization task of [PID::] CLO_EOD-2015a.eml [::PID] failed. Cause: InvalidSystemMetadata: authoritativeMN in systemMetadata was not found in the Nodelist

[ERROR] 2017-03-10 22:39:11,475 (SyncFailedTask:submitSynchronizationFailed:132) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>

The processing instruction target matching "[xX][mM][lL]" is not allowed.

The reason for the failure of synchronization is: authoritativeMN in systemMetadata was not found in the Nodelist.

The "The processing instruction target matching "[xX][mM][lL]" is not allowed" is for the failure of sending the synchronization failure message back to MN.

Let's look at the real message on the production cn and it is:

[ WARN] 2017-03-06 18:57:15,364 (SyncFailedTask:submitSynchronizationFailed:116) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>

Synchronization task of [PID::] CLO_EOD-2015a.eml [::PID] failed. Cause: ServiceFailure: Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml - null

[ERROR] 2017-03-06 18:57:15,534 (SyncFailedTask:submitSynchronizationFailed:132) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>

The processing instruction target matching "[xX][mM][lL]" is not allowed.

So the reason for the synchronization failure is null, which is not very helpful :(

In order to reproduce the error, I download the system metadata and the object from the ebird node and changed the authoritative member to urn:node:mnDemo11. I used curl command to insert the object to mn-demo-11 which is in the cn-stage. I tried six times and all of them worked, not only the mn, but also cn. You may read them here:
https://cn-stage.test.dataone.org/cn/v2/object/CLO_EOD-2015a.eml.5
https://cn-stage.test.dataone.org/cn/v2/object/CLO_EOD-2015a.eml.4
https://cn-stage.test.dataone.org/cn/v2/object/CLO_EOD-2015a.eml.3
https://cn-stage.test.dataone.org/cn/v2/object/CLO_EOD-2015a.eml.2
https://cn-stage.test.dataone.org/cn/v2/object/CLO_EOD-2015a.eml.1
https://cn-stage.test.dataone.org/cn/v2/object/CLO_EOD-2015a.eml

Cn stage and production have the identical code, so I can't understand why the production doesn't work.

Maybe we can restart tomcat on the ebird node, then resync the object again?

Thanks,

Jing

#2 Updated by Jing Tao over 7 years ago

Hi everyone:

Mark reset the last harvest date and did a synchronization again. However, we got the same error message.
I compared the Metacat log message on cn-stage (successful) and cn production (failed) and found the metacat cn.create wasn't called at all on the production cn. In the cn-stage (successful), I saw some thing like (the pid is CLO_EOD-2015a.eml.6) :

/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: handling verb 2 request with resource 'object' [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: Using resource 'object' [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: D1 Rest: Starting resource processing... [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: objectId: null [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: verb:2 [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: Disassembling MIME multipart form [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: temp dir: /var/metacat/temporary [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: resolved multipart request [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: got multipart files [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: iterating through files [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: files key: sysmeta [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: files value: /var/metacat/temporary/upload_69c58b7e_15a5f765388_8000_00458051.tmp [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: files key: object [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: files value: /var/metacat/temporary/upload_69c58b7e_15a5f765388_8000_00458050.tmp [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: iterating through multipartparams [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: multipartparams key: pid [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3:metacat 20170314-23:06:12: [DEBUG]: multipartparams value: [CLO_EOD-2015a.eml.6] [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: iterating through params [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: done iterating the request... [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3:metacat 20170314-23:06:12: [DEBUG]: putObject: CLO_EOD-2015a.eml.6/insert [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3-metacat 20170314-23:06:12: [DEBUG]: Commence creation... [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]
/var/metacat/logs/metacat.log.3:metacat 20170314-23:06:12: [DEBUG]: creating object with pid CLO_EOD-2015a.eml.6 [edu.ucsb.nceas.metacat.restservice.D1ResourceHandler]

They are the log message from Metacat cn rest service for creating object. But it didn't show up at the production metacat log. This means the synchronization process didn't get that point.

I looked at the synchronization log on both cn-stage and cn production as well. They both got this point:
logger.debug(task.taskLabel() + " Calling CNCreate...");
d1Identifier = nodeCommunications.getCnCore().create(session, d1Identifier, sciMetaStream,
systemMetadata);

For the cn-stage, when it ran above the code, it got a RatryableException and eventually it succeeded. However, for the production cn, it got an UnrecoverableException and failed. As I mentioned above, the Metacat log on the production cn suggested that the Metacat rest service wasn't called. Do you guys have some idea?

Thanks,
Jing

Here is the sync log from stage (successful):
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:12,552 (V2TransferObjectTask:createObject:777) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 Calling CNCreate...
/var/log/dataone/synchronize/cn-synchronization.log-[ERROR] 2017-03-14 23:06:30,148 (ObjectListHarvestTask:retrieve:304) urn:node:mnTestMPC- <?xml version="1.0" encoding="UTF-8"?>
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log- class org.dataone.client.exception.ClientSideException: /Connect to dataone-test.pop.umn.edu:443 [dataone-test.pop.umn.edu/134.84.88.240] failed: connect timed out
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:30,215 (ObjectListHarvestTask:call:241) urn:node:mnTestMPC- ObjectListHarvestTask End
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:30,216 (MemberNodeHarvestJob:execute:71) urn:node:mnTestMPC - ObjectListHarvestTask Completed at Tue Mar 14 2017 23:06:30 UTC
/var/log/dataone/synchronize/cn-synchronization.log:[ WARN] 2017-03-14 23:06:42,660 (V2TransferObjectTask:processTask:421) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - RetryableException - RetryableException - retryable exception discovered (SocketTimeout)
/var/log/dataone/synchronize/cn-synchronization.log:[ WARN] 2017-03-14 23:06:42,660 (V2TransferObjectTask:call:212) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - RetryableException raised on attempt 1 of 20. Sleeping and requeueing. - RetryableException - retryable exception discovered (SocketTimeout)
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:42,888 (V2TransferObjectTask:call:285) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Unlocked Pid.
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:42,888 (V2TransferObjectTask:call:288) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - exiting with callState: STARTED
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:42,928 (SyncObjectTask:reapFutures:274) waiting on 1 futures
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:42,928 (SyncObjectTask:reapFutures:293) trying future Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:42,928 (SyncObjectTask:reapFutures:297) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 SyncObjectState: STARTED
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:42,928 (SyncObjectTask:reapFutures:302) futureMap is done? true
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:42,929 (SyncObjectTask:reapFutures:303) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 Returned from the Future :(1):
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:42,929 (SyncObjectTask:executeTransferObjectTask:219) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 received
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:42,929 (SyncObjectTask:executeTransferObjectTask:236) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 submitted for execution
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:42,929 (SyncObjectTask:call:164) ActiveCount: 1 Pool size 2 Max Pool Size 100
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:45,000 (MemberNodeHarvestJob:execute:56) urn:node:mnTestSEAD - ObjectListHarvestTask Start
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:45,000 (ObjectListHarvestTask:call:113) urn:node:mnTestSEAD- Calling ObjectListHarvestTask
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:45,075 (ObjectListHarvestTask:call:163) urn:node:mnTestSEAD- starting retrieval http://seadva-test.d2i.indiana.edu/sead/rest/mn with startDate of 2017-03-14T12:37:42.652+00:00 and endDate of 2017-03-14T23:06:35.000+00:00
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:45,288 (ObjectListHarvestTask:call:241) urn:node:mnTestSEAD- ObjectListHarvestTask End
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:45,288 (MemberNodeHarvestJob:execute:71) urn:node:mnTestSEAD - ObjectListHarvestTask Completed at Tue Mar 14 2017 23:06:45 UTC
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,510 (SyncMetricLogJobTriggerListener:triggerFired:68) triggerFired
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,510 (SyncMetricLogJobTriggerListener:vetoJobExecution:86) vetoJobExecution
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,510 (SyncMetricLogJobTriggerListener:lockJob:109) lockJob is true queue size is 1
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,511 (SyncMetricLogJob:execute:41) start
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,511 (SyncMetricLogReport:reportSyncMetrics:29) start
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:47,660 (V2TransferObjectTask:call:194) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Locking task, attempt 2
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:47,688 (V2TransferObjectTask:call:202) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Processing SyncObject
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,713 (SyncMetricLogReport:reportSyncMetrics:59) end
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,713 (SyncMetricLogJob:execute:49) end
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,714 (SyncMetricLogJobTriggerListener:releaseJob:98) releaseJob
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:06:47,714 (SyncMetricLogJobTriggerListener:triggerComplete:62) triggersComplete
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:48,025 (V2TransferObjectTask:retrieveMNSystemMetadata:304) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Retrieved SystemMetadata Identifier:CLO_EOD-2015a.eml.6 from node urn:node:mnDemo11 for ObjectInfo Identifier CLO_EOD-2015a.eml.6
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,025 (V2TransferObjectTask:call:204) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 MN system metadata retrieved...
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,025 (V2TransferObjectTask:processTask:399) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 entering processTask...
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,026 (V2TransferObjectTask:validateSeriesId:567) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 entering validateSeriesId...
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,026 (V2TransferObjectTask:resolve:669) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 entering resolve...
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,438 (V2TransferObjectTask:resolve:672) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 PID CLO_EOD-2015a.eml.6 exists on the CN.
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,438 (V2TransferObjectTask:processUpdates:958) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 entering processUpdates...
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:48,438 (V2TransferObjectTask:processUpdates:963) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Start ProcessUpdate
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,438 (V2TransferObjectTask:processUpdates:964) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 Getting sysMeta from HazelCast map
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:48,439 (SystemMetadataValidator:schemaValidateSystemMetadata:70) Entering schemaValidateSysMeta method...
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:06:48,439 (SystemMetadataValidator:validateEssentialProperties:180) The submitted checksum matches existing one
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:06:48,549 (V2TransferObjectTask:processV2AuthoritativeUpdate:1159) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 entering processV2AuthoritativeUpdate...
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:48,552 (V2TransferObjectTask:processV2AuthoritativeUpdate:1199) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - No changes to update.
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:48,552 (V2TransferObjectTask:processUpdates:988) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Completed ProcessUpdate
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:48,581 (V2TransferObjectTask:call:285) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - Unlocked Pid.
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:06:48,581 (V2TransferObjectTask:call:288) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 - exiting with callState: SUCCESS
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,510 (SyncMetricLogJobTriggerListener:triggerFired:68) triggerFired
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,510 (SyncMetricLogJobTriggerListener:vetoJobExecution:86) vetoJobExecution
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,510 (SyncMetricLogJobTriggerListener:lockJob:109) lockJob is true queue size is 1
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,510 (SyncMetricLogJob:execute:41) start
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,510 (SyncMetricLogReport:reportSyncMetrics:29) start
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,714 (SyncMetricLogReport:reportSyncMetrics:59) end
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,714 (SyncMetricLogJob:execute:49) end
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,714 (SyncMetricLogJobTriggerListener:releaseJob:98) releaseJob
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:07:47,714 (SyncMetricLogJobTriggerListener:triggerComplete:62) triggersComplete
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 23:08:13,344 (SyncObjectTask:reapFutures:274) waiting on 1 futures
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:08:13,344 (SyncObjectTask:reapFutures:293) trying future Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 23:08:13,344 (SyncObjectTask:reapFutures:297) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 SyncObjectState: SUCCESS
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 23:08:13,344 (SyncObjectTask:reapFutures:302) futureMap is done? true
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 23:08:13,345 (SyncObjectTask:reapFutures:303) Task-urn:node:mnDemo11-CLO_EOD-2015a.eml.6 Returned from the Future :(1):

Here is the sync log from production (failed):
/var/log/dataone/synchronize/cn-synchronization.log:[DEBUG] 2017-03-14 21:51:16,074 (V2TransferObjectTask:createObject:777) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml Calling CNCreate...
/var/log/dataone/synchronize/cn-synchronization.log-[DEBUG] 2017-03-14 21:51:17,258 (V2TransferObjectTask:createObject:781) Task-urn:node:ARCTIC-resource_map_urn:uuid:c93fe787-4ce4-4dd6-b932-739069ef0ea9 ... CNCreate finished
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 21:51:17,259 (V2TransferObjectTask:createObject:792) Task-urn:node:ARCTIC-resource_map_urn:uuid:c93fe787-4ce4-4dd6-b932-739069ef0ea9 - Completed CreateObject
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 21:51:17,328 (V2TransferObjectTask:call:285) Task-urn:node:ARCTIC-resource_map_urn:uuid:c93fe787-4ce4-4dd6-b932-739069ef0ea9 - Unlocked Pid.
/var/log/dataone/synchronize/cn-synchronization.log-[ INFO] 2017-03-14 21:51:17,328 (V2TransferObjectTask:call:288) Task-urn:node:ARCTIC-resource_map_urn:uuid:c93fe787-4ce4-4dd6-b932-739069ef0ea9 - exiting with callState: SUCCESS
/var/log/dataone/synchronize/cn-synchronization.log:[ WARN] 2017-03-14 21:51:17,916 (SyncFailedTask:submitSynchronizationFailed:116) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>
/var/log/dataone/synchronize/cn-synchronization.log:
/var/log/dataone/synchronize/cn-synchronization.log: Synchronization task of [PID::] CLO_EOD-2015a.eml [::PID] failed. Cause: ServiceFailure: Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml - null
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log:[ERROR] 2017-03-14 21:51:18,130 (SyncFailedTask:submitSynchronizationFailed:132) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml <?xml version="1.0" encoding="UTF-8"?>
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log- The processing instruction target matching "[xX][mM][lL]" is not allowed.
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log-
/var/log/dataone/synchronize/cn-synchronization.log:[ERROR] 2017-03-14 21:51:18,130 (V2TransferObjectTask:call:269) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml - UnrecoverableException: CLO_EOD-2015a.eml cn.createObject failed
/var/log/dataone/synchronize/cn-synchronization.log:org.dataone.cn.batch.exceptions.UnrecoverableException: CLO_EOD-2015a.eml cn.createObject failed
/var/log/dataone/synchronize/cn-synchronization.log- at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.createObject(V2TransferObjectTask.java:795)
/var/log/dataone/synchronize/cn-synchronization.log- at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processNewObject(V2TransferObjectTask.java:480)
/var/log/dataone/synchronize/cn-synchronization.log- at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processTask(V2TransferObjectTask.java:413)
/var/log/dataone/synchronize/cn-synchronization.log- at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:206)
/var/log/dataone/synchronize/cn-synchronization.log- at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:110)
/var/log/dataone/synchronize/cn-synchronization.log- at java.util.concurrent.FutureTask.run(FutureTask.java:266)
/var/log/dataone/synchronize/cn-synchronization.log- at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
/var/log/dataone/synchronize/cn-synchronization.log- at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
/var/log/dataone/synchronize/cn-synchronization.log- at java.lang.Thread.run(Thread.java:745)
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 21:51:18,198 (V2TransferObjectTask:call:285) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml - Unlocked Pid.
/var/log/dataone/synchronize/cn-synchronization.log:[ INFO] 2017-03-14 21:51:18,199 (V2TransferObjectTask:call:288) Task-urn:node:CLOEBIRD-CLO_EOD-2015a.eml - exiting with callState: FAILED