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
|
|