Bug #8361
Updated by Rob Nahf almost 7 years ago
Seen in STAGE, from among a group of task left in the 'IN PROCESS' state:
~~~
[ INFO] 2018-02-12 16:52:10,292 (IndexTaskProcessor:getNextIndexTask:610) Start of indexing pid: urn:uuid:eff10cb2-e454-4bc8-acc2-0927488621b0
[ERROR] 2018-02-12 16:52:10,311 (IndexTask:unMarshalSystemMetadata:221)
org.dataone.exceptions.MarshallingException
at org.dataone.service.util.TypeMarshaller.unmarshalTypeFromStream(TypeMarshaller.java:299)
at org.dataone.cn.index.task.IndexTask.unMarshalSystemMetadata(IndexTask.java:213)
at org.dataone.cn.index.task.IndexTask.isArchived(IndexTask.java:251)
at org.dataone.cn.index.task.IndexTask.isDeleteTask(IndexTask.java:265)
at org.dataone.cn.index.processor.IndexTaskProcessor.getNextIndexTask(IndexTaskProcessor.java:612)
at org.dataone.cn.index.processor.IndexTaskProcessor.processIndexTaskQueue(IndexTaskProcessor.java:184)
at org.dataone.cn.index.processor.IndexTaskProcessorJob.execute(IndexTaskProcessorJob.java:57)
at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
Caused by: javax.xml.bind.UnmarshalException
- with linked exception:
[org.xml.sax.SAXParseException; Premature end of file.]
at javax.xml.bind.helpers.AbstractUnmarshallerImpl.createUnmarshalException(AbstractUnmarshallerImpl.java:335)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.createUnmarshalException(UnmarshallerImpl.java:563)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:249)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:214)
at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:157)
at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:204)
at org.dataone.service.util.TypeMarshaller.unmarshalTypeFromStream(TypeMarshaller.java:297)
... 8 more
Caused by: org.xml.sax.SAXParseException; Premature end of file.
at org.apache.xerces.util.ErrorHandlerWrapper.createSAXParseException(Unknown Source)
at org.apache.xerces.util.ErrorHandlerWrapper.fatalError(Unknown Source)
at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
at org.apache.xerces.impl.XMLVersionDetector.determineDocVersion(Unknown Source)
at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
at org.apache.xerces.parsers.XMLParser.parse(Unknown Source)
at org.apache.xerces.parsers.AbstractSAXParser.parse(Unknown Source)
at org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:243)
... 12 more
[ERROR] 2018-02-12 16:52:10,312 (JobRunShell:run:222) Job d1-cn-index-processor.d1-index-processor-job threw an unhandled Exception:
java.lang.NullPointerException
[ERROR] 2018-02-12 16:52:10,313 (ErrorLogger:schedulerError:2360) Job (d1-cn-index-processor.d1-index-processor-job threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: java.lang.NullPointerException]
at org.quartz.core.JobRunShell.run(JobRunShell.java:224)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
Caused by: java.lang.NullPointerException
[ WARN] 2018-02-12 16:54:08,196 (IndexTaskProcessorJob:execute:55) processing job [1806183035/org.dataone.cn.index.processor.IndexTaskProcessorJob@15d15ed9] executing index task with processor [org.dataone.cn.index.processor.IndexTaskProcessor@20621d44]
[ INFO] 2018-02-12 16:54:09,567 (IndexTaskProcessor:logProcessorLoad:245) new tasks:375, tasks previously failed: 1660
~~~
and this in postgres:
~~~
d1-index-queue=# select * from index_task where sysmetadata = '';
id | datesysmetamodified | deleted | formatid | nextexecution | objectpath | pid | priority | status | sysmetadata | taskmodifieddate | trycount | version
----------+---------------------+---------+---------------------------------------+---------------+------------+-----------------------------------------------+----------+------------+-------------+------------------+----------+---------
14083132 | 1452029399937 | f | text/plain | 1518032957157 | | urn:uuid:eff10cb2-e454-4bc8-acc2-0927488621b0 | 1 | IN PROCESS | | 1518454330288 | 4 | 5
14083818 | 1452029390440 | f | eml://ecoinformatics.org/eml-2.1.1 | 1518032959192 | | urn:uuid:0f327426-3e97-428f-810e-44a83ec92047 | 1 | IN PROCESS | | 1518454449880 | 4 | 5
14085245 | 1452032067206 | f | text/plain | 1518032963639 | | urn:uuid:7a31a8e1-54c1-4d10-9c7d-7cf969db4015 | 1 | IN PROCESS | | 1518454569874 | 4 | 5
14087397 | 1452032061198 | f | text/csv | 1518032967945 | | urn:uuid:0d07b6f5-4299-43e5-a1b8-aa37b259e51f | 1 | IN PROCESS | | 1518454690716 | 4 | 5
14087857 | 1452032064477 | f | eml://ecoinformatics.org/eml-2.1.1 | 1518032968646 | | urn:uuid:56e25ff0-dc85-4441-a4c2-74b9955cc43d | 1 | IN PROCESS | | 1518454809882 | 4 | 5
14088344 | 1452032063246 | f | text/csv | 1518032969414 | | urn:uuid:2fb13ee6-fb8a-4eea-b9ee-f52e85b35a7a | 1 | IN PROCESS | | 1518454930608 | 4 | 5
14092345 | 1452032069944 | f | http://www.openarchives.org/ore/terms | 1518032978246 | | urn:uuid:5429c13d-db3e-4997-985a-eee1273163d7 | 3 | IN PROCESS | | 1518455322387 | 4 | 5
(7 rows)
~~~
The missing systemMetadata causes a parse error that in turn causes a Marshalling Exception, which I believe caused the NPE. Need to investigate the source code to see if this is the case.
The index processor should ideally handle the lack of sysmetadata more gracefully.
~~~
[ INFO] 2018-02-12 16:52:10,292 (IndexTaskProcessor:getNextIndexTask:610) Start of indexing pid: urn:uuid:eff10cb2-e454-4bc8-acc2-0927488621b0
[ERROR] 2018-02-12 16:52:10,311 (IndexTask:unMarshalSystemMetadata:221)
org.dataone.exceptions.MarshallingException
at org.dataone.service.util.TypeMarshaller.unmarshalTypeFromStream(TypeMarshaller.java:299)
at org.dataone.cn.index.task.IndexTask.unMarshalSystemMetadata(IndexTask.java:213)
at org.dataone.cn.index.task.IndexTask.isArchived(IndexTask.java:251)
at org.dataone.cn.index.task.IndexTask.isDeleteTask(IndexTask.java:265)
at org.dataone.cn.index.processor.IndexTaskProcessor.getNextIndexTask(IndexTaskProcessor.java:612)
at org.dataone.cn.index.processor.IndexTaskProcessor.processIndexTaskQueue(IndexTaskProcessor.java:184)
at org.dataone.cn.index.processor.IndexTaskProcessorJob.execute(IndexTaskProcessorJob.java:57)
at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
Caused by: javax.xml.bind.UnmarshalException
- with linked exception:
[org.xml.sax.SAXParseException; Premature end of file.]
at javax.xml.bind.helpers.AbstractUnmarshallerImpl.createUnmarshalException(AbstractUnmarshallerImpl.java:335)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.createUnmarshalException(UnmarshallerImpl.java:563)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:249)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:214)
at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:157)
at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:204)
at org.dataone.service.util.TypeMarshaller.unmarshalTypeFromStream(TypeMarshaller.java:297)
... 8 more
Caused by: org.xml.sax.SAXParseException; Premature end of file.
at org.apache.xerces.util.ErrorHandlerWrapper.createSAXParseException(Unknown Source)
at org.apache.xerces.util.ErrorHandlerWrapper.fatalError(Unknown Source)
at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
at org.apache.xerces.impl.XMLVersionDetector.determineDocVersion(Unknown Source)
at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
at org.apache.xerces.parsers.XMLParser.parse(Unknown Source)
at org.apache.xerces.parsers.AbstractSAXParser.parse(Unknown Source)
at org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:243)
... 12 more
[ERROR] 2018-02-12 16:52:10,312 (JobRunShell:run:222) Job d1-cn-index-processor.d1-index-processor-job threw an unhandled Exception:
java.lang.NullPointerException
[ERROR] 2018-02-12 16:52:10,313 (ErrorLogger:schedulerError:2360) Job (d1-cn-index-processor.d1-index-processor-job threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: java.lang.NullPointerException]
at org.quartz.core.JobRunShell.run(JobRunShell.java:224)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
Caused by: java.lang.NullPointerException
[ WARN] 2018-02-12 16:54:08,196 (IndexTaskProcessorJob:execute:55) processing job [1806183035/org.dataone.cn.index.processor.IndexTaskProcessorJob@15d15ed9] executing index task with processor [org.dataone.cn.index.processor.IndexTaskProcessor@20621d44]
[ INFO] 2018-02-12 16:54:09,567 (IndexTaskProcessor:logProcessorLoad:245) new tasks:375, tasks previously failed: 1660
~~~
and this in postgres:
~~~
d1-index-queue=# select * from index_task where sysmetadata = '';
id | datesysmetamodified | deleted | formatid | nextexecution | objectpath | pid | priority | status | sysmetadata | taskmodifieddate | trycount | version
----------+---------------------+---------+---------------------------------------+---------------+------------+-----------------------------------------------+----------+------------+-------------+------------------+----------+---------
14083132 | 1452029399937 | f | text/plain | 1518032957157 | | urn:uuid:eff10cb2-e454-4bc8-acc2-0927488621b0 | 1 | IN PROCESS | | 1518454330288 | 4 | 5
14083818 | 1452029390440 | f | eml://ecoinformatics.org/eml-2.1.1 | 1518032959192 | | urn:uuid:0f327426-3e97-428f-810e-44a83ec92047 | 1 | IN PROCESS | | 1518454449880 | 4 | 5
14085245 | 1452032067206 | f | text/plain | 1518032963639 | | urn:uuid:7a31a8e1-54c1-4d10-9c7d-7cf969db4015 | 1 | IN PROCESS | | 1518454569874 | 4 | 5
14087397 | 1452032061198 | f | text/csv | 1518032967945 | | urn:uuid:0d07b6f5-4299-43e5-a1b8-aa37b259e51f | 1 | IN PROCESS | | 1518454690716 | 4 | 5
14087857 | 1452032064477 | f | eml://ecoinformatics.org/eml-2.1.1 | 1518032968646 | | urn:uuid:56e25ff0-dc85-4441-a4c2-74b9955cc43d | 1 | IN PROCESS | | 1518454809882 | 4 | 5
14088344 | 1452032063246 | f | text/csv | 1518032969414 | | urn:uuid:2fb13ee6-fb8a-4eea-b9ee-f52e85b35a7a | 1 | IN PROCESS | | 1518454930608 | 4 | 5
14092345 | 1452032069944 | f | http://www.openarchives.org/ore/terms | 1518032978246 | | urn:uuid:5429c13d-db3e-4997-985a-eee1273163d7 | 3 | IN PROCESS | | 1518455322387 | 4 | 5
(7 rows)
~~~
The missing systemMetadata causes a parse error that in turn causes a Marshalling Exception, which I believe caused the NPE. Need to investigate the source code to see if this is the case.
The index processor should ideally handle the lack of sysmetadata more gracefully.