Harvest for Lovegrove and Haines 2004 Created 22 Jul 13:04

Harvesting Log

# Logfile created on 2020-07-22 12:59:53 -0400 by logger.rb/v1.4.2
[START] [2020-07-22 12:59:53] logged process
[START] [2020-07-22 12:59:53] Creating resource from OpenData
[START] [2020-07-22 12:59:54] logged process
[START] [2020-07-22 12:59:54] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 12:59:54] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 12:59:54] Creating resource from OpenData
[INFO] [2020-07-22 13:00:10] ## HARVEST: type = -harvest
[START] [2020-07-22 13:00:13] logged process
[START] [2020-07-22 13:00:13] create_harvest_instance
[STOP] [2020-07-22 13:00:14] create_harvest_instance
[START] [2020-07-22 13:00:14] fetch_files
[STOP] [2020-07-22 13:00:14] fetch_files
[START] [2020-07-22 13:00:14] validate_each_file
[STOP] [2020-07-22 13:00:14] validate_each_file
[ERR] [2020-07-22 13:00:14] Exceptions::ColumnMissing
[ERR] [2020-07-22 13:00:14] MISSING COLUMN: occurrences: 
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:157:in `block in check_each_column'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:156:in `each_with_index'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:156:in `check_each_column'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:135:in `block in validate_each_file'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:665:in `block in each_format'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:650:in `each_format'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-07-22 13:00:14] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-07-22 13:00:14] ../models/resource.rb:151:in `lock'
[ERR] [2020-07-22 13:00:14] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-07-22 13:00:14] ../models/resource.rb:232:in `harvest'
[ERR] [2020-07-22 13:00:14] bin/rails:4:in `require'
[ERR] [2020-07-22 13:00:14] bin/rails:4:in `<main>'
[STOP] [2020-07-22 13:00:14] logged process, took 1.22
[START] [2020-07-22 13:01:31] logged process
[START] [2020-07-22 13:01:31] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 13:01:31] Parse meta.xml file and create formats with fields
[INFO] [2020-07-22 13:02:32] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-07-22 13:02:36] ## remove_type: ScientificName
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.545] Removed 0 Scientificnames
[INFO] [2020-07-22 13:02:36] ## remove_type: Vernacular
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.548] Removed 0 Vernaculars
[INFO] [2020-07-22 13:02:36] ## remove_type: Article
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.551] Removed 0 Articles
[INFO] [2020-07-22 13:02:36] ## remove_type: Medium
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.555] Removed 0 Media
[INFO] [2020-07-22 13:02:36] ## remove_type: Trait
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.558] Removed 0 Traits
[INFO] [2020-07-22 13:02:36] ## remove_type: MetaTrait
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.564] Removed 0 Metatraits
[INFO] [2020-07-22 13:02:36] ## remove_type: OccurrenceMetadatum
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.567] Removed 0 Occurrencemetadata
[INFO] [2020-07-22 13:02:36] ## remove_type: Assoc
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.570] Removed 0 Assocs
[INFO] [2020-07-22 13:02:36] ## remove_type: MetaAssoc
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.583] Removed 0 Metaassocs
[INFO] [2020-07-22 13:02:36] ## remove_type: Identifier
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.604] Removed 0 Identifiers
[INFO] [2020-07-22 13:02:36] ## remove_type: Reference
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.607] Removed 0 References
[INFO] [2020-07-22 13:02:36] ## remove_type: Node
[INFO] [2020-07-22 13:02:36] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:02:36] [13:02:36.641] Removed 0 Nodes
[START] [2020-07-22 13:02:37] logged process
[START] [2020-07-22 13:02:37] Creating resource from OpenData
[START] [2020-07-22 13:02:37] logged process
[START] [2020-07-22 13:02:37] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 13:02:37] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 13:02:37] Creating resource from OpenData
[START] [2020-07-22 13:02:37] logged process
[START] [2020-07-22 13:02:37] create_harvest_instance
[STOP] [2020-07-22 13:02:38] create_harvest_instance
[START] [2020-07-22 13:02:38] fetch_files
[STOP] [2020-07-22 13:02:38] fetch_files
[START] [2020-07-22 13:02:38] validate_each_file
[STOP] [2020-07-22 13:02:38] validate_each_file
[ERR] [2020-07-22 13:02:38] Exceptions::ColumnMissing
[ERR] [2020-07-22 13:02:38] MISSING COLUMN: measurements: 
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:157:in `block in check_each_column'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:156:in `each_with_index'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:156:in `check_each_column'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:135:in `block in validate_each_file'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:665:in `block in each_format'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:650:in `each_format'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:132:in `validate_each_file'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-07-22 13:02:38] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-07-22 13:02:38] ../models/resource.rb:151:in `lock'
[ERR] [2020-07-22 13:02:38] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-07-22 13:02:38] ../models/resource.rb:232:in `harvest'
[ERR] [2020-07-22 13:02:38] ../models/resource.rb:208:in `re_download_opendata_and_harvest'
[ERR] [2020-07-22 13:02:38] bin/rails:4:in `require'
[ERR] [2020-07-22 13:02:38] bin/rails:4:in `<main>'
[STOP] [2020-07-22 13:02:38] logged process, took 1.16
[INFO] [2020-07-22 13:04:54] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-07-22 13:04:55] ## remove_type: ScientificName
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.324] Removed 0 Scientificnames
[INFO] [2020-07-22 13:04:55] ## remove_type: Vernacular
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.327] Removed 0 Vernaculars
[INFO] [2020-07-22 13:04:55] ## remove_type: Article
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.330] Removed 0 Articles
[INFO] [2020-07-22 13:04:55] ## remove_type: Medium
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.334] Removed 0 Media
[INFO] [2020-07-22 13:04:55] ## remove_type: Trait
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.338] Removed 0 Traits
[INFO] [2020-07-22 13:04:55] ## remove_type: MetaTrait
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.340] Removed 0 Metatraits
[INFO] [2020-07-22 13:04:55] ## remove_type: OccurrenceMetadatum
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.343] Removed 0 Occurrencemetadata
[INFO] [2020-07-22 13:04:55] ## remove_type: Assoc
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.346] Removed 0 Assocs
[INFO] [2020-07-22 13:04:55] ## remove_type: MetaAssoc
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.349] Removed 0 Metaassocs
[INFO] [2020-07-22 13:04:55] ## remove_type: Identifier
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.352] Removed 0 Identifiers
[INFO] [2020-07-22 13:04:55] ## remove_type: Reference
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.355] Removed 0 References
[INFO] [2020-07-22 13:04:55] ## remove_type: Node
[INFO] [2020-07-22 13:04:55] ++ Calling delete_all on 0 instances...
[INFO] [2020-07-22 13:04:55] [13:04:55.385] Removed 0 Nodes
[START] [2020-07-22 13:04:55] logged process
[START] [2020-07-22 13:04:55] Creating resource from OpenData
[START] [2020-07-22 13:04:55] logged process
[START] [2020-07-22 13:04:55] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 13:04:55] Parse meta.xml file and create formats with fields
[STOP] [2020-07-22 13:04:55] Creating resource from OpenData
[START] [2020-07-22 13:04:55] logged process
[START] [2020-07-22 13:04:55] create_harvest_instance
[STOP] [2020-07-22 13:04:56] create_harvest_instance
[START] [2020-07-22 13:04:56] fetch_files
[STOP] [2020-07-22 13:04:56] fetch_files
[START] [2020-07-22 13:04:56] validate_each_file
[STOP] [2020-07-22 13:04:57] validate_each_file
[START] [2020-07-22 13:04:57] convert_to_csv
[CMD] [2020-07-22 13:04:57] /usr/bin/sort /app/public/converted_csv/lovegrove_haines_nodes_21977.csv > /app/public/converted_csv/lovegrove_haines_nodes_21977.csv_sorted
[CMD] [2020-07-22 13:04:57] /usr/bin/sort /app/public/converted_csv/lovegrove_haines_occurrences_21978.csv > /app/public/converted_csv/lovegrove_haines_occurrences_21978.csv_sorted
[CMD] [2020-07-22 13:04:57] /usr/bin/sort /app/public/converted_csv/lovegrove_haines_measurements_21979.csv > /app/public/converted_csv/lovegrove_haines_measurements_21979.csv_sorted
[STOP] [2020-07-22 13:04:57] convert_to_csv
[START] [2020-07-22 13:04:57] calculate_delta
[CMD] [2020-07-22 13:04:57] echo "0a" > /app/public/diff/lovegrove_haines_nodes_21977.diff
[CMD] [2020-07-22 13:04:57] tail -n +1 /app/public/converted_csv/lovegrove_haines_nodes_21977.csv >> /app/public/diff/lovegrove_haines_nodes_21977.diff
[CMD] [2020-07-22 13:04:57] echo "." >> /app/public/diff/lovegrove_haines_nodes_21977.diff
[CMD] [2020-07-22 13:04:57] echo "0a" > /app/public/diff/lovegrove_haines_occurrences_21978.diff
[CMD] [2020-07-22 13:04:57] tail -n +1 /app/public/converted_csv/lovegrove_haines_occurrences_21978.csv >> /app/public/diff/lovegrove_haines_occurrences_21978.diff
[CMD] [2020-07-22 13:04:57] echo "." >> /app/public/diff/lovegrove_haines_occurrences_21978.diff
[CMD] [2020-07-22 13:04:57] echo "0a" > /app/public/diff/lovegrove_haines_measurements_21979.diff
[CMD] [2020-07-22 13:04:57] tail -n +1 /app/public/converted_csv/lovegrove_haines_measurements_21979.csv >> /app/public/diff/lovegrove_haines_measurements_21979.diff
[CMD] [2020-07-22 13:04:57] echo "." >> /app/public/diff/lovegrove_haines_measurements_21979.diff
[STOP] [2020-07-22 13:04:57] calculate_delta
[START] [2020-07-22 13:04:57] parse_diff_and_store
[INFO] [2020-07-22 13:04:57] Loading nodes diff file into memory (true lines)...
[INFO] [2020-07-22 13:04:57] Loading occurrences diff file into memory (true lines)...
[INFO] [2020-07-22 13:04:57] Loading measurements diff file into memory (true lines)...
[INFO] [2020-07-22 13:04:57] Storing 2 ScientificNames
[INFO] [2020-07-22 13:04:57] Processing group of 2 in 1 groups of 1000
[INFO] [2020-07-22 13:04:57] Average Time: 0.0
[INFO] [2020-07-22 13:04:57] Total Time: 1s
[INFO] [2020-07-22 13:04:57] Storing 2 Nodes
[INFO] [2020-07-22 13:04:57] Processing group of 2 in 1 groups of 1000
[INFO] [2020-07-22 13:04:57] Average Time: 0.0
[INFO] [2020-07-22 13:04:57] Total Time: 1s
[INFO] [2020-07-22 13:04:57] Storing 2 Occurrences
[INFO] [2020-07-22 13:04:57] Processing group of 2 in 1 groups of 1000
[INFO] [2020-07-22 13:04:57] Average Time: 0.0
[INFO] [2020-07-22 13:04:57] Total Time: 1s
[INFO] [2020-07-22 13:04:57] Storing 4 Traits
[INFO] [2020-07-22 13:04:57] Processing group of 4 in 1 groups of 1000
[INFO] [2020-07-22 13:04:57] Average Time: 0.0
[INFO] [2020-07-22 13:04:57] Total Time: 1s
[INFO] [2020-07-22 13:04:57] Storing 4 MetaTraits
[INFO] [2020-07-22 13:04:57] Processing group of 4 in 1 groups of 1000
[INFO] [2020-07-22 13:04:57] Average Time: 0.0
[INFO] [2020-07-22 13:04:57] Total Time: 1s
[STOP] [2020-07-22 13:04:57] parse_diff_and_store
[START] [2020-07-22 13:04:57] resolve_keys
[INFO] [2020-07-22 13:05:04] Occurrences to nodes (through scientific_names)...
[INFO] [2020-07-22 13:05:04] traits to occurrences...
[INFO] [2020-07-22 13:05:04] traits to nodes (through occurrences)...
[INFO] [2020-07-22 13:05:04] Traits to sex term...
[INFO] [2020-07-22 13:05:04] Traits to lifestage term...
[INFO] [2020-07-22 13:05:04] MetaTraits to traits...
[INFO] [2020-07-22 13:05:04] MetaTraits (simple, measurement row refers to parent) to traits...
[INFO] [2020-07-22 13:05:04] Assocs to occurrences...
[INFO] [2020-07-22 13:05:04] Assocs to nodes...
[INFO] [2020-07-22 13:05:04] Assoc to sex term...
[INFO] [2020-07-22 13:05:04] Assoc to lifestage term...
[STOP] [2020-07-22 13:05:04] resolve_keys
[START] [2020-07-22 13:05:04] hold_for_later_1
[STOP] [2020-07-22 13:05:04] hold_for_later_1
[START] [2020-07-22 13:05:05] hold_for_later_2
[STOP] [2020-07-22 13:05:05] hold_for_later_2
[START] [2020-07-22 13:05:05] resolve_missing_parents
[STOP] [2020-07-22 13:05:05] resolve_missing_parents
[START] [2020-07-22 13:05:05] rebuild_nodes
[START] [2020-07-22 13:05:05] Flattener#flatten
[START] [2020-07-22 13:05:05] Flattener#study_resource
[START] [2020-07-22 13:05:05] Flattener#build_ancestry
[STOP] [2020-07-22 13:05:05] Flattener#build_ancestry
[INFO] [2020-07-22 13:05:05] 2 ancestry keys
[START] [2020-07-22 13:05:05] build_node_ancestors
[INFO] [2020-07-22 13:05:05] old ancestors deleted.
[STOP] [2020-07-22 13:05:05] build_node_ancestors
[WARN] [2020-07-22 13:05:05] Flattener: nothing to flatten! (Completely flat resource?)
[STOP] [2020-07-22 13:05:05] Flattener#flatten
[STOP] [2020-07-22 13:05:05] rebuild_nodes
[START] [2020-07-22 13:05:05] resolve_missing_media_owners
[STOP] [2020-07-22 13:05:05] resolve_missing_media_owners
[START] [2020-07-22 13:05:05] sanitize_media_verbatims
[STOP] [2020-07-22 13:05:05] sanitize_media_verbatims
[START] [2020-07-22 13:05:05] queue_downloads
[STOP] [2020-07-22 13:05:05] queue_downloads
[START] [2020-07-22 13:05:05] parse_names
[WARN] [2020-07-22 13:05:05] I see 2 names which still need to be parsed.
[STOP] [2020-07-22 13:05:06] parse_names
[START] [2020-07-22 13:05:06] denormalize_canonical_names_to_nodes
[STOP] [2020-07-22 13:05:06] denormalize_canonical_names_to_nodes
[START] [2020-07-22 13:05:06] match_nodes
[START] [2020-07-22 13:05:06] map_all_nodes_to_pages
[STOP] [2020-07-22 13:05:06] map_all_nodes_to_pages
[INFO] [2020-07-22 13:05:06] ZERO unmatched nodes (of 2)! Nicely done.
[START] [2020-07-22 13:05:06] update_nodes
[STOP] [2020-07-22 13:05:06] update_nodes
[STOP] [2020-07-22 13:05:06] match_nodes
[START] [2020-07-22 13:05:06] reindex_search
[STOP] [2020-07-22 13:05:06] reindex_search
[START] [2020-07-22 13:05:06] normalize_units
[STOP] [2020-07-22 13:05:06] normalize_units
[START] [2020-07-22 13:05:06] calculate_statistics
[2020-07-22 13:05:06] ZERO NODE ANCESTORS. Is this actually a completely flat resource?
[STOP] [2020-07-22 13:05:06] calculate_statistics
[START] [2020-07-22 13:05:06] complete_harvest_instance
[START] [2020-07-22 13:05:06] overall_tsv_creation
[INFO] [2020-07-22 13:05:06] Processing group of 2 in 1 batches of 10000
[INFO] [2020-07-22 13:06:53] 2 Traits (unfiltered)...
[INFO] [2020-07-22 13:07:29] 2 Traits (filtered)...
[INFO] [2020-07-22 13:07:29] 0 Associations (filtered)...
[INFO] [2020-07-22 13:07:29] 6 metadata added.
[INFO] [2020-07-22 13:07:29] 0 metadata added.
[INFO] [2020-07-22 13:07:29] Average Time: 57.71
[INFO] [2020-07-22 13:07:29] Total Time: 2m24s
[STOP] [2020-07-22 13:07:29] overall_tsv_creation
[INFO] [2020-07-22 13:07:29] Done. Check your files:
[INFO] [2020-07-22 13:07:29] (2 lines) /app/public/data/lovegrove_haines/publish_nodes.tsv
[INFO] [2020-07-22 13:07:29] (2 lines) /app/public/data/lovegrove_haines/publish_scientific_names.tsv
[INFO] [2020-07-22 13:07:29] (3 lines) /app/public/data/lovegrove_haines/publish_traits.tsv
[INFO] [2020-07-22 13:07:29] (3 lines) /app/public/data/lovegrove_haines/publish_metadata.tsv
[STOP] [2020-07-22 13:07:29] complete_harvest_instance
[START] [2020-07-22 13:07:29] completed
[STOP] [2020-07-22 13:07:29] completed
[STOP] [2020-07-22 13:07:29] logged process, took 154.05

Latest Process

22 Jul 13:04 EXITED currently processing 0