Project

General

Profile

identifiersMissingUCSB-Documents.analysis.txt

Robert Waltz, 2012-08-15 16:10

Download (15.8 KB)

 
1
Examining issue #2 from UCSB
2
FROM UCSB identifiers missing xml_documents or xml_revisions
3

    
4
 doi:10.6073/AA/knb-lter-gce.144.3
5
 doi:10.6073/AA/knb-lter-gce.172.3
6
 doi:10.6073/AA/knb-lter-gce.170.1
7
 doi:10.6073/AA/knb-lter-gce.178.1
8
 doi:10.6073/AA/knb-lter-gce.181.2
9
 doi:10.6073/AA/knb-lter-gce.57.14
10
 doi:10.6073/AA/knb-lter-gce.50.5
11
 doi:10.6073/AA/knb-lter-gce.66.3
12
 doi:10.6073/AA/knb-lter-gce.83.5
13
 doi:10.6073/AA/knb-lter-gce.71.12
14
 doi:10.6073/AA/knb-lter-gce.80.6
15
 doi:10.6073/AA/knb-lter-gce.87.4
16
 doi:10.6073/AA/knb-lter-gce.87.5
17
 doi:10.6073/AA/knb-lter-gce.97.4
18
 doi:10.6073/AA/knb-lter-gce.8.3
19
 doi:10.6073/AA/knb-lter-kbs.35.6
20
 doi:10.6073/AA/knb-lter-kbs.38.2
21
 doi:10.6073/AA/knb-lter-kbs.39.2
22
(18 rows)
23

    
24
looking at doi:10.6073/AA/knb-lter-gce.144.3
25
cd /var/log/dataone/synchronize/
26
grep -P 'doi\:10\.6073\/AA\/knb\-lter\-gce\.144\.3' *
27

    
28
FROM UCSB (CREATED)
29
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:01,716 (SyncObjectTask:call:207)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 received
30
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:01,716 (TransferObjectTask:call:114)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Locking task of  attempt 1
31
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:01,857 (TransferObjectTask:call:120)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Processing task
32
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:02,271  (TransferObjectTask:retrieveSystemMetadata:250)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Retrieved  SystemMetadata Identifier:doi:10.6073/AA/knb-lter-gce.144.3 from node  urn:node:LTER for ObjectInfo Identifier  doi:10.6073/AA/knb-lter-gce.144.3
33
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:02,271 (TransferObjectTask:call:123)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Writing task
34
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:02,271 (TransferObjectTask:write:376)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Getting sysMeta  from CN
35
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:02,438 (TransferObjectTask:write:396)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Create from  Exception
36
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:02,852 (SyncObjectTask:call:180)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3Waiting for the  future :(5): since 2012-06-26T13:12:01.716+00:00
37
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:03,144 (TransferObjectTask:createObject:535)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Creating Object
38
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:05,488 (SyncObjectTask:call:180)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3Waiting for the  future :(5): since 2012-06-26T13:12:01.716+00:00
39
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:07,658 (SyncObjectTask:call:180)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3Waiting for the  future :(5): since 2012-06-26T13:12:01.716+00:00
40
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:11,065 (TransferObjectTask:createObject:538)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Created Object
41
cn-synchronization.log.15:[  INFO] 2012-06-26 13:12:20,056 (SyncObjectTask:call:149)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Returned from the  Future :5:
42

    
43
FROM ORC (UPDATED)
44
cn-synchronization.log.6:[  INFO] 2012-06-30 04:13:58,705 (SyncObjectTask:call:207)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 received
45
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:25,604 (SyncObjectTask:call:207)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 received
46
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:25,607 (TransferObjectTask:call:114)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Locking task of  attempt 1
47
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:25,886 (TransferObjectTask:call:120)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Processing task
48
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,313 (SyncObjectTask:call:180)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3Waiting for the  future :(4): since 2012-06-30T04:14:25.604+00:00
49
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,494  (TransferObjectTask:retrieveSystemMetadata:250)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Retrieved  SystemMetadata Identifier:doi:10.6073/AA/knb-lter-gce.144.3 from node  urn:node:LTER for ObjectInfo Identifier  doi:10.6073/AA/knb-lter-gce.144.3
50
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,494 (TransferObjectTask:call:123)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Writing task
51
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,494 (TransferObjectTask:write:376)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Getting sysMeta  from CN
52
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,567 (TransferObjectTask:write:398)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Pid Exists. Must be  an Update
53
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,638 (TransferObjectTask:write:419)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Update sysMeta  because checksum is same
54
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:26,708  (TransferObjectTask:updateSystemMetadata:579)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Update Archived
55
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:36,521  (TransferObjectTask:auditReplicaSystemMetadata:636)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3  auditReplicaSystemMetadata
56
cn-synchronization.log.6:[  INFO] 2012-06-30 04:14:37,756  (TransferObjectTask:updateSystemMetadata:583)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Updated Archived
57
cn-synchronization.log.6:[  INFO] 2012-06-30 04:15:10,771 (SyncObjectTask:call:149)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Returned from the  Future :4:
58

    
59
FROM UCSB (updated again?)
60
cn-synchronization.log.13:[  INFO] 2012-06-30 04:12:33,056 (SyncObjectTask:call:207)  Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 received
61
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,054 (SyncObjectTask:call:207) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 received
62
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,093 (TransferObjectTask:call:114) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Locking task of attempt 1
63
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,119 (TransferObjectTask:call:120) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Processing task
64
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,608 (TransferObjectTask:retrieveSystemMetadata:250) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Retrieved SystemMetadata Identifier:doi:10.6073/AA/knb-lter-gce.144.3 from node urn:node:LTER for ObjectInfo Identifier doi:10.6073/AA/knb-lter-gce.144.3
65
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,609 (TransferObjectTask:call:123) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Writing task
66
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,609 (TransferObjectTask:write:376) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Getting sysMeta from CN
67
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,619 (SyncObjectTask:call:180) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3Waiting for the future :(2): since 2012-07-01T21:12:06.054+00:00
68
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,636 (TransferObjectTask:write:398) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Pid Exists. Must be an Update
69
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,662 (TransferObjectTask:write:419) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Update sysMeta because checksum is same
70
cn-synchronization.log.12:[ INFO] 2012-07-01 21:12:06,712 (SyncObjectTask:call:149) Task-urn:node:LTER-doi:10.6073/AA/knb-lter-gce.144.3 Returned from the Future :2:
71

    
72

    
73
Next, look at tables and metacat logs to determine the cause and extent of the error.
74

    
75
TRYING: 
76
doi:10.6073/AA/knb-lter-gce.144.3
77

    
78
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.144.3'\""
79
               guid                |            docid            | rev 
80
-----------------------------------+-----------------------------+-----
81
 doi:10.6073/AA/knb-lter-gce.144.3 | autogen.2012062606120365006 |   1
82

    
83
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062606120365006' and rev= 1\""  0 on UCSB, 1 on UNM, 1 on ORC
84

    
85
 revisionid |            docid            | rootnodeid | docname |              doctype               |              user_owner               | user_updated | server_location | rev | date_created | date_updated | public_access | catalog_id 
86
------------+-----------------------------+------------+---------+------------------------------------+---------------------------------------+--------------+-----------------+-----+--------------+--------------+---------------+------------
87
       2650 | autogen.2012062606120365006 |   23138109 | eml     | eml://ecoinformatics.org/eml-2.0.0 | CN=urn:node:CNUCSB1,DC=dataone,DC=org |              |               2 |   1 | 2012-06-26   | 2012-06-26   |             0 |         24
88
(1 row)
89

    
90
/var/metacat/logs# grep -P 'autogen\.2012062606120365006' replicate.log*
91

    
92
replicate.log.53:knb 2012-06-30T04:17:33: [ERROR]: ReplicationService.handleForceReplicateDeleteRequest - error: Problem deleting xml query result for docid autogen.2012062606120365006 : XMLQueryresultAccess.deleteXMLQueryresulForDoc - SQL error when deletingxml query result for doc id: autogen.2012062606120365006:Backend start-up failed: FATAL: connection limit exceeded for non-superusers.
93

    
94
TRYING:
95
 doi:10.6073/AA/knb-lter-gce.172.3
96
autogen.2012062606221626752
97
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062606221626752' and rev= 1\"" 0 on UCSB, 1 on UNM, 1 on ORC
98
grep -P '\[ERROR\].+?autogen\.2012062606221626752' replicate.log* 
99

    
100
no reason given for failure
101

    
102
TRYING:
103
doi:10.6073/AA/knb-lter-gce.170.1
104
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.170.1'\""
105
 doi:10.6073/AA/knb-lter-gce.170.1 | autogen.2012062606222580668 |   1
106

    
107
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062606222580668' and rev= 1\"" 0 on UCSB, 1 on UNM, 1 on ORC
108
grep -P '\[ERROR\].+?autogen\.2012062606222580668' replicate.log*
109
replicate.log.52:knb 2012-07-03T00:04:27: [ERROR]: ReplicationHandler.handleSingleXMLDocument - Failed to write doc autogen.2012062606222580668.1 into db because The file you are trying to write already exists  in metacat.  Please update your version number. 
110

    
111
TRYING:
112
 doi:10.6073/AA/knb-lter-gce.178.1
113
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.178.1'\""
114
 doi:10.6073/AA/knb-lter-gce.178.1 | autogen.2012062606252741934 |   1
115
 
116
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062606252741934' and rev= 1\"" 0 on UCSB, 1 on UNM, 1 on ORC
117
grep -P '\[ERROR\].+?autogen\.2012062606252741934' replicate.log*
118

    
119
no reason for failure
120

    
121
TRYING:
122
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.181.2'\""
123
 doi:10.6073/AA/knb-lter-gce.181.2 | autogen.2012062606250182948 |   1
124
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062606250182948'\"" 0 on UCSB, 1 on UNM, 1 on ORC
125
grep -P '\[ERROR\].+?autogen.2012062606250182948' replicate.log*
126
replicate.log.51:knb 2012-07-04T01:03:11: [ERROR]: ReplicationHandler.handleSingleXMLDocument - Failed to write doc autogen.2012062606250182948.1 into db because The file you are trying to write already exists  in metacat.  Please update your version number. 
127

    
128
TRYING:
129
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.57.14'\""
130
 doi:10.6073/AA/knb-lter-gce.57.14 | autogen.2012062607340591517 |   1
131
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607340591517'\"" 0 on UCSB, 1 on UNM, 1 on ORC
132

    
133
TRYING:
134
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.50.5'\""
135
 doi:10.6073/AA/knb-lter-gce.50.5 | autogen.2012062607353935542 |   1
136
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607353935542'\"" 0 on UCSB, 1 on UNM, 1 on ORC
137

    
138
TRYING:
139
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.66.3'\""
140
 doi:10.6073/AA/knb-lter-gce.66.3 | autogen.2012062607395066141 |   1
141
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607395066141'\"" 0 on UCSB, 1 on UNM, 1 on ORC
142

    
143
TRYING:
144
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.83.5'\""
145
 doi:10.6073/AA/knb-lter-gce.83.5 | autogen.2012062607482200460 |   1
146
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607482200460'\"" 0 on UCSB, 1 on UNM, 1 on ORC
147

    
148
TRYING:
149
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.71.12'\""
150
 doi:10.6073/AA/knb-lter-gce.71.12 | autogen.2012062607482390661 |   1
151
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607482390661'\"" 0 on UCSB, 1 on UNM, 1 on ORC
152

    
153
TRYING:
154
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.80.6'\""
155
 doi:10.6073/AA/knb-lter-gce.80.6 | autogen.2012062607511917641 |   1
156
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607511917641'\"" 0 on UCSB, 1 on UNM, 1 on ORC
157

    
158
TRYING:
159
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.87.4'\""
160
 doi:10.6073/AA/knb-lter-gce.87.4 | autogen.2012062607512667245 |   1
161
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607512667245'\"" 0 on UCSB, 1 on UNM, 1 on ORC
162

    
163
TRYING:
164
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.87.5'\""
165
 doi:10.6073/AA/knb-lter-gce.87.5 | autogen.2012062607511486800 |   1
166
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607511486800'\"" 0 on UCSB, 1 on UNM, 1 on ORC
167

    
168
TRYING:
169
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.97.4'\""
170
 doi:10.6073/AA/knb-lter-gce.97.4 | autogen.2012062607550210306 |   1
171
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062607550210306'\"" 0 on UCSB, 1 on UNM, 1 on ORC
172

    
173
TRYING:
174
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-gce.8.3'\""
175
 doi:10.6073/AA/knb-lter-gce.8.3 | autogen.2012062610185537952 |   1
176
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062610185537952'\"" 0 on UCSB, 1 on UNM, 1 on ORC
177

    
178
TRYING:
179
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-kbs.35.6'\""
180
 doi:10.6073/AA/knb-lter-kbs.35.6 | autogen.2012062921413143003 |   1
181
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062921413143003'\"" 0 on UCSB, 1 on UNM, 1 on ORC
182

    
183
TRYING:
184
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-kbs.38.2'\""
185
 doi:10.6073/AA/knb-lter-kbs.38.2 | autogen.2012062921414116209 |   1
186
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062921414116209'\"" 0 on UCSB, 1 on UNM, 1 on ORC
187

    
188
TRYING:
189
su postgres -c "psql -d metacat  -c \"select * from identifier where guid = 'doi:10.6073/AA/knb-lter-kbs.39.2'\""
190
 doi:10.6073/AA/knb-lter-kbs.39.2 | autogen.2012062921414281310 |   1
191
su postgres -c "psql -d metacat  -c \"select * from xml_revisions where docid='autogen.2012062921414281310'\"" 0 on UCSB, 1 on UNM, 1 on ORC
192

    
193

    
Add picture from clipboard (Maximum size: 14.8 MB)