Bug #7938
Malformed system metadata
100%
Description
System metadata for the PID @doi:10.5063/AA/wolkovich.29.1@ is malformed:
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
11
doi:10.5063/AA/wolkovich.29.1
text/csv
171623
1286d997ca68c198862a6f1d266cbc2b
uid=wolkovich,o=NCEAS,dc=ecoinformatics,dc=org
uid=wolkovich,o=NCEAS,dc=ecoinformatics,dc=org
cn=esa-moderators,dc=ecoinformatics,dc=org
read
write
changePermission
public
read
cn=knb-prod,o=NCEAS,dc=ecoinformatics,dc=org</<?xml version="1.0" encoding="UTF-8"?>
Copy of system metadata retrieved from the KNB MN:
<?xml version="1.0" encoding="UTF-8"?>
11
doi:10.5063/AA/wolkovich.29.1
text/csv
171623
1286d997ca68c198862a6f1d266cbc2b
uid=wolkovich,o=NCEAS,dc=ecoinformatics,dc=org
uid=wolkovich,o=NCEAS,dc=ecoinformatics,dc=org
public
read
uid=nceasadmin,o=NCEAS,dc=ecoinformatics,dc=org
read
write
changePermission
cn=knb-prod,o=NCEAS,dc=ecoinformatics,dc=org
read
write
changePermission
cn=esa-moderators,dc=ecoinformatics,dc=org
read
write
changePermission
uid=ewolkovich,o=unaffiliated,dc=ecoinformatics,dc=org
read
write
false
2012-02-23T00:00:00.000+00:00
2014-12-14T04:25:32.024+00:00
urn:node:KNB
urn:node:KNB
urn:node:mnUCSB1
completed
2014-12-14T04:25:16.028+00:00
urn:node:mnUNM1
completed
2014-12-14T04:25:23.515+00:00
urn:node:KNB
completed
2014-12-14T04:25:30.943+00:00
History
#1 Updated by Dave Vieglais almost 8 years ago
- Description updated (diff)
#2 Updated by Dave Vieglais almost 8 years ago
Log grepping (from cn-ucsb-1, before upgrade complete):
$ cd /var/log/dataone
$ sudo grep -r "doi:10.5063/AA/wolkovich.29.1" * | tee /tmp/wolkovich.logs
[sudo] password for vieglais:
cn/d1SolrExtensions.log.19:[DEBUG] 2016-11-12 21:52:43,982 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.30.1" OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.19:[DEBUG] 2016-11-12 21:52:43,984 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.30.1" OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.37:[DEBUG] 2016-11-01 07:33:54,712 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.37:[DEBUG] 2016-11-01 07:33:54,714 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.38:[DEBUG] 2016-10-31 19:05:27,735 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.38:[DEBUG] 2016-10-31 19:05:27,740 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.38:[DEBUG] 2016-10-31 19:41:34,395 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.38:[DEBUG] 2016-10-31 19:41:34,396 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.26:[DEBUG] 2016-11-08 02:28:37,220 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.26:[DEBUG] 2016-11-08 02:28:37,222 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.4:[DEBUG] 2016-11-20 18:36:12,863 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.4:[DEBUG] 2016-11-20 18:36:12,865 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.47:[DEBUG] 2016-10-27 06:17:59,076 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
cn/d1SolrExtensions.log.47:[DEBUG] 2016-10-27 06:17:59,077 (SolrSearchHandlerUtil:logSolrParameters:205) value: nodeId:"urn:node:KNB" event:read pid:("doi:10.5063/F10V89RP" OR wolkovich.50.1 OR "doi:10.5063/AA/wolkovich.28.1" OR "doi:10.5063/AA/wolkovich.29.1" OR "doi:10.5063/AA/wolkovich.30.1") inPartialRobotList:false isRepeatVisit:false
daemon/cn-process-daemon.log.34:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:isAllowed:807) ReplicationManager.isAllowed() called for doi:10.5063/AA/wolkovich.29.1
daemon/cn-process-daemon.log.34:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:isAllowed:824) ReplicationManager.isAllowed() = true for doi:10.5063/AA/wolkovich.29.1
daemon/cn-process-daemon.log.34:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:processPid:418) Replication is allowed for identifier doi:10.5063/AA/wolkovich.29.1
daemon/cn-process-daemon.log.34:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:processPid:423) Getting the replica list for identifier doi:10.5063/AA/wolkovich.29.1
daemon/cn-process-daemon.log.34:[ INFO] 2016-11-18 07:11:18,550 (ReplicationManager:removeReplicationTasksForPid:772) removing replication tasks for pid: doi:10.5063/AA/wolkovich.29.1
daemon/cn-process-daemon.log.34:[ INFO] 2016-11-18 07:11:18,722 (ReplicationManager:createAndQueueTasks:390) Added 0 MNReplicationTasks to the queue for doi:10.5063/AA/wolkovich.29.1
daemon/cn-process-daemon.log.34:[ WARN] 2016-11-18 07:11:18,723 (ReplicationManager:requeueReplicationTask:787) In Replication Manager, task that should exist 'in process' does not exist. Creating new task for pid: doi:10.5063/AA/wolkovich.29.1
index/cn-index-generator-daemon.log.7:[ INFO] 2015-12-12 12:10:25,676 (IndexTaskGeneratorEntryListener:entryUpdated:87) UPDATE EVENT - index task generator - system metadata callback invoked on pid: doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:isAllowed:807) ReplicationManager.isAllowed() called for doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:isAllowed:824) ReplicationManager.isAllowed() = true for doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:processPid:418) Replication is allowed for identifier doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[DEBUG] 2016-11-18 07:11:18,490 (ReplicationManager:processPid:423) Getting the replica list for identifier doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[ INFO] 2016-11-18 07:11:18,550 (ReplicationManager:removeReplicationTasksForPid:772) removing replication tasks for pid: doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[ INFO] 2016-11-18 07:11:18,722 (ReplicationManager:createAndQueueTasks:390) Added 0 MNReplicationTasks to the queue for doi:10.5063/AA/wolkovich.29.1
replicate/cn-replication.log.35:[ WARN] 2016-11-18 07:11:18,723 (ReplicationManager:requeueReplicationTask:787) In Replication Manager, task that should exist 'in process' does not exist. Creating new task for pid: doi:10.5063/AA/wolkovich.29.1
#3 Updated by Dave Vieglais almost 8 years ago
- File wolkovich.logs added
Attaching output from grep on /var/log/dataone and /var/log/tomcat7 on cn-ucsb-1.
#4 Updated by Dave Vieglais almost 8 years ago
- Description updated (diff)
#5 Updated by Dave Vieglais almost 8 years ago
- Status changed from New to Closed
- % Done changed from 0 to 100
This issue was resolved by manually editing the postgres database.
The problem appears to be that invalid system metadata was written to the postgres database in the past (metacat, or more specifically java libclient nodes would produce empty elements which caused invalid entries).
With the 2.3 upgrade, the infrastructure moved to a different serialization mechanism which would fail when the system metadata was being serialized to xml. By manually editing the database and doing the equivalent of removing empty elements, the serializer was able to correctly generate the system metadata entries.
