Infrastructure » CN REST

this is most likely a NullPointerException, and the stacktrace will be in the logs. Unfortunately, not caught in a grep unless you look for it (the -A or -B argument). I don't have ssh access to DEV2 machines, so Chris, can you run this grep and copy in the result?

grep -B20 "Task-urn:node:mnDevUCSB2-http://dx.doi.org/10.5061/dryad.37mm8/2/bitstream" /var/log/dataone/synchronization/cn-synchronization.log

(or -B30 or whatever catches the relevant portions of the stacktrace )

Hey Rob, I've run the grep above but didn't see any stack trace. I vi'd the sync log and looked for the stacktrace around that timestamp (2015-09-28 12:19:11,121) but also didn't see anything. Looks like we need to figure out why we're not getting the stacktrace. I've added your ssh key to cn-dev-{ucsb|unm}-2 and mn-dev-{ucsb|unm}-{1|2} and put you in the sudo group.

looks like the ex.printStackTrace doesn't end up in any logs I looked through. the bare-line 'null' is the message from the exception, which is what NPEs use. By the other log messages, I can isolate the NPE to 2 lines of code in sync:

        NodeList nl = nodeCommunications.getNodeRegistryService().listNodes();
        boolean isV1Object = AuthUtils.isCNAuthorityForSystemMetadataUpdate(nl, newSystemMetadata);

calling https://mn-dev-ucsb-2.test.dataone.org/metacat/d1/mn/v1/meta/http://dx.doi.org/10.5061/dryad.37mm8/2/bitstream, I can rule out problems with the newSystemMetadata parameter, so there's an issue with either procuring the NodeRegisteryService, or the returned NodeList. NPEs will be emitted from AuthUtils.isCNAuthorityFor... if either the passed in NodeList is null, or the chosen Node record has no Services.

Will add better parameter checking to the AuthUtils methods, because null services is schema valid, although maybe not by business rules...
Also, will change the catch Exception to include the exception in the log statement so the stack trace has a better chance to make it into the logs.

Rob,

Looking at the d1_sync log on cn-dev-ucsb-2, here's the NPE that you were suspecting:

[ERROR] 2015-10-05 07:58:04,899 (V2TransferObjectTask:processTask:409) Task-urn:node:mnDevUNM2-testV2CreateV1Archive_201527873421430
null
java.lang.NullPointerException
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processUpdates(V2TransferObjectTask.java:896)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processTask(V2TransferObjectTask.java:392)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:204)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:110)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

which is coming from the call to get the node list:

NodeList nl = nodeCommunications.getNodeRegistryService().listNodes();

the same thing happening on DEV:

[ERROR] 2015-10-04 05:11:11,811 (V2TransferObjectTask:processTask:409) Task-urn:node:mnDemo8-P1_20152762259634
null
java.lang.NullPointerException
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processUpdates(V2TransferObjectTask.java:896)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processTask(V2TransferObjectTask.java:392)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:204)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:110)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:745)¶

and I also see an NPE in validateChecksum when trying to create meaningful error message

[ERROR] 2015-10-04 05:31:14,873 (V2TransferObjectTask:processTask:409) Task-urn:node:mnDemo8-testUpdateSystemMetadata_MutableAccessPolicy_2015276222828801
null
java.lang.NullPointerException
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.validateChecksum(V2TransferObjectTask.java:765)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.createObject(V2TransferObjectTask.java:654)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processNewObject(V2TransferObjectTask.java:430)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.processTask(V2TransferObjectTask.java:394)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:204)
at org.dataone.cn.batch.synchronization.tasks.V2TransferObjectTask.call(V2TransferObjectTask.java:110)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

the latter can be addressed through null checking.

The former, I'm not sure the reason for. If it's happening in two environments, it's either a client resource consumption issue, or a network one. the DEV-2 mn where the failure is happening is on the same LAN as the DEV2 CN, so less likely a network issue.

Jing reports that after the hazelcast changes, synchronize method still does not work.

The error in the synchronize log file reads, “The requested identifier tao.13365.1 is already used by another object and therefore can not be used for this object. Clients should choose a new identifier that is unique and retry the operation or use CN.reserveIdentifier() to reserve one.”

Looks like synchronization believes the call to be a create instead of an update.
From log file:

[DEBUG] 2015-10-13 15:54:10,675 (V2TransferObjectTask:alreadyExists:566) Task-urn:node:mnDemo6-tao.13365.1 entering alreadyExists...
[ INFO] 2015-10-13 15:54:10,809 (V2TransferObjectTask:alreadyExists:583) Task-urn:node:mnDemo6-tao.13365.1 Pid doesn't exist as reservation or object.

it does not appear that the object was found in the reserveIdentifier service though it was already created in the object store. maybe a hangover from a previous bug that has been since squashed?

This is happening because sync is still relying on hasReservation to determine if something is a new object or an update. If the Identifier Manager Service no longer throws IdentifierNotUnique, it will only see no reservation and assume it's a new object. This will fix when the changes are committed and deployed.