Harvest for Negrin et al 2019 Created 11 Jun 13:50

Harvesting Log

# Logfile created on 2020-06-11 13:17:48 -0400 by logger.rb/v1.4.2
[INFO] [2020-06-11 13:17:49] ## HARVEST: type = -harvest
[START] [2020-06-11 13:17:50] logged process
[INFO] [2020-06-11 13:18:00] ## HARVEST: type = -harvest
[START] [2020-06-11 13:18:00] logged process
[START] [2020-06-11 13:18:00] create_harvest_instance
[STOP] [2020-06-11 13:18:00] create_harvest_instance
[ERR] [2020-06-11 13:18:00] NoMethodError
[ERR] [2020-06-11 13:18:00] undefined method `fields' for nil:NilClass
[ERR] [2020-06-11 13:18:00] ../models/resource.rb:277:in `create_harvest_instance'
[ERR] [2020-06-11 13:18:00] ../models/resource_harvester.rb:108:in `create_harvest_instance'
[ERR] [2020-06-11 13:18:00] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-11 13:18:00] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-11 13:18:00] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-11 13:18:00] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-11 13:18:00] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-11 13:18:00] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-11 13:18:00] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-11 13:18:00] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-11 13:18:00] bin/rails:4:in `require'
[ERR] [2020-06-11 13:18:00] bin/rails:4:in `<main>'
[STOP] [2020-06-11 13:18:00] logged process, took 0.04
[INFO] [2020-06-11 13:40:25] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-11 13:40:25] ## remove_type: ScientificName
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.484] Removed 0 Scientificnames
[INFO] [2020-06-11 13:40:25] ## remove_type: Vernacular
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.487] Removed 0 Vernaculars
[INFO] [2020-06-11 13:40:25] ## remove_type: Article
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.489] Removed 0 Articles
[INFO] [2020-06-11 13:40:25] ## remove_type: Medium
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.493] Removed 0 Media
[INFO] [2020-06-11 13:40:25] ## remove_type: Trait
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.496] Removed 0 Traits
[INFO] [2020-06-11 13:40:25] ## remove_type: MetaTrait
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.498] Removed 0 Metatraits
[INFO] [2020-06-11 13:40:25] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.501] Removed 0 Occurrencemetadata
[INFO] [2020-06-11 13:40:25] ## remove_type: Assoc
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.504] Removed 0 Assocs
[INFO] [2020-06-11 13:40:25] ## remove_type: MetaAssoc
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.506] Removed 0 Metaassocs
[INFO] [2020-06-11 13:40:25] ## remove_type: Identifier
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.509] Removed 0 Identifiers
[INFO] [2020-06-11 13:40:25] ## remove_type: Reference
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.511] Removed 0 References
[INFO] [2020-06-11 13:40:25] ## remove_type: Node
[INFO] [2020-06-11 13:40:25] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:25] [13:40:25.533] Removed 0 Nodes
[START] [2020-06-11 13:40:25] logged process
[START] [2020-06-11 13:40:25] Creating resource from OpenData
[START] [2020-06-11 13:40:25] logged process
[START] [2020-06-11 13:40:25] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:40:25] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:40:25] Creating resource from OpenData
[START] [2020-06-11 13:40:25] logged process
[START] [2020-06-11 13:40:25] create_harvest_instance
[STOP] [2020-06-11 13:40:26] create_harvest_instance
[START] [2020-06-11 13:40:26] fetch_files
[STOP] [2020-06-11 13:40:26] fetch_files
[START] [2020-06-11 13:40:26] validate_each_file
[STOP] [2020-06-11 13:40:26] validate_each_file
[ERR] [2020-06-11 13:40:26] Exceptions::ColumnUnmatched
[ERR] [2020-06-11 13:40:26] TOO MANY COLUMNS: measurements: referenceID
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:138:in `block in validate_each_file'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:666:in `block in each_format'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:651:in `each_format'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-11 13:40:26] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-11 13:40:26] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-11 13:40:26] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-11 13:40:26] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-11 13:40:26] ../models/resource.rb:208:in `re_download_opendata_and_harvest'
[ERR] [2020-06-11 13:40:26] bin/rails:4:in `require'
[ERR] [2020-06-11 13:40:26] bin/rails:4:in `<main>'
[STOP] [2020-06-11 13:40:27] logged process, took 1.12
[INFO] [2020-06-11 13:40:50] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-11 13:40:53] ## remove_type: ScientificName
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.638] Removed 0 Scientificnames
[INFO] [2020-06-11 13:40:53] ## remove_type: Vernacular
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.641] Removed 0 Vernaculars
[INFO] [2020-06-11 13:40:53] ## remove_type: Article
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.644] Removed 0 Articles
[INFO] [2020-06-11 13:40:53] ## remove_type: Medium
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.648] Removed 0 Media
[INFO] [2020-06-11 13:40:53] ## remove_type: Trait
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.651] Removed 0 Traits
[INFO] [2020-06-11 13:40:53] ## remove_type: MetaTrait
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.653] Removed 0 Metatraits
[INFO] [2020-06-11 13:40:53] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.656] Removed 0 Occurrencemetadata
[INFO] [2020-06-11 13:40:53] ## remove_type: Assoc
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.659] Removed 0 Assocs
[INFO] [2020-06-11 13:40:53] ## remove_type: MetaAssoc
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.662] Removed 0 Metaassocs
[INFO] [2020-06-11 13:40:53] ## remove_type: Identifier
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.665] Removed 0 Identifiers
[INFO] [2020-06-11 13:40:53] ## remove_type: Reference
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.667] Removed 0 References
[INFO] [2020-06-11 13:40:53] ## remove_type: Node
[INFO] [2020-06-11 13:40:53] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:40:53] [13:40:53.698] Removed 0 Nodes
[START] [2020-06-11 13:40:54] logged process
[START] [2020-06-11 13:40:54] Creating resource from OpenData
[START] [2020-06-11 13:40:54] logged process
[START] [2020-06-11 13:40:54] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:40:54] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:40:54] Creating resource from OpenData
[START] [2020-06-11 13:40:54] logged process
[START] [2020-06-11 13:40:54] create_harvest_instance
[STOP] [2020-06-11 13:40:55] create_harvest_instance
[START] [2020-06-11 13:40:55] fetch_files
[STOP] [2020-06-11 13:40:55] fetch_files
[START] [2020-06-11 13:40:55] validate_each_file
[STOP] [2020-06-11 13:40:55] validate_each_file
[ERR] [2020-06-11 13:40:55] Exceptions::ColumnUnmatched
[ERR] [2020-06-11 13:40:55] TOO MANY COLUMNS: measurements: referenceID
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:138:in `block in validate_each_file'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:666:in `block in each_format'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:651:in `each_format'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-11 13:40:55] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-11 13:40:55] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-11 13:40:55] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-11 13:40:55] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-11 13:40:55] ../models/resource.rb:208:in `re_download_opendata_and_harvest'
[ERR] [2020-06-11 13:40:55] bin/rails:4:in `require'
[ERR] [2020-06-11 13:40:55] bin/rails:4:in `<main>'
[STOP] [2020-06-11 13:40:55] logged process, took 1.12
[INFO] [2020-06-11 13:43:57] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-11 13:44:02] ## remove_type: ScientificName
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.317] Removed 0 Scientificnames
[INFO] [2020-06-11 13:44:02] ## remove_type: Vernacular
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.320] Removed 0 Vernaculars
[INFO] [2020-06-11 13:44:02] ## remove_type: Article
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.323] Removed 0 Articles
[INFO] [2020-06-11 13:44:02] ## remove_type: Medium
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.327] Removed 0 Media
[INFO] [2020-06-11 13:44:02] ## remove_type: Trait
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.330] Removed 0 Traits
[INFO] [2020-06-11 13:44:02] ## remove_type: MetaTrait
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.333] Removed 0 Metatraits
[INFO] [2020-06-11 13:44:02] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.336] Removed 0 Occurrencemetadata
[INFO] [2020-06-11 13:44:02] ## remove_type: Assoc
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.339] Removed 0 Assocs
[INFO] [2020-06-11 13:44:02] ## remove_type: MetaAssoc
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.342] Removed 0 Metaassocs
[INFO] [2020-06-11 13:44:02] ## remove_type: Identifier
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.344] Removed 0 Identifiers
[INFO] [2020-06-11 13:44:02] ## remove_type: Reference
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.347] Removed 0 References
[INFO] [2020-06-11 13:44:02] ## remove_type: Node
[INFO] [2020-06-11 13:44:02] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:02] [13:44:02.366] Removed 0 Nodes
[START] [2020-06-11 13:44:02] logged process
[START] [2020-06-11 13:44:02] Creating resource from OpenData
[START] [2020-06-11 13:44:02] logged process
[START] [2020-06-11 13:44:02] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:44:02] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:44:02] Creating resource from OpenData
[START] [2020-06-11 13:44:02] logged process
[START] [2020-06-11 13:44:02] create_harvest_instance
[STOP] [2020-06-11 13:44:03] create_harvest_instance
[START] [2020-06-11 13:44:03] fetch_files
[STOP] [2020-06-11 13:44:03] fetch_files
[START] [2020-06-11 13:44:03] validate_each_file
[STOP] [2020-06-11 13:44:03] validate_each_file
[ERR] [2020-06-11 13:44:03] Exceptions::ColumnUnmatched
[ERR] [2020-06-11 13:44:03] TOO MANY COLUMNS: measurements: bibliographicCitation
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:138:in `block in validate_each_file'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:666:in `block in each_format'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:651:in `each_format'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-11 13:44:03] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-11 13:44:03] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-11 13:44:03] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-11 13:44:03] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-11 13:44:03] ../models/resource.rb:208:in `re_download_opendata_and_harvest'
[ERR] [2020-06-11 13:44:03] bin/rails:4:in `require'
[ERR] [2020-06-11 13:44:03] bin/rails:4:in `<main>'
[STOP] [2020-06-11 13:44:03] logged process, took 1.04
[INFO] [2020-06-11 13:44:17] ## HARVEST: type = resume_-harvest
[START] [2020-06-11 13:44:20] logged process
[ERR] [2020-06-11 13:44:20][hdls] *****
[ERR] [2020-06-11 13:44:20][hdls] ***** HARVEST ATTEMPT FAILED: This resource is locked; assuming it is already running. Remove lock if not.
[ERR] [2020-06-11 13:44:20][hdls] *****
[INFO] [2020-06-11 13:44:50] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-11 13:44:50] ## remove_type: ScientificName
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.827] Removed 0 Scientificnames
[INFO] [2020-06-11 13:44:50] ## remove_type: Vernacular
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.830] Removed 0 Vernaculars
[INFO] [2020-06-11 13:44:50] ## remove_type: Article
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.833] Removed 0 Articles
[INFO] [2020-06-11 13:44:50] ## remove_type: Medium
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.837] Removed 0 Media
[INFO] [2020-06-11 13:44:50] ## remove_type: Trait
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.840] Removed 0 Traits
[INFO] [2020-06-11 13:44:50] ## remove_type: MetaTrait
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.843] Removed 0 Metatraits
[INFO] [2020-06-11 13:44:50] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.846] Removed 0 Occurrencemetadata
[INFO] [2020-06-11 13:44:50] ## remove_type: Assoc
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.850] Removed 0 Assocs
[INFO] [2020-06-11 13:44:50] ## remove_type: MetaAssoc
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.853] Removed 0 Metaassocs
[INFO] [2020-06-11 13:44:50] ## remove_type: Identifier
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.855] Removed 0 Identifiers
[INFO] [2020-06-11 13:44:50] ## remove_type: Reference
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.858] Removed 0 References
[INFO] [2020-06-11 13:44:50] ## remove_type: Node
[INFO] [2020-06-11 13:44:50] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:44:50] [13:44:50.877] Removed 0 Nodes
[START] [2020-06-11 13:44:51] logged process
[START] [2020-06-11 13:44:51] Creating resource from OpenData
[START] [2020-06-11 13:44:51] logged process
[START] [2020-06-11 13:44:51] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:44:51] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:44:51] Creating resource from OpenData
[START] [2020-06-11 13:44:51] logged process
[START] [2020-06-11 13:44:51] create_harvest_instance
[STOP] [2020-06-11 13:44:52] create_harvest_instance
[START] [2020-06-11 13:44:52] fetch_files
[STOP] [2020-06-11 13:44:52] fetch_files
[START] [2020-06-11 13:44:52] validate_each_file
[STOP] [2020-06-11 13:44:52] validate_each_file
[ERR] [2020-06-11 13:44:52] Exceptions::ColumnUnmatched
[ERR] [2020-06-11 13:44:52] TOO MANY COLUMNS: measurements: bibliographicCitation
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:138:in `block in validate_each_file'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:666:in `block in each_format'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:651:in `each_format'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-11 13:44:52] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-11 13:44:52] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-11 13:44:52] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-11 13:44:52] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-11 13:44:52] ../models/resource.rb:208:in `re_download_opendata_and_harvest'
[ERR] [2020-06-11 13:44:52] bin/rails:4:in `require'
[ERR] [2020-06-11 13:44:52] bin/rails:4:in `<main>'
[STOP] [2020-06-11 13:44:52] logged process, took 1.05
[START] [2020-06-11 13:48:24] logged process
[START] [2020-06-11 13:48:24] overall_tsv_creation
[INFO] [2020-06-11 13:48:24] Processing group of 0 in 0 batches of 10000
[INFO] [2020-06-11 13:48:24] Average Time: NaN
[INFO] [2020-06-11 13:48:24] Total Time: 1s
[STOP] [2020-06-11 13:48:24] overall_tsv_creation
[INFO] [2020-06-11 13:48:24] Done. Check your files:
[INFO] [2020-06-11 13:48:38] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-11 13:48:39] ## remove_type: ScientificName
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.486] Removed 0 Scientificnames
[INFO] [2020-06-11 13:48:39] ## remove_type: Vernacular
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.490] Removed 0 Vernaculars
[INFO] [2020-06-11 13:48:39] ## remove_type: Article
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.493] Removed 0 Articles
[INFO] [2020-06-11 13:48:39] ## remove_type: Medium
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.496] Removed 0 Media
[INFO] [2020-06-11 13:48:39] ## remove_type: Trait
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.499] Removed 0 Traits
[INFO] [2020-06-11 13:48:39] ## remove_type: MetaTrait
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.502] Removed 0 Metatraits
[INFO] [2020-06-11 13:48:39] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.505] Removed 0 Occurrencemetadata
[INFO] [2020-06-11 13:48:39] ## remove_type: Assoc
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.508] Removed 0 Assocs
[INFO] [2020-06-11 13:48:39] ## remove_type: MetaAssoc
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.511] Removed 0 Metaassocs
[INFO] [2020-06-11 13:48:39] ## remove_type: Identifier
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.513] Removed 0 Identifiers
[INFO] [2020-06-11 13:48:39] ## remove_type: Reference
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.516] Removed 0 References
[INFO] [2020-06-11 13:48:39] ## remove_type: Node
[INFO] [2020-06-11 13:48:39] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:48:39] [13:48:39.533] Removed 0 Nodes
[START] [2020-06-11 13:48:39] logged process
[START] [2020-06-11 13:48:39] Creating resource from OpenData
[START] [2020-06-11 13:48:39] logged process
[START] [2020-06-11 13:48:39] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:48:40] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:48:40] Creating resource from OpenData
[START] [2020-06-11 13:48:40] logged process
[START] [2020-06-11 13:48:40] create_harvest_instance
[STOP] [2020-06-11 13:48:41] create_harvest_instance
[START] [2020-06-11 13:48:41] fetch_files
[STOP] [2020-06-11 13:48:41] fetch_files
[START] [2020-06-11 13:48:41] validate_each_file
[STOP] [2020-06-11 13:48:41] validate_each_file
[ERR] [2020-06-11 13:48:41] Exceptions::ColumnUnmatched
[ERR] [2020-06-11 13:48:41] TOO MANY COLUMNS: measurements: bibliographicCitation
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:138:in `block in validate_each_file'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:666:in `block in each_format'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:651:in `each_format'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-11 13:48:41] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-11 13:48:41] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-11 13:48:41] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-11 13:48:41] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-11 13:48:41] ../models/resource.rb:208:in `re_download_opendata_and_harvest'
[ERR] [2020-06-11 13:48:41] bin/rails:4:in `require'
[ERR] [2020-06-11 13:48:41] bin/rails:4:in `<main>'
[STOP] [2020-06-11 13:48:41] logged process, took 1.08
[INFO] [2020-06-11 13:50:45] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-11 13:50:47] ## remove_type: ScientificName
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.932] Removed 0 Scientificnames
[INFO] [2020-06-11 13:50:47] ## remove_type: Vernacular
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.935] Removed 0 Vernaculars
[INFO] [2020-06-11 13:50:47] ## remove_type: Article
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.937] Removed 0 Articles
[INFO] [2020-06-11 13:50:47] ## remove_type: Medium
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.940] Removed 0 Media
[INFO] [2020-06-11 13:50:47] ## remove_type: Trait
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.943] Removed 0 Traits
[INFO] [2020-06-11 13:50:47] ## remove_type: MetaTrait
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.946] Removed 0 Metatraits
[INFO] [2020-06-11 13:50:47] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.948] Removed 0 Occurrencemetadata
[INFO] [2020-06-11 13:50:47] ## remove_type: Assoc
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.951] Removed 0 Assocs
[INFO] [2020-06-11 13:50:47] ## remove_type: MetaAssoc
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.953] Removed 0 Metaassocs
[INFO] [2020-06-11 13:50:47] ## remove_type: Identifier
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.955] Removed 0 Identifiers
[INFO] [2020-06-11 13:50:47] ## remove_type: Reference
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.957] Removed 0 References
[INFO] [2020-06-11 13:50:47] ## remove_type: Node
[INFO] [2020-06-11 13:50:47] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-11 13:50:47] [13:50:47.976] Removed 0 Nodes
[START] [2020-06-11 13:50:48] logged process
[START] [2020-06-11 13:50:48] Creating resource from OpenData
[START] [2020-06-11 13:50:48] logged process
[START] [2020-06-11 13:50:48] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:50:48] Parse meta.xml file and create formats with fields
[STOP] [2020-06-11 13:50:48] Creating resource from OpenData
[START] [2020-06-11 13:50:48] logged process
[START] [2020-06-11 13:50:48] create_harvest_instance
[STOP] [2020-06-11 13:50:49] create_harvest_instance
[START] [2020-06-11 13:50:49] fetch_files
[STOP] [2020-06-11 13:50:49] fetch_files
[START] [2020-06-11 13:50:49] validate_each_file
[STOP] [2020-06-11 13:50:49] validate_each_file
[START] [2020-06-11 13:50:49] convert_to_csv
[CMD] [2020-06-11 13:50:49] /usr/bin/sort /app/public/converted_csv/negrin_et_al_neg_nodes_21180.csv > /app/public/converted_csv/negrin_et_al_neg_nodes_21180.csv_sorted
[CMD] [2020-06-11 13:50:49] /usr/bin/sort /app/public/converted_csv/negrin_et_al_neg_occurrences_21181.csv > /app/public/converted_csv/negrin_et_al_neg_occurrences_21181.csv_sorted
[CMD] [2020-06-11 13:50:49] /usr/bin/sort /app/public/converted_csv/negrin_et_al_neg_measurements_21182.csv > /app/public/converted_csv/negrin_et_al_neg_measurements_21182.csv_sorted
[STOP] [2020-06-11 13:50:49] convert_to_csv
[START] [2020-06-11 13:50:49] calculate_delta
[CMD] [2020-06-11 13:50:49] echo "0a" > /app/public/diff/negrin_et_al_neg_nodes_21180.diff
[CMD] [2020-06-11 13:50:49] tail -n +1 /app/public/converted_csv/negrin_et_al_neg_nodes_21180.csv >> /app/public/diff/negrin_et_al_neg_nodes_21180.diff
[CMD] [2020-06-11 13:50:49] echo "." >> /app/public/diff/negrin_et_al_neg_nodes_21180.diff
[CMD] [2020-06-11 13:50:49] echo "0a" > /app/public/diff/negrin_et_al_neg_occurrences_21181.diff
[CMD] [2020-06-11 13:50:49] tail -n +1 /app/public/converted_csv/negrin_et_al_neg_occurrences_21181.csv >> /app/public/diff/negrin_et_al_neg_occurrences_21181.diff
[CMD] [2020-06-11 13:50:49] echo "." >> /app/public/diff/negrin_et_al_neg_occurrences_21181.diff
[CMD] [2020-06-11 13:50:49] echo "0a" > /app/public/diff/negrin_et_al_neg_measurements_21182.diff
[CMD] [2020-06-11 13:50:49] tail -n +1 /app/public/converted_csv/negrin_et_al_neg_measurements_21182.csv >> /app/public/diff/negrin_et_al_neg_measurements_21182.diff
[CMD] [2020-06-11 13:50:49] echo "." >> /app/public/diff/negrin_et_al_neg_measurements_21182.diff
[STOP] [2020-06-11 13:50:49] calculate_delta
[START] [2020-06-11 13:50:49] parse_diff_and_store
[INFO] [2020-06-11 13:50:49] Loading nodes diff file into memory (true lines)...
[INFO] [2020-06-11 13:50:50] Loading occurrences diff file into memory (true lines)...
[INFO] [2020-06-11 13:50:50] Loading measurements diff file into memory (true lines)...
[INFO] [2020-06-11 13:50:50] Storing 7 ScientificNames
[INFO] [2020-06-11 13:50:50] Processing group of 7 in 1 groups of 1000
[INFO] [2020-06-11 13:50:50] Average Time: 0.0
[INFO] [2020-06-11 13:50:50] Total Time: 1s
[INFO] [2020-06-11 13:50:50] Storing 7 Nodes
[INFO] [2020-06-11 13:50:50] Processing group of 7 in 1 groups of 1000
[INFO] [2020-06-11 13:50:50] Average Time: 0.0
[INFO] [2020-06-11 13:50:50] Total Time: 1s
[INFO] [2020-06-11 13:50:50] Storing 4 Occurrences
[INFO] [2020-06-11 13:50:50] Processing group of 4 in 1 groups of 1000
[INFO] [2020-06-11 13:50:50] Average Time: 0.0
[INFO] [2020-06-11 13:50:50] Total Time: 1s
[INFO] [2020-06-11 13:50:50] Storing 8 Traits
[INFO] [2020-06-11 13:50:50] Processing group of 8 in 1 groups of 1000
[INFO] [2020-06-11 13:50:50] Average Time: 0.0
[INFO] [2020-06-11 13:50:50] Total Time: 1s
[INFO] [2020-06-11 13:50:50] Storing 8 MetaTraits
[INFO] [2020-06-11 13:50:50] Processing group of 8 in 1 groups of 1000
[INFO] [2020-06-11 13:50:50] Average Time: 0.01
[INFO] [2020-06-11 13:50:50] Total Time: 1s
[STOP] [2020-06-11 13:50:50] parse_diff_and_store
[START] [2020-06-11 13:50:50] resolve_keys
[INFO] [2020-06-11 13:50:57] Occurrences to nodes (through scientific_names)...
[INFO] [2020-06-11 13:50:57] traits to occurrences...
[INFO] [2020-06-11 13:50:57] traits to nodes (through occurrences)...
[INFO] [2020-06-11 13:50:57] Traits to sex term...
[INFO] [2020-06-11 13:50:57] Traits to lifestage term...
[INFO] [2020-06-11 13:50:57] MetaTraits to traits...
[INFO] [2020-06-11 13:50:57] MetaTraits (simple, measurement row refers to parent) to traits...
[INFO] [2020-06-11 13:50:57] Assocs to occurrences...
[INFO] [2020-06-11 13:50:57] Assocs to nodes...
[INFO] [2020-06-11 13:50:57] Assoc to sex term...
[INFO] [2020-06-11 13:50:57] Assoc to lifestage term...
[STOP] [2020-06-11 13:50:57] resolve_keys
[START] [2020-06-11 13:50:57] hold_for_later_1
[STOP] [2020-06-11 13:50:57] hold_for_later_1
[START] [2020-06-11 13:50:57] hold_for_later_2
[STOP] [2020-06-11 13:50:57] hold_for_later_2
[START] [2020-06-11 13:50:57] resolve_missing_parents
[STOP] [2020-06-11 13:50:57] resolve_missing_parents
[START] [2020-06-11 13:50:57] rebuild_nodes
[START] [2020-06-11 13:50:57] Flattener#flatten
[START] [2020-06-11 13:50:57] Flattener#study_resource
[START] [2020-06-11 13:50:57] Flattener#build_ancestry
[STOP] [2020-06-11 13:50:57] Flattener#build_ancestry
[INFO] [2020-06-11 13:50:57] 7 ancestry keys
[START] [2020-06-11 13:50:57] build_node_ancestors
[INFO] [2020-06-11 13:50:57] old ancestors deleted.
[STOP] [2020-06-11 13:50:57] build_node_ancestors
[START] [2020-06-11 13:50:57] Flattener#propagate_ancestor_ids
[STOP] [2020-06-11 13:50:57] Flattener#propagate_ancestor_ids
[STOP] [2020-06-11 13:50:57] Flattener#flatten
[STOP] [2020-06-11 13:50:57] rebuild_nodes
[START] [2020-06-11 13:50:57] resolve_missing_media_owners
[STOP] [2020-06-11 13:50:57] resolve_missing_media_owners
[START] [2020-06-11 13:50:57] sanitize_media_verbatims
[STOP] [2020-06-11 13:50:57] sanitize_media_verbatims
[START] [2020-06-11 13:50:57] queue_downloads
[STOP] [2020-06-11 13:50:57] queue_downloads
[START] [2020-06-11 13:50:57] parse_names
[WARN] [2020-06-11 13:50:57] I see 7 names which still need to be parsed.
[STOP] [2020-06-11 13:50:58] parse_names
[START] [2020-06-11 13:50:58] denormalize_canonical_names_to_nodes
[STOP] [2020-06-11 13:50:58] denormalize_canonical_names_to_nodes
[START] [2020-06-11 13:50:58] match_nodes
[START] [2020-06-11 13:50:58] map_all_nodes_to_pages
[STOP] [2020-06-11 13:50:58] map_all_nodes_to_pages
[INFO] [2020-06-11 13:50:58] ZERO unmatched nodes (of 7)! Nicely done.
[START] [2020-06-11 13:50:58] update_nodes
[STOP] [2020-06-11 13:50:58] update_nodes
[STOP] [2020-06-11 13:50:58] match_nodes
[START] [2020-06-11 13:50:58] reindex_search
[STOP] [2020-06-11 13:50:58] reindex_search
[START] [2020-06-11 13:50:58] normalize_units
[STOP] [2020-06-11 13:50:59] normalize_units
[START] [2020-06-11 13:50:59] calculate_statistics
[STOP] [2020-06-11 13:50:59] calculate_statistics
[START] [2020-06-11 13:50:59] complete_harvest_instance
[START] [2020-06-11 13:50:59] overall_tsv_creation
[INFO] [2020-06-11 13:50:59] Processing group of 7 in 1 batches of 10000
[INFO] [2020-06-11 13:51:49] 4 Traits (unfiltered)...
[INFO] [2020-06-11 13:52:02] 4 Traits (filtered)...
[INFO] [2020-06-11 13:52:02] 0 Associations (filtered)...
[INFO] [2020-06-11 13:52:39] 12 metadata added.
[INFO] [2020-06-11 13:52:39] 0 metadata added.
[INFO] [2020-06-11 13:52:39] Average Time: 72.18
[INFO] [2020-06-11 13:52:39] Total Time: 1m41s
[STOP] [2020-06-11 13:52:39] overall_tsv_creation
[INFO] [2020-06-11 13:52:39] Done. Check your files:
[INFO] [2020-06-11 13:52:39] (7 lines) /app/public/data/negrin_et_al_neg/publish_nodes.tsv
[INFO] [2020-06-11 13:52:39] (15 lines) /app/public/data/negrin_et_al_neg/publish_node_ancestors.tsv
[INFO] [2020-06-11 13:52:39] (7 lines) /app/public/data/negrin_et_al_neg/publish_scientific_names.tsv
[INFO] [2020-06-11 13:52:39] (5 lines) /app/public/data/negrin_et_al_neg/publish_traits.tsv
[INFO] [2020-06-11 13:52:39] (13 lines) /app/public/data/negrin_et_al_neg/publish_metadata.tsv
[STOP] [2020-06-11 13:52:39] complete_harvest_instance
[START] [2020-06-11 13:52:39] completed
[STOP] [2020-06-11 13:52:39] completed
[STOP] [2020-06-11 13:52:39] logged process, took 110.6

Latest Process

11 Jun 13:50 EXITED currently processing 0