[Archivesspace_Users_Group] Need help troubleshooting an error on CSV import

Thu Jun 11 11:56:12 EDT 2015

Hi all,

I have a little over 600 accession records to import using the CSV
template.  On my first attempt I received a non-specific error appearing on
the Import Job:Job Status screen within the application so I began
splitting these into batches of 100 records each.  My first two batches
imported fine, exactly as expected but when I tried the third batch I again
received a non-specific error.

I opened the archivesspace.out log to see if that might yield any clues but
couldn't make heads or tails of it, as far as identify what is failing in
the process.

I'm a couple versions back, using Version v1.1.2 running against the demo
database (my current test environment).

Here's a snippet of code from the .out log from one attempt:

D, [2015-06-10T15:20:47.877000 #5076] DEBUG -- : Thread-14292: Import
running for job 75
E, [2015-06-10T15:20:47.924000 #5076] ERROR -- : Thread-14296: Job 75
failed: Permission denied -
C:\UserFiles\archivesspace\data\tmp\import_batch_working_file_143397124790920150610-5076-lv1tbj
["org/jruby/RubyFile.java:1106:in `unlink'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/converters/converter.rb:22:in
`remove_files'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/converters/lib/parse_queue.rb:85:in
`each_open_file_path'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/converters/converter.rb:21:in
`remove_files'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/batch_import_runner.rb:80:in
`run'", "org/jruby/RubyArray.java:1613:in `each'",
"org/jruby/RubyEnumerable.java:977:in `each_with_index'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/batch_import_runner.rb:63:in
`run'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:125:in
`open'", "org/jruby/RubyFixnum.java:280:in `times'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/model/db.rb:113:in
`open'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/batch_import_runner.rb:59:in
`run'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/batch_import_job_queue.rb:96:in
`run_pending_import'",
"C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/lib/batch_import_job_queue.rb:123:in
`start_background_thread'"]
Started GET "/jobs/75/status" for 0:0:0:0:0:0:0:1 at 2015-06-10 15:20:47
-0600
Processing by JobsController#status as JSON
  Parameters: {"id"=>"75"}
D, [2015-06-10T15:20:48.018000 #5076] DEBUG -- : Thread-13264: GET
/repositories/4/jobs/75 [session: #<Session:0x91cfe @store={:user=>"admin",
:login_time=>2015-06-10 15:17:42 -0600, :expirable=>true},
@id="35a81ae84f5476b18dca98bab372f309ef68464c588359398c4f25e917d14cdf">]
D, [2015-06-10T15:20:48.018000 #5076] DEBUG -- : Thread-13264:
Post-processed params: {:id=>75, :repo_id=>4}
D, [2015-06-10T15:20:48.081000 #5076] DEBUG -- : Thread-13264: Responded
with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private,
must-revalidate, max-age=0", "Content-Length"=>"469"},
["{\"import_type\":\"accession_csv\",\"lock_version\":2,\"filenames\":[\"realdatatest_301ThruLine400.csv\"],\"time_submitted\":\"2015-06-10
21:20:46 UTC\",\"time_started\":\"2015-06-10 21:20:47
UTC\",\"status\":\"running\",\"created_by\":\"admin\",\"last_modified_by\":\"admin\",\"create_time\":\"2015-06-10T21:20:46Z\",\"system_mtime\":\"2015-06-10T21:20:47Z\",\"user_mtime\":\"2015-06-1...
in 94.0ms
Completed 200 OK in 125.0ms (Views: 0.0ms)
Started GET "/jobs/75" for 0:0:0:0:0:0:0:1 at 2015-06-10 15:20:48 -0600
Processing by JobsController#show as HTML
  Parameters: {"id"=>"75"}
D, [2015-06-10T15:20:48.221000 #5076] DEBUG -- : Thread-6996: GET
/repositories/4/jobs/75?resolve%5B%5D=repository [session:
#<Session:0x1cfa0ee @store={:user=>"admin", :login_time=>2015-06-10
15:17:42 -0600, :expirable=>true},
@id="35a81ae84f5476b18dca98bab372f309ef68464c588359398c4f25e917d14cdf">]
D, [2015-06-10T15:20:48.221000 #5076] DEBUG -- : Thread-6996:
Post-processed params: {:id=>75, :resolve=>["repository"], :repo_id=>4}
D, [2015-06-10T15:20:48.284000 #5076] DEBUG -- : Thread-6996: Responded
with [200, {"Content-Type"=>"application/json", "Cache-Control"=>"private,
must-revalidate, max-age=0", "Content-Length"=>"826"},
["{\"import_type\":\"accession_csv\",\"lock_version\":2,\"filenames\":[\"realdatatest_301ThruLine400.csv\"],\"time_submitted\":\"2015-06-10
21:20:46 UTC\",\"time_started\":\"2015-06-10 21:20:47
UTC\",\"status\":\"running\",\"created_by\":\"admin\",\"last_modified_by\":\"admin\",\"create_time\":\"2015-06-10T21:20:46Z\",\"system_mtime\":\"2015-06-10T21:20:47Z\",\"user_mtime\":\"2015-06-1...
in 78.0ms
  Rendered shared/_breadcrumb.html.erb (16.0ms)
  Rendered jobs/_show_templates.html.erb (0.0ms)
  Rendered shared/_sidebar_entry.html.erb (0.0ms)
  Rendered shared/_sidebar_entry.html.erb (0.0ms)
  Rendered shared/_sidebar_entry.html.erb (0.0ms)
  Rendered shared/_sidebar.html.erb (0.0ms)
  Rendered jobs/_sidebar.html.erb (0.0ms)
  Rendered jobs/_toolbar.html.erb (0.0ms)
  Rendered shared/_flash_messages.html.erb (0.0ms)
  Rendered shared/_flash_messages.html.erb (0.0ms)
  Rendered jobs/show.html.erb within layouts/application (110.0ms)
  Rendered shared/_browser_support.html.erb (16.0ms)
  Rendered shared/_header_user.html.erb (31.0ms)
  Rendered shared/_header_global.html.erb (31.0ms)
  Rendered site/_branding.html.erb (0.0ms)
  Rendered shared/_advanced_search.html.erb (16.0ms)
  Rendered shared/_header_repository.html.erb (94.0ms)
  Rendered
C:/UserFiles/archivesspace/plugins/aspace_feedback/frontend/views/site/_feedback_form.html.erb
(0.0ms)
  Rendered
C:/UserFiles/archivesspace/plugins/aspace_feedback/frontend/views/site/_footer.html.erb
(16.0ms)
  Rendered shared/_templates.html.erb (15.0ms)
Completed 200 OK in 406.0ms (Views: 312.0ms)
Started GET "/jobs/75/log?offset=0" for 0:0:0:0:0:0:0:1 at 2015-06-10
15:20:48 -0600
Processing by JobsController#log as */*
  Parameters: {"offset"=>"0", "id"=>"75"}
Completed 200 OK in 16.0ms
D, [2015-06-10T15:20:48.987000 #5076] DEBUG -- : Thread-13264: GET
/repositories/4/jobs/75/log?offset=0 [session: #<Session:0xa7438f
@store={:user=>"admin", :login_time=>2015-06-10 15:17:42 -0600,
:expirable=>true},
@id="35a81ae84f5476b18dca98bab372f309ef68464c588359398c4f25e917d14cdf">]
D, [2015-06-10T15:20:48.987000 #5076] DEBUG -- : Thread-13264:
Post-processed params: {:id=>75, :repo_id=>4, :offset=>0}
D, [2015-06-10T15:20:49.049000 #5076] DEBUG -- : Thread-13264: Responded
with [200, {"Content-Type"=>"text/plain", "Cache-Control"=>"private,
must-revalidate, max-age=0", "Content-Length"=>"499"}, #<Enumerator:
#<JRuby::Generator::Threaded:0x1790ec7
@block=#<Proc:0x410aaa at C:/UserFiles/archivesspace/data/tmp/jetty-0.0.0.0-8089-backend.war-_-any-/webapp/WEB-INF/app/controllers/job.rb:116>,
@next_element=nil, @index=0,
@queue_finalizer=#<JRuby::Generator::Threaded::QueueFinalizer:0xc80a7c
@queue=#<JRuby::Generator::Threaded::ProducerQueue:0x4debc2>>,
@queue=#<JRuby::Generator::Threaded::... in 93.0ms

******
Nicole Blechynden
Archivist
Heart Mountain Wyoming Foundation
1539 Road 19
Powell, WY 82435
307-754-8000 x103
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lyralists.lyrasis.org/pipermail/archivesspace_users_group/attachments/20150611/809f3bfc/attachment.html>