Harvest for Stensmyr et al 2002 Created 16 Jun 09:01

Harvesting Log

# Logfile created on 2020-06-16 08:53:04 -0400 by logger.rb/v1.4.2
[INFO] [2020-06-16 08:53:04] ## HARVEST: type = -harvest
[START] [2020-06-16 08:55:02] logged process
[START] [2020-06-16 08:55:02] create_harvest_instance
[STOP] [2020-06-16 08:55:03] create_harvest_instance
[START] [2020-06-16 08:55:03] fetch_files
[STOP] [2020-06-16 08:55:03] fetch_files
[START] [2020-06-16 08:55:03] validate_each_file
[STOP] [2020-06-16 08:55:04] validate_each_file
[START] [2020-06-16 08:55:04] convert_to_csv
[CMD] [2020-06-16 08:55:04] /usr/bin/sort /app/public/converted_csv/stensmyr_et_al_s_nodes_21244.csv > /app/public/converted_csv/stensmyr_et_al_s_nodes_21244.csv_sorted
[CMD] [2020-06-16 08:55:04] /usr/bin/sort /app/public/converted_csv/stensmyr_et_al_s_occurrences_21245.csv > /app/public/converted_csv/stensmyr_et_al_s_occurrences_21245.csv_sorted
[CMD] [2020-06-16 08:55:04] /usr/bin/sort /app/public/converted_csv/stensmyr_et_al_s_measurements_21246.csv > /app/public/converted_csv/stensmyr_et_al_s_measurements_21246.csv_sorted
[STOP] [2020-06-16 08:55:04] convert_to_csv
[START] [2020-06-16 08:55:04] calculate_delta
[CMD] [2020-06-16 08:55:04] echo "0a" > /app/public/diff/stensmyr_et_al_s_nodes_21244.diff
[CMD] [2020-06-16 08:55:04] tail -n +1 /app/public/converted_csv/stensmyr_et_al_s_nodes_21244.csv >> /app/public/diff/stensmyr_et_al_s_nodes_21244.diff
[CMD] [2020-06-16 08:55:04] echo "." >> /app/public/diff/stensmyr_et_al_s_nodes_21244.diff
[CMD] [2020-06-16 08:55:04] echo "0a" > /app/public/diff/stensmyr_et_al_s_occurrences_21245.diff
[CMD] [2020-06-16 08:55:04] tail -n +1 /app/public/converted_csv/stensmyr_et_al_s_occurrences_21245.csv >> /app/public/diff/stensmyr_et_al_s_occurrences_21245.diff
[CMD] [2020-06-16 08:55:04] echo "." >> /app/public/diff/stensmyr_et_al_s_occurrences_21245.diff
[CMD] [2020-06-16 08:55:04] echo "0a" > /app/public/diff/stensmyr_et_al_s_measurements_21246.diff
[CMD] [2020-06-16 08:55:04] tail -n +1 /app/public/converted_csv/stensmyr_et_al_s_measurements_21246.csv >> /app/public/diff/stensmyr_et_al_s_measurements_21246.diff
[CMD] [2020-06-16 08:55:04] echo "." >> /app/public/diff/stensmyr_et_al_s_measurements_21246.diff
[STOP] [2020-06-16 08:55:04] calculate_delta
[START] [2020-06-16 08:55:04] parse_diff_and_store
[INFO] [2020-06-16 08:55:04] Loading nodes diff file into memory (true lines)...
[INFO] [2020-06-16 08:55:04] Loading occurrences diff file into memory (true lines)...
[INFO] [2020-06-16 08:55:04] Loading measurements diff file into memory (true lines)...
[INFO] [2020-06-16 08:55:04] Storing 3 ScientificNames
[INFO] [2020-06-16 08:55:04] Processing group of 3 in 1 groups of 1000
[INFO] [2020-06-16 08:55:04] Average Time: 0.0
[INFO] [2020-06-16 08:55:04] Total Time: 1s
[INFO] [2020-06-16 08:55:04] Storing 3 Nodes
[INFO] [2020-06-16 08:55:04] Processing group of 3 in 1 groups of 1000
[INFO] [2020-06-16 08:55:04] Average Time: 0.0
[INFO] [2020-06-16 08:55:04] Total Time: 1s
[INFO] [2020-06-16 08:55:04] Storing 1 Occurrences
[INFO] [2020-06-16 08:55:04] Processing group of 1 in 1 groups of 1000
[INFO] [2020-06-16 08:55:04] Average Time: 0.0
[INFO] [2020-06-16 08:55:04] Total Time: 1s
[INFO] [2020-06-16 08:55:04] Storing 1 Traits
[INFO] [2020-06-16 08:55:04] Processing group of 1 in 1 groups of 1000
[INFO] [2020-06-16 08:55:04] Average Time: 0.0
[INFO] [2020-06-16 08:55:04] Total Time: 1s
[INFO] [2020-06-16 08:55:04] Storing 3 MetaTraits
[INFO] [2020-06-16 08:55:04] Processing group of 3 in 1 groups of 1000
[INFO] [2020-06-16 08:55:04] Average Time: 0.0
[INFO] [2020-06-16 08:55:04] Total Time: 1s
[STOP] [2020-06-16 08:55:04] parse_diff_and_store
[START] [2020-06-16 08:55:04] resolve_keys
[STOP] [2020-06-16 08:55:06] resolve_keys
[ERR] [2020-06-16 08:55:06] ActiveRecord::StatementInvalid
[ERR] [2020-06-16 08:55:06] Lockfile::StolenLockError: Lockfile::StolenLockError: SELECT MIN(`articles_sections`.`id`) FROM `articles_sections` WHERE (1=1) AND `articles_sections`.`harvest_id` = 2884
[ERR] [2020-06-16 08:55:06] ./config/initializers/core_extensions.rb:14:in `propagate_id'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:577:in `propagate_id'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:471:in `resolve_article_keys'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:429:in `resolve_keys'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:86:in `block (3 levels) in start'
[ERR] [2020-06-16 08:55:06] ../models/logged_process.rb:19:in `run_step'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:86:in `block (2 levels) in start'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:75:in `each_key'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:75:in `block in start'
[ERR] [2020-06-16 08:55:06] ../models/resource.rb:151:in `lock'
[ERR] [2020-06-16 08:55:06] ../models/resource_harvester.rb:72:in `start'
[ERR] [2020-06-16 08:55:06] ../models/resource.rb:232:in `harvest'
[ERR] [2020-06-16 08:55:06] bin/rails:4:in `require'
[ERR] [2020-06-16 08:55:06] bin/rails:4:in `<main>'
[STOP] [2020-06-16 08:55:06] logged process, took 3.97
[INFO] [2020-06-16 08:57:59] ## HARVEST: type = resume_-harvest
[START] [2020-06-16 08:58:00] logged process
[ERR] [2020-06-16 08:58:00][hdls] *****
[ERR] [2020-06-16 08:58:00][hdls] ***** HARVEST ATTEMPT FAILED: This resource is locked; assuming it is already running. Remove lock if not.
[ERR] [2020-06-16 08:58:00][hdls] *****
[INFO] [2020-06-16 09:01:43] ## HARVEST: type = re_download_opendata_-harvest
[INFO] [2020-06-16 09:01:46] ## remove_type: ScientificName
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 3 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.251] Removed 3 Scientificnames
[INFO] [2020-06-16 09:01:46] ## remove_type: Vernacular
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.254] Removed 0 Vernaculars
[INFO] [2020-06-16 09:01:46] ## remove_type: Article
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.258] Removed 0 Articles
[INFO] [2020-06-16 09:01:46] ## remove_type: Medium
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.261] Removed 0 Media
[INFO] [2020-06-16 09:01:46] ## remove_type: Trait
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 1 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.264] Removed 1 Traits
[INFO] [2020-06-16 09:01:46] ## remove_type: MetaTrait
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 3 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.268] Removed 3 Metatraits
[INFO] [2020-06-16 09:01:46] ## remove_type: OccurrenceMetadatum
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.271] Removed 0 Occurrencemetadata
[INFO] [2020-06-16 09:01:46] ## remove_type: Assoc
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.274] Removed 0 Assocs
[INFO] [2020-06-16 09:01:46] ## remove_type: MetaAssoc
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.277] Removed 0 Metaassocs
[INFO] [2020-06-16 09:01:46] ## remove_type: Identifier
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.280] Removed 0 Identifiers
[INFO] [2020-06-16 09:01:46] ## remove_type: Reference
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 0 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.283] Removed 0 References
[INFO] [2020-06-16 09:01:46] ## remove_type: Node
[INFO] [2020-06-16 09:01:46] ++ Calling delete_all on 3 instances...
[INFO] [2020-06-16 09:01:46] [09:01:46.306] Removed 3 Nodes
[START] [2020-06-16 09:01:46] logged process
[START] [2020-06-16 09:01:46] Creating resource from OpenData
[START] [2020-06-16 09:01:46] logged process
[START] [2020-06-16 09:01:46] Parse meta.xml file and create formats with fields
[STOP] [2020-06-16 09:01:46] Parse meta.xml file and create formats with fields
[STOP] [2020-06-16 09:01:46] Creating resource from OpenData
[START] [2020-06-16 09:01:46] logged process
[START] [2020-06-16 09:01:46] create_harvest_instance
[STOP] [2020-06-16 09:01:47] create_harvest_instance
[START] [2020-06-16 09:01:47] fetch_files
[STOP] [2020-06-16 09:01:47] fetch_files
[START] [2020-06-16 09:01:47] validate_each_file
[STOP] [2020-06-16 09:01:47] validate_each_file
[START] [2020-06-16 09:01:48] convert_to_csv
[CMD] [2020-06-16 09:01:48] /usr/bin/sort /app/public/converted_csv/stensmyr_et_al_s_nodes_21250.csv > /app/public/converted_csv/stensmyr_et_al_s_nodes_21250.csv_sorted
[CMD] [2020-06-16 09:01:48] /usr/bin/sort /app/public/converted_csv/stensmyr_et_al_s_occurrences_21251.csv > /app/public/converted_csv/stensmyr_et_al_s_occurrences_21251.csv_sorted
[CMD] [2020-06-16 09:01:48] /usr/bin/sort /app/public/converted_csv/stensmyr_et_al_s_measurements_21252.csv > /app/public/converted_csv/stensmyr_et_al_s_measurements_21252.csv_sorted
[STOP] [2020-06-16 09:01:48] convert_to_csv
[START] [2020-06-16 09:01:48] calculate_delta
[CMD] [2020-06-16 09:01:48] echo "0a" > /app/public/diff/stensmyr_et_al_s_nodes_21250.diff
[CMD] [2020-06-16 09:01:48] tail -n +1 /app/public/converted_csv/stensmyr_et_al_s_nodes_21250.csv >> /app/public/diff/stensmyr_et_al_s_nodes_21250.diff
[CMD] [2020-06-16 09:01:48] echo "." >> /app/public/diff/stensmyr_et_al_s_nodes_21250.diff
[CMD] [2020-06-16 09:01:48] echo "0a" > /app/public/diff/stensmyr_et_al_s_occurrences_21251.diff
[CMD] [2020-06-16 09:01:48] tail -n +1 /app/public/converted_csv/stensmyr_et_al_s_occurrences_21251.csv >> /app/public/diff/stensmyr_et_al_s_occurrences_21251.diff
[CMD] [2020-06-16 09:01:48] echo "." >> /app/public/diff/stensmyr_et_al_s_occurrences_21251.diff
[CMD] [2020-06-16 09:01:48] echo "0a" > /app/public/diff/stensmyr_et_al_s_measurements_21252.diff
[CMD] [2020-06-16 09:01:48] tail -n +1 /app/public/converted_csv/stensmyr_et_al_s_measurements_21252.csv >> /app/public/diff/stensmyr_et_al_s_measurements_21252.diff
[CMD] [2020-06-16 09:01:48] echo "." >> /app/public/diff/stensmyr_et_al_s_measurements_21252.diff
[STOP] [2020-06-16 09:01:48] calculate_delta
[START] [2020-06-16 09:01:48] parse_diff_and_store
[INFO] [2020-06-16 09:01:48] Loading nodes diff file into memory (true lines)...
[INFO] [2020-06-16 09:01:48] Loading occurrences diff file into memory (true lines)...
[INFO] [2020-06-16 09:01:48] Loading measurements diff file into memory (true lines)...
[INFO] [2020-06-16 09:01:48] Storing 3 ScientificNames
[INFO] [2020-06-16 09:01:48] Processing group of 3 in 1 groups of 1000
[INFO] [2020-06-16 09:01:48] Average Time: 0.0
[INFO] [2020-06-16 09:01:48] Total Time: 1s
[INFO] [2020-06-16 09:01:48] Storing 3 Nodes
[INFO] [2020-06-16 09:01:48] Processing group of 3 in 1 groups of 1000
[INFO] [2020-06-16 09:01:48] Average Time: 0.0
[INFO] [2020-06-16 09:01:48] Total Time: 1s
[INFO] [2020-06-16 09:01:48] Storing 1 Occurrences
[INFO] [2020-06-16 09:01:48] Processing group of 1 in 1 groups of 1000
[INFO] [2020-06-16 09:01:48] Average Time: 0.0
[INFO] [2020-06-16 09:01:48] Total Time: 1s
[INFO] [2020-06-16 09:01:48] Storing 1 Traits
[INFO] [2020-06-16 09:01:48] Processing group of 1 in 1 groups of 1000
[INFO] [2020-06-16 09:01:48] Average Time: 0.0
[INFO] [2020-06-16 09:01:48] Total Time: 1s
[INFO] [2020-06-16 09:01:48] Storing 3 MetaTraits
[INFO] [2020-06-16 09:01:48] Processing group of 3 in 1 groups of 1000
[INFO] [2020-06-16 09:01:48] Average Time: 0.0
[INFO] [2020-06-16 09:01:48] Total Time: 1s
[STOP] [2020-06-16 09:01:48] parse_diff_and_store
[START] [2020-06-16 09:01:48] resolve_keys
[INFO] [2020-06-16 09:01:54] Occurrences to nodes (through scientific_names)...
[INFO] [2020-06-16 09:01:54] traits to occurrences...
[INFO] [2020-06-16 09:01:54] traits to nodes (through occurrences)...
[INFO] [2020-06-16 09:01:54] Traits to sex term...
[INFO] [2020-06-16 09:01:54] Traits to lifestage term...
[INFO] [2020-06-16 09:01:54] MetaTraits to traits...
[INFO] [2020-06-16 09:01:54] MetaTraits (simple, measurement row refers to parent) to traits...
[INFO] [2020-06-16 09:01:54] Assocs to occurrences...
[INFO] [2020-06-16 09:01:54] Assocs to nodes...
[INFO] [2020-06-16 09:01:54] Assoc to sex term...
[INFO] [2020-06-16 09:01:54] Assoc to lifestage term...
[STOP] [2020-06-16 09:01:54] resolve_keys
[START] [2020-06-16 09:01:54] hold_for_later_1
[STOP] [2020-06-16 09:01:54] hold_for_later_1
[START] [2020-06-16 09:01:54] hold_for_later_2
[STOP] [2020-06-16 09:01:54] hold_for_later_2
[START] [2020-06-16 09:01:54] resolve_missing_parents
[STOP] [2020-06-16 09:01:54] resolve_missing_parents
[START] [2020-06-16 09:01:54] rebuild_nodes
[START] [2020-06-16 09:01:54] Flattener#flatten
[START] [2020-06-16 09:01:54] Flattener#study_resource
[START] [2020-06-16 09:01:55] Flattener#build_ancestry
[STOP] [2020-06-16 09:01:55] Flattener#build_ancestry
[INFO] [2020-06-16 09:01:55] 3 ancestry keys
[START] [2020-06-16 09:01:55] build_node_ancestors
[INFO] [2020-06-16 09:01:55] old ancestors deleted.
[STOP] [2020-06-16 09:01:55] build_node_ancestors
[START] [2020-06-16 09:01:55] Flattener#propagate_ancestor_ids
[STOP] [2020-06-16 09:01:55] Flattener#propagate_ancestor_ids
[STOP] [2020-06-16 09:01:55] Flattener#flatten
[STOP] [2020-06-16 09:01:55] rebuild_nodes
[START] [2020-06-16 09:01:55] resolve_missing_media_owners
[STOP] [2020-06-16 09:01:55] resolve_missing_media_owners
[START] [2020-06-16 09:01:55] sanitize_media_verbatims
[STOP] [2020-06-16 09:01:55] sanitize_media_verbatims
[START] [2020-06-16 09:01:55] queue_downloads
[STOP] [2020-06-16 09:01:55] queue_downloads
[START] [2020-06-16 09:01:55] parse_names
[WARN] [2020-06-16 09:01:55] I see 3 names which still need to be parsed.
[STOP] [2020-06-16 09:01:56] parse_names
[START] [2020-06-16 09:01:56] denormalize_canonical_names_to_nodes
[STOP] [2020-06-16 09:01:56] denormalize_canonical_names_to_nodes
[START] [2020-06-16 09:01:56] match_nodes
[START] [2020-06-16 09:01:56] map_all_nodes_to_pages
[STOP] [2020-06-16 09:01:56] map_all_nodes_to_pages
[INFO] [2020-06-16 09:01:56] ZERO unmatched nodes (of 3)! Nicely done.
[START] [2020-06-16 09:01:56] update_nodes
[STOP] [2020-06-16 09:01:56] update_nodes
[STOP] [2020-06-16 09:01:56] match_nodes
[START] [2020-06-16 09:01:56] reindex_search
[STOP] [2020-06-16 09:01:56] reindex_search
[START] [2020-06-16 09:01:56] normalize_units
[STOP] [2020-06-16 09:01:56] normalize_units
[START] [2020-06-16 09:01:56] calculate_statistics
[STOP] [2020-06-16 09:01:56] calculate_statistics
[START] [2020-06-16 09:01:56] complete_harvest_instance
[START] [2020-06-16 09:01:56] overall_tsv_creation
[INFO] [2020-06-16 09:01:56] Processing group of 3 in 1 batches of 10000
[INFO] [2020-06-16 09:02:50] 1 Traits (unfiltered)...
[INFO] [2020-06-16 09:03:03] 1 Traits (filtered)...
[INFO] [2020-06-16 09:03:03] 0 Associations (filtered)...
[INFO] [2020-06-16 09:03:40] 3 metadata added.
[INFO] [2020-06-16 09:03:40] 0 metadata added.
[INFO] [2020-06-16 09:03:40] Average Time: 72.48
[INFO] [2020-06-16 09:03:40] Total Time: 1m45s
[STOP] [2020-06-16 09:03:40] overall_tsv_creation
[INFO] [2020-06-16 09:03:40] Done. Check your files:
[INFO] [2020-06-16 09:03:40] (3 lines) /app/public/data/stensmyr_et_al_s/publish_nodes.tsv
[INFO] [2020-06-16 09:03:40] (3 lines) /app/public/data/stensmyr_et_al_s/publish_node_ancestors.tsv
[INFO] [2020-06-16 09:03:40] (3 lines) /app/public/data/stensmyr_et_al_s/publish_scientific_names.tsv
[INFO] [2020-06-16 09:03:40] (2 lines) /app/public/data/stensmyr_et_al_s/publish_traits.tsv
[INFO] [2020-06-16 09:03:40] (4 lines) /app/public/data/stensmyr_et_al_s/publish_metadata.tsv
[STOP] [2020-06-16 09:03:40] complete_harvest_instance
[START] [2020-06-16 09:03:40] completed
[STOP] [2020-06-16 09:03:40] completed
[STOP] [2020-06-16 09:03:40] logged process, took 113.91

Latest Process

16 Jun 09:01 EXITED currently processing 0